StackOverflowException from ServiceProfiler.EventPipe.Client.EventListeners.TraceSessionListener when LogLevel trace is used

[andscho-msft]

Repro

AddServiceProfiler() with the ApplicationInsightsLogger and min loglevel of trace. The TraceSessionListener tries to log, which seems to trigger the TraceSessionListener again, resulting in a stack overflow.

What is printed to console

trce: ServiceProfiler.EventPipe.Client.EventListeners.TraceSessionListener[0]
      OnRichPayloadEventWritten - EventName: Message, Keywords: 2, OpCode: Info
trce: ServiceProfiler.EventPipe.Client.EventListeners.TraceSessionListener[0]
      OnRichPayloadEventWritten - EventName: Message, Keywords: 2, OpCode: Info
.....
..... Keeps printing this until it crashes

Stack Trace (captured from WinDgb)

... Keeps going like this in a loop for a long time
...
000000BE9517AE40 00007ffe50579d9e Microsoft.Extensions.Logging.Logger.Log[[System.__Canon, System.Private.CoreLib]](Microsoft.Extensions.Logging.LogLevel, Microsoft.Extensions.Logging.EventId, System.__Canon, System.Exception, System.Func`3<System.__Canon,System.Exception,System.String>) [/_/src/Logging/Logging/src/Logger.cs @ 50]
000000BE9517AF68 00007ffeafb1b1d6 [StubHelperFrame: 000000be9517af68] 
000000BE9517AFC0 00007ffe505795a7 Microsoft.Extensions.Logging.Logger`1[[System.__Canon, System.Private.CoreLib]].Microsoft.Extensions.Logging.ILogger.Log[[System.__Canon, System.Private.CoreLib]](Microsoft.Extensions.Logging.LogLevel, Microsoft.Extensions.Logging.EventId, System.__Canon, System.Exception, System.Func`3<System.__Canon,System.Exception,System.String>) [/_/src/Logging/Logging.Abstractions/src/LoggerOfT.cs @ 45]
000000BE9517B088 00007ffeafb1b1d6 [StubHelperFrame: 000000be9517b088] 
000000BE9517B0E0 00007ffe505792a2 Microsoft.Extensions.Logging.LoggerExtensions.Log(Microsoft.Extensions.Logging.ILogger, Microsoft.Extensions.Logging.LogLevel, Microsoft.Extensions.Logging.EventId, System.Exception, System.String, System.Object[]) [/_/src/Logging/Logging.Abstractions/src/LoggerExtensions.cs @ 397]
000000BE9517B150 00007ffe512513aa ServiceProfiler.EventPipe.Client.EventListeners.TraceSessionListener.OnRichPayloadEventWritten(System.Diagnostics.Tracing.EventWrittenEventArgs)
000000BE9517B3F0 00007ffea9253bb1 System.Diagnostics.Tracing.EventSource.DispatchToAllListeners(Int32, System.Guid*, System.Diagnostics.Tracing.EventWrittenEventArgs) [E:\A\_work\644\s\src\mscorlib\shared\System\Diagnostics\Tracing\EventSource.cs @ 2076]
000000BE9517B450 00007ffea9259160 System.Diagnostics.Tracing.EventSource.WriteImpl(System.String, System.Diagnostics.Tracing.EventSourceOptions ByRef, System.Object, System.Guid*, System.Guid*, System.Diagnostics.Tracing.TraceLoggingEventTypes) [E:\A\_work\644\s\src\mscorlib\shared\System\Diagnostics\Tracing\TraceLogging\TraceLoggingEventSource.cs @ 702]
000000BE9517B700 00007ffea9257eb1 System.Diagnostics.Tracing.EventSource.Write[[System.__Canon, System.Private.CoreLib]](System.String, System.Diagnostics.Tracing.EventSourceOptions, System.__Canon) [E:\A\_work\644\s\src\mscorlib\shared\System\Diagnostics\Tracing\TraceLogging\TraceLoggingEventSource.cs @ 219]
000000BE9517B760 00007ffe512506f2 Microsoft.ApplicationInsights.Extensibility.Implementation.RichPayloadEventSource.WriteEvent[[System.__Canon, System.Private.CoreLib]](System.String, System.String, System.Collections.Generic.IDictionary`2<System.String,System.String>, System.__Canon, Int64, System.Diagnostics.Tracing.EventKeywords)
000000BE9517B830 00007ffe50bb163c Microsoft.ApplicationInsights.Extensibility.Implementation.RichPayloadEventSource.Process(Microsoft.ApplicationInsights.Channel.ITelemetry)
000000BE9517B8B0 00007ffe50bae235 Microsoft.Extensions.Logging.ApplicationInsights.ApplicationInsightsLogger.Log[[System.__Canon, System.Private.CoreLib]](Microsoft.Extensions.Logging.LogLevel, Microsoft.Extensions.Logging.EventId, System.__Canon, System.Exception, System.Func`3<System.__Canon,System.Exception,System.String>) [E:\A\_work\419\s\src\ILogger\ApplicationInsightsLogger.cs @ 103]
000000BE9517B9B8 00007ffeafb1b1d6 [StubHelperFrame: 000000be9517b9b8] 
000000BE9517BA10 00007ffe50579d9e Microsoft.Extensions.Logging.Logger.Log[[System.__Canon, System.Private.CoreLib]](Microsoft.Extensions.Logging.LogLevel, Microsoft.Extensions.Logging.EventId, System.__Canon, System.Exception, System.Func`3<System.__Canon,System.Exception,System.String>) [/_/src/Logging/Logging/src/Logger.cs @ 50]
000000BE9517BB38 00007ffeafb1b1d6 [StubHelperFrame: 000000be9517bb38] 
000000BE9517BB90 00007ffe505795a7 Microsoft.Extensions.Logging.Logger`1[[System.__Canon, System.Private.CoreLib]].Microsoft.Extensions.Logging.ILogger.Log[[System.__Canon, System.Private.CoreLib]](Microsoft.Extensions.Logging.LogLevel, Microsoft.Extensions.Logging.EventId, System.__Canon, System.Exception, System.Func`3<System.__Canon,System.Exception,System.String>) [/_/src/Logging/Logging.Abstractions/src/LoggerOfT.cs @ 45]
000000BE9517BC58 00007ffeafb1b1d6 [StubHelperFrame: 000000be9517bc58] 
000000BE9517BCB0 00007ffe505792a2 Microsoft.Extensions.Logging.LoggerExtensions.Log(Microsoft.Extensions.Logging.ILogger, Microsoft.Extensions.Logging.LogLevel, Microsoft.Extensions.Logging.EventId, System.Exception, System.String, System.Object[]) [/_/src/Logging/Logging.Abstractions/src/LoggerExtensions.cs @ 397]
000000BE9517BD20 00007ffe512513aa ServiceProfiler.EventPipe.Client.EventListeners.TraceSessionListener.OnRichPayloadEventWritten(System.Diagnostics.Tracing.EventWrittenEventArgs)
000000BE9517BFC0 00007ffea9253bb1 System.Diagnostics.Tracing.EventSource.DispatchToAllListeners(Int32, System.Guid*, System.Diagnostics.Tracing.EventWrittenEventArgs) [E:\A\_work\644\s\src\mscorlib\shared\System\Diagnostics\Tracing\EventSource.cs @ 2076]
000000BE9517C020 00007ffea9259160 System.Diagnostics.Tracing.EventSource.WriteImpl(System.String, System.Diagnostics.Tracing.EventSourceOptions ByRef, System.Object, System.Guid*, System.Guid*, System.Diagnostics.Tracing.TraceLoggingEventTypes) [E:\A\_work\644\s\src\mscorlib\shared\System\Diagnostics\Tracing\TraceLogging\TraceLoggingEventSource.cs @ 702]
000000BE9517C2D0 00007ffea9257eb1 System.Diagnostics.Tracing.EventSource.Write[[System.__Canon, System.Private.CoreLib]](System.String, System.Diagnostics.Tracing.EventSourceOptions, System.__Canon) [E:\A\_work\644\s\src\mscorlib\shared\System\Diagnostics\Tracing\TraceLogging\TraceLoggingEventSource.cs @ 219]
000000BE9517C330 00007ffe512506f2 Microsoft.ApplicationInsights.Extensibility.Implementation.RichPayloadEventSource.WriteEvent[[System.__Canon, System.Private.CoreLib]](System.String, System.String, System.Collections.Generic.IDictionary`2<System.String,System.String>, System.__Canon, Int64, System.Diagnostics.Tracing.EventKeywords)
000000BE9517C400 00007ffe50bb163c Microsoft.ApplicationInsights.Extensibility.Implementation.RichPayloadEventSource.Process(Microsoft.ApplicationInsights.Channel.ITelemetry)
000000BE9517C480 00007ffe50bae235 Microsoft.Extensions.Logging.ApplicationInsights.ApplicationInsightsLogger.Log[[System.__Canon, System.Private.CoreLib]](Microsoft.Extensions.Logging.LogLevel, Microsoft.Extensions.Logging.EventId, System.__Canon, System.Exception, System.Func`3<System.__Canon,System.Exception,System.String>) [E:\A\_work\419\s\src\ILogger\ApplicationInsightsLogger.cs @ 103]
000000BE9517C588 00007ffeafb1b1d6 [StubHelperFrame: 000000be9517c588] 
000000BE9517C5E0 00007ffe50579d9e Microsoft.Extensions.Logging.Logger.Log[[System.__Canon, System.Private.CoreLib]](Microsoft.Extensions.Logging.LogLevel, Microsoft.Extensions.Logging.EventId, System.__Canon, System.Exception, System.Func`3<System.__Canon,System.Exception,System.String>) [/_/src/Logging/Logging/src/Logger.cs @ 50]
000000BE9517C708 00007ffeafb1b1d6 [StubHelperFrame: 000000be9517c708] 
000000BE9517C760 00007ffe505795a7 Microsoft.Extensions.Logging.Logger`1[[System.__Canon, System.Private.CoreLib]].Microsoft.Extensions.Logging.ILogger.Log[[System.__Canon, System.Private.CoreLib]](Microsoft.Extensions.Logging.LogLevel, Microsoft.Extensions.Logging.EventId, System.__Canon, System.Exception, System.Func`3<System.__Canon,System.Exception,System.String>) [/_/src/Logging/Logging.Abstractions/src/LoggerOfT.cs @ 45]
000000BE9517C828 00007ffeafb1b1d6 [StubHelperFrame: 000000be9517c828] 
000000BE9517C880 00007ffe505792a2 Microsoft.Extensions.Logging.LoggerExtensions.Log(Microsoft.Extensions.Logging.ILogger, Microsoft.Extensions.Logging.LogLevel, Microsoft.Extensions.Logging.EventId, System.Exception, System.String, System.Object[]) [/_/src/Logging/Logging.Abstractions/src/LoggerExtensions.cs @ 397]
000000BE9517C8F0 00007ffe512513aa ServiceProfiler.EventPipe.Client.EventListeners.TraceSessionListener.OnRichPayloadEventWritten(System.Diagnostics.Tracing.EventWrittenEventArgs)
000000BE9517CB90 00007ffea9253bb1 System.Diagnostics.Tracing.EventSource.DispatchToAllListeners(Int32, System.Guid*, System.Diagnostics.Tracing.EventWrittenEventArgs) [E:\A\_work\644\s\src\mscorlib\shared\System\Diagnostics\Tracing\EventSource.cs @ 2076]
000000BE9517CBF0 00007ffea9259160 System.Diagnostics.Tracing.EventSource.WriteImpl(System.String, System.Diagnostics.Tracing.EventSourceOptions ByRef, System.Object, System.Guid*, System.Guid*, System.Diagnostics.Tracing.TraceLoggingEventTypes) [E:\A\_work\644\s\src\mscorlib\shared\System\Diagnostics\Tracing\TraceLogging\TraceLoggingEventSource.cs @ 702]
000000BE9517CEA0 00007ffea9257eb1 System.Diagnostics.Tracing.EventSource.Write[[System.__Canon, System.Private.CoreLib]](System.String, System.Diagnostics.Tracing.EventSourceOptions, System.__Canon) [E:\A\_work\644\s\src\mscorlib\shared\System\Diagnostics\Tracing\TraceLogging\TraceLoggingEventSource.cs @ 219]
000000BE9517CF00 00007ffe512506f2 Microsoft.ApplicationInsights.Extensibility.Implementation.RichPayloadEventSource.WriteEvent[[System.__Canon, System.Private.CoreLib]](System.String, System.String, System.Collections.Generic.IDictionary`2<System.String,System.String>, System.__Canon, Int64, System.Diagnostics.Tracing.EventKeywords)
000000BE9517CFD0 00007ffe50bb163c Microsoft.ApplicationInsights.Extensibility.Implementation.RichPayloadEventSource.Process(Microsoft.ApplicationInsights.Channel.ITelemetry)
000000BE9517D050 00007ffe50bae235 Microsoft.Extensions.Logging.ApplicationInsights.ApplicationInsightsLogger.Log[[System.__Canon, System.Private.CoreLib]](Microsoft.Extensions.Logging.LogLevel, Microsoft.Extensions.Logging.EventId, System.__Canon, System.Exception, System.Func`3<System.__Canon,System.Exception,System.String>) [E:\A\_work\419\s\src\ILogger\ApplicationInsightsLogger.cs @ 103]
000000BE9517D158 00007ffeafb1b1d6 [StubHelperFrame: 000000be9517d158] 
000000BE9517D1B0 00007ffe50579d9e Microsoft.Extensions.Logging.Logger.Log[[System.__Canon, System.Private.CoreLib]](Microsoft.Extensions.Logging.LogLevel, Microsoft.Extensions.Logging.EventId, System.__Canon, System.Exception, System.Func`3<System.__Canon,System.Exception,System.String>) [/_/src/Logging/Logging/src/Logger.cs @ 50]
000000BE9517D2D8 00007ffeafb1b1d6 [StubHelperFrame: 000000be9517d2d8] 
000000BE9517D330 00007ffe505795a7 Microsoft.Extensions.Logging.Logger`1[[System.__Canon, System.Private.CoreLib]].Microsoft.Extensions.Logging.ILogger.Log[[System.__Canon, System.Private.CoreLib]](Microsoft.Extensions.Logging.LogLevel, Microsoft.Extensions.Logging.EventId, System.__Canon, System.Exception, System.Func`3<System.__Canon,System.Exception,System.String>) [/_/src/Logging/Logging.Abstractions/src/LoggerOfT.cs @ 45]
000000BE9517D3F8 00007ffeafb1b1d6 [StubHelperFrame: 000000be9517d3f8] 
000000BE9517D450 00007ffe505792a2 Microsoft.Extensions.Logging.LoggerExtensions.Log(Microsoft.Extensions.Logging.ILogger, Microsoft.Extensions.Logging.LogLevel, Microsoft.Extensions.Logging.EventId, System.Exception, System.String, System.Object[]) [/_/src/Logging/Logging.Abstractions/src/LoggerExtensions.cs @ 397]
000000BE9517D4C0 00007ffe512513aa ServiceProfiler.EventPipe.Client.EventListeners.TraceSessionListener.OnRichPayloadEventWritten(System.Diagnostics.Tracing.EventWrittenEventArgs)
000000BE9517D760 00007ffea9253bb1 System.Diagnostics.Tracing.EventSource.DispatchToAllListeners(Int32, System.Guid*, System.Diagnostics.Tracing.EventWrittenEventArgs) [E:\A\_work\644\s\src\mscorlib\shared\System\Diagnostics\Tracing\EventSource.cs @ 2076]
000000BE9517D7C0 00007ffea9259160 System.Diagnostics.Tracing.EventSource.WriteImpl(System.String, System.Diagnostics.Tracing.EventSourceOptions ByRef, System.Object, System.Guid*, System.Guid*, System.Diagnostics.Tracing.TraceLoggingEventTypes) [E:\A\_work\644\s\src\mscorlib\shared\System\Diagnostics\Tracing\TraceLogging\TraceLoggingEventSource.cs @ 702]
000000BE9517DA70 00007ffea9257eb1 System.Diagnostics.Tracing.EventSource.Write[[System.__Canon, System.Private.CoreLib]](System.String, System.Diagnostics.Tracing.EventSourceOptions, System.__Canon) [E:\A\_work\644\s\src\mscorlib\shared\System\Diagnostics\Tracing\TraceLogging\TraceLoggingEventSource.cs @ 219]
000000BE9517DAD0 00007ffe512506f2 Microsoft.ApplicationInsights.Extensibility.Implementation.RichPayloadEventSource.WriteEvent[[System.__Canon, System.Private.CoreLib]](System.String, System.String, System.Collections.Generic.IDictionary`2<System.String,System.String>, System.__Canon, Int64, System.Diagnostics.Tracing.EventKeywords)
000000BE9517DBA0 00007ffe50bb163c Microsoft.ApplicationInsights.Extensibility.Implementation.RichPayloadEventSource.Process(Microsoft.ApplicationInsights.Channel.ITelemetry)
000000BE9517DC20 00007ffe50bc9984 Microsoft.ApplicationInsights.AspNetCore.Logging.ApplicationInsightsLogger.Log[[System.__Canon, System.Private.CoreLib]](Microsoft.Extensions.Logging.LogLevel, Microsoft.Extensions.Logging.EventId, System.__Canon, System.Exception, System.Func`3<System.__Canon,System.Exception,System.String>)
000000BE9517DD38 00007ffeafb1b1d6 [StubHelperFrame: 000000be9517dd38] 
000000BE9517DD90 00007ffe50579d9e Microsoft.Extensions.Logging.Logger.Log[[System.__Canon, System.Private.CoreLib]](Microsoft.Extensions.Logging.LogLevel, Microsoft.Extensions.Logging.EventId, System.__Canon, System.Exception, System.Func`3<System.__Canon,System.Exception,System.String>) [/_/src/Logging/Logging/src/Logger.cs @ 50]
000000BE9517DEB8 00007ffeafb1b1d6 [StubHelperFrame: 000000be9517deb8] 
000000BE9517DF10 00007ffe505795a7 Microsoft.Extensions.Logging.Logger`1[[System.__Canon, System.Private.CoreLib]].Microsoft.Extensions.Logging.ILogger.Log[[System.__Canon, System.Private.CoreLib]](Microsoft.Extensions.Logging.LogLevel, Microsoft.Extensions.Logging.EventId, System.__Canon, System.Exception, System.Func`3<System.__Canon,System.Exception,System.String>) [/_/src/Logging/Logging.Abstractions/src/LoggerOfT.cs @ 45]
000000BE9517DFD8 00007ffeafb1b1d6 [StubHelperFrame: 000000be9517dfd8] 
000000BE9517E030 00007ffe505792a2 Microsoft.Extensions.Logging.LoggerExtensions.Log(Microsoft.Extensions.Logging.ILogger, Microsoft.Extensions.Logging.LogLevel, Microsoft.Extensions.Logging.EventId, System.Exception, System.String, System.Object[]) [/_/src/Logging/Logging.Abstractions/src/LoggerExtensions.cs @ 397]
000000BE9517E0A0 00007ffe5123dd05 ServiceProfiler.EventPipe.Client.ServiceProfilerProvider.StartServiceProfilerAsync(Microsoft.ServiceProfiler.Orchestration.IProfilerSource)
000000BE9517E190 00007ffe5123c8c2 Microsoft.ServiceProfiler.EventPipe.Orchestration.OrchestratorEventPipe+d__2.MoveNext() [E:\A\_work\366\s\src\ServiceProfiler.EventPipe\ServiceProfiler.EventPipe.Orchestration\OrchestratorEventPipe.cs @ 82]
000000BE9517E250 00007ffe5123b569 System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[[Microsoft.ServiceProfiler.EventPipe.Orchestration.OrchestratorEventPipe+d__2, Microsoft.ServiceProfiler.EventPipe.Orchestration]](d__2 ByRef) [E:\A\_work\644\s\src\mscorlib\src\System\Runtime\CompilerServices\AsyncMethodBuilder.cs @ 958]
000000BE9517E2C0 00007ffe5123a585 Microsoft.ServiceProfiler.EventPipe.Orchestration.OrchestratorEventPipe.StartProfilingAsync(Microsoft.ServiceProfiler.Orchestration.SchedulingPolicy, System.Threading.CancellationToken)
000000BE9517E330 00007ffe5123753b Microsoft.ServiceProfiler.Orchestration.SchedulingPolicy+d__1.MoveNext()
000000BE9517E490 00007ffe51233169 System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[[Microsoft.ServiceProfiler.Orchestration.SchedulingPolicy+d__1, Microsoft.ServiceProfiler.Orchestration]](d__1 ByRef) [E:\A\_work\644\s\src\mscorlib\src\System\Runtime\CompilerServices\AsyncMethodBuilder.cs @ 958]
000000BE9517E500 00007ffe51232eb3 Microsoft.ServiceProfiler.Orchestration.SchedulingPolicy.StartPolicyAsync(System.Threading.CancellationToken)
000000BE9517E5A0 00007ffe50fc66af Microsoft.ServiceProfiler.EventPipe.Orchestration.OrchestratorEventPipe+d__1.MoveNext() [E:\A\_work\366\s\src\ServiceProfiler.EventPipe\ServiceProfiler.EventPipe.Orchestration\OrchestratorEventPipe.cs @ 60]
000000BE9517E670 00007ffea9170af9 System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object) [E:\A\_work\644\s\src\mscorlib\shared\System\Threading\ExecutionContext.cs @ 167]
000000BE9517E6F0 00007ffe51231857 System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[[System.Threading.Tasks.VoidTaskResult, System.Private.CoreLib],[Microsoft.ServiceProfiler.EventPipe.Orchestration.OrchestratorEventPipe+d__1, Microsoft.ServiceProfiler.EventPipe.Orchestration]].MoveNext() [E:\A\_work\644\s\src\mscorlib\src\System\Runtime\CompilerServices\AsyncMethodBuilder.cs @ 568]
000000BE9517E750 00007ffea925c954 System.Threading.Tasks.AwaitTaskContinuation.RunOrScheduleAction(System.Runtime.CompilerServices.IAsyncStateMachineBox, Boolean) [E:\A\_work\644\s\src\mscorlib\src\System\Threading\Tasks\TaskContinuation.cs @ 798]
000000BE9517E7B0 00007ffea9225d63 System.Threading.Tasks.Task.RunContinuations(System.Object) [E:\A\_work\644\s\src\mscorlib\src\System\Threading\Tasks\Task.cs @ 3258]
000000BE9517E880 00007ffea928bbbd System.Threading.Tasks.Task`1[[System.Threading.Tasks.VoidTaskResult, System.Private.CoreLib]].TrySetResult(System.Threading.Tasks.VoidTaskResult) [E:\A\_work\644\s\src\mscorlib\src\System\Threading\Tasks\future.cs @ 424]
000000BE9517E8C0 00007ffea9266bfc System.Threading.Tasks.Task+DelayPromise.Complete() [E:\A\_work\644\s\src\mscorlib\src\System\Threading\Tasks\Task.cs @ 5453]
000000BE9517E900 00007ffea9170af9 System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object) [E:\A\_work\644\s\src\mscorlib\shared\System\Threading\ExecutionContext.cs @ 167]
000000BE9517E980 00007ffea926731c System.Threading.TimerQueueTimer.CallCallback() [E:\A\_work\644\s\src\mscorlib\src\System\Threading\Timer.cs @ 610]
000000BE9517E9E0 00007ffea926710a System.Threading.TimerQueueTimer.Fire() [E:\A\_work\644\s\src\mscorlib\src\System\Threading\Timer.cs @ 569]
000000BE9517EA50 00007ffea925ea32 System.Threading.ThreadPoolWorkQueue.Dispatch() [E:\A\_work\644\s\src\mscorlib\src\System\Threading\ThreadPool.cs @ 588]
000000BE9517EED0 00007ffeafb1a673 [DebuggerU2MCatchHandlerFrame: 000000be9517eed0] 

Workaround

services.Configure<LoggerFilterOptions>(opts =>
 {
     opts.AddFilter("ServiceProfiler.EventPipe.Client.EventListeners.TraceSessionListener", LogLevel.Debug);
});

[xiaomi7732]

Hi @andscho-msft thank you so much for reporting this. I'll look into this when there's cycle.