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

A failed write or sync of ddl_recovery.log after the engine change makes DROP TABLE / ALTER TABLE return an error although the DDL was applied; ALTER TABLE is then also missing from the binary log, so replicas diverge

    XMLWordPrintable

Details

    Description

      The atomic-DDL log (ddl_recovery.log) is written and synced at several points
      of a DDL statement. Most of the sync calls deliberately ignore the result
      ("(void) ddl_log_sync_no_lock()", or ddl_log_update_phase() whose return value
      is not checked), but ddl_log_sync_file() passes MY_WME to mysql_file_sync(), so
      a failure still calls my_error() and puts an error into the statement's
      diagnostics area. The same happens for the pwrite() of a phase update. When
      this happens after the engine part of the DDL is done, the statement is
      reported as failed although it was applied:

      • DROP TABLE t3 with one ENOSPC (or EIO) on the first fdatasync of
        ddl_recovery.log: error 27 "Can't sync file './ddl_recovery.log' to disk",
        but the table is gone and "DROP TABLE `t3` /* generated by server */" is in
        the binary log. Retrying gives "Unknown table".
      • ALTER TABLE t1 ADD COLUMN c1 INT (in-place) with one EIO on the 5th
        fdatasync of ddl_recovery.log in the statement (the sync after the phase
        update DDL_ALTER_TABLE_PHASE_INPLACE_COPIED, after InnoDB has committed the
        change): error 27, the column exists on the primary (also after restart),
        but the ALTER is NOT written to the binary log. The replica never gets the
        column; replication continues without an error until a statement uses c1.

      A scan with one EIO on the N-th pwrite64 or fdatasync of ddl_recovery.log
      (N = 1..6) gave the same pattern for ALTER TABLE ADD INDEX, DROP INDEX and
      RENAME TABLE: failures at the early calls are honest (nothing applied, nothing
      logged), failures at the later calls are false failures; for the in-place
      ALTER variants the binlog event is missing, for DROP TABLE and RENAME TABLE it
      is present. No message is written to the error log for the sync failures.

      How to repeat:

      P=quay.io/mariadb-foundation/mariadb-devel:verylatest
      for x in "pri 3310 1" "rep 3311 2"; do set – $x
      docker run -d --name $1 --network host -e MARIADB_ALLOW_EMPTY_ROOT_PASSWORD=1 -e MARIADB_DATABASE=test $P \
      --port=$2 --server-id=$3 --log-bin=binlog --sync-binlog=1 --innodb-flush-log-at-trx-commit=1
      done

      1. (wait until both servers are ready)
        q() { c=$1; shift; docker exec $c mariadb -uroot test -e "$*"; }

        q pri "CREATE TABLE t1 (id INT PRIMARY KEY, v INT); CREATE TABLE t3 LIKE t1; INSERT INTO t1 VALUES (1,1)"
        q rep "CHANGE MASTER TO master_host='127.0.0.1', master_port=3310, master_user='root', master_use_gtid=slave_pos; START SLAVE"
        fail() { # $1 = strace inject spec, $2 = statement; counts only calls on ddl_recovery.log
        sudo timeout 8 strace -f -qq -y -p $(docker inspect -f '.State.Pid' pri) -e trace=pwrite64,fdatasync \
        e inject=$1 -P /var/lib/mysql/ddl_recovery.log -o trace$RANDOM.txt & sleep 2
        q pri "$2"; wait
        }
        fail fdatasync:error=ENOSPC:when=1 "DROP TABLE t3"
        fail fdatasync:error=EIO:when=5 "ALTER TABLE t1 ADD COLUMN c1 INT"
        q pri "INSERT INTO t1 (id, v) VALUES (2,2)"; sleep 2
        for c in pri rep; do echo "== $c"; q $c "SHOW TABLES; SHOW COLUMNS FROM t1; SELECT @@gtid_current_pos"; done
        q rep "SHOW SLAVE STATUS\G" | grep -E "Running:|Last_.*Error:"
        q pri "SHOW BINLOG EVENTS IN 'binlog.000002'" | grep -E "Query|Gtid"

      Result on 13.2 main (327437ade1d6); 13.0.2 gives the same:

      DROP TABLE t3 -> ERROR 27 (HY000): Can't sync file './ddl_recovery.log' to disk (Errcode: 28 "No space left on device")
      ALTER TABLE t1 ADD COLUMN c1 INT -> ERROR 27 (HY000): Can't sync file './ddl_recovery.log' to disk (Errcode: 5 "Input/output error")
      INSERT -> OK

      primary replica
      tables t1 t1
      t1 columns id, v, c1 id, v
      gtid_current_pos 0-1-6 0-1-6
      Slave_IO_Running: Yes, Slave_SQL_Running: Yes, Last_Error: (empty)

      primary binlog: ... GTID 0-1-5 use `test`; DROP TABLE `t3` /* generated by server */
      BEGIN GTID 0-1-6 (the INSERT) <- no ALTER TABLE event
      After kill -9 and restart of the primary: t1 columns id, v, c1; no t3.

      trace (DROP TABLE):
      pwrite64(4</var/lib/mysql/ddl_recovery.log>, "\2\7\0..."..., 4096, 4096) = 4096
      fdatasync(4</var/lib/mysql/ddl_recovery.log>) = -1 ENOSPC (No space left on device) (INJECTED)
      pwrite64(4</var/lib/mysql/ddl_recovery.log>, "\1\0\0\0\1\0..."..., 4096, 8192) = 4096 <- execution continues
      fdatasync(4</var/lib/mysql/ddl_recovery.log>) = 0
      pwrite64(4</var/lib/mysql/ddl_recovery.log>, "\2\10\0...InnoDB..."...) = 4096
      ...
      trace (ALTER TABLE, 5th sync):
      pwrite64(4</var/lib/mysql/ddl_recovery.log>, "\4", 1, 8194) = 1 <- phase update of the ALTER entry
      fdatasync(4</var/lib/mysql/ddl_recovery.log>) = -1 EIO (Input/output error) (INJECTED)

      Expected: either the DDL log failure stops the statement before the change is
      applied (and the change is rolled back), or, once the change has been
      committed and cannot be undone, the statement completes normally: it is
      written to the binary log and reported as successful (an error-log entry about
      the DDL log would be appropriate; the next sync makes the log durable again,
      and if the server crashed before that, recovery would still find the earlier
      phase). Returning an error for a completed DDL, and for ALTER TABLE also
      dropping its binlog event, is the one outcome that cannot be right.

      Cause, as far as I can tell:

      ddl_log_sync_file() uses MYF(MY_WME), so every failed sync raises an error,
      including the calls whose result is ignored on purpose; update_phase() also
      writes with MY_WME:
      https://github.com/MariaDB/server/blob/327437ade1d6dc6e4e57a6f1723b4abe4ac6c4b4/sql/ddl_log.cc#L202-L206
      https://github.com/MariaDB/server/blob/327437ade1d6dc6e4e57a6f1723b4abe4ac6c4b4/sql/ddl_log.cc#L347-L356
      https://github.com/MariaDB/server/blob/327437ade1d6dc6e4e57a6f1723b4abe4ac6c4b4/sql/ddl_log.cc#L2736-L2739
      In mysql_inplace_alter_table() the phase update after the commit ignores its
      return value, but the following check of thd->is_error() sees the error
      raised by MY_WME and jumps to err ("Since changes were done in-place, we
      can't revert them"), which skips the binlog write:
      https://github.com/MariaDB/server/blob/327437ade1d6dc6e4e57a6f1723b4abe4ac6c4b4/sql/sql_table.cc#L8778
      https://github.com/MariaDB/server/blob/327437ade1d6dc6e4e57a6f1723b4abe4ac6c4b4/sql/sql_table.cc#L8812-L8820

      Related: MDEV-17567 (atomic DDL), MDEV-41534 (option to write the DDL
      recovery log to InnoDB, open). No report found about failed writes/syncs of
      ddl_recovery.log during normal operation.

      Attachments

        Issue Links

          Activity

            People

              sanja Oleksandr Byelkin
              kehan5800 Ke Han
              Votes:
              0 Vote for this issue
              Watchers:
              2 Start watching this issue

              Dates

                Created:
                Updated:

                Git Integration

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