ヤマハ NVR510 / 500のsyslogをLinux rsyslogで受けた時の振る舞い

「ひかり電話 HGW PR-600MI DHCPv6-PDサーバーが再起動時に割り当てるPrefix」でPR-600MIのDHCPv6が発行するreconfigureメッセージをNVR500, NVR510, OpenWrtで受けたログをsyslogでDebian10サーバーに集約し監視する事にした。Debian10では、「rsyslog」が動作している。rsyslogで受け取ったNVR500/510のsyslogデータを処理中に意図しない動作があったため確認した。

（１）NVR510/500の設定
Debian10自身のログとNVR510/500のログを識別するためfacilityをlocal0に変更した（defaultは、user）。

NVR510/500のconfig
syslog host 192.168.1.57
syslog facility local0
syslog notice on
syslog debug on

WiresharkでキャプチャーされたNVR510から転送されたsyslogデータ


（２）Debian10のrsyslog設定
Debian10の初期設定から「514/UDP」でsyslogを受ける設定に変更する
NVR510/NVR500/OpenWrtに依存する設定を「/etc/rsyslog.d/」フォルダに「nvr510.conf」「nvr500.conf」「openwrt.conf」で設定した

/etc/rsyslog.conf
#### MODULES ####
module(load="imuxsock") # provides support for local system logging
module(load="imklog")   # provides kernel logging support
# provides UDP syslog reception
module(load="imudp")
input(type="imudp" port="514")
# provides TCP syslog reception
#module(load="imtcp")
#input(type="imtcp" port="514")
#### GLOBAL DIRECTIVES ####
$ActionFileDefaultTemplate RSYSLOG_TraditionalFileFormat
# Set the default permissions for all log files.
$FileOwner root
$FileGroup adm
$FileCreateMode 0640
$DirCreateMode 0755
$Umask 0022
# Where to place spool and state files
$WorkDirectory /var/spool/rsyslog
# Include all config files in /etc/rsyslog.d/
$IncludeConfig /etc/rsyslog.d/*.conf
### RULES ####
auth,authpriv.*			/var/log/auth.log
*.*;auth,authpriv.none		-/var/log/syslog
#cron.*				/var/log/cron.log
daemon.*			-/var/log/daemon.log
kern.*				-/var/log/kern.log
lpr.*				-/var/log/lpr.log
mail.*				-/var/log/mail.log
user.*				-/var/log/user.log
# Logging for the mail system.  Split it up so that
mail.info			-/var/log/mail.info
mail.warn			-/var/log/mail.warn
mail.err			/var/log/mail.err
# Some "catch-all" log files.
*.=debug;\
	auth,authpriv.none;\
	news.none;mail.none	-/var/log/debug
*.=info;*.=notice;*.=warn;\
	auth,authpriv.none;\
	cron,daemon.none;\
	mail,news.none		-/var/log/messages
# Emergencies are sent to everybody logged in.
*.emerg				:omusrmsg:*

/etc/rsyslog.d/nvr510.conf
:hostname,isequal,"nvr510-lan2.familyname"	/var/log/nvr510.log
& stop

「/etc/rsyslog.d」配下の設定「nvr510.conf」は、「/etc/rsyslog.conf」のRULESより前に処理されるので「nvr510-lan2.familyname」のログを「/var/log/nvr510.log」に記録後、「& stop」で処理が終了する。

（３）ログ確認と調査
WiresharkでキャプチャーされたNVR510の#3,#6のログが、「/var/log/syslog」「/var/log/messages」に記録されてしまう。
「nvr510.conf」で「& stop」が評価されず「*.*」や「*.=notice」の対象になるためと推定される。
RFC3164(The BSD syslog protocol)【日本語訳】によれば、ヤマハのsyslogメッセージは、Headderパートが無く「PRI部」に続き「MSG部」で構成されているようだ（YAMAHA RTX Syslog Formatでも分析例が報告されている）。

NVR510/500からのsyslogデータは、Debian10のrsyslogで受け取った後、受信した時刻（timegenerated）と送信ホスト（fromhost）でHeadder部を補完しRULES処理を行なっているようだ。

WiresharkでキャプチャーされたNVR510の#1,#2,#5は、PRI部の後が「[」で始まるためHeadder部の時刻もホスト名も無しとされ、受信した時刻、IP Src「192.168.1.51」から名前解決した「nvr510-lan2.familyname」のFQDNがホスト名として補完される（RFC5424相当）。
#3,#6のパケットは、PRI 部の後が「Rejected」「LAN2」がホスト名として認識される（hostname）。上記設定では、「nvr510.log」に記録されず、「*.*のsyslog」と「*.=noticeのmessages」に記録される。
#4のパケットは、PRI部の後が「TUNNEL[」であるため、ホスト名無しと認識される。また、MSG部（msg）で「TUNNEL」がタグ部（syslogtag）、「[1] Rejected」以下がコンテント部と認識される。

（４）対処
rsyslog設定プロパティで「hostname」で無く「fromhost」を使用する。

/etc/rsyslog.d/nvr510.conf
:fromhost,isequal,"nvr510-lan2.familyname"	    /var/log/nvr510.log
& stop

ホスト名「"nvr510-lan2.familyname"」は、resolverで名前解決できないと成立しない。DNSの不具合や停止などがあると名前解決出来ない。IPv4アドレス「"192.168.1.51"」やIPv6アドレス「"2409:10:XXXXYY00:ae44:f2ff:feaa:bbcc"」で指定する場合は、fromhost-ipプロパティを使用する。nvr510から受けるsyslogは、全て「/var/log/nvr510.log」に記録される。facilityをlocal0に指定せず、デフォルトのuserのままで良さそう。
特定のキーワードを含むsyslogデータを抽出するには

/etc/rsyslog.d/nvr510-picked-key.conf
:fromhost, isequal,"nvr510-lan2.familyname"	    /var/log/nvr510.log
if $fromhost == 'nvr510-lan2.familyname' and $msg contains 'DHCPv6' then {
user.*	    /var/log/nvr510-dhcpv6.log
stop
}
if ( $fromhost == 'nvr510-lan2.familyname' and $pri-text startswith 'user.' and $msg contains 'DHCPv6' ) then 	    /var/log/nvr510-dhcpv6.log
& stop
:fromhost, isequal,"nvr510-lan2.familyname"	    stop

line#2-#5とline#6-#7で同じ動作をする。line#8は、line#2-#7がマッチしないときの処理。

（５）その他
OpenWrtの送信するsyslogデータは、Headder部（timereported,hostname）が含まれている。ruleでhostnameにFQDN指定すると成立しない。ドメイン名を含まないホスト名指定が必要。大文字小文字も指定が必要（case sensitive）。

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

「ひかり電話 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メッセージを調べた。

（１）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を集約し監視する事にする。

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