MySQL Bugs: #96986: Column Ordinal Position Not orderly updating

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) )

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.

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)

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.

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..

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)

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 ?

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]

Hi,

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