NLog prepends unspecified data to Trace target.

[loligans]

Type: Bug

NLog version: 4.4.0

Platform: .Net 4.6

Current NLog config (xml or C#, if relevant)

<?xml version="1.0" encoding="utf-8" ?>
<nlog xmlns="http://www.nlog-project.org/schemas/NLog.xsd"
      xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
      xsi:schemaLocation="http://www.nlog-project.org/schemas/NLog.xsd NLog.xsd"
      autoReload="true"
      throwExceptions="false"
      internalLogLevel="Trace" internalLogFile="c:\temp\nlog-internal.log">

  <variable name="VisualStudioTrace" value="TEST [${processtime}] ${message}"/>

  <targets>
    <target xsi:type="Trace"
            name="vstrace"
            layout="${VisualStudioTrace}"/>
  </targets>

  <rules>
    <logger name="*" levels="Trace,Debug,Info,Warn,Error" writeTo="vstrace" />
  </rules>
</nlog>

In case of a BUG:

• What is the current result?

TEST [00:00:00.069] Trace Log
TEST [00:00:00.089] Debug Log
ByteLogging.vshost.exe Information: 0 : TEST [00:00:00.089] Info Log
ByteLogging.vshost.exe Warning: 0 : TEST [00:00:00.100] Warning Log
ByteLogging.vshost.exe Error: 0 : TEST [00:00:00.130] Exception Log

• What is the expected result?

TEST [00:00:00.069] Trace Log
TEST [00:00:00.089] Debug Log
TEST [00:00:00.089] Info Log
TEST [00:00:00.100] Warning Log
TEST [00:00:00.130] Exception Log

• Did you checked the Internal log?
  Yes it appeared to be working correctly
• Please post full exception details (message, stacktrace, inner exceptions)
  This is not an exception but logs from the nlog-internal.log

2017-02-15 15:57:14.6361 Debug Setting 'TraceTarget.name' to 'vstrace'
2017-02-15 15:57:14.6361 Debug Setting 'TraceTarget.layout' to 'TEST [${processtime}] ${message}'
2017-02-15 15:57:14.7501 Trace   Scanning SimpleLayout ''TEST [${processtime}] ${message}''
2017-02-15 15:57:14.8082 Trace Initializing 'TEST [${processtime}] ${message}'
2017-02-15 15:57:14.8082 Trace Scanning SimpleLayout ''TEST [${processtime}] ${message}''

• Are there any work arrounds? yes/no
  not that I am aware of
• Is there a version in which it did worked?
  I haven't tried yet.
• Can you help us by writing an unit test?
  Not sure how to write a unit test, sorry.

in case of a FEATURE REQUEST:

• Why do we need it?
  A user should be allowed to configure the default log messages to how they would like them to appear.

[loligans]

After playing with Trace it appears the data being prepended in the issue above is caused from a call to

System.Diagnostics.Trace.TraceError()

Is there something that could be done to remove the prepended data?

[304NotModified]

so this is a feature of TraceError?

The current code is:

        protected override void Write(LogEventInfo logEvent)
        {
            if (logEvent.Level <= LogLevel.Debug)
            {
                Trace.WriteLine(this.Layout.Render(logEvent));
            }
            else if (logEvent.Level == LogLevel.Info)
            {
                Trace.TraceInformation(this.Layout.Render(logEvent));
            }
            else if (logEvent.Level == LogLevel.Warn)
            {
                Trace.TraceWarning(this.Layout.Render(logEvent));
            }
            else if (logEvent.Level == LogLevel.Error)
            {
                Trace.TraceError(this.Layout.Render(logEvent));
            }
            else if (logEvent.Level >= LogLevel.Fatal)
            {
                Trace.Fail(this.Layout.Render(logEvent));
            }
            else
            {
                Trace.WriteLine(this.Layout.Render(logEvent));                
            }
        }

It should be Trace.WriteLine all the time?

[304NotModified]

you could create your own trace target:

    [Target("Trace2")]
    public sealed class MyTraceTarget : TargetWithLayout
    {
        /// <summary>
        /// Initializes a new instance of the <see cref="TraceTarget" /> class.
        /// </summary>
        /// <remarks>
        /// The default value of the layout is: <code>${longdate}|${level:uppercase=true}|${logger}|${message}</code>
        /// </remarks>
        public TraceTarget() : base()
        {
        }

        /// <summary>
        /// Initializes a new instance of the <see cref="TraceTarget" /> class.
        /// </summary>
        /// <remarks>
        /// The default value of the layout is: <code>${longdate}|${level:uppercase=true}|${logger}|${message}</code>
        /// </remarks>
        /// <param name="name">Name of the target.</param>
        public TraceTarget(string name) : this()
        {
            this.Name = name;
        }

        /// <summary>
        /// Writes the specified logging event to the <see cref="System.Diagnostics.Trace"/> facility.
        /// If the log level is greater than or equal to <see cref="LogLevel.Error"/> it uses the
        /// <see cref="System.Diagnostics.Trace.Fail(string)"/> method, otherwise it uses
        /// <see cref="System.Diagnostics.Trace.Write(string)" /> method.
        /// </summary>
        /// <param name="logEvent">The logging event.</param>
        protected override void Write(LogEventInfo logEvent)
        {
                Trace.WriteLine(this.Layout.Render(logEvent));
        }
    }

...

Target.Register<MyTraceTarget >("trace2");

[loligans]

Yes this is a feature of Trace unfortunately. Thank you for the example! I think that is what I will have to do.

[304NotModified]

another option is to add an option to the TraceTarget: UseAlwaysWriteLine

PR accepted ;)