Weird vanished file name

[moisseev]

file has vanished: "/usr/local/lib/ffsroot/fusr/flocal/flib/attrib"

I am quite sure a file (or several files) has really vanished during the backup, but the logged file name is wrong. The reported file and the directory never existed on both client host and BackupPC server.

Contents of file /var/db/BackupPC/pc/mx_fsroot/XferLOG.2723, modified 2020-10-13 01:35:30 (Extracting only Errors)

XferLOG file /var/db/BackupPC/pc/mx_fsroot/XferLOG.2723 created 2020-10-13 01:17:25 

>>>skipped<<<

Running: /usr/local/bin/rsync_bpc --bpc-top-dir /var/db/BackupPC --bpc-host-name mx_fsroot --bpc-share-name fsroot --bpc-bkup-num 2723 --bpc-bkup-comp 0 --bpc-bkup-prevnum -1 --bpc-bkup-prevcomp -1 --bpc-bkup-inode0 555084 --bpc-log-level 1 --bpc-attrib-new --super --recursive --protect-args --numeric-ids --perms --owner --group -D --times --links --hard-links --delete --delete-excluded --partial --log-format=log:\ %o\ %i\ %B\ %8U,%8G\ %9l\ %f%L --stats --checksum --timeout=72000 --password-file=/var/db/BackupPC/pc/mx_fsroot/.rsyncdpw98269 --exclude=/cdrom --exclude=/dev --exclude=/media --exclude=/mnt --exclude=/proc --exclude=/smb --exclude=/tmp --exclude=/usr/obj --exclude=/usr/ports --exclude=/usr/src --exclude=/var/db/portsnap --exclude=/var/tmp --exclude=/vmail --exclude=/coreland backuppc@mx::fsroot /
full backup started for directory fsroot
Xfer PIDs are now 98289
This is the rsync child about to exec /usr/local/bin/rsync_bpc
Xfer PIDs are now 98289,98290
xferPids 98289,98290
[ skipped 408 lines ]
file has vanished: "/usr/local/lib/ffsroot/fusr/flocal/flib/attrib"
[ skipped 649 lines ]
Done: 0 errors, 194 filesExist, 116904421 sizeExist, 116904421 sizeExistComp, 0 filesTotal, 0 sizeTotal, 123 filesNew, 467075837 sizeNew, 467075837 sizeNewComp, 555229 inode

>>>skipped<<<

DoneGen: 0 errors, 1 filesExist, 32 sizeExist, 32 sizeExistComp, 67806 filesTotal, 4981734188 sizeTotal, 17 filesNew, 554 sizeNew, 554 sizeNewComp, 555234 inode
rsync warning: some files vanished before they could be transferred (code 24) at main.c(1685) [generator=3.1.3.0]
rsync_bpc exited with benign status 24 (6144)

[craigbarratt]

Which version of rsync_bpc is this, and what is the remote rsyncd version?

[moisseev]

rsync-bpc 3.1.3.0
Remote rsyncd version 3.2.3 protocol version 31.

[craigbarratt]

This is internal to rsync_bpc and I can't see how the wrong file name could be generated.

The next step is to increase the logging level of rsync_bpc by adding two or three -v options (eg: -vv or -vvv) to $Conf{RsyncArgs}, and setting $Conf{XferLogLevel} to, say, 6. Since the backup seems quite small, it should be ok to have a relatively high level of debugging.

[moisseev]

...
[generator] make_file(usr/local/info/dir,*,2)
G bpc_readdir -> NULL
G bpc_closedir()
recv_generator(usr/local/info/dir,12304)
G bpc_lstat(usr/local/info/dir)
G bpc_file_checksum(usr/local/info/dir)
G bpc_lstat(usr/local/include/xcb)
recv_generator(usr/local/lib,12305)
G bpc_lstat(usr/local/lib)
delete_in_dir(usr/local/lib)
[generator] pushing local filters for /usr/local/lib/
G bpc_opendir(usr/local/lib)
G bpc_attrib_dirRead(/var/db/BackupPC/pc/mx_fsroot/2749/ffsroot/fusr/flocal/flib/attrib); dirPath = /var/db/BackupPC/pc/mx_fsroot/2749, attribFilePath = ffsroot/fusr/flocal/flib/attrib, attribFileName = attr
ib
G bpc_attrib_dirRead: Got attrib file attrib_032146d5ac080418877cffc74860ffa4: digest = 032146d5ac080418877cffc74860ffa4, len = 16
G bpc_readdir -> .
G bpc_readdir -> ..
G bpc_readdir -> libprotoc.so
G bpc_lstat(usr/local/lib/libprotoc.so)
G bpc_readlink(usr/local/lib/libprotoc.so, buf, 1023)
[generator] make_file(usr/local/lib/libprotoc.so,*,2)
...
G bpc_readdir -> libgettextlib.so
G bpc_lstat(usr/local/lib/libgettextlib.so)
G bpc_readlink(usr/local/lib/libgettextlib.so, buf, 1023)
[generator] make_file(usr/local/lib/libgettextlib.so,*,2)
G bpc_readdir -> ffsroot/fusr/flocal/flib/attrib
G bpc_lstat(usr/local/lib/ffsroot/fusr/flocal/flib/attrib)
G bpc_attrib_dirRead(/var/db/BackupPC/pc/mx_fsroot/2749/ffsroot/fusr/flocal/flib/fffsroot/ffusr/fflocal/fflib/attrib); dirPath = /var/db/BackupPC/pc/mx_fsroot/2749, attribFilePath = ffsroot/fusr/flocal/flib/
fffsroot/ffusr/fflocal/fflib/attrib, attribFileName = attrib
file has vanished: "/usr/local/lib/ffsroot/fusr/flocal/flib/attrib"
G bpc_readdir -> libXext.a
G bpc_lstat(usr/local/lib/libXext.a)
[generator] make_file(usr/local/lib/libXext.a,*,2)
...

Somehow it was written to the attrib file. Probably it is a bug but I am afraid we won't be able to reproduce it. What is the proper way to remove the wrong entry from the attrib file?

# su -m backuppc -c 'BackupPC_attribPrint /var/db/BackupPC/pc/mx_fsroot/2748/ffsroot/fusr/flocal/flib/attrib_032146d5ac080418877cffc74860ffa4' | grep -A 6 ffsroot
  'ffsroot/fusr/flocal/flib/attrib' => {
    'compress' => 0,
    'digest' => '840ecab5effd0357b41c894e45e01943',
    'gid' => 0,
    'inode' => 555010,
    'mode' => 493,
    'mtime' => 1601947653,
    'name' => 'ffsroot/fusr/flocal/flib/attrib',
    'nlinks' => 0,
    'size' => 19,
    'type' => 2,
    'uid' => 0
  },
  'libXext.a' => {

[craigbarratt]

I can't (yet) explain this. The name in the attribute file should not be mangled (both the key and the value inside the hash). The top-level attribute file could have a path for name, but the subdirectory attribute files should be simple names, not paths.

The type of 2 means a symbolic link. The digest should tell us where that link was pointing to. Could you find out what that is:

BackupPC_zcat 840ecab5effd0357b41c894e45e01943

The bug is likely in rsync-bpc 3.1.3.0 somewhere. But localizing it to symlinks definitely narrows it down. I'll look at that code to see if there is anyway this could happen.

[moisseev]

# su -m backuppc -c 'BackupPC_zcat 840ecab5effd0357b41c894e45e01943'
libgobject-2.0.so.0

On the client host:

# ll /usr/local/lib/libgobject-2.0.so.0
lrwxr-xr-x  1 root  wheel  26 24 окт.  04:19 /usr/local/lib/libgobject-2.0.so.0@ -> libgobject-2.0.so.0.6600.2