Re: [Bacula-users] Bacula and vchanger Cannot Label Volume

Hi Josh,

On Wed, May 11, 2016 at 9:08 PM, Josh Fisher <jfisher AT pvct DOT com> wrote:

The mountpoint with root:root permission is correct. The mountpoint is created by root (a script called from a udev rule) and is a directory on the underlying filesystem until something gets mounted. When another filesystem gets mounted at that mountpoint, then the permissions for the mountpoint path will take on the permissions of the newly mounted filesystem. When the filesystem is unmounted, the permissions for that path will revert back to the underlying filesystem (ie. back to root:root). You need to make sure that the permissions are bacula:tape when it is mounted, but it doesn't matter what the permissions are when it is unmounted.

The vchanger-mount-uuid.sh script first looks in /etc/fstab for a matching uuid. If found, then it uses the mountpoint specified in fstab. If not found, then it creates a mountpoint (if it doesn't already exist) at $MOUNTDIR/$UUID, where $MOUNTDIR is set in /etc/sysconfig/vchanger (or /etc/default/vchanger). By default, if not specified in /etc/sysconfig/vchanger, $MOUNTDIR=/mnt.

This is my /etc/sysconfig/vchanger:

[root@deneb vchanger]# cat /etc/sysconfig/vchanger
MOUNT_DIR=/mnt/vchanger
MOUNT_OPTIONS=
[root@deneb vchanger]#

Yes, the mount point is set to /mnt/vchanger.

If vchanger-mount-uuid.sh is creating the mountpoint directory, but nothing is getting mounted, then most likely your udev is not configured to create the /dev/disk/by-uuid symlinks. The script relies on finding /dev/disk/by-uuid/$UUID, which is a symlink (created by udev rules) pointing to the actual device node assigned to the partition having that UUID.

To see if my udev is creating the symlinks for the device node to /dev/disk/by-uuid, I edited the script vchanger-mount-uuid.sh to output some information to a log file I call /tmp/vchtemp.log. Here's the portion of the vchanger-mount-uuid.sh script that I made the changes just for monitoring purposes:

74         # Mount under configured MOUNT_DIR
75         if [ ! -d $MOUNT_DIR/$uuid ]; then
76           mkdir -p $MOUNT_DIR/$uuid &>/dev/null
77           [ -d $MOUNT_DIR/$uuid ] || exit 0 # cannot create mountpoint dir
78           chmod 0750 $MOUNT_DIR/$uuid
79         fi
80         echo checking dev
81         [ -e /dev/disk/by-uuid/$uuid ] || exit 0 # udev has no by-uuid symlinks
82         echo "`date +"%b %d %T";ls -l /dev/disk/by-uuid`" >> /tmp/vchtemp.log
83         mount $MOUNT_OPTIONS /dev/disk/by-uuid/$uuid $MOUNT_DIR/$uuid &>/dev/null
84         mount | grep $uuid >> /tmp/vchtemp.log
85         if [ $? -eq 0 ] ; then
86                   # On successful mount, cause update slots to be issued in bconsole
87           /usr/bin/vchanger $cf refresh
88         echo `date +"%b %d %T"`": Done vchanger REFRESH" >> /tmp/vchtemp.log
89         mount | grep $uuid >> /tmp/vchtemp.log
90         echo "Sleeping 10s..." >> /tmp/vchtemp.log
91         sleep 10
92         echo `date +"%b %d %T"` >> /tmp/vchtemp.log
93         mount | grep $uuid >> /tmp/vchtemp.log
94         echo "Done" >> /tmp/vchtemp.log
95                 fi
96         exit 0
97       fi
98     fi
99   done
100 done
101 exit 0

Lines 82, 84, 88 - 94 are the ones that I added to output some additional information to /tmp/vchtemp.log.

While inserting the "magazine", I watched the logs: /var/log/vchanger/vchanger01.log and /tmp/vchtemp.log. Note, I set "log level = 7" in /etc/vchanger/vchanger01.conf. Here's the output for /var/log/vchanger/vchanger01.log:

May 12 12:15:48: created lockfile for pid 4533
May 12 12:15:48: magazine 0 has 18 volumes on /mnt/vchanger/1fde15be-83a4-4b67-accc-378d5fa10ea7
May 12 12:15:48: update slots needed. magazine 0 has 18 volumes, previously had 0
May 12 12:15:48: magazine 1 is not mounted
May 12 12:15:48: magazine 2 is not mounted
May 12 12:15:48: magazine 3 is not mounted
May 12 12:15:48: 18 volumes on magazine 0 assigned slots 1-18
May 12 12:15:48: saved state of magazine 0
May 12 12:15:48: saved dynamic configuration (max used slot: 37)
May 12 12:15:48: drive 0 previously unloaded
May 12 12:15:48: ==== preforming REFRESH command pid=4533
May 12 12:15:48:   SUCCESS pid=4533
May 12 12:15:48: removing lockfile for pid 4533
May 12 12:15:48: created update lockfile for pid 4533
May 12 12:15:48: bconsole: running 'update slots storage="vchanger01"'
May 12 12:15:48: popen: child stdin uses pipe (5 -> 6)
May 12 12:15:48: popen: child stdout uses pipe (7 -> 8)
May 12 12:15:48: popen: forking now
May 12 12:15:48: popen: parent closing pipe ends 5,8,-1 used by child
May 12 12:15:48: popen: parent writes child's stdin to 6
May 12 12:15:48: popen: parent reads child's stdout from 7
May 12 12:15:48: popen: parent returning pid=4534 of child
May 12 12:15:48: popen: child closing pipe ends 6,7,-1 used by parent
May 12 12:15:48: popen: child will read stdin from 5
May 12 12:15:48: popen: child will write stdout to 8
May 12 12:15:48: popen: child executing '/usr/sbin/bconsole'
May 12 12:15:48: created lockfile for pid 4539
May 12 12:15:48: restored state of magazine 0
May 12 12:15:48: magazine 0 is not mounted
May 12 12:15:48: update slots needed. magazine 0 no longer mounted; previous: 18 volumes in slots 1-18
May 12 12:15:48: magazine 1 is not mounted
May 12 12:15:48: magazine 2 is not mounted
May 12 12:15:48: magazine 3 is not mounted
May 12 12:15:48: saved dynamic configuration (max used slot: 37)
May 12 12:15:48: drive 0 previously unloaded
May 12 12:15:48: ==== preforming SLOTS command pid=4539
May 12 12:15:48:   SUCCESS reporting 37 slots
May 12 12:15:48: removing lockfile for pid 4539
May 12 12:15:48: created lockfile for pid 4541
May 12 12:15:48: magazine 0 is not mounted
May 12 12:15:48: magazine 1 is not mounted
May 12 12:15:48: magazine 2 is not mounted
May 12 12:15:48: magazine 3 is not mounted
May 12 12:15:48: saved dynamic configuration (max used slot: 37)
May 12 12:15:48: drive 0 previously unloaded
May 12 12:15:48: ==== preforming LOADED command pid=4541
May 12 12:15:48:   SUCCESS reporting drive 0 loaded from slot 0
May 12 12:15:48: removing lockfile for pid 4541
May 12 12:15:48: created lockfile for pid 4542
May 12 12:15:48: magazine 0 is not mounted
May 12 12:15:48: magazine 1 is not mounted
May 12 12:15:48: magazine 2 is not mounted
May 12 12:15:48: magazine 3 is not mounted
May 12 12:15:48: saved dynamic configuration (max used slot: 37)
May 12 12:15:48: drive 0 previously unloaded
May 12 12:15:48: ==== preforming LIST command pid=4542
May 12 12:15:48:   SUCCESS sent list to stdout
May 12 12:15:48: removing lockfile for pid 4542
May 12 12:15:48: bconsole: output:
Connecting to Director deneb.pt.local:9101
1000 OK: 102 bacula-dir Version: 7.4.0 (16 January 2016)
Enter a period to cancel a command.
update slots storage="vchanger01"Automatically selected Catalog: MyCatalog
Using Catalog "MyCatalog"
Connecting to Storage daemon vchanger01 at deneb.pt.local:9103 ...
3306 Issuing autochanger "slots" command.
Device "SATA-vchanger01" has 37 slots.
Connecting to Storage daemon vchanger01 at deneb.pt.local:9103 ...
3306 Issuing autochanger "list" command.
No Volumes found to label, or no barcodes.

May 12 12:15:48: removed update lockfile for pid 4533

And, here is the output for /tmp/vchtemp.log:

May 12 12:15:48
total 0
lrwxrwxrwx 1 root root 10 May 12 12:15 1fde15be-83a4-4b67-accc-378d5fa10ea7 -> ../../sdb1
lrwxrwxrwx 1 root root 10 May 12 10:20 f08f9d6e-a4eb-42a1-8a62-566562ab5ea6 -> ../../sda3
lrwxrwxrwx 1 root root 10 May 12 10:20 f94bef3a-a7ed-4eca-ae1a-330076f36336 -> ../../sda2
lrwxrwxrwx 1 root root 10 May 12 10:20 fd490b6b-21cb-4b20-9ff8-f00832424501 -> ../../sda1
/dev/sdb1 on /mnt/vchanger/1fde15be-83a4-4b67-accc-378d5fa10ea7 type ext4 (rw,relatime,data="">May 12 12:15:48: Done vchanger REFRESH
/dev/sdb1 on /mnt/vchanger/1fde15be-83a4-4b67-accc-378d5fa10ea7 type ext4 (rw,relatime,data="">Sleeping 10s...
May 12 12:15:58
/dev/sdb1 on /mnt/vchanger/1fde15be-83a4-4b67-accc-378d5fa10ea7 type ext4 (rw,relatime,data="">Done

You can see that as I inserted the "magazine", udev DID created the dev node ID /dev/sdb1. As the vchanger-mount-uuid.sh script runs, the filesystem "1fde15be-83a4-4b67-accc-378d5fa10ea7" DID gets mounted as seen by this line, which was output by line 84 mount | grep $uuid >> /tmp/vchtemp.log:

/dev/sdb1 on /mnt/vchanger/1fde15be-83a4-4b67-accc-378d5fa10ea7 type ext4 (rw,relatime,data="">

When the "/usr/bin/vchanger $cf refresh" line completes, the filesystem "1fde15be-83a4-4b67-accc-378d5fa10ea7" was STILL mounted, as seen by these lines:

May 12 12:15:48: Done vchanger REFRESH
/dev/sdb1 on /mnt/vchanger/1fde15be-83a4-4b67-accc-378d5fa10ea7 type ext4 (rw,relatime,data="">

The lines after that are just for me to see if the filesystem was still mounted after 10secs wait. Which, it reports as it still is mounted.

Howerver, on the other hand. from the /var/log/vchanger/vchanger01.log, I can see that the magazine was initially mounted. Then, by the time vchanger attempts to perform the REFRESH command, the magazine was already dismounted:

May 12 12:15:48: created lockfile for pid 4533
May 12 12:15:48: magazine 0 has 18 volumes on /mnt/vchanger/1fde15be-83a4-4b67-accc-378d5fa10ea7
May 12 12:15:48: update slots needed. magazine 0 has 18 volumes, previously had 0
May 12 12:15:48: magazine 1 is not mounted
May 12 12:15:48: magazine 2 is not mounted
May 12 12:15:48: magazine 3 is not mounted
May 12 12:15:48: 18 volumes on magazine 0 assigned slots 1-18
May 12 12:15:48: saved state of magazine 0
May 12 12:15:48: saved dynamic configuration (max used slot: 37)
May 12 12:15:48: drive 0 previously unloaded
May 12 12:15:48: ==== preforming REFRESH command pid=4533
May 12 12:15:48: SUCCESS pid=4533
May 12 12:15:48: removing lockfile for pid 4533
May 12 12:15:48: created update lockfile for pid 4533
May 12 12:15:48: bconsole: running 'update slots storage="vchanger01"'
May 12 12:15:48: popen: child stdin uses pipe (5 -> 6)
May 12 12:15:48: popen: child stdout uses pipe (7 -> 8)
May 12 12:15:48: popen: forking now
May 12 12:15:48: popen: parent closing pipe ends 5,8,-1 used by child
May 12 12:15:48: popen: parent writes child's stdin to 6
May 12 12:15:48: popen: parent reads child's stdout from 7
May 12 12:15:48: popen: parent returning pid=4534 of child
May 12 12:15:48: popen: child closing pipe ends 6,7,-1 used by parent
May 12 12:15:48: popen: child will read stdin from 5
May 12 12:15:48: popen: child will write stdout to 8
May 12 12:15:48: popen: child executing '/usr/sbin/bconsole'
May 12 12:15:48: created lockfile for pid 4539
May 12 12:15:48: restored state of magazine 0
May 12 12:15:48: magazine 0 is not mounted
May 12 12:15:48: update slots needed. magazine 0 no longer mounted; previous: 18 volumes in slots 1-18 <==== Here magazine 0 was no longer mounted
May 12 12:15:48: magazine 1 is not mounted
May 12 12:15:48: magazine 2 is not mounted
May 12 12:15:48: magazine 3 is not mounted
May 12 12:15:48: saved dynamic configuration (max used slot: 37)
May 12 12:15:48: drive 0 previously unloaded

I don't know what's going on behind udev - the filesystem was mounted, but immediately, it gets unmounted. May be someone can shed some light to this mystery.

Thanks again.

Pann

------------------------------------------------------------------------------
Mobile security can be enabling, not merely restricting. Employees who
bring their own devices (BYOD) to work are irked by the imposition of MDM
restrictions. Mobile Device Manager Plus allows you to control only the
apps on BYO-devices by containerizing them, leaving personal data untouched!
https://ad.doubleclick.net/ddm/clk/304595813;131938128;j

_______________________________________________
Bacula-users mailing list
Bacula-users AT lists.sourceforge DOT net
https://lists.sourceforge.net/lists/listinfo/bacula-users