Bug 1498080 - dmeventd: race causing inability to stop dmeventd right after unmonitoring devices
Summary: dmeventd: race causing inability to stop dmeventd right after unmonitoring de...
Keywords:
Status: POST
Alias: None
Product: LVM and device-mapper
Classification: Community
Component: lvm2
Version: unspecified
Hardware: All
OS: Linux
unspecified
medium
Target Milestone: ---
: ---
Assignee: Zdenek Kabelac
QA Contact: cluster-qe
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2017-10-03 13:03 UTC by Peter Rajnoha
Modified: 2025-05-17 08:28 UTC (History)
7 users (show)

Fixed In Version:
Clone Of:
Environment:
Last Closed:
Embargoed:
rule-engine: lvm-technical-solution?
rule-engine: lvm-test-coverage?


Attachments (Terms of Use)

Description Peter Rajnoha 2017-10-03 13:03:19 UTC
Summary:
There's a small race window where right after unmonitoring monitored devices we're not able to stop (SIGTERM) dmeventd. This is because each monitored device is handled in its own thread while the indicator that tracks whether dmeventd can be stopped or not is handled in a different thread.

Reproducer:
To reproduce, it should be enough to call these commands (in a script so there's as little time as possible between vgchange exit and kill command):

  vgchange --monitor n
  kill -TERM <dmeventd_pid>


Context:
This may cause trouble when we're trying to properly deactivate services on shutdown. In systemd environment, we have lvm2-monitor.service (and possibly other dmeventd monitoring clients) and dm-event.service. First, we stop the lvm2-monitor.service (which in turn calls vgchange --monitor n) and then we let the dmeventd to get killed later at shutdown sequence.

However, for a cleaner solution, we should be able to order the services so that after all monitoring clients have stopped, like lvm2-monitor.service (and hence they have commanded dmeventd to unmonitor particular devices), the dmeventd (dm-event.service) is stopped right after that too.

Related post on lvm-devel:
(not actually for this bug, but it lead to discovery of this bug)
https://www.redhat.com/archives/lvm-devel/2017-October/msg00000.html

Comment 1 Peter Rajnoha 2017-10-03 13:16:57 UTC
Example with thin monitored thin-pool:

[0] raw/~ # systemctl -o short-precise status dm-event.service
● dm-event.service - Device-mapper event daemon
   Loaded: loaded (/usr/lib/systemd/system/dm-event.service; disabled; vendor preset: enabled)
   Active: active (running) since Tue 2017-10-03 15:15:10 CEST; 24s ago
     Docs: man:dmeventd(8)
 Main PID: 861 (dmeventd)
    Tasks: 3 (limit: 4915)
   CGroup: /system.slice/dm-event.service
           └─861 /usr/sbin/dmeventd -f

Oct 03 15:15:10.244649 raw.virt dmeventd[861]: dmeventd ready for processing.
Oct 03 15:15:10.319107 raw.virt lvm[861]: Monitoring thin pool vg-pool-tpool.
Oct 03 15:15:10.403733 raw.virt dmeventd[861]: No longer monitoring thin pool vg-pool-tpool.
Oct 03 15:15:10.480664 raw.virt lvm[861]: Monitoring thin pool vg-pool-tpool.
Oct 03 15:15:10.586789 raw.virt dmeventd[861]: No longer monitoring thin pool vg-pool-tpool.
Oct 03 15:15:10.728556 raw.virt lvm[861]: Monitoring thin pool vg-pool-tpool.


[0] raw/~ # vgchange --monitor n; kill -TERM 861
  2 logical volume(s) in volume group "fedora" unmonitored
  4 logical volume(s) in volume group "vg" unmonitored


[0] raw/~ # systemctl -o short-precise status dm-event.service
● dm-event.service - Device-mapper event daemon
   Loaded: loaded (/usr/lib/systemd/system/dm-event.service; disabled; vendor preset: enabled)
   Active: active (running) since Tue 2017-10-03 15:15:10 CEST; 45s ago
     Docs: man:dmeventd(8)
 Main PID: 861 (dmeventd)
    Tasks: 1 (limit: 4915)
   CGroup: /system.slice/dm-event.service
           └─861 /usr/sbin/dmeventd -f

Oct 03 15:15:10.244649 raw.virt dmeventd[861]: dmeventd ready for processing.
Oct 03 15:15:10.319107 raw.virt lvm[861]: Monitoring thin pool vg-pool-tpool.
Oct 03 15:15:10.403733 raw.virt dmeventd[861]: No longer monitoring thin pool vg-pool-tpool.
Oct 03 15:15:10.480664 raw.virt lvm[861]: Monitoring thin pool vg-pool-tpool.
Oct 03 15:15:10.586789 raw.virt dmeventd[861]: No longer monitoring thin pool vg-pool-tpool.
Oct 03 15:15:10.728556 raw.virt lvm[861]: Monitoring thin pool vg-pool-tpool.
Oct 03 15:15:53.571796 raw.virt lvm[861]: WARNING: There are still devices being monitored.
Oct 03 15:15:53.571815 raw.virt lvm[861]: WARNING: Refusing to exit.
Oct 03 15:15:53.584987 raw.virt dmeventd[861]: No longer monitoring thin pool vg-pool-tpool.

Comment 2 Peter Rajnoha 2017-10-03 13:19:28 UTC
Putting a delay between vgchange --monitor n and killing dmeventd works, hence the race:

0] raw/~ # systemctl -o short-precise status dm-event.service
● dm-event.service - Device-mapper event daemon
   Loaded: loaded (/usr/lib/systemd/system/dm-event.service; disabled; vendor preset: enabled)
   Active: active (running) since Tue 2017-10-03 15:17:01 CEST; 24s ago
     Docs: man:dmeventd(8)
 Main PID: 863 (dmeventd)
    Tasks: 3 (limit: 4915)
   CGroup: /system.slice/dm-event.service
           └─863 /usr/sbin/dmeventd -f

Oct 03 15:17:01.746099 raw.virt dmeventd[863]: dmeventd ready for processing.
Oct 03 15:17:01.824081 raw.virt lvm[863]: Monitoring thin pool vg-pool-tpool.
Oct 03 15:17:01.881961 raw.virt lvm[863]: No longer monitoring thin pool vg-pool-tpool.
Oct 03 15:17:01.950993 raw.virt lvm[863]: Monitoring thin pool vg-pool-tpool.
Oct 03 15:17:02.037967 raw.virt dmeventd[863]: No longer monitoring thin pool vg-pool-tpool.
Oct 03 15:17:02.121636 raw.virt lvm[863]: Monitoring thin pool vg-pool-tpool.


[0] raw/~ # vgchange --monitor n
  2 logical volume(s) in volume group "fedora" unmonitored
  4 logical volume(s) in volume group "vg" unmonitored


----> short delay here



[0] raw/~ # kill -TERM 863


[0] raw/~ # systemctl -o short-precise status dm-event.service
● dm-event.service - Device-mapper event daemon
   Loaded: loaded (/usr/lib/systemd/system/dm-event.service; disabled; vendor preset: enabled)
   Active: inactive (dead) since Tue 2017-10-03 15:17:38 CEST; 2s ago
     Docs: man:dmeventd(8)
  Process: 863 ExecStart=/usr/sbin/dmeventd -f (code=exited, status=0/SUCCESS)
 Main PID: 863 (code=exited, status=0/SUCCESS)

Oct 03 15:17:01.746099 raw.virt dmeventd[863]: dmeventd ready for processing.
Oct 03 15:17:01.824081 raw.virt lvm[863]: Monitoring thin pool vg-pool-tpool.
Oct 03 15:17:01.881961 raw.virt lvm[863]: No longer monitoring thin pool vg-pool-tpool.
Oct 03 15:17:01.950993 raw.virt lvm[863]: Monitoring thin pool vg-pool-tpool.
Oct 03 15:17:02.037967 raw.virt dmeventd[863]: No longer monitoring thin pool vg-pool-tpool.
Oct 03 15:17:02.121636 raw.virt lvm[863]: Monitoring thin pool vg-pool-tpool.
Oct 03 15:17:31.005860 raw.virt dmeventd[863]: No longer monitoring thin pool vg-pool-tpool.
Oct 03 15:17:38.626845 raw.virt dmeventd[863]: dmeventd detected break while being idle for 7 second(s), exiting.
Oct 03 15:17:38.626941 raw.virt dmeventd[863]: dmeventd shutting down.

Comment 3 Zdenek Kabelac 2017-10-03 14:06:28 UTC
So we decided to slightly change the logic of exit of dmeventd.

TERM signal will be marked as permanent state  unless new monitoring is requested 

So unlike today - we will treat 'TERM' as request scheduling exit when there is nothing monitored.

It will be irrelevant if the 'kill' is send before or after  'vgchange --monitor n' - both will lead to exit of dmeventd if there is no monitored device.

If there is new '--monitor y' request - this will clear TERM state and drop scheduled exit.


dmevent should be logging such state changes.

Comment 4 Zdenek Kabelac 2017-10-05 09:47:44 UTC
The final solution treats TERM signal persistently. There is no way to cancel termination.  Dmeventd will exit as soon as no device is being monitored.

Related patch:


https://www.redhat.com/archives/lvm-devel/2017-October/msg00004.html

Comment 5 Eric Ren 2017-12-18 08:53:57 UTC
Hello,

A similar bug report for lvm2-2.02.176 (but on openSUSE tumbleweed) bring me here:

https://bugzilla.suse.com/show_bug.cgi?id=1072492

When there is thin/snapshot monitoring for system LV, the dm-event.service cannot be stopped cleanly, but timed out/killed in the end as below:

"""
Dec 18 15:19:10 eric-pc systemd[1]: Reached target Unmount All Filesystems.
Dec 18 15:19:10 eric-pc systemd[1]: Stopped target Local File Systems (Pre).
Dec 18 15:19:10 eric-pc systemd[1]: Stopped Create Static Device Nodes in /dev.
Dec 18 15:19:10 eric-pc systemd[1]: Stopped Create System Users.
Dec 18 15:19:10 eric-pc systemd[1]: Stopped Remount Root and Kernel File Systems.
Dec 18 15:19:10 eric-pc systemd[1]: Stopping Device-mapper event daemon...
Dec 18 15:19:10 eric-pc lvm[15030]: dmeventd received break, scheduling exit.
Dec 18 15:19:10 eric-pc systemd[1]: Received SIGRTMIN+20 from PID 931 (plymouthd).
Dec 18 15:20:29 eric-pc systemd[1]: lvm2-lvmetad.service: State 'stop-sigterm' timed out. Killing.
Dec 18 15:20:29 eric-pc systemd[1]: lvm2-lvmetad.service: Killing process 600 (lvmetad) with signal SIGKILL.
Dec 18 15:20:29 eric-pc systemd[1]: lvm2-lvmetad.service: Main process exited, code=killed, status=9/KILL
Dec 18 15:20:29 eric-pc systemd[1]: Stopped LVM2 metadata daemon.
Dec 18 15:20:29 eric-pc systemd[1]: lvm2-lvmetad.service: Unit entered failed state.
Dec 18 15:20:29 eric-pc systemd[1]: lvm2-lvmetad.service: Failed with result 'timeout'.
Dec 18 15:20:40 eric-pc systemd[1]: dm-event.service: State 'stop-sigterm' timed out. Killing.
Dec 18 15:20:40 eric-pc systemd[1]: dm-event.service: Killing process 15030 (dmeventd) with signal SIGKILL.
Dec 18 15:20:40 eric-pc systemd[1]: dm-event.service: Main process exited, code=killed, status=9/KILL
Dec 18 15:20:40 eric-pc systemd[1]: Stopped Device-mapper event daemon.
Dec 18 15:20:40 eric-pc systemd[1]: dm-event.service: Unit entered failed state.
Dec 18 15:20:40 eric-pc systemd[1]: dm-event.service: Failed with result 'timeout'.
Dec 18 15:20:40 eric-pc systemd[1]: Reached target Shutdown.
Dec 18 15:20:40 eric-pc systemd[1]: Starting /etc/init.d/halt.local Compatibility...
Dec 18 15:20:40 eric-pc systemd[1]: Started /etc/init.d/halt.local Compatibility.
Dec 18 15:20:40 eric-pc systemd[1]: Reached target Final Step.
Dec 18 15:20:40 eric-pc systemd[1]: Starting Power-Off...
"""

So far for fedora, I just tested on fedora25 with lvm2-2.02.173, without this problem. Later on, after upgrading to the latest fedora, I will see if it's OK.


These 2 fixes are included in v2.02.175, not sure if they cause this regression:

9940c2f754e3292b6d96628682c254941ae6cc58  dmeventd: schedule exit on break
3ae8adce928d4ce6ef36c87c2a0bb8aa737346b8 dmeventd: ensure systemd service gets stopped on shutdown

Comment 6 Eric Ren 2017-12-18 10:42:38 UTC
Sorry for disturbing, have verified, fedora28 with lvm2-2.02.176 doesn't have this problem :)

Comment 7 Eric Ren 2017-12-18 11:48:06 UTC
on openSUSE, the lvm2-monitor service is disabled by default, and the following commands solve my problem:

systemctl enable lvm2-monitor.service
systemctl start lvm2-monitor.service

Comment 8 Zdenek Kabelac 2020-09-15 09:20:49 UTC
(In reply to Eric Ren from comment #7)
> on openSUSE, the lvm2-monitor service is disabled by default, and the
> following commands solve my problem:
> 
> systemctl enable lvm2-monitor.service
> systemctl start lvm2-monitor.service

lvm2 (on systemd's system) does NOT start dmeventd on it's own - it relies on existence of the service (so dmeventd is executed from controlled environment and not forked from lvm).

So openSUSE needs to install and enabled service by default.
And btw same applies to lvmpolld service used for polling.

Other option is to compiled lvm2 without systemd support - and let lvm2 fork 'the old way'...

Depending on whatever openSuse distro prefers...


Note You need to log in before you can comment on or make changes to this bug.