nginxの$time_localで出力される日時のタイミングはいつなのか

こんにちは。エキサイト株式会社の三浦です。

今回は、nginxのアクセスログで出力される日時が、どのタイミングのものなのかを説明します。

疑問

nginxは、 $time_local というフォーマットを使うことで、アクセスの日時をアクセスログに出力してくれます。ただ、「アクセスの日時」とは具体的にいつなのでしょうか？

「アクセスを受け取った日時」でしょうか？それとも、「アクセスに対してレスポンスを返した日時」でしょうか？

というわけで今回は、それを検証しました。

今回は、 nginx + Golang を使って検証します。 Golang には gin というHTTP web フレームワークを使っています。

コードの抜粋は以下です。

e := gin.Default()

e.GET("/ping", func(c *gin.Context) {
    c.String(http.StatusOK, "pong")
})

やっていることは単純で、 http://localhost/ping というアクセスが来たら、ステータスコード200で pong というレスポンスを返すというものです。これを、nginx経由でアクセスするようにします。

まずはそのまま、上記のコードを使用してみます。

e := gin.Default()

e.GET("/ping", func(c *gin.Context) {
    c.String(http.StatusOK, "pong")
})

11:59:00 にアクセスしてみました。

世界標準時になっているので -9時間 ですが、アクセス日時と全く同じ日時が記録されているのがわかります。

続いて、以下のように一旦sleepを入れて、レスポンスにかかる時間を延ばして検証してみます。

e := gin.Default()

e.GET("/ping", func(c *gin.Context) {
    // 5秒間sleepする
    time.Sleep(5 * time.Second)

    c.String(http.StatusOK, "pong")
})

13:14:50 にアクセスしてみました。

世界標準時になっているので -9時間 ですが、アクセス日時から5秒後の時間が記録されているのがわかります。

検証の結果、 $time_local は「アクセスを受け取った日時」ではなく「アクセスに対してレスポンスを返した日時」であることがわかりました。

特に、時間がかかる系の処理のアクセスログを見るときは、このあたりが正確にわかっていないとちゃんとログを読み解けない可能性があります。気をつけましょう。