Installing auditd sometimes fails in post-inst

[Dr. Jens Harbott]

[Impact]

Sometimes, auditd will get stuck when starting up, causing systemd to kill it after a while since it (systemd) never got the start notification.

Upstream troubleshooted this to be caused by calling a syslog() function inside a signal handler.

[Test Case]
There is no reliable test case to reproduce the bug, other than trying the fixed packages on an affected system where the hang occurs more frequently.

Basically:
sudo systemctl stop auditd
sudo systemctl start auditd

should work reliably. Do not run that in a tight loop, however, as that will trigger a it's-restarting-too-frequently failure.

[Where problems could occur]
- if auditd fails to start, then the first fallback is syslog, and if that is not picking up the audit messages, the last resort is the kernel buffer, which can fill up. In the case it fills up, audit logs will be lost.

- it's possible to configure the audit system to panic() the machine if audit messages are lost or otherwise not able to be recorded (auditctl -f 2; default is 1 which is printk())

- the update restarts auditd as expected. Misconfiguration on very very busy systems could mean that audit logs would be lost during the brief moment the service is restarted. If that's the case, this update would just be one more way to trigger it, but not be the root cause of the problem

- similarly, as is usual with updates that restart services, it's possible than an incorrect configuration for auditd is present, but was never loaded before. The restart will load the config, and will fail in such a case.

- this update removes a logging statement that occurs during startup:

    ("dispatcher %d reaped", pid)

It's unlikely, but possible, that some monitoring software could be looking for that message in the logs. It won't be there anymore after this update.

[Other Info]
The patch is committed upstream and part of the 2.8.5 release, which is present in Focal and later.
The real fix for this bug is just dropping the audit_msg() call in the signal handler code. But the original reporter of the bug, who is also who came up with the fix (see https://bugzilla.redhat.com/show_bug.cgi?id=1587995#c4) stated that with the 3 changes in the patch the startup hang didn't happen to him anymore. Since this bug is difficult to reproduce elsewhere (either you have it, or you don't), I chose to keep the 3 changes instead of just the removal of the audit_msg() call.

[Original Description]

This happens sometimes when installing auditd on Ubuntu 18.04.2, most installations work successfully, though. Re-running the install also fixes the issue, but the failure breaks our automation. The log from the failure looks like this:

# apt install auditd
...
Setting up auditd (1:2.8.2-1ubuntu1) ...
Created symlink /etc/systemd/system/multi-user.target.wants/auditd.service → /lib/systemd/system/auditd.service.
Job for auditd.service failed because a timeout was exceeded.
See "systemctl status auditd.service" and "journalctl -xe" for details.
invoke-rc.d: initscript auditd, action "start" failed.
● auditd.service - Security Auditing Service
   Loaded: loaded (/lib/systemd/system/auditd.service; enabled; vendor preset: enabled)
   Active: failed (Result: timeout) since Tue 2019-09-17 18:43:06 UTC; 11ms ago
     Docs: man:auditd(8)
           https://github.com/linux-audit/audit-documentation
  Process: 9702 ExecStart=/sbin/auditd (code=killed, signal=KILL)

Sep 17 18:40:06 compute-node21 systemd[1]: Starting Security Auditing Service...
Sep 17 18:40:06 compute-node21 auditd[9703]: Started dispatcher: /sbin/audispd pid: 9705
Sep 17 18:40:06 compute-node21 audispd[9705]: No plugins found, exiting
Sep 17 18:41:36 compute-node21 systemd[1]: auditd.service: Start operation timed out. Terminating.
Sep 17 18:43:06 compute-node21 systemd[1]: auditd.service: State 'stop-sigterm' timed out. Killing.
Sep 17 18:43:06 compute-node21 systemd[1]: auditd.service: Killing process 9702 (auditd) with signal SIGKILL.
Sep 17 18:43:06 compute-node21 systemd[1]: auditd.service: Killing process 9703 (auditd) with signal SIGKILL.
Sep 17 18:43:06 compute-node21 systemd[1]: auditd.service: Control process exited, code=killed status=9
Sep 17 18:43:06 compute-node21 systemd[1]: auditd.service: Failed with result 'timeout'.
Sep 17 18:43:06 compute-node21 systemd[1]: Failed to start Security Auditing Service.
dpkg: error processing package auditd (--configure):
 installed auditd package post-installation script subprocess returned error exit status 1

[Launchpad Janitor (janitor)]

Status changed to 'Confirmed' because the bug affects multiple users.

[Kodiak Firesmith (kodiakf)]

Hrm - any word on this one? We just hit it for 18.04 and it's a real bummer because on hosts that it happens on for us, it happens every time and we haven't figure out how to actually work around it. Purging auditd and reinstalling errors in the same way every time.

[Kodiak Firesmith (kodiakf)]

Here's what we see:

# apt-get install auditd
Reading package lists... Done
Building dependency tree
Reading state information... Done
Suggested packages:
  audispd-plugins
The following NEW packages will be installed:
  auditd
0 upgraded, 1 newly installed, 0 to remove and 0 not upgraded.
Need to get 0 B/194 kB of archives.
After this operation, 651 kB of additional disk space will be used.
Selecting previously unselected package auditd.
(Reading database ... 102723 files and directories currently installed.)
Preparing to unpack .../auditd_1%3a2.8.2-1ubuntu1_amd64.deb ...
Unpacking auditd (1:2.8.2-1ubuntu1) ...
Setting up auditd (1:2.8.2-1ubuntu1) ...
Created symlink /etc/systemd/system/multi-user.target.wants/auditd.service → /lib/systemd/system/auditd.service.
Job for auditd.service failed because the control process exited with error code.
See "systemctl status auditd.service" and "journalctl -xe" for details.
invoke-rc.d: initscript auditd, action "start" failed.
● auditd.service - Security Auditing Service
   Loaded: loaded (/lib/systemd/system/auditd.service; enabled; vendor preset: enabled)
   Active: failed (Result: exit-code) since Wed 2020-04-15 15:42:15 EDT; 6ms ago
     Docs: man:auditd(8)
           https://github.com/linux-audit/audit-documentation
  Process: 2634 ExecStart=/sbin/auditd (code=exited, status=1/FAILURE)
    Tasks: 0 (limit: 2318)
   CGroup: /system.slice/auditd.service

Apr 15 15:42:15 somehost systemd[1]: Starting Security Auditing Service...
Apr 15 15:42:15 somehost systemd[1]: auditd.service: Control process exited, code=exited status=1
Apr 15 15:42:15 somehost systemd[1]: auditd.service: Failed with result 'exit-code'.
Apr 15 15:42:15 somehost systemd[1]: Failed to start Security Auditing Service.
dpkg: error processing package auditd (--configure):
 installed auditd package post-installation script subprocess returned error exit status 1
Processing triggers for man-db (2.8.3-2ubuntu0.1) ...
Processing triggers for ureadahead (0.100.0-21) ...
Processing triggers for systemd (237-3ubuntu10.39) ...
Errors were encountered while processing:
 auditd

[Andreas Hasenack (ahasenack)]

Are you also enabling audit in the kernel command line?

[Andreas Hasenack (ahasenack)]

Kodiak, your log doesn't show a timeout like the one in this bug's description. You may have a syntax error, as it fails to start immediately. You should check /var/log/audit/audit.log and /var/log/syslog for other hints too.

[Andreas Hasenack (ahasenack)]

https://bugzilla.redhat.com/show_bug.cgi?id=1587995 is probably relevant

2.8.5 also mentions it in its changelog

[Andreas Hasenack (ahasenack)]

Upstream commit: https://github.com/linux-audit/audit-userspace/commit/ee6608eca034494fc2597b2990852adec236e486

[Andreas Hasenack (ahasenack)]

correct source package name is audit, not auditd (apparently we have/had both)

[Andreas Hasenack (ahasenack)]

I'm having difficulties reproducing the bug, to validate the patch. I build bionic test packages with the patch mentioned earlier, if someone wants to test: https://launchpad.net/~ahasenack/+archive/ubuntu/audit-startup-hang-1848330

[Kodiak Firesmith (kodiakf)]

Apologies - I don't remember the full specifics here but IIRC, the Mandiant FireEye HX agent foolishly re-implements Linux Audit, and it's every bit as terrible as that sounds. We discovered that we needed to basically purge both FireEye HX and Auditd on the system, then install Auditd, then disable it entirely, then allow the travesty of having the FireEye HX agent run it's own auditd daemon which clobbers the OS auditd. Yikes. And yes we filed a "please don't do such ugly things with core Linux services" request with their support. :/

[Andreas Hasenack (ahasenack)]

Yikes @Kodiak, sounds painful :(

[Andreas Hasenack (ahasenack)]

Package uploaded to the SRU queue

[Robie Basak (racb)]

I verified that this is fixed in both Focal and Hirsute by examining the source (so presumably Groovy too).

[Robie Basak (racb)]

Hello Dr., or anyone else affected,

Accepted audit into bionic-proposed. The package will build now and be available at https://launchpad.net/ubuntu/+source/audit/1:2.8.2-1ubuntu1.1 in a few hours, and then in the -proposed repository.

Please help us by testing this new package. See https://wiki.ubuntu.com/Testing/EnableProposed for documentation on how to enable and use -proposed. Your feedback will aid us getting this update out to other Ubuntu users.

If this package fixes the bug for you, please add a comment to this bug, mentioning the version of the package you tested, what testing has been performed on the package and change the tag from verification-needed-bionic to verification-done-bionic. If it does not fix the bug for you, please add a comment stating that, and change the tag to verification-failed-bionic. In either case, without details of your testing we will not be able to proceed.

Further information regarding the verification process can be found at https://wiki.ubuntu.com/QATeam/PerformingSRUVerification . Thank you in advance for helping!

N.B. The updated package will be released to -updates after the bug(s) fixed by this package have been verified and the package has been in -proposed for a minimum of 7 days.

[Ubuntu SRU Bot (ubuntu-sru-bot)]

All autopkgtests for the newly accepted audit (1:2.8.2-1ubuntu1.1) for bionic have finished running.
The following regressions have been reported in tests triggered by the package:

openssh/1:7.6p1-4ubuntu0.3 (arm64, armhf, amd64, i386, ppc64el)
linux/4.15.0-132.136 (i386)
libvirt/4.0.0-1ubuntu8.17 (amd64, i386)
glibc/2.27-3ubuntu1.4 (amd64)
linux-raspi-5.4/5.4.0-1026.29~18.04.1 (armhf)
linux-hwe-5.4/5.4.0-62.70~18.04.1 (armhf)
linux-hwe-5.0/5.0.0-63.69 (armhf)

Please visit the excuses page listed below and investigate the failures, proceeding afterwards as per the StableReleaseUpdates policy regarding autopkgtest regressions [1].

https://people.canonical.com/~ubuntu-archive/proposed-migration/bionic/update_excuses.html#audit

[1] https://wiki.ubuntu.com/StableReleaseUpdates#Autopkgtest_Regressions

Thank you!

[Andreas Hasenack (ahasenack)]

I'm going over the DEP8 failures

[Andreas Hasenack (ahasenack)]

All regressions have been resolved after some retries.

[Andreas Hasenack (ahasenack)]

Since it's difficult to reproduce the bug, what I'm going to do is setup a system with the previous auditd, setup some rules, confirm they are working, then upgrade, and confirm it keeps working, also after a reboot.

# Bionic verification

auditd from bionic:
auditd:
  Installed: 1:2.8.2-1ubuntu1
  Candidate: 1:2.8.2-1ubuntu1
  Version table:
 *** 1:2.8.2-1ubuntu1 500
        500 http://br.archive.ubuntu.com/ubuntu bionic/main amd64 Packages

Created a simple rule:
# cat /etc/audit/rules.d/30-shadow.rules
-w /etc/shadow -p wa -k shadow-changed

Loaded after restart:
# auditctl -l
-w /etc/shadow -p wa -k shadow-changed

Confirmed a change to the file gets logged:
# chmod 0400 /etc/shadow
#

/var/log/audit/auditd.log (parsed with ausearch -i):
type=PROCTITLE msg=audit(01/18/21 17:49:31.077:32) : proctitle=chmod 0400 /etc/shadow
type=PATH msg=audit(01/18/21 17:49:31.077:32) : item=0 name=/etc/shadow inode=64070 dev=fc:01 mode=file,640 ouid=root ogid=shadow rdev=00:00 nametype=NORMAL cap_fp=none cap_fi=none cap_fe=0 cap_fver=0
type=CWD msg=audit(01/18/21 17:49:31.077:32) : cwd=/root
type=SYSCALL msg=audit(01/18/21 17:49:31.077:32) : arch=x86_64 syscall=fchmodat success=yes exit=0 a0=0xffffff9c a1=0x5577580dc1c0 a2=0400 a3=0x0 items=1 ppid=1499 pid=1992 auid=ubuntu uid=root gid=root euid=root suid=root fsuid=root egid=root sgid=root fsgid=root tty=pts1 ses=3 comm=chmod exe=/bin/chmod key=shadow-changed

Now updating the package:
# apt-cache policy auditd
auditd:
  Installed: 1:2.8.2-1ubuntu1.1
  Candidate: 1:2.8.2-1ubuntu1.1
  Version table:
 *** 1:2.8.2-1ubuntu1.1 500
        500 http://br.archive.ubuntu.com/ubuntu bionic-proposed/main amd64 Packages
        100 /var/lib/dpkg/status
     1:2.8.2-1ubuntu1 500
        500 http://br.archive.ubuntu.com/ubuntu bionic/main amd64 Packages

(and its deps, like libaudit1, etc).

The same rule continues loaded:
# auditctl -l
-w /etc/shadow -p wa -k shadow-changed

Also after a manual restart:
# systemctl restart auditd
# auditctl -l
-w /etc/shadow -p wa -k shadow-changed

And changing /etc/shadow is logged (let's use 0640 this time):
# chmod 0640 /etc/shadow
#

log:
type=PROCTITLE msg=audit(01/18/21 17:54:51.942:56) : proctitle=chmod 0640 /etc/shadow
type=PATH msg=audit(01/18/21 17:54:51.942:56) : item=0 name=/etc/shadow inode=64070 dev=fc:01 mode=file,400 ouid=root ogid=shadow rdev=00:00 nametype=NORMAL cap_fp=none cap_fi=none cap_fe=0 cap_fver=0
type=CWD msg=audit(01/18/21 17:54:51.942:56) : cwd=/root
type=SYSCALL msg=audit(01/18/21 17:54:51.942:56) : arch=x86_64 syscall=fchmodat success=yes exit=0 a0=0xffffff9c a1=0x563ae04471c0 a2=0640 a3=0x0 items=1 ppid=1499 pid=2845 auid=ubuntu uid=root gid=root euid=root suid=root fsuid=root egid=root sgid=root fsgid=root tty=pts1 ses=3 comm=chmod exe=/bin/chmod key=shadow-changed

I then rebooted the system, performed the same tests, and got the same results with the updated package.

It would be great if people who were affected by this bug, and can reasonably reproduce it, could test the packages from proposed. In the meantime, I'll mark this as verification succeeded.

[Robie Basak (racb)]

I'd like to see some testing from someone actually affected please. Otherwise we'd be releasing a change that risks regression to users not affected, for a bug that we're not even sure if we've fixed.

[Andreas Hasenack (ahasenack)]

Dr. Harbott, would you be able to test the new audit packages in bionic-proposed? The SRU team is reluctant to approve this update without some sort of confirmation that it fixes the bug, and I haven't been able to reproduce it myself.

[Pedro Principeza (pprincipeza)]

Hi, all.

I obtained feedback from one Canonical customer (with a Support Case opened just for that), that hit the very same bug and, when testing the package sitting in -proposed, didn't reproduce the issue anymore.

From his own words:

"I wasn't able to recreate the auditd problem with the updated auditd package from proposed. Once we have the release package we can test that in the production environment."

Thanks!

[Robie Basak (racb)]

I think it's important to distinguish:

 a) merely failing to reproduce the issue; versus

 b) confirming reproduction of the issue against the previous version of the package (version 1:2.8.2-1ubuntu1 in this case), and then confirming that the proposed version (version 1:2.8.2-1ubuntu1.1 in this case) resolves the issue _in the same environment_.

The distinction is important because if the test method and environment used is unable to reproduce against the previous version, then confirming that it's not possible to reproduce the issue with the proposed version is effectively no testing at all.

Please could you confirm if the testing was actually case b, and if so detail what testing was performed?

Thanks!

[Andreas Hasenack (ahasenack)]

I prepared two bionic instances to run over the weekend.

One is running auditd from bionic, and the other is running the SRU proposed package.

I have auditd being restarted via this script in both (just the email message is different, to say which package it was):
#!/bin/bash

result=0

while /bin/true; do
    date
    sudo systemctl restart auditd || result=$?
    if [ "$result" -ne "0" ]; then
        echo "FAILED, result=$result"
        break
    fi
    pid=$(pidof auditd) || result=$?
    if [ "$result" -ne "0" ]; then
        echo "FAILED, auditd not running"
        break
    fi
    echo "auditd pid = $pid"
    sleep 2
    echo
done
mail -s "ALERT: audit orig test failed" <email address hidden> <<EOF
$(date)
Hello, the audit test failed with the orig package
result = $result
EOF

The one running the SRU version hasn't failed yet, but the one running the original auditd pkg from bionic has failed after a few hours, with the error message that this bug is addressing. I saved the logs, and kicked another run, just to try to get another failure. If it fails again, I'll update the package there to the SRU one, and let it run again.

I'll attach logs and a summary after this experiment is over, hopefully later today if the failure repeats itself in the same amount of time.

Here is a glimpse:
Fri Jan 22 19:20:29 UTC 2021
auditd pid = 25215

Fri Jan 22 19:20:31 UTC 2021
auditd pid = 25255

Fri Jan 22 19:20:33 UTC 2021
auditd pid = 25334
...
Fri Jan 22 22:43:47 UTC 2021
auditd pid = 23985

Fri Jan 22 22:43:49 UTC 2021
auditd pid = 24022

Fri Jan 22 22:43:51 UTC 2021
Job for auditd.service failed because a timeout was exceeded.
See "systemctl status auditd.service" and "journalctl -xe" for details.
FAILED, result=1

And from syslog:
...
Jan 22 22:43:51 orig-audit-bionic systemd[1]: Stopping Security Auditing Service...
Jan 22 22:43:51 orig-audit-bionic auditd[24022]: The audit daemon is exiting.
Jan 22 22:43:51 orig-audit-bionic kernel: [13955.899540] audit: type=1305 audit(1611355431.494:81546): audit_pid=0 old=24022 auid=4294967295 ses=4294967295 res=1
Jan 22 22:43:51 orig-audit-bionic systemd[1]: Stopped Security Auditing Service.
Jan 22 22:43:51 orig-audit-bionic kernel: [13955.901464] audit: type=1131 audit(1611355431.498:81547): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=auditd comm="systemd" exe="/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Jan 22 22:43:51 orig-audit-bionic systemd[1]: Starting Security Auditing Service...
Jan 22 22:43:51 orig-audit-bionic auditd[24058]: Started dispatcher: /sbin/audispd pid: 24060
Jan 22 22:43:51 orig-audit-bionic audispd: No plugins found, exiting
Jan 22 22:45:21 orig-audit-bionic systemd[1]: auditd.service: Start operation timed out. Terminating.
Jan 22 22:46:51 orig-audit-bionic systemd[1]: auditd.service: State 'stop-sigterm' timed out. Killing.
Jan 22 22:46:51 orig-audit-bionic systemd[1]: auditd.service: Killing process 24057 (auditd) with signal SIGKILL.
Jan 22 22:46:51 orig-audit-bionic systemd[1]: auditd.service: Killing process 24058 (auditd) with signal SIGKILL.
Jan 22 22:46:51 orig-audit-bionic systemd[1]: auditd.service: Control process exited, code=killed sta...

[Andreas Hasenack (ahasenack)]

TL;DR verification-succeeded

Ok, so here are the details.

I have two vms: one called orig-audit-bionic, the other called sru-audit-bionic, where I ran the script from comment #23 over the weekend in multiple scenarios. With auditd-1:2.8.2-1ubuntu1, the bug is reproduced after a few hours, whereas with 1:2.8.2-1ubuntu1.1 I had it running over 36h in one case with no failure.

a) orig-audit-bionic
Installed with the original auditd-1:2.8.2-1ubuntu1, I had two runs to verify the failure:
a.1) First run
started at Fri Jan 22 19:20:29 UTC 2021
failed at Fri Jan 22 22:43:51 UTC 2021
Jan 22 22:43:51 orig-audit-bionic systemd[1]: Starting Security Auditing Service...
Jan 22 22:43:51 orig-audit-bionic auditd[24058]: Started dispatcher: /sbin/audispd pid: 24060
Jan 22 22:43:51 orig-audit-bionic audispd: No plugins found, exiting
Jan 22 22:45:21 orig-audit-bionic systemd[1]: auditd.service: Start operation timed out. Terminating.

a.2) Second run, same package
started at Sat Jan 23 14:30:11 UTC 2021
failed at Sat Jan 23 21:35:20 UTC 2021
Jan 23 21:35:20 orig-audit-bionic systemd[1]: Starting Security Auditing Service...
Jan 23 21:35:20 orig-audit-bionic auditd[7794]: Started dispatcher: /sbin/audispd pid: 7796
Jan 23 21:35:20 orig-audit-bionic audispd: No plugins found, exiting
Jan 23 21:36:50 orig-audit-bionic systemd[1]: auditd.service: Start operation timed out. Terminating.

I then upgraded the auditd package to 1:2.8.2-1ubuntu1.1, and started another run:
started at Sat Jan 23 23:54:35 UTC 2021
manually aborted at Mon Jan 25 12:23:42 UTC 2021
No failure.

b) sru-audit-bionic
Installed the original auditd-1:2.8.2-1ubuntu1, and upgraded it straight away to 1:2.8.2-1ubuntu1.1. Then started the script.
started at Fri Jan 22 19:23:38 UTC 2021
manually aborted at Sun Jan 24 18:53:09 UTC 2021
No failure.

I then downgraded the auditd package back to auditd-1:2.8.2-1ubuntu1 and ran the script again.
started at Sun Jan 24 19:00:56 UTC 2021
failed at Sun Jan 24 23:32:58 UTC 2021
Jan 24 23:32:58 sru-audit-bionic systemd[1]: Starting Security Auditing Service...
Jan 24 23:32:58 sru-audit-bionic auditd[11439]: Started dispatcher: /sbin/audispd pid: 11441
Jan 24 23:32:58 sru-audit-bionic audispd: No plugins found, exiting
Jan 24 23:34:28 sru-audit-bionic systemd[1]: auditd.service: Start operation timed out. Terminating.

Full logs attached as tarballs for, heh, audit purposes :)

[Robie Basak (racb)]

The verification of the Stable Release Update for audit has completed successfully and the package is now being released to -updates. Subsequently, the Ubuntu Stable Release Updates Team is being unsubscribed and will not receive messages about this bug report. In the event that you encounter a regression using the package from -updates please report a new bug using ubuntu-bug and tag the bug report regression-update so we can easily find any regressions.

[Launchpad Janitor (janitor)]

This bug was fixed in the package audit - 1:2.8.2-1ubuntu1.1

---------------
audit (1:2.8.2-1ubuntu1.1) bionic; urgency=medium

  * d/p/04-startup-hang.patch: fix hang on startup (LP: #1848330)

 -- Andreas Hasenack <email address hidden> Fri, 08 Jan 2021 14:23:06 -0300