rabbit51

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

ひかり電話 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」で確認）。


（１）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を実行する

（２）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メッセージである事が確認される。

（３）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が割り当てられているか確認する事とする。

（４）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メッセージを確認することが目的なので問題無し。

（５）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


（６）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

（７）結果
事例１（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指定実行を確認した。

事例２（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でシェアする
« ヤマハ NVR510 / 500のsyslog... | トップ | Dyson DC62の充電不良と電池交換 »
最新の画像［もっと見る］

コメントを投稿

ブログ作成者から承認されるまでコメントは反映されません。

「ひかり電話」カテゴリの最新記事

カレンダー

2024年8月
日 月 火 水 木 金 土
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

カテゴリー

アクセス状況

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

バックナンバー

  • RSS2.0