Level filtering is broken when depending on tracing-subscriber from crates.io

ConradIrwin commented 3 months ago

Bug Report

Version

mixed

Platform

macOS

Description

Depend on tracing-subscriber = { version = 0.3.18, features = ["env-filter", "json", "registry", "tracing-log"] } from crates.io
Set an env filter to a string like warn,collab::rpc=info
Notice that output from tracing::error! inside collab::rpc with level ERROR is not printed to the console.
Replace tracing-subscriber = { git = "https://github.com/tokio-rs/tracing", rev = "tracing-subscriber-0.3.18", features = ["env-filter", "json", "registry", "tracing-log"] }
Notice that output from tracing::error! inside collab::rpc with level ERROR is printed to the console

We dug into this a little bit and noticed that the published version of tracing-subscriber depends on tracing-core v0.1.30 but when we depend on the git repository directly we get a version of tracing-core that's just a bit newer than v0.1.32. It seems to be the case that when the versions mismatch like this the filtering logic is sometimes wrong.

davidbarsky commented 3 months ago

Can you replicate this if you set a dependency on tracing-core of 0.1.32 in your Cargo.toml? Is there a branch where I can try and replicate this?

(I'm guessing is this in Zed: is it https://github.com/zed-industries/zed/pull/10085?)

ConradIrwin commented 3 months ago

That does not seem to fix the problem, so I guess the difference is in the commits between 0.1.32 and the tracing-subscriber release.

You can test here: https://github.com/zed-industries/zed/commit/d56730b82b88025eb7fe81736ec339c1494eafa4 vs https://github.com/zed-industries/zed/commit/d1c6b4acfe5d4a556eda38a9f20ac36ca78bfc9a

By running:

RUST_LOG=warn,collab::rpc=info cargo run --package=collab serve

(Though you'll need to set up the local collaboration dev dependencies: https://zed.dev/docs/local-collaboration)

hawkw commented 3 months ago

Well, this is extremely strange; the 0.3.18 release on crates.io should be exactly the same as the tagged commit for tracing-subscriber-0.3.18...the only difference I can think of is the path dep on tracing-core that you get with the repo version, but I think the explicit tracing dep will still pull the release version of tracing and tracing-core.

Can you run cargo tree -i -p tracing-core on the working and non-working commits?

ConradIrwin commented 3 months ago

On the version I've marked as broken, the output is here: https://gist.github.com/ConradIrwin/dc0103d52e390eae9ebacc87c311cdb4.

On the commit I've tagged as working, I get:

    Updating git repository `https://github.com/tokio-rs/tracing`
error: There are multiple `tracing-core` packages in your project, and the specification `tracing-core` is ambiguous.
Please re-run this command with one of the following specifications:
  registry+https://github.com/rust-lang/crates.io-index#tracing-core@0.1.32
  git+https://github.com/tokio-rs/tracing?rev=tracing-subscriber-0.3.18#tracing-core@0.1.32

So I guess both are being included, but as there are commits in the git repo's tracing-core directory at tag tracing-subscriber-0.3.18 that are not released by tracing-core-0.1.32 this is not actually running the same code as the released crate.

I haven't yet tried bisecting these commits, but a quick scan of the messages reveals no obvious culprits. It's also worth noting that the tracing-subscriber v0.3.18 depends on tracing-core v0.1.30 which was not the latest release at the time it was made, though that doesn't seem to be the cause of this bug, it also seems like a potential issue.

This could also be a bug in any of the other tracing-* crates; because they are all released on different schedules, the versions on crates.io will rarely correspond to a state of the git repository that ever existed.

In terms of narrowing the bug down:

It seems like this only happens when you have two different levels in the env filter warn,rpc::collab=info is broken, but warn,rpc::collab=warn is not.
We also observed this before we upgraded to the latest releases (which we did to try and solve this problem). The same issue happens on current zed main (https://github.com/zed-industries/zed/commit/0f1c2e6f2b35f471b5f0079b0114db75d40c0069), which is requesting tracing = "0.1.34", tracing-subscriber = { version = "0.3.11", features = ["env-filter", "json", "registry", "tracing-log"] } and resolving to v0.1.31 and v0.3.17 respectively.

ConradIrwin commented 3 months ago

Looking into this more, it seems like there's some kind of unexpected interaction with sqlx. I suspect that the reason it "works" when we include the git version is because sqlx is still depending on the non-git version and so shared state is not mutated.

From the broken commit on zed above, I narrowed down the test case, and it seems that if I don't make any SQL queries between init'ing the tracing subscriber and logging, then the log levels are preserved.

I also observe that I can control logging of collab::rpc's error logs by changing the filter on the sqlx package:

RUST_LOG=warn,sqlx=info,collab::rpc=info cargo run --package=collab serve # shows error logs in collab::rpc
RUST_LOG=warn,sqlx=warn,collab::rpc=info cargo run --package=collab serve # does not show error logs in collab::rpc

It also seems that if I build zed's collab using sqlite instead of Postgres, that fixes the problem.

ConradIrwin commented 3 months ago

Ok, zooming in more; the problem is this call in the sqlx-postgres crate: https://github.com/launchbadge/sqlx/blob/635dba5b2682033101a1271e9fb4bf2516c0b840/sqlx-postgres/src/connection/stream.rs#L154-L156

A minimal reproduction of this bug is https://github.com/ConradIrwin/tracing-bug/commit/00a1b1492a6435ebea70eac405270aa5163118d1#diff-42cb6807ad74b3e201c5a7ca98b911c5fa08380e942be6e4ac5807f8377f87fc

davidbarsky commented 3 months ago

Oh, thank you for the minimal reproduction—that is a bit odd. I bet we're doing something silly when interacting with log.

tokio-rs / tracing