search

dbt-labs / dbt-snowflake

dbt-snowflake contains all of the code enabling dbt to work with Snowflake
https://getdbt.com
Apache License 2.0
297 stars 177 forks source link

[Bug] Snowflake connections closing before on-run-end macro(s) finish #1158

Closed kmampe closed 3 months ago

kmampe commented 3 months ago

Is this a new bug in dbt-snowflake?

Current Behavior

I am running a custom on-run-end macro that creates a cloned table that is built during my dbt run/build command. It appears that dbt is closing connections made with snowflake before my on-run-end is able to finish. The on-run-end hook begins, and abruptly exists with the below error.

17:24:38  Running 1 on-run-end hook
17:24:39  1 of 1 START hook: <hookname>.on-run-end.0 ................. [RUN]
17:24:39  Snowflake adapter: [WARNING]: Explicit transactional logic should be used only to wrap DML
logic (MERGE, DELETE, UPDATE, etc). The keywords BEGIN; and COMMIT; should be
placed directly before and after your DML statement, rather than in separate
statement calls or run_query() macros.
17:24:40  
17:24:40  Finished running 9 view models, 1 table model, 5 tests in 0 hours 0 minutes and 25.68 seconds (25.68s).
17:24:40  Encountered an error:
local variable 'connection' referenced before assignment

Below is my macro

{% macro deploy_staged_aggregation(results) %}

{% if execute %}

    {% set final_tables = [] %}

    {% set failed_test_models = [] %}

    {% for result in results %}

        /* Creates a list[dict] of 'final' aggregation table models */
        {% if 'marts/' in result.node.path|lower
            and result.node.resource_type|lower == 'model'
            and result.status|lower == 'success'
            and result.node.config.materialized|lower  == 'table'%}
            {% do final_tables.append(result) %}
        {% endif %}

        /* Creates a list[string] of models that had a failed test */
        {% if result.status == 'fail'
            and result.node.resource_type == 'test' %}
            {% do failed_test_models.append(result.node.file_key_name.split(".")[-1]) %}
        {% endif %}

    {% endfor %}

    /* For each model (table) object in 'final_tables', check if it has a failed test */
    {% for final_table in final_tables %}

        /* If the final table had a test failure */
        {% if final_table.node.name in failed_test_models %}
            {{ log("FAILED: not deploying " ~ final_table.node.name ~ " to " ~ target.schema, info=True) }}

        /* No test failure, create clone */
        {% else %}
            {{ log("PASSED, deploying " ~ final_table.node.name ~ " to " ~ target.schema, info=True) }}

            {% set sql %}
            CREATE OR REPLACE TABLE {{ target.database }}.{{ target.schema }}.{{ final_table.node.name }}
            CLONE {{ final_table.node.database }}.{{ final_table.node.schema }}.{{ final_table.node.name }};
            {% endset %}

              {% do run_query(sql) %}

        {% endif %}

    {% endfor %}

{% endif %}

{% endmacro %}

It is not using any DML logic. It parses logs to find out if any tests failed, and if they did not, it creates a clone of the final built table in my dbt run/build/test.

Expected Behavior

I expect this on-run-end to create a clone of a table if all tests do pass. If all tests do not pass, the on-run-end should still run, just not create a clone table.

Steps To Reproduce

Private environment. I am running a custom on-run-end macro that creates a clone of a table depending on conditions.

Relevant log output

17:33:41  Running with dbt=1.7.17
17:33:41  target not specified in profile 'aggregations_xsmall', using 'default'
17:33:41  Registered adapter: snowflake=1.7.5
17:33:41  Found 10 models, 1 operation, 5 tests, 7 sources, 0 exposures, 0 metrics, 572 macros, 0 groups, 0 semantic models
17:33:41  
17:33:43  Concurrency: 4 threads (target='default')
17:33:43  
17:33:43  1 of 15 START sql view model <model> [RUN]
17:33:44  1 of 15 OK created sql view model <model>  [SUCCESS 1 in 0.80s]
17:33:44  2 of 15 START sql view model <model>  [RUN]
17:33:44  3 of 15 START sql view model <model>  [RUN]
17:33:44  4 of 15 START sql view model <model>  [RUN]
17:33:44  4 of 15 OK created sql view model <model>  [SUCCESS 1 in 0.79s]
17:33:45  3 of 15 OK created sql view model <model>  [SUCCESS 1 in 0.82s]
17:33:45  5 of 15 START sql view model <model>  [RUN]
17:33:45  6 of 15 START sql view model <model>  [RUN]
17:33:45  2 of 15 OK created sql view model <model>  [SUCCESS 1 in 0.84s]
17:33:45  7 of 15 START sql view model <model>  [RUN]
17:33:45  6 of 15 OK created sql view model <model>  [SUCCESS 1 in 0.78s]
17:33:45  5 of 15 OK created sql view model <model>  [SUCCESS 1 in 0.79s]
17:33:45  8 of 15 START sql view model <model>  [RUN]
17:33:46  7 of 15 OK created sql view model <model>  [SUCCESS 1 in 1.36s]
17:33:47  8 of 15 OK created sql view model <model>  [SUCCESS 1 in 1.87s]
17:33:47  9 of 15 START sql view model <model>  [RUN]
17:33:49  9 of 15 OK created sql view model <model>  [SUCCESS 1 in 1.92s]
17:33:49  10 of 15 START sql table model <model> ....... [RUN]
17:34:05  10 of 15 OK created sql table model <model> .. [SUCCESS 1 in 15.46s]
17:34:05  11 of 15 START test <test>  [RUN]
17:34:05  12 of 15 START test <test>[RUN]
17:34:05  13 of 15 START test <test>  [RUN]
17:34:05  14 of 15 START test <test>  [RUN]
17:34:05  14 of 15 PASS <test>  [PASS in 0.68s]
17:34:05  15 of 15 START test <test>  [RUN]
17:34:06  15 of 15 PASS <test>  [PASS in 0.61s]
17:34:07  11 of 15 PASS <test>  [PASS in 2.66s]
17:34:08  12 of 15 PASS <test> [PASS in 3.31s]
17:34:08  13 of 15 PASS <test>  [PASS in 3.33s]
17:34:08  
17:34:08  Running 1 on-run-end hook
17:34:10  1 of 1 START hook: <project name>.on-run-end.0 ................. [RUN]
17:34:10  Snowflake adapter: [WARNING]: Explicit transactional logic should be used only to wrap DML
logic (MERGE, DELETE, UPDATE, etc). The keywords BEGIN; and COMMIT; should be
placed directly before and after your DML statement, rather than in separate
statement calls or run_query() macros.
17:34:10  
17:34:10  Finished running 9 view models, 1 table model, 5 tests in 0 hours 0 minutes and 28.46 seconds (28.46s).
17:34:10  Encountered an error:
local variable 'connection' referenced before assignment
17:34:10  Traceback (most recent call last):
  File "/Users/kevinmampe/mai-github/snowflake-dbt/venv/lib/python3.10/site-packages/dbt/cli/requires.py", line 91, in wrapper
    result, success = func(*args, **kwargs)
  File "/Users/kevinmampe/mai-github/snowflake-dbt/venv/lib/python3.10/site-packages/dbt/cli/requires.py", line 76, in wrapper
    return func(*args, **kwargs)
  File "/Users/kevinmampe/mai-github/snowflake-dbt/venv/lib/python3.10/site-packages/dbt/cli/requires.py", line 169, in wrapper
    return func(*args, **kwargs)
  File "/Users/kevinmampe/mai-github/snowflake-dbt/venv/lib/python3.10/site-packages/dbt/cli/requires.py", line 198, in wrapper
    return func(*args, **kwargs)
  File "/Users/kevinmampe/mai-github/snowflake-dbt/venv/lib/python3.10/site-packages/dbt/cli/requires.py", line 245, in wrapper
    return func(*args, **kwargs)
  File "/Users/kevinmampe/mai-github/snowflake-dbt/venv/lib/python3.10/site-packages/dbt/cli/requires.py", line 278, in wrapper
    return func(*args, **kwargs)
  File "/Users/kevinmampe/mai-github/snowflake-dbt/venv/lib/python3.10/site-packages/dbt/cli/main.py", line 220, in build
    results = task.run()
  File "/Users/kevinmampe/mai-github/snowflake-dbt/venv/lib/python3.10/site-packages/dbt/task/runnable.py", line 502, in run
    result = self.execute_with_hooks(selected_uids)
  File "/Users/kevinmampe/mai-github/snowflake-dbt/venv/lib/python3.10/site-packages/dbt/task/runnable.py", line 464, in execute_with_hooks
    self.after_run(adapter, res)
  File "/Users/kevinmampe/mai-github/snowflake-dbt/venv/lib/python3.10/site-packages/dbt/task/run.py", line 476, in after_run
    self.safe_run_hooks(adapter, RunHookType.End, extras)
  File "/Users/kevinmampe/mai-github/snowflake-dbt/venv/lib/python3.10/site-packages/dbt/task/run.py", line 415, in safe_run_hooks
    self.run_hooks(adapter, hook_type, extra_context)
  File "/Users/kevinmampe/mai-github/snowflake-dbt/venv/lib/python3.10/site-packages/dbt/task/run.py", line 383, in run_hooks
    response, _ = adapter.execute(sql, auto_begin=False, fetch=False)
  File "/Users/kevinmampe/mai-github/snowflake-dbt/venv/lib/python3.10/site-packages/dbt/adapters/base/impl.py", line 310, in execute
    return self.connections.execute(sql=sql, auto_begin=auto_begin, fetch=fetch, limit=limit)
  File "/Users/kevinmampe/mai-github/snowflake-dbt/venv/lib/python3.10/site-packages/dbt/adapters/snowflake/connections.py", line 472, in execute
    _, cursor = self.add_query(sql, auto_begin)
  File "/Users/kevinmampe/mai-github/snowflake-dbt/venv/lib/python3.10/site-packages/dbt/adapters/snowflake/connections.py", line 500, in add_query
    connection, cursor = self._add_begin_commit_only_queries(
  File "/Users/kevinmampe/mai-github/snowflake-dbt/venv/lib/python3.10/site-packages/dbt/adapters/snowflake/connections.py", line 548, in _add_begin_commit_only_queries
    return connection, cursor
UnboundLocalError: local variable 'connection' referenced before assignment

Environment

- OS: macOS Monterey version 12.1.1
- Python: 3.10.9
- dbt-core: 1.7.17
- dbt-snowflake: 1.7.5

Additional Context

No response

whlufisc commented 2 months ago

Hello! Did you find any solution for your problem? We get the same error local variable 'connection' referenced before assignment. This happens in a post_hook of the last model in our DAG.