add node_info to relevant logs #4336

emmyoop · 2021-11-24T17:17:18Z

resolves #4324

Description

First pass - any feedback on approach welcome!

Checklist

I have signed the CLA
I have run this code in development and it appears to resolve the stated issue
This PR includes tests, or tests are not required/relevant for this PR
I have updated the CHANGELOG.md and added information about my change

nathaniel-may

I left a bunch of comments regarding some alternatives for the core type modeling of this. I think if we get that right, the rest will come easy.

core/dbt/events/base_types.py

core/dbt/events/format.py

core/dbt/events/functions.py

nathaniel-may · 2021-11-24T17:39:37Z

core/dbt/events/functions.py

@@ -178,6 +182,7 @@ def create_json_log_line(e: T_Event, msg_fn: Callable[[T_Event], str]) -> str:
 in e.__dataclass_fields__.items() # type: ignore[attr-defined]
 if type(y._field_type) == _FIELD_BASE
 }
+ values['data']['type'] = 'dataclass_attr'


hmm I don't think this is quite what we're looking for here. type should communicate a schema i.e. what fields and types of values to expect, however this seems to communicate the lack of a schema.

I'm not really seeing what the schema here is since it is just any attributes that were passed in. I know we've defined them in the event classes but each one is different.

my guess is that "any attributes that were passed in" is a distributed type instead of a centralized type. The schema is written down, it's just written across the whole codebase not in one place. It exists even if it's annoying to pin down. I can help pin this down in the future. we may have to release with this kind of unstructured for now though.

core/dbt/events/types.py

jtcohen6

Nice work pulling this together! I think we're heading in the right overall direction. I left some scattered thoughts, would be happy to discuss in more detail when I'm back online a bit later

core/dbt/events/types.py

core/dbt/events/format.py

jtcohen6 · 2021-11-24T17:44:49Z

core/dbt/events/base_types.py

+ def get_node_info(self) -> Any:
+ if self.report_node_data:
+ return {
+ "type": 'node_status',


Not convinced we need this — I can't think of any events right now that should have node info, and aren't 'node_status' in one way or another

Realized this is here for functional/plumbing reasons, not user-facing context

core/dbt/events/types.py

core/dbt/events/base_types.py

jtcohen6 · 2021-11-24T17:57:43Z

core/dbt/events/types.py

@@ -2170,6 +2190,9 @@ def message(self) -> str:
 @dataclass
 class NodeFinished(DebugLevel, Cli, File):
 unique_id: str
+ report_node_data: ParsedModelNode
+ node_status: str = node_statuses['pass']
+ node_state: str = node_states['success']


I wonder if it makes sense to include the full contracted RunResult object in NodeFinished as well — even if we don't use it to template out the CLI message or specific node_info — that way, users can access its serialized representation from data within structured logs

nathaniel-may

We're getting there! definitely some great improvements keeping these changes on track to use nominal typing. Let me know what you think of these suggestions and we'll keep tweaking from there.

core/dbt/events/base_types.py

nathaniel-may · 2021-11-24T20:29:03Z

core/dbt/events/base_types.py

+
+
+class NodeInfo(Event, metaclass=ABCMeta):
+ report_node_data: Any


hmm lets see if we can make this type annotation tighter than Any. Looking at the call sites below, I think they're all subclasses of some parent Node type?

core/dbt/events/base_types.py

core/dbt/events/types.py

nathaniel-may

Thanks for chatting over zoom! here's some comments.

core/dbt/events/base_types.py

nathaniel-may · 2021-11-24T22:57:55Z

core/dbt/events/base_types.py

+ node_finished_at="TODO",
+ node_status="TODO" # self.node_status # pull from contract
+ )
+ return vars(node_info) #TODO: can just return node_info after #4326 is merged in


yes totally! I'll let you know when this PR is in.

nathaniel-may · 2021-11-24T22:59:11Z

core/dbt/events/base_types.py

+ node_path=self.report_node_data.path,
+ node_name=self.report_node_data.name,
+ resource_type=self.report_node_data.resource_type,
+ materialized=self.report_node_data.config.materialized,
+ node_started_at="TODO",
+ unique_id=self.report_node_data.unique_id,
+ node_finished_at="TODO",
+ node_status="TODO" # self.node_status # pull from contract
+ )


the fields you're accessing on report_node_data like path, name, resource_type, config.materialized etc. ARE the type that we've defined with the type hint Any above. I suspect we can represent this with a union of node types instead.

jtcohen6 · 2021-11-29T17:59:25Z

core/dbt/task/runnable.py

@@ -206,17 +206,34 @@ def call_runner(self, runner):
 with RUNNING_STATE, uid_context:
 startctx = TimestampNamed('node_started_at')
 index = self.index_offset(runner.node_index)
+ runner.node.config['started_at'] = datetime.utcnow().isoformat()


Is there any possibility that these could interfere with user-provided configs for started_at + finished_at? If so, could we name these in such a way that collisions are extremely unlikely (e.g. dbt_internal__started_at)?

nathaniel-may

I'm guessing we can delete the file trash.py. Added some questions.

nathaniel-may · 2021-11-29T22:33:29Z

core/dbt/task/runnable.py

+ del runner.node._event_status["dbt_internal__started_at"]
+ del runner.node._event_status["dbt_internal__finished_at"]
+ del runner.node._event_status["node_status"]


this is kind of awkward but I wouldn't be surprised if it's necessary. I think it's worth commenting though since it's odd.

Jeremy asked for this when we were putting these keys in the config, but we don't need it now that I changed it to put the keys in an event_status dict instead. So they names could be changed back.

it's the deleting of all the keys that seems odd to me.

I guess I was concerned that there might be situations where the nodes are reused and the status information is leftover from a previous run. I'm not sure if that can happen or not... Once we're really solid on what information we want to store there we could change it to a class and just reset it.

nathaniel-may · 2021-11-29T22:35:18Z

core/dbt/task/base.py

@@ -286,6 +287,13 @@ def skip_result(self, node, message):
 def compile_and_execute(self, manifest, ctx):
 result = None
 with self.adapter.connection_for(self.node):
+ ctx.node._event_status['node_status'] = str(RunningStatus.Compiling)


is this string representation of this class name user visible? the conversion to user-visible strings should live in the events module if possible.

The problem is that the node_status can contain either RunningStatus or NodeStatus, so it's just more work to get that straight.

it is more work, but I don't want us to change a classname and break an app parsing our logs.

I'm not sure what you're asking about here. When enums like NodeStatus are serialized, I think they're always strings.

nathaniel-may · 2021-11-29T22:40:50Z

core/dbt/events/functions.py

@@ -178,6 +182,7 @@ def create_json_log_line(e: T_Event, msg_fn: Callable[[T_Event], str]) -> str:
 in e.__dataclass_fields__.items() # type: ignore[attr-defined]
 if type(y._field_type) == _FIELD_BASE
 }
+ values['data']['type'] = 'dataclass_attr'


my guess is that "any attributes that were passed in" is a distributed type instead of a centralized type. The schema is written down, it's just written across the whole codebase not in one place. It exists even if it's annoying to pin down. I can help pin this down in the future. we may have to release with this kind of unstructured for now though.

core/dbt/events/base_types.py

nathaniel-may · 2021-11-29T22:43:31Z

core/dbt/events/functions.py

+ 'node_info': e.get_node_info() # TODO: update to just `node_info` and more calling this to
+ # `event_to_serializable_dict` after #4326 gets merged in.
+ # also remove refrence to node_info in Event class


highighting this TODO since that PR is soon to be merged in.

nathaniel-may · 2021-11-29T22:44:35Z

core/dbt/contracts/graph/parsed.py

+ def __post_serialize__(self, dct):
+ if '_event_status' in dct:
+ del dct['_event_status']
+ return dct


what is this and when is it called?

@gshank can you speak to this?

__post_serialize is a method that's called by the mashumaro serialization code. This removes the '_event_status' dictionary from the serialized form of the class (like manifest.json) because we should only need while running.

nathaniel-may

Approving with the intent that we'll do more cleanup after we cut the RC.

* WIP * fixed some merg issues * WIP * first pass with node_status logging * add node details to one more * another pass at node info * fixed failures * convert to classes * more tweaks to basic implementation * added in ststus, organized a bit * saving broken state * working state with lots of todos * formatting * add start/end tiemstamps * adding node_status logging to more events * adding node_status to more events * Add RunningStatus and set in node * Add NodeCompiling and NodeExecuting events, switch to _event_status dict * add _event_status to SourceDefinition * small tweaks to NodeInfo * fixed misnamed attr * small fix to validation * rename logging timestamps to minimize name collision * fixed flake failure * move str formatting to events * incorporate serialization changes * add node_status to event_to_serializable_dict * convert nodeInfo to dict with dataclass builtin * Try to fix failing unit, flake8, mypy tests (#4362) * fixed leftover merge conflict Co-authored-by: Gerda Shank <gerda@dbtlabs.com> automatic commit by git-black, original commits: caa6269

cla-bot bot added the cla:yes label Nov 24, 2021

emmyoop added test all run tests for all python versions + systems and removed cla:yes labels Nov 24, 2021

emmyoop changed the title ~~add nod_info to relevant logs~~ add node_info to relevant logs Nov 24, 2021

emmyoop requested review from nathaniel-may and jtcohen6 November 24, 2021 17:17

nathaniel-may reviewed Nov 24, 2021

View reviewed changes

jtcohen6 reviewed Nov 24, 2021

View reviewed changes

cla-bot bot added the cla:yes label Nov 24, 2021

nathaniel-may suggested changes Nov 24, 2021

View reviewed changes

emmyoop requested a review from nathaniel-may November 24, 2021 21:53

nathaniel-may mentioned this pull request Nov 24, 2021

Structured Logging Phase 2 #4260

Closed

26 tasks

nathaniel-may reviewed Nov 24, 2021

View reviewed changes

emmyoop force-pushed the er/sl-log-node-status branch from 200cfda to 8c8bfdd Compare November 29, 2021 14:39

jtcohen6 reviewed Nov 29, 2021

View reviewed changes

emmyoop force-pushed the er/sl-log-node-status branch from f88f067 to dffdaa3 Compare November 29, 2021 21:25

emmyoop closed this Nov 29, 2021

emmyoop reopened this Nov 29, 2021

emmyoop marked this pull request as ready for review November 29, 2021 22:05

emmyoop requested review from jtcohen6, nathaniel-may, iknox-fa and leahwicz November 29, 2021 22:13

nathaniel-may suggested changes Nov 29, 2021

View reviewed changes

emmyoop force-pushed the er/sl-log-node-status branch from 51d314b to 61b8f67 Compare November 30, 2021 00:51

jtcohen6 mentioned this pull request Nov 30, 2021

Try to fix failing tests for node_info additions #4362

Merged

emmyoop added 4 commits November 30, 2021 06:23

WIP

8131966

fixed some merg issues

8825fe0

WIP

730b2a6

first pass with node_status logging

5bbd0d5

emmyoop and others added 24 commits November 30, 2021 06:25

fixed failures

8e87bc8

convert to classes

b5a3a11

more tweaks to basic implementation

2796872

added in ststus, organized a bit

26d45c9

saving broken state

8cbcf57

working state with lots of todos

de0f353

formatting

4ca9682

add start/end tiemstamps

212f3be

adding node_status logging to more events

ac6b407

adding node_status to more events

01d9015

Add RunningStatus and set in node

0081a5f

Add NodeCompiling and NodeExecuting events, switch to _event_status dict

f029add

add _event_status to SourceDefinition

203a89e

small tweaks to NodeInfo

e95c952

fixed misnamed attr

9a15808

small fix to validation

b40192c

rename logging timestamps to minimize name collision

12b5926

fixed flake failure

ca7b32a

move str formatting to events

0839843

incorporate serialization changes

64168c1

add node_status to event_to_serializable_dict

3c82efd

convert nodeInfo to dict with dataclass builtin

603be18

Try to fix failing unit, flake8, mypy tests (#4362)

511e339

fixed leftover merge conflict

8ad4055

emmyoop force-pushed the er/sl-log-node-status branch from 07262e2 to 8ad4055 Compare November 30, 2021 12:30

nathaniel-may approved these changes Nov 30, 2021

View reviewed changes

leahwicz merged commit caa6269 into main Nov 30, 2021

leahwicz deleted the er/sl-log-node-status branch November 30, 2021 14:34

nathaniel-may mentioned this pull request Dec 6, 2021

Structured Logging Cleanup #4441

Closed

11 tasks

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

add node_info to relevant logs #4336

add node_info to relevant logs #4336

emmyoop commented Nov 24, 2021

nathaniel-may left a comment

nathaniel-may Nov 24, 2021

emmyoop Nov 29, 2021

nathaniel-may Nov 29, 2021

jtcohen6 left a comment

jtcohen6 Nov 24, 2021

jtcohen6 Nov 24, 2021

jtcohen6 Nov 24, 2021

nathaniel-may left a comment

nathaniel-may Nov 24, 2021

nathaniel-may left a comment

nathaniel-may Nov 24, 2021

nathaniel-may Nov 24, 2021

jtcohen6 Nov 29, 2021

nathaniel-may left a comment

nathaniel-may Nov 29, 2021

gshank Nov 29, 2021

nathaniel-may Nov 30, 2021

gshank Nov 30, 2021

nathaniel-may Nov 29, 2021

gshank Nov 29, 2021

nathaniel-may Nov 30, 2021

gshank Nov 30, 2021

nathaniel-may Nov 29, 2021

nathaniel-may Nov 29, 2021

nathaniel-may Nov 29, 2021

emmyoop Nov 29, 2021

gshank Nov 29, 2021

nathaniel-may left a comment



		class NodeInfo(Event, metaclass=ABCMeta):
		report_node_data: Any

add node_info to relevant logs #4336

add node_info to relevant logs #4336

Conversation

emmyoop commented Nov 24, 2021

Description

Checklist

nathaniel-may left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

jtcohen6 left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

nathaniel-may left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

nathaniel-may left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

nathaniel-may left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

nathaniel-may left a comment

Choose a reason for hiding this comment