Article shows how to save log information in the application with implementation in different programming languages. It also describes implementation logging for the kernel mode drivers.
Table of Contents
Saving helper information of what goes in the application into a file which later helps to determine program issues called logging. I think anyone who develops an application knows about logging. There are lots of libraries and components which can be integrated into your application and used. Or you can say that the easy way is just redirecting output where it is needed and or replace debug API calls with file writing and that’s all. But that is not the correct implementation for saving data due to some reasons.
The first reason is the multithreading. As applications can have lots of threads and calls for logging data can be made from any of them. We can arrange critical sections or mutexes and perform single access for logs but the periods of accessing file writing can vary, which is not good, so we need to think about how to minimize the period of the log writing operation. And another issue which comes in the case of logging in the kernel driver is that in the kernel we have another dimension: calls for writing logs can be made at different interrupt request levels (IRQL), but the file writing API only works at the low level - passive. So the result of calling such an API at the higher level will be BSOD with IRQL NOT LESS OR EQUAL. So in the scenarios above, I suggest having one thread which will perform writing operations.
Based on the above notes, we can create a simple log saving implementation. We just arrange simple text line output, but you can add any of your own metadata along with it.
C++
typedef struct _log_record_t
{
std::string text;
}_log_record_t,*p_log_record_t;
Our aim is just to display a basis of how that should be organized for fast and safe processing. And, as was mentioned, we need to arrange a list of those structures, which will be accessed from any threads. For those needs, we define next variables:
std::list<_log_record_t> g_LogData;
std::recursive_mutex g_csLock;
std::condition_variable g_cvNotify;
std::mutex g_LockMutex;
std::atomic<bool> g_bExit;
The definitions above are in C++11. We have a list of the log records structures with type of _log_record_t. The recursive mutex variable for locking access to that list. Conditional variable for notification that list updated. The quit signal atomic variable which is used for exit threads. Log record structure is possible to extend for any other fields which may be needed for logging.
The logger function will just arrange a log record with data after putting that into a list and signal that it contains something to output.
void LogPrint(const char * format, ...)
{
if (!g_bExit.load())
{
va_list args;
__crt_va_start_a(args, format);
int _length = _vscprintf(format, args) + 1;
char * _string = (char *)malloc(_length);
if (_string)
{
memset(_string, 0, _length);
_vsprintf_p(_string, _length, format, args);
_log_record_t record;
record.text = _string;
g_csLock.lock();
g_LogData.push_back(record);
g_cvNotify.notify_all();
g_csLock.unlock();
free(_string);
}
__crt_va_end(args);
}
}
As you can see only the code part with adding record into list and update of that list notification are locked with critical section. At the same time in the logger thread, we wait for notification to appear, then get the record from the list and write it into the log file.
void LogThread()
{
while (true) {
_log_record_t record;
bool have_data;
g_csLock.lock();
if (have_data = (g_LogData.size() > 0)) {
auto it = g_LogData.begin();
record = *it;
g_LogData.erase(it);
}
g_csLock.unlock();
if (have_data) {
std::ofstream ofs("d:\\test.log",
std::ofstream::out | std::ofstream::app);
ofs << record.text << std::endl;
ofs.close();
} else {
if (g_bExit.load()) break;
std::unique_lock<std::mutex> lock(g_LockMutex);
g_cvNotify.wait(lock);
}
}
}
In thread, we are locked with critical section only actual accessing of the record list, so writing output latency does not affect all other threads which output log messages at the same time. In code, extract all available records from the list and if nothing to write, then we check for quit or new record arrives. In the example, we just open a file each time we need to write data but in real implementation, I suggest opening the file at the beginning of the log thread and with shared reading access. In that case, you avoid issues with accessing the file and will be able to view log changes during updates in real time.
To test our implementation with multithreading access, we manage processing threads which will perform sending log messages with random delay:
void ProcessThread()
{
std::srand((uint32_t)std::time(nullptr));
int period = std::rand() * 300 / RAND_MAX;
auto id = std::this_thread::get_id();
while (!g_bExit.load()) {
LogPrint("Hello from thread: %d",id);
std::this_thread::sleep_for(std::chrono::milliseconds(period));
}
}
In the main function, we start a log thread. Along with it, we also started the 100 of processing threads to feed the log. Then wait for 5 seconds and shut down.
int main(int argc, char* argv[])
{
g_bExit = false;
std::cout << "Application Started" << std::endl;
std::thread log_thread = std::thread(LogThread);
std::vector<std::thread> processes;
int threads = 100;
while (threads-- > 0) {
processes.push_back(std::thread(ProcessThread));
}
std::this_thread::sleep_for(std::chrono::seconds(5));
g_bExit = true;
g_cvNotify.notify_all();
while (processes.size()) {
auto it = processes.begin();
it->join();
processes.erase(it);
}
log_thread.join();
std::cout << "Application Exit" << std::endl;
_getch();
return 0;
}
C
The classic C way is more general. To organize a list of the _log_record_t structures, we should make a pointer to the next structure as one of the fields.
typedef struct _log_record_t
{
struct _log_record_t * next;
char * text;
}_log_record_t,*p_log_record_t;
For the organizing queue, as we need to put records to the tail and pick them from the head, the actual list definition looks next.
typedef struct
{
struct _log_record_t * head;
struct _log_record_t * tail;
}_log_list_t,*p_log_list_t;
Variables which we need to organize processing.
_log_list_t g_LogData;
CRITICAL_SECTION g_csLock;
HANDLE g_evNotify;
HANDLE g_evQuit;
Here, we have two events: one for quit and another one for queue signal. Critical section for locking our list accessing.
Implementation of adding records to the processing queue differs a bit, as we organize our own list.
void LogPrint(const char * format, ...)
{
if (WAIT_TIMEOUT == WaitForSingleObject(g_evQuit,0)) {
va_list args;
__crt_va_start_a(args, format);
int _length = _vscprintf(format, args) + 2;
char * _string = (char *)malloc(_length);
if (_string) {
__try {
memset(_string, 0, _length);
_vsprintf_p(_string, _length, format, args);
if (_string[_length - 1] != '\n') strcat_s(_string,_length,"\n");
_log_record_t * record = (_log_record_t*)malloc(sizeof(_log_record_t));
if (record) {
memset(record, 0x00, sizeof(_log_record_t));
record->text = _string;
record->next = NULL;
_string = NULL;
EnterCriticalSection(&g_csLock);
__try {
_log_record_t * tail = g_LogData.tail;
if (tail) {
tail->next = record;
}
else {
g_LogData.head = record;
}
g_LogData.tail = record;
SetEvent(g_evNotify);
}
__finally {
LeaveCriticalSection(&g_csLock);
}
}
} __finally {
if (_string) free(_string);
}
}
__crt_va_end(args);
}
}
We add new records to the list and the tail field of the g_LogData variable always points to the last record, at the same time, the head field points to the first one. Once the record is added, we signal the notification event.
DWORD WINAPI LogThread(PVOID p)
{
UNREFERENCED_PARAMETER(p);
while (TRUE) {
_log_record_t * record = NULL;
EnterCriticalSection(&g_csLock);
record = g_LogData.head;
if (record) {
g_LogData.head = record->next;
if (g_LogData.tail == record) {
g_LogData.tail = NULL;
}
}
LeaveCriticalSection(&g_csLock);
if (record) {
if (record->text) {
HANDLE hFile = CreateFileA("d:\\test.log",FILE_GENERIC_WRITE,
FILE_SHARE_READ,NULL,OPEN_ALWAYS,FILE_ATTRIBUTE_NORMAL,NULL);
if (hFile != INVALID_HANDLE_VALUE) {
DWORD written = 0;
SetFilePointer(hFile,0,NULL,FILE_END);
WriteFile(hFile,record->text,(DWORD)strlen(record->text),&written,NULL);
CloseHandle(hFile);
}
}
if (record->text) {
free(record->text);
}
free(record);
} else {
HANDLE hHandles[2];
hHandles[0] = g_evNotify;
hHandles[1] = g_evQuit;
if (WAIT_OBJECT_0 != WaitForMultipleObjects(
_countof(hHandles), hHandles, FALSE, INFINITE)) {
break;
}
}
}
return 0;
}
The log thread which dequeues the records and writes them into the file waits for one of the two events to be signaled. Either a new record arrived or exits. We pick up records from the list head pointer field and assign it to the next field of the extracted record. The last record has NULL on the last record and if the extracted pointer equals the list tail, we set it to NULL also. Only dequeue records operation is locked with the critical section. With our own list implementation, we have a good performance advantage here.
The processing thread for output log messages:
DWORD WINAPI ProcessThread(PVOID p)
{
UNREFERENCED_PARAMETER(p);
srand(GetTickCount());
int period = rand() * 300 / RAND_MAX;
DWORD id = GetCurrentThreadId();
while (TRUE) {
LogPrint("Hello from thread: %d",id);
if (WAIT_OBJECT_0 == WaitForSingleObject(g_evQuit,period)) break;
}
return 0;
}
Main function with similar functionality: starting 100 processing threads which output log messages at the same time, and exiting after 5 seconds.
int main(int argc, char* argv[])
{
g_LogData.head = NULL;
g_LogData.tail = NULL;
g_evQuit = CreateEvent(NULL,TRUE,FALSE,NULL);
g_evNotify = CreateEvent(NULL,FALSE,FALSE,NULL);
InitializeCriticalSection(&g_csLock);
printf("Application Started\n");
HANDLE log_thread = CreateThread(NULL,0,LogThread,NULL,0,NULL);
int threads = 100;
HANDLE * processes = (HANDLE *)malloc(threads * sizeof(HANDLE));
for (int i = 0; i < threads; i++) {
processes[i] = CreateThread(NULL, 0, ProcessThread, NULL, 0, NULL);
}
Sleep(5000);
SetEvent(g_evQuit);
for (int i = 0; i < threads; i++) {
WaitForSingleObject(processes[i], INFINITE);
CloseHandle(processes[i]);
}
free(processes);
WaitForSingleObject(log_thread,INFINITE);
CloseHandle(log_thread);
CloseHandle(g_evQuit);
CloseHandle(g_evNotify);
DeleteCriticalSection(&g_csLock);
assert(g_LogData.head == NULL);
_log_record_t * record = g_LogData.head;
while (record) {
_log_record_t * temp = record->next;
if (record->callback) record->callback(record);
if (record->text) free(record->text);
free(record);
record = temp;
}
printf("Application Exit\n");
_getch();
return 0;
}
C#
In C# declaration of the log record structure is not much different from C++.
class log_record
{
public string text;
}
As for the variables: we also have two events, one for exit and another one for notification, log records we will be storing in the generic list, and for locking list access, there will be a simple object.
static List<log_record> g_LogData = new List<log_record>();
static object g_csLock = new object();
static EventWaitHandle g_evNotify = new AutoResetEvent(false);
static EventWaitHandle g_evQuit = new ManualResetEvent(false);
Adding record to the list in C# is done most simply, as it is not necessary to have string formatting.
static void LogPrint(string text)
{
if (!g_evQuit.WaitOne(0))
{
log_record record = new log_record();
record.text = text;
lock (g_csLock)
{
g_LogData.Add(record);
g_evNotify.Set();
}
}
}
We are using lock C# keyword on the threading critical code part. This can be replaced with the Monitor.Enter() and Monitor.Exit() methods in other .NET languages. The log output thread has the same logic as implementations in C++ or C.
static void LogThread()
{
while (true)
{
log_record record = null;
lock (g_csLock)
{
if (g_LogData.Count > 0)
{
record = g_LogData[0];
g_LogData.RemoveAt(0);
}
}
if (record != null)
{
TextWriter tw = new StreamWriter("d:\\test.log", true, Encoding.ASCII);
try
{
tw.WriteLine(record.text);
}
finally
{
tw.Dispose();
}
}
else
{
if (0 != WaitHandle.WaitAny(new WaitHandle[] {
g_evNotify, g_evQuit
}
)) break;
}
}
}
Thread implementation for output log messages.
static void ProcessThread()
{
int id = Thread.CurrentThread.ManagedThreadId;
int period = (new Random(id)).Next(20,1000);
while (true)
{
LogPrint(string.Format("Hello from thread: {0}",id));
if (g_evQuit.WaitOne(period)) break;
}
}
And the main function.
static void Main(string[] args)
{
Console.WriteLine("Application Started");
Thread log_thread = new Thread(LogThread);
log_thread.Start();
List<Thread> processes = new List<Thread>();
int threads = 100;
while (threads-- > 0) {
var t = new Thread(ProcessThread);
t.Start();
processes.Add(t);
}
Thread.Sleep(5000);
g_evQuit.Set();
while (processes.Count > 0) {
processes[0].Join();
processes.RemoveAt(0);
}
log_thread.Join();
Console.WriteLine("Application Exit");
Console.ReadKey();
}
As you can see, the implementations on different programming languages of this article look mostly similar. The result of the test.log file after execution of the code:
It is possible that we supply some additional memory, object or COM object for providing some additional information for logging. And that memory or object should be freed properly. Of course in .NET, it may be handled automatically but the question with the COM objects remains opened.
C++
We design a logger function to accept the callback function which will be called once the record is written to the log, so resources may be freed. Also, we pass the user context as an argument which will be stored in the record structure. So it will look as follows:
typedef struct _log_record_t
{
std::string text;
void * ctx;
std::function<void(_log_record_t *)> callback;
}_log_record_t,*p_log_record_t;
For the callback type, we are using the function template. The extended logger function will look next.
void LogPrintEx(void * ctx, std::function<void(_log_record_t *)> callback,
const char * format, ...)
{
if (!g_bExit.load())
{
va_list args;
__crt_va_start_a(args, format);
int _length = _vscprintf(format, args) + 1;
char * _string = (char *)malloc(_length);
if (_string)
{
memset(_string, 0, _length);
_vsprintf_p(_string, _length, format, args);
_log_record_t record;
record.text = _string;
record.ctx = ctx;
record.callback = callback;
g_csLock.lock();
g_LogData.push_back(record);
g_cvNotify.notify_all();
g_csLock.unlock();
free(_string);
}
__crt_va_end(args);
}
else {
if (callback) {
_log_record_t record;
record.ctx = ctx;
callback(&record);
}
}
}
In the function above, we design that the record may not be placed into the log queue due to the signal of exit. In that case, we should manually free resources and call the callback manually to free extra memory.
In the log output thread, we just call the callback once the record is written.
if (record.callback) {
record.callback(&record);
}
In the callback function, the user context data can be accessed as the ctx field of the record structure which passed as an argument.
C
In this implementation, we have only differences with the callback type declaration. Instead of a usage template, we have our own function type.
typedef void (* LogPrintCallback)(struct _log_record_t * record);
typedef struct _log_record_t
{
struct _log_record_t * next;
char * text;
PVOID ctx;
LogPrintCallback callback;
}_log_record_t,*p_log_record_t;
The extended logger function also accepts the callback and context arguments like we did in the previous implementation.
C#
In .NET, we can use any existing function delegate as the callback. At least we need only one argument of the object which can be casted into our record structure. For example, we just choose an existing delegate for the EventHandler. In that case, our record structure will be next.
class log_record
{
public string text;
public object ctx;
public EventHandler callback;
}
In the logger function, we pass that delegate and the context object.
static void LogPrintEx(string text, EventHandler callback, object ctx)
{
if (!g_evQuit.WaitOne(0))
{
log_record record = new log_record();
record.text = text;
record.callback = callback;
record.ctx = ctx;
lock (g_csLock)
{
g_LogData.Add(record);
g_evNotify.Set();
}
}
else
{
if (callback != null)
{
log_record record = new log_record();
record.text = text;
record.callback = callback;
record.ctx = ctx;
callback(record,EventArgs.Empty);
}
}
}
The callback will be invoked in the logger thread.
if (record.callback != null)
{
record.callback(record,EventArgs.Empty);
}
In the callback function, we should cast an object into our record structure type.
In some cases, we may need to know what exactly is written before something happens in our application. For that, we can use a previously designed callback. We design it so that the context parameter for that callback is the notification handle. That handle sets into signaled state once the callback is executed. In the thread which is output log message, we just need to wait for this notification to become the signaled state.
C++
In C++, we will use the conditional variable for this. We are also modifying the record structure by adding the pointer to the notification variable.
typedef struct _log_record_t
{
std::string text;
union {
std::condition_variable * notify;
void * ctx;
};
std::function<void(_log_record_t *)> callback;
}_log_record_t,*p_log_record_t;
This is done as the union as we can use either context or the notification. In the callback function, we signal the conditional variable.
void LogPrintNotifyCallback(_log_record_t * record) {
if (record->notify) {
record->notify->notify_all();
}
}
The call of the log output we design with the macro in which we just call the function created previously and pass our callback implementation. As the notification in record is designed within the union, along with the context, then it will be placed into the same address space.
#define LogPrint2(notify,format,...) LogPrintEx( \
(void*)notify,LogPrintNotifyCallback,format,__VA_ARGS__)
Test code looks next.
std::condition_variable notify;
LogPrint2(¬ify,"This text we are waiting to be written into the log");
std::mutex mtx;
std::unique_lock<std::mutex> lock(mtx);
notify.wait(lock);
C
In C for the notification, we use the auto reset event. And put it also to the record structure as the union.
typedef struct _log_record_t
{
struct _log_record_t * next;
char * text;
union {
PVOID ctx;
HANDLE notify;
} ;
LogPrintCallback callback;
}_log_record_t,*p_log_record_t;
The callback implementation.
void LogPrintNotifyCallback(_log_record_t * record) {
if (record->notify) {
SetEvent(record->notify);
}
}
The macro definition for the usage is the same as for C++ implementation. The test code also looks similar.
HANDLE hNotify = CreateEvent(NULL, FALSE, FALSE, NULL);
LogPrint2(hNotify, "This text we are waiting to be written into the log");
if (WAIT_OBJECT_0 == WaitForSingleObject(hNotify, INFINITE)) {
printf("Notification Signaled\n");
}
CloseHandle(hNotify);
C#
In C#, we don’t need to change the context variable in the log record. As we can just do boxing and unboxing the object. So the structure remains the same. The callback will be next.
static void LogPrintNotifyCallback(object sender, EventArgs e)
{
if (sender != null
&& (sender is log_record)
&& (((log_record)sender).ctx is EventWaitHandle))
{
((EventWaitHandle)((log_record)sender).ctx).Set();
}
}
Instead of the macro implementation in C#, we just create the function with different arguments.
static void LogPrint2(string text,EventWaitHandle notify)
{
LogPrintEx(text,LogPrintNotifyCallback, notify);
}
The code for test.
EventWaitHandle evNotify = new AutoResetEvent(false);
LogPrint2("This text we are waiting to be written into the log", evNotify);
if (evNotify.WaitOne())
{
Console.WriteLine("Notification Signaled");
}
evNotify.Dispose();
You can see the results in the next screen shot. If you set breakpoint to the callback function, you see that the main thread waits for the notification and the callback is executed. After notification signals, the main function is continued.
Okay, we found out how to organize log writing for particular applications, but now you can ask: “there is a way of writing log in a driver”? And here it is. Implementation in a driver has the same logic as we discussed earlier, but lots of things look a bit different - as it is a kernel. As I already mentioned, in the kernel, we have another dimension IRQL. All applications under user mode are executed at one level which is “0” and called passive. But driver code can be executed from a higher level, more of that the code of the driver as long as the allocated data can be in paged memory pool or non paged. Non paged code and data are always resident and the paged code may be stored on disk due memory pressure and to execute such code or accessing the memory. For in the system were added the page files. You can find such a file named pagefile.sys in the root on your system drive. Make sure that you enable the option to display hidden files. And the file accessing in the system is done on a passive level which is not possible on higher IRQL and the result…,right - BSOD. Higher IRQL levels have higher privileges to execution, and the code at the “passive” stops until code at higher level finishes. This is a simple description for understanding what needs to be handled, as on levels higher than “passive”, the code is also executed and it also may need to provide some log messages.
Based on the notes above, let's see how to make the implementation. First, like in the previous description, we define the variables and structures and variables. Our log record is similar and contains only text information, the “Entry” field required to organize the list.
typedef struct
{
LIST_ENTRY Entry;
CHAR * Text;
}LOG_RECORD, *PLOG_RECORD;
The variables which are declared in previous samples we put into structure. That needs to be allocated in the non paged memory pool, due the already mentioned reason.
typedef struct
{
KEVENT EvQuit;
KEVENT EvHaveData;
PFILE_OBJECT ThreadObject;
KMUTEX ListLock;
LIST_ENTRY List;
} DRIVER_LOG;
And the other variables:
DRIVER_LOG * s_pLog = NULL;
KSPIN_LOCK s_LogSpinLock;
First one is the allocated pointer to the log and the critical section for accessing the log pointer. For information: the code which is locked with a spin lock critical section raises execution to dispatch IRQL.
The log printing function implementation looks a bit differ but doing the same things like in user mode application. We need to keep in mind that this function will be called from any IRQL levels.
void LogPrint(const char * format, ...)
{
if (format) {
KIRQL irqlsp;
va_list args;
va_start(args, format);
int _length = 1024 + 3;
char * _string = (char *)ExAllocatePool(NonPagedPool, _length);
if (_string) {
__try {
memset(_string, 0, _length);
vsprintf_s(_string, _length - 3, format, args);
strcat_s(_string,_length,"\n");
KeAcquireSpinLock(&s_LogSpinLock, &irqlsp);
if (s_pLog) {
KIRQL irql = KeGetCurrentIrql();
LARGE_INTEGER time_out = {0};
if (STATUS_TIMEOUT == KeWaitForSingleObject(&s_pLog->EvQuit, Executive,
KernelMode, FALSE, &time_out)) {
PLOG_RECORD rec = (PLOG_RECORD)ExAllocatePool(NonPagedPool,
sizeof(LOG_RECORD));
if (rec) {
memset(rec, 0x00, sizeof(LOG_RECORD));
rec->Text = _string;
if (STATUS_SUCCESS == KeWaitForSingleObject(
&s_pLog->ListLock, Executive, KernelMode, FALSE,
irql <= APC_LEVEL ? NULL : &time_out)) {
_string = NULL;
InsertTailList(&s_pLog->List, &(rec->Entry));
KeSetEvent(&s_pLog->EvHaveData, IO_NO_INCREMENT, FALSE);
KeReleaseMutex(&s_pLog->ListLock, FALSE);
}
else {
ExFreePool(rec);
}
}
}
}
KeReleaseSpinLock(&s_LogSpinLock, irqlsp);
}
__finally {
if (_string) ExFreePool(_string);
}
}
va_end(args);
}
}
In logger thread, we also have the same functionality as in user mode application, the actual log records writing just split into separate functions:
void LogThread(PVOID Context)
{
PAGED_CODE();
DRIVER_LOG * log = (DRIVER_LOG *)Context;
PVOID hEvents[2] = { 0 };
hEvents[0] = &log->EvHaveData;
hEvents[1] = &log->EvQuit;
while (TRUE) {
NTSTATUS Status = KeWaitForMultipleObjects(2, hEvents,
WaitAny, Executive, KernelMode, FALSE, NULL, NULL);
if (Status == STATUS_WAIT_0) {
WritePendingRecords(log);
} else {
break;
}
}
KeSetEvent(&log->EvQuit, IO_NO_INCREMENT, FALSE);
PsTerminateSystemThread(STATUS_SUCCESS);
}
The WritePendingRecords performs writing all records from a list into a file. Getting records from list looks next:
PLOG_RECORD rec = NULL;
if (STATUS_SUCCESS == KeWaitForSingleObject(&log->ListLock,
Executive, KernelMode, FALSE, 0)) {
if (!IsListEmpty(&log->List)) {
PLIST_ENTRY entry = log->List.Flink;
if (entry) {
rec = CONTAINING_RECORD(entry, LOG_RECORD, Entry);
RemoveEntryList(entry);
}
}
if (!rec) {
KeResetEvent(&log->EvHaveData);
}
KeReleaseMutex(&log->ListLock, FALSE);
}
And the file writing is done:
if (rec->Text) {
HANDLE hFile = NULL;
UNICODE_STRING FileName;
IO_STATUS_BLOCK iosb;
OBJECT_ATTRIBUTES Attributes;
RtlInitUnicodeString(&FileName, L"\\DosDevices\\d:\\DriverLog.log");
InitializeObjectAttributes(&Attributes, &FileName,
(OBJ_CASE_INSENSITIVE | OBJ_KERNEL_HANDLE), NULL, NULL);
if (STATUS_SUCCESS == ZwCreateFile(
&hFile,
GENERIC_WRITE | SYNCHRONIZE,
&Attributes,
&iosb,
0,
FILE_ATTRIBUTE_NORMAL,
FILE_SHARE_READ,
FILE_OPEN_IF,
FILE_NON_DIRECTORY_FILE | FILE_SYNCHRONOUS_IO_NONALERT,
NULL,
0
)) {
LARGE_INTEGER pos = {0};
FILE_STANDARD_INFORMATION info;
if (STATUS_SUCCESS == ZwQueryInformationFile(hFile, &iosb, &info,
sizeof(info), FileStandardInformation))
{
pos = info.EndOfFile;
}
ZwWriteFile(hFile, NULL, NULL, NULL, &iosb,
rec->Text, (ULONG)strlen(rec->Text), &pos, NULL);
ZwClose(hFile);
}
ExFreePool(rec->Text);
}
We will store log records into a file with name DriverLog.log in the root of drive D:. As you can see in kernel mode, simple operation requires more lines of code compared to user mode application. Now we need to define functions starting and stopping our log. Starting log, we perform on driver entry, and stopping is done on driver unloading message.
NTSTATUS StartLog()
{
NTSTATUS Status = STATUS_SUCCESS;
DRIVER_LOG * log = NULL;
KIRQL irql;
KeAcquireSpinLock(&s_LogSpinLock, &irql);
if (!s_pLog) {
s_pLog = (DRIVER_LOG *)ExAllocatePool(NonPagedPool, sizeof(DRIVER_LOG));
if (s_pLog) {
memset(s_pLog, 0x00, sizeof(DRIVER_LOG));
KeInitializeMutex(&s_pLog->ListLock, 0);
KeInitializeEvent(&s_pLog->EvQuit, NotificationEvent, TRUE);
KeInitializeEvent(&s_pLog->EvHaveData, NotificationEvent, FALSE);
InitializeListHead(&s_pLog->List);
log = s_pLog;
}
}
KeReleaseSpinLock(&s_LogSpinLock, irql);
if (log) {
HANDLE hThread;
KeResetEvent(&log->EvQuit);
Status = PsCreateSystemThread(&hThread, 0, NULL, NULL, NULL, LogThread, (PVOID)log);
if (NT_SUCCESS(Status)) {
Status = ObReferenceObjectByHandle(hThread, GENERIC_READ | GENERIC_WRITE,
NULL, KernelMode, (PVOID *)&log->ThreadObject, NULL);
}
if (!NT_SUCCESS(Status)) {
KeSetEvent(&log->EvQuit, IO_NO_INCREMENT, FALSE);
}
}
LogPrint("Driver Log Started '%S'",DRIVER_NAME);
return Status;
}
NTSTATUS StopLog()
{
NTSTATUS Status = STATUS_SUCCESS;
DRIVER_LOG * log = NULL;
KIRQL irql;
LogPrint("Driver Log Stopped '%S'",DRIVER_NAME);
KeAcquireSpinLock(&s_LogSpinLock, &irql);
log = s_pLog;
s_pLog = NULL;
KeReleaseSpinLock(&s_LogSpinLock, irql);
if (log) {
KeSetEvent(&log->EvQuit, IO_NO_INCREMENT, FALSE);
if (log->ThreadObject) {
KeWaitForSingleObject(log->ThreadObject, Executive, KernelMode, FALSE, NULL);
ObDereferenceObject(log->ThreadObject);
}
WritePendingRecords(log);
ExFreePool(log);
}
return Status;
}
I will not describe any other parts as that is not the target, just say that I put some call of the log writing in driver routines to see how it will be.
Now we need a test application which will perform driver install and loading then unloading and uninstalling. Installing and uninstalling operations performed like for regular windows service applications with usage of service control manager APIs. And loading the driver made with a particular CreateFile API. After execution of that application, we can see the following log messages:
Wow, our log is working!!! The driver code also contains some DbgPrint API calls for tracing, which were mentioned in previous topics. For example in the code, you can find:
DbgPrint("DriverLog: DriverEntry\n");
So you will be able to see debug output strings from the driver in DbgView, or in sample applications from previous articles. Those trace messages started with DriverLog: prefix:
In the log file above, messages come just from basic driver functionality which runs out at passive mode IRQL and I were promising that it will work under higher level. So let’s arrange a DPC timer in a driver and call logging from it callback, it will be executed at dispatch level. We will add the ability of starting and stopping that timer from our user mode application. First, we define structure for our DPC. Fields I describe in the code.
typedef struct LOG_DPC
{
BOOLEAN Stop;
KEVENT EvStopped;
KDPC DPC;
KTIMER Timer;
}LOG_DPC;
And the variable of that structure type:
LOG_DPC * s_pDPC = NULL;
Initialization of that variable we add into the driver entry routine.
s_pDPC = (LOG_DPC*)ExAllocatePool(NonPagedPool,sizeof(LOG_DPC));
if (s_pDPC) {
s_pDPC->Stop = TRUE;
KeInitializeEvent(&s_pDPC->EvStopped, NotificationEvent, TRUE);
KeInitializeTimer(&s_pDPC->Timer);
KeInitializeDpc(&s_pDPC->DPC,(PKDEFERRED_ROUTINE)(TimerRoutine),s_pDPC);
}
Here you can see that DPC initialized with the TimerRoutine. This callback will be called on timer elapsed. In that callback, we output log text and reschedule the timer if exit wasn’t requested from the driver:
void TimerRoutine(IN PKDPC Dpc,IN LOG_DPC *pThis,
IN PVOID SystemArg1,IN PVOID SystemArg2)
{
UNREFERENCED_PARAMETER(Dpc);
UNREFERENCED_PARAMETER(SystemArg1);
UNREFERENCED_PARAMETER(SystemArg2);
if (!pThis->Stop) {
LogPrint("Hello From DPC!!! IRQL: %d", KeGetCurrentIrql());
LARGE_INTEGER time;
KeQuerySystemTime(&time);
time.QuadPart += 10000000;
KeSetTimer(&pThis->Timer, time, &pThis->DPC);
} else {
KeSetEvent (&pThis->EvStopped, IO_NO_INCREMENT, FALSE);
}
}
As mentioned, starting our timer we will make from our test application. To communicate with the driver from user mode, we will be using Device Input and Output Control (IOCTL) which is provided by DeviceIoControl function. First prepare the IOCTL message:
#define IOCTL_DRIVERLOG_ENABLE_DPC_TIMER \
CTL_CODE( FILE_DEVICE_UNKNOWN, 0x801, METHOD_BUFFERED, FILE_ANY_ACCESS )
After design callback for handling IOCTL requests from our application:
DriverObject->MajorFunction[ IRP_MJ_DEVICE_CONTROL ] = DriverDispatchDeviceControl;
In the dispatch handler, we add functionality for our control code.
PIO_STACK_LOCATION Stack = IoGetCurrentIrpStackLocation( Irp );
ULONG ControlCode = Stack->Parameters.DeviceIoControl.IoControlCode;
switch (ControlCode) {
case IOCTL_DRIVERLOG_ENABLE_DPC_TIMER:
{
DbgPrint("DriverLog: IOCTL_DRIVERLOG_ENABLE_DPC_TIMER \n");
Irp->IoStatus.Status = STATUS_SUCCESS;
Irp->IoStatus.Information = 0;
if (Irp->AssociatedIrp.SystemBuffer) {
}
}
break;
}
We will be able to pass a boolean variable on input with a type of BOOL which will command the driver to start or stop the DPC timer depending on its value. On output, we provide the state of the DPC timer: is it running or not, also as a boolean variable with type of BOOL.
LARGE_INTEGER time_out = {0};
ULONG32 bStopped = (STATUS_SUCCESS == KeWaitForSingleObject(&s_pDPC->EvStopped,
Suspended,KernelMode,FALSE,&time_out));
if (Stack->Parameters.DeviceIoControl.InputBufferLength >= sizeof(ULONG32)) {
PULONG32 p = (PULONG32)Irp->AssociatedIrp.SystemBuffer;
if (bStopped) {
if (*p) {
LogPrint("Start DPC");
s_pDPC->Stop = FALSE;
KeResetEvent(&s_pDPC->EvStopped);
LARGE_INTEGER time;
KeQuerySystemTime(&time);
time.QuadPart += 1000000;
KeSetTimer(&s_pDPC->Timer, time, &s_pDPC->DPC);
}
} else {
if (!*p) {
s_pDPC->Stop = TRUE;
KeWaitForSingleObject(&s_pDPC->EvStopped, Suspended,KernelMode,FALSE,NULL);
LogPrint("Stop DPC");
}
}
}
So we are checking if our timer is active or not by querying the state of the event. And if it stopped and the user requested to start, then we started the timer, otherwise if stop requested and the timer was active, then we would stop DPC. The output data handled in case of output buffer passed:
if (Stack->Parameters.DeviceIoControl.OutputBufferLength >= sizeof(ULONG32)) {
PULONG32 p = (PULONG32)Irp->AssociatedIrp.SystemBuffer;
*p = bStopped ? 1 : s_pDPC->Stop;
Irp->IoStatus.Information = sizeof(ULONG32);
}
In application, we should add calling of starting and stopping DPC once open the driver handle:
hDevice = CreateFile(FileName, GENERIC_WRITE, 0,
NULL, OPEN_EXISTING, FILE_ATTRIBUTE_NORMAL, NULL);
DWORD dwBytesReturned = 0;
BOOL bEnabledDpc = TRUE;
if (DeviceIoControl(hDevice, IOCTL_DRIVERLOG_ENABLE_DPC_TIMER,
&bEnabledDpc, sizeof(bEnabledDpc), NULL, 0, &dwBytesReturned, NULL))
{
_tprintf(_T("DeviceIOControl DPC Started\n"));
}
bEnabledDpc = FALSE;
if (DeviceIoControl(hDevice, IOCTL_DRIVERLOG_ENABLE_DPC_TIMER,
&bEnabledDpc, sizeof(bEnabledDpc), NULL, 0, &dwBytesReturned, NULL))
{
_tprintf(_T("DeviceIOControl DPC Stopped\n"));
}
We also add 5 seconds delay between those calls and see what will be in a log file:
In the system, the logger functionality is done as a service with some way of inter-process communication (IPC). So any applications can access the system log mechanism with the API designed for that. The system logger technologies, which I describe here below, have system background as windows service or a driver, or even both which communicate with each other. Actually, the driver is also a service which is running in kernel mode and we can use it to save the log records. For that purpose, we define another IOCTL message with the ability to pass the text message to the driver, and the driver writes it into the log file.
#define IOCTL_DRIVERLOG_SEND_TEXT_TO_LOG \
CTL_CODE( FILE_DEVICE_UNKNOWN, 0x802, METHOD_BUFFERED, FILE_ANY_ACCESS )
In the driver, we implement handling that message in the prepared IRP_MJ_DEVICE_CONTROL dispatch routine.
if (Irp->AssociatedIrp.SystemBuffer) {
size_t cch = Stack->Parameters.DeviceIoControl.InputBufferLength;
if (cch) {
cch += 1;
char * text = (char *)ExAllocatePool(NonPagedPool, cch);
if (text) {
memset(text, 0x00, cch);
memcpy(text, Irp->AssociatedIrp.SystemBuffer, cch - 1);
LogPrint(text);
ExFreePool(text);
if (Stack->Parameters.DeviceIoControl.OutputBufferLength >= sizeof(ULONG32)) {
PULONG32 p = Irp->AssociatedIrp.SystemBuffer;
*p = (ULONG32)(cch - 1);
Irp->IoStatus.Information = sizeof(ULONG32);
}
}
}else {
LogPrint("No text to log");
Irp->IoStatus.Status = STATUS_BUFFER_TOO_SMALL;
}
}else {
LogPrint("NULL buffer as argument");
Irp->IoStatus.Status = STATUS_FWP_NULL_POINTER;
}
So we simply get data from the input buffer and pass it to the log print function, on output we just pass the processed data length. Add code for passing text code looks:
char text[] = "This log text is sent from an application";
ULONG nProcessedLength = 0;
if (DeviceIoControl(
hDevice, IOCTL_DRIVERLOG_SEND_TEXT_TO_LOG, text, (DWORD)strlen(text), &nProcessedLength, sizeof(nProcessedLength), &dwBytesReturned, NULL ) == 0) {
_tprintf(_T("DeviceIOControl Failed %d\n"),GetLastError());
result = 5;
}
After execution, we got in a log file:
We can try to add multiple threads which will perform output text messages to a driver. We add a multithreaded code part of the ProcessThread from previous examples and modify it:
DWORD WINAPI ProcessThread(PVOID p)
{
TCHAR * FileName = (TCHAR *)p;
HANDLE hDevice = CreateFile(FileName, 0, 0, NULL, OPEN_EXISTING,
FILE_ATTRIBUTE_NORMAL, NULL);
if (hDevice != INVALID_HANDLE_VALUE)
{
srand(GetTickCount());
int period = rand() * 300 / RAND_MAX;
DWORD id = GetCurrentThreadId();
char text[200] ;
while (TRUE) {
DWORD dwBytesReturned;
sprintf_s(text,"Driver Hello from thread: %d", id);
if (!DeviceIoControl(hDevice,IOCTL_DRIVERLOG_SEND_TEXT_TO_LOG,
text,(DWORD)strlen(text),NULL,0,&dwBytesReturned,NULL)) {
_tprintf(_T("DeviceIOControl Failed %d\n"), GetLastError());
break;
}
if (WAIT_OBJECT_0 == WaitForSingleObject(g_hQuit, period)) break;
}
CloseHandle(hDevice);
}
return 0;
}
From code, you can see that we are opening the handle of the driver in each thread and passing messages until the thread quits. The resulted log file contains:
If we comment in the driver test application code path where we uninstall the driver, then we can start many instances of our test application and they will use the same driver instance for writing log messages which are passed from those running applications.
We can manage our driver to handle file writing operations. In the application, we just call the WriteFile API with the driver handle. The changes should be made on the driver side only. In the previous article, you saw that some drivers failed with the writing operation and we design to use IOCTL. At the start of the planning IO in the driver, we should decide which processing way of data buffers we are going to use. It is similar to IOCTL but the buffer access operation is set up with the driver flags during the initialization.
DeviceObject->Flags |= DO_DIRECT_IO;
As we use buffered IO in our IOCTL implementation, so for the writing operation we are setting it to direct IO. Next, we should add the IRP_MJ_WRITE dispatch handler routine.
NTSTATUS DriverDispatchWrite(IN PDEVICE_OBJECT pDO, IN PIRP Irp)
{
PAGED_CODE();
UNREFERENCED_PARAMETER (pDO);
NTSTATUS Status = STATUS_SUCCESS;
PIO_STACK_LOCATION Stack = IoGetCurrentIrpStackLocation( Irp );
PVOID p = MmGetSystemAddressForMdlSafe(Irp->MdlAddress, NormalPagePriority);
if (p) {
Irp->IoStatus.Status = STATUS_SUCCESS;
size_t cch = Stack->Parameters.Write.Length;
if (cch) {
cch += 1;
char * text = (char *)ExAllocatePool(NonPagedPool, cch);
if (text) {
memset(text, 0x00, cch);
memcpy(text, p, cch - 1);
LogPrint(text);
ExFreePool(text);
Irp->IoStatus.Information = cch;
}
else {
Irp->IoStatus.Status = STATUS_NO_MEMORY;
}
}
}
else {
Irp->IoStatus.Status = STATUS_INVALID_PARAMETER;
}
IoCompleteRequest( Irp, IO_NO_INCREMENT );
return Status;
}
The direct IO is mostly used for large data transfer which improves the driver performance, as in such cases the data is not copied into the intermediate buffer and we receive it with the MDL. To access the data pointer, we call MmGetSystemAddressForMdlSafe and process the returned pointer as usual. In our implementation, we copy input data into a separate buffer with zero-ending and call our log function, like we did with IOCTL implementation.
In the test application, if we are going to use the WriteFile API for the device then it is required to specify write access GENERIC_WRITE during the call of the CreateFile API.
hDevice = CreateFile(FileName, GENERIC_WRITE, 0,
NULL, OPEN_EXISTING, FILE_ATTRIBUTE_NORMAL, NULL);
Test code for usage of the WriteFile API looks simpler than for IOCTL.
char text[] = "This log text is sent from an application by the WriteFile API";
ULONG nProcessedLength = 0;
if (!WriteFile(hDevice,text,(DWORD)strlen(text),&nProcessedLength,NULL)) {
_tprintf(_T("WriteFile Failed %d\n"),GetLastError());
result = 6;
}
else
{
_tprintf(_T("WriteFile Processed Text Length: %d\n"),nProcessedLength);
}
After execution, you can see the result in the output file.
It is not limited to just passing the text string, you also can design for any other additional data fields and structures. It is also possible to add notifications even if a new log record arrives and allows applications to subscribe to it. Such things are also designed in the system. Those applications which just provide the log messages are called Providers. Our driver controls the logging: in our case, writing those messages into a file - so it is called a Controller. The applications which read log messages and/or subscribe to log messages notifications are called Consumers.
The application's output path is the root of drive D: it is hardcoded with filenames, but you can change that in source code. If you want to try out the driver for this part of an article. The sample driver can be compiled from the sources. It is configured to compile with the WDK toolset. During build, it creates the test certificate DriverLog.cer and signs the driver. To be able to use the driver, you need to install that certificate on your system and enable test mode, or disable driver signing checking on the system.
- 18th August, 2023: Initial version
