[Airflow] 로그 기록 시간대 문제

개요

• airflow가 DAG의 로그를 기록할 때, 로그 라인의 시간 정보의 시간대가 UTC로 나타나는 문제.
• 로그가 기록될 때 생성되는 파일 이름에서 시간을 지정하면 UTC로 나타나는 문제.

해결 방법

로그 라인 시간대 UTC 문제

# airflow.cfg

...
[logging]
...
log_format = [%%(asctime)s] {%%(filename)s:%%(lineno)d} %%(levelname)s - %%(message)s
...

log_format이 남기는 로그의 포맷인데 asctime이 UTC로 나오게 된다.

airflow는 base_log_folder로 로그를 저장하는데 worker들이 task를 실행하고 남기는 로그들의 타임스탬프가 UTC로 되어 있어서 이를 현지 시간대(KST)로 변경하려고 Amazon Linux 2에서 Timezone 설정을 위해 timedatectl 명령어를 통해 설정했는데 Timezone을 Asia/Seoul로 변경했는데도 로그 시간은 변경되지 않음. airflow.cfg에서 default_timezone을 Asia/Seoul로 지정해도 변하지 않음.

# airflow/utils/log/timezone_aware.py

...
class TimezoneAware(logging.Formatter):
    """
    Override `default_time_format`, `default_msec_format` and `formatTime` to specify utc offset.
    utc offset is the matter, without it, time conversion could be wrong.
    With this Formatter, `%(asctime)s` will be formatted containing utc offset. (ISO 8601)
    (e.g. 2022-06-12T13:00:00.123+0000)
    """

    default_time_format = '%Y-%m-%dT%H:%M:%S'
    default_msec_format = '%s.%03d'
    default_tz_format = '%z'

    def formatTime(self, record, datefmt=None):
        """
        Returns the creation time of the specified LogRecord in ISO 8601 date and time format
        in the local time zone.
        """
        dt = pendulum.from_timestamp(record.created, tz=pendulum.local_timezone())
        if datefmt:
            s = dt.strftime(datefmt)
        else:
            s = dt.strftime(self.default_time_format)

        if self.default_msec_format:
            s = self.default_msec_format % (s, record.msecs)
        if self.default_tz_format:
            s += dt.strftime(self.default_tz_format)
        return s

• dt = pendulum.from_timestamp(record.created, tz=pendulum.local_timezone())
• 이 코드를 보면 pendulum 라이브러리의 local_timezone() 함수를 통해 시간을 얻는 것을 알 수 있다.

def local_timezone():  # type: () -> _Timezone
    """
    Return the local timezone.
    """
    return get_local_timezone()

def get_local_timezone():  # type: () -> Timezone
    global _local_timezone

    if _mock_local_timezone is not None:
        return _mock_local_timezone

    if _local_timezone is None:
        tz = _get_system_timezone()

        _local_timezone = tz

    return _local_timezone

def _get_system_timezone():  # type: () -> Timezone
    if sys.platform == "win32":
        return _get_windows_timezone()
    elif "darwin" in sys.platform:
        return _get_darwin_timezone()

    return _get_unix_timezone()

def _get_unix_timezone(_root="/"):  # type: (str) -> Timezone
    tzenv = os.environ.get("TZ")
    if tzenv:
        try:
            return _tz_from_env(tzenv)
        except ValueError:
            pass
    ...

• UNIX 기반 OS는 TZ 환경 변수 설정으로 해결 가능.
• export TZ=Asia/Seoul 로 해결함.

로그 파일 이름 시간대 UTC 문제

# airflow.cfg

log_filename_template = {{ ti.dag_id }}/{{ logical_date.now().year }}-{{ logical_date.now().month }}-{{ logical_date.now().day }}.log

• Jinja Template으로 사용하는 Task Context 변수가 여러 가지 있는데, logical_date 이라는 변수가 존재한다.
• 해당 변수는 pendulum 모듈의 DateTime object로 Airflow는 DagRun 이라는 object를 생성해 Dag를 실행하게 되는데 이때 타임스탬프로 logical_date를 사용하게 된다. airflow에서는 내부적으로 그리고 DB에서 시간대 정보를 UTC로 관리하고 있고 이를 권장하고 있다.
  • https://airflow.apache.org/docs/apache-airflow/stable/authoring-and-scheduling/timezone.html
  • https://airflow.apache.org/docs/apache-airflow/stable/_modules/airflow/models/dagrun.html#CreatedTasks
• 따라서 logical_date 는 UTC 시간대이고 DateTime 객체이므로 Jinja Template 에서 now() 함수를 통해 system 시간대로 변경이 가능하다.
• (추가) 해당 설정으로 사용할 시, Airflow Webserver 에서 DAG의 로그를 확인할 때 이슈가 있는데, Webserver는 API를 통해 Log를 읽어 오는데 해당 DAG에 대한 filename으로 읽어오기 때문에 now() 를 통해 현재 시간을 읽어와서 웹 UI에서 로그를 확인할 때, 로그 파일을 찾을 수 없는 문제가 발생하였다. 그래서 now()는 사용하지 않는 것이 좋고 그냥 UTC로 로그 파일을 저장하는 것을 추천한다.