はじめに
SREチームの磯村です。
コミューンではクラウド基盤としてGoogle Cloudを利用しています。 ユーザーのブラウザからのリクエストはCloud Load Balancing経由してCloud Run上のプログラムに渡されます。 このため、一つのリクエストに対してCloud Load BalancingとCloud Runのそれぞれのリクエストログが出力されます。 この記事ではCloud Load Balancingのリクエストログのtimestampが 実際にリクエストを受け取った時刻よりも前の時刻になってしまう事例について紹介します。
Cloud Load BalancingのtimestampとCloud Runのtimestampが5分以上ずれている事例
Cloud Load Balancingのリクエストログ、Cloud Runのリクエストログにはtraceという項目があります。 これらの値はリクエスト毎に異なる値が自動的に付与されます。 この値が同じログであれば同じリクエストに対するログであるということがわかります。
これをふまえて、あるリクエストに対するCloud Load BalancingとCloud Runのそれぞれのログをご覧ください。
それぞれのtraceのフィールドが同じ値になっているため、同じリクエストに対するログであることが確認できます。 このリクエストのtimestampはCloud Load Balancingは13時43分52秒なのに対してCloud Runの方は13時49分19秒となっています。 同じリクエストのログであるにも関わらずタイムスタンプが5分以上ずれています。 Cloud Load BalancingからCloud Runへのリクエストが受け渡される時間の分だけ差分があるはずですが、 5分のずれは不自然です。 このリクエストをGoogle Cloudが受け取ったのは実際には一体どちらの時刻なのでしょうか。 このことをGoogle Cloudのサポートを行っている会社に問い合わせました。
Cloud Load Balancingのtimestampがずれている
サポートの方に回答を頂いた結果、Cloud Load Balancingのtimestampは実際のリクエストの時刻よりも 前の時刻になる場合があることがわかりました。
アプリケーション側で出力しているログのtimestampはCloud Runのリクエストのtimestampと近い時刻だったため、 不正確なのはCloud Load Balancingのtimestampの方であるという回答は納得がいくものでした。
リクエストの時刻が前にずれるのはなぜなのか
リクエストのtimestampはリクエストが発生したあとに作成されるはずです。 このため処理の遅れなどにより実際の時刻より後の時刻が記録されることはありそうな気がするのですが、 実際の時刻より前にずれるのは非常に不自然に感じます。 実際の時刻より前にずれたtimestampはどのような由来で生成されたのでしょうか？
サポートに問い合わせたところ回答を頂くことはできて、内容は納得が行くものでした。 内容については私が公開するべき情報ではないためここでは書きません。
おわりに
今回サポートに問い合わせたのは、バグの調査でログを詳細に確認していた際にこのようにCloud Load Balancingの リクエストログのtimestampがCloud Runのリクエストログのtimestampと数分ずれた時刻となっていて酷く混乱させられたためでした。 Cloud Load Balancingのtimestampはずれている場合があることがわかったので、 細かな時刻が問題になるような場合には気をつけて利用しようと思います。
なお、どのくらいの割合で時刻のずれがおきているのか集計したところ この一ヶ月で全体のリクエストログの中で30秒以上timestampがずれているログは2.8%、最大のずれは609秒でした。 このように時刻がずれているログはそれなりに見かけることがありそうな割合となっていました。 これだけ起きているのであれば、今回判明した事実を覚えておく価値がありそうです。
最後になりますが、コミューンの開発に少しでも興味をお持ちいただけた方、今回の記事についてやコミューンにおけるクラウドインフラとの向き合い方などをぜひカジュアルにお話しませんか？ 下記フォームよりカジュアル面談のお申し込みをお待ちしております！ https://docs.google.com/forms/d/e/1FAIpQLScwJuVhCX88b1IB_hcDdqTmd61skiZwuQJvfMyFHgIbOQNdUA/viewform
