audit_debug: diagnostics for audit internal workings

PATCH In review Richard Guy Briggs 2 participants 18 messages Oct 22, 2015

Subsystems (2)

Networking Audit

lore

Share & tools

lore

Richard Guy Briggs

author

2015-10-22 18:58 UTC #0 lore raw

cover audit_debug: diagnostics for audit internal workings

A number of diagnostic patches including a /proc/audit* interface to get a better view of what is happenning with what frequency in the audit queue code.

Richard Guy Briggs (13):
audit_debug: set reserve to same size as backlog
audit_debug: squawk when digging into reserve
audit_debug: proc instrumentation
audit_debug: add /proc counters for overflows, waiters, recovers,
reserves
audit_debug: proc debug output easier to paste
audit_debug: don't let systemd change config
audit_debug: instrument audit_cmd_mutex contention
audit_debug: seperate out audit_titles in proc display
netlink_debug: instrument timing of calls by init/systemd or
audit_pid
audit_debug: bark on impossible reserve process conditions in while
loop
audit_debug: instrument audit_receive timing
audit_debug: list processes and frequencies waiting for auditd
audit_debug: print inode nr for each path when listing exe rules

 include/linux/skbuff.h   |   16 ++++
 kernel/audit.c           |  219 ++++++++++++++++++++++++++++++++++++++++++++--
 kernel/audit.h           |    2 +
 kernel/audit_fsnotify.c  |    5 +
 kernel/auditfilter.c     |    1 +
 net/netlink/af_netlink.c |   16 ++++
 6 files changed, 250 insertions(+), 9 deletions(-)

Richard Guy Briggs

author

2015-10-22 18:58 UTC #1 lore raw

PATCH 1/13 audit_debug: set reserve to same size as backlog

Debug the unlikely possibility that the audit_backlog_limit reserve is being overflowed too. Make the reserve proportional to the backlog limit.

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

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

kernel/audit.c +2 -2

index 369cfcc..795d604 100644
@@ -1371,8 +1371,8 @@ struct audit_buffer *audit_log_start(struct audit_context *ctx, gfp_t gfp_mask,
 	struct audit_buffer	*ab	= NULL;
 	struct timespec		t;
 	unsigned int		uninitialized_var(serial);
-	int reserve = 5; /* Allow atomic callers to go up to five
-			    entries over the normal backlog limit */
+	/* reserve: Allow atomic callers to go over the normal backlog limit */
+	int reserve = audit_backlog_limit/16;
 	unsigned long timeout_start = jiffies;
 
 	if (audit_initialized != AUDIT_INITIALIZED)

Signature · 1 line

1.7.1

Richard Guy Briggs

author

2015-10-22 18:58 UTC #2 lore raw

PATCH 2/13 audit_debug: squawk when digging into reserve

In reply to Richard Guy Briggs

Debug when audit_backlog_limit reserves are used for bypassing the queue limits by listing timing, process and queue length.

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

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

kernel/audit.c +8 -0

index 795d604..d4e19fc 100644
@@ -1391,6 +1391,14 @@ struct audit_buffer *audit_log_start(struct audit_context *ctx, gfp_t gfp_mask,
 			reserve = 0;
 		rcu_read_unlock();
 	}
+
+	if (reserve) {
+		pr_warn("( %lu %lu )"
+			" Qreq apid=%d pid=%d comm=%s type=%d reserve=%d Qlen=%d\n",
+			timeout_start, jiffies-timeout_start,
+			audit_pid, current->pid, current->comm, type, reserve, skb_queue_len(&audit_skb_queue));
+	}
+
 	while (audit_backlog_limit
 	       && skb_queue_len(&audit_skb_queue) > audit_backlog_limit + reserve) {
 		if (gfp_mask & __GFP_WAIT && audit_backlog_wait_time) {

Signature · 1 line

1.7.1

Richard Guy Briggs

author

2015-10-22 18:58 UTC #3 lore raw

PATCH 3/13 audit_debug: proc instrumentation

In reply to Richard Guy Briggs

Add a /proc/audit entry for debugging to instrument many audit subsystem internal parameters not normally visible.

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

---
 include/linux/skbuff.h |   16 ++++++++++++++++
 kernel/audit.c         |   48 ++++++++++++++++++++++++++++++++++++++++++++++++
 2 files changed, 64 insertions(+), 0 deletions(-)

include/linux/skbuff.h +16 -0

index f54d665..bcde922 100644
@@ -180,6 +180,7 @@ struct sk_buff_head {
 
 	__u32		qlen;
 	spinlock_t	lock;
+	__u32		qlen_max;
 };
 
 struct sk_buff;

@@ -1301,6 +1302,11 @@ static inline __u32 skb_queue_len(const struct sk_buff_head *list_)
 	return list_->qlen;
 }
 
+static inline __u32 skb_queue_len_max(const struct sk_buff_head *list_)
+{
+	return list_->qlen_max;
+}
+
 /**
  *	__skb_queue_head_init - initialize non-spinlock portions of sk_buff_head
  *	@list: queue to initialize

@@ -1354,6 +1360,8 @@ static inline void __skb_insert(struct sk_buff *newsk,
 	newsk->prev = prev;
 	next->prev  = prev->next = newsk;
 	list->qlen++;
+	if(list->qlen > list->qlen_max)
+		list->qlen_max = list->qlen;
 }
 
 static inline void __skb_queue_splice(const struct sk_buff_head *list,

@@ -1381,6 +1389,8 @@ static inline void skb_queue_splice(const struct sk_buff_head *list,
 	if (!skb_queue_empty(list)) {
 		__skb_queue_splice(list, (struct sk_buff *) head, head->next);
 		head->qlen += list->qlen;
+		if(head->qlen > head->qlen_max)
+			head->qlen_max = head->qlen;
 	}
 }

@@ -1397,6 +1407,8 @@ static inline void skb_queue_splice_init(struct sk_buff_head *list,
 	if (!skb_queue_empty(list)) {
 		__skb_queue_splice(list, (struct sk_buff *) head, head->next);
 		head->qlen += list->qlen;
+		if(head->qlen > head->qlen_max)
+			head->qlen_max = head->qlen;
 		__skb_queue_head_init(list);
 	}
 }

@@ -1412,6 +1424,8 @@ static inline void skb_queue_splice_tail(const struct sk_buff_head *list,
 	if (!skb_queue_empty(list)) {
 		__skb_queue_splice(list, head->prev, (struct sk_buff *) head);
 		head->qlen += list->qlen;
+		if(head->qlen > head->qlen_max)
+			head->qlen_max = head->qlen;
 	}
 }

@@ -1429,6 +1443,8 @@ static inline void skb_queue_splice_tail_init(struct sk_buff_head *list,
 	if (!skb_queue_empty(list)) {
 		__skb_queue_splice(list, head->prev, (struct sk_buff *) head);
 		head->qlen += list->qlen;
+		if(head->qlen > head->qlen_max)
+			head->qlen_max = head->qlen;
 		__skb_queue_head_init(list);
 	}
 }

kernel/audit.c +48 -0

80 lines not on this page · raw message

Signature · 1 line

1.7.1

Steve Grubb

2015-10-22 19:23 UTC #4 lore raw

Re: [ARCHIVE DEBUG 03/13] audit_debug: proc instrumentation

What is the permissions on this? Who can view it?

-Steve

Quoted 169 lines · Richard Guy Briggs

Add a /proc/audit entry for debugging to instrument many audit subsystem internal parameters not normally visible.

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

---
 include/linux/skbuff.h |   16 ++++++++++++++++
 kernel/audit.c         |   48

++++++++++++++++++++++++++++++++++++++++++++++++ 2 files changed, 64 insertions(+), 0 deletions(-)

include/linux/skbuff.h +16 -0

index f54d665..bcde922 100644
@@ -180,6 +180,7 @@ struct sk_buff_head {
 
 	__u32		qlen;
 	spinlock_t	lock;
+	__u32		qlen_max;
 };
 
 struct sk_buff;

@@ -1301,6 +1302,11 @@ static inline __u32 skb_queue_len(const struct
 sk_buff_head *list_) return list_->qlen;
 }
 
+static inline __u32 skb_queue_len_max(const struct sk_buff_head *list_)
+{
+	return list_->qlen_max;
+}
+
 /**
  *	__skb_queue_head_init - initialize non-spinlock portions of sk_buff_head
 *	@list: queue to initialize

@@ -1354,6 +1360,8 @@ static inline void __skb_insert(struct sk_buff *newsk,
 newsk->prev = prev;
 	next->prev  = prev->next = newsk;
 	list->qlen++;
+	if(list->qlen > list->qlen_max)
+		list->qlen_max = list->qlen;
 }
 
 static inline void __skb_queue_splice(const struct sk_buff_head *list,

@@ -1381,6 +1389,8 @@ static inline void skb_queue_splice(const struct
 sk_buff_head *list, if (!skb_queue_empty(list)) {
 		__skb_queue_splice(list, (struct sk_buff *) head, head->next);
 		head->qlen += list->qlen;
+		if(head->qlen > head->qlen_max)
+			head->qlen_max = head->qlen;
 	}
 }

@@ -1397,6 +1407,8 @@ static inline void skb_queue_splice_init(struct
 sk_buff_head *list, if (!skb_queue_empty(list)) {
 		__skb_queue_splice(list, (struct sk_buff *) head, head->next);
 		head->qlen += list->qlen;
+		if(head->qlen > head->qlen_max)
+			head->qlen_max = head->qlen;
 		__skb_queue_head_init(list);
 	}
 }

@@ -1412,6 +1424,8 @@ static inline void skb_queue_splice_tail(const struct
 sk_buff_head *list, if (!skb_queue_empty(list)) {
 		__skb_queue_splice(list, head->prev, (struct sk_buff *) head);
 		head->qlen += list->qlen;
+		if(head->qlen > head->qlen_max)
+			head->qlen_max = head->qlen;
 	}
 }

@@ -1429,6 +1443,8 @@ static inline void skb_queue_splice_tail_init(struct
 sk_buff_head *list, if (!skb_queue_empty(list)) {
 		__skb_queue_splice(list, head->prev, (struct sk_buff *) head);
 		head->qlen += list->qlen;
+		if(head->qlen > head->qlen_max)
+			head->qlen_max = head->qlen;
 		__skb_queue_head_init(list);
 	}
 }

kernel/audit.c +26 -0

index d4e19fc..82df9fd 100644
@@ -124,6 +124,7 @@ u32		audit_sig_sid = 0;
    4) suppressed due to audit_backlog_limit
 */
 static atomic_t    audit_lost = ATOMIC_INIT(0);
+static atomic_t    audit_hold_lost = ATOMIC_INIT(0);
 
 /* The netlink socket. */
 static struct sock *audit_sock;

@@ -381,7 +382,10 @@ static void audit_hold_skb(struct sk_buff *skb)
 	     skb_queue_len(&audit_skb_hold_queue) < audit_backlog_limit))
 		skb_queue_tail(&audit_skb_hold_queue, skb);
 	else
+	{
 		kfree_skb(skb);
+		atomic_inc(&audit_hold_lost);
+	}
 }
 
 /*

@@ -510,7 +514,10 @@ static void flush_hold_queue(void)
 	 * dequeued an skb we need to drop ref
 	 */
 	if (skb)
+	{
 		consume_skb(skb);
+		atomic_inc(&audit_hold_lost);
+	}
 }
 
 static int kauditd_thread(void *dummy)

@@ -1174,6 +1181,45 @@ static struct pernet_operations audit_net_ops
 __net_initdata = { .size = sizeof(struct audit_net),
 };
 
+/* Display information about audit subsystem */
+static int proc_auditstats_show(struct seq_file *m, void *v)
+{
+	//seq_printf(m, "audit_initialized\t%d\n", audit_initialized);
+	//seq_printf(m, "audit_enabled\t%u\n", audit_enabled);
+	//seq_printf(m, "audit_ever_enabled\t%u\n", audit_ever_enabled);
+	//seq_printf(m, "audit_default\t%u\n", audit_default);
+	//seq_printf(m, "audit_failure\t%u\n", audit_failure);
+	seq_printf(m, "audit_pid\t\t\t%d\n", audit_pid);
+	//seq_printf(m, "audit_nlk_portid\t%u\n", audit_nlk_portid);
+	//seq_printf(m, "audit_rate_limit\t%u\n", audit_rate_limit);
+	//seq_printf(m, "audit_backlog_limit\t%u\n", audit_backlog_limit);
+	//seq_printf(m, "audit_backlog_wait_time\t%u\n", audit_backlog_wait_time);
+	//seq_printf(m, "audit_sig_uid\t%u\n", from_kuid(&init_user_ns,
 audit_sig_uid)); +	//seq_printf(m, "audit_sig_pid\t%d\n", audit_sig_pid);
+	//seq_printf(m, "audit_sig_sid\t%u\n", audit_sig_sid);
+	seq_printf(m, "audit_lost\t\t\t%d\n", atomic_read(&audit_lost));
+	seq_printf(m, "audit_hold_lost\t\t\t%d\n", atomic_read(&audit_hold_lost));
+	seq_printf(m, "audit_freelist_count\t\t%u\n", audit_freelist_count);
+	seq_printf(m, "audit_skb_queue len\t\t%d\n",

skb_queue_len(&audit_skb_queue)); + seq_printf(m, "audit_skb_queue
len_max\t\t%d\n", skb_queue_len_max(&audit_skb_queue)); + seq_printf(m,
"audit_skb_hold_queue len\t%d\n", skb_queue_len(&audit_skb_hold_queue));

kernel/audit.c +1 -0

+	seq_printf(m, "audit_skb_hold_queue len_max\t%d\n",

skb_queue_len_max(&audit_skb_hold_queue)); +

kernel/audit.c +17 -0

+	return 0;
+}
+
+static int auditstats_open(struct inode *inode, struct file *file)
+{
+	return single_open(file, proc_auditstats_show, NULL);
+}
+
+static const struct file_operations proc_auditstats_operations = {
+	.open = auditstats_open,
+	.read = seq_read,
+	.llseek = seq_lseek,
+	.release = single_release,
+};
+
 /* Initialize audit support at boot time. */
 static int __init audit_init(void)
 {

@@ -1197,6 +1243,8 @@ static int __init audit_init(void)
 	for (i = 0; i < AUDIT_INODE_BUCKETS; i++)
 		INIT_LIST_HEAD(&audit_inode_hash[i]);
 
+	proc_create("audit", 0, NULL, &proc_auditstats_operations);
+
 	return 0;
 }
 __initcall(audit_init);

Richard Guy Briggs

author

2015-10-22 19:47 UTC #5 lore raw

Re: [ARCHIVE DEBUG 03/13] audit_debug: proc instrumentation

Quoted 1 line · Steve Grubb

What is the permissions on this? Who can view it?

proc_create() was called with mode 0, so I'm guessing it is 777. Actually, it is 444. That should be changed to 400 (S_IRUSR) for use on a system that matters, but again, this is a debug patch set giving internal read-only stats, not intended for upstream or production use. Nice catch.

Quoted 167 lines

-Steve

Quoted 164 lines · Richard Guy Briggs

Add a /proc/audit entry for debugging to instrument many audit subsystem internal parameters not normally visible.

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

---
 include/linux/skbuff.h |   16 ++++++++++++++++
 kernel/audit.c         |   48

++++++++++++++++++++++++++++++++++++++++++++++++ 2 files changed, 64 insertions(+), 0 deletions(-)

include/linux/skbuff.h +16 -0

index f54d665..bcde922 100644
@@ -180,6 +180,7 @@ struct sk_buff_head {
 
 	__u32		qlen;
 	spinlock_t	lock;
+	__u32		qlen_max;
 };
 
 struct sk_buff;

@@ -1301,6 +1302,11 @@ static inline __u32 skb_queue_len(const struct
 sk_buff_head *list_) return list_->qlen;
 }
 
+static inline __u32 skb_queue_len_max(const struct sk_buff_head *list_)
+{
+	return list_->qlen_max;
+}
+
 /**
  *	__skb_queue_head_init - initialize non-spinlock portions of sk_buff_head
 *	@list: queue to initialize

@@ -1354,6 +1360,8 @@ static inline void __skb_insert(struct sk_buff *newsk,
 newsk->prev = prev;
 	next->prev  = prev->next = newsk;
 	list->qlen++;
+	if(list->qlen > list->qlen_max)
+		list->qlen_max = list->qlen;
 }
 
 static inline void __skb_queue_splice(const struct sk_buff_head *list,

@@ -1381,6 +1389,8 @@ static inline void skb_queue_splice(const struct
 sk_buff_head *list, if (!skb_queue_empty(list)) {
 		__skb_queue_splice(list, (struct sk_buff *) head, head->next);
 		head->qlen += list->qlen;
+		if(head->qlen > head->qlen_max)
+			head->qlen_max = head->qlen;
 	}
 }

@@ -1397,6 +1407,8 @@ static inline void skb_queue_splice_init(struct
 sk_buff_head *list, if (!skb_queue_empty(list)) {
 		__skb_queue_splice(list, (struct sk_buff *) head, head->next);
 		head->qlen += list->qlen;
+		if(head->qlen > head->qlen_max)
+			head->qlen_max = head->qlen;
 		__skb_queue_head_init(list);
 	}
 }

@@ -1412,6 +1424,8 @@ static inline void skb_queue_splice_tail(const struct
 sk_buff_head *list, if (!skb_queue_empty(list)) {
 		__skb_queue_splice(list, head->prev, (struct sk_buff *) head);
 		head->qlen += list->qlen;
+		if(head->qlen > head->qlen_max)
+			head->qlen_max = head->qlen;
 	}
 }

@@ -1429,6 +1443,8 @@ static inline void skb_queue_splice_tail_init(struct
 sk_buff_head *list, if (!skb_queue_empty(list)) {
 		__skb_queue_splice(list, head->prev, (struct sk_buff *) head);
 		head->qlen += list->qlen;
+		if(head->qlen > head->qlen_max)
+			head->qlen_max = head->qlen;
 		__skb_queue_head_init(list);
 	}
 }

kernel/audit.c +26 -0

index d4e19fc..82df9fd 100644
@@ -124,6 +124,7 @@ u32		audit_sig_sid = 0;
    4) suppressed due to audit_backlog_limit
 */
 static atomic_t    audit_lost = ATOMIC_INIT(0);
+static atomic_t    audit_hold_lost = ATOMIC_INIT(0);
 
 /* The netlink socket. */
 static struct sock *audit_sock;

@@ -381,7 +382,10 @@ static void audit_hold_skb(struct sk_buff *skb)
 	     skb_queue_len(&audit_skb_hold_queue) < audit_backlog_limit))
 		skb_queue_tail(&audit_skb_hold_queue, skb);
 	else
+	{
 		kfree_skb(skb);
+		atomic_inc(&audit_hold_lost);
+	}
 }
 
 /*

@@ -510,7 +514,10 @@ static void flush_hold_queue(void)
 	 * dequeued an skb we need to drop ref
 	 */
 	if (skb)
+	{
 		consume_skb(skb);
+		atomic_inc(&audit_hold_lost);
+	}
 }
 
 static int kauditd_thread(void *dummy)

@@ -1174,6 +1181,45 @@ static struct pernet_operations audit_net_ops
 __net_initdata = { .size = sizeof(struct audit_net),
 };
 
+/* Display information about audit subsystem */
+static int proc_auditstats_show(struct seq_file *m, void *v)
+{
+	//seq_printf(m, "audit_initialized\t%d\n", audit_initialized);
+	//seq_printf(m, "audit_enabled\t%u\n", audit_enabled);
+	//seq_printf(m, "audit_ever_enabled\t%u\n", audit_ever_enabled);
+	//seq_printf(m, "audit_default\t%u\n", audit_default);
+	//seq_printf(m, "audit_failure\t%u\n", audit_failure);
+	seq_printf(m, "audit_pid\t\t\t%d\n", audit_pid);
+	//seq_printf(m, "audit_nlk_portid\t%u\n", audit_nlk_portid);
+	//seq_printf(m, "audit_rate_limit\t%u\n", audit_rate_limit);
+	//seq_printf(m, "audit_backlog_limit\t%u\n", audit_backlog_limit);
+	//seq_printf(m, "audit_backlog_wait_time\t%u\n", audit_backlog_wait_time);
+	//seq_printf(m, "audit_sig_uid\t%u\n", from_kuid(&init_user_ns,
 audit_sig_uid)); +	//seq_printf(m, "audit_sig_pid\t%d\n", audit_sig_pid);
+	//seq_printf(m, "audit_sig_sid\t%u\n", audit_sig_sid);
+	seq_printf(m, "audit_lost\t\t\t%d\n", atomic_read(&audit_lost));
+	seq_printf(m, "audit_hold_lost\t\t\t%d\n", atomic_read(&audit_hold_lost));
+	seq_printf(m, "audit_freelist_count\t\t%u\n", audit_freelist_count);
+	seq_printf(m, "audit_skb_queue len\t\t%d\n",

kernel/audit.c +1 -0

+	seq_printf(m, "audit_skb_hold_queue len_max\t%d\n",

skb_queue_len_max(&audit_skb_hold_queue)); +

kernel/audit.c +15 -0

+	return 0;
+}
+
+static int auditstats_open(struct inode *inode, struct file *file)
+{
+	return single_open(file, proc_auditstats_show, NULL);
+}
+
+static const struct file_operations proc_auditstats_operations = {
+	.open = auditstats_open,
+	.read = seq_read,
+	.llseek = seq_lseek,
+	.release = single_release,
+};
+
 /* Initialize audit support at boot time. */
 static int __init audit_init(void)
 {

@@ -1197,6 +1243,8 @@ static int __init audit_init(void)
 	for (i = 0; i < AUDIT_INODE_BUCKETS; i++)
 		INIT_LIST_HEAD(&audit_inode_hash[i]);

Quoted 10 lines

kernel/audit.c static int __init audit_init(void) · line 1250
Quoted 5 lines
kernel/audit.c +2 -0
+	proc_create("audit", 0, NULL, &proc_auditstats_operations);
+
 	return 0;
 }
 __initcall(audit_init);
--
Linux-audit mailing list
[email protected]
https://www.redhat.com/mailman/listinfo/linux-audit

- RGB

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

Richard Guy Briggs

author

2015-10-22 18:58 UTC #6 lore raw

PATCH 4/13 audit_debug: add /proc counters for overflows, waiters, recovers, reserves

In reply to Richard Guy Briggs

Add counters to /proc/audit to instrument the wait_for_auditd condition.

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

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

kernel/audit.c +24 -0

index 82df9fd..ffdec0c 100644
@@ -125,6 +125,10 @@ u32		audit_sig_sid = 0;
 */
 static atomic_t    audit_lost = ATOMIC_INIT(0);
 static atomic_t    audit_hold_lost = ATOMIC_INIT(0);
+static atomic_t	audit_overflows	= ATOMIC_INIT(0);
+static atomic_t	audit_waiters	= ATOMIC_INIT(0);
+static atomic_t	audit_recovers	= ATOMIC_INIT(0);
+static atomic_t	audit_reserves	= ATOMIC_INIT(0);
 
 /* The netlink socket. */
 static struct sock *audit_sock;

@@ -1204,6 +1208,10 @@ static int proc_auditstats_show(struct seq_file *m, void *v)
 	seq_printf(m, "audit_skb_queue len_max\t\t%d\n", skb_queue_len_max(&audit_skb_queue));
 	seq_printf(m, "audit_skb_hold_queue len\t%d\n", skb_queue_len(&audit_skb_hold_queue));
 	seq_printf(m, "audit_skb_hold_queue len_max\t%d\n", skb_queue_len_max(&audit_skb_hold_queue));
+	seq_printf(m, "audit_overflows\t\t\t%d\n", atomic_read(&audit_overflows));
+	seq_printf(m, "audit_waiters\t\t\t%d\n", atomic_read(&audit_waiters));
+	seq_printf(m, "audit_recovers\t\t\t%d\n", atomic_read(&audit_recovers));
+	seq_printf(m, "audit_reserves\t\t\t%d\n", atomic_read(&audit_reserves));
 
 	return 0;
 }

@@ -1422,6 +1430,8 @@ struct audit_buffer *audit_log_start(struct audit_context *ctx, gfp_t gfp_mask,
 	/* reserve: Allow atomic callers to go over the normal backlog limit */
 	int reserve = audit_backlog_limit/16;
 	unsigned long timeout_start = jiffies;
+	int waiter = 0;
+	int overflow_counted = 0;
 
 	if (audit_initialized != AUDIT_INITIALIZED)
 		return NULL;

@@ -1434,7 +1444,10 @@ struct audit_buffer *audit_log_start(struct audit_context *ctx, gfp_t gfp_mask,
 		if (ACCESS_ONCE(audit_cmd_mutex.owner) == current ||
 		    current->tgid == 1 ||
 		    (audit_pid && audit_pid == current->tgid))
+		{
 			gfp_mask &= ~__GFP_WAIT;
+			atomic_inc(&audit_reserves);
+		}
 		else
 			reserve = 0;
 		rcu_read_unlock();

@@ -1449,14 +1462,25 @@ 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 (!overflow_counted) {
+			atomic_inc(&audit_overflows);
+			overflow_counted = 1;
+		}
 		if (gfp_mask & __GFP_WAIT && audit_backlog_wait_time) {
 			long sleep_time;
 
+			if (!waiter) {
+				atomic_inc(&audit_waiters);
+				waiter = 1;
+			}
 			sleep_time = timeout_start + audit_backlog_wait_time - jiffies;
 			if (sleep_time > 0) {
 				sleep_time = wait_for_auditd(sleep_time);
 				if (audit_pid && sleep_time > 0)
+				{
+					atomic_inc(&audit_recovers);
 					continue;
+				}
 			}
 		}
 		if (audit_rate_check() && printk_ratelimit())

Signature · 1 line

1.7.1

Richard Guy Briggs

author

2015-10-22 18:58 UTC #7 lore raw

PATCH 5/13 audit_debug: proc debug output easier to paste

In reply to Richard Guy Briggs

Convert /proc/audit debug output from label-value per line to one title line with one output line.

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

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

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

index ffdec0c..30b3b08 100644
@@ -1188,30 +1188,57 @@ static struct pernet_operations audit_net_ops __net_initdata = {
 /* Display information about audit subsystem */
 static int proc_auditstats_show(struct seq_file *m, void *v)
 {
-	//seq_printf(m, "audit_initialized\t%d\n", audit_initialized);
-	//seq_printf(m, "audit_enabled\t%u\n", audit_enabled);
-	//seq_printf(m, "audit_ever_enabled\t%u\n", audit_ever_enabled);
-	//seq_printf(m, "audit_default\t%u\n", audit_default);
-	//seq_printf(m, "audit_failure\t%u\n", audit_failure);
-	seq_printf(m, "audit_pid\t\t\t%d\n", audit_pid);
-	//seq_printf(m, "audit_nlk_portid\t%u\n", audit_nlk_portid);
-	//seq_printf(m, "audit_rate_limit\t%u\n", audit_rate_limit);
-	//seq_printf(m, "audit_backlog_limit\t%u\n", audit_backlog_limit);
-	//seq_printf(m, "audit_backlog_wait_time\t%u\n", audit_backlog_wait_time);
-	//seq_printf(m, "audit_sig_uid\t%u\n", from_kuid(&init_user_ns, audit_sig_uid));
-	//seq_printf(m, "audit_sig_pid\t%d\n", audit_sig_pid);
-	//seq_printf(m, "audit_sig_sid\t%u\n", audit_sig_sid);
-	seq_printf(m, "audit_lost\t\t\t%d\n", atomic_read(&audit_lost));
-	seq_printf(m, "audit_hold_lost\t\t\t%d\n", atomic_read(&audit_hold_lost));
-	seq_printf(m, "audit_freelist_count\t\t%u\n", audit_freelist_count);
-	seq_printf(m, "audit_skb_queue len\t\t%d\n", skb_queue_len(&audit_skb_queue));
-	seq_printf(m, "audit_skb_queue len_max\t\t%d\n", skb_queue_len_max(&audit_skb_queue));
-	seq_printf(m, "audit_skb_hold_queue len\t%d\n", skb_queue_len(&audit_skb_hold_queue));
-	seq_printf(m, "audit_skb_hold_queue len_max\t%d\n", skb_queue_len_max(&audit_skb_hold_queue));
-	seq_printf(m, "audit_overflows\t\t\t%d\n", atomic_read(&audit_overflows));
-	seq_printf(m, "audit_waiters\t\t\t%d\n", atomic_read(&audit_waiters));
-	seq_printf(m, "audit_recovers\t\t\t%d\n", atomic_read(&audit_recovers));
-	seq_printf(m, "audit_reserves\t\t\t%d\n", atomic_read(&audit_reserves));
+	//seq_printf(m, "init\t");
+	//seq_printf(m, "en\t");
+	//seq_printf(m, "ever_en\t");
+	//seq_printf(m, "def\t");
+	//seq_printf(m, "failure\t");
+	seq_printf(m, "pid\t");
+	//seq_printf(m, "portid\t");
+	//seq_printf(m, "rt_lim\t");
+	//seq_printf(m, "bk_lim\t");
+	//seq_printf(m, "bk_wait\t");
+	//seq_printf(m, "sig_uid\t");
+	//seq_printf(m, "sig_pid\t");
+	//seq_printf(m, "sig_sid\t");
+	seq_printf(m, "lost\t");
+	seq_printf(m, "hlost\t");
+	seq_printf(m, "freelis\t");
+	seq_printf(m, "Qln\t");
+	seq_printf(m, "Qln_mx\t");
+	seq_printf(m, "hQln\t");
+	seq_printf(m, "hQln_mx\t");
+	seq_printf(m, "oflow\t");
+	seq_printf(m, "waiter\t");
+	seq_printf(m, "recover\t");
+	seq_printf(m, "reserve\t");
+	seq_printf(m, "\n");
+
+	//seq_printf(m, "%d\t", audit_initialized);
+	//seq_printf(m, "%u\t", audit_enabled);
+	//seq_printf(m, "%u\t", audit_ever_enabled);
+	//seq_printf(m, "%u\t", audit_default);
+	//seq_printf(m, "%u\t", audit_failure);
+	seq_printf(m, "%d\t", audit_pid);
+	//seq_printf(m, "%u\t", audit_nlk_portid);
+	//seq_printf(m, "%u\t", audit_rate_limit);
+	//seq_printf(m, "%u\t", audit_backlog_limit);
+	//seq_printf(m, "%u\t", audit_backlog_wait_time);
+	//seq_printf(m, "%u\t", from_kuid(&init_user_ns, audit_sig_uid));
+	//seq_printf(m, "%d\t", audit_sig_pid);
+	//seq_printf(m, "%u\t", audit_sig_sid);
+	seq_printf(m, "%d\t", atomic_read(&audit_lost));
+	seq_printf(m, "%d\t", atomic_read(&audit_hold_lost));
+	seq_printf(m, "%u\t", audit_freelist_count);
+	seq_printf(m, "%d\t", skb_queue_len(&audit_skb_queue));
+	seq_printf(m, "%d\t", skb_queue_len_max(&audit_skb_queue));
+	seq_printf(m, "%d\t", skb_queue_len(&audit_skb_hold_queue));
+	seq_printf(m, "%d\t", skb_queue_len_max(&audit_skb_hold_queue));
+	seq_printf(m, "%d\t", atomic_read(&audit_overflows));
+	seq_printf(m, "%d\t", atomic_read(&audit_waiters));
+	seq_printf(m, "%d\t", atomic_read(&audit_recovers));
+	seq_printf(m, "%d\t", atomic_read(&audit_reserves));
+	seq_printf(m, "\n");
 
 	return 0;
 }

Signature · 1 line

1.7.1

Richard Guy Briggs

author

2015-10-22 18:58 UTC #8 lore raw

PATCH 6/13 audit_debug: don't let systemd change config

In reply to Richard Guy Briggs

Debug the possibility of systemd changing the audit config causing shutdown delays by blocking all such requests.

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

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

kernel/audit.c +8 -6

index 30b3b08..93a466b 100644
@@ -680,18 +680,20 @@ static int audit_netlink_ok(struct sk_buff *skb, u16 msg_type)
 	case AUDIT_ADD:
 	case AUDIT_DEL:
 		return -EOPNOTSUPP;
-	case AUDIT_GET:
 	case AUDIT_SET:
-	case AUDIT_GET_FEATURE:
 	case AUDIT_SET_FEATURE:
-	case AUDIT_LIST_RULES:
 	case AUDIT_ADD_RULE:
 	case AUDIT_DEL_RULE:
-	case AUDIT_SIGNAL_INFO:
-	case AUDIT_TTY_GET:
-	case AUDIT_TTY_SET:
 	case AUDIT_TRIM:
 	case AUDIT_MAKE_EQUIV:
+	case AUDIT_TTY_SET:
+		if (current->tgid == 1)
+			return -EPERM;
+	case AUDIT_GET:
+	case AUDIT_GET_FEATURE:
+	case AUDIT_LIST_RULES:
+	case AUDIT_SIGNAL_INFO:
+	case AUDIT_TTY_GET:
 		/* Only support auditd and auditctl in initial pid namespace
 		 * for now. */
 		if ((task_active_pid_ns(current) != &init_pid_ns))

Signature · 1 line

1.7.1

Steve Grubb

2015-10-22 19:18 UTC #9 lore raw

Re: [ARCHIVE DEBUG 06/13] audit_debug: don't let systemd change config

Quoted 2 lines · Richard Guy Briggs

Debug the possibility of systemd changing the audit config causing shutdown delays by blocking all such requests.

I don't understand what you are saying here. As long as something something has CAP_AUDIT_CONTROL, it can make changes. But we have to record what made the changes in the logs.

-Steve

Quoted 36 lines

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

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

kernel/audit.c +0 -0

index 30b3b08..93a466b 100644
@@ -680,18 +680,20 @@ static int audit_netlink_ok(struct sk_buff *skb, u16

msg_type) case AUDIT_ADD:

kernel/audit.c +8 -6

 	case AUDIT_DEL:
 		return -EOPNOTSUPP;
-	case AUDIT_GET:
 	case AUDIT_SET:
-	case AUDIT_GET_FEATURE:
 	case AUDIT_SET_FEATURE:
-	case AUDIT_LIST_RULES:
 	case AUDIT_ADD_RULE:
 	case AUDIT_DEL_RULE:
-	case AUDIT_SIGNAL_INFO:
-	case AUDIT_TTY_GET:
-	case AUDIT_TTY_SET:
 	case AUDIT_TRIM:
 	case AUDIT_MAKE_EQUIV:
+	case AUDIT_TTY_SET:
+		if (current->tgid == 1)
+			return -EPERM;
+	case AUDIT_GET:
+	case AUDIT_GET_FEATURE:
+	case AUDIT_LIST_RULES:
+	case AUDIT_SIGNAL_INFO:
+	case AUDIT_TTY_GET:
 		/* Only support auditd and auditctl in initial pid namespace
 		 * for now. */
 		if ((task_active_pid_ns(current) != &init_pid_ns))

Richard Guy Briggs

author

2015-10-22 19:28 UTC #10 lore raw

Re: [ARCHIVE DEBUG 06/13] audit_debug: don't let systemd change config

Quoted 7 lines · Steve Grubb

Quoted 2 lines · Richard Guy Briggs
Debug the possibility of systemd changing the audit config causing shutdown delays by blocking all such requests.
I don't understand what you are saying here. As long as something something has CAP_AUDIT_CONTROL, it can make changes. But we have to record what made the changes in the logs.

I grouped all the message types that make changes first so that if it was init or systemd attempting such a change, it would be denied with -EPERM. Systemd should only have CAP_AUDIT_READ. If it isn't process 1 (init or systemd) it will just fallthrough this list of message types as it did before. This was done for debug testing only. This isn't intended to be accepted upstream.

Does this help? Perhaps I should have been more explicit that even if systemd somehow was configured with CAP_AUDIT_CONTROL, it would be denied.

Quoted 35 lines

-Steve

Quoted 33 lines

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

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

kernel/audit.c +0 -0

index 30b3b08..93a466b 100644
@@ -680,18 +680,20 @@ static int audit_netlink_ok(struct sk_buff *skb, u16

msg_type) case AUDIT_ADD:

kernel/audit.c +8 -6

 	case AUDIT_DEL:
 		return -EOPNOTSUPP;
-	case AUDIT_GET:
 	case AUDIT_SET:
-	case AUDIT_GET_FEATURE:
 	case AUDIT_SET_FEATURE:
-	case AUDIT_LIST_RULES:
 	case AUDIT_ADD_RULE:
 	case AUDIT_DEL_RULE:
-	case AUDIT_SIGNAL_INFO:
-	case AUDIT_TTY_GET:
-	case AUDIT_TTY_SET:
 	case AUDIT_TRIM:
 	case AUDIT_MAKE_EQUIV:
+	case AUDIT_TTY_SET:
+		if (current->tgid == 1)
+			return -EPERM;
+	case AUDIT_GET:
+	case AUDIT_GET_FEATURE:
+	case AUDIT_LIST_RULES:
+	case AUDIT_SIGNAL_INFO:
+	case AUDIT_TTY_GET:

Quoted 8 lines

kernel/audit.c static int audit_netlink_ok(struct sk_buff *skb, u16 msg_type) · line 699
Quoted 3 lines
kernel/audit.c +0 -0
 		/* Only support auditd and auditctl in initial pid namespace
 		 * for now. */
 		if ((task_active_pid_ns(current) != &init_pid_ns))
--
Linux-audit mailing list
[email protected]
https://www.redhat.com/mailman/listinfo/linux-audit

- RGB

Richard Guy Briggs

author

2015-10-22 18:58 UTC #11 lore raw

PATCH 7/13 audit_debug: instrument audit_cmd_mutex contention

In reply to Richard Guy Briggs

Debug contention for the audit_cmd_mutex including timing, stalling and identies of holder and requestor.

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

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

kernel/audit.c +17 -1

index 93a466b..a586bf2 100644
@@ -1131,7 +1131,23 @@ static void audit_receive_skb(struct sk_buff *skb)
 /* Receive messages from netlink socket. */
 static void audit_receive(struct sk_buff  *skb)
 {
-	mutex_lock(&audit_cmd_mutex);
+	struct task_struct *owner;
+	unsigned long trytime = jiffies;
+	
+	pid_t pid = 0;
+
+	if (!mutex_trylock(&audit_cmd_mutex)) {
+		rcu_read_lock();
+		owner = ACCESS_ONCE(audit_cmd_mutex.owner);
+		if (owner)
+			pid = owner->pid;
+		rcu_read_unlock();
+		pr_warn("( %lu %lu )audit_cmd_mutex apid=%d Qlen=%d %d(%s) trying, already held by %d\n",
+			trytime, jiffies - trytime, audit_pid, skb_queue_len(&audit_skb_queue), current->pid, current->comm, pid);
+		mutex_lock(&audit_cmd_mutex);
+		pr_warn("( %lu %lu )audit_cmd_mutex apid=%d Qlen=%d %d(%s) acquired, released by %d\n",
+			trytime, jiffies - trytime, audit_pid, skb_queue_len(&audit_skb_queue), current->pid, current->comm, pid);
+	}
 	audit_receive_skb(skb);
 	mutex_unlock(&audit_cmd_mutex);
 }

Signature · 1 line

1.7.1

Richard Guy Briggs

author

2015-10-22 18:58 UTC #12 lore raw

PATCH 8/13 audit_debug: seperate out audit_titles in proc display

In reply to Richard Guy Briggs

Format debugging output in /proc/audit to seperate titles and data output to one line each in /proc/audit and /proc/audit_titles.

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

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

kernel/audit.c +18 -2

index a586bf2..d6f4763 100644
@@ -1204,7 +1204,7 @@ static struct pernet_operations audit_net_ops __net_initdata = {
 };
 
 /* Display information about audit subsystem */
-static int proc_auditstats_show(struct seq_file *m, void *v)
+static int proc_auditstatstitles_show(struct seq_file *m, void *v)
 {
 	//seq_printf(m, "init\t");
 	//seq_printf(m, "en\t");

@@ -1231,7 +1231,23 @@ static int proc_auditstats_show(struct seq_file *m, void *v)
 	seq_printf(m, "recover\t");
 	seq_printf(m, "reserve\t");
 	seq_printf(m, "\n");
+	return 0;
+}
+
+static int auditstatstitles_open(struct inode *inode, struct file *file)
+{
+	return single_open(file, proc_auditstatstitles_show, NULL);
+}
+
+static const struct file_operations proc_auditstatstitles_operations = {
+	.open = auditstatstitles_open,
+	.read = seq_read,
+	.llseek = seq_lseek,
+	.release = single_release,
+};
 
+static int proc_auditstats_show(struct seq_file *m, void *v)
+{
 	//seq_printf(m, "%d\t", audit_initialized);
 	//seq_printf(m, "%u\t", audit_enabled);
 	//seq_printf(m, "%u\t", audit_ever_enabled);

@@ -1257,7 +1273,6 @@ static int proc_auditstats_show(struct seq_file *m, void *v)
 	seq_printf(m, "%d\t", atomic_read(&audit_recovers));
 	seq_printf(m, "%d\t", atomic_read(&audit_reserves));
 	seq_printf(m, "\n");
-
 	return 0;
 }

@@ -1296,6 +1311,7 @@ static int __init audit_init(void)
 	for (i = 0; i < AUDIT_INODE_BUCKETS; i++)
 		INIT_LIST_HEAD(&audit_inode_hash[i]);
 
+	proc_create("audit_titles", 0, NULL, &proc_auditstatstitles_operations);
 	proc_create("audit", 0, NULL, &proc_auditstats_operations);
 
 	return 0;

Signature · 1 line

1.7.1

Richard Guy Briggs

author

2015-10-22 18:58 UTC #13 lore raw

PATCH 9/13 netlink_debug: instrument timing of calls by init/systemd or audit_pid

In reply to Richard Guy Briggs

Debug the timing and stalling of calls to netlink_sendmsg() for processes we care about with any error return values.

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

---
 net/netlink/af_netlink.c |   16 ++++++++++++++++
 1 files changed, 16 insertions(+), 0 deletions(-)

net/netlink/af_netlink.c +16 -0

index 05919bf..ba5eedf 100644
@@ -2256,6 +2256,8 @@ static void netlink_cmsg_recv_pktinfo(struct msghdr *msg, struct sk_buff *skb)
 	put_cmsg(msg, SOL_NETLINK, NETLINK_PKTINFO, sizeof(info), &info);
 }
 
+extern int audit_pid;
+
 static int netlink_sendmsg(struct kiocb *kiocb, struct socket *sock,
 			   struct msghdr *msg, size_t len)
 {

@@ -2268,10 +2270,19 @@ static int netlink_sendmsg(struct kiocb *kiocb, struct socket *sock,
 	int err;
 	struct scm_cookie scm;
 	u32 netlink_skb_flags = 0;
+	//unsigned long trytime = 0;
+	unsigned long trytime = jiffies;
+	pid_t audit_pid_cached = audit_pid;
+	int pr;
 
 	if (msg->msg_flags&MSG_OOB)
 		return -EOPNOTSUPP;
 
+	if (current->tgid == 1 || (audit_pid && audit_pid == current->tgid))
+		//pr_warn("( %lu )netlink_sendmsg apid=%d pid=%d(%s)\n",
+			//trytime = jiffies, audit_pid, current->pid, current->comm);
+		pr = 1;
+
 	err = scm_send(sock, msg, &scm, true);
 	if (err < 0)
 		return err;

@@ -2343,6 +2354,11 @@ static int netlink_sendmsg(struct kiocb *kiocb, struct socket *sock,
 
 out:
 	scm_destroy(&scm);
+
+	if (pr || current->tgid == 1 || (audit_pid && audit_pid == current->tgid))
+		pr_warn("( %lu %lu )netlink_sendmsg-exit apid=%d apid-old=%d pid=%d(%s) err=%d\n",
+			trytime, jiffies - trytime, audit_pid, audit_pid_cached, current->pid, current->comm, err);
+
 	return err;
 }

Signature · 1 line

1.7.1

Richard Guy Briggs

author

2015-10-22 18:58 UTC #14 lore raw

PATCH 10/13 audit_debug: bark on impossible reserve process conditions in while loop

In reply to Richard Guy Briggs

Debug the expected impossibility of the audit_backlog_queue reserve being used up.

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

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

kernel/audit.c +12 -0

index d6f4763..9e9c02b 100644
@@ -1527,6 +1527,12 @@ struct audit_buffer *audit_log_start(struct audit_context *ctx, gfp_t gfp_mask,
 			atomic_inc(&audit_overflows);
 			overflow_counted = 1;
 		}
+		if (reserve) {
+			pr_warn("( %lu %lu )"
+				"  Qstuck apid=%d pid=%d comm=%s type=%d reserve=%d Qlen=%d\n",
+				timeout_start, jiffies-timeout_start,
+				audit_pid, current->pid, current->comm, type, reserve, skb_queue_len(&audit_skb_queue));
+		}
 		if (gfp_mask & __GFP_WAIT && audit_backlog_wait_time) {
 			long sleep_time;

@@ -1534,6 +1540,12 @@ struct audit_buffer *audit_log_start(struct audit_context *ctx, gfp_t gfp_mask,
 				atomic_inc(&audit_waiters);
 				waiter = 1;
 			}
+			if (reserve) {
+				pr_warn("( %lu %lu )"
+					"   Qreallystuck apid=%d pid=%d comm=%s type=%d reserve=%d Qlen=%d\n",
+					timeout_start, jiffies-timeout_start,
+					audit_pid, current->pid, current->comm, type, reserve, skb_queue_len(&audit_skb_queue));
+			}
 			sleep_time = timeout_start + audit_backlog_wait_time - jiffies;
 			if (sleep_time > 0) {
 				sleep_time = wait_for_auditd(sleep_time);

Signature · 1 line

1.7.1

Richard Guy Briggs

author

2015-10-22 18:58 UTC #15 lore raw

PATCH 11/13 audit_debug: instrument audit_receive timing

In reply to Richard Guy Briggs

Debug the timing and stalling of calls to audit_receive() for processes we care about.

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

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

kernel/audit.c +16 -0

index 9e9c02b..76b6878 100644
@@ -1136,6 +1136,18 @@ static void audit_receive(struct sk_buff  *skb)
 	
 	pid_t pid = 0;
 
+	int pr = 0;
+	//pid_t audit_pid_cached;
+	pid_t audit_pid_cached = audit_pid;
+
+	if (current->tgid == 1 || (audit_pid && audit_pid == current->tgid)) {
+		//pr_warn("( %lu )audit_receive apid=%d pid=%d(%s) Qlen=%d\n",
+			//jiffies, audit_pid, current->pid, current->comm, skb_queue_len(&audit_skb_queue));
+		pr = 1;
+	//} else {
+		//audit_pid_cached = audit_pid;
+	}
+
 	if (!mutex_trylock(&audit_cmd_mutex)) {
 		rcu_read_lock();
 		owner = ACCESS_ONCE(audit_cmd_mutex.owner);

@@ -1150,6 +1162,10 @@ static void audit_receive(struct sk_buff  *skb)
 	}
 	audit_receive_skb(skb);
 	mutex_unlock(&audit_cmd_mutex);
+
+	if (pr || current->tgid == 1 || (audit_pid && audit_pid == current->tgid))
+		pr_warn("( %lu %lu )audit_receive-exit apid=%d apid-old=%d pid=%d(%s) Qlen=%d\n",
+			trytime, jiffies - trytime, audit_pid, audit_pid_cached, current->pid, current->comm, skb_queue_len(&audit_skb_queue));
 }
 
 /* Run custom bind function on netlink socket group connect or bind requests. */

Signature · 1 line

1.7.1

Richard Guy Briggs

author

2015-10-22 18:58 UTC #16 lore raw

PATCH 12/13 audit_debug: list processes and frequencies waiting for auditd

In reply to Richard Guy Briggs

Debug to list each process, its first call time and how many times it is called while waiting for auditd upon queue overflow. It is reported and cleared when the queue is drained sufficiently to clear the condition.

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

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

kernel/audit.c +32 -0

index 76b6878..e4be6f3 100644
@@ -1498,6 +1498,11 @@ static long wait_for_auditd(long sleep_time)
  * will be written at syscall exit.  If there is no associated task, then
  * task context (ctx) should be NULL.
  */
+#define PIDS_WAITING_MAX 1024
+pid_t pids_waiting[PIDS_WAITING_MAX];
+int pids_waiting_c[PIDS_WAITING_MAX];
+char pids_waiting_comm[PIDS_WAITING_MAX][16];
+unsigned long pids_waiting_j[PIDS_WAITING_MAX];
 struct audit_buffer *audit_log_start(struct audit_context *ctx, gfp_t gfp_mask,
 				     int type)
 {

@@ -1539,6 +1544,19 @@ 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) {
+		int c = 0;
+		while (pids_waiting[c] && pids_waiting[c] != current->pid)
+			c++;
+		if (c < PIDS_WAITING_MAX) {
+			if (!pids_waiting[c]) {
+				pids_waiting[c] = current->pid;
+				memcpy(pids_waiting_comm[c], current->comm, 16);
+				pids_waiting_j[c] = jiffies;
+			}
+			pids_waiting_c[c]++;
+		} else
+			pr_warn("overflowed pids_waiting counter\n");
+		
 		if (!overflow_counted) {
 			atomic_inc(&audit_overflows);
 			overflow_counted = 1;

@@ -1572,6 +1590,20 @@ struct audit_buffer *audit_log_start(struct audit_context *ctx, gfp_t gfp_mask,
 				}
 			}
 		}
+		if (audit_backlog_wait_time) {
+			int c = 0;
+			if (pids_waiting[0]) {
+				pr_warn("pids_waiting:");
+				while (pids_waiting[c]) {
+					printk(" %d\"%s\"(%lu:%d)", pids_waiting[c], pids_waiting_comm[c], pids_waiting_j[c], pids_waiting_c[c]);
+					pids_waiting[c] = pids_waiting_c[c] = 0;
+					if (c++ >= PIDS_WAITING_MAX) {
+						break;
+						printk("\n");
+					}
+				}
+			}
+		}
 		if (audit_rate_check() && printk_ratelimit())
 			pr_warn("audit_backlog=%d > audit_backlog_limit=%d\n",
 				skb_queue_len(&audit_skb_queue),

Signature · 1 line

1.7.1

Richard Guy Briggs

author

2015-10-22 18:58 UTC #17 lore raw

PATCH 13/13 audit_debug: print inode nr for each path when listing exe rules

In reply to Richard Guy Briggs

Debug to list inode number and path for each audit watch when audit watch rules are listed.

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

---
 kernel/audit.h          |    2 ++
 kernel/audit_fsnotify.c |    5 +++++
 kernel/auditfilter.c    |    1 +
 3 files changed, 8 insertions(+), 0 deletions(-)

kernel/audit.h +2 -0

index 24ec861..a7cf1ad 100644
@@ -271,6 +271,7 @@ extern int audit_watch_compare(struct audit_watch *watch, unsigned long ino, dev
 
 extern struct audit_fsnotify_mark *audit_alloc_mark(struct audit_krule *krule, char *pathname, int len);
 extern char *audit_mark_path(struct audit_fsnotify_mark *mark);
+extern unsigned int audit_mark_ino(struct audit_fsnotify_mark *mark);
 extern void audit_remove_mark(struct audit_fsnotify_mark *audit_mark);
 extern void audit_remove_mark_rule(struct audit_krule *krule);
 extern int audit_mark_compare(struct audit_fsnotify_mark *mark, unsigned long ino, dev_t dev);

@@ -287,6 +288,7 @@ extern int audit_exe_compare(struct task_struct *tsk, struct audit_fsnotify_mark
 #define audit_watch_compare(w, i, d) 0
 
 #define audit_alloc_mark(k, p, l) (ERR_PTR(-EINVAL))
+#define audit_mark_ino(m) 0
 #define audit_mark_path(m) ""
 #define audit_remove_mark(m)
 #define audit_remove_mark_rule(k)

kernel/audit_fsnotify.c +5 -0

index 27c6046..dcf788c 100644
@@ -61,6 +61,11 @@ static void audit_fsnotify_free_mark(struct fsnotify_mark *mark)
 	audit_fsnotify_mark_free(audit_mark);
 }
 
+unsigned int audit_mark_ino(struct audit_fsnotify_mark *mark)
+{
+	return mark->ino;
+}
+
 char *audit_mark_path(struct audit_fsnotify_mark *mark)
 {
 	return mark->path;

kernel/auditfilter.c +1 -0

index 7714d93..0c36546 100644
@@ -645,6 +645,7 @@ static struct audit_rule_data *audit_krule_to_data(struct audit_krule *krule)
 		case AUDIT_EXE:
 			data->buflen += data->values[i] =
 				audit_pack_string(&bufp, audit_mark_path(krule->exe));
+			pr_warn("list: \"%s\" ino=%u\n", audit_mark_path(krule->exe), audit_mark_ino(krule->exe));
 			break;
 		case AUDIT_LOGINUID_SET:
 			if (krule->pflags & AUDIT_LOGINUID_LEGACY && !f->val) {

Signature · 1 line

1.7.1