Axumでのアクセスログ出力の現状について調べてみた

Axumでのアクセスログ出力の現状について調べてみたのでメモです。 個人的には特にヘッダとボディ（新しい用語だとフィールドとコンテント）を合わせた転送量をログに書きたいというニーズがあります。

結論を先に書くと現状は非対応で今のところ予定もないそうです。

axum でのログ出力の実現方法について調査

tokio-rs/axum: Ergonomic and modular web framework built with Tokio, Tower, and Hyper の Getting Help で紹介されている Discord での axumのメインの開発者の davidpdrsn さんの発言 によると

とのことでした。

axum の examples/tracing-aka-logging/src/main.rs を試してみたのですが、 on_eos は End of Stream ということでこれでレスポンスボディを送り切った最後に呼ばれるのかと思いきや、これは Transfer-Encoding: chunked でかつ最後に trailer のフィールドを送らないと呼ばれなさそうでした（ここはしっかりは確認してないです）。

Question - getting last byte latency metric with trace layer · Issue #119 · tower-rs/tower-http のやり取りを見ても hyper の polling の現状の実装だとにレスポンスの最後で呼ばれるメソッドというのは今後も出来なさそうでした。 davidpdrsn さんの発言 に classifier はレスポンスボディが最後まで送信した後に drop されるというのを使った回避策的なコードが紹介されていました。

でもこの技を使っても axum/main.rs at main · tokio-rs/axum の

            TraceLayer::new_for_http()
                .on_request(|_request: &Request<_>, _span: &Span| {
                    // ...
                })
                .on_response(|_response: &Response, _latency: Duration, _span: &Span| {
                    // ...
                })
                .on_body_chunk(|_chunk: &Bytes, _latency: Duration, _span: &Span| {
                    // ..
                })
                .on_eos(
                    |_trailers: Option<&HeaderMap>, _stream_duration: Duration, _span: &Span| {
                        // ...
                    },
                )
                .on_failure(
                    |_error: ServerErrorsFailureClass, _latency: Duration, _span: &Span| {
                        // ...
                    },
                ),

on_body_chunk でボディのチャンクサイズは取れるので合算していくとボディサイズは出せるとしてヘッダサイズは on_response の Response の HeaderMap からエンコード後のサイズを再度計算するのは出来れば避けたいなという印象です。 HTTP のバージョンによってエンコード方法も違いますし。

とりあえず現状では Question - getting last byte latency metric with trace layer · Issue #119 · tower-rs/tower-http の lkts さんのコメント のように Stream をラップして対応するほうが良さそうな気がします。と言いつつ私は具体的な方法が今のところ分かってないです。

hyper での転送量取得について調査

hyper の tracing 対応について Meta: Tracing · Issue #2678 · hyperium/hyper というトラッキング・イシューがありました。

そこからリンクされている

横道ですが、 2022年2月に hyper 1.0 timeline - seanmonstar が出ていたのに先程気づきました。2022年に 1.0 をリリース予定らしいです。

ちなみに actix-web のアクセスログのレスポンスサイズについても調べてみた

Middleware のドキュメントの Logging の Format には

%b Size of response in bytes, including HTTP headers

と書いてありました。

ですが src/middleware/logger.rs を見るとボディのみのサイズになっているようです。

examples/basic.rs を試してみても

$ curl -v 127.0.0.1:8080
*   Trying 127.0.0.1:8080...
* Connected to 127.0.0.1 (127.0.0.1) port 8080 (#0)
> GET / HTTP/1.1
> Host: 127.0.0.1:8080
> User-Agent: curl/7.81.0
> Accept: */*
>
* Mark bundle as not supporting multiuse
< HTTP/1.1 200 OK
< content-length: 14
< content-type: text/plain; charset=utf-8
< x-version: 0.2
< date: Sun, 08 May 2022 14:11:55 GMT
<
Hello world!

に対してログは

[2022-05-08T14:11:55Z INFO  http_log] 127.0.0.1 "GET / HTTP/1.1" 200 14 "-" "curl/7.81.0" 0.000802

となっていてレスポンスサイズは 14 バイトで、やはりボディのみのサイズとなっていました。

$ printf 'Hello world!\r\n' | wc -c
14