RHEL Engineering is moving the tracking of its product development work on RHEL 6 through RHEL 9 to Red Hat Jira (issues.redhat.com). If you're a Red Hat customer, please continue to file support cases via the Red Hat customer portal. If you're not, please head to the "RHEL project" in Red Hat Jira and file new tickets here. Individual Bugzilla bugs in the statuses "NEW", "ASSIGNED", and "POST" are being migrated throughout September 2023. Bugs of Red Hat partners with an assigned Engineering Partner Manager (EPM) are migrated in late September as per pre-agreed dates. Bugs against components "kernel", "kernel-rt", and "kpatch" are only migrated if still in "NEW" or "ASSIGNED". If you cannot log in to RH Jira, please consult article #7032570. That failing, please send an e-mail to the RH Jira admins at rh-issues@redhat.com to troubleshoot your issue as a user management inquiry. The email creates a ServiceNow ticket with Red Hat. Individual Bugzilla bugs that are migrated will be moved to status "CLOSED", resolution "MIGRATED", and set with "MigratedToJIRA" in "Keywords". The link to the successor Jira issue will be found under "Links", have a little "two-footprint" icon next to it, and direct you to the "RHEL project" in Red Hat Jira (issue links are of type "https://issues.redhat.com/browse/RHEL-XXXX", where "X" is a digit). This same link will be available in a blue banner at the top of the page informing you that that bug has been migrated.
Bug 1053600 - Systemd is not sending AUDIT_SYSTEM_SHUTDOWN events
Summary: Systemd is not sending AUDIT_SYSTEM_SHUTDOWN events
Keywords:
Status: CLOSED CURRENTRELEASE
Alias: None
Product: Red Hat Enterprise Linux 7
Classification: Red Hat
Component: systemd
Version: 7.0
Hardware: Unspecified
OS: Unspecified
urgent
medium
Target Milestone: rc
: ---
Assignee: Lukáš Nykrýn
QA Contact: Ondrej Moriš
URL:
Whiteboard:
Depends On: 853104
Blocks: RHEL7CCC
TreeView+ depends on / blocked
 
Reported: 2014-01-15 13:27 UTC by Steve Grubb
Modified: 2014-06-18 13:41 UTC (History)
20 users (show)

Fixed In Version: systemd-208-8.el7
Doc Type: Bug Fix
Doc Text:
Clone Of: 853104
Environment:
Last Closed: 2014-06-13 13:25:19 UTC
Target Upstream Version:
Embargoed:

Attachments (Terms of Use)

Description Steve Grubb 2014-01-15 13:27:37 UTC 
+++ This bug was initially created as a clone of Bug #853104 +++

Description of problem:
When systemd gets the command to shut down the system, its supposed to send the AUDIT_SYSTEM_SHUTDOWN event to the audit system. If its not sent, then the aulast program is broken and assumes the system oopsed. It might need to send the event earlier in the shutdown phase...and it needs to give the audit system enough time to record it to disk or enqueue it into the persistent queue if remote logging is selected.

How reproducible:
always

Steps to Reproduce:
1. aulast
  
Actual results:
reboot   system boot  3.5.2-3.fc17.x86 Wed Aug 29 19:12 - crash
reboot   system boot  3.5.2-3.fc17.x86 Thu Aug 30 06:12 - crash


Expected results:
reboot   system boot  2.6.35.14-106.fc Mon May 21 07:35 - 14:31  (06:56)
reboot   system boot  2.6.35.14-106.fc Mon May 21 16:01 - 18:11  (02:09)

--- Additional comment from Lennart Poettering on 2013-05-15 18:25:43 EDT ---

Fixed in systemd git.

--- Additional comment from Michal Schmidt on 2013-05-16 08:19:37 EDT ---

http://cgit.freedesktop.org/systemd/systemd/commit/?id=3f92e4b4b61042391bd44de4dceb18177df0dd57

--- Additional comment from Steve Grubb on 2013-06-01 11:01:33 EDT ---

Has the fix been put into a released systemd rpm? I just tested an updated F19 system and aulast is still reporting that the system always crashes instead of shutting down.

--- Additional comment from Steve Grubb on 2013-07-03 15:07:56 EDT ---

Tested this on a new F19 system. Its not working.

# ausearch --start today -m SYSTEM_SHUTDOWN
<no matches>

Unit file looks like this:

[Unit]
Description=Security Auditing Service
DefaultDependencies=no
After=local-fs.target
Conflicts=shutdown.target
Before=sysinit.target shutdown.target
RefuseManualStop=yes

Has the above commit made it into Fedora? Has anyone on systemd team verified the fix? Thanks.

--- Additional comment from Harald Hoyer on 2013-07-04 04:28:34 EDT ---

(In reply to Steve Grubb from comment #7)
> Has the above commit made it into Fedora? Has anyone on systemd team
> verified the fix? Thanks.

Will be in systemd-205

--- Additional comment from Steve Grubb on 2014-01-14 13:09:49 EST ---

Just checked this problem on F20 which uses systemd-208. Either it was never fixed or it regressed. When this was fixed, did anyone run aulast to see if it was fixed?
Comment 2 Lukáš Nykrýn 2014-01-16 16:29:15 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'
Comment 3 Steve Grubb 2014-01-17 12:55:54 UTC 
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.
Comment 4 Lukáš Nykrýn 2014-01-22 13:02:54 UTC 
Can you please post here a log from shutdown? http://freedesktop.org/wiki/Software/systemd/Debugging/#index2h1
Comment 5 Steve Grubb 2014-01-30 02:54:35 UTC 
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.
Comment 6 Michal Schmidt 2014-01-30 11:26:06 UTC 
(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().
Comment 7 Steve Grubb 2014-01-30 12:30:27 UTC 
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.
Comment 8 Michal Schmidt 2014-01-30 14:06:12 UTC 
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
Comment 9 Steve Grubb 2014-01-31 03:27:13 UTC 
Seeing as there is a Fedora bug on this, can a fix be pushed via the Fedora bz so that this can be tested?
Comment 10 Lukáš Nykrýn 2014-01-31 10:53:51 UTC 
Can you try this one in rhel7? http://lnykryn.fedorapeople.org/systemd/systemd-207-14.el7.1.src.rpm
Comment 11 Steve Grubb 2014-02-04 15:15:20 UTC 
Working on getting a RHEL7 system running. Testing on F20 would be easier.
Comment 12 Steve Grubb 2014-02-04 22:57:57 UTC 
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.
Comment 13 Michal Schmidt 2014-02-05 08:59:34 UTC 
(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.
Comment 14 Lukáš Nykrýn 2014-02-05 09:01:26 UTC 
Thanks for testing, I will include that patch in next build.
Comment 15 Steve Grubb 2014-02-05 12:15:02 UTC 
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!
Comment 16 Eduard Benes 2014-03-03 09:53:40 UTC 
Do you have any ETA when this could land into 7.0 composes?
Comment 19 Ludek Smid 2014-06-13 13:25:19 UTC 
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.
Note You need to log in before you can comment on or make changes to this bug.