Is there an existing issue for this?
- [x] I have searched the existing issues
Current Behavior
When i run dbt snapshot
my snapshot model is run, but the cli never moves on to the following task. As far as i can tell all the snapshot work is done successfully (the snapshot table is appended to etc).
This happens both locally and on dbt cloud. Exact same behaviour.
Expected Behavior
I expect the cli to either successfully take me back to an empty prompt, or continue with the next command.
Steps To Reproduce
- Setup a snapshot model like this:
% snapshot snap__transaction_records_state %}
{{
config(
description='Snapshot of transaction records state for accounting automation project. Started 2022-02-21.',
target_database='transfer-galaxy',
target_schema='dbt_snapshots',
unique_key='tx_id',
strategy='check',
check_cols='all',
partition_by={'field': 'tx_date_day', 'data_type': 'date'},
)
}}
select
tx_id,
date(tx_time_cet) as tx_date_day,
tx_state_enum,
tx_state,
from
{{ ref('src_portal__transaction_records') }}
{% endsnapshot %}
- Run "dbt snapshot'
- Get terminal output like:
11:12:50 Running with dbt=1.0.3
11:12:50 Found 205 models, 100 tests, 1 snapshot, 13 analyses, 392 macros, 0 operations, 5 seed files, 80 sources, 1 exposure, 0 metrics
11:12:50
11:12:51 Concurrency: 16 threads (target='default')
11:12:51
11:12:51 1 of 1 START snapshot dbt_snapshots.snap__transaction_records_state............. [RUN]
Wait an eternity (until a timeout of some sort, in dbt cloud i think it's 13 hours), until the job is cancelled.
Relevant log output
Log output from dbt cloud for "dbt snapshot" here:
2022-03-10 11:12:50.561223 (MainThread): 11:12:50 Running with dbt=1.0.3
2022-03-10 11:12:50.561843 (MainThread): 11:12:50 running dbt with arguments Namespace(cls=<class 'dbt.task.snapshot.SnapshotTask'>, debug=None, defer=None, event_buffer_size=None, exclude=None, fail_fast=None, log_cache_events=False, log_format=None, partial_parse=None, printer_width=None, profile='user', profiles_dir='/tmp/jobs/47162168/.dbt', project_dir=None, record_timing_info=None, rpc_method='snapshot', select=None, selector_name=None, send_anonymous_usage_stats=None, single_threaded=False, state=None, static_parser=None, target='default', threads=None, use_colors=None, use_experimental_parser=None, vars='{}', version_check=None, warn_error=None, which='snapshot', write_json=None)
2022-03-10 11:12:50.562060 (MainThread): 11:12:50 Tracking: tracking
2022-03-10 11:12:50.571622 (MainThread): 11:12:50 Sending event: {'category': 'dbt', 'action': 'invocation', 'label': 'start', 'context': [<snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x7f49a8616a90>, <snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x7f49a8616850>, <snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x7f49a8616c70>]}
2022-03-10 11:12:50.701971 (MainThread): 11:12:50 Partial parsing enabled: 0 files deleted, 0 files added, 0 files changed.
2022-03-10 11:12:50.702302 (MainThread): 11:12:50 Partial parsing enabled, no changes found, skipping parsing
2022-03-10 11:12:50.723178 (MainThread): 11:12:50 Sending event: {'category': 'dbt', 'action': 'load_project', 'label': '35add917-e38d-4443-a411-d0171182a210', 'context': [<snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x7f4991fe4e50>]}
2022-03-10 11:12:50.951696 (MainThread): 11:12:50 Sending event: {'category': 'dbt', 'action': 'resource_counts', 'label': '35add917-e38d-4443-a411-d0171182a210', 'context': [<snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x7f49a8719e50>]}
2022-03-10 11:12:50.952118 (MainThread): 11:12:50 Found 205 models, 100 tests, 1 snapshot, 13 analyses, 392 macros, 0 operations, 5 seed files, 80 sources, 1 exposure, 0 metrics
2022-03-10 11:12:50.964288 (MainThread): 11:12:50
2022-03-10 11:12:50.964778 (MainThread): 11:12:50 Acquiring new bigquery connection "master"
2022-03-10 11:12:50.965712 (ThreadPoolExecutor-0_0): 11:12:50 Acquiring new bigquery connection "list_transfer-galaxy"
2022-03-10 11:12:50.966081 (ThreadPoolExecutor-0_0): 11:12:50 Opening a new connection, currently in state init
2022-03-10 11:12:51.221515 (ThreadPoolExecutor-1_0): 11:12:51 Acquiring new bigquery connection "list_transfer-galaxy_dbt_risk_scoring"
2022-03-10 11:12:51.222081 (ThreadPoolExecutor-1_1): 11:12:51 Acquiring new bigquery connection "list_transfer-galaxy_dbt_forecasting"
2022-03-10 11:12:51.222541 (ThreadPoolExecutor-1_0): 11:12:51 Opening a new connection, currently in state closed
2022-03-10 11:12:51.222941 (ThreadPoolExecutor-1_2): 11:12:51 Acquiring new bigquery connection "list_transfer-galaxy_dbt_staging_zendesk"
2022-03-10 11:12:51.223551 (ThreadPoolExecutor-1_3): 11:12:51 Acquiring new bigquery connection "list_transfer-galaxy_dbt_snapshots"
2022-03-10 11:12:51.223754 (ThreadPoolExecutor-1_1): 11:12:51 Opening a new connection, currently in state init
2022-03-10 11:12:51.224255 (ThreadPoolExecutor-1_4): 11:12:51 Acquiring new bigquery connection "list_transfer-galaxy_dbt_staging_airtable"
2022-03-10 11:12:51.224911 (ThreadPoolExecutor-1_5): 11:12:51 Acquiring new bigquery connection "list_transfer-galaxy_dbt_behavioural"
2022-03-10 11:12:51.225430 (ThreadPoolExecutor-1_6): 11:12:51 Acquiring new bigquery connection "list_transfer-galaxy_dbt_seeds"
2022-03-10 11:12:51.225943 (ThreadPoolExecutor-1_2): 11:12:51 Opening a new connection, currently in state init
2022-03-10 11:12:51.226308 (ThreadPoolExecutor-1_7): 11:12:51 Acquiring new bigquery connection "list_transfer-galaxy_dbt_referral"
2022-03-10 11:12:51.227004 (ThreadPoolExecutor-1_8): 11:12:51 Acquiring new bigquery connection "list_transfer-galaxy_dbt_playground"
2022-03-10 11:12:51.227548 (ThreadPoolExecutor-1_9): 11:12:51 Acquiring new bigquery connection "list_transfer-galaxy_dbt_staging"
2022-03-10 11:12:51.228091 (ThreadPoolExecutor-1_10): 11:12:51 Acquiring new bigquery connection "list_transfer-galaxy_dbt_staging_accounting"
2022-03-10 11:12:51.228691 (ThreadPoolExecutor-1_11): 11:12:51 Acquiring new bigquery connection "list_transfer-galaxy_dbt_accounting"
2022-03-10 11:12:51.229038 (ThreadPoolExecutor-1_3): 11:12:51 Opening a new connection, currently in state init
2022-03-10 11:12:51.229424 (ThreadPoolExecutor-1_12): 11:12:51 Acquiring new bigquery connection "list_transfer-galaxy_dbt_outgoing"
2022-03-10 11:12:51.230062 (ThreadPoolExecutor-1_13): 11:12:51 Acquiring new bigquery connection "list_transfer-galaxy_dbt_marts"
2022-03-10 11:12:51.230479 (ThreadPoolExecutor-1_4): 11:12:51 Opening a new connection, currently in state init
2022-03-10 11:12:51.230918 (ThreadPoolExecutor-1_14): 11:12:51 Acquiring new bigquery connection "list_transfer-galaxy_dbt_events"
2022-03-10 11:12:51.231544 (ThreadPoolExecutor-1_15): 11:12:51 Acquiring new bigquery connection "list_transfer-galaxy_dbt_intermediary"
2022-03-10 11:12:51.232549 (ThreadPoolExecutor-1_5): 11:12:51 Opening a new connection, currently in state init
2022-03-10 11:12:51.232995 (ThreadPoolExecutor-1_6): 11:12:51 Opening a new connection, currently in state init
2022-03-10 11:12:51.233441 (ThreadPoolExecutor-1_7): 11:12:51 Opening a new connection, currently in state init
2022-03-10 11:12:51.233739 (ThreadPoolExecutor-1_8): 11:12:51 Opening a new connection, currently in state init
2022-03-10 11:12:51.234178 (ThreadPoolExecutor-1_9): 11:12:51 Opening a new connection, currently in state init
2022-03-10 11:12:51.235224 (ThreadPoolExecutor-1_10): 11:12:51 Opening a new connection, currently in state init
2022-03-10 11:12:51.235596 (ThreadPoolExecutor-1_11): 11:12:51 Opening a new connection, currently in state init
2022-03-10 11:12:51.236978 (ThreadPoolExecutor-1_12): 11:12:51 Opening a new connection, currently in state init
2022-03-10 11:12:51.237314 (ThreadPoolExecutor-1_13): 11:12:51 Opening a new connection, currently in state init
2022-03-10 11:12:51.238763 (ThreadPoolExecutor-1_14): 11:12:51 Opening a new connection, currently in state init
2022-03-10 11:12:51.240000 (ThreadPoolExecutor-1_15): 11:12:51 Opening a new connection, currently in state init
2022-03-10 11:12:51.509916 (ThreadPoolExecutor-1_11): 11:12:51 Acquiring new bigquery connection "list_transfer-galaxy_dbt_staging_soluno"
2022-03-10 11:12:51.510480 (ThreadPoolExecutor-1_11): 11:12:51 Opening a new connection, currently in state closed
2022-03-10 11:12:51.664519 (MainThread): 11:12:51 Concurrency: 16 threads (target='default')
2022-03-10 11:12:51.664816 (MainThread): 11:12:51
2022-03-10 11:12:51.667539 (Thread-18): 11:12:51 Began running node snapshot.transfergalaxy.snap__transaction_records_state
2022-03-10 11:12:51.667922 (Thread-18): 11:12:51 1 of 1 START snapshot dbt_snapshots.snap__transaction_records_state............. [RUN]
2022-03-10 11:12:51.668325 (Thread-18): 11:12:51 Acquiring new bigquery connection "snapshot.transfergalaxy.snap__transaction_records_state"
2022-03-10 11:12:51.668513 (Thread-18): 11:12:51 Began compiling node snapshot.transfergalaxy.snap__transaction_records_state
2022-03-10 11:12:51.668694 (Thread-18): 11:12:51 Compiling snapshot.transfergalaxy.snap__transaction_records_state
2022-03-10 11:12:51.673363 (Thread-18): 11:12:51 finished collecting timing info
2022-03-10 11:12:51.673586 (Thread-18): 11:12:51 Began executing node snapshot.transfergalaxy.snap__transaction_records_state
2022-03-10 11:12:51.692717 (Thread-18): 11:12:51 Opening a new connection, currently in state closed
2022-03-10 11:12:51.923759 (Thread-18): 11:12:51 On snapshot.transfergalaxy.snap__transaction_records_state: /* {"app": "dbt", "dbt_version": "1.0.3", "profile_name": "user", "target_name": "default", "node_id": "snapshot.transfergalaxy.snap__transaction_records_state"} */
select CURRENT_TIMESTAMP() as snapshot_start
2022-03-10 11:12:52.774374 (Thread-18): 11:12:52 On snapshot.transfergalaxy.snap__transaction_records_state: /* {"app": "dbt", "dbt_version": "1.0.3", "profile_name": "user", "target_name": "default", "node_id": "snapshot.transfergalaxy.snap__transaction_records_state"} */
select * from (
select
tx_id,
date(tx_time_cet) as tx_date_day,
tx_state_enum,
tx_state,
from
`transfer-galaxy`.`dbt_staging`.`src_portal__transaction_records`
) as __dbt_sbq
where false
limit 0
2022-03-10 11:12:53.703297 (Thread-18): 11:12:53 On snapshot.transfergalaxy.snap__transaction_records_state: /* {"app": "dbt", "dbt_version": "1.0.3", "profile_name": "user", "target_name": "default", "node_id": "snapshot.transfergalaxy.snap__transaction_records_state"} */
select * from (
select * from `transfer-galaxy`.`dbt_snapshots`.`snap__transaction_records_state`
) as __dbt_sbq
where false
limit 0
2022-03-10 11:12:55.098683 (Thread-18): 11:12:55 On snapshot.transfergalaxy.snap__transaction_records_state: /* {"app": "dbt", "dbt_version": "1.0.3", "profile_name": "user", "target_name": "default", "node_id": "snapshot.transfergalaxy.snap__transaction_records_state"} */
create or replace table `transfer-galaxy`.`dbt_snapshots`.`snap__transaction_records_state__dbt_tmp`
partition by tx_date_day
OPTIONS(
expiration_timestamp=TIMESTAMP_ADD(CURRENT_TIMESTAMP(), INTERVAL 12 hour)
)
as (
with snapshot_query as (
select
tx_id,
date(tx_time_cet) as tx_date_day,
tx_state_enum,
tx_state,
from
`transfer-galaxy`.`dbt_staging`.`src_portal__transaction_records`
),
snapshotted_data as (
select *,
tx_id as dbt_unique_key
from `transfer-galaxy`.`dbt_snapshots`.`snap__transaction_records_state`
where dbt_valid_to is null
),
insertions_source_data as (
select
*,
tx_id as dbt_unique_key,
TIMESTAMP("2022-03-10 11:12:52.097775+00:00") as dbt_updated_at,
TIMESTAMP("2022-03-10 11:12:52.097775+00:00") as dbt_valid_from,
nullif(TIMESTAMP("2022-03-10 11:12:52.097775+00:00"), TIMESTAMP("2022-03-10 11:12:52.097775+00:00")) as dbt_valid_to,
to_hex(md5(concat(coalesce(cast(tx_id as string), ''), '|',coalesce(cast(TIMESTAMP("2022-03-10 11:12:52.097775+00:00") as string), '')))) as dbt_scd_id
from snapshot_query
),
updates_source_data as (
select
*,
tx_id as dbt_unique_key,
TIMESTAMP("2022-03-10 11:12:52.097775+00:00") as dbt_updated_at,
TIMESTAMP("2022-03-10 11:12:52.097775+00:00") as dbt_valid_from,
TIMESTAMP("2022-03-10 11:12:52.097775+00:00") as dbt_valid_to
from snapshot_query
),
insertions as (
select
'insert' as dbt_change_type,
source_data.*
from insertions_source_data as source_data
left outer join snapshotted_data on snapshotted_data.dbt_unique_key = source_data.dbt_unique_key
where snapshotted_data.dbt_unique_key is null
or (
snapshotted_data.dbt_unique_key is not null
and (
(snapshotted_data.tx_id != source_data.tx_id
or
(
((snapshotted_data.tx_id is null) and not (source_data.tx_id is null))
or
((not snapshotted_data.tx_id is null) and (source_data.tx_id is null))
) or snapshotted_data.tx_date_day != source_data.tx_date_day
or
(
((snapshotted_data.tx_date_day is null) and not (source_data.tx_date_day is null))
or
((not snapshotted_data.tx_date_day is null) and (source_data.tx_date_day is null))
) or snapshotted_data.tx_state_enum != source_data.tx_state_enum
or
(
((snapshotted_data.tx_state_enum is null) and not (source_data.tx_state_enum is null))
or
((not snapshotted_data.tx_state_enum is null) and (source_data.tx_state_enum is null))
) or snapshotted_data.tx_state != source_data.tx_state
or
(
((snapshotted_data.tx_state is null) and not (source_data.tx_state is null))
or
((not snapshotted_data.tx_state is null) and (source_data.tx_state is null))
))
)
)
),
updates as (
select
'update' as dbt_change_type,
source_data.*,
snapshotted_data.dbt_scd_id
from updates_source_data as source_data
join snapshotted_data on snapshotted_data.dbt_unique_key = source_data.dbt_unique_key
where (
(snapshotted_data.tx_id != source_data.tx_id
or
(
((snapshotted_data.tx_id is null) and not (source_data.tx_id is null))
or
((not snapshotted_data.tx_id is null) and (source_data.tx_id is null))
) or snapshotted_data.tx_date_day != source_data.tx_date_day
or
(
((snapshotted_data.tx_date_day is null) and not (source_data.tx_date_day is null))
or
((not snapshotted_data.tx_date_day is null) and (source_data.tx_date_day is null))
) or snapshotted_data.tx_state_enum != source_data.tx_state_enum
or
(
((snapshotted_data.tx_state_enum is null) and not (source_data.tx_state_enum is null))
or
((not snapshotted_data.tx_state_enum is null) and (source_data.tx_state_enum is null))
) or snapshotted_data.tx_state != source_data.tx_state
or
(
((snapshotted_data.tx_state is null) and not (source_data.tx_state is null))
or
((not snapshotted_data.tx_state is null) and (source_data.tx_state is null))
))
)
)
select * from insertions
union all
select * from updates
);
2022-03-10 11:13:00.608568 (Thread-18): 11:13:00 BigQuery adapter: Adding columns ([]) to table `transfer-galaxy`.`dbt_snapshots`.`snap__transaction_records_state`".
2022-03-10 11:13:01.249736 (Thread-18): 11:13:01 Writing runtime SQL for node "snapshot.transfergalaxy.snap__transaction_records_state"
2022-03-10 11:13:01.250481 (Thread-18): 11:13:01 On snapshot.transfergalaxy.snap__transaction_records_state: /* {"app": "dbt", "dbt_version": "1.0.3", "profile_name": "user", "target_name": "default", "node_id": "snapshot.transfergalaxy.snap__transaction_records_state"} */
merge into `transfer-galaxy`.`dbt_snapshots`.`snap__transaction_records_state` as DBT_INTERNAL_DEST
using `transfer-galaxy`.`dbt_snapshots`.`snap__transaction_records_state__dbt_tmp` as DBT_INTERNAL_SOURCE
on DBT_INTERNAL_SOURCE.dbt_scd_id = DBT_INTERNAL_DEST.dbt_scd_id
when matched
and DBT_INTERNAL_DEST.dbt_valid_to is null
and DBT_INTERNAL_SOURCE.dbt_change_type in ('update', 'delete')
then update
set dbt_valid_to = DBT_INTERNAL_SOURCE.dbt_valid_to
when not matched
and DBT_INTERNAL_SOURCE.dbt_change_type = 'insert'
then insert (`tx_id`, `tx_date_day`, `tx_state_enum`, `tx_state`, `dbt_updated_at`, `dbt_valid_from`, `dbt_valid_to`, `dbt_scd_id`)
values (`tx_id`, `tx_date_day`, `tx_state_enum`, `tx_state`, `dbt_updated_at`, `dbt_valid_from`, `dbt_valid_to`, `dbt_scd_id`)
2022-03-10 11:13:06.113359 (Thread-18): 11:13:06 On snapshot.transfergalaxy.snap__transaction_records_state: /* {"app": "dbt", "dbt_version": "1.0.3", "profile_name": "user", "target_name": "default", "node_id": "snapshot.transfergalaxy.snap__transaction_records_state"} */
drop table if exists `transfer-galaxy`.`dbt_snapshots`.`snap__transaction_records_state__dbt_tmp`
2022-03-10 11:13:06.726671 (Thread-18): 11:13:06 finished collecting timing info
2022-03-10 11:13:06.727242 (Thread-18): 11:13:06 Sending event: {'category': 'dbt', 'action': 'run_model', 'label': '35add917-e38d-4443-a411-d0171182a210', 'context': [<snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x7f499065b280>]}
2022-03-10 14:11:42.039645 (MainThread): 14:11:42 [33mThe bigquery adapter does not support query cancellation. Some queries may still be running![0m
2022-03-10 14:11:42.040546 (MainThread): 14:11:42
2022-03-10 14:11:42.040856 (MainThread): 14:11:42 [33mExited because of keyboard interrupt.[0m
2022-03-10 14:11:42.041085 (MainThread): 14:11:42
2022-03-10 14:11:42.041310 (MainThread): 14:11:42 Done. PASS=0 WARN=0 ERROR=0 SKIP=0 TOTAL=0
2022-03-10 14:11:42.041545 (MainThread): 14:11:42 Connection 'master' was properly closed.
2022-03-10 14:11:42.041723 (MainThread): 14:11:42 Connection 'list_transfer-galaxy_dbt_risk_scoring' was properly closed.
2022-03-10 14:11:42.041904 (MainThread): 14:11:42 Connection 'list_transfer-galaxy_dbt_forecasting' was properly closed.
2022-03-10 14:11:42.042059 (MainThread): 14:11:42 Connection 'list_transfer-galaxy_dbt_staging_zendesk' was properly closed.
2022-03-10 14:11:42.042208 (MainThread): 14:11:42 Connection 'list_transfer-galaxy_dbt_snapshots' was properly closed.
2022-03-10 14:11:42.042409 (MainThread): 14:11:42 Connection 'list_transfer-galaxy_dbt_staging_airtable' was properly closed.
2022-03-10 14:11:42.042577 (MainThread): 14:11:42 Connection 'list_transfer-galaxy_dbt_behavioural' was properly closed.
2022-03-10 14:11:42.042729 (MainThread): 14:11:42 Connection 'list_transfer-galaxy_dbt_seeds' was properly closed.
2022-03-10 14:11:42.042878 (MainThread): 14:11:42 Connection 'list_transfer-galaxy_dbt_referral' was properly closed.
2022-03-10 14:11:42.043024 (MainThread): 14:11:42 Connection 'list_transfer-galaxy_dbt_playground' was properly closed.
2022-03-10 14:11:42.043170 (MainThread): 14:11:42 Connection 'list_transfer-galaxy_dbt_staging' was properly closed.
2022-03-10 14:11:42.043315 (MainThread): 14:11:42 Connection 'list_transfer-galaxy_dbt_staging_accounting' was properly closed.
2022-03-10 14:11:42.043459 (MainThread): 14:11:42 Connection 'snapshot.transfergalaxy.snap__transaction_records_state' was properly closed.
2022-03-10 14:11:42.043603 (MainThread): 14:11:42 Connection 'list_transfer-galaxy_dbt_outgoing' was properly closed.
2022-03-10 14:11:42.043746 (MainThread): 14:11:42 Connection 'list_transfer-galaxy_dbt_marts' was properly closed.
2022-03-10 14:11:42.043890 (MainThread): 14:11:42 Connection 'list_transfer-galaxy_dbt_events' was properly closed.
2022-03-10 14:11:42.044032 (MainThread): 14:11:42 Connection 'list_transfer-galaxy_dbt_intermediary' was properly closed.
2022-03-10 14:11:42.044218 (MainThread): 14:11:42 Flushing usage events
2022-03-10 14:11:42.065240 (MainThread):
Environment
- OS: macOS Big Sur version 11.1
- Python: 3.7.9
- dbt: 1.0
What database are you using dbt with?
bigquery
Additional Context
Snapshot model code:
`{% snapshot snap__transaction_records_state %}
{{
config(
description='Snapshot of transaction records state for accounting automation project. Started 2022-02-21.',
target_database='transfer-galaxy',
target_schema='dbt_snapshots',
unique_key='tx_id',
strategy='check',
check_cols='all',
partition_by={'field': 'tx_date_day', 'data_type': 'date'},
)
}}
select
tx_id,
date(tx_time_cet) as tx_date_day,
tx_state_enum,
tx_state,
from
{{ ref('src_portal__transaction_records') }}
{% endsnapshot %}
`
bug Team:Execution