redstrate.com/content/blog/marrying-rust-qt-logging/index.md

title	date	draft	tags
Marrying Qt and Tracing message output	2023-10-14	false	Qt Rust

Do you have a mixed of Qt and Rust in your project, and dislike how your logs mismatch? Do you want one single source of truth, so it's easier to redirect to a file or other destination? I've been hitting my head against this problem, and developed a novel solution for marrying the two. It's even possible to transfer information like the source file and line!

As mentioned previously in my [Obscure Qt post on logging]({{< ref "obscure-qt3" >}}), the default logging format for Qt isn't that great in the first place. Not to mention, it looks really out of place when mixing in logs from Tracing in the Rust parts of the code:

2023-10-04T12:33:21.310435Z DEBUG physis::gamedata: Extracting file file="exd/Item_41000_en.exd"
Uploading imgui font size 512 x 64
false true true
Looking up "Hyur" "Midlander" "Male"
2023-10-04T12:33:21.405104Z DEBUG physis::gamedata: Extracting file file="chara/equipment/e0000/model/c0101e0000_top.mdl"
Uploading imgui font size 512 x 64
false false true

The Qt logger looks basic compared to the default formatting of the Tracing crate. But what if we try to marry their output together? If I want to do some advanced operations like redirecting it all to a file, then it becomes easier as we're only dealing with one log!

In this case the final application is Qt based, so I think the best course of action is to shove everything through their logger. Going in the other direction might be an interesting future project :-)

Piping messages from Tracing into Qt

First we'll want to set up a C function for use by our application. You can use your favorite FFI crate, but in this example we'll just use good ol' extern "C" Let's begin by defining a LogCallback type. It will take a QtMsgType, the message, file and line.

#[repr(i8)]
pub enum QtMsgType {
    Debug = 0,
    Warning = 1,
    Critical = 2,
    Fatal = 3,
    Info = 4,
}

type LogCallback = unsafe extern "C" fn(QtMsgType, *const c_char, *const c_char, i32);

#[no_mangle]
pub unsafe extern "C" fn setup_logging(callback: LogCallback) {
    tracing_subscriber::registry().with(CustomLayer {
        callback
    }).init();
}

Now it's time to define CustomLayer. As hinted above, it's a struct with one member: the callback. The trait we'll implement is Layer.

pub struct CustomLayer {
    callback: LogCallback,
}

impl<S> Layer<S> for CustomLayer
    where
        S: tracing::Subscriber,
{
    fn on_event(
        &self,
        event: &tracing::Event<'_>,
        _ctx: tracing_subscriber::layer::Context<'_, S>,
    ) {
        ...
    }
}

Getting the message content is a bit complex due to how Tracing works. We need to implement the Visit trait which and it's up to you to decide how to format each field. For this example we'll simply append each field into one big string.

struct CustomVisitor<'a> {
    string: &'a mut String,
}

impl tracing::field::Visit for CustomVisitor<'_> {
    fn record_debug(&mut self, field: &tracing::field::Field, value: &dyn std::fmt::Debug) {
        write!(self.string, "{} = {:?} ", field.name(), value).unwrap();
    }
}

Here we implement the record_debug and print each field via the Display trait ({:?}). Let's plug it into our CustomLayer's on_event():

let mut buffer: String = String::new();
let mut visitor = CustomVisitor {
    string: &mut buffer
};
event.record(&mut visitor);

In order for the message levels to transfer, let's set up a match case for converting Tracing's Level to Qt's. Except Qt doesn't have a tracing level so we'll map that to QtMsgType::Debug.

let msg_type = match *event.metadata().level() {
    Level::ERROR => QtMsgType::Critical,
    Level::WARN => QtMsgType::Warning,
    Level::INFO => QtMsgType::Info,
    Level::DEBUG => QtMsgType::Debug,
    Level::TRACE => QtMsgType::Debug
};

The final step on the Rust side is to pass the message and relevant information over the FFI layer like so:

unsafe {
    let file = if let Some(file) = event.metadata().file() {
        CString::new(file).unwrap().into_raw()
    } else {
        null()
    };

    let line = if let Some(line) = event.metadata().line() {
        line as i32
    } else {
        -1
    };

    (self.callback)(msg_type, CString::new(buffer).unwrap().into_raw(), file, line);
}

In order to hook this up to the Qt application, we'll write a bit of C++ code which will glue it to the Qt logging:

extern "C" void setup_logging(void (*callback) (QtMsgType type, const char*, const char*, int));

void callback(QtMsgType type, const char *message, const char *file, int line) {
    QMessageLogContext context;
    context.file = file;
    context.line = line;

    qt_message_output(type, context, message);
}

int main() {
    setup_logging(callback);

    ...
}

There's an undocumented function in the header called qt_message_output that will format your message and hand it off to the current message handler. If you don't want to depend on that, using qFormatLogMessage works as well.

You can view the full example on git.sr.ht. Here's the expected output:

[2023-10-13 21:54:42.765] [info] [src/lib.rs:77] message = something has happened!
[2023-10-13 21:54:42.765] [critical] [src/lib.rs:78] message = something bad has happened!
[2023-10-13 21:54:42.765] [info] [/home/josh/Development/logging-qt-and-tracing/main.cpp:28] Application started up!