ERROR Error 1048: Column 'guid' cannot be null

[zafermalik]

@shlomi-noach I am facing below issue when using gh-ost, may you please help to debug it if possible.

I am using gh-ost version 1.0.48 mysql version is 5.7.34 binlog_row_image is FULL

I am using below command- ./gh-ost --max-load=threads_connected=200,threads_running=25 --chunk-size=500 --allow-on-master --throttle-control-replicas="10.1.1.1:3306,10.1.1.2:3306,10.1.1.3:3306" --max-lag-millis=2000 --port=3306 --user=ghostusr --password=********* --host=... --database=warehouse --table=batch --verbose --alter="ADD INDEX ix_settletime_type(settletime,type)" --cut-over=default --default-retries=120 --nice-ratio=0 --throttle-flag-file=/tmp/gh-ost.throttle --panic-flag-file=/tmp/ghost.panic.flag --postpone-cut-over-flag-file=/tmp/ghost.postpone.flag --execute 1> /tmp/ghost.out 2>/tmp/ghost.err

As per ghost.err file (also updating complete output below), complete data was copied at "2021-09-02 08:26:26 INFO Row copy complete" successfully and same time ghost.out file generated message "State: postponing cut-over; ETA: due" means everything was fine for cut-over but as I tried to verify ghost.err file before taking cut-over got this error "2021-09-02 08:30:01 ERROR Error 1048: Column 'guid' cannot be null;" means after 4 minutes. May you help me to identify why this happened. I tried 3 times and each time getting same issue.

Table structure is-

CREATE TABLE `batch` (
  `uid` int(10) unsigned NOT NULL AUTO_INCREMENT COMMENT 'Primary Key Value',
  `guid` char(15) NOT NULL COMMENT 'Application assigned batch guid',
  `client_uid` int(10) unsigned NOT NULL COMMENT 'Client Id',
  `name` varchar(25) NOT NULL COMMENT 'Customer provided batch name',
  `type` tinyint(4) NOT NULL COMMENT 'Batch type 0 - non-financial 1 - credit 2 - debit',
  `status` tinyint(4) NOT NULL COMMENT 'Batch status 0 - open 1 - closed 2 - hold 3 - pre-settle 4 - settled',
  `closedby` char(6) DEFAULT NULL COMMENT 'Identifies who closed batch system or client',
  `opentime` datetime NOT NULL COMMENT 'The Date the batch was opened',
  `closetime` datetime DEFAULT NULL COMMENT 'Batch close time',
  `settletime` datetime DEFAULT NULL COMMENT 'Batch settle time',
  `dbtime` timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP ON UPDATE CURRENT_TIMESTAMP COMMENT 'Database insert time',
  `who` varchar(30) NOT NULL COMMENT 'Insert user and machine name',
  PRIMARY KEY (`uid`),
  UNIQUE KEY `ix_guid` (`guid`),
  KEY `ix_client_uid` (`client_uid`),
  KEY `ix_name` (`name`),
  KEY `ix_status` (`status`),
  KEY `ix_settletime` (`settletime`),
  KEY `ix_opentime` (`opentime`),
  KEY `ix_type` (`type`)
) ENGINE=InnoDB AUTO_INCREMENT=40520073 DEFAULT CHARSET=utf8;

ghost.err file output is-

2021-09-02 08:20:56 INFO starting gh-ost 1.0.48
2021-09-02 08:20:56 INFO Migrating `warehouse`.`batch`
2021-09-02 08:20:56 INFO connection validated on 10.1.1.1:3306
2021-09-02 08:20:56 INFO User has REPLICATION CLIENT, REPLICATION SLAVE privileges, and has ALL privileges on `warehouse`.*
2021-09-02 08:20:56 INFO binary logs validated on 10.1.1.1:3306
2021-09-02 08:20:56 INFO Restarting replication on 10.1.1.1:3306 to make sure binlog settings apply to replication thread
2021-09-02 08:20:56 INFO Inspector initiated on xxxxxx.com:3306, version 5.7.34-log
2021-09-02 08:20:56 INFO Table found. Engine=InnoDB
2021-09-02 08:20:56 INFO Estimated number of rows via EXPLAIN: 5127232
2021-09-02 08:20:56 INFO Recursively searching for replication master
2021-09-02 08:20:56 INFO Master found to be xxxxx.com:3306
2021-09-02 08:20:56 INFO log_slave_updates validated on 10.1.1.1:3306
2021-09-02 08:20:56 INFO connection validated on 10.1.1.1:3306
2021-09-02 08:20:56 INFO Connecting binlog streamer at mysql-bin.004304:923988
2021-09-02 08:20:56 INFO connection validated on 10.1.1.1:3306
2021-09-02 08:20:56 INFO connection validated on 10.1.1.1:3306
2021-09-02 08:20:56 INFO will use time_zone='SYSTEM' on applier
2021-09-02 08:20:56 INFO Examining table structure on applier
2021-09-02 08:20:56 INFO Applier initiated on xxxxxxx.com:3306, version 5.7.34--log
2021-09-02 08:20:56 INFO Dropping table `warehouse`.`_batch_ghc`
2021-09-02 08:20:56 INFO Table dropped
2021-09-02 08:20:56 INFO Creating changelog table `warehouse`.`_batch_ghc`
2021-09-02 08:20:56 INFO rotate to next log from mysql-bin.004304:0 to mysql-bin.004304
2021-09-02 08:20:56 INFO Changelog table created
2021-09-02 08:20:56 INFO Creating ghost table `warehouse`.`_batch_gho`
2021-09-02 08:20:56 INFO Ghost table created
2021-09-02 08:20:56 INFO Altering ghost table `warehouse`.`_batch_gho`
2021-09-02 08:20:56 INFO Ghost table altered
2021-09-02 08:20:56 INFO Intercepted changelog state GhostTableMigrated
2021-09-02 08:20:56 INFO Waiting for ghost table to be migrated. Current lag is 0s
2021-09-02 08:20:56 INFO Handled changelog state GhostTableMigrated
2021-09-02 08:20:56 INFO Chosen shared unique key is PRIMARY
2021-09-02 08:20:56 INFO Shared columns are uid,guid,client_uid,name,type,status,closedby,opentime,closetime,settletime,dbtime,who
2021-09-02 08:20:56 INFO Listening on unix socket file: /tmp/gh-ost.warehouse.batch.sock
2021-09-02 08:20:56 INFO Migration min values: [24747176]
2021-09-02 08:20:56 INFO Migration max values: [40522872]
2021-09-02 08:20:56 INFO Waiting for first throttle metrics to be collected
2021-09-02 08:20:56 INFO First throttle metrics collected
2021-09-02 08:23:45 INFO rotate to next log from mysql-bin.004305:268453047 to mysql-bin.004305
2021-09-02 08:23:45 INFO rotate to next log from mysql-bin.004305:0 to mysql-bin.004305
2021-09-02 08:26:26 INFO Row copy complete
2021-09-02 08:30:01 ERROR Error 1048: Column 'guid' cannot be null; query=
                        replace /* gh-ost `warehouse`.`_batch_gho` */ into
                                `warehouse`.`_batch_gho`
                                        (`uid`, `guid`, `client_uid`, `name`, `type`, `status`, `closedby`, `opentime`, `closetime`, `settletime`, `dbtime`, `who`)
                                values
                                        (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?)
                ; args=[<nil> <nil> <nil> <nil> <nil> 2 System <nil> 2021-09-02 08:30:00 <nil> 2021-09-02 08:30:00 +0000 UTC <nil>]

ghost.out file last output is-

Copy: 5123000/5127232 99.9%; Applied: 4; Backlog: 0/1000; Time: 5m23s(total), 5m23s(copy); streamer: mysql-bin.004305:215096234; State: migrating; E
TA: 0s
Copy: 5238104/5238104 100.0%; Applied: 4; Backlog: 0/1000; Time: 5m30s(total), 5m29s(copy); streamer: mysql-bin.004305:225903899; State: migrating;
ETA: due
Copy: 5238104/5238104 100.0%; Applied: 4; Backlog: 0/1000; Time: 5m30s(total), 5m29s(copy); streamer: mysql-bin.004305:225913107; State: postponing
cut-over; ETA: due