[ADAP-377] [CT-2308] [Bug] 1.5.0-b3 has funky error logging

[joellabes]

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

While looking at the debug logs for a dbt utils CI job, I noticed that there's some funky things happening in the logs.

1. Entire JSON object being dumped for database errors:

Observed:

01:59:07  Finished running 67 seeds in 0 hours 0 minutes and 23.98 seconds (23.98s).
01:59:07  
01:59:07  Completed with 1 error and 0 warnings:
01:59:07  
01:59:07  Database Error in seed data_events_20180103 (data/sql/data_events_20180103.csv)
01:59:07    {'S': 'ERROR', 'C': '42501', 'M': 'permission denied for schema dbt_utils_integration_tests_redshift_events', 'F': '../src/pg/src/backend/catalog/aclchk.c', 'L': '2946', 'R': 'aclcheck_error'}
01:59:07  
01:59:07  Done. PASS=66 WARN=0 ERROR=1 SKIP=0 TOTAL=67

Expected:

01:59:07  Finished running 67 seeds in 0 hours 0 minutes and 23.98 seconds (23.98s).
01:59:07  
01:59:07  Completed with 1 error and 0 warnings:
01:59:07  
01:59:07  Database Error in seed data_events_20180103 (data/sql/data_events_20180103.csv)
01:59:07    permission denied for schema dbt_utils_integration_tests_redshift_events
01:59:07  
01:59:07  Done. PASS=66 WARN=0 ERROR=1 SKIP=0 TOTAL=67

2. Wrong output for successful model builds on Redshift

Observed:

01:59:13  4 of 47 START sql view model dbt_utils_integration_tests_redshift.test_deduplicate  [RUN]
[...]
01:59:14  4 of 47 OK created sql view model dbt_utils_integration_tests_redshift.test_deduplicate  [cursor.rowcount = -1 in 0.98s]

Expected:
I don't remember offhand, but it sure isn't cursor.rowcount = -1! Isn't it meant to be something like SUCCESS 1 for views and SUCCESS [impacted row count] for tables?

Expected Behavior

Noted above

Steps To Reproduce

Check out this pipeline for the specific logs https://app.circleci.com/pipelines/github/dbt-labs/dbt-utils/1474/workflows/3b5f8db1-2663-4366-8c53-8a2e7cfb2899/jobs/4810

Relevant log output

No response

Environment

- OS: Ubuntu 20.04.5 LTS
- Python: cimg/python:3.9

Core:
  - installed: 1.5.0-b3
  - latest:    1.4.5    - Ahead of latest version!

Plugins:
  - postgres:  1.5.0b3 - Ahead of latest version!
  - snowflake: 1.5.0b2 - Ahead of latest version!
  - redshift:  1.5.0b2 - Ahead of latest version!
  - bigquery:  1.5.0b2 - Ahead of latest version!

Which database adapter are you using with dbt?

redshift

Additional Context

No response

[jtcohen6]

Thanks for flagging @joellabes! I think this is due to our switch to using redshift-python-connector in dbt-redshift v1.5. I'm going to transfer over to the dbt-redshift repo so folks there can take a deeper look.

[mikealfare]

While troubleshooting #365, I found that RedshiftConnectionManager.get_response() creates a message using cursor.rowcount whereas PostgresConnectionManager.get_response() gets the message from cursor.statusmessage. I think that could be the source of item 2 above. The cursor for dbt-redshift is an instance of redshift_connector.Cursor, which does not have a status message that I can find. So we might need to think about how to handle that if we want to change it.

[Fleid]

Lined up to the next sprint

[VersusFacit]

Hi team, I've got a fix for the first bug. 🎉

However, Mike's point stands in the unfortunate way. There is no easy field -- judging both from my experiences and looking over redshift documentation -- to replicate the old behavior in the cursor object that redshift provides.

One thing we can do is Jerry rig a success message, but not necessarily a count of rows affected. Here are some paths forward for now:

1. Success message but not necessarily a row count
2. Try to use the execute function on the cursor to extract the row count of the last command sent to a database – to be clear I have no idea if this is a good idea (I'm concerned about concurrency issues) but in theory I could see extracting that information through another query
3. Keep researching system objects and hope that we find something that replicates the Postgres cursor

In the meantime, I'm going to look more in core that might be causing this bug that I'm overlooking, just in case.

[Fleid]

I'm feeling number 1 for 1.5 to be honest...

[VersusFacit]

1 makes sense given additional research I did into the library and comparing against core. What's nice is that the offending function is only used as far as I can tell when dbt-redshift completes a successful run. The old behavior for seed, test, etc. in both success and failure is preserved. We just lost the row count for successful run operations – doesn't seem like much of a loss here.

PR is updated to illustrate more of what I'm talking about