Bug 1651823 - Possible race condition inflicted with (multi-applied) RPM (file)triggers touching systemctl (daemon-reload vs. start)
Summary: Possible race condition inflicted with (multi-applied) RPM (file)triggers tou...
Keywords:
Status: CLOSED NOTABUG
Alias: None
Product: Fedora
Classification: Fedora
Component: systemd
Version: rawhide
Hardware: Unspecified
OS: Unspecified
unspecified
unspecified
Target Milestone: ---
Assignee: systemd-maint
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2018-11-20 23:54 UTC by Jan Pokorný [poki]
Modified: 2018-11-21 18:45 UTC (History)
6 users (show)

Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2018-11-21 18:45:44 UTC


Attachments (Terms of Use)


Links
System ID Priority Status Summary Last Updated
Red Hat Bugzilla 850199 None None None Never

Internal Links: 850199

Description Jan Pokorný [poki] 2018-11-20 23:54:46 UTC
Something fishy around this made me spuriously reopen and older
packaging: [bug 850199 comment 9], i.e. this behaviour:

# dnf install -y mcelog

# rpm -q mcelog
> mcelog-153-3.fc29.x86_64

# systemctl start mcelog.service 
> Warning: The unit file, source configuration file or drop-ins of
> mcelog.service changed on disk. Run 'systemctl daemon-reload' to
> reload units.


In fact, all looks fine with the package in question, except for
the observed response that then logically must have the roots
elsewhere.

Follow with me:

- /var/log/dnf.rpm.log:

> 2018-11-20T21:02:44Z INFO Installed: mcelog-3:153-3.fc29.x86_64
> 2018-11-20T21:02:44Z INFO Installed: mcelog-3:153-3.fc29.x86_64

(the times translate to 22:02 "local time", not sure why, but every
message of importance is doubled in that file so I do not put any
weight to that strangeness)

- journal:

> Nov 20 22:02:44 systemd[1]: Started /usr/bin/systemctl start man-db-cache-update.
> Nov 20 22:02:44 audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=run-rc81263ddb05046a9920bcfbd4608f48d comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal>
> Nov 20 22:02:44 systemd[1]: Starting man-db-cache-update.service...
> Nov 20 22:02:44 systemd[1]: Reloading.
> Nov 20 22:02:48 systemd[1]: Started man-db-cache-update.service.

Note that there are at least two filetrigger events stemming from
the mcelog installation (rpm triggers feature):

  a. systemd-native since /usr/lib/systemd/system
     file was changed/added, resulting in "systemctl daemon-reload", and

  b. man page indexing as can be observed above, since the package
     at hand does carry manpages


I suspect there's still some kind of asynchronous handling interference
akin to at least reliably reproduced

  https://github.com/systemd/systemd/issues/10627

from the past.  Sadly, I cannot reproduce it anymore over a couple
of tries.  But "daemon-reload" seems quite a beast in this asynchronous
logic.


This was with:
> systemd-239-9.git9f3aed1.fc30.x86_64
> mcelog-153-3.fc29.x86_64

Comment 1 Jan Pokorný [poki] 2018-11-21 18:45:44 UTC
Hmm, looking back in bash history, I think, silly me, it must have
been that when I opened /usr/lib/systemd/system/mcelog.service in vim 
beforehand to take a look at what it's meant to do, I likely used
':w' to close it again, just by the muscle memory, and it indeed
changes mtime of the file even without a single change.
Time to somehow swap it to do what ':update' normally does, I guess.

Sorry for noise :-/


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