Bug #96986 Column Ordinal Position Not orderly updating

Submitted: 24 Sep 2019 7:21 Modified: 25 Oct 2019 9:55
Reporter: pon suresh pandian soundara rajan Email Updates:
Status: Can't repeat Impact on me:
None 
Category:MySQL Server: Replication Severity:S1 (Critical)
Version:8.0.17 OS:CentOS (7.4 )
Assigned to: MySQL Verification Team CPU Architecture:x86 (CentOS Linux release 7.4.1708 (Core) )

[24 Sep 2019 7:21] pon suresh pandian soundara rajan 
Description:
Hi Team,

Currently our production mysql is running in mysql latest version 8.0.17 (MySQL Community Server).

I have a one master i created one slave server under my production master server.

I configured the replication based on file name & Position.After some time this replication will be broken.

I have checked the slave status i am getting below error.

Error :
------

Column 19 of table cannot be converted from type 'varchar(900(bytes))' to type 'int(11)'

Fix :

I have checked the both master & slave server both servers have a same table structure.And tried with slave type conversion method also.it will not work.

So i decoded my relay log in slave and find the position where it's exactly stopped.

I found the column ordinal position was not incrementing properly.

Relay log :
---------

### INSERT INTO `accounts`.`people`
### SET
###   @1=101501932 /* LONGINT meta=0 nullable=0 is_null=0 */
###   @2='xyz' /* VARSTRING(900) meta=900 nullable=1 is_null=0 */
###   @3=NULL /* VARSTRING(300) meta=300 nullable=1 is_null=1 */
###   @4=NULL /* VARSTRING(150) meta=150 nullable=1 is_null=1 */
###   @5=NULL /* VARSTRING(900) meta=900 nullable=1 is_null=1 */
###   @6=NULL /* INT meta=0 nullable=1 is_null=1 */
###   @7=NULL /* VARSTRING(6) meta=6 nullable=1 is_null=1 */
###   @8='User' /* VARSTRING(120) meta=120 nullable=1 is_null=0 */
###   @9='2019-08-25 18:28:08' /* DATETIME(0) meta=0 nullable=1 is_null=0 */
###   @10='2019-08-25 18:28:08' /* DATETIME(0) meta=0 nullable=1 is_null=0 */
###   @11=NULL /* VARSTRING(120) meta=120 nullable=1 is_null=1 */
###   @12=NULL /* DATETIME(0) meta=0 nullable=1 is_null=1 */
###   @13=NULL /* DATETIME(0) meta=0 nullable=1 is_null=1 */
###   @14=NULL /* VARSTRING(300) meta=300 nullable=1 is_null=1 */
###   @15='www.xyz.sa' /* VARSTRING(300) meta=300 nullable=0 is_null=0 */
###   @16=0 /* INT meta=0 nullable=1 is_null=0 */
###   @17='air' /* VARSTRING(300) meta=300 nullable=1 is_null=0 */
###   @18=NULL /* VARSTRING(3) meta=3 nullable=1 is_null=1 */
###   @19=NULL /* DECIMAL(10,0) meta=2560 nullable=1 is_null=1 */
###   @22=0 /* INT meta=0 nullable=0 is_null=0 */
###   @23=NULL /* INT meta=0 nullable=1 is_null=1 */
###   @24=NULL /* VARSTRING(300) meta=300 nullable=1 is_null=1 */
# at 29310

How to repeat:
I tested my local and ,Here i mentioned my table structure to repeat this issue.

Table Structure :
----------------

CREATE TABLE `people` (
  `id` bigint(20) NOT NULL AUTO_INCREMENT,
  `username` varchar(300) DEFAULT NULL,
  `password` varchar(100) DEFAULT NULL,
  `openid_url` varchar(50) DEFAULT NULL,
  `screen_name` varchar(300) DEFAULT NULL,
  `admin_role` int(11) DEFAULT NULL,
  `registration_confirmed` varchar(2) DEFAULT NULL,
  `type` varchar(40) DEFAULT NULL,
  `created_at` datetime DEFAULT NULL,
  `updated_at` datetime DEFAULT NULL,
  `status` varchar(40) DEFAULT NULL,
  `activation_date_time` datetime DEFAULT NULL,
  `last_login_date_time` datetime DEFAULT NULL,
  `api_key` varchar(100) DEFAULT NULL,
  `domain` varchar(100) NOT NULL DEFAULT 'cleartrip.com',
  `marketing_subscription` int(11) DEFAULT '0',
  `source_of_registration` varchar(100) DEFAULT NULL,
  `bonvoyage_subscription` varchar(1) DEFAULT NULL,
  `token` decimal(10,0) DEFAULT NULL,
  `partner` int(11) NOT NULL DEFAULT '0',
  `partner_id` int(11) DEFAULT NULL,
  `partners_password` varchar(100) DEFAULT NULL,
  PRIMARY KEY (`id`),
  UNIQUE KEY `peoples_pk` (`id`),
  KEY `people_index1` (`api_key`),
  KEY `people_index2` (`domain`),
  KEY `people_index3` (`activation_date_time`),
  KEY `people_index4` (`last_login_date_time`),
  KEY `people_index5` (`status`),
  KEY `people_index6` (`created_at`),
  KEY `people_index7` (`updated_at`),
  KEY `people_index8` (`marketing_subscription`),
  KEY `people_index9` (`source_of_registration`),
  KEY `people_type_idx1` (`type`),
  KEY `people_uk2` (`username`),
  KEY `ppl_screen_name_idx` (`screen_name`),
  KEY `people_index15` (`partner`),
  KEY `people_index16` (`partner_id`),
  KEY `people_lower_username_index` ((lower(`username`))),
  KEY `people_lower_screen_name_index` ((lower(`screen_name`)))
) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4;

After creating this table I checked the ordinal position.It's look's fine.

mysql> select ORDINAL_POSITION,TABLE_NAME from information_schema.columns where table_name='people' order by ORDINAL_POSITION;
+------------------+------------+
| ORDINAL_POSITION | TABLE_NAME |
+------------------+------------+
|                1 | people     |
|                2 | people     |
|                3 | people     |
|                4 | people     |
|                5 | people     |
|                6 | people     |
|                7 | people     |
|                8 | people     |
|                9 | people     |
|               10 | people     |
|               11 | people     |
|               12 | people     |
|               13 | people     |
|               14 | people     |
|               15 | people     |
|               16 | people     |
|               17 | people     |
|               18 | people     |
|               19 | people     |
|               20 | people     |
|               21 | people     |
|               22 | people     |
+------------------+------------+
22 rows in set (0.00 sec)

But i have added few more columns  in people table and again checked the ordinal position.

mysql> alter table people add column test_1 varchar(20);
Query OK, 0 rows affected (0.04 sec)
Records: 0  Duplicates: 0  Warnings: 0

mysql> alter table people add column test_2 varchar(20);
Query OK, 0 rows affected (0.05 sec)
Records: 0  Duplicates: 0  Warnings: 0

mysql> alter table people add column test_3 varchar(20);
Query OK, 0 rows affected (0.04 sec)
Records: 0  Duplicates: 0  Warnings: 0

mysql> alter table people add column test_4 varchar(20);
Query OK, 0 rows affected (0.03 sec)
Records: 0  Duplicates: 0  Warnings: 0

mysql> select ORDINAL_POSITION,TABLE_NAME from information_schema.columns where table_name='people' order by ORDINAL_POSITION;
+------------------+------------+
| ORDINAL_POSITION | TABLE_NAME |
+------------------+------------+
|                1 | people     |
|                2 | people     |
|                3 | people     |
|                4 | people     |
|                5 | people     |
|                6 | people     |
|                7 | people     |
|                8 | people     |
|                9 | people     |
|               10 | people     |
|               11 | people     |
|               12 | people     |
|               13 | people     |
|               14 | people     |
|               15 | people     |
|               16 | people     |
|               17 | people     |
|               18 | people     |
|               19 | people     |
|               20 | people     |
|               21 | people     |
|               22 | people     |
|               25 | people     |
|               26 | people     |
|               27 | people     |
|               28 | people     |
+------------------+------------+
26 rows in set (0.00 sec)

I dropped and recreated the columns then also facing same issue.

Logs:
------

mysql> alter table people add column test_1 varchar(10);
Query OK, 0 rows affected (0.04 sec)
Records: 0  Duplicates: 0  Warnings: 0

mysql> alter table people add column test_2 varchar(10);
Query OK, 0 rows affected (0.04 sec)
Records: 0  Duplicates: 0  Warnings: 0

mysql> alter table people add column test_3 varchar(10);
Query OK, 0 rows affected (0.03 sec)
Records: 0  Duplicates: 0  Warnings: 0

mysql> select ORDINAL_POSITION,TABLE_NAME from information_schema.columns where table_name='people' order by ORDINAL_POSITION;
+------------------+------------+
| ORDINAL_POSITION | TABLE_NAME |
+------------------+------------+
|                1 | people     |
|                2 | people     |
|                3 | people     |
|                4 | people     |
|                5 | people     |
|                6 | people     |
|                7 | people     |
|                8 | people     |
|                9 | people     |
|               10 | people     |
|               11 | people     |
|               12 | people     |
|               13 | people     |
|               14 | people     |
|               15 | people     |
|               16 | people     |
|               17 | people     |
|               18 | people     |
|               19 | people     |
|               20 | people     |
|               21 | people     |
|               22 | people     |
|               25 | people     |
|               26 | people     |
|               27 | people     |
+------------------+------------+
25 rows in set (0.01 sec)

The ordinal position 23 & 24 are missing.Kindly let me know how to fix this issue.
[24 Sep 2019 9:21] Tsubasa Tanaka 
I can reproduce behavior of "ordinal_position" is skipped.
This maybe caused by expression-index.
I can see ordinal_position=22 in ibd2sdi output like this.

```
$ ibd2sdi /path/to/people.ibd | less
..
            {
                "name": "5945be6e841c5d99c61623f402375978",
                "type": 16,
                "is_nullable": true,
                "is_zerofill": false,
                "is_unsigned": false,
                "is_auto_increment": false,
                "is_virtual": true,
                "hidden": 3,
                "ordinal_position": 23,
                "char_length": 1200,
                "numeric_precision": 0,
                "numeric_scale": 0,
                "numeric_scale_null": true,
                "datetime_precision": 0,
                "datetime_precision_null": 1,
                "has_no_default": false,
                "default_value_null": true,
                "srs_id_null": true,
                "srs_id": 0,
                "default_value": "",
                "default_value_utf8_null": true,
                "default_value_utf8": "",
                "default_option": "",
                "update_option": "",
                "comment": "",
                "generation_expression": "lower(`username`)",
                "generation_expression_utf8": "lower(`username`)",
                "options": "interval_count=0;",
                "se_private_data": "table_id=1086;",
                "column_key": 4,
                "column_type_utf8": "varchar(300)",
                "elements": [],
                "collation_id": 255,
                "is_explicit_collation": false
            },
..
```

And I can NOT reproduce to break a replication slave.
Master correctly outputted ordinal_position (skipping @23, @24 collectly)

IMHO, tool like flexview and gh-ost effected this behavior.
Do you use like them?

```
$ mysqlbinlog -vv /usr/mysql/8.0.17/data/bin.000015
..
### INSERT INTO `d1`.`people`
### SET
###   @1=2 /* LONGINT meta=0 nullable=0 is_null=0 */
###   @2=NULL /* VARSTRING(1200) meta=1200 nullable=1 is_null=1 */
###   @3=NULL /* VARSTRING(400) meta=400 nullable=1 is_null=1 */
###   @4=NULL /* VARSTRING(200) meta=200 nullable=1 is_null=1 */
###   @5=NULL /* VARSTRING(1200) meta=1200 nullable=1 is_null=1 */
###   @6=NULL /* INT meta=0 nullable=1 is_null=1 */
###   @7=NULL /* VARSTRING(8) meta=8 nullable=1 is_null=1 */
###   @8=NULL /* VARSTRING(160) meta=160 nullable=1 is_null=1 */
###   @9=NULL /* DATETIME(0) meta=0 nullable=1 is_null=1 */
###   @10=NULL /* DATETIME(0) meta=0 nullable=1 is_null=1 */
###   @11=NULL /* VARSTRING(160) meta=160 nullable=1 is_null=1 */
###   @12=NULL /* DATETIME(0) meta=0 nullable=1 is_null=1 */
###   @13=NULL /* DATETIME(0) meta=0 nullable=1 is_null=1 */
###   @14=NULL /* VARSTRING(400) meta=400 nullable=1 is_null=1 */
###   @15='cleartrip.com' /* VARSTRING(400) meta=400 nullable=0 is_null=0 */
###   @16=0 /* INT meta=0 nullable=1 is_null=0 */
###   @17=NULL /* VARSTRING(400) meta=400 nullable=1 is_null=1 */
###   @18=NULL /* VARSTRING(4) meta=4 nullable=1 is_null=1 */
###   @19=NULL /* DECIMAL(10,0) meta=2560 nullable=1 is_null=1 */
###   @20=0 /* INT meta=0 nullable=0 is_null=0 */
###   @21=NULL /* INT meta=0 nullable=1 is_null=1 */
###   @22=NULL /* VARSTRING(400) meta=400 nullable=1 is_null=1 */
###   @25=NULL /* VARSTRING(80) meta=80 nullable=1 is_null=1 */
###   @26=NULL /* VARSTRING(80) meta=80 nullable=1 is_null=1 */
###   @27=NULL /* VARSTRING(80) meta=80 nullable=1 is_null=1 */
###   @28=NULL /* VARSTRING(80) meta=80 nullable=1 is_null=1 */
..
```

(I'm not oracle person)
[1 Oct 2019 12:05] pon suresh pandian soundara rajan 
Hi tsubasa tanaka,

I have taken a logical backup and restored into slave, then configured the replication still the ordinal position was not properly updated and it's causing the replication breakage .

I am not using IMHO kind of tools.

Kindly provide the solution for this issue.
[7 Oct 2019 2:57] Tsubasa Tanaka 
I found a scenario for this issue leads to break replication.

1. Add column to master's table which has expression-index.
2. Get logical-backup(mysqldump, mysqlpump, myloader, etc.) from master.
3. Restore logical-backup to slave and configure replication-settings.
4. START SLAVE and UPDATE master's table, then replication breaks down.

I seem this is Critical issue..
[7 Oct 2019 2:58] Tsubasa Tanaka 
How to reproduce.

---

# Setup 2 instances

$ docker run -d -e MYSQL_ALLOW_EMPTY_PASSWORD=1 -e MYSQL_ROOT_PASSWORD="""" -e MYSQL_ROOT_HOST=""%"" --name=master mysql/mysql-server:8.0 --server-id=111
  -> 172.17.0.3 is assigned.

$ docker run -d -e MYSQL_ALLOW_EMPTY_PASSWORD=1 -e MYSQL_ROOT_PASSWORD="""" -e MYSQL_ROOT_HOST=""%"" --name=slave mysql/mysql-server:8.0 --server-id=112
  -> 172.17.0.4 is assigned.

## Step 1.

$ mysql -h172.17.0.3 -uroot --prompt="master> "

master> CREATE DATABASE d1;
Query OK, 1 row affected (0.00 sec)

master> CREATE TABLE d1.t1 (num INT PRIMARY KEY, KEY((num < 100)));
Query OK, 0 rows affected (0.01 sec)

master> ALTER TABLE d1.t1 ADD COLUMN val varchar(32);
Query OK, 0 rows affected (0.02 sec)
Records: 0  Duplicates: 0  Warnings: 0

master> SHOW CREATE TABLE d1.t1\G
*************************** 1. row ***************************
       Table: t1
Create Table: CREATE TABLE `t1` (
  `num` int(11) NOT NULL,
  `val` varchar(32) DEFAULT NULL,
  PRIMARY KEY (`num`),
  KEY `functional_index` (((`num` < 100)))
) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_0900_ai_ci
1 row in set (0.00 sec)

master> SELECT @@binlog_format;
+-----------------+
| @@binlog_format |
+-----------------+
| ROW             |
+-----------------+
1 row in set (0.00 sec)

master> SHOW MASTER STATUS;
+---------------+----------+--------------+------------------+-------------------+
| File          | Position | Binlog_Do_DB | Binlog_Ignore_DB | Executed_Gtid_Set |
+---------------+----------+--------------+------------------+-------------------+
| binlog.000002 |      754 |              |                  |                   |
+---------------+----------+--------------+------------------+-------------------+
1 row in set (0.00 sec)

master> quit
Bye

## Step 2 and 3.

$ mysqldump -h172.17.0.3 -uroot --all-databases | mysql -h172.17.0.4 -uroot

$ mysql -h172.17.0.4 -uroot --prompt="slave> "

slave> CHANGE MASTER TO master_host= '172.17.0.3', master_port= 3306, master_user= 'root', master_log_file= 'binlog.000002', master_log_pos= 754;
Query OK, 0 rows affected, 1 warning (0.04 sec)

slave> START SLAVE;
Query OK, 0 rows affected (0.02 sec)

slave> SHOW SLAVE STATUS\G
*************************** 1. row ***************************
               Slave_IO_State: Waiting for master to send event
                  Master_Host: 172.17.0.3
                  Master_User: root
                  Master_Port: 3306
                Connect_Retry: 60
              Master_Log_File: binlog.000002
          Read_Master_Log_Pos: 754
               Relay_Log_File: f604d4e7a1ae-relay-bin.000002
                Relay_Log_Pos: 319
        Relay_Master_Log_File: binlog.000002
             Slave_IO_Running: Yes
            Slave_SQL_Running: Yes
              Replicate_Do_DB:
          Replicate_Ignore_DB:
           Replicate_Do_Table:
       Replicate_Ignore_Table:
      Replicate_Wild_Do_Table:
  Replicate_Wild_Ignore_Table:
                   Last_Errno: 0
                   Last_Error:
                 Skip_Counter: 0
          Exec_Master_Log_Pos: 754
              Relay_Log_Space: 534
              Until_Condition: None
               Until_Log_File:
                Until_Log_Pos: 0
           Master_SSL_Allowed: No
           Master_SSL_CA_File:
           Master_SSL_CA_Path:
              Master_SSL_Cert:
            Master_SSL_Cipher:
               Master_SSL_Key:
        Seconds_Behind_Master: 0
Master_SSL_Verify_Server_Cert: No
                Last_IO_Errno: 0
                Last_IO_Error:
               Last_SQL_Errno: 0
               Last_SQL_Error:
  Replicate_Ignore_Server_Ids:
             Master_Server_Id: 111
                  Master_UUID: a7646d86-e8ad-11e9-8827-0242ac110003
             Master_Info_File: mysql.slave_master_info
                    SQL_Delay: 0
          SQL_Remaining_Delay: NULL
      Slave_SQL_Running_State: Slave has read all relay log; waiting for more updates
           Master_Retry_Count: 86400
                  Master_Bind:
      Last_IO_Error_Timestamp:
     Last_SQL_Error_Timestamp:
               Master_SSL_Crl:
           Master_SSL_Crlpath:
           Retrieved_Gtid_Set:
            Executed_Gtid_Set:
                Auto_Position: 0
         Replicate_Rewrite_DB:
                 Channel_Name:
           Master_TLS_Version:
       Master_public_key_path:
        Get_master_public_key: 0
            Network_Namespace:
1 row in set (0.00 sec)

slave> quit
Bye

## Step 4.

$ mysql -h172.17.0.3 -uroot --prompt="master> "

master> INSERT INTO d1.t1 VALUES (1, 'one');
Query OK, 1 row affected (0.01 sec)

master> SELECT * FROM d1.t1;
+-----+------+
| num | val  |
+-----+------+
|   1 | one  |
+-----+------+
1 row in set (0.00 sec)

master> quit
Bye

$ mysql -h172.17.0.4 -uroot --prompt="slave> "

slave> SHOW SLAVE STATUS\G
*************************** 1. row ***************************
               Slave_IO_State: Waiting for master to send event
                  Master_Host: 172.17.0.3
                  Master_User: root
                  Master_Port: 3306
                Connect_Retry: 60
              Master_Log_File: binlog.000002
          Read_Master_Log_Pos: 1034
               Relay_Log_File: f604d4e7a1ae-relay-bin.000002
                Relay_Log_Pos: 319
        Relay_Master_Log_File: binlog.000002
             Slave_IO_Running: Yes
            Slave_SQL_Running: No
              Replicate_Do_DB:
          Replicate_Ignore_DB:
           Replicate_Do_Table:
       Replicate_Ignore_Table:
      Replicate_Wild_Do_Table:
  Replicate_Wild_Ignore_Table:
                   Last_Errno: 13146
                   Last_Error: Column 1 of table 'd1.t1' cannot be converted from type 'int' to type 'varchar(128(bytes) utf8mb4)'
                 Skip_Counter: 0
          Exec_Master_Log_Pos: 754
              Relay_Log_Space: 814
              Until_Condition: None
               Until_Log_File:
                Until_Log_Pos: 0
           Master_SSL_Allowed: No
           Master_SSL_CA_File:
           Master_SSL_CA_Path:
              Master_SSL_Cert:
            Master_SSL_Cipher:
               Master_SSL_Key:
        Seconds_Behind_Master: NULL
Master_SSL_Verify_Server_Cert: No
                Last_IO_Errno: 0
                Last_IO_Error:
               Last_SQL_Errno: 13146
               Last_SQL_Error: Column 1 of table 'd1.t1' cannot be converted from type 'int' to type 'varchar(128(bytes) utf8mb4)'
  Replicate_Ignore_Server_Ids:
             Master_Server_Id: 111
                  Master_UUID: a7646d86-e8ad-11e9-8827-0242ac110003
             Master_Info_File: mysql.slave_master_info
                    SQL_Delay: 0
          SQL_Remaining_Delay: NULL
      Slave_SQL_Running_State:
           Master_Retry_Count: 86400
                  Master_Bind:
      Last_IO_Error_Timestamp:
     Last_SQL_Error_Timestamp: 191007 02:56:23
               Master_SSL_Crl:
           Master_SSL_Crlpath:
           Retrieved_Gtid_Set:
            Executed_Gtid_Set:
                Auto_Position: 0
         Replicate_Rewrite_DB:
                 Channel_Name:
           Master_TLS_Version:
       Master_public_key_path:
        Get_master_public_key: 0
            Network_Namespace:
1 row in set (0.00 sec)
[9 Oct 2019 8:13] pon suresh pandian soundara rajan 
Hi  tsubasa tanaka,

can you check the ordinal position for t1 table from both master & slave servers 

I think in both server it seems different ?
[9 Oct 2019 19:41] Shane Bester 
somebody could test if this is fixed in 8.0.18 by:

http://bugs.mysql.com/bug.php?id=94225
[Replication is sensitive to order of hidden columns for functional indexes]
[25 Oct 2019 9:55] MySQL Verification Team 
Hi,

Cannot reproduce this with 8.0.18.
Most probably fixed with http://bugs.mysql.com/bug.php?id=94225 fix.

Portions of this website are copyright © 2001, 2002 The PHP Group

Page generated in 0.062 sec. using MySQL 8.4.7-u6-cloud

Timestamp references displayed by the system are UTC.
Content reproduced on this site is the property of the respective copyright holders.
It is not reviewed in advance by Oracle and does not necessarily represent the opinion of Oracle or any other party.