audit: avoid soft lockup in audit_log_start()

RFC In review Luiz Capitulino 6 participants 33 messages Aug 28, 2013 – Sep 23, 2013 Audit

lore

Share & tools

lore

Luiz Capitulino

author

2013-08-28 22:21 UTC #0 lore raw

RFC 1/1 audit: avoid soft lockup in audit_log_start()

I'm getting the following soft lockup:

CPU: 6 PID: 2278 Comm: killall5 Tainted: GF            3.11.0-rc7+ #1
Hardware name: Bochs Bochs, BIOS Bochs 01/01/2011
 0000000000000099 ffff88011fd83de8 ffffffff815324df 0000000000002800
 ffffffff817d48f9 ffff88011fd83e68 ffffffff8152e669 ffff88011fd83e68
 ffffffff00000008 ffff88011fd83e78 ffff88011fd83e18 0000004081dac040
Call Trace:
 <IRQ>  [<ffffffff815324df>] dump_stack+0x46/0x58
 [<ffffffff8152e669>] panic+0xbb/0x1c4
 [<ffffffff810d03c3>] watchdog_timer_fn+0x163/0x170
 [<ffffffff8106c691>] __run_hrtimer+0x81/0x1c0
 [<ffffffff810d0260>] ? watchdog+0x30/0x30
 [<ffffffff8106cea7>] hrtimer_interrupt+0x107/0x240
 [<ffffffff8102f61b>] local_apic_timer_interrupt+0x3b/0x60
 [<ffffffff81542465>] smp_apic_timer_interrupt+0x45/0x60
 [<ffffffff8154124a>] apic_timer_interrupt+0x6a/0x70
 <EOI>  [<ffffffff810c2f5f>] ? audit_log_start+0xbf/0x430
 [<ffffffff810c2fe7>] ? audit_log_start+0x147/0x430
 [<ffffffff81079030>] ? try_to_wake_up+0x2a0/0x2a0
 [<ffffffff810c86be>] audit_log_exit+0x6ae/0xc30
 [<ffffffff81188662>] ? __alloc_fd+0x42/0x100
 [<ffffffff810c98e7>] __audit_syscall_exit+0x257/0x2b0
 [<ffffffff81540794>] sysret_audit+0x17/0x21

The reproducer is somewhat unusual:

1. Install RHEL6.5 (maybe a similar older user-space will do)
2. Boot the just installed system
3. In this first boot you'll meet the firstboot script, which will do some setup and (depending on your answers) it will reboot the machine
4. During that first reboot the system hangs while terminating all processes:

Sending all processes the TERM signal...

It's when the soft lockup above happens. And yes, I managed to get this with latest upstream kernel (HEAD fa8218def1b1)

I'm reproducing it on a VM, but the first report was on bare-metal.

This is what is happening:

1. audit_log_start() is called
2. As we have SKBs waiting in audit_skb_queue and all conditions evaluate to true, we sleep in wait_for_auditd()
3. Go to 2, until sleep_time gets negative and audit_log_start() just busy-waits

Now, *why* this is happening is a mistery to me. I tried debugging it, but all I could find is that at some point the kauditd thread never wakes up after having called schedule(). I even tried waking it up before calling wait_for_auditd(), but it didn't.

This patch is a RFC because it doesn't actually fix anything. It just bails out before we busy-wait. Which is better than nothing, but the system will still give a long pause when terminating all processes. Besides, we risk papering over the real bug...

Signed-off-by Luiz Capitulino <[email protected]>

---
 kernel/audit.c | 9 ++++-----
 1 file changed, 4 insertions(+), 5 deletions(-)

kernel/audit.c +4 -5

index 91e53d0..33e9c4c 100644
@@ -1097,6 +1097,7 @@ struct audit_buffer *audit_log_start(struct audit_context *ctx, gfp_t gfp_mask,
 	unsigned int		uninitialized_var(serial);
 	int reserve;
 	unsigned long timeout_start = jiffies;
+	unsigned long sleep_time;
 
 	if (audit_initialized != AUDIT_INITIALIZED)
 		return NULL;

@@ -1112,13 +1113,11 @@ struct audit_buffer *audit_log_start(struct audit_context *ctx, gfp_t gfp_mask,
 
 	while (audit_backlog_limit
 	       && skb_queue_len(&audit_skb_queue) > audit_backlog_limit + reserve) {
-		if (gfp_mask & __GFP_WAIT && audit_backlog_wait_time) {
-			unsigned long sleep_time;
-
 			sleep_time = timeout_start + audit_backlog_wait_time -
 					jiffies;
-			if ((long)sleep_time > 0)
-				wait_for_auditd(sleep_time);
+		if (gfp_mask & __GFP_WAIT && audit_backlog_wait_time
+			&& sleep_time > 0) {
+			wait_for_auditd(sleep_time);
 			continue;
 		}
 		if (audit_rate_check() && printk_ratelimit())

Signature · 1 line

1.8.1.4

Andrew Morton

2013-08-28 22:33 UTC #1 lore raw

Quoted 50 lines · On Wed, 28 Aug 2013 18:21:14 -0400 Luiz Capitulino <[email protected]>…

I'm getting the following soft lockup:
CPU: 6 PID: 2278 Comm: killall5 Tainted: GF            3.11.0-rc7+ #1
Hardware name: Bochs Bochs, BIOS Bochs 01/01/2011
 0000000000000099 ffff88011fd83de8 ffffffff815324df 0000000000002800
 ffffffff817d48f9 ffff88011fd83e68 ffffffff8152e669 ffff88011fd83e68
 ffffffff00000008 ffff88011fd83e78 ffff88011fd83e18 0000004081dac040
Call Trace:
 <IRQ>  [<ffffffff815324df>] dump_stack+0x46/0x58
 [<ffffffff8152e669>] panic+0xbb/0x1c4
 [<ffffffff810d03c3>] watchdog_timer_fn+0x163/0x170
 [<ffffffff8106c691>] __run_hrtimer+0x81/0x1c0
 [<ffffffff810d0260>] ? watchdog+0x30/0x30
 [<ffffffff8106cea7>] hrtimer_interrupt+0x107/0x240
 [<ffffffff8102f61b>] local_apic_timer_interrupt+0x3b/0x60
 [<ffffffff81542465>] smp_apic_timer_interrupt+0x45/0x60
 [<ffffffff8154124a>] apic_timer_interrupt+0x6a/0x70
 <EOI>  [<ffffffff810c2f5f>] ? audit_log_start+0xbf/0x430
 [<ffffffff810c2fe7>] ? audit_log_start+0x147/0x430
 [<ffffffff81079030>] ? try_to_wake_up+0x2a0/0x2a0
 [<ffffffff810c86be>] audit_log_exit+0x6ae/0xc30
 [<ffffffff81188662>] ? __alloc_fd+0x42/0x100
 [<ffffffff810c98e7>] __audit_syscall_exit+0x257/0x2b0
 [<ffffffff81540794>] sysret_audit+0x17/0x21
The reproducer is somewhat unusual:
1. Install RHEL6.5 (maybe a similar older user-space will do)
2. Boot the just installed system
3. In this first boot you'll meet the firstboot script, which will do some setup and (depending on your answers) it will reboot the machine
4. During that first reboot the system hangs while terminating all processes:
Sending all processes the TERM signal...
It's when the soft lockup above happens. And yes, I managed to get this with latest upstream kernel (HEAD fa8218def1b1)
I'm reproducing it on a VM, but the first report was on bare-metal.
This is what is happening:
1. audit_log_start() is called
2. As we have SKBs waiting in audit_skb_queue and all conditions evaluate to true, we sleep in wait_for_auditd()
3. Go to 2, until sleep_time gets negative and audit_log_start() just busy-waits

Quoted 4 lines

Now, *why* this is happening is a mistery to me. I tried debugging it, but all I could find is that at some point the kauditd thread never wakes up after having called schedule(). I even tried waking it up before calling wait_for_auditd(), but it didn't.

Odd. If kauditd_thread() is stuck in schedule() in state TASK_INTERRUPTIBLE then a wake_up(kauditd_task) should get it running again, unless scheduler-related data structures are screwed up.

Are you really sure that kauditd is stuck in schedule() and doesn't come out?

Luiz Capitulino

author

2013-08-28 22:54 UTC #2 lore raw

Quoted 57 lines · On Wed, 28 Aug 2013 15:33:45 -0700 Andrew Morton <[email protected]>…

Quoted 50 lines · On Wed, 28 Aug 2013 18:21:14 -0400 Luiz Capitulino <[email protected]>…
I'm getting the following soft lockup:
CPU: 6 PID: 2278 Comm: killall5 Tainted: GF            3.11.0-rc7+ #1
Hardware name: Bochs Bochs, BIOS Bochs 01/01/2011
 0000000000000099 ffff88011fd83de8 ffffffff815324df 0000000000002800
 ffffffff817d48f9 ffff88011fd83e68 ffffffff8152e669 ffff88011fd83e68
 ffffffff00000008 ffff88011fd83e78 ffff88011fd83e18 0000004081dac040
Call Trace:
 <IRQ>  [<ffffffff815324df>] dump_stack+0x46/0x58
 [<ffffffff8152e669>] panic+0xbb/0x1c4
 [<ffffffff810d03c3>] watchdog_timer_fn+0x163/0x170
 [<ffffffff8106c691>] __run_hrtimer+0x81/0x1c0
 [<ffffffff810d0260>] ? watchdog+0x30/0x30
 [<ffffffff8106cea7>] hrtimer_interrupt+0x107/0x240
 [<ffffffff8102f61b>] local_apic_timer_interrupt+0x3b/0x60
 [<ffffffff81542465>] smp_apic_timer_interrupt+0x45/0x60
 [<ffffffff8154124a>] apic_timer_interrupt+0x6a/0x70
 <EOI>  [<ffffffff810c2f5f>] ? audit_log_start+0xbf/0x430
 [<ffffffff810c2fe7>] ? audit_log_start+0x147/0x430
 [<ffffffff81079030>] ? try_to_wake_up+0x2a0/0x2a0
 [<ffffffff810c86be>] audit_log_exit+0x6ae/0xc30
 [<ffffffff81188662>] ? __alloc_fd+0x42/0x100
 [<ffffffff810c98e7>] __audit_syscall_exit+0x257/0x2b0
 [<ffffffff81540794>] sysret_audit+0x17/0x21
The reproducer is somewhat unusual:
1. Install RHEL6.5 (maybe a similar older user-space will do)
2. Boot the just installed system
3. In this first boot you'll meet the firstboot script, which will do some setup and (depending on your answers) it will reboot the machine
4. During that first reboot the system hangs while terminating all processes:
Sending all processes the TERM signal...
It's when the soft lockup above happens. And yes, I managed to get this with latest upstream kernel (HEAD fa8218def1b1)
I'm reproducing it on a VM, but the first report was on bare-metal.
This is what is happening:
1. audit_log_start() is called
2. As we have SKBs waiting in audit_skb_queue and all conditions evaluate to true, we sleep in wait_for_auditd()
3. Go to 2, until sleep_time gets negative and audit_log_start() just busy-waits
Quoted 4 lines
Now, *why* this is happening is a mistery to me. I tried debugging it, but all I could find is that at some point the kauditd thread never wakes up after having called schedule(). I even tried waking it up before calling wait_for_auditd(), but it didn't.

Quoted 6 lines

Odd. If kauditd_thread() is stuck in schedule() in state TASK_INTERRUPTIBLE then a wake_up(kauditd_task) should get it running again, unless scheduler-related data structures are screwed up.
Are you really sure that kauditd is stuck in schedule() and doesn't come out?

No, that's a guess. Inferred from:

1. I tried calling wake_up_interruptible(&kauditd_wait); right before wait_for_auditd(). Nothing changes

2. I added this debug printks:

  diff --git a/kernel/audit.c b/kernel/audit.c
  index 91e53d0..27448ad 100644
  --- a/kernel/audit.c
  +++ b/kernel/audit.c
  @@ -458,11 +458,14 @@ static int kauditd_thread(void *dummy)
   		set_current_state(TASK_INTERRUPTIBLE);
   		add_wait_queue(&kauditd_wait, &wait);
   
  +		pr_emerg_ratelimited("*** sleeping\n");
  +
   		if (!skb_queue_len(&audit_skb_queue)) {
   			try_to_freeze();
   			schedule();
   		}
   
  +		pr_emerg_ratelimited("*** waking up\n");
   		__set_current_state(TASK_RUNNING);
   		remove_wait_queue(&kauditd_wait, &wait);
   	}

I get several pairs of sleeping/waking up strings right before the system begins to shut down. Then it stops (even though we do have SKBs queued)

Now, the kauditd thread does exists when the soft lockup happens, I could verify that with crash.

What's interesting is that I can only get it in that first reboot done by the firstboot script in RHEL6. I didn't manage to get it in any other way.

I'm open to any debugging tips, but be gentle because I'm not very familiar with that stuff.

Andrew Morton

2013-08-28 23:08 UTC #3 lore raw

Quoted 30 lines · On Wed, 28 Aug 2013 18:54:36 -0400 Luiz Capitulino <[email protected]>…

Quoted 2 lines
Are you really sure that kauditd is stuck in schedule() and doesn't come out?
No, that's a guess. Inferred from:
1. I tried calling wake_up_interruptible(&kauditd_wait); right before wait_for_auditd(). Nothing changes
2. I added this debug printks:
  diff --git a/kernel/audit.c b/kernel/audit.c
  index 91e53d0..27448ad 100644
  --- a/kernel/audit.c
  +++ b/kernel/audit.c
  @@ -458,11 +458,14 @@ static int kauditd_thread(void *dummy)
   		set_current_state(TASK_INTERRUPTIBLE);
   		add_wait_queue(&kauditd_wait, &wait);
   
  +		pr_emerg_ratelimited("*** sleeping\n");
  +
   		if (!skb_queue_len(&audit_skb_queue)) {
   			try_to_freeze();
   			schedule();
   		}
   
  +		pr_emerg_ratelimited("*** waking up\n");
   		__set_current_state(TASK_RUNNING);
   		remove_wait_queue(&kauditd_wait, &wait);
   	}

Quoted 3 lines

I get several pairs of sleeping/waking up strings right before the system begins to shut down. Then it stops (even though we do have SKBs queued)

Well. I assume "*** sleeping" the last thing kauditd prints? If the last print is "waking up" then obviously kauditd is stuck somewhere else, which makes more sense. A sysrq-T (or echo t > /proc/sysrq-trigger) should provide clues.

I'd remove the "_ratelimited" - you don't want your debug messages to be ratelimited (ie: omitted).

Quoted 9 lines

Now, the kauditd thread does exists when the soft lockup happens, I could verify that with crash.
What's interesting is that I can only get it in that first reboot done by the firstboot script in RHEL6. I didn't manage to get it in any other way.
I'm open to any debugging tips, but be gentle because I'm not very familiar with that stuff.

Luiz Capitulino

author

2013-08-29 00:49 UTC #4 lore raw

Quoted 32 lines · On Wed, 28 Aug 2013 16:08:13 -0700 Andrew Morton <[email protected]>…

Quoted 30 lines · On Wed, 28 Aug 2013 18:54:36 -0400 Luiz Capitulino <[email protected]>…
Quoted 2 lines
Are you really sure that kauditd is stuck in schedule() and doesn't come out?
No, that's a guess. Inferred from:
1. I tried calling wake_up_interruptible(&kauditd_wait); right before wait_for_auditd(). Nothing changes
2. I added this debug printks:
  diff --git a/kernel/audit.c b/kernel/audit.c
  index 91e53d0..27448ad 100644
  --- a/kernel/audit.c
  +++ b/kernel/audit.c
  @@ -458,11 +458,14 @@ static int kauditd_thread(void *dummy)
   		set_current_state(TASK_INTERRUPTIBLE);
   		add_wait_queue(&kauditd_wait, &wait);
   
  +		pr_emerg_ratelimited("*** sleeping\n");
  +
   		if (!skb_queue_len(&audit_skb_queue)) {
   			try_to_freeze();
   			schedule();
   		}
   
  +		pr_emerg_ratelimited("*** waking up\n");
   		__set_current_state(TASK_RUNNING);
   		remove_wait_queue(&kauditd_wait, &wait);
   	}

Quoted 8 lines

Quoted 3 lines
I get several pairs of sleeping/waking up strings right before the system begins to shut down. Then it stops (even though we do have SKBs queued)
Well. I assume "*** sleeping" the last thing kauditd prints? If the last print is "waking up" then obviously kauditd is stuck somewhere else, which makes more sense. A sysrq-T (or echo t > /proc/sysrq-trigger) should provide clues.

Yes, "*** sleeping" is the last one.

Quoted 2 lines

I'd remove the "_ratelimited" - you don't want your debug messages to be ratelimited (ie: omitted).

I'll try that.

Another interesting info is that the process that triggers the hang is killall5 and by the time the hang happens auditd is not running anymore.

Luiz Capitulino

author

2013-08-30 18:23 UTC #5 lore raw

In reply to Andrew Morton

Quoted 32 lines · On Wed, 28 Aug 2013 16:08:13 -0700 Andrew Morton <[email protected]>…

Quoted 30 lines · On Wed, 28 Aug 2013 18:54:36 -0400 Luiz Capitulino <[email protected]>…
Quoted 2 lines
Are you really sure that kauditd is stuck in schedule() and doesn't come out?
No, that's a guess. Inferred from:
1. I tried calling wake_up_interruptible(&kauditd_wait); right before wait_for_auditd(). Nothing changes
2. I added this debug printks:
  diff --git a/kernel/audit.c b/kernel/audit.c
  index 91e53d0..27448ad 100644
  --- a/kernel/audit.c
  +++ b/kernel/audit.c
  @@ -458,11 +458,14 @@ static int kauditd_thread(void *dummy)
   		set_current_state(TASK_INTERRUPTIBLE);
   		add_wait_queue(&kauditd_wait, &wait);
   
  +		pr_emerg_ratelimited("*** sleeping\n");
  +
   		if (!skb_queue_len(&audit_skb_queue)) {
   			try_to_freeze();
   			schedule();
   		}
   
  +		pr_emerg_ratelimited("*** waking up\n");
   		__set_current_state(TASK_RUNNING);
   		remove_wait_queue(&kauditd_wait, &wait);
   	}

Quoted 7 lines

Quoted 3 lines
I get several pairs of sleeping/waking up strings right before the system begins to shut down. Then it stops (even though we do have SKBs queued)
Well. I assume "*** sleeping" the last thing kauditd prints? If the last print is "waking up" then obviously kauditd is stuck somewhere else, which makes more sense.

That's correct. According to crash, here's where it's stuck:

#0 [ffff880115511c58] __schedule at ffffffff815361de #1 [ffff880115511cd0] schedule at ffffffff81537039 #2 [ffff880115511ce0] schedule_timeout at ffffffff81534524 #3 [ffff880115511d90] netlink_attachskb at ffffffff81498c69 #4 [ffff880115511df0] netlink_unicast at ffffffff81498d7f #5 [ffff880115511e40] kauditd_send_skb at ffffffff810c254f #6 [ffff880115511e60] kauditd_thread at ffffffff810c26e9 #7 [ffff880115511ec0] kthread at ffffffff810693b0 #8 [ffff880115511f50] ret_from_fork at ffffffff8154071c

I see two possible reasons for this:

1. User-space triggered a NETLINK_CONGESTED condition. If this is the problem, then the fix is to make audit's netlink socket non-blocking and queue SKBs if netlink_unicast() returns -EINVAL

2. It's a race condition in the audit code. This bug is only triggered on SMP machines _and_ adding printk()s to kauditd_thread() makes it go away. Also, if I'm not mistaken, there's a number of global variables that are shared between kaudit_thread() and threads calling audit_log(). For example: kaudit_sock, audit_skb_hold_queue, kauditd_wait and others

I can try protecting the global data structures with a mutex but, will such a patch be accepted if the bug goes away? :)

Konstantin Khlebnikov

2013-09-09 14:32 UTC #6 lore raw

In reply to Luiz Capitulino

Quoted 50 lines · Luiz Capitulino

I'm getting the following soft lockup:
CPU: 6 PID: 2278 Comm: killall5 Tainted: GF            3.11.0-rc7+ #1
Hardware name: Bochs Bochs, BIOS Bochs 01/01/2011
  0000000000000099 ffff88011fd83de8 ffffffff815324df 0000000000002800
  ffffffff817d48f9 ffff88011fd83e68 ffffffff8152e669 ffff88011fd83e68
  ffffffff00000008 ffff88011fd83e78 ffff88011fd83e18 0000004081dac040
Call Trace:
  <IRQ>   [<ffffffff815324df>] dump_stack+0x46/0x58
  [<ffffffff8152e669>] panic+0xbb/0x1c4
  [<ffffffff810d03c3>] watchdog_timer_fn+0x163/0x170
  [<ffffffff8106c691>] __run_hrtimer+0x81/0x1c0
  [<ffffffff810d0260>] ? watchdog+0x30/0x30
  [<ffffffff8106cea7>] hrtimer_interrupt+0x107/0x240
  [<ffffffff8102f61b>] local_apic_timer_interrupt+0x3b/0x60
  [<ffffffff81542465>] smp_apic_timer_interrupt+0x45/0x60
  [<ffffffff8154124a>] apic_timer_interrupt+0x6a/0x70
  <EOI>   [<ffffffff810c2f5f>] ? audit_log_start+0xbf/0x430
  [<ffffffff810c2fe7>] ? audit_log_start+0x147/0x430
  [<ffffffff81079030>] ? try_to_wake_up+0x2a0/0x2a0
  [<ffffffff810c86be>] audit_log_exit+0x6ae/0xc30
  [<ffffffff81188662>] ? __alloc_fd+0x42/0x100
  [<ffffffff810c98e7>] __audit_syscall_exit+0x257/0x2b0
  [<ffffffff81540794>] sysret_audit+0x17/0x21
The reproducer is somewhat unusual:
1. Install RHEL6.5 (maybe a similar older user-space will do)
2. Boot the just installed system
3. In this first boot you'll meet the firstboot script, which will do some setup and (depending on your answers) it will reboot the machine
4. During that first reboot the system hangs while terminating all processes:
Sending all processes the TERM signal...
It's when the soft lockup above happens. And yes, I managed to get this with latest upstream kernel (HEAD fa8218def1b1)
I'm reproducing it on a VM, but the first report was on bare-metal.
This is what is happening:
1. audit_log_start() is called
2. As we have SKBs waiting in audit_skb_queue and all conditions evaluate to true, we sleep in wait_for_auditd()
3. Go to 2, until sleep_time gets negative and audit_log_start() just busy-waits

Quoted 4 lines

Now, *why* this is happening is a mistery to me. I tried debugging it, but all I could find is that at some point the kauditd thread never wakes up after having called schedule(). I even tried waking it up before calling wait_for_auditd(), but it didn't.

We run into the same problem in rhel6 kernel.

"readahead-collector" uses audit interface and sometimes stuck in 'stopped' state.

After commit 829199197a430dade2519d54f5545c4a094393b8
(which was backported by RH into their kernel)
audit emiters will block forever if userspace daemon cannot handle backlog. That commit just breaks timeout condition, after timeout waiting loop turns into busy loop until deamon dies or returns back to work.

this trivial patch should fix that problem

kernel/audit.c +3 -2

@@ -1215,9 +1215,10 @@ struct audit_buffer *audit_log_start(struct audit_context *ctx, gfp_t gfp_mask,
 
                        sleep_time = timeout_start + audit_backlog_wait_time -
                                        jiffies;
-                       if ((long)sleep_time > 0)
+                       if ((long)sleep_time > 0) {
                                wait_for_auditd(sleep_time);
-                       continue;
+                               continue;
+                       }
                }
                if (audit_rate_check() && printk_ratelimit())
                        printk(KERN_WARNING

Quoted 40 lines

Signed-off-by Luiz Capitulino<[email protected]>

---
  kernel/audit.c | 9 ++++-----
  1 file changed, 4 insertions(+), 5 deletions(-)

kernel/audit.c +4 -5

index 91e53d0..33e9c4c 100644
@@ -1097,6 +1097,7 @@ struct audit_buffer *audit_log_start(struct audit_context *ctx, gfp_t gfp_mask,
  	unsigned int		uninitialized_var(serial);
  	int reserve;
  	unsigned long timeout_start = jiffies;
+	unsigned long sleep_time;
 
  	if (audit_initialized != AUDIT_INITIALIZED)
  		return NULL;

@@ -1112,13 +1113,11 @@ struct audit_buffer *audit_log_start(struct audit_context *ctx, gfp_t gfp_mask,
 
  	while (audit_backlog_limit
  	&&  skb_queue_len(&audit_skb_queue)>  audit_backlog_limit + reserve) {
-		if (gfp_mask&  __GFP_WAIT&&  audit_backlog_wait_time) {
-			unsigned long sleep_time;
-
  			sleep_time = timeout_start + audit_backlog_wait_time -
  					jiffies;
-			if ((long)sleep_time>  0)
-				wait_for_auditd(sleep_time);
+		if (gfp_mask&  __GFP_WAIT&&  audit_backlog_wait_time
+			&&  sleep_time>  0) {
+			wait_for_auditd(sleep_time);
  			continue;
  		}
  		if (audit_rate_check()&&  printk_ratelimit())

Luiz Capitulino

author

2013-09-09 14:54 UTC #7 lore raw

Quoted 51 lines · On Mon, 09 Sep 2013 18:32:13 +0400 Konstantin Khlebnikov…

Quoted 50 lines · Luiz Capitulino
I'm getting the following soft lockup:
CPU: 6 PID: 2278 Comm: killall5 Tainted: GF            3.11.0-rc7+ #1
Hardware name: Bochs Bochs, BIOS Bochs 01/01/2011
  0000000000000099 ffff88011fd83de8 ffffffff815324df 0000000000002800
  ffffffff817d48f9 ffff88011fd83e68 ffffffff8152e669 ffff88011fd83e68
  ffffffff00000008 ffff88011fd83e78 ffff88011fd83e18 0000004081dac040
Call Trace:
  <IRQ>   [<ffffffff815324df>] dump_stack+0x46/0x58
  [<ffffffff8152e669>] panic+0xbb/0x1c4
  [<ffffffff810d03c3>] watchdog_timer_fn+0x163/0x170
  [<ffffffff8106c691>] __run_hrtimer+0x81/0x1c0
  [<ffffffff810d0260>] ? watchdog+0x30/0x30
  [<ffffffff8106cea7>] hrtimer_interrupt+0x107/0x240
  [<ffffffff8102f61b>] local_apic_timer_interrupt+0x3b/0x60
  [<ffffffff81542465>] smp_apic_timer_interrupt+0x45/0x60
  [<ffffffff8154124a>] apic_timer_interrupt+0x6a/0x70
  <EOI>   [<ffffffff810c2f5f>] ? audit_log_start+0xbf/0x430
  [<ffffffff810c2fe7>] ? audit_log_start+0x147/0x430
  [<ffffffff81079030>] ? try_to_wake_up+0x2a0/0x2a0
  [<ffffffff810c86be>] audit_log_exit+0x6ae/0xc30
  [<ffffffff81188662>] ? __alloc_fd+0x42/0x100
  [<ffffffff810c98e7>] __audit_syscall_exit+0x257/0x2b0
  [<ffffffff81540794>] sysret_audit+0x17/0x21
The reproducer is somewhat unusual:
1. Install RHEL6.5 (maybe a similar older user-space will do)
2. Boot the just installed system
3. In this first boot you'll meet the firstboot script, which will do some setup and (depending on your answers) it will reboot the machine
4. During that first reboot the system hangs while terminating all processes:
Sending all processes the TERM signal...
It's when the soft lockup above happens. And yes, I managed to get this with latest upstream kernel (HEAD fa8218def1b1)
I'm reproducing it on a VM, but the first report was on bare-metal.
This is what is happening:
1. audit_log_start() is called
2. As we have SKBs waiting in audit_skb_queue and all conditions evaluate to true, we sleep in wait_for_auditd()
3. Go to 2, until sleep_time gets negative and audit_log_start() just busy-waits

Quoted 8 lines

Quoted 4 lines
Now, *why* this is happening is a mistery to me. I tried debugging it, but all I could find is that at some point the kauditd thread never wakes up after having called schedule(). I even tried waking it up before calling wait_for_auditd(), but it didn't.
We run into the same problem in rhel6 kernel.
"readahead-collector" uses audit interface and sometimes stuck in 'stopped' state.

Yes, please also see:

http://marc.info/?l=linux-kernel&m=137818375024600&w=2

Quoted 11 lines

After commit 829199197a430dade2519d54f5545c4a094393b8
(which was backported by RH into their kernel)
audit emiters will block forever if userspace daemon cannot handle backlog. That commit just breaks timeout condition, after timeout waiting loop turns into busy loop until deamon dies or returns back to work.
this trivial patch should fix that problem

kernel/audit.c struct audit_buffer *audit_log_start(struct audit_context *ctx, gfp_t gfp_mask, · line 1222

Quoted 10 lines

kernel/audit.c +3 -2

@@ -1215,9 +1215,10 @@ struct audit_buffer *audit_log_start(struct audit_context *ctx, gfp_t gfp_mask,
 
                         sleep_time = timeout_start + audit_backlog_wait_time -
                                         jiffies;
-                       if ((long)sleep_time > 0)
+                       if ((long)sleep_time > 0) {
                                 wait_for_auditd(sleep_time);
-                       continue;
+                               continue;
+                       }
                 }

Chuck Anderson posted a similar fix:

http://marc.info/?l=linux-kernel&m=137817994623832&w=2

I still get a hang for around a minute with Chuck's fix, I believe I'll get the same thing with yours.

Konstantin Khlebnikov

2013-09-09 15:19 UTC #8 lore raw

Quoted 92 lines · Luiz Capitulino

Quoted 51 lines · On Mon, 09 Sep 2013 18:32:13 +0400 Konstantin…
Quoted 50 lines · Luiz Capitulino
I'm getting the following soft lockup:
CPU: 6 PID: 2278 Comm: killall5 Tainted: GF            3.11.0-rc7+ #1
Hardware name: Bochs Bochs, BIOS Bochs 01/01/2011
   0000000000000099 ffff88011fd83de8 ffffffff815324df 0000000000002800
   ffffffff817d48f9 ffff88011fd83e68 ffffffff8152e669 ffff88011fd83e68
   ffffffff00000008 ffff88011fd83e78 ffff88011fd83e18 0000004081dac040
Call Trace:
   <IRQ>    [<ffffffff815324df>] dump_stack+0x46/0x58
   [<ffffffff8152e669>] panic+0xbb/0x1c4
   [<ffffffff810d03c3>] watchdog_timer_fn+0x163/0x170
   [<ffffffff8106c691>] __run_hrtimer+0x81/0x1c0
   [<ffffffff810d0260>] ? watchdog+0x30/0x30
   [<ffffffff8106cea7>] hrtimer_interrupt+0x107/0x240
   [<ffffffff8102f61b>] local_apic_timer_interrupt+0x3b/0x60
   [<ffffffff81542465>] smp_apic_timer_interrupt+0x45/0x60
   [<ffffffff8154124a>] apic_timer_interrupt+0x6a/0x70
   <EOI>    [<ffffffff810c2f5f>] ? audit_log_start+0xbf/0x430
   [<ffffffff810c2fe7>] ? audit_log_start+0x147/0x430
   [<ffffffff81079030>] ? try_to_wake_up+0x2a0/0x2a0
   [<ffffffff810c86be>] audit_log_exit+0x6ae/0xc30
   [<ffffffff81188662>] ? __alloc_fd+0x42/0x100
   [<ffffffff810c98e7>] __audit_syscall_exit+0x257/0x2b0
   [<ffffffff81540794>] sysret_audit+0x17/0x21
The reproducer is somewhat unusual:
1. Install RHEL6.5 (maybe a similar older user-space will do)
2. Boot the just installed system
3. In this first boot you'll meet the firstboot script, which will do some setup and (depending on your answers) it will reboot the machine
4. During that first reboot the system hangs while terminating all processes:
Sending all processes the TERM signal...
It's when the soft lockup above happens. And yes, I managed to get this with latest upstream kernel (HEAD fa8218def1b1)
I'm reproducing it on a VM, but the first report was on bare-metal.
This is what is happening:
1. audit_log_start() is called
2. As we have SKBs waiting in audit_skb_queue and all conditions evaluate to true, we sleep in wait_for_auditd()
3. Go to 2, until sleep_time gets negative and audit_log_start() just busy-waits
Quoted 8 lines
Quoted 4 lines
Now, *why* this is happening is a mistery to me. I tried debugging it, but all I could find is that at some point the kauditd thread never wakes up after having called schedule(). I even tried waking it up before calling wait_for_auditd(), but it didn't.
We run into the same problem in rhel6 kernel.
"readahead-collector" uses audit interface and sometimes stuck in 'stopped' state.
Yes, please also see:
http://marc.info/?l=linux-kernel&m=137818375024600&w=2
Quoted 11 lines
After commit 829199197a430dade2519d54f5545c4a094393b8
(which was backported by RH into their kernel)
audit emiters will block forever if userspace daemon cannot handle backlog. That commit just breaks timeout condition, after timeout waiting loop turns into busy loop until deamon dies or returns back to work.
this trivial patch should fix that problem
kernel/audit.c struct audit_buffer *audit_log_start(struct audit_context *ctx, gfp_t gfp_mask, · line 1222
Quoted 10 lines
kernel/audit.c +3 -2
@@ -1215,9 +1215,10 @@ struct audit_buffer *audit_log_start(struct audit_context *ctx, gfp_t gfp_mask,
 
                          sleep_time = timeout_start + audit_backlog_wait_time -
                                          jiffies;
-                       if ((long)sleep_time>  0)
+                       if ((long)sleep_time>  0) {
                                  wait_for_auditd(sleep_time);
-                       continue;
+                               continue;
+                       }
                  }
Chuck Anderson posted a similar fix:

Quoted 4 lines

http://marc.info/?l=linux-kernel&m=137817994623832&w=2
I still get a hang for around a minute with Chuck's fix, I believe I'll get the same thing with yours.

Yep, this is normal behaviour -- default audit_backlog_wait_time is 60 seconds.

But this logic is really strange, I don't see any interface for tuning that timeout and seems like kernel set it to zero after first disaster and never recovers it back.

Luiz Capitulino

author

2013-09-09 15:30 UTC #9 lore raw

Quoted 93 lines · On Mon, 09 Sep 2013 19:19:14 +0400 Konstantin Khlebnikov…

Quoted 92 lines · Luiz Capitulino
Quoted 51 lines · On Mon, 09 Sep 2013 18:32:13 +0400 Konstantin…
Quoted 50 lines · Luiz Capitulino
I'm getting the following soft lockup:
CPU: 6 PID: 2278 Comm: killall5 Tainted: GF            3.11.0-rc7+ #1
Hardware name: Bochs Bochs, BIOS Bochs 01/01/2011
   0000000000000099 ffff88011fd83de8 ffffffff815324df 0000000000002800
   ffffffff817d48f9 ffff88011fd83e68 ffffffff8152e669 ffff88011fd83e68
   ffffffff00000008 ffff88011fd83e78 ffff88011fd83e18 0000004081dac040
Call Trace:
   <IRQ>    [<ffffffff815324df>] dump_stack+0x46/0x58
   [<ffffffff8152e669>] panic+0xbb/0x1c4
   [<ffffffff810d03c3>] watchdog_timer_fn+0x163/0x170
   [<ffffffff8106c691>] __run_hrtimer+0x81/0x1c0
   [<ffffffff810d0260>] ? watchdog+0x30/0x30
   [<ffffffff8106cea7>] hrtimer_interrupt+0x107/0x240
   [<ffffffff8102f61b>] local_apic_timer_interrupt+0x3b/0x60
   [<ffffffff81542465>] smp_apic_timer_interrupt+0x45/0x60
   [<ffffffff8154124a>] apic_timer_interrupt+0x6a/0x70
   <EOI>    [<ffffffff810c2f5f>] ? audit_log_start+0xbf/0x430
   [<ffffffff810c2fe7>] ? audit_log_start+0x147/0x430
   [<ffffffff81079030>] ? try_to_wake_up+0x2a0/0x2a0
   [<ffffffff810c86be>] audit_log_exit+0x6ae/0xc30
   [<ffffffff81188662>] ? __alloc_fd+0x42/0x100
   [<ffffffff810c98e7>] __audit_syscall_exit+0x257/0x2b0
   [<ffffffff81540794>] sysret_audit+0x17/0x21
The reproducer is somewhat unusual:
1. Install RHEL6.5 (maybe a similar older user-space will do)
2. Boot the just installed system
3. In this first boot you'll meet the firstboot script, which will do some setup and (depending on your answers) it will reboot the machine
4. During that first reboot the system hangs while terminating all processes:
Sending all processes the TERM signal...
It's when the soft lockup above happens. And yes, I managed to get this with latest upstream kernel (HEAD fa8218def1b1)
I'm reproducing it on a VM, but the first report was on bare-metal.
This is what is happening:
1. audit_log_start() is called
2. As we have SKBs waiting in audit_skb_queue and all conditions evaluate to true, we sleep in wait_for_auditd()
3. Go to 2, until sleep_time gets negative and audit_log_start() just busy-waits
Quoted 8 lines
Quoted 4 lines
Now, *why* this is happening is a mistery to me. I tried debugging it, but all I could find is that at some point the kauditd thread never wakes up after having called schedule(). I even tried waking it up before calling wait_for_auditd(), but it didn't.
We run into the same problem in rhel6 kernel.
"readahead-collector" uses audit interface and sometimes stuck in 'stopped' state.
Yes, please also see:
http://marc.info/?l=linux-kernel&m=137818375024600&w=2
Quoted 11 lines
After commit 829199197a430dade2519d54f5545c4a094393b8
(which was backported by RH into their kernel)
audit emiters will block forever if userspace daemon cannot handle backlog. That commit just breaks timeout condition, after timeout waiting loop turns into busy loop until deamon dies or returns back to work.
this trivial patch should fix that problem
kernel/audit.c struct audit_buffer *audit_log_start(struct audit_context *ctx, gfp_t gfp_mask, · line 1222
Quoted 10 lines
kernel/audit.c +3 -2
@@ -1215,9 +1215,10 @@ struct audit_buffer *audit_log_start(struct audit_context *ctx, gfp_t gfp_mask,
 
                          sleep_time = timeout_start + audit_backlog_wait_time -
                                          jiffies;
-                       if ((long)sleep_time>  0)
+                       if ((long)sleep_time>  0) {
                                  wait_for_auditd(sleep_time);
-                       continue;
+                               continue;
+                       }
                  }
Chuck Anderson posted a similar fix:

Quoted 6 lines

Quoted 4 lines
http://marc.info/?l=linux-kernel&m=137817994623832&w=2
I still get a hang for around a minute with Chuck's fix, I believe I'll get the same thing with yours.
Yep, this is normal behaviour -- default audit_backlog_wait_time is 60 seconds.

Yes, I know that's the cause but I don't call it normal behavior to be unable to use my system during 60 seconds.

Quoted 2 lines

But this logic is really strange, I don't see any interface for tuning that timeout and seems like kernel set it to zero after first disaster and never recovers it back.

Konstantin Khlebnikov

2013-09-09 15:42 UTC #10 lore raw

Quoted 98 lines · Luiz Capitulino

Quoted 95 lines · On Mon, 09 Sep 2013 19:19:14 +0400 Konstantin…
Quoted 94 lines · Luiz Capitulino
Quoted 51 lines · On Mon, 09 Sep 2013 18:32:13 +0400 Konstantin…
Quoted 50 lines · Luiz Capitulino
I'm getting the following soft lockup:
CPU: 6 PID: 2278 Comm: killall5 Tainted: GF            3.11.0-rc7+ #1
Hardware name: Bochs Bochs, BIOS Bochs 01/01/2011
    0000000000000099 ffff88011fd83de8 ffffffff815324df 0000000000002800
    ffffffff817d48f9 ffff88011fd83e68 ffffffff8152e669 ffff88011fd83e68
    ffffffff00000008 ffff88011fd83e78 ffff88011fd83e18 0000004081dac040
Call Trace:
    <IRQ>     [<ffffffff815324df>] dump_stack+0x46/0x58
    [<ffffffff8152e669>] panic+0xbb/0x1c4
    [<ffffffff810d03c3>] watchdog_timer_fn+0x163/0x170
    [<ffffffff8106c691>] __run_hrtimer+0x81/0x1c0
    [<ffffffff810d0260>] ? watchdog+0x30/0x30
    [<ffffffff8106cea7>] hrtimer_interrupt+0x107/0x240
    [<ffffffff8102f61b>] local_apic_timer_interrupt+0x3b/0x60
    [<ffffffff81542465>] smp_apic_timer_interrupt+0x45/0x60
    [<ffffffff8154124a>] apic_timer_interrupt+0x6a/0x70
    <EOI>     [<ffffffff810c2f5f>] ? audit_log_start+0xbf/0x430
    [<ffffffff810c2fe7>] ? audit_log_start+0x147/0x430
    [<ffffffff81079030>] ? try_to_wake_up+0x2a0/0x2a0
    [<ffffffff810c86be>] audit_log_exit+0x6ae/0xc30
    [<ffffffff81188662>] ? __alloc_fd+0x42/0x100
    [<ffffffff810c98e7>] __audit_syscall_exit+0x257/0x2b0
    [<ffffffff81540794>] sysret_audit+0x17/0x21
The reproducer is somewhat unusual:
1. Install RHEL6.5 (maybe a similar older user-space will do)
2. Boot the just installed system
3. In this first boot you'll meet the firstboot script, which will do some setup and (depending on your answers) it will reboot the machine
4. During that first reboot the system hangs while terminating all processes:
Sending all processes the TERM signal...
It's when the soft lockup above happens. And yes, I managed to get this with latest upstream kernel (HEAD fa8218def1b1)
I'm reproducing it on a VM, but the first report was on bare-metal.
This is what is happening:
1. audit_log_start() is called
2. As we have SKBs waiting in audit_skb_queue and all conditions evaluate to true, we sleep in wait_for_auditd()
3. Go to 2, until sleep_time gets negative and audit_log_start() just busy-waits
Quoted 8 lines
Quoted 4 lines
Now, *why* this is happening is a mistery to me. I tried debugging it, but all I could find is that at some point the kauditd thread never wakes up after having called schedule(). I even tried waking it up before calling wait_for_auditd(), but it didn't.
We run into the same problem in rhel6 kernel.
"readahead-collector" uses audit interface and sometimes stuck in 'stopped' state.
Yes, please also see:
   http://marc.info/?l=linux-kernel&m=137818375024600&w=2
Quoted 11 lines
After commit 829199197a430dade2519d54f5545c4a094393b8
(which was backported by RH into their kernel)
audit emiters will block forever if userspace daemon cannot handle backlog. That commit just breaks timeout condition, after timeout waiting loop turns into busy loop until deamon dies or returns back to work.
this trivial patch should fix that problem
kernel/audit.c struct audit_buffer *audit_log_start(struct audit_context *ctx, gfp_t gfp_mask, · line 1222
Quoted 10 lines
kernel/audit.c +3 -2
@@ -1215,9 +1215,10 @@ struct audit_buffer *audit_log_start(struct audit_context *ctx, gfp_t gfp_mask,
 
                           sleep_time = timeout_start + audit_backlog_wait_time -
                                           jiffies;
-                       if ((long)sleep_time>   0)
+                       if ((long)sleep_time>   0) {
                                   wait_for_auditd(sleep_time);
-                       continue;
+                               continue;
+                       }
                   }
Chuck Anderson posted a similar fix:
   http://marc.info/?l=linux-kernel&m=137817994623832&w=2

Quoted 7 lines

Quoted 4 lines
Quoted 2 lines
I still get a hang for around a minute with Chuck's fix, I believe I'll get the same thing with yours.
Yep, this is normal behaviour -- default audit_backlog_wait_time is 60 seconds.
Yes, I know that's the cause but I don't call it normal behavior to be unable to use my system during 60 seconds.

This stuff was designed for auditing, so it shouldn't loose messages too easily. Meanwhile 'readahead' reuses it for a different purpose without proper tuning. I think kernel should provide interface for tuning that timeout and let 'readahead' set it to zero or some small value.

Quoted 3 lines

Quoted 3 lines
But this logic is really strange, I don't see any interface for tuning that timeout and seems like kernel set it to zero after first disaster and never recovers it back.

Eric Paris

maintainer

2013-09-10 16:03 UTC #11 lore raw

In reply to Konstantin Khlebnikov

Quoted 73 lines · Konstantin Khlebnikov

Quoted 50 lines · Luiz Capitulino
I'm getting the following soft lockup:
CPU: 6 PID: 2278 Comm: killall5 Tainted: GF            3.11.0-rc7+ #1
Hardware name: Bochs Bochs, BIOS Bochs 01/01/2011
  0000000000000099 ffff88011fd83de8 ffffffff815324df 0000000000002800
  ffffffff817d48f9 ffff88011fd83e68 ffffffff8152e669 ffff88011fd83e68
  ffffffff00000008 ffff88011fd83e78 ffff88011fd83e18 0000004081dac040
Call Trace:
  <IRQ>   [<ffffffff815324df>] dump_stack+0x46/0x58
  [<ffffffff8152e669>] panic+0xbb/0x1c4
  [<ffffffff810d03c3>] watchdog_timer_fn+0x163/0x170
  [<ffffffff8106c691>] __run_hrtimer+0x81/0x1c0
  [<ffffffff810d0260>] ? watchdog+0x30/0x30
  [<ffffffff8106cea7>] hrtimer_interrupt+0x107/0x240
  [<ffffffff8102f61b>] local_apic_timer_interrupt+0x3b/0x60
  [<ffffffff81542465>] smp_apic_timer_interrupt+0x45/0x60
  [<ffffffff8154124a>] apic_timer_interrupt+0x6a/0x70
  <EOI>   [<ffffffff810c2f5f>] ? audit_log_start+0xbf/0x430
  [<ffffffff810c2fe7>] ? audit_log_start+0x147/0x430
  [<ffffffff81079030>] ? try_to_wake_up+0x2a0/0x2a0
  [<ffffffff810c86be>] audit_log_exit+0x6ae/0xc30
  [<ffffffff81188662>] ? __alloc_fd+0x42/0x100
  [<ffffffff810c98e7>] __audit_syscall_exit+0x257/0x2b0
  [<ffffffff81540794>] sysret_audit+0x17/0x21
The reproducer is somewhat unusual:
1. Install RHEL6.5 (maybe a similar older user-space will do)
2. Boot the just installed system
3. In this first boot you'll meet the firstboot script, which will do some setup and (depending on your answers) it will reboot the machine
4. During that first reboot the system hangs while terminating all processes:
Sending all processes the TERM signal...
It's when the soft lockup above happens. And yes, I managed to get this with latest upstream kernel (HEAD fa8218def1b1)
I'm reproducing it on a VM, but the first report was on bare-metal.
This is what is happening:
1. audit_log_start() is called
2. As we have SKBs waiting in audit_skb_queue and all conditions evaluate to true, we sleep in wait_for_auditd()
3. Go to 2, until sleep_time gets negative and audit_log_start() just busy-waits
Quoted 4 lines
Now, *why* this is happening is a mistery to me. I tried debugging it, but all I could find is that at some point the kauditd thread never wakes up after having called schedule(). I even tried waking it up before calling wait_for_auditd(), but it didn't.
We run into the same problem in rhel6 kernel.
"readahead-collector" uses audit interface and sometimes stuck in 'stopped' state.
After commit 829199197a430dade2519d54f5545c4a094393b8
(which was backported by RH into their kernel)
audit emiters will block forever if userspace daemon cannot handle backlog. That commit just breaks timeout condition, after timeout waiting loop turns into busy loop until deamon dies or returns back to work.
this trivial patch should fix that problem
kernel/audit.c +0 -0
@@ -1215,9 +1215,10 @@ struct audit_buffer *audit_log_start(struct audit_context *ctx, gfp_t gfp_mask,
 
                         sleep_time = timeout_start + audit_backlog_wait_time -

kernel/audit.c struct audit_buffer *audit_log_start(struct audit_context *ctx, gfp_t gfp_mask, · line 1224

Quoted 10 lines

kernel/audit.c +3 -2

                                         jiffies;
-                       if ((long)sleep_time > 0)
+                       if ((long)sleep_time > 0) {
                                 wait_for_auditd(sleep_time);
-                       continue;
+                               continue;
+                       }
                 }
                 if (audit_rate_check() && printk_ratelimit())
                         printk(KERN_WARNING

I think this is the right(ish) fix, at least it gets at the real bug. 829199197a430dade2519d54f5545c4a094393b8 definitely is the problem. The 60 second wait is NOT causing the soft lockup. Instead after the 60 second wait, sleep_time, will go negative on subsequent trips through the loop. Since sleep_time is negative we will hit the continue and loop FOREVER with no opportunity for progress. Aka, softlockup...

I think it's a really ?interesting? (poor) coding style to leave sleep_time going negative on the second trip through the loop to indicate a timeout in wait_for_auditd(). Maybe the function should be rewritten a bit. Have a return code from wait_for_auditd, if it waited 60 seconds, call the failure function, if it succeeded in less the 60 seconds continue along... At least something that makes the logic here obvious.

I think Richard is also going to set audit_backlog_wait_time to 0 on failure and will reset it to default on success. To address the other issue as well. That is just dumb.

RGB should be taking care of it in RHEL as soon as he gets this worked out.

-Eric

Luiz Capitulino

author

2013-09-10 17:45 UTC #12 lore raw

Quoted 73 lines · On Tue, 10 Sep 2013 12:03:25 -0400 Eric Paris <[email protected]> wrote:

Quoted 72 lines · Konstantin Khlebnikov
Quoted 50 lines · Luiz Capitulino
I'm getting the following soft lockup:
CPU: 6 PID: 2278 Comm: killall5 Tainted: GF            3.11.0-rc7+ #1
Hardware name: Bochs Bochs, BIOS Bochs 01/01/2011
  0000000000000099 ffff88011fd83de8 ffffffff815324df 0000000000002800
  ffffffff817d48f9 ffff88011fd83e68 ffffffff8152e669 ffff88011fd83e68
  ffffffff00000008 ffff88011fd83e78 ffff88011fd83e18 0000004081dac040
Call Trace:
  <IRQ>   [<ffffffff815324df>] dump_stack+0x46/0x58
  [<ffffffff8152e669>] panic+0xbb/0x1c4
  [<ffffffff810d03c3>] watchdog_timer_fn+0x163/0x170
  [<ffffffff8106c691>] __run_hrtimer+0x81/0x1c0
  [<ffffffff810d0260>] ? watchdog+0x30/0x30
  [<ffffffff8106cea7>] hrtimer_interrupt+0x107/0x240
  [<ffffffff8102f61b>] local_apic_timer_interrupt+0x3b/0x60
  [<ffffffff81542465>] smp_apic_timer_interrupt+0x45/0x60
  [<ffffffff8154124a>] apic_timer_interrupt+0x6a/0x70
  <EOI>   [<ffffffff810c2f5f>] ? audit_log_start+0xbf/0x430
  [<ffffffff810c2fe7>] ? audit_log_start+0x147/0x430
  [<ffffffff81079030>] ? try_to_wake_up+0x2a0/0x2a0
  [<ffffffff810c86be>] audit_log_exit+0x6ae/0xc30
  [<ffffffff81188662>] ? __alloc_fd+0x42/0x100
  [<ffffffff810c98e7>] __audit_syscall_exit+0x257/0x2b0
  [<ffffffff81540794>] sysret_audit+0x17/0x21
The reproducer is somewhat unusual:
1. Install RHEL6.5 (maybe a similar older user-space will do)
2. Boot the just installed system
3. In this first boot you'll meet the firstboot script, which will do some setup and (depending on your answers) it will reboot the machine
4. During that first reboot the system hangs while terminating all processes:
Sending all processes the TERM signal...
It's when the soft lockup above happens. And yes, I managed to get this with latest upstream kernel (HEAD fa8218def1b1)
I'm reproducing it on a VM, but the first report was on bare-metal.
This is what is happening:
1. audit_log_start() is called
2. As we have SKBs waiting in audit_skb_queue and all conditions evaluate to true, we sleep in wait_for_auditd()
3. Go to 2, until sleep_time gets negative and audit_log_start() just busy-waits
Quoted 4 lines
Now, *why* this is happening is a mistery to me. I tried debugging it, but all I could find is that at some point the kauditd thread never wakes up after having called schedule(). I even tried waking it up before calling wait_for_auditd(), but it didn't.
We run into the same problem in rhel6 kernel.
"readahead-collector" uses audit interface and sometimes stuck in 'stopped' state.
After commit 829199197a430dade2519d54f5545c4a094393b8
(which was backported by RH into their kernel)
audit emiters will block forever if userspace daemon cannot handle backlog. That commit just breaks timeout condition, after timeout waiting loop turns into busy loop until deamon dies or returns back to work.
this trivial patch should fix that problem
kernel/audit.c +0 -0
@@ -1215,9 +1215,10 @@ struct audit_buffer *audit_log_start(struct audit_context *ctx, gfp_t gfp_mask,
 

Quoted 15 lines

kernel/audit.c struct audit_buffer *audit_log_start(struct audit_context *ctx, gfp_t gfp_mask, · line 1224

Quoted 11 lines

kernel/audit.c +3 -2

                         sleep_time = timeout_start + audit_backlog_wait_time -
                                         jiffies;
-                       if ((long)sleep_time > 0)
+                       if ((long)sleep_time > 0) {
                                 wait_for_auditd(sleep_time);
-                       continue;
+                               continue;
+                       }
                 }
                 if (audit_rate_check() && printk_ratelimit())
                         printk(KERN_WARNING

I think this is the right(ish) fix, at least it gets at the real bug. 829199197a430dade2519d54f5545c4a094393b8 definitely is the problem. The 60 second wait is NOT causing the soft lockup.

It's not. What it does cause is a 60 seconds hang, during which my system is unusable. Let me stress that. It's not auditd that gets a 60 second hang. My _impression_ is that any process doing a system call will hang there, which causes the system to become unusable. IMHO, that's not acceptable behavior.

Now, I don't know if the other changes you suggest Richard doing are going to help with that (if they are then I'm all for them). Also, I wonder why this long hang is not a problem for Chuck's and Konstantin's test-cases, given they submitted similar fixes (which are also similar to my RFC).

Andrew Morton

2013-09-17 22:28 UTC #13 lore raw

In reply to Eric Paris

Quoted 4 lines · On Tue, 10 Sep 2013 12:03:25 -0400 Eric Paris <[email protected]> wrote:

Quoted 4 lines

kernel/audit.c +0 -0

@@ -1215,9 +1215,10 @@ struct audit_buffer *audit_log_start(struct audit_context *ctx, gfp_t gfp_mask,

Quoted 14 lines

kernel/audit.c struct audit_buffer *audit_log_start(struct audit_context *ctx, gfp_t gfp_mask, · line 1224

Quoted 11 lines

kernel/audit.c +3 -2

                         sleep_time = timeout_start + audit_backlog_wait_time -
                                         jiffies;
-                       if ((long)sleep_time > 0)
+                       if ((long)sleep_time > 0) {
                                 wait_for_auditd(sleep_time);
-                       continue;
+                               continue;
+                       }
                 }
                 if (audit_rate_check() && printk_ratelimit())
                         printk(KERN_WARNING

I think this is the right(ish) fix, at least it gets at the real bug. 829199197a430dade2519d54f5545c4a094393b8 definitely is the problem.

um, which idiot wrote that?

Thngs are somewhat foggy at present. I have two patches from Dan/Chuck:

Subject: audit: fix soft lockups due to loop in audit_log_start() wh,en audit_backlog_limit exceeded
Subject: audit: two efficiency fixes for audit mechanism

and two from Luiz:

Subject: audit: flush_hold_queue(): don't drop queued SKBs
Subject: audit: kaudit_send_skb(): make non-blocking call to netlink_unicast()

and now a protopatch from Konstantin which eparis likes.

So, umm, guys, can you please devote a bit of time to working out what we should do here?

Luiz Capitulino

author

2013-09-17 22:54 UTC #14 lore raw

Quoted 21 lines · On Tue, 17 Sep 2013 15:28:42 -0700 Andrew Morton <[email protected]>…

Quoted 4 lines · On Tue, 10 Sep 2013 12:03:25 -0400 Eric Paris <[email protected]> wrote:

Quoted 4 lines

kernel/audit.c +0 -0

@@ -1215,9 +1215,10 @@ struct audit_buffer *audit_log_start(struct audit_context *ctx, gfp_t gfp_mask,

Quoted 14 lines

kernel/audit.c struct audit_buffer *audit_log_start(struct audit_context *ctx, gfp_t gfp_mask, · line 1224

Quoted 11 lines

kernel/audit.c +3 -2

                         sleep_time = timeout_start + audit_backlog_wait_time -
                                         jiffies;
-                       if ((long)sleep_time > 0)
+                       if ((long)sleep_time > 0) {
                                 wait_for_auditd(sleep_time);
-                       continue;
+                               continue;
+                       }
                 }
                 if (audit_rate_check() && printk_ratelimit())
                         printk(KERN_WARNING

I think this is the right(ish) fix, at least it gets at the real bug. 829199197a430dade2519d54f5545c4a094393b8 definitely is the problem.

Quoted 1 line

um, which idiot wrote that?

LOL!

Quoted 8 lines

Thngs are somewhat foggy at present. I have two patches from Dan/Chuck:
Subject: audit: fix soft lockups due to loop in audit_log_start() wh,en audit_backlog_limit exceeded
Subject: audit: two efficiency fixes for audit mechanism
and two from Luiz:

Quoted 7 lines

Subject: audit: flush_hold_queue(): don't drop queued SKBs
Subject: audit: kaudit_send_skb(): make non-blocking call to netlink_unicast()
and now a protopatch from Konstantin which eparis likes.
So, umm, guys, can you please devote a bit of time to working out what we should do here?

You can drop my patches. Konstantin's patch is a better version of my first RFC. My second series is kind of a new concept which the audit team seems to disagree with, and I won't push hard on it.

Richard Guy Briggs

2013-09-18 01:57 UTC #15 lore raw

In reply to Andrew Morton

Quoted 21 lines · Andrew Morton

Quoted 4 lines · On Tue, 10 Sep 2013 12:03:25 -0400 Eric Paris <[email protected]> wrote:

Quoted 4 lines

kernel/audit.c +0 -0

@@ -1215,9 +1215,10 @@ struct audit_buffer *audit_log_start(struct audit_context *ctx, gfp_t gfp_mask,

Quoted 14 lines

kernel/audit.c struct audit_buffer *audit_log_start(struct audit_context *ctx, gfp_t gfp_mask, · line 1224

Quoted 11 lines

kernel/audit.c +3 -2

                         sleep_time = timeout_start + audit_backlog_wait_time -
                                         jiffies;
-                       if ((long)sleep_time > 0)
+                       if ((long)sleep_time > 0) {
                                 wait_for_auditd(sleep_time);
-                       continue;
+                               continue;
+                       }
                 }
                 if (audit_rate_check() && printk_ratelimit())
                         printk(KERN_WARNING

I think this is the right(ish) fix, at least it gets at the real bug. 829199197a430dade2519d54f5545c4a094393b8 definitely is the problem.

Quoted 1 line

um, which idiot wrote that?

Heh...

Quoted 5 lines

Thngs are somewhat foggy at present. I have two patches from Dan/Chuck:
Subject: audit: fix soft lockups due to loop in audit_log_start() wh,en audit_backlog_limit exceeded
Subject: audit: two efficiency fixes for audit mechanism

I have a patchset very similar to the first and breaking up the second, with some added bits to address other related issues I'll post RSN...

Quoted 9 lines

and two from Luiz:
Subject: audit: flush_hold_queue(): don't drop queued SKBs
Subject: audit: kaudit_send_skb(): make non-blocking call to netlink_unicast()
and now a protopatch from Konstantin which eparis likes.
So, umm, guys, can you please devote a bit of time to working out what we should do here?

It is coming... I'm hearing reports from others of the same bug, so it is getting around...

- RGB

--
Richard Guy Briggs <[email protected]>
Senior Software Engineer
Kernel Security
AMER ENG Base Operating Systems
Remote, Ottawa, Canada
Voice: +1.647.777.2635
Internal: (81) 32635
Alt: +1.613.693.0684x3545

Konstantin Khlebnikov

2013-09-18 09:48 UTC #16 lore raw

PATCH 1/1 audit: fix endless wait in audit_log_start()

In reply to Andrew Morton

After commit 829199197a430dade2519d54f5545c4a094393b8 audit emiters will block forever if userspace daemon cannot handle backlog. After the timeout waiting loop turns into busy loop and runs until daemon dies or returns back to work. This is minimal patch for that bug.

Signed-off-by Konstantin Khlebnikov <[email protected]>

Cc Andrew Morton <[email protected]>

Cc Luiz Capitulino <[email protected]>

Cc Richard Guy Briggs <[email protected]>

Cc Eric Paris <[email protected]>

Cc Chuck Anderson <[email protected]>

Cc Dan Duval <[email protected]>

Cc Dave Kleikamp <[email protected]>

---
 kernel/audit.c |    5 +++--
 1 file changed, 3 insertions(+), 2 deletions(-)

kernel/audit.c +3 -2

index 91e53d0..7b0e23a 100644
@@ -1117,9 +1117,10 @@ struct audit_buffer *audit_log_start(struct audit_context *ctx, gfp_t gfp_mask,
 
 			sleep_time = timeout_start + audit_backlog_wait_time -
 					jiffies;
-			if ((long)sleep_time > 0)
+			if ((long)sleep_time > 0) {
 				wait_for_auditd(sleep_time);
-			continue;
+				continue;
+			}
 		}
 		if (audit_rate_check() && printk_ratelimit())
 			printk(KERN_WARNING

Richard Guy Briggs

2013-09-18 13:31 UTC #17 lore raw

Re: [PATCH] audit: fix endless wait in audit_log_start()

Quoted 4 lines · Konstantin Khlebnikov

After commit 829199197a430dade2519d54f5545c4a094393b8 audit emiters will block forever if userspace daemon cannot handle backlog. After the timeout waiting loop turns into busy loop and runs until daemon dies or returns back to work. This is minimal patch for that bug.

Thanks Konstantin,

This patch is in my patchset...

Quoted 20 lines

Signed-off-by Konstantin Khlebnikov <[email protected]>
Cc Andrew Morton <[email protected]>
Cc Luiz Capitulino <[email protected]>
Cc Richard Guy Briggs <[email protected]>
Cc Eric Paris <[email protected]>
Cc Chuck Anderson <[email protected]>
Cc Dan Duval <[email protected]>
Cc Dave Kleikamp <[email protected]>
---
 kernel/audit.c |    5 +++--
 1 file changed, 3 insertions(+), 2 deletions(-)
kernel/audit.c +0 -0
index 91e53d0..7b0e23a 100644
@@ -1117,9 +1117,10 @@ struct audit_buffer *audit_log_start(struct audit_context *ctx, gfp_t gfp_mask,
 
 			sleep_time = timeout_start + audit_backlog_wait_time -

kernel/audit.c struct audit_buffer *audit_log_start(struct audit_context *ctx, gfp_t gfp_mask, · line 1126

Quoted 10 lines

kernel/audit.c +3 -2

 					jiffies;
-			if ((long)sleep_time > 0)
+			if ((long)sleep_time > 0) {
 				wait_for_auditd(sleep_time);
-			continue;
+				continue;
+			}
 		}
 		if (audit_rate_check() && printk_ratelimit())
 			printk(KERN_WARNING

- RGB

Richard Guy Briggs

2013-09-18 19:06 UTC #18 lore raw

cover Audit backlog queue fixes related to soft lockup

In reply to Andrew Morton

This patchset covers a number of issues surrounding the audit backlog queue. The original trigger was a bug in a patch to fix code that produced negative sleep times (commit 82919919). This bug caused soft lockups. There were a number of other issues raised surrounding this bug which have been attempted to be addressed in this patchset.

The first patch fixes this obvious bug.

The 2nd fixes the lack of reset to the original wait time that was set to zero under error conditions should the system recover from the conditions that tickled the first bug.

The 3rd makes use of the remaining timeout to avoid re-checking the loop conditions on error.

The 4th and 5th are efficiency fixes for waking up waiting processes only when necessary.

The 6th adds a boot parameter to temporarily override the backlog queue length in case more buffers are needed before auditd is available.

The 7th and 8th are to add a config option to make the backlog wait time configurable from the hard-coded default.

Richard Guy Briggs (8):
audit: avoid soft lockup due to audit_log_start() incorrect loop
termination
audit: reset audit backlog wait time after error recovery
audit: make use of remaining sleep time from wait_for_auditd
audit: efficiency fix 1: only wake up if queue shorter than backlog
limit
audit: efficiency fix 2: request exclusive wait since all need same
resource
audit: add boot option to override default backlog limit
audit: clean up AUDIT_GET/SET local variables and future-proof API
audit: add audit_backlog_wait_time configuration option

 include/uapi/linux/audit.h |    2 +
 kernel/audit.c             |  111 +++++++++++++++++++++++++++++++-------------
 2 files changed, 80 insertions(+), 33 deletions(-)

Richard Guy Briggs

2013-09-18 19:06 UTC #19 lore raw

PATCH 1/8 audit: avoid soft lockup due to audit_log_start() incorrect loop termination

In reply to Andrew Morton

Commit 82919919 caused the wait for auditd timeout condition to loop endlessly rather than fall through to the error recovery code.

 BUG: soft lockup - CPU#0 stuck for 22s! [preload:785]
 RIP: 0010:[<ffffffff810fb240>]  [<ffffffff810fb240>] audit_log_start+0xf0/0x460
 Call Trace:
  [<ffffffff810aca40>] ? try_to_wake_up+0x310/0x310
  [<ffffffff81100fd1>] audit_log_exit+0x51/0xcb0
  [<ffffffff811020b5>] __audit_syscall_exit+0x275/0x2d0
  [<ffffffff816ec540>] sysret_audit+0x17/0x21

If the timeout condition goes negative, the loop continues endlessly instead of breaking out and going to the failure code and allow other processes to run when auditd is unable to drain the queue fast enough.

This can easily be triggered by readahead-collector, in particular during installations. The readahead-collector (ab)uses the audit interface and sometimes gets stuck in a 'stopped' state.

To trigger:
readahead-collector -f &
pkill -SIGSTOP readahead-collector
top

See:

	https://lkml.org/lkml/2013/8/28/626
	https://lkml.org/lkml/2013/9/2/471
	https://lkml.org/lkml/2013/9/3/4

Signed-off-by Luiz Capitulino <[email protected]>

Signed-off-by Konstantin Khlebnikov <[email protected]>

Signed-off-by Dan Duval <[email protected]>

Signed-off-by Chuck Anderson <[email protected]>

Signed-off-by Richard Guy Briggs <[email protected]>

---
 kernel/audit.c |    5 +++--
 1 files changed, 3 insertions(+), 2 deletions(-)

kernel/audit.c +3 -2

index 91e53d0..7b0e23a 100644
@@ -1117,9 +1117,10 @@ struct audit_buffer *audit_log_start(struct audit_context *ctx, gfp_t gfp_mask,
 
 			sleep_time = timeout_start + audit_backlog_wait_time -
 					jiffies;
-			if ((long)sleep_time > 0)
+			if ((long)sleep_time > 0) {
 				wait_for_auditd(sleep_time);
-			continue;
+				continue;
+			}
 		}
 		if (audit_rate_check() && printk_ratelimit())
 			printk(KERN_WARNING

Signature · 1 line

1.7.1

Richard Guy Briggs

2013-09-18 19:06 UTC #20 lore raw

PATCH 2/8 audit: reset audit backlog wait time after error recovery

In reply to Andrew Morton

When the audit queue overflows and times out (audit_backlog_wait_time), the audit queue overflow timeout is set to zero. Once the audit queue overflow timeout condition recovers, the timeout should be reset to the original value.

Richard Guy Briggs

2013-09-18 19:06 UTC #21 lore raw

PATCH 3/8 audit: make use of remaining sleep time from wait_for_auditd

In reply to Andrew Morton

If wait_for_auditd() times out, go immediately to the error function rather than retesting the loop conditions.

Signed-off-by Richard Guy Briggs <[email protected]>

---
 kernel/audit.c |   12 ++++++++----
 1 files changed, 8 insertions(+), 4 deletions(-)

kernel/audit.c +8 -4

index 772725e..42c68db 100644
@@ -1054,18 +1054,21 @@ static inline void audit_get_stamp(struct audit_context *ctx,
 /*
  * Wait for auditd to drain the queue a little
  */
-static void wait_for_auditd(unsigned long sleep_time)
+static unsigned long wait_for_auditd(unsigned long sleep_time)
 {
+	unsigned long timeout = sleep_time;
 	DECLARE_WAITQUEUE(wait, current);
 	set_current_state(TASK_UNINTERRUPTIBLE);
 	add_wait_queue(&audit_backlog_wait, &wait);
 
 	if (audit_backlog_limit &&
 	    skb_queue_len(&audit_skb_queue) > audit_backlog_limit)
-		schedule_timeout(sleep_time);
+		timeout = schedule_timeout(sleep_time);
 
 	__set_current_state(TASK_RUNNING);
 	remove_wait_queue(&audit_backlog_wait, &wait);
+
+	return timeout;
 }
 
 /* Obtain an audit buffer.  This routine does locking to obtain the

@@ -1119,8 +1122,9 @@ struct audit_buffer *audit_log_start(struct audit_context *ctx, gfp_t gfp_mask,
 			sleep_time = timeout_start + audit_backlog_wait_time -
 					jiffies;
 			if ((long)sleep_time > 0) {
-				wait_for_auditd(sleep_time);
-				continue;
+				sleep_time = wait_for_auditd(sleep_time);
+				if ((long)sleep_time > 0)
+					continue;
 			}
 		}
 		if (audit_rate_check() && printk_ratelimit())

Signature · 1 line

1.7.1

Richard Guy Briggs

2013-09-18 19:06 UTC #22 lore raw

PATCH 4/8 audit: efficiency fix 1: only wake up if queue shorter than backlog limit

In reply to Andrew Morton

author: Dan Duval <[email protected]>

These and similar errors were seen on a patched 3.8 kernel when the audit subsystem was overrun during boot:

udevd[876]: worker [887] unexpectedly returned with status 0x0100 udevd[876]: worker [887] failed while handling
'/devices/pci0000:00/0000:00:03.0/0000:40:00.0'
udevd[876]: worker [880] unexpectedly returned with status 0x0100 udevd[876]: worker [880] failed while handling
'/devices/LNXSYSTM:00/LNXPWRBN:00/input/input1/event1'

udevadm settle - timeout of 180 seconds reached, the event queue
contains:

    /sys/devices/LNXSYSTM:00/LNXPWRBN:00/input/input1/event1 (3995)
    /sys/devices/LNXSYSTM:00/LNXSYBUS:00/PNP0A08:00/INT3F0D:00 (4034)

audit: audit_backlog=258 > audit_backlog_limit=256
audit: audit_lost=1 audit_rate_limit=0 audit_backlog_limit=256

The change below increases the efficiency of the audit code and prevents it from being overrun:

Only issue a wake_up in kauditd if the length of the skb queue is less than the backlog limit. Otherwise, threads waiting in wait_for_auditd() will simply wake up, discover that the queue is still too long for them to proceed, and go back to sleep. This results in wasted context switches and machine cycles. kauditd_thread() is the only function that removes buffers from audit_skb_queue so we can't race. If we did, the timeout in wait_for_auditd() would expire and the waiting thread would continue.

See: https://lkml.org/lkml/2013/9/2/479

Signed-off-by Dan Duval <[email protected]>

Signed-off-by Chuck Anderson <[email protected]>

Signed-off-by Richard Guy Briggs <[email protected]>

---
 kernel/audit.c |    4 +++-
 1 files changed, 3 insertions(+), 1 deletions(-)

kernel/audit.c +3 -1

index 42c68db..25fab2d 100644
@@ -448,8 +448,10 @@ static int kauditd_thread(void *dummy)
 		flush_hold_queue();
 
 		skb = skb_dequeue(&audit_skb_queue);
-		wake_up(&audit_backlog_wait);
+
 		if (skb) {
+			if(skb_queue_len(&audit_skb_queue) <= audit_backlog_limit)
+				wake_up(&audit_backlog_wait);
 			if (audit_pid)
 				kauditd_send_skb(skb);
 			else

Signature · 1 line

1.7.1

Richard Guy Briggs

2013-09-18 19:06 UTC #23 lore raw

PATCH 5/8 audit: efficiency fix 2: request exclusive wait since all need same resource

In reply to Andrew Morton

author: Dan Duval <[email protected]>

These and similar errors were seen on a patched 3.8 kernel when the audit subsystem was overrun during boot:

udevadm settle - timeout of 180 seconds reached, the event queue
contains:

    /sys/devices/LNXSYSTM:00/LNXPWRBN:00/input/input1/event1 (3995)
    /sys/devices/LNXSYSTM:00/LNXSYBUS:00/PNP0A08:00/INT3F0D:00 (4034)

audit: audit_backlog=258 > audit_backlog_limit=256
audit: audit_lost=1 audit_rate_limit=0 audit_backlog_limit=256

The change below increases the efficiency of the audit code and prevents it from being overrun:

Use add_wait_queue_exclusive() in wait_for_auditd() to put the thread on the wait queue. When kauditd dequeues an skb, all of the waiting threads are waiting for the same resource, but only one is going to get it, so there's no need to wake up more than one waiter.

See: https://lkml.org/lkml/2013/9/2/479

Signed-off-by Dan Duval <[email protected]>

Signed-off-by Chuck Anderson <[email protected]>

Signed-off-by Richard Guy Briggs <[email protected]>

---
 kernel/audit.c |    2 +-
 1 files changed, 1 insertions(+), 1 deletions(-)

kernel/audit.c +1 -1

index 25fab2d..990d02f 100644
@@ -1061,7 +1061,7 @@ static unsigned long wait_for_auditd(unsigned long sleep_time)
 	unsigned long timeout = sleep_time;
 	DECLARE_WAITQUEUE(wait, current);
 	set_current_state(TASK_UNINTERRUPTIBLE);
-	add_wait_queue(&audit_backlog_wait, &wait);
+	add_wait_queue_exclusive(&audit_backlog_wait, &wait);
 
 	if (audit_backlog_limit &&
 	    skb_queue_len(&audit_skb_queue) > audit_backlog_limit)

Signature · 1 line

1.7.1

Richard Guy Briggs

2013-09-18 19:06 UTC #24 lore raw

PATCH 6/8 audit: add boot option to override default backlog limit

In reply to Andrew Morton

The default audit_backlog_limit is 64. This was a reasonable limit at one time.

systemd causes so much audit queue activity on startup that auditd doesn't start before the backlog queue has already overflowed by more than a factor of
2. On a system with audit= not set on the kernel command line, this isn't an issue since that history isn't kept for auditd when it is available. On a system with audit=1 set on the kernel command line, kaudit tries to keep that history until auditd is able to drain the queue.

This default can be changed by the "-b" option in audit.rules once the system has booted, but won't help with lost messages on boot.

One way to solve this would be to increase the default backlog queue size to avoid losing any messages before auditd is able to consume them. This would be overkill to the embedded community and insufficient for some servers.

Another way to solve it might be to add a kconfig option to set the default based on the system type. An embedded system would get the current (or smaller) default, while Workstations might get more than now and servers might get more.

None of these solutions helps if a system's compiled default is too small to see the lost messages without compiling a new kernel.

This patch adds a boot option (audit already has one to enable/disable it) "audit_backlog_limit=<n>" that overrides the default to allow the system administrator to set the backlog limit.

Signed-off-by Richard Guy Briggs <[email protected]>

---
 kernel/audit.c |   14 +++++++++++++-
 1 files changed, 13 insertions(+), 1 deletions(-)

kernel/audit.c +13 -1

index 990d02f..acfa7a9 100644
@@ -944,9 +944,21 @@ static int __init audit_enable(char *str)
 
 	return 1;
 }
-
 __setup("audit=", audit_enable);
 
+/* Process kernel command-line parameter at boot time.  audit_backlog_limit=<n> */
+static int __init audit_backlog_limit_set(char *str)
+{
+	int audit_backlog_limit_arg = simple_strtol(str, NULL, 0);
+	if ((audit_backlog_limit_arg >= 0) && (audit_backlog_limit_arg < 8192))
+		audit_backlog_limit = audit_backlog_limit_arg;
+
+	printk(KERN_INFO "audit_backlog_limit: %d\n", audit_backlog_limit);
+
+	return 1;
+}
+__setup("audit_backlog_limit=", audit_backlog_limit_set);
+
 static void audit_buffer_free(struct audit_buffer *ab)
 {
 	unsigned long flags;

Signature · 1 line

1.7.1

Richard Guy Briggs

2013-09-18 19:06 UTC #25 lore raw

PATCH 7/8 audit: clean up AUDIT_GET/SET local variables and future-proof API

In reply to Andrew Morton

Re-named confusing local variable names (status_set and status_get didn't agree with their command type name) and reduced their scope.

Future-proof API changes by not depending on the exact size of the audit_status struct.

Signed-off-by Richard Guy Briggs <[email protected]>

---
 kernel/audit.c |   51 +++++++++++++++++++++++++++------------------------
 1 files changed, 27 insertions(+), 24 deletions(-)

kernel/audit.c +27 ~~-24~~

index acfa7a9..3d17670 100644
@@ -635,7 +635,6 @@ static int audit_receive_msg(struct sk_buff *skb, struct nlmsghdr *nlh)
 {
 	u32			seq;
 	void			*data;
-	struct audit_status	*status_get, status_set;
 	int			err;
 	struct audit_buffer	*ab;
 	u16			msg_type = nlh->nlmsg_type;

@@ -661,47 +660,51 @@ static int audit_receive_msg(struct sk_buff *skb, struct nlmsghdr *nlh)
 	data = nlmsg_data(nlh);
 
 	switch (msg_type) {
-	case AUDIT_GET:
-		status_set.enabled	 = audit_enabled;
-		status_set.failure	 = audit_failure;
-		status_set.pid		 = audit_pid;
-		status_set.rate_limit	 = audit_rate_limit;
-		status_set.backlog_limit = audit_backlog_limit;
-		status_set.lost		 = atomic_read(&audit_lost);
-		status_set.backlog	 = skb_queue_len(&audit_skb_queue);
+	case AUDIT_GET: {
+		struct audit_status	s;
+		s.enabled	 = audit_enabled;
+		s.failure	 = audit_failure;
+		s.pid		 = audit_pid;
+		s.rate_limit	 = audit_rate_limit;
+		s.backlog_limit = audit_backlog_limit;
+		s.lost		 = atomic_read(&audit_lost);
+		s.backlog	 = skb_queue_len(&audit_skb_queue);
 		audit_send_reply(NETLINK_CB(skb).portid, seq, AUDIT_GET, 0, 0,
-				 &status_set, sizeof(status_set));
+				 &s, sizeof(s));
 		break;
-	case AUDIT_SET:
-		if (nlh->nlmsg_len < sizeof(struct audit_status))
-			return -EINVAL;
-		status_get   = (struct audit_status *)data;
-		if (status_get->mask & AUDIT_STATUS_ENABLED) {
-			err = audit_set_enabled(status_get->enabled);
+	}
+	case AUDIT_SET: {
+		struct audit_status	s;
+		memset(&s, 0, sizeof(s));
+		/* guard against past and future API changes */
+		memcpy(&s, data, min(sizeof(s), (size_t)nlh->nlmsg_len));
+		if (s.mask & AUDIT_STATUS_ENABLED) {
+			err = audit_set_enabled(s.enabled);
 			if (err < 0)
 				return err;
 		}
-		if (status_get->mask & AUDIT_STATUS_FAILURE) {
-			err = audit_set_failure(status_get->failure);
+		if (s.mask & AUDIT_STATUS_FAILURE) {
+			err = audit_set_failure(s.failure);
 			if (err < 0)
 				return err;
 		}
-		if (status_get->mask & AUDIT_STATUS_PID) {
-			int new_pid = status_get->pid;
+		if (s.mask & AUDIT_STATUS_PID) {
+			int new_pid = s.pid;
 
 			if (audit_enabled != AUDIT_OFF)
 				audit_log_config_change("audit_pid", new_pid, audit_pid, 1);
 			audit_pid = new_pid;
 			audit_nlk_portid = NETLINK_CB(skb).portid;
 		}
-		if (status_get->mask & AUDIT_STATUS_RATE_LIMIT) {
-			err = audit_set_rate_limit(status_get->rate_limit);
+		if (s.mask & AUDIT_STATUS_RATE_LIMIT) {
+			err = audit_set_rate_limit(s.rate_limit);
 			if (err < 0)
 				return err;
 		}
-		if (status_get->mask & AUDIT_STATUS_BACKLOG_LIMIT)
-			err = audit_set_backlog_limit(status_get->backlog_limit);
+		if (s.mask & AUDIT_STATUS_BACKLOG_LIMIT)
+			err = audit_set_backlog_limit(s.backlog_limit);
 		break;
+	}
 	case AUDIT_USER:
 	case AUDIT_FIRST_USER_MSG ... AUDIT_LAST_USER_MSG:
 	case AUDIT_FIRST_USER_MSG2 ... AUDIT_LAST_USER_MSG2:

Signature · 1 line

1.7.1

Steve Grubb

2013-09-19 21:18 UTC #26 lore raw

Re: [PATCH 7/8] audit: clean up AUDIT_GET/SET local variables and future-proof API

Quoted 5 lines · Richard Guy Briggs

Re-named confusing local variable names (status_set and status_get didn't agree with their command type name) and reduced their scope.
Future-proof API changes by not depending on the exact size of the audit_status struct.

I wished things like this were coordinated before being written. We had some discussion of this back in July under a topic, "audit: implement generic feature setting and retrieving". Maybe that API can be fixed so its not just set/unset but can take a number as well.

Also, because there is no way to query the kernel to see what kind of things it supports, we've typically defined a new message type and put into it exactly what we need. In other words, if you want something expandable, the define a new message type like AUDIT_GET_EXT and AUDIT_SET_EXT and build it to be expandable.

Then in a future version of auditctl it will try to use the new command and fall back to the old one if it gets EINVAL. Then some years later the old GET and SET can be deprecated. But the audit code base has to support a wide variety of kernels and suddenly making on resizable might break old code on new kernel. A new message type is a safer migration path.

-Steve

Quoted 63 lines

Signed-off-by Richard Guy Briggs <[email protected]>

---
 kernel/audit.c |   51 +++++++++++++++++++++++++++------------------------
 1 files changed, 27 insertions(+), 24 deletions(-)

kernel/audit.c +20 ~~-18~~

index acfa7a9..3d17670 100644
@@ -635,7 +635,6 @@ static int audit_receive_msg(struct sk_buff *skb, struct
 nlmsghdr *nlh) {
 	u32			seq;
 	void			*data;
-	struct audit_status	*status_get, status_set;
 	int			err;
 	struct audit_buffer	*ab;
 	u16			msg_type = nlh->nlmsg_type;

@@ -661,47 +660,51 @@ static int audit_receive_msg(struct sk_buff *skb,
 struct nlmsghdr *nlh) data = nlmsg_data(nlh);
 
 	switch (msg_type) {
-	case AUDIT_GET:
-		status_set.enabled	 = audit_enabled;
-		status_set.failure	 = audit_failure;
-		status_set.pid		 = audit_pid;
-		status_set.rate_limit	 = audit_rate_limit;
-		status_set.backlog_limit = audit_backlog_limit;
-		status_set.lost		 = atomic_read(&audit_lost);
-		status_set.backlog	 = skb_queue_len(&audit_skb_queue);
+	case AUDIT_GET: {
+		struct audit_status	s;
+		s.enabled	 = audit_enabled;
+		s.failure	 = audit_failure;
+		s.pid		 = audit_pid;
+		s.rate_limit	 = audit_rate_limit;
+		s.backlog_limit = audit_backlog_limit;
+		s.lost		 = atomic_read(&audit_lost);
+		s.backlog	 = skb_queue_len(&audit_skb_queue);
 		audit_send_reply(NETLINK_CB(skb).portid, seq, AUDIT_GET, 0, 0,
-				 &status_set, sizeof(status_set));
+				 &s, sizeof(s));
 		break;
-	case AUDIT_SET:
-		if (nlh->nlmsg_len < sizeof(struct audit_status))
-			return -EINVAL;
-		status_get   = (struct audit_status *)data;
-		if (status_get->mask & AUDIT_STATUS_ENABLED) {
-			err = audit_set_enabled(status_get->enabled);
+	}
+	case AUDIT_SET: {
+		struct audit_status	s;
+		memset(&s, 0, sizeof(s));
+		/* guard against past and future API changes */
+		memcpy(&s, data, min(sizeof(s), (size_t)nlh->nlmsg_len));
+		if (s.mask & AUDIT_STATUS_ENABLED) {
+			err = audit_set_enabled(s.enabled);
 			if (err < 0)
 				return err;
 		}
-		if (status_get->mask & AUDIT_STATUS_FAILURE) {
-			err = audit_set_failure(status_get->failure);
+		if (s.mask & AUDIT_STATUS_FAILURE) {
+			err = audit_set_failure(s.failure);

kernel/audit.c static int audit_receive_msg(struct sk_buff *skb, · line 695

Quoted 10 lines

kernel/audit.c +2 -2

 			if (err < 0)
 				return err;
 		}
-		if (status_get->mask & AUDIT_STATUS_PID) {
-			int new_pid = status_get->pid;
+		if (s.mask & AUDIT_STATUS_PID) {
+			int new_pid = s.pid;
 
 			if (audit_enabled != AUDIT_OFF)
 				audit_log_config_change("audit_pid", new_pid, audit_pid,

1);

Quoted 19 lines

kernel/audit.c +5 -4

 			audit_pid = new_pid;
 			audit_nlk_portid = NETLINK_CB(skb).portid;
 		}
-		if (status_get->mask & AUDIT_STATUS_RATE_LIMIT) {
-			err = audit_set_rate_limit(status_get->rate_limit);
+		if (s.mask & AUDIT_STATUS_RATE_LIMIT) {
+			err = audit_set_rate_limit(s.rate_limit);
 			if (err < 0)
 				return err;
 		}
-		if (status_get->mask & AUDIT_STATUS_BACKLOG_LIMIT)
-			err = audit_set_backlog_limit(status_get->backlog_limit);
+		if (s.mask & AUDIT_STATUS_BACKLOG_LIMIT)
+			err = audit_set_backlog_limit(s.backlog_limit);
 		break;
+	}
 	case AUDIT_USER:
 	case AUDIT_FIRST_USER_MSG ... AUDIT_LAST_USER_MSG:
 	case AUDIT_FIRST_USER_MSG2 ... AUDIT_LAST_USER_MSG2:

Eric Paris

maintainer

2013-09-20 14:47 UTC #27 lore raw

Re: [PATCH 7/8] audit: clean up AUDIT_GET/SET local variables and future-proof API

Quoted 11 lines · Steve Grubb

Quoted 5 lines · Richard Guy Briggs
Re-named confusing local variable names (status_set and status_get didn't agree with their command type name) and reduced their scope.
Future-proof API changes by not depending on the exact size of the audit_status struct.
I wished things like this were coordinated before being written. We had some discussion of this back in July under a topic, "audit: implement generic feature setting and retrieving". Maybe that API can be fixed so its not just set/unset but can take a number as well.

Your right, we did talk about it. Though it seems we talked past each other. What was implemented was an on off extensible interface. The status interface already fits for setting numbers. And because of how it is used has been extended is is extensible for setting numbers.

Quoted 3 lines

Also, because there is no way to query the kernel to see what kind of things it supports

I'll agree. Richard, can you please add a version field to the status? Start at version 1. Any time we add a new audit feature we'll bump it.

Quoted 4 lines

, we've typically defined a new message type and put into it exactly what we need. In other words, if you want something expandable, the define a new message type like AUDIT_GET_EXT and AUDIT_SET_EXT and build it to be expandable.

There is no reason we can't use what we have. (As we've done it before)

Richard Guy Briggs

2013-09-23 16:38 UTC #28 lore raw

Re: [PATCH 7/8] audit: clean up AUDIT_GET/SET local variables and future-proof API

Quoted 5 lines · Eric Paris

Quoted 4 lines · Steve Grubb
Quoted 3 lines · Richard Guy Briggs
Re-named confusing local variable names (status_set and status_get didn't agree with their command type name) and reduced their scope.

Quoted 8 lines

Quoted 5 lines
Quoted 2 lines
Future-proof API changes by not depending on the exact size of the audit_status struct.
Also, because there is no way to query the kernel to see what kind of things it supports
I'll agree. Richard, can you please add a version field to the status? Start at version 1. Any time we add a new audit feature we'll bump it.

Done. Adding the interface and version field is version 1, so without, it is zero. Adding the backlog timeout is version 2.

- RGB

Richard Guy Briggs

2013-09-18 19:06 UTC #29 lore raw

PATCH 8/8 audit: add audit_backlog_wait_time configuration option

In reply to Andrew Morton

reaahead-collector abuses the audit logging facility to discover which files are accessed at boot time to make a pre-load list

Add a tuning option to audit_backlog_wait_time so that if auditd can't keep up, or gets blocked, the callers won't be blocked.

Signed-off-by Richard Guy Briggs <[email protected]>

---
 include/uapi/linux/audit.h |    2 ++
 kernel/audit.c             |   22 +++++++++++++++++++++-
 2 files changed, 23 insertions(+), 1 deletions(-)

include/uapi/linux/audit.h +2 -0

index 75cef3f..493a66e 100644
@@ -316,6 +316,7 @@ enum {
 #define AUDIT_STATUS_PID		0x0004
 #define AUDIT_STATUS_RATE_LIMIT		0x0008
 #define AUDIT_STATUS_BACKLOG_LIMIT	0x0010
+#define AUDIT_STATUS_BACKLOG_WAIT_TIME	0x0020
 				/* Failure-to-log actions */
 #define AUDIT_FAIL_SILENT	0
 #define AUDIT_FAIL_PRINTK	1

@@ -367,6 +368,7 @@ struct audit_status {
 	__u32		backlog_limit;	/* waiting messages limit */
 	__u32		lost;		/* messages lost */
 	__u32		backlog;	/* messages waiting in queue */
+	__u32		backlog_wait_time;/* message queue wait timeout */
 };
 
 struct audit_tty_status {

kernel/audit.c +21 -1

index 3d17670..fc535b6 100644
@@ -321,6 +321,12 @@ static int audit_set_backlog_limit(int limit)
 	return audit_do_config_change("audit_backlog_limit", &audit_backlog_limit, limit);
 }
 
+static int audit_set_backlog_wait_time(int timeout)
+{
+	return audit_do_config_change("audit_backlog_wait_time",
+				      &audit_backlog_wait_time, timeout);
+}
+
 static int audit_set_enabled(int state)
 {
 	int rc;

@@ -669,6 +675,7 @@ static int audit_receive_msg(struct sk_buff *skb, struct nlmsghdr *nlh)
 		s.backlog_limit = audit_backlog_limit;
 		s.lost		 = atomic_read(&audit_lost);
 		s.backlog	 = skb_queue_len(&audit_skb_queue);
+		s.backlog_wait_time = audit_backlog_wait_time;
 		audit_send_reply(NETLINK_CB(skb).portid, seq, AUDIT_GET, 0, 0,
 				 &s, sizeof(s));
 		break;

@@ -701,8 +708,21 @@ static int audit_receive_msg(struct sk_buff *skb, struct nlmsghdr *nlh)
 			if (err < 0)
 				return err;
 		}
-		if (s.mask & AUDIT_STATUS_BACKLOG_LIMIT)
+		if (s.mask & AUDIT_STATUS_BACKLOG_LIMIT) {
 			err = audit_set_backlog_limit(s.backlog_limit);
+			if (err < 0)
+				return err;
+		}
+		if (s.mask & AUDIT_STATUS_BACKLOG_WAIT_TIME) {
+			if (sizeof(s) > (size_t)nlh->nlmsg_len)
+				break;
+			if (s.backlog_wait_time < 0 ||
+			    s.backlog_wait_time > 10*AUDIT_BACKLOG_WAIT_TIME)
+				return -EINVAL;
+			err = audit_set_backlog_wait_time(s.backlog_wait_time);
+			if (err < 0)
+				return err;
+		}
 		break;
 	}
 	case AUDIT_USER:

Signature · 1 line

1.7.1

Eric Paris

maintainer

2013-09-18 20:33 UTC #30 lore raw

Re: [PATCH 8/8] audit: add audit_backlog_wait_time configuration option

Quoted 60 lines · Richard Guy Briggs

reaahead-collector abuses the audit logging facility to discover which files are accessed at boot time to make a pre-load list

Add a tuning option to audit_backlog_wait_time so that if auditd can't keep up, or gets blocked, the callers won't be blocked.

Signed-off-by Richard Guy Briggs <[email protected]>

---
 include/uapi/linux/audit.h |    2 ++
 kernel/audit.c             |   22 +++++++++++++++++++++-
 2 files changed, 23 insertions(+), 1 deletions(-)

include/uapi/linux/audit.h +2 -0

index 75cef3f..493a66e 100644
@@ -316,6 +316,7 @@ enum {
 #define AUDIT_STATUS_PID		0x0004
 #define AUDIT_STATUS_RATE_LIMIT		0x0008
 #define AUDIT_STATUS_BACKLOG_LIMIT	0x0010
+#define AUDIT_STATUS_BACKLOG_WAIT_TIME	0x0020
 				/* Failure-to-log actions */
 #define AUDIT_FAIL_SILENT	0
 #define AUDIT_FAIL_PRINTK	1

@@ -367,6 +368,7 @@ struct audit_status {
 	__u32		backlog_limit;	/* waiting messages limit */
 	__u32		lost;		/* messages lost */
 	__u32		backlog;	/* messages waiting in queue */
+	__u32		backlog_wait_time;/* message queue wait timeout */
 };
 
 struct audit_tty_status {

kernel/audit.c +7 -0

index 3d17670..fc535b6 100644
@@ -321,6 +321,12 @@ static int audit_set_backlog_limit(int limit)
 	return audit_do_config_change("audit_backlog_limit", &audit_backlog_limit, limit);
 }
 
+static int audit_set_backlog_wait_time(int timeout)
+{
+	return audit_do_config_change("audit_backlog_wait_time",
+				      &audit_backlog_wait_time, timeout);
+}
+
 static int audit_set_enabled(int state)
 {
 	int rc;

@@ -669,6 +675,7 @@ static int audit_receive_msg(struct sk_buff *skb, struct nlmsghdr *nlh)
 		s.backlog_limit = audit_backlog_limit;
 		s.lost		 = atomic_read(&audit_lost);
 		s.backlog	 = skb_queue_len(&audit_skb_queue);
+		s.backlog_wait_time = audit_backlog_wait_time;
 		audit_send_reply(NETLINK_CB(skb).portid, seq, AUDIT_GET, 0, 0,
 				 &s, sizeof(s));
 		break;

@@ -701,8 +708,21 @@ static int audit_receive_msg(struct sk_buff *skb, struct nlmsghdr *nlh)
 			if (err < 0)
 				return err;

kernel/audit.c static int audit_receive_msg(struct sk_buff *skb, struct nlmsghdr *nlh) · line 718

Quoted 10 lines

kernel/audit.c +7 -1

 		}
-		if (s.mask & AUDIT_STATUS_BACKLOG_LIMIT)
+		if (s.mask & AUDIT_STATUS_BACKLOG_LIMIT) {
 			err = audit_set_backlog_limit(s.backlog_limit);
+			if (err < 0)
+				return err;
+		}
+		if (s.mask & AUDIT_STATUS_BACKLOG_WAIT_TIME) {
+			if (sizeof(s) > (size_t)nlh->nlmsg_len)
+				break;

What gets returned here? I think err has a value of 0, but it doesn't seem to have been clearly intentional. If they know about the AUDIT_STATUS_BACKLOG_WAIT_TIME flag, but they didn't send a long enough skb? That seems like an error condition....

Quoted 10 lines

kernel/audit.c +7 -0

+			if (s.backlog_wait_time < 0 ||
+			    s.backlog_wait_time > 10*AUDIT_BACKLOG_WAIT_TIME)
+				return -EINVAL;
+			err = audit_set_backlog_wait_time(s.backlog_wait_time);
+			if (err < 0)
+				return err;
+		}
 		break;
 	}
 	case AUDIT_USER:

Richard Guy Briggs

2013-09-18 20:49 UTC #31 lore raw

Re: [PATCH 8/8] audit: add audit_backlog_wait_time configuration option

Quoted 21 lines · Eric Paris

Quoted 20 lines · Richard Guy Briggs
reaahead-collector abuses the audit logging facility to discover which files are accessed at boot time to make a pre-load list
Add a tuning option to audit_backlog_wait_time so that if auditd can't keep up, or gets blocked, the callers won't be blocked.
kernel/audit.c +4 -1
index 3d17670..fc535b6 100644
@@ -701,8 +708,21 @@ static int audit_receive_msg(struct sk_buff *skb, struct nlmsghdr *nlh)
 			if (err < 0)
 				return err;
 		}
-		if (s.mask & AUDIT_STATUS_BACKLOG_LIMIT)
+		if (s.mask & AUDIT_STATUS_BACKLOG_LIMIT) {
 			err = audit_set_backlog_limit(s.backlog_limit);
+			if (err < 0)
+				return err;
+		}

Quoted 8 lines

kernel/audit.c static int audit_receive_msg(struct sk_buff *skb, struct nlmsghdr *nlh) · line 718
Quoted 3 lines
kernel/audit.c +3 -0
+		if (s.mask & AUDIT_STATUS_BACKLOG_WAIT_TIME) {
+			if (sizeof(s) > (size_t)nlh->nlmsg_len)
+				break;
What gets returned here? I think err has a value of 0, but it doesn't seem to have been clearly intentional. If they know about the AUDIT_STATUS_BACKLOG_WAIT_TIME flag, but they didn't send a long enough skb? That seems like an error condition....

The intent was that it is a NOP, since err would have a value of zero, but I see your point, that if that flag is present, the struct member should be too. My original intent was that if the structure member wasn't present, it would default to zero, unintentionally setting the wait time to zero. It was part of my paranoia in the absence of an API version indicator. No harm done, but I agree it should return an error.

Thanks for the catch.

Quoted 3 lines

kernel/audit.c static int audit_receive_msg(struct sk_buff *skb, struct nlmsghdr *nlh) · line 721
Quoted 3 lines
kernel/audit.c +3 -0
+			if (s.backlog_wait_time < 0 ||
+			    s.backlog_wait_time > 10*AUDIT_BACKLOG_WAIT_TIME)
+				return -EINVAL;

I assume values less than zero or larger than 10 times the current default of one minute are errors or unreasonable.

Any argument for more than 10 minutes?

- RGB

Eric Paris

maintainer

2013-09-18 20:54 UTC #32 lore raw

Re: [PATCH 8/8] audit: add audit_backlog_wait_time configuration option

Quoted 40 lines · Richard Guy Briggs

Quoted 21 lines · Eric Paris
Quoted 20 lines · Richard Guy Briggs
reaahead-collector abuses the audit logging facility to discover which files are accessed at boot time to make a pre-load list
Add a tuning option to audit_backlog_wait_time so that if auditd can't keep up, or gets blocked, the callers won't be blocked.
kernel/audit.c +4 -1
index 3d17670..fc535b6 100644
@@ -701,8 +708,21 @@ static int audit_receive_msg(struct sk_buff *skb, struct nlmsghdr *nlh)
 			if (err < 0)
 				return err;
 		}
-		if (s.mask & AUDIT_STATUS_BACKLOG_LIMIT)
+		if (s.mask & AUDIT_STATUS_BACKLOG_LIMIT) {
 			err = audit_set_backlog_limit(s.backlog_limit);
+			if (err < 0)
+				return err;
+		}
Quoted 8 lines
kernel/audit.c static int audit_receive_msg(struct sk_buff *skb, struct nlmsghdr *nlh) · line 718
Quoted 3 lines
kernel/audit.c +3 -0
+		if (s.mask & AUDIT_STATUS_BACKLOG_WAIT_TIME) {
+			if (sizeof(s) > (size_t)nlh->nlmsg_len)
+				break;
What gets returned here? I think err has a value of 0, but it doesn't seem to have been clearly intentional. If they know about the AUDIT_STATUS_BACKLOG_WAIT_TIME flag, but they didn't send a long enough skb? That seems like an error condition....
The intent was that it is a NOP, since err would have a value of zero, but I see your point, that if that flag is present, the struct member should be too. My original intent was that if the structure member wasn't present, it would default to zero, unintentionally setting the wait time to zero. It was part of my paranoia in the absence of an API version indicator. No harm done, but I agree it should return an error.
Thanks for the catch.

Quoted 8 lines

Quoted 3 lines
kernel/audit.c static int audit_receive_msg(struct sk_buff *skb, struct nlmsghdr *nlh) · line 721
Quoted 3 lines
kernel/audit.c +3 -0
+			if (s.backlog_wait_time < 0 ||
+			    s.backlog_wait_time > 10*AUDIT_BACKLOG_WAIT_TIME)
+				return -EINVAL;
I assume values less than zero or larger than 10 times the current default of one minute are errors or unreasonable.
Any argument for more than 10 minutes?

10 Minutes already seems nuts. If someone has a reason to go higher, we can change this sanity check then.

-Eric