tracing-subscriber 0.3.18 silently drops module paths when `tracing-log` is in use

[SludgePhD]

Bug Report

Version

│   │   │       │   │   │   │   │   ├── tracing v0.1.40
│   │   │       │   │   │   │   │   │   ├── tracing-attributes v0.1.27 (proc-macro)
│   │   │       │   │   │   │   │   │   └── tracing-core v0.1.32
│   │   │       │   │   │   │   └── tracing v0.1.40 (*)
│   │   │       │   │   │   ├── tracing-log v0.1.4
│   │   │       │   │   │   │   └── tracing-core v0.1.32 (*)
│   │   │       │   │   │   └── tracing-subscriber v0.3.18
│   │   │       │   │   │       ├── tracing v0.1.40 (*)
│   │   │       │   │   │       ├── tracing-core v0.1.32 (*)
│   │   │       │   │   │       └── tracing-log v0.2.0
│   │   │       │   │   │           └── tracing-core v0.1.32 (*)
│   │   │       │   │   │   ├── tracing v0.1.40 (*)

Platform

Linux bertie 6.6.7-arch1-1 #1 SMP PREEMPT_DYNAMIC Thu, 14 Dec 2023 03:45:42 +0000 x86_64 GNU/Linux

Crates

tracing-subscriber and possibly tracing-log. bevy_log directly depends on tracing-log 0.1, but tracing-subscriber 0.3.18 updates to tracing-log 0.2.

It's possible that bevy_log does something inappropriate here and is to blame instead. However, neither tracing-subscriber not tracing-log maintain changelogs, so I'm blaming tracing for not communicating what's going on properly.

Description

Log output with tracing-subscriber 0.3.17:

2024-01-13T02:15:45.283091Z DEBUG bevy_salva2d::systems: new boundary; entity=32v0, handle=BoundaryHandle(Index { index: 2, generation: 0 })    
2024-01-13T02:15:45.283172Z  WARN bevy_salva2d::systems: max. owed time exceeded (0.12464798 > 0.1)! possible system overload.    
2024-01-13T02:15:46.504858Z  INFO artifice::shadowmouse: opened shadowmouse evdev device `/dev/input/event25`: evdev-switch-switched (<no unique name>, <no physical path>)    
2024-01-13T02:15:46.561518Z  INFO artifice::hotkeys: opened hotkey evdev device `/dev/input/event19`: SINO WEALTH RK Bluetooth Keyboard (<no unique name>, usb-0000:02:00.0-5.4/input0)    

Log output after updating to tracing-subscriber 0.3.18:

2024-01-13T02:19:20.141993Z DEBUG log: new boundary; entity=32v0, handle=BoundaryHandle(Index { index: 2, generation: 0 })    
2024-01-13T02:19:20.142013Z  WARN log: max. owed time exceeded (0.10533147 > 0.1)! possible system overload.    
2024-01-13T02:19:21.424821Z  INFO log: opened shadowmouse evdev device `/dev/input/event25`: evdev-switch-switched (<no unique name>, <no physical path>)    
2024-01-13T02:19:21.464820Z  INFO log: opened hotkey evdev device `/dev/input/event19`: SINO WEALTH RK Bluetooth Keyboard (<no unique name>, usb-0000:02:00.0-5.4/input0)    

Instead of proper module and crate names everything is attributed to "log".

[kaffarell]

Could you provide a code example? I just tested the LogTracer (tracing-log) like it is used in bevy (https://github.com/bevyengine/bevy/blob/main/crates/bevy_log/src/lib.rs), and it seems to work fine for me... Changelogs are btw here (tracing-log) and here (tracing-subscriber).

[SludgePhD]

Ah, I looked into https://github.com/tokio-rs/tracing/blob/master/tracing-log/CHANGELOG.md, which hasn't been updated

[kaffarell]

It is on the v0.1.x branch (https://github.com/tokio-rs/tracing/blob/v0.1.x/tracing-log/CHANGELOG.md) :)

[SludgePhD]

This reproduces it:

use bevy::{app::App, log::LogPlugin};

fn main() {
    App::new().add_plugins(LogPlugin::default());

    tracing::error!("via tracing");
    log::error!("via log");
}

With these dependencies:

[dependencies]
bevy = { version = "0.13.0", default-features = false }
tracing = "0.1.40"
log = "0.4.20"

Output with up-to-date dependencies:

     Running `target/debug/hello`
2024-02-27T21:49:11.237546Z ERROR hello: via tracing
2024-02-27T21:49:11.237574Z ERROR log: via log    

Output after cargo update -p tracing-subscriber --precise 0.3.17:

     Running `target/debug/hello`
2024-02-27T21:49:53.488578Z ERROR hello: via tracing
2024-02-27T21:49:53.488605Z ERROR hello: via log    

As you can see, tracing-subscriber 0.3.18 misattributes every use of the log crate's macros to the log crate itself, presumably because the two copies of the tracing-log crate don't interact well.

[kaffarell]

Hmm it looks like this is fixed with the latest bevy version because they updated tracing-log to 0.2.0 (https://github.com/bevyengine/bevy/pull/10404). Could you please check as well?

[SludgePhD]

Yes, bevy's main branch doesn't have the issue. But there is still seemingly a breaking change published in a non-breaking update of tracing-subscriber.