[dm-devel] Disconcerting observation with multipathd's dmevent polling code

[Hannes Reinecke]

On 11/21/18 11:50 AM, Martin Wilck wrote:
> Hi Ben,
> 
> I recently encountered a strange and disturbing phenomenon with the
> latest upstream code.
> 
> The system in question had two iSCSI connections on separate networks.
> On one of them, I tested iSCSI disconnect and re-connects, and broken
> storage configurations (different LUNs diffenent sizes and with the
> same WWID). The other one was idle.
> 
> During one test, I observed that multipathd's internal representation
> of the map representing the *idle* connection had vanished. The map was
> still present on the device-mapper level, but multipathd seemed to have
> "forgotten" it completely. The respective paths were tracked as
> orphans.
> 
> Here is a log excerpt. multipathd is working on path additions for the
> map I was testing with (149455...), when a DM event is received. Right
> after ev_add_path() releases the lock, the idle map
> (36001405...) is removed (not flushed, as the messages suggest).
> 
> Nov 15 22:05:46 sles15-gm-iscsi-03 multipathd[568]: sdg: add path (uevent)
> # uev_add_path->pathinfo()
> Nov 15 22:05:46 sles15-gm-iscsi-03 multipathd[568]: sdg: udev property SCSI_IDENT_LUN_T10 whitelisted
> # ev_add_path()->adopt_paths()
> Nov 15 22:05:46 sles15-gm-iscsi-03 multipathd[568]: sde: ownership set to 149455400000000006d706174683100000000000000000000
> ...
> # ev_add_path->setup_map()
> Nov 15 22:05:46 sles15-gm-iscsi-03 multipathd[568]: 149455400000000006d706174683100000000000000000000: failback = "manual" (setting: multipath internal)
> # ev_add_path->domap()
> Nov 15 22:05:46 sles15-gm-iscsi-03 multipathd[568]: 149455400000000006d706174683100000000000000000000: load table [0 2097152 multipath 0 0 3 1 service-time 0 1 1 8:64 ...
> # ev_add_path->setup_multipath()->update-multipath_strings
> Nov 15 22:05:46 sles15-gm-iscsi-03 multipathd[568]: 149455400000000006d706174683100000000000000000000: disassemble map [0 0 3 1 service-time 0 1 2 8:64 1 1 service-time ...
> # (!!!!) devmap event for LIO map
> Nov 15 22:05:46 sles15-gm-iscsi-03 multipathd[568]: 36001405d08f748dd4c5481f9ec22b888: devmap event #20
> Nov 15 22:05:46 sles15-gm-iscsi-03 multipathd[568]: sdg [8:96]: path added to devmap 149455400000000006d706174683100000000000000000000
> # ev_add_path() returns, vecs->lock is released
> # uev_add_path() goes on to next path, lock currently not held
> Nov 15 22:05:46 sles15-gm-iscsi-03 multipathd[568]: sdh: add path (uevent)
> # (!!!!) The LIO map is flushed (36001405d08f748dd4c5481f9ec22b888)
> # this looks like remove_map() or remove_map_and_stop_waiter()
>> Nov 15 22:05:46 sles15-gm-iscsi-03 multipathd[568]: sdd: orphan path, map flushed
>> Nov 15 22:05:46 sles15-gm-iscsi-03 multipathd[568]: sysfs prioritizer refcount 2
>> Nov 15 22:05:46 sles15-gm-iscsi-03 multipathd[568]: sdc: orphan path, map flushed
> 
> To me this looks like the map was removed by the DM event handler.
> More detail can be found on
> https://bugzilla.opensuse.org/show_bug.cgi?id=1116272.
> I've also tried to reproduce the problem, with no success so far
> (actually I haven't observed any dmevents in those reproduction
> attempts).
> 
> After encountering this problem, I've scrutinized your polling dmevent
> handler code over and over last week, but I couldn't spot any possible
> problems :-)
> 
> The concern that I have is with the design of the polling dmevent API,
> in particular the fact that the default action is EVENT_REMOVE. If, for
> whatever reason, one map is missing from the return value of the
> DM_DEVICE_LIST ioctl, multipath removes the map immediately, and
> there's nothing short of a "reconfigure" or "add map" CLI command that
> would reinstate the map. IOW, we remove the map not on a kernel event
> saying "this map has been removed", but on receiving a list where this
> element happens to be missing. We handle this differently for paths,
> where we wait for a "remove" uevent before we really delete the path
> from our data structures. (Note that the messages file I saved from the
> event above shows no sign of such an uevent ever beeing sent - as I
> said, the dm map was still present after the above occured).
> 
> What do you think about this? Could you maybe inspect those logs I
> took, to make sure I didn't get on a totally wrong track here?
> 
There's an easy solution to it: drop the dmevent handling code in 
multipath-tools completely.
It's original design was to track _external_ map reloads, as originally 
the maps had been setup by 'multipath', and 'multipahtd' was just 
tracking state changes. As such multipathd needed to track those 
changes, and it had been using dmevents for this.
However, with the advent of udev and updates to the multipathd daemon 
external map reloads rarely happens, and even if they happen we still 
would be notified by uevents.
So we might as well drop the dmevent code and rely on udev completely.
Which is what we do nowadays anyway.

Cheers,

Hannes