Skip to content
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

Merged
merged 5 commits into from
Jan 12, 2023

Conversation

jtcohen6
Copy link
Contributor

@jtcohen6 jtcohen6 commented Jan 11, 2023

resolves #6571

Description

There are places where we were already explicitly passing in node_info, preceding the parity work in #6325 — but the information was actually incorrect! This PR updates those events to call get_node_info instead. This is especially important for NodeFinished-type events, to properly update node_status + node_finished_at.

Move update_event_status to a different spot in tasks, which gets called earlier, and crucially before the info-level LogModelResult event.

While here: rename HookFinished to FinishedRunningStats. This event has nothing to do with "hooks," as a dbt user would understand them :)

Checklist

@jtcohen6 jtcohen6 requested a review from a team January 11, 2023 12:42
@jtcohen6 jtcohen6 requested review from a team as code owners January 11, 2023 12:42
@jtcohen6 jtcohen6 requested review from iknox-fa and emmyoop January 11, 2023 12:42
@cla-bot cla-bot bot added the cla:yes label Jan 11, 2023
@gshank
Copy link
Contributor

gshank commented Jan 11, 2023

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.

@jtcohen6
Copy link
Contributor Author

jtcohen6 commented Jan 11, 2023

@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 node_status or node_finished_at populating correctly:

{"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 update_event_status call here is somehow "not sticking":

runner.node.update_event_status(
node_status=result.status, finished_at=datetime.utcnow().isoformat()
)

FWIW if I drop a breakpoint in right before the NodeFinished event is fired, and run with a single thread, I can see that these are equivalent:

> /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'})

@jtcohen6 jtcohen6 force-pushed the jerco/fix-6571-nodefinished-nodeinfo branch from 5cabd17 to f8b190f Compare January 11, 2023 16:45
@jtcohen6 jtcohen6 changed the title Call get_node_info for more events + rename one event Call update_event_status earlier + rename an event Jan 11, 2023
@jtcohen6
Copy link
Contributor Author

Now working as expected for LogModelResult:

{"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"}}

Copy link
Contributor

@gshank gshank left a 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...

@jtcohen6
Copy link
Contributor Author

@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 timing_info is actually available (not for error-status nodes)... worth another look in the future for sure.

In the meantime, I did catch that we're also not setting node_status for "skipped" nodes—that's a quick hit, so I'll sneak it in here as well.

@jtcohen6 jtcohen6 force-pushed the jerco/fix-6571-nodefinished-nodeinfo branch from ed880c1 to f0b49e8 Compare January 11, 2023 21:06
@jtcohen6 jtcohen6 merged commit 86e8722 into main Jan 12, 2023
@jtcohen6 jtcohen6 deleted the jerco/fix-6571-nodefinished-nodeinfo branch January 12, 2023 08:34
github-actions bot pushed a commit that referenced this pull request Jan 12, 2023
* 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)
jtcohen6 added a commit that referenced this pull request Jan 13, 2023
* 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>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging this pull request may close these issues.

[CT-1785] [Bug] Update node_info before LogModelResult events
2 participants