[Airflow] 웹서버의 LOG 에 찍힌 날짜가 다르게 나오는 문제 해결하기 - timezone 계산 버그

airflow 2.x 버전에서는 timezone 처리가 가능하다. execution_date 를 로컬날짜 기준으로 사용하기위해서는 python 코드에서 로컬타임존 세팅후 전환하는 로직을 호출해주면 해결이 되는데, 문제는 DAG 의 실행결과를 확인하기위한 로그의 날짜가 버그가 존재한다.

어떤 상황이냐면,  airflow 가 설치된 서버의 타임존은 한국기준로 세팅되어있고, 실행된 시점은 "Tue Feb 21 12:30:02 KST 2023" 이라고 가정하자. 편의상 시간만 보면 한국시간으로 12시 30분이라고 보면 된다.

[2023-02-21, 21:30:02 KST] {subprocess.py:85} INFO - Output:
[2023-02-21, 21:30:02 KST] {subprocess.py:92} INFO - date                            => Tue Feb 21 12:30:02 KST 2023
[2023-02-21, 21:30:02 KST] {subprocess.py:92} INFO - logical_date                    => 2023-02-21T03:20:00+00:00
[2023-02-21, 21:30:02 KST] {subprocess.py:92} INFO - execution_date                  => 2023-02-21 03:20:00
[2023-02-21, 21:30:02 KST] {subprocess.py:92} INFO - next_execution_date             => 2023-02-21 03:30:00
[2023-02-21, 21:30:02 KST] {subprocess.py:92} INFO - prev_execution_date             => 2023-02-21 03:10:00
[2023-02-21, 21:30:02 KST] {subprocess.py:92} INFO - local_dt(execution_date)        => 2023-02-21 12:20:00
[2023-02-21, 21:30:02 KST] {subprocess.py:92} INFO - local_dt(next_execution_date)   => 2023-02-21 12:30:00
[2023-02-21, 21:30:02 KST] {subprocess.py:92} INFO - local_dt(prev_execution_date)   => 2023-02-21 12:10:00
[2023-02-21, 21:30:02 KST] {subprocess.py:96} INFO - Command exited with return code 0

그런데, 로그에 찍힌 날짜는 쌩뚱맞게 21시 30분이다. 한국시간도 아니도 UTC 도 아니다. 왜 이런걸까? 해결방법과 원인을 이야기 해보도록 하겠다.

 

해결방법

결과부터 말하면, 시간계산이 잘못되었다. Airflow WEB UI 상에서 로그를 보면 타임존에 따라서 시간계산을 다시 해주는데, 서버의 타임존 세팅이 UTC 로 되었을 경우만 정상 작동하는 버그가 있었다. 이 문제를 해결하는 방법은 아래 링크의 댓글에서 발견했다.

https://github.com/apache/airflow/issues/19342#issuecomment-989752208

 

나는 Airflow 2.3.3 을 사용중인데, airflow 계정으로 virtualenv 를 사용중일때 다음 경로의 파일을 수정해주면 되었다. 코드 난독화가 되어있으므로, javascript 를 pretty 하게 변경해주는 사이트에가서 보기 편하게 하고 해당 로직을 찾아 수정하도록 하자.

(web 의 경우 javascript 를 yarn 으로 빌드한 결과물이라 파일명에 숫자는 바뀔수도 있다)

 

/home/airflow/py3/lib/python3.9/site-packages/airflow/www/static/dist/tiLog.74059164f78498e04d63.js

...생략...

// [추가] 서버 타임존 관련 offset 값 추출
const tzOffset = moment().tz(Airflow.serverTimezone).format('Z'); 
//const l = (0, e.escapeHtml)(o[1]).replace(i, (e => `<a href="${e}" target="_blank">${e}</a>`)).replaceAll(m, (e => `<time datetime="${e}+00:00" data-with-tz="true">${(0,a.o0)(`${e}+00:00`)}</time>`));
const l = (0, e.escapeHtml)(o[1]).replace(i, (e => `<a href="${e}" target="_blank">${e}</a>`)).replaceAll(m, (e => `<time datetime="${e}${tzOffset}" data-with-tz="true">${(0,a.o0)(`${e}${tzOffset}`)}</time>`));

...생략...

tiLog.74059164f78498e04d63.js

0.01MB

위와 같이 로그의 날짜 계산하는 로직을 수정해주면, 엉뚱하게 계산되는 로그의 날짜값이 잘 계산되어 나온다. (위치 찾기 어려울까봐 내가 수정한 버전도 첨부했다)

아래는 실제 호출이 한국시간기준 13:30:01 되었고, 한국시간으로 세팅해서 조회하면 동일한 13:30:01 값으로 나옴을 확인할 수 있다. 

수정이 되었다면 서버의 시간과 동일한 값으로 볼 수있다. (타임존 변경해도 잘 계산되고)

배포 혹은 다운로드된 라이브러리를 직접 수정해서 돌아가게만 하려는거면 위와 같은 방식으로 하면 되는데, 사용자가 직접 빌드해서 사용한다면, 아예 소스코드에서 수정후 빌드하는것이 좋다. 코드 위치는 아래와 같다.

https://github.com/apache/airflow/blob/2.3.3/airflow/www/static/js/ti_log.js

원인알기

위에 말했지만, 서버가 UTC 라고 가정된상태로 계산되었기 때문이다. 아마 1.x 버전대 타임존 문제가 잘 해결되기전의 코드가 남아 넘어온게 아닐까 하는 생각도 든다. airflow.cfg 에서 타임존 설정은 아래와 같은데, system 으로 세팅하면 서버의 타임존을 따라가게 된다.

default_timezone = system
default_ui_timezone = system

그리고, 한국인이라면 서버의 타임존은 보통 한국시간 기준으로 되어있다보니, 서버에 직접 붙어서 DAG 의 로그파일을 확인해보면 system 타임존 즉, 한국시간 기준으로 잘 보일거다. 그런데 문제가 되는건 이걸 UI 에서는 타임존을 지원한다고 날짜 차이를 계산해주는데 남은값은 한국시간인데, UTC 로 가정하고 계산하다보니 계산이 잘못되었다는게 문제다. 

일단 문제를 추적할때 시간값이 달라서 헤맸는데 해결방법을 찾아서 한숨 돌렸다. 에휴~