TraceEvent - Exception "Read past end of stream." processing .nettrace file when a program exits with an exception

[ivberg]

1. If you compile this code and gather a .nettrace TraceEvent

Console.WriteLine("Hello, World!");

throw new Exception("This in an exception");

2. Collect a trace with dotnet-trace collect -- bin/Debug/net6.0/TestApp

3. Trace will collect fine ..... [00:00:00:00] Recording trace 59.795 (KB) Press <Enter> or <Ctrl+C> to exit...

Trace completed. Process exited with code '134'.

5. TraceEvent will throw an exception Unable to process 'file:///TestApp_20220521_150059.nettrace': System.Exception: Read past end of stream. at FastSerialization.IOStreamStreamReader.Fill(Int32 minimum) at FastSerialization.MemoryStreamReader.ReadByte() at FastSerialization.Deserializer.ReadTag() at FastSerialization.Deserializer.ReadObject() at Microsoft.Diagnostics.Tracing.EventPipeEventSource.Process()

[noahfalk]

Thanks @ivberg! I can see different angles to approach this from, not sure which you had in mind?

1. We could try to do work in the runtime to complete the stream gracefully in a broader set of circumstances. This will never be 100% (an app could call TerminateProcess()) but there is probably room to decide between 99%, 99.9%, 99.99%, etc.
2. We could modify dotnet-trace to better recognize when a trace is incomplete and show a warning on the console when it is collected.
3. Assuming TraceEvent is parsing an incomplete .nettrace file (as-is the case here), we could modify how it responds. I assume we wouldn't want to surpress the error entirely, but we might throw a different exception that makes it clear that the file is incomplete.

[ivberg]

Some of this I guess depends on the architecture of how dotnet-trace works under the hood. I was thinking (1) more, so that dotnet-trace could complete the trace gracefully on fatal exception. I had assumed that some of this tracing was done out of process since you can attach or start from launch a .NET program. But maybe it's not and this is why a .NET terminate could mess up the trace. Today the trace implies it's fine from just the console output.

I would assume this would be a case where a dev would want a complete trace at times that led to an exception. Right now you would have to SysInternals procdump, a .dmp, or the event log to see the exception.

[noahfalk]

I had assumed that some of this tracing was done out of process

All the event generation and the file format serialization logic is in-proc today. dotnet-trace is responsible for writing the final bits to disk, but all it is doing is copying byte for byte data that it is receiving from the runtime via a named pipe or unix domain socket. Technically dotnet-trace could parse all the data it received, recognize the file format was incomplete and write a terminator on there, but it would still leave some issues:

• none of the rundown events would be present
• not all scenarios that write the .nettrace file use a 2nd process (example)

Today the trace implies it's fine from just the console output

Yeah, this could certainly be improved, its (2) above.

I would assume this would be a case where a dev would want a complete trace at times that led to an exception. Right now you would have to SysInternals procdump, a .dmp, or the event log to see the exception.

All the events leading up to the exception should still be useable. Were you seeing different results? For example when I parse the trace like this:

using Microsoft.Diagnostics.Tracing;
EventPipeEventSource s = new EventPipeEventSource(@"E:\temp\exception\exception.exe_20220523_162446.nettrace");
s.Clr.ExceptionStart += e => Console.WriteLine(e);
s.Process();

It prints this before throwing the 'Read past end of stream' exception

<Event MSec=    "39.7151" PID="29160" PName="Process(29160)" TID="28088" EventName="Exception/Start" ExceptionType="System.Exception" ExceptionMessage="This in an exception" ExceptionEIP="0x00007FFA0A3FA853" ExceptionHRESULT="0xFFFFFFFF80131500" ExceptionFlags="CLSCompliant" ClrInstanceID="8"/>

[ivberg]

Thanks @noahfalk ! All the details you provided make sense. Surprised the trace processes the trace until the exception. I guess I had assumed the whole-trace was unreadable when I saw the "read past end of stream' exception. It seems the TraceEvent library is doing the right thing, in processing as much of the trace as it can, and then leaving it up to the caller to decide what to do next (via the exception).

Speaking of which, the traces for this scenario were also unreadable by perfview - which is perhaps why I also had assumed what I did. It seems like fixing this in perfview would be good as well?

[ivberg]

Actually it turns out your example with EventPipeEventSource does have the behavior your describe.

However, I am using TraceLog.CreateFromEventPipeDataFile() which throws the exception right away before processing events. I currently need to use this method to get access to stacks.

            string traceLogPath = TraceLog.CreateFromEventPipeDataFile(TracePath);
            using (TraceLog traceLog = new TraceLog(traceLogPath))
            {
                TraceLogEventSource source = traceLog.Events.GetSource();

Full example from @brianrob - https://github.com/brianrob/tests/blob/master/managed/eventpipe-stacks/Program.cs This would throw that exception right away before processing events.

[noahfalk]

Got it, makes sense. @brianrob, do you think we should change the TraceLog behavior to make it more resilient to incomplete state? I know PerfView has the /continueOnError flag but I haven't looked into how that was plumbed through yet.

[brianrob]

When creating the TraceLog, you can specify TraceLogOptions.ContinueOnError which is what gets set if you specify /continueOnError. This effectively tells TraceLog to assume that the trace ended here and continue. In the case that parsing fails, I would recommend using this option to complete the ETLX so that you can analyze it. The default option is to fail so that you know something went wrong, but you then have the option to continue if you want.

I do think it would be good to harden the collection scenarios too if there is room here. For the most part, I would not expect an app that crashes due to an exception to fail to shutdown tracing (unless it hangs on shutdown and the thread is terminated). I suspect there will always be cases where things fall down, and so we'll always want the option to continue when an error is encountered.