write: broken pipe and _gho doesn't exist

hi，shlomi-noach

gh-ost 1.045
MySQL 5.7.19

```
time ./gh-ost --host=127.0.0.1 --port=3306 --user=lion --password=123456 \
--database=db1 --table=t1 \
--max-load='Threads_running=20,threads_connected=20' \
--critical-load='Threads_running=30,threads_connected=30' \
--chunk-size=6000 --assume-rbr --cut-over=atomic --timestamp-old-table \
--exact-rowcount --concurrent-rowcount \
--panic-flag-file=/tmp/gh-ost.panic.flag \
--postpone-cut-over-flag-file=/tmp/gh-ost.postpone.flag \
--default-retries=120 --approve-renamed-columns --dml-batch-size=10 \
--verbose --debug --allow-on-master \
--alter "modify c1 decimal(29,9) DEFAULT NULL,modify c2 decimal(29,9) DEFAULT NULL,modify c3 decimal(29,9) DEFAULT NULL" \
--execute
```
**Rowcopy completed for a long time (with an interval of about 1 hour) before the cut-over operation
rm -f /tmp/gh-ost.postpone.flag**
```

2018-05-24 18:04:19 DEBUG ApplyDMLEventQueries() applied 10 events in one transaction
2018-05-24 18:04:19 DEBUG ApplyDMLEventQueries() applied 9 events in one transaction
2018-05-24 18:04:19 DEBUG Getting nothing in the write queue. Sleeping...
Copy: 13374034/13374034 100.0%; Applied: 205502; Backlog: 0/1000; Time: 1h22m0s(total), 43m15s(copy); streamer: mysql-bin.000137:111529866; State: postponing cut-over; ETA: due
2018-05-24 18:04:20 DEBUG ApplyDMLEventQueries() applied 10 events in one transaction
2018-05-24 18:04:20 DEBUG ApplyDMLEventQueries() applied 10 events in one transaction
2018-05-24 18:04:20 DEBUG ApplyDMLEventQueries() applied 10 events in one transaction
2018-05-24 18:04:20 DEBUG ApplyDMLEventQueries() applied 3 events in one transaction
....................................................................................................................................................
2018-05-24 18:04:32 DEBUG Getting nothing in the write queue. Sleeping...
2018-05-24 18:04:33 DEBUG ApplyDMLEventQueries() applied 10 events in one transaction
2018-05-24 18:04:33 DEBUG ApplyDMLEventQueries() applied 10 events in one transaction
2018-05-24 18:04:33 DEBUG ApplyDMLEventQueries() applied 10 events in one transaction
2018-05-24 18:04:33 DEBUG ApplyDMLEventQueries() applied 3 events in one transaction
2018-05-24 18:04:33 DEBUG Getting nothing in the write queue. Sleeping...
2018-05-24 18:04:34 DEBUG checking for cut-over postpone: complete
2018-05-24 18:04:34 INFO Grabbing voluntary lock: gh-ost.2228.lock
2018-05-24 18:04:34 INFO Setting LOCK timeout as 6 seconds
2018-05-24 18:04:34 INFO Looking for magic cut-over table
2018-05-24 18:04:34 INFO Creating magic cut-over table `db1`.`_t1_20180524164219_del`
2018-05-24 18:04:34 INFO Magic cut-over table created
2018-05-24 18:04:34 INFO Locking `db1`.`t1`, `db1`.`_t1_20180524164219_del`
2018-05-24 18:04:34 INFO Tables locked
2018-05-24 18:04:34 INFO Session locking original & magic tables is 2228
2018-05-24 18:04:34 INFO Writing changelog state: AllEventsUpToLockProcessed:1527156274042181302
2018-05-24 18:04:34 INFO Intercepted changelog state AllEventsUpToLockProcessed
2018-05-24 18:04:34 INFO Handled changelog state AllEventsUpToLockProcessed
2018-05-24 18:04:34 INFO Waiting for events up to lock
2018-05-24 18:04:34 DEBUG ApplyDMLEventQueries() applied 10 events in one transaction
2018-05-24 18:04:34 DEBUG ApplyDMLEventQueries() applied 10 events in one transaction
2018-05-24 18:04:34 DEBUG ApplyDMLEventQueries() applied 10 events in one transaction
2018-05-24 18:04:34 DEBUG ApplyDMLEventQueries() applied 3 events in one transaction
2018-05-24 18:04:34 DEBUG Getting nothing in the write queue. Sleeping...
2018-05-24 18:04:34 INFO Waiting for events up to lock: got AllEventsUpToLockProcessed:1527156274042181302
2018-05-24 18:04:34 INFO Done waiting for events up to lock; duration=155.691525ms
Migrating `db1`.`t1`; Ghost table is `db1`.`_t1_gho`
Migrating DB-TEST-01:3306; inspecting DB-TEST-01:3306; executing on DB-TEST-01
Migration started at Thu May 24 16:42:19 +0800 2018
```
**The value of chunk-size is set to 6000. Why does the following print 2000?**
```
--chunk-size=6000
chunk-size: 2000; max-lag-millis: 1500ms; dml-batch-size: 10; max-load: Threads_running=20,threads_connected=20; critical-load: Threads_running=30,threads_connected=30; nice-ratio: 0.000000

throttle-additional-flag-file: /tmp/gh-ost.throttle
postpone-cut-over-flag-file: /tmp/gh-ost.postpone.flag
panic-flag-file: /tmp/gh-ost.panic.flag
Serving on unix socket: /tmp/gh-ost.db1.t1.sock

Copy: 13374034/13374034 100.0%; Applied: 206096; Backlog: 0/1000; Time: 1h22m14s(total), 43m15s(copy); streamer: mysql-bin.000137:113878395; State: migrating; ETA: due
2018-05-24 18:04:34 INFO Setting RENAME timeout as 3 seconds
2018-05-24 18:04:34 INFO Session renaming tables is 2230
2018-05-24 18:04:34 INFO Issuing and expecting this to block: rename /* gh-ost */ table `db1`.`t1` to `db1`.`_t1_20180524164219_del`, `db1`.`_t1_gho` to `db1`.`t1`
2018-05-24 18:04:34 INFO Found atomic RENAME to be blocking, as expected. Double checking the lock is still in place (though I don't strictly have to)
2018-05-24 18:04:34 INFO Checking session lock: gh-ost.2228.lock
2018-05-24 18:04:34 INFO Connection holding lock on original table still exists
2018-05-24 18:04:34 INFO Will now proceed to drop magic table and unlock tables
2018-05-24 18:04:34 INFO Dropping magic cut-over table
2018-05-24 18:04:34 INFO Releasing lock from `db1`.`t1`, `db1`.`_t1_20180524164219_del`
2018-05-24 18:04:34 INFO Tables unlocked
2018-05-24 18:04:34 INFO Tables renamed
2018-05-24 18:04:34 INFO Lock & rename duration: 201.43332ms. During this time, queries on `t1` were blocked
2018-05-24 18:04:34 INFO Looking for magic cut-over table
Copy: 13374034/13374034 100.0%; Applied: 206096; Backlog: 62/1000; Time: 1h22m15s(total), 43m15s(copy); streamer: mysql-bin.000137:113956819; State: migrating; ETA: due
```
**Temporary table has been renamed, why do dml operations on temporary tables ?**
```
2018-05-24 18:04:35 ERROR Error 1146: Table 'db1._t1_gho' doesn't exist; query=
update /* gh-ost `db1`.`_t1_gho` */
`db1`.`_t1_gho`
set
`id`=?, `c1`=?, `c2`=?, `c3`=?, `c4`=?,`create_time` = ? .......
where
((`id` = ?) and (`create_time` = ?))
; args=[1188415 41879 .................. 2 test 2017-11-01 01:01:42 2017-11-01 01:06:01 0
2017-11-01 01:01:42 System 127.0.0.1 2017-11-01 01:06:01 test 192.168.1.1
[65 48 49 103 103 104 57 51 51 51 32 124 32 229 190 144 232 148 154 230 152 165 32 124 32 90 77 89 40 229 188 160 231 190 142 230 156 136 41 32 124 32 228 186 164
233 128 154 233 147 182 232 161 140 32 124 32 28 184 138 230 181 183 44 228 184 138 230 181 183 32 124 32 230 137 139 230 156 186 232 189 172 232 180 166 32 124
32 50 48 49 55 45 49 49 45 48 49 32 48 49 58 48 49 58 48 55 32 124 32 53 48 48 48 32 124 124]
2017-11-01 01:01:41 ......... ..... 1000 0
5 10 0 f0abb5ac46041e6753db6df2db6ac9fa 2017-11-01 01:01:42 0 test 0 8841159 2017-11-01 01:01:42]

2018-05-24 18:04:36 ERROR Error 1146: Table 'db1._t1_gho' doesn't exist; query=
update /* gh-ost `db1`.`_t1_gho` */
`db1`.`_t1_gho`
set
`id`=?, `c1`=?, `c2`=?, `c3`=?, `c4`=?,`create_time` = ? .......
where
((`id` = ?) and (`create_time` = ?))
; args=[1188416 41879 .................. 2 test 2017-11-01 01:01:42 2017-11-01 01:06:01 0
2017-11-01 01:01:42 System 127.0.0.1 2017-11-01 01:06:01 test 192.168.1.1
[65 48 49 103 103 104 57 51 51 51 32 124 32 229 190 144 232 148 154 230 152 165 32 124 32 90 77 89 40 229 188 160 231 190 142 230 156 136 41 32 124 32 228 186 164
233 128 154 233 147 182 232 161 140 32 124 32 28 184 138 230 181 183 44 228 184 138 230 181 183 32 124 32 230 137 139 230 156 186 232 189 172 232 180 166 32 124
32 50 48 49 55 45 49 49 45 48 49 32 48 49 58 48 49 58 48 55 32 124 32 53 48 48 48 32 124 124]
2017-11-01 01:01:41 ......... ..... 1000 0
5 10 0 f0abb5ac46041e6753db6df2db6ac9fa 2017-11-01 01:01:42 0 test 0 8841159 2017-11-01 01:01:42]
...............................................................
2018-05-24 18:04:48 ERROR Error 1146: Table 'db1._t1_gho' doesn't exist; query=
update /* gh-ost `db1`.`_t1_gho` */
`db1`.`_t1_gho`
set
`id`=?, `c1`=?, `c2`=?, `c3`=?, `c4`=?,`create_time` = ? .......
where
((`id` = ?) and (`create_time` = ?))
; args=[1188416 41879 .................. 2 test 2017-11-01 01:01:42 2017-11-01 01:06:01 0
2017-11-01 01:01:42 System 127.0.0.1 2017-11-01 01:06:01 test 192.168.1.1
[65 48 49 103 103 104 57 51 51 51 32 124 32 229 190 144 232 148 154 230 152 165 32 124 32 90 77 89 40 229 188 160 231 190 142 230 156 136 41 32 124 32 228 186 164
233 128 154 233 147 182 232 161 140 32 124 32 28 184 138 230 181 183 44 228 184 138 230 181 183 32 124 32 230 137 139 230 156 186 232 189 172 232 180 166 32 124
32 50 48 49 55 45 49 49 45 48 49 32 48 49 58 48 49 58 48 55 32 124 32 53 48 48 48 32 124 124]
2017-11-01 01:01:41 ......... ..... 1000 0
5 10 0 f0abb5ac46041e6753db6df2db6ac9fa 2017-11-01 01:01:42 0 test 0 8841159 2017-11-01 01:01:42]

2018/05/24 18:04:48 binlogsyncer.go:107: [info] syncer is closing...
2018/05/24 18:04:48 binlogstreamer.go:47: [error] close sync with err: sync is been closing...
2018/05/24 18:04:48 binlogsyncer.go:122: [info] syncer is closed
2018-05-24 18:04:48 INFO Closed streamer connection. err=
2018-05-24 18:04:48 INFO Dropping table `db1`.`_t1_ghc`
2018-05-24 18:04:48 DEBUG Done streaming
2018-05-24 18:04:48 INFO Table dropped
2018-05-24 18:04:48 INFO Am not dropping old table because I want this operation to be as live as possible. If you insist I should do it, please add `--ok-to-drop-table` next time. But I prefer you do not. To drop the old table, issue:
2018-05-24 18:04:48 INFO -- drop table `db1`.`_t1_20180524164219_del`
2018-05-24 18:04:48 INFO Done migrating `db1`.`t1`
2018-05-24 18:04:48 INFO Removing socket file: /tmp/gh-ost.db1.t1.sock
2018-05-24 18:04:48 INFO Tearing down inspector
```
**The above message indicates that the table has been migrated, the following message says that my write is interrupted**
```
[MySQL] 2018/05/24 18:04:48 packets.go:118: write tcp 127.0.0.1:52025->127.0.0.1:3306: write: broken pipe
2018-05-24 18:04:49 INFO Tearing down applier
2018-05-24 18:04:49 DEBUG Tearing down...
[MySQL] 2018/05/24 18:04:49 packets.go:118: write tcp 127.0.0.1:52024->127.0.0.1:3306: write: broken pipe
2018-05-24 18:04:49 INFO Tearing down streamer
2018-05-24 18:04:49 INFO Tearing down throttler
2018-05-24 18:04:49 DEBUG Tearing down...
# Done
```

**Rowcopy completed for a long time (with an interval of about 1 hour)
Gh-ost has been waiting for cut-over
during this process
My ssh securecrt client interrupted once due to timeout during running gh-ost. When I connected to ssh securecrt client again, I found that the gh-ost program is still running and I did not exit.
When I perform cut-over (rm -f /tmp/gh-ost.postpone.flag)**

**Log message says:
```
2018-05-24 18:04:48 ERROR Error 1146: Table 'db1._t1_gho' doesn't exist; query=
[MySQL] 2018/05/24 18:04:48 packets.go:118: write tcp 127.0.0.1:52025->127.0.0.1:3306: write: broken pipe
```
In this case, I don't know if the data is complete**

**thanks shlomi-noach**