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

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