Uploaded image for project: 'MariaDB Server'
  1. MariaDB Server
  2. MDEV-30311

system-wide max transaction id corrupted (from MySQL-5.7 upgrade)

Details

    Description

      $ docker run -v  m57:/var/lib/mysql:Z -e MYSQL_INITDB_SKIP_TZINFO=1 -e MYSQL_ROOT_PASSWORD=bob --rm  docker.io/library/mysql:5.7
      2022-12-28 00:12:20+00:00 [Note] [Entrypoint]: Entrypoint script for MySQL Server 5.7.40-1.el7 started.
      ...
      $ podman exec jovial_hertz mysql -u root -pbob -e "set global innodb_fast_shutdown=0;SHUTDOWN"
      

      Use same volume in MariaDB:

      11.0.0+1cb0835be98985f20cccd1724ac78de3649eb2e6

      $ podman run --env   MARIADB_AUTO_UPGRADE=1 -v m57:/var/lib/mysql:Z --user mysql mariadb-31171 bash -x -v docker-entrypoint.sh mariadbd
      #!/bin/bash
      set -eo pipefail
      ....
      + mariadbd --skip-grant-tables --loose-innodb_buffer_pool_dump_at_shutdown=0 --skip-slave-start --skip-networking --default-time-zone=SYSTEM --socket=/run/mysqld/mysqld.sock --wsrep_on=OFF --expire-logs-days=0 --loose-innodb_buffer_pool_load_at_startup=0
      ++ date --rfc-3339=seconds
      + printf '%s [%s] [Entrypoint]: %s\n' '2022-12-28 00:23:36+00:00' Note 'Waiting for server startup'
      2022-12-28 00:23:36+00:00 [Note] [Entrypoint]: Waiting for server startup
      + extraArgs=()
      + '[' -z true ']'
      + local i
      + for i in {30..0}
      + docker_process_sql --database=mysql
      + sleep 1
      2022-12-28  0:23:36 0 [Note] mariadbd (server 11.0.0-MariaDB-1:11.0.0+maria~ubu2204) starting as process 106 ...
      2022-12-28  0:23:36 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
      2022-12-28  0:23:36 0 [Note] InnoDB: Number of transaction pools: 1
      2022-12-28  0:23:36 0 [Note] InnoDB: Using crc32 + pclmulqdq instructions
      2022-12-28  0:23:36 0 [Note] mariadbd: O_TMPFILE is not supported on /tmp (disabling future attempts)
      2022-12-28  0:23:36 0 [Warning] mariadbd: io_uring_queue_init() failed with ENOSYS: check seccomp filters, and the kernel version (newer than 5.1 required)
      2022-12-28  0:23:36 0 [Warning] InnoDB: liburing disabled: falling back to innodb_use_native_aio=OFF
      2022-12-28  0:23:36 0 [Note] InnoDB: Initializing buffer pool, total size = 128.000MiB, chunk size = 2.000MiB
      2022-12-28  0:23:36 0 [Note] InnoDB: Completed initialization of buffer pool
      2022-12-28  0:23:36 0 [Note] InnoDB: Resetting space id's in the doublewrite buffer
      2022-12-28  0:23:36 0 [Note] InnoDB: Buffered log writes (block size=512 bytes)
      2022-12-28  0:23:36 0 [Note] InnoDB: Opened 3 undo tablespaces
      2022-12-28  0:23:36 0 [Note] InnoDB: 128 rollback segments in 3 undo tablespaces are active.
      2022-12-28  0:23:36 0 [Note] InnoDB: Setting file './ibtmp1' size to 12.000MiB. Physically writing the file full; Please wait ...
      2022-12-28  0:23:36 0 [Note] InnoDB: File './ibtmp1' size is now 12.000MiB.
      2022-12-28  0:23:36 0 [Note] InnoDB: log sequence number 2774559; transaction id 770
      2022-12-28  0:23:36 0 [Note] Plugin 'FEEDBACK' is disabled.
      2022-12-28  0:23:36 0 [ERROR] WSREP: plugin-wsrep-provider can't be enabled if wsrep_on==OFF or wsrep_provider is unset or set to 'none'
      2022-12-28  0:23:36 0 [ERROR] mariadbd: plugin-wsrep-provider can't be enabled if wsrep_on==OFF or wsrep_provider is unset or set to 'none'
      2022-12-28  0:23:36 0 [ERROR] Plugin 'wsrep_provider' init function returned error.
      2022-12-28  0:23:36 1 [Warning] Failed to load slave replication state from table mysql.gtid_slave_pos: 1146: Table 'mysql.gtid_slave_pos' doesn't exist
      2022-12-28  0:23:36 0 [Note] mariadbd: ready for connections.
      Version: '11.0.0-MariaDB-1:11.0.0+maria~ubu2204'  socket: '/run/mysqld/mysqld.sock'  port: 0  mariadb.org binary distribution
      + for i in {30..0}
      + docker_process_sql --database=mysql
      + break
      + '[' 29 = 0 ']'
      + mysql_note 'Temporary server started.'
      + mysql_log Note 'Temporary server started.'
      + local type=Note
      + shift
      ++ date --rfc-3339=seconds
      2022-12-28 00:23:37+00:00 [Note] [Entrypoint]: Temporary server started.
      + printf '%s [%s] [Entrypoint]: %s\n' '2022-12-28 00:23:37+00:00' Note 'Temporary server started.'
      + docker_mariadb_backup_system
      + '[' -n '' ']'
      + local backup_db=system_mysql_backup_unknown_version.sql.zst
      + local oldfullversion=unknown_version
      + '[' -r /var/lib/mysql//mysql_upgrade_info ']'
      + mysql_note 'Backing up system database to system_mysql_backup_unknown_version.sql.zst'
      + mysql_log Note 'Backing up system database to system_mysql_backup_unknown_version.sql.zst'
      + local type=Note
      + shift
      ++ date --rfc-3339=seconds
      2022-12-28 00:23:37+00:00 [Note] [Entrypoint]: Backing up system database to system_mysql_backup_unknown_version.sql.zst
      + printf '%s [%s] [Entrypoint]: %s\n' '2022-12-28 00:23:37+00:00' Note 'Backing up system database to system_mysql_backup_unknown_version.sql.zst'
      + zstd
      + mariadb-dump --skip-lock-tables --replace --databases mysql --socket=/run/mysqld/mysqld.sock
      2022-12-28  0:23:37 4 [Warning] InnoDB: A transaction id in a record of table `mysql`.`engine_cost` is newer than the system-wide maximum.
      2022-12-28  0:23:37 4 [ERROR] InnoDB: We detected index corruption in an InnoDB type table. You have to dump + drop + reimport the table or, in a case of widespread corruption, dump all InnoDB tables and recreate the whole tablespace. If the mariadbd server crashes after the startup or when you dump the tables. Please refer to https://mariadb.com/kb/en/library/innodb-recovery-modes/ for information about forcing recovery.
      2022-12-28  0:23:37 4 [ERROR] mariadbd: Index for table 'engine_cost' is corrupt; try to repair it
      mariadb-dump: Error 1034: Index for table 'engine_cost' is corrupt; try to repair it when dumping table `engine_cost` at row: 0
      + mysql_error 'Unable backup system database for upgrade from unknown_version.'
      + mysql_log ERROR 'Unable backup system database for upgrade from unknown_version.'
      + local type=ERROR
      + shift
      ++ date --rfc-3339=seconds
      + printf '%s [%s] [Entrypoint]: %s\n' '2022-12-28 00:23:37+00:00' ERROR 'Unable backup system database for upgrade from unknown_version.'
      2022-12-28 00:23:37+00:00 [ERROR] [Entrypoint]: Unable backup system database for upgrade from unknown_version.
      + exit 1
      

      "unknown version" is expected as mysql doesn't generate an automatic mysql_upgrade file.

      From amd64-rhel8-dockerlibrary in bb.

      Attachments

        1. 0001-WIP-test-case.patch
          25 kB
          Marko Mäkelä
        2. ibdata1.gz
          32 kB
          Marko Mäkelä
        3. m57.tar.bz2
          956 kB
          Daniel Black

        Issue Links

          Activity

            danblack Daniel Black added a comment -

            11.0-1cb0835be98985f20cccd1724ac78de3649eb2e6

            sql/mariadbd --no-defaults --skip-grant-tables --loose-innodb_buffer_pool_dump_at_shutdown=0 --skip-slave-start --skip-networking --default-time-zone=SYSTEM --socket=/tmp/mysqld.sock --wsrep_on=OFF --expire-logs-days=0 --loose-innodb_buffer_pool_load_at_startup=0 --datadir=/tmp/m57
            

            dump with

            $ client/mariadb-dump -u root -pbob -S /tmp/mysqld.sock --databases mysql --skip-lock-tables --replace
             
            LOCK TABLES `engine_cost` WRITE;
            /*!40000 ALTER TABLE `engine_cost` DISABLE KEYS */;
            mariadb-dump: Error 1034: Index for table 'engine_cost' is corrupt; try to repair it when dumping table `engine_cost` at row: 0
            

            danblack Daniel Black added a comment - 11.0-1cb0835be98985f20cccd1724ac78de3649eb2e6 sql/mariadbd --no-defaults --skip-grant-tables --loose-innodb_buffer_pool_dump_at_shutdown=0 --skip-slave-start --skip-networking --default-time-zone=SYSTEM --socket=/tmp/mysqld.sock --wsrep_on=OFF --expire-logs-days=0 --loose-innodb_buffer_pool_load_at_startup=0 --datadir=/tmp/m57 dump with $ client/mariadb-dump -u root -pbob -S /tmp/mysqld.sock --databases mysql --skip-lock-tables --replace   LOCK TABLES `engine_cost` WRITE; /*!40000 ALTER TABLE `engine_cost` DISABLE KEYS */; mariadb-dump: Error 1034: Index for table 'engine_cost' is corrupt; try to repair it when dumping table `engine_cost` at row: 0
            danblack Daniel Black added a comment -

            Somehow went away by 11.0-944beb9e7acd53488dbfc7edc09bf29e10ce68ab

            danblack Daniel Black added a comment - Somehow went away by 11.0-944beb9e7acd53488dbfc7edc09bf29e10ce68ab
            danblack Daniel Black added a comment -

            $ d=build-mariadb-server-11.0-datadir; rm -rf $d; mkdir $d; tar -C $d -xf m57.tar.bz2 
             
            $ sql/mariadbd --no-defaults --skip-networking --datadir=/tmp/${PWD##*/}-datadir --socket=/tmp/${PWD##*/}.sock --plugin-dir=${PWD}/mysql-test/var/plugins/ --verbose &
            [1] 239736
             
            ~/repos/build-mariadb-server-11.0 
            $ 2023-02-24 12:21:41 0 [Note] Starting MariaDB 11.0.2-MariaDB source revision b4ef9f766db28d258621aa888fdffd168321e3ba as process 239736
            2023-02-24 12:21:41 0 [Note] InnoDB: Compressed tables use zlib 1.2.12
            2023-02-24 12:21:41 0 [Note] InnoDB: Number of transaction pools: 1
            2023-02-24 12:21:41 0 [Note] InnoDB: Using crc32 + pclmulqdq instructions
            2023-02-24 12:21:41 0 [Note] InnoDB: Using liburing
            2023-02-24 12:21:41 0 [Note] InnoDB: Initializing buffer pool, total size = 128.000MiB, chunk size = 2.000MiB
            2023-02-24 12:21:41 0 [Note] InnoDB: Completed initialization of buffer pool
            2023-02-24 12:21:41 0 [Note] InnoDB: Buffered log writes (block size=512 bytes)
            2023-02-24 12:21:41 0 [Note] InnoDB: Upgrading redo log: 96.000MiB; LSN=2762352
            2023-02-24 12:21:41 0 [Note] InnoDB: Buffered log writes (block size=512 bytes)
            2023-02-24 12:21:41 0 [Note] InnoDB: Upgrading the change buffer
            2023-02-24 12:21:41 0 [Note] InnoDB: Upgraded the change buffer: 0 tablespaces, 0 pages
            2023-02-24 12:21:41 0 [Note] InnoDB: Reinitializing innodb_undo_tablespaces= 3 from 0
            2023-02-24 12:21:41 0 [Note] InnoDB: Setting O_DIRECT on file .//undo001 failed
            2023-02-24 12:21:41 0 [Note] InnoDB: Data file .//undo001 did not exist: new to be created
            2023-02-24 12:21:41 0 [Note] InnoDB: Setting file .//undo001 size to 10.000MiB
            2023-02-24 12:21:41 0 [Note] InnoDB: Database physically writes the file full: wait...
            2023-02-24 12:21:41 0 [Note] InnoDB: Data file .//undo002 did not exist: new to be created
            2023-02-24 12:21:41 0 [Note] InnoDB: Setting file .//undo002 size to 10.000MiB
            2023-02-24 12:21:41 0 [Note] InnoDB: Database physically writes the file full: wait...
            2023-02-24 12:21:41 0 [Note] InnoDB: Data file .//undo003 did not exist: new to be created
            2023-02-24 12:21:41 0 [Note] InnoDB: Setting file .//undo003 size to 10.000MiB
            2023-02-24 12:21:41 0 [Note] InnoDB: Database physically writes the file full: wait...
            2023-02-24 12:21:41 0 [Note] InnoDB: 128 rollback segments in 3 undo tablespaces are active.
            2023-02-24 12:21:41 0 [Note] InnoDB: Setting file './ibtmp1' size to 12.000MiB. Physically writing the file full; Please wait ...
            2023-02-24 12:21:41 0 [Note] InnoDB: File './ibtmp1' size is now 12.000MiB.
            2023-02-24 12:21:41 0 [Note] InnoDB: log sequence number 2762352; transaction id 1794
            2023-02-24 12:21:41 0 [Note] Plugin 'FEEDBACK' is disabled.
            2023-02-24 12:21:41 0 [Note] Plugin 'wsrep-provider' is disabled.
            2023-02-24 12:21:41 0 [Note] InnoDB: Loading buffer pool(s) from /tmp/build-mariadb-server-11.0-datadir/ib_buffer_pool
            2023-02-24 12:21:41 0 [Note] InnoDB: Buffer pool(s) load completed at 230224 12:21:41
            2023-02-24 12:21:41 0 [ERROR] Missing system table mysql.roles_mapping; please run mysql_upgrade to create it
            2023-02-24 12:21:41 0 [ERROR] Incorrect definition of table mysql.event: expected column 'definer' at position 3 to have type varchar(, found type char(93).
            2023-02-24 12:21:41 0 [ERROR] Incorrect definition of table mysql.event: expected column 'sql_mode' at position 14 to have type set('REAL_AS_FLOAT','PIPES_AS_CONCAT','ANSI_QUOTES','IGNORE_SPACE','IGNORE_BAD_TABLE_OPTIONS','ONLY_FULL_GROUP_BY','NO_UNSIGNED_SUBTRACTION','NO_DIR_IN_CREATE','POSTGRESQL','ORACLE','MSSQL','DB2','MAXDB','NO_KEY_OPTIONS','NO_TABLE_OPTIONS','NO_FIELD_OPTIONS','MYSQL323','MYSQL40','ANSI','NO_AUTO_VALUE_ON_ZERO','NO_BACKSLASH_ESCAPES','STRICT_TRANS_TABLES','STRICT_ALL_TABLES','NO_ZERO_IN_DATE','NO_ZERO_DATE','INVALID_DATES','ERROR_FOR_DIVISION_BY_ZERO','TRADITIONAL','NO_AUTO_CREATE_USER','HIGH_NOT_PRECEDENCE','NO_ENGINE_SUBSTITUTION','PAD_CHAR_TO_FULL_LENGTH','EMPTY_STRING_IS_NULL','SIMULTANEOUS_ASSIGNMENT'), found type set('REAL_AS_FLOAT','PIPES_AS_CONCAT','ANSI_QUOTES','IGNORE_SPACE','NOT_USED','ONLY_FULL_GROUP_BY','NO_UNSIGNED_SUBTRACTION','NO_DIR_IN_CREATE','POSTGRESQL','ORACLE','MSSQL','DB2','MAXDB','NO_KEY_OPTIONS','NO_TABLE_OPTIONS','NO_FIELD_OPTIONS','MYSQL323','MYSQL40','ANSI','NO_AUTO_VALUE_ON_ZERO','NO_B
            2023-02-24 12:21:41 0 [ERROR] mariadbd: Event Scheduler: An error occurred when initializing system tables. Disabling the Event Scheduler.
            2023-02-24 12:21:41 1 [Warning] Failed to load slave replication state from table mysql.gtid_slave_pos: 1146: Table 'mysql.gtid_slave_pos' doesn't exist
            2023-02-24 12:21:41 0 [Note] sql/mariadbd: ready for connections.
            Version: '11.0.2-MariaDB'  socket: '/tmp/build-mariadb-server-11.0.sock'  port: 0  Source distribution
            killall mariadbd
            2023-02-24 12:21:46 0 [Note] sql/mariadbd (initiated by: unknown): Normal shutdown
            2023-02-24 12:21:46 0 [Note] InnoDB: FTS optimize thread exiting.
            2023-02-24 12:21:46 0 [Note] InnoDB: Starting shutdown...
            2023-02-24 12:21:46 0 [Note] InnoDB: Dumping buffer pool(s) to /tmp/build-mariadb-server-11.0-datadir/ib_buffer_pool
            2023-02-24 12:21:46 0 [Note] InnoDB: Buffer pool(s) dump completed at 230224 12:21:46
             
            # Note the killall mariadbd was on the promt
             
            ql/mariadbd --no-defaults --skip-networking --datadir=/tmp/${PWD##*/}-datadir --socket=/tmp/${PWD##*/}.sock --plugin-dir=${PWD}/mysql-test/var/plugins/ --verbose & while [ ! -S /tmp/${PWD##*/}.sock ]; do sleep 0.05; done ; client/mariadb-dump --user root -pbob  -S /tmp/${PWD##*/}.sock mysql > /dev/null
            [2] 239807
            2023-02-24 12:21:54 0 [Note] Starting MariaDB 11.0.2-MariaDB source revision b4ef9f766db28d258621aa888fdffd168321e3ba as process 239807
            2023-02-24 12:21:54 0 [Note] InnoDB: Compressed tables use zlib 1.2.12
            2023-02-24 12:21:54 0 [Note] InnoDB: Number of transaction pools: 1
            2023-02-24 12:21:54 0 [Note] InnoDB: Using crc32 + pclmulqdq instructions
            2023-02-24 12:21:54 0 [Note] InnoDB: Using liburing
            2023-02-24 12:21:54 0 [Note] InnoDB: Initializing buffer pool, total size = 128.000MiB, chunk size = 2.000MiB
            2023-02-24 12:21:54 0 [Note] InnoDB: Completed initialization of buffer pool
            2023-02-24 12:21:54 0 [Note] InnoDB: Resetting space id's in the doublewrite buffer
            2023-02-24 12:21:54 0 [Note] InnoDB: Buffered log writes (block size=512 bytes)
            2023-02-24 12:21:54 0 [Note] InnoDB: Opened 3 undo tablespaces
            2023-02-24 12:21:54 0 [Note] InnoDB: 128 rollback segments in 3 undo tablespaces are active.
            2023-02-24 12:21:54 0 [Note] InnoDB: Setting O_DIRECT on file ./ibtmp1 failed
            2023-02-24 12:21:54 0 [Note] InnoDB: Setting file './ibtmp1' size to 12.000MiB. Physically writing the file full; Please wait ...
            2023-02-24 12:21:54 0 [Note] InnoDB: File './ibtmp1' size is now 12.000MiB.
            2023-02-24 12:21:54 0 [Note] InnoDB: log sequence number 2781972; transaction id 770
            2023-02-24 12:21:54 0 [Note] Plugin 'FEEDBACK' is disabled.
            2023-02-24 12:21:54 0 [Note] Plugin 'wsrep-provider' is disabled.
            2023-02-24 12:21:54 0 [Note] InnoDB: Loading buffer pool(s) from /tmp/build-mariadb-server-11.0-datadir/ib_buffer_pool
            2023-02-24 12:21:54 0 [Note] InnoDB: Buffer pool(s) load completed at 230224 12:21:54
            2023-02-24 12:21:54 0 [ERROR] Missing system table mysql.roles_mapping; please run mysql_upgrade to create it
            2023-02-24 12:21:54 0 [ERROR] Incorrect definition of table mysql.event: expected column 'definer' at position 3 to have type varchar(, found type char(93).
            2023-02-24 12:21:54 0 [ERROR] Incorrect definition of table mysql.event: expected column 'sql_mode' at position 14 to have type set('REAL_AS_FLOAT','PIPES_AS_CONCAT','ANSI_QUOTES','IGNORE_SPACE','IGNORE_BAD_TABLE_OPTIONS','ONLY_FULL_GROUP_BY','NO_UNSIGNED_SUBTRACTION','NO_DIR_IN_CREATE','POSTGRESQL','ORACLE','MSSQL','DB2','MAXDB','NO_KEY_OPTIONS','NO_TABLE_OPTIONS','NO_FIELD_OPTIONS','MYSQL323','MYSQL40','ANSI','NO_AUTO_VALUE_ON_ZERO','NO_BACKSLASH_ESCAPES','STRICT_TRANS_TABLES','STRICT_ALL_TABLES','NO_ZERO_IN_DATE','NO_ZERO_DATE','INVALID_DATES','ERROR_FOR_DIVISION_BY_ZERO','TRADITIONAL','NO_AUTO_CREATE_USER','HIGH_NOT_PRECEDENCE','NO_ENGINE_SUBSTITUTION','PAD_CHAR_TO_FULL_LENGTH','EMPTY_STRING_IS_NULL','SIMULTANEOUS_ASSIGNMENT'), found type set('REAL_AS_FLOAT','PIPES_AS_CONCAT','ANSI_QUOTES','IGNORE_SPACE','NOT_USED','ONLY_FULL_GROUP_BY','NO_UNSIGNED_SUBTRACTION','NO_DIR_IN_CREATE','POSTGRESQL','ORACLE','MSSQL','DB2','MAXDB','NO_KEY_OPTIONS','NO_TABLE_OPTIONS','NO_FIELD_OPTIONS','MYSQL323','MYSQL40','ANSI','NO_AUTO_VALUE_ON_ZERO','NO_B
            2023-02-24 12:21:54 0 [ERROR] mariadbd: Event Scheduler: An error occurred when initializing system tables. Disabling the Event Scheduler.
            2023-02-24 12:21:54 1 [Warning] Failed to load slave replication state from table mysql.gtid_slave_pos: 1146: Table 'mysql.gtid_slave_pos' doesn't exist
            2023-02-24 12:21:54 0 [Note] sql/mariadbd: ready for connections.
            Version: '11.0.2-MariaDB'  socket: '/tmp/build-mariadb-server-11.0.sock'  port: 0  Source distribution
            [1]   Done                    sql/mariadbd --no-defaults --skip-networking --datadir=/tmp/${PWD##*/}-datadir --socket=/tmp/${PWD##*/}.sock --plugin-dir=${PWD}/mysql-test/var/plugins/ --verbose
            2023-02-24 12:21:54 3 [ERROR] InnoDB: Column last_update in table mysql.innodb_table_stats is BINARY(4) NOT NULL but should be INT UNSIGNED NOT NULL
            2023-02-24 12:21:54 3 [ERROR] InnoDB: Fetch of persistent statistics requested for table `mysql`.`gtid_executed` but the required system tables mysql.innodb_table_stats and mysql.innodb_index_stats are not present or have unexpected structure. Using transient stats instead.
            2023-02-24 12:21:54 3 [Warning] InnoDB: A transaction id in a record of table `mysql`.`engine_cost` is newer than the system-wide maximum.
            2023-02-24 12:21:54 3 [ERROR] InnoDB: We detected index corruption in an InnoDB type table. You have to dump + drop + reimport the table or, in a case of widespread corruption, dump all InnoDB tables and recreate the whole tablespace. If the mariadbd server crashes after the startup or when you dump the tables. Please refer to https://mariadb.com/kb/en/library/innodb-recovery-modes/ for information about forcing recovery.
            2023-02-24 12:21:54 3 [ERROR] mariadbd: Index for table 'engine_cost' is corrupt; try to repair it
            mariadb-dump: Error 1034: Index for table 'engine_cost' is corrupt; try to repair it when dumping table `engine_cost` at row: 0
            

            Note first startup:

            InnoDB: log sequence number 2762352; transaction id 1794
            

            Second startup

            2023-02-24 12:21:54 0 [Note] InnoDB: log sequence number 2781972; transaction id 770
            

            danblack Daniel Black added a comment - $ d=build-mariadb-server-11.0-datadir; rm -rf $d; mkdir $d; tar -C $d -xf m57.tar.bz2   $ sql/mariadbd --no-defaults --skip-networking --datadir=/tmp/${PWD##*/}-datadir --socket=/tmp/${PWD##*/}.sock --plugin-dir=${PWD}/mysql-test/var/plugins/ --verbose & [1] 239736   ~/repos/build-mariadb-server-11.0 $ 2023-02-24 12:21:41 0 [Note] Starting MariaDB 11.0.2-MariaDB source revision b4ef9f766db28d258621aa888fdffd168321e3ba as process 239736 2023-02-24 12:21:41 0 [Note] InnoDB: Compressed tables use zlib 1.2.12 2023-02-24 12:21:41 0 [Note] InnoDB: Number of transaction pools: 1 2023-02-24 12:21:41 0 [Note] InnoDB: Using crc32 + pclmulqdq instructions 2023-02-24 12:21:41 0 [Note] InnoDB: Using liburing 2023-02-24 12:21:41 0 [Note] InnoDB: Initializing buffer pool, total size = 128.000MiB, chunk size = 2.000MiB 2023-02-24 12:21:41 0 [Note] InnoDB: Completed initialization of buffer pool 2023-02-24 12:21:41 0 [Note] InnoDB: Buffered log writes (block size=512 bytes) 2023-02-24 12:21:41 0 [Note] InnoDB: Upgrading redo log: 96.000MiB; LSN=2762352 2023-02-24 12:21:41 0 [Note] InnoDB: Buffered log writes (block size=512 bytes) 2023-02-24 12:21:41 0 [Note] InnoDB: Upgrading the change buffer 2023-02-24 12:21:41 0 [Note] InnoDB: Upgraded the change buffer: 0 tablespaces, 0 pages 2023-02-24 12:21:41 0 [Note] InnoDB: Reinitializing innodb_undo_tablespaces= 3 from 0 2023-02-24 12:21:41 0 [Note] InnoDB: Setting O_DIRECT on file .//undo001 failed 2023-02-24 12:21:41 0 [Note] InnoDB: Data file .//undo001 did not exist: new to be created 2023-02-24 12:21:41 0 [Note] InnoDB: Setting file .//undo001 size to 10.000MiB 2023-02-24 12:21:41 0 [Note] InnoDB: Database physically writes the file full: wait... 2023-02-24 12:21:41 0 [Note] InnoDB: Data file .//undo002 did not exist: new to be created 2023-02-24 12:21:41 0 [Note] InnoDB: Setting file .//undo002 size to 10.000MiB 2023-02-24 12:21:41 0 [Note] InnoDB: Database physically writes the file full: wait... 2023-02-24 12:21:41 0 [Note] InnoDB: Data file .//undo003 did not exist: new to be created 2023-02-24 12:21:41 0 [Note] InnoDB: Setting file .//undo003 size to 10.000MiB 2023-02-24 12:21:41 0 [Note] InnoDB: Database physically writes the file full: wait... 2023-02-24 12:21:41 0 [Note] InnoDB: 128 rollback segments in 3 undo tablespaces are active. 2023-02-24 12:21:41 0 [Note] InnoDB: Setting file './ibtmp1' size to 12.000MiB. Physically writing the file full; Please wait ... 2023-02-24 12:21:41 0 [Note] InnoDB: File './ibtmp1' size is now 12.000MiB. 2023-02-24 12:21:41 0 [Note] InnoDB: log sequence number 2762352; transaction id 1794 2023-02-24 12:21:41 0 [Note] Plugin 'FEEDBACK' is disabled. 2023-02-24 12:21:41 0 [Note] Plugin 'wsrep-provider' is disabled. 2023-02-24 12:21:41 0 [Note] InnoDB: Loading buffer pool(s) from /tmp/build-mariadb-server-11.0-datadir/ib_buffer_pool 2023-02-24 12:21:41 0 [Note] InnoDB: Buffer pool(s) load completed at 230224 12:21:41 2023-02-24 12:21:41 0 [ERROR] Missing system table mysql.roles_mapping; please run mysql_upgrade to create it 2023-02-24 12:21:41 0 [ERROR] Incorrect definition of table mysql.event: expected column 'definer' at position 3 to have type varchar(, found type char(93). 2023-02-24 12:21:41 0 [ERROR] Incorrect definition of table mysql.event: expected column 'sql_mode' at position 14 to have type set('REAL_AS_FLOAT','PIPES_AS_CONCAT','ANSI_QUOTES','IGNORE_SPACE','IGNORE_BAD_TABLE_OPTIONS','ONLY_FULL_GROUP_BY','NO_UNSIGNED_SUBTRACTION','NO_DIR_IN_CREATE','POSTGRESQL','ORACLE','MSSQL','DB2','MAXDB','NO_KEY_OPTIONS','NO_TABLE_OPTIONS','NO_FIELD_OPTIONS','MYSQL323','MYSQL40','ANSI','NO_AUTO_VALUE_ON_ZERO','NO_BACKSLASH_ESCAPES','STRICT_TRANS_TABLES','STRICT_ALL_TABLES','NO_ZERO_IN_DATE','NO_ZERO_DATE','INVALID_DATES','ERROR_FOR_DIVISION_BY_ZERO','TRADITIONAL','NO_AUTO_CREATE_USER','HIGH_NOT_PRECEDENCE','NO_ENGINE_SUBSTITUTION','PAD_CHAR_TO_FULL_LENGTH','EMPTY_STRING_IS_NULL','SIMULTANEOUS_ASSIGNMENT'), found type set('REAL_AS_FLOAT','PIPES_AS_CONCAT','ANSI_QUOTES','IGNORE_SPACE','NOT_USED','ONLY_FULL_GROUP_BY','NO_UNSIGNED_SUBTRACTION','NO_DIR_IN_CREATE','POSTGRESQL','ORACLE','MSSQL','DB2','MAXDB','NO_KEY_OPTIONS','NO_TABLE_OPTIONS','NO_FIELD_OPTIONS','MYSQL323','MYSQL40','ANSI','NO_AUTO_VALUE_ON_ZERO','NO_B 2023-02-24 12:21:41 0 [ERROR] mariadbd: Event Scheduler: An error occurred when initializing system tables. Disabling the Event Scheduler. 2023-02-24 12:21:41 1 [Warning] Failed to load slave replication state from table mysql.gtid_slave_pos: 1146: Table 'mysql.gtid_slave_pos' doesn't exist 2023-02-24 12:21:41 0 [Note] sql/mariadbd: ready for connections. Version: '11.0.2-MariaDB' socket: '/tmp/build-mariadb-server-11.0.sock' port: 0 Source distribution killall mariadbd 2023-02-24 12:21:46 0 [Note] sql/mariadbd (initiated by: unknown): Normal shutdown 2023-02-24 12:21:46 0 [Note] InnoDB: FTS optimize thread exiting. 2023-02-24 12:21:46 0 [Note] InnoDB: Starting shutdown... 2023-02-24 12:21:46 0 [Note] InnoDB: Dumping buffer pool(s) to /tmp/build-mariadb-server-11.0-datadir/ib_buffer_pool 2023-02-24 12:21:46 0 [Note] InnoDB: Buffer pool(s) dump completed at 230224 12:21:46   # Note the killall mariadbd was on the promt   ql/mariadbd --no-defaults --skip-networking --datadir=/tmp/${PWD##*/}-datadir --socket=/tmp/${PWD##*/}.sock --plugin-dir=${PWD}/mysql-test/var/plugins/ --verbose & while [ ! -S /tmp/${PWD##*/}.sock ]; do sleep 0.05; done ; client/mariadb-dump --user root -pbob -S /tmp/${PWD##*/}.sock mysql > /dev/null [2] 239807 2023-02-24 12:21:54 0 [Note] Starting MariaDB 11.0.2-MariaDB source revision b4ef9f766db28d258621aa888fdffd168321e3ba as process 239807 2023-02-24 12:21:54 0 [Note] InnoDB: Compressed tables use zlib 1.2.12 2023-02-24 12:21:54 0 [Note] InnoDB: Number of transaction pools: 1 2023-02-24 12:21:54 0 [Note] InnoDB: Using crc32 + pclmulqdq instructions 2023-02-24 12:21:54 0 [Note] InnoDB: Using liburing 2023-02-24 12:21:54 0 [Note] InnoDB: Initializing buffer pool, total size = 128.000MiB, chunk size = 2.000MiB 2023-02-24 12:21:54 0 [Note] InnoDB: Completed initialization of buffer pool 2023-02-24 12:21:54 0 [Note] InnoDB: Resetting space id's in the doublewrite buffer 2023-02-24 12:21:54 0 [Note] InnoDB: Buffered log writes (block size=512 bytes) 2023-02-24 12:21:54 0 [Note] InnoDB: Opened 3 undo tablespaces 2023-02-24 12:21:54 0 [Note] InnoDB: 128 rollback segments in 3 undo tablespaces are active. 2023-02-24 12:21:54 0 [Note] InnoDB: Setting O_DIRECT on file ./ibtmp1 failed 2023-02-24 12:21:54 0 [Note] InnoDB: Setting file './ibtmp1' size to 12.000MiB. Physically writing the file full; Please wait ... 2023-02-24 12:21:54 0 [Note] InnoDB: File './ibtmp1' size is now 12.000MiB. 2023-02-24 12:21:54 0 [Note] InnoDB: log sequence number 2781972; transaction id 770 2023-02-24 12:21:54 0 [Note] Plugin 'FEEDBACK' is disabled. 2023-02-24 12:21:54 0 [Note] Plugin 'wsrep-provider' is disabled. 2023-02-24 12:21:54 0 [Note] InnoDB: Loading buffer pool(s) from /tmp/build-mariadb-server-11.0-datadir/ib_buffer_pool 2023-02-24 12:21:54 0 [Note] InnoDB: Buffer pool(s) load completed at 230224 12:21:54 2023-02-24 12:21:54 0 [ERROR] Missing system table mysql.roles_mapping; please run mysql_upgrade to create it 2023-02-24 12:21:54 0 [ERROR] Incorrect definition of table mysql.event: expected column 'definer' at position 3 to have type varchar(, found type char(93). 2023-02-24 12:21:54 0 [ERROR] Incorrect definition of table mysql.event: expected column 'sql_mode' at position 14 to have type set('REAL_AS_FLOAT','PIPES_AS_CONCAT','ANSI_QUOTES','IGNORE_SPACE','IGNORE_BAD_TABLE_OPTIONS','ONLY_FULL_GROUP_BY','NO_UNSIGNED_SUBTRACTION','NO_DIR_IN_CREATE','POSTGRESQL','ORACLE','MSSQL','DB2','MAXDB','NO_KEY_OPTIONS','NO_TABLE_OPTIONS','NO_FIELD_OPTIONS','MYSQL323','MYSQL40','ANSI','NO_AUTO_VALUE_ON_ZERO','NO_BACKSLASH_ESCAPES','STRICT_TRANS_TABLES','STRICT_ALL_TABLES','NO_ZERO_IN_DATE','NO_ZERO_DATE','INVALID_DATES','ERROR_FOR_DIVISION_BY_ZERO','TRADITIONAL','NO_AUTO_CREATE_USER','HIGH_NOT_PRECEDENCE','NO_ENGINE_SUBSTITUTION','PAD_CHAR_TO_FULL_LENGTH','EMPTY_STRING_IS_NULL','SIMULTANEOUS_ASSIGNMENT'), found type set('REAL_AS_FLOAT','PIPES_AS_CONCAT','ANSI_QUOTES','IGNORE_SPACE','NOT_USED','ONLY_FULL_GROUP_BY','NO_UNSIGNED_SUBTRACTION','NO_DIR_IN_CREATE','POSTGRESQL','ORACLE','MSSQL','DB2','MAXDB','NO_KEY_OPTIONS','NO_TABLE_OPTIONS','NO_FIELD_OPTIONS','MYSQL323','MYSQL40','ANSI','NO_AUTO_VALUE_ON_ZERO','NO_B 2023-02-24 12:21:54 0 [ERROR] mariadbd: Event Scheduler: An error occurred when initializing system tables. Disabling the Event Scheduler. 2023-02-24 12:21:54 1 [Warning] Failed to load slave replication state from table mysql.gtid_slave_pos: 1146: Table 'mysql.gtid_slave_pos' doesn't exist 2023-02-24 12:21:54 0 [Note] sql/mariadbd: ready for connections. Version: '11.0.2-MariaDB' socket: '/tmp/build-mariadb-server-11.0.sock' port: 0 Source distribution [1] Done sql/mariadbd --no-defaults --skip-networking --datadir=/tmp/${PWD##*/}-datadir --socket=/tmp/${PWD##*/}.sock --plugin-dir=${PWD}/mysql-test/var/plugins/ --verbose 2023-02-24 12:21:54 3 [ERROR] InnoDB: Column last_update in table mysql.innodb_table_stats is BINARY(4) NOT NULL but should be INT UNSIGNED NOT NULL 2023-02-24 12:21:54 3 [ERROR] InnoDB: Fetch of persistent statistics requested for table `mysql`.`gtid_executed` but the required system tables mysql.innodb_table_stats and mysql.innodb_index_stats are not present or have unexpected structure. Using transient stats instead. 2023-02-24 12:21:54 3 [Warning] InnoDB: A transaction id in a record of table `mysql`.`engine_cost` is newer than the system-wide maximum. 2023-02-24 12:21:54 3 [ERROR] InnoDB: We detected index corruption in an InnoDB type table. You have to dump + drop + reimport the table or, in a case of widespread corruption, dump all InnoDB tables and recreate the whole tablespace. If the mariadbd server crashes after the startup or when you dump the tables. Please refer to https://mariadb.com/kb/en/library/innodb-recovery-modes/ for information about forcing recovery. 2023-02-24 12:21:54 3 [ERROR] mariadbd: Index for table 'engine_cost' is corrupt; try to repair it mariadb-dump: Error 1034: Index for table 'engine_cost' is corrupt; try to repair it when dumping table `engine_cost` at row: 0 Note first startup: InnoDB: log sequence number 2762352; transaction id 1794 Second startup 2023-02-24 12:21:54 0 [Note] InnoDB: log sequence number 2781972; transaction id 770
            danblack Daniel Black added a comment -

            not-10.11.3-8460eb25d1f897d403136e75b75ef595470d641c

            2023-02-24 14:03:40 0 [Note] InnoDB: log sequence number 2766763; transaction id 1794
            

            Much more sensible transaction id (same as first startup).

            danblack Daniel Black added a comment - not-10.11.3-8460eb25d1f897d403136e75b75ef595470d641c 2023-02-24 14:03:40 0 [Note] InnoDB: log sequence number 2766763; transaction id 1794 Much more sensible transaction id (same as first startup).

            This problem can happen in 10.11 too if we start the server with --innodb_undo_tablespaces=3
            At first(in case of upgrade), we do max trx id from TRX_SYS_TRX_ID_STORE of TRX_SYS page.
            In MDEV-19229, InnoDB reset TRX_SYS page and assign rollback segment (1..127) as FIL_NULL ,
            frees the existing rollback segment(1..127) of system tablespace. Recreates the specified undo
            log tablespace. During next restart, InnoDB fetches the maximum transaction ID from
            TRX_UNDO_TRX_ID of 0th rollback segment.

            thiru Thirunarayanan Balathandayuthapani added a comment - This problem can happen in 10.11 too if we start the server with --innodb_undo_tablespaces=3 At first(in case of upgrade), we do max trx id from TRX_SYS_TRX_ID_STORE of TRX_SYS page. In MDEV-19229 , InnoDB reset TRX_SYS page and assign rollback segment (1..127) as FIL_NULL , frees the existing rollback segment(1..127) of system tablespace. Recreates the specified undo log tablespace. During next restart, InnoDB fetches the maximum transaction ID from TRX_UNDO_TRX_ID of 0th rollback segment.

            I think that a more appropriate place to store the transaction ID is TRX_RSEG_MAX_TRX_ID in rollback segment 0. The upgrade process should also set TRX_RSEG_FORMAT to 0 in that page.

            The fields TRX_UNDO_TRX_ID or TRX_UNDO_TRX_NO are transient, referring to active transactions or transactions whose history has not been purged yet. If the undo logs are logically empty, these fields should not be read. That is why TRX_RSEG_MAX_TRX_ID exists.

            marko Marko Mäkelä added a comment - I think that a more appropriate place to store the transaction ID is TRX_RSEG_MAX_TRX_ID in rollback segment 0. The upgrade process should also set TRX_RSEG_FORMAT to 0 in that page. The fields TRX_UNDO_TRX_ID or TRX_UNDO_TRX_NO are transient, referring to active transactions or transactions whose history has not been purged yet. If the undo logs are logically empty, these fields should not be read. That is why TRX_RSEG_MAX_TRX_ID exists.

            I spent quite a bit of time in an attempt to create a dummy InnoDB system tablespace in Perl code in our regression test suite, but there simply are too many pages in it. I got to the point where dict_sys_t::create_or_check_sys_tables() would crash when trying to create missing data dictionary tables. I could work around it by setting innodb_force_recovery=3, but that will also prevent a change of innodb_undo_tablespaces to take effect. I did not want to add debug injection for this case, and I thought that inserting dummy metadata into the 4 hard-coded system tables for the non-hard-coded system tables in Perl code would be too much effort.

            The m57.tar.bz2 can be simplified to a rather small ibdata1.gz like this:

            dd if=/dev/zero bs=16384 count=128 seek=64 of=ibdata1 conv=notrunc
            gzip -9 ibdata1
            

            This will zero out the doublewrite buffer pages. With that file, the problem can be reproduced as follows, starting from an initially empty directory that only contains the file ibdata1.gz:

            gunzip ibdata1.gz
            touch ib_logfile0
            mariadbd --innodb-undo-tablespaces=3 --datadir "$(pwd)"
            mariadbd --innodb-undo-tablespaces=3 --datadir "$(pwd)"
            

            There will be a lot of error messages due to missing files. The relevant part is that the first start-up attempt says the following:

            2023-03-03 10:43:57 0 [Note] InnoDB: File './ibtmp1' size is now 12.000MiB.
            2023-03-03 10:43:57 0 [Note] InnoDB: log sequence number 2762352; transaction id 1794
            

            The second start-up attempt will wrongly rewind the transaction ID if the fix is not present:

            2023-03-03 10:44:17 0 [Note] InnoDB: File './ibtmp1' size is now 12.000MiB.
            2023-03-03 10:44:17 0 [Note] InnoDB: log sequence number 2786076; transaction id 770
            

            marko Marko Mäkelä added a comment - I spent quite a bit of time in an attempt to create a dummy InnoDB system tablespace in Perl code in our regression test suite, but there simply are too many pages in it. I got to the point where dict_sys_t::create_or_check_sys_tables() would crash when trying to create missing data dictionary tables. I could work around it by setting innodb_force_recovery=3 , but that will also prevent a change of innodb_undo_tablespaces to take effect. I did not want to add debug injection for this case, and I thought that inserting dummy metadata into the 4 hard-coded system tables for the non-hard-coded system tables in Perl code would be too much effort. The m57.tar.bz2 can be simplified to a rather small ibdata1.gz like this: dd if=/dev/zero bs=16384 count=128 seek=64 of=ibdata1 conv=notrunc gzip -9 ibdata1 This will zero out the doublewrite buffer pages. With that file, the problem can be reproduced as follows, starting from an initially empty directory that only contains the file ibdata1.gz : gunzip ibdata1.gz touch ib_logfile0 mariadbd --innodb-undo-tablespaces=3 --datadir "$(pwd)" mariadbd --innodb-undo-tablespaces=3 --datadir "$(pwd)" There will be a lot of error messages due to missing files. The relevant part is that the first start-up attempt says the following: 2023-03-03 10:43:57 0 [Note] InnoDB: File './ibtmp1' size is now 12.000MiB. 2023-03-03 10:43:57 0 [Note] InnoDB: log sequence number 2762352; transaction id 1794 The second start-up attempt will wrongly rewind the transaction ID if the fix is not present: 2023-03-03 10:44:17 0 [Note] InnoDB: File './ibtmp1' size is now 12.000MiB. 2023-03-03 10:44:17 0 [Note] InnoDB: log sequence number 2786076; transaction id 770

            For the record, my attempt at a regression test is in 0001-WIP-test-case.patch, against 10.11 8460eb25d1f897d403136e75b75ef595470d641c. It is missing an explicit innodb_undo_tablespaces parameter, so it would not actually execute the MDEV-19229 code. It is hitting some errors in dict_sys_t::create_or_check_sys_tables(). I think that that code should be after the undo log rebuild. With some more effort, could be made a working test, but I think that the time would be better spent on implementing an upgrade test that would catch cases where the LSN or the maximum transaction ID are moving backwards.

            I’m mainly attaching the test changes in case we want to improve our robustness of handling corrupted data. In the Perl code, it is rather easy to corrupt specific things.

            marko Marko Mäkelä added a comment - For the record, my attempt at a regression test is in 0001-WIP-test-case.patch , against 10.11 8460eb25d1f897d403136e75b75ef595470d641c. It is missing an explicit innodb_undo_tablespaces parameter, so it would not actually execute the MDEV-19229 code. It is hitting some errors in dict_sys_t::create_or_check_sys_tables() . I think that that code should be after the undo log rebuild. With some more effort, could be made a working test, but I think that the time would be better spent on implementing an upgrade test that would catch cases where the LSN or the maximum transaction ID are moving backwards. I’m mainly attaching the test changes in case we want to improve our robustness of handling corrupted data. In the Perl code, it is rather easy to corrupt specific things.

            People

              marko Marko Mäkelä
              danblack Daniel Black
              Votes:
              0 Vote for this issue
              Watchers:
              5 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved:

                Git Integration

                  Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.