SSSD の子プロセスが WATCHDOG で停止後、OOM-Killer で mysql が停止

先日、WordPress編集中に保存ができなくなり、Lightsail のCPUクレジットが80%を切ったとアラートが飛んできました。「そんなはずは・・」と思い、Linuxサーバーへ接続を試みたところ、SSH認証まで進むものの、ログインはできません。本サイトも編集機能だけではなく動いていない模様です。
環境：Rocky Linux 8

Lightsailのコンソールから再起動／停止

Lightsail のコンソールを開くと確かに、CPU 使用率が見たことないほど上がり、クレジットを消費していました。SSH で接続できないため、Lightsail のコンソールから「再起動」を実施ししばらく待つも、復旧しませんでした。

仕方がないので、Lightsailのコンソールから「停止」を実行。しばらくして停止が完了しました。再度、Lightsailコンソールから「起動」すると、何事もなかったかのように動き始めました。

一時復旧

WordPressで保存できなくなった頃のログを確認したところ、問題がありそうなものは以下のようです。

Sep 25 23:13:01 hostname sssd[785]: Child [19852] ('nss':'nss') was terminated by own WATCHDOG. Consult corresponding logs to figure out the reason.
Sep 25 23:14:19 hostname sssd[785]: Child [19833] ('implicit_files':'%BE_implicit_files') was terminated by own WATCHDOG. Consult corresponding logs to figure out the reason.

この時は、とりあえず、nss(sssd_nss) と implicit_files(sssd_be) が、SSSD(System Security Services Daemon) の子プロセスのようだということで、面倒くさそうなので、様子見をかねて放置しました。
ただ、WordPress 編集中に保存ができなくなった後で通知が来たことを考えると、バーストキャパシティの監視だけでは通知タイミングとして遅いかなと感じましたので、CPU 使用率も合わせて監視を開始しました。

再発・過去にも

3日後、CPU 使用率の警告が来ました。青が前回、赤が今回です。早速、確認したところ上記の様なログが再発生しました。

時々、このくらいCPUを使用していることは把握していましたが、不正アクセスなんかが集中しているのかな？くらいに思っていました。いったん、過去のログも含め確認・調査したところ気が付いていなかっただけで、不定期に発生しているようです。

詳細なログをチェック

たまたまとかではないので、詳細にみていくことにしました。
CPU 利用率が高まったと連絡があった時刻のログ。前回同様ですね。

Sep 29 01:13:08 hostname sssd[787]: Child [823] ('nss':'nss') was terminated by own WATCHDOG. Consult corresponding logs to figure out the reason.
Sep 29 01:21:31 hostname sssd[787]: Child [817] ('implicit_files':'%BE_implicit_files') was terminated by own WATCHDOG. Consult corresponding logs to figure out the reason.

その後、oom-killerにより、DBプロセスが停止される。これによりサーバー負荷（WordPress）は自動復旧。（前回は、Lightsail のコンソールから停止・起動）

Sep 29 01:31:18 hostname kernel: Out of memory: Killed process 953 (mysqld) total-vm:1335420kB, anon-rss:10960kB, file-rss:0kB, shmem-rss:0kB, UID:27 pgtables:852kB oom_score_adj:0

確かに当時の SA を確認してもメモリがかなり不足していそうです（01:04-01:30 の間の記録が飛んでしまっています。）

過去のログを oom-killer で確認したところ、同様に sssd のエラーの後に oom-killer により、mysqld が停止させられていました。

しかし、sssd_nss.log や sssd_implicit_files.logや mariadb.log のログを確認したところ、それっぽいものは、oom-killer 後のログしか残っていませんでした。

/var/log/sssd/sssd_nss.log

sssd_nss の方は、以下の様なログでunixソケットの接続に失敗してそうです。通常起動時には出ていません。

(2022-09-29 1:31:08): [nss] [sbus_dbus_connect_address] (0x0020): Unable to connect to unix:path=/var/lib/sss/pipes/private/sbus-dp_implicit_files [org.freedesktop.DBus.Error.NoServer]: Failed to connect to socket /var/lib/sss/pipes/private/sbus-dp_implicit_files: Connection refused

/var/log/sssd/sssd_implicit_files.log

sssd_be の方は、nssで問題が起きているため接続タイムアウトが発生してそうです。こちらも通常起動時には出ていません。

(2022-09-29 1:31:19): [be[implicit_files]] [dp_client_handshake_timeout] (0x0040): Client [:not.active.yet] timed out before identification [0x5568b1e27fd0]!

/var/log/mariadb/mariadb.log

mysql の方は、oom-killer 後の起動時に以下のエラーが起きています。これは、通常起動時にも出ていました。

2022-09-29 1:31:42 0 [ERROR] mysqld: Server GSSAPI error (major 851968, minor 2529639093) : gss_acquire_cred failed -Unspecified GSS failure. Minor code may provide more information. Keytab FILE:/etc/krb5.keytab is nonexistent or empty.
2022-09-29 1:31:42 0 [ERROR] Plugin 'gssapi' init function returned error.

まとめ・処置

どのログにも、問題がおき始めた 01:03-04 ごろのログは無し。SSSD の子プロセスが WATCHDOG で停止した直接原因、oom-killer が出た原因がいまいちわかりません。単純に考えると mysql がメモリを食いすぎて、メモリ不足になっただけのようにも思えますが、アクセスの多い時間帯ではないため、単純なメモリ不足は少し考えづらいです。ただ、oom-killer が動く前に、sssd の子プロセス（sssd_nss、sssd_be)が、WATCHDOG で停止していることを鑑みて、以下のような処置をしました。