add versioning to structured logging

core/dbt/events/adapter_endpoint.py

@@ -3,84 +3,63 @@ from dbt.events.functions import fire_event
 from dbt.events.types import (
     AdapterEventDebug, AdapterEventInfo, AdapterEventWarning, AdapterEventError
 )
-from typing import Any
+from typing import Any, Optional
 
 
 @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, *args, **kwargs):
+        event = AdapterEventDebug(self.name, args, kwargs)
 
-        event.exc_info = exc_info
-        event.stack_info = stack_info
-        event.extra = extra
+        event.exc_info = or_none(kwargs, 'exc_info')
+        event.stack_info = or_none(kwargs, 'stack_info')
+        event.extra = or_none(kwargs, 'extra')
 
         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, *args, **kwargs):
+        event = AdapterEventInfo(self.name, args, kwargs)
 
-        event.exc_info = exc_info
-        event.stack_info = stack_info
-        event.extra = extra
+        event.exc_info = or_none(kwargs, 'exc_info')
+        event.stack_info = or_none(kwargs, 'stack_info')
+        event.extra = or_none(kwargs, 'extra')
 
         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, *args, **kwargs):
+        event = AdapterEventWarning(self.name, args, kwargs)
 
-        event.exc_info = exc_info
-        event.stack_info = stack_info
-        event.extra = extra
+        event.exc_info = or_none(kwargs, 'exc_info')
+        event.stack_info = or_none(kwargs, 'stack_info')
+        event.extra = or_none(kwargs, 'extra')
 
         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, *args, **kwargs):
+        event = AdapterEventError(self.name, args, kwargs)
 
-        event.exc_info = exc_info
-        event.stack_info = stack_info
-        event.extra = extra
+        event.exc_info = or_none(kwargs, 'exc_info')
+        event.stack_info = or_none(kwargs, 'stack_info')
+        event.extra = or_none(kwargs, 'extra')
 
         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)
+    def exception(self, *args, **kwargs):
+        event = AdapterEventError(self.name, args, kwargs)
 
-        event.exc_info = exc_info
-        event.stack_info = stack_info
-        event.extra = extra
+        # defaulting exc_info=True if it is empty is what makes this method different
+        x = or_none(kwargs, 'exc_info')
+        event.exc_info = x if x else True
+        event.stack_info = or_none(kwargs, 'stack_info')
+        event.extra = or_none(kwargs, 'extra')
 
         fire_event(event)
+
+
+def or_none(x: dict, key: str) -> Optional[Any]:
+    try:
+        return x[key]
+    except KeyError:
+        return None

core/dbt/events/base_types.py

@@ -0,0 +1,97 @@
+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
+    log_version: int = 1
+    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} ",
+            'log_version': self.log_version
+        }
+
+
+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 List, Union
 
 
 # create the global file logger with no configuration
@@ -105,37 +106,30 @@ 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())
+# 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: Event, msg: 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, env_secrets())
+    level: str = e.level_tag()
+    log_line: str = f"{color_tag}{ts} | [ {level} ] | {scrubbed_msg}"
+    return log_line
 
-    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']}"
 
+# 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: Event, msg: str) -> str:
+    values = e.to_dict(scrub_secrets(msg, 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 +203,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=e.message())
+            if this.format_json else
+            create_text_log_line(e, msg=e.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=e.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=e.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.:

core/dbt/events/types.py

@@ -1,117 +1,71 @@
-from abc import ABCMeta, abstractmethod
 import argparse
 from dataclasses import dataclass
-from datetime import datetime
-from typing import Any, Callable, cast, Dict, List, Optional, Set, Union
 from dbt.events.stubs import _CachedRelation, AdapterResponse, BaseRelation, _ReferenceKey
 from dbt import ui
-from dbt.node_types import NodeType
+from dbt.events.base_types import (
+    Cli, File, DebugLevel, InfoLevel, WarnLevel, ErrorLevel, ShowException
+)
 from dbt.events.format import format_fancy_output_line, pluralize
-import os
+from dbt.node_types import NodeType
+from io import StringIO
+from logging import Formatter, getLogger, StreamHandler
+from typing import Any, Callable, cast, Dict, List, Optional, Set, Tuple, Union
 
 
-# types to represent log levels
-
-# 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
-
-
-# The following classes represent the data necessary to describe a
+# The classes in this file represent the data necessary to describe a
 # particular event to both human readable logs, and machine reliable
 # event streams. classes extend superclasses that indicate what
 # destinations they are intended for, which mypy uses to enforce
 # that the necessary methods are defined.
 
 
-# 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")
-
-
-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()
-
-
+# can't use ABCs with @dataclass because of https://github.com/python/mypy/issues/5374
 @dataclass
-class AdapterEventBase():
+class AdapterEventBase(Cli, File):
     name: str
-    raw_msg: str
+    args: Tuple[Any, ...]
+    kwargs: dict
+
+    # instead of having this inherit from one of the level classes
+    def level_tag(self) -> str:
+        raise Exception("level_tag should never be called on AdapterEventBase")
 
     def message(self) -> str:
-        return f"{self.name} adapter: {self.raw_msg}"
+        # this class shouldn't be createable, but we can't make it an ABC because of a mypy bug
+        if type(self).__name__ == 'AdapterEventBase':
+            raise Exception(
+                'attempted to create a message for AdapterEventBase which cannot be created'
+            )
+
+        # to be backwards compatable with the logbook interface our adapters are used to, we send
+        # the messages to a std lib logger and capture the output to a string buffer to render the
+        # very permissive `*args, **kwargs` interface.
+        capture_buf = StringIO()
+        tmp_logger = getLogger('tmp_logger')
+        passthrough_formatter = Formatter(fmt="%(message)s")
+        tmp_handler = StreamHandler(capture_buf)
+        tmp_handler.setFormatter(passthrough_formatter)
+        tmp_logger.addHandler(tmp_handler)
+
+        # logger level doesn't matter since the formatter is only outputting the message
+        tmp_logger.info(*self.args, **self.kwargs)
+        msg = capture_buf.getvalue()
+        return f"{self.name} adapter: {msg}"
 
 
-class AdapterEventDebug(DebugLevel, AdapterEventBase, Cli, File, ShowException):
+class AdapterEventDebug(DebugLevel, AdapterEventBase, ShowException):
     pass
 
 
-class AdapterEventInfo(InfoLevel, AdapterEventBase, Cli, File, ShowException):
+class AdapterEventInfo(InfoLevel, AdapterEventBase, ShowException):
     pass
 
 
-class AdapterEventWarning(WarnLevel, AdapterEventBase, Cli, File, ShowException):
+class AdapterEventWarning(WarnLevel, AdapterEventBase, ShowException):
     pass
 
 
-class AdapterEventError(ErrorLevel, AdapterEventBase, Cli, File, ShowException):
+class AdapterEventError(ErrorLevel, AdapterEventBase, ShowException):
     pass
 
 

test/unit/test_events.py

@@ -0,0 +1,19 @@
+from dbt.events import AdapterLogger
+from unittest import TestCase
+
+
+class TestAdapterLogger(TestCase):
+
+    def setUp(self):
+        pass
+
+    # this interface is documented for adapter maintainers to plug into
+    # so we should test that it at the very least doesn't explode.
+    def test_adapter_logging_interface(self):
+        logger = AdapterLogger("dbt_tests")
+        logger.debug("debug message")
+        logger.info("info message")
+        logger.warning("warning message")
+        logger.error("error message")
+        logger.exception("exception message")
+        self.assertTrue(True)