インターネット接続のトラブル

先日、自宅ネットワークのインターネット接続が断続的に切断・再接続を繰り返す問題があり、無線LAN ルーターの設定をいろいろ試行錯誤してました。その辺りの経緯は次に書いています。
無線LANルーターAtermのリンクダウン頻発 - torutkの日記で

自宅ネットワークは、CATV回線でインターネット接続しており、CATVケーブルモデムを使用しています。

この切断が、無線LAN ルーターの問題か、ケーブルモデムの問題かを切り分けるため、ケーブルモデムにPCを直結し、インターネット上のサーバー*1へpingを定期的に飛ばして様子をみてみました。

また、DHCPクライアントのイベントログを有効にして、切断が発生するときのログを見れるようにしました。

本日昼過ぎに、ケーブルモデムにPCを直結し、ケーブルモデムの電源を抜き挿ししてリセット、PC側も再起動して、pingをインターネットに飛ばして8時間ほど様子をみました。

結果

ping結果

8時間ほど実行しました。
インターネットとの接続が断絶するときのping結果は次のようになっていました。

2017/03/12 12:54:35 xxx.xxx.xxx.xxxからの応答: バイト数 =32 時間 =26ms TTL=54
2017/03/12 12:54:36 xxx.xxx.xxx.xxxからの応答: バイト数 =32 時間 =26ms TTL=54
  :
2017/03/12 15:58:07 xxx.xxx.xxx.xxxからの応答: バイト数 =32 時間 =27ms TTL=54
2017/03/12 15:58:12 要求がタイムアウトしました。
2017/03/12 15:58:13 一般エラー。
2017/03/12 15:58:14 一般エラー。
  :
2017/03/12 15:58:20 一般エラー。
2017/03/12 15:58:25 要求がタイムアウトしました。
2017/03/12 15:58:30 要求がタイムアウトしました。
2017/03/12 15:58:35 要求がタイムアウトしました。
2017/03/12 15:58:38 一般エラー。
2017/03/12 15:58:39 ping: 転送に失敗しました。一般エラーです。
2017/03/12 15:58:40 ping: 転送に失敗しました。一般エラーです。
  :
2017/03/12 15:59:35 ping: 転送に失敗しました。一般エラーです。
2017/03/12 15:59:36 xxx.xxx.xxx.xxxからの応答: バイト数 =32 時間 =35ms TTL=54
2017/03/12 15:59:41 要求がタイムアウトしました。
2017/03/12 15:59:42 xxx.xxx.xxx.xxxからの応答: バイト数 =32 時間 =40ms TTL=54
2017/03/12 15:59:43 xxx.xxx.xxx.xxxからの応答: バイト数 =32 時間 =27ms TTL=54
  :

このときのDHCP Clientのイベントログ（Microsoft-Windows-DHCP Client Events/Admin）には、

2017/03/12 15:58:37 エラーイベント1002

「ネットワークアドレスが 0x... のネットワークカードに対するIPアドレス xxx.xxx.xxx.xxx のリースが、DHCPサーバー192.168.100.1 から拒否されました。DHCPサーバーは DHCPNACKメッセージを送信しました。」

2017/03/12 15:59:29 警告イベント1003

「ネットワークアドレスが 0x... のネットワークカードに対して、ネットワーク（DHCPサーバー）から割り当てられたアドレスを更新することができませんでした。次のエラーが発生しました：0x79。ネットワークアドレス（DHCP）サーバーから引き続き、アドレスの取得を試みます。」

このときのDHCP Clientのイベントログ（Microsoft-Windows-DHCP Client Events/Operational）には、

2017/03/12 15:58:09 情報イベント50002

「メディア切断の通知をインターフェイス ID 14 で受信しました」

2017/03/12 15:58:31 情報イベント50001

「メディア接続の通知をインターフェイス ID 14 で受信しました」

2017/03/12 15:58:31 情報イベント50004

「インターフェイス ID が 14 のアダプターでDHCPが有効化されました」
　　：

2017/03/12 15:58:39 情報イベント50010

「アダプター 14 で OFFER メッセージが受け入れられました。提供アドレス: 192.168.100.20、サーバーアドレス: 192.168.100.1」
　　：

2017/03/12 15:59:29 エラーイベント50039

「アダプター 14 でソケットを開こうとしてエラーが発生しました。エラーコード:0x2741」

2017/03/12 15:59:29 エラーイベント50053

「メッセージを送信するときに、ネットワークでエラーが発生しました。エラーコード:0x2741」

2017/03/12 15:59:29 情報イベント50029

「アダプター 14 へのアドレス 192.168.100.20 の組み込みが解除されました。ステータスコード:0x57」

2017/03/12 15:59:29 エラーイベント50030

「アダプター 14 で組み込みエラーが発生しました。ステータスコード: 0x57」

2017/03/12 15:59:35 情報イベント50007

「インターフェイス ID が14 のアダプターで、DISCOVER-OFFER-REQUEST-ACK メッセージが開始されました」

2017/03/12 15:59:35 情報イベント50009

「アダプター 14 から DISCOVER メッセージが送信されました。ステータスコード:0x0」

2017/03/12 15:59:35 情報イベント50010

「アダプター 14 で OFFER メッセージが受け入れられました。提供アドレス: xxx.xxx.xxx.xxx、サーバーアドレス: xxx.xxx.xxx.xxx」

インターネット接続の断絶発生時刻

2017/03/12 12:54〜20:55までの間、次の時刻で断絶が発生していました。

15:58
16:11
16:17
16:30
16:34
17:18
18:37
20:23

サポートへの電話問い合わせ

内容を伝えましたが、障害もなく、類似問題の情報も上がっていませんとのこと。後日調査に来るということで予定日を調整して終わりました。

ケーブルモデムのLED

20:23の断絶発生時、ちょうどWeb検索中でエラーが発生したのでケーブルモデムのLEDを確認したところ、

POWER 点灯
DS 消灯
US 消灯
Online 消灯
Link 消灯

となっていました。数秒すると、DSが点滅→点灯となり、続いてUSが点滅→点灯、Onlineが点滅→点灯、Linkが点滅となりました。

調査方法のメモ

Windowsでpingの結果を時刻付きでファイルに保存する

PowerShellを使う方法がありました。

> ping www.torutk.com -t | ?{$_ -ne ""} | %{(Get-Date).ToString() + " $_"} | Out-File ping_result.txt

カレントディレクトリ上にping_result.txtという名前でping結果を保存します。

WindowsでDHCP Clientのイベントログを有効にする

DHCP Clientの動作ログ取得について

イベントビューアで、[アプリケーションとサービスログ] > [Microsoft] > [Windows] > [Dhcp-Client] の下に次の2つの項目があります。

Microsoft-Windows-DHCP Client Events/Admin
Microsoft-Windows-DHCP Client Events/Operational

これらを有効にして（右クリック > [ログの有効化]）、イベントを記録します。

Arris製ケーブルモデム

「arris 192.168.100」でググってみると、いろいろ情報がでてきました。なんと、192.168.100.1でケーブルモデムの管理Webページにアクセスでき、このモデムは、アップリンクが途絶えたとき、DHCPサーバーとして振る舞うようです。

(後日追記）

ケーブルモデムの交換となりました。
交換後、様子見中です。

*1:ping先は、さくらVPSで借りている自前のサーバーです。

torutkのブログ

ソフトウェア・エンジニアのブログ