Serilog formatted logs aren't very legible

[QuintillusCFC]

On Windows, which may be relevant.

Running from either the Godot IDE, or the Rider IDE, formatted Serilog logs look like this:

←[38;5;0246m01:30:27.246←[0m←[38;5;0242m [←[0m←[37mDBG←[0m←[38;5;0242m]←[0m←[38;5;0242m ←[0m←[38;5;0246mMainMenu←[0m←[38;5;0242m:←[0m←[38;5;0242m ←[0m←[38;5;0246menter MainMenu._R
eady←[0m←[38;5;0242m

This... isn't really how we want them to look. I don't know if it's a problem with some sort of loop in the configuration, or the formatter, or how it's being printed to the console, or if Serilog just doesn't like Windows, but it's not really human readable.

[QuintillusCFC]

What I get when I go to the main menu, in full:

Hello logger!
←[38;5;0246m01:53:37.229←[0m←[38;5;0242m [←[0m←[37mDBG←[0m←[38;5;0242m]←[0m←[38;5;0242m ←[0m←[38;5;0246mLogManager←[0m←[38;5;0242m:←[0m←[38;5;0242m ←[0m←[38;5;0246mHello!←[0m←[38;
5;0242m
←[0m←[38;5;0246m01:53:37.229←[0m←[38;5;0242m [←[0m←[37mDBG←[0m←[38;5;0242m]←[0m←[38;5;0242m ←[0m←[38;5;0246mLogManager←[0m←[38;5;0242m:←[0m←[38;5;0242m ←[0m←[38;5;0246mHello!←[0m←
[38;5;0242m
←[0m
←[38;5;0246m01:53:37.372←[0m←[38;5;0242m [←[0m←[37mDBG←[0m←[38;5;0242m]←[0m←[38;5;0242m ←[0m←[38;5;0246mMainMenuMusicPlayer←[0m←[38;5;0242m:←[0m←[38;5;0242m ←[0m←[38;5;0246msettin
g volume to 100, which is 0 decibel offset←[0m←[38;5;0242m
←[0m←[38;5;0246m01:53:37.372←[0m←[38;5;0242m [←[0m←[37mDBG←[0m←[38;5;0242m]←[0m←[38;5;0242m ←[0m←[38;5;0246mMainMenuMusicPlayer←[0m←[38;5;0242m:←[0m←[38;5;0242m ←[0m←[38;5;0246mse
tting volume to 100, which is 0 decibel offset←[0m←[38;5;0242m
←[0m
MainMenu got logger: Serilog.Core.Logger
←[38;5;0246m01:53:37.384←[0m←[38;5;0242m [←[0m←[37mDBG←[0m←[38;5;0242m]←[0m←[38;5;0242m ←[0m←[38;5;0246mMainMenu←[0m←[38;5;0242m:←[0m←[38;5;0242m ←[0m←[38;5;0246menter MainMenu._R
eady←[0m←[38;5;0242m
←[0m←[38;5;0246m01:53:37.384←[0m←[38;5;0242m [←[0m←[37mDBG←[0m←[38;5;0242m]←[0m←[38;5;0242m ←[0m←[38;5;0246mMainMenu←[0m←[38;5;0242m:←[0m←[38;5;0242m ←[0m←[38;5;0246menter MainMen
u._Ready←[0m←[38;5;0242m
←[0m

The logs are getting Serilog'ized, but the formatting is weird.

[QuintillusCFC]

If I change the ExpressionTemplate to "{@m:lj}\n",, it cleans it up a bit...

Hello logger!
←[38;5;0246mHello!←[0m←[38;5;0242m
←[0m←[38;5;0246mHello!←[0m←[38;5;0242m
←[0m
←[38;5;0246msetting volume to 100, which is 0 decibel offset←[0m←[38;5;0242m
←[0m←[38;5;0246msetting volume to 100, which is 0 decibel offset←[0m←[38;5;0242m
←[0m
MainMenu got logger: Serilog.Core.Logger
←[38;5;0246menter MainMenu._Ready←[0m←[38;5;0242m
←[0m←[38;5;0246menter MainMenu._Ready←[0m←[38;5;0242m
←[0m

[QuintillusCFC]

Okay, figured out some things.

If I switch it to this:

        Log.Logger = new LoggerConfiguration()
            .WriteTo.Console(outputTemplate: "{Timestamp} [{Level}] {Message}\n")
            // .WriteTo.GodotSink(formatter: consoleTemplate)
            .MinimumLevel.Debug()
            .CreateLogger();

With an outputTemplate instead of a formatter for Console, and commenting out the GodotSink, I get nice helpful formatted output (in Rider):

Hello logger!
06/04/2022 02:05:31 -04:00 [Debug] Hello!
06/04/2022 02:05:31 -04:00 [Debug] setting volume to "100", which is 0 decibel offset
MainMenu got logger: Serilog.Core.Logger
06/04/2022 02:05:31 -04:00 [Debug] enter MainMenu._Ready

But with the Godot sink enabled, that becomes:

Hello logger!
06/04/2022 02:06:50 -04:00 [Debug] Hello!
←[38;5;0246m02:06:50.759←[0m←[38;5;0242m [←[0m←[37mDBG←[0m←[38;5;0242m]←[0m←[38;5;0242m ←[0m←[38;5;0246mLogManager←[0m←[38;5;0242m:←[0m←[38;5;0242m ←[0m←[38;5;0246mHello!←[0m←[38;5;0242m
←[0m
06/04/2022 02:06:50 -04:00 [Debug] setting volume to "100", which is 0 decibel offset
←[38;5;0246m02:06:50.915←[0m←[38;5;0242m [←[0m←[37mDBG←[0m←[38;5;0242m]←[0m←[38;5;0242m ←[0m←[38;5;0246mMainMenuMusicPlayer←[0m←[38;5;0242m:←[0m←[38;5;0242m ←[0m←[38;5;0246msetting volume to 100, which
is 0 decibel offset←[0m←[38;5;0242m
←[0m
MainMenu got logger: Serilog.Core.Logger
06/04/2022 02:06:50 -04:00 [Debug] enter MainMenu._Ready
←[38;5;0246m02:06:50.933←[0m←[38;5;0242m [←[0m←[37mDBG←[0m←[38;5;0242m]←[0m←[38;5;0242m ←[0m←[38;5;0246mMainMenu←[0m←[38;5;0242m:←[0m←[38;5;0242m ←[0m←[38;5;0246menter MainMenu._Ready←[0m←[38;5;0242m
←[0m

The nicely formatted ones are still there, but it also prints out a bunch of garbage.

But within the GodotSink, Godot (IDE) just prints out the things that don't use Serilog:

Hello logger!
MainMenu got logger: Serilog.Core.Logger

With only the Godot sink, the Godot IDE prints out the logs, but with all the garbage:

Hello logger!
02:08:31.307 [DBG] LogManager: Hello!

02:08:31.448 [DBG] MainMenuMusicPlayer: setting volume to 100, which is 0 decibel offset

MainMenu got logger: Serilog.Core.Logger
02:08:31.463 [DBG] MainMenu: enter MainMenu._Ready


If I change the consoleTemplate to just be "{@m:lj}",, with only the Godot sink enabled, Godot (IDE) prints:

Hello logger!
Hello!
setting volume to 100, which is 0 decibel offset
MainMenu got logger: Serilog.Core.Logger
enter MainMenu._Ready

Which loses a lot of the garbage, but also stuff like the timestamp and level... which I suppose weren't really being printed out in a legible format anyway.

If I shorten it to just "{@m}", which switches off JSON and changes quote encoding mode, we get:

Hello logger!
Hello!
setting volume to 100, which is 0 decibel offset
MainMenu got logger: Serilog.Core.Logger
enter MainMenu._Ready

Not really any better.

---

Conclusions:

1. In IDEs with "advanced" console logging, such as Rider, we only really want/need the console sink. We can format it more simply and get better results.
2. Something is not right with the Godot sink. I wonder if @WildWeazel was seeing better results on Linux (hopefully)? It would be useful when running from the Godot IDE, but only if it's legible.

[QuintillusCFC]

Okay, concluded that the problem appears to be in the Emit method of GodotSink, and/or with the ITextFormatter it receives. The simple "Hello!" gets formatted as:

Hello!

This was confirmed with a debug breakpoint at GD.Print(message) on line 32 of GodotSink.cs, i.e. before it's printed to the console. It's theoretically possible that the IDE formatter is also formatting it weirdly due to something platform-specific, but overall this seems to lessen the chance that it's a platform thing and increase the chance that it's a formatter thing.

[QuintillusCFC]

New experimental config:

        RawFormatter rf = new RawFormatter();

        Log.Logger = new LoggerConfiguration()
            // .WriteTo.Console(outputTemplate: "{Timestamp} [{Level}] {Message}\n")
            .WriteTo.GodotSink(rf)
            .MinimumLevel.Debug()
            .CreateLogger();

This produces (Godot IDE):

Hello logger!
[6/4/2022 2:56:34 AM -04:00] Debug: "Hello!"
SourceContext = "LogManager"

[6/4/2022 2:56:34 AM -04:00] Debug: "setting volume to {volume}, which is {offset} decibel offset"
volume = "100"
offset = 0
SourceContext = "MainMenuMusicPlayer"

MainMenu got logger: Serilog.Core.Logger
[6/4/2022 2:56:34 AM -04:00] Debug: "enter MainMenu._Ready"
SourceContext = "MainMenu"

Well, this is legible. RawFormatter is annotated: [Obsolete("A JSON-based formatter such asSerilog.Formatting.Compact.CompactJsonFormatteris recommended for this task.")] But it does a great job showing what the data is behind the scenes. And other than not interpolating the strings, it's quite legible.

(I also realize that if we had a large database capturing logs in a mineable format, having the strings as properties like this would be quite handy. Though for our use case, ironically, RawFormat would be kinda nice if we just string-interpolated instead of logging-framework interpolated)

[QuintillusCFC]

Okay, found a blog (https://nblumhardt.com/2021/06/customize-serilog-text-output/) that seems to know what's up.

Godot IDE, configuration using the ExpressionTemplate on that blog (ignoring the already-set-up consoleTemplate):

        Log.Logger = new LoggerConfiguration()
            // .WriteTo.Console(outputTemplate: "{Timestamp} [{Level}] {Message}\n")
            .WriteTo.GodotSink(new ExpressionTemplate(
                                   "[{@t:HH:mm:ss} {@l:u3} {SourceContext}] {@m}\n{@x}"))
            .MinimumLevel.Debug()
            .CreateLogger();

Output:

Hello logger!
[03:05:21 DBG LogManager] Hello!

[03:05:21 DBG MainMenuMusicPlayer] setting volume to 100, which is 0 decibel offset

MainMenu got logger: Serilog.Core.Logger
[03:05:21 DBG MainMenu] enter MainMenu._Ready

The exact same config from Rider:

Hello logger!
[03:06:42 DBG LogManager] Hello!

[03:06:42 DBG MainMenuMusicPlayer] setting volume to 100, which is 0 decibel offset

MainMenu got logger: Serilog.Core.Logger
[03:06:42 DBG MainMenu] enter MainMenu._Ready

With the console one also enabled, in Rider:

Hello logger!
06/04/2022 03:07:19 -04:00 [Debug] Hello!
[03:07:19 DBG LogManager] Hello!

06/04/2022 03:07:19 -04:00 [Debug] setting volume to "100", which is 0 decibel offset
[03:07:19 DBG MainMenuMusicPlayer] setting volume to 100, which is 0 decibel offset

MainMenu got logger: Serilog.Core.Logger
06/04/2022 03:07:19 -04:00 [Debug] enter MainMenu._Ready
[03:07:19 DBG MainMenu] enter MainMenu._Ready

Other than the formatting difference, which you can see, the console one also has syntax highlighting in Rider, with the [ and ] around "Debug" being in lighter font, and the "100" and 0 parameters being teal and lavender, respectively. I'm not sure exactly why. This difference also appears in the Windows console.

As a reminder, the Console sink output doesn't show up in the Godot IDE, only the GodotSink output.

---

This allows us to make some more conclusions.

1. There is an important difference in our ExpressionTemplate formatting that is throwing it off. I'm somewhat surprised my attempts to use a minimal format still didn't fix it, but there's a secret in that blog post somewhere.
2. We can probably just use GodotSink and leave off Console sink, since that works across all IDEs. The Godot output also shows up in the Windows console that's started with Godot.

Corollary for 2: Ideally we'd use the one with fancy syntax highlighting where it's supported, but IMO that's just icing on the cake.

I have saved the linked blog post to my local storage so it's archived in case the blog disappears tomorrow (unlikely, but you never know). Haven't fully read it yet, but it has proven to have value.

[QuintillusCFC]

With our format string, but inlined as:

            .WriteTo.GodotSink(new ExpressionTemplate(
                                   "{@t:HH:mm:ss.fff} [{@l:u3}]{#if SourceContext is not null} {SourceContext}:{#end} {@m:lj}\n{#if @x is not null}\tException: {@x}{#end}"))

Result (Godot IDE):

Hello logger!
03:18:05.740 [DBG] LogManager: Hello!

03:18:05.877 [DBG] MainMenuMusicPlayer: setting volume to 100, which is 0 decibel offset

MainMenu got logger: Serilog.Core.Logger
03:18:05.887 [DBG] MainMenu: enter MainMenu._Ready

Compare to blog version:

Hello logger!
[03:05:21 DBG LogManager] Hello!

[03:05:21 DBG MainMenuMusicPlayer] setting volume to 100, which is 0 decibel offset

MainMenu got logger: Serilog.Core.Logger
[03:05:21 DBG MainMenu] enter MainMenu._Ready

and when I add in , theme: TemplateTheme.Code this new version gives:

Hello logger!
03:20:26.414 [DBG] LogManager: Hello!

03:20:26.558 [DBG] MainMenuMusicPlayer: setting volume to 100, which is 0 decibel offset

MainMenu got logger: Serilog.Core.Logger
03:20:26.570 [DBG] MainMenu: enter MainMenu._Ready

So it's not the expression itself! It's the theme!

The JavaDoc (C# Doc?) for the ExpressionTemplate constructor describes it thus:

<param name="theme">Optionally, an ANSI theme to apply to the template output.</param>

So, this ANSI theme is causing problems. Diving into the Serilog code, it defaults to TemplateTheme.None when it isn't provided, which seems to work. I'm guessing the console one uses something a bit fancier than TemplateTheme.None, but less complex than the Code one.

FWIW, I also tried the Grayscale and Literate options on TemplateTheme an hour or so ago, when throwing darts at the problem, but did not see a discernable difference. "None" wasn't an option, as it's an internal property.

The TemplateTheme class describes itself as, A template theme using the ANSI terminal escape sequences.. So it must be those ANSI escape sequences that are getting printed out and causing chaos. That very well could be platform specific, or at least terminal specific.

---

Conclusions:

1. We should leave off the TemplateTheme (effectively using TemplateTheme.None) for now, and leave it that way until we better understand how they work.
2. Our format string is probably okay, but we should document what each of the sections is intended to mean. I spent a lot of time messing around with that thinking something funky in the syntax was probably the problem, at least until realizing that couldn't be it when the minimal case still gave weird output.

[QuintillusCFC]

So it looks like the Console sink is using SystemConsoleTheme, in Serilog.Sinks.SystemConsole.Themes. It has options Grayscale, Literate, and Colored (but not Code). It notes about itself:

  /// A console theme using the styling facilities of the <see cref="T:System.Console" /> class. Recommended
  /// for Windows versions prior to Windows 10.

I happen to be using Windows 8.1. I wonder if the logging works better on 10? I hadn't been paying much attention to it while working on the priority arbitrator, so I'm not sure. Unfortunately, it isn't assignable as a theme due to a type mismatch. The same is true for Serilog.Sinks.SystemConsole.Themes.ConsoleTheme, which offers None.

I found more info about these Console sink themes at https://github.com/serilog/serilog-sinks-console . Unfortunately I haven't figured out a way to shoehorn them into the ExpressionTemplate.

The other thing I've wondered it whether it makes sense to use an ExpressionTemplate, or if something else would work better? GodotSink actually takes ITextFormatter, of which ExpressionTemplate is an type. It uses that formatter to format the message, before tossing it on GD.Print. But RawFormatter also of type ITextFormatter, and... it looks like the outputTemplate being used by the nice colorful Console sink uses OutputTemplateRenderer, which is an ITextFormatter.

---

So I now think the ideal solution is to use an OutputTemplateRenderer instead of an ExpressionTemplate for the Godot sink, and to only use it (and eventually a file output variant).

Question to @WildWeazel - does the current setup buy us anything nice on Linux? Like super-amazing formatting that the console one can't match? I don't really want to have a fancy setup to try to differentiate between platforms, but if there is a huge advantage it would be nice to know about.

[WildWeazel]

I'm not sure I follow everything you did, but #268 (still) works in Linux! Other than the extra newline the only difference is that before there was some subtle color-coding of the level itself with the rest of the message a soft gray. So that'd be nice to reproduce, but not necessary. And it wasn't even intentional on my part, I just followed the official tutorial.

[QuintillusCFC]

Yeah, this kind of became my scratchpad as I learned more about it. If we ever need a deep dive on log formatting, we now have notes.

Interesting that the color coding was slightly different than what I saw with the Console sink. I agree that it's a nice to have. But the logs were literally unusable (in a non-sarcastic way) on Windows previously, so especially as we roll out Serilog to more areas, legibility first and then color-coding will be better than vice-versa.

I'm interpreting your mention of the extra newline to mean it was "extra", and that there isn't a good reason to add it back.