Debugging Stack overflow errors on background services
Asked Answered
W

3

10

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.

Welloiled answered 17/9, 2013 at 14:30 Comment(6)
Put your solution as an answer. Read one more time blog.stackoverflow.com/2011/07/…Helmsman
This is fine, and actually encouraged on stack overflow. But you should still present it in a question, which you then answer yourself.Frederic
Thanks for your contribution. I encourage you to do as others have suggested: edit your question so it is just the question, then submit the answer as an answer. Once you have enough reputation to pass new-user restrictions, you can actually submit your question and answer simultaneously.Mun
Cool. Will do so next time. This is my first contribution to Stack Overflow.Welloiled
@Welloiled I don't want to repeat what others already pointed out. Except that if you keep it like this on SO it is considered a question that has no answer - as such - many people come and check if they can help with an answer. so it is kind of misleading to keep it like that.Allout
Now, please: UNTIL you post your answer as an answer, it WASTES OUR TIME to keep checking how we can help with your "unanswered question"Subdual
L
0

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()
Leff answered 17/9, 2013 at 14:30 Comment(0)
X
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:

The result

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.

Xanthous answered 19/10, 2013 at 18:0 Comment(0)
L
0

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()
Leff answered 17/9, 2013 at 14:30 Comment(0)
S
0

Nice job, but if the real problem is working with big logs or even huge logs, you should take a look at microsoft LogParser. As long as you format your log files properly you will be able to query the log the same way you would use in SQL. You can even create csv files from the results and analyze them or use the libraries to perform complex operations within a .net application.

For instance, say you want to select all IIS entries for a given page and save the results as CSV, you could do something like this

logparser "select * into LANDINGPAGEHITS.CSV from [yourlogfile] where cs-uri-stem like '/home.aspx"

My point here is not to burst your bubble but to show you how to handle big files if you previously formated your application log output and without worrying to remove entries out of it.

Segura answered 15/10, 2013 at 19:32 Comment(0)

© 2022 - 2024 — McMap. All rights reserved.