Logging Errors

Logging Errors

In the discussions of error handling up until now, I ve been concerned only with detecting (and propagating) status codes and with doing various things in the checked build to help debug problems that show up as errors. Even in the free build of a driver, however, some errors are serious enough that we want to be sure the system administrator knows about them. For example, maybe a disk driver discovers that the disk s physical surface has an unusually large number of bad sectors. Or maybe a driver is encountering unexpectedly frequent data errors or some sort of difficulty configuring or starting the device.

To deal with these types of situations, a driver can write an entry to the system error log. The Event Viewer applet one of the administrative tools on a MicrosoftWindows XP system can later display this entry so that an administrator can learn about the problem. See Figure 14-1 for an illustration of the Event Viewer. Another way to indicate sudden errors is by signaling a Windows Management Instrumentation (WMI) event. I ll discuss event logging in this section; WMI was the subject of Chapter 10.

Figure 14-1. The Windows XP Event Viewer.

Production of an administrative report from the error log involves the steps diagrammed in Figure 14-2. A driver uses the kernel-mode service function IoWriteErrorLogEntry to send an error log packet data structure to the event logger service. The packet contains a numeric code instead of message text. As time permits, the event logger writes packets to a logging file on disk. Later the Event Viewer combines the packets in the log file with message text drawn from a collection of message files to produce the report. The message files are ordinary 32-bit DLLs containing text appropriate to all possible logged events in the local language.

Your job as a driver author is to create appropriate error log packets when noteworthy events occur. As a practical matter, you ll probably also be the person who has to build the message file in at least one natural language. I ll describe both aspects of error logging in the next two sections.

Figure 14-2. Overview of event logging and reporting.

Creating an Error Log Packet

To log an error, a driver creates an IO_ERROR_LOG_PACKET data structure and sends it to the kernel-mode logger. The packet is a variable-length structure see Figure 14-3 with a fixed-size header containing general information about the event you re logging. ErrorCode indicates the event you re logging; it correlates with the message text file I ll describe shortly. After the fixed header comes an array of doublewords named DumpData, which contains Dump Data Size bytes of data that the Event Viewer will display in hexadecimal notation when asked for detailed information about this event. The size is in bytes even though the array is declared as consisting of 32-bit integers. After DumpData, the packet can contain zero or more null-terminated Unicode strings that will end up being substituted into the formatted message text by the Event Viewer. The string area begins StringOffset bytes from the start of the packet and contains NumberOfStrings strings.

Figure 14-3. The IO_ERROR_LOG_PACKET structure.

You don t have to fill in any of the fixed-header members besides the ones I just mentioned. But they add, perhaps, diagnostic utility to the log entries, which might help you track down problems.

Since the logging packet is of variable length, your first job is to determine how much memory is needed for the packet you want to create. Add the size of the fixed header to the number of bytes of DumpData to the number of bytes occupied by the substitution strings (including their null terminators). For example, the following code fragment, taken from the EVENTLOG sample in the companion content, allocates an error log packet big enough to hold 4 bytes of dump data plus a single string:

VOID LogEvent(NTSTATUS code, PDEVICE_OBJECT fdo) { PWSTR myname = L"EventLog"; ULONG packetlen = (wcslen(myname) + 1) * sizeof(WCHAR) + sizeof(IO_ERROR_LOG_PACKET) + 4; if (packetlen > ERROR_LOG_MAXIMUM_SIZE) return; PIO_ERROR_LOG_PACKET p = (PIO_ERROR_LOG_PACKET) IoAllocateErrorLogEntry(fdo, (UCHAR) packetlen); if (!p) return;  }

One trap for the unwary in this sequence is that error log packets have a maximum length of 152 bytes, the value of ERROR_LOG_MAXIMUM_SIZE. Furthermore, the size argument to IoAllocateErrorLogEntry is a UCHAR, which is only 8 bits wide. It would be very easy to ask for a packet that was, say, 400 bytes long and be embarrassed when only 144 bytes get allocated. (400 is 0x190; 144 is 0x90, which is what you d get after the truncation to 8 bits.)

Notice that the first argument to IoAllocateErrorLogEntry is the address of a device object. The name, if any, of that device object will appear in eventual log entries in place of the %1 substitution escape, which I will discuss more in the next section.

This code fragment also illustrates the action you should take in response to a problem allocating a log entry: none. It s not considered an error if you can t log some other error, so you don t want to fail any I/O request packet, generate a bug check, or do anything else that will cause your processing to terminate. In fact, you ll notice that this LogEvent helper function is VOID because no programmer should be concerned enough about whether it succeeds or fails to have to put a check in his or her code.

After successfully allocating the log packet, your next job is to initialize the structure and hand off control of it to the logger. For example:

 memset(p, 0, sizeof(IO_ERROR_LOG_PACKET)); p->ErrorCode = code; p->DumpDataSize = 4; p->DumpData[0] = <whatever>; p->StringOffset = sizeof(IO_ERROR_LOG_PACKET) + p->DumpDataSize; p->NumberOfStrings = 1; wcscpy((PWSTR) ((PUCHAR) p + p->StringOffset), myname); IoWriteErrorLogEntry(p); }

When logging a device error, you d fill in more of the fields in the header than just the error code. For information about these other fields, consult the IoAllocateErrorLogEntry function in the DDK documentation.

Error log entries remain in system memory until the logger service gets around to writing them to disk. A system crash might intervene and prevent them from showing up later when you run the Event Viewer. If you re running a kernel debugger at the time, or if you have a crash dump, the !errorlog command will let you see the queued entries.

Creating a Message File

The Event Viewer uses the ErrorCode in an error packet to locate the text of an appropriate message in one of the message files associated with your driver. A message file is just a DLL with a message resource containing text in one or more natural languages. Since a WDM driver uses the same executable file format as a DLL, the message file for your private messages can just be your driver file itself. I ll give you an introduction here to building a message file. You can find additional information on MSDN and in James D. Murray s Windows NT Event Logging (O Reilly & Associates, 1998) at pages 125-57.

Figure 14-4 illustrates the process by which you attach message text to your driver. You begin by creating a message source file with the file extension MC. Your build script uses the message compiler (MC.EXE) to translate the messages. One of the outputs of the message compiler is a header file containing symbolic constants for your messages; you include that file in your driver, and the constants end up being the ErrorCode values for the events you log. The other outputs from the message compiler are a set of intermediate files containing message text in one or more natural languages and a resource script file (.RC) that lists those intermediate files. Your build script goes on to compile the resource file and to specify the translated resources as input to the linkage editor. At the end of the build, your driver contains the message resources required to support the Event Viewer.

Figure 14-4. Creating a message file.

The following is an example of a simple message source file. (This code is part of the EVENTLOG sample program.)

 
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 Eventlog = 0x2A:FACILITY_EVENTLOG_ERROR_CODE ) 
 LanguageNames = ( English = 0x0409:msg00001 German = 0x0407:msg00002 French = 0x040C:msg00003 Spanish = 0x040A:msg00004 ) 
 MessageId = 0x0001 Facility = Eventlog Severity = Informational SymbolicName = EVENTLOG_MSG_TEST 
 Language = English %2 said, "Hello, world!" . Language = German %2 hat gesagt, Wir sind nicht mehr in Kansas! . Language = French %2 a dit, Mon chien a mang mon devoir! . Language = Spanish %2 habl , La lluvia en Espa a permanece principalmente en el llano! .

1. The MessageIdTypedef statement allows you to specify a symbol that will appear as a cast operator in the definition of each of the message identifier constants generated by this message file. For example, later we ll define a message with the symbolic name EVENT LOG_MSG_TEST. The presence of the MessageIdTypedef statement causes the header file generated by the message compiler to define this symbol as ((NTSTATUS)0x602A0001L).

2. The SeverityNames statement allows you to define your own names for the four possible severity codes. The names on the left side of the equal signs (Success, Informational, and so on) appear in the definition of messages elsewhere in this very file. The symbol after the colon ends up being defined in the header output file as equal to the number before the colon. For example, #define STATUS_SEVER ITY_SUCCESS 0x0.

3. The FacilityNames statement allows you to define your own names for the facility codes that will be included in the message identifier definitions. Here we ve said we ll use the name Eventlog in Facility statements later. The message compiler generates the statement #define FACILITY_EVENTLOG_ERROR_CODE 0x2A as a result of the third line of the FacilityNames statement.

4. The LanguageNames statement allows you to define your own names for the languages into which you ve translated your messages. Here we ve said we ll use the name English elsewhere in the file when we mean to specify LANGID 0x0409, which is Standard English in the normal Microsoft Windows NT scheme of languages. The name after the colon is the name of the intermediate binary file that receives the compiled messages for this particular language.

5. Each individual message definition contains some header statements followed by the text of the message in each of the languages supported by this message source file. The MessageId statement can specify an absolute number, as in this example, or it can specify a delta from the last message (such as MessageId = +1). You specify the facility code and severity by using names defined at the start of the message source file. You also specify, with the SymbolicName statement, a symbolic name for this message. The message compiler will define this symbol in the header file it generates.

6. For each language you specified in the LanguageNames statement, you have a message text definition like this one. It begins with a Language statement that uses one of the language names you defined. Text for the message follows. Each message text definition ends with a line containing just a period.

Within the message texts, you can indicate by means of a percent symbol followed by an integer the places where you want string substitution to occur. %1 refers to the name of the device object that generated the message. That name is an implicit parameter when you create an error log entry; you don t have to specify it directly. %2, %3, and so on correspond to the first, second, and so on Unicode strings you append to the log entry. In the example we ve been following, %2 will be replaced by EventLog because we put that string in our error packet.

This way of indicating substitution is especially useful in that you re free to put strings in the text in whatever order is appropriate for the language you re dealing with. So if your message text read The %1 %2 fox jumped over the %3 dog in English, it might read Der %3 Hund wurde vom %1 %2 Fuchs bergesprungen in German. (This is a silly example, of course. If the driver supplied quick , brown , and lazy for the substitution strings, they d appear in English in all displayed versions of the message. But I think you get the point I m trying to make about word order.)

The Event Viewer can t find your message file without a little bit of help in the form of some registry entries. A key named EventLog resides in the services branch of the Windows NT registry that is, the collection of subkeys below HKLM\System\CurrentControlSet\Services. Each driver or other service that logs events has its own subkey below that. Each service-specific subkey has values named EventMessageFile and TypesSupported. The EventMessageFile value is a REG_SZ or REG_EXPAND_SZ type that names all of the message files that the Event Viewer might need to access to format the messages your driver generates. This value would have a data string like %SystemRoot%\System32\iologmsg.dll; %SystemRoot%\System32\Drivers\EventLog.sys . IOLOGMSG.DLL contains the text of all the standard NTSTATUS.H codes, by the way. Consult the following sidebar for some tantalizing hints about how to automatically set these registry entries when you install your driver. The TypesSupported value should just be a REG_DWORD type equaling 7 to indicate that your driver can generate all possible events that is, errors, warnings, and informational messages. (The fact that you even need to specify this value seems like a historical artifact of some kind.)

A Practical Note About Message Files

Two practical facts about putting message resources into your driver are difficult to discover: how precisely you make your build script compile your messages, and how you convince the system s hardware installer to put the necessary entries in the registry so the Event Viewer will find your messages.

Like the other sample programs in this book, the EVENTLOG sample is based on a Microsoft Visual C++ 6.0 project file. I modified the project definition to include a custom build step for EVENTLOG.MC and to include the resulting RC file in the build. If you open the project settings, you ll see what I mean. It s even easier if you use the DDK BUILD utility, with which you can just list your MC file as one of the SOURCES.

Later in this book (in Chapter 15), I ll discuss the general topic of how you use an INF file to install drivers. To see how you specify your message file in an INF file, take a look at DEVICE.INF in the EVENTLOG project directory and, specifically, at its AddService statement. You ll see that the AddService line points to an EventLogLogging section that, in turn, uses the AddReg statement to point to an EventLogAddReg section. The latter section adds EventMessageFile and TypesSupported values to the service-specific subkey of the event logger service.