[ADAP-982] [Bug] Issue with Snowflake connections hanging 1.7

[DanMawdsleyBA]

Is this a new bug in dbt-snowflake?

• I believe this is a new bug in dbt-snowflake
• I have searched the existing issues, and I could not find an existing issue for this bug

Current Behavior

When running dbt tasks on Airflow I notice that before it runs the create table it opens a connection however this just seems to hang. In non debug mode there is no way of knowing if it is running correctly or hanging. I have been able to get the task to run successfully on 1.7 before but seems quite temperamental to if it works.

Expected Behavior

Establish the connection run the query and then close the connection.

Steps To Reproduce

On airflow environment using airflow cosmos.
I have tried limit the concurrency, max_active_dag_runs to 1. But the issue keeps happening.

I manually then terminated the task.

Relevant log output

[2023-11-03, 16:30:16 GMT] {{subprocess.py:94}} INFO - �[0m16:30:16  Began running node model.dbt_olympus_oprn_crw_ops_planning.poc_booking
[2023-11-03, 16:30:16 GMT] {{subprocess.py:94}} INFO - �[0m16:30:16  1 of 1 START sql table model DBT.poc_booking ................................... [RUN]
[2023-11-03, 16:30:16 GMT] {{subprocess.py:94}} INFO - �[0m16:30:16  Re-using an available connection from the pool (formerly list_db_dev_DBT, now model.dbt_olympus_oprn_crw_ops_planning.poc_booking)
[2023-11-03, 16:30:16 GMT] {{subprocess.py:94}} INFO - �[0m16:30:16  Began compiling node model.dbt_olympus_oprn_crw_ops_planning.poc_booking
[2023-11-03, 16:30:16 GMT] {{subprocess.py:94}} INFO - �[0m16:30:16  Writing injected SQL for node "model.dbt_olympus_oprn_crw_ops_planning.poc_booking"
[2023-11-03, 16:30:16 GMT] {{subprocess.py:94}} INFO - �[0m16:30:16  Timing info for model.dbt_olympus_oprn_crw_ops_planning.poc_booking (compile): 16:30:16.397353 => 16:30:16.408496
[2023-11-03, 16:30:16 GMT] {{subprocess.py:94}} INFO - �[0m16:30:16  Began executing node model.dbt_olympus_oprn_crw_ops_planning.poc_booking
[2023-11-03, 16:30:16 GMT] {{subprocess.py:94}} INFO - �[0m16:30:16  Writing runtime sql for node "model.dbt_olympus_oprn_crw_ops_planning.poc_booking"
[2023-11-03, 16:30:16 GMT] {{subprocess.py:94}} INFO - �[0m16:30:16  Using snowflake connection "model.dbt_olympus_oprn_crw_ops_planning.poc_booking"
[2023-11-03, 16:30:16 GMT] {{subprocess.py:94}} INFO - �[0m16:30:16  On model.dbt_olympus_oprn_crw_ops_planning.poc_booking: /* {"app": "dbt", "dbt_version": "1.7.0", "profile_name": "dbt_profile", "target_name": "snowflake_airflow", "node_id": "model.dbt_olympus_oprn_crw_ops_planning.poc_booking"} */
[2023-11-03, 16:30:16 GMT] {{subprocess.py:94}} INFO - create or replace transient table db_dev.DBT.poc_booking
[2023-11-03, 16:30:16 GMT] {{subprocess.py:94}} INFO -          as
[2023-11-03, 16:30:16 GMT] {{subprocess.py:94}} INFO -         (
[2023-11-03, 16:30:16 GMT] {{logging_mixin.py:150}} WARNING - /usr/local/airflow/.local/lib/python3.10/site-packages/watchtower/__init__.py:349 WatchtowerWarning: Received empty message. Empty messages cannot be sent to CloudWatch Logs
[2023-11-03, 16:30:16 GMT] {{logging_mixin.py:150}} WARNING - Traceback (most recent call last):
[2023-11-03, 16:30:16 GMT] {{logging_mixin.py:150}} WARNING -   File "/usr/local/airflow/config/cloudwatch_logging.py", line 161, in emit
    self.sniff_errors(record)
[2023-11-03, 16:30:16 GMT] {{logging_mixin.py:150}} WARNING -   File "/usr/local/airflow/config/cloudwatch_logging.py", line 212, in sniff_errors
    if pattern.search(record.message):
[2023-11-03, 16:30:16 GMT] {{logging_mixin.py:150}} WARNING - AttributeError: 'LogRecord' object has no attribute 'message'
[2023-11-03, 16:30:16 GMT] {{subprocess.py:94}} INFO - select
[2023-11-03, 16:30:16 GMT] {{subprocess.py:94}} INFO - 123 as booking_id
[2023-11-03, 16:30:16 GMT] {{subprocess.py:94}} INFO - ,'Dan' as customer_name
[2023-11-03, 16:30:16 GMT] {{subprocess.py:94}} INFO - ,'LHR' as source_cd
[2023-11-03, 16:30:16 GMT] {{subprocess.py:94}} INFO - ,'PVG' as destination_cd
[2023-11-03, 16:30:16 GMT] {{subprocess.py:94}} INFO - , 699 as booking_cost
[2023-11-03, 16:30:16 GMT] {{subprocess.py:94}} INFO -         );
[2023-11-03, 16:30:16 GMT] {{subprocess.py:94}} INFO - �[0m16:30:16  Opening a new connection, currently in state closed
[2023-11-03, 16:34:54 GMT] {{local_task_job_runner.py:291}} WARNING - State of this instance has been externally set to restarting. Terminating instance.
[2023-11-03, 16:34:54 GMT] {{taskinstance.py:1517}} ERROR - Received SIGTERM. Terminating subprocesses.

Environment

- OS: Airflow 2.6
- Python: 3.10
- dbt-core: 1.7
- dbt-snowflake: 1.7

Additional Context

I was able to get the task to run previously but seems quite tempremental as to whether it works or not. I have no issues running models on my local computer. Logs at the same point below:

�[0m17:03:59.887387 [debug] [Thread-3 (]: Began running node model.dbt_olympus_oprn_crw_ops_planning.poc_booking
�[0m17:03:59.891117 [info ] [Thread-3 (]: 1 of 1 START sql table model DEV.poc_booking ................................... [RUN]
�[0m17:03:59.891117 [debug] [Thread-3 (]: Acquiring new snowflake connection 'model.dbt_olympus_oprn_crw_ops_planning.poc_booking'
�[0m17:03:59.899709 [debug] [Thread-3 (]: Began compiling node model.dbt_olympus_oprn_crw_ops_planning.poc_booking
�[0m17:03:59.909898 [debug] [Thread-3 (]: Writing injected SQL for node "model.dbt_olympus_oprn_crw_ops_planning.poc_booking"
�[0m17:03:59.924470 [debug] [Thread-3 (]: Timing info for model.dbt_olympus_oprn_crw_ops_planning.poc_booking (compile): 17:03:59.900713 => 17:03:59.923185
�[0m17:03:59.926542 [debug] [Thread-3 (]: Began executing node model.dbt_olympus_oprn_crw_ops_planning.poc_booking
�[0m17:03:59.993947 [debug] [Thread-3 (]: Writing runtime sql for node "model.dbt_olympus_oprn_crw_ops_planning.poc_booking"
�[0m17:04:00.019611 [debug] [Thread-3 (]: Using snowflake connection "model.dbt_olympus_oprn_crw_ops_planning.poc_booking"
�[0m17:04:00.023995 [debug] [Thread-3 (]: On model.dbt_olympus_oprn_crw_ops_planning.poc_booking: /* {"app": "dbt", "dbt_version": "1.7.0", "profile_name": "dbt_profile", "target_name": "snowflake_local", "node_id": "model.dbt_olympus_oprn_crw_ops_planning.poc_booking"} */
create or replace transient table DB_DAN_MAWDSLEY.DEV.poc_booking
         as
        (


select
123 as booking_id
,'Dan' as customer_name
,'LHR' as source_cd
,'PVG' as destination_cd
, 699 as booking_cost
        );
�[0m17:04:00.024996 [debug] [Thread-3 (]: Opening a new connection, currently in state init
�[0m17:04:05.477382 [debug] [Thread-3 (]: SQL status: SUCCESS 1 in 5.0 seconds

[dbeatty10]

Thanks for reaching out about this @DanMawdsleyBA.

Since you have no issues running models on your local computer, that seems to point towards something within Cosmos or some kind of interaction effect between dbt-snowflake and Cosmos.

I'm going to close this issue in favor of astronomer/astronomer-cosmos#647.

If you find more information that would allow us to reproduce the issue independently of Cosmos (or if someone discovers something that dbt-snowflake or dbt-core is doing sub-optimally), just reach out and we can re-open this issue!