/var/log/messages: backlog limit exceeded

[David Woodhouse]

On Wed, 2005-06-15 at 13:10 -0600, Denise Garrett wrote:
> Content-Type: text/html; charset="US-ASCII"
> <br><font size=2 face="sans-serif">Howdy,</font><br><br><font size=2
> face="sans-serif">I am currently working with the attached test,
> config3_test, that I have pasted into a text file below. Config3
> (assertions 4 and 5) fail on multiple platforms that contain
> audit-0.9.4-1, although they will pass with earlier audits. When it is
> ran the messages file in var/log/messages is filled with the following
> repeating lines during the problem cases. </font>

I think the answer to this problem is to make the auditable processes
_wait_ until they can get a slot in the backlog, whenever that's
possible. Obviously, some callers of audit_log_start() cannot sleep, but
most of the high-bandwidth callers can...

Assuming this approach is satisfactory we may want to look for more
callers which can be converted to audit_log_start_wait(), and perhaps
give a few more slots to the atomic callers, so there's always space for
them.

--- linux-2.6.9/kernel/auditsc.c.orig	2005-06-20 00:21:52.000000000 +0100
+++ linux-2.6.9/kernel/auditsc.c	2005-06-20 01:14:05.000000000 +0100
@@ -728,7 +734,7 @@ static void audit_log_exit(struct audit_
 	struct audit_watch_info *winfo;
 	struct hlist_node *pos;
 
-	ab = audit_log_start(context, AUDIT_SYSCALL);
+	ab = audit_log_start_wait(context, AUDIT_SYSCALL);
 	if (!ab)
 		return;		/* audit_panic has been called */
 	audit_log_format(ab, "arch=%x syscall=%d",
@@ -759,7 +765,7 @@ static void audit_log_exit(struct audit_
 	audit_log_end(ab);
 	for (aux = context->aux; aux; aux = aux->next) {
 
-		ab = audit_log_start(context, aux->type);
+		ab = audit_log_start_wait(context, aux->type);
 		if (!ab)
 			continue; /* audit_panic has been called */
 
@@ -801,7 +807,7 @@ static void audit_log_exit(struct audit_
 					 MAJOR(axi->dev), MINOR(axi->dev),
 					 MAJOR(axi->rdev), MINOR(axi->rdev));
 			hlist_for_each_entry(winfo, pos, &axi->watches, node) {
-				sub_ab = audit_log_start(context, AUDIT_FS_WATCH);
+				sub_ab = audit_log_start_wait(context, AUDIT_FS_WATCH);
 				if (!sub_ab)
 					return;		/* audit_panic has been called */
 				audit_log_format(sub_ab, "watch_inode=%lu", axi->ino);
@@ -819,14 +825,14 @@ static void audit_log_exit(struct audit_
 	}
 
 	if (context->pwd && context->pwdmnt) {
-		ab = audit_log_start(context, AUDIT_CWD);
+		ab = audit_log_start_wait(context, AUDIT_CWD);
 		if (ab) {
 			audit_log_d_path(ab, "cwd=", context->pwd, context->pwdmnt);
 			audit_log_end(ab);
 		}
 	}
 	for (i = 0; i < context->name_count; i++) {
-		ab = audit_log_start(context, AUDIT_PATH);
+		ab = audit_log_start_wait(context, AUDIT_PATH);
 		if (!ab)
 			continue; /* audit_panic has been called */
 
--- linux-2.6.9/kernel/audit.c.orig	2005-06-20 00:21:52.000000000 +0100
+++ linux-2.6.9/kernel/audit.c	2005-06-20 01:14:41.000000000 +0100
@@ -106,6 +106,7 @@ static LIST_HEAD(audit_freelist);
 static struct sk_buff_head audit_skb_queue;
 static struct task_struct *kauditd_task;
 static DECLARE_WAIT_QUEUE_HEAD(kauditd_wait);
+static DECLARE_WAIT_QUEUE_HEAD(audit_backlog_wait);
 
 /* The netlink socket is only to be read by 1 CPU, which lets us assume
  * that list additions and deletions, and watch insertions never happen
@@ -280,6 +281,7 @@ int kauditd_thread(void *dummy)
 
 	while (1) {
 		skb = skb_dequeue(&audit_skb_queue);
+		wake_up(&audit_backlog_wait);
 		if (skb) {
 			if (audit_pid) {
 				int err = netlink_unicast(audit_sock, skb, audit_pid, 0);
@@ -694,7 +696,8 @@ static inline void audit_get_stamp(struc
  * syscall, then the syscall is marked as auditable and an audit record
  * will be written at syscall exit.  If there is no associated task, tsk
  * should be NULL. */
-struct audit_buffer *audit_log_start(struct audit_context *ctx, int type)
+
+struct audit_buffer *__audit_log_start(struct audit_context *ctx, int type, int wait)
 {
 	struct audit_buffer	*ab	= NULL;
 	struct timespec		t;
@@ -703,8 +706,24 @@ struct audit_buffer *audit_log_start(str
 	if (!audit_initialized)
 		return NULL;
 
-	if (audit_backlog_limit
+	while (audit_backlog_limit
 	    && skb_queue_len(&audit_skb_queue) > audit_backlog_limit) {
+		if (wait) {
+			int ret = 1;
+			/* Wait for auditd to drain the queue a little */
+			DECLARE_WAITQUEUE(wait, current);
+			set_current_state(TASK_INTERRUPTIBLE);
+			add_wait_queue(&audit_backlog_wait, &wait);
+
+			if (audit_backlog_limit &&
+			    skb_queue_len(&audit_skb_queue) > audit_backlog_limit)
+				ret = schedule_timeout(HZ * 60);
+
+			__set_current_state(TASK_RUNNING);
+			remove_wait_queue(&audit_backlog_wait, &wait);
+			if (ret)
+				continue;
+		}
 		if (audit_rate_check())
 			printk(KERN_WARNING
 			       "audit: audit_backlog=%d > "
@@ -715,7 +734,7 @@ struct audit_buffer *audit_log_start(str
 		return NULL;
 	}
 
-	ab = audit_buffer_alloc(ctx, GFP_ATOMIC, type);
+	ab = audit_buffer_alloc(ctx, wait?GFP_KERNEL:GFP_ATOMIC, type);
 	if (!ab) {
 		audit_log_lost("out of memory in audit_log_start");
 		return NULL;
@@ -728,6 +747,16 @@ struct audit_buffer *audit_log_start(str
 	return ab;
 }
 
+struct audit_buffer *audit_log_start(struct audit_context *ctx, int type)
+{
+	return __audit_log_start(ctx, type, 0);
+}
+
+struct audit_buffer *audit_log_start_wait(struct audit_context *ctx, int type)
+{
+	return __audit_log_start(ctx, type, 1);
+}
+
 /**
  * audit_expand - expand skb in the audit buffer
  * @ab: audit_buffer
--- linux-2.6.9/include/linux/audit.h.orig	2005-06-20 01:15:24.000000000 +0100
+++ linux-2.6.9/include/linux/audit.h	2005-06-20 01:15:45.000000000 +0100
@@ -337,6 +337,7 @@ extern void		    audit_log(struct audit_
 			    __attribute__((format(printf,3,4)));
 
 extern struct audit_buffer *audit_log_start(struct audit_context *ctx,int type);
+extern struct audit_buffer *audit_log_start_wait(struct audit_context *ctx,int type);
 extern void		    audit_log_format(struct audit_buffer *ab,
 					     const char *fmt, ...)
 			    __attribute__((format(printf,2,3)));

-- 
dwmw2