All of lore.kernel.org
 help / color / mirror / Atom feed
* multipath-tools 0.7.4 failure to remove device
@ 2018-01-12  8:38 Julian Andres Klode
  2018-01-12 20:35 ` Martin Wilck
  0 siblings, 1 reply; 22+ messages in thread
From: Julian Andres Klode @ 2018-01-12  8:38 UTC (permalink / raw)
  To: Christophe Varoqui, Device-mapper development mailing list

[-- Attachment #1: Type: text/plain, Size: 4583 bytes --]

Hi,

I am working on updating Ubuntu's multipath-tools from 0.6.4 to 0.7.4, and
our tests report a weird failure. We first build a multipath device from 4
nodes, and then start removing nodes while performing I/O to the multipath
device. This works fine for one or two removals, but eventually we end up
with:

+ multipath -ll
Jan 12 08:23:50 | 8:16: cannot find block device
Jan 12 08:23:50 | 8:16: Empty device name
Jan 12 08:23:50 | 8:16: Empty device name
360000000000000000e00000000010001 dm-0 IET,VIRTUAL-DISK
size=100M features='0' hwhandler='0' wp=rw
|-+- policy='service-time 0' prio=0 status=enabled
| `- #:#:#:# -   #:#  failed undef unknown
|-+- policy='service-time 0' prio=1 status=active
| `- 4:0:0:1 sdc 8:32 active ready running
`-+- policy='service-time 0' prio=1 status=enabled
  `- 5:0:0:1 sdd 8:48 active ready running

and then we get I/O error on the device and it's rendered unusable. It's
also crashing in uev_pathfail_check() occassionally because find_path_by_devt()
returns NULL, so I applied the following patch to at least continue, but that's
obviously wrong - We get an udev event for a device which does not exist in /dev
(but it should)?

--- a/multipathd/main.c
+++ b/multipathd/main.c
@@ -1090,6 +1090,11 @@ uev_pathfail_check(struct uevent *uev, s
 	lock(&vecs->lock);
 	pthread_testcancel();
 	pp = find_path_by_devt(vecs->pathvec, devt);
+	if (!pp) {
+		condlog(3, "%s: Cannot find path by dm path %s", uev->kernel, devt);
+		FREE(devt);
+		goto out;
+	}
 	r = io_err_stat_handle_pathfail(pp);
 	lock_cleanup_pop(vecs->lock);
 

The journal mentions something useful I guess. Let's start at the mount:

Jan 12 09:17:30 autopkgtest kernel: EXT4-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null)
Jan 12 09:17:42 autopkgtest kernel: device-mapper: multipath: Failing path 8:0.
Jan 12 09:17:42 autopkgtest multipathd[1980]: sda: mark as failed
Jan 12 09:17:42 autopkgtest multipathd[1980]: 360000000000000000e00000000010001: remaining active paths: 3
Jan 12 09:17:42 autopkgtest kernel: sd 2:0:0:1: [sda] Synchronizing SCSI cache
Jan 12 09:17:42 autopkgtest multipathd[1980]: sda: remove path (uevent)
Jan 12 09:17:42 autopkgtest multipathd[1980]: 360000000000000000e00000000010001: load table [0 204800 multipath 0 0 3 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:32 1 service-time 0 1 1 8:48 1
Jan 12 09:17:42 autopkgtest multipathd[1980]: ]
Jan 12 09:17:42 autopkgtest multipathd[1980]: sda [8:0]: path removed from map 360000000000000000e00000000010001
Jan 12 09:17:42 autopkgtest multipath[6877]: dm-0: usable paths found
Jan 12 09:17:42 autopkgtest multipath[6887]: dm-0: usable paths found
Jan 12 09:17:43 autopkgtest iscsid[649]: Connection1:0 to [target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] through [iface: default] is shutdown.
Jan 12 09:17:43 autopkgtest multipathd[1980]: dm-0: Cannot find path by dm path 8:0

			   ^^^^^^^^^^^^^^^^^^^ would have crashed here

Jan 12 09:17:52 autopkgtest kernel: device-mapper: multipath: Failing path 8:16.
Jan 12 09:17:52 autopkgtest kernel: sd 3:0:0:1: [sdb] Synchronizing SCSI cache
Jan 12 09:17:52 autopkgtest multipath[6909]: 8:16: cannot find block device
Jan 12 09:17:52 autopkgtest multipath[6909]: 8:16: Empty device name
Jan 12 09:17:52 autopkgtest multipath[6909]: 8:16: Empty device name
Jan 12 09:17:52 autopkgtest multipath[6909]: get_udev_device: failed to look up 8:16 with type 1
Jan 12 09:17:52 autopkgtest multipath[6909]: dm-0: usable paths found
Jan 12 09:17:53 autopkgtest iscsid[649]: Connection2:0 to [target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] through [iface: default] is shutdown.

We can see that it correctly removed the first device (sda) - except well, it seems to try
again and fail with the part where it would have crashed. But when it tries to lookup the
second one it fails.

Given that this works in 0.6.4, I think it's a bug that appeared later on,
but I can't really pin point the source of it.


I attached:

* the test script (might need some changes to run outside Ubuntu,
  it uses service tgt restart and writes output to $AUTOPKGTEST_ARTIFACTS)
* a udevadm monitor log when removing devices
* test-background.log which logs the path removals
* journal.log which contains the systemd journal, starting when multipathd started
* autopkgtest.log containing the output (from the run before, I accidentally deleted
  the current run, but output is the same)

-- 
debian developer - deb.li/jak | jak-linux.org - free software dev
ubuntu core developer                              i speak de, en

[-- Attachment #2: test-background.log --]
[-- Type: text/plain, Size: 7460 bytes --]

+ iscsiadm --mode session
tcp: [1] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash)
tcp: [2] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash)
tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash)
tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash)
+ sleep 10s
+ date +MP report (expect 4) %H:%M:%S.%N
MP report (expect 4) 09:17:41.865602408
+ multipath -ll
360000000000000000e00000000010001 dm-0 IET,VIRTUAL-DISK
size=100M features='0' hwhandler='0' wp=rw
|-+- policy='service-time 0' prio=1 status=active
| `- 2:0:0:1 sda 8:0  active ready running
|-+- policy='service-time 0' prio=1 status=enabled
| `- 3:0:0:1 sdb 8:16 active ready running
|-+- policy='service-time 0' prio=1 status=enabled
| `- 4:0:0:1 sdc 8:32 active ready running
`-+- policy='service-time 0' prio=1 status=enabled
  `- 5:0:0:1 sdd 8:48 active ready running
+ date +UN-plug path 1 %H:%M:%S.%N
UN-plug path 1 09:17:42.061970430
+ iscsiadm --mode session -r 1 -u
Logging out of session [sid: 1, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260]
Logout of [sid: 1, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful.
+ iscsiadm --mode session
tcp: [2] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash)
tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash)
tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash)
+ sleep 10s
+ date +MP report (expect 3) %H:%M:%S.%N
MP report (expect 3) 09:17:52.120551204
+ multipath -ll
360000000000000000e00000000010001 dm-0 IET,VIRTUAL-DISK
size=100M features='0' hwhandler='0' wp=rw
|-+- policy='service-time 0' prio=1 status=active
| `- 3:0:0:1 sdb 8:16 active ready running
|-+- policy='service-time 0' prio=1 status=enabled
| `- 4:0:0:1 sdc 8:32 active ready running
`-+- policy='service-time 0' prio=1 status=enabled
  `- 5:0:0:1 sdd 8:48 active ready running
+ date +UN-plug path 2 %H:%M:%S.%N
UN-plug path 2 09:17:52.140778540
+ iscsiadm --mode session -r 2 -u
Logging out of session [sid: 2, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260]
Logout of [sid: 2, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful.
+ iscsiadm --mode session
tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash)
tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash)
+ sleep 10s
+ date +MP report (expect 2) %H:%M:%S.%N
MP report (expect 2) 09:18:02.174689219
+ multipath -ll
Jan 12 09:18:02 | 8:16: cannot find block device
Jan 12 09:18:02 | 8:16: Empty device name
Jan 12 09:18:02 | 8:16: Empty device name
360000000000000000e00000000010001 dm-0 IET,VIRTUAL-DISK
size=100M features='0' hwhandler='0' wp=rw
|-+- policy='service-time 0' prio=0 status=enabled
| `- #:#:#:# -   #:#  failed undef unknown
|-+- policy='service-time 0' prio=1 status=active
| `- 4:0:0:1 sdc 8:32 active ready running
`-+- policy='service-time 0' prio=1 status=enabled
  `- 5:0:0:1 sdd 8:48 active ready running
+ date +UN-plug path 3 %H:%M:%S.%N
UN-plug path 3 09:18:02.211466936
+ iscsiadm --mode session -r 3 -u
Logging out of session [sid: 3, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260]
Logout of [sid: 3, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful.
+ iscsiadm --mode session
tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash)
+ sleep 10s
+ date +MP report (expect 1) %H:%M:%S.%N
MP report (expect 1) 09:18:12.259643693
+ multipath -ll
Jan 12 09:18:12 | 8:16: cannot find block device
Jan 12 09:18:12 | 8:16: Empty device name
Jan 12 09:18:12 | 8:16: Empty device name
Jan 12 09:18:12 | 8:32: cannot find block device
Jan 12 09:18:12 | 8:32: Empty device name
Jan 12 09:18:12 | 8:32: Empty device name
360000000000000000e00000000010001 dm-0 IET,VIRTUAL-DISK
size=100M features='0' hwhandler='0' wp=rw
|-+- policy='service-time 0' prio=0 status=enabled
| `- #:#:#:# -   #:#  failed undef unknown
|-+- policy='service-time 0' prio=0 status=enabled
| `- #:#:#:# -   #:#  failed undef unknown
`-+- policy='service-time 0' prio=1 status=active
  `- 5:0:0:1 sdd 8:48 active ready running
+ date +Add paths 5/6/7/8 %H:%M:%S.%N
Add paths 5/6/7/8 09:18:12.271680780
+ iscsiadm --mode session -r 4 --op new
Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple)
Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful.
+ iscsiadm --mode session -r 4 --op new
Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple)
Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful.
+ iscsiadm --mode session -r 4 --op new
Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple)
Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful.
+ iscsiadm --mode session -r 4 --op new
Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple)
Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful.
+ iscsiadm --mode session
tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash)
tcp: [5] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash)
tcp: [6] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash)
tcp: [7] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash)
tcp: [8] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash)
+ sleep 10s
+ date +MP report (expect 5) %H:%M:%S.%N
MP report (expect 5) 09:18:22.361908579
+ multipath -ll
Jan 12 09:18:22 | 8:16: cannot find block device
Jan 12 09:18:22 | 8:16: Empty device name
Jan 12 09:18:22 | 8:16: Empty device name
Jan 12 09:18:22 | 8:32: cannot find block device
Jan 12 09:18:22 | 8:32: Empty device name
Jan 12 09:18:22 | 8:32: Empty device name
360000000000000000e00000000010001 dm-0 IET,VIRTUAL-DISK
size=100M features='0' hwhandler='0' wp=rw
|-+- policy='service-time 0' prio=0 status=enabled
| `- #:#:#:# -   #:#  failed undef unknown
|-+- policy='service-time 0' prio=0 status=enabled
| `- #:#:#:# -   #:#  failed undef unknown
`-+- policy='service-time 0' prio=1 status=active
  `- 5:0:0:1 sdd 8:48 active ready running
+ date +UN-plug multiple paths 4/7/8 %H:%M:%S.%N
UN-plug multiple paths 4/7/8 09:18:22.391372112
+ iscsiadm --mode session -r 4 -u
Logging out of session [sid: 4, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260]
Logout of [sid: 4, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful.
+ iscsiadm --mode session -r 7 -u
Logging out of session [sid: 7, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260]
Logout of [sid: 7, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful.
+ iscsiadm --mode session -r 8 -u
Logging out of session [sid: 8, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260]
Logout of [sid: 8, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful.
+ iscsiadm --mode session
tcp: [5] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash)
tcp: [6] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash)
+ sleep 10s
+ date +Restart multipath daemon %H:%M:%S.%N
Restart multipath daemon 09:18:32.503401265
+ systemctl restart multipathd

[-- Attachment #3: tgtbasedmpaths --]
[-- Type: text/plain, Size: 5832 bytes --]

#!/bin/sh
# autopkgtest check: tgt and open-iscsi based mpath operations
# The test is intentionally extra verbose to have rich log and to stress
# some of the code paths in and around multipath on top of the actual IO test.
# (C) 2016 Canonical Ltd.
# Author: Christian Ehrhardt <christian.ehrhardt@canonical.com>

# Tests the creation and usage of a tgt target and lun on localhost
set -uxe

targetname="iqn.2016-11.foo.com:target.iscsi"
cwd=$(pwd)
testdir="/mnt/tgtmpathtest"
localhost="127.0.0.1"
portal="${localhost}:3260"
maxpaths=4
backfn="backingfile"
expectwwid="360000000000000000e00000000010001"
testdisk="/dev/disk/by-id/scsi-${expectwwid}"
bglog="$AUTOPKGTEST_ARTIFACTS/test-background.log"
udevlog="$AUTOPKGTEST_ARTIFACTS/udev-path-changes.log"
fioprep="$AUTOPKGTEST_ARTIFACTS/path-change-prep.fio"
fiovrfy="$AUTOPKGTEST_ARTIFACTS/path-change-check.fio"

# Restart tgtd to make sure modules are all loaded
service tgt restart || echo "Failed to restart tgt" >&2

# prep SINGLE test file
truncate --size 100M ${backfn}

# create target
tgtadm --lld iscsi --op new --mode target --tid 1 -T "${targetname}"
# allow all to bind the target
tgtadm --lld iscsi --op bind --mode target --tid 1 -I ALL
# set backing file
tgtadm --lld iscsi --op new --mode logicalunit --tid 1 --lun 1 -b "${cwd}/${backfn}"

# scan for targets (locally)
iscsiadm --mode discovery --type sendtargets --portal ${localhost}

# login
echo "login #1"
iscsiadm --mode node --targetname "${targetname}" --portal ${portal} --login
# duplicate this session (always 1)
for i in $(seq 2 ${maxpaths})
do
    echo "extra login #${i}"
    iscsiadm --mode session -r 1 --op new
done

udevadm settle

# status summary
echo "Status after initial setup"
tgtadm --lld iscsi --mode target --op show
tgtadm --lld iscsi --op show --mode conn --tid 1
iscsiadm --mode session -P 1
lsscsi -liv
multipath -v3 -ll
dmsetup table

echo "Test WWN should now point to DM"
readlink "${testdisk}" | grep dm

# create FS on the mpathed device
mkfs.ext4 -F "${testdisk}"
udevadm settle
sleep 3s
mkdir -p ${testdir}
mount "${testdisk}" ${testdir}

# based on /usr/share/doc/fio/examples/surface-scan.fio
cat << EOF > ${fioprep}
; writes 512 byte verification blocks until the disk is full,
; then verifies written data
[global]
directory=${testdir}
thread=1
bs=64k
direct=1
ioengine=sync
verify=meta
verify_pattern=0xaa555aa5
verify_interval=512

[write-phase]
filename=datafile.tmp   ; or use a full disk, for example /dev/sda
rw=write
fill_device=1
do_verify=0
EOF

cat << EOF > ${fiovrfy}
; verifies written data
[global]
directory=${testdir}
thread=1
bs=64k
direct=1
ioengine=sync
verify=meta
verify_pattern=0xaa555aa5
verify_interval=512

[verify-phase]
stonewall
create_serialize=0
filename=datafile.tmp
rw=read
do_verify=1
runtime=180
time_based
EOF

# IO Bench with verify
# prep files
fio "${fioprep}"

udevadm monitor > $udevlog		&

# while verify is running unplud/plug paths as well as restart the daemon
# Note - we run in a clean env, so we just assume each new session is an increment
# Even with other multipath/scsi devices on the system this is true, jutst no
# other iscsi logins are allowed - since the test runs under isolation-machine
# that should be safe.
# That way we can directly call IDs without huge logic on the session IDs
echo "Starting the path changes in background"
(
    iscsiadm --mode session
    sleep 10s
    date +'MP report (expect 4) %H:%M:%S.%N'
    multipath -ll
    date +'UN-plug path 1 %H:%M:%S.%N'
    iscsiadm --mode session -r 1 -u
    iscsiadm --mode session
    sleep 10s
    date +'MP report (expect 3) %H:%M:%S.%N'
    multipath -ll
    date +'UN-plug path 2 %H:%M:%S.%N'
    iscsiadm --mode session -r 2 -u
    iscsiadm --mode session
    sleep 10s
    date +'MP report (expect 2) %H:%M:%S.%N'
    multipath -ll
    date +'UN-plug path 3 %H:%M:%S.%N'
    iscsiadm --mode session -r 3 -u
    iscsiadm --mode session
    sleep 10s
    date +'MP report (expect 1) %H:%M:%S.%N'
    multipath -ll
    date +'Add paths 5/6/7/8 %H:%M:%S.%N'
    iscsiadm --mode session -r 4 --op new
    iscsiadm --mode session -r 4 --op new
    iscsiadm --mode session -r 4 --op new
    iscsiadm --mode session -r 4 --op new
    iscsiadm --mode session
    sleep 10s
    date +'MP report (expect 5) %H:%M:%S.%N'
    multipath -ll
    date +'UN-plug multiple paths 4/7/8 %H:%M:%S.%N'
    iscsiadm --mode session -r 4 -u
    iscsiadm --mode session -r 7 -u
    iscsiadm --mode session -r 8 -u
    iscsiadm --mode session
    sleep 10s
    date +'Restart multipath daemon %H:%M:%S.%N'
    systemctl restart multipathd
    sleep 10s
    date +'Final background report (expect 2) %H:%M:%S.%N'
    multipath -ll
) > "${bglog}" 2>&1 &

# test I/O with verification of actual content
# on any I/O error or verification of read data it would fail
date +'Pre FIO %H:%M:%S.%N'
fio "${fiovrfy}"
date +'Post FIO %H:%M:%S.%N'

echo "FIO verify test with changing paths - OK"

echo "Report log of background activity"
cat "${bglog}"

sync
umount "${testdisk}"

# report stats - might be useful if checked across various tests that misbehave
echo "Final stats"
iscsiadm --mode session --stats
journalctl --no-pager -u multipathd

echo "Check final path status"
multipath -ll
# ensure we have one active and one running path
diskc=$(multipath -ll | grep --count 'status=')
diska=$(multipath -ll | grep --count 'status=active')
diske=$(multipath -ll | grep --count 'status=enabled')
if [ "${diskc}" -ne "2" -o "${diska}" -ne "1" -o "${diske}" -ne "1" ]; then
    echo "Error: Not the expected count of active/enabled disks"
    exit 1
else
    echo "OK"
fi

# logout and target delete should work even after all of this
iscsiadm --mode node --targetname "${targetname}" --portal "${portal}" --logout
tgtadm --lld iscsi --op delete --mode logicalunit --tid 1 --lun 1

[-- Attachment #4: autopkgtest.log --]
[-- Type: text/plain, Size: 66880 bytes --]

autopkgtest [08:49:10]: version 5.1
autopkgtest [08:49:10]: host jak-x230; command line: /usr/bin/autopkgtest -l autopkgtest.log '--setup-commands=apt install -y systemd-coredump gdb' --shell-fail ../multipath-tools_0.7.4-2ubuntu1_amd64.changes -- qemu /home/jak/autopkgtest-bionic-amd64.img
autopkgtest [08:49:31]: @@@@@@@@@@@@@@@@@@@@ test bed setup

WARNING: apt does not have a stable CLI interface. Use with caution in scripts.

Reading package lists...
Building dependency tree...
Reading state information...
The following package was automatically installed and is no longer required:
  grub-pc-bin
Use 'apt autoremove' to remove it.
The following additional packages will be installed:
  gdbserver libbabeltrace1 libc6-dbg libcc1-0 libdw1 libelf1 libnss-systemd
  libpam-systemd libsystemd0 python3-apport systemd
Suggested packages:
  gdb-doc python3-launchpadlib systemd-container
Recommended packages:
  apport
The following packages will be REMOVED:
  apport ubuntu-server
The following NEW packages will be installed:
  gdb gdbserver libbabeltrace1 libc6-dbg libcc1-0 libdw1 systemd-coredump
The following packages will be upgraded:
  libelf1 libnss-systemd libpam-systemd libsystemd0 python3-apport systemd
6 upgraded, 7 newly installed, 2 to remove and 16 not upgraded.
Need to get 11.7 MB of archives.
After this operation, 48.5 MB of additional disk space will be used.
Get:1 http://archive.ubuntu.com/ubuntu bionic/main amd64 libnss-systemd amd64 235-3ubuntu3 [97.2 kB]
Get:2 http://archive.ubuntu.com/ubuntu bionic/main amd64 libpam-systemd amd64 235-3ubuntu3 [100 kB]
Get:3 http://archive.ubuntu.com/ubuntu bionic/main amd64 systemd amd64 235-3ubuntu3 [2,834 kB]
Get:4 http://archive.ubuntu.com/ubuntu bionic/main amd64 libsystemd0 amd64 235-3ubuntu3 [197 kB]
Get:5 http://archive.ubuntu.com/ubuntu bionic/main amd64 libelf1 amd64 0.170-0.2 [44.4 kB]
Get:6 http://archive.ubuntu.com/ubuntu bionic/main amd64 libdw1 amd64 0.170-0.2 [203 kB]
Get:7 http://archive.ubuntu.com/ubuntu bionic/main amd64 libbabeltrace1 amd64 1.5.3-4 [152 kB]
Get:8 http://archive.ubuntu.com/ubuntu bionic/main amd64 gdb amd64 8.0.1-0ubuntu3 [2,735 kB]
Get:9 http://archive.ubuntu.com/ubuntu bionic/main amd64 gdbserver amd64 8.0.1-0ubuntu3 [185 kB]
Get:10 http://archive.ubuntu.com/ubuntu bionic/main amd64 libcc1-0 amd64 7.2.0-18ubuntu2 [38.7 kB]
Get:11 http://archive.ubuntu.com/ubuntu bionic/main amd64 python3-apport all 2.20.8-0ubuntu6 [80.6 kB]
Get:12 http://archive.ubuntu.com/ubuntu bionic/universe amd64 systemd-coredump amd64 235-3ubuntu3 [41.6 kB]
Get:13 http://archive.ubuntu.com/ubuntu bionic/main amd64 libc6-dbg amd64 2.26-0ubuntu2 [4,996 kB]
Fetched 11.7 MB in 0s (50.7 MB/s)
(Reading database ... \r(Reading database ... 5%\r(Reading database ... 10%\r(Reading database ... 15%\r(Reading database ... 20%\r(Reading database ... 25%\r(Reading database ... 30%\r(Reading database ... 35%\r(Reading database ... 40%\r(Reading database ... 45%\r(Reading database ... 50%\r(Reading database ... 55%\r(Reading database ... 60%\r(Reading database ... 65%\r(Reading database ... 70%\r(Reading database ... 75%\r(Reading database ... 80%\r(Reading database ... 85%\r(Reading database ... 90%\r(Reading database ... 95%\r(Reading database ... 100%\r(Reading database ... 57061 files and directories currently installed.)
Removing ubuntu-server (1.407) ...
Removing apport (2.20.8-0ubuntu5) ...
(Reading database ... \r(Reading database ... 5%\r(Reading database ... 10%\r(Reading database ... 15%\r(Reading database ... 20%\r(Reading database ... 25%\r(Reading database ... 30%\r(Reading database ... 35%\r(Reading database ... 40%\r(Reading database ... 45%\r(Reading database ... 50%\r(Reading database ... 55%\r(Reading database ... 60%\r(Reading database ... 65%\r(Reading database ... 70%\r(Reading database ... 75%\r(Reading database ... 80%\r(Reading database ... 85%\r(Reading database ... 90%\r(Reading database ... 95%\r(Reading database ... 100%\r(Reading database ... 56982 files and directories currently installed.)
Preparing to unpack .../libnss-systemd_235-3ubuntu3_amd64.deb ...
Unpacking libnss-systemd:amd64 (235-3ubuntu3) over (235-3ubuntu2) ...
Preparing to unpack .../libpam-systemd_235-3ubuntu3_amd64.deb ...
Unpacking libpam-systemd:amd64 (235-3ubuntu3) over (235-3ubuntu2) ...
Preparing to unpack .../systemd_235-3ubuntu3_amd64.deb ...
Unpacking systemd (235-3ubuntu3) over (235-3ubuntu2) ...
Preparing to unpack .../libsystemd0_235-3ubuntu3_amd64.deb ...
Unpacking libsystemd0:amd64 (235-3ubuntu3) over (235-3ubuntu2) ...
Setting up libsystemd0:amd64 (235-3ubuntu3) ...
(Reading database ... \r(Reading database ... 5%\r(Reading database ... 10%\r(Reading database ... 15%\r(Reading database ... 20%\r(Reading database ... 25%\r(Reading database ... 30%\r(Reading database ... 35%\r(Reading database ... 40%\r(Reading database ... 45%\r(Reading database ... 50%\r(Reading database ... 55%\r(Reading database ... 60%\r(Reading database ... 65%\r(Reading database ... 70%\r(Reading database ... 75%\r(Reading database ... 80%\r(Reading database ... 85%\r(Reading database ... 90%\r(Reading database ... 95%\r(Reading database ... 100%\r(Reading database ... 56982 files and directories currently installed.)
Preparing to unpack .../0-libelf1_0.170-0.2_amd64.deb ...
Unpacking libelf1:amd64 (0.170-0.2) over (0.170-0.1) ...
Selecting previously unselected package libdw1:amd64.
Preparing to unpack .../1-libdw1_0.170-0.2_amd64.deb ...
Unpacking libdw1:amd64 (0.170-0.2) ...
Selecting previously unselected package libbabeltrace1:amd64.
Preparing to unpack .../2-libbabeltrace1_1.5.3-4_amd64.deb ...
Unpacking libbabeltrace1:amd64 (1.5.3-4) ...
Selecting previously unselected package gdb.
Preparing to unpack .../3-gdb_8.0.1-0ubuntu3_amd64.deb ...
Unpacking gdb (8.0.1-0ubuntu3) ...
Selecting previously unselected package gdbserver.
Preparing to unpack .../4-gdbserver_8.0.1-0ubuntu3_amd64.deb ...
Unpacking gdbserver (8.0.1-0ubuntu3) ...
Selecting previously unselected package libcc1-0:amd64.
Preparing to unpack .../5-libcc1-0_7.2.0-18ubuntu2_amd64.deb ...
Unpacking libcc1-0:amd64 (7.2.0-18ubuntu2) ...
Preparing to unpack .../6-python3-apport_2.20.8-0ubuntu6_all.deb ...
Unpacking python3-apport (2.20.8-0ubuntu6) over (2.20.8-0ubuntu5) ...
Selecting previously unselected package systemd-coredump.
Preparing to unpack .../7-systemd-coredump_235-3ubuntu3_amd64.deb ...
Unpacking systemd-coredump (235-3ubuntu3) ...
Selecting previously unselected package libc6-dbg:amd64.
Preparing to unpack .../8-libc6-dbg_2.26-0ubuntu2_amd64.deb ...
Unpacking libc6-dbg:amd64 (2.26-0ubuntu2) ...
Setting up libcc1-0:amd64 (7.2.0-18ubuntu2) ...
Setting up libc6-dbg:amd64 (2.26-0ubuntu2) ...
Processing triggers for ureadahead (0.100.0-20) ...
Setting up libelf1:amd64 (0.170-0.2) ...
Setting up python3-apport (2.20.8-0ubuntu6) ...
Processing triggers for libc-bin (2.26-0ubuntu2) ...
Setting up systemd (235-3ubuntu3) ...
Created symlink /etc/systemd/system/dbus-org.freedesktop.network1.service → /lib/systemd/system/systemd-networkd.service.
Processing triggers for man-db (2.7.6.1-4) ...
Setting up gdbserver (8.0.1-0ubuntu3) ...
Processing triggers for dbus (1.12.2-1ubuntu1) ...
Setting up libnss-systemd:amd64 (235-3ubuntu3) ...
Setting up libpam-systemd:amd64 (235-3ubuntu3) ...
Setting up libdw1:amd64 (0.170-0.2) ...
Setting up libbabeltrace1:amd64 (1.5.3-4) ...
Setting up systemd-coredump (235-3ubuntu3) ...
Setting up gdb (8.0.1-0ubuntu3) ...
Processing triggers for libc-bin (2.26-0ubuntu2) ...
autopkgtest [08:49:44]: rebooting testbed after setup commands that affected boot
autopkgtest [08:50:05]: testbed running kernel: Linux 4.13.0-17-generic #20-Ubuntu SMP Mon Nov 6 10:04:08 UTC 2017
autopkgtest [08:50:05]: testbed dpkg architecture: amd64
autopkgtest [08:50:08]: @@@@@@@@@@@@@@@@@@@@ source ../multipath-tools_0.7.4-2ubuntu1.dsc
Reading package lists...
Building dependency tree...
Reading state information...
Correcting dependencies...Starting pkgProblemResolver with broken count: 0
Starting 2 pkgProblemResolver with broken count: 0
Done
 Done
Starting pkgProblemResolver with broken count: 0
Starting 2 pkgProblemResolver with broken count: 0
Done
The following package was automatically installed and is no longer required:
  grub-pc-bin
Use 'apt autoremove' to remove it.
The following additional packages will be installed:
  binutils binutils-common binutils-x86-64-linux-gnu dpkg-dev libbinutils
  libdpkg-perl make
Suggested packages:
  binutils-doc debian-keyring gcc | c-compiler bzr make-doc
Recommended packages:
  build-essential gcc | c-compiler fakeroot libalgorithm-merge-perl
  libfile-fcntllock-perl
The following NEW packages will be installed:
  binutils binutils-common binutils-x86-64-linux-gnu dpkg-dev libbinutils
  libdpkg-perl make
0 upgraded, 7 newly installed, 0 to remove and 21 not upgraded.
1 not fully installed or removed.
Need to get 3,492 kB of archives.
After this operation, 18.9 MB of additional disk space will be used.
Get:1 http://archive.ubuntu.com/ubuntu bionic/main amd64 libdpkg-perl all 1.19.0.4ubuntu1 [211 kB]
Get:2 http://archive.ubuntu.com/ubuntu bionic/main amd64 make amd64 4.1-9.1 [154 kB]
Get:3 http://archive.ubuntu.com/ubuntu bionic/main amd64 binutils-common amd64 2.29.1-12ubuntu1 [190 kB]
Get:4 http://archive.ubuntu.com/ubuntu bionic/main amd64 libbinutils amd64 2.29.1-12ubuntu1 [503 kB]
Get:5 http://archive.ubuntu.com/ubuntu bionic/main amd64 binutils-x86-64-linux-gnu amd64 2.29.1-12ubuntu1 [1,825 kB]
Get:6 http://archive.ubuntu.com/ubuntu bionic/main amd64 binutils amd64 2.29.1-12ubuntu1 [3,408 B]
Get:7 http://archive.ubuntu.com/ubuntu bionic/main amd64 dpkg-dev all 1.19.0.4ubuntu1 [607 kB]
Fetched 3,492 kB in 0s (30.2 MB/s)
Selecting previously unselected package libdpkg-perl.
(Reading database ... \r(Reading database ... 5%\r(Reading database ... 10%\r(Reading database ... 15%\r(Reading database ... 20%\r(Reading database ... 25%\r(Reading database ... 30%\r(Reading database ... 35%\r(Reading database ... 40%\r(Reading database ... 45%\r(Reading database ... 50%\r(Reading database ... 55%\r(Reading database ... 60%\r(Reading database ... 65%\r(Reading database ... 70%\r(Reading database ... 75%\r(Reading database ... 80%\r(Reading database ... 85%\r(Reading database ... 90%\r(Reading database ... 95%\r(Reading database ... 100%\r(Reading database ... 57437 files and directories currently installed.)
Preparing to unpack .../0-libdpkg-perl_1.19.0.4ubuntu1_all.deb ...
Unpacking libdpkg-perl (1.19.0.4ubuntu1) ...
Selecting previously unselected package make.
Preparing to unpack .../1-make_4.1-9.1_amd64.deb ...
Unpacking make (4.1-9.1) ...
Selecting previously unselected package binutils-common:amd64.
Preparing to unpack .../2-binutils-common_2.29.1-12ubuntu1_amd64.deb ...
Unpacking binutils-common:amd64 (2.29.1-12ubuntu1) ...
Selecting previously unselected package libbinutils:amd64.
Preparing to unpack .../3-libbinutils_2.29.1-12ubuntu1_amd64.deb ...
Unpacking libbinutils:amd64 (2.29.1-12ubuntu1) ...
Selecting previously unselected package binutils-x86-64-linux-gnu.
Preparing to unpack .../4-binutils-x86-64-linux-gnu_2.29.1-12ubuntu1_amd64.deb ...
Unpacking binutils-x86-64-linux-gnu (2.29.1-12ubuntu1) ...
Selecting previously unselected package binutils.
Preparing to unpack .../5-binutils_2.29.1-12ubuntu1_amd64.deb ...
Unpacking binutils (2.29.1-12ubuntu1) ...
Selecting previously unselected package dpkg-dev.
Preparing to unpack .../6-dpkg-dev_1.19.0.4ubuntu1_all.deb ...
Unpacking dpkg-dev (1.19.0.4ubuntu1) ...
Setting up make (4.1-9.1) ...
Setting up libdpkg-perl (1.19.0.4ubuntu1) ...
Setting up binutils-common:amd64 (2.29.1-12ubuntu1) ...
Processing triggers for libc-bin (2.26-0ubuntu2) ...
Processing triggers for man-db (2.7.6.1-4) ...
Setting up libbinutils:amd64 (2.29.1-12ubuntu1) ...
Setting up binutils-x86-64-linux-gnu (2.29.1-12ubuntu1) ...
Setting up binutils (2.29.1-12ubuntu1) ...
Setting up dpkg-dev (1.19.0.4ubuntu1) ...
Setting up autopkgtest-satdep (0) ...
Processing triggers for libc-bin (2.26-0ubuntu2) ...
(Reading database ... 58021 files and directories currently installed.)
Removing autopkgtest-satdep (0) ...
dpkg-source: warning: extracting unsigned source package (/tmp/autopkgtest.ei92jh/multipath-tools_0.7.4-2ubuntu1.dsc)
dpkg-source: info: extracting multipath-tools in src
dpkg-source: info: unpacking multipath-tools_0.7.4.orig.tar.gz
dpkg-source: info: unpacking multipath-tools_0.7.4-2ubuntu1.debian.tar.xz
dpkg-source: info: applying 0004-Fix-lintian-complaint-about-bad-whatis-entry.patch
dpkg-source: info: applying 0001-blacklist-cciss-devices.patch
dpkg-source: info: applying 0009-hardened-build-flags.patch
dpkg-source: info: applying 0011-patch-udev-rule.patch
dpkg-source: info: applying 0014-libmultipath-discovery-blank-rev-attr.patch
dpkg-source: info: applying systemd-alias.patch
dpkg-source: info: applying disable-systemd-for-udeb.patch
dpkg-source: info: applying disable-rados-link-for-udeb-new.patch
dpkg-source: info: applying 1000--set-umask-in-multipathd.patch
dpkg-source: info: applying disable-fexceptions-udeb.patch
dpkg-source: info: applying kpartx_more_loopback_fixes.patch
dpkg-source: info: applying multipathd-crash-fix.patch
dpkg-source: info: applying fix-usrmerge-paths.patch
dpkg-source: info: applying 11-dm-mpath-fix-DM_UDEV_RULES_VSN-check.patch
autopkgtest [08:50:21]: testing package multipath-tools version 0.7.4-2ubuntu1
autopkgtest [08:50:21]: build not needed
autopkgtest [08:50:22]: test kpartx-file-loopback: preparing testbed
Get:1 file:/tmp/autopkgtest.ei92jh/binaries  InRelease
Ign:1 file:/tmp/autopkgtest.ei92jh/binaries  InRelease
Get:2 file:/tmp/autopkgtest.ei92jh/binaries  Release [816 B]
Get:2 file:/tmp/autopkgtest.ei92jh/binaries  Release [816 B]
Get:3 file:/tmp/autopkgtest.ei92jh/binaries  Release.gpg
Ign:3 file:/tmp/autopkgtest.ei92jh/binaries  Release.gpg
Get:4 file:/tmp/autopkgtest.ei92jh/binaries  Packages [4,627 B]
Reading package lists...
Reading package lists...
Building dependency tree...
Reading state information...
Correcting dependencies...Starting pkgProblemResolver with broken count: 0
Starting 2 pkgProblemResolver with broken count: 0
Done
 Done
Starting pkgProblemResolver with broken count: 0
Starting 2 pkgProblemResolver with broken count: 0
Done
The following additional packages will be installed:
  kpartx libaio1 libboost-iostreams1.65.1 libboost-random1.65.1
  libboost-regex1.65.1 libboost-system1.65.1 libboost-thread1.65.1 libibverbs1
  libiscsi7 libnl-3-200 libnl-route-3-200 libnspr4 libnss3 librados2 librbd1
  qemu-block-extra qemu-utils
Suggested packages:
  debootstrap
Recommended packages:
  sharutils
The following NEW packages will be installed:
  kpartx libaio1 libboost-iostreams1.65.1 libboost-random1.65.1
  libboost-regex1.65.1 libboost-system1.65.1 libboost-thread1.65.1 libibverbs1
  libiscsi7 libnl-3-200 libnl-route-3-200 libnspr4 libnss3 librados2 librbd1
  qemu-block-extra qemu-utils
0 upgraded, 17 newly installed, 0 to remove and 21 not upgraded.
1 not fully installed or removed.
Need to get 6,242 kB/6,289 kB of archives.
After this operation, 27.3 MB of additional disk space will be used.
Get:1 file:/tmp/autopkgtest.ei92jh/binaries  kpartx 0.7.4-2ubuntu1 [46.7 kB]
Get:2 http://archive.ubuntu.com/ubuntu bionic/main amd64 libaio1 amd64 0.3.110-5 [6,448 B]
Get:3 http://archive.ubuntu.com/ubuntu bionic/main amd64 libiscsi7 amd64 1.17.0-1.1 [55.4 kB]
Get:4 http://archive.ubuntu.com/ubuntu bionic/main amd64 libboost-iostreams1.65.1 amd64 1.65.1+dfsg-0ubuntu4 [29.1 kB]
Get:5 http://archive.ubuntu.com/ubuntu bionic/main amd64 libboost-system1.65.1 amd64 1.65.1+dfsg-0ubuntu4 [10.5 kB]
Get:6 http://archive.ubuntu.com/ubuntu bionic/main amd64 libboost-random1.65.1 amd64 1.65.1+dfsg-0ubuntu4 [12.8 kB]
Get:7 http://archive.ubuntu.com/ubuntu bionic/main amd64 libboost-regex1.65.1 amd64 1.65.1+dfsg-0ubuntu4 [255 kB]
Get:8 http://archive.ubuntu.com/ubuntu bionic/main amd64 libboost-thread1.65.1 amd64 1.65.1+dfsg-0ubuntu4 [43.2 kB]
Get:9 http://archive.ubuntu.com/ubuntu bionic/main amd64 libnl-3-200 amd64 3.2.29-0ubuntu3 [52.8 kB]
Get:10 http://archive.ubuntu.com/ubuntu bionic/main amd64 libnl-route-3-200 amd64 3.2.29-0ubuntu3 [146 kB]
Get:11 http://archive.ubuntu.com/ubuntu bionic/main amd64 libibverbs1 amd64 1.2.1-2ubuntu1 [30.8 kB]
Get:12 http://archive.ubuntu.com/ubuntu bionic/main amd64 libnspr4 amd64 2:4.16-1ubuntu2 [112 kB]
Get:13 http://archive.ubuntu.com/ubuntu bionic/main amd64 libnss3 amd64 2:3.32-1ubuntu3 [1,141 kB]
Get:14 http://archive.ubuntu.com/ubuntu bionic/main amd64 librados2 amd64 12.2.2-0ubuntu1 [2,550 kB]
Get:15 http://archive.ubuntu.com/ubuntu bionic/main amd64 librbd1 amd64 12.2.2-0ubuntu1 [917 kB]
Get:16 http://archive.ubuntu.com/ubuntu bionic/main amd64 qemu-block-extra amd64 1:2.10+dfsg-0ubuntu5 [40.1 kB]
Get:17 http://archive.ubuntu.com/ubuntu bionic/main amd64 qemu-utils amd64 1:2.10+dfsg-0ubuntu5 [841 kB]
Fetched 6,242 kB in 0s (48.6 MB/s)
Selecting previously unselected package kpartx.
(Reading database ... \r(Reading database ... 5%\r(Reading database ... 10%\r(Reading database ... 15%\r(Reading database ... 20%\r(Reading database ... 25%\r(Reading database ... 30%\r(Reading database ... 35%\r(Reading database ... 40%\r(Reading database ... 45%\r(Reading database ... 50%\r(Reading database ... 55%\r(Reading database ... 60%\r(Reading database ... 65%\r(Reading database ... 70%\r(Reading database ... 75%\r(Reading database ... 80%\r(Reading database ... 85%\r(Reading database ... 90%\r(Reading database ... 95%\r(Reading database ... 100%\r(Reading database ... 58021 files and directories currently installed.)
Preparing to unpack .../00-kpartx.deb ...
Unpacking kpartx (0.7.4-2ubuntu1) ...
Selecting previously unselected package libaio1:amd64.
Preparing to unpack .../01-libaio1_0.3.110-5_amd64.deb ...
Unpacking libaio1:amd64 (0.3.110-5) ...
Selecting previously unselected package libiscsi7:amd64.
Preparing to unpack .../02-libiscsi7_1.17.0-1.1_amd64.deb ...
Unpacking libiscsi7:amd64 (1.17.0-1.1) ...
Selecting previously unselected package libboost-iostreams1.65.1:amd64.
Preparing to unpack .../03-libboost-iostreams1.65.1_1.65.1+dfsg-0ubuntu4_amd64.deb ...
Unpacking libboost-iostreams1.65.1:amd64 (1.65.1+dfsg-0ubuntu4) ...
Selecting previously unselected package libboost-system1.65.1:amd64.
Preparing to unpack .../04-libboost-system1.65.1_1.65.1+dfsg-0ubuntu4_amd64.deb ...
Unpacking libboost-system1.65.1:amd64 (1.65.1+dfsg-0ubuntu4) ...
Selecting previously unselected package libboost-random1.65.1:amd64.
Preparing to unpack .../05-libboost-random1.65.1_1.65.1+dfsg-0ubuntu4_amd64.deb ...
Unpacking libboost-random1.65.1:amd64 (1.65.1+dfsg-0ubuntu4) ...
Selecting previously unselected package libboost-regex1.65.1:amd64.
Preparing to unpack .../06-libboost-regex1.65.1_1.65.1+dfsg-0ubuntu4_amd64.deb ...
Unpacking libboost-regex1.65.1:amd64 (1.65.1+dfsg-0ubuntu4) ...
Selecting previously unselected package libboost-thread1.65.1:amd64.
Preparing to unpack .../07-libboost-thread1.65.1_1.65.1+dfsg-0ubuntu4_amd64.deb ...
Unpacking libboost-thread1.65.1:amd64 (1.65.1+dfsg-0ubuntu4) ...
Selecting previously unselected package libnl-3-200:amd64.
Preparing to unpack .../08-libnl-3-200_3.2.29-0ubuntu3_amd64.deb ...
Unpacking libnl-3-200:amd64 (3.2.29-0ubuntu3) ...
Selecting previously unselected package libnl-route-3-200:amd64.
Preparing to unpack .../09-libnl-route-3-200_3.2.29-0ubuntu3_amd64.deb ...
Unpacking libnl-route-3-200:amd64 (3.2.29-0ubuntu3) ...
Selecting previously unselected package libibverbs1.
Preparing to unpack .../10-libibverbs1_1.2.1-2ubuntu1_amd64.deb ...
Unpacking libibverbs1 (1.2.1-2ubuntu1) ...
Selecting previously unselected package libnspr4:amd64.
Preparing to unpack .../11-libnspr4_2%3a4.16-1ubuntu2_amd64.deb ...
Unpacking libnspr4:amd64 (2:4.16-1ubuntu2) ...
Selecting previously unselected package libnss3:amd64.
Preparing to unpack .../12-libnss3_2%3a3.32-1ubuntu3_amd64.deb ...
Unpacking libnss3:amd64 (2:3.32-1ubuntu3) ...
Selecting previously unselected package librados2.
Preparing to unpack .../13-librados2_12.2.2-0ubuntu1_amd64.deb ...
Unpacking librados2 (12.2.2-0ubuntu1) ...
Selecting previously unselected package librbd1.
Preparing to unpack .../14-librbd1_12.2.2-0ubuntu1_amd64.deb ...
Unpacking librbd1 (12.2.2-0ubuntu1) ...
Selecting previously unselected package qemu-block-extra:amd64.
Preparing to unpack .../15-qemu-block-extra_1%3a2.10+dfsg-0ubuntu5_amd64.deb ...
Unpacking qemu-block-extra:amd64 (1:2.10+dfsg-0ubuntu5) ...
Selecting previously unselected package qemu-utils.
Preparing to unpack .../16-qemu-utils_1%3a2.10+dfsg-0ubuntu5_amd64.deb ...
Unpacking qemu-utils (1:2.10+dfsg-0ubuntu5) ...
Setting up libboost-iostreams1.65.1:amd64 (1.65.1+dfsg-0ubuntu4) ...
Setting up libiscsi7:amd64 (1.17.0-1.1) ...
Setting up libnspr4:amd64 (2:4.16-1ubuntu2) ...
Setting up libboost-system1.65.1:amd64 (1.65.1+dfsg-0ubuntu4) ...
Processing triggers for libc-bin (2.26-0ubuntu2) ...
Setting up libaio1:amd64 (0.3.110-5) ...
Setting up kpartx (0.7.4-2ubuntu1) ...
Setting up libboost-thread1.65.1:amd64 (1.65.1+dfsg-0ubuntu4) ...
Processing triggers for man-db (2.7.6.1-4) ...
Setting up libnl-3-200:amd64 (3.2.29-0ubuntu3) ...
Setting up libboost-random1.65.1:amd64 (1.65.1+dfsg-0ubuntu4) ...
Setting up libboost-regex1.65.1:amd64 (1.65.1+dfsg-0ubuntu4) ...
Setting up libnss3:amd64 (2:3.32-1ubuntu3) ...
Setting up libnl-route-3-200:amd64 (3.2.29-0ubuntu3) ...
Setting up libibverbs1 (1.2.1-2ubuntu1) ...
Setting up librados2 (12.2.2-0ubuntu1) ...
Setting up librbd1 (12.2.2-0ubuntu1) ...
Setting up qemu-block-extra:amd64 (1:2.10+dfsg-0ubuntu5) ...
Setting up qemu-utils (1:2.10+dfsg-0ubuntu5) ...
Setting up autopkgtest-satdep (0) ...
Processing triggers for libc-bin (2.26-0ubuntu2) ...
(Reading database ... 58148 files and directories currently installed.)
Removing autopkgtest-satdep (0) ...
autopkgtest [08:50:37]: test kpartx-file-loopback: [-----------------------
Formatting 'foo.img', fmt=raw size=20971520
Creating new GPT entries.
Warning: The kernel is still using the old partition table.
The new table will be used at the next reboot or after you
run partprobe(8) or kpartx(8)
The operation has completed successfully.
add map loop0p1 (253:0): 0 38879 linear 7:0 2048
standard_filename: FAIL
standard_filename_cleanup: ERROR
autopkgtest [08:50:39]: test kpartx-file-loopback: -----------------------]
autopkgtest [08:50:40]: test kpartx-file-loopback:  - - - - - - - - - - results - - - - - - - - - -
kpartx-file-loopback FAIL non-zero exit status 6
autopkgtest [08:50:40]:  - - - - - - - - - - running shell - - - - - - - - - -
autopkgtest [08:51:36]: test tgtbasedmpaths: preparing testbed
qemu-system-x86_64: terminating on signal 15 from pid 25453 (/usr/bin/python3)
autopkgtest [08:51:57]: @@@@@@@@@@@@@@@@@@@@ test bed setup

WARNING: apt does not have a stable CLI interface. Use with caution in scripts.

Reading package lists...
Building dependency tree...
Reading state information...
The following package was automatically installed and is no longer required:
  grub-pc-bin
Use 'apt autoremove' to remove it.
The following additional packages will be installed:
  gdbserver libbabeltrace1 libc6-dbg libcc1-0 libdw1 libelf1 libnss-systemd
  libpam-systemd libsystemd0 python3-apport systemd
Suggested packages:
  gdb-doc python3-launchpadlib systemd-container
Recommended packages:
  apport
The following packages will be REMOVED:
  apport ubuntu-server
The following NEW packages will be installed:
  gdb gdbserver libbabeltrace1 libc6-dbg libcc1-0 libdw1 systemd-coredump
The following packages will be upgraded:
  libelf1 libnss-systemd libpam-systemd libsystemd0 python3-apport systemd
6 upgraded, 7 newly installed, 2 to remove and 21 not upgraded.
Need to get 11.7 MB of archives.
After this operation, 48.5 MB of additional disk space will be used.
Get:1 http://archive.ubuntu.com/ubuntu bionic/main amd64 libnss-systemd amd64 235-3ubuntu3 [97.2 kB]
Get:2 http://archive.ubuntu.com/ubuntu bionic/main amd64 libpam-systemd amd64 235-3ubuntu3 [100 kB]
Get:3 http://archive.ubuntu.com/ubuntu bionic/main amd64 systemd amd64 235-3ubuntu3 [2,834 kB]
Get:4 http://archive.ubuntu.com/ubuntu bionic/main amd64 libsystemd0 amd64 235-3ubuntu3 [197 kB]
Get:5 http://archive.ubuntu.com/ubuntu bionic/main amd64 libelf1 amd64 0.170-0.2 [44.4 kB]
Get:6 http://archive.ubuntu.com/ubuntu bionic/main amd64 libdw1 amd64 0.170-0.2 [203 kB]
Get:7 http://archive.ubuntu.com/ubuntu bionic/main amd64 libbabeltrace1 amd64 1.5.3-4 [152 kB]
Get:8 http://archive.ubuntu.com/ubuntu bionic/main amd64 gdb amd64 8.0.1-0ubuntu3 [2,735 kB]
Get:9 http://archive.ubuntu.com/ubuntu bionic/main amd64 gdbserver amd64 8.0.1-0ubuntu3 [185 kB]
Get:10 http://archive.ubuntu.com/ubuntu bionic/main amd64 libcc1-0 amd64 7.2.0-18ubuntu2 [38.7 kB]
Get:11 http://archive.ubuntu.com/ubuntu bionic/main amd64 python3-apport all 2.20.8-0ubuntu6 [80.6 kB]
Get:12 http://archive.ubuntu.com/ubuntu bionic/universe amd64 systemd-coredump amd64 235-3ubuntu3 [41.6 kB]
Get:13 http://archive.ubuntu.com/ubuntu bionic/main amd64 libc6-dbg amd64 2.26-0ubuntu2 [4,996 kB]
Fetched 11.7 MB in 0s (57.4 MB/s)
(Reading database ... \r(Reading database ... 5%\r(Reading database ... 10%\r(Reading database ... 15%\r(Reading database ... 20%\r(Reading database ... 25%\r(Reading database ... 30%\r(Reading database ... 35%\r(Reading database ... 40%\r(Reading database ... 45%\r(Reading database ... 50%\r(Reading database ... 55%\r(Reading database ... 60%\r(Reading database ... 65%\r(Reading database ... 70%\r(Reading database ... 75%\r(Reading database ... 80%\r(Reading database ... 85%\r(Reading database ... 90%\r(Reading database ... 95%\r(Reading database ... 100%\r(Reading database ... 57061 files and directories currently installed.)
Removing ubuntu-server (1.407) ...
Removing apport (2.20.8-0ubuntu5) ...
(Reading database ... \r(Reading database ... 5%\r(Reading database ... 10%\r(Reading database ... 15%\r(Reading database ... 20%\r(Reading database ... 25%\r(Reading database ... 30%\r(Reading database ... 35%\r(Reading database ... 40%\r(Reading database ... 45%\r(Reading database ... 50%\r(Reading database ... 55%\r(Reading database ... 60%\r(Reading database ... 65%\r(Reading database ... 70%\r(Reading database ... 75%\r(Reading database ... 80%\r(Reading database ... 85%\r(Reading database ... 90%\r(Reading database ... 95%\r(Reading database ... 100%\r(Reading database ... 56982 files and directories currently installed.)
Preparing to unpack .../libnss-systemd_235-3ubuntu3_amd64.deb ...
Unpacking libnss-systemd:amd64 (235-3ubuntu3) over (235-3ubuntu2) ...
Preparing to unpack .../libpam-systemd_235-3ubuntu3_amd64.deb ...
Unpacking libpam-systemd:amd64 (235-3ubuntu3) over (235-3ubuntu2) ...
Preparing to unpack .../systemd_235-3ubuntu3_amd64.deb ...
Unpacking systemd (235-3ubuntu3) over (235-3ubuntu2) ...
Preparing to unpack .../libsystemd0_235-3ubuntu3_amd64.deb ...
Unpacking libsystemd0:amd64 (235-3ubuntu3) over (235-3ubuntu2) ...
Setting up libsystemd0:amd64 (235-3ubuntu3) ...
(Reading database ... \r(Reading database ... 5%\r(Reading database ... 10%\r(Reading database ... 15%\r(Reading database ... 20%\r(Reading database ... 25%\r(Reading database ... 30%\r(Reading database ... 35%\r(Reading database ... 40%\r(Reading database ... 45%\r(Reading database ... 50%\r(Reading database ... 55%\r(Reading database ... 60%\r(Reading database ... 65%\r(Reading database ... 70%\r(Reading database ... 75%\r(Reading database ... 80%\r(Reading database ... 85%\r(Reading database ... 90%\r(Reading database ... 95%\r(Reading database ... 100%\r(Reading database ... 56982 files and directories currently installed.)
Preparing to unpack .../0-libelf1_0.170-0.2_amd64.deb ...
Unpacking libelf1:amd64 (0.170-0.2) over (0.170-0.1) ...
Selecting previously unselected package libdw1:amd64.
Preparing to unpack .../1-libdw1_0.170-0.2_amd64.deb ...
Unpacking libdw1:amd64 (0.170-0.2) ...
Selecting previously unselected package libbabeltrace1:amd64.
Preparing to unpack .../2-libbabeltrace1_1.5.3-4_amd64.deb ...
Unpacking libbabeltrace1:amd64 (1.5.3-4) ...
Selecting previously unselected package gdb.
Preparing to unpack .../3-gdb_8.0.1-0ubuntu3_amd64.deb ...
Unpacking gdb (8.0.1-0ubuntu3) ...
Selecting previously unselected package gdbserver.
Preparing to unpack .../4-gdbserver_8.0.1-0ubuntu3_amd64.deb ...
Unpacking gdbserver (8.0.1-0ubuntu3) ...
Selecting previously unselected package libcc1-0:amd64.
Preparing to unpack .../5-libcc1-0_7.2.0-18ubuntu2_amd64.deb ...
Unpacking libcc1-0:amd64 (7.2.0-18ubuntu2) ...
Preparing to unpack .../6-python3-apport_2.20.8-0ubuntu6_all.deb ...
Unpacking python3-apport (2.20.8-0ubuntu6) over (2.20.8-0ubuntu5) ...
Selecting previously unselected package systemd-coredump.
Preparing to unpack .../7-systemd-coredump_235-3ubuntu3_amd64.deb ...
Unpacking systemd-coredump (235-3ubuntu3) ...
Selecting previously unselected package libc6-dbg:amd64.
Preparing to unpack .../8-libc6-dbg_2.26-0ubuntu2_amd64.deb ...
Unpacking libc6-dbg:amd64 (2.26-0ubuntu2) ...
Setting up libcc1-0:amd64 (7.2.0-18ubuntu2) ...
Setting up libc6-dbg:amd64 (2.26-0ubuntu2) ...
Processing triggers for ureadahead (0.100.0-20) ...
Setting up libelf1:amd64 (0.170-0.2) ...
Setting up python3-apport (2.20.8-0ubuntu6) ...
Processing triggers for libc-bin (2.26-0ubuntu2) ...
Setting up systemd (235-3ubuntu3) ...
Created symlink /etc/systemd/system/dbus-org.freedesktop.network1.service → /lib/systemd/system/systemd-networkd.service.
Processing triggers for man-db (2.7.6.1-4) ...
Setting up gdbserver (8.0.1-0ubuntu3) ...
Processing triggers for dbus (1.12.2-1ubuntu1) ...
Setting up libnss-systemd:amd64 (235-3ubuntu3) ...
Setting up libpam-systemd:amd64 (235-3ubuntu3) ...
Setting up libdw1:amd64 (0.170-0.2) ...
Setting up libbabeltrace1:amd64 (1.5.3-4) ...
Setting up systemd-coredump (235-3ubuntu3) ...
Setting up gdb (8.0.1-0ubuntu3) ...
Processing triggers for libc-bin (2.26-0ubuntu2) ...
autopkgtest [08:52:06]: rebooting testbed after setup commands that affected boot
autopkgtest [08:52:26]: testbed dpkg architecture: amd64
Get:1 file:/tmp/autopkgtest.ei92jh/binaries  InRelease
Ign:1 file:/tmp/autopkgtest.ei92jh/binaries  InRelease
Get:2 file:/tmp/autopkgtest.ei92jh/binaries  Release [816 B]
Get:2 file:/tmp/autopkgtest.ei92jh/binaries  Release [816 B]
Get:3 file:/tmp/autopkgtest.ei92jh/binaries  Release.gpg
Ign:3 file:/tmp/autopkgtest.ei92jh/binaries  Release.gpg
Get:4 file:/tmp/autopkgtest.ei92jh/binaries  Packages [4,627 B]
Reading package lists...
Reading package lists...
Building dependency tree...
Reading state information...
Correcting dependencies...Starting pkgProblemResolver with broken count: 0
Starting 2 pkgProblemResolver with broken count: 0
Done
 Done
Starting pkgProblemResolver with broken count: 0
Starting 2 pkgProblemResolver with broken count: 0
Done
The following package was automatically installed and is no longer required:
  grub-pc-bin
Use 'apt autoremove' to remove it.
The following additional packages will be installed:
  fio kpartx libaio1 libboost-iostreams1.65.1 libboost-random1.65.1
  libboost-regex1.65.1 libboost-system1.65.1 libboost-thread1.65.1
  libconfig-general-perl libibverbs1 libnl-3-200 libnl-route-3-200 libnspr4
  libnss3 libpython-stdlib libpython2.7-minimal libpython2.7-stdlib librados2
  librbd1 librdmacm1 libsgutils2-2 liburcu6 lsscsi multipath-tools python
  python-minimal python2.7 python2.7-minimal sg3-utils sg3-utils-udev tgt
Suggested packages:
  gnuplot gfio python-scipy multipath-tools-boot python-doc python-tk
  python2.7-doc binutils binfmt-support tgt-rbd
The following NEW packages will be installed:
  fio kpartx libaio1 libboost-iostreams1.65.1 libboost-random1.65.1
  libboost-regex1.65.1 libboost-system1.65.1 libboost-thread1.65.1
  libconfig-general-perl libibverbs1 libnl-3-200 libnl-route-3-200 libnspr4
  libnss3 libpython-stdlib libpython2.7-minimal libpython2.7-stdlib librados2
  librbd1 librdmacm1 libsgutils2-2 liburcu6 lsscsi multipath-tools python
  python-minimal python2.7 python2.7-minimal sg3-utils sg3-utils-udev tgt
0 upgraded, 31 newly installed, 0 to remove and 21 not upgraded.
1 not fully installed or removed.
Need to get 10.9 MB/11.3 MB of archives.
After this operation, 44.8 MB of additional disk space will be used.
Get:1 file:/tmp/autopkgtest.ei92jh/binaries  kpartx 0.7.4-2ubuntu1 [46.7 kB]
Get:2 http://archive.ubuntu.com/ubuntu bionic/main amd64 libaio1 amd64 0.3.110-5 [6,448 B]
Get:3 http://archive.ubuntu.com/ubuntu bionic/main amd64 libboost-iostreams1.65.1 amd64 1.65.1+dfsg-0ubuntu4 [29.1 kB]
Get:4 http://archive.ubuntu.com/ubuntu bionic/main amd64 libboost-system1.65.1 amd64 1.65.1+dfsg-0ubuntu4 [10.5 kB]
Get:5 http://archive.ubuntu.com/ubuntu bionic/main amd64 libboost-random1.65.1 amd64 1.65.1+dfsg-0ubuntu4 [12.8 kB]
Get:6 http://archive.ubuntu.com/ubuntu bionic/main amd64 libboost-regex1.65.1 amd64 1.65.1+dfsg-0ubuntu4 [255 kB]
Get:7 file:/tmp/autopkgtest.ei92jh/binaries  multipath-tools 0.7.4-2ubuntu1 [275 kB]
Get:8 http://archive.ubuntu.com/ubuntu bionic/main amd64 libboost-thread1.65.1 amd64 1.65.1+dfsg-0ubuntu4 [43.2 kB]
Get:9 http://archive.ubuntu.com/ubuntu bionic/main amd64 libnl-3-200 amd64 3.2.29-0ubuntu3 [52.8 kB]
Get:10 http://archive.ubuntu.com/ubuntu bionic/main amd64 libnl-route-3-200 amd64 3.2.29-0ubuntu3 [146 kB]
Get:11 http://archive.ubuntu.com/ubuntu bionic/main amd64 libibverbs1 amd64 1.2.1-2ubuntu1 [30.8 kB]
Get:12 http://archive.ubuntu.com/ubuntu bionic/main amd64 libnspr4 amd64 2:4.16-1ubuntu2 [112 kB]
Get:13 http://archive.ubuntu.com/ubuntu bionic/main amd64 libnss3 amd64 2:3.32-1ubuntu3 [1,141 kB]
Get:14 http://archive.ubuntu.com/ubuntu bionic/main amd64 librados2 amd64 12.2.2-0ubuntu1 [2,550 kB]
Get:15 http://archive.ubuntu.com/ubuntu bionic/main amd64 liburcu6 amd64 0.10.0-2 [51.7 kB]
Get:16 http://archive.ubuntu.com/ubuntu bionic/main amd64 libsgutils2-2 amd64 1.42-2ubuntu1 [59.3 kB]
Get:17 http://archive.ubuntu.com/ubuntu bionic/main amd64 sg3-utils amd64 1.42-2ubuntu1 [743 kB]
Get:18 http://archive.ubuntu.com/ubuntu bionic/main amd64 sg3-utils-udev all 1.42-2ubuntu1 [4,864 B]
Get:19 http://archive.ubuntu.com/ubuntu bionic/main amd64 librdmacm1 amd64 1.1.0-2 [48.9 kB]
Get:20 http://archive.ubuntu.com/ubuntu bionic/main amd64 libconfig-general-perl all 2.63-1 [53.9 kB]
Get:21 http://archive.ubuntu.com/ubuntu bionic/main amd64 tgt amd64 1:1.0.72-1ubuntu1 [214 kB]
Get:22 http://archive.ubuntu.com/ubuntu bionic/main amd64 librbd1 amd64 12.2.2-0ubuntu1 [917 kB]
Get:23 http://archive.ubuntu.com/ubuntu bionic/main amd64 libpython2.7-minimal amd64 2.7.14-4 [337 kB]
Get:24 http://archive.ubuntu.com/ubuntu bionic/main amd64 python2.7-minimal amd64 2.7.14-4 [1,293 kB]
Get:25 http://archive.ubuntu.com/ubuntu bionic/main amd64 python-minimal amd64 2.7.14-2ubuntu1 [28.1 kB]
Get:26 http://archive.ubuntu.com/ubuntu bionic/main amd64 libpython2.7-stdlib amd64 2.7.14-4 [1,910 kB]
Get:27 http://archive.ubuntu.com/ubuntu bionic/main amd64 python2.7 amd64 2.7.14-4 [233 kB]
Get:28 http://archive.ubuntu.com/ubuntu bionic/main amd64 libpython-stdlib amd64 2.7.14-2ubuntu1 [7,576 B]
Get:29 http://archive.ubuntu.com/ubuntu bionic/main amd64 python amd64 2.7.14-2ubuntu1 [140 kB]
Get:30 http://archive.ubuntu.com/ubuntu bionic/universe amd64 fio amd64 3.1-1 [467 kB]
Get:31 http://archive.ubuntu.com/ubuntu bionic/main amd64 lsscsi amd64 0.28-0.1 [35.5 kB]
Fetched 10.9 MB in 0s (50.4 MB/s)
Selecting previously unselected package libaio1:amd64.
(Reading database ... \r(Reading database ... 5%\r(Reading database ... 10%\r(Reading database ... 15%\r(Reading database ... 20%\r(Reading database ... 25%\r(Reading database ... 30%\r(Reading database ... 35%\r(Reading database ... 40%\r(Reading database ... 45%\r(Reading database ... 50%\r(Reading database ... 55%\r(Reading database ... 60%\r(Reading database ... 65%\r(Reading database ... 70%\r(Reading database ... 75%\r(Reading database ... 80%\r(Reading database ... 85%\r(Reading database ... 90%\r(Reading database ... 95%\r(Reading database ... 100%\r(Reading database ... 57437 files and directories currently installed.)
Preparing to unpack .../00-libaio1_0.3.110-5_amd64.deb ...
Unpacking libaio1:amd64 (0.3.110-5) ...
Selecting previously unselected package libboost-iostreams1.65.1:amd64.
Preparing to unpack .../01-libboost-iostreams1.65.1_1.65.1+dfsg-0ubuntu4_amd64.deb ...
Unpacking libboost-iostreams1.65.1:amd64 (1.65.1+dfsg-0ubuntu4) ...
Selecting previously unselected package libboost-system1.65.1:amd64.
Preparing to unpack .../02-libboost-system1.65.1_1.65.1+dfsg-0ubuntu4_amd64.deb ...
Unpacking libboost-system1.65.1:amd64 (1.65.1+dfsg-0ubuntu4) ...
Selecting previously unselected package libboost-random1.65.1:amd64.
Preparing to unpack .../03-libboost-random1.65.1_1.65.1+dfsg-0ubuntu4_amd64.deb ...
Unpacking libboost-random1.65.1:amd64 (1.65.1+dfsg-0ubuntu4) ...
Selecting previously unselected package libboost-regex1.65.1:amd64.
Preparing to unpack .../04-libboost-regex1.65.1_1.65.1+dfsg-0ubuntu4_amd64.deb ...
Unpacking libboost-regex1.65.1:amd64 (1.65.1+dfsg-0ubuntu4) ...
Selecting previously unselected package libboost-thread1.65.1:amd64.
Preparing to unpack .../05-libboost-thread1.65.1_1.65.1+dfsg-0ubuntu4_amd64.deb ...
Unpacking libboost-thread1.65.1:amd64 (1.65.1+dfsg-0ubuntu4) ...
Selecting previously unselected package libnl-3-200:amd64.
Preparing to unpack .../06-libnl-3-200_3.2.29-0ubuntu3_amd64.deb ...
Unpacking libnl-3-200:amd64 (3.2.29-0ubuntu3) ...
Selecting previously unselected package libnl-route-3-200:amd64.
Preparing to unpack .../07-libnl-route-3-200_3.2.29-0ubuntu3_amd64.deb ...
Unpacking libnl-route-3-200:amd64 (3.2.29-0ubuntu3) ...
Selecting previously unselected package libibverbs1.
Preparing to unpack .../08-libibverbs1_1.2.1-2ubuntu1_amd64.deb ...
Unpacking libibverbs1 (1.2.1-2ubuntu1) ...
Selecting previously unselected package libnspr4:amd64.
Preparing to unpack .../09-libnspr4_2%3a4.16-1ubuntu2_amd64.deb ...
Unpacking libnspr4:amd64 (2:4.16-1ubuntu2) ...
Selecting previously unselected package libnss3:amd64.
Preparing to unpack .../10-libnss3_2%3a3.32-1ubuntu3_amd64.deb ...
Unpacking libnss3:amd64 (2:3.32-1ubuntu3) ...
Selecting previously unselected package librados2.
Preparing to unpack .../11-librados2_12.2.2-0ubuntu1_amd64.deb ...
Unpacking librados2 (12.2.2-0ubuntu1) ...
Selecting previously unselected package liburcu6:amd64.
Preparing to unpack .../12-liburcu6_0.10.0-2_amd64.deb ...
Unpacking liburcu6:amd64 (0.10.0-2) ...
Selecting previously unselected package kpartx.
Preparing to unpack .../13-kpartx.deb ...
Unpacking kpartx (0.7.4-2ubuntu1) ...
Selecting previously unselected package libsgutils2-2.
Preparing to unpack .../14-libsgutils2-2_1.42-2ubuntu1_amd64.deb ...
Unpacking libsgutils2-2 (1.42-2ubuntu1) ...
Selecting previously unselected package sg3-utils.
Preparing to unpack .../15-sg3-utils_1.42-2ubuntu1_amd64.deb ...
Unpacking sg3-utils (1.42-2ubuntu1) ...
Selecting previously unselected package sg3-utils-udev.
Preparing to unpack .../16-sg3-utils-udev_1.42-2ubuntu1_all.deb ...
Unpacking sg3-utils-udev (1.42-2ubuntu1) ...
Selecting previously unselected package multipath-tools.
Preparing to unpack .../17-multipath-tools.deb ...
insmod /lib/modules/4.13.0-17-generic/kernel/drivers/md/dm-multipath.ko 
Unpacking multipath-tools (0.7.4-2ubuntu1) ...
Selecting previously unselected package librdmacm1.
Preparing to unpack .../18-librdmacm1_1.1.0-2_amd64.deb ...
Unpacking librdmacm1 (1.1.0-2) ...
Selecting previously unselected package libconfig-general-perl.
Preparing to unpack .../19-libconfig-general-perl_2.63-1_all.deb ...
Unpacking libconfig-general-perl (2.63-1) ...
Selecting previously unselected package tgt.
Preparing to unpack .../20-tgt_1%3a1.0.72-1ubuntu1_amd64.deb ...
Unpacking tgt (1:1.0.72-1ubuntu1) ...
Selecting previously unselected package librbd1.
Preparing to unpack .../21-librbd1_12.2.2-0ubuntu1_amd64.deb ...
Unpacking librbd1 (12.2.2-0ubuntu1) ...
Selecting previously unselected package libpython2.7-minimal:amd64.
Preparing to unpack .../22-libpython2.7-minimal_2.7.14-4_amd64.deb ...
Unpacking libpython2.7-minimal:amd64 (2.7.14-4) ...
Selecting previously unselected package python2.7-minimal.
Preparing to unpack .../23-python2.7-minimal_2.7.14-4_amd64.deb ...
Unpacking python2.7-minimal (2.7.14-4) ...
Selecting previously unselected package python-minimal.
Preparing to unpack .../24-python-minimal_2.7.14-2ubuntu1_amd64.deb ...
Unpacking python-minimal (2.7.14-2ubuntu1) ...
Selecting previously unselected package libpython2.7-stdlib:amd64.
Preparing to unpack .../25-libpython2.7-stdlib_2.7.14-4_amd64.deb ...
Unpacking libpython2.7-stdlib:amd64 (2.7.14-4) ...
Selecting previously unselected package python2.7.
Preparing to unpack .../26-python2.7_2.7.14-4_amd64.deb ...
Unpacking python2.7 (2.7.14-4) ...
Selecting previously unselected package libpython-stdlib:amd64.
Preparing to unpack .../27-libpython-stdlib_2.7.14-2ubuntu1_amd64.deb ...
Unpacking libpython-stdlib:amd64 (2.7.14-2ubuntu1) ...
Setting up libpython2.7-minimal:amd64 (2.7.14-4) ...
Setting up python2.7-minimal (2.7.14-4) ...
Setting up python-minimal (2.7.14-2ubuntu1) ...
Selecting previously unselected package python.
(Reading database ... \r(Reading database ... 5%\r(Reading database ... 10%\r(Reading database ... 15%\r(Reading database ... 20%\r(Reading database ... 25%\r(Reading database ... 30%\r(Reading database ... 35%\r(Reading database ... 40%\r(Reading database ... 45%\r(Reading database ... 50%\r(Reading database ... 55%\r(Reading database ... 60%\r(Reading database ... 65%\r(Reading database ... 70%\r(Reading database ... 75%\r(Reading database ... 80%\r(Reading database ... 85%\r(Reading database ... 90%\r(Reading database ... 95%\r(Reading database ... 100%\r(Reading database ... 58668 files and directories currently installed.)
Preparing to unpack .../python_2.7.14-2ubuntu1_amd64.deb ...
Unpacking python (2.7.14-2ubuntu1) ...
Selecting previously unselected package fio.
Preparing to unpack .../archives/fio_3.1-1_amd64.deb ...
Unpacking fio (3.1-1) ...
Selecting previously unselected package lsscsi.
Preparing to unpack .../lsscsi_0.28-0.1_amd64.deb ...
Unpacking lsscsi (0.28-0.1) ...
Setting up libboost-iostreams1.65.1:amd64 (1.65.1+dfsg-0ubuntu4) ...
Processing triggers for mime-support (3.60ubuntu1) ...
Processing triggers for ureadahead (0.100.0-20) ...
Setting up lsscsi (0.28-0.1) ...
Setting up liburcu6:amd64 (0.10.0-2) ...
Setting up libnspr4:amd64 (2:4.16-1ubuntu2) ...
Setting up libboost-system1.65.1:amd64 (1.65.1+dfsg-0ubuntu4) ...
Setting up libsgutils2-2 (1.42-2ubuntu1) ...
Processing triggers for libc-bin (2.26-0ubuntu2) ...
Setting up libaio1:amd64 (0.3.110-5) ...
Setting up kpartx (0.7.4-2ubuntu1) ...
Setting up libboost-thread1.65.1:amd64 (1.65.1+dfsg-0ubuntu4) ...
Processing triggers for systemd (235-3ubuntu3) ...
Processing triggers for man-db (2.7.6.1-4) ...
Setting up sg3-utils (1.42-2ubuntu1) ...
Setting up libnl-3-200:amd64 (3.2.29-0ubuntu3) ...
Setting up sg3-utils-udev (1.42-2ubuntu1) ...
update-initramfs: deferring update (trigger activated)
Setting up libboost-random1.65.1:amd64 (1.65.1+dfsg-0ubuntu4) ...
Setting up libpython2.7-stdlib:amd64 (2.7.14-4) ...
Setting up libconfig-general-perl (2.63-1) ...
Setting up libboost-regex1.65.1:amd64 (1.65.1+dfsg-0ubuntu4) ...
Setting up python2.7 (2.7.14-4) ...
Setting up libnss3:amd64 (2:3.32-1ubuntu3) ...
Setting up libnl-route-3-200:amd64 (3.2.29-0ubuntu3) ...
Setting up libpython-stdlib:amd64 (2.7.14-2ubuntu1) ...
Setting up python (2.7.14-2ubuntu1) ...
Setting up libibverbs1 (1.2.1-2ubuntu1) ...
Setting up librdmacm1 (1.1.0-2) ...
Setting up librados2 (12.2.2-0ubuntu1) ...
Setting up multipath-tools (0.7.4-2ubuntu1) ...
Created symlink /etc/systemd/system/multipath-tools.service → /lib/systemd/system/multipathd.service.
Created symlink /etc/systemd/system/sysinit.target.wants/multipathd.service → /lib/systemd/system/multipathd.service.
multipathd.socket is a disabled or a static unit, not starting it.
Setting up tgt (1:1.0.72-1ubuntu1) ...
Created symlink /etc/systemd/system/multi-user.target.wants/tgt.service → /lib/systemd/system/tgt.service.
Setting up librbd1 (12.2.2-0ubuntu1) ...
Setting up fio (3.1-1) ...
Setting up autopkgtest-satdep (0) ...
Processing triggers for libc-bin (2.26-0ubuntu2) ...
Processing triggers for initramfs-tools (0.125ubuntu13) ...
update-initramfs: Generating /boot/initrd.img-4.13.0-17-generic
WARNING: Setting CRYPTSETUP in /etc/initramfs-tools/initramfs.conf is deprecated and will stop working in the future. Use /etc/cryptsetup-initramfs/conf-hook instead.
Processing triggers for systemd (235-3ubuntu3) ...
Processing triggers for ureadahead (0.100.0-20) ...
(Reading database ... 58802 files and directories currently installed.)
Removing autopkgtest-satdep (0) ...
autopkgtest [08:52:56]: test tgtbasedmpaths: [-----------------------
+ targetname=iqn.2016-11.foo.com:target.iscsi
+ pwd
+ cwd=/tmp/autopkgtest.ei92jh/build.HoZ/src
+ testdir=/mnt/tgtmpathtest
+ localhost=127.0.0.1
+ portal=127.0.0.1:3260
+ maxpaths=4
+ backfn=backingfile
+ expectwwid=360000000000000000e00000000010001
+ testdisk=/dev/disk/by-id/scsi-360000000000000000e00000000010001
+ bglog=/tmp/autopkgtest.ei92jh/tgtbasedmpaths-artifacts/test-background.log
+ fioprep=/tmp/autopkgtest.ei92jh/tgtbasedmpaths-artifacts/path-change-prep.fio
+ fiovrfy=/tmp/autopkgtest.ei92jh/tgtbasedmpaths-artifacts/path-change-check.fio
+ service tgt restart
+ truncate --size 100M backingfile
+ tgtadm --lld iscsi --op new --mode target --tid 1 -T iqn.2016-11.foo.com:target.iscsi
+ tgtadm --lld iscsi --op bind --mode target --tid 1 -I ALL
+ tgtadm --lld iscsi --op new --mode logicalunit --tid 1 --lun 1 -b /tmp/autopkgtest.ei92jh/build.HoZ/src/backingfile
+ iscsiadm --mode discovery --type sendtargets --portal 127.0.0.1
127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi
login #1
+ echo login #1
+ iscsiadm --mode node --targetname iqn.2016-11.foo.com:target.iscsi --portal 127.0.0.1:3260 --login
+ seq 2 4
+ echo extra login #2
+ iscsiadm --mode session -r 1 --op new
Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple)
Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful.
extra login #2
+ echo extra login #3
+ iscsiadm --mode session -r 1 --op new
Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple)
Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful.
extra login #3
Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple)
Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful.
extra login #4
+ echo extra login #4
+ iscsiadm --mode session -r 1 --op new
Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple)
Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful.
+ udevadm settle
Status after initial setup
Target 1: iqn.2016-11.foo.com:target.iscsi
    System information:
        Driver: iscsi
        State: ready
    I_T nexus information:
        I_T nexus: 1
            Initiator: iqn.1993-08.org.debian:01:54a3714cca34 alias: autopkgtest
            Connection: 0
                IP Address: 127.0.0.1
        I_T nexus: 2
            Initiator: iqn.1993-08.org.debian:01:54a3714cca34 alias: autopkgtest
            Connection: 0
                IP Address: 127.0.0.1
        I_T nexus: 3
            Initiator: iqn.1993-08.org.debian:01:54a3714cca34 alias: autopkgtest
            Connection: 0
                IP Address: 127.0.0.1
        I_T nexus: 4
            Initiator: iqn.1993-08.org.debian:01:54a3714cca34 alias: autopkgtest
            Connection: 0
                IP Address: 127.0.0.1
    LUN information:
        LUN: 0
            Type: controller
            SCSI ID: IET     00010000
            SCSI SN: beaf10
            Size: 0 MB, Block size: 1
            Online: Yes
            Removable media: No
            Prevent removal: No
            Readonly: No
            SWP: No
            Thin-provisioning: No
            Backing store type: null
            Backing store path: None
            Backing store flags: 
        LUN: 1
            Type: disk
            SCSI ID: IET     00010001
            SCSI SN: beaf11
            Size: 105 MB, Block size: 512
            Online: Yes
            Removable media: No
            Prevent removal: No
            Readonly: No
            SWP: No
            Thin-provisioning: No
            Backing store type: rdwr
            Backing store path: /tmp/autopkgtest.ei92jh/build.HoZ/src/backingfile
            Backing store flags: 
    Account information:
    ACL information:
        ALL
Session: 4
    Connection: 0
        Initiator: iqn.1993-08.org.debian:01:54a3714cca34
        IP Address: 127.0.0.1
Session: 3
    Connection: 0
        Initiator: iqn.1993-08.org.debian:01:54a3714cca34
        IP Address: 127.0.0.1
Session: 2
    Connection: 0
        Initiator: iqn.1993-08.org.debian:01:54a3714cca34
        IP Address: 127.0.0.1
Session: 1
    Connection: 0
        Initiator: iqn.1993-08.org.debian:01:54a3714cca34
        IP Address: 127.0.0.1
Target: iqn.2016-11.foo.com:target.iscsi (non-flash)
	Current Portal: 127.0.0.1:3260,1
	Persistent Portal: 127.0.0.1:3260,1
		**********
		Interface:
		**********
		Iface Name: default
		Iface Transport: tcp
		Iface Initiatorname: iqn.1993-08.org.debian:01:54a3714cca34
		Iface IPaddress: 127.0.0.1
		Iface HWaddress: <empty>
		Iface Netdev: <empty>
		SID: 1
		iSCSI Connection State: LOGGED IN
		iSCSI Session State: LOGGED_IN
		Internal iscsid Session State: NO CHANGE

		**********
		Interface:
		**********
		Iface Name: default
		Iface Transport: tcp
		Iface Initiatorname: iqn.1993-08.org.debian:01:54a3714cca34
		Iface IPaddress: 127.0.0.1
		Iface HWaddress: <empty>
		Iface Netdev: <empty>
		SID: 4
		iSCSI Connection State: LOGGED IN
		iSCSI Session State: LOGGED_IN
		Internal iscsid Session State: NO CHANGE

		**********
		Interface:
		**********
		Iface Name: default
		Iface Transport: tcp
		Iface Initiatorname: iqn.1993-08.org.debian:01:54a3714cca34
		Iface IPaddress: 127.0.0.1
		Iface HWaddress: <empty>
		Iface Netdev: <empty>
		SID: 3
		iSCSI Connection State: LOGGED IN
		iSCSI Session State: LOGGED_IN
		Internal iscsid Session State: NO CHANGE

		**********
		Interface:
		**********
		Iface Name: default
		Iface Transport: tcp
		Iface Initiatorname: iqn.1993-08.org.debian:01:54a3714cca34
		Iface IPaddress: 127.0.0.1
		Iface HWaddress: <empty>
		Iface Netdev: <empty>
		SID: 2
		iSCSI Connection State: LOGGED IN
		iSCSI Session State: LOGGED_IN
		Internal iscsid Session State: NO CHANGE
[1:0:0:0]    cd/dvd  QEMU     QEMU DVD-ROM     2.5+  /dev/sr0   -
  state=running queue_depth=1 scsi_level=6 type=5 device_blocked=0 timeout=30
  dir: /sys/bus/scsi/devices/1:0:0:0  [/sys/devices/pci0000:00/0000:00:01.1/ata2/host1/target1:0:0/1:0:0:0]
[2:0:0:0]    storage IET      Controller       0001  -          -
  state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=0
  dir: /sys/bus/scsi/devices/2:0:0:0  [/sys/devices/platform/host2/session1/target2:0:0/2:0:0:0]
[2:0:0:1]    disk    IET      VIRTUAL-DISK     0001  /dev/sda   360000000000000000e00000000010001
  state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30
  dir: /sys/bus/scsi/devices/2:0:0:1  [/sys/devices/platform/host2/session1/target2:0:0/2:0:0:1]
[3:0:0:0]    storage IET      Controller       0001  -          -
  state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=0
  dir: /sys/bus/scsi/devices/3:0:0:0  [/sys/devices/platform/host3/session2/target3:0:0/3:0:0:0]
[3:0:0:1]    disk    IET      VIRTUAL-DISK     0001  /dev/sdb   -
  state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30
  dir: /sys/bus/scsi/devices/3:0:0:1  [/sys/devices/platform/host3/session2/target3:0:0/3:0:0:1]
[4:0:0:0]    storage IET      Controller       0001  -          -
  state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=0
  dir: /sys/bus/scsi/devices/4:0:0:0  [/sys/devices/platform/host4/session3/target4:0:0/4:0:0:0]
[4:0:0:1]    disk    IET      VIRTUAL-DISK     0001  /dev/sdc   -
  state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30
  dir: /sys/bus/scsi/devices/4:0:0:1  [/sys/devices/platform/host4/session3/target4:0:0/4:0:0:1]
[5:0:0:0]    storage IET      Controller       0001  -          -
  state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=0
  dir: /sys/bus/scsi/devices/5:0:0:0  [/sys/devices/platform/host5/session4/target5:0:0/5:0:0:0]
[5:0:0:1]    disk    IET      VIRTUAL-DISK     0001  /dev/sdd   SIET_VIRTUAL-DISK_beaf11
  state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30
  dir: /sys/bus/scsi/devices/5:0:0:1  [/sys/devices/platform/host5/session4/target5:0:0/5:0:0:1]
+ echo Status after initial setup
+ tgtadm --lld iscsi --mode target --op show
+ tgtadm --lld iscsi --op show --mode conn --tid 1
+ iscsiadm --mode session -P 1
+ lsscsi -liv
+ multipath -v3 -ll
Jan 12 08:52:57 | loading //lib/multipath/libchecktur.so checker
Jan 12 08:52:57 | loading //lib/multipath/libprioconst.so prioritizer
Jan 12 08:52:57 | sr0: blacklisted, udev property missing
Jan 12 08:52:57 | vda: blacklisted, udev property missing
Jan 12 08:52:57 | vdb: blacklisted, udev property missing
Jan 12 08:52:57 | fd0: blacklisted, udev property missing
Jan 12 08:52:57 | sda: udev property ID_WWN whitelisted
Jan 12 08:52:57 | sda: mask = 0x7
Jan 12 08:52:57 | sda: dev_t = 8:0
Jan 12 08:52:57 | sda: size = 204800
Jan 12 08:52:57 | sda: vendor = IET
Jan 12 08:52:57 | sda: product = VIRTUAL-DISK
Jan 12 08:52:57 | sda: rev = 0001
Jan 12 08:52:57 | sda: h:b:t:l = 2:0:0:1
Jan 12 08:52:57 | sda: tgt_node_name = iqn.2016-11.foo.com:target.iscsi
Jan 12 08:52:57 | sda: path state = running
Jan 12 08:52:57 | sda: 1024 cyl, 4 heads, 50 sectors/track, start at 0
Jan 12 08:52:57 | sda: serial =                               beaf11
Jan 12 08:52:57 | sda: get_state
Jan 12 08:52:57 | sda: detect_checker = yes (setting: multipath internal)
Jan 12 08:52:57 | failed to issue vpd inquiry for pgc9
Jan 12 08:52:57 | sda: path_checker = tur (setting: multipath internal)
Jan 12 08:52:57 | sda: checker timeout = 30 s (setting: multipath internal)
Jan 12 08:52:57 | sda: tur state = up
Jan 12 08:52:57 | sdb: udev property ID_WWN whitelisted
Jan 12 08:52:57 | sdb: mask = 0x7
Jan 12 08:52:57 | sdb: dev_t = 8:16
Jan 12 08:52:57 | sdb: size = 204800
Jan 12 08:52:57 | sdb: vendor = IET
Jan 12 08:52:57 | sdb: product = VIRTUAL-DISK
Jan 12 08:52:57 | sdb: rev = 0001
Jan 12 08:52:57 | sdb: h:b:t:l = 3:0:0:1
Jan 12 08:52:57 | sdb: tgt_node_name = iqn.2016-11.foo.com:target.iscsi
Jan 12 08:52:57 | sdb: path state = running
Jan 12 08:52:57 | sdb: 1024 cyl, 4 heads, 50 sectors/track, start at 0
Jan 12 08:52:57 | sdb: serial =                               beaf11
Jan 12 08:52:57 | sdb: get_state
Jan 12 08:52:57 | sdb: detect_checker = yes (setting: multipath internal)
Jan 12 08:52:57 | failed to issue vpd inquiry for pgc9
Jan 12 08:52:57 | sdb: path_checker = tur (setting: multipath internal)
Jan 12 08:52:57 | sdb: checker timeout = 30 s (setting: multipath internal)
Jan 12 08:52:57 | sdb: tur state = up
Jan 12 08:52:57 | sdc: udev property ID_WWN whitelisted
Jan 12 08:52:57 | sdc: mask = 0x7
Jan 12 08:52:57 | sdc: dev_t = 8:32
Jan 12 08:52:57 | sdc: size = 204800
Jan 12 08:52:57 | sdc: vendor = IET
Jan 12 08:52:57 | sdc: product = VIRTUAL-DISK
Jan 12 08:52:57 | sdc: rev = 0001
Jan 12 08:52:57 | sdc: h:b:t:l = 4:0:0:1
Jan 12 08:52:57 | sdc: tgt_node_name = iqn.2016-11.foo.com:target.iscsi
Jan 12 08:52:57 | sdc: path state = running
Jan 12 08:52:57 | sdc: 1024 cyl, 4 heads, 50 sectors/track, start at 0
Jan 12 08:52:57 | sdc: serial =                               beaf11
Jan 12 08:52:57 | sdc: get_state
Jan 12 08:52:57 | sdc: detect_checker = yes (setting: multipath internal)
Jan 12 08:52:57 | failed to issue vpd inquiry for pgc9
Jan 12 08:52:57 | sdc: path_checker = tur (setting: multipath internal)
Jan 12 08:52:57 | sdc: checker timeout = 30 s (setting: multipath internal)
Jan 12 08:52:57 | sdc: tur state = up
Jan 12 08:52:57 | sdd: udev property ID_WWN whitelisted
Jan 12 08:52:57 | sdd: mask = 0x7
Jan 12 08:52:57 | sdd: dev_t = 8:48
Jan 12 08:52:57 | sdd: size = 204800
Jan 12 08:52:57 | sdd: vendor = IET
Jan 12 08:52:57 | sdd: product = VIRTUAL-DISK
Jan 12 08:52:57 | sdd: rev = 0001
Jan 12 08:52:57 | sdd: h:b:t:l = 5:0:0:1
Jan 12 08:52:57 | sdd: tgt_node_name = iqn.2016-11.foo.com:target.iscsi
Jan 12 08:52:57 | sdd: path state = running
Jan 12 08:52:57 | sdd: 1024 cyl, 4 heads, 50 sectors/track, start at 0
Jan 12 08:52:57 | sdd: serial =                               beaf11
Jan 12 08:52:57 | sdd: get_state
Jan 12 08:52:57 | sdd: detect_checker = yes (setting: multipath internal)
Jan 12 08:52:57 | failed to issue vpd inquiry for pgc9
Jan 12 08:52:57 | sdd: path_checker = tur (setting: multipath internal)
Jan 12 08:52:57 | sdd: checker timeout = 30 s (setting: multipath internal)
Jan 12 08:52:57 | sdd: tur state = up
Jan 12 08:52:57 | loop0: blacklisted, udev property missing
Jan 12 08:52:57 | loop1: blacklisted, udev property missing
Jan 12 08:52:57 | loop2: blacklisted, udev property missing
Jan 12 08:52:57 | loop3: blacklisted, udev property missing
Jan 12 08:52:57 | loop4: blacklisted, udev property missing
Jan 12 08:52:57 | loop5: blacklisted, udev property missing
Jan 12 08:52:57 | loop6: blacklisted, udev property missing
Jan 12 08:52:57 | loop7: blacklisted, udev property missing
Jan 12 08:52:57 | dm-0: blacklisted, udev property missing
===== paths list =====
uuid hcil    dev dev_t pri dm_st chk_st vend/prod/rev    dev_st 
     2:0:0:1 sda 8:0   -1  undef undef  IET,VIRTUAL-DISK unknown
     3:0:0:1 sdb 8:16  -1  undef undef  IET,VIRTUAL-DISK unknown
     4:0:0:1 sdc 8:32  -1  undef undef  IET,VIRTUAL-DISK unknown
     5:0:0:1 sdd 8:48  -1  undef undef  IET,VIRTUAL-DISK unknown
Jan 12 08:52:57 | libdevmapper version 1.02.137 (2016-11-30)
Jan 12 08:52:57 | DM multipath kernel driver v1.12.0
Jan 12 08:52:57 | params = 0 0 1 1 service-time 0 1 2 8:0 1 1 
Jan 12 08:52:57 | status = 2 0 0 0 1 1 A 0 1 2 8:0 A 0 0 1 
Jan 12 08:52:57 | 360000000000000000e00000000010001: disassemble map [0 0 1 1 service-time 0 1 2 8:0 1 1 ]
Jan 12 08:52:57 | sda: udev property ID_WWN whitelisted
Jan 12 08:52:57 | sda: mask = 0x8
Jan 12 08:52:57 | sda: path state = running
Jan 12 08:52:57 | sda: detect_prio = yes (setting: multipath internal)
Jan 12 08:52:57 | sda: prio = const (setting: multipath internal)
Jan 12 08:52:57 | sda: prio args = "" (setting: multipath internal)
Jan 12 08:52:57 | sda: const prio = 1
Jan 12 08:52:57 | 360000000000000000e00000000010001: disassemble status [2 0 0 0 1 1 A 0 1 2 8:0 A 0 0 1 ]
360000000000000000e00000000010001 dm-0 IET,VIRTUAL-DISK
size=100M features='0' hwhandler='0' wp=rw
`-+- policy='service-time 0' prio=1 status=active
  `- 2:0:0:1 sda 8:0  active ready running
Jan 12 08:52:57 | tur checker refcount 4
Jan 12 08:52:57 | const prioritizer refcount 1
Jan 12 08:52:57 | tur checker refcount 3
Jan 12 08:52:57 | tur checker refcount 2
Jan 12 08:52:57 | tur checker refcount 1
Jan 12 08:52:57 | unloading const prioritizer
Jan 12 08:52:57 | unloading tur checker
360000000000000000e00000000010001: 0 204800 multipath 0 0 1 1 service-time 0 1 2 8:0 1 1 
Test WWN should now point to DM
../../dm-0
Creating filesystem with 102400 1k blocks and 25688 inodes
Filesystem UUID: fde6596d-e098-4bae-8dae-d7fb3094ea05
Superblock backups stored on blocks: 
	8193, 24577, 40961, 57345, 73729

Allocating group tables:  0/13\b\b\b\b\b     \b\b\b\b\bdone                            
Writing inode tables:  0/13\b\b\b\b\b     \b\b\b\b\bdone                            
+ dmsetup table
+ echo Test WWN should now point to DM
+ grep dm
+ readlink /dev/disk/by-id/scsi-360000000000000000e00000000010001
+ mkfs.ext4 -F /dev/disk/by-id/scsi-360000000000000000e00000000010001
mke2fs 1.43.7 (16-Oct-2017)
Creating journal (4096 blocks): done
Writing superblocks and filesystem accounting information:  0/13\b\b\b\b\b     \b\b\b\b\bdone

+ udevadm settle
+ sleep 3s
+ mkdir -p /mnt/tgtmpathtest
+ mount /dev/disk/by-id/scsi-360000000000000000e00000000010001 /mnt/tgtmpathtest
+ cat
+ cat
+ fio /tmp/autopkgtest.ei92jh/tgtbasedmpaths-artifacts/path-change-prep.fio
write-phase: (g=0): rw=write, bs=(R) 64.0KiB-64.0KiB, (W) 64.0KiB-64.0KiB, (T) 64.0KiB-64.0KiB, ioengine=sync, iodepth=1
fio-3.1
Starting 1 thread
write-phase: Laying out IO file (1 file / 17592186044415MiB)
fio: io_u error on file /mnt/tgtmpathtest/datafile.tmp: No space left on device: write offset=93585408, buflen=65536

write-phase: (groupid=0, jobs=1): err= 0: pid=6780: Fri Jan 12 08:53:01 2018
  write: IOPS=5049, BW=315MiB/s (331MB/s)(89.2MiB/283msec)
    clat (usec): min=143, max=4878, avg=194.58, stdev=232.11
     lat (usec): min=143, max=4878, avg=194.92, stdev=232.14
    clat percentiles (usec):
     |  1.00th=[  149],  5.00th=[  149], 10.00th=[  149], 20.00th=[  151],
     | 30.00th=[  151], 40.00th=[  153], 50.00th=[  153], 60.00th=[  159],
     | 70.00th=[  165], 80.00th=[  180], 90.00th=[  221], 95.00th=[  310],
     | 99.00th=[  799], 99.50th=[ 1045], 99.90th=[ 4047], 99.95th=[ 4883],
     | 99.99th=[ 4883]
  lat (usec)   : 250=91.46%, 500=6.23%, 750=1.12%, 1000=0.49%
  lat (msec)   : 2=0.28%, 4=0.21%, 10=0.14%
  cpu          : usr=3.90%, sys=9.22%, ctx=1436, majf=0, minf=1
  IO depths    : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued rwt: total=0,1429,0, short=0,0,0, dropped=0,0,0
     latency   : target=0, window=0, percentile=100.00%, depth=1

Run status group 0 (all jobs):
  WRITE: bw=315MiB/s (331MB/s), 315MiB/s-315MiB/s (331MB/s-331MB/s), io=89.2MiB (93.6MB), run=283-283msec

Disk stats (read/write):
    dm-0: ios=2/688, merge=0/0, ticks=0/136, in_queue=136, util=55.97%, aggrios=0/358, aggrmerge=0/0, aggrticks=0/59, aggrin_queue=59, aggrutil=58.85%
  sdd: ios=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00%
  sdb: ios=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00%
  sdc: ios=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00%
  sda: ios=3/1432, merge=0/0, ticks=0/236, in_queue=236, util=58.85%
+ echo Starting the path changes in background
+ date +Pre FIO %H:%M:%S.%N
+ fio /tmp/autopkgtest.ei92jh/tgtbasedmpaths-artifacts/path-change-check.fio
Starting the path changes in background
Pre FIO 08:53:01.239699087
verify-phase: (g=0): rw=read, bs=(R) 64.0KiB-64.0KiB, (W) 64.0KiB-64.0KiB, (T) 64.0KiB-64.0KiB, ioengine=sync, iodepth=1
fio-3.1
Starting 1 thread
fio: pid=6787, err=5/file:io_u.c:1756, func=io_u error, error=Input/output error
fio: io_u error on file /mnt/tgtmpathtest/datafile.tmp: Input/output error: read offset=36438016, buflen=65536

verify-phase: (groupid=0, jobs=1): err= 5 (file:io_u.c:1756, func=io_u error, error=Input/output error): pid=6787: Fri Jan 12 08:53:51 2018
   read: IOPS=10.9k, BW=681MiB/s (714MB/s)(33.3GiB/50095msec)
    clat (usec): min=71, max=22932, avg=84.76, stdev=83.84
     lat (usec): min=71, max=22932, avg=85.09, stdev=83.86
    clat percentiles (usec):
     |  1.00th=[   75],  5.00th=[   75], 10.00th=[   75], 20.00th=[   76],
     | 30.00th=[   76], 40.00th=[   76], 50.00th=[   76], 60.00th=[   77],
     | 70.00th=[   81], 80.00th=[   88], 90.00th=[  109], 95.00th=[  123],
     | 99.00th=[  157], 99.50th=[  182], 99.90th=[  297], 99.95th=[  570],
     | 99.99th=[ 2180]
   bw (  KiB/s): min=407936, max=762368, per=100.00%, avg=698791.41, stdev=63680.08, samples=100
   iops        : min= 6374, max=11912, avg=10918.44, stdev=994.96, samples=100
  lat (usec)   : 100=86.92%, 250=12.94%, 500=0.09%, 750=0.01%, 1000=0.01%
  lat (msec)   : 2=0.02%, 4=0.01%, 10=0.01%, 20=0.01%, 50=0.01%
  cpu          : usr=9.85%, sys=12.32%, ctx=546977, majf=0, minf=17
  IO depths    : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.1%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued rwt: total=546053,0,0, short=0,0,0, dropped=0,0,0
     latency   : target=0, window=0, percentile=100.00%, depth=1

Run status group 0 (all jobs):
   READ: bw=681MiB/s (714MB/s), 681MiB/s-681MiB/s (714MB/s-714MB/s), io=33.3GiB (35.8GB), run=50095-50095msec

Disk stats (read/write):
    dm-0: ios=547162/24, merge=0/36, ticks=53376/964, in_queue=54144, util=100.00%, aggrios=135945/5, aggrmerge=0/0, aggrticks=8914/2, aggrin_queue=8870, aggrutil=70.87%
  sdd: ios=207988/0, merge=0/0, ticks=14492/0, in_queue=14424, util=28.71%
  sdb: ios=112840/3, merge=0/0, ticks=7108/4, in_queue=7076, util=35.93%
  sdc: ios=114524/5, merge=0/0, ticks=7140/0, in_queue=7096, util=23.72%
  sda: ios=108429/14, merge=0/0, ticks=6916/4, in_queue=6884, util=70.87%
autopkgtest [08:53:52]: test tgtbasedmpaths: -----------------------]
autopkgtest [08:53:53]: test tgtbasedmpaths:  - - - - - - - - - - results - - - - - - - - - -
tgtbasedmpaths       FAIL non-zero exit status 1
autopkgtest [08:53:53]:  - - - - - - - - - - running shell - - - - - - - - - -
autopkgtest [09:11:38]: @@@@@@@@@@@@@@@@@@@@ summary
kpartx-file-loopback FAIL non-zero exit status 6
tgtbasedmpaths       FAIL non-zero exit status 1
qemu-system-x86_64: terminating on signal 15 from pid 25453 (/usr/bin/python3)

[-- Attachment #5: journal.log --]
[-- Type: text/plain, Size: 21974 bytes --]

Jan 12 09:17:08 autopkgtest multipathd[1980]: --------start up--------
Jan 12 09:17:08 autopkgtest multipathd[1980]: read /etc/multipath.conf
Jan 12 09:17:08 autopkgtest multipathd[1980]: path checkers start up
Jan 12 09:17:08 autopkgtest systemd[1]: Started Device-Mapper Multipath Device Controller.
Jan 12 09:17:08 autopkgtest systemd[1]: Reloading.
Jan 12 09:17:08 autopkgtest systemd[1]: Reloading.
Jan 12 09:17:09 autopkgtest systemd[1]: Reloading.
Jan 12 09:17:09 autopkgtest systemd[1]: Reloading.
Jan 12 09:17:09 autopkgtest systemd[1]: Starting (i)SCSI target daemon...
Jan 12 09:17:09 autopkgtest tgtd[2069]: tgtd: iser_ib_init(3431) Failed to initialize RDMA; load kernel modules?
Jan 12 09:17:09 autopkgtest tgtd[2069]: tgtd: work_timer_start(146) use timer_fd based scheduler
Jan 12 09:17:09 autopkgtest tgtd[2069]: tgtd: bs_init(387) use signalfd notification
Jan 12 09:17:09 autopkgtest systemd[1]: Started (i)SCSI target daemon.
Jan 12 09:17:12 autopkgtest kernel: print_req_error: I/O error, dev fd0, sector 0
Jan 12 09:17:12 autopkgtest kernel: floppy: error 10 while reading block 0
Jan 12 09:17:15 autopkgtest systemd[1]: Reloading.
Jan 12 09:17:17 autopkgtest systemd-timesyncd[476]: Synchronized to time server 91.189.89.198:123 (ntp.ubuntu.com).
Jan 12 09:17:26 autopkgtest su[6567]: Successful su for root by root
Jan 12 09:17:26 autopkgtest su[6567]: + ??? root:root
Jan 12 09:17:26 autopkgtest su[6567]: pam_unix(su:session): session opened for user root by (uid=0)
Jan 12 09:17:26 autopkgtest systemd[1]: Created slice User Slice of root.
Jan 12 09:17:26 autopkgtest systemd[1]: Starting User Manager for UID 0...
Jan 12 09:17:26 autopkgtest systemd[6568]: pam_unix(systemd-user:session): session opened for user root by (uid=0)
Jan 12 09:17:26 autopkgtest systemd[1]: Started Session c1 of user root.
Jan 12 09:17:26 autopkgtest systemd-logind[592]: New session c1 of user root.
Jan 12 09:17:26 autopkgtest systemd[6568]: Reached target Timers.
Jan 12 09:17:26 autopkgtest systemd[6568]: Reached target Sockets.
Jan 12 09:17:26 autopkgtest systemd[6568]: Reached target Paths.
Jan 12 09:17:26 autopkgtest systemd[6568]: Reached target Basic System.
Jan 12 09:17:26 autopkgtest systemd[6568]: Reached target Default.
Jan 12 09:17:26 autopkgtest systemd[6568]: Startup finished in 24ms.
Jan 12 09:17:26 autopkgtest systemd[1]: Started User Manager for UID 0.
Jan 12 09:17:26 autopkgtest systemd[1]: Stopping (i)SCSI target daemon...
Jan 12 09:17:26 autopkgtest systemd[1]: Stopped (i)SCSI target daemon.
Jan 12 09:17:26 autopkgtest systemd[1]: Starting (i)SCSI target daemon...
Jan 12 09:17:26 autopkgtest tgtd[6609]: tgtd: iser_ib_init(3431) Failed to initialize RDMA; load kernel modules?
Jan 12 09:17:26 autopkgtest tgtd[6609]: tgtd: work_timer_start(146) use timer_fd based scheduler
Jan 12 09:17:26 autopkgtest tgtd[6609]: tgtd: bs_init(387) use signalfd notification
Jan 12 09:17:27 autopkgtest systemd[1]: Started (i)SCSI target daemon.
Jan 12 09:17:27 autopkgtest tgtd[6609]: tgtd: device_mgmt(246) sz:46 params:path=/tmp/autopkgtest.zdJK5Z/tree/backingfile
Jan 12 09:17:27 autopkgtest tgtd[6609]: tgtd: bs_thread_open(409) 16
Jan 12 09:17:27 autopkgtest kernel: scsi host2: iSCSI Initiator over TCP/IP
Jan 12 09:17:27 autopkgtest kernel: scsi 2:0:0:0: RAID              IET      Controller       0001 PQ: 0 ANSI: 5
Jan 12 09:17:27 autopkgtest kernel: scsi 2:0:0:0: Attached scsi generic sg1 type 12
Jan 12 09:17:27 autopkgtest kernel: scsi 2:0:0:1: Direct-Access     IET      VIRTUAL-DISK     0001 PQ: 0 ANSI: 5
Jan 12 09:17:27 autopkgtest kernel: sd 2:0:0:1: [sda] 204800 512-byte logical blocks: (105 MB/100 MiB)
Jan 12 09:17:27 autopkgtest kernel: sd 2:0:0:1: [sda] 4096-byte physical blocks
Jan 12 09:17:27 autopkgtest kernel: sd 2:0:0:1: [sda] Write Protect is off
Jan 12 09:17:27 autopkgtest kernel: sd 2:0:0:1: [sda] Mode Sense: 69 00 10 08
Jan 12 09:17:27 autopkgtest kernel: sd 2:0:0:1: [sda] Write cache: enabled, read cache: enabled, supports DPO and FUA
Jan 12 09:17:27 autopkgtest kernel: sd 2:0:0:1: [sda] Attached SCSI disk
Jan 12 09:17:27 autopkgtest kernel: sd 2:0:0:1: Attached scsi generic sg2 type 0
Jan 12 09:17:27 autopkgtest kernel: scsi host3: iSCSI Initiator over TCP/IP
Jan 12 09:17:27 autopkgtest kernel: scsi 3:0:0:0: RAID              IET      Controller       0001 PQ: 0 ANSI: 5
Jan 12 09:17:27 autopkgtest kernel: scsi 3:0:0:0: Attached scsi generic sg3 type 12
Jan 12 09:17:27 autopkgtest kernel: scsi 3:0:0:1: Direct-Access     IET      VIRTUAL-DISK     0001 PQ: 0 ANSI: 5
Jan 12 09:17:27 autopkgtest kernel: sd 3:0:0:1: [sdb] 204800 512-byte logical blocks: (105 MB/100 MiB)
Jan 12 09:17:27 autopkgtest kernel: sd 3:0:0:1: [sdb] 4096-byte physical blocks
Jan 12 09:17:27 autopkgtest kernel: sd 3:0:0:1: [sdb] Write Protect is off
Jan 12 09:17:27 autopkgtest kernel: sd 3:0:0:1: [sdb] Mode Sense: 69 00 10 08
Jan 12 09:17:27 autopkgtest kernel: sd 3:0:0:1: [sdb] Write cache: enabled, read cache: enabled, supports DPO and FUA
Jan 12 09:17:27 autopkgtest kernel: sd 3:0:0:1: [sdb] Attached SCSI disk
Jan 12 09:17:27 autopkgtest kernel: sd 3:0:0:1: Attached scsi generic sg4 type 0
Jan 12 09:17:27 autopkgtest kernel: scsi host4: iSCSI Initiator over TCP/IP
Jan 12 09:17:27 autopkgtest kernel: scsi 4:0:0:0: RAID              IET      Controller       0001 PQ: 0 ANSI: 5
Jan 12 09:17:27 autopkgtest kernel: scsi 4:0:0:0: Attached scsi generic sg5 type 12
Jan 12 09:17:27 autopkgtest kernel: scsi 4:0:0:1: Direct-Access     IET      VIRTUAL-DISK     0001 PQ: 0 ANSI: 5
Jan 12 09:17:27 autopkgtest kernel: sd 4:0:0:1: [sdc] 204800 512-byte logical blocks: (105 MB/100 MiB)
Jan 12 09:17:27 autopkgtest kernel: sd 4:0:0:1: [sdc] 4096-byte physical blocks
Jan 12 09:17:27 autopkgtest kernel: sd 4:0:0:1: [sdc] Write Protect is off
Jan 12 09:17:27 autopkgtest kernel: sd 4:0:0:1: [sdc] Mode Sense: 69 00 10 08
Jan 12 09:17:27 autopkgtest kernel: sd 4:0:0:1: [sdc] Write cache: enabled, read cache: enabled, supports DPO and FUA
Jan 12 09:17:27 autopkgtest kernel: sd 4:0:0:1: [sdc] Attached SCSI disk
Jan 12 09:17:27 autopkgtest kernel: sd 4:0:0:1: Attached scsi generic sg6 type 0
Jan 12 09:17:27 autopkgtest kernel: scsi host5: iSCSI Initiator over TCP/IP
Jan 12 09:17:27 autopkgtest kernel: scsi 5:0:0:0: RAID              IET      Controller       0001 PQ: 0 ANSI: 5
Jan 12 09:17:27 autopkgtest kernel: scsi 5:0:0:0: Attached scsi generic sg7 type 12
Jan 12 09:17:27 autopkgtest kernel: scsi 5:0:0:1: Direct-Access     IET      VIRTUAL-DISK     0001 PQ: 0 ANSI: 5
Jan 12 09:17:27 autopkgtest kernel: sd 5:0:0:1: [sdd] 204800 512-byte logical blocks: (105 MB/100 MiB)
Jan 12 09:17:27 autopkgtest kernel: sd 5:0:0:1: [sdd] 4096-byte physical blocks
Jan 12 09:17:27 autopkgtest kernel: sd 5:0:0:1: [sdd] Write Protect is off
Jan 12 09:17:27 autopkgtest kernel: sd 5:0:0:1: [sdd] Mode Sense: 69 00 10 08
Jan 12 09:17:27 autopkgtest kernel: sd 5:0:0:1: [sdd] Write cache: enabled, read cache: enabled, supports DPO and FUA
Jan 12 09:17:27 autopkgtest kernel: sd 5:0:0:1: [sdd] Attached SCSI disk
Jan 12 09:17:27 autopkgtest kernel: sd 5:0:0:1: Attached scsi generic sg8 type 0
Jan 12 09:17:27 autopkgtest multipathd[1980]: sda: add path (uevent)
Jan 12 09:17:27 autopkgtest multipathd[1980]: sda: duration = 0 (ms)
Jan 12 09:17:27 autopkgtest multipathd[1980]: sda: persistent reservation in: requested 8200 bytes but got 8 bytes)
Jan 12 09:17:27 autopkgtest multipathd[1980]: sda: No key found. Device may not be registered.
Jan 12 09:17:27 autopkgtest kernel: device-mapper: multipath service-time: version 0.3.0 loaded
Jan 12 09:17:27 autopkgtest multipathd[1980]: 360000000000000000e00000000010001: load table [0 204800 multipath 0 0 1 1 service-time 0 1 1 8:0 1
Jan 12 09:17:27 autopkgtest multipathd[1980]: ]
Jan 12 09:17:27 autopkgtest multipathd[1980]: 360000000000000000e00000000010001: event checker started
Jan 12 09:17:27 autopkgtest multipathd[1980]: sda [8:0]: path added to devmap 360000000000000000e00000000010001
Jan 12 09:17:27 autopkgtest systemd-udevd[6687]: Process '/usr/bin/partx -d --nr 1-1024 /dev/sda' failed with exit code 1.
Jan 12 09:17:27 autopkgtest multipath[6787]: dm-0: usable paths found
Jan 12 09:17:27 autopkgtest multipath[6810]: dm-0: usable paths found
Jan 12 09:17:28 autopkgtest iscsid[649]: Connection1:0 to [target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] through [iface: default] is operational now
Jan 12 09:17:28 autopkgtest iscsid[649]: Connection2:0 to [target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] through [iface: default] is operational now
Jan 12 09:17:28 autopkgtest iscsid[649]: Connection3:0 to [target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] through [iface: default] is operational now
Jan 12 09:17:28 autopkgtest iscsid[649]: Connection4:0 to [target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] through [iface: default] is operational now
Jan 12 09:17:28 autopkgtest multipathd[1980]: sdb: add path (uevent)
Jan 12 09:17:28 autopkgtest multipathd[1980]: sdb: delaying path addition until 360000000000000000e00000000010001 is fully initialized
Jan 12 09:17:28 autopkgtest multipathd[1980]: sdc: add path (uevent)
Jan 12 09:17:28 autopkgtest multipathd[1980]: sdc: delaying path addition until 360000000000000000e00000000010001 is fully initialized
Jan 12 09:17:28 autopkgtest multipathd[1980]: sdd: add path (uevent)
Jan 12 09:17:28 autopkgtest multipathd[1980]: sdd: delaying path addition until 360000000000000000e00000000010001 is fully initialized
Jan 12 09:17:28 autopkgtest multipathd[1980]: 360000000000000000e00000000010001: performing delayed actions
Jan 12 09:17:28 autopkgtest multipathd[1980]: 360000000000000000e00000000010001: load table [0 204800 multipath 0 0 4 1 service-time 0 1 1 8:0 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:32 1 service-time 0 1 1 8:48 1
Jan 12 09:17:28 autopkgtest multipathd[1980]: ]
Jan 12 09:17:28 autopkgtest multipath[6825]: dm-0: usable paths found
Jan 12 09:17:30 autopkgtest kernel: EXT4-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null)
Jan 12 09:17:42 autopkgtest kernel: device-mapper: multipath: Failing path 8:0.
Jan 12 09:17:42 autopkgtest multipathd[1980]: sda: mark as failed
Jan 12 09:17:42 autopkgtest multipathd[1980]: 360000000000000000e00000000010001: remaining active paths: 3
Jan 12 09:17:42 autopkgtest kernel: sd 2:0:0:1: [sda] Synchronizing SCSI cache
Jan 12 09:17:42 autopkgtest multipathd[1980]: sda: remove path (uevent)
Jan 12 09:17:42 autopkgtest multipathd[1980]: 360000000000000000e00000000010001: load table [0 204800 multipath 0 0 3 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:32 1 service-time 0 1 1 8:48 1
Jan 12 09:17:42 autopkgtest multipathd[1980]: ]
Jan 12 09:17:42 autopkgtest multipathd[1980]: sda [8:0]: path removed from map 360000000000000000e00000000010001
Jan 12 09:17:42 autopkgtest multipath[6877]: dm-0: usable paths found
Jan 12 09:17:42 autopkgtest multipath[6887]: dm-0: usable paths found
Jan 12 09:17:43 autopkgtest iscsid[649]: Connection1:0 to [target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] through [iface: default] is shutdown.
Jan 12 09:17:43 autopkgtest multipathd[1980]: dm-0: Cannot find path by dm path 8:0
Jan 12 09:17:52 autopkgtest kernel: device-mapper: multipath: Failing path 8:16.
Jan 12 09:17:52 autopkgtest kernel: sd 3:0:0:1: [sdb] Synchronizing SCSI cache
Jan 12 09:17:52 autopkgtest multipath[6909]: 8:16: cannot find block device
Jan 12 09:17:52 autopkgtest multipath[6909]: 8:16: Empty device name
Jan 12 09:17:52 autopkgtest multipath[6909]: 8:16: Empty device name
Jan 12 09:17:52 autopkgtest multipath[6909]: get_udev_device: failed to look up 8:16 with type 1
Jan 12 09:17:52 autopkgtest multipath[6909]: dm-0: usable paths found
Jan 12 09:17:53 autopkgtest iscsid[649]: Connection2:0 to [target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] through [iface: default] is shutdown.
Jan 12 09:18:02 autopkgtest kernel: device-mapper: multipath: Failing path 8:32.
Jan 12 09:18:02 autopkgtest kernel: sd 4:0:0:1: [sdc] Synchronizing SCSI cache
Jan 12 09:18:02 autopkgtest multipath[6933]: 8:16: cannot find block device
Jan 12 09:18:02 autopkgtest multipath[6933]: 8:16: Empty device name
Jan 12 09:18:02 autopkgtest multipath[6933]: 8:16: Empty device name
Jan 12 09:18:02 autopkgtest multipath[6933]: 8:32: cannot find block device
Jan 12 09:18:02 autopkgtest multipath[6933]: 8:32: Empty device name
Jan 12 09:18:02 autopkgtest multipath[6933]: 8:32: Empty device name
Jan 12 09:18:02 autopkgtest multipath[6933]: get_udev_device: failed to look up 8:16 with type 1
Jan 12 09:18:02 autopkgtest multipath[6933]: get_udev_device: failed to look up 8:32 with type 1
Jan 12 09:18:02 autopkgtest multipath[6933]: dm-0: usable paths found
Jan 12 09:18:03 autopkgtest iscsid[649]: Connection3:0 to [target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] through [iface: default] is shutdown.
Jan 12 09:18:12 autopkgtest kernel: scsi host2: iSCSI Initiator over TCP/IP
Jan 12 09:18:12 autopkgtest kernel: scsi 2:0:0:0: RAID              IET      Controller       0001 PQ: 0 ANSI: 5
Jan 12 09:18:12 autopkgtest kernel: scsi 2:0:0:0: Attached scsi generic sg1 type 12
Jan 12 09:18:12 autopkgtest kernel: scsi 2:0:0:1: Direct-Access     IET      VIRTUAL-DISK     0001 PQ: 0 ANSI: 5
Jan 12 09:18:12 autopkgtest kernel: sd 2:0:0:1: Attached scsi generic sg2 type 0
Jan 12 09:18:12 autopkgtest kernel: sd 2:0:0:1: [sda] 204800 512-byte logical blocks: (105 MB/100 MiB)
Jan 12 09:18:12 autopkgtest kernel: sd 2:0:0:1: [sda] 4096-byte physical blocks
Jan 12 09:18:12 autopkgtest kernel: sd 2:0:0:1: [sda] Write Protect is off
Jan 12 09:18:12 autopkgtest kernel: sd 2:0:0:1: [sda] Mode Sense: 69 00 10 08
Jan 12 09:18:12 autopkgtest kernel: sd 2:0:0:1: [sda] Write cache: enabled, read cache: enabled, supports DPO and FUA
Jan 12 09:18:12 autopkgtest kernel: sd 2:0:0:1: [sda] Attached SCSI disk
Jan 12 09:18:12 autopkgtest kernel: scsi host6: iSCSI Initiator over TCP/IP
Jan 12 09:18:12 autopkgtest kernel: scsi 6:0:0:0: RAID              IET      Controller       0001 PQ: 0 ANSI: 5
Jan 12 09:18:12 autopkgtest kernel: scsi 6:0:0:0: Attached scsi generic sg3 type 12
Jan 12 09:18:12 autopkgtest kernel: scsi 6:0:0:1: Direct-Access     IET      VIRTUAL-DISK     0001 PQ: 0 ANSI: 5
Jan 12 09:18:12 autopkgtest kernel: sd 6:0:0:1: Attached scsi generic sg4 type 0
Jan 12 09:18:12 autopkgtest kernel: sd 6:0:0:1: [sde] 204800 512-byte logical blocks: (105 MB/100 MiB)
Jan 12 09:18:12 autopkgtest kernel: sd 6:0:0:1: [sde] 4096-byte physical blocks
Jan 12 09:18:12 autopkgtest kernel: sd 6:0:0:1: [sde] Write Protect is off
Jan 12 09:18:12 autopkgtest kernel: sd 6:0:0:1: [sde] Mode Sense: 69 00 10 08
Jan 12 09:18:12 autopkgtest kernel: sd 6:0:0:1: [sde] Write cache: enabled, read cache: enabled, supports DPO and FUA
Jan 12 09:18:12 autopkgtest kernel: sd 6:0:0:1: [sde] Attached SCSI disk
Jan 12 09:18:12 autopkgtest kernel: scsi host7: iSCSI Initiator over TCP/IP
Jan 12 09:18:12 autopkgtest kernel: scsi 7:0:0:0: RAID              IET      Controller       0001 PQ: 0 ANSI: 5
Jan 12 09:18:12 autopkgtest kernel: scsi 7:0:0:0: Attached scsi generic sg5 type 12
Jan 12 09:18:12 autopkgtest kernel: scsi 7:0:0:1: Direct-Access     IET      VIRTUAL-DISK     0001 PQ: 0 ANSI: 5
Jan 12 09:18:12 autopkgtest kernel: sd 7:0:0:1: Attached scsi generic sg6 type 0
Jan 12 09:18:12 autopkgtest kernel: sd 7:0:0:1: [sdf] 204800 512-byte logical blocks: (105 MB/100 MiB)
Jan 12 09:18:12 autopkgtest kernel: sd 7:0:0:1: [sdf] 4096-byte physical blocks
Jan 12 09:18:12 autopkgtest kernel: sd 7:0:0:1: [sdf] Write Protect is off
Jan 12 09:18:12 autopkgtest kernel: sd 7:0:0:1: [sdf] Mode Sense: 69 00 10 08
Jan 12 09:18:12 autopkgtest kernel: sd 7:0:0:1: [sdf] Write cache: enabled, read cache: enabled, supports DPO and FUA
Jan 12 09:18:12 autopkgtest kernel: sd 7:0:0:1: [sdf] Attached SCSI disk
Jan 12 09:18:12 autopkgtest kernel: scsi host8: iSCSI Initiator over TCP/IP
Jan 12 09:18:12 autopkgtest kernel: scsi 8:0:0:0: RAID              IET      Controller       0001 PQ: 0 ANSI: 5
Jan 12 09:18:12 autopkgtest kernel: scsi 8:0:0:0: Attached scsi generic sg9 type 12
Jan 12 09:18:12 autopkgtest kernel: scsi 8:0:0:1: Direct-Access     IET      VIRTUAL-DISK     0001 PQ: 0 ANSI: 5
Jan 12 09:18:12 autopkgtest kernel: sd 8:0:0:1: Attached scsi generic sg10 type 0
Jan 12 09:18:12 autopkgtest kernel: sd 8:0:0:1: [sdg] 204800 512-byte logical blocks: (105 MB/100 MiB)
Jan 12 09:18:12 autopkgtest kernel: sd 8:0:0:1: [sdg] 4096-byte physical blocks
Jan 12 09:18:12 autopkgtest kernel: sd 8:0:0:1: [sdg] Write Protect is off
Jan 12 09:18:12 autopkgtest kernel: sd 8:0:0:1: [sdg] Mode Sense: 69 00 10 08
Jan 12 09:18:12 autopkgtest kernel: sd 8:0:0:1: [sdg] Write cache: enabled, read cache: enabled, supports DPO and FUA
Jan 12 09:18:12 autopkgtest kernel: sd 8:0:0:1: [sdg] Attached SCSI disk
Jan 12 09:18:12 autopkgtest systemd-udevd[6963]: Process '/usr/bin/partx -d --nr 1-1024 /dev/sda' failed with exit code 1.
Jan 12 09:18:12 autopkgtest systemd-udevd[6958]: Process '/usr/bin/partx -d --nr 1-1024 /dev/sde' failed with exit code 1.
Jan 12 09:18:12 autopkgtest systemd-udevd[6949]: Process '/usr/bin/partx -d --nr 1-1024 /dev/sdf' failed with exit code 1.
Jan 12 09:18:12 autopkgtest systemd-udevd[6961]: Process '/usr/bin/partx -d --nr 1-1024 /dev/sdg' failed with exit code 1.
Jan 12 09:18:13 autopkgtest iscsid[649]: Connection5:0 to [target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] through [iface: default] is operational now
Jan 12 09:18:13 autopkgtest iscsid[649]: Connection6:0 to [target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] through [iface: default] is operational now
Jan 12 09:18:13 autopkgtest iscsid[649]: Connection7:0 to [target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] through [iface: default] is operational now
Jan 12 09:18:13 autopkgtest iscsid[649]: Connection8:0 to [target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] through [iface: default] is operational now
Jan 12 09:18:22 autopkgtest kernel: device-mapper: multipath: Failing path 8:48.
Jan 12 09:18:22 autopkgtest kernel: print_req_error: I/O error, dev dm-0, sector 136066
Jan 12 09:18:22 autopkgtest kernel: sd 5:0:0:1: [sdd] Synchronizing SCSI cache
Jan 12 09:18:22 autopkgtest kernel: sd 7:0:0:1: [sdf] Synchronizing SCSI cache
Jan 12 09:18:22 autopkgtest su[6567]: pam_unix(su:session): session closed for user root
Jan 12 09:18:22 autopkgtest systemd-logind[592]: Removed session c1.
Jan 12 09:18:22 autopkgtest systemd[1]: Stopping User Manager for UID 0...
Jan 12 09:18:22 autopkgtest systemd[6568]: Stopped target Default.
Jan 12 09:18:22 autopkgtest systemd[6568]: Stopped target Basic System.
Jan 12 09:18:22 autopkgtest systemd[6568]: Stopped target Paths.
Jan 12 09:18:22 autopkgtest systemd[6568]: Stopped target Timers.
Jan 12 09:18:22 autopkgtest systemd[6568]: Stopped target Sockets.
Jan 12 09:18:22 autopkgtest systemd[6568]: Reached target Shutdown.
Jan 12 09:18:22 autopkgtest systemd[6568]: Starting Exit the Session...
Jan 12 09:18:22 autopkgtest kernel: sd 8:0:0:1: [sdg] Synchronizing SCSI cache
Jan 12 09:18:22 autopkgtest systemd[6568]: Received SIGRTMIN+24 from PID 7084 (kill).
Jan 12 09:18:22 autopkgtest systemd[1]: Stopped User Manager for UID 0.
Jan 12 09:18:22 autopkgtest systemd[1]: Removed slice User Slice of root.
Jan 12 09:18:23 autopkgtest iscsid[649]: Connection4:0 to [target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] through [iface: default] is shutdown.
Jan 12 09:18:23 autopkgtest iscsid[649]: Connection7:0 to [target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] through [iface: default] is shutdown.
Jan 12 09:18:23 autopkgtest iscsid[649]: Connection8:0 to [target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] through [iface: default] is shutdown.
Jan 12 09:18:32 autopkgtest systemd[1]: Stopping Device-Mapper Multipath Device Controller...
Jan 12 09:18:37 autopkgtest multipathd[1980]: exit (signal)
Jan 12 09:18:38 autopkgtest sshd[7124]: Accepted password for ubuntu from 10.0.2.2 port 55444 ssh2
Jan 12 09:18:38 autopkgtest sshd[7124]: pam_unix(sshd:session): session opened for user ubuntu by (uid=0)
Jan 12 09:18:38 autopkgtest systemd[1]: Created slice User Slice of ubuntu.
Jan 12 09:18:38 autopkgtest systemd[1]: Starting User Manager for UID 1000...
Jan 12 09:18:38 autopkgtest systemd[7137]: pam_unix(systemd-user:session): session opened for user ubuntu by (uid=0)
Jan 12 09:18:38 autopkgtest systemd[1]: Started Session 3 of user ubuntu.
Jan 12 09:18:38 autopkgtest systemd-logind[592]: New session 3 of user ubuntu.
Jan 12 09:18:38 autopkgtest systemd[7137]: Reached target Timers.
Jan 12 09:18:38 autopkgtest systemd[7137]: Reached target Sockets.
Jan 12 09:18:38 autopkgtest systemd[7137]: Reached target Paths.
Jan 12 09:18:38 autopkgtest systemd[7137]: Reached target Basic System.
Jan 12 09:18:38 autopkgtest systemd[7137]: Reached target Default.
Jan 12 09:18:38 autopkgtest systemd[7137]: Startup finished in 26ms.
Jan 12 09:18:38 autopkgtest systemd[1]: Started User Manager for UID 1000.
Jan 12 09:18:38 autopkgtest kernel: print_req_error: I/O error, dev dm-0, sector 98304
Jan 12 09:18:38 autopkgtest kernel: Buffer I/O error on dev dm-0, logical block 49152, async page read
Jan 12 09:18:38 autopkgtest kernel: print_req_error: I/O error, dev dm-0, sector 98310
Jan 12 09:18:38 autopkgtest kernel: Buffer I/O error on dev dm-0, logical block 49155, async page read
Jan 12 09:18:38 autopkgtest kernel: print_req_error: I/O error, dev dm-0, sector 98304
Jan 12 09:18:38 autopkgtest kernel: Buffer I/O error on dev dm-0, logical block 49152, async page read
Jan 12 09:18:38 autopkgtest kernel: print_req_error: I/O error, dev dm-0, sector 98310
Jan 12 09:18:38 autopkgtest kernel: Buffer I/O error on dev dm-0, logical block 49155, async page read

[-- Attachment #6: udevlog --]
[-- Type: text/plain, Size: 11867 bytes --]

KERNEL[64.000145] remove   /devices/platform/host2/session1/target2:0:0/2:0:0:0/bsg/2:0:0:0 (bsg)
KERNEL[64.000192] remove   /devices/platform/host2/session1/target2:0:0/2:0:0:0/scsi_generic/sg1 (scsi_generic)
KERNEL[64.000215] remove   /devices/platform/host2/session1/target2:0:0/2:0:0:0/scsi_device/2:0:0:0 (scsi_device)
KERNEL[64.000242] remove   /devices/platform/host2/session1/target2:0:0/2:0:0:0 (scsi)
KERNEL[64.000267] remove   /devices/platform/host2/session1/target2:0:0/2:0:0:1/bsg/2:0:0:1 (bsg)
KERNEL[64.000288] remove   /devices/platform/host2/session1/target2:0:0/2:0:0:1/scsi_generic/sg2 (scsi_generic)
KERNEL[64.000304] remove   /devices/platform/host2/session1/target2:0:0/2:0:0:1/scsi_device/2:0:0:1 (scsi_device)
KERNEL[64.000347] remove   /devices/platform/host2/session1/target2:0:0/2:0:0:1/scsi_disk/2:0:0:1 (scsi_disk)    
UDEV  [64.002088] remove   /devices/platform/host2/session1/target2:0:0/2:0:0:1/scsi_disk/2:0:0:1 (scsi_disk)    
KERNEL[64.004135] change   /devices/virtual/block/dm-0 (block)                        
KERNEL[64.012462] remove   /devices/virtual/bdi/8:0 (bdi)                                        
KERNEL[64.012896] remove   /devices/platform/host2/session1/target2:0:0/2:0:0:1/block/sda (block)              
KERNEL[64.016890] remove   /devices/platform/host2/session1/target2:0:0/2:0:0:1 (scsi)                           
UDEV  [64.018408] remove   /devices/platform/host2/session1/target2:0:0/2:0:0:1/scsi_generic/sg2 (scsi_generic)
UDEV  [64.021040] remove   /devices/platform/host2/session1/target2:0:0/2:0:0:1/scsi_device/2:0:0:1 (scsi_device)
UDEV  [64.022886] remove   /devices/platform/host2/session1/target2:0:0/2:0:0:0/scsi_generic/sg1 (scsi_generic)
UDEV  [64.024884] remove   /devices/platform/host2/session1/target2:0:0/2:0:0:1/bsg/2:0:0:1 (bsg)
KERNEL[64.028232] remove   /devices/platform/host2/session1/target2:0:0 (scsi)                                 
KERNEL[64.028722] remove   /devices/platform/host2/session1/connection1:0/iscsi_connection/connection1:0 (iscsi_connection)
KERNEL[64.028958] remove   /devices/platform/host2/session1/iscsi_session/session1 (iscsi_session)
KERNEL[64.029059] remove   /devices/platform/host2/iscsi_host/host2 (iscsi_host)      
KERNEL[64.029171] remove   /devices/platform/host2/scsi_host/host2 (scsi_host)
KERNEL[64.029296] remove   /devices/platform/host2 (scsi)                                        
UDEV  [64.036503] remove   /devices/platform/host2/session1/target2:0:0/2:0:0:0/bsg/2:0:0:0 (bsg)
UDEV  [64.036542] remove   /devices/virtual/bdi/8:0 (bdi) 
UDEV  [64.045615] remove   /devices/platform/host2/session1/iscsi_session/session1 (iscsi_session)
UDEV  [64.047954] remove   /devices/platform/host2/session1/connection1:0/iscsi_connection/connection1:0 (iscsi_connection)
UDEV  [64.057855] remove   /devices/platform/host2/scsi_host/host2 (scsi_host)                                             
UDEV  [64.059690] remove   /devices/platform/host2/iscsi_host/host2 (iscsi_host)                  
UDEV  [64.063312] remove   /devices/platform/host2/session1/target2:0:0/2:0:0:0/scsi_device/2:0:0:0 (scsi_device)
UDEV  [64.067748] remove   /devices/platform/host2/session1/target2:0:0/2:0:0:1/block/sda (block)
UDEV  [64.073994] remove   /devices/platform/host2/session1/target2:0:0/2:0:0:0 (scsi)
UDEV  [64.081780] remove   /devices/platform/host2/session1/target2:0:0/2:0:0:1 (scsi)            
UDEV  [64.082874] remove   /devices/platform/host2/session1/target2:0:0 (scsi)                                             
KERNEL[64.084673] change   /devices/virtual/block/dm-0 (block)                                                              
UDEV  [64.086194] remove   /devices/platform/host2 (scsi)                                                                  
UDEV  [64.144668] change   /devices/virtual/block/dm-0 (block)                                                              
UDEV  [64.230774] change   /devices/virtual/block/dm-0 (block)                                                             
KERNEL[74.069607] remove   /devices/platform/host3/session2/target3:0:0/3:0:0:0/bsg/3:0:0:0 (bsg)                                          
UDEV  [74.069628] remove   /devices/platform/host3/session2/target3:0:0/3:0:0:1/scsi_disk/3:0:0:1 (scsi_disk)   
KERNEL[74.069641] remove   /devices/platform/host3/session2/target3:0:0/3:0:0:0/scsi_generic/sg3 (scsi_generic)            
UDEV  [74.069650] remove   /devices/platform/host3/session2/target3:0:0/3:0:0:1/scsi_device/3:0:0:1 (scsi_device)          
KERNEL[74.069657] remove   /devices/platform/host3/session2/target3:0:0/3:0:0:0/scsi_device/3:0:0:0 (scsi_device)
KERNEL[74.069667] remove   /devices/platform/host3/session2/target3:0:0/3:0:0:0 (scsi)                                      
KERNEL[74.069678] remove   /devices/platform/host3/session2/target3:0:0/3:0:0:1/bsg/3:0:0:1 (bsg)                           
KERNEL[74.069688] remove   /devices/platform/host3/session2/target3:0:0/3:0:0:1/scsi_generic/sg4 (scsi_generic)
KERNEL[74.069695] remove   /devices/platform/host3/session2/target3:0:0/3:0:0:1/scsi_device/3:0:0:1 (scsi_device)
KERNEL[74.069701] remove   /devices/platform/host3/session2/target3:0:0/3:0:0:1/scsi_disk/3:0:0:1 (scsi_disk)              
UDEV  [74.070450] remove   /devices/platform/host3/session2/target3:0:0/3:0:0:0/scsi_device/3:0:0:0 (scsi_device) 
UDEV  [74.071029] remove   /devices/platform/host3/session2/target3:0:0/3:0:0:1/bsg/3:0:0:1 (bsg)                 
KERNEL[74.071416] change   /devices/virtual/block/dm-0 (block)                                                   
UDEV  [74.073108] remove   /devices/platform/host3/session2/target3:0:0/3:0:0:1/scsi_generic/sg4 (scsi_generic)            
UDEV  [74.074455] remove   /devices/platform/host3/session2/target3:0:0/3:0:0:0/scsi_generic/sg3 (scsi_generic)            
UDEV  [74.075626] remove   /devices/platform/host3/session2/target3:0:0/3:0:0:0/bsg/3:0:0:0 (bsg)                          
UDEV  [74.077001] remove   /devices/platform/host3/session2/target3:0:0/3:0:0:0 (scsi)                           
KERNEL[74.080125] remove   /devices/virtual/bdi/8:16 (bdi)                                                        
KERNEL[74.080270] remove   /devices/platform/host3/session2/target3:0:0/3:0:0:1/block/sdb (block)                
KERNEL[74.080759] remove   /devices/platform/host3/session2/target3:0:0/3:0:0:1 (scsi)                           
UDEV  [74.083661] remove   /devices/virtual/bdi/8:16 (bdi)                                                       
UDEV  [74.086799] remove   /devices/platform/host3/session2/target3:0:0/3:0:0:1/block/sdb (block)                           
KERNEL[74.088142] remove   /devices/platform/host3/session2/target3:0:0 (scsi)                                             
KERNEL[74.088422] remove   /devices/platform/host3/session2/connection2:0/iscsi_connection/connection2:0 (iscsi_connection)
KERNEL[74.088584] remove   /devices/platform/host3/session2/iscsi_session/session2 (iscsi_session)                         
KERNEL[74.088657] remove   /devices/platform/host3/iscsi_host/host3 (iscsi_host)                                                                                         
KERNEL[74.088740] remove   /devices/platform/host3/scsi_host/host3 (scsi_host)                                   
KERNEL[74.088785] remove   /devices/platform/host3 (scsi)                                                        
UDEV  [74.093773] remove   /devices/platform/host3/session2/iscsi_session/session2 (iscsi_session)                
UDEV  [74.094775] remove   /devices/platform/host3/iscsi_host/host3 (iscsi_host)                                                                                                                                                                                                 [304/11793]
UDEV  [74.095345] remove   /devices/platform/host3/scsi_host/host3 (scsi_host)
UDEV  [74.095910] remove   /devices/platform/host3/session2/connection2:0/iscsi_connection/connection2:0 (iscsi_connection)
UDEV  [74.098530] remove   /devices/platform/host3/session2/target3:0:0/3:0:0:1 (scsi)
UDEV  [74.099420] remove   /devices/platform/host3/session2/target3:0:0 (scsi)
UDEV  [74.100500] remove   /devices/platform/host3 (scsi)
UDEV  [74.134076] change   /devices/virtual/block/dm-0 (block)
KERNEL[84.143452] remove   /devices/platform/host4/session3/target4:0:0/4:0:0:0/bsg/4:0:0:0 (bsg)
KERNEL[84.143493] remove   /devices/platform/host4/session3/target4:0:0/4:0:0:0/scsi_generic/sg5 (scsi_generic)
KERNEL[84.143509] remove   /devices/platform/host4/session3/target4:0:0/4:0:0:0/scsi_device/4:0:0:0 (scsi_device)
KERNEL[84.143527] remove   /devices/platform/host4/session3/target4:0:0/4:0:0:0 (scsi)
KERNEL[84.143548] remove   /devices/platform/host4/session3/target4:0:0/4:0:0:1/bsg/4:0:0:1 (bsg)
KERNEL[84.143568] remove   /devices/platform/host4/session3/target4:0:0/4:0:0:1/scsi_generic/sg6 (scsi_generic)
KERNEL[84.143582] remove   /devices/platform/host4/session3/target4:0:0/4:0:0:1/scsi_device/4:0:0:1 (scsi_device)
KERNEL[84.143594] remove   /devices/platform/host4/session3/target4:0:0/4:0:0:1/scsi_disk/4:0:0:1 (scsi_disk)
UDEV  [84.144843] remove   /devices/platform/host4/session3/target4:0:0/4:0:0:1/scsi_device/4:0:0:1 (scsi_device)
UDEV  [84.145769] remove   /devices/platform/host4/session3/target4:0:0/4:0:0:1/scsi_generic/sg6 (scsi_generic)
KERNEL[84.146120] change   /devices/virtual/block/dm-0 (block)
UDEV  [84.150544] remove   /devices/platform/host4/session3/target4:0:0/4:0:0:1/scsi_disk/4:0:0:1 (scsi_disk)
UDEV  [84.153129] remove   /devices/platform/host4/session3/target4:0:0/4:0:0:0/scsi_generic/sg5 (scsi_generic)
UDEV  [84.155032] remove   /devices/platform/host4/session3/target4:0:0/4:0:0:0/scsi_device/4:0:0:0 (scsi_device)
KERNEL[84.156175] remove   /devices/virtual/bdi/8:32 (bdi)
KERNEL[84.156327] remove   /devices/platform/host4/session3/target4:0:0/4:0:0:1/block/sdc (block)
UDEV  [84.158249] remove   /devices/platform/host4/session3/target4:0:0/4:0:0:0/bsg/4:0:0:0 (bsg)
UDEV  [84.163414] remove   /devices/platform/host4/session3/target4:0:0/4:0:0:1/bsg/4:0:0:1 (bsg)
KERNEL[84.163959] remove   /devices/platform/host4/session3/target4:0:0/4:0:0:1 (scsi)
UDEV  [84.165762] remove   /devices/virtual/bdi/8:32 (bdi)
KERNEL[84.172202] remove   /devices/platform/host4/session3/target4:0:0 (scsi)
KERNEL[84.172627] remove   /devices/platform/host4/session3/connection3:0/iscsi_connection/connection3:0 (iscsi_connection)
KERNEL[84.172853] remove   /devices/platform/host4/session3/iscsi_session/session3 (iscsi_session)
KERNEL[84.172954] remove   /devices/platform/host4/iscsi_host/host4 (iscsi_host)
KERNEL[84.173016] remove   /devices/platform/host4/scsi_host/host4 (scsi_host)
KERNEL[84.173069] remove   /devices/platform/host4 (scsi)
UDEV  [84.178398] remove   /devices/platform/host4/session3/target4:0:0/4:0:0:0 (scsi)
UDEV  [84.178433] remove   /devices/platform/host4/session3/iscsi_session/session3 (iscsi_session)
UDEV  [84.178452] remove   /devices/platform/host4/iscsi_host/host4 (iscsi_host)                                                                                                                                                                                                 [268/11793]
UDEV  [84.181797] remove   /devices/platform/host4/scsi_host/host4 (scsi_host)
UDEV  [84.186165] remove   /devices/platform/host4/session3/connection3:0/iscsi_connection/connection3:0 (iscsi_connection)
UDEV  [84.191566] remove   /devices/platform/host4/session3/target4:0:0/4:0:0:1/block/sdc (block)
UDEV  [84.200973] remove   /devices/platform/host4/session3/target4:0:0/4:0:0:1 (scsi)
UDEV  [84.202042] remove   /devices/platform/host4/session3/target4:0:0 (scsi)
UDEV  [84.203355] remove   /devices/platform/host4 (scsi)
UDEV  [84.250480] change   /devices/virtual/block/dm-0 (block)

[-- Attachment #7: Type: text/plain, Size: 0 bytes --]



^ permalink raw reply	[flat|nested] 22+ messages in thread

* Re: multipath-tools 0.7.4 failure to remove device
  2018-01-12  8:38 multipath-tools 0.7.4 failure to remove device Julian Andres Klode
@ 2018-01-12 20:35 ` Martin Wilck
  2018-01-12 21:47   ` Julian Andres Klode
  0 siblings, 1 reply; 22+ messages in thread
From: Martin Wilck @ 2018-01-12 20:35 UTC (permalink / raw)
  To: Julian Andres Klode, Christophe Varoqui,
	Device-mapper development mailing list
  Cc: Guan Junxiong

[-- Attachment #1: Type: text/plain, Size: 3124 bytes --]

On Fri, 2018-01-12 at 09:38 +0100, Julian Andres Klode wrote:
> 
> and then we get I/O error on the device and it's rendered unusable.
> It's
> also crashing in uev_pathfail_check() occassionally because
> find_path_by_devt()
> returns NULL, so I applied the following patch to at least continue,
> but that's
> obviously wrong - We get an udev event for a device which does not
> exist in /dev
> (but it should)?

Adding Guan, as the pathfail check is from his code.

> --- a/multipathd/main.c
> +++ b/multipathd/main.c
> @@ -1090,6 +1090,11 @@ uev_pathfail_check(struct uevent *uev, s
>  	lock(&vecs->lock);
>  	pthread_testcancel();
>  	pp = find_path_by_devt(vecs->pathvec, devt);
> +	if (!pp) {
> +		condlog(3, "%s: Cannot find path by dm path %s",
> uev->kernel, devt);
> +		FREE(devt);
> +		goto out;
> +	}
>  	r = io_err_stat_handle_pathfail(pp);
>  	lock_cleanup_pop(vecs->lock);

You need to cleanup the lock in the error path. I'd pefer checking
for a NULL path argument in io_err_stat_handle_pathfail(). See
attachment.

I'm assuming that you are not using the "marginal path" logic. In
general I don't like the fact that PATH_FAILED events are handled at
all in multipathd if this logic is inactive; that code path is only
needed for this purpose. But that's just a side note.

> Jan 12 09:17:52 autopkgtest kernel: device-mapper: multipath: Failing
> path 8:16.
> > Jan 12 09:17:52 autopkgtest kernel: sd 3:0:0:1: [sdb] Synchronizing
> SCSI cache
> > Jan 12 09:17:52 autopkgtest multipath[6909]: 8:16: cannot find
> block device
> Jan 12 09:17:52 autopkgtest multipath[6909]: 8:16: Empty device
name
> Jan 12 09:17:52 autopkgtest multipath[6909]: 8:16: Empty device
name
> > Jan 12 09:17:52 autopkgtest multipath[6909]: get_udev_device: >
> failed to look up 8:16 with type 1
> > Jan 12 09:17:52 autopkgtest multipath[6909]: dm-0: usable paths
> found
> > Jan 12 09:17:53 autopkgtest iscsid[649]: Connection2:0 to [target:
> iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] through
> [iface: default] is shutdown.

> > We can see that it correctly removed the first device (sda) -
> except well, it seems to try
> >again and fail with the part where it would have crashed. But when
> it tries to lookup the
> second one it fails.

> > Given that this works in 0.6.4, I think it's a bug that appeared
> later on,
> > but I can't really pin point the source of it.

Well, it may be because of the locking being broken by your patch.
If you look at the journal you sent, multipathd never prints a single
message after the removal of sda, until it says

Jan 12 09:18:37 autopkgtest multipathd[1980]: exit (signal)

That makes me think it hangs somehow, which could well be explained by
the lock not being released. Please retry with the attached patch.

We are seeing the *multipath* messages ([6069]) which are printed from
multipath during udev rule processing, because the map still holds
references to the deleted path. 

Regards,
Martin

-- 
Dr. Martin Wilck <mwilck@suse.com>, Tel. +49 (0)911 74053 2107
SUSE Linux GmbH, GF: Felix Imendörffer, Jane Smithard, Graham Norton
HRB 21284 (AG Nürnberg)

[-- Attachment #2: deal-with-NULL-path-in-pathfail-handler.patch --]
[-- Type: text/x-patch, Size: 849 bytes --]

commit c4d48c633b0825941024a34acf2304a6f5a2d17d (HEAD -> upstream)
Author: Martin Wilck <mwilck@suse.com>
Date:   Fri Jan 12 21:21:49 2018 +0100

    libmultipath: deal with NULL path in pathfail handler
    
    This avoids a crash for paths which are already deleted.
    
    Reported-by: Julian Andres Klode <julian.klode@canonical.com>

diff --git a/libmultipath/io_err_stat.c b/libmultipath/io_err_stat.c
index 75a6df67c207..d2d2276a523e 100644
--- a/libmultipath/io_err_stat.c
+++ b/libmultipath/io_err_stat.c
@@ -315,6 +315,10 @@ int io_err_stat_handle_pathfail(struct path *path)
 	struct timespec curr_time;
 	int res;
 
+	if (path == NULL) {
+		io_err_stat_log(1, "%s: called with empty path", __func__);
+		return 1;
+	}
 	if (path->io_err_disable_reinstate) {
 		io_err_stat_log(3, "%s: reinstate is already disabled",
 				path->dev);

[-- Attachment #3: Type: text/plain, Size: 0 bytes --]



^ permalink raw reply related	[flat|nested] 22+ messages in thread

* Re: multipath-tools 0.7.4 failure to remove device
  2018-01-12 20:35 ` Martin Wilck
@ 2018-01-12 21:47   ` Julian Andres Klode
  2018-01-12 22:18     ` Martin Wilck
  2018-01-13 19:46     ` multipath-tools 0.7.4 failure to remove device Martin Wilck
  0 siblings, 2 replies; 22+ messages in thread
From: Julian Andres Klode @ 2018-01-12 21:47 UTC (permalink / raw)
  To: Martin Wilck; +Cc: Device-mapper development mailing list, Guan Junxiong

On Fri, Jan 12, 2018 at 09:35:39PM +0100, Martin Wilck wrote:
> On Fri, 2018-01-12 at 09:38 +0100, Julian Andres Klode wrote:
> > 
> > and then we get I/O error on the device and it's rendered unusable.
> > It's
> > also crashing in uev_pathfail_check() occassionally because
> > find_path_by_devt()
> > returns NULL, so I applied the following patch to at least continue,
> > but that's
> > obviously wrong - We get an udev event for a device which does not
> > exist in /dev
> > (but it should)?
> 
> Adding Guan, as the pathfail check is from his code.
> 
> > --- a/multipathd/main.c
> > +++ b/multipathd/main.c
> > @@ -1090,6 +1090,11 @@ uev_pathfail_check(struct uevent *uev, s
> >  	lock(&vecs->lock);
> >  	pthread_testcancel();
> >  	pp = find_path_by_devt(vecs->pathvec, devt);
> > +	if (!pp) {
> > +		condlog(3, "%s: Cannot find path by dm path %s",
> > uev->kernel, devt);
> > +		FREE(devt);
> > +		goto out;
> > +	}
> >  	r = io_err_stat_handle_pathfail(pp);
> >  	lock_cleanup_pop(vecs->lock);
> 
> You need to cleanup the lock in the error path. I'd pefer checking
> for a NULL path argument in io_err_stat_handle_pathfail(). See
> attachment.

Oh, silly me. Yes, you're right, and your patch fixes the issue. 

> 
> I'm assuming that you are not using the "marginal path" logic. In
> general I don't like the fact that PATH_FAILED events are handled at
> all in multipathd if this logic is inactive; that code path is only
> needed for this purpose. But that's just a side note.

I don't know actually, I'm just updating the package :) I can say that
the tests were run with default configuration, normally we run with
DEFAULT_FIND_MULTIPATHS but that does not work yet with 0.7.4 - no
dm-0 device seems to get created in this test case (some systems without
multipath were broken 2.5 years ago just by installing it because it
took over non-multipath devices, hence the option was enabled; might
not even be needed anymore).

I'll collect some more data on Monday.

-- 
debian developer - deb.li/jak | jak-linux.org - free software dev
ubuntu core developer                              i speak de, en

^ permalink raw reply	[flat|nested] 22+ messages in thread

* Re: multipath-tools 0.7.4 failure to remove device
  2018-01-12 21:47   ` Julian Andres Klode
@ 2018-01-12 22:18     ` Martin Wilck
  2018-01-12 22:26       ` Julian Andres Klode
  2018-01-15 15:44       ` Julian Andres Klode
  2018-01-13 19:46     ` multipath-tools 0.7.4 failure to remove device Martin Wilck
  1 sibling, 2 replies; 22+ messages in thread
From: Martin Wilck @ 2018-01-12 22:18 UTC (permalink / raw)
  To: Julian Andres Klode
  Cc: Guan Junxiong, development mailing list, Device-mapper

On Fri, 2018-01-12 at 22:47 +0100, Julian Andres Klode wrote:
> 
> I don't know actually, I'm just updating the package :) 

The feature needs to be enabled explicitly, so indeed you weren't using
it.

> >I can say that
> the tests were run with default configuration, normally we run with
> DEFAULT_FIND_MULTIPATHS but that does not work yet with 0.7.4 - no
> dm-0 device seems to get created in this test case (some systems
> without
> multipath were broken 2.5 years ago just by installing it because it
> took over non-multipath devices, hence the option was enabled; might
> not even be needed anymore).

That's still the default behavior if find_multipaths is off. And
actually, I don't know what's wrong with that. If you don't like it,
blacklist your root device. All you need to make sure is that multipath
settings in the initrd and in the booted system are the same.

"find_multipaths" is not a silver bullet to kill off multipath-related
boot problems. It has advantages and disadvantages, depending on the
use case. Anyway, I'm not aware of general problems with it in the
later multipath versions.

Btw, one thing you should be aware of is that udev rule files and
systemd service files have changed. That requires also dracut changes
that are not in upstream dracut yet.

Regards,
Martin

-- 
Dr. Martin Wilck <mwilck@suse.com>, Tel. +49 (0)911 74053 2107
SUSE Linux GmbH, GF: Felix Imendörffer, Jane Smithard, Graham Norton
HRB 21284 (AG Nürnberg)

--
dm-devel mailing list
dm-devel@redhat.com
https://www.redhat.com/mailman/listinfo/dm-devel

^ permalink raw reply	[flat|nested] 22+ messages in thread

* Re: multipath-tools 0.7.4 failure to remove device
  2018-01-12 22:18     ` Martin Wilck
@ 2018-01-12 22:26       ` Julian Andres Klode
  2018-01-15 15:44       ` Julian Andres Klode
  1 sibling, 0 replies; 22+ messages in thread
From: Julian Andres Klode @ 2018-01-12 22:26 UTC (permalink / raw)
  To: Martin Wilck; +Cc: Device-mapper development mailing list, Guan Junxiong

On Fri, Jan 12, 2018 at 11:18:01PM +0100, Martin Wilck wrote:
> On Fri, 2018-01-12 at 22:47 +0100, Julian Andres Klode wrote:
> > 
> > I don't know actually, I'm just updating the package :) 
> 
> The feature needs to be enabled explicitly, so indeed you weren't using
> it.
> 
> > >I can say that
> > the tests were run with default configuration, normally we run with
> > DEFAULT_FIND_MULTIPATHS but that does not work yet with 0.7.4 - no
> > dm-0 device seems to get created in this test case (some systems
> > without
> > multipath were broken 2.5 years ago just by installing it because it
> > took over non-multipath devices, hence the option was enabled; might
> > not even be needed anymore).
> 
> That's still the default behavior if find_multipaths is off. And
> actually, I don't know what's wrong with that. If you don't like it,
> blacklist your root device. All you need to make sure is that multipath
> settings in the initrd and in the booted system are the same.
> 
> "find_multipaths" is not a silver bullet to kill off multipath-related
> boot problems. It has advantages and disadvantages, depending on the
> use case. Anyway, I'm not aware of general problems with it in the
> later multipath versions.

I'll try to give it a bisect since the test works in 0.6.4 and not in
0.7.4. It's going to be painful :)

> 
> Btw, one thing you should be aware of is that udev rule files and
> systemd service files have changed. That requires also dracut changes
> that are not in upstream dracut yet.

We don't use dracut, we use initramfs-tools, but yes, I have to update
the hooks for that too.

-- 
debian developer - deb.li/jak | jak-linux.org - free software dev
ubuntu core developer                              i speak de, en

^ permalink raw reply	[flat|nested] 22+ messages in thread

* Re: multipath-tools 0.7.4 failure to remove device
  2018-01-12 21:47   ` Julian Andres Klode
  2018-01-12 22:18     ` Martin Wilck
@ 2018-01-13 19:46     ` Martin Wilck
  1 sibling, 0 replies; 22+ messages in thread
From: Martin Wilck @ 2018-01-13 19:46 UTC (permalink / raw)
  To: Julian Andres Klode
  Cc: Guan Junxiong, development mailing list, Device-mapper

On Fri, 2018-01-12 at 22:47 +0100, Julian Andres Klode wrote:
> On Fri, Jan 12, 2018 at 09:35:39PM +0100, Martin Wilck wrote:
> > On Fri, 2018-01-12 at 09:38 +0100, Julian Andres Klode wrote:
> > > 
> > > --- a/multipathd/main.c
> > > +++ b/multipathd/main.c
> > > @@ -1090,6 +1090,11 @@ uev_pathfail_check(struct uevent *uev, s
> > >  	lock(&vecs->lock);
> > >  	pthread_testcancel();
> > >  	pp = find_path_by_devt(vecs->pathvec, devt);
> > > +	if (!pp) {
> > > +		condlog(3, "%s: Cannot find path by dm path %s",
> > > uev->kernel, devt);
> > > +		FREE(devt);
> > > +		goto out;
> > > +	}
> > >  	r = io_err_stat_handle_pathfail(pp);
> > >  	lock_cleanup_pop(vecs->lock);
> > 
> > You need to cleanup the lock in the error path. I'd pefer checking
> > for a NULL path argument in io_err_stat_handle_pathfail(). See
> > attachment.
> 
> Oh, silly me. Yes, you're right, and your patch fixes the issue. 

And both of us missed Guan's own patch, which Christophe has just
merged as 83924318. :-/

Martin

-- 
Dr. Martin Wilck <mwilck@suse.com>, Tel. +49 (0)911 74053 2107
SUSE Linux GmbH, GF: Felix Imendörffer, Jane Smithard, Graham Norton
HRB 21284 (AG Nürnberg)

--
dm-devel mailing list
dm-devel@redhat.com
https://www.redhat.com/mailman/listinfo/dm-devel

^ permalink raw reply	[flat|nested] 22+ messages in thread

* Re: multipath-tools 0.7.4 failure to remove device
  2018-01-12 22:18     ` Martin Wilck
  2018-01-12 22:26       ` Julian Andres Klode
@ 2018-01-15 15:44       ` Julian Andres Klode
  2018-01-15 16:12         ` Martin Wilck
  1 sibling, 1 reply; 22+ messages in thread
From: Julian Andres Klode @ 2018-01-15 15:44 UTC (permalink / raw)
  To: Martin Wilck; +Cc: Device-mapper development mailing list, Guan Junxiong

On Fri, Jan 12, 2018 at 11:18:01PM +0100, Martin Wilck wrote:
> "find_multipaths" is not a silver bullet to kill off multipath-related
> boot problems. It has advantages and disadvantages, depending on the
> use case. Anyway, I'm not aware of general problems with it in the
> later multipath versions.

It was your commit that made it imply -n that caused the test failure :)
I understand your position on that, but reverted it for Ubuntu, because,
while it might be somewhat broken, it's at least the same level of broken
as before.

-- 
debian developer - deb.li/jak | jak-linux.org - free software dev
ubuntu core developer                              i speak de, en

^ permalink raw reply	[flat|nested] 22+ messages in thread

* Re: multipath-tools 0.7.4 failure to remove device
  2018-01-15 15:44       ` Julian Andres Klode
@ 2018-01-15 16:12         ` Martin Wilck
  2018-01-15 16:26           ` Julian Andres Klode
  0 siblings, 1 reply; 22+ messages in thread
From: Martin Wilck @ 2018-01-15 16:12 UTC (permalink / raw)
  To: Julian Andres Klode
  Cc: Guan Junxiong, development mailing list, Device-mapper

On Mon, 2018-01-15 at 16:44 +0100, Julian Andres Klode wrote:
> 
> It was your commit that made it imply -n that caused the test failure
> :)
> I understand your position on that, but reverted it for Ubuntu,
> because,
> while it might be somewhat broken, it's at least the same level of
> broken
> as before.

I'd like to understand that better. Why would this break boot?

If the root device was already in the "wwids" file, it wouldn't be
"new", and thus "-n" should have no effect. 

If the root device is a "real" multipath device with >=2 paths, there's
of course a difference with and without "-n". But in that case, I'd
expect the device to be listed in "wwids", because it should have been
detected as multipath device during installation already.

Finally, if the root device is not a real multipath device (1 path
only), and is not in "wwids", my patch would cause it not to be
multipathed, which is the Right Thing todo AFAICS.

The same reasoning applies to other devices required for booting
besides the root FS (swap or whatever).

What am I missing here?

Martin

-- 
Dr. Martin Wilck <mwilck@suse.com>, Tel. +49 (0)911 74053 2107
SUSE Linux GmbH, GF: Felix Imendörffer, Jane Smithard, Graham Norton
HRB 21284 (AG Nürnberg)

--
dm-devel mailing list
dm-devel@redhat.com
https://www.redhat.com/mailman/listinfo/dm-devel

^ permalink raw reply	[flat|nested] 22+ messages in thread

* Re: multipath-tools 0.7.4 failure to remove device
  2018-01-15 16:12         ` Martin Wilck
@ 2018-01-15 16:26           ` Julian Andres Klode
  2018-01-15 16:46             ` Martin Wilck
  0 siblings, 1 reply; 22+ messages in thread
From: Julian Andres Klode @ 2018-01-15 16:26 UTC (permalink / raw)
  To: Martin Wilck; +Cc: Device-mapper development mailing list, Guan Junxiong

On Mon, Jan 15, 2018 at 05:12:10PM +0100, Martin Wilck wrote:
> On Mon, 2018-01-15 at 16:44 +0100, Julian Andres Klode wrote:
> > 
> > It was your commit that made it imply -n that caused the test failure
> > :)
> > I understand your position on that, but reverted it for Ubuntu,
> > because,
> > while it might be somewhat broken, it's at least the same level of
> > broken
> > as before.
> 
> I'd like to understand that better. Why would this break boot?

Ah sorry for the confusion. It did not break boot. Having finding
disabled would have "broken" boot. The problem I was talking about
was that with finding enabled, no dm devices were generated, which
it turned out, was not entirely true - you had to run multipath
manually (due to your find implies -n commit). 

It seems to me that this would cause more issues in practice than
just keeping the slightly race-y combination enabled. It's something
to revisit after the ubuntu lts when then people have some time to
adjust to that change.

-- 
debian developer - deb.li/jak | jak-linux.org - free software dev
ubuntu core developer                              i speak de, en

^ permalink raw reply	[flat|nested] 22+ messages in thread

* Re: multipath-tools 0.7.4 failure to remove device
  2018-01-15 16:26           ` Julian Andres Klode
@ 2018-01-15 16:46             ` Martin Wilck
  2018-01-16 20:30               ` Benjamin Marzinski
  0 siblings, 1 reply; 22+ messages in thread
From: Martin Wilck @ 2018-01-15 16:46 UTC (permalink / raw)
  To: Julian Andres Klode
  Cc: Guan Junxiong, development mailing list, Device-mapper

On Mon, 2018-01-15 at 17:26 +0100, Julian Andres Klode wrote:
> On Mon, Jan 15, 2018 at 05:12:10PM +0100, Martin Wilck wrote:
> > On Mon, 2018-01-15 at 16:44 +0100, Julian Andres Klode wrote:
> > > 
> > > It was your commit that made it imply -n that caused the test
> > > failure
> > > :)
> > > I understand your position on that, but reverted it for Ubuntu,
> > > because,
> > > while it might be somewhat broken, it's at least the same level
> > > of
> > > broken
> > > as before.
> > 
> > I'd like to understand that better. Why would this break boot?
> 
> Ah sorry for the confusion. It did not break boot. Having finding
> disabled would have "broken" boot. The problem I was talking about
> was that with finding enabled, no dm devices were generated, which
> it turned out, was not entirely true - you had to run multipath
> manually (due to your find implies -n commit). 
> 
> It seems to me that this would cause more issues in practice than
> just keeping the slightly race-y combination enabled. It's something
> to revisit after the ubuntu lts when then people have some time to
> adjust to that change.

I wouldn't call it "slightly race-y". With find_multipaths "on" and
"ignore_wwids" "off", "multipath -u" classifies every device as a
multipath device. So SYSTEMD_READY=0 will be set on each device. But
multipathd, which is responsible for actually setting up the map, will
honor "find_multipaths", and will not set up a map for a device it
finds only a single path for. So the device never appears in a state in
which systemd would be able to use it. Unless you've put in some other
magic, this is almost guaranteed to make your system unbootable in the
quite common case where people using multipath are running off a non-
multipathed local root disk.

Martin

-- 
Dr. Martin Wilck <mwilck@suse.com>, Tel. +49 (0)911 74053 2107
SUSE Linux GmbH, GF: Felix Imendörffer, Jane Smithard, Graham Norton
HRB 21284 (AG Nürnberg)

--
dm-devel mailing list
dm-devel@redhat.com
https://www.redhat.com/mailman/listinfo/dm-devel

^ permalink raw reply	[flat|nested] 22+ messages in thread

* Re: multipath-tools 0.7.4 failure to remove device
  2018-01-15 16:46             ` Martin Wilck
@ 2018-01-16 20:30               ` Benjamin Marzinski
  2018-01-16 22:05                 ` Xose Vazquez Perez
                                   ` (3 more replies)
  0 siblings, 4 replies; 22+ messages in thread
From: Benjamin Marzinski @ 2018-01-16 20:30 UTC (permalink / raw)
  To: Martin Wilck; +Cc: Julian Andres Klode, Guan Junxiong, development mailing list

On Mon, Jan 15, 2018 at 05:46:24PM +0100, Martin Wilck wrote:
> On Mon, 2018-01-15 at 17:26 +0100, Julian Andres Klode wrote:
> > On Mon, Jan 15, 2018 at 05:12:10PM +0100, Martin Wilck wrote:
> > > On Mon, 2018-01-15 at 16:44 +0100, Julian Andres Klode wrote:
> > > > 
> > > > It was your commit that made it imply -n that caused the test
> > > > failure
> > > > :)
> > > > I understand your position on that, but reverted it for Ubuntu,
> > > > because,
> > > > while it might be somewhat broken, it's at least the same level
> > > > of
> > > > broken
> > > > as before.
> > > 
> > > I'd like to understand that better. Why would this break boot?
> > 
> > Ah sorry for the confusion. It did not break boot. Having finding
> > disabled would have "broken" boot. The problem I was talking about
> > was that with finding enabled, no dm devices were generated, which
> > it turned out, was not entirely true - you had to run multipath
> > manually (due to your find implies -n commit). 
> > 
> > It seems to me that this would cause more issues in practice than
> > just keeping the slightly race-y combination enabled. It's something
> > to revisit after the ubuntu lts when then people have some time to
> > adjust to that change.
> 
> I wouldn't call it "slightly race-y". With find_multipaths "on" and
> "ignore_wwids" "off", "multipath -u" classifies every device as a
> multipath device. So SYSTEMD_READY=0 will be set on each device. But
> multipathd, which is responsible for actually setting up the map, will
> honor "find_multipaths", and will not set up a map for a device it
> finds only a single path for. So the device never appears in a state in
> which systemd would be able to use it. Unless you've put in some other
> magic, this is almost guaranteed to make your system unbootable in the
> quite common case where people using multipath are running off a non-
> multipathed local root disk.

RedHat also removes your patches to force ignore_wwids off and imply -n

64e27ec066a001012f44550f095c93443e91d845
ffbb886a8a16cb063d669cd76a1e656fd3ec8c4b

I don't see any why that this could claim all the devices and render a
system unbootable. First off, I assume you mean that there is a problem
with find_multipaths "on" and ignore_wwids "on", since your patch forces
ignore_wwids "off", and with that setting, mutipath will obviously only
claim devices in the wwids file.

But with find_multipaths "on" and ignore_wwids "on", you don't classify
every device as a multipath device. Here's the code

        if (get_dm_mpvec(cmd, curmp, pathvec, refwwid))
                goto out;

        filter_pathvec(pathvec, refwwid);


        if (cmd == CMD_VALID_PATH) {
                /* This only happens if find_multipaths and
                 * ignore_wwids is set.
                 * If there is currently a multipath device matching
                 * the refwwid, or there is more than one path matching
                 * the refwwid, then the path is valid */
                if (VECTOR_SIZE(curmp) != 0 || VECTOR_SIZE(pathvec) > 1)
                        r = 0;
                printf("%s %s a valid multipath device path\n",
                       devpath, r == 0 ? "is" : "is not");
                goto out;
        }

So you only classify a device as a multipath device, if either:

1. you find multiple devices with the same WWID. That's what the
   (VECTOR_SIZE(pathvec) > 1) check after the filter_pathvec() call
   does.

2. You find that the device is already part of a multipath device.
   That's what the (VECTOR_SIZE(curmp) != 0) after the get_dm_mpvec()
   call does.

This code is actually more stingy with allowing devices to be claimed as
multipath devices than it could safely be.  Even though ignore_wwids is
set, it should probably also allow devices that are in the wwids file,
since they are multipath-able. The idea of ignore_wwids is to be more
generous in accepting devices, but by disallowing devices even if they
are in the wwids file, it is being less generous in some cases. 

As for implying -n with find_multipaths, my personal opinion is that it
breaks the main point of find_multipaths, which is to make stuff "just
work". Since RedHat has been running with find_multipaths as the default
for years now, I am well aware of the race-y issue. But in practice
it's not very bad.

Here is how I see it. The first time a multipathable device appears, the
udev rules will not claim the first path of it. Multipathd will also not
immediately create a multipath device on top of it.  This means that
something else could auto set-up on it.  The most likely way this can
happen is if you are adding new storage that already has LVM/MD metadata
on it.  lvm will auto-activate on that new path, making multipath unable
to create the multipath device.

If you think that sounds like a big problem, you should consider that if
you use the default multipath udev rules, the exact same problem happens
if you don't use find_multipaths as well. That's because when we check
if multipath can claim a device, we don't call multipath -u with -i.
This actually can save thoughtless users some headaches.  If they aren't
using find_multipaths, and they don't setup their blacklisting
correctly, multipath still won't claim devices that are already in use
when it starts up, because it will never create a multipath device on
them, so it will never add their wwid to the wwids file.

So in short, the problem (which currently effects multipath regardless
of whether find_multipaths is set) is that when new storage is added, if
that new storage already has metadata on it that the system will use to
autoassemble something else on top of the device (in practice this means
lvm/md metadata), you may autoassemble the wrong thing on the device.
It's a race, and yes, find-multipaths is more likely to lose the race
because it can't start assembling until the second path appears.
The solution is to simply remove the lvm/dm device, and run multipath,
and from then on, you will never see the problem again.

The only bug I have ever received about this issue was because anaconda
(the redhat system installer) knew that multipath was supposed to be
running on a device, but couldn't disassemble the lvm device that got
automatically created, because of the old meta-data. The solution is to
make anaconda smarter.

As a side note, RedHat also adds code to automatically fire off a change
uevent on all the path devices on the first time a multipath device is
created, so that all the path devices get correctly claimed by multipath
after the fact, on the first create. It's currently part of the same
patch that reverts the two commits listed above, but I have no problem
with posting it as a seperate patch. I obviously have no problem with
reverting those two commits upstream either. But I don't feel horribly
burdened with carrying them as RedHat patches.

-Ben

> Martin
> 
> -- 
> Dr. Martin Wilck <mwilck@suse.com>, Tel. +49 (0)911 74053 2107
> SUSE Linux GmbH, GF: Felix Imendörffer, Jane Smithard, Graham Norton
> HRB 21284 (AG Nürnberg)
> 
> --
> dm-devel mailing list
> dm-devel@redhat.com
> https://www.redhat.com/mailman/listinfo/dm-devel

^ permalink raw reply	[flat|nested] 22+ messages in thread

* Re: multipath-tools 0.7.4 failure to remove device
  2018-01-16 20:30               ` Benjamin Marzinski
@ 2018-01-16 22:05                 ` Xose Vazquez Perez
  2018-01-17  0:43                 ` Martin Wilck
                                   ` (2 subsequent siblings)
  3 siblings, 0 replies; 22+ messages in thread
From: Xose Vazquez Perez @ 2018-01-16 22:05 UTC (permalink / raw)
  To: Benjamin Marzinski, development mailing list
  Cc: Julian Andres Klode, Guan Junxiong, Martin Wilck

On 01/16/2018 09:30 PM, Benjamin Marzinski wrote:

> RedHat also removes your patches to force ignore_wwids off and imply -n
> 
> 64e27ec066a001012f44550f095c93443e91d845
> ffbb886a8a16cb063d669cd76a1e656fd3ec8c4b


For reference, they are at(-RH- prefix):

https://src.fedoraproject.org/rpms/device-mapper-multipath/tree/master or
$ git clone https://src.fedoraproject.org/rpms/device-mapper-multipath.git

^ permalink raw reply	[flat|nested] 22+ messages in thread

* Re: multipath-tools 0.7.4 failure to remove device
  2018-01-16 20:30               ` Benjamin Marzinski
  2018-01-16 22:05                 ` Xose Vazquez Perez
@ 2018-01-17  0:43                 ` Martin Wilck
  2018-01-17 18:38                   ` Benjamin Marzinski
  2018-01-17  9:38                 ` Julian Andres Klode
  2018-01-17 16:27                 ` Multipath path classification revisited Martin Wilck
  3 siblings, 1 reply; 22+ messages in thread
From: Martin Wilck @ 2018-01-17  0:43 UTC (permalink / raw)
  To: Benjamin Marzinski
  Cc: Julian Andres Klode, Guan Junxiong, development mailing list

On Tue, 2018-01-16 at 14:30 -0600, Benjamin Marzinski wrote:
> On Mon, Jan 15, 2018 at 05:46:24PM +0100, Martin Wilck wrote:
> > On Mon, 2018-01-15 at 17:26 +0100, Julian Andres Klode wrote:
> > > On Mon, Jan 15, 2018 at 05:12:10PM +0100, Martin Wilck wrote:
> > > > On Mon, 2018-01-15 at 16:44 +0100, Julian Andres Klode wrote:
> > > > > 
> > > > > It was your commit that made it imply -n that caused the test
> > > > > failure
> > > > > :)
> > > > > I understand your position on that, but reverted it for
> > > > > Ubuntu,
> > > > > because,
> > > > > while it might be somewhat broken, it's at least the same
> > > > > level
> > > > > of
> > > > > broken
> > > > > as before.
> > > > 
> > > > I'd like to understand that better. Why would this break boot?
> > > 
> > > Ah sorry for the confusion. It did not break boot. Having finding
> > > disabled would have "broken" boot. The problem I was talking
> > > about
> > > was that with finding enabled, no dm devices were generated,
> > > which
> > > it turned out, was not entirely true - you had to run multipath
> > > manually (due to your find implies -n commit). 
> > > 
> > > It seems to me that this would cause more issues in practice than
> > > just keeping the slightly race-y combination enabled. It's
> > > something
> > > to revisit after the ubuntu lts when then people have some time
> > > to
> > > adjust to that change.
> > 
> > I wouldn't call it "slightly race-y". With find_multipaths "on" and
> > "ignore_wwids" "off", "multipath -u" classifies every device as a
> > multipath device. So SYSTEMD_READY=0 will be set on each device.
> > But
> > multipathd, which is responsible for actually setting up the map,
> > will
> > honor "find_multipaths", and will not set up a map for a device it
> > finds only a single path for. So the device never appears in a
> > state in
> > which systemd would be able to use it. Unless you've put in some
> > other
> > magic, this is almost guaranteed to make your system unbootable in
> > the
> > quite common case where people using multipath are running off a
> > non-
> > multipathed local root disk.
> 
> RedHat also removes your patches to force ignore_wwids off and imply
> -n
> 
> 64e27ec066a001012f44550f095c93443e91d845
> ffbb886a8a16cb063d669cd76a1e656fd3ec8c4b
> 
> I don't see any why that this could claim all the devices and render
> a
> system unbootable. First off, I assume you mean that there is a
> problem
> with find_multipaths "on" and ignore_wwids "on", since your patch
> forces
> ignore_wwids "off", and with that setting, mutipath will obviously
> only
> claim devices in the wwids file.

OK, you're right. I was confused by the double negation, once more :-/
So my statement above was incorrect, sorry everyone.

> [...]
> 
> So you only classify a device as a multipath device, if either:
> 
> 1. you find multiple devices with the same WWID. That's what the
>    (VECTOR_SIZE(pathvec) > 1) check after the filter_pathvec() call
>    does.
> 
> 2. You find that the device is already part of a multipath device.
>    That's what the (VECTOR_SIZE(curmp) != 0) after the get_dm_mpvec()
>    call does.

My argument from ffbb886 still applies. You classify the first path as
non-multipath, and subsequent paths as multipath. If systemd is in the
game, it seems highly likely to me that this will cause havoc, because
I'd expect it to grab the first path immediately after it's processed. 

In general, I strongly dislike the fact that subsequent events for the
same device get opposite results. It just doesn't feel right.

On practical terms, for users who have root on non-multipath and don't
care about blacklisting, this logic results in desired behavior. That's
good.

But with root on multipath, I expect this to cause trouble. What are
you doing to avoid the root FS being mounted before it can be
multipathed? I guess you can get away with it with root on xfs or ext4,
because the only problem you have is a non-multipathed root FS. With
root on BTRFS and subvolumes for /usr, /var, etc (as is the default on
SUSE), you'll run into emergency mode because the latter can't be
mounted.

Note that since d7188fcd, multipathd is started after "udev settle"
during boot. Thus it isn't available for picking up events while the
first devices are processed. That makes it almost certain that systemd
will grab the first path (without SYSTEMD_READY=0) for mounting root.

> This code is actually more stingy with allowing devices to be claimed
> as
> multipath devices than it could safely be.  Even though ignore_wwids
> is
> set, it should probably also allow devices that are in the wwids
> file,
> since they are multipath-able. The idea of ignore_wwids is to be more
> generous in accepting devices, but by disallowing devices even if
> they
> are in the wwids file, it is being less generous in some cases. 

I didn't realize this so far. I agree that it might be better to allow
devices from the wwids file, too.

> As for implying -n with find_multipaths, my personal opinion is that
> it
> breaks the main point of find_multipaths, which is to make stuff
> "just
> work". Since RedHat has been running with find_multipaths as the
> default
> for years now, I am well aware of the race-y issue. But in practice
> it's not very bad.
> 
> Here is how I see it. The first time a multipathable device appears,
> the
> udev rules will not claim the first path of it. Multipathd will also
> not
> immediately create a multipath device on top of it.  This means that
> something else could auto set-up on it.  The most likely way this can
> happen is if you are adding new storage that already has LVM/MD
> metadata
> on it.  
> lvm will auto-activate on that new path, making multipath unable
> to create the multipath device.
> 
> If you think that sounds like a big problem, you should consider that
> if
> you use the default multipath udev rules, the exact same problem
> happens
> if you don't use find_multipaths as well. That's because when we
> check
> if multipath can claim a device, we don't call multipath -u with -i.

At SUSE, we apply a patch that adds the "-i" flag to the "multipath -u
call" in the udev rules. By default, we treat all non-blacklisted
devices as multipath devices. That's why ffbb886 "ignore -i if
find_multipaths is set" is handy for SUSE - it avoids the non-
deterministic behavior with both "find_multpaths" and "ignore_wwids".

Unless I'm mistaken, the configuration with "find_multipaths=on" and
"ignore_wwids=on" would only matter in practice if "-i" was added to
the rules (as SUSE does) *and* ffbb886 is backed out (as Red Hat does,
and apparently Ubuntu, too). No big distro seems to do it that way by
default, apparently. But OTOH, no big distro is using the current
upstream conventions, either.

> This actually can save thoughtless users some headaches.  If they
> aren't
> using find_multipaths, and they don't setup their blacklisting
> correctly, multipath still won't claim devices that are already in
> use
> when it starts up, because it will never create a multipath device on
> them, so it will never add their wwid to the wwids file.

Am I mistaken, or did you just present an argument for not using (aka
"ignoring") "-i" with find_multipath? :-)

> So in short, the problem (which currently effects multipath
> regardless
> of whether find_multipaths is set) is that when new storage is added,
> if
> that new storage already has metadata on it that the system will use
> to
> autoassemble something else on top of the device (in practice this
> means
> lvm/md metadata), you may autoassemble the wrong thing on the device.
> It's a race, and yes, find-multipaths is more likely to lose the race
> because it can't start assembling until the second path appears.
> The solution is to simply remove the lvm/dm device, and run
> multipath,
> and from then on, you will never see the problem again.

If this was the only issue, I wouldn't see any reason to argue. I'm
fairly sure that I made the two patches in question in order to
fix some really nasty boot issues. That was almost a year ago, so I
need to double-check. If neither Red Hat nor Ubuntu are seeing severe
problems, maybe those hangs in the past were caused by something else.

> The only bug I have ever received about this issue was because
> anaconda
> (the redhat system installer) knew that multipath was supposed to be
> running on a device, but couldn't disassemble the lvm device that got
> automatically created, because of the old meta-data. The solution is
> to
> make anaconda smarter.
> 
> As a side note, RedHat also adds code to automatically fire off a
> change
> uevent on all the path devices on the first time a multipath device
> is
> created, so that all the path devices get correctly claimed by
> multipath
> after the fact, on the first create. It's currently part of the same
> patch that reverts the two commits listed above, but I have no
> problem
> with posting it as a seperate patch. 

That sounds interesting, although I don't see how it would help once
systemd has grabbed the first path.

> I obviously have no problem with
> reverting those two commits upstream either. But I don't feel
> horribly
> burdened with carrying them as RedHat patches.

No problem for me to carry 64e27ec and ffbb886 as SUSE-patches, either.
It's not optimal that the current upstream code represents a mixture of
various distro patches that no distro is actually using. We should
agree on one approach for upstream.

So either we should revert 64e27ec (and maybe ffbb886, too, but I'm not
yet convinced), and add your "fire off change uevent" patch (take the
"Red Hat / Ubuntu approach"), or we should add "-i" to the multipath
call in the udev rules ("SUSE approach"). I'm fine with both.

Regards,
Martin

-- 
Dr. Martin Wilck <mwilck@suse.com>, Tel. +49 (0)911 74053 2107
SUSE Linux GmbH, GF: Felix Imendörffer, Jane Smithard, Graham Norton
HRB 21284 (AG Nürnberg)

--
dm-devel mailing list
dm-devel@redhat.com
https://www.redhat.com/mailman/listinfo/dm-devel

^ permalink raw reply	[flat|nested] 22+ messages in thread

* Re: multipath-tools 0.7.4 failure to remove device
  2018-01-16 20:30               ` Benjamin Marzinski
  2018-01-16 22:05                 ` Xose Vazquez Perez
  2018-01-17  0:43                 ` Martin Wilck
@ 2018-01-17  9:38                 ` Julian Andres Klode
  2018-01-17 18:45                   ` Benjamin Marzinski
  2018-01-17 16:27                 ` Multipath path classification revisited Martin Wilck
  3 siblings, 1 reply; 22+ messages in thread
From: Julian Andres Klode @ 2018-01-17  9:38 UTC (permalink / raw)
  To: Benjamin Marzinski; +Cc: Guan Junxiong, Martin Wilck, development mailing list

On Tue, Jan 16, 2018 at 02:30:46PM -0600, Benjamin Marzinski wrote:
> On Mon, Jan 15, 2018 at 05:46:24PM +0100, Martin Wilck wrote:
> > On Mon, 2018-01-15 at 17:26 +0100, Julian Andres Klode wrote:
> > > On Mon, Jan 15, 2018 at 05:12:10PM +0100, Martin Wilck wrote:
> > > > On Mon, 2018-01-15 at 16:44 +0100, Julian Andres Klode wrote:
> > > > > 
> > > > > It was your commit that made it imply -n that caused the test
> > > > > failure
> > > > > :)
> > > > > I understand your position on that, but reverted it for Ubuntu,
> > > > > because,
> > > > > while it might be somewhat broken, it's at least the same level
> > > > > of
> > > > > broken
> > > > > as before.
> > > > 
> > > > I'd like to understand that better. Why would this break boot?
> > > 
> > > Ah sorry for the confusion. It did not break boot. Having finding
> > > disabled would have "broken" boot. The problem I was talking about
> > > was that with finding enabled, no dm devices were generated, which
> > > it turned out, was not entirely true - you had to run multipath
> > > manually (due to your find implies -n commit). 
> > > 
> > > It seems to me that this would cause more issues in practice than
> > > just keeping the slightly race-y combination enabled. It's something
> > > to revisit after the ubuntu lts when then people have some time to
> > > adjust to that change.
> > 
> > I wouldn't call it "slightly race-y". With find_multipaths "on" and
> > "ignore_wwids" "off", "multipath -u" classifies every device as a
> > multipath device. So SYSTEMD_READY=0 will be set on each device. But
> > multipathd, which is responsible for actually setting up the map, will
> > honor "find_multipaths", and will not set up a map for a device it
> > finds only a single path for. So the device never appears in a state in
> > which systemd would be able to use it. Unless you've put in some other
> > magic, this is almost guaranteed to make your system unbootable in the
> > quite common case where people using multipath are running off a non-
> > multipathed local root disk.
> 
> RedHat also removes your patches to force ignore_wwids off and imply -n
> 
> 64e27ec066a001012f44550f095c93443e91d845
> ffbb886a8a16cb063d669cd76a1e656fd3ec8c4b

I only see you reverting the former, in  

  0013-RH-trigger-change-uevent-on-new-device-creation.patch


> As a side note, RedHat also adds code to automatically fire off a change
> uevent on all the path devices on the first time a multipath device is
> created, so that all the path devices get correctly claimed by multipath
> after the fact, on the first create. It's currently part of the same
> patch that reverts the two commits listed above, but I have no problem
> with posting it as a seperate patch. I obviously have no problem with
> reverting those two commits upstream either. But I don't feel horribly
> burdened with carrying them as RedHat patches.

I like that patch, that sounds like a good idea.

-- 
debian developer - deb.li/jak | jak-linux.org - free software dev
ubuntu core developer                              i speak de, en

^ permalink raw reply	[flat|nested] 22+ messages in thread

* Multipath path classification revisited
  2018-01-16 20:30               ` Benjamin Marzinski
                                   ` (2 preceding siblings ...)
  2018-01-17  9:38                 ` Julian Andres Klode
@ 2018-01-17 16:27                 ` Martin Wilck
  2018-01-18 22:35                   ` Benjamin Marzinski
  3 siblings, 1 reply; 22+ messages in thread
From: Martin Wilck @ 2018-01-17 16:27 UTC (permalink / raw)
  To: Benjamin Marzinski
  Cc: Julian Andres Klode, Guan Junxiong, development mailing list

Here's an attempt to write down the issue from ground up. Let me know
if I've missed, or if you disagree with, anything in this document.

**TL;DR:** Please scroll down to the "Recommendations" section.

# The goal

The goal is to make good decisions whether a given path is part of a multipath
map, and make multipath setup "just work". This implies:

 * (Mandatory) multipathing must not harm system stability.

   - Entering emergency mode because a wrong multipath classification must be
     avoided. 
   - Multipath activation shouldn't cause devices or filesystems to
     be undetected, even if they're not required for booting (unless these file
     systems are marked "nofail", emergency mode will be entered anyway).
 
 * (Important) Known devices that are reachable via multiple paths should be
    detected and set up correctly under multipath. It should be avoided that only
    a single path is used for such devices.

 * (Nice-to-have) Newly added devices should classified correctly.

# Blacklisting

The historical approach to the problem has been blacklisting. Users are
supposed to set the list of paths to be multipathed using blacklist and
blacklist exceptions. This works well if done properly.

Unfortunately, getting the blacklist right is not so easy, in particular if it
has to be done on many hosts, and thus I'll restrict the discussion from now
on to a setup without explicit blacklisting by the user. Furthermore, I'll
consider only setups using systemd.

# Critical points in the code flow

There are four places where paths are considered for multipathing:

 - `multipath -u` call in udev rules in initramfs,
 - multipathd in initramfs,
 - `multipath -u` call after switching root,
 - multipathd after switching root.

# Avoiding errors

It's simple: in order to avoid boot errors of the "mandatory"
category, we must make sure that the results for all four points above are the
same, for all paths to a given device. If the classifications differ, various
kinds of problems may arise, from hard-to-even-notice to fatal.

# Agreement between initramfs and booted system

This is also quite simple:

   **Ensure identical configuration between root fs and initrd.**

`multipath.conf`, `config_dir` contents, `wwids` file, udev rules, and command
line parameters have to be equal between initramfs and root FS. Moreover, all
relevant kernel modules 
need to be available and loaded early in initramfs (before uevent processing),
to avoid errors caused by missing drivers. Also, multipathd service/socket must
be enabled both in root and initrd.

Unfortunately, that __puts the burden on the user__. He must recreate the initrd
whenever any of the above changes. We have no means to enforce that. One might
consider making the multipath configuration files read-only and creating a
tool such as `visudo` that would recreate the initrd after every change, but
that would be a future project and might not be appreciated by users.

The above needs to be taken with a grain of salt, obviously only few config
parameters and command line options have an effect on path classification:

 - blacklist and blacklist exceptions
 - `find_multipaths` 
 - options related to WWID detection, `uid_attrs` etc.
 - `-i` option to multipath (`ignore_wwids`)
 - `-n` option to multipathd (`ignore_new_devs`)
 - `wwids`

## non-multipathed root

An exception to the rule in the previous section is the use case where only
data partitions (no disks required to boot the root FS) are multipathed. In
this case it's sufficient to make sure that multipathing is off during initrd
processing, and that, after switching root, the root device isn't falsely
classied as multipath member. The latter can be achieved in various ways:

 - blacklisting
 - find_multipaths
 - not using "ignore_wwids" in udev rules

If either of these is used, it actually doesn't matter whether multipath is
kept out of the initrd or the "equal configuration" rule is followed.

# Agreement between "multipath -u" and multipathd

This is where it gets tricky, because configuration and timing matter.
multipath and multipathd share most of the configuration, so unless
the configuration is modified between the runs of the two executables, we can
focus on just a few parameters.

## find_multipaths=off

This case is quite simple:

**"`ignore_wwids`" should be used if and only if "ignore_new_devs" is not**

 1. `ignore_new_devs`=off and `ignore_wwids`=on: all paths will be treated as multipath
    devices by both multipathd and multipath -u.
 2. `ignore_new devs`=on and `ignore_wwids`=off: both multipath and multipathd will
    only consider paths with WWIDs in the wwids file.

Unfortunately, the current upstream default is `ignore_new_devs` off and
`ignore_wwids` off, which is almost certain to lead to trouble.

Option 1. is the current SUSE approach.

## find_multipaths=on

The simple case, again, is

 3. ignore_new devs=on and `ignore_wwids`=off: this behaves like 2.
    above. Users  must explicitly add WWIDs in order to have them multipathed.

If `ignore_new_devs`=off, multipathd will try to set up a map for a WWID if and
only if

 - a) it sees more than one path to the WWID, or
 - b) the WWID is referenced in the wwids file.

Setting up the map may fail if one or more paths have already been opened
otherwise (by FS mounts, LVM, MD, whatever), which can happen if the path was
classified as non-multipath before.

If `ignore_wwids`=on, multipath -u will classify a path as multipath member if
 and only if

 - c) it sees more than one path to the WWID, or
 - d) there is already a multipath map referencing the path.

"multipath -u" sees paths before multipathd during udev rule processing, so
d) matters only in the root FS after a map may have been set up
in initramfs already. Anyway, d) is an important difference to the behavior of
multipathd, because multipathd (currently, as of 0.7.4) has no such
logic. Vice versa, the logic of b) isn't followed by `multipath -u`.

If we insist that multipath  and multipathd come to the same conclusion about
a given path at in a given situation, it follows that only 3. above is valid.
This is what the past patches 64e27ec and ffbb886 enforce.

It's obvious that `ignore_new_devs` and `ignore_wwids` should neither both be
"on" nor "off". In both cases the applied logic would be just too different, agreement
would be by coincidence only.

### ignore_new_devs=off+ignore_wwids=on

Most of this can be fixed by adding case d) to the logic of multipathd, and b) to
the logic of multipath.

What remains is the question of paths being detected one at a time. If we fix
b), we can focus on the case where the WWID is not in the wwids file.

The first `multipath -u` invocation for a given WWID is guaranteed to yield
"non multipath" (only one visible path). Once multipathd gets to see this
path, the situation may already have changed, because additional paths may
have been detected in the meantime. Follow-up invocations of `multipath -u`
will also see several paths.

Red Hat already has a patch that generates a change event on all paths when
multipathd creates a map. When this event is processed, `multipath -u` will
see the existing map and (re-)classify the paths as multipath members.

The problematic case arises when the first uevent is processed by systemd, as
it will not have `SYSTEMD_READY=0` set. If some other service such as LVM grabs
the device at this point, subsequent attempts to create a multipath map will
fail. If it's DM, the `reassign_maps` option may come to rescue. But if someting
else (MD, mounted file system or swap, you name it) grabbed the device, that's
impossible. As we currently start multipathd pretty late in the boot cycle,
it's highly likely that this problem occurs if the device in question contains
meta data that is recognized by higher layers.

Here's an idea how to fix this: When a path is first encountered, and
`ignore_new_devs`=off+`ignore_wwids`=on, udev rules set a certain property
(e.g. `DM_MULTIPATH_DEVICE_PATH==2`), set `SYSTEMD_READY=0`, and use **systemd-run**
to create a timer that will fire a change event for the same path
at a certain point in time. For that we need a new config option.

multipathd treats this path as orphan, until additional paths show up,
in which case it will create a map as usual. Nothing special here.

When the timer fires, either the map will have been set up, or multipath will
see that it's being invoked for the second time, and proceed with SYSTEMD_READY=1.

# Recommendation

The command line options `multipath -i` and `multipathd -n` should be
deprecated and replaced by a config option shared between multipath and
multipathd. As the double negation ("unset ignore_wwids") is sort of
irritating, I propose something like `force_wwids`. This option, if set, would
imply `ignore_new_devs`=on and `ignore_wwids`=off; otherwise, the contrary.
The default value of `force_wwids` would be "off". In that case, multipath and
multipathd should apply exactly the same logic (a), b), d) above).

Finally, the idea outlined in the previous section, or maybe something better,
should be implemented. And, maybe, we can come up with a user-friendly scheme
to make sure that multipath configuration between initramfs and root FS is in
agreement.

-- 
Dr. Martin Wilck <mwilck@suse.com>, Tel. +49 (0)911 74053 2107
SUSE Linux GmbH, GF: Felix Imendörffer, Jane Smithard, Graham Norton
HRB 21284 (AG Nürnberg)

--
dm-devel mailing list
dm-devel@redhat.com
https://www.redhat.com/mailman/listinfo/dm-devel

^ permalink raw reply	[flat|nested] 22+ messages in thread

* Re: multipath-tools 0.7.4 failure to remove device
  2018-01-17  0:43                 ` Martin Wilck
@ 2018-01-17 18:38                   ` Benjamin Marzinski
  2018-01-18  3:50                     ` Benjamin Marzinski
  0 siblings, 1 reply; 22+ messages in thread
From: Benjamin Marzinski @ 2018-01-17 18:38 UTC (permalink / raw)
  To: Martin Wilck; +Cc: Julian Andres Klode, Guan Junxiong, development mailing list

On Wed, Jan 17, 2018 at 01:43:47AM +0100, Martin Wilck wrote:
> On Tue, 2018-01-16 at 14:30 -0600, Benjamin Marzinski wrote:
> > On Mon, Jan 15, 2018 at 05:46:24PM +0100, Martin Wilck wrote:
> > > On Mon, 2018-01-15 at 17:26 +0100, Julian Andres Klode wrote:
> > > > On Mon, Jan 15, 2018 at 05:12:10PM +0100, Martin Wilck wrote:
> > > > > On Mon, 2018-01-15 at 16:44 +0100, Julian Andres Klode wrote:
> > So you only classify a device as a multipath device, if either:
> > 
> > 1. you find multiple devices with the same WWID. That's what the
> >    (VECTOR_SIZE(pathvec) > 1) check after the filter_pathvec() call
> >    does.
> > 
> > 2. You find that the device is already part of a multipath device.
> >    That's what the (VECTOR_SIZE(curmp) != 0) after the get_dm_mpvec()
> >    call does.
> 
> My argument from ffbb886 still applies. You classify the first path as
> non-multipath, and subsequent paths as multipath. If systemd is in the
> game, it seems highly likely to me that this will cause havoc, because
> I'd expect it to grab the first path immediately after it's processed. 
> 
> In general, I strongly dislike the fact that subsequent events for the
> same device get opposite results. It just doesn't feel right.
> 
> On practical terms, for users who have root on non-multipath and don't
> care about blacklisting, this logic results in desired behavior. That's
> good.
> 
> But with root on multipath, I expect this to cause trouble. What are
> you doing to avoid the root FS being mounted before it can be
> multipathed? I guess you can get away with it with root on xfs or ext4,
> because the only problem you have is a non-multipathed root FS. With
> root on BTRFS and subvolumes for /usr, /var, etc (as is the default on
> SUSE), you'll run into emergency mode because the latter can't be
> mounted.
> 
> Note that since d7188fcd, multipathd is started after "udev settle"
> during boot. Thus it isn't available for picking up events while the
> first devices are processed. That makes it almost certain that systemd
> will grab the first path (without SYSTEMD_READY=0) for mounting root.

Ah, so it seems our disagreement here boils down to the fact that SUSE
adds -i to the mutipath -u call in the udev rules. Clearly, if we aren't
using "multipath -iu" to determine if a path should be claimed in udev,
none of the above applies.

> > This code is actually more stingy with allowing devices to be claimed
> > as
> > multipath devices than it could safely be.  Even though ignore_wwids
> > is
> > set, it should probably also allow devices that are in the wwids
> > file,
> > since they are multipath-able. The idea of ignore_wwids is to be more
> > generous in accepting devices, but by disallowing devices even if
> > they
> > are in the wwids file, it is being less generous in some cases. 
> 
> I didn't realize this so far. I agree that it might be better to allow
> devices from the wwids file, too.
> 
> > As for implying -n with find_multipaths, my personal opinion is that
> > it
> > breaks the main point of find_multipaths, which is to make stuff
> > "just
> > work". Since RedHat has been running with find_multipaths as the
> > default
> > for years now, I am well aware of the race-y issue. But in practice
> > it's not very bad.
> > 
> > Here is how I see it. The first time a multipathable device appears,
> > the
> > udev rules will not claim the first path of it. Multipathd will also
> > not
> > immediately create a multipath device on top of it.  This means that
> > something else could auto set-up on it.  The most likely way this can
> > happen is if you are adding new storage that already has LVM/MD
> > metadata
> > on it.  
> > lvm will auto-activate on that new path, making multipath unable
> > to create the multipath device.
> > 
> > If you think that sounds like a big problem, you should consider that
> > if
> > you use the default multipath udev rules, the exact same problem
> > happens
> > if you don't use find_multipaths as well. That's because when we
> > check
> > if multipath can claim a device, we don't call multipath -u with -i.
> 
> At SUSE, we apply a patch that adds the "-i" flag to the "multipath -u
> call" in the udev rules. By default, we treat all non-blacklisted
> devices as multipath devices. That's why ffbb886 "ignore -i if
> find_multipaths is set" is handy for SUSE - it avoids the non-
> deterministic behavior with both "find_multpaths" and "ignore_wwids".
> 
> Unless I'm mistaken, the configuration with "find_multipaths=on" and
> "ignore_wwids=on" would only matter in practice if "-i" was added to
> the rules (as SUSE does) *and* ffbb886 is backed out (as Red Hat does,
> and apparently Ubuntu, too). No big distro seems to do it that way by
> default, apparently. But OTOH, no big distro is using the current
> upstream conventions, either.

Yeah. The reason I added the -i code in the first place was to allow
anaconda (the RHEL system installer) a way to determine what devices
should be multipathable. It is called by the program after the system
has booted and all devices are discovered. Anaconda doesn't actually use
it anymore, but I would still like there to be a command to let users
find out what devices should be multipath-able, recardless of whether
they have been multipathed before. That is what I see "-i" as being for.

> > This actually can save thoughtless users some headaches.  If they
> > aren't
> > using find_multipaths, and they don't setup their blacklisting
> > correctly, multipath still won't claim devices that are already in
> > use
> > when it starts up, because it will never create a multipath device on
> > them, so it will never add their wwid to the wwids file.
> 
> Am I mistaken, or did you just present an argument for not using (aka
> "ignoring") "-i" with find_multipath? :-)

Again, We don't use -i with udev. I want it solely to help users gather
information (what devices could be multipathed, not which are).

> > So in short, the problem (which currently effects multipath
> > regardless
> > of whether find_multipaths is set) is that when new storage is added,
> > if
> > that new storage already has metadata on it that the system will use
> > to
> > autoassemble something else on top of the device (in practice this
> > means
> > lvm/md metadata), you may autoassemble the wrong thing on the device.
> > It's a race, and yes, find-multipaths is more likely to lose the race
> > because it can't start assembling until the second path appears.
> > The solution is to simply remove the lvm/dm device, and run
> > multipath,
> > and from then on, you will never see the problem again.
> 
> If this was the only issue, I wouldn't see any reason to argue. I'm
> fairly sure that I made the two patches in question in order to
> fix some really nasty boot issues. That was almost a year ago, so I
> need to double-check. If neither Red Hat nor Ubuntu are seeing severe
> problems, maybe those hangs in the past were caused by something else.

If you use -i in your udev rules, then with find_multipaths enabled, you
will run into the issue where multipath will not claim the first path
(and this will happen every time, not just the first time mutipath sees
a device, because like I mentioned above, when -i is used, we don't
allow devices just beacuase the are in the wwids file). Then, when
multipathd does create the device (and it will try immediately if the
device is in the wwids file), it can race with whoever is using it. Once
a second path has appeared, the next time a change event happens on the
first path, it will get claimed by multipath, and set to not ready, and
udev will remove the path's partition devices. I can see how this would
cause a lot of boot issues.

> > The only bug I have ever received about this issue was because
> > anaconda
> > (the redhat system installer) knew that multipath was supposed to be
> > running on a device, but couldn't disassemble the lvm device that got
> > automatically created, because of the old meta-data. The solution is
> > to
> > make anaconda smarter.
> > 
> > As a side note, RedHat also adds code to automatically fire off a
> > change
> > uevent on all the path devices on the first time a multipath device
> > is
> > created, so that all the path devices get correctly claimed by
> > multipath
> > after the fact, on the first create. It's currently part of the same
> > patch that reverts the two commits listed above, but I have no
> > problem
> > with posting it as a seperate patch. 
> 
> That sounds interesting, although I don't see how it would help once
> systemd has grabbed the first path.

It can't stop something automated from using the path before multipathd
creates a device the first time it sees new storage. The race is still
there, and users still have to remove the lvm device or whatever it was
that got autoassembled (it's not usually a filesystem, since people
don't generally update their fstab to automount new storage before
connecting it for the first time) and then run mutipath. But the
majority of the time that people connect new storage, nothing will
autoassemble on top of it. And in this case, mutipath will update the
udev database so that all the new paths are claimed before any manual
setup is run on the new storage.  And like I said, I've only ever gotten
one bug for this.
 
> > I obviously have no problem with
> > reverting those two commits upstream either. But I don't feel
> > horribly
> > burdened with carrying them as RedHat patches.
> 
> No problem for me to carry 64e27ec and ffbb886 as SUSE-patches, either.
> It's not optimal that the current upstream code represents a mixture of
> various distro patches that no distro is actually using. We should
> agree on one approach for upstream.
> 
> So either we should revert 64e27ec (and maybe ffbb886, too, but I'm not
> yet convinced), and add your "fire off change uevent" patch (take the
> "Red Hat / Ubuntu approach"), or we should add "-i" to the multipath
> call in the udev rules ("SUSE approach"). I'm fine with both.

Like I said, none of the RedHat multipath rules use -i, and neither does
anaconda anymore, so it's not essential. But I'd like it to be around to
help users gather information about their devices.

-Ben
 
> Regards,
> Martin
> 
> -- 
> Dr. Martin Wilck <mwilck@suse.com>, Tel. +49 (0)911 74053 2107
> SUSE Linux GmbH, GF: Felix Imendörffer, Jane Smithard, Graham Norton
> HRB 21284 (AG Nürnberg)

^ permalink raw reply	[flat|nested] 22+ messages in thread

* Re: multipath-tools 0.7.4 failure to remove device
  2018-01-17  9:38                 ` Julian Andres Klode
@ 2018-01-17 18:45                   ` Benjamin Marzinski
  0 siblings, 0 replies; 22+ messages in thread
From: Benjamin Marzinski @ 2018-01-17 18:45 UTC (permalink / raw)
  To: Julian Andres Klode; +Cc: Guan Junxiong, Martin Wilck, development mailing list

On Wed, Jan 17, 2018 at 10:38:42AM +0100, Julian Andres Klode wrote:
> On Tue, Jan 16, 2018 at 02:30:46PM -0600, Benjamin Marzinski wrote:
> > 
> > RedHat also removes your patches to force ignore_wwids off and imply -n
> > 
> > 64e27ec066a001012f44550f095c93443e91d845
> > ffbb886a8a16cb063d669cd76a1e656fd3ec8c4b
> 
> I only see you reverting the former, in  
> 
>   0013-RH-trigger-change-uevent-on-new-device-creation.patch
> 

Oops. It appears that the other patch got lost in the shuffle of
converting over to the new git repo, and rebasing, and since nothing
uses -i anymore, its absence was never noticed.

I suppose that sort of undercuts my argument that we need to keep -i
working the way I orginally envisioned.

Thanks for noticing.

> 
> > As a side note, RedHat also adds code to automatically fire off a change
> > uevent on all the path devices on the first time a multipath device is
> > created, so that all the path devices get correctly claimed by multipath
> > after the fact, on the first create. It's currently part of the same
> > patch that reverts the two commits listed above, but I have no problem
> > with posting it as a seperate patch. I obviously have no problem with
> > reverting those two commits upstream either. But I don't feel horribly
> > burdened with carrying them as RedHat patches.
> 
> I like that patch, that sounds like a good idea.

I'll post this as an RFC, and we can sort it out along with the other
patches.

-Ben

> 
> -- 
> debian developer - deb.li/jak | jak-linux.org - free software dev
> ubuntu core developer                              i speak de, en

^ permalink raw reply	[flat|nested] 22+ messages in thread

* Re: multipath-tools 0.7.4 failure to remove device
  2018-01-17 18:38                   ` Benjamin Marzinski
@ 2018-01-18  3:50                     ` Benjamin Marzinski
  2018-01-18  8:11                       ` Martin Wilck
  0 siblings, 1 reply; 22+ messages in thread
From: Benjamin Marzinski @ 2018-01-18  3:50 UTC (permalink / raw)
  To: Martin Wilck; +Cc: Julian Andres Klode, Guan Junxiong, development mailing list

Just a bit more information about how RedHat works with multipath
claiming devices in a find_multipaths setup.

Clearly, if you have a multipathed root device, it should be in the
wwids file from the time of installation. So, multipath will
automatically claim it right away when "-i" isn't used. This should
always work fine. But like I mentioned, there is a race when new storage
is added. If that new storage is discovered in the initramfs, the race
can happen there during boot.

When -i isn't used in udev this race isn't as bad.  Usually multipathd
will lose the race to autoassemble on the device, since it can't start
until the second path has been discovered, and lvm/md can start right
away. This means that the wwid will never get in the wwids file, so
multipath will never claim any of the paths, and lvm/md will get
assembled on one path. However if multipathd wins the race and it's
close to a tie, there's a chance that lvm/md will be trying to
autoassemble on the device, and will fail because mutipath just did (or
possibly because the partition devices were removed out from under it).

Now, I don't see how this could cause a boot to fail since this is a new
device that isn't getting set up, but I really never test this, because
when we create the initramfs in RedHat based distros, we edit the
multipath.conf file in it to blacklist all devices except those needed
by the initramfs. This means that we never discover new devices in the
initramfs. In fact, we don't multipath any devices unnecessary for
booting in the initramfs. So, while I can't see a way for this new
device race to cause boot to fail when -i isn't used in udev, I must
admit that we just exclude that from ever happening, so I can't say for
certain that it would always work. Of course it's simple to avoid the
possibility of this race in the initramfs, even without editting
multipath.conf. You just start multipathd with -n in the initramfs.

-Ben

^ permalink raw reply	[flat|nested] 22+ messages in thread

* Re: multipath-tools 0.7.4 failure to remove device
  2018-01-18  3:50                     ` Benjamin Marzinski
@ 2018-01-18  8:11                       ` Martin Wilck
  2018-01-18 15:22                         ` Benjamin Marzinski
  0 siblings, 1 reply; 22+ messages in thread
From: Martin Wilck @ 2018-01-18  8:11 UTC (permalink / raw)
  To: Benjamin Marzinski
  Cc: Julian Andres Klode, Guan Junxiong, development mailing list

On Wed, 2018-01-17 at 21:50 -0600, Benjamin Marzinski wrote:

> Now, I don't see how this could cause a boot to fail since this is a
> new
> device that isn't getting set up, but I really never test this,
> because
> when we create the initramfs in RedHat based distros, we edit the
> multipath.conf file in it to blacklist all devices except those
> needed
> by the initramfs.

I'm a bit puzzled. It's against my personcal conviction that the
blacklist must be the same between initrd and root FS. How do you
prevent LVM or other layers grabbing blacklisted devices during
initramfs processing, so that they can't be multipathed any more later?

Martin

-- 
Dr. Martin Wilck <mwilck@suse.com>, Tel. +49 (0)911 74053 2107
SUSE Linux GmbH, GF: Felix Imendörffer, Jane Smithard, Graham Norton
HRB 21284 (AG Nürnberg)

--
dm-devel mailing list
dm-devel@redhat.com
https://www.redhat.com/mailman/listinfo/dm-devel

^ permalink raw reply	[flat|nested] 22+ messages in thread

* Re: multipath-tools 0.7.4 failure to remove device
  2018-01-18  8:11                       ` Martin Wilck
@ 2018-01-18 15:22                         ` Benjamin Marzinski
  2018-01-18 16:32                           ` Martin Wilck
  0 siblings, 1 reply; 22+ messages in thread
From: Benjamin Marzinski @ 2018-01-18 15:22 UTC (permalink / raw)
  To: Martin Wilck; +Cc: Julian Andres Klode, Guan Junxiong, development mailing list

On Thu, Jan 18, 2018 at 09:11:02AM +0100, Martin Wilck wrote:
> On Wed, 2018-01-17 at 21:50 -0600, Benjamin Marzinski wrote:
> 
> > Now, I don't see how this could cause a boot to fail since this is a
> > new
> > device that isn't getting set up, but I really never test this,
> > because
> > when we create the initramfs in RedHat based distros, we edit the
> > multipath.conf file in it to blacklist all devices except those
> > needed
> > by the initramfs.
> 
> I'm a bit puzzled. It's against my personcal conviction that the
> blacklist must be the same between initrd and root FS. How do you
> prevent LVM or other layers grabbing blacklisted devices during
> initramfs processing, so that they can't be multipathed any more later?

lvm only assembles on the devices necessary to boot in the initramfs
also.

-Ben

> 
> Martin
> 
> -- 
> Dr. Martin Wilck <mwilck@suse.com>, Tel. +49 (0)911 74053 2107
> SUSE Linux GmbH, GF: Felix Imendörffer, Jane Smithard, Graham Norton
> HRB 21284 (AG Nürnberg)

^ permalink raw reply	[flat|nested] 22+ messages in thread

* Re: multipath-tools 0.7.4 failure to remove device
  2018-01-18 15:22                         ` Benjamin Marzinski
@ 2018-01-18 16:32                           ` Martin Wilck
  0 siblings, 0 replies; 22+ messages in thread
From: Martin Wilck @ 2018-01-18 16:32 UTC (permalink / raw)
  To: Benjamin Marzinski
  Cc: Julian Andres Klode, Guan Junxiong, development mailing list

On Thu, 2018-01-18 at 09:22 -0600, Benjamin Marzinski wrote:
> On Thu, Jan 18, 2018 at 09:11:02AM +0100, Martin Wilck wrote:
> > On Wed, 2018-01-17 at 21:50 -0600, Benjamin Marzinski wrote:
> > 
> > > Now, I don't see how this could cause a boot to fail since this
> > > is a
> > > new
> > > device that isn't getting set up, but I really never test this,
> > > because
> > > when we create the initramfs in RedHat based distros, we edit the
> > > multipath.conf file in it to blacklist all devices except those
> > > needed
> > > by the initramfs.
> > 
> > I'm a bit puzzled. It's against my personcal conviction that the
> > blacklist must be the same between initrd and root FS. How do you
> > prevent LVM or other layers grabbing blacklisted devices during
> > initramfs processing, so that they can't be multipathed any more
> > later?
> 
> lvm only assembles on the devices necessary to boot in the initramfs
> also.

And MD? And other layers such as dm-crypt? I haven't thought it all
through, but I feel there's a lot more stuff that might grab a block
device once it appears. But hey, if that's not the case, that's good
news. The set of dracut modules is finite, so I guess it can actually
be reviewed, at least in a given distribution framework.

IIUC this requires hardcoding the WWIDs to be activated in the initrd,
which also has some disadvantages.

Anyway, making the initramfs and booted system play together nicely is
not an upstream issue for multipath-tools. I guess this will remain an
area where distributions differentiate.

Btw, I've been considering whether the dracut multipath module should
rather be maintained in multipath-tools than in dracut. It would make
certain changes easier. Opinions welcome.

Regards,
Martin

-- 
Dr. Martin Wilck <mwilck@suse.com>, Tel. +49 (0)911 74053 2107
SUSE Linux GmbH, GF: Felix Imendörffer, Jane Smithard, Graham Norton
HRB 21284 (AG Nürnberg)

--
dm-devel mailing list
dm-devel@redhat.com
https://www.redhat.com/mailman/listinfo/dm-devel

^ permalink raw reply	[flat|nested] 22+ messages in thread

* Re: Multipath path classification revisited
  2018-01-17 16:27                 ` Multipath path classification revisited Martin Wilck
@ 2018-01-18 22:35                   ` Benjamin Marzinski
  0 siblings, 0 replies; 22+ messages in thread
From: Benjamin Marzinski @ 2018-01-18 22:35 UTC (permalink / raw)
  To: Martin Wilck; +Cc: Julian Andres Klode, Guan Junxiong, development mailing list

On Wed, Jan 17, 2018 at 05:27:07PM +0100, Martin Wilck wrote:
> Here's an attempt to write down the issue from ground up. Let me know
> if I've missed, or if you disagree with, anything in this document.
> 
> **TL;DR:** Please scroll down to the "Recommendations" section.
> 
> # The goal
> 
> The goal is to make good decisions whether a given path is part of a multipath
> map, and make multipath setup "just work". This implies:
> 
>  * (Mandatory) multipathing must not harm system stability.
> 
>    - Entering emergency mode because a wrong multipath classification must be
>      avoided. 
>    - Multipath activation shouldn't cause devices or filesystems to
>      be undetected, even if they're not required for booting (unless these file
>      systems are marked "nofail", emergency mode will be entered anyway).
>  
>  * (Important) Known devices that are reachable via multiple paths should be
>     detected and set up correctly under multipath. It should be avoided that only
>     a single path is used for such devices.
> 
>  * (Nice-to-have) Newly added devices should classified correctly.
> 
> # Blacklisting
> 
> The historical approach to the problem has been blacklisting. Users are
> supposed to set the list of paths to be multipathed using blacklist and
> blacklist exceptions. This works well if done properly.
> 
> Unfortunately, getting the blacklist right is not so easy, in particular if it
> has to be done on many hosts, and thus I'll restrict the discussion from now
> on to a setup without explicit blacklisting by the user. Furthermore, I'll
> consider only setups using systemd.
> 
> # Critical points in the code flow
> 
> There are four places where paths are considered for multipathing:
> 
>  - `multipath -u` call in udev rules in initramfs,
>  - multipathd in initramfs,
>  - `multipath -u` call after switching root,
>  - multipathd after switching root.
> 
> # Avoiding errors
> 
> It's simple: in order to avoid boot errors of the "mandatory"
> category, we must make sure that the results for all four points above are the
> same, for all paths to a given device. If the classifications differ, various
> kinds of problems may arise, from hard-to-even-notice to fatal.

This may be a nit, but like I've said, I don't see this as necessary to
satisfy your "mandatory" requirements. If multipath and multipathd
classify all devices that have never been seen before as not-multipathed
in the initramfs, and then allow them after switching root, I fail to
see how this could break any of your mandatory requirements.
 
> # Agreement between initramfs and booted system
> 
> This is also quite simple:
> 
>    **Ensure identical configuration between root fs and initrd.**
> 
> `multipath.conf`, `config_dir` contents, `wwids` file, udev rules, and command
> line parameters have to be equal between initramfs and root FS. Moreover, all
> relevant kernel modules 
> need to be available and loaded early in initramfs (before uevent processing),
> to avoid errors caused by missing drivers. Also, multipathd service/socket must
> be enabled both in root and initrd.
> 
> Unfortunately, that __puts the burden on the user__. He must recreate the initrd
> whenever any of the above changes. We have no means to enforce that. One might
> consider making the multipath configuration files read-only and creating a
> tool such as `visudo` that would recreate the initrd after every change, but
> that would be a future project and might not be appreciated by users.
> 
> The above needs to be taken with a grain of salt, obviously only few config
> parameters and command line options have an effect on path classification:
> 
>  - blacklist and blacklist exceptions
>  - `find_multipaths` 
>  - options related to WWID detection, `uid_attrs` etc.
>  - `-i` option to multipath (`ignore_wwids`)
>  - `-n` option to multipathd (`ignore_new_devs`)
>  - `wwids`
> 
> ## non-multipathed root
> 
> An exception to the rule in the previous section is the use case where only
> data partitions (no disks required to boot the root FS) are multipathed. In
> this case it's sufficient to make sure that multipathing is off during initrd
> processing, and that, after switching root, the root device isn't falsely
> classied as multipath member. The latter can be achieved in various ways:
> 
>  - blacklisting
>  - find_multipaths
>  - not using "ignore_wwids" in udev rules
> 
> If either of these is used, it actually doesn't matter whether multipath is
> kept out of the initrd or the "equal configuration" rule is followed.
> 
> # Agreement between "multipath -u" and multipathd
> 
> This is where it gets tricky, because configuration and timing matter.
> multipath and multipathd share most of the configuration, so unless
> the configuration is modified between the runs of the two executables, we can
> focus on just a few parameters.
> 
> ## find_multipaths=off
> 
> This case is quite simple:
> 
> **"`ignore_wwids`" should be used if and only if "ignore_new_devs" is not**
> 
>  1. `ignore_new_devs`=off and `ignore_wwids`=on: all paths will be treated as multipath
>     devices by both multipathd and multipath -u.
>  2. `ignore_new devs`=on and `ignore_wwids`=off: both multipath and multipathd will
>     only consider paths with WWIDs in the wwids file.
> 
> Unfortunately, the current upstream default is `ignore_new_devs` off and
> `ignore_wwids` off, which is almost certain to lead to trouble.

I don't think this is as problematic as you seem to think. What is the
problem you are worried about? Obviously, it will only happen with new
devices. The problem as I see it is that multipathd will attempt to use
devices that multipath hasn't claimed. This can have one of two
outcomes:

1. Multipathd fails to create a multipath device with these devices
because they weren't claimed by udev, and someone else started using
them. This is pretty clearly only a failure of the "Nice-to-have" type.
Some other subsystem is using the device, and the udev variables reflect
that, and this is a new device.

2. Multipathd creates a multipath device using these devices, even
though it hasn't claimed the devices, and something else uses the
devices.  Due to device-mapper locking the devices, you are very limited
as to how this can happen. You can't mount a filesystem or have anything
besides device-mapper autoassemble on either the whole device or a
partition.  Other device mapper devices will be able to use the whole
device, but not the partitions (because of some quirks of kernel device
locking that I can explain if anyone is interested and doesn't feel like
reading the kernel source to see why). The only real danger that I see
is that systemd is planning on using that device for something, and
can't because multipath is. This is a real concern, but if you don't
allow new devices in your initramfs, you will guarantee the you have
gotten your regular root filesystem booted before this can ever take
place. And remember, we're talking about systemd wanting to do something
with a new device the first time it has been seen.

Here is the only scenario that I know if that fits this situation. Your
storage dies. You restore the data on a new device, and reboot.  If this
device is set up in the initramfs, then it will come up perfectly
correctly but in single-pathed mode. Assuming that "-i" correctly tells
you whether a device should be multipathed (this is what I made it for),
you run

# multipath -ic <device>

It shows you that "yes, multipath should be working on this device".
Then you run

# multipath -a <device>

to add it to the wwids file, remake your initramfs, and reboot. It's not
simplicity itself, but it's not horrible.

So the only real problem is if the device isn't mounted by the
initramfs.  In practice multipathd will almost invariably lose this
race, but if you replace a failed drive that contains no filesystems
mounted in the initramfs and does contain a filesystem directly on the
device (instead of being on LVM or MD, which will simply wait and
autoassemble on the multipath device), it is possible, I think, for
systemd to fail in boot after the switch-root because it can't mount
that filesystem.  You would need to manually mount the filesystem on the
multipath device to continue. This wouldn't occur on future boots
because the wwid will already be in the wwids file. I should point out
that I have never gotten a bug report on this.  I don't believe that
systemd is smart enough to say, "I failed using this device, but there
is another device that would also satisfy my requirements. Let me try
using it." But in theory, it could be, and this would solve the problem.

Outside of this boot race, multipath claiming a device that multipathd
doesn't use is stil bad.  multipathd using a device that multipath
hasn't claimed is much less bad.  The reason is that once multipathd
uses a device, no one else can, and even if they think they can, they
don't change the device state any.  The converse is not true.  Multipath
does change the device state when it claims a device.  This comes down
to the fact that LVM/MD present you with a different device than the one
they were assembled on (one that, for instance, no longer contains that
LVM/MD metadata). Multipath doesn't do this, it presents you with the
same device, just through a different devnode.  This is why multipath
has to do the extra work to make sure that others are using it and not
its path devices.

That is why it's so much worse to get things wrong when multipath is
running -u with -i.  When multipath claims the device, it sets it to
not ready, changes the blkid info, removes the partition devs, etc.
When lvmetad tries to autoassemble on a device and fails, it doesn't
muck with the device state.

> Option 1. is the current SUSE approach.
> 
> ## find_multipaths=on
> 
> The simple case, again, is
> 
>  3. ignore_new devs=on and `ignore_wwids`=off: this behaves like 2.
>     above. Users  must explicitly add WWIDs in order to have them multipathed.

I feel that this change will be completely non-obvious to users, since
(at least for RedHat and Ubuntu) that is not how find_multipaths has
ever worked before. And it is different from how non-find_multipaths
setups work for everyone.

> If `ignore_new_devs`=off, multipathd will try to set up a map for a WWID if and
> only if
> 
>  - a) it sees more than one path to the WWID, or
>  - b) the WWID is referenced in the wwids file.
> 
> Setting up the map may fail if one or more paths have already been opened
> otherwise (by FS mounts, LVM, MD, whatever), which can happen if the path was
> classified as non-multipath before.
> 
> If `ignore_wwids`=on, multipath -u will classify a path as multipath member if
>  and only if
> 
>  - c) it sees more than one path to the WWID, or
>  - d) there is already a multipath map referencing the path.
> 
> "multipath -u" sees paths before multipathd during udev rule processing, so
> d) matters only in the root FS after a map may have been set up
> in initramfs already. Anyway, d) is an important difference to the behavior of
> multipathd, because multipathd (currently, as of 0.7.4) has no such
> logic. Vice versa, the logic of b) isn't followed by `multipath -u`.

Is d) necessary for multipathd?  If so, then I'd say there is some other
bug. When multipathd starts up, it makes sure all of the wwids of any
existing multipath devices are in the wwids file. Whenever it creates a
new multipath device, it adds the wwid to the wwids file. If multipathd
is running and there is a multipath device without its wwid in the wwids
file, then that seems like its own bug to me. Otherwise, the check for
b) should always include the devices that a check for d) would catch. Am
I missing a case here?

I agree that mutipath should contain the logic for b).

> If we insist that multipath  and multipathd come to the same conclusion about
> a given path at in a given situation, it follows that only 3. above is valid.
> This is what the past patches 64e27ec and ffbb886 enforce.
> 
> It's obvious that `ignore_new_devs` and `ignore_wwids` should neither both be
> "on" nor "off". In both cases the applied logic would be just too different, agreement
> would be by coincidence only.

Again, if run "multipath -u" without "-i", having "ignore_new_devs" off
is only a problem in the case of new devices, and like I detailed above,
AFAIK only in one very specific and unlikely case.
 
> ### ignore_new_devs=off+ignore_wwids=on
> 
> Most of this can be fixed by adding case d) to the logic of multipathd, and b) to
> the logic of multipath.
> 
> What remains is the question of paths being detected one at a time. If we fix
> b), we can focus on the case where the WWID is not in the wwids file.
> 
> The first `multipath -u` invocation for a given WWID is guaranteed to yield
> "non multipath" (only one visible path). Once multipathd gets to see this
> path, the situation may already have changed, because additional paths may
> have been detected in the meantime. Follow-up invocations of `multipath -u`
> will also see several paths.
> 
> Red Hat already has a patch that generates a change event on all paths when
> multipathd creates a map. When this event is processed, `multipath -u` will
> see the existing map and (re-)classify the paths as multipath members.
> 
> The problematic case arises when the first uevent is processed by systemd, as
> it will not have `SYSTEMD_READY=0` set. If some other service such as LVM grabs
> the device at this point, subsequent attempts to create a multipath map will
> fail. If it's DM, the `reassign_maps` option may come to rescue. But if someting
> else (MD, mounted file system or swap, you name it) grabbed the device, that's
> impossible. As we currently start multipathd pretty late in the boot cycle,
> it's highly likely that this problem occurs if the device in question contains
> meta data that is recognized by higher layers.

So, in this case you simply have a non-multipathed device, correctly
identified in udev as such (assuming the you don't use "multipath -iu".
If you do use "-iu", you get a mess).

> Here's an idea how to fix this: When a path is first encountered, and
> `ignore_new_devs`=off+`ignore_wwids`=on, udev rules set a certain property
> (e.g. `DM_MULTIPATH_DEVICE_PATH==2`), set `SYSTEMD_READY=0`, and use **systemd-run**
> to create a timer that will fire a change event for the same path
> at a certain point in time. For that we need a new config option.
> 
> multipathd treats this path as orphan, until additional paths show up,
> in which case it will create a map as usual. Nothing special here.
> 
> When the timer fires, either the map will have been set up, or multipath will
> see that it's being invoked for the second time, and proceed with SYSTEMD_READY=1.

This is much like first approach i tried years ago when we first
integrated multipath into udev, and gave up due to corner cases and
problems with large numbers of non-multipathable device. udev has come
along way since then, and we've added systemd, and this may work better
now.  But RedHat is doing what it is doing due to the problems with
getting this method to work reliably. Also, multipath would be grabbing
every possibly-multipathable block device and holding it for a timeout.
I have a feeling that people will complain about this. For one thing,
this hold and timeout wouldn't just happen the first time multipath saw
a single-pathed device. It would happen every time.

I suppose that we could store a list of non-multipathable devices to
avoid waiting when we saw them in the future. But then, what happens if
you time out before seeing the second path, the first time you see a new
device.  It would be declared non-multipathable, and you would have to
run multipath to change that. Users sometimes having to run multipath to
get a multipath device and sometimes not would be really confusing.

> # Recommendation
> 
> The command line options `multipath -i` and `multipathd -n` should be
> deprecated and replaced by a config option shared between multipath and
> multipathd. As the double negation ("unset ignore_wwids") is sort of
> irritating, I propose something like `force_wwids`. This option, if set, would
> imply `ignore_new_devs`=on and `ignore_wwids`=off; otherwise, the contrary.
> The default value of `force_wwids` would be "off". In that case, multipath and
> multipathd should apply exactly the same logic (a), b), d) above).

If we are going to say that multipathd doesn't automatically create new
multipath devices, that is a big change. There are certainly advantages
to it, but I feel like it would require some significant version number
bumping, and a lot of explaining to users that things are going to work
differently now. It also seems like something that would be even more
important to keep consistent between dirtibutions, because it will
impact the end user, and anyone writing documentation on how to use
multipath for them. I know SUSE has been doing this for a while on
find_multipaths devices. Do you default to using find_multipaths in
SUSE, because by default RedHat creates a multipath.conf file with
find_multipaths enabled when people set up multipath?

On the other hand, saying that multipathd will automatically create new
devices, and you won't check the wwids file before claiming them is
definitely broken in the find_multipaths case. That's why you wrote
those patches in the first place.

I'm not sure that this is the right route to take.

-Ben

> Finally, the idea outlined in the previous section, or maybe something better,
> should be implemented. And, maybe, we can come up with a user-friendly scheme
> to make sure that multipath configuration between initramfs and root FS is in
> agreement.
> 
> -- 
> Dr. Martin Wilck <mwilck@suse.com>, Tel. +49 (0)911 74053 2107
> SUSE Linux GmbH, GF: Felix Imendörffer, Jane Smithard, Graham Norton
> HRB 21284 (AG Nürnberg)

^ permalink raw reply	[flat|nested] 22+ messages in thread

end of thread, other threads:[~2018-01-18 22:35 UTC | newest]

Thread overview: 22+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2018-01-12  8:38 multipath-tools 0.7.4 failure to remove device Julian Andres Klode
2018-01-12 20:35 ` Martin Wilck
2018-01-12 21:47   ` Julian Andres Klode
2018-01-12 22:18     ` Martin Wilck
2018-01-12 22:26       ` Julian Andres Klode
2018-01-15 15:44       ` Julian Andres Klode
2018-01-15 16:12         ` Martin Wilck
2018-01-15 16:26           ` Julian Andres Klode
2018-01-15 16:46             ` Martin Wilck
2018-01-16 20:30               ` Benjamin Marzinski
2018-01-16 22:05                 ` Xose Vazquez Perez
2018-01-17  0:43                 ` Martin Wilck
2018-01-17 18:38                   ` Benjamin Marzinski
2018-01-18  3:50                     ` Benjamin Marzinski
2018-01-18  8:11                       ` Martin Wilck
2018-01-18 15:22                         ` Benjamin Marzinski
2018-01-18 16:32                           ` Martin Wilck
2018-01-17  9:38                 ` Julian Andres Klode
2018-01-17 18:45                   ` Benjamin Marzinski
2018-01-17 16:27                 ` Multipath path classification revisited Martin Wilck
2018-01-18 22:35                   ` Benjamin Marzinski
2018-01-13 19:46     ` multipath-tools 0.7.4 failure to remove device Martin Wilck

This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.