add node type codes to more events + more hook log data

[emmyoop]

on-run-start/end hooks were not getting node_status, node_started_at, node_finished_at populated in node_status of logs. Fixed.

Made it a little more clear when we use the _message method in AdapterResponse for logging purposes.

Fixed up a few logging codes to point to nodes.

[gshank]

We don't need to prefix the 'started_at' and 'finished_at' keys with 'dbt_internal_' anymore since it's now not in the config dict. Could we change that back?

[jtcohen6]

I couldn't figure out how to get these mypy checks passing either!

core/dbt/task/run.py:361: error: Argument "report_node_data" to "PrintHookStartLine" has incompatible type "dbt.contracts.graph.parsed.ParsedHookNode"; expected "dbt.events.stubs.ParsedHookNode"

[nathaniel-may]

Take a close look at that error. There's two ParsedHookNodes: one is a type stub and one is a real class. We need to make sure we're not using the type stub, and delete it if we can.

[emmyoop]

So I am using the stub type. But I"m also referencing ParsedHookNode on other events that don't trigger the error. Then I'm using the stub type for ParsedModelNode on 16 events that don't trigger this. Why does it only trigger sometimes?

[nathaniel-may]

probably because mypy doesn't run on all the files so some of the call sites don't get caught.

[nathaniel-may]

Status gets hard coded to 'OK' and then if the hook contains SQL, the status becomes an instance of AdapterResponse for logging purposes. Is this intended?

I think we can make a better choice than this. What would you like to do here?

[emmyoop]

@nathaniel-may I'm honestly thinking now it's on purpose. It's actually consistent with how it gets handled on other log lines. The second line is the one I'm speaking of specifically.

16:10:15 | [ info  ] | 1 of 1 START hook: jaffle_shop.on-run-start.0................................... [RUN]
16:10:15 | [ info  ] | 1 of 1 OK hook: jaffle_shop.on-run-start.0...................................... [SELECT 1 in 0.00s]
16:10:15 | [ info  ] |
16:10:15 | [ info  ] | Concurrency: 4 threads (target='dev')
16:10:15 | [ info  ] |
16:10:15 | [ info  ] | 1 of 7 START view model dbt_testing.env_var_model............................... [RUN]
16:10:15 | [ info  ] | 2 of 7 START view model dbt_testing.even_id_table............................... [RUN]
16:10:15 | [ info  ] | 3 of 7 START table model dbt_testing.my_first_dbt_model......................... [RUN]
16:10:15 | [ error ] | 1 of 7 ERROR creating view model dbt_testing.env_var_model...................... [ERROR in 0.12s]
16:10:15 | [ info  ] | 3 of 7 OK created table model dbt_testing.my_first_dbt_model.................... [SELECT 2 in 0.16s]
16:10:15 | [ info  ] | 2 of 7 OK created view model dbt_testing.even_id_table.......................... [CREATE VIEW in 0.16s]

AdapterResponse has a __str__ method so that it just returns the _message. I'm going to add a comment but the behavior (I believe?) is correct.

[nathaniel-may]

Maybe there's a better way to model this behavior so it's more obviously intentional. I'm ok leaving that for later unless you're particularly motivated now.

[leahwicz]

The only conflict I fixed myself with the rebase was removing _ReferenceKey from here since @nathaniel-may added it above in his PR