Try, Except, Finally and IoWriteErrorLogEntry (Part 1)

September 25th, 2007 - Fernando Roberto

Most of you have already known about exception handling in C. Knowing that the C Run Time Kernel does not support exception handling in C++, the exception handling in C fits us like a glove. Exceptions do not always mean that a critical error has occurred, but regardless, it is essential to treat them. An unhandled exception in kernel means blue screen. In the case of an unexpected exception, such as an Access Violation, using exception handlers could prevent the system from a blue finish. That’s great, congratulations, one more life saved, but we must not forget that there had been an unexpected exception. This post will not mention how to use exception handlers in details, but it will talk about how we can report such events to the system administrator.

A Typical Exception Handling

For those who are just waking up right now, I’ll just give you a brief description of exception handling in the source below. The details are in the reference. The following source was taken from one of the examples available on this blog. This feature can save us from a merciless blue screen whenever “a loser” who calls this function, passes an invalid string as a source of duplication.

/****
***     DupString
**
**      This routine receives a Unicode String and duplicates it.
**      The resulting string should be released
**      using the ExFreePool routine.
*/
 
NTSTATUS
DupString(IN PUNICODE_STRING   pusSource,
          OUT PUNICODE_STRING  pusTarget)
{
    NTSTATUS    nts = STATUS_SUCCESS;
 
    __try
    {
        __try
        {
            //-f--> Initializes the target
            pusTarget->Buffer = NULL;
 
            //-f--> Allocates the target buffer
            if (!(pusTarget->Buffer = (PWSTR)ExAllocatePool(PagedPool,
                                                            pusSource->Length)))
                ExRaiseStatus(STATUS_INSUFFICIENT_RESOURCES);
 
            //-f--> Copies the buffer
            RtlCopyMemory(pusTarget->Buffer,
                          pusSource->Buffer,
                          pusSource->Length);
 
            //-f--> Copies the buffer legths
            pusTarget->MaximumLength = pusTarget->Length = pusSource->Length;
        }
        __finally
        {
            //-f--> If something gets wrong, we must release the target buffer.
            if (AbnormalTermination())
                if (pusTarget->Buffer)
                    ExFreePool(pusTarget->Buffer);
        }
    }
    __except(EXCEPTION_EXECUTE_HANDLER)
    {
        nts = GetExceptionCode();
 
        DbgPrint("DupString >> An exception occourred at "__FUNCTION__
                 " with status 0x%08x.\n", nts);
 
        ASSERT(FALSE);
    }
    return nts;
}

Note that there are two blocks of execution. The outermost is the one, which will deal with unhandled exceptions, and the innermost the one, which will deal with resource releasing. The exception handler block will executes the __except block when any exception is thrown from the inside of __try block. This will give us the opportunity to find out what happened and, in some cases, to request that the instruction causing the exception is re-executed. The completion __finally block is executed when the thread goes out of the main block, either by reaching the block’s end, for a return, for a goto out of the block, or even an exception that was thrown. The __finally block is always executed. This gives us the opportunity to release any resource that has been pending during the execution of the block. Taken it together, we can imagine the following situation: suppose the function RtlCopyMemory() throw an exception. In this case, the __except block will run, but for this to occur, the execution flow will leave the inner block as well, thus causing the __finally block execution.

Within each handler, there is a special function call. Inside __except, we have GetExceptionCode(), which returns us the exception code that was thrown. This function can only be called within this context. Also note that, within __finally block, there is a call to the AbnormalTermination() function which indicates that the block was not executed until reaching its end. In our example, we use this function to determine that something wrong should have happened and it is necessary to release the buffer which would be returned to the calling function. Anyway, check out the reference for a complete description of these resources.

The main point here to note is the ASSERT at the end of the __except block. If this source is compiled in Checked, the ASSERT will cause a prompt in the debugger. If there is no debugger attached to the system, then a blue screen will appear. That’s because this macro will throw a break exception to the debugger but, as the debugger will not be there to handle this exception, figure it out. When compiled in Free, the ASSERT macro is translated into nothing: our function will handle the exception gracefully and it will return the exception code to the calling function. How sweet but, when will is the administrator going to know?

A Life Sign

The standard way to leave this signal is writing in the system event log. What is this? This link can give you detailed information about the system event logs. To write a record in this list from the kernel, we initially must allocate the buffer that will house all the information record using the IoAllocateErrorLogEntry() function.

PVOID 
  IoAllocateErrorLogEntry(
    IN PVOID  IoObject,
    IN UCHAR  EntrySize
    );

The pointer returned by this function, although being the type PVOID, points out to an IO_ERROR_LOG_PACKET structure, which has variable size depending on the information that composes it. This structure is used to package all the event data that will be logged.

typedef struct _IO_ERROR_LOG_PACKET
{
    UCHAR MajorFunctionCode;
    UCHAR RetryCount;
    USHORT DumpDataSize;
    USHORT NumberOfStrings;
    USHORT StringOffset;
    USHORT EventCategory;
    NTSTATUS ErrorCode;
    ULONG UniqueErrorValue;
    NTSTATUS FinalStatus;
    ULONG SequenceNumber;
    ULONG IoControlCode;
    LARGE_INTEGER DeviceOffset;
    ULONG DumpData[1];
 
} IO_ERROR_LOG_PACKET, *PIO_ERROR_LOG_PACKET;

Although this structure has three kilograms of members, you won’t need to fill most of them up. Then, the next step is to pass the structure to the IoWriteErrorLogEntry() function and that is it.

VOID 
  IoWriteErrorLogEntry(
    IN PVOID  ElEntry
    );

It is not that easy

So, is it just to allocate the structure, initialize it, call the function of writing and all is done? This question is simply funny. Not long ago, I was in Porto Alegre, and there someone told me that when one explain something starting with “It’s just…”, the actual work is five times bigger than the one explained. Let’s start writing that famous phrase “Hello World” to see the size of the mess!

Well… Where do I put error message? Oh yeah, that’s right, into the message file. Unlikely log files we usually do in applications, the messages are not passed directly to the writing function. Instead, the ErrorCode member of the IO_ERROR_LOG_PACKET structure receives a handle to the message which will be displayed. When the IoWriteErrorLogEntry() function is called, it puts the packet in a list in memory. Later, this package is written to the system events log file. The EventViewer, the software used to view such events, gets the message identifier contained in the package. With this handle, it finds the string that will be stored in a separated module. This module can be your own driver or a DLL. Thus, this string is read and displayed to the user’s module. Phew!

Huh? Who? When? Where? We will rely on the simplest driver example we have to add these features. Let’s start composing the module writing messages to a text file that takes the .mc extension. This text file will be compiled by the Message Compiler. This compilation will generate the resource file containing strings along with the header file that will refer to certain created symbols. See the template message file below:

MessageIdTypedef = NTSTATUS
 
SeverityNames =
(
    Success         = 0x0:STATUS_SEVERITY_SUCCESS
    Informational   = 0x1:STATUS_SEVERITY_INFORMATIONAL
    Warning         = 0x2:STATUS_SEVERITY_WARNING
    Error           = 0x3:STATUS_SEVERITY_ERROR
)
 
FacilityNames =
(
    System          = 0x0
    DriverEntryLogs = 0x2A:DRIVERENTRY_FACILITY_CODE
)
 
LanguageNames =
(
    Portuguese  = 0x0416:msg00001
    English     = 0x0409:msg00002
)
 
MessageId = 0x0001
Facility = DriverEntryLogs
Severity = Informational
SymbolicName = EVT_HELLO_MESSAGE
 
Language = Portuguese
"Ola mundo!"
.
Language = English
"Hello world!"
.

Notice that we have the same message in several languages. What a fancy thing, uh? Save this file with the name of LogMsgs.mc. You can name it of your choice, but remember that this name will be repeated at the generated files. To compile this file, just put it in the list of sources to be compiled, which is in the sources of your project file, as it is shown below. If you decide the messages should be contained within the driver itself, then you need to add the LogMsgs.rc file that will be generated by the Message Compiler.

TARGETNAME=Useless
TARGETPATH=obj
TARGETTYPE=DRIVER
 
SOURCES=LogMsgs.mc\
        Useless.c \
        LogMsgs.rc

Once compiled, the files LogMsgs.rc and LogMsgs.h will be generated. The header file defines the error codes defined at the message file and should be included in the sources files that will make calls for log creation. Watch an excerpt of this file that was generated automagically.

//
// MessageId: EVT_HELLO_MESSAGE
//
// MessageText:
//
//  "Ola mundo!"
//
#define EVT_HELLO_MESSAGE                ((NTSTATUS)0x402A0001L)

Finally we can write the code lines that will use all of this stuff we have created.

#include  
#include "LogMsgs.h"
 
/****
***     DriverEntry 
**
**      That's our driver entry point, everything starts from here,
**      and atfer gets worse and worse...
*/
 
NTSTATUS DriverEntry(IN PDRIVER_OBJECT  pDriverObject,
                     IN PUNICODE_STRING pusRegistryPath)
{
    PIO_ERROR_LOG_PACKET    pLogPacket;
 
    //-f--> Allocates an entry to the event.
    pLogPacket = IoAllocateErrorLogEntry(pDriverObject,
                                         sizeof(IO_ERROR_LOG_PACKET));
 
    //-f--> Inicializes all the structure
    RtlZeroMemory(pLogPacket, sizeof(IO_ERROR_LOG_PACKET));
 
    //-f--> Puts up the desired message
    pLogPacket->ErrorCode = EVT_HELLO_MESSAGE;
 
    //-f--> Sends the entry to the system event list
    IoWriteErrorLogEntry(pLogPacket);
 
    //-f--> Phew, we got to be here; that makes
    //      a success returning code to the system be worthy!
    return STATUS_SUCCESS;
}

Is everything done now?

From the driver viewpoint, it is all already done. The driver can now be compiled, loaded and thus able to create the entry in the log, carrying the message number to be displayed by EventViewer. After executing the driver, we can open the EventViewer; and it is able to find the entry generated by our driver, and then to see the message.

Oops! We still have to tell EventViewer what is the responsible module for storing the strings. In our case, the messages are in the driver itself. To achieve this, we must add a key with the name of our driver in the EventLog registry key. Within this key, we still have to create two values indicating the module path which contains the messages and what kinds of events our driver can generate. Look at carefully the registry path in the figure below.

Once we set the values described above in the registry, just reopen the same event so that the message is displayed as it should be. Remember that the driver does not need to send the event again for the message to be displayed correctly. The driver sends only one entry with the message identifier. This was already done regardless of the message module has been configured. In the figure below, we can see the messages in Portuguese and English, depending on the language of the operating system. What a cute!

As this post is getting bigger than I had expected (for change), I will divide it into parts. I still want to comment on how to use its input parameters to clarify the doubts that some of you may be asking now: “If the log entry is initially in a linked list, and only after a time that is actually going to the disk, can entries be lost if the machine falls in this interval? “.

Is the butler really culprit? Is the Matrix inside another Matrix? Does Tostines sell more because it’s fresh, or is it fresh because it sells more? Do not miss it!

CYA … 🙂

Leave a Reply