[BACKPORT 1.4.latest] Improved event log msg stringification (#7342)

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

* Add changie info for changes

* Add test to check exception handling of `msg_to_dict`

* Ensure all events with self.msg stringify self.msg

---------

Co-authored-by: leahwicz <[email protected]>

.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

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"
 

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