TL:DR;

• bash
  • 基本的にstdout, stderrを>で出力するのは悪手
  • 特段の理由がない場合は>>を使うべし
• copytruncateには罠がある
  • logrotateに関しては、想定の挙動をしているかどうか念入りに確認すべし

Background

bashシェルで起動するAPIサーバを運用している。
APIサーバ自体にログ出力機能が無いことから、bashシェルのstdout, stderrを>で拾ってログ出力していた。
イメージとしてはこんな感じ。

$ bash start-server.sh 1>/var/log/server/stdout.log 2>/var/log/server/stderr.log

このstdout.log、stderr.logをAWSのCloudwatch Logs Agentで回収する、という運用をしている。

ログファイルが肥大化するたびに、一時サーバを停止&再起動という形でログファイルをパージするという運用をしていたが、
さすがに無駄なのでlogrotateを仕込んでログファイルの肥大化を防ぐような対応を行った。

logrotate.conf

/var/log/server/stdout.log {
  rotate 7
  hourly
  missingok
  copytruncate
}

が、この対応を実施してから一日に一度、サーバのCPU使用量・メモリ使用量が急激に上昇し
レスポンスを応答できなくなる、という事態が発生した。。。

リソース逼迫の原因

問題のサーバを確認すると、Cloudwatch Logs Agentがリソースを大量に消費しており、それがAPIサーバの応答に影響を与えていた。
当初はAgentのバグかと思ったが、他サーバでは安定して運用できているし、フォーラムでも同様の問題にあたっている人が見えないように思えた。
途方に暮れていたが、よくよく見るとローテートされているはずのログサイズが、想定より遥かに多い。
一日に出力されるログが1GBであれば、一時間ごとのログサイズは50M以内に収まるはずだが、ローテートされているログサイズは雄に500Mを超えていた。 そこに来て初めてcopytruncateが効いていない説に思い当たった…。

なぜcopytruncateが効かないのか

的確に理由を示している質問をStackOverflowで見つけることができた。
Null bytes in a file created by 2> rotated with logrotate?

これによると、copytruncateの対象となるファイルは「O_APPEND」フラグ付きで開かれている必要があるらしい。
よくよく考えるとcopytruncateもファイルの内容をいじるので、そりゃそうだという話だった。。。

Solution

>>を使ってリダイレクトするように修正することで、一発で解決した。

$ bash start-server.sh 1>>/var/log/server/stdout.log 2>>/var/log/server/stderr.log

サーバのリソースも嘘のように安定するようになった。
思い込みは駄目だということと、ログに関わる部分はきちんと検証すべきということを（改めて）思い直した事件だった。