[CT-2083] [Bug] Store failures log message keeps reporting the failures table as None

[jsnb-devoted]

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

I didn't see anyone mention this yet so I'm not ruling out that it is user error somewhere but after upgrading to 1.4.1 all of our test failure logs stopped showing the --store-failures table in the query:

[2023-02-09, 00:23:44 UTC] {dbt_hook.py:154} INFO - �[0m00:23:44    See test failures:
[2023-02-09, 00:23:44 UTC] {dbt_hook.py:154} INFO -   ------------------
[2023-02-09, 00:23:44 UTC] {dbt_hook.py:154} INFO -   select * from None
[2023-02-09, 00:23:44 UTC] {dbt_hook.py:154} INFO -   ------------------

Expected Behavior

[2023-02-01, 11:44:39 UTC] {dbt_hook.py:154} INFO - �[0m11:44:39    See test failures:
[2023-02-01, 11:44:39 UTC] {dbt_hook.py:154} INFO -   ---------------------------------------------------------------------
[2023-02-01, 11:44:39 UTC] {dbt_hook.py:154} INFO -   select * from PROD.dbt_test__audit.measures_rate_of_change_validation
[2023-02-01, 11:44:39 UTC] {dbt_hook.py:154} INFO -   ---------------------------------------------------------------------

Steps To Reproduce

dbt test with any failing tests

Relevant log output

No response

Environment

- OS: ubuntu
- Python: 3.9.10
- dbt: 1.4.1

Which database adapter are you using with dbt?

snowflake

Additional Context

I tried poking around the new logging code to see if there was something obvious. It looks like the property that it is trying to print is self.relation_name but I don't know what should go there in its place. (code)

[jtcohen6]

@jsnb-devoted Thanks for opening!

I wasn't able to reproduce this quickly, when I tried just now:

-- models/my_model.sql
select 1 as id
union all
select 1 as id

# models/schema.yml
version: 2
models:
  - name: my_model
    columns:
      - name: id
        tests:
          - unique

$ dbt build --store-failures
23:57:38  Running with dbt=1.4.1
...
23:57:39  Failure in test unique_my_model_id (models/schema.yml)
23:57:39    Got 1 result, configured to fail if != 0
23:57:39
23:57:39    compiled Code at target/compiled/test/models/schema.yml/unique_my_model_id.sql
23:57:39
23:57:39    See test failures:
  -----------------------------------------------------------------------
  select * from "jerco"."dbt_jcohen_dbt_test__audit"."unique_my_model_id"
  -----------------------------------------------------------------------
23:57:39
23:57:39  Done. PASS=2 WARN=0 ERROR=1 SKIP=0 TOTAL=3

So, some follow-up questions that may (or may not) help with debugging, and getting to a reproduction case:

• Are you seeing this for all tests? Some tests in particular?
• If you pop open manifest.json and take a look at one of the tests in question, does it have database, schema, alias defined, and only relation_name missing / None?

[jsnb-devoted]

Thanks for taking a look at this @jtcohen6 -- that definitely makes me think it is us. I'm AFK for a bit but I will check out the manifest first thing tomorrow.

[jsnb-devoted]

As you expected -- relation_name is null and database/schema/alias are all populated as expected.

This has happened for all test failures that I have seen so far. Not sure I have a great way of confirming it is truly 100% of them.

For this case I ran/tested the model directly:

dbt run -m sample_model
dbt -- test -m sample_model --store-failures

Below is the full node from the manifest:

        "test.devoted.dbt_expectations_expect_table_row_count_to_be_between_sample_model_1.374a0bca32": {
            "test_metadata": {
                "name": "expect_table_row_count_to_be_between",
                "kwargs": {
                    "min_value": 1,
                    "model": "{{ get_where_subquery(ref('sample_model')) }}"
                },
                "namespace": "dbt_expectations"
            },
            "database": "dev_jbrownstein",
            "schema": "dbt_test__audit",
            "name": "dbt_expectations_expect_table_row_count_to_be_between_sample_model_1",
            "resource_type": "test",
            "package_name": "devoted",
            "path": "dbt_expectations_expect_table__1a15a1299c7337ce59664ee712e0fcbb.sql",
            "original_file_path": "models/sample_model_group/sample_model/schema.yml",
            "unique_id": "test.devoted.dbt_expectations_expect_table_row_count_to_be_between_sample_model_1.374a0bca32",
            "fqn": [
                "devoted",
                "sample_model_group",
                "sample_model",
                "dbt_expectations_expect_table_row_count_to_be_between_sample_model_1"
            ],
            "alias": "dbt_expectations_expect_table__1a15a1299c7337ce59664ee712e0fcbb",
            "checksum": {
                "name": "none",
                "checksum": ""
            },
            "config": {
                "enabled": true,
                "alias": "dbt_expectations_expect_table__1a15a1299c7337ce59664ee712e0fcbb",
                "schema": "dbt_test__audit",
                "database": null,
                "tags": [],
                "meta": {},
                "materialized": "test",
                "severity": "ERROR",
                "store_failures": null,
                "where": null,
                "limit": null,
                "fail_calc": "count(*)",
                "warn_if": "!= 0",
                "error_if": "!= 0"
            },
            "tags": [],
            "description": "",
            "columns": {},
            "meta": {},
            "docs": {
                "show": true,
                "node_color": null
            },
            "patch_path": null,
            "build_path": "target/run/devoted/models/sample_model_group/sample_model/schema.yml/dbt_expectations_expect_table__1a15a1299c7337ce59664ee712e0fcbb.sql",
            "deferred": false,
            "unrendered_config": {
                "alias": "dbt_expectations_expect_table__1a15a1299c7337ce59664ee712e0fcbb"
            },
            "created_at": 1676002305.90605,
            "relation_name": null,
            "raw_code": "{{ dbt_expectations.test_expect_table_row_count_to_be_between(**_dbt_generic_test_kwargs) }}{{ config(alias=\"dbt_expectations_expect_table__1a15a1299c7337ce59664ee712e0fcbb\") }}",
            "language": "sql",
            "refs": [
                [
                    "sample_model"
                ]
            ],
            "sources": [],
            "metrics": [],
            "depends_on": {
                "macros": [
                    "macro.dbt_expectations.test_expect_table_row_count_to_be_between",
                    "macro.dbt.get_where_subquery",
                    "macro.devoted.ref",
                    "macro.elementary.materialize_test",
                    "macro.dbt_snowflake.materialization_test_snowflake"
                ],
                "nodes": [
                    "model.devoted.sample_model"
                ]
            },
            "compiled_path": "target/compiled/devoted/models/sample_model_group/sample_model/schema.yml/dbt_expectations_expect_table__1a15a1299c7337ce59664ee712e0fcbb.sql",
            "compiled": true,
            "compiled_code": "\n\n\n\n    with grouped_expression as (\n    select\n        \n        \n    \n  \n( 1=1 and count(*) >= 1\n)\n as expression\n\n\n    from dev_jbrownstein.transform.sample_model\n    \n\n),\nvalidation_errors as (\n\n    select\n        *\n    from\n        grouped_expression\n    where\n        not(expression = true)\n\n)\n\nselect *\nfrom validation_errors\n\n\n\n\n\n",
            "extra_ctes_injected": true,
            "extra_ctes": [],
            "column_name": null,
            "file_key_name": "models.sample_model"
        },

[jsnb-devoted]

One other data point to add is that the test audit table dbt_expectations_expect_table__1a15a1299c7337ce59664ee712e0fcbb does exist and has the expected failure row.

[gshank]

For tests the relation_name is only set if "store_failures" is set in the test config, and it isn't for that test node: "store_failures": null. The logging message should be fixed though, to not display that query when there is no relation_name. What are you using that logging message for if you're not storing the failures for the test?

[jsnb-devoted]

@gshank -- we aren't setting the store_failures setting in the test config but we are specifying --store-failures flag in the cli call to dbt test. I would expect the manifest to reflect store_failures: true when we use the flag like that even if we don't have in the test config and for the table to show in the log.

We use the flag so that it can be an opt in feature decided by the developer in the orchestration code.

[gshank]

Okay, the problem is that we moved generation of relation_name to parse time. The manifest is probably generated in a prior run (not the one with --store-failures), and so when the test command is run, the relation_name is not set in the test nodes.

We could either re-generate the relation_name at compile time or always set it on tests. My inclination would be to re-generate it at compile time, but I'll let @jtcohen6 weigh in on that.

[jtcohen6]

We could either re-generate the relation_name at compile time or always set it on tests. My inclination would be to re-generate it at compile time, but I'll let @jtcohen6 weigh in on that.

Ah, right, this makes sense! The parse took place without --store-failures (no relation_name), and then the test is rerun with --store-failures (re-compiled but not re-parsed). I'm happy with your instinct here @gshank.

[jsnb-devoted]

Thank you @gshank + @jtcohen6!