[INFO] fetching crate tracing-perfetto 0.1.5...
[INFO] testing tracing-perfetto-0.1.5 against beta-2025-10-28 for beta-1.92-2
[INFO] extracting crate tracing-perfetto 0.1.5 into /workspace/builds/worker-0-tc2/source
[INFO] started tweaking crates.io crate tracing-perfetto 0.1.5
[INFO] removed 0 missing tests
[INFO] finished tweaking crates.io crate tracing-perfetto 0.1.5
[INFO] tweaked toml for crates.io crate tracing-perfetto 0.1.5 written to /workspace/builds/worker-0-tc2/source/Cargo.toml
[INFO] validating manifest of crates.io crate tracing-perfetto 0.1.5 on toolchain beta-2025-10-28
[INFO] running `Command { std: CARGO_HOME="/workspace/cargo-home" RUSTUP_HOME="/workspace/rustup-home" "/workspace/cargo-home/bin/cargo" "+beta-2025-10-28" "metadata" "--manifest-path" "Cargo.toml" "--no-deps", kill_on_drop: false }`
[INFO] running `Command { std: CARGO_HOME="/workspace/cargo-home" RUSTUP_HOME="/workspace/rustup-home" "/workspace/cargo-home/bin/cargo" "+beta-2025-10-28" "generate-lockfile" "--manifest-path" "Cargo.toml", kill_on_drop: false }`
[INFO] [stderr]     Updating crates.io index
[INFO] [stderr]      Locking 83 packages to latest compatible versions
[INFO] [stderr]       Adding prost v0.12.6 (available: v0.14.1)
[INFO] [stderr]       Adding rand v0.8.5 (available: v0.9.2)
[INFO] [stderr]       Adding thread-id v4.2.2 (available: v5.0.0)
[INFO] running `Command { std: CARGO_HOME="/workspace/cargo-home" RUSTUP_HOME="/workspace/rustup-home" "/workspace/cargo-home/bin/cargo" "+beta-2025-10-28" "fetch" "--manifest-path" "Cargo.toml", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-0-tc2/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-0-tc2/source:/opt/rustwide/workdir:ro,Z" "-v" "/var/lib/crater-agent-workspace/cargo-home:/opt/rustwide/cargo-home:ro,Z" "-v" "/var/lib/crater-agent-workspace/rustup-home:/opt/rustwide/rustup-home:ro,Z" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-w" "/opt/rustwide/workdir" "-m" "1610612736" "--user" "0:0" "--network" "none" "ghcr.io/rust-lang/crates-build-env/linux@sha256:4848fb76d95f26979359cc7e45710b1dbc8f3acb7aeedee7c460d7702230f228" "/opt/rustwide/cargo-home/bin/cargo" "+beta-2025-10-28" "metadata" "--no-deps" "--format-version=1", kill_on_drop: false }`
[INFO] [stdout] d751361bb247a63600b7d439cd3dc3b5ff8c9e58ed46cd00807e450eda747b99
[INFO] running `Command { std: "docker" "start" "-a" "d751361bb247a63600b7d439cd3dc3b5ff8c9e58ed46cd00807e450eda747b99", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "inspect" "d751361bb247a63600b7d439cd3dc3b5ff8c9e58ed46cd00807e450eda747b99", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "d751361bb247a63600b7d439cd3dc3b5ff8c9e58ed46cd00807e450eda747b99", kill_on_drop: false }`
[INFO] [stdout] d751361bb247a63600b7d439cd3dc3b5ff8c9e58ed46cd00807e450eda747b99
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-0-tc2/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-0-tc2/source:/opt/rustwide/workdir:ro,Z" "-v" "/var/lib/crater-agent-workspace/cargo-home:/opt/rustwide/cargo-home:ro,Z" "-v" "/var/lib/crater-agent-workspace/rustup-home:/opt/rustwide/rustup-home:ro,Z" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_INCREMENTAL=0" "-e" "RUST_BACKTRACE=full" "-e" "RUSTFLAGS=--cap-lints=warn" "-e" "RUSTDOCFLAGS=--cap-lints=warn" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-w" "/opt/rustwide/workdir" "-m" "1610612736" "--user" "0:0" "--network" "none" "ghcr.io/rust-lang/crates-build-env/linux@sha256:4848fb76d95f26979359cc7e45710b1dbc8f3acb7aeedee7c460d7702230f228" "/opt/rustwide/cargo-home/bin/cargo" "+beta-2025-10-28" "build" "--frozen" "--message-format=json", kill_on_drop: false }`
[INFO] [stdout] e4bede52a0a7ca89654cabcd7d8ff33c29110b67c44f133e5934258c18a32344
[INFO] running `Command { std: "docker" "start" "-a" "e4bede52a0a7ca89654cabcd7d8ff33c29110b67c44f133e5934258c18a32344", kill_on_drop: false }`
[INFO] [stderr]    Compiling proc-macro2 v1.0.103
[INFO] [stderr]    Compiling unicode-ident v1.0.22
[INFO] [stderr]    Compiling libc v0.2.177
[INFO] [stderr]    Compiling quote v1.0.41
[INFO] [stderr]    Compiling cfg-if v1.0.4
[INFO] [stderr]    Compiling zerocopy v0.8.27
[INFO] [stderr]    Compiling anyhow v1.0.100
[INFO] [stderr]    Compiling autocfg v1.5.0
[INFO] [stderr]    Compiling either v1.15.0
[INFO] [stderr]    Compiling lazy_static v1.5.0
[INFO] [stderr]    Compiling log v0.4.28
[INFO] [stderr]    Compiling nu-ansi-term v0.50.3
[INFO] [stderr]    Compiling iana-time-zone v0.1.64
[INFO] [stderr]    Compiling tracing-core v0.1.34
[INFO] [stderr]    Compiling smallvec v1.15.1
[INFO] [stderr]    Compiling thread_local v1.1.9
[INFO] [stderr]    Compiling sharded-slab v0.1.7
[INFO] [stderr]    Compiling itertools v0.12.1
[INFO] [stderr]    Compiling num-traits v0.2.19
[INFO] [stderr]    Compiling tracing-log v0.2.0
[INFO] [stderr]    Compiling tracing-subscriber v0.3.20
[INFO] [stderr]    Compiling syn v2.0.108
[INFO] [stderr]    Compiling chrono v0.4.42
[INFO] [stderr]    Compiling getrandom v0.2.16
[INFO] [stderr]    Compiling thread-id v4.2.2
[INFO] [stderr]    Compiling rand_core v0.6.4
[INFO] [stderr]    Compiling ppv-lite86 v0.2.21
[INFO] [stderr]    Compiling rand_chacha v0.3.1
[INFO] [stderr]    Compiling rand v0.8.5
[INFO] [stderr]    Compiling tracing-attributes v0.1.30
[INFO] [stderr]    Compiling prost-derive v0.12.6
[INFO] [stderr]    Compiling tracing v0.1.41
[INFO] [stderr]    Compiling prost v0.12.6
[INFO] [stderr]    Compiling tracing-perfetto v0.1.5 (/opt/rustwide/workdir)
[INFO] [stdout] warning: struct `PerfEvents` is never constructed
[INFO] [stdout]     --> src/perfetto.protos.rs:2284:12
[INFO] [stdout]      |
[INFO] [stdout] 2284 | pub struct PerfEvents {}
[INFO] [stdout]      |            ^^^^^^^^^^
[INFO] [stdout]      |
[INFO] [stdout]      = note: `#[warn(dead_code)]` (part of `#[warn(unused)]`) on by default
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stdout] warning: struct `Profiling` is never constructed
[INFO] [stdout]      --> src/perfetto.protos.rs:21163:12
[INFO] [stdout]       |
[INFO] [stdout] 21163 | pub struct Profiling {}
[INFO] [stdout]       |            ^^^^^^^^^
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stderr]     Finished `dev` profile [unoptimized + debuginfo] target(s) in 47.84s
[INFO] running `Command { std: "docker" "inspect" "e4bede52a0a7ca89654cabcd7d8ff33c29110b67c44f133e5934258c18a32344", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "e4bede52a0a7ca89654cabcd7d8ff33c29110b67c44f133e5934258c18a32344", kill_on_drop: false }`
[INFO] [stdout] e4bede52a0a7ca89654cabcd7d8ff33c29110b67c44f133e5934258c18a32344
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-0-tc2/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-0-tc2/source:/opt/rustwide/workdir:ro,Z" "-v" "/var/lib/crater-agent-workspace/cargo-home:/opt/rustwide/cargo-home:ro,Z" "-v" "/var/lib/crater-agent-workspace/rustup-home:/opt/rustwide/rustup-home:ro,Z" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_INCREMENTAL=0" "-e" "RUST_BACKTRACE=full" "-e" "RUSTFLAGS=--cap-lints=warn" "-e" "RUSTDOCFLAGS=--cap-lints=warn" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-w" "/opt/rustwide/workdir" "-m" "1610612736" "--user" "0:0" "--network" "none" "ghcr.io/rust-lang/crates-build-env/linux@sha256:4848fb76d95f26979359cc7e45710b1dbc8f3acb7aeedee7c460d7702230f228" "/opt/rustwide/cargo-home/bin/cargo" "+beta-2025-10-28" "test" "--frozen" "--no-run" "--message-format=json", kill_on_drop: false }`
[INFO] [stdout] 9e957f7b104af7ee5ae5b9c2bbd4833d9c83f89da36e7bbf916b894013186904
[INFO] running `Command { std: "docker" "start" "-a" "9e957f7b104af7ee5ae5b9c2bbd4833d9c83f89da36e7bbf916b894013186904", kill_on_drop: false }`
[INFO] [stderr]    Compiling parking_lot_core v0.9.12
[INFO] [stderr]    Compiling scopeguard v1.2.0
[INFO] [stderr]    Compiling mio v1.1.0
[INFO] [stderr]    Compiling signal-hook-registry v1.4.6
[INFO] [stderr]    Compiling socket2 v0.6.1
[INFO] [stderr]    Compiling tokio-macros v2.6.0
[INFO] [stdout] warning: struct `PerfEvents` is never constructed
[INFO] [stdout]     --> src/perfetto.protos.rs:2284:12
[INFO] [stdout]      |
[INFO] [stdout] 2284 | pub struct PerfEvents {}
[INFO] [stdout]      |            ^^^^^^^^^^
[INFO] [stdout]      |
[INFO] [stdout]      = note: `#[warn(dead_code)]` (part of `#[warn(unused)]`) on by default
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stdout] warning: struct `Profiling` is never constructed
[INFO] [stdout]      --> src/perfetto.protos.rs:21163:12
[INFO] [stdout]       |
[INFO] [stdout] 21163 | pub struct Profiling {}
[INFO] [stdout]       |            ^^^^^^^^^
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stderr]    Compiling lock_api v0.4.14
[INFO] [stderr]    Compiling parking_lot v0.12.5
[INFO] [stderr]    Compiling tokio v1.48.0
[INFO] [stderr]    Compiling tracing-perfetto v0.1.5 (/opt/rustwide/workdir)
[INFO] [stdout] warning: struct `PerfEvents` is never constructed
[INFO] [stdout]     --> src/perfetto.protos.rs:2284:12
[INFO] [stdout]      |
[INFO] [stdout] 2284 | pub struct PerfEvents {}
[INFO] [stdout]      |            ^^^^^^^^^^
[INFO] [stdout]      |
[INFO] [stdout]      = note: `#[warn(dead_code)]` (part of `#[warn(unused)]`) on by default
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stdout] warning: struct `Profiling` is never constructed
[INFO] [stdout]      --> src/perfetto.protos.rs:21163:12
[INFO] [stdout]       |
[INFO] [stdout] 21163 | pub struct Profiling {}
[INFO] [stdout]       |            ^^^^^^^^^
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stderr]     Finished `test` profile [unoptimized + debuginfo] target(s) in 39.75s
[INFO] running `Command { std: "docker" "inspect" "9e957f7b104af7ee5ae5b9c2bbd4833d9c83f89da36e7bbf916b894013186904", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "9e957f7b104af7ee5ae5b9c2bbd4833d9c83f89da36e7bbf916b894013186904", kill_on_drop: false }`
[INFO] [stdout] 9e957f7b104af7ee5ae5b9c2bbd4833d9c83f89da36e7bbf916b894013186904
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-0-tc2/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-0-tc2/source:/opt/rustwide/workdir:ro,Z" "-v" "/var/lib/crater-agent-workspace/cargo-home:/opt/rustwide/cargo-home:ro,Z" "-v" "/var/lib/crater-agent-workspace/rustup-home:/opt/rustwide/rustup-home:ro,Z" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_INCREMENTAL=0" "-e" "RUST_BACKTRACE=full" "-e" "RUSTFLAGS=--cap-lints=warn" "-e" "RUSTDOCFLAGS=--cap-lints=warn" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-w" "/opt/rustwide/workdir" "-m" "1610612736" "--user" "0:0" "--network" "none" "ghcr.io/rust-lang/crates-build-env/linux@sha256:4848fb76d95f26979359cc7e45710b1dbc8f3acb7aeedee7c460d7702230f228" "/opt/rustwide/cargo-home/bin/cargo" "+beta-2025-10-28" "test" "--frozen", kill_on_drop: false }`
[INFO] [stdout] f6be9d49b450f3e34f7f06875b22695768e2445a8388c6278ae5401b484ff12e
[INFO] running `Command { std: "docker" "start" "-a" "f6be9d49b450f3e34f7f06875b22695768e2445a8388c6278ae5401b484ff12e", kill_on_drop: false }`
[INFO] [stderr] warning: struct `PerfEvents` is never constructed
[INFO] [stderr]     --> src/perfetto.protos.rs:2284:12
[INFO] [stderr]      |
[INFO] [stderr] 2284 | pub struct PerfEvents {}
[INFO] [stderr]      |            ^^^^^^^^^^
[INFO] [stderr]      |
[INFO] [stderr]      = note: `#[warn(dead_code)]` (part of `#[warn(unused)]`) on by default
[INFO] [stderr] 
[INFO] [stderr] warning: struct `Profiling` is never constructed
[INFO] [stderr]      --> src/perfetto.protos.rs:21163:12
[INFO] [stderr]       |
[INFO] [stderr] 21163 | pub struct Profiling {}
[INFO] [stderr]       |            ^^^^^^^^^
[INFO] [stderr] 
[INFO] [stderr] warning: `tracing-perfetto` (lib) generated 2 warnings
[INFO] [stderr] warning: `tracing-perfetto` (lib test) generated 2 warnings (2 duplicates)
[INFO] [stderr]     Finished `test` profile [unoptimized + debuginfo] target(s) in 0.12s
[INFO] [stderr]      Running unittests src/lib.rs (/opt/rustwide/target/debug/deps/tracing_perfetto-148322f3d9d0966d)
[INFO] [stdout] 
[INFO] [stdout] running 0 tests
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 0 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s
[INFO] [stdout] 
[INFO] [stderr]      Running tests/log.rs (/opt/rustwide/target/debug/deps/log-a3bdfe1bbbe2db0e)
[INFO] [stdout] 
[INFO] [stdout] running 1 test
[INFO] [stdout] 2025-11-05T07:00:59.585182Z  INFO ThreadId(02) log: start file="/tmp/test.pftrace"
[INFO] [stdout] 2025-11-05T07:00:59.586800Z TRACE ThreadId(02) demo_span{regular_arg="Arg data"}: log: new
[INFO] [stdout] 2025-11-05T07:00:59.586937Z TRACE ThreadId(02) demo_span{regular_arg="Arg data"}: log: enter
[INFO] [stdout] 2025-11-05T07:00:59.586990Z  INFO ThreadId(02) demo_span{regular_arg="Arg data"}: log: in span
[INFO] [stdout] 2025-11-05T07:00:59.587105Z  INFO ThreadId(02) demo_span{regular_arg="Arg data"}:sync_fn{i=1 perfetto=true}: log: new
[INFO] [stdout] 2025-11-05T07:00:59.587190Z  INFO ThreadId(02) demo_span{regular_arg="Arg data"}:sync_fn{i=1 perfetto=true}: log: enter
[INFO] [stdout] 2025-11-05T07:00:59.587244Z  INFO ThreadId(02) demo_span{regular_arg="Arg data"}:sync_fn{i=1 perfetto=true}: log: inside function
[INFO] [stdout] 2025-11-05T07:00:59.587362Z TRACE ThreadId(02) demo_span{regular_arg="Arg data"}:sync_fn{i=1 perfetto=true}:sync_inner{perfetto=true}: log: new
[INFO] [stdout] 2025-11-05T07:00:59.587445Z TRACE ThreadId(02) demo_span{regular_arg="Arg data"}:sync_fn{i=1 perfetto=true}:sync_inner{perfetto=true}: log: enter
[INFO] [stdout] 2025-11-05T07:00:59.587529Z  INFO ThreadId(02) demo_span{regular_arg="Arg data"}:sync_fn{i=1 perfetto=true}:sync_inner{perfetto=true}: log: inner x=2
[INFO] [stdout] 2025-11-05T07:00:59.587629Z TRACE ThreadId(02) demo_span{regular_arg="Arg data"}:sync_fn{i=1 perfetto=true}:sync_inner{perfetto=true}: log: exit
[INFO] [stdout] 2025-11-05T07:00:59.587696Z TRACE ThreadId(02) demo_span{regular_arg="Arg data"}:sync_fn{i=1 perfetto=true}:sync_inner{perfetto=true}: log: close time.busy=184µs time.idle=151µs
[INFO] [stdout] 2025-11-05T07:00:59.587890Z  INFO ThreadId(02) demo_span{regular_arg="Arg data"}:sync_fn{i=1 perfetto=true}: log: exit
[INFO] [stdout] 2025-11-05T07:00:59.587956Z  INFO ThreadId(02) demo_span{regular_arg="Arg data"}:sync_fn{i=1 perfetto=true}: log: close time.busy=699µs time.idle=181µs
[INFO] [stdout] 2025-11-05T07:00:59.613114Z  INFO ThreadId(02) demo_span{regular_arg="Arg data"}:async_fn: log: new
[INFO] [stdout] 2025-11-05T07:00:59.613391Z  INFO ThreadId(02) demo_span{regular_arg="Arg data"}:async_fn: log: enter
[INFO] [stdout] 2025-11-05T07:00:59.613448Z  INFO ThreadId(02) demo_span{regular_arg="Arg data"}:async_fn: log: test perfetto=true
[INFO] [stdout] 2025-11-05T07:00:59.613541Z  INFO ThreadId(02) demo_span{regular_arg="Arg data"}:async_fn:async_inner: log: new
[INFO] [stdout] 2025-11-05T07:00:59.613623Z  INFO ThreadId(02) demo_span{regular_arg="Arg data"}:async_fn:async_inner: log: enter
[INFO] [stdout] 2025-11-05T07:00:59.613729Z  INFO ThreadId(02) demo_span{regular_arg="Arg data"}:async_fn:async_inner: log: exit
[INFO] [stdout] 2025-11-05T07:00:59.613777Z  INFO ThreadId(02) demo_span{regular_arg="Arg data"}:async_fn: log: exit
[INFO] [stdout] 2025-11-05T07:00:59.613845Z  INFO ThreadId(02) demo_span{regular_arg="Arg data"}:async_fn: log: new
[INFO] [stdout] 2025-11-05T07:00:59.613923Z  INFO ThreadId(02) demo_span{regular_arg="Arg data"}:async_fn: log: enter
[INFO] [stdout] 2025-11-05T07:00:59.613960Z  INFO ThreadId(02) demo_span{regular_arg="Arg data"}:async_fn: log: test perfetto=true
[INFO] [stdout] 2025-11-05T07:00:59.614027Z  INFO ThreadId(02) demo_span{regular_arg="Arg data"}:async_fn:async_inner: log: new
[INFO] [stdout] 2025-11-05T07:00:59.614103Z  INFO ThreadId(02) demo_span{regular_arg="Arg data"}:async_fn:async_inner: log: enter
[INFO] [stdout] 2025-11-05T07:00:59.614164Z  INFO ThreadId(02) demo_span{regular_arg="Arg data"}:async_fn:async_inner: log: exit
[INFO] [stdout] 2025-11-05T07:00:59.614215Z  INFO ThreadId(02) demo_span{regular_arg="Arg data"}:async_fn: log: exit
[INFO] [stdout] 2025-11-05T07:01:00.615717Z  INFO ThreadId(02) demo_span{regular_arg="Arg data"}:async_fn: log: enter
[INFO] [stdout] 2025-11-05T07:01:00.615874Z  INFO ThreadId(02) demo_span{regular_arg="Arg data"}:async_fn:async_inner: log: enter
[INFO] [stderr]    Doc-tests tracing_perfetto
[INFO] [stdout] 2025-11-05T07:01:00.615962Z  INFO ThreadId(02) demo_span{regular_arg="Arg data"}:async_fn:async_inner: log: exit
[INFO] [stdout] 2025-11-05T07:01:00.616016Z  INFO ThreadId(02) demo_span{regular_arg="Arg data"}:async_fn:async_inner: log: enter
[INFO] [stdout] 2025-11-05T07:01:00.616056Z  INFO ThreadId(02) demo_span{regular_arg="Arg data"}:async_fn:async_inner: log: exit
[INFO] [stdout] 2025-11-05T07:01:00.616093Z  INFO ThreadId(02) demo_span{regular_arg="Arg data"}:async_fn:async_inner: log: close time.busy=236µs time.idle=1.00s
[INFO] [stdout] 2025-11-05T07:01:00.616427Z  INFO ThreadId(02) demo_span{regular_arg="Arg data"}:async_fn: log: exit
[INFO] [stdout] 2025-11-05T07:01:00.616499Z  INFO ThreadId(02) demo_span{regular_arg="Arg data"}:async_fn: log: enter
[INFO] [stdout] 2025-11-05T07:01:00.616540Z  INFO ThreadId(02) demo_span{regular_arg="Arg data"}:async_fn: log: exit
[INFO] [stdout] 2025-11-05T07:01:00.616574Z  INFO ThreadId(02) demo_span{regular_arg="Arg data"}:async_fn: log: close time.busy=1.15ms time.idle=1.00s
[INFO] [stdout] 2025-11-05T07:01:00.616797Z  INFO ThreadId(02) demo_span{regular_arg="Arg data"}:async_fn: log: enter
[INFO] [stdout] 2025-11-05T07:01:00.616872Z  INFO ThreadId(02) demo_span{regular_arg="Arg data"}:async_fn:async_inner: log: enter
[INFO] [stdout] 2025-11-05T07:01:00.616930Z  INFO ThreadId(02) demo_span{regular_arg="Arg data"}:async_fn:async_inner: log: exit
[INFO] [stdout] 2025-11-05T07:01:00.616982Z  INFO ThreadId(02) demo_span{regular_arg="Arg data"}:async_fn:async_inner: log: enter
[INFO] [stdout] 2025-11-05T07:01:00.617030Z  INFO ThreadId(02) demo_span{regular_arg="Arg data"}:async_fn:async_inner: log: exit
[INFO] [stdout] 2025-11-05T07:01:00.617068Z  INFO ThreadId(02) demo_span{regular_arg="Arg data"}:async_fn:async_inner: log: close time.busy=166µs time.idle=1.00s
[INFO] [stdout] 2025-11-05T07:01:00.617201Z  INFO ThreadId(02) demo_span{regular_arg="Arg data"}:async_fn: log: exit
[INFO] [stdout] 2025-11-05T07:01:00.617261Z  INFO ThreadId(02) demo_span{regular_arg="Arg data"}:async_fn: log: enter
[INFO] [stdout] 2025-11-05T07:01:00.617303Z  INFO ThreadId(02) demo_span{regular_arg="Arg data"}:async_fn: log: exit
[INFO] [stdout] 2025-11-05T07:01:00.617373Z  INFO ThreadId(02) demo_span{regular_arg="Arg data"}:async_fn: log: close time.busy=740µs time.idle=1.00s
[INFO] [stdout] 2025-11-05T07:01:00.617594Z TRACE ThreadId(02) demo_span{regular_arg="Arg data" extra_arg="Some Extra Data" regular_arg="New Arg Data"}: log: exit
[INFO] [stdout] 2025-11-05T07:01:00.617657Z TRACE ThreadId(02) demo_span{regular_arg="Arg data" extra_arg="Some Extra Data" regular_arg="New Arg Data"}: log: close time.busy=1.03s time.idle=205µs
[INFO] [stdout] test write ... ok
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 1.04s
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stdout] running 2 tests
[INFO] [stdout] test src/lib.rs - PerfettoLayer<W>::with_filter_by_marker (line 83) ... ok
[INFO] [stdout] test src/lib.rs - (line 11) ... ok
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 2 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 4.52s
[INFO] [stdout] 
[INFO] running `Command { std: "docker" "inspect" "f6be9d49b450f3e34f7f06875b22695768e2445a8388c6278ae5401b484ff12e", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "f6be9d49b450f3e34f7f06875b22695768e2445a8388c6278ae5401b484ff12e", kill_on_drop: false }`
[INFO] [stdout] f6be9d49b450f3e34f7f06875b22695768e2445a8388c6278ae5401b484ff12e