CT-1685: Restore certain aspects of legacy logging behavior important… (

#6443)

* CT-1685: Restore certain aspects of legacy logging behavior important to dbt-rpc

* CT-1658: And changelog entry

.changes/unreleased/Under the Hood-20221213-214106.yaml

@@ -0,0 +1,7 @@
+kind: Under the Hood
+body: Restore important legacy logging behaviors, following refactor which removed
+  them
+time: 2022-12-13T21:41:06.815133-05:00
+custom:
+  Author: peterallenwebb
+  Issue: "6437"

core/dbt/events/eventmgr.py

@@ -47,6 +47,33 @@ class LineFormat(Enum):
 }
 
 
+# We should consider fixing the problem, but log_level() can return a string for
+# DynamicLevel events, even thought it is supposed to return an EventLevel. This
+# function gets a string for the level, no matter what.
+def _get_level_str(e: BaseEvent) -> str:
+    return e.log_level().value if isinstance(e.log_level(), EventLevel) else str(e.log_level())
+
+
+# We need this function for now because the numeric log severity levels in
+# Python do not match those for logbook, so we have to explicitly call the
+# correct function by name.
+def send_to_logger(l, level: str, log_line: str):
+    if level == "test":
+        l.debug(log_line)
+    elif level == "debug":
+        l.debug(log_line)
+    elif level == "info":
+        l.info(log_line)
+    elif level == "warn":
+        l.warning(log_line)
+    elif level == "error":
+        l.error(log_line)
+    else:
+        raise AssertionError(
+            f"While attempting to log {log_line}, encountered the unhandled level: {level}"
+        )
+
+
 @dataclass
 class LoggerConfig:
     name: str
@@ -93,7 +120,7 @@ def write_line(self, e: BaseEvent):
         line = self.create_line(e)
         python_level = _log_level_map[e.log_level()]
         if self._python_logger is not None:
-            self._python_logger.log(python_level, line)
+            send_to_logger(self._python_logger, _get_level_str(e), line)
         elif self._stream is not None and _log_level_map[self.level] <= python_level:
             self._stream.write(line + "\n")
 
@@ -128,8 +155,7 @@ def create_debug_line(self, e: BaseEvent) -> str:
             log_line = f"\n\n{separator} {datetime.utcnow()} | {self.event_manager.invocation_id} {separator}\n"
         ts: str = datetime.utcnow().strftime("%H:%M:%S.%f")
         scrubbed_msg: str = self.scrubber(e.message())  # type: ignore
-        # log_level() for DynamicLevel events returns str instead of EventLevel
-        level = e.log_level().value if isinstance(e.log_level(), EventLevel) else e.log_level()
+        level = _get_level_str(e)
         log_line += (
             f"{self._get_color_tag()}{ts} [{level:<5}]{self._get_thread_name()} {scrubbed_msg}"
         )

core/dbt/events/functions.py

@@ -18,10 +18,6 @@
 LOG_VERSION = 3
 metadata_vars: Optional[Dict[str, str]] = None
 
-# The default event manager will not log anything, but some tests run code that
-# generates events, without configuring the event manager.
-EVENT_MANAGER: EventManager = EventManager()
-
 
 def setup_event_logger(log_path: str, level_override: Optional[EventLevel] = None):
     cleanup_event_logger()
@@ -114,6 +110,16 @@ def cleanup_event_logger():
     EVENT_MANAGER.callbacks.clear()
 
 
+# The default event manager will not log anything, but some tests run code that
+# generates events, without configuring the event manager, so we create an empty
+# manager here until there is a better testing strategy in place.
+EVENT_MANAGER: EventManager = EventManager()
+
+# Since dbt-rpc does not do its own log setup, we set up logbook if legacy
+# logging is enabled.
+if flags.ENABLE_LEGACY_LOGGER:
+    EVENT_MANAGER.add_logger(_get_logbook_log_config(None))
+
 # This global, and the following two functions for capturing stdout logs are
 # an unpleasant hack we intend to remove as part of API-ification. The GitHub
 # issue #6350 was opened for that work.