Skip to content

Commit

Permalink
Minor Cleanup of Structured Logging Module (#4266)
Browse files Browse the repository at this point in the history
* cleanup structured logging module

* update adapter logger to preserve new-style logging formatting
  • Loading branch information
Nathaniel May authored Nov 17, 2021
1 parent 2241698 commit 719b202
Show file tree
Hide file tree
Showing 8 changed files with 206 additions and 179 deletions.
69 changes: 24 additions & 45 deletions core/dbt/events/adapter_endpoint.py
Original file line number Diff line number Diff line change
Expand Up @@ -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)
95 changes: 95 additions & 0 deletions core/dbt/events/base_types.py
Original file line number Diff line number Diff line change
@@ -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()
2 changes: 1 addition & 1 deletion core/dbt/events/format.py
Original file line number Diff line number Diff line change
@@ -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(
Expand Down
86 changes: 40 additions & 46 deletions core/dbt/events/functions.py
Original file line number Diff line number Diff line change
@@ -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
Expand Down Expand Up @@ -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)
Expand Down Expand Up @@ -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
Expand Down
2 changes: 1 addition & 1 deletion core/dbt/events/history.py
Original file line number Diff line number Diff line change
@@ -1,4 +1,4 @@
from dbt.events.types import Event
from dbt.events.base_types import Event
from typing import List


Expand Down
2 changes: 1 addition & 1 deletion core/dbt/events/stubs.py
Original file line number Diff line number Diff line change
@@ -1,7 +1,7 @@
from typing import (
Any,
Optional,
NamedTuple,
Optional,
)

# N.B.:
Expand Down
Loading

0 comments on commit 719b202

Please sign in to comment.