-
Notifications
You must be signed in to change notification settings - Fork 1.7k
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
Call update_event_status
earlier + rename an event
#6572
Conversation
Using get_node_info and model.node_info ought to be functionally equivalent, unless the actual node_info in the contextvar is for a different node than what's in the current node/model variable. The node on which 'update_event_status' was last called would be the node that contains the status updates. |
@gshank Weird! I could have sworn that I managed to get this working when I was testing the change earlier, but now when I run it locally (including the changes in this PR), I'm not seeing {"data": {"log_version": 3, "version": "=1.4.0-b1"}, "info": {"category": "", "code": "A001", "extra": {}, "invocation_id": "9c7e2031-89ea-4529-a683-a9a125cc6fb5", "level": "info", "msg": "Running with dbt=1.4.0-b1", "name": "MainReportVersion", "pid": 15434, "thread": "MainThread", "ts": "2023-01-11T14:36:02.632042Z"}}
{"data": {"stat_line": "3 models, 0 tests, 0 snapshots, 0 analyses, 291 macros, 0 operations, 0 seed files, 0 sources, 0 exposures, 0 metrics"}, "info": {"category": "", "code": "W006", "extra": {}, "invocation_id": "9c7e2031-89ea-4529-a683-a9a125cc6fb5", "level": "info", "msg": "Found 3 models, 0 tests, 0 snapshots, 0 analyses, 291 macros, 0 operations, 0 seed files, 0 sources, 0 exposures, 0 metrics", "name": "FoundStats", "pid": 15434, "thread": "MainThread", "ts": "2023-01-11T14:36:02.699814Z"}}
{"data": {"node_count": 3, "num_threads": 5, "target_name": "dev"}, "info": {"category": "", "code": "Q027", "extra": {}, "invocation_id": "9c7e2031-89ea-4529-a683-a9a125cc6fb5", "level": "info", "msg": "Concurrency: 5 threads (target='dev')", "name": "ConcurrencyLine", "pid": 15434, "thread": "MainThread", "ts": "2023-01-11T14:36:02.950973Z"}}
{"data": {"description": "sql view model dbt_jcohen.model_a", "index": 1, "node_info": {"materialized": "view", "meta": {"another_key": "3", "some_key": "some_value"}, "node_finished_at": null, "node_name": "model_a", "node_path": "model_a.sql", "node_started_at": "2023-01-11T14:36:02.955415", "node_status": "started", "resource_type": "model", "unique_id": "model.testy.model_a"}, "total": 3}, "info": {"category": "", "code": "Q011", "extra": {}, "invocation_id": "9c7e2031-89ea-4529-a683-a9a125cc6fb5", "level": "info", "msg": "1 of 3 START sql view model dbt_jcohen.model_a ................................. [RUN]", "name": "LogStartLine", "pid": 15434, "thread": "Thread-1 (worker)", "ts": "2023-01-11T14:36:02.956067Z"}}
{"data": {"description": "sql view model dbt_jcohen.model_b", "index": 2, "node_info": {"materialized": "view", "meta": {}, "node_finished_at": null, "node_name": "model_b", "node_path": "model_b.sql", "node_started_at": "2023-01-11T14:36:02.955725", "node_status": "started", "resource_type": "model", "unique_id": "model.testy.model_b"}, "total": 3}, "info": {"category": "", "code": "Q011", "extra": {}, "invocation_id": "9c7e2031-89ea-4529-a683-a9a125cc6fb5", "level": "info", "msg": "2 of 3 START sql view model dbt_jcohen.model_b ................................. [RUN]", "name": "LogStartLine", "pid": 15434, "thread": "Thread-2 (worker)", "ts": "2023-01-11T14:36:02.956823Z"}}
{"data": {"description": "sql view model dbt_jcohen.model_b", "execution_time": 0.07095599174499512, "index": 2, "node_info": {"materialized": "view", "meta": {}, "node_finished_at": null, "node_name": "model_b", "node_path": "model_b.sql", "node_started_at": "2023-01-11T14:36:02.955725", "node_status": "executing", "resource_type": "model", "unique_id": "model.testy.model_b"}, "status": "error", "total": 3}, "info": {"category": "", "code": "Q012", "extra": {}, "invocation_id": "9c7e2031-89ea-4529-a683-a9a125cc6fb5", "level": "error", "msg": "2 of 3 ERROR creating sql view model dbt_jcohen.model_b ........................ [\u001b[31mERROR\u001b[0m in 0.07s]", "name": "LogModelResult", "pid": 15434, "thread": "Thread-2 (worker)", "ts": "2023-01-11T14:36:03.029310Z"}}
{"data": {"description": "sql view model dbt_jcohen.model_a", "execution_time": 0.1068418025970459, "index": 1, "node_info": {"materialized": "view", "meta": {"another_key": "3", "some_key": "some_value"}, "node_finished_at": null, "node_name": "model_a", "node_path": "model_a.sql", "node_started_at": "2023-01-11T14:36:02.955415", "node_status": "executing", "resource_type": "model", "unique_id": "model.testy.model_a"}, "status": "CREATE VIEW", "total": 3}, "info": {"category": "", "code": "Q012", "extra": {}, "invocation_id": "9c7e2031-89ea-4529-a683-a9a125cc6fb5", "level": "info", "msg": "1 of 3 OK created sql view model dbt_jcohen.model_a ............................ [\u001b[32mCREATE VIEW\u001b[0m in 0.11s]", "name": "LogModelResult", "pid": 15434, "thread": "Thread-1 (worker)", "ts": "2023-01-11T14:36:03.064386Z"}}
{"data": {"index": 3, "node_info": {"materialized": "view", "meta": {}, "node_finished_at": null, "node_name": "model_c", "node_path": "model_c.sql", "node_started_at": "2023-01-11T14:36:03.065376", "node_status": "started", "resource_type": "model", "unique_id": "model.testy.model_c"}, "node_name": "model_c", "resource_type": "model", "schema": "dbt_jcohen", "total": 3}, "info": {"category": "", "code": "Q034", "extra": {}, "invocation_id": "9c7e2031-89ea-4529-a683-a9a125cc6fb5", "level": "info", "msg": "3 of 3 SKIP relation dbt_jcohen.model_c ........................................ [\u001b[33mSKIP\u001b[0m]", "name": "SkippingDetails", "pid": 15434, "thread": "Thread-4 (worker)", "ts": "2023-01-11T14:36:03.065660Z"}}
{"data": {"execution": " in 0 hours 0 minutes and 0.38 seconds", "execution_time": 0.37717723846435547, "stat_line": "3 view models"}, "info": {"category": "", "code": "E047", "extra": {}, "invocation_id": "9c7e2031-89ea-4529-a683-a9a125cc6fb5", "level": "info", "msg": "Finished running 3 view models in 0 hours 0 minutes and 0.38 seconds (0.38s).", "name": "FinishedRunningStats", "pid": 15434, "thread": "MainThread", "ts": "2023-01-11T14:36:03.078509Z"}}
{"data": {"keyboard_interrupt": false, "num_errors": 1, "num_warnings": 0}, "info": {"category": "", "code": "Z030", "extra": {}, "invocation_id": "9c7e2031-89ea-4529-a683-a9a125cc6fb5", "level": "info", "msg": "\u001b[31mCompleted with 1 error and 0 warnings:\u001b[0m", "name": "EndOfRunSummary", "pid": 15434, "thread": "MainThread", "ts": "2023-01-11T14:36:03.083913Z"}}
{"data": {"msg": "Database Error in model model_b (models/model_b.sql)"}, "info": {"category": "", "code": "Z028", "extra": {}, "invocation_id": "9c7e2031-89ea-4529-a683-a9a125cc6fb5", "level": "error", "msg": "\u001b[33mDatabase Error in model model_b (models/model_b.sql)\u001b[0m", "name": "FirstRunResultError", "pid": 15434, "thread": "MainThread", "ts": "2023-01-11T14:36:03.084432Z"}}
{"data": {"msg": " column \"asojasdfl\" does not exist"}, "info": {"category": "", "code": "Z029", "extra": {}, "invocation_id": "9c7e2031-89ea-4529-a683-a9a125cc6fb5", "level": "error", "msg": " column \"asojasdfl\" does not exist", "name": "AfterFirstRunResultError", "pid": 15434, "thread": "MainThread", "ts": "2023-01-11T14:36:03.084778Z"}}
{"data": {"msg": " LINE 4: select asojasdfl"}, "info": {"category": "", "code": "Z029", "extra": {}, "invocation_id": "9c7e2031-89ea-4529-a683-a9a125cc6fb5", "level": "error", "msg": " LINE 4: select asojasdfl", "name": "AfterFirstRunResultError", "pid": 15434, "thread": "MainThread", "ts": "2023-01-11T14:36:03.085108Z"}}
{"data": {"msg": " ^"}, "info": {"category": "", "code": "Z029", "extra": {}, "invocation_id": "9c7e2031-89ea-4529-a683-a9a125cc6fb5", "level": "error", "msg": " ^", "name": "AfterFirstRunResultError", "pid": 15434, "thread": "MainThread", "ts": "2023-01-11T14:36:03.085359Z"}}
{"data": {"msg": " compiled Code at target/run/testy/models/model_b.sql"}, "info": {"category": "", "code": "Z029", "extra": {}, "invocation_id": "9c7e2031-89ea-4529-a683-a9a125cc6fb5", "level": "error", "msg": " compiled Code at target/run/testy/models/model_b.sql", "name": "AfterFirstRunResultError", "pid": 15434, "thread": "MainThread", "ts": "2023-01-11T14:36:03.085603Z"}}
{"data": {"stats": {"error": 1, "pass": 1, "skip": 1, "total": 3, "warn": 0}}, "info": {"category": "", "code": "Z023", "extra": {}, "invocation_id": "9c7e2031-89ea-4529-a683-a9a125cc6fb5", "level": "info", "msg": "Done. PASS=1 WARN=0 ERROR=1 SKIP=1 TOTAL=3", "name": "StatsLine", "pid": 15434, "thread": "MainThread", "ts": "2023-01-11T14:36:03.085893Z"}} I buy your explanation that there must be something else at play, whereby the dbt-core/core/dbt/task/runnable.py Lines 230 to 232 in 7a61602
FWIW if I drop a breakpoint in right before the > /Users/jerco/dev/product/dbt-core/core/dbt/task/runnable.py(239)call_runner()
238 import ipdb; ipdb.set_trace()
--> 239 fire_event(
240 NodeFinished(
ipdb> get_node_info()
NodeInfo(node_path='model_a.sql', node_name='model_a', unique_id='model.testy.model_a', resource_type='model', materialized='view', node_status='success', node_started_at='2023-01-11T14:47:09.578469', node_finished_at='2023-01-11T14:47:09.653346', meta={'some_key': 'some_value', 'another_key': '3'})
ipdb> model
*** NameError: name 'model' is not defined
ipdb> node
*** NameError: name 'node' is not defined
ipdb> runner.node.node_info
NodeInfo(node_path='model_a.sql', node_name='model_a', unique_id='model.testy.model_a', resource_type='model', materialized='view', node_status='success', node_started_at='2023-01-11T14:47:09.578469', node_finished_at='2023-01-11T14:47:09.653346', meta={'some_key': 'some_value', 'another_key': '3'}) |
5cabd17
to
f8b190f
Compare
get_node_info
for more events + rename one eventupdate_event_status
earlier + rename an event
Now working as expected for {"data": {"log_version": 3, "version": "=1.4.0-b1"}, "info": {"category": "", "code": "A001", "extra": {}, "invocation_id": "72ab609c-e8d2-40be-b375-380e974d1c5f", "level": "info", "msg": "Running with dbt=1.4.0-b1", "name": "MainReportVersion", "pid": 20963, "thread": "MainThread", "ts": "2023-01-11T17:33:39.488134Z"}}
{"data": {"stat_line": "3 models, 0 tests, 0 snapshots, 0 analyses, 291 macros, 0 operations, 0 seed files, 0 sources, 0 exposures, 0 metrics"}, "info": {"category": "", "code": "W006", "extra": {}, "invocation_id": "72ab609c-e8d2-40be-b375-380e974d1c5f", "level": "info", "msg": "Found 3 models, 0 tests, 0 snapshots, 0 analyses, 291 macros, 0 operations, 0 seed files, 0 sources, 0 exposures, 0 metrics", "name": "FoundStats", "pid": 20963, "thread": "MainThread", "ts": "2023-01-11T17:33:39.586762Z"}}
{"data": {"node_count": 3, "num_threads": 5, "target_name": "dev"}, "info": {"category": "", "code": "Q027", "extra": {}, "invocation_id": "72ab609c-e8d2-40be-b375-380e974d1c5f", "level": "info", "msg": "Concurrency: 5 threads (target='dev')", "name": "ConcurrencyLine", "pid": 20963, "thread": "MainThread", "ts": "2023-01-11T17:33:40.764280Z"}}
{"data": {"description": "sql view model dbt_jcohen.model_a", "index": 1, "node_info": {"materialized": "view", "meta": {"another_key": "3", "some_key": "some_value"}, "node_finished_at": null, "node_name": "model_a", "node_path": "model_a.sql", "node_started_at": "2023-01-11T17:33:40.768641", "node_status": "started", "resource_type": "model", "unique_id": "model.testy.model_a"}, "total": 3}, "info": {"category": "", "code": "Q011", "extra": {}, "invocation_id": "72ab609c-e8d2-40be-b375-380e974d1c5f", "level": "info", "msg": "1 of 3 START sql view model dbt_jcohen.model_a ................................. [RUN]", "name": "LogStartLine", "pid": 20963, "thread": "Thread-1 (worker)", "ts": "2023-01-11T17:33:40.769409Z"}}
{"data": {"description": "sql view model dbt_jcohen.model_b", "index": 2, "node_info": {"materialized": "view", "meta": {}, "node_finished_at": null, "node_name": "model_b", "node_path": "model_b.sql", "node_started_at": "2023-01-11T17:33:40.768977", "node_status": "started", "resource_type": "model", "unique_id": "model.testy.model_b"}, "total": 3}, "info": {"category": "", "code": "Q011", "extra": {}, "invocation_id": "72ab609c-e8d2-40be-b375-380e974d1c5f", "level": "info", "msg": "2 of 3 START sql view model dbt_jcohen.model_b ................................. [RUN]", "name": "LogStartLine", "pid": 20963, "thread": "Thread-2 (worker)", "ts": "2023-01-11T17:33:40.770174Z"}}
{"data": {"description": "sql view model dbt_jcohen.model_b", "execution_time": 0.06903600692749023, "index": 2, "node_info": {"materialized": "view", "meta": {}, "node_finished_at": "2023-01-11T17:33:40.840247", "node_name": "model_b", "node_path": "model_b.sql", "node_started_at": "2023-01-11T17:33:40.768977", "node_status": "error", "resource_type": "model", "unique_id": "model.testy.model_b"}, "status": "error", "total": 3}, "info": {"category": "", "code": "Q012", "extra": {}, "invocation_id": "72ab609c-e8d2-40be-b375-380e974d1c5f", "level": "error", "msg": "2 of 3 ERROR creating sql view model dbt_jcohen.model_b ........................ [\u001b[31mERROR\u001b[0m in 0.07s]", "name": "LogModelResult", "pid": 20963, "thread": "Thread-2 (worker)", "ts": "2023-01-11T17:33:40.840683Z"}}
{"data": {"description": "sql view model dbt_jcohen.model_a", "execution_time": 0.10790801048278809, "index": 1, "node_info": {"materialized": "view", "meta": {"another_key": "3", "some_key": "some_value"}, "node_finished_at": "2023-01-11T17:33:40.878454", "node_name": "model_a", "node_path": "model_a.sql", "node_started_at": "2023-01-11T17:33:40.768641", "node_status": "success", "resource_type": "model", "unique_id": "model.testy.model_a"}, "status": "CREATE VIEW", "total": 3}, "info": {"category": "", "code": "Q012", "extra": {}, "invocation_id": "72ab609c-e8d2-40be-b375-380e974d1c5f", "level": "info", "msg": "1 of 3 OK created sql view model dbt_jcohen.model_a ............................ [\u001b[32mCREATE VIEW\u001b[0m in 0.11s]", "name": "LogModelResult", "pid": 20963, "thread": "Thread-1 (worker)", "ts": "2023-01-11T17:33:40.878892Z"}}
{"data": {"index": 3, "node_info": {"materialized": "view", "meta": {}, "node_finished_at": null, "node_name": "model_c", "node_path": "model_c.sql", "node_started_at": "2023-01-11T17:33:40.879829", "node_status": "started", "resource_type": "model", "unique_id": "model.testy.model_c"}, "node_name": "model_c", "resource_type": "model", "schema": "dbt_jcohen", "total": 3}, "info": {"category": "", "code": "Q034", "extra": {}, "invocation_id": "72ab609c-e8d2-40be-b375-380e974d1c5f", "level": "info", "msg": "3 of 3 SKIP relation dbt_jcohen.model_c ........................................ [\u001b[33mSKIP\u001b[0m]", "name": "SkippingDetails", "pid": 20963, "thread": "Thread-4 (worker)", "ts": "2023-01-11T17:33:40.880305Z"}}
{"data": {"execution": " in 0 hours 0 minutes and 1.30 seconds", "execution_time": 1.3032629489898682, "stat_line": "3 view models"}, "info": {"category": "", "code": "E047", "extra": {}, "invocation_id": "72ab609c-e8d2-40be-b375-380e974d1c5f", "level": "info", "msg": "Finished running 3 view models in 0 hours 0 minutes and 1.30 seconds (1.30s).", "name": "FinishedRunningStats", "pid": 20963, "thread": "MainThread", "ts": "2023-01-11T17:33:40.892883Z"}}
{"data": {"keyboard_interrupt": false, "num_errors": 1, "num_warnings": 0}, "info": {"category": "", "code": "Z030", "extra": {}, "invocation_id": "72ab609c-e8d2-40be-b375-380e974d1c5f", "level": "info", "msg": "\u001b[31mCompleted with 1 error and 0 warnings:\u001b[0m", "name": "EndOfRunSummary", "pid": 20963, "thread": "MainThread", "ts": "2023-01-11T17:33:40.898296Z"}}
{"data": {"msg": "Database Error in model model_b (models/model_b.sql)"}, "info": {"category": "", "code": "Z028", "extra": {}, "invocation_id": "72ab609c-e8d2-40be-b375-380e974d1c5f", "level": "error", "msg": "\u001b[33mDatabase Error in model model_b (models/model_b.sql)\u001b[0m", "name": "FirstRunResultError", "pid": 20963, "thread": "MainThread", "ts": "2023-01-11T17:33:40.898810Z"}}
{"data": {"msg": " column \"asojasdfl\" does not exist"}, "info": {"category": "", "code": "Z029", "extra": {}, "invocation_id": "72ab609c-e8d2-40be-b375-380e974d1c5f", "level": "error", "msg": " column \"asojasdfl\" does not exist", "name": "AfterFirstRunResultError", "pid": 20963, "thread": "MainThread", "ts": "2023-01-11T17:33:40.899134Z"}}
{"data": {"msg": " LINE 4: select asojasdfl"}, "info": {"category": "", "code": "Z029", "extra": {}, "invocation_id": "72ab609c-e8d2-40be-b375-380e974d1c5f", "level": "error", "msg": " LINE 4: select asojasdfl", "name": "AfterFirstRunResultError", "pid": 20963, "thread": "MainThread", "ts": "2023-01-11T17:33:40.899443Z"}}
{"data": {"msg": " ^"}, "info": {"category": "", "code": "Z029", "extra": {}, "invocation_id": "72ab609c-e8d2-40be-b375-380e974d1c5f", "level": "error", "msg": " ^", "name": "AfterFirstRunResultError", "pid": 20963, "thread": "MainThread", "ts": "2023-01-11T17:33:40.899692Z"}}
{"data": {"msg": " compiled Code at target/run/testy/models/model_b.sql"}, "info": {"category": "", "code": "Z029", "extra": {}, "invocation_id": "72ab609c-e8d2-40be-b375-380e974d1c5f", "level": "error", "msg": " compiled Code at target/run/testy/models/model_b.sql", "name": "AfterFirstRunResultError", "pid": 20963, "thread": "MainThread", "ts": "2023-01-11T17:33:40.899929Z"}}
{"data": {"stats": {"error": 1, "pass": 1, "skip": 1, "total": 3, "warn": 0}}, "info": {"category": "", "code": "Z023", "extra": {}, "invocation_id": "72ab609c-e8d2-40be-b375-380e974d1c5f", "level": "info", "msg": "Done. PASS=1 WARN=0 ERROR=1 SKIP=1 TOTAL=3", "name": "StatsLine", "pid": 20963, "thread": "MainThread", "ts": "2023-01-11T17:33:40.900209Z"}} |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Looks good.
As a side issue, it bothers me a bit that the finished at time is different for node_status and for timing_info. I don't think it should be done in this ticket, but just wanted to point that out...
@gshank I played around with it a bit, but I don't think there's a great way to pass this information around. We also have inconsistencies already in terms of when In the meantime, I did catch that we're also not setting |
ed880c1
to
f0b49e8
Compare
* Rename HookFinished -> FinishedRunningStats * Move update_event_status earlier when node finishes * Add changelog entry * Add update_event_status for skip * Update changelog entry (cherry picked from commit 86e8722)
* Rename HookFinished -> FinishedRunningStats * Move update_event_status earlier when node finishes * Add changelog entry * Add update_event_status for skip * Update changelog entry (cherry picked from commit 86e8722) Co-authored-by: Jeremy Cohen <jeremy@dbtlabs.com>
resolves #6571
Description
There are places where we were already explicitly passing innode_info
, preceding the parity work in #6325 — but the information was actually incorrect! This PR updates those events to callget_node_info
instead. This is especially important forNodeFinished
-type events, to properly updatenode_status
+node_finished_at
.Move
update_event_status
to a different spot in tasks, which gets called earlier, and crucially before the info-levelLogModelResult
event.While here: rename
HookFinished
toFinishedRunningStats
. This event has nothing to do with "hooks," as a dbt user would understand them :)Checklist
changie new
to create a changelog entry