For more context, the profiler injects a shim assembly that loads a supporting managed assembly containing the code for auto instrumentation. One of the first operations it does is to ensure the singleton agent instance is initialized:
In the case of .NET Framework running in a hosted environment e.g. IIS, it defers instantiation to the ASP.NET integration, which in turn, will end up instantiating the agent in the ElasticApmModule that it registers in the ASP.NET pipeline:
This is primarily done to allow the agent to be configured with ASP.NET specific components.
Now, if for some reason, you wanted to explicitly register ElasticApmModule yourself in web.config, and ultimately control the instantiation of the agent instead of leaving it to the profiler, you could as an alternative, disable the ASP.NET auto instrumentation integration with the Elastic APM profiler environment variable:
Hosted environments where we do not have control of the Front-ends. For this, we created a .Net library so that we can instantiate the agent through Application_Start.
On-premise environments. Here we just want to use the Auto-instrumentation, so we used the setup as I displayed in my initial post. However, the test environment is also where we developed the .Net library and demo applications that initiate the Agent. I disabled all of these applications, so they can't initiate the agent any longer.
However, I still get the Singleton error, can't find yet what is causing this. Can you confirm that the setup we did is the correct way of auto instrumenting ASP.Net applications, or did we miss something?
[2022-02-04T07:47:26.097466000+01:00] [TRACE] Initialize: started. profiler package version 1.13.0-beta.1 (commit: 33c296c3ccc2f3158915d8b3cb67cc1db9397e78)
[2022-02-04T07:47:26.098146300+01:00] [DEBUG] Environment variables
APP_POOL_ID="OutSystemsApplications"
COMPlus_LoaderOptimization="1"
COR_PROFILER_PATH="E:\ElasticStack\elastic_apm_profiler\elastic_apm_profiler.dll"
ELASTIC_APM_PROFILER_INTEGRATIONS="E:\ElasticStack\elastic_apm_profiler\integrations.yml"
ELASTIC_APM_PROFILER_HOME="E:\ElasticStack\elastic_apm_profiler\"
ELASTIC_APM_PROFILER_LOG_DIR="E:\ElasticStack\elastic_apm_profiler\logs"
ELASTIC_APM_PROFILER_LOG_IL="1"
ELASTIC_APM_PROFILER_LOG="trace"
COR_PROFILER="{FA65FE15-F085-4681-9B20-95E04F6C03CC}"
COR_ENABLE_PROFILING="1"
[2022-02-04T07:47:26.108434900+01:00] [TRACE] loaded 9 integration(s) from E:\ElasticStack\elastic_apm_profiler\integrations.yml
[2022-02-04T07:47:26.108497700+01:00] [DEBUG] Problem reading ELASTIC_APM_PROFILER_CALLTARGET_ENABLED: environment variable not found. Setting to true
[2022-02-04T07:47:26.108736000+01:00] [DEBUG] Initialize: loaded 123 integration(s)
[2022-02-04T07:47:26.108782500+01:00] [INFO ] Initialize: CallTarget instrumentation is enabled
[2022-02-04T07:47:26.108795300+01:00] [DEBUG] Problem reading ELASTIC_APM_PROFILER_ENABLE_INLINING: environment variable not found. Setting to true
[2022-02-04T07:47:26.108802700+01:00] [INFO ] Initialize: JIT Inlining is enabled
[2022-02-04T07:47:26.108828500+01:00] [DEBUG] Problem reading ELASTIC_APM_PROFILER_DISABLE_OPTIMIZATIONS: environment variable not found. Setting to false
[2022-02-04T07:47:26.108836500+01:00] [TRACE] Initialize: set event mask2 to COR_PRF_MONITOR_MODULE_LOADS | COR_PRF_MONITOR_ASSEMBLY_LOADS | COR_PRF_MONITOR_APPDOMAIN_LOADS | COR_PRF_MONITOR_JIT_COMPILATION | COR_PRF_ENABLE_REJIT | COR_PRF_DISABLE_TRANSPARENCY_CHECKS_UNDER_FULL_TRUST | COR_PRF_DISABLE_ALL_NGEN_IMAGES, COR_PRF_HIGH_ADD_ASSEMBLY_REFERENCES
Something I found suspicious, but need your help to identify as part of the standard tracing or indeed an exception of the profiler which explains the issue?
That's not an issue; it's an IL ldstr opcode that pushes a new object reference to a string literal stored in module metadata, onto the stack. It's part of the IL instructions of the original System.Web.Compilation.BuildManager.InvokePreStartInitMethodsCore method
specifically the constant SR.Pre_application_start_init_method_threw_exception on line 907. This method is rewritten for the ASP.NET integration. I wouldn't worry about logging out the IL instructions of rewritten methods with the ELASTIC_APM_PROFILER_LOG_IL="1" environment variable, unless you see an InvalidProgramException i.e. rewritten IL is incorrect in some way- it'll be just added noise in the logs.
The <appSettings> section shown looks fine, but the <modules> section isn't shown, or the HttpApplication methods like Application_Start(), so I can't advise if there is something there that would instantiate the agent. Are you able to share those?
What you're saying seems to imply that. If you reconfigure the profiler and restart IIS, do you get any traces? If not, are you able to attach a debugger and inspect the properties of the instantiated agent?
After reconfiguring the profiler and restarting we get only one singleton message in the agent log. Trace logs are present..but still nothing besides metrics in APM server..
We will install VS on the server and attach debugger..hopefully more information soon.
We have some trouble debugging, if it's possible to set up a meeting to have a look with us it would be great.
What we did figure out is that in our case the IIS has 1 website with every application as a virtual directory. We noticed that each initialization of an APP triggers the Singleton message. Is that as designed or part of the problem?
Potentially- I don't think this is a scenario that has been thoroughly tested so far.
The best way to determine whether having multiple applications in virtual directories under one website might be affecting things would be to remove all virtual directories except for one, where the remaining one is configured to run with the profiler. If that works as expected, add another app in a virtual directory and see if the issue arises.
ETW is used by the APM agent on Windows for .NET Framework, to collect GC metrics
If there's an issue in starting a trace event session, the exception is caught, and GC metrics won't be reported.
It looks like the UnauthorizedAccessException is caught? Is the exception coming from the agent when attempting to collect GC metrics? It's not super clear from the screenshot if it's coming from the agent or something else that might be using ETW.
We did quite a lot of testing and I can share the following, hope it rings a bell:
ApplicationPool with 1 application worked like a charm. We immediately received transactions
We created a new application pool and moved one of the applications from the shared pool to it. It fails to send transactions like with the shared pool
We inspected the differences between the already isolated application in its own pool and the one we moved to an isolated pool.
To give a bit more context, the application giving transactions is a platform (low-code) application built by the supplier. It is a standalone application with its own binaries
Our applications are built/generated by the low-code platform which generates a virtual directory per module that we created. These modules do not have isolated binaries but have symbolic links to a platform repository where all the application DLLs are stored. This is how the platform handles references between modules etc..nothing we can do about it.
Both applications are the same .net/asp.net code, same settings in IIS, the only difference is that applications built by the platform use symbolic links.
Getting APM to work for the applications our customers built is crucial for us. Therefore I wouldn't mind a collaboration with the elastic team to see if we can figure out why this scenario doesn't work. I know it can work since a big competitor already proved that. Would this be possible? I have the environment all ready for it.
I believe this came from the agent but can't say with certainty, was quite a challenge to get the debugger going. Placing the apppool owner in Administrator group solved the messages. Its not the solution but I wanted to know if I was missing rights or if it was related to something else. Once we get the agent working on our application I'll focus on finding the missing rights. Placing the apppool owner in the user log/monitor groups wasn't enough.
@forloop We believe that this is why no traces are being collected.
so far it only occurs for the isolated application with symbolic links to the dlls
[2022-02-23 10:06:28.496 +01:00][Trace] - {SingleThreadTaskScheduler (thread: ElasticApmCentralConfigurationFetcher)} Finished executing task. Task: {ID: 46, Status: RanToCompletion, AsyncState: null}
[2022-02-23 10:06:28.630 +01:00][Warning] - {GcMetricsProvider} TraceEventSession initialization failed - GC metrics won't be collected+-> Exception: System.Runtime.InteropServices.COMException: Insufficient system resources exist to complete the requested service. (Exception from HRESULT: 0x800705AA)
at System.Runtime.InteropServices.Marshal.ThrowExceptionForHRInternal(Int32 errorCode, IntPtr errorInfo)
at Microsoft.Diagnostics.Tracing.Session.TraceEventSession.InsureStarted(EVENT_TRACE_PROPERTIES* properties)
at Microsoft.Diagnostics.Tracing.Session.TraceEventSession.get_Source()
at Elastic.Apm.Metrics.MetricsProvider.GcMetricsProvider..ctor(IApmLogger logger, IReadOnlyList`1 disabledMetrics) in C:\Users\jenkins\workspace\net_apm-agent-dotnet-mbp_PR-1594\apm-agent-dotnet\src\Elastic.Apm\Metrics\MetricsProvider\GcMetricsProvider.cs:line 91
[2022-02-23 10:06:28.631 +01:00][Trace] - {CgroupMetricsProvider} CgroupMetricsProvider detected a non Linux OS, therefore Cgroup metrics will not be reported
[2022-02-23 10:06:28.632 +01:00][Info] - {MetricsCollector} Collecting metrics in 30000 milliseconds interval
[2022-02-23 10:06:28.647 +01:00][Debug] - {ElasticApmModule.#1} Found ASP.NET version: 4.8.4465.0
[2022-02-23 10:06:28.649 +01:00][Error] - The singleton APM agent has already been instantiated and can no longer be configured. Reusing existing instance
[2022-02-23 10:06:28.649 +01:00][Trace] - Initialization - Agent.Setup called. Callstack: at Elastic.Apm.Agent.Setup(AgentComponents agentComponents)
at Elastic.Apm.AspNetFullFramework.ElasticApmModule.<>c__DisplayClass25_0.<InitOnceForAllInstancesUnderLock>b__0()
at Elastic.Apm.Helpers.LazyContextualInit.<>c__DisplayClass6_0.<Init>b__0()
at System.Threading.LazyInitializer.EnsureInitializedCore[T](T& target, Boolean& initialized, Object& syncLock, Func`1 valueFactory)
at Elastic.Apm.Helpers.LazyContextualInit.Init(Action initAction)
at Elastic.Apm.AspNetFullFramework.ElasticApmModule.InitOnceForAllInstancesUnderLock(String dbgInstanceName)
at Elastic.Apm.AspNetFullFramework.ElasticApmModule.InitImpl(HttpApplication application)
at Elastic.Apm.AspNetFullFramework.ElasticApmModule.Init(HttpApplication application)
at System.Web.HttpApplication.RegisterEventSubscriptionsWithIIS(IntPtr appContext, HttpContext context, MethodInfo[] handlers)
at System.Web.HttpApplication.InitSpecial(HttpApplicationState state, MethodInfo[] handlers, IntPtr appContext, HttpContext context)
at System.Web.HttpApplicationFactory.GetSpecialApplicationInstance(IntPtr appContext, HttpContext context)
at System.Web.Hosting.PipelineRuntime.InitializeApplication(IntPtr appContext)
We ran out of event listeners (somehow). We manually removed them and do not see the issue about resources coming back. We will try to find out why caused this, but it seems not to be the main issue.
The failure to set up an ETW trace session should not be an issue for agent startup, but it does mean you wouldn't get GC metrics. You can disable GC metrics with
which won't attempt to create an ETW trace session.
From the APM agent log posted, it looks like there is still an attempt to instantiate the singleton instance of the agent when it has already been instantiated
[2022-02-23 10:06:28.649 +01:00][Error] - The singleton APM agent has already been instantiated and can no longer be configured. Reusing existing instance
[2022-02-23 10:06:28.649 +01:00][Trace] - Initialization - Agent.Setup called. Callstack: at Elastic.Apm.Agent.Setup(AgentComponents agentComponents)
at Elastic.Apm.AspNetFullFramework.ElasticApmModule.<>c__DisplayClass25_0.<InitOnceForAllInstancesUnderLock>b__0()
at Elastic.Apm.Helpers.LazyContextualInit.<>c__DisplayClass6_0.<Init>b__0()
at System.Threading.LazyInitializer.EnsureInitializedCore[T](T& target, Boolean& initialized, Object& syncLock, Func`1 valueFactory)
at Elastic.Apm.Helpers.LazyContextualInit.Init(Action initAction)
at Elastic.Apm.AspNetFullFramework.ElasticApmModule.InitOnceForAllInstancesUnderLock(String dbgInstanceName)
at Elastic.Apm.AspNetFullFramework.ElasticApmModule.InitImpl(HttpApplication application)
at Elastic.Apm.AspNetFullFramework.ElasticApmModule.Init(HttpApplication application)
at System.Web.HttpApplication.RegisterEventSubscriptionsWithIIS(IntPtr appContext, HttpContext context, MethodInfo[] handlers)
at System.Web.HttpApplication.InitSpecial(HttpApplicationState state, MethodInfo[] handlers, IntPtr appContext, HttpContext context)
at System.Web.HttpApplicationFactory.GetSpecialApplicationInstance(IntPtr appContext, HttpContext context)
at System.Web.Hosting.PipelineRuntime.InitializeApplication(IntPtr appContext)
I'm fairly sure this is the crux of why we're not seeing traces.
Something worth trying is to disable the ASP.NET integration in the profiler, and add the ElasticApmModule manually in web.config, by referencing the NuGet Gallery | Elastic.Apm.AspNetFullFramework 1.14.0 package. The integration can be disabled with the environment variable
ELASTIC_APM_PROFILER_EXCLUDE_INTEGRATIONS=AspNet
added to the app pool. You'll need to recycle the app pool for changes to take effect.
@forloop We managed to figure out why we receive no traces..You are right that it is related to the Agent already being instantiated, but not in a way we were expecting. Here's what we found out..:
Thread exceptions are due to app pool recycles (consistent reproduced). So those are not related to our issue
Traces are being captured. During debug we saw that traces are being captured and logs are written. However, we couldn't find any trace of it. No logs, no data received. But profiler, agent is active
We finally managed to caught the very first initialization of the Agent. The first init is done with an empty serverurl, which made it fall back on localhost:8200. Then there is a second attempt to start the agent and then we see our ServerUrl being passed to the Agent init, but it's too late due to the Singleton already being active. That's why we see no logs or receive data.
So far we haven't figured out why the agent starts with no configuration for the first Dll from our app that instantiates it. Any ideas about this behaviour?
The weird thing is that we do get Mectrics, so how is that possible since the Agent instantiated with localhost instead of our elastic url??
@forloopUpdate: figured out where the first agent init comes from. It's from the profiler and that is not using the web.config. I added the environment variables to the profiler powershell setup script and am now seeing the new service being added to APM server and traces
The initial configuration consisted out of auto Profiler setup on the Application pools with the environment variables in the central /windows/microsoft.net/framework64/v4.0****/web.config
That setup works fine for stand-alone applications that do not use shared DLLs through a symbolic link.
For platforms that uses this setup you can solve it by only using the profiler setup like below:
It also simplifies our setup since I only need to change the Application pool name and rerun it..
@forloop Thanks for all the help!. Any chance our findings can be added to the installation documentation to help others?
Disadvantage: Can't use a service name per application anymore since it's configured centrally per app pool. But at least it's capturing, will see if we can find some way of identifying/grouping per app
It sounds like all applications within virtual directories, assigned to the same application pool, are sharing a single instance of the agent. Can you confirm if they use the same AppDomain?
The use of APM agent environment variables for the application pool means that the agent is configured the same way, irrespective of which application might instantiate the singleton instance first, which is what you would want I think.
The behaviour we're seeing here is related to the ASP.NET agent instrumentation, rather than the profiler auto instrumentation per se. That is, if we were to take the profiler out of the equation altogether, and configure each application through web.config to add the ElasticApmModule HttpModule, I'm sure we would see the same behaviour. More tests to assert behaviour under different IIS configurations will help, so that the documentation can provide better guidance for how to configure for different scenarios, or if certain scenarios are not officially supported. @GregKalapos, @alexander.wert - this may be something to add an issue for.
I believe they do all use the same AppDomain. I also believe that the current setup from your documentation works for most environments as long as they do not share the binaries by symbolic links, which is pretty common for low code platforms.
Applications on my environment in IIS that have their own binaries and no shared ones worked fine with the initial setup.
Apache, Apache Lucene, Apache Hadoop, Hadoop, HDFS and the yellow elephant
logo are trademarks of the
Apache Software Foundation
in the United States and/or other countries.