読者です 読者をやめる 読者になる 読者になる

平常運転

アニソンが好き

過去記事とかは記事一覧で見れます

Plack 1.0040 で Plack::Middleware::AcceessLog::Timed のログフォーマットが一部変わることになる

perl engineer

Perl の話です。
Perl で Web アプリケーションを書くならほぼ確実にお世話になるであろう Plack が提供するモジュールのバグを見つけて修正が取り込まれました。このバグ修正で非互換の変更が入ったので、その話を書いています。

github.com

依存モジュール(Apache::LogFormat::Compiler)と Plack の繋ぎ込み部分で正しくパラメータが渡されていなかったこと、また Apache::LogFormat::Compiler 自身にもバグがあったことから、 Plack::Middleware::AcceessLog::Timed のログフォーマットのうち、%D%Tが意図したものと異なる値が保存されていました。
この不具合を修正する pull-request を出して、それが取り込まれたことでドキュメントなどが意図した挙動が実現するようになりました。

  • Apache::LogFormat::Compiler の 0.33 から、%Tのフォーマット形式が変わりました
  • Plack の 1.0040 から、%T%Dのフォーマット形式が変わります

Plack 1.0040 は他にも内部構造の変更があったりして、 2016/04/02 現在 TRIAL としてリリースされています。
metacpan.org


経緯やポエムに興味の無い人向け

あなたが Plack::Middleware::AccessLog::Timed を使っているなら

  • リクエスト処理にかかったマイクロ秒を %T で記録しているなら、 Plack 1.0040 に追従する際に %D に書き換えてください
  • リクエスト処理にかかった秒を %D で記録しているなら、 Plack 1.0040 に追従する際に
    • %T に書き換えるとオーダーは維持されますが、小数点以下が切り捨てられるので情報量が減ります
    • %D のままにしておくと情報量は維持されますが、バージョンアップを境に記録される情報が秒単位からマイクロ秒単位に変わります
      • fluentd などでログを収集して解析しているのであれば、記録するフィールド名を変えるなどする必要がありそうです

何故変わったのか

だいたい 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 subclasses
Apache::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ので、それぞれ秒とマイクロ秒単位と秒単位の値が得られてほしいというように見えます。

なので、

になってほしい気がするのですが、 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 コントリビューターデビューです。

metacpan.org

あなたのコードで対処が必要なのかどうか

ログに %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 プロダクトのコントリビューターの末席に自分の名前があって嬉しいのも確かなので、今後も何か機会があればきちんとプロダクトにフィードバックしていきたいなと思っています。

*1: mod_log_config - Apache HTTP Server

*2:Plackperl 5.8 系もサポートしているので、Plack で使う為には defined-or を潰さないといけない、というのもありました……