Debugging Stack overflow errors on background services

Question

This is not really a question, but an answer which would hopefully help other people.

Those who've written a windows service before, know what a mission it could be to find a bug in it, particularly if it only happens on the live environment. In my case, I had a service that ran smoothly for a couple of hours, and then fell over from a stack overflow error. No stack trace. Good luck finding the needle in the haystack.

The service did produce a log file, and the code was littered with log entries, but as detailed as is was, it produced log files of 500 MB! You could barely open the file, never mind analyse it. But how do you get around this problem? You could try to produce log files with less information, or one that automatically delete older logs entries as newer ones are being written, but then you loose important context of the error.

The solution is a log file that will keep track of loops in your code, and automatically delete the log entries for each successful iteration of that loop. This way, you can maintain a highly detained log file which remains relatively small at the same time. When your service breaks, your log file will tell you exactly where it happened, plus all the necessary context to explain how and why it happened.

You can download this logfile generator from http://sourceforge.net/projects/smartl/files/?source=navbar. It's a stand alone class and all its methods is static. An example class is provided to show you how to use the logging methods correctly:

    public void ExampleMethod()
    {           
        SmartLog.EnterMethod("ExampleMethod()"); 
        try
        {
            SmartLog.Write("Some code happening before the loop");

            Guid exampleLoopID = SmartLog.RegisterLoop("exampleLoopID");
            for (int i = 0; i < 10; i++)
            {
                SmartLog.IncrementLoop(exampleLoopID);

                SmartLog.Write("Some code happening inside the loop.");

            }
            SmartLog.CompleteLoop(exampleLoopID);

            SmartLog.Write("Some code happening after the loop.");

            SmartLog.LeaveMethod("ExampleMethod()");
        }
        catch (Exception ex)
        {
            SmartLog.WriteException(ex);
            SmartLog.LeaveMethod("ExampleMethod()");
            throw;
        }
    }

Make sure your application has read and write access on its root folder.

If you execute the code, and you break it inside the loop, the logfile will look something like this:

. ENTER METHOD: FirstMethod()
some code happening here.
Calling a different method:

. . ENTER METHOD: ExampleMethod()
some code happening before the loop.

LOOP: doWorkLoopID [4135a8ed-05b7-45de-b887-b2ab3c638faa] - CURRENT ITERATION: 20
some code happening inside the loop.

Once the loop has been completed, its content is removed, and your log file will look like this:

. ENTER METHOD: FirstMethod()
some code happening here.
Calling a different method:

. . ENTER METHOD: ExampleMethod()
some code happening before the loop.

LOOP: doWorkLoopID [4135a8ed-05b7-45de-b887-b2ab3c638faa] - TOTAL ITERATIONS: 22

some code happening after the loop.
. . LEAVING METHOD: ExampleMethod()

some code happening here.
some code happening here.
. LEAVING METHOD: FirstMethod()

I hope this can help someone solve that problem which otherwise could've taken weeks. It sure did the trick for me.

Answer 1

Here is my static logger solution. Useful for ALL projects not only services:

Application start with:

MyLog.Reset();

Yhen every static or nonstatic method starts with:

System.Diagnostics.StackTrace stackTrace = new System.Diagnostics.StackTrace(); MyLog.Log("", stackTrace.GetFrame(0).GetMethod().DeclaringType.ToString(), stackTrace.GetFrame(0).GetMethod().Name, 0);

The result is a graphviz diagram source and looks like this: Please note that a last closing curly bracket shuld be added by hand when you copy the text from log.text to generate a GraphViz diagram.

digraph G{arrowsize=2.0; ratio=fill; node[fontsize=24];graph [fontsize=24] edge [fontsize=24] node [fontsize=24] ranksep = 1.5 nodesep = .25 edge [style="setlinewidth(3)"]; 

subgraph cluster_Riogrande_UI { node [style=filled]; label = "Riogrande_UI"; color=red  
subgraph cluster_UsersForm { node [style=filled]; _ctor_UF; label = "UsersForm"; color=blue }}
subgraph cluster_Riogrande_DL { node [style=filled]; label = "Riogrande_DL"; color=red  
subgraph cluster_DataAccessUsers { node [style=filled]; _ctor_DAU; label = "DataAccessUsers"; color=blue    }}
_ctor_UF -> _ctor_DAU;
}

This is the diagram resulted from GraphViz:

This is the class I use:

namespace Riogrande
{
    public class MyLog
    {
        private static int MaximAcceptedLevel = 5;
        private static string lastMethodName = string.Empty;
        private static string filePath = "log.txt";

        public static void Log(string namespaceName, string className, string methodName, int logLevel)
        {
            if (logLevel < MaximAcceptedLevel)
            using (StreamWriter w = File.AppendText(filePath))
            {
                string namespceName = className.Substring(0, className.LastIndexOf('.')).Replace('.', '_');

                if (className.Contains('.'))
                {
                    className = className.Substring(className.LastIndexOf('.') + 1);
                }
                if (className.Contains('+'))
                {
                    className = className.Substring(0, className.LastIndexOf('+'));
                }
                className = className.Replace('.', '_');
                string cls = "";
                for (int i = className.Length-1; i > -1; i--)
                {
                    if (Char.IsUpper(className[i]))
                    {
                        if (cls.Length < 3)
                        {
                            cls = className[i] + cls;
                        }
                    }
                }
                string currentMethodName = methodName.Replace('.', '_') + "_" + cls;
                w.WriteLine("subgraph cluster_" + namespceName + " { node [style=filled]; label = \"" + namespceName + "\"; color=red   ");
                w.WriteLine("subgraph cluster_" + className + " { node [style=filled]; " + currentMethodName + "; label = \"" + className + "\"; color=blue }}");
                if (!string.IsNullOrEmpty(lastMethodName))
                {
                    w.WriteLine(lastMethodName + " -> " + currentMethodName + ";");
                }
                lastMethodName = currentMethodName;
            }
        }

        public static void Reset()
        {
            File.Delete(filePath);
            using (StreamWriter w = File.AppendText(filePath))
            {
                w.WriteLine("digraph G{arrowsize=2.0; ratio=fill; node[fontsize=24];graph [fontsize=24] edge [fontsize=24] node [fontsize=24] ranksep = 1.5 nodesep = .25 edge [style=\"setlinewidth(3)\"]; ");
                w.WriteLine();
            }
        }    
    }
}

The solution does not provide a small size file but you can implement this option in the same class.