Add %z for %(asctime)s to fix timezone for logs on UI #24373

rino0601 · 2022-06-10T11:11:46Z

In this PR I have fixed the bug with logs display in UI.

For those who not using UTC on their system, time conversion doesn't work correctly.
Because previous fix(PR #23075) consider UTC only.

This PR:

append %z to logging.Formatter.default_time_format so that moments.js could understand the time properly.
make it configurable
modify parse logic on UI side (both log view and log view in grid view) to cooperate with above change.

closes: #23796

^ Add meaningful description above

Read the Pull Request Guidelines for more information.
In case of fundamental code change, Airflow Improvement Proposal (AIP) is needed.
In case of a new dependency, check compliance with the ASF 3rd Party License Policy.
In case of backwards incompatible changes please leave a note in a newsfragement file, named {pr_number}.significant.rst, in newsfragments.

boring-cyborg · 2022-06-10T11:11:50Z

Congratulations on your first Pull Request and welcome to the Apache Airflow community! If you have any issues or are unsure about any anything please check our Contribution Guide (https://github.com/apache/airflow/blob/main/CONTRIBUTING.rst)
Here are some useful points:

Pay attention to the quality of your code (flake8, mypy and type annotations). Our pre-commits will help you with that.
In case of a new feature add useful documentation (in docstrings or in docs/ directory). Adding a new operator? Check this short guide Consider adding an example DAG that shows how users should use it.
Consider using Breeze environment for testing locally, it’s a heavy docker but it ships with a working Airflow and a lot of integrations.
Be patient and persistent. It might take some time to get a review or get the final approval from Committers.
Please follow ASF Code of Conduct for all communication including (but not limited to) comments on Pull Requests, Mailing list and Slack.
Be sure to read the Airflow Coding style.
Apache Airflow is a community-driven project and together we are making it better 🚀.
In case of doubts contact the developers at:
Mailing List: dev@airflow.apache.org
Slack: https://s.apache.org/airflow-slack

bbovenzi · 2022-06-13T16:54:47Z

cc: @uranusjr

uranusjr · 2022-06-14T03:23:41Z

The logging side (Python) looks reasonable to me, thanks for the effort! On the JavaScript side though, I think we need some compatibiliy code to be able to deal with existing log files, which lack the timezone part. We probably should add some tests as well. (Do we have a mechanism to test non-React code now?)

rino0601 · 2022-06-15T04:26:34Z

@bbovenzi
I did a local rebase and force push to update the branch. I didn't know this would cancel workflow approval. Could you approve it again? thank you

@uranusjr
By specifying a group in the regular expression, the code has been changed to perform the previous behavior when matched with the old format. b09da7a5d4c17190ef0cd3410e9976bb3fad6df7

And, speaking of ui test, although the jest configuration file is seen in the www directory, it seems to be for grid view only. I'm not familiar with jquery, webpack, I have no idea of a way to test the jquery code. Even if it were possible, I guess it would be impossible without major structural changes.

If someone makes a test procedure for the files under www/static/js, I'd be happy to contribute to maintaining the test code related to this PR.

uranusjr · 2022-06-15T06:15:53Z

airflow/config_templates/airflow_local_settings.py

-        'airflow': {'format': LOG_FORMAT},
+        'airflow': {
+            'format': LOG_FORMAT,
+            'class': 'airflow.utils.log.timezone_aware.TimezoneAware',


Let’s make this string a constant like COLORED_FORMATTER_CLASS.

@uranusjr

Like COLORED_FORMATTER_CLASS, I changed it to be user configurable. This is a bugfix, and backwards compatibility was adjusted in js, so a new class was designated as fallback.
Could you check it out?

bbovenzi · 2022-06-15T14:40:41Z

airflow/utils/log/colored_log.py

@@ -43,6 +43,9 @@ class CustomTTYColoredFormatter(TTYColoredFormatter):
    traceback.
    """

+    default_time_format = '%Y-%m-%d %H:%M:%S%z'
+    default_msec_format = '%s %03dms'


Why are we adding milliseconds to this PR? I don't think the logs showed ms before...

@bbovenzi

The original value before override in this part is %s,%03d.
If left as is, the file will have something like 2022-06-14 06:00:00-0600,123 which is a bit awkward. Also, it's in a format that moments.js doesn't understand.
It would be ideal to have a format like 2022-06-14 06:00:00,123-0600, but that would be a very difficult because it would have to modify the standard library.

There are 3 ways to solve this problem:

Avoid specifying milliseconds in the first place. by doing that we can leave the same level of information both in the UI and in the file (which is currently not. file is verbose than UI). It is possible by assigning default_msec_format to None , but this requires python3.9 or higher. Dropping 3.7 and 3.8 because of this small change is ridiculous. so this is not an option. (if there is a way to consume an argument in the %-format but not print it, we can do this without dropping 3.7 and 3.8. but I don't think such a method exists.)

In order to stick current behavior, modify the regex to match including the rear part of datetime, and then not use the rear part in replaceAll. In this case, the file side has more detailed information, anyway I think -0600 123ms is easier to understand than -0600,123.

(which I chose) To provide the same level of information to both the UI and the file, the regex didn't match the milliseconds part. so they could exposed as they is. By doing this, UI shows more information that wasn't there before, but I didn't think that would be a problem.

Previously, milliseconds was not shown because it was discarded from the format of moments.js added on August 3, 2018. While searching for this, I found that the most recently added format (presumably used in grid views) uses milliseconds. Based on this, I guessed that there is a demand for milliseconds.

If you think displaying milliseconds is too verbose, I'll edit the code to use the second method. However, the regular expression become a bit more complicated than it is now, and code of replaceAll become getting the milliseconds value and then ignoring it. This can be awkward code for anyone who hasn't read the conversation in this PR.

We should send the date to the UI that moment can parse. But that is annoying if it's non-trivial. We can go with this for now. But we should get that single log parsing function soon so the gird view keeps this in consideration too.

@bbovenzi

After I git rebase onto main:

A lot of thoughts went through my mind when I saw this screen. 😢

It would be desirable to fix it in this PR because it takes more effort to find and process it later. so I've spend some times try to fix it. it seems that if I fix the regular expression in grid/details/content/taskInstance/Logs/utils.js I can fix it for now, but if I do, as you concerned, we will have two log parsers.

Then I stopped trying, to ask you comment. Also, my front-end knowledge is frozen in the days of react15, so I need some time to review if I understand the grid code properly.

Anyway,
I wonder if logs in the grid view feature will be released in 2.3 or 2.4.
If it's going to be released in 2.4, so if this PR also has to go out in 2.4 too, I'd like to know in advance.

I'm using 1.10.15 at work, and dozens of instances are stuck with that version. I recently migrated one instance to 2.3.2 as a pilot. Then I discovered this time zone problem. Therefore, other instances are waiting for the result of this PR.

My co-worker's previous contribution was classified as a minor release, it took 5 months to release. If this PR is going to be classified as minor release, I would like to say "migrate now (with workaround config)" to my colleagues because I can guess that it will be released in a few months.

Go ahead and do the simple fix for now. I'm happy to help out combine them into a single parser in a subsequent PR. I think for this change we can target 2.3.3, so it shouldn't be months.

bbovenzi · 2022-06-15T14:42:22Z

We've started to add logs into the grid view too. I think a useful thing is that we can have a single log parser function that both pages use and we write tests for. I can play around with that after this PR.

rino0601 · 2022-06-19T13:36:08Z

@bbovenzi I updated PR (579b9c92bf749783a888eb6d2eb5b9644a6ff929):

uranusjr · 2022-06-21T15:44:15Z

Just realised, we should add a news entry to tell users using custom loggers to update their configuration so they can benefit from this enhancement.

rino0601 · 2022-06-22T05:47:17Z

Since the UI side code maintains backwards compatibility, I thought it would not be a significant addition, so I wrote it as an improvement and a bugfix. Would it be appropriate?

uranusjr · 2022-06-22T05:57:28Z

newsfragments/24373.improvement.rst

@@ -0,0 +1 @@
+Support config ``[logging]log_formatter_class`` for overriding logging.Formatter


We probably only need one of these. Also, this should add a sentence saying something like

If you are using a custom Formatter subclass in your logging_config_class, please inherit from airflow.utils.log.timezone_aware.TimezoneAware instead of logging.Formatter.

@uranusjr
I misinterpreted significant as breaking change.

Referring to the following paragraph of the contribution guide, it seems that 'body' to explain the procedure is supported only in the 'significant' type. is that right?

In general newsfragments must be one line. For newsfragment type significant, you may include summary and body separated by a blank line, similar to git commit messages.

If so, I think you should change it to a significant type and put the explanation you suggested. thanks for the comment

github-actions · 2022-06-22T06:00:52Z

The PR most likely needs to run full matrix of tests because it modifies parts of the core of Airflow. However, committers might decide to merge it quickly and take the risk. If they don't merge it quickly - please rebase it to the latest main at your convenience, or amend the last commit of the PR, and push it with --force-with-lease.

uranusjr · 2022-06-24T13:16:26Z

Failure unrelated (and this doesn’t change the providers).

boring-cyborg · 2022-06-24T13:17:27Z

Awesome work, congrats on your first merged pull request!

potiuk · 2022-06-24T14:04:25Z

The failure was because oit was not rebased BTW

millin · 2022-07-01T06:27:42Z

Dear @rino0601 @uranusjr
Why not just apply ISO 8601 format (e.g 2022-06-12T13:00:00.123+0000)?
For what you complicate and come up with a new non-standard format?

I already suggested in my PR to use ISO 8601 for ES Logger because it is native for it.
https://github.com/apache/airflow/blob/4af6779867691e04e24dbb59f8e3cb75170968ec/airflow/providers/elasticsearch/log/es_json_formatter.py#L29-L48

rino0601 · 2022-07-01T12:30:23Z

@millin Thanks for the suggestion.
I was shocked that I did not realize this simple way on my own. 😱
I need to fix this embarrassing PR right now 🤕

…#24373)" This reverts commit 7de050c.

…" (#24810) This reverts commit 7de050c.

rino0601 requested review from ryanahamilton, ashb and bbovenzi as code owners June 10, 2022 11:11

boring-cyborg bot added area:logging area:UI Related to UI/UX. For Frontend Developers. area:webserver Webserver related Issues labels Jun 10, 2022

rino0601 mentioned this pull request Jun 10, 2022

Webserver shows wrong datetime (timezone) in log #23796

Closed

2 tasks

rino0601 force-pushed the fix-issue-23796 branch 3 times, most recently from 9633f50 to 1718474 Compare June 12, 2022 09:56

rino0601 force-pushed the fix-issue-23796 branch from 1718474 to b09da7a Compare June 15, 2022 04:12

uranusjr reviewed Jun 15, 2022

View reviewed changes

bbovenzi reviewed Jun 15, 2022

View reviewed changes

rino0601 force-pushed the fix-issue-23796 branch from b261672 to 579b9c9 Compare June 19, 2022 10:35

potiuk mentioned this pull request Jun 19, 2022

Timezone changed on server and UI to local/Pacific, but DateTimeSensor still using UTC #24359

Closed

2 tasks

rino0601 force-pushed the fix-issue-23796 branch from 579b9c9 to b7aae8a Compare June 21, 2022 08:10

bbovenzi approved these changes Jun 21, 2022

View reviewed changes

rino0601 force-pushed the fix-issue-23796 branch from e5a0568 to c3b3a4d Compare June 22, 2022 05:44

uranusjr reviewed Jun 22, 2022

View reviewed changes

github-actions bot added the full tests needed We need to run full set of tests for this PR to merge label Jun 22, 2022

rino0601 force-pushed the fix-issue-23796 branch from c3b3a4d to 5e52f77 Compare June 23, 2022 04:40

rino0601 added 5 commits June 23, 2022 13:41

fulfil static test

72f2cd4

fix regex to support backward compatibility

53f24d3

Make log_formatter_class configurable

d5b31cc

fix grid view ui to understand timezone aware log

4668c65

Attach newsfragments

02eed05

rino0601 force-pushed the fix-issue-23796 branch from 5e52f77 to 02eed05 Compare June 23, 2022 04:41

uranusjr approved these changes Jun 24, 2022

View reviewed changes

uranusjr changed the title ~~Fix timezone display for logs on UI by adding %z for %(asctime)s (#23796)~~ Add %z for %(asctime)s to fix timezone for logs on UI Jun 24, 2022

uranusjr merged commit 7de050c into apache:main Jun 24, 2022

rino0601 deleted the fix-issue-23796 branch June 27, 2022 08:51

hwooson12 mentioned this pull request Jul 2, 2022

Sync v2-3-stable with v2-3-test to release 2.3.3 #24762

Merged

rino0601 added a commit to rino0601/airflow that referenced this pull request Jul 3, 2022

Revert "Add %z for %(asctime)s to fix timezone for logs on UI (apache…

3cff1cd

…#24373)" This reverts commit 7de050c.

This was referenced Jul 3, 2022

Revert "Add %z for %(asctime)s to fix timezone for logs on UI (#24373)" #24810

Merged

Add %z for %(asctime)s to fix timezone for logs on UI #24811

Merged

ephraimbuddy added this to the Airflow 2.3.3 milestone Jul 5, 2022

ephraimbuddy added the type:bug-fix Changelog: Bug Fixes label Jul 5, 2022

ephraimbuddy modified the milestones: Airflow 2.3.3, Airflow 2.4.0 Jul 5, 2022

bbovenzi pushed a commit that referenced this pull request Jul 8, 2022

Revert "Add %z for %(asctime)s to fix timezone for logs on UI (#24373)…

8200723

…" (#24810) This reverts commit 7de050c.

ephraimbuddy added changelog:skip Changes that should be skipped from the changelog (CI, tests, etc..) and removed type:bug-fix Changelog: Bug Fixes labels Aug 12, 2022

ephraimbuddy removed this from the Airflow 2.4.0 milestone Aug 12, 2022

ephraimbuddy mentioned this pull request Aug 20, 2022

Status of testing of Apache Airflow 2.3.4rc1 #25846

Closed

53 tasks

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Add %z for %(asctime)s to fix timezone for logs on UI #24373

Add %z for %(asctime)s to fix timezone for logs on UI #24373

rino0601 commented Jun 10, 2022 •

edited

Loading

boring-cyborg bot commented Jun 10, 2022

bbovenzi commented Jun 13, 2022

uranusjr commented Jun 14, 2022 •

edited

Loading

rino0601 commented Jun 15, 2022 •

edited

Loading

uranusjr Jun 15, 2022

rino0601 Jun 15, 2022

bbovenzi Jun 15, 2022

rino0601 Jun 16, 2022 •

edited

Loading

bbovenzi Jun 16, 2022

rino0601 Jun 17, 2022

bbovenzi Jun 17, 2022

bbovenzi commented Jun 15, 2022

rino0601 commented Jun 19, 2022

uranusjr commented Jun 21, 2022

rino0601 commented Jun 22, 2022

uranusjr Jun 22, 2022 •

edited

Loading

rino0601 Jun 22, 2022 •

edited

Loading

github-actions bot commented Jun 22, 2022

uranusjr commented Jun 24, 2022

boring-cyborg bot commented Jun 24, 2022

potiuk commented Jun 24, 2022

millin commented Jul 1, 2022

rino0601 commented Jul 1, 2022

		@@ -0,0 +1 @@
		Support config ``[logging]log_formatter_class`` for overriding logging.Formatter

Add %z for %(asctime)s to fix timezone for logs on UI #24373

Add %z for %(asctime)s to fix timezone for logs on UI #24373

Conversation

rino0601 commented Jun 10, 2022 • edited Loading

boring-cyborg bot commented Jun 10, 2022

bbovenzi commented Jun 13, 2022

uranusjr commented Jun 14, 2022 • edited Loading

rino0601 commented Jun 15, 2022 • edited Loading

uranusjr Jun 15, 2022

Choose a reason for hiding this comment

rino0601 Jun 15, 2022

Choose a reason for hiding this comment

bbovenzi Jun 15, 2022

Choose a reason for hiding this comment

rino0601 Jun 16, 2022 • edited Loading

Choose a reason for hiding this comment

bbovenzi Jun 16, 2022

Choose a reason for hiding this comment

rino0601 Jun 17, 2022

Choose a reason for hiding this comment

bbovenzi Jun 17, 2022

Choose a reason for hiding this comment

bbovenzi commented Jun 15, 2022

rino0601 commented Jun 19, 2022

uranusjr commented Jun 21, 2022

rino0601 commented Jun 22, 2022

uranusjr Jun 22, 2022 • edited Loading

Choose a reason for hiding this comment

rino0601 Jun 22, 2022 • edited Loading

Choose a reason for hiding this comment

github-actions bot commented Jun 22, 2022

uranusjr commented Jun 24, 2022

boring-cyborg bot commented Jun 24, 2022

potiuk commented Jun 24, 2022

millin commented Jul 1, 2022

rino0601 commented Jul 1, 2022

rino0601 commented Jun 10, 2022 •

edited

Loading

uranusjr commented Jun 14, 2022 •

edited

Loading

rino0601 commented Jun 15, 2022 •

edited

Loading

rino0601 Jun 16, 2022 •

edited

Loading

uranusjr Jun 22, 2022 •

edited

Loading

rino0601 Jun 22, 2022 •

edited

Loading