faulty paths are not removed

Trying to recreate on 20.04

# enable my FC adapters
$ sudo chccwdev -e 0.0.e000
$ sudo chccwdev -e 0.0.e100

# Ensure and check I have a one minute set (default would be infinite)
$ for f in /sys/devices/css0/0.0.*/0.0.*/host*/rport-*/fc_remote_ports/rport-*/*loss_tmo; do b=$(basename $f); echo "$b : $(cat $f)"; done
dev_loss_tmo : 60
dev_loss_tmo : 60
dev_loss_tmo : 60
dev_loss_tmo : 60

An individual device right now looks like this:
mpathb (36005076306ffd6b6000000000000240a) dm-3 IBM,2107900
size=10G features='1 queue_if_no_path' hwhandler='1 alua' wp=rw
`-+- policy='service-time 0' prio=50 status=active
  |- 0:0:0:1074413604 sdc 8:32 active ready running
  |- 0:0:1:1074413604 sdh 8:112 active ready running
  |- 1:0:1:1074413604 sdr 65:16 active ready running
  `- 1:0:0:1074413604 sdm 8:192 active ready running

Then I was unmapping that on the storage server makes this

Even not "using" the disks actively I immediately see the errors on them in dmesg.

[ 4438.196385] device-mapper: multipath: Failing path 8:32.
[ 4438.205404] sd 0:0:1:1074413604: [sdh] tag#2379 FAILED Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE
[ 4438.205407] sd 0:0:1:1074413604: [sdh] tag#2379 Sense Key : Aborted Command [current]
[ 4438.205410] sd 0:0:1:1074413604: [sdh] tag#2379 Add. Sense: Logical unit not supported
[ 4438.205413] sd 0:0:1:1074413604: [sdh] tag#2379 CDB: Read(10) 28 00 01 3f ff 80 00 00 08 00
[ 4438.205416] blk_update_request: I/O error, dev sdh, sector 20971392 op 0x0:(READ) flags 0x84700 phys_seg 1 prio class 0
[ 4438.205428] device-mapper: multipath: Failing path 8:112.
[ 4438.205595] sd 1:0:1:1074413604: [sdr] tag#2933 FAILED Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE
[ 4438.205598] sd 1:0:1:1074413604: [sdr] tag#2933 Sense Key : Aborted Command [current]
[ 4438.205605] sd 1:0:1:1074413604: [sdr] tag#2933 Add. Sense: Logical unit not supported
[ 4438.205609] sd 1:0:1:1074413604: [sdr] tag#2933 CDB: Read(10) 28 00 01 3f ff 80 00 00 08 00
[ 4438.205611] blk_update_request: I/O error, dev sdr, sector 20971392 op 0x0:(READ) flags 0x84700 phys_seg 1 prio class 0
[ 4438.205617] device-mapper: multipath: Failing path 65:16.
[ 4438.205772] sd 1:0:0:1074413604: [sdm] tag#2934 FAILED Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE
[ 4438.205775] sd 1:0:0:1074413604: [sdm] tag#2934 Sense Key : Aborted Command [current]
[ 4438.205777] sd 1:0:0:1074413604: [sdm] tag#2934 Add. Sense: Logical unit not supported
[ 4438.205779] sd 1:0:0:1074413604: [sdm] tag#2934 CDB: Read(10) 28 00 01 3f ff 80 00 00 08 00
[ 4438.205781] blk_update_request: I/O error, dev sdm, sector 20971392 op 0x0:(READ) flags 0x84700 phys_seg 1 prio class 0
[ 4438.205788] device-mapper: multipath: Failing path 8:192.

And multipath immediately switched them to faulty state

mpathb (36005076306ffd6b6000000000000240a) dm-3 IBM,2107900
size=10G features='1 queue_if_no_path' hwhandler='1 alua' wp=rw
`-+- policy='service-time 0' prio=0 status=enabled
  |- 0:0:0:1074413604 sdc 8:32 failed faulty running
  |- 0:0:1:1074413604 sdh 8:112 failed faulty running
  |- 1:0:1:1074413604 sdr 65:16 failed faulty running
  `- 1:0:0:1074413604 sdm 8:192 failed faulty runni...

I'm not a 100% sure, but I wondered what "to expect" from dev_loss_tmo.
Reading more docs I think it is more like:
"I/O is held in flight, since the target might come back"
After the timeout I'd assume it will kill the remaining I/O.

This makes me think that this bug is about two things:
a) "faulty path is not removed" as reported
b) "mapping new disk to a formerly present LUN should be detected as different/new"

# Argument why (a) isn't a problem: the "paths are never going away"

And this is (as seen on the sysfs) on the rports, which are the links between local and remote FC ports. In my case for example two ports on each side doing NxM => 4 rports.

-rw-r--r-- 1 root root 4096 Jan 21 15:51 /sys/class/fc_remote_ports/rport-0:0-0/dev_loss_tmo
-rw-r--r-- 1 root root 4096 Jan 21 15:51 /sys/class/fc_remote_ports/rport-0:0-1/dev_loss_tmo
-rw-r--r-- 1 root root 4096 Jan 21 15:51 /sys/class/fc_remote_ports/rport-1:0-0/dev_loss_tmo
-rw-r--r-- 1 root root 4096 Jan 21 15:51 /sys/class/fc_remote_ports/rport-1:0-1/dev_loss_tmo

Those rports do not go down at all when I unmap the disk, as the paths are unaffected.

It more seems like kernel & multipath think "the paths are all happy and up, but something is wrong at the remote end" (which is true as we unmapped the disk). When the disk comes back everyone would expect and wan this to continue.
E.g. in my case I "mapped back" the original volume and was happy that

Mapping back the LUN:

journal:
Jan 25 08:16:46 s1lp5 kernel: sd 0:0:1:1074413604: Power-on or device reset occurred
Jan 25 08:16:46 s1lp5 kernel: sd 1:0:1:1074413604: Power-on or device reset occurred
Jan 25 08:16:46 s1lp5 kernel: sd 1:0:0:1074413604: Power-on or device reset occurred
Jan 25 08:16:46 s1lp5 kernel: sd 0:0:1:1074413604: alua: port group 00 state A preferred supports tolusnA
Jan 25 08:16:47 s1lp5 multipathd[782]: mpathb: sdh - tur checker reports path is up
Jan 25 08:16:47 s1lp5 multipathd[782]: 8:112: reinstated
Jan 25 08:16:47 s1lp5 multipathd[782]: mpathb: remaining active paths: 1
Jan 25 08:16:47 s1lp5 multipathd[782]: mpathb: sdr - tur checker reports path is up
Jan 25 08:16:47 s1lp5 multipathd[782]: 65:16: reinstated
Jan 25 08:16:47 s1lp5 multipathd[782]: mpathb: remaining active paths: 2
Jan 25 08:16:47 s1lp5 multipathd[782]: mpathb: sdm - tur checker reports path is up
Jan 25 08:16:47 s1lp5 multipathd[782]: 8:192: reinstated
Jan 25 08:16:47 s1lp5 multipathd[782]: mpathb: remaining active paths: 3
Jan 25 08:16:47 s1lp5 kernel: device-mapper: multipath: Reinstating path 8:112.
Jan 25 08:16:47 s1lp5 kernel: device-mapper: multipath: Reinstating path 65:16.
Jan 25 08:16:47 s1lp5 kernel: device-mapper: multipath: Reinstating path 8:192.
Jan 25 08:16:47 s1lp5 systemd-udevd[648]: Worker [18540] terminated by signal 9 (KILL)
Jan 25 08:16:47 s1lp5 systemd-udevd[648]: dm-3: Worker [18540] failed
Jan 25 08:16:47 s1lp5 kernel: sd 0:0:1:1074413604: alua: port group 00 state A preferred supports tolusnA
Jan 25 08:16:47 s1lp5 kernel: sd 0:0:1:1074413604: alua: port group 00 state A preferred supports tolusnA
Jan 25 08:16:48 s1lp5 dbus-daemon[1048]: [system] Activating via systemd: service name='org.freedesktop.PackageKit' unit='packagekit.service' requested by ':1.34' (uid=0 pid=983318 comm="/usr/bin/gdbus call --system --dest org.freedeskto" label="unconfined")
Jan 25 08:16:48 s1lp5 systemd[1]: Starting PackageKit Daemon...
Jan 25 08:16:48 s1lp5 PackageKit[983321]: daemon start
Jan 25 08:16:48 s1lp5 kernel: sd 0:0:0:1074413604: Power-on or device reset occurred
Jan 25 08:16:48 s1lp5 kernel: sd 0:0:0:1074413604: alua: port group 00 state A ...

# Argument why (b) might in fact a problem: "disk should be detected as new, and not mapped onto the old paths/devices"

Obviously one could just say "have a static LUN Id plan and don't map back the old LUN, but that is evasive. In a perfect world something in kernel/udev/multipath would recognize it is a new thing.

I agree that if you "map a different / new disk to the same lun" things should not totally break as you reported. I'd have expected that it would detect e.g. a UUID and only do so if these match.
Do in your case the UUIDs also stay the same when you map a new disk under the same LUN?

In my case (adding back the same disk under the same LUN) nothing changed.
For example sg_inq reports absolutely the same

$ sudo sg_inq --id /dev/sdh
VPD INQUIRY: Device Identification page
  Designation descriptor number 1, descriptor length: 20
    designator_type: NAA, code_set: Binary
    associated with the Addressed logical unit
      NAA 6, IEEE Company_id: 0x5076
      Vendor Specific Identifier: 0x306ffd6b6
      Vendor Specific Identifier Extension: 0x240a
      [0x6005076306ffd6b6000000000000240a]
  Designation descriptor number 2, descriptor length: 8
    designator_type: Relative target port, code_set: Binary
    associated with the Target port
      Relative target port: 0x130
  Designation descriptor number 3, descriptor length: 8
    designator_type: Target port group, code_set: Binary
    associated with the Target port
      Target port group: 0x0

Be careful as there are plenty of UUIDs.
The one of the FC/SCSI layer (sg_inq).

Then there could be some below on GPT and on Filesystem.
But IMHO multipath works "below" that and most likely only considers the ID of the FC/SCSI layer.
In my test my LUN was totally empty, so I had no Partition/FS UUID at all.

If your SCSI/FC UUID does not change, then I think this is mis-usage/mis-expectation. I'd be unsure what kernel/udev/multipass should do different.
But if your UUID changes, then IMHO it should work. But I wonder if "appearance of a different disk in place of a missing one" was ever considered in mutlipath. I'd ask you to start a discussion upstream [1][2] for "what to expect" and "how to handle" that case.
Please report a link to the discussion here and let us know of the outcome. No matter if it will be:
1. a different config (then everyone tracking this can benefit)
2. a patch we can fix the package(s) with
3. a lessons learned about what to expect from which component (then everyone tracking this can still benefit)

[1]: https://www.redhat.com/mailman/listinfo/dm-devel
[2]: https://github.com/opensvc/multipath-tools/issues

Bonus for my theory that these timeouts are about the paths going down and not the disks.
If I unplug the adapter (= 2 paths) it goes through this:

1. it immediately detects that something is wrong. I/O might still be queued.

Jan 25 09:27:52 s1lp5 multipathd[782]: checker failed path 65:32 in map mpatha
Jan 25 09:27:52 s1lp5 multipathd[782]: mpatha: remaining active paths: 3
Jan 25 09:27:52 s1lp5 kernel: device-mapper: multipath: Failing path 65:32.
Jan 25 09:27:53 s1lp5 multipathd[782]: checker failed path 8:176 in map mpathc
Jan 25 09:27:53 s1lp5 multipathd[782]: mpathc: remaining active paths: 3
Jan 25 09:27:53 s1lp5 multipathd[782]: checker failed path 8:160 in map mpathd
Jan 25 09:27:53 s1lp5 multipathd[782]: mpathd: remaining active paths: 3
Jan 25 09:27:53 s1lp5 kernel: device-mapper: multipath: Failing path 8:176.
Jan 25 09:27:53 s1lp5 kernel: device-mapper: multipath: Failing path 8:160.
Jan 25 09:27:54 s1lp5 multipathd[782]: checker failed path 8:208 in map mpatha
Jan 25 09:27:54 s1lp5 multipathd[782]: mpatha: remaining active paths: 2
Jan 25 09:27:54 s1lp5 multipathd[782]: checker failed path 65:48 in map mpathe
Jan 25 09:27:54 s1lp5 multipathd[782]: mpathe: remaining active paths: 3
Jan 25 09:27:54 s1lp5 multipathd[782]: checker failed path 8:240 in map mpathd
Jan 25 09:27:54 s1lp5 multipathd[782]: mpathd: remaining active paths: 2
Jan 25 09:27:54 s1lp5 multipathd[782]: checker failed path 8:224 in map mpathe
Jan 25 09:27:54 s1lp5 multipathd[782]: mpathe: remaining active paths: 2
Jan 25 09:27:54 s1lp5 multipathd[782]: checker failed path 65:0 in map mpathc
Jan 25 09:27:54 s1lp5 multipathd[782]: mpathc: remaining active paths: 2
Jan 25 09:27:54 s1lp5 kernel: device-mapper: multipath: Failing path 8:208.
Jan 25 09:27:54 s1lp5 kernel: device-mapper: multipath: Failing path 65:48.
Jan 25 09:27:54 s1lp5 kernel: device-mapper: multipath: Failing path 8:240.
Jan 25 09:27:54 s1lp5 kernel: device-mapper: multipath: Failing path 8:224.
Jan 25 09:27:54 s1lp5 kernel: device-mapper: multipath: Failing path 65:0.

state now:
mpathb (36005076306ffd6b6000000000000240a) dm-3 IBM,2107900
size=10G features='1 queue_if_no_path' hwhandler='1 alua' wp=rw
`-+- policy='service-time 0' prio=50 status=active
  |- 0:0:0:1074413604 sdc 8:32 active ready running
  |- 0:0:1:1074413604 sdh 8:112 active ready running
  |- 1:0:1:1074413604 sdr 65:16 active i/o pending running
  `- 1:0:0:1074413604 sdm 8:192 active i/o pending running

2. after the timeouts for failing I/O (fast_io_fail_tmo) all queued is cancelled

state now:
mpathb (36005076306ffd6b6000000000000240a) dm-3 IBM,2107900
size=10G features='1 queue_if_no_path' hwhandler='1 alua' wp=rw
`-+- policy='service-time 0' prio=50 status=active
  |- 0:0:0:1074413604 sdc 8:32 active ready running
  |- 0:0:1:1074413604 sdh 8:112 active ready running
  |- 1:0:1:1074413604 sdr 65:16 failed faulty running
  `- 1:0:0:1074413604 sdm 8:192 failed faulty running

3. finally once I hit my 60 second limit on the paths (dev_loss_tmo) they are considered dead

Jan 25 09:28:52 s1lp5 kernel: rport-1:0-0: blocked FC remote port time out: removing target and saving binding
Jan 25 09:28:52 s1lp...

I have also checked if this was any different in the past and checked Bionic (thanks Frank for the system). It behaved the same way (i.e. no regression).

Unmapping device:

Jan 25 05:07:15 hwe0006 kernel: sd 1:0:0:1074151462: [sdc] tag#1877 FAILED Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE
Jan 25 05:07:15 hwe0006 kernel: sd 1:0:0:1074151462: [sdc] tag#1877 Sense Key : Aborted Command [current]
Jan 25 05:07:15 hwe0006 kernel: sd 1:0:0:1074151462: [sdc] tag#1877 Add. Sense: Logical unit not supported
Jan 25 05:07:15 hwe0006 kernel: sd 1:0:0:1074151462: [sdc] tag#1877 CDB: Write(10) 2a 00 01 04 88 00 00 00 08 00
Jan 25 05:07:15 hwe0006 kernel: print_req_error: I/O error, dev sdc, sector 17074176
Jan 25 05:07:15 hwe0006 kernel: device-mapper: multipath: Failing path 8:32.
Jan 25 05:07:15 hwe0006 kernel: sd 0:0:0:1074151462: [sda] tag#2231 FAILED Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE
Jan 25 05:07:15 hwe0006 kernel: sd 0:0:0:1074151462: [sda] tag#2231 Sense Key : Aborted Command [current]
Jan 25 05:07:15 hwe0006 kernel: sd 0:0:0:1074151462: [sda] tag#2231 Add. Sense: Logical unit not supported
Jan 25 05:07:15 hwe0006 kernel: sd 0:0:0:1074151462: [sda] tag#2231 CDB: Write(10) 2a 00 01 04 88 00 00 00 08 00
Jan 25 05:07:15 hwe0006 kernel: print_req_error: I/O error, dev sda, sector 17074176
Jan 25 05:07:15 hwe0006 kernel: device-mapper: multipath: Failing path 8:0.
Jan 25 05:07:15 hwe0006 kernel: sd 1:0:1:1074151462: [sdd] tag#1877 FAILED Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE
Jan 25 05:07:15 hwe0006 kernel: sd 1:0:1:1074151462: [sdd] tag#1877 Sense Key : Aborted Command [current]
Jan 25 05:07:15 hwe0006 kernel: sd 1:0:1:1074151462: [sdd] tag#1877 Add. Sense: Logical unit not supported
Jan 25 05:07:15 hwe0006 kernel: sd 1:0:1:1074151462: [sdd] tag#1877 CDB: Write(10) 2a 00 01 04 88 00 00 00 08 00
Jan 25 05:07:15 hwe0006 kernel: print_req_error: I/O error, dev sdd, sector 17074176
Jan 25 05:07:15 hwe0006 kernel: device-mapper: multipath: Failing path 8:48.
Jan 25 05:07:15 hwe0006 kernel: sd 0:0:1:1074151462: [sdb] tag#2231 FAILED Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE
Jan 25 05:07:15 hwe0006 kernel: sd 0:0:1:1074151462: [sdb] tag#2231 Sense Key : Aborted Command [current]
Jan 25 05:07:15 hwe0006 kernel: sd 0:0:1:1074151462: [sdb] tag#2231 Add. Sense: Logical unit not supported
Jan 25 05:07:15 hwe0006 kernel: sd 0:0:1:1074151462: [sdb] tag#2231 CDB: Write(10) 2a 00 01 04 88 00 00 00 08 00
Jan 25 05:07:15 hwe0006 kernel: print_req_error: I/O error, dev sdb, sector 17074176
Jan 25 05:07:15 hwe0006 kernel: device-mapper: multipath: Failing path 8:16.
Jan 25 05:07:15 hwe0006 kernel: sd 1:0:0:1074151462: Power-on or device reset occurred
Jan 25 05:07:15 hwe0006 kernel: sd 1:0:0:1074151462: alua: port group 00 state A preferred supports tolusnA
Jan 25 05:07:15 hwe0006 kernel: sd 0:0:0:1074151462: Power-on or device reset occurred
Jan 25 05:07:15 hwe0006 kernel: sd 0:0:1:1074151462: Power-on or device reset occurred
Jan 25 05:07:15 hwe0006 kernel: device-mapper: multipath: Reinstating path 8:32.
Jan 25 05:07:15 hwe0006 kernel: sd 1:0:1:1074151462: Power-on or device reset occurred
Jan 25 05:07:15 hwe0006 multipathd[591]: s...

Yes, it was the same on 18.04 also.
The problem is that I don't reach "3. finally once I hit my 60 second limit on the paths (dev_loss_tmo) they are considered dead" . The paths are never removed and stay "running" forever. Maybe it is related to the fact that there is only one HBA active.

 Do in your case the UUIDs also stay the same when you map a new disk under the same LUN?
The udev is caching the old disk info, so all the ids should be the same. When you run sg_inq, it is checking the real values and returns the real ID. Multipath however is still using the cached wrong ids from udev.

Also when the both paths are failing and the map is flushed(as we have only one FC HBA we have only 2 paths to both controllers of the storage), it is expected the devices underneath to be removed as well. They are not removed and the map comes back on multipath reload maps.

My expectation is the paths to be removed after dev_loss_tmo. However if it is acting on the whole rport - we still have healthy paths on the both rports, so it might be actually working as expected.

Also the udev is to reluctant to rescan the readded devices because they are never removed. When a path is reinstated it should be rescanned to validate that it is in fact the same disk.
Please tell me if you need more information.

here is some logs of a failing map:
Jan 25 13:30:36 joker multipathd[2127]: 360050763808081638000000000000054: sdh - tur checker reports path is down
Jan 25 13:30:36 joker multipathd[2127]: checker failed path 8:112 in map 360050763808081638000000000000054
Jan 25 13:30:36 joker multipathd[2127]: 360050763808081638000000000000054: remaining active paths: 1
Jan 25 13:30:37 joker multipathd[2127]: sdr: mark as failed
Jan 25 13:30:37 joker multipathd[2127]: 360050763808081638000000000000054: remaining active paths: 0
Jan 25 13:30:39 joker multipathd[2127]: 360050763808081638000000000000054: sdr - tur checker reports path is down
Jan 25 13:30:41 joker multipathd[2127]: 360050763808081638000000000000054: sdh - tur checker reports path is down
Jan 25 13:30:44 joker multipathd[2127]: 360050763808081638000000000000054: sdr - tur checker reports path is down
Jan 25 13:30:46 joker multipathd[2127]: 360050763808081638000000000000054: sdh - tur checker reports path is down
Jan 25 13:30:49 joker multipathd[2127]: 360050763808081638000000000000054: sdr - tur checker reports path is down
Jan 25 13:30:51 joker multipathd[2127]: 360050763808081638000000000000054: sdh - tur checker reports path is down
Jan 25 13:30:54 joker multipathd[2127]: 360050763808081638000000000000054: sdr - tur checker reports path is down
Jan 25 13:30:56 joker multipathd[2127]: 360050763808081638000000000000054: sdh - tur checker reports path is down
Jan 25 13:30:59 joker multipathd[2127]: 360050763808081638000000000000054: sdr - tur checker reports path is down
Jan 25 13:31:01 joker multipathd[2127]: 360050763808081638000000000000054: sdh - tur checker reports path is down
Jan 25 13:31:05 joker multipathd[2127]: 360050763808081638000000000000054: sdr - tur checker reports path is down
Jan 25 13:31:07 joker multipathd[2127]: 360050763808081638000000000000054: sdh - tur checker reports path is do...

Hi,
I reordered this slightly to split into topics properly.

> The problem is that I don't reach "3. finally once I hit my 60 second limit on the paths
> (dev_loss_tmo) they are considered dead" . The paths are never removed and stay "running"
> forever. Maybe it is related to the fact that there is only one HBA active.

> My expectation is the paths to be removed after dev_loss_tmo. However if it is acting on the
> whole rport - we still have healthy paths on the both rports, so it might be actually working
> as expected.

^^ yes I think this part indeed work as expected, but I'm open to be convinced otherwise

> Also when the both paths are failing and the map is flushed(as we have only one FC HBA we have
> only 2 paths to both controllers of the storage), it is expected the devices underneath to be
> removed as well. They are not removed and the map comes back on multipath reload maps.

You saw my example on "failing paths" above which indeed seemed to remove the devices for me.
In Journal/dmesg I had:
  "rport-1:0-0: blocked FC remote port time out: removing target and saving binding"
If the port/path is down (not the LUN) then I'd expect the kernel to trigger that after dev_loss_tmo.

> udev is caching the old disk info, so all the ids should be the same. When you run sg_inq, it
> is checking the real values and returns the real ID. Multipath however is still using the
> cached wrong ids from udev.

> Also the udev is to reluctant to rescan the readded devices because they are never removed.
> When a path is reinstated it should be rescanned to validate that it is in fact the same disk.

^^ I agree to this, if indeed the UUID changed but is cached/not-rescanned that seems like an issue to me.

> Please tell me if you need more information.

I don't think "I/we" need any more here - it seems to be something that the multipath-tools don't do yet (or it could, but we both fail to see the right mix of config options to do so).

The next step to me seems to be to engage with upstream which is usually done best by the affected person. As mentioned before that would be at [1][2].
A link back to the discussion/issue would be awesome so that we can track the outcome and integrate it into Ubuntu.

[1]: https://www.redhat.com/mailman/listinfo/dm-devel
[2]: https://github.com/opensvc/multipath-tools/issues

[Expired for multipath-tools (Ubuntu) because there has been no activity for 60 days.]