Minor Cleanup of Structured Logging Module (#4266)

* cleanup structured logging module

* update adapter logger to preserve new-style logging formatting

core/dbt/events/adapter_endpoint.py

@@ -3,84 +3,63 @@
 from dbt.events.types import (
     AdapterEventDebug, AdapterEventInfo, AdapterEventWarning, AdapterEventError
 )
-from typing import Any
 
 
 @dataclass
 class AdapterLogger():
     name: str
 
-    def debug(
-        self,
-        msg: str,
-        exc_info: Any = None,
-        stack_info: Any = None,
-        extra: Any = None
-    ):
-        event = AdapterEventDebug(name=self.name, raw_msg=msg)
+    def debug(self, msg, *args, exc_info=None, extra=None, stack_info=False):
+        event = AdapterEventDebug(name=self.name, base_msg=msg, args=args)
 
         event.exc_info = exc_info
-        event.stack_info = stack_info
         event.extra = extra
+        event.stack_info = stack_info
 
         fire_event(event)
 
-    def info(
-        self,
-        msg: str,
-        exc_info: Any = None,
-        stack_info: Any = None,
-        extra: Any = None
-    ):
-        event = AdapterEventInfo(name=self.name, raw_msg=msg)
+    def info(self, msg, *args, exc_info=None, extra=None, stack_info=False):
+        event = AdapterEventInfo(name=self.name, base_msg=msg, args=args)
 
         event.exc_info = exc_info
-        event.stack_info = stack_info
         event.extra = extra
+        event.stack_info = stack_info
 
         fire_event(event)
 
-    def warning(
-        self,
-        msg: str,
-        exc_info: Any = None,
-        stack_info: Any = None,
-        extra: Any = None
-    ):
-        event = AdapterEventWarning(name=self.name, raw_msg=msg)
+    def warning(self, msg, *args, exc_info=None, extra=None, stack_info=False):
+        event = AdapterEventWarning(name=self.name, base_msg=msg, args=args)
 
         event.exc_info = exc_info
-        event.stack_info = stack_info
         event.extra = extra
+        event.stack_info = stack_info
 
         fire_event(event)
 
-    def error(
-        self,
-        msg: str,
-        exc_info: Any = None,
-        stack_info: Any = None,
-        extra: Any = None
-    ):
-        event = AdapterEventError(name=self.name, raw_msg=msg)
+    def error(self, msg, *args, exc_info=None, extra=None, stack_info=False):
+        event = AdapterEventError(name=self.name, base_msg=msg, args=args)
 
         event.exc_info = exc_info
-        event.stack_info = stack_info
         event.extra = extra
+        event.stack_info = stack_info
 
         fire_event(event)
 
-    def exception(
-        self,
-        msg: str,
-        exc_info: Any = True,  # this default is what makes this method different
-        stack_info: Any = None,
-        extra: Any = None
-    ):
-        event = AdapterEventError(name=self.name, raw_msg=msg)
+    # The default exc_info=True is what makes this method different
+    def exception(self, msg, *args, exc_info=True, extra=None, stack_info=False):
+        event = AdapterEventError(name=self.name, base_msg=msg, args=args)
 
         event.exc_info = exc_info
+        event.extra = extra
         event.stack_info = stack_info
+
+        fire_event(event)
+
+    def critical(self, msg, *args, exc_info=False, extra=None, stack_info=False):
+        event = AdapterEventError(name=self.name, base_msg=msg, args=args)
+
+        event.exc_info = exc_info
         event.extra = extra
+        event.stack_info = stack_info
 
         fire_event(event)

core/dbt/events/base_types.py

@@ -0,0 +1,95 @@
+from abc import ABCMeta, abstractmethod
+from dataclasses import dataclass
+from datetime import datetime
+import os
+from typing import Any
+
+
+# # # # # # # # # # # # # # # # # # # # # # # # # # # # # # # # # # # # # #
+# These base types define the _required structure_ for the concrete event #
+# types defined in types.py                                               #
+# # # # # # # # # # # # # # # # # # # # # # # # # # # # # # # # # # # # # #
+
+
+# in preparation for #3977
+class TestLevel():
+    def level_tag(self) -> str:
+        return "test"
+
+
+class DebugLevel():
+    def level_tag(self) -> str:
+        return "debug"
+
+
+class InfoLevel():
+    def level_tag(self) -> str:
+        return "info"
+
+
+class WarnLevel():
+    def level_tag(self) -> str:
+        return "warn"
+
+
+class ErrorLevel():
+    def level_tag(self) -> str:
+        return "error"
+
+
+@dataclass
+class ShowException():
+    # N.B.:
+    # As long as we stick with the current convention of setting the member vars in the
+    # `message` method of subclasses, this is a safe operation.
+    # If that ever changes we'll want to reassess.
+    def __post_init__(self):
+        self.exc_info: Any = True
+        self.stack_info: Any = None
+        self.extra: Any = None
+
+
+# TODO add exhaustiveness checking for subclasses
+# top-level superclass for all events
+class Event(metaclass=ABCMeta):
+    # fields that should be on all events with their default implementations
+    ts: datetime = datetime.now()
+    pid: int = os.getpid()
+    # code: int
+
+    # do not define this yourself. inherit it from one of the above level types.
+    @abstractmethod
+    def level_tag(self) -> str:
+        raise Exception("level_tag not implemented for event")
+
+    # Solely the human readable message. Timestamps and formatting will be added by the logger.
+    # Must override yourself
+    @abstractmethod
+    def message(self) -> str:
+        raise Exception("msg not implemented for cli event")
+
+    # returns a dictionary representation of the event fields. You must specify which of the
+    # available messages you would like to use (i.e. - e.message, e.cli_msg(), e.file_msg())
+    # used for constructing json formatted events. includes secrets which must be scrubbed at
+    # the usage site.
+    def to_dict(self, msg: str) -> dict:
+        level = self.level_tag()
+        return {
+            'pid': self.pid,
+            'msg': msg,
+            'level': level if len(level) == 5 else f"{level} "
+        }
+
+
+class File(Event, metaclass=ABCMeta):
+    # Solely the human readable message. Timestamps and formatting will be added by the logger.
+    def file_msg(self) -> str:
+        # returns the event msg unless overriden in the concrete class
+        return self.message()
+
+
+class Cli(Event, metaclass=ABCMeta):
+    # Solely the human readable message. Timestamps and formatting will be added by the logger.
+    def cli_msg(self) -> str:
+        # returns the event msg unless overriden in the concrete class
+        return self.message()

core/dbt/events/format.py

@@ -1,6 +1,6 @@
 from dbt import ui
-from typing import Optional, Union
 from dbt.node_types import NodeType
+from typing import Optional, Union
 
 
 def format_fancy_output_line(

core/dbt/events/functions.py

@@ -1,18 +1,19 @@
 
 from colorama import Style
 import dbt.events.functions as this  # don't worry I hate it too.
-from dbt.events.types import Cli, Event, File, ShowException
+from dbt.events.base_types import Cli, Event, File, ShowException
 import dbt.flags as flags
 # TODO this will need to move eventually
 from dbt.logger import SECRET_ENV_PREFIX, make_log_dir_if_missing, GLOBAL_LOGGER
 import io
 from io import StringIO, TextIOWrapper
 import json
+import logbook
 import logging
 from logging import Logger
 from logging.handlers import RotatingFileHandler
 import os
-from typing import List
+from typing import Callable, List, TypeVar, Union
 
 
 # create the global file logger with no configuration
@@ -105,37 +106,34 @@ def scrub_secrets(msg: str, secrets: List[str]) -> str:
     return scrubbed
 
 
-# translates an Event to a completely formatted output log_line
-# json=True -> json formatting
-# json=False -> text formatting
-# cli=True -> cli formatting
-# cli=False -> file formatting
-def create_log_line(e: Event, json_fmt: bool, cli_dest: bool) -> str:
-    level = e.level_tag()
-    values: dict = {
-        'pid': e.pid,
-        'msg': '',
-        'level': level if len(level) == 5 else f"{level} "
-    }
-    if cli_dest and isinstance(e, Cli):
-        values['msg'] = scrub_secrets(e.cli_msg(), env_secrets())
-    elif not cli_dest and isinstance(e, File):
-        values['msg'] = scrub_secrets(e.file_msg(), env_secrets())
-
-    if json_fmt:
-        values['ts'] = e.ts.isoformat()
-        log_line = json.dumps(values, sort_keys=True)
-    else:
-        values['ts'] = e.ts.strftime("%H:%M:%S")
-        color_tag = '' if this.format_color else Style.RESET_ALL
-        log_line = f"{color_tag}{values['ts']} | [ {values['level']} ] | {values['msg']}"
+# Type representing Event and all subclasses of Event
+T_Event = TypeVar('T_Event', bound=Event)
+
+
+# translates an Event to a completely formatted text-based log line
+# you have to specify which message you want. (i.e. - e.message, e.cli_msg(), e.file_msg())
+# type hinting everything as strings so we don't get any unintentional string conversions via str()
+def create_text_log_line(e: T_Event, msg_fn: Callable[[T_Event], str]) -> str:
+    color_tag: str = '' if this.format_color else Style.RESET_ALL
+    ts: str = e.ts.strftime("%H:%M:%S")
+    scrubbed_msg: str = scrub_secrets(msg_fn(e), env_secrets())
+    level: str = e.level_tag()
+    log_line: str = f"{color_tag}{ts} | [ {level} ] | {scrubbed_msg}"
+    return log_line
+
 
+# translates an Event to a completely formatted json log line
+# you have to specify which message you want. (i.e. - e.message, e.cli_msg(), e.file_msg())
+def create_json_log_line(e: T_Event, msg_fn: Callable[[T_Event], str]) -> str:
+    values = e.to_dict(scrub_secrets(msg_fn(e), env_secrets()))
+    values['ts'] = e.ts.isoformat()
+    log_line = json.dumps(values, sort_keys=True)
     return log_line
 
 
 # allows for resuse of this obnoxious if else tree.
 # do not use for exceptions, it doesn't pass along exc_info, stack_info, or extra
-def send_to_logger(l: Logger, level_tag: str, log_line: str):
+def send_to_logger(l: Union[Logger, logbook.Logger], level_tag: str, log_line: str):
     if level_tag == 'test':
         # TODO after implmenting #3977 send to new test level
         l.debug(log_line)
@@ -209,37 +207,33 @@ def send_exc_to_logger(
 # to files, etc.)
 def fire_event(e: Event) -> None:
     # TODO manage history in phase 2:  EVENT_HISTORY.append(e)
-    # explicitly checking the debug flag here so that potentially expensive-to-construct
-    # log messages are not constructed if debug messages are never shown.
 
     # backwards compatibility for plugins that require old logger (dbt-rpc)
     if flags.ENABLE_LEGACY_LOGGER:
-        log_line = create_log_line(e, json_fmt=this.format_json, cli_dest=False)
-        level_tag = e.level_tag()
-        if level_tag == 'debug':
-            GLOBAL_LOGGER.debug(log_line)
-        elif level_tag == 'info':
-            GLOBAL_LOGGER.info(log_line)
-        elif level_tag == 'warn':
-            GLOBAL_LOGGER.warn(log_line)
-        elif level_tag == 'error':
-            GLOBAL_LOGGER.error(log_line)
-        else:
-            raise AssertionError(
-                f"While attempting to log {log_line}, encountered the unhandled level: {level_tag}"
-            )
-        return
+        # using Event::message because the legacy logger didn't differentiate messages by
+        # destination
+        log_line = (
+            create_json_log_line(e, msg_fn=lambda x: x.message())
+            if this.format_json else
+            create_text_log_line(e, msg_fn=lambda x: x.message())
+        )
+
+        send_to_logger(GLOBAL_LOGGER, e.level_tag(), log_line)
+        return  # exit the function to avoid using the current logger as well
 
     # always logs debug level regardless of user input
     if isinstance(e, File):
-        log_line = create_log_line(e, json_fmt=this.format_json, cli_dest=False)
+        log_line = create_json_log_line(e, msg_fn=lambda x: x.file_msg())
         # doesn't send exceptions to exception logger
         send_to_logger(FILE_LOG, level_tag=e.level_tag(), log_line=log_line)
 
     if isinstance(e, Cli):
+        # explicitly checking the debug flag here so that potentially expensive-to-construct
+        # log messages are not constructed if debug messages are never shown.
         if e.level_tag() == 'debug' and not flags.DEBUG:
             return  # eat the message in case it was one of the expensive ones
-        log_line = create_log_line(e, json_fmt=this.format_json, cli_dest=True)
+
+        log_line = create_json_log_line(e, msg_fn=lambda x: x.cli_msg())
         if not isinstance(e, ShowException):
             send_to_logger(STDOUT_LOG, level_tag=e.level_tag(), log_line=log_line)
         # CliEventABC and ShowException

core/dbt/events/history.py

@@ -1,4 +1,4 @@
-from dbt.events.types import Event
+from dbt.events.base_types import Event
 from typing import List
 
 

core/dbt/events/stubs.py

@@ -1,7 +1,7 @@
 from typing import (
     Any,
-    Optional,
     NamedTuple,
+    Optional,
 )
 
 # N.B.: