[ARCHIVE DEBUG 00/13] audit_debug: diagnostics for audit internal workings

[ARCHIVE DEBUG 00/13] audit_debug: diagnostics for audit internal workings

[Richard Guy Briggs]

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(-)

[ARCHIVE DEBUG 01/13] audit_debug: set reserve to same size as backlog

[Richard Guy Briggs]

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 <rgb@redhat.com>
---
 kernel/audit.c |    4 ++--
 1 files changed, 2 insertions(+), 2 deletions(-)

diff --git a/kernel/audit.c b/kernel/audit.c
index 369cfcc..795d604 100644
--- a/kernel/audit.c
+++ b/kernel/audit.c
@@ -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)
-- 
1.7.1

[ARCHIVE DEBUG 02/13] audit_debug: squawk when digging into reserve

[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 <rgb@redhat.com>
---
 kernel/audit.c |    8 ++++++++
 1 files changed, 8 insertions(+), 0 deletions(-)

diff --git a/kernel/audit.c b/kernel/audit.c
index 795d604..d4e19fc 100644
--- a/kernel/audit.c
+++ b/kernel/audit.c
@@ -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) {
-- 
1.7.1

[ARCHIVE DEBUG 03/13] audit_debug: proc instrumentation

[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 <rgb@redhat.com>
---
 include/linux/skbuff.h |   16 ++++++++++++++++
 kernel/audit.c         |   48 ++++++++++++++++++++++++++++++++++++++++++++++++
 2 files changed, 64 insertions(+), 0 deletions(-)

diff --git a/include/linux/skbuff.h b/include/linux/skbuff.h
index f54d665..bcde922 100644
--- a/include/linux/skbuff.h
+++ b/include/linux/skbuff.h
@@ -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);
 	}
 }
diff --git a/kernel/audit.c b/kernel/audit.c
index d4e19fc..82df9fd 100644
--- a/kernel/audit.c
+++ b/kernel/audit.c
@@ -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));
+	seq_printf(m, "audit_skb_hold_queue len_max\t%d\n", skb_queue_len_max(&audit_skb_hold_queue));
+
+	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);
-- 
1.7.1

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

[Steve Grubb]

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

-Steve

On Thursday, October 22, 2015 02:58:49 PM Richard Guy Briggs wrote:
> Add a /proc/audit entry for debugging to instrument many audit subsystem
> internal parameters not normally visible.
> 
> Signed-off-by: Richard Guy Briggs <rgb@redhat.com>
> ---
>  include/linux/skbuff.h |   16 ++++++++++++++++
>  kernel/audit.c         |   48
> ++++++++++++++++++++++++++++++++++++++++++++++++ 2 files changed, 64
> insertions(+), 0 deletions(-)
> 
> diff --git a/include/linux/skbuff.h b/include/linux/skbuff.h
> index f54d665..bcde922 100644
> --- a/include/linux/skbuff.h
> +++ b/include/linux/skbuff.h
> @@ -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);
>  	}
>  }
> diff --git a/kernel/audit.c b/kernel/audit.c
> index d4e19fc..82df9fd 100644
> --- a/kernel/audit.c
> +++ b/kernel/audit.c
> @@ -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));
> +	seq_printf(m, "audit_skb_hold_queue len_max\t%d\n",
> skb_queue_len_max(&audit_skb_hold_queue)); +
> +	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);

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

[Richard Guy Briggs]

On 15/10/22, Steve Grubb wrote:
> 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.

> -Steve
> 
> On Thursday, October 22, 2015 02:58:49 PM Richard Guy Briggs wrote:
> > Add a /proc/audit entry for debugging to instrument many audit subsystem
> > internal parameters not normally visible.
> > 
> > Signed-off-by: Richard Guy Briggs <rgb@redhat.com>
> > ---
> >  include/linux/skbuff.h |   16 ++++++++++++++++
> >  kernel/audit.c         |   48
> > ++++++++++++++++++++++++++++++++++++++++++++++++ 2 files changed, 64
> > insertions(+), 0 deletions(-)
> > 
> > diff --git a/include/linux/skbuff.h b/include/linux/skbuff.h
> > index f54d665..bcde922 100644
> > --- a/include/linux/skbuff.h
> > +++ b/include/linux/skbuff.h
> > @@ -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);
> >  	}
> >  }
> > diff --git a/kernel/audit.c b/kernel/audit.c
> > index d4e19fc..82df9fd 100644
> > --- a/kernel/audit.c
> > +++ b/kernel/audit.c
> > @@ -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));
> > +	seq_printf(m, "audit_skb_hold_queue len_max\t%d\n",
> > skb_queue_len_max(&audit_skb_hold_queue)); +
> > +	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);
> 
> --
> Linux-audit mailing list
> Linux-audit@redhat.com
> https://www.redhat.com/mailman/listinfo/linux-audit

- RGB

--
Richard Guy Briggs <rbriggs@redhat.com>
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

[ARCHIVE DEBUG 04/13] audit_debug: add /proc counters for overflows, waiters, recovers, reserves

[Richard Guy Briggs]

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

Signed-off-by: Richard Guy Briggs <rgb@redhat.com>
---
 kernel/audit.c |   24 ++++++++++++++++++++++++
 1 files changed, 24 insertions(+), 0 deletions(-)

diff --git a/kernel/audit.c b/kernel/audit.c
index 82df9fd..ffdec0c 100644
--- a/kernel/audit.c
+++ b/kernel/audit.c
@@ -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())
-- 
1.7.1

[ARCHIVE DEBUG 05/13] audit_debug: proc debug output easier to paste

[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 <rgb@redhat.com>
---
 kernel/audit.c |   75 ++++++++++++++++++++++++++++++++++++++------------------
 1 files changed, 51 insertions(+), 24 deletions(-)

diff --git a/kernel/audit.c b/kernel/audit.c
index ffdec0c..30b3b08 100644
--- a/kernel/audit.c
+++ b/kernel/audit.c
@@ -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;
 }
-- 
1.7.1

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

[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 <rgb@redhat.com>
---
 kernel/audit.c |   14 ++++++++------
 1 files changed, 8 insertions(+), 6 deletions(-)

diff --git a/kernel/audit.c b/kernel/audit.c
index 30b3b08..93a466b 100644
--- a/kernel/audit.c
+++ b/kernel/audit.c
@@ -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))
-- 
1.7.1

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

[Steve Grubb]

On Thursday, October 22, 2015 02:58:52 PM Richard Guy Briggs wrote:
> 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

> Signed-off-by: Richard Guy Briggs <rgb@redhat.com>
> ---
>  kernel/audit.c |   14 ++++++++------
>  1 files changed, 8 insertions(+), 6 deletions(-)
> 
> diff --git a/kernel/audit.c b/kernel/audit.c
> index 30b3b08..93a466b 100644
> --- a/kernel/audit.c
> +++ b/kernel/audit.c
> @@ -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))

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

[Richard Guy Briggs]

On 15/10/22, Steve Grubb wrote:
> On Thursday, October 22, 2015 02:58:52 PM Richard Guy Briggs wrote:
> > 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.

> -Steve
> 
> > Signed-off-by: Richard Guy Briggs <rgb@redhat.com>
> > ---
> >  kernel/audit.c |   14 ++++++++------
> >  1 files changed, 8 insertions(+), 6 deletions(-)
> > 
> > diff --git a/kernel/audit.c b/kernel/audit.c
> > index 30b3b08..93a466b 100644
> > --- a/kernel/audit.c
> > +++ b/kernel/audit.c
> > @@ -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))
> 
> --
> Linux-audit mailing list
> Linux-audit@redhat.com
> https://www.redhat.com/mailman/listinfo/linux-audit

- RGB

--
Richard Guy Briggs <rbriggs@redhat.com>
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

[ARCHIVE DEBUG 07/13] audit_debug: instrument audit_cmd_mutex contention

[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 <rgb@redhat.com>
---
 kernel/audit.c |   18 +++++++++++++++++-
 1 files changed, 17 insertions(+), 1 deletions(-)

diff --git a/kernel/audit.c b/kernel/audit.c
index 93a466b..a586bf2 100644
--- a/kernel/audit.c
+++ b/kernel/audit.c
@@ -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);
 }
-- 
1.7.1

[ARCHIVE DEBUG 08/13] audit_debug: seperate out audit_titles in proc display

[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 <rgb@redhat.com>
---
 kernel/audit.c |   20 ++++++++++++++++++--
 1 files changed, 18 insertions(+), 2 deletions(-)

diff --git a/kernel/audit.c b/kernel/audit.c
index a586bf2..d6f4763 100644
--- a/kernel/audit.c
+++ b/kernel/audit.c
@@ -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;
-- 
1.7.1

[ARCHIVE DEBUG 09/13] netlink_debug: instrument timing of calls by init/systemd or audit_pid

[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 <rgb@redhat.com>
---
 net/netlink/af_netlink.c |   16 ++++++++++++++++
 1 files changed, 16 insertions(+), 0 deletions(-)

diff --git a/net/netlink/af_netlink.c b/net/netlink/af_netlink.c
index 05919bf..ba5eedf 100644
--- a/net/netlink/af_netlink.c
+++ b/net/netlink/af_netlink.c
@@ -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;
 }
 
-- 
1.7.1

[ARCHIVE DEBUG 10/13] audit_debug: bark on impossible reserve process conditions in while loop

[Richard Guy Briggs]

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

Signed-off-by: Richard Guy Briggs <rgb@redhat.com>
---
 kernel/audit.c |   12 ++++++++++++
 1 files changed, 12 insertions(+), 0 deletions(-)

diff --git a/kernel/audit.c b/kernel/audit.c
index d6f4763..9e9c02b 100644
--- a/kernel/audit.c
+++ b/kernel/audit.c
@@ -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);
-- 
1.7.1

[ARCHIVE DEBUG 11/13] audit_debug: instrument audit_receive timing

[Richard Guy Briggs]

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

Signed-off-by: Richard Guy Briggs <rgb@redhat.com>
---
 kernel/audit.c |   16 ++++++++++++++++
 1 files changed, 16 insertions(+), 0 deletions(-)

diff --git a/kernel/audit.c b/kernel/audit.c
index 9e9c02b..76b6878 100644
--- a/kernel/audit.c
+++ b/kernel/audit.c
@@ -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. */
-- 
1.7.1

[ARCHIVE DEBUG 12/13] audit_debug: list processes and frequencies waiting for auditd

[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 <rgb@redhat.com>
---
 kernel/audit.c |   32 ++++++++++++++++++++++++++++++++
 1 files changed, 32 insertions(+), 0 deletions(-)

diff --git a/kernel/audit.c b/kernel/audit.c
index 76b6878..e4be6f3 100644
--- a/kernel/audit.c
+++ b/kernel/audit.c
@@ -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),
-- 
1.7.1

[ARCHIVE DEBUG 13/13] audit_debug: print inode nr for each path when listing exe rules

[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 <rgb@redhat.com>
---
 kernel/audit.h          |    2 ++
 kernel/audit_fsnotify.c |    5 +++++
 kernel/auditfilter.c    |    1 +
 3 files changed, 8 insertions(+), 0 deletions(-)

diff --git a/kernel/audit.h b/kernel/audit.h
index 24ec861..a7cf1ad 100644
--- a/kernel/audit.h
+++ b/kernel/audit.h
@@ -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)
diff --git a/kernel/audit_fsnotify.c b/kernel/audit_fsnotify.c
index 27c6046..dcf788c 100644
--- a/kernel/audit_fsnotify.c
+++ b/kernel/audit_fsnotify.c
@@ -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;
diff --git a/kernel/auditfilter.c b/kernel/auditfilter.c
index 7714d93..0c36546 100644
--- a/kernel/auditfilter.c
+++ b/kernel/auditfilter.c
@@ -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) {
-- 
1.7.1