fix!: remove time field from structured logs (#263)

Summary:

The initial version of structured logs contained a 'time' field within
the structure. This field is redundant when forwarded to AWS CloudWatch.
This removes it.  It also:

1. Modified the bootstrap log to always be structured (the worker-agent.log file contains
    the same info in an unstructured manner); and
2. Modified the structured formatting for host-local destinations to prepend the log line
    with the timestamp.

Signed-off-by: Daniel Neilson <53624638+ddneilson@users.noreply.github.com>

README.md

@@ -57,9 +57,8 @@ with information about the specific log event.
 
 All log events structures contain:
 
-1. An `time` field that indicates the local time on the host at which the event was generated.
-2. A `level` field that indicates the severity of the log event, following the typical Python Logger
-   semantics: INFO, WARNING, ERROR, EXCEPTION, and CRITICAL.
+- A `level` field that indicates the severity of the log event, following the typical Python Logger
+  semantics: INFO, WARNING, ERROR, EXCEPTION, and CRITICAL.
 
 Log events may also contain a `type`, `subtype`, icon (`ti`), and additional fields as indicated in the following table.
 

src/deadline_worker_agent/log_messages.py

@@ -559,10 +559,9 @@ def filter(self, record: logging.LogRecord) -> bool:
             record.exc_info = None
 
         if not hasattr(record, "json"):
-            # Order is important here; we want 'time to be first followed by 'level'
+            # Order is important here; we want 'level' to be the first thing
             # when printing the dictionary as a string.
             structure = {
-                "time": self.formatter.formatTime(record, self.formatter.datefmt),
                 "level": record.levelname,
             }
             if isinstance(record.msg, BaseLogEvent):

src/deadline_worker_agent/startup/entrypoint.py

@@ -359,7 +359,7 @@ def _configure_base_logging(
         console_handler = RichHandler(rich_tracebacks=True, tracebacks_show_locals=verbose)
 
     if structured_logs:
-        fmt_str = "%(json)s"
+        fmt_str = "[%(asctime)s] %(json)s"
     else:
         fmt_str = "[%(asctime)s][%(levelname)-8s] %(desc)s%(message)s"
     console_handler.formatter = logging.Formatter(fmt_str)
@@ -380,7 +380,10 @@ def _configure_base_logging(
         when="d",
         interval=1,
     )
-    bootstrapping_handler.formatter = logging.Formatter(fmt_str)
+    # Bootstrap file should always be json. It's primarily intended
+    # for use by Service Managed Fleet workers, and needs to be queryable
+    # via AWS CloudWatch logs.
+    bootstrapping_handler.formatter = logging.Formatter("%(json)s")
     root_logger.addHandler(bootstrapping_handler)
     bootstrapping_handler.addFilter(translation_filter)
 

test/unit/startup/test_entrypoint.py

@@ -270,11 +270,16 @@ def test_configuration_logged(
 @pytest.mark.parametrize(
     ("verbose", "expected_root_log_level", "expected_console_fmt_str"),
     (
-        pytest.param(False, logging.INFO, "%(json)s", id="non-verbose"),
+        pytest.param(
+            False,
+            logging.INFO,
+            "[%(asctime)s][%(levelname)-8s] %(desc)s%(message)s",
+            id="non-verbose",
+        ),
         pytest.param(
             True,
             logging.DEBUG,
-            "%(json)s",
+            "[%(asctime)s][%(levelname)-8s] %(desc)s%(message)s",
             id="verbose",
         ),
     ),
@@ -304,6 +309,7 @@ def test_log_configuration(
         _config_mock.load().worker_credentials_dir.mkdir()
         # Required because MagicMock does not support int comparison
         _config_mock.load().host_metrics_logging_interval_seconds = 10
+        _config_mock.load().structured_logs = False
 
         # Mock logging.getLogger
         root_logger = MagicMock()

test/unit/test_log_messages.py

@@ -550,11 +550,8 @@ def test_messages_logged(
     assert text_result == expected_message
 
     # Make sure that the generated json is as expected
-    assert "time" in dict_result
-    assert list(dict_result.keys())[0] == "time"  # time is first
     assert dict_result.get("level") == record.levelname
-    assert list(dict_result.keys())[1] == "level"  # level is second
-    del dict_result["time"]
+    assert list(dict_result.keys())[0] == "level"  # level is fist
     del dict_result["level"]
     assert dict_result == expected_dict
     assert list(dict_result.keys()) == list(expected_dict.keys()), "Key ordering differs"
@@ -610,7 +607,7 @@ def test_messages_logged_exception(
         'in test_messages_logged_exception\n    raise RuntimeError("Test exception!")\nRuntimeError: Test exception!'
         in dict_result["exception"]
     )
-    for extra_key in ("time", "level", "exception"):
+    for extra_key in ("level", "exception"):
         del dict_result[extra_key]
     assert dict_result == expected_dict