Instrumentation and tracing – Goshoom.NET Dev Blog

Regardless of how hard we try to write flawless software, sooner or later something goes wrong and we must identify where exactly the problem lies (to be able to fix it). One option is using the debugger, but it’s not always possible – we can’t reproduce the problem, for example. Another way is inserting some trace messages into code (= instrumenting the code) and logging them somewhere – it can reveal what code was called, values of certain variables, identity of a user executing some method and so on.

There are quite a few things you may want to do with such trace messages – filter them by priority or origin, save them to various destinations (e.g. text/XML/EventLog), activate/deactivate tracing without rebuilding your application and so on.

The good news is that .NET already contains such a framework and we can use it.

TraceSource in .NET (4.0)

Instead of jumping into details, let’s look at a rather simple example. If you find it interesting, you can learn more in Tracing and Instrumenting Applications.

We’ll need two main components:

A trace source. We’ll pass information about interesting events to the source, but the source itself doesn’t know how (or whether) messages will be logged.
Trace listeners. Listeners get information from a trace source and log them somewhere.

In your source code, you simply create a named TraceSource instance and use one of its methods to record an event:

System.Diagnostics.TraceSource ts = new System.Diagnostics.TraceSource("Goshoom.DemoApplication");
ts.TraceInformation("Started");

Because we don’t want to create a new TraceSource every time, it’s typically stored in a static field.

Even if we write something into a trace source, nothing is going to happen unless there is a listener. Listeners can be registered in code as well, but the usual approach is using configuration files, because it’s much more flexible. Check out the following fragment of a configuration file:

<system.diagnostics>
  <sources>
    <source name="Goshoom.DemoApplication" switchValue="Information">
      <listeners>
        <add name="TextFile" 
             type="System.Diagnostics.TextWriterTraceListener" 
             initializeData="DemoApplication.log" />
      </listeners>
    </source>
  </sources>
</system.diagnostics>

We identify the trace source by its name (that’s the value we passed to TraceSource’s constructor) and set a switch saying that we’re interested in messages of severity “Information” and higher. It gives you great flexibility – you can, say, log only errors in production environments and switch to more details only when needed and only for the trace source related to the failing component.

Then we add one listener which writes messages received from the trace source to a text file. You can have several listeners for a single source, listeners shared between sources etc. See Trace Listeners on MSDN to learn a bit more about various types of listeners.

Dynamics AX 2012

If you create .NET libraries to be used by AX as part of an AX process itself, the approach is exactly the same – you’ll create and use a trace source in your library and configure listeners in Ax32.exe.config (if the library is used by AX client) or Ax32Serv.exe.config (for AOS). Naturally, you can also listen to events recorded by existing libraries, such as WCF. (It sometimes helps me a lot, just note that you can’t configure diagnostics in endpoint configuration, you have to do that in AOS configuration).

Furthermore, you can use exactly the same approach in X++ via .NET Interop – our example mentioned before as C# is also valid X++ code:

System.Diagnostics.TraceSource ts = new System.Diagnostics.TraceSource("Goshoom.DemoApplication");
ts.TraceInformation("Started");

If X++ code doesn’t run in CIL, there is a performance penalty when invoking calls via .NET Interop. It’s nothing you have to care about if you do few calls, but it may cause troubles if it’s used in huge loops, for instance.

Infolog

Infolog messages created in AX are also automatically passed to a trace source and you can use usual techniques to log them. If you look at the MSDN article about propagating infolog messages to Event Log, you will recognize the pattern described before:

<configuration>
  <system.diagnostics>
    <trace autoflush="true"/>
    <sources>
      <source name="Microsoft.Dynamics.Kernel.Client.DiagnosticLog-Infolog"
              switchValue="Information">
        <listeners>
          <add name="EventLog" 
               type="System.Diagnostics.EventLogTraceListener" 
               initializeData="Dynamics Infolog"/>
          <add name="TextFile" 
               type="System.Diagnostics.TextWriterTraceListener" 
               initializeData="DynamicsInfologTrace.log" 
               traceOutputOptions="DateTime"/>
        </listeners>
      </source>
    </sources>
  </system.diagnostics>
</configuration>

We have two listeners there (writing messages to Event Log and to a text file) for messages received from Microsoft.Dynamics.Kernel.Client.DiagnosticLog-Infolog trace source.

Let’s try another type of listener – XmlWriterTraceListener:

<add initializeData="infolog.svclog" type="System.Diagnostics.XmlWriterTraceListener"
    name="xmlListener" traceOutputOptions="DateTime, Callstack" />

You can open such files in any text or XML editor, but there is one more option – Service Trace Viewer. I intentionally used .svclog extension instead of .xml, because .svclog files are associated with Service Trace Viewer. If you don’t have it installed, you can get it as part of Windows SDK. See how it looks like:

It has a lot of great features regarding visualization, filtering, opening several trace files in the same time (e.g. client and AOS or multiple AOSes) and so on. You may not appreciate that too much when working with infolog messages, but it’s extremely useful when things start to be a bit more complicated.

I selected Callstack as one of output options – let’s look at what we get from AX:

at System.Environment.GetStackTrace(Exception e, Boolean needFileInfo)
at System.Environment.get_StackTrace()
at System.Diagnostics.TraceEventCache.get_Callstack()
at System.Diagnostics.XmlWriterTraceListener.WriteFooter(TraceEventCache eventCache)
at System.Diagnostics.XmlWriterTraceListener.TraceEvent(TraceEventCache eventCache, String source, TraceEventType eventType, Int32 id, String message)
at System.Diagnostics.TraceSource.TraceEvent(TraceEventType eventType, Int32 id, String message)
at Microsoft.Dynamics.Kernel.Client.DiagnosticLog.AddInfologMessage(TraceEventType eventType, Int32 errorType, String message)
at Microsoft.Dynamics.Kernel.Client.DiagnosticLogWrapper.AddInfologMessage(DiagnosticLogWrapper* , Int32 errorType, Char* message)
at System.Windows.Forms.UnsafeNativeMethods.CallWindowProc(IntPtr wndProc, IntPtr hWnd, Int32 msg, IntPtr wParam, IntPtr lParam)
at System.Windows.Forms.NativeWindow.DefWndProc(Message& m)
at Microsoft.Dynamics.Kernel.Client.NativeWindowWithEvents.WndProc(Message& m)
at System.Windows.Forms.NativeWindow.Callback(IntPtr hWnd, Int32 msg, IntPtr wparam, IntPtr lparam)
at _wWinMainCRTStartup()

If you expected an X++ call stack, this must be a huge disappointment. All what we get is a sequence of .NET architecture calls that as some point call X++ (CallWindowProc()). Although it makes a good sense, it renders the log much less useful than it usually would be. Normally we want to know where exactly an event occured.

We can’t change the call stack generated by .NET – it’s even correct, it’s just not what we want. But we can make a workaround – we can create an additional trace message containing the X++ call stack. We’ll make following changes to the Info class:

classDeclaration
{
    System.Diagnostics.TraceSource ts;
    …
}
 
new
{
    …    
    super();
    ts = new System.Diagnostics.TraceSource("Microsoft.Dynamics.Kernel.Client.DiagnosticLog-Infolog");
    …
}
 
private void addTraceCallstack(str _txt)
{
    str msg = _txt + " - Callstack";
    container c = xSession::xppCallStack();
    str path;
    int i;
    boolean found;
    #AOT
 
    for (i = 1; i <= conLen(c); i += 2)
    {
        path = conPeek(c, i);
        path = substr(path, strfind(path,'\\',1,strlen(path)), strlen(path));
 
        if (found)
        {
            msg += strFmt("\n%1 [%2]", conPeek(c, i), conPeek(c, i+1));
        }
        else
        {
            if (path == #ClassesPath+'\\'+classstr(Global)+'\\'+staticmethodstr(Global, info) ||
                path == #ClassesPath+'\\'+classstr(Global)+'\\'+staticmethodstr(Global, error)||
                path == #ClassesPath+'\\'+classstr(Global)+'\\'+staticmethodstr(Global, warning) ||
                path == #ClassesPath+'\\'+classstr(Global)+'\\'+staticmethodstr(Global, checkFailed))
            {
                found = true;
            }
        }
    }
 
    ts.TraceEvent(System.Diagnostics.TraceEventType::Verbose, 0, msg);
}
 
Exception add(…)
{
    Exception ex;
    …
    //return super(_exception, (buildprefix?getprefix():'')+_txt);
    ex = super(_exception, (buildprefix?getprefix():'')+_txt);
    this.addTraceCallstack(_txt);
    return ex;
}

We’ve created a new TraceSource instance with the same name as used for standard infologs, which is completely valid. In addTraceCallstack(), we get X++ callstack, drop calls related to infolog handling, format the message and log it as a trace event of type Verbose. This method is triggered by add(), after processing the infolog message itself.

Any infolog message logged through the tracing infrastructure will be followed by another massage with X++ call stack.

Infolog - Callstack You’ll have to set switchValue in configuration file to Verbose. You could also log the call stack with the same severity as the original message – it’s all up to you.

If you don’t have enough, you can also check some new features for tracing in .NET 4.5.