Application won't load when using UseAllElasticApm

[poserdonut (Jens Bengtsson)]

Hi!

We are using apm-agent-dotnet 1.3 in a .NET Core 3.1.1 Web API with Entity Framework Core 3.1.1.

When I add app.UseAllElasticApm(Configuration); and try to start the application it won't entirely load. It just hangs in the browser trying to load the swagger interface.

However if I use
app.UseElasticApm(Configuration);

Then it loads fine but we don't get EF logs.

If I use:
app.UseElasticApm(Configuration, new EfCoreDiagnosticsSubscriber())

Then it works and we get EF logs.

If I use:
app.UseElasticApm(Configuration,
new HttpDiagnosticsSubscriber(),
new EfCoreDiagnosticsSubscriber());

Then it hangs again when trying to load the UI.

The output in visual studio gets spammed with rows similiar to this when using UseAllElasticApm or when registering both subscribers:

Elastic.Apm: Debug: {PayloadSenderV2} Enqueued Transaction. newEventQueueCount: 1. MaxQueueEventCount: 1000. Transaction: Transaction{Id: f50c65a936f30cf8, TraceId: 8a24edee8eb59dfb5a729a14df14cfdb, ParentId: null, Name: POST Meddelande/GetAvdelningar, Type: request, IsSampled: True}.

Elastic.Apm: Debug: {PayloadSenderV2} Enqueued Span. newEventQueueCount: 2. MaxQueueEventCount: 1000. Span: Span{Id: 935a6bfbf005f149, TransactionId: c533a13956749369, ParentId: c533a13956749369, TraceId: 7b7b6716bcdc9fb54362dcc094b4633a, Name: SELECT [a].[Id], [a].[Epost], [a].[Namn] FROM [Avdelning] AS [a], Type: db, IsSampled: True}.



Elastic.Apm: Debug: {HttpDiagnosticListener} Current runtime is not detected as Full Framework - returning implementation for Core. RuntimeInformation.FrameworkDescription: .NET Core 3.1.1
Elastic.Apm: Debug: {DiagnosticInitializer} Subscribed Elastic.Apm.DiagnosticListeners.HttpDiagnosticListenerCoreImpl to `HttpHandlerDiagnosticListener' events source
Elastic.Apm: Debug: {HttpDiagnosticListenerImplBase} No current transaction, skip creating span for outgoing HTTP request
Elastic.Apm: Debug: {DiagnosticInitializer} Subscribed Elastic.Apm.AspNetCore.DiagnosticListener.AspNetCoreDiagnosticListener to `Microsoft.AspNetCore' events source
Elastic.Apm: Debug: {HttpDiagnosticListenerImplBase} No current transaction, skip creating span for outgoing HTTP request
Elastic.Apm: Debug: {HttpDiagnosticListenerImplBase} No current transaction, skip creating span for outgoing HTTP request
Elastic.Apm: Debug: {HttpDiagnosticListenerImplBase} No current transaction, skip creating span for outgoing HTTP request
Elastic.Apm: Debug: {HttpDiagnosticListenerImplBase} No current transaction, skip creating span for outgoing HTTP request
Elastic.Apm: Warning: {HttpDiagnosticListenerImplBase} Failed capturing request (failed to remove from ProcessingRequests) - This Span will be skipped in case it wasn't captured before. Request: method: POST, URL: [REMOVED]
Elastic.Apm: Warning: {HttpDiagnosticListenerImplBase} Failed capturing request (failed to remove from ProcessingRequests) - This Span will be skipped in case it wasn't captured before. Request: method: POST, URL: [REMOVED]
Elastic.Apm: Warning: {HttpDiagnosticListenerImplBase} Failed capturing request (failed to remove from ProcessingRequests) - This Span will be skipped in case it wasn't captured before. Request: method: POST, URL: [REMOVED]
Elastic.Apm: Debug: {HttpDiagnosticListenerImplBase} No current transaction, skip creating span for outgoing HTTP request
Elastic.Apm: Debug: {HttpDiagnosticListenerImplBase} No current transaction, skip creating span for outgoing HTTP request
Elastic.Apm: Debug: {HttpDiagnosticListenerImplBase} No current transaction, skip creating span for outgoing HTTP request
Elastic.Apm: Debug: {HttpDiagnosticListenerImplBase} No current transaction, skip creating span for outgoing HTTP request
Elastic.Apm: Debug: {HttpDiagnosticListenerImplBase} No current transaction, skip creating span for outgoing HTTP request
Elastic.Apm: Warning: {HttpDiagnosticListenerImplBase} Failed capturing request (failed to remove from ProcessingRequests) - This Span will be skipped in case it wasn't captured before. Request: method: POST, URL: [REMOVED]

Any idea what could cause this?

[GregKalapos]

Hi @poserdonut,

I tried to reproduce the issue, but no success so far.

Based on what you write this seems to be related to outgoing HTTP Request capturing. That's what HttpDiagnosticsSubscriber does - so if that's not passed to UseElasticApm (in case you use UseElasticApm) then outgoing HTTP requests won't be captured.

Unfortunately I was unable to create a situation where this happens. Tried it on .NET Core 3.1.100 and ASP.NET Core 3.1 Web API on Windows with the new 1.3 Agent release release.

I also added <PackageReference Include="Swashbuckle.AspNetCore" Version="5.0.0" /> to the project and enabled it with:

app.UseSwagger();

app.UseSwaggerUI(c =>
{
	c.SwaggerEndpoint("/swagger/v1/swagger.json", "My API V1");
});

Triggered the swagger UI on /swagger - all worked as expected.

Regarding the logs:

Lines with No current transaction, skip creating span for outgoing HTTP request are maybe from swagger - if you registered swagger first and then the Elastic APM .NET Agent middleware then there will be no transactions, so the HTTP request won't be captured either - but that's normal, this should not cause the app to hang.

So, unfortunately I'll need more hints to be able to tell more. Is it possible to maybe trim your code and give me a minimal repro? That'd help a lot.

If not, then is there any other info you could tell me to help to repro?

[poserdonut (Jens Bengtsson)]

I have left work but next week I will try to strip down my current solution and see if the issue persists. Maybe I can find the problem while removing stuff otherwise I will try to post something here that recreates the issue.

[poserdonut (Jens Bengtsson)]

@GregKalapos

So by chance I changed the logging of the Elastic.APM agent to Warning instead of Debug and the application loaded fine. So it seems that the amount of debug logging generated by the agent is causing it to not start.

There is still a lot of logging on the warning level but not enough so it causes an issue. However what seem to be causing the issue is this that the http diagnostic is not able to capture a request to a WCF service we use for logging.

Elastic.Apm: Warning: {HttpDiagnosticListenerImplBase} Failed capturing request (failed to remove from ProcessingRequests) - This Span will be skipped in case it wasn't captured before. Request: method: POST, URL: http://wcf.service.com/logging.svc/ext
Elastic.Apm: Warning: {HttpDiagnosticListenerImplBase} Failed capturing request (failed to remove from ProcessingRequests) - This Span will be skipped in case it wasn't captured before. Request: method: POST, URL: http://wcf.service.com/logging.svc/ext
Elastic.Apm: Warning: {HttpDiagnosticListenerImplBase} Failed capturing request (failed to remove from ProcessingRequests) - This Span will be skipped in case it wasn't captured before. Request: method: POST, URL: http://wcf.service.com/logging.svc/ext
Elastic.Apm: Warning: {HttpDiagnosticListenerImplBase} Failed capturing request (failed to remove from ProcessingRequests) - This Span will be skipped in case it wasn't captured before. Request: method: POST, URL: http://wcf.service.com/logging.svc/ext
Elastic.Apm: Warning: {HttpDiagnosticListenerImplBase} Failed capturing request (failed to remove from ProcessingRequests) - This Span will be skipped in case it wasn't captured before. Request: method: POST, URL: http://wcf.service.com/logging.svc/ext
Elastic.Apm: Warning: {HttpDiagnosticListenerImplBase} Failed capturing request (failed to remove from ProcessingRequests) - This Span will be skipped in case it wasn't captured before. Request: method: POST, URL: http://wcf.service.com/logging.svc/ext
Elastic.Apm: Warning: {HttpDiagnosticListenerImplBase} Failed capturing request (failed to remove from ProcessingRequests) - This Span will be skipped in case it wasn't captured before. Request: method: POST, URL: http://wcf.service.com/logging.svc/ext
Elastic.Apm: Warning: {HttpDiagnosticListenerImplBase} Failed capturing request (failed to remove from ProcessingRequests) - This Span will be skipped in case it wasn't captured before. Request: method: POST, URL: http://wcf.service.com/logging.svc/ext
Elastic.Apm: Warning: {HttpDiagnosticListenerImplBase} Failed capturing request (failed to remove from ProcessingRequests) - This Span will be skipped in case it wasn't captured before. Request: method: POST, URL: http://wcf.service.com/logging.svc/ext
Elastic.Apm: Warning: {HttpDiagnosticListenerImplBase} Failed capturing request (failed to remove from ProcessingRequests) - This Span will be skipped in case it wasn't captured before. Request: method: POST, URL: http://wcf.service.com/logging.svc/ext
Elastic.Apm: Warning: {HttpDiagnosticListenerImplBase} Failed capturing request (failed to remove from ProcessingRequests) - This Span will be skipped in case it wasn't captured before. Request: method: POST, URL: http://wcf.service.com/logging.svc/ext
Elastic.Apm: Warning: {HttpDiagnosticListenerImplBase} Failed capturing request (failed to remove from ProcessingRequests) - This Span will be skipped in case it wasn't captured before. Request: method: POST, URL: http://wcf.service.com/logging.svc/ext
Elastic.Apm: Warning: {HttpDiagnosticListenerImplBase} Failed capturing request (failed to remove from ProcessingRequests) - This Span will be skipped in case it wasn't captured before. Request: method: POST, URL: http://wcf.service.com/logging.svc/ext
Elastic.Apm: Warning: {HttpDiagnosticListenerImplBase} Failed capturing request (failed to remove from ProcessingRequests) - This Span will be skipped in case it wasn't captured before. Request: method: POST, URL: http://wcf.service.com/logging.svc/ext
Elastic.Apm: Warning: {HttpDiagnosticListenerImplBase} Failed capturing request (failed to remove from ProcessingRequests) - This Span will be skipped in case it wasn't captured before. Request: method: POST, URL: http://wcf.service.com/logging.svc/ext
Elastic.Apm: Warning: {HttpDiagnosticListenerImplBase} Failed capturing request (failed to remove from ProcessingRequests) - This Span will be skipped in case it wasn't captured before. Request: method: POST, URL: http://wcf.service.com/logging.svc/ext
Elastic.Apm: Warning: {HttpDiagnosticListenerImplBase} Failed capturing request (failed to remove from ProcessingRequests) - This Span will be skipped in case it wasn't captured before. Request: method: POST, URL: http://wcf.service.com/logging.svc/ext
Elastic.Apm: Warning: {HttpDiagnosticListenerImplBase} Failed capturing request (failed to remove from ProcessingRequests) - This Span will be skipped in case it wasn't captured before. Request: method: POST, URL: http://wcf.service.com/logging.svc/ext
Elastic.Apm: Warning: {HttpDiagnosticListenerImplBase} Failed capturing request (failed to remove from ProcessingRequests) - This Span will be skipped in case it wasn't captured before. Request: method: POST, URL: http://wcf.service.com/logging.svc/ext
Elastic.Apm: Warning: {HttpDiagnosticListenerImplBase} Failed capturing request (failed to remove from ProcessingRequests) - This Span will be skipped in case it wasn't captured before. Request: method: POST, URL: http://wcf.service.com/logging.svc/ext
Elastic.Apm: Warning: {HttpDiagnosticListenerImplBase} Failed capturing request (failed to remove from ProcessingRequests) - This Span will be skipped in case it wasn't captured before. Request: method: POST, URL: http://wcf.service.com/logging.svc/ext
Elastic.Apm: Warning: {HttpDiagnosticListenerImplBase} Failed capturing request (failed to remove from ProcessingRequests) - This Span will be skipped in case it wasn't captured before. Request: method: POST, URL: http://wcf.service.com/logging.svc/ext
Elastic.Apm: Warning: {HttpDiagnosticListenerImplBase} Failed capturing request (failed to remove from ProcessingRequests) - This Span will be skipped in case it wasn't captured before. Request: method: POST, URL: http://wcf.service.com/logging.svc/ext
Elastic.Apm: Warning: {HttpDiagnosticListenerImplBase} Failed capturing request (failed to remove from ProcessingRequests) - This Span will be skipped in case it wasn't captured before. Request: method: POST, URL: http://wcf.service.com/logging.svc/ext
Elastic.Apm: Warning: {HttpDiagnosticListenerImplBase} Failed capturing request (failed to remove from ProcessingRequests) - This Span will be skipped in case it wasn't captured before. Request: method: POST, URL: http://wcf.service.com/logging.svc/ext

So I guess a "solution" is to set the logging to Error for Elastic.APM but it would be interesting to know why it's having problems capturing this call.

[GregKalapos]

Thanks for the additional info @poserdonut.

This is very strange. In a normal case there are 2 events for all outgoing web request - one when it starts and one when it ends - this is how we capture the call and measure its duration. Logs above basically say that there is no begin event for the given requests, only ends events are triggered - or to be precise: in the end event we try to find the corresponding HttpRequestMessage message that we pin in the begin event, but it's not there.

I also looked at your first logs and that's also interesting, there are some logs that say {HttpDiagnosticListenerImplBase} No current transaction, skip creating span for outgoing HTTP request - My theory here is that there is no active transaction when the begin event is received, so we don't pin the request, therefore we don't have it when we receive the end event.

But this is something I'd really need to debug in that scenario - any chance for a small reproducer?

Alternatively logs with loglevel trace would maybe also help - but a reproducer would be the bigger help here.

[poserdonut (Jens Bengtsson)]

Thanks for quick answers @GregKalapos

I have captured some trace logging: https://pastebin.com/LsXsQReY

I understand that a repro would be the most helpful but I think it will be hard to provide since it will require a WCF-service with a similar .net core client as we are using etc. Sorry to not be more helpful.

[poserdonut (Jens Bengtsson)]

The APM client is the first thing that is added, before swagger etc.

It seems that the service start now even though logging is set to information. However when doing that the log get filled with:

Elastic.Apm: Warning: {HttpDiagnosticListenerImplBase} Failed capturing request (failed to remove from ProcessingRequests) - This Span will be skipped in case it wasn't captured before. Request: method: POST, URL: http://services.test.se/LoggingService/LoggingService.svc/ext
Elastic.Apm: Warning: {HttpDiagnosticListenerImplBase} Failed capturing request (failed to remove from ProcessingRequests) - This Span will be skipped in case it wasn't captured before. Request: method: POST, URL: http://services.test.se/LoggingService/LoggingService.svc/ext
Elastic.Apm: Warning: {HttpDiagnosticListenerImplBase} Failed capturing request (failed to remove from ProcessingRequests) - This Span will be skipped in case it wasn't captured before. Request: method: POST, URL: http://services.test.se/LoggingService/LoggingService.svc/ext
Elastic.Apm: Warning: {HttpDiagnosticListenerImplBase} Failed capturing request (failed to remove from ProcessingRequests) - This Span will be skipped in case it wasn't captured before. Request: method: POST, URL: http://services.test.se/LoggingService/LoggingService.svc/ext

It logs so much that when we deployed it to a test server it got unresponsive. So it's like it get stuck in some kind of loop. Because it's not like we are calling the logging WCF service all the time.

I realise you won't be able to help us solve this problem based on only this information. But trimming the solution down to something that can reproduced it seems quite hard since it relies on providing an external WCF service and our general nuget-logging package for .net core which uses the WCF servie.

So, the workaround for us is probably just putting the log level to error and I will continue my quest to replace this old WCF-service with something better.

[GregKalapos]

Hey, thanks @poserdonut for the info.

I also looked deeper into it, and yeah, this is not ok in the agent, those warnings are not good.

There was another thread here with something similar (referenced in the GitHub issue below). I already have some findings and a reproducer - I suspect your issue and the other one have the same root cause.

More here: https://github.com/elastic/apm-agent-dotnet/issues/734

[poserdonut (Jens Bengtsson)]

OK, hopefully that issue relates to mine since you have a way of reproducing it.