Bug 1053600
| Summary: | Systemd is not sending AUDIT_SYSTEM_SHUTDOWN events | ||
|---|---|---|---|
| Product: | Red Hat Enterprise Linux 7 | Reporter: | Steve Grubb <sgrubb> |
| Component: | systemd | Assignee: | Lukáš Nykrýn <lnykryn> |
| Status: | CLOSED CURRENTRELEASE | QA Contact: | Ondrej Moriš <omoris> |
| Severity: | medium | Docs Contact: | |
| Priority: | urgent | ||
| Version: | 7.0 | CC: | ebenes, harald, johannbg, jrieden, lnykryn, lpoetter, metherid, mschmidt, msekleta, mvadkert, omoris, plautrba, rvokal, sforsber, sgrubb, svenkatr, systemd-maint-list, systemd-maint, vpavlin, zbyszek |
| Target Milestone: | rc | ||
| Target Release: | --- | ||
| Hardware: | Unspecified | ||
| OS: | Unspecified | ||
| Whiteboard: | |||
| Fixed In Version: | systemd-208-8.el7 | Doc Type: | Bug Fix |
| Doc Text: | Story Points: | --- | |
| Clone Of: | 853104 | Environment: | |
| Last Closed: | 2014-06-13 13:25:19 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: | |||
| Bug Depends On: | 853104 | ||
| Bug Blocks: | 717785 | ||
|
Description
Steve Grubb
2014-01-15 13:27:37 UTC
Hmm it seems to me that systemd is sending the SYSTEM_SHUTDOWN event. Could not this be an issue in audit? [root@localhost ~]# ausearch --start today -m SYSTEM_SHUTDOWN ---- time->Thu Jan 16 11:11:41 2014 type=SYSTEM_SHUTDOWN msg=audit(1389888701.835:523): pid=2386 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='init exe="/usr/lib/systemd/systemd-update-utmp" hostname=? addr=? terminal=? res=success' ---- time->Thu Jan 16 11:12:03 2014 type=SYSTEM_SHUTDOWN msg=audit(1389888723.681:506): pid=2335 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='init exe="/usr/lib/systemd/systemd-update-utmp" hostname=? addr=? terminal=? res=success' ---- time->Thu Jan 16 11:12:48 2014 type=SYSTEM_SHUTDOWN msg=audit(1389888768.446:506): pid=2339 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='init exe="/usr/lib/systemd/systemd-update-utmp" hostname=? addr=? terminal=? res=success' ---- time->Thu Jan 16 11:14:05 2014 type=SYSTEM_SHUTDOWN msg=audit(1389888845.208:510): pid=2347 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='init exe="/usr/lib/systemd/systemd-update-utmp" hostname=? addr=? terminal=? res=success' ---- time->Thu Jan 16 11:23:17 2014 type=SYSTEM_SHUTDOWN msg=audit(1389889397.012:532): pid=2394 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='init exe="/usr/lib/systemd/systemd-update-utmp" hostname=? addr=? terminal=? res=success' On my computer, I have 2 SYSTEM_SHUTDOWN events for the whole month of January. So, its racy at best. We need it to be more certain. I think upstart sent the audit event as soon as shutdown was requested. This gave the event enough time to travel through the kernel and back to user space and to disk before the termination signal was sent to the audit daemon. Which it should be among the last to get a termination signal since its recording the shutdown of everything else. Can you please post here a log from shutdown? http://freedesktop.org/wiki/Software/systemd/Debugging/#index2h1 I did some more research on what aulast is telling me. What I found is: 1) Systemd is sending 2 SYSTEM_BOOT events for 1 boot. This means when the system goes down, one is not closed out and counts as a crash. Systemd should only send 1 boot event. 2) gdm is sending spurious user session events. So, I think the way forward for the moment is to find out why we are getting 2 boot events when there should be only one. You can check this by: ausearch --start today -m system_boot Assuming this is the first boot of the day, you should only have one. (In reply to Steve Grubb from comment #5) > 1) Systemd is sending 2 SYSTEM_BOOT events for 1 boot. This means when the > system goes down, one is not closed out and counts as a crash. Systemd > should only send 1 boot event. It seems one SYSTEM_BOOT event is generated by systemd-update-utmp.service ("systemd-update-utmp reboot") and the other by systemd-update-utmp-runlevel.service ("systemd-update-utmp runlevel"). The latter should normally generate only a SYSTEM_RUNLEVEL event, but it may also generate a SYSTEM_BOOT event if it cannot determine a previous runlevel: http://cgit.freedesktop.org/systemd/systemd/tree/src/update-utmp/update-utmp.c?id=v208#n271 I don't see I good reason for having this extra test and call to on_reboot() from on_runlevel(). One last comment, the issue is not limited to just the audit system. If you run: last | head You will see that utmp is also not right and shows a crash. Lennart's patch from a few minutes ago should fix the double boot utmp/audit events: http://cgit.freedesktop.org/systemd/systemd/commit/?id=e7fb33ffefcdc68ad096eea7444da877b68390e8 Seeing as there is a Fedora bug on this, can a fix be pushed via the Fedora bz so that this can be tested? Can you try this one in rhel7? http://lnykryn.fedorapeople.org/systemd/systemd-207-14.el7.1.src.rpm Working on getting a RHEL7 system running. Testing on F20 would be easier. OK, its looking a lot better. But I see something else that needs checking. I ssh'd into a VM and issued a 'reboot' command. When it came back up, it had not logged me out. On RHEL6 I get this: # reboot Broadcast message from sgrubb (/dev/pts/0) at 17:51 ... The system is going down for reboot NOW! On RHEL7, nothing except a broken pipe message after a while. When checking how this shows up in the RHEL6 logs: reboot system boot 2.6.32-220.el6.x Tue Feb 4 17:50 - 17:51 (00:00) sgrubb pts/0 192.168.122.1 Tue Feb 4 17:51 - 17:51 (00:00) And RHEL7: reboot system boot 3.10.0-78.el7.x8 Tue Feb 4 16:10 - 17:48 (01:38) sgrubb pts/0 192.168.122.1 Tue Feb 4 17:44 - down This looks like sshd wasn't given enough time to tear down the pam session before being killed. (In reply to Steve Grubb from comment #12) > OK, its looking a lot better. But I see something else that needs checking. > I ssh'd into a VM and issued a 'reboot' command. When it came back up, it > had not logged me out. Yes, this has been reported. See bug 1047614. Thanks for testing, I will include that patch in next build. If you don't mind, please also push a patch into F20 (bug 853104) because that is where I am doing development work and I need to get the sessions properly bounded for analysis. Thanks! Do you have any ETA when this could land into 7.0 composes? This request was resolved in Red Hat Enterprise Linux 7.0. Contact your manager or support representative in case you have further questions about the request. |