Opened 2 years ago

Closed 21 months ago

#253 closed defect (fixed)

vbd attach race condition

Reported by: joanna Owned by: rafal
Priority: major Milestone: Release 1 Beta 2
Component: core Keywords:
Cc:

Description

Non-deterministic problem with attaching the blkbacked for the xvda to the first VM in the system. Can only reproduce on one test machine (it has a very fast SSD driver, which might contribute to the race).

Change History (15)

comment:1 Changed 2 years ago by joanna

  • Priority changed from major to critical

comment:2 Changed 23 months ago by joanna

Keep getting this every once in a while, even after I started using the recent 2.6.38 kernel in VMs...

comment:3 Changed 23 months ago by joanna

Hint: adding a few (VERY UGLY!) sleeps seem to solve the problem:

​http://git.qubes-os.org/?p=joanna/core.git;a=commitdiff;h=3bd1c700f6d97db2354a459f8e7b2e4473e7e41c

Of course this is an unacceptable solution. Among other things it slows down the VM startup time. Also it's just wrong...

comment:4 Changed 23 months ago by marmarek

  • Owner changed from joanna to marmarek
  • Status changed from new to assigned

comment:5 Changed 23 months ago by marmarek

  • Resolution set to fixed
  • Status changed from assigned to closed

Workarounded by wrapping hotplug script with flock
​http://git.qubes-os.org/gitweb/?p=marmarek/core.git;a=commit;h=bfe28d5ee6b780f6333955069d873c31d519510e

comment:6 Changed 22 months ago by joanna

  • Resolution fixed deleted
  • Status changed from closed to reopened

Still present! (as of core 1.6.12, kernel 2.6.38.3-7, xen 4.1.0-7)

[    0.195851] XENBUS: Device with no driver: device/vbd/51712
[    0.195854] XENBUS: Device with no driver: device/vbd/51728
[    0.195857] XENBUS: Device with no driver: device/vbd/51744
[    0.195860] XENBUS: Device with no driver: device/vbd/51760
[    0.195864] /home/joanna/qubes/kernel/kernel-2.6.38.3/linux-2.6.38.3/drivers/rtc/hctosys.c: unable to open rtc device (rtc0)
[    0.196108] Freeing unused kernel memory: 372k freed
[    0.196236] Write protecting the kernel read-only data: 6868k
[    0.216561] dracut: dracut-005-3.fc13
Qubes initramfs script here:
[    5.340160] XENBUS: Waiting for devices to initialise: 295s...290s...285s...280s...275s...270s...265s...260s...255s...250s...245s...240s...235s...230s...225s...220s...215s...210s...205s...
[   95.829408] xen-vbd: registered block device major 202
[   95.829493] blkfront: xvda: barriers enabled
[   95.832946]  xvda: unknown partition table
[   96.038283] blkfront: xvdb: barriers enabled
[   96.039636]  xvdb: unknown partition table
[   96.242524] blkfront: xvdc: barriers enabled
[   96.243839]  xvdc: xvdc1 xvdc2
[   96.441737] blkfront: xvdd: barriers enabled
[   96.443027]  xvdd: unknown partition table
[   96.540161] 
Waiting for /dev/xvda* devices...
Qubes: Doing COW setup for AppVM...
Qubes: done.
[   96.567113] dracut: rd_NO_MDIMSM: no MD RAID for imsm/isw raids
[   96.571136] udev: starting version 153
[   96.571245] udevd (65): /proc/65/oom_adj is deprecated, please use /proc/65/oom_score_adj instead.
[   99.844068] EXT4-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null)
[   99.862670] dracut: Remounting /dev/mapper/dmroot with -o noatime,ro
[   99.867042] EXT4-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null)
[   99.871478] dracut: Mounted root filesystem /dev/mapper/dmroot
Waiting for /dev/xvdd device...
[   99.895883] kjournald starting.  Commit interval 15 seconds
[   99.895922] EXT3-fs (xvdd): mounted filesystem with ordered data mode
[   99.914039] dracut: Loading SELinux policy
[   99.956117] dracut: /sbin/load_policy: Can't load policy: No such device
[   99.998116] dracut: Switching root
[  100.148670] usbcore: registered new interface driver usbfs
[  100.148710] usbcore: registered new interface driver hub
[  100.148794] usbcore: registered new device driver usb
                Welcome to Fedora

comment:7 Changed 22 months ago by joanna

  • Owner changed from marmarek to rafal
  • Status changed from reopened to assigned

comment:8 Changed 22 months ago by rafal

Please add 

PS4=-"$$"-'\D{%s}-'
set -x

to /etc/xen/scripts/block at line 7 (after HOTPLUG_STORE=... line).
And similarly please add 

PS4=+"$$"+'\D{%s}+'
set -x

to /etc/xen/scripts/block-snapshot at line 17 (after HOTPLUG_STORE=... line).
After problem has manifested itself, please upload /var/log/xen/xen-hotplug.log, and contents of /proc/mounts taken from VM that was so delayed.

comment:9 Changed 22 months ago by joanna

Now the VM doesn't start at all (I can reproduce it almost with every other boot)! The xen-hotplug below:

++2731+1311699329+xenstore_read_default backend/vbd/2/51712/type MISSING
++2731+1311699329+xenstore-read backend/vbd/2/51712/type
++2731+1311699329+echo MISSING
+2731+1311699329+t=MISSING
+2731+1311699329+case "$command" in
+2731+1311699329+'[' remove = cleanup ']'
++2731+1311699329+cat /var/run/xen-hotplug/backend-vbd-2-51712-type
+2731+1311699329+t=snapshot
+2731+1311699329+case $t in
+2731+1311699329+'[' remove = cleanup ']'
++2731+1311699329+cat /var/run/xen-hotplug/backend-vbd-2-51712-node
+2731+1311699329+node=/dev/mapper/snapshot-fd00:1971082-fd00:1971095
+2731+1311699329+'[' -z /dev/mapper/snapshot-fd00:1971082-fd00:1971095 ']'
+2731+1311699329+'[' '!' -e /dev/mapper/snapshot-fd00:1971082-fd00:1971095 ']'
+2731+1311699329+claim_lock block
+2731+1311699329+local lockdir=/var/run/xen-hotplug/block
+2731+1311699329+mkdir -p /var/run/xen-hotplug
+2731+1311699329+_claim_lock /var/run/xen-hotplug/block
+2731+1311699329+local lockdir=/var/run/xen-hotplug/block
++2731+1311699329+_lock_owner /var/run/xen-hotplug/block
++2731+1311699329+cat /var/run/xen-hotplug/block/owner
+2731+1311699329+local 'owner=2701: /etc/xen/scripts/xen-hotplug-cleanup'
+2731+1311699329+local retries=0
+2731+1311699329+'[' 0 -lt 100 ']'
+2731+1311699329+mkdir /var/run/xen-hotplug/block
++2731+1311699329+_lock_owner /var/run/xen-hotplug/block
++2731+1311699329+cat /var/run/xen-hotplug/block/owner
+2731+1311699329+local 'new_owner=2701: /etc/xen/scripts/xen-hotplug-cleanup'
+2731+1311699329+'[' '2701: /etc/xen/scripts/xen-hotplug-cleanup' '!=' '2701: /etc/xen/scripts/xen-hotplug-cleanup' ']'
++2731+1311699329+echo 2701: /etc/xen/scripts/xen-hotplug-cleanup
++2731+1311699329+cut -d : -f 1
+2731+1311699329+local pid=2701
+2731+1311699329+'[' -n 2701 -a 2701 '!=' unknown -a '!' -f /proc/2701/status ']'
+2731+1311699329+_release_lock /var/run/xen-hotplug/block
+2731+1311699329+trap sigerr ERR
+2731+1311699329+rm -rf /var/run/xen-hotplug/block
+2731+1311699329+'[' 0 -gt 5 ']'
+2731+1311699329+sleep 0
+2731+1311699329+retries=1
+2731+1311699329+'[' 1 -lt 100 ']'
+2731+1311699329+mkdir /var/run/xen-hotplug/block
+2731+1311699329+trap '_release_lock /var/run/xen-hotplug/block; sigerr' ERR
+2731+1311699329+_update_lock_info /var/run/xen-hotplug/block
+2731+1311699329+echo '2731: /etc/xen/scripts/block-snapshot'
+2731+1311699329+return
++2731+1311699329+dmsetup info /dev/mapper/snapshot-fd00:1971082-fd00:1971095
++2731+1311699329+awk '{print $3}'
++2731+1311699329+grep Open
+2731+1311699329+use_count=1
++2731+1311699329+echo /dev/mapper/snapshot-fd00:1971082-fd00:1971095
++2731+1311699329+cut -d- -f2
+2731+1311699329+'[' /dev/mapper/-fd00:1971082-fd00:1971095 '!=' /dev/mapper/snapshot-fd00:1971082-fd00:1971095 -a -e /dev/mapper/origin-fd00:1971082 ']'
+2731+1311699329+'[' 1 -gt 0 ']'
+2731+1311699329+log info 'Device /dev/mapper/snapshot-fd00:1971082-fd00:1971095 still in use - not removing'
+2731+1311699329+local level=info
+2731+1311699329+shift
+2731+1311699329+logger -p daemon.info -- /etc/xen/scripts/block-snapshot: 'Device /dev/mapper/snapshot-fd00:1971082-fd00:1971095 still in use - not removing'
+2731+1311699329+release_lock block
+2731+1311699329+_release_lock /var/run/xen-hotplug/block
+2731+1311699329+trap sigerr ERR
+2731+1311699329+rm -rf /var/run/xen-hotplug/block
+2731+1311699329+exit 0
++1649+1311699365+xenstore_read_default backend/vbd/1/51712/type MISSING
++1649+1311699365+xenstore-read backend/vbd/1/51712/type
+1649+1311699365+t=snapshot
+1649+1311699365+case "$command" in
+1649+1311699365+case $t in
++1649+1311699365+xenstore_read backend/vbd/1/51712/params
+++1649+1311699365+xenstore-read backend/vbd/1/51712/params
++1649+1311699365+local v=/var/lib/qubes/vm-templates/fedora-14-x64/root.img:/var/lib/qubes/vm-templates/fedora-14-x64/root-cow.img
++1649+1311699365+'[' /var/lib/qubes/vm-templates/fedora-14-x64/root.img:/var/lib/qubes/vm-templates/fedora-14-x64/root-cow.img '!=' '' ']'
++1649+1311699365+echo /var/lib/qubes/vm-templates/fedora-14-x64/root.img:/var/lib/qubes/vm-templates/fedora-14-x64/root-cow.img
+1649+1311699365+p=/var/lib/qubes/vm-templates/fedora-14-x64/root.img:/var/lib/qubes/vm-templates/fedora-14-x64/root-cow.img
+1649+1311699365+base=/var/lib/qubes/vm-templates/fedora-14-x64/root.img
+1649+1311699365+cow=/var/lib/qubes/vm-templates/fedora-14-x64/root-cow.img
+1649+1311699365+'[' -L /var/lib/qubes/vm-templates/fedora-14-x64/root.img ']'
+1649+1311699365+'[' -L /var/lib/qubes/vm-templates/fedora-14-x64/root-cow.img ']'
++1649+1311699365+get_dm_snapshot_name /var/lib/qubes/vm-templates/fedora-14-x64/root.img /var/lib/qubes/vm-templates/fedora-14-x64/root-cow.img
++1649+1311699365+base=/var/lib/qubes/vm-templates/fedora-14-x64/root.img
++1649+1311699365+cow=/var/lib/qubes/vm-templates/fedora-14-x64/root-cow.img
+++1649+1311699365+stat -c %D:%i /var/lib/qubes/vm-templates/fedora-14-x64/root.img
+++1649+1311699365+stat -c %D:%i /var/lib/qubes/vm-templates/fedora-14-x64/root-cow.img
++1649+1311699365+echo snapshot-fd00:1971082-fd00:1971095
+1649+1311699365+dm_devname=snapshot-fd00:1971082-fd00:1971095
+1649+1311699365+claim_lock block
+1649+1311699365+local lockdir=/var/run/xen-hotplug/block
+1649+1311699365+mkdir -p /var/run/xen-hotplug
+1649+1311699365+_claim_lock /var/run/xen-hotplug/block
+1649+1311699365+local lockdir=/var/run/xen-hotplug/block
++1649+1311699365+_lock_owner /var/run/xen-hotplug/block
++1649+1311699365+cat /var/run/xen-hotplug/block/owner
++1649+1311699365+echo unknown
+1649+1311699365+local owner=unknown
+1649+1311699365+local retries=0
+1649+1311699365+'[' 0 -lt 100 ']'
+1649+1311699365+mkdir /var/run/xen-hotplug/block
+1649+1311699365+trap '_release_lock /var/run/xen-hotplug/block; sigerr' ERR
+1649+1311699365+_update_lock_info /var/run/xen-hotplug/block
+1649+1311699365+echo '1649: /etc/xen/scripts/block-snapshot'
+1649+1311699365+return
+1649+1311699365+create_dm_snapshot snapshot-fd00:1971082-fd00:1971095 /var/lib/qubes/vm-templates/fedora-14-x64/root.img /var/lib/qubes/vm-templates/fedora-14-x64/root-cow.img
+1649+1311699365+local base_dev cow_dev base_sz
+1649+1311699365+dm_devname=snapshot-fd00:1971082-fd00:1971095
+1649+1311699365+base=/var/lib/qubes/vm-templates/fedora-14-x64/root.img
+1649+1311699365+cow=/var/lib/qubes/vm-templates/fedora-14-x64/root-cow.img
+1649+1311699365+'[' '!' -e /dev/mapper/snapshot-fd00:1971082-fd00:1971095 ']'
++1649+1311699365+get_dev /var/lib/qubes/vm-templates/fedora-14-x64/root.img
++1649+1311699365+dev=/var/lib/qubes/vm-templates/fedora-14-x64/root.img
++1649+1311699365+'[' -L /var/lib/qubes/vm-templates/fedora-14-x64/root.img ']'
++1649+1311699365+'[' -f /var/lib/qubes/vm-templates/fedora-14-x64/root.img ']'
++1649+1311699365+file=/var/lib/qubes/vm-templates/fedora-14-x64/root.img
+++1649+1311699365+stat -c %i /var/lib/qubes/vm-templates/fedora-14-x64/root.img
++1649+1311699365+inode=1971082
+++1649+1311699365+stat -c %D /var/lib/qubes/vm-templates/fedora-14-x64/root.img
++1649+1311699365+devnum=fd00
++1649+1311699365+'[' -z 1971082 ']'
++1649+1311699365+'[' -z fd00 ']'
+++1649+1311699365+losetup -a
+++1649+1311699365+grep ' \[0*fd00\]:1971082'
+++1649+1311699365+cut -d : -f 1
++1649+1311699365+dev_list=
+++1649+1311699365+losetup -f
++1649+1311699365+loopdev=/dev/loop0
++1649+1311699365+'[' /dev/loop0 = '' ']'
++1649+1311699365+do_or_die losetup /dev/loop0 /var/lib/qubes/vm-templates/fedora-14-x64/root.img
++1649+1311699365+losetup /dev/loop0 /var/lib/qubes/vm-templates/fedora-14-x64/root.img
++1649+1311699365+echo /dev/loop0
+1649+1311699365+base_dev=/dev/loop0
++1649+1311699365+get_dev /var/lib/qubes/vm-templates/fedora-14-x64/root-cow.img
++1649+1311699365+dev=/var/lib/qubes/vm-templates/fedora-14-x64/root-cow.img
++1649+1311699365+'[' -L /var/lib/qubes/vm-templates/fedora-14-x64/root-cow.img ']'
++1649+1311699365+'[' -f /var/lib/qubes/vm-templates/fedora-14-x64/root-cow.img ']'
++1649+1311699365+file=/var/lib/qubes/vm-templates/fedora-14-x64/root-cow.img
+++1649+1311699365+stat -c %i /var/lib/qubes/vm-templates/fedora-14-x64/root-cow.img
++1649+1311699365+inode=1971095
+++1649+1311699365+stat -c %D /var/lib/qubes/vm-templates/fedora-14-x64/root-cow.img
++1649+1311699365+devnum=fd00
++1649+1311699365+'[' -z 1971095 ']'
++1649+1311699365+'[' -z fd00 ']'
+++1649+1311699365+grep ' \[0*fd00\]:1971095'
+++1649+1311699365+losetup -a
+++1649+1311699365+cut -d : -f 1
++1649+1311699365+dev_list=
+++1649+1311699365+losetup -f
++1649+1311699365+loopdev=/dev/loop1
++1649+1311699365+'[' /dev/loop1 = '' ']'
++1649+1311699365+do_or_die losetup /dev/loop1 /var/lib/qubes/vm-templates/fedora-14-x64/root-cow.img
++1649+1311699365+losetup /dev/loop1 /var/lib/qubes/vm-templates/fedora-14-x64/root-cow.img
++1649+1311699365+echo /dev/loop1
+1649+1311699365+cow_dev=/dev/loop1
++1649+1311699365+blockdev --getsz /dev/loop0
+1649+1311699365+base_sz=20971520
+1649+1311699365+do_or_die dmsetup create snapshot-fd00:1971082-fd00:1971095 --table '0 20971520 snapshot /dev/loop0 /dev/loop1 P 256'
+1649+1311699365+dmsetup create snapshot-fd00:1971082-fd00:1971095 --table '0 20971520 snapshot /dev/loop0 /dev/loop1 P 256'
+1649+1311699365+'[' snapshot == snapshot ']'
+1649+1311699365+xenstore_write backend/vbd/1/51712/node /dev/mapper/snapshot-fd00:1971082-fd00:1971095
+1649+1311699365+_xenstore_write backend/vbd/1/51712/node /dev/mapper/snapshot-fd00:1971082-fd00:1971095
+1649+1311699365+log debug 'Writing backend/vbd/1/51712/node' '/dev/mapper/snapshot-fd00:1971082-fd00:1971095 to xenstore.'
+1649+1311699365+local level=debug
+1649+1311699365+shift
+1649+1311699365+logger -p daemon.debug -- /etc/xen/scripts/block-snapshot: 'Writing backend/vbd/1/51712/node' '/dev/mapper/snapshot-fd00:1971082-fd00:1971095 to xenstore.'
+1649+1311699365+xenstore-write backend/vbd/1/51712/node /dev/mapper/snapshot-fd00:1971082-fd00:1971095
+1649+1311699365+echo /dev/mapper/snapshot-fd00:1971082-fd00:1971095
+1649+1311699365+write_dev /dev/mapper/snapshot-fd00:1971082-fd00:1971095
+1649+1311699365+local mm
++1649+1311699365+device_major_minor /dev/mapper/snapshot-fd00:1971082-fd00:1971095
++1649+1311699365+stat -L -c %t:%T /dev/mapper/snapshot-fd00:1971082-fd00:1971095
+1649+1311699365+mm=fd:2
+1649+1311699365+'[' -z fd:2 ']'
+1649+1311699365+xenstore_write backend/vbd/1/51712/physical-device fd:2
+1649+1311699365+_xenstore_write backend/vbd/1/51712/physical-device fd:2
+1649+1311699365+log debug 'Writing backend/vbd/1/51712/physical-device' 'fd:2 to xenstore.'
+1649+1311699365+local level=debug
+1649+1311699365+shift
+1649+1311699365+logger -p daemon.debug -- /etc/xen/scripts/block-snapshot: 'Writing backend/vbd/1/51712/physical-device' 'fd:2 to xenstore.'
+1649+1311699365+xenstore-write backend/vbd/1/51712/physical-device fd:2
+1649+1311699365+success
+1649+1311699365+xenstore_write backend/vbd/1/51712/hotplug-status connected
+1649+1311699365+_xenstore_write backend/vbd/1/51712/hotplug-status connected
+1649+1311699365+log debug 'Writing backend/vbd/1/51712/hotplug-status' 'connected to xenstore.'
+1649+1311699365+local level=debug
+1649+1311699365+shift
+1649+1311699365+logger -p daemon.debug -- /etc/xen/scripts/block-snapshot: 'Writing backend/vbd/1/51712/hotplug-status' 'connected to xenstore.'
+1649+1311699365+xenstore-write backend/vbd/1/51712/hotplug-status connected
++1649+1311699365+xenstore_read_default backend/vbd/1/51712/domain ''
++1649+1311699365+xenstore-read backend/vbd/1/51712/domain
++1649+1311699365+echo ''
+1649+1311699365+domain=
+1649+1311699365+'[' -z '' ']'
++1649+1311699365+xenstore_read backend/vbd/1/51712/frontend-id
+++1649+1311699365+xenstore-read backend/vbd/1/51712/frontend-id
++1649+1311699365+local v=1
++1649+1311699365+'[' 1 '!=' '' ']'
++1649+1311699365+echo 1
+1649+1311699365+domid=1
++1649+1311699365+xl domname 1
+1649+1311699365+domain=netvm
+1649+1311699365+echo netvm
+1649+1311699365+release_lock block
+1649+1311699365+_release_lock /var/run/xen-hotplug/block
+1649+1311699365+trap sigerr ERR
+1649+1311699365+rm -rf /var/run/xen-hotplug/block
+1649+1311699365+exit 0
++1997+1311699486+xenstore_read_default backend/vbd/1/51712/type MISSING
++1997+1311699486+xenstore-read backend/vbd/1/51712/type
+1997+1311699486+t=snapshot
+1997+1311699486+case "$command" in
+1997+1311699486+'[' remove = cleanup ']'
++1997+1311699486+cat /var/run/xen-hotplug/backend-vbd-1-51712-type
+1997+1311699486+t=snapshot
+1997+1311699486+case $t in
+1997+1311699486+'[' remove = cleanup ']'
++1997+1311699486+cat /var/run/xen-hotplug/backend-vbd-1-51712-node
+1997+1311699486+node=/dev/mapper/snapshot-fd00:1971082-fd00:1971095
+1997+1311699486+'[' -z /dev/mapper/snapshot-fd00:1971082-fd00:1971095 ']'
+1997+1311699486+'[' '!' -e /dev/mapper/snapshot-fd00:1971082-fd00:1971095 ']'
+1997+1311699486+claim_lock block
+1997+1311699486+local lockdir=/var/run/xen-hotplug/block
+1997+1311699486+mkdir -p /var/run/xen-hotplug
+1997+1311699486+_claim_lock /var/run/xen-hotplug/block
+1997+1311699486+local lockdir=/var/run/xen-hotplug/block
++1997+1311699486+_lock_owner /var/run/xen-hotplug/block
++1997+1311699486+cat /var/run/xen-hotplug/block/owner
++1997+1311699486+echo unknown
+1997+1311699486+local owner=unknown
+1997+1311699486+local retries=0
+1997+1311699486+'[' 0 -lt 100 ']'
+1997+1311699486+mkdir /var/run/xen-hotplug/block
+1997+1311699486+trap '_release_lock /var/run/xen-hotplug/block; sigerr' ERR
+1997+1311699486+_update_lock_info /var/run/xen-hotplug/block
+1997+1311699486+echo '1997: /etc/xen/scripts/block-snapshot'
+1997+1311699486+return
++1997+1311699486+grep Open
++1997+1311699486+dmsetup info /dev/mapper/snapshot-fd00:1971082-fd00:1971095
++1997+1311699486+awk '{print $3}'
+1997+1311699486+use_count=0
++1997+1311699486+echo /dev/mapper/snapshot-fd00:1971082-fd00:1971095
++1997+1311699486+cut -d- -f2
+1997+1311699486+'[' /dev/mapper/-fd00:1971082-fd00:1971095 '!=' /dev/mapper/snapshot-fd00:1971082-fd00:1971095 -a -e /dev/mapper/origin-fd00:1971082 ']'
+1997+1311699486+'[' 0 -gt 0 ']'
++1997+1311699486+dmsetup deps /dev/mapper/snapshot-fd00:1971082-fd00:1971095
++1997+1311699486+sed -e 's#(7, \([0-9]\+\))#/dev/loop\1#g'
++1997+1311699486+cut -d: -f2
+1997+1311699486+deps=' /dev/loop1 /dev/loop0'
+1997+1311699486+'[' /dev/mapper/snapshot-fd00:1971082-fd00:1971095 '!=' /dev/mapper/snapshot-fd00:1971082-fd00:1971095 ']'
+1997+1311699486+'[' -e /dev/mapper/snapshot-fd00:1971082-fd00:1971095 ']'
+1997+1311699486+log debug 'Removing /dev/mapper/snapshot-fd00:1971082-fd00:1971095'
+1997+1311699486+local level=debug
+1997+1311699486+shift
+1997+1311699486+logger -p daemon.debug -- /etc/xen/scripts/block-snapshot: 'Removing /dev/mapper/snapshot-fd00:1971082-fd00:1971095'
+1997+1311699486+dmsetup remove /dev/mapper/snapshot-fd00:1971082-fd00:1971095
+1997+1311699486+for dev in '$deps'
+1997+1311699486+'[' -b /dev/loop1 ']'
+1997+1311699486+log debug 'Removing /dev/loop1'
+1997+1311699486+local level=debug
+1997+1311699486+shift
+1997+1311699486+logger -p daemon.debug -- /etc/xen/scripts/block-snapshot: 'Removing /dev/loop1'
+1997+1311699486+losetup -d /dev/loop1
+1997+1311699486+for dev in '$deps'
+1997+1311699486+'[' -b /dev/loop0 ']'
+1997+1311699486+log debug 'Removing /dev/loop0'
+1997+1311699486+local level=debug
+1997+1311699486+shift
+1997+1311699486+logger -p daemon.debug -- /etc/xen/scripts/block-snapshot: 'Removing /dev/loop0'
+1997+1311699486+losetup -d /dev/loop0
+1997+1311699486+release_lock block
+1997+1311699486+_release_lock /var/run/xen-hotplug/block
+1997+1311699486+trap sigerr ERR
+1997+1311699486+rm -rf /var/run/xen-hotplug/block
+1997+1311699486+exit 0

comment:10 Changed 22 months ago by joanna

Here's an updated dump (with correct PS4 I hope):

--2694-1311844964-xenstore_read_default backend/vbd/2/51728/type MISSING
--2694-1311844964-xenstore-read backend/vbd/2/51728/type
--2694-1311844964-echo MISSING
-2694-1311844964-t=MISSING
-2694-1311844964-case "$command" in
--2694-1311844964-cat /var/run/xen-hotplug/backend-vbd-2-51728-type
-2694-1311844964-t=file
-2694-1311844964-case $t in
-2694-1311844964-claim_lock block
-2694-1311844964-local lockdir=/var/run/xen-hotplug/block
-2694-1311844964-mkdir -p /var/run/xen-hotplug
-2694-1311844964-_claim_lock /var/run/xen-hotplug/block
-2694-1311844964-local lockdir=/var/run/xen-hotplug/block
--2694-1311844964-_lock_owner /var/run/xen-hotplug/block
--2694-1311844964-cat /var/run/xen-hotplug/block/owner
-2694-1311844964-local 'owner=2706: /etc/xen/scripts/xen-hotplug-cleanup'
-2694-1311844964-local retries=0
-2694-1311844964-'[' 0 -lt 100 ']'
-2694-1311844964-mkdir /var/run/xen-hotplug/block
--2694-1311844964-_lock_owner /var/run/xen-hotplug/block
--2694-1311844964-cat /var/run/xen-hotplug/block/owner
-2694-1311844964-local 'new_owner=2706: /etc/xen/scripts/xen-hotplug-cleanup'
-2694-1311844964-'[' '2706: /etc/xen/scripts/xen-hotplug-cleanup' '!=' '2706: /etc/xen/scripts/xen-hotplug-cleanup' ']'
--2694-1311844964-echo 2706: /etc/xen/scripts/xen-hotplug-cleanup
--2694-1311844964-cut -d : -f 1
-2694-1311844964-local pid=2706
-2694-1311844964-'[' -n 2706 -a 2706 '!=' unknown -a '!' -f /proc/2706/status ']'
-2694-1311844964-'[' 0 -gt 5 ']'
-2694-1311844964-sleep 0
-2694-1311844964-retries=1
-2694-1311844964-'[' 1 -lt 100 ']'
-2694-1311844964-mkdir /var/run/xen-hotplug/block
--2694-1311844964-_lock_owner /var/run/xen-hotplug/block
--2694-1311844964-cat /var/run/xen-hotplug/block/owner
-2694-1311844964-local 'new_owner=2706: /etc/xen/scripts/xen-hotplug-cleanup'
-2694-1311844964-'[' '2706: /etc/xen/scripts/xen-hotplug-cleanup' '!=' '2706: /etc/xen/scripts/xen-hotplug-cleanup' ']'
--2694-1311844964-echo 2706: /etc/xen/scripts/xen-hotplug-cleanup
--2694-1311844964-cut -d : -f 1
-2694-1311844964-local pid=2706
-2694-1311844964-'[' -n 2706 -a 2706 '!=' unknown -a '!' -f /proc/2706/status ']'
-2694-1311844964-'[' 1 -gt 5 ']'
-2694-1311844964-sleep 0
-2694-1311844964-retries=2
-2694-1311844964-'[' 2 -lt 100 ']'
-2694-1311844964-mkdir /var/run/xen-hotplug/block
-2694-1311844964-trap '_release_lock /var/run/xen-hotplug/block; sigerr' ERR
-2694-1311844964-_update_lock_info /var/run/xen-hotplug/block
-2694-1311844964-echo '2694: /etc/xen/scripts/block'
-2694-1311844964-return
--2694-1311844964-cat /var/run/xen-hotplug/backend-vbd-2-51728-node
-2694-1311844964-node=/dev/loop6
-2694-1311844964-losetup -d /dev/loop6
-2694-1311844964-release_lock block
-2694-1311844964-_release_lock /var/run/xen-hotplug/block
-2694-1311844964-trap sigerr ERR
-2694-1311844964-rm -rf /var/run/xen-hotplug/block
-2694-1311844964-exit 0
--2785-1311844964-xenstore_read_default backend/vbd/2/51744/type MISSING
--2785-1311844964-xenstore-read backend/vbd/2/51744/type
--2785-1311844964-echo MISSING
-2785-1311844964-t=MISSING
-2785-1311844964-case "$command" in
--2785-1311844964-cat /var/run/xen-hotplug/backend-vbd-2-51744-type
-2785-1311844964-t=file
-2785-1311844964-case $t in
-2785-1311844964-claim_lock block
-2785-1311844964-local lockdir=/var/run/xen-hotplug/block
-2785-1311844964-mkdir -p /var/run/xen-hotplug
-2785-1311844964-_claim_lock /var/run/xen-hotplug/block
-2785-1311844964-local lockdir=/var/run/xen-hotplug/block
--2785-1311844964-_lock_owner /var/run/xen-hotplug/block
--2785-1311844964-cat /var/run/xen-hotplug/block/owner
-2785-1311844964-local 'owner=2786: /etc/xen/scripts/xen-hotplug-cleanup'
-2785-1311844964-local retries=0
-2785-1311844964-'[' 0 -lt 100 ']'
-2785-1311844964-mkdir /var/run/xen-hotplug/block
--2785-1311844964-_lock_owner /var/run/xen-hotplug/block
--2785-1311844964-cat /var/run/xen-hotplug/block/owner
-2785-1311844964-local 'new_owner=2786: /etc/xen/scripts/xen-hotplug-cleanup'
-2785-1311844964-'[' '2786: /etc/xen/scripts/xen-hotplug-cleanup' '!=' '2786: /etc/xen/scripts/xen-hotplug-cleanup' ']'
--2785-1311844964-echo 2786: /etc/xen/scripts/xen-hotplug-cleanup
--2785-1311844964-cut -d : -f 1
-2785-1311844964-local pid=2786
-2785-1311844964-'[' -n 2786 -a 2786 '!=' unknown -a '!' -f /proc/2786/status ']'
-2785-1311844964-_release_lock /var/run/xen-hotplug/block
-2785-1311844964-trap sigerr ERR
-2785-1311844964-rm -rf /var/run/xen-hotplug/block
-2785-1311844964-'[' 0 -gt 5 ']'
-2785-1311844964-sleep 0
-2785-1311844964-retries=1
-2785-1311844964-'[' 1 -lt 100 ']'
-2785-1311844964-mkdir /var/run/xen-hotplug/block
-2785-1311844964-trap '_release_lock /var/run/xen-hotplug/block; sigerr' ERR
-2785-1311844964-_update_lock_info /var/run/xen-hotplug/block
-2785-1311844964-echo '2785: /etc/xen/scripts/block'
-2785-1311844964-return
--2785-1311844964-cat /var/run/xen-hotplug/backend-vbd-2-51744-node
-2785-1311844964-node=/dev/loop5
-2785-1311844964-losetup -d /dev/loop5
-2785-1311844964-release_lock block
-2785-1311844964-_release_lock /var/run/xen-hotplug/block
-2785-1311844964-trap sigerr ERR
-2785-1311844964-rm -rf /var/run/xen-hotplug/block
-2785-1311844964-exit 0
--2837-1311844964-xenstore_read_default backend/vbd/2/51712/type MISSING
--2837-1311844964-xenstore-read backend/vbd/2/51712/type
--2837-1311844964-echo MISSING
-2837-1311844964-t=MISSING
-2837-1311844964-case "$command" in
--2837-1311844964-cat /var/run/xen-hotplug/backend-vbd-2-51712-type
-2837-1311844964-t=snapshot
-2837-1311844964-case $t in
-2837-1311844964-'[' -x /etc/xen/scripts/block-snapshot ']'
-2837-1311844964-/etc/xen/scripts/block-snapshot remove
++2869+1311844964+xenstore_read_default backend/vbd/2/51712/type MISSING
++2869+1311844964+xenstore-read backend/vbd/2/51712/type
++2869+1311844964+echo MISSING
+2869+1311844964+t=MISSING
+2869+1311844964+case "$command" in
+2869+1311844964+'[' remove = cleanup ']'
++2869+1311844964+cat /var/run/xen-hotplug/backend-vbd-2-51712-type
+2869+1311844964+t=snapshot
+2869+1311844964+case $t in
+2869+1311844964+'[' remove = cleanup ']'
++2869+1311844964+cat /var/run/xen-hotplug/backend-vbd-2-51712-node
+2869+1311844964+node=/dev/mapper/snapshot-fd00:1971082-fd00:1971095
+2869+1311844964+'[' -z /dev/mapper/snapshot-fd00:1971082-fd00:1971095 ']'
+2869+1311844964+'[' '!' -e /dev/mapper/snapshot-fd00:1971082-fd00:1971095 ']'
+2869+1311844964+claim_lock block
+2869+1311844964+local lockdir=/var/run/xen-hotplug/block
+2869+1311844964+mkdir -p /var/run/xen-hotplug
+2869+1311844965+_claim_lock /var/run/xen-hotplug/block
+2869+1311844965+local lockdir=/var/run/xen-hotplug/block
++2869+1311844965+_lock_owner /var/run/xen-hotplug/block
++2869+1311844965+cat /var/run/xen-hotplug/block/owner
++2869+1311844965+echo unknown
+2869+1311844965+local owner=unknown
+2869+1311844965+local retries=0
+2869+1311844965+'[' 0 -lt 100 ']'
+2869+1311844965+mkdir /var/run/xen-hotplug/block
+2869+1311844965+trap '_release_lock /var/run/xen-hotplug/block; sigerr' ERR
+2869+1311844965+_update_lock_info /var/run/xen-hotplug/block
+2869+1311844965+echo '2869: /etc/xen/scripts/block-snapshot'
+2869+1311844965+return
++2869+1311844965+dmsetup info /dev/mapper/snapshot-fd00:1971082-fd00:1971095
++2869+1311844965+awk '{print $3}'
++2869+1311844965+grep Open
+2869+1311844965+use_count=1
++2869+1311844965+echo /dev/mapper/snapshot-fd00:1971082-fd00:1971095
++2869+1311844965+cut -d- -f2
+2869+1311844965+'[' /dev/mapper/-fd00:1971082-fd00:1971095 '!=' /dev/mapper/snapshot-fd00:1971082-fd00:1971095 -a -e /dev/mapper/origin-fd00:1971082 ']'
+2869+1311844965+'[' 1 -gt 0 ']'
+2869+1311844965+log info 'Device /dev/mapper/snapshot-fd00:1971082-fd00:1971095 still in use - not removing'
+2869+1311844965+local level=info
+2869+1311844965+shift
+2869+1311844965+logger -p daemon.info -- /etc/xen/scripts/block-snapshot: 'Device /dev/mapper/snapshot-fd00:1971082-fd00:1971095 still in use - not removing'
+2869+1311844965+release_lock block
+2869+1311844965+_release_lock /var/run/xen-hotplug/block
+2869+1311844965+trap sigerr ERR
+2869+1311844965+rm -rf /var/run/xen-hotplug/block
+2869+1311844965+exit 0
--2902-1311844965-xenstore_read_default backend/vbd/2/51760/type MISSING
--2902-1311844965-xenstore-read backend/vbd/2/51760/type
--2902-1311844965-echo MISSING
-2902-1311844965-t=MISSING
-2902-1311844965-case "$command" in
--2902-1311844965-cat /var/run/xen-hotplug/backend-vbd-2-51760-type
-2902-1311844965-t=file
-2902-1311844965-case $t in
-2902-1311844965-claim_lock block
-2902-1311844965-local lockdir=/var/run/xen-hotplug/block
-2902-1311844965-mkdir -p /var/run/xen-hotplug
-2902-1311844965-_claim_lock /var/run/xen-hotplug/block
-2902-1311844965-local lockdir=/var/run/xen-hotplug/block
--2902-1311844965-_lock_owner /var/run/xen-hotplug/block
--2902-1311844965-cat /var/run/xen-hotplug/block/owner
-2902-1311844965-local 'owner=2903: /etc/xen/scripts/xen-hotplug-cleanup'
-2902-1311844965-local retries=0
-2902-1311844965-'[' 0 -lt 100 ']'
-2902-1311844965-mkdir /var/run/xen-hotplug/block
--2902-1311844965-_lock_owner /var/run/xen-hotplug/block
--2902-1311844965-cat /var/run/xen-hotplug/block/owner
--2902-1311844965-echo unknown
-2902-1311844965-local new_owner=unknown
-2902-1311844965-'[' unknown '!=' '2903: /etc/xen/scripts/xen-hotplug-cleanup' ']'
-2902-1311844965-owner=unknown
-2902-1311844965-retries=0
-2902-1311844965-'[' 0 -gt 5 ']'
-2902-1311844965-sleep 0
-2902-1311844965-retries=1
-2902-1311844965-'[' 1 -lt 100 ']'
-2902-1311844965-mkdir /var/run/xen-hotplug/block
-2902-1311844965-trap '_release_lock /var/run/xen-hotplug/block; sigerr' ERR
-2902-1311844965-_update_lock_info /var/run/xen-hotplug/block
-2902-1311844965-echo '2902: /etc/xen/scripts/block'
-2902-1311844965-return
--2902-1311844965-cat /var/run/xen-hotplug/backend-vbd-2-51760-node
-2902-1311844965-node=/dev/loop7
-2902-1311844965-losetup -d /dev/loop7
-2902-1311844965-release_lock block
-2902-1311844965-_release_lock /var/run/xen-hotplug/block
-2902-1311844965-trap sigerr ERR
-2902-1311844965-rm -rf /var/run/xen-hotplug/block
-2902-1311844965-exit 0
--1598-1311845001-xenstore_read_default backend/vbd/1/51712/type MISSING
--1598-1311845001-xenstore-read backend/vbd/1/51712/type
-1598-1311845001-t=snapshot
-1598-1311845001-case "$command" in
--1598-1311845001-xenstore_read_default backend/vbd/1/51712/physical-device MISSING
--1598-1311845001-xenstore-read backend/vbd/1/51712/physical-device
--1598-1311845001-echo MISSING
-1598-1311845001-phys=MISSING
-1598-1311845001-'[' MISSING '!=' MISSING ']'
-1598-1311845001-'[' -n snapshot ']'
--1598-1311845001-xenstore_read backend/vbd/1/51712/params
---1598-1311845001-xenstore-read backend/vbd/1/51712/params
--1598-1311845001-local v=/var/lib/qubes/vm-templates/fedora-14-x64/root.img:/var/lib/qubes/vm-templates/fedora-14-x64/root-cow.img
--1598-1311845001-'[' /var/lib/qubes/vm-templates/fedora-14-x64/root.img:/var/lib/qubes/vm-templates/fedora-14-x64/root-cow.img '!=' '' ']'
--1598-1311845001-echo /var/lib/qubes/vm-templates/fedora-14-x64/root.img:/var/lib/qubes/vm-templates/fedora-14-x64/root-cow.img
-1598-1311845001-p=/var/lib/qubes/vm-templates/fedora-14-x64/root.img:/var/lib/qubes/vm-templates/fedora-14-x64/root-cow.img
--1598-1311845001-xenstore_read backend/vbd/1/51712/mode
---1598-1311845001-xenstore-read backend/vbd/1/51712/mode
--1598-1311845001-local v=r
--1598-1311845001-'[' r '!=' '' ']'
--1598-1311845001-echo r
-1598-1311845001-mode=r
-1598-1311845001-echo /var/lib/qubes/vm-templates/fedora-14-x64/root.img:/var/lib/qubes/vm-templates/fedora-14-x64/root-cow.img
-1598-1311845001-echo r
-1598-1311845001-echo snapshot
--1598-1311845001-xenstore_read backend/vbd/1/51712/frontend-id
---1598-1311845001-xenstore-read backend/vbd/1/51712/frontend-id
--1598-1311845001-local v=1
--1598-1311845001-'[' 1 '!=' '' ']'
--1598-1311845001-echo 1
-1598-1311845001-FRONTEND_ID=1
--1598-1311845001-xenstore_read_default /local/domain/1/vm unknown
--1598-1311845001-xenstore-read /local/domain/1/vm
-1598-1311845001-FRONTEND_UUID=/vm/46ee1fc4-0bb2-4990-9f06-108107beb59c
-1598-1311845001-case $t in
-1598-1311845001-'[' -x /etc/xen/scripts/block-snapshot ']'
-1598-1311845001-/etc/xen/scripts/block-snapshot add
++1630+1311845001+xenstore_read_default backend/vbd/1/51712/type MISSING
++1630+1311845001+xenstore-read backend/vbd/1/51712/type
+1630+1311845001+t=snapshot
+1630+1311845001+case "$command" in
+1630+1311845001+case $t in
++1630+1311845001+xenstore_read backend/vbd/1/51712/params
+++1630+1311845001+xenstore-read backend/vbd/1/51712/params
++1630+1311845001+local v=/var/lib/qubes/vm-templates/fedora-14-x64/root.img:/var/lib/qubes/vm-templates/fedora-14-x64/root-cow.img
++1630+1311845001+'[' /var/lib/qubes/vm-templates/fedora-14-x64/root.img:/var/lib/qubes/vm-templates/fedora-14-x64/root-cow.img '!=' '' ']'
++1630+1311845001+echo /var/lib/qubes/vm-templates/fedora-14-x64/root.img:/var/lib/qubes/vm-templates/fedora-14-x64/root-cow.img
+1630+1311845001+p=/var/lib/qubes/vm-templates/fedora-14-x64/root.img:/var/lib/qubes/vm-templates/fedora-14-x64/root-cow.img
+1630+1311845001+base=/var/lib/qubes/vm-templates/fedora-14-x64/root.img
+1630+1311845001+cow=/var/lib/qubes/vm-templates/fedora-14-x64/root-cow.img
+1630+1311845001+'[' -L /var/lib/qubes/vm-templates/fedora-14-x64/root.img ']'
+1630+1311845001+'[' -L /var/lib/qubes/vm-templates/fedora-14-x64/root-cow.img ']'
++1630+1311845001+get_dm_snapshot_name /var/lib/qubes/vm-templates/fedora-14-x64/root.img /var/lib/qubes/vm-templates/fedora-14-x64/root-cow.img
++1630+1311845001+base=/var/lib/qubes/vm-templates/fedora-14-x64/root.img
++1630+1311845001+cow=/var/lib/qubes/vm-templates/fedora-14-x64/root-cow.img
+++1630+1311845001+stat -c %D:%i /var/lib/qubes/vm-templates/fedora-14-x64/root.img
+++1630+1311845001+stat -c %D:%i /var/lib/qubes/vm-templates/fedora-14-x64/root-cow.img
++1630+1311845001+echo snapshot-fd00:1971082-fd00:1971095
+1630+1311845001+dm_devname=snapshot-fd00:1971082-fd00:1971095
+1630+1311845001+claim_lock block
+1630+1311845001+local lockdir=/var/run/xen-hotplug/block
+1630+1311845001+mkdir -p /var/run/xen-hotplug
+1630+1311845001+_claim_lock /var/run/xen-hotplug/block
+1630+1311845001+local lockdir=/var/run/xen-hotplug/block
++1630+1311845001+_lock_owner /var/run/xen-hotplug/block
++1630+1311845001+cat /var/run/xen-hotplug/block/owner
++1630+1311845001+echo unknown
+1630+1311845001+local owner=unknown
+1630+1311845001+local retries=0
+1630+1311845001+'[' 0 -lt 100 ']'
+1630+1311845001+mkdir /var/run/xen-hotplug/block
+1630+1311845001+trap '_release_lock /var/run/xen-hotplug/block; sigerr' ERR
+1630+1311845001+_update_lock_info /var/run/xen-hotplug/block
+1630+1311845001+echo '1630: /etc/xen/scripts/block-snapshot'
+1630+1311845001+return
+1630+1311845001+create_dm_snapshot snapshot-fd00:1971082-fd00:1971095 /var/lib/qubes/vm-templates/fedora-14-x64/root.img /var/lib/qubes/vm-templates/fedora-14-x64/root-cow.img
+1630+1311845001+local base_dev cow_dev base_sz
+1630+1311845001+dm_devname=snapshot-fd00:1971082-fd00:1971095
+1630+1311845001+base=/var/lib/qubes/vm-templates/fedora-14-x64/root.img
+1630+1311845001+cow=/var/lib/qubes/vm-templates/fedora-14-x64/root-cow.img
+1630+1311845001+'[' '!' -e /dev/mapper/snapshot-fd00:1971082-fd00:1971095 ']'
++1630+1311845001+get_dev /var/lib/qubes/vm-templates/fedora-14-x64/root.img
++1630+1311845001+dev=/var/lib/qubes/vm-templates/fedora-14-x64/root.img
++1630+1311845001+'[' -L /var/lib/qubes/vm-templates/fedora-14-x64/root.img ']'
++1630+1311845001+'[' -f /var/lib/qubes/vm-templates/fedora-14-x64/root.img ']'
++1630+1311845001+file=/var/lib/qubes/vm-templates/fedora-14-x64/root.img
+++1630+1311845001+stat -c %i /var/lib/qubes/vm-templates/fedora-14-x64/root.img
++1630+1311845001+inode=1971082
+++1630+1311845001+stat -c %D /var/lib/qubes/vm-templates/fedora-14-x64/root.img
++1630+1311845001+devnum=fd00
++1630+1311845001+'[' -z 1971082 ']'
++1630+1311845001+'[' -z fd00 ']'
+++1630+1311845001+losetup -a
+++1630+1311845001+cut -d : -f 1
+++1630+1311845001+grep ' \[0*fd00\]:1971082'
++1630+1311845001+dev_list=
+++1630+1311845001+losetup -f
++1630+1311845001+loopdev=/dev/loop0
++1630+1311845001+'[' /dev/loop0 = '' ']'
++1630+1311845001+do_or_die losetup /dev/loop0 /var/lib/qubes/vm-templates/fedora-14-x64/root.img
++1630+1311845001+losetup /dev/loop0 /var/lib/qubes/vm-templates/fedora-14-x64/root.img
++1630+1311845001+echo /dev/loop0
+1630+1311845001+base_dev=/dev/loop0
++1630+1311845001+get_dev /var/lib/qubes/vm-templates/fedora-14-x64/root-cow.img
++1630+1311845001+dev=/var/lib/qubes/vm-templates/fedora-14-x64/root-cow.img
++1630+1311845001+'[' -L /var/lib/qubes/vm-templates/fedora-14-x64/root-cow.img ']'
++1630+1311845001+'[' -f /var/lib/qubes/vm-templates/fedora-14-x64/root-cow.img ']'
++1630+1311845001+file=/var/lib/qubes/vm-templates/fedora-14-x64/root-cow.img
+++1630+1311845001+stat -c %i /var/lib/qubes/vm-templates/fedora-14-x64/root-cow.img
++1630+1311845001+inode=1971095
+++1630+1311845001+stat -c %D /var/lib/qubes/vm-templates/fedora-14-x64/root-cow.img
++1630+1311845001+devnum=fd00
++1630+1311845001+'[' -z 1971095 ']'
++1630+1311845001+'[' -z fd00 ']'
+++1630+1311845001+losetup -a
+++1630+1311845001+cut -d : -f 1
+++1630+1311845001+grep ' \[0*fd00\]:1971095'
++1630+1311845001+dev_list=
+++1630+1311845001+losetup -f
++1630+1311845001+loopdev=/dev/loop1
++1630+1311845001+'[' /dev/loop1 = '' ']'
++1630+1311845001+do_or_die losetup /dev/loop1 /var/lib/qubes/vm-templates/fedora-14-x64/root-cow.img
++1630+1311845001+losetup /dev/loop1 /var/lib/qubes/vm-templates/fedora-14-x64/root-cow.img
++1630+1311845001+echo /dev/loop1
+1630+1311845001+cow_dev=/dev/loop1
++1630+1311845001+blockdev --getsz /dev/loop0
+1630+1311845001+base_sz=20971520
+1630+1311845001+do_or_die dmsetup create snapshot-fd00:1971082-fd00:1971095 --table '0 20971520 snapshot /dev/loop0 /dev/loop1 P 256'
+1630+1311845001+dmsetup create snapshot-fd00:1971082-fd00:1971095 --table '0 20971520 snapshot /dev/loop0 /dev/loop1 P 256'
+1630+1311845002+'[' snapshot == snapshot ']'
+1630+1311845002+xenstore_write backend/vbd/1/51712/node /dev/mapper/snapshot-fd00:1971082-fd00:1971095
+1630+1311845002+_xenstore_write backend/vbd/1/51712/node /dev/mapper/snapshot-fd00:1971082-fd00:1971095
+1630+1311845002+log debug 'Writing backend/vbd/1/51712/node' '/dev/mapper/snapshot-fd00:1971082-fd00:1971095 to xenstore.'
+1630+1311845002+local level=debug
+1630+1311845002+shift
+1630+1311845002+logger -p daemon.debug -- /etc/xen/scripts/block-snapshot: 'Writing backend/vbd/1/51712/node' '/dev/mapper/snapshot-fd00:1971082-fd00:1971095 to xenstore.'
+1630+1311845002+xenstore-write backend/vbd/1/51712/node /dev/mapper/snapshot-fd00:1971082-fd00:1971095
+1630+1311845002+echo /dev/mapper/snapshot-fd00:1971082-fd00:1971095
+1630+1311845002+write_dev /dev/mapper/snapshot-fd00:1971082-fd00:1971095
+1630+1311845002+local mm
++1630+1311845002+device_major_minor /dev/mapper/snapshot-fd00:1971082-fd00:1971095
++1630+1311845002+stat -L -c %t:%T /dev/mapper/snapshot-fd00:1971082-fd00:1971095
+1630+1311845002+mm=fd:2
+1630+1311845002+'[' -z fd:2 ']'
+1630+1311845002+xenstore_write backend/vbd/1/51712/physical-device fd:2
+1630+1311845002+_xenstore_write backend/vbd/1/51712/physical-device fd:2
+1630+1311845002+log debug 'Writing backend/vbd/1/51712/physical-device' 'fd:2 to xenstore.'
+1630+1311845002+local level=debug
+1630+1311845002+shift
+1630+1311845002+logger -p daemon.debug -- /etc/xen/scripts/block-snapshot: 'Writing backend/vbd/1/51712/physical-device' 'fd:2 to xenstore.'
+1630+1311845002+xenstore-write backend/vbd/1/51712/physical-device fd:2
+1630+1311845002+success
+1630+1311845002+xenstore_write backend/vbd/1/51712/hotplug-status connected
+1630+1311845002+_xenstore_write backend/vbd/1/51712/hotplug-status connected
+1630+1311845002+log debug 'Writing backend/vbd/1/51712/hotplug-status' 'connected to xenstore.'
+1630+1311845002+local level=debug
+1630+1311845002+shift
+1630+1311845002+logger -p daemon.debug -- /etc/xen/scripts/block-snapshot: 'Writing backend/vbd/1/51712/hotplug-status' 'connected to xenstore.'
+1630+1311845002+xenstore-write backend/vbd/1/51712/hotplug-status connected
++1630+1311845002+xenstore_read_default backend/vbd/1/51712/domain ''
++1630+1311845002+xenstore-read backend/vbd/1/51712/domain
++1630+1311845002+echo ''
+1630+1311845002+domain=
+1630+1311845002+'[' -z '' ']'
++1630+1311845002+xenstore_read backend/vbd/1/51712/frontend-id
+++1630+1311845002+xenstore-read backend/vbd/1/51712/frontend-id
++1630+1311845002+local v=1
++1630+1311845002+'[' 1 '!=' '' ']'
++1630+1311845002+echo 1
+1630+1311845002+domid=1
++1630+1311845002+xl domname 1
+1630+1311845002+domain=netvm
+1630+1311845002+echo netvm
+1630+1311845002+release_lock block
+1630+1311845002+_release_lock /var/run/xen-hotplug/block
+1630+1311845002+trap sigerr ERR
+1630+1311845002+rm -rf /var/run/xen-hotplug/block
+1630+1311845002+exit 0
--1720-1311845002-xenstore_read_default backend/vbd/1/51728/type MISSING
--1720-1311845002-xenstore-read backend/vbd/1/51728/type
-1720-1311845002-t=file
-1720-1311845002-case "$command" in
--1720-1311845002-xenstore_read_default backend/vbd/1/51728/physical-device MISSING
--1720-1311845002-xenstore-read backend/vbd/1/51728/physical-device
--1720-1311845002-echo MISSING
-1720-1311845002-phys=MISSING
-1720-1311845002-'[' MISSING '!=' MISSING ']'
-1720-1311845002-'[' -n file ']'
--1720-1311845002-xenstore_read backend/vbd/1/51728/params
---1720-1311845002-xenstore-read backend/vbd/1/51728/params
--1720-1311845002-local v=/var/lib/qubes/servicevms/netvm/private.img
--1720-1311845002-'[' /var/lib/qubes/servicevms/netvm/private.img '!=' '' ']'
--1720-1311845002-echo /var/lib/qubes/servicevms/netvm/private.img
-1720-1311845002-p=/var/lib/qubes/servicevms/netvm/private.img
--1720-1311845002-xenstore_read backend/vbd/1/51728/mode
---1720-1311845002-xenstore-read backend/vbd/1/51728/mode
--1720-1311845002-local v=w
--1720-1311845002-'[' w '!=' '' ']'
--1720-1311845002-echo w
-1720-1311845002-mode=w
-1720-1311845002-echo /var/lib/qubes/servicevms/netvm/private.img
-1720-1311845002-echo w
-1720-1311845002-echo file
--1720-1311845002-xenstore_read backend/vbd/1/51728/frontend-id
---1720-1311845002-xenstore-read backend/vbd/1/51728/frontend-id
--1720-1311845002-local v=1
--1720-1311845002-'[' 1 '!=' '' ']'
--1720-1311845002-echo 1
-1720-1311845002-FRONTEND_ID=1
--1720-1311845002-xenstore_read_default /local/domain/1/vm unknown
--1720-1311845002-xenstore-read /local/domain/1/vm
-1720-1311845002-FRONTEND_UUID=/vm/46ee1fc4-0bb2-4990-9f06-108107beb59c
-1720-1311845002-case $t in
--1720-1311845002-readlink -f /var/lib/qubes/servicevms/netvm/private.img
-1720-1311845002-file=/var/lib/qubes/servicevms/netvm/private.img
-1720-1311845002-test -f /var/lib/qubes/servicevms/netvm/private.img
--1720-1311845002-canonicalise_mode w
--1720-1311845002-local mode=w
--1720-1311845002-expr index w w
--1720-1311845002-expr index w '!'
--1720-1311845002-echo w
-1720-1311845002-mode=w
-1720-1311845002-claim_lock block
-1720-1311845002-local lockdir=/var/run/xen-hotplug/block
-1720-1311845002-mkdir -p /var/run/xen-hotplug
-1720-1311845002-_claim_lock /var/run/xen-hotplug/block
-1720-1311845002-local lockdir=/var/run/xen-hotplug/block
--1720-1311845002-_lock_owner /var/run/xen-hotplug/block
--1720-1311845002-cat /var/run/xen-hotplug/block/owner
--1720-1311845002-echo unknown
-1720-1311845002-local owner=unknown
-1720-1311845002-local retries=0
-1720-1311845002-'[' 0 -lt 100 ']'
-1720-1311845002-mkdir /var/run/xen-hotplug/block
-1720-1311845002-trap '_release_lock /var/run/xen-hotplug/block; sigerr' ERR
-1720-1311845002-_update_lock_info /var/run/xen-hotplug/block
-1720-1311845002-echo '1720: /etc/xen/scripts/block'
-1720-1311845002-return
--1720-1311845002-xenstore_read_default backend/vbd/1/51728/state unknown
--1720-1311845002-xenstore-read backend/vbd/1/51728/state
-1720-1311845002-xenbus_state=2
-1720-1311845002-'[' 2 '!=' 2 ']'
-1720-1311845002-'[' w = w ']'
-1720-1311845002-stat /var/lib/qubes/servicevms/netvm/private.img -c %A
-1720-1311845002-grep -q w
-1720-1311845002-'[' xw '!=' 'x!' ']'
--1720-1311845002-stat -c %i /var/lib/qubes/servicevms/netvm/private.img
-1720-1311845002-inode=1835126
--1720-1311845002-stat -c %D /var/lib/qubes/servicevms/netvm/private.img
-1720-1311845002-dev=fd00
-1720-1311845002-'[' -z 1835126 ']'
-1720-1311845002-'[' -z fd00 ']'
--1720-1311845002-losetup -a
--1720-1311845002-sed -n -e 's@^\([^:]\+\)\(:[[:blank:]]\[0*fd00\]:1835126[[:blank:]](.*)\)@\1@p'
-1720-1311845002-shared_list=
--1720-1311845002-losetup -f
-1720-1311845002-loopdev=/dev/loop2
-1720-1311845002-'[' /dev/loop2 = '' ']'
-1720-1311845002-LANG=C
-1720-1311845002-losetup -h
-1720-1311845002-grep read-only
-1720-1311845002-roflag=-w
-1720-1311845002-roflag=
-1720-1311845002-roflag=
-1720-1311845002-do_or_die losetup /dev/loop2 /var/lib/qubes/servicevms/netvm/private.img
-1720-1311845002-losetup /dev/loop2 /var/lib/qubes/servicevms/netvm/private.img
-1720-1311845002-xenstore_write backend/vbd/1/51728/node /dev/loop2
-1720-1311845002-_xenstore_write backend/vbd/1/51728/node /dev/loop2
-1720-1311845002-log debug 'Writing backend/vbd/1/51728/node' '/dev/loop2 to xenstore.'
-1720-1311845002-local level=debug
-1720-1311845002-shift
-1720-1311845002-logger -p daemon.debug -- /etc/xen/scripts/block: 'Writing backend/vbd/1/51728/node' '/dev/loop2 to xenstore.'
-1720-1311845002-xenstore-write backend/vbd/1/51728/node /dev/loop2
-1720-1311845002-echo /dev/loop2
-1720-1311845002-write_dev /dev/loop2
-1720-1311845002-local mm
--1720-1311845002-device_major_minor /dev/loop2
--1720-1311845002-stat -L -c %t:%T /dev/loop2
-1720-1311845002-mm=7:2
-1720-1311845002-'[' -z 7:2 ']'
-1720-1311845002-xenstore_write backend/vbd/1/51728/physical-device 7:2
-1720-1311845002-_xenstore_write backend/vbd/1/51728/physical-device 7:2
-1720-1311845002-log debug 'Writing backend/vbd/1/51728/physical-device' '7:2 to xenstore.'
-1720-1311845002-local level=debug
-1720-1311845002-shift
-1720-1311845002-logger -p daemon.debug -- /etc/xen/scripts/block: 'Writing backend/vbd/1/51728/physical-device' '7:2 to xenstore.'
-1720-1311845002-xenstore-write backend/vbd/1/51728/physical-device 7:2
-1720-1311845002-success
-1720-1311845002-xenstore_write backend/vbd/1/51728/hotplug-status connected
-1720-1311845002-_xenstore_write backend/vbd/1/51728/hotplug-status connected
-1720-1311845002-log debug 'Writing backend/vbd/1/51728/hotplug-status' 'connected to xenstore.'
-1720-1311845002-local level=debug
-1720-1311845002-shift
-1720-1311845002-logger -p daemon.debug -- /etc/xen/scripts/block: 'Writing backend/vbd/1/51728/hotplug-status' 'connected to xenstore.'
-1720-1311845002-xenstore-write backend/vbd/1/51728/hotplug-status connected
-1720-1311845002-release_lock block
-1720-1311845002-_release_lock /var/run/xen-hotplug/block
-1720-1311845002-trap sigerr ERR
-1720-1311845002-rm -rf /var/run/xen-hotplug/block
-1720-1311845002-exit 0
--1786-1311845002-xenstore_read_default backend/vbd/1/51744/type MISSING
--1786-1311845002-xenstore-read backend/vbd/1/51744/type
-1786-1311845002-t=file
-1786-1311845002-case "$command" in
--1786-1311845002-xenstore_read_default backend/vbd/1/51744/physical-device MISSING
--1786-1311845002-xenstore-read backend/vbd/1/51744/physical-device
--1786-1311845002-echo MISSING
-1786-1311845002-phys=MISSING
-1786-1311845002-'[' MISSING '!=' MISSING ']'
-1786-1311845002-'[' -n file ']'
--1786-1311845002-xenstore_read backend/vbd/1/51744/params
---1786-1311845002-xenstore-read backend/vbd/1/51744/params
--1786-1311845002-local v=/var/lib/qubes/servicevms/netvm/volatile.img
--1786-1311845002-'[' /var/lib/qubes/servicevms/netvm/volatile.img '!=' '' ']'
--1786-1311845002-echo /var/lib/qubes/servicevms/netvm/volatile.img
-1786-1311845002-p=/var/lib/qubes/servicevms/netvm/volatile.img
--1786-1311845002-xenstore_read backend/vbd/1/51744/mode
---1786-1311845002-xenstore-read backend/vbd/1/51744/mode
--1786-1311845002-local v=w
--1786-1311845002-'[' w '!=' '' ']'
--1786-1311845002-echo w
-1786-1311845002-mode=w
-1786-1311845002-echo /var/lib/qubes/servicevms/netvm/volatile.img
-1786-1311845002-echo w
-1786-1311845002-echo file
--1786-1311845002-xenstore_read backend/vbd/1/51744/frontend-id
---1786-1311845002-xenstore-read backend/vbd/1/51744/frontend-id
--1786-1311845002-local v=1
--1786-1311845002-'[' 1 '!=' '' ']'
--1786-1311845002-echo 1
-1786-1311845002-FRONTEND_ID=1
--1786-1311845002-xenstore_read_default /local/domain/1/vm unknown
--1786-1311845002-xenstore-read /local/domain/1/vm
-1786-1311845002-FRONTEND_UUID=/vm/46ee1fc4-0bb2-4990-9f06-108107beb59c
-1786-1311845002-case $t in
--1786-1311845002-readlink -f /var/lib/qubes/servicevms/netvm/volatile.img
-1786-1311845002-file=/var/lib/qubes/servicevms/netvm/volatile.img
-1786-1311845002-test -f /var/lib/qubes/servicevms/netvm/volatile.img
--1786-1311845002-canonicalise_mode w
--1786-1311845002-local mode=w
--1786-1311845002-expr index w w
--1786-1311845002-expr index w '!'
--1786-1311845002-echo w
-1786-1311845002-mode=w
-1786-1311845002-claim_lock block
-1786-1311845002-local lockdir=/var/run/xen-hotplug/block
-1786-1311845002-mkdir -p /var/run/xen-hotplug
-1786-1311845002-_claim_lock /var/run/xen-hotplug/block
-1786-1311845002-local lockdir=/var/run/xen-hotplug/block
--1786-1311845002-_lock_owner /var/run/xen-hotplug/block
--1786-1311845002-cat /var/run/xen-hotplug/block/owner
--1786-1311845002-echo unknown
-1786-1311845002-local owner=unknown
-1786-1311845002-local retries=0
-1786-1311845002-'[' 0 -lt 100 ']'
-1786-1311845002-mkdir /var/run/xen-hotplug/block
-1786-1311845002-trap '_release_lock /var/run/xen-hotplug/block; sigerr' ERR
-1786-1311845002-_update_lock_info /var/run/xen-hotplug/block
-1786-1311845002-echo '1786: /etc/xen/scripts/block'
-1786-1311845002-return
--1786-1311845002-xenstore_read_default backend/vbd/1/51744/state unknown
--1786-1311845002-xenstore-read backend/vbd/1/51744/state
-1786-1311845002-xenbus_state=2
-1786-1311845002-'[' 2 '!=' 2 ']'
-1786-1311845002-'[' w = w ']'
-1786-1311845002-stat /var/lib/qubes/servicevms/netvm/volatile.img -c %A
-1786-1311845002-grep -q w
-1786-1311845002-'[' xw '!=' 'x!' ']'
--1786-1311845002-stat -c %i /var/lib/qubes/servicevms/netvm/volatile.img
-1786-1311845002-inode=1835118
--1786-1311845002-stat -c %D /var/lib/qubes/servicevms/netvm/volatile.img
-1786-1311845002-dev=fd00
-1786-1311845002-'[' -z 1835118 ']'
-1786-1311845002-'[' -z fd00 ']'
--1786-1311845002-losetup -a
--1786-1311845002-sed -n -e 's@^\([^:]\+\)\(:[[:blank:]]\[0*fd00\]:1835118[[:blank:]](.*)\)@\1@p'
-1786-1311845002-shared_list=
--1786-1311845002-losetup -f
-1786-1311845002-loopdev=/dev/loop3
-1786-1311845002-'[' /dev/loop3 = '' ']'
-1786-1311845002-LANG=C
-1786-1311845002-losetup -h
-1786-1311845002-grep read-only
-1786-1311845002-roflag=-w
-1786-1311845002-roflag=
-1786-1311845002-roflag=
-1786-1311845002-do_or_die losetup /dev/loop3 /var/lib/qubes/servicevms/netvm/volatile.img
-1786-1311845002-losetup /dev/loop3 /var/lib/qubes/servicevms/netvm/volatile.img
-1786-1311845002-xenstore_write backend/vbd/1/51744/node /dev/loop3
-1786-1311845002-_xenstore_write backend/vbd/1/51744/node /dev/loop3
-1786-1311845002-log debug 'Writing backend/vbd/1/51744/node' '/dev/loop3 to xenstore.'
-1786-1311845002-local level=debug
-1786-1311845002-shift
-1786-1311845002-logger -p daemon.debug -- /etc/xen/scripts/block: 'Writing backend/vbd/1/51744/node' '/dev/loop3 to xenstore.'
-1786-1311845002-xenstore-write backend/vbd/1/51744/node /dev/loop3
-1786-1311845002-echo /dev/loop3
-1786-1311845002-write_dev /dev/loop3
-1786-1311845002-local mm
--1786-1311845002-device_major_minor /dev/loop3
--1786-1311845002-stat -L -c %t:%T /dev/loop3
-1786-1311845002-mm=7:3
-1786-1311845002-'[' -z 7:3 ']'
-1786-1311845002-xenstore_write backend/vbd/1/51744/physical-device 7:3
-1786-1311845002-_xenstore_write backend/vbd/1/51744/physical-device 7:3
-1786-1311845002-log debug 'Writing backend/vbd/1/51744/physical-device' '7:3 to xenstore.'
-1786-1311845002-local level=debug
-1786-1311845002-shift
-1786-1311845002-logger -p daemon.debug -- /etc/xen/scripts/block: 'Writing backend/vbd/1/51744/physical-device' '7:3 to xenstore.'
-1786-1311845002-xenstore-write backend/vbd/1/51744/physical-device 7:3
-1786-1311845002-success
-1786-1311845002-xenstore_write backend/vbd/1/51744/hotplug-status connected
-1786-1311845002-_xenstore_write backend/vbd/1/51744/hotplug-status connected
-1786-1311845002-log debug 'Writing backend/vbd/1/51744/hotplug-status' 'connected to xenstore.'
-1786-1311845002-local level=debug
-1786-1311845002-shift
-1786-1311845002-logger -p daemon.debug -- /etc/xen/scripts/block: 'Writing backend/vbd/1/51744/hotplug-status' 'connected to xenstore.'
-1786-1311845002-xenstore-write backend/vbd/1/51744/hotplug-status connected
-1786-1311845002-release_lock block
-1786-1311845002-_release_lock /var/run/xen-hotplug/block
-1786-1311845002-trap sigerr ERR
-1786-1311845002-rm -rf /var/run/xen-hotplug/block
-1786-1311845002-exit 0
--1846-1311845002-xenstore_read_default backend/vbd/1/51760/type MISSING
--1846-1311845002-xenstore-read backend/vbd/1/51760/type
-1846-1311845002-t=file
-1846-1311845002-case "$command" in
--1846-1311845002-xenstore_read_default backend/vbd/1/51760/physical-device MISSING
--1846-1311845002-xenstore-read backend/vbd/1/51760/physical-device
--1846-1311845002-echo MISSING
-1846-1311845002-phys=MISSING
-1846-1311845002-'[' MISSING '!=' MISSING ']'
-1846-1311845002-'[' -n file ']'
--1846-1311845002-xenstore_read backend/vbd/1/51760/params
---1846-1311845002-xenstore-read backend/vbd/1/51760/params
--1846-1311845002-local v=/var/lib/qubes/vm-kernels/2.6.38.3/modules.img
--1846-1311845002-'[' /var/lib/qubes/vm-kernels/2.6.38.3/modules.img '!=' '' ']'
--1846-1311845002-echo /var/lib/qubes/vm-kernels/2.6.38.3/modules.img
-1846-1311845002-p=/var/lib/qubes/vm-kernels/2.6.38.3/modules.img
--1846-1311845002-xenstore_read backend/vbd/1/51760/mode
---1846-1311845002-xenstore-read backend/vbd/1/51760/mode
--1846-1311845002-local v=r
--1846-1311845002-'[' r '!=' '' ']'
--1846-1311845002-echo r
-1846-1311845002-mode=r
-1846-1311845002-echo /var/lib/qubes/vm-kernels/2.6.38.3/modules.img
-1846-1311845002-echo r
-1846-1311845002-echo file
--1846-1311845002-xenstore_read backend/vbd/1/51760/frontend-id
---1846-1311845002-xenstore-read backend/vbd/1/51760/frontend-id
--1846-1311845002-local v=1
--1846-1311845002-'[' 1 '!=' '' ']'
--1846-1311845002-echo 1
-1846-1311845002-FRONTEND_ID=1
--1846-1311845002-xenstore_read_default /local/domain/1/vm unknown
--1846-1311845002-xenstore-read /local/domain/1/vm
-1846-1311845002-FRONTEND_UUID=/vm/46ee1fc4-0bb2-4990-9f06-108107beb59c
-1846-1311845002-case $t in
--1846-1311845002-readlink -f /var/lib/qubes/vm-kernels/2.6.38.3/modules.img
-1846-1311845002-file=/var/lib/qubes/vm-kernels/2.6.38.3/modules.img
-1846-1311845002-test -f /var/lib/qubes/vm-kernels/2.6.38.3/modules.img
--1846-1311845002-canonicalise_mode r
--1846-1311845002-local mode=r
--1846-1311845002-expr index r w
--1846-1311845002-echo r
-1846-1311845002-mode=r
-1846-1311845002-claim_lock block
-1846-1311845002-local lockdir=/var/run/xen-hotplug/block
-1846-1311845002-mkdir -p /var/run/xen-hotplug
-1846-1311845002-_claim_lock /var/run/xen-hotplug/block
-1846-1311845002-local lockdir=/var/run/xen-hotplug/block
--1846-1311845002-_lock_owner /var/run/xen-hotplug/block
--1846-1311845002-cat /var/run/xen-hotplug/block/owner
--1846-1311845002-echo unknown
-1846-1311845002-local owner=unknown
-1846-1311845002-local retries=0
-1846-1311845002-'[' 0 -lt 100 ']'
-1846-1311845002-mkdir /var/run/xen-hotplug/block
-1846-1311845002-trap '_release_lock /var/run/xen-hotplug/block; sigerr' ERR
-1846-1311845002-_update_lock_info /var/run/xen-hotplug/block
-1846-1311845002-echo '1846: /etc/xen/scripts/block'
-1846-1311845002-return
--1846-1311845002-xenstore_read_default backend/vbd/1/51760/state unknown
--1846-1311845002-xenstore-read backend/vbd/1/51760/state
-1846-1311845002-xenbus_state=2
-1846-1311845002-'[' 2 '!=' 2 ']'
-1846-1311845002-'[' r = w ']'
-1846-1311845002-'[' xr '!=' 'x!' ']'
--1846-1311845002-stat -c %i /var/lib/qubes/vm-kernels/2.6.38.3/modules.img
-1846-1311845002-inode=3014660
--1846-1311845002-stat -c %D /var/lib/qubes/vm-kernels/2.6.38.3/modules.img
-1846-1311845002-dev=fd00
-1846-1311845002-'[' -z 3014660 ']'
-1846-1311845002-'[' -z fd00 ']'
--1846-1311845002-losetup -a
--1846-1311845002-sed -n -e 's@^\([^:]\+\)\(:[[:blank:]]\[0*fd00\]:3014660[[:blank:]](.*)\)@\1@p'
-1846-1311845002-shared_list=
--1846-1311845002-losetup -f
-1846-1311845002-loopdev=/dev/loop4
-1846-1311845002-'[' /dev/loop4 = '' ']'
-1846-1311845002-LANG=C
-1846-1311845002-losetup -h
-1846-1311845002-grep read-only
-1846-1311845002-roflag=-r
-1846-1311845002-roflag=-r
-1846-1311845002-roflag=-r
-1846-1311845002-do_or_die losetup -r /dev/loop4 /var/lib/qubes/vm-kernels/2.6.38.3/modules.img
-1846-1311845002-losetup -r /dev/loop4 /var/lib/qubes/vm-kernels/2.6.38.3/modules.img
-1846-1311845002-xenstore_write backend/vbd/1/51760/node /dev/loop4
-1846-1311845002-_xenstore_write backend/vbd/1/51760/node /dev/loop4
-1846-1311845002-log debug 'Writing backend/vbd/1/51760/node' '/dev/loop4 to xenstore.'
-1846-1311845002-local level=debug
-1846-1311845002-shift
-1846-1311845002-logger -p daemon.debug -- /etc/xen/scripts/block: 'Writing backend/vbd/1/51760/node' '/dev/loop4 to xenstore.'
-1846-1311845002-xenstore-write backend/vbd/1/51760/node /dev/loop4
-1846-1311845002-echo /dev/loop4
-1846-1311845002-write_dev /dev/loop4
-1846-1311845002-local mm
--1846-1311845002-device_major_minor /dev/loop4
--1846-1311845002-stat -L -c %t:%T /dev/loop4
-1846-1311845002-mm=7:4
-1846-1311845002-'[' -z 7:4 ']'
-1846-1311845002-xenstore_write backend/vbd/1/51760/physical-device 7:4
-1846-1311845002-_xenstore_write backend/vbd/1/51760/physical-device 7:4
-1846-1311845002-log debug 'Writing backend/vbd/1/51760/physical-device' '7:4 to xenstore.'
-1846-1311845002-local level=debug
-1846-1311845002-shift
-1846-1311845002-logger -p daemon.debug -- /etc/xen/scripts/block: 'Writing backend/vbd/1/51760/physical-device' '7:4 to xenstore.'
-1846-1311845002-xenstore-write backend/vbd/1/51760/physical-device 7:4
-1846-1311845002-success
-1846-1311845002-xenstore_write backend/vbd/1/51760/hotplug-status connected
-1846-1311845002-_xenstore_write backend/vbd/1/51760/hotplug-status connected
-1846-1311845002-log debug 'Writing backend/vbd/1/51760/hotplug-status' 'connected to xenstore.'
-1846-1311845002-local level=debug
-1846-1311845002-shift
-1846-1311845002-logger -p daemon.debug -- /etc/xen/scripts/block: 'Writing backend/vbd/1/51760/hotplug-status' 'connected to xenstore.'
-1846-1311845002-xenstore-write backend/vbd/1/51760/hotplug-status connected
-1846-1311845002-release_lock block
-1846-1311845002-_release_lock /var/run/xen-hotplug/block
-1846-1311845002-trap sigerr ERR
-1846-1311845002-rm -rf /var/run/xen-hotplug/block
-1846-1311845002-exit 0
--1940-1311845122-xenstore_read_default backend/vbd/1/51760/type MISSING
--1940-1311845122-xenstore-read backend/vbd/1/51760/type
-1940-1311845122-t=file
-1940-1311845122-case "$command" in
--1940-1311845122-cat /var/run/xen-hotplug/backend-vbd-1-51760-type
-1940-1311845122-t=file
-1940-1311845122-case $t in
-1940-1311845122-claim_lock block
-1940-1311845122-local lockdir=/var/run/xen-hotplug/block
-1940-1311845122-mkdir -p /var/run/xen-hotplug
-1940-1311845122-_claim_lock /var/run/xen-hotplug/block
-1940-1311845122-local lockdir=/var/run/xen-hotplug/block
--1940-1311845122-_lock_owner /var/run/xen-hotplug/block
--1940-1311845122-cat /var/run/xen-hotplug/block/owner
--1940-1311845122-echo unknown
-1940-1311845122-local owner=unknown
-1940-1311845122-local retries=0
-1940-1311845122-'[' 0 -lt 100 ']'
-1940-1311845122-mkdir /var/run/xen-hotplug/block
-1940-1311845122-trap '_release_lock /var/run/xen-hotplug/block; sigerr' ERR
-1940-1311845122-_update_lock_info /var/run/xen-hotplug/block
-1940-1311845122-echo '1940: /etc/xen/scripts/block'
-1940-1311845122-return
--1940-1311845122-cat /var/run/xen-hotplug/backend-vbd-1-51760-node
-1940-1311845122-node=/dev/loop4
-1940-1311845122-losetup -d /dev/loop4
-1940-1311845122-release_lock block
-1940-1311845122-_release_lock /var/run/xen-hotplug/block
-1940-1311845122-trap sigerr ERR
-1940-1311845122-rm -rf /var/run/xen-hotplug/block
-1940-1311845122-exit 0
--1993-1311845122-xenstore_read_default backend/vbd/1/51728/type MISSING
--1993-1311845122-xenstore-read backend/vbd/1/51728/type
-1993-1311845122-t=file
-1993-1311845122-case "$command" in
--1993-1311845122-cat /var/run/xen-hotplug/backend-vbd-1-51728-type
-1993-1311845122-t=file
-1993-1311845122-case $t in
-1993-1311845122-claim_lock block
-1993-1311845122-local lockdir=/var/run/xen-hotplug/block
-1993-1311845122-mkdir -p /var/run/xen-hotplug
-1993-1311845122-_claim_lock /var/run/xen-hotplug/block
-1993-1311845122-local lockdir=/var/run/xen-hotplug/block
--1993-1311845122-_lock_owner /var/run/xen-hotplug/block
--1993-1311845122-cat /var/run/xen-hotplug/block/owner
-1993-1311845122-local 'owner=1994: /etc/xen/scripts/xen-hotplug-cleanup'
-1993-1311845122-local retries=0
-1993-1311845122-'[' 0 -lt 100 ']'
-1993-1311845122-mkdir /var/run/xen-hotplug/block
--1993-1311845122-_lock_owner /var/run/xen-hotplug/block
--1993-1311845122-cat /var/run/xen-hotplug/block/owner
--1993-1311845122-echo unknown
-1993-1311845122-local new_owner=unknown
-1993-1311845122-'[' unknown '!=' '1994: /etc/xen/scripts/xen-hotplug-cleanup' ']'
-1993-1311845122-owner=unknown
-1993-1311845122-retries=0
-1993-1311845122-'[' 0 -gt 5 ']'
-1993-1311845122-sleep 0
-1993-1311845122-retries=1
-1993-1311845122-'[' 1 -lt 100 ']'
-1993-1311845122-mkdir /var/run/xen-hotplug/block
-1993-1311845122-trap '_release_lock /var/run/xen-hotplug/block; sigerr' ERR
-1993-1311845122-_update_lock_info /var/run/xen-hotplug/block
-1993-1311845122-echo '1993: /etc/xen/scripts/block'
-1993-1311845122-return
--1993-1311845122-cat /var/run/xen-hotplug/backend-vbd-1-51728-node
-1993-1311845122-node=/dev/loop2
-1993-1311845122-losetup -d /dev/loop2
-1993-1311845122-release_lock block
-1993-1311845122-_release_lock /var/run/xen-hotplug/block
-1993-1311845122-trap sigerr ERR
-1993-1311845122-rm -rf /var/run/xen-hotplug/block
-1993-1311845122-exit 0
--2060-1311845122-xenstore_read_default backend/vbd/1/51712/type MISSING
--2060-1311845122-xenstore-read backend/vbd/1/51712/type
-2060-1311845122-t=snapshot
-2060-1311845122-case "$command" in
--2060-1311845122-cat /var/run/xen-hotplug/backend-vbd-1-51712-type
-2060-1311845122-t=snapshot
-2060-1311845122-case $t in
-2060-1311845122-'[' -x /etc/xen/scripts/block-snapshot ']'
-2060-1311845122-/etc/xen/scripts/block-snapshot remove
++2094+1311845122+xenstore_read_default backend/vbd/1/51712/type MISSING
++2094+1311845122+xenstore-read backend/vbd/1/51712/type
+2094+1311845122+t=snapshot
+2094+1311845122+case "$command" in
+2094+1311845122+'[' remove = cleanup ']'
++2094+1311845122+cat /var/run/xen-hotplug/backend-vbd-1-51712-type
+2094+1311845122+t=snapshot
+2094+1311845122+case $t in
+2094+1311845122+'[' remove = cleanup ']'
++2094+1311845122+cat /var/run/xen-hotplug/backend-vbd-1-51712-node
+2094+1311845122+node=/dev/mapper/snapshot-fd00:1971082-fd00:1971095
+2094+1311845122+'[' -z /dev/mapper/snapshot-fd00:1971082-fd00:1971095 ']'
+2094+1311845122+'[' '!' -e /dev/mapper/snapshot-fd00:1971082-fd00:1971095 ']'
+2094+1311845122+claim_lock block
+2094+1311845122+local lockdir=/var/run/xen-hotplug/block
+2094+1311845122+mkdir -p /var/run/xen-hotplug
+2094+1311845122+_claim_lock /var/run/xen-hotplug/block
+2094+1311845122+local lockdir=/var/run/xen-hotplug/block
++2094+1311845122+_lock_owner /var/run/xen-hotplug/block
++2094+1311845122+cat /var/run/xen-hotplug/block/owner
++2094+1311845122+echo unknown
+2094+1311845122+local owner=unknown
+2094+1311845122+local retries=0
+2094+1311845122+'[' 0 -lt 100 ']'
+2094+1311845122+mkdir /var/run/xen-hotplug/block
+2094+1311845122+trap '_release_lock /var/run/xen-hotplug/block; sigerr' ERR
+2094+1311845122+_update_lock_info /var/run/xen-hotplug/block
+2094+1311845122+echo '2094: /etc/xen/scripts/block-snapshot'
+2094+1311845122+return
++2094+1311845122+dmsetup info /dev/mapper/snapshot-fd00:1971082-fd00:1971095
++2094+1311845122+awk '{print $3}'
++2094+1311845122+grep Open
+2094+1311845122+use_count=0
++2094+1311845122+echo /dev/mapper/snapshot-fd00:1971082-fd00:1971095
++2094+1311845122+cut -d- -f2
+2094+1311845122+'[' /dev/mapper/-fd00:1971082-fd00:1971095 '!=' /dev/mapper/snapshot-fd00:1971082-fd00:1971095 -a -e /dev/mapper/origin-fd00:1971082 ']'
+2094+1311845122+'[' 0 -gt 0 ']'
++2094+1311845122+dmsetup deps /dev/mapper/snapshot-fd00:1971082-fd00:1971095
++2094+1311845122+sed -e 's#(7, \([0-9]\+\))#/dev/loop\1#g'
++2094+1311845122+cut -d: -f2
+2094+1311845122+deps=' /dev/loop1 /dev/loop0'
+2094+1311845122+'[' /dev/mapper/snapshot-fd00:1971082-fd00:1971095 '!=' /dev/mapper/snapshot-fd00:1971082-fd00:1971095 ']'
+2094+1311845122+'[' -e /dev/mapper/snapshot-fd00:1971082-fd00:1971095 ']'
+2094+1311845122+log debug 'Removing /dev/mapper/snapshot-fd00:1971082-fd00:1971095'
+2094+1311845122+local level=debug
+2094+1311845122+shift
+2094+1311845122+logger -p daemon.debug -- /etc/xen/scripts/block-snapshot: 'Removing /dev/mapper/snapshot-fd00:1971082-fd00:1971095'
+2094+1311845122+dmsetup remove /dev/mapper/snapshot-fd00:1971082-fd00:1971095
+2094+1311845122+for dev in '$deps'
+2094+1311845122+'[' -b /dev/loop1 ']'
+2094+1311845122+log debug 'Removing /dev/loop1'
+2094+1311845122+local level=debug
+2094+1311845122+shift
+2094+1311845122+logger -p daemon.debug -- /etc/xen/scripts/block-snapshot: 'Removing /dev/loop1'
+2094+1311845122+losetup -d /dev/loop1
+2094+1311845122+for dev in '$deps'
+2094+1311845122+'[' -b /dev/loop0 ']'
+2094+1311845122+log debug 'Removing /dev/loop0'
+2094+1311845122+local level=debug
+2094+1311845122+shift
+2094+1311845122+logger -p daemon.debug -- /etc/xen/scripts/block-snapshot: 'Removing /dev/loop0'
+2094+1311845122+losetup -d /dev/loop0
+2094+1311845122+release_lock block
+2094+1311845122+_release_lock /var/run/xen-hotplug/block
+2094+1311845122+trap sigerr ERR
+2094+1311845122+rm -rf /var/run/xen-hotplug/block
+2094+1311845122+exit 0
--2138-1311845122-xenstore_read_default backend/vbd/1/51744/type MISSING
--2138-1311845122-xenstore-read backend/vbd/1/51744/type
-2138-1311845122-t=file
-2138-1311845122-case "$command" in
--2138-1311845122-cat /var/run/xen-hotplug/backend-vbd-1-51744-type
-2138-1311845122-t=file
-2138-1311845122-case $t in
-2138-1311845122-claim_lock block
-2138-1311845122-local lockdir=/var/run/xen-hotplug/block
-2138-1311845122-mkdir -p /var/run/xen-hotplug
-2138-1311845122-_claim_lock /var/run/xen-hotplug/block
-2138-1311845122-local lockdir=/var/run/xen-hotplug/block
--2138-1311845122-_lock_owner /var/run/xen-hotplug/block
--2138-1311845122-cat /var/run/xen-hotplug/block/owner
-2138-1311845122-local 'owner=2139: /etc/xen/scripts/xen-hotplug-cleanup'
-2138-1311845122-local retries=0
-2138-1311845122-'[' 0 -lt 100 ']'
-2138-1311845122-mkdir /var/run/xen-hotplug/block
-2138-1311845122-trap '_release_lock /var/run/xen-hotplug/block; sigerr' ERR
-2138-1311845122-_update_lock_info /var/run/xen-hotplug/block
-2138-1311845122-echo '2138: /etc/xen/scripts/block'
-2138-1311845122-return
--2138-1311845122-cat /var/run/xen-hotplug/backend-vbd-1-51744-node
-2138-1311845122-node=/dev/loop3
-2138-1311845122-losetup -d /dev/loop3
-2138-1311845122-release_lock block
-2138-1311845122-_release_lock /var/run/xen-hotplug/block
-2138-1311845122-trap sigerr ERR
-2138-1311845122-rm -rf /var/run/xen-hotplug/block
-2138-1311845122-exit 0

comment:11 Changed 22 months ago by joanna

  • Milestone changed from Release 1 Beta 2 to Release 1 Beta 3
  • Priority changed from critical to major

Sadly we're unable to find the cause of those races. Additionally, they seem to occur only on one of the test systems (with fast SSD disk, but do not seem to be present on another system with similarly fast SSD). There certainly is a race conditions somewhere in Xen/kernel, but we are not fixing it at the moment. I'm moving this to Beta 3 -- perhaps it will be fixed in the meantime by xen-devel or linux folks, and when we upgrade to a new kernel in beta 3, it will just disappear.

comment:12 Changed 21 months ago by joanna

  • Milestone changed from Release 1 Beta 3 to Release 1 Beta 2

comment:13 Changed 21 months ago by joanna

So, this one seems to be solved now by tsc_mode=2?

comment:14 Changed 21 months ago by marmarek

Yes.
BTW this was separate issue, not connected with vbd backend scripts.

comment:15 Changed 21 months ago by marmarek

  • Resolution set to fixed
  • Status changed from assigned to closed
Note: See TracTickets for help on using tickets.