[CT-2267] [Bug] Unexpected stacktrace for dbt --fail-fast run

[dbeatty10]

Is this a new bug in dbt-core?

• I believe this is a new bug in dbt-core
• I have searched the existing issues, and I could not find an existing issue for this bug

Current Behavior

With 1.5.0-b2, running dbt --fail-fast run emits a long stack trace to standard out.

Expected Behavior

I'd like a TL;DR of the error emitted to standard out instead.

Steps To Reproduce

Let's say I have a model like this:

my_bad_model.sql

this will raise an error

And then I run it:

dbt run -s my_bad_model

I get reasonable output like this when using dbt-redshift:

20:58:52  Running with dbt=1.5.0-b2
20:58:52  Found 3 models, 0 tests, 0 snapshots, 0 analyses, 337 macros, 0 operations, 3 seed files, 0 sources, 0 exposures, 0 metrics, 0 groups
20:58:52  
20:58:55  Concurrency: 5 threads (target='redshift')
20:58:55  
20:58:55  1 of 1 START sql view model dbt_dbeatty.my_bad_model ........................... [RUN]
20:58:56  1 of 1 ERROR creating sql view model dbt_dbeatty.my_bad_model .................. [ERROR in 0.84s]
20:58:57  
20:58:57  Finished running 1 view model in 0 hours 0 minutes and 4.27 seconds (4.27s).
20:58:57  
20:58:57  Completed with 1 error and 0 warnings:
20:58:57  
20:58:57  Database Error in model my_bad_model (models/my_bad_model.sql)
20:58:57    {'S': 'ERROR', 'C': '42601', 'M': 'syntax error at or near "this"', 'P': '65', 'F': '/home/ec2-user/padb/src/pg/src/backend/parser/parser_scan.l', 'L': '732', 'R': 'yyerror'}
20:58:57    compiled Code at target/run/my_dbt_project/models/my_bad_model.sql
20:58:57  
20:58:57  Done. PASS=0 WARN=0 ERROR=1 SKIP=0 TOTAL=1

But then I try to add the --fail-fast flag

dbt --fail-fast run -s my_bad_model

The output dumps a big long stacktrace to standard out 😢

21:02:19  Running with dbt=1.5.0-b2
21:02:19  Found 3 models, 0 tests, 0 snapshots, 0 analyses, 337 macros, 0 operations, 3 seed files, 0 sources, 0 exposures, 0 metrics, 0 groups
21:02:19  
21:02:22  Concurrency: 5 threads (target='redshift')
21:02:22  
21:02:22  1 of 1 START sql view model dbt_dbeatty.my_bad_model ........................... [RUN]
21:02:23  1 of 1 ERROR creating sql view model dbt_dbeatty.my_bad_model .................. [ERROR in 0.84s]
21:02:23  CANCEL query model.my_dbt_project.my_bad_model ................................. [CANCEL]
21:02:23  
21:02:23  Database Error in model my_bad_model (models/my_bad_model.sql)
21:02:23    {'S': 'ERROR', 'C': '42601', 'M': 'syntax error at or near "this"', 'P': '65', 'F': '/home/ec2-user/padb/src/pg/src/backend/parser/parser_scan.l', 'L': '732', 'R': 'yyerror'}
21:02:23    compiled Code at target/run/my_dbt_project/models/my_bad_model.sql
21:02:23  
21:02:23  Finished running 1 view model in 0 hours 0 minutes and 3.44 seconds (3.44s).
Traceback (most recent call last):
  File "/Users/dbeatty/projects/environments/redshift_1.5.0b1/bin/dbt", line 8, in <module>
    sys.exit(cli())
  File "/Users/dbeatty/projects/environments/redshift_1.5.0b1/lib/python3.9/site-packages/click/core.py", line 1130, in __call__
    return self.main(*args, **kwargs)
  File "/Users/dbeatty/projects/environments/redshift_1.5.0b1/lib/python3.9/site-packages/click/core.py", line 1055, in main
    rv = self.invoke(ctx)
  File "/Users/dbeatty/projects/environments/redshift_1.5.0b1/lib/python3.9/site-packages/click/core.py", line 1657, in invoke
    return _process_result(sub_ctx.command.invoke(sub_ctx))
  File "/Users/dbeatty/projects/environments/redshift_1.5.0b1/lib/python3.9/site-packages/click/core.py", line 1404, in invoke
    return ctx.invoke(self.callback, **ctx.params)
  File "/Users/dbeatty/projects/environments/redshift_1.5.0b1/lib/python3.9/site-packages/click/core.py", line 760, in invoke
    return __callback(*args, **kwargs)
  File "/Users/dbeatty/projects/environments/redshift_1.5.0b1/lib/python3.9/site-packages/click/decorators.py", line 26, in new_func
    return f(get_current_context(), *args, **kwargs)
  File "/Users/dbeatty/projects/environments/redshift_1.5.0b1/lib/python3.9/site-packages/dbt/cli/requires.py", line 53, in wrapper
    return func(*args, **kwargs)
  File "/Users/dbeatty/projects/environments/redshift_1.5.0b1/lib/python3.9/site-packages/dbt/cli/requires.py", line 89, in wrapper
    return func(*args, **kwargs)
  File "/Users/dbeatty/projects/environments/redshift_1.5.0b1/lib/python3.9/site-packages/dbt/cli/requires.py", line 111, in wrapper
    return func(*args, **kwargs)
  File "/Users/dbeatty/projects/environments/redshift_1.5.0b1/lib/python3.9/site-packages/dbt/cli/requires.py", line 137, in wrapper
    return func(*args, **kwargs)
  File "/Users/dbeatty/projects/environments/redshift_1.5.0b1/lib/python3.9/site-packages/dbt/cli/requires.py", line 172, in wrapper
    return func(*args, **kwargs)
  File "/Users/dbeatty/projects/environments/redshift_1.5.0b1/lib/python3.9/site-packages/dbt/cli/main.py", line 432, in run
    results = task.run()
  File "/Users/dbeatty/projects/environments/redshift_1.5.0b1/lib/python3.9/site-packages/dbt/task/runnable.py", line 438, in run
    result = self.execute_with_hooks(selected_uids)
  File "/Users/dbeatty/projects/environments/redshift_1.5.0b1/lib/python3.9/site-packages/dbt/task/runnable.py", line 401, in execute_with_hooks
    res = self.execute_nodes()
  File "/Users/dbeatty/projects/environments/redshift_1.5.0b1/lib/python3.9/site-packages/dbt/task/runnable.py", line 350, in execute_nodes
    self.run_queue(pool)
  File "/Users/dbeatty/projects/environments/redshift_1.5.0b1/lib/python3.9/site-packages/dbt/task/runnable.py", line 280, in run_queue
    self._raise_set_error()
  File "/Users/dbeatty/projects/environments/redshift_1.5.0b1/lib/python3.9/site-packages/dbt/task/runnable.py", line 240, in _raise_set_error
    raise self._raise_next_tick
dbt.exceptions.FailFastError: FailFast Error in model my_bad_model (models/my_bad_model.sql)
  Failing early due to test failure or runtime error

Relevant log output

No response

Environment

$ dbt --version                            
Core:
  - installed: 1.5.0-b2
  - latest:    1.4.4    - Ahead of latest version!

Plugins:
  - redshift: 1.5.0b1

Which database adapter are you using with dbt?

redshift

Additional Context

No response

[dbeatty10]

@jtcohen6 offered this hunch in Slack:

My hunch would be, it has to do with us no longer handling FailFastError in quite the same way, possibly due to this sort of logic being removed. So it may require touching / re-adding logic similar to the fix for this regression

[stu-k]

@dbeatty10 Should we raise a small exception without the traceback here, or should we continue firing the traceback event as we did in 1.4?

@jtcohen6 This may be a good idea to pull out into a spike or a bigger discussion given we're not sure how exceptions should be handled in the cli vs from dbtRunner.

[dbeatty10]

@stu-k the traceback in this case was surprising, so definitely without the stacktrace.

From here it looks like the MainStackTrace was only fired if the exception was not a dbtException (dbt.Exceptions.Exception).

@jtcohen6 had an idea how to handle exceptions in #7010 (comment), so maybe that can be an idea considered in a spike or bigger discussion.

[jtcohen6]

This requires modifying (= re-adding) the same spot in the execution flow as #7010, so we've estimated this one as an extension of that one.

[jtcohen6]

This ticket can be closed when:

• We have added back MainEncounteredError and MainStackTrace, at parity with how it was in v1.4, rather than just throwing whatever exception we encounter

Restoring these logging events is also needed for dbt-server integration. Slack thread with additional context