Expose more structured logging capabilities to {{ log() }}

[jtcohen6]

Picking up from #4164 (comment). This is a fairly half-baked idea, and I'm definitely open to suggestions on how to structure/implement.

By my unscientific estimate, the most critical logging is:

• 70% in dbt-core
• 10% in dbt adapter plugins, i.e. for debugging connections
• 20% calls to the context macro {{ log() }}

Why so much in the last category? This could be logging from:

• materializations, built-in or custom
• other macros that wrap log()
• complex operations, e.g. those defined in packages
• any custom user-space code

Based on the implementation of structured logging that will be included in v1, these log messages will be passed along as relatively unstructured events, MacroEventInfo or MacroEventDebug, with just one string property, msg.

As structured logs become an increasingly important interface for interacting with / listening to dbt, we should seek to open up more capabilities to end users who want to hook into more powerful logging from the macro/materialization context. I could see us doing that by:

• Adding a new argument to the log() macro that enables users to pass along any key-value pairs they want, and a templated message (Jinja expression or f-string) using those keys/values
• Adding complementary information gleaned from the Jinja context—if it's even available!—e.g. the parent macro/frame calling this log() message

[nathaniel-may]

I love the idea of exposing some of this new functionality via our jinja interface. I do want to ask if some of the common use cases for {{ log() }} like materializations should just be implemented in core so they don't have to be written by users. For the remaining calls to {{ log() }} I like the direction you're heading by allowing users to construct messages at runtime with functions. I suspect this is possible today, but might look less graceful than it could. Is there any log functionality that is simply not possible today?

[jtcohen6]

The context available to users is the same as that available to dbt-core's built-in materializations today. It's a good callout, we could think about supporting other types of logging/event functions in the Jinja context, or optional arguments to {{ log() }} that would lead it to call (e.g.) a MaterializationEventInfo instead of MacroEventInfo.

From my vantage, I was thinking that the simplest way would be to add an argument to {{ log() }} along the lines of:

@dataclass
class MacroEventInfo(InfoLevel, CliEventABC):
    msg: str
    properties: dict

    def cli_msg(self) -> str:
        return self.msg

dict = {thing_a: x, thing_b: y}
message = "Could not do {{ thing_a }} because {{ thing_b }}"
{{ log(message, info = true, properties = dict) }}

To achieve the equivalent of:

class ThisSpecificCustomEvent(...):
  thing_a: str
  thing_b: str

def cli_msg(self) -> str:
  return(
    f"Could not {self.thing_a} because {self.thing_b}"
  )

And be able to use the additional structure of properties accordingly

[nathaniel-may]

Yeah I can see how that would work, and it seems consistent to use Jinja here as opposed to python f-string syntax for instance.

[jtcohen6]

Another version of this that we discussed, following the same pseudo-code above:

{% set thing_a = ... %}
{% set thing_b = ... %}
{{ fire_event(event_type='MyCoolEvent', thing_a=thing_a, thing_b=thing_b }}

Wherein fire_event() is a Jinja macro / context member that, in turn, calls fire_event(EventType(**kwargs)).

That could be especially useful for events that are (a) consistent, frequent, expected, and (b) firmly in Jinja-land. Materializations are the prime example.

[dataders]

as someone who spends way too much time debugging jinja, I'd like to "yes, and..." this idea by saying it'd be great to have to log message return:

• a timestamp of the same format as the rest of the logs,
• the callstack of jinja macros from where it's called (a la Delgan/loguru), and
• a shorthand way to print the name of var in addition to it's value? akin to the fstring impl mentioned in new jinja function: log var #3911

[github-actions]

This issue has been marked as Stale because it has been open for 180 days with no activity. If you would like the issue to remain open, please remove the stale label or comment on the issue, or it will be closed in 7 days.

[nathaniel-may]

Closing in favor of #5325. Since this is going to be a part of that effort.