Runtime: TraceSource: Will support load setting from App.config file?

[TingluoHuang]

The original System.Diagnostic.TraceSource support define tracesource/sourceswitch/tracelistener in app.config xml. Will that be support in the near future for dotnet core?

Thanks,
Ting

[ViktorHofer]

Maybe @brianrob @vancem @valenis can answer?

@karelz I think the Milestone should be set to Future.

[karelz]

We now have System.Configuration in 2.0, so we might do something here. The question is - how important is it for this API? (@brianrob @vancem any insight?)

@danmosemsft do you have general config usage guidance for CoreFX, esp. given the fact we now have System.Configuration?

[danmosemsft]

No I don't believe @JeremyKuhne wrote anything up on usage of S.Configuration. That would be a good idea at some future point, as the usage patterns are more limited than the desktop implementatioln.

[karelz]

Also technically, in .NET Core there is no app.exe.config (or machine.config), there can be only "main dll.config" (offline info from @danmosemsft).

[brianrob]

In general, we are not expanding support for TraceSource. However, if there is someone who is interested in contributing support for System.Configuration, I think that is OK. Either way, this can move to Future.

[MikeDempseyFL]

How can we turn on Network Tracing for the System.Net.Sockets.Socket class?
This was previously done using entries in app.config, with help from an entry in machine.config.
In DiagnosticsConfiguration I see it is still using ConfigurationManager.GetSection("system.diagnostics") but I can't figure out how to get the required information into the Configuration for it to use.
Are there any docs or examples available?
I would think network/socket tracing is something a lot of folks will need to do.

[davidsh]

In .NET Core, the network tracing is completely different. It is based on ETW. It is not turned on via a config file.

See:
https://github.com/dotnet/corefx/blob/master/Documentation/debugging/windows-instructions.md

[CalArabshahi]

To my knowledge ETW is a Windows only technology. Is there a way to turn on Network Tracing (i.e. Socket Tracing) on Linux and macOS? preferably using external configuration settings similar to
.NET Framework Network Tracing

[davidsh]

There is no "config file" mechanism in .NET Core.

On .NET Core, tracing is done with .NET EventSource. On Windows, this translates to Windows ETW. On Linux, it translates to something else.

@stephentoub can assist further with how to enable Linux tracing for networking.

[vancem]

On Linux EventSource data goes to Lttng. There is a script called 'PerfCollect' that wraps this

See
https://github.com/dotnet/coreclr/blob/master/Documentation/project-docs/linux-performance-tracing.md

For detailed instructions.

@brianrob

[MikeDempseyFL]

I tried adding *Microsoft-System-Net-Sockets as an additional EventSource when starting PerfView monitoring but I did not see any socket trace info in the resulting output files.

I also tried using logman start/stop with the associated GUID for Net-Sockets.
I tried this command both without keywords/level [i.e. the defaults] and with 0xFFFFFFFF 0x5, which I think would be 'All' and 'Debug'.
Again I was unable to find any socket tracing in the output.

When I ran 'logman query providers' it listed a couple hundred providers - but the list did not include Microsoft-System-Net-Sockets.

Are there additional steps we need to perform in order to turn on socket tracing?

[vancem]

@MikeDempseyFL I am assuming you are running on windows (since you are using PerfView and logman).

I just tried the following

PerfView /Providers=*Microsoft-System-Net-Sockets collect

Then I ran a .NET core scenario that used sockets. Then hit the 'Stop collect' button on PerfView and open the PerfViewData.etl file that resulted, and then looked at the 'Events view.

In this few I see the Microsoft-System-Net-Sockets events as shown below.

Event Name                                   Time MSec  Process Name    Rest  
Microsoft-System-Net-Sockets/ManifestData      393.395  dotnet (19932)  ThreadID="19,816" Format="1" MajorVersion="1" MinorVersion="0" Magic="91" TotalChunks="1" ChunkNumber="0" 
Microsoft-System-Net-Sockets/ManifestData    7,694.894  dotnet (22424)  ThreadID="19,340" Format="1" MajorVersion="1" MinorVersion="0" Magic="91" TotalChunks="1" ChunkNumber="0" 
Microsoft-System-Net-Sockets/Enter           7,695.025  dotnet (22424)  ThreadID="19,340" thisOrContextObject="Socket#33826822" memberName=".ctor" parameters="(InterNetwork)" 
Microsoft-System-Net-Sockets/Info            7,719.400  dotnet (22424)  ThreadID="19,340" thisOrContextObject="TaskSocketAsyncEventArgs`1#37095509" memberName="InitializeInternals" message="new PreAllocatedOverlapped PreAllocatedOverlapped#12479570" 
Microsoft-System-Net-Sockets/Info            7,719.572  dotnet (22424)  ThreadID="19,340" thisOrContextObject="Int32TaskSocketAsyncEventArgs#28016690" memberName="InitializeInternals" message="new PreAllocatedOverlapped PreAllocatedOverlapped#28672654" 
Microsoft-System-Net-Sockets/Info            7,737.602  dotnet (22424)  ThreadID="19,340" thisOrContextObject="(null)" memberName="CreateSocket" message="SafeCloseSocket:37200188(0x868)" 
Microsoft-System-Net-Sockets/Exit            7,737.618  dotnet (22424)  ThreadID="19,340" thisOrContextObject="Socket#33826822" memberName=".ctor" result="" 
Microsoft-System-Net-Sockets/Enter           7,737.847  dotnet (22424)  ThreadID="19,340" thisOrContextObject="Socket#33826822" memberName="Bind" parameters="(0.0.0.0:5000)" 
Microsoft-System-Net-Sockets/Info            7,737.852  dotnet (22424)  ThreadID="19,340" thisOrContextObject="Socket#33826822" memberName="Bind" message="localEP:0.0.0.0:5000" 
Microsoft-System-Net-Sockets/Exit            7,739.244  dotnet (22424)  ThreadID="19,340" thisOrContextObject="Socket#33826822" memberName="Bind" result="" 
Microsoft-System-Net-Sockets/Enter           7,739.538  dotnet (22424)  ThreadID="19,340" thisOrContextObject="Socket#33826822" memberName="Listen" parameters="(1000)" 
Microsoft-System-Net-Sockets/Info            7,739.541  dotnet (22424)  ThreadID="19,340" thisOrContextObject="Socket#33826822" memberName="Listen" message="backlog:1000" 
Microsoft-System-Net-Sockets/Exit            7,739.872  dotnet (22424)  ThreadID="19,340" thisOrContextObject="Socket#33826822" memberName="Listen" result="" 
Microsoft-System-Net-Sockets/Enter           7,739.914  dotnet (22424)  ThreadID="19,340" thisOrContextObject="Socket#33826822" memberName="Accept" parameters="" 
Microsoft-System-Net-Sockets/Info            7,740.929  dotnet (22424)  ThreadID="19,340" thisOrContextObject="Socket#33826822" memberName="Accept" message="SRC:0.0.0.0:5000" 
Microsoft-System-Net-Sockets/Info           20,139.465  dotnet (22424)  ThreadID="19,340" thisOrContextObject="(null)" memberName="CreateSocket" message="SafeCloseSocket:13840400(0x872)" 
Microsoft-System-Net-Sockets/Enter          20,139.527  dotnet (22424)  ThreadID="19,340" thisOrContextObject="Socket#45707473" memberName=".ctor" parameters="" 
Microsoft-System-Net-Sockets/Exit           20,139.530  dotnet (22424)  ThreadID="19,340" thisOrContextObject="Socket#45707473" memberName=".ctor" result="" 
Microsoft-System-Net-Sockets/Info           20,139.568  dotnet (22424)  ThreadID="19,340" thisOrContextObject="Socket#45707473" memberName="SetToConnected" message="now connected" 
Microsoft-System-Net-Sockets/Enter          20,139.644  dotnet (22424)  ThreadID="19,340" thisOrContextObject="Socket#45707473" memberName="InternalSetBlocking" parameters="desired:True willBlock:True willBlockInternal:True" 

This is what I would expect (the data being logged into the PerfVIewdata.etl and viable from the 'events' view.

Where does your experience diverge from this?

[MikeDempseyFL]

Sorry, it was user error.
There was a bug in my test that prevented it from making the network calls.

Now that I have fixed it I can see socket events including the 'DumpBuffer' events which is what I need to look at.
These events only show the first 16 bytes in the initial grid display - which makes it difficult to recognize the messages I'm interested in without opening each one individually (using context menu 'Dump Event'). It was much easier to simply scroll through the old [text] log files.
Is there any way to make it display something more like that?
(I tried exporting it but that still only exports the first 16 bytes.)

Also, the detail dialog only displays the first and last 256 bytes of the buffer. How do we tell it to collect/display the entire buffer - which can be quite large, but is sometimes necessary when researching 'boundary' conditions. This used to be done through the config file that is no longer used.

[vancem]

@MikeDempseyFL - You are describing limitations in the PerfView viewer. The actual data being dumped is complete, and it is the viewer that is truncating it as not to create a huge artifact. The viewer is really not designed for your use case (where you want to look at large buffers as raw bytes). This scenario really is a unusual corner case (normally loggers don't log large byte buffers anyway, and even if they did people would not probably want them).

The right 'answer' to your question should have been to dump data file as XML (so you can do whatever you want with it). There is a command that does this

PerfView UserCommand DumpEventsAsXml FILENAME 

but it happens to use the same pretty-printer as the viewer (which is arguably a bug). You can log an issue on this at https://github.com/Microsoft/perfview/issues if you wish and we can fix it reasonably quickly (a few days).

You can also fix it yourself by making a PerfView user command (See the 'Extending PerfView' entry in the 'Help' menu). See the 'DumpEventsAsXml' and 'Listen' user commands as templates.

You can also of course build PerfView yourself (pretty easy if you have VS2017 installed see https://github.com/Microsoft/perfview and hack the limits you care about (see PayloadString() and Dump() in TraceEvent.cs).

[MikeDempseyFL]

I don't see any events in which the payload is > 1080 bytes.
Since there is 56 bytes of other info in the payload that means a data buffer of 1024.
I also see "MaxDumpSize = 1024;" in the source code so everything seems to point to the fact that it only logs the first 1024 bytes of the data buffer to the event source.
So unless there is some way to override that it would not help for me to write my own listener.
Or am I missing something here?

[jemiller0]

Just my two cents, but, I think it is ridiculous to even include TraceSource if you aren't reading the settings from the configuration file. It is useless without support for that. If all you are going to do is port unusable code to .NET Core that does nothing more than make your app compile, I think you shouldn't waste your time. Or waste other people's time trying to get it to work and then finding that it is completely broken and unusable. Also, could you please implement a consistent mechanism for logging in .NET Core as a whole? Why is the network stack using it's own logging and ASP.NET has different logging? I would rather stick to using TraceSource, as Microsoft.Extensions.Logging is ridiculously overcomplicated given that it appears to expect you to be using dependency injection. Is it too much to ask to be able to do simple logging without fuss from something simple like a console application? IMHO, the ASP.NET people shouldn't be in charge of things like logging. I find it amazing simple things like this are not in .NET Core. How hard is it to make it read the config file?

[MikeDempseyFL]

The built in .NET Core logging for sockets is basically useless since that 1024 byte limit is built into the logging code without any way to override it. (It is defined as a constant) The issue is not just a PerfView issue.

In order to get around this we have added our own EventSource to our data provider and configure the buffer limit from a config file. This allows us to see the full contents of the message buffers when we need to. It does not however allow us to see how those messages are broken down into socket level messages - but hopefully that will never be required.

Anyone needing to log socket data will probably have to write their own EventSource unless this logging limit is changed to something that can be configured.

[jemiller0]

I think they should port over the same trace source logging that is in .NET Framework. It has been working fine for years. No need to implement a new solution that doesn't work.

[MikeDempseyFL]

Our event source is working fine on Windows but I am still unable to switch on the logging on Linux.
Our source is called Teradata-Data-Provider
I tried the following series of commands and it does create a set of log files but the log file is only 4K long and all except a few bytes at the start of the file is binary zeros.

lttng create teradata-trace
lttng add-context -u --type vpid
lttng add-context -u --type vtid
lttng add-context -u --type procname
lttng enable-event -u --tracepoint Teradata-Data-Provider:*
lttng start
--- run my test app here ---
lttng stop
lttng destroy

We tried the above both with/without the following:
export COMPlus_EnableEventLog=1
export COMPlus_PerfMapEnabled=1
export COMPlus_EventSourceFilter=Teradata-Data-Provider

If the Event source is called Teradata-Data-Provider is the following not correct?
lttng enable-event -u --tracepoint Teradata-Data-Provider:*

I also tried to switch on the .NET socket tracing using:
lttng enable-event -u --tracepoint Microsoft-System-Net-Sockets:*
but that produced no useful output either.

I checked the commands issued by perfcollect and this appears to be the correct form (although no use of '*' in there) and perfcollect does not enable Microsoft-System-Net-Sockets.

What is the correct command to switch on tracing for a specific EventSource?
(I'm using Ubuntu if that makes any difference.)

[brianrob]

@MikeDempseyFL the issue that you're hitting here is that LTTng doesn't know anything about specific EventSources because it does not currently allow for dynamic registration of tracepoint providers. Thus, all EventSource events are sent to a single LTTng tracepoint called DotNETRuntime:EventSource. When you enable this, you'll get all EventSource events - you can further filter this using COMPlus_EventSourceFilter and COMPlus_EventNameFilter, which are comma delimited lists to allow you to only enable the EventSources you care about. This is a workaround that we'd like to remove once LTTng supports dynamic creation of tracepoint providers.

Also, you should know that the EventPipe features in CoreCLR will eventually solve this problem as well. EventPipe is a cross-platform logging platform within CoreCLR that can consume and direct EventSources and native tracing within the runtime. Right now, it can write to a file, but you can imagine all sorts of other sinks, and some of these are already in the plans (e.g. EventListeners). Control for EventPipe is currently fairly limited (private APIs and COMPlus variables), but there is work post 2.1 to make this much more accessible.

[MikeDempseyFL]

Great Thanks. I now get the expected data in the log file.

The format of this file is completely different from the Windows etl files so neither PerfView nor my text converter app [which uses EventLogReader] recognizes it.

When I used perfcollect I noticed that it did a lot of post processing before it created the zip file. Is there a utility I can run to convert the output files to something that can be read by PerfView or the EventLogReader class?

[MikeDempseyFL]

Having looked more closely at the data I see a major problem.
The payload for one of our events includes a byte array. [the data buffer]
On Windows the event log correctly shows the data in that buffer, but on Linux it simply shows "System.Byte[]". Apparently it is simply using ToString() which will not work for arrays.

Are there any plans to handle arrays on Linux?
If not, my only option would seem to be to convert the byte array to a hex character string and pass that in the event payload. That would add a significant performance hit in the application since these buffers can be quite large and that work would occur on the application's thread.

Also, I don't see a timestamp on the events unless that is what the 4 byte value following the payload is.
(We removed the timestamps from our event payloads since they were available in the ETW records.)

[vancem]

@MikeDempseyFL First I want to confirm that you are using An EventSource and passing a byte array as one of the parameters. Showing the code you use is useful here.

The behavior on Linux does feel like a bug (after all it works differently on Linux and Window). But we should firm up exactly what the repro behavior is (presumably you are reading LTTng somehow. Repro instructions would help.

Finally this behavior is in EvenSource which is part of CoreCLR, and we should log the bug there (after all this bug is about TraceSource, so we should make a new bug anyway.

[jemiller0]

Please just fix TraceSource, it is unusable the way it is now.

[MikeDempseyFL]

I opened issue #27660 and added the requested information to that issue.

[brianrob]

Thanks @MikeDempseyFL.

[brianrob]

I'm going to close this issue since there is another one that also tracks the same thing, and there is a good amount of discussion on this issue around non-TraceSource functionality. If you're interested in following the TraceSource discussion, please follow dotnet/corefx#24829.

Duplicate of dotnet/corefx#24829

[augustoproiete]

Issue dotnet/corefx#24829 was moved to https://github.com/dotnet/runtime/issues/23937