Bug 1449831 - audit has begun spamming virtual consoles with messages relating to logins
Summary: audit has begun spamming virtual consoles with messages relating to logins
Keywords:
Status: CLOSED NOTABUG
Alias: None
Product: Fedora
Classification: Fedora
Component: audit
Version: 25
Hardware: All
OS: Linux
unspecified
low
Target Milestone: ---
Assignee: Steve Grubb
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2017-05-10 20:17 UTC by David H. Gutteridge
Modified: 2017-05-16 13:53 UTC (History)
1 user (show)

Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2017-05-16 13:53:15 UTC
Type: Bug
Embargoed:


Attachments (Terms of Use)

Description David H. Gutteridge 2017-05-10 20:17:32 UTC
Description of problem:
Recently, audit began spamming my virtual consoles with messages such as:

[47362.898982] audit: type=1100 audit(1494446835.336:711): pid=14799 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:local_login_t:s0-s0:c0.c1023 msg='op=PAM:authentication grantors=pam_unix acct="disciple" exe="/usr/bin/login" hostname=arcusix.nonus-porta.net addr=? terminal=tty3 res=success'
[47362.902650] audit: type=1101 audit(1494446835.339:712): pid=14799 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:local_login_t:s0-s0:c0.c1023 msg='op=PAM:accounting grantors=pam_unix,pam_localuser acct="disciple" exe="/usr/bin/login" hostname=arcusix.nonus-porta.net addr=? terminal=tty3 res=success'
[47362.914368] audit: type=1103 audit(1494446835.351:713): pid=14799 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:local_login_t:s0-s0:c0.c1023 msg='op=PAM:setcred grantors=pam_unix acct="disciple" exe="/usr/bin/login" hostname=arcusix.nonus-porta.net addr=? terminal=tty3 res=success'
[47362.915133] audit: type=1006 audit(1494446835.352:714): pid=14799 uid=0 subj=system_u:system_r:local_login_t:s0-s0:c0.c1023 old-auid=4294967295 auid=1000 tty=tty3 old-ses=4294967295 ses=10 res=1
[47362.959012] audit: type=2300 audit(1494446835.396:715): pid=14799 uid=0 auid=1000 ses=10 subj=system_u:system_r:local_login_t:s0-s0:c0.c1023 msg='pam: default-context=unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023 selected-context=unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023 exe="/usr/bin/login" hostname=arcusix.nonus-porta.net addr=? terminal=tty3 res=success'
[47362.999942] audit: type=1105 audit(1494446835.435:716): pid=14799 uid=0 auid=1000 ses=10 subj=system_u:system_r:local_login_t:s0-s0:c0.c1023 msg='op=PAM:session_open grantors=pam_selinux,pam_loginuid,pam_selinux,pam_namespace,pam_keyinit,pam_keyinit,pam_limits,pam_systemd,pam_unix,pam_lastlog acct="disciple" exe="/usr/bin/login" hostname=arcusix.nonus-porta.net addr=? terminal=tty3 res=success'
[47363.000156] audit: type=1110 audit(1494446835.435:717): pid=14799 uid=0 auid=1000 ses=10 subj=system_u:system_r:local_login_t:s0-s0:c0.c1023 msg='op=PAM:setcred grantors=pam_unix acct="disciple" exe="/usr/bin/login" hostname=arcusix.nonus-porta.net addr=? terminal=tty3 res=success'
[47363.000288] audit: type=1112 audit(1494446835.436:718): pid=14799 uid=0 auid=1000 ses=10 subj=system_u:system_r:local_login_t:s0-s0:c0.c1023 msg='op=login id=1000 exe="/usr/bin/login" hostname=arcusix.nonus-porta.net addr=? terminal=tty3 res=success'

I don't know if this is an issue with audit itself, or something else. I've just started experiencing this in the past weeks.

Version-Release number of selected component (if applicable):
audit-2.7.6-1.fc25

How reproducible:
Always.

Steps to Reproduce:
1. Log into a virtual console.
2. Observe immediately there are audit messages being output concerning the fact you just logged on.
3. Observe there are more messages being output when running a command via sudo, e.g. a script that requires elevated privileges to gather information. Observe in that case the audit output is mixed in between regular lines of output to stdout, which is not optimal.

Actual results:
As above.

Expected results:
Not being subjected to many lines of undesired audit output. (It violates the "principle of least surprise", which I'm a big fan of: don't change the default behaviour of a program in ways that will surprise or confound a user, especially in a CLI environment.)

Comment 1 Steve Grubb 2017-05-10 20:40:19 UTC
I have no idea how this is happening. Audit events are read from the kernel into auditd and it writes them to disk. It never writes to consoles.

Comment 2 Steve Grubb 2017-05-10 20:41:32 UTC
Actually, auditd writes to stderr if its launched with the '-f' command line option.

Comment 3 David H. Gutteridge 2017-05-10 20:54:49 UTC
My environments are mostly stock Fedora 25 in terms of configuration. auditd isn't launched with the -f command line option (unless ps is lying to me).

My auditd service file is:

$ more auditd.service 
[Unit]
Description=Security Auditing Service
DefaultDependencies=no
## If auditd.conf has tcp_listen_port enabled, copy this file to
## /etc/systemd/system/auditd.service and add network-online.target
## to the next line so it waits for the network to start before launching.
After=local-fs.target systemd-tmpfiles-setup.service
Conflicts=shutdown.target
Before=sysinit.target shutdown.target
RefuseManualStop=yes
ConditionKernelCommandLine=!audit=0
Documentation=man:auditd(8) https://github.com/linux-audit/audit-documentation

[Service]
Type=forking
PIDFile=/var/run/auditd.pid
ExecStart=/sbin/auditd
## To not use augenrules, copy this file to /etc/systemd/system/auditd.service
## and comment/delete the next line and uncomment the auditctl line.
## NOTE: augenrules expect any rules to be added to /etc/audit/rules.d/
ExecStartPost=-/sbin/augenrules --load
#ExecStartPost=-/sbin/auditctl -R /etc/audit/audit.rules
ExecReload=/bin/kill -HUP $MAINPID
# By default we don't clear the rules on exit. To enable this, uncomment
# the next line after copying the file to /etc/systemd/system/auditd.service
#ExecStopPost=/sbin/auditctl -R /etc/audit/audit-stop.rules

[Install]
WantedBy=multi-user.target

Comment 4 Steve Grubb 2017-05-10 21:45:32 UTC
What happens if you stop journald or rsyslog? Auditd doesn't write to anything but the disk.

Comment 5 David H. Gutteridge 2017-05-11 21:24:21 UTC
I rebooted before experimenting with stopping journald, and whatever was going on ended after the reboot. I can't duplicate this anymore. I have no idea why it was happening and then stopped (at least for now), since I haven't made any configuration changes of late, and the package updates applied recently all seem to be completely unrelated.

Looking back two boots ago, I can see it wasn't happening then, either, so it was specific to one time, it seems:

Kernel 4.10.14, up for a few days:
$ journalctl -k -b -2 | grep audit | wc
     55    1034   14428

Kernel 4.10.15, up for a couple of days:
$ journalctl -k -b -1 | grep audit | wc
    668   12179  182114

Kernel 4.10.15, up since this morning (with a bunch of logins, as per usual):
$ journalctl -k | grep audit | wc
     42     797   11077

This can be closed if need be, and I'll reopen if I experience this again. Thanks for your quick response!

Comment 6 Steve Grubb 2017-05-16 13:53:15 UTC
OK. Thanks for checking on this. I will close it as the code that writes to the logging file hasn't changed much in a year. I'd almost bet it was journald related since it spams syslog with audit events.


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