VPCフローログに含まれるタイムスタンプを確認する

こんにちは、なおにしです。

VPCフローログで出力されるレコードの出力タイミングや含まれているタイムスタンプなど、時刻に関する部分の挙動を確認してみました。

はじめに

ネットワーク疎通の確認やトラブルシューティングを行う際は、Ping応答を調査することが多いかと思います。
もしPing応答が無い場合やどのようなルーティングで応答があったのかを調査する場合、送信したICMPパケットを追跡するために実行時刻と送信元/送信先IPアドレスなどを参照しながらログを眺めていく状況になることもあるかもしれません。

tcpdumpなどで確認する場合はほぼリアルタイム(1秒以下≒パケットを受信したタイミング)でログが出力されるため、目視確認もしやすいかと思います。一方でVPCフローログはリアルタイムで出力されるわけではなく、出力されるレコードもtcpdumpのように1つのパケットと対ではなく一定時間で集約された内容がログに出力されます。

そこで、送信されたICMPパケットに対してVPCフローログがどのように出力されるのか挙動を細かく見てみたいと思います。

やってみた

前提

以下の構成で実際にVPCフローログとしてどのように出力されるのか確認します。

作成したVPCフローログの最大集約間隔は「1分間」です。

以下のとおりコマンドを実行してICMPパケットを1回だけ送信しました。（1714545000で送信したかった...）

対向のEC2インスタンスで実行していたtcpdumpコマンドでは以下のとおり出力されました。出力するパケット情報をICMPのみで絞っており、送受信の方向は制限していないため両方のパケットについて表示されています。

VPCフローログの出力結果

冒頭に記載のケースを想定して、今回はVPCフローログをCloudWatch Logs Insights で分析するという前提で進めます。

CloudWatch Logs Insights でも上記のtcpdumpコマンドのように送受信の方向やインターフェースを指定せずにクエリを実行した結果、以下のとおり4つのログが出力されました。

VPCフローログでもtcpdumpと同様に各インターフェースごとに送受信それぞれの方向で個別にログが出力されているため、1つのICMPパケット送信に対して4つのログが出力されていることが分かります。

続いて、1つのレコードを展開して中身を確認します。

枠で囲った箇所がタイムスタンプで、同色の部分は同じフィールドを示しています。

先頭に@マークがついているフィールドはCloudWatch Logs Insightsが自動的に生成したシステムフィールドです。

＠マークがついていないフィールドはVPCフローログのレコードで使用可能なフィールドに含まれます。

なお、@timestampと@messageはCloudWatch Logsのログイベントとして共通で含まれるフィールドとなります。

上記のドキュメントから抜粋したそれぞれの時刻フィールドの内容は以下のとおりです。

フィールド名	説明
@timestamp	InputLogEvent が発生した時刻
@ingestionTime	CloudWatch Logs がログイベントを受信した時刻
start	集約間隔内にフローの最初のパケットが受信された時刻（パケットがネットワークインターフェイス上で送信または受信されてから最大 60 秒かかる場合がある）
end	集約間隔内にフローの最後のパケットが受信された時刻 （パケットがネットワークインターフェイス上で送信または受信されてから最大 60 秒かかる場合がある）

startおよびendの説明に記載の集約間隔については以下の記事をご参照ください。

ここまでを踏まえ、改めて今回実行したPing(1714545001 → 2024/05/01 15:30:01 JSTに実行)に対して出力されたVPCフローログを眺めてみます。

時刻表記が統一されていないため分かりづらいですが、@timestampについてはPingを実行した時刻から25秒前後遅れて記録されていることが分かります。start/endや@ingestionTimeのタイミングも把握するために図示してみます。

送信元ENIと送信先ENIのそれぞれ2つのログに含まれるタイムスタンプは各フィールドごとに同一だったため、ENIごとに時系列で表すと上記のとおりになりました。

@timestampとstartは同一時刻を指していました。startについてはドキュメントに記載のとおり「パケットがネットワークインターフェイス上で送信または受信されてから最大 60 秒かかる場合がある」という挙動になっています。endについてはパケット通過時刻からは60秒以上経過していますが、startを基準時刻としているのかもしれません。

CloudWatch Logs がログイベントを受信した時刻である@ingestionTimeがそれぞれのENIに含まれるタイムスタンプで最も遅い時刻になっているのは意味合いとしても想定どおりの挙動ですが、CloudWatch Logs Insights のクエリ実行結果として画面に表示されるまでは体感でさらに1〜2分ほどかかったように思います。 実際、ドキュメントには以下の記載があります。

集約間隔内にデータが取得された後、データの処理および CloudWatch Logs または Amazon S3 へのパブリッシュにさらに時間がかかります。フローログサービスは、通常、約 5 分で CloudWatch Logs に、約 10 分で Amazon S3 にログを配信します。ただし、ログの配信はベストエフォートベースであり、通常の配信時間を超えてログが遅れる可能性があります。

集約間隔

まとめ

VPCフローログで出力される内容を1つのICMPパケット単位で確認してみました。同様の検証を複数回実施したわけではないので、状況によってタイムスタンプに記録される時刻にはブレがあるかと思いますが、大まかなタイミングについては把握できました。　　 VPCフローログを使って特定のパケットを調査するような状況になった際、それぞれのタイムスタンプをどのように捉えれば良いか、CloudWatch Logs Insights のクエリでどのように条件を絞れば良いかといったことの参考になれば幸いです。