ILogger extension methods could add the Arcus additional meta-data in a structured way

[fgheysels]

I like the functionality that Arcus provides to easily log custom events , metrics, etc... very much.
As far as I know, this functionality is made possible by adding additional meta-information to the message that is being logged, and the ApplicationInsights sink parses the log-message and retrieves that information. This works, and this is great.

However, we have also services that are not logging to Application Insights directly. Those services are running in containers in a Kubernetes cluster (on prem), and hence, the logs are written to the stdout & stderr of the containers.

We are using Azure Arc, and are transferring the stdout/stderr container logs via Azure Arc to Log Analytics. We would like to work with those logs by executing KQL queries on the Log Analytics workspace. The problem is, is that those logs are not in a structured format. To be able to have them in a structured format, it would be great if the Arcus extension method could write the additional meta-information in a structured way in the log message.

I would suggest that the Arcus extension method do something like this. (Warning, non compiled c# code; it's just to give you an idea on what could be possible):

public static void LogEvent( this ILogger logger, string name, Dictionary<string,object> context )
{
     var entry = new LogEntry
     {
          Type = "Event",
          Message = name,
          Context = context;
     };
     logger.LogWarning("{@entry}", entry);
}

public class LogEntry
{
    public string LogType {get;set;}
    public string Message {get;set;}
    public Dictionary<string,object> Context {get;set;}
}

When you then use Serilogs' ConsoleLogger with this outputtemplate:

loggerConfig.MinimumLevel.Information()
    .WriteTo.Console(
        outputTemplate: "{{ \"ts\": {Timestamp:yyyy-MM-ddTHH:mm:ss.zzz}, \"level\": \"{Level}\", \"message\": \"{Message:lj}\", \"properties\": {Properties:j} }{NewLine}",
        formatProvider: CultureInfo.InvariantCulture);

You get the output like this:

{ "ts": 2021-04-22T12:07:36+02:00, "level": "Warning", "message": "{"Type": "Event", "Message": "SomeEvent", "Properties": {"Item": "foo", "Error": "bar"}, "$type": "LogEntry"}", "properties": {"SourceContext": "ArcusObservabilityConsoleTest.TestClass"} }

So as you can see, the Message now contains all the requested information in a structured piece of json (note the lj formatter on Message in the template, so I guess would make this also easier for the AppInsights sink to retrieve the required information. (Instead of doing some string parsing, you can deserialize the message to the LogEntry class and retrieve the information in a more typed way).

If Arcus could add the meta-information in this way, then I can have this as well in a structured way in Log Analytics :)

More information on the Serilog specifics can be found here.

[stijnmoreels]

Oh, yeah, seems like there's only advantages of this approach. What I thought about is that some log extensions write dependencies in a more 'string like' way as in a sentence and that will become more obscure if we use this approach for all. I think, technically it's also a breaking change so we'll have to do it in a next major if we want to be correct.

[fgheysels]

Oh, yeah, seems like there's only advantages of this approach. What I thought about is that some log extensions write dependencies in a more 'string like' way as in a sentence and that will become more obscure if we use this approach for all.

I don't know if Arcus also 'overwrites' the ILogger LogInformation , LogWarning, etc.... methods ? They won't be impacted I guess.

The way things are outputted is also very much determined by the outputTemplate that you specify. For instance:

loggerConfiguration
    .MinimumLevel.Information()
    .WriteTo.Console(outputTemplate: "{Timestamp} [{Level}] {Message}{NewLine}");


var scope = new Dictionary<string, object>()
{
    ["Item"] = "foo",
    ["Error"] = "bar"
};

LogEntry entry = new LogEntry()
{
    Type = "Event",
    Message = "SomeEvent",
    Properties = scope
};

_logger.LogWarning("{@entry}", entry);

using (_logger.BeginScope(scope))
{
    _logger.LogInformation("Some information trace");
   _logger.LogWarning("Some warning trace");
}

results in:

04/23/2021 07:41:35 +02:00 [Warning] LogEntry {Type="Event", Message="SomeEvent", Properties={["Item"]="foo", ["Error"]="bar"}}
04/23/2021 07:41:35 +02:00 [Information] Some information trace
04/23/2021 07:41:35 +02:00 [Warning] Some warning trace

I think, technically it's also a breaking change so we'll have to do it in a next major if we want to be correct.

How's that, since I think it's only internal workings that change ?

[stijnmoreels]

Oh, and btw, thanks a lot for proposing this!! You are one of the few external people that actually invest in new issues, ideas and PR's. So, thanks lot!

[stijnmoreels]

Oh, yeah, seems like there's only advantages of this approach. What I thought about is that some log extensions write dependencies in a more 'string like' way as in a sentence and that will become more obscure if we use this approach for all.

I don't know if Arcus also 'overwrites' the ILogger LogInformation , LogWarning, etc.... methods ? They won't be impacted I guess.

Let me give an example. When tracking an Azure Blob storage instance, you'll output this:

Dependency Azure blob multimedia named images in 00:00:00.2521801 at 03/23/2020 09:56:31 +00:00 (Successful: True - Context: )

That's what I meant by a 'sentence'. But I guess if we use seperate log entry types for dependencies, metrics, events... we can overcome this 'obscurity'.

I think, technically it's also a breaking change so we'll have to do it in a next major if we want to be correct.

How's that, since I think it's only internal workings that change ?

Well, maybe this is nitpicking. When we log our custom meta-data, we change the Serilog public MessageTemplate property that holds the structure of the log message (w/o the injected arguments). If we change this property with the proposal described here, we change that public property. Any sinks or custom-consumer functionality that uses this will possibly break. So, I think in the context of 'public supported' and since we change that public value, we break it by this change.

[tomkerkhove]

There is a breaking change though, that if you use STDOUT/STDERR you will now get JSONified data, instead of purely string. However, it depends on the output template I guess?

[fgheysels]

It depends on the outputtemplate indeed. Although for those structured logs for events, metrics, you'll have some json in your Message indeed. (See #205 (comment) )

[fgheysels]

I think we're not completely there yet.
See my remark in the discussion here.

We're still getting this as some kind of unstructured data because of the EventFormat which looks like this:

/// <summary>
/// Gets the message format to log events; compatible with Application Insights 'Events'.
/// </summary>
public const string EventFormat = MessagePrefixes.Event + " {@" + ContextProperties.EventTracking.EventLogEntry + "}";

(source)

IMHO, we should just write the event like this:

var entry = new EventLogEntry(name, context);

logger.LogWarning("{@entry}", entry);

(Note that the placeholder name must match the variable name).
EventLogEntry can be a custom type that contains all properties that we want to log, like this:

var scope = new Dictionary<string, object>()
{
          ["Item"] = "foo",
          ["Error"] = "bar"
 };

EventLogEntry entry = new EventLogEntry()
 {
         Type = "Event",
          Message = "SomeEvent",
          Properties = scope
};

 _logger.LogWarning("{@entry}", entry);

Then, in the AppInsights Sink, you can deserialize the string to the appropriate type to construct the EventTelemetry instance.
(The type that has been used to create the logentry, is present in the $type property in the JSON:

"message": "{"Type": "Event", "Message": "SomeEvent", "Properties": {"Item": "foo", "Error": "bar"}, "$type": "EventLogEntry"}"

[stijnmoreels]

I think we're not completely there yet.
See my remark in the discussion here.

We're still getting this as some kind of unstructured data because of the EventFormat which looks like this:

/// <summary>
/// Gets the message format to log events; compatible with Application Insights 'Events'.
/// </summary>
public const string EventFormat = MessagePrefixes.Event + " {@" + ContextProperties.EventTracking.EventLogEntry + "}";

Seems that there was an missunderstanding as this was the sturcture we proposed before we changed this 😄 .
We can look for this change though, where we solely rely on the structured data.

[tomkerkhove]

IMHO, we should just write the event like this:

var entry = new EventLogEntry(name, context);

logger.LogWarning("{@entry}", entry);

(Note that the placeholder name must match the variable name).

I think this is the gist of it @stijnmoreels

[stijnmoreels]

Note that the placeholder name must match the variable name

@fgheysels , I don't see that in the docs?

[fgheysels]

Might indeed not be necessary.

[stijnmoreels]

@fgheysels , is this something you were able to test with the MyGet package? Or do you require a preview package?
We'll release a new minor for this library, so you could maybe use that one more easily.

[fgheysels]

No, I haven't been able to test this yet, sorry.

[tomkerkhove]

This is shipped so closing

[tomkerkhove]

Feel free to let us know how it works @fgheysels

[tomkerkhove]

This probably works in Log Analytics now, but the default outcome with the console sink sucks pretty much:

[12:15:54 WRN] {@request}

[stijnmoreels]

This probably works in Log Analytics now, but the default outcome with the console sink sucks pretty much:

[12:15:54 WRN] {@request}

Hmm, yeah, that's not very good. The default string representation of these types is still the sentence, so I'm wondering how this becomes this kind of format. Does the output template not match or something?

[fgheysels]

At first sight, it looks OK to me.
Further investigation and testing is required at my side though.

[fgheysels]

This probably works in Log Analytics now, but the default outcome with the console sink sucks pretty much:

[12:15:54 WRN] {@request}

When I output to the console, without specifying an output-template, it looks like this:

[tomkerkhove]

What do your request logs look like @fgheysels ?

Is that on STDOUT or Log Analytics?

[fgheysels]

That's stdout, via a console application where I'm using Arcus Observability.

This:

Results in this:

(That's just stdout, with a custom output-template configured).
Without a custom output-template, it looks like this:

[stijnmoreels]

That's stdout, via a console application where I'm using Arcus Observability.

This:

Results in this:

(That's just stdout, with a custom output-template configured).
Without a custom output-template, it looks like this:

So you're happy with this? We can leave this issue closed, then?

[tomkerkhove]

Odd, that's not what we are seeing. What version of Serilog/.NET are you on @fgheysels?