JsonConsoleFormatter to use array of scope to fix unique key issue #39860

maryamariyan · 2020-07-23T19:46:39Z

Fixes duplicate keys in Json
Fixes: #39664

ghost · 2020-07-23T19:46:42Z

Tagging subscribers to this area: @maryamariyan
See info in area-owners.md if you want to be subscribed.

maryamariyan · 2020-07-23T19:48:08Z

src/libraries/Microsoft.Extensions.Logging.Console/src/JsonConsoleFormatter.cs

                    var timestampFormat = FormatterOptions.TimestampFormat;
                    if (timestampFormat != null)
                    {
                        var dateTime = FormatterOptions.UseUtcTimestamp ? DateTime.UtcNow : DateTime.Now;
-                        timestamp = dateTime.ToString(timestampFormat);
+                        writer.WriteString("Timestamp", dateTime.ToString(timestampFormat));


also would skip showing Timestamp when value is null

maryamariyan · 2020-07-23T19:49:39Z

src/libraries/Microsoft.Extensions.Logging.Console/src/JsonConsoleFormatter.cs

+                    }
+                    else if (logEntry.State != null)
+                    {
+                        writer.WriteString(nameof(logEntry.State), logEntry.State.ToString());


Also note the current implementation is missing the rendered message for some of the scopes, not sure if that should be tracked as separate issue?

(taken from #39664 (comment))
@alefranz I think this is what you were asking for.

Not really, I was referring to the scope. Sorry I should have raised the issue before. Here it is: #39867

Regarding this change, in which scenarios would the state not be a k/v collection?

Regarding this change, in which scenarios would the state not be a k/v collection?

Refer to test: Log_IncludeScopes_ContainsDuplicateNamedPropertiesInScope_AcceptableJson

using (logger.BeginScope("scope1 {name1}", 123)) using (logger.BeginScope("scope2 {name1} {name2}", 456, 789)) logger.Log(LogLevel.Information, 0, state: "exception message", exception: null, formatter: (a, b) => a);

tarekgh · 2020-07-23T20:50:45Z

src/libraries/Microsoft.Extensions.Logging.Console/src/JsonConsoleFormatter.cs

@@ -79,10 +77,16 @@ public override void Write<TState>(in LogEntry<TState> logEntry, IExternalScopeP

                    if (logEntry.State is IReadOnlyCollection<KeyValuePair<string, object>> stateDictionary)


IReadOnlyCollection [](start = 42, length = 19)

does it make sense to use IEnumerable rather than IReadOnlyCollection? this will give more coverage to other types.

I don't think it is supposed to work if it is not IReadOnlyCollection

So why we are testing the type? doesn't mean you can get other types?

From my understanding the contract expects IReadOnlyCollection<KeyValuePair<string, object>> and that is why I check for it. (Referring to @davidfowl 's comment in #34742 (comment))

tarekgh

I added a question. other than that LGTM.

alefranz · 2020-07-23T21:14:49Z

I'm not super convinced as while it solve the duplicate keys issue, I had originally in mind mainly the {OriginalFormat} field. I wonder if once this logs gets ingested into a queryable datastore, it would make harder to write queries against properties.

At least for me, the main scenario to use scopes is to attach properties to have in all log entries (e.g. a transaction id) so it needs to be possible to query the datastore with this property no matter how nested is the specific property.

For example:

using (logger.BeginScope("{Number}", 2))
using (logger.BeginScope("{AnotherNumber}", 3))
{
    logger.LogInformation("{LogEntryNumber}", 1);
}

will become:

{
  "Timestamp": "2020-07-23T22:09:59.4750365\u002B01:00",
  "EventId": 0,
  "LogLevel": "Information",
  "Category": "JsonLogging.Program",
  "Message": "1",
  "State": {
    "LogEntryNumber": "1",
    "{OriginalFormat}": "{LogEntryNumber}"
  },
  "Scopes": [
    {
      "Number": "2",
      "{OriginalFormat}": "{Number}"
    },
    {
      "AnotherNumber": "3",
      "{OriginalFormat}": "{AnotherNumber}"
    }
  ]
}

I need to play with ingest this entries into a system like Seq or Kibana.
My worry is that out of the box you will have to know the order of the scopes if you want for example to get all the logs entries with Number = 2, unless you define some custom indexing that would be needed for each of this properties.
I wonder if the properties should be stored in a different field and merged together.
But then there would be a risk of collision, not sure how high it would be?
Unless we remove duplicates keeping latest like Serilog does, but then you will lose date.

tarekgh · 2020-07-23T21:17:27Z

CC @davidfowl

alefranz · 2020-07-23T21:38:30Z

My worry is that out of the box you will have to know the order of the scopes if you want for example to get all the logs entries with Number = 2, unless you define some custom indexing that would be needed for each of this properties.

I've tried in Seq and you can query with Scopes[?].Number = '2', so it would work, although you will not be able to create such filter just clicking on a log entry in the UI.

maryamariyan · 2020-07-24T20:04:13Z

I wonder if the properties should be stored in a different field and merged together.
But then there would be a risk of collision, not sure how high it would be?
Unless we remove duplicates keeping latest like Serilog does, but then you will lose date.

I added your use case as well to JsonConsoleFormatterTests
Interesting observation about Serilog. At least for the scope of this PR the aim is to make sure we don't end up with invalid Json format (duplicate keys).

UPDATE:
Now for your example

using (logger.BeginScope("{Number}", 2))
using (logger.BeginScope("{AnotherNumber}", 3))
{
    logger.LogInformation("{LogEntryNumber}", 1);
}

we'd get:

{
  "Timestamp": "15:57:40 ",
  "EventId": 0,
  "LogLevel": "Information",
  "Category": "ConsoleApp46.Program",
  "Message": "1",
  "State": {
    "Message": "1",
    "LogEntryNumber": "1",
    "{OriginalFormat}": "{LogEntryNumber}"
  },
  "Scopes": [
    {
      "Message": "2",
      "Number": "2",
      "{OriginalFormat}": "{Number}"
    },
    {
      "Message": "3",
      "AnotherNumber": "3",
      "{OriginalFormat}": "{AnotherNumber}"
    }
  ]
}

maryamariyan · 2020-07-25T00:53:20Z

There is an issue to solve that I'll leave out of scope for this PR, and that is, we are now introducing more "Message" JSON elements per logged output. and it would be better if the name "Message" was reduced to something like @m or something to make more compact and efficient. Other JSON elements could also be shortened, but as this needs more thought I will tackle it separately.

There is a conversation about it here: #39664 (comment).

I'll create an issue to track this individually: Allow JsonConsoleFormatter to write in compact format #39917

maryamariyan · 2020-07-27T17:24:15Z

fixed PR conflict through rebase

ghost · 2020-07-27T17:24:55Z

Hello @maryamariyan!

Because this pull request has the auto-merge label, I will be glad to assist with helping to merge this pull request once all check-in policies pass.

p.s. you can customize the way I help with merging this pull request, such as holding this pull request until a specific person approves. Simply @mention me (`@msftbot`) and give me an instruction to get started! Learn more here.

maryamariyan added the area-Extensions-Logging label Jul 23, 2020

maryamariyan self-assigned this Jul 23, 2020

maryamariyan commented Jul 23, 2020

View reviewed changes

maryamariyan requested review from layomia and tarekgh July 23, 2020 20:07

tarekgh reviewed Jul 23, 2020

View reviewed changes

tarekgh approved these changes Jul 23, 2020

View reviewed changes

alefranz mentioned this pull request Jul 23, 2020

JsonConsoleFormatter: should include formatted string for scopes #39867

Closed

maryamariyan force-pushed the json-formatter branch from 57d5516 to 2e85a48 Compare July 24, 2020 20:05

jaredpar mentioned this pull request Jul 24, 2020

OSX machines are de-provisioned during CI / PR runs leading to failures #34472

Closed

maryamariyan force-pushed the json-formatter branch 2 times, most recently from 02f1367 to bf1f03c Compare July 25, 2020 00:42

jaredpar mentioned this pull request Jul 27, 2020

Errors installing the SDK during builds #34015

Closed

Fix JSON possible dupe key issue

54b74ed

maryamariyan force-pushed the json-formatter branch from bf1f03c to 54b74ed Compare July 27, 2020 17:24

maryamariyan added the auto-merge label Jul 27, 2020

ghost merged commit 168409e into dotnet:master Jul 27, 2020

Jacksondr5 pushed a commit to Jacksondr5/runtime that referenced this pull request Aug 10, 2020

Fix JSON possible dupe key issue (dotnet#39860)

632af4a

karelz added this to the 5.0.0 milestone Aug 18, 2020

ghost locked as resolved and limited conversation to collaborators Dec 8, 2020

This pull request was closed.

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

JsonConsoleFormatter to use array of scope to fix unique key issue #39860

JsonConsoleFormatter to use array of scope to fix unique key issue #39860

maryamariyan commented Jul 23, 2020

ghost commented Jul 23, 2020

maryamariyan Jul 23, 2020 •

edited

Loading

maryamariyan Jul 23, 2020 •

edited

Loading

alefranz Jul 23, 2020

maryamariyan Jul 24, 2020

tarekgh Jul 23, 2020

maryamariyan Jul 23, 2020 •

edited

Loading

tarekgh Jul 23, 2020

maryamariyan Jul 24, 2020

tarekgh left a comment

alefranz commented Jul 23, 2020

tarekgh commented Jul 23, 2020

alefranz commented Jul 23, 2020

maryamariyan commented Jul 24, 2020 •

edited

Loading

maryamariyan commented Jul 25, 2020 •

edited

Loading

maryamariyan commented Jul 27, 2020 •

edited

Loading

ghost commented Jul 27, 2020

		@@ -79,10 +77,16 @@ public override void Write<TState>(in LogEntry<TState> logEntry, IExternalScopeP

		if (logEntry.State is IReadOnlyCollection<KeyValuePair<string, object>> stateDictionary)

JsonConsoleFormatter to use array of scope to fix unique key issue #39860

JsonConsoleFormatter to use array of scope to fix unique key issue #39860

Conversation

maryamariyan commented Jul 23, 2020

ghost commented Jul 23, 2020

maryamariyan Jul 23, 2020 • edited Loading

Choose a reason for hiding this comment

maryamariyan Jul 23, 2020 • edited Loading

Choose a reason for hiding this comment

alefranz Jul 23, 2020

Choose a reason for hiding this comment

maryamariyan Jul 24, 2020

Choose a reason for hiding this comment

tarekgh Jul 23, 2020

Choose a reason for hiding this comment

maryamariyan Jul 23, 2020 • edited Loading

Choose a reason for hiding this comment

tarekgh Jul 23, 2020

Choose a reason for hiding this comment

maryamariyan Jul 24, 2020

Choose a reason for hiding this comment

tarekgh left a comment

Choose a reason for hiding this comment

alefranz commented Jul 23, 2020

tarekgh commented Jul 23, 2020

alefranz commented Jul 23, 2020

maryamariyan commented Jul 24, 2020 • edited Loading

maryamariyan commented Jul 25, 2020 • edited Loading

maryamariyan commented Jul 27, 2020 • edited Loading

ghost commented Jul 27, 2020

p.s. you can customize the way I help with merging this pull request, such as holding this pull request until a specific person approves. Simply @mention me (@msftbot) and give me an instruction to get started! Learn more here.

maryamariyan Jul 23, 2020 •

edited

Loading

maryamariyan Jul 23, 2020 •

edited

Loading

maryamariyan Jul 23, 2020 •

edited

Loading

maryamariyan commented Jul 24, 2020 •

edited

Loading

maryamariyan commented Jul 25, 2020 •

edited

Loading

maryamariyan commented Jul 27, 2020 •

edited

Loading

p.s. you can customize the way I help with merging this pull request, such as holding this pull request until a specific person approves. Simply @mention me (`@msftbot`) and give me an instruction to get started! Learn more here.