Logs and tracing in Rust: Structured Fields and Spans
Caroline Morton
May 22, 2026
This blog post is the second part of a 3 part series on logging and tracing in Rust. The first part is here and the third part is here. This series accompanies my Women in Rust talk on this topic but should stand alone as a reference. If you are brand new to logging and tracing, I would recommend starting with the first part, but if you are already familiar with the basics of using logging macros in rust and want to learn about spans and fields, then this post is a good starting point. In this post we are going to be covering: what are spans and fields, how to use them in your Rust projects, and some best practices for using them effectively.
The code for this post is available in this repository if you want to try it out yourself.
Structured vs Unstructured Logging
In the last post, I tried to convince you that using print statements limits your ability to understand what is happening in your code. One of the main reasons for this is that print statements are unstructured, meaning that they are just strings of text that are printed to the console. Logs on the other hand are meant to be structured but they can be used in an unstructured way. The usefulness of logs can be limited by not putting in enough information. For the rest of this blog post, I am going to be using simplified examples from my own work on synthetic data generation in healthcare. Let’s imagine we have a rust project that generates synthetic patient records and then needs to write them to a sqlite database. We want to log any errors that occur when we are writing to the database. If we just use a simple log message without any structured fields, we might end up with something like this:
For example, this code snippet is using the tracing crate to log an error message:
fn main() {
tracing_subscriber::fmt().init();
tracing::error!("database connection failed");
}
The emitted log message will be unstructured and look something like this:
[2026-05-21T12:00:00Z ERROR my_crate] database connection failed
Ok, so it is useful in the sense that you are getting some information about what is happening in your code but aside from the timestamp and log level, it isn’t giving you much more than a print statement. Can we really tell if the database is missing, if the credentials are wrong, if there is a network issue, or if the database is just overloaded in some way? No, we can’t. We have no context on what the error was, what database we were trying to connect to, or how many times we have tried to connect. This is the problem with unstructured logging. It is also reliant on you the programmer having written a good error message, that is correct. We are not allowing the underlying error to bubble up and be part of the log message.
We could improve this by interpolating values into the string, the same way you might with println!:
tracing::error!("database connection failed for host {} after {} retries: {}", host, retries, err);
This gives us:
[2026-05-21T12:00:00Z ERROR my_crate] database connection failed for host localhost after 3 retries: connection refused
That is better. We can see which host we were trying to connect to, how many retries we attempted and what the error was. But the information is still baked into a string. If you are looking at this in Grafana Loki or Datadog, you would have to parse this string to extract the host, the number of retries, or the error message. You cannot easily filter for “show me all errors where retries > 2” or “show me all errors for host localhost” because those values are not fields, they are just substrings in a message.
Structured Fields
This is where structured fields come in. Instead of writing values into a string, you can just attach key-value pairs to your log events. These key-value pairs are called fields and they are the thing that makes structured logging structured. Here is the same log line, but using structured fields.
tracing::error!(
database = %database_url,
patient_id = %patient_id,
error = %err,
"failed to write synthetic patient to reference database"
);
The human-readable output from tracing_subscriber::fmt() will look something like this (note I have wrapped this for readability, in your terminal it will appear on a single line):
[2026-05-21T12:00:00Z ERROR my_crate]
failed to write synthetic patient to reference database
database=postgres://db:5432/reference
patient_id=a0c7e4a-3f1d-4b5e-9c2f-8d6b3e1a7f04
error=connection refused
It does not look radically different in the terminal, but the difference is significant. The fields database, patient_id, and error are now separate, typed pieces of data rather than substrings in a message. We can use the tracing subscriber to output these logs in a structured format like JSON, which is what most log aggregation tools expect. If you are using tracing_subscriber::fmt(), you can enable JSON output like this:
tracing_subscriber::fmt().json().init();
If we do this, the emitted log message will look something like this:
{
"timestamp": "2026-05-21T12:00:00Z",
"level": "ERROR",
"target": "my_crate",
"message": "failed to write synthetic patient to reference database",
"database": "postgres://db:5432/reference",
"patient_id": "a0c7e4a-3f1d-4b5e-9c2f-8d6b3e1a7f04",
"error": "connection refused"
}
Now database, patient_id, and error are individual JSON keys. You can filter, search, and alert on them independently. “Show me all errors for patient a0c7e4a-3f1d-4b5e-9c2f-8d6b3e1a7f04” or “show me all connection refused errors in the last hour” become straightforward queries in your log aggregation tool.
We can still add in additional information in the message string and I would encourage that you do that for human readability. You put the fields before the message string in the macro call, and then add in some useful information in the message string that will be helpful when you are looking at the logs in the terminal. For example:
tracing::info!(patient_id = %patient_id, age = age, "generated synthetic patient");
tracing::warn!(queue_depth = queue.len(), "patient write queue length");
tracing::debug!(query = %sql, rows_written = count, "batch insert completed");
A few things to notice about the syntax. The field names are on the left of the = sign and the values are on the right. The message string always comes last. And some of the values have a % symbol in front of them while others do not. That brings us to an important topic: how tracing decides to format your field values.
Display vs Debug
You might have noticed the % symbol in front of some of the field values in the examples above. This is not just decoration, it tells tracing how to format that value. There are two formatting modes:
%uses theDisplaytrait (i.e.fmt::Display). This is the human-readable representation of a value. It is the same formatting you get when you use{}in aprintln!.?uses theDebugtrait (i.e.fmt::Debug). This is the programmer-oriented representation of a value. It is the same formatting you get when you use{:?}in aprintln!.
If you do not specify either % or ?, tracing will use the value directly. This works for primitive types like integers, booleans and floats, but for most other types you will need to specify one or the other.
Let’s look at a concrete example. Suppose we have a struct representing a synthetic patient that we want to write to a reference database:
use uuid::Uuid;
#[derive(Debug)]
struct Patient {
id: Uuid,
age: u8,
sex: String,
diagnosis_codes: Vec<String>,
}
impl std::fmt::Display for Patient {
fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
write!(f, "Patient({}, age {}, {:?})", self.id, self.age, self.diagnosis_codes)
}
}
Now let’s log it using both formatting modes:
// Using Display (%)
tracing::info!(patient = %patient, "writing synthetic patient to reference database");
// Using Debug (?)
tracing::info!(patient = ?patient, "writing synthetic patient to reference database");
The Display version will output (I have wrapped this again for readability):
2026-05-22T10:09:29.017462Z INFO first_setup:
writing synthetic patient to reference database
patient=Patient { id: 9ad9544e-0b74-4e36-b1ff-0c2e6d70837c,
age: 67,
sex: "F",
diagnosis_codes: ["E11.9"]
}
The Debug version will output:
2026-05-22T10:09:29.017290Z INFO first_setup:
writing synthetic patient to reference database
patient=Patient(9ad9544e-0b74-4e36-b1ff-0c2e6d70837c, age 67, ["E11.9"])
The Display output is cleaner, more customisable and therefore in theory more readable because it is tailored to the specific struct by the impl Display block. The Debug output is more verbose and less customisable. It is the default representation of the struct and is not necessarily designed to be human-friendly. In this example, I think the Display output is more readable. There is no right or wrong answer here and it depends on the context and your preferences. I have also worked in code bases where we didn’t really want to have to create a Display implementation for every struct we wanted to log, so we just used Debug for everything. In other codebases, we had a lot of custom structs and we wanted to have more control over how they were formatted in the logs, so we implemented Display for them and used % in the log macros.
There is also a shorthand syntax. If your variable name is the same as the field name you want, you can omit the field name:
tracing::info!(patient = ?patient, "writing synthetic patient to reference database");
tracing::info!(?patient, "writing synthetic patient to reference database");
Both of these will produce the same output.
Introducing Spans
So far everything we have logged has been an individual event. An event is a point in time where something happened, and we reported a log. However sometimes we do need more information, particularly when there are several different operations happening at the same time. For example, let’s imagine that creating a synthetic patient record involves calling a function called generate_patient() and this function has several steps: generating the patient’s demographics, generating their medical history by sampling a json file of possible diagnoses, and then writing the record to a reference database. If we just log events for each of these steps, we might end up with something like this:
tracing::info!(patient_id = %patient.id, "generated patient demographics");
tracing::info!(patient_id = %patient.id, "generated patient medical history");
tracing::info!(patient_id = %patient.id, "writing synthetic patient to reference database");
This is useful but it is not going to be super clear that these three log events are all part of the same overall function of creating a synthetic patient record. We can match on patient_id but that is not ideal. This is where we can use a span. A span is a period of time during which a certain operation is happening. We can create a span for the whole process of generating a synthetic patient record, and then we can log events within that span.
This looks like this:
fn generate_patient() {
let patient_id = Uuid::new_v4();
let span = tracing::info_span!("generate_patient", %patient_id);
let _guard = span.enter();
tracing::info!("generated patient demographics");
tracing::info!("generated patient medical history");
tracing::info!("writing synthetic patient to reference database");
}
fn main() {
tracing_subscriber::fmt()
.with_env_filter(EnvFilter::new("debug"))
.init();
generate_patient();
}
We end up with something like this:
2026-05-21T11:56:46.563474Z INFO
generate_patient{patient_id=835fc68d-ba89-403a-a59d-0cf413b7f7c4}:
first_setup: generated patient demographics
2026-05-21T11:56:46.563664Z INFO
generate_patient{patient_id=835fc68d-ba89-403a-a59d-0cf413b7f7c4}:
first_setup: generated patient medical history
2026-05-21T11:56:46.563695Z INFO
generate_patient{patient_id=835fc68d-ba89-403a-a59d-0cf413b7f7c4}:
first_setup: writing synthetic patient to reference database
You can see that each log line now has the span name generate_patient and the field patient_id attached to it. This makes it much easier to see that these three log events are all part of the same overall operation of generating a synthetic patient record. If we had multiple patients being generated at the same time, we would be able to easily distinguish which log events belong to which patient by looking at the span and the fields.
Without getting into the weeds of how this works (again, see Jon Gjengset’s long walk through for that), the main thing to note is that when you call tracing::info_span!(), you are creating a new span. Calling span.enter() returns a guard that will keep the span active until it is dropped. This means that any log events that happen while the guard is active will be associated with that span. We could also have nested spans if we wanted to. For example, lets imagine that creating the patient’s demographics is itself a function. We could create a span for that function as well:
struct Demographics {
age: u8,
sex: String,
}
fn generate_demographics() -> Demographics {
let span = tracing::info_span!("generate_demographics");
let _guard = span.enter();
let age = rand::thread_rng().gen_range(0..100);
let sex = if rand::thread_rng().gen_bool(0.5) {
"M".to_string()
} else {
"F".to_string()
};
let demographics = Demographics { age, sex };
tracing::info!(age = demographics.age, sex = %demographics.sex, "generated patient demographics");
demographics
}
Providing we call generate_demographics() from within generate_patient(), we would end up with nested spans in our logs:
2026-05-21T12:05:40.009557Z INFO
generate_patient{patient_id=faf23430-a077-40fa-9d7c-dcfabd2d5c22}:
generate_demographics:
first_setup: generated patient demographics age=35 sex=M
2026-05-21T12:05:40.009697Z INFO
generate_patient{patient_id=faf23430-a077-40fa-9d7c-dcfabd2d5c22}:
first_setup: generated patient medical history
2026-05-21T12:05:40.009721Z INFO
generate_patient{patient_id=faf23430-a077-40fa-9d7c-dcfabd2d5c22}:
first_setup: writing synthetic patient to reference database
You can see here that we have a span for generate_patient and a nested span for generate_demographics.
The #[instrument] macro
You might notice that the pattern for creating a span inside a function gets a bit repetitive. You can imagine if you have many functions that you want to create spans for, you would have to write this boilerplate code in each function. Luckily for us the tracing crate provides us with a convenient macro called #[instrument] that does this for us. We can just add the #[instrument] attribute to our function and it will automatically create a span for that function and attach any arguments as fields.
#[tracing::instrument]
fn generate_demographics() -> Demographics {
let age = rand::thread_rng().gen_range(0..100);
let sex = if rand::thread_rng().gen_bool(0.5) {
"M".to_string()
} else {
"F".to_string()
};
let demographics = Demographics { age, sex };
tracing::info!(age = demographics.age, sex = %demographics.sex, "generated patient demographics");
demographics
}
If I switch this out, I get the exact same output as before. It is very convenient! By default, the #[instrument] macro will also include all the function’s arguments as fields in the span. You can also customise this behaviour by using the fields argument to specify which fields you want to include or exclude. Let’s imagine, we only care about age when generating our medical history for some reason, we could do this:
#[tracing::instrument(fields(age = demographics.age), skip(demographics))]
fn generate_medical_history(demographics: &Demographics) -> Vec<String> {
// Sample from a json file of possible diagnoses based on age but just pretend for now
let diagnoses = vec!["E11.9".to_string(), "I10".to_string()];
tracing::info!(
diagnoses_count = diagnoses.len(),
"generated patient medical history"
);
diagnoses
}
fn generate_patient() {
let patient_id = Uuid::new_v4();
let span = tracing::info_span!("generate_patient", %patient_id);
let _guard = span.enter();
let demographics = generate_demographics();
let medical_history = generate_medical_history(&demographics);
tracing::info!("writing synthetic patient to reference database");
}
We would end up with logs that look like this:
2026-05-21T12:13:26.659447Z INFO
generate_patient{patient_id=16f1f077-6026-4b50-8f8b-47362efaa98d}:
generate_demographics:
first_setup: generated patient demographics age=16 sex=F
2026-05-21T12:13:26.659504Z INFO
generate_patient{patient_id=16f1f077-6026-4b50-8f8b-47362efaa98d}:
generate_medical_history{age=16}:
first_setup: generated patient medical history diagnoses_count=2
2026-05-21T12:13:26.659518Z INFO
generate_patient{patient_id=16f1f077-6026-4b50-8f8b-47362efaa98d}:
first_setup: writing synthetic patient to reference database
I did have to annotate Demographics with #[derive(Debug)] to get this to work because the #[instrument] macro needs to be able to format the arguments as fields. If you want to skip an argument, you can use the skip argument as shown above.
Measuring latency with spans
One of the things you often want to know about your code is how long operations are taking. You could measure this yourself by recording the time before and after an operation and logging the difference, but spans give you this for free. A span has a natural start and end point: it starts when you enter it and ends when the guard is dropped. The tracing-subscriber crate can be configured to emit a log line when a span closes, and that log line includes how long the span was active.
To enable this, add .with_span_events(FmtSpan::CLOSE) to your subscriber setup:
use tracing_subscriber::fmt::format::FmtSpan;
tracing_subscriber::fmt()
.with_env_filter(EnvFilter::new("info"))
.with_span_events(FmtSpan::CLOSE)
.init();
Now when a span closes, you will get a log line with the duration of the span. If I add a sleep into one of my functions to simulate some work being done, I can see the latency in the logs:
#[tracing::instrument(fields(age = demographics.age), skip(demographics))]
fn generate_medical_history(demographics: &Demographics) -> Vec<String> {
std::thread::sleep(Duration::from_millis(100));
let diagnoses = vec!["E11.9".to_string(), "I10".to_string()];
tracing::info!(
diagnoses_count = diagnoses.len(),
"generated patient medical history"
);
diagnoses
}
The logs will now include something like this (again, I have wrapped this for readability):
2026-05-21T18:00:15.406529Z INFO
generate_patient{patient_id=58a74988-d1ed-49ca-89aa-b706b9ba9eb9}:
generate_demographics:
first_setup: generated patient demographics age=23 sex=M
2026-05-21T18:00:15.406577Z INFO
generate_patient{patient_id=58a74988-d1ed-49ca-89aa-b706b9ba9eb9}:
generate_demographics:
first_setup: close time.busy=152µs time.idle=2.83µs
2026-05-21T18:00:15.506729Z INFO
generate_patient{patient_id=58a74988-d1ed-49ca-89aa-b706b9ba9eb9}:
generate_medical_history{age=23}:
first_setup: generated patient medical history diagnoses_count=2
2026-05-21T18:00:15.506777Z INFO
generate_patient{patient_id=58a74988-d1ed-49ca-89aa-b706b9ba9eb9}:
generate_medical_history{age=23}:
first_setup: close time.busy=100ms time.idle=4.25µs
2026-05-21T18:00:15.506798Z INFO
generate_patient{patient_id=58a74988-d1ed-49ca-89aa-b706b9ba9eb9}:
first_setup: writing synthetic patient to reference database
2026-05-21T18:00:15.506809Z INFO
generate_patient{patient_id=58a74988-d1ed-49ca-89aa-b706b9ba9eb9}:
first_setup: close time.busy=100ms time.idle=15.5µs
From this we can see that the generate_patient span was active for 100ms, and if we trace backwards, we can see that this delay was caused by the generate_medical_history function. This is really useful for understanding where the bottlenecks in your code are and for identifying performance issues.
Wrapping up
In this post we have covered structured fields and spans, which are the two features that really set tracing apart from simple logging. Structured fields let you attach typed, searchable data to your log events rather than burying information in strings. Spans let you group related events together and track the flow of execution through your code, with context that is automatically inherited by every event inside the span. The #[instrument] macro makes this easy to apply in practice without a lot of boilerplate.
I hope this has been a useful introduction to these concepts and that you feel like you can start using them in your own projects. I think the bar to entry for using tracing is quite low - the developers and maintainers have done such a great job at making it easy to get started with basic logging with very little effort. The more advanced features like spans and structured fields do require a bit more thought and intentionality in how you instrument your code, but I think the benefits are worth it in terms of the insights you can gain from your logs.
In the next post, I walk through the bare minimum you need to do to ship your structured logs to a log aggregation tool like Grafana Loki and how to query them once they are there.
