DotnetLog.Reader 1.0.0

DotnetLog.Reader

A library for reading the log produced by the dotnet-log tool.

The log is a JSONL file: one line per event, where entering a method and leaving it are two separate lines. Such a file is impossible to read by eye, and the most useful thing — "who called whom" — is not visible in a flat list of lines at all. This library glues every "enter + exit" pair into a single object and links the calls into a tree, after which any question about the log is one line of C#.

using DotnetLog.Reader.BuildingCallTree;

var log = CallLog.LoadFromFile("dotnet-log.jsonl");

// how many times each method was called
log.Calls.GroupBy(call => call.FullMethodName);

// what failed and who called it
foreach (var failed in log.Calls.Where(call => call.ThrownException is not null))
    foreach (var above in failed.AllCallsAbove)
        Console.WriteLine(above.FullMethodName);

Target framework: net8.0. Package: DotnetLog.Reader.

What is inside

Public API

Everything below is the full public surface you can use. Method bodies and internals are omitted; the signatures are exactly as they are in the library.

DotnetLog.Reader.BuildingCallTree

CallLog — the main entry point

The whole log loaded into memory: calls already paired and linked into a tree.

public sealed class CallLog
{
    // Read the whole file and build the tree. The usual way to start.
    public static CallLog LoadFromFile(string filePath);

    // Same, but from any sequence of entries: streaming with a filter,
    // tests, or several files merged into one log.
    public static CallLog BuildFromEntries(IEnumerable<LogEntry> entries);

    // Every call, in the order they started. A plain list — Where, GroupBy, OrderBy all work.
    public IReadOnlyList<CallRecord> Calls { get; }

    // Calls nobody called ("pid": 0 in the log) — the tops of the trees.
    // Effectively the list of separate operations: one HTTP request handled = one root call.
    public IReadOnlyList<CallRecord> RootCalls { get; }

    // How many records the logger lost because its queue overflowed ("dropped" lines).
    // Above zero means the tree has holes, and it is better to know that up front.
    public int HowManyRecordsWereDropped { get; }

    // Path to the file everything was read from. Empty when the log was built from entries.
    public string FilePath { get; }

    // Find a call by its number. null when there is no such number in the log.
    public CallRecord? FindCallById(long callId);

    // Write the given calls into a separate file as the original JSONL lines, not as some
    // own format. The slice stays a real log: it can be opened again with this same library
    // and attached to a ticket when the whole log is too big.
    public void SaveCallsToFile(IEnumerable<CallRecord> calls, string filePath);
}

CallRecord — one method call

One glued "enter + exit" pair plus the links to its neighbours in the tree.

public sealed class CallRecord
{
    // --- identity ---

    // Call number, field "id". Unique within one run of the application.
    public long CallId { get; }

    // Full class name: "SampleApp.Account".
    public string TypeName { get; }

    // Method signature: "Task<Int32> SumAsync(Int32, Int32, Int32)".
    public string MethodSignature { get; }

    // Class and method on one line. A ready-made grouping key:
    // GroupBy(call => call.FullMethodName) answers "how often was this method called".
    public string FullMethodName { get; }

    // --- values ---

    // Argument values by parameter name.
    public IReadOnlyDictionary<string, LogValue> ArgumentValues { get; }

    // State of the object on entry — the "this" block. null when there is none.
    public LogValue? ObjectStateValue { get; }

    // What the method returned. null when the method returns nothing,
    // or when there is no exit line in the log.
    public LogValue? ReturnedValue { get; }

    // Values of out-parameters by name: they only appear on exit.
    public IReadOnlyDictionary<string, LogValue> OutParameterValues { get; }

    // The exception, when the method failed. null otherwise.
    public LoggedException? ThrownException { get; }

    // --- time ---

    // When the entry into the method was written.
    public DateTimeOffset StartedAt { get; }

    // How long the call ran. null when there is no exit line in the log.
    public TimeSpan? HowLongItRan { get; }

    // How much time the call spent by itself, without the nested calls. If a method ran
    // 300 ms but waited 295 of them on a nested call, it is not the guilty one — and this
    // property shows exactly that. Zero when there is no exit line to measure against.
    public TimeSpan TimeSpentByItself { get; }

    // How it all ended: Returned / ReturnedAfterAwait / Failed / NeverFinished.
    public CallEnding HowItEnded { get; }

    // --- position in the tree ---

    // Nesting depth: 0 at the top of the chain.
    public int NestingLevel { get; }

    // Number of the thread the method was entered on.
    public int ThreadNumber { get; }

    // Who called this method. null at the top of the chain ("pid": 0 in the log).
    public CallRecord? ParentCall { get; }

    // Whom this method called, in call order. Empty list for a leaf of the tree.
    public IReadOnlyList<CallRecord> ChildCalls { get; }

    // The whole way up: the parent, its parent, and so on to the top. Bottom-up.
    public IEnumerable<CallRecord> AllCallsAbove { get; }

    // The whole subtree down: children, children of children, and so on.
    // Top-down, in call order.
    public IEnumerable<CallRecord> AllCallsBelow { get; }

    // Top of the chain — the call everything started with, e.g. handling an HTTP request.
    // For the top call itself this is the call itself.
    public CallRecord RootCall { get; }

    // --- raw lines ---

    // The "enter" line exactly as it is in the file — the source this object was built from.
    public LogEntry EnterEntry { get; }

    // The paired exit line ("exit" / "async-exit" / "error"); null when there is no pair.
    public LogEntry? ExitEntry { get; }

    // Does this text occur in the arguments, object state, returned value, out-parameter
    // values or error message. The search goes into nested objects as well.
    public bool HasTextInside(string textToFind);

    // Short line for printing: method name and how it ended.
    public override string ToString();
}

CallEnding — how a call ended

One enum instead of checking three fields by hand.

public enum CallEnding
{
    Returned,           // the method returned normally — "exit" in the log
    ReturnedAfterAwait, // an async method whose task really completed — "async-exit"
    Failed,             // an exception flew out of the method — "error"
    NeverFinished,      // there is an entry but no exit: the application was killed
                        // mid-work, or the records were lost to queue overflow
}

DotnetLog.Reader.ReadingValues

LogValue — one logged value

An argument, a field of an object, a returned value. In the file it is a piece of JSON of arbitrary shape — a number here, a string there, a nested object elsewhere. This class hides the JSON parsing and offers simple questions instead.

public sealed class LogValue
{
    // Wraps an already parsed piece of JSON. Usually you get instances from CallRecord,
    // not by calling this yourself.
    public LogValue(JsonElement value);

    // The value as a string. null when it is not a string.
    public string? AsText();

    // The value as a number of the type you ask for: AsNumber<int>(), AsNumber<double>().
    // null when it is not a number, or when it does not fit into the requested type.
    public TNumber? AsNumber<TNumber>();

    // The value as true/false. null when it is not a boolean.
    public bool? AsBoolean();

    // The elements, when the value is an array. Empty list when it is not.
    public IReadOnlyList<LogValue> AsList();

    // The fields and properties, when the value is an object. Empty dictionary when it is not.
    public IReadOnlyDictionary<string, LogValue> AsMembers();

    // Get a nested member by name: value["_cache"]?["Count"].
    // Returns null when there is no such member or the value is not an object at all,
    // so long ?. chains do not blow up on an unexpected shape of the data.
    public LogValue? this[string memberName] { get; }

    // Is this text somewhere inside — descending into nested objects and arrays.
    // The main way to answer "where did the value user:7 ever show up".
    public bool HasTextInside(string textToFind);

    // True when the serializer refused to write the value in full and put a placeholder
    // instead: "<max-depth>", "<cycle>", "<lazy: …>", "<error: …>". Without this check it
    // is easy to mistake a placeholder for a real string.
    public bool IsCutByLimit { get; }

    // The placeholder text without the angle brackets when the value is cut; null otherwise.
    // For example "max-depth" or "lazy: IEnumerable<Int32>".
    public string? WhyItIsCut { get; }

    // The original JSON of this value, in case you need exactly that.
    public string ToJsonText();

    // Short readable form for printing to the console: a string is given without quotes,
    // everything else as in the file.
    public override string ToString();
}

LoggedException — an exception as it was logged

This cannot be a real Exception: the exception type lives in someone else's application and its assemblies are not here — there are only the three strings the logger managed to write.

public sealed record LoggedException(
    string TypeName,    // "System.InvalidOperationException"
    string Message,     // "Connection closed"
    string? StackText); // the stack trace as text; null when the logger did not write it

DotnetLog.Reader.ReadingLogFile

The lowest layer: it glues and links nothing, it just turns a JSONL line into an object. Useful on its own for huge files that must not be loaded whole, and for the "live tail".

CallLogFile — reading the file line by line

public static class CallLogFile
{
    // Walk the file and hand out entries one at a time. Memory needed is one line, so a file
    // of any size can be read this way. There is no tree here — that is what CallLog is for.
    public static IEnumerable<LogEntry> ReadEntriesOneByOne(
        string filePath,
        LogFileReadingOptions? options = null);
}

LogFileReadingOptions — reading settings

All of them have defaults, so usually you do not need this class at all.

public sealed class LogFileReadingOptions
{
    // Do not stop at the end of the file, wait for new lines while the application runs.
    // This is the replacement for "tail --follow": watching the log live. Default: false.
    public bool KeepWatchingFile { get; init; }

    // How long to wait between attempts when the file has ended but reading continues.
    // Too often wastes CPU, too rarely adds a noticeable delay. Default: 200 milliseconds.
    public TimeSpan HowLongToWaitForNewLines { get; init; }

    // Skip lines that could not be parsed. Default: true, and here is why — the last line of
    // the file is almost always cut in half because the application was killed while the
    // buffer was being written. Blowing up over that mid-read would be pointless.
    public bool SkipBrokenLines { get; init; }

    // Where to report a skipped line — e.g. print a warning to the console. The first
    // argument is the line itself, the second is what exactly failed to parse.
    public Action<string, Exception>? WhenLineCannotBeRead { get; init; }
}

LogEntry — one line of the file as it is

Half of the properties are not always filled: an "exit" line has no class or method name (they are not duplicated, so the file does not double in size), an "enter" line has no returned value and no duration. That is the price of a compact file — and exactly what CallRecord hides by gluing a pair of lines into one object.

public sealed class LogEntry
{
    // Parse one line of the file. positionInFile is the byte offset of the line from the
    // start of the file — the index over a big file needs it.
    public static LogEntry ReadFromJsonLine(string jsonLine, long positionInFile = 0);

    public LogEntryKind Kind { get; }          // enter, exit, error and so on — field "ev"
    public DateTimeOffset WrittenAt { get; }   // when the event was written — field "ts"
    public long CallId { get; }                // call number, field "id"; pairs are glued by it
    public long ParentCallId { get; }          // caller's number, field "pid"; zero = nobody called us
    public long RootCallId { get; }            // number of the topmost call of the chain, field "root"
    public int NestingLevel { get; }           // nesting depth, field "d"
    public int ThreadNumber { get; }           // thread number, field "th"

    public string? TypeName { get; }           // full class name, field "type"; only on entry
    public string? MethodSignature { get; }    // method signature, field "sig"; only on entry

    public IReadOnlyDictionary<string, LogValue> ArgumentValues { get; }     // field "args"
    public LogValue? ObjectStateValue { get; }                               // field "this"
    public LogValue? ReturnedValue { get; }                                  // field "ret"
    public IReadOnlyDictionary<string, LogValue> OutParameterValues { get; } // field "out"
    public LoggedException? ThrownException { get; }                         // field "ex"

    public double? HowManyMillisecondsItRan { get; }  // duration of the call, field "ms"
    public int HowManyRecordsWereDropped { get; }     // only on Dropped lines, otherwise 0
    public long PositionInFile { get; }               // byte offset of this line in the file

    // The original JSONL line — so a slice file can be rewritten without any loss.
    public string ToJsonText();
}

LogEntryKind — what kind of line it is

This is field "ev" from the log.

public enum LogEntryKind
{
    Enter,          // "enter" — entering a method
    Exit,           // "exit" — a normal return from a method
    ExitAfterAwait, // "async-exit" — an async method whose task really completed
    Error,          // "error" — an exception flew out of the method
    Dropped,        // "dropped" — the queue overflowed, that many records were lost
    Unknown,        // a line of an unknown shape, e.g. a log from a newer logger version
}

DotnetLog.Reader.DrawingCallTree

CallTreeText — the tree as indented text

The main way to look at the log with your eyes.

public static class CallTreeText
{
    // Draw the tree starting from the given call and return it as text.
    public static string Draw(CallRecord topCall, CallTreeTextOptions? options = null);
}

CallTreeTextOptions — printing settings

public sealed class CallTreeTextOptions
{
    // Print the values (arguments, object state, returned value, out-parameters).
    // Turn it off and only method names remain — the tree gets compact and fits more
    // levels on screen. Default: true.
    public bool ShowValues { get; init; }

    // How deep to unfold the subtree. Default: 2 — the whole tree usually does not fit
    // on a screen.
    public int HowManyLevelsDown { get; init; }

    // Mark this one line with a "you were looking for this" sign, so it is not lost
    // among the others in a big tree. Default: null (nothing marked).
    public CallRecord? MarkThisCall { get; init; }

    // Cut long values down to this many characters, otherwise the tree sprawls sideways
    // and becomes unreadable. Default: 120.
    public int HowManyCharactersPerValue { get; init; }
}

CallTreeMermaid — the tree as a Mermaid diagram

Mermaid is a way to describe a diagram with words instead of drawing it with a mouse. Such text turns into a picture right inside a ticket, on GitHub and in most markdown editors, so the diagram is convenient to attach to an incident write-up.

public static class CallTreeMermaid
{
    // Returns the text of a sequence diagram — paste it into a ticket or a README.
    public static string Draw(CallRecord topCall);
}

CallTreeChromeTrace — the tree as a flame graph

The resulting file opens in Perfetto or in chrome://tracing and shows a flame graph: every call is a rectangle as wide as its duration, nested calls sit under their parent. On such a picture you immediately see who was really taking the time.

public static class CallTreeChromeTrace
{
    // Returns JSON understood by Perfetto and chrome://tracing.
    public static string Draw(CallRecord topCall);
}

DotnetLog.Reader.FindingCallsInBigFile

CallLogIndex — pinpoint reads from a huge file

An index of "which call sits where in the file". It lets you read one call and its ancestors out of a multi-gigabyte file without loading the file: per call it remembers only the call number, the caller number and two byte offsets.

The difference from CallLog matters and is worth keeping in mind: CallLog reads the whole file and links everything; the index reads only the requested lines, so it only has links between what has actually been read.

public sealed class CallLogIndex
{
    // Walk the file once and remember the offsets. The lines themselves are not stored.
    public static CallLogIndex BuildForFile(string logFilePath);

    // Read a ready-made index from disk instead of building it again.
    public static CallLogIndex LoadFromFile(string indexFilePath);

    // Save the index next to the log (usually log.jsonl.idx). The format is simple and
    // human-readable: first line is the path to the log, then one line per call —
    // number, caller number, offset of the enter line, offset of the exit line.
    public void SaveToFile(string indexFilePath);

    // Read one call by its number: only its two lines are read from the file.
    // Careful — the returned object has neither caller nor callees, because nobody read
    // the neighbours. If you need the ancestors, use ReadAllCallsAbove.
    public CallRecord? ReadCallById(long callId);

    // Read the call together with the whole way up to the top of the chain. As many lines
    // are read as the stack is deep — usually a handful. The returned calls are already
    // linked to each other. Order is bottom-up: the call itself, then its caller, and so on.
    public IReadOnlyList<CallRecord> ReadAllCallsAbove(long callId);

    // Read the calls made by the given call — one level down.
    public IReadOnlyList<CallRecord> ReadChildCallsOf(long callId);

    // Path to the log file this index was built for.
    public string LogFilePath { get; }

    // How many calls made it into the index — also a check that the file was parsed whole.
    public int HowManyCallsAreIndexed { get; }
}

IndexedCall — what the index remembers about one call

The lines themselves are not here — that is the whole point: remember the place, not the content, so an index over a gigabyte-sized file takes only a few megabytes itself.

public readonly record struct IndexedCall(
    long CallId,        // call number
    long ParentCallId,  // number of whoever called it; 0 means the top of the chain
    long EnterPosition, // byte offset of the enter line from the start of the file
    long ExitPosition); // byte offset of the exit line; -1 when there is no exit in the log

Full examples

Every example below is a single-file .NET 10 application: copy it into a file and run it right away, no project needed:

dotnet run 01-summary.cs dotnet-log.jsonl

The first line of each file is a #:package directive: it tells dotnet run which NuGet package to reference. After that comes ordinary code, without class Program and Main.

The repository's examples/ folder holds runnable versions of these scripts together with a small ready log, sample-log.jsonl — so the examples can be tried out without instrumenting anything yet. Every output shown below was produced by actually running the example against that sample log.

1. What is in this log at all

#:package DotnetLog.Reader@1.0.0
using DotnetLog.Reader.BuildingCallTree;

var log = CallLog.LoadFromFile(args[0]);

Console.WriteLine($"Calls in total: {log.Calls.Count}");
Console.WriteLine($"Separate operations (root calls): {log.RootCalls.Count}");
Console.WriteLine($"Records lost: {log.HowManyRecordsWereDropped}");

foreach (var byEnding in log.Calls.GroupBy(call => call.HowItEnded))
    Console.WriteLine($"{byEnding.Key}: {byEnding.Count()}");

On the sample log this prints:

Calls in total: 6
Separate operations (root calls): 1
Records lost: 0
Returned: 4
ReturnedAfterAwait: 1
Failed: 1

2. Which methods were called most often

#:package DotnetLog.Reader@1.0.0
using DotnetLog.Reader.BuildingCallTree;

var log = CallLog.LoadFromFile(args[0]);

var byMethod = log.Calls
    .GroupBy(call => call.FullMethodName)
    .Select(group => new
    {
        Method = group.Key,
        HowManyTimes = group.Count(),
        TotalMilliseconds = group.Sum(call => call.HowLongItRan?.TotalMilliseconds ?? 0),
    })
    .OrderByDescending(row => row.HowManyTimes)
    .ThenBy(row => row.Method);

Console.WriteLine($"{"calls",7}   {"total ms",8}   method");

foreach (var row in byMethod)
    Console.WriteLine($"{row.HowManyTimes,7}   {row.TotalMilliseconds,8:0.0}   {row.Method}");

On the sample log this prints:

  calls   total ms   method
      1        0.5   App.Cache.Boolean TryGet(String, Int32&)
      1      120.0   App.Db.Task<Account> LoadAsync(String)
      1        5.0   App.Money.Decimal Count(Decimal)
      1        0.2   App.Money.Decimal Rate(String)
      1      200.0   App.Web.String Handle(String)
      1        3.0   App.Web.String Render(String)

3. What failed and who called it

#:package DotnetLog.Reader@1.0.0
using DotnetLog.Reader.BuildingCallTree;

var log = CallLog.LoadFromFile(args[0]);

foreach (var failed in log.Calls.Where(call => call.ThrownException is not null))
{
    Console.WriteLine($"x {failed.ThrownException!.TypeName}: {failed.ThrownException.Message}");
    Console.WriteLine($"  in method {failed.FullMethodName}");

    foreach (var above in failed.AllCallsAbove)
        Console.WriteLine($"      called from {above.FullMethodName}");

    Console.WriteLine($"      the chain started at {failed.RootCall.FullMethodName}");
}

On the sample log this prints:

x System.InvalidOperationException: Счёт закрыт
  in method App.Money.Decimal Count(Decimal)
      called from App.Web.String Handle(String)
      the chain started at App.Web.String Handle(String)

The exception type and message come from the logged application, so they stay in whatever language that application used.

4. Show the whole chain

#:package DotnetLog.Reader@1.0.0
using DotnetLog.Reader.BuildingCallTree;
using DotnetLog.Reader.DrawingCallTree;

var log = CallLog.LoadFromFile(args[0]);
var top = log.RootCalls[0];

Console.WriteLine(CallTreeText.Draw(top, new CallTreeTextOptions { HowManyLevelsDown = 3 }));
Console.WriteLine(CallTreeMermaid.Draw(top));

On the sample log the text tree comes out like this (the labels the drawing code prints are in Russian: мс = ms, длит. = duration, не завершился = never finished, ИСКЛЮЧЕНИЕ = exception):

[1] App.Web.String Handle(String)   +0.000 мс   длит. 200.000 мс
     args : { path: "/user/7" }
     ret  : "ошибка"
  ├─ [2] App.Cache.Boolean TryGet(String, Int32&)   +10.000 мс   длит. 0.500 мс
  │       args : { key: "user:7" }
  │       this : { Count: 3 }
  │       ret  : false
  │       out  : { value: 0 }
  ├─ [3] App.Db.Task<Account> LoadAsync(String) async   +20.000 мс   длит. 120.000 мс
  │       args : { key: "user:7" }
  │       this : { Host: "db1", Port: 5432 }
  │       ret  : { Owner: "Иванов", Balance: 100.5 }
  ├─ [4] App.Money.Decimal Count(Decimal)   +150.000 мс   длит. 5.000 мс
  │       args : { amount: 100.5 }
  │       ✗ ИСКЛЮЧЕНИЕ System.InvalidOperationException: Счёт закрыт
  │    └─ [5] App.Money.Decimal Rate(String)   +151.000 мс   длит. 0.200 мс
  │            args : { code: "RUB" }
  │            ret  : 1.0
  └─ [6] App.Web.String Render(String)   +160.000 мс   длит. 3.000 мс
          args : { template: "user" }
          ret  : "готовая страница"

And the Mermaid diagram printed right after it:

sequenceDiagram
    Web->>Cache: TryGet("user:7")
    Cache-->>Web: false
    Web->>Db: LoadAsync("user:7")
    Db-->>Web: { Owner: "Иванов", Balance: 100.5 }
    Web->>Money: Count(100.5)
    Money->>Money: Rate("RUB")
    Money-->>Money: 1.0
    Money--xWeb: System.InvalidOperationException: Счёт закрыт
    Web->>Web: Render("user")
    Web-->>Web: "готовая страница"

5. Where a value leaked to

#:package DotnetLog.Reader@1.0.0
using DotnetLog.Reader.BuildingCallTree;

var log = CallLog.LoadFromFile(args[0]);

foreach (var call in log.Calls.Where(call => call.HasTextInside("user:7")))
    Console.WriteLine($"[{call.CallId}] {call.FullMethodName}");

On the sample log this prints:

[2] App.Cache.Boolean TryGet(String, Int32&)
[3] App.Db.Task<Account> LoadAsync(String)

The search descends into nested objects too, so the value is found both in an argument and in a field of an object deeper down.

6. Where the application is stuck

#:package DotnetLog.Reader@1.0.0
using DotnetLog.Reader.BuildingCallTree;

var log = CallLog.LoadFromFile(args[0]);

var slowest = log.Calls
    .Where(call => call.HowLongItRan is not null)
    .OrderByDescending(call => call.TimeSpentByItself)
    .Take(5);

foreach (var call in slowest)
    Console.WriteLine($"{call.TimeSpentByItself.TotalMilliseconds,6:0.0}   {call.FullMethodName}");

On the sample log this prints:

 120.0   App.Db.Task<Account> LoadAsync(String)
  71.5   App.Web.String Handle(String)
   4.8   App.Money.Decimal Count(Decimal)
   3.0   App.Web.String Render(String)
   0.5   App.Cache.Boolean TryGet(String, Int32&)

What matters is not the total duration of a call but its own time: Handle ran for 200 ms in total but only 71.5 of them were its own — the rest it spent waiting on the calls below it. That is exactly what TimeSpentByItself shows.

Big files

A log of several gigabytes will not fit into memory. There is an index for it: it walks the file once and remembers only the line offsets.

using DotnetLog.Reader.FindingCallsInBigFile;

var index = CallLogIndex.BuildForFile("dotnet-log.jsonl");
index.SaveToFile("dotnet-log.jsonl.idx");

var call = index.ReadCallById(4242);          // only two lines of the file were read
var wayUp = index.ReadAllCallsAbove(4242);    // plus two more per ancestor

And to watch the log of a running application there is the "live tail" — a read that does not stop at the end of the file:

using DotnetLog.Reader.ReadingLogFile;

var options = new LogFileReadingOptions { KeepWatchingFile = true };
foreach (var entry in CallLogFile.ReadEntriesOneByOne("dotnet-log.jsonl", options))
    Console.WriteLine(entry.MethodSignature);