#2775 Issue closed: mkbackup with Borg tries to backup /mnt/* and dies

Labels: support / question, external tool, no-issue-activity

scruloose opened issue at 2022-03-16 14:10:

  • ReaR version ("/usr/sbin/rear -V"):

    • Relax-and-Recover 2.6-git.4698.a16e8403.master / 2022-03-09

  • OS version ("cat /etc/os-release" or "lsb_release -a" or "cat /etc/rear/os.conf"):

    • Debian Bookworm

  • ReaR configuration files ("cat /etc/rear/site.conf" and/or "cat /etc/rear/local.conf"):

BACKUP=BORG
OUTPUT=RAWDISK
OUTPUT_URL="file:///ReaR"
OUTPUT_PREFIX=""
MODULES=( 'all_modules' )
COPY_AS_IS_EXCLUDE=( "${COPY_AS_IS_EXCLUDE[@]}" /etc/ssh/ssh_host* )
SSH_FILES='yes'
SSH_UNPROTECTED_PRIVATE_KEYS='no'
TIMESYNC=CHRONY
COPY_AS_IS_BORG=( "$ROOT_HOME_DIR/.config/borg/keys/" )
BORGBACKUP_HOST="neo"
BORGBACKUP_USERNAME="borg-$HOSTNAME"
BORGBACKUP_REPO="/~/borg"
BORGBACKUP_ARCHIVE_PREFIX="rear"
BORGBACKUP_COMPRESSION="auto,lz4"
BORGBACKUP_ENC_TYPE="keyfile-blake2"
BORGBACKUP_PRUNE_KEEP_DAILY=7
BORGBACKUP_PRUNE_KEEP_WEEKLY=4
BORGBACKUP_PRUNE_KEEP_MONTHLY=12
export BORG_PASSPHRASE=<redacted>
export BORG_RELOCATED_REPO_ACCESS_IS_OK="yes"
export BORG_UNKNOWN_UNENCRYPTED_REPO_ACCESS_IS_OK="yes"
export BORG_LOGGING_CONF="/etc/rear/borg-logging.conf"

  • Hardware vendor/product (PC or PowerNV BareMetal or ARM) or VM (KVM guest or PowerVM LPAR):

    • Sager laptop; bare metal

  • System architecture (x86 compatible or PPC64/PPC64LE or what exact ARM device):

    • x86_64

  • Firmware (BIOS or UEFI or Open Firmware) and bootloader (GRUB or ELILO or Petitboot):

    • UEFI and GRUB

  • Storage (local disk or SSD) and/or SAN (FC or iSCSI or FCoE) and/or multipath (DM or NVMe):

    • local NVMe

  • Storage layout ("lsblk -ipo NAME,KNAME,PKNAME,TRAN,TYPE,FSTYPE,LABEL,SIZE,MOUNTPOINT"):

/dev/nvme1n1            /dev/nvme1n1
|                                    nvme   disk               465.8G 
|-/dev/nvme1n1p1        /dev/nvme1n1p1
|                             /dev/nvme1n1
|                                    nvme   part  vfat           487M /boot/efi
|-/dev/nvme1n1p2        /dev/nvme1n1p2
|                             /dev/nvme1n1
|                                    nvme   part  ext4           954M /boot
|-/dev/nvme1n1p3        /dev/nvme1n1p3
|                             /dev/nvme1n1
|                                    nvme   part                  16M 
|-/dev/nvme1n1p4        /dev/nvme1n1p4
|                             /dev/nvme1n1
|                                    nvme   part  ntfs         231.4G 
`-/dev/nvme1n1p5        /dev/nvme1n1p5
                              /dev/nvme1n1
                                     nvme   part  crypto       232.9G 
  `-/dev/mapper/nvme0n1p2_crypt
                        /dev/dm-0
                              /dev/nvme1n1p5
                                            crypt LVM2_m       232.9G 
    |-/dev/mapper/rem--vg-vg--root
    |                   /dev/dm-1
    |                         /dev/dm-0
    |                                       lvm   ext4   root  217.9G /
    `-/dev/mapper/rem--vg-vg--swap
                        /dev/dm-2
                              /dev/dm-0
                                            lvm   swap            15G [SWAP]
/dev/nvme0n1            /dev/nvme0n1
|                                    nvme   disk                 1.8T 
`-/dev/nvme0n1p1        /dev/nvme0n1p1
                              /dev/nvme0n1
                                     nvme   part                 1.8T
  • Description of the issue (ideally so that others can reproduce it):
    rear mkbackup runs for a couple of minutes, then aborts. systemctl status rear.service shows the following:
Mar 09 14:45:19 rem rear[317255]: ERROR: Borg failed to create backup archive, borg rc 1!
Mar 09 14:45:19 rem rear[317255]: Some latest log messages since the last called script 500_make_backup.sh:
Mar 09 14:45:19 rem rear[317255]:   2022-03-09 14:44:06.707125026 Creating backup archive 'rear_235' in Borg repository /~/borg on neo
Mar 09 14:45:19 rem rear[317255]: Use debug mode '-d' for some debug messages or debugscript mode '-D' for full debug messages with 'set -x' output
Mar 09 14:45:19 rem rear[317255]: Aborting due to an error, check /var/log/rear/rear-rem.log for details
Mar 09 14:45:22 rem systemd[1]: rear.service: Deactivated successfully.
Mar 09 14:45:22 rem systemd[1]: rear.service: Consumed 2min 35.624s CPU time.

This isn't the primary issue, but I will note that according to the Borg docs, return code 1 indicates that Borg successfully completed, but with warning(s) — not that it failed. I have verified that Borg does successfully create the backup archive. ReaR should probably pass along the warning and keep going in this case, not abort with an error message claiming that Borg failed.

borg.log contents:

2022-03-09 14:44:08,213 INFO Creating archive at "ssh://borg-rem@neo:22/~/borg::rear_235"
2022-03-09 14:44:36,140 WARNING /mnt/<dir1>/<foo>: dir_open: [Errno 19] No such device: 'collab'
2022-03-09 14:44:36,300 WARNING /mnt/<di1r>/<bar>: dir_open: [Errno 19] No such device: 'trinity'
2022-03-09 14:44:36,924 WARNING /mnt/<dir2>: file inode changed (race condition), skipping file
2022-03-09 14:44:38,113 WARNING /mnt/<dir3>: file inode changed (race condition), skipping file
2022-03-09 14:44:38,601 WARNING /mnt/<dir4>/<baz>: file inode changed (race condition), skipping file
2022-03-09 14:44:38,930 WARNING /mnt/<dir5>/<blah> file inode changed (race condition), skipping file
2022-03-09 14:44:39,081 WARNING /mnt/<dir6>: file inode changed (race condition), skipping file

It looks like when ReaR calls Borg to do the backup, it's including things under /mnt, which (to the best of my understanding) should all be excluded automatically.

And here's the rear.log:

Partition table scan:
  MBR: protective
  BSD: not present
  APM: not present
  GPT: present

Found valid GPT with protective MBR; using GPT.
Disk /var/tmp/rear.ZDumIhuP58NgCnr/tmp/rear-rem.raw: 778240 sectors, 380.0 MiB
Sector size (logical): 512 bytes
Disk identifier (GUID): 87B36ABC-0B06-42AA-B830-FBA9CBE2DD1A
Partition table holds up to 128 entries
Main partition table begins at sector 2 and ends at sector 33
First usable sector is 34, last usable sector is 778206
Partitions will be aligned on 2048-sector boundaries
Total free space is 2014 sectors (1007.0 KiB)

Number  Start (sector)    End (sector)  Size       Code  Name
   1            2048          778206   379.0 MiB   EF00  Rescue System
2022-03-16 02:35:45.054100533 Using syslinux to install a Legacy BIOS bootloader
2022-03-16 02:35:45.367482529 Raw disk boot partition capacity after copying:
Filesystem      Size  Used Avail Use% Mounted on
/dev/loop0p1    379M  354M   25M  94% /var/tmp/rear.ZDumIhuP58NgCnr/tmp/boot
2022-03-16 02:35:55.247410124 Including output/default/400_copy_disk_struct_files.sh
2022-03-16 02:35:55.251655077 Including output/default/940_grub2_rescue.sh
2022-03-16 02:35:55.255723780 Including output/default/940_grub_rescue.sh
2022-03-16 02:35:55.260051080 Including output/default/950_copy_result_files.sh
2022-03-16 02:35:55.265194400 Copying resulting files to file location
2022-03-16 02:35:55.270463844 Saving /var/log/rear/rear-rem.log as rear-rem.log to file location
2022-03-16 02:35:55.273341144 Copying result files '/var/tmp/rear.ZDumIhuP58NgCnr/tmp/rear-rem.raw.gz /var/tmp/rear.ZDumIhuP58NgCnr/tmp/VERSION /var/tmp/rear.ZDumIhuP58NgCnr/tmp/README /var/tmp/rear.ZDumIhuP58NgCnr/tmp/rear-rem.log' to /ReaR/ at file location
2022-03-16 02:35:55.552225170 Including output/default/950_email_result_files.sh
2022-03-16 02:35:55.556252181 Including output/default/970_remove_lock.sh
2022-03-16 02:35:55.564144533 Including output/default/980_umount_output_dir.sh
2022-03-16 02:35:55.568271775 Finished running 'output' stage in 16 seconds
2022-03-16 02:35:55.570469638 ======================
2022-03-16 02:35:55.573768830 Running 'backup' stage
2022-03-16 02:35:55.579414682 ======================
2022-03-16 02:35:55.597765085 Including backup/default/010_pre_backup_script.sh
2022-03-16 02:35:55.610350022 Including backup/BORG/default/100_get_suffix.sh
2022-03-16 02:35:55.619167083 Including backup/BORG/default/400_create_include_exclude_files.sh
2022-03-16 02:35:55.624631202 Including backup/BORG/default/500_make_backup.sh
2022-03-16 02:35:55.627234920 Creating backup archive 'rear_241' in Borg repository /~/borg on neo
2022-03-16 02:37:11.016508231 ERROR: Borg failed to create backup archive, borg rc 1!
2022-03-16 02:37:11.022567421 Exiting rear mkbackup (PID 169576) and its descendant processes ...
2022-03-16 02:37:14.074604872 rear,169576 /usr/sbin/rear mkbackup
                                `-rear,189076 /usr/sbin/rear mkbackup
                                    `-pstree,189077 -Aplau 169576
2022-03-16 02:37:14.093484395 Running exit tasks
2022-03-16 02:37:14.097010892 Finished rear mkbackup in 169 seconds
2022-03-16 02:37:14.099265876 Removing build area /var/tmp/rear.ZDumIhuP58NgCnr
2022-03-16 02:37:14.577957829 End of program 'rear' reached

I see in this log that the step Including backup/BORG/default/400_create_include_exclude_files.sh does get called, but of course the temp area gets removed at the end of the run, so I can't check the contents of backup-include.txt.

  • Workaround, if any:

I haven't found any successful workaround yet. I have tried adding the following lines to local.conf:

  • EXCLUDE_BACKUP=( '/mnt' )
  • AUTOEXCLUDE_PATH=( ${AUTOEXCLUDE_PATH[@]}" /mnt )

But rear mkbackup still fails with the same log output shown above.

jsmeix commented at 2022-03-17 12:56:

I didn't have a closer look but on first glance (excerpts from above)

rear mkbackup runs for a couple of minutes, then aborts.
systemctl status rear.service shows the following:
...
Mar 09 14:45:22 rem systemd[1]: rear.service: Deactivated successfully.
Mar 09 14:45:22 rem systemd[1]: rear.service: Consumed 2min 35.624s CPU time.

indicates this issue could be similar as what I described in
https://github.com/rear/rear/issues/840

I know nothing at all about a rear.service for systemd.
As far as I can see there is no rear.service in our sources.
But I am not a systemd expert so I may miss something.

gdha commented at 2022-03-17 13:56:

@scruloose Borg is responsible for the backup not ReaR, therefore, excluding paths from the backup falls under Borgs' configuration settings. ReaR tasks during recovery is creating the empty filesystems and trigger borg to start the restore of the files.
Furthermore, I guess the rear.service is a kind of cron written in systemd?

scruloose commented at 2022-03-17 13:57:

Thanks for taking a look!

I'm pretty confident that what's going on here is unrelated to that issue...

  • udev is not involved at all. I wrote the rear.service systemd unit myself, and it's activated by a timer, not a udev event.
  • The systemd service type is "simple", which neither monitors the status of the command it launches nor enforces any limit on how long it may run.
  • I use the same rear.service unit on several client systems, all using Borg for the backup component, and I've seen it run for many hours and succeed.
  • borg.log clearly indicates that Borg is throwing warnings when it tries to back up various mounts located under /mnt, which it shouldn't be trying to back up in the first place.
  • rear.log shows that ReaR is (wrongly) interpreting Borg's exit status of 1 as a failure and thus aborting the mkbackup workflow. There is no indication that ReaR is being interrupted.

So I'm fairly sure the actual problem is that the rear mkbackup workflow is failing to exclude /mnt/* in its call to Borg, even though it should be excluded by default. I don't know how to determine whether the failure of the include/exclude logic stems from a bug in ReaR or a mistake in my configuration.

gdha commented at 2022-03-17 14:06:

@gozora Hi Vlad - you are our Borg specialist - could you have a look and comment on this issue please?

scruloose commented at 2022-03-17 14:49:

@gdha But Borg is taking all of its instructions from ReaR. There is no Borg configuration, beyond the env-vars and command-line that it receives from ReaR.

The step Including backup/BORG/default/400_create_include_exclude_files.sh creates a temp file called backup-include.txt which is then read by backup/BORG/default/500_make_backup.sh at the step commented as "Create Borg friendly include list."

Presumably some combination of ReaR's various EXCLUDE and AUTOEXCLUDE options determines what goes into that file and thus what inclusions and exclusions ReaR passes when calling Borg... Right?

Yes, my setup is indeed "a kind of cron written in systemd". A timer unit triggers the service unit, which executes rear mkbackup. I chose Type=simple for that service unit specifically because it's the "fire and forget" type: systemd considers the command successful as soon as it's forked off, and pays no attention to how long the process runs or what its exit status is. I'm happy to paste in those unit files, if anyone thinks they're likely to be relevant.

jsmeix commented at 2022-04-04 15:47:

I am not a Borg backup user so I cannot actually help with
Borg backup specific issues (if this one is a Borg backup specific issue).

Because
usr/share/rear/backup/BORG/default/400_create_include_exclude_files.sh
is a symbolic link to
usr/share/rear/backup/NETFS/default/400_create_include_exclude_files.sh
it seems in particular BACKUP_ONLY_INCLUDE could be
also supported for BACKUP=BORG.

See usr/share/rear/conf/default.conf how BACKUP_ONLY_INCLUDE
is meant to work which is currently online at
https://github.com/rear/rear/blob/master/usr/share/rear/conf/default.conf#L1309

I don't know if BACKUP_ONLY_INCLUDE actually works with BACKUP=BORG.
I had BACKUP_ONLY_INCLUDE only tested with 'tar' for BACKUP=NETFS.
If the ReaR default behaviour does not backup what I specifically need
I find it easier to specify exactly what I need in BACKUP_PROG_INCLUDE
plus BACKUP_ONLY_INCLUDE="yes" to switch off ReaR's automatisms.

I cannot imagine why things under /mnt are not automatically
excluded via our default

AUTOEXCLUDE_PATH=( /media /run /mnt /tmp )

in this particular case here.

In general without a full debugscripts log file (i.e. "rear -D mkbackup")
it is impossible to tell what actually happens in this particular case here.
See our issue template
https://github.com/rear/rear/blob/master/.github/ISSUE_TEMPLATE.md
which reads (excerpt)

Attachments, as applicable ("rear -D mkrescue/mkbackup/recover" debug log files)

that is shown when one enters a new issue via the "New issue" button at
https://github.com/rear/rear/issues

You may also have a look at the section
"Debugging issues with Relax-and-Recover" in
https://en.opensuse.org/SDB:Disaster_Recovery

gozora commented at 2022-04-04 16:14:

Hello guys,

I'm sorry, but I've never used OUTPUT=RAWDISK neither with or without Borg so I have no clue of its implications.
When talking about include/exclude of files, BORG should use same config variables and processes as NETFS.

I'm sorry I can't help here more but I really lack spare time nowadays .

@gdha sorry for 18 days delay, but I've probably overlook you mentioning me.

V.

jsmeix commented at 2022-04-05 05:52:

@gozora
no need to be sorry.
You already contributed so much to ReaR so feel free to focus on
and hopefully also enjoy what has topmost priority for you now!

github-actions commented at 2022-06-05 03:00:

Stale issue message

[Export of Github issue for rear/rear.]