Working solution serialization bug.

[VersusFacit]

resolves #5436
resolves #5385

Description

Ho, boy! What an odyssey. This PR has some reworks to the adapter logging functions for dbt. These changes help us conform to the intended spec of the logging classes. The resulting behavior makes our log functions reminiscent of python's print().

reproducing the errors

5385 models/asdf.sql:

{% set some_list = ['a', 'b', 'c'] %}
{{ log(some_list, info = true) }}
select 1 as id

DBT_ENV_SECRET_WHATEVER=1234 dbt run -s asdf

5436 asdf2.sql:

dbt --no-use-colors --log-format json run -s asdf2 | jq .msg

select * from foo.bar

——————

dbt-bigquery==1.0.0
dbt-core==1.0.8

1 of 1 START table model my_dataset.asdf........................................ [RUN]
Unhandled error while executing model.jaffle_shop.asdf
Pickling client objects is explicitly not supported.
Clients have non-trivial state that is local and unpickleable.
1 of 1 ERROR creating table model my_dataset.asdf............................... [ERROR in 0.61s]
Finished running 1 table model in 1.47s.
Completed with 1 error and 0 warnings:
Pickling client objects is explicitly not supported.
Clients have non-trivial state that is local and unpickleable.

dbt-bigquery==1.1.0
dbt-core==1.1.2

dbt-bigquery==1.2.0
dbt-bigquery==1.3.0b2

dbt-core==1.3.0b2
dbt-core==1.2.1

1 of 1 START table model my_dataset.asdf ....................................... [RUN]
1 of 1 ERROR creating table model my_dataset.asdf .............................. [ERROR in 0.53s]
Finished running 1 table model in 1.17s.
Completed with 1 error and 0 warnings:
Compilation Error in macro statement (macros/etc/statement.sql)
Object of type NotFound is not JSON serializable

in macro materialization_table_bigquery (macros/materializations/table.sql)
called by macro statement (macros/etc/statement.sql)

Error 1: Serialization Woes

json.dumps presumes that all elements within a dictionary can be simply rendered as a json string. But complex objects inside the argument will cause a serialization error. This happens precisely at line 209 of core/dbt/events/functions.

Several classes have msg parameter. This spec does not always match reality: Some arguments are not strings. This leads to trouble when logger member function calls are made. So, if we force the message given to logger functions to be a string, the spec matches reality and the error vanishes. Local proof of it working on development.

This error is what the user OwenKephart graciously documented over in Bigquery issue 206 as a desired output for my test case model, designed to fail.

QED.

Error 2: Secret scrubbing implodes when provided a non-str type

Jinja log hands a type to Python which should but isn't always a string. Although, we have a function scrub_secrets which expects that.

By making sure these MacroEvent* types are all in fact strings, we solve the current problem and hopefully, future ones.

Checklist

• I have read the contributing guide and understand what's expected of me
• I have signed the CLA
• I have run this code in development and it appears to resolve the stated issue
• This PR includes tests, or tests are not required/relevant for this PR
• I have opened an issue to add/update docs, or docs changes are not required/relevant for this PR
• I have run changie new to create a changelog entry

[github-actions]

Thank you for your pull request! We could not find a changelog entry for this change. For details on how to document a change, see the contributing guide.

[gshank]

We're converting all of these Exception object to strings in the next structured logging update anyway, because everything in the event has to be encoded into a protobuf message.

[colin-rogers-dbt]

LGTM

[nathaniel-may]

So it looks like #5385 has the exact same problem (passing a non-string to log). Since it's jinja log, the first the value time exits Jinja-land into our control is in fire_event. My question to you is- do you think we should solve this lower in the call stack to knock both of these bugs out?

[VersusFacit]

Revised in light of the recent structured logging change.

PR description revised, mostly expanded to describe the second bug.

Employs the same subclass-as-trait paradigm to . And for good measure, I did check the new structured logging code on main still exhibits the bugs described in the linked issues before folding these changes into the code.

[colin-rogers-dbt]

do we need to check if base_msg exists?

[VersusFacit]

Thought about this. We're talking data classes so these objects must be instantiated with params. A little toy example:

from dataclasses import dataclass

@dataclass
class Item:
    a:str
    b:str
    c:str

asdf = Item()

Try running this and it complains:

TypeError: init() missing 3 required positional arguments: 'a', 'b', and 'c'

Hence, if a dataclass exists, it's gotta have the params. And this functor should only be used in classes that have this param. I think that renders an existential check redundant? (if it's not, tell me)

[colin-rogers-dbt]

Makes sense, just one question. Also, do we need unit tests to validate this behavior?

[VersusFacit]

Unsure about unit tests. Is it worth having tests to check that the intended spec holds for something like the structured logging? That feels extra to me, but I'm also open to writing some quick ones if it seems like a good idea from your POV!

[colin-rogers-dbt]

LGTM