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

airflow/config_templates/airflow_local_settings.py

@@ -31,13 +31,16 @@
 # settings.py and cli.py. Please see AIRFLOW-1455.
 LOG_LEVEL: str = conf.get_mandatory_value('logging', 'LOGGING_LEVEL').upper()
 
-
 # Flask appbuilder's info level log is very verbose,
 # so it's set to 'WARN' by default.
 FAB_LOG_LEVEL: str = conf.get_mandatory_value('logging', 'FAB_LOGGING_LEVEL').upper()
 
 LOG_FORMAT: str = conf.get_mandatory_value('logging', 'LOG_FORMAT')
 
+LOG_FORMATTER_CLASS: str = conf.get_mandatory_value(
+    'logging', 'LOG_FORMATTER_CLASS', fallback='airflow.utils.log.timezone_aware.TimezoneAware'
+)
+
 COLORED_LOG_FORMAT: str = conf.get_mandatory_value('logging', 'COLORED_LOG_FORMAT')
 
 COLORED_LOG: bool = conf.getboolean('logging', 'COLORED_CONSOLE_LOG')
@@ -60,10 +63,13 @@
     'version': 1,
     'disable_existing_loggers': False,
     'formatters': {
-        'airflow': {'format': LOG_FORMAT},
+        'airflow': {
+            'format': LOG_FORMAT,
+            'class': LOG_FORMATTER_CLASS,
+        },
         'airflow_coloured': {
             'format': COLORED_LOG_FORMAT if COLORED_LOG else LOG_FORMAT,
-            'class': COLORED_FORMATTER_CLASS if COLORED_LOG else 'logging.Formatter',
+            'class': COLORED_FORMATTER_CLASS if COLORED_LOG else LOG_FORMATTER_CLASS,
         },
     },
     'filters': {

airflow/config_templates/config.yml

@@ -633,6 +633,12 @@
       type: string
       example: ~
       default: "%%(asctime)s %%(levelname)s - %%(message)s"
+    - name: log_formatter_class
+      description: ~
+      version_added: 2.3.3
+      type: string
+      example: ~
+      default: "airflow.utils.log.timezone_aware.TimezoneAware"
     - name: task_log_prefix_template
       description: |
         Specify prefix pattern like mentioned below with stream handler TaskHandlerWithCustomFormatter

airflow/config_templates/default_airflow.cfg

@@ -349,6 +349,7 @@ colored_formatter_class = airflow.utils.log.colored_log.CustomTTYColoredFormatte
 # Format of Log line
 log_format = [%%(asctime)s] {{%%(filename)s:%%(lineno)d}} %%(levelname)s - %%(message)s
 simple_log_format = %%(asctime)s %%(levelname)s - %%(message)s
+log_formatter_class = airflow.utils.log.timezone_aware.TimezoneAware
 
 # Specify prefix pattern like mentioned below with stream handler TaskHandlerWithCustomFormatter
 # Example: task_log_prefix_template = {{ti.dag_id}}-{{ti.task_id}}-{{execution_date}}-{{try_number}}

airflow/utils/log/colored_log.py

@@ -43,6 +43,10 @@ class CustomTTYColoredFormatter(TTYColoredFormatter):
     traceback.
     """
 
+    # copy of airflow.utils.log.timezone_aware.TimezoneAware
+    default_time_format = '%Y-%m-%d %H:%M:%S%z'
+    default_msec_format = '%s %03dms'
+
     def __init__(self, *args, **kwargs):
         kwargs["stream"] = sys.stdout or kwargs.get("stream")
         kwargs["log_colors"] = DEFAULT_COLORS

airflow/utils/log/timezone_aware.py

@@ -0,0 +1,39 @@
+#
+# 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.
+import logging
+
+
+class TimezoneAware(logging.Formatter):
+    """
+    Override `default_time_format` and `default_msec_format` to specify utc offset.
+
+    utc offset is the matter, without it,  time conversion could be wrong. With this Formatter, `%(asctime)s`
+    will be formatted containing utc offset. (e.g. 2022-06-12 13:00:00+0000 123ms)
+
+    moments.js couldn't parse milliseconds comes after utc offset, so it would be ideal `%(asctime)s`
+    formatted with millisecond comes before utc offset in th first place. (e.g 2022-06-12 13:00:00.123+0000)
+    But python standard lib doesn't support format like that.
+
+    Omitting milliseconds is possible by assigning `default_msec_format` to `None`. But this requires
+    python3.9 or higher, so we can't omit milliseconds until dropping support 3.8 or under.
+
+    Therefore, to use in moments.js, formatted `%(asctime)s` has to be re-formatted by javascript side.
+    """
+
+    default_time_format = '%Y-%m-%d %H:%M:%S%z'
+    default_msec_format = '%s %03dms'

airflow/www/static/js/grid/details/content/taskInstance/Logs/utils.js

@@ -48,17 +48,39 @@ export const parseLogs = (data, timezone, logLevelFilter, fileSourceFilter) => {
     }
 
     const regExp = /\[(.*?)\] \{(.*?)\}/;
+    // e.g) '2022-06-15 10:30:06,020' or '2022-06-15 10:30:06+0900'
+    const dateRegex = /(\d{4}[./-]\d{2}[./-]\d{2} \d{2}:\d{2}:\d{2})((,\d{3})|([+-]\d{4} \d{3}ms))/;
+    // above regex is a kind of duplication of 'dateRegex'
+    // in airflow/www/static/js/tl_log.js
     const matches = line.match(regExp);
     let logGroup = '';
     if (matches) {
-      // Replace UTC with the local timezone.
+      // Replace system timezone with user selected timezone.
       const dateTime = matches[1];
-      [logGroup] = matches[2].split(':');
-      if (dateTime && timezone) {
-        const localDateTime = moment.utc(dateTime).tz(timezone).format(defaultFormatWithTZ);
-        parsedLine = line.replace(dateTime, localDateTime);
-      }
 
+      // e.g) '2022-06-15 10:30:06,020' or '2022-06-15 10:30:06+0900 123ms'
+      const dateMatches = dateTime?.match(dateRegex);
+      if (dateMatches) {
+        const [date, msecOrUTCOffset] = [dateMatches[1], dateMatches[2]];
+        if (msecOrUTCOffset.startsWith(',')) { // e.g) date='2022-06-15 10:30:06', msecOrUTCOffset=',020'
+          // for backward compatibility. (before 2.3.3)
+          // keep previous behavior if utcoffset not found. (consider it UTC)
+          //
+          if (dateTime && timezone) { // dateTime === fullMatch
+            const localDateTime = moment.utc(dateTime).tz(timezone).format(defaultFormatWithTZ);
+            parsedLine = line.replace(dateTime, localDateTime);
+          }
+        } else {
+          // e.g) date='2022-06-15 10:30:06', msecOrUTCOffset='+0900 123ms'
+          // (formatted by airflow.utils.log.timezone_aware.TimezoneAware) (since 2.3.3)
+          const [utcoffset, threeDigitMs] = msecOrUTCOffset.split(' ');
+          const msec = threeDigitMs.replace(/\D+/g, ''); // drop 'ms'
+          // e.g) datetime='2022-06-15 10:30:06.123+0900'
+          const localDateTime = moment(`${date}.${msec}${utcoffset}`).tz(timezone).format(defaultFormatWithTZ);
+          parsedLine = line.replace(dateTime, localDateTime);
+        }
+      }
+      [logGroup] = matches[2].split(':');
       fileSources.add(logGroup);
     }
     if (!fileSourceFilter || fileSourceFilter === logGroup) {

airflow/www/static/js/ti_log.js

@@ -102,7 +102,9 @@ function autoTailingLog(tryNumber, metadata = null, autoTailing = false) {
 
       // Detect urls and log timestamps
       const urlRegex = /http(s)?:\/\/[\w.-]+(\.?:[\w.-]+)*([/?#][\w\-._~:/?#[\]@!$&'()*+,;=.%]+)?/g;
-      const dateRegex = /\d{4}[./-]\d{2}[./-]\d{2} \d{2}:\d{2}:\d{2},\d{3}/g;
+      const dateRegex = /(\d{4}[./-]\d{2}[./-]\d{2} \d{2}:\d{2}:\d{2})((,\d{3})|([+-]\d{4} \d{3}ms))/g;
+      // above regex is a kind of duplication of 'dateRegex'
+      // in airflow/www/static/js/grid/details/content/taskinstance/Logs/utils.js
 
       res.message.forEach((item) => {
         const logBlockElementId = `try-${tryNumber}-${item[0]}`;
@@ -120,7 +122,22 @@ function autoTailingLog(tryNumber, metadata = null, autoTailing = false) {
         const escapedMessage = escapeHtml(item[1]);
         const linkifiedMessage = escapedMessage
           .replace(urlRegex, (url) => `<a href="${url}" target="_blank">${url}</a>`)
-          .replaceAll(dateRegex, (date) => `<time datetime="${date}+00:00" data-with-tz="true">${formatDateTime(`${date}+00:00`)}</time>`);
+          .replaceAll(dateRegex, (dateMatches, date, msecOrUTCOffset) => {
+            // e.g) '2022-06-15 10:30:06,020' or '2022-06-15 10:30:06+0900 123ms'
+            if (msecOrUTCOffset.startsWith(',')) { // e.g) date='2022-06-15 10:30:06', msecOrUTCOffset=',020'
+              // for backward compatibility. (before 2.3.3)
+              // keep previous behavior if utcoffset not found.
+              //
+              return `<time datetime="${dateMatches}+00:00" data-with-tz="true">${formatDateTime(`${dateMatches}+00:00`)}</time>`;
+            }
+            // e.g) date='2022-06-15 10:30:06', msecOrUTCOffset='+0900 123ms'
+            // (formatted by airflow.utils.log.timezone_aware.TimezoneAware) (since 2.3.3)
+            const [utcoffset, threeDigitMs] = msecOrUTCOffset.split(' ');
+            const msec = threeDigitMs.replace(/\D+/g, ''); // drop 'ms'
+            const dateTime = `${date}.${msec}${utcoffset}`; // e.g) datetime='2022-06-15 10:30:06.123+0900'
+            //
+            return `<time datetime="${dateTime}" data-with-tz="true">${formatDateTime(`${dateTime}`)}</time>`;
+          });
         logBlock.innerHTML += `${linkifiedMessage}\n`;
       });
 

newsfragments/24373.significant.rst

@@ -0,0 +1,23 @@
+Added new config ``[logging]log_formatter_class`` to fix timezone display for logs on UI
+
+If you are using a custom Formatter subclass in your ``[logging]logging_config_class``, please inherit from ``airflow.utils.log.timezone_aware.TimezoneAware`` instead of ``logging.Formatter``.
+For example, in your ``custom_config.py``:
+
+.. code-block:: python
+
+   from airflow.utils.log.timezone_aware import TimezoneAware
+
+   # before
+   class YourCustomFormatter(logging.Formatter):
+       ...
+
+
+   # after
+   class YourCustomFormatter(TimezoneAware):
+       ...
+
+
+   AIRFLOW_FORMATTER = LOGGING_CONFIG["formatters"]["airflow"]
+   AIRFLOW_FORMATTER["class"] = "somewhere.your.custom_config.YourCustomFormatter"
+   # or use TimezoneAware class directly. If you don't have custom Formatter.
+   AIRFLOW_FORMATTER["class"] = "airflow.utils.log.timezone_aware.TimezoneAware"