RPC: Error handling improvements #1341

beckjake · 2019-03-06T22:05:31Z

All dbt errors now have proper error codes/messages
The raised message at runtime ends up in result.error.data.message
The raised message type at runtime ends up in result.error.data.typename
result.error.message is a plaintext name for result.error.code
dbt.exceptions.Exception.data() becomes result.error.data
Include logs in the RPC responses - for errors under response.error.data.logs and for results under response.result.logs. The results are enqueued back to the main process, so even timeouts get logs.

I refactored safe_run by just chunking everything up as part of this, as I wanted to override particular parts of the error handling chain (mostly to keep raising errors farther and father up the stack of safe_*)

drewbanin

The logging logistics here largely look alright to me, but it would be good to also get @cmcarthur's eyes on the queue/multiprocessing aspects of this.

I have some immediate thoughts after playing around with this, and would love to discuss feasibility before we make any of these changes. I had a hard time responding to this PR, since I:

don't have a great handle on exactly what the requirements are yet (though this is very close, and I feel well equipped to solidify these reqs in short order)
don't have great insight into how feasible the things i think we need are

I wrote the the rest of this comment as a series of demands, as it was a little more straightforward than hedging everything with "i think... if it's not infeasible..." :). So, let's definitely discuss what our options and needs are before proceeding with any of the things I've said below!

Thoughts:

We should make logs a dict with three elements: debug, info, and manual
The existing logs array should become logs['debug']
We should siphon off info-level logs into the info array
Only the logs generated by the {{ log(..., info=true) }} context function should be routed to the manual array

The manual logs will be useful for macros that spit out textual information (like a describe macro which returns a string of descriptive statistics about a table).

Instead of re-routing the info-level {{ logs() }} calls in the rpc server, we could alternatively make a print() context function for this purpose. I don't feel strongly about that either way! These functions should work sensibly in CLI or RPC contexts.

Other random thoughts:

We currently drop a backtrace into the debug logs which is good, but we'll want to tidy that up for info/manual level logs if possible
Can we nix the time string for info/manual logs?
What should we do about warnings? I know we shelved some warning conversations here.... let's possibly revisit. I can imagine wanting to see these in the "manual" output too...

The distinction between info and manual logs:
Compiling a SQL string that calls a macro or two results in info-logs like:

2019-03-07 21:08:17,991 (MainThread): Found 13 models, 2 tests, 1 archives, 0 analyses, 204 macros, 0 operations, 2 seed files, 1 sources, 1 None

There's limited utility to info-level logs like these being shown in an interactive dbt client session. A separate array of "manual" logs lets us preserve these logs for debugging use cases, but hide them in the typical compile/execute case.

Things for us to consider:

Are there system-generated info-level logs besides warnings that we should return to dbt clients in interactive sessions? Is it easier to circumvent the one Found 13 models, 2 tests.... log line in the RPC context and instead just return info-level logs to the client in general? Is this something we'd feel good about maintaining long-term?
Is {{ log(...) }} the way we want to surface user-generated information from macros in interactive sessions?

beckjake · 2019-03-08T14:19:09Z

We should make logs a dict with three elements: debug, info, and manual
The existing logs array should become logs['debug']
We should siphon off info-level logs into the info array

Does this mean we should duplicate logs, or that users have to manually reconcile ordering between the debug/info levels if they care about that?

We currently drop a backtrace into the debug logs which is good, but we'll want to tidy that up for info/manual level logs if possible

What do you mean by this? What exactly output do you want from an exception stack trace and where do you want to see it? Do you want them in the debug logs returned to the user, or not? Currently we don't to my knowledge log any stack traces at info level so I guess I'm confused as to why this is a concern at all in the context of your other comments.

Instead of re-routing the info-level {{ logs() }} calls in the rpc server, we could alternatively make a print() context function for this purpose. I don't feel strongly about that either way! These functions should work sensibly in CLI or RPC contexts.

That sounds like it would be harder for no benefit? Currently I just added a log handler, so anything that would get logged goes there and gets sent over the queue. I assume {{ print() }} would have to know if it's in an RPC vs CLI context and react accordingly. Why bother?

Can we nix the time string for info/manual logs?

Yeah. In emit() we get a logRecord and can do whatever we want with it. We don't even have to emit strings, we can emit any json-serializable object. What format, exactly, do you want?

All dbt errors now have proper error codes/messages The raised message at runtime ends up in result.error.data.message The raised message type at runtime ends up in result.error.data.typename result.error.message is a plaintext name for result.error.code dbt.exceptions.Exception.data() becomes result.error.data Collect dbt logs and make them available to requests/responses

cmcarthur · 2019-03-08T14:53:57Z

Instead of re-routing the info-level {{ logs() }} calls in the rpc server, we could alternatively make a print() context function for this purpose. I don't feel strongly about that either way! These functions should work sensibly in CLI or RPC contexts.

That sounds like it would be harder for no benefit? Currently I just added a log handler, so anything that would get logged goes there and gets sent over the queue. I assume {{ print() }} would have to know if it's in an RPC vs CLI context and react accordingly. Why bother?

👍

@beckjake what does the typical INFO output from a RemoteRunTask look like right now?

beckjake · 2019-03-08T15:01:03Z

@cmcarthur The only INFO line I see is: 2019-03-08 08:00:38,609 (MainThread): Found 3 models, 0 tests, 0 archives, 0 analyses, 95 macros, 0 operations, 1 seed files, 1 sources, 1 None'

cmcarthur

looks good. make a MessageType class instead of using random strings :) also from reading this it looks to me like concurrent requests will work great. have you tested that?

cmcarthur · 2019-03-08T14:58:33Z

core/dbt/task/rpc_server.py

+        if error is not None:
+            self.queue.put(['error', error.error])
+        else:
+            self.queue.put(['result', result])


can you enumerate the message types in a separate class?

cmcarthur · 2019-03-08T15:00:43Z

core/dbt/task/rpc_server.py

+        exceeded, raise an RPCTimeoutException.
+        """
+        while True:
+            get_timeout = self._next_timeout()


the timeout solution here is great.

cmcarthur · 2019-03-08T15:05:48Z

core/dbt/task/rpc_server.py

+            self.process.join()
+
+        self.process = None
+        self.queue = None


are these two lines significant from a GC perspective? if so it should probably go into the finally block

Nope, they're not significant, I should just remove them.

Fixes "called by <Unknown>"

…evels

drewbanin

This LGTM! The rpc CLI client was super helpful here. Ship it

RPC: macros

beckjake force-pushed the feature/rpc-improve-dbt-exceptions branch 3 times, most recently from b397868 to e27a1d8 Compare March 7, 2019 17:50

beckjake marked this pull request as ready for review March 7, 2019 17:53

beckjake force-pushed the feature/rpc-improve-dbt-exceptions branch 2 times, most recently from 84dad1b to 5316cd4 Compare March 7, 2019 19:39

drewbanin reviewed Mar 8, 2019

View reviewed changes

cmcarthur reviewed Mar 8, 2019

View reviewed changes

beckjake force-pushed the feature/rpc-improve-dbt-exceptions branch from 5316cd4 to 3360aa3 Compare March 8, 2019 15:19

PR feedback: QueueMessageType class, remove extra assignments

7e18128

beckjake force-pushed the feature/rpc-improve-dbt-exceptions branch from 3360aa3 to 7e18128 Compare March 8, 2019 15:20

Jacob Beck added 6 commits March 8, 2019 10:15

wrap all context-raised exceptions in node info

6620a3c

Fixes "called by <Unknown>"

add NOTICE level logging, make log messages richer types

d890642

use notice logging for "Found x models, ...", change a couple other l…

c86390e

…evels

fix Python 2.7

fbaae2e

when encoding json, handle dates and times like datetimes

fc22cb2

add optional "macros" parameter to dbt rpc calls

81426ae

drewbanin approved these changes Mar 12, 2019

View reviewed changes

beckjake and others added 2 commits March 12, 2019 14:00

Merge pull request #1348 from fishtown-analytics/feature/rpc-with-macros

c1c09f3

RPC: macros

redshift can just change this on you apparently

9c8e088

beckjake merged commit 027a0d2 into dev/wilt-chamberlain Mar 12, 2019

beckjake deleted the feature/rpc-improve-dbt-exceptions branch March 12, 2019 22:17

This was referenced Mar 12, 2019

Attach another log handler to log() in RPC server context #1309

Closed

Add richer exception info to all of the dbt exceptions #1310

Closed

jtcohen6 mentioned this pull request Oct 6, 2021

dbt --warn-error does not error when no models are selected #4006

Closed

5 tasks

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

RPC: Error handling improvements #1341

RPC: Error handling improvements #1341

beckjake commented Mar 6, 2019 •

edited

Loading

drewbanin left a comment

beckjake commented Mar 8, 2019 •

edited

Loading

cmcarthur commented Mar 8, 2019

beckjake commented Mar 8, 2019

cmcarthur left a comment

cmcarthur Mar 8, 2019

cmcarthur Mar 8, 2019

cmcarthur Mar 8, 2019

beckjake Mar 8, 2019

drewbanin left a comment

RPC: Error handling improvements #1341

RPC: Error handling improvements #1341

Conversation

beckjake commented Mar 6, 2019 • edited Loading

drewbanin left a comment

Choose a reason for hiding this comment

beckjake commented Mar 8, 2019 • edited Loading

cmcarthur commented Mar 8, 2019

beckjake commented Mar 8, 2019

cmcarthur left a comment

Choose a reason for hiding this comment

cmcarthur Mar 8, 2019

Choose a reason for hiding this comment

cmcarthur Mar 8, 2019

Choose a reason for hiding this comment

cmcarthur Mar 8, 2019

Choose a reason for hiding this comment

beckjake Mar 8, 2019

Choose a reason for hiding this comment

drewbanin left a comment

Choose a reason for hiding this comment

beckjake commented Mar 6, 2019 •

edited

Loading

beckjake commented Mar 8, 2019 •

edited

Loading