search

dbt-labs / dbt-core

dbt enables data analysts and engineers to transform their data using the same practices that software engineers use to build applications.
https://getdbt.com
Apache License 2.0
9.96k stars 1.63k forks source link

[Bug] Console logs emitting CANCEL for the last model ran by each thread even if those models finished building when receiving SIGINT (CTRL+C) #10746

Open jeremyyeo opened 1 month ago

jeremyyeo commented 1 month ago

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:

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

models:
  my_dbt_project:
    +materialized: table
-- models/a.sql
select pg_sleep(10)::text as c
-- models/b.sql
select pg_sleep(10)::text as c
-- models/c.sql
select pg_sleep(10)::text as c
-- models/d.sql
select pg_sleep(10)::text as c
-- models/e.sql
select pg_sleep(10)::text as 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, in wait
    waiter.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 ==============================
11:38:51.754797 [info ] [MainThread]: Running with dbt=1.8.6
11: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'}
11: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>]}
11: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>]}
11:38:51.855877 [info ] [MainThread]: Registered adapter: postgres=1.8.2
11:38:51.863756 [debug] [MainThread]: checksum: 2f2fb10c73cafe3e79aa104295a8244291492b32b5598ce46af770f7d0bd5194, vars: {}, profile: , target: , version: 1.8.6
11:38:51.891412 [info ] [MainThread]: Unable to do partial parsing because of a version mismatch
11: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>]}
11: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>]}
11: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>]}
11:38:52.362809 [info ] [MainThread]: Found 5 models, 418 macros
11: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>]}
11:38:52.363860 [info ] [MainThread]: 
11:38:52.364183 [debug] [MainThread]: Acquiring new postgres connection 'master'
11:38:52.366002 [debug] [ThreadPool]: Acquiring new postgres connection 'list_postgres'
11:38:52.416156 [debug] [ThreadPool]: Using postgres connection "list_postgres"
11: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

11:38:52.416495 [debug] [ThreadPool]: Opening a new connection, currently in state init
11:38:52.440258 [debug] [ThreadPool]: SQL status: SELECT 26 in 0.024 seconds
11:38:52.440880 [debug] [ThreadPool]: On list_postgres: Close
11:38:52.441495 [debug] [ThreadPool]: Re-using an available connection from the pool (formerly list_postgres, now list_postgres_public)
11:38:52.444055 [debug] [ThreadPool]: Using postgres connection "list_postgres_public"
11:38:52.444212 [debug] [ThreadPool]: On list_postgres_public: BEGIN
11:38:52.444343 [debug] [ThreadPool]: Opening a new connection, currently in state closed
11:38:52.452553 [debug] [ThreadPool]: SQL status: BEGIN in 0.008 seconds
11:38:52.452689 [debug] [ThreadPool]: Using postgres connection "list_postgres_public"
11: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'

11:38:52.456225 [debug] [ThreadPool]: SQL status: SELECT 98 in 0.003 seconds
11:38:52.457438 [debug] [ThreadPool]: On list_postgres_public: ROLLBACK
11:38:52.457985 [debug] [ThreadPool]: On list_postgres_public: Close
11:38:52.464173 [debug] [MainThread]: Using postgres connection "master"
11:38:52.464340 [debug] [MainThread]: On master: BEGIN
11:38:52.464463 [debug] [MainThread]: Opening a new connection, currently in state init
11:38:52.471328 [debug] [MainThread]: SQL status: BEGIN in 0.007 seconds
11:38:52.471511 [debug] [MainThread]: Using postgres connection "master"
11: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;
11:38:52.498543 [debug] [MainThread]: SQL status: SELECT 47 in 0.027 seconds
11: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>]}
11:38:52.502662 [debug] [MainThread]: On master: ROLLBACK
11:38:52.503122 [debug] [MainThread]: Using postgres connection "master"
11:38:52.503252 [debug] [MainThread]: On master: BEGIN
11:38:52.503836 [debug] [MainThread]: SQL status: BEGIN in 0.000 seconds
11:38:52.503991 [debug] [MainThread]: On master: COMMIT
11:38:52.504122 [debug] [MainThread]: Using postgres connection "master"
11:38:52.504254 [debug] [MainThread]: On master: COMMIT
11:38:52.504548 [debug] [MainThread]: SQL status: COMMIT in 0.000 seconds
11:38:52.504686 [debug] [MainThread]: On master: Close
11:38:52.504890 [info ] [MainThread]: Concurrency: 2 threads (target='pg')
11:38:52.505057 [info ] [MainThread]: 
11:38:52.506845 [debug] [Thread-1 (]: Began running node model.my_dbt_project.a
11:38:52.507030 [debug] [Thread-2 (]: Began running node model.my_dbt_project.b
11:38:52.507238 [info ] [Thread-1 (]: 1 of 5 START sql table model public.a .......................................... [RUN]
11:38:52.507557 [info ] [Thread-2 (]: 2 of 5 START sql table model public.b .......................................... [RUN]
11:38:52.507788 [debug] [Thread-1 (]: Re-using an available connection from the pool (formerly list_postgres_public, now model.my_dbt_project.a)
11:38:52.507988 [debug] [Thread-2 (]: Acquiring new postgres connection 'model.my_dbt_project.b'
11:38:52.508144 [debug] [Thread-1 (]: Began compiling node model.my_dbt_project.a
11:38:52.508298 [debug] [Thread-2 (]: Began compiling node model.my_dbt_project.b
11:38:52.511045 [debug] [Thread-1 (]: Writing injected SQL for node "model.my_dbt_project.a"
11:38:52.511835 [debug] [Thread-2 (]: Writing injected SQL for node "model.my_dbt_project.b"
11:38:52.512208 [debug] [Thread-2 (]: Began executing node model.my_dbt_project.b
11:38:52.512367 [debug] [Thread-1 (]: Began executing node model.my_dbt_project.a
11:38:52.530181 [debug] [Thread-2 (]: Writing runtime sql for node "model.my_dbt_project.b"
11:38:52.533099 [debug] [Thread-1 (]: Writing runtime sql for node "model.my_dbt_project.a"
11:38:52.533586 [debug] [Thread-1 (]: Using postgres connection "model.my_dbt_project.a"
11:38:52.533777 [debug] [Thread-2 (]: Using postgres connection "model.my_dbt_project.b"
11:38:52.533949 [debug] [Thread-1 (]: On model.my_dbt_project.a: BEGIN
11:38:52.534115 [debug] [Thread-2 (]: On model.my_dbt_project.b: BEGIN
11:38:52.534268 [debug] [Thread-1 (]: Opening a new connection, currently in state closed
11:38:52.534413 [debug] [Thread-2 (]: Opening a new connection, currently in state init
11:38:52.540768 [debug] [Thread-2 (]: SQL status: BEGIN in 0.006 seconds
11:38:52.540983 [debug] [Thread-2 (]: Using postgres connection "model.my_dbt_project.b"
11: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
  );

11:38:52.542933 [debug] [Thread-1 (]: SQL status: BEGIN in 0.009 seconds
11:38:52.543121 [debug] [Thread-1 (]: Using postgres connection "model.my_dbt_project.a"
11: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
  );

11:39:02.560431 [debug] [Thread-1 (]: SQL status: SELECT 1 in 10.017 seconds
11:39:02.561770 [debug] [Thread-2 (]: SQL status: SELECT 1 in 10.020 seconds
11:39:02.572660 [debug] [Thread-1 (]: Using postgres connection "model.my_dbt_project.a"
11:39:02.576296 [debug] [Thread-2 (]: Using postgres connection "model.my_dbt_project.b"
11: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"
11: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"
11:39:02.578848 [debug] [Thread-1 (]: SQL status: ALTER TABLE in 0.002 seconds
11:39:02.579206 [debug] [Thread-2 (]: SQL status: ALTER TABLE in 0.002 seconds
11:39:02.581758 [debug] [Thread-1 (]: Using postgres connection "model.my_dbt_project.a"
11:39:02.583193 [debug] [Thread-2 (]: Using postgres connection "model.my_dbt_project.b"
11: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"
11: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"
11:39:02.584989 [debug] [Thread-1 (]: SQL status: ALTER TABLE in 0.001 seconds
11:39:02.585168 [debug] [Thread-2 (]: SQL status: ALTER TABLE in 0.001 seconds
11:39:02.593610 [debug] [Thread-1 (]: On model.my_dbt_project.a: COMMIT
11:39:02.594145 [debug] [Thread-2 (]: On model.my_dbt_project.b: COMMIT
11:39:02.594302 [debug] [Thread-1 (]: Using postgres connection "model.my_dbt_project.a"
11:39:02.594449 [debug] [Thread-2 (]: Using postgres connection "model.my_dbt_project.b"
11:39:02.594600 [debug] [Thread-1 (]: On model.my_dbt_project.a: COMMIT
11:39:02.594742 [debug] [Thread-2 (]: On model.my_dbt_project.b: COMMIT
11:39:02.597358 [debug] [Thread-1 (]: SQL status: COMMIT in 0.002 seconds
11:39:02.599776 [debug] [Thread-1 (]: Applying DROP to: "postgres"."public"."a__dbt_backup"
11:39:02.599960 [debug] [Thread-2 (]: SQL status: COMMIT in 0.005 seconds
11:39:02.602048 [debug] [Thread-1 (]: Using postgres connection "model.my_dbt_project.a"
11:39:02.602999 [debug] [Thread-2 (]: Applying DROP to: "postgres"."public"."b__dbt_backup"
11: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
11:39:02.603408 [debug] [Thread-2 (]: Using postgres connection "model.my_dbt_project.b"
11: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
11:39:02.606828 [debug] [Thread-1 (]: SQL status: DROP TABLE in 0.003 seconds
11:39:02.607736 [debug] [Thread-1 (]: On model.my_dbt_project.a: Close
11:39:02.607908 [debug] [Thread-2 (]: SQL status: DROP TABLE in 0.004 seconds
11: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>]}
11:39:02.609054 [debug] [Thread-2 (]: On model.my_dbt_project.b: Close
11:39:02.609319 [info ] [Thread-1 (]: 1 of 5 OK created sql table model public.a ..................................... [SELECT 1 in 10.10s]
11: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>]}
11:39:02.609803 [debug] [Thread-1 (]: Finished running node model.my_dbt_project.a
11:39:02.610049 [info ] [Thread-2 (]: 2 of 5 OK created sql table model public.b ..................................... [SELECT 1 in 10.10s]
11:39:02.610275 [debug] [Thread-1 (]: Began running node model.my_dbt_project.c
11:39:02.610539 [debug] [Thread-2 (]: Finished running node model.my_dbt_project.b
11:39:02.610737 [info ] [Thread-1 (]: 3 of 5 START sql table model public.c .......................................... [RUN]
11:39:02.610941 [debug] [Thread-2 (]: Began running node model.my_dbt_project.d
11: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)
11:39:02.611348 [info ] [Thread-2 (]: 4 of 5 START sql table model public.d .......................................... [RUN]
11:39:02.611531 [debug] [Thread-1 (]: Began compiling node model.my_dbt_project.c
11: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)
11:39:02.612506 [debug] [Thread-1 (]: Writing injected SQL for node "model.my_dbt_project.c"
11:39:02.612664 [debug] [Thread-2 (]: Began compiling node model.my_dbt_project.d
11:39:02.613455 [debug] [Thread-2 (]: Writing injected SQL for node "model.my_dbt_project.d"
11:39:02.613737 [debug] [Thread-1 (]: Began executing node model.my_dbt_project.c
11:39:02.613891 [debug] [Thread-2 (]: Began executing node model.my_dbt_project.d
11:39:02.615800 [debug] [Thread-1 (]: Writing runtime sql for node "model.my_dbt_project.c"
11:39:02.617862 [debug] [Thread-2 (]: Writing runtime sql for node "model.my_dbt_project.d"
11:39:02.618249 [debug] [Thread-1 (]: Using postgres connection "model.my_dbt_project.c"
11:39:02.618407 [debug] [Thread-2 (]: Using postgres connection "model.my_dbt_project.d"
11:39:02.618570 [debug] [Thread-1 (]: On model.my_dbt_project.c: BEGIN
11:39:02.618718 [debug] [Thread-2 (]: On model.my_dbt_project.d: BEGIN
11:39:02.618864 [debug] [Thread-1 (]: Opening a new connection, currently in state closed
11:39:02.619004 [debug] [Thread-2 (]: Opening a new connection, currently in state closed
11:39:02.627346 [debug] [Thread-1 (]: SQL status: BEGIN in 0.008 seconds
11:39:02.627524 [debug] [Thread-2 (]: SQL status: BEGIN in 0.009 seconds
11:39:02.627694 [debug] [Thread-1 (]: Using postgres connection "model.my_dbt_project.c"
11:39:02.627846 [debug] [Thread-2 (]: Using postgres connection "model.my_dbt_project.d"
11: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
  );

11: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
  );

11:39:12.649258 [debug] [Thread-1 (]: SQL status: SELECT 1 in 10.021 seconds
11:39:12.650634 [debug] [Thread-2 (]: SQL status: SELECT 1 in 10.022 seconds
11:39:12.660338 [debug] [Thread-1 (]: Using postgres connection "model.my_dbt_project.c"
11:39:12.664711 [debug] [Thread-2 (]: Using postgres connection "model.my_dbt_project.d"
11: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"
11: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"
11:39:12.667200 [debug] [Thread-2 (]: SQL status: ALTER TABLE in 0.001 seconds
11:39:12.667536 [debug] [Thread-1 (]: SQL status: ALTER TABLE in 0.002 seconds
11:39:12.670090 [debug] [Thread-2 (]: Using postgres connection "model.my_dbt_project.d"
11:39:12.671521 [debug] [Thread-1 (]: Using postgres connection "model.my_dbt_project.c"
11: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"
11: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"
11:39:12.673555 [debug] [Thread-1 (]: SQL status: ALTER TABLE in 0.001 seconds
11:39:12.673751 [debug] [Thread-2 (]: SQL status: ALTER TABLE in 0.002 seconds
11:39:12.674314 [debug] [Thread-1 (]: On model.my_dbt_project.c: COMMIT
11:39:12.674895 [debug] [Thread-2 (]: On model.my_dbt_project.d: COMMIT
11:39:12.675058 [debug] [Thread-1 (]: Using postgres connection "model.my_dbt_project.c"
11:39:12.675206 [debug] [Thread-2 (]: Using postgres connection "model.my_dbt_project.d"
11:39:12.675354 [debug] [Thread-1 (]: On model.my_dbt_project.c: COMMIT
11:39:12.675504 [debug] [Thread-2 (]: On model.my_dbt_project.d: COMMIT
11:39:12.677803 [debug] [Thread-2 (]: SQL status: COMMIT in 0.002 seconds
11:39:12.677972 [debug] [Thread-1 (]: SQL status: COMMIT in 0.002 seconds
11:39:12.678834 [debug] [Thread-2 (]: Applying DROP to: "postgres"."public"."d__dbt_backup"
11:39:12.679729 [debug] [Thread-1 (]: Applying DROP to: "postgres"."public"."c__dbt_backup"
11:39:12.680014 [debug] [Thread-2 (]: Using postgres connection "model.my_dbt_project.d"
11:39:12.680226 [debug] [Thread-1 (]: Using postgres connection "model.my_dbt_project.c"
11: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
11: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
11:39:12.684297 [debug] [Thread-1 (]: SQL status: DROP TABLE in 0.004 seconds
11:39:12.684822 [debug] [Thread-1 (]: On model.my_dbt_project.c: Close
11: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>]}
11:39:12.685223 [debug] [Thread-2 (]: SQL status: DROP TABLE in 0.005 seconds
11:39:12.685466 [info ] [Thread-1 (]: 3 of 5 OK created sql table model public.c ..................................... [SELECT 1 in 10.07s]
11:39:12.685957 [debug] [Thread-2 (]: On model.my_dbt_project.d: Close
11:39:12.686185 [debug] [Thread-1 (]: Finished running node model.my_dbt_project.c
11: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>]}
11:39:12.686579 [debug] [Thread-1 (]: Began running node model.my_dbt_project.e
11:39:12.686846 [info ] [Thread-2 (]: 4 of 5 OK created sql table model public.d ..................................... [SELECT 1 in 10.07s]
11:39:12.687073 [info ] [Thread-1 (]: 5 of 5 START sql table model public.e .......................................... [RUN]
11:39:12.687318 [debug] [Thread-2 (]: Finished running node model.my_dbt_project.d
11: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)
11:39:12.687705 [debug] [Thread-1 (]: Began compiling node model.my_dbt_project.e
11:39:12.688417 [debug] [Thread-1 (]: Writing injected SQL for node "model.my_dbt_project.e"
11:39:12.688758 [debug] [Thread-1 (]: Began executing node model.my_dbt_project.e
11:39:12.690744 [debug] [Thread-1 (]: Writing runtime sql for node "model.my_dbt_project.e"
11:39:12.691005 [debug] [Thread-1 (]: Using postgres connection "model.my_dbt_project.e"
11:39:12.691155 [debug] [Thread-1 (]: On model.my_dbt_project.e: BEGIN
11:39:12.691294 [debug] [Thread-1 (]: Opening a new connection, currently in state closed
11:39:12.697511 [debug] [Thread-1 (]: SQL status: BEGIN in 0.006 seconds
11:39:12.697727 [debug] [Thread-1 (]: Using postgres connection "model.my_dbt_project.e"
11: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
  );

11:39:13.351661 [debug] [MainThread]: Postgres adapter: Cancelling query 'model.my_dbt_project.e' (9221)
11:39:13.352323 [debug] [MainThread]: Using postgres connection "master"
11:39:13.352810 [debug] [MainThread]: On master: BEGIN
11:39:13.353191 [debug] [MainThread]: Opening a new connection, currently in state closed
11:39:13.362533 [debug] [MainThread]: SQL status: BEGIN in 0.009 seconds
11:39:13.362774 [debug] [MainThread]: Using postgres connection "master"
11:39:13.362910 [debug] [MainThread]: On master: select pg_terminate_backend(9221)
11:39:13.364041 [debug] [MainThread]: SQL status: SELECT 1 in 0.001 seconds
11:39:13.364180 [debug] [MainThread]: Postgres adapter: Cancel query 'model.my_dbt_project.e': (True,)
11:39:13.364317 [error] [MainThread]: CANCEL query model.my_dbt_project.e ............................................ [CANCEL]
11:39:13.364479 [error] [MainThread]: CANCEL query model.my_dbt_project.d ............................................ [CANCEL]
11:39:13.364637 [debug] [MainThread]: On master: ROLLBACK
11:39:13.365139 [debug] [MainThread]: On master: Close
11: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.

11:39:13.367244 [debug] [Thread-1 (]: On model.my_dbt_project.e: ROLLBACK
11:39:13.368539 [debug] [Thread-1 (]: Failed to rollback 'model.my_dbt_project.e'
11:39:13.368753 [debug] [Thread-1 (]: On model.my_dbt_project.e: Close
11: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
11: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>]}
11:39:13.373099 [error] [Thread-1 (]: 5 of 5 ERROR creating sql table model public.e ................................. [ERROR in 0.69s]
11:39:13.373349 [debug] [Thread-1 (]: Finished running node model.my_dbt_project.e
11:39:13.373528 [info ] [MainThread]: 
11:39:13.373729 [info ] [MainThread]: Exited because of keyboard interrupt
11:39:13.373874 [info ] [MainThread]: 
11:39:13.374023 [info ] [MainThread]: Done. PASS=4 WARN=0 ERROR=0 SKIP=0 TOTAL=4
11:39:13.374160 [debug] [MainThread]: Connection 'master' was properly closed.
11:39:13.374277 [debug] [MainThread]: Connection 'model.my_dbt_project.e' was properly closed.
11:39:13.374389 [debug] [MainThread]: Connection 'model.my_dbt_project.d' was properly closed.
11:39:13.374530 [info ] [MainThread]: 
11:39:13.374674 [info ] [MainThread]: Finished running 4 table models in 0 hours 0 minutes and 21.01 seconds (21.01s).
11:39:13.374862 [error] [MainThread]: Encountered an error:

11: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

11: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"}
11:39:13.378482 [debug] [MainThread]: Command `dbt run` failed at 11:39:13.378443 after 21.66 seconds
11: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>]}
11:39:13.378971 [debug] [MainThread]: Flushing usage events

Environment

- OS: macOS
- Python: 3.11.9
- dbt: dbt-core==1.8.6 / dbt-postgres==1.8.2

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 has status: success

        {
            "status": "success",
            "timing": [
                {
                    "name": "compile",
                    "started_at": "2024-09-19T23:38:52.508408Z",
                    "completed_at": "2024-09-19T23:38:52.512328Z"
                },
                {
                    "name": "execute",
                    "started_at": "2024-09-19T23:38:52.530406Z",
                    "completed_at": "2024-09-19T23:39:02.607688Z"
                }
            ],
            "thread_id": "Thread-1 (worker)",
            "execution_time": 10.100392818450928,
            "adapter_response": {
                "_message": "SELECT 1",
                "code": "SELECT",
                "rows_affected": 1
            },
            "message": "SELECT 1",
            "failures": null,
            "unique_id": "model.my_dbt_project.a",
            "compiled": true,
            "compiled_code": "select pg_sleep(10)::text as c",
            "relation_name": "\"postgres\".\"public\".\"a\""
        },
        {
            "status": "success",
            "timing": [
                {
                    "name": "compile",
                    "started_at": "2024-09-19T23:38:52.511185Z",
                    "completed_at": "2024-09-19T23:38:52.512160Z"
                },
                {
                    "name": "execute",
                    "started_at": "2024-09-19T23:38:52.512474Z",
                    "completed_at": "2024-09-19T23:39:02.609014Z"
                }
            ],
            "thread_id": "Thread-2 (worker)",
            "execution_time": 10.101626873016357,
            "adapter_response": {
                "_message": "SELECT 1",
                "code": "SELECT",
                "rows_affected": 1
            },
            "message": "SELECT 1",
            "failures": null,
            "unique_id": "model.my_dbt_project.b",
            "compiled": true,
            "compiled_code": "select pg_sleep(10)::text as c",
            "relation_name": "\"postgres\".\"public\".\"b\""
        },
        {
            "status": "success",
            "timing": [
                {
                    "name": "compile",
                    "started_at": "2024-09-19T23:39:02.611820Z",
                    "completed_at": "2024-09-19T23:39:02.613697Z"
                },
                {
                    "name": "execute",
                    "started_at": "2024-09-19T23:39:02.614005Z",
                    "completed_at": "2024-09-19T23:39:12.684779Z"
                }
            ],
            "thread_id": "Thread-1 (worker)",
            "execution_time": 10.073916912078857,
            "adapter_response": {
                "_message": "SELECT 1",
                "code": "SELECT",
                "rows_affected": 1
            },
            "message": "SELECT 1",
            "failures": null,
            "unique_id": "model.my_dbt_project.c",
            "compiled": true,
            "compiled_code": "select pg_sleep(10)::text as c",
            "relation_name": "\"postgres\".\"public\".\"c\""
        },
        {
            "status": "success",
            "timing": [
                {
                    "name": "compile",
                    "started_at": "2024-09-19T23:39:02.612822Z",
                    "completed_at": "2024-09-19T23:39:02.613851Z"
                },
                {
                    "name": "execute",
                    "started_at": "2024-09-19T23:39:02.615928Z",
                    "completed_at": "2024-09-19T23:39:12.685920Z"
                }
            ],
            "thread_id": "Thread-2 (worker)",
            "execution_time": 10.074712038040161,
            "adapter_response": {
                "_message": "SELECT 1",
                "code": "SELECT",
                "rows_affected": 1
            },
            "message": "SELECT 1",
            "failures": null,
            "unique_id": "model.my_dbt_project.d",
            "compiled": true,
            "compiled_code": "select pg_sleep(10)::text as c",
            "relation_name": "\"postgres\".\"public\".\"d\""
        }

Bonus:

Can we make run_results.json also record the fact that model e errored when the error was due to a cancel?