ccl/backupccl: TestDataDriven_backup_dropped_descriptors failed

[cockroach-teamcity]

ccl/backupccl.TestDataDriven_backup_dropped_descriptors failed on master @ 1084d88d63187bf66a2ee078e2f7ffd89cdfefba:

        /var/lib/engflow/worker/work/1/exec/bazel-out/k8-fastbuild/bin/pkg/ccl/backupccl/backupccl_test_/backupccl_test.runfiles/com_github_cockroachdb_cockroach/pkg/ccl/backupccl/testdata/backup-restore/backup-dropped-descriptors:115:
        exec-sql [0 args]
        CREATE TABLE d2.t2 (id INT);
        ----
    datadriven.go:259: 
        /var/lib/engflow/worker/work/1/exec/bazel-out/k8-fastbuild/bin/pkg/ccl/backupccl/backupccl_test_/backupccl_test.runfiles/com_github_cockroachdb_cockroach/pkg/ccl/backupccl/testdata/backup-restore/backup-dropped-descriptors:119:
        exec-sql [0 args]
        CREATE TYPE d2.typ AS ENUM ('hello');
        CREATE SCHEMA d2.s;
        CREATE TABLE d2.s.t (id INT);
        ----
    datadriven.go:259: 
        /var/lib/engflow/worker/work/1/exec/bazel-out/k8-fastbuild/bin/pkg/ccl/backupccl/backupccl_test_/backupccl_test.runfiles/com_github_cockroachdb_cockroach/pkg/ccl/backupccl/testdata/backup-restore/backup-dropped-descriptors:125:
        exec-sql [0 args]
        SET use_declarative_schema_changer = 'off';
        ----
    datadriven.go:259: 
        /var/lib/engflow/worker/work/1/exec/bazel-out/k8-fastbuild/bin/pkg/ccl/backupccl/backupccl_test_/backupccl_test.runfiles/com_github_cockroachdb_cockroach/pkg/ccl/backupccl/testdata/backup-restore/backup-dropped-descriptors:129:
        exec-sql [0 args]
        SET CLUSTER SETTING jobs.debug.pausepoints = 'schemachanger.before.exec';
        ----
    datadriven.go:259: 
        /var/lib/engflow/worker/work/1/exec/bazel-out/k8-fastbuild/bin/pkg/ccl/backupccl/backupccl_test_/backupccl_test.runfiles/com_github_cockroachdb_cockroach/pkg/ccl/backupccl/testdata/backup-restore/backup-dropped-descriptors:133:
        schema-change [1 args]
        DROP SCHEMA d2.s CASCADE;
        ----
        job paused at pausepoint
    datadriven.go:259: 
        /var/lib/engflow/worker/work/1/exec/bazel-out/k8-fastbuild/bin/pkg/ccl/backupccl/backupccl_test_/backupccl_test.runfiles/com_github_cockroachdb_cockroach/pkg/ccl/backupccl/testdata/backup-restore/backup-dropped-descriptors:138:
        exec-sql [0 args]
        SET CLUSTER SETTING jobs.debug.pausepoints = 'typeschemachanger.before.exec';
        ----
    datadriven.go:259: 
        /var/lib/engflow/worker/work/1/exec/bazel-out/k8-fastbuild/bin/pkg/ccl/backupccl/backupccl_test_/backupccl_test.runfiles/com_github_cockroachdb_cockroach/pkg/ccl/backupccl/testdata/backup-restore/backup-dropped-descriptors:142:
        schema-change [1 args]
        DROP TYPE d2.typ;
        ----
        job paused at pausepoint
    datadriven.go:259: 
        /var/lib/engflow/worker/work/1/exec/bazel-out/k8-fastbuild/bin/pkg/ccl/backupccl/backupccl_test_/backupccl_test.runfiles/com_github_cockroachdb_cockroach/pkg/ccl/backupccl/testdata/backup-restore/backup-dropped-descriptors:147:
         WITH tbls AS (
        	SELECT id, crdb_internal.pb_to_json('cockroach.sql.sqlbase.Descriptor', descriptor) AS orig FROM system.descriptor
        )
        SELECT orig->'schema'->'name', orig->'schema'->'state' FROM tbls WHERE id = 112;
        expected:
        "s" "DROP"
        
        found:
        <nil> <nil>
    --- FAIL: TestDataDriven_backup_dropped_descriptors/dropped-schema-descriptors (3.09s)

Parameters:

• attempt=1
• run=26
• shard=9

Help

See also: How To Investigate a Go Test Failure (internal)

/cc @cockroachdb/test-eng

This test on roachdash | Improve this report!

Jira issue: CRDB-36951

[blathers-crl]

cc @cockroachdb/disaster-recovery

[msbutler]

Ok, this is still reproducible on master via:

./dev test pkg/ccl/backupccl -f TestDataDriven_backup_dropped_descriptors --stress

[msbutler]

Looks like this fails before a backup-restore sequence. We're expecting to observe a descriptor in the dropped state but we can't find it (fails in backup-dropped-descriptors:147):

/var/lib/engflow/worker/work/1/exec/bazel-out/k8-fastbuild/bin/pkg/ccl/backupccl/backupccl_test_/backupccl_test.runfiles/com_github_cockroachdb_cockroach/pkg/ccl/backupccl/testdata/backup-restore/backup-dropped-descriptors:147:
         WITH tbls AS (
        	SELECT id, crdb_internal.pb_to_json('cockroach.sql.sqlbase.Descriptor', descriptor) AS orig FROM system.descriptor
        )
        SELECT orig->'schema'->'name', orig->'schema'->'state' FROM tbls WHERE id = 112;
        expected:
        "s" "DROP"
        
        found:
        <nil> <nil>

[msbutler]

Ok I think i've bisected this to #120144

[cockroach-teamcity]

ccl/backupccl.TestDataDriven_backup_dropped_descriptors failed with artifacts on master @ 215ece44cfba2ab950570f9d03cf29599e1ad088:

        /home/roach/.cache/bazel/_bazel_roach/c5a4e7d36696d9cd970af2045211a7df/sandbox/processwrapper-sandbox/5611/execroot/com_github_cockroachdb_cockroach/bazel-out/k8-fastbuild/bin/pkg/ccl/backupccl/backupccl_test_/backupccl_test.runfiles/com_github_cockroachdb_cockroach/pkg/ccl/backupccl/testdata/backup-restore/backup-dropped-descriptors:115:
        exec-sql [0 args]
        CREATE TABLE d2.t2 (id INT);
        ----
    datadriven.go:259: 
        /home/roach/.cache/bazel/_bazel_roach/c5a4e7d36696d9cd970af2045211a7df/sandbox/processwrapper-sandbox/5611/execroot/com_github_cockroachdb_cockroach/bazel-out/k8-fastbuild/bin/pkg/ccl/backupccl/backupccl_test_/backupccl_test.runfiles/com_github_cockroachdb_cockroach/pkg/ccl/backupccl/testdata/backup-restore/backup-dropped-descriptors:119:
        exec-sql [0 args]
        CREATE TYPE d2.typ AS ENUM ('hello');
        CREATE SCHEMA d2.s;
        CREATE TABLE d2.s.t (id INT);
        ----
    datadriven.go:259: 
        /home/roach/.cache/bazel/_bazel_roach/c5a4e7d36696d9cd970af2045211a7df/sandbox/processwrapper-sandbox/5611/execroot/com_github_cockroachdb_cockroach/bazel-out/k8-fastbuild/bin/pkg/ccl/backupccl/backupccl_test_/backupccl_test.runfiles/com_github_cockroachdb_cockroach/pkg/ccl/backupccl/testdata/backup-restore/backup-dropped-descriptors:125:
        exec-sql [0 args]
        SET use_declarative_schema_changer = 'off';
        ----
    datadriven.go:259: 
        /home/roach/.cache/bazel/_bazel_roach/c5a4e7d36696d9cd970af2045211a7df/sandbox/processwrapper-sandbox/5611/execroot/com_github_cockroachdb_cockroach/bazel-out/k8-fastbuild/bin/pkg/ccl/backupccl/backupccl_test_/backupccl_test.runfiles/com_github_cockroachdb_cockroach/pkg/ccl/backupccl/testdata/backup-restore/backup-dropped-descriptors:129:
        exec-sql [0 args]
        SET CLUSTER SETTING jobs.debug.pausepoints = 'schemachanger.before.exec';
        ----
    datadriven.go:259: 
        /home/roach/.cache/bazel/_bazel_roach/c5a4e7d36696d9cd970af2045211a7df/sandbox/processwrapper-sandbox/5611/execroot/com_github_cockroachdb_cockroach/bazel-out/k8-fastbuild/bin/pkg/ccl/backupccl/backupccl_test_/backupccl_test.runfiles/com_github_cockroachdb_cockroach/pkg/ccl/backupccl/testdata/backup-restore/backup-dropped-descriptors:133:
        schema-change [1 args]
        DROP SCHEMA d2.s CASCADE;
        ----
        job paused at pausepoint
    datadriven.go:259: 
        /home/roach/.cache/bazel/_bazel_roach/c5a4e7d36696d9cd970af2045211a7df/sandbox/processwrapper-sandbox/5611/execroot/com_github_cockroachdb_cockroach/bazel-out/k8-fastbuild/bin/pkg/ccl/backupccl/backupccl_test_/backupccl_test.runfiles/com_github_cockroachdb_cockroach/pkg/ccl/backupccl/testdata/backup-restore/backup-dropped-descriptors:138:
        exec-sql [0 args]
        SET CLUSTER SETTING jobs.debug.pausepoints = 'typeschemachanger.before.exec';
        ----
    datadriven.go:259: 
        /home/roach/.cache/bazel/_bazel_roach/c5a4e7d36696d9cd970af2045211a7df/sandbox/processwrapper-sandbox/5611/execroot/com_github_cockroachdb_cockroach/bazel-out/k8-fastbuild/bin/pkg/ccl/backupccl/backupccl_test_/backupccl_test.runfiles/com_github_cockroachdb_cockroach/pkg/ccl/backupccl/testdata/backup-restore/backup-dropped-descriptors:142:
        schema-change [1 args]
        DROP TYPE d2.typ;
        ----
        job paused at pausepoint
    datadriven.go:259: 
        /home/roach/.cache/bazel/_bazel_roach/c5a4e7d36696d9cd970af2045211a7df/sandbox/processwrapper-sandbox/5611/execroot/com_github_cockroachdb_cockroach/bazel-out/k8-fastbuild/bin/pkg/ccl/backupccl/backupccl_test_/backupccl_test.runfiles/com_github_cockroachdb_cockroach/pkg/ccl/backupccl/testdata/backup-restore/backup-dropped-descriptors:147:
         WITH tbls AS (
        	SELECT id, crdb_internal.pb_to_json('cockroach.sql.sqlbase.Descriptor', descriptor) AS orig FROM system.descriptor
        )
        SELECT orig->'schema'->'name', orig->'schema'->'state' FROM tbls WHERE id = 112;
        expected:
        "s" "DROP"
        
        found:
        <nil> <nil>
    --- FAIL: TestDataDriven_backup_dropped_descriptors/dropped-schema-descriptors (4.10s)

Help

See also: How To Investigate a Go Test Failure (internal)

This test on roachdash | Improve this report!

[cockroach-teamcity]

ccl/backupccl.TestDataDriven_backup_dropped_descriptors failed on master @ 7488e090daa588c4d7c0f828c8006bb9b13a90f6:

=== RUN   TestDataDriven_backup_dropped_descriptors
    test_log_scope.go:170: test logs captured to: outputs.zip/logTestDataDriven_backup_dropped_descriptors580006820
    test_log_scope.go:81: use -show-logs to present logs inline
    datadriven_test.go:446: Mock HTTP Storage "http://127.0.0.1:42379"
    testutils.go:289: no Invalid Descriptors
    panic.go:626: -- test log scope end --
test logs left over in: outputs.zip/logTestDataDriven_backup_dropped_descriptors580006820
--- FAIL: TestDataDriven_backup_dropped_descriptors (2.26s)
    testutils.go:266: Warning: Could not check for invalid descriptors: sql: database is closed
=== RUN   TestDataDriven_backup_dropped_descriptors/dropped-database-descriptors
    test_server_shim.go:157: automatically injected an external process virtual cluster under test; see comment at top of test_server_shim.go for details.
    datadriven.go:259: 
        /var/lib/engflow/worker/work/3/exec/bazel-out/k8-fastbuild/bin/pkg/ccl/backupccl/backupccl_test_/backupccl_test.runfiles/com_github_cockroachdb_cockroach/pkg/ccl/backupccl/testdata/backup-restore/backup-dropped-descriptors:5:
        new-cluster [1 args]
        <no input to command>
        ----
    datadriven.go:259: 
        /var/lib/engflow/worker/work/3/exec/bazel-out/k8-fastbuild/bin/pkg/ccl/backupccl/backupccl_test_/backupccl_test.runfiles/com_github_cockroachdb_cockroach/pkg/ccl/backupccl/testdata/backup-restore/backup-dropped-descriptors:8:
        exec-sql [0 args]
        SET use_declarative_schema_changer = 'off';
        ----
    datadriven.go:259: 
        /var/lib/engflow/worker/work/3/exec/bazel-out/k8-fastbuild/bin/pkg/ccl/backupccl/backupccl_test_/backupccl_test.runfiles/com_github_cockroachdb_cockroach/pkg/ccl/backupccl/testdata/backup-restore/backup-dropped-descriptors:12:
        exec-sql [0 args]
        SET CLUSTER SETTING jobs.debug.pausepoints = 'schemachanger.before.exec';
        ----
    datadriven.go:259: 
        /var/lib/engflow/worker/work/3/exec/bazel-out/k8-fastbuild/bin/pkg/ccl/backupccl/backupccl_test_/backupccl_test.runfiles/com_github_cockroachdb_cockroach/pkg/ccl/backupccl/testdata/backup-restore/backup-dropped-descriptors:16:
        exec-sql [0 args]
        CREATE DATABASE d;
        CREATE TABLE d.foo (id INT);
        ----
    datadriven.go:259: 
        /var/lib/engflow/worker/work/3/exec/bazel-out/k8-fastbuild/bin/pkg/ccl/backupccl/backupccl_test_/backupccl_test.runfiles/com_github_cockroachdb_cockroach/pkg/ccl/backupccl/testdata/backup-restore/backup-dropped-descriptors:21:
        schema-change [1 args]
        DROP DATABASE d CASCADE;
        ----
        job paused at pausepoint
    datadriven.go:259: 
        /var/lib/engflow/worker/work/3/exec/bazel-out/k8-fastbuild/bin/pkg/ccl/backupccl/backupccl_test_/backupccl_test.runfiles/com_github_cockroachdb_cockroach/pkg/ccl/backupccl/testdata/backup-restore/backup-dropped-descriptors:27:
         WITH tbls AS (
        	SELECT id, crdb_internal.pb_to_json('cockroach.sql.sqlbase.Descriptor', descriptor) AS orig FROM system.descriptor
        )
        SELECT orig->'database'->'name', orig->'database'->'state' FROM tbls WHERE id = 107;
        expected:
        "d" "DROP"
        
        found:
        <nil> <nil>
    --- FAIL: TestDataDriven_backup_dropped_descriptors/dropped-database-descriptors (2.20s)

Parameters:

• attempt=1
• run=25
• shard=9

Help

See also: How To Investigate a Go Test Failure (internal)

This test on roachdash | Improve this report!

[rafiss]

It looks like the test is making an assumption about object IDs that isn't really guaranteed.

The test is failing at this line:

         WITH tbls AS (
        	SELECT id, crdb_internal.pb_to_json('cockroach.sql.sqlbase.Descriptor', descriptor) AS orig FROM system.descriptor
        )
        SELECT orig->'schema'->'name', orig->'schema'->'state' FROM tbls WHERE id = 112;
        expected:
        "s" "DROP"
        
        found:
        <nil> <nil>

I added one more assertion as a sanity check:

diff --git a/pkg/ccl/backupccl/testdata/backup-restore/backup-dropped-descriptors b/pkg/ccl/backupccl/testdata/backup-restore/backup-dropped-descriptors
index 732feedcf3b..721d92dec02 100644
--- a/pkg/ccl/backupccl/testdata/backup-restore/backup-dropped-descriptors
+++ b/pkg/ccl/backupccl/testdata/backup-restore/backup-dropped-descriptors
@@ -130,6 +130,11 @@ exec-sql
 SET CLUSTER SETTING jobs.debug.pausepoints = 'schemachanger.before.exec';
 ----
 
+query-sql
+SELECT id, name FROM system.namespace WHERE name = 's';
+----
+112 s
+
 schema-change expect-pausepoint
 DROP SCHEMA d2.s CASCADE;
 ----

Then, when I ran with: ./dev test pkg/ccl/backupccl -f TestDataDriven_backup_dropped_descriptors --stress --count=200, I got:

==================== Test output for //pkg/ccl/backupccl:backupccl_test (run 150 of 200):
I240326 06:18:14.456043 1 (gostd) rand.go:250  [-] 1  random seed: 3448683347250967837
test logs left over in: /tmp/_tmp/9ec53f3970e0daeba7b0705722a2cad8/logTestDataDriven_backup_dropped_descriptors1752351742
--- FAIL: TestDataDriven_backup_dropped_descriptors (6.96s)
    test_log_scope.go:170: test logs captured to: /tmp/_tmp/9ec53f3970e0daeba7b0705722a2cad8/logTestDataDriven_backup_dropped_descriptors1752351742
    test_log_scope.go:81: use -show-logs to present logs inline
    datadriven_test.go:446: Mock HTTP Storage "http://127.0.0.1:64268"
    --- FAIL: TestDataDriven_backup_dropped_descriptors/dropped-schema-descriptors (2.73s)
        test_server_shim.go:157: automatically injected an external process virtual cluster under test; see comment at top of test_server_shim.go for details.
        datadriven.go:259:
            /private/var/tmp/_bazel_rafiss/9796b4657e3f3e4bab52d5a958783c22/sandbox/darwin-sandbox/2348/execroot/com_github_cockroachdb_cockroach/bazel-out/darwin_arm64-fastbuild/bin/pkg/ccl/backupccl/backupccl_test_/backupccl_test.runfiles/com_github_cockroachdb_cockroach/pkg/ccl/backupccl/testdata/backup-restore/backup-dropped-descriptors:133:
             SELECT id, name FROM system.namespace WHERE name = 's';
            expected:
            112 s

            found:
            114 s
    testutils.go:289: no Invalid Descriptors
    testutils.go:289: no Invalid Descriptors
    testutils.go:266: Warning: Could not check for invalid descriptors: sql: database is closed
    testutils.go:266: Warning: Could not check for invalid descriptors: sql: database is closed
    panic.go:626: -- test log scope end --

So I wonder if something about #120144 made it more likely for descriptor ID generation to create IDs in a different order.

[msbutler]

It would be a relief if all these test flakes are due to an incorrect assumption, but I'm not sure it's the root cause:

• If it were, I'd expect these suite of tests to have flaked before this change.
• One of the recent roachtest flakes, which i have yet to bisect to this change, suggests that a descriptor was missing from the backup: roachtest: backup-restore/round-trip failed: database restore with missing desc dep #120936 (comment)

[rafiss]

If it were, I'd expect these suite of tests to have flaked before this change.

Well the theory I have proposed is that the change made it more likely for the incorrect assumption to be violated. I don't yet have a solid theory for why, but it could be something like: the extra work that happens in order to apply the ExcludeDataFromBackup flag to the the relevant spans inside of system tables make the descriptor ID generation code more likely to hit transaction retries.

It would be a relief if all these test flakes are due to an incorrect assumption, but I'm not sure it's the root cause:

Yeah I agree, maybe it isn't the root cause. But IMO the example I posted above where I added

             SELECT id, name FROM system.namespace WHERE name = 's';
            expected:
            112 s

            found:
            114 s

does prove that the test is incorrect in assuming that the ID of s should be 112.

---

To check what's going on, I added some logging around whenever we generate a new descriptor ID, as well as when we auto-retry a transaction. Here's what happened:

database name=defaultdb id=100
public schema db=defaultdb name=public id=101
database name=postgres id=102
public schema db=postgres name=public id=103
database name=data id=104
public schema db=data name=public id=105
auto retry: TransactionRetryWithProtoRefreshError: TransactionRetryError: retry txn (RETRY_ASYNC_WRITE_FAILURE - missing intent on: /Tenant/10/NamespaceTable/30/1/0/0/"data"/4/1): "sql txn" meta={id=98a9a95
7 key=/Tenant/10/Table/3/1/104/2/1 iso=Serializable pri=0.02257735 epo=0 ts=1711465514.999416000,2 min=1711465514.954528000,0 seq=5} lock=true stat=PENDING rts=1711465514.999416000,2 wto=false gul=171146551
5.454528000,0
database name=data id=106
public schema db=data name=public id=107
table name=bank id=108
database name=d2 id=109
public schema db=d2 name=public id=110
table name=t2 id=111
udt type name=d2.public.typ id=112
array type name=d2.public.typ id=113
schema name=s id=114
table name=t id=115

This shows that creating the data database (here) is hitting a retry error, and that causes the IDs to all be off from what the test assumes.

In general, retry errors are always possible here. So I definitely think the test should be updated to account for that.

However, I don't have a good explanation yet for why #120144 made it more likely for the RETRY_ASYNC_WRITE_FAILURE - missing intent error to occur.

[rafiss]

From our docs

The RETRY_ASYNC_WRITE_FAILURE error occurs when some kind of problem with your cluster's operation occurs at the moment of a previous write in the transaction, causing CockroachDB to fail to replicate one of the transaction's writes. This can happen if a lease transfer occurs while the transaction is executing, or less commonly if you have a network partition that cuts off access to some nodes in your cluster.

Maybe it's something like:

1. Applying the ExcludeDataFromBackup flag to system tables requires split points to be added due to @stevendanna's fix in kvserver: don't apply ExcludeDataFromBackup outside config bounds #120188.
2. With more split points, it's more likely for the leaseholder of one of the system ranges to be transferred somewhere else in close proximity to the cluster starting up.

I can test that theory by disabling lease transfers.

[msbutler]

Sounds good. Agreed that tests should not assume a descriptor ID. I can try updating this test to be descID agnostic. If it's green under stress, then I think we can remove the Release blocker for this.

If your lease transfer theory holds, the roachtest failure could be explained by a bad bug in backup/restore logic that assumes something about descriptor ID values. But no need to hypothesize yet :)

[rafiss]

I tried using the BlockTransferTarget testing knob. But the test still hit a transaction retry:

database name=defaultdb id=100
public schema db=defaultdb name=public id=101
auto retry: TransactionRetryWithProtoRefreshError: TransactionRetryError: retry txn (RETRY_ASYNC_WRITE_FAILURE - missing intent on: /Tenant/10/NamespaceTable/30/1/0/0/"defaultdb"/4/1): "sql txn" meta={id=f93868ba key=/Tenant/10/Table/3/1/100/2/1 iso=Serializable pri=0.01345403 epo=0 ts=1711470047.005753000,0 min=1711470047.005753000,0 seq=5} lock=true stat=PENDING rts=1711470047.005753000,0 wto=false gul=1711470047.505753000,0
database name=defaultdb id=102
public schema db=defaultdb name=public id=103

---

As another experiment, I changed clusterCfg.defaultTestTenant to always be base.TODOTestTenantDisabled. This makes the test pass reliably.