はじめに
仕事でRHEL6.9を使って、rsyslogのTCPモードを使ってsyslog転送を行っていた。
そうしたら、とあるNWセグメントにて、rsyslogサーバのTCP:514のESTABLISHポートがどんどん増えて行く、という不可解な現象に遭遇した。
クライアント側では、宛先サーバに対するTCP:514のESTABLISHポートは4つしかない。この4つは想定内。
つまりrsyslogサーバ側でTCPハーフコネクションの状態になっているということ。
※クライアント側は4つTCPをはっているのに、サーバ側は100個以上コネクションをはっていると認識している
※このrsyslogサーバには単一クライアントからのsyslog転送しか受け付けていない
ちなみに1時間から2時間に1つ程度ESTABLISHポートが増えていく。大した数ではないが、塵も積もれば山となる。
結論から言うと、 中継経路に存在するFWとrsyslogのせい だったのだが、この記事はそういう話。
ESTABLISHって何？ハーフコネクション？？という方は下記を参考にして頂きたい。
とっても詳しく丁寧に説明して頂いているので、是非。
むしろ本記事は下記記事のおかげで事象解消につながったので、先に読んでおいたほうがわかりやすいかも。
tcpdumpとiptablesで理解するTCPのキープアライブ(TCP keepalive)
TCP keepalive設定でハーフコネクションを解消
何が原因？
中間に存在するFW(FortiGate)のコネクションアイドルタイマーによりTCPコネクションが強制切断されたが、サーバ側がそれを検知できなかったから。
まず前提として、FW(Fortigate)はデフォルト設定では、3600秒通信がなければ、こいつ無駄にコネクションはってやがんな？と認識して、TCPコネクションを強制的にぶった切ってくる。
でもって、このときTCPコネクションを乗っ取って、代理でFINかRSTを投げてくれたりなどしてクローズ処理を行うわけではないようだ。
※ごめんなさい、これは未確認です。だが、RSTかFINを投げてくれたら正常にクローズするので投げてくれてないはず。
そのため、サーバ側はTCPコネクションが既に切断されてしまっていることに気づかず、該当コネクションのポートをESTABLISH状態として維持する。
クライアント側も当然気づいてはいないのだが、何らかの通信が発生、今回の場合でいえばsyslog転送が行われたタイミングで、サーバ側からackが返ってこないので、TCPの再送を繰り返した上で、いずれポートがクローズする。
そして、また3ウェイハンドシェイクを行った上で新しくTCPコネクションを確立してsyslog転送を引続き実施する。
このため、クライアント側は想定した数のESTABLISHポートが存在し、サーバ側だけどんどんESTABLISHポートが増え続ける、という事態になってしまっていた。
今回の環境はそれほど頻繁にはsyslog転送が行われないので、このFWのありがた迷惑機能が発動した上で事象がたまに発生する状態が続いていたということになる。
※特にアクセス数が少ない夜間
ところで、強制的に切られたところで、TCP Keepaliveが機能していれば、必ず対抗との通信が途切れたことを認識してコネクションはクローズする。
なのでクライアント側もそうだし、サーバ側も普通はあまり問題にならない・・・が・・・ここにLinuxにおけるTCP Keepaliveの知られざる仕様がある。
いや、知られてないかどうかはわからないが、私と同じインフラエンジニアの中でも知らない人ちょいちょいいると思う。。。
私もお恥ずかしながらこの本事象に直面するまで知らなかった。
本質的な原因
で何かと言うと、普通TCP Keepaliveの設定を弄るときはLinux Kernelの設定を変更するわけだが、この設定を弄ったところで、そのとおりに動作する、というより、そもそもTCP Keepaliveを使ってくれるかどうかはアプリ次第、という仕様がある。
もう少し具体的に言うと、TCP Keepaliveの設定変更をするときは、下記設定を弄る必要がある。
net.ipv4.tcp_keepalive_time = 7200
net.ipv4.tcp_keepalive_probes = 9
net.ipv4.tcp_keepalive_intvl = 75
値はRHEL6.9におけるデフォルト値だ。
設定を読み解くとデフォルトでは、該当TCPコネクションにて7200秒無通信状態が続いた場合、TCP Keepaliveが動きはじめ、75秒間隔で9回実行して、失敗したらコネクションをクローズする、ということになる。
今回の環境におけるFW、FortiGateは3600秒無通信ならコネクションを切るので、これではTCP Keepaliveが動く前にFortiGateにコネクションを切られてしまう可能性が高い。
あーあ、なら設定変えてもっと短くすりゃいいじゃん。らくしょーらくしょーと思うかもしれない。私もそう思った。
が・・・そもそもTCP Keepaliveを使うかどうかはTCPポートを制御しているアプリの実装によるのだ。。。
いくらカーネルパラメータとしてどんな値があろうとも、それらを考慮した実装でなければ意味がない。
これについては、参考にさせて頂いたTCP keepalive設定でハーフコネクションを解消においても言及されている。
Remember that keepalive support, even if configured in the kernel, is not the default behavior in Linux. Programs must request keepalive control for their sockets using the setsockopt interface. There are relatively few programs implementing keepalive, but you can easily add keepalive support for most of them following the instructions explained later in this document.
manにも実は書かれている。知らなかった・・・
https://linux.die.net/man/7/tcp
tcp_keepalive_time (integer; default: 7200; since Linux 2.2)
The number of seconds a connection needs to be idle before TCP begins sending out keep-alive probes. Keep-alives are only sent when the SO_KEEPALIVE socket option is enabled. The default value is 7200 seconds (2 hours). An idle connection is terminated after approximately an additional 11 minutes (9 probes an interval of 75 seconds apart) when keep-alive is enabled.
でもって、 rsyslog v5はデフォルトではTCP Keepaliveを使用しない。
というか、デフォルトの話をするなら、それ以降のバージョンにおいても同じだ。
こちらの公式ドキュメントによれば、rsyslogの設定値として、TCP Keepaliveを司るものが存在する。
いくつかあるが、主要なものは以下。
$InputPTCPServerKeepAlive [on|off]
$InputPTCPServerKeepAlive_probes <number>
$InputPTCPServerKeepAlive_intvl <number>
$InputPTCPServerKeepAlive_time <number>
一番重要なのが、一番上の InputPTCPServerKeepAlive なわけだが、この設定がデフォルトでは オフ になっている。
つまり、rsyslogはデフォルトではTCP Keepaliveが使われていない状態になる。あーあ。
まぁそれならそれで、設定追加すりゃいいだけじゃん、となるかもしれないが、これもまた罠がある。
実はRHEL6系におけるデフォルトのrsyslogはv5なのだが、こいつにはTCP Keepalive機能が備わっていない。
上記ドキュメントの通り、正確にはオリジナルのrsyslog v5にはそういった機能が存在するが、RHEL版にはない。何故かは知らない。
なので、TCPサーバ機能を司る imptcpモジュール をロードして、該当機能を有効化しても実際にはエラーが出る。
※サービスの起動は失敗しない。 /var/log/messages にエラーログが吐かれて該当モジュールの該当機能が存在しない旨のログが載っている。
解決策
簡潔に言えば、TCP Keepalive機能が実装されている rsyslog v7をインストールすること
実はばっちりこの問題に該当するナレッジがRHEL公式にあがっている。
Why rsyslog imptcp module generates hung TCP connections ?
上記の通り、RHELのrsyslog v5にはTCP Keepaliveを実現する $inputtcpserverkeepalive 機能が存在しない。
記事では、imtcpモジュールをロードしているが、imptcpモジュールにおいても変わらない。存在しない。
※imtcpもimptcpもどちらもsyslogのTCP機能を提供するモジュールだが、imptcpのほうが高速とのこと。詳細は上で載せた公式ドキュメントを読んで欲しい。
そして、解決策も上記の通り、rsyslog v7をインストールこと。
rsyslog v7は実はRHELから公式に配布されている。外部リポジトリなどを追加する必要はない。
そしてrsyslog v7に入れ替えた後、 $InputPTCPServerKeepAlive を有効化する。
これでTCP Keepaliveが効くので、ハーフコネクション状態を検知して勝手にクローズしてくれるはずだ。
具体的な手順
# rpm -qa | grep rsyslog
rsyslog-5.8.10-10.el6_6.x86_64
# yum shell
> install rsyslog7
> remove rsyslog
> run
> exit
# rpm -qa | grep rsyslog
rsyslog7-7.4.10-7.el6.x86_64
rsyslogはcrontabやanacronと依存関係がある。
そのため、普通にyum remove rsyslog とやろうとすると、それらも削除を求められるため、ちょっと都合が悪い。
というわけで、 yum shell を使って、 removeとinstallを同時にやってしまう。 これで依存関係はクリアできる。
また、rpmパッケージ名は、rsyslog7 とv5とは少し違う名前になっているが、実際のバイナリとしてはrsyslogのままとなる。
でもって、一回消してしまっている関係で、自動起動などもオフの状態になっているのでオンにしておこう。
# chkconfig --add rsyslog
# chkconfig rsyslog on
# service rsyslog start
次にrsyslog.confの中に設定を追加する。
本当はrsyslog v7になると設定ファイルの書き方が変わるのだが、v5のときの書き方も使えるので、わかりやすく今回はv5のままでいく。
# 上部に下記を追加
$ModLoad imptcp
$InputPTCPServerNotifyOnConnectionClose on
$InputPTCPServerKeepAlive on
$InputPTCPServerRun 514
$InputPTCPServerNotifyOnConnectionClose って何じゃらほい？と思うかもしれないが、公式ドキュメントでは、下記のように書かれている。
Instructs imptcp to emit a message if the remote peer closes a connection. Defaults to off.
というわけで入れておいたほうが良い。
ここまで設定してrsyslogを再起動すれば、TCP Keepaliveが有効化されているはずである。
tcpdumpをかけてある一定時間待てば、length 0のパケットがrsyslogサーバ側から打たれていることが確認できる。
ex) tcpdump -i eth0 -n -vvv -A port 514
追加項目
TCP Keepaliveがオンになった上で、タイマーなどの各設定は基本的にカーネルの設定に依存するが、それぞれrsyslog側でも設定を記述できる。
rsyslog.confに記述がなければ、カーネル側の設定が反映される。
例えば下記の通り。
$InputPTCPServerKeepAlive_probes <number> #Keepaliveを送信する最大回数(この回数送信して失敗したらコネクションをクローズ)
$InputPTCPServerKeepAlive_intvl <number> #Keepaliveを再送信する間隔
$InputPTCPServerKeepAlive_time <number> #最初にKeepaliveを送信するまでの時間(最後に通信が流れたからのアイドル時間)
カーネル側の設定は再掲になるが、下記の通り。
net.ipv4.tcp_keepalive_time = <number>
net.ipv4.tcp_keepalive_probes = <number>
net.ipv4.tcp_keepalive_intvl = <number>
RHEL6.9のデフォルト値は下記の通り。
# sysctl -a | grep tcp_keepalive
net.ipv4.tcp_keepalive_time = 7200
net.ipv4.tcp_keepalive_probes = 9
net.ipv4.tcp_keepalive_intvl = 75
最終的にkeepalive_timeをどうするかは個々の環境次第だと思うので、ここでどうこう言わないが、rsyslogとしてTCP Keepaliveが有効化されたかどうかを確認するのに、7200秒(2時間)待つのはナンセンスだと思うので、適当に短い値にしてみて確認してみたほうが良いと思う。
ex) echo 60 > /proc/sys/net/ipv4/tcp_keepalive_time
もちろん恒久値にするならば、sysctl.conf側に記述しよう。
最後に
このTCP Keepaliveはアプリ側で制御できるということを割と最近まで知らなかったことを本当に悔やんでいる。
当たり前の如く、使ってるやろーｗ とか思ってしまっていた。本当にバカです。ごめんなさい。
とはいえ挙動としてはKeepaliveが動いていない感があったので、tcpdumpしてみたら、マジでKeepaliveが飛んできてなかった。
そして、はぁ？と思いつつ、いろいろ調べ試した結果、本記事のような内容になった。
ここまで呼んで頂いた方はわかっているとは思うが、この問題は他のアプリにおいても同じことが言えるし、同じような事象が起こりうる。
自分自身、開発するときには気をつけねば。。。
あ、ちなみにRHEL7系は最初からrsyslog v7が入っているので、単純にimptcpロードして$InputPTCPServerKeepAliveをonすれば良いだけっぽい。
試してはいないのでダメだったらごめんなさい。
参考
本記事内にも記載していますが、本事象を解決するにあたって参考にさせて頂いたWebサイトの一覧です。
特に下記qiitaの記事には本当に助けられました。本当にありがとうございました。