Fix exception handling masking on cleanup (#997)

[beckjake]

Fix #997 by improving error handling during cleanup.

I'm not sure this is exactly what we want, but the general idea here is:

• when we enter the re-raising except: block, stash the exception.
• in the finally block, try to release the connection. On failure:
  • log the message at error and the stack trace at debug.
  • If we have a result that is not errored, set it to an error - this will trigger a run failure
• in the finally block, regardless of what happened with releasing, if we are in the middle of an exception handling stack, re-raise the original.

I don't have logs for the original failure so this is about as good as I can do. I suspect we'll also need to add explicit handling for SSL errors and converting them into RuntimeExceptions if we haven't already. At the end of the day, the bad error message comes from how main.py handles non-dbt errors.

[drewbanin]

I think traceback isn't imported here

[drewbanin]

I gave this a spin locally and found one issue around a missing import. When I imported traceback, I saw this behavior on this branch:

Found 1 operations, 179 macros, 1 analyses, 1 seed files, 1 tests, 4 models, 1 archives

09:33:45 | Concurrency: 8 threads (target='dev')
09:33:45 |
09:33:45 | 1 of 4 START view model demo_schema.base_payments.................... [RUN]
09:33:45 | 2 of 4 START table model demo_schema.sleep........................... [RUN]
09:33:45 | 3 of 4 START view model demo_schema.base_orders...................... [RUN]
09:33:45 | 3 of 4 OK created view model demo_schema.base_orders................. [CREATE VIEW in 0.14s]
09:33:45 | 1 of 4 OK created view model demo_schema.base_payments............... [CREATE VIEW in 0.17s]
Error releasing connection for node sleep: connection already closed
09:33:49 | 2 of 4 ERROR creating table model demo_schema.sleep.................. [ERROR in 3.53s]
09:33:49 | 4 of 4 START view model demo_schema.orders........................... [RUN]
09:33:49 | 4 of 4 ERROR creating view model demo_schema.orders.................. [ERROR in 0.02s]
09:33:49 |
09:33:49 | Finished running 1 table models, 3 view models in 3.67s.

Completed with 2 errors:

Database Error in model sleep (models/sleep.sql)
  terminating connection due to administrator command
  server closed the connection unexpectedly
        This probably means the server terminated abnormally
        before or while processing the request.
  compiled SQL at target/compiled/my_project/sleep.sql

Database Error in model orders (models/orders.sql)
  terminating connection due to administrator command
  server closed the connection unexpectedly
        This probably means the server terminated abnormally
        before or while processing the request.
  compiled SQL at target/compiled/my_project/orders.sql

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

It's a little funky that the line:

Error releasing connection for node sleep: connection already closed

shows up in the terminal. I think that's due to logger.debug call that was changed to logger.error. This error messages at the bottom are really good though! I think it's exactly the behavior we were looking for.

---

I was able to test this out by spinning up a postgres server:

postgres -D /usr/local/var/postgres/ -p 5433

then ctrl-c'ing it mid-run. This model is helpful:

-- models/sleep.sql

{{ config(materialized='table') }}

select 1 as id from pg_sleep(10)

[drewbanin]

see comments above

[beckjake]

Ok, comments addressed - I lowered that error back to debug and added the missing import.

[drewbanin]

ship it!