FreshnessStatus.Error causes exit status of 1 but no error level logging.

[wrgoldstein]

Describe the bug

When I run dbt --log-format=json source snapshot-freshness and there is a SourceFreshnessResult with status = FreshnessStatus.Error: 'error', the log level of the output is INFO but message has a red ERROR and the cli returns with status code 1.

Steps To Reproduce

As far as I can tell this will happen with any stale snapshot when you run dbt --log-format=json source snapshot-freshness.

Expected behavior

I expect the log level of the output to be error.

Screenshots and log output

{
  "timestamp": "2020-08-03T19:16:19.227088Z", 
  "message": "15:16:19 | 1 of 1 ERROR STALE freshness of foo.bar.............. [\u001b[31mERROR STALE\u001b[0m in 2.43s]", 
  "channel": "dbt", "level": 11,
  "levelname": "INFO",    <------------ ???
  "thread_name": "Thread-1", 
  "process": 65779, 
  "extra": {"unique_id":  "source.db.sch.tab", "run_state": "running"}
}

System information

Which database are you using dbt with?

• postgres
• redshift
• bigquery
• snowflake
• other (specify: ____________)

The output of dbt --version:

installed version: 0.16.1
   latest version: 0.17.2

The operating system you're using: MacOS Catalina

The output of python --version: 3.8.1

Additional context

We parse the json output of a dbt run and report any ERROR level log statements to a monitoring tool, so this causes us to have a gap in our reporting.

Please let me know if I've mistaken a feature for a bug. Happy to contribute a fix if it is something that needs fixing.

[jtcohen6]

@wrgoldstein Thanks for the detailed writeup. I think there's a reason for the behavior here, but I'm not convinced that it's how we want it to be in the long run.

In dbt source snapshot-freshness:

• dbt returns logs with {"level": 14, "levelname": "ERROR"} if it runs an invalid query as part of source freshness checks, e.g. if the loaded_at_field is misspelled
• dbt returns logs with {"level": 11, "levelname": "INFO"} and message ERROR STALE. In sources.json, it will report "state": "error". (We want to rename this to status per the proposal in run results reporting is a mess #2493).

Compare that to dbt test:

• dbt returns logs with {"level": 14, "levelname": "ERROR"} if a test errors when running (invalid SQL) OR if the test runs successfully and returns >0 results (FAIL)

@beckjake I'm inclined to say that snapshot-freshness should return level-13 (WARNING) and level-14 (ERROR) log output for sources that are beyond those respective thresholds. What do you think?

[beckjake]

I don't have any feelings either way. Historically, dbt's stance has been that there are really only two levels: debug, and info - debug goes into the log file, and everything info and up also goes to stdout. I guess now that we show log levels we could also make changes here. It's buried behind a flag so I think it's hard to justify spending all that much energy on it.

I am in favor of accepting PRs that fix this, and this is probably a "good first issue".

[tpilewicz]

Hello, I would like to give this a try as a first contribution. Unless you're already on it, @wrgoldstein ?

Just to be sure I'm going the right way, it seems to me that I should make printer.print_fancy_output_line able to call logger.warning and logger.error, depending on its status argument. Is that correct?

[wrgoldstein]

I'm not! Go for it :)

[jtcohen6]

resolved by #2723