Skip to content

[Bug] TestFindMatching sometimes fails with KeyError: 'FindMatchingRecord' #280

@booxter

Description

@booxter

Is this a new bug in dbt-common?

  • I believe this is a new bug in dbt-common
  • I have searched the existing issues, and I could not find an existing issue for this bug

Current Behavior

When running unit tests from the current head, 03e09c0, sometimes I catch the following failure:

============================= test session starts ==============================
platform darwin -- Python 3.12.10, pytest-8.3.5, pluggy-1.5.0
rootdir: /private/tmp/nix-build-python3.12-dbt-common-1.23.0-unstable-2025-04-21.drv-0/source
configfile: pyproject.toml
plugins: xdist-3.6.1, mock-3.14.0
12 workers [194 items]    
........................................................................ [ 37%]
...............s........................................................ [ 74%]
........................................F.........                       [100%]
=================================== FAILURES ===================================
__________ TestFindMatching.test_find_matching_lowercase_file_pattern __________
[gw2] darwin -- Python 3.12.10 /nix/store/ixbf5xsmxbscjhb8j84slnfa23p2cq00-python3-3.12.10/bin/python3.12

self = <tests.unit.test_system_client.TestFindMatching testMethod=test_find_matching_lowercase_file_pattern>

    def test_find_matching_lowercase_file_pattern(self) -> None:
        with NamedTemporaryFile(prefix="sql-files", suffix=".sql", dir=self.tempdir) as named_file:
            file_path = os.path.dirname(named_file.name)
            relative_path = os.path.basename(file_path)
>           out = dbt_common.clients.system.find_matching(
                self.base_dir,
                [relative_path],
                "*.sql",
            )

tests/unit/test_system_client.py:163: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
dbt_common/record.py:543: in record_replay_wrapper
    return recorder.expect_record(params)
dbt_common/record.py:293: in expect_record
    record = self.pop_matching_record(params)
dbt_common/record.py:226: in pop_matching_record
    self._ensure_records_processed(rec_type_name)
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

self = <dbt_common.record.Recorder object at 0x10dacbb90>
record_type_name = 'FindMatchingRecord'

    def _ensure_records_processed(self, record_type_name: str) -> None:
        if record_type_name in self._records_by_type:
            return
    
        rec_list = []
        record_cls = self._record_cls_by_name[record_type_name]
>       for record_dct in self._unprocessed_records_by_type[record_type_name]:
E       KeyError: 'FindMatchingRecord'

dbt_common/record.py:287: KeyError
=============================== warnings summary ===============================
../../../../nix/store/1v1bw072bcg8mbxbl29smwr5pn38fn1a-python3.12-protobuf-6.30.2/lib/python3.12/site-packages/google/protobuf/runtime_version.py:98: 12 warnings
  /nix/store/1v1bw072bcg8mbxbl29smwr5pn38fn1a-python3.12-protobuf-6.30.2/lib/python3.12/site-packages/google/protobuf/runtime_version.py:98: UserWarning: Protobuf gencode version 5.28.3 is exactly one major version older than the runtime version 6.30.2 at types.proto. Please update the gencode to av
oid compatibility violations in the next runtime release.
    warnings.warn(

dbt_common/invocation.py:5: 12 warnings
  /private/tmp/nix-build-python3.12-dbt-common-1.23.0-unstable-2025-04-21.drv-0/source/dbt_common/invocation.py:5: DeprecationWarning: datetime.datetime.utcnow() is deprecated and scheduled for removal in a future version. Use timezone-aware objects to represent datetimes in UTC: datetime.datetime.n
ow(datetime.UTC).
    _INVOCATION_STARTED_AT = datetime.utcnow()

tests/unit/test_record.py:22: 12 warnings
  /private/tmp/nix-build-python3.12-dbt-common-1.23.0-unstable-2025-04-21.drv-0/source/tests/unit/test_record.py:22: PytestCollectionWarning: cannot collect test class 'TestRecordParams' because it has a __init__ constructor (from: tests/unit/test_record.py)
    @dataclasses.dataclass

tests/unit/test_record.py:29: 12 warnings
  /private/tmp/nix-build-python3.12-dbt-common-1.23.0-unstable-2025-04-21.drv-0/source/tests/unit/test_record.py:29: PytestCollectionWarning: cannot collect test class 'TestRecordResult' because it has a __init__ constructor (from: tests/unit/test_record.py)
    @dataclasses.dataclass

tests/unit/test_record.py:34: 12 warnings
  /private/tmp/nix-build-python3.12-dbt-common-1.23.0-unstable-2025-04-21.drv-0/source/tests/unit/test_record.py:34: PytestCollectionWarning: cannot collect test class 'TestRecord' because it has a __init__ constructor (from: tests/unit/test_record.py)
    @Recorder.register_record_type

tests/unit/test_invocation.py::test_invocation_started_at
  /private/tmp/nix-build-python3.12-dbt-common-1.23.0-unstable-2025-04-21.drv-0/source/dbt_common/invocation.py:19: DeprecationWarning: datetime.datetime.utcnow() is deprecated and scheduled for removal in a future version. Use timezone-aware objects to represent datetimes in UTC: datetime.datetime.
now(datetime.UTC).
    _INVOCATION_STARTED_AT = datetime.utcnow()

tests/unit/test_system_client.py::TestUntarPackage::test_untar_package_success
  /private/tmp/nix-build-python3.12-dbt-common-1.23.0-unstable-2025-04-21.drv-0/source/dbt_common/clients/system.py:634: DeprecationWarning: Python 3.14 will, by default, filter extracted tar archives and reject files or modify their metadata. Use the filter argument to control this behavior.
    tarball.extractall(path, members=members)

-- Docs: https://docs.pytest.org/en/stable/how-to/capture-warnings.html
=========================== short test summary info ============================
FAILED tests/unit/test_system_client.py::TestFindMatching::test_find_matching_lowercase_file_pattern - KeyError: 'FindMatchingRecord'
============ 1 failed, 192 passed, 1 skipped, 62 warnings in 8.52s =============

Another example with the same test class but different test cases:

============================= test session starts ==============================
platform darwin -- Python 3.12.10, pytest-8.3.5, pluggy-1.5.0
rootdir: /private/tmp/nix-build-python3.12-dbt-common-1.23.0-unstable-2025-04-21.drv-1/source
configfile: pyproject.toml
plugins: xdist-3.6.1, mock-3.14.0
5 workers [194 items]  m
....................................................................s... [ 37%]
........................................................................ [ 74%]
...................................FF.............                       [100%]
=================================== FAILURES ===================================
__________ TestFindMatching.test_find_matching_file_pattern_not_found __________
[gw1] darwin -- Python 3.12.10 /nix/store/ixbf5xsmxbscjhb8j84slnfa23p2cq00-python3-3.12.10/bin/python3.12

self = <tests.unit.test_system_client.TestFindMatching testMethod=test_find_matching_file_pattern_not_found>

    def test_find_matching_file_pattern_not_found(self) -> None:
        with NamedTemporaryFile(prefix="sql-files", suffix=".SQLT", dir=self.tempdir):
>           out = dbt_common.clients.system.find_matching(self.tempdir, [""], "*.sql")

tests/unit/test_system_client.py:195: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
dbt_common/record.py:543: in record_replay_wrapper
    return recorder.expect_record(params)
dbt_common/record.py:293: in expect_record
    record = self.pop_matching_record(params)
dbt_common/record.py:226: in pop_matching_record
    self._ensure_records_processed(rec_type_name)
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

self = <dbt_common.record.Recorder object at 0x10f6ba8d0>
record_type_name = 'FindMatchingRecord'

    def _ensure_records_processed(self, record_type_name: str) -> None:
        if record_type_name in self._records_by_type:
            return
    
        rec_list = []
        record_cls = self._record_cls_by_name[record_type_name]
>       for record_dct in self._unprocessed_records_by_type[record_type_name]:
E       KeyError: 'FindMatchingRecord'

dbt_common/record.py:287: KeyError
______________________ TestFindMatching.test_ignore_spec _______________________
[gw1] darwin -- Python 3.12.10 /nix/store/ixbf5xsmxbscjhb8j84slnfa23p2cq00-python3-3.12.10/bin/python3.12

self = <tests.unit.test_system_client.TestFindMatching testMethod=test_ignore_spec>

    def test_ignore_spec(self) -> None:
        with NamedTemporaryFile(prefix="sql-files", suffix=".sql", dir=self.tempdir):
>           out = dbt_common.clients.system.find_matching(
                self.tempdir,
                [""],
                "*.sql",
                pathspec.PathSpec.from_lines(
                    pathspec.patterns.GitWildMatchPattern, "sql-files*".splitlines()
                ),
            )

tests/unit/test_system_client.py:200: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
dbt_common/record.py:543: in record_replay_wrapper
    return recorder.expect_record(params)
dbt_common/record.py:293: in expect_record
    record = self.pop_matching_record(params)
dbt_common/record.py:226: in pop_matching_record
    self._ensure_records_processed(rec_type_name)
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

self = <dbt_common.record.Recorder object at 0x10f6ba8d0>
record_type_name = 'FindMatchingRecord'

    def _ensure_records_processed(self, record_type_name: str) -> None:
        if record_type_name in self._records_by_type:
            return
    
        rec_list = []
        record_cls = self._record_cls_by_name[record_type_name]
>       for record_dct in self._unprocessed_records_by_type[record_type_name]:
E       KeyError: 'FindMatchingRecord'

dbt_common/record.py:287: KeyError
=============================== warnings summary ===============================
../../../../nix/store/1v1bw072bcg8mbxbl29smwr5pn38fn1a-python3.12-protobuf-6.30.2/lib/python3.12/site-packages/google/protobuf/runtime_version.py:98
../../../../nix/store/1v1bw072bcg8mbxbl29smwr5pn38fn1a-python3.12-protobuf-6.30.2/lib/python3.12/site-packages/google/protobuf/runtime_version.py:98
../../../../nix/store/1v1bw072bcg8mbxbl29smwr5pn38fn1a-python3.12-protobuf-6.30.2/lib/python3.12/site-packages/google/protobuf/runtime_version.py:98
../../../../nix/store/1v1bw072bcg8mbxbl29smwr5pn38fn1a-python3.12-protobuf-6.30.2/lib/python3.12/site-packages/google/protobuf/runtime_version.py:98
../../../../nix/store/1v1bw072bcg8mbxbl29smwr5pn38fn1a-python3.12-protobuf-6.30.2/lib/python3.12/site-packages/google/protobuf/runtime_version.py:98
  /nix/store/1v1bw072bcg8mbxbl29smwr5pn38fn1a-python3.12-protobuf-6.30.2/lib/python3.12/site-packages/google/protobuf/runtime_version.py:98: UserWarning: Protobuf gencode version 5.28.3 is exactly one major version older than the runtime version 6.30.2 at types.proto. Please update the gencode to avoid compatibility violations in the next runtime release.
    warnings.warn(

dbt_common/invocation.py:5
dbt_common/invocation.py:5
dbt_common/invocation.py:5
dbt_common/invocation.py:5
dbt_common/invocation.py:5
  /private/tmp/nix-build-python3.12-dbt-common-1.23.0-unstable-2025-04-21.drv-1/source/dbt_common/invocation.py:5: DeprecationWarning: datetime.datetime.utcnow() is deprecated and scheduled for removal in a future version. Use timezone-aware objects to represent datetimes in UTC: datetime.datetime.now(datetime.UTC).
    _INVOCATION_STARTED_AT = datetime.utcnow()

tests/unit/test_record.py:22
tests/unit/test_record.py:22
tests/unit/test_record.py:22
tests/unit/test_record.py:22
tests/unit/test_record.py:22
  /private/tmp/nix-build-python3.12-dbt-common-1.23.0-unstable-2025-04-21.drv-1/source/tests/unit/test_record.py:22: PytestCollectionWarning: cannot collect test class 'TestRecordParams' because it has a __init__ constructor (from: tests/unit/test_record.py)
    @dataclasses.dataclass

tests/unit/test_record.py:29
tests/unit/test_record.py:29
tests/unit/test_record.py:29
tests/unit/test_record.py:29
tests/unit/test_record.py:29
  /private/tmp/nix-build-python3.12-dbt-common-1.23.0-unstable-2025-04-21.drv-1/source/tests/unit/test_record.py:29: PytestCollectionWarning: cannot collect test class 'TestRecordResult' because it has a __init__ constructor (from: tests/unit/test_record.py)
    @dataclasses.dataclass

tests/unit/test_record.py:34
tests/unit/test_record.py:34
tests/unit/test_record.py:34
tests/unit/test_record.py:34
tests/unit/test_record.py:34
  /private/tmp/nix-build-python3.12-dbt-common-1.23.0-unstable-2025-04-21.drv-1/source/tests/unit/test_record.py:34: PytestCollectionWarning: cannot collect test class 'TestRecord' because it has a __init__ constructor (from: tests/unit/test_record.py)
    @Recorder.register_record_type

tests/unit/test_invocation.py::test_invocation_started_at
  /private/tmp/nix-build-python3.12-dbt-common-1.23.0-unstable-2025-04-21.drv-1/source/dbt_common/invocation.py:19: DeprecationWarning: datetime.datetime.utcnow() is deprecated and scheduled for removal in a future version. Use timezone-aware objects to represent datetimes in UTC: datetime.datetime.now(datetime.UTC).
    _INVOCATION_STARTED_AT = datetime.utcnow()

tests/unit/test_system_client.py::TestUntarPackage::test_untar_package_success
  /private/tmp/nix-build-python3.12-dbt-common-1.23.0-unstable-2025-04-21.drv-1/source/dbt_common/clients/system.py:634: DeprecationWarning: Python 3.14 will, by default, filter extracted tar archives and reject files or modify their metadata. Use the filter argument to control this behavior.
    tarball.extractall(path, members=members)

-- Docs: https://docs.pytest.org/en/stable/how-to/capture-warnings.html
=========================== short test summary info ============================
FAILED tests/unit/test_system_client.py::TestFindMatching::test_find_matching_file_pattern_not_found - KeyError: 'FindMatchingRecord'
FAILED tests/unit/test_system_client.py::TestFindMatching::test_ignore_spec - KeyError: 'FindMatchingRecord'
============ 2 failed, 191 passed, 1 skipped, 27 warnings in 10.67s ============

This happens every so often, I have to run the suite ~5-10 times to hit it.

Note: I've seen it on x86_64-darwin through Rosetta as well as native aarch64-darwin.

Note2: this was found in context of nixpkgs packaging for the library where we run tests as part of the package build.

Expected Behavior

Test pass consistently.

Steps To Reproduce

This was triggered in nixpkgs build environment.

Relevant log output

Additional Context

No response

Metadata

Metadata

Assignees

No one assigned

    Labels

    bugSomething isn't workingtriage

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions