[PATCH 0/4] audit: refactor and fix for potential deadlock

[PATCH 0/4] audit: refactor and fix for potential deadlock

[Eiichi Tsukata]

Commit 7ffb8e317bae ("audit: we don't need to
__set_current_state(TASK_RUNNING)") accidentally moved queue full check
before add_wait_queue_exclusive() which introduced the following race:

    CPU1                           CPU2
  ========                       ========
  (in audit_log_start())         (in kauditd_thread())

  queue is full
                                 wake_up(&audit_backlog_wait)
                                 wait_event_freezable()
  add_wait_queue_exclusive()
  ...
  schedule_timeout()

Once this happens, both audit_log_start() and kauditd_thread() can cause
deadlock for up to backlog_wait_time waiting for each other. To prevent
the race, this patch adds queue full check after
prepare_to_wait_exclusive().

This patchset consists of the following parts:

Patch 1-3: Refactorings and a small fix preferable for deadlock fix
Patch 4: Actual deadlock fix

Eiichi Tsukata (4):
  audit: refactor queue full checks
  audit: account backlog waiting time in audit_receive()
  audit: convert DECLARE_WAITQUEUE to DEFINE_WAIT
  audit: check if queue is full after prepare_to_wait_exclusive()

 kernel/audit.c | 71 ++++++++++++++++++++++++++++++--------------------
 1 file changed, 43 insertions(+), 28 deletions(-)

-- 
2.40.0

[PATCH 1/4] audit: refactor queue full checks

[Eiichi Tsukata]

Currently audit queue full checks are done in multiple places.
Consolidate them into one audit_queue_full().

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

diff --git a/kernel/audit.c b/kernel/audit.c
index 9bc0b0301198..c15694e1a76b 100644
--- a/kernel/audit.c
+++ b/kernel/audit.c
@@ -341,6 +341,12 @@ static inline int audit_rate_check(void)
 	return retval;
 }
 
+static inline int audit_queue_full(const struct sk_buff_head *queue)
+{
+	return audit_backlog_limit &&
+	       (skb_queue_len(queue) > audit_backlog_limit);
+}
+
 /**
  * audit_log_lost - conditionally log lost audit message event
  * @message: the message stating reason for lost audit message
@@ -579,8 +585,7 @@ static void kauditd_hold_skb(struct sk_buff *skb, int error)
 	 * record on the retry queue unless it's full, in which case drop it
 	 */
 	if (error == -EAGAIN) {
-		if (!audit_backlog_limit ||
-		    skb_queue_len(&audit_retry_queue) < audit_backlog_limit) {
+		if (!audit_queue_full(&audit_retry_queue)) {
 			skb_queue_tail(&audit_retry_queue, skb);
 			return;
 		}
@@ -589,8 +594,7 @@ static void kauditd_hold_skb(struct sk_buff *skb, int error)
 	}
 
 	/* if we have room in the hold queue, queue the message */
-	if (!audit_backlog_limit ||
-	    skb_queue_len(&audit_hold_queue) < audit_backlog_limit) {
+	if (!audit_queue_full(&audit_hold_queue)) {
 		skb_queue_tail(&audit_hold_queue, skb);
 		return;
 	}
@@ -613,8 +617,7 @@ static void kauditd_hold_skb(struct sk_buff *skb, int error)
  */
 static void kauditd_retry_skb(struct sk_buff *skb, __always_unused int error)
 {
-	if (!audit_backlog_limit ||
-	    skb_queue_len(&audit_retry_queue) < audit_backlog_limit) {
+	if (!audit_queue_full(&audit_retry_queue)) {
 		skb_queue_tail(&audit_retry_queue, skb);
 		return;
 	}
@@ -1564,8 +1567,7 @@ static void audit_receive(struct sk_buff  *skb)
 	audit_ctl_unlock();
 
 	/* can't block with the ctrl lock, so penalize the sender now */
-	if (audit_backlog_limit &&
-	    (skb_queue_len(&audit_queue) > audit_backlog_limit)) {
+	if (audit_queue_full(&audit_queue)) {
 		DECLARE_WAITQUEUE(wait, current);
 
 		/* wake kauditd to try and flush the queue */
@@ -1866,8 +1868,7 @@ struct audit_buffer *audit_log_start(struct audit_context *ctx, gfp_t gfp_mask,
 	if (!(auditd_test_task(current) || audit_ctl_owner_current())) {
 		long stime = audit_backlog_wait_time;
 
-		while (audit_backlog_limit &&
-		       (skb_queue_len(&audit_queue) > audit_backlog_limit)) {
+		while (audit_queue_full(&audit_queue)) {
 			/* wake kauditd to try and flush the queue */
 			wake_up_interruptible(&kauditd_wait);
 
-- 
2.40.0

[PATCH 2/4] audit: account backlog waiting time in audit_receive()

[Eiichi Tsukata]

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

[PATCH 3/4] audit: convert DECLARE_WAITQUEUE to DEFINE_WAIT

[Eiichi Tsukata]

As there is no need to use DECLARE_WAITQUEUE, use simpler DEFINE_WAIT.

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

diff --git a/kernel/audit.c b/kernel/audit.c
index 89e119ccda76..bcbb0ba33c84 100644
--- a/kernel/audit.c
+++ b/kernel/audit.c
@@ -640,13 +640,13 @@ static void kauditd_retry_skb(struct sk_buff *skb, __always_unused int error)
 static long wait_for_kauditd(long stime)
 {
 	long rtime;
-	DECLARE_WAITQUEUE(wait, current);
+	DEFINE_WAIT(wait);
 
-	add_wait_queue_exclusive(&audit_backlog_wait, &wait);
-	set_current_state(TASK_UNINTERRUPTIBLE);
+	prepare_to_wait_exclusive(&audit_backlog_wait, &wait,
+				  TASK_UNINTERRUPTIBLE);
 	rtime = schedule_timeout(stime);
 	atomic_add(stime - rtime, &audit_backlog_wait_time_actual);
-	remove_wait_queue(&audit_backlog_wait, &wait);
+	finish_wait(&audit_backlog_wait, &wait);
 
 	return rtime;
 }
-- 
2.40.0

[PATCH 4/4] audit: check if queue is full after prepare_to_wait_exclusive()

[Eiichi Tsukata]

Commit 7ffb8e317bae ("audit: we don't need to
__set_current_state(TASK_RUNNING)") accidentally moved queue full check
before add_wait_queue_exclusive() which introduced the following race:

    CPU1                           CPU2
  ========                       ========
  (in audit_log_start())         (in kauditd_thread())

  queue is full
                                 wake_up(&audit_backlog_wait)
                                 wait_event_freezable()
  add_wait_queue_exclusive()
  ...
  schedule_timeout()

Once this happens, both audit_log_start() and kauditd_thread() can cause
deadlock for up to backlog_wait_time waiting for each other. To prevent
the race, this patch adds queue full check after
prepare_to_wait_exclusive().

Fixes: 7ffb8e317bae ("audit: we don't need to __set_current_state(TASK_RUNNING)")
Signed-off-by: Eiichi Tsukata <eiichi.tsukata@nutanix.com>
---
 kernel/audit.c | 10 ++++++++--
 1 file changed, 8 insertions(+), 2 deletions(-)

diff --git a/kernel/audit.c b/kernel/audit.c
index bcbb0ba33c84..d37a3a045230 100644
--- a/kernel/audit.c
+++ b/kernel/audit.c
@@ -644,8 +644,14 @@ static long wait_for_kauditd(long stime)
 
 	prepare_to_wait_exclusive(&audit_backlog_wait, &wait,
 				  TASK_UNINTERRUPTIBLE);
-	rtime = schedule_timeout(stime);
-	atomic_add(stime - rtime, &audit_backlog_wait_time_actual);
+
+	/* need to check if the queue is full again because kauditd might have
+	 * flushed the queue and went to sleep after prepare_to_wait_exclusive()
+	 */
+	if (audit_queue_full(&audit_queue)) {
+		rtime = schedule_timeout(stime);
+		atomic_add(stime - rtime, &audit_backlog_wait_time_actual);
+	}
 	finish_wait(&audit_backlog_wait, &wait);
 
 	return rtime;
-- 
2.40.0

Re: [PATCH 0/4] audit: refactor and fix for potential deadlock

[Paul Moore]

On Mon, May 8, 2023 at 3:58 AM Eiichi Tsukata
<eiichi.tsukata@nutanix.com> wrote:
> Commit 7ffb8e317bae ("audit: we don't need to
> __set_current_state(TASK_RUNNING)") accidentally moved queue full check
> before add_wait_queue_exclusive() which introduced the following race:
>
>     CPU1                           CPU2
>   ========                       ========
>   (in audit_log_start())         (in kauditd_thread())
>
>   queue is full
>                                  wake_up(&audit_backlog_wait)
>                                  wait_event_freezable()
>   add_wait_queue_exclusive()
>   ...
>   schedule_timeout()
>
> Once this happens, both audit_log_start() and kauditd_thread() can cause
> deadlock for up to backlog_wait_time waiting for each other. To prevent
> the race, this patch adds queue full check after
> prepare_to_wait_exclusive().

Have you seen this occur in practice?  The first thing that
audit_log_start() does when detecting that @audit_queue is full is to
wake kauditd_thread, which should start immediately draining
@audit_queue (even if a daemon is not listening, the @audit_queue will
be drained into one of the other queues).  While it is hard to predict
scheduling behavior, it seems unlikely that kauditd_thread would be
able to process the entire queue before audit_log_start() progresses
from waking kauditd_thread() to sleeping.

In the absolute worst case, the task attempting to emit an audit
record sleeps for either the configured wait time or until it is
awakened by kauditd_thread() which could be triggered by another task
attempting to emit an audit record.

-- 
paul-moore.com

Re: [PATCH 4/4] audit: check if queue is full after prepare_to_wait_exclusive()

[kernel test robot]

Hi Eiichi,

kernel test robot noticed the following build warnings:

[auto build test WARNING on pcmoore-audit/next]
[also build test WARNING on linus/master v6.4-rc1 next-20230508]
[If your patch is applied to the wrong git tree, kindly drop us a note.
And when submitting patch, we suggest to use '--base' as documented in
https://git-scm.com/docs/git-format-patch#_base_tree_information]

url:    https://github.com/intel-lab-lkp/linux/commits/Eiichi-Tsukata/audit-refactor-queue-full-checks/20230508-160019
base:   https://git.kernel.org/pub/scm/linux/kernel/git/pcmoore/audit.git next
patch link:    https://lore.kernel.org/r/20230508075812.76077-5-eiichi.tsukata%40nutanix.com
patch subject: [PATCH 4/4] audit: check if queue is full after prepare_to_wait_exclusive()
config: i386-randconfig-a001-20230508 (https://download.01.org/0day-ci/archive/20230509/202305090112.uJSc0NBw-lkp@intel.com/config)
compiler: clang version 14.0.6 (https://github.com/llvm/llvm-project f28c006a5895fc0e329fe15fead81e37457cb1d1)
reproduce (this is a W=1 build):
        wget https://raw.githubusercontent.com/intel/lkp-tests/master/sbin/make.cross -O ~/bin/make.cross
        chmod +x ~/bin/make.cross
        # https://github.com/intel-lab-lkp/linux/commit/cbc69d0c34bdbc06ebca3e3020cfc24034fcf173
        git remote add linux-review https://github.com/intel-lab-lkp/linux
        git fetch --no-tags linux-review Eiichi-Tsukata/audit-refactor-queue-full-checks/20230508-160019
        git checkout cbc69d0c34bdbc06ebca3e3020cfc24034fcf173
        # save the config file
        mkdir build_dir && cp config build_dir/.config
        COMPILER_INSTALL_PATH=$HOME/0day COMPILER=clang make.cross W=1 O=build_dir ARCH=i386 olddefconfig
        COMPILER_INSTALL_PATH=$HOME/0day COMPILER=clang make.cross W=1 O=build_dir ARCH=i386 SHELL=/bin/bash

If you fix the issue, kindly add following tag where applicable
| Reported-by: kernel test robot <lkp@intel.com>
| Link: https://lore.kernel.org/oe-kbuild-all/202305090112.uJSc0NBw-lkp@intel.com/

All warnings (new ones prefixed by >>):

>> kernel/audit.c:651:6: warning: variable 'rtime' is used uninitialized whenever 'if' condition is false [-Wsometimes-uninitialized]
           if (audit_queue_full(&audit_queue)) {
               ^~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
   kernel/audit.c:657:9: note: uninitialized use occurs here
           return rtime;
                  ^~~~~
   kernel/audit.c:651:2: note: remove the 'if' if its condition is always true
           if (audit_queue_full(&audit_queue)) {
           ^~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
   kernel/audit.c:642:12: note: initialize the variable 'rtime' to silence this warning
           long rtime;
                     ^
                      = 0
   1 warning generated.


vim +651 kernel/audit.c

   630	
   631	/**
   632	 * wait_for_kauditd - Wait for kauditd to drain the queue
   633	 * @stime: time to sleep
   634	 *
   635	 * Description:
   636	 * Waits for kauditd to drain the queue then adds duration of sleep time to
   637	 * audit_backlog_wait_time_actual as cumulative sum.
   638	 * Returns remaining time to sleep.
   639	 */
   640	static long wait_for_kauditd(long stime)
   641	{
   642		long rtime;
   643		DEFINE_WAIT(wait);
   644	
   645		prepare_to_wait_exclusive(&audit_backlog_wait, &wait,
   646					  TASK_UNINTERRUPTIBLE);
   647	
   648		/* need to check if the queue is full again because kauditd might have
   649		 * flushed the queue and went to sleep after prepare_to_wait_exclusive()
   650		 */
 > 651		if (audit_queue_full(&audit_queue)) {
   652			rtime = schedule_timeout(stime);
   653			atomic_add(stime - rtime, &audit_backlog_wait_time_actual);
   654		}
   655		finish_wait(&audit_backlog_wait, &wait);
   656	
   657		return rtime;
   658	}
   659	

-- 
0-DAY CI Kernel Test Service
https://github.com/intel/lkp-tests

Re: [PATCH 0/4] audit: refactor and fix for potential deadlock

[Eiichi Tsukata]

> On May 8, 2023, at 23:07, Paul Moore <paul@paul-moore.com> wrote:
> 
> On Mon, May 8, 2023 at 3:58 AM Eiichi Tsukata
> <eiichi.tsukata@nutanix.com> wrote:
>> Commit 7ffb8e317bae ("audit: we don't need to
>> __set_current_state(TASK_RUNNING)") accidentally moved queue full check
>> before add_wait_queue_exclusive() which introduced the following race:
>> 
>>    CPU1                           CPU2
>>  ========                       ========
>>  (in audit_log_start())         (in kauditd_thread())
>> 
>>  queue is full
>>                                 wake_up(&audit_backlog_wait)
>>                                 wait_event_freezable()
>>  add_wait_queue_exclusive()
>>  ...
>>  schedule_timeout()
>> 
>> Once this happens, both audit_log_start() and kauditd_thread() can cause
>> deadlock for up to backlog_wait_time waiting for each other. To prevent
>> the race, this patch adds queue full check after
>> prepare_to_wait_exclusive().
> 
> Have you seen this occur in practice?  

Yes, we hit this issue multiple times, though it’s pretty rare as you are mentioning.
In our case, sshd got stuck in audit_log_user_message(), which caused SSH connection
timeout.

Eiichi

Re: [PATCH 4/4] audit: check if queue is full after prepare_to_wait_exclusive()

[Eiichi Tsukata]

> On May 9, 2023, at 2:13, kernel test robot <lkp@intel.com> wrote:
> 
> Hi Eiichi,
> 
> kernel test robot noticed the following build warnings:
> 
> [auto build test WARNING on pcmoore-audit/next]
> [also build test WARNING on linus/master v6.4-rc1 next-20230508]
> [If your patch is applied to the wrong git tree, kindly drop us a note.
> And when submitting patch, we suggest to use '--base' as documented in
> https://urldefense.proofpoint.com/v2/url?u=https-3A__git-2Dscm.com_docs_git-2Dformat-2Dpatch-23-5Fbase-5Ftree-5Finformation&d=DwIBAg&c=s883GpUCOChKOHiocYtGcg&r=dy01Dr4Ly8mhvnUdx1pZhhT1bkq4h9z5aVWu3paoZtk&m=iEsfAln6T0-ALFZ77M_oT-wS2T2UFxboG589BXhqJFYG7-pvNIFPZ_GOAcQLlAj7&s=hJmkWbARWhiKbVA6rbRJyTnRSNu6CCcbc8h_5kv9OMs&e= ]
> 
> url:    https://urldefense.proofpoint.com/v2/url?u=https-3A__github.com_intel-2Dlab-2Dlkp_linux_commits_Eiichi-2DTsukata_audit-2Drefactor-2Dqueue-2Dfull-2Dchecks_20230508-2D160019&d=DwIBAg&c=s883GpUCOChKOHiocYtGcg&r=dy01Dr4Ly8mhvnUdx1pZhhT1bkq4h9z5aVWu3paoZtk&m=iEsfAln6T0-ALFZ77M_oT-wS2T2UFxboG589BXhqJFYG7-pvNIFPZ_GOAcQLlAj7&s=SgsiWqTcS-KNlz7pbWtpJLkfU4NCNx1PPnf561OBl_Y&e= 
> base:   https://urldefense.proofpoint.com/v2/url?u=https-3A__git.kernel.org_pub_scm_linux_kernel_git_pcmoore_audit.git&d=DwIBAg&c=s883GpUCOChKOHiocYtGcg&r=dy01Dr4Ly8mhvnUdx1pZhhT1bkq4h9z5aVWu3paoZtk&m=iEsfAln6T0-ALFZ77M_oT-wS2T2UFxboG589BXhqJFYG7-pvNIFPZ_GOAcQLlAj7&s=ODnLSauQV_XYtGzJFN1XMH7WQhUdZfa4kgzeiRdieOk&e=  next
> patch link:    https://urldefense.proofpoint.com/v2/url?u=https-3A__lore.kernel.org_r_20230508075812.76077-2D5-2Deiichi.tsukata-2540nutanix.com&d=DwIBAg&c=s883GpUCOChKOHiocYtGcg&r=dy01Dr4Ly8mhvnUdx1pZhhT1bkq4h9z5aVWu3paoZtk&m=iEsfAln6T0-ALFZ77M_oT-wS2T2UFxboG589BXhqJFYG7-pvNIFPZ_GOAcQLlAj7&s=xz0pVOvfxWhxF6yp8r3GFk7YmDc34ntJLAvFhHkVWqo&e= 
> patch subject: [PATCH 4/4] audit: check if queue is full after prepare_to_wait_exclusive()
> config: i386-randconfig-a001-20230508 (https://urldefense.proofpoint.com/v2/url?u=https-3A__download.01.org_0day-2Dci_archive_20230509_202305090112.uJSc0NBw-2Dlkp-40intel.com_config&d=DwIBAg&c=s883GpUCOChKOHiocYtGcg&r=dy01Dr4Ly8mhvnUdx1pZhhT1bkq4h9z5aVWu3paoZtk&m=iEsfAln6T0-ALFZ77M_oT-wS2T2UFxboG589BXhqJFYG7-pvNIFPZ_GOAcQLlAj7&s=q5366dSfHPWCbkUzXNPdIjJ8BOj2forT0D4fl3XwOQM&e= )
> compiler: clang version 14.0.6 (https://urldefense.proofpoint.com/v2/url?u=https-3A__github.com_llvm_llvm-2Dproject&d=DwIBAg&c=s883GpUCOChKOHiocYtGcg&r=dy01Dr4Ly8mhvnUdx1pZhhT1bkq4h9z5aVWu3paoZtk&m=iEsfAln6T0-ALFZ77M_oT-wS2T2UFxboG589BXhqJFYG7-pvNIFPZ_GOAcQLlAj7&s=cVl2Fv0ruc2lDCYKGZ2MsG1xkcmDSm0yVdz_UYbBk2A&e=  f28c006a5895fc0e329fe15fead81e37457cb1d1)
> reproduce (this is a W=1 build):
>        wget https://urldefense.proofpoint.com/v2/url?u=https-3A__raw.githubusercontent.com_intel_lkp-2Dtests_master_sbin_make.cross&d=DwIBAg&c=s883GpUCOChKOHiocYtGcg&r=dy01Dr4Ly8mhvnUdx1pZhhT1bkq4h9z5aVWu3paoZtk&m=iEsfAln6T0-ALFZ77M_oT-wS2T2UFxboG589BXhqJFYG7-pvNIFPZ_GOAcQLlAj7&s=Uwk-WxemwAN0EiTlBE5VBdk5GGUUOMySKGZXEEpkDBM&e=  -O ~/bin/make.cross
>        chmod +x ~/bin/make.cross
>        # https://urldefense.proofpoint.com/v2/url?u=https-3A__github.com_intel-2Dlab-2Dlkp_linux_commit_cbc69d0c34bdbc06ebca3e3020cfc24034fcf173&d=DwIBAg&c=s883GpUCOChKOHiocYtGcg&r=dy01Dr4Ly8mhvnUdx1pZhhT1bkq4h9z5aVWu3paoZtk&m=iEsfAln6T0-ALFZ77M_oT-wS2T2UFxboG589BXhqJFYG7-pvNIFPZ_GOAcQLlAj7&s=RWanBTSRB28iteIUKeSVppj2xq4uJygfumsMWjJv5jI&e= 
>        git remote add linux-review https://urldefense.proofpoint.com/v2/url?u=https-3A__github.com_intel-2Dlab-2Dlkp_linux&d=DwIBAg&c=s883GpUCOChKOHiocYtGcg&r=dy01Dr4Ly8mhvnUdx1pZhhT1bkq4h9z5aVWu3paoZtk&m=iEsfAln6T0-ALFZ77M_oT-wS2T2UFxboG589BXhqJFYG7-pvNIFPZ_GOAcQLlAj7&s=14mmQ3GZhIozHeufPooQIuKd1O2SeFL8-1gIi9c79EM&e= 
>        git fetch --no-tags linux-review Eiichi-Tsukata/audit-refactor-queue-full-checks/20230508-160019
>        git checkout cbc69d0c34bdbc06ebca3e3020cfc24034fcf173
>        # save the config file
>        mkdir build_dir && cp config build_dir/.config
>        COMPILER_INSTALL_PATH=$HOME/0day COMPILER=clang make.cross W=1 O=build_dir ARCH=i386 olddefconfig
>        COMPILER_INSTALL_PATH=$HOME/0day COMPILER=clang make.cross W=1 O=build_dir ARCH=i386 SHELL=/bin/bash
> 
> If you fix the issue, kindly add following tag where applicable
> | Reported-by: kernel test robot <lkp@intel.com>
> | Link: https://urldefense.proofpoint.com/v2/url?u=https-3A__lore.kernel.org_oe-2Dkbuild-2Dall_202305090112.uJSc0NBw-2Dlkp-40intel.com_&d=DwIBAg&c=s883GpUCOChKOHiocYtGcg&r=dy01Dr4Ly8mhvnUdx1pZhhT1bkq4h9z5aVWu3paoZtk&m=iEsfAln6T0-ALFZ77M_oT-wS2T2UFxboG589BXhqJFYG7-pvNIFPZ_GOAcQLlAj7&s=cKrS8zKrWpbCBg5KOGiZDk0iqjUu9BXkChKAu4pMC2Q&e= 
> 
> All warnings (new ones prefixed by >>):
> 
>>> kernel/audit.c:651:6: warning: variable 'rtime' is used uninitialized whenever 'if' condition is false [-Wsometimes-uninitialized]
>           if (audit_queue_full(&audit_queue)) {
>               ^~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
>   kernel/audit.c:657:9: note: uninitialized use occurs here
>           return rtime;
>                  ^~~~~
>   kernel/audit.c:651:2: note: remove the 'if' if its condition is always true
>           if (audit_queue_full(&audit_queue)) {
>           ^~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
>   kernel/audit.c:642:12: note: initialize the variable 'rtime' to silence this warning
>           long rtime;
>                     ^
>                      = 0
>   1 warning generated.
> 

Nice catch thanks!
We can initialize rtime as you suggested but in this case it will be better to return 0
explicitly if there is some room in the queue. i.e:

diff --git a/kernel/audit.c b/kernel/audit.c
index d37a3a045230..6b0cc0459984 100644
--- a/kernel/audit.c
+++ b/kernel/audit.c
@@ -651,6 +651,8 @@ static long wait_for_kauditd(long stime)
        if (audit_queue_full(&audit_queue)) {
                rtime = schedule_timeout(stime);
                atomic_add(stime - rtime, &audit_backlog_wait_time_actual);
+       } else {
+               rtime = 0;
        }
        finish_wait(&audit_backlog_wait, &wait);

I’ll fix it in v2.

Eiichi

Re: [PATCH 1/4] audit: refactor queue full checks

[Rinat Gadelshin]

Hi Eiichi!

Just one one for your patch.

On 08.05.2023 10:58, Eiichi Tsukata wrote:
> Currently audit queue full checks are done in multiple places.
> Consolidate them into one audit_queue_full().
>
> Signed-off-by: Eiichi Tsukata <eiichi.tsukata@nutanix.com>
> ---
>   kernel/audit.c | 21 +++++++++++----------
>   1 file changed, 11 insertions(+), 10 deletions(-)
>
> diff --git a/kernel/audit.c b/kernel/audit.c
> index 9bc0b0301198..c15694e1a76b 100644
> --- a/kernel/audit.c
> +++ b/kernel/audit.c
> @@ -341,6 +341,12 @@ static inline int audit_rate_check(void)
>   	return retval;
>   }
>   
> +static inline int audit_queue_full(const struct sk_buff_head *queue)
> +{
> +	return audit_backlog_limit &&
> +	       (skb_queue_len(queue) > audit_backlog_limit);
It seems that we should use `>=` here.
> +}
> +
>   /**
>    * audit_log_lost - conditionally log lost audit message event
>    * @message: the message stating reason for lost audit message
> @@ -579,8 +585,7 @@ static void kauditd_hold_skb(struct sk_buff *skb, int error)
>   	 * record on the retry queue unless it's full, in which case drop it
>   	 */
>   	if (error == -EAGAIN) {
> -		if (!audit_backlog_limit ||
> -		    skb_queue_len(&audit_retry_queue) < audit_backlog_limit) {
> +		if (!audit_queue_full(&audit_retry_queue)) {
>   			skb_queue_tail(&audit_retry_queue, skb);
>   			return;
>   		}
> @@ -589,8 +594,7 @@ static void kauditd_hold_skb(struct sk_buff *skb, int error)
>   	}
>   
>   	/* if we have room in the hold queue, queue the message */
> -	if (!audit_backlog_limit ||
> -	    skb_queue_len(&audit_hold_queue) < audit_backlog_limit) {
> +	if (!audit_queue_full(&audit_hold_queue)) {
>   		skb_queue_tail(&audit_hold_queue, skb);
>   		return;
>   	}
> @@ -613,8 +617,7 @@ static void kauditd_hold_skb(struct sk_buff *skb, int error)
>    */
>   static void kauditd_retry_skb(struct sk_buff *skb, __always_unused int error)
>   {
> -	if (!audit_backlog_limit ||
> -	    skb_queue_len(&audit_retry_queue) < audit_backlog_limit) {
> +	if (!audit_queue_full(&audit_retry_queue)) {
>   		skb_queue_tail(&audit_retry_queue, skb);
>   		return;
>   	}
> @@ -1564,8 +1567,7 @@ static void audit_receive(struct sk_buff  *skb)
>   	audit_ctl_unlock();
>   
>   	/* can't block with the ctrl lock, so penalize the sender now */
> -	if (audit_backlog_limit &&
> -	    (skb_queue_len(&audit_queue) > audit_backlog_limit)) {
> +	if (audit_queue_full(&audit_queue)) {
>   		DECLARE_WAITQUEUE(wait, current);
>   
>   		/* wake kauditd to try and flush the queue */
> @@ -1866,8 +1868,7 @@ struct audit_buffer *audit_log_start(struct audit_context *ctx, gfp_t gfp_mask,
>   	if (!(auditd_test_task(current) || audit_ctl_owner_current())) {
>   		long stime = audit_backlog_wait_time;
>   
> -		while (audit_backlog_limit &&
> -		       (skb_queue_len(&audit_queue) > audit_backlog_limit)) {
> +		while (audit_queue_full(&audit_queue)) {
>   			/* wake kauditd to try and flush the queue */
>   			wake_up_interruptible(&kauditd_wait);
>   

Re: [PATCH 1/4] audit: refactor queue full checks

[Eiichi Tsukata]

> On May 10, 2023, at 15:54, Rinat Gadelshin <rgadelsh@gmail.com> wrote:
> 
> Hi Eiichi!
> 
> Just one one for your patch.
> 
> On 08.05.2023 10:58, Eiichi Tsukata wrote:
>> Currently audit queue full checks are done in multiple places.
>> Consolidate them into one audit_queue_full().
>> 
>> Signed-off-by: Eiichi Tsukata <eiichi.tsukata@nutanix.com>
>> ---
>>  kernel/audit.c | 21 +++++++++++----------
>>  1 file changed, 11 insertions(+), 10 deletions(-)
>> 
>> diff --git a/kernel/audit.c b/kernel/audit.c
>> index 9bc0b0301198..c15694e1a76b 100644
>> --- a/kernel/audit.c
>> +++ b/kernel/audit.c
>> @@ -341,6 +341,12 @@ static inline int audit_rate_check(void)
>>   return retval;
>>  }
>>  +static inline int audit_queue_full(const struct sk_buff_head *queue)
>> +{
>> + return audit_backlog_limit &&
>> +        (skb_queue_len(queue) > audit_backlog_limit);
> It seems that we should use `>=` here.

Hi Rinat

Could you provide the detailed reason?

Currently queue full checks are done with ‘>’,
on the other hand queue NOT full checks are done with ‘<‘.

Looking into other similar checks in the kernel, unix_recvq_full() is using ‘>’.


Paul, how do you think about it?

Eiichi

Re: [PATCH 1/4] audit: refactor queue full checks

[Rinat Gadelshin]

On 10.05.2023 10:17, Eiichi Tsukata wrote:
>
>> On May 10, 2023, at 15:54, Rinat Gadelshin <rgadelsh@gmail.com> wrote:
>>
>> Hi Eiichi!
>>
>> Just one one for your patch.
>>
>> On 08.05.2023 10:58, Eiichi Tsukata wrote:
>>> Currently audit queue full checks are done in multiple places.
>>> Consolidate them into one audit_queue_full().
>>>
>>> Signed-off-by: Eiichi Tsukata <eiichi.tsukata@nutanix.com>
>>> ---
>>>   kernel/audit.c | 21 +++++++++++----------
>>>   1 file changed, 11 insertions(+), 10 deletions(-)
>>>
>>> diff --git a/kernel/audit.c b/kernel/audit.c
>>> index 9bc0b0301198..c15694e1a76b 100644
>>> --- a/kernel/audit.c
>>> +++ b/kernel/audit.c
>>> @@ -341,6 +341,12 @@ static inline int audit_rate_check(void)
>>>    return retval;
>>>   }
>>>   +static inline int audit_queue_full(const struct sk_buff_head *queue)
>>> +{
>>> + return audit_backlog_limit &&
>>> +        (skb_queue_len(queue) > audit_backlog_limit);
>> It seems that we should use `>=` here.
> Hi Rinat
>
> Could you provide the detailed reason?
>
> Currently queue full checks are done with ‘>’,
> on the other hand queue NOT full checks are done with ‘<‘.
>
> Looking into other similar checks in the kernel, unix_recvq_full() is using ‘>’.
Was (OR statement): `if (!audit_backlog_limit || 
skb_queue_len(&audit_retry_queue) < audit_backlog_limit)
For AND-statement it should be `if (audit_backlog_limit && 
(skb_queue_len(&audit_retry_queue) >= audit_backlog_limit))
Otherwise we get false for case `(skb_queue_len(&audit_retry_queue) == 
audit_backlog_limit)` which was true for the old implementation.
>
> Paul, how do you think about it?
>
> Eiichi
>
>

Re: [PATCH 0/4] audit: refactor and fix for potential deadlock

[Eiichi Tsukata]

> On May 9, 2023, at 10:34, Eiichi Tsukata <eiichi.tsukata@nutanix.com> wrote:
> 
> 
> 
>> On May 8, 2023, at 23:07, Paul Moore <paul@paul-moore.com> wrote:
>> 
>> On Mon, May 8, 2023 at 3:58 AM Eiichi Tsukata
>> <eiichi.tsukata@nutanix.com> wrote:
>>> Commit 7ffb8e317bae ("audit: we don't need to
>>> __set_current_state(TASK_RUNNING)") accidentally moved queue full check
>>> before add_wait_queue_exclusive() which introduced the following race:
>>> 
>>>   CPU1                           CPU2
>>> ========                       ========
>>> (in audit_log_start())         (in kauditd_thread())
>>> 
>>> queue is full
>>>                                wake_up(&audit_backlog_wait)
>>>                                wait_event_freezable()
>>> add_wait_queue_exclusive()
>>> ...
>>> schedule_timeout()
>>> 
>>> Once this happens, both audit_log_start() and kauditd_thread() can cause
>>> deadlock for up to backlog_wait_time waiting for each other. To prevent
>>> the race, this patch adds queue full check after
>>> prepare_to_wait_exclusive().
>> 
>> Have you seen this occur in practice?  
> 
> Yes, we hit this issue multiple times, though it’s pretty rare as you are mentioning.
> In our case, sshd got stuck in audit_log_user_message(), which caused SSH connection
> timeout.
> 

I found another case.

kauditd_thread issues wake_up(&audit_backlog_wait) once after wake up.
As waiter side is using add_wait_queue_exclusive() it only wakes up one process at once.

If kauditd wakes up a process which is sleeping in audit_log_start(), then the process will
queue skb and issue wake_up_interruptible(&kauditd_wait). No problem.
But if kauditd wakes up a process which is sleeping in audit_receive(), then the process
won’t try to wake up kauditd. In this case other processes sleeping in audit_log_start()
keep sleeping even if kauditd have flushed the queue.

At this point I’m planning to use non-exclusive wait in audit_receive() in v2.
Let me know if we should use wake_up_all() in kauditd or you have better solution.

Eiichi

Re: [PATCH 0/4] audit: refactor and fix for potential deadlock

[Paul Moore]

On Mon, May 8, 2023 at 9:49 PM Eiichi Tsukata
<eiichi.tsukata@nutanix.com> wrote:
> > On May 8, 2023, at 23:07, Paul Moore <paul@paul-moore.com> wrote:
> > On Mon, May 8, 2023 at 3:58 AM Eiichi Tsukata
> > <eiichi.tsukata@nutanix.com> wrote:
> >> Commit 7ffb8e317bae ("audit: we don't need to
> >> __set_current_state(TASK_RUNNING)") accidentally moved queue full check
> >> before add_wait_queue_exclusive() which introduced the following race:
> >>
> >>    CPU1                           CPU2
> >>  ========                       ========
> >>  (in audit_log_start())         (in kauditd_thread())
> >>
> >>  queue is full
> >>                                 wake_up(&audit_backlog_wait)
> >>                                 wait_event_freezable()
> >>  add_wait_queue_exclusive()
> >>  ...
> >>  schedule_timeout()
> >>
> >> Once this happens, both audit_log_start() and kauditd_thread() can cause
> >> deadlock for up to backlog_wait_time waiting for each other. To prevent
> >> the race, this patch adds queue full check after
> >> prepare_to_wait_exclusive().
> >
> > Have you seen this occur in practice?
>
> Yes, we hit this issue multiple times, though it’s pretty rare as you are mentioning.
> In our case, sshd got stuck in audit_log_user_message(), which caused SSH connection
> timeout.

Sorry for the delay, I was away at a conference last week.

Regardless of how we tweak the wait, there is always going to be a
chance that rescheduling the task with a timeout is going to impact
the application.  If you have sensitive applications where this is
proving to be a problem I would suggest tuning your backlog size, the
wait time, or removing the backlog limit entirely.

--
paul-moore.com

Re: [PATCH 0/4] audit: refactor and fix for potential deadlock

[Paul Moore]

On Wed, May 10, 2023 at 4:09 AM Eiichi Tsukata
<eiichi.tsukata@nutanix.com> wrote:
> > On May 9, 2023, at 10:34, Eiichi Tsukata <eiichi.tsukata@nutanix.com> wrote:
> >> On May 8, 2023, at 23:07, Paul Moore <paul@paul-moore.com> wrote:
> >> On Mon, May 8, 2023 at 3:58 AM Eiichi Tsukata
> >> <eiichi.tsukata@nutanix.com> wrote:
> >>> Commit 7ffb8e317bae ("audit: we don't need to
> >>> __set_current_state(TASK_RUNNING)") accidentally moved queue full check
> >>> before add_wait_queue_exclusive() which introduced the following race:
> >>>
> >>>   CPU1                           CPU2
> >>> ========                       ========
> >>> (in audit_log_start())         (in kauditd_thread())
> >>>
> >>> queue is full
> >>>                                wake_up(&audit_backlog_wait)
> >>>                                wait_event_freezable()
> >>> add_wait_queue_exclusive()
> >>> ...
> >>> schedule_timeout()
> >>>
> >>> Once this happens, both audit_log_start() and kauditd_thread() can cause
> >>> deadlock for up to backlog_wait_time waiting for each other. To prevent
> >>> the race, this patch adds queue full check after
> >>> prepare_to_wait_exclusive().
> >>
> >> Have you seen this occur in practice?
> >
> > Yes, we hit this issue multiple times, though it’s pretty rare as you are mentioning.
> > In our case, sshd got stuck in audit_log_user_message(), which caused SSH connection
> > timeout.
> >
>
> I found another case.
>
> kauditd_thread issues wake_up(&audit_backlog_wait) once after wake up.
> As waiter side is using add_wait_queue_exclusive() it only wakes up one process at once.
>
> If kauditd wakes up a process which is sleeping in audit_log_start(), then the process will
> queue skb and issue wake_up_interruptible(&kauditd_wait). No problem.
> But if kauditd wakes up a process which is sleeping in audit_receive(), then the process
> won’t try to wake up kauditd. In this case other processes sleeping in audit_log_start()
> keep sleeping even if kauditd have flushed the queue.
>
> At this point I’m planning to use non-exclusive wait in audit_receive() in v2.
> Let me know if we should use wake_up_all() in kauditd or you have better solution.

The nice part about marking the waiters as WQ_FLAG_EXCLUSIVE is that
we avoid the thundering herd problem.  The waiter was held in the
first place because the system was under high levels of audit
pressure, so it stands to reason that a slow wake-up of the waiters is
a wise choice to avoid re-entering another audit pressure state.

I'll take a look at your v2 patch, but as things stand I still believe
that this is better addressed via runtime configuration (see my
previous email).  However, some of the refactoring you've done might
be nice, I'll reply back on that in your v2 patch.

Thanks.

-- 
paul-moore.com