message_span_propogation broke top span reporting?

[kanru]

Describe the bug I'm not sure if it's my configuration issue. With the default tracing-subscriber formatter, I can only see one actor in the log and it's not the correct actor when message_span_propogation is enabled.

With message_span_propogation

2025-01-07T12:16:42.329762Z  INFO Actor{id="0.3" name="A8sMLi"}:handle:handle: raft: received request for vote from=A8sMLi myself=1rms8t current_term=0

Without message_span_propogation

2025-01-07T12:21:15.619959Z  INFO Actor{id="0.2" name="WcN4nY"}:handle: raft: received request for vote from=D9ez05 myself=WcN4nY current_term=0

Notice the myself field, it should match the name in the span, not the message's originator.

To Reproduce Steps to reproduce the behavior:

1. Initialize tracing with tracing_subscriber::fmt::init();
2. Setup some actors
3. Send a message from one actor to another

Expected behavior

The span in the log should print the correct actor_id and name of the handling actor

Additional context

├── ractor v0.14.3
├── ractor_cluster v0.14.3
├── tokio v1.42.0
├── tracing v0.1.41
└── tracing-subscriber v0.3.19

BTW, I had to patch ractor_cluster to disable message_span_propogation.

[kanru]

I feel it should use follows_from instead, as described in https://github.com/tokio-rs/tracing/issues/80#issuecomment-465654414

The handler future has a current span from the processing_loop, but it follows from the sender's processing_loop.

[slawlor]

do you have a repro available? it's difficult to see what's going on here, but process-internal actor casualty may be possible with follows_from, however we'd need to see what happens with the span's fields.

[kanru]

I got a minimum reproducer https://github.com/kanru/ractor-316. Just need to clone it and cargo run

Expected output:

2025-01-08T00:15:04.410460Z  INFO Actor{id="0.1"}: club: got ping from=0.0 myself=0.1
2025-01-08T00:15:05.411834Z  INFO Actor{id="0.0"}: club: got pong from=0.1 myself=0.0
2025-01-08T00:15:06.414860Z  INFO Actor{id="0.1"}: club: got ping from=0.0 myself=0.1
2025-01-08T00:15:07.416635Z  INFO Actor{id="0.0"}: club: got pong from=0.1 myself=0.0
2025-01-08T00:15:08.418443Z  INFO Actor{id="0.1"}: club: got ping from=0.0 myself=0.1
^C

Actual

2025-01-08T00:15:48.018419Z  INFO Actor{id="0.1"}: club: got ping from=0.0 myself=0.1
2025-01-08T00:15:49.020422Z  INFO Actor{id="0.1"}: club: got pong from=0.1 myself=0.0
2025-01-08T00:15:50.021012Z  INFO Actor{id="0.1"}: club: got ping from=0.0 myself=0.1
2025-01-08T00:15:51.022498Z  INFO Actor{id="0.1"}: club: got pong from=0.1 myself=0.0
2025-01-08T00:15:52.024314Z  INFO Actor{id="0.1"}: club: got ping from=0.0 myself=0.1
^C

Interestingly it seems only ractor::cast! exhibit this issue. If I use actor_ref.send_after() then the log looks as expected.

[slawlor]

I've asked someone from Tracing to help out on this one for best practices. They're going to take oa look when they have a chance CC: @davidbarsky.