gh-ost completed success but print Errors #1573
Description
I used below command to add column to table:
gh-ost --chunk-size=200000 --host=x.x.x.x --verbose --timestamp-old-table --ask-pass --port=xxx--user=dbauser --database=game_usercenter_01 --table=game_player_10 --allow-on-master --ok-to-drop-table --max-lag-millis=100 --alter="add column game_mode tinyint(4) DEFAULT '0' COMMENT 'xxx'" --execute
gh-ost will completed successfully , and the resutl is as expected, but I'm confused is it will print Error message in the log, as below:
2025-07-22 14:50:06 INFO Copy: 11900000/11710096 101.6%; Applied: 0; Backlog: 0/1000; Time: 7m33s(total), 7m33s(copy); streamer: mysql-bin.000027:793269783; Lag: 0.01s, HeartbeatLag: 0.01s, State: migrating; ETA: due []
2025-07-22 14:50:07 INFO Row copy complete
Copy: 12002122/12002122 100.0%; Applied: 0; Backlog: 0/1000; Time: 7m34s(total), 7m33s(copy); streamer: mysql-bin.000027:815218176; Lag: 0.01s, HeartbeatLag: 0.04s, State: migrating; ETA: due
2025-07-22 14:50:07 INFO Copy: 12002122/12002122 100.0%; Applied: 0; Backlog: 0/1000; Time: 7m34s(total), 7m33s(copy); streamer: mysql-bin.000027:815218176; Lag: 0.01s, HeartbeatLag: 0.04s, State: migrating; ETA: due []
2025-07-22 14:50:07 INFO Grabbing voluntary lock: gh-ost.395.lock
2025-07-22 14:50:07 INFO Setting LOCK timeout as 6 seconds
2025-07-22 14:50:07 INFO Looking for magic cut-over table
2025-07-22 14:50:07 INFO Creating magic cut-over table game_usercenter_01._game_player_10_20250722144233_del
2025-07-22 14:50:07 INFO Magic cut-over table created
2025-07-22 14:50:07 INFO Setting cut-over idle timeout as 9 seconds
2025-07-22 14:50:07 INFO Locking game_usercenter_01.game_player_10, game_usercenter_01._game_player_10_20250722144233_del
2025-07-22 14:50:07 INFO Tables locked
2025-07-22 14:50:07 INFO Session locking original & magic tables is 395
2025-07-22 14:50:07 INFO Writing changelog state: AllEventsUpToLockProcessed:1753167007393436520
2025-07-22 14:50:07 INFO Intercepted changelog state AllEventsUpToLockProcessed
2025-07-22 14:50:07 INFO Handled changelog state AllEventsUpToLockProcessed
2025-07-22 14:50:07 INFO Waiting for events up to lock
Copy: 12002122/12002122 100.0%; Applied: 0; Backlog: 1/1000; Time: 7m34s(total), 7m33s(copy); streamer: mysql-bin.000027:815220562; Lag: 0.01s, HeartbeatLag: 0.01s, State: migrating; ETA: due
2025-07-22 14:50:07 INFO Copy: 12002122/12002122 100.0%; Applied: 0; Backlog: 1/1000; Time: 7m34s(total), 7m33s(copy); streamer: mysql-bin.000027:815220562; Lag: 0.01s, HeartbeatLag: 0.01s, State: migrating; ETA: due []
2025-07-22 14:50:08 INFO Waiting for events up to lock: got AllEventsUpToLockProcessed:1753167007393436520
2025-07-22 14:50:08 INFO Done waiting for events up to lock; duration=988.348385ms
Migrating game_usercenter_01.game_player_10; Ghost table is game_usercenter_01._game_player_10_gho
Migrating xx-xx-xx-xx.rds-fatpod-game-union.bjht:33xx; inspecting xx-xx-xxx-xx.rds-fatpod-game-union.bjht:33xx; executing on xx-xx-xxx-xxx.rdsrestore.bjht
Migration started at Tue Jul 22 14:42:33 +0800 2025
chunk-size: 100000; max-lag-millis: 100ms; dml-batch-size: 10; max-load: ; critical-load: ; nice-ratio: 0.000000
throttle-additional-flag-file: /tmp/gh-ost.throttle
Serving on unix socket: /tmp/gh-ost.game_usercenter_01.game_player_10.sock
Copy: 12002122/12002122 100.0%; Applied: 0; Backlog: 0/1000; Time: 7m35s(total), 7m33s(copy); streamer: mysql-bin.000027:815224002; Lag: 0.01s, HeartbeatLag: 0.04s, State: migrating; ETA: due
2025-07-22 14:50:08 INFO Copy: 12002122/12002122 100.0%; Applied: 0; Backlog: 0/1000; Time: 7m35s(total), 7m33s(copy); streamer: mysql-bin.000027:815224002; Lag: 0.01s, HeartbeatLag: 0.04s, State: migrating; ETA: due []
2025-07-22 14:50:08 INFO Setting RENAME timeout as 3 seconds
2025-07-22 14:50:08 INFO Session renaming tables is 391
2025-07-22 14:50:08 INFO Issuing and expecting this to block: rename /* gh-ost */ table game_usercenter_01.game_player_10 to game_usercenter_01._game_player_10_20250722144233_del, game_usercenter_01._game_player_10_gho to game_usercenter_01.game_player_10
2025-07-22 14:50:08 INFO Found atomic RENAME to be blocking, as expected. Double checking the lock is still in place (though I don't strictly have to)
2025-07-22 14:50:08 INFO Checking session lock: gh-ost.395.lock
2025-07-22 14:50:08 INFO Connection holding lock on original table still exists
2025-07-22 14:50:08 INFO Will now proceed to drop magic table and unlock tables
2025-07-22 14:50:08 INFO Dropping magic cut-over table
2025-07-22 14:50:08 INFO Releasing lock from game_usercenter_01.game_player_10, game_usercenter_01._game_player_10_20250722144233_del
2025-07-22 14:50:08 INFO Tables unlocked
2025-07-22 14:50:08 INFO Reverting cut-over idle timeout to 28800 seconds
2025-07-22 14:50:08 INFO Looking for magic cut-over table
2025-07-22 14:50:08 INFO Tables renamed
2025-07-22 14:50:08 INFO Lock & rename duration: 1.057990808s. During this time, queries on game_player_10 were blocked
2025-07-22 14:50:08 INFO Writing changelog state: Migrated
[2025/07/22 14:50:08] [info] binlogsyncer.go:206 syncer is closing...
[2025/07/22 14:50:08] [info] binlogsyncer.go:906 kill last connection id 390
[2025/07/22 14:50:08] [info] binlogsyncer.go:236 syncer is closed
2025-07-22 14:50:08 INFO Closed streamer connection. err=
2025-07-22 14:50:08 INFO Dropping table game_usercenter_01._game_player_10_ghc
2025-07-22 14:50:08 INFO Table dropped
2025-07-22 14:50:08 INFO Dropping table game_usercenter_01._game_player_10_20250722144233_del
_2025-07-22 14:50:08 ERROR Error 1146 (42S02): Table 'game_usercenter_01._game_player_10_ghc' doesn't exist
2025-07-22 14:50:08 ERROR Error 1146 (42S02): Table 'game_usercenter_01.game_player_10_ghc' doesn't exist
Copy: 12002122/12002122 100.0%; Applied: 0; Backlog: 0/1000; Time: 7m35s(total), 7m33s(copy); streamer: mysql-bin.000027:815225489; Lag: 0.01s, HeartbeatLag: 0.11s, State: migrating; ETA: due
2025-07-22 14:50:08 INFO Copy: 12002122/12002122 100.0%; Applied: 0; Backlog: 0/1000; Time: 7m35s(total), 7m33s(copy); streamer: mysql-bin.000027:815225489; Lag: 0.01s, HeartbeatLag: 0.11s, State: migrating; ETA: due []
2025-07-22 14:50:08 ERROR Error 1146 (42S02): Table 'game_usercenter_01._game_player_10_ghc' doesn't exist
2025-07-22 14:50:08 ERROR Error 1146 (42S02): Table 'game_usercenter_01._game_player_10_ghc' doesn't exist
2025-07-22 14:50:08 INFO Table dropped
2025-07-22 14:50:08 INFO Done migrating game_usercenter_01.game_player_10
2025-07-22 14:50:08 INFO Removing socket file: /tmp/gh-ost.game_usercenter_01.game_player_10.sock
2025-07-22 14:50:08 INFO Tearing down inspector
2025-07-22 14:50:08 INFO Tearing down applier
2025-07-22 14:50:08 INFO Tearing down streamer
2025-07-22 14:50:08 INFO Tearing down throttler
Done
In our platform code, we will check if gh-ost run success by checking the log, if there are ERROR messages our code will treat the gh-ost job run failed.
please have a look and check why above job printed Error messages, and how to avoid print the error message , thanks a lot