feature: Logging #47

str4d · 2023-03-02T02:08:01Z

The Level and LevelFilter types are based on the equivalent tracing-core types. We then use them to implement wrapper macros around sys::furi_log_print_format.

crates/flipperzero/src/furi/log/mod.rs

str4d · 2023-03-02T02:23:22Z

Adding info!("Hello, reader of the logs!"); line to the hello-rust example app increases the size of hello-rust.fap from 908 bytes to 1080 bytes.

crates/flipperzero/src/furi/log/mod.rs

crates/flipperzero/src/furi/log/metadata.rs

crates/flipperzero/src/furi/log/mod.rs

examples/hello-rust/src/main.rs

dcoles · 2023-03-03T06:06:16Z

@str4d I have a PR up that switches the print!/println! macros to ufmt. It results in a 76% smaller binary for the simple case of println!("Hello, {}", "Rust").

That seems to be enough of an improvement over core::fmt that it's probably worth using that rather than calling through to a printf-like function for formatting.

crates/flipperzero/src/furi/log/metadata.rs

str4d · 2023-03-03T20:46:18Z

Rebased on main to fix merge conflicts.

crates/flipperzero/src/furi/log/mod.rs

dcoles · 2023-03-04T05:44:40Z

crates/flipperzero/src/furi/log/metadata.rs

+// The structs and enums in this file are extracted from the `tracing-core` crate with
+// adaptions to Furi. The original code is copyright (c) 2019 Tokio Contributors


This seems a lot of code for what should mostly be just some macros around sys::furi_log_print_format.

The log crate has no-std support and only needs about 15 lines to implement. As a bonus, we'd immediately support any crate that used the log crate as a logging facade.

The tracing crate is quite powerful, but the main reason for using it is to be able to understand asynchronous code where tasks can jump between threads. While it looks like it could be possible to implement a tracing::Subscriber, there's a lot of code that needs to be generated to support spans, which I worry would blow out binary sizes quite quickly.

I actually started this effort by trying to write a log backend, and I very quickly ran into the problem that log assumes that you will be writing and formatting with &str, while sys::furi_log_print_format requires &CStr. This would force inline allocations at every individual log point, in order to copy the format string and append a nul byte.

tracing has the same issue here. It's a fantastic library and I use it wherever I can (it's useful for way more than just understanding async code), but it also is built around &str, and thus doesn't match up well with sys::furi_log_print_format.

My next thought was that we can use the c_string! macro to ensure that the format string is statically null-terminated, but this requires writing our own macros. Once we've done that, the next step is to represent the FuriLevel enum on the Rust side, which is where I turned to tracing's implementation as it is heavily optimised for low code overhead, which we want here.

All that being said: if we're going to use ufmt and FuriString for formatting log output before calling sys::furi_log_print_format, then we could provide a log::Log and/or tracing::Subscriber implementation that users can choose to install.

I think FuriString is going to be the right approach. We may be able to do something clever like using a static FuriString buffer for formatting, so we're not constantly doing allocations (the logger is already serialized on a mutex).

I just realized another issue with the log crate. It expects records to be formatted as core::fmt::Arguments which pretty much forces the use of core::fmt which we're trying to avoid. Tracing is a bit better since it can keep track of individual fields, but generic messages are still formatted using core::fmt.

We now use FuriString (allocating each time), and ufmt for formatting. So our arguments are whatever ufmt::uwrite takes instead of core::fmt::Arguments.

We could maybe use the rt macros to set up a static, and then free it on exit. That seems like an approach that would be generally useful for various sub-systems; opened #64.

str4d · 2023-04-09T19:06:47Z

Rebased on current main. I am not currently working on this (because it is blocked on #50, which in turn is blocked on #57), but I will rebase it for testing purposes when the main branch is updated to newer SDKs.

str4d · 2023-05-06T17:55:50Z

Rebased on aa1bfde5f3ce688c1f44c6945ea5863d03b5dac0 (the same base as #50).

We don't need these for the Furi Logging system.

We aren't constrained by the const fn conversions of the `tracing` crate, so we can avoid the edge cases caused by that representation.

This enables us to greatly simplify the ordering implementations: - We have a dedicated `LevelFilterInner` enum, so we don't need to rely on the niche optimization of `Option<Level>` like `tracing-core` does. - We will be placing the logging macros in the same crate as `Level` and `LevelFilter`, so we don't need to add `#[inline(always)]` annotations to the comparison methods. - The Flipper Zero SDK orders their discriminants in verbosity ordering, so we don't need to invert the ordering.

The Flipper Zero SDK's log level numbers don't line up with the ones `tracing` used, and are offset by `FuriLogLevelDefault`, so they would just make the API confusing.

str4d · 2023-05-08T01:03:58Z

Rebased on main and switched from the Flipper Zero SDK's printf to FuriString and ufmt instead.

str4d · 2023-05-08T01:07:06Z

Force-pushed because I forgot I'd renamed String to FuriString 😅

The `tracing` ecosystem uses this to set a global maximum based on all uses of log macros within the binary. FAPs are instead loaded within the wider Flipper Zero environment, and `sys::furi_log_set_level` configures the global log level that affects other apps.

str4d force-pushed the log branch 2 times, most recently from 6cf53a9 to 4a5c79d Compare March 2, 2023 02:11