Test async_fn_with_async_trait fails

[lenaschoenburg]

Version

Current master, tracing version 0.2.0

Platform

$ uname -a
Linux a6bea2cb28d9 5.10.16-200.fc33.x86_64 #1 SMP Sun Feb 14 03:02:32 UTC 2021 x86_64 GNU/Linux`
$ rustc --version 
rustc 1.52.0-nightly (234781afe 2021-03-07)

Crates

This is a test in the tracing-attributes crate.

Description

Running tests for the tracing-attributes crate like this:

cd tracing-attributes/
RUST_BACKTRACE=1 cargo test

fails on my machine:

root ➜ /workspaces/tracing/tracing-attributes (fix-pretty-with-log-meta) $ RUST_BACKTRACE=1 cargo test
warning: unnecessary braces around block return value
   --> tracing-attributes/tests/async_fn.rs:176:44
    |
176 |         async fn call(&mut self, v: usize) {}
    |                                            ^^ help: remove these braces
    |
    = note: `#[warn(unused_braces)]` on by default

warning: unnecessary braces around block return value
   --> tracing-attributes/tests/async_fn.rs:223:40
    |
223 |         async fn call_with_self(&self) {}
    |                                        ^^ help: remove these braces

warning: unnecessary braces around block return value
   --> tracing-attributes/tests/async_fn.rs:226:48
    |
226 |         async fn call_with_mut_self(&mut self) {}
    |                                                ^^ help: remove these braces

warning: unused variable: `v`
   --> tracing-attributes/tests/async_fn.rs:176:34
    |
176 |         async fn call(&mut self, v: usize) {}
    |                                  ^ help: if this is intentional, prefix it with an underscore: `_v`
    |
    = note: `#[warn(unused_variables)]` on by default

warning: 4 warnings emitted

    Finished test [unoptimized + debuginfo] target(s) in 0.10s
     Running /workspaces/tracing/target/debug/deps/tracing_attributes-d01e8e7b4cc9956a

running 0 tests

test result: ok. 0 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out

     Running /workspaces/tracing/target/debug/deps/async_fn-22788547df2f4800

running 5 tests
test async_fn_with_async_trait_and_fields_expressions ... ok
test async_fn_only_enters_for_polls ... ok
test async_fn_nested ... ok
test async_fn_with_async_trait_and_fields_expressions_with_generic_parameter ... ok
test async_fn_with_async_trait ... FAILED

failures:

---- async_fn_with_async_trait stdout ----
[async_fn_nested] register_callsite: Metadata {
    name: "event tracing-attributes/tests/async_fn.rs:13",
    target: "async_fn",
    level: Level(
        Trace,
    ),
    module_path: "async_fn",
    location: tracing-attributes/tests/async_fn.rs:13,
    fields: {awaiting},
    callsite: Identifier(0x559c283f2080),
    kind: Kind(
        Event,
    ),
}
[async_fn_nested] enabled: Metadata {
    name: "event tracing-attributes/tests/async_fn.rs:13",
    target: "async_fn",
    level: Level(
        Trace,
    ),
    module_path: "async_fn",
    location: tracing-attributes/tests/async_fn.rs:13,
    fields: {awaiting},
    callsite: Identifier(0x559c283f2080),
    kind: Kind(
        Event,
    ),
}
[async_fn_nested] enabled -> true
[async_fn_only_enters_for_polls] register_callsite: Metadata {
    name: "event tracing-attributes/tests/async_fn.rs:13",
    target: "async_fn",
    level: Level(
        Trace,
    ),
    module_path: "async_fn",
    location: tracing-attributes/tests/async_fn.rs:13,
    fields: {awaiting},
    callsite: Identifier(0x559c283f2080),
    kind: Kind(
        Event,
    ),
}
[async_fn_only_enters_for_polls] enabled: Metadata {
    name: "event tracing-attributes/tests/async_fn.rs:13",
    target: "async_fn",
    level: Level(
        Trace,
    ),
    module_path: "async_fn",
    location: tracing-attributes/tests/async_fn.rs:13,
    fields: {awaiting},
    callsite: Identifier(0x559c283f2080),
    kind: Kind(
        Event,
    ),
}
[async_fn_only_enters_for_polls] enabled -> true
[async_fn_with_async_trait] register_callsite: Metadata {
    name: "event tracing-attributes/tests/async_fn.rs:13",
    target: "async_fn",
    level: Level(
        Trace,
    ),
    module_path: "async_fn",
    location: tracing-attributes/tests/async_fn.rs:13,
    fields: {awaiting},
    callsite: Identifier(0x559c283f2080),
    kind: Kind(
        Event,
    ),
}
[async_fn_with_async_trait] enabled: Metadata {
    name: "event tracing-attributes/tests/async_fn.rs:13",
    target: "async_fn",
    level: Level(
        Trace,
    ),
    module_path: "async_fn",
    location: tracing-attributes/tests/async_fn.rs:13,
    fields: {awaiting},
    callsite: Identifier(0x559c283f2080),
    kind: Kind(
        Event,
    ),
}
[async_fn_with_async_trait] enabled -> true
[async_fn_nested] register_callsite: Metadata {
    name: "test_async_fns_nested_other",
    target: "async_fn",
    level: Level(
        Info,
    ),
    module_path: "async_fn",
    location: tracing-attributes/tests/async_fn.rs:42,
    fields: {},
    callsite: Identifier(0x559c283f20f0),
    kind: Kind(
        Span,
    ),
}
[async_fn_nested] enabled: Metadata {
    name: "test_async_fns_nested_other",
    target: "async_fn",
    level: Level(
        Info,
    ),
    module_path: "async_fn",
    location: tracing-attributes/tests/async_fn.rs:42,
    fields: {},
    callsite: Identifier(0x559c283f20f0),
    kind: Kind(
        Span,
    ),
}
[async_fn_nested] enabled -> true
[async_fn_with_async_trait] register_callsite: Metadata {
    name: "test_async_fns_nested_other",
    target: "async_fn",
    level: Level(
        Info,
    ),
    module_path: "async_fn",
    location: tracing-attributes/tests/async_fn.rs:42,
    fields: {},
    callsite: Identifier(0x559c283f20f0),
    kind: Kind(
        Span,
    ),
}
[async_fn_with_async_trait] enabled: Metadata {
    name: "test_async_fns_nested_other",
    target: "async_fn",
    level: Level(
        Info,
    ),
    module_path: "async_fn",
    location: tracing-attributes/tests/async_fn.rs:42,
    fields: {},
    callsite: Identifier(0x559c283f20f0),
    kind: Kind(
        Span,
    ),
}
[async_fn_with_async_trait] enabled -> true
[async_fn_nested] register_callsite: Metadata {
    name: "call",
    target: "async_fn",
    level: Level(
        Info,
    ),
    module_path: "async_fn",
    location: tracing-attributes/tests/async_fn.rs:175,
    fields: {self, v, val, test},
    callsite: Identifier(0x559c283f21d0),
    kind: Kind(
        Span,
    ),
}
[async_fn_nested] enabled: Metadata {
    name: "call",
    target: "async_fn",
    level: Level(
        Info,
    ),
    module_path: "async_fn",
    location: tracing-attributes/tests/async_fn.rs:175,
    fields: {self, v, val, test},
    callsite: Identifier(0x559c283f21d0),
    kind: Kind(
        Span,
    ),
}
[async_fn_nested] enabled -> true
[async_fn_with_async_trait] register_callsite: Metadata {
    name: "call",
    target: "async_fn",
    level: Level(
        Info,
    ),
    module_path: "async_fn",
    location: tracing-attributes/tests/async_fn.rs:175,
    fields: {self, v, val, test},
    callsite: Identifier(0x559c283f21d0),
    kind: Kind(
        Span,
    ),
}
[async_fn_with_async_trait] enabled: Metadata {
    name: "call",
    target: "async_fn",
    level: Level(
        Info,
    ),
    module_path: "async_fn",
    location: tracing-attributes/tests/async_fn.rs:175,
    fields: {self, v, val, test},
    callsite: Identifier(0x559c283f21d0),
    kind: Kind(
        Span,
    ),
}
[async_fn_with_async_trait] enabled -> true
[async_fn_nested] register_callsite: Metadata {
    name: "test_async_fn",
    target: "async_fn",
    level: Level(
        Info,
    ),
    module_path: "async_fn",
    location: tracing-attributes/tests/async_fn.rs:10,
    fields: {polls},
    callsite: Identifier(0x559c283f2048),
    kind: Kind(
        Span,
    ),
}
[async_fn_nested] enabled: Metadata {
    name: "test_async_fn",
    target: "async_fn",
    level: Level(
        Info,
    ),
    module_path: "async_fn",
    location: tracing-attributes/tests/async_fn.rs:10,
    fields: {polls},
    callsite: Identifier(0x559c283f2048),
    kind: Kind(
        Span,
    ),
}
[async_fn_nested] enabled -> true
[async_fn_with_async_trait] register_callsite: Metadata {
    name: "test_async_fn",
    target: "async_fn",
    level: Level(
        Info,
    ),
    module_path: "async_fn",
    location: tracing-attributes/tests/async_fn.rs:10,
    fields: {polls},
    callsite: Identifier(0x559c283f2048),
    kind: Kind(
        Span,
    ),
}
[async_fn_with_async_trait] enabled: Metadata {
    name: "test_async_fn",
    target: "async_fn",
    level: Level(
        Info,
    ),
    module_path: "async_fn",
    location: tracing-attributes/tests/async_fn.rs:10,
    fields: {polls},
    callsite: Identifier(0x559c283f2048),
    kind: Kind(
        Span,
    ),
}
[async_fn_with_async_trait] enabled -> true
[async_fn_nested] register_callsite: Metadata {
    name: "test_async_fns_nested",
    target: "async_fn",
    level: Level(
        Info,
    ),
    module_path: "async_fn",
    location: tracing-attributes/tests/async_fn.rs:37,
    fields: {},
    callsite: Identifier(0x559c283f20b8),
    kind: Kind(
        Span,
    ),
}
[async_fn_nested] enabled: Metadata {
    name: "test_async_fns_nested",
    target: "async_fn",
    level: Level(
        Info,
    ),
    module_path: "async_fn",
    location: tracing-attributes/tests/async_fn.rs:37,
    fields: {},
    callsite: Identifier(0x559c283f20b8),
    kind: Kind(
        Span,
    ),
}
[async_fn_nested] enabled -> true
[async_fn_with_async_trait] register_callsite: Metadata {
    name: "test_async_fns_nested",
    target: "async_fn",
    level: Level(
        Info,
    ),
    module_path: "async_fn",
    location: tracing-attributes/tests/async_fn.rs:37,
    fields: {},
    callsite: Identifier(0x559c283f20b8),
    kind: Kind(
        Span,
    ),
}
[async_fn_with_async_trait] enabled: Metadata {
    name: "test_async_fns_nested",
    target: "async_fn",
    level: Level(
        Info,
    ),
    module_path: "async_fn",
    location: tracing-attributes/tests/async_fn.rs:37,
    fields: {},
    callsite: Identifier(0x559c283f20b8),
    kind: Kind(
        Span,
    ),
}
[async_fn_with_async_trait] enabled -> true
[async_fn_nested] register_callsite: Metadata {
    name: "fake",
    target: "async_fn::support::support::field",
    level: Level(
        Trace,
    ),
    module_path: "async_fn::support::support::field",
    location: tracing-attributes/tests/../../tracing-futures/tests/../../tracing/tests/support/field.rs:204,
    fields: {fake_field},
    callsite: Identifier(0x559c283f2028),
    kind: Kind(
        Event,
    ),
}
[async_fn_nested] enabled: Metadata {
    name: "fake",
    target: "async_fn::support::support::field",
    level: Level(
        Trace,
    ),
    module_path: "async_fn::support::support::field",
    location: tracing-attributes/tests/../../tracing-futures/tests/../../tracing/tests/support/field.rs:204,
    fields: {fake_field},
    callsite: Identifier(0x559c283f2028),
    kind: Kind(
        Event,
    ),
}
[async_fn_nested] enabled -> true
[async_fn_with_async_trait] register_callsite: Metadata {
    name: "fake",
    target: "async_fn::support::support::field",
    level: Level(
        Trace,
    ),
    module_path: "async_fn::support::support::field",
    location: tracing-attributes/tests/../../tracing-futures/tests/../../tracing/tests/support/field.rs:204,
    fields: {fake_field},
    callsite: Identifier(0x559c283f2028),
    kind: Kind(
        Event,
    ),
}
[async_fn_with_async_trait] enabled: Metadata {
    name: "fake",
    target: "async_fn::support::support::field",
    level: Level(
        Trace,
    ),
    module_path: "async_fn::support::support::field",
    location: tracing-attributes/tests/../../tracing-futures/tests/../../tracing/tests/support/field.rs:204,
    fields: {fake_field},
    callsite: Identifier(0x559c283f2028),
    kind: Kind(
        Event,
    ),
}
[async_fn_with_async_trait] enabled -> true
[async_fn_nested] register_callsite: Metadata {
    name: "foo",
    target: "async_fn",
    level: Level(
        Info,
    ),
    module_path: "async_fn",
    location: tracing-attributes/tests/async_fn.rs:97,
    fields: {self, v},
    callsite: Identifier(0x559c283f22e8),
    kind: Kind(
        Span,
    ),
}
[async_fn_nested] enabled: Metadata {
    name: "foo",
    target: "async_fn",
    level: Level(
        Info,
    ),
    module_path: "async_fn",
    location: tracing-attributes/tests/async_fn.rs:97,
    fields: {self, v},
    callsite: Identifier(0x559c283f22e8),
    kind: Kind(
        Span,
    ),
}
[async_fn_nested] enabled -> true
[async_fn_with_async_trait] register_callsite: Metadata {
    name: "foo",
    target: "async_fn",
    level: Level(
        Info,
    ),
    module_path: "async_fn",
    location: tracing-attributes/tests/async_fn.rs:97,
    fields: {self, v},
    callsite: Identifier(0x559c283f22e8),
    kind: Kind(
        Span,
    ),
}
[async_fn_with_async_trait] enabled: Metadata {
    name: "foo",
    target: "async_fn",
    level: Level(
        Info,
    ),
    module_path: "async_fn",
    location: tracing-attributes/tests/async_fn.rs:97,
    fields: {self, v},
    callsite: Identifier(0x559c283f22e8),
    kind: Kind(
        Span,
    ),
}
[async_fn_with_async_trait] enabled -> true
[async_fn_with_async_trait] new_span: name="foo"; target="async_fn"; id=Id(1);
[async_fn_with_async_trait] enter: foo; id=Id(1);
[async_fn_with_async_trait] exit: foo; id=Id(1);
thread 'async_fn_with_async_trait' panicked at '[async_fn_with_async_trait] expected a new span named `baz` but exited span "foo" instead', tracing-attributes/tests/../../tracing-futures/tests/../../tracing/tests/support/collector.rs:555:35
stack backtrace:
   0: rust_begin_unwind
             at /rustc/e1884a8e3c3e813aada8254edfa120e85bf5ffca/library/std/src/panicking.rs:495:5
   1: std::panicking::begin_panic_fmt
             at /rustc/e1884a8e3c3e813aada8254edfa120e85bf5ffca/library/std/src/panicking.rs:437:5
   2: async_fn::support::support::collector::Expect::bad
             at ./tests/../../tracing-futures/tests/../../tracing/tests/support/collector.rs:555:35
   3: <async_fn::support::support::collector::Running<F> as tracing_core::collect::Collect>::exit
             at ./tests/../../tracing-futures/tests/../../tracing/tests/support/collector.rs:443:25
   4: tracing_core::dispatch::Dispatch::exit
             at /workspaces/tracing/tracing-core/src/dispatch.rs:705:9
   5: tracing::span::Span::do_exit
             at /workspaces/tracing/tracing/src/span.rs:937:13
   6: <tracing::span::Entered as core::ops::drop::Drop>::drop
             at /workspaces/tracing/tracing/src/span.rs:1419:9
   7: core::ptr::drop_in_place
             at /usr/local/rustup/toolchains/1.49-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/core/src/ptr/mod.rs:175:1
   8: <async_fn::async_fn_with_async_trait::TestImpl as async_fn::async_fn_with_async_trait::TestA>::foo
             at ./tests/async_fn.rs:97:21
   9: async_fn::async_fn_with_async_trait::{{closure}}::{{closure}}
             at ./tests/async_fn.rs:148:33
  10: <core::future::from_generator::GenFuture<T> as core::future::future::Future>::poll
             at /usr/local/rustup/toolchains/1.49-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/core/src/future/mod.rs:80:19
  11: tokio_test::task::Spawn<T>::poll::{{closure}}
             at /usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/tokio-test-0.2.1/src/task.rs:107:30
  12: tokio_test::task::MockTask::enter
             at /usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/tokio-test-0.2.1/src/task.rs:159:9
  13: tokio_test::task::Spawn<T>::poll
             at /usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/tokio-test-0.2.1/src/task.rs:107:9
  14: async_fn::support::block_on_future
             at ./tests/../../tracing-futures/tests/support.rs:65:33
  15: async_fn::async_fn_with_async_trait::{{closure}}
             at ./tests/async_fn.rs:148:9
  16: tracing_core::dispatch::with_default
             at /workspaces/tracing/tracing-core/src/dispatch.rs:266:5
  17: tracing::collect::with_default
             at /workspaces/tracing/tracing/src/collect.rs:24:5
  18: async_fn::async_fn_with_async_trait
             at ./tests/async_fn.rs:146:5
  19: async_fn::async_fn_with_async_trait::{{closure}}
             at ./tests/async_fn.rs:70:1
  20: core::ops::function::FnOnce::call_once
             at /usr/local/rustup/toolchains/1.49-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/core/src/ops/function.rs:227:5
  21: core::ops::function::FnOnce::call_once
             at /rustc/e1884a8e3c3e813aada8254edfa120e85bf5ffca/library/core/src/ops/function.rs:227:5
note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.
[async_fn_with_async_trait] drop_span: id=Id(1)


failures:
    async_fn_with_async_trait

I'm fairly certain that I already had this test failing a week ago but that it was working fine once a ran cargo test again. I've also tested with older rustc versions and get the same result with 1.49 and 1.50.

[hawkw]

This will be fixed by #1228

[hawkw]

Fixed in #1228.