Bug 1651823

Summary:	Possible race condition inflicted with (multi-applied) RPM (file)triggers touching systemctl (daemon-reload vs. start)
Product:	[Fedora] Fedora	Reporter:	Jan Pokorný [poki] <jpokorny>
Component:	systemd	Assignee:	systemd-maint
Status:	CLOSED NOTABUG	QA Contact:	Fedora Extras Quality Assurance <extras-qa>
Severity:	unspecified	Docs Contact:
Priority:	unspecified
Version:	rawhide	CC:	lnykryn, msekleta, ssahani, s, systemd-maint, zbyszek
Target Milestone:	---
Target Release:	---
Hardware:	Unspecified
OS:	Unspecified
Whiteboard:
Fixed In Version:		Doc Type:	If docs needed, set a value
Doc Text:		Story Points:	---
Clone Of:		Environment:
Last Closed:	2018-11-21 18:45:44 UTC	Type:	Bug
Regression:	---	Mount Type:	---
Documentation:	---	CRM:
Verified Versions:		Category:	---
oVirt Team:	---	RHEL 7.3 requirements from Atomic Host:
Cloudforms Team:	---	Target Upstream Version:
Embargoed:

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 :-/