nginxでリクエスト開始時刻をログに出力する

nginxがログに出力する時刻はリクエスト処理が終わった時点の時刻のため、障害対応時など、いつ開始したリクエストから問題が出たのかを調査するために開始時刻もログにだしたいことがあります。

nginx単体ではリクエスト開始時刻にアクセスする方法が見つけられなかったのですが lua-nginx-module を使うと以下のようにできました。

set_by_lua_block $start_time {
    return os.date("%Y-%m-%dT%T%z", ngx.req.start_time());
}

ngx.req.start_time() でリクエスト開始時刻のunix timeが取れるので、それを os.date() でフォーマットして変数に設定し、ログでは $start_time 変数を出力する形です。

log_format ltsv 'time:$time_iso8601\t'
                'start_time:$start_time\t'
...

出力結果

time:2016-03-29T12:33:15+09:00	start_time:2016-03-29T12:33:14+0900

timezone部分が $time_iso8601 と異なり : が入らないのが若干気持ち悪いですが…