[Bug] "dbt run --log-format json" throws exception "Encountered an error:Object of type CompilationException is not JSON serializable"

[zsvoboda]

Is there an existing issue for this?

• [X] I have searched the existing issues

Current Behavior

python --version

Python 3.8.12

 pip --version

pip 22.1.2 from /Users/xxx/.pyenv/versions/3.8.12/lib/python3.8/site-packages/pip (python 3.8)

dbt --version

- installed: 1.1.0
  - latest:    1.1.0 - Up to date!

Plugins:
  - trino:     1.1.0 - Up to date!
  - bigquery:  1.1.0 - Up to date!
  - snowflake: 1.1.0 - Up to date!
  - redshift:  1.1.0 - Up to date!
  - postgres:  1.1.0 - Up to date!
  - spark:     1.1.0 - Up to date!

dbt  --log-format json run

throws:

{"code": "A001", "data": {"v": "=1.1.0"}, "invocation_id": "33f6d5ef-a3f3-4373-b8b9-f30159894015", "level": "info", "log_version": 2, "msg": "Running with dbt=1.1.0", "pid": 31958, "thread_name": "MainThread", "ts": "2022-06-10T12:34:55.428292Z", "type": "log_line"}
{"code": "W006", "data": {"stat_line": "4 models, 0 tests, 0 snapshots, 0 analyses, 200 macros, 0 operations, 0 seed files, 0 sources, 0 exposures, 0 metrics"}, "invocation_id": "33f6d5ef-a3f3-4373-b8b9-f30159894015", "level": "info", "log_version": 2, "msg": "Found 4 models, 0 tests, 0 snapshots, 0 analyses, 200 macros, 0 operations, 0 seed files, 0 sources, 0 exposures, 0 metrics", "pid": 31958, "thread_name": "MainThread", "ts": "2022-06-10T12:34:55.474334Z", "type": "log_line"}
{"code": "Z002", "data": {"e": "Object of type CompilationException is not JSON serializable"}, "invocation_id": "33f6d5ef-a3f3-4373-b8b9-f30159894015", "level": "error", "log_version": 2, "msg": "Encountered an error:\nObject of type CompilationException is not JSON serializable", "pid": 31958, "thread_name": "MainThread", "ts": "2022-06-10T12:34:56.316655Z", "type": "log_line"}

Expected Behavior

Run the model as if I don't specify the --log-format json flag

Steps To Reproduce

1. MacOSX 12.4 / M1
2. pip install dbt-core "dbt-spark[PyHive]" dbt-trino dbt-postgres
3. Run any project via dbt --log-format json run

Relevant log output

{"code": "A001", "data": {"v": "=1.1.0"}, "invocation_id": "33f6d5ef-a3f3-4373-b8b9-f30159894015", "level": "info", "log_version": 2, "msg": "Running with dbt=1.1.0", "pid": 31958, "thread_name": "MainThread", "ts": "2022-06-10T12:34:55.428292Z", "type": "log_line"}
{"code": "W006", "data": {"stat_line": "4 models, 0 tests, 0 snapshots, 0 analyses, 200 macros, 0 operations, 0 seed files, 0 sources, 0 exposures, 0 metrics"}, "invocation_id": "33f6d5ef-a3f3-4373-b8b9-f30159894015", "level": "info", "log_version": 2, "msg": "Found 4 models, 0 tests, 0 snapshots, 0 analyses, 200 macros, 0 operations, 0 seed files, 0 sources, 0 exposures, 0 metrics", "pid": 31958, "thread_name": "MainThread", "ts": "2022-06-10T12:34:55.474334Z", "type": "log_line"}
{"code": "Z002", "data": {"e": "Object of type CompilationException is not JSON serializable"}, "invocation_id": "33f6d5ef-a3f3-4373-b8b9-f30159894015", "level": "error", "log_version": 2, "msg": "Encountered an error:\nObject of type CompilationException is not JSON serializable", "pid": 31958, "thread_name": "MainThread", "ts": "2022-06-10T12:34:56.316655Z", "type": "log_line"}

Environment

- OS:
- Python:
- dbt:

What database are you using dbt with?

No response

Additional Context

Spark[PyHive]

kt_spark:
  target: dev
  outputs:
    dev:
      type: spark
      method: thrift
      host: localhost
      port: 10000
      schema: silver
      user: dbt
      password: dbt
      auth: NOSASL
      connect_retries: 5
      connect_timeout: 60
      retry_all: true

[zsvoboda]

Downgrading to 1.0.0 fixes the issue.

[jtcohen6]

@zsvoboda Thanks for opening! It sounds like this is cropping up here in dbt-spark, where we're running the equivalent of:

from dbt.events import AdapterLogger
logger = AdapterLogger("Spark")
...
        except Exception as exc:
            logger.debug("Error while running:\n{}".format(sql))
            logger.debug(exc)

I believe this falls under a broader category of JSON serialization issues that we've been seeing with the AdapterLogger, when a dbt adapter tries to log a complex object, and it's not being unpacked/stringified correctly within dbt-core: https://github.com/dbt-labs/dbt-core/issues/5436

Downgrading to 1.0.0 fixes the issue.

This is a good hint—it sounds like the issue may have resurfaced during the change to our JSON serialization logic for events in v1.1 (possibly https://github.com/dbt-labs/dbt-core/pull/4505).

We'll take a look at resolving that issue, once and for all.

[zsvoboda]

Hi, do you have any updates on this? I tried 1.2.0, and the issue persisted.

[Fleid]

FYI, the PR is being finalized : https://github.com/dbt-labs/dbt-core/pull/5874

[VersusFacit]

Closing for cleanup post merge of #5874 .