show on-run-start/end + hooks in dbt output

[drewbanin]

Feature

dbt doesn't output any info about the start/end hooks that it runs, so it can be hard to understand why the stdout seems to stall. Instead, dbt should log the start/end hooks that it is running to the console.

Example:

$ dbt run

Found 3 models, 2 tests, 0 archives, 0 analyses, 96 macros, 2 operations, 0 seed files

12:27:16 | Concurrency: 8 threads (target='dev')
12:27:16 |
12:27:16 | Running 3 on-run-start hooks:
12:27:16 | 1 of 3 START grant usage on ...
12:27:16 | 2 of 3 START grant create on ...
12:27:16 | 3 of 3 START insert into public._audit ...
12:27:16 |
12:27:16 | Running 2 models:
12:27:16 | 1 of 2 START table model demo_schema.dep............................. [RUN]
12:27:16 | 2 of 2 START incremental model demo_schema.local..................... [RUN]
12:27:16 | 1 of 2 OK created table model demo_schema.dep........................ [SELECT 1 in 0.13s]
12:27:16 | 2 of 2 OK created incremental model demo_schema.local................ [INSERT 0 1 in 0.14s]
12:27:16 |
12:27:16 | Running 3 on-run-end hooks:
12:27:16 | 1 of 3 START grant usage on ...
12:27:16 | 2 of 3 START grant create on ...
12:27:16 | 3 of 3 START insert into public._audit ...
12:27:16 |
12:27:16 | Finished running 1 table models, 1 incremental models, 6 run hooks in 0.32s.

Completed successfully

Done. PASS=2 ERROR=0 SKIP=0 TOTAL=2

If there are no on-run-start/end hooks, dbt should skip those sections of the info logs. Note that we should also add something like 6 run hooks to the final line of model run logs.

^ this is an initial idea of how this could look, but I don't know that I love it. Very open to other ideas!

[vijaykiran]

I'd like to take a stab at this.

[drewbanin]

Cool @vijaykiran! Let me know if there's anything I can do to help out when you give it a shot :)

[EdPre]

This looks good