A span represents an operation of some sort. They often map to a region of code but they don't have to. Spans can have data attached to them, and can be nested. Events are associated with the current active spans, and can also have data attached to them in addition to the data attached to the spans that are active.
A simple way to model your problem with tracing would be to have a game span with some sort of ID attached to it, and to attach a user ID to all of the events that apply to specific users
use tracing::Level;
fn main() {
tracing_subscriber::fmt().init();
// Construct and enter a span manually.
let span = tracing::span!(Level::INFO, "game", id = 12);
let _guard = span.enter();
startup();
tracing::info!(player = 2, action = "foo");
tracing::info!(player = 0, action = "bar");
tracing::info!(player = 3, action = "baz");
}
// Or let the proc macro construct the span for a function for you
#[tracing::instrument]
fn startup() {
for i in 0..4 {
tracing::info!(player = i, "Log in succeeded");
}
tracing::info!("Start up completed")
}
Using the default tracing-subscriber
formatter there gets you
2023-04-23T19:14:16.973787Z INFO game{id=12}:startup: main: Log in succeeded player=0
2023-04-23T19:14:16.973964Z INFO game{id=12}:startup: main: Log in succeeded player=1
2023-04-23T19:14:16.974102Z INFO game{id=12}:startup: main: Log in succeeded player=2
2023-04-23T19:14:16.974179Z INFO game{id=12}:startup: main: Log in succeeded player=3
2023-04-23T19:14:16.974247Z INFO game{id=12}:startup: main: Start up completed
2023-04-23T19:14:16.974379Z INFO game{id=12}: main: player=2 action="foo"
2023-04-23T19:14:16.974479Z INFO game{id=12}: main: player=0 action="bar"
2023-04-23T19:14:16.974560Z INFO game{id=12}: main: player=3 action="baz"
If you're consistent about how you specify ids and such, it's pretty easy to search through the log file for what you're looking for. There's also a built in JSON formatter
{"timestamp":"2023-04-23T19:16:17.092361Z","level":"INFO","fields":{"message":"Log in succeeded","player":0},"target":"main","span":{"name":"startup"},"spans":[{"id":12,"name":"game"},{"name":"startup"}]}
{"timestamp":"2023-04-23T19:16:17.092647Z","level":"INFO","fields":{"message":"Log in succeeded","player":1},"target":"main","span":{"name":"startup"},"spans":[{"id":12,"name":"game"},{"name":"startup"}]}
{"timestamp":"2023-04-23T19:16:17.092801Z","level":"INFO","fields":{"message":"Log in succeeded","player":2},"target":"main","span":{"name":"startup"},"spans":[{"id":12,"name":"game"},{"name":"startup"}]}
{"timestamp":"2023-04-23T19:16:17.092892Z","level":"INFO","fields":{"message":"Log in succeeded","player":3},"target":"main","span":{"name":"startup"},"spans":[{"id":12,"name":"game"},{"name":"startup"}]}
{"timestamp":"2023-04-23T19:16:17.092977Z","level":"INFO","fields":{"message":"Start up completed"},"target":"main","span":{"name":"startup"},"spans":[{"id":12,"name":"game"},{"name":"startup"}]}
{"timestamp":"2023-04-23T19:16:17.093118Z","level":"INFO","fields":{"player":2,"action":"foo"},"target":"main","span":{"id":12,"name":"game"},"spans":[{"id":12,"name":"game"}]}
{"timestamp":"2023-04-23T19:16:17.093225Z","level":"INFO","fields":{"player":0,"action":"bar"},"target":"main","span":{"id":12,"name":"game"},"spans":[{"id":12,"name":"game"}]}
{"timestamp":"2023-04-23T19:16:17.093455Z","level":"INFO","fields":{"player":3,"action":"baz"},"target":"main","span":{"id":12,"name":"game"},"spans":[{"id":12,"name":"game"}]}
That's obviously much harder to read directly, but it gives you a lot of flexibility in searching for logs programmatically.