Mysql backup fails due to closed pipe when exclude_nodump is set #720

New Issue

vierbergenlars · 2023-06-27T11:59:33Z

vierbergenlars commented

2023-06-27 11:59:33 +00:00

What I'm trying to do and why

I am trying to use borgmatic to back up my mysql databases

Steps to reproduce (if a bug)

Set up a mysql database and a borgmatic config file.
Try to run a backup of the database

storage:
    encryption_passphrase: XXXX
    ssh_command: ssh -i /etc/borgmatic/backup-ssh-key

consistency:
    checks:
    - repository
    - archives
location:
    exclude_caches: true
    exclude_if_present:
        - .nobackup
    keep_exclude_tags: true
    exclude_nodump: true
    source_directories:
        - /etc/borgmatic
        - /etc/borgmatic.d
    repositories:
        - XXX
hooks:
    mysql_databases:
        - name: all

Actual behavior (if a bug)

The mysqldump itself fails with an EPIPE error.

I have run borgmatic under strace as well, and I was able to find that borg [...] --dry-run --list opens and closes the pipe file, which results in the mysqldump failing before the actual backup can be started.

root@vps06:~# borgmatic -c /etc/borgmatic.d/db.yml create --verbosity 2
Ensuring legacy configuration is upgraded
/etc/borgmatic.d/db.yml: No commands to run for pre-everything hook
borg --version --debug --show-rc
/etc/borgmatic.d/db.yml: No commands to run for pre-actions hook
/etc/borgmatic.d/db.yml: Running 2 commands for pre-backup hook
/etc/borgmatic/record-metric start /etc/borgmatic.d/db.yml
/etc/borgmatic/record-metric start /etc/borgmatic.d/db.yml
XXX: Creating archive
XXX: Calling postgresql_databases hook function remove_database_dumps
XXX: Removing PostgreSQL database dumps
XXX: Calling mysql_databases hook function remove_database_dumps
XXX: Removing MySQL database dumps
XXX: Calling mongodb_databases hook function remove_database_dumps
XXX: Removing MongoDB database dumps
XXX: Calling mysql_databases hook function dump_databases
XXX: Dumping MySQL databases
XXX: Querying for "all" MySQL databases to dump
mysql --skip-column-names --batch --execute show schemas
XXX: Dumping MySQL database "all" to /root/.borgmatic/mysql_databases/localhost/all
mysqldump --add-drop-database --databases metrics_submitter monitoring_annotations > /root/.borgmatic/mysql_databases/localhost/all
XXX: Collecting special file paths
borg create --exclude-caches --exclude-if-present .nobackup --exclude-if-present .nobackup --keep-exclude-tags --exclude-nodump --one-file-system --read-special XXX::{hostname}-{now:%Y-%m-%dT%H:%M:%S.%f} /etc/borgmatic /etc/borgmatic.d /root/.borgmatic --dry-run --list
borg create --exclude-caches --exclude-if-present .nobackup --exclude-if-present .nobackup --keep-exclude-tags --exclude-nodump --one-file-system --read-special XXX::{hostname}-{now:%Y-%m-%dT%H:%M:%S.%f} /etc/borgmatic /etc/borgmatic.d /root/.borgmatic --debug --show-rc
mysqldump: Got errno 32 on write
XXX: Error running actions for repository
Command 'mysqldump --add-drop-database --databases metrics_submitter monitoring_annotations > /root/.borgmatic/mysql_databases/localhost/all' returned non-zero exit status 5.
/etc/borgmatic.d/db.yml: Running 2 commands for on-error hook
/etc/borgmatic/record-metric error /etc/borgmatic.d/db.yml
/etc/borgmatic/record-metric error /etc/borgmatic.d/db.yml
/etc/borgmatic.d/db.yml: Error running configuration file
/etc/borgmatic.d/db.yml: No commands to run for post-everything hook

summary:
/etc/borgmatic.d/db.yml: Remote repository paths without ssh:// syntax are deprecated. Interpreting "XXX" as "XXX"
/etc/borgmatic.d/db.yml: Error running configuration file
XXX: Error running actions for repository
mysqldump: Got errno 32 on write
Command 'mysqldump --add-drop-database --databases metrics_submitter monitoring_annotations > /root/.borgmatic/mysql_databases/localhost/all' returned non-zero exit status 5.

Need some help? https://torsion.org/borgmatic/#issues

Relevant strace snippets, with comments

# mysqldump is started
[pid 1702367] execve("/bin/sh", ["/bin/sh", "-c", "mysqldump --add-drop-database --"...], 0x7ffd48c8e978 /* 21 vars */ <unfinished ...>
# mysqldump opens pipe for writing
[pid 1702367] openat(AT_FDCWD, "/root/.borgmatic/mysql_databases/localhost/all", O_WRONLY|O_CREAT|O_TRUNC, 0666 <unfinished ...>

# Borg is started in dry-run mode
[pid 1702368] execve("/usr/bin/borg", ["borg", "create", "--exclude-caches", "--exclude-if-present", ".nobackup", "--exclude-if-present", ".nobackup", "--keep-exclude-tags", "--exclude-nodump", "--one-file-system", "--read-special", "XXX"..., "/etc/borgmatic", "/etc/borgmatic.d", "/root/.borgmatic", "--dry-run", "--list"], 0x7f4b497ce660 /* 25 vars */ <unfinished ...>
# It opens the pipe for reading
[pid 1702368] openat(AT_FDCWD, "/root/.borgmatic/mysql_databases/localhost/all", O_RDONLY|O_NONBLOCK|O_NOFOLLOW|O_CLOEXEC <unfinished ...>

#  the mysqldump pipe open returns, and the shell starts executing mysqldump
[pid 1702367] <... openat resumed>)     = 3
[pid 1702367] fcntl(1, F_DUPFD, 10)     = 10
[pid 1702367] close(1)                  = 0
[pid 1702367] fcntl(10, F_SETFD, FD_CLOEXEC) = 0
# pipe is set to be stdout of the mysqldump process
[pid 1702367] dup2(3, 1)                = 1
[pid 1702367] close(3)                  = 0
[pid 1702367] newfstatat(AT_FDCWD, "/usr/bin/mysqldump", {st_mode=S_IFREG|0755, st_size=5076040, ...}, 0) = 0
[pid 1702367] rt_sigprocmask(SIG_SETMASK, ~[RTMIN RT_1], NULL, 8) = 0
# mysqldump is started here
[pid 1702367] vfork( <unfinished ...>

# borg (in dry-run mode) pipe open returns and is immediately closed by borg
[pid 1702368] <... openat resumed>)     = 7
[pid 1702368] ioctl(7, FS_IOC_GETFLAGS, 0x7ffc5ba37348) = -1 ENOTTY (Inappropriate ioctl for device)
[pid 1702368] close(7)                  = 0


# mysqldump process is started by the shell
[pid 1702765] execve("/usr/bin/mysqldump", ["mysqldump", "--add-drop-database", "--databases", "metrics_submitter", "monitoring_annotations"], 0x55d7acc18a88 /* 21 vars */ <unfinished ...>
[pid 1702367] <... vfork resumed>)      = 1702765
# mysqldump tries to write to pipe and receives an error
[pid 1702765] write(1, "-- MariaDB dump 10.19  Distrib 1"..., 4096) = -1 EPIPE (Broken pipe)
[pid 1702765] --- SIGPIPE {si_signo=SIGPIPE, si_code=SI_USER, si_pid=1702765, si_uid=0} ---
[pid 1702765] write(2, "mysqldump: Got errno 32 on write"..., 33) = 33
# mysqldump exits with an error code
[pid 1702765] exit_group(5)             = ?

Expected behavior (if a bug)

Other notes / implementation ideas

This error can be avoided by either omitting the --dry-run --list invocation of borg, or only starting the mysqldump after the dry-run has run.

When starting the mysqldump after the dry-run has run, I think that borg may get stuck while trying to read from the pipe. To solve that problem, you can write some dummy content to the pipe before starting borg in dry-run mode. (e.g. simply echo "" > /root/.borgmatic/mysql_databases/localhost/all i the same way that mysqldump is started now)

Environment

borgmatic version: 1.7.7

borgmatic installation method: Debian package

Borg version: borg 1.2.4

Python version: Python 3.11.2

Database version (if applicable): mysql Ver 15.1 Distrib 10.11.3-MariaDB, for debian-linux-gnu (x86_64) using EditLine wrapper

operating system and version: Debian GNU/Linux 12

#### What I'm trying to do and why I am trying to use borgmatic to back up my mysql databases #### Steps to reproduce (if a bug) Set up a mysql database and a borgmatic config file. Try to run a backup of the database ```yaml storage: encryption_passphrase: XXXX ssh_command: ssh -i /etc/borgmatic/backup-ssh-key consistency: checks: - repository - archives location: exclude_caches: true exclude_if_present: - .nobackup keep_exclude_tags: true exclude_nodump: true source_directories: - /etc/borgmatic - /etc/borgmatic.d repositories: - XXX hooks: mysql_databases: - name: all ``` #### Actual behavior (if a bug) The mysqldump itself fails with an EPIPE error. I have run borgmatic under `strace` as well, and I was able to find that `borg [...] --dry-run --list` opens and closes the pipe file, which results in the mysqldump failing before the actual backup can be started. ``` root@vps06:~# borgmatic -c /etc/borgmatic.d/db.yml create --verbosity 2 Ensuring legacy configuration is upgraded /etc/borgmatic.d/db.yml: No commands to run for pre-everything hook borg --version --debug --show-rc /etc/borgmatic.d/db.yml: No commands to run for pre-actions hook /etc/borgmatic.d/db.yml: Running 2 commands for pre-backup hook /etc/borgmatic/record-metric start /etc/borgmatic.d/db.yml /etc/borgmatic/record-metric start /etc/borgmatic.d/db.yml XXX: Creating archive XXX: Calling postgresql_databases hook function remove_database_dumps XXX: Removing PostgreSQL database dumps XXX: Calling mysql_databases hook function remove_database_dumps XXX: Removing MySQL database dumps XXX: Calling mongodb_databases hook function remove_database_dumps XXX: Removing MongoDB database dumps XXX: Calling mysql_databases hook function dump_databases XXX: Dumping MySQL databases XXX: Querying for "all" MySQL databases to dump mysql --skip-column-names --batch --execute show schemas XXX: Dumping MySQL database "all" to /root/.borgmatic/mysql_databases/localhost/all mysqldump --add-drop-database --databases metrics_submitter monitoring_annotations > /root/.borgmatic/mysql_databases/localhost/all XXX: Collecting special file paths borg create --exclude-caches --exclude-if-present .nobackup --exclude-if-present .nobackup --keep-exclude-tags --exclude-nodump --one-file-system --read-special XXX::{hostname}-{now:%Y-%m-%dT%H:%M:%S.%f} /etc/borgmatic /etc/borgmatic.d /root/.borgmatic --dry-run --list borg create --exclude-caches --exclude-if-present .nobackup --exclude-if-present .nobackup --keep-exclude-tags --exclude-nodump --one-file-system --read-special XXX::{hostname}-{now:%Y-%m-%dT%H:%M:%S.%f} /etc/borgmatic /etc/borgmatic.d /root/.borgmatic --debug --show-rc mysqldump: Got errno 32 on write XXX: Error running actions for repository Command 'mysqldump --add-drop-database --databases metrics_submitter monitoring_annotations > /root/.borgmatic/mysql_databases/localhost/all' returned non-zero exit status 5. /etc/borgmatic.d/db.yml: Running 2 commands for on-error hook /etc/borgmatic/record-metric error /etc/borgmatic.d/db.yml /etc/borgmatic/record-metric error /etc/borgmatic.d/db.yml /etc/borgmatic.d/db.yml: Error running configuration file /etc/borgmatic.d/db.yml: No commands to run for post-everything hook summary: /etc/borgmatic.d/db.yml: Remote repository paths without ssh:// syntax are deprecated. Interpreting "XXX" as "XXX" /etc/borgmatic.d/db.yml: Error running configuration file XXX: Error running actions for repository mysqldump: Got errno 32 on write Command 'mysqldump --add-drop-database --databases metrics_submitter monitoring_annotations > /root/.borgmatic/mysql_databases/localhost/all' returned non-zero exit status 5. Need some help? https://torsion.org/borgmatic/#issues ``` Relevant strace snippets, with comments ``` # mysqldump is started [pid 1702367] execve("/bin/sh", ["/bin/sh", "-c", "mysqldump --add-drop-database --"...], 0x7ffd48c8e978 /* 21 vars */ <unfinished ...> # mysqldump opens pipe for writing [pid 1702367] openat(AT_FDCWD, "/root/.borgmatic/mysql_databases/localhost/all", O_WRONLY|O_CREAT|O_TRUNC, 0666 <unfinished ...> # Borg is started in dry-run mode [pid 1702368] execve("/usr/bin/borg", ["borg", "create", "--exclude-caches", "--exclude-if-present", ".nobackup", "--exclude-if-present", ".nobackup", "--keep-exclude-tags", "--exclude-nodump", "--one-file-system", "--read-special", "XXX"..., "/etc/borgmatic", "/etc/borgmatic.d", "/root/.borgmatic", "--dry-run", "--list"], 0x7f4b497ce660 /* 25 vars */ <unfinished ...> # It opens the pipe for reading [pid 1702368] openat(AT_FDCWD, "/root/.borgmatic/mysql_databases/localhost/all", O_RDONLY|O_NONBLOCK|O_NOFOLLOW|O_CLOEXEC <unfinished ...> # the mysqldump pipe open returns, and the shell starts executing mysqldump [pid 1702367] <... openat resumed>) = 3 [pid 1702367] fcntl(1, F_DUPFD, 10) = 10 [pid 1702367] close(1) = 0 [pid 1702367] fcntl(10, F_SETFD, FD_CLOEXEC) = 0 # pipe is set to be stdout of the mysqldump process [pid 1702367] dup2(3, 1) = 1 [pid 1702367] close(3) = 0 [pid 1702367] newfstatat(AT_FDCWD, "/usr/bin/mysqldump", {st_mode=S_IFREG|0755, st_size=5076040, ...}, 0) = 0 [pid 1702367] rt_sigprocmask(SIG_SETMASK, ~[RTMIN RT_1], NULL, 8) = 0 # mysqldump is started here [pid 1702367] vfork( <unfinished ...> # borg (in dry-run mode) pipe open returns and is immediately closed by borg [pid 1702368] <... openat resumed>) = 7 [pid 1702368] ioctl(7, FS_IOC_GETFLAGS, 0x7ffc5ba37348) = -1 ENOTTY (Inappropriate ioctl for device) [pid 1702368] close(7) = 0 # mysqldump process is started by the shell [pid 1702765] execve("/usr/bin/mysqldump", ["mysqldump", "--add-drop-database", "--databases", "metrics_submitter", "monitoring_annotations"], 0x55d7acc18a88 /* 21 vars */ <unfinished ...> [pid 1702367] <... vfork resumed>) = 1702765 # mysqldump tries to write to pipe and receives an error [pid 1702765] write(1, "-- MariaDB dump 10.19 Distrib 1"..., 4096) = -1 EPIPE (Broken pipe) [pid 1702765] --- SIGPIPE {si_signo=SIGPIPE, si_code=SI_USER, si_pid=1702765, si_uid=0} --- [pid 1702765] write(2, "mysqldump: Got errno 32 on write"..., 33) = 33 # mysqldump exits with an error code [pid 1702765] exit_group(5) = ? ``` #### Expected behavior (if a bug) #### Other notes / implementation ideas This error can be avoided by either omitting the `--dry-run --list` invocation of borg, or only starting the mysqldump *after* the dry-run has run. When starting the mysqldump after the dry-run has run, I think that borg may get stuck while trying to read from the pipe. To solve that problem, you can write some dummy content to the pipe before starting borg in dry-run mode. (e.g. simply `echo "" > /root/.borgmatic/mysql_databases/localhost/all` i the same way that mysqldump is started now) #### Environment **borgmatic version:** 1.7.7 **borgmatic installation method:** Debian package **Borg version:** borg 1.2.4 **Python version:** Python 3.11.2 **Database version (if applicable):** mysql Ver 15.1 Distrib 10.11.3-MariaDB, for debian-linux-gnu (x86_64) using EditLine wrapper **operating system and version:** Debian GNU/Linux 12

witten commented

2023-06-27 18:02:02 +00:00

Thanks for filing the detailed ticket + annotated strace logs! I've tried to repro this locally, but thus far I haven't had any luck even though I'm using the same version of borgmatic and Borg and MariaDB. (Although my version of mysqldump is 10.11.2.)

Looking at the comparable strace -f on my own system though, I'm only seeing the mysqldump opening the named pipe. The Borg dry run appears to be stat-ing it, but that's it. So given that we're using the exact same version of Borg, do you have any ideas as to what might be causing this difference in behavior? Here's my Borg dry run invocation from strace, which looks very similar to yours minus some of the exclude flags:

[pid 137201] execve("/usr/bin/borg", ["borg", "create", "--one-file-system", "--read-special", "1.2.borg::{hostname}-{now:%Y-%m-"..., "/root/.borgmatic", "/root/tmp/dst", "--dry-run", "--list"], 0x7fdd560ceb80 /* 16 vars */ <unfinished ...>

If it comes to it, I could try spinning up a Debian VM just to attempt to get a better repro.

Thanks for filing the detailed ticket + annotated strace logs! I've tried to repro this locally, but thus far I haven't had any luck even though I'm using the same version of borgmatic and Borg and MariaDB. (Although my version of `mysqldump` is 10.11.2.) Looking at the comparable `strace -f` on my own system though, I'm only seeing the `mysqldump` opening the named pipe. The Borg dry run appears to be stat-ing it, but that's it. So given that we're using the exact same version of Borg, do you have any ideas as to what might be causing this difference in behavior? Here's my Borg dry run invocation from strace, which looks very similar to yours minus some of the exclude flags: ``` [pid 137201] execve("/usr/bin/borg", ["borg", "create", "--one-file-system", "--read-special", "1.2.borg::{hostname}-{now:%Y-%m-"..., "/root/.borgmatic", "/root/tmp/dst", "--dry-run", "--list"], 0x7fdd560ceb80 /* 16 vars */ <unfinished ...> ``` If it comes to it, I could try spinning up a Debian VM just to attempt to get a better repro.

vierbergenlars commented

2023-06-28 07:49:30 +00:00

Both borg and borgmatic are the version from the debian repositories.

I just tried running the backup without the exclude flags, they are not important here, but were included from a global configuration.

It looks like borg does take a different approach and does not open any files now, it only opens and reads directories now, it doesn't open the pipe itself.

[pid 2079479] execve("/usr/bin/borg", ["borg", "create", "--one-file-system", "--read-special", "XXX"..., "/etc/borgmatic", "/etc/borgmatic.d", "/root/.borgmatic", "--dry-run", "--list"], 0x7ff221e16f70 /* 26 vars */ <unfinished ...>
[pid 2079479] openat(AT_FDCWD, "/root", O_RDONLY|O_NOATIME|O_CLOEXEC) = 3
[pid 2079479] openat(3, ".borgmatic", O_RDONLY|O_NOFOLLOW|O_NOATIME|O_CLOEXEC|O_DIRECTORY) = 4
[pid 2079479] newfstatat(4, "", {st_mode=S_IFDIR|0755, st_size=4096, ...}, AT_EMPTY_PATH) = 0
[pid 2079479] fcntl(4, F_DUPFD_CLOEXEC, 0) = 5
[pid 2079479] newfstatat(5, "", {st_mode=S_IFDIR|0755, st_size=4096, ...}, AT_EMPTY_PATH) = 0
[pid 2079479] fcntl(5, F_GETFL)         = 0x78000 (flags O_RDONLY|O_LARGEFILE|O_NOFOLLOW|O_NOATIME|O_DIRECTORY)
[pid 2079479] fcntl(5, F_SETFD, FD_CLOEXEC) = 0
[pid 2079479] getdents64(5, 0x2f344e0 /* 4 entries */, 32768) = 120
[pid 2079479] getdents64(5, 0x2f344e0 /* 0 entries */, 32768) = 0
[pid 2079479] lseek(5, 0, SEEK_SET)     = 0
[pid 2079479] close(5)                  = 0
[pid 2079479] newfstatat(4, "mysql_databases", {st_mode=S_IFDIR|0755, st_size=4096, ...}, AT_SYMLINK_NOFOLLOW) = 0
[pid 2079479] openat(4, "mysql_databases", O_RDONLY|O_NOFOLLOW|O_NOATIME|O_CLOEXEC|O_DIRECTORY) = 5
[pid 2079479] newfstatat(5, "", {st_mode=S_IFDIR|0755, st_size=4096, ...}, AT_EMPTY_PATH) = 0
[pid 2079479] fcntl(5, F_DUPFD_CLOEXEC, 0) = 6
[pid 2079479] newfstatat(6, "", {st_mode=S_IFDIR|0755, st_size=4096, ...}, AT_EMPTY_PATH) = 0
[pid 2079479] fcntl(6, F_GETFL)         = 0x78000 (flags O_RDONLY|O_LARGEFILE|O_NOFOLLOW|O_NOATIME|O_DIRECTORY)
[pid 2079479] fcntl(6, F_SETFD, FD_CLOEXEC) = 0
[pid 2079479] getdents64(6, 0x2f344e0 /* 3 entries */, 32768) = 80
[pid 2079479] getdents64(6, 0x2f344e0 /* 0 entries */, 32768) = 0
[pid 2079479] lseek(6, 0, SEEK_SET)     = 0
[pid 2079479] close(6)                  = 0
[pid 2079479] newfstatat(5, "localhost", {st_mode=S_IFDIR|0700, st_size=4096, ...}, AT_SYMLINK_NOFOLLOW) = 0
[pid 2079479] openat(5, "localhost", O_RDONLY|O_NOFOLLOW|O_NOATIME|O_CLOEXEC|O_DIRECTORY) = 6
[pid 2079479] newfstatat(6, "", {st_mode=S_IFDIR|0700, st_size=4096, ...}, AT_EMPTY_PATH) = 0
[pid 2079479] fcntl(6, F_DUPFD_CLOEXEC, 0) = 7
[pid 2079479] newfstatat(7, "", {st_mode=S_IFDIR|0700, st_size=4096, ...}, AT_EMPTY_PATH) = 0
[pid 2079479] fcntl(7, F_GETFL)         = 0x78000 (flags O_RDONLY|O_LARGEFILE|O_NOFOLLOW|O_NOATIME|O_DIRECTORY)
[pid 2079479] fcntl(7, F_SETFD, FD_CLOEXEC) = 0
[pid 2079479] getdents64(7, 0x2f344e0 /* 3 entries */, 32768) = 72
[pid 2079479] getdents64(7, 0x2f344e0 /* 0 entries */, 32768) = 0
[pid 2079479] lseek(7, 0, SEEK_SET)     = 0
[pid 2079479] close(7)                  = 0
[pid 2079479] newfstatat(6, "all", {st_mode=S_IFIFO|0600, st_size=0, ...}, AT_SYMLINK_NOFOLLOW) = 0
[pid 2079479] getpid()                  = 2079479
[pid 2079479] write(2, "- /root/.borgmatic/mysql_databas"..., 49 <unfinished ...>
[pid 2079454] <... read resumed>"- /root/.borgmatic/mysql_databas"..., 7917) = 49
[pid 2079479] <... write resumed>)      = 49

Both borg and borgmatic are the version from the debian repositories. I just tried running the backup without the exclude flags, they are not important here, but were included from a global configuration. It looks like borg does take a different approach and does not open any files now, it only opens and reads directories now, it doesn't open the pipe itself. ``` [pid 2079479] execve("/usr/bin/borg", ["borg", "create", "--one-file-system", "--read-special", "XXX"..., "/etc/borgmatic", "/etc/borgmatic.d", "/root/.borgmatic", "--dry-run", "--list"], 0x7ff221e16f70 /* 26 vars */ <unfinished ...> [pid 2079479] openat(AT_FDCWD, "/root", O_RDONLY|O_NOATIME|O_CLOEXEC) = 3 [pid 2079479] openat(3, ".borgmatic", O_RDONLY|O_NOFOLLOW|O_NOATIME|O_CLOEXEC|O_DIRECTORY) = 4 [pid 2079479] newfstatat(4, "", {st_mode=S_IFDIR|0755, st_size=4096, ...}, AT_EMPTY_PATH) = 0 [pid 2079479] fcntl(4, F_DUPFD_CLOEXEC, 0) = 5 [pid 2079479] newfstatat(5, "", {st_mode=S_IFDIR|0755, st_size=4096, ...}, AT_EMPTY_PATH) = 0 [pid 2079479] fcntl(5, F_GETFL) = 0x78000 (flags O_RDONLY|O_LARGEFILE|O_NOFOLLOW|O_NOATIME|O_DIRECTORY) [pid 2079479] fcntl(5, F_SETFD, FD_CLOEXEC) = 0 [pid 2079479] getdents64(5, 0x2f344e0 /* 4 entries */, 32768) = 120 [pid 2079479] getdents64(5, 0x2f344e0 /* 0 entries */, 32768) = 0 [pid 2079479] lseek(5, 0, SEEK_SET) = 0 [pid 2079479] close(5) = 0 [pid 2079479] newfstatat(4, "mysql_databases", {st_mode=S_IFDIR|0755, st_size=4096, ...}, AT_SYMLINK_NOFOLLOW) = 0 [pid 2079479] openat(4, "mysql_databases", O_RDONLY|O_NOFOLLOW|O_NOATIME|O_CLOEXEC|O_DIRECTORY) = 5 [pid 2079479] newfstatat(5, "", {st_mode=S_IFDIR|0755, st_size=4096, ...}, AT_EMPTY_PATH) = 0 [pid 2079479] fcntl(5, F_DUPFD_CLOEXEC, 0) = 6 [pid 2079479] newfstatat(6, "", {st_mode=S_IFDIR|0755, st_size=4096, ...}, AT_EMPTY_PATH) = 0 [pid 2079479] fcntl(6, F_GETFL) = 0x78000 (flags O_RDONLY|O_LARGEFILE|O_NOFOLLOW|O_NOATIME|O_DIRECTORY) [pid 2079479] fcntl(6, F_SETFD, FD_CLOEXEC) = 0 [pid 2079479] getdents64(6, 0x2f344e0 /* 3 entries */, 32768) = 80 [pid 2079479] getdents64(6, 0x2f344e0 /* 0 entries */, 32768) = 0 [pid 2079479] lseek(6, 0, SEEK_SET) = 0 [pid 2079479] close(6) = 0 [pid 2079479] newfstatat(5, "localhost", {st_mode=S_IFDIR|0700, st_size=4096, ...}, AT_SYMLINK_NOFOLLOW) = 0 [pid 2079479] openat(5, "localhost", O_RDONLY|O_NOFOLLOW|O_NOATIME|O_CLOEXEC|O_DIRECTORY) = 6 [pid 2079479] newfstatat(6, "", {st_mode=S_IFDIR|0700, st_size=4096, ...}, AT_EMPTY_PATH) = 0 [pid 2079479] fcntl(6, F_DUPFD_CLOEXEC, 0) = 7 [pid 2079479] newfstatat(7, "", {st_mode=S_IFDIR|0700, st_size=4096, ...}, AT_EMPTY_PATH) = 0 [pid 2079479] fcntl(7, F_GETFL) = 0x78000 (flags O_RDONLY|O_LARGEFILE|O_NOFOLLOW|O_NOATIME|O_DIRECTORY) [pid 2079479] fcntl(7, F_SETFD, FD_CLOEXEC) = 0 [pid 2079479] getdents64(7, 0x2f344e0 /* 3 entries */, 32768) = 72 [pid 2079479] getdents64(7, 0x2f344e0 /* 0 entries */, 32768) = 0 [pid 2079479] lseek(7, 0, SEEK_SET) = 0 [pid 2079479] close(7) = 0 [pid 2079479] newfstatat(6, "all", {st_mode=S_IFIFO|0600, st_size=0, ...}, AT_SYMLINK_NOFOLLOW) = 0 [pid 2079479] getpid() = 2079479 [pid 2079479] write(2, "- /root/.borgmatic/mysql_databas"..., 49 <unfinished ...> [pid 2079454] <... read resumed>"- /root/.borgmatic/mysql_databas"..., 7917) = 49 [pid 2079479] <... write resumed>) = 49 ```

vierbergenlars commented

2023-06-28 08:13:35 +00:00

I found the cause of the different path in borg.

When exclude_nodump: true, borg tries to read the flags.

https://github.com/borgbackup/borg/blob/1.2.4/src/borg/archiver.py#L776-L781

For the linux platform, this results in the file being opened, an ioctl being executed and then the file being closed.

https://github.com/borgbackup/borg/blob/1.2.4/src/borg/platform/linux.pyx#L156

The same behavior is still there in the latest version.

At this point, I'm not sure if this should be considered a bug in borg or in borgmatic.

With the same exclude options, borg itself works fine to run the backup, as long as you don't use --dry-run first without restarting the mysqldump on the other side of the pipe.

I found the cause of the different path in borg. When `exclude_nodump: true`, borg tries to read the flags. https://github.com/borgbackup/borg/blob/1.2.4/src/borg/archiver.py#L776-L781 For the linux platform, this results in the file being opened, an ioctl being executed and then the file being closed. https://github.com/borgbackup/borg/blob/1.2.4/src/borg/platform/linux.pyx#L156 The same behavior is still there in the latest version. At this point, I'm not sure if this should be considered a bug in borg or in borgmatic. With the same exclude options, borg itself works fine to run the backup, as long as you don't use `--dry-run` first without restarting the mysqldump on the other side of the pipe.

witten commented

2023-06-28 15:48:34 +00:00

Amazing detective work!

It looks like borg does take a different approach and does not open any files now, it only opens and reads directories now, it doesn't open the pipe itself.

I found the cause of the different path in borg.

When exclude_nodump: true, borg tries to read the flags.

So am I to take it that without exclude_nodump, this borgmatic MySQL error stops happening and the action succeeds?

At this point, I'm not sure if this should be considered a bug in borg or in borgmatic.

I think it's fair to call it an unfortunate interaction between the two. It wouldn't be the first—the whole purpose of the dry run to begin with is to find special files so that they can be auto-excluded to prevent Borg from hanging due to an interaction with borgmatic's named pipe!

In any case, I think this is probably something borgmatic can work around. Omitting the --exclude-nodump flag on the dry run (only) should be easy enough, and it sounds like that should sidestep the issue in this ticket.

Amazing detective work! > It looks like borg does take a different approach and does not open any files now, it only opens and reads directories now, it doesn't open the pipe itself. > I found the cause of the different path in borg. > > When exclude_nodump: true, borg tries to read the flags. So am I to take it that without `exclude_nodump`, this borgmatic MySQL error stops happening and the action succeeds? > At this point, I'm not sure if this should be considered a bug in borg or in borgmatic. I think it's fair to call it an unfortunate interaction between the two. It wouldn't be the first—the whole purpose of the dry run to begin with is to find special files so that they can be auto-excluded to prevent Borg from hanging due to an interaction with borgmatic's named pipe! In any case, I think this is probably something borgmatic can work around. Omitting the `--exclude-nodump` flag on the dry run (only) should be easy enough, and it sounds like that should sidestep the issue in this ticket.

witten added the

bug

label 2023-06-28 15:49:02 +00:00

witten changed title from ~~Mysql backup fails due to closed pipe~~ to Mysql backup fails due to closed pipe when exclude_nodump is set

2023-06-28 15:49:45 +00:00

witten referenced this issue from a commit

2023-06-28 16:15:26 +00:00

Fix an error when dumping a MySQL database and the "exclude_nodump" option is set (#720).

witten commented

2023-06-28 16:17:52 +00:00

I've got a local repro now and confirmed that with the exclude_nodump option, the MySQL error happens. And also that without exclude_nodump, the error goes away. So I went ahead and omitted --exclude-nodump inside the dry run code, and now things appear to work even when the option is set in borgmatic's configuration file. This fix will be part of the next release.. Thanks again for all your work here!

I've got a local repro now and confirmed that with the `exclude_nodump` option, the MySQL error happens. And also that without `exclude_nodump`, the error goes away. So I went ahead and omitted `--exclude-nodump` inside the dry run code, and now things appear to work even when the option is set in borgmatic's configuration file. This fix will be part of the next release.. Thanks again for all your work here!

witten closed this issue

2023-06-28 16:17:52 +00:00

jchristgit commented

2023-07-15 09:27:01 +00:00

I found the same behaviour with PostgreSQL, pg_dumpall would fail with code 141 when exclude_nodump: true is set, but outside of dry runs. Removing exclude_nodump: true fixes the issue. Is it possible PostgreSQL databases are treated differently compared to MySQL for dumps?

I found the same behaviour with PostgreSQL, `pg_dumpall` would fail with code 141 when `exclude_nodump: true` is set, but outside of dry runs. Removing `exclude_nodump: true` fixes the issue. Is it possible PostgreSQL databases are treated differently compared to MySQL for dumps?

witten commented

2023-07-17 17:43:09 +00:00

@jchristgit Are you running main or a released version of borgmatic? The fix in this ticket (which should apply to PostgreSQL too) hasn't been released yet; it'll go out in 1.8.0.

@jchristgit Are you running main or a released version of borgmatic? The fix in this ticket (which *should* apply to PostgreSQL too) hasn't been released yet; it'll go out in 1.8.0.

witten commented

2023-07-19 06:02:28 +00:00

Released in borgmatic 1.8.0!

❤️ 1

jchristgit commented

2023-07-19 07:24:58 +00:00

Ah sorry, looks like my previous reply per mail didn't arrive - per your suggestion, I should have tested with main first, I cannot reproduce the issue there even without dry run... Thank you so much!

👍 1

Sign in to join this conversation.