Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

roachtest: schemachange/invertedindex failed #91977

Closed
cockroach-teamcity opened this issue Nov 16, 2022 · 20 comments · Fixed by #98262
Closed

roachtest: schemachange/invertedindex failed #91977

cockroach-teamcity opened this issue Nov 16, 2022 · 20 comments · Fixed by #98262
Labels
branch-master Failures on the master branch. C-test-failure Broken test (automatically or manually discovered). O-roachtest O-robot Originated from a bot. release-blocker Indicates a release-blocker. Use with branch-release-2x.x label to denote which branch is blocked. T-sql-foundations SQL Foundations Team (formerly SQL Schema + SQL Sessions)
Milestone

Comments

@cockroach-teamcity
Copy link
Member

cockroach-teamcity commented Nov 16, 2022

roachtest.schemachange/invertedindex failed with artifacts on master @ d98d195dfa7a3480ce3e07657aa870692fe71cea:

test artifacts and logs in: /artifacts/schemachange/invertedindex/run_1
(test_impl.go:291).Fatal: output in run_094929.834993958_n5_workload_run_json: ./workload run json --read-percent=50 --duration 1h0m0s {pgurl:1-4} --sequential returned: COMMAND_PROBLEM: exit status 1
(test_impl.go:291).Fatal: monitor failure: monitor task failed: t.Fatal() was called

Parameters: ROACHTEST_cloud=gce , ROACHTEST_cpu=4 , ROACHTEST_encrypted=false , ROACHTEST_ssd=0

Help

See: roachtest README

See: How To Investigate (internal)

/cc @cockroachdb/sql-schema

This test on roachdash | Improve this report!

Jira issue: CRDB-21504

@cockroach-teamcity cockroach-teamcity added branch-master Failures on the master branch. C-test-failure Broken test (automatically or manually discovered). O-roachtest O-robot Originated from a bot. release-blocker Indicates a release-blocker. Use with branch-release-2x.x label to denote which branch is blocked. labels Nov 16, 2022
@cockroach-teamcity cockroach-teamcity added this to the 23.1 milestone Nov 16, 2022
@blathers-crl blathers-crl bot added the T-sql-schema-deprecated Use T-sql-foundations instead label Nov 16, 2022
@ajwerner
Copy link
Contributor

This had a weird stall for more than 11s in the workload which is not obviously attributable, and then the workload gets an error about a nonsensical deadline and exits. The deadline error propagation is somewhat tracked in #76727.

@ajwerner ajwerner moved this from Triage to Requiring Investigation in SQL Foundations Nov 22, 2022
@cockroach-teamcity
Copy link
Member Author

roachtest.schemachange/invertedindex failed with artifacts on master @ 6723e00a46aaa3ea575093bd82a02b7d6f6b131b:

test artifacts and logs in: /artifacts/schemachange/invertedindex/run_1
(test_impl.go:291).Fatal: output in run_081206.829525081_n5_workload_run_json: ./workload run json --read-percent=50 --duration 1h0m0s {pgurl:1-4} --sequential returned: COMMAND_PROBLEM: exit status 1
(test_impl.go:291).Fatal: monitor failure: monitor task failed: t.Fatal() was called

Parameters: ROACHTEST_cloud=gce , ROACHTEST_cpu=4 , ROACHTEST_encrypted=false , ROACHTEST_ssd=0

Help

See: roachtest README

See: How To Investigate (internal)

This test on roachdash | Improve this report!

@cockroach-teamcity
Copy link
Member Author

roachtest.schemachange/invertedindex failed with artifacts on master @ 286b3e235171a39b8f9910555affcc7ce310741a:

test artifacts and logs in: /artifacts/schemachange/invertedindex/run_1
(cluster.go:1956).Run: output in run_095033.704370316_n5_workload-run-json-re: ./workload run json --read-percent=50 --duration 1h0m0s {pgurl:1-4} --sequential returned: context canceled
(monitor.go:127).Wait: monitor failure: monitor task failed: pq: failed to verify keys for Scan: end key /Table/106/3/Arr/"b"/NULL/14632/0/NULL must be greater than start /Table/106/3/Arr/"b"/NULL/14632/0/NULL

Parameters: ROACHTEST_cloud=gce , ROACHTEST_cpu=4 , ROACHTEST_encrypted=false , ROACHTEST_ssd=0

Help

See: roachtest README

See: How To Investigate (internal)

This test on roachdash | Improve this report!

@cockroach-teamcity
Copy link
Member Author

roachtest.schemachange/invertedindex failed with artifacts on master @ e028ce5b14505dfd17ef8b13001c0ab8ac811e3c:

test artifacts and logs in: /artifacts/schemachange/invertedindex/run_1
(cluster.go:1956).Run: output in run_095441.074287230_n5_workload-run-json-re: ./workload run json --read-percent=50 --duration 1h0m0s {pgurl:1-4} --sequential returned: context canceled
(monitor.go:127).Wait: monitor failure: monitor task failed: pq: failed to verify keys for Scan: end key /Table/106/3/Arr/"rIb0"/NULL/12066/0/NULL must be greater than start /Table/106/3/Arr/"rIb0"/NULL/12066/0/NULL

Parameters: ROACHTEST_cloud=gce , ROACHTEST_cpu=4 , ROACHTEST_encrypted=false , ROACHTEST_ssd=0

Help

See: roachtest README

See: How To Investigate (internal)

This test on roachdash | Improve this report!

@kvoli kvoli self-assigned this Feb 23, 2023
@cockroach-teamcity
Copy link
Member Author

roachtest.schemachange/invertedindex failed with artifacts on master @ 0d3393b0623a5c258b25725f64f3689e2f54667b:

test artifacts and logs in: /artifacts/schemachange/invertedindex/run_1
(cluster.go:1956).Run: output in run_094823.236625211_n5_workload-run-json-re: ./workload run json --read-percent=50 --duration 1h0m0s {pgurl:1-4} --sequential returned: context canceled
(monitor.go:127).Wait: monitor failure: monitor task failed: pq: failed to verify keys for Scan: end key /Table/106/3/Arr/"gM"/"bar"/True/16700/0/NULL must be greater than start /Table/106/3/Arr/"gM"/"bar"/True/16700/0/NULL

Parameters: ROACHTEST_cloud=gce , ROACHTEST_cpu=4 , ROACHTEST_encrypted=false , ROACHTEST_ssd=0

Help

See: roachtest README

See: How To Investigate (internal)

This test on roachdash | Improve this report!

@cockroach-teamcity
Copy link
Member Author

roachtest.schemachange/invertedindex failed with artifacts on master @ 39c06b5a438c01c93ffbfeeefe702d3f9b620eaf:

test artifacts and logs in: /artifacts/schemachange/invertedindex/run_1
(cluster.go:1956).Run: output in run_090228.030437973_n5_workload-run-json-re: ./workload run json --read-percent=50 --duration 1h0m0s {pgurl:1-4} --sequential returned: context canceled
(monitor.go:127).Wait: monitor failure: monitor task failed: pq: failed to verify keys for Scan: end key /Table/106/3/Arr/"gD"/False/15499/0/NULL must be greater than start /Table/106/3/Arr/"gD"/False/15499/0/NULL

Parameters: ROACHTEST_cloud=gce , ROACHTEST_cpu=4 , ROACHTEST_encrypted=false , ROACHTEST_ssd=0

Help

See: roachtest README

See: How To Investigate (internal)

This test on roachdash | Improve this report!

@kvoli
Copy link
Collaborator

kvoli commented Feb 27, 2023

With #97539 merged, the subsequent failures don't look related to recent changes to do with rebalancing or splitting.

The error is coming from: #97539

cc @ajwerner

@kvoli kvoli removed their assignment Feb 27, 2023
@cockroach-teamcity
Copy link
Member Author

roachtest.schemachange/invertedindex failed with artifacts on master @ 21786aa112e6b822858f281c1cc59608987c5c0a:

test artifacts and logs in: /artifacts/schemachange/invertedindex/run_1
(cluster.go:1956).Run: output in run_090113.352348136_n5_workload-run-json-re: ./workload run json --read-percent=50 --duration 1h0m0s {pgurl:1-4} --sequential returned: context canceled
(monitor.go:127).Wait: monitor failure: monitor task failed: pq: failed to verify keys for Scan: end key /Table/106/3/Arr/"nO3I2I"/True/20490/0/NULL must be greater than start /Table/106/3/Arr/"nO3I2I"/True/20490/0/NULL

Parameters: ROACHTEST_cloud=gce , ROACHTEST_cpu=4 , ROACHTEST_encrypted=false , ROACHTEST_ssd=0

Help

See: roachtest README

See: How To Investigate (internal)

This test on roachdash | Improve this report!

@ajwerner ajwerner added this to Triage in SQL Queries via automation Mar 1, 2023
@blathers-crl blathers-crl bot added the T-sql-queries SQL Queries Team label Mar 1, 2023
@ajwerner
Copy link
Contributor

ajwerner commented Mar 1, 2023

@cockroachdb/sql-queries, I'm tagging y'all because I think this has something to do with query execution. The workload which is doing a single json workload, seems to be constructing bad batch requests.

@cockroach-teamcity
Copy link
Member Author

roachtest.schemachange/invertedindex failed with artifacts on master @ cf14ad694ee562676f53e36fa8495206c3aed61f:

test artifacts and logs in: /artifacts/schemachange/invertedindex/run_1
(cluster.go:1968).Run: output in run_090436.619985041_n5_workload-run-json-re: ./workload run json --read-percent=50 --duration 1h0m0s {pgurl:1-4} --sequential returned: context canceled
(monitor.go:127).Wait: monitor failure: monitor task failed: pq: failed to verify keys for Scan: end key /Table/106/3/Arr/"c"/Arr/NULL/10547/0/NULL must be greater than start /Table/106/3/Arr/"c"/Arr/NULL/10547/0/NULL

Parameters: ROACHTEST_cloud=gce , ROACHTEST_cpu=4 , ROACHTEST_encrypted=false , ROACHTEST_ssd=0

Help

See: roachtest README

See: How To Investigate (internal)

This test on roachdash | Improve this report!

@mgartner mgartner removed this from Requiring Investigation in SQL Foundations Mar 8, 2023
@msirek
Copy link
Contributor

msirek commented Mar 8, 2023

I've been unable to reproduce this so far.

@msirek
Copy link
Contributor

msirek commented Mar 8, 2023

Stack trace:

teamcity-8880604-1677651368-21-n5cpu4-0001> W230301 09:07:01.637217 166952 sql/schemachanger/scrun/scrun.go:134 ⋮ [T1,n1,job=‹×›] 1404 failed executing declarative schema change PostCommitPhase stage 5 of 7 with 1 BackfillType op (rollback=false) for CREATE INDEX with error: failed to verify keys for Scan: end key /Table/106/3/‹×›/‹×›/‹×›/‹×›/‹×› must be greater than start /Table/106/3/‹×›/‹×›/‹×›/‹×›/‹×›
teamcity-8880604-1677651368-21-n5cpu4-0001> I230301 09:07:01.638472 166952 jobs/registry.go:1493 ⋮ [T1,n1] 1405 NEW SCHEMA CHANGE job 844073774019510273: stepping through state reverting with error: failed to verify keys for Scan: end key /Table/106/3/‹×›/‹×›/‹×›/‹×›/‹×› must be greater than start /Table/106/3/‹×›/‹×›/‹×›/‹×›/‹×›
(1) tags: [n1,received-error]
Wraps: (2) tags: [n‹×›,f‹×›,job=‹×›,distsql.gateway=‹×›,sent-error=‹×›]
Wraps: (3)
  | (opaque error wrapper)
  | type name: github.com/cockroachdb/errors/withstack/*withstack.withStack
  | reportable 0:
  |
  | github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*Store).SendWithWriteBytes
  | 	github.com/cockroachdb/cockroach/pkg/kv/kvserver/pkg/kv/kvserver/store_send.go:68
  | github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*Stores).SendWithWriteBytes
  | 	github.com/cockroachdb/cockroach/pkg/kv/kvserver/pkg/kv/kvserver/stores.go:202
  | github.com/cockroachdb/cockroach/pkg/server.(*Node).batchInternal
  | 	github.com/cockroachdb/cockroach/pkg/server/node.go:1150
  | github.com/cockroachdb/cockroach/pkg/server.(*Node).Batch
  | 	github.com/cockroachdb/cockroach/pkg/server/node.go:1220
  | github.com/cockroachdb/cockroach/pkg/rpc.makeInternalClientAdapter.func1
  | 	github.com/cockroachdb/cockroach/pkg/rpc/pkg/rpc/context.go:802
  | github.com/cockroachdb/cockroach/pkg/util/tracing/grpcinterceptor.ServerInterceptor.func1
  | 	github.com/cockroachdb/cockroach/pkg/util/tracing/grpcinterceptor/grpc_interceptor.go:96
  | github.com/cockroachdb/cockroach/pkg/rpc.bindUnaryServerInterceptorToHandler.func1
  | 	github.com/cockroachdb/cockroach/pkg/rpc/pkg/rpc/context.go:913
  | github.com/cockroachdb/cockroach/pkg/rpc.NewServerEx.func3
  | 	github.com/cockroachdb/cockroach/pkg/rpc/pkg/rpc/context.go:266
  | github.com/cockroachdb/cockroach/pkg/rpc.bindUnaryServerInterceptorToHandler.func1
  | 	github.com/cockroachdb/cockroach/pkg/rpc/pkg/rpc/context.go:913
  | github.com/cockroachdb/cockroach/pkg/rpc.NewServerEx.func1.1
  | 	github.com/cockroachdb/cockroach/pkg/rpc/pkg/rpc/context.go:233
  | github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunTaskWithErr
  | 	github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:322
  | github.com/cockroachdb/cockroach/pkg/rpc.NewServerEx.func1
  | 	github.com/cockroachdb/cockroach/pkg/rpc/pkg/rpc/context.go:231
  | github.com/cockroachdb/cockroach/pkg/rpc.bindUnaryServerInterceptorToHandler.func1
  | 	github.com/cockroachdb/cockroach/pkg/rpc/pkg/rpc/context.go:913
  | github.com/cockroachdb/cockroach/pkg/rpc.makeInternalClientAdapter.func2
  | 	github.com/cockroachdb/cockroach/pkg/rpc/pkg/rpc/context.go:812
  | github.com/cockroachdb/cockroach/pkg/util/tracing/grpcinterceptor.ClientInterceptor.func2
  | 	github.com/cockroachdb/cockroach/pkg/util/tracing/grpcinterceptor/grpc_interceptor.go:227
  | github.com/cockroachdb/cockroach/pkg/rpc.getChainUnaryInvoker.func1
  | 	github.com/cockroachdb/cockroach/pkg/rpc/pkg/rpc/context.go:997
  | github.com/cockroachdb/cockroach/pkg/rpc.makeInternalClientAdapter.func3
  | 	github.com/cockroachdb/cockroach/pkg/rpc/pkg/rpc/context.go:882
  | github.com/cockroachdb/cockroach/pkg/rpc.internalClientAdapter.Batch
  | 	github.com/cockroachdb/cockroach/pkg/rpc/pkg/rpc/context.go:1005
  | github.com/cockroachdb/cockroach/pkg/kv/kvclient/kvcoord.(*grpcTransport).sendBatch
  | 	github.com/cockroachdb/cockroach/pkg/kv/kvclient/kvcoord/transport.go:210
  | github.com/cockroachdb/cockroach/pkg/kv/kvclient/kvcoord.(*grpcTransport).SendNext
  | 	github.com/cockroachdb/cockroach/pkg/kv/kvclient/kvcoord/transport.go:189
  | github.com/cockroachdb/cockroach/pkg/kv/kvclient/kvcoord.(*DistSender).sendToReplicas
  | 	github.com/cockroachdb/cockroach/pkg/kv/kvclient/kvcoord/dist_sender.go:2141
  | github.com/cockroachdb/cockroach/pkg/kv/kvclient/kvcoord.(*DistSender).sendPartialBatch
  | 	github.com/cockroachdb/cockroach/pkg/kv/kvclient/kvcoord/dist_sender.go:1667
  | github.com/cockroachdb/cockroach/pkg/kv/kvclient/kvcoord.(*DistSender).divideAndSendBatchToRanges
  | 	github.com/cockroachdb/cockroach/pkg/kv/kvclient/kvcoord/dist_sender.go:1239
  | github.com/cockroachdb/cockroach/pkg/kv/kvclient/kvcoord.(*DistSender).Send
  | 	github.com/cockroachdb/cockroach/pkg/kv/kvclient/kvcoord/dist_sender.go:860
  | github.com/cockroachdb/cockroach/pkg/kv/kvclient/kvcoord.(*txnLockGatekeeper).SendLocked
  | 	github.com/cockroachdb/cockroach/pkg/kv/kvclient/kvcoord/txn_lock_gatekeeper.go:82
  | github.com/cockroachdb/cockroach/pkg/kv/kvclient/kvcoord.(*txnMetricRecorder).SendLocked
  | 	github.com/cockroachdb/cockroach/pkg/kv/kvclient/kvcoord/txn_interceptor_metric_recorder.go:47
  | github.com/cockroachdb/cockroach/pkg/kv/kvclient/kvcoord.(*txnCommitter).SendLocked
  | 	github.com/cockroachdb/cockroach/pkg/kv/kvclient/kvcoord/txn_interceptor_committer.go:130
  | github.com/cockroachdb/cockroach/pkg/kv/kvclient/kvcoord.(*txnSpanRefresher).sendLockedWithRefreshAttempts
  | 	github.com/cockroachdb/cockroach/pkg/kv/kvclient/kvcoord/txn_interceptor_span_refresher.go:226
  | github.com/cockroachdb/cockroach/pkg/kv/kvclient/kvcoord.(*txnSpanRefresher).SendLocked
  | 	github.com/cockroachdb/cockroach/pkg/kv/kvclient/kvcoord/txn_interceptor_span_refresher.go:154
  | github.com/cockroachdb/cockroach/pkg/kv/kvclient/kvcoord.(*txnPipeliner).SendLocked
  | 	github.com/cockroachdb/cockroach/pkg/kv/kvclient/kvcoord/txn_interceptor_pipeliner.go:291
  | github.com/cockroachdb/cockroach/pkg/kv/kvclient/kvcoord.(*txnSeqNumAllocator).SendLocked
  | 	github.com/cockroachdb/cockroach/pkg/kv/kvclient/kvcoord/txn_interceptor_seq_num_allocator.go:105
  | github.com/cockroachdb/cockroach/pkg/kv/kvclient/kvcoord.(*txnHeartbeater).SendLocked
  | 	github.com/cockroachdb/cockroach/pkg/kv/kvclient/kvcoord/txn_interceptor_heartbeater.go:246
Wraps: (4) failed to verify keys for Scan
Wraps: (5)
  | (opaque error wrapper)
  | type name: github.com/cockroachdb/errors/withstack/*withstack.withStack
  | reportable 0:
  |
  | github.com/cockroachdb/cockroach/pkg/kv/kvserver.verifyKeys
  | 	github.com/cockroachdb/cockroach/pkg/kv/kvserver/pkg/kv/kvserver/store.go:323
  | github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*Store).SendWithWriteBytes
  | 	github.com/cockroachdb/cockroach/pkg/kv/kvserver/pkg/kv/kvserver/store_send.go:67
  | github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*Stores).SendWithWriteBytes
  | 	github.com/cockroachdb/cockroach/pkg/kv/kvserver/pkg/kv/kvserver/stores.go:202
  | github.com/cockroachdb/cockroach/pkg/server.(*Node).batchInternal
  | 	github.com/cockroachdb/cockroach/pkg/server/node.go:1150
  | github.com/cockroachdb/cockroach/pkg/server.(*Node).Batch
  | 	github.com/cockroachdb/cockroach/pkg/server/node.go:1220
  | github.com/cockroachdb/cockroach/pkg/rpc.makeInternalClientAdapter.func1
  | 	github.com/cockroachdb/cockroach/pkg/rpc/pkg/rpc/context.go:802
  | github.com/cockroachdb/cockroach/pkg/util/tracing/grpcinterceptor.ServerInterceptor.func1
  | 	github.com/cockroachdb/cockroach/pkg/util/tracing/grpcinterceptor/grpc_interceptor.go:96
  | github.com/cockroachdb/cockroach/pkg/rpc.bindUnaryServerInterceptorToHandler.func1
  | 	github.com/cockroachdb/cockroach/pkg/rpc/pkg/rpc/context.go:913
  | github.com/cockroachdb/cockroach/pkg/rpc.NewServerEx.func3
  | 	github.com/cockroachdb/cockroach/pkg/rpc/pkg/rpc/context.go:266
  | github.com/cockroachdb/cockroach/pkg/rpc.bindUnaryServerInterceptorToHandler.func1
  | 	github.com/cockroachdb/cockroach/pkg/rpc/pkg/rpc/context.go:913
  | github.com/cockroachdb/cockroach/pkg/rpc.NewServerEx.func1.1
  | 	github.com/cockroachdb/cockroach/pkg/rpc/pkg/rpc/context.go:233
  | github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunTaskWithErr
  | 	github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:322
  | github.com/cockroachdb/cockroach/pkg/rpc.NewServerEx.func1
  | 	github.com/cockroachdb/cockroach/pkg/rpc/pkg/rpc/context.go:231
  | github.com/cockroachdb/cockroach/pkg/rpc.bindUnaryServerInterceptorToHandler.func1
  | 	github.com/cockroachdb/cockroach/pkg/rpc/pkg/rpc/context.go:913
  | github.com/cockroachdb/cockroach/pkg/rpc.makeInternalClientAdapter.func2
  | 	github.com/cockroachdb/cockroach/pkg/rpc/pkg/rpc/context.go:812
  | github.com/cockroachdb/cockroach/pkg/util/tracing/grpcinterceptor.ClientInterceptor.func2
  | 	github.com/cockroachdb/cockroach/pkg/util/tracing/grpcinterceptor/grpc_interceptor.go:227
  | github.com/cockroachdb/cockroach/pkg/rpc.getChainUnaryInvoker.func1
  | 	github.com/cockroachdb/cockroach/pkg/rpc/pkg/rpc/context.go:997
  | github.com/cockroachdb/cockroach/pkg/rpc.makeInternalClientAdapter.func3
  | 	github.com/cockroachdb/cockroach/pkg/rpc/pkg/rpc/context.go:882
  | github.com/cockroachdb/cockroach/pkg/rpc.internalClientAdapter.Batch
  | 	github.com/cockroachdb/cockroach/pkg/rpc/pkg/rpc/context.go:1005
  | github.com/cockroachdb/cockroach/pkg/kv/kvclient/kvcoord.(*grpcTransport).sendBatch
  | 	github.com/cockroachdb/cockroach/pkg/kv/kvclient/kvcoord/transport.go:210
  | github.com/cockroachdb/cockroach/pkg/kv/kvclient/kvcoord.(*grpcTransport).SendNext
  | 	github.com/cockroachdb/cockroach/pkg/kv/kvclient/kvcoord/transport.go:189
  | github.com/cockroachdb/cockroach/pkg/kv/kvclient/kvcoord.(*DistSender).sendToReplicas
  | 	github.com/cockroachdb/cockroach/pkg/kv/kvclient/kvcoord/dist_sender.go:2141
  | github.com/cockroachdb/cockroach/pkg/kv/kvclient/kvcoord.(*DistSender).sendPartialBatch
  | 	github.com/cockroachdb/cockroach/pkg/kv/kvclient/kvcoord/dist_sender.go:1667
  | github.com/cockroachdb/cockroach/pkg/kv/kvclient/kvcoord.(*DistSender).divideAndSendBatchToRanges
  | 	github.com/cockroachdb/cockroach/pkg/kv/kvclient/kvcoord/dist_sender.go:1239
  | github.com/cockroachdb/cockroach/pkg/kv/kvclient/kvcoord.(*DistSender).Send
  | 	github.com/cockroachdb/cockroach/pkg/kv/kvclient/kvcoord/dist_sender.go:860
  | github.com/cockroachdb/cockroach/pkg/kv/kvclient/kvcoord.(*txnLockGatekeeper).SendLocked
  | 	github.com/cockroachdb/cockroach/pkg/kv/kvclient/kvcoord/txn_lock_gatekeeper.go:82
  | github.com/cockroachdb/cockroach/pkg/kv/kvclient/kvcoord.(*txnMetricRecorder).SendLocked
  | 	github.com/cockroachdb/cockroach/pkg/kv/kvclient/kvcoord/txn_interceptor_metric_recorder.go:47
  | github.com/cockroachdb/cockroach/pkg/kv/kvclient/kvcoord.(*txnCommitter).SendLocked
  | 	github.com/cockroachdb/cockroach/pkg/kv/kvclient/kvcoord/txn_interceptor_committer.go:130
  | github.com/cockroachdb/cockroach/pkg/kv/kvclient/kvcoord.(*txnSpanRefresher).sendLockedWithRefreshAttempts
  | 	github.com/cockroachdb/cockroach/pkg/kv/kvclient/kvcoord/txn_interceptor_span_refresher.go:226
  | github.com/cockroachdb/cockroach/pkg/kv/kvclient/kvcoord.(*txnSpanRefresher).SendLocked
  | 	github.com/cockroachdb/cockroach/pkg/kv/kvclient/kvcoord/txn_interceptor_span_refresher.go:154
  | github.com/cockroachdb/cockroach/pkg/kv/kvclient/kvcoord.(*txnPipeliner).SendLocked
  | 	github.com/cockroachdb/cockroach/pkg/kv/kvclient/kvcoord/txn_interceptor_pipeliner.go:291
  | github.com/cockroachdb/cockroach/pkg/kv/kvclient/kvcoord.(*txnSeqNumAllocator).SendLocked
  | 	github.com/cockroachdb/cockroach/pkg/kv/kvclient/kvcoord/txn_interceptor_seq_num_allocator.go:105
Wraps: (6) end key /Table/106/3/‹×›/‹×›/‹×›/‹×›/‹×› must be greater than start /Table/106/3/‹×›/‹×›/‹×›/‹×›/‹×›

@msirek
Copy link
Contributor

msirek commented Mar 8, 2023

230308 18:33:27.982743 873129 kv/kvserver/split_queue.go:212 ⋮ [T1,n1,split,s1,r146/4:‹/Table/106/2/Arr/{Arr/…-"6g"…}›] 1162  split saw concurrent descriptor modification; maybe retrying; err: split at key /Table/106/2/‹Arr/"EUgJwn"/"IM4maFA2"›/‹"c"›/‹12912215› failed: descriptor changed: [expected] r146:‹/Table/106/2/Arr/{Arr/"baz"/3187730-"pey8"/NULL/5088058}› [(n4,s4):1, (n2,s2):2, (n1,s1):4, next=5, gen=91, sticky=1678303957.114260268,0] != [actual] r146:‹/Table/106/2/Arr/{Arr/"baz"/3187730-"6g"/Arr/0.23614991113843475/11687521}› [(n4,s4):1, (n2,s2):2, (n1,s1):4, next=5, gen=92, sticky=1678303957.114260268,0]: unexpected value: ‹raw_bytes:"&\201\371'\003\010\222\001\022\023\362\2127\000\003\000\003\000\001\022baz\000\001\3700\244\022\032\034\362\2127\000\0036g\000\002\000\003\000\001)/{c\267\027MW_d\000\370\262Va\"\010\010\004\020\004\030\001 \000\"\010\010\002\020\002\030\002 \000\"\010\010\001\020\001\030\004 \000(\0050\\:\n\010\254\226\266\247\351\221\242\245\027" timestamp:<wall_time:1678300398980212794 >›

I230308 18:33:43.589381 894458 kv/kvserver/split_queue.go:212 ⋮ [T1,n1,split,s1,r147/4:‹/Table/106/2/{Arr/"p…-"KiAwA…}›] 1190  split saw concurrent descriptor modification; maybe retrying; err: split at key /Table/106/2/‹"NTc"/"zRWt"›/‹True›/‹3828536› failed: descriptor changed: [expected] r147:‹/Table/106/2/{Arr/"pey8"/NULL/5088058-"bar"/Arr/NULL/2366786}› [(n4,s4):1, (n2,s2):2, (n1,s1):4, next=5, gen=95, sticky=1678303957.114260268,0] != [actual] r147:‹/Table/106/2/{Arr/"pey8"/NULL/5088058-"KiAwAY"/Arr/0.2910046695627784/11731017}› [(n4,s4):1, (n2,s2):2, (n1,s1):4, next=5, gen=96, sticky=1678303957.114260268,0]: unexpected value: ‹raw_bytes:"+v\233\221\003\010\223\001\022\020\362\2127\000\003pey8\000\001\000\370M\243:\032\035\362\2127KiAwAY\000\002\000\003\000\001);\025\t\205\277}\233\250\000\370\263\000I\"\010\010\004\020\004\030\001 \000\"\010\010\002\020\002\030\002 \000\"\010\010\001\020\001\030\004 \000(\0050`:\n\010\254\226\266\247\351\221\242\245\027" timestamp:<wall_time:1678300410375293028 >›

I230308 18:34:21.022219 932467 kv/kvserver/replica_command.go:410 ⋮ [T1,n1,split,s1,r211/3:‹/Table/106/2/"{KiAwA…-bar"/…}›] 1244  initiating a split of this range at key /Table/106/2/‹"a"›/‹NULL›/‹8555412› [r217] (‹518 MiB above threshold size 512 MiB›)‹›

I230308 18:34:26.815545 932467 kv/kvserver/split_queue.go:212 ⋮ [T1,n1,split,s1,r211/3:‹/Table/106/2/"{KiAwA…-VSZjb…}›] 1250  split saw concurrent descriptor modification; maybe retrying; err: split at key /Table/106/2/‹"a"›/‹NULL›/‹8555412› failed: descriptor changed: [expected] r211:‹/Table/106/2/"{KiAwAY"/Arr/0.2910046695627784/11731017-bar"/Arr/NULL/2366786}› [(n4,s4):1, (n2,s2):2, (n1,s1):3, next=4, gen=96, sticky=1678301010.374951480,0] != [actual] r211:‹/Table/106/2/"{KiAwAY"/Arr/0.2910046695627784/11731017-VSZjbptG"/False/16021885}› [(n4,s4):1, (n2,s2):2, (n1,s1):3, next=4, gen=97, sticky=1678301010.374951480,0]: unexpected value: ‹raw_bytes:"\260yd\023\003\010\323\001\022\035\362\2127KiAwAY\000\002\000\003\000\001);\025\t\205\277}\233\250\000\370\263\000I\032\022\362\2127VSZjbptG\000\001\013\370\364y}\"\010\010\004\020\004\030\001 \000\"\010\010\002\020\002\030\002 \000\"\010\010\001\020\001\030\003 \000(\0040a:\n\010\270\204\320\354\207\274\241\245\027" timestamp:<wall_time:1678300455748773096 >›
W230308 18:34:26.816767 554623 kv/bulk/sst_batcher.go:581 ⋮ [T1,n1,f‹c43f656f›,job=0,distsql.gateway=‹1›,indexBackfillerProcessor=106] 1251  ‹j backfill› failed to scatter     : existing range size 349555727 exceeds specified limit 4194304

I230308 18:34:55.249858 89339 sql/schemachanger/scrun/scrun.go:176 ⋮ [T1,n1,job=‹NEW SCHEMA CHANGE id=846167522586689537›] 1286  executing declarative schema change PostCommitPhase stage 4 of 7 with 3 MutationType ops (rollback=false) for CREATE INDEX
I230308 18:34:55.312271 89339 sql/catalog/lease/lease.go:168 ⋮ [T1,n1,job=‹NEW SCHEMA CHANGE id=846167522586689537›] 1287  waiting for 4 leases to expire: desc=[{‹j› 106 4}]
I230308 18:34:55.329894 89339 sql/catalog/lease/lease.go:168 ⋮ [T1,n1,job=‹NEW SCHEMA CHANGE id=846167522586689537›] 1288  waiting for 3 leases to expire: desc=[{‹j› 106 4}]
I230308 18:34:55.330010 989213 sql/catalog/lease/descriptor_state.go:142 ⋮ [T1,n1] 1289  new lease: tabledesc.immutable: {ID: 106, Version: 5, ModificationTime: "1678300495.249816138,0", ParentID: 104, ParentSchemaID: 105, State: PUBLIC, NextColumnID: 3, Columns: [{ID: 1, TypeID: 20, Null: false}, {ID: 2, TypeID: 3802, Null: false}], NextFamilyID: 1, Families: [{ID: 0, Columns: [1, 2]}], Mutations: [{MutationID: 1, Direction: ADD, State: MERGING, Index: {ID: 2, Unique: false, KeyColumns: [{ID: 2, Dir: ASC}], KeySuffixColumns: [1], State: ADD, MutationID: 1}}, {MutationID: 1, Direction: ADD, State: WRITE_ONLY, Index: {ID: 3, Unique: false, KeyColumns: [{ID: 2, Dir: ASC}], KeySuffixColumns: [1], State: ADD, MutationID: 1}}], PrimaryIndex: 1, NextIndexID: 4, Indexes: [{ID: 1, Unique: true, KeyColumns: [{ID: 1, Dir: ASC}], StoreColumns: [2]}]}
I230308 18:34:55.356880 89339 sql/catalog/lease/lease.go:168 ⋮ [T1,n1,job=‹NEW SCHEMA CHANGE id=846167522586689537›] 1290  waiting for 1 leases to expire: desc=[{‹j› 106 4}]
I230308 18:34:55.369700 89339 sql/schemachanger/scrun/scrun.go:176 ⋮ [T1,n1,job=‹NEW SCHEMA CHANGE id=846167522586689537›] 1291  executing declarative schema change PostCommitPhase stage 5 of 7 with 1 BackfillType op (rollback=false) for CREATE INDEX

W230308 18:35:00.293963 89339 sql/schemachanger/scrun/scrun.go:134 ⋮ [T1,n1,job=‹NEW SCHEMA CHANGE id=846167522586689537›] 1297  failed executing declarative schema change PostCommitPhase stage 5 of 7 with 1 BackfillType op (rollback=false) for CREATE INDEX with error: failed to verify keys for Scan: end key /Table/106/3/‹Arr/"foobar"/Arr›/‹True›/‹11243›/‹0›/‹NULL› must be greater than start /Table/106/3/‹Arr/"foobar"/Arr›/‹True›/‹11243›/‹0›/‹NULL›
I230308 18:35:00.294935 89339 jobs/registry.go:1493 ⋮ [T1,n1] 1298  NEW SCHEMA CHANGE job 846167522586689537: stepping through state reverting with error: failed to verify keys for Scan: end key /Table/106/3/‹Arr/"foobar"/Arr›/‹True›/‹11243›/‹0›/‹NULL› must be greater than start /Table/106/3/‹Arr/"foobar"/Arr›/‹True›/‹11243›/‹0›/‹NULL›

I230308 18:35:00.294935 89339 jobs/registry.go:1493 ⋮ [T1,n1] 1298 +(1) tags: [n1,received-error]
I230308 18:35:00.294935 89339 jobs/registry.go:1493 ⋮ [T1,n1] 1298 +Wraps: (2) tags: [n‹3›,f‹a92a8f3e›,job=‹NEW SCHEMA CHANGE id=846167522586689537›,distsql.gateway=‹1›,sent-error=‹›]
I230308 18:35:00.294935 89339 jobs/registry.go:1493 ⋮ [T1,n1] 1298 +Wraps: (3)
I230308 18:35:00.294935 89339 jobs/registry.go:1493 ⋮ [T1,n1] 1298 +  | (opaque error wrapper)
I230308 18:35:00.294935 89339 jobs/registry.go:1493 ⋮ [T1,n1] 1298 +  | type name: github.com/cockroachdb/errors/withstack/*withstack.withStack
I230308 18:35:00.294935 89339 jobs/registry.go:1493 ⋮ [T1,n1] 1298 +  | reportable 0:
I230308 18:35:00.294935 89339 jobs/registry.go:1493 ⋮ [T1,n1] 1298 +  |
I230308 18:35:00.294935 89339 jobs/registry.go:1493 ⋮ [T1,n1] 1298 +  | github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*Store).SendWithWriteBytes
I230308 18:35:00.294935 89339 jobs/registry.go:1493 ⋮ [T1,n1] 1298 +  |         github.com/cockroachdb/cockroach/pkg/kv/kvserver/pkg/kv/kvserver/store_send.go:68
I230308 18:35:00.294935 89339 jobs/registry.go:1493 ⋮ [T1,n1] 1298 +  | github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*Stores).SendWithWriteBytes
I230308 18:35:00.294935 89339 jobs/registry.go:1493 ⋮ [T1,n1] 1298 +  |         github.com/cockroachdb/cockroach/pkg/kv/kvserver/pkg/kv/kvserver/stores.go:202
I230308 18:35:00.294935 89339 jobs/registry.go:1493 ⋮ [T1,n1] 1298 +  | github.com/cockroachdb/cockroach/pkg/server.(*Node).batchInternal
I230308 18:35:00.294935 89339 jobs/registry.go:1493 ⋮ [T1,n1] 1298 +  |         github.com/cockroachdb/cockroach/pkg/server/node.go:1150
I230308 18:35:00.294935 89339 jobs/registry.go:1493 ⋮ [T1,n1] 1298 +  | github.com/cockroachdb/cockroach/pkg/server.(*Node).Batch
I230308 18:35:00.294935 89339 jobs/registry.go:1493 ⋮ [T1,n1] 1298 +  |         github.com/cockroachdb/cockroach/pkg/server/node.go:1220
I230308 18:35:00.294935 89339 jobs/registry.go:1493 ⋮ [T1,n1] 1298 +  | github.com/cockroachdb/cockroach/pkg/kv/kvpb._Internal_Batch_Handler.func1
I230308 18:35:00.294935 89339 jobs/registry.go:1493 ⋮ [T1,n1] 1298 +  |         github.com/cockroachdb/cockroach/pkg/kv/kvpb/bazel-out/k8-fastbuild/bin/pkg/kv/kvpb/kvpb_go_proto_/github.com/cockroachdb/cockroach/pkg/kv/kvpb/api.pb.go:9909
I230308 18:35:00.294935 89339 jobs/registry.go:1493 ⋮ [T1,n1] 1298 +  | github.com/cockroachdb/cockroach/pkg/util/tracing/grpcinterceptor.ServerInterceptor.func1
I230308 18:35:00.294935 89339 jobs/registry.go:1493 ⋮ [T1,n1] 1298 +  |         github.com/cockroachdb/cockroach/pkg/util/tracing/grpcinterceptor/grpc_interceptor.go:96
I230308 18:35:00.294935 89339 jobs/registry.go:1493 ⋮ [T1,n1] 1298 +  | google.golang.org/grpc.chainUnaryInterceptors.func1.1
I230308 18:35:00.294935 89339 jobs/registry.go:1493 ⋮ [T1,n1] 1298 +  |         google.golang.org/grpc/external/org_golang_google_grpc/server.go:1162
I230308 18:35:00.294935 89339 jobs/registry.go:1493 ⋮ [T1,n1] 1298 +  | github.com/cockroachdb/cockroach/pkg/rpc.NewServerEx.func3
I230308 18:35:00.294935 89339 jobs/registry.go:1493 ⋮ [T1,n1] 1298 +  |         github.com/cockroachdb/cockroach/pkg/rpc/pkg/rpc/context.go:266
I230308 18:35:00.294935 89339 jobs/registry.go:1493 ⋮ [T1,n1] 1298 +  | google.golang.org/grpc.chainUnaryInterceptors.func1.1
I230308 18:35:00.294935 89339 jobs/registry.go:1493 ⋮ [T1,n1] 1298 +  |         google.golang.org/grpc/external/org_golang_google_grpc/server.go:1165
I230308 18:35:00.294935 89339 jobs/registry.go:1493 ⋮ [T1,n1] 1298 +  | github.com/cockroachdb/cockroach/pkg/rpc.NewServerEx.func1.1
I230308 18:35:00.294935 89339 jobs/registry.go:1493 ⋮ [T1,n1] 1298 +  |         github.com/cockroachdb/cockroach/pkg/rpc/pkg/rpc/context.go:233
I230308 18:35:00.294935 89339 jobs/registry.go:1493 ⋮ [T1,n1] 1298 +  | github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunTaskWithErr
I230308 18:35:00.294935 89339 jobs/registry.go:1493 ⋮ [T1,n1] 1298 +  |         github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:322
I230308 18:35:00.294935 89339 jobs/registry.go:1493 ⋮ [T1,n1] 1298 +  | github.com/cockroachdb/cockroach/pkg/rpc.NewServerEx.func1
I230308 18:35:00.294935 89339 jobs/registry.go:1493 ⋮ [T1,n1] 1298 +  |         github.com/cockroachdb/cockroach/pkg/rpc/pkg/rpc/context.go:231
I230308 18:35:00.294935 89339 jobs/registry.go:1493 ⋮ [T1,n1] 1298 +  | google.golang.org/grpc.chainUnaryInterceptors.func1.1
I230308 18:35:00.294935 89339 jobs/registry.go:1493 ⋮ [T1,n1] 1298 +  |         google.golang.org/grpc/external/org_golang_google_grpc/server.go:1165
I230308 18:35:00.294935 89339 jobs/registry.go:1493 ⋮ [T1,n1] 1298 +  | google.golang.org/grpc.chainUnaryInterceptors.func1
I230308 18:35:00.294935 89339 jobs/registry.go:1493 ⋮ [T1,n1] 1298 +  |         google.golang.org/grpc/external/org_golang_google_grpc/server.go:1167
I230308 18:35:00.294935 89339 jobs/registry.go:1493 ⋮ [T1,n1] 1298 +  | github.com/cockroachdb/cockroach/pkg/kv/kvpb._Internal_Batch_Handler
I230308 18:35:00.294935 89339 jobs/registry.go:1493 ⋮ [T1,n1] 1298 +  |         github.com/cockroachdb/cockroach/pkg/kv/kvpb/bazel-out/k8-fastbuild/bin/pkg/kv/kvpb/kvpb_go_proto_/github.com/cockroachdb/cockroach/pkg/kv/kvpb/api.pb.go:9911
I230308 18:35:00.294935 89339 jobs/registry.go:1493 ⋮ [T1,n1] 1298 +  | google.golang.org/grpc.(*Server).processUnaryRPC
I230308 18:35:00.294935 89339 jobs/registry.go:1493 ⋮ [T1,n1] 1298 +  |         google.golang.org/grpc/external/org_golang_google_grpc/server.go:1340
I230308 18:35:00.294935 89339 jobs/registry.go:1493 ⋮ [T1,n1] 1298 +  | google.golang.org/grpc.(*Server).handleStream
I230308 18:35:00.294935 89339 jobs/registry.go:1493 ⋮ [T1,n1] 1298 +  |         google.golang.org/grpc/external/org_golang_google_grpc/server.go:1713
I230308 18:35:00.294935 89339 jobs/registry.go:1493 ⋮ [T1,n1] 1298 +  | google.golang.org/grpc.(*Server).serveStreams.func1.2
I230308 18:35:00.294935 89339 jobs/registry.go:1493 ⋮ [T1,n1] 1298 +  |         google.golang.org/grpc/external/org_golang_google_grpc/server.go:965
I230308 18:35:00.294935 89339 jobs/registry.go:1493 ⋮ [T1,n1] 1298 +  | runtime.goexit
I230308 18:35:00.294935 89339 jobs/registry.go:1493 ⋮ [T1,n1] 1298 +  |         GOROOT/src/runtime/asm_amd64.s:1594
I230308 18:35:00.294935 89339 jobs/registry.go:1493 ⋮ [T1,n1] 1298 +Wraps: (4) failed to verify keys for Scan
I230308 18:35:00.294935 89339 jobs/registry.go:1493 ⋮ [T1,n1] 1298 +Wraps: (5)
I230308 18:35:00.294935 89339 jobs/registry.go:1493 ⋮ [T1,n1] 1298 +  | (opaque error wrapper)
I230308 18:35:00.294935 89339 jobs/registry.go:1493 ⋮ [T1,n1] 1298 +  | type name: github.com/cockroachdb/errors/withstack/*withstack.withStack
I230308 18:35:00.294935 89339 jobs/registry.go:1493 ⋮ [T1,n1] 1298 +  | reportable 0:
I230308 18:35:00.294935 89339 jobs/registry.go:1493 ⋮ [T1,n1] 1298 +  |
I230308 18:35:00.294935 89339 jobs/registry.go:1493 ⋮ [T1,n1] 1298 +  | github.com/cockroachdb/cockroach/pkg/kv/kvserver.verifyKeys
I230308 18:35:00.294935 89339 jobs/registry.go:1493 ⋮ [T1,n1] 1298 +  |         github.com/cockroachdb/cockroach/pkg/kv/kvserver/pkg/kv/kvserver/store.go:323
I230308 18:35:00.294935 89339 jobs/registry.go:1493 ⋮ [T1,n1] 1298 +  | github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*Store).SendWithWriteBytes
I230308 18:35:00.294935 89339 jobs/registry.go:1493 ⋮ [T1,n1] 1298 +  |         github.com/cockroachdb/cockroach/pkg/kv/kvserver/pkg/kv/kvserver/store_send.go:67
I230308 18:35:00.294935 89339 jobs/registry.go:1493 ⋮ [T1,n1] 1298 +  | github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*Stores).SendWithWriteBytes
I230308 18:35:00.294935 89339 jobs/registry.go:1493 ⋮ [T1,n1] 1298 +  |         github.com/cockroachdb/cockroach/pkg/kv/kvserver/pkg/kv/kvserver/stores.go:202
I230308 18:35:00.294935 89339 jobs/registry.go:1493 ⋮ [T1,n1] 1298 +  | github.com/cockroachdb/cockroach/pkg/server.(*Node).batchInternal
I230308 18:35:00.294935 89339 jobs/registry.go:1493 ⋮ [T1,n1] 1298 +  |         github.com/cockroachdb/cockroach/pkg/server/node.go:1150
I230308 18:35:00.294935 89339 jobs/registry.go:1493 ⋮ [T1,n1] 1298 +  | github.com/cockroachdb/cockroach/pkg/server.(*Node).Batch
I230308 18:35:00.294935 89339 jobs/registry.go:1493 ⋮ [T1,n1] 1298 +  |         github.com/cockroachdb/cockroach/pkg/server/node.go:1220
I230308 18:35:00.294935 89339 jobs/registry.go:1493 ⋮ [T1,n1] 1298 +  | github.com/cockroachdb/cockroach/pkg/kv/kvpb._Internal_Batch_Handler.func1
I230308 18:35:00.294935 89339 jobs/registry.go:1493 ⋮ [T1,n1] 1298 +  |         github.com/cockroachdb/cockroach/pkg/kv/kvpb/bazel-out/k8-fastbuild/bin/pkg/kv/kvpb/kvpb_go_proto_/github.com/cockroachdb/cockroach/pkg/kv/kvpb/api.pb.go:9909
I230308 18:35:00.294935 89339 jobs/registry.go:1493 ⋮ [T1,n1] 1298 +  | github.com/cockroachdb/cockroach/pkg/util/tracing/grpcinterceptor.ServerInterceptor.func1
I230308 18:35:00.294935 89339 jobs/registry.go:1493 ⋮ [T1,n1] 1298 +  |         github.com/cockroachdb/cockroach/pkg/util/tracing/grpcinterceptor/grpc_interceptor.go:96
I230308 18:35:00.294935 89339 jobs/registry.go:1493 ⋮ [T1,n1] 1298 +  | google.golang.org/grpc.chainUnaryInterceptors.func1.1
I230308 18:35:00.294935 89339 jobs/registry.go:1493 ⋮ [T1,n1] 1298 +  |         google.golang.org/grpc/external/org_golang_google_grpc/server.go:1162
I230308 18:35:00.294935 89339 jobs/registry.go:1493 ⋮ [T1,n1] 1298 +  | github.com/cockroachdb/cockroach/pkg/rpc.NewServerEx.func3
I230308 18:35:00.294935 89339 jobs/registry.go:1493 ⋮ [T1,n1] 1298 +  |         github.com/cockroachdb/cockroach/pkg/rpc/pkg/rpc/context.go:266
I230308 18:35:00.294935 89339 jobs/registry.go:1493 ⋮ [T1,n1] 1298 +  | google.golang.org/grpc.chainUnaryInterceptors.func1.1
I230308 18:35:00.294935 89339 jobs/registry.go:1493 ⋮ [T1,n1] 1298 +  |         google.golang.org/grpc/external/org_golang_google_grpc/server.go:1165
I230308 18:35:00.294935 89339 jobs/registry.go:1493 ⋮ [T1,n1] 1298 +  | github.com/cockroachdb/cockroach/pkg/rpc.NewServerEx.func1.1
I230308 18:35:00.294935 89339 jobs/registry.go:1493 ⋮ [T1,n1] 1298 +  |         github.com/cockroachdb/cockroach/pkg/rpc/pkg/rpc/context.go:233
I230308 18:35:00.294935 89339 jobs/registry.go:1493 ⋮ [T1,n1] 1298 +  | github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunTaskWithErr
I230308 18:35:00.294935 89339 jobs/registry.go:1493 ⋮ [T1,n1] 1298 +  |         github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:322
I230308 18:35:00.294935 89339 jobs/registry.go:1493 ⋮ [T1,n1] 1298 +  | github.com/cockroachdb/cockroach/pkg/rpc.NewServerEx.func1
I230308 18:35:00.294935 89339 jobs/registry.go:1493 ⋮ [T1,n1] 1298 +  |         github.com/cockroachdb/cockroach/pkg/rpc/pkg/rpc/context.go:231
I230308 18:35:00.294935 89339 jobs/registry.go:1493 ⋮ [T1,n1] 1298 +  | google.golang.org/grpc.chainUnaryInterceptors.func1.1
I230308 18:35:00.294935 89339 jobs/registry.go:1493 ⋮ [T1,n1] 1298 +  |         google.golang.org/grpc/external/org_golang_google_grpc/server.go:1165
I230308 18:35:00.294935 89339 jobs/registry.go:1493 ⋮ [T1,n1] 1298 +  | google.golang.org/grpc.chainUnaryInterceptors.func1
I230308 18:35:00.294935 89339 jobs/registry.go:1493 ⋮ [T1,n1] 1298 +  |         google.golang.org/grpc/external/org_golang_google_grpc/server.go:1167
I230308 18:35:00.294935 89339 jobs/registry.go:1493 ⋮ [T1,n1] 1298 +  | github.com/cockroachdb/cockroach/pkg/kv/kvpb._Internal_Batch_Handler
I230308 18:35:00.294935 89339 jobs/registry.go:1493 ⋮ [T1,n1] 1298 +  |         github.com/cockroachdb/cockroach/pkg/kv/kvpb/bazel-out/k8-fastbuild/bin/pkg/kv/kvpb/kvpb_go_proto_/github.com/cockroachdb/cockroach/pkg/kv/kvpb/api.pb.go:9911
I230308 18:35:00.294935 89339 jobs/registry.go:1493 ⋮ [T1,n1] 1298 +  | google.golang.org/grpc.(*Server).processUnaryRPC
I230308 18:35:00.294935 89339 jobs/registry.go:1493 ⋮ [T1,n1] 1298 +  |         google.golang.org/grpc/external/org_golang_google_grpc/server.go:1340
I230308 18:35:00.294935 89339 jobs/registry.go:1493 ⋮ [T1,n1] 1298 +  | google.golang.org/grpc.(*Server).handleStream
I230308 18:35:00.294935 89339 jobs/registry.go:1493 ⋮ [T1,n1] 1298 +  |         google.golang.org/grpc/external/org_golang_google_grpc/server.go:1713
I230308 18:35:00.294935 89339 jobs/registry.go:1493 ⋮ [T1,n1] 1298 +  | google.golang.org/grpc.(*Server).serveStreams.func1.2
I230308 18:35:00.294935 89339 jobs/registry.go:1493 ⋮ [T1,n1] 1298 +  |         google.golang.org/grpc/external/org_golang_google_grpc/server.go:965
I230308 18:35:00.294935 89339 jobs/registry.go:1493 ⋮ [T1,n1] 1298 +  | runtime.goexit
I230308 18:35:00.294935 89339 jobs/registry.go:1493 ⋮ [T1,n1] 1298 +  |         GOROOT/src/runtime/asm_amd64.s:1594
I230308 18:35:00.294935 89339 jobs/registry.go:1493 ⋮ [T1,n1] 1298 +Wraps: (6) end key /Table/106/3/‹Arr/"foobar"/Arr›/‹True›/‹11243›/‹0›/‹NULL› must be greater than start /Table/106/3/‹Arr/"foobar"/Arr›/‹True›/‹11243›/‹0›/‹NULL›
I230308 18:35:00.294935 89339 jobs/registry.go:1493 ⋮ [T1,n1] 1298 +Error types: (1) *contexttags.withContext (2) *contexttags.withContext (3) *errbase.opaqueWrapper (4) *errutil.withPrefix (5) *errbase.opaqueWrapper (6) *errutil.leafError
I230308 18:35:00.317727 89339 sql/schemachanger/scrun/scrun.go:298 ⋮ [T1,n1,job=846167522586689537] 1299  rebuilding declarative schema change state from descriptors [106]
I230308 18:35:00.318079 89339 sql/schemachanger/scplan/plan.go:90 ⋮ [T1,n1,job=846167522586689537] 1300  building declarative schema changer plan in PostCommitPhase (rollback=false) for CREATE INDEX
I230308 18:35:00.322283 89339 sql/schemachanger/scrun/scrun.go:176 ⋮ [T1,n1,job=846167522586689537] 1301  executing declarative schema change PostCommitNonRevertiblePhase stage 1 of 2 with 9 MutationType ops (rollback=true) for CREATE INDEX

@ajwerner
Copy link
Contributor

ajwerner commented Mar 8, 2023

Cool this is great. I think we can take it from here.

@ajwerner
Copy link
Contributor

ajwerner commented Mar 8, 2023

Do you have the rest of the artifacts from the failing run?

@ajwerner
Copy link
Contributor

ajwerner commented Mar 8, 2023

I think what's going on here is that the merge phase of the backfill has some incorrect logic to determine whether it is done.

It'll be a bit icky to test this.

@ajwerner
Copy link
Contributor

ajwerner commented Mar 8, 2023

@msirek how many iterations did it take for this to flake?

@msirek
Copy link
Contributor

msirek commented Mar 8, 2023

Do you have the rest of the artifacts from the failing run?

It's too large for github. Here's the first one that failed:
https://upload.cockroachlabs.com/receive/?recipientCode=N0beftHyORDA00htbwJe7kHOIO02rpdHTWfcDf8AabY&src=null#keyCode=1APzk-TlcPEARqs5TwuI1mqXvZh_0BQSkbbJpb0Xim4

roachtest run schemachange/invertedindex --count 10 -p 30 roachtest run schemachange/invertedindex --cpu-quota 1000

@ajwerner
Copy link
Contributor

ajwerner commented Mar 8, 2023

#98262 is a speculative fix. Thanks for doing the repro exercise. Much appreciated.

@msirek msirek added this to Triage in SQL Foundations via automation Mar 8, 2023
@msirek
Copy link
Contributor

msirek commented Mar 9, 2023

I tried running the test against #98262 and it still fails.

@msirek msirek removed this from Triage in SQL Queries Mar 9, 2023
@msirek msirek removed their assignment Mar 9, 2023
craig bot pushed a commit that referenced this issue Mar 9, 2023
98262: sql/backfill: consult the ResumeSpan when scanning in index merge r=ajwerner a=ajwerner

The existing logic could construct an invalid batch request which would result in spurious errors.

Fixes #91977

Release note (bug fix): Fixed a bug which rarely could result in some CREATE INDEX statements to fail with an error `failed to verify keys for Scan`.

Co-authored-by: ajwerner <awerner32@gmail.com>
@craig craig bot closed this as completed in f044122 Mar 10, 2023
SQL Foundations automation moved this from Triage to Done Mar 10, 2023
@exalate-issue-sync exalate-issue-sync bot removed the T-sql-queries SQL Queries Team label Mar 10, 2023
@exalate-issue-sync exalate-issue-sync bot added T-sql-foundations SQL Foundations Team (formerly SQL Schema + SQL Sessions) and removed T-sql-schema-deprecated Use T-sql-foundations instead labels May 10, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
branch-master Failures on the master branch. C-test-failure Broken test (automatically or manually discovered). O-roachtest O-robot Originated from a bot. release-blocker Indicates a release-blocker. Use with branch-release-2x.x label to denote which branch is blocked. T-sql-foundations SQL Foundations Team (formerly SQL Schema + SQL Sessions)
Projects
Development

Successfully merging a pull request may close this issue.

4 participants