Details
-
Bug
-
Status: Confirmed (View Workflow)
-
Major
-
Resolution: Unresolved
-
10.11, 11.4, 11.8, 12.3, 13.1, 13.2, 13.0.2
-
None
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
- (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
- relates to
-
MDEV-17567 Atomic DDL
-
- Closed
-
-
MDEV-41534 Option to write DDL recovery log to InnoDB
-
- Open
-