Bug 1487352

*** Bug 1478517 has been marked as a duplicate of this bug. ***

*** Bug 1478521 has been marked as a duplicate of this bug. ***

*** Bug 1478528 has been marked as a duplicate of this bug. ***

For reference, this is the commit that should fix the problem; it currently lives in the audit/next branch and should go into Linux v4.15.

  commit d3b09ee2b47df7bb97f1b72a71d73835f79cd958
  Author: Paul Moore <paul>
  Date:   Fri Sep 1 09:44:34 2017 -0400

    audit: ensure that 'audit=1' actually enables audit for PID 1
    
    Prior to this patch we enabled audit in audit_init(), which is too
    late for PID 1 as the standard initcalls are run after the PID 1 task
    is forked.  This means that we never allocate an audit_context (see
    audit_alloc()) for PID 1 and therefore miss a lot of audit events
    generated by PID 1.
    
    This patch enables audit as early as possible to help ensure that when
    PID 1 is forked it can allocate an audit_context if required.
    
    Reviewed-by: Richard Guy Briggs <rgb>
    Signed-off-by: Paul Moore <paul>

Created attachment 1334814 [details]
01-bz1487352-1.patch

Created attachment 1334815 [details]
01-bz1487352-1.patch

Testing notes, pay attention to the extra records (PROCTITLE, SYSCALL) in the working kernel.

* Current RHEL-7.x kernel (BAD)

 # uname -r
 3.10.0-709.el7.x86_64
 # grep "^SELINUX=" /etc/selinux/config 
 SELINUX=enforcing
 # grep "audit=1" /proc/cmdline 
 BOOT_IMAGE=/vmlinuz-3.10.0-709.el7.x86_64 root=UUID=84615751-d377-4530-a005-
 d24ff46b5c19 ro rd.md=0 rd.lvm=0 rd.dm=0 rd.luks=0 vconsole.keymap=us 
 nomodeset 
 console=ttyS0 LANG=en_US.UTF-8 audit=1
 # ausearch -ts boot -m MAC_STATUS
 ----
 time->Thu Oct  5 11:22:22 2017
 type=MAC_STATUS msg=audit(1507216942.353:40): enforcing=1 old_enforcing=0 
 auid=4294967295 ses=4294967295

* Patches RHEL-7.x kernel (GOOD)

 # uname -r
 3.10.0-725.el7.1.bz1487352.x86_64
 # grep "^SELINUX=" /etc/selinux/config
 SELINUX=enforcing
 # grep "audit=1" /proc/cmdline
 BOOT_IMAGE=/vmlinuz-3.10.0-725.el7.1.bz1487352.x86_64 root=UUID=84615751-
 d377-4530-a005-d24ff46b5c19 ro rd.md=0 rd.lvm=0 rd.dm=0 rd.luks=0 
 vconsole.keymap=us nomodeset console=ttyS0 LANG=en_US.UTF-8 audit=1
 # ausearch -ts boot -m MAC_STATUS
 ----
 time->Thu Oct  5 11:26:21 2017
 type=PROCTITLE msg=audit(1507217181.241:40): 
 proctitle=2F7573722F6C69622F73797374656D642F73797374656D64002D2D73776974636865
 642D726F6F74002D2D73797374656D002D2D646573657269616C697A65003231
 type=SYSCALL msg=audit(1507217181.241:40): arch=c000003e syscall=1 success=yes 
 exit=1 a0=3 a1=7fffdd628a30 a2=1 a3=7fffdd628740 items=0 ppid=0 pid=1 
 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=
 (none) ses=4294967295 comm="systemd" exe="/usr/lib/systemd/systemd" 
 subj=kernel key=(null)
 type=MAC_STATUS msg=audit(1507217181.241:40): enforcing=1 old_enforcing=0 
 auid=4294967295 ses=4294967295

Patch(es) committed on kernel repository and an interim kernel build is undergoing testing

This is not a bug in RHEL7 because the patch that broke things upstream:
  https://github.com/linux-audit/audit-kernel/commit/d3ca0344b21f04786219bf0f49647f24e4e17323
was never backported.  Recommend closing NOTABUG.

Richard, see comment #8.

(In reply to Paul Moore from comment #14)
> Richard, see comment #8.

Ok, my bad.  I had seen comment 8 but evidently didn't let it sink in.  I thought I had identified when it broke (because I remember it working at one point), but that isn't it on further inspection.  Perhaps it was other changes that moved around initialization of other subsystems that changed this startup timing.

From your testing this appears to be the minimum necessary to fix this issue.  The other 4 patches from that set (plus the one mentioned above) would make it tidier, but are evidently not needed.

I'm surprised this works alone since the rest of the audit infrastructure isn't ready until audit_initialized is set.  Other processes will just bounce off audit_log_start() until that is set anyways as it should have until audit_enabled was set just after audit_initialized.

(In reply to Richard Guy Briggs from comment #15)
> (In reply to Paul Moore from comment #14)
> > Richard, see comment #8.
> 
> Ok, my bad.  I had seen comment 8 but evidently didn't let it sink in ...

I guess it doesn't hurt, but I don't think you need to repeat what is said on RHKL here, you can simply reference the patchwork link in comment #10.  Anyway, here is my RHKL response:

"You are focusing on the wrong thing, the key with the init problem
 lies with audit_ever_enabled and the audit_alloc() function (see the
 commit description).  We need to make sure audit_ever_enabled is set
 *before* we fork for the init process; if audit_ever_enabled is not
 set before we fork, audit_alloc() never allocates an audit_context
 struct for the task.

 As you say, early audit_log_start() calls are going to fail, but that
 isn't the problem."

Paul, you're right. It's not _the_ problem but it is a problem. I thought you said you moved the module initialization up to earlier in the boot. Did that not make it as part of this set?

(In reply to Steve Grubb from comment #17)
> Paul, you're right. It's not _the_ problem but it is a problem. I thought
> you said you moved the module initialization up to earlier in the boot. Did
> that not make it as part of this set?

Steve that change does not have any bearing on this issue.  If you are concerned because you heard about audit_log_start() failing on early boot, rest assured those have always been failing.  We are talking about a small corner case, I'm not even sure there are any affected audit_log_start() calls (maybe, I haven't checked).

If you have a specific problem Steve, open either a BZ (RHEL-7.x) or a GH issue (upstream); you know the drill.

Patch(es) available on kernel-3.10.0-738.el7

Successfully reproduced and verified on x86_64.

OLD (kernel-3.10.0-693.el7)
===========================
type=MAC_STATUS msg=audit(12/20/2017 07:27:55.266:40) : enforcing=1 old_enforcing=0 auid=unset ses=unset 

NEW (kernel-3.10.0-823.el7)
===========================
type=PROCTITLE msg=audit(12/20/2017 07:11:39.221:40) : proctitle=/usr/lib/systemd/systemd --switched-root --system --deserialize 22 
type=SYSCALL msg=audit(12/20/2017 07:11:39.221:40) : arch=x86_64 syscall=write success=yes exit=1 a0=0x3 a1=0x7ffe4ae79f30 a2=0x1 a3=0x7ffe4ae799a0 items=0 ppid=0 pid=1 auid=unset uid=root gid=root euid=root suid=root fsuid=root egid=root sgid=root fsgid=root tty=(none) ses=unset comm=systemd exe=/usr/lib/systemd/systemd subj=kernel key=(null) 
type=MAC_STATUS msg=audit(12/20/2017 07:11:39.221:40) : enforcing=1 old_enforcing=0 auid=unset ses=unset 

For more details please see TJ#2212673 and TJ#2212678.

Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHSA-2018:1062