Minor Cleanup of Structured Logging Module

core/dbt/events/adapter_endpoint.py

@@ -3,84 +3,63 @@
 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,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 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())
-
- 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 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
 
+
+# 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.: