Bug 457061 - Many, many messages discard (full queue) during startup
Summary: Many, many messages discard (full queue) during startup
Keywords:
Status: CLOSED CURRENTRELEASE
Alias: None
Product: Fedora
Classification: Fedora
Component: audit
Version: 9
Hardware: All
OS: Linux
low
low
Target Milestone: ---
Assignee: Steve Grubb
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2008-07-29 14:20 UTC by Charlie Brady
Modified: 2013-02-04 11:07 UTC (History)
3 users (show)

Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed: 2008-09-25 18:29:43 UTC
Type: ---
Embargoed:


Attachments (Terms of Use)

Description Charlie Brady 2008-07-29 14:20:32 UTC
FC9, fully updated. I enabled selinux in enforcing mode, told it to relable on
next reboot, and then rebooted, and left it overnight. In the morning it was
still clunking away busily, and unusable. After reboot with selinux disabled, I
find these syslog messages:

Jul 28 01:40:57 localhost kernel: imklog 3.16.1, log source = /proc/kmsg started.
Jul 28 01:40:57 localhost rsyslogd: [origin software="rsyslogd"
swVersion="3.16.1" x-pid="2012" x-info="http://www.rsyslog.com"] restart
Jul 28 01:40:58 localhost audispd: queue is full - dropping event
Jul 28 01:40:59 localhost audispd: queue is full - dropping event
Jul 28 01:40:59 localhost audispd: queue is full - dropping event
Jul 28 01:41:00 localhost kernel: printk: 1793714 messages suppressed.
Jul 28 01:41:00 localhost kernel: audit: audit_backlog=326 > audit_backlog_limit=320
Jul 28 01:41:05 localhost kernel: printk: 1798331 messages suppressed.
Jul 28 01:41:05 localhost kernel: audit: audit_backlog=326 > audit_backlog_limit=320
Jul 28 01:41:06 localhost audispd: queue is full - dropping event
Jul 28 01:41:06 localhost audispd: queue is full - dropping event
...
Jul 28 01:41:10 localhost audispd: queue is full - dropping event
Jul 28 01:41:10 localhost audispd: queue is full - dropping event
Jul 28 01:41:10 localhost kernel: printk: 1793048 messages suppressed.
Jul 28 01:41:10 localhost kernel: audit: audit_backlog=321 > audit_backlog_limit=320
Jul 28 01:41:10 localhost audispd: queue is full - dropping event
Jul 28 01:41:10 localhost audispd: queue is full - dropping event
Jul 28 01:41:10 localhost audispd: queue is full - dropping event
...
Jul 28 02:21:51 localhost audispd: queue is full - dropping event
Jul 28 02:21:51 localhost audispd: queue is full - dropping event
Jul 28 02:21:55 localhost kernel: printk: 1783088 messages suppressed.
Jul 28 02:21:55 localhost kernel: audit: audit_backlog=326 > audit_backlog_limit=320
Jul 28 02:22:00 localhost kernel: printk: 1787699 messages suppressed.
Jul 28 02:22:00 localhost kernel: audit: audit_backlog=326 > audit_backlog_limit=320
Jul 28 02:22:05 localhost kernel: printk: 1791258 messages suppressed.
Jul 28 02:22:05 localhost kernel: audit: audit_lost=855520514 audit_rate_limit=0
audit_backlog_limit=320
Jul 28 02:22:10 localhost kernel: printk: 1782535 messages suppressed.
...
Jul 28 02:23:05 localhost kernel: audit: audit_backlog=326 > audit_backlog_limit=320
Jul 28 02:23:10 localhost kernel: printk: 1787558 messages suppressed.
Jul 28 02:23:10 localhost kernel: audit: audit_backlog=326 > audit_backlog_limit=320
Jul 28 02:23:12 localhost audispd: queue is full - dropping event
Jul 28 02:23:12 localhost audispd: queue is full - dropping event
Jul 28 02:23:12 localhost audispd: queue is full - dropping event
...
Jul 28 08:39:50 localhost kernel: audit: audit_backlog=326 > audit_backlog_limit=320
Jul 28 08:39:55 localhost kernel: printk: 1797635 messages suppressed.
Jul 28 08:39:55 localhost kernel: audit: audit_backlog=326 > audit_backlog_limit=320
Jul 28 08:40:00 localhost kernel: printk: 1793795 messages suppressed.
Jul 28 08:40:00 localhost kernel: audit: audit_backlog=326 > audit_backlog_limit=320
Jul 28 08:40:01 localhost gconfd (charlieb-31276): starting (version 2.22.0),
pid 31276 user 'charlieb'
Jul 28 08:40:01 localhost gconfd (charlieb-31276): Resolved address
"xml:readonly:/etc/gconf/gconf.xml.mandatory" to a read-only configurati
on source at position 0
Jul 28 08:40:01 localhost gconfd (charlieb-31276): Resolved address
"xml:readwrite:/home/charlieb/.gconf" to a writable configuration source
 at position 1
Jul 28 08:40:01 localhost gconfd (charlieb-31276): Resolved address
"xml:readonly:/etc/gconf/gconf.xml.system" to a read-only configuration 
source at position 2
Jul 28 08:40:01 localhost gconfd (charlieb-31276): Resolved address
"xml:readonly:/etc/gconf/gconf.xml.defaults" to a read-only configuratio
n source at position 3
Jul 28 08:40:05 localhost kernel: printk: 1793900 messages suppressed.
Jul 28 08:40:05 localhost kernel: audit: audit_backlog=326 > audit_backlog_limit=320
Jul 28 08:40:10 localhost kernel: printk: 1779674 messages suppressed.
Jul 28 08:40:10 localhost kernel: audit: audit_backlog=326 > audit_backlog_limit=320
Jul 28 08:40:15 localhost kernel: printk: 1792682 messages suppressed.
Jul 28 08:40:15 localhost kernel: audit: audit_backlog=326 > audit_backlog_limit=320
Jul 28 08:40:15 localhost audispd: queue is full - dropping event
Jul 28 08:40:15 localhost audispd: queue is full - dropping event
Jul 28 08:40:15 localhost audispd: queue is full - dropping event
Jul 28 08:40:15 localhost audispd: queue is full - dropping event
Jul 28 08:40:15 localhost audispd: queue is full - dropping event
...

Comment 1 Steve Grubb 2008-07-29 14:32:35 UTC
You should increase your backlog, increase the auditd and audispd
priority_boost, and increase the audispd internal queue size.

try -b 8192 in auditd.conf
priority_boost = 4  in auditd.conf
priority_boost = 8  in audispd.conf
q_depth = 2048  in audispd.conf

Comment 2 Charlie Brady 2008-07-29 14:51:39 UTC
(In reply to comment #1)
> You should increase your backlog, increase the auditd and audispd
> priority_boost, and increase the audispd internal queue size.

Well maybe, but I'd still wonder why the defaults weren't appropriate.

Comment 3 Steve Grubb 2008-07-29 15:03:20 UTC
Because not everyone has massive problems bombarding their system. Increasing
all these items have an effect of eating memory and changing performance of
non-security things. I have been increasing the baseline settings over time, but
I always have people arguing the other way to reduce my footprint so something
else works better. Hard to satisfy everyone.  :)

Comment 4 Charlie Brady 2008-07-29 15:17:17 UTC
(In reply to comment #3)
> Because not everyone has massive problems bombarding their system. Increasing
> all these items have an effect of eating memory and changing performance of
> non-security things. I have been increasing the baseline settings over time, but
> I always have people arguing the other way to reduce my footprint so something
> else works better.

OK, fair enough. But what "massive problems" did I have bombarding my system? My
logs don't tell me anything useful, before the queue was apparently full.

The "massive problems" are presumably just due to running selinux in enforcing
mode. I had hoped (and was assured by James Morris when I saw him last week)
that it was usable now, but apparently not.

I've set selinux back to permissive, and I am seeing fewer alerts than
previously, so that's progress at least.

[charlieb@localhost ~]$ sudo grep sealert /var/log/messages | wc -l
3605
[charlieb@localhost ~]$ 

Comment 5 Steve Grubb 2008-07-29 16:44:09 UTC
The relabel generates a whole lot of events very quickly. The queues need to be
big enough to handle that flood of info. relabelling is not something that one
normally has to do. My fedora 9 machine has never had to be relabelled. 

There's not much that you can do except make things bigger & give it more time
slices to handle the flood or just don't worry about the lost events because its
a known cause.

Comment 6 Steve Grubb 2008-07-29 16:48:32 UTC
Also, if you really want to make sure events are getting passed to audispd,
change disp_qos to lossless in auditd.conf. This tells auditd to pause until
audispd takes the event. This means the kernal's queue needs to be bigger. The
kernel is set by the -b option in audit.rules.

Comment 7 Charlie Brady 2008-07-29 17:27:29 UTC
(In reply to comment #5)
> The relabel generates a whole lot of events very quickly. The queues need
> to be big enough to handle that flood of info.

It wasn't just the relabel generating events though - that didn't take seven hours.

> relabelling is not something that one
> normally has to do. My fedora 9 machine has never had to be relabelled. 

I don't know whether it did or not. I assume it does if the policy is updated.
Mine was originally installed from the alpha release, so I presume much changed.

BTW, have you ever tried to run in enforcing mode? If so, was it usable.

BTW2, thanks.




Comment 8 Steve Grubb 2008-07-30 17:56:50 UTC
Yes, its in enforcing and I don't have any problems using it. I don't do
anything exotic, I only install rpms made by red hat, and I keep all paths to
files where SE Linux expects them.

Comment 9 Charlie Brady 2008-07-30 18:03:51 UTC
Please see bug 457051. For reasons as yet undiscovered my selinux installation
was very broken.

Comment 10 Steve Grubb 2008-08-25 21:38:00 UTC
audit-1.7.5-1.fc9 was built into the updates-testing repo. You might try that next push. This does have some code in it to try to work around the scheduler issue that's popped up in recent kernels.

Comment 11 Steve Grubb 2008-09-19 20:34:10 UTC
audit-1.7.5 is in F-9. Does upgrading to it help?

Comment 12 Charlie Brady 2008-09-19 20:53:14 UTC
> Does upgrading to it help?

I'm not seeing the problem any more, since doing what I was asked to do in bug 457051. So I don't know whether it helps.

Comment 13 Steve Grubb 2008-09-25 18:29:43 UTC
OK, there was an update in 1.7.5 that should have helped this problem. I'll close this bug for now and you can re-open it if the problem comes back. Thanks for reporting it.

Comment 14 Derek Atkins 2010-03-08 15:21:33 UTC
For what it's worth I see this problem on Fedora-12 using audit-2.0.4-1.fc12.i686


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