Today I debugged a Bacula backup issue at of the networks I support during spare time. Every backup terminated with an “i/o error reading loaded0 file on magazine in bay 1” error after the first virtual volume was full and a new one should be loaded. I quickly figured out that upon mounting, the loaded0 file was still empty and therefore every unmount request as well as new mount requests just fails.

In order to see what exactly is going on when vchanger tries to load a volume, I ran:


strace -f vchanger /etc/bacula/vchanger.conf -u bacula -g disk load 8 usbchanger1 0


You’ll never guess what the problem was! I forgot to set the number of reserved blocks to zero when preparing the file system of the disks, so from a normal users perspective the disk was just out of space.

Here you can see the important lines of the strace call:
open("/mnt/vchanger/donnerstag/loaded0", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 5
fstat64(5, {st_mode=S_IFREG|0644, st_size=0, ...}) = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb77c2000
write(5, "usbchanger1_0004_0008\n"..., 22) = -1 ENOSPC (No space left on device)
close(5) = 0

A tune2fs -m 0 /dev/sdc1 solved the problem, but why isn’t vchanger’s first load failing with an error message that tells me that it was not possible to update the loaded0 file? I think I am going to write a patch for this now.

UPDATE: Here is my patch to correctly interrupt loading and write useful log information: diskmanager.patch