[CT-792] [Bug] Warnings are being logged as errors during dbt test

[alexrosenfeld10]

Is there an existing issue for this?

• I have searched the existing issues

Current Behavior

Warnings are logged as errors during dbt tests output when tests have configured thresholds. This is quite an issue for me actually because I want to drive automated alerting on conditions like "are there any error logs" and this totally breaks the ability to do that.

Expected Behavior

Warnings should be logged at their appropriate level.

Steps To Reproduce

1. Set up a dbt project with a model with severity configured tests, like such:

version: 2

models:
  - name: my_model
    columns:
      - name: id
        tests:
          - unique:
              config:
                severity: warn

2. set up data such that my_model will fail (should trigger a warning)
3. run dbt --log-format json test
4. Observe results. You should have a log line that looks like this:

{"code": "Z024", "data": {"msg": "Got 3 results, configured to warn if != 0"}, "invocation_id": "blah", "level": "error", "log_version": 2, "msg": "  Got 3 results, configured to warn if != 0", "pid": 6816, "thread_name": "MainThread", "ts": "2022-06-29T18:03:13.214485Z", "type": "log_line"}

You'll notice the log is written with "level": "error", this is the problem.

Relevant log output

No response

Environment

- OS: macOS
- Python:

❯ python --version
Python 3.10.4

• dbt:

❯ dbt --version
Core:
  - installed: 1.1.1
  - latest:    1.1.1 - Up to date!

Plugins:
  - snowflake: 1.1.0 - Up to date!

### What database are you using dbt with?

snowflake

### Additional Context

_No response_

[lostmygithubaccount]

quick disclaimer: I am a relatively new product manager at dbt Labs working in Core. I'm fairly confident all of this is correct, but unsure of exactly how to fix (at least without side affects I'm not sure are okay).

I am able to verify the issue and (roughly) find the root cause. Normal CLI output for a unique test configured to warn is expected:

(debug) cody@dbtpro debug-dbt % dbt test 
20:36:05  Running with dbt=1.1.1
20:36:05  Found 5 models, 1 test, 0 snapshots, 2 analyses, 224 macros, 0 operations, 0 seed files, 1 source, 0 exposures, 0 metrics
20:36:05  
20:36:05  Concurrency: 8 threads (target='dev')
20:36:05  
20:36:05  1 of 1 START test unique_stg_green_taxi_color .................................. [RUN]
20:36:08  1 of 1 WARN 1 unique_stg_green_taxi_color ...................................... [WARN 1 in 2.14s]
20:36:08  
20:36:08  Finished running 1 test in 2.62s.
20:36:08  
20:36:08  Completed with 1 warning:
20:36:08  
20:36:08  Warning in test unique_stg_green_taxi_color (models/staging/models.yml)
20:36:08    Status: warn
20:36:08  
20:36:08    compiled SQL at target/compiled/nyc_taxi_demo/models/staging/models.yml/unique_stg_green_taxi_color.sql
20:36:08  
20:36:08  Done. PASS=0 WARN=1 ERROR=0 SKIP=0 TOTAL=1

However the json output (with a little re-formatting) shows "level": "error", which seems incorrect and would cause issues as described if used for downstream logic:

{
    "code": "Z024",
    "data": {
        "msg": "Got 1 result, configured to warn if != 0"
    },
    "invocation_id": "928cf171-d56b-422d-9013-499787674eaf",
    "level": "error",
    "log_version": 2,
    "msg": "  Got 1 result, configured to warn if != 0",
    "pid": 8752,
    "thread_name": "MainThread",
    "ts": "2022-07-22T20:39:02.561431Z",
    "type": "log_line"
}

This is coming from this line: https://github.com/dbt-labs/dbt-core/blob/main/core/dbt/task/printer.py#L102

It is easy enough to write some logic to instead fire a warning instead of an error, but doing so from my local testing is affecting the logs in other ways I'm not sure are acceptable. For example: c98d7f2

Before change:

{"code": "A001", "data": {"v": "=1.1.1"}, "invocation_id": "b741ef3d-13e6-427e-ac8f-33d7dc2d6ed9", "level": "info", "log_version": 2, "msg": "Running with dbt=1.1.1", "pid": 8861, "thread_name": "MainThread", "ts": "2022-07-22T20:42:05.673627Z", "type": "log_line"}
{"code": "W006", "data": {"stat_line": "5 models, 1 test, 0 snapshots, 2 analyses, 224 macros, 0 operations, 0 seed files, 1 source, 0 exposures, 0 metrics"}, "invocation_id": "b741ef3d-13e6-427e-ac8f-33d7dc2d6ed9", "level": "info", "log_version": 2, "msg": "Found 5 models, 1 test, 0 snapshots, 2 analyses, 224 macros, 0 operations, 0 seed files, 1 source, 0 exposures, 0 metrics", "pid": 8861, "thread_name": "MainThread", "ts": "2022-07-22T20:42:05.708022Z", "type": "log_line"}
{"code": "Q026", "data": {"num_threads": 1, "target_name": "dev"}, "invocation_id": "b741ef3d-13e6-427e-ac8f-33d7dc2d6ed9", "level": "info", "log_version": 2, "msg": "Concurrency: 1 threads (target='dev')", "pid": 8861, "thread_name": "MainThread", "ts": "2022-07-22T20:42:06.234328Z", "type": "log_line"}
{"code": "Q033", "data": {"description": "test unique_stg_green_taxi_color", "index": 1, "node_info": {"materialized": "test", "node_finished_at": null, "node_name": "unique_stg_green_taxi_color", "node_path": "unique_stg_green_taxi_color.sql", "node_started_at": "2022-07-22T20:42:06.237576", "node_status": "started", "resource_type": "test", "unique_id": "test.nyc_taxi_demo.unique_stg_green_taxi_color.b72aa30692"}, "total": 1}, "invocation_id": "b741ef3d-13e6-427e-ac8f-33d7dc2d6ed9", "level": "info", "log_version": 2, "msg": "1 of 1 START test unique_stg_green_taxi_color .................................. [RUN]", "pid": 8861, "thread_name": "Thread-1", "ts": "2022-07-22T20:42:06.237914Z", "type": "log_line"}
{"code": "Q010", "data": {"execution_time": 0, "failures": 1, "index": 1, "name": "unique_stg_green_taxi_color", "node_info": {"materialized": "test", "node_finished_at": null, "node_name": "unique_stg_green_taxi_color", "node_path": "unique_stg_green_taxi_color.sql", "node_started_at": null, "node_status": "executing", "resource_type": "test", "unique_id": "test.nyc_taxi_demo.unique_stg_green_taxi_color.b72aa30692"}, "num_models": 1}, "invocation_id": "b741ef3d-13e6-427e-ac8f-33d7dc2d6ed9", "level": "warn", "log_version": 2, "msg": "1 of 1 WARN 1 unique_stg_green_taxi_color ...................................... [\u001b[33mWARN 1\u001b[0m in 0.47s]", "pid": 8861, "thread_name": "Thread-1", "ts": "2022-07-22T20:42:06.706175Z", "type": "log_line"}
{"code": "E040", "data": {"execution": " in 1.00s", "stat_line": "1 test"}, "invocation_id": "b741ef3d-13e6-427e-ac8f-33d7dc2d6ed9", "level": "info", "log_version": 2, "msg": "Finished running 1 test in 1.00s.", "pid": 8861, "thread_name": "MainThread", "ts": "2022-07-22T20:42:06.708953Z", "type": "log_line"}
{"code": "Z030", "data": {"keyboard_interrupt": false, "num_errors": 0, "num_warnings": 1}, "invocation_id": "b741ef3d-13e6-427e-ac8f-33d7dc2d6ed9", "level": "info", "log_version": 2, "msg": "\u001b[33mCompleted with 1 warning:\u001b[0m", "pid": 8861, "thread_name": "MainThread", "ts": "2022-07-22T20:42:06.717999Z", "type": "log_line"}
{"code": "Z021", "data": {"node_name": "unique_stg_green_taxi_color", "path": "models/staging/models.yml", "resource_type": "test"}, "invocation_id": "b741ef3d-13e6-427e-ac8f-33d7dc2d6ed9", "level": "warn", "log_version": 2, "msg": "\u001b[33mWarning in test unique_stg_green_taxi_color (models/staging/models.yml)\u001b[0m", "pid": 8861, "thread_name": "MainThread", "ts": "2022-07-22T20:42:06.718432Z", "type": "log_line"}
{"code": "Z024", "data": {"msg": "Got 1 result, configured to warn if != 0"}, "invocation_id": "b741ef3d-13e6-427e-ac8f-33d7dc2d6ed9", "level": "error", "log_version": 2, "msg": "  Got 1 result, configured to warn if != 0", "pid": 8861, "thread_name": "MainThread", "ts": "2022-07-22T20:42:06.718787Z", "type": "log_line"}
{"code": "Z026", "data": {"path": "target/compiled/nyc_taxi_demo/models/staging/models.yml/unique_stg_green_taxi_color.sql"}, "invocation_id": "b741ef3d-13e6-427e-ac8f-33d7dc2d6ed9", "level": "info", "log_version": 2, "msg": "  compiled SQL at target/compiled/nyc_taxi_demo/models/staging/models.yml/unique_stg_green_taxi_color.sql", "pid": 8861, "thread_name": "MainThread", "ts": "2022-07-22T20:42:06.719120Z", "type": "log_line"}
{"code": "Z023", "data": {"stats": {"error": 0, "pass": 0, "skip": 0, "total": 1, "warn": 1}}, "invocation_id": "b741ef3d-13e6-427e-ac8f-33d7dc2d6ed9", "level": "info", "log_version": 2, "msg": "Done. PASS=0 WARN=1 ERROR=0 SKIP=0 TOTAL=1", "pid": 8861, "thread_name": "MainThread", "ts": "2022-07-22T20:42:06.719460Z", "type": "log_line"}

After change:

{"code": "A001", "data": {"v": "=1.1.1"}, "invocation_id": "5dc58a24-6bad-4f66-af08-48459d16aad4", "level": "info", "log_version": 2, "msg": "Running with dbt=1.1.1", "pid": 8952, "thread_name": "MainThread", "ts": "2022-07-22T20:42:52.124460Z", "type": "log_line"}
{"code": "W006", "data": {"stat_line": "5 models, 1 test, 0 snapshots, 2 analyses, 224 macros, 0 operations, 0 seed files, 1 source, 0 exposures, 0 metrics"}, "invocation_id": "5dc58a24-6bad-4f66-af08-48459d16aad4", "level": "info", "log_version": 2, "msg": "Found 5 models, 1 test, 0 snapshots, 2 analyses, 224 macros, 0 operations, 0 seed files, 1 source, 0 exposures, 0 metrics", "pid": 8952, "thread_name": "MainThread", "ts": "2022-07-22T20:42:52.160494Z", "type": "log_line"}
{"code": "Q026", "data": {"num_threads": 1, "target_name": "dev"}, "invocation_id": "5dc58a24-6bad-4f66-af08-48459d16aad4", "level": "info", "log_version": 2, "msg": "Concurrency: 1 threads (target='dev')", "pid": 8952, "thread_name": "MainThread", "ts": "2022-07-22T20:42:52.717238Z", "type": "log_line"}
{"code": "Q033", "data": {"description": "test unique_stg_green_taxi_color", "index": 1, "node_info": {"materialized": "test", "node_finished_at": null, "node_name": "unique_stg_green_taxi_color", "node_path": "unique_stg_green_taxi_color.sql", "node_started_at": "2022-07-22T20:42:52.719700", "node_status": "started", "resource_type": "test", "unique_id": "test.nyc_taxi_demo.unique_stg_green_taxi_color.b72aa30692"}, "total": 1}, "invocation_id": "5dc58a24-6bad-4f66-af08-48459d16aad4", "level": "info", "log_version": 2, "msg": "1 of 1 START test unique_stg_green_taxi_color .................................. [RUN]", "pid": 8952, "thread_name": "Thread-1", "ts": "2022-07-22T20:42:52.719997Z", "type": "log_line"}
{"code": "Q010", "data": {"execution_time": 0, "failures": 1, "index": 1, "name": "unique_stg_green_taxi_color", "node_info": {"materialized": "test", "node_finished_at": null, "node_name": "unique_stg_green_taxi_color", "node_path": "unique_stg_green_taxi_color.sql", "node_started_at": null, "node_status": "executing", "resource_type": "test", "unique_id": "test.nyc_taxi_demo.unique_stg_green_taxi_color.b72aa30692"}, "num_models": 1}, "invocation_id": "5dc58a24-6bad-4f66-af08-48459d16aad4", "level": "warn", "log_version": 2, "msg": "1 of 1 WARN 1 unique_stg_green_taxi_color ...................................... [\u001b[33mWARN 1\u001b[0m in 0.43s]", "pid": 8952, "thread_name": "Thread-1", "ts": "2022-07-22T20:42:53.150600Z", "type": "log_line"}
{"code": "E040", "data": {"execution": " in 0.99s", "stat_line": "1 test"}, "invocation_id": "5dc58a24-6bad-4f66-af08-48459d16aad4", "level": "info", "log_version": 2, "msg": "Finished running 1 test in 0.99s.", "pid": 8952, "thread_name": "MainThread", "ts": "2022-07-22T20:42:53.152556Z", "type": "log_line"}
{"code": "Z030", "data": {"keyboard_interrupt": false, "num_errors": 0, "num_warnings": 1}, "invocation_id": "5dc58a24-6bad-4f66-af08-48459d16aad4", "level": "info", "log_version": 2, "msg": "\u001b[33mCompleted with 1 warning:\u001b[0m", "pid": 8952, "thread_name": "MainThread", "ts": "2022-07-22T20:42:53.159532Z", "type": "log_line"}
{"code": "Z021", "data": {"node_name": "unique_stg_green_taxi_color", "path": "models/staging/models.yml", "resource_type": "test"}, "invocation_id": "5dc58a24-6bad-4f66-af08-48459d16aad4", "level": "warn", "log_version": 2, "msg": "\u001b[33mWarning in test unique_stg_green_taxi_color (models/staging/models.yml)\u001b[0m", "pid": 8952, "thread_name": "MainThread", "ts": "2022-07-22T20:42:53.159837Z", "type": "log_line"}
{"code": "Z002", "data": {"e": "__init__() got an unexpected keyword argument 'msg'"}, "invocation_id": "5dc58a24-6bad-4f66-af08-48459d16aad4", "level": "error", "log_version": 2, "msg": "Encountered an error:\n__init__() got an unexpected keyword argument 'msg'", "pid": 8952, "thread_name": "MainThread", "ts": "2022-07-22T20:42:53.466416Z", "type": "log_line"}

I think I'm clearly missing something in the logic, but will post this comment to capture my investigation.

[jtcohen6]

@lostmygithubaccount Exactly the right spot!

A test warning is being fired as RunResultError, which is an ErrorLevel event type.

The test status and message gets set in the test task here:

dbt-core/core/dbt/task/test.py

Lines 190 to 196 in 1071a46

	elif result.should_warn:
	if flags.WARN_ERROR:
	status = TestStatus.Fail
	message = f"Got {num_errors}, configured to fail if {test.config.warn_if}"
	else:
	status = TestStatus.Warn
	message = f"Got {num_errors}, configured to warn if {test.config.warn_if}"

The message correctly contains the word "warn," so the node should have TestStatus.Warn as its status.

Then, in the generic task printer.py, there's a tricky bit of conditional branching happening. This sends this test warning to be fired as a warning:

dbt-core/core/dbt/task/printer.py

Lines 135 to 136 in 1071a46

	elif r.status == NodeStatus.Warn:
	warnings.append(r)

dbt-core/core/dbt/task/printer.py

Lines 152 to 153 in 1071a46

	for warning in warnings:
	print_run_result_error(warning, is_warning=True)

dbt-core/core/dbt/task/printer.py

Lines 83 to 91 in 1071a46

	if result.status == NodeStatus.Fail or (is_warning and result.status == NodeStatus.Warn):
	if is_warning:
	fire_event(
	RunResultWarning(
	resource_type=result.node.resource_type,
	node_name=result.node.name,
	path=result.node.original_file_path,
	)
	)

That all works correctly — but then, just below, it also sends it to be fired as a RunResultError!

dbt-core/core/dbt/task/printer.py

Lines 101 to 104 in 1071a46

	if result.message:
	fire_event(RunResultError(msg=result.message))
	else:
	fire_event(RunResultErrorNoMessage(status=result.status))

09:11:29  Warning in test not_null_model_a_id (models/schema.yml) <--- RunResultWarning, "warn" level
09:11:29    Got 1 result, configured to warn if != 0              <--- RunResultError, "error" level

When this is a real failure (error-level severity, rather than warn):

09:12:38  Failure in test not_null_model_a_id (models/schema.yml) <--- RunResultFailure, "error" level
09:12:38    Got 1 result, configured to fail if != 0              <--- RunResultError, "error" level

IMO the resolution here looks a lot like the one you're recommending:

• Fire an error-level warn-level version of RunResultError, depending on whether is_warning
• Disambiguate between these event types, whose names are a bit too confusing:
  • "warning/failure in test" — RunResultFailure + RunResultWarning (current)
  • "got X result, configured to warn/fail if" — perhaps RunResultFailureDetails (renamed) + RunResultWarningDetails (new)