2025.04.22

Apacheエラー「ScriptSock does not exist」との格闘記：原因は深夜のlogrotate設定

こんにちは。植松です。先日、管理しているウェブサーバーで少し厄介なトラブルに遭遇しました。ある日突然、特定のCGI（今回はMovable Typeでした）を利用するページでサーバーエラーが発生するようになりました。エラーログには見慣れないメッセージが。今回は、そのエラーの原因特定から解決までの一部始終を備忘録としてまとめたいと思います。

謎のエラー「ScriptSock does not exist」

まず確認したのは、Apacheのエラーログ (/var/log/httpd/error_log) です。そこには、問題が発生している時間帯に以下のエラーが繰り返し記録されていました。

[Sun Apr 20 03:25:21.347699 2025] [cgid:error] [pid 89370:tid 139976289228544] (2)No such file or directory: [client XXX.XXX.XXX.XXX:XXXXX] AH02833: ScriptSock /etc/httpd/run/cgisock.728 does not exist: /path/to/mt.cgi

cgid:error とあるように、Apacheの mod_cgid モジュールが出しているエラーのようです。mod_cgid はCGIスクリプトを実行するためのモジュールで、メッセージによると ScriptSock (スクリプトと通信するためのソケットファイル) である /etc/httpd/run/cgisock.728 が存在しない、と言っています。

確かに /run/httpd/ ディレクトリを確認すると、そのファイルが見当たりません。これが原因でCGIが実行できないのは間違いなさそうです。でも、なぜ突然このファイルが消えてしまったのでしょうか？

原因調査の旅

1. 消失時刻の特定

エラーログをさらに遡ると、この ScriptSock ... does not exist エラーが最初に出現したのは 4月20日(日) の午前3時25分頃であることがわかりました。サーバー自体は4月12日に起動・以降再起動や停止はしておらず、MTについては少なくとも4月17日までは正常に動作していたことが確認できています。

日曜日の早朝3時台... システムの定期処理が動く怪しい時間帯です。

2. systemd-tmpfiles の疑い

/run ディレクトリは一時ファイルが置かれる場所であり、systemd-tmpfiles という仕組みで管理されていることがあります。もしかして、設定ミスで自動的に削除されたのでは？と考え、設定ファイルを確認しました。

cat /usr/lib/tmpfiles.d/httpd.conf
ls -la /etc/tmpfiles.d/

しかし、関連する設定ファイル (/usr/lib/tmpfiles.d/httpd.conf) には削除するような記述はなく、管理者が独自設定を追加する /etc/tmpfiles.d/ ディレクトリは空でした。systemd-tmpfiles が原因である可能性は低いと判断しました。

3. 監査ログ(auditd) の確認

次に、ファイルが「いつ」「誰に/何に」削除されたかの記録が残っていないか、auditd のログを確認することにしました。

ausearch -ts 04/17/2025 00:00:00 -te 04/20/2025 03:26:00 -sc unlink -i
ausearch -ts 04/17/2025 00:00:00 -te 04/20/2025 03:26:00 -sc unlinkat -i
ausearch -ts 04/17/2025 00:00:00 -te 04/20/2025 03:26:00 -sc rmdir -i

結果はすべて <no matches>。該当する記録はありませんでした。さらに auditctl -l を実行すると、

No rules

監査ルールが設定されていませんでした。これではファイル削除を追跡できるはずがなく、調査は振り出しに戻ったかに思えました。

再びApacheエラーログへ

auditd からの手がかりが得られなかった以上、最も信頼できるのはやはりApacheのエラーログです。エラーが最初に出始めた4月20日午前3時25分の少し前、午前3時15分頃のログを、今度はもっと注意深く見直してみました。すると...

[Sun Apr 20 03:15:02.337387 2025] [mpm_event:notice] [pid 728:...] AH00493: SIGUSR1 received.  Doing graceful restart
... (約3秒後) ...
[Sun Apr 20 03:15:05.360061 2025] [mpm_event:notice] [pid 728:...] AH00493: SIGUSR1 received.  Doing graceful restart
... (約3秒後) ...
[Sun Apr 20 03:15:08.390226 2025] [core:notice] [pid 728:...] AH00094: Command line: '/usr/sbin/httpd -D FOREGROUND'
[Sun Apr 20 03:15:08.393105 2025] [cgid:error] [pid 89125:...] (98)Address already in use: AH01243: Couldn't bind unix domain socket /etc/httpd/run/cgisock.728
[Sun Apr 20 03:15:09.396280 2025] [cgid:crit] [pid 728:...] AH01238: cgid daemon failed to initialize

4/20、午前3時15分頃に、わずか6秒間で3回もの graceful restart が実行されていました。そしてその直後に Address already in use (ソケットが使用中) エラー、続けて cgid daemon failed to initialize (cgid 初期化失敗) エラーが発生していました。

原因はlogrotateの設定

短時間に複数回の graceful restart がかかると、古いプロセスがソケットファイルを解放する前に新しいプロセスが掴もうとして競合が発生し、mod_cgid が正常に初期化できなくなることがあります。その結果、ソケットファイルが利用できなくなり、「ScriptSock does not exist」エラーにつながったと考えられます。

では、なぜ連続リスタートが発生したのか？疑うべきは、この時間帯に実行される可能性が高い logrotate です。設定を確認します。

cat /etc/logrotate.d/httpd
ls -la /etc/logrotate.d/

すると、メインの httpd 設定ファイルに加え、バーチャルホストごとに httpd-vhost-*.conf という設定ファイルが多数存在しました。そして、それぞれのファイルの中身を確認すると...

# /etc/logrotate.d/httpd の中身 (一部)
postrotate
    /bin/systemctl reload httpd.service > /dev/null 2>/dev/null || true
endscript

# /etc/logrotate.d/httpd-vhost-xxx.co.jp の中身 (一部)
postrotate
    /bin/systemctl reload httpd.service > /dev/null 2>/dev/null || true
endscript
# 他の vhost ファイルも同様...

メインの設定ファイルだけでなく、各バーチャルホストの設定ファイルにも Apache を reload する記述がありました。logrotate は /etc/logrotate.d/ 内のファイルをすべてチェックするため、Apache関連のログが複数ローテーション対象になると、その数だけ reload コマンドがほぼ同時に実行されていたのです。これが連続リスタートの原因でした。

解決策

原因がわかれば対策は明確です。logrotate 実行時に reload が1回だけ実行されるようにします。今回は、メインの /etc/logrotate.d/httpd ファイルに sharedscripts オプション（既にありました）が設定されていることを利用し、他のすべての httpd-vhost-*.conf ファイルから postrotate セクションをコメントアウトしました。（セクションはコメントアウトではなく削除でもOKです）

 /var/www/html/xxx.co.jp/httpd_log/*log {
     missingok
     notifempty
     sharedscripts
     delaycompress
#    postrotate
#        /bin/systemctl reload httpd.service > /dev/null 2>/dev/null || true
#    endscript
 }

すべてのバーチャルホスト用設定ファイルに対してこの修正を行いました。念のため logrotate -d /etc/logrotate.conf でデバッグ実行し、意図した動作になりそうかを確認しました（この時点ではローテーション対象ログがなかったため、reloadのシミュレーションまではできませんでしたが、設定は正しく読み込まれていました）。

まとめと教訓

今回の障害は、「ソケットファイルがない」というエラーから始まりましたが、その根本原因は logrotate の設定不備による Apache の連続リスタートと、それに伴う mod_cgid の初期化失敗でした。

エラーログは細部まで見る: 最初のエラーだけでなく、その前後のログに重要なヒントが隠されていることがある。
設定の相互作用を意識する: 個々の設定は正しくても、複数の設定が組み合わさることで意図しない動作を引き起こすことがある。特に自動化された処理は要注意。
地道な切り分けが重要: systemd-tmpfiles や auditd など、可能性のある要因を一つずつ潰していくことが解決への近道。

今回の経験が、どこかの誰かの助けになれば幸いです。

ITブログの一覧に戻る