You signed in with another tab or window. Reload to refresh your session.You signed out in another tab or window. Reload to refresh your session.You switched accounts on another tab or window. Reload to refresh your session.Dismiss alert
I have searched the existing issues, and I could not find an existing issue for this bug
Current Behavior
When we CTRL+C a running dbt process - dbt emits CANCEL for the last-ish ran model for each thread even if those models ran successfully. This causes some user confusion.
Expected Behavior
Don't emit CANCEL in the console logs unless necessary.
-- models/a.sqlselect pg_sleep(10)::textas c
-- models/b.sqlselect pg_sleep(10)::textas c
-- models/c.sqlselect pg_sleep(10)::textas c
-- models/d.sqlselect pg_sleep(10)::textas c
-- models/e.sqlselect pg_sleep(10)::textas c
Run with 2 threads, then cancel (CTRL+C) as we see model e starting:
$ dbt run --threads 2
23:38:51 Running with dbt=1.8.6
23:38:51 Registered adapter: postgres=1.8.2
23:38:51 Unable to do partial parsing because of a version mismatch
23:38:52 Found 5 models, 418 macros
23:38:52
23:38:52 Concurrency: 2 threads (target='pg')
23:38:52
23:38:52 1 of 5 START sql table model public.a .......................................... [RUN]
23:38:52 2 of 5 START sql table model public.b .......................................... [RUN]
23:39:02 1 of 5 OK created sql table model public.a ..................................... [SELECT 1 in 10.10s]
23:39:02 2 of 5 OK created sql table model public.b ..................................... [SELECT 1 in 10.10s]
23:39:02 3 of 5 START sql table model public.c .......................................... [RUN]
23:39:02 4 of 5 START sql table model public.d .......................................... [RUN]
23:39:12 3 of 5 OK created sql table model public.c ..................................... [SELECT 1 in 10.07s]
23:39:12 4 of 5 OK created sql table model public.d ..................................... [SELECT 1 in 10.07s]
23:39:12 5 of 5 START sql table model public.e .......................................... [RUN]
^C23:39:13 CANCEL query model.my_dbt_project.e ............................................ [CANCEL]
23:39:13 CANCEL query model.my_dbt_project.d ............................................ [CANCEL]
23:39:13 5 of 5 ERROR creating sql table model public.e ................................. [ERROR in 0.69s]
23:39:13
23:39:13 Exited because of keyboard interrupt
23:39:13
23:39:13 Done. PASS=4 WARN=0 ERROR=0 SKIP=0 TOTAL=4
23:39:13
23:39:13 Finished running 4 table models in 0 hours 0 minutes and 21.01 seconds (21.01s).
23:39:13 Encountered an error:
23:39:13 Traceback (most recent call last):
File "/Users/jeremy/git/dbt-basic/venv_dbt_1.8.latest/lib/python3.11/site-packages/dbt/cli/requires.py", line 138, in wrapper
result, success = func(*args, **kwargs)
^^^^^^^^^^^^^^^^^^^^^
File "/Users/jeremy/git/dbt-basic/venv_dbt_1.8.latest/lib/python3.11/site-packages/dbt/cli/requires.py", line 101, in wrapper
return func(*args, **kwargs)
^^^^^^^^^^^^^^^^^^^^^
File "/Users/jeremy/git/dbt-basic/venv_dbt_1.8.latest/lib/python3.11/site-packages/dbt/cli/requires.py", line 218, in wrapper
return func(*args, **kwargs)
^^^^^^^^^^^^^^^^^^^^^
File "/Users/jeremy/git/dbt-basic/venv_dbt_1.8.latest/lib/python3.11/site-packages/dbt/cli/requires.py", line 247, in wrapper
return func(*args, **kwargs)
^^^^^^^^^^^^^^^^^^^^^
File "/Users/jeremy/git/dbt-basic/venv_dbt_1.8.latest/lib/python3.11/site-packages/dbt/cli/requires.py", line 294, in wrapper
return func(*args, **kwargs)
^^^^^^^^^^^^^^^^^^^^^
File "/Users/jeremy/git/dbt-basic/venv_dbt_1.8.latest/lib/python3.11/site-packages/dbt/cli/requires.py", line 332, in wrapper
return func(*args, **kwargs)
^^^^^^^^^^^^^^^^^^^^^
File "/Users/jeremy/git/dbt-basic/venv_dbt_1.8.latest/lib/python3.11/site-packages/dbt/cli/main.py", line 569, in run
results = task.run()
^^^^^^^^^^
File "/Users/jeremy/git/dbt-basic/venv_dbt_1.8.latest/lib/python3.11/site-packages/dbt/task/runnable.py", line 526, in run
result = self.execute_with_hooks(selected_uids)
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/Users/jeremy/git/dbt-basic/venv_dbt_1.8.latest/lib/python3.11/site-packages/dbt/task/runnable.py", line 487, in execute_with_hooks
res = self.execute_nodes()
^^^^^^^^^^^^^^^^^^^^
File "/Users/jeremy/git/dbt-basic/venv_dbt_1.8.latest/lib/python3.11/site-packages/dbt/task/runnable.py", line 397, in execute_nodes
self.run_queue(pool)
File "/Users/jeremy/git/dbt-basic/venv_dbt_1.8.latest/lib/python3.11/site-packages/dbt/task/runnable.py", line 315, in run_queue
self.job_queue.join()
File "/Users/jeremy/git/dbt-basic/venv_dbt_1.8.latest/lib/python3.11/site-packages/dbt/graph/queue.py", line 198, in join
self.inner.join()
File "/Users/jeremy/.pyenv/versions/3.11.9/lib/python3.11/queue.py", line 90, in join
self.all_tasks_done.wait()
File "/Users/jeremy/.pyenv/versions/3.11.9/lib/python3.11/threading.py", line 327, inwaitwaiter.acquire()
KeyboardInterrupt
^ d shows as both CANCEL and OK:
23:39:12 4 of 5 OK created sql table model public.d ..................................... [SELECT 1 in 10.07s]
23:39:13 CANCEL query model.my_dbt_project.d ............................................ [CANCEL]
With many threads and models, this can be confusing to some users.
Relevant log output
============================== 11:38:51.754797 | d2feb866-1233-45d0-b388-4701e02bebcb ==============================
�[0m11:38:51.754797 [info ] [MainThread]: Running with dbt=1.8.6
�[0m11:38:51.755087 [debug] [MainThread]: running dbt with arguments {'printer_width': '80', 'indirect_selection': 'eager', 'log_cache_events': 'False', 'write_json': 'True', 'partial_parse': 'True', 'cache_selected_only': 'False', 'profiles_dir': '/Users/jeremy/.dbt', 'debug': 'False', 'fail_fast': 'False', 'log_path': '/Users/jeremy/git/dbt-basic/logs', 'version_check': 'True', 'warn_error': 'None', 'use_colors': 'True', 'use_experimental_parser': 'False', 'empty': 'False', 'quiet': 'False', 'no_print': 'None', 'log_format': 'default', 'static_parser': 'True', 'warn_error_options': 'WarnErrorOptions(include=[], exclude=[])', 'invocation_command': 'dbt run --threads 2', 'target_path': 'None', 'introspect': 'True', 'send_anonymous_usage_stats': 'True'}
�[0m11:38:51.834410 [debug] [MainThread]: Sending event: {'category': 'dbt', 'action': 'project_id', 'label': 'd2feb866-1233-45d0-b388-4701e02bebcb', 'context': [<snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x10a4b9150>]}
�[0m11:38:51.855408 [debug] [MainThread]: Sending event: {'category': 'dbt', 'action': 'adapter_info', 'label': 'd2feb866-1233-45d0-b388-4701e02bebcb', 'context': [<snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x106f65550>]}
�[0m11:38:51.855877 [info ] [MainThread]: Registered adapter: postgres=1.8.2
�[0m11:38:51.863756 [debug] [MainThread]: checksum: 2f2fb10c73cafe3e79aa104295a8244291492b32b5598ce46af770f7d0bd5194, vars: {}, profile: , target: , version: 1.8.6
�[0m11:38:51.891412 [info ] [MainThread]: Unable to do partial parsing because of a version mismatch
�[0m11:38:51.891733 [debug] [MainThread]: Sending event: {'category': 'dbt', 'action': 'partial_parser', 'label': 'd2feb866-1233-45d0-b388-4701e02bebcb', 'context': [<snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x10835bdd0>]}
�[0m11:38:52.327774 [debug] [MainThread]: Sending event: {'category': 'dbt', 'action': 'load_project', 'label': 'd2feb866-1233-45d0-b388-4701e02bebcb', 'context': [<snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x10a62b510>]}
�[0m11:38:52.362450 [debug] [MainThread]: Sending event: {'category': 'dbt', 'action': 'resource_counts', 'label': 'd2feb866-1233-45d0-b388-4701e02bebcb', 'context': [<snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x10a527010>]}
�[0m11:38:52.362809 [info ] [MainThread]: Found 5 models, 418 macros
�[0m11:38:52.362978 [debug] [MainThread]: Sending event: {'category': 'dbt', 'action': 'runnable_timing', 'label': 'd2feb866-1233-45d0-b388-4701e02bebcb', 'context': [<snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x109bb12d0>]}
�[0m11:38:52.363860 [info ] [MainThread]:
�[0m11:38:52.364183 [debug] [MainThread]: Acquiring new postgres connection 'master'
�[0m11:38:52.366002 [debug] [ThreadPool]: Acquiring new postgres connection 'list_postgres'
�[0m11:38:52.416156 [debug] [ThreadPool]: Using postgres connection "list_postgres"
�[0m11:38:52.416361 [debug] [ThreadPool]: On list_postgres: /* {"app": "dbt", "dbt_version": "1.8.6", "profile_name": "all", "target_name": "pg", "connection_name": "list_postgres"} */
select distinct nspname from pg_namespace
�[0m11:38:52.416495 [debug] [ThreadPool]: Opening a new connection, currently in state init
�[0m11:38:52.440258 [debug] [ThreadPool]: SQL status: SELECT 26 in 0.024 seconds
�[0m11:38:52.440880 [debug] [ThreadPool]: On list_postgres: Close
�[0m11:38:52.441495 [debug] [ThreadPool]: Re-using an available connection from the pool (formerly list_postgres, now list_postgres_public)
�[0m11:38:52.444055 [debug] [ThreadPool]: Using postgres connection "list_postgres_public"
�[0m11:38:52.444212 [debug] [ThreadPool]: On list_postgres_public: BEGIN
�[0m11:38:52.444343 [debug] [ThreadPool]: Opening a new connection, currently in state closed
�[0m11:38:52.452553 [debug] [ThreadPool]: SQL status: BEGIN in 0.008 seconds
�[0m11:38:52.452689 [debug] [ThreadPool]: Using postgres connection "list_postgres_public"
�[0m11:38:52.452829 [debug] [ThreadPool]: On list_postgres_public: /* {"app": "dbt", "dbt_version": "1.8.6", "profile_name": "all", "target_name": "pg", "connection_name": "list_postgres_public"} */
select
'postgres' as database,
tablename as name,
schemaname as schema,
'table' as type
from pg_tables
where schemaname ilike 'public'
union all
select
'postgres' as database,
viewname as name,
schemaname as schema,
'view' as type
from pg_views
where schemaname ilike 'public'
union all
select
'postgres' as database,
matviewname as name,
schemaname as schema,
'materialized_view' as type
from pg_matviews
where schemaname ilike 'public'
�[0m11:38:52.456225 [debug] [ThreadPool]: SQL status: SELECT 98 in 0.003 seconds
�[0m11:38:52.457438 [debug] [ThreadPool]: On list_postgres_public: ROLLBACK
�[0m11:38:52.457985 [debug] [ThreadPool]: On list_postgres_public: Close
�[0m11:38:52.464173 [debug] [MainThread]: Using postgres connection "master"
�[0m11:38:52.464340 [debug] [MainThread]: On master: BEGIN
�[0m11:38:52.464463 [debug] [MainThread]: Opening a new connection, currently in state init
�[0m11:38:52.471328 [debug] [MainThread]: SQL status: BEGIN in 0.007 seconds
�[0m11:38:52.471511 [debug] [MainThread]: Using postgres connection "master"
�[0m11:38:52.471692 [debug] [MainThread]: On master: /* {"app": "dbt", "dbt_version": "1.8.6", "profile_name": "all", "target_name": "pg", "connection_name": "master"} */
with relation as (
select
pg_rewrite.ev_class as class,
pg_rewrite.oid as id
from pg_rewrite
),
class as (
select
oid as id,
relname as name,
relnamespace as schema,
relkind as kind
from pg_class
),
dependency as (
select distinct
pg_depend.objid as id,
pg_depend.refobjid as ref
from pg_depend
),
schema as (
select
pg_namespace.oid as id,
pg_namespace.nspname as name
from pg_namespace
where nspname != 'information_schema' and nspname not like 'pg\_%'
),
referenced as (
select
relation.id AS id,
referenced_class.name ,
referenced_class.schema ,
referenced_class.kind
from relation
join class as referenced_class on relation.class=referenced_class.id
where referenced_class.kind in ('r', 'v', 'm')
),
relationships as (
select
referenced.name as referenced_name,
referenced.schema as referenced_schema_id,
dependent_class.name as dependent_name,
dependent_class.schema as dependent_schema_id,
referenced.kind as kind
from referenced
join dependency on referenced.id=dependency.id
join class as dependent_class on dependency.ref=dependent_class.id
where
(referenced.name != dependent_class.name or
referenced.schema != dependent_class.schema)
)
select
referenced_schema.name as referenced_schema,
relationships.referenced_name as referenced_name,
dependent_schema.name as dependent_schema,
relationships.dependent_name as dependent_name
from relationships
join schema as dependent_schema on relationships.dependent_schema_id=dependent_schema.id
join schema as referenced_schema on relationships.referenced_schema_id=referenced_schema.id
group by referenced_schema, referenced_name, dependent_schema, dependent_name
order by referenced_schema, referenced_name, dependent_schema, dependent_name;
�[0m11:38:52.498543 [debug] [MainThread]: SQL status: SELECT 47 in 0.027 seconds
�[0m11:38:52.502431 [debug] [MainThread]: Sending event: {'category': 'dbt', 'action': 'runnable_timing', 'label': 'd2feb866-1233-45d0-b388-4701e02bebcb', 'context': [<snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x10c0aaa90>]}
�[0m11:38:52.502662 [debug] [MainThread]: On master: ROLLBACK
�[0m11:38:52.503122 [debug] [MainThread]: Using postgres connection "master"
�[0m11:38:52.503252 [debug] [MainThread]: On master: BEGIN
�[0m11:38:52.503836 [debug] [MainThread]: SQL status: BEGIN in 0.000 seconds
�[0m11:38:52.503991 [debug] [MainThread]: On master: COMMIT
�[0m11:38:52.504122 [debug] [MainThread]: Using postgres connection "master"
�[0m11:38:52.504254 [debug] [MainThread]: On master: COMMIT
�[0m11:38:52.504548 [debug] [MainThread]: SQL status: COMMIT in 0.000 seconds
�[0m11:38:52.504686 [debug] [MainThread]: On master: Close
�[0m11:38:52.504890 [info ] [MainThread]: Concurrency: 2 threads (target='pg')
�[0m11:38:52.505057 [info ] [MainThread]:
�[0m11:38:52.506845 [debug] [Thread-1 (]: Began running node model.my_dbt_project.a
�[0m11:38:52.507030 [debug] [Thread-2 (]: Began running node model.my_dbt_project.b
�[0m11:38:52.507238 [info ] [Thread-1 (]: 1 of 5 START sql table model public.a .......................................... [RUN]
�[0m11:38:52.507557 [info ] [Thread-2 (]: 2 of 5 START sql table model public.b .......................................... [RUN]
�[0m11:38:52.507788 [debug] [Thread-1 (]: Re-using an available connection from the pool (formerly list_postgres_public, now model.my_dbt_project.a)
�[0m11:38:52.507988 [debug] [Thread-2 (]: Acquiring new postgres connection 'model.my_dbt_project.b'
�[0m11:38:52.508144 [debug] [Thread-1 (]: Began compiling node model.my_dbt_project.a
�[0m11:38:52.508298 [debug] [Thread-2 (]: Began compiling node model.my_dbt_project.b
�[0m11:38:52.511045 [debug] [Thread-1 (]: Writing injected SQL for node "model.my_dbt_project.a"
�[0m11:38:52.511835 [debug] [Thread-2 (]: Writing injected SQL for node "model.my_dbt_project.b"
�[0m11:38:52.512208 [debug] [Thread-2 (]: Began executing node model.my_dbt_project.b
�[0m11:38:52.512367 [debug] [Thread-1 (]: Began executing node model.my_dbt_project.a
�[0m11:38:52.530181 [debug] [Thread-2 (]: Writing runtime sql for node "model.my_dbt_project.b"
�[0m11:38:52.533099 [debug] [Thread-1 (]: Writing runtime sql for node "model.my_dbt_project.a"
�[0m11:38:52.533586 [debug] [Thread-1 (]: Using postgres connection "model.my_dbt_project.a"
�[0m11:38:52.533777 [debug] [Thread-2 (]: Using postgres connection "model.my_dbt_project.b"
�[0m11:38:52.533949 [debug] [Thread-1 (]: On model.my_dbt_project.a: BEGIN
�[0m11:38:52.534115 [debug] [Thread-2 (]: On model.my_dbt_project.b: BEGIN
�[0m11:38:52.534268 [debug] [Thread-1 (]: Opening a new connection, currently in state closed
�[0m11:38:52.534413 [debug] [Thread-2 (]: Opening a new connection, currently in state init
�[0m11:38:52.540768 [debug] [Thread-2 (]: SQL status: BEGIN in 0.006 seconds
�[0m11:38:52.540983 [debug] [Thread-2 (]: Using postgres connection "model.my_dbt_project.b"
�[0m11:38:52.541138 [debug] [Thread-2 (]: On model.my_dbt_project.b: /* {"app": "dbt", "dbt_version": "1.8.6", "profile_name": "all", "target_name": "pg", "node_id": "model.my_dbt_project.b"} */
create table "postgres"."public"."b__dbt_tmp"
as
(
select pg_sleep(10)::text as c
);
�[0m11:38:52.542933 [debug] [Thread-1 (]: SQL status: BEGIN in 0.009 seconds
�[0m11:38:52.543121 [debug] [Thread-1 (]: Using postgres connection "model.my_dbt_project.a"
�[0m11:38:52.543283 [debug] [Thread-1 (]: On model.my_dbt_project.a: /* {"app": "dbt", "dbt_version": "1.8.6", "profile_name": "all", "target_name": "pg", "node_id": "model.my_dbt_project.a"} */
create table "postgres"."public"."a__dbt_tmp"
as
(
select pg_sleep(10)::text as c
);
�[0m11:39:02.560431 [debug] [Thread-1 (]: SQL status: SELECT 1 in 10.017 seconds
�[0m11:39:02.561770 [debug] [Thread-2 (]: SQL status: SELECT 1 in 10.020 seconds
�[0m11:39:02.572660 [debug] [Thread-1 (]: Using postgres connection "model.my_dbt_project.a"
�[0m11:39:02.576296 [debug] [Thread-2 (]: Using postgres connection "model.my_dbt_project.b"
�[0m11:39:02.576619 [debug] [Thread-1 (]: On model.my_dbt_project.a: /* {"app": "dbt", "dbt_version": "1.8.6", "profile_name": "all", "target_name": "pg", "node_id": "model.my_dbt_project.a"} */
alter table "postgres"."public"."a" rename to "a__dbt_backup"
�[0m11:39:02.576809 [debug] [Thread-2 (]: On model.my_dbt_project.b: /* {"app": "dbt", "dbt_version": "1.8.6", "profile_name": "all", "target_name": "pg", "node_id": "model.my_dbt_project.b"} */
alter table "postgres"."public"."b" rename to "b__dbt_backup"
�[0m11:39:02.578848 [debug] [Thread-1 (]: SQL status: ALTER TABLE in 0.002 seconds
�[0m11:39:02.579206 [debug] [Thread-2 (]: SQL status: ALTER TABLE in 0.002 seconds
�[0m11:39:02.581758 [debug] [Thread-1 (]: Using postgres connection "model.my_dbt_project.a"
�[0m11:39:02.583193 [debug] [Thread-2 (]: Using postgres connection "model.my_dbt_project.b"
�[0m11:39:02.583368 [debug] [Thread-1 (]: On model.my_dbt_project.a: /* {"app": "dbt", "dbt_version": "1.8.6", "profile_name": "all", "target_name": "pg", "node_id": "model.my_dbt_project.a"} */
alter table "postgres"."public"."a__dbt_tmp" rename to "a"
�[0m11:39:02.583529 [debug] [Thread-2 (]: On model.my_dbt_project.b: /* {"app": "dbt", "dbt_version": "1.8.6", "profile_name": "all", "target_name": "pg", "node_id": "model.my_dbt_project.b"} */
alter table "postgres"."public"."b__dbt_tmp" rename to "b"
�[0m11:39:02.584989 [debug] [Thread-1 (]: SQL status: ALTER TABLE in 0.001 seconds
�[0m11:39:02.585168 [debug] [Thread-2 (]: SQL status: ALTER TABLE in 0.001 seconds
�[0m11:39:02.593610 [debug] [Thread-1 (]: On model.my_dbt_project.a: COMMIT
�[0m11:39:02.594145 [debug] [Thread-2 (]: On model.my_dbt_project.b: COMMIT
�[0m11:39:02.594302 [debug] [Thread-1 (]: Using postgres connection "model.my_dbt_project.a"
�[0m11:39:02.594449 [debug] [Thread-2 (]: Using postgres connection "model.my_dbt_project.b"
�[0m11:39:02.594600 [debug] [Thread-1 (]: On model.my_dbt_project.a: COMMIT
�[0m11:39:02.594742 [debug] [Thread-2 (]: On model.my_dbt_project.b: COMMIT
�[0m11:39:02.597358 [debug] [Thread-1 (]: SQL status: COMMIT in 0.002 seconds
�[0m11:39:02.599776 [debug] [Thread-1 (]: Applying DROP to: "postgres"."public"."a__dbt_backup"
�[0m11:39:02.599960 [debug] [Thread-2 (]: SQL status: COMMIT in 0.005 seconds
�[0m11:39:02.602048 [debug] [Thread-1 (]: Using postgres connection "model.my_dbt_project.a"
�[0m11:39:02.602999 [debug] [Thread-2 (]: Applying DROP to: "postgres"."public"."b__dbt_backup"
�[0m11:39:02.603180 [debug] [Thread-1 (]: On model.my_dbt_project.a: /* {"app": "dbt", "dbt_version": "1.8.6", "profile_name": "all", "target_name": "pg", "node_id": "model.my_dbt_project.a"} */
drop table if exists "postgres"."public"."a__dbt_backup" cascade
�[0m11:39:02.603408 [debug] [Thread-2 (]: Using postgres connection "model.my_dbt_project.b"
�[0m11:39:02.603611 [debug] [Thread-2 (]: On model.my_dbt_project.b: /* {"app": "dbt", "dbt_version": "1.8.6", "profile_name": "all", "target_name": "pg", "node_id": "model.my_dbt_project.b"} */
drop table if exists "postgres"."public"."b__dbt_backup" cascade
�[0m11:39:02.606828 [debug] [Thread-1 (]: SQL status: DROP TABLE in 0.003 seconds
�[0m11:39:02.607736 [debug] [Thread-1 (]: On model.my_dbt_project.a: Close
�[0m11:39:02.607908 [debug] [Thread-2 (]: SQL status: DROP TABLE in 0.004 seconds
�[0m11:39:02.608551 [debug] [Thread-1 (]: Sending event: {'category': 'dbt', 'action': 'run_model', 'label': 'd2feb866-1233-45d0-b388-4701e02bebcb', 'context': [<snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x10c175e50>]}
�[0m11:39:02.609054 [debug] [Thread-2 (]: On model.my_dbt_project.b: Close
�[0m11:39:02.609319 [info ] [Thread-1 (]: 1 of 5 OK created sql table model public.a ..................................... [�[32mSELECT 1�[0m in 10.10s]
�[0m11:39:02.609578 [debug] [Thread-2 (]: Sending event: {'category': 'dbt', 'action': 'run_model', 'label': 'd2feb866-1233-45d0-b388-4701e02bebcb', 'context': [<snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x10afc3d10>]}
�[0m11:39:02.609803 [debug] [Thread-1 (]: Finished running node model.my_dbt_project.a
�[0m11:39:02.610049 [info ] [Thread-2 (]: 2 of 5 OK created sql table model public.b ..................................... [�[32mSELECT 1�[0m in 10.10s]
�[0m11:39:02.610275 [debug] [Thread-1 (]: Began running node model.my_dbt_project.c
�[0m11:39:02.610539 [debug] [Thread-2 (]: Finished running node model.my_dbt_project.b
�[0m11:39:02.610737 [info ] [Thread-1 (]: 3 of 5 START sql table model public.c .......................................... [RUN]
�[0m11:39:02.610941 [debug] [Thread-2 (]: Began running node model.my_dbt_project.d
�[0m11:39:02.611141 [debug] [Thread-1 (]: Re-using an available connection from the pool (formerly model.my_dbt_project.a, now model.my_dbt_project.c)
�[0m11:39:02.611348 [info ] [Thread-2 (]: 4 of 5 START sql table model public.d .......................................... [RUN]
�[0m11:39:02.611531 [debug] [Thread-1 (]: Began compiling node model.my_dbt_project.c
�[0m11:39:02.611697 [debug] [Thread-2 (]: Re-using an available connection from the pool (formerly model.my_dbt_project.b, now model.my_dbt_project.d)
�[0m11:39:02.612506 [debug] [Thread-1 (]: Writing injected SQL for node "model.my_dbt_project.c"
�[0m11:39:02.612664 [debug] [Thread-2 (]: Began compiling node model.my_dbt_project.d
�[0m11:39:02.613455 [debug] [Thread-2 (]: Writing injected SQL for node "model.my_dbt_project.d"
�[0m11:39:02.613737 [debug] [Thread-1 (]: Began executing node model.my_dbt_project.c
�[0m11:39:02.613891 [debug] [Thread-2 (]: Began executing node model.my_dbt_project.d
�[0m11:39:02.615800 [debug] [Thread-1 (]: Writing runtime sql for node "model.my_dbt_project.c"
�[0m11:39:02.617862 [debug] [Thread-2 (]: Writing runtime sql for node "model.my_dbt_project.d"
�[0m11:39:02.618249 [debug] [Thread-1 (]: Using postgres connection "model.my_dbt_project.c"
�[0m11:39:02.618407 [debug] [Thread-2 (]: Using postgres connection "model.my_dbt_project.d"
�[0m11:39:02.618570 [debug] [Thread-1 (]: On model.my_dbt_project.c: BEGIN
�[0m11:39:02.618718 [debug] [Thread-2 (]: On model.my_dbt_project.d: BEGIN
�[0m11:39:02.618864 [debug] [Thread-1 (]: Opening a new connection, currently in state closed
�[0m11:39:02.619004 [debug] [Thread-2 (]: Opening a new connection, currently in state closed
�[0m11:39:02.627346 [debug] [Thread-1 (]: SQL status: BEGIN in 0.008 seconds
�[0m11:39:02.627524 [debug] [Thread-2 (]: SQL status: BEGIN in 0.009 seconds
�[0m11:39:02.627694 [debug] [Thread-1 (]: Using postgres connection "model.my_dbt_project.c"
�[0m11:39:02.627846 [debug] [Thread-2 (]: Using postgres connection "model.my_dbt_project.d"
�[0m11:39:02.628001 [debug] [Thread-1 (]: On model.my_dbt_project.c: /* {"app": "dbt", "dbt_version": "1.8.6", "profile_name": "all", "target_name": "pg", "node_id": "model.my_dbt_project.c"} */
create table "postgres"."public"."c__dbt_tmp"
as
(
select pg_sleep(10)::text as c
);
�[0m11:39:02.628161 [debug] [Thread-2 (]: On model.my_dbt_project.d: /* {"app": "dbt", "dbt_version": "1.8.6", "profile_name": "all", "target_name": "pg", "node_id": "model.my_dbt_project.d"} */
create table "postgres"."public"."d__dbt_tmp"
as
(
select pg_sleep(10)::text as c
);
�[0m11:39:12.649258 [debug] [Thread-1 (]: SQL status: SELECT 1 in 10.021 seconds
�[0m11:39:12.650634 [debug] [Thread-2 (]: SQL status: SELECT 1 in 10.022 seconds
�[0m11:39:12.660338 [debug] [Thread-1 (]: Using postgres connection "model.my_dbt_project.c"
�[0m11:39:12.664711 [debug] [Thread-2 (]: Using postgres connection "model.my_dbt_project.d"
�[0m11:39:12.665202 [debug] [Thread-1 (]: On model.my_dbt_project.c: /* {"app": "dbt", "dbt_version": "1.8.6", "profile_name": "all", "target_name": "pg", "node_id": "model.my_dbt_project.c"} */
alter table "postgres"."public"."c" rename to "c__dbt_backup"
�[0m11:39:12.665612 [debug] [Thread-2 (]: On model.my_dbt_project.d: /* {"app": "dbt", "dbt_version": "1.8.6", "profile_name": "all", "target_name": "pg", "node_id": "model.my_dbt_project.d"} */
alter table "postgres"."public"."d" rename to "d__dbt_backup"
�[0m11:39:12.667200 [debug] [Thread-2 (]: SQL status: ALTER TABLE in 0.001 seconds
�[0m11:39:12.667536 [debug] [Thread-1 (]: SQL status: ALTER TABLE in 0.002 seconds
�[0m11:39:12.670090 [debug] [Thread-2 (]: Using postgres connection "model.my_dbt_project.d"
�[0m11:39:12.671521 [debug] [Thread-1 (]: Using postgres connection "model.my_dbt_project.c"
�[0m11:39:12.671718 [debug] [Thread-2 (]: On model.my_dbt_project.d: /* {"app": "dbt", "dbt_version": "1.8.6", "profile_name": "all", "target_name": "pg", "node_id": "model.my_dbt_project.d"} */
alter table "postgres"."public"."d__dbt_tmp" rename to "d"
�[0m11:39:12.671890 [debug] [Thread-1 (]: On model.my_dbt_project.c: /* {"app": "dbt", "dbt_version": "1.8.6", "profile_name": "all", "target_name": "pg", "node_id": "model.my_dbt_project.c"} */
alter table "postgres"."public"."c__dbt_tmp" rename to "c"
�[0m11:39:12.673555 [debug] [Thread-1 (]: SQL status: ALTER TABLE in 0.001 seconds
�[0m11:39:12.673751 [debug] [Thread-2 (]: SQL status: ALTER TABLE in 0.002 seconds
�[0m11:39:12.674314 [debug] [Thread-1 (]: On model.my_dbt_project.c: COMMIT
�[0m11:39:12.674895 [debug] [Thread-2 (]: On model.my_dbt_project.d: COMMIT
�[0m11:39:12.675058 [debug] [Thread-1 (]: Using postgres connection "model.my_dbt_project.c"
�[0m11:39:12.675206 [debug] [Thread-2 (]: Using postgres connection "model.my_dbt_project.d"
�[0m11:39:12.675354 [debug] [Thread-1 (]: On model.my_dbt_project.c: COMMIT
�[0m11:39:12.675504 [debug] [Thread-2 (]: On model.my_dbt_project.d: COMMIT
�[0m11:39:12.677803 [debug] [Thread-2 (]: SQL status: COMMIT in 0.002 seconds
�[0m11:39:12.677972 [debug] [Thread-1 (]: SQL status: COMMIT in 0.002 seconds
�[0m11:39:12.678834 [debug] [Thread-2 (]: Applying DROP to: "postgres"."public"."d__dbt_backup"
�[0m11:39:12.679729 [debug] [Thread-1 (]: Applying DROP to: "postgres"."public"."c__dbt_backup"
�[0m11:39:12.680014 [debug] [Thread-2 (]: Using postgres connection "model.my_dbt_project.d"
�[0m11:39:12.680226 [debug] [Thread-1 (]: Using postgres connection "model.my_dbt_project.c"
�[0m11:39:12.680383 [debug] [Thread-2 (]: On model.my_dbt_project.d: /* {"app": "dbt", "dbt_version": "1.8.6", "profile_name": "all", "target_name": "pg", "node_id": "model.my_dbt_project.d"} */
drop table if exists "postgres"."public"."d__dbt_backup" cascade
�[0m11:39:12.680535 [debug] [Thread-1 (]: On model.my_dbt_project.c: /* {"app": "dbt", "dbt_version": "1.8.6", "profile_name": "all", "target_name": "pg", "node_id": "model.my_dbt_project.c"} */
drop table if exists "postgres"."public"."c__dbt_backup" cascade
�[0m11:39:12.684297 [debug] [Thread-1 (]: SQL status: DROP TABLE in 0.004 seconds
�[0m11:39:12.684822 [debug] [Thread-1 (]: On model.my_dbt_project.c: Close
�[0m11:39:12.685052 [debug] [Thread-1 (]: Sending event: {'category': 'dbt', 'action': 'run_model', 'label': 'd2feb866-1233-45d0-b388-4701e02bebcb', 'context': [<snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x10a653910>]}
�[0m11:39:12.685223 [debug] [Thread-2 (]: SQL status: DROP TABLE in 0.005 seconds
�[0m11:39:12.685466 [info ] [Thread-1 (]: 3 of 5 OK created sql table model public.c ..................................... [�[32mSELECT 1�[0m in 10.07s]
�[0m11:39:12.685957 [debug] [Thread-2 (]: On model.my_dbt_project.d: Close
�[0m11:39:12.686185 [debug] [Thread-1 (]: Finished running node model.my_dbt_project.c
�[0m11:39:12.686398 [debug] [Thread-2 (]: Sending event: {'category': 'dbt', 'action': 'run_model', 'label': 'd2feb866-1233-45d0-b388-4701e02bebcb', 'context': [<snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x10ad44c50>]}
�[0m11:39:12.686579 [debug] [Thread-1 (]: Began running node model.my_dbt_project.e
�[0m11:39:12.686846 [info ] [Thread-2 (]: 4 of 5 OK created sql table model public.d ..................................... [�[32mSELECT 1�[0m in 10.07s]
�[0m11:39:12.687073 [info ] [Thread-1 (]: 5 of 5 START sql table model public.e .......................................... [RUN]
�[0m11:39:12.687318 [debug] [Thread-2 (]: Finished running node model.my_dbt_project.d
�[0m11:39:12.687502 [debug] [Thread-1 (]: Re-using an available connection from the pool (formerly model.my_dbt_project.c, now model.my_dbt_project.e)
�[0m11:39:12.687705 [debug] [Thread-1 (]: Began compiling node model.my_dbt_project.e
�[0m11:39:12.688417 [debug] [Thread-1 (]: Writing injected SQL for node "model.my_dbt_project.e"
�[0m11:39:12.688758 [debug] [Thread-1 (]: Began executing node model.my_dbt_project.e
�[0m11:39:12.690744 [debug] [Thread-1 (]: Writing runtime sql for node "model.my_dbt_project.e"
�[0m11:39:12.691005 [debug] [Thread-1 (]: Using postgres connection "model.my_dbt_project.e"
�[0m11:39:12.691155 [debug] [Thread-1 (]: On model.my_dbt_project.e: BEGIN
�[0m11:39:12.691294 [debug] [Thread-1 (]: Opening a new connection, currently in state closed
�[0m11:39:12.697511 [debug] [Thread-1 (]: SQL status: BEGIN in 0.006 seconds
�[0m11:39:12.697727 [debug] [Thread-1 (]: Using postgres connection "model.my_dbt_project.e"
�[0m11:39:12.697872 [debug] [Thread-1 (]: On model.my_dbt_project.e: /* {"app": "dbt", "dbt_version": "1.8.6", "profile_name": "all", "target_name": "pg", "node_id": "model.my_dbt_project.e"} */
create table "postgres"."public"."e__dbt_tmp"
as
(
select pg_sleep(10)::text as c
);
�[0m11:39:13.351661 [debug] [MainThread]: Postgres adapter: Cancelling query 'model.my_dbt_project.e' (9221)
�[0m11:39:13.352323 [debug] [MainThread]: Using postgres connection "master"
�[0m11:39:13.352810 [debug] [MainThread]: On master: BEGIN
�[0m11:39:13.353191 [debug] [MainThread]: Opening a new connection, currently in state closed
�[0m11:39:13.362533 [debug] [MainThread]: SQL status: BEGIN in 0.009 seconds
�[0m11:39:13.362774 [debug] [MainThread]: Using postgres connection "master"
�[0m11:39:13.362910 [debug] [MainThread]: On master: select pg_terminate_backend(9221)
�[0m11:39:13.364041 [debug] [MainThread]: SQL status: SELECT 1 in 0.001 seconds
�[0m11:39:13.364180 [debug] [MainThread]: Postgres adapter: Cancel query 'model.my_dbt_project.e': (True,)
�[0m11:39:13.364317 [error] [MainThread]: CANCEL query model.my_dbt_project.e ............................................ [�[31mCANCEL�[0m]
�[0m11:39:13.364479 [error] [MainThread]: CANCEL query model.my_dbt_project.d ............................................ [�[31mCANCEL�[0m]
�[0m11:39:13.364637 [debug] [MainThread]: On master: ROLLBACK
�[0m11:39:13.365139 [debug] [MainThread]: On master: Close
�[0m11:39:13.367026 [debug] [Thread-1 (]: Postgres adapter: Postgres error: server closed the connection unexpectedly
This probably means the server terminated abnormally
before or while processing the request.
�[0m11:39:13.367244 [debug] [Thread-1 (]: On model.my_dbt_project.e: ROLLBACK
�[0m11:39:13.368539 [debug] [Thread-1 (]: Failed to rollback 'model.my_dbt_project.e'
�[0m11:39:13.368753 [debug] [Thread-1 (]: On model.my_dbt_project.e: Close
�[0m11:39:13.372590 [debug] [Thread-1 (]: Database Error in model e (models/e.sql)
server closed the connection unexpectedly
This probably means the server terminated abnormally
before or while processing the request.
compiled Code at target/run/my_dbt_project/models/e.sql
�[0m11:39:13.372825 [debug] [Thread-1 (]: Sending event: {'category': 'dbt', 'action': 'run_model', 'label': 'd2feb866-1233-45d0-b388-4701e02bebcb', 'context': [<snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x10c18be90>]}
�[0m11:39:13.373099 [error] [Thread-1 (]: 5 of 5 ERROR creating sql table model public.e ................................. [�[31mERROR�[0m in 0.69s]
�[0m11:39:13.373349 [debug] [Thread-1 (]: Finished running node model.my_dbt_project.e
�[0m11:39:13.373528 [info ] [MainThread]:
�[0m11:39:13.373729 [info ] [MainThread]: �[33mExited because of keyboard interrupt�[0m
�[0m11:39:13.373874 [info ] [MainThread]:
�[0m11:39:13.374023 [info ] [MainThread]: Done. PASS=4 WARN=0 ERROR=0 SKIP=0 TOTAL=4
�[0m11:39:13.374160 [debug] [MainThread]: Connection 'master' was properly closed.
�[0m11:39:13.374277 [debug] [MainThread]: Connection 'model.my_dbt_project.e' was properly closed.
�[0m11:39:13.374389 [debug] [MainThread]: Connection 'model.my_dbt_project.d' was properly closed.
�[0m11:39:13.374530 [info ] [MainThread]:
�[0m11:39:13.374674 [info ] [MainThread]: Finished running 4 table models in 0 hours 0 minutes and 21.01 seconds (21.01s).
�[0m11:39:13.374862 [error] [MainThread]: Encountered an error:
�[0m11:39:13.377105 [error] [MainThread]: Traceback (most recent call last):
File "/Users/jeremy/git/dbt-basic/venv_dbt_1.8.latest/lib/python3.11/site-packages/dbt/cli/requires.py", line 138, in wrapper
result, success = func(*args, **kwargs)
^^^^^^^^^^^^^^^^^^^^^
File "/Users/jeremy/git/dbt-basic/venv_dbt_1.8.latest/lib/python3.11/site-packages/dbt/cli/requires.py", line 101, in wrapper
return func(*args, **kwargs)
^^^^^^^^^^^^^^^^^^^^^
File "/Users/jeremy/git/dbt-basic/venv_dbt_1.8.latest/lib/python3.11/site-packages/dbt/cli/requires.py", line 218, in wrapper
return func(*args, **kwargs)
^^^^^^^^^^^^^^^^^^^^^
File "/Users/jeremy/git/dbt-basic/venv_dbt_1.8.latest/lib/python3.11/site-packages/dbt/cli/requires.py", line 247, in wrapper
return func(*args, **kwargs)
^^^^^^^^^^^^^^^^^^^^^
File "/Users/jeremy/git/dbt-basic/venv_dbt_1.8.latest/lib/python3.11/site-packages/dbt/cli/requires.py", line 294, in wrapper
return func(*args, **kwargs)
^^^^^^^^^^^^^^^^^^^^^
File "/Users/jeremy/git/dbt-basic/venv_dbt_1.8.latest/lib/python3.11/site-packages/dbt/cli/requires.py", line 332, in wrapper
return func(*args, **kwargs)
^^^^^^^^^^^^^^^^^^^^^
File "/Users/jeremy/git/dbt-basic/venv_dbt_1.8.latest/lib/python3.11/site-packages/dbt/cli/main.py", line 569, in run
results = task.run()
^^^^^^^^^^
File "/Users/jeremy/git/dbt-basic/venv_dbt_1.8.latest/lib/python3.11/site-packages/dbt/task/runnable.py", line 526, in run
result = self.execute_with_hooks(selected_uids)
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/Users/jeremy/git/dbt-basic/venv_dbt_1.8.latest/lib/python3.11/site-packages/dbt/task/runnable.py", line 487, in execute_with_hooks
res = self.execute_nodes()
^^^^^^^^^^^^^^^^^^^^
File "/Users/jeremy/git/dbt-basic/venv_dbt_1.8.latest/lib/python3.11/site-packages/dbt/task/runnable.py", line 397, in execute_nodes
self.run_queue(pool)
File "/Users/jeremy/git/dbt-basic/venv_dbt_1.8.latest/lib/python3.11/site-packages/dbt/task/runnable.py", line 315, in run_queue
self.job_queue.join()
File "/Users/jeremy/git/dbt-basic/venv_dbt_1.8.latest/lib/python3.11/site-packages/dbt/graph/queue.py", line 198, in join
self.inner.join()
File "/Users/jeremy/.pyenv/versions/3.11.9/lib/python3.11/queue.py", line 90, in join
self.all_tasks_done.wait()
File "/Users/jeremy/.pyenv/versions/3.11.9/lib/python3.11/threading.py", line 327, in wait
waiter.acquire()
KeyboardInterrupt
�[0m11:39:13.378228 [debug] [MainThread]: Resource report: {"command_name": "run", "command_wall_clock_time": 21.654987, "process_user_time": 1.271145, "process_kernel_time": 0.144544, "process_mem_max_rss": "126156800", "command_success": false, "process_in_blocks": "0", "process_out_blocks": "0"}
�[0m11:39:13.378482 [debug] [MainThread]: Command `dbt run` failed at 11:39:13.378443 after 21.66 seconds
�[0m11:39:13.378769 [debug] [MainThread]: Sending event: {'category': 'dbt', 'action': 'invocation', 'label': 'end', 'context': [<snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x109b6ff90>, <snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x109b2aa90>, <snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x10c042610>]}
�[0m11:39:13.378971 [debug] [MainThread]: Flushing usage events
Is this a new bug in dbt-core?
Current Behavior
When we CTRL+C a running dbt process - dbt emits
CANCEL
for the last-ish ran model for each thread even if those models ran successfully. This causes some user confusion.Expected Behavior
Don't emit CANCEL in the console logs unless necessary.
Steps To Reproduce
Project setup:
Run with 2 threads, then cancel (CTRL+C) as we see model
e
starting:^
d
shows as both CANCEL and OK:With many threads and models, this can be confusing to some users.
Relevant log output
Environment
Which database adapter are you using with dbt?
postgres
Additional Context
run_results.json
shows the true state as well where a, b, c, and d hasstatus: success
Bonus:
Can we make
run_results.json
also record the fact that modele
errored when the error was due to a cancel?The text was updated successfully, but these errors were encountered: