Diagnostics: dotnet trace does not properly pass filter data to application

[davidfowl]

I was trying to use dotnet-trace to collect Microsoft.Extensions.Logging logs but there's an issue with configuring multiple logger providers and it seems like dotnet trace or trace event isn't sending the correct filter data to the application.

This is the command I ran:

dotnet trace collect -p {pid}--providers Microsoft-Extensions-Logging:C:5:FilterSpecs="Microsoft.AspNetCore.Hosting;Microsoft.AspNetCore.Routing"

Debugging dotnet-trace showed me the provider was being properly parsed:

But debugging the application showed that the FilterSpec property was being truncated:

[sywhang]

This might turn out to be a runtime bug. Taking a look now.

cc @josalem

[josalem]

Taking a quick look at it, I think this is expected behavior. The provider is specified with quotes, but I don’t believe they are being passed along to the runtime correctly due to parsing at the command line. Try changing the quoting to the following:

... —providers ‘::FilterSpecs=“myfilter;myotherfilter”’

Depending on what terminal you’re using, you may need to escape the double quotes as well. Due to a limitation in the v1 version of the IPC protocol, filter string values with ‘=‘ or ‘;‘ characters in them must be surrounded by double quotes when they’re sent to the runtime. I believe what’s happening here is that the filter string isn’t showing up on the runtime side with double quotes around the value of “FilterSpecs” so it is truncating at the semicolon. I’ll take a closer look on Monday when I’m back at my computer.

---

From: Sung Yoon Whang [e-mail]
Sent: Sunday, October 6, 2019 12:57:31 AM
To: dotnet/diagnostics [e-mail]
Cc: John Salem [e-mail]; Mention [e-mail]
Subject: Re: [dotnet/diagnostics] dotnet trace does not properly pass filter data to application (#539)

This might turn out to be a runtime bug. Taking a look now.

cc @josalemhttps://nam06.safelinks.protection.outlook.com/?url=https%3A%2F%2Fgithub.com%2Fjosalem&data=02%7C01%7Cjosalem%40microsoft.com%7Cc5d7ece3ae0f4efdc3b408d74a32d771%7C72f988bf86f141af91ab2d7cd011db47%7C1%7C0%7C637059454530432201&sdata=RRFczYHD0WDgKsiBYtmRz98dO2q%2F8qcO17DpA8l5AfM%3D&reserved=0

—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHubhttps://nam06.safelinks.protection.outlook.com/?url=https%3A%2F%2Fgithub.com%2Fdotnet%2Fdiagnostics%2Fissues%2F539%3Femail_source%3Dnotifications%26email_token%3DAE5VXHIELEPR5IRFWMT7G53QNGK6XA5CNFSM4I523BE2YY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOEAODYNY%23issuecomment-538721335&data=02%7C01%7Cjosalem%40microsoft.com%7Cc5d7ece3ae0f4efdc3b408d74a32d771%7C72f988bf86f141af91ab2d7cd011db47%7C1%7C0%7C637059454530432201&sdata=V9j4GsQBq90QiRynGvD4u6DHSngGaQsm76ERxGBKae0%3D&reserved=0, or mute the threadhttps://nam06.safelinks.protection.outlook.com/?url=https%3A%2F%2Fgithub.com%2Fnotifications%2Funsubscribe-auth%2FAE5VXHJFUBFMAVIMU6Z7KHTQNGK6XANCNFSM4I523BEQ&data=02%7C01%7Cjosalem%40microsoft.com%7Cc5d7ece3ae0f4efdc3b408d74a32d771%7C72f988bf86f141af91ab2d7cd011db47%7C1%7C0%7C637059454530442194&sdata=0GwglZYBIMf9tSbg7P0lsxY1t32NYOCZLyTH5b0jWns%3D&reserved=0.

[davidfowl]

adding single quotes seems to make it work:

dotnet trace collect -p {pid} --providers Microsoft-Extensions-Logging:C:2:'FilterSpecs="Microsoft.AspNetCore.Hosting;System.Net"'

[josalem]

I'm going to close this issue as expected behavior, but I'll reference it in a new issue over in dotnet/coreclr for updating the IPC protocol to treat filter string key-value pairs as first class parameters.

[davidfowl]

I'm going to close this issue as expected behavior, but I'll reference it in a new issue over in dotnet/coreclr for updating the IPC protocol to treat filter string key-value pairs as first class parameters.

I mean, sure but who is going to figure this out?

[josalem]

Currently, it is documented in the help text for dotnet-trace as part of using filters on providers: https://github.com/dotnet/diagnostics/blob/master/documentation/dotnet-trace-instructions.md. It is definitely not ideal, but that is a limitation until a change to the protocol is made, which won't happen until 5. Once there is an updated version of the protocol that correctly handles filter strings as a bag of key-value pairs rather than a single string, we can remove the limitation. If that isn't sufficient, steps could be taken to document this limitation more loudly.

It does look like the help documentation differs from the help text the tool outputs, though, so that should be updated to show the correct usage: https://github.com/dotnet/diagnostics/blob/f92d9203692e86b7e67ec813cefa66c4555a2516/src/Tools/dotnet-trace/CommandLine/Commands/CollectCommand.cs#L307

[davidfowl]

It does look like the help documentation differs from the help text the tool outputs, though, so that should be updated to show the correct usage:

Lets fix that doc altogether. It took me a 5 minutes to figure the syntax out. I thought those square brackets were required at first. Also the nesting looks weird.

Lastly, an example of what it actually looks like would have saved me so much time.

[josalem]

Writing up a PR now 😄. What would you expect the syntax to be in the help text for this? I'm used to seeing [] as denoting "optional" in cli tools and <> as denoting required. I'll certainly put an example in the tool's help text.

[davidfowl]

Turns out I didn't actually get this working, or at least, I can't replicate it. I can't get the FilterSpecs to have more than a single setting from the command line.