Happy Developing

楽しい開発ライフ 🦀

tracing/tracing-subscriberでログが出力される仕組みを理解する

本記事ではRustのtracing/tracing-subscriberでログが出力される仕組みをソースコードを読みながら理解することを目指します。
具体的には以下のコードにおいてtracingがどのようにしてログを出力するかを見ていきます。

use tracing::{info, info_span};

fn main() {
    tracing_subscriber::fmt()
        .init();

    let span = info_span!("span_1", key="hello");
    let _guard = span.enter();

    info!("hello");
}

Cargo.toml

[dependencies]
thread_local = "1.1.4"
tracing = "=0.1.35"
tracing-core = "=0.1.30"
tracing-subscriber = { version = "=0.3.16", default-features = false, features = ["smallvec", "fmt", "ansi", "std"] }

上記のコードを実行すると以下の出力を得ます。

2022-11-11T08:39:02.198973Z  INFO span_1{key="hello"}: tracing_handson: hello

versionはtracing-subscriber-0.3.16を対象にしました。
(なお、tracing::info!()はtracing的にはEventといわれているので以下ではログではなくEventと呼んでいきます)

本記事のゴール

本記事では以下の点を目指します。

  • tracing_subscriber::fmt()::init()でなにが初期化されているか
    • tracing_subscriber::Subscriberの内部構造
      • Subscriberの実態はLayer * n + Registry
    • tracing_subscriber::Registryの役割
  • tracing::Spanの仕組み
    • info_span!()の内容がどのようにして後続のeventに出力されるか
  • tracing::info!()が出力される仕組み

本記事で扱わないこと

  • tracing-future
    • async/awaitでのtracingの利用の仕方(ただし、asyncなコードでそのまま使うとどうしてうまく動作しないかは理解できます)
  • tracing-log
    • log crateとの互換処理も提供されています
  • per-filter-layer

前提の確認

Spanとは

最初にtracingを触った時にinfo!()error!()はログの出力として理解できたのですが、spanの役割や使い方がわかりませんでした。公式のdocには以下のようにあります。

Unlike a log line that represents a moment in time, a span represents a period of time with a beginning and an end.

自分の言葉で説明するなら、spanは後続のstack trace上で作られるevent(info!())に付与されるkey,valueで、eventに実行時のcontextを付与するものです。といってもわかりづらいと思うので具体的なコードでみていきます。

use tracing::{info, info_span};

fn start() {
    // Generate unique request id
    let request_id = "req-123";

    let _guard = info_span!("req", request_id).entered();

    handle_request();
}

fn handle_request() {
    // Authenticate
    let user_id = "user_aaa";
    let _guard = info_span!("user", user_id).entered();

    do_process();
}

fn do_process() {
    info!("successfully processed");
}

fn main() {
    tracing_subscriber::fmt()
        .init();

    start();
}

処理の内容はなんでもよいのですが、まずリクエストの識別子を生成して次に認証して、...と処理を進めていく中で処理内容のcontextができていくと思います。それをspanとして表現します。上記のコードを実行すると以下のようなログが出力されます。

2022-11-11T09:19:18.317693Z  INFO req{request_id="req-123"}:user{user_id="user_aaa"}: span: successfully processed

info!()で生成したeventにspanに与えたkey,valueが付与されました。このように処理の階層構造のcontextをログに構造的に表現できます。一度このログが作れるとわかるともうspanなしには戻れないです。

thread_local!, thread_local::ThreadLocal

tracingの実装ではしばしばthread_local!thread_local::ThreadLocalがでてきます。
自分自身、thread localという機構への理解があやしいのですが本記事を読む範囲では以下のようにRustのAPI的観点から捉えておけばよいと考えております。

thread_local!はglobalなstatic変数にRefCellを保持できる。
具体的には以下のコードはglobalなstatic変数を複数threadから変更しようとしておりcompileに失敗します。

static STATE: RefCell<String> = RefCell::new(String::new());

fn main() {
    let threads = 5;
    let mut handles = Vec::with_capacity(threads);
    for i in 0..threads {
        let handle = thread::spawn(move || {
            STATE.borrow_mut().push_str(i.to_string().as_str());
        });
        handles.push(handle);
    }

    for handle in handles {
        handle.join().unwrap();
    }
}
--> examples/thread_local.rs:8:15
  |
8 | static STATE: RefCell<String> = RefCell::new(String::new());
  |               ^^^^^^^^^^^^^^^ `RefCell<String>` cannot be shared between threads safely
  |
  = help: the trait `Sync` is not implemented for `RefCell<String>`
  = note: shared static variables must have a type that implements `Sync`

そこで、global変数STATEthread_local!にするとcompileが通ります。

use std::cell::RefCell;
use std::thread;

thread_local! {
    static STATE: RefCell<String> = RefCell::new(String::new());
}

fn main() {
    let threads = 5;
    let mut handles = Vec::with_capacity(threads);
    for i in 0..threads {
        let handle = thread::spawn(move || {
            STATE.with(|state: &RefCell<String>| {
                state.borrow_mut().push_str(i.to_string().as_str());
            })
        });
        handles.push(handle);
    }

    for handle in handles {
        handle.join().unwrap();
    }
}

RefCellSyncではないのでmulti threadではArc<Mutext<T>>等を使うところですが、thread localにするとthreadごとにglobal変数を保持でき、single threadで利用できたRefCellが使えます。

ThreadLocalは上記の機能をstructのfieldでも使えるようにするものです。 具体的には以下のコードはcompileが通りません。

use std::cell::RefCell;

struct A {
    _a: RefCell<String>,
}

fn should_sync<T: Sync>(_t: T) {}

fn main() {
    let a = A { _a: RefCell::new(String::new()) };
    should_sync(a);
}
  --> examples/thread_local.rs:14:17
   |
14 |     should_sync(a);
   |     ----------- ^ `RefCell<String>` cannot be shared between threads safely
   |     |
   |     required by a bound introduced by this call
   |
   = help: within `A`, the trait `Sync` is not implemented for `RefCell<String>`

RefCellSyncでないと言われます。そこで、ThreadLocalでwrapするとcompileが通ります。

use std::cell::RefCell;
use thread_local::ThreadLocal;

struct A {
    _a: ThreadLocal<RefCell<String>>,
}

fn should_sync<T: Sync>(_t: T) {}

fn main() {
    let a = A { _a: ThreadLocal::new() };
    should_sync(a);
}

shareded_slab::Pool

shareded_slab::Poolはslabというデータ構造をmulti thread間で共有できるようにし(Sync)かつ、object pool likeなAPIを提供するものです。あまり深入りすると本記事のゴールからそれてしまうので、ここではdataをcreate/insertするとindex(usize)を返してくれるSyncで効率的なVecという程度に理解します。

Macroをexpand

tracing以外のcrateで押さえておきたい型は前提の確認で概要を押さえたのであとはtracingとstdだけで完結します。
まずはmacroをexpandして、実行されているtracingのapiを確認していきましょう。

use tracing::{info, info_span};

fn main() {
    tracing_subscriber::fmt()
        .init();

    let span = info_span!("span_1", key="hello");
    let _guard = span.enter();

    info!("hello");
}

このcodeをcargo expandすると以下のようになります。(compileできるようにprelude等を削りました。)

#![feature(fmt_internals)]
use std::prelude::rust_2021::*;
fn main() {
    tracing_subscriber::fmt().init();

    let span = {
        use ::tracing::__macro_support::Callsite as _;
        static CALLSITE: ::tracing::callsite::DefaultCallsite = {
            static META: ::tracing::Metadata<'static> = {
                ::tracing_core::metadata::Metadata::new(
                    "span_1",
                    "tracing_handson",
                    ::tracing::Level::INFO,
                    Some("src/main.rs"),
                    Some(8u32),
                    Some("tracing_handson"),
                    ::tracing_core::field::FieldSet::new(
                        &["key"],
                        ::tracing_core::callsite::Identifier(&CALLSITE),
                    ),
                    ::tracing::metadata::Kind::SPAN,
                )
            };
            ::tracing::callsite::DefaultCallsite::new(&META)
        };
        let mut interest = ::tracing::subscriber::Interest::never();
        if ::tracing::Level::INFO <= ::tracing::level_filters::STATIC_MAX_LEVEL
            && ::tracing::Level::INFO <= ::tracing::level_filters::LevelFilter::current()
            && {
                interest = CALLSITE.interest();
                !interest.is_never()
            }
            && ::tracing::__macro_support::__is_enabled(CALLSITE.metadata(), interest)
        {
            let meta = CALLSITE.metadata();
            ::tracing::Span::new(meta, &{
                #[allow(unused_imports)]
                use ::tracing::field::{debug, display, Value};
                let mut iter = meta.fields().iter();
                meta.fields().value_set(&[(
                    &iter.next().expect("FieldSet corrupted (this is a bug)"),
                    Some(&"hello" as  &dyn Value),
                )])
            })
        } else {
            let span = ::tracing::__macro_support::__disabled_span(CALLSITE.metadata());
            {};
            span
        }
    };
    let _guard = span.enter();
 {
        use ::tracing::__macro_support::Callsite as _;
        static CALLSITE: ::tracing::callsite::DefaultCallsite = {
            static META: ::tracing::Metadata<'static> = {
                ::tracing_core::metadata::Metadata::new(
                    "event src/main.rs:11",
                    "tracing_handson",
                    ::tracing::Level::INFO,
                    Some("src/main.rs"),
                    Some(11u32),
                    Some("tracing_handson"),
                    ::tracing_core::field::FieldSet::new(
                        &["message"],
                        ::tracing_core::callsite::Identifier(&CALLSITE),
                    ),
                    ::tracing::metadata::Kind::EVENT,
                )
            };
            ::tracing::callsite::DefaultCallsite::new(&META)
        };
        let enabled = ::tracing::Level::INFO <= ::tracing::level_filters::STATIC_MAX_LEVEL
            && ::tracing::Level::INFO <= ::tracing::level_filters::LevelFilter::current()
            && {
                let interest = CALLSITE.interest();
                !interest.is_never()
                    && ::tracing::__macro_support::__is_enabled(CALLSITE.metadata(), interest)
            };
        if enabled {
            (|value_set: ::tracing::field::ValueSet| {
                let meta = CALLSITE.metadata();
                ::tracing::Event::dispatch(meta, &value_set);
            })({
                #[allow(unused_imports)]
                use ::tracing::field::{debug, display, Value};
                let mut iter = CALLSITE.metadata().fields().iter();
                CALLSITE.metadata().fields().value_set(&[(
                    &iter.next().expect("FieldSet corrupted (this is a bug)"),
                    Some(&::core::fmt::Arguments::new_v1(&["hello"], &[]) as  &dyn Value),
                )])
            });
        } else {
        }
    };
}

長いですが、概要はシンプルです。 info_span!(),info!()共通で、macroを呼び出すと当該呼び出し箇所の情報が以下のようにtracing::callsite::DefaultCallsiteとして表現されます。

        static CALLSITE: ::tracing::callsite::DefaultCallsite = {
            static META: ::tracing::Metadata<'static> = {
                ::tracing_core::metadata::Metadata::new(
                    // ...
                )
            };
            ::tracing::callsite::DefaultCallsite::new(&META)
        };

まず見ていただきたいのが、static CALLSITEのようにstaticになっている点です。
tracingのコードを読むまで知らなかったのですが、rustでは関数の中でもstatic変数が定義できるそうです。

A static item defined in a generic scope (for example in a blanket or default implementation) will result in exactly one static item being defined, as if the static definition was pulled out of the current scope into the module.

https://doc.rust-lang.org/reference/items/static-items.html#statics--generics

関数内でstaticを定義しても実際にはmoduleのtop levelで定義したのと同様になり、当該変数には定義した関数からしかアクセスできないという挙動になります。
CALLSITEについては全体の構造を押さえてからのほうがわかりやすいのでここではmacroの呼び出しの情報(source code上の位置、key,value, span or event)を保持しているというくらいでOKです。

CALLSITEはstaticなのでcompile時に決まります。次の箇所からがruntime時の挙動です。

let mut interest = ::tracing::subscriber::Interest::never();
if ::tracing::Level::INFO <= ::tracing::level_filters::STATIC_MAX_LEVEL
    && ::tracing::Level::INFO <= ::tracing::level_filters::LevelFilter::current()
    && {
        interest = CALLSITE.interest();
        !interest.is_never()
    }
    && ::tracing::__macro_support::__is_enabled(CALLSITE.metadata(), interest)
{ // ... }

subscriberのInterestなるものや、levelの判定を行っています。こちらもsubscriberの構造がかかわってくるので後述します。ざっくりですがinfo_span!()debug_span!()のようなlevelに応じた判定処理を実施している程度に理解しておきます。次がspanの実質的な処理です。

let meta = CALLSITE.metadata();
::tracing::Span::new(meta, &{
    #[allow(unused_imports)]
    use ::tracing::field::{debug, display, Value};
    let mut iter = meta.fields().iter();
    meta.fields().value_set(&[(
        &iter.next().expect("FieldSet corrupted (this is a bug)"),
        Some(&"hello" as  &dyn Value),
    )])
})

ここで大事なのはtracing::Span::new()が呼び出されている点です。引数にはmacro呼び出し時の情報を渡しています。
spanの処理についてまとめると概要としては以下のようになります。

fn main() {
    tracing_subscriber::fmt().init();
    
    let span = {
        static CALLSITE = { /* ... */ };
        tracing::Span::new(CALLSITE)
    };
    let _guard = span.enter();
}

要は、tracing::Span::new()にmacroの情報渡して、spanを生成し、span.enter()して、guardをdropしないように変数で保持しているだけです。

info!()のevent生成でも流れはspanと同じで、staticなCALLSITE生成、levelの判定処理、api callという流れです。eventの場合はtracing::Event::dispatch(CALLSITE)が呼ばれます。

話を整理すると、メンタルモデルとしてはspanとeventのmacroは概ね以下のように展開されるといえます。

fn main() {
    tracing_subscriber::fmt().init();

    let span = info_span!("span_1", key="hello");
    let _guard = span.enter();

    info!("hello");
}

fn main() {
    tracing_subscriber::fmt().init();

    let span = {
        static CALLSITE = { /* ... */ };
        tracing::Span::new(CALLSITE)
    };
    let _guard = span.enter();

    {
        static CALLSITE = { /* ... */ }
        tracing::Event::dispatch(CALLSITE)
    }
}

ということで、以下のtracingのapiの処理を追っていきます。

  1. tracing::Span::new()
  2. tracing::Span::enter()
  3. tracing::Event::dispatch()

さっそく、tracing::Span::new()のdefinitionにjumpしていきたいところですが、ここからはtracing_subscriber側の処理になるので、tracing_subscriber crateについて説明させてください。

tracing_subscriber crate

tracingは生成したspanやeventを処理するために必要な機能をtracing_core::Subscriberとして定義しています。tracingはtracing_core::Subscriberの実装がspanやeventの生成前にtracingのapiを通じて初期化されていることを期待しています。tracing_subscribertracing_core::Subscriberの実装を提供するためのcrateです。
tracingではtraitとそれを実装する型に同じ名前を使う場合があり最初は紛らわしいのですが、tracing_core::Subscriberはtraitでtracing_subscriber::fmt::Subscriberはこのtraitの実装を提供するstructです。
以後は紛らわしいのでtracing_subscriberのre-exportにならって、tracing_subscriber::fmt::SubscriberFmtSubscriberと呼びます。

上記のコードの最初にでてきたtracing_subscriber::fmt().init();FmtSubscriberを生成して、tracingに見える位置にセットする処理と理解することができます。

FmtSubscriber

さっそくFmtSubscriberの定義を確認してみましょう。

pub struct Subscriber<
    N = format::DefaultFields,
    E = format::Format<format::Full>,
    F = LevelFilter,
    W = fn() -> io::Stdout,
> {
    inner: layer::Layered<F, Formatter<N, E, W>>,
}

https://github.com/tokio-rs/tracing/blob/tracing-subscriber-0.3.16/tracing-subscriber/src/fmt/mod.rs#L225-L232

Genericsが4つもでてきて、うっとなります。ただし、よくみてみると以下の構造をしているinnerのwrapperであることがわかります。

inner: layer::Layered<F,Formatter<_>>

Formatter<_>はすぐ下に以下のように定義されています。

pub type Formatter<
    N = format::DefaultFields,
    E = format::Format<format::Full>,
    W = fn() -> io::Stdout,
> = layer::Layered<fmt_layer::Layer<Registry, N, E, W>, Registry>;

https://github.com/tokio-rs/tracing/blob/tracing-subscriber-0.3.16/tracing-subscriber/src/fmt/mod.rs#L237-L241

ということで、Formatterも実体はlayer::Layeredでした。
N = format::DefaultFieldsE = format::Fromat<format::Full>はログの出力方法をカスタマイズするためのgenerics、W = fn() -> io::Stdoutはログの出力先を切り替えるためのgenericです。そこでこれらのgenericsをいったん無視するとFmtSubscriberは概ね以下の構造をしているといえます。

Layered<
    LevelFilter,
    Layered<
        fmt_layer::Layer,
        Registry,
    >
>

FmtSubscriberは、LevelFilter,fmt_layer::Layer, RegistryLayeredというstructでnestさせてできていえるように見えないでしょうか。
ということで、tracing_subscriberLayer,Layeredをまずは理解していきましょう。

Layer

まずはdocを見てみます。Layerについてはtracing_subscriber::layer moduleに説明があります。

The Layer trait, a composable abstraction for building Subscribers.

LayerSubscriberを作るためのcomposable abstractionなtraitとあります。Layerを知ったあとに読むとなるほどと思えますが最初に読むとピンとこなかったです。

The Subscriber trait in tracing-core represents the complete set of functionality required to consume tracing instrumentation. This means that a single Subscriber instance is a self-contained implementation of a complete strategy for collecting traces; but it also means that the Subscriber trait cannot easily be composed with other Subscribers.

tracing_core::Subscriberはtracing instrumentationをconsumeするために必要な機能をすべて集約したものなので、Subscriber instanceはいろいろな責務をもちます。そのためSubscriberを他のSubscriberと組み合わせづらいという問題点があります。

In particular, Subscribers are responsible for generating span IDs and assigning them to spans. Since these IDs must uniquely identify a span within the context of the current trace, this means that there may only be a single Subscriber for a given thread at any point in time — otherwise, there would be no authoritative source of span IDs.

Subscriberを他のSubscriberとcomposableにできない理由が書いてあります。このspan IDを生成する箇所については後述します。ここではどうやらSubscriberの責務のひとつにspanにIDを振ることがあるくらいを押さえておきます。

On the other hand, the majority of the Subscriber trait’s functionality is composable: any number of subscribers may observe events, span entry and exit, and so on, provided that there is a single authoritative source of span IDs. The Layer trait represents this composable subset of the Subscriber behavior; it can observe events and spans, but does not assign IDs.

一方で、Subscriber traitのmethodはcomposable。
eventの出力やspanのentryやexitといった処理は複数のsubscriberで実装できます。(stdoutにjsonでloggingしつつ、特定のspanのパフォーマンス計測しつつ、特定のeventをmetricsで収集したり)
Layer traitはSubscriber traitの一部のmethodの実装を担い、Subscriberをcomposableにするためにあります。

まとめ

  • tracing_core::Subscriberにはtracingを利用するうえで必要な処理がまとめて定義されている
  • Subscriberの実装はspanにIDを付与する責務をもつ観点から特定のcontext内で1つである必要がある
  • そこでSubscriberをcomposableに作っていくためにLayerがある

Layered

次にtracing_subscriber::layer::Layeredをみていきます。Layeredは以下のように定義されています。

pub struct Layered<L, I, S = I> {
    /// The layer.
    layer: L,

    /// The inner value that `self.layer` was layered onto.
    ///
    /// If this is also a `Layer`, then this `Layered` will implement `Layer`.
    /// If this is a `Subscriber`, then this `Layered` will implement
    /// `Subscriber` instead.
    inner: I,
    // ...
}

https://github.com/tokio-rs/tracing/blob/tracing-subscriber-0.3.16/tracing-subscriber/src/layer/layered.rs#L22

省略していますが、基本的には1つのLayerでinnerをwrapするstructです。コメントにある通り、inner: IにはSubscriberLayerをいれます。

重要なのはLayeredSubscriberをwrapしているときはSubscriberとして振る舞う点です。

impl<L, S> Subscriber for Layered<L, S>
where
    L: Layer<S>,
    S: Subscriber,
{
    // ...
}

https://github.com/tokio-rs/tracing/blob/tracing-subscriber-0.3.16/tracing-subscriber/src/layer/layered.rs#L89

またSubscriberの実装方法は

fn event(&self, event: &Event<'_>) {
        self.inner.event(event);
        self.layer.on_event(event, self.ctx());
}

https://github.com/tokio-rs/tracing/blob/tracing-subscriber-0.3.16/tracing-subscriber/src/layer/layered.rs#L151-L154

のように、wrapしているinnerを呼び出した後自身のlayerを呼び出します。

まとめるとLayeredSubscriberをcomposableに構築するためのLayerをまとめていくためのstructでそれ自身もSubscriberの実装であることがわかりました。

Filter

あらためてFmtSubscriberの概要を確認します。

Layered<
    LevelFilter,
    Layered<
        fmt_layer::Layer,
        Registry,
    >
>    

LayeredはinnerにSubscriber(orLayer)をもちLayerと組み合わせるということをみてきました。
とすると、LevelFilterもFilterといいながらLayerなのでしょうか。ここではFilterについて見ていきます。

Filterについてはlayer moduleのdocで以下のように説明されています。

As well as strategies for handling trace events, the Layer trait may also be used to represent composable filters. This allows the determination of what spans and events should be recorded to be decoupled from how they are recorded: a filtering layer can be applied to other layers or subscribers.

ということでLayerのうち,spanやeventを処理対象とするかの判定のみを行うLayerFilterとしているようです。

pub use tracing_core::metadata::{LevelFilter, ParseLevelFilterError as ParseError};

impl<S: Subscriber> crate::Layer<S> for LevelFilter {
    fn register_callsite(&self, metadata: &'static Metadata<'static>) -> Interest {
        if self >= metadata.level() {
            Interest::always()
        } else {
            Interest::never()
        }
    }

    fn enabled(&self, metadata: &Metadata<'_>, _: crate::layer::Context<'_, S>) -> bool {
        self >= metadata.level()
    }

    fn max_level_hint(&self) -> Option<LevelFilter> {
        Some(*self)
    }
}

https://github.com/tokio-rs/tracing/blob/tracing-subscriber-0.3.16/tracing-subscriber/src/filter/level.rs#L11

として、LevelFilterLayerを実装しています。
ということでLevelFilterの実体はtracingの有効判断を実装したLayerということがわかりました。

Registry

FmtSubscriberのcomponentで次にみていくのがRegistryです。

Layered<
    LevelFilter,
    Layered<
        fmt_layer::Layer,
        Registry,
    >
>    

Registryはもっとも深くnestされており、他のLayerはRegistry上にcomposeされています。また、Layeredの実装では基本的にinnerを最初に呼び出すので実質的に最初に呼び出されるのはRegistryの処理になります。まずはtracing_subscriber::registry::Registryのdocを見てみます。

A shared, reusable store for spans. A Registry is a Subscriber around which multiple Layers implementing various behaviors may be added. Unlike other types implementing Subscriber, Registry does not actually record traces itself: instead, it collects and stores span data that is exposed to any Layers wrapping it through implementations of the LookupSpan trait. The Registry is responsible for storing span metadata, recording relationships between spans, and tracking which spans are active and which are closed. In addition, it provides a mechanism for Layers to store user-defined per-span data, called extensions, in the registry. This allows Layer-specific data to benefit from the Registry’s high-performance concurrent storage.

まとめると

  • Subscriberの実装で、layerが追加される
  • traceを記録しない
  • spanのdataをcollectして他のlayerに提供する
  • metadataやrelationships,activeやcloseといったspanの情報を管理する
  • extensionを通じてuser側でspanを拡張できる仕組みを提供する

ということで、Subscriberの機能のうちspan関連の責務をになっていそうです。詳細についてはこのあとSpan::new()Span::enter()をおっていく中でみていきます。
ここでは以下の点をおさえます

  • Layeredの実装から最初によばれるのはRegistryの処理
  • spanの情報を管理して他のLayerに提供するのがRegistryの責務

fmt_layer::Layer

Layered<
    LevelFilter,
    Layered<
        fmt_layer::Layer,
        Registry,
    >
>    

FmtSubscriberの最後のcomponentはfmt_layer::Layerです。doc

A Layer that logs formatted representations of tracing events.

とある通り、tracing_subscriber::Layerを実装するstructです。このLayerが実際にinfo!()した際にeventを出力する処理を実装します。

以下のように定義されています。

pub struct Layer<
    S,
    N = format::DefaultFields,
    E = format::Format<format::Full>,
    W = fn() -> io::Stdout,
> {
    make_writer: W,
    fmt_fields: N,
    fmt_event: E,
    fmt_span: format::FmtSpanConfig,
    is_ansi: bool,
    log_internal_errors: bool,
    _inner: PhantomData<fn(S)>,
}

https://github.com/tokio-rs/tracing/blob/tracing-subscriber-0.3.16/tracing-subscriber/src/fmt/fmt_layer.rs#L62

4つもgenericsをもっています。FmtSubscriberのgenericsが多かったのはこのfmt_layer::Layerのためです。
まずSですが、これはfmt_layer::LayerがwrapしているSubscriberを抽象化しています。最初わかりづらかったのはfmt_layer::Layer自体はSubscriberを保持しておらず、実際に保持しているのはLayeredになります。そのため、PhantomData<fn(S)>となっています。
NEですが、tracing_subscriberではeventを出力する際に必要な機能が細かくtraitになっています。
Nはeventとspan共通のkey,valueを出力し、Eは実際にeventを出力します。Wは出力先の切り替えを担います。

impl<S, N, E, W> layer::Layer<S> for Layer<S, N, E, W>
where
    S: Subscriber + for<'a> LookupSpan<'a>,
    N: for<'writer> FormatFields<'writer> + 'static,
    E: FormatEvent<S, N> + 'static,
    W: for<'writer> MakeWriter<'writer> + 'static,
{
    // ...
    fn on_event(&self, event: &Event<'_>, ctx: Context<'_, S>) { /* .. */ }
}

https://github.com/tokio-rs/tracing/blob/tracing-subscriber-0.3.16/tracing-subscriber/src/fmt/fmt_layer.rs#L764

のちほど処理の内容をおっていきますが、fmt_layer::LayerLayerを実装しており、Layeredから呼ばれるon_event()が実際のeventのロギング処理です。

Subscriberの登録

FmtSubscriberの各componentをみてきたので最後にconstructしたFmtSubscribertracingから見える位置にセットする処理をみます。

tracing_subscriber::fmt().init();

この処理が呼ばれるとSubscriberBuilderFmtSubscriberをconstructしたのち以下の処理が呼ばれます

fn try_init(self) -> Result<(), TryInitError> {
        dispatcher::set_global_default(self.into()).map_err(TryInitError::new)?;
    
        // ...

        Ok(())
    }

https://github.com/tokio-rs/tracing/blob/tracing-subscriber-0.3.16/tracing-subscriber/src/util.rs#L59

dispatcher::set_global_defaulttracing_coreに定義されており、以下のような処理です。

static GLOBAL_INIT: AtomicUsize = AtomicUsize::new(UNINITIALIZED);

const UNINITIALIZED: usize = 0;
const INITIALIZING: usize = 1;
const INITIALIZED: usize = 2;

static mut GLOBAL_DISPATCH: Option<Dispatch> = None;
// ...
pub fn set_global_default(dispatcher: Dispatch) -> Result<(), SetGlobalDefaultError> {
    if GLOBAL_INIT
        .compare_exchange(
            UNINITIALIZED,
            INITIALIZING,
            Ordering::SeqCst,
            Ordering::SeqCst,
        )
        .is_ok()
    {
        unsafe {
            GLOBAL_DISPATCH = Some(dispatcher);
        }
        GLOBAL_INIT.store(INITIALIZED, Ordering::SeqCst);
        EXISTS.store(true, Ordering::Release);
        Ok(())
    } else {
        Err(SetGlobalDefaultError { _no_construct: () })
    }
}

https://github.com/tokio-rs/tracing/blob/tracing-subscriber-0.3.16/tracing-core/src/dispatcher.rs#L296

名前にglobalとある通りglobal変数のGLOBAL_DISPATCHにセットする処理です。
AtomicUsize::compare_exchange()は現在の値が第一引数のときのみ第二引数の値をセットする関数です。
そのためこの処理は一度しか呼べないことがわかります。
set_global_default()の引数の型はDispatchとなっているので、FmtSubscriberからDispatchへの変換が必要です。

ここでDispatchの定義ですが以下にある通り、SubscriberArcでtrait objectとして保持しているwrapperです。

#[derive(Clone)]
pub struct Dispatch {
    subscriber: Arc<dyn Subscriber + Send + Sync>,
}

https://github.com/tokio-rs/tracing/blob/tracing-subscriber-0.3.16/tracing-core/src/dispatcher.rs#L154

シンプルなwrapperなのでtracing_core::Subscriberを実装した型からDispatchへの変換が提供されています。

impl<S> From<S> for Dispatch
where
    S: Subscriber + Send + Sync + 'static,
{
    #[inline]
    fn from(subscriber: S) -> Self {
        Dispatch::new(subscriber)
    }
}

https://github.com/tokio-rs/tracing/blob/tracing-subscriber-0.3.16/tracing-core/src/dispatcher.rs#L720

impl Dispatch {
    // ...
    pub fn new<S>(subscriber: S) -> Self
        where
            S: Subscriber + Send + Sync + 'static,
    {
        let me = Dispatch {
            subscriber: Arc::new(subscriber),
        };
        callsite::register_dispatch(&me);
        me
    }
}

https://github.com/tokio-rs/tracing/blob/tracing-subscriber-0.3.16/tracing-core/src/dispatcher.rs#L451

Dispatch::new()の中でSubscriberをHeapに確保します。callsite::register_dispatch()はのちほど言及します。

ということで、FmtSubscriberの初期化処理(init())ではFmtSubscriberをArcにしてDispatchで薄くwrapしてglobal変数にセットしていることがわかりました。info!()info_span!()ではこのglobalのDispatch(FmtSubscriber)が参照されます。
callsite::register_dispatch()はfiltering処理を見ていく際に確認します。

FmtSubscriber まとめ

Layered<
    LevelFilter,
    Layered<
        fmt_layer::Layer,
        Registry,
    >
>

FmtSubscriberの各componentの概要をみてきました。
LayeredLayerSubscriberをcomposeする型でそれ自身がSubscriberです。
LevelFilterはloggingのenable判断を行うLayerです。
fmt_layer::Layerはeventのloggingを担うLayerinfo!()がloggingされるのはこのLayerの実装によります。
Registerはroot Layerともいうべき役割で、spanの管理をおこないます。

tracing::Span::new()

FmtSubscriberの概要を押さえたのでいよいよtracingのapiを追っていきます。 コードの概略をもう一度みてみます。

fn main() {
    tracing_subscriber::fmt().init();

    let span = {
        static CALLSITE = { /* ... */ };
        tracing::Span::new(CALLSITE)
    };
    let _guard = span.enter();

    {
        static CALLSITE = { /* ... */ }
        tracing::Event::dispatch(CALLSITE)
    }
}

tracing_subscriber::fmt().init()FmtSubscriberのconstructとglobal変数へのセットということを見てきたので、tracing::Span::new()をみていきます。

impl Span {
    pub fn new(meta: &'static Metadata<'static>, values: &field::ValueSet<'_>) -> Span {
        dispatcher::get_default(|dispatch| Self::new_with(meta, values, dispatch))
    }
    
    pub fn new_with(
        meta: &'static Metadata<'static>,
        values: &field::ValueSet<'_>,
        dispatch: &Dispatch,
    ) -> Span {
        let new_span = Attributes::new(meta, values);
        Self::make_with(meta, new_span, dispatch)
    }

    fn make_with(
        meta: &'static Metadata<'static>,
        new_span: Attributes<'_>,
        dispatch: &Dispatch,
    ) -> Span {
        let attrs = &new_span;
        let id = dispatch.new_span(attrs);
        let inner = Some(Inner::new(id, dispatch));

        let span = Self {
            inner,
            meta: Some(meta),
        };

        // ...
        
        span
    }
}

https://github.com/tokio-rs/tracing/blob/tracing-subscriber-0.3.16/tracing/src/span.rs#L436

dispatcher::get_default()Span::new_with()で自身をconstructする処理をclosureで渡しています。

thread_local! {
    static CURRENT_STATE: State = State {
        default: RefCell::new(None),
        can_enter: Cell::new(true),
    };
}

struct State {
    default: RefCell<Option<Dispatch>>,
    can_enter: Cell<bool>,
}

pub fn get_default<T, F>(mut f: F) -> T
where
    F: FnMut(&Dispatch) -> T,
{
    CURRENT_STATE
        .try_with(|state| {
            if let Some(entered) = state.enter() {
                return f(&*entered.current());
            }

            f(&Dispatch::none())
        })
        .unwrap_or_else(|_| f(&Dispatch::none()))
}

https://github.com/tokio-rs/tracing/blob/tracing-subscriber-0.3.16/tracing-core/src/dispatcher.rs#L364

dispatcher::get_default()の中ではthreadごとに保持しているDispatchを参照します。State.defaultに保持されているRefCell<Option<Dispatch>>は初期状態ではNoneです。

State自体はstaticでcompile時に初期化されているので、State::enter()の処理をみてみると

impl State {
    // ...
    fn enter(&self) -> Option<Entered<'_>> {
    if self.can_enter.replace(false) {
        Some(Entered(self))
    } else {
        None
    }
}

https://github.com/tokio-rs/tracing/blob/tracing-subscriber-0.3.16/tracing-core/src/dispatcher.rs#L799

EnteredというStateのguardを表す型を返し、Entered::current()の戻り値でSpan::new()で渡したclosureを呼び出します。

impl<'a> Entered<'a> {
    #[inline]
    fn current(&self) -> RefMut<'a, Dispatch> {
        let default: RefMut<Option<Dispatch>> = self.0.default.borrow_mut();
        // default is None
        RefMut::map(default, |default| {
            default.get_or_insert_with(|| get_global().cloned().unwrap_or_else(Dispatch::none))
        })
    }
}

https://github.com/tokio-rs/tracing/blob/tracing-subscriber-0.3.16/tracing-core/src/dispatcher.rs#L811

わかりづらいかもしれませんがここにきてようやく最初にセットしたGlobalのDispatchが参照されます。上記のdefault変数はNoneで、Option::get_or_insert_with()はNoneの場合closureの戻り値を自身にセットしたうでそのmut参照を返します。

fn get_global() -> Option<&'static Dispatch> {
    if GLOBAL_INIT.load(Ordering::SeqCst) != INITIALIZED {
        return None;
    }
    unsafe {
        // This is safe given the invariant that setting the global dispatcher
        // also sets `GLOBAL_INIT` to `INITIALIZED`.
        Some(GLOBAL_DISPATCH.as_ref().expect(
            "invariant violated: GLOBAL_DISPATCH must be initialized before GLOBAL_INIT is set",
        ))
    }
}

https://github.com/tokio-rs/tracing/blob/tracing-subscriber-0.3.16/tracing-core/src/dispatcher.rs#L423

これでようやく最初のtracing_subscriber::fmt().init()でセットしたDispatch(FmtSubscriber)が参照されていることがわかりました。

あらためて、Span::new()に戻るとnew() -> new_with() -> make_with()と呼ばれます。

impl Span {
    // ...
    fn make_with(
        meta: &'static Metadata<'static>,
        new_span: Attributes<'_>,
        dispatch: &Dispatch,
    ) -> Span {
        let attrs = &new_span;
        let id = dispatch.new_span(attrs);
        let inner = Some(Inner::new(id, dispatch));

        let span = Self {
            inner,
            meta: Some(meta),
        };

        // ...

        span
    }
}

https://github.com/tokio-rs/tracing/blob/tracing-subscriber-0.3.16/tracing/src/span.rs#L563

MetadataAttributesinfo_span!()の情報です。

let id = dispatch.new_span(attrs);

ここにきてようやくtracingtracing_subscriberがつながりました。
引数のdispatchはglobalに確保したDispatchであることを見てきておりさらにDispatchFmtSubscriberのwrapperであることもわかっています。ということでFmtSubscriber::new_span()をみていきます。

pub struct Subscriber<
    N = format::DefaultFields,
    E = format::Format<format::Full>,
    F = LevelFilter,
    W = fn() -> io::Stdout,
> {
    inner: layer::Layered<F, Formatter<N, E, W>>,
}

impl<N, E, F, W> tracing_core::Subscriber for Subscriber<N, E, F, W>
    where // ...
{
    fn new_span(&self, attrs: &span::Attributes<'_>) -> span::Id {
        self.inner.new_span(attrs)
    }
}

https://github.com/tokio-rs/tracing/blob/tracing-subscriber-0.3.16/tracing-subscriber/src/fmt/mod.rs#L387

Subscriber(FmtSubscriber)はLayeredのwrapperなので基本的に処理をすべてinnerに委譲します。ということで次はLayered::new_span()です。

impl<L, S> Subscriber for Layered<L, S>
where
    L: Layer<S>,
    S: Subscriber,
{
    fn new_span(&self, span: &span::Attributes<'_>) -> span::Id {
        let id = self.inner.new_span(span);
        self.layer.on_new_span(span, &id, self.ctx());
        id
    }
}

https://github.com/tokio-rs/tracing/blob/tracing-subscriber-0.3.16/tracing-subscriber/src/layer/layered.rs#L125

LayeredのgenericsSは自身がwrapしているSubscriber(orLayer)でそれがSubscriberを実装していることがわかっています。
ここで注目していただきたいのが、最初にself.inner.new_span()を呼び出した後自身のself.layer.on_new_span()を呼んでいる点です。
FmtSubscriberの構造の概略を再掲すると

Layered<
    LevelFilter,
    Layered<
        fmt_layer::Layer,
        Registry,
    >
>

のようになっているので、上記のself.innerLayered<fmt_layer::Layer,Registry>を参照します。そして、このnestしたLayerednew_span()でもself.inner.new_span()が最初によばれるので結局、Registry::new_span()が呼ばれることになります。

impl Subscriber for Registry {
    // ...
    fn new_span(&self, attrs: &span::Attributes<'_>) -> span::Id {
        let parent = if attrs.is_root() {
            None
        } else if attrs.is_contextual() {
            self.current_span().id().map(|id| self.clone_span(id))
        } else {
            attrs.parent().map(|id| self.clone_span(id))
        };

        let id = self
            .spans
            .create_with(|data| {
                data.metadata = attrs.metadata();
                data.parent = parent;
                data.filter_map = crate::filter::FILTERING.with(|filtering| filtering.filter_map());
                #[cfg(debug_assertions)]
                {
                    if data.filter_map != FilterMap::default() {
                        debug_assert!(self.has_per_layer_filters());
                    }
                }

                let refs = data.ref_count.get_mut();
                debug_assert_eq!(*refs, 0);
                *refs = 1;
            })
            .expect("Unable to allocate another span");
        idx_to_id(id)
    }
}

ようやくspanの実質的な処理にたどり着きました。
まず、

let parent = if attrs.is_root() {
    None
} else if attrs.is_contextual() {
    self.current_span().id().map(|id| self.clone_span(id))
} else {
    attrs.parent().map(|id| self.clone_span(id))
};

このparentNoneが入ります。info_span!() macroは明示的に親のspanを指定することもできるのでここで親のspan::Idの判定をしています。今回の例では今生成しているspanがrootなので親はいません。
重要なのは以下の箇所です。

let id = self
    .spans
    .create_with(|data: &mut DataInner| {
        data.metadata = attrs.metadata();
        data.parent = parent;
        // ...

Registryの定義を確認すると

use sharded_slab::{pool::Ref, Clear, Pool};

pub struct Registry {
    spans: Pool<DataInner>,
    current_spans: ThreadLocal<RefCell<SpanStack>>,
    next_filter_id: u8,
}

となっており、self.span.create_with()shareded_slab::Pool::create_with()を呼んでいます。
ここで前提でふれたshareded_slab::Poolがでてきます。 docには

Creates a new object in the pool with the provided initializer, returning a key that may be used to access the new object.

とあるので、この処理でRegistry内にDataInnerが生成され、そのDataInnerを識別するためのidが返されます。DataInnerの定義をみてみると以下のようになっています。

struct DataInner {
    filter_map: FilterMap,
    metadata: &'static Metadata<'static>,
    parent: Option<Id>,
    ref_count: AtomicUsize,
    pub(crate) extensions: RwLock<ExtensionsInner>,
}

https://github.com/tokio-rs/tracing/blob/tracing-subscriber-0.3.16/tracing-subscriber/src/registry/sharded.rs#L123

ここで、metadataとして、info_span!()で生成した呼び出し元の情報を 保持していることがわかります。またextensionsを通じて任意の型を保持できる機能もあるのですがこれはSpan::enter()で利用します。

最後にidx_to_id()sharded_slabのindexをSpan::Idにwrapします。

pub struct Id(NonZeroU64);

fn idx_to_id(idx: usize) -> Id {
    Id::from_u64(idx as u64 + 1)
}

この生成されたsharded_slabのindexをspanのidとして呼び出し元に返します。

impl Span {
    // ...
    fn make_with(
        meta: &'static Metadata<'static>,
        new_span: Attributes<'_>,
        dispatch: &Dispatch,
    ) -> Span {
        let attrs = &new_span;
        // 👇
        let id = dispatch.new_span(attrs);
        let inner = Some(Inner::new(id, dispatch));

        let span = Self {
            inner,
            meta: Some(meta),
        };

        // ...

        span
    }
}

このidとDispatchMetadataを保持するSpanを返します。

pub struct Span {
    inner: Option<Inner>,
    meta: Option<&'static Metadata<'static>>,
}

#[derive(Debug)]
pub(crate) struct Inner {
    id: Id,
    subscriber: Dispatch,
}

https://github.com/tokio-rs/tracing/blob/tracing-subscriber-0.3.16/tracing/src/span.rs#L348

ということで、Spann::new()を呼び出すとglobalに確保したFmtSubscriberのinnerに保持していたRegistry内のsharded_slab::PoolSpanに関する情報が保持され識別子としてSpan::Idが振り出されることがわかりました。
これがRegistryのdocに書いてあった

Registry is responsible for storing span metadata

の実体ということがわかりました。
次にSpan::enter()をみていくのですが、この処理を追っていくとdocの

recording relationships between spans, and tracking which spans are active and which are closed.

の具体的な処理内容がわかります。

tracing::Span::enter()

Span::enter()の内容は以下にようになっています。

impl Span {
    // ...
    pub fn enter(&self) -> Entered<'_> {
        self.do_enter();
        Entered { span: self }
    }

    fn do_enter(&self) {
        if let Some(inner) = self.inner.as_ref() {
            inner.subscriber.enter(&inner.id);
        }

        // ...
    }
}

https://github.com/tokio-rs/tracing/blob/tracing-subscriber-0.3.16/tracing/src/span.rs#L785

Enteredはguard用のstructでDropを実装しているので最後に見ます。Spanは以下のように定義されているので、Span.inner.subscriberFmtSubscriberを参照しています。

#[derive(Clone)]
pub struct Span {
    inner: Option<Inner>,
    meta: Option<&'static Metadata<'static>>,
}

#[derive(Debug)]
pub(crate) struct Inner {
    id: Id,
    subscriber: Dispatch,
}

そして、FmtSubscriberは処理をLayeredに委譲しており、LayeredSpan::new()でみたとおり、innerをまず呼び出します。

impl<L, S> Subscriber for Layered<L, S>
    where
        L: Layer<S>,
        S: Subscriber,
{
    // ...
    fn enter(&self, span: &span::Id) {
        self.inner.enter(span);
        self.layer.on_enter(span, self.ctx());
    }
}

ということで、Span::new()同様、Span::enter()も最初にRegistryによって処理されます。
RegistrySpan::enter()で渡されたSpan::Idをどのように扱うかみていきます。

pub struct Registry {
    spans: Pool<DataInner>,
    current_spans: ThreadLocal<RefCell<SpanStack>>,
    next_filter_id: u8,
}

impl Subscriber for Registry {
    // ...
    fn enter(&self, id: &span::Id) {
        if self
            .current_spans
            .get_or_default()
            .borrow_mut()
            .push(id.clone())
        {
            self.clone_span(id);
        }
    }
}

https://github.com/tokio-rs/tracing/blob/tracing-subscriber-0.3.16/tracing-subscriber/src/registry/sharded.rs#L289

self.current_spansThreadLocalを参照しており、以下のようにThreadLocalは以下のようにThreadLocal<T>TDefaultを実装している場合、ThreadLocal::get_or_default()T::default()を返します。

impl<T: Send + Default> ThreadLocal<T> {
    pub fn get_or_default(&self) -> &T {
        self.get_or(Default::default)
    }
}

https://docs.rs/thread_local/latest/thread_local/struct.ThreadLocal.html#method.get_or_default

同様にRefCell<T>TDefaultを実装している場合、T::default()を返すので最終的にはSpanStack::default()が呼ばれます。

pub(crate) use tracing_core::span::Id;

#[derive(Debug)]
struct ContextId {
    id: Id,
    duplicate: bool,
}

#[derive(Debug, Default)]
pub(crate) struct SpanStack {
    stack: Vec<ContextId>,
}

https://github.com/tokio-rs/tracing/blob/tracing-subscriber-0.3.16/tracing-subscriber/src/registry/stack.rs#L14

SpanStackVec<ContextId>のwrapperで、ContextIdspan::Idのwrapperなので、実体としてはVec<span::Id>といえます。
以上を踏まえてもう一度Registry::enter()をみてみると

    fn enter(&self, id: &span::Id) {
        if self
            .current_spans    // ThreadLocal<RefCell<SpanStack>>
            .get_or_default() // RefCell<SpanStack>
            .borrow_mut()     // RefMut<SpanStack>
            .push(id.clone()) // SpanStack::push()
        {
            self.clone_span(id);
        }
    }

のようになっており、SpanStackをconstructしたのち、span::IdVecにpushします。

impl SpanStack {
    #[inline]
    pub(super) fn push(&mut self, id: Id) -> bool {
        let duplicate = self.stack.iter().any(|i| i.id == id);
        self.stack.push(ContextId { id, duplicate });
        !duplicate
    }
}

https://github.com/tokio-rs/tracing/blob/tracing-subscriber-0.3.16/tracing-subscriber/src/registry/stack.rs#L20

SpanStack::push()は現在のstack上に重複があるかを判定したのちpushします。
ここでなぜ重複を考慮する必要があるのだろうという疑問が生じます。

let _guard_a = info_span!("outer").entered();
{
    let _guard_b = info_span!("inner").entered();
}

のようにSpanはmacroの呼び出しごとに生成されるので、上記のouter spanがdropされるまではouter spanに再びenterすることはないように思われるからです。
ここがtracingの注意点でもあるのですが、tracingはasync/awaitのコードではそのまま使えません。(本記事の例のようには)。async/await用にtracing_future crateが用意されそちらを合わせて使う必要があります。本記事ではtracing_futureにはふれません。(次回言及するかもしれません)

Warning: in asynchronous code that uses async/await syntax, Span::enter should be used very carefully or avoided entirely. Holding the drop guard returned by Span::enter across .await points will result in incorrect traces

docにも上記のようにwarningが書かれています。

tracingのコードを読んでみようとおもったきっかけのひとつにどうしてasync/awaitで使うとうまく動作しないのか知りたいというのが一つありました。これはあくまで推測なのですが、async fnの中でinfo_span!()を書くと最終的には以下のようなコードになるからではと考えております。

impl Future for MyFuture {
    type Output = ();

    fn poll(self: Pin<&mut Self>, _cx: &mut Context<'_>) -> Poll<Self::Output> {
        match self.project().state {
            // Running at thread A
            MyFutureState::A(..) => {
                self.span = info_span!("my_span");
                self.guard = span.enter();
                self.state = MyFutureState::B;
                // ...
            }
            // Running at thread B
            MyFutureState::B(..) => { /* ... */ }
        }
    }
}

のようなFuture::pollになり、Span::enter()がthread Aで実行され、guardのdropがthread Bで実行される結果、thread AのSpanStack上のidがpopされずstack上に留まり続けることになってしまう。

話をRegistry::enter()に戻します。ここで注意したいのが

pub struct Registry {
    spans: Pool<DataInner>,
    current_spans: ThreadLocal<RefCell<SpanStack>>,
    // ...
}

spansはthread間で共有されるのに対して、current_spansThreadLocal型なのでthreadごとにSpanStackが生成される点です。

これでSpan::enter()の中で、Registryのstackにenterしたspanのidを保持することによって

tracking which spans are active

していることがわかりました。

impl Span {
    pub fn enter(&self) -> Entered<'_> {
        self.do_enter();
        Entered { span: self }
    }
}

Span::enter()は戻り値としてEnteredを返します。Enteredはdrop時にspanを閉じる責務をもつguardです。

impl<'a> Drop for Entered<'a> {
    #[inline(always)]
    fn drop(&mut self) {
        self.span.do_exit()
    }
}

Drop時にSpan::do_exit()を呼んでいます。

impl Span {
    fn do_exit(&self) {
        if let Some(inner) = self.inner.as_ref() {
            inner.subscriber.exit(&inner.id);
        }
        // ...
    }
}

Span::do_exit()enter()同様subscriberのexitを呼び出します。exit()の実装も興味深い点(Drop時特有の考慮事項)が多いのですがeventのloggingの観点からはずれてしまうので詳細は割愛します。基本的にはSpanStackから当該idをremoveします。

ここまででようやくspanの生成とactivate(enter)の処理内容がわかりました。
前準備が終わったのでついにinfo!()処理に入ることができます。

tracing::Event::dispatch

Macroのexpandで確認したようにinfo!()は最終的にEvent::dispatch()に展開されます。
Metadadafield::ValueSetは呼び出し時の情報です。

impl<'a> Event<'a> {
    /// Constructs a new `Event` with the specified metadata and set of values,
    /// and observes it with the current subscriber.
    pub fn dispatch(metadata: &'static Metadata<'static>, fields: &'a field::ValueSet<'_>) {
        let event = Event::new(metadata, fields);
        crate::dispatcher::get_default(|current| {
            current.event(&event);
        });
    }
}

Eventは以下のように定義されています。fieldmetadataはmacro呼び出し時の情報です。parentEventが含まれているspanです。

#[derive(Debug)]
pub struct Event<'a> {
    fields: &'a field::ValueSet<'a>,
    metadata: &'static Metadata<'static>,
    parent: Parent,
}

impl<'a> Event<'a> {
    pub fn new(metadata: &'static Metadata<'static>, fields: &'a field::ValueSet<'a>) -> Self {
        Event {
            fields,
            metadata,
            parent: Parent::Current,
        }
    }
}

https://github.com/tokio-rs/tracing/blob/tracing-subscriber-0.3.16/tracing-core/src/event.rs#L23

pub(crate) enum Parent {
    Root,
    Current,
    Explicit(Id),
}

Parentは上記のようにExplicitで明示的に指定するか、Currentでcontextから判断するかの情報です。info!()は内部的にevent!() macro呼び出しに展開されるのですがevent!()では紐づくspanを下記のように指定することも可能です。

let span = span!(Level::TRACE, "my span");
event!(parent: &span, Level::INFO, "something has happened!");

Event::dispatch()Dispatch::event()を呼び出しています。

impl Dispatch {
    pub fn event(&self, event: &Event<'_>) {
        if self.subscriber.event_enabled(event) {
            self.subscriber.event(event);
        }
    } 
}

https://github.com/tokio-rs/tracing/blob/tracing-subscriber-0.3.16/tracing-core/src/dispatcher.rs#L584

Subscriber::event_enabled()のenable判定は一通りの流れを確認したあと、CALLSITEのregister処理でみるのでここでは割愛します。
Dispatch::event() -> FmtSubscriber::event() -> Layered::event()の委譲の流れはspanと同様です。またLayeredの処理もまずinnerに先に委譲するのも同じです。

impl<L, S> Subscriber for Layered<L, S>
where
    L: Layer<S>,
    S: Subscriber,
{
    fn event(&self, event: &Event<'_>) {
        self.inner.event(event);
        self.layer.on_event(event, self.ctx());
    }
}

ということで、最初にRegistryはなにかしているでしょうか。

impl Subscriber for Registry {
    /// This is intentionally not implemented, as recording events
    /// is the responsibility of layers atop of this registry.
    fn event(&self, _: &Event<'_>) {}
}

コメントにもある通り、Registry::event()ではなにもしていません。eventのhandlingはlayerの責務であるとしています。ということで、次はfmt_layer::Layerです。

impl<S, N, E, W> layer::Layer<S> for Layer<S, N, E, W>
    where
        S: Subscriber + for<'a> LookupSpan<'a>,
        N: for<'writer> FormatFields<'writer> + 'static,
        E: FormatEvent<S, N> + 'static,
        W: for<'writer> MakeWriter<'writer> + 'static,
{
    fn on_event(&self, event: &Event<'_>, ctx: Context<'_, S>) {
        thread_local! {
                static BUF: RefCell<String> = RefCell::new(String::new());
            }

        BUF.with(|buf| {
            let borrow = buf.try_borrow_mut();
            let mut a;
            let mut b;
            let mut buf = match borrow {
                Ok(buf) => {
                    a = buf;
                    &mut *a
                }
                _ => {
                    b = String::new();
                    &mut b
                }
            };

            let ctx = self.make_ctx(ctx, event);
            if self
                .fmt_event
                .format_event(
                    &ctx,
                    format::Writer::new(&mut buf).with_ansi(self.is_ansi),
                    event,
                )
                .is_ok()
            {
                let mut writer = self.make_writer.make_writer_for(event.metadata());
                let res = io::Write::write_all(&mut writer, buf.as_bytes());
                if self.log_internal_errors {
                    if let Err(e) = res {
                        eprintln!("[tracing-subscriber] Unable to write an event to the Writer for this Subscriber! Error: {}\n", e);
                    }
                }
            } else if self.log_internal_errors {
                let err_msg = format!("Unable to format the following event. Name: {}; Fields: {:?}\n",
                                      event.metadata().name(), event.fields());
                let mut writer = self.make_writer.make_writer_for(event.metadata());
                let res = io::Write::write_all(&mut writer, err_msg.as_bytes());
                if let Err(e) = res {
                    eprintln!("[tracing-subscriber] Unable to write an \"event formatting error\" to the Writer for this Subscriber! Error: {}\n", e);
                }
            }

            buf.clear();
        });
    }
}

https://github.com/tokio-rs/tracing/blob/tracing-subscriber-0.3.16/tracing-subscriber/src/fmt/fmt_layer.rs#L904

がっつり処理が書かれています。またio::Write::write_all()があるのでどうやらここでeventの書き込み処理まで実施していそうです。ここがeventのlogging処理と思われるで見ていきましょう。

fn on_event(&self, event: &Event<'_>, ctx: Context<'_, S>) { }

まずon_event()の引数ですが、Eventinfo!()で生成したEventなのは良いとして、Contextはどこから来たのでしょうか。
Layeredevent()をもう一度みてみると

    fn event(&self, event: &Event<'_>) {
        self.inner.event(event);
        self.layer.on_event(event, self.ctx());
    }

fmt_layer::Layer::on_event()self.ctx()Contextを生成して渡していました。

impl<L, S> Layered<L, S>
where
    S: Subscriber,
{
    fn ctx(&self) -> Context<'_, S> {
        Context::new(&self.inner)
    }
}

pub struct Context<'a, S> {
    subscriber: Option<&'a S>,
    #[cfg(all(feature = "registry", feature = "std"))]
    filter: FilterId,
}

// === impl Context ===

impl<'a, S> Context<'a, S>
    where
        S: Subscriber,
{
    pub(super) fn new(subscriber: &'a S) -> Self {
        Self {
            subscriber: Some(subscriber),

            #[cfg(feature = "registry")]
            filter: FilterId::none(),
        }
    }
}

ということで、ContextSubscriberのwrapperで、ここではRegistryを渡していると考えることができます。

    fn on_event(&self, event: &Event<'_>, ctx: Context<'_, S>) {
        thread_local! {
                static BUF: RefCell<String> = RefCell::new(String::new());
            }

        BUF.with(|buf| {
            let borrow = buf.try_borrow_mut();
            let mut a;
            let mut b;
            let mut buf = match borrow {
                Ok(buf) => {
                    a = buf;
                    &mut *a
                }
                _ => {
                    b = String::new();
                    &mut b
                }
            };

            // ...
        }
}

ここは実質的にformatしたeventの書き込みbufferの生成処理です。thread localとRefCellの合わせ技でStringをこの様に再利用する方法が参考になります。

let ctx = self.make_ctx(ctx, event);

ContextEventを保持するFmtContextを生成しています。

pub struct FmtContext<'a, S, N> {
    pub(crate) ctx: Context<'a, S>,
    pub(crate) fmt_fields: &'a N,
    pub(crate) event: &'a Event<'a>,
}

impl<S, N, E, W> Layer<S, N, E, W>
where
    S: Subscriber + for<'a> LookupSpan<'a>,
    N: for<'writer> FormatFields<'writer> + 'static,
    E: FormatEvent<S, N> + 'static,
    W: for<'writer> MakeWriter<'writer> + 'static,
{
    #[inline]
    fn make_ctx<'a>(&'a self, ctx: Context<'a, S>, event: &'a Event<'a>) -> FmtContext<'a, S, N> {
        FmtContext {
            ctx,
            fmt_fields: &self.fmt_fields,
            event,
        }
    }
}

https://github.com/tokio-rs/tracing/blob/tracing-subscriber-0.3.16/tracing-subscriber/src/fmt/fmt_layer.rs#L971

if self
    .fmt_event
    .format_event(
        &ctx,
        format::Writer::new(&mut buf).with_ansi(self.is_ansi),
        event,
    )
    .is_ok()
{
    let mut writer = self.make_writer.make_writer_for(event.metadata());
    let res = io::Write::write_all(&mut writer, buf.as_bytes());
    if self.log_internal_errors {
        if let Err(e) = res {
            eprintln!("[tracing-subscriber] Unable to write an event to the Writer for this Subscriber! Error: {}\n", e);
        }
    }
} else if self.log_internal_errors {
    let err_msg = format!("Unable to format the following event. Name: {}; Fields: {:?}\n",
                          event.metadata().name(), event.fields());
    let mut writer = self.make_writer.make_writer_for(event.metadata());
    let res = io::Write::write_all(&mut writer, err_msg.as_bytes());
    if let Err(e) = res {
        eprintln!("[tracing-subscriber] Unable to write an \"event formatting error\" to the Writer for this Subscriber! Error: {}\n", e);
    }
}

buf.clear();

self.fmt_event.format_event()でおそらく、確保したStringにeventの情報を書き込んでおり、成功した場合は

let mut writer = self.make_writer.make_writer_for(event.metadata());
let res = io::Write::write_all(&mut writer, buf.as_bytes());

self.make_writerで書き込み先のwriterを生成します。

pub struct Subscriber<
    // ...
    W = fn() -> io::Stdout,
> {/* ... */ }

としてデフォルトでio::Stdoutを返す関数が指定されているのでここではwriterStdoutになります。残りの処理はeventのformat時のエラーやbuffer書き込み時のエラーハンドリングなので省略します。
async fnの中でinfo!()を呼ぶと上記でみたようにio::Stdoutに書きこみ処理が走っておりこれはblockingな処理と思われるので、async fnの中ではblockingな処理を呼ばないという原則に反しないのかなという疑問が生じました。ソースを読んだ限りですと、Event::dispatch()といっても別threadに逃すような処理は見受けられなかったので気になりました。

この点はともかくとして、ついにeventの書き込み処理をみつけたので残りは以下のeventのformat処理です。

self
    .fmt_event
    .format_event(
        &ctx,
        format::Writer::new(&mut buf).with_ansi(self.is_ansi),
        event,
   )

fmt_layer::Layerの定義は以下のようになっており、fmt_eventはデフォルトではformat::Format<format::Full>です。

pub struct Layer<
    S,
    N = format::DefaultFields,
    E = format::Format<format::Full>,
    W = fn() -> io::Stdout,
> {
    make_writer: W,
    fmt_fields: N,
    fmt_event: E,
    fmt_span: format::FmtSpanConfig,
    is_ansi: bool,
    log_internal_errors: bool,
    _inner: PhantomData<fn(S)>,
}

また、format_event()FormatEvent traitとして定義されており、format::Format<format::Full>はこれを実装しています。

pub trait FormatEvent<S, N>
where
    S: Subscriber + for<'a> LookupSpan<'a>,
    N: for<'a> FormatFields<'a> + 'static,
{
    /// Write a log message for `Event` in `Context` to the given [`Writer`].
    fn format_event(
        &self,
        ctx: &FmtContext<'_, S, N>,
        writer: Writer<'_>,
        event: &Event<'_>,
    ) -> fmt::Result;
}

https://github.com/tokio-rs/tracing/blob/tracing-subscriber-0.3.16/tracing-subscriber/src/fmt/format/mod.rs#L195

impl<S, N, T> FormatEvent<S, N> for Format<Full, T>
where
    S: Subscriber + for<'a> LookupSpan<'a>,
    N: for<'a> FormatFields<'a> + 'static,
    T: FormatTime,
{
    fn format_event(
        &self,
        ctx: &FmtContext<'_, S, N>,
        mut writer: Writer<'_>,
        event: &Event<'_>,
    ) -> fmt::Result {
        // ...
        let meta = event.metadata();
        
        if let Some(ansi) = self.ansi {
            writer = writer.with_ansi(ansi);
        }

        self.format_timestamp(&mut writer)?;

        if self.display_level {
            // ...
        }

        if self.display_thread_name {
            // ...
        }

        if self.display_thread_id {
            // ...
        }

        let dimmed = writer.dimmed();

        if let Some(scope) = ctx.event_scope() {
            // ...
            for span in scope.from_root() {
                write!(writer, "{}", bold.paint(span.metadata().name()))?;
                // ...

                let ext = span.extensions();
                if let Some(fields) = &ext.get::<FormattedFields<N>>() {
                    if !fields.is_empty() {
                        write!(writer, "{}{}{}", bold.paint("{"), fields, bold.paint("}"))?;
                    }
                }
                // ...
            }
            // ...
        };

        if self.display_target {
            // ...
        }

        // ...

        if self.display_filename {
            // ...
        }

        ctx.format_fields(writer.by_ref(), event)?;
        writeln!(writer)
    }
}

https://github.com/tokio-rs/tracing/blob/tracing-subscriber-0.3.16/tracing-subscriber/src/fmt/format/mod.rs#L890

長いですが、概要としては以下のようなログの情報を設定に応じて書き込んでいます。

2022-11-11T08:39:02.198973Z  INFO span_1{key="hello"}: tracing_handson: hello

今回注目するのは、どのようにspanの情報を書き込んでいるかですが、おそらく以下の処理と思われます。

if let Some(scope) = ctx.event_scope() {
    // ...
    for span in scope.from_root() {
        // ...
        let ext = span.extensions();
        if let Some(fields) = &ext.get::<FormattedFields<N>>() {
            if !fields.is_empty() {
                write!(writer, "{}{}{}", bold.paint("{"), fields, bold.paint("}"))?;
            }
        }
        // ...
    }
    // ...
};

概要としては、ctx(FmtContext)からscopeを取得し、scopeからSpanのiteratorを取得したのち、FormattedFields<N>がspanの情報(key/value)を書き込んでいます。
ということで、まずはscopeから見てみます。

impl<'a, S, N> FmtContext<'a, S, N>
where
    S: Subscriber + for<'lookup> LookupSpan<'lookup>,
    N: for<'writer> FormatFields<'writer> + 'static,
{
    pub fn event_scope(&self) -> Option<registry::Scope<'_, S>>
        where
            S: for<'lookup> registry::LookupSpan<'lookup>,
    {
        self.ctx.event_scope(self.event)
    }    
}

https://github.com/tokio-rs/tracing/blob/tracing-subscriber-0.3.16/tracing-subscriber/src/fmt/fmt_layer.rs#L1147

まずContext.event_scope()に委譲します。

impl<'a, S> Context<'a, S>
where
    S: Subscriber,
{
    pub fn event_scope(&self, event: &Event<'_>) -> Option<registry::Scope<'_, S>>
        where
            S: for<'lookup> LookupSpan<'lookup>,
    {
        Some(self.event_span(event)?.scope())
    }

    pub fn event_span(&self, event: &Event<'_>) -> Option<SpanRef<'_, S>>
        where
            S: for<'lookup> LookupSpan<'lookup>,
    {
        if event.is_root() {
            None
        } else if event.is_contextual() {
            self.lookup_current()
        } else {
            event.parent().and_then(|id| self.span(id))
        }
    }
}

https://github.com/tokio-rs/tracing/blob/tracing-subscriber-0.3.16/tracing-subscriber/src/layer/context.rs#L364

Context::event_scope()Context::event_span()を呼び出します。
is_root()is_contextual()Event.parentの判定でここでは、Parent::Currentが設定されているので、is_contextual()がtrueを返し、Context::lookup_current()が呼び出されます。

impl<'a, S> Context<'a, S>
    where
        S: Subscriber,
{

    pub fn lookup_current(&self) -> Option<registry::SpanRef<'_, S>>
        where
            S: for<'lookup> LookupSpan<'lookup>,
    {
        let subscriber = *self.subscriber.as_ref()?;
        let current = subscriber.current_span();
        let id = current.id()?;
        let span = subscriber.span(id);
        debug_assert!(
            span.is_some(),
            "the subscriber should have data for the current span ({:?})!",
            id,
        );
        
        // ...
        
        span
    }
}

https://github.com/tokio-rs/tracing/blob/tracing-subscriber-0.3.16/tracing-subscriber/src/layer/context.rs#L256

ということでようやく取得処理にたどり着きました。
ContextSubscriberのwrapperでここではRegistryを指しています。

let current = subscriber.current_span();
let id = current.id()?;
let span = subscriber.span(id);

上記で、Registry::current_span()で現在のspanの情報を取得したのち当該span::IdからSpanRefを取得して返しています。

impl Subscriber for Registry {
    fn current_span(&self) -> Current {
        self.current_spans        // ThreadLocal<RefCell<SpanStack>>
            .get()                // Option<&RefCell<SpanStack>>
            .and_then(|spans: &RefCell<SpanStack>| {
                let spans = spans.borrow(); // Ref<SpanStack>
                let id = spans.current()?;
                let span = self.get(id)?;
                Some(Current::new(id.clone(), span.metadata))
            })
            .unwrap_or_else(Current::none)
    }
}

https://github.com/tokio-rs/tracing/blob/tracing-subscriber-0.3.16/tracing-subscriber/src/registry/sharded.rs#L330

Registry::current_span()の中でSpanStackの先頭のspan::Idを取得しています。

impl SpanStack {
    #[inline]
    pub(crate) fn iter(&self) -> impl Iterator<Item = &Id> {
        self.stack
            .iter()
            .rev()
            .filter_map(|ContextId { id, duplicate }| if !*duplicate { Some(id) } else { None })
    }

    #[inline]
    pub(crate) fn current(&self) -> Option<&Id> {
        self.iter().next()
    }
}

https://github.com/tokio-rs/tracing/blob/tracing-subscriber-0.3.16/tracing-subscriber/src/registry/stack.rs#L50

Currentspan::Idのwrapperです。

let current = subscriber.current_span();
let id = current.id()?;
let span = subscriber.span(id);

subscriber.spanspan::Idからspanの情報を取得します。このspanの情報の取得は以下のようにLookupSpanというtraitで定義されています。

pub trait LookupSpan<'a> {
    type Data: SpanData<'a>;
    fn span_data(&'a self, id: &Id) -> Option<Self::Data>;
    
    fn span(&'a self, id: &Id) -> Option<SpanRef<'_, Self>>
    where
        Self: Sized,
    {
        let data = self.span_data(id)?;
        Some(SpanRef {
            registry: self,
            data,
            #[cfg(feature = "registry")]
            filter: FilterId::none(),
        })
    }
    // ...
}

https://github.com/tokio-rs/tracing/blob/tracing-subscriber-0.3.16/tracing-subscriber/src/registry/mod.rs#L92

LookupSpan::span()はdefaultの実装が提供されており、実装する型はspan_data()をimplすればよさそうです。
Registry::span_data()の実装はシンプルでPool<DataInner>から取得するだけです。

impl<'a> LookupSpan<'a> for Registry {
    type Data = Data<'a>;

    fn span_data(&'a self, id: &Id) -> Option<Self::Data> {
        let inner = self.get(id)?;
        Some(Data { inner })
    }

    fn register_filter(&mut self) -> FilterId {
        let id = FilterId::new(self.next_filter_id);
        self.next_filter_id += 1;
        id
    }
}

https://github.com/tokio-rs/tracing/blob/tracing-subscriber-0.3.16/tracing-subscriber/src/registry/sharded.rs#L369

impl Registry {
    fn get(&self, id: &Id) -> Option<Ref<'_, DataInner>> {
        self.spans.get(id_to_idx(id))
    }
}

https://github.com/tokio-rs/tracing/blob/tracing-subscriber-0.3.16/tracing-subscriber/src/registry/sharded.rs#L182

ここまでで、RegistrySpanStackから先頭のspan::Idを取得したのち、Poolに確保していたSpanの情報を取得して、SpanRefとして返すことがわかりました。
必要なのは現在のeventを含んでいるSpanのiteratorなので、それを取得するために、SpanRef::scope()が呼ばれています。

impl<'a, S> Context<'a, S>
where
    S: Subscriber,
{
    pub fn event_scope(&self, event: &Event<'_>) -> Option<registry::Scope<'_, S>>
        where
            S: for<'lookup> LookupSpan<'lookup>,
    {
        Some(self.event_span(event)?.scope())
    }
}
impl<'a, R> SpanRef<'a, R>
where
    R: LookupSpan<'a>,
{
    pub fn scope(&self) -> Scope<'a, R> {
        Scope {
            registry: self.registry,
            next: Some(self.id()),

            #[cfg(feature = "registry")]
            filter: self.filter,
        }
    }
}

https://github.com/tokio-rs/tracing/blob/tracing-subscriber-0.3.16/tracing-subscriber/src/registry/mod.rs#L465

#[derive(Debug)]
pub struct Scope<'a, R> {
    registry: &'a R,
    next: Option<Id>,
    // ...
}

https://github.com/tokio-rs/tracing/blob/tracing-subscriber-0.3.16/tracing-subscriber/src/registry/mod.rs#L210

Scopeはspanのiterateする手段をいくつか提供しており、今回はroot(outer)から取得したいので、Scope::from_root()を呼びます。

impl<'a, R> Scope<'a, R>
where
    R: LookupSpan<'a>,
{
    pub fn from_root(self) -> ScopeFromRoot<'a, R> {
        #[cfg(feature = "smallvec")]
        type Buf<T> = smallvec::SmallVec<T>;
        #[cfg(not(feature = "smallvec"))]
        type Buf<T> = Vec<T>;
        ScopeFromRoot {
            spans: self.collect::<Buf<_>>().into_iter().rev(),
        }
    }
}

https://github.com/tokio-rs/tracing/blob/tracing-subscriber-0.3.16/tracing-subscriber/src/registry/mod.rs#L254

わかりづらいのですが、spans::self.collect::<Buf<_>>().into_iter().rev()Scopeからiteratorを生成しています。

pub struct SpanRef<'a, R: LookupSpan<'a>> {
    registry: &'a R,
    data: R::Data,
    // ...
}

impl<'a, R> Iterator for Scope<'a, R>
where
    R: LookupSpan<'a>,
{
    type Item = SpanRef<'a, R>;

    fn next(&mut self) -> Option<Self::Item> {
        loop {
            let curr = self.registry.span(self.next.as_ref()?)?;

            // ...
            self.next = curr.data.parent().cloned();
            
            // ...
            
            return Some(curr);
        }
    }
}

wrapしているRegistryから現在のspan::Idに対応するspanの情報(SpanRef)を取得したのち、当該spanの親の情報を次に返すidとして保持します。

いろいろ型がでてきてわかりづらいですが、概要としては、Registryで管理しているSpanStackの先頭のspan::Idを取得したのち、そこからthread間で共有している、Spanのmetadataや親情報を保持しているDataInnerを取得して親がなくなるまでiterateしているといえます。

ここまででて以下のようにeventをformatしてStringに書き込む処理のうち、当該eventをscopeに含むspanをiterateする方法がわかりました。

impl<S, N, T> FormatEvent<S, N> for Format<Full, T>
where
    S: Subscriber + for<'a> LookupSpan<'a>,
    N: for<'a> FormatFields<'a> + 'static,
    T: FormatTime,
{
    fn format_event(
        &self,
        ctx: &FmtContext<'_, S, N>,
        mut writer: Writer<'_>,
        event: &Event<'_>,
    ) -> fmt::Result {
        // ...
        if let Some(scope) = ctx.event_scope() {
            // ...
            for span in scope.from_root() {
                write!(writer, "{}", bold.paint(span.metadata().name()))?;
                // ...

                let ext = span.extensions();
                if let Some(fields) = &ext.get::<FormattedFields<N>>() {
                    if !fields.is_empty() {
                        write!(writer, "{}{}{}", bold.paint("{"), fields, bold.paint("}"))?;
                    }
                }
                // ...
            }
            // ...
        };
        // ...
    }
}
for span in scope.from_root() {
    // ...

    let ext = span.extensions();
    if let Some(fields) = &ext.get::<FormattedFields<N>>() {
        if !fields.is_empty() {
            write!(writer, "{}{}{}", bold.paint("{"), fields, bold.paint("}"))?;
        }
    }
    // ...
}

次にSpan::extensions()です。以下のようにこれはExtensionsを返します。

impl<'a, R> SpanRef<'a, R>
where
    R: LookupSpan<'a>,
{
    pub fn extensions(&self) -> Extensions<'_> {
        self.data.extensions()
    }
}

https://github.com/tokio-rs/tracing/blob/tracing-subscriber-0.3.16/tracing-subscriber/src/registry/mod.rs#L481

Extensionsとはなんでしょうか。定義は以下のようになっています。

use crate::sync::RwLockReadGuard;

pub struct Extensions<'a> {
    inner: RwLockReadGuard<'a, ExtensionsInner>,
}

impl<'a> Extensions<'a> {
    #[cfg(feature = "registry")]
    pub(crate) fn new(inner: RwLockReadGuard<'a, ExtensionsInner>) -> Self {
        Self { inner }
    }

    /// Immutably borrows a type previously inserted into this `Extensions`.
    pub fn get<T: 'static>(&self) -> Option<&T> {
        self.inner.get::<T>()
    }
}

https://github.com/tokio-rs/tracing/blob/tracing-subscriber-0.3.16/tracing-subscriber/src/registry/extensions.rs#L39

ExtensionsInnerをwrapしており、Extension::get()で任意のTを取得できるapiを提供しています。

if let Some(fields) = &ext.get::<FormattedFields<N>>() {
    if !fields.is_empty() {
        write!(writer, "{}{}{}", bold.paint("{"), fields, bold.paint("}"))?;
    }
}

eventのformat時に、このget()を利用して、FormattedFieldsを取得しており、このFormattedFieldsがspanのkey/valueの情報をDisplayとして実装していそうです。

ちなみにExtensionsInnerstd::anyを利用して任意の型を受け渡せる様になっています。

use std::{
    any::{Any, TypeId},
    hash::{BuildHasherDefault, Hasher},
};

type AnyMap = HashMap<TypeId, Box<dyn Any + Send + Sync>, BuildHasherDefault<IdHasher>>;

pub(crate) struct ExtensionsInner {
    map: AnyMap,
}

次にこのExtensionsはどこで生成されてspanに付与されているかが気になります。
spanのkey/valueの値はSpan::new()時に決まるはずなので、Span::new()であるとあたりをつけます。
Spanがenterした際にRegistry::new_span()が呼ばれたあとに、Layeredfmt_layer::Layeron_new_span()を呼ぶのでそこをみてみます。

impl<S, N, E, W> layer::Layer<S> for Layer<S, N, E, W>
where
    S: Subscriber + for<'a> LookupSpan<'a>,
    N: for<'writer> FormatFields<'writer> + 'static,
    E: FormatEvent<S, N> + 'static,
    W: for<'writer> MakeWriter<'writer> + 'static,
{
    fn on_new_span(&self, attrs: &Attributes<'_>, id: &Id, ctx: Context<'_, S>) {
        let span = ctx.span(id).expect("Span not found, this is a bug");
        let mut extensions = span.extensions_mut();

        if extensions.get_mut::<FormattedFields<N>>().is_none() {
            let mut fields = FormattedFields::<N>::new(String::new());
            if self
                .fmt_fields
                .format_fields(fields.as_writer().with_ansi(self.is_ansi), attrs)
                .is_ok()
            {
                fields.was_ansi = self.is_ansi;
                extensions.insert(fields);
            } else {
                eprintln!(
                    "[tracing-subscriber] Unable to format the following event, ignoring: {:?}",
                    attrs
                );
            }
        }
        // ...
    }
}

https://github.com/tokio-rs/tracing/blob/tracing-subscriber-0.3.16/tracing-subscriber/src/fmt/fmt_layer.rs#L771

予想通り、extensions.get_mut::<FormattedFields<N>>().is_none()で判定し、extension.insert(fields)でセットしています。
self.fmt_fieldsFormatFields traitを実装しており、span::Attributesの書き込み方法を定義しています。 spanとeventのkey/valueの書き込み処理を共通化しているので、詳細はeventの書き込み時にみていきます。

ここまででて、spanの情報を書き込めたので最後にEventの情報を書き込むことでlogging処理が完了します。

impl<S, N, T> FormatEvent<S, N> for Format<Full, T>
where
    S: Subscriber + for<'a> LookupSpan<'a>,
    N: for<'a> FormatFields<'a> + 'static,
    T: FormatTime,
{
    fn format_event(
        &self,
        ctx: &FmtContext<'_, S, N>,
        mut writer: Writer<'_>,
        event: &Event<'_>,
    ) -> fmt::Result {
        // ...

        ctx.format_fields(writer.by_ref(), event)?;
        writeln!(writer)
    }
}

FmtContext::format_fields()はwrapしているfmt_fieldsに処理を委譲しており、型はDefaultFieldsです。

pub struct FmtContext<'a, S, N> {
    // ...
    pub(crate) fmt_fields: &'a N,
}

impl<'cx, 'writer, S, N> FormatFields<'writer> for FmtContext<'cx, S, N>
where
    S: Subscriber + for<'lookup> LookupSpan<'lookup>,
    N: FormatFields<'writer> + 'static,
{
    fn format_fields<R: RecordFields>(
        &self,
        writer: format::Writer<'writer>,
        fields: R,
    ) -> fmt::Result {
        self.fmt_fields.format_fields(writer, fields)
    }
}

ということで、DefaultFieldsはどうやってeventとspanのkey/valueをformatしているのかなと確認したいところですが、この処理もカスタマイズできるようにgenericになっております。

impl<'writer, M> FormatFields<'writer> for M
where
    M: MakeOutput<Writer<'writer>, fmt::Result>,
    M::Visitor: VisitFmt + VisitOutput<fmt::Result>,
{
    fn format_fields<R: RecordFields>(&self, writer: Writer<'writer>, fields: R) -> fmt::Result {
        let mut v = self.make_visitor(writer);
        fields.record(&mut v);
        v.finish()
    }
}

https://github.com/tokio-rs/tracing/blob/tracing-subscriber-0.3.16/tracing-subscriber/src/fmt/format/mod.rs#L1141

ということでDefaultFieldsFormatFieldsをimplする処理を見にいきたいところですが、このあたりは複雑になっており、どのような問題意識でこれらの処理がtraitに切り出されているか理解できていないです。具体的には以下のようになっています。

FormatFields traitはMakeOutput<_>を実装するMに対してgenericに実装されています。

impl<'writer, M> FormatFields<'writer> for M
where
    M: MakeOutput<Writer<'writer>, fmt::Result>,
    M::Visitor: VisitFmt + VisitOutput<fmt::Result>,
{
    fn format_fields<R: RecordFields>(&self, writer: Writer<'writer>, fields: R) -> fmt::Result {
        let mut v = self.make_visitor(writer);
        fields.record(&mut v);
        v.finish()
    }
}

https://github.com/tokio-rs/tracing/blob/tracing-subscriber-0.3.16/tracing-subscriber/src/fmt/format/mod.rs#L1141

それならDefaultFieldsMakeOutput<_>を実装しているのかなと思うのですがもう一段かませてあり、MakeOutput<_>MakeVisitor<_>を実装するMに対して実装されています。

impl<T, Out, M> MakeOutput<T, Out> for M
where
    M: MakeVisitor<T>,
    M::Visitor: VisitOutput<Out>,
{ }

https://github.com/tokio-rs/tracing/blob/tracing-subscriber-0.3.16/tracing-subscriber/src/field/mod.rs#L212

そして、DefaultFieldsはこのMakeVisitor<_>を実装しているので

impl<'a> MakeVisitor<Writer<'a>> for DefaultFields {
    type Visitor = DefaultVisitor<'a>;

    #[inline]
    fn make_visitor(&self, target: Writer<'a>) -> Self::Visitor {
        DefaultVisitor::new(target, true)
    }
}

https://github.com/tokio-rs/tracing/blob/tracing-subscriber-0.3.16/tracing-subscriber/src/fmt/format/mod.rs#L1187

DefaultFields ->(impl) MakeVisitor<_> ->(blanket impl) MakeOutput<_> ->(blanket impl) FormatFieldsという流れで、DefaultFieldsがfieldsのformat処理を実施しているという理解です。

あらためてeventのformat処理ですが以下のようにvisitorを生成し、RecordFields::record()に渡しています。

impl<'writer, M> FormatFields<'writer> for M
where
    M: MakeOutput<Writer<'writer>, fmt::Result>,
    M::Visitor: VisitFmt + VisitOutput<fmt::Result>,
{
    fn format_fields<R: RecordFields>(&self, writer: Writer<'writer>, fields: R) -> fmt::Result {
        let mut v = self.make_visitor(writer);
        fields.record(&mut v);
        v.finish()
    }
}

fields: RにはEventが渡されるのでEventの実装をみてみます。

impl<'a> RecordFields for Event<'a> {
    fn record(&self, visitor: &mut dyn Visit) {
        Event::record(self, visitor)
    }
}

https://github.com/tokio-rs/tracing/blob/tracing-subscriber-0.3.16/tracing-subscriber/src/field/mod.rs#L162

単純にEvent::recordに委譲しているようです。

impl<'a> Event<'a> {
    pub fn record(&self, visitor: &mut dyn field::Visit) {
        self.fields.record(visitor);
    }
}

https://github.com/tokio-rs/tracing/blob/tracing-subscriber-0.3.16/tracing-core/src/event.rs#L86

さらに、Event.fieldsに委譲しています。Eventの定義を確認すると

pub struct Event<'a> {
    fields: &'a field::ValueSet<'a>,
    metadata: &'static Metadata<'static>,
    parent: Parent,
}

https://github.com/tokio-rs/tracing/blob/tracing-subscriber-0.3.16/tracing-core/src/event.rs#L23

fieldsValueSet型なので、ValueSet::record()を見てみます。

impl<'a> ValueSet<'a> {
    pub fn record(&self, visitor: &mut dyn Visit) {
        let my_callsite = self.callsite();
        for (field, value) in self.values {
            if field.callsite() != my_callsite {
                continue;
            }
            if let Some(value) = value {
                value.record(field, visitor);
            }
        }
    }
}

https://github.com/tokio-rs/tracing/blob/tracing-subscriber-0.3.16/tracing-core/src/field.rs#L990

self.valuesをiterateして、それぞれのvalue.recordにvisitorを渡しています。
ValueSetの定義を確認すると

pub struct ValueSet<'a> {
    values: &'a [(&'a Field, Option<&'a (dyn Value + 'a)>)],
    fields: &'a FieldSet,
}

https://github.com/tokio-rs/tracing/blob/tracing-subscriber-0.3.16/tracing-core/src/field.rs#L166

Field&dyn Valueのtupleのsliceになっています。

Valueは以下のようなtraitで、visitorに自身を記録するmethodを実装しています。

pub trait Value: crate::sealed::Sealed {
    /// Visits this value with the given `Visitor`.
    fn record(&self, key: &Field, visitor: &mut dyn Visit);
}

https://github.com/tokio-rs/tracing/blob/tracing-subscriber-0.3.16/tracing-core/src/field.rs#L335

そして、このVisitの実装はDefaultVisitorとして提供されています。

use tracing_core::{
    field::{self, Field, Visit},
};

// ...
impl<'a> field::Visit for DefaultVisitor<'a> { }

https://github.com/tokio-rs/tracing/blob/tracing-subscriber-0.3.16/tracing-subscriber/src/fmt/format/mod.rs#L1222

試しにこの処理に以下のように🦀を出力する処理を入れてみます。

impl<'a> DefaultVisitor<'a> {
    fn record_debug(&mut self, field: &Field, value: &dyn fmt::Debug) {
        if self.result.is_err() {
            return;
        }

        self.maybe_pad();
        // 👇👇
        write!(self.writer, "🦀");
        
        self.result = match field.name() {
            "message" => write!(self.writer, "{:?}", value),
            // Skip fields that are actually log metadata that have already been handled
            #[cfg(feature = "tracing-log")]
            name if name.starts_with("log.") => Ok(()),
            name if name.starts_with("r#") => write!(
                self.writer,
                "{}{}{:?}",
                self.writer.italic().paint(&name[2..]),
                self.writer.dimmed().paint("="),
                value
            ),
            name => write!(
                self.writer,
                "{}{}{:?}",
                self.writer.italic().paint(name),
                self.writer.dimmed().paint("="),
                value
            ),
        };
    }
}

このあたりはCustom Logging in Rust Using tracing and tracing-subscriberというブログの説明がわかりやすいのでおすすめです。

するとloggingにも🦀が出力されました。

2022-11-18T13:21:33.092617Z  INFO span_1{🦀key="hello"}: tracing_handson: 🦀hello

spanとevent両方に🦀がいるので、fieldのformat処理が共通化されていることもわかります。

ログのfiltering

実際の処理の順番とは前後してしまいますが、最後にログのfiltering処理をみていきます。info!()macro展開後のコードは以下のようになっていました。

    use ::tracing::__macro_support::Callsite as _;
    static CALLSITE: ::tracing::callsite::DefaultCallsite = {/* ... */ };
    let enabled = ::tracing::Level::INFO <= ::tracing::level_filters::STATIC_MAX_LEVEL
        && ::tracing::Level::INFO <= ::tracing::level_filters::LevelFilter::current()
        && {
            let interest = CALLSITE.interest();
            !interest.is_never()
                && ::tracing::__macro_support::__is_enabled(CALLSITE.metadata(), interest)
        };
    if enabled {
        // Event dispatch
    } else {
    }

enabledを判定したのち、trueの場合のみlogging(Event::dispatch())されます。
判定は以下の条件についてなされます。

  • tracing::level_fiters::STATIC_MAX_LEVEL
  • tracing::level_filters::LevelFilter::current()
  • CALLISTE.interest()
  • tracing::__macro_support::__is_enabled()

順番にみていきます。

tracing::level_fiters::STATIC_MAX_LEVEL

コードを読んで初めて知ったのですがloggingのverbosityをruntimeでなくcompile時に指定できるようにするための判定です。以下のようにfeature指定時にverbosityを指定できます。

[dependencies]
tracing = { 
    version = "0.1", 
    features = ["max_level_debug", "release_max_level_warn"],
}

実装方法ですが、cfg_ifが使われています。

cfg_if::cfg_if! {
    if #[cfg(all(not(debug_assertions), feature = "release_max_level_off"))] {
        const MAX_LEVEL: LevelFilter = LevelFilter::OFF;
    } else if #[cfg(all(not(debug_assertions), feature = "release_max_level_error"))] {
        const MAX_LEVEL: LevelFilter = LevelFilter::ERROR;
    } else if #[cfg(all(not(debug_assertions), feature = "release_max_level_warn"))] {
        const MAX_LEVEL: LevelFilter = LevelFilter::WARN;
    } else if #[cfg(all(not(debug_assertions), feature = "release_max_level_info"))] {
        const MAX_LEVEL: LevelFilter = LevelFilter::INFO;
    // ...    
    } else {
        const MAX_LEVEL: LevelFilter = LevelFilter::TRACE;
    }
}

featureで特定の設定値を決める実装方法として参考になりました。

tracing::level_filters::LevelFilter::current()

static MAX_LEVEL: AtomicUsize = AtomicUsize::new(LevelFilter::OFF_USIZE);

https://github.com/tokio-rs/tracing/blob/tracing-subscriber-0.3.16/tracing-core/src/metadata.rs#L246

初期状態では、OFFなので全てのloggingがdisableになります。どの時点で値がセットされているかというとtracing_subscriber::fmt().init()の中で実行される、Dispatch::new()です

impl Dispatch {
    pub fn new<S>(subscriber: S) -> Self
        where
            S: Subscriber + Send + Sync + 'static,
    {
        let me = Dispatch {
            subscriber: Arc::new(subscriber),
        };
        callsite::register_dispatch(&me);
        me
    }
}

https://github.com/tokio-rs/tracing/blob/tracing-subscriber-0.3.16/tracing-core/src/dispatcher.rs#L458

callsite::register_dispatch()の中でDispatch(=Subscriber)が新規に登録された際のInterestの再計算が行われ、その際にLevelFilter::set_max()が実行されます。

impl Callsites {
    /// Rebuild `Interest`s for all callsites in the registry.
    ///
    /// This also re-computes the max level hint.
    fn rebuild_interest(&self, dispatchers: dispatchers::Rebuilder<'_>) {
        let mut max_level = LevelFilter::OFF;
        dispatchers.for_each(|dispatch| {
            // If the subscriber did not provide a max level hint, assume
            // that it may enable every level.
            let level_hint = dispatch.max_level_hint().unwrap_or(LevelFilter::TRACE);
            if level_hint > max_level {
                max_level = level_hint;
            }
        });

        self.for_each(|callsite| {
            rebuild_callsite_interest(callsite, &dispatchers);
        });
        LevelFilter::set_max(max_level);
    }
}

https://github.com/tokio-rs/tracing/blob/tracing-subscriber-0.3.16/tracing-core/src/callsite.rs#L425

CALLISTE.interest()

pub struct DefaultCallsite {
    interest: AtomicU8,
    registration: AtomicU8,
    meta: &'static Metadata<'static>,
    next: AtomicPtr<Self>,
}

impl DefaultCallsite {
    pub fn interest(&'static self) -> Interest {
        match self.interest.load(Ordering::Relaxed) {
            Self::INTEREST_NEVER => Interest::never(),
            Self::INTEREST_SOMETIMES => Interest::sometimes(),
            Self::INTEREST_ALWAYS => Interest::always(),
            _ => self.register(),
        }
    }
}

https://github.com/tokio-rs/tracing/blob/tracing-subscriber-0.3.16/tracing-core/src/callsite.rs#L351

DefaultCallsite::interest()Interestを返します。
InterestSubscriberと当該callsite(macro呼び出し)の関係で、処理の対象とするかどうかの判定です。上記のようにNEVER,SOMETIMES, ALWAYSがあります。SOMETIMESはruntime時に都度判定することを意味すると理解しております。結果をcacheしており、初回は、DefaultCallsite::register()が実行されます。

impl DefaultCallsite {
    pub fn register(&'static self) -> Interest {
        // Attempt to advance the registration state to `REGISTERING`...
        match self.registration.compare_exchange(
            Self::UNREGISTERED,
            Self::REGISTERING,
            Ordering::AcqRel,
            Ordering::Acquire,
        ) {
            Ok(_) => {
                // Okay, we advanced the state, try to register the callsite.
                rebuild_callsite_interest(self, &DISPATCHERS.rebuilder());
                CALLSITES.push_default(self);
                self.registration.store(Self::REGISTERED, Ordering::Release);
            }
            // Great, the callsite is already registered! Just load its
            // previous cached interest.
            Err(Self::REGISTERED) => {}
            // Someone else is registering...
            Err(_state) => {
                debug_assert_eq!(
                    _state,
                    Self::REGISTERING,
                    "weird callsite registration state"
                );
                // Just hit `enabled` this time.
                return Interest::sometimes();
            }
        }

        match self.interest.load(Ordering::Relaxed) {
            Self::INTEREST_NEVER => Interest::never(),
            Self::INTEREST_ALWAYS => Interest::always(),
            _ => Interest::sometimes(),
        }
    }
}

AtomicUsizeで状態を制御しつつ、初回はrebuild_callsite_interest()を実行します。

https://github.com/tokio-rs/tracing/blob/tracing-subscriber-0.3.16/tracing-core/src/callsite.rs#L312

fn rebuild_callsite_interest(
    callsite: &'static dyn Callsite,
    dispatchers: &dispatchers::Rebuilder<'_>,
) {
    let meta = callsite.metadata();

    let mut interest = None;
    dispatchers.for_each(|dispatch| {
        let this_interest = dispatch.register_callsite(meta);
        interest = match interest.take() {
            None => Some(this_interest),
            Some(that_interest) => Some(that_interest.and(this_interest)),
        }
    });

    let interest = interest.unwrap_or_else(Interest::never);
    callsite.set_interest(interest)
}

https://github.com/tokio-rs/tracing/blob/tracing-subscriber-0.3.16/tracing-core/src/callsite.rs#L494

dispatchers::Rebuilder<_>がわかりづらいですがここでは、これまでみてきたDispatch(FmtSubscriber)が実体です。なので、Layered::register_callsite()を見ていきます。

impl<L, S> Subscriber for Layered<L, S>
    where
        L: Layer<S>,
        S: Subscriber,
{
    fn register_callsite(&self, metadata: &'static Metadata<'static>) -> Interest {
        self.pick_interest(self.layer.register_callsite(metadata), || {
            self.inner.register_callsite(metadata)
        })
    }
}

https://github.com/tokio-rs/tracing/blob/tracing-subscriber-0.3.16/tracing-subscriber/src/layer/layered.rs#L94

Layered::pick_interest()は第一引数の結果をうけて第二引数のclosureを実行する処理です。
ここではinnerに委譲する前にself.layerを先に呼び出している点がポイントです。
一番外側のlayerはLevelFilterなので、LevelFilter::register_callsite()を見てみます。

impl<S: Subscriber> crate::Layer<S> for LevelFilter {
    fn register_callsite(&self, metadata: &'static Metadata<'static>) -> Interest {
        if self >= metadata.level() {
            Interest::always()
        } else {
            Interest::never()
        }
    }
}

https://github.com/tokio-rs/tracing/blob/tracing-subscriber-0.3.16/tracing-subscriber/src/filter/level.rs#L11

自身の値に応じてInterestを返しています。
これでようやく、FmtSubscriberの各layerの役割分担が理解できました。

tracing::__macro_support::__is_enabled()

これまでの判定でdisableと判定されなかった場合に最終的に実行されるruntimeの判定処理です。
逆にいうとlogging毎の判定処理をできるだけ避ける様に工夫されているといえます。
コードの詳細はここではみませんが、実装は今までの委譲と同じ流れです。

まとめ

ということで、info!()するとinfo_span!()の情報もあわせてloggingされるまでの流れをみてきました。
以下の点がわかり、macroのブラックボックス度が少し減ったのがうれしいです。

  • global変数にtracingのinstruction(info!(),info_span!())を処理するSubscriberの実装が保持されている。
  • tracing_subscriberLayerという概念で、Subscriberをcomposableにできる機構を提供してくれている
  • tracing_subscriber::fmt::Subscriber(FmtSubscriber)の実体はLayeredでnestされた、LevelFilter + fmt_layer::Layer + Registry
  • Spanのメタ情報とenterの状態はRegistryによって管理されている
    • span::Idの実装はshareded_slabのindex
    • RegistryThreadLocal<_>でenterしたspanのidを管理しているので、futureだとうまく動作しない

tracing_core,tracing_suscriberの役割がなんとなくわかったので、tracing workspaceにある他のcrateも理解できるように読んでみようと思います。