fix: Add level and logger name to default log format (#1233)

meltano · Dec 6, 2022 · c94ae17 · c94ae17
1 parent 48f20f4
commit c94ae17
Show file tree

Hide file tree

Showing 4 changed files with 42 additions and 15 deletions.
diff --git a/docs/implementation/logging.md b/docs/implementation/logging.md
@@ -1,13 +1,43 @@
-# Logging
+# [SDK Implementation Details](./index.md) - Logging
 
-Logs are configurable by the environment variables `<PLUGIN_NAME>_LOGLEVEL` (preferred)
+## Logging levels
+
+Logging levels are configurable by the environment variables `<PLUGIN_NAME>_LOGLEVEL` (preferred)
 or `LOGLEVEL`. Use `LOGLEVEL` when you intend to control the log output for all taps
 and targets running within the environment. In contrast, we recommend setting
 `<PLUGIN_NAME>_LOGLEVEL` for more granual control of each tap or target individually.
 
 From most verbose to least verbose, the accepted values for logging level are `debug`,
 `info`, `warning`, and `error`. Logging level inputs are case-insensitive.
 
+To use different logging levels for different loggers, see the [custom logging configuration](#custom-logging-configuration) section below.
+
+## Default log format
+
+The default log format is `"{asctime:23s} | {levelname:8s} | {name:20s} | {message}"`.
+
+This produces logs that look like this:
+
+```
+2022-12-05 19:46:46,744 | INFO     | my_tap               | Added 'child' as child stream to 'my_stream'
+2022-12-05 19:46:46,744 | INFO     | my_tap               | Beginning incremental sync of 'my_stream'...
+2022-12-05 19:46:46,744 | INFO     | my_tap               | Tap has custom mapper. Using 1 provided map(s).
+2022-12-05 19:46:46,745 | INFO     | my_tap               | Beginning full_table sync of 'child' with context: {'parent_id': 1}...
+2022-12-05 19:46:46,745 | INFO     | my_tap               | Tap has custom mapper. Using 1 provided map(s).
+2022-12-05 19:46:46,746 | INFO     | singer_sdk.metrics   | INFO METRIC: {"metric_type": "timer", "metric": "sync_duration", "value": 0.0005319118499755859, "tags": {"stream": "child", "context": {"parent_id": 1}, "status": "succeeded"}}
+2022-12-05 19:46:46,747 | INFO     | singer_sdk.metrics   | INFO METRIC: {"metric_type": "counter", "metric": "record_count", "value": 3, "tags": {"stream": "child", "context": {"parent_id": 1}}}
+2022-12-05 19:46:46,747 | INFO     | my_tap               | Beginning full_table sync of 'child' with context: {'parent_id': 2}...
+2022-12-05 19:46:46,748 | INFO     | singer_sdk.metrics   | INFO METRIC: {"metric_type": "timer", "metric": "sync_duration", "value": 0.0004410743713378906, "tags": {"stream": "child", "context": {"parent_id": 2}, "status": "succeeded"}}
+2022-12-05 19:46:46,748 | INFO     | singer_sdk.metrics   | INFO METRIC: {"metric_type": "counter", "metric": "record_count", "value": 3, "tags": {"stream": "child", "context": {"parent_id": 2}}}
+2022-12-05 19:46:46,749 | INFO     | my_tap               | Beginning full_table sync of 'child' with context: {'parent_id': 3}...
+2022-12-05 19:46:46,749 | INFO     | singer_sdk.metrics   | INFO METRIC: {"metric_type": "timer", "metric": "sync_duration", "value": 0.0004508495330810547, "tags": {"stream": "child", "context": {"parent_id": 3}, "status": "succeeded"}}
+2022-12-05 19:46:46,750 | INFO     | singer_sdk.metrics   | INFO METRIC: {"metric_type": "counter", "metric": "record_count", "value": 3, "tags": {"stream": "child", "context": {"parent_id": 3}}}
+2022-12-05 19:46:46,750 | INFO     | singer_sdk.metrics   | INFO METRIC: {"metric_type": "timer", "metric": "sync_duration", "value": 0.0052759647369384766, "tags": {"stream": "my_stream", "context": {}, "status": "succeeded"}}
+2022-12-05 19:46:46,750 | INFO     | singer_sdk.metrics   | INFO METRIC: {"metric_type": "counter", "metric": "record_count", "value": 3, "tags": {"stream": "my_stream", "context": {}}}
+```
+
+To use a different log format, see the [custom logging configuration](#custom-logging-configuration) section below.
+
 ## Custom logging configuration
 
 Users of a tap can configure the SDK logging by setting the `SINGER_SDK_LOG_CONFIG`

diff --git a/poetry.lock b/poetry.lock
diff --git a/singer_sdk/default_logging.yml b/singer_sdk/default_logging.yml
@@ -2,7 +2,7 @@ version: 1
 disable_existing_loggers: false
 formatters:
   console:
-    format: "{asctime} {message}"
+    format: "{asctime:23s} | {levelname:8s} | {name:20s} | {message}"
     style: "{"
 handlers:
   default:
@@ -11,5 +11,4 @@ handlers:
     stream: ext://sys.stderr
 root:
   level: INFO
-  propagate: true
   handlers: [default]
diff --git a/singer_sdk/plugin_base.py b/singer_sdk/plugin_base.py
@@ -63,17 +63,15 @@ def logger(cls) -> logging.Logger:
             Plugin logger.
         """
         # Get the level from <PLUGIN_NAME>_LOGLEVEL or LOGLEVEL environment variables
-        LOGLEVEL = (
-            os.environ.get(f"{cls.name.upper()}_LOGLEVEL")
-            or os.environ.get("LOGLEVEL")
-            or "INFO"
-        ).upper()
-
-        assert (
-            LOGLEVEL in logging._levelToName.values()
-        ), f"Invalid LOGLEVEL configuration: {LOGLEVEL}"
+        LOGLEVEL = os.environ.get(f"{cls.name.upper()}_LOGLEVEL") or os.environ.get(
+            "LOGLEVEL"
+        )
+
         logger = logging.getLogger(cls.name)
-        logger.setLevel(LOGLEVEL)
+
+        if LOGLEVEL is not None and LOGLEVEL.upper() in logging._levelToName.values():
+            logger.setLevel(LOGLEVEL.upper())
+
         return logger
 
     # Constructor