Atomic DROP TABLE is not crash-safe on power loss: the link to the DROP TABLE entry in ddl_recovery.log is not synced, so after a power failure during DROP TABLE the .frm survives while InnoDB has dropped the table

Description:

DROP TABLE t8 (an ordinary InnoDB table) writes three entries to
ddl_recovery.log: entry 1 DDL_LOG_DROP_INIT_ACTION, entry 2 the execute entry
(pointing to entry 1), entry 3 DDL_LOG_DROP_TABLE_ACTION for t8. Each entry is
synced after it is written. Entry 3 is then linked into the chain by
update_next_entry_pos(1 -> 3), a 4-byte pwrite() at offset 4096+4 that is not
synced. Next InnoDB commits the drop (redo log write + fdatasync) and the
files are unlinked.

If the power fails after the InnoDB commit and before anything else syncs
ddl_recovery.log, the link is lost: on disk entry 1 still has next_entry = 0.
At restart InnoDB's recovery completes its drop (t8.ibd is deleted), the DDL
log recovery follows the chain from the execute entry to entry 1, finds
next_entry = 0 and never sees entry 3, so t8.frm stays. (The "DDL_LOG:
Crash recovery executed 1 entries" line counts execute entries; it is the
same after a plain kill.) The table is listed by
SHOW TABLES and information_schema, but

SELECT count FROM t8 -> ERROR 1932 (42S02): Table 'test.t8' doesn't exist in engine
CHECK TABLE t8 -> Error / Operation failed
mariadb-dump test -> Got error: 1932 ... when using LOCK TABLES (exit code 2)

so logical backups of the schema fail until someone drops t8 again. The
statement was never acknowledged, so no acknowledged data is lost; the
problem is that the atomic-DDL guarantee (after a crash the drop is either
completed or not done) does not hold for a power failure.

With a plain SIGKILL at the same point (no power cut) the link is in the page
cache, the recovery executes entry 3, removes t8.frm and binlogs
"DROP TABLE IF EXISTS `t8` /* generated by ddl recovery */": correct.

trace of DROP TABLE t8 (13.2 main):
pwrite64(4</var/lib/mysql/ddl_recovery.log>, "\2\7\0..."..., 4096, 4096) = 4096 entry 1 DROP_INIT
fdatasync(4</var/lib/mysql/ddl_recovery.log>) = 0
pwrite64(4</var/lib/mysql/ddl_recovery.log>, "\1\0\0\0\1\0..."..., 4096, 8192) = 4096 entry 2 execute -> 1
fdatasync(4</var/lib/mysql/ddl_recovery.log>) = 0
pwrite64(4</var/lib/mysql/ddl_recovery.log>, "\2\10\0...InnoDB\0...t8..."..., 4096, 12288) = 4096 entry 3 DROP_TABLE t8
fdatasync(4</var/lib/mysql/ddl_recovery.log>) = 0
pwrite64(4</var/lib/mysql/ddl_recovery.log>, "\3\0\0\0", 4, 4100) = 4 entry 1 next_entry = 3 <- never synced
pwrite64(9</var/lib/mysql/ib_logfile0>, ...)
fdatasync(9</var/lib/mysql/ib_logfile0>) = 0 InnoDB commits the drop
unlink("./test/t8.ibd") = ? <- SIGKILL + power cut here

How to repeat (as root; ext4 on a dm-linear device over a loop file):

truncate -s 3G /dev/shm/pcut.img; LOOP=$(losetup -f --show /dev/shm/pcut.img)
dmsetup create pcut --table "0 $((3*1024*2048)) linear $LOOP 0"
mkfs.ext4 -q /dev/mapper/pcut; mkdir -p /mnt/pcut
mount -o noatime,commit=3600 /dev/mapper/pcut /mnt/pcut
docker run -d --name m006 --network host -v /mnt/pcut:/var/lib/mysql -e MARIADB_ALLOW_EMPTY_ROOT_PASSWORD=1 \
-e MARIADB_DATABASE=test quay.io/mariadb-foundation/mariadb-devel:verylatest --port=3313 --log-bin=binlog --sync-binlog=1

1. (wait until the server is ready)
   q() { docker exec m006 mariadb -uroot test -e "$*"; }

   q "CREATE TABLE t1 (id INT PRIMARY KEY, v INT); INSERT INTO t1 VALUES (1,1);
   CREATE TABLE t8 (id INT PRIMARY KEY, k INT, n INT, v VARCHAR(1100));
   INSERT INTO t8 SELECT seq, seq, seq, REPEAT('x',100) FROM seq_1_to_100;"
   sync -f /mnt/pcut; sleep 1 # t8 is durable

2. SIGKILL the server when it enters its first unlink() (t8.ibd, after the InnoDB commit)
   timeout 15 strace -f -qq -p $(docker inspect -f '.State.Pid' m006) -e trace=unlink,unlinkat \
   -e inject=unlink,unlinkat:signal=KILL:when=1 -o /dev/null & sleep 2
   q "DROP TABLE t8"; wait # connection lost
3. power cut, then "reboot"
   dmsetup suspend --noflush --nolockfs pcut; dmsetup load pcut --table "0 $((3*1024*2048)) error"; dmsetup resume pcut
   docker kill -s KILL m006 2>/dev/null # (already dead)
   umount -l /mnt/pcut; dmsetup remove pcut; losetup -d $LOOP
   LOOP=$(losetup -f --show /dev/shm/pcut.img); mount -o noatime $LOOP /mnt/pcut
   od -A d -t u4 -j 4100 -N 4 /mnt/pcut/ddl_recovery.log # next_entry of entry 1 (entry positions
4. depend on earlier DDL; 1 in this script)
   docker start m006
5. (wait until the server is ready)
   docker logs m006 2>&1 | grep -E "DDL_LOG|table recovery"
   ls -l /mnt/pcut/test/ | grep t8
   q "SHOW TABLES"; q "SELECT count FROM t8"; q "CHECK TABLE t8"
   docker exec m006 mariadb-dump -uroot test > /dev/null; echo "mariadb-dump rc=$?"

(Without the three dmsetup commands, i.e. a plain kill, the same steps end
with t8 correctly dropped.)

Result on 13.2 main (13.0.2 gives the same outcome):

next_entry of entry 1 on disk: 0 (3 after a plain kill without the power cut)
[Note] Starting table crash recovery...
[Note] Crash table recovery finished.
[Note] DDL_LOG: Crash recovery executed 1 entries
ls: t8.frm (5392 bytes), no t8.ibd
SHOW TABLES -> t1, t8
SELECT count FROM t8 -> ERROR 1932 (42S02) at line 1: Table 'test.t8' doesn't exist in engine
CHECK TABLE t8 -> Error: Table 'test.t8' doesn't exist in engine / status: Operation failed
mariadb-dump -> mariadb-dump: Got error: 1932: "Table 'test.t8' doesn't exist in engine" when using LOCK TABLES; rc=2
binlog -> no DROP TABLE event for t8 (consistent with the table being "present")

Expected: after the restart t8 is either completely dropped or completely
present. The link to the new entry should be synced before the engine part of
the drop is executed (a ddl_log_sync after update_next_entry_pos() in
ddl_log_drop(), or link the entry before the sync that follows its write).

Cause:

ddl_log_drop() syncs the new entry, then updates the previous entry's
next_entry field without a sync:
https://github.com/MariaDB/server/blob/327437ade1d6dc6e4e57a6f1723b4abe4ac6c4b4/sql/ddl_log.cc#L3431-L3442
https://github.com/MariaDB/server/blob/327437ade1d6dc6e4e57a6f1723b4abe4ac6c4b4/sql/ddl_log.cc#L379-L391
Nothing else syncs ddl_recovery.log before the InnoDB commit of the drop and
the unlink of the files.

Related: MDEV-17567 (atomic DDL), MDEV-41534 (option to write the DDL recovery
log to InnoDB, open), MDEV-27618 (atomic DDL on partitioned tables). No report
found for a lost DDL log link after power loss.