CT-2264, CT-2259, CT-1783: Improved event serialization failure handling (#7249)

* Add tests for logging jinja2.Undefined objects

[CT-2259](#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

* Add tests for checking `DBT_ENV_SECRET_`s don't break logging

[CT-1783](#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

* Add tests ensuring failed event serialization is handled correctly

[CT-2264](#7113) states
that failed serialization should result in an exception handling path
which will fire another event instead of raising an exception. This is
hard to test perfectly because the exception handling path for
serialization depending on whether pytest is present. If pytest isn't
present, a new event documentation the failed serialization is fired.
If pytest is present, the failed serialization gets raised as an exception.
Thus this added test ensures that the expected exception is raised and
assumes that the correct event will be fired normally.

* 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.
Truthfully, we're not sure if this exception handling path is even
possible to hit. That's because we recently switched from betterproto
to google's protobuf. However, exception path is the subject of
[CT-2264](#7113). Though we
don't think it's actually possible to hit it anymore, we still want
to handle the case if it is.

* Update serialization failure note to be a warn level event in `BaseEvent`

[CT-2264](#7113) wants
logging messages about event serialization failure to be `WARNING`
level events. This does that.

* Add changie info for changes

* Add test to check exception handling of `msg_to_dict`

Author: QMalcolm

.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

core/dbt/events/base_types.py

@@ -79,7 +79,7 @@ def __init__(self, *args, **kwargs):
             if "pytest" in sys.modules:
                 raise Exception(error_msg)
             else:
-                fire_event(Note(msg=error_msg))
+                fire_event(Note(msg=error_msg), level=EventLevel.WARN)
                 self.pb_msg = msg_cls()
 
     def __setattr__(self, key, value):

core/dbt/events/functions.py

@@ -2,7 +2,7 @@
 from dbt.events.base_types import BaseEvent, EventLevel, EventMsg
 from dbt.events.eventmgr import EventManager, LoggerConfig, LineFormat, NoFilter
 from dbt.events.helpers import env_secrets, scrub_secrets
-from dbt.events.types import Formatting
+from dbt.events.types import Formatting, Note
 from dbt.flags import get_flags, ENABLE_LEGACY_LOGGER
 from dbt.logger import GLOBAL_LOGGER, make_log_dir_if_missing
 from functools import partial
@@ -219,7 +219,9 @@ def msg_to_dict(msg: EventMsg) -> dict:
         )
     except Exception 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

tests/unit/test_base_context.py

@@ -0,0 +1,22 @@
+import os
+
+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}"
+
+    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}"

tests/unit/test_events.py

@@ -1,3 +1,4 @@
+import pytest
 import re
 from typing import TypeVar
 
@@ -443,3 +444,21 @@ def test_date_serialization():
     ti_dict = ti.to_dict()
     assert ti_dict["started_at"].endswith("Z")
     assert ti_dict["completed_at"].endswith("Z")
+
+
+def test_bad_serialization():
+    """Tests that bad serialization enters the proper exception handling
+
+    When pytest is in use the exception handling of `BaseEvent` raises an
+    exception. When pytest isn't present, it fires a Note event. Thus to test
+    that bad serializations are properly handled, the best we can do is test
+    that the exception handling path is used.
+    """
+
+    with pytest.raises(Exception) as excinfo:
+        types.Note(param_event_doesnt_have="This should break")
+
+    assert (
+        str(excinfo.value)
+        == "[Note]: Unable to parse dict {'param_event_doesnt_have': 'This should break'}"
+    )

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
 
 
@@ -43,3 +43,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}"