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

[jskeet]

Updated by @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; }
+    }
}

[secana]

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.

[paulomorgado]

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

[jskeet]

@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.

[paulomorgado]

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

[jskeet]

@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 :)

[secana]

@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.

[paulomorgado]

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

[jskeet]

@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.

[secana]

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

[nblumhardt]

@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! :-)

[jskeet]

@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.)

[nblumhardt]

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!

[nblumhardt]

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.

[jskeet]

@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.

[nblumhardt]

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]

Thinking about this we should add Json to ConsoleLoggerFormat and add support for this. Seems like its quite ubiquitous at this point.

[jskeet]

@davidfowl: If there's anything I can do to help prove out any designs, tests against Stackdriver etc, do let me know. Would love to help progress this.

[pharring]

@jskeet do you happen to know if Stackdriver documents a particular structure or schema for structured logs?
For example:

1. Should "level" be represented as an integer or a string? Are the expected levels compatible with .NET's LogLevel?
2. How should scopes be represented? As an array, or flattened into properties on the main object?

Edit: Looking at your code at https://github.com/nodatime/nodatime.org/blob/master/src/NodaTime.Web/Logging/JsonConsoleLogger.cs there's no timestamp field. Is that intentional? I also see a translation from LogLevel to severity (DEBUG,INFO,WARNING,ERROR,CRITICAL). Is that specific to Stackdriver?

[jskeet]

@pharring: This is the best documentation I know of for the log structure: https://cloud.google.com/logging/docs/reference/v2/rest/v2/LogEntry

The level should be represented as a string; the mapping in the nodatime.org code was the most appropriate I could work out; there's a full list of severities if you want to think about a different way of mapping things.

I don't understand logging scopes well enough to answer the question about them, but if you'd like to give a good example of what code might look like and what you'd want the log to look like, I could perform some experiments in Stackdriver quite easily.

[pharring]

Thanks. I now see the relevance of the earlier discussion of an "opinionated" JSON writer. It seems whatever we do here, someone's going to want something different for their cloud/host/environment. Reading through the Stackdriver docs, I get the impression that people deal with mismatches (differences of opinion?) by writing custom parsers -- often using regular expressions. Following that to its logical conclusion, perhaps we should just use the systemd format (everything on one line) and have folks derive structure by parsing that. There seems to be some middleground that "fluentd/fluentbits" operates in: adapting minimal structure to opinionated structure.

Scopes are a way of adding additional context to log messages. Scopes are nested. Scopes flow with async calls. They're used to add correlation identifiers (spans, request IDs, routing information). They're vital in a multi-threaded app so you can recover 'causality' -- especially useful when things go wrong (errors, exceptions), but also for measuring elapsed times (pairing up "start/stop" events and comparing their timestamps). So, I think (here's an opinion again) you really want them in your structured JSON. Scopes can be arbitrary objects, name-value pairs, formattable strings, etc. Which means that serialized property names may clash with properties in the user's logged message -- which implies they should be nested objects. And since there may be an arbitrary number of them, they should be in a "scopes" array. I say "should", but this is just (my) opinion.

If you want to see them in action, create a new ASP.NET Core MVC application and add the ConsoleLoggerOptions.IncludeScopes option to the console logger. e.g. In appsettings.json:

{
  "Logging": {
    "LogLevel": {
      "Default": "Information",
      "Microsoft": "Warning",
      "Microsoft.Hosting.Lifetime": "Information"
    },
    "Console": {
      "IncludeScopes": true
    }
  },
  "AllowedHosts": "*"
}

I've been playing with a JSON-structured logger as well. Here's example output from a demo app which includes scopes:

{
  "Timestamp": "2019-11-25T17:43:05.9213085Z",
  "Level": "Information",
  "Category": "Microsoft.AspNetCore.Routing.EndpointMiddleware",
  "EventId": {
    "Id": 1,
    "Name": "ExecutedEndpoint"
  },
  "EndpointName": "DemoWebApp.Controllers.HomeController.Index (DemoWebApp)",
  "{OriginalFormat}": "Executed endpoint '{EndpointName}'",
  "FormattedMessage": "Executed endpoint 'DemoWebApp.Controllers.HomeController.Index (DemoWebApp)'",
  "Scopes": [
    {
      "RequestId": "0HLRHPRMM9FR1:00000001",
      "RequestPath": "/",
      "SpanId": "|599b24d2-462d01d53895a972.",
      "TraceId": "599b24d2-462d01d53895a972",
      "ParentId": ""
    },
    {
      "SessionId": "JpQkpFw6yRuj",
      "Version": "1.0.0-test"
    }
  ]
}

The first of the scopes represents the request in flight. The second is "ambient" (set globally for the "session").

Here's another that has an exception:

{
  "Timestamp": "2019-11-25T17:49:48.9729469Z",
  "Level": "Error",
  "Category": "Microsoft.AspNetCore.Diagnostics.DeveloperExceptionPageMiddleware",
  "EventId": {
    "Id": 1,
    "Name": "UnhandledException"
  },
  "{OriginalFormat}": "An unhandled exception has occurred while executing the request.",
  "Exception": {
    "Message": "The privacy page is not implemented.",
    "Type": "System.NotImplementedException",
    "StackTrace": [
      "at DemoWebApp.Controllers.HomeController.Privacy() in D:\\StructuredConsoleLogger\\DemoWebApp\\Controllers\\HomeController.cs:line 26",
      "at lambda_method(Closure , Object , Object[] )",
      "at Microsoft.Extensions.Internal.ObjectMethodExecutor.Execute(Object target, Object[] parameters)",
      "at Microsoft.AspNetCore.Mvc.Infrastructure.ActionMethodExecutor.SyncActionResultExecutor.Execute(IActionResultTypeMapper mapper, ObjectMethodExecutor executor, Object controller, Object[] arguments)",
      "at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.InvokeActionMethodAsync()",
      "at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.Next(State& next, Scope& scope, Object& state, Boolean& isCompleted)",
      "at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.InvokeNextActionFilterAsync()",
      "--- End of stack trace from previous location where exception was thrown ---",
      "at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.Rethrow(ActionExecutedContextSealed context)",
      "at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.Next(State& next, Scope& scope, Object& state, Boolean& isCompleted)",
      "at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.InvokeInnerFilterAsync()",
      "--- End of stack trace from previous location where exception was thrown ---",
      "at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeNextResourceFilter>g__Awaited|24_0(ResourceInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted)",
      "at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.Rethrow(ResourceExecutedContextSealed context)",
      "at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.Next(State& next, Scope& scope, Object& state, Boolean& isCompleted)",
      "at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.InvokeFilterPipelineAsync()",
      "--- End of stack trace from previous location where exception was thrown ---",
      "at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeAsync>g__Logged|17_1(ResourceInvoker invoker)",
      "at Microsoft.AspNetCore.Routing.EndpointMiddleware.<Invoke>g__AwaitRequestTask|6_0(Endpoint endpoint, Task requestTask, ILogger logger)",
      "at Microsoft.AspNetCore.Authorization.AuthorizationMiddleware.Invoke(HttpContext context)",
      "at Microsoft.AspNetCore.Diagnostics.DeveloperExceptionPageMiddleware.Invoke(HttpContext context)"
    ],
    "HResult": -2147467263
  },
  "Scopes": [
    {
      "RequestId": "0HLRHPRMM9FR2:00000003",
      "RequestPath": "/Home/Privacy",
      "SpanId": "|599b24d4-462d01d53895a972.",
      "TraceId": "599b24d4-462d01d53895a972",
      "ParentId": ""
    },
    {
      "SessionId": "JpQkpFw6yRuj",
      "Version": "1.0.0-test"
    }
  ]
}

As you can see, they can get pretty big. However, the (advanced?) structure gives plenty of handholds for parsers/ingestors/aggregators to lock onto.

Disclaimer: I'm coming from an Application Insights world where this kind of structure is built in - albeit opinionated and inflexible.

[jskeet]

Right. Stackdriver tracing has support for scopes, but I don't know about the logging side. I'll have to do more research on that.

[analogrelay]

An update on this: We're looking at providing this in 5.0. Specifically three things:

• An abstraction/API to allow fully customizing the Console Logger formatting (Think Func<Logging data, string>, but with some nuance around console colors and such)
• A formatter implementation that generates a single-line human-readable textual log message
• A formatter implementation that generates a JSON log message (one object per line)

Formatters would be configurable, much like other parts of our stack (options objects, DI/Config integration, etc.). That would allow the JSON formatter to allow customization of the object. If absolutely necessary, users can replace the formatter entirely with custom code.

The existing formats (Default and Systemd) would be refactored as formatter implementations. This should achieve the requirements from this issue and provide more flexibility in general to support richer and more flexible console logging.

Things will take a little bit to get rolling since we're focusing on migrating extensions packages to dotnet/runtime (see aspnet/Announcements#411) but this is on our radar for 5.0!

[Dotnet-GitSync-Bot]

I couldn't figure out the best area label to add to this issue. Please help me learn by adding exactly one area label.

[maryamariyan]

@davidfowl: If there's anything I can do to help prove out any designs, tests against Stackdriver etc, do let me know. Would love to help progress this.

@jskeet the above APIs made their way to preview 8. It would be great to get feedback while the feature is in preview. As for the built-in Json formatter. Here's a screenshot of how it looks like:

screenshot below is:

for

using (_logger.BeginScope(new { Message = "Hello" }))
using (_logger.BeginScope(new KeyValuePair<string, string>("key", "value")))
using (_logger.BeginScope("This is a scope message with number: {CustomNumber}", 11123))
{
    _logger.LogInformation(_ex, "exception message with {0}", "stacktrace");
}

Other samples:

Sample usage:

using var loggerFactory = LoggerFactory.Create(builder =>
    {
        builder.AddJsonConsole(o =>
            {
                o.JsonWriterOptions = new JsonWriterOptions()
                        {
                            Indented = true
                        };
                o.IncludeScopes = true;
                o.TimestampFormat = "HH:mm:ss ";
            });
    });

var logger = loggerFactory.CreateLogger<Program>();
using (logger.BeginScope(new { Message = "Hello" }))
using (logger.BeginScope(new KeyValuePair<string, string>("key", "value")))
using (logger.BeginScope("This is a scope message with number: {CustomNumber}", 11123))
{
    logger.LogInformation(exxx, "exception message with {0}", "stacktrace");
}

There is also the option to implement a custom formatter using the above APIs. This gist shows how to make a custom formatter: https://gist.github.com/maryamariyan/8fdf800318f61b1244b42c185b83b179

[jskeet]

@maryamariyan: Great, thank you. I'll try it out next week.

[alefranz]

Hi @maryamariyan, I've played with this and it is super great!
I hope you don't mind if I jump into this conversation with some personal observations, but I believe this aspects haven't been discussed yet.

I personally think that it is quite common to need the json to conform to a particular format (e.g. to meet the requirement of a 3rd party tool to ingest the logs or to be compatible with logs produced by other applications) or at least that happens quite a lot to me. It would help me to have some facility to create custom json formatters.
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.
In my use case, I would also need to pull some of this properties or scopes and put them at top level, so ideally it would be nice to have a struct with all the required info already pulled out from the LogEntry so I can decide how to format iit and have a virtual method that receive it.

Maybe this is too specific and it should be solved externally from this formatter, like providing a pooled buffer solution for the json writer and maybe some easier API to get the KeyValuePairs out of the scopes (handling the edge cases which would be nice to handle as per below)

Regarding the provided JsonConsoleFormatter, I have a few questions:

• By default the Timestamp field is null. Why not having a default format (e.g. ISO 8601) so that it works well out of the box?
• If the scope is a string with a place holder, the rendered version doesn't get added. I think it is useful to have it (except the scenario when the content is only the placeholder).
• If there are multiple scopes which are a string with a place holder, the {OriginalFormat} get added multiple time, but having duplicated keys in JSON, while correct, it is generally not recommended (see RFC8259 section 4. Also I'm unsure if it makes sense to have {OriginalFormat} when the content is only the place holder and it gets pulled out as key.
• If the scope is a KeyValuePair, and specifically a KeyValuePair<string, object>, it doesn't get pulled out as key/value in the scope json, like it happens instead when using a string with only a placeholder or using Dictionary<string, object>, so that when you have only one property to add to the scope you don't have to either allocate or implement a custom IReadOnlyCollection<KeyValuePair<string, object>>.

Here is an extension of your example to better illustrate my points:

using (logger.BeginScope(new { Message = "Hello" }))
using (logger.BeginScope(new KeyValuePair<string, string>("key", "value")))
using (logger.BeginScope(new KeyValuePair<string, object>("anotherkey", "anothervalue")))
using (logger.BeginScope(new Dictionary<string, object> { ["yetanotherkey"] = "yetanothervalue" }))
using (logger.BeginScope("A string"))
using (logger.BeginScope("This is a scope message with number: {CustomNumber}", 11123))
using (logger.BeginScope("{AnotherNumber}", 42))
{
    logger.LogInformation(new Exception(), "exception message with {0}", "stacktrace");
}

Output:

{
  "Timestamp": "2020-07-19T20:21:33.8836859\u002B01:00",
  "EventId": 0,
  "LogLevel": "Information",
  "Category": "JsonLogging.Program",
  "Message": "exception message with stacktrace",
  "Exception": {
    "Message": "Exception of type \u0027System.Exception\u0027 was thrown.",
    "Type": "System.Exception",
    "StackTrace": [],
    "HResult": -2146233088
  },
  "0": "stacktrace",
  "{OriginalFormat}": "exception message with {0}",
  "Scopes": {
    "0": "{ Message = Hello }",
    "1": "[key, value]",
    "2": "[anotherkey, anothervalue]",
    "yetanotherkey": "yetanothervalue",
    "3": "A string",
    "CustomNumber": "11123",
    "{OriginalFormat}": "This is a scope message with number: {CustomNumber}",
    "AnotherNumber": "42",
    "{OriginalFormat}": "{AnotherNumber}"
  }
}

Thank you!

[davidfowl]

By default the Timestamp field is null. Why not having a default format (e.g. ISO 8601) so that it works well out of the box?

We should do this for all console loggers not just JSON (maybe that's a breaking change but it seems small). Anyways I'm not opposed to that change but it's unrelated to JSON formatting.

If there are multiple scopes which are a string with a place holder, the {OriginalFormat} get added multiple time, but having duplicated keys in JSON, while correct, it is generally not recommended (see RFC8259 section 4. Also I'm unsure if it makes sense to have {OriginalFormat} when the content is only the place holder and it gets pulled out as key.

That seems like a bug.

If the scope is a KeyValuePair, and specifically a KeyValuePair<string, object>, it doesn't get pulled out as key/value in the scope json, like it happens instead when using a string with only a placeholder or using Dictionary<string, object>, so that when you have only one property to add to the scope you don't have to either allocate or implement a custom IReadOnlyCollection<KeyValuePair<string, object>>.

KeyValuePair isn't understood by any of the loggers, the contract is IReadOnlyCollection<KeyValuePair<string, object>>, I don't think that should be part of this change.

[jskeet]

Great, thank you. I'll try it out next week.

Oops - I hadn't realized that preview 8 isn't actually out yet. I'll wait until there's a preview I can install a little more simply than building it from source, but I'll try to jump on it promptly at that point.

[davidfowl]

@jskeet you don't need to wait, in fact:

https://github.com/dotnet/installer#installers-and-binaries

Add the dotnet5 nuget feed.

<configuration>
  <packageSources>
    <add key="dotnet5" value="https://pkgs.dev.azure.com/dnceng/public/_packaging/dotnet5/nuget/v3/index.json" />
  </packageSources>
</configuration>

Then add the package:

<PackageReference Include="Microsoft.Extensions.Logging.Console" Version="5.0.0-preview.8.20365.13" />

[jskeet]

@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...)

[davidfowl]

@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 😄

[jskeet]

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

[maryamariyan]

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.

[jskeet]

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.

[davidfowl]

@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.

[fredrikhr]

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

[jskeet]

@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

[maryamariyan]

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.

[dmitriyse]

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

[hannahchan]

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?

[IEvangelist]

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