Bug 1010697

Summary: why does it do this stuff at this time?
Product: [Fedora] Fedora Reporter: udo <udovdh>
Component: systemdAssignee: systemd-maint
Status: CLOSED ERRATA QA Contact: Fedora Extras Quality Assurance <extras-qa>
Severity: unspecified Docs Contact:
Priority: unspecified    
Version: 19CC: johannbg, lnykryn, msekleta, plautrba, systemd-maint, vpavlin, zbyszek
Target Milestone: ---   
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: systemd-204-16.fc19 Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2013-10-08 11:38:10 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 udo 2013-09-22 15:41:51 UTC
Description of problem:
Suddenly systemd shows weird activity

Version-Release number of selected component (if applicable):


How reproducible:
DUnno

Steps to Reproduce:
1.
2.
3.

Actual results:
Sep 22 01:26:27 epia systemd[1]: Starting Multi-router Traffic Grapher...
Sep 22 01:26:27 epia systemd[1]: Started Multi-router Traffic Grapher.
Sep 22 01:26:32 epia kernel: INVALID: IN=ppp0 OUT= MAC= SRC=201.212.254.90 DST=80.101.128.228 LEN=40 TOS=0x00 PREC=0x00 TTL=239 ID=32500 PROTO=TCP SPT=6881 DPT=35971 WINDOW=0 RES=0x00 RST URGP=0 
Sep 22 01:26:32 epia kernel: INVALID: IN=ppp0 OUT= MAC= SRC=113.190.171.115 DST=80.101.128.228 LEN=40 TOS=0x08 PREC=0x00 TTL=110 ID=10383 DF PROTO=TCP SPT=18314 DPT=6881 WINDOW=0 RES=0x00 ACK RST URGP=0 
Sep 22 01:26:41 epia systemd[1]: Reexecuting.
Sep 22 01:26:41 epia systemd[1]: systemd 204 running in system mode. (+PAM +LIBWRAP +AUDIT +SELINUX +IMA +SYSVINIT +LIBCRYPTSETUP +GCRYPT +ACL +XZ)
Sep 22 01:26:42 epia systemd[1]: Found device /dev/mapper/swap.
Sep 22 01:26:42 epia systemd[1]: Found device Hitachi_HDS721050CLA360.
Sep 22 01:26:42 epia systemd[1]: Activated swap /dev/mapper/swap.
Sep 22 01:26:42 epia systemd[1]: Mounted /var/www.
Sep 22 01:26:42 epia systemd[1]: Mounted /usr/local/data3.
Sep 22 01:26:42 epia systemd[1]: Mounted /usr/local/data.
Sep 22 01:26:43 epia systemd[1]: Mounted /usr/src.
Sep 22 01:26:43 epia systemd[1]: Mounted /var.
Sep 22 01:26:43 epia systemd[1]: Mounted /home.
Sep 22 01:26:43 epia systemd[1]: Mounted /boot.
Sep 22 01:26:43 epia systemd[1]: Mounted /.
Sep 22 01:26:43 epia systemd[1]: Found device Hitachi_HDS721050CLA360.
Sep 22 01:26:43 epia systemd[1]: Starting Cryptography Setup for swap...
Sep 22 01:26:43 epia systemd[1]: Starting File System Check on /dev/disk/by-label/\x2fboot...
Sep 22 01:26:43 epia systemd[1]: Started CUPS Printing Service.
Sep 22 01:26:43 epia systemd-cryptsetup[19896]: Volume swap already active.
Sep 22 01:26:43 epia systemd[1]: systemd-cryptsetup: control process exited, code=exited status=1
Sep 22 01:26:43 epia kernel: UDP_Dropped_I: IN=ppp0 OUT= MAC= SRC=172.9.147.0 DST=80.101.128.228 LEN=364 TOS=0x00 PREC=0x00 TTL=114 ID=17003 PROTO=UDP SPT=500 DPT=500 LEN=344 
Sep 22 01:26:44 epia systemd[1]: Started File System Check on /dev/disk/by-label/\x2fusr\x2fsrc.
Sep 22 01:26:44 epia systemd[1]: Started File System Check on /dev/disk/by-label/\x2fboot.
Sep 22 01:26:44 epia systemd[1]: Started File System Check on /dev/disk/by-label/\x2fhome.
Sep 22 01:26:44 epia systemd[1]: Started File System Check on /dev/disk/by-label/data.
Sep 22 01:26:44 epia systemd[1]: Started File System Check on /dev/disk/by-label/\x2fusr.
Sep 22 01:26:44 epia systemd[1]: Started File System Check on /dev/disk/by-label/data3.
Sep 22 01:26:44 epia systemd[1]: Started File System Check on /dev/disk/by-label/\x2fvar.
Sep 22 01:26:44 epia systemd[1]: Started File System Check on /dev/disk/by-label/www.
Sep 22 01:26:47 epia systemd-cryptsetup[19909]: Failed to deactivate: Device or resource busy
Sep 22 01:26:47 epia systemd[1]: systemd-cryptsetup: control process exited, code=exited status=1
Sep 22 01:26:47 epia systemd[1]: Failed to start Cryptography Setup for swap.
Sep 22 01:26:47 epia systemd[1]: Unit systemd-cryptsetup entered failed state.
Sep 22 01:27:11 epia kernel: INVALID: IN=ppp0 OUT= MAC= SRC=70.68.60.181 DST=80.101.128.228 LEN=108 TOS=0x08 PREC=0x00 TTL=114 ID=6412 DF PROTO=TCP SPT=52607 DPT=6881 WINDOW=16425 RES=0x00 ACK PSH FIN URGP=0
 
Why did it reexecute? I was not at the console at that time.
Then why does it mount already mounted stuff?
WHy does it fsck mounted stuff?
Why does it start already decrypted stuff?



Expected results:
No such confusion.

Additional info:

Comment 1 Zbigniew Jędrzejewski-Szmek 2013-09-22 19:26:08 UTC
Hi, we haven't had issues with systemd reexecuting spontaneously, afaik. It will reexecute when it either receives a dbus signal or a unix signal (TERM). Any ideas on what could have sent a signal? If you put systemd in debug mode (kill -56 1), it'll log dbus communications.

Regarding the restarting of fsck units: this has been fixed post-204: http://cgit.freedesktop.org/systemd/systemd/commit/?id=d0a2d726, http://cgit.freedesktop.org/systemd/systemd/commit/?id=ef7e6e0598 and other commits which do related changes for similar units. I'm not sure if we got all of them... If such spurious restarts of units happen post-207, please report them.

Comment 2 udo 2013-09-23 15:23:03 UTC
I do not have any visible controle over dbus and I was not oat the system to give it a kill -whatever.

Aside from the reexecution we see that systemd is not aware of the situation of the system, does not even bother to even check, and thus goes along with stuff that you would expect during a system startup.
That is very strange indeed as it could hose a system very badly.
Please adjust your code to check stuff before you execute certain commands on the system.
Why fsck when the stuff is mounted already?
Why mount it first before checking if it is already mounted?

Together with the mertg stuff and the logging stuff I do think that systemd is a step too far.
The init replacement is OK as it provides a quicker boot if no issues are encountered.
The rest should be skipped as soon as possible. (!!)
Please stay true to the core of the project.
Please do not do stuff 'because we can' as it appears to contradict UNIX itself as I know it.

Comment 3 Zbigniew Jędrzejewski-Szmek 2013-09-23 17:14:56 UTC
(In reply to udo from comment #2)
> I do not have any visible controle over dbus and I was not oat the system to
> give it a kill -whatever.
If "oat" means "own", then sorry, you can't debug stuff without necessary privileges.

> Aside from the reexecution we see that systemd is not aware of the situation
> of the system, does not even bother to even check, and thus goes along with
> stuff that you would expect during a system startup.
> That is very strange indeed as it could hose a system very badly.
It doesn't hose the system, since fsck does not run on a mounted filesystem, so it's just a bunch of misleading messages. It was a bug, noticed and fixed after F19 was released. The fix has certain side-effects and thus wasn't backported to F19.

> Please adjust your code to check stuff before you execute certain commands
> on the system.
Right, fsck does check, and (with the fix) systemd doesn't try to invoke it after the filesystem has been mounted anymore.

> Why fsck when the stuff is mounted already?
It was a bug.

> Why mount it first before checking if it is already mounted?
It doesn't actually get mounted again.

> Together with the mertg stuff and the logging stuff I do think that systemd
> is a step too far.
mertg stuff?

> The init replacement is OK as it provides a quicker boot if no issues are
> encountered.
> The rest should be skipped as soon as possible. (!!)
> Please stay true to the core of the project.
> Please do not do stuff 'because we can' as it appears to contradict UNIX
> itself as I know it.
I'm sorry that you encounter issues, but the First in Fedora unfortunately means that sometimes you get stuff which you get to find bugs in.

You might want to create a file /etc/systemd/system/systemd-fsck@.service.d/90-remain.conf with the following contents:
-------------------------------
[Service]
RemainAfterExit=yes
-------------------------------
and similar for other units which get needlessly started twice.

Comment 4 Michal Schmidt 2013-09-23 17:17:35 UTC
(In reply to Zbigniew Jędrzejewski-Szmek from comment #3)
> (In reply to udo from comment #2)
> > I do not have any visible controle over dbus and I was not oat the system to
> > give it a kill -whatever.
> If "oat" means "own", then sorry, you can't debug stuff without necessary
> privileges.

A misspelling of "at" seems more likely.

> > Together with the mertg stuff and the logging stuff I do think that systemd
> > is a step too far.
> mertg stuff?

Likely "mrtg stuff", referring to bug 911766.

Comment 5 udo 2013-09-23 17:26:58 UTC
oat -> at
If the disks are mounted, why even start fsck?
Why not backport to F19 if that release has 'support'/'maintenance' or whatever euphemism is en vogue these days?
If fsck is to be relied on then systemd does simply fire off commands. What is the added value if systemd is apparantly not aware of the situation before even deducing what to do?
mertg -> mrtg. 
The con-job replacement that logs way too much in the wrong places. Not a task for an init-replacement. No progress, but a step backwards.
See bugzilla https://bugzilla.redhat.com/show_bug.cgi?id=984565. Ask Lennart P.
Also ask him about the reasons for the journalctl stuff over cat/less/more/grep etc in the 'classic' log files.
Where is my ~/.xinit-errors? Does that stuff really belong in /var/log/messages?

The Fedora folks are messing up a good UNIX system for no good reason as I did not yet get pointed towards a good read explaining all this.
Together with the breakneck upgrade schedule/speed and the perceived lack of attention and thus support for core issues: what is Fedora aiming at and what does it think it is doing to get there? We might perceive a different thing here.
(I did not yet mention the upgrade procedure which is utterly broken as I discovered by going from F17 to F19: we cannot do a upgrade via DVD, the ketchup or whatever tool is broken on anything that has raid, crypto, etc and yum needs somebody that is not afraid of dependency hell. Do you really want to press this onto users? Please think again.

Comment 6 udo 2013-10-06 15:01:31 UTC
Looks like https://bugzilla.redhat.com/show_bug.cgi?id=974122 might be related.

Comment 7 Zbigniew Jędrzejewski-Szmek 2013-10-06 15:21:59 UTC
Please stop setting needinfo on various bugs to their owners. This is a tool for bug owners. We are aware, really, of this bug, and the other 200 open bugs, and 150 or so on freedesktop.org. You're not helping by adding noise.

Comment 8 Fedora Update System 2013-10-06 22:16:01 UTC
systemd-204-16.fc19 has been submitted as an update for Fedora 19.
https://admin.fedoraproject.org/updates/systemd-204-16.fc19

Comment 9 Zbigniew Jędrzejewski-Szmek 2013-10-06 22:23:50 UTC
This update should be a partial fix, please test that the fsck's don't happen.

Comment 10 Fedora Update System 2013-10-08 11:38:10 UTC
systemd-204-16.fc19 has been pushed to the Fedora 19 stable repository.  If problems still persist, please make note of it in this bug report.