Tracing not present in tests

[BoManev]

Hi,

First and foremost, thank you for the awesome book. I'm currently on chapter 8, eg the error handling chapter. However, I noticed that my tracing doesn't look right, especially on failing tests. This is a sample input from a successful test (TEST_LOG=1 cargo test)

test subscriptions::subscribe_returns_a_400_when_data_is_missing ... ok
{"v":0,"name":"z2p-test","msg":"[HTTP REQUEST - START]"...
{"v":0,"name":"z2p-test","msg":"[CONFIRM A PENDING SUBSCRIBER - START]"...
{"v":0,"name":"z2p-test","msg":"[GET SUBSCRIBER_ID FROM TOKEN - START]"...
{"v":0,"name":"z2p-test","msg":"[GET SUBSCRIBER_ID FROM TOKEN - END]"...
{"v":0,"name":"z2p-test","msg":"[MARK SUBSCRIBER AS COFNIRMED - START]"..

This shows that tracing is indeed configured and working and my handler and supporting functions are instrumented correctly. Similar correct behavior is present when running the application locally (cargo run).

However, the output of the TEST_LOG=1 cargo test seems to be missing the tracing logs from some successful and error tests.

This is a sample input from a failed test (TEST_LOG=1 cargo test --test api subscribe_fails)

{"v":0,"name":"z2p-test","msg":"Tokio runtime found; starting in existing Tokio runtime","level":30...
test subscriptions::subscribe_fails_if_there_is_a_fatal_error ... FAILED

failures:

---- subscriptions::subscribe_fails_if_there_is_a_fatal_error stdout ----
thread 'subscriptions::subscribe_fails_if_there_is_a_fatal_error' panicked at 'called `Result::unwrap()` on an `Err` value: Database(PgDatabaseError { severity: Error, code: "42P01", message: "relation \"subscription_token\" does not exist", detail: None, hint: None, position: None, where: None, schema: None, table: None, column: None, data_type: None, constraint: None, file: Some("namespace.c"), line: Some(433), routine: Some("RangeVarGetRelidExtended") })', tests/api/subscriptions.rs:132:6
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace

failures:
    subscriptions::subscribe_fails_if_there_is_a_fatal_error

test result: FAILED. 0 passed; 1 failed; 0 ignored; 0 measured; 10 filtered out; finished in 0.63s

Cargo.toml

[dependencies]
actix-web = "4"
tokio = { version = "1", features = ["macros", "rt-multi-thread"] }
config = { version = "0.13", default-features = false, features = ["yaml"] }
uuid = { version = "0.8.1", features = ["v4", "serde"] }
chrono = { version = "0.4.22", default-features = false, features = ["clock"] }
log = "0.4"
tracing = "0.1.19"
tracing-subscriber = { version = "0.3", features = ["registry", "env-filter"] }
tracing-bunyan-formatter = "0.3.0"
tracing-log = "0.1.1"
secrecy = { version = "0.8", features = ["serde"] }
tracing-actix-web = "0.7"
serde-aux = "4"
unicode-segmentation = "1.7.1"
claim = "0.5"
validator = "0.14"
reqwest = { version = "0.11", default-features = false, features = [
    "json",
    "rustls-tls",
] }
rand = { version = "0.8", features = ["std_rng"], default-features = false }
serde = "1.0.15"

[dependencies.sqlx]
version = "0.5.7"
default-features = false
features = [
    "runtime-actix-rustls", # use the actix runtime futures and rustls as TLS backend;
    "macros",               # access to sqlx::query! and sqlx::query_as!
    "postgres",
    "uuid",                 # mapping SQL UUIDs to the Uuid type
    "chrono",               # mapping SQL timestamptz to the DateTime<T>
    "migrate",              # access to sqlx-cli
    "offline",
]

I don't know what's happening. I tried setting RUST_LOG and -- --nocapture. I went over the sources in this repo and they look similar to mine. I have an older version of the book and I had to adjust the configuration from using .merge() to '::builder().add_source()'. I check for the TEST_LOG var and configure the tracing subscriber with either sink/stdout. I'm using the Lazy cell to make sure this initialization is only run once, per run of the test suite. TLDR: Tracing stops working mid thru the run of the test suite

EDIT: NVM, I figured it out. I had a wrong assumption about the test case. I had a type inside of the sqlx::query!() macro, however it didn't trigger a comp time error. I thought this was the special thing about sqlx. Maybe sqlx is skiping the comp time checks for any macro invocations outside the main binary/lib create, eg the tests/.