[PATCH] selftests/livepatch: better synchronize test_klp_callbacks_busy

[PATCH] selftests/livepatch: better synchronize test_klp_callbacks_busy

[Joe Lawrence]

The test_klp_callbacks_busy module conditionally blocks a future
livepatch transition by busy waiting inside its workqueue function,
busymod_work_func().  After scheduling this work, a test livepatch is
loaded, introducing the transition under test.

Both events are marked in the kernel log for later verification, but
there is no synchronization to ensure that busymod_work_func() logs its
function entry message before subsequent selftest commands log their own
messages.  This can lead to a rare test failure due to unexpected
ordering like:

  --- expected
  +++ result
  @@ -1,7 +1,7 @@
   % modprobe test_klp_callbacks_busy block_transition=Y
   test_klp_callbacks_busy: test_klp_callbacks_busy_init
  -test_klp_callbacks_busy: busymod_work_func enter
   % modprobe test_klp_callbacks_demo
  +test_klp_callbacks_busy: busymod_work_func enter
   livepatch: enabling patch 'test_klp_callbacks_demo'
   livepatch: 'test_klp_callbacks_demo': initializing patching transition
   test_klp_callbacks_demo: pre_patch_callback: vmlinux

Force the module init function to wait until busymod_work_func() has
started (and logged its message), before exiting to the next selftest
steps.

Fixes: 547840bd5ae5 ("selftests/livepatch: simplify test-klp-callbacks busy target tests")
Signed-off-by: Joe Lawrence <joe.lawrence@redhat.com>
---

Hi Petr, I remember you discouraged against a completion variable the
first time around [1], but is there any better way with the workqueue
API to ensure our "enter" message gets logged first?  Or should we just
drop the msg altogether to avoid the situation?  I don't think it's
absolutely necessary for the tests.

[1] https://lore.kernel.org/live-patching/20200602081654.GI27273@linux-b0ei/

 lib/livepatch/test_klp_callbacks_busy.c | 7 +++++++
 1 file changed, 7 insertions(+)

diff --git a/lib/livepatch/test_klp_callbacks_busy.c b/lib/livepatch/test_klp_callbacks_busy.c
index 7ac845f65be5..eb502b2bb3ef 100644
--- a/lib/livepatch/test_klp_callbacks_busy.c
+++ b/lib/livepatch/test_klp_callbacks_busy.c
@@ -16,10 +16,16 @@ MODULE_PARM_DESC(block_transition, "block_transition (default=false)");
 
 static void busymod_work_func(struct work_struct *work);
 static DECLARE_WORK(work, busymod_work_func);
+static DECLARE_COMPLETION(busymod_work_started);
 
 static void busymod_work_func(struct work_struct *work)
 {
+	/*
+	 * Hold the init function from exiting until we've started and
+	 * announced our appearence in the kernel log.
+	 */
 	pr_info("%s enter\n", __func__);
+	complete(&busymod_work_started);
 
 	while (READ_ONCE(block_transition)) {
 		/*
@@ -36,6 +42,7 @@ static int test_klp_callbacks_busy_init(void)
 {
 	pr_info("%s\n", __func__);
 	schedule_work(&work);
+	wait_for_completion(&busymod_work_started);
 
 	if (!block_transition) {
 		/*
-- 
2.26.3

Re: [PATCH] selftests/livepatch: better synchronize test_klp_callbacks_busy

[Joe Lawrence]

On Wed, May 18, 2022 at 01:34:24PM -0400, Joe Lawrence wrote:
> The test_klp_callbacks_busy module conditionally blocks a future
> livepatch transition by busy waiting inside its workqueue function,
> busymod_work_func().  After scheduling this work, a test livepatch is
> loaded, introducing the transition under test.
> 
> Both events are marked in the kernel log for later verification, but
> there is no synchronization to ensure that busymod_work_func() logs its
> function entry message before subsequent selftest commands log their own
> messages.  This can lead to a rare test failure due to unexpected
> ordering like:
> 
>   --- expected
>   +++ result
>   @@ -1,7 +1,7 @@
>    % modprobe test_klp_callbacks_busy block_transition=Y
>    test_klp_callbacks_busy: test_klp_callbacks_busy_init
>   -test_klp_callbacks_busy: busymod_work_func enter
>    % modprobe test_klp_callbacks_demo
>   +test_klp_callbacks_busy: busymod_work_func enter
>    livepatch: enabling patch 'test_klp_callbacks_demo'
>    livepatch: 'test_klp_callbacks_demo': initializing patching transition
>    test_klp_callbacks_demo: pre_patch_callback: vmlinux
> 
> Force the module init function to wait until busymod_work_func() has
> started (and logged its message), before exiting to the next selftest
> steps.
> 
> Fixes: 547840bd5ae5 ("selftests/livepatch: simplify test-klp-callbacks busy target tests")
> Signed-off-by: Joe Lawrence <joe.lawrence@redhat.com>
> ---
> 
> Hi Petr, I remember you discouraged against a completion variable the
> first time around [1], but is there any better way with the workqueue
> API to ensure our "enter" message gets logged first?  Or should we just
> drop the msg altogether to avoid the situation?  I don't think it's
> absolutely necessary for the tests.
> 
> [1] https://lore.kernel.org/live-patching/20200602081654.GI27273@linux-b0ei/
> 
>  lib/livepatch/test_klp_callbacks_busy.c | 7 +++++++
>  1 file changed, 7 insertions(+)
> 
> diff --git a/lib/livepatch/test_klp_callbacks_busy.c b/lib/livepatch/test_klp_callbacks_busy.c
> index 7ac845f65be5..eb502b2bb3ef 100644
> --- a/lib/livepatch/test_klp_callbacks_busy.c
> +++ b/lib/livepatch/test_klp_callbacks_busy.c
> @@ -16,10 +16,16 @@ MODULE_PARM_DESC(block_transition, "block_transition (default=false)");
>  
>  static void busymod_work_func(struct work_struct *work);
>  static DECLARE_WORK(work, busymod_work_func);
> +static DECLARE_COMPLETION(busymod_work_started);
>  
>  static void busymod_work_func(struct work_struct *work)
>  {
> +	/*
> +	 * Hold the init function from exiting until we've started and
> +	 * announced our appearence in the kernel log.
> +	 */
>  	pr_info("%s enter\n", __func__);
> +	complete(&busymod_work_started);
>  
>  	while (READ_ONCE(block_transition)) {
>  		/*
> @@ -36,6 +42,7 @@ static int test_klp_callbacks_busy_init(void)
>  {
>  	pr_info("%s\n", __func__);
>  	schedule_work(&work);
> +	wait_for_completion(&busymod_work_started);
>  
>  	if (!block_transition) {
>  		/*
> -- 
> 2.26.3
> 

[ fixup ycote's email address, sorry Yannick :D ]

-- Joe

Re: [PATCH] selftests/livepatch: better synchronize test_klp_callbacks_busy

[Petr Mladek]

On Wed 2022-05-18 13:34:24, Joe Lawrence wrote:
> The test_klp_callbacks_busy module conditionally blocks a future
> livepatch transition by busy waiting inside its workqueue function,
> busymod_work_func().  After scheduling this work, a test livepatch is
> loaded, introducing the transition under test.
> 
> Both events are marked in the kernel log for later verification, but
> there is no synchronization to ensure that busymod_work_func() logs its
> function entry message before subsequent selftest commands log their own
> messages.  This can lead to a rare test failure due to unexpected
> ordering like:
> 
>   --- expected
>   +++ result
>   @@ -1,7 +1,7 @@
>    % modprobe test_klp_callbacks_busy block_transition=Y
>    test_klp_callbacks_busy: test_klp_callbacks_busy_init
>   -test_klp_callbacks_busy: busymod_work_func enter
>    % modprobe test_klp_callbacks_demo
>   +test_klp_callbacks_busy: busymod_work_func enter
>    livepatch: enabling patch 'test_klp_callbacks_demo'
>    livepatch: 'test_klp_callbacks_demo': initializing patching transition
>    test_klp_callbacks_demo: pre_patch_callback: vmlinux
> 
> Force the module init function to wait until busymod_work_func() has
> started (and logged its message), before exiting to the next selftest
> steps.
> 
> Fixes: 547840bd5ae5 ("selftests/livepatch: simplify test-klp-callbacks busy target tests")
> Signed-off-by: Joe Lawrence <joe.lawrence@redhat.com>
> ---
> 
> Hi Petr, I remember you discouraged against a completion variable the
> first time around [1], but is there any better way with the workqueue
> API to ensure our "enter" message gets logged first?

I think that the code was more complicated at that time.
Or I have got used to it ;-)


> Or should we just drop the msg altogether to avoid the situation?
> I don't think it's absolutely necessary for the tests.

IMHO, the message helps to make sure that the timing is correct.
I would keep it.


> [1] https://lore.kernel.org/live-patching/20200602081654.GI27273@linux-b0ei/
> 
>  lib/livepatch/test_klp_callbacks_busy.c | 7 +++++++
>  1 file changed, 7 insertions(+)
> 
> diff --git a/lib/livepatch/test_klp_callbacks_busy.c b/lib/livepatch/test_klp_callbacks_busy.c
> index 7ac845f65be5..eb502b2bb3ef 100644
> --- a/lib/livepatch/test_klp_callbacks_busy.c
> +++ b/lib/livepatch/test_klp_callbacks_busy.c
> @@ -16,10 +16,16 @@ MODULE_PARM_DESC(block_transition, "block_transition (default=false)");
>  
>  static void busymod_work_func(struct work_struct *work);
>  static DECLARE_WORK(work, busymod_work_func);
> +static DECLARE_COMPLETION(busymod_work_started);
>  
>  static void busymod_work_func(struct work_struct *work)
>  {
> +	/*
> +	 * Hold the init function from exiting until we've started and
> +	 * announced our appearence in the kernel log.
> +	 */

This message would make more sense above the wait_for_completion().
The wait function holds the init function. I would remove the comment here.

>  	pr_info("%s enter\n", __func__);
> +	complete(&busymod_work_started);
>  
>  	while (READ_ONCE(block_transition)) {
>  		/*
> @@ -36,6 +42,7 @@ static int test_klp_callbacks_busy_init(void)
>  {
>  	pr_info("%s\n", __func__);
>  	schedule_work(&work);

Instead, I would add here something like:

	/*
	 * Hold the init function from exiting until the message
	 * about entering the busy loop is printed.
	 */
> +	wait_for_completion(&busymod_work_started);
>  
>  	if (!block_transition) {
>  		/*
> -- 
> 2.26.3

With the updated message:

Reviewed-by: Petr Mladek <pmladek@suse.com>

Best Regards,
Petr

PS: I am sorry for the late review. I have busy times.