Bug 1300453

Created attachment 1116717 [details]
Output of journalctl -b

Created attachment 1116718 [details]
Output of multipath -ll

This does not appear, at least on the surface, to be the same root cause as NTAP CQ 669667/BZ 1187403, which was caused by bad udev rules (I checked and didn't see those here)

It is a long shot, but can you try this build?
https://people.redhat.com/lnykryn/systemd-219-19.el7_2.3/

I tried the build at https://people.redhat.com/lnykryn/systemd-219-19.el7_2.3/ and am still seeing the same behavior.

This phantom unmount behavior is now being seen on other test configs, not just Ryan's.  This is endangering our upcoming program release and we would like to know what can be done to escalate this problem.  We need to find someone with some pretty deep systemd knowledge to help us understand this issue.

(In reply to Ryan from comment #1)
> Created attachment 1116717 [details]
> Output of journalctl -b

At least on my machine this looks broken, can you please reattach the log?

MIME type was incorrectly set to text.  Changed to application/zip

(In reply to Lukáš Nykrýn from comment #8)
> (In reply to Ryan from comment #1)
> > Created attachment 1116717 [details]
> > Output of journalctl -b
> 
> At least on my machine this looks broken, can you please reattach the log?

Hi Lukas,

Are you now able to view the logs that NetApp just attached? What else do you need from them to get this debugged?

Thanks!

--Chris

Can you please create debug log once again, this time using this build?
https://copr.fedorainfracloud.org/coprs/lnykryn/systemd-rhel-staging/

I've tried to simulate scenario from bug description with 4 iscsi sessions to the same LUN. However I was not able to reproduce. I was still able to access filesystems when I brought two paths offline and then back online. systemd didn't unmount anything.

Note that I was testing with newest build prepared for next z-stream batch. However it contains only couple of unrelated patches on top of https://people.redhat.com/lnykryn/systemd-219-19.el7_2.3/.

Is this reproducible on smaller setup? If yes, then it would be great to gather requested debug log on such setup.

Hi Ryan,

Can you help capture debug logs per comments 11 & 12 please?

Thanks!

--Chris

Not sure if it will reproduce with less LUNs, but I'll give it a shot and use the build mentioned by Lukáš.

One thing I should have mentioned in the description is that the issue doesn't always happen on the first down/up.  Sometimes several iterations can pass before the issue occurs.

Created attachment 1123289 [details]
Output of journalctl -b

Reproduced the issue using the build referenced by Lukáš Nykrýn.  Attaching journalctl debug log.

I'm now going to try reproducing it with less LUNs.  We are currently testing with many raw LUN and a handful of filesystem.  Going to remove the raw LUNs and see if I can reproduce with only the handful of filesystems attached.

Ryan, 

While trying to reproduce please also try to capture output of the following command,

udevadm monitor --udev --property

It will print udev event after rule processing with its properties.

I've reproduced the issue with only a single mounted LUN and filesystem.  Attaching journalctl and udevadm monitor output.

Created attachment 1123832 [details]
udevadm monitor output

udevadm monitor output while recreating with a single mount

Created attachment 1123833 [details]
journalctl output

journalctl log while recreating with a single mount

In udevadm monitor output I see following event logged 

UDEV  [94891.553203] change   /devices/virtual/block/dm-5 (block)
ACTION=change
DEVLINKS=/dev/disk/by-id/dm-name-mpathak /dev/disk/by-id/dm-uuid-mpath-360080e500029f68800008f33564b3cf2 /dev/mapper/mpathak
DEVNAME=/dev/dm-5
DEVPATH=/devices/virtual/block/dm-5
DEVTYPE=disk
DM_ACTION=PATH_FAILED
DM_MULTIPATH_TIMESTAMP=1455225500
DM_NAME=mpathak
DM_NR_VALID_PATHS=3
DM_PATH=8:80
DM_SEQNUM=488
DM_SUSPENDED=1
DM_TARGET=multipath
DM_UDEV_DISABLE_LIBRARY_FALLBACK_FLAG=1
DM_UDEV_DISABLE_OTHER_RULES_FLAG=1
DM_UDEV_PRIMARY_SOURCE_FLAG=1
DM_UDEV_RULES_VSN=2
DM_UUID=mpath-360080e500029f68800008f33564b3cf2
MAJOR=253
MINOR=5
MPATH_SBIN_PATH=/sbin
SEQNUM=9741
SUBSYSTEM=block
SYSTEMD_READY=0
TAGS=:systemd:
USEC_INITIALIZED=2538

From journal output it seems like processing of the above event was finished just before the umount attempt. Note that this event has in its environment SYSTEMD_READY=0. This basically tells systemd that if this device (/dev/dm-5) was previously announced by udev now it is not supposed to be used by systemd anymore. Thus systemd transitions this device to "dead" state and umount of dependent mount unit is triggered because of this.

When I was (unsuccessfully) trying to reproduce this bug I did not observe change events about path failure or reinstatement with following flags set.

DM_UDEV_DISABLE_OTHER_RULES_FLAG=1
SYSTEMD_READY=0

This seems like a bug in device-mapper-multipath rules. Reassigning.

Something looks wrong here.

In 10-dm.rules, DM_UDEV_DISABLE_OTHER_RULES_FLAG=1 is set when the device is suspended:

# Avoid processing and scanning a DM device in the other (foreign)
# rules if it is in suspended state. However, we still keep 'disk'
# and 'DM subsystem' related rules enabled in this case.
ENV{DM_SUSPENDED}=="1", ENV{DM_UDEV_DISABLE_OTHER_RULES_FLAG}="1"

This looks like the most likely reason why DM_UDEV_DISABLE_OTHER_RULES_FLAG is set in this case.

In 99-systemd.rules, SYSTEMD_READY=0 is set when DM_UDEV_DISABLE_OTHER_RULES_FLAG is set:

SUBSYSTEM=="block", KERNEL!="ram*", ENV{DM_UDEV_DISABLE_OTHER_RULES_FLAG}=="1", ENV{SYSTEMD_READY}="0"

So it looks like whenever a udev is processing an event on a suspended dm device, SYSTEMD_READY will be set to 0.  While it makes sense to not act on a
dm device before it is ready, once the device is up, it shouldn't be unmounted simply because it is suspended for a second.

Peter, am I missing something here?

(In reply to Ben Marzinski from comment #23)
> SUBSYSTEM=="block", KERNEL!="ram*",
> ENV{DM_UDEV_DISABLE_OTHER_RULES_FLAG}=="1", ENV{SYSTEMD_READY}="0"
> 
> So it looks like whenever a udev is processing an event on a suspended dm
> device, SYSTEMD_READY will be set to 0.  While it makes sense to not act on a
> dm device before it is ready, once the device is up, it shouldn't be
> unmounted simply because it is suspended for a second.
> 
> Peter, am I missing something here?

Yes, it's exactly like you said. I need to find out now how we're going to fix this...

So Peter, to be clear, bz1312011 is the answer here as well?

(In reply to Ryan Sawhill from comment #25)
> So Peter, to be clear, bz1312011 is the answer here as well?

Yes, after further discussion with systemd team we also tracked the history and we found out that the rule setting SYSTEMD_READY=0 got there by mistake, it seems - the rules were suppoesed to be skipped only.

See also https://github.com/systemd/systemd/commit/b7cf1b68a79833411851fa547ac9b4906207c224 which also references the https://github.com/systemd/systemd/commit/b7cf1b68a79833411851fa547ac9b4906207c224 - so we should put back this rule:

SUBSYSTEM=="block", KERNEL!="ram*", ENV{DM_UDEV_DISABLE_OTHER_RULES_FLAG}=="1", GOTO="systemd_end"

(so GOTO="systemd_end" instead of that SYSTEMD_READY=0)

I think we don't need to do anything else on dm side of rules then so we can probably close this bug and let bug #1312011 to track the issue.

(In reply to Peter Rajnoha from comment #26)
> so we should put back this rule:
> 
> SUBSYSTEM=="block", KERNEL!="ram*",
> ENV{DM_UDEV_DISABLE_OTHER_RULES_FLAG}=="1", GOTO="systemd_end"
> 
> (so GOTO="systemd_end" instead of that SYSTEMD_READY=0)
> 

Currently, the 99-systemd.rules doesn't process DM devices any further, so removing the rule completely will have the same effect.

Sorry, I overlooked one important thing! We need to make sure that the DM device is not marked as ready on ADD event. So the rule in 99-systemd.rules should be:

SUBSYSTEM=="block", ACTION=="add", ENV{DM_UDEV_DISABLE_OTHER_RULES_FLAG}=="1", ENV{SYSTEMD_READY}="0"

(I've also update bug #1312011)

*** This bug has been marked as a duplicate of bug 1312011 ***