home backup files vanish

[alcina]

Software
XBian version: 1.0 Knockout
XBMC/Kodi version: 18.5 (also a problem when it was 18.3)
Overclock settings: default


Hardware
Device type and model: RPi3B
Power supply rating: 3A
SD card size and make/type: 64G SanDisk SDXC UHS-I (also a problem with 16G SanDisk)
Network (Ethernet or wireless): ethernet
Connected devices: TV, NAS (Netgear) via nfs

Problem description:
The backups of /home disappear the moment they are completed. The backups of system are fine.

In xbian-config I have it set to backup home every day and the system weekly. I have only set this up recently, mostly because I figure I should In the past I have manually rsynced files or done an image of the SD card to back up. It is set to backup to a folder on the NAS. xbian has write permissions to this NAS. The system backup happens and there is the image file. It is about 8.5G. But when I looked there were never any home backups. Using the GUI I told it to backup home 'now'. It started the backup, I checked the NAS and could see the home img.gz file getting bigger and bigger until it got to the approximate size of the xbian home directory - about 6G. Then it disappeared. The log file says:

Code:

2021-04-15 15:08:52.716 T:2063569632   DEBUG: XBian-config : xbian-config xbiancopy homestatus : ['0']
2021-04-15 15:28:59.353 T:2398089952   DEBUG: Previous line repeats 356 times.
2021-04-15 15:28:59.404 T:2398089952   DEBUG: <Event dir=True mask=0x40000200 maskname=IN_DELETE|IN_ISDIR name=xbian-storage path=/run pathname=/run/xbian-storage wd=2 >
2021-04-15 15:28:59.405 T:2063569632   DEBUG: XBian-config : xbian-config xbiancopy homestatus : ['-1']
2021-04-15 15:29:02.409 T:2063569632   DEBUG: getSetting file: /home/xbian/.kodi/userdata/addon_data/plugin.xbianconfig/notifyonerror=1
2021-04-15 15:29:02.431 T:2985345888   DEBUG: ------ Window Init (DialogNotification.xml) ------
2021-04-15 15:29:02.432 T:2985345888   DEBUG: Window DialogNotification.xml was already loaded
2021-04-15 15:29:02.432 T:2985345888   DEBUG: Alloc resources: 0.02ms
2021-04-15 15:29:18.186 T:2985345888   DEBUG: ------ Window Deinit (DialogNotification.xml) ------

At the point the WindowDialogNotification bit happened, the GUI on the tv flashed a notice which said "Can't prepare destination file.." or it might have been "Can't prepare destination files" - it didn't seem to fit the screen and then it disappeared off the screen.

I then used the commandline GUI and selected to backup the home directory to /xbian-backup/temp (so the local SD drive, in case it was a NAS/network issue). Again I watched the file get bigger until it reached the approximate size of the home directory, then the GUI said: "Backup /home process failed!" and the file that had been in /xbian-backup/temp disappeared. This time there was nothing at all in the log file.

Background: This was also happening before I upgraded from 18.3 to 18.5 - I was hoping the upgrade would fix it. My main problem at the time though was the memory leak, for which the answer was "it's been fixed, upgrade!". At the time of upgrading I also changed to a bigger 64G SD card (thank you Nachteule for the excellent instructions on how to do this if it doesn't expand automatically) as I thought that perhaps it was simply running out of space on the card. When I just said "upgrade everything" the Pi would hang on the "network started" screen and get no further. So I would roll back to the previous btrfs (again thank you Nachteule for the clear instructions on how to do this, I am LOVING btrfs!) and try again. Eventually I decided to upgrade the Debian bits, rebooting between almost each one, then when they were all installed I started on upgrading the xbian bits one by one, trying to do them in chronological order. I managed to install all of them except xbian-upgrade. Each time on the reboot it would do the mercury coming together splash screen, then drop into commandline login before reaching the Kodi splash screen. The log file indicated missing python modules ("builtins", then then next time "pyinotify"). I installed those but it is still crashing out into commandline login at boot time. So I haven't installed xbian-upgrade yet. This may be a completely different issue, but I thought I'm mention it in case it is relevant!


How to reproduce:
Try to backup the home directory using the inbuilt tools.

[Nachteule]

What is the destination directory for your backup?

And please show /etc/default/xbian-snap

Sounds to me like it has something to do with these settings

Code:

# how many /home images should be kept (0 means unlimited)
HOMEKEEP=0

[alcina]

Thank for responding.

The destination directory on the NAS is: /mnt/ReadyNAS2/xbian/newbackups The NAS volume that is backed up to is mounted at startup from /etc/fstab as an NFS mount (other volumes, containing the video files are mounted the same but as read only):

Code:

192.168.1.63:/data/Backup    /mnt/ReadyNAS2    nfs    rw,noatime,nosuid,noexec,intr,nolock,vers=3    0    0
192.168.1.63:/data/Videos    /mnt/Videos    nfs    ro,noatime,nosuid,noexec,intr,nolock,vers=3    0    0

/etc/default/xbian-snap:

Code:

#
# This is controlfile for xbian-config console application and Kodi's
# XBian config GUI. Please do not modify this file manually unless you
# know what you are doing.
#


# enable periodic running (daily / weekly / monthly)
ENABLEDSCHEDULE=yes
KEEPDAYS=7
KEEPWEEKS=4
KEEPMONTHS=4

# enable creating of snapshot before APT operations. if wrong packages installed or something stopped working,
# restoration will take few seconds to state before APT run
ENABLEDAPT=yes
KEEPAPT=3

# exclude those subvolumes for scheduled generated snapshots (comma separated list)
EXCLUDESUB=

# Comma separated mount options for mounting IMGDEST and HOMEDEST shares
NFSOPTS=
CIFSOPTS=
SSHFSOPTS=

# auto clone / image creation should be run: none/daily/weekly/monthly
IMGPLAN=weekly

# backup to img file (file) (in case of total SD card corruption, your system can be restored by reflashing this image)
# or directly to block device (block)
IMGTYPE=file

# path to img including file name (/media/my_disk/xbian_backup.img) or block device (/dev/sda1)
IMGDEST="/mnt/ReadyNAS2/xbian/newbackups/$(hostname)_xbian_image_$(date +%F).img"

# how many images should be kept (0 means unlimited)
IMGKEEP=04

# exclude those subvolumes for scheduled generated image backups (comma separated list)
IMGEXCLUDE=

# auto backup of /home should be run: none/daily/weekly/monthly
HOMEPLAN=daily

# path to img.gz including file name (/media/my_disk/xbian_home_backup.img.gz)
HOMEDEST="/mnt/ReadyNAS2/xbian/newbackups/$(hostname)_backup_home_$(date +%F).img.gz"

# how many /home images should be kept (0 means unlimited)
HOMEKEEP=04

[Nachteule]

Hmm, looks ok, but one thing (or two):

Please change IMGKEEP=04 and HOMEKEEP=04 to IMGKEEP=4 and HOMEKEEP=4

and make sure that after HOMEKEEP=4 is a new line character

I have a similar setup and with me nothing has ever disappeared for many years

[alcina]

(17th Apr, 2021 08:26 PM)Nachteule Wrote:  Hmm, looks ok, but one thing (or two):

Please change IMGKEEP=04 and HOMEKEEP=04 to IMGKEEP=4 and HOMEKEEP=4

and make sure that after HOMEKEEP=4 is a new line character

I have a similar setup and with me nothing has ever disappeared for many years

Ok, I did all those, rebooted, and from within the GUI said "backup now". As before the file "xbiansnug_backup_home_2021-04-17.img.gz" appeared in the backup directory on the NAS, got bigger and bigger until it reached approximately the same size as the /home/xbian directory, then....disappeared

Might try manually running btrfs snapshots and send from the commandline and see what they do...

[Nachteule]

Hmmm, really very strange

By the way, the relevant log messages are not in the kodi log but in the syslog (/var/log/syslog) but a syslogger (I use rsyslog) must be active for this

[alcina]

Ok...so I ran:

Code:

btrfs subvolume snapshot -r /home /root/.snaps/home-20210417

to create the snapshot of /home.
It resulted:

Code:

Create a readonly snapshot of '/home' in '/root/.snaps/home-20210417'

Then, to copy the snapshot to an image file on the NAS, I ran:

Code:

btrfs send -v /root/.snaps/home-20210417 > /mnt/ReadyNAS2/xbian/newbackups/home-20210417.img

It resulted:

Code:

At subvol /root/.snaps/home-20210417
BTRFS_IOC_SEND returned 0
joining genl thread

The file was happily sitting there on the NAS

Then, to make it a bit more like /usr/local/sbin/xbian-storager I ran:

Code:

btrfs send -v /root/.snaps/home-20210417 | gzip -1 >> /mnt/ReadyNAS2/xbian/newbackups/home-20210417.img.gz

It resulted:

Code:

At subvol /root/.snaps/home-20210417
BTRFS_IOC_SEND returned 0
joining genl thread

The file was happily sitting there on the NAS

So I installed a syslogger and ran "backup now" from the GUI. All happened exactly as before: the file appeared, it got bigger until it was finished, then immediately disappeared. The relevant syslog lines are:

Code:

Apr 17 16:13:55 xbiansnug btrfs-auto-snapshot: xbiancopy mount /mnt/ReadyNAS2/xbian/newbackups/xbiansnug_backup_home_2021-04-17.img.gz
Apr 17 16:41:12 xbiansnug btrfs-auto-snapshot: xbiancopy umount

To me it looks like the file is getting deleted the moment after it is created. I am presuming lines 1659-1662 in xbian-storager are relevant:

Code:

if [ "$RC" -ne 0 ]; then
        rm -f "$FILE"
        exit 1
    fi

It's looking like it's not receiving an exit code of 0 and so is deleting the file. So I nobbled those lines in xbian-storager:

Code:

if [ "$RC" -ne 0 ]; then
        #rm -f "$FILE"
        echo $RC >> /root/exitcode
        exit 1
    fi

and ran "backup now" from the GUI.

The file appeared on the NAS, it got bigger and bigger until it was nearly the same size as /home, then...it stayed! The contents of /root/exitcode was, as expected, "1"

I ran it again to reproduce the problem. The resultant gzipped image files are all slightly different sizes, with the ones being created by xbian-storager being smaller. I am presuming that is to do with the fact that xbian-storager is taking a snapshot immediately before copying the image over and not much has changed (if I understand vaguely how btrfs snapshots work...)

Code:

-rw-rw-rw- 1 recovery nasbackup 5845568491 Apr 17 16:03 home-20210417.img.gz
-rw-rw-rw- 1 recovery nasbackup 5845567506 Apr 17 17:59 xbiansnug_backup_home_2021-04-17.img.gz
-rw-rw-rw- 1 recovery nasbackup 5845568489 Apr 17 17:21 xbiansnug_backup_home_2021-04-17-1.img.gz

So...next question is to find out why the btrfs send is exiting with code 1, and, is it actually a faulty image or is it a restorable image.

Am considering line 1646 of xbian-storager:

Code:

( btrfs send -v "${tmp_dir}/home/@ro" | pv -i 20 -n -s $(du -sxb ${tmp_dir}/home/@ro | awk '{printf "%d", $1*1.08}') | $packcmd -1 >> "$FILE") 2>&1 | cpb

and redirecting the errors elsewhere rather than to "cpb" (I have no idea what cpb is!!)

[Nachteule]

Code:

cpb () {
                ar=0
                while read a; do
                        echo "$a" | grep -q ^[0-9] && { (($a > $ar)) && ar=$a; echo "$a"; }
                done | eval "$PIPECMD"
        }

See a couple of lines above

One of the program inside of the pipe seems to exit with an error code. The question is which one

[alcina]

Ok, I finally have some time to look again at this! I've left the rm -f "$FILE" line in xbian-storager hashed out and it's been backing up fine despite the exit code of 1 from the pipe.

To try to find out what program in the pipe is exiting with 1, as xbian-storager is a bash script, I utilised $PIPESTATUS to grab the exit code of each program in the pipe. Slightly complicated as the pipe isn't simply a linear command but I think I have it right (please correct if I am wrong!):

Code:

( btrfs send -v "${tmp_dir}/home/@ro" | pv -i 20 -n -s $(du -sxb ${tmp_dir}/home/@ro | awk '{printf "%d", $1*1.08}' && echo "Inner-Inner: ${PIPESTATUS[0]} ${PIPESTATUS[1]}" >> /root/pipestatus) | $packcmd -1 >> "$FILE" && echo "Outer-Inner: ${PIPESTATUS[0]} ${PIPESTATUS[1]} ${PIPESTATUS[2]}" >> /root/pipestatus) 2>&1 | cpb
echo "Outer: ${PIPESTATUS[0]} ${PIPESTATUS[1]}" >> /root/pipestatus

After running "backup now" from the GUI the contents of /root/pipestatus are:

Code:

Inner-Inner: 0 0
Outer-Inner: 0 0 0
Outer: 0 1

So I think the error is coming from cpb, i.e the second exit code in the pipe as a whole. But I don't know why. /tmp/xbiancopy.log contains lots of stuff relating to successful btrfs and ends "Operation sucessfully completed!". /tmp/backuphome.log contains the lines starting with positive digits from the output of pv in the pipe as the grep implies.

[Nachteule]

(27th Apr, 2021 06:13 PM)alcina Wrote:  So I think the error is coming from cpb, i.e the second exit code in the pipe as a whole. But I don't know why. /tmp/xbiancopy.log contains lots of stuff relating to successful btrfs and ends "Operation sucessfully completed!". /tmp/backuphome.log contains the lines starting with positive digits from the output of pv in the pipe as the grep implies.

This was also my first thought, but all tests I have done always lead to the same result: cpb() never terminates with an error in the xbian-storager script.
However, in a simplified test program it does give an error. But why this sometimes brings an error and sometimes not is completely unclear to me.

Terminal

kmnote5:/tmp # cat t.sh
#!/bin/bash

PIPECMD="cat > /tmp/out.log"

cpb () {
ar=0
while read a; do
echo "$a" | grep -q ^[0-9] && { (($a > $ar)) && ar=$a; echo "$a"; }
done | eval $PIPECMD || :
}

set -o pipefail

false | true | echo -e "1\n2\n3\n" | cpb

ps=${PIPESTATUS[*]}
RC=0; for i in $ps; do [ "$i" -ne 0 ] && RC=$i; done
echo $RC, $ps
kmnote5:/tmp # ./t.sh
1, 1 0 0 0

The solution seems simple, just add a ' || :' after the $PIPECMD this deletes the strange error if it occurs.

Code:

diff --git a/content/usr/local/sbin/xbian-storager b/content/usr/local/sbin/xbian-storager
index 3d462ca..98f9dda 100755
--- a/content/usr/local/sbin/xbian-storager
+++ b/content/usr/local/sbin/xbian-storager
@@ -1637,26 +1637,28 @@ do_backuphome ()
        cpb () {
                ar=0
                while read a; do
-                       echo "$a" | grep -q ^[0-9] && { (($a > $ar)) && ar=$a; echo "$a"; }
-               done | eval "$PIPECMD"
+                       echo "$a" | grep -q ^[0-9] && { (($a > $ar)) && ar=$a || ar=100; echo "$ar"; }
+               done | eval "$PIPECMD" || :
        }
        if [ "$opt_fstype" = btrfs ]; then
                btrfs sub delete "${tmp_dir}/home/@ro" 2>/dev/null
                btrfs sub snap -r "${tmp_dir}/home/@" "${tmp_dir}/home/@ro" && \
                ( btrfs send -v "${tmp_dir}/home/@ro" | pv -i 20 -n -s $(du -sxb ${tmp_dir}/home/@ro | awk '{printf "%d", $1*1.08}') | $packcmd -1 >> "$FILE") 2>&1 | cpb
-               RC=$?
+               ps=${PIPESTATUS[*]}
                btrfs sub delete "${tmp_dir}/home/@ro" && btrfs fi sync ${tmp_dir}
        else
                home_ds=$(zfs list -Ho name,mountpoint | grep /home$ | awk '{print $1}')
                zfs destroy ${home_ds}@ro 2>/dev/null
                zfs snapshot ${home_ds}@ro && \
                ( zfs send --props ${home_ds}@ro | pv -i 20 -n -s $(zfs list -Hpo refer,compressratio ${home_ds}@ro | awk '{printf "%d", $1*$2*0.970}') | $packcmd -1 >> "$FILE") 2>&1 | cpb
-               RC=$?
+               ps=${PIPESTATUS[*]}
                zfs destroy ${home_ds}@ro
        fi
        set +o pipefail

+       RC=0; for i in $ps; do [ "$i" -ne 0 ] && RC=$i; done
        if [ "$RC" -ne 0 ]; then
+               echo "Pipe result: $ps" | eval "$PIPECMD"
                rm -f "$FILE"
                exit 1
        fi

[alcina]

I like it! Simple and elegant: if not, true.

And if you can't work out why cpb is producing an error then I don't feel too bad that I can't work it out

I returned the original xbian-storager to its place, changed the $PIPECMD line adding ||: to the end, and ran "backup now" from the GUI. The file appeared on my NAS, got bigger and bigger, and....stayed! Thank you very much for all your help on this!

Now I just have to work out why I can't install xbian-update...a whole new thread!

[Nachteule]

This problem has now been finally solved with this commit