Bugzilla will be upgraded to version 5.0. The upgrade date is tentatively scheduled for 2 December 2018, pending final testing and feedback.
Bug 1227379 - Audit events in /var/log/messages
Audit events in /var/log/messages
Status: NEW
Product: Fedora
Classification: Fedora
Component: systemd (Show other bugs)
28
Unspecified Unspecified
unspecified Severity unspecified
: ---
: ---
Assigned To: systemd-maint
Fedora Extras Quality Assurance
https://github.com/systemd/systemd/is...
: Reopened
Depends On:
Blocks: 1231364 1281852
  Show dependency treegraph
 
Reported: 2015-06-02 10:11 EDT by udo
Modified: 2018-10-16 14:44 EDT (History)
77 users (show)

See Also:
Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2016-07-19 10:28:28 EDT
Type: Bug
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)
Patch that doesn't enable audit (2.33 KB, patch)
2015-07-28 08:32 EDT, Steve Grubb
no flags Details | Diff
'journalctl -b | grep "audit:" ' from boot to sddm with systemd-journald-audit.socket masked and dracut regenerated (2.48 KB, text/plain)
2016-12-09 06:30 EST, Oliver Henshaw
no flags Details

  None (edit)
Description udo 2015-06-02 10:11:29 EDT
Description of problem:
audit messages show up in /var/log/messages ever since upgrading to Fedora 22 from 20.

Version-Release number of selected component (if applicable):
audit-2.4.2-1.fc22.x86_64

How reproducible:
Upgrade to fedora 22.


Actual results:
audit stuff in /var/log messages (along with a whole laod of other stuff that does not belong there)

Expected results:
No audit messages in /var/log/messages

Additional info:
# ps -ef|grep audit
root       161     2  0 Jun01 ?        00:00:00 [kauditd]
root      1277     1  0 Jun01 ?        00:00:00 /sbin/auditd -n
Comment 1 Steve Grubb 2015-06-02 11:04:18 EDT
This is not an audit problem. Systemd is doing it. There are actually security requirements for keeping them separate. Transferring to appropriate subsystem.
Comment 2 udo 2015-06-02 11:11:16 EDT
@Steve: So we have an official statement about needs to keep loggings separate?
Can you please menion the underlying documentation so I can mention these to systemd peopel in other logging issues?
Thanks.
Comment 3 Steve Grubb 2015-06-02 12:04:31 EDT
We certify against OS PP which has several extended modules:

https://www.bsi.bund.de/SharedDocs/Downloads/DE/BSI/Zertifizierung/ReportePP/pp0067_EP_zip.zip

In this zip archive, there is OSPP_EP_AM-v1.0.pdf which defines the Advanced Management capabilities such as Roles. SE Linux defines a number of them:

# seinfo -r

Roles: 14
   auditadm_r
   dbadm_r
   guest_r
   staff_r
   user_r
   logadm_r
   object_r
   secadm_r
   sysadm_r
   system_r
   webadm_r
   xguest_r
   nx_server_r
   unconfined_r

Notice that there is an auditadm_r and an sysadm_t. There is supposed to be a separation of roles. This means that if the security officer is conducting an investigation of a typical admin for insider threat reasons, then placing audit logs in something reachable by the admin would tip him off that such an investigation is underway.

The actual details is very long winded and requires a lot of cross referencing. It starts in the "Security management roles (FMT_SMR.2)" and you have to understand roles need to be separated, users may have access to multiple roles, and system objects must be labeled appropriately to allow this access.

By co-mingling the logs, they cannot be separately labeled so that each role can correctly access just its data.
Comment 4 Lennart Poettering 2015-06-09 09:40:54 EDT
Well, systemd model is to drop all loggable events into the same pool and apply filtering at read time, not write time. Hence we place audit events in the same journal files as everything else.

Note that journald is not involved in writing /var/log/messages. That's something rsyslog is doing. If you don#t want the audit events to show up there, then rsyslog should filter them out when reading things from the journal.

REassigning to rsyslog hence.
Comment 5 udo 2015-06-09 09:51:41 EDT
We don't want journals.
We don't need journals.
You don't even propose a solution, you just point fingers.
Systemd got in between a working setup so please explain way more deeply.
You owe us that with this 'init-replacement' of yours.
Comment 6 udo 2015-06-09 10:34:12 EDT
Why did this (mostly) work in Fedora 20?
Why did it break during the forced upgrade to Fedora 22?
Comment 7 Tomas Heinrich 2015-06-10 08:06:21 EDT
@Steve:
Hello. Didn't audit use to write the logs by itself? When and what changed?
Comment 8 Tomas Heinrich 2015-06-10 08:06:45 EDT
@Lennart:
> Well, systemd model is to drop all loggable events into the same pool and apply filtering at read time, not write time.

How does that work with log rotation or rate limiting? Are all messages treated equally?
Comment 9 Steve Grubb 2015-06-10 11:42:40 EDT
Audit does write to /var/log/audit/audit.logs. What's changed is that the kernel now supports multicast audit events, which I objected to for security reasons. And that was requested by systemd folks because they want everything. They also assume syslog wants the same stuff. But the problem is syslog can also get audit events via printk in the kernel, so there's a real complication.

The best solution in my opinion is not have journald grab audit logs. Problem solved.
Comment 10 Zbigniew Jędrzejewski-Szmek 2015-06-11 10:12:39 EDT
I think we should make audit-logs-in-journal configurable by modifying journald to not open sockets by itself if at least one socket was given, and making systemd-journal-audit.socket enableable on its own. Then 'systemctl enable/disable systemd-journal-audit.socket && systemctl restart systemd-journald' would enable/disable the functionality. The default should probably be disabled.
Comment 11 Tomas Heinrich 2015-06-12 10:32:15 EDT
OK, switching back to systemd.

Zbigniew, I'd still be interested to know whether some "sets" of messages can be treated differently by journald, e.g. in relation to log rotation.
Comment 12 Zbigniew Jędrzejewski-Szmek 2015-06-12 10:58:29 EDT
(In reply to Tomas Heinrich from comment #11)
> OK, switching back to systemd.
Ack.

> Zbigniew, I'd still be interested to know whether some "sets" of messages
> can be treated differently by journald, e.g. in relation to log rotation.
We only do per-uid splitting currently. Extending this has been discussed many times in the past, and so far the conclusion has always been that "use rsyslog or some other `smart' log processor" if you need the functionality.
Comment 13 Lennart Poettering 2015-06-17 19:16:49 EDT
Zbigniew, I am not convinced this should have explicit support for allowing enabling or not. I could be convinced to make a journald change so that masking the audit socket would be effective, but other than that, this should be a static unit really.

I am pretty sure the audit situation would be much better if the kernel wouldn#t duplicate msgs via the audit mcast stuff and kmsg though... but that's something to fix in the kernel, and the kernel audit guys are already aware of it.

Thomas, no, we treat everything the same, and rotate it synchronously by disk size and age. We do minimal split up only to take benefit of the UNIX file access modes, so that each user can get his own journal file, and access to it can be managed via fs ACLs.

Thomas, if you grab the messages for rsyslog from the journal (which is fine), then consider filtering all with _TRANSPORT=audit out if you are not interested in audit msgs.
Comment 14 Zbigniew Jędrzejewski-Szmek 2015-06-17 23:24:30 EDT
(In reply to Lennart Poettering from comment #13)
> Zbigniew, I am not convinced this should have explicit support for allowing
> enabling or not. I could be convinced to make a journald change so that
> masking the audit socket would be effective, but other than that, this
> should be a static unit really.
Masking would be fine too.
Comment 15 Davide Repetto 2015-06-22 06:41:43 EDT
I'm noticing a slightly different facet of this problem.

On my systems many very uninteresting audit messages related to *successful* operations keep flowing in the journal even after an "auditctl -e 0" and apparently the only way to stop the flood (which BTW takes a measurable toll on the system, grows logs too much and makes them rotate too fast anyway, thus making journal operations themselves way slower and less manageable) is to disable audit in the kernel cmdline with audit=0.

Isn't "auditctl -e 0" supposed to be enough stop the production of such audit messages?
Plus my systems have "-D" and "-a task,never" in /etc/audit/rules.d/audit.rules.
Shouldn't it already stop the auditing of at least user programs such as Evolution, Firefox, or Opera?

Am I interpreting things in the wrong way or is there some kind of bug in the toolset?

note: kernel 4.0.5-300.fc22.x86_64 - systemd-libs-219-18.fc22.x86_64
Comment 16 Steve Grubb 2015-06-22 09:10:25 EDT
In reply to comment #15, run auditctl -s and see if its enabled. I have a feeling that it is. Note that if you use the audit daemon, it by default enables the audit system unless you add the command line options, "-s=disable" or "-s=nochange".
Comment 17 Davide Repetto 2015-06-22 10:42:36 EDT
Several minutes after an "auditctl -e 0", the "auditctl -s" still reports "enabled 0". Yet the flow of audit logs doens't stop. Which is what made me wonder about a possible bug in honoring the flag.

# auditctl -s
enabled 0
flag 1
pid 584
rate_limit 0
backlog_limit 64
lost 52
backlog 0
backlog_wait_time 60000
loginuid_immutable 0 unlocked
Comment 18 Steve Grubb 2015-06-22 11:45:32 EDT
What kind of events are you seeing? SE Linux AVC's are the only audit events that are known to bypass the audit enabled flag by design, so anything else we'd want to check into.
Comment 19 Davide Repetto 2015-06-22 12:36:14 EDT
Stuff like this:
giu 22 11:30:22 dave.idp.it audit[1]: <audit-1131> pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=systemd-hostnamed comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
giu 22 11:31:03 dave.idp.it audit[1]: <audit-1130> pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=dnf-makecache comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
giu 22 11:31:03 dave.idp.it audit[1]: <audit-1131> pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=dnf-makecache comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'


And stuff like this:
giu 22 12:02:49 dave.idp.it audit[27902]: <audit-1326> auid=1000 uid=1000 gid=1000 ses=1 subj=unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023 pid=27902 comm="opera" exe="/usr/lib64/opera-stable/opera" sig=0 arch=c000003e syscall=273 compat=0 ip=0x3884a074f4 code=0x50000
giu 22 12:02:49 dave.idp.it audit[27902]: <audit-1326> auid=1000 uid=1000 gid=1000 ses=1 subj=unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023 pid=27902 comm="HTMLParserThrea" exe="/usr/lib64/opera-stable/opera" sig=0 arch=c000003e syscall=204 compat=0 ip=0x3884a10734 code=0x30000
giu 22 12:02:49 dave.idp.it audit[27902]: <audit-1326> auid=1000 uid=1000 gid=1000 ses=1 subj=unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023 pid=27902 comm="HTMLParserThrea" exe="/usr/lib64/opera-stable/opera" sig=0 arch=c000003e syscall=204 compat=0 ip=0x3884a10734 code=0x30000

This is what I kept before leaving the office. But if needed I can try and recreate the situation on a VM here at home, it shoudn't be difficult because it appears to happen also on clean installs.
Comment 20 Steve Grubb 2015-06-22 12:48:45 EDT
1130/31 are service start/stop respectively. They come from systemd itself. So, my guess is that systemd is handing these over internally rather than sending them to the kernel like it should so that they are serialized with other events.

The next one, 1326 comes from the seccomp framework. A quick check of the kernel source code shows that it is not consulting the audit_enabled flag in the kernel. Because its an independent security framework independent of the audit system, the upstream community may have chosen, like selinux, to ignore the flag because they want to let people know why an app was not allowed to do something. So, this would be a separate bug report on the kernel seccomp subsystem if you wanted to pursue a fix for it.
Comment 21 Stuart Auchterlonie 2015-06-22 17:57:10 EDT
Here's a further selection for you from my logs,
i've picked out one of each audit-<num> lines

<audit-1101> pid=7902 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:crond_t:s0-s0:c0.c1023 msg='op=PAM:accounting grantors=pam_access,pam_unix,pam_localuser acct="mailman" exe="/usr/sbin/crond" hostname=? addr=? terminal=cron res=success'
<audit-1103> pid=6293 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:crond_t:s0-s0:c0.c1023 msg='op=PAM:setcred grantors=pam_env,pam_unix acct="mailman" exe="/usr/sbin/crond" hostname=? addr=? terminal=cron res=success'
<audit-1104> pid=6293 uid=0 auid=41 ses=3435 subj=system_u:system_r:crond_t:s0-s0:c0.c1023 msg='op=PAM:setcred grantors=pam_env,pam_unix acct="mailman" exe="/usr/sbin/crond" hostname=? addr=? terminal=cron res=success'
<audit-1105> pid=6293 uid=0 auid=41 ses=3435 subj=system_u:system_r:crond_t:s0-s0:c0.c1023 msg='op=PAM:session_open grantors=pam_loginuid,pam_keyinit,pam_limits,pam_systemd acct="mailman" exe="/usr/sbin/crond" hostname=? addr=? terminal=cron res=success'
<audit-1106> pid=6567 uid=0 auid=41 ses=3436 subj=system_u:system_r:crond_t:s0-s0:c0.c1023 msg='op=PAM:session_close grantors=pam_loginuid,pam_keyinit,pam_limits,pam_systemd acct="mailman" exe="/usr/sbin/crond" hostname=? addr=? terminal=cron res=success'
<audit-1109> pid=6470 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:sshd_t:s0-s0:c0.c1023 msg='op=PAM:bad_ident grantors=? acct="?" exe="/usr/sbin/sshd" hostname=81.88.225.228 addr=81.88.225.228 terminal=ssh res=failed'
<audit-1110> pid=6293 uid=0 auid=41 ses=3435 subj=system_u:system_r:crond_t:s0-s0:c0.c1023 msg='op=PAM:setcred grantors=pam_env,pam_unix acct="mailman" exe="/usr/sbin/crond" hostname=? addr=? terminal=cron res=success'
<audit-1112> pid=6470 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:sshd_t:s0-s0:c0.c1023 msg='op=login acct="root" exe="/usr/sbin/sshd" hostname=? addr=81.88.225.228 terminal=ssh res=failed'

<audit-1123> pid=29112 uid=1000 auid=1000 ses=1 subj=unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023 msg='cwd="/home/stuarta" cmd=7375202D terminal=pts/0 res=success'

<audit-1300> arch=c000003e syscall=59 success=yes exit=0 a0=7fe0a56d48b0 a1=7fe0a57cba00 a2=7fe0a5836280 a3=7fe0a5729e00 items=0 ppid=1 pid=21368 auid=4294967295 uid=997 gid=996 euid=997 suid=997 fsuid=997 egid=996 sgid=996 fsgid=996 tty=(none) ses=4294967295 comm="amavisd" exe="/usr/bin/perl" subj=system_u:system_r:init_t:s0 key=(null)

<audit-1325> table=filter family=2 entries=0

<audit-1327> proctitle=2F7573722F62696E2F7065726C002D54002F7573722F7362696E2F616D6176697364002D63002F6574632F616D61766973642F616D61766973642E636F6E66
<audit-1401> op=security_bounded_transition seresult=denied oldcontext=system_u:system_r:init_t:s0 newcontext=system_u:system_r:antivirus_t:s0

<audit-2404> pid=6470 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:sshd_t:s0-s0:c0.c1023 msg='op=destroy kind=server fp=SHA256:1d:35:82:b7:17:e3:3a:87:5d:e9:df:9a:e2:90:56:2c:2f:8e:79:55:3b:d5:d6:cf:f1:70:25:d7:58:bd:fc:50 direction=? spid=6470 suid=0  exe="/usr/sbin/sshd" hostname=? addr=81.88.225.228 terminal=? res=success'
<audit-2407> pid=6470 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:sshd_t:s0-s0:c0.c1023 msg='op=start direction=from-client cipher=aes128-ctr ksize=128 mac=hmac-sha1 pfs=diffie-hellman-group14-sha1 spid=6471 suid=74 rport=56963 laddr=140.211.167.216 lport=22  exe="/usr/sbin/sshd" hostname=? addr=81.88.225.228 terminal=? res=success'
Comment 22 Alex Regan 2015-07-15 11:06:22 EDT
Is there any progress on this? Is there a temporary solution while it is being worked out?
Comment 23 Richard Guy Briggs 2015-07-16 13:42:04 EDT
This BZ is related, but doesn't completely address or explain what's happenning above:
"If no audit daemon is running, but an audit multicast subscriber is around, then the kernel shouldn't forward audit data to kmsg"
https://bugzilla.redhat.com/show_bug.cgi?id=1160046
Comment 24 Paul Moore 2015-07-16 14:32:02 EDT
(In reply to Steve Grubb from comment #20)
> The next one, 1326 comes from the seccomp framework. A quick check of the
> kernel source code shows that it is not consulting the audit_enabled flag in
> the kernel. Because its an independent security framework independent of the
> audit system, the upstream community may have chosen, like selinux, to
> ignore the flag because they want to let people know why an app was not
> allowed to do something. So, this would be a separate bug report on the
> kernel seccomp subsystem if you wanted to pursue a fix for it.

It is my opinion that we want to emit seccomp records regardless of the audit enabled/disable state, for much of the same reasons as SELinux.
Comment 25 Steve Grubb 2015-07-23 14:18:54 EDT
I think the root of the problem here is journald. There is a function, server_open_audit() which _enables_ audit even if people don't want it on. Journald should not enable audit, that is the audit daemon's job. What journald should do is:

1) Stop enabling audit.
2) Make it configurable as to whether or not to include audit data in the logs. Because its potentially mixing Top Secret data with unclassified data, there needs to be a way for people to shut that off when needed. If enabled, just attach to the multicast group and listen. AVC's will still come out. If not, open a bug on that. But enabling audit will slow the system down. If you want the highest performance of your system, audit must be disabled since boot and never turned on.
3) Make it configurable as to whether or not to pass audit data to syslog. Again, journald is the only thing that knows the provenance of the data stream. Therefore its incumbent on journald to prevent unintended reclassification of data.

The audit subsystem leaves sending event to syslog as a configuration option. It defaults to off because that is what the majority of the people wanted. Some people want it on, though, so that its aggregated and searchable by splunk. But this is the minority.
Comment 26 Benjamin Gordon 2015-07-28 00:44:06 EDT
For what it's worth, I've "fixed" this on my systems by adding this line to the beginning of the rules section in /etc/rsyslog.conf:

:programname, isequal, "audit" ~

This doesn't prevent systemd from putting the audit events in the journal or passing them to rsyslog, but it does keep them out of /var/log/messages.  I haven't observed any other bad effects, although I assume this would lose messages from programs that happen to be named audit.
Comment 27 Steve Grubb 2015-07-28 08:32:25 EDT
Created attachment 1057008 [details]
Patch that doesn't enable audit

This patch makes systemd not enable audit. It should be off unless enabled by the audit system or the user puts audit=1 on the command line.
Comment 28 Orion Poplawski 2015-08-14 11:49:02 EDT
Filed upstream: https://github.com/systemd/systemd/issues/959 in case that helps get any more traction on this.
Comment 29 dac.override 2015-08-24 07:32:31 EDT
Give us the possibility to disable audit in journald.

I tried to forcible stop journal from tapping the netlink_audit_socket using SELinux. It went completely nuts and effectively took my system down.

Aside from this issue. I cannot imagine how RHEL7 is used in any MLS-environment in any meaningful way.

I tried to configure MLS recently but couldnt get it to work. Mainly due to systemd. I was not able to get systemd-user running in the same mount namespace as the login user (/run/user/$UID poly instantiation) and systemd was mounting cgroupfs on MLS SystemHigh.

SELinux, to systemd maintainer, is not UNIX, and so do not expect any sympathy or compromise.
Comment 30 Eric Paris 2015-08-24 13:08:47 EDT
What version of journald 'took down the system' ? There was a bug that was suppsoedly fixed in systemd-219-19.fc22
Comment 32 dac.override 2015-08-24 13:45:20 EDT
(In reply to Eric Paris from comment #30)
> What version of journald 'took down the system' ? There was a bug that was
> suppsoedly fixed in systemd-219-19.fc22

That has been a while, granted. Not sure when i last tried that. Assuming that is fixed, I still do not see why this cannot be handled more gracefully. A simple option in journald.conf would make this all go away as far as I am concerned.
Comment 33 Eric Paris 2015-08-24 13:49:25 EDT
If you actually want the ability to analyze your system it is the only option. If you want to do it in a config file without changing selinux policy see:

https://github.com/systemd/systemd/issues/959#issuecomment-134304400

I admit, it's UGLY. But it is in config instead of policy.
Comment 34 dac.override 2015-08-24 14:31:42 EDT
(In reply to Eric Paris from comment #33)
> If you actually want the ability to analyze your system it is the only
> option. If you want to do it in a config file without changing selinux
> policy see:
> 
> https://github.com/systemd/systemd/issues/959#issuecomment-134304400
> 
> I admit, it's UGLY. But it is in config instead of policy.

I suppose that addresses my personal immediate concerns. I would appreciate if that solution would be documented (more prominently)

I really do hope though that journald behaves when it determines that its not allowed to be an audit client. I haven't tested it recently but I will take your word for it.
Comment 35 Mikhail Strizhov 2015-09-30 16:07:40 EDT
So, any workarounds for this bug? We are having tons of audit messages in dmesg and /var/log/messages.
Comment 36 Orion Poplawski 2015-09-30 23:00:31 EDT
(In reply to Eric Paris from comment #33)
> If you actually want the ability to analyze your system it is the only
> option. If you want to do it in a config file without changing selinux
> policy see:
> 
> https://github.com/systemd/systemd/issues/959#issuecomment-134304400
> 
> I admit, it's UGLY. But it is in config instead of policy.

Has this worked for anyone?  I've tried it but I still see audit stuff in the journal:

Sep 30 20:47:13 vmf23.cora.nwra.com audit[4071]: CRED_REFR pid=4071 uid=0 auid=0 ses=1 subj=unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023 msg='op=PAM:setcred grantors=pam_env,pam_localuser,pam_unix acct="root" exe="/usr/sbin/sshd" hostname=10.11.1.6 addr=10.11.1.6 terminal=ssh res=success'
Sep 30 20:50:01 vmf23.cora.nwra.com audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=sysstat-collect comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'

systemd-journal:
CapBnd: 00000005002800cf
Comment 37 Henrique Martins 2015-09-30 23:26:28 EDT
Until the dust settles, adding this to rsyslog.conf seems to remove all that crap from /var/log/messages

# don't log audit stuff
:programname, isequal, "audit" ~
Comment 38 Pete Zaitcev 2015-10-05 15:10:00 EDT
Yeah, that. Or simply this:

[zaitcev@guren ~]$ cat /etc/rc.d/rc.local 
#!/bin/sh
#
# This script will be executed *after* all the other init scripts.
# You can put your own initialization stuff in here if you don't
# want to do the full Sys V style init stuff.

# Fedora 22, massive pollution of logs
# https://bugzilla.redhat.com/show_bug.cgi?id=1227379
auditctl -e 0

touch /var/lock/subsys/local
[zaitcev@guren ~]$
Comment 39 Andy Lutomirski 2015-10-23 12:22:25 EDT
This seems all backwards to me.  I thought that one of the explicit purposes of systemd was to get rid of all of the manual make-sure-that-I-do-things-in-the-right-order stuff.  We shouldn't have to let journald turn on auditing and then somehow make sure that we overrule it late enough that it takes effect.

Can this at least be promoted to a journald config option?  (Also, auditing really is its own special thing, and I don't see why it makes sense for journald to touch the configuration at all.  Auditing is all tangled up in special Common Criteria guidelines and such, and I think that journald should just stay away.  Sticking AVC denials in the journal by default seems entirely reasonable.  Actually twiddling the audit state seems inappropriate.)

On the seccomp side, I've asked some other seccomp and audit people if the behavior should be changed so that seccomp only audits when auditing is on.
Comment 40 udo 2015-10-23 12:30:20 EDT
Systemd complicated many things since taking init's place.
Especially the logging is still a mess and journal-stuff is not really helping here.
How can we most quickly get back to a situation where we have no audit stuff when we want it like that, message file stuff in messages, and the rest of the messages (.xsession-errors stuff, crond, secure,  etc) in places where they once were?
That was so much more practical.
Less bugs to deal with too.
Comment 42 Andy Lutomirski 2015-10-23 16:23:43 EDT
As mentioned in the FESCo ticket, I think that systemd has broken audit support.  Configuring the kernel audit subsystem requires more than just setting the audit-enabled flag.  The user code is also supposed to read the configuration in /etc/audit/audit.rules and apply it.

Unfortunately, auditd picks up the requested value of the enabled flag from the command line -- it would be nice if it lived in the config files.

Nonetheless, if systemd is going to enable audit, it should also load the rules.  Failure to do so breaks FESCo ticket #1311 and hurts performance.  On a default Fedora configuration, there should be no time during which any process whatsoever can be created while audit is on and the rules are not loaded.  systemd makes this impossible.
Comment 43 Eric Paris 2015-10-23 16:54:57 EDT
Systemd should, in my mind, enable audit but disable syscall audit by default. That is enough to solve the FESCo/performance issue and auditd when it starts (if it starts) will set up things in a CC complaint way.

systemd is not replacing auditd here. It's merely listening (and aggregating) what auditd also gets.

As to all the crap in the journal/syslog I don't really blame systemd that the greater 'audit' system (auditd + kernel + pam + login + ssh + nss + openssh + polkit + god know what else) writes all sorts of messages that no one asked for (even though every single on of those messages has some purpose for someone, maybe even you)
Comment 44 Steve Grubb 2015-10-23 17:02:30 EDT
Enabling audit is enabling syscall audit. They are the same. Journald should not be messing with the audit settings. That would make the problem go away and everyone will be happy like before. AVCs go to syslog if auditd is not running, so it can get them there.
Comment 45 Eric Paris 2015-10-23 17:12:36 EDT
Agreed, they are the same, which is broken/stupid and was a bad decision long ago when it was implemented . It's what FESCo asked auditd to work around. Now I ask ask systemd to do the same. Enable audit, but turn syscall audit back off, for people up the stack to "do the right thing"

Not everyone was happy before. I for one love having all my logs in a single indexed searchable place...
Comment 46 Josh Boyer 2015-10-28 11:14:55 EDT
Eric, Zbigniew, did the request in comment #45 get implemented at all?  I won't comment on the broader aspects of systemd/journald toggling audit itself, but having journald leaving syscall auditing off does seem to be the minimum required approach here.
Comment 47 Steve Grubb 2015-10-28 11:46:28 EDT
In reply to comment #46, if journald loads rules marks processes not auditable and then later the audit daemon starts and wants to audit all processes, then we have a bunch of processes that escaped. The design of the audit system is such that when a process is marked unauditable, it can never be audited in the future. So, journald really should not be messing with the audit system.
Comment 48 Eric Paris 2015-10-28 12:03:32 EDT
(In reply to Steve Grubb from comment #47)

Fair point. systemd should only set -a task,never if audit=1 is not present on the kernel command line. So the situation would be the same as today...  you need audit=1 to make early processes audit-able and systemd wouldn't ruin that.

without audit=1 processes before auditd are already unauditable, and thus no change...
Comment 49 Steve Grubb 2015-10-28 13:44:24 EDT
Well, if you want to bring the boot command into this, then why don't you use that to enable audit when you want extra events and journald just doesn't do anything to audit? This want everyone who doesn't want events in their logs get that by default just like it used to be.
Comment 50 Josh Boyer 2015-10-28 13:59:09 EDT
The last two comments confused me.  Can you walk me through this like the simpleton I am?

Before journald started doing stuff with audit, Fedora was configured such that syscall auditing was off for all processed by default.  If auditd wasn't installed, then this remained the case.  If auditd was installed and started, it still remained in effect because the config file for auditd disables syscall auditing by default.  This was all done via bug 1117953.  (I believe this is correct).

With journald doing audit stuff, this is no longer the case.  It enables auditing internally, which means it doesn't consult the auditd configuration at all.  The current manner in which it enables audit is such that audit is enabled entirely including syscall auditing.  (I believe that is also correct.)

So I'm confused by we can't have journald enable audit but not enable syscall auditing.  Please explain?
Comment 51 Steve Grubb 2015-10-28 14:04:20 EDT
Its a terminology misnomer. If audit is enabled, syscall auditing is enabled. What auditd was commanded to do by FESCO is load rules that mark all processes permanently unauditable. This short circuits some audit data collection and improves performance.

That said, the audit system can be independently enabled on the kernel boot prompt by adding audit=1, meaning that anyone wanting extra audit events can just do that without systemd touching the audit system. By default, its off and people don't get extra events.
Comment 52 Eric Paris 2015-10-28 14:52:54 EDT
@josh but it's clear as mud!

Before FESCO:

auditd (when enabled by default) would turn on audit in the kernel. processes launched before auditd would be completely un-auditable unless the kernel was launched with audit=1. All processes launched after audit would have syscall audit enabled, which has a performance penalty.

After FESCO:

audit (when enabled by default) would turn on audit in the kernel. processes launched before auditd would be completely un-auditable unless the kernel was launched with audit=1. But an extra auditd rules was added by default which would cause all processes launched AFTER auditd to also be un-auditable. And thus not suffer the perf hit.



In both cases, if auditd was never started, kernel audit was never enabled and syscall audit was never enabled for any processes. Thus no perf hit.



Systemd:

In the last case, where people don't want auditd AT ALL systemd returned us to (very close to) the pre-FESCO decision. It turns on audit in the kernel. And thus processes after system have syscall audit enabled. All system processes take a performance hit because of the kernel default "syscall audit for all when audit enabled"

If auditd is installed and enabled (with default rules) it will then disable syscall audit for all processes launched after auditd.

***********
Opinion/My Suggestion:

If systemd is going to enable kernel audit it should follow the FESCO decision and automatically load the "do not enable syscall audit for any process" rule. If should, however, NOT do this if the kernel command line has audit=1, as that means users care about audit being enabled for processes before auditd.  For users who do not care about audit for processes launched before auditd (those who do not explicitly add audit=1) this will have NO effect as auditd will load the appropriate rule set.
Comment 53 Jiri Jaburek 2015-11-13 09:36:16 EST
Can somebody please point out what's wrong with my scenario?

Users who don't care about auditing (most Fedora users, some RHEL users):
 * run without any audit= option
 * have auditd disabled / uninstalled
 * suffer no performance hit or any additional complications

Users who care about auditing (RHEL CC, etc.):
 * run with audit=1 kernel boot option (set during auditd installation)
 * have auditd installed and enabled

and the boot process would work like

 1) kernel boots, with kauditd active, any AVCs are stored in the klog
    ring buffer
 2) systemd/journald boots, it treats AVCs in klog like any other misc
    klog output, no special interpretation
 3) auditd boots, reads klog, configures kauditd, logs processed AVCs
    to /var/log/audit AND/OR via journald to indexed binary log storage

This way,
 * journald makes no effort/decision about the auditing subsystem
 * auditd retains full control what to enable when and where
 * journald effectively does only what it should - processes logs from
   auditd, which can do simply syslog(3) or use some journald API

I'm not trying to point out what (out of the 2 scenarios above) should
be the default for Fedora and which one should be the default for RHEL,
just elaborating on whether we need to support some middle-case between
the two.

Or maybe I missed something and this was already considered before.

Thanks.
Comment 54 Eric Paris 2015-11-13 10:23:18 EST
There is nothing "wrong" with your thought. My opinion is that if the system is generating information which can be correctly collected, attributed, logged, etc with little/no penalty it should. You seem to be of the opinion that such things should be dropped entirely. Maybe they shouldn't be generated. Maybe you're right. I kinda see it as a fundamental flaw in the design of 'audit'.

Remember, audit is not just kernel+auditd. There are patches hacked into PAM, login, nss, openssl, all of the dang place. Going through syslog removes all possibility of reliability, attribution, etc. There's a reason things go through journal to get to syslog instead of the other way around.

Lets just that I do see there being 2 'problems'/'bugs'.

1) systemd enables kernel audit, but does not disable syscall audit, which causes a performance hit for the entire system. This sucks and should be fixed in systemd.

2) The kernel spams all audit messages to dmesg when kernel audit is turned on but auditd is not running and there is no way to stop that. I think this is a kernel bug. I even wrote kernel patches to allow it to be stopped. I think these died because Paul Moore didn't want any patches while he fixed all of the terribleness that is audit. I'm not sure how his (sisyphean) task is going and if he plans to resurrect these. (After the kernel is patched systemd can stop it from spamming kmsg foolishly)
Comment 55 Steve Grubb 2015-11-13 10:46:31 EST
In reply to comment #53, the first two paragraphs are the correct goals. There is a middle use case where people want to use syslog transport to aggregate logs. They use a specific audispd-plugin so that audispd correctly labels the facility that audit events get written to syslog. So, it has always been the case that auditd could put events into syslog the way that the admin wants it.

The current situation causes mixing of security officer and sysadmin roles. This is forbidden. There seems to be no good way to turn that off. For people that do not care about auditing, journal's turning on the audit system spams the logs with duplicate information. AVC's are written to syslog and audit, login events are written to both syslog and audit, user account events are wriiten to both syslog and audit. There is no need to have duplicate information. You also get a performance hit when perhaps no one knew it would happen.

Making journald do audit things is the wrong answer. It has no business controlling a subsystem that is not its own. It already gets a copy of user space security events via syslog. All the duplication fills the logs and causes logs to rotate faster thus losing information you might need.
Comment 56 Jiri Jaburek 2015-11-13 10:50:53 EST
(In reply to Eric Paris from comment #54)
> There is nothing "wrong" with your thought. My opinion is that if the system
> is generating information which can be correctly collected, attributed,
> logged, etc with little/no penalty it should. You seem to be of the opinion
> that such things should be dropped entirely. Maybe they shouldn't be
> generated.

My idea was not to drop messages, but have a central aggregator for them - auditd, which then passes them to journald (if desired). The aggregator would collect messages from the kernel (through which PAM/login/su/nss/.. send their msgs, IIRC), audit plugins (ie. audisp-remote), taking care of the configuration of what should or should not be parsed/logged.
Journald would then simply store/index the result provided by auditd.

All the information are accounted for as long as the klog buffer is large enough to contain all AVCs generated prior to auditd start (and kauditd configuration) without systemd/journald having to do anything as (AFAIK) auditd reads the klog to get messages generated prior to its start. If not, that may be the flaw in my grand plan.
Comment 57 Eric Paris 2015-11-13 11:06:31 EST
(In reply to Jiri Jaburek from comment #56)
> My idea was not to drop messages, but have a central aggregator for them -
> auditd, which then passes them to journald (if desired). The aggregator
> would collect messages from the kernel (through which PAM/login/su/nss/..
> send their msgs, IIRC), audit plugins (ie. audisp-remote), taking care of
> the configuration of what should or should not be parsed/logged.
> Journald would then simply store/index the result provided by auditd.

I think this is the philosophical difference held by many, and not one I bet either of us convinces the other  :)  Auditd is not a central aggregator. It is a dumping ground for only its own messages. journald is an aggregator. journald neither creates nor destroys messages. It simply puts them in the journal. journald neither interferes with auditd nor requires it. journald should be completely orthogonal and should have no impact.

That is not the case today. journald causes 2 different impacts on the system.  I think no matter where you fall on the philosophical design side of things, we all agree those impacts should be fixed.

> All the information are accounted for as long as the klog buffer is large
> enough to contain all AVCs generated prior to auditd start (and kauditd
> configuration) without systemd/journald having to do anything as (AFAIK)
> auditd reads the klog to get messages generated prior to its start. If not,
> that may be the flaw in my grand plan.

<pedantic> Not quite. Auditd does not read klog at all. If you boot kernel with audit=1, the kernel will queue audit messages until auditd starts and will forward them to auditd (as well as forward those audit messages to klog). If you do not boot with audit=1 audit messages before auditd starts are in klog/dmesg but not in audit log. systemd makes no changes here and has no affect. The fact that systemd enabled kernel audit slightly sooner has no real impact on this bit of wacky design. I also don't think this <pedantic> has any material implication to your position.
Comment 58 Paul Moore 2015-11-13 11:22:58 EST
(In reply to Eric Paris from comment #54)
> 2) The kernel spams all audit messages to dmesg when kernel audit is turned
> on but auditd is not running and there is no way to stop that. I think this
> is a kernel bug. I even wrote kernel patches to allow it to be stopped. I
> think these died because Paul Moore didn't want any patches while he fixed
> all of the terribleness that is audit. I'm not sure how his (sisyphean) task
> is going and if he plans to resurrect these. (After the kernel is patched
> systemd can stop it from spamming kmsg foolishly)

<grumble> <grumble> <grumble>

I thought this was a BZ already, yes?  no?  If not, it would be appreciated if you can create one and attach the patchset so it doesn't get lost.
Comment 59 Jiri Jaburek 2015-11-13 11:28:45 EST
(In reply to Eric Paris from comment #57)
> (In reply to Jiri Jaburek from comment #56)
> > My idea was not to drop messages, but have a central aggregator for them -
> > auditd, which then passes them to journald (if desired). The aggregator
> > would collect messages from the kernel (through which PAM/login/su/nss/..
> > send their msgs, IIRC), audit plugins (ie. audisp-remote), taking care of
> > the configuration of what should or should not be parsed/logged.
> > Journald would then simply store/index the result provided by auditd.
> 
> I think this is the philosophical difference held by many, and not one I bet
> either of us convinces the other  :)

I personally don't care either way - my point was
 * auditd = aggregator for audit-related messages
 * journald = aggregator for system-wide logs
where auditd is "under" journald in an imaginary "aggregator tree".

To use an analogy, mcelog aggregates hardware error logs, potentially passing
them to journald for further aggregation/archival. There's no point in having
mcelog functionality (configuration/filters) in journald.

I don't know, maybe there's something philosophical about it that I'm missing.
:)

> Auditd is not a central aggregator. It
> is a dumping ground for only its own messages. journald is an aggregator.
> journald neither creates nor destroys messages. It simply puts them in the
> journal. journald neither interferes with auditd nor requires it. journald
> should be completely orthogonal and should have no impact.
> 
> That is not the case today. journald causes 2 different impacts on the
> system.  I think no matter where you fall on the philosophical design side
> of things, we all agree those impacts should be fixed.
> 
> > All the information are accounted for as long as the klog buffer is large
> > enough to contain all AVCs generated prior to auditd start (and kauditd
> > configuration) without systemd/journald having to do anything as (AFAIK)
> > auditd reads the klog to get messages generated prior to its start. If not,
> > that may be the flaw in my grand plan.
> 
> <pedantic> Not quite. Auditd does not read klog at all. If you boot kernel
> with audit=1, the kernel will queue audit messages until auditd starts and
> will forward them to auditd (as well as forward those audit messages to
> klog). If you do not boot with audit=1 audit messages before auditd starts
> are in klog/dmesg but not in audit log. systemd makes no changes here and
> has no affect. The fact that systemd enabled kernel audit slightly sooner
> has no real impact on this bit of wacky design. I also don't think this
> <pedantic> has any material implication to your position.

If I start without any audit= option and with auditd disabled, I get
no messages in klog (RHEL7).

So unless the behavior changed, I don't see any problem with the two scenarios
I described earlier - systemd/journald interaction with the audit subsystem
is unnecessary in either of them. The problems start appearing only if we decide
to support gray areas between the two.

That is, unless the goal was to deprecate auditd in favor of journald.
Comment 60 Michael Cronenworth 2015-11-16 09:13:08 EST
(In reply to Pete Zaitcev from comment #38)
> auditctl -e 0

There is a weekly job that reactivates audit so this isn't a perfect workaround. I do have the audit package installed, but I do not see any cron job or any other job that would turn audit back on.
Comment 61 Oliver Henshaw 2016-02-05 08:23:26 EST
(In reply to dac.override from comment #41)
> Related:
> 
> https://github.com/keszybz/systemd/commit/
> 7d18d348da26fdbb392c76b0f5edb7f06282afbb

If I read the git history right, this is in systemd v228 so will be in Fedora 24 (and not any earlier release)
Comment 62 Sergio Monteiro Basto 2016-02-20 11:18:23 EST
Have we any workaround to stop audit spam /var/log/messages and dmesg ?
Comment 63 Eddie Lania 2016-02-21 08:03:19 EST
Is there a workaround to stop audit spam /var/log/messages and dmesg ?
Comment 64 Eddie Lania 2016-03-09 02:43:11 EST
Please can somebody give a solution or workaround?
Comment 65 Jiri Jaburek 2016-03-09 08:18:43 EST
(In reply to Eddie Lania from comment #64)
> Please can somebody give a solution or workaround?

To disable audit completely, you can use 'audit=0' on kernel cmdline. The systemd argument is to have you explicitly opt-out of this instead of opt-in (with 'audit=1').

https://github.com/systemd/systemd/issues/959#issuecomment-131174949

If you want to keep auditing enabled, but disable its logging by journald, you can use

  systemctl mask systemd-journald-audit.socket

and restart journald.

https://github.com/systemd/systemd/issues/959#issuecomment-134304400

If you want to keep auditing enabled *and* journald logging it, just without passing it to /var/log/messages, I guess the best option would be to filter it out by whatever writes /var/log/messages on your system, an rsyslog filter if you use rsyslog - see comment #26.
Comment 66 Eddie Lania 2016-03-11 05:33:52 EST
Thank You.

I use the third option as in comment #26.


I am a bit worried about SELinux messages not to show up in the messages log anymore.
Comment 67 Fedora End Of Life 2016-07-19 10:28:28 EDT
Fedora 22 changed to end-of-life (EOL) status on 2016-07-19. Fedora 22 is
no longer maintained, which means that it will not receive any further
security or bug fix updates. As a result we are closing this bug.

If you can reproduce this bug against a currently maintained version of
Fedora please feel free to reopen this bug against that version. If you
are unable to reopen this bug, please file a new report against the
current release. If you experience problems, please add a comment to this
bug.

Thank you for reporting this bug and we are sorry it could not be fixed.
Comment 68 udo 2016-07-19 10:33:46 EDT
Systemd still (!) does not know how to behave:
Very regularly it spams:

systemd: Cannot add dependency job for unit systemd-journald-audit.socket, ignoring: Unit systemd-journald-audit.socket is masked.


Why oh why?
Comment 69 Jan Kurik 2016-07-26 01:06:26 EDT
This bug appears to have been reported against 'rawhide' during the Fedora 25 development cycle.
Changing version to '25'.
Comment 70 John Griffiths 2016-09-26 10:52:29 EDT
This is happening in version 24.
Comment 71 Oliver Henshaw 2016-12-09 06:30 EST
Created attachment 1229934 [details]
'journalctl -b | grep "audit:" ' from boot to sddm with systemd-journald-audit.socket masked and dracut regenerated

Is this entirely fixed? If I take an F25 install (in a VM from the kde spin and updated to the current package set) and mask systemd-journald-audit.socket then the number of audit events in the journal falls, but does not reach zero. Regenerating the dracut image cuts the number of audit lines further but there are still some left

(boot systemd)
# journalctl -b | grep "audit:" | wc -l
77

# systemctl mask systemd-journald-audit.socket
(reboot)
# journalctl -b | grep "audit:" | wc -l
21

# dracut -f
(reboot)
# journalctl -b | grep "audit:" | wc -l
11

The remaining audit lines in the log are attached.


audit-2.6.7-1.fc25.x86_64
kernel-4.8.10-300.fc25.x86_64
systemd-231-10.fc25.x86_6
Comment 72 udo 2016-12-09 07:08:14 EST
The workarounds mentioned work very well for me.
But they are workarounds and no solution...
(F24 with kernels-compiledby-me(tm))
Comment 73 udo 2017-11-06 09:15:18 EST
Another workaround could be to filter things from the logs.
Not exactly tailored for this specific bug but to work as an idea:

# pwd
/etc/rsyslog.d
# cat drop-user-messages.conf 
:syslogtag,contains,"yum"       stop
:syslogtag,contains,"cupsd"       stop
:msg,contains,"[system] Activating via systemd: service name"    stop
:msg,contains,"[system] Successfully activated service"    stop
user.* -/var/log/user.log
& stop


This rsyslog config file puts all 'user' category logging in a separate log
file, away from /var/log/messages.
All 'user' stuff, except for yum and cupsd that weirdly enough are also in the
'user' category.
Then we also filter out messages containing "[system] Activating via systemd:
service name" and messages containing "[system] Successfully activated
service".
The syslogtag filter could be applied to audit.
Comment 74 Fedora End Of Life 2017-11-16 13:33:29 EST
This message is a reminder that Fedora 25 is nearing its end of life.
Approximately 4 (four) weeks from now Fedora will stop maintaining
and issuing updates for Fedora 25. It is Fedora's policy to close all
bug reports from releases that are no longer maintained. At that time
this bug will be closed as EOL if it remains open with a Fedora  'version'
of '25'.

Package Maintainer: If you wish for this bug to remain open because you
plan to fix it in a currently maintained version, simply change the 'version'
to a later Fedora version.

Thank you for reporting this issue and we are sorry that we were not
able to fix it before Fedora 25 is end of life. If you would still like
to see this bug fixed and are able to reproduce it against a later version
of Fedora, you are encouraged  change the 'version' to a later Fedora
version prior this bug is closed as described in the policy above.

Although we aim to fix as many bugs as possible during every release's
lifetime, sometimes those efforts are overtaken by events. Often a
more recent Fedora release includes newer upstream software that fixes
bugs or makes them obsolete.
Comment 75 Philip Prindeville 2018-10-16 12:53:41 EDT
If this is never going anywhere, should it just be closed as WONTFIX and we’ll just accept that audit logs will be like searching for a needle in a haystack and hence of no use to anyone?
Comment 76 Steve Grubb 2018-10-16 13:55:13 EDT
Masking systemd-journald-audit.socket should stop audit events that came from the journal. There are times when audit events can be written to syslog by the kernel. If audit is enabled and the audit daemon disappears is one. And I also think that AVC's will go there in addition to the audit log.
Comment 77 Philip Prindeville 2018-10-16 14:44:41 EDT
(In reply to Steve Grubb from comment #76)
> Masking systemd-journald-audit.socket should stop audit events that came
> from the journal. There are times when audit events can be written to syslog
> by the kernel. If audit is enabled and the audit daemon disappears is one.
> And I also think that AVC's will go there in addition to the audit log.

Why not have exceptional events extracted by logwatch while suppressing routine events?

At the very least, repeating events like dnf-make-cache could be factored down to a single line with a count like what is done for sendmail.

Note You need to log in before you can comment on or make changes to this bug.