2022年3月のブログ記事一覧-rabbit51

ひかり電話 HGW PR-600MI のハングアップと勝手に再起動する不具合について

2022-03-20 16:00:00 | ひかり電話

「ひかり電話 HGW PR-S300SEからPR-600MIに変更された」（2021/2/25）後、firmwareが「01.00.0007」(2021/5/13)に更新され、「ひかり電話 HGW PR-600MIのfirmware更新とIPv6パケットフィルターの不具合」が発生するようになった（「01.00.0005」で発生するかは確認出来なかった。PR-S300SEでは、経験した事が無かった）。

更新後の障害
・「セキュリティログ（IPv6）」が突然「0 entries」になる
・ログ記録が止まる
・数時間後にIPv6通信ができなくなる（ルーティングされなくなる）
・その他の機能は、動作している（不具合を認識できない）

である。

この不具合が発生すると「再起動」するしか方法がない。
「再起動」を行うと「情報」「DHCPv6サーバ払い出し状況」の順序が変化するため「ひかり電話 HGW PR-600MI のDHCPv6-PDサーバーが割当てるPrefixを制御する」で対応した。
「ひかり電話 HGW PR-600MI のDHCPv6-PDサーバーが割り当てるPrefixの変化を検出する」
「ひかり電話 HGW PR-600MI DHCPv6-PDサーバーが再起動時に割り当てるPrefix」
「ひかり電話 HGW PR-600MI DHCPv6-PDのReconfigureを捉えPrefix再取得を実行する」
などで「再起動」後のシステム復帰状態が確実になった。
しかし、発生が稀で、ログ停止からIPv6通信が出来なくなるまで時間が掛かり不具合の要因を探るのが難しい。
2022年になって「突然の再起動」が２回（2022/2/26, 2022/3/1）、「セキュリティログentries 0」が１回（2022/3/16）発生した。そこで、「セキュリティログentries 0」の検出と「再起動」の自動実行方法を検討してみた。

（１）dhclientのreleaseして終了不具合対応
「ひかり電話 HGW PR-600MI DHCPv6-PDサーバーが再起動時に割り当てるPrefix」で二重起動対策を行っていたが、dhclientが「-r」オプション「releaseして終了」で終了しない場合があるため対策を強化した（Line#33-#40）。他装置で取得済prefixを再委譲させるためにleasesファイルをクリアしてから実行する事とdhclient終了時に未終了のdhclientをSIGKILLで終了する事とした。

RebindAllISC Line#33-#40
for CL in $CID; do
    if [ "$CL" = "$ID3" ]; then
        if [ -e "/run/dhclient6.$IF.pid" ]; then kill -SIGKILL `cat "/run/dhclient6.$IF.pid"`; fi
	if [ -e "/var/lib/dhcp/dhclient6.$IF.leases" ]; then rm "/var/lib/dhcp/dhclient6.$IF.leases"; fi
        $DHCPV6CL -I -N -pf "/run/dhclient6.$IF.pid" -lf "/var/lib/dhcp/dhclient6.$IF.leases" $IF
        if [ -n "/run/dhclient6.$IF.pid" ]; then DHCLPID=`cat "/run/dhclient6.$IF.pid"`;
        else DHCLPID="65536"; fi
        $DHCPV6CL -r -pf "/run/dhclient6.$IF.pid" -lf "/var/lib/dhcp/dhclient6.$IF.leases" $IF
        if ps -p "$DHCLPID" | grep dhclient > /dev/null ;
        then logger -s -t $0 "($$):dhclient exist, so kill id=$DHCLPID($CL)"; kill -SIGKILL "$DHCLPID";
        else logger -s -t $0 "($$):dhclient killed($CL)"; fi
    else
        if [ -e "$PTH/$CL.$IF.leases" ]; then rm "$PTH/$CL.$IF.leases"; fi
        $DHCPV6CL -cf "$PTH/$CL.conf" -pf "$PTH/$CL.pid" -lf "$PTH/$CL.$IF.leases" $IF
        if [ -n "/$PTH/$CL.pid" ]; then DHCLPID=`cat "/$PTH/$CL.pid"`;
        else DHCLPID="65536"; fi
        $DHCPV6CL -r -cf "$PTH/$CL.conf" -pf "$PTH/$CL.pid" -lf "$PTH/$CL.$IF.leases" $IF
        if ps -p "$DHCLPID" | grep dhclient > /dev/null ;
        then logger -s -t $0 "($$):dhclient exist, so kill id=$DHCLPID($CL)"; kill -SIGKILL "$DHCLPID";
        else logger -s -t $0 "($$):dhclient killed($CL)"; fi
    fi
done

2022年2月16日 10:53:13 PR-600MIが応答しなくなった。IPv6セキュリティログが停止していた。手動で再起動を実行後、reconfigureメッセージを捉えてRebindAllISCが起動された。各装置に計画通りprefixが委譲された。原因不明だが、DHCPv６がrenewに応答しなくなり、ログ記録が停止し、IPv6通信のルーティングも停止。IPv4通信は未確認。
2022年2月16日 15:41:37 再度PR-600MIが応答しなくなる。手動で再起動。
2022年2月26日 10:53:13 勝手に再起動する。renewに応答しなくなり再起動。再起動直前までIPv6通信稼働。
2022年3月1日 03:47:54 深夜に再起動していた。
2022年3月5日 16:20:01 勝手に再起動する。renewに応答がなくなり再起動。再起動直前までIPv6通信稼働。

推測だが、DHCPv6がhung upして委譲済みのprefixのrenewに応答しなくなり、prefixのvalid lifetime(=14400)が切れてIPv6通信が出来なくなるのかもしれない。何故セキュリティログ（IPv6）が停止するのかは不明。

（２）PR-600MIセキュリティログ（IPv6）の「0 entries」を検出する
セキュリティログが停止してからIPv6通信が出来なくなるまで3-4時間程度経過するため、いつセキュリティログが停止したのか判断出来ない。PR-600MIから直接ログ状態を取得し記録する事にした。検出後、プログラムからPR-600MIの再起動実行も検討する。

ck-pr600mi-hangup
#!/bin/bash
# check a hanging up of the pr-600mi HGW
i=0
while [ $i -lt 3 ]
do
    # getting the IPv6 security log information from the ntt home gateway
    loginf=`wget --dns-timeout=2 --connect-timeout=5 -qO- ¥
      http://pr600mi.familyname/ntt/information/v6SecurityLog |
      sed -e 's/\(<\/tr>\)/\1\n/g' | sed -n 's/^.*ip6_security : There are \(.*\) entries.*$/\1/p'`
    if [ $loginf -ne 0 ]; then logger -s -t $0 "$loginf entries"; exit 0; fi
    i=$((i += 1))
    echo -n "."
    sleep 60
done
# PR600MI will be hanging up ...
logger -s -t $0 "PR-600MI will be hanging up ..."
echo "PR-600MI should be reboot!"

2022年3月16日 11:35:00 IPv6 Security log 0を検出。検出後４時間程度IPv6通信稼働。IPv6通信が出来なくなったので手動で再起動。
「0 entries」後に、「ping -6 -i 10 www11.plala.or.jp」でIPv6通信が遮断されるタイミング記録を試みたが、アクセス不能後もping応答があり確認出来なかった。一度処理を停止して再度コマンドを実行すると応答が無かった。不思議。

「0 entries」検出後のsyslog
Mar 16 11:30:01 debian10 CRON[19971]:  (root) CMD (/root/RebindAllISCWaitX > /dev/null 2>&1)
Mar 16 11:30:01 debian10 /root/ck-pr600mi-hang:  100 entries
Mar 16 11:30:01 debian10 /root/RebindAllISCWait:  (19983):Delegated prefix is 2409:10:XXXX:YY00::/56
Mar 16 11:30:01 debian10 /root/RebindAllISCWait:  (19983):bb10 nvr510(ac:44:f2:AA:BB:CC)
Mar 16 11:30:01 debian10 /root/RebindAllISCWait:  (19983):bb20 openwrt(00:1d:73:34:45:56)
Mar 16 11:30:01 debian10 /root/RebindAllISCWait:  (19983):bb30 xps8300enp3s0(c0:25:e9:34:51:23)
Mar 16 11:30:01 debian10 /root/RebindAllISCWait:  (19983):bb40 nvr500(00:a0:de:AA:BB:DD)
Mar 16 11:30:39 debian10 dhclient[26400]:  PRC: Renewing lease on enp3s0.
Mar 16 11:30:39 debian10 dhclient[26400]:  XMT: Renew on enp3s0, interval 9370ms.
Mar 16 11:30:40 debian10 dhclient[26400]:  RCV: Reply message on enp3s0 from fe80::2ae9:8eff:fe12:3457.

*** この間でセキュリティログ（IPv6）がhanging up ***
Mar 16 11:35:01 debian10 CRON[20031]:  (root) CMD (/root/ck-pr600mi-hang > /dev/null 2>&1)
Mar 16 11:38:02 debian10 /root/ck-pr600mi-hang:  PR-600MI is hanging up ...
*** １分毎に3回ログ停止状態を確認したのでPR-600MIのhanging upを認定 ***

Mar 16 13:15:01 debian10 CRON[21096]:  (root) CMD (/root/ck-pr600mi-hang > /dev/null 2>&1)
Mar 16 13:15:02 debian10 /root/RebindAllISCWait:  (21108):Delegated prefix is 2409:10:XXXX:YY00::/56
Mar 16 13:15:02 debian10 /root/RebindAllISCWait:  (21108):bb10 nvr510(ac:44:f2:AA:BB:CC)
Mar 16 13:15:02 debian10 /root/RebindAllISCWait:  (21108):bb20 openwrt(00:1d:73:34:45:56)
Mar 16 13:15:02 debian10 /root/RebindAllISCWait:  (21108):bb30 xps8300enp3s0(c0:25:e9:34:51:23)
Mar 16 13:15:02 debian10 /root/RebindAllISCWait:  (21108):bb40 nvr500(00:a0:de:AA:BB:DD)
*** DHCPv6 renewに応答がなくなる ***
Mar 16 13:15:40 debian10 dhclient[26400]:  PRC: Renewing lease on enp3s0.
Mar 16 13:15:40 debian10 dhclient[26400]:  XMT: Renew on enp3s0, interval 10860ms.
Mar 16 13:15:51 debian10 dhclient[26400]:  XMT: Renew on enp3s0, interval 21840ms.
Mar 16 13:16:13 debian10 dhclient[26400]:  XMT: Renew on enp3s0, interval 43490ms.
Mar 16 13:16:56 debian10 dhclient[26400]:  XMT: Renew on enp3s0, interval 90670ms.
Mar 16 13:18:27 debian10 dhclient[26400]:  XMT: Renew on enp3s0, interval 180850ms.
Mar 16 13:21:28 debian10 dhclient[26400]:  XMT: Renew on enp3s0, interval 376830ms.
Mar 16 13:27:45 debian10 dhclient[26400]:  XMT: Renew on enp3s0, interval 548600ms.
Mar 16 13:36:54 debian10 dhclient[26400]:  XMT: Renew on enp3s0, interval 581670ms.
Mar 16 13:46:36 debian10 dhclient[26400]:  XMT: Renew on enp3s0, interval 613720ms.
Mar 16 13:56:49 debian10 dhclient[26400]:  XMT: Renew on enp3s0, interval 632030ms.
Mar 16 14:07:22 debian10 dhclient[26400]:  XMT: Renew on enp3s0, interval 598000ms.
Mar 16 14:17:20 debian10 dhclient[26400]:  XMT: Renew on enp3s0, interval 581800ms.
Mar 16 14:27:02 debian10 dhclient[26400]:  XMT: Renew on enp3s0, interval 218780ms.
*** DHCPv6 rebind要求に変わる ***
Mar 16 14:30:40 debian10 dhclient[26400]:  PRC: Rebinding lease on enp3s0.
Mar 16 14:30:40 debian10 dhclient[26400]:  XMT: Rebind on enp3s0, interval 10090ms.
Mar 16 14:30:51 debian10 dhclient[26400]:  XMT: Rebind on enp3s0, interval 20610ms.
Mar 16 14:31:11 debian10 dhclient[26400]:  XMT: Rebind on enp3s0, interval 42280ms.
Mar 16 14:31:53 debian10 dhclient[26400]:  XMT: Rebind on enp3s0, interval 83720ms.
Mar 16 14:33:17 debian10 dhclient[26400]:  XMT: Rebind on enp3s0, interval 172830ms.
Mar 16 14:36:10 debian10 dhclient[26400]:  XMT: Rebind on enp3s0, interval 350540ms.
Mar 16 14:42:01 debian10 dhclient[26400]:  XMT: Rebind on enp3s0, interval 542270ms.
Mar 16 14:51:03 debian10 dhclient[26400]:  XMT: Rebind on enp3s0, interval 548910ms.
Mar 16 15:00:12 debian10 dhclient[26400]:  XMT: Rebind on enp3s0, interval 618590ms.
*** preferred life timeを超える ***
Mar 16 15:00:40 debian10 dhclient[26400]:  PRC: Prefix 2409:10:XXXX:YY30::/60 depreferred.
*** valid life timeを超える ***
Mar 16 15:30:40 debian10 dhclient[26400]:  PRC: Prefix 2409:10:XXXX:YY30::/60 expired.

*** 時間を特定できなかったがインターネットアクセスができなくなる ***
*** IPv6通信が出来ず、IPv4overIPv6が遮断、 IPv4 PPPoEの疎通確認をしなかった ***

Mar 16 15:30:40 debian10 dhclient[26400]:  PRC: Bound lease is devoid of active addresses.  Re-initializing.
Mar 16 15:30:40 debian10 dhclient[26400]:  XMT: Solicit on enp3s0, interval 1090ms.
Mar 16 15:30:41 debian10 dhclient[26400]:  XMT: Solicit on enp3s0, interval 2130ms.
Mar 16 15:30:43 debian10 dhclient[26400]:  XMT: Solicit on enp3s0, interval 4290ms.
Mar 16 15:30:48 debian10 dhclient[26400]:  XMT: Solicit on enp3s0, interval 8540ms.
Mar 16 15:30:56 debian10 dhclient[26400]:  XMT: Solicit on enp3s0, interval 16910ms.
Mar 16 15:31:13 debian10 dhclient[26400]:  XMT: Solicit on enp3s0, interval 32890ms.
Mar 16 15:31:46 debian10 dhclient[26400]:  XMT: Solicit on enp3s0, interval 67200ms.
Mar 16 15:32:53 debian10 dhclient[26400]:  XMT: Solicit on enp3s0, interval 117520ms.
Mar 16 15:34:51 debian10 dhclient[26400]:  XMT: Solicit on enp3s0, interval 122260ms.
Mar 16 15:36:53 debian10 dhclient[26400]:  XMT: Solicit on enp3s0, interval 111390ms.
Mar 16 15:38:45 debian10 dhclient[26400]:  XMT: Solicit on enp3s0, interval 119110ms.
Mar 16 15:40:44 debian10 dhclient[26400]:  XMT: Solicit on enp3s0, interval 126030ms.
Mar 16 15:42:50 debian10 dhclient[26400]:  XMT: Solicit on enp3s0, interval 126850ms.
Mar 16 15:44:57 debian10 dhclient[26400]:  XMT: Solicit on enp3s0, interval 131120ms.
Mar 16 15:47:08 debian10 dhclient[26400]:  XMT: Solicit on enp3s0, interval 117100ms.
Mar 16 15:49:06 debian10 dhclient[26400]:  XMT: Solicit on enp3s0, interval 113780ms.
Mar 16 15:50:59 debian10 dhclient[26400]:  XMT: Solicit on enp3s0, interval 112280ms.
Mar 16 15:52:52 debian10 dhclient[26400]:  XMT: Solicit on enp3s0, interval 131270ms.
Mar 16 15:55:03 debian10 dhclient[26400]:  XMT: Solicit on enp3s0, interval 128880ms.
Mar 16 15:57:12 debian10 dhclient[26400]:  XMT: Solicit on enp3s0, interval 117290ms.

*** 2022/03/16 15:58:00 JavaVM normal stop   PR-600MIの手動再起動 ***

Mar 16 15:59:06 debian10 dhclient[26400]:  RCV: Reconfigure message on enp3s0 from fe80::2ae9:8eff:fe12:3457.
Mar 16 15:59:06 debian10 dhclient[26400]:  Packet received, but nothing done with it.
Mar 16 15:59:07 debian10 dhclient[26400]:  RCV: Reconfigure message on enp3s0 from fe80::2ae9:8eff:fe12:3457.
Mar 16 15:59:07 debian10 dhclient[26400]:  Packet received, but nothing done with it.
Mar 16 15:59:09 debian10 dhclient[26400]:  RCV: Reconfigure message on enp3s0 from fe80::2ae9:8eff:fe12:3457.
Mar 16 15:59:09 debian10 dhclient[26400]:  Packet received, but nothing done with it.

セキュリティログ（IPv6）の停止を確認した時、DHCPv4でIPv4アドレスを取得した直後だった。DHCPv4とも関係するのかもしれない。。。

（３）PR-600MIを再起動する
ck-pr600mi-hangでセキュリティログ（IPv6）が停止した事を検出し、PR-600MIの再起動をプログラムから実行出来るようにしてみた

pr600mi-reboot
#!/bin/bash
# Reboot the pr-600mi HGW
# getting the security token for reboot from the ntt home gateway
# id="REBOOT_FORM" action="/ntt/useMaintenance/reboot/execute" method="post"
# SECURITY_TOKEN=
# save session cookie  HGWSESSIONID
securitytoken=`wget --dns-timeout=2 --connect-timeout=5 -qO-¥
   --save-cookies cookies.txt --keep-session-cookies¥
    http://pr600mi.familyname/ntt/userMaintenance/reboot |
    sed -n 's/^.*form .*value=\"\([0-9a-f]*\)\".*$/\1/p'`
#echo "SECURITY_TOKEN=$securitytoken"
# reboot PR-600MI
reboot=`wget --dns-timeout=2 --connect-timeout=5 -qO-¥
    --load-cookies cookies.txt --post-data="SECURITY_TOKEN=$securitytoken"¥
    http://pr600mi.familyname/ntt/userMaintenance/reboot/execute`
logger -s -t $0 "($$):reboot PR-600MI direct"

「0 entries」検出後に自動でPR-600MIの再起動実行を設定していない。このコマンドを手動実行している。

（４）今後の方針
DHCPv6でmulti prefix delegationを行うとPR-600MIのDHCPv6がhangすると思われるので再確認と再現方法を確立する。
hanging up時のIPv4 PPPoE、IPv4関連の状態確認。

「ひかり電話 HGW PR-600MI のハングアップと勝手に再起動する不具合について＃2」

記事一覧 | 画像一覧 | フォロワー一覧 | フォトチャンネル一覧

アクセス
訪問者	342	IP
トータル
訪問者	859,758	IP

	ブログを読むだけ。毎月の訪問日数に応じてポイント進呈
	gooブロガーの今日のひとこと
	訪問者数に応じてdポイント最大1,000pt当たる！
	goo blogは20周年を迎えました！

rabbit51

it's since Nov.30 2005
May.29 2014, transferred from broach

ひかり電話 HGW PR-600MI のハングアップと勝手に再起動する不具合について

カレンダー

カテゴリー

アクセス状況

最新記事

最新コメント

バックナンバー

ブックマーク

goo blog お知らせ

goo blog おすすめ

2022年3月
日	月	火	水	木	金	土
		1	2	3	4	5
6	7	8	9	10	11	12
13	14	15	16	17	18	19
20	21	22	23	24	25	26
27	28	29	30	31

rabbit51

it's since Nov.30 2005 May.29 2014, transferred from broach

ひかり電話 HGW PR-600MI のハングアップと勝手に再起動する不具合について

カレンダー

カテゴリー

アクセス状況

最新記事

最新コメント

バックナンバー

ブックマーク

goo blog お知らせ

goo blog おすすめ

it's since Nov.30 2005
May.29 2014, transferred from broach