goo blog サービス終了のお知らせ 

rabbit51

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

ひかり電話HGW PR-600MI の「メインテナンス」「pingテスト」の表記バグ

2022-04-01 23:00:00 | ひかり電話
ひかり電話HGW PR-600MIに「メインテナンス」「PINGテスト」機能がある。


「PINGテスト」は、IPv4とIPv6共にIPアドレス指定で行う。

実行後、戻るボタンで戻ると入力項目がクリアされる。
毎回入力するのが厄介なので、スクリプト実行をしてみた。
pr600mi-ping
#!/bin/bash
# getting the security token for ping from the ntt home gateway
# id="EXECUTE_PING_FORM" action="/ntt/userMaintenance/fifth/ping/execute" method="post"
# SECURITY_TOKEN=
# ping IPv4
hostip="60.43.63.111"
ipv6flag=""
securitytoken=`wget --dns-timeout=2 --connect-timeout=5 -q -O - --save-cookies cookies.txt ¥
    --keep-session-cookies http://pr600mi.familyname/ntt/userMaintenance/fifth/ping | 
    sed -n 's/^.*form .*value=\"\([0-9a-f]*\)\".*$/\1/p'`
pingresult=$(wget --dns-timeout=2 --connect-timeout=5 -qO- --load-cookies cookies.txt ¥
    --post-data="SECURITY_TOKEN=$securitytoken&ipAddress=$hostip&ipv6Option=$ipv6flag" ¥
    http://pr600mi.familyname/ntt/userMaintenance/fifth/ping/execute | 
    sed -e 's/$/\\/g' | sed -nz 's/^.*<pre>\(.*\)<\/pre>.*$/\1/p')
echo $pingresult | sed 's/\\/\n/g'

# ping IPv6
hostip6="2400:7800:0:3003::1:11"
ipv6flag6="true"
securitytoken=`wget --dns-timeout=2 --connect-timeout=5 -q -O - --save-cookies cookies.txt ¥
    --keep-session-cookies http://pr600mi.familyname/ntt/userMaintenance/fifth/ping | 
    sed -n 's/^.*form .*value=\"\([0-9a-f]*\)\".*$/\1/p'`
pingresult=$(wget --dns-timeout=2 --connect-timeout=5 -q -O - --load-cookies cookies.txt ¥
    --post-data="SECURITY_TOKEN=$securitytoken&ipAddress=$hostip6&ipv6Option=$ipv6flag6" ¥
    http://pr600mi.familyname/ntt/userMaintenance/fifth/ping/execute | 
    sed -e 's/$/\\/g' | sed -nz 's/^.*<pre>\(.*\)<\/pre>.*$/\1/p')
echo $pingresult | sed 's/\\/\n/g'
wgetで複数行の実行結果を変数に代入すると「行末文字」が削除され、連結した1行文字列になる。文字列代入する前に行末文字を「//」に変換し、表示に「//」を改行文字「/n」に再変換して表示している。また、ブログ表示で「<pre>」の「<」が正しく表記されないので、全角文字で記載している。スクリプトでは、半角にする必要がある。
実行結果
PING 60.43.63.111 (60.43.63.111): 56 data bytes
 ping: sendto: Network is unreachable

PING 2400:7800:0:3003::1:11 (2400:7800:0:3003::1:11): 56 data bytes
 64 bytes from 2400:7800:0:3003::1:11: seq=0 ttl=51 time=8.349 ms
 64 bytes from 2400:7800:0:3003::1:11: seq=1 ttl=51 time=5.690 ms
 64 bytes from 2400:7800:0:3003::1:11: seq=2 ttl=51 time=5.588 ms
 64 bytes from 2400:7800:0:3003::1:11: seq=3 ttl=51 time=5.640 ms
 64 bytes from 2400:7800:0:3003::1:11: seq=4 ttl=51 time=5.698 ms
 
 --- 2400:7800:0:3003::1:11 ping statistics ---
 5 packets transmitted, 5 packets received, 0% packet loss
 round-trip min/avg/max = 5.588/6.193/8.349 ms
PR-600MIの接続先設定でISPにIPv4 PPPoE接続がされていれば、インターネットサイトへ接続できるがNVR510のIPv4 PPPoE接続をPPPoEブリッジしているため、Network is unreachableとなる。IPv6は、transix経由で利用できる。
「情報」「DHCPクライアント取得情報」「IPv4アドレス/マスク長」のPR-600MI WAN側IPv4アドレス(第3第4オクテット部の表記を変更してある)で確認
IPv4実行結果
PING 118.177.AAAA.BBBB (118.177.AAAA.BBBB): 56 data bytes
 64 bytes from 118.177.AAAA.BBBB: seq=0 ttl=64 time=0.561 ms
 64 bytes from 118.177.AAAA.BBBB: seq=1 ttl=64 time=0.306 ms
 64 bytes from 118.177.AAAA.BBBB: seq=2 ttl=64 time=0.783 ms
 64 bytes from 118.177.AAAA.BBBB: seq=3 ttl=64 time=0.305 ms
 64 bytes from 118.177.AAAA.BBBB: seq=4 ttl=64 time=0.308 ms
 
 --- 118.177.AAAA.BBBB ping statistics ---
 5 packets transmitted, 5 packets received, 0% packet loss
 round-trip min/avg/max = 0.305/0.452/0.783 ms
「情報」「DHCPv6サーバ払い出し状況」「DNSサーバアドレス」(一部アドレス表記を変更してある)で確認
IPv6実行結果
PING 2409:10:XXXX:YY00:2ae9:8eff:fe12:3457 (2409:10:XXXX:YY00:2ae9:8eff:fe12:3457): 56 data bytes
 64 bytes from 2409:10:XXXX:YY00:2ae9:8eff:fe12:3457: seq=0 ttl=64 time=0.838 ms
 64 bytes from 2409:10:XXXX:YY00:2ae9:8eff:fe12:3457: seq=1 ttl=64 time=0.438 ms
 64 bytes from 2409:10:XXXX:YY00:2ae9:8eff:fe12:3457: seq=2 ttl=64 time=0.447 ms
 64 bytes from 2409:10:XXXX:YY00:2ae9:8eff:fe12:3457: seq=3 ttl=64 time=0.456 ms
 64 bytes from 2409:10:XXXX:YY00:2ae9:8eff:fe12:3457: seq=4 ttl=64 time=0.442 ms
 
 --- 2409:10:XXXX:YY00:2ae9:8eff:fe12:3457 ping statistics ---
 5 packets transmitted, 5 packets received, 0% packet loss
 round-trip min/avg/mapingResult
round-trip値がおかしい。スクリプトの問題かWebページで確認してみた。

①LAN側グローバルIPv6アドレス

②LAN側グローバルIPv6自己アドレス

③LAN側グローバルIPv6自己アドレス(DNS始点)

④LAN側リンクローカルIPv6アドレス

⑤LAN側リンクローカルIPv6自己アドレス

⑥WAN側グローバルIPv6アドレス

⑦WAN側リンクローカルIPv6自己アドレス

スクリプトもWebページも同じ結果
①−⑦の結果からグローバル・プレフィックス+EUI64アドレスで表記不具合が発生するようだ。
同じグローバル・プレフィックス内の他のEUI64アドレスを持つホストで確認してみた

NVR500のWAN(LAN2)


OpenWRT(Buffalo WZR-HP-G300NH)のWAN




 

コメント
  • X
  • Facebookでシェアする
  • はてなブックマークに追加する
  • LINEでシェアする

ひかり電話 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年になって「突然の再起動」が2回(2022/2/26, 2022/3/1)、「セキュリティログentries 0」が1回(2022/3/16)発生した。そこで、「セキュリティログentries 0」の検出と「再起動」の自動実行方法を検討してみた。

(1)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が委譲された。原因不明だが、DHCPv6が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)が停止するのかは不明。

(2)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を検出。検出後4時間程度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 ...
*** 1分毎に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とも関係するのかもしれない。。。

(3)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の再起動実行を設定していない。このコマンドを手動実行している。

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

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


 

コメント
  • X
  • Facebookでシェアする
  • はてなブックマークに追加する
  • LINEでシェアする

ひかり電話 HGW PR-600MI DHCPv6-PDのReconfigureを捉えPrefix再取得を実行する

2022-01-20 09:00:00 | ひかり電話
ひかり電話 HGW PR-600MI(PR-S300SEも同じ)の再起動時やNGN配布のPrefixが変更された時、DHCPv6 Reconfigureメッセージで通知される(「ひかり電話 HGW PR-600MI のDHCPv6-PDサーバーが割り当てるPrefixの変化を検出する」や「ヤマハ NVR500で「ぷらら」のIPv6 IPoE接続を行う」で確認)。ただ、PR-600MI再起動時のreconfigureメッセージは、Prefix Delegation先に通知したり、しなかったりと不安定だ(バグか?)(「ひかり電話 HGW PR-600MI DHCPv6-PDサーバーが再起動時に割り当てるPrefix」で確認)。


(1)PR-600MI再起動時のPrefix変更を検知
prefix委譲されているルータ(NVR510/NVR500/OpenWrt)からdebian10サーバーへsyslogデータを送信する
debian10サーバーでsyslogを監視し、DHCPv6 reconfigureメッセージを検知する
recofigureメッセージを検知したら「ひかり電話 HGW PR-600MI のDHCPv6-PDサーバーが割当てるPrefixを制御する」のRebindAllISCスクリプトを実行する(複数機器からのreconfigureメッセージでRebindAllISCが複数起動されない対策が必要)。

reconfigureメッセージが発行されない場合の対策
cronで15分毎にRebindAllISCを実行する

debian10再起動時
cronで@reboot時にRebindAllISCを実行する

(2)NVR510/500の設定とログ確認
NVR510/500 config
syslog host 192.168.1.57
syslog debug on
syslog notice on
syslog記録
    info,user Dec 24 17:14:32 nvr500-lan2.familyname  [DHCPv6] receive RECONFIGURE
debug,user Dec 24 17:14:32 nvr500-lan2.familyname  [DHCPv6] Success RECONFIGURE message authentication
debug,user Dec 24 17:14:32 nvr500-lan2.familyname  [DHCPv6] start requesting
debug,user Dec 24 17:14:38 nvr500-lan2.familyname  [DHCPv6] select DHCPv6 server :: [0003000128e98e123457]
    info,user Dec 24 17:14:39 nvr500-lan2.familyname  [DHCPv6] Renumbering start (LAN2)
debug,user Dec 24 17:14:40 nvr500-lan2.familyname  [IPv6] prefix 2409:10:XXXX:YY20::/60 (duration: 14400) is delegated from LAN2 (DHCPv6)
debug,user Dec 24 17:14:41 nvr500-lan2.familyname  [IPv6] start DAD for 2409:10:XXXX:YY20::1
debug,user Dec 24 17:14:42 nvr500-lan2.familyname  [IPv6] complete DAD for 2409:10:XXXX:YY20::1
    info,user Dec 24 17:14:42 nvr500-lan2.familyname  [DHCPv6] Renumbering success (LAN2)
reconfigureメッセージを受けるとauthenticationを確認し、prefixの再取得が実行される。タイミングによるのかログ項目が記録されない場合がある。本体ログと同じなのでsyslog送信との関連は無いと思われる。reconfigureメッセージ受信のトリガー用途であれば、「syslog debug off」で良い。加えて「syslog notice on」だとパケットフィルタのINSPECTION記録が送出されるので「syslog notice off」とする。
reconfigureメッセージを受け取ってからprefixを再取得するまで約10秒掛かる。

Success RECONFIGURE message authentication
reconfigureメッセージを受けた後、メッセージ認証結果がログ記録される(デバックレベル)。認証できなければ、reconfigureメッセージは無視される。
reconfigureメッセージに含まれるauthenticationオプションでメッセージのダイジェストが渡される(HMAC-MD5)。ダイジェスト生成の鍵は、request時のreconfigure-acceptオプションに対してreply時のauthenticationオプションで渡される。認証を確認してみる。

DHCPv6 reply message

Informationの先頭1バイトが「01」が鍵を示す。「01」に続く128ビット(16バイト)をメモしておく。「Authentication Information」を選択しCopy as a Hex Stream でコピーしtextファイルに保存しておく。
Authentication Information: 
013146XXXXXXXXXXXXXXXXXXXXXXXX7743
鍵は、接続される全デバイスに渡り同じ鍵が配布される。時間経過で変化する事も無い。バージョンアップされても変化ない(01.00.0005->01.00.0007)。RFC3315のReconfigure Key Authentication Protocolによれば、悪意のあるreconfigureメッセージから保護できる程度が想定されているが、鍵が固定値というのは、どうなんだろうか?一つの管理ドメイン内で同じ鍵である事は、良いと思うが、鍵のlifetimeが長すぎるので、起動毎に異なる鍵が用意された方が良いような気がする。

DHCPv6 reconfigure message

reconfigureメッセージのDHCPv6メッセージ部を選択し、「右クリック」・「Export Packet Bytes...」でファイル名「test.bin」で書き出す。
test.bin | od -t xC
0000000    0a  00  00  00  00  01  00  0a  00  03  00  01  00  a0  de  7d
0000020    a5  1b  00  02  00  0a  00  03  00  01  28  e9  8e  b5  98  27
0000040    00  06  00  02  00  19  00  13  00  01  05  00  0b  00  1c  03
0000060    01  00  e5  71  00  61  75  2b  90  a7  02  fb  7f  a3  53  22
0000100    68  dc  a0  04  d9  e8  dc  1d  dc  f5  24                    
0000113
Authentication Informationの先頭バイトが「02」でダイジェストを示す。ダイジェスト部(最後の16バイト)を「0」に置き換え、HMAC-MD5を生成する。
test.binからダイジェスト部を「0」にしたファイルtest3.binを生成する
xxd -p -l 58 test.bin | xxd -r -p > test1.bin
cat test1.bin | od -t xC
0000000    0a  00  00  00  00  01  00  0a  00  03  00  01  00  a0  de  7d
0000020    a5  1b  00  02  00  0a  00  03  00  01  28  e9  8e  b5  98  27
0000040    00  06  00  02  00  19  00  13  00  01  05  00  0b  00  1c  03
0000060    01  00  e5  71  00  61  75  2b  90  a7                        
0000072

echo -n "0200000000000000000000000000000000" | xxd -r -p > test2.bin
cat test2.bin | od -t xC
0000000    02  00  00  00  00  00  00  00  00  00  00  00  00  00  00  00
0000020    00                                                            
0000021

cat test1.bin test2.bin > test3.bin
cat test3.bin | od -t xC
0000000    0a  00  00  00  00  01  00  0a  00  03  00  01  00  a0  de  7d
0000020    a5  1b  00  02  00  0a  00  03  00  01  28  e9  8e  b5  98  27
0000040    00  06  00  02  00  19  00  13  00  01  05  00  0b  00  1c  03
0000060    01  00  e5  71  00  61  75  2b  90  a7  02  00  00  00  00  00
0000100    00  00  00  00  00  00  00  00  00  00  00                    
0000113
opensslでHMAC-MD5を計算する
cat test3.bin | openssl dgst -md5 -mac hmac -macopt hexkey:3146XXXXXXXXXXXXXXXXXXXXXXXX7743 -hex
fb7fa3532268dca004d9e8dc1ddcf524
reconfigureで通知されたダイジェストと計算値が一致したのでprefixがdelegationされたDHCPv6サーバからのreconfigureメッセージである事が確認される。

(3)OpenWrtの設定とログ確認
「システム」「システムプロパティ」「ロギング」
外部システムログ サーバー=192.168.1.57
ログ出力レベル=デバッグ
/etc/config/system
config system                            
        option hostname 'OpenWrt'        
        option ttylogin '0'              
        option log_size '64'             
        option urandom_seed '0'          
        option zonename 'Asia/Tokyo'         
        option timezone 'JST-9'              
        option log_proto 'udp'               
        option conloglevel '8'               
        option cronloglevel '8'              
        option log_ip '192.168.1.57' 
syslogは、debugレベルまで出力する。odhcpv6cは、「reconfigure」メッセージを受けた時に記録しない。odhcp6cのログレベルを上げて確認してみる。「Openwrt ipv6 -odhcp6c client」の情報から、
/lib/netifd/proto/dhcpv6.sh
proto_dhcpv6_setup() {
--@line#61 local opts=""   --> local opts="-v "
と変更し、odhcp6cのログレベルを変更した。
reconfigureメッセージは、renewするよう指示しているので、odhcp6cは、renewが行われる。
 syslog記録
notice,daemon Dec 26 13:47:18 OpenWrt odhcp6c[16605]:  Starting RENEW transaction (timeout 4500s, max rc 0)
notice,daemon Dec 26 13:47:18 OpenWrt odhcp6c[16605]:  Send RENEW message (elapsed 0ms, rc 0)
notice,daemon Dec 26 13:47:18 OpenWrt odhcp6c[16605]:  Got a valid reply after 3ms
warning,daemon Dec 26 13:47:18 OpenWrt odhcp6c[16605]:  Server returned IA_PD status 3
notice,daemon Dec 26 13:47:19 OpenWrt odhcp6c[16605]:  Starting REQUEST transaction (timeout 4294967295s, max rc 10)
notice,daemon Dec 26 13:47:19 OpenWrt odhcp6c[16605]:  Send REQUEST message (elapsed 0ms, rc 0)
notice,daemon Dec 26 13:47:19 OpenWrt odhcp6c[16605]:  Got a valid reply after 3ms
warning,daemon Dec 26 13:47:19 OpenWrt odhcp6c[16605]:  Server returned IA_PD status 4
notice,daemon Dec 26 13:47:19 OpenWrt odhcp6c[16605]:  Starting REBIND transaction (timeout 3600s, max rc 0)
notice,daemon Dec 26 13:47:19 OpenWrt odhcp6c[16605]:  Send REBIND message (elapsed 0ms, rc 0)
notice,daemon Dec 26 13:47:19 OpenWrt odhcp6c[16605]:  Got a valid reply after 95ms
notice,daemon Dec 26 13:47:19 OpenWrt odhcp6c[16605]:  (re)starting transaction on eth1
notice,user Dec 26 13:47:20 OpenWrt odhcp6c:  unbound::00030001001d73344556
notice,daemon Dec 26 13:47:20 OpenWrt netifd:  wan6 (16605): odhcp6c: unbound::00030001001d73344556
notice,daemon Dec 26 13:47:20 OpenWrt odhcp6c[16605]:  Starting SOLICIT transaction (timeout 4294967295s, max rc 0)
notice,daemon Dec 26 13:47:20 OpenWrt odhcp6c[16605]:  Got a valid reply after 3ms
notice,daemon Dec 26 13:47:22 OpenWrt odhcp6c[16605]:  Starting SOLICIT transaction (timeout 4294967295s, max rc 0)
notice,daemon Dec 26 13:47:22 OpenWrt odhcp6c[16605]:  Got a valid reply after 3ms
notice,daemon Dec 26 13:47:23 OpenWrt odhcp6c[16605]:  Starting REQUEST transaction (timeout 4294967295s, max rc 10)
notice,daemon Dec 26 13:47:23 OpenWrt odhcp6c[16605]:  Send REQUEST message (elapsed 0ms, rc 0)
notice,daemon Dec 26 13:47:23 OpenWrt odhcp6c[16605]:  Got a valid reply after 93ms
notice,daemon Dec 26 13:47:23 OpenWrt odhcp6c[16605]:  entering stateful-mode on eth1
notice,daemon Dec 26 13:47:23 OpenWrt odhcp6c[16605]:  Starting <POLL> transaction (timeout 6300s, max rc 0)
notice,user Dec 26 13:47:34 OpenWrt odhcp6c:  bound:2409:10:XXXX:YY20::/60,12590,14390:00030001001d73344556
notice,daemon Dec 26 13:47:34 OpenWrt netifd:  wan6 (16605): odhcp6c: bound:2409:10:XXXX:YY20::/60,12590,14390:00030001001d73344556
reconfigureメッセージ受信の記録がsyslogに残されない。Githubのソースを確認してみた。
「information request」時に「reconfigure」を受けるとsyslog(notice)に記録されるが、その他のモードでは、syslogに記録されないようだ。
odhcp6cは、reconfigureメッセージを受けると、メッセージの認証を行いrenewを実施する。DHCPv6 status code=3(NoBindings)が返される。requestを実施する。DHCPv6 status=4(NotOnLink)が返される。rebindを実施する(releaseを行い、solicit/requestでprefixを再取得する)。reconfigureメッセージを受けてからprefixを再取得するまで約16秒掛かる。
prefix再取得の手続きからreconfigureメッセージを受けた事を推定するのも難しそうだ。
RebindAllISCの定期実行で期待するprefixが割り当てられているか確認する事とする。

(4)debian10の設定とログ確認
manualによれば、Reconfigureメッセージを受け取れないと思われる。
DHCP 4.4.2 option dhcp6.reconf-accept ;
The reconf-accept option is included by DHCPv6 clients that support the Reconfigure extensions, advertising that they will respond if the server were to ask them to Reconfigure. There is no support for DHCPv6 Reconfigure extensions, and this option is documented informationally only.
ソースコードを確認してみる。reconfigureメッセージを受けた事をログ記録するようだ。
dhclient.c(DhcpDdns-4.4.2-P1/client)
#1771
dhcpv6(struct packet *packet) {
........
#1794
         switch(packet->dhcpv6_msg_type) {
........
#1806
               case DHCPV6_ADVERTISE:
               case DHCPV6_RECONFIGURE:
                 if (stateless)
                   return;
               /* Falls through */
               case DHCPV6_REPLY:
                 log_info("RCV: %s message on %s from %s.",
                          dhcpv6_type_names[packet->dhcpv6_msg_type],
                          packet->interface->name, piaddr(packet->client_addr));
                 break;
........
#1832
         log_info("Packet received, but nothing done with it.");
reconfigureメッセージ処理は実行されない。
dhc6.c(dhcp-4.4.2-P1/client)
/* While bound, ignore packets.  In the future we'll want to answer
 * Reconfigure-Request messages and the like.
 */
void
bound_handler(struct packet *packet, struct client_state *client)
{
        log_debug("RCV: Input packets are ignored once bound.");
}
dhclientがdhcp6.reconf-acceptオプションを送信できるか確認してみる。
/etc/dhcp/dhclient.conf
option rfc3442-classless-static-routes code 121 = array of unsigned integer 8;
option dhcp6.vendor-class code 16 = {integer 32, integer 16, string};
## NTT
option space NTT code width 2 length width 2 hash size 8;
option NTT.mac-address code 201 = string;
option NTT.tel-number code 202 = text;
option NTT.additional-tel-number code 203 = text;
option NTT.sip-domain code 204 = domain-list;
option NTT.hgw-server code 210 = domain-list;
option vsio.NTT code 210 = encapsulate NTT;
interface "enp3s0" {
        also request dhcp6.sntp-servers, dhcp6.sip-servers-addresses;
        also request dhcp6.vendor-opts;
        send dhcp6.client-id 00:03:00:01:c0:25:e9:XX:XX:XX; #debian10 enp3s0
        send dhcp6.vendor-class 210 6 28:e9:8e:12:34:57; # Enterprise ID
        send dhcp6.reconf-accept; #Reconfigure message accept
}
reconfigure accept オプションが送信され、PR-600MIからreconfigureメッセージを受けたログが記録される
/var/log/syslog
info,daemon Dec 26 09:50:13 debian10 dhclient[26955]: RCV: Reconfigure message on enp3s0 from fe80::2ae9:8eff:fe12:3457.
info,daemon Dec 26 09:50:13 debian10 dhclient[26955]: Packet received, but nothing done with it.
info,daemon Dec 26 09:50:14 debian10 dhclient[26955]: RCV: Reconfigure message on enp3s0 from fe80::2ae9:8eff:fe12:3457.
info,daemon Dec 26 09:50:14 debian10 dhclient[26955]: Packet received, but nothing done with it.
info,daemon Dec 26 09:50:16 debian10 dhclient[26955]: RCV: Reconfigure message on enp3s0 from fe80::2ae9:8eff:fe12:3457.
info,daemon Dec 26 09:50:16 debian10 dhclient[26955]: Packet received, but nothing done with it.
info,daemon Dec 26 09:50:20 debian10 dhclient[26955]: RCV: Reconfigure message on enp3s0 from fe80::2ae9:8eff:fe12:3457.
info,daemon Dec 26 09:50:20 debian10 dhclient[26955]: Packet received, but nothing done with it.
info,daemon Dec 26 09:50:28 debian10 dhclient[26955]: RCV: Reconfigure message on enp3s0 from fe80::2ae9:8eff:fe12:3457.
info,daemon Dec 26 09:50:28 debian10 dhclient[26955]: Packet received, but nothing done with it.
info,daemon Dec 26 09:50:44 debian10 dhclient[26955]: RCV: Reconfigure message on enp3s0 from fe80::2ae9:8eff:fe12:3457.
info,daemon Dec 26 09:50:44 debian10 dhclient[26955]: Packet received, but nothing done with it.
info,daemon Dec 26 09:51:16 debian10 dhclient[26955]: RCV: Reconfigure message on enp3s0 from fe80::2ae9:8eff:fe12:3457.
info,daemon Dec 26 09:51:16 debian10 dhclient[26955]: Packet received, but nothing done with it.
dhclientがreconfigureメッセージに応答しないため、PR-600MIがreconfigureメッセージの再送を行う。reconfigureメッセージを確認することが目的なので問題無し。

(5)Reconfigure検知とスクリプト実行設定
reconfigureメッセージを受け、NVR500/510が約10秒、OpenWrtが約16秒後にprefixの再取得を完了する。DHCPv6がreconfigureメッセージを受けたことをsyslogサーバーで識別し、RebindAllISCスクリプトを約20秒後に実行するよう制御する。
rsyslog.confのグローバルセクションでRebindAllISCの起動待ち時間を設定する「WaitValue」templateを定義する。このテンプレートで設定されたデータがシェル実行アクション時にargv[1]で渡される
/etc/rsyslog.conf
#########################
#### GLOBAL DIRECTIVES ####
#########################
$template WaitValue,"20"
/etc/rsyslog.d/nvr510.conf
if $fromhost == "nvr510-lan2.familyname" and $msg contains "[DHCPv6] receive RECONFIGURE" then ^/root/RebindAllISCWait;WaitValue
:fromhost, isequal,"nvr510-lan2.familyname"         /var/log/nvr510.log
& stop
/etc/rsyslog.d/nvr500.conf
if $fromhost == "nvr500-lan2.familyname" and $msg contains "[DHCPv6] receive RECONFIGURE" then ^/root/RebindAllISCWait;WaitValue
:fromhost, isequal,"nvr500-lan2.familyname"         /var/log/nvr500.log
& stop
/etc/rsyslog.d/debian10.conf
if ($hostname == "debian10" and $msg contains "RCV: Reconfigure message") then ^/root/RebindAllISCWait;WaitValue
各器機からのスクリプト起動とreconfigure再送信に対応するため、RebindAllISCに多重起動防止処理を加える。また、reconfigure受信後、各機器でprefixの再取得が行われるので、取得後に実行するよう待ち時間が必要となる。RebindAllISCWaitで引数指定時間sleepしてRebindAllISCを実行する
RebindAllISCWait
#!/bin/bash
if [ $$ -ne $(pgrep -fo "$0") ]; then logger -s -t $0 "$0 is already running ..."; exit 1; fi
if [ $# -gt 1 ]; then logger -s -t $0 "argument is only one."; exit 1; fi
if [ $# -eq 1 ]; then logger -s -t $0 "sleep $1 ..."; sleep $1; fi
#Original RebindAllISC script from here
. $(dirname "$0")/RebindAllISC
/etc/crontab
*/15 * * * * root /root/RebindAllISCWait > /dev/null 2>&1


(6)PR-600MI再起動処理の詳細
再起動を実行するとRebindAllISCWaitの多重起動制御が動作しない。
Linux - bash スクリプト二重起動チェック!」を参考に二重起動のチェック方法を一部変更したが効果が無い。
複数のRebindAllISCWaitが同時に起動するのではなく、連続して起動される。
rsyslogのシェルスクリプト実行が連続して複数回(reconfigureメッセージの数だけ)実行されてしまう。rsyslogのマニュアルを確認すると
Shell execute
       This executes a program in a subshell. The program is passed the
       template-generated message as the only command line parameter.
       Rsyslog waits until the program terminates and only then
       continues to run.
が要因のようだ。RebindAllISCWaitが非同期プロセスで実行するようにRebindAllISCWaitXをrsyslogから起動し、RebindAllISCWaitを非同期起動するように変更した。
RebindAllISCWaitX
#!/bin/bash
if [ $# -gt 1 ]; then logger -s -t $0 "argument is only one."; exit 1; fi
$(dirname "$0")/RebindAllISCWait $1&
RebindAllISCWait
#!/bin/bash
PID=$(pgrep -of "$0")
if [[ $$ -ne ${PID} ]]; then logger -s -t $0 "($$):${PID} is already running..."; exit 1; fi
if [ $# -gt 1 ]; then logger -s -t $0 "arg is only one."; exit 1; fi
if [ $# -eq 1 ]; then logger -s -t $0 "($$):sleep $1 ..."; sleep $1; fi
. $(dirname "$0")/RebindAllISC
cron起動は、起動直後に起動ずみのプロセスがあるとなり起動出来ない。cronも同様にRebindAllISCWaitXからの非同期起動に変更した。また、debian10のboot時にもRebindAllISCWaitXが起動するよう@rebootを設定した。一応ネットワーク関連設定が完了後に動作するよう約30秒の遅延実行指定した。
/etc/crontab
*/15 * * * * root /root/RebindAllISCWaitX > /dev/null 2>&1
@reboot   root /root/RebindAllISCWaitX 30 > /dev/null 2>&1
/etc/rsyslog.d/nvr510.conf
if $fromhost == "nvr510-lan2.familyname" and $msg contains "[DHCPv6] receive RECONFIGURE" then ^/root/RebindAllISCWaitX;WaitValue
:fromhost, isequal,"nvr510-lan2.familyname"         /var/log/nvr510.log
& stop
/etc/rsyslog.d/nvr500.conf
if $fromhost == "nvr500-lan2.familyname" and $msg contains "[DHCPv6] receive RECONFIGURE" then ^/root/RebindAllISCWaitX;WaitValue
:fromhost, isequal,"nvr500-lan2.familyname"         /var/log/nvr500.log
& stop
/etc/rsyslog.d/debian10.conf
if ($hostname == "debian10" and $msg contains "RCV: Reconfigure message") then ^/root/RebindAllISCWaitX;WaitValue

(7)結果
事例1(2022/1/17 12:39:00再起動)
PR600MI再起動後に発行されるDHCPv6 reconfigureメッセージ(renewタイプ)でRebindAllISCWaitXが起動された時のログ。xps8300enp3s0は、debian10サーバーの機種とネットワークドライバー名。PR600MIからのreconfigureは、nvr510とnvr500に発行されず、OpenWrtとdebian10にだけ発行された。
設計通りRebinAllISCWaitの複数起動処理がうまく動作する。15分毎のcron起動も実行される。
/var/log/syslog@debian10
---- Reconfigure(type:renew)を受信
info,daemon Jan 17 12:40:37 debian10 dhclient[13773]:  RCV: Reconfigure message on enp3s0 from fe80::2ae9:8eff:fe12:3457.
info,daemon Jan 17 12:40:37 debian10 dhclient[13773]:  Packet received, but nothing done with it.
notice,user Jan 17 12:40:37 debian10 /root/RebindAllISCWait:  (12121):sleep 20 ...
info,daemon Jan 17 12:40:38 debian10 dhclient[13773]:  RCV: Reconfigure message on enp3s0 from fe80::2ae9:8eff:fe12:3457.
info,daemon Jan 17 12:40:38 debian10 dhclient[13773]:  Packet received, but nothing done with it.
notice,user Jan 17 12:40:38 debian10 /root/RebindAllISCWait:  (12137):(12121)/root/RebindAllISCWait is already running...
info,daemon Jan 17 12:40:40 debian10 dhclient[13773]:  RCV: Reconfigure message on enp3s0 from fe80::2ae9:8eff:fe12:3457.
info,daemon Jan 17 12:40:40 debian10 dhclient[13773]:  Packet received, but nothing done with it.
notice,user Jan 17 12:40:40 debian10 /root/RebindAllISCWait:  (12153):(12121)/root/RebindAllISCWait is already running...
info,daemon Jan 17 12:40:44 debian10 dhclient[13773]:  RCV: Reconfigure message on enp3s0 from fe80::2ae9:8eff:fe12:3457.
info,daemon Jan 17 12:40:44 debian10 dhclient[13773]:  Packet received, but nothing done with it.
notice,user Jan 17 12:40:44 debian10 /root/RebindAllISCWait:  (12168):(12121)/root/RebindAllISCWait is already running...
info,daemon Jan 17 12:40:52 debian10 dhclient[13773]:  RCV: Reconfigure message on enp3s0 from fe80::2ae9:8eff:fe12:3457.
info,daemon Jan 17 12:40:52 debian10 dhclient[13773]:  Packet received, but nothing done with it.
notice,user Jan 17 12:40:52 debian10 /root/RebindAllISCWait:  (12184):(12121)/root/RebindAllISCWait is already running...
notice,user Jan 17 12:40:58 debian10 /root/RebindAllISCWait:  Delegated prefix is 2409:10:XXXX:YY00::/56
notice,user Jan 17 12:40:58 debian10 /root/RebindAllISCWait:  bb10 openwrt(00:1d:73:34:45:56)
notice,user Jan 17 12:40:58 debian10 /root/RebindAllISCWait:  Release devices:nvr510 openwrt xps8300enp3s0 nvr500 - Rebind devices:nvr510 openwrt xps8300enp3s0 nvr500
---- PR600MIへprefixのreleaseを開始
notice,user Jan 17 12:41:16 debian10 /root/RebindAllISCWait:  dhclient killed(xps8300enp3s0)
notice,user Jan 17 12:41:23 debian10 /root/RebindAllISCWait:  Released nvr510 openwrt xps8300enp3s0 nvr500
---- PR600MIへprefixのrelease終了と再取得開始
notice,user Jan 17 12:41:31 debian10 /root/RebindAllISCWait:  Bind #1(nvr510)
notice,user Jan 17 12:41:48 debian10 /root/RebindAllISCWait:  Bind #2(openwrt)
notice,user Jan 17 12:41:50 debian10 /root/RebindAllISCWait:  Bind #3(xps8300enp3s0)
notice,user Jan 17 12:41:50 debian10 /root/RebindAllISCWait:  Bind #4(nvr500)
---- PR600MIからprefix再取得完了
info,daemon Jan 17 12:42:44 debian10 dhclient[12732]:  RCV: Reconfigure message on enp3s0 from fe80::2ae9:8eff:fe12:3457.
info,daemon Jan 17 12:42:44 debian10 dhclient[12732]:  Packet received, but nothing done with it.
notice,user Jan 17 12:42:44 debian10 /root/RebindAllISCWait:  (12807):sleep 20 ...
notice,user Jan 17 12:43:04 debian10 /root/RebindAllISCWait:  Delegated prefix is 2409:10:XXXX:YY00::/56
notice,user Jan 17 12:43:05 debian10 /root/RebindAllISCWait:  bb10 nvr510(ac:44:f2:AA:BB:CC)
notice,user Jan 17 12:43:05 debian10 /root/RebindAllISCWait:  bb20 openwrt(00:1d:73:34:45:56)
notice,user Jan 17 12:43:05 debian10 /root/RebindAllISCWait:  bb30 xps8300enp3s0(c0:25:e9:34:51:23)
notice,user Jan 17 12:43:05 debian10 /root/RebindAllISCWait:  bb40 nvr500(00:a0:de:AA:BB:DD)

info,daemon Jan 17 12:44:44 debian10 dhclient[12732]:  RCV: Reconfigure message on enp3s0 from fe80::2ae9:8eff:fe12:3457.
info,daemon Jan 17 12:44:44 debian10 dhclient[12732]:  Packet received, but nothing done with it.
notice,user Jan 17 12:44:44 debian10 /root/RebindAllISCWait:  (12853):sleep 20 ...
info,cron Jan 17 12:45:01 debian10 CRON[12865]:  (root) CMD (/root/RebindAllISCWaitX > /dev/null 2>&1)
notice,user Jan 17 12:45:01 debian10 /root/RebindAllISCWait:  (12872):(12853)/root/RebindAllISCWait is already running...
notice,user Jan 17 12:45:04 debian10 /root/RebindAllISCWait:  Delegated prefix is 2409:10:XXXX:YY00::/56
notice,user Jan 17 12:45:04 debian10 /root/RebindAllISCWait:  bb10 nvr510(ac:44:f2:AA:BB:CC)
notice,user Jan 17 12:45:04 debian10 /root/RebindAllISCWait:  bb20 openwrt(00:1d:73:34:45:56)
notice,user Jan 17 12:45:04 debian10 /root/RebindAllISCWait:  bb30 xps8300enp3s0(c0:25:e9:34:51:23)
notice,user Jan 17 12:45:04 debian10 /root/RebindAllISCWait:  bb40 nvr500(00:a0:de:AA:BB:DD)
・debian10起動時(boot時)のcron起動でRebindAllISCWaitXの30秒sleep指定実行を確認した。

事例2(2022/1/19 9:59:00再起動)
PR-600MIの再起動中にcronでRebindAllISCが起動し(10:00:01)、タイムアウトする(10:00:10)。OpenWrtが最初にreconfigureを受け(10:00:04)、prefixを取得。cron起動のRebindAllISC実行中にNVR500とNVR510へのreconfigureメッセージ(10:00:05, 10:00:06)によりRebindAllISCが起動されalready runningで終了。NVR500とNVR510は、それぞれprefixを取得。debian10は、取得ずみのprefixでrenewingがおこなれるが、PR-600MIとbindされていないため、prefixの再取得が行われた。OpenWrt以外予定されたprefixが委譲されない状態となる。15分毎のcronによりRebindAllISCが実行されNVR510, OpenWrt, debian10, NVR500の順にprefixが委譲された状態に修正された。
PR-600MIのreconfigureは、OpenWrt, NVR500, NVR510の順に発行され、debian10には、発行されなかった。
PR-600MIのELOG.LOG : There are 100 entries.
  1. 2022/01/19 10:19:41 内線端末設定 内線登録[3]
  2. 2022/01/19 10:00:01 時刻の同期成功
  3. 2022/01/19 10:00:01 電話使用可能
  4. 2013/01/01 00:00:36 DHCPv6アドレス取得
  5. 2013/01/01 00:00:36 DHCPv4アドレス取得
  6. 2013/01/01 00:00:16 LANインタフェース(port4) リンクアップ
  7. 2013/01/01 00:00:14 LANインタフェース(port4) リンクダウン
  8. 2013/01/01 00:00:11 JavaVM active
  9. 2013/01/01 00:00:04 機器起動(code=0x08, WAN=RJ-45)
 10. 2022/01/19 09:59:01 機器再起動
 11. 2022/01/19 09:58:59 JavaVM normal stop


 

コメント
  • X
  • Facebookでシェアする
  • はてなブックマークに追加する
  • LINEでシェアする

ひかり電話 HGW PR-600MI DHCPv6-PDサーバーが再起動時に割り当てるPrefix

2021-12-17 11:00:00 | ひかり電話
ひかり電話 HGW PR-600MI のDHCPv6-PDサーバーが割当てるPrefixを制御する」の構成で、OpenWrtが「2409:10:XXXX:YY20::/60」と「2409:10:XXXX:YY30::/60」のprefixを委譲されるよう制御したが、「2409:10:XXXX:YY30::/60」をdebian10が委譲を受けるよう変更し、PR-600MI再起動時に受けるreconfigureメッセージを調べた。

(1)DHCPv6 Reconfigureメッセージ確認
2021年10月19日12時49分リブート時のreconfigureメッセージ

PR-600MIのPrefix-PD表示は、2409:10:XXXX:YY40, YY30, YY20, YY10の順でYY10が最新
reconfigureメッセージは、YY10のNVR510にだけ発行される。OpenWrt, debian10, NVR500には発行されない。

2021年10月19日23時52分リブート時のreconfigureメッセージ

PR-600MIのPrefix-PD表示は、2409:10:XXXX:YY20, YY30, YY40, YY10の順でYY10が最新
reconfigureメッセージは、YY10のNVR510,YY40のNVR500,YY20のOpenWrtの順に発行され、Debian10には発行されない。

2021年11月1日10時41分リブート時のreconfigureメッセージ

PR-600MIのPrefix-PD表示は、2409:10:XXXX:YY20, YY30, YY40, YY10の順でYY10が最新
reconfigureメッセージは、YY40のNVR500,YY10のNVR510の順に発行され、OpenWrt, debian10には発行されない。

2021年11月19日9時25分リブート時のreconfigureメッセージ
PR-600MIのPrefix-PD表示は、2409:10:XXXX:YY20, YY10, YY40, YY30の順でYY30が最新
reconfigureメッセージは、どのデバイスにも発行されなかった。

確認結果
PR-600MIのPDデータ変更を「DHCPv6 reconfigureメッセージ」だけで認識することが出来ない。
定期的に委譲されたprefixを確認し、変更されていたら再取得を行い、「DHCPv6 reconfigureメッセージ」を受けたら直ちにprefixの再取得を行う。
定期的確認は、cronを使い、reconfigureメッセージ確認は、syslogを集約し監視する事にする。

(2)DHCPv6-PDの取得制御

RebindAllISCスクリプト
ひかり電話 HGW PR-600MI のDHCPv6-PDサーバーが割当てるPrefixを制御する」の「RebindAllISC」に、必要な装置だけreleaseとrebindを行うように変更。

試行の結果、いくつかの不具合が発生した
・PR-600MIが委譲していないprefixに対してrelease実行をしないと指定した装置が期待しないprefix委譲を受ける不具合
・debian10でdhclientが二重に起動する不具合(releaseが不完全)
・OpenWrtのodhcp6cがprefix委譲を受ける前にdebian10がprefixを取得してしまいprefix順序が期待値にならない不具合

(あ)期待しないprefix委譲を受ける不具合対策
15行目から23行目で装置に委譲されるprefixが指定したprefixと一致しない場合は(委譲していない場合も含む)、releaseを実行するように変更
for i in $order
do
    if [ "${curdevprefix[${i}]}" != "${deviceprefix[${i}]}" ]; then
        releasedevice="$releasedevice ${devicename[${i}]}" 
        rebinddevice="$rebinddevice ${devicename[${i}]}"
        releasedevice=${releasedevice## }; rebinddevice=${rebinddevice## }
    fi
done

(い)dhclientが二重に起動する不具合対策
33行目から40行目でrelease後に、dhclientプロセスが終了していなければ、終了させる
for CL in $CID; do
    if [ "$CL" = "$ID3" ]; then
        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
            kill "$DHCLPID"
        fi
    else
        $DHCPV6CL -cf "$PTH/$CL.conf" -pf "$PTH/$CL.pid" -lf "$PTH/$CL.$IF.leases" $IF
        $DHCPV6CL -r -cf "$PTH/$CL.conf" -pf "$PTH/$CL.pid" -lf "$PTH/$CL.$IF.leases" $IF
    fi
done

(う)prefix順序が期待値にならない不具合対策
OpenWrtでは、「odhcp6c」がprefix delegationを担っている。
/etc/config/network
config interface 'wan6'                  
        option ifname 'eth1'             
        option proto 'dhcpv6'           
        option reqaddress 'try'         
        option reqprefix 'auto'         
        option clientid '00030001001d73344556'
-----------
odhcp6c -s /lib/netfid/dhcpv6.script -Ntry -P0 -t120 -c00030001001d73344556 eth1
で起動される。
clientidのdefault値は、LLTなのでLL指定する(PR-600MI指定)。LLTでもprefix delegationされるがタイム値が不明となるため、他デバイスからのreleaseが困難になる(OpenWrtは、default固定値。確か000000=2000/1/1 00:00:00UTCだったような・・・)。
「dhcpv6.script」の最後で「/etc/odhcp6c.user」ファイルをincludeするので、odhcp6cの状態をログに記録するよう設定している
/etc/odhcp6c.user
        case "$2" in
                bound|updated|unbound|rebound|informed)
                        logger -t "odhcp6c" -s "$2:$PREFIXES:$OPTION_1"
                ;;
                *)
                        logger -t "odhcp6c" -s "$2"
                ;;
        esac
PR-600MIが再起動するとreconfigureメッセージを送る(場合がある)。
「odhcp6c」は、reconfigureメッセージを受けると
・renewを行う(結果:status code 3 [NoBinding]
・rebindを行う(結果:status code 4 [NotOnLink]
・solicit/requestでprefix delegation取得を行う(prefixが取得されるとifdown/ifupが行われ処理時間が掛かる。WZR-HP-G300NHで約14秒位)
起動されている「odhcp6c」にprefixの再取得をさせるには、「SIGUSR1」を送る(OpenWrtがPR-600MIからprefixを得ている場合は、renewが成功する)。
XID=`ssh root@openwrt.familyname "ps | grep ' odhcp6c ' | grep -v grep | sed -e 's/^ *\([0-9]*\) .*$/\1/'"`
ssh root@openwrt.familyname kill -sigusr1 $XID
シグナル送信は、odhcp6cのprefix取得を待たない。
シグナル発行後、odhcp6cがrebindしdhcpv6.scriptでbound処理を実行し、odhcp6c.userでboundログを記録する。boundログを監視し、prefix取得を待つスクリプトを使い同期を取る事にした。
OpenWrtの/rootに
odhcp6c-bound
#!/bin/sh
kill -sigusr1 `ps | grep ' odhcp6c ' | grep -v grep | sed -e 's/^ *\([0-9]*\) .*$/\1/'`
TMP=`logread -l1 -e '^odhcp6c:' | grep ' updated:\| bound:' | sed -e 's/^.* \(.*:[0-9:/]*\),.*$/\1/'`
WL=0; CN=0
while [ -z ${TMP} ]; do
    if [ ${CN} -gt 20 ]; then break; fi
    sleep 1
    CN=$((CN += 1))
    if [ ${WL} -lt 10 ]; then WL=$((WL += 1)); fi
    echo -n "."
    TMP=`logread -l${WL} -e '^odhcp6c:' | grep ' updated:\| bound:' | sed -e 's/^.* \(.*:[0-9:/]*\),.*$/\1/'`
done
echo "done!"
を配置する。
「システム」「バックアップ/ファームウェア更新」「設定」の設定リストに「/root/odhcp6c-bound」と「/etc/odhcp6c.user」を設定し、再起動時の設定消失を防ぐ。
RebindAllISCの54行目から58行目を変更する
---- before ----
# rebind OpenWrt for #2
if echo -n $CID | grep "$ID2" >/dev/null; then
    ssh root@openwrt-wan.familyname ubus call network.interface.wan6 renew
    logger -s -t $0 "Bind #2($ID2)"
fi
---- after ----
# rebind OpenWrt for #2
if echo -n $CID | grep "$ID2" >/dev/null; then
    ssh root@openwrt-wan.familyname /root/odhcp6c-bound
    logger -s -t $0 "Bind #2($ID2)"
fi



 

コメント
  • X
  • Facebookでシェアする
  • はてなブックマークに追加する
  • LINEでシェアする

ひかり電話 HGW PR-600MI のDHCPv6-PDサーバーが割り当てるPrefixの変化を検出する

2021-10-23 09:00:00 | ひかり電話
PR-600MIのDHCPv6-PDサーバーが割り当てるPrefixが再起動などで変化する事がある。変化した場合、「ひかり電話 HGW PR-600MI のDHCPv6-PDサーバーが割当てるPrefixを制御する」で修正する事が出来る。変化の自動検出を考えてみる。


(1)検出と判定方法
・PR-600MIの「情報」「DHCPv6サーバ払い出し状況」の「IPv6プレフィックス」と「MACアドレス」を取り出して判定する
・NVR510が委譲されたPrefixを取得して判断する
・OpenWrt及びDebian10上で動作するシェルスクリプトで実現する

(2)スクリプト
(a)PR-600MIからPrefix情報を取得
GetPDInfo.sh( -rwxr-x--- someone root )
#!/bin/bash
nvr510="ac:44:f2:AA:BB:CC"
prefixes=`wget -q -O - http://pr600mi.familyname/ntt/information/dhcpV6Server | sed -e 's/\(<\/tr>\)/\1\n/g' | sed -n 's/^.*\([0-9a-zA-Z:\/]*\)<\/td>\([0-9a-zA-Z:]*\)<\/td>.*$/\1,\2/p'`
for i in $prefixes;
do
    if [ "${i%%,[0-9a-zA-Z:]*}" = "2409:10:XXXX:YY10:0:0:0:0/60" ]; then
        if [ "${i##[0-9a-zA-Z:/]*,}" = "$nvr510" ]; then
            echo "Good..bb10..NVR510..${i%%,[0-9a-zA-Z:]*}"
        else
            echo "NoGood..RebindAll.."
        fi
    fi
done
~/.wgetrc( -rw-r----- someone root )
http_user=user
http_password=JYUMONdeHIRAKU

(b)NVR510からPrefixを取得
ckNvr510prefix.sh( -rwxr-x--- someone root )
#!/bin/bash
pf=`wget -q -O - --post-data="show status ipv6 dhcp" http://nvr510-lan2.familyname/custom/api?password=JYUGEM | grep prefix | sed 's/ *prefix: //' | td -d "\r\n"`
while [ "$pf" = "" ]
do
    sleep 1
    pf=`wget -q -O - --post-data="show status ipv6 dhcp" http://nvr510-lan2.familyname/custom/api?password=JYUGEM | grep prefix | sed 's/ *prefix: //' | td -d "\r\n"`
   echo -n "."
done
if [ "$pf" = "2409:10:XXXX:YY10::/60" ]; then
    echo "Good..$pf"
else
    echo "NoGood..$pf"
fi

(3)スクリプト実行結果

NVR510のPrefix検出が良さそうだが、「2409:10:XXXX:YY10::/60」以外のPrefixに移行してしまうと他の機器からNVR510へ到達出来なくなる可能性が高い。PR600MIのLAN側に直接接続された機器からNVR510に委譲されているPrefixを取得確認し、「2409:10:XXXX:YY10::/60」以外であれば、再取得させるのが良さそうである。再取得は、「ひかり電話 HGW PR-600MI のDHCPv6-PDサーバーが割当てるPrefixを制御する」で行う。

(4)確認頻度の検討
PR-600MIのPrefix変更(NTT側から)が行われるとreconfigureメッセージが発行される。
PR-600MIが再起動した時にもreconfigureメッセージが発行される。
現在4つのPrefix委譲を受けているので、再起動時に全てのDHCPv6接続機器にreconfigureメッセージが発行されるはずだが、最後に委譲されたDHCPv6接続機器だけにreconfigureメッセージが発行される場合がある。
ただ、数回のテストで不確かであるが最後に委譲されたDHCPv6接続機器が最初にreconfigureメッセージを受けるようである。

全ての接続機器にreconfigureメッセージが確実に送られるのであれば、reconfigureメッセージを監視してprefixの確認を行うのが良さそうである。

nvr510が委譲を受けるprefix「2409:10:XXXX:YY10::/60」がホームネットワークの主で、その他はテストネットワークとなっている。nvr510が委譲されたDHCPv6接続機器となるよう定期的に制御すれば、再起動時に最低限の接続環境が確保されそうである。

さらに確認検討する事にする。

 


コメント
  • X
  • Facebookでシェアする
  • はてなブックマークに追加する
  • LINEでシェアする