How to - log model runs that include fetching some data about the previous time the model ran

[jeremyyeo]

Not too sure what to call these "how to do X with dbt" types of artifacts. Perhaps this requires it's own category or shouldn't be included in this repo's discussion.

The following playbook covers a really specific use case - logging model runs to an audit table that also:

1. Fetches data (a hash) related to the previous time the model ran.
2. Generates a new hash using the previous hash, a var that can be passed in at run time via the --vars flag, and the name of the model.

Note: there is the logging dbt package that covers many more things than this example as well as the surrogate_key function from the dbt_utils package that provides a hashing function.

---

1. Add the following macros to your project:

-- macros/logger.sql

{% macro create_audit_table() %}

  {%- do log('macro [create_audit_table]: Creating `dbt_meta__audit_log` table if not exists.', info=True) -%}

  create table if not exists {{ target.database }}.{{ target.schema }}.dbt_meta__audit_log (
      run_hash text not null,
      run_hash_previous text,
      salt text not null,
      model_name text not null,
      model_status text not null,
      updated_at timestamp not null
  );

{% endmacro %}

{% macro generate_hash(old_hash, new_salt, model_name) %}

    {% set full_string = [old_hash, new_salt, model_name] | join('') %}
    {% set output = '' %}

    {% set query -%}
        select md5('{{ full_string }}') as hash;
    {%- endset %}

    {% if execute %}
        {% set results = run_query(query) %}
        {% set output = results.columns[0].values()[0] %}
    {% endif %}

    {% do return(output) %}

{% endmacro %}

{% macro fetch_previous_hash(model_name) %}

    {% set output = '' %}
    
    {% set query -%}
        select run_hash 
          from {{ target.database }}.{{ target.schema }}.dbt_meta__audit_log
         where model_name = '{{ model_name }}'
       qualify row_number() over (partition by model_name order by updated_at desc) = 1;
    {%- endset %}

    {% if execute %}
        {% set results = run_query(query) %}
        {% set output = results.columns[0].values()[0] or '' %}
    {% endif %}

    {% if output == '' %}
        {% do log('macro [fetch_previous_hash]: no previous hash found - likely this model is running for the first time.', info=True) %}
    {% endif %}

    {% do return(output) %}

{% endmacro %}

{% macro log_to_audit_table(model_name, new_salt) %}

    {% if execute %}
        {% set prev_hash = fetch_previous_hash(model_name) %}
        {% set current_hash = generate_hash(prev_hash, new_salt, model_name) %}
    {% else %}
        {% set prev_hash = '' %}
        {% set current_hash = '' %}
    {% endif %}

    {% set query -%}
        insert into {{ target.database }}.{{ target.schema }}.dbt_meta__audit_log values (
            '{{ current_hash }}',
            '{{ prev_hash }}',
            '{{ new_salt }}',
            '{{ model_name }}',
            'completed',
            current_timestamp()
        );
    {%- endset %}

    {% if execute %}
        {% do run_query(query) %}
        {% do log('macro [log_to_audit_table]: model ' ~ model_name ~ ' logged to audit table.', info=True) %}
    {% endif %}

{% endmacro %}

2. Let's use those macros by adding the following to your dbt_project.yml file:

# dbt_project.yml
name: my_dbt_project

...

models:
  my_dbt_project:
    +materialized: table
    +post-hook: "{{ log_to_audit_table(this.name, var('salt')) }}"

on-run-start:
  - "{{ create_audit_table() }}"
  - "{{ log('Running with salt: ' ~ var('salt'), info=True) }}"

vars:
  salt: "abc"

The var salt here is nothing special, you can use any other name or even exclude it if you want. The use case here calls for passing in a "string" that gets used to generate the hash so we have named this salt.

The this object is a special object that represents the current model. Here we are extracting the "name" of the model instead of the whole representation of the model that includes the database and schema name. We then pass that "name" as an input value to the log_to_audit_table() macro. Feel free to experiment with logging out the value of this via a model post-hook like so: {{ log(this, True) }}.

3. Add some simple models to test that our macros are doing the right thing during the run:

-- models/my_model_a.sql
select 1 as user_id

-- models/my_model_b.sql
select 1 as user_id

5. Let's do a first run and see what happens:

Click to expand...

$ dbt run
23:56:27  Running with dbt=1.0.3
23:56:28  macro [create_audit_table]: Creating `dbt_meta__audit_log` table if not exists.
23:56:28  Running with salt: abc
23:56:28  Found 2 models, 0 tests, 0 snapshots, 0 analyses, 183 macros, 2 operations, 0 seed files, 0 sources, 0 exposures, 0 metrics
23:56:28  
23:56:33  
23:56:33  Running 2 on-run-start hooks
23:56:33  macro [create_audit_table]: Creating `dbt_meta__audit_log` table if not exists.
23:56:33  1 of 2 START hook: my_dbt_project.on-run-start.0................................ [RUN]
23:56:35  1 of 2 OK hook: my_dbt_project.on-run-start.0................................... [SUCCESS 1 in 1.77s]
23:56:35  Running with salt: abc
23:56:35  2 of 2 START hook: my_dbt_project.on-run-start.1................................ [RUN]
23:56:35  2 of 2 OK hook: my_dbt_project.on-run-start.1................................... [OK in 0.00s]
23:56:35  
23:56:36  Concurrency: 1 threads (target='dev')
23:56:36  
23:56:36  1 of 2 START table model dbt_jyeo.my_model_a.................................... [RUN]
23:56:39  macro [fetch_previous_hash]: no previous hash found - likely this model is running for the first time.
23:56:40  macro [log_to_audit_table]: model my_model_a logged to audit table.
23:56:40  1 of 2 OK created table model dbt_jyeo.my_model_a............................... [SUCCESS 1 in 4.74s]
23:56:40  2 of 2 START table model dbt_jyeo.my_model_b.................................... [RUN]
23:56:43  macro [fetch_previous_hash]: no previous hash found - likely this model is running for the first time.
23:56:44  macro [log_to_audit_table]: model my_model_b logged to audit table.
23:56:45  2 of 2 OK created table model dbt_jyeo.my_model_b............................... [SUCCESS 1 in 4.79s]
23:56:45  
23:56:45  Finished running 2 table models, 2 hooks in 17.45s.
23:56:45  
23:56:45  Completed successfully
23:56:45  
23:56:45  Done. PASS=2 WARN=0 ERROR=0 SKIP=0 TOTAL=2

And let's check our audit table in Snowflake:

6. Let's do another run with the same salt value:

Click to expand...

$ dbt run
00:00:10  Running with dbt=1.0.3
00:00:11  macro [create_audit_table]: Creating `dbt_meta__audit_log` table if not exists.
00:00:11  Running with salt: abc
00:00:11  Found 2 models, 0 tests, 0 snapshots, 0 analyses, 183 macros, 2 operations, 0 seed files, 0 sources, 0 exposures, 0 metrics
00:00:11  
00:00:17  
00:00:17  Running 2 on-run-start hooks
00:00:17  macro [create_audit_table]: Creating `dbt_meta__audit_log` table if not exists.
00:00:17  1 of 2 START hook: my_dbt_project.on-run-start.0................................ [RUN]
00:00:19  1 of 2 OK hook: my_dbt_project.on-run-start.0................................... [SUCCESS 1 in 2.07s]
00:00:19  Running with salt: abc
00:00:19  2 of 2 START hook: my_dbt_project.on-run-start.1................................ [RUN]
00:00:19  2 of 2 OK hook: my_dbt_project.on-run-start.1................................... [OK in 0.00s]
00:00:19  
00:00:20  Concurrency: 1 threads (target='dev')
00:00:20  
00:00:20  1 of 2 START table model dbt_jyeo.my_model_a.................................... [RUN]
00:00:24  macro [log_to_audit_table]: model my_model_a logged to audit table.
00:00:25  1 of 2 OK created table model dbt_jyeo.my_model_a............................... [SUCCESS 1 in 5.44s]
00:00:25  2 of 2 START table model dbt_jyeo.my_model_b.................................... [RUN]
00:00:29  macro [log_to_audit_table]: model my_model_b logged to audit table.
00:00:30  2 of 2 OK created table model dbt_jyeo.my_model_b............................... [SUCCESS 1 in 5.03s]
00:00:30  
00:00:30  Finished running 2 table models, 2 hooks in 19.09s.
00:00:30  
00:00:30  Completed successfully
00:00:30  
00:00:30  Done. PASS=2 WARN=0 ERROR=0 SKIP=0 TOTAL=2

And it looks like our audit table's run_hash_previous column is behaving as expected:

7. Now let's try a final run that changes the salt value at run time:

Click to expand...

$ dbt run --vars 'salt: def'
00:02:35  Running with dbt=1.0.3
00:02:36  macro [create_audit_table]: Creating `dbt_meta__audit_log` table if not exists.
00:02:36  Running with salt: def
00:02:36  Found 2 models, 0 tests, 0 snapshots, 0 analyses, 183 macros, 2 operations, 0 seed files, 0 sources, 0 exposures, 0 metrics
00:02:36  
00:02:42  
00:02:42  Running 2 on-run-start hooks
00:02:42  macro [create_audit_table]: Creating `dbt_meta__audit_log` table if not exists.
00:02:42  1 of 2 START hook: my_dbt_project.on-run-start.0................................ [RUN]
00:02:43  1 of 2 OK hook: my_dbt_project.on-run-start.0................................... [SUCCESS 1 in 1.72s]
00:02:43  Running with salt: def
00:02:43  2 of 2 START hook: my_dbt_project.on-run-start.1................................ [RUN]
00:02:43  2 of 2 OK hook: my_dbt_project.on-run-start.1................................... [OK in 0.00s]
00:02:43  
00:02:44  Concurrency: 1 threads (target='dev')
00:02:44  
00:02:44  1 of 2 START table model dbt_jyeo.my_model_a.................................... [RUN]
00:02:48  macro [log_to_audit_table]: model my_model_a logged to audit table.
00:02:49  1 of 2 OK created table model dbt_jyeo.my_model_a............................... [SUCCESS 1 in 4.78s]
00:02:49  2 of 2 START table model dbt_jyeo.my_model_b.................................... [RUN]
00:02:53  macro [log_to_audit_table]: model my_model_b logged to audit table.
00:02:54  2 of 2 OK created table model dbt_jyeo.my_model_b............................... [SUCCESS 1 in 5.01s]
00:02:54  
00:02:54  Finished running 2 table models, 2 hooks in 17.74s.
00:02:54  
00:02:54  Completed successfully
00:02:54  
00:02:54  Done. PASS=2 WARN=0 ERROR=0 SKIP=0 TOTAL=2

And check that the resulting audit table correctly records the new salt value:

[krevitt]

Couple questions!

1. Curious how you'd see this being used downstream?
2. Curious how this solves for a different use case than querying the models endpoint of the metadata API?

[jeremyyeo]

Hey @krevitt, I create another discussion to capture my thoughts #1268 since have been prompted twice about why these exist.

Curious how you'd see this being used downstream?

This is so we can link to an artefact that lives on a dbt Labs domain when we share these patterns with customers (CS perspective) or just anyone else in the community.

Curious how this solves for a different use case than querying the models endpoint of the metadata API?

I think it's a different use case completely since this one blends the knowledge of:

• how to use macros
• how to fetch data back from the database in a macro
• how to use run_query
• how to insert rows into a table using a macro

Querying the metadata API (and specifically that link) is more to answer "what information can I retrieve about the models that have been executed in a run" and it kind of stops there. It doesn't really touch the above "dbt concepts" at all I suppose.

Nor would someone be too excited if they had asked "give me a practical example of how I can query data from a database, hash that information, and write some new rows to a table" and we presented them with that link imho :)