Chrome 便利ツール NetLog を利用した問題判別
最近社内メンバーが特定のサイトを開くことができないと相談を受けました。詳細をヒアリングしてみると、
当時その事象が発生しているのはその人だけ
Chrome のみで発生、Safari では再現せず
ブラウザ・OS 再起動やシークレットウィンドウ(拡張機能は無効化)で開いても再現
Chrome 開発者ビューでネットワークタブを開くと、タイムアウトが発生している
ネットワークのスピードテストでは上り下りとも 50Mbps 程度
といったような状況でした。正直この時点では何が原因かわからず、「クライアント環境に依存するものか?」と推測することしかできませんでした。パケットキャプチャをしたくなりましたが、弊社は完全リモートワークで、かつ、今回相談を受けた方はエンジニアの方ではないため、画面共有をしてもらいながら tcpdump や Wireshark をインストール・操作してもらうのは少し面倒に感じてしまいました。なにか良いツールはないものかと調べてみると、Chromium には NetLog というツールがあることがわかりました。tcpdump を置き換えるものではないが、開発者ビューのネットワークタブでは見ることができないネットワークレベルのログを確認できるようです。NetLog は Chrome や Edge でも利用することができ、NetLog の生成手順も追加ソフトウェアのインストールは不要で、chrome://net-export/ にアクセスすれば NetLog ファイルを出力できます。とりあえず物は試しに NetLog の取得を依頼してみました。
出力された NetLog は JSON 形式で、https://netlog-viewer.appspot.com を利用すると可視化することができます。
自分でも同じサイトを開いて NetLog を出力して、正常にサイトが開けるときの NetLog と開けないときの NetLog を比較してみました。
NetLog を比較してみると正常時と異常時のログで挙動が異なる箇所を見つけることができました。
画像は netlog-viewer の events ページから確認できるもので、Chrome の Network stack が排出したイベントログが確認できます。調べて見たところ、SSL_CONNECT_JOB では、コネクションを確立し、SSL ハンドシェイクを実施する箇所だということがわかりました。また、画像左側にある "t" は NetLog をキャプチャしてからの経過時間(ミリ秒)を、"st" は SSL_CONNECT_JOB が開始してからの経過時間(ミリ秒)を表します。正常時では最後の st の値が 100 であるのに対して、異常時では st の値が 9304 と約 9 秒ほどの差が発生していることがわかります。詳細ヒアリング時に「Chrome 開発者ビューでネットワークタブを開くと、タイムアウトが発生している」という状態の原因がここにありそうです。なぜこれほどの差が発生しているかを見極めるために、異常時のログを改めて見てみると "TRANSPORT_CONNECT_JOB_IPV6_FALLBACK" というイベントが発生していることがわかりました。このイベントは Chromium のソースコードのコメントに "This event is logged when the TransportConnectJob IPv6 fallback timer expires and the IPv4 addresses are attempted." とある通り、IPv6 接続時にタイムアウトが発生して IPv4 にフォールバックした際に発生しそうです。イベントログにも IPv6 アドレスで 3 回接続したあとに、IPv4 アドレスが表示されていることからも、IPv4 へのフォールバックが発生していることが確認できます。これらのことから、サイト接続時に IPv6 で接続しようとしているが IPv6 では接続できず、IPv4 へのフォールバックを待機するために接続がタイムアウトしてページが開けないのではないかと推測しました。
今回のメンバーには OS 上で IPv6 を利用しないように設定することで、無事サイトが開けるようになりました。
このように Chromium に搭載されている NetLog を利用することで、追加のソフトウェアを利用せずにネットワークレベルのログを取得して問題判別を実施することができました。NetLog には Chrome のイベントログの他にもProxy・拡張機能の有無や、DNS 設定とキャプチャ時のクエリ結果なども取得できるのでみなさんも困ったときは試してみてください。