From 30b62bd0eeb0daf12482f3cc2fb105c50e8975aa Mon Sep 17 00:00:00 2001 From: Nathaniel May Date: Wed, 10 Nov 2021 13:50:01 -0500 Subject: [PATCH 01/17] init with empty file --- core/dbt/events/base_types.py | 0 1 file changed, 0 insertions(+), 0 deletions(-) create mode 100644 core/dbt/events/base_types.py diff --git a/core/dbt/events/base_types.py b/core/dbt/events/base_types.py new file mode 100644 index 00000000000..e69de29bb2d From cb7f007b9b3636b1537a9f9852c3530884111f1a Mon Sep 17 00:00:00 2001 From: Nathaniel May Date: Wed, 10 Nov 2021 14:18:06 -0500 Subject: [PATCH 02/17] separate base types --- core/dbt/events/base_types.py | 85 ++++++++++++++++++++++++++++++++++ core/dbt/events/functions.py | 2 +- core/dbt/events/history.py | 2 +- core/dbt/events/types.py | 86 ++--------------------------------- 4 files changed, 90 insertions(+), 85 deletions(-) diff --git a/core/dbt/events/base_types.py b/core/dbt/events/base_types.py index e69de29bb2d..aba9bdf5a7a 100644 --- a/core/dbt/events/base_types.py +++ b/core/dbt/events/base_types.py @@ -0,0 +1,85 @@ +from abc import ABCMeta, abstractmethod +from datetime import datetime +from dataclasses import dataclass +import os +from typing import Any + + +# 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 +# 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() diff --git a/core/dbt/events/functions.py b/core/dbt/events/functions.py index a515c763605..52449b086f8 100644 --- a/core/dbt/events/functions.py +++ b/core/dbt/events/functions.py @@ -1,7 +1,7 @@ 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 diff --git a/core/dbt/events/history.py b/core/dbt/events/history.py index 1bbc1995f7d..e561add49d3 100644 --- a/core/dbt/events/history.py +++ b/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 diff --git a/core/dbt/events/types.py b/core/dbt/events/types.py index ddb6caa7bf5..ca7017d73d3 100644 --- a/core/dbt/events/types.py +++ b/core/dbt/events/types.py @@ -1,93 +1,13 @@ -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 - - -# 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 -# 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() @dataclass From cf26be7bf0ac0f080e8f43adb0c8bfe4f2f46a0a Mon Sep 17 00:00:00 2001 From: Nathaniel May Date: Wed, 10 Nov 2021 14:23:36 -0500 Subject: [PATCH 03/17] add header --- core/dbt/events/base_types.py | 6 +++++- 1 file changed, 5 insertions(+), 1 deletion(-) diff --git a/core/dbt/events/base_types.py b/core/dbt/events/base_types.py index aba9bdf5a7a..a537e8a1430 100644 --- a/core/dbt/events/base_types.py +++ b/core/dbt/events/base_types.py @@ -5,7 +5,11 @@ from typing import Any -# types to represent log levels +# # # # # # # # # # # # # # # # # # # # # # # # # # # # # # # # # # # # # # +# These base types define the _required structure_ for the concrete event # +# types defined in types.py # +# # # # # # # # # # # # # # # # # # # # # # # # # # # # # # # # # # # # # # + # in preparation for #3977 class TestLevel(): From cbc881051721f0dc8720b8b8d566c4c9ea50c6de Mon Sep 17 00:00:00 2001 From: Nathaniel May Date: Wed, 10 Nov 2021 14:35:32 -0500 Subject: [PATCH 04/17] reuse send_to_logger for legacy logging --- core/dbt/events/functions.py | 21 +++++---------------- 1 file changed, 5 insertions(+), 16 deletions(-) diff --git a/core/dbt/events/functions.py b/core/dbt/events/functions.py index 52449b086f8..629ed0af383 100644 --- a/core/dbt/events/functions.py +++ b/core/dbt/events/functions.py @@ -8,11 +8,12 @@ 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 @@ -135,7 +136,7 @@ def create_log_line(e: Event, json_fmt: bool, cli_dest: bool) -> str: # 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) @@ -215,20 +216,8 @@ def fire_event(e: Event) -> None: # 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 + send_to_logger(GLOBAL_LOGGER, e.level_tag(), log_line) + return # exit the function to avoid using the current logger # always logs debug level regardless of user input if isinstance(e, File): From 444097facb6fdfc780205866a5d76db7303ec982 Mon Sep 17 00:00:00 2001 From: Nathaniel May Date: Wed, 10 Nov 2021 14:38:31 -0500 Subject: [PATCH 05/17] move comment --- core/dbt/events/functions.py | 5 +++-- 1 file changed, 3 insertions(+), 2 deletions(-) diff --git a/core/dbt/events/functions.py b/core/dbt/events/functions.py index 629ed0af383..1149522000a 100644 --- a/core/dbt/events/functions.py +++ b/core/dbt/events/functions.py @@ -210,8 +210,6 @@ 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: @@ -226,8 +224,11 @@ def fire_event(e: Event) -> None: 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) if not isinstance(e, ShowException): send_to_logger(STDOUT_LOG, level_tag=e.level_tag(), log_line=log_line) From 1e6530948a4a0d77e657584b741bbe01804b0124 Mon Sep 17 00:00:00 2001 From: Nathaniel May Date: Wed, 10 Nov 2021 14:42:23 -0500 Subject: [PATCH 06/17] alphabetize imports --- core/dbt/events/base_types.py | 2 +- core/dbt/events/format.py | 2 +- core/dbt/events/stubs.py | 2 +- core/dbt/events/types.py | 4 ++-- 4 files changed, 5 insertions(+), 5 deletions(-) diff --git a/core/dbt/events/base_types.py b/core/dbt/events/base_types.py index a537e8a1430..7255d5a7d1d 100644 --- a/core/dbt/events/base_types.py +++ b/core/dbt/events/base_types.py @@ -1,6 +1,6 @@ from abc import ABCMeta, abstractmethod -from datetime import datetime from dataclasses import dataclass +from datetime import datetime import os from typing import Any diff --git a/core/dbt/events/format.py b/core/dbt/events/format.py index 0e40a6f2a75..72e10fcd49b 100644 --- a/core/dbt/events/format.py +++ b/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( diff --git a/core/dbt/events/stubs.py b/core/dbt/events/stubs.py index b2329ce2787..de574668676 100644 --- a/core/dbt/events/stubs.py +++ b/core/dbt/events/stubs.py @@ -1,7 +1,7 @@ from typing import ( Any, - Optional, NamedTuple, + Optional, ) # N.B.: diff --git a/core/dbt/events/types.py b/core/dbt/events/types.py index ca7017d73d3..ff688eec105 100644 --- a/core/dbt/events/types.py +++ b/core/dbt/events/types.py @@ -1,13 +1,13 @@ import argparse from dataclasses import dataclass -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 +from dbt.node_types import NodeType +from typing import Any, Callable, cast, Dict, List, Optional, Set, Union @dataclass From cca15475167bed09d1b6f8d21ac4ba934fb71609 Mon Sep 17 00:00:00 2001 From: Nathaniel May Date: Wed, 10 Nov 2021 15:00:35 -0500 Subject: [PATCH 07/17] add back missed test file --- test/unit/test_events.py | 19 +++++++++++++++++++ 1 file changed, 19 insertions(+) create mode 100644 test/unit/test_events.py diff --git a/test/unit/test_events.py b/test/unit/test_events.py new file mode 100644 index 00000000000..1cfd18b3e85 --- /dev/null +++ b/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) From 5e39857027a6d76d75b13f4041102e4c3f247acd Mon Sep 17 00:00:00 2001 From: Nathaniel May Date: Thu, 11 Nov 2021 18:49:47 -0500 Subject: [PATCH 08/17] streamline log line creation --- core/dbt/events/base_types.py | 13 ++++++++ core/dbt/events/functions.py | 56 +++++++++++++++++------------------ 2 files changed, 41 insertions(+), 28 deletions(-) diff --git a/core/dbt/events/base_types.py b/core/dbt/events/base_types.py index 7255d5a7d1d..db27d74460c 100644 --- a/core/dbt/events/base_types.py +++ b/core/dbt/events/base_types.py @@ -49,6 +49,7 @@ def __post_init__(self): self.extra: Any = None +# TODO move this in a later commit # The following classes 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 @@ -74,6 +75,18 @@ def level_tag(self) -> str: 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. diff --git a/core/dbt/events/functions.py b/core/dbt/events/functions.py index 1149522000a..f4a39906edf 100644 --- a/core/dbt/events/functions.py +++ b/core/dbt/events/functions.py @@ -106,31 +106,24 @@ 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 @@ -213,13 +206,20 @@ def fire_event(e: Event) -> None: # 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) + # 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 + 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) @@ -229,7 +229,7 @@ def fire_event(e: Event) -> None: 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 From 3e6d24ee19b98dd57648b03429afd0c8f71a8b12 Mon Sep 17 00:00:00 2001 From: Nathaniel May Date: Thu, 11 Nov 2021 18:52:19 -0500 Subject: [PATCH 09/17] move misplaced comment --- core/dbt/events/base_types.py | 8 -------- core/dbt/events/types.py | 7 +++++++ 2 files changed, 7 insertions(+), 8 deletions(-) diff --git a/core/dbt/events/base_types.py b/core/dbt/events/base_types.py index db27d74460c..8186ac2eae7 100644 --- a/core/dbt/events/base_types.py +++ b/core/dbt/events/base_types.py @@ -49,14 +49,6 @@ def __post_init__(self): self.extra: Any = None -# TODO move this in a later commit -# The following classes 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 diff --git a/core/dbt/events/types.py b/core/dbt/events/types.py index ff688eec105..dc57976e136 100644 --- a/core/dbt/events/types.py +++ b/core/dbt/events/types.py @@ -10,6 +10,13 @@ from typing import Any, Callable, cast, Dict, List, Optional, Set, Union +# 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. + + @dataclass class AdapterEventBase(): name: str From 3c64b142e7aa2e3f8a9228ba9cb28af7d7be1790 Mon Sep 17 00:00:00 2001 From: Nathaniel May Date: Thu, 11 Nov 2021 19:05:57 -0500 Subject: [PATCH 10/17] make event adapter abstract so it can't be created and passed around --- core/dbt/events/types.py | 19 +++++++++++-------- 1 file changed, 11 insertions(+), 8 deletions(-) diff --git a/core/dbt/events/types.py b/core/dbt/events/types.py index dc57976e136..7fa2629b277 100644 --- a/core/dbt/events/types.py +++ b/core/dbt/events/types.py @@ -1,3 +1,4 @@ +from abc import ABCMeta import argparse from dataclasses import dataclass from dbt.events.stubs import _CachedRelation, AdapterResponse, BaseRelation, _ReferenceKey @@ -17,28 +18,30 @@ # that the necessary methods are defined. -@dataclass -class AdapterEventBase(): - name: str - raw_msg: str +# can't use @dataclass because of https://github.com/python/mypy/issues/5374 +class AdapterEventBase(Cli, File, metaclass=ABCMeta): + + def __init__(self, name: str, raw_msg: str): + self.name = name + self.raw_msg = raw_msg def message(self) -> str: return f"{self.name} adapter: {self.raw_msg}" -class AdapterEventDebug(DebugLevel, AdapterEventBase, Cli, File, ShowException): +class AdapterEventDebug(DebugLevel, ShowException, AdapterEventBase): pass -class AdapterEventInfo(InfoLevel, AdapterEventBase, Cli, File, ShowException): +class AdapterEventInfo(InfoLevel, ShowException, AdapterEventBase): pass -class AdapterEventWarning(WarnLevel, AdapterEventBase, Cli, File, ShowException): +class AdapterEventWarning(WarnLevel, ShowException, AdapterEventBase): pass -class AdapterEventError(ErrorLevel, AdapterEventBase, Cli, File, ShowException): +class AdapterEventError(ErrorLevel, ShowException, AdapterEventBase): pass From 53d20eb276f633efaf88e0d1be7f4b69867217b3 Mon Sep 17 00:00:00 2001 From: Nathaniel May Date: Thu, 11 Nov 2021 19:20:12 -0500 Subject: [PATCH 11/17] add todo --- core/dbt/events/base_types.py | 1 + 1 file changed, 1 insertion(+) diff --git a/core/dbt/events/base_types.py b/core/dbt/events/base_types.py index 8186ac2eae7..ce606ae31d0 100644 --- a/core/dbt/events/base_types.py +++ b/core/dbt/events/base_types.py @@ -49,6 +49,7 @@ def __post_init__(self): 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 From cc75daf0c3b54bba966ad4de354a081d6182f744 Mon Sep 17 00:00:00 2001 From: Nathaniel May Date: Mon, 15 Nov 2021 10:57:10 -0500 Subject: [PATCH 12/17] removed named params for adapter event calls --- core/dbt/events/adapter_endpoint.py | 10 +++++----- 1 file changed, 5 insertions(+), 5 deletions(-) diff --git a/core/dbt/events/adapter_endpoint.py b/core/dbt/events/adapter_endpoint.py index aad71080acc..1866648890e 100644 --- a/core/dbt/events/adapter_endpoint.py +++ b/core/dbt/events/adapter_endpoint.py @@ -17,7 +17,7 @@ def debug( stack_info: Any = None, extra: Any = None ): - event = AdapterEventDebug(name=self.name, raw_msg=msg) + event = AdapterEventDebug(self.name, msg) event.exc_info = exc_info event.stack_info = stack_info @@ -32,7 +32,7 @@ def info( stack_info: Any = None, extra: Any = None ): - event = AdapterEventInfo(name=self.name, raw_msg=msg) + event = AdapterEventInfo(self.name, msg) event.exc_info = exc_info event.stack_info = stack_info @@ -47,7 +47,7 @@ def warning( stack_info: Any = None, extra: Any = None ): - event = AdapterEventWarning(name=self.name, raw_msg=msg) + event = AdapterEventWarning(self.name, msg) event.exc_info = exc_info event.stack_info = stack_info @@ -62,7 +62,7 @@ def error( stack_info: Any = None, extra: Any = None ): - event = AdapterEventError(name=self.name, raw_msg=msg) + event = AdapterEventError(self.name, msg) event.exc_info = exc_info event.stack_info = stack_info @@ -77,7 +77,7 @@ def exception( stack_info: Any = None, extra: Any = None ): - event = AdapterEventError(name=self.name, raw_msg=msg) + event = AdapterEventError(self.name, msg) event.exc_info = exc_info event.stack_info = stack_info From 29bbddfb80dc6418e7791d61694bc29ae597e8e7 Mon Sep 17 00:00:00 2001 From: Nathaniel May Date: Mon, 15 Nov 2021 18:08:19 -0500 Subject: [PATCH 13/17] fix adapter interface --- core/dbt/events/adapter_endpoint.py | 91 +++++++++++------------------ core/dbt/events/types.py | 46 +++++++++++---- 2 files changed, 70 insertions(+), 67 deletions(-) diff --git a/core/dbt/events/adapter_endpoint.py b/core/dbt/events/adapter_endpoint.py index 1866648890e..fdda2736082 100644 --- a/core/dbt/events/adapter_endpoint.py +++ b/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(self.name, 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(self.name, 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(self.name, 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(self.name, 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(self.name, 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 diff --git a/core/dbt/events/types.py b/core/dbt/events/types.py index 7fa2629b277..c59616472ed 100644 --- a/core/dbt/events/types.py +++ b/core/dbt/events/types.py @@ -1,4 +1,3 @@ -from abc import ABCMeta import argparse from dataclasses import dataclass from dbt.events.stubs import _CachedRelation, AdapterResponse, BaseRelation, _ReferenceKey @@ -8,7 +7,9 @@ ) from dbt.events.format import format_fancy_output_line, pluralize from dbt.node_types import NodeType -from typing import Any, Callable, cast, Dict, List, Optional, Set, Union +from io import StringIO +from logging import Formatter, getLogger, StreamHandler +from typing import Any, Callable, cast, Dict, List, Optional, Set, Tuple, Union # The classes in this file represent the data necessary to describe a @@ -18,15 +19,38 @@ # that the necessary methods are defined. -# can't use @dataclass because of https://github.com/python/mypy/issues/5374 -class AdapterEventBase(Cli, File, metaclass=ABCMeta): - - def __init__(self, name: str, raw_msg: str): - self.name = name - self.raw_msg = raw_msg - - def message(self) -> str: - return f"{self.name} adapter: {self.raw_msg}" +# can't use ABCs with @dataclass because of https://github.com/python/mypy/issues/5374 +@dataclass +class AdapterEventBase(Cli, File): + name: 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 not implemented for AdapterEventBase") + + def message(self) -> str: + # 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, ShowException, AdapterEventBase): From c5ca29fa9c410e226e2e945e74abe33489cdc322 Mon Sep 17 00:00:00 2001 From: Nathaniel May Date: Mon, 15 Nov 2021 19:31:47 -0500 Subject: [PATCH 14/17] fix adapter issues --- core/dbt/events/adapter_endpoint.py | 10 +++++----- core/dbt/events/types.py | 10 +++++----- 2 files changed, 10 insertions(+), 10 deletions(-) diff --git a/core/dbt/events/adapter_endpoint.py b/core/dbt/events/adapter_endpoint.py index fdda2736082..d7499f9a68a 100644 --- a/core/dbt/events/adapter_endpoint.py +++ b/core/dbt/events/adapter_endpoint.py @@ -11,7 +11,7 @@ class AdapterLogger(): name: str def debug(self, *args, **kwargs): - event = AdapterEventDebug(self.name, *args, **kwargs) + event = AdapterEventDebug(self.name, args, kwargs) event.exc_info = or_none(kwargs, 'exc_info') event.stack_info = or_none(kwargs, 'stack_info') @@ -20,7 +20,7 @@ def debug(self, *args, **kwargs): fire_event(event) def info(self, *args, **kwargs): - event = AdapterEventInfo(self.name, *args, **kwargs) + event = AdapterEventInfo(self.name, args, kwargs) event.exc_info = or_none(kwargs, 'exc_info') event.stack_info = or_none(kwargs, 'stack_info') @@ -29,7 +29,7 @@ def info(self, *args, **kwargs): fire_event(event) def warning(self, *args, **kwargs): - event = AdapterEventWarning(self.name, *args, **kwargs) + event = AdapterEventWarning(self.name, args, kwargs) event.exc_info = or_none(kwargs, 'exc_info') event.stack_info = or_none(kwargs, 'stack_info') @@ -38,7 +38,7 @@ def warning(self, *args, **kwargs): fire_event(event) def error(self, *args, **kwargs): - event = AdapterEventError(self.name, *args, **kwargs) + event = AdapterEventError(self.name, args, kwargs) event.exc_info = or_none(kwargs, 'exc_info') event.stack_info = or_none(kwargs, 'stack_info') @@ -47,7 +47,7 @@ def error(self, *args, **kwargs): fire_event(event) def exception(self, *args, **kwargs): - event = AdapterEventError(self.name, *args, **kwargs) + event = AdapterEventError(self.name, args, kwargs) # defaulting exc_info=True if it is empty is what makes this method different x = or_none(kwargs, 'exc_info') diff --git a/core/dbt/events/types.py b/core/dbt/events/types.py index c59616472ed..4245fb7b1cf 100644 --- a/core/dbt/events/types.py +++ b/core/dbt/events/types.py @@ -28,7 +28,7 @@ class AdapterEventBase(Cli, File): # instead of having this inherit from one of the level classes def level_tag(self) -> str: - raise Exception("level_tag not implemented for AdapterEventBase") + raise Exception("level_tag should never be called on AdapterEventBase") def message(self) -> str: # this class shouldn't be createable, but we can't make it an ABC because of a mypy bug @@ -53,19 +53,19 @@ def message(self) -> str: return f"{self.name} adapter: {msg}" -class AdapterEventDebug(DebugLevel, ShowException, AdapterEventBase): +class AdapterEventDebug(DebugLevel, AdapterEventBase, ShowException): pass -class AdapterEventInfo(InfoLevel, ShowException, AdapterEventBase): +class AdapterEventInfo(InfoLevel, AdapterEventBase, ShowException): pass -class AdapterEventWarning(WarnLevel, ShowException, AdapterEventBase): +class AdapterEventWarning(WarnLevel, AdapterEventBase, ShowException): pass -class AdapterEventError(ErrorLevel, ShowException, AdapterEventBase): +class AdapterEventError(ErrorLevel, AdapterEventBase, ShowException): pass From 09557f8613addd8f1d6aaa1f4426b513652bfd20 Mon Sep 17 00:00:00 2001 From: Nathaniel May Date: Tue, 16 Nov 2021 11:10:42 -0500 Subject: [PATCH 15/17] use get for kwargs --- core/dbt/events/adapter_endpoint.py | 38 ++++++++++++----------------- 1 file changed, 15 insertions(+), 23 deletions(-) diff --git a/core/dbt/events/adapter_endpoint.py b/core/dbt/events/adapter_endpoint.py index d7499f9a68a..0ebda5d508a 100644 --- a/core/dbt/events/adapter_endpoint.py +++ b/core/dbt/events/adapter_endpoint.py @@ -3,7 +3,6 @@ from dbt.events.types import ( AdapterEventDebug, AdapterEventInfo, AdapterEventWarning, AdapterEventError ) -from typing import Any, Optional @dataclass @@ -13,36 +12,36 @@ class AdapterLogger(): def debug(self, *args, **kwargs): event = AdapterEventDebug(self.name, args, kwargs) - event.exc_info = or_none(kwargs, 'exc_info') - event.stack_info = or_none(kwargs, 'stack_info') - event.extra = or_none(kwargs, 'extra') + event.exc_info = kwargs.get('exc_info') + event.stack_info = kwargs.get('stack_info') + event.extra = kwargs.get('extra') fire_event(event) def info(self, *args, **kwargs): event = AdapterEventInfo(self.name, args, kwargs) - event.exc_info = or_none(kwargs, 'exc_info') - event.stack_info = or_none(kwargs, 'stack_info') - event.extra = or_none(kwargs, 'extra') + event.exc_info = kwargs.get('exc_info') + event.stack_info = kwargs.get('stack_info') + event.extra = kwargs.get('extra') fire_event(event) def warning(self, *args, **kwargs): event = AdapterEventWarning(self.name, args, kwargs) - event.exc_info = or_none(kwargs, 'exc_info') - event.stack_info = or_none(kwargs, 'stack_info') - event.extra = or_none(kwargs, 'extra') + event.exc_info = kwargs.get('exc_info') + event.stack_info = kwargs.get('stack_info') + event.extra = kwargs.get('extra') fire_event(event) def error(self, *args, **kwargs): event = AdapterEventError(self.name, args, kwargs) - event.exc_info = or_none(kwargs, 'exc_info') - event.stack_info = or_none(kwargs, 'stack_info') - event.extra = or_none(kwargs, 'extra') + event.exc_info = kwargs.get('exc_info') + event.stack_info = kwargs.get('stack_info') + event.extra = kwargs.get('extra') fire_event(event) @@ -50,16 +49,9 @@ def exception(self, *args, **kwargs): event = AdapterEventError(self.name, args, kwargs) # defaulting exc_info=True if it is empty is what makes this method different - x = or_none(kwargs, 'exc_info') + x = kwargs.get('exc_info') event.exc_info = x if x else True - event.stack_info = or_none(kwargs, 'stack_info') - event.extra = or_none(kwargs, 'extra') + event.stack_info = kwargs.get('stack_info') + event.extra = kwargs.get('extra') fire_event(event) - - -def or_none(x: dict, key: str) -> Optional[Any]: - try: - return x[key] - except KeyError: - return None From fce745986bce493576bfcbda2e31bd9dac4ca7ee Mon Sep 17 00:00:00 2001 From: Nathaniel May Date: Tue, 16 Nov 2021 14:23:30 -0500 Subject: [PATCH 16/17] tighten up type safety with bounded TypeVar --- core/dbt/events/functions.py | 22 +++++++++++++--------- 1 file changed, 13 insertions(+), 9 deletions(-) diff --git a/core/dbt/events/functions.py b/core/dbt/events/functions.py index f4a39906edf..ab322840fb7 100644 --- a/core/dbt/events/functions.py +++ b/core/dbt/events/functions.py @@ -13,7 +13,7 @@ from logging import Logger from logging.handlers import RotatingFileHandler import os -from typing import List, Union +from typing import Callable, List, TypeVar, Union # create the global file logger with no configuration @@ -106,13 +106,17 @@ def scrub_secrets(msg: str, secrets: List[str]) -> str: return scrubbed +# 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: Event, msg: str) -> 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, env_secrets()) + 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 @@ -120,8 +124,8 @@ def create_text_log_line(e: Event, msg: str) -> str: # 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())) +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 @@ -209,9 +213,9 @@ def fire_event(e: Event) -> None: # using Event::message because the legacy logger didn't differentiate messages by # destination log_line = ( - create_json_log_line(e, msg=e.message()) + create_json_log_line(e, msg_fn=lambda x: x.message()) if this.format_json else - create_text_log_line(e, msg=e.message()) + create_text_log_line(e, msg_fn=lambda x: x.message()) ) send_to_logger(GLOBAL_LOGGER, e.level_tag(), log_line) @@ -219,7 +223,7 @@ def fire_event(e: Event) -> None: # always logs debug level regardless of user input if isinstance(e, File): - log_line = create_json_log_line(e, msg=e.file_msg()) + 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) @@ -229,7 +233,7 @@ def fire_event(e: Event) -> None: 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_json_log_line(e, msg=e.cli_msg()) + 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 From cecc7eee4a17b0ea9b57ed981c570f259f5f5f74 Mon Sep 17 00:00:00 2001 From: Nathaniel May Date: Tue, 16 Nov 2021 14:45:13 -0500 Subject: [PATCH 17/17] manually do string formatting to preserve new-style logging interface --- core/dbt/events/adapter_endpoint.py | 62 ++++++++++++++++------------- core/dbt/events/types.py | 18 +-------- 2 files changed, 37 insertions(+), 43 deletions(-) diff --git a/core/dbt/events/adapter_endpoint.py b/core/dbt/events/adapter_endpoint.py index 0ebda5d508a..96ce73d4516 100644 --- a/core/dbt/events/adapter_endpoint.py +++ b/core/dbt/events/adapter_endpoint.py @@ -9,49 +9,57 @@ class AdapterLogger(): name: str - def debug(self, *args, **kwargs): - event = AdapterEventDebug(self.name, args, kwargs) + 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 = kwargs.get('exc_info') - event.stack_info = kwargs.get('stack_info') - event.extra = kwargs.get('extra') + event.exc_info = exc_info + event.extra = extra + event.stack_info = stack_info fire_event(event) - def info(self, *args, **kwargs): - event = AdapterEventInfo(self.name, args, kwargs) + 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 = kwargs.get('exc_info') - event.stack_info = kwargs.get('stack_info') - event.extra = kwargs.get('extra') + event.exc_info = exc_info + event.extra = extra + event.stack_info = stack_info fire_event(event) - def warning(self, *args, **kwargs): - event = AdapterEventWarning(self.name, args, kwargs) + 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 = kwargs.get('exc_info') - event.stack_info = kwargs.get('stack_info') - event.extra = kwargs.get('extra') + event.exc_info = exc_info + event.extra = extra + event.stack_info = stack_info fire_event(event) - def error(self, *args, **kwargs): - event = AdapterEventError(self.name, args, kwargs) + 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 = kwargs.get('exc_info') - event.stack_info = kwargs.get('stack_info') - event.extra = kwargs.get('extra') + event.exc_info = exc_info + event.extra = extra + event.stack_info = stack_info fire_event(event) - def exception(self, *args, **kwargs): - event = AdapterEventError(self.name, args, kwargs) + # 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) - # defaulting exc_info=True if it is empty is what makes this method different - x = kwargs.get('exc_info') - event.exc_info = x if x else True - event.stack_info = kwargs.get('stack_info') - event.extra = kwargs.get('extra') + 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) diff --git a/core/dbt/events/types.py b/core/dbt/events/types.py index 4245fb7b1cf..0ce14417275 100644 --- a/core/dbt/events/types.py +++ b/core/dbt/events/types.py @@ -7,8 +7,6 @@ ) from dbt.events.format import format_fancy_output_line, pluralize 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 @@ -23,8 +21,8 @@ @dataclass class AdapterEventBase(Cli, File): name: str + base_msg: str args: Tuple[Any, ...] - kwargs: dict # instead of having this inherit from one of the level classes def level_tag(self) -> str: @@ -37,19 +35,7 @@ def message(self) -> str: '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() + msg = self.base_msg.format(*self.args) return f"{self.name} adapter: {msg}"