WIP: Add hook information to the log

[vijaykiran]

This commit adds logging info for on-run-start/end hooks (Fixes #696)

Here's the sample output.

Found 3 models, 0 tests, 0 archives, 0 analyses, 95 macros, 7 operations, 1 seed files

21:04:16 |
21:04:16 | Running 3 on-run-start hooks:
21:04:16 | 1 of 3 select 'ON RUN START HOOK - 1'
21:04:16 | 2 of 3 select 'ON RUN START HOOK - 2'
21:04:16 | 3 of 3 select 'ON RUN START HOOK - 3'
21:04:16 | Concurrency: 4 threads (target='default')
21:04:16 |
21:04:16 | 1 of 3 START view model dbt_postgres.moby_dick_base.................. [RUN]
21:04:16 | 1 of 3 OK created view model dbt_postgres.moby_dick_base............. [CREATE VIEW in 0.05s]
21:04:16 | 2 of 3 START table model dbt_postgres.word_count..................... [RUN]
21:04:16 | 2 of 3 OK created table model dbt_postgres.word_count................ [SELECT 27390 in 0.32s]
21:04:16 | 3 of 3 START view model dbt_postgres_new.word_count_custom_schema.... [RUN]
21:04:16 | 3 of 3 OK created view model dbt_postgres_new.word_count_custom_schema [CREATE VIEW in 0.02s]
21:04:16 |
21:04:16 | Running 2 on-run-end hooks:
21:04:16 | 1 of 2 select 'ON RUN END HOOK - 1'
21:04:16 | 2 of 2 select 'ON RUN END HOOK - 2'
21:04:16 |
21:04:16 | Finished running 2 view models, 1 table models in 0.54s.

Adding the hook count to the final line (Finished ...) seems more invasive because as far as I understand, hooks don't return results object. @drewbanin any pointers on how to do this in a clean way?

[drewbanin]

hey @vijaykiran - thanks for this PR -- it looks like a great start. I think you're right that we will want to make hooks return a results object. That way, we could show the status of the query, as well as how long it took to run.

I'm also not sure that I love the output shown here (and described in the original issue). I think that for any non-trivial SQL, showing the full statement is going to be overly verbose.

Maybe we can do something like:

21:04:16 | Running 3 on-run-start hooks:
21:04:16 | 1 of 3 on-run-start-1................. [RUN]
21:04:16 | 1 of 3 on-run-start-1................. [SELECT in 0.05s]
21:04:16 | 2 of 3 on-run-start-2................. [RUN]
21:04:16 | 2 of 3 on-run-start-2................. [SELECT in 0.05s]
21:04:16 | 3 of 3 on-run-start-3................. [RUN]
21:04:16 | 3 of 3 on-run-start-3................. [SELECT in 0.05s]
21:04:16 |
21:04:16 | Concurrency: 4 threads (target='default')

[drewbanin]

you can construct a RunModelResult object here with something like:

res = RunModelResult(hook, status=status)

You can get a status from the adapter.execute call below. That will return a tuple of a status and an Agate dataframe, as shown here: https://github.com/fishtown-analytics/dbt/blob/dev/stephen-girard/dbt/adapters/base/impl.py#L138

eg:

status, _ = adapter.execute(sql, model_name=model_name, auto_begin=False, fetch=False)

[drewbanin]

^ I think this will work, but I haven't tested it. Let me know if you hit any more snags

[vijaykiran]

@drewbanin Thanks for the feedback!

I'm also not sure that I love the output shown here (and described in the original issue). I think that for any non-trivial SQL, showing the full statement is going to be overly verbose.

I agree and I think adding SQL become unreadable quickly. I'll update the code. I'll dig a bit deeper into Results stuff this weekend.

[vijaykiran]

I'll open a new one with the Results work, thanks for the review @drewbanin !