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

mariabackup reports backup OK even if file closed is failed

    XMLWordPrintable

    Details

    • Type: Bug
    • Status: Open (View Workflow)
    • Priority: Critical
    • Resolution: Unresolved
    • Affects Version/s: 10.5.8
    • Fix Version/s: 10.5
    • Component/s: Backup
    • Labels:
    • Environment:

      Description

      The MariaDB utility correctly identifies that there is a failed closure of a file descriptor (/backup/test8/ib_buffer_pool), but that does not cause the overall status of the backup to changed to a failed status.

      Mariabackup info:

      [01] 2021-04-03 19:34:32 Copying ./mysql/columns_priv.MAD to /backup/test8/mysql/columns_priv.MAD
      [01] 2021-04-03 19:34:32 ...done
      [01] 2021-04-03 19:34:33 Copying ./mysql/columns_priv.MAI to /backup/test8/mysql/columns_priv.MAI
      [01] 2021-04-03 19:34:33 ...done
      [00] 2021-04-03 19:34:33 >> log scanned up to (1225049684)
      [01] 2021-04-03 19:34:33 Copying ./mysql/columns_priv.frm to /backup/test8/mysql/columns_priv.frm
      [01] 2021-04-03 19:34:33 ...done
      [01] 2021-04-03 19:34:34 Copying ./mysql/db.MAD to /backup/test8/mysql/db.MAD
      [01] 2021-04-03 19:34:34 ...done
      [00] 2021-04-03 19:34:34 >> log scanned up to (1225049684)
      [01] 2021-04-03 19:34:34 Copying ./mysql/db.MAI to /backup/test8/mysql/db.MAI
      [01] 2021-04-03 19:34:34 ...done
      [00] 2021-04-03 19:34:35 >> log scanned up to (1225049684)
      [01] 2021-04-03 19:34:35 Copying ./mysql/db.frm to /backup/test8/mysql/db.frm
      [01] 2021-04-03 19:34:35 ...done
      [01] 2021-04-03 19:34:35 Copying ./mysql/db.opt to /backup/test8/mysql/db.opt
      [01] 2021-04-03 19:34:36 ...done
      [00] 2021-04-03 19:34:36 >> log scanned up to (1225049684)
      [01] 2021-04-03 19:34:36 Copying ./mysql/slow_log.CSV to /backup/test8/mysql/slow_log.CSV
      [01] 2021-04-03 19:34:36 ...done
      [01] 2021-04-03 19:34:36 Copying ./performance_schema/db.opt to /backup/test8/performance_schema/db.opt
      [01] 2021-04-03 19:34:36 ...done
      [00] 2021-04-03 19:34:37 >> log scanned up to (1225049684)
      [01] 2021-04-03 19:34:37 Copying ./test/db.opt to /backup/test8/test/db.opt
      [01] 2021-04-03 19:34:37 ...done
      [00] 2021-04-03 19:34:38 >> log scanned up to (1225049684)
      [01] 2021-04-03 19:34:38 Copying ./testdb/db.opt to /backup/test8/testdb/db.opt
      [01] 2021-04-03 19:34:38 ...done
      [00] 2021-04-03 19:34:38 Finished backing up non-InnoDB tables and files
      [01] 2021-04-03 19:34:38 Copying ./aria_log.00000001 to /backup/test8/aria_log.00000001
      [01] 2021-04-03 19:34:38 ...done
      2021-04-03 19:34:39 0 [Note] InnoDB: Read redo log up to LSN=1225050112
      [00] 2021-04-03 19:34:39 >> log scanned up to (1225049684)
      [01] 2021-04-03 19:34:39 Copying ./aria_log_control to /backup/test8/aria_log_control
      [01] 2021-04-03 19:34:39 ...done
      [00] 2021-04-03 19:34:39 Waiting for log copy thread to read lsn 1225049684
      [00] 2021-04-03 19:34:40 >> log scanned up to (1225049684)
      [00] 2021-04-03 19:34:40 Executing FLUSH NO_WRITE_TO_BINLOG ENGINE LOGS...
      [00] 2021-04-03 19:34:40 mariabackup: The latest check point (for incremental): '1225049672'
      mariabackup: Stopping log copying thread.[00] 2021-04-03 19:34:40 >> log scanned up to (1225049684)
      [00] 2021-04-03 19:34:40 >> log scanned up to (1225049684)
      [00] 2021-04-03 19:34:42 Executing BACKUP STAGE END
      [00] 2021-04-03 19:34:42 All tables unlocked
      [00] 2021-04-03 19:34:42 Copying ib_buffer_pool to /backup/test8/ib_buffer_pool
      [00] 2021-04-03 19:34:42 ...done
      mariabackup: Error on close of '/backup/test8/ib_buffer_pool' (errno: 1 "Operation not permitted")
      [00] 2021-04-03 19:34:43 Backup created in directory '/backup/test8/'
      [00] 2021-04-03 19:34:43 Writing backup-my.cnf
      [00] 2021-04-03 19:34:43 ...done
      [00] 2021-04-03 19:34:44 Writing xtrabackup_info
      [00] 2021-04-03 19:34:44 ...done
      [00] 2021-04-03 19:34:44 Redo log (from LSN 1225049672 to 1225049684) was copied.
      [00] 2021-04-03 19:34:45 completed OK!
      [root@att-gptest#

      The MariaDB utility correctly identifies that there is a failed closure of a file descriptor (/backup/test8/ib_buffer_pool), but that does not cause the overall status of the backup to changed to a failed status.

      Note that file copying is not synchronous by designed in Linux, it depends on how the file system is mounted. Normally the file systems are mounted without the dio (direct I/O) option, which means that the return codes from a write call is returned immediately when it arrives to the cache.
      It is only when a flush is called that the actual status is reported back to the caller.
      Note that a flush call is called immediately before a system close() call, which is why it is important to detect and report failed closure of file descriptors.

        Attachments

          Activity

            People

            Assignee:
            bar Alexander Barkov
            Reporter:
            spictera Tomas
            Votes:
            0 Vote for this issue
            Watchers:
            3 Start watching this issue

              Dates

              Created:
              Updated:

                Git Integration