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

[jtcohen6]

The node_info dictionary does not appropriately update for the NodeFinished event.

Running with the 1.4.latest branch:

$ dbt --log-format json run

{"data": {"log_version": 3, "version": "=1.4.0-rc1"}, "info": {"category": "", "code": "A001", "extra": {}, "invocation_id": "66a2fa8c-5843-4df2-8128-ea4b4070858f", "level": "info", "msg": "Running with dbt=1.4.0-rc1", "name": "MainReportVersion", "pid": 10868, "thread": "MainThread", "ts": "2023-01-11T12:16:57.720622Z"}}
{"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": "66a2fa8c-5843-4df2-8128-ea4b4070858f", "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": 10868, "thread": "MainThread", "ts": "2023-01-11T12:16:57.777880Z"}}
{"data": {"node_count": 3, "num_threads": 5, "target_name": "dev"}, "info": {"category": "", "code": "Q027", "extra": {}, "invocation_id": "66a2fa8c-5843-4df2-8128-ea4b4070858f", "level": "info", "msg": "Concurrency: 5 threads (target='dev')", "name": "ConcurrencyLine", "pid": 10868, "thread": "MainThread", "ts": "2023-01-11T12:16:57.925877Z"}}
{"data": {"description": "sql view model dbt_jcohen.model_a", "index": 1, "node_info": {"materialized": "view", "meta": {}, "node_finished_at": null, "node_name": "model_a", "node_path": "model_a.sql", "node_started_at": "2023-01-11T12:16:57.929551", "node_status": "started", "resource_type": "model", "unique_id": "model.testy.model_a"}, "total": 3}, "info": {"category": "", "code": "Q011", "extra": {}, "invocation_id": "66a2fa8c-5843-4df2-8128-ea4b4070858f", "level": "info", "msg": "1 of 3 START sql view model dbt_jcohen.model_a ................................. [RUN]", "name": "LogStartLine", "pid": 10868, "thread": "Thread-1 (worker)", "ts": "2023-01-11T12:16:57.930248Z"}}
{"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-11T12:16:57.929876", "node_status": "started", "resource_type": "model", "unique_id": "model.testy.model_b"}, "total": 3}, "info": {"category": "", "code": "Q011", "extra": {}, "invocation_id": "66a2fa8c-5843-4df2-8128-ea4b4070858f", "level": "info", "msg": "2 of 3 START sql view model dbt_jcohen.model_b ................................. [RUN]", "name": "LogStartLine", "pid": 10868, "thread": "Thread-2 (worker)", "ts": "2023-01-11T12:16:57.931008Z"}}
{"data": {"description": "sql view model dbt_jcohen.model_a", "execution_time": 0.08171987533569336, "index": 1, "node_info": {"materialized": "view", "meta": {}, "node_finished_at": null, "node_name": "model_a", "node_path": "model_a.sql", "node_started_at": "2023-01-11T12:16:57.929551", "node_status": "executing", "resource_type": "model", "unique_id": "model.testy.model_a"}, "status": "CREATE VIEW", "total": 3}, "info": {"category": "", "code": "Q012", "extra": {}, "invocation_id": "66a2fa8c-5843-4df2-8128-ea4b4070858f", "level": "info", "msg": "1 of 3 OK created sql view model dbt_jcohen.model_a ............................ [\u001b[32mCREATE VIEW\u001b[0m in 0.08s]", "name": "LogModelResult", "pid": 10868, "thread": "Thread-1 (worker)", "ts": "2023-01-11T12:16:58.015065Z"}}
{"data": {"description": "sql view model dbt_jcohen.model_b", "execution_time": 0.08798003196716309, "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-11T12:16:57.929876", "node_status": "executing", "resource_type": "model", "unique_id": "model.testy.model_b"}, "status": "CREATE VIEW", "total": 3}, "info": {"category": "", "code": "Q012", "extra": {}, "invocation_id": "66a2fa8c-5843-4df2-8128-ea4b4070858f", "level": "info", "msg": "2 of 3 OK created sql view model dbt_jcohen.model_b ............................ [\u001b[32mCREATE VIEW\u001b[0m in 0.09s]", "name": "LogModelResult", "pid": 10868, "thread": "Thread-2 (worker)", "ts": "2023-01-11T12:16:58.020156Z"}}
{"data": {"description": "sql view model dbt_jcohen.model_c", "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-11T12:16:58.021113", "node_status": "started", "resource_type": "model", "unique_id": "model.testy.model_c"}, "total": 3}, "info": {"category": "", "code": "Q011", "extra": {}, "invocation_id": "66a2fa8c-5843-4df2-8128-ea4b4070858f", "level": "info", "msg": "3 of 3 START sql view model dbt_jcohen.model_c ................................. [RUN]", "name": "LogStartLine", "pid": 10868, "thread": "Thread-4 (worker)", "ts": "2023-01-11T12:16:58.021504Z"}}
{"data": {"description": "sql view model dbt_jcohen.model_c", "execution_time": 0.02683401107788086, "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-11T12:16:58.021113", "node_status": "executing", "resource_type": "model", "unique_id": "model.testy.model_c"}, "status": "CREATE VIEW", "total": 3}, "info": {"category": "", "code": "Q012", "extra": {}, "invocation_id": "66a2fa8c-5843-4df2-8128-ea4b4070858f", "level": "info", "msg": "3 of 3 OK created sql view model dbt_jcohen.model_c ............................ [\u001b[32mCREATE VIEW\u001b[0m in 0.03s]", "name": "LogModelResult", "pid": 10868, "thread": "Thread-4 (worker)", "ts": "2023-01-11T12:16:58.049071Z"}}
{"data": {"execution": " in 0 hours 0 minutes and 0.28 seconds", "execution_time": 0.28208422660827637, "stat_line": "3 view models"}, "info": {"category": "", "code": "E047", "extra": {}, "invocation_id": "66a2fa8c-5843-4df2-8128-ea4b4070858f", "level": "info", "msg": "Finished running 3 view models in 0 hours 0 minutes and 0.28 seconds (0.28s).", "name": "HookFinished", "pid": 10868, "thread": "MainThread", "ts": "2023-01-11T12:16:58.061531Z"}}
{"data": {"keyboard_interrupt": false, "num_errors": 0, "num_warnings": 0}, "info": {"category": "", "code": "Z030", "extra": {}, "invocation_id": "66a2fa8c-5843-4df2-8128-ea4b4070858f", "level": "info", "msg": "\u001b[32mCompleted successfully\u001b[0m", "name": "EndOfRunSummary", "pid": 10868, "thread": "MainThread", "ts": "2023-01-11T12:16:58.067601Z"}}
{"data": {"stats": {"error": 0, "pass": 3, "skip": 0, "total": 3, "warn": 0}}, "info": {"category": "", "code": "Z023", "extra": {}, "invocation_id": "66a2fa8c-5843-4df2-8128-ea4b4070858f", "level": "info", "msg": "Done. PASS=3 WARN=0 ERROR=0 SKIP=0 TOTAL=3", "name": "StatsLine", "pid": 10868, "thread": "MainThread", "ts": "2023-01-11T12:16:58.068113Z"}}

I would expect the CREATE VIEW lines to include:

• node_finished_at populated
• node_status = success

It looks like we have some legacy logic around this:

dbt-core/core/dbt/task/run.py

Lines 372 to 373 in eb200b4

	with finishctx, DbtModelState({"node_status": "passed"}):
	hook.update_event_status(node_status=RunStatus.Success)

dbt-core/core/dbt/task/runnable.py

Lines 233 to 241 in 7a61602

	finally:
	finishctx = TimestampNamed("finished_at")
	with finishctx, DbtModelState(status):
	fire_event(
	NodeFinished(
	node_info=runner.node.node_info,
	run_result=result.to_msg(),
	)
	)

But we're not using the contextvars-based get_node_info(), introduced in #6325. I was able to get this working with a few small tweaks.

---

While I was here: HookFinished is a weird name for this log line! It has nothing to do with hooks. Could we rename it to (e.g.) FinishedRunningStats?

12:29:09  Finished running 3 view models in 0 hours 0 minutes and 0.30 seconds (0.30s).

{"category": "", "code": "E047", "extra": {}, "invocation_id": "1a3843b9-06cd-47dc-a778-13a6bede78c0", "level": "info", "msg": "Finished running 3 view models in 0 hours 0 minutes and 0.30 seconds (0.30s).", "name": "HookFinished", "pid": 11087, "thread": "MainThread", "ts": "2023-01-11T12:27:55.346489Z"}}

[jtcohen6]

Turns out this was me getting confused between NodeFinished and LogModelResult! Less critical than I thought. Though I'm probably not the last person who will find this confusing, so still worth changing.