This project has moved. For the latest updates, please go here.

Hello Logging

Let’s introduce some logging into our application, and we can see what it can do.

This examples shows manually configuring the app.config file, however the easiest way to add this, right now, to your existing project is using NuGet via "nuget System.Diagnostics.Config" or "nuget Essential.Diagnostics.Config".


Note that this code is intended to demonstrate logging and does not necessarily follow best practices in order to keep things simple (e.g. normally you would use properties instead of public fields). Also there is a lot of logging code because even though the example is short it tries to include many of the logging features.

HelloLogging.cs
using System;
using System.Collections.ObjectModel;
using System.Diagnostics;
using System.Threading;

// Program class
class Program {
  static TraceSource _trace = new TraceSource("HelloProgram");
  public static Random Random = new Random();
  public static Collection<Worker> Workers = new Collection<Worker>();

  public static void Main(string[] args) {
    // Trace start
    Trace.CorrelationManager.ActivityId = Guid.NewGuid();
    Trace.CorrelationManager.StartLogicalOperation("Main");
    _trace.TraceEvent(TraceEventType.Start, 1000, "Program start.");
    // Run program
    int numberOfWorkers = Program.Random.Next(2, 4);
    _trace.TraceEvent(TraceEventType.Information, 2000, "Creating {0} workers", numberOfWorkers);
    for(int i = 1; i <= numberOfWorkers; i++ ) {
      Worker worker = new Worker() { Id = string.Format("Worker {0}", i) };
      Workers.Add(worker);
    }
    StartWorkers();
    foreach(Worker worker in Workers) {
      worker.FinishedEvent.WaitOne();
    }
    // Trace stop
    _trace.TraceEvent(TraceEventType.Stop, 8000, "Program stop.");
    Trace.CorrelationManager.StopLogicalOperation();
    _trace.Flush();
  }

  static void StartWorkers() {
    // Trace transfer in
    Guid newActivity = Guid.NewGuid();
    _trace.TraceTransfer(6011, "Transferred to Start", newActivity);
    Guid oldActivity = Trace.CorrelationManager.ActivityId;
    Trace.CorrelationManager.ActivityId = newActivity;
    _trace.TraceEvent(TraceEventType.Start, 1010, "Starting workers.");
    // Do work
    foreach(Worker worker in Workers) {
      ThreadPool.QueueUserWorkItem(worker.Work);
    }
    // Trace transfer back
    _trace.TraceTransfer(6012, "Transferred back", oldActivity);
    _trace.TraceEvent(TraceEventType.Stop, 8010, "Finished starting.");
    Trace.CorrelationManager.ActivityId = oldActivity;
  }
}

// Worker class
class Worker {
  int _count;
  static TraceSource _trace = new TraceSource("HelloWorker");
  public AutoResetEvent FinishedEvent = new AutoResetEvent(false);
  public string Id;

  public void Poke() {
    // Trace - mark with logical operation
    Trace.CorrelationManager.StartLogicalOperation(string.Format("Poked:{0}", Id));
    _trace.TraceEvent(TraceEventType.Verbose, 0, "Worker {0} was poked", Id);
    // Work
    Thread.Sleep(Program.Random.Next(500));
    _count++;
    if( _count < 4 )
        Console.WriteLine("Hello World {1}", Id, _count);
    else if( _count < 6 ) {
        Console.WriteLine("Hi", Id);
        _trace.TraceEvent(TraceEventType.Warning, 4500, "Worker {0} getting annoyed", Id);
    } else {
        _trace.TraceEvent(TraceEventType.Error, 5500, "Worker {0} - too many pokes", Id);
    }
    // Trace - end logical operation
    Trace.CorrelationManager.StopLogicalOperation();
  }
  
  public void Work(object state) {
    // Trace transfer to thread
    Guid newActivity = Guid.NewGuid();
    _trace.TraceTransfer(6501, "Transfered to worker", newActivity);
    Trace.CorrelationManager.ActivityId = newActivity;
    Trace.CorrelationManager.StartLogicalOperation(string.Format("Worker:{0}", Id));
    _trace.TraceEvent(TraceEventType.Start, 1500, "Worker {0} start.", Id);
    // Do work
    int numberOfPokes = Program.Random.Next(3, 6);
    _trace.TraceEvent(TraceEventType.Information, 2500, "Worker {0} will poke {1} times", Id, numberOfPokes);
    for(int i = 1; i <= numberOfPokes; i++) {
      Thread.Sleep(Program.Random.Next(500));
      int index = Program.Random.Next(Program.Workers.Count);
      _trace.TraceEvent(TraceEventType.Verbose, 0, "Worker {0} poking {1}", Id, Program.Workers[index].Id);
      Program.Workers[index].Poke();
    }
    FinishedEvent.Set();
    // Trace stop (no transfer)
    _trace.TraceEvent(TraceEventType.Stop, 8500, "Worker stop.");
    Trace.CorrelationManager.StopLogicalOperation();
  }
}

For logging you also need a configuration file:

HelloLogging.exe.config
<?xml version="1.0" encoding="utf-8" ?>
<configuration>
  <system.diagnostics>
    <sharedListeners>
      <add name="console"
         type="System.Diagnostics.ConsoleTraceListener" />
    </sharedListeners>
    <sources>
      <source name="HelloProgram" switchValue="Information,ActivityTracing">
        <listeners>
          <clear />
          <add name="console" />
        </listeners>
      </source>
      <source name="HelloWorker" switchValue="All">
        <listeners>
          <clear />
          <add name="console" />
        </listeners>
      </source>
    </sources>
  </system.diagnostics>
</configuration>

Now, compile with “csc HelloLogging.cs /d:TRACE” – don’t forget the TRACE flag, or you won’t get any logging – and run.

With the basic console logger the information may not add much clarity, however the level of detail can be controlled by simply altering the configuration file without having to recompile.

 

Last edited Jun 5, 2013 at 12:40 PM by sgryphon, version 5

Comments

OrenSh Oct 9, 2012 at 12:56 PM 
thanks! this seems very useful.
While working with your program I find 2 very minor indexing issues (but potentially confusing):
1. "for(int i = 1; i < numberOfPokes; i++)" should be changed to "for(int i = 0; i < numberOfPokes; i++)" otherwise we miss one poke per worker.
2. "_trace.TraceEvent(TraceEventType.Verbose, 0, "Worker {0} poking {1}", Id, index);" should be changed to "_trace.TraceEvent(TraceEventType.Verbose, 0, "Worker {0} poking {1}", Id, index+1);"

Again, thank you for the great example. It really helped me understand the issue of transfer between activities and getting it to show correctly in the service trace viewer.

I wonder why there are so few examples for this. Seems like a very good way of generating and viewing traces.