1

質問内容

  • print関数を使用して標準出力に書き出されたログが、ECSタスクが実行終了されるまで書き込まれない(ログストリームが作成されない)原因は何だと考えられますか?
    • 後述の検証にて、logging.StreamHandlerを使用したログ書き出しではログが即時書き込まれることを確認しています。

アプリケーションと基盤設定の概要

Amazon ECS + Fargateの構成で、Pythonのアプリケーションを実行しています。
ECSタスクのログドライバーにawslogsを設定しており、CloudWatchLogsにログを書き込むように設定しています。
コンテナ内で実行されるPythonコードは、print関数を使用して、ログ出力を行っています。

発生した事象

ECSタスクを実行すると、出力先のロググループにログストリームが作成されません。
ECSタスクの実行が完了されたタイミングで、ログストリームが作成され、ログが保存されました。

仮説

print関数を使用してログを書き出しているアプリケーションの他に、loggingモジュールのロガーを使用してログを書き出しているアプリケーションも存在しており、こちらについては即時ログストリームが作成され、ログが保管されます。
ロガーには、logging.StreamHandlerインスタンスを渡しています。

import time
from logging import INFO, Formatter, StreamHandler, getLogger

logger = getLogger()
logger.setLevel(INFO)

if not logger.hasHandlers():
    handler = StreamHandler()
    logger.addHandler(handler)

    formatter = Formatter(
        '[%(levelname)s]\t%(asctime)s\t%(message)s\n',
        '%Y-%m-%d %H:%M:%S'
    )

    for handler in logger.handlers:
        handler.setFormatter(formatter)

logger.info('開始')

print関数とlogging.StreamHandlerで書き込む際の動きが違う可能性があると思っています。

検証したこと

以下の2つの Pythonコードを、ECS+Fargateの構成にデプロイし、タスクを実行してみました。
なお、両タスクで使用しているDockerfileは共通のものです。

FROM python:3.9

COPY main.py main.py

CMD ["python", "main.py"]

1.print関数を使用したログ書き出し

import time
from datetime import datetime


def log(log: str):
    print(f'{datetime.now():%Y-%m-%d %H:%M:%S} {log}')


log('開始')

for _ in range(20):
    time.sleep(10)
    log('tick')

log('終了')

2.logging.StreamHandlerを使用したログ書き出し

import time
from logging import INFO, Formatter, StreamHandler, getLogger

logger = getLogger()
logger.setLevel(INFO)

if not logger.hasHandlers():
    handler = StreamHandler()
    logger.addHandler(handler)

    formatter = Formatter(
        '[%(levelname)s]\t%(asctime)s\t%(message)s\n',
        '%Y-%m-%d %H:%M:%S'
    )

    for handler in logger.handlers:
        handler.setFormatter(formatter)

logger.info('開始')

for _ in range(20):
    time.sleep(10)
    logger.info('tick')

logger.info('終了')

検証結果

1.print関数を使用したログ書き出し

ECSタスクの実行が完了したらログストリームが作成され、ログが保管される

2.logging.StreamHandlerを使用したログ書き出し

ECSタスクの実行中にログストリームが作成され、ログが保管される

環境情報

  • python: 3.9
  • Fargate プラットフォームバージョン: 1.4.0
  • ECSタスクオペレーティングシステム/アーキテクチャ: LINUX/-

2024/01/18 追記

追加で2点検証しました。

結論:両方とも、ECSタスクの実行中にログストリームが作成され、ログが保管される

1.1 print関数の引数に、flush=Trueを追加

print('hello', flush=True)

1.2 print関数の引数に、file=sys.stderrを追加

print("hello", file=sys.stderr)

@oriri san
@jackson san
コメントいただきありがとうございます。

結論

検証結果から、以下の結論を得た。

  • print関数のデフォルトの動作は、sys.stdoutに出力されるようになっているが、標準出力はバッファリングを有しているため、バッファが開放されたタイミングでCloudWatchLogsに転送される。
  • 一方、sys.stderrは、バッファリングされないため、CloudWatchLogsに即時転送される。
  • logging.StreamHandlerのデフォルトの出力先はsys.stdeerrのため、CloudWatchLogsに即時転送される。
4
  • 1
    print('hello', flush=True) のようにオプション付けるとどうなりますか?
    – oriri
    Commented 1月12日 3:36
  • StreamHandlerのデフォルトの出力先はstdoutではなくstderrのようですが、print("hoge", file=sys.stderr)のようにするとどうなるでしょうか?
    – jackson
    Commented 1月12日 4:10
  • @oriri コメントありがとうございます。 提案された内容で検証したところ、タスクの実行中にCloudWatchLogsにログが保管されました。 検証内容は質問本文に追記しました。
    – shimomoclo
    Commented 1月18日 2:59
  • @jackson コメントありがとうございます。 提案された内容で検証したところ、タスクの実行中にCloudWatchLogsにログが保管されました。 検証内容は質問本文に追記しました。
    – shimomoclo
    Commented 1月18日 3:01

1 件の回答 1

1

(結論出てるようなので, 補足的な?)


stdin, stdout, stderr (標準入力・標準出力・標準エラー出力)は OSが用意します
(UNIX系 OSの仕組みで, 例えば汎用機用 OSには存在しません。UNIX系以外でも 機能取り込んでる例はあります)

stdout, stderr の用途の違いは

  • stdout: 比較的 速度が重視されるため, 通常はバッファリング(蓄積)が行われる
  • stderr: 主にエラーメッセージの表示に利用され, 通常 (ただちに表示されたほうがよいので)バッファリングされない

例えばプログレスバーを使うとき, 以下のコードでは期待した動きにはなりません
(Python含めそれ以外のプログラミング言語でも同様)

for _ in 処理のリスト:
    print('*', end='')
    何らかの処理
  • 出力毎に フラッシュを行う
  • setbuf などの APIでバッファリングを(一時的に)制御
  • (上記の場合)専用のプログレスバー・パッケージを利用する。(この質問での場合 logging.StreamHandlerなど)

などの対処を行うことになるでしょう

質問にある "auto flush" は, 「setbuf などの API」を指すのでしょう
Linuxコンテナー利用するのなら以下にマニュアルがあります

この質問に回答するには、ログインする必要があります。

求めていた回答ではありませんか? のタグが付いた他の質問を参照する。