tracing: generate macro tests

There are a large number of combinations of field types which currently
are not matched by the level event macros (e.g. `info!`).

A recent example from #3407 is the following invocation that doesn't
compile:

```rust
info!(name: "order.received.ok", order.id = 123, "order received");
```

However, the corresponding `event!` macro does compile:

```rust
event!(name: "order.received.ok", Level::INFO, order.id = 123, "order received");
```

And other variants also compile:

```rust
// Without `name:` directive
info!(order.id = 123, "order received");

// With another field before the dotted one
info!(name: "order.received.ok", foo = true, order.id = 123, "order received");
```

Many such cases have been fixed in the past (#2983, #2883, #2879).
However, this has been a bit like wack-a-mole, where we keep finding
issues and then fixing those issues, adding extra tests for them and
then going on our way.

Since the complexity is often in combinations (as above, only when using
the `name:` directive together with a dotted field name on the first
field), it would be useful to have some extensive tests that attempt to
cover all possible combinations.

It turns out that there are **a lot** of combiantions.

This change adds an `xtask` that generates tests for event macros (span
macros are out of scope for this change) similar to the ones found in
`tracing/tests/macros.rs`. Which is to say, tests containing macros
which should compile, but don't need to run.

Owing to the large number of combinations, the tests are split into test
files by macro (e.g. `event!`, `info!`) and directive combination (e.g.
no directives, just `name:`, `name:` and `target:`). The tests are kept
in a separate crate outside the main workspace to avoid rust-analyzer
trying to parse the files - as they are quite large. Specifically, there
are 1220 macro invocations per test file.

For each macro, there are 9760 invocations generated (including all
combinatiosn of directives). When run against the current `tracing`
macros, this resulted in the following failure counts:
* `event!`: 705
* `info!`, `warn!`: 1683 (each)
* `trace!`, `debug!`, `error!`: 1652 (each)

The test files are generated (no need to check them in) and then
validated by `cargo check` on CI.

The CI job has not been made blocking because none of the errors have
been fixed yet!
This commit is contained in:
Hayden Stainsby
2025-12-03 23:06:42 +01:00
parent 9feb241133
commit 4c0f2634f8
7 changed files with 741 additions and 1 deletions

View File

@@ -314,6 +314,21 @@ jobs:
- name: "Test tracing-mock with all features enabled"
run: cargo test --all-features -p tracing-mock
check-tracing-macros-stable:
# Feature flag tests that run on stable Rust.
name: cargo check (tracing macros)
needs: check
runs-on: ubuntu-latest
steps:
- uses: actions/checkout@v4
- uses: dtolnay/rust-toolchain@stable
- name: "Generate macro tests"
run: cargo run --bin xtask -- gen-macro-tests
- name: "Check tracing macro invocations ("
# TODO(hds): remove `|| true` when all macros compile
run: cargo check --tests || true
working-directory: "tracing/test-macros"
# all required checks except for the main test run (which we only require
# specific matrix combinations from)
all_required:
@@ -326,5 +341,6 @@ jobs:
- test-build-wasm
- test-wasm
- test-features-stable
- check-tracing-macros-stable
steps:
- run: exit 0

View File

@@ -16,7 +16,8 @@ members = [
"tracing-test",
"tracing-appender",
"tracing-journald",
"examples"
"examples",
"xtask",
]
# This will be ignored with Rust older than 1.74, but for now that's okay;

View File

@@ -0,0 +1,10 @@
[workspace]
[package]
name = "test-macros"
version = "0.1.0"
publish = false
edition = "2018"
[dependencies]
tracing = { path = ".." }

1
tracing/test-macros/tests/.gitignore vendored Normal file
View File

@@ -0,0 +1 @@
*

11
xtask/Cargo.toml Normal file
View File

@@ -0,0 +1,11 @@
[package]
name = "xtask"
version = "0.1.0"
edition = "2018"
publish = false
[dependencies]
clap = { version = "4.5", features = ["derive"] }
[lints]
workspace = true

668
xtask/src/macro_tests.rs Normal file
View File

@@ -0,0 +1,668 @@
use std::{
error, fmt, fs, io,
path::{self, PathBuf},
sync::OnceLock,
};
pub fn gen_macro_tests() -> Result<(), Box<dyn error::Error>> {
let proj_root = {
let mut path = PathBuf::from(std::env!("CARGO_MANIFEST_DIR"));
if !path.pop() {
return Err(format!("Manifest dir should be absolute, not relative: {path:?}").into());
}
path
};
for macro_invocation in MacroInvocation::all() {
create_macro_tests(&proj_root, macro_invocation)?;
}
Ok(())
}
fn create_macro_tests(
proj_root: &path::Path,
macro_inv: &MacroInvocation,
) -> Result<(), io::Error> {
for directives in Directives::all() {
let test_file = proj_root.join(format!(
"tracing/test-macros/tests/{macro_name}{suffix}.rs",
macro_name = macro_inv.macro_name(),
suffix = directives.file_suffix()
));
eprintln!("generating test file: {test_file:?}");
let mut test_fh = fs::File::create(test_file).unwrap();
emit_header(&mut test_fh, macro_inv.macro_name()).unwrap();
emit_macro_test_file(&mut test_fh, macro_inv, directives)?;
}
Ok(())
}
fn emit_header<W: io::Write>(writer: &mut W, name: &str) -> Result<(), io::Error> {
let header = r#"#![deny(warnings)]
#![no_implicit_prelude]
extern crate tracing;
// We call all macros in this module with `no_implicit_prelude` to ensure they do not depend on the standard prelude.
#[cfg(target_arch = "wasm32")]
extern crate wasm_bindgen_test;
struct Disp {
val: u64,
}
impl ::std::fmt::Display for Disp {
fn fmt(&self, f: &mut ::std::fmt::Formatter<'_>) -> ::std::fmt::Result {
::std::write!(f, "Disp.val={val}", val = self.val)
}
}
struct Deb {
val: u64,
}
/// Manual implementation because otherwise `val` is unused.
impl ::std::fmt::Debug for Deb {
fn fmt(&self, f: &mut ::std::fmt::Formatter<'_>) -> ::std::fmt::Result {
f.debug_struct("Deb").field("val", &self.val).finish()
}
}
struct Sub {
field: u64,
}"#;
writeln!(
writer,
"//! DO NOT EDIT! This file is generated by `xtask`.\n//! Contains tests for the `{name}!` macro."
)?;
writeln!(writer, "{}", header)
}
fn emit_macro_test_file<W: io::Write>(
writer: &mut W,
invocation: &MacroInvocation,
directives: &Directives,
) -> Result<(), io::Error> {
let braces_fmt_args = [
(FieldBraces::None, FmtArgs::None),
(FieldBraces::None, FmtArgs::Fmt),
(FieldBraces::Braces, FmtArgs::Fmt),
(FieldBraces::None, FmtArgs::WithArgs),
(FieldBraces::Braces, FmtArgs::WithArgs),
];
writeln!(
writer,
r#"#[cfg_attr(target_arch = "wasm32", wasm_bindgen_test::wasm_bindgen_test)]
#[test]
fn {name}() {{
const CONST_VAR: &str = "const-field";
let var = true;
let sub = Sub {{ field: 4, }};
let disp = Disp {{ val: 61, }};
let deb = Deb {{ val: 102, }};
"#,
name = invocation.macro_name()
)?;
for field in Field::all() {
for (field_braces, fmt_args) in &braces_fmt_args {
for surrounding in SurroundingFields::all() {
let emit_macro = EmitMacro {
invocation,
directives,
field_braces,
surrounding,
fmt_args,
field,
};
writeln!(writer, "{emit_macro} // DEBUG:{emit_macro:?}")?;
//emit_invocations(writer, invocation, directives, field_braces, surrounding, fmt_args, field)?;
}
}
}
writeln!(writer, "}}")?;
Ok(())
}
/// This struct emits the macro code.
///
/// It contains all the combined elements for a single invocation.
struct EmitMacro<'a> {
/// The macro being called
///
/// For example, `event!` or `trace!`
invocation: &'a MacroInvocation,
/// The directives, such as `name:`
directives: &'a Directives,
/// Whether the fields have braces around them
field_braces: &'a FieldBraces,
/// Other fields before or after the field we're focussed on
surrounding: &'a SurroundingFields,
/// A message text which can also have format arguments
fmt_args: &'a FmtArgs,
/// The field we are focussed on
field: &'a Field,
}
impl<'a> fmt::Display for EmitMacro<'a> {
fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
write!(
f,
" tracing::{name}!({directives}{level}{lb}{preceding}{field}{following}{rb}{fmt_args});",
name = self.invocation.macro_name(),
directives = self.directives,
level = self.invocation.level(),
lb = self.field_braces.lb(),
preceding = self.surrounding.preceding(),
field = self.field,
following = self.surrounding.following(),
rb = self.field_braces.rb(),
fmt_args = self.fmt_args,
)
}
}
impl<'a> fmt::Debug for EmitMacro<'a> {
fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
write!(
f,
"{invocation:?},{directives:?},{field_braces:?},{surrounding:?},{fmt_args:?},{field:?}",
invocation = self.invocation,
directives = self.directives,
field_braces = self.field_braces,
surrounding = self.surrounding,
fmt_args = self.fmt_args,
field = self.field,
)
}
}
/// The macro being called
///
/// For example, `event!` or `trace!`
enum MacroInvocation {
/// `event!` macro (with level INFO)
Event,
/// `trace!` macro
Trace,
/// `debug!` macro
Debug,
/// `info!` macro
Info,
/// `warn!` macro
Warn,
/// `error!` macro
Error,
}
impl MacroInvocation {
fn macro_name(&self) -> &'static str {
match self {
Self::Event => "event",
Self::Trace => "trace",
Self::Debug => "debug",
Self::Info => "info",
Self::Warn => "warn",
Self::Error => "error",
}
}
fn level(&self) -> &'static str {
match self {
Self::Event => "tracing::Level::INFO, ",
_ => "",
}
}
const fn all() -> &'static [MacroInvocation; 6] {
const ALL: [MacroInvocation; 6] = [
MacroInvocation::Event,
MacroInvocation::Trace,
MacroInvocation::Debug,
MacroInvocation::Info,
MacroInvocation::Warn,
MacroInvocation::Error,
];
&ALL
}
}
impl fmt::Debug for MacroInvocation {
fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
write!(f, "{}", self.macro_name())
}
}
/// The directives, such as `name:`
enum Directives {
/// No directives
None,
/// `target:` directive
Target,
/// `parent:` directive (setting parent to `None`)
Parent,
/// `name:` directive
Name,
/// `name:` and `target:` directives together
NameTarget,
/// `name:` and `parent:` directives together (setting parent to `None`)
NameParent,
/// `target:` and `parent:` directives together (setting parent to `None`)
TargetParent,
/// `name:`, `target:`, and `parent:` directives together (setting parent to `None`)
NameTargetParent,
}
impl Directives {
const fn file_suffix(&self) -> &str {
match self {
Self::None => "",
Self::Name => "_n",
Self::Target => "_t",
Self::Parent => "_p",
Self::NameTarget => "_nt",
Self::NameParent => "_np",
Self::TargetParent => "_tp",
Self::NameTargetParent => "_ntp",
}
}
const fn all() -> &'static [Self; 8] {
const ALL: [Directives; 8] = [
Directives::None,
Directives::Name,
Directives::Target,
Directives::Parent,
Directives::NameTarget,
Directives::NameParent,
Directives::TargetParent,
Directives::NameTargetParent,
];
&ALL
}
}
impl fmt::Display for Directives {
fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
write!(
f,
"{}",
match self {
Self::None => "",
Self::Name => "name: \"mog\", ",
Self::Target => "target: \"my::module\", ",
Self::Parent => "parent: ::core::option::Option::None, ",
Self::NameTarget => "name: \"mog\", target: \"my::module\", ",
Self::NameParent => "name: \"mog\", parent: ::core::option::Option::None, ",
Self::TargetParent =>
"target: \"my::module\", parent: ::core::option::Option::None, ",
Self::NameTargetParent =>
"name: \"mog\", target: \"my::module\", parent: ::core::option::Option::None, ",
}
)
}
}
impl fmt::Debug for Directives {
fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
write!(
f,
"{}",
match self {
Self::None => "-",
Self::Name => "n",
Self::Target => "t",
Self::Parent => "p",
Self::NameTarget => "nt",
Self::NameParent => "np",
Self::TargetParent => "tp",
Self::NameTargetParent => "ntp",
}
)
}
}
/// Whether the fields have braces around them
enum FieldBraces {
/// No braces around fields
None,
/// Braces `{ .. }` around fields. Only applicable when there is a message
/// at the end.
Braces,
}
impl FieldBraces {
fn lb(&self) -> &'static str {
match self {
Self::None => "",
Self::Braces => "{ ",
}
}
fn rb(&self) -> &'static str {
match self {
Self::None => "",
Self::Braces => " }",
}
}
}
impl fmt::Debug for FieldBraces {
fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
match self {
Self::None => write!(f, "-"),
Self::Braces => write!(f, "{{}}"),
}
}
}
/// Other fields before or after the field we're focussed on
enum SurroundingFields {
/// Single field
None,
/// Field preceding the interesting field.
Preceding,
/// Field following the interesting field.
Following,
/// Fields preceding and following the interesting field.
PrecedingFollowing,
}
impl SurroundingFields {
fn preceding(&self) -> &'static str {
match self {
Self::None | Self::Following => "",
Self::Preceding | Self::PrecedingFollowing => "foo = true, ",
}
}
fn following(&self) -> &'static str {
match self {
Self::None | Self::Preceding => "",
Self::Following | Self::PrecedingFollowing => ", qux = 3",
}
}
fn all() -> &'static [SurroundingFields] {
const ALL: [SurroundingFields; 4] = [
SurroundingFields::None,
SurroundingFields::Preceding,
SurroundingFields::Following,
SurroundingFields::PrecedingFollowing,
];
&ALL
}
}
impl fmt::Debug for SurroundingFields {
fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
match self {
Self::None => write!(f, "-"),
Self::Preceding => write!(f, "p"),
Self::Following => write!(f, "f"),
Self::PrecedingFollowing => write!(f, "pf"),
}
}
}
/// A message text which can also have format arguments
#[derive(Clone, Copy)]
enum FmtArgs {
/// No message (macro only has fields)
None,
/// Message without format arguments
Fmt,
/// Message with format arguments after it
WithArgs,
}
impl fmt::Display for FmtArgs {
fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
match self {
Self::None => write!(f, ""),
Self::Fmt => write!(f, ", \"msg without args\""),
Self::WithArgs => write!(f, ", \"msg with arg: {{:?}}\", 56"),
}
}
}
impl fmt::Debug for FmtArgs {
fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
match self {
Self::None => write!(f, "-"),
Self::Fmt => write!(f, "m"),
Self::WithArgs => write!(f, "ma"),
}
}
}
/// The field we are focussed on
#[derive(Clone, Copy)]
enum Field {
/// A labeled field, for example `name = value`
Labeled { label: Label, value: Value },
/// A labelless field where the field name comes from the value for example `foo` or `%bar`
Labelless { value: Labelless },
}
impl fmt::Display for Field {
fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
match self {
Self::Labeled { label, value } => write!(f, "{label} = {value}"),
Self::Labelless { value } => write!(f, "{value}"),
}
}
}
impl fmt::Debug for Field {
fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
match self {
Self::Labeled { label, value } => write!(f, "{label:?},{value:?}"),
Self::Labelless { value } => write!(f, "-,{value:?}"),
}
}
}
impl Field {
fn all() -> &'static Vec<Field> {
static ALL: OnceLock<Vec<Field>> = OnceLock::new();
ALL.get_or_init(|| {
let mut all_fields = Vec::new();
for label in Label::all() {
for value in Value::all() {
all_fields.push(Field::Labeled {
label: *label,
value: *value,
});
}
}
for value in Labelless::all() {
all_fields.push(Field::Labelless { value: *value });
}
all_fields
})
}
}
/// A field label, this is paired with a [`Value`]
#[derive(Clone, Copy)]
enum Label {
/// Label is an identifier, e.g. `status`
Ident,
/// Label is a dotted identifier, e.g. `order.id`
DottedIdent,
/// Label is a literal, e.g. `"foo"`
Literal,
/// Label is a const, e.g. `{ CONST_VAR }`
ConstVar,
/// Label is a raw identifier, e.g. `r#type`
RawIdent,
}
impl fmt::Display for Label {
fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
match self {
Self::Ident => write!(f, "ident"),
Self::DottedIdent => write!(f, "dotted.ident"),
Self::Literal => write!(f, "\"literal\""),
Self::ConstVar => write!(f, "{{ CONST_VAR }}"),
Self::RawIdent => write!(f, "r#type"),
}
}
}
impl fmt::Debug for Label {
fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
write!(f, "{:?}", format!("{self}"))
}
}
impl Label {
const fn all() -> &'static [Label; 5] {
const ALL: [Label; 5] = [
Label::Ident,
Label::DottedIdent,
Label::Literal,
Label::ConstVar,
Label::RawIdent,
];
&ALL
}
}
/// A labelless field, where the field name is derived from the value
#[derive(Clone, Copy)]
enum Labelless {
/// Field is a variable name, e.g. `foo`
Var,
/// Field accesses a sub-field, e.g. `data.status`
SubField,
/// Field is a variable treated as `impl Display` via the sigil, e.g. `%foo`
DisplaySigil,
/// Field is a variable treated as `impl Debug` via the sigil, e.g. `?foo`
DebugSigil,
/// Field is a sub-field treated as `impl Display` via the sigil, e.g. `%data.status`
DisplaySigilSubField,
/// Field is a sub-field treated as `impl Debug` via the sigil, e.g. `?data.status`
DebugSigilSubField,
}
impl fmt::Display for Labelless {
fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
match self {
Self::Var => write!(f, "var"),
Self::SubField => write!(f, "sub.field"),
Self::DisplaySigil => write!(f, "%disp"),
Self::DebugSigil => write!(f, "?deb"),
Self::DisplaySigilSubField => write!(f, "%sub.field"),
Self::DebugSigilSubField => write!(f, "?sub.field"),
}
}
}
impl fmt::Debug for Labelless {
fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
write!(f, "{:?}", format!("{self}"))
}
}
impl Labelless {
const fn all() -> &'static [Labelless; 6] {
const ALL: [Labelless; 6] = [
Labelless::Var,
Labelless::SubField,
Labelless::DisplaySigil,
Labelless::DebugSigil,
Labelless::DisplaySigilSubField,
Labelless::DebugSigilSubField,
];
&ALL
}
}
/// The value for a field with a label
#[derive(Clone, Copy)]
enum Value {
/// Value is a literal int, e.g. `3`
LiteralInt,
/// Value is a literal bool, e.g. `true`
LiteralBool,
/// Value is an integer treated as `impl Display` via the sigil, e.g. `%3`
DisplaySigilInt,
/// Value is an integer treated as `impl Debug` via the sigil, e.g. `?3`
DebugSigilInt,
/// Value is a variable treated as `impl Display` via the sigil, e.g. `%foo`
DisplaySigilVar,
/// Value is a variable treated as `impl Debug` via the sigil, e.g. `?foo`
DebugSigilVar,
/// Value is accessing a subfield, treated as `impl Display` via the sigil, e.g. `%order.id`
DisplaySigilSubField,
/// Value is accessing a subfield, treated as `impl Debug` via the sigil, e.g. `?order.id`
DebugSigilSubField,
/// Value is a variable treated as `impl Display` via the use of the bare function, e.g.
/// `display(foo)`
BareDisplayFn,
/// Value is a variable treated as `impl Debug` via the use of the bare function, e.g.
/// `debug(foo)`
BareDebugFn,
/// Value is tracing's Empty field, e.g. `tracing::field::Empty`
Empty,
}
impl fmt::Display for Value {
fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
match self {
Self::LiteralInt => write!(f, "3"),
Self::LiteralBool => write!(f, "false"),
Self::DebugSigilInt => write!(f, "?3"),
Self::DisplaySigilInt => write!(f, "%3"),
Self::DebugSigilVar => write!(f, "?deb"),
Self::DisplaySigilVar => write!(f, "%disp"),
Self::DebugSigilSubField => write!(f, "?sub.field"),
Self::DisplaySigilSubField => write!(f, "%sub.field"),
Self::BareDebugFn => write!(f, "debug(&deb)"),
Self::BareDisplayFn => write!(f, "display(&disp)"),
Self::Empty => write!(f, "tracing::field::Empty"),
}
}
}
impl fmt::Debug for Value {
fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
write!(f, "{:?}", format!("{self}"))
}
}
impl Value {
const fn all() -> &'static [Value; 11] {
const ALL: [Value; 11] = [
Value::LiteralInt,
Value::LiteralBool,
Value::DebugSigilInt,
Value::DisplaySigilInt,
Value::DebugSigilVar,
Value::DisplaySigilVar,
Value::DebugSigilSubField,
Value::DisplaySigilSubField,
Value::BareDebugFn,
Value::BareDisplayFn,
Value::Empty,
];
&ALL
}
}

33
xtask/src/main.rs Normal file
View File

@@ -0,0 +1,33 @@
use std::error;
use clap::{Parser, Subcommand};
mod macro_tests;
use macro_tests::gen_macro_tests;
#[derive(Debug, Parser)]
struct Args {
#[clap(subcommand)]
cmd: Command,
}
#[derive(Debug, Subcommand)]
enum Command {
/// Generate tests for `tracing` macros.
///
/// This will be placed in the dedicated project `tracing/test-macros`.
GenMacroTests,
}
impl Command {
fn run(&self) -> Result<(), Box<dyn error::Error>> {
match self {
Self::GenMacroTests => gen_macro_tests(),
}
}
}
fn main() -> Result<(), Box<dyn error::Error>> {
Args::parse().cmd.run()
}