User seeing initial wh var being used rather than incremental var when running incremental model

[crystalro0]

hey all, I have a user running into an issue while using snowflake_utils 0.5.0 (w/3 declared vars in dbt_project) and an incremental model.

  snowflake_utils:initial_run_warehouse: "transforming_m_wh"
  snowflake_utils:full_refresh_run_warehouse: "transforming_xl_wh"
  snowflake_utils:incremental_run_warehouse: "TRANSFORMING"

If the model already exists, the logging shows the following:

21:49:12  21:49:12 + Incremental Run - Using alternative warehouse TRANSFORMING     **<-- correct warehouse for incremental run but no refresh**
21:49:12  Writing injected SQL for node "model.jaffle_shop.views_incremental"
21:49:13  Timing info for model.jaffle_shop.views_incremental (compile): 2023-08-21 21:49:12.976129 => 2023-08-21 21:49:13.004013
21:49:13  Began executing node model.jaffle_shop.views_incremental
21:49:13  Using snowflake connection "model.jaffle_shop.views_incremental"
21:49:13  On model.jaffle_shop.views_incremental: /* {"app": "dbt", "dbt_version": "1.4.7", "profile_name": "user", "target_name": "default", "node_id": "model.jaffle_shop.views_incremental"} */
select current_warehouse() as warehouse
21:49:13  Opening a new connection, currently in state closed
21:49:13  SQL status: SUCCESS 1 in 1 seconds
21:49:13  Using snowflake connection "model.jaffle_shop.views_incremental"
21:49:13  On model.jaffle_shop.views_incremental: /* {"app": "dbt", "dbt_version": "1.4.7", "profile_name": "user", "target_name": "default", "node_id": "model.jaffle_shop.views_incremental"} */
use warehouse transforming_m_wh        **<---- set as the initial run warehouse**

it looks like it's going to set the correct TRANSFORMING warehouse but it goes with the initial warehouse var and errors out.

Tested on:

• dbt Cloud 1.5 and 1.6
• snowflake_utils 0.5.0

[ljanda-amplify]

I just wanted to note that I had multiple people do the package implementation and see the same issue I was having. When I build in dbt, the log gives the expected warehouse but when I check in snowflake, the wrong warehouse is being used. However, the macro looks straightforward and I'm curious if this is actually due to a dbt bug rather than an issue with this package.

[jeremyyeo]

Hey folks - just wanted to clarify that dbt itself has never supported such behaviour - i.e.

Detect the existence of the relation prior to setting a model config (like snowflake_warehouse)

Feel free to read relevant issues here: https://github.com/dbt-labs/dbt-core/issues/7868 and here: https://github.com/dbt-labs/dbt-snowflake/issues/103

The problem is that dbt has to set the model config - prior to even touching the datawarehouse to determnine the existence of a table. I can illustrate simply.

I have created 3 different warehouses with names that resemble the intended type - i.e. wh_intial, wh_incremental, wh_fullrefresh.

Modify the macro that comes from this package:

-- dbt_packages/snowflake_utils/macros/warehouse_size.sql
{% macro warehouse_size() %}

    {% set initial_wh = var('snowflake_utils:initial_run_warehouse', none) %}
    {% set full_wh = var('snowflake_utils:full_refresh_run_warehouse', none) %}
    {% set inc_wh = var('snowflake_utils:incremental_run_warehouse', none) %}

    {% set relation = adapter.get_relation(this.database, this.schema, this.table) %}
    {% do log("--------------------------------------------", True) %}
    {% do log(relation, True) %}
    {% do log("--------------------------------------------", True) %}

    {#-- use alternative warehouse if full-refresh run #}
    {# if relation is not none and flags.FULL_REFRESH and full_wh is not none #}
    {% if flags.FULL_REFRESH and full_wh is not none %}
        {% if execute %}
            {{ dbt_utils.log_info("Full Refresh Run - Using alternative warehouse " ~ full_wh | upper) }}
        {% endif %}
        {% do return(full_wh) %}

    {#-- use alternative warehouse if incremental run #}
    {% elif relation is not none and flags.FULL_REFRESH == False and inc_wh is not none %}
        {% if execute %}
            {{ dbt_utils.log_info("Incremental Run - Using alternative warehouse " ~ inc_wh | upper) }}
        {% endif %}
        {% do return(inc_wh) %}

    {#-- use alternative warehouse if initial run #}
    {% elif relation is none and initial_wh is not none %}
        {% if execute %} 
            {{ dbt_utils.log_info("Initial Run - Using alternative warehouse " ~ initial_wh | upper) }}
        {% endif %}
        {% do return(initial_wh) %}

    {#-- use target warehouse if variable not configured for a condition #}
    {% else %}
        {{ dbt_utils.log_info("Using target warehouse " ~ target.warehouse | upper) }}
        {% do return(target.warehouse) %}

    {% endif %}

{% endmacro %}

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

models:
  my_dbt_project:
    +materialized: table
    +query_tag: "{{ invocation_id }}"

# The default snowflake warehouse i.e. target.warehouse is 'analytics'

vars:
  "snowflake_utils:initial_run_warehouse": "wh_initial"
  "snowflake_utils:incremental_run_warehouse": "wh_incremental"
  "snowflake_utils:full_refresh_run_warehouse": "wh_fullrefresh"

-- models/my_inc.sql
{{
    config(
        materialized = "incremental",
        snowflake_warehouse = snowflake_utils.warehouse_size()
    )
}}

/* {{ invocation_id }} */
select 1 id

First let's delete the incremental model so that it doesn't exist:

Let's do our first run:

$ dbt --debug run -s my_inc

============================== 2023-09-27 01:08:30.230650 | 3120452f-2d89-4797-8cd7-3e70d8bc95cb ==============================
01:08:30.230650 [info ] [MainThread]: Running with dbt=1.4.7
01:08:30.234895 [debug] [MainThread]: running dbt with arguments {'debug': True, 'write_json': True, 'use_colors': True, 'printer_width': 80, 'version_check': True, 'partial_parse': False, 'static_parser': True, 'profiles_dir': '/Users/jeremy/.dbt', 'send_anonymous_usage_stats': True, 'quiet': False, 'no_print': False, 'cache_selected_only': False, 'select': ['my_inc'], 'which': 'run', 'rpc_method': 'run', 'indirect_selection': 'eager'}
01:08:30.235581 [debug] [MainThread]: Tracking: tracking
01:08:30.236721 [debug] [MainThread]: Sending event: {'category': 'dbt', 'action': 'invocation', 'label': 'start', 'context': [<snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x11defa100>, <snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x11defadf0>, <snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x11defad00>]}
01:08:30.301385 [debug] [MainThread]: checksum: f4f4cdde9b257b3a8e3791263c44f34b0bd0facc33ef1ba84a563bd63785ce73, vars: {}, profile: None, target: None, version: 1.4.7
01:08:30.303503 [debug] [MainThread]: Partial parsing not enabled
01:08:32.113136 [debug] [MainThread]: 1603: static parser failed on my_inc.sql
01:08:32.129938 [info ] [MainThread]: --------------------------------------------
01:08:32.130781 [info ] [MainThread]: None
01:08:32.131231 [info ] [MainThread]: --------------------------------------------
01:08:32.145543 [debug] [MainThread]: 1602: parser fallback to jinja rendering on my_inc.sql
01:08:32.148513 [debug] [MainThread]: 1603: static parser failed on foo.sql
01:08:32.155109 [debug] [MainThread]: 1602: parser fallback to jinja rendering on foo.sql
01:08:32.158015 [debug] [MainThread]: 1603: static parser failed on my_inc_b.sql
01:08:32.163338 [info ] [MainThread]: --------------------------------------------
01:08:32.164088 [info ] [MainThread]: None
01:08:32.164701 [info ] [MainThread]: --------------------------------------------
01:08:32.167961 [debug] [MainThread]: 1602: parser fallback to jinja rendering on my_inc_b.sql
01:08:32.257965 [debug] [MainThread]: Sending event: {'category': 'dbt', 'action': 'load_project', 'label': '3120452f-2d89-4797-8cd7-3e70d8bc95cb', 'context': [<snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x11e0e45e0>]}
01:08:32.268349 [debug] [MainThread]: Sending event: {'category': 'dbt', 'action': 'resource_counts', 'label': '3120452f-2d89-4797-8cd7-3e70d8bc95cb', 'context': [<snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x11dff4d30>]}
01:08:32.269248 [info ] [MainThread]: Found 3 models, 0 tests, 0 snapshots, 0 analyses, 429 macros, 0 operations, 0 seed files, 0 sources, 0 exposures, 0 metrics
01:08:32.269858 [debug] [MainThread]: Sending event: {'category': 'dbt', 'action': 'runnable_timing', 'label': '3120452f-2d89-4797-8cd7-3e70d8bc95cb', 'context': [<snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x11dfffca0>]}
01:08:32.272476 [info ] [MainThread]: 
01:08:32.273702 [debug] [MainThread]: Acquiring new snowflake connection 'master'
01:08:32.275337 [debug] [ThreadPool]: Acquiring new snowflake connection 'list_development'
01:08:32.298494 [debug] [ThreadPool]: Using snowflake connection "list_development"
01:08:32.299298 [debug] [ThreadPool]: On list_development: /* {"app": "dbt", "dbt_version": "1.4.7", "profile_name": "all", "target_name": "sf", "connection_name": "list_development"} */
show terse schemas in database development
    limit 10000
01:08:32.299852 [debug] [ThreadPool]: Opening a new connection, currently in state init
01:08:34.716089 [debug] [ThreadPool]: SQL status: SUCCESS 294 in 2 seconds
01:08:34.729384 [debug] [ThreadPool]: On list_development: Close
01:08:35.323272 [debug] [ThreadPool]: Acquiring new snowflake connection 'list_development_dbt_jyeo'
01:08:35.335590 [debug] [ThreadPool]: Using snowflake connection "list_development_dbt_jyeo"
01:08:35.336415 [debug] [ThreadPool]: On list_development_dbt_jyeo: /* {"app": "dbt", "dbt_version": "1.4.7", "profile_name": "all", "target_name": "sf", "connection_name": "list_development_dbt_jyeo"} */
show terse objects in development.dbt_jyeo
01:08:35.337120 [debug] [ThreadPool]: Opening a new connection, currently in state closed
01:08:37.188054 [debug] [ThreadPool]: SQL status: SUCCESS 33 in 2 seconds
01:08:37.194920 [debug] [ThreadPool]: On list_development_dbt_jyeo: Close
01:08:37.830846 [debug] [MainThread]: Sending event: {'category': 'dbt', 'action': 'runnable_timing', 'label': '3120452f-2d89-4797-8cd7-3e70d8bc95cb', 'context': [<snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x11deeffd0>]}
01:08:37.832870 [info ] [MainThread]: Concurrency: 1 threads (target='sf')
01:08:37.833749 [info ] [MainThread]: 
01:08:37.843046 [debug] [Thread-1  ]: Began running node model.my_dbt_project.my_inc
01:08:37.844422 [info ] [Thread-1  ]: 1 of 1 START sql incremental model dbt_jyeo.my_inc ............................. [RUN]
01:08:37.845740 [debug] [Thread-1  ]: Acquiring new snowflake connection 'model.my_dbt_project.my_inc'
01:08:37.846506 [debug] [Thread-1  ]: Began compiling node model.my_dbt_project.my_inc
01:08:37.854740 [info ] [Thread-1  ]: --------------------------------------------
01:08:37.855617 [info ] [Thread-1  ]: None
01:08:37.856326 [info ] [Thread-1  ]: --------------------------------------------
01:08:37.871553 [info ] [Thread-1  ]: 14:08:37 + Initial Run - Using alternative warehouse WH_INITIAL
01:08:37.872508 [debug] [Thread-1  ]: Writing injected SQL for node "model.my_dbt_project.my_inc"
01:08:37.874446 [debug] [Thread-1  ]: Timing info for model.my_dbt_project.my_inc (compile): 2023-09-27 01:08:37.847129 => 2023-09-27 01:08:37.874318
01:08:37.875188 [debug] [Thread-1  ]: Began executing node model.my_dbt_project.my_inc
01:08:37.877964 [debug] [Thread-1  ]: Using snowflake connection "model.my_dbt_project.my_inc"
01:08:37.878609 [debug] [Thread-1  ]: On model.my_dbt_project.my_inc: /* {"app": "dbt", "dbt_version": "1.4.7", "profile_name": "all", "target_name": "sf", "node_id": "model.my_dbt_project.my_inc"} */
select current_warehouse() as warehouse
01:08:37.879108 [debug] [Thread-1  ]: Opening a new connection, currently in state closed
01:08:39.668617 [debug] [Thread-1  ]: SQL status: SUCCESS 1 in 2 seconds
01:08:39.686045 [debug] [Thread-1  ]: Using snowflake connection "model.my_dbt_project.my_inc"
01:08:39.686953 [debug] [Thread-1  ]: On model.my_dbt_project.my_inc: /* {"app": "dbt", "dbt_version": "1.4.7", "profile_name": "all", "target_name": "sf", "node_id": "model.my_dbt_project.my_inc"} */
use warehouse wh_initial
01:08:40.011748 [debug] [Thread-1  ]: SQL status: SUCCESS 1 in 0 seconds
01:08:40.056684 [debug] [Thread-1  ]: Using snowflake connection "model.my_dbt_project.my_inc"
01:08:40.057297 [debug] [Thread-1  ]: On model.my_dbt_project.my_inc: /* {"app": "dbt", "dbt_version": "1.4.7", "profile_name": "all", "target_name": "sf", "node_id": "model.my_dbt_project.my_inc"} */
show parameters like 'query_tag' in session
01:08:40.431236 [debug] [Thread-1  ]: SQL status: SUCCESS 1 in 0 seconds
01:08:40.433219 [debug] [Thread-1  ]: Setting query_tag to '3120452f-2d89-4797-8cd7-3e70d8bc95cb'. Will reset to '' after materialization.
01:08:40.434271 [debug] [Thread-1  ]: Using snowflake connection "model.my_dbt_project.my_inc"
01:08:40.434784 [debug] [Thread-1  ]: On model.my_dbt_project.my_inc: /* {"app": "dbt", "dbt_version": "1.4.7", "profile_name": "all", "target_name": "sf", "node_id": "model.my_dbt_project.my_inc"} */
alter session set query_tag = '3120452f-2d89-4797-8cd7-3e70d8bc95cb'
01:08:40.762479 [debug] [Thread-1  ]: SQL status: SUCCESS 1 in 0 seconds
01:08:40.813883 [debug] [Thread-1  ]: Writing runtime sql for node "model.my_dbt_project.my_inc"
01:08:40.815754 [debug] [Thread-1  ]: Using snowflake connection "model.my_dbt_project.my_inc"
01:08:40.816402 [debug] [Thread-1  ]: On model.my_dbt_project.my_inc: /* {"app": "dbt", "dbt_version": "1.4.7", "profile_name": "all", "target_name": "sf", "node_id": "model.my_dbt_project.my_inc"} */
create or replace transient table development.dbt_jyeo.my_inc  as
        (

/* 3120452f-2d89-4797-8cd7-3e70d8bc95cb */
select 1 id
        );
01:08:42.433106 [debug] [Thread-1  ]: SQL status: SUCCESS 1 in 2 seconds
01:08:42.450984 [debug] [Thread-1  ]: Using snowflake connection "model.my_dbt_project.my_inc"
01:08:42.451786 [debug] [Thread-1  ]: On model.my_dbt_project.my_inc: /* {"app": "dbt", "dbt_version": "1.4.7", "profile_name": "all", "target_name": "sf", "node_id": "model.my_dbt_project.my_inc"} */
drop view if exists development.dbt_jyeo.my_inc__dbt_tmp cascade
01:08:42.877673 [debug] [Thread-1  ]: SQL status: SUCCESS 1 in 0 seconds
01:08:42.915554 [debug] [Thread-1  ]: No original query_tag, unsetting parameter.
01:08:42.917145 [debug] [Thread-1  ]: Using snowflake connection "model.my_dbt_project.my_inc"
01:08:42.918077 [debug] [Thread-1  ]: On model.my_dbt_project.my_inc: /* {"app": "dbt", "dbt_version": "1.4.7", "profile_name": "all", "target_name": "sf", "node_id": "model.my_dbt_project.my_inc"} */
alter session unset query_tag
01:08:43.225724 [debug] [Thread-1  ]: SQL status: SUCCESS 1 in 0 seconds
01:08:43.228577 [debug] [Thread-1  ]: Using snowflake connection "model.my_dbt_project.my_inc"
01:08:43.229217 [debug] [Thread-1  ]: On model.my_dbt_project.my_inc: /* {"app": "dbt", "dbt_version": "1.4.7", "profile_name": "all", "target_name": "sf", "node_id": "model.my_dbt_project.my_inc"} */
use warehouse ANALYTICS
01:08:43.562021 [debug] [Thread-1  ]: SQL status: SUCCESS 1 in 0 seconds
01:08:43.565530 [debug] [Thread-1  ]: Timing info for model.my_dbt_project.my_inc (execute): 2023-09-27 01:08:37.875604 => 2023-09-27 01:08:43.565388
01:08:43.566718 [debug] [Thread-1  ]: On model.my_dbt_project.my_inc: Close
01:08:44.157249 [debug] [Thread-1  ]: Sending event: {'category': 'dbt', 'action': 'run_model', 'label': '3120452f-2d89-4797-8cd7-3e70d8bc95cb', 'context': [<snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x121fc9130>]}
01:08:44.159139 [info ] [Thread-1  ]: 1 of 1 OK created sql incremental model dbt_jyeo.my_inc ........................ [SUCCESS 1 in 6.31s]
01:08:44.162546 [debug] [Thread-1  ]: Finished running node model.my_dbt_project.my_inc
01:08:44.165893 [debug] [MainThread]: Acquiring new snowflake connection 'master'
01:08:44.167293 [debug] [MainThread]: Connection 'master' was properly closed.
01:08:44.168027 [debug] [MainThread]: Connection 'model.my_dbt_project.my_inc' was properly closed.
01:08:44.168750 [info ] [MainThread]: 
01:08:44.169521 [info ] [MainThread]: Finished running 1 incremental model in 0 hours 0 minutes and 11.90 seconds (11.90s).
01:08:44.170380 [debug] [MainThread]: Command end result
01:08:44.184477 [info ] [MainThread]: 
01:08:44.185244 [info ] [MainThread]: Completed successfully
01:08:44.185802 [info ] [MainThread]: 
01:08:44.186317 [info ] [MainThread]: Done. PASS=1 WARN=0 ERROR=0 SKIP=0 TOTAL=1
01:08:44.187056 [debug] [MainThread]: Sending event: {'category': 'dbt', 'action': 'invocation', 'label': 'end', 'context': [<snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x121fc6bb0>, <snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x121fc66d0>, <snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x121fc6610>]}
01:08:44.187991 [debug] [MainThread]: Flushing usage events

^ Worth calling out now, there's 3 times the log I added was None:

PARSING 

01:08:32.113136 [debug] [MainThread]: 1603: static parser failed on my_inc.sql
01:08:32.129938 [info ] [MainThread]: --------------------------------------------
01:08:32.130781 [info ] [MainThread]: None
01:08:32.131231 [info ] [MainThread]: --------------------------------------------
01:08:32.145543 [debug] [MainThread]: 1602: parser fallback to jinja rendering on my_inc.sql
01:08:32.148513 [debug] [MainThread]: 1603: static parser failed on foo.sql
01:08:32.155109 [debug] [MainThread]: 1602: parser fallback to jinja rendering on foo.sql
01:08:32.158015 [debug] [MainThread]: 1603: static parser failed on my_inc_b.sql
01:08:32.163338 [info ] [MainThread]: --------------------------------------------
01:08:32.164088 [info ] [MainThread]: None
01:08:32.164701 [info ] [MainThread]: --------------------------------------------
01:08:32.167961 [debug] [MainThread]: 1602: parser fallback to jinja rendering on my_inc_b.sql
01:08:32.257965 [debug] [MainThread]: Sending event: {'category': 'dbt', 'action': 'load_project', 'label': '3120452f-2d89-4797-8cd7-3e70d8bc95cb', 'context': [<snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x11e0e45e0>]}
01:08:32.268349 [debug] [MainThread]: Sending event: {'category': 'dbt', 'action': 'resource_counts', 'label': '3120452f-2d89-4797-8cd7-3e70d8bc95cb', 'context': [<snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x11dff4d30>]}
01:08:32.269248 [info ] [MainThread]: Found 3 models, 0 tests, 0 snapshots, 0 analyses, 429 macros, 0 operations, 0 seed files, 0 sources, 0 exposures, 0 metrics

==== Editors Note ====
The config `snowflake_warehouse` is already set at this stage.
==================

COMPILE

01:08:37.845740 [debug] [Thread-1  ]: Acquiring new snowflake connection 'model.my_dbt_project.my_inc'
01:08:37.846506 [debug] [Thread-1  ]: Began compiling node model.my_dbt_project.my_inc
01:08:37.854740 [info ] [Thread-1  ]: --------------------------------------------
01:08:37.855617 [info ] [Thread-1  ]: None
01:08:37.856326 [info ] [Thread-1  ]: --------------------------------------------
01:08:37.871553 [info ] [Thread-1  ]: 14:08:37 + Initial Run - Using alternative warehouse WH_INITIAL

Now, that the model exist, let's rerun and hopefully the warehouse used now is wh_incremental:

$ dbt --debug run -s my_inc

============================== 2023-09-27 01:12:45.117491 | dd0b8062-4457-44f3-a7e2-fc6e90fcfbd6 ==============================
01:12:45.117491 [info ] [MainThread]: Running with dbt=1.4.7
01:12:45.120453 [debug] [MainThread]: running dbt with arguments {'debug': True, 'write_json': True, 'use_colors': True, 'printer_width': 80, 'version_check': True, 'partial_parse': False, 'static_parser': True, 'profiles_dir': '/Users/jeremy/.dbt', 'send_anonymous_usage_stats': True, 'quiet': False, 'no_print': False, 'cache_selected_only': False, 'select': ['my_inc'], 'which': 'run', 'rpc_method': 'run', 'indirect_selection': 'eager'}
01:12:45.120992 [debug] [MainThread]: Tracking: tracking
01:12:45.121779 [debug] [MainThread]: Sending event: {'category': 'dbt', 'action': 'invocation', 'label': 'start', 'context': [<snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x11c07c100>, <snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x11c07cdf0>, <snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x11c07cd00>]}
01:12:45.163362 [debug] [MainThread]: checksum: f4f4cdde9b257b3a8e3791263c44f34b0bd0facc33ef1ba84a563bd63785ce73, vars: {}, profile: None, target: None, version: 1.4.7
01:12:45.164685 [debug] [MainThread]: Partial parsing not enabled
01:12:46.453770 [debug] [MainThread]: 1603: static parser failed on my_inc.sql
01:12:46.479638 [info ] [MainThread]: --------------------------------------------
01:12:46.480701 [info ] [MainThread]: None
01:12:46.481316 [info ] [MainThread]: --------------------------------------------
01:12:46.497353 [debug] [MainThread]: 1602: parser fallback to jinja rendering on my_inc.sql
01:12:46.500119 [debug] [MainThread]: 1603: static parser failed on foo.sql
01:12:46.507270 [debug] [MainThread]: 1602: parser fallback to jinja rendering on foo.sql
01:12:46.509413 [debug] [MainThread]: 1603: static parser failed on my_inc_b.sql
01:12:46.513487 [info ] [MainThread]: --------------------------------------------
01:12:46.514146 [info ] [MainThread]: None
01:12:46.514711 [info ] [MainThread]: --------------------------------------------
01:12:46.517995 [debug] [MainThread]: 1602: parser fallback to jinja rendering on my_inc_b.sql
01:12:46.604247 [debug] [MainThread]: Sending event: {'category': 'dbt', 'action': 'load_project', 'label': 'dd0b8062-4457-44f3-a7e2-fc6e90fcfbd6', 'context': [<snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x11c2633d0>]}
01:12:46.614687 [debug] [MainThread]: Sending event: {'category': 'dbt', 'action': 'resource_counts', 'label': 'dd0b8062-4457-44f3-a7e2-fc6e90fcfbd6', 'context': [<snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x11c1bd850>]}
01:12:46.615591 [info ] [MainThread]: Found 3 models, 0 tests, 0 snapshots, 0 analyses, 429 macros, 0 operations, 0 seed files, 0 sources, 0 exposures, 0 metrics
01:12:46.616212 [debug] [MainThread]: Sending event: {'category': 'dbt', 'action': 'runnable_timing', 'label': 'dd0b8062-4457-44f3-a7e2-fc6e90fcfbd6', 'context': [<snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x11c138700>]}
01:12:46.618274 [info ] [MainThread]: 
01:12:46.619436 [debug] [MainThread]: Acquiring new snowflake connection 'master'
01:12:46.620829 [debug] [ThreadPool]: Acquiring new snowflake connection 'list_development'
01:12:46.643108 [debug] [ThreadPool]: Using snowflake connection "list_development"
01:12:46.644020 [debug] [ThreadPool]: On list_development: /* {"app": "dbt", "dbt_version": "1.4.7", "profile_name": "all", "target_name": "sf", "connection_name": "list_development"} */
show terse schemas in database development
    limit 10000
01:12:46.644576 [debug] [ThreadPool]: Opening a new connection, currently in state init
01:12:49.128260 [debug] [ThreadPool]: SQL status: SUCCESS 294 in 2 seconds
01:12:49.144625 [debug] [ThreadPool]: On list_development: Close
01:12:49.761564 [debug] [ThreadPool]: Acquiring new snowflake connection 'list_development_dbt_jyeo'
01:12:49.776056 [debug] [ThreadPool]: Using snowflake connection "list_development_dbt_jyeo"
01:12:49.776863 [debug] [ThreadPool]: On list_development_dbt_jyeo: /* {"app": "dbt", "dbt_version": "1.4.7", "profile_name": "all", "target_name": "sf", "connection_name": "list_development_dbt_jyeo"} */
show terse objects in development.dbt_jyeo
01:12:49.777483 [debug] [ThreadPool]: Opening a new connection, currently in state closed
01:12:51.543447 [debug] [ThreadPool]: SQL status: SUCCESS 34 in 2 seconds
01:12:51.550314 [debug] [ThreadPool]: On list_development_dbt_jyeo: Close
01:12:52.265249 [debug] [MainThread]: Sending event: {'category': 'dbt', 'action': 'runnable_timing', 'label': 'dd0b8062-4457-44f3-a7e2-fc6e90fcfbd6', 'context': [<snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x11c098d90>]}
01:12:52.267239 [info ] [MainThread]: Concurrency: 1 threads (target='sf')
01:12:52.268105 [info ] [MainThread]: 
01:12:52.277840 [debug] [Thread-1  ]: Began running node model.my_dbt_project.my_inc
01:12:52.279179 [info ] [Thread-1  ]: 1 of 1 START sql incremental model dbt_jyeo.my_inc ............................. [RUN]
01:12:52.280842 [debug] [Thread-1  ]: Acquiring new snowflake connection 'model.my_dbt_project.my_inc'
01:12:52.281834 [debug] [Thread-1  ]: Began compiling node model.my_dbt_project.my_inc
01:12:52.290794 [info ] [Thread-1  ]: --------------------------------------------
01:12:52.291567 [info ] [Thread-1  ]: "DEVELOPMENT"."DBT_JYEO"."MY_INC"
01:12:52.292081 [info ] [Thread-1  ]: --------------------------------------------
01:12:52.307505 [info ] [Thread-1  ]: 14:12:52 + Incremental Run - Using alternative warehouse WH_INCREMENTAL
01:12:52.308147 [debug] [Thread-1  ]: Writing injected SQL for node "model.my_dbt_project.my_inc"
01:12:52.308938 [debug] [Thread-1  ]: Timing info for model.my_dbt_project.my_inc (compile): 2023-09-27 01:12:52.282545 => 2023-09-27 01:12:52.308857
01:12:52.309474 [debug] [Thread-1  ]: Began executing node model.my_dbt_project.my_inc
01:12:52.312226 [debug] [Thread-1  ]: Using snowflake connection "model.my_dbt_project.my_inc"
01:12:52.312967 [debug] [Thread-1  ]: On model.my_dbt_project.my_inc: /* {"app": "dbt", "dbt_version": "1.4.7", "profile_name": "all", "target_name": "sf", "node_id": "model.my_dbt_project.my_inc"} */
select current_warehouse() as warehouse
01:12:52.313784 [debug] [Thread-1  ]: Opening a new connection, currently in state closed
01:12:53.913057 [debug] [Thread-1  ]: SQL status: SUCCESS 1 in 2 seconds
01:12:53.933325 [debug] [Thread-1  ]: Using snowflake connection "model.my_dbt_project.my_inc"
01:12:53.934395 [debug] [Thread-1  ]: On model.my_dbt_project.my_inc: /* {"app": "dbt", "dbt_version": "1.4.7", "profile_name": "all", "target_name": "sf", "node_id": "model.my_dbt_project.my_inc"} */
use warehouse wh_initial
01:12:54.258513 [debug] [Thread-1  ]: SQL status: SUCCESS 1 in 0 seconds
01:12:54.309829 [debug] [Thread-1  ]: Using snowflake connection "model.my_dbt_project.my_inc"
01:12:54.310610 [debug] [Thread-1  ]: On model.my_dbt_project.my_inc: /* {"app": "dbt", "dbt_version": "1.4.7", "profile_name": "all", "target_name": "sf", "node_id": "model.my_dbt_project.my_inc"} */
show parameters like 'query_tag' in session
01:12:54.623631 [debug] [Thread-1  ]: SQL status: SUCCESS 1 in 0 seconds
01:12:54.625461 [debug] [Thread-1  ]: Setting query_tag to 'dd0b8062-4457-44f3-a7e2-fc6e90fcfbd6'. Will reset to '' after materialization.
01:12:54.626470 [debug] [Thread-1  ]: Using snowflake connection "model.my_dbt_project.my_inc"
01:12:54.626924 [debug] [Thread-1  ]: On model.my_dbt_project.my_inc: /* {"app": "dbt", "dbt_version": "1.4.7", "profile_name": "all", "target_name": "sf", "node_id": "model.my_dbt_project.my_inc"} */
alter session set query_tag = 'dd0b8062-4457-44f3-a7e2-fc6e90fcfbd6'
01:12:54.929973 [debug] [Thread-1  ]: SQL status: SUCCESS 1 in 0 seconds
01:12:54.979101 [debug] [Thread-1  ]: Using snowflake connection "model.my_dbt_project.my_inc"
01:12:54.979835 [debug] [Thread-1  ]: On model.my_dbt_project.my_inc: /* {"app": "dbt", "dbt_version": "1.4.7", "profile_name": "all", "target_name": "sf", "node_id": "model.my_dbt_project.my_inc"} */
create or replace  temporary view development.dbt_jyeo.my_inc__dbt_tmp

   as (

/* dd0b8062-4457-44f3-a7e2-fc6e90fcfbd6 */
select 1 id
  );
01:12:55.403590 [debug] [Thread-1  ]: SQL status: SUCCESS 1 in 0 seconds
01:12:55.424190 [debug] [Thread-1  ]: Using snowflake connection "model.my_dbt_project.my_inc"
01:12:55.424986 [debug] [Thread-1  ]: On model.my_dbt_project.my_inc: /* {"app": "dbt", "dbt_version": "1.4.7", "profile_name": "all", "target_name": "sf", "node_id": "model.my_dbt_project.my_inc"} */
describe table development.dbt_jyeo.my_inc__dbt_tmp
01:12:55.750696 [debug] [Thread-1  ]: SQL status: SUCCESS 1 in 0 seconds
01:12:55.755603 [debug] [Thread-1  ]: Using snowflake connection "model.my_dbt_project.my_inc"
01:12:55.756244 [debug] [Thread-1  ]: On model.my_dbt_project.my_inc: /* {"app": "dbt", "dbt_version": "1.4.7", "profile_name": "all", "target_name": "sf", "node_id": "model.my_dbt_project.my_inc"} */
describe table development.dbt_jyeo.my_inc
01:12:56.137271 [debug] [Thread-1  ]: SQL status: SUCCESS 1 in 0 seconds
01:12:56.158086 [debug] [Thread-1  ]: Using snowflake connection "model.my_dbt_project.my_inc"
01:12:56.158838 [debug] [Thread-1  ]: On model.my_dbt_project.my_inc: /* {"app": "dbt", "dbt_version": "1.4.7", "profile_name": "all", "target_name": "sf", "node_id": "model.my_dbt_project.my_inc"} */
describe table "DEVELOPMENT"."DBT_JYEO"."MY_INC"
01:12:56.471343 [debug] [Thread-1  ]: SQL status: SUCCESS 1 in 0 seconds
01:12:56.506412 [debug] [Thread-1  ]: Writing runtime sql for node "model.my_dbt_project.my_inc"
01:12:56.507771 [debug] [Thread-1  ]: Using snowflake connection "model.my_dbt_project.my_inc"
01:12:56.508246 [debug] [Thread-1  ]: On model.my_dbt_project.my_inc: /* {"app": "dbt", "dbt_version": "1.4.7", "profile_name": "all", "target_name": "sf", "node_id": "model.my_dbt_project.my_inc"} */
-- back compat for old kwarg name

  begin;
01:12:56.850853 [debug] [Thread-1  ]: SQL status: SUCCESS 1 in 0 seconds
01:12:56.851609 [debug] [Thread-1  ]: Using snowflake connection "model.my_dbt_project.my_inc"
01:12:56.852082 [debug] [Thread-1  ]: On model.my_dbt_project.my_inc: /* {"app": "dbt", "dbt_version": "1.4.7", "profile_name": "all", "target_name": "sf", "node_id": "model.my_dbt_project.my_inc"} */
insert into development.dbt_jyeo.my_inc ("ID")
        (
            select "ID"
            from development.dbt_jyeo.my_inc__dbt_tmp
        );
01:12:57.790892 [debug] [Thread-1  ]: SQL status: SUCCESS 1 in 1 seconds
01:12:57.792500 [debug] [Thread-1  ]: Using snowflake connection "model.my_dbt_project.my_inc"
01:12:57.793541 [debug] [Thread-1  ]: On model.my_dbt_project.my_inc: /* {"app": "dbt", "dbt_version": "1.4.7", "profile_name": "all", "target_name": "sf", "node_id": "model.my_dbt_project.my_inc"} */
COMMIT
01:12:58.276912 [debug] [Thread-1  ]: SQL status: SUCCESS 1 in 0 seconds
01:12:58.295834 [debug] [Thread-1  ]: Using snowflake connection "model.my_dbt_project.my_inc"
01:12:58.296613 [debug] [Thread-1  ]: On model.my_dbt_project.my_inc: /* {"app": "dbt", "dbt_version": "1.4.7", "profile_name": "all", "target_name": "sf", "node_id": "model.my_dbt_project.my_inc"} */
drop view if exists development.dbt_jyeo.my_inc__dbt_tmp cascade
01:12:58.656663 [debug] [Thread-1  ]: SQL status: SUCCESS 1 in 0 seconds
01:12:58.696459 [debug] [Thread-1  ]: No original query_tag, unsetting parameter.
01:12:58.697505 [debug] [Thread-1  ]: Using snowflake connection "model.my_dbt_project.my_inc"
01:12:58.698004 [debug] [Thread-1  ]: On model.my_dbt_project.my_inc: /* {"app": "dbt", "dbt_version": "1.4.7", "profile_name": "all", "target_name": "sf", "node_id": "model.my_dbt_project.my_inc"} */
alter session unset query_tag
01:12:59.016176 [debug] [Thread-1  ]: SQL status: SUCCESS 1 in 0 seconds
01:12:59.020518 [debug] [Thread-1  ]: Using snowflake connection "model.my_dbt_project.my_inc"
01:12:59.021543 [debug] [Thread-1  ]: On model.my_dbt_project.my_inc: /* {"app": "dbt", "dbt_version": "1.4.7", "profile_name": "all", "target_name": "sf", "node_id": "model.my_dbt_project.my_inc"} */
use warehouse ANALYTICS
01:12:59.353178 [debug] [Thread-1  ]: SQL status: SUCCESS 1 in 0 seconds
01:12:59.356762 [debug] [Thread-1  ]: Timing info for model.my_dbt_project.my_inc (execute): 2023-09-27 01:12:52.310056 => 2023-09-27 01:12:59.356632
01:12:59.357919 [debug] [Thread-1  ]: On model.my_dbt_project.my_inc: Close
01:12:59.932066 [debug] [Thread-1  ]: Sending event: {'category': 'dbt', 'action': 'run_model', 'label': 'dd0b8062-4457-44f3-a7e2-fc6e90fcfbd6', 'context': [<snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x11fd35eb0>]}
01:12:59.933909 [info ] [Thread-1  ]: 1 of 1 OK created sql incremental model dbt_jyeo.my_inc ........................ [SUCCESS 1 in 7.65s]
01:12:59.937591 [debug] [Thread-1  ]: Finished running node model.my_dbt_project.my_inc
01:12:59.940988 [debug] [MainThread]: Acquiring new snowflake connection 'master'
01:12:59.942465 [debug] [MainThread]: Connection 'master' was properly closed.
01:12:59.943199 [debug] [MainThread]: Connection 'model.my_dbt_project.my_inc' was properly closed.
01:12:59.943986 [info ] [MainThread]: 
01:12:59.944875 [info ] [MainThread]: Finished running 1 incremental model in 0 hours 0 minutes and 13.32 seconds (13.32s).
01:12:59.945753 [debug] [MainThread]: Command end result
01:12:59.958727 [info ] [MainThread]: 
01:12:59.959410 [info ] [MainThread]: Completed successfully
01:12:59.959899 [info ] [MainThread]: 
01:12:59.960367 [info ] [MainThread]: Done. PASS=1 WARN=0 ERROR=0 SKIP=0 TOTAL=1
01:12:59.960918 [debug] [MainThread]: Sending event: {'category': 'dbt', 'action': 'invocation', 'label': 'end', 'context': [<snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x11fd4cfd0>, <snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x11fd143a0>, <snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x11fc1dbe0>]}
01:12:59.961477 [debug] [MainThread]: Flushing usage events

And now we have:

PARSING
01:12:45.164685 [debug] [MainThread]: Partial parsing not enabled
01:12:46.453770 [debug] [MainThread]: 1603: static parser failed on my_inc.sql
01:12:46.479638 [info ] [MainThread]: --------------------------------------------
01:12:46.480701 [info ] [MainThread]: None
01:12:46.481316 [info ] [MainThread]: --------------------------------------------
01:12:46.497353 [debug] [MainThread]: 1602: parser fallback to jinja rendering on my_inc.sql
01:12:46.500119 [debug] [MainThread]: 1603: static parser failed on foo.sql
01:12:46.507270 [debug] [MainThread]: 1602: parser fallback to jinja rendering on foo.sql
01:12:46.509413 [debug] [MainThread]: 1603: static parser failed on my_inc_b.sql
01:12:46.513487 [info ] [MainThread]: --------------------------------------------
01:12:46.514146 [info ] [MainThread]: None
01:12:46.514711 [info ] [MainThread]: --------------------------------------------
01:12:46.517995 [debug] [MainThread]: 1602: parser fallback to jinja rendering on my_inc_b.sql
01:12:46.604247 [debug] [MainThread]: Sending event: {'category': 'dbt', 'action': 'load_project', 'label': 'dd0b8062-4457-44f3-a7e2-fc6e90fcfbd6', 'context': [<snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x11c2633d0>]}
01:12:46.614687 [debug] [MainThread]: Sending event: {'category': 'dbt', 'action': 'resource_counts', 'label': 'dd0b8062-4457-44f3-a7e2-fc6e90fcfbd6', 'context': [<snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x11c1bd850>]}
01:12:46.615591 [info ] [MainThread]: Found 3 models, 0 tests, 0 snapshots, 0 analyses, 429 macros, 0 operations, 0 seed files, 0 sources, 0 exposures, 0 metrics
01:12:46.616212 [debug] [MainThread]: Sending event: {'category': 'dbt', 'action': 'runnable_timing', 'label': 'dd0b8062-4457-44f3-a7e2-fc6e90fcfbd6', 'context': [<snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x11c138700>]}
01:12:46.618274 [info ] [MainThread]: 
01:12:46.619436 [debug] [MainThread]: Acquiring new snowflake connection 'master'
01:12:46.620829 [debug] [ThreadPool]: Acquiring new snowflake connection 'list_development'
01:12:46.643108 [debug] [ThreadPool]: Using snowflake connection "list_development"
01:12:46.644020 [debug] [ThreadPool]: On list_development: /* {"app": "dbt", "dbt_version": "1.4.7", "profile_name": "all", "target_name": "sf", "connection_name": "list_development"} */
show terse schemas in database development
    limit 10000

==== Editors Note ====
The config `snowflake_warehouse` is already set at this stage.... which of course is `wh_initial` because of `None`
The print out below during the compile phase gives a false sense that the warehouse was actually switched.
==================

COMPILE
01:12:52.281834 [debug] [Thread-1  ]: Began compiling node model.my_dbt_project.my_inc
01:12:52.290794 [info ] [Thread-1  ]: --------------------------------------------
01:12:52.291567 [info ] [Thread-1  ]: "DEVELOPMENT"."DBT_JYEO"."MY_INC"
01:12:52.292081 [info ] [Thread-1  ]: --------------------------------------------
01:12:52.307505 [info ] [Thread-1  ]: 14:12:52 + Incremental Run - Using alternative warehouse WH_INCREMENTAL
01:12:52.308147 [debug] [Thread-1  ]: Writing injected SQL for node "model.my_dbt_project.my_inc"
01:12:52.308938 [debug] [Thread-1  ]: Timing info for model.my_dbt_project.my_inc (compile): 2023-09-27 01:12:52.282545 => 2023-09-27 01:12:52.308857
01:12:52.309474 [debug] [Thread-1  ]: Began executing node model.my_dbt_project.my_inc
01:12:52.312226 [debug] [Thread-1  ]: Using snowflake connection "model.my_dbt_project.my_inc"
01:12:52.312967 [debug] [Thread-1  ]: On model.my_dbt_project.my_inc: /* {"app": "dbt", "dbt_version": "1.4.7", "profile_name": "all", "target_name": "sf", "node_id": "model.my_dbt_project.my_inc"} */
select current_warehouse() as warehouse
01:12:52.313784 [debug] [Thread-1  ]: Opening a new connection, currently in state closed
01:12:53.913057 [debug] [Thread-1  ]: SQL status: SUCCESS 1 in 2 seconds
01:12:53.933325 [debug] [Thread-1  ]: Using snowflake connection "model.my_dbt_project.my_inc"
01:12:53.934395 [debug] [Thread-1  ]: On model.my_dbt_project.my_inc: /* {"app": "dbt", "dbt_version": "1.4.7", "profile_name": "all", "target_name": "sf", "node_id": "model.my_dbt_project.my_inc"} */
use warehouse wh_initial
01:12:54.258513 [debug] [Thread-1  ]: SQL status: SUCCESS 1 in 0 seconds

^ The logging out of:

01:12:52.307505 [info ] [Thread-1  ]: 14:12:52 + Incremental Run - Using alternative warehouse WH_INCREMENTAL

Would have given users a false sense of "yup, this works". Because as you can tell, that warehouse is not really used as per the subsequent line:

01:12:53.934395 [debug] [Thread-1  ]: On model.my_dbt_project.my_inc: /* {"app": "dbt", "dbt_version": "1.4.7", "profile_name": "all", "target_name": "sf", "node_id": "model.my_dbt_project.my_inc"} */
use warehouse wh_initial

So no matter the scenario, the snowflake warehouse is always set to wh_initial because at the time (parsing) when the config is set for the model, dbt does not yet "detect the existence of the model in the datawarehouse".

This is the case for dbt 1.3, 1.4, 1.5 and 1.6 so I'm not 100% sure how users were using it in the first place.

EDIT: Minor exception to the above wrt this packages' warehous_size() macro and it's intended use is that --full-refresh is the only case when we would be swapping the warehouse from wh_initial to wh_fullrefresh - because it doesn't check for the existence of the model but simply that the flag is set - which is determinable at the very start of the dbt invocation.

[MartinGuindon]

Very late response on this, my apologies! I'm no longer actively involved in dbt projects.

When I initially wrote this macro (almost 4 years ago!), it was built with insights and feedback from Drew Banin, and it was absolutely working on the project I built it for. Now, dbt has evolved significantly in the last 4 years, and this macro was a bit of a hack to begin with, so it's no surprise that changes under the hood broke this macro at some point. As we haven't worked for that client in 3+ years, the issue was not apparent to us.

I'm no longer working with dbt, so I'm not the best person to investigate and fix this, unfortunately. If someone wants to investigate if a refactor is possible and issue a PR, we're happy to merge any changes. Otherwise, I guess we might have to deprecate it if it's not working at all.

@JFrackson fyi

[rothrock]

Hi, Thanks @MartinGuindon for the update. Running with dbt=1.7.6, I can confirm that this macro doesn't work as expected for incremental models.