Webserver shows wrong datetime (timezone) in log

[sartyukhov]

Apache Airflow version

2.2.1 (latest released)

Operating System

Ubuntu 20.04.2 (docker)

Versions of Apache Airflow Providers

• apache-airflow-providers-amazon==2.3.0
• apache-airflow-providers-ftp==2.0.1
• apache-airflow-providers-http==2.0.1
• apache-airflow-providers-imap==2.0.1
• apache-airflow-providers-mongo==2.1.0
• apache-airflow-providers-postgres==2.3.0
• apache-airflow-providers-sqlite==2.0.1

Deployment

Docker-Compose

Deployment details

Docker image build on Ubuntu 20.04 -> installed apache airflow via pip.
Localtime in image changed to Europe/Moscow.

Log format ariflow.cfg option:
log_format = %%(asctime)s %%(filename)s:%%(lineno)d %%(levelname)s - %%(message)s

What happened

For my purposes it's more usefull to run dags when it's midnight in my timezone.
So I changed default_timezone option in airflow.cfg to "Europe/Moscow" and also changed /etc/localtime in my docker image.

It works nice:

• dags with @daily schedule_interval runs at midnight
• python`s datetime.now() get me my localtime by default
• airflow webserver shows all time correctly when I change timezone in right top corner

... except one thing.
Python logging module saves asctime without timezone (for example "2021-10-31 18:25:42,550").
And when I open task`s log in web interface, it shifts this time forward by three hours (for my timzone), but it's already in my timzone.
It is a little bit confusing :(

What you expected to happen

I expected to see my timezone in logs :)

I see several solutions for that:

1. any possibility to turn that shift off?
2. setup logging timezone in airflow.cfg?

That problem is gone when I change system (in container) /etc/localtime to UTC.
But this is very problematic because of the ability to affect a lot of python tasks.

How to reproduce

1. build docker container with different /etc/localtime

FROM ubuntu:20.04

ARG DEBIAN_FRONTEND=noninteractive
RUN apt-get update && apt-get install -y apt-utils locales tzdata
&& locale-gen en_US.UTF-8
&& ln -sf /usr/share/zoneinfo/Europe/Moscow /etc/localtime
ENV LANG=en_US.UTF-8 LANGUAGE=en_US:en AIRFLOW_GPL_UNIDECODE=yes

RUN apt-get install -y
python3-pip
&& python3 -m pip install --upgrade pip setuptools wheel
&& pip3 install --no-cache-dir
apache-airflow-providers-amazon
apache-airflow-providers-mongo
apache-airflow-providers-postgres
apache-airflow==2.2.1
celery
... anything else

2. run webserver / scheduler / celery worker inside
3. open web page -> trigger dag with python operator which prints something via logging
4. open done dag -> task log -> find asctime mark in log
   
5. switch timezone in web interface
6. watch how airflow thinks that asctime in log in UTC, but it's not
   

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!

[Smirn08]

Faced the same thing on 2.2.0, but did not issue the problem.
Looks relevant. Thanks @sartyukhov

[calfzhou]

2.2.0 and 2.2.1 both facing the same issue.

[bbovenzi]

I believe it is an issue with the added +00:00 on this line if someone wants to try a fix.

[EricGao888]

I believe it is an issue with the added +00:00 on this line if someone wants to try a fix.

I'm interested in this issue, will try to give a fix. Thx.

[aborigine]

I followed the merge code, but not fix this issue, the webserver still shows wrong datetime in log

[calfzhou]

I followed the merge code, but not fix this issue, the webserver still shows wrong datetime in log

What's your server's timezone and Airflow config's default timezone?

[sartyukhov]

Has this patch been added to the 2.2.2? Because the bug is still exists in it.

[calfzhou]

Has this patch been added to the 2.2.2? Because the bug is still exists in it.

it seems not. The pr was merged into main branch, not included in release 2.2.2.

[aborigine]

I followed the merge code, but not fix this issue, the webserver still shows wrong datetime in log

What's your server's timezone and Airflow config's default timezone?

I know what's the problem, I should change the js file tiLog.478df866123cef0b0eae.js under 'airflow/www/static/dist' directly instead of 'airflow/www/static/js/ti_log.js'. Once I restart the webserver, the datetime became the right one. Thanks for your reply anyway.

[bbovenzi]

I followed the merge code, but not fix this issue, the webserver still shows wrong datetime in log

What's your server's timezone and Airflow config's default timezone?

I know what's the problem, I should change the js file tiLog.478df866123cef0b0eae.js under 'airflow/www/static/dist' directly instead of 'airflow/www/static/js/ti_log.js'. Once I restart the webserver, the datetime became the right one. Thanks for your reply anyway.

Sounds like webpack wasn't rebuilding the files. In the future, you can run airflow webserver -d and in airflow/www run yarn dev to see your changes.

[aborigine]

I followed the merge code, but not fix this issue, the webserver still shows wrong datetime in log

What's your server's timezone and Airflow config's default timezone?

I know what's the problem, I should change the js file tiLog.478df866123cef0b0eae.js under 'airflow/www/static/dist' directly instead of 'airflow/www/static/js/ti_log.js'. Once I restart the webserver, the datetime became the right one. Thanks for your reply anyway.

Sounds like webpack wasn't rebuilding the files. In the future, you can run airflow webserver -d and in airflow/www run yarn dev to see your changes.

Got it, and thank you so much. I don't know much about front-end development.

[siddarthjha]

I followed the merge code, but not fix this issue, the webserver still shows wrong datetime in log

What's your server's timezone and Airflow config's default timezone?

I know what's the problem, I should change the js file tiLog.478df866123cef0b0eae.js under 'airflow/www/static/dist' directly instead of 'airflow/www/static/js/ti_log.js'. Once I restart the webserver, the datetime became the right one. Thanks for your reply anyway.

Hey, Can you tell me what changes do I have to do in this .js file. I am not familiar to javascript. I did the changes in “ti_log.js”. But the logs are same. Can you please tell the changes to be done in tiLog.478df866123cef0eae.js

[calfzhou]

[siddarthjha]

Thank you

[mashirali]

airflow db shell
mysql> drop database airflow;
mysql> create database airflow;
mysql> grant all on airflow.* to 'airflow'@'localhost' identified by '123456!a';
mysql> flush privileges;
mysql> grant all on airflow.* to 'airflow'@'%' identified by '123456!a';
mysql> flush privileges;

mysql> show global variables like '%timestamp%';
+---------------------------------+-------+
| Variable_name | Value |
+---------------------------------+-------+
| explicit_defaults_for_timestamp | OFF |
| log_timestamps | UTC |
+---------------------------------+-------+
2 rows in set (0.00 sec)

mysql> set global explicit_defaults_for_timestamp =1;
Query OK, 0 rows affected (0.00 sec)