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

mariadb-backup exits 0 and prints completed OK after encrypted redo pread returns EIO

    XMLWordPrintable

Details

    • Bug
    • Status: Open (View Workflow)
    • Major
    • Resolution: Unresolved
    • 12.3.3
    • None
    • Encryption
    • None

    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`.

      Attachments

        Activity

          People

            thiru Thirunarayanan Balathandayuthapani
            csfuzz csfuzz
            Votes:
            0 Vote for this issue
            Watchers:
            1 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.