You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@airflow.apache.org by "humit0 (via GitHub)" <gi...@apache.org> on 2025/08/13 02:11:32 UTC
[PR] Fix: Incorrect log timestamps in UI when default_timezone is not UTC [airflow]
humit0 opened a new pull request, #54431:
URL: https://github.com/apache/airflow/pull/54431
<!--
Licensed to the Apache Software Foundation (ASF) under one
or more contributor license agreements. See the NOTICE file
distributed with this work for additional information
regarding copyright ownership. The ASF licenses this file
to you under the Apache License, Version 2.0 (the
"License"); you may not use this file except in compliance
with the License. You may obtain a copy of the License at
http://www.apache.org/licenses/LICENSE-2.0
Unless required by applicable law or agreed to in writing,
software distributed under the License is distributed on an
"AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY
KIND, either express or implied. See the License for the
specific language governing permissions and limitations
under the License.
-->
<!--
Thank you for contributing! Please make sure that your code changes
are covered with tests. And in case of new features or big changes
remember to adjust the documentation.
Feel free to ping committers for the review!
In case of an existing issue, reference it using one of the following:
closes: #ISSUE
related: #ISSUE
How to write a good git commit message:
http://chris.beams.io/posts/git-commit/
-->
related: #53195
This pull request addresses a previously reported issue where log timestamps are displayed incorrectly in the Airflow UI if the `[core] default_timezone` in airflow.cfg is set to a value other than UTC. This issue was converted to a discussion and has not seen recent activity from the original assignee, so I am submitting a new PR to resolve it.
A clear example of this problem occurs when the timezone is set to KST (UTC+09:00). In this case, the timestamps displayed in the Airflow UI are nine hours earlier than the actual log generation time.
## Implementation
I considered two potential approaches to fix this issue:
1. Parsing with Timezone Awareness: Modify the `_log_stream_to_parsed_log_stream` function within `airflow-core/src/airflow/utils/log/file_task_handler.py` to handle timezone-aware timestamp parsing.
2. Including Timezone in Logs: Embed the timezone information directly into the log message at the time of logging.
I have chosen the second approach as I believe it offers greater clarity and explicitness by ensuring the timezone is always part of the log entry itself. The implemented changes ensure that the timezone offset is included when logs are written.
## Local test result
Only set environment variable `AIRFLOW__CORE__DEFAULT_TIMEZONE=Asia/Seoul`
current
<img width="1279" height="517" alt="image" src="https://github.com/user-attachments/assets/0af4e0c0-6107-4d62-bdd7-d032ae813934" />
after changed code
<img width="1281" height="553" alt="image" src="https://github.com/user-attachments/assets/35a353b9-b53b-4a24-9ae1-231b5eea836f" />
I welcome any feedback or suggestions on this approach. Please let me know if there are any potential concerns with this implementation.
Thank you!
<!-- Please keep an empty line above the dashes. -->
---
**^ Add meaningful description above**
Read the **[Pull Request Guidelines](https://github.com/apache/airflow/blob/main/contributing-docs/05_pull_requests.rst#pull-request-guidelines)** for more information.
In case of fundamental code changes, an Airflow Improvement Proposal ([AIP](https://cwiki.apache.org/confluence/display/AIRFLOW/Airflow+Improvement+Proposals)) is needed.
In case of a new dependency, check compliance with the [ASF 3rd Party License Policy](https://www.apache.org/legal/resolved.html#category-x).
In case of backwards incompatible changes please leave a note in a newsfragment file, named `{pr_number}.significant.rst` or `{issue_number}.significant.rst`, in [airflow-core/newsfragments](https://github.com/apache/airflow/tree/main/airflow-core/newsfragments).
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@airflow.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [PR] Fix: Incorrect log timestamps in UI when default_timezone is not UTC [airflow]
Posted by "ashb (via GitHub)" <gi...@apache.org>.
ashb commented on PR #54431:
URL: https://github.com/apache/airflow/pull/54431#issuecomment-3198307798
(I think this change is good, I just don't have time to do a proper review or test on it right now, sorry)
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@airflow.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [PR] Fix: Incorrect log timestamps in UI when default_timezone is not UTC [airflow]
Posted by "ashb (via GitHub)" <gi...@apache.org>.
ashb commented on code in PR #54431:
URL: https://github.com/apache/airflow/pull/54431#discussion_r2275877100
##########
task-sdk/src/airflow/sdk/execution_time/supervisor.py:
##########
@@ -1597,12 +1597,7 @@ def process_log_messages_from_subprocess(
if ts := event.get("timestamp"):
# We use msgspec to decode the timestamp as it does it orders of magnitude quicker than
# datetime.strptime cn
- #
- # We remove the timezone info here, as the json encoding has `+00:00`, and since the log came
- # from a subprocess we know that the timezone of the log message is the same, so having some
- # messages include tz (from subprocess) but others not (ones from supervisor process) is
- # confusing.
- event["timestamp"] = msgspec.json.decode(f'"{ts}"', type=datetime).replace(tzinfo=None)
+ event["timestamp"] = msgspec.json.decode(f'"{ts}"', type=datetime)
Review Comment:
Oh hmmm maybe this is right.
Could you show me what the raw JSON lines written to the file look like (before and after) with this change please?
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@airflow.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [PR] Fix: Incorrect log timestamps in UI when default_timezone is not UTC [airflow]
Posted by "ashb (via GitHub)" <gi...@apache.org>.
ashb commented on PR #54431:
URL: https://github.com/apache/airflow/pull/54431#issuecomment-3292629363
@humit0 Can you give precise reproduction steps? We're not able to see the same behaviour anymore. And make a note of what version you are seeing this on please.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@airflow.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [PR] Fix: Incorrect log timestamps in UI when default_timezone is not UTC [airflow]
Posted by "pierrejeambrun (via GitHub)" <gi...@apache.org>.
pierrejeambrun merged PR #54431:
URL: https://github.com/apache/airflow/pull/54431
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@airflow.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [PR] Fix: Incorrect log timestamps in UI when default_timezone is not UTC [airflow]
Posted by "humit0 (via GitHub)" <gi...@apache.org>.
humit0 commented on code in PR #54431:
URL: https://github.com/apache/airflow/pull/54431#discussion_r2281093038
##########
task-sdk/src/airflow/sdk/execution_time/supervisor.py:
##########
@@ -1597,12 +1597,7 @@ def process_log_messages_from_subprocess(
if ts := event.get("timestamp"):
# We use msgspec to decode the timestamp as it does it orders of magnitude quicker than
# datetime.strptime cn
- #
- # We remove the timezone info here, as the json encoding has `+00:00`, and since the log came
- # from a subprocess we know that the timezone of the log message is the same, so having some
- # messages include tz (from subprocess) but others not (ones from supervisor process) is
- # confusing.
- event["timestamp"] = msgspec.json.decode(f'"{ts}"', type=datetime).replace(tzinfo=None)
+ event["timestamp"] = msgspec.json.decode(f'"{ts}"', type=datetime)
Review Comment:
@ashb
Sorry for late response. Here are the raw log file contents!
before
```jsonl
{"timestamp":"2025-08-13T01:38:27.459132","level":"info","event":"DAG bundles loaded: dags-folder","logger":"airflow.dag_processing.bundles.manager.DagBundlesManager"}
{"timestamp":"2025-08-13T01:38:27.459490","level":"info","event":"Filling up the DagBag from /files/dags/dag.py","logger":"airflow.models.dagbag.DagBag"}
{"timestamp":"2025-08-13T01:38:27.910325","level":"info","event":"Tmp dir root location: /tmp","logger":"airflow.task.hooks.airflow.providers.standard.hooks.subprocess.SubprocessHook"}
{"timestamp":"2025-08-13T01:38:27.910602","level":"info","event":"Running command: ['/usr/bin/bash', '-c', \"echo '2022-12-31'\"]","logger":"airflow.task.hooks.airflow.providers.standard.hooks.subprocess.SubprocessHook"}
{"timestamp":"2025-08-13T01:38:27.913484","level":"info","event":"Output:","logger":"airflow.task.hooks.airflow.providers.standard.hooks.subprocess.SubprocessHook"}
{"timestamp":"2025-08-13T01:38:27.914388","level":"info","event":"2022-12-31","logger":"airflow.task.hooks.airflow.providers.standard.hooks.subprocess.SubprocessHook"}
{"timestamp":"2025-08-13T01:38:27.914490","level":"info","event":"Command exited with return code 0","logger":"airflow.task.hooks.airflow.providers.standard.hooks.subprocess.SubprocessHook"}
{"timestamp":"2025-08-13T01:38:27.914823","level":"info","event":"Pushing xcom","ti":"RuntimeTaskInstance(id=UUID('0198a114-1dbf-7bdb-a7d2-1bc32154fb72'), task_id='test_task', dag_id='test_dag', run_id='scheduled__2022-12-31T15:00:00+00:00', try_number=2, dag_version_id=UUID('0198a10a-fdbd-775f-97de-a0b2c89a6eee'), map_index=-1, hostname='0a3aaf1ba399', context_carrier=None, task=<Task(BashOperator): test_task>, bundle_instance=LocalDagBundle(name=dags-folder), max_tries=2, start_date=datetime.datetime(2025, 8, 13, 1, 38, 27, 81666, tzinfo=datetime.timezone.utc), end_date=None, state=<TaskInstanceState.RUNNING: 'running'>, is_mapped=False, rendered_map_index=None, log_url='http://localhost:8080/dags/test_dag/runs/scheduled__2022-12-31T15%3A00%3A00%2B00%3A00/tasks/test_task?try_number=2')","logger":"task"}
```
after
```jsonl
{"timestamp":"2025-08-13T02:05:21.148361Z","level":"info","event":"DAG bundles loaded: dags-folder","logger":"airflow.dag_processing.bundles.manager.DagBundlesManager"}
{"timestamp":"2025-08-13T02:05:21.148831Z","level":"info","event":"Filling up the DagBag from /files/dags/dag.py","logger":"airflow.models.dagbag.DagBag"}
{"timestamp":"2025-08-13T02:05:21.687594Z","level":"info","event":"Tmp dir root location: /tmp","logger":"airflow.task.hooks.airflow.providers.standard.hooks.subprocess.SubprocessHook"}
{"timestamp":"2025-08-13T02:05:21.687884Z","level":"info","event":"Running command: ['/usr/bin/bash', '-c', \"echo '2022-12-31'\"]","logger":"airflow.task.hooks.airflow.providers.standard.hooks.subprocess.SubprocessHook"}
{"timestamp":"2025-08-13T02:05:21.690570Z","level":"info","event":"Output:","logger":"airflow.task.hooks.airflow.providers.standard.hooks.subprocess.SubprocessHook"}
{"timestamp":"2025-08-13T02:05:21.691518Z","level":"info","event":"2022-12-31","logger":"airflow.task.hooks.airflow.providers.standard.hooks.subprocess.SubprocessHook"}
{"timestamp":"2025-08-13T02:05:21.691581Z","level":"info","event":"Command exited with return code 0","logger":"airflow.task.hooks.airflow.providers.standard.hooks.subprocess.SubprocessHook"}
{"timestamp":"2025-08-13T02:05:21.691911Z","level":"info","event":"Pushing xcom","ti":"RuntimeTaskInstance(id=UUID('0198a12c-ba73-709e-8d48-14b87d48688d'), task_id='test_task', dag_id='test_dag', run_id='scheduled__2022-12-31T15:00:00+00:00', try_number=3, dag_version_id=UUID('0198a10a-fdbd-775f-97de-a0b2c89a6eee'), map_index=-1, hostname='d3d7af713f58', context_carrier=None, task=<Task(BashOperator): test_task>, bundle_instance=LocalDagBundle(name=dags-folder), max_tries=3, start_date=datetime.datetime(2025, 8, 13, 2, 5, 20, 744889, tzinfo=datetime.timezone.utc), end_date=None, state=<TaskInstanceState.RUNNING: 'running'>, is_mapped=False, rendered_map_index=None, log_url='http://localhost:8080/dags/test_dag/runs/scheduled__2022-12-31T15%3A00%3A00%2B00%3A00/tasks/test_task?try_number=3')","logger":"task"}
```
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@airflow.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [PR] Fix: Incorrect log timestamps in UI when default_timezone is not UTC [airflow]
Posted by "humit0 (via GitHub)" <gi...@apache.org>.
humit0 commented on PR #54431:
URL: https://github.com/apache/airflow/pull/54431#issuecomment-3294375923
@ashb
With below environment variables and
```bash
export AIRFLOW__CORE__DEFAULT_TIMEZONE=Asia/Seoul
```
Using below python file. (airflow version is 3.0.6)
```python
from airflow.models import DAG
from airflow.providers.standard.operators.bash import BashOperator
default_args = {
"owner": "airflow",
"depends_on_past": False,
"start_date": "2023-01-01",
"retries": 1,
}
with DAG(
dag_id="test_dag",
default_args=default_args,
schedule="@once",
) as dag:
BashOperator(
task_id="test_task",
bash_command="echo '{{ ds }}'",
)
```
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@airflow.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org