CT-2264, CT-2259, CT-1783: Improved event serialization failure handl…

…ing (#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

* 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.

* Add changie info for changes

* Add test to check exception handling of `msg_to_dict`

.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/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

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,7 +1,10 @@
 # flake8: noqa
+import pytest
+import os
+import datetime
 from dbt.events.test_types import UnitTestInfo
 from dbt.events import AdapterLogger
-from dbt.events.functions import msg_to_json, LOG_VERSION, msg_to_dict
+from dbt.events.functions import msg_to_json, LOG_VERSION, msg_to_dict, fire_event
 from dbt.events.base_types import msg_from_base_event
 from dbt.events.types import *
 from dbt.events.test_types import *

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}"