[CT-2264] Don't raise exception during event serialization failure, just log warning

[jtcohen6]

Instead of raising as an Exception that stops the whole run, let's instead fire a different warn-level event to call out the event serialization failure. Ideally, this would include enough information about the event's contents (serialized as a string?) that would be helpful in debugging, but let's make extra sure that doesn't silently/loudly fail either.

In main branch:

dbt-core/core/dbt/events/functions.py

Lines 205 to 209 in 72076b3

	try:
	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)}")

In 1.3.latest (should be similar in 1.2.latest and 1.1.latest):

dbt-core/core/dbt/events/functions.py

Lines 129 to 135 in 7f2e9f9

	try:
	log_line = e.to_dict()
	except AttributeError as exc:
	event_type = type(e).__name__
	raise Exception( # TODO this may hang async threads
	f"type {event_type} is not serializable. {str(exc)}"
	)

[gshank]

Duh. An obvious improvement. Should have thought of this before...

[jtcohen6]

Opened this up while chatting with @QMalcolm earlier! We were taking a look at:

• [CT-2259] Avoid serialization error of Undefined with JSON-formatted logs #7108
• [CT-1783] [Bug] AttributeError: 'dict' object has no attribute 'replace' when logging a dict if an DBT_ENV_SECRET_ env var is set #6568

Both of those have actually been fixed in main / 1.4.latest, but it's worth:

• adding tests for the odd behavior to main (to ensure we don't regress on either one in the future)
• making this change, to prevent serialization errors from ever being a deal-breaker
• backporting those patches to older versions (v1.1, v1.2, v1.3)

[jtcohen6]

Proposed catch-all fixes for:

• 1.0.latest: fd83cc7
• 1.1.latest, 1.2.latest, 1.3.latest: dd9bcdd (need to handle errors dict construction and also during JSON serialization)

I tested those changes with the reproduction case from #7108, and it gracefully handled the bad log message:

{"code": "A001", "data": {"v": "=1.3.3"}, "invocation_id": "c3726ca0-9001-46d7-a554-21e5299f0333", "level": "info", "log_version": 2, "msg": "Running with dbt=1.3.3", "pid": 71932, "thread_name": "MainThread", "ts": "2023-03-03T21:16:43.492425Z", "type": "log_line"}
{"code": "W006", "data": {"stat_line": "1 model, 0 tests, 0 snapshots, 0 analyses, 290 macros, 0 operations, 1 seed file, 0 sources, 0 exposures, 0 metrics"}, "invocation_id": "c3726ca0-9001-46d7-a554-21e5299f0333", "level": "info", "log_version": 2, "msg": "Found 1 model, 0 tests, 0 snapshots, 0 analyses, 290 macros, 0 operations, 1 seed file, 0 sources, 0 exposures, 0 metrics", "pid": 71932, "thread_name": "MainThread", "ts": "2023-03-03T21:16:43.574628Z", "type": "log_line"}
{"code": "Q026", "data": {"num_threads": 5, "target_name": "dev"}, "invocation_id": "c3726ca0-9001-46d7-a554-21e5299f0333", "level": "info", "log_version": 2, "msg": "Concurrency: 5 threads (target='dev')", "pid": 71932, "thread_name": "MainThread", "ts": "2023-03-03T21:16:43.778860Z", "type": "log_line"}
{"code": "Q033", "data": {"description": "sql view model dbt_jcohen.my_model", "index": 1, "node_info": {"materialized": "view", "node_finished_at": null, "node_name": "my_model", "node_path": "my_model.sql", "node_started_at": "2023-03-03T21:16:43.782645", "node_status": "started", "resource_type": "model", "unique_id": "model.test.my_model"}, "total": 1}, "invocation_id": "c3726ca0-9001-46d7-a554-21e5299f0333", "level": "info", "log_version": 2, "msg": "1 of 1 START sql view model dbt_jcohen.my_model ................................ [RUN]", "pid": 71932, "thread_name": "Thread-1", "ts": "2023-03-03T21:16:43.783106Z", "type": "log_line"}
{"code": "Z046", "data": {"log_fmt": "", "msg": "Error while serializing MacroEventInfo(msg=Undefined, code='M011')"}, "invocation_id": "c3726ca0-9001-46d7-a554-21e5299f0333", "level": "warn", "log_version": 2, "msg": "", "pid": 71932, "thread_name": "Thread-1", "ts": "2023-03-03T21:16:43.786917Z", "type": "log_line"}
{"code": "Q012", "data": {"description": "sql view model dbt_jcohen.my_model", "execution_time": 0, "index": 1, "node_info": {"materialized": "view", "node_finished_at": null, "node_name": "my_model", "node_path": "my_model.sql", "node_started_at": "2023-03-03T21:16:43.782645", "node_status": "compiling", "resource_type": "model", "unique_id": "model.test.my_model"}, "status": "CREATE VIEW", "total": 1}, "invocation_id": "c3726ca0-9001-46d7-a554-21e5299f0333", "level": "info", "log_version": 2, "msg": "1 of 1 OK created sql view model dbt_jcohen.my_model ........................... [\u001b[32mCREATE VIEW\u001b[0m in 0.08s]", "pid": 71932, "thread_name": "Thread-1", "ts": "2023-03-03T21:16:43.867398Z", "type": "log_line"}
{"code": "E040", "data": {"execution": " in 0 hours 0 minutes and 0.30 seconds", "execution_time": 0.3049299716949463, "stat_line": "1 view model"}, "invocation_id": "c3726ca0-9001-46d7-a554-21e5299f0333", "level": "info", "log_version": 2, "msg": "Finished running 1 view model in 0 hours 0 minutes and 0.30 seconds (0.30s).", "pid": 71932, "thread_name": "MainThread", "ts": "2023-03-03T21:16:43.880736Z", "type": "log_line"}
{"code": "Z030", "data": {"keyboard_interrupt": false, "num_errors": 0, "num_warnings": 0}, "invocation_id": "c3726ca0-9001-46d7-a554-21e5299f0333", "level": "info", "log_version": 2, "msg": "\u001b[32mCompleted successfully\u001b[0m", "pid": 71932, "thread_name": "MainThread", "ts": "2023-03-03T21:16:43.887088Z", "type": "log_line"}
{"code": "Z023", "data": {"stats": {"error": 0, "pass": 1, "skip": 0, "total": 1, "warn": 0}}, "invocation_id": "c3726ca0-9001-46d7-a554-21e5299f0333", "level": "info", "log_version": 2, "msg": "Done. PASS=1 WARN=0 ERROR=0 SKIP=0 TOTAL=1", "pid": 71932, "thread_name": "MainThread", "ts": "2023-03-03T21:16:43.887329Z", "type": "log_line"}

We can do something nicer for main + 1.4.latest, which are using the nice new event system

[gshank]

Also "tojson" can cause a similar error.