Parsing ASP.NET event log error messages for fun and profit
a customer will ask me to look at their site and make some recommendations on what
can be improved. One of the many things I’ll look at is their event logs.
One of the nice things about ASP.NET is that when you encounter an unhandled exception,
an event will be placed into your Application event log. The message of the
event log entry will usually include lots of good stuff like the application, path,
machine name, exception type, stack trace, etc. Loads of great stuff and all
for free. For customers that don’t have a centralized exception logging strategy,
this can be a gold mine.
The way it usually works is that they will provide me an EVTX from their servers.
If you’re not aware, an EVTX is just an archive of the events from the event log you
specify. By itself, looking at the raw event logs from a server can be quite
daunting. There are usually thousands of entries in the event log and filtering
down to what you actually care about can be exhausting. Even if you do find
a series of ASP.NET event log messages, the problem has always been – how do you take
all of this great information that’s just dumped into the Message property of the
event log entry and put it into a format you can easily report on, generate statistics,
etc. Fortunately, I have a non-painful solution.
I’ve broken this down into a relatively simple 4-step process:
- Get the EVTX
Generate a useful XML file
- Parse into an object model
- Analyze and report on the data
Let’s get to it.
Step 1: Get the EVTX
This step is pretty short and sweet. In the Event Log manager, select the “Application”
group and then select the “Save All Events As…” option.
That will produce an EVTX file with whatever name you specify. Once you have
the file, transfer it to your machine as you generally do not want to install too
many tools in your production environment.
Step 2: Generate a useful XML file
Now that we have the raw EVTX file, we can get just the data we care about using a
great tool called LogParser. Jeff
Atwood did a nice little write-up on the tool but simply put it’s the Swiss
Army knife of parsing tools. It can do just about anything data related you
would wish using a nice pseudo-SQL language. We’ll use the tool to pull out
just the data from the event log we want and dump it into an XML file. The query
that we can use for this task is daunting in its simplicity:
SELECT Message INTO MyData.xml
FROM ‘*.evtx’
WHERE EventID=1309
The only other thing we need to tell LogParser is the format in which it the data
is coming in and the format to put it into. This makes our single command the
following:
C:\>logparser -i:EVT -o:XML
"SELECT Message INTO MyData.xml FROM ‘*.evtx’ WHERE EventID=1309"
This will produce a nice XML file that looks something like the following:
<?xml version="1.0" encoding="ISO-10646-UCS-2" standalone="yes" ?>
<ROOT DATE_CREATED="2010-08-29
06:04:20" CREATED_BY="Microsoft
Log Parser V2.2">
<ROW>
<Message>Event
code: 3005 Event message: An unhandled exception has occurred...
</Message>
</ROW>
...
</ROOT>
One thing that you may notice is that all of the nicely formatted data from our original
event log message is munged together into one unending string. This will actually
work in our favor but more on that in the next step.
Step 3: Parse into an object model
So, now that we have an XML file with all of our event details, let’s do some parsing.
Since all of our data is in one string, the simplest method is to apply a RegEx expression
with grouping to grab the data we care about.
In a future post, I’ll talk about a much faster way of getting this type
of data without a RegEx expression. After
all, refactoring is a way of life for developers .
private const string LargeRegexString
= @"Event code:(?<Eventcode>.+)" +
@"Event message:(?<Eventmessage>.+)" +
@"Event time:(?<Eventtime>.+)" +
@"Event time \(UTC\):(?<EventtimeUTC>.+)" +
@"Event ID:(?<EventID>.+)" +
@"Event sequence:(?<Eventsequence>.+)" +
@"Event occurrence:(?<Eventoccurrence>.+)" +
@"Event detail code:(?<Eventdetailcode>.+)" +
@"Application information:(?<Applicationinformation>.+)" +
@"Application domain:(?<Applicationdomain>.+)" +
@"Trust level:(?<Trustlevel>.+)" +
@"Full Application Virtual Path:(?<FullApplicationVirtualPath>.+)" +
@"Application Path:(?<ApplicationPath>.+)" +
@"Machine name:(?<Machinename>.+)" +
@"Process information:(?<Processinformation>.+)" +
@"Process ID:(?<ProcessID>.+)" +
@"Process name:(?<Processname>.+)" +
@"Account name:(?<Accountname>.+)" +
@"Exception information:(?<Exceptioninformation>.+)" +
@"Exception type:(?<Exceptiontype>.+)" +
@"Exception message:(?<Exceptionmessage>.+)" +
@"Request information:(?<Requestinformation>.+)" +
@"Request URL:(?<RequestURL>.+)" +
@"Request path:(?<Requestpath>.+)" +
@"User host address:(?<Userhostaddress>.+)" +
@"User:(?<User>.+)" +
@"Is authenticated:(?<Isauthenticated>.+)" +
@"Authentication Type:(?<AuthenticationType>.+)" +
@"Thread account name:(?<Threadaccountname>.+)" +
@"Thread information:(?<Threadinformation>.+)" +
@"Thread ID:(?<ThreadID>.+)" +
@"Thread account name:(?<Threadaccountname>.+)" +
@"Is impersonating:(?<Isimpersonating>.+)" +
@"Stack trace:(?<Stacktrace>.+)" +
@"Custom event details:(?<Customeventdetails>.+)";
Now that we have our RegEx, we’ll just write the code to match it against a string
and populate our class. While I’ve included the entire regex above, I’ve
only included a partial implementation of the class population below.
public class EventLogMessage
{
private static Regex
s_regex = new Regex(LargeRegexString,
RegexOptions.Compiled);
public EventLogMessage(string rawMessageText)
{
Match myMatch = s_regex.Match(rawMessageText);
Eventcode = myMatch.Groups["Eventcode"].Value;
Eventmessage = myMatch.Groups["Eventmessage"].Value;
Eventtime = myMatch.Groups["Eventtime"].Value;
EventtimeUTC = myMatch.Groups["EventtimeUTC"].Value;
EventID = myMatch.Groups["EventID"].Value;
Eventsequence = myMatch.Groups["Eventsequence"].Value;
Eventoccurrence = myMatch.Groups["Eventoccurrence"].Value;
Eventdetailcode = myMatch.Groups["Eventdetailcode"].Value;
Applicationinformation = myMatch.Groups["Applicationinformation"].Value;
Applicationdomain = myMatch.Groups["Applicationdomain"].Value;
Trustlevel = myMatch.Groups["Trustlevel"].Value;
FullApplicationVirtualPath = myMatch.Groups["FullApplicationVirtualPath"].Value;
ApplicationPath = myMatch.Groups["ApplicationPath"].Value;
Machinename = myMatch.Groups["Machinename"].Value;
Processinformation = myMatch.Groups["Processinformation"].Value;
...
}
public string Eventcode
{ get; set; }
public string Eventmessage
{ get; set; }
public string Eventtime
{ get; set; }
public string EventtimeUTC
{ get; set; }
public string EventID
{ get; set; }
public string Eventsequence
{ get; set; }
public string Eventoccurrence
{ get; set; }
public string Eventdetailcode
{ get; set; }
public string Applicationinformation
{ get; set; }
public string Applicationdomain
{ get; set; }
public string Trustlevel
{ get; set; }
public string FullApplicationVirtualPath
{ get; set; }
public string ApplicationPath
{ get; set; }
public string Machinename
{ get; set; }
public string Processinformation
{ get; set; }
...
}
The last step is just to read in the XML file and instantiate these objects.
XDocument document = XDocument.Load(@"<pathToData>\MyData.xml");
var messages = from message in document.Descendants("Message")
select new EventLogMessage(message.Value);
Now that we have our objects and everything is parsed just right, we can finally get
some statistics and make sense of the data.
Step 4: Analyze and report on the data
This last step is really the whole point of this exercise. Fortunately, now
that all of the data is an easily query’able format using our old friend LINQ, the
actual aggregates and statistics are trivial. Really, though, everyone’s needs
are going to be different but I’ll provide a few queries that might be useful.
Query 1: Exception Type Summary
For example, let’s say you wanted to output a breakdown of the various Exception Types
in your log file. The query you would use for that would be something like:
var results = from log in messages
group log by log.Exceptiontype into l
orderby l.Count() descending, l.Key
select new
{
ExceptionType = l.Key,
ExceptionCount = l.Count()
};
foreach (var result in results)
{
Console.WriteLine("{0} : {1} time(s)",
result.ExceptionType,
result.ExceptionCount);
}
This would then output something like:
WebException : 15 time(s)
InvalidOperationException : 7 time(s)
NotImplementedException : 2 time(s)
InvalidCastException : 1 time(s)
MissingMethodException : 1 time(s)
Query 2: Exception Type and Request URL Summary
Let’s say that you wanted to go deeper and get the breakdown of which URL’s generated
the most exceptions. You can just expand that second foreach loop in the above
snippet to do the following:
foreach (var
result in results)
{
Console.WriteLine("{0} : {1} time(s)",
result.ExceptionType,
result.ExceptionCount);
var requestUrls = from urls in messages
where urls.Exceptiontype == result.ExceptionType
group urls by urls.RequestURL.ToLower() into url
orderby url.Count() descending, url.Key
select new
{
RequestUrl = url.Key,
Count = url.Count()
};
foreach (var url in requestUrls){
Console.WriteLine("\t{0} : {1} times ",
url.RequestUrl,
url.Count);
}
}
This then would produce output like this:
WebException : 15 time(s)
https://localhost/menusample/default.aspx : 11
times
https://localhost:63188/menusample/default.aspx
: 4 times
InvalidOperationException : 7 time(s)
https://localhost:63188/menusample/default.aspx
: 6 times
https://localhost/menusample/default.aspx : 1 times
NotImplementedException : 2 time(s)
https://localhost/samplewebsiteerror/default.aspx
: 2 times
InvalidCastException : 1 time(s)
https://localhost:63188/menusample/default.aspx
: 1 times
MissingMethodException : 1 time(s)
https://localhost:63188/menusample/default.aspx
: 1 times
Query 3: Exception Type, Request URL and Method Name Summary
You can even go deeper, if you so desire, to find out which of your methods threw
the most exceptions. For this to work, we need to make a slight change to our
EventLogMessage class to parse the Stack Trace data into a class. First, we’ll
start with our simple little StackTraceFrame class:
public class StackTraceFrame
{
public string Method
{ get; set; }
}
Second, add a new property to our EventLogMessage class to hold a List<StackTraceFrame>:
public List<StackTraceFrame>
StackTraceFrames { get; set; }
Lastly, add a method (and its caller) to parse out the stack frames and assign the
resulting List to the StackTraceFrames property mentioned above:
public EventLogMessage(string rawMessageText)
{
Match myMatch = s_regex.Match(rawMessageText);
...
Stacktrace = myMatch.Groups["Stacktrace"].Value;
...
StackTraceFrames = ParseStackTrace(Stacktrace);
}
private List<StackTraceFrame> ParseStackTrace(string stackTrace)
{
List<StackTraceFrame> frames = new List<StackTraceFrame>();
string[] stackTraceSplit = stackTrace.Split(new string[]
{ " at " },
StringSplitOptions.RemoveEmptyEntries);
foreach (string st in stackTraceSplit)
{
if (!string.IsNullOrEmpty(st))
{
frames.Add(new StackTraceFrame() { Method = st
});
}
}
return frames;
}
Please Note: You could enhance the ParseStackTrace(…) method to
parse out the source files, line numbers, etc. I’ll leave this as an exercise for
you, dear reader.
Now that we have the infrastructure in place, the query is just as simple. We’ll
just nest this additional query inside of our URL query like so:
foreach (var
url in requestUrls){
Console.WriteLine("\t{0} : {1} times ",
url.RequestUrl,
url.Count);
var methods = from method in messages
where string.Equals(method.RequestURL,
url.RequestUrl,
StringComparison.InvariantCultureIgnoreCase)
&&
string.Equals(method.Exceptiontype,
result.ExceptionType,
StringComparison.InvariantCultureIgnoreCase)
group method by method.StackTraceFrames[0].Method into mt
orderby mt.Count() descending, mt.Key
select new
{
MethodName = mt.Key,
Count = mt.Count()
};
foreach (var method in methods)
{
Console.WriteLine("\t\t{0} : {1} times ",
method.MethodName,
method.Count
);
}
}
This would then produce output like the following:
WebException : 15 time(s)
https://localhost/menusample/default.aspx : 11 times
System.Net.HttpWebRequest.GetResponse() : 11 times
https://localhost:63188/menusample/default.aspx : 4 times
System.Net.HttpWebRequest.GetResponse() : 4 times
InvalidOperationException : 7 time(s)
https://localhost:63188/menusample/default.aspx : 6 times
System.Web.UI.WebControls.Menu... : 6 times
https://localhost/menusample/default.aspx : 1 times
System.Web.UI.WebControls.Menu... : 1 times
One last thing you may notice is that the in the example above, the first frame for
each of those exceptions are somewhere in the bowels of the .NET BCL. You may
want to filter this out even further to only return YOUR method.
This can be accomplished very easily with the method below. It will simply loop
through the StackTraceFrame List and return the first method it encounters that does
not start with “System.” or “Microsoft.”.
private static string GetMyMethod(List<StackTraceFrame>
frames)
{
foreach (StackTraceFrame frame in frames)
{
if (!frame.Method.StartsWith("System.")
&&
!frame.Method.StartsWith("Microsoft."))
return frame.Method;
}
return "No User
Code detected.";
}
Then, you can just call that method from the new query we wrote above:
var methods = from method in messages
where ...
group method by
GetMyMethod(method.StackTraceFrames) into mt
...
Finally, with this new snippet in place, we’ll get output like this:
WebException : 15 time(s)
https://localhost/menusample/default.aspx : 11 times
_Default.Page_Load(Object sender, EventArgs e)...: 8 times
No User Code detected. : 3 times
https://localhost:63188/menusample/default.aspx : 4 times
_Default.Page_Load(Object sender, EventArgs e)... : 1 times
No User Code detected. : 1 times
WebControls.CustomXmlHierarchicalDataSourceView.Select()... : 2 times
As you can see, the sky’s the limit.
Enjoy!