gh-ost icon indicating copy to clipboard operation
gh-ost copied to clipboard

The table cut failed and caused the slave library to block

Open boomballa opened this issue 3 years ago • 2 comments

Excuse me, I would like to ask a question. When using gh-ost to execute ddl yesterday, an error occurred in the main library, which caused the table to fail to switch successfully. But there are two errors, and I am not sure which error caused the table to fail to switch successfully.

2022/12/19 16:33:11 binlogsyncer.go:79: [0;37m[info] create BinlogSyncer with config {99999 mysql localhost 3306 root false false }[0m 2022/12/19 16:33:11 binlogsyncer.go:246: [0;37m[info] begin to sync binlog from position (mysql-bin.000196, 1004574218)[0m 2022/12/19 16:33:11 binlogsyncer.go:139: [0;37m[info] register slave for master server localhost:3306[0m 2022/12/19 16:33:11 binlogsyncer.go:573: [0;37m[info] rotate to (mysql-bin.000196, 1004574218)[0m Migrating customer3.customer_company; Ghost table is customer3._customer_company_gho Migrating rdsdbn3-sirius-customer-online:3306; inspecting rdsdbn3-sirius-customer-online:3306; executing on rdsdbn3-sirius-customer-online Migration started at Mon Dec 19 16:33:11 +0800 2022 chunk-size: 1000; max-lag-millis: 1500ms; dml-batch-size: 10; max-load: Threads_running=100; critical-load: Threads_running=500; nice-ratio: 0.000000 throttle-additional-flag-file: /tmp/gh-ost.throttle Serving on unix socket: /tmp/gh-ost.customer3.customer_company.sock Serving on TCP port: 13316 Copy: 0/821093 0.0%; Applied: 0; Backlog: 0/1000; Time: 0s(total), 0s(copy); streamer: mysql-bin.000196:1004589539; State: migrating; ETA: N/A Copy: 0/821093 0.0%; Applied: 0; Backlog: 0/1000; Time: 1s(total), 1s(copy); streamer: mysql-bin.000196:1004965536; State: migrating; ETA: N/A Copy: 9000/821093 1.1%; Applied: 0; Backlog: 0/1000; Time: 2s(total), 2s(copy); streamer: mysql-bin.000196:1007404907; State: migrating; ETA: 3m0s Copy: 18000/821093 2.2%; Applied: 0; Backlog: 0/1000; Time: 3s(total), 3s(copy); streamer: mysql-bin.000196:1010115047; State: migrating; ETA: 2m13s ... ... ... 2022/12/19 16:35:14 binlogstreamer.go:47: [0;31m[error] close sync with err: data len 310 < expected 2179[0m Copy: 769329/769329 100.0%; Applied: 0; Backlog: 0/1000; Time: 2m5s(total), 2m0s(copy); streamer: mysql-bin.000197:21632791; State: migrating; ETA: due 2022-12-19 16:35:17 ERROR Timeout while waiting for events up to lock 2022-12-19 16:35:17 ERROR 2022-12-19 16:35:17 ERROR Timeout while waiting for events up to lock 2022/12/19 16:35:19 binlogsyncer.go:79: [0;37m[info] create BinlogSyncer with config {99999 mysql localhost 3306 rdsadmin false false }[0m 2022/12/19 16:35:19 binlogsyncer.go:246: [0;37m[info] begin to sync binlog from position (mysql-bin.000197, 4)[0m 2022/12/19 16:35:19 binlogsyncer.go:139: [0;37m[info] register slave for master server localhost:3306[0m 2022/12/19 16:35:19 binlogsyncer.go:573: [0;37m[info] rotate to (mysql-bin.000197, 4)[0m 2022/12/19 16:35:21 binlogstreamer.go:47: [0;31m[error] close sync with err: data len 310 < expected 2179[0m Copy: 769329/769329 100.0%; Applied: 0; Backlog: 0/1000; Time: 2m10s(total), 2m0s(copy); streamer: mysql-bin.000197:21632791; State: migrating; ETA: due 2022-12-19 16:35:21 ERROR Timeout while waiting for events up to lock 2022-12-19 16:35:21 ERROR 2022-12-19 16:35:21 ERROR Timeout while waiting for events up to lock 2022/12/19 16:35:26 binlogsyncer.go:79: [0;37m[info] create BinlogSyncer with config {99999 mysql localhost 3306 rdsadmin false false }[0m 2022/12/19 16:35:26 binlogsyncer.go:246: [0;37m[info] begin to sync binlog from position (mysql-bin.000197, 4)[0m 2022/12/19 16:35:26 binlogsyncer.go:139: [0;37m[info] register slave for master server localhost:3306[0m 2022/12/19 16:35:26 binlogsyncer.go:573: [0;37m[info] rotate to (mysql-bin.000197, 4)[0m Copy: 769329/769329 100.0%; Applied: 0; Backlog: 0/1000; Time: 2m15s(total), 2m0s(copy); streamer: mysql-bin.000197:3096692; State: migrating; ETA: due 2022-12-19 16:35:27 ERROR Timeout while waiting for events up to lock 2022-12-19 16:35:27 ERROR 2022-12-19 16:35:27 ERROR Timeout while waiting for events up to lock 2022/12/19 16:35:28 binlogstreamer.go:47: [0;31m[error] close sync with err: data len 310 < expected 2179[0m Copy: 769329/769329 100.0%; Applied: 0; Backlog: 0/1000; Time: 2m20s(total), 2m0s(copy); streamer: mysql-bin.000197:21632791; State: migrating; ETA: due 2022-12-19 16:35:31 ERROR Timeout while waiting for events up to lock 2022-12-19 16:35:31 ERROR 2022-12-19 16:35:31 ERROR Timeout while waiting for events up to lock 2022/12/19 16:35:33 binlogsyncer.go:79: [0;37m[info] create BinlogSyncer with config {99999 mysql localhost 3306 rdsadmin false false }[0m 2022/12/19 16:35:33 binlogsyncer.go:246: [0;37m[info] begin to sync binlog from position (mysql-bin.000197, 4)[0m 2022/12/19 16:35:33 binlogsyncer.go:139: [0;37m[info] register slave for master server localhost:3306[0m 2022/12/19 16:35:33 binlogsyncer.go:573: [0;37m[info] rotate to (mysql-bin.000197, 4)[0m 2022/12/19 16:35:35 binlogstreamer.go:47: [0;31m[error] close sync with err: data len 310 < expected 2179[0m Copy: 769329/769329 100.0%; Applied: 0; Backlog: 0/1000; Time: 2m25s(total), 2m0s(copy); streamer: mysql-bin.000197:21536965; State: migrating; ETA: due 2022-12-19 16:35:37 ERROR Timeout while waiting for events up to lock 2022-12-19 16:35:37 ERROR 2022-12-19 16:35:37 ERROR Timeout while waiting for events up to lock 2022/12/19 16:35:40 binlogsyncer.go:79: [0;37m[info] create BinlogSyncer with config {99999 mysql localhost 3306 rdsadmin false false }[0m 2022/12/19 16:35:40 binlogsyncer.go:246: [0;37m[info] begin to sync binlog from position (mysql-bin.000197, 4)[0m 2022/12/19 16:35:40 binlogsyncer.go:139: [0;37m[info] register slave for master server localhost:3306[0m 2022/12/19 16:35:40 binlogsyncer.go:573: [0;37m[info] rotate to (mysql-bin.000197, 4)[0m Copy: 769329/769329 100.0%; Applied: 0; Backlog: 0/1000; Time: 2m30s(total), 2m0s(copy); streamer: mysql-bin.000197:10420122; State: migrating; ETA: due 2022/12/19 16:35:43 binlogstreamer.go:47: [0;31m[error] close sync with err: data len 310 < expected 2179[0m 2022-12-19 16:35:43 ERROR Timeout while waiting for events up to lock 2022-12-19 16:35:43 ERROR 2022-12-19 16:35:43 ERROR Timeout while waiting for events up to lock Copy: 769329/769329 100.0%; Applied: 0; Backlog: 0/1000; Time: 2m35s(total), 2m0s(copy); streamer: mysql-bin.000197:21632791; State: migrating; ETA: due 2022/12/19 16:35:48 binlogsyncer.go:79: [0;37m[info] create BinlogSyncer with config {99999 mysql localhost 3306 rdsadmin false false }[0m 2022/12/19 16:35:48 binlogsyncer.go:246: [0;37m[info] begin to sync binlog from position (mysql-bin.000197, 4)[0m 2022/12/19 16:35:48 binlogsyncer.go:139: [0;37m[info] register slave for master server localhost:3306[0m 2022/12/19 16:35:48 binlogsyncer.go:573: [0;37m[info] rotate to (mysql-bin.000197, 4)[0m 2022-12-19 16:35:50 ERROR Timeout while waiting for events up to lock 2022-12-19 16:35:50 ERROR 2022-12-19 16:35:50 ERROR Timeout while waiting for events up to lock 2022/12/19 16:35:50 binlogstreamer.go:47: [0;31m[error] close sync with err: data len 310 < expected 2179[0m Copy: 769329/769329 100.0%; Applied: 0; Backlog: 0/1000; Time: 2m40s(total), 2m0s(copy); streamer: mysql-bin.000197:21632791; State: migrating; ETA: due 2022/12/19 16:35:55 binlogsyncer.go:79: [0;37m[info] create BinlogSyncer with config {99999 mysql localhost 3306 rdsadmin false false }[0m 2022/12/19 16:35:55 binlogsyncer.go:246: [0;37m[info] begin to sync binlog from position (mysql-bin.000197, 4)[0m 2022/12/19 16:35:55 binlogsyncer.go:139: [0;37m[info] register slave for master server localhost:3306[0m 2022/12/19 16:35:55 binlogsyncer.go:573: [0;37m[info] rotate to (mysql-bin.000197, 4)[0m 2022-12-19 16:35:56 ERROR Timeout while waiting for events up to lock 2022-12-19 16:35:56 ERROR 2022-12-19 16:35:56 ERROR Timeout while waiting for events up to lock Copy: 769329/769329 100.0%; Applied: 0; Backlog: 0/1000; Time: 2m45s(total), 2m0s(copy); streamer: mysql-bin.000197:9353085; State: migrating; ETA: due 2022/12/19 16:35:58 binlogstreamer.go:47: [0;31m[error] close sync with err: data len 310 < expected 2179[0m Copy: 769329/769329 100.0%; Applied: 0; Backlog: 0/1000; Time: 2m50s(total), 2m0s(copy); streamer: mysql-bin.000197:21632791; State: migrating; ETA: due 2022-12-19 16:36:02 ERROR Timeout while waiting for events up to lock 2022-12-19 16:36:02 ERROR 2022-12-19 16:36:02 ERROR Timeout while waiting for events up to lock 2022/12/19 16:36:03 binlogsyncer.go:79: [0;37m[info] create BinlogSyncer with config {99999 mysql localhost 3306 rdsadmin false false }[0m 2022/12/19 16:36:03 binlogsyncer.go:246: [0;37m[info] begin to sync binlog from position (mysql-bin.000197, 4)[0m 2022/12/19 16:36:03 binlogsyncer.go:139: [0;37m[info] register slave for master server localhost:3306[0m 2022/12/19 16:36:03 binlogsyncer.go:573: [0;37m[info] rotate to (mysql-bin.000197, 4)[0m 2022/12/19 16:36:05 binlogstreamer.go:47: [0;31m[error] close sync with err: data len 310 < expected 2179[0m Copy: 769329/769329 100.0%; Applied: 0; Backlog: 0/1000; Time: 2m55s(total), 2m0s(copy); streamer: mysql-bin.000197:21632791; State: migrating; ETA: due 2022-12-19 16:36:08 ERROR Timeout while waiting for events up to lock 2022-12-19 16:36:08 ERROR 2022-12-19 16:36:08 ERROR Timeout while waiting for events up to lock 2022/12/19 16:36:10 binlogsyncer.go:79: [0;37m[info] create BinlogSyncer with config {99999 mysql localhost 3306 rdsadmin false false }[0m 2022/12/19 16:36:10 binlogsyncer.go:246: [0;37m[info] begin to sync binlog from position (mysql-bin.000197, 4)[0m 2022/12/19 16:36:10 binlogsyncer.go:139: [0;37m[info] register slave for master server localhost:3306[0m 2022/12/19 16:36:10 binlogsyncer.go:573: [0;37m[info] rotate to (mysql-bin.000197, 4)[0m Copy: 769329/769329 100.0%; Applied: 0; Backlog: 0/1000; Time: 3m0s(total), 2m0s(copy); streamer: mysql-bin.000197:17516759; State: migrating; ETA: due 2022/12/19 16:36:12 binlogstreamer.go:47: [0;31m[error] close sync with err: data len 310 < expected 2179[0m 2022-12-19 16:36:12 ERROR Timeout while waiting for events up to lock 2022-12-19 16:36:12 ERROR 2022-12-19 16:36:12 ERROR Timeout while waiting for events up to lock 2022-12-19 16:36:16 ERROR Timeout while waiting for events up to lock 2022-12-19 16:36:16 ERROR 2022-12-19 16:36:16 ERROR Timeout while waiting for events up to lock Copy: 769329/769329 100.0%; Applied: 0; Backlog: 0/1000; Time: 3m5s(total), 2m0s(copy); streamer: mysql-bin.000197:21608867; State: migrating; ETA: due 2022/12/19 16:36:17 binlogsyncer.go:79: [0;37m[info] create BinlogSyncer with config {99999 mysql localhost 3306 rdsadmin false false }[0m 2022/12/19 16:36:17 binlogsyncer.go:246: [0;37m[info] begin to sync binlog from position (mysql-bin.000197, 4)[0m 2022/12/19 16:36:17 binlogsyncer.go:139: [0;37m[info] register slave for master server localhost:3306[0m 2022/12/19 16:36:17 binlogsyncer.go:573: [0;37m[info] rotate to (mysql-bin.000197, 4)[0m 2022/12/19 16:36:18 binlogstreamer.go:47: [0;31m[error] close sync with err: data len 310 < expected 2179[0m Copy: 769329/769329 100.0%; Applied: 0; Backlog: 0/1000; Time: 3m10s(total), 2m0s(copy); streamer: mysql-bin.000197:21584851; State: migrating; ETA: due 2022-12-19 16:36:22 ERROR Timeout while waiting for events up to lock 2022-12-19 16:36:22 ERROR 2022-12-19 16:36:22 ERROR Timeout while waiting for events up to lock 2022/12/19 16:36:23 binlogsyncer.go:79: [0;37m[info] create BinlogSyncer with config {99999 mysql localhost 3306 rdsadmin false false }[0m 2022/12/19 16:36:23 binlogsyncer.go:246: [0;37m[info] begin to sync binlog from position (mysql-bin.000197, 4)[0m 2022/12/19 16:36:23 binlogsyncer.go:139: [0;37m[info] register slave for master server localhost:3306[0m 2022/12/19 16:36:23 binlogsyncer.go:573: [0;37m[info] rotate to (mysql-bin.000197, 4)[0m 2022/12/19 16:36:25 binlogstreamer.go:47: [0;31m[error] close sync with err: data len 310 < expected 2179[0m 2022-12-19 16:36:26 ERROR Timeout while waiting for events up to lock 2022-12-19 16:36:26 ERROR 2022-12-19 16:36:26 ERROR Timeout while waiting for events up to lock Copy: 769329/769329 100.0%; Applied: 0; Backlog: 0/1000; Time: 3m15s(total), 2m0s(copy); streamer: mysql-bin.000197:21632791; State: migrating; ETA: due 2022/12/19 16:36:30 binlogsyncer.go:79: [0;37m[info] create BinlogSyncer with config {99999 mysql localhost 3306 rdsadmin false false }[0m 2022/12/19 16:36:30 binlogsyncer.go:246: [0;37m[info] begin to sync binlog from position (mysql-bin.000197, 4)[0m 2022/12/19 16:36:30 binlogsyncer.go:139: [0;37m[info] register slave for master server localhost:3306[0m 2022/12/19 16:36:30 binlogsyncer.go:573: [0;37m[info] rotate to (mysql-bin.000197, 4)[0m Copy: 769329/769329 100.0%; Applied: 0; Backlog: 0/1000; Time: 3m20s(total), 2m0s(copy); streamer: mysql-bin.000197:12833146; State: migrating; ETA: due 2022/12/19 16:36:32 binlogstreamer.go:47: [0;31m[error] close sync with err: data len 310 < expected 2179[0m 2022-12-19 16:36:32 ERROR Timeout while waiting for events up to lock 2022-12-19 16:36:32 ERROR 2022-12-19 16:36:32 ERROR Timeout while waiting for events up to lock Copy: 769329/769329 100.0%; Applied: 0; Backlog: 0/1000; Time: 3m25s(total), 2m0s(copy); streamer: mysql-bin.000197:21632791; State: migrating; ETA: due 2022/12/19 16:36:37 binlogsyncer.go:79: [0;37m[info] create BinlogSyncer with config {99999 mysql localhost 3306 rdsadmin false false }[0m 2022/12/19 16:36:37 binlogsyncer.go:246: [0;37m[info] begin to sync binlog from position (mysql-bin.000197, 4)[0m 2022/12/19 16:36:37 binlogsyncer.go:139: [0;37m[info] register slave for master server localhost:3306[0m 2022/12/19 16:36:37 binlogsyncer.go:573: [0;37m[info] rotate to (mysql-bin.000197, 4)[0m 2022-12-19 16:36:38 ERROR Timeout while waiting for events up to lock 2022-12-19 16:36:38 ERROR 2022-12-19 16:36:38 ERROR Timeout while waiting for events up to lock 2022/12/19 16:36:38 binlogstreamer.go:47: [0;31m[error] close sync with err: data len 310 < expected 2179[0m Copy: 769329/769329 100.0%; Applied: 0; Backlog: 0/1000; Time: 3m30s(total), 2m0s(copy); streamer: mysql-bin.000197:21569140; State: migrating; ETA: due 2022/12/19 16:36:43 binlogsyncer.go:79: [0;37m[info] create BinlogSyncer with config {99999 mysql localhost 3306 rdsadmin false false }[0m 2022/12/19 16:36:43 binlogsyncer.go:246: [0;37m[info] begin to sync binlog from position (mysql-bin.000197, 4)[0m 2022/12/19 16:36:43 binlogsyncer.go:139: [0;37m[info] register slave for master server localhost:3306[0m 2022/12/19 16:36:43 binlogsyncer.go:573: [0;37m[info] rotate to (mysql-bin.000197, 4)[0m 2022-12-19 16:36:44 ERROR Timeout while waiting for events up to lock 2022-12-19 16:36:44 ERROR 2022-12-19 16:36:44 ERROR Timeout while waiting for events up to lock 2022/12/19 16:36:45 binlogstreamer.go:47: [0;31m[error] close sync with err: data len 310 < expected 2179[0m Copy: 769329/769329 100.0%; Applied: 0; Backlog: 0/1000; Time: 3m35s(total), 2m0s(copy); streamer: mysql-bin.000197:21632791; State: migrating; ETA: due 2022/12/19 16:36:50 binlogsyncer.go:79: [0;37m[info] create BinlogSyncer with config {99999 mysql localhost 3306 rdsadmin false false }[0m 2022/12/19 16:36:50 binlogsyncer.go:246: [0;37m[info] begin to sync binlog from position (mysql-bin.000197, 4)[0m 2022/12/19 16:36:50 binlogsyncer.go:139: [0;37m[info] register slave for master server localhost:3306[0m 2022/12/19 16:36:50 binlogsyncer.go:573: [0;37m[info] rotate to (mysql-bin.000197, 4)[0m 2022-12-19 16:36:51 ERROR Timeout while waiting for events up to lock 2022-12-19 16:36:51 ERROR 2022-12-19 16:36:51 ERROR Timeout while waiting for events up to lock Copy: 769329/769329 100.0%; Applied: 0; Backlog: 0/1000; Time: 3m40s(total), 2m0s(copy); streamer: mysql-bin.000197:18875201; State: migrating; ETA: due 2022/12/19 16:36:51 binlogstreamer.go:47: [0;31m[error] close sync with err: data len 310 < expected 2179[0m Copy: 769329/769329 100.0%; Applied: 0; Backlog: 0/1000; Time: 3m45s(total), 2m0s(copy); streamer: mysql-bin.000197:21632791; State: migrating; ETA: due 2022/12/19 16:36:56 binlogsyncer.go:79: [0;37m[info] create BinlogSyncer with config {99999 mysql localhost 3306 rdsadmin false false }[0m 2022/12/19 16:36:56 binlogsyncer.go:246: [0;37m[info] begin to sync binlog from position (mysql-bin.000197, 4)[0m 2022/12/19 16:36:56 binlogsyncer.go:139: [0;37m[info] register slave for master server localhost:3306[0m 2022/12/19 16:36:56 binlogsyncer.go:573: [0;37m[info] rotate to (mysql-bin.000197, 4)[0m 2022-12-19 16:36:57 ERROR Timeout while waiting for events up to lock 2022-12-19 16:36:57 ERROR 2022-12-19 16:36:57 ERROR Timeout while waiting for events up to lock 2022/12/19 16:36:58 binlogstreamer.go:47: [0;31m[error] close sync with err: data len 310 < expected 2179[0m Copy: 769329/769329 100.0%; Applied: 0; Backlog: 0/1000; Time: 3m50s(total), 2m0s(copy); streamer: mysql-bin.000197:21632791; State: migrating; ETA: due 2022-12-19 16:37:03 ERROR Timeout while waiting for events up to lock 2022-12-19 16:37:03 ERROR 2022-12-19 16:37:03 ERROR Timeout while waiting for events up to lock 2022/12/19 16:37:03 binlogsyncer.go:79: [0;37m[info] create BinlogSyncer with config {99999 mysql localhost 3306 rdsadmin false false }[0m 2022/12/19 16:37:03 binlogsyncer.go:246: [0;37m[info] begin to sync binlog from position (mysql-bin.000197, 4)[0m 2022/12/19 16:37:03 binlogsyncer.go:139: [0;37m[info] register slave for master server localhost:3306[0m 2022/12/19 16:37:03 binlogsyncer.go:573: [0;37m[info] rotate to (mysql-bin.000197, 4)[0m 2022/12/19 16:37:05 binlogstreamer.go:47: [0;31m[error] close sync with err: data len 310 < expected 2179[0m Copy: 769329/769329 100.0%; Applied: 0; Backlog: 0/1000; Time: 3m55s(total), 2m0s(copy); streamer: mysql-bin.000197:21632791; State: migrating; ETA: due 2022-12-19 16:37:09 ERROR Timeout while waiting for events up to lock 2022-12-19 16:37:09 ERROR 2022-12-19 16:37:09 ERROR Timeout while waiting for events up to lock 2022/12/19 16:37:10 binlogsyncer.go:79: [0;37m[info] create BinlogSyncer with config {99999 mysql localhost 3306 rdsadmin false false }[0m 2022/12/19 16:37:10 binlogsyncer.go:246: [0;37m[info] begin to sync binlog from position (mysql-bin.000197, 4)[0m 2022/12/19 16:37:10 binlogsyncer.go:139: [0;37m[info] register slave for master server localhost:3306[0m 2022/12/19 16:37:10 binlogsyncer.go:573: [0;37m[info] rotate to (mysql-bin.000197, 4)[0m Copy: 769329/769329 100.0%; Applied: 0; Backlog: 0/1000; Time: 4m0s(total), 2m0s(copy); streamer: mysql-bin.000197:15550736; State: migrating; ETA: due 2022/12/19 16:37:12 binlogstreamer.go:47: [0;31m[error] close sync with err: data len 310 < expected 2179[0m 2022-12-19 16:37:16 ERROR Timeout while waiting for events up to lock 2022-12-19 16:37:16 ERROR 2022-12-19 16:37:16 ERROR Timeout while waiting for events up to lock Copy: 769329/769329 100.0%; Applied: 0; Backlog: 0/1000; Time: 4m5s(total), 2m0s(copy); streamer: mysql-bin.000197:21632791; State: migrating; ETA: due 2022/12/19 16:37:17 binlogsyncer.go:79: [0;37m[info] create BinlogSyncer with config {99999 mysql localhost 3306 rdsadmin false false }[0m 2022/12/19 16:37:17 binlogsyncer.go:246: [0;37m[info] begin to sync binlog from position (mysql-bin.000197, 4)[0m 2022/12/19 16:37:17 binlogsyncer.go:139: [0;37m[info] register slave for master server localhost:3306[0m 2022/12/19 16:37:17 binlogsyncer.go:573: [0;37m[info] rotate to (mysql-bin.000197, 4)[0m 2022/12/19 16:37:18 binlogstreamer.go:47: [0;31m[error] close sync with err: data len 310 < expected 2179[0m Copy: 769329/769329 100.0%; Applied: 0; Backlog: 0/1000; Time: 4m10s(total), 2m0s(copy); streamer: mysql-bin.000197:21632791; State: migrating; ETA: due 2022-12-19 16:37:22 ERROR Timeout while waiting for events up to lock 2022-12-19 16:37:22 ERROR 2022-12-19 16:37:22 ERROR Timeout while waiting for events up to lock 2022/12/19 16:37:23 binlogsyncer.go:79: [0;37m[info] create BinlogSyncer with config {99999 mysql localhost 3306 rdsadmin false false }[0m 2022/12/19 16:37:23 binlogsyncer.go:246: [0;37m[info] begin to sync binlog from position (mysql-bin.000197, 4)[0m 2022/12/19 16:37:23 binlogsyncer.go:139: [0;37m[info] register slave for master server localhost:3306[0m 2022/12/19 16:37:23 binlogsyncer.go:573: [0;37m[info] rotate to (mysql-bin.000197, 4)[0m 2022/12/19 16:37:25 binlogstreamer.go:47: [0;31m[error] close sync with err: data len 310 < expected 2179[0m Copy: 769329/769329 100.0%; Applied: 0; Backlog: 0/1000; Time: 4m15s(total), 2m0s(copy); streamer: mysql-bin.000197:21632791; State: migrating; ETA: due 2022-12-19 16:37:28 ERROR Timeout while waiting for events up to lock 2022-12-19 16:37:28 ERROR 2022-12-19 16:37:28 ERROR Timeout while waiting for events up to lock 2022/12/19 16:37:30 binlogsyncer.go:79: [0;37m[info] create BinlogSyncer with config {99999 mysql localhost 3306 rdsadmin false false }[0m 2022/12/19 16:37:30 binlogsyncer.go:246: [0;37m[info] begin to sync binlog from position (mysql-bin.000197, 4)[0m 2022/12/19 16:37:30 binlogsyncer.go:139: [0;37m[info] register slave for master server localhost:3306[0m 2022/12/19 16:37:30 binlogsyncer.go:573: [0;37m[info] rotate to (mysql-bin.000197, 4)[0m Copy: 769329/769329 100.0%; Applied: 0; Backlog: 0/1000; Time: 4m20s(total), 2m0s(copy); streamer: mysql-bin.000197:8319580; State: migrating; ETA: due 2022/12/19 16:37:32 binlogstreamer.go:47: [0;31m[error] close sync with err: data len 310 < expected 2179[0m 2022-12-19 16:37:34 ERROR Timeout while waiting for events up to lock 2022-12-19 16:37:34 ERROR 2022-12-19 16:37:34 ERROR Timeout while waiting for events up to lock Copy: 769329/769329 100.0%; Applied: 0; Backlog: 0/1000; Time: 4m25s(total), 2m0s(copy); streamer: mysql-bin.000197:21632791; State: migrating; ETA: due 2022/12/19 16:37:37 binlogsyncer.go:79: [0;37m[info] create BinlogSyncer with config {99999 mysql localhost 3306 rdsadmin false false }[0m 2022/12/19 16:37:37 binlogsyncer.go:246: [0;37m[info] begin to sync binlog from position (mysql-bin.000197, 4)[0m 2022/12/19 16:37:37 binlogsyncer.go:139: [0;37m[info] register slave for master server localhost:3306[0m 2022/12/19 16:37:37 binlogsyncer.go:573: [0;37m[info] rotate to (mysql-bin.000197, 4)[0m 2022/12/19 16:37:39 binlogstreamer.go:47: [0;31m[error] close sync with err: data len 310 < expected 2179[0m 2022-12-19 16:37:40 ERROR Timeout while waiting for events up to lock 2022-12-19 16:37:40 ERROR 2022-12-19 16:37:40 ERROR Timeout while waiting for events up to lock Copy: 769329/769329 100.0%; Applied: 0; Backlog: 0/1000; Time: 4m30s(total), 2m0s(copy); streamer: mysql-bin.000197:21624860; State: migrating; ETA: due 2022/12/19 16:37:44 binlogsyncer.go:79: [0;37m[info] create BinlogSyncer with config {99999 mysql localhost 3306 rdsadmin false false }[0m 2022/12/19 16:37:44 binlogsyncer.go:246: [0;37m[info] begin to sync binlog from position (mysql-bin.000197, 4)[0m 2022/12/19 16:37:44 binlogsyncer.go:139: [0;37m[info] register slave for master server localhost:3306[0m 2022/12/19 16:37:44 binlogsyncer.go:573: [0;37m[info] rotate to (mysql-bin.000197, 4)[0m 2022/12/19 16:37:46 binlogstreamer.go:47: [0;31m[error] close sync with err: data len 310 < expected 2179[0m Copy: 769329/769329 100.0%; Applied: 0; Backlog: 0/1000; Time: 4m35s(total), 2m0s(copy); streamer: mysql-bin.000197:21584851; State: migrating; ETA: due 2022-12-19 16:37:47 ERROR Timeout while waiting for events up to lock 2022-12-19 16:37:47 ERROR 2022-12-19 16:37:47 ERROR Timeout while waiting for events up to lock 2022/12/19 16:37:51 binlogsyncer.go:79: [0;37m[info] create BinlogSyncer with config {99999 mysql localhost 3306 rdsadmin false false }[0m 2022/12/19 16:37:51 binlogsyncer.go:246: [0;37m[info] begin to sync binlog from position (mysql-bin.000197, 4)[0m 2022/12/19 16:37:51 binlogsyncer.go:139: [0;37m[info] register slave for master server localhost:3306[0m 2022/12/19 16:37:51 binlogsyncer.go:573: [0;37m[info] rotate to (mysql-bin.000197, 4)[0m Copy: 769329/769329 100.0%; Applied: 0; Backlog: 0/1000; Time: 4m40s(total), 2m0s(copy); streamer: mysql-bin.000197:3346793; State: migrating; ETA: due 2022-12-19 16:37:53 ERROR Timeout while waiting for events up to lock 2022-12-19 16:37:53 ERROR 2022-12-19 16:37:53 ERROR Timeout while waiting for events up to lock 2022/12/19 16:37:53 binlogstreamer.go:47: [0;31m[error] close sync with err: data len 310 < expected 2179[0m Copy: 769329/769329 100.0%; Applied: 0; Backlog: 0/1000; Time: 4m45s(total), 2m0s(copy); streamer: mysql-bin.000197:21632791; State: migrating; ETA: due 2022/12/19 16:37:58 binlogsyncer.go:79: [0;37m[info] create BinlogSyncer with config {99999 mysql localhost 3306 rdsadmin false false }[0m 2022/12/19 16:37:58 binlogsyncer.go:246: [0;37m[info] begin to sync binlog from position (mysql-bin.000197, 4)[0m 2022/12/19 16:37:58 binlogsyncer.go:139: [0;37m[info] register slave for master server localhost:3306[0m 2022/12/19 16:37:58 binlogsyncer.go:573: [0;37m[info] rotate to (mysql-bin.000197, 4)[0m 2022-12-19 16:37:59 ERROR Timeout while waiting for events up to lock 2022-12-19 16:37:59 ERROR 2022-12-19 16:37:59 ERROR Timeout while waiting for events up to lock 2022/12/19 16:38:00 binlogstreamer.go:47: [0;31m[error] close sync with err: data len 310 < expected 2179[0m Copy: 769329/769329 100.0%; Applied: 0; Backlog: 0/1000; Time: 4m50s(total), 2m0s(copy); streamer: mysql-bin.000197:21632791; State: migrating; ETA: due 2022/12/19 16:38:05 binlogsyncer.go:79: [0;37m[info] create BinlogSyncer with config {99999 mysql localhost 3306 rdsadmin false false }[0m 2022/12/19 16:38:05 binlogsyncer.go:246: [0;37m[info] begin to sync binlog from position (mysql-bin.000197, 4)[0m 2022/12/19 16:38:05 binlogsyncer.go:139: [0;37m[info] register slave for master server localhost:3306[0m 2022/12/19 16:38:05 binlogsyncer.go:573: [0;37m[info] rotate to (mysql-bin.000197, 4)[0m 2022-12-19 16:38:05 ERROR Timeout while waiting for events up to lock 2022-12-19 16:38:05 ERROR 2022-12-19 16:38:05 ERROR Timeout while waiting for events up to lock Copy: 769329/769329 100.0%; Applied: 0; Backlog: 0/1000; Time: 4m55s(total), 2m0s(copy); streamer: mysql-bin.000197:8519807; State: migrating; ETA: due 2022/12/19 16:38:07 binlogstreamer.go:47: [0;31m[error] close sync with err: data len 310 < expected 2179[0m Copy: 769329/769329 100.0%; Applied: 0; Backlog: 0/1000; Time: 5m0s(total), 2m0s(copy); streamer: mysql-bin.000197:21632791; State: migrating; ETA: due 2022-12-19 16:38:12 ERROR Timeout while waiting for events up to lock 2022-12-19 16:38:12 ERROR 2022-12-19 16:38:12 ERROR Timeout while waiting for events up to lock 2022/12/19 16:38:12 binlogsyncer.go:79: [0;37m[info] create BinlogSyncer with config {99999 mysql localhost 3306 rdsadmin false false }[0m 2022/12/19 16:38:12 binlogsyncer.go:246: [0;37m[info] begin to sync binlog from position (mysql-bin.000197, 4)[0m 2022/12/19 16:38:12 binlogsyncer.go:139: [0;37m[info] register slave for master server localhost:3306[0m 2022/12/19 16:38:12 binlogsyncer.go:573: [0;37m[info] rotate to (mysql-bin.000197, 4)[0m 2022/12/19 16:38:16 binlogstreamer.go:47: [0;31m[error] close sync with err: data len 310 < expected 2179[0m Copy: 769329/769329 100.0%; Applied: 0; Backlog: 0/1000; Time: 5m5s(total), 2m0s(copy); streamer: mysql-bin.000197:21632791; State: migrating; ETA: due 2022-12-19 16:38:18 ERROR Timeout while waiting for events up to lock 2022-12-19 16:38:18 ERROR 2022-12-19 16:38:18 ERROR Timeout while waiting for events up to lock 2022/12/19 16:38:21 binlogsyncer.go:79: [0;37m[info] create BinlogSyncer with config {99999 mysql localhost 3306 rdsadmin false false }[0m 2022/12/19 16:38:21 binlogsyncer.go:246: [0;37m[info] begin to sync binlog from position (mysql-bin.000197, 4)[0m 2022/12/19 16:38:21 binlogsyncer.go:139: [0;37m[info] register slave for master server localhost:3306[0m 2022/12/19 16:38:21 binlogsyncer.go:573: [0;37m[info] rotate to (mysql-bin.000197, 4)[0m Copy: 769329/769329 100.0%; Applied: 0; Backlog: 0/1000; Time: 5m10s(total), 2m0s(copy); streamer: mysql-bin.000197:2841618; State: migrating; ETA: due 2022/12/19 16:38:24 binlogstreamer.go:47: [0;31m[error] close sync with err: data len 310 < expected 2179[0m 2022-12-19 16:38:25 ERROR Timeout while waiting for events up to lock 2022-12-19 16:38:25 ERROR 2022-12-19 16:38:25 ERROR Timeout while waiting for events up to lock Copy: 769329/769329 100.0%; Applied: 0; Backlog: 0/1000; Time: 5m15s(total), 2m0s(copy); streamer: mysql-bin.000197:21632791; State: migrating; ETA: due 2022/12/19 16:38:29 binlogsyncer.go:79: [0;37m[info] create BinlogSyncer with config {99999 mysql localhost 3306 rdsadmin false false }[0m 2022/12/19 16:38:29 binlogsyncer.go:246: [0;37m[info] begin to sync binlog from position (mysql-bin.000197, 4)[0m 2022/12/19 16:38:29 binlogsyncer.go:139: [0;37m[info] register slave for master server localhost:3306[0m 2022/12/19 16:38:29 binlogsyncer.go:573: [0;37m[info] rotate to (mysql-bin.000197, 4)[0m 2022/12/19 16:38:31 binlogstreamer.go:47: [0;31m[error] close sync with err: data len 310 < expected 2179[0m 2022-12-19 16:38:31 ERROR Timeout while waiting for events up to lock 2022-12-19 16:38:31 ERROR 2022-12-19 16:38:31 ERROR Timeout while waiting for events up to lock Copy: 769329/769329 100.0%; Applied: 0; Backlog: 0/1000; Time: 5m20s(total), 2m0s(copy); streamer: mysql-bin.000197:21632791; State: migrating; ETA: due 2022/12/19 16:38:36 binlogsyncer.go:79: [0;37m[info] create BinlogSyncer with config {99999 mysql localhost 3306 rdsadmin false false }[0m 2022/12/19 16:38:36 binlogsyncer.go:246: [0;37m[info] begin to sync binlog from position (mysql-bin.000197, 4)[0m 2022/12/19 16:38:36 binlogsyncer.go:139: [0;37m[info] register slave for master server localhost:3306[0m 2022/12/19 16:38:36 binlogsyncer.go:573: [0;37m[info] rotate to (mysql-bin.000197, 4)[0m Copy: 769329/769329 100.0%; Applied: 0; Backlog: 0/1000; Time: 5m25s(total), 2m0s(copy); streamer: mysql-bin.000197:4548675; State: migrating; ETA: due 2022-12-19 16:38:37 ERROR Timeout while waiting for events up to lock 2022-12-19 16:38:37 ERROR 2022-12-19 16:38:37 ERROR Timeout while waiting for events up to lock 2022/12/19 16:38:37 binlogstreamer.go:47: [0;31m[error] close sync with err: data len 310 < expected 2179[0m Copy: 769329/769329 100.0%; Applied: 0; Backlog: 0/1000; Time: 5m30s(total), 2m0s(copy); streamer: mysql-bin.000197:21569140; State: migrating; ETA: due 2022/12/19 16:38:42 binlogsyncer.go:79: [0;37m[info] create BinlogSyncer with config {99999 mysql localhost 3306 rdsadmin false false }[0m 2022/12/19 16:38:42 binlogsyncer.go:246: [0;37m[info] begin to sync binlog from position (mysql-bin.000197, 4)[0m 2022/12/19 16:38:42 binlogsyncer.go:139: [0;37m[info] register slave for master server localhost:3306[0m 2022/12/19 16:38:42 binlogsyncer.go:573: [0;37m[info] rotate to (mysql-bin.000197, 4)[0m 2022-12-19 16:38:43 ERROR Timeout while waiting for events up to lock 2022-12-19 16:38:43 ERROR 2022-12-19 16:38:43 ERROR Timeout while waiting for events up to lock 2022/12/19 16:38:44 binlogstreamer.go:47: [0;31m[error] close sync with err: data len 310 < expected 2179[0m Copy: 769329/769329 100.0%; Applied: 0; Backlog: 0/1000; Time: 5m35s(total), 2m0s(copy); streamer: mysql-bin.000197:21561394; State: migrating; ETA: due 2022/12/19 16:38:49 binlogsyncer.go:79: [0;37m[info] create BinlogSyncer with config {99999 mysql localhost 3306 rdsadmin false false }[0m 2022/12/19 16:38:49 binlogsyncer.go:246: [0;37m[info] begin to sync binlog from position (mysql-bin.000197, 4)[0m 2022/12/19 16:38:49 binlogsyncer.go:139: [0;37m[info] register slave for master server localhost:3306[0m 2022/12/19 16:38:49 binlogsyncer.go:573: [0;37m[info] rotate to (mysql-bin.000197, 4)[0m 2022-12-19 16:38:49 ERROR Timeout while waiting for events up to lock 2022-12-19 16:38:49 ERROR 2022-12-19 16:38:49 ERROR Timeout while waiting for events up to lock Copy: 769329/769329 100.0%; Applied: 0; Backlog: 0/1000; Time: 5m40s(total), 2m0s(copy); streamer: mysql-bin.000197:20796315; State: migrating; ETA: due 2022/12/19 16:38:51 binlogstreamer.go:47: [0;31m[error] close sync with err: data len 310 < expected 2179[0m 2022-12-19 16:38:55 ERROR Timeout while waiting for events up to lock 2022-12-19 16:38:55 ERROR 2022-12-19 16:38:55 ERROR Timeout while waiting for events up to lock Copy: 769329/769329 100.0%; Applied: 0; Backlog: 0/1000; Time: 5m45s(total), 2m0s(copy); streamer: mysql-bin.000197:21632791; State: migrating; ETA: due 2022/12/19 16:38:56 binlogsyncer.go:79: [0;37m[info] create BinlogSyncer with config {99999 mysql localhost 3306 rdsadmin false false }[0m 2022/12/19 16:38:56 binlogsyncer.go:246: [0;37m[info] begin to sync binlog from position (mysql-bin.000197, 4)[0m 2022/12/19 16:38:56 binlogsyncer.go:139: [0;37m[info] register slave for master server localhost:3306[0m 2022/12/19 16:38:56 binlogsyncer.go:573: [0;37m[info] rotate to (mysql-bin.000197, 4)[0m 2022/12/19 16:38:58 binlogstreamer.go:47: [0;31m[error] close sync with err: data len 310 < expected 2179[0m Copy: 769329/769329 100.0%; Applied: 0; Backlog: 0/1000; Time: 5m50s(total), 2m0s(copy); streamer: mysql-bin.000197:21632791; State: migrating; ETA: due 2022-12-19 16:39:02 ERROR Timeout while waiting for events up to lock 2022-12-19 16:39:02 ERROR 2022-12-19 16:39:02 ERROR Timeout while waiting for events up to lock 2022/12/19 16:39:03 binlogsyncer.go:79: [0;37m[info] create BinlogSyncer with config {99999 mysql localhost 3306 rdsadmin false false }[0m 2022/12/19 16:39:03 binlogsyncer.go:246: [0;37m[info] begin to sync binlog from position (mysql-bin.000197, 4)[0m 2022/12/19 16:39:03 binlogsyncer.go:139: [0;37m[info] register slave for master server localhost:3306[0m 2022/12/19 16:39:03 binlogsyncer.go:573: [0;37m[info] rotate to (mysql-bin.000197, 4)[0m 2022/12/19 16:39:05 binlogstreamer.go:47: [0;31m[error] close sync with err: data len 310 < expected 2179[0m Copy: 769329/769329 100.0%; Applied: 0; Backlog: 0/1000; Time: 5m55s(total), 2m0s(copy); streamer: mysql-bin.000197:21632791; State: migrating; ETA: due 2022-12-19 16:39:08 ERROR Timeout while waiting for events up to lock 2022-12-19 16:39:08 ERROR 2022-12-19 16:39:08 ERROR Timeout while waiting for events up to lock 2022/12/19 16:39:10 binlogsyncer.go:79: [0;37m[info] create BinlogSyncer with config {99999 mysql localhost 3306 rdsadmin false false }[0m 2022/12/19 16:39:10 binlogsyncer.go:246: [0;37m[info] begin to sync binlog from position (mysql-bin.000197, 4)[0m 2022/12/19 16:39:10 binlogsyncer.go:139: [0;37m[info] register slave for master server localhost:3306[0m 2022/12/19 16:39:10 binlogsyncer.go:573: [0;37m[info] rotate to (mysql-bin.000197, 4)[0m Copy: 769329/769329 100.0%; Applied: 0; Backlog: 0/1000; Time: 6m0s(total), 2m0s(copy); streamer: mysql-bin.000197:15982497; State: migrating; ETA: due 2022/12/19 16:39:12 binlogstreamer.go:47: [0;31m[error] close sync with err: data len 310 < expected 2179[0m 2022-12-19 16:39:14 ERROR Timeout while waiting for events up to lock 2022-12-19 16:39:14 ERROR 2022-12-19 16:39:14 ERROR Timeout while waiting for events up to lock Copy: 769329/769329 100.0%; Applied: 0; Backlog: 0/1000; Time: 6m5s(total), 2m0s(copy); streamer: mysql-bin.000197:21616782; State: migrating; ETA: due 2022/12/19 16:39:17 binlogsyncer.go:79: [0;37m[info] create BinlogSyncer with config {99999 mysql localhost 3306 rdsadmin false false }[0m 2022/12/19 16:39:17 binlogsyncer.go:246: [0;37m[info] begin to sync binlog from position (mysql-bin.000197, 4)[0m 2022/12/19 16:39:17 binlogsyncer.go:139: [0;37m[info] register slave for master server localhost:3306[0m 2022/12/19 16:39:17 binlogsyncer.go:573: [0;37m[info] rotate to (mysql-bin.000197, 4)[0m 2022/12/19 16:39:19 binlogstreamer.go:47: [0;31m[error] close sync with err: data len 310 < expected 2179[0m 2022-12-19 16:39:20 ERROR Timeout while waiting for events up to lock 2022-12-19 16:39:20 ERROR 2022-12-19 16:39:20 ERROR Timeout while waiting for events up to lock Copy: 769329/769329 100.0%; Applied: 0; Backlog: 0/1000; Time: 6m10s(total), 2m0s(copy); streamer: mysql-bin.000197:21569140; State: migrating; ETA: due 2022/12/19 16:39:24 binlogsyncer.go:79: [0;37m[info] create BinlogSyncer with config {99999 mysql localhost 3306 rdsadmin false false }[0m 2022/12/19 16:39:24 binlogsyncer.go:246: [0;37m[info] begin to sync binlog from position (mysql-bin.000197, 4)[0m 2022/12/19 16:39:24 binlogsyncer.go:139: [0;37m[info] register slave for master server localhost:3306[0m 2022/12/19 16:39:24 binlogsyncer.go:573: [0;37m[info] rotate to (mysql-bin.000197, 4)[0m 2022/12/19 16:39:25 binlogstreamer.go:47: [0;31m[error] close sync with err: data len 310 < expected 2179[0m 2022-12-19 16:39:26 ERROR Timeout while waiting for events up to lock 2022-12-19 16:39:26 ERROR 2022-12-19 16:39:26 ERROR Timeout while waiting for events up to lock Copy: 769329/769329 100.0%; Applied: 0; Backlog: 0/1000; Time: 6m15s(total), 2m0s(copy); streamer: mysql-bin.000197:21632791; State: migrating; ETA: due 2022/12/19 16:39:30 binlogsyncer.go:79: [0;37m[info] create BinlogSyncer with config {99999 mysql localhost 3306 rdsadmin false false }[0m 2022/12/19 16:39:30 binlogsyncer.go:246: [0;37m[info] begin to sync binlog from position (mysql-bin.000197, 4)[0m 2022/12/19 16:39:30 binlogsyncer.go:139: [0;37m[info] register slave for master server localhost:3306[0m 2022/12/19 16:39:30 binlogsyncer.go:573: [0;37m[info] rotate to (mysql-bin.000197, 4)[0m Copy: 769329/769329 100.0%; Applied: 0; Backlog: 0/1000; Time: 6m20s(total), 2m0s(copy); streamer: mysql-bin.000197:15536690; State: migrating; ETA: due 2022/12/19 16:39:32 binlogstreamer.go:47: [0;31m[error] close sync with err: data len 310 < expected 2179[0m 2022-12-19 16:39:32 ERROR Timeout while waiting for events up to lock 2022-12-19 16:39:32 ERROR 2022-12-19 16:39:32 ERROR Timeout while waiting for events up to lock Copy: 769329/769329 100.0%; Applied: 0; Backlog: 0/1000; Time: 6m25s(total), 2m0s(copy); streamer: mysql-bin.000197:21632791; State: migrating; ETA: due 2022/12/19 16:39:37 binlogsyncer.go:79: [0;37m[info] create BinlogSyncer with config {99999 mysql localhost 3306 rdsadmin false false }[0m 2022/12/19 16:39:37 binlogsyncer.go:246: [0;37m[info] begin to sync binlog from position (mysql-bin.000197, 4)[0m 2022/12/19 16:39:37 binlogsyncer.go:139: [0;37m[info] register slave for master server localhost:3306[0m 2022/12/19 16:39:37 binlogsyncer.go:573: [0;37m[info] rotate to (mysql-bin.000197, 4)[0m 2022-12-19 16:39:38 ERROR Timeout while waiting for events up to lock 2022-12-19 16:39:38 ERROR 2022-12-19 16:39:38 ERROR Timeout while waiting for events up to lock 2022/12/19 16:39:38 binlogstreamer.go:47: [0;31m[error] close sync with err: data len 310 < expected 2179[0m Copy: 769329/769329 100.0%; Applied: 0; Backlog: 0/1000; Time: 6m30s(total), 2m0s(copy); streamer: mysql-bin.000197:21632791; State: migrating; ETA: due 2022/12/19 16:39:43 binlogsyncer.go:79: [0;37m[info] create BinlogSyncer with config {99999 mysql localhost 3306 rdsadmin false false }[0m 2022/12/19 16:39:43 binlogsyncer.go:246: [0;37m[info] begin to sync binlog from position (mysql-bin.000197, 4)[0m 2022/12/19 16:39:43 binlogsyncer.go:139: [0;37m[info] register slave for master server localhost:3306[0m 2022/12/19 16:39:43 binlogsyncer.go:573: [0;37m[info] rotate to (mysql-bin.000197, 4)[0m 2022-12-19 16:39:45 ERROR Error 1205: Lock wait timeout exceeded; try restarting transaction 2022-12-19 16:39:45 ERROR Error 1205: Lock wait timeout exceeded; try restarting transaction 2022/12/19 16:39:45 binlogstreamer.go:47: [0;31m[error] close sync with err: data len 310 < expected 2179[0m Copy: 769329/769329 100.0%; Applied: 0; Backlog: 0/1000; Time: 6m35s(total), 2m0s(copy); streamer: mysql-bin.000197:21632791; State: migrating; ETA: due 2022/12/19 16:39:50 binlogsyncer.go:79: [0;37m[info] create BinlogSyncer with config {99999 mysql localhost 3306 rdsadmin false false }[0m 2022/12/19 16:39:50 binlogsyncer.go:246: [0;37m[info] begin to sync binlog from position (mysql-bin.000197, 4)[0m 2022/12/19 16:39:50 binlogsyncer.go:139: [0;37m[info] register slave for master server localhost:3306[0m 2022/12/19 16:39:50 binlogsyncer.go:573: [0;37m[info] rotate to (mysql-bin.000197, 4)[0m Copy: 769329/769329 100.0%; Applied: 0; Backlog: 0/1000; Time: 6m40s(total), 2m0s(copy); streamer: mysql-bin.000197:7727416; State: migrating; ETA: due 2022/12/19 16:39:52 binlogstreamer.go:47: [0;31m[error] close sync with err: data len 310 < expected 2179[0m 2022-12-19 16:39:53 ERROR Timeout while waiting for events up to lock 2022-12-19 16:39:53 ERROR 2022-12-19 16:39:53 ERROR Timeout while waiting for events up to lock Copy: 769329/769329 100.0%; Applied: 0; Backlog: 0/1000; Time: 6m45s(total), 2m0s(copy); streamer: mysql-bin.000197:21632791; State: migrating; ETA: due 2022/12/19 16:39:57 binlogsyncer.go:79: [0;37m[info] create BinlogSyncer with config {99999 mysql localhost 3306 rdsadmin false false }[0m 2022/12/19 16:39:57 binlogsyncer.go:246: [0;37m[info] begin to sync binlog from position (mysql-bin.000197, 4)[0m 2022/12/19 16:39:57 binlogsyncer.go:139: [0;37m[info] register slave for master server localhost:3306[0m 2022/12/19 16:39:57 binlogsyncer.go:573: [0;37m[info] rotate to (mysql-bin.000197, 4)[0m 2022-12-19 16:39:59 ERROR Timeout while waiting for events up to lock 2022-12-19 16:39:59 ERROR 2022-12-19 16:39:59 ERROR Timeout while waiting for events up to lock 2022/12/19 16:39:59 binlogstreamer.go:47: [0;31m[error] close sync with err: data len 310 < expected 2179[0m Copy: 769329/769329 100.0%; Applied: 0; Backlog: 0/1000; Time: 6m50s(total), 2m0s(copy); streamer: mysql-bin.000197:21632791; State: migrating; ETA: due 2022/12/19 16:40:04 binlogsyncer.go:79: [0;37m[info] create BinlogSyncer with config {99999 mysql localhost 3306 rdsadmin false false }[0m 2022/12/19 16:40:04 binlogsyncer.go:246: [0;37m[info] begin to sync binlog from position (mysql-bin.000197, 4)[0m 2022/12/19 16:40:04 binlogsyncer.go:139: [0;37m[info] register slave for master server localhost:3306[0m 2022/12/19 16:40:04 binlogsyncer.go:573: [0;37m[info] rotate to (mysql-bin.000197, 4)[0m 2022-12-19 16:40:05 ERROR Timeout while waiting for events up to lock 2022-12-19 16:40:05 ERROR 2022-12-19 16:40:05 ERROR Timeout while waiting for events up to lock Copy: 769329/769329 100.0%; Applied: 0; Backlog: 0/1000; Time: 6m55s(total), 2m0s(copy); streamer: mysql-bin.000197:19093954; State: migrating; ETA: due 2022/12/19 16:40:07 binlogstreamer.go:47: [0;31m[error] close sync with err: data len 310 < expected 2179[0m 2022-12-19 16:40:11 ERROR Timeout while waiting for events up to lock 2022-12-19 16:40:11 ERROR 2022-12-19 16:40:11 ERROR Timeout while waiting for events up to lock Copy: 769329/769329 100.0%; Applied: 0; Backlog: 0/1000; Time: 7m0s(total), 2m0s(copy); streamer: mysql-bin.000197:21632791; State: migrating; ETA: due 2022/12/19 16:40:12 binlogsyncer.go:79: [0;37m[info] create BinlogSyncer with config {99999 mysql localhost 3306 rdsadmin false false }[0m 2022/12/19 16:40:12 binlogsyncer.go:246: [0;37m[info] begin to sync binlog from position (mysql-bin.000197, 4)[0m 2022/12/19 16:40:12 binlogsyncer.go:139: [0;37m[info] register slave for master server localhost:3306[0m 2022/12/19 16:40:12 binlogsyncer.go:573: [0;37m[info] rotate to (mysql-bin.000197, 4)[0m 2022/12/19 16:40:13 binlogstreamer.go:47: [0;31m[error] close sync with err: data len 310 < expected 2179[0m Copy: 769329/769329 100.0%; Applied: 0; Backlog: 0/1000; Time: 7m5s(total), 2m0s(copy); streamer: mysql-bin.000197:21632791; State: migrating; ETA: due 2022-12-19 16:40:17 ERROR Timeout while waiting for events up to lock 2022-12-19 16:40:17 ERROR 2022-12-19 16:40:17 ERROR Timeout while waiting for events up to lock 2022/12/19 16:40:18 binlogsyncer.go:79: [0;37m[info] create BinlogSyncer with config {99999 mysql localhost 3306 rdsadmin false false }[0m 2022/12/19 16:40:18 binlogsyncer.go:246: [0;37m[info] begin to sync binlog from position (mysql-bin.000197, 4)[0m 2022/12/19 16:40:18 binlogsyncer.go:139: [0;37m[info] register slave for master server localhost:3306[0m 2022/12/19 16:40:18 binlogsyncer.go:573: [0;37m[info] rotate to (mysql-bin.000197, 4)[0m 2022/12/19 16:40:20 binlogstreamer.go:47: [0;31m[error] close sync with err: data len 310 < expected 2179[0m Copy: 769329/769329 100.0%; Applied: 0; Backlog: 0/1000; Time: 7m10s(total), 2m0s(copy); streamer: mysql-bin.000197:21632791; State: migrating; ETA: due 2022-12-19 16:40:23 ERROR Timeout while waiting for events up to lock 2022-12-19 16:40:23 ERROR 2022-12-19 16:40:23 ERROR Timeout while waiting for events up to lock 2022/12/19 16:40:25 binlogsyncer.go:79: [0;37m[info] create BinlogSyncer with config {99999 mysql localhost 3306 rdsadmin false false }[0m 2022/12/19 16:40:25 binlogsyncer.go:246: [0;37m[info] begin to sync binlog from position (mysql-bin.000197, 4)[0m 2022/12/19 16:40:25 binlogsyncer.go:139: [0;37m[info] register slave for master server localhost:3306[0m 2022/12/19 16:40:25 binlogsyncer.go:573: [0;37m[info] rotate to (mysql-bin.000197, 4)[0m Copy: 769329/769329 100.0%; Applied: 0; Backlog: 0/1000; Time: 7m15s(total), 2m0s(copy); streamer: mysql-bin.000197:6506231; State: migrating; ETA: due 2022-12-19 16:40:27 ERROR Timeout while waiting for events up to lock 2022-12-19 16:40:27 ERROR 2022-12-19 16:40:27 ERROR Timeout while waiting for events up to lock 2022/12/19 16:40:29 binlogstreamer.go:47: [0;31m[error] close sync with err: data len 310 < expected 2179[0m Copy: 769329/769329 100.0%; Applied: 0; Backlog: 0/1000; Time: 7m20s(total), 2m0s(copy); streamer: mysql-bin.000197:21632791; State: migrating; ETA: due 2022-12-19 16:40:31 ERROR Timeout while waiting for events up to lock 2022-12-19 16:40:31 ERROR 2022-12-19 16:40:31 ERROR Timeout while waiting for events up to lock 2022/12/19 16:40:34 binlogsyncer.go:79: [0;37m[info] create BinlogSyncer with config {99999 mysql localhost 3306 rdsadmin false false }[0m 2022/12/19 16:40:34 binlogsyncer.go:246: [0;37m[info] begin to sync binlog from position (mysql-bin.000197, 4)[0m 2022/12/19 16:40:34 binlogsyncer.go:139: [0;37m[info] register slave for master server localhost:3306[0m 2022/12/19 16:40:34 binlogsyncer.go:573: [0;37m[info] rotate to (mysql-bin.000197, 4)[0m 2022-12-19 16:40:35 ERROR Timeout while waiting for events up to lock 2022-12-19 16:40:35 ERROR 2022-12-19 16:40:35 ERROR Timeout while waiting for events up to lock 2022/12/19 16:40:36 binlogstreamer.go:47: [0;31m[error] close sync with err: data len 310 < expected 2179[0m Copy: 769329/769329 100.0%; Applied: 0; Backlog: 0/1000; Time: 7m25s(total), 2m0s(copy); streamer: mysql-bin.000197:21553308; State: migrating; ETA: due 2022-12-19 16:40:39 ERROR Timeout while waiting for events up to lock 2022-12-19 16:40:39 ERROR 2022-12-19 16:40:39 ERROR Timeout while waiting for events up to lock 2022/12/19 16:40:41 binlogsyncer.go:79: [0;37m[info] create BinlogSyncer with config {99999 mysql localhost 3306 rdsadmin false false }[0m 2022/12/19 16:40:41 binlogsyncer.go:246: [0;37m[info] begin to sync binlog from position (mysql-bin.000197, 4)[0m 2022/12/19 16:40:41 binlogsyncer.go:139: [0;37m[info] register slave for master server localhost:3306[0m 2022/12/19 16:40:41 binlogsyncer.go:573: [0;37m[info] rotate to (mysql-bin.000197, 4)[0m Copy: 769329/769329 100.0%; Applied: 0; Backlog: 0/1000; Time: 7m30s(total), 2m0s(copy); streamer: mysql-bin.000197:8687216; State: migrating; ETA: due 2022/12/19 16:40:42 binlogstreamer.go:47: [0;31m[error] close sync with err: data len 310 < expected 2179[0m 2022-12-19 16:40:43 ERROR Timeout while waiting for events up to lock 2022-12-19 16:40:43 ERROR 2022-12-19 16:40:43 ERROR Timeout while waiting for events up to lock Copy: 769329/769329 100.0%; Applied: 0; Backlog: 0/1000; Time: 7m35s(total), 2m0s(copy); streamer: mysql-bin.000197:21632791; State: migrating; ETA: due 2022/12/19 16:40:47 binlogsyncer.go:79: [0;37m[info] create BinlogSyncer with config {99999 mysql localhost 3306 rdsadmin false false }[0m 2022/12/19 16:40:47 binlogsyncer.go:246: [0;37m[info] begin to sync binlog from position (mysql-bin.000197, 4)[0m 2022/12/19 16:40:47 binlogsyncer.go:139: [0;37m[info] register slave for master server localhost:3306[0m 2022/12/19 16:40:47 binlogsyncer.go:573: [0;37m[info] rotate to (mysql-bin.000197, 4)[0m 2022-12-19 16:40:47 ERROR Timeout while waiting for events up to lock 2022-12-19 16:40:47 ERROR 2022-12-19 16:40:47 ERROR Timeout while waiting for events up to lock 2022/12/19 16:40:49 binlogstreamer.go:47: [0;31m[error] close sync with err: data len 310 < expected 2179[0m Copy: 769329/769329 100.0%; Applied: 0; Backlog: 0/1000; Time: 7m40s(total), 2m0s(copy); streamer: mysql-bin.000197:21632791; State: migrating; ETA: due 2022-12-19 16:40:51 ERROR Timeout while waiting for events up to lock 2022-12-19 16:40:51 ERROR 2022-12-19 16:40:51 ERROR Timeout while waiting for events up to lock 2022/12/19 16:40:54 binlogsyncer.go:79: [0;37m[info] create BinlogSyncer with config {99999 mysql localhost 3306 rdsadmin false false }[0m 2022/12/19 16:40:54 binlogsyncer.go:246: [0;37m[info] begin to sync binlog from position (mysql-bin.000197, 4)[0m 2022/12/19 16:40:54 binlogsyncer.go:139: [0;37m[info] register slave for master server localhost:3306[0m 2022/12/19 16:40:54 binlogsyncer.go:573: [0;37m[info] rotate to (mysql-bin.000197, 4)[0m 2022-12-19 16:40:55 ERROR Timeout while waiting for events up to lock 2022-12-19 16:40:55 ERROR 2022-12-19 16:40:55 ERROR Timeout while waiting for events up to lock 2022-12-19 16:40:56 FATAL 2022-12-19 16:40:55 ERROR Timeout while waiting for events up to lock

There are two errors here: 1、 [error] close sync with err: data len 310 < expected 2179 The trigger reason for this error is not detailed,i don't know what caused it.

2、 ERROR Timeout while waiting for events up to lock Here I think that due to the existence of large transactions, multiple acquisitions of metadata locks failed, resulting in timeouts for acquiring metadata locks.

In addition, the execution failure on the main library will also cause the replication of the slave library to be stuck, and the drop table and multi-threaded replication will cause lock conflicts. image

boomballa avatar Dec 20 '22 02:12 boomballa

image

It should not be caused by large transactions. I did an experiment on a mysql without production requests, and this problem still occurs.

boomballa avatar Dec 20 '22 06:12 boomballa

@boomballa can you provide the version of gh-ost and the command line flags (with sensitive info redacted)?

I believe the [error] close sync with err: data len 310 < expected 2179 may be resolved in a more recent gh-ost version containing a newer mysql library, assuming you are using an older version

timvaillancourt avatar Jan 08 '23 00:01 timvaillancourt