Allow adapters to include python package logging in dbt logs

.changes/unreleased/Features-20230915-123733.yaml

@@ -0,0 +1,6 @@
+kind: Features
+body: 'Allow adapters to include package logs in dbt standard logging '
+time: 2023-09-15T12:37:33.862862-07:00
+custom:
+  Author: colin-rogers-dbt
+  Issue: "7859"

core/dbt/events/adapter_endpoint.py

@@ -1,7 +1,8 @@
 import traceback
 from dataclasses import dataclass
-from dbt.events.functions import fire_event
+from dbt.events.functions import fire_event, EVENT_MANAGER
 from dbt.events.contextvars import get_node_info
+from dbt.events.event_handler import set_package_logging
 from dbt.events.types import (
     AdapterEventDebug,
     AdapterEventInfo,
@@ -56,3 +57,10 @@ def critical(self, msg, *args):
             name=self.name, base_msg=str(msg), args=list(args), node_info=get_node_info()
         )
         fire_event(event)
+
+    @staticmethod
+    def set_adapter_dependency_log_level(package_name, level):
+        """By default, dbt suppresses non-dbt package logs. This method allows
+        you to set the log level for a specific package.
+        """
+        set_package_logging(package_name, level, EVENT_MANAGER)

core/dbt/events/event_handler.py

@@ -0,0 +1,40 @@
+import logging
+from typing import Union
+
+from dbt.events.base_types import EventLevel
+from dbt.events.types import Note
+
+from dbt.events.eventmgr import IEventManager
+
+_log_level_to_event_level_map = {
+    logging.DEBUG: EventLevel.DEBUG,
+    logging.INFO: EventLevel.INFO,
+    logging.WARN: EventLevel.WARN,
+    logging.WARNING: EventLevel.WARN,
+    logging.ERROR: EventLevel.ERROR,
+    logging.CRITICAL: EventLevel.ERROR,
+}
+
+
+class DbtEventLoggingHandler(logging.Handler):
+    """A logging handler that wraps the EventManager
+    This allows non-dbt packages to log to the dbt event stream.
+    All logs are generated as "Note" events.
+    """
+
+    def __init__(self, event_manager: IEventManager, level):
+        super().__init__(level)
+        self.event_manager = event_manager
+
+    def emit(self, record: logging.LogRecord):
+        note = Note(msg=record.getMessage())
+        level = _log_level_to_event_level_map[record.levelno]
+        self.event_manager.fire_event(e=note, level=level)
+
+
+def set_package_logging(package_name: str, log_level: Union[str, int], event_mgr: IEventManager):
+    """Attach dbt's custom logging handler to the package's logger."""
+    log = logging.getLogger(package_name)
+    log.setLevel(log_level)
+    event_handler = DbtEventLoggingHandler(event_manager=event_mgr, level=log_level)
+    log.addHandler(event_handler)

core/dbt/events/functions.py

@@ -95,7 +95,6 @@ def _get_stdout_config(
     level: EventLevel,
     log_cache_events: bool,
 ) -> LoggerConfig:
-
     return LoggerConfig(
         name="stdout_log",
         level=level,
@@ -127,6 +126,7 @@ def _get_logfile_config(
     level: EventLevel,
     log_file_max_bytes: int,
 ) -> LoggerConfig:
+
     return LoggerConfig(
         name="file_log",
         line_format=line_format,

tests/unit/test_event_handler.py

@@ -0,0 +1,40 @@
+import logging
+
+from dbt.events.base_types import EventLevel
+from dbt.events.event_handler import DbtEventLoggingHandler, set_package_logging
+from dbt.events.eventmgr import TestEventManager
+
+
+def test_event_logging_handler_emits_records_correctly():
+    event_manager = TestEventManager()
+    handler = DbtEventLoggingHandler(event_manager=event_manager, level=logging.DEBUG)
+    log = logging.getLogger("test")
+    log.setLevel(logging.DEBUG)
+    log.addHandler(handler)
+
+    log.debug("test")
+    log.info("test")
+    log.warning("test")
+    log.error("test")
+    log.exception("test")
+    log.critical("test")
+    assert len(event_manager.event_history) == 6
+    assert event_manager.event_history[0][1] == EventLevel.DEBUG
+    assert event_manager.event_history[1][1] == EventLevel.INFO
+    assert event_manager.event_history[2][1] == EventLevel.WARN
+    assert event_manager.event_history[3][1] == EventLevel.ERROR
+    assert event_manager.event_history[4][1] == EventLevel.ERROR
+    assert event_manager.event_history[5][1] == EventLevel.ERROR
+
+
+def test_set_package_logging_sets_level_correctly():
+    event_manager = TestEventManager()
+    log = logging.getLogger("test")
+    set_package_logging("test", logging.DEBUG, event_manager)
+    log.debug("debug")
+    assert len(event_manager.event_history) == 1
+    set_package_logging("test", logging.WARN, event_manager)
+    log.debug("debug 2")
+    assert len(event_manager.event_history) == 1
+    log.warning("warning")
+    assert len(event_manager.event_history) == 3  # warning logs create two events

tests/unit/test_events.py

@@ -1,3 +1,4 @@
+import logging
 import re
 from argparse import Namespace
 from typing import TypeVar
@@ -83,6 +84,12 @@ def test_formatting(self):
         event = types.JinjaLogDebug(msg=[1, 2, 3])
         assert isinstance(event.msg, str)
 
+    def test_set_adapter_dependency_log_level(self):
+        logger = AdapterLogger("dbt_tests")
+        package_log = logging.getLogger("test_package_log")
+        logger.set_adapter_dependency_log_level("test_package_log", "DEBUG")
+        package_log.debug("debug message")
+
 
 class TestEventCodes: