Repetitive failure to cut-over
- Dominant language
- Go
- Stars
- 13.6k
- Forks
- 1.4k
- Avg merge
- 2h 31m
- Merged PRs (30d)
- 4
Description
We met with the following yesterday:
- migration was running
- was reaching cut-over phase, cut-over was psotponed
- we issued `cut-over`
- cut-over failed on `Timeout while waiting for events up to lock`
additional attempts continued to result with same error, and finally the cut-over worked as expected.
Redacted logs:
```
2017-04-17 14:14:21 INFO Grabbing voluntary lock: gh-ost.495404886.lock
2017-04-17 14:14:21 INFO Setting LOCK timeout as 6 seconds
2017-04-17 14:14:21 INFO Looking for magic cut-over table
2017-04-17 14:14:21 INFO Creating magic cut-over table `redacted_db`.`_archived_redacted_table_20170417094910_del`
2017-04-17 14:14:21 INFO Magic cut-over table created
2017-04-17 14:14:21 INFO Locking `redacted_db`.`archived_redacted_table`, `redacted_db`.`_archived_redacted_table_20170417094910_del`
2017-04-17 14:14:21 INFO Tables locked
2017-04-17 14:14:21 INFO Session locking original & magic tables is 495404886
2017-04-17 14:14:21 INFO Writing changelog state: AllEventsUpToLockProcessed:1492463661889295557
2017-04-17 14:14:21 INFO Waiting for events up to lock
2017-04-17 14:14:21 INFO Waiting for events up to lock: skipping AllEventsUpToLockProcessed:1492462282840008051
2017-04-17 14:14:21 INFO Waiting for events up to lock: skipping AllEventsUpToLockProcessed:1492462672846715971
2017/04/17 14:14:22 binlogsyncer.go:490: [error] connection was bad
2017/04/17 14:14:23 binlogsyncer.go:452: [info] begin to re-sync from (mysql-bin.007375, 800594842)
2017/04/17 14:14:23 binlogsyncer.go:134: [info] register slave for master server redacted-replica-server:3306
2017/04/17 14:14:23 binlogsyncer.go:568: [info] rotate to (mysql-bin.007375, 800594842)
2017-04-17 14:14:23 INFO rotate to next log name: mysql-bin.007375
2017-04-17 14:14:24 ERROR Timeout while waiting for events up to lock
2017-04-17 14:14:24 ERROR
2017-04-17 14:14:24 ERROR Timeout while waiting for events up to lock
2017-04-17 14:14:24 INFO Looking for magic cut-over table
2017-04-17 14:14:24 INFO Will now proceed to drop magic table and unlock tables
2017-04-17 14:14:24 INFO Dropping magic cut-over table
2017-04-17 14:14:25 INFO Releasing lock from `redacted_db`.`archived_redacted_table`, `redacted_db`.`_archived_redacted_table_20170417094910_del`
2017-04-17 14:14:25 INFO Tables unlocked
```
```
2017-04-17 14:24:10 INFO Grabbing voluntary lock: gh-ost.495489219.lock
2017-04-17 14:24:10 INFO Setting LOCK timeout as 6 seconds
2017-04-17 14:24:10 INFO Looking for magic cut-over table
2017-04-17 14:24:10 INFO Creating magic cut-over table `redacted_db`.`_archived_redacted_table_20170417094910_del`
2017-04-17 14:24:10 INFO Magic cut-over table created
2017-04-17 14:24:10 INFO Locking `redacted_db`.`archived_redacted_table`, `redacted_db`.`_archived_redacted_table_20170417094910_del`
2017-04-17 14:24:10 INFO Tables locked
2017-04-17 14:24:10 INFO Session locking original & magic tables is 495489219
2017-04-17 14:24:10 INFO Writing changelog state: AllEventsUpToLockProcessed:1492464250917621211
2017-04-17 14:24:10 INFO Waiting for events up to lock
2017-04-17 14:24:10 INFO Waiting for events up to lock: skipping AllEventsUpToLockProcessed:1492463661889295557
2017/04/17 14:24:11 binlogsyncer.go:490: [error] connection was bad
2017/04/17 14:24:12 binlogsyncer.go:452: [info] begin to re-sync from (mysql-bin.007376, 264831180)
2017/04/17 14:24:12 binlogsyncer.go:134: [info] register slave for master server redacted-replica-server:3306
2017/04/17 14:24:12 binlogsyncer.go:568: [info] rotate to (mysql-bin.007376, 264831180)
2017-04-17 14:24:12 INFO rotate to next log name: mysql-bin.007376
2017-04-17 14:24:13 ERROR Timeout while waiting for events up to lock
2017-04-17 14:24:13 ERROR
2017-04-17 14:24:13 ERROR Timeout while waiting for events up to lock
2017-04-17 14:24:13 INFO Looking for magic cut-over table
2017-04-17 14:24:13 INFO Will now proceed to drop magic table and unlock tables
2017-04-17 14:24:13 INFO Dropping magic cut-over table
2017-04-17 14:24:14 INFO Releasing lock from `redacted_db`.`archived_redacted_table`, `redacted_db`.`_archived_redacted_table_20170417094910_del`
2017-04-17 14:24:14 INFO Tables unlocked Copy: 11793026/11793026 100.0%; Applied: 68056; Backlog: 0/100; Time: 4h35m5s(total), 3h5m8s(copy); streamer: mysql-bin.007376:294545501; State: throttled, max-load Threads_running=385 >= 25; ETA: due
11793026/11793026 100.0%; Applied: 68083; Backlog: 0/100; Time: 4h35m20s(total), 3h5m8s(copy); streamer: mysql-bin.007376:464153593; State: postponing cut-over; ETA: due Copy: 11793026/11793026 100.0%; Applied: 68087; Backlog: 3/100; Time: 4h35m25s(total), 3h5m8s(copy); streamer: mysql-bin.007376:516299249; State: postponing cut-over; ETA: due
2017-04-17 14:24:36 INFO Intercepted changelog state AllEventsUpToLockProcessed
2017-04-17 14:24:36 INFO Handled changelog state AllEventsUpToLockProcessed Copy: 11793026/11793026 100.0%; Applied: 68090; Backlog: 0/100; Time: 4h35m30s(total), 3h5m8s(copy); streamer: mysql-bin.007376:542022463; State: postponing cut-over; ETA: due
```
cc @github/database-infrastructure @jonahberquist @tomkrouper
Contributor guide
Assessment
This issue has not been assessed yet.