Flexible and efficient optionally-structured console logging out of the box

@maryamariyan

Description

We want to add the capability to control the format of the logs produced by our console logger. Currently, there is an option to choose between Default (logging on multiple lines with colors) and Systemd (logs on a single line without color). We would like to be able to:

[a] add a readable and coloured compact format which will log using a single line
[b] add a JSON based log format.
[c] add an extension point so that users can specify their own custom log format.
[d] we would need to be able to control the formatter used as well as the formatters via Configuration.

Proposal:

The proposal below is aimed at satisfying all the above requirements.

Scope

We are considering limiting the scope of the formatter API to Logging.Console for now, instead of Logging.Abstractions, though this could potentially in the future be adapted to be used for Logging.Debug as well,

Usage and New APIs

Refer to gist: https://gist.github.com/maryamariyan/81f1526fe2156e95352e516f03a61724

we would need to be able to control the formatter used as well as the formatters via Configuration.

As seen in the sample appsettings.json below, the formatter would be selected via Console:Logging:FormatterName, and the formatter options would be set via Console:Logging:FomratterOptions:

{
  "Logging": {
    "LogLevel": {
      "Default": "None",
      "Microsoft": "Warning",
      "Microsoft.Hosting.Lifetime": "Information"
    },

    "Console": {
      "LogLevel": {
        "Default": "Information"
      },
      "FormatterName": "json",
      "FormatterOptions": {
        "JsonWriterOptions": {
          "Indented": true
        },
        "ExtraCustomProperty": "modified",
        "IncludeScopes": true,
        "TimestampFormat": "HH:mm:ss",
        "UseUtcTimestamp": true
      }
    }
  },
  "AllowedHosts": "*"
}

Screenshots

Screenshots for the different built-in selections (click to view)

default:

default:
(when DefaultConsoleLogFormatterOptions.SingleLine is true)
or we could have an additional formatter called compact rather than toggling by property.

systemd:

json:

Original proposal (click to view)

Is your feature request related to a problem? Please describe.

As a web app developer, I'm trying to write web apps (such as nodatime.org) that log efficiently and cleanly, with minimal effort.
As a Google Cloud Platform client library author, I'm trying to make it really easy for our users to integrate with Stackdriver logging and error reporting.
As a .NET community member, I'm trying to make 12-factor apps easier to write.

Currently, there are three reasonably obvious options for logging in my web application:

Option 1: Use the default console logger.

The "no code changed" option.

This has at least three problems:

Each log entry spans two lines, which makes it far less useful than it might be, and presumably means log entries on busy systems could be interleaved.
The log entries contain control characters for colour; I'm sure I can disable this, but it's annoying out-of-the-box behaviour
It's not structured in an easily machine-readable way.

Option 2: Use Google.Cloud.Diagnostics.AspNetCore

This library makes RPCs directly to the Stackdriver Logging API.

As one of the contributors to the library, I should be able to get this to work easily, right? Well, it does work, but not as conveniently as I'd like. I can improve things, but this is likely to always be a somewhat-heavyweight option. Useful in some cases, such as when there's nothing monitoring console output, but not necessary in modern container-based systems which almost always do monitor the console. It also requires appropriate credentials to be provided when not running on GCP, etc. This ties it to Stackdriver in a way that could be harmful to app portability. (It's fine if you don't need portability of course, but it's a heavyweight dependency otherwise.)

Option 3: Use Serilog

I did get this working, writing out structured JSON to the console, but it was relatively painful to do, and didn't write the JSON in a format that Stackdriver expects. In order to get a custom JSON format, I had to do far more work than I'd normally expect to. It worked, but there's no way that every app should have all of this code in it.

Describe the solution you'd like

Ideally I'd like three simple options:;

A more concise single-line-per-entry console logger, still just lines of plain text
A simple structured logger writing JSON in whatever format seems most reasonable after some research
A way of adapting the second option to write in a custom JSON format

The last is for integration with Stackdriver and presumably other cloud providers' monitoring offerings. With the right JSON, the Stackdriver user interface is clear and easy to read, but still provides structured data that can be used to trigger error reporting, create filters etc.

In an ideal world the CNCF would provide a common JSON format for everyone to use for maximum interoperability, but until that happens it would be useful for the ASP.NET Core team to handle the concerns of gathering the log data and writing the resulting to the console efficiently and atomically, leaving cloud providers to just provide the code to convert the raw log data into appropriate JSON. Even though an app using this would still have a dependency on Stackdriver, it's a much lighter-weight one than Google.Cloud.Diagnostics.AspNetCore - and it would be entirely reasonable to depend on multiple formatters and pick the right one at execution time, expecting each to be standalone and small.

Additional context

I have tried to find existing solutions to this, but I've failed so far.

For nodatime.org, I ended up writing my own console logger, which should only be used for the sake of seeing what I'm trying to achieve - it's not aimed at high-performance scenarios, for example. (If anyone wants to point and laugh, they're welcome - it does the job though :)
https://github.com/nodatime/nodatime.org/blob/master/src/NodaTime.Web/Logging/JsonConsoleLogger.cs

API Proposal

Assembly: Microsoft.Extensions.Logging.Abstractions.dll

Drop Log from names
Rename Default so something that doesn't imply a subset relationship, such as Simple

Assembly: Microsoft.Extensions.Logging.Abstractions.dll

 namespace Microsoft.Extensions.Logging
 {
+    public readonly struct LogEntry<TState>
+    {
+       public LogEntry(LogLevel logLevel,
+                       string category,
+                       EventId eventId,
+                       TState state,
+                       Exception exception,
+                       Func<TState, Exception, string> formatter);
+       public LogLevel LogLevel { get; }
+       public string Category { get; }
+       public EventId EventId { get; }
+       public TState State { get; }
+       public Exception Exception { get; }
+       public Func<TState, Exception, string> Formatter { get; }
+    }
}

Assembly: Microsoft.Extensions.Logging.Console.dll

 namespace Microsoft.Extensions.Logging
 {
     public static partial class ConsoleLoggerExtensions
     {
         public static ILoggingBuilder AddConsole(this ILoggingBuilder builder);
         public static ILoggingBuilder AddConsole(this ILoggingBuilder builder, Action<ConsoleLoggerOptions> configure);
+        public static ILoggingBuilder AddConsoleFormatter<TFormatter, TOptions>(this ILoggingBuilder builder)
+                                      where TFormatter : class, IConsoleFormatter where TOptions : ConsoleFormatterOptions;
+        public static ILoggingBuilder AddConsoleFormatter<TFormatter, TOptions>(this ILoggingBuilder builder, Action<TOptions> configure)
+                                      where TFormatter : class, IConsoleFormatter where TOptions : ConsoleFormatterOptions;
+        public static ILoggingBuilder AddSimpleConsole(this ILoggingBuilder builder, Action<SimpleConsoleFormatterOptions> configure);
+        public static ILoggingBuilder AddJsonConsole(this ILoggingBuilder builder, Action<JsonConsoleFormatterOptions> configure);
+        public static ILoggingBuilder AddSystemdConsole(this ILoggingBuilder builder, Action<ConsoleFormatterOptions> configure);
     }
 }
 namespace Microsoft.Extensions.Logging.Console
 {
+    public static partial class ConsoleFormatterNames
+    {
+        public const string Simple = "simple";
+        public const string Json = "json";
+        public const string Systemd = "systemd";
+    }
+    [ObsoleteAttribute("ConsoleLoggerFormat has been deprecated.", false)]
     public enum ConsoleLoggerFormat
     {
         Default = 0,
         Systemd = 1,
     }
     public partial class ConsoleLoggerOptions
     {
         public ConsoleLoggerOptions();
+        [ObsoleteAttribute("ConsoleLoggerOptions.DisableColors has been deprecated. Please use ColoredConsoleFormatterOptions.DisableColors instead.", false)]
         public bool DisableColors { get; set; }
+        [ObsoleteAttribute("ConsoleLoggerOptions.Format has been deprecated. Please use ConsoleLoggerOptions.FormatterName instead.", false)]
         public ConsoleLoggerFormat Format { get; set; }
         public string FormatterName { get; set; }
+        [ObsoleteAttribute("ConsoleLoggerOptions.IncludeScopes has been deprecated..", false)]
         public bool IncludeScopes { get; set; }
         public LogLevel LogToStandardErrorThreshold { get; set; }
+        [ObsoleteAttribute("ConsoleLoggerOptions.TimestampFormat has been deprecated..", false)]
         public string TimestampFormat { get; set; }
+        [ObsoleteAttribute("ConsoleLoggerOptions.UseUtcTimestamp has been deprecated..", false)]
         public bool UseUtcTimestamp { get; set; }
     }
     [ProviderAliasAttribute("Console")]
     public partial class ConsoleLoggerProvider : ILoggerProvider, ISupportExternalScope, IDisposable
     {
         public ConsoleLoggerProvider(IOptionsMonitor<ConsoleLoggerOptions> options);
+        public ConsoleLoggerProvider(IOptionsMonitor<ConsoleLoggerOptions> options, IEnumerable<IConsoleFormatter> formatters);
         public ILogger CreateLogger(string name);
         public void Dispose();
         public void SetScopeProvider(IExternalScopeProvider scopeProvider);
     }
+    public partial class SimpleConsoleFormatterOptions : ConsoleFormatterOptions
+    {
+        public SimpleConsoleFormatterOptions();
+        public bool DisableColors { get; set; }
+        public bool SingleLine { get; set; }
+    }
+    public partial abstract ConsoleFormatter
+    {
+        protected ConsoleFormatter(string name);
+        public string Name { get; }
+        public abstract void Write<TState>(in LogEntry<TState> logEntry,
+                                           IExternalScopeProvider scopeProvider,
+                                           TextWriter textWriter);
+    }
+    public partial class JsonConsoleFormatterOptions : ConsoleFormatterOptions
+    {
+        public JsonConsoleFormatterOptions();
+        public JsonWriterOptions JsonWriterOptions { get; set; }
+    }
+    public partial class ConsoleFormatterOptions
+    {
+        public ConsoleFormatterOptions();
+        public bool IncludeScopes { get; set; }
+        public string TimestampFormat { get; set; }
+        public bool UseUtcTimestamp { get; set; }
+    }
}

We run into the sample problems frequently. The default logger is not usable for log aggregation in a service oriented architecture. Structured logging, like Serilog provides it, would be a much better default. Logs with color and two lines per message break every log aggregations system and renders them useless.
This means that we have to provide our own Logger assembly in every service which uses Serilog for the ILogger interface. An easy to use default implementation with structured logging, directly provided through Microsoft.Extensions.Logging would be much preferred.

Microsoft.Extensions.Logging provides structured logging. You wouldn't be able to use Serilog as a provider if it didn't.

@paulomorgado

@paulomorgado: Yes, it's definitely possible to use structured logging with ASP.NET Core - it's just that it's relatively painful to do out-of-the-box, especially in a 12-factor friendly (stdout) way. With a more flexible console logger, it would be really simple.

@jskeet

I'm sorry, @jskeet, but from what I've seen in the wild, I would make console logging physically painful for production logging. 😄

@paulomorgado

@paulomorgado: Whereas in the wild I've found that with things like Stackdriver logging + fluentd automatically capturing stdout, it's a lot simpler to handle logging just to the console than having to configure logging in more complex ways. Each to their own, but I'd at least like it to be a reasonable option. You can still avoid using the console if you want to :)

@paulomorgado

@paulomorgado Logging to stdout is the default for distributed micro-services with Docker. E.g. Docker Swarm/K8s greps all stdout and forwards it to Logstash/fluentd or similar. It should be as easy as possible not as painful as possible for production.

@secana

@secana, how do you go from screen grepping to structure logging?

@paulomorgado

@paulomorgado: In the case of Stackdriver at least, if you write a line of JSON to the console, that's parsed and treated in a structured way. I'd certainly hope that other log collectors work that way too.

@jskeet

@jskeet yes, that is how it works for all other collectors that I know of.

@jskeet

@jskeet slightly O/T, but would appreciate your feedback:

In order to get a custom JSON format, I had to do far more work than I'd normally expect to.

seems at odds with:

A simple structured logger writing JSON in whatever format seems most reasonable after some research

Did you find Serilog.Formatting.Compact? It's an implementation of the latter (opinionated/reasonable JSON rendering). Thanks! :-)

@nblumhart: I don't see how those two statements are at odds at all. I'd like there to be an out-of-the-box solution for a simple structured JSON logger that writes in some reasonable format... if there's something that multiple log consumers will accept, that would be great. But it still needs to be adaptable as per the bullet point that follows the one quoted.

Yes, I found Serilog.Formatting.Compact. It did indeed write out JSON to the console - after more hoops than I'd like to see in an out-of-the-box ASP.NET Core implementation - but it did so in its own unconfigurable format, which Stackdriver can't do much with. Stackdriver expects specific JSON properties, specific severity levels etc. CompactJsonFormatter is completely hard-coded in that respect, which means I can't use it with Stackdriver. (It also doesn't format the message itself, which makes perfect sense for a compact formatter, but also makes it less useful for Stackdriver.)

@jskeet

Thanks for the reply, @jskeet!

I initially misread your third point-

A way of adapting the second option to write in a custom JSON format

Sorry about my confusion there, on re-reading no I understand what you meant 👍

My interest in "configurable vs. opinionated" comes from having started with a configurable JsonFormatter in Serilog, but later backpedalling to the much simpler and more efficient CompactJsonFormatter /RenderedCompactJsonFormatter after failing to put limits on the flexibility of the original implementation. Adding configurability in there without sacrificing perf, usability, or maintainability is a challenge, and we didn't want to end up with essentially a clone of JSON.NET :-)

Will be interesting to see what kinds of approaches are possible, here.

Just RE jumping through hoops, adding a NuGet package and WriteTo.Console(new CompactJsonFormatter()) seems like a reasonable API/experience, anything we should change or improve? Cheers!

Ah, also - sorry

(It also doesn't format the message itself, which makes perfect sense for a compact formatter, but also makes it less useful for Stackdriver.)

The example in the README shows the CompactJsonFormatter variant, but RenderedCompactJsonFormatter is probably much closer to what you need, and does format the message in there.

@nblumhardt

@nblumhardt: This is the code I ended up with in my Program.cs:

public static IWebHostBuilder CreateWebHostBuilder(string[] args) =>
    WebHost.CreateDefaultBuilder(args)
        .UseSerilog((hostingContext, loggerConfiguration) => loggerConfiguration
            .ReadFrom.Configuration(hostingContext.Configuration)
            .Enrich.FromLogContext()
            .WriteTo.Console(new StackdriverJsonFormatter()))
        .UseStartup<Startup>();

For someone who hasn't used Serilog before, that took a while to get right (including finding all the right packages to start with - there was a fair amount of trial and error and trying to find docs, checking which packages I'd need etc) and seems unnecessarily verbose. I'd expect most ASP.NET Core Serilog users to want to read from the regular ASP.NET Core configuration and enrich from the log context. If we could just have:

public static IWebHostBuilder CreateWebHostBuilder(string[] args) =>
    WebHost.CreateDefaultBuilder(args)
        .UseSerilog(sinkConfig => sinkConfig.WriteTo.Console(new StackdriverJsonFormatter()))
        .UseStartup<Startup>();

that would significantly lower the barriers to entry for someone who doesn't need or care about most of the Serilog features, but just wants to use a specific log renderer. However, this issue is intended to be about ASP.NET Core built-in usability rather than Serilog - if you'd like me to file a friction log with my experiences, I'm happy to do that (although I'd be starting again; I don't think I kept a detailed friction log of that at the time). I don't think users should have to use Serilog just to write a reasonable 12factor app with ASP.NET Core.

Thanks for the feedback! Any further feedback you can send our way would be much appreciated. We're edging towards a more "batteries included" default configuration in Serilog.AspNetCore, hooking into configuration and the log context by default definitely seems worth us considering, there 👍

Let me know if you need another set of eyes on StackdriverJsonFormatter, happy to dig through and see if there are any APIs/goodies in the Serilog ecosystem that might help with it.

@davidfowl

@davidfowl: Thanks for that. I assume that means using the absolute latest installer? Happy to do so, given how stable .NET Core has been for uninstalling things, just thought I'd check. (I'm assuming trying to use the preview 8 ASP.NET Core bits against the preview 7 .NET Core Runtime would be a bad idea...)

@jskeet

@jskeet you don't need to install anything, you can just add the feed and a reference to the package and it should work like magic. I'm trying it out right now on an ASP.NET Core 3.1 application 😄

Aha! In that case, that makes it a slam dunk to try today. Thanks for clarifying!

In particular, the current implementation solves a few problem that it would be nice to not have to solve again when implementing a custom one, like pooling the byte buffer (PooledByteBufferWriter is not publicly available), getting the KeyValuePairs out of properties and iterating on the scopes.

Issue #33598 is tracking the ask to make PooledByteBufferWriter public.

Wahoo - tried it earlier, and it worked out of the box. I wasn't doing anything complicated, admittedly.

Thanks so much for this - I don't have any feedback on the API yet, as I'm not really deeply enough into ASP.NET Core logging (or the general logging abstraction) to have well-informed comments, but this definitely looks like it'll be a huge help.

@jskeet

@jskeet show us a screenshot or something 😄

@jskeet

@jskeet show us a screenshot or something 😄

I'll do better than that - tomorrow I'm going to start on a prototype of the actual GoogleCloudLoggingConsoleFormatter (with a briefer name if possible!) in https://github.com/googleapis/google-cloud-dotnet :)
Will cc you in the first PR (which I'm sure will do very little).

This really feels like a huge step forward.

Yeah, I'll adapt my Azure Pipelines logger to use this as well :)

@davidfowl

@davidfowl: It took a little longer to get to this than expected, but there's a prototype PR here, including before/after screenshots:

googleapis/google-cloud-dotnet#5200

Thanks again all for the feedback. I'll close this as complete as it should now satisfy the requested features described in the description. Any further feature requests or bugs can be tracked on separate new issues.

Please add support for logging InnerException. It will be beneficial to add additional JSON property which will store Exception.ToString().

I've been looking forward to this being released with .NET 5. Is there any documentation on how to use these new console formatter options properly?

@hannahchan

Hi @hannahchan - please see here:
https://docs.microsoft.com/dotnet/core/extensions/console-log-formatter
/cc @maryamariyan

Navigation Menu

Repository navigation

Flexible and efficient optionally-structured console logging out of the box #34742

Description

Proposal:

Scope

Usage and New APIs

we would need to be able to control the formatter used as well as the formatters via Configuration.

Screenshots

Is your feature request related to a problem? Please describe.

Describe the solution you'd like

Additional context

API Proposal

43 remaining items

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Flexible and efficient optionally-structured console logging out of the box #34742

Description

Description

Proposal:

Scope

Usage and New APIs

we would need to be able to control the formatter used as well as the formatters via Configuration.

Screenshots

Is your feature request related to a problem? Please describe.

Describe the solution you'd like

Additional context

API Proposal

Activity

secana commented on Aug 13, 2019

paulomorgado commented on Aug 13, 2019

jskeet commented on Aug 13, 2019

paulomorgado commented on Aug 13, 2019

jskeet commented on Aug 13, 2019

secana commented on Aug 14, 2019

paulomorgado commented on Aug 14, 2019

jskeet commented on Aug 14, 2019

secana commented on Aug 14, 2019

nblumhardt commented on Aug 14, 2019

jskeet commented on Aug 15, 2019

nblumhardt commented on Aug 15, 2019

nblumhardt commented on Aug 15, 2019

jskeet commented on Aug 15, 2019

nblumhardt commented on Aug 15, 2019

43 remaining items

jskeet commented on Jul 20, 2020

davidfowl commented on Jul 20, 2020

jskeet commented on Jul 20, 2020

maryamariyan commented on Jul 20, 2020

jskeet commented on Jul 20, 2020

davidfowl commented on Jul 20, 2020

jskeet commented on Jul 20, 2020

fredrikhr commented on Jul 20, 2020

jskeet commented on Jul 23, 2020

maryamariyan commented on Jul 23, 2020

dmitriyse commented on Aug 7, 2020

hannahchan commented on Nov 16, 2020

IEvangelist commented on Nov 16, 2020

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions