How does System.TraceListener prepend message with process name?

Question

I have been looking at using System.Diagnostics.Trace for doing logging is a very basic app. Generally it does all I need it to do. The downside is that if I call

Trace.TraceInformation("Some info");

The output is "SomeApp.Exe Information: 0: Some info". Initally this entertained me but no longer. I would like to just output "Some info" to console. So I thought writing a cusom TraceListener, rather than using the inbuilt ConsoleTraceListener, would solve the problem. I can see a specific format that I want all the text after the second colon. Here is my attempt to see if this would work.

class LogTraceListener : TraceListener
{
    public override void Write(string message)
    {
        int firstColon = message.IndexOf(":");
        int secondColon = message.IndexOf(":", firstColon + 1);

        Console.Write(message);
    }

    public override void WriteLine(string message)
    {
        int firstColon = message.IndexOf(":");
        int secondColon = message.IndexOf(":", firstColon + 1);

        Console.WriteLine(message);
    }
}

If I output the value of firstColon it is always -1. If I put a break point the message is always just "Some info". Where does all the other information come from?

So I had a look at the call stack at the point just before Console.WriteLine was called. The method that called my WriteLine method is: System.dll!System.Diagnostics.TraceListener.TraceEvent(System.Diagnostics.TraceEventCache eventCache, string source, System.Diagnostics.TraceEventType eventType, int id, string message) + 0x33 bytes

When I use Reflector to look at this message it all seems pretty straight forward. I can't see any code that changes the value of the string after I have sent it to Console.WriteLine. The only method that could posibly change the underlying string value is a call to UnsafeNativeMethods.EventWriteString which has a parameter that is a pointer to the message.

Does anyone understand what is going on here and whether I can change the output to be just my message with out the additional fluff. It seems like evil magic that I can pass a string "Some info" to Console.WriteLine (or any other method for that matter) and the string that output is different.

EDIT: I found the magic. Obviously it wasn't magic. The Write method gets call from a call to WriteHeader before the call to WriteLine which is where I thought the magic was happening.

Sarsen

Answer 1

You can get this by overriding the TraceEvent() method in your listener. Like this:

    public override void TraceEvent(TraceEventCache eventCache, string source, TraceEventType eventType, int id, string message) {
        Console.WriteLine("{0}: {1}", id, message);
    }

Peck

Thanks this is very useful. It solves the issue of having different output from different listeners. However I still do not understand how the call to my override of WriteLine has a string passed to it. However if I pass this tring to another function it is somehow modified at a later point in time. – Sarsen

Not sure I follow, what's the real problem? The default implementation of TraceEvent formats the "source" and "id" arguments and calls your WriteLine() method. Note that there's another one. – Peck

I can see how my question was cleared. I have this the answer as it gave me an immediate work around to the problem I thought I was having then I realised it gave me the question I was really looking for, to which this is the answer. – Sarsen

Answer 2

You also need to override this TraceEvent overload if using formatting:

public override void TraceEvent(TraceEventCache eventCache, string source, TraceEventType eventType, 
                                int id, string format, params Object[] data)
{
  base.WriteLine(String.Format(format, data));
}

For example:

Trace.TraceInformation("Thread {0} Waiting", Thread.CurrentThread.ManagedThreadId);

Override will output output only "Thread 9 Waiting\n" when data[0] == 9

Cyruscyst

Answer 3

Why not use Trace.WriteLine("SomeInfo") instead of Trace.TraceInformation("SomeInfo") ?

Ever

I actually have multiple trace listners and the level is important for one of the listeners. I am mostly interested in how the string changes. – Sarsen