dotnet-trace: unhandled exception results in a broken trace

[CarnaViire]

Description

Unhandled exception in a program results in a broken trace collected by dotnet-trace. (If I catch the exception, the produced trace is OK)

Steps to reproduce:

1. Run a program via dotnet run -c release
2. Start collecting the trace via dotnet-trace collect -p <PID>
3. At some point the program throws an unhandled exception and exits
4. dotnet-trace exits too, says Trace completed. and produces a trace file

However, that trace file would be broken.

When trying to open it in PerfView, the error is

[ERROR: processing events ****]
***** Consider using /ContinueOnError to ignore the bad part of the trace.  *****
Error: Exception EventPipe conversion: System.Exception: Read past end of stream.
   at FastSerialization.IOStreamStreamReader.Fill(Int32 minimum)
   at FastSerialization.MemoryStreamReader.ReadByte()
   at FastSerialization.Deserializer.ReadObject()
   at Microsoft.Diagnostics.Tracing.EventPipeEventSource.Process()
   at Microsoft.Diagnostics.Tracing.Etlx.TraceLog.CopyRawEvents(TraceEventDispatcher rawEvents, IStreamWriter writer)
   at Microsoft.Diagnostics.Tracing.Etlx.TraceLog.<>c__DisplayClass120_0.<FastSerialization.IFastSerializable.ToStream>b__0()
   at FastSerialization.DeferedRegion.Write(Serializer serializer, Action toStream)
   at Microsoft.Diagnostics.Tracing.Etlx.TraceLog.FastSerialization.IFastSerializable.ToStream(Serializer serializer)
   at FastSerialization.Serializer.WriteObjectData(IFastSerializable obj, Tags beginTag)
   at FastSerialization.Serializer.WriteObjectRef(IFastSerializable obj, Boolean defered)
   at FastSerialization.Serializer..ctor(IStreamWriter writer, IFastSerializable entryObject)
   at Microsoft.Diagnostics.Tracing.Etlx.TraceLog.CreateFromEventPipeEventSources(TraceEventDispatcher source, String etlxFilePath, TraceLogOptions options)
   at Microsoft.Diagnostics.Tracing.Etlx.TraceLog.CreateFromEventPipeDataFile(String filePath, String etlxFilePath, TraceLogOptions options)
   at PerfView.EventPipePerfViewData.GetTraceLog(TextWriter log, Action`3 onLostEvents)
[Error: exception while opening EventPipe data.]

When trying to convert it to Speedscope format, via dotnet-trace convert, it would say

Detected a potentially broken trace. Continuing with best-efforts to convert the trace, but resulting speedscope file may contain broken stacks as a result.

and produce an empty result.

Configuration

OS: Windows 11
dotnet-trace version: 6.0.257301+27172ce4d05e8a3b0ffdefd65f073d40a1b1fe54
.NET SDK version: 7.0 Preview 2
App's target framework: net6.0 (.NET 6.0.2)

[mikelle-rogers]

Hi @CarnaViire, that is expected behavior. To understand what causes the exception, please set the environment variable COMPlus_DbgEnableMiniDump = 1, as explained here. This will cause a dump to be collected when the program throws the exception. Feel free to reach out with any questions!

[CarnaViire]

Hi @mikelle-rogers -- But what is the reason why the behavior is like this?
For example, there were situations where I don't need the dump on the exception, but I care about traces/logs of the behavior that led to this exception. Imagine frustration if you e.g. managed to capture some rare race condition on the trace and then you cannot load it because the trace became broken...

It might be also nice to have the message mention that the trace collecting was unsuccessful and the trace is broken. Right now it says "Trace completed." just as if everything is ok, and I learn it's not ok only after trying to open it in PerfView... this is very confusing.

[mikelle-rogers]

@CarnaViire Thank you for voicing your concerns, the trace is truncated because when an unhandled exception is hit by the runtime, the runtime rips apart immediately to prevent breaking other parts of the program. This includes closing the socket/NamedPipe that the trace is being streamed over.

Even though the trace is broken, it can still be opened to see what happened leading up to the failure, but will be missing Rundown information (this happens at the end of a trace) so stacks might be unresolved (depending on what providers were turned on). Opening the trace is done by executing PerfView with the /ContinueOnError flag at the command line.

What are you expecting to see in the traces/logs that led to the exception?
The logs will contain the location the exception was fired.

Making dotnet-trace aware of a broken trace is quite difficult because dotnet-trace knows little of the target process other than it is being traced and sending data. dotnet-trace does not inspect the data as it arrives. It could validate the trace after completion, but that can be expensive if the traces are long.

[CarnaViire]

Thanks a lot for explaining the limitations @mikelle-rogers! And I didn't know about /ContinueOnError, that's good to know!

As for what I look at the traces for -- I'm on .NET Networking team, so a lot of the time I find myself looking at HTTP telemetry, and things might get highly concurrent there and some painful race conditions are sometimes extremely hard to reproduce. And most of the time you're more interested in what happened before the exception, rather than its stacktrace. That's why I raised the concern, and because the current behavior seemed counter-intuitive to me.

I understand the limitations now, but maybe it would be useful to document that as a note in https://docs.microsoft.com/en-us/dotnet/core/diagnostics/dotnet-trace ?

[mikelle-rogers]

@CarnaViire I will make that note in the dotnet-trace documentation. Did using /ContinueOnError provide useful information?

[CarnaViire]

Did using /ContinueOnError provide useful information?

Yes, with it I'm able to open the trace and see the networking events I collected 👍