-
Notifications
You must be signed in to change notification settings - Fork 1.7k
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
[CT-2264] Don't raise exception during event serialization failure, just log warning #7113
Comments
Duh. An obvious improvement. Should have thought of this before... |
Opened this up while chatting with @QMalcolm earlier! We were taking a look at:
Both of those have actually been fixed in
|
Proposed catch-all fixes for:
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 |
Also "tojson" can cause a similar error. |
[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.
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.
…ent` [CT-2264](#7113) wants logging messages about event serialization failure to be `WARNING` level events. This does that.
…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 * 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`
…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 * 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`
…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 * 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`
…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`
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.
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
In
1.3.latest
(should be similar in1.2.latest
and1.1.latest
):dbt-core/core/dbt/events/functions.py
Lines 129 to 135 in 7f2e9f9
The text was updated successfully, but these errors were encountered: