dbt test: Is there a good way to output "what values are invalid" as a failure message?

[gecko655]

When I have:

version: 2

models:
  - name: table_1
    columns:
      - name: col_a
        tests:
          - unique:
              name: table_1.col_a is not unique

then dbt test will output:

08:32:07 Failure in test table_1.col_a is not unique (models/mart/table_1.yml)
08:32:07 Got 54 results, configured to fail if != 0

From this failure message, I understood "54 values are somehow duplicated" but I could not get the information of "what values are duplicated".

I know --store-failures option to store the failure values to DB table, but I needed to query the DB table by myself to see the values.
To be used for CI report, it is too bothersome to look up what values are invalid via DB table for every test failures, instead of reading the CI report itself.

Is there a good way to output "what values are invalid" as a failure message?
If not, how difficult is it to implement? (I am thinking of making a contribution.)

[jtcohen6]

@gecko655 This is a quite-old issue, and so the implementation steps I played around with a few years ago would need some updating, but this is theoretically possible to do what you're describing:

• Show unexpected values when accepted_values test fails #3265 (comment)

I don't think it would scale well to showing all 54 results in the console, but perhaps:

• a sample of first 5-10
• to store as additional contextual information in run_results.json

[gecko655]

Wow! This is exactly what I want!

So, you mean the idea is was considered but the implementation is not yet included in any dbt-core versions?
If so, do you think it is a good idea to re-create #3265 and work on it?

---

I think showing "a sample of first n" ( n=5 by default) and ignore additional values is good enough. I will do so if I were to implement the option.

[jtcohen6]

Correct - the idea was considered when we revamped dbt test a few years ago, but there hasn't been an implementation included in any dbt-core version.

It's not likely to be something that our team prioritizes for near-term development — but you're welcome to open a new issue, and to hack on this a bit if you'd like :)

[gecko655]

Understood. I will consider implementing it when I have time. And if I could implement it cleanly enough, I'd like to make a Pull Request.
Thank you!

[gecko655]

I noticed that I could use the dbt show command (added in dbt 1.5) to show test results saved by store_failure.
This seems to meet my requirements.

doc: https://docs.getdbt.com/reference/commands/show

So, my CI script is going to look like this:

# prerequisite: jq

# Delete previous log if exists
rm -f logs/dbt.log

# Execute the test and show human readable output while output json log file
dbt --log-format-file json test --store-failures -t dev

# Extract the failed test node names
# note: Z022 is 'RunResultFailure' log ( https://github.com/dbt-labs/dbt-core/blob/5814928e3836467ffa90297e871d8a99f8c8b855/core/dbt/events/types.py#L2121-L2128 )
failed_test_names="$(cat logs/dbt.log | jq -r 'select(.info.code == "Z022") | .data.node_name')"

# Show failed values for each failed tests
for failed_test_name in $(echo $failed_test_names);  do
  echo '-----'
  echo "Failed values for test '$failed_test_name':"
  dbt show -t dev -s "$failed_test_name"
done

This script outputs like:

# dbt --log-format-file json test --store-failures -t dev

05:28:51  Running with dbt=1.5.0
05:28:51  Found 10 models, 28 tests, 0 snapshots, 0 analyses, 357 macros, 0 operations, 0 seed files, 3 sources, 0 exposures, 0 metrics, 0 groups
05:28:51  
05:28:53  Concurrency: 4 threads (target='dev')
05:28:53  

... (progress log omitted)

05:29:30  Finished running 28 tests in 0 hours 0 minutes and 38.38 seconds (38.38s).
05:29:30  
05:29:30  Completed with 1 errors and 0 warnings:
05:29:30  
05:29:30  Failure in test duplicate_xxxxxxx (tests/duplicate_xxxxxxx.sql)
05:29:30    Got 1 result, configured to fail if != 0
05:29:30  
05:29:30    compiled Code at target/compiled/project_name/tests/duplicate_xxxxxxx.sql
05:29:30  
05:29:30    See test failures:
  -----------------------------------------------------------------------------------------------------
  select * from `gcp_project`.`bq_dataset`.`duplicate_xxxxxxx`
  -----------------------------------------------------------------------------------------------------
05:29:30  Done. PASS=27 WARN=0 ERROR=1 SKIP=0 TOTAL=28

# failed_test_names="$(cat logs/dbt.log | jq -r 'select(.info.code == "Z022") | .data.node_name')"
# for failed_test_name in $(echo $failed_test_names);  do
#   echo '-----'
#   echo "Failed values on $failed_test_name:"
#   dbt show -t dev -s "$failed_test_name"
# done

Failed values on duplicate_xxxxxxx:
05:29:33  Running with dbt=1.5.0
05:29:33  Found 10 models, 28 tests, 0 snapshots, 0 analyses, 357 macros, 0 operations, 0 seed files, 3 sources, 0 exposures, 0 metrics, 0 groups
05:29:33  
05:29:34  Concurrency: 4 threads (target='dev')
05:29:34  
05:29:36  Previewing node 'duplicate_xxxxxxx':
| from_field         |
| ------------------ |
| some_invalid_value |

It contains some verbose output, but this is good enough for me to use as a CI report.

[jtcohen6]

Nice answer!!

You can also use dbt show without --store-failures, by passing in the name of the failing test — though this has the effect of running the same test query twice:

$ dbt build
08:52:23  Running with dbt=1.7.0-a1
08:52:23  Registered adapter: postgres=1.7.0-a1
08:52:24  Found 1 model, 1 test, 0 sources, 0 exposures, 0 metrics, 352 macros, 0 groups, 0 semantic models
08:52:24
08:52:24  Concurrency: 5 threads (target='dev')
08:52:24
08:52:24  1 of 2 START sql view model dbt_jcohen.my_model ................................ [RUN]
08:52:24  1 of 2 OK created sql view model dbt_jcohen.my_model ........................... [CREATE VIEW in 0.12s]
08:52:24  2 of 2 START test unique_my_model_id ........................................... [RUN]
08:52:24  2 of 2 FAIL 1 unique_my_model_id ............................................... [FAIL 1 in 0.05s]
08:52:24
08:52:24  Finished running 1 view model, 1 test in 0 hours 0 minutes and 0.33 seconds (0.33s).
08:52:24
08:52:24  Completed with 1 error and 0 warnings:
08:52:24
08:52:24  Failure in test unique_my_model_id (models/schema.yml)
08:52:24    Got 1 result, configured to fail if != 0
08:52:24
08:52:24    compiled Code at target/compiled/my_dbt_project/models/schema.yml/unique_my_model_id.sql
08:52:24
08:52:24  Done. PASS=1 WARN=0 ERROR=1 SKIP=0 TOTAL=2

$ dbt show -s unique_my_model_id
08:52:35  Running with dbt=1.7.0-a1
08:52:35  Registered adapter: postgres=1.7.0-a1
08:52:35  Found 1 model, 1 test, 0 sources, 0 exposures, 0 metrics, 352 macros, 0 groups, 0 semantic models
08:52:35
08:52:35  Concurrency: 5 threads (target='dev')
08:52:35
08:52:35  Previewing node 'unique_my_model_id':
| unique_field | n_records |
| ------------ | --------- |
|            1 |         2 |

[gecko655]

That's good to know!
So dbt show has nothing to do with dbt test --store_failures, but dbt show itself executes the query and gets the data.
Thank you for your help 🙏