From ee7a98eba96e7628a8b839d8840eff10f314f13b Mon Sep 17 00:00:00 2001 From: Quigley Malcolm Date: Tue, 28 Mar 2023 16:12:40 -0700 Subject: [PATCH 1/6] Add tests for logging jinja2.Undefined objects [CT-2259](https://github.com/dbt-labs/dbt-core/issues/7108) identifies an issue wherein dbt-core 1.0-1.3 raise errors if a jinja2.Undefined object is attempted to be logged. This generally happened in the form of `{{ log(undefined_variable, info=True) }}`. This commit adding this test exists for two reasons 1. Ensure we don't have a regression in this going forward 2. Exist as a commit to be used for backport fixes for dbt-core 1.0-1.3 --- tests/unit/test_base_context.py | 12 ++++++++++++ 1 file changed, 12 insertions(+) create mode 100644 tests/unit/test_base_context.py diff --git a/tests/unit/test_base_context.py b/tests/unit/test_base_context.py new file mode 100644 index 00000000000..462323de5d7 --- /dev/null +++ b/tests/unit/test_base_context.py @@ -0,0 +1,12 @@ +from dbt.context.base import BaseContext +from jinja2.runtime import Undefined + + +class TestBaseContext: + def test_log_jinja_undefined(self): + # regression test for CT-2259 + try: + os.environ["DBT_ENV_SECRET_LOG_TEST"] = "cats_are_cool" + BaseContext.log(msg=Undefined(), info=True) + except Exception as e: + assert False, f"Logging an jinja2.Undefined object raises an exception: {e}" From 74637e20e3dddfd7c23e157613361c57ed6e2a03 Mon Sep 17 00:00:00 2001 From: Quigley Malcolm Date: Tue, 28 Mar 2023 16:23:14 -0700 Subject: [PATCH 2/6] Add tests for checking `DBT_ENV_SECRET_`s don't break logging [CT-1783](https://github.com/dbt-labs/dbt-core/issues/6568) describes a bug in dbt-core 1.0-1.3 wherein when a `DBT_ENV_SECRET_` all `{{ log("logging stuff", info=True) }}` invocations break. This commit adds a test for this for two reasons: 1. Ensure we don't regress to this behavior going forward 2. Act as a base commit for making the backport fixes to dbt-core 1.0-1.3 --- tests/unit/test_base_context.py | 10 ++++++++++ 1 file changed, 10 insertions(+) diff --git a/tests/unit/test_base_context.py b/tests/unit/test_base_context.py index 462323de5d7..0dc2d93ddca 100644 --- a/tests/unit/test_base_context.py +++ b/tests/unit/test_base_context.py @@ -1,3 +1,5 @@ +import os + from dbt.context.base import BaseContext from jinja2.runtime import Undefined @@ -10,3 +12,11 @@ def test_log_jinja_undefined(self): BaseContext.log(msg=Undefined(), info=True) except Exception as e: assert False, f"Logging an jinja2.Undefined object raises an exception: {e}" + + def test_log_with_dbt_env_secret(self): + # regression test for CT-1783 + try: + os.environ["DBT_ENV_SECRET_LOG_TEST"] = "cats_are_cool" + BaseContext.log({"fact1": "I like cats"}, info=True) + except Exception as e: + assert False, f"Logging while a `DBT_ENV_SECRET` was set raised an exception: {e}" From a2f03839ed4113b19a362e80ffe04412915a1780 Mon Sep 17 00:00:00 2001 From: Quigley Malcolm Date: Fri, 31 Mar 2023 09:19:16 -0700 Subject: [PATCH 3/6] Log warning when event serialization fails in `msg_to_dict` This commit updates the `msg_to_dict` exception handling path to fire a warning level event instead of raising an exception. --- core/dbt/events/functions.py | 6 ++++-- 1 file changed, 4 insertions(+), 2 deletions(-) diff --git a/core/dbt/events/functions.py b/core/dbt/events/functions.py index 8a20dd2be80..c353e7740ec 100644 --- a/core/dbt/events/functions.py +++ b/core/dbt/events/functions.py @@ -3,7 +3,7 @@ from dbt.events.base_types import BaseEvent, Cache, EventLevel, NoFile, NoStdOut, EventMsg from dbt.events.eventmgr import EventManager, LoggerConfig, LineFormat, NoFilter from dbt.events.helpers import env_secrets, scrub_secrets -from dbt.events.types import EmptyLine +from dbt.events.types import EmptyLine, Note import dbt.flags as flags from dbt.logger import GLOBAL_LOGGER, make_log_dir_if_missing from functools import partial @@ -156,7 +156,9 @@ def msg_to_dict(msg: EventMsg) -> dict: msg_dict = msg.to_dict(casing=betterproto.Casing.SNAKE, include_default_values=True) # type: ignore except AttributeError as exc: event_type = type(msg).__name__ - raise Exception(f"type {event_type} is not serializable. {str(exc)}") + fire_event( + Note(msg=f"type {event_type} is not serializable. {str(exc)}"), level=EventLevel.WARN + ) # We don't want an empty NodeInfo in output if ( "data" in msg_dict From 03ddcba7e99193ff670a5472a6bdcb822d903247 Mon Sep 17 00:00:00 2001 From: Quigley Malcolm Date: Fri, 31 Mar 2023 09:55:12 -0700 Subject: [PATCH 4/6] Add changie info for changes --- .changes/unreleased/Fixes-20230331-095428.yaml | 6 ++++++ 1 file changed, 6 insertions(+) create mode 100644 .changes/unreleased/Fixes-20230331-095428.yaml diff --git a/.changes/unreleased/Fixes-20230331-095428.yaml b/.changes/unreleased/Fixes-20230331-095428.yaml new file mode 100644 index 00000000000..772ce077b7d --- /dev/null +++ b/.changes/unreleased/Fixes-20230331-095428.yaml @@ -0,0 +1,6 @@ +kind: Fixes +body: Improved failed event serialization handling and associated tests +time: 2023-03-31T09:54:28.701963-07:00 +custom: + Author: QMalcolm + Issue: 7113 7108 6568 From 2fd0f7c227379ae3a1d985cffd3335c6ff413f92 Mon Sep 17 00:00:00 2001 From: Quigley Malcolm Date: Mon, 3 Apr 2023 16:07:55 -0700 Subject: [PATCH 5/6] Add test to check exception handling of `msg_to_dict` --- tests/unit/test_functions.py | 20 ++++++++++++++++++-- 1 file changed, 18 insertions(+), 2 deletions(-) diff --git a/tests/unit/test_functions.py b/tests/unit/test_functions.py index 4f7cb6845ac..f79648164fe 100644 --- a/tests/unit/test_functions.py +++ b/tests/unit/test_functions.py @@ -2,8 +2,8 @@ import pytest import dbt.flags as flags -from dbt.events.functions import warn_or_error -from dbt.events.types import NoNodesForSelectionCriteria +from dbt.events.functions import msg_to_dict, warn_or_error +from dbt.events.types import InfoLevel, NoNodesForSelectionCriteria from dbt.exceptions import EventCompilationError @@ -47,3 +47,19 @@ def test_warn_or_error_warn_error(warn_error, expect_compilation_exception): warn_or_error(NoNodesForSelectionCriteria()) else: warn_or_error(NoNodesForSelectionCriteria()) + + +def test_msg_to_dict_handles_exceptions_gracefully(): + class BadEvent(InfoLevel): + """A spoof Note event which breaks dictification""" + + def __init__(self): + self.__class__.__name__ = "Note" + + event = BadEvent() + try: + msg_to_dict(event) + except Exception as exc: + assert ( + False + ), f"We expect `msg_to_dict` to gracefully handle exceptions, but it raised {exc}" From b82864fe682bbc03d0f2a69e69ba2df11efdeef6 Mon Sep 17 00:00:00 2001 From: Quigley Malcolm Date: Tue, 11 Apr 2023 16:04:04 -0700 Subject: [PATCH 6/6] Ensure all events with self.msg stringify self.msg --- core/dbt/events/types.py | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/core/dbt/events/types.py b/core/dbt/events/types.py index 67d56946ba3..d92af6e6e48 100644 --- a/core/dbt/events/types.py +++ b/core/dbt/events/types.py @@ -769,7 +769,7 @@ def message(self) -> str: @dataclass -class ParseCmdOut(InfoLevel, pt.ParseCmdOut): +class ParseCmdOut(InfoLevel, EventStringFunctor, pt.ParseCmdOut): def code(self): return "I001" @@ -1163,7 +1163,7 @@ def message(self) -> str: @dataclass -class JinjaLogWarning(WarnLevel, pt.JinjaLogWarning): +class JinjaLogWarning(WarnLevel, EventStringFunctor, pt.JinjaLogWarning): def code(self): return "I061" @@ -2359,7 +2359,7 @@ def message(self) -> str: # The Note event provides a way to log messages which aren't likely to be useful as more structured events. # For conslole formatting text like empty lines and separator bars, use the Formatting event instead. @dataclass -class Note(InfoLevel, pt.Note): +class Note(InfoLevel, EventStringFunctor, pt.Note): def code(self): return "Z050"