Atomic Copy: Fix panics when the copy phase starts in some clusters

[rohit-nayak-ps]

Description

Note that this doesn't fix the underlying issue that was reported but just fixes the panic, adds debug logging and returns an error so that vttablet doesn't crash.

It does fix a bug in a list initialization, used only for logging in atomicCopy mode, that was resulting in a confusing log message.

Unable to repro the underlying issue, so we will create a new issue with details when we get more info on it.

Backporting to all supported versions to prevent the panic.

Related Issue(s)

Fixes #17716

Checklist

• "Backport to:" labels have been added if this change should be back-ported to release branches
• If this change is to be back-ported to previous releases, a justification is included in the PR description
• Tests were added or are not required
• Did the new or modified tests pass consistently locally and on CI?
• Documentation was added or is not required

Deployment Notes

[vitess-bot]

Review Checklist

Hello reviewers! 👋 Please follow this checklist when reviewing this Pull Request.

General

• Ensure that the Pull Request has a descriptive title.
• Ensure there is a link to an issue (except for internal cleanup and flaky test fixes), new features should have an RFC that documents use cases and test cases.

Tests

• Bug fixes should have at least one unit or end-to-end test, enhancement and new features should have a sufficient number of tests.

Documentation

• Apply the release notes (needs details) label if users need to know about this change.
• New features should be documented.
• There should be some code comments as to why things are implemented the way they are.
• There should be a comment at the top of each new or modified test to explain what the test does.

New flags

• Is this flag really necessary?
• Flag names must be clear and intuitive, use dashes (-), and have a clear help text.

If a workflow is added or modified:

• Each item in Jobs should be named in order to mark it as required.
• If the workflow needs to be marked as required, the maintainer team must be notified.

Backward compatibility

• Protobuf changes should be wire-compatible.
• Changes to _vt tables and RPCs need to be backward compatible.
• RPC changes should be compatible with vitess-operator
• If a flag is removed, then it should also be removed from vitess-operator and arewefastyet, if used there.
• vtctl command output order should be stable and awk-able.

[codecov]

Codecov Report

Attention: Patch coverage is 10.00000% with 9 lines in your changes missing coverage. Please review.

Project coverage is 67.96%. Comparing base (10a6916) to head (c2cfa0e).
Report is 11 commits behind head on main.

Files with missing lines	Patch %	Lines
...ablet/tabletmanager/vreplication/vcopier_atomic.go	0.00%	6 Missing ⚠️
...blet/tabletmanager/vreplication/replicator_plan.go	25.00%	3 Missing ⚠️

Additional details and impacted files

@@            Coverage Diff             @@
##             main   #17717      +/-   ##
==========================================
+ Coverage   67.94%   67.96%   +0.01%     
==========================================
  Files        1586     1586              
  Lines      255173   255229      +56     
==========================================
+ Hits       173389   173476      +87     
+ Misses      81784    81753      -31     

☔ View full report in Codecov by Sentry.
📢 Have feedback on the report? Share it here.

[mattlord]

Nit, but table.column would be more clear

[wiebeytec]

I tested this code with the atomic move that failed for me with panic: runtime error: index out of range [0] with length 0. It still fails, but with more logs, and differently:

I0210 09:15:36.108535    1400 controller.go:151] creating tablet picker for source keyspace/shard vrm2024/0 with cell: vic-vrm-dev-docker-1 and tabletTypes: replica,primary
I0210 09:15:36.109277    1400 controller.go:344] Trying to find an eligible source tablet for vreplication stream id 1 for workflow: vrm_all
I0210 09:15:36.111604    1400 tablet_picker.go:370] Tablet picker found a healthy tablet for streaming: alias:{cell:"vic-vrm-dev-docker-1" uid:610} hostname:"172.18.0.6" port_map:{key:"grpc" value:15610} port_map:{key:"vt" value:18610} keyspace:"vrm2024" shard:"0" type:PRIMARY mysql_hostname:"172.18.0.6" mysql_port:17610 primary_term_start_time:{seconds:1739177264 nanoseconds:61928327} default_conn_collation:255
I0210 09:15:36.115249    1400 rpc_server.go:76] TabletManager.UpdateVReplicationWorkflow(workflow:"vrm_all" cells:"NULL" tablet_types:-1 state:Running)(on vic-vrm-dev-docker-1-0000000612 from ): (*tabletmanagerdata.UpdateVReplicationWorkflowResponse)(nil)
I0210 09:15:36.117936    1400 rpc_server.go:76] TabletManager.ReadVReplicationWorkflow(workflow:"vrm_all")(on vic-vrm-dev-docker-1-0000000612 from ): (*tabletmanagerdata.ReadVReplicationWorkflowResponse)(nil)
I0210 09:15:36.118380    1400 controller.go:359] Found eligible source tablet cell:"vic-vrm-dev-docker-1" uid:610 for vreplication stream id 1 for workflow vrm_all
I0210 09:15:36.138444    1400 rpc_server.go:76] TabletManager.ReadVReplicationWorkflows(include_workflows:"vrm_all")(on vic-vrm-dev-docker-1-0000000612 from ): (*tabletmanagerdata.ReadVReplicationWorkflowsResponse)(nil)
I0210 09:15:36.140611    1400 rpc_server.go:76] TabletManager.VReplicationExec(query:"select vrepl_id, table_name, lastpk from _vt.copy_state where vrepl_id in (1) and id in (select max(id) from _vt.copy_state where vrepl_id in (1) group by vrepl_id, table_name)")(on vic-vrm-dev-docker-1-0000000612 from ): (*tabletmanagerdata.VReplicationExecResponse)(nil)
I0210 09:15:36.223493    1400 vcopier_atomic.go:71] Starting copyAll for vrm_all
I0210 09:15:36.244911    1400 vcopier_atomic.go:109] VStreamTablesResponse: received table SshIpToVncRelay, #fields 4, #rows 0, gtid MySQL56/9224b988-e78b-11ef-a7cf-0242ac120006:1-1420, lastpk <nil>
I0210 09:15:36.245219    1400 vcopier_atomic.go:143] starting copy phase with table SshIpToVncRelay
I0210 09:15:36.245296    1400 vcopier_atomic.go:109] VStreamTablesResponse: received table SshIpToVncRelay, #fields 0, #rows 12, gtid MySQL56/9224b988-e78b-11ef-a7cf-0242ac120006:1-1420, lastpk lengths:12 values:"84.22.108.49"
I0210 09:15:36.245674    1400 vcopier_atomic.go:200] copying table SshIpToVncRelay with lastpk map[lastpk:type:VARBINARY value:"fields:{name:\"SshIp\" type:VARCHAR charset:224 flags:20483} rows:{}"]
W0210 09:15:36.246723    1400 replicator_plan.go:730] appendFromRow: wrong number of lengths for table SshIpToVncRelay: got 0 lengths for 4 fields
W0210 09:15:36.246766    1400 replicator_plan.go:733] appendFromRow: field:: 0:SshIpToVncRelay/SshIp
W0210 09:15:36.246771    1400 replicator_plan.go:733] appendFromRow: field:: 1:SshIpToVncRelay/VncHost
W0210 09:15:36.246775    1400 replicator_plan.go:733] appendFromRow: field:: 2:SshIpToVncRelay/ProxyRelayGroup
W0210 09:15:36.246779    1400 replicator_plan.go:733] appendFromRow: field:: 3:SshIpToVncRelay/PreLoadBalancer
I0210 09:15:36.251809    1400 vcopier_atomic.go:109] VStreamTablesResponse: received table accessLevelTranslations, #fields 4, #rows 0, gtid MySQL56/9224b988-e78b-11ef-a7cf-0242ac120006:1-1420, lastpk <nil>
I0210 09:15:36.252064    1400 vcopier_atomic.go:138] copy of table SshIpToVncRelay is done at lastpk map[lastpk:type:VARBINARY value:"fields:{name:\"SshIp\" type:VARCHAR charset:224 flags:20483} rows:{}"]
I0210 09:15:36.252098    1400 vcopier_atomic.go:306] Deleting copy state for table SshIpToVncRelay
I0210 09:15:36.258120    1400 vcopier_atomic.go:109] VStreamTablesResponse: received table accessLevelTranslations, #fields 0, #rows 12, gtid MySQL56/9224b988-e78b-11ef-a7cf-0242ac120006:1-1420, lastpk lengths:2 values:"14"
I0210 09:15:36.258326    1400 vcopier_atomic.go:200] copying table accessLevelTranslations with lastpk map[lastpk:type:VARBINARY value:"fields:{name:\"id\" type:INT8 charset:63 flags:49667} rows:{}"]
I0210 09:15:36.259161    1400 vcopier_atomic.go:280] VStreamTables failed: Code: INTERNAL
wrong number of lengths for table SshIpToVncRelay: got 0 lengths for 4 fields

failed inserting rows
task error
I0210 09:15:36.259184    1400 vcopier_atomic.go:281] Returning from copyAll for vrm_all
I0210 09:15:36.259189    1400 vreplicator.go:303] Error atomically copying all tables: Code: INTERNAL
wrong number of lengths for table SshIpToVncRelay: got 0 lengths for 4 fields

failed inserting rows
task error
W0210 09:15:36.259269    1400 replicator_plan.go:730] appendFromRow: wrong number of lengths for table accessLevelTranslations: got 0 lengths for 4 fields
W0210 09:15:36.259294    1400 replicator_plan.go:733] appendFromRow: field:: 0:accessLevelTranslations/id
W0210 09:15:36.259299    1400 replicator_plan.go:733] appendFromRow: field:: 1:accessLevelTranslations/userAccessLevel
W0210 09:15:36.259302    1400 replicator_plan.go:733] appendFromRow: field:: 2:accessLevelTranslations/siteAccessLevel
W0210 09:15:36.259306    1400 replicator_plan.go:733] appendFromRow: field:: 3:accessLevelTranslations/accessLevel
panic: send on closed channel

goroutine 2080 [running]:
vitess.io/vitess/go/vt/vttablet/tabletmanager/vreplication.(*vcopier).copyAll.func1.(*vcopierCopyTaskResultHooks).sendTo.4({0x3634028?, 0xc001755ab0?}, 0xc001755ab0?)
	vitess.io/vitess/go/vt/vttablet/tabletmanager/vreplication/vcopier.go:922 +0x76
vitess.io/vitess/go/vt/vttablet/tabletmanager/vreplication.(*vcopierCopyTaskResultHooks).notify(...)
	vitess.io/vitess/go/vt/vttablet/tabletmanager/vreplication/vcopier.go:908
vitess.io/vitess/go/vt/vttablet/tabletmanager/vreplication.(*vcopierCopyWorker).execute(0xc00176dc20, {0x3634028, 0xc001755ab0}, 0xc00150d450)
	vitess.io/vitess/go/vt/vttablet/tabletmanager/vreplication/vcopier.go:1120 +0x3a2
vitess.io/vitess/go/vt/vttablet/tabletmanager/vreplication.(*vcopierCopyWorkQueue).enqueue.func1(0xc0011ecf80?)
	vitess.io/vitess/go/vt/vttablet/tabletmanager/vreplication/vcopier.go:771 +0x45
created by vitess.io/vitess/go/vt/vttablet/tabletmanager/vreplication.(*vcopierCopyWorkQueue).enqueue in goroutine 2107
	vitess.io/vitess/go/vt/vttablet/tabletmanager/vreplication/vcopier.go:779 +0x132

[rohit-nayak-ps]

We isolated the issue to being related to concurrent inserts (the --vreplication-parallel-insert-workers flag). For now, while we work on the fix, we are overriding that flag and only doing the copy single threaded.