How to setup a non global NLog custom layout renderer not bound to a specific thread?

Question

I have a job engine, which runs several jobs in parallel. The jobs may be multithreaded themselves.

There is a job specific information I would like to expose via custom layout renderers. The solutions I have seen so far suggest using either of GDC, NDC or MDC facilities. For example - http://nlog-forum.1685105.n2.nabble.com/Custom-Layout-Renderers-Runtime-Values-td4065731.html

This approach is not good, because the information I want to expose is per job, which is neither global nor thread local. A job execution may involve different threads, from the thread pool and/or explicitly created.

I want to make as less as possible changes to the existing job code. For instance, I understand I might need to change how the log instances are obtained or life scoped (instance vs static), but I certainly do not want to change the log messages.

Any ideas?

Answer 1

If you are willing to use the Logger's Log method, then you can create a LogEventInfo and store your extra job-specific values in the LogEventInfo's Properties (similar to GDC and MDC, except that each LogEventInfo has its own instance).

So, your code might look something like this:

void RunJob(object job)
{
  string name;
  int id;
  DateTime started;

  GetSomeParametersFromJob(job, out name, out id, out started);

  var le = new LogEventInfo(LogLevel.Info, logger.Name, "Hello from RunJob");
  le.Properties.Add("JobName", name);
  le.Properties.Add("JobId", id);
  le.Properties.Add("JobStarted", started);

  logger.Log(le);
}

The logging call could be cleaned up some that it is less verbose, but you get the idea. Simply add your desired parameters to the Properties dictionary on the LogEventInfo class, then you can log those values out using the EventContext layout renderer. You would configure it something like this:

<targets>
    <target name="file" xsi:type="File" layout="${longdate} | ${level} | ${logger} | JobName = ${event-context:JobName} | JobId = ${event-context:JobId} | JobStarted = ${event-context:JobStarted} | ${message}" fileName="${basedir}/${shortdate}.log" />
</targets>

You could clean up the configuration by using "variables":

<variable name="JobName" value = "${event-context:JobName}" />
<variable name="JobId" value = "${event-context:JobId}" />
<variable name="JobStarted" value = "${event-context:JobStarted}" />
<variable name="JobLayout" value="${longdate} | ${level} | ${logger} | ${JobName} | ${JobId} | ${JobStarted} | $ ${message}"/>

<targets>
  <target name="file" 
          xsi:type="File" 
          layout="${JobLayout}" 
          fileName="${basedir}/${shortdate}.log" />
</targets>

UPDATE

Here is another idea... You could write your own "context" object (similar to GDC and MDC) that is keyed by something that would identify your job. You might want to use the CallContext to hold your extra parameters, as it is possible to put values into the CallContext such that they will be "flowed" to child threads. Then again, if you are putting the values in the context from the job runner, you don't want them flowed to all child threads, you only want them flowed to the job that is being run. So, maybe to start they could be put into global data, but that might lead to a bottleneck... At any rate... How might this work?

This is all pretty rough, but I think it conveys the idea. Whether or not it is a good idea? I'll let you be the judge. On the plus side, your logging sites are unchanged, you can set the "context" parameters without much more effort than it would have taken if you had used GDC/MDC. On the minus side, there is some code to write, there could be a bottleneck in accessing the global dictionary.

Create your own global dictionary (similar to NLog's GlobalDiagnosticContext here https://github.com/NLog/NLog/blob/master/src/NLog/GlobalDiagnosticsContext.cs). Make the Add API have an extra parameter of type GUID. So, your parameter storing code before starting a job might look like this:

string name;
int id;
DateTime started;

GetSomeParametersFromJob(job, out name, out id, out started);

GUID jobActivity = Guid.NewGuid();
JobRunnerNamespace.JobContext.Add(jobActivity, "JobName", name);
JobRunnerNamespace.JobCotnext.Add(jobActivity, "JobId", id);
JobRunnerNamespace.JobContext.Add(jobActivity, "JobStarted", started);

job.Activity = jobActivity;

job.Run();

Inside the job, when it starts, it sets System.Diagnostics.CorrelationManager.ActivityId to the input guid:

public class MyJob
{
  private Guid activityId;

  public Guid
  {
    set 
    {
      activityId = value;
    }
    get
    {
      return activityId;
    }
  }

  public void Run()
  {
    System.Diagnostics.CorrelationManager.ActivityId = activityId;

    //Do whatever the job does.

    logger.Info("Hello from Job.Run.  Hopefully the extra context parameters will get logged!");
  }
}

The JobContextLayoutRenderer would look something like this:

[LayoutRenderer("JobContext")]
public class JobContextLayoutRenderer : LayoutRenderer
{
    [RequiredParameter]
    [DefaultParameter]
    public string Item { get; set; }

    protected override void Append(StringBuilder builder, LogEventInfo logEvent)
    {
        Guid activity = System.Diagnostics.CorrelationManager.ActivityId;

        string msg = JobContext.Get(activity, this.Item);
        builder.Append(msg);
    }
}

JobContext would look something like this (let's just consider Set and Get for now):

public static class JobContext
{
    private static Dictionary<Guid, Dictionary<string, string>> dict = new Dictionary<Guid, Dictionary<string, string>>();

    public static void Set(Guid activity, string item, string value)
    {
        lock (dict)
        {
            if (!dict.ContainsKey(activity))
            {
              dict[activity] = new Dictionary<string, string>();
            }
            var d = dict[activity];
            lock (d) //Might need to lock this dictionary
            {
              d[activity][item] = value;
            }
        }
    }

    /// <summary>
    /// Gets the Global Diagnostics Context named item.
    /// </summary>
    /// <param name="item">Item name.</param>
    /// <returns>The item value of string.Empty if the value is not present.</returns>
    public static string Get(Guid activity, string item)
    {
        lock (dict)
        {
            string s = string.Empty;

            var d = dict.TryGetValue(activity, d);
            if (d != null)
            {
              lock(d) //Might need to lock this dictionary as well
              {
                if (!d.TryGetValue(item, out s))
                {
                  s = string.Empty;
                }
              }
            }

            return s;
        }
    }
}