spdlog-rs icon indicating copy to clipboard operation
spdlog-rs copied to clipboard

Introduce `AtomicLevelFilter`

Open SpriteOvO opened this issue 2 weeks ago • 3 comments

Reasons

  1. Using Atomic<T> (from atomic crate) with types that contain uninitialized bytes is undefined behavior. Prior to atomic v0.6, that crate did not restrict this (Amanieu/atomic-rs#23). In spdlog-rs, LevelFilter is an enum, for variants Off and All, they have uninitialized bytes.

  2. The new introduced AtomicLevelFilter, makes downstream users no longer need to add atomic crate to their Cargo.toml, and eliminates uninitialized bytes. Ensured the soundness of atomic level filter.

  3. We can now bump atomic to the latest version, this was the main obstacle that kept us locked to atomic v0.5.

  4. Miri currently reports this error, so once it's fixed we can enable Miri in CI (there may be other obstacles, some tests run very slowly even on my real machine).

test log_macros::tests::kv_types ... error: Undefined Behavior: reading memory at alloc855131[0x8c..0x90], but memory is uninitialized at [0x8e..0x90], and this operation requires initialized memory
   --> ~/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/atomic-0.5.3/src/ops.rs:118:30
    |
118 |         mem::transmute_copy(&(*(dst as *const A)).load(order)),
    |                              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ Undefined Behavior occurred here
    |
    = help: this indicates a bug in the program: it performed an invalid operation, and caused Undefined Behavior
    = help: see https://doc.rust-lang.org/nightly/reference/behavior-considered-undefined.html for further information
    = note: BACKTRACE on thread `log_macros::tes`:
    = note: inside `atomic::ops::atomic_load::<level::LevelFilter>` at ~/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/atomic-0.5.3/src/ops.rs:118:30: 118:62
    = note: inside `atomic::Atomic::<level::LevelFilter>::load` at ~/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/atomic-0.5.3/src/lib.rs:145:18: 145:59
note: inside `logger::Logger::flush_level_filter`
   --> spdlog/src/logger.rs:261:9
    |
261 |         self.flush_level_filter.load(Ordering::Relaxed)
    |         ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
note: inside `logger::Logger::should_flush`
   --> spdlog/src/logger.rs:526:9
    |
526 |         self.flush_level_filter().test(record.level())
    |         ^^^^^^^^^^^^^^^^^^^^^^^^^
note: inside `logger::Logger::sink_record`
   --> spdlog/src/logger.rs:493:12
    |
493 |         if self.should_flush(record) {
    |            ^^^^^^^^^^^^^^^^^^^^^^^^^
note: inside `logger::Logger::log`
   --> spdlog/src/logger.rs:241:9
    |
241 |         self.sink_record(record);
    |         ^^^^^^^^^^^^^^^^^^^^^^^^
note: inside `__log`
   --> spdlog/src/lib.rs:802:5
    |
802 |     logger.log(&record);
    |     ^^^^^^^^^^^^^^^^^^^
note: inside `log_macros::tests::kv_types`
   --> spdlog/src/log_macros.rs:35:13
    |
 35 |             $crate::__log(logger, $level, $crate::source_location_current!(), $crate::__kv!($kv), format_args!($($arg)+));
    |             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
...
425 |         info!(logger: asserter, "1", kv: { v = 1 });
    |         ------------------------------------------- in this macro invocation
note: inside closure
   --> spdlog/src/log_macros.rs:370:18
    |
369 |     #[test]
    |     ------- in this attribute macro expansion
370 |     fn kv_types() {
    |                  ^

Uninitialized memory occurred at alloc855131[0x8e..0x90], in this allocation:
alloc855131 (stack variable, size: 144, align: 8) {
    0x00 │ 01 00 00 00 00 00 00 00 ╾0x139ded8[a854901]<2511963> (8 ptr bytes)╼ │ ........╾──────╼
    0x10 │ 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 80 │ ................
    0x20 │ __ __ __ __ __ __ __ __ __ __ __ __ __ __ __ __ │ ░░░░░░░░░░░░░░░░
    0x30 │ 00 00 00 00 00 00 00 00 00 __ __ __ __ __ __ __ │ .........░░░░░░░
    0x40 │ ╾0x139ab58[a854353]<2510869> (8 ptr bytes)╼ ╾0x139af90[a854401]<2510872> (8 ptr bytes)╼ │ ╾──────╼╾──────╼
    0x50 │ 00 00 00 00 00 __ __ __ __ __ __ __ __ __ __ __ │ .....░░░░░░░░░░░
    0x60 │ 00 ca 9a 3b __ __ __ __ __ __ __ __ __ __ __ __ │ ...;░░░░░░░░░░░░
    0x70 │ __ __ __ __ __ __ __ __ __ __ __ __ __ __ __ __ │ ░░░░░░░░░░░░░░░░
    0x80 │ __ __ __ __ __ __ __ __ 04 00 03 00 00 00 __ __ │ ░░░░░░░░......░░
}
alloc854901 (Rust heap, size: 16, align: 8) {
    ╾0x139bb48[a854532]<2511155> (8 ptr bytes)╼ ╾0x139bfa8[a854580]<2511158> (8 ptr bytes)╼ │ ╾──────╼╾──────╼
}
alloc854353 (Rust heap, size: 16, align: 8) {
    01 00 00 00 00 00 00 00 01 00 00 00 00 00 00 00 │ ................
}
alloc854401 (vtable: impl std::ops::Fn(error::Error) + std::marker::Send + std::marker::Sync for {closure@/tmp/cargo-target/miri/x86_64-unknown-linux-gnu/debug/build/spdlog-rs-c502dd30f0c9c7f4/out/test_utils/common_for_unit_test.rs:201:30: 201:35})
alloc854532 (Rust heap, size: 80, align: 8) {
    0x00 │ 01 00 00 00 00 00 00 00 01 00 00 00 00 00 00 00 │ ................
    0x10 │ 00 00 00 00 00 00 00 00 00 __ __ __ __ __ __ __ │ .........░░░░░░░
    0x20 │ 00 00 00 00 00 00 00 00 __ __ __ __ __ __ __ __ │ ........░░░░░░░░
    0x30 │ 00 00 00 00 00 00 00 00 ╾0x139b1e9[a854436]<2511046> (8 ptr bytes)╼ │ ........╾──────╼
    0x40 │ ╾0x139b4f0[a854470]<2510976> (8 ptr bytes)╼ 07 00 __ __ __ __ __ __ │ ╾──────╼..░░░░░░
}
alloc854580 (vtable: impl sink::Sink for log_macros::tests::kv_types::Asserter)
alloc854436 (Rust heap, size: 1, align: 1) {
    01                                              │ .
}
alloc854470 (vtable: impl formatter::Formatter for formatter::full_formatter::FullFormatter)

note: some details are omitted, run with `MIRIFLAGS=-Zmiri-backtrace=full` for a verbose backtrace

error: aborting due to 1 previous error; 5 warnings emitted

error: test failed, to rerun pass `-p spdlog-rs --lib`

@Lancern Given that this PR relates to safety, would you be willing to take a look?

SpriteOvO avatar Nov 29 '25 22:11 SpriteOvO

I have changed to use mem::transmute(AtomicLevelFilterInner) -> LevelFilter, since they should have the same layout and struct Inner contains no uninitialized bytes, this should be safe. This way we can avoid an extra discriminant enum and multiple match branches.

I'll run Miri later to see if there are any issues.

SpriteOvO avatar Dec 04 '25 09:12 SpriteOvO

In this PR we adds a repr(u16) to LevelFilter, refer to The Cargo Book - SemVer Compatibility, this change may not be considered as a breaking change, so we could include it in v0.5.2.

SpriteOvO avatar Dec 05 '25 05:12 SpriteOvO

⚠️ Performance Alert ⚠️

Possible performance regression was detected for benchmark 'spdlog-rs on Linux'. Benchmark result of this commit is worse than the previous benchmark result exceeding threshold 2. Benchmark suite Current: 1896486 Previous: 7c107c2 Ratio bench_2_full_pattern_ct 428.9 ns/iter (± 10.42) 196.64 ns/iter (± 25.57) 2.18

This comment was automatically generated by workflow using github-action-benchmark.

CC: @SpriteOvO

Should be false positive due to unstable CI VM environment.

SpriteOvO avatar Dec 05 '25 05:12 SpriteOvO

Renamed AtomicLevelFilterInner to LevelFilterLayout.

SpriteOvO avatar Dec 06 '25 02:12 SpriteOvO