[ADAP-739] [Bug] Query was empty error in dbt-redshift==1.5.8 with dbt-core==1.5.4 #561

lsabreu96 · 2023-07-31T17:02:21Z

Is this a new bug in dbt-redshift?

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

Current Behavior

Upgrading from dbt-core==1.3.2 to dbt-core==1.5.4 I started receiving the Query was empty error for incremental models. It seems to be due to some listing mechanism dbt seems to perform on the database.

Inspecing the generated code for incremental models, it returns me only the delete+insert step whereas for non incremental models it shows me the actual query (not sure if it's relevant).

Inspecing the database objects affected by the query, the query does seems to work just fine, tho. It seems something related to a teardown process of the run

Expected Behavior

No error if the executions seemed to have worked fine.

Steps To Reproduce

Install dbt-core==1.5.4 along with dbt-redshift==1.5.8
Create a incremental model. Below is a MWE

{{
  config(
    materialized='incremental',
    unique_key='model_pk_id',
    incremental_strategy='delete+insert',
  )
}}

select 1 as model_pk_id

Relevant log output

[[0m13:57:16.023568 [debug] [Thread-1  ]: Using redshift connection "model.loggi_warehouse.base_city_inc"
[[0m13:57:16.024268 [debug] [Thread-1  ]: On model.loggi_warehouse.base_city_inc: ;
[[0m13:57:16.839975 [debug] [Thread-1  ]: Redshift adapter: Redshift error: query was empty
[[0m13:57:16.840876 [debug] [Thread-1  ]: On model.loggi_warehouse.base_city_inc: ROLLBACK
[[0m13:57:16.842184 [debug] [Thread-1  ]: Timing info for model.loggi_warehouse.base_city_inc (execute): 13:56:29.923933 => 13:57:16.841745
[[0m13:57:16.842977 [debug] [Thread-1  ]: On model.loggi_warehouse.base_city_inc: Close
[[0m13:57:16.846557 [debug] [Thread-1  ]: Database Error in model base_city_inc (models/shared/midnight_group/base_city_inc.sql)  query was empty


^ first log of error

Environment

- OS:Ubuntu 20.04.6 LTS
- Python: 3.8.10
- dbt-core:1.5.4
- dbt-redshift:1.5.8

Additional Context

No response

The text was updated successfully, but these errors were encountered:

dataders · 2023-08-03T17:21:08Z

@lsabreu96 thanks for reporting this!

I just tried but failed to reproduce. Can you think of anything else you might have configured? My brain jumps to things like query_comment.

Also, does this happen on initial model creation? or only when the model is updated?

lsabreu96 · 2023-08-03T18:17:14Z

Hi @dataders , we have some pre-post hooks as well as on-run-start configured, but the error seems to be returned from the model itself.

For the sake of reference:
on-run-start: is set to create_audit_schema(), create_audit_log_table() and log_run_start_event() from dbt-labs/logging==0.6.0

pre-hook:
logging.log_model_start_event()

post-hook:
logging.log_model_end_event()

I noticed that the logging package is outdated, but even when bumping it to the latest version, the error persists. We also have some custom macros, but all they do is run some inserts/deletes in the database

Also, does this happen on initial model creation? or only when the model is updated?

I was running a small model for the sake of testing and the error raised. I hadn't altered it in anyway

lsabreu96 · 2023-08-03T18:40:18Z

Just removed all on-run-start/end as well as any pre/post-hooks and it fails with the same error.

The compiled query shows me the delete+insert step (not sure if that's relevant)

lsabreu96 · 2023-08-03T19:50:54Z

The problem seems to be a macro we have as a post-hook for models. I got the project from the prior team and is implemented as such

{% macro set_last_execution() %}

{% if execute %}

begin;
DELETE FROM dbt_dw_log.dbt_incremental_control WHERE dbt_schema_nm = '{{ this.schema }}' and dbt_model_nm = '{{ this.table }}';
commit;

begin;
INSERT INTO dbt_dw_log.dbt_incremental_control(dbt_model_nm, dbt_schema_nm, last_execution_dt)

with
table_aux as (
    select max(source_updated_dt) last_execution_dt from {{this}}
)
SELECT
    '{{ this.table }}' as dbt_model_nm,
    '{{ this.schema }}' as dbt_schema_nm,
    isnull(table_aux.last_execution_dt, to_timestamp('1990-01-01 00:00:00', 'YYYY-MM-DD HH24:MI:SS')) as last_execution_dt
FROM table_aux
;
commit;

{% endif %}

{% endmacro %}

It's meant to fine grain control over incremental execution accross the database. It's regular transaction management, but something seems to be slipping off whenever this query get submmited to the database. What I find it odd is that all operations return ok. I'll attach the logs below

16:49:19.626458 [debug] [Thread-1  ]: On model.loggi_warehouse.base_city_inc: /* {"app": "dbt", "dbt_version": "1.6.0", "profile_name": "loggi", "target_name": "dev", "node_id": "model.loggi_warehouse.base_city_inc"} */

        begin;
16:49:20.263078 [debug] [Thread-1  ]: SQL status: SUCCESS in 1.0 seconds
16:49:20.265536 [debug] [Thread-1  ]: Using redshift connection "model.loggi_warehouse.base_city_inc"
16:49:20.267657 [debug] [Thread-1  ]: On model.loggi_warehouse.base_city_inc: DELETE FROM dbt_dw_log.dbt_incremental_control WHERE dbt_schema_nm = 'dbt_labreu' and dbt_model_nm = 'base_city_inc';
16:49:20.861434 [debug] [Thread-1  ]: SQL status: SUCCESS in 1.0 seconds
16:49:20.866396 [debug] [Thread-1  ]: Using redshift connection "model.loggi_warehouse.base_city_inc"
16:49:20.869445 [debug] [Thread-1  ]: On model.loggi_warehouse.base_city_inc: commit;
16:49:21.553467 [debug] [Thread-1  ]: SQL status: SUCCESS in 1.0 seconds
16:49:21.554317 [debug] [Thread-1  ]: Using redshift connection "model.loggi_warehouse.base_city_inc"
16:49:21.555207 [debug] [Thread-1  ]: On model.loggi_warehouse.base_city_inc: begin;
16:49:21.959266 [debug] [Thread-1  ]: SQL status: SUCCESS in 0.0 seconds
16:49:21.960673 [debug] [Thread-1  ]: Using redshift connection "model.loggi_warehouse.base_city_inc"
16:49:21.962179 [debug] [Thread-1  ]: On model.loggi_warehouse.base_city_inc: INSERT INTO dbt_dw_log.dbt_incremental_control(dbt_model_nm, dbt_schema_nm, last_execution_dt)

with
table_aux as (
    select max(source_updated_dt) last_execution_dt from "prod"."dbt_labreu"."base_city_inc"
)
SELECT
    'base_city_inc' as dbt_model_nm,
    'dbt_labreu' as dbt_schema_nm,
    isnull(table_aux.last_execution_dt, to_timestamp('1990-01-01 00:00:00', 'YYYY-MM-DD HH24:MI:SS')) as last_execution_dt
FROM table_aux
;
16:49:22.441903 [debug] [Thread-1  ]: SQL status: SUCCESS in 0.0 seconds
16:49:22.442551 [debug] [Thread-1  ]: Using redshift connection "model.loggi_warehouse.base_city_inc"
16:49:22.443038 [debug] [Thread-1  ]: On model.loggi_warehouse.base_city_inc: commit;
16:49:23.102864 [debug] [Thread-1  ]: SQL status: SUCCESS in 1.0 seconds
16:49:23.104375 [debug] [Thread-1  ]: Using redshift connection "model.loggi_warehouse.base_city_inc"
16:49:23.106058 [debug] [Thread-1  ]: On model.loggi_warehouse.base_city_inc: ;
16:49:23.746309 [debug] [Thread-1  ]: Redshift adapter: Redshift error: query was empty
16:49:23.747266 [debug] [Thread-1  ]: On model.loggi_warehouse.base_city_inc: ROLLBACK
16:49:23.748252 [debug] [Thread-1  ]: Timing info for model.loggi_warehouse.base_city_inc (execute): 16:48:39.722191 => 16:49:23.747969
16:49:23.749032 [debug] [Thread-1  ]: On model.loggi_warehouse.base_city_inc: Close
16:49:23.751455 [debug] [Thread-1  ]: Database Error in model base_city_inc (models/shared/midnight_group/base_city_inc.sql)
  query was empty
  compiled Code at target/run/loggi_warehouse/models/shared/midnight_group/base_city_inc.sql
16:49:23.752263 [debug] [Thread-1  ]: Sending event: {'category': 'dbt', 'action': 'run_model', 'label': 'bdf799ca-0f3a-419e-9e59-25f2f15f4f7a', 'context': [<snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x7feec30cf9a0>]}
16:49:23.753506 [error] [Thread-1  ]: 1 of 1 ERROR creating sql incremental model dbt_labreu.base_city_inc ........... [ERROR in 46.31s]

lsabreu96 · 2023-08-03T20:37:54Z

Reading this part

16:49:23.104375 [debug] [Thread-1  ]: Using redshift connection "model.loggi_warehouse.base_city_inc"
16:49:23.106058 [debug] [Thread-1  ]: On model.loggi_warehouse.base_city_inc: ;
16:49:23.746309 [debug] [Thread-1  ]: Redshift adapter: Redshift error: query was empty
16:

DBT seems to be indeed issuing an empty query

dbeatty10 · 2023-08-10T02:16:40Z

@lsabreu96 I still wasn't able to reproduce the bug that you reported.

See below for a full project setup and a list of commands that worked for me in both dbt-redshift 1.5.x and 1.6.x.

Could you try to tweak the setup below to generate the error you are seeing?

Project setup and commands

models/incremental_control.sql

{{ config(materialized="table") }}

select
  cast('' as varchar(65535)) as dbt_schema_nm,
  cast('' as varchar(65535)) as dbt_model_nm,
  cast({{ dbt.current_timestamp() }} as timestamp without time zone) as last_execution_dt

where 1=0

models/my_model.sql

{{
  config(
    materialized='incremental',
    unique_key='model_pk_id',
    incremental_strategy='delete+insert',
    post_hook=["{{ set_last_execution() }}"],
  )
}}

-- depends_on: {{ ref('incremental_control') }}
select
  1 as model_pk_id,
  {{ dbt.current_timestamp() }} as source_updated_dt

macros/my_macros.sql

{% macro set_last_execution() %}

{% if execute %}

begin;
DELETE FROM {{ ref("incremental_control") }} WHERE dbt_schema_nm = '{{ this.schema }}' and dbt_model_nm = '{{ this.table }}';
commit;

begin;
INSERT INTO {{ ref("incremental_control") }}(dbt_model_nm, dbt_schema_nm, last_execution_dt)

with
table_aux as (
    select max(source_updated_dt) as last_execution_dt from {{ this }}
)
SELECT
    '{{ this.table }}' as dbt_model_nm,
    '{{ this.schema }}' as dbt_schema_nm,
    isnull(table_aux.last_execution_dt, to_timestamp('1990-01-01 00:00:00', 'YYYY-MM-DD HH24:MI:SS')) as last_execution_dt
FROM table_aux
;
commit;

{% endif %}

{% endmacro %}

models/_models.yml

version: 2

models:
  - name: incremental_control
    config:
      contract:
        enforced: true
    columns:
      - name: dbt_schema_nm
        data_type: varchar(65535)
      - name: dbt_model_nm
        data_type: varchar(65535)
      - name: last_execution_dt
        data_type: timestamp without time zone

Run these commands to see the output of the updates in the control table:

dbt run -s incremental_control --full-refresh
dbt show --inline 'select * from {{ ref("incremental_control") }} order by 3 asc'
dbt run -s my_model --full-refresh
dbt show --inline 'select * from {{ ref("incremental_control") }} order by 3 asc'
dbt run -s my_model
dbt show --inline 'select * from {{ ref("incremental_control") }} order by 3 asc'

lsabreu96 · 2023-08-10T11:41:10Z

@dbeatty10 , thanks for the help.
Asides from using ref in the macro, the only thing different I noticed was that you passed the post hook as a list, in our case, some tables do have more than one post hooks and we were providing it as a giant string
{{ macro1() }}; {{ macro2() }}

The ; seems that was parsed as a query such ash ;, hence leading to the error I was seeing in the logs

Changing it to ["{{ macro1() }}", "{{ macro2() }}"] seems to have worked for this example. I'll run a couple more tests and will let you know

lsabreu96 · 2023-08-31T22:15:36Z

Sorry for the really delayed answer.
Turns out the issue was the ; in the giant string set in the post-hook for a couple of models. Switching it to python list solved the issue.
Thanks for the help, everyone

jeremyyeo · 2023-11-05T22:22:57Z

Adding an example.

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

models:
  my_dbt_project:
    +materialized: table

-- macros/do_thing.sql
{% macro do_thing() %}
    {% if execute %}
        begin;
        select 1 id;
        commit;

        begin;
        select 2 id;
        commit;
    {% endif %}
{% endmacro %}

-- macros/do_another_thing.sql
{% macro do_another_thing() %}
    {% if execute %}
        begin;
        select 1 id;
        commit;

        begin;
        select 2 id;
        commit;
    {% endif %}
{% endmacro %}

-- models/foo.sql
{{ config(pre_hook="{{ do_thing() }}; {{ do_another_thing() }}") }}

select 1 id

On a now deprecated version of dbt (i.e. 1.0):

$ dbt --debug run
...

22:17:59.604512 [debug] [Thread-1  ]: Began running node model.my_dbt_project.foo
22:17:59.605488 [info ] [Thread-1  ]: 1 of 1 START table model public.foo............................................. [RUN]
22:17:59.606566 [debug] [Thread-1  ]: Acquiring new redshift connection "model.my_dbt_project.foo"
22:17:59.607473 [debug] [Thread-1  ]: Began compiling node model.my_dbt_project.foo
22:17:59.608192 [debug] [Thread-1  ]: Compiling model.my_dbt_project.foo
22:17:59.612817 [debug] [Thread-1  ]: Writing injected SQL for node "model.my_dbt_project.foo"
22:17:59.614078 [debug] [Thread-1  ]: finished collecting timing info
22:17:59.614536 [debug] [Thread-1  ]: Began executing node model.my_dbt_project.foo
22:17:59.644589 [debug] [Thread-1  ]: Using redshift connection "model.my_dbt_project.foo"
22:17:59.645235 [debug] [Thread-1  ]: On model.my_dbt_project.foo: BEGIN
22:17:59.645612 [debug] [Thread-1  ]: Opening a new connection, currently in state closed
22:17:59.646093 [debug] [Thread-1  ]: Redshift adapter: Connecting to Redshift using 'database' credentials
22:18:01.502412 [debug] [Thread-1  ]: SQL status: BEGIN in 1.86 seconds
22:18:01.503887 [debug] [Thread-1  ]: Using redshift connection "model.my_dbt_project.foo"
22:18:01.504424 [debug] [Thread-1  ]: On model.my_dbt_project.foo: /* {"app": "dbt", "dbt_version": "1.0.9", "profile_name": "all", "target_name": "rs", "node_id": "model.my_dbt_project.foo"} */

        begin;
select 1 id;
commit;

begin;
select 2 id;
commit;

; 
    
        begin;
        select 1 id;
        commit;

        begin;
        select 2 id;
        commit;
      
22:18:01.713792 [debug] [Thread-1  ]: SQL status: COMMIT in 0.21 seconds
22:18:01.752544 [debug] [Thread-1  ]: Writing runtime SQL for node "model.my_dbt_project.foo"
22:18:01.753666 [debug] [Thread-1  ]: Using redshift connection "model.my_dbt_project.foo"
22:18:01.754089 [debug] [Thread-1  ]: On model.my_dbt_project.foo: /* {"app": "dbt", "dbt_version": "1.0.9", "profile_name": "all", "target_name": "rs", "node_id": "model.my_dbt_project.foo"} */


  create  table
    "dev"."public"."foo__dbt_tmp"
    
    
    
  as (
    

select 1 id
  );
22:18:02.645070 [debug] [Thread-1  ]: SQL status: SELECT in 0.89 seconds
...

And on a more recent version (1.6):

$ dbt --debug run
...
22:20:32  1 of 1 START sql table model public.foo ........................................ [RUN]
22:20:32  Re-using an available connection from the pool (formerly list_dev_public, now model.my_dbt_project.foo)
22:20:32  Began compiling node model.my_dbt_project.foo
22:20:32  Writing injected SQL for node "model.my_dbt_project.foo"
22:20:32  Timing info for model.my_dbt_project.foo (compile): 11:20:32.200303 => 11:20:32.207719
22:20:32  Began executing node model.my_dbt_project.foo
22:20:32  Using redshift connection "model.my_dbt_project.foo"
22:20:32  On model.my_dbt_project.foo: BEGIN
22:20:32  Opening a new connection, currently in state closed
22:20:32  Redshift adapter: Establishing connection using ssl with `sslmode` set to 'prefer'.To connect without ssl, set `sslmode` to 'disable'.
22:20:32  Redshift adapter: Connecting to redshift with username/password based auth...
22:20:34  SQL status: SUCCESS in 2.0 seconds
22:20:34  Using redshift connection "model.my_dbt_project.foo"
22:20:34  On model.my_dbt_project.foo: /* {"app": "dbt", "dbt_version": "1.6.6", "profile_name": "all", "target_name": "rs", "node_id": "model.my_dbt_project.foo"} */

        begin;
22:20:34  SQL status: SUCCESS in 0.0 seconds
22:20:34  Using redshift connection "model.my_dbt_project.foo"
22:20:34  On model.my_dbt_project.foo: select 1 id;
22:20:34  SQL status: SUCCESS in 0.0 seconds
22:20:34  Using redshift connection "model.my_dbt_project.foo"
22:20:34  On model.my_dbt_project.foo: commit;
22:20:35  SQL status: SUCCESS in 0.0 seconds
22:20:35  Using redshift connection "model.my_dbt_project.foo"
22:20:35  On model.my_dbt_project.foo: begin;
22:20:35  SQL status: SUCCESS in 0.0 seconds
22:20:35  Using redshift connection "model.my_dbt_project.foo"
22:20:35  On model.my_dbt_project.foo: select 2 id;
22:20:36  SQL status: SUCCESS in 0.0 seconds
22:20:36  Using redshift connection "model.my_dbt_project.foo"
22:20:36  On model.my_dbt_project.foo: commit;
22:20:36  SQL status: SUCCESS in 0.0 seconds
22:20:36  Using redshift connection "model.my_dbt_project.foo"
22:20:36  On model.my_dbt_project.foo: ;
22:20:36  Redshift adapter: Redshift error: query was empty
22:20:36  On model.my_dbt_project.foo: ROLLBACK
22:20:36  Timing info for model.my_dbt_project.foo (execute): 11:20:32.209790 => 11:20:36.757150
22:20:36  On model.my_dbt_project.foo: Close
22:20:36  Database Error in model foo (models/marts/foo.sql)
  query was empty
22:20:36  Sending event: {'category': 'dbt', 'action': 'run_model', 'label': '253b7274-8631-420b-99a3-4f2df0ca0907', 'context': [<snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x109fe9a30>]}
22:20:36  1 of 1 ERROR creating sql table model public.foo ............................... [ERROR in 4.57s]
22:20:36  Finished running node model.my_dbt_project.foo
22:20:36  Using redshift connection "master"
22:20:36  On master: BEGIN
22:20:36  Opening a new connection, currently in state closed
22:20:36  Redshift adapter: Establishing connection using ssl with `sslmode` set to 'prefer'.To connect without ssl, set `sslmode` to 'disable'.
22:20:36  Redshift adapter: Connecting to redshift with username/password based auth...
22:20:38  SQL status: SUCCESS in 2.0 seconds
22:20:38  On master: COMMIT
22:20:38  Using redshift connection "master"
22:20:38  On master: COMMIT
22:20:38  SQL status: SUCCESS in 0.0 seconds
22:20:38  On master: Close
22:20:38  Connection 'master' was properly closed.
22:20:38  Connection 'model.my_dbt_project.foo' was properly closed.
22:20:38  
22:20:38  Finished running 1 table model in 0 hours 0 minutes and 14.84 seconds (14.84s).
22:20:38  Command end result
22:20:38  
22:20:38  Completed with 1 error and 0 warnings:
22:20:38  
22:20:38    Database Error in model foo (models/marts/foo.sql)
  query was empty
22:20:38  
22:20:38  Done. PASS=0 WARN=0 ERROR=1 SKIP=0 TOTAL=1
...

Convert the hook into a list of strings will fix the issue:

-- models/foo.sql
{{ config(pre_hook=["{{ do_thing() }}", "{{ do_another_thing() }}"]) }}

select 1 id

$ dbt --debug run
22:22:50  Began running node model.my_dbt_project.foo
22:22:50  1 of 1 START sql table model public.foo ........................................ [RUN]
22:22:50  Re-using an available connection from the pool (formerly list_dev_public, now model.my_dbt_project.foo)
22:22:50  Began compiling node model.my_dbt_project.foo
22:22:50  Writing injected SQL for node "model.my_dbt_project.foo"
22:22:50  Timing info for model.my_dbt_project.foo (compile): 11:22:50.880053 => 11:22:50.887606
22:22:50  Began executing node model.my_dbt_project.foo
22:22:50  Using redshift connection "model.my_dbt_project.foo"
22:22:50  On model.my_dbt_project.foo: BEGIN
22:22:50  Opening a new connection, currently in state closed
22:22:50  Redshift adapter: Establishing connection using ssl with `sslmode` set to 'prefer'.To connect without ssl, set `sslmode` to 'disable'.
22:22:50  Redshift adapter: Connecting to redshift with username/password based auth...
22:22:52  SQL status: SUCCESS in 2.0 seconds
22:22:52  Using redshift connection "model.my_dbt_project.foo"
22:22:52  On model.my_dbt_project.foo: /* {"app": "dbt", "dbt_version": "1.6.6", "profile_name": "all", "target_name": "rs", "node_id": "model.my_dbt_project.foo"} */

        begin;
22:22:53  SQL status: SUCCESS in 0.0 seconds
22:22:53  Using redshift connection "model.my_dbt_project.foo"
22:22:53  On model.my_dbt_project.foo: select 1 id;
22:22:53  SQL status: SUCCESS in 0.0 seconds
22:22:53  Using redshift connection "model.my_dbt_project.foo"
22:22:53  On model.my_dbt_project.foo: commit;
22:22:53  SQL status: SUCCESS in 0.0 seconds
22:22:53  Using redshift connection "model.my_dbt_project.foo"
22:22:53  On model.my_dbt_project.foo: begin;
22:22:54  SQL status: SUCCESS in 0.0 seconds
22:22:54  Using redshift connection "model.my_dbt_project.foo"
22:22:54  On model.my_dbt_project.foo: select 2 id;
22:22:54  SQL status: SUCCESS in 0.0 seconds
22:22:54  Using redshift connection "model.my_dbt_project.foo"
22:22:54  On model.my_dbt_project.foo: commit;
22:22:55  SQL status: SUCCESS in 0.0 seconds
22:22:55  Using redshift connection "model.my_dbt_project.foo"
22:22:55  On model.my_dbt_project.foo: /* {"app": "dbt", "dbt_version": "1.6.6", "profile_name": "all", "target_name": "rs", "node_id": "model.my_dbt_project.foo"} */

        begin;
22:22:55  SQL status: SUCCESS in 0.0 seconds
22:22:55  Using redshift connection "model.my_dbt_project.foo"
22:22:55  On model.my_dbt_project.foo: select 1 id;
22:22:55  SQL status: SUCCESS in 0.0 seconds
22:22:55  Using redshift connection "model.my_dbt_project.foo"
22:22:55  On model.my_dbt_project.foo: commit;
22:22:55  SQL status: SUCCESS in 0.0 seconds
22:22:55  Using redshift connection "model.my_dbt_project.foo"
22:22:55  On model.my_dbt_project.foo: begin;
22:22:55  SQL status: SUCCESS in 0.0 seconds
22:22:55  Using redshift connection "model.my_dbt_project.foo"
22:22:55  On model.my_dbt_project.foo: select 2 id;
22:22:56  SQL status: SUCCESS in 0.0 seconds
22:22:56  Using redshift connection "model.my_dbt_project.foo"
22:22:56  On model.my_dbt_project.foo: commit;
22:22:56  SQL status: SUCCESS in 0.0 seconds
22:22:56  Writing runtime sql for node "model.my_dbt_project.foo"
22:22:56  Using redshift connection "model.my_dbt_project.foo"
22:22:56  On model.my_dbt_project.foo: /* {"app": "dbt", "dbt_version": "1.6.6", "profile_name": "all", "target_name": "rs", "node_id": "model.my_dbt_project.foo"} */

  
    

  create  table
    "dev"."public"."foo__dbt_tmp"
    
    
    
  as (
    

select 1 id
  );
22:22:57  SQL status: SUCCESS in 2.0 seconds
22:22:57  Using redshift connection "model.my_dbt_project.foo"
22:22:57  On model.my_dbt_project.foo: /* {"app": "dbt", "dbt_version": "1.6.6", "profile_name": "all", "target_name": "rs", "node_id": "model.my_dbt_project.foo"} */
alter table "dev"."public"."foo" rename to "foo__dbt_backup"
22:23:00  SQL status: SUCCESS in 3.0 seconds
22:23:00  Using redshift connection "model.my_dbt_project.foo"
22:23:00  On model.my_dbt_project.foo: /* {"app": "dbt", "dbt_version": "1.6.6", "profile_name": "all", "target_name": "rs", "node_id": "model.my_dbt_project.foo"} */
alter table "dev"."public"."foo__dbt_tmp" rename to "foo"
22:23:01  SQL status: SUCCESS in 1.0 seconds
22:23:02  On model.my_dbt_project.foo: COMMIT
22:23:02  Using redshift connection "model.my_dbt_project.foo"
22:23:02  On model.my_dbt_project.foo: COMMIT
22:23:02  SQL status: SUCCESS in 0.0 seconds
22:23:02  Using redshift connection "model.my_dbt_project.foo"
22:23:02  On model.my_dbt_project.foo: BEGIN
22:23:02  SQL status: SUCCESS in 0.0 seconds
22:23:02  Using redshift connection "model.my_dbt_project.foo"
22:23:02  On model.my_dbt_project.foo: /* {"app": "dbt", "dbt_version": "1.6.6", "profile_name": "all", "target_name": "rs", "node_id": "model.my_dbt_project.foo"} */
drop table if exists "dev"."public"."foo__dbt_backup" cascade
22:23:03  SQL status: SUCCESS in 0.0 seconds
22:23:03  On model.my_dbt_project.foo: COMMIT
22:23:03  Using redshift connection "model.my_dbt_project.foo"
22:23:03  On model.my_dbt_project.foo: COMMIT
22:23:03  SQL status: SUCCESS in 1.0 seconds
22:23:03  Using redshift connection "model.my_dbt_project.foo"
22:23:03  On model.my_dbt_project.foo: BEGIN
22:23:04  SQL status: SUCCESS in 0.0 seconds
22:23:04  Timing info for model.my_dbt_project.foo (execute): 11:22:50.889735 => 11:23:04.042058
22:23:04  On model.my_dbt_project.foo: ROLLBACK
22:23:04  On model.my_dbt_project.foo: Close
22:23:04  Sending event: {'category': 'dbt', 'action': 'run_model', 'label': 'c8eac612-6df4-4566-8c7a-fb72cb68fb35', 'context': [<snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x111dc7f10>]}
22:23:04  1 of 1 OK created sql table model public.foo ................................... [SUCCESS in 13.59s]
22:23:04  Finished running node model.my_dbt_project.foo
22:23:04  Using redshift connection "master"
22:23:04  On master: BEGIN
22:23:04  Opening a new connection, currently in state closed
22:23:04  Redshift adapter: Establishing connection using ssl with `sslmode` set to 'prefer'.To connect without ssl, set `sslmode` to 'disable'.
22:23:04  Redshift adapter: Connecting to redshift with username/password based auth...
22:23:06  SQL status: SUCCESS in 2.0 seconds
22:23:06  On master: COMMIT
22:23:06  Using redshift connection "master"
22:23:06  On master: COMMIT
22:23:06  SQL status: SUCCESS in 1.0 seconds
22:23:06  On master: Close
22:23:06  Connection 'master' was properly closed.
22:23:06  Connection 'model.my_dbt_project.foo' was properly closed.
22:23:06  
22:23:06  Finished running 1 table model in 0 hours 0 minutes and 24.20 seconds (24.20s).
22:23:06  Command end result
22:23:06  
22:23:06  Completed successfully

Personally though, my recommendation is to not have begin;, commit; keywords in the macro if we can help it and use the before_begin / after_commit helpers instead (https://docs.getdbt.com/reference/resource-configs/pre-hook-post-hook#transaction-behavior).

-- macros/do_thing.sql
{% macro do_thing() %}
    select 1 id;
    select 2 id;
{% endmacro %}

-- macros/do_another_thing.sql
{% macro do_another_thing() %}
    select 1 id;
    select 2 id;
{% endmacro %}

-- models/foo.sql
{{ 
    config(
        pre_hook=[
            before_begin("{{ do_thing() }}"), 
            before_begin("{{ do_another_thing()}}")
        ]
    ) 
}}

select 1 id

The way I removed the pair of begin;commit; keywords from each macros leads this to not be 100% the same but that's left as an exercise to the user to split it into 4 macros if they want to.

$ dbt --debug run
...
22:29:27  1 of 1 START sql table model public.foo ........................................ [RUN]
22:29:27  Re-using an available connection from the pool (formerly list_dev_public, now model.my_dbt_project.foo)
22:29:27  Began compiling node model.my_dbt_project.foo
22:29:27  Writing injected SQL for node "model.my_dbt_project.foo"
22:29:27  Timing info for model.my_dbt_project.foo (compile): 11:29:27.431571 => 11:29:27.436701
22:29:27  Began executing node model.my_dbt_project.foo
22:29:27  Using redshift connection "model.my_dbt_project.foo"
22:29:27  On model.my_dbt_project.foo: /* {"app": "dbt", "dbt_version": "1.6.6", "profile_name": "all", "target_name": "rs", "node_id": "model.my_dbt_project.foo"} */

        commit;
22:29:27  Opening a new connection, currently in state closed
22:29:27  Redshift adapter: Establishing connection using ssl with `sslmode` set to 'prefer'.To connect without ssl, set `sslmode` to 'disable'.
22:29:27  Redshift adapter: Connecting to redshift with username/password based auth...
22:29:29  SQL status: SUCCESS in 2.0 seconds
22:29:29  Using redshift connection "model.my_dbt_project.foo"
22:29:29  On model.my_dbt_project.foo: /* {"app": "dbt", "dbt_version": "1.6.6", "profile_name": "all", "target_name": "rs", "node_id": "model.my_dbt_project.foo"} */

        select 1 id;
22:29:29  SQL status: SUCCESS in 0.0 seconds
22:29:29  Using redshift connection "model.my_dbt_project.foo"
22:29:29  On model.my_dbt_project.foo: select 2 id;
22:29:30  SQL status: SUCCESS in 0.0 seconds
22:29:30  Using redshift connection "model.my_dbt_project.foo"
22:29:30  On model.my_dbt_project.foo: /* {"app": "dbt", "dbt_version": "1.6.6", "profile_name": "all", "target_name": "rs", "node_id": "model.my_dbt_project.foo"} */

        select 1 id;
22:29:30  SQL status: SUCCESS in 0.0 seconds
22:29:30  Using redshift connection "model.my_dbt_project.foo"
22:29:30  On model.my_dbt_project.foo: select 2 id;
22:29:30  SQL status: SUCCESS in 0.0 seconds
22:29:30  Writing runtime sql for node "model.my_dbt_project.foo"
22:29:30  Using redshift connection "model.my_dbt_project.foo"
22:29:30  On model.my_dbt_project.foo: BEGIN
22:29:30  SQL status: SUCCESS in 0.0 seconds
22:29:30  Using redshift connection "model.my_dbt_project.foo"
22:29:30  On model.my_dbt_project.foo: /* {"app": "dbt", "dbt_version": "1.6.6", "profile_name": "all", "target_name": "rs", "node_id": "model.my_dbt_project.foo"} */

  
    

  create  table
    "dev"."public"."foo__dbt_tmp"
    
    
    
  as (
    

select 1 id
  );
22:29:31  SQL status: SUCCESS in 0.0 seconds
22:29:31  Using redshift connection "model.my_dbt_project.foo"
22:29:31  On model.my_dbt_project.foo: /* {"app": "dbt", "dbt_version": "1.6.6", "profile_name": "all", "target_name": "rs", "node_id": "model.my_dbt_project.foo"} */
alter table "dev"."public"."foo" rename to "foo__dbt_backup"
22:29:33  SQL status: SUCCESS in 2.0 seconds
22:29:33  Using redshift connection "model.my_dbt_project.foo"
22:29:33  On model.my_dbt_project.foo: /* {"app": "dbt", "dbt_version": "1.6.6", "profile_name": "all", "target_name": "rs", "node_id": "model.my_dbt_project.foo"} */
alter table "dev"."public"."foo__dbt_tmp" rename to "foo"
22:29:33  SQL status: SUCCESS in 1.0 seconds
22:29:33  On model.my_dbt_project.foo: COMMIT
22:29:33  Using redshift connection "model.my_dbt_project.foo"
22:29:33  On model.my_dbt_project.foo: COMMIT
22:29:34  SQL status: SUCCESS in 1.0 seconds
22:29:34  Using redshift connection "model.my_dbt_project.foo"
22:29:34  On model.my_dbt_project.foo: BEGIN
22:29:35  SQL status: SUCCESS in 0.0 seconds
22:29:35  Using redshift connection "model.my_dbt_project.foo"
22:29:35  On model.my_dbt_project.foo: /* {"app": "dbt", "dbt_version": "1.6.6", "profile_name": "all", "target_name": "rs", "node_id": "model.my_dbt_project.foo"} */
drop table if exists "dev"."public"."foo__dbt_backup" cascade
22:29:35  SQL status: SUCCESS in 0.0 seconds
22:29:35  On model.my_dbt_project.foo: COMMIT
22:29:35  Using redshift connection "model.my_dbt_project.foo"
22:29:35  On model.my_dbt_project.foo: COMMIT
22:29:36  SQL status: SUCCESS in 1.0 seconds
22:29:36  Using redshift connection "model.my_dbt_project.foo"
22:29:36  On model.my_dbt_project.foo: BEGIN
22:29:36  SQL status: SUCCESS in 0.0 seconds
22:29:36  Timing info for model.my_dbt_project.foo (execute): 11:29:27.438485 => 11:29:36.646265
22:29:36  On model.my_dbt_project.foo: ROLLBACK
22:29:37  On model.my_dbt_project.foo: Close
22:29:37  Sending event: {'category': 'dbt', 'action': 'run_model', 'label': '3f1c7282-f792-40c3-a57d-2996a7c3907b', 'context': [<snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x1124b8cd0>]}
22:29:37  1 of 1 OK created sql table model public.foo ................................... [SUCCESS in 9.70s]
22:29:37  Finished running node model.my_dbt_project.foo
22:29:37  Using redshift connection "master"
22:29:37  On master: BEGIN
22:29:37  Opening a new connection, currently in state closed
22:29:37  Redshift adapter: Establishing connection using ssl with `sslmode` set to 'prefer'.To connect without ssl, set `sslmode` to 'disable'.
22:29:37  Redshift adapter: Connecting to redshift with username/password based auth...
22:29:38  SQL status: SUCCESS in 2.0 seconds
22:29:38  On master: COMMIT
22:29:38  Using redshift connection "master"
22:29:38  On master: COMMIT
22:29:39  SQL status: SUCCESS in 0.0 seconds
22:29:39  On master: Close
22:29:39  Connection 'master' was properly closed.
22:29:39  Connection 'model.my_dbt_project.foo' was properly closed.
22:29:39  
22:29:39  Finished running 1 table model in 0 hours 0 minutes and 20.14 seconds (20.14s).
22:29:39  Command end result
22:29:39  
22:29:39  Completed successfully

lsabreu96 added bug Something isn't working triage labels Jul 31, 2023

github-actions bot changed the title ~~[Bug] Query was empty error in dbt-redshift==1.5.8 with dbt-core==1.5.4~~ [ADAP-739] [Bug] Query was empty error in dbt-redshift==1.5.8 with dbt-core==1.5.4 Jul 31, 2023

dataders assigned dbeatty10 Aug 3, 2023

dbeatty10 removed their assignment Aug 3, 2023

dbeatty10 added awaiting_response and removed triage labels Aug 10, 2023

github-actions bot added triage and removed awaiting_response labels Aug 10, 2023

dbeatty10 added awaiting_response and removed triage labels Aug 10, 2023

lsabreu96 closed this as completed Aug 31, 2023

github-actions bot added triage and removed awaiting_response labels Aug 31, 2023

dbeatty10 removed the triage label Sep 6, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[ADAP-739] [Bug] Query was empty error in dbt-redshift==1.5.8 with dbt-core==1.5.4 #561

[ADAP-739] [Bug] Query was empty error in dbt-redshift==1.5.8 with dbt-core==1.5.4 #561

lsabreu96 commented Jul 31, 2023 •

edited

Loading

dataders commented Aug 3, 2023

lsabreu96 commented Aug 3, 2023 •

edited

Loading

lsabreu96 commented Aug 3, 2023

lsabreu96 commented Aug 3, 2023 •

edited

Loading

lsabreu96 commented Aug 3, 2023

dbeatty10 commented Aug 10, 2023

Project setup and commands

lsabreu96 commented Aug 10, 2023 •

edited

Loading

lsabreu96 commented Aug 31, 2023

jeremyyeo commented Nov 5, 2023 •

edited

Loading

[ADAP-739] [Bug] Query was empty error in dbt-redshift==1.5.8 with dbt-core==1.5.4 #561

[ADAP-739] [Bug] Query was empty error in dbt-redshift==1.5.8 with dbt-core==1.5.4 #561

Comments

lsabreu96 commented Jul 31, 2023 • edited Loading

Is this a new bug in dbt-redshift?

Current Behavior

Expected Behavior

Steps To Reproduce

Relevant log output

Environment

Additional Context

dataders commented Aug 3, 2023

lsabreu96 commented Aug 3, 2023 • edited Loading

lsabreu96 commented Aug 3, 2023

lsabreu96 commented Aug 3, 2023 • edited Loading

lsabreu96 commented Aug 3, 2023

dbeatty10 commented Aug 10, 2023

Project setup and commands

lsabreu96 commented Aug 10, 2023 • edited Loading

lsabreu96 commented Aug 31, 2023

jeremyyeo commented Nov 5, 2023 • edited Loading

lsabreu96 commented Jul 31, 2023 •

edited

Loading

lsabreu96 commented Aug 3, 2023 •

edited

Loading

lsabreu96 commented Aug 3, 2023 •

edited

Loading

lsabreu96 commented Aug 10, 2023 •

edited

Loading

jeremyyeo commented Nov 5, 2023 •

edited

Loading