Skip to content
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-756] Stringify user-provided messages to {{ log() }} #5385

Closed
jtcohen6 opened this issue Jun 16, 2022 · 2 comments · Fixed by #5874 · May be fixed by DavidMah/dbt-core#1
Closed

[CT-756] Stringify user-provided messages to {{ log() }} #5385

jtcohen6 opened this issue Jun 16, 2022 · 2 comments · Fixed by #5874 · May be fixed by DavidMah/dbt-core#1
Labels
bug Something isn't working logging

Comments

@jtcohen6
Copy link
Contributor

jtcohen6 commented Jun 16, 2022

Reproduction case

-- models/any_model.sql

{% set some_list = ['a', 'b', 'c'] %}

{{ log(some_list, info = true) }}

select 1 as id
$ DBT_ENV_SECRET_WHATEVER=1234 dbt run
12:12:30  Running with dbt=1.2.0-a1
12:12:30  Encountered an error:
'list' object has no attribute 'replace'

I'm not even using the secret, but because I've defined one, dbt is searching log messages to scrub out any instances of the secret value. This error is not related to the recent change re: secret rendering. It's just related to how we're scrubbing secrets from log messages in general, and have been since v1.0.0:

def scrub_secrets(msg: str, secrets: List[str]) -> str:
scrubbed = msg
for secret in secrets:
scrubbed = scrubbed.replace(secret, "*****")
return scrubbed

When a user passes a non-string object into {{ log() }}, we end up passing that object straight through to scrub_secrets. Which expects to be receiving a string!

The type signature of log actually expects to be receiving a string, too:

@contextmember
@staticmethod
def log(msg: str, info: bool = False) -> str:
"""Logs a line to either the log file or stdout.
:param msg: The message to log
:param info: If `False`, write to the log file. If `True`, write to
both the log file and stdout.
> macros/my_log_macro.sql
{% macro some_macro(arg1, arg2) %}
{{ log("Running some_macro: " ~ arg1 ~ ", " ~ arg2) }}
{% endmacro %}"
"""
if info:
fire_event(MacroEventInfo(msg=msg))
else:
fire_event(MacroEventDebug(msg=msg))
return ""

Resolution

We could put this logic anywhere, but it feels like the simplest and most appropriate fix may well be to stringify whatever users are passing into log, before firing it:

    def log(msg: str, info: bool = False) -> str:
        ...
        # user-provided msg should be a string
        msg = str(msg)
        if info:
            fire_event(MacroEventInfo(msg=msg))
        else:
            fire_event(MacroEventDebug(msg=msg))
        return ""

This successfully handles some pretty weird edge cases:

{{ log(this, info = true) }}
{{ log(create_table_as, info = true) }}
{{ log(context, info = true) }}
12:11:26  "jerco"."dbt_jcohen"."model_a"
12:11:26  <dbt.clients.jinja.MacroGenerator object at 0x10dca87f0>
... giant context blob ...

Still, we should make sure it raises a useful error, in case users try passing in objects that aren't string serializable. (I can't think of an example right now, but maybe there is one?)

@jtcohen6 jtcohen6 added bug Something isn't working Team:Language logging labels Jun 16, 2022
@github-actions github-actions bot changed the title Stringify user-provided messages to {{ log() }} [CT-756] Stringify user-provided messages to {{ log() }} Jun 16, 2022
@leahwicz
Copy link
Contributor

@VersusFacit does this seem related to the ticket you just closed out? Should we solve this further down the stack?
#5436
#5874

@VersusFacit
Copy link
Contributor

Solution provided in this PR

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working logging
Projects
None yet
3 participants