dbt should not crash when it sees Materialized Views

[tomtl]

Describe the bug

When I run dbt run I get an error of "Cache inconsistency detected" referring to a materialized view in the same schema, not referenced in this DBT project, but part of a previous DBT project. Manually dropping the materialized view fixes the problem.

Steps To Reproduce

Created a new DBT project that does not include mention of "cpp009_business_spend". Run dbt run. Get an error "dbt.exceptions.InternalException: Cache inconsistency detected: in add_link, referenced link key _ReferenceKey(database='reference', schema='tlee', identifier='cpp009_business_spend') not in cache!" (see below for full error). This was using DBT 0.13.1 installed with brew. I also updated to version 0.14.0 and got the same error.

Using SQL to run DROP MATERIALIZED VIEW tlee.cpp009_business_spend CASCADE; fixes the problem and afterward DBT can run without any problems.

Expected behavior

DBT should run without querying the "cpp009_business_spend" materialized view as it is not part of the DBT project.

Screenshots and log output

If applicable, add screenshots or log output to help explain your problem.

System information

DBT version 0.13.1 and 0.14.0 installed with Brew
Postgres 9.4
Mac OS current

The output of dbt --version:

dbt --version
installed version: 0.14.0
   latest version: 0.14.0

Up to date!

The output of python --version: Python 2.7.15

Additional context

STACK TRACE

dbt --debug run
​
Running with dbt=0.14.0
2019-08-26 10:41:40,953 (MainThread): Tracking: tracking
2019-08-26 10:41:40,959 (MainThread): Sending event: {'category': 'dbt', 'action': 'invocation', 'label': 'start', 'context': [<snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x10eda3bd0>, <snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x10edae510>, <snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x10eda3b90>]}
2019-08-26 10:41:41,213 (MainThread): Parsing macros/core.sql
2019-08-26 10:41:41,219 (MainThread): Parsing macros/materializations/helpers.sql
2019-08-26 10:41:41,227 (MainThread): Parsing macros/materializations/snapshot/snapshot_merge.sql
2019-08-26 10:41:41,229 (MainThread): Parsing macros/materializations/snapshot/strategies.sql
2019-08-26 10:41:41,242 (MainThread): Parsing macros/materializations/snapshot/snapshot.sql
2019-08-26 10:41:41,261 (MainThread): Parsing macros/materializations/seed/seed.sql
2019-08-26 10:41:41,275 (MainThread): Parsing macros/materializations/incremental/incremental.sql
2019-08-26 10:41:41,282 (MainThread): Parsing macros/materializations/common/merge.sql
2019-08-26 10:41:41,288 (MainThread): Parsing macros/materializations/table/table.sql
2019-08-26 10:41:41,293 (MainThread): Parsing macros/materializations/view/view.sql
2019-08-26 10:41:41,298 (MainThread): Parsing macros/materializations/view/create_or_replace_view.sql
2019-08-26 10:41:41,303 (MainThread): Parsing macros/etc/get_custom_alias.sql
2019-08-26 10:41:41,304 (MainThread): Parsing macros/etc/query.sql
2019-08-26 10:41:41,305 (MainThread): Parsing macros/etc/is_incremental.sql
2019-08-26 10:41:41,307 (MainThread): Parsing macros/etc/get_relation_comment.sql
2019-08-26 10:41:41,309 (MainThread): Parsing macros/etc/datetime.sql
2019-08-26 10:41:41,317 (MainThread): Parsing macros/etc/get_custom_schema.sql
2019-08-26 10:41:41,319 (MainThread): Parsing macros/adapters/common.sql
2019-08-26 10:41:41,348 (MainThread): Parsing macros/schema_tests/relationships.sql
2019-08-26 10:41:41,350 (MainThread): Parsing macros/schema_tests/not_null.sql
2019-08-26 10:41:41,351 (MainThread): Parsing macros/schema_tests/unique.sql
2019-08-26 10:41:41,352 (MainThread): Parsing macros/schema_tests/accepted_values.sql
2019-08-26 10:41:41,354 (MainThread): Parsing macros/catalog.sql
2019-08-26 10:41:41,356 (MainThread): Parsing macros/relations.sql
2019-08-26 10:41:41,357 (MainThread): Parsing macros/adapters.sql
2019-08-26 10:41:41,367 (MainThread): Parsing macros/materializations/snapshot_merge.sql
2019-08-26 10:41:41,380 (MainThread): Parsing model.towers.distance_sita2019_spgmi2018
2019-08-26 10:41:41,381 (MainThread): Acquiring new postgres connection "distance_sita2019_spgmi2018".
2019-08-26 10:41:41,381 (MainThread): Opening a new connection, currently in state init
2019-08-26 10:41:41,698 (MainThread): Parsing model.towers.distance_spgmi2018_sita2019
2019-08-26 10:41:41,699 (MainThread): Acquiring new postgres connection "distance_spgmi2018_sita2019".
2019-08-26 10:41:41,699 (MainThread): Re-using an available connection from the pool (formerly distance_sita2019_spgmi2018).
2019-08-26 10:41:41,705 (MainThread): Parsing model.towers.towers_spgmisita100m_20180701
2019-08-26 10:41:41,706 (MainThread): Acquiring new postgres connection "towers_spgmisita100m_20180701".
2019-08-26 10:41:41,706 (MainThread): Re-using an available connection from the pool (formerly distance_spgmi2018_sita2019).
2019-08-26 10:41:41,710 (MainThread): Parsing model.towers.towers_transform_sita2009_nearspgmi
2019-08-26 10:41:41,711 (MainThread): Acquiring new postgres connection "towers_transform_sita2009_nearspgmi".
2019-08-26 10:41:41,711 (MainThread): Re-using an available connection from the pool (formerly towers_spgmisita100m_20180701).
2019-08-26 10:41:41,716 (MainThread): Parsing model.towers.towers_transform_spgmi2018_buffers
2019-08-26 10:41:41,717 (MainThread): Acquiring new postgres connection "towers_transform_spgmi2018_buffers".
2019-08-26 10:41:41,717 (MainThread): Re-using an available connection from the pool (formerly towers_transform_sita2009_nearspgmi).
2019-08-26 10:41:41,723 (MainThread): Parsing model.towers.towers_transform_sita2019_buffers
2019-08-26 10:41:41,723 (MainThread): Acquiring new postgres connection "towers_transform_sita2019_buffers".
2019-08-26 10:41:41,724 (MainThread): Re-using an available connection from the pool (formerly towers_transform_spgmi2018_buffers).
2019-08-26 10:41:41,729 (MainThread): Parsing model.towers.towers_transform_sita2009_buffers
2019-08-26 10:41:41,729 (MainThread): Acquiring new postgres connection "towers_transform_sita2009_buffers".
2019-08-26 10:41:41,729 (MainThread): Re-using an available connection from the pool (formerly towers_transform_sita2019_buffers).
2019-08-26 10:41:41,734 (MainThread): Parsing model.towers.base_towers_sita_2019
2019-08-26 10:41:41,735 (MainThread): Acquiring new postgres connection "base_towers_sita_2019".
2019-08-26 10:41:41,735 (MainThread): Re-using an available connection from the pool (formerly towers_transform_sita2009_buffers).
2019-08-26 10:41:41,738 (MainThread): Parsing model.towers.base_towers_spgmi_2018
2019-08-26 10:41:41,739 (MainThread): Acquiring new postgres connection "base_towers_spgmi_2018".
2019-08-26 10:41:41,739 (MainThread): Re-using an available connection from the pool (formerly base_towers_sita_2019).
2019-08-26 10:41:41,742 (MainThread): Parsing model.towers.base_towers_sita_2009
2019-08-26 10:41:41,743 (MainThread): Acquiring new postgres connection "base_towers_sita_2009".
2019-08-26 10:41:41,743 (MainThread): Re-using an available connection from the pool (formerly base_towers_spgmi_2018).
2019-08-26 10:41:41,747 (MainThread): Parsing analysis.towers.morphology_spgmi_2018
2019-08-26 10:41:41,748 (MainThread): Acquiring new postgres connection "morphology_spgmi_2018".
2019-08-26 10:41:41,748 (MainThread): Re-using an available connection from the pool (formerly base_towers_sita_2009).
2019-08-26 10:41:41,780 (MainThread): Found 10 models, 0 tests, 0 snapshots, 1 analyses, 116 macros, 0 operations, 0 seed files, 0 sources
2019-08-26 10:41:41,781 (MainThread):
2019-08-26 10:41:41,781 (MainThread): Acquiring new postgres connection "master".
2019-08-26 10:41:41,781 (MainThread): Re-using an available connection from the pool (formerly morphology_spgmi_2018).
2019-08-26 10:41:41,792 (MainThread): Parsing macros/core.sql
2019-08-26 10:41:41,796 (MainThread): Parsing macros/materializations/helpers.sql
2019-08-26 10:41:41,802 (MainThread): Parsing macros/materializations/snapshot/snapshot_merge.sql
2019-08-26 10:41:41,804 (MainThread): Parsing macros/materializations/snapshot/strategies.sql
2019-08-26 10:41:41,815 (MainThread): Parsing macros/materializations/snapshot/snapshot.sql
2019-08-26 10:41:41,833 (MainThread): Parsing macros/materializations/seed/seed.sql
2019-08-26 10:41:41,846 (MainThread): Parsing macros/materializations/incremental/incremental.sql
2019-08-26 10:41:41,853 (MainThread): Parsing macros/materializations/common/merge.sql
2019-08-26 10:41:41,860 (MainThread): Parsing macros/materializations/table/table.sql
2019-08-26 10:41:41,865 (MainThread): Parsing macros/materializations/view/view.sql
2019-08-26 10:41:41,869 (MainThread): Parsing macros/materializations/view/create_or_replace_view.sql
2019-08-26 10:41:41,874 (MainThread): Parsing macros/etc/get_custom_alias.sql
2019-08-26 10:41:41,875 (MainThread): Parsing macros/etc/query.sql
2019-08-26 10:41:41,876 (MainThread): Parsing macros/etc/is_incremental.sql
2019-08-26 10:41:41,877 (MainThread): Parsing macros/etc/get_relation_comment.sql
2019-08-26 10:41:41,880 (MainThread): Parsing macros/etc/datetime.sql
2019-08-26 10:41:41,887 (MainThread): Parsing macros/etc/get_custom_schema.sql
2019-08-26 10:41:41,889 (MainThread): Parsing macros/adapters/common.sql
2019-08-26 10:41:41,918 (MainThread): Parsing macros/schema_tests/relationships.sql
2019-08-26 10:41:41,919 (MainThread): Parsing macros/schema_tests/not_null.sql
2019-08-26 10:41:41,920 (MainThread): Parsing macros/schema_tests/unique.sql
2019-08-26 10:41:41,921 (MainThread): Parsing macros/schema_tests/accepted_values.sql
2019-08-26 10:41:41,923 (MainThread): Parsing macros/catalog.sql
2019-08-26 10:41:41,926 (MainThread): Parsing macros/relations.sql
2019-08-26 10:41:41,927 (MainThread): Parsing macros/adapters.sql
2019-08-26 10:41:41,936 (MainThread): Parsing macros/materializations/snapshot_merge.sql
2019-08-26 10:41:42,036 (MainThread): Using postgres connection "master".
2019-08-26 10:41:42,036 (MainThread): On master:
    select distinct nspname from pg_namespace
​
2019-08-26 10:41:42,119 (MainThread): SQL status: SELECT 370 in 0.08 seconds
2019-08-26 10:41:42,148 (MainThread): Using postgres connection "master".
2019-08-26 10:41:42,148 (MainThread): On master: BEGIN
2019-08-26 10:41:42,194 (MainThread): SQL status: BEGIN in 0.05 seconds
2019-08-26 10:41:42,195 (MainThread): Using postgres connection "master".
2019-08-26 10:41:42,195 (MainThread): On master: select
      'reference' as database,
      tablename as name,
      schemaname as schema,
      'table' as type
    from pg_tables
    where schemaname ilike 'tlee'
    union all
    select
      'reference' as database,
      viewname as name,
      schemaname as schema,
      'view' as type
    from pg_views
    where schemaname ilike 'tlee'
​
2019-08-26 10:41:42,314 (MainThread): SQL status: SELECT 261 in 0.12 seconds
2019-08-26 10:41:43,070 (MainThread): Using postgres connection "master".
2019-08-26 10:41:43,070 (MainThread): On master: --
    --
    with relation as (
        select
            pg_rewrite.ev_class as class,
            pg_rewrite.oid as id
        from pg_rewrite
    ),
    class as (
        select
            oid as id,
            relname as name,
            relnamespace as schema,
            relkind as kind
        from pg_class
    ),
    dependency as (
        select
            pg_depend.objid as id,
            pg_depend.refobjid as ref
        from pg_depend
    ),
    schema as (
        select
            pg_namespace.oid as id,
            pg_namespace.nspname as name
        from pg_namespace
        where nspname != 'information_schema' and nspname not like 'pg_%'
    ),
    referenced as (
        select
            relation.id AS id,
            referenced_class.name ,
            referenced_class.schema ,
            referenced_class.kind
        from relation
        join class as referenced_class on relation.class=referenced_class.id
        where referenced_class.kind in ('r', 'v')
    ),
    relationships as (
        select
            referenced.name as referenced_name,
            referenced.schema as referenced_schema_id,
            dependent_class.name as dependent_name,
            dependent_class.schema as dependent_schema_id,
            referenced.kind as kind
        from referenced
        join dependency on referenced.id=dependency.id
        join class as dependent_class on dependency.ref=dependent_class.id
        where
            (referenced.name != dependent_class.name or
             referenced.schema != dependent_class.schema)
    )
​
    select
        referenced_schema.name as referenced_schema,
        relationships.referenced_name as referenced_name,
        dependent_schema.name as dependent_schema,
        relationships.dependent_name as dependent_name
    from relationships
    join schema as dependent_schema on relationships.dependent_schema_id=dependent_schema.id
    join schema as referenced_schema on relationships.referenced_schema_id=referenced_schema.id
    group by referenced_schema, referenced_name, dependent_schema, dependent_name
    order by referenced_schema, referenced_name, dependent_schema, dependent_name;
2019-08-26 10:41:46,706 (MainThread): SQL status: SELECT 49106 in 3.64 seconds
2019-08-26 10:42:04,957 (MainThread): On master: ROLLBACK
2019-08-26 10:42:04,995 (MainThread): Connection 'master' was left open.
2019-08-26 10:42:04,996 (MainThread): On master: Close
2019-08-26 10:42:04,997 (MainThread): Sending event: {'category': 'dbt', 'action': 'invocation', 'label': 'end', 'context': [<snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x10edab110>, <snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x1109d8910>, <snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x1109d8cd0>]}
2019-08-26 10:42:05,196 (MainThread): Flushing usage events
2019-08-26 10:42:05,196 (MainThread): Encountered an error:
2019-08-26 10:42:05,196 (MainThread): Cache inconsistency detected: in add_link, referenced link key _ReferenceKey(database='reference', schema='tlee', identifier='cpp009_business_spend') not in cache!
2019-08-26 10:42:05,198 (MainThread): Traceback (most recent call last):
  File "/usr/local/Cellar/[email protected]/0.14.0/libexec/lib/python3.7/site-packages/dbt/main.py", line 82, in main
    results, succeeded = handle_and_check(args)
  File "/usr/local/Cellar/[email protected]/0.14.0/libexec/lib/python3.7/site-packages/dbt/main.py", line 151, in handle_and_check
    task, res = run_from_args(parsed)
  File "/usr/local/Cellar/[email protected]/0.14.0/libexec/lib/python3.7/site-packages/dbt/main.py", line 216, in run_from_args
    results = task.run()
  File "/usr/local/Cellar/[email protected]/0.14.0/libexec/lib/python3.7/site-packages/dbt/task/runnable.py", line 282, in run
    result = self.execute_with_hooks(selected_uids)
  File "/usr/local/Cellar/[email protected]/0.14.0/libexec/lib/python3.7/site-packages/dbt/task/runnable.py", line 252, in execute_with_hooks
    self.before_run(adapter, selected_uids)
  File "/usr/local/Cellar/[email protected]/0.14.0/libexec/lib/python3.7/site-packages/dbt/task/run.py", line 150, in before_run
    self.populate_adapter_cache(adapter)
  File "/usr/local/Cellar/[email protected]/0.14.0/libexec/lib/python3.7/site-packages/dbt/task/run.py", line 63, in populate_adapter_cache
    adapter.set_relations_cache(self.manifest)
  File "/usr/local/Cellar/[email protected]/0.14.0/libexec/lib/python3.7/site-packages/dbt/adapters/base/impl.py", line 342, in set_relations_cache
    self._relations_cache_for_schemas(manifest)
  File "/usr/local/Cellar/[email protected]/0.14.0/libexec/lib/python3.7/site-packages/dbt/adapters/postgres/impl.py", line 88, in _relations_cache_for_schemas
    self._link_cached_relations(manifest)
  File "/usr/local/Cellar/[email protected]/0.14.0/libexec/lib/python3.7/site-packages/dbt/adapters/postgres/impl.py", line 84, in _link_cached_relations
    self._link_cached_database_relations(schemas)
  File "/usr/local/Cellar/[email protected]/0.14.0/libexec/lib/python3.7/site-packages/dbt/adapters/postgres/impl.py", line 60, in _link_cached_database_relations
    self.cache.add_link(dependent, referenced)
  File "/usr/local/Cellar/[email protected]/0.14.0/libexec/lib/python3.7/site-packages/dbt/adapters/cache.py", line 296, in add_link
    self._add_link(referenced, dependent)
  File "/usr/local/Cellar/[email protected]/0.14.0/libexec/lib/python3.7/site-packages/dbt/adapters/cache.py", line 254, in _add_link
    .format(referenced_key)
  File "/usr/local/Cellar/[email protected]/0.14.0/libexec/lib/python3.7/site-packages/dbt/exceptions.py", line 473, in raise_cache_inconsistent
    raise InternalException('Cache inconsistency detected: {}'.format(message))
dbt.exceptions.InternalException: Cache inconsistency detected: in add_link, referenced link key _ReferenceKey(database='reference', schema='tlee', identifier='cpp009_business_spend') not in cache!

[drewbanin]

Thanks for the report @tomtl! I think we'll need to upgrade the introspective query that dbt runs to account for materialized views on PG.

[albielin]

This would greatly help us - we have a ton of materialized views in our data warehouse and this is a blocker at the moment. Any suggested work arounds besides dropping the materialized views?

[drewbanin]

I think the only workaround for the moment is to run dbt against a schema that does not contain any materialized views. A fix for this is going to be prioritized for dbt's next minor release.

[beckjake]

I can't reproduce this in 0.14.0 (nor 0.14.3, nor 0.15.0a1). I'm using Postgres 10.4 server, 11.2 client because that's what I have locally, and:
```
$ psql -c ' create materialized view dbt_postgres_case_1698.some_matview as (select * from dbt_postgres_case_1698.some_table);'
SELECT 1

$ cat models/x.sql
select 1 as id

$ cat models/y.sql
select * from {{ ref('x') }}

$ cat models/z.sql
select * from {{ ref('y') }}

$ dbt run
Running with dbt=0.14.0-rc1
Found 3 models, 0 tests, 0 snapshots, 0 analyses, 235 macros, 0 operations, 1 seed files, 0 sources

07:38:35 | Concurrency: 2 threads (target='default')
07:38:35 |
07:38:35 | 1 of 3 START view model dbt_postgres_case_1698.x..................... [RUN]
07:38:35 | 1 of 3 OK created view model dbt_postgres_case_1698.x................ [CREATE VIEW in 0.08s]
07:38:35 | 2 of 3 START view model dbt_postgres_case_1698.y..................... [RUN]
07:38:35 | 2 of 3 OK created view model dbt_postgres_case_1698.y................ [CREATE VIEW in 0.05s]
07:38:35 | 3 of 3 START view model dbt_postgres_case_1698.z..................... [RUN]
07:38:35 | 3 of 3 OK created view model dbt_postgres_case_1698.z................ [CREATE VIEW in 0.05s]
07:38:35 |
07:38:35 | Finished running 3 view models in 0.56s.

Completed successfully

Done. PASS=3 ERROR=0 SKIP=0 TOTAL=3
```

[drewbanin]

@beckjake I'm able to reproduce this with:

create schema test_schema;
create table test_schema.abc123 (id int);
create materialized view test_schema.some_matview as (
    select * from test_schema.abc123
); 

create view test_schema.ref_some_matview as (
    select * from test_schema.some_matview
)

After running this sql, a dbt run against the test_schema schema fails with an error like:

Cache inconsistency detected: in add_link, referenced link key _ReferenceKey(database='analytics', schema='test_schema', identifier='some_matview') not in cache!