Runtime: Certain tests in Microsoft.Extensions.Logging.EventSource may fail in non-ASCII locales

[Gnbrkm41]

Description

Run tests in Microsoft.Extensions.Logging.EventSource.Tests test project in non-ASCII locales. The expected data that's constructed in runtime do not match with the actual data.

Test    Duration    Traits  Error Message
Microsoft.Extensions.Logging.Test.EventSourceLoggerTest.Logs_AllEvents_IfTraceSet Failed    25.8 sec        Assert.Collection() Failure Collection: ["{\"__EVENT_NAME\":\"MessageJson\",\"Level\":1,\"Fa"..., "{\"__EVENT_NAME\":\"MessageJson\",\"Level\":0,\"Fa"..., "{\"__EVENT_NAME\":\"MessageJson\",\"Level\":2,\"Fa"..., "{\"__EVENT_NAME\":\"ActivityJsonStart\",\"ID\":1,\"..., "{\"__EVENT_NAME\":\"MessageJson\",\"Level\":4,\"Fa"..., ...] Error during comparison of item at index 6 Inner exception: Event data '{"__EVENT_NAME":"ActivityJsonStart","ID":2,"FactoryID":1,"LoggerName":"Logger3","ArgumentsJson":{"timeParam":"2016-05-03 \uC624\uD6C4 7:00:00","guidParam":"29bebd2c-7fa6-4e97-af68-b91fdaae24b6","{OriginalFormat}":"Inner scope {timeParam} {guidParam}"}}' does not contain expected fragment "ArgumentsJson":{"timeParam":"2016-05-03 오후 7:00:00","guidParam":"29bebd2c-7fa6-4e97-af68-b91fdaae24b6         Expected: True         Actual:   False
Microsoft.Extensions.Logging.Test.EventSourceLoggerTest.Logs_AsExpected_AtErrorLevel Failed < 1 ms      Assert.Collection() Failure Collection: ["{\"__EVENT_NAME\":\"ActivityJsonStart\",\"ID\":8,\"..., "{\"__EVENT_NAME\":\"MessageJson\",\"Level\":4,\"Fa"..., "{\"__EVENT_NAME\":\"MessageJson\",\"Level\":5,\"Fa"..., "{\"__EVENT_NAME\":\"ActivityJsonStart\",\"ID\":9,\"..., "{\"__EVENT_NAME\":\"ActivityJsonStop\",\"ID\":9,\""..., ...] Error during comparison of item at index 3 Inner exception: Event data '{"__EVENT_NAME":"ActivityJsonStart","ID":9,"FactoryID":6,"LoggerName":"Logger3","ArgumentsJson":{"timeParam":"2016-05-03 \uC624\uD6C4 7:00:00","guidParam":"29bebd2c-7fa6-4e97-af68-b91fdaae24b6","{OriginalFormat}":"Inner scope {timeParam} {guidParam}"}}' does not contain expected fragment "ArgumentsJson":{"timeParam":"2016-05-03 오후 7:00:00","guidParam":"29bebd2c-7fa6-4e97-af68-b91fdaae24b6         Expected: True         Actual:   False
Microsoft.Extensions.Logging.Test.EventSourceLoggerTest.Logs_AsExpected_AtWarningLevel Failed   < 1 ms      Assert.Collection() Failure Collection: ["{\"__EVENT_NAME\":\"ActivityJsonStart\",\"ID\":13,"..., "{\"__EVENT_NAME\":\"MessageJson\",\"Level\":4,\"Fa"..., "{\"__EVENT_NAME\":\"MessageJson\",\"Level\":5,\"Fa"..., "{\"__EVENT_NAME\":\"ActivityJsonStart\",\"ID\":14,"..., "{\"__EVENT_NAME\":\"MessageJson\",\"Level\":3,\"Fa"..., ...] Error during comparison of item at index 3 Inner exception: Event data '{"__EVENT_NAME":"ActivityJsonStart","ID":14,"FactoryID":12,"LoggerName":"Logger3","ArgumentsJson":{"timeParam":"2016-05-03 \uC624\uD6C4 7:00:00","guidParam":"29bebd2c-7fa6-4e97-af68-b91fdaae24b6","{OriginalFormat}":"Inner scope {timeParam} {guidParam}"}}' does not contain expected fragment "ArgumentsJson":{"timeParam":"2016-05-03 오후 7:00:00","guidParam":"29bebd2c-7fa6-4e97-af68-b91fdaae24b6         Expected: True         Actual:   False
Microsoft.Extensions.Logging.Test.EventSourceLoggerTest.Logs_AsExpected_WithDefaults Failed 1 ms        Assert.Collection() Failure Collection: ["{\"__EVENT_NAME\":\"FormattedMessage\",\"Level\":1"..., "{\"__EVENT_NAME\":\"Message\",\"Level\":1,\"Factor"..., "{\"__EVENT_NAME\":\"MessageJson\",\"Level\":1,\"Fa"..., "{\"__EVENT_NAME\":\"FormattedMessage\",\"Level\":2"..., "{\"__EVENT_NAME\":\"Message\",\"Level\":2,\"Factor"..., ...] Error during comparison of item at index 13 Inner exception: Event data '{"__EVENT_NAME":"ActivityJsonStart","ID":16,"FactoryID":13,"LoggerName":"Logger3","ArgumentsJson":{"timeParam":"2016-05-03 \uC624\uD6C4 7:00:00","guidParam":"29bebd2c-7fa6-4e97-af68-b91fdaae24b6","{OriginalFormat}":"Inner scope {timeParam} {guidParam}"}}' does not contain expected fragment "ArgumentsJson":{"timeParam":"2016-05-03 오후 7:00:00","guidParam":"29bebd2c-7fa6-4e97-af68-b91fdaae24b6         Expected: True         Actual:   False
Microsoft.Extensions.Logging.Test.EventSourceLoggerTest.Logs_AsExpected_WithDefaults_EnabledEarly Failed    1 ms        Assert.Collection() Failure Collection: ["{\"__EVENT_NAME\":\"FormattedMessage\",\"Level\":1"..., "{\"__EVENT_NAME\":\"Message\",\"Level\":1,\"Factor"..., "{\"__EVENT_NAME\":\"MessageJson\",\"Level\":1,\"Fa"..., "{\"__EVENT_NAME\":\"FormattedMessage\",\"Level\":2"..., "{\"__EVENT_NAME\":\"Message\",\"Level\":2,\"Factor"..., ...] Error during comparison of item at index 13 Inner exception: Event data '{"__EVENT_NAME":"ActivityJsonStart","ID":18,"FactoryID":14,"LoggerName":"Logger3","ArgumentsJson":{"timeParam":"2016-05-03 \uC624\uD6C4 7:00:00","guidParam":"29bebd2c-7fa6-4e97-af68-b91fdaae24b6","{OriginalFormat}":"Inner scope {timeParam} {guidParam}"}}' does not contain expected fragment "ArgumentsJson":{"timeParam":"2016-05-03 오후 7:00:00","guidParam":"29bebd2c-7fa6-4e97-af68-b91fdaae24b6         Expected: True         Actual:   False
Microsoft.Extensions.Logging.Test.EventSourceLoggerTest.Logs_OnlyJson_IfKeywordSet Failed   86 ms       Assert.Collection() Failure Collection: ["{\"__EVENT_NAME\":\"MessageJson\",\"Level\":1,\"Fa"..., "{\"__EVENT_NAME\":\"MessageJson\",\"Level\":2,\"Fa"..., "{\"__EVENT_NAME\":\"ActivityJsonStart\",\"ID\":3,\"..., "{\"__EVENT_NAME\":\"MessageJson\",\"Level\":4,\"Fa"..., "{\"__EVENT_NAME\":\"MessageJson\",\"Level\":5,\"Fa"..., ...] Error during comparison of item at index 5 Inner exception: Event data '{"__EVENT_NAME":"ActivityJsonStart","ID":4,"FactoryID":2,"LoggerName":"Logger3","ArgumentsJson":{"timeParam":"2016-05-03 \uC624\uD6C4 7:00:00","guidParam":"29bebd2c-7fa6-4e97-af68-b91fdaae24b6","{OriginalFormat}":"Inner scope {timeParam} {guidParam}"}}' does not contain expected fragment "ArgumentsJson":{"timeParam":"2016-05-03 오후 7:00:00","guidParam":"29bebd2c-7fa6-4e97-af68-b91fdaae24b6         Expected: True         Actual:   False

Configuration

• Windows 10 Pro Insider Preview, Build 20170, x64
• Locale ko-KR
• Ran with VS2019 16.7 P4, with ./build.cmd -vs Microsoft.Extensions.Logging.EventSource -runtimeConfiguration Release -librariesConfiguration Debug

Regression?

I do not recall having this problem previously when I ran the library tests, but I actually don't remember when was the last time I did that and not had problems. 😅

Other information

Looking at the assertion message, it looks like the expected message uses the raw output from DateTime.ToString() which is locale dependent and therefore may have unicode characters: (TimeParam.ToString())
https://github.com/dotnet/runtime/blob/34e5c24ba2b8de54741a55b702eba72bf991e9d4/src/libraries/Microsoft.Extensions.Logging.EventSource/tests/EventSourceLoggerTest.cs#L849-L851

This results in the expected string containing 2016-05-03 오후 7:00:00 (locale ko-KR), however the actual result contains a JSON-encoded string (that is, with all the unicode characters escaped): 2016-05-03 \uC624\uD6C4 7:00:00 - I have verified that \uC624\uD6C4 is indeed 오후 (p.m. in Korean).

I expect this to happen on any other locales that contain non-ASCII characters in the output string. Ideally, the expected data should have the output properly JSON encoded before it's compared with the actual result (That is, assuming that we expect the actual result to JSON encode strings).

[Dotnet-GitSync-Bot]

I couldn't figure out the best area label to add to this issue. If you have write-permissions please help me learn by adding exactly one area label.

[safern]

Could it be related that this test was probably written based on NLS data and now we use ICU?

cc: @tarekgh

[Gnbrkm41]

Not exactly sure how they relate, unless with NLS data Korean characters were not considered candidates for escaping before being written to JSON output, and now with ICU they suddenly are?

I don't know much about the JSON spec so I can't tell much.

[msftbot[bot]]

Tagging subscribers to this area: @maryamariyan
Notify danmosemsft if you want to be subscribed.

[tarekgh]

This is related to codepoints "\uC624\uD6C4" just in case make the investigation easier.

[ericstj]

I believe this is only a problem with the test's assertion.

[tarekgh]

@ericstj we need to confirm if it is expected to produce escaped characters for Korean characters in JSON. it is worth to check that before we ship 5.0.

[ericstj]

Did we change anything that would impact the escaping of EventSourceLogger this release?

[tarekgh]

Did we change anything that would impact the escaping of EventSourceLogger this release?

Honestly, I don't know nor what is the expected behavior. I wanted to point this is something we need to validate before we release. I think JSON can be configured for escaping the characters. @maryamariyan may know better here.

CC @layomia

[ericstj]

Here's the relevant portion of EventSourceLogger:
https://github.com/dotnet/runtime/blob/34e5c24ba2b8de54741a55b702eba72bf991e9d4/src/libraries/Microsoft.Extensions.Logging.EventSource/src/EventSourceLogger.cs#L212-L232

This is just using the raw writer and is equivalent to what was done in 3.1.
https://github.com/dotnet/extensions/blob/1866984b44f34ffd498931075efed06f3cb09eaa/src/Logging/Logging.EventSource/src/EventSourceLogger.cs#L209-L229

[ericstj]

FWIW we found more than a couple tests for extensions that fail on other locales. It wasn't something that was being tested in dotnet/extensions.

[tarekgh]

sounds good then. thanks for confirming.

[ericstj]

Sure, I ran a quick sanity test and confirm the same escaping happened in 3.1.

[Gnbrkm41]

Still seeing the same issue on W10 Build 20211.

Looks like we concluded that the test data is the wrong part and the API itself is producing correct values. What do we want to do about this? perhaps we could set the current culture so that we have control of the output, or escape the result from DateTime.ToString before comparison?

[tarekgh]

perhaps we could set the current culture so that we have control of the output, or escape the result from DateTime.ToString before comparison?

I would prefer escaping the results before the comparison. This will make the test reliable to run on with any locale. Just in case if we set the current culture, then this will need to be done inside the RemoteExecutor but I am still preferring escaping the results.