Try, Except, Finally and IoWriteLogErrorEntry (Part 2)

October 11th, 2007 - Fernando Roberto

In the first part of this post, I talked a little bit about the demand and the basic logic involved in creating and sending messages to the system event log. Today I’m going to extend a little longer talking about sending parameters in these events, not just getting stuck with fixed messages defined in the file .mc. Another sample driver is available for downloading at the end of this post.

Sending Parameters in Messages

So far, we have seen how to send fixed strings to EventViewer: however, it would be very useful to be able to send strings dynamically generated by the driver. Following the issue of handling exceptions, throughout this post, we will write a function that can be called from the __except block, and thus log which exception was thrown and handled by your driver, so that the administrator can finally know if something wrong is happening. If you do not know what I mean, look at the first part of this post.

Like Jack, the Ripper used to say: “Let’s split it.” First, let’s make the code able to display the event’s exception code. To do this, we must put this information at the allocated package. The dumpdata member of the IO_ERROR_LOG_PACKET structure can take binary data to the EventViewer. This member is an array of ULONG and has its size defined by the DumpDataSize member, which should always be a multiple of sizeof (ULONG). Thinking about our example, the handled exception code could be placed on the first position of this array; that is 0xC0000005 for “Access Violation”. See the following example that adds this functionality. Remember that, in addition to the DumpDataSize member properly set, the bytes used by elements of this array should be taken into consideration when determining the package size to be allocated.

***     SendHelloEventWithData
**      Routine that allocates and sends an event which
**      takes an additional 32-bit parameter.
VOID SendHelloEventWithData(IN ULONG    ulData)
    PIO_ERROR_LOG_PACKET    pLogPacket;
    //-f--> It allocates the event entry. We should sum
    //      the used bytes by the DumpData array. That
    //      size should always be a multiple of sizeof(ULONG).
    pLogPacket = IoAllocateErrorLogEntry(pDriverObj,
                                         sizeof(IO_ERROR_LOG_PACKET) +
    //-f--> It Initializes the whole structure.
    RtlZeroMemory(pLogPacket, sizeof(IO_ERROR_LOG_PACKET));
    //-f--> Puts up the desired message
    pLogPacket->ErrorCode = EVT_HELLO_MESSAGE;
    //-f--> It fills up the binary dump and its size.
    pLogPacket->DumpData[0] = ulData;
    pLogPacket->DumpDataSize = sizeof(ULONG);
    //-f--> It sends up the event entry to the event list.

If you call this function passing 0x12345678 as a parameter, you will be able to see the sent data as it is shown in the figure below.

Inserting Strings

But where will these strings appear in the event log? We will have to create new messages making use of the strings on our message file. From here, we will build a routine that will be called within the __except block  to log the exception that was handled. Complete the message file with the following text.

MessageId = 0x0002
Facility = DriverEntryLogs
Severity = Warning
Language = Portuguese
A casa caiu na rotina %2 com status %3.
Language = English
The house fell down at routine %2 with status %3.

Notice that in these new messages there are these weird %2 and %3. These are the points where the first and second string will be respectively inserted in the message. But why is the first string indicated by %2 instead of %1? The %1 indicator is reserved to map a string with the driver name or device name. That will depend on what object was passed in the IoAllocateErrorLogEntry() first parameter. Although %1 is well documented, sometimes the string is not replaced in the message when the driver is starting or ending. Do not ask me why.

To make our example more complete, it would be very helpful if we could put a string that carried the symbol defined in the ntstatus.h header. So, we would have STATUS_ACCESS_VIOLATION for the exception code 0xc0000005 in the text displayed by EventViewer.

The first problem is to transform the exception code, which is a numeric value, into a string. This must have been multiple kernel developer’s need, because there is a routine source at the OSR Online site that does this. To get an idea, this routine is implemented in approximately 2200 lines of code. Is it oo much? Take a look at the beginning of it and you’ll understand it.

PUCHAR OsrNTStatusToString(NTSTATUS Status) {
    switch (Status) {
        return "STATUS_SUCCESS";
    case STATUS_WAIT_1:
        return "STATUS_WAIT_1";
    case STATUS_WAIT_2:
        return "STATUS_WAIT_2";

After that, we will have to convert these strings from ANSI to UNICODE, but all of this is in the sample code.

In order the strings can be displayed by the EventViewer event, even when the driver is not loaded, they need to be copied into the package. So now, it is necessary to determine the package size that will be allocated using the IoAllocateErrorLogEntry() routine. The package size should be added from the number of bytes occupied by the unicode string including the terminating zero. I think it is better for you follow the comments in the source below that already does everything.

***     LogExceptionHandled
**      This routine receives an NTSTATUS and sends a record to
**      the system event log.
VOID LogExceptionHandled(PWSTR     wzFunctionName,
                         NTSTATUS  nts)
    UNICODE_STRING          usNtStatus;
    ANSI_STRING             asNtStatus;
    UCHAR                   ucFinalSize;
    PWSTR                   pwzTarget;
    PIO_ERROR_LOG_PACKET    pLogPacket;
    //-f--> It initializes an ANSI_STRING with the error code
    //-f--> Convert up the string into unicode
    //-f--> It get the package size, that is, respectively:
    //  IO_ERROR_LOG_PACKET size
    //  DumpData element size
    //  Size of the string containing the error code
    //      Remember that we should reserve some space for the terminator.
    //  Size of the string containing the routine name that thrown the
    //      exception plus its respective terminator (/0).
    ucFinalSize = sizeof(IO_ERROR_LOG_PACKET) +
                  sizeof(ULONG) +
                  usNtStatus.Length + sizeof(WCHAR) +
                  (wcslen(wzFunctionName) + 1) * sizeof(WCHAR);
    //-f--> It allocates an entry for the event
    pLogPacket = IoAllocateErrorLogEntry(g_pDriverObj,
    //-f--> It initializes the whole structure
    RtlZeroMemory(pLogPacket, sizeof(IO_ERROR_LOG_PACKET));
    //-f--> It saves the error code into DumpData array
    //      and sets up its size into DumpDataSize member.
    pLogPacket->DumpData[0] = nts;
    pLogPacket->DumpDataSize = sizeof(ULONG);
    //-f--> It informs where the strings are and how many they are.
    pLogPacket->StringOffset = sizeof(IO_ERROR_LOG_PACKET) +
    pLogPacket->NumberOfStrings = 2;
    //-f--> It copies the first string into the package.
    pwzTarget = (PWSTR) ((PCHAR)pLogPacket +
    //-f--> It copies the second string into the package.
    pwzTarget += wcslen(wzFunctionName) + 1;
            usNtStatus.Length / sizeof(WCHAR));
    //-f--> Since the documentation referring to RtlAnsiStringToUnicodeString 
    //      doesn't mention there will always be a zero terminator
    //      on the converted string, we cannot assume
    //      that this terminator always be there.
    pwzTarget += usNtStatus.Length / sizeof(WCHAR);
    *pwzTarget = 0;
    //-f--> It puts the desired message.
    //-f--> It sends the entry to the event list.
    //-f--> It releases the converted string.

In that way, our __except block function, which was provided at the first part of this post, could be set as it is shown below:

        //-f--> Oops! An exception has been thrown. Let's log this,
        //      pretend insanity and just return the exception code.
        nts = GetExceptionCode();
        //-f--> It sends a record to the system event log.
        LogExceptionHandled(__FUNCTIONW__, nts);

Just for a test, let’s make a call to the DupString() function passing invalid parameters such as NULL and we will get the following output as it appears below. All the source code of the shown example is available for downloading at the end of this post.

The End is Near

As it was explained in the first part of this post, the event record doesn’t go to the disk synchronously when IoWriteErrorLogEntry() function is called; instead, the event record goes to a linked list before going to the disk. If the machine falls down and a dump is generated, we can consult this list with the !errlog in WinDbg, which analyzes the generated dump. Cool, let’s see if it works? Let’s send the message below and then dereference a null pointer, just to… The code for this function is written in KillYourSelf () routine in the sample code available for downloading.

MessageId = 0x0003
Facility = DriverEntryLogs
Severity = Error
Language = Portuguese
Adeus mundo cruel!
Language = English
Goodbye cruel world!

The KillYourSelf() function will only be called when a particular symbol is set, as you can see below. Therefore, if you want to test and see the results with your own eyes modify this symbol definition at the beginning of the source code and redo the test with a test machine.

    //-f--> Oh! I dream to be a Linux driver. Good-bye cruel world!

Inevitably a blue screen will occur, and with it, its memory dump is generated. Opening this dump for analysis using WinDbg, we should use the !errlog command to have the output, as it is shown below.

Microsoft (R) Windows Debugger  Version 6.7.0005.0
Copyright (c) Microsoft Corporation. All rights reserved.
Loading Dump File [C:\Documents and Settings\froberto\Desktop\MEMORY.DMP]
Kernel Complete Dump File: Full address space is available
Symbol search path is: srv*c:\symbols*
Executable search path is: 
Windows 2000 Kernel Version 2195 UP Free x86 compatible
Product: WinNt
Kernel base = 0x80400000 PsLoadedModuleList = 0x8046a4c0
Debug session time: Thu Oct 11 11:05:56.375 2007 (GMT-3)
System Uptime: 0 days 0:02:06.875
Loading Kernel Symbols
Loading User Symbols
*                                                                             *
*                        Bugcheck Analysis                                    *
*                                                                             *
Use !analyze -v to get detailed debugging information.
BugCheck 1E, {c0000005, be552682, 1, 0}
Probably caused by : EventSender.sys ( EventSender!KillYourSelf+2a )
Followup: MachineOwner
kd> !errlog
PacketAdr  DeviceObj  DriverObj  Function  ErrorCode  UniqueVal  FinalStat
81551108   00000000   815c1830    0        402a0001   00000000   00000000
        DumpData:  12345678 
815b1f88   00000000   815c1830    0        802a0002   00000000   00000000
        DumpData:  c0000005 
81535248   00000000   815c1830    0        c02a0003   00000000   00000000

At the ErrorCode column, we have the codes that have been defined by the message file compilation and are visible at the header file also generated. Watch up the messages and their identifiers in the excerpt below. As you can see, none of the three test messages used in this example went to the disk. All records were still in memory. Thus, do not expect to see these messages using EventViewer; they have not yet been written at the disk yet.

// MessageText:
//  Ola mundo!
#define EVT_HELLO_MESSAGE                ((NTSTATUS)0x402A0001L)
// MessageText:
//  A casa caiu na rotina %2 com status %3.
// MessageText:
//  Adeus mundo cruel!
#define EVT_GOODBYE_MESSAGE              ((NTSTATUS)0xC02A0003L)

Phew! I have thought this post would not finish any more. Once again, I hope this could have helped. CYA!

Leave a Reply