Currently backlog waiting time in audit_receive() is not accounted as
audit_backlog_wait_time_actual. Accounts it as well.

Signed-off-by: Eiichi Tsukata <eiichi.tsukata@nutanix.com>
---
 kernel/audit.c | 44 ++++++++++++++++++++++++++------------------
 1 file changed, 26 insertions(+), 18 deletions(-)

diff --git a/kernel/audit.c b/kernel/audit.c
index c15694e1a76b..89e119ccda76 100644
--- a/kernel/audit.c
+++ b/kernel/audit.c
@@ -628,6 +628,29 @@ static void kauditd_retry_skb(struct sk_buff *skb, __always_unused int error)
 	kfree_skb(skb);
 }
 
+/**
+ * wait_for_kauditd - Wait for kauditd to drain the queue
+ * @stime: time to sleep
+ *
+ * Description:
+ * Waits for kauditd to drain the queue then adds duration of sleep time to
+ * audit_backlog_wait_time_actual as cumulative sum.
+ * Returns remaining time to sleep.
+ */
+static long wait_for_kauditd(long stime)
+{
+	long rtime;
+	DECLARE_WAITQUEUE(wait, current);
+
+	add_wait_queue_exclusive(&audit_backlog_wait, &wait);
+	set_current_state(TASK_UNINTERRUPTIBLE);
+	rtime = schedule_timeout(stime);
+	atomic_add(stime - rtime, &audit_backlog_wait_time_actual);
+	remove_wait_queue(&audit_backlog_wait, &wait);
+
+	return rtime;
+}
+
 /**
  * auditd_reset - Disconnect the auditd connection
  * @ac: auditd connection state
@@ -1568,15 +1591,9 @@ static void audit_receive(struct sk_buff  *skb)
 
 	/* can't block with the ctrl lock, so penalize the sender now */
 	if (audit_queue_full(&audit_queue)) {
-		DECLARE_WAITQUEUE(wait, current);
-
 		/* wake kauditd to try and flush the queue */
 		wake_up_interruptible(&kauditd_wait);
-
-		add_wait_queue_exclusive(&audit_backlog_wait, &wait);
-		set_current_state(TASK_UNINTERRUPTIBLE);
-		schedule_timeout(audit_backlog_wait_time);
-		remove_wait_queue(&audit_backlog_wait, &wait);
+		wait_for_kauditd(audit_backlog_wait_time);
 	}
 }
 
@@ -1874,17 +1891,8 @@ struct audit_buffer *audit_log_start(struct audit_context *ctx, gfp_t gfp_mask,
 
 			/* sleep if we are allowed and we haven't exhausted our
 			 * backlog wait limit */
-			if (gfpflags_allow_blocking(gfp_mask) && (stime > 0)) {
-				long rtime = stime;
-
-				DECLARE_WAITQUEUE(wait, current);
-
-				add_wait_queue_exclusive(&audit_backlog_wait,
-							 &wait);
-				set_current_state(TASK_UNINTERRUPTIBLE);
-				stime = schedule_timeout(rtime);
-				atomic_add(rtime - stime, &audit_backlog_wait_time_actual);
-				remove_wait_queue(&audit_backlog_wait, &wait);
+			if (gfpflags_allow_blocking(gfp_mask) && stime > 0) {
+				stime = wait_for_kauditd(stime);
 			} else {
 				if (audit_rate_check() && printk_ratelimit())
 					pr_warn("audit_backlog=%d > audit_backlog_limit=%d\n",
-- 
2.40.0

On May 11, 2023 Eiichi Tsukata <eiichi.tsukata@nutanix.com> wrote:
> 
> Currently backlog waiting time in audit_receive() is not accounted as
> audit_backlog_wait_time_actual. Accounts it as well.
> 
> Signed-off-by: Eiichi Tsukata <eiichi.tsukata@nutanix.com>
> ---
>  kernel/audit.c | 44 ++++++++++++++++++++++++++------------------
>  1 file changed, 26 insertions(+), 18 deletions(-)

The audit_receive() wait is different from that in audit_log_start()
as processes calling into audit_receive() are performing an explicit
audit operation whereas those processes calling audit_log_start() are
likely doing something else, e.g. opening a file, that happens to
result in an audit record being generated.  The fact that the
audit_receive() accounting logic, as well as the timeout calculation
used, is different from audit_log_start() is intentional.

--
paul-moore.com

> On May 20, 2023, at 5:54, Paul Moore <paul@paul-moore.com> wrote:
> 
> On May 11, 2023 Eiichi Tsukata <eiichi.tsukata@nutanix.com> wrote:
>> 
>> Currently backlog waiting time in audit_receive() is not accounted as
>> audit_backlog_wait_time_actual. Accounts it as well.
>> 
>> Signed-off-by: Eiichi Tsukata <eiichi.tsukata@nutanix.com>
>> ---
>> kernel/audit.c | 44 ++++++++++++++++++++++++++------------------
>> 1 file changed, 26 insertions(+), 18 deletions(-)
> 
> The audit_receive() wait is different from that in audit_log_start()
> as processes calling into audit_receive() are performing an explicit
> audit operation whereas those processes calling audit_log_start() are
> likely doing something else, e.g. opening a file, that happens to
> result in an audit record being generated.  The fact that the
> audit_receive() accounting logic, as well as the timeout calculation
> used, is different from audit_log_start() is intentional.
> 

The intention still sounds a bit not clear to me as both cases wait using
the same parameter “backlog_wait_time” and use the same wait
queue.

IMHO, it will be better to have some comprehensive code comments there.

Eiichi

On Mon, May 22, 2023 at 12:22 AM Eiichi Tsukata
<eiichi.tsukata@nutanix.com> wrote:
> > On May 20, 2023, at 5:54, Paul Moore <paul@paul-moore.com> wrote:
> > On May 11, 2023 Eiichi Tsukata <eiichi.tsukata@nutanix.com> wrote:
> >>
> >> Currently backlog waiting time in audit_receive() is not accounted as
> >> audit_backlog_wait_time_actual. Accounts it as well.
> >>
> >> Signed-off-by: Eiichi Tsukata <eiichi.tsukata@nutanix.com>
> >> ---
> >> kernel/audit.c | 44 ++++++++++++++++++++++++++------------------
> >> 1 file changed, 26 insertions(+), 18 deletions(-)
> >
> > The audit_receive() wait is different from that in audit_log_start()
> > as processes calling into audit_receive() are performing an explicit
> > audit operation whereas those processes calling audit_log_start() are
> > likely doing something else, e.g. opening a file, that happens to
> > result in an audit record being generated.  The fact that the
> > audit_receive() accounting logic, as well as the timeout calculation
> > used, is different from audit_log_start() is intentional.
> >
>
> The intention still sounds a bit not clear to me as both cases wait using
> the same parameter “backlog_wait_time” and use the same wait
> queue.
>
> IMHO, it will be better to have some comprehensive code comments there.

A fair point.  I'll add that to the todo list.

-- 
paul-moore.com