Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Output run hooks (#696) #1440

Merged
merged 7 commits into from
May 10, 2019
Merged

Output run hooks (#696) #1440

Show file tree
Hide file tree
Changes from 2 commits
Commits
Show all changes
7 commits
Select commit Hold shift + click to select a range
c190858
suppress some cache logger noise
May 3, 2019
80482aa
add on-run-start/on-run-end hook logging
May 3, 2019
9507669
PR feedback
May 7, 2019
ec8277b
add color to hooks, give hooks names
May 9, 2019
5d05bf0
PR feedback
May 9, 2019
58bf73d
Update core/dbt/task/run.py
beckjake May 9, 2019
f6bf8d9
PR feedback
May 10, 2019
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
4 changes: 4 additions & 0 deletions core/dbt/logger.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -67,6 +67,10 @@ def notice(self, msg, *args, **kwargs):

# provide this for the cache.
CACHE_LOGGER = logging.getLogger('dbt.cache')
# add a dummy handler to avoid `No handlers could be found for logger`
nothing_handler = logging.StreamHandler()
nothing_handler.setLevel(CRITICAL)
CACHE_LOGGER.addHandler(nothing_handler)
# provide this for RPC connection logging
RPC_LOGGER = logging.getLogger('dbt.rpc')

Expand Down
24 changes: 20 additions & 4 deletions core/dbt/task/run.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -16,6 +16,10 @@


class RunTask(CompileTask):
def __init__(self, args, config):
super(RunTask, self).__init__(args, config)
self.ran_hooks = []

def raise_on_first_error(self):
return False

Expand All @@ -33,11 +37,22 @@ def run_hooks(self, adapter, hook_type, extra_context):
# b/c psycopg2 automatically begins a transaction when a connection
# is created.
adapter.clear_transaction()
if not ordered_hooks:
return

for i, hook in enumerate(ordered_hooks):
plural = 'hook' if len(ordered_hooks) == 1 else 'hooks'
dbt.ui.printer.print_timestamped_line("")
dbt.ui.printer.print_timestamped_line(
'Running {} {} {}'.format(len(ordered_hooks), hook_type, plural)
)

for idx, hook in enumerate(ordered_hooks, start=1):
compiled = compile_node(adapter, self.config, hook,
self.manifest, extra_context)
statement = compiled.wrapped_sql
dbt.ui.printer.print_timestamped_line(
'{} of {} START {}'.format(idx, len(ordered_hooks), statement)
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Can we format this like all of the other timestamped lines that dbt prints?

07:58:48 | 1 of 2 START hook: grant usage on schema......... [RUN]
07:58:48 | 1 of 2 OK hook: grant usage on schema......... [GRANT in 0.4s]
07:58:48 | 2 of 2 START hook: grant select on ......... [RUN]
07:58:48 | 2 of 2 OK hook: grant select on......... [GRANT in 2.8s]

I think we'll also want to reshape/truncate the hook SQL. It's not uncommon to do operational things (like create UDFs, or insert into an audit table in these hooks, and they currently take over the stdout!

I imagine we can do something like (pseudocode):

hook_text = hook.replace("\n", " ")[0:60] + "..."

This doesn't need to be the exact same SQL that dbt is actually running, it just needs to be a stand-in for a name! Maybe some day it will make sense to name hooks, but today is not that day :)

Let's also include a line for when the hooks completes, and a status if it's easy to grab. I think a lot of folks don't actually have insight into how long their hooks currently take, and I be it will be helpful to expose this info to them!

Here's an example hook for testing:

on-run-start:
 - "{{ load_udfs() }}"

-- macros/udfs.sql (imagine this did something useful....)

CREATE OR REPLACE FUNCTION no_op()
RETURNS void AS $$
$$ LANGUAGE SQL;

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

We can also be pretty aggressive with the truncation here -- the point is just to show that hooks are running, and to indicate how long they have taken. If folks want to dig further into that, they can find the full queries in the logs!

)

hook_index = hook.get('index', len(hooks))
hook_dict = get_hook_dict(statement, index=hook_index)
Expand All @@ -49,6 +64,8 @@ def run_hooks(self, adapter, hook_type, extra_context):

if len(sql.strip()) > 0:
adapter.execute(sql, auto_begin=False, fetch=False)
self.ran_hooks.append(hook)
dbt.ui.printer.print_timestamped_line("")

def safe_run_hooks(self, adapter, hook_type, extra_context):
try:
Expand All @@ -57,9 +74,8 @@ def safe_run_hooks(self, adapter, hook_type, extra_context):
logger.info("Database error while running {}".format(hook_type))
raise

@classmethod
def print_results_line(cls, results, execution_time):
nodes = [r.node for r in results]
def print_results_line(self, results, execution_time):
nodes = [r.node for r in results] + self.ran_hooks
stat_line = dbt.ui.printer.get_counts(nodes)

execution = ""
Expand Down
2 changes: 2 additions & 0 deletions core/dbt/ui/printer.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -83,6 +83,8 @@ def get_counts(flat_nodes):

if node.get('resource_type') == NodeType.Model:
t = '{} {}'.format(get_materialization(node), t)
elif node.get('resource_type') == NodeType.Operation:
t = 'hook'

counts[t] = counts.get(t, 0) + 1

Expand Down