Webserver shows wrong datetime (timezone) in log

[freshlu11]

Apache Airflow version

2.3.0 (latest released)

What happened

same as #19401 , when I open task`s log in web interface, it shifts this time forward by 8 hours (for Asia/Shanghai), but it's already in Asia/Shanghai.
here is the log in web:

*** Reading local file: /opt/airflow/logs/forecast/cal/2022-05-18T09:50:00+00:00/1.log
[2022-05-19, 13:54:52] {taskinstance.py:1037} INFO ...

As you seee, UTC time is 2022-05-18T09:50:00，and My timezone is Asia/Shanghai(should shift forward 8 hours)，but it shift forward 16hours!

What you think should happen instead

No response

How to reproduce

No response

Operating System

Debian GNU/Linux 11 (bullseye)(docker)

Versions of Apache Airflow Providers

No response

Deployment

Docker-Compose

Deployment details

1. build my docker image from apache/airflow:2.3.0 to change timezone

FROM apache/airflow:2.3.0
# bugfix of log UI in web, here I change ti_log.js file by following on #19401 
COPY ./ti_log.js /home/airflow/.local/lib/python3.7/site-packages/airflow/www/static/js/ti_log.js
USER root
# container timezone changed to CST time
RUN ln -sf /usr/share/zoneinfo/Asia/Shanghai /etc/localtime \
  && rm -rf /etc/timezone \
  && echo Asia/Shanghai >> /etc/timezone \
  && chown airflow /home/airflow/.local/lib/python3.7/site-packages/airflow/www/static/js/ti_log.js
USER airflow

2. use my image to run airflow by docker-compose

3. check task logs in web
   Although I have changed the file airflow/www/static/js/ti_log.js, but it did not work! Then check source from Web, I found another file : airflow/www/static/dist/tiLog.e915520196109d459cf8.js, then I replace "+00:00" by "+08:00" in this file. Finally it works!

# origin tiLog.e915520196109d459cf8.js
replaceAll(c,(e=>`<time datetime="${e}+00:00" data-with-tz="true">${Object(a.f)(`${e}+00:00`)}</time>`))

# what I changed
replaceAll(c,(e=>`<time datetime="${e}+08:00" data-with-tz="true">${Object(a.f)(`${e}+08:00`)}</time>`))

Anything else

No response

Are you willing to submit PR?

• Yes I am willing to submit a PR!

Code of Conduct

• I agree to follow this project's Code of Conduct

[boring-cyborg]

Thanks for opening your first issue here! Be sure to follow the issue template!

[tanelk]

Just to document the history:

This was initially fixed in #19401 and then reverted in #23075

For some users the logs are in the server time and for others the logs are in UTC.
Should we have a separate configuration option so we wont have to "fix" it back and forth anymore?

Also a side note - I think #19401 was a partial fix as it does not take in account that the offset for a timezone can change.

[uranusjr]

It sounds like a configuration is the only way to satisfy all use cases. There’s no way Airflow can automatically know what timezone the log files use otherwise.

[rino0601]

I found workaround. via configuration. here's how:

1. write ${PYTHONPATH}/airflow_local_settings.py

import logging
import time
from copy import deepcopy

from airflow.config_templates.airflow_local_settings import DEFAULT_LOGGING_CONFIG
LOGGING_CONFIG = deepcopy(DEFAULT_LOGGING_CONFIG)

# from https://stackoverflow.com/a/60342048
class UTCFormatter(logging.Formatter):
    converter = time.gmtime  # this makes logger's asctime as UTC

LOGGING_CONFIG['formatters']['airflow']['class'] = 'airflow_local_settings.UTCFormatter'

2. Edit airflow.cfg

[logging]
logging_config_class = airflow_local_settings.LOGGING_CONFIG

working as same as #20315

3. then

---

I have tried something like [2022-06-08 10:45:01+09:00] by appending %z to datefmt on logging.Filter. but regex in airflow/www/static/js/ti_log.js couldn't understand it.

[rino0601]

I've create PR #24373 for this issue.

@tanelk @uranusjr could you take a look?

[hwooson12]

@uranusjr
I think it is wrong that Airflow basically assumes all timezone in logging is UTC. The idea of converting logging time as the timezone that users select from the browser UI was very good but the problem is that all system timezone is not UTC. So we could see wrong time in the log files because it is converted on only the frontend side without any clue of timezone. Even though Airflow does not automatically know what timezone the log files use, at least we can leave timezone information on the log files by fixing default log format class which means Airflow knows what timezone is so that it can be handled by using only Javascript.

[uranusjr]

I never waid assuming UTC is right, but the problem is the frontend doesn’t know what timezone the log files used. Appending %z in the timestamp actually sounds like the best solution, if we can change the frontend code to correctly parse them. The formatter patch mentioned above should also solve the issue (by making the log files always use UTC), but I’m not sure it’s a desired outcome for a lot of people—if people want to read logs in the web UI in their own timezone, I would expect they also want the actual log files display the server timezone as well.

[rino0601]

@uranusjr Seems to need more explain about PR, let me supplement that.

In the comment above, I found a way to do it only with configuration, so I used time.gmtime to always output utc regardless of the system settings. The reason I had to do that was because the regular expression of UI could not be changed with configuration .

While writing PR , I was also able to edit the UI regex, so I didn't have to lock the log to UTC, so I didn't use time.gmtime (to allow users to get log files that use server timezone ).

Instead, I override the default_time_format to append %z to the %(asctime)s output of the log file. Also, in python 3.7 and 3.8, default_msec_format cannot be omitted, so I set it to an appropriate value so that it does not interfere with the regular expression of the UI.

Thankfully moments.js can handle both +00:00 and +0000(python %z style) properly.

https://jsfiddle.net/wbqs84x3/

Since we are already using moments.js in updateAllDateTimes at www/static/js/datetime_utils.js,

airflow/airflow/www/static/js/datetime_utils.js

Line 79 in fe2ef0f

const dt = moment($el.attr('datetime'));

all I have to do is pass in a datetime string that moments.js can recognize. This was achieved by fixing the regex in www/static/js/ti_log.js