DockerCompose移行ログ転送と処理時間計測

前回ログ転送は作成しておいたログ転送用ネットワーク経由で実施することに決めた。既存アプリケーションもログ転送用ネットワークへ接続する方針とした。また、これに対応させるためDockerfileでのみ管理していたアプリケーションをDocker Composeに対応させたが、アプリ周辺の改修やシステム構成の調整がもう少し必要だったため、今回はそれらに対応する。

アプリケーションはバッチであり、CI/CDはhostサーバ上でbuildしたimageをcronで定期実行させる構成となっている。バッチアプリケーションの成功・失敗を通知させるため、cronから直接docker runコマンドでimageを起動させるのではなく、成功・失敗通知機能や、起動させたバッチアプリケーションがハングしていないかを監視する機能を盛り込んだシェルスクリプト経由で起動させている。今回はこのハング監視もdocker composeコマンドに対応させる。

やること

docker compose作成
起動スクリプトの修正

docker compose作成

作成したdocker composeファイルは前回の「アプリケーション: Dockerロギング・ドライバ導入」で作成したものとほぼ同じであるが、観点として「ログ転送を優先するか」「それともアプリケーション処理の実行を優先するか」の2択があった。今回ログはあくまで失敗時のデバッグ用との位置づけであり、最も優先するのはアプリケーションが処理を実行することと考えた。この観点を盛り込み修正した。そのため転送先のログ管理システムが停止している場合でも、ログ転送によってアプリケーション起動をブロックしないようmode: non-blockingを指定した。これにより、転送できないログは一度Docker側のバッファに保持され、接続できている間は非同期に転送される(blockingの場合は転送先と疎通できるまでアプリケーションは起動されない)。一応バッファを設定(max-buffer-size: 4m)しているため、疎通できない間もしばらくはロギングドライバ側でデータを保持できる。ただ、バッファサイズを超えた分のログは捨てられてしまうし、また、アプリケーションの処理完了後にdocker composeでコンテナを停止・削除した場合はその時点でバッファに保持されている未転送のログは破棄される恐れが高い。さらにアプリケーション起動時のブロックを避けるため、ログ転送用Fluent Bitへの接続はバックグラウンドで非同期に実施させるようfluentd-async: "true"を設定した。これでFluent Bitと接続できなくともアプリケーションの処理を優先する構成になった。 docker composeを使うことで、ロギングドライバのfluentdが転送する宛先である、自前で構築したログシステム上のFluent Bitをサービス名で指定可能になった。便利ッ

修正した docker-compose.yml

services:
  sample-app:
    build:
      context: ../..
      dockerfile: etc/docker/Dockerfile
    image: docker-sample-app
    networks:
      - shared-log-network
    logging:
      driver: fluentd
      options:
        fluentd-address: fluent-bit:24224
        tag: sample-app
        mode: non-blocking
        max-buffer-size: 4m
        fluentd-async: "true"

networks:
  shared-log-network:
    external: true

起動スクリプトの修正

もともと起動スクリプトのアプリケーションのハング対策は、timeoutコマンドでコンテナを起動させ、成功・失敗は終了ステータスを確認する簡単な仕組みで実装していた。(詳しくはwebスクレイピング inコンテナ)

修正前

# コンテナ実行開始時刻を記録
START_TIME=$(date +%s)

# タイムアウト（秒）- 長時間応答がない場合に強制終了
TIMEOUT=3600  # 1時間

# Dockerコンテナを実行（タイムアウト付き）
timeout ${TIMEOUT} docker run --rm -v "${DOWNLOAD_DIR}:/app/result" "${DOCKER_IMAGE}" > /dev/null 2>&1
EXIT_CODE=$?

# 実行時間を計算
END_TIME=$(date +%s)

修正後

結論紆余曲折あり、起動スクリプトのハング対策及び成功・失敗判定処理はバックグラウンドで起動、waitで特定サービスが終了するまで待機し処理時間を算出する下記構成となった。

# コンテナ実行開始時刻を記録
START_TIME=$(date +%s)

# タイムアウト（秒）- 長時間応答がない場合に強制終了
TIMEOUT=3600  # 1時間

# 古いコンテナを削除してからComposeで実行（タイムアウト付き）
# ※ビルドは行わず、事前にbuildされたイメージを使用する
# ハングしたコンテナが残っているかもしれないため、念の為古いコンテナを削除してから実行する
docker compose -f "${COMPOSE_FILE}" down > /dev/null 2>&1

# docker compose up自体はバックグラウンド実行し、終了待ちはdocker compose waitで実施
docker compose -f "${COMPOSE_FILE}" up -d > /dev/null 2>&1

# sample-appコンテナが正常に終了するまで待機（最大TIMEOUT秒）
timeout ${TIMEOUT} docker compose -f "${COMPOSE_FILE}" wait sample-app
EXIT_CODE=$?

# Dockerデーモン側にログバッファを持たせている。
# downを直後に実行すると未転送ログが失われる可能性があるため、少し待ってから停止する
sleep 5
docker compose -f "${COMPOSE_FILE}" down > /dev/null 2>&1

# コンテナ実行完了時刻を記録
END_TIME=$(date +%s)

起動スクリプトの修正で詰まったもろもろ

timeoutコマンドでdocker compose upできない

一番の問題はdocker compose upではtimeoutコマンドを使用できなかった点である。もともと処理時間の計測はtimeoutコマンド経由でdocker runをフォアグラウンドで動作させ、そのまま終了するまでの処理時間を前後の時刻から計測させていた。単に起動コマンドをdocker compose upに変えるだけでは、imageのcreateまでは進むがその後コンテナが起動せずハングしてしまった。

timeoutコマンドとdocker composeコマンドは相性が悪い

timeoutコマンドは後続のdocker composeコマンドを子プロセスとするため、どうやらDockerと標準出力先のTTY(擬似端末)とのやり取りの間にtimeoutコマンドが挟まる構造となり、DockerがTTYと接続できていないと判断し処理がハングしてしまった。のかもしれない。よくわからないが。一旦-dオプションを付けバックグラウンドで動作し標準出力にログを出力させなくしてみたが、状況は変わらず結局同じ箇所でハングしてしまった。つまりtimeoutを介すためDockerがTTYと接続できない説が、説得力を持たなくなってしまった。。。ログが無いことには深入りして調査することもできないため、timeoutコマンドとdocker composeコマンドは相性が悪いとだけ理解しtimeoutは別の方法で実装することにした。

docker compose waitで実行時間を計測

docker compose wait サービス名にて対象サービスが正常終了するまで待機してくれるてくれるので、コマンド前後の時刻を持っていれば処理時間を計測可能であることが分かったためコレを使うことにした。ただハングした場合、一生待機してしまうためtimeoutコマンドでラップすることにした。これで対象サービスの処理時間が前後の時刻から算出可能となり、また、timeoutで指定した時間内に終了しない場合はdocker compose waitを終了させ、後続のdocker compose downで強制終了可能となった。

docker compose の成功/失敗を何で判断するのか

docker composeは複数のコンポーネントを統合的に管理するため、何を持ってこのdocker composeが正常終了したのか判断できない。docker compose up -dの終了ステータスはコンポーネントを立ち上げられたかしか意味しない。ただ、ちょうどdocker compose wait サービス名で対象サービスの終了コードが取れるため、これをアプリケーション全体の成功/失敗の判断基準とした。いくつかコンポーネントが立ち上がるが、メインの処理を担っているのは1つのコンポーネントなのでたまたまこの方法が成立した。

ログ転送をどの程度保証するのか

基本方針としてアプリケーション処理が正常終了することを最優先とし、ログの転送は補助的なものと位置づけた。docker compose wait終了直後にdocker compose downしてしまうと、コンテナのライフサイクルと同期しているロギングドライバ側の未転送ログも失われる可能性がある。mode: non-blockingを指定しているため、ログ転送先が利用不能でもアプリケーションは継続できるが、その代わりログ欠落の可能性は受け入れる必要がある。対象サービスの正常終了確認後、即downによるログ消失の恐れが大きいため、暫定的にdocker compose downは5秒遅らせて実行することにした。この5秒には強い根拠があるわけではなく、あくまで運用上の妥協案である。バッファが空になったことを確認してからdownできるのが理想だが、そのための簡潔な手段を見つけられなかったため、今回はsleepで対処した。

その他

バックグラウンド起動でログは転送されるのか

-dオプションでバックグラウンド動作としたがログはDockerのロギングドライバに拾われ転送されるのかちょっと疑問に思った。結論ちゃんと拾われて転送された。Dockerデーモンも起動したコンテナアプリケーションにおける標準出力の接続先として待ち受けているためちゃんと拾われるらしい。ついでに-dを外すと、標準出力の接続先にTTYも加わる挙動となるらしい。