TCP 接続で syslog サーバにログを送ると、syslog サーバが停止している場合、rsyslogd 本体が停止してしまう #rsyslog

メールシステムなど複数サーバからなるシステムを運用している場合、トラブルシュートを行う時に複数サーバの /var/log/ を横断検索するのは大変なので、

各サーバの /var/log/ にログは蓄積する
同時に、syslog サーバにもログを転送しておく

と設定をするのは、ごく自然な話だと思います。が、今回、その設定で痛い思いをしました。

192.0.2.17 で動作しているメールサーバ（Postfix や Dovecot が稼働）には、以下のように設定が書いてあり、同一サブネット内の syslog サーバ（192.0.2.65）だけでなく、遠隔地の syslog サーバ（198.51.100.65）にもログを転送しています。

/etc/rsyslog.d/forward-syslog.conf

mail.* @@198.51.100.65
mail.* @@192.0.2.65

遠隔地の syslog サーバ（198.51.100.65）が停電により停止していると、192.0.2.17 で動作している rsyslogd は、遠隔地の syslog サーバとの通信を開始しようと SYN パケットを送ったまま、そこで処理が止まってしまいます。

root@mx1:/local/tutimcadmin# netstat -nap | grep syslog
tcp        0      1 192.0.2.17:46698       198.51.100.65:514        SYN_SENT    11353/rsyslogd  
unix  5      [ ]         DGRAM                    1699971854 11353/rsyslogd      /dev/log
unix  5      [ ]         DGRAM                    1699971856 11353/rsyslogd      /var/spool/postfix/dev/log

すると、症状としては、/var/log/syslog に rsyslogd が再起動したよというログは残るのですが、Postfix や Dovecot などのログは一切 /var/log/mail.log に出てこないだけでなく、192.0.2.65 で動作している同一サブネット内の syslog サーバにも全くログが転送されないという状況になります。

/var/log/syslog

Aug 11 10:03:45 mx1 rsyslogd: [origin software="rsyslogd" swVersion="5.8.11" x-pid="11353" x-info="http://www.rsyslog.com"] start

Postfix は /dev/log に書き込みができない場合、SMTP セッションそのものは受け付けるのですが、その後、応答ができなくなってしまうらしく、/proc/net/nf_conntrack を調べてみると、ESTABLISH されているのに UNREPLIED なセッションが大量に存在しているという状態になります。

root@mx1:/local/tutimcadmin# cat /proc/net/nf_conntrack|grep ESTABLISHED|grep UNREPLIED|wc -l
1065
root@mx1:/local/tutimcadmin# cat /proc/net/nf_conntrack|grep ESTABLISHED|grep UNREPLIED|tail -1
ipv4     2 tcp      6 303348 ESTABLISHED src=192.0.2.17 dst=203.0.113.42 sport=25 dport=53413 [UNREPLIED] src=203.0.113.42 dst=192.0.2.17 sport=53413 dport=25 mark=0 zone=0 use=2

syslog に記録が出てこないため、トラブルシュート初期の段階で rsyslogd の動作は疑ったのですが、

rsyslogd のプロセスは存在している。
/var/log/syslog に rsyslogd が起動したというメッセージは出ている。
rsyslogd -N 1 と /etc/rsyslog.conf の文法チェックを行なってもエラーも警告も出ない。

という状況で、ネットワークやハードウェアなどより低レイヤーが原因となっている可能性を疑ったため、rsyslogd が原因であると辿り着くのに時間を要しました。

というわけで、 rsyslog-5.8.x を使って TCP 接続でログを送信する設定を行う場合は、十分な検証が必要です。
少なくとも rsyslog-8.4 ならば、TCP 接続および RELP 接続ともにタイムアウトして、rsyslogd 本体の機能は維持されるようなので、素直に rsyslog を更新したほうが良さそうです。

また、検証は相当に厄介そうです。まず、同一サブネット内の存在しないサーバを指定しても、上記の症状は再現できませんでした（停電中のサーバを指定すれば再現できる）。また、同僚の記憶によれば、2018年の停電時も同じ設定だったはずということなので、2018年には発生しなかったトラブルが何故2019年には発生したのか？の理由も不明のままです。