Struct log for adapter call sites #4189
Conversation
add event type modeling and fire_event calls
* updated context dir to new structured logging
handle exec info
update log call sites with new event system
graph call sites for structured logging
iknox-fa
changed the title
There was a problem hiding this comment.
We definitely need to address the lazy log situation which I completely didn't understand until now. Of course the obvious solution runs us into a mypy bug so this will be fun to handle. I'll put up a PR to make message evaluation lazy in fire_event, so our solution here can assume that's already in.
core/dbt/adapters/cache.py
Outdated
| lazy_log('before adding: {!s}', self.dump_graph) | ||
| fire_event(AddRelation(relation=cached)) | ||
| # TODO: conditionally fire this event (logger.disabled, if it was std python logger) | ||
| fire_event(DumpBeforeAddGraph(graph=self.dump_graph())) |
There was a problem hiding this comment.
OH I see what lazy_log is doing here. I think it's guarding against log levels. If we're on info level, but this is debug level, because of strict evaluation, the long running dump graph will get called even though the message will never be displayed. The way the event module works right now, we force the message early so lazy logging won't help. I think this might be worth solving inside fire_event so we as developers don't have to decide whether the construction of a message is long running or not, it only constructs each message as they are needed.
There was a problem hiding this comment.
that being said... we're going to have the same problem with creating the event type. That will evaluate self.dump_graph() as part of __init__. We should change the event types to take a function value instead, and apply the empty arguments at message creation time. Let's cache it in the event type so it doesn't have to be called again.
We're basically threading laziness farther down the pipeline.
| @@ -0,0 +1,44 @@ | |||
| from typing import ( | |||
There was a problem hiding this comment.
is the plan for this file to grow a lot for now and then we can delete it when we turn on mypy everywhere?
core/dbt/events/types.py
Outdated
| class DumpBeforeAddGraph(DebugLevel, CliEventABC): | ||
| graph: Dict[str, List[str]] | ||
|
|
||
| def cli_msg(self) -> str: | ||
| return f"before adding: {str(self.graph)}" |
There was a problem hiding this comment.
Here's the kind of thing I think we should be doing:
from dataclasses import dataclass
from typing import Callable, Dict, List
def dump_graph() -> Dict[str, List[str]]:
raise Exception('stub')
@dataclass
class Foo():
graph_thunk: Callable[[], Dict[str, List[str]]]
def bar(self) -> str:
# this runs into a mypy bug: https://github.com/python/mypy/issues/6910
# I'll leave it up to you how you want to get around it.
return f"some msg with the graph:\n{self.graph_thunk()}"
Foo(graph_thunk=dump_graph)| # N.B: a temporary string replacement regex to strip the HH:MM:SS from the log line if present. | ||
| # TODO: make this go away when structured logging is stable | ||
| log_msg = re.sub("(?:[01]\d|2[0123]):(?:[012345]\d):(?:[012345]\d \| )", "", log['message']) | ||
| prefix = 'On {}: '.format(model_name) | ||
|
|
||
| if log['message'].startswith(prefix): | ||
| msg = log['message'][len(prefix):] | ||
| if log_msg.startswith(prefix): | ||
| msg = log_msg[len(prefix):] |
There was a problem hiding this comment.
What's this addition about?
|
Please see #4210 for the preserved laziness in |
core/dbt/adapters/cache.py
Outdated
|
|
||
| with self.lock: | ||
| self._setdefault(cached) | ||
|
|
||
| lazy_log('after adding: {!s}', self.dump_graph) | ||
| fire_event(DumpAfterAddGraph(graph_func=self.dump_graph())) |
There was a problem hiding this comment.
| fire_event(DumpAfterAddGraph(graph_func=self.dump_graph())) | |
| fire_event(DumpAfterAddGraph(graph_func=self.dump_graph)) |
emmyoop
force-pushed
the
feature/structured-logging
branch
from
89e478f to
66cece0
Compare
graph call sites for structured logging Co-authored-by: Nathaniel May <nathaniel.may@fishtownanalytics.com> Co-authored-by: Emily Rockman <emily.rockman@dbtlabs.com>
graph call sites for structured logging Co-authored-by: Nathaniel May <nathaniel.may@fishtownanalytics.com> Co-authored-by: Emily Rockman <emily.rockman@dbtlabs.com>
graph call sites for structured logging Co-authored-by: Nathaniel May <nathaniel.may@fishtownanalytics.com> Co-authored-by: Emily Rockman <emily.rockman@dbtlabs.com> automatic commit by git-black, original commits: b2aea11
Updated logging call sites for
core/dbt/adapters