Merge pull request #71560 from xogoodnow/json-utc-formatted-log

Added UTC date format (RFC 3339) for json formatted logging

docs/en/operations/server-configuration-parameters/settings.md

@@ -1643,6 +1643,7 @@ You can specify the log format that will be outputted in the console log. Curren
 
 ```json
 {
+  "date_time_utc": "2024-11-06T09:06:09Z",
   "date_time": "1650918987.180175",
   "thread_name": "#1",
   "thread_id": "254545",

programs/server/config.xml

@@ -70,12 +70,15 @@
         You can specify log format(for now, JSON only). In that case, the console log will be printed
         in specified format like JSON.
         For example, as below:
+
         {"date_time":"1650918987.180175","thread_name":"#1","thread_id":"254545","level":"Trace","query_id":"","logger_name":"BaseDaemon","message":"Received signal 2","source_file":"../base/daemon/BaseDaemon.cpp; virtual void SignalListener::run()","source_line":"192"}
+        {"date_time_utc":"2024-11-06T09:06:09Z","thread_name":"#1","thread_id":"254545","level":"Trace","query_id":"","logger_name":"BaseDaemon","message":"Received signal 2","source_file":"../base/daemon/BaseDaemon.cpp; virtual void SignalListener::run()","source_line":"192"}
         To enable JSON logging support, please uncomment the entire <formatting> tag below.
 
         a) You can modify key names by changing values under tag values inside <names> tag.
         For example, to change DATE_TIME to MY_DATE_TIME, you can do like:
             <date_time>MY_DATE_TIME</date_time>
+            <date_time_utc>MY_UTC_DATE_TIME</date_time_utc>
         b) You can stop unwanted log properties to appear in logs. To do so, you can simply comment out (recommended)
         that property from this file.
         For example, if you do not want your log to print query_id, you can comment out only <query_id> tag.
@@ -86,6 +89,7 @@
             <type>json</type>
             <names>
                 <date_time>date_time</date_time>
+                <date_time_utc>date_time_utc</date_time_utc>
                 <thread_name>thread_name</thread_name>
                 <thread_id>thread_id</thread_id>
                 <level>level</level>

src/Loggers/OwnJSONPatternFormatter.cpp

@@ -7,12 +7,18 @@
 #include <base/terminalColors.h>
 #include <Common/CurrentThread.h>
 #include <Common/HashTable/Hash.h>
+#include <Common/DateLUT.h>
+#include <Common/DateLUTImpl.h>
+
 
 OwnJSONPatternFormatter::OwnJSONPatternFormatter(Poco::Util::AbstractConfiguration & config)
 {
     if (config.has("logger.formatting.names.date_time"))
         date_time = config.getString("logger.formatting.names.date_time", "");
 
+    if (config.has("logger.formatting.names.date_time_utc"))
+        date_time_utc= config.getString("logger.formatting.names.date_time_utc", "");
+
     if (config.has("logger.formatting.names.thread_name"))
         thread_name = config.getString("logger.formatting.names.thread_name", "");
 
@@ -41,6 +47,7 @@ OwnJSONPatternFormatter::OwnJSONPatternFormatter(Poco::Util::AbstractConfigurati
         && logger_name.empty() && message.empty() && source_file.empty() && source_line.empty())
     {
         date_time = "date_time";
+        date_time_utc = "date_time_utc";
         thread_name = "thread_name";
         thread_id = "thread_id";
         level = "level";
@@ -62,8 +69,22 @@ void OwnJSONPatternFormatter::formatExtended(const DB::ExtendedLogMessage & msg_
     const Poco::Message & msg = msg_ext.base;
     DB::writeChar('{', wb);
 
+    if (!date_time_utc.empty())
+    {
+        writeJSONString(date_time_utc, wb, settings);
+        DB::writeChar(':', wb);
+
+        DB::writeChar('\"', wb);
+        static const DateLUTImpl & utc_time_zone = DateLUT::instance("UTC");
+        writeDateTimeTextISO(msg_ext.time_seconds, 0, wb, utc_time_zone);
+
+        DB::writeChar('\"', wb);
+        print_comma = true;
+    }
+
     if (!date_time.empty())
     {
+        if (print_comma) DB::writeChar(',', wb);
         writeJSONString(date_time, wb, settings);
         DB::writeChar(':', wb);
 
@@ -81,6 +102,7 @@ void OwnJSONPatternFormatter::formatExtended(const DB::ExtendedLogMessage & msg_
         print_comma = true;
     }
 
+
     if (!thread_name.empty())
     {
         if (print_comma)

src/Loggers/OwnJSONPatternFormatter.h

@@ -33,6 +33,7 @@ public:
 
 private:
     std::string date_time;
+    std::string date_time_utc;
     std::string thread_name;
     std::string thread_id;
     std::string level;

tests/integration/test_structured_logging_json/configs/config_all_keys_json.xml

@@ -6,12 +6,14 @@
         in specified format like JSON.
         For example, as below:
         {"date_time":"1650918987.180175","thread_name":"#1","thread_id":"254545","level":"Trace","query_id":"","logger_name":"BaseDaemon","message":"Received signal 2","source_file":"../base/daemon/BaseDaemon.cpp; virtual void SignalListener::run()","source_line":"192"}
+        {"date_time_utc":"2024-11-06T09:06:09Z","thread_name":"#1","thread_id":"254545","level":"Trace","query_id":"","logger_name":"BaseDaemon","message":"Received signal 2","source_file":"../base/daemon/BaseDaemon.cpp; virtual void SignalListener::run()","source_line":"192"}
         To enable JSON logging support, just uncomment <formatting> tag below.
         -->
         <formatting>
             <type>json</type>
             <names>
                 <date_time>DATE_TIME</date_time>
+                <date_time_utc>DATE_TIME_UTC</date_time_utc>
                 <thread_name>THREAD_NAME</thread_name>
                 <thread_id>THREAD_ID</thread_id>
                 <level>LEVEL</level>

tests/integration/test_structured_logging_json/configs/config_json.xml

@@ -5,12 +5,14 @@
         in specified format like JSON.
         For example, as below:
         {"date_time":"1650918987.180175","thread_name":"#1","thread_id":"254545","level":"Trace","query_id":"","logger_name":"BaseDaemon","message":"Received signal 2","source_file":"../base/daemon/BaseDaemon.cpp; virtual void SignalListener::run()","source_line":"192"}
+        {"date_time_utc":"2024-11-06T09:06:09Z","thread_name":"#1","thread_id":"254545","level":"Trace","query_id":"","logger_name":"BaseDaemon","message":"Received signal 2","source_file":"../base/daemon/BaseDaemon.cpp; virtual void SignalListener::run()","source_line":"192"}
         To enable JSON logging support, just uncomment <formatting> tag below.
         -->
         <formatting>
             <type>json</type>
             <names>
                 <date_time>DATE_TIME</date_time>
+                <date_time_utc>DATE_TIME_UTC</date_time_utc>
                 <thread_name>THREAD_NAME</thread_name>
                 <thread_id>THREAD_ID</thread_id>
                 <level>LEVEL</level>

tests/integration/test_structured_logging_json/configs/config_no_keys_json.xml

@@ -6,12 +6,14 @@
         in specified format like JSON.
         For example, as below:
         {"date_time":"1650918987.180175","thread_name":"#1","thread_id":"254545","level":"Trace","query_id":"","logger_name":"BaseDaemon","message":"Received signal 2","source_file":"../base/daemon/BaseDaemon.cpp; virtual void SignalListener::run()","source_line":"192"}
+        {"date_time_utc":"2024-11-06T09:06:09Z","thread_name":"#1","thread_id":"254545","level":"Trace","query_id":"","logger_name":"BaseDaemon","message":"Received signal 2","source_file":"../base/daemon/BaseDaemon.cpp; virtual void SignalListener::run()","source_line":"192"}
         To enable JSON logging support, just uncomment <formatting> tag below.
         -->
         <formatting>
             <type>json</type>
             <!--<names>
                 <date_time>DATE_TIME</date_time>
+                <date_time_utc>DATE_TIME_UTC</date_time_utc>
                 <thread_name>THREAD_NAME</thread_name>
                 <thread_id>THREAD_ID</thread_id>
                 <level>LEVEL</level>

tests/integration/test_structured_logging_json/configs/config_some_keys_json.xml

@@ -6,12 +6,14 @@
         in specified format like JSON.
         For example, as below:
         {"date_time":"1650918987.180175","thread_name":"#1","thread_id":"254545","level":"Trace","query_id":"","logger_name":"BaseDaemon","message":"Received signal 2","source_file":"../base/daemon/BaseDaemon.cpp; virtual void SignalListener::run()","source_line":"192"}
+        {"date_time_utc":"2024-11-06T09:06:09Z","thread_name":"#1","thread_id":"254545","level":"Trace","query_id":"","logger_name":"BaseDaemon","message":"Received signal 2","source_file":"../base/daemon/BaseDaemon.cpp; virtual void SignalListener::run()","source_line":"192"}
         To enable JSON logging support, just uncomment <formatting> tag below.
         -->
         <formatting>
             <type>json</type>
             <names>
                 <date_time>DATE_TIME</date_time>
+                <date_time_utc>DATE_TIME_UTC</date_time_utc>
                 <thread_name>THREAD_NAME</thread_name>
                 <thread_id>THREAD_ID</thread_id>
                 <level>LEVEL</level>

tests/integration/test_structured_logging_json/test.py

@@ -1,4 +1,5 @@
 import json
+from datetime import datetime
 from xml.etree import ElementTree as ET
 
 import pytest
@@ -58,12 +59,25 @@ def validate_log_level(config, logs):
     return True
 
 
+def is_valid_utc_datetime(datetime_str):
+    try:
+        datetime.strptime(datetime_str, "%Y-%m-%dT%H:%M:%S.%fZ")
+        return True
+    except ValueError:
+        try:
+            datetime.strptime(datetime_str, "%Y-%m-%dT%H:%M:%SZ")
+            return True
+        except ValueError:
+            return False
+
+
 def validate_log_config_relation(config, logs, config_type):
     root = ET.fromstring(config)
     keys_in_config = set()
 
     if config_type == "config_no_keys":
         keys_in_config.add("date_time")
+        keys_in_config.add("date_time_utc")
         keys_in_config.add("thread_name")
         keys_in_config.add("thread_id")
         keys_in_config.add("level")
@@ -80,14 +94,17 @@ def validate_log_config_relation(config, logs, config_type):
         length = min(10, len(logs))
         for i in range(0, length):
             json_log = json.loads(logs[i])
-            keys_in_log = set()
+            keys_in_log = set(json_log.keys())
-            for log_key in json_log.keys():
+
-                keys_in_log.add(log_key)
+            if not keys_in_config.issubset(keys_in_log):
-                if log_key not in keys_in_config:
+                return False
-                    return False
+
-            for config_key in keys_in_config:
+            # Validate the UTC datetime format in "date_time_utc" if it exists
-                if config_key not in keys_in_log:
+            if "date_time_utc" in json_log and not is_valid_utc_datetime(
-                    return False
+                json_log["date_time_utc"]
+            ):
+                return False
+
     except ValueError as e:
         return False
     return True
@@ -101,7 +118,7 @@ def validate_logs(logs):
     return result
 
 
-def valiade_everything(config, node, config_type):
+def validate_everything(config, node, config_type):
     node.query("SELECT 1")
     logs = node.grep_in_log("").split("\n")
     return (
@@ -122,8 +139,11 @@ def test_structured_logging_json_format(start_cluster):
         ["cat", "/etc/clickhouse-server/config.d/config_no_keys_json.xml"]
     )
 
-    assert valiade_everything(config_all_keys, node_all_keys, "config_all_keys") == True
     assert (
-        valiade_everything(config_some_keys, node_some_keys, "config_some_keys") == True
+        validate_everything(config_all_keys, node_all_keys, "config_all_keys") == True
     )
-    assert valiade_everything(config_no_keys, node_no_keys, "config_no_keys") == True
+    assert (
+        validate_everything(config_some_keys, node_some_keys, "config_some_keys")
+        == True
+    )
+    assert validate_everything(config_no_keys, node_no_keys, "config_no_keys") == True