Details
-
Bug
-
Status: Open (View Workflow)
-
Major
-
Resolution: Unresolved
-
12.3.3
-
None
-
None
-
Linux x86_64 host with GCC; official image
`mariadb@sha256:dd9b303aed4f4890ed09f766d8ca9ddfd176c0c6f6267feff53b3192ec65a979`;
server reports `12.3.3-MariaDB-ubu2404`, source revision
`83e909fc2a0dbc394b4b683fb3fa2d7dcf26cc5e`.
Description
In the non-mmap redo-copy path, `xtrabackup_copy_logfile()` calls
`log_sys.log.read()` at three sites without checking its `dberr_t` return value,
then sets `recv_sys.len` to the requested byte count. When the final real
`pread()` of encrypted `ib_logfile0` returns `-1/EIO`, MariaDB logs the InnoDB
error but `mariadb-backup` still exits with status 0, writes
`mariadb_backup_checkpoints`, reports that the redo range was copied, and
prints `completed OK!`.
The reproduction below first traces a no-fault control, then makes only the
sixth and final matching `ib_logfile0` read fail. The trace confirms there is
no later successful redo `pread()` after the injected failure.
Steps to reproduce
Run only on a disposable Docker host. The preload shim passes every operation
through unchanged except one numbered `pread()`/`pread64()` on a file whose
resolved descriptor path ends in `/ib_logfile0`.
set -eu
|
IMAGE='mariadb@sha256:dd9b303aed4f4890ed09f766d8ca9ddfd176c0c6f6267feff53b3192ec65a979'
|
C='mdev-redo-eio-repro'
|
OWNER="edbf-report-$C-$$"
|
D=$(mktemp -d)
|
cleanup() {
|
if docker inspect --format '{{ index .Config.Labels "io.encryptiondbfuzz.owner" }}' \
|
"$C" 2>/dev/null | grep -Fqx "$OWNER"; then
|
docker rm -f "$C" >/dev/null 2>&1 || true
|
fi
|
rm -r "$D" >/dev/null 2>&1 || true
|
}
|
trap cleanup EXIT
|
|
|
cat >"$D/pread_fail_once.c" <<'EOF'
|
#define _GNU_SOURCE
|
#include <errno.h>
|
#include <fcntl.h>
|
#include <limits.h>
|
#include <pthread.h>
|
#include <stdio.h>
|
#include <stdlib.h>
|
#include <string.h>
|
#include <sys/syscall.h>
|
#include <sys/types.h>
|
#include <unistd.h>
|
static pthread_mutex_t lock=PTHREAD_MUTEX_INITIALIZER;
|
static unsigned long calls;
|
static int is_redo(int fd) {
|
char link[64],path[PATH_MAX+1];
|
snprintf(link,sizeof(link),"/proc/self/fd/%d",fd);
|
ssize_t n=readlink(link,path,sizeof(path)-1);
|
if (n<=0) return 0;
|
path[n]='\0';
|
const char suffix[]="/ib_logfile0";
|
return (size_t)n>=sizeof(suffix)-1 &&
|
memcmp(path+n-(sizeof(suffix)-1),suffix,sizeof(suffix)-1)==0;
|
}
|
static unsigned long fail_at(void) {
|
const char *s=getenv("FAIL_AT");
|
return s ? strtoul(s,0,10) : 0;
|
}
|
static void log_call(unsigned long nr,size_t count,off_t offset,
|
ssize_t result,int err) {
|
char line[192];
|
int n=snprintf(line,sizeof(line),
|
"redo_pread ordinal=%lu count=%zu offset=%lld result=%zd errno=%d\n",
|
nr,count,(long long)offset,result,err);
|
int fd=open("/tmp/redo-pread.log",O_WRONLY|O_CREAT|O_APPEND,0600);
|
if (fd>=0) { if (n>0) (void)write(fd,line,(size_t)n); close(fd); }
|
}
|
static ssize_t do_pread(int fd,void *buf,size_t count,off_t offset) {
|
if (!is_redo(fd)) return syscall(SYS_pread64,fd,buf,count,offset);
|
pthread_mutex_lock(&lock); unsigned long nr=++calls; pthread_mutex_unlock(&lock);
|
if (nr==fail_at()) {
|
errno=EIO; log_call(nr,count,offset,-1,EIO); return -1;
|
}
|
ssize_t result=syscall(SYS_pread64,fd,buf,count,offset);
|
int err=result<0 ? errno : 0;
|
log_call(nr,count,offset,result,err); errno=err; return result;
|
}
|
ssize_t pread(int fd,void *buf,size_t count,off_t offset) {
|
return do_pread(fd,buf,count,offset);
|
}
|
ssize_t wrapped_pread64(int fd,void *buf,size_t count,off64_t offset)
|
__asm__("pread64");
|
ssize_t wrapped_pread64(int fd,void *buf,size_t count,off64_t offset) {
|
return do_pread(fd,buf,count,(off_t)offset);
|
}
|
EOF
|
gcc -shared -fPIC -O2 -Wall -Wextra -o "$D/pread_fail_once.so" \
|
"$D/pread_fail_once.c" -pthread
|
printf '%s\n' '1;0123456789ABCDEF0123456789ABCDEF' >"$D/keys.txt"
|
chmod 0755 "$D"
|
chmod 0644 "$D/pread_fail_once.so" "$D/keys.txt"
|
|
|
docker run --detach --name "$C" --network none --read-only --cap-drop ALL \
|
--label "io.encryptiondbfuzz.owner=$OWNER" \
|
--security-opt no-new-privileges=true --user 999:999 \
|
--tmpfs /var/lib/mysql:rw,nosuid,nodev,size=700m,uid=999,gid=999 \
|
--tmpfs /run/mysqld:rw,nosuid,nodev,size=16m,uid=999,gid=999 \
|
--tmpfs /tmp:rw,nosuid,nodev,size=900m,uid=999,gid=999 \
|
--mount type=bind,src="$D",dst=/edbf,readonly \
|
--env MARIADB_ALLOW_EMPTY_ROOT_PASSWORD=1 "$IMAGE" \
|
--plugin-load-add=file_key_management.so \
|
--file-key-management-filename=/edbf/keys.txt --innodb-encrypt-log=ON
|
|
|
READY=0
|
for i in $(seq 1 90); do
|
if docker exec "$C" mariadb --protocol=socket -uroot -NBe \
|
"SELECT @@port" 2>/dev/null | grep -qx 3306; then READY=1; break; fi
|
sleep 1
|
done
|
test "$READY" -eq 1
|
docker exec "$C" mariadb --protocol=socket -uroot -e \
|
"CREATE DATABASE edbf; USE edbf;
|
CREATE TABLE t(id INT PRIMARY KEY,pad VARCHAR(255)) ENGINE=InnoDB;
|
INSERT INTO t SELECT seq,REPEAT(CHAR(65+(seq%26)),220) FROM seq_1_to_4000;
|
FLUSH TABLES; FLUSH LOGS;"
|
docker exec "$C" mariadb --protocol=socket -uroot -NBe \
|
"SELECT @@innodb_encrypt_log"
|
|
|
# No-fault control. It should show six successful redo reads and complete.
|
docker exec --env LD_PRELOAD=/edbf/pread_fail_once.so --env FAIL_AT=0 "$C" \
|
mariadb-backup --backup --protocol=socket \
|
--socket=/run/mysqld/mysqld.sock --user=root --target-dir=/tmp/control
|
docker exec "$C" cat /tmp/redo-pread.log
|
docker exec "$C" rm /tmp/redo-pread.log
|
|
|
# Trigger: only the sixth/final redo read returns EIO.
|
set +e
|
docker exec --env LD_PRELOAD=/edbf/pread_fail_once.so --env FAIL_AT=6 "$C" \
|
mariadb-backup --backup --protocol=socket \
|
--socket=/run/mysqld/mysqld.sock --user=root --target-dir=/tmp/trigger
|
RC=$?
|
set -e
|
docker exec "$C" cat /tmp/redo-pread.log
|
docker exec "$C" test -f /tmp/trigger/mariadb_backup_checkpoints
|
printf 'trigger_exit_code=%s\n' "$RC"
|
Actual result
The control had six successful matching reads and ended with `completed OK!`.
In the trigger, the last trace record was the injected failure:
redo_pread ordinal=6 count=2097152 offset=1219072 result=-1 errno=5
|
There was no later matching redo read. Nevertheless the same command printed:
[ERROR] InnoDB: pread("ib_logfile0") returned -1, operating system error 5
|
[00] ... Redo log (from LSN 48242 to 1219219) was copied.
|
[00] ... completed OK!
|
trigger_exit_code=0
|
`mariadb_backup_checkpoints` existed in the trigger target. The server remained
running, was not OOM-killed, and the 4,000-row source table remained readable.
Expected result
An unrecovered redo-log read error should make the backup fail with a nonzero
exit status. The tool must not advertise the requested bytes as valid, say the
redo range was copied, or print `completed OK!` after `log_file_t::read()`
returns `DB_IO_ERROR`.