DFSR Debug Analysis with Message Analyzer – Part 2, Timestamps and Simple DFSR Debug Log Messages
This post continues the series that started here.
Last post, I started discussing my journey in creating a DFSR debug log parser for Message Analyzer. Today I want to begin breaking down that work in detail.
Having worked with DFSR a lot in the past, I had reasonable familiarity with the debug logs but to build a parser, I needed a formal definition for their structure. Luckily, Ned Pyle has created an incredible set of blog posts on that very topic. You can read through them starting here.
The first thing to consider is that there are three types of DFSR debug messages –
- Debug log headers
- Single-line messages
- Nested (or multi-line) message
I decided to start with single-line messages.
Single-line DFSR Debug Log Message Structure
Taking a screen clipping directly from the first post in Ned’s series, we see the single-line message structure –
After examining a set of DFSR logs taken from my own lab, I noticed a few anomalies –
In this example, there is no Class included in the message –
20120522 11:01:16.999 1824 PDBX 6182 ReadLastInstanceValue SYSTEM\CurrentControlSet\Control\BackupRestore\SystemStateRestore\LastRestoreId value is not present.
In this example, we see the Namespace included right before the Class::Method –
20120522 11:01:19.202 1824 CLUS 3988 Cluster::ClusterUtil::GetOwnedOnlinePhysicalDisks [CLUSTER] Get locally owned online physical disk list
In this example, an extra field appears containing [ERROR] –
20120522 11:01:16.999 1824 SYSM 3971 [ERROR] Migration::SysVolUtil::GetDwordFromRegistry [MIG] Failed to Open() rKey:System\CurrentControlSet\Services\DFSR\Parameters\SysVols\Migrating SysVols. Cannot read value valueName:Local State
I was able to discuss these anomalies with Ned and conclude that
- The first example should be interpreted simply as
- Method = ReadLastInstanceValue
- The second example should be interpreted as
- Namespace = Cluster
- Class = ClusterUtil
- Method = GetOwnedOnlinePhysicalDisks
- The third example should be interpreted as
- Level = ERROR
With this understanding in hand, I was ready to begin writing a parser.
Handling Timestamps
Message Analyzer defaults to sorting messages by time stamp using the DateTime structure for this data. My first task was to extract the date stamps from DFSR debug logs and provide them to Message Analyzer correctly. As luck would have it, the pre-existing Netlogon parser (Netlogon.config) that ships with Message Analyzer includes a great example of this.
Text file parsers for Message Analyzer contain message definitions that describe how information is extracted from log messages. These message definitions inherit from a base definition called LogEntry. I create a message definition for timestamps -
message DfsrTimeStamp : LogEntry
{
string Date;
string Time;
}
Next I create a syntax using RegEx that will convert the time stamp we see in the DFSR debug logs to the format expected for a DateTime structure –
syntax CustomDateTimeFormat = year:regex{[0-9][0-9][0-9][0-9]}month:regex{[0-9][0-9]}day:regex{[0-9][0-9]} " " hours:regex{[0-9][0-9]} ":" minutes:regex{[0-9][0-9]} ":" seconds:regex{[0-9][0-9]} "." fract:regex{[0-9]+} => ToDateTime(year + "-" + month + "-" + day + "T" + hours + ":" + minutes + ":" + seconds + "." + fract, DateTimeStyles.None);
Lastly, I create a property to return a DateTime given a DfsrTimeStamp message.
DateTime get DFSRtsDateTime(this DfsrTimeStamp msg) with EntryFieldInfo {IsTimestamp = true, IsLocalTime = true }
{
optional DateTime theDateTime = CustomDateTimeFormat(msg.Date + " " + msg.Time) as DateTime;
if(theDateTime == nothing)
{
return CustomDateTimeFormat("19680107 12:34:56.987") as DateTime;
}
else
{
return theDateTime as DateTime;
}
}
At this point, any DfsrTimeStamp message containing Date and Time strings will be consumed and Message Analyzer will receive a DateTime structure. What’s missing is the ability to populate the DfsrTimeStamp message Date and Time with data from the DFSR debug log. To do this, I create a new message definition that inherits from DfsrTimeStamp –
message DfsrMessage with
EntryInfo { Regex = @"(?<Date>^[\d]+)\s+(?<Time>[\d:\.]+)\s*(?<MessageText>.*)"},
DisplayInfo { ToText = GetSimpleSummaryText } : DfsrTimeStamp
{
string MessageText;static string GetSimpleSummaryText(any d)
{
var e = d as DfsrMessage;
return e.MessageText;
}
}
Here, DfsrMessage inherits from DfsrTimeStamp and so this message contains three strings –
- Date
- Time
- MessageText
Message Analyzer knows that it should use this message definition when it encounters a log message that matches the EntryInfo criteria … the RegEx expression
(?<Date>^[\d]+)\s+(?<Time>[\d:\.]+)\s*(?<MessageText>.*)
This RegEx expression expects
- One or more decimal digits (which will be injected into the Date string) – (?<Date>^[\d]+)
- One or more spaces – \s+
- One or more decimal digits colons or periods (which will be injected into the Time string) – (?<Time>[\d:\.]+)
- Any number of spaces – \s*
- Any set of characters (which will be injected into the MessageText string) – (?<MessageText>.*)
Lastly, Message Analyzer displays a Summary column in its Analysis Grid. To populate this column, my parser calls GetSimpleSummaryText (via the ToText statement) which outputs the MessageText string.
I save my parser as DFSRDebug.config and copy it to the parser directory –
%localappdata%\Microsoft\MessageAnalyzer\OpnAndConfiguration\TextLogConfiguration\DevicesAndLogs
Open Message Analyzer and start a session –
Choose files –
Add my DFSR debug log file and choose my parser –
The result is that single-line messages are parsed, displaying the Timestamp and the Summary text –
Parsing Message Fields
Now that I have the start of my parser, I want to extract the other message fields instead of dumping them all in MessageText. I add additional fields to the message definition and modify the RegEx –
Message Fields become –
uint Thread;
string ModuleID;
uint SourceCodeLine;
string Namespace;
string Class;
string Method;
string Level;
string MessageText;
RegEx becomes –
(?<Date>^[\d]+)\s+(?<Time>[\d:\.]+)\s+(?<Thread>[\d]+)\s+(?<ModuleID>[A-Za-z]+)\s+(?<SourceCodeLine>[\d]+)(\s+\[(?<Level>[A-Za-z]+)\])?\s+((?<Namespace>[A-Za-z]+)::(?<Class>[A-Za-z]+)::)?((?<Class>[A-Za-z]+)::)?(?<Method>[A-Za-z~]+)\s*(?<MessageText>.*)
The RegEx expression expects –
- One or more decimal digits (injected into Date) – (?<Date>^[\d]+)
- One or more spaces – \s+
- One or more decimal digits colons or periods (injected into Time) – (?<Time>[\d:\.]+)
- One or more spaces – \s+
- One or more decimal digits (injected into Thread) – (?<Thread>^[\d]+)
- One or more spaces – \s+
- One or more alpha characters (injected into ModuleID) – (?<ModuleID>[A-Za-z]+)
- One or more spaces – \s+
- One or more decimal digits (injected into SourceCodeLine) – (?<SourceCodeLine>^[\d]+)
- Optionally, one or more spaces followed by one or more alpha characters between square brackets (the alpha string injected into Level) - (\s+\[(?<Level>[A-Za-z]+)\])?
- One or more spaces – \s+
- Optionally, one or more alpha characters followed by :: and then one or more alpha characters (alpha strings being injected into Namespace and then Class) – ((?<Namespace>[A-Za-z]+)::(?<Class>[A-Za-z]+)::)?
- Optionally, one or more alpha characters followed by :: (the alpha string injected into Class) - ((?<Class>[A-Za-z]+)::)?
- One or more alpha characters or tildes (injected into Method) – (?<Method>[A-Za-z~]+)
- Any number of spaces – \s*
- Any set of characters (which will be injected into the MessageText string) – (?<MessageText>.*)
After saving the parser and opening the DFSR debug log in Message Analyzer again, I see the message fields extracted nicely –
Conclusion
With single-line messages parsing correctly, I’m ready to consider DFSR debug log header messages and also multi-line messages. Before I do though, I’ll create a cleaner Analysis Grid Layout.
Next Up