Each trace record includes an extra message: <program name> <trace level> #

ATECoder commented 3 years ago

Serilog Sinks Trace works like a charm but seems to added an extra record before each log message. Is there a way to control this behavior?

To demonstrate, I am showing below the Console log messages (each tagged with a c::) and the Trace messages (each tagged with a t::). The trace messages where stored in a queue, which is dumped for testing purposes.

Here is the Console trace messages: ` c::20:46:08.731 -08:00, [INF], (isr.Core.Logging.Tester.Program), Starting application...

c::20:46:08.759 -08:00, [INF], (isr.Core.Logging.Tester.App), Running application.

c::20:46:08.803 -08:00, [INF], (isr.Core.Logging.Tester.App), Logging into C:\My\Libraries\VS\Core\Core5\src\Testers\Logging\bin\Debug_Logs\lime_20210210.log.

c::20:46:08.810 -08:00, [DBG], (isr.Core.Logging.Tester.TestService), Running logging service.

c::20:46:08.817 -08:00, [DBG], (isr.Core.Logging.Tester.TestService), Throwing divide by zero exception.

c::20:46:08.835 -08:00, [ERR], (isr.Core.Logging.Tester.App), reporting exception

System.InvalidOperationException: Caught in App

---> System.DivideByZeroException: Attempted to divide by zero.

at isr.Core.Logging.Tester.TestService.Run() in C:\My\Libraries\VS\Core\Core5\src\Testers\Logging\Program\Program.cs:line 309

at isr.Core.Logging.Tester.App.Run() in C:\My\Libraries\VS\Core\Core5\src\Testers\Logging\Program\Program.cs:line 249

--- End of inner exception stack trace ---
`

And here are the trace messages where each line is preceded by the name of the program (LoggingTester) , the trace level (e.g., information) and a zero.

` --- Queue Trace Listener Records after flush:

LoggingTester Information: 0 :

t::20:40:22.955 -08:00, [INF], (isr.Core.Logging.Tester.Program), Starting application...

LoggingTester Information: 0 :

t::20:40:22.979 -08:00, [INF], (isr.Core.Logging.Tester.App), Running application.

LoggingTester Information: 0 :

t::20:40:23.024 -08:00, [INF], (isr.Core.Logging.Tester.App), Logging into C:\My\Libraries\VS\Core\Core5\src\Testers\Logging\bin\Debug_Logs\lime_20210210.log.

t::20:40:23.031 -08:00, [DBG], (isr.Core.Logging.Tester.TestService), Running logging service.

t::20:40:23.035 -08:00, [DBG], (isr.Core.Logging.Tester.TestService), Throwing divide by zero exception.

LoggingTester Error: 0 :

t::20:40:23.052 -08:00, [ERR], (isr.Core.Logging.Tester.App), reporting exception

System.InvalidOperationException: Caught in App

---> System.DivideByZeroException: Attempted to divide by zero.

at isr.Core.Logging.Tester.TestService.Run() in C:\My\Libraries\VS\Core\Core5\src\Testers\Logging\Program\Program.cs:line 309

at isr.Core.Logging.Tester.App.Run() in C:\My\Libraries\VS\Core\Core5\src\Testers\Logging\Program\Program.cs:line 249

--- End of inner exception stack trace ---

--- End of Queue Trace Listener Records
`

Numpsy commented 3 years ago

Is this related to what #7 and #15 were discussing?

ATECoder commented 3 years ago

It seems that these issues are related. Indeed, when issuing a trace message in a unit test, the trace message is prefixed with the 'source name' and trace level.

Replacing Trace.Information with Trace.Write will brake the trace listeners ability to filter the trace, which is critical to this framework design.

So it seems we'll have to live with this added message.

As a side, I noticed that each Debug sink message leaks into the Trace. Is that also a Microsoft doing?

Finally, thank you for the devotion and great work on these projects. It is very much appreciated. I was able to build a nice framework around it and everything that I thought of adding worked as expected. Looking at the source code was a learning experience. Kudos to you and your colleagues!

From: Richard Webb notifications@github.com Sent: Saturday, February 13, 2021 7:18:24 AM To: serilog/serilog-sinks-trace serilog-sinks-trace@noreply.github.com Cc: David Hary david.hary@outlook.com; Author author@noreply.github.com Subject: Re: [serilog/serilog-sinks-trace] Each trace record includes an extra message: # (#20)

— You are receiving this because you authored the thread. Reply to this email directly, view it on GitHubhttps://na01.safelinks.protection.outlook.com/?url=https%3A%2F%2Fgithub.com%2Fserilog%2Fserilog-sinks-trace%2Fissues%2F20%23issuecomment-778632872&data=04%7C01%7C%7C4ca12692ac654dee11b908d8d0329b91%7C84df9e7fe9f640afb435aaaaaaaaaaaa%7C1%7C0%7C637488263062932916%7CUnknown%7CTWFpbGZsb3d8eyJWIjoiMC4wLjAwMDAiLCJQIjoiV2luMzIiLCJBTiI6Ik1haWwiLCJXVCI6Mn0%3D%7C1000&sdata=r4tjvS4tNmCuTeq2TtrqA2aW%2FiPxYHoru1cKpPZgjBM%3D&reserved=0, or unsubscribehttps://na01.safelinks.protection.outlook.com/?url=https%3A%2F%2Fgithub.com%2Fnotifications%2Funsubscribe-auth%2FAAGBGSQK3KHVI5SEV2AWBXLS62J4BANCNFSM4XOGE3UA&data=04%7C01%7C%7C4ca12692ac654dee11b908d8d0329b91%7C84df9e7fe9f640afb435aaaaaaaaaaaa%7C1%7C0%7C637488263062942906%7CUnknown%7CTWFpbGZsb3d8eyJWIjoiMC4wLjAwMDAiLCJQIjoiV2luMzIiLCJBTiI6Ik1haWwiLCJXVCI6Mn0%3D%7C1000&sdata=BUut14G4wGwpOeW9nUKeSa4TsKgFMbOmNf7xQmSogX8%3D&reserved=0.

Numpsy commented 3 years ago

As a side, I noticed that each Debug sink message leaks into the Trace. Is that also a Microsoft doing?

There is some overlap between the two (on .NET at least, I can't recall offhand if .NETCore is the same) - the Microsoft documentation at https://docs.microsoft.com/en-us/dotnet/api/system.diagnostics.debug.listeners?view=netframework-4.8#remarks states that the Trace and Debug classes share a single listeners collection, so adding a listener to one also adds it to the other.

ATECoder commented 3 years ago

Per the TraceSource.TraceEvent method documentation, an override of the TraceSource.TraceEvent method could construct the message w/o the default output prefix:

"The trace content is listener specific. If the method is not overridden by the listener implementation, the default output is the name of the trace source, its numeric identity, and the event type. Additional trace content is dependent upon the listener's TraceOutputOptions property value." https://docs.microsoft.com/en-us/dotnet/api/system.diagnostics.tracesource.traceevent?view=net-5.0

However, looking at the code of the trace listener (https://referencesource.microsoft.com/#System/compmod/system/diagnostics/TraceListener.cs,8b8ba5341c6d1740), a header is emitted by the trace listener: ` [ComVisible(false)] public virtual void TraceEvent(TraceEventCache eventCache, String source, TraceEventType eventType, int id, string format, params object[] args) { if (Filter != null && !Filter.ShouldTrace(eventCache, source, eventType, id, format, args)) return;

        WriteHeader(source, eventType, id);
        if (args != null)
            WriteLine(String.Format(CultureInfo.InvariantCulture, format, args));
        else
            WriteLine(format);

        WriteFooter(eventCache);
    }

    private void WriteHeader(String source, TraceEventType eventType, int id) {
        Write(String.Format(CultureInfo.InvariantCulture, "{0} {1}: {2} : ", source, eventType.ToString(), id.ToString(CultureInfo.InvariantCulture)));
    }

`

serilog / serilog-sinks-trace

Each trace record includes an extra message: <program name> <trace level> # #20