Perl の話です。
Perl で Web アプリケーションを書くならほぼ確実にお世話になるであろう Plack が提供するモジュールのバグを見つけて修正が取り込まれました。このバグ修正で非互換の変更が入ったので、その話を書いています。
依存モジュール(Apache::LogFormat::Compiler)と Plack の繋ぎ込み部分で正しくパラメータが渡されていなかったこと、また Apache::LogFormat::Compiler 自身にもバグがあったことから、 Plack::Middleware::AcceessLog::Timed のログフォーマットのうち、%Dと%Tが意図したものと異なる値が保存されていました。
この不具合を修正する pull-request を出して、それが取り込まれたことでドキュメントなどが意図した挙動が実現するようになりました。
Plack 1.0040 は他にも内部構造の変更があったりして、 2016/04/02 現在 TRIAL としてリリースされています。
metacpan.org
経緯やポエムに興味の無い人向け
あなたが Plack::Middleware::AccessLog::Timed を使っているなら
何故変わったのか
だいたい issue にボロボロの英語で書いたのでさっとだけ書きます。
Plack::Middleware::AccessLog::Timed で処理所要時間を記録するフォーマットは、依存モジュールの Apache::LogFormat::Compiler によって処理されます。このうち特にリクエストにかかった時間に関しては以下のように定義されています。
%T custom field for handling times in subclasses %D custom field for handling sub-second times in subclassesApache::LogFormat::Compiler - Compile a log format string to perl-code - metacpan.org
これだけ見るとなんなのか分かりづらいのだけれど、これらは Apache のログフォーマットに従う(a subset of Apache's LogFormat templates)ので Apache のログフォーマットを追いかけることにします。すると、
%T は「The time taken to serve the request, in seconds.」%Dは「The time taken to serve the request, in microseconds.」と定められている*1ので、それぞれ秒とマイクロ秒単位と秒単位の値が得られてほしいというように見えます。
なので、
- あるリクエストの処理に2.5秒かかったなら:
%Tは 2- Apache の mod_log_config.cやapr_time_sec の定義を読むと整数部分だけが得られることがわかる
%Dは 2500000 (2_500_000)
になってほしい気がするのですが、 Plack 1.0039 以前 + Apache::LogFormat::Compiler 0.32 以前の組み合わせの場合、実際に記録されていたのは
- あるリクエストの処理に2秒かかったとき:
%Tは 2500000 (2_500_000)%Dは 2.5
なので、ドキュメントと異なる挙動になっていました。テストコードを書いたりもしています :
github.com
直接的には Apache::LogFormat::Compiler の挙動がドキュメントと異なったことが原因で、さらに Plack::Middleware::AccessLog::Timed の処理も一部修正する必要があった、というのが原因でした。これら2つのモジュールに pull request を投げてマージされ、先日この変更を含んだ Plack の新バージョンが TRIAL としてリリースされました。 Plack コントリビューターデビューです。
あなたのコードで対処が必要なのかどうか
ログに %D や %T を出力していた場合、特にその値を集計している場合は Plack のバージョンアップに合わせてコードを修正する必要がありそうです。
[INCOMPATIBLE CHANGES]
- Fixes a mistake in the value of %D and %T in Accesslog::Timed middleware.
This is due to a bug in Apache::LogFormat::Compiler that sets a wrong value
for these fields. This bug has been fixed and now it emits what the documentation
has always said, in the same way as how Apache's log format works.
However, this is a BREAKING CHANGE if you are using '%D' or '%T' in your log
formats, and you'll likely need to swap them if you need the same values as
previously. Read https://github.com/plack/Plack/issues/549 for more details.
(astj) #549, #551
Changes - metacpan.org
%Tでマイクロ秒単位の処理時間を記録していた場合は、フィールド名を%Dに修正することで今までと同じ値が得られます。
いっぽう、%Dで小数点以下を含む秒単位の処理時間を記録していた場合は、今回の修正後の%Tは小数点以下を切り捨てた秒精度の値を返す為、情報量が減ってしまうことになります。そのため、この場合は(%T => %Dのような)自然な変更を諦め、単位か精度のどちらかを犠牲にする必要があります。
Web アプリケーションの処理時間としては秒以上の精度が求められることも多いかと思いますが、その場合はマイクロ秒単位の値を返すようになった%Dをログフォーマットとしては引き続き用いて、単位の変更を受け入れつつ精度を保つ、という判断が必要になりそうです。その上で、ログの集計などで今までと一貫した秒単位の値で集計する必要があるのなら fluentd などの集計レイヤで秒単位に変換することでフォーマットの変更を吸収することも可能ではないかと思います。
経緯と感想
仕事でアプリケーションのログ中の処理時間を見る必要があった時に、「この値が意味するのはなんなのだろうか」と調べていったところ上記のバグに行き着いたという感じでした。 また、実際は上記の2モジュールの他に、同僚である 
id:tarao さんによる Test::MockTime::HiRes にも機能追加や修正の p-r を出してリリースしてもらうなどもしていたりしました。 *2
また、今回の秒単位処理時間(旧: %D / 新: %T)の精度が落ちてしまったことについては最近まで見落としていたのですが、今から振り返ると本当にこれでいいのか、ということも悩んでいたりします。 Apache のログフォーマットに従うという方針からすれば正しい変更だと思うけれど、 Apache を知らない人間からすると変更前のように「秒単位だがそれ以上の精度」という方がよいのではないか、という感じもあります。そもそも論として、そのことを見落としてよいしょーで p-r 出してしまったのはふつうに手落ちだったという気もしています。
とはいえ、よく使われてる/使っている OSS プロダクトのコントリビューターの末席に自分の名前があって嬉しいのも確かなので、今後も何か機会があればきちんとプロダクトにフィードバックしていきたいなと思っています。
