[CT-1783] [Bug] `AttributeError: 'dict' object has no attribute 'replace'` when logging a dict if an `DBT_ENV_SECRET_` env var is set

[jeremyyeo]

Is this a new bug in dbt-core?

• I believe this is a new bug in dbt-core
• I have searched the existing issues, and I could not find an existing issue for this bug

Current Behavior

If you set a secret env var DBT_ENV_SECRET_x and try to log a dict (not related to the env var at all), you run into an error:

AttributeError: 'dict' object has no attribute 'replace'

Expected Behavior

No errors when logging dicts even with secret env vars.

Steps To Reproduce

1. Project setup.

# dbt_project.yml
name: my_dbt_project
profile: snowflake
config-version: 2
version: 1.0

models:
  my_dbt_project:
    +materialized: table

-- models/foo.sql

select 1 as id
{{ my_macro() }}

-- macros/my_macro.sql

{% macro my_macro() %}
    {% set val = {'foo': 1} %}
    {% do log(val, True) %}
{% endmacro %}

2. Make sure there are no secret dbt env vars set and do a run.

$ printenv | grep DBT_ENV_SECRET
$ dbt run
23:00:35  Running with dbt=1.3.2
23:00:35  {'foo': 1}
23:00:35  Found 1 model, 0 tests, 0 snapshots, 0 analyses, 304 macros, 0 operations, 0 seed files, 0 sources, 0 exposures, 0 metrics
23:00:35  
23:00:42  Concurrency: 8 threads (target='dev')
23:00:42  
23:00:42  1 of 1 START sql table model dbt_jyeo.foo ...................................... [RUN]
23:00:42  {'foo': 1}
23:00:46  1 of 1 OK created sql table model dbt_jyeo.foo ................................. [SUCCESS 1 in 3.93s]
23:00:46  
23:00:46  Finished running 1 table model in 0 hours 0 minutes and 10.45 seconds (10.45s).
23:00:46  
23:00:46  Completed successfully
23:00:46  
23:00:46  Done. PASS=1 WARN=0 ERROR=0 SKIP=0 TOTAL=1

3. Set an env var and then rerun.

$ export DBT_ENV_SECRET_FOO=topsecret
$ dbt run
23:01:26  Running with dbt=1.3.2
23:01:28  Encountered an error:
'dict' object has no attribute 'replace'
23:01:28  Traceback (most recent call last):
  File "/Users/jeremy/src/dbt-sandcastles/venv_dbt_latest/lib/python3.8/site-packages/dbt/main.py", line 135, in main
    results, succeeded = handle_and_check(args)
  File "/Users/jeremy/src/dbt-sandcastles/venv_dbt_latest/lib/python3.8/site-packages/dbt/main.py", line 198, in handle_and_check
    task, res = run_from_args(parsed)
  File "/Users/jeremy/src/dbt-sandcastles/venv_dbt_latest/lib/python3.8/site-packages/dbt/main.py", line 245, in run_from_args
    results = task.run()
  File "/Users/jeremy/src/dbt-sandcastles/venv_dbt_latest/lib/python3.8/site-packages/dbt/task/runnable.py", line 453, in run
    self._runtime_initialize()
  File "/Users/jeremy/src/dbt-sandcastles/venv_dbt_latest/lib/python3.8/site-packages/dbt/task/runnable.py", line 161, in _runtime_initialize
    super()._runtime_initialize()
  File "/Users/jeremy/src/dbt-sandcastles/venv_dbt_latest/lib/python3.8/site-packages/dbt/task/runnable.py", line 94, in _runtime_initialize
    self.load_manifest()
  File "/Users/jeremy/src/dbt-sandcastles/venv_dbt_latest/lib/python3.8/site-packages/dbt/task/runnable.py", line 81, in load_manifest
    self.manifest = ManifestLoader.get_full_manifest(self.config)
  File "/Users/jeremy/src/dbt-sandcastles/venv_dbt_latest/lib/python3.8/site-packages/dbt/parser/manifest.py", line 221, in get_full_manifest
    manifest = loader.load()
  File "/Users/jeremy/src/dbt-sandcastles/venv_dbt_latest/lib/python3.8/site-packages/dbt/parser/manifest.py", line 351, in load
    self.parse_project(
  File "/Users/jeremy/src/dbt-sandcastles/venv_dbt_latest/lib/python3.8/site-packages/dbt/parser/manifest.py", line 479, in parse_project
    parser.parse_file(block)
  File "/Users/jeremy/src/dbt-sandcastles/venv_dbt_latest/lib/python3.8/site-packages/dbt/parser/base.py", line 414, in parse_file
    self.parse_node(file_block)
  File "/Users/jeremy/src/dbt-sandcastles/venv_dbt_latest/lib/python3.8/site-packages/dbt/parser/base.py", line 388, in parse_node
    self.render_update(node, config)
  File "/Users/jeremy/src/dbt-sandcastles/venv_dbt_latest/lib/python3.8/site-packages/dbt/parser/models.py", line 337, in render_update
    super().render_update(node, config)
  File "/Users/jeremy/src/dbt-sandcastles/venv_dbt_latest/lib/python3.8/site-packages/dbt/parser/base.py", line 363, in render_update
    context = self.render_with_context(node, config)
  File "/Users/jeremy/src/dbt-sandcastles/venv_dbt_latest/lib/python3.8/site-packages/dbt/parser/base.py", line 242, in render_with_context
    get_rendered(parsed_node.raw_code, context, parsed_node, capture_macros=True)
  File "/Users/jeremy/src/dbt-sandcastles/venv_dbt_latest/lib/python3.8/site-packages/dbt/clients/jinja.py", line 587, in get_rendered
    return render_template(template, ctx, node)
  File "/Users/jeremy/src/dbt-sandcastles/venv_dbt_latest/lib/python3.8/site-packages/dbt/clients/jinja.py", line 542, in render_template
    return template.render(ctx)
  File "/Users/jeremy/src/dbt-sandcastles/venv_dbt_latest/lib/python3.8/site-packages/jinja2/environment.py", line 1301, in render
    self.environment.handle_exception()
  File "/Users/jeremy/src/dbt-sandcastles/venv_dbt_latest/lib/python3.8/site-packages/jinja2/environment.py", line 936, in handle_exception
    raise rewrite_traceback_stack(source=source)
  File "<template>", line 2, in top-level template code
  File "/Users/jeremy/src/dbt-sandcastles/venv_dbt_latest/lib/python3.8/site-packages/jinja2/sandbox.py", line 393, in call
    return __context.call(__obj, *args, **kwargs)
  File "/Users/jeremy/src/dbt-sandcastles/venv_dbt_latest/lib/python3.8/site-packages/dbt/clients/jinja.py", line 326, in __call__
    return self.call_macro(*args, **kwargs)
  File "/Users/jeremy/src/dbt-sandcastles/venv_dbt_latest/lib/python3.8/site-packages/dbt/clients/jinja.py", line 253, in call_macro
    return macro(*args, **kwargs)
  File "/Users/jeremy/src/dbt-sandcastles/venv_dbt_latest/lib/python3.8/site-packages/jinja2/runtime.py", line 777, in _invoke
    rv = self._func(*arguments)
  File "<template>", line 3, in template
  File "/Users/jeremy/src/dbt-sandcastles/venv_dbt_latest/lib/python3.8/site-packages/jinja2/sandbox.py", line 393, in call
    return __context.call(__obj, *args, **kwargs)
  File "/Users/jeremy/src/dbt-sandcastles/venv_dbt_latest/lib/python3.8/site-packages/dbt/context/base.py", line 560, in log
    fire_event(MacroEventInfo(msg=msg))
  File "/Users/jeremy/src/dbt-sandcastles/venv_dbt_latest/lib/python3.8/site-packages/dbt/events/functions.py", line 275, in fire_event
    log_line = create_log_line(e, file_output=True)
  File "/Users/jeremy/src/dbt-sandcastles/venv_dbt_latest/lib/python3.8/site-packages/dbt/events/functions.py", line 206, in create_log_line
    return create_debug_text_log_line(e)  # default file output
  File "/Users/jeremy/src/dbt-sandcastles/venv_dbt_latest/lib/python3.8/site-packages/dbt/events/functions.py", line 179, in create_debug_text_log_line
    scrubbed_msg: str = scrub_secrets(e.message(), env_secrets())
  File "/Users/jeremy/src/dbt-sandcastles/venv_dbt_latest/lib/python3.8/site-packages/dbt/events/functions.py", line 116, in scrub_secrets
    scrubbed = scrubbed.replace(secret, "*****")
AttributeError: 'dict' object has no attribute 'replace'

Relevant log output

See above.

Environment

- OS: macOS
- Python: 3.8
- dbt: 1.3.2

Which database adapter are you using with dbt?

snowflake

Additional Context

We should stringify scrubbed.

[jtcohen6]

This looks familiar: #5385

Was meant to be resolved by: #5874

[dbeatty10]

An idea to fix this

I didn't actually test this out, but I suspect that changing return self.msg to return str(self.msg) in both places here might fix this. Seeing e.message() here is what lead me to guess down this path.

An alternative might be changing msg=msg to msg=str(msg) here.

Or we could do both!

In the big-picture, there's very few def message(self) method defintions within core/dbt/events/types.py that aren't explicitly cast to a string. (I quickly read through all 220+ of them!) As part of this effort, we could ensure that all of them are explicitly cast to strings.

Functional testing

It looks like it would be pretty easy to convert @jeremyyeo's reproduction case into a functional test to prevent an accidental regression.

[lsabreu96]

Any updates on this ?
I'm believing I'm facing a similar issue in the same environment, but I'm using Ubuntu rather than macOs. The error is

Encountered an error while running operation: 'AttributeError' object has no attribute 'replace'

I was trying to perform a run-operation and this error popped up. I removed all the DBT_ENV vars and rerun and it worked just fine.

The original macro being called had a legacy logging step, which queried the database, fetched the values and then printed'em out. After removing the logging, the macro ran just fine.

[dbeatty10]

@lsabreu96 Glad you found a workaround!

We don't have any updates on when a fix for this will be released.

But I think there's a couple ways to solve it (neither of which I have actually tested):

1. here, change return self.msg to return str(self.msg) in both places
2. here, change msg=msg to msg=str(msg)

(We could do both.)

[jtcohen6]

here, change msg=msg to msg=str(msg)

This seems like the Correct approach to me, given the promised return type of this function:

dbt-core/core/dbt/context/base.py

Line 544 in 066346f

def log(msg: str, info: bool = False) -> str:

If users want the ability to log more structured data (not just a string), that's a different feature request:

• [CT-1906] Enable user-space code to fire typed events #6733

[gshank]

I ran into a related error in the protobuf branch and put a "str" cast around the "msg" in scrub_secrets. So that might have fixed this. In a more general sense, the "msg" in exceptions should probably always be a string...