Error logging

How to implement error logging and custom panic logging in Rust

Error logging

If you’re following my Rust driver development series, don’t skip this — the second half of this post deals with logging messages in the driver,

Logging messages is crucial for large-scale applications, but it can feel tedious. I’ve implemented usermode logging and will do the same for the driver when the time comes.

If you want to see my driver implementation of error logging without reading this page, or to use it as a reference, check it here (note that link may be invalid over time as my repo grows).

Usermode logging

I considered multiple approaches:

1. Macro + global variable
2. Function + global variable
3. Macro that resolves the log file path at runtime
4. Function that resolves the log file path at runtime
5. A struct, an impl, and a function

I chose #5. This approach lets me avoid heavy use of global variables or Arc. By storing the resolved log path in a Log object, I only resolve the path once rather than every time I log a message.

Essentially, I have chosen for my log file to live in %AppData/Sanctum/logs. Resolving this path takes time (albeit a short one), but do we want to waste computation on that? No. So; I create a Log object which can be initialised either locally in a scope, or as part of a parent Struct (where that struct has an impl and a reference to self) - when constructing the logger locally on the stack, we do spend time resolving the path, but this is far less intensive than having to do this every time we want to log something. Whenever possible, I include logging functionality in existing structs through their implementations.

The logging module

This module consists of a public struct Log; an enum for LogLevel, and then the implementation.

I would recommend having standard logging separate to panic logging. Imagine the scenario where you are pattern matching like so:

let something = match some_variable {
    Ok(result) => result,
    Err(e) => // here you need to panic
}

For panics, I use a dedicated panic method with #[track_caller] so the compiler reports the correct caller location, rather than just the line where I wrote panic! in the logger code.

#[track_caller]

Which will allow for the accurate reporting of caller location during panics. If we call panic!() directly from within our implementation, our panic message will show the line number where we have written the panic - not the line number where we called our custom log panic function.

Below is a simplified example. In your case, you might replace get_logged_in_username() or get_setting_paths() with your own logic, or just hardcode the path if known at compile time.

pub struct Log {
    log_file_path: PathBuf,
}

pub enum LogLevel {
    Info,
    Warning,
    Success,
    Error,
}

impl Log {
    pub fn init() -> Self {
        // .. your own implementation here as required,
        // but importantly we construct Log        
        Log {
            log_file_path: get_log_file_path(),
        }
    }

    /// Logs the message and panics.
    /// 
    /// # Warning
    /// This function does not return and will panic.
    #[track_caller]
    pub fn panic(&self, msg: &str) -> ! {
        // open the file
        let mut file = OpenOptions::new()
            .create(true)
            .append(true)
            .open(&self.log_file_path)
            .expect(format!("[fatal] Unable to open log file: {}", self.log_file_path.display()).as_str());

        // write to the file
        writeln!(file, "{}", msg)
                .expect("Unable to write to log file");
            
        panic!("[fatal] {}", msg);
    }

    /// Log messages to the log file defined in the applications constant strings.
    pub fn log(&self, level: LogLevel, msg: &str) {
        // open the file
        let mut file = OpenOptions::new()
            .create(true)
            .append(true)
            .open(&self.log_file_path)
            .expect(format!("[fatal] Unable to open log file: {}", self.log_file_path.display()).as_str());

        // write to the file
        writeln!(file, "{}", msg)
                .expect("Unable to write to log file");

        // console log the message
        match level {
            LogLevel::Info => println!("[i] {}", msg),
            LogLevel::Warning => println!("[w] {}", msg),
            LogLevel::Success => println!("[+] {}", msg),
            LogLevel::Error => println!("[e] {}", msg),
        }
    }
}

Kernel error logging

Implementing error logging in the driver is a little more complicated, albeit not that much more. The most complicated part is we cannot use the standard library file writing functions, and we have to explicitly, provide the path to the file via its object name, which is \DosDevices\ plus the full path to the file. If the driver gets loaded very early on, \DosDevices\ may not yet be available. As a result, I chose to write logs to \SystemRoot\, the directory where the operating system is installed.

As an overview, this is what we want to do:

1. Create a unicode string that contains the path (including the object name or system root) to the log file we want to create.
2. Initialise an OBJECT_ATTRIBUTES structure.
3. Check we are safe to proceed at the current IRQL (more on this later).
4. Create the log file, or open if it currently exists (and getting a handle in the process).
5. Allocate a mutable buffer (we will use a vector) for the data we wish to write.
6. Write the buffer to the file.
7. Ensure our handle is cleaned up.

Macro issue

There is one slight problem with the above steps, the C macro for the function InitializeObjectAttributes doesn’t exist (yet) in the Windows Drivers crates. So, for now we will implement this ourselves. I have submitted a pull request to the official Windows Drivers crate for this function, so hopefully the changes get merged at some point in the future!

Before cracking on with our example of writing to files from a Windows kernel driver in Rust, we will first implement the macro in Rust for InitializeObjectAttributes. Looking at the C definition from ntdef.h:

#define InitializeObjectAttributes( p, n, a, r, s ) { \
    (p)->Length = sizeof( OBJECT_ATTRIBUTES );          \
    (p)->RootDirectory = r;                             \
    (p)->Attributes = a;                                \
    (p)->ObjectName = n;                                \
    (p)->SecurityDescriptor = s;                        \
    (p)->SecurityQualityOfService = NULL;               \
    }

This is a nice easy one to implement, we simply assign each input to a field of p, which is a pointer to an OBJECT_ATTRIBUTES struct. To make it a little more idiomatic in Rust, we can add a check for a null pointer and return with an Err(()) if it is null, seeing as we don’t want to attempt to dereference that! To get information on the arguments, we can look at the MSDN documentation.

#[allow(non_snake_case)]
pub unsafe fn InitializeObjectAttributes(
    p: POBJECT_ATTRIBUTES,
    n: PUNICODE_STRING,
    a: ULONG,
    r: HANDLE,
    s: PSECURITY_DESCRIPTOR,
) -> Result<(), ()>{
    if p.is_null() {
        return Err(());
    }

    (*p).Length = size_of::<OBJECT_ATTRIBUTES>() as u32;
    (*p).RootDirectory = r;
    (*p).Attributes = a;
    (*p).ObjectName = n;
    (*p).SecurityDescriptor = s;
    (*p).SecurityQualityOfService = null_mut();

    Ok(())
}

With that out of the way, lets look at how we can actually write to a file from the driver.

Initialising our objects

Let’s initialise a UNICODE_STRING and call our newly created InitializeObjectAttributes function:

//
// Initialise a UNICODE_STRING
//
let mut log_path_unicode = UNICODE_STRING::default();
let src = r"\SystemRoot\my_driver.log".encode_utf16().chain(once(0)).collect::<Vec<_>>(); // null terminate
unsafe { RtlInitUnicodeString(&mut log_path_unicode, src.as_ptr()) };

//
// Initialise OBJECT_ATTRIBUTES
//
let mut oa: OBJECT_ATTRIBUTES = OBJECT_ATTRIBUTES::default();
let result = unsafe {
    InitializeObjectAttributes(
        &mut oa,
        &mut log_path_unicode,
        OBJ_CASE_INSENSITIVE | OBJ_KERNEL_HANDLE,
        null_mut(),
        null_mut(),      
    )
};
if result.is_err() {
    println!("[my_driver] [-] Error calling InitializeObjectAttributes. No log event taking place..");
    return;
}

Checking the IRQL

One thing we need to note, is that when doing file operations, we cannot do this at a higher IRQL, so we need to make a quick check that we are at the correct IRQ level:

unsafe {
    if KeGetCurrentIrql() as u32 != PASSIVE_LEVEL {
        println!("[sanctum] [-] IRQL level too high to log event.");
        self.log_to_userland("[-] IRQL level too high to log event.".to_string());
        return;
    }
}

Creating the log file

Now we can actually create the log file itself. Similar to the usermode function CreateFile, we can use the Kernel mode function ZwCreateFile. Lucky for us, this is included in the Windows drivers crate.

With this, we want to get a handle to the file which will be in our handle variable, and we want to make sure we specify:

• FILE_APPEND_DATA
• FILE_OPEN_IF
• FILE_SYNCHRONOUS_IO_NONALERT

Where appropriate to make sure we are appending data to the file, and if it exists, we open the file rather than have Windows give us an error.

let mut handle: PHANDLE = null_mut();
let mut io_status_block = IO_STATUS_BLOCK::default();

let result = unsafe {
    ZwCreateFile(
        &mut handle as *mut _ as *mut _,
        FILE_APPEND_DATA,
        &mut oa,
        &mut io_status_block,
        null_mut(),
        FILE_ATTRIBUTE_NORMAL,
        0,
        FILE_OPEN_IF,
        FILE_SYNCHRONOUS_IO_NONALERT,
        null_mut(),
        0
    )
};

If this was successful, we should now have a handle to the file.

Allocating the buffer

We now need to allocate a mutable buffer to pass into the ZwWriteFile function; the mutability is enforced by the function signature, so we cannot simply pass a &str into it. Assuming you have a string slice that you wish to write to the file, we can turn this into a vector easily like so:

let buf: Vec<u8> = msg.as_bytes().iter().chain("\r\n".as_bytes().iter()).cloned().collect();

We add “\r\n” for a proper carriage return at the end of the line, so we don’t append data to the same line of the file.

Writing to the file

Now, calling ZwWriteFile:

let result = unsafe {
    ZwWriteFile(
        handle as *mut _ as *mut _, 
        null_mut(),
        None, 
        null_mut(), 
        &mut io_status_block, 
        buf.as_ptr() as *mut _, 
        buf.len() as u32,
        null_mut(), // should be ignored due to flag FILE_APPEND_DATA
        null_mut(),
    )
};

We should have written to the file! Go check it out at C:\Windows\my_driver.log!

Closing the handle

Finally, we need to close the handle to the opened file with a simple:

unsafe {
    if !handle.is_null() {
        let _ = ZwClose(handle as *mut _);
        println!("[sanctum] [+] Closed file handle");
    }
}

Remember to do this also in failure checks before returning out of your logging function. Handles opened in Kernel mode wont automatically be closed once your driver gets to the end of it’s life like a usermode process does - we want to make sure we avoid memory leaks where possible!