capistrano-sidekiq でインストールされる systemd 制御ファイル入れた時のロギングについて、CentOS7 あたりだと対応できないので、その対応について。

何が問題なのか

このあたりで書いた問題ですね。

donbulinux.hatenablog.jp

syslog を利用する

append による追記処理が利用できないので、 syslog に流して logrotate で処理するよう設定します。

変更したら daemon-reload してから sudo systemctl restart sydekiq しておいてください。

systemd ファイルを修正

sidekiq:install タスクを利用していると、 /etc/systemd/system/sidekiq.service に標準ファイルが設置されるので、以下のように変更します。

-StandardOutput=append:/var/www/example/shared/log/sidekiq.log
-StandardError=append:/var/www/example/shared/log/sidekiq.error.log
+StandardOutput=syslog
+StandardError=syslog

# これは標準記述されているままにしておく
SyslogIdentifier=sidekiq

syslog を設定する

/var/log/messages 見てるとわかると思うのですが、ログ位置行ごとに識別子のようなものが付与されていると思います。これが SyslogIdentifier で指定できるヤツです。

特定の識別子を持つログは、指定したファイルに書き出すように設定します。

ちなみに syslog と連呼していますが、 RHEL(CentOS) 7 以降は rsyslog という名前になっています。 /etc/rsyslog.d/ 以下に .conf ファイルを設置すると読み込むようになるので、そちらにファイル設置します。

設置後は rsyslog の再起動を行って設定ファイルを読み込ませておきます。

sudo vi /etc/rsyslog.d/sidekiq.conf
sudo mkdir -p /var/log/sidekiq/
# ec2-user 権限で動かしているのでログ出力先もそのようにしています、Rails アプリを動かすユーザに合わせて変更してください
sudo chown ec2-user:ec2-user /var/log/sidekiq/
sudo systemctl restart rsyslog

/etc/rsyslog.d/sidekiq.conf

if $programname == 'sidekiq' then /var/log/sidekiq/sidekiq.log
& stop

logrotate を設定する

このままだと /var/log/sidekiq/sidekiq.log が肥大化するので、ローテートするようにします。

以下の logrotate 用設定ファイルは、だいたいこのような感じです。

ec2-user ユーザの 0644 (-rw-rw-r--) でファイルを処理
日毎にローテート
30 世代保持
圧縮する
sidekiq.log-20210711 のように日付を付与する
空ファイルならローテートをスキップする
圧縮する対象は 3 世代目から (当日と前日にあたる 2 世代までは生ファイルとなる)
ローテート時ファイルポインタを開放しない

logrotate はデーモンではなく cron で発火するので、ファイル設置したらそこで終わりです。

/etc/logrotate.d/sidekiq

/var/log/sidekiq/sidekiq.log {
  su ec2-user ec2-user
  daily
  rotate 30
  compress
  dateext
  missingok
  notifempty
  sharedscripts
  delaycompress
  create 0664 ec2-user ec2-user
  copytruncate
}

sidekiq のログ再オープンは USR2 シグナル、ではありません！

どこもかしこも USR2 シグナルを送信しろ、と書いてあったのですが、最初に公式ドキュメントを読んでいたので記述が違って「ああーん？」となったやつ。

qiita.com

こちらにわかりやすく書いてあるのですが、公式もおそらく「ログドライバってやつがあるんだからそっちを使え、俺はもう面倒を見ねえ」って事だと思います。

とはいえ金払う有償版？だと USR2 で従来どおりの動作らしいとのことなので、まあハイ、という気持ちになってしまう。

ジョブの流入カットして、おそらく処理が終わるであろうタイミングでプロセス止めてファイルローテートして新規再開、はたしかに理想的なのですが、今回自分が導入した環境は以下のような状態でした。

短時間 (< 60s)で終了するキュー
- メール送信など
長時間 (> 60s) 必要なキュー
- ユーザデータの export と xlsx などの加工まで含むトランザクション

長時間のキューが入ってるタイミングだと事故る、かつ sidekiq はたしか実行途中のキューが存在すると、最後まで終了しない限りプロセス再起動で処理済みのキューも再実行する、とかだった気がします。

ソースどこだったか忘れたんですが、マー実際発生しそうだし発生するとクレームボンバーでヤバいな、という感じだったので「それならログ欠ける方がマシだろ、 Rails 側の production.log にも一応履歴出てるはずだし」という判断で copytruncate しています。

環境に応じて、としか言えないのですが、今の所 copytruncate で致命的にログがぶっ壊れたり取りこぼしした事ないので、おそらく大丈夫じゃないかなあ、と考えています。

参考