[PATCH] selftests/livepatch: adopt to newer sysctl error format

[PATCH] selftests/livepatch: adopt to newer sysctl error format

[Kamalesh Babulal]

With procfs v3.3.16, the sysctl command doesn't prints the set key and
value on error.  This change breaks livepatch selftest test-ftrace.sh,
that tests the interaction of sysctl ftrace_enabled:

 # selftests: livepatch: test-ftrace.sh
 # TEST: livepatch interaction with ftrace_enabled sysctl ... not ok
 #
 # --- expected
 # +++ result
 # @@ -16,7 +16,7 @@ livepatch: 'test_klp_livepatch': initial
 #  livepatch: 'test_klp_livepatch': starting patching transition
 #  livepatch: 'test_klp_livepatch': completing patching transition
 #  livepatch: 'test_klp_livepatch': patching complete
 # -livepatch: sysctl: setting key "kernel.ftrace_enabled": Device or
    resource busy kernel.ftrace_enabled = 0
 # +livepatch: sysctl: setting key "kernel.ftrace_enabled": Device or
    resource busy
 #  % echo 0 > /sys/kernel/livepatch/test_klp_livepatch/enabled
 #  livepatch: 'test_klp_livepatch': initializing unpatching transition
 #  livepatch: 'test_klp_livepatch': starting unpatching transition
 #
 # ERROR: livepatch kselftest(s) failed

on setting sysctl kernel.ftrace_enabled={0,1} value successfully, the
set key and value is displayed.

This patch fixes it by limiting the output from both the cases to eight
words, that includes the error message or set key and value on failure
and success. The upper bound of eight words is enough to display the
only tracked error message. Also, adjust the check_result string in
test-ftrace.sh to match the expected output.

With the patch, the test-ftrace.sh passes on v3.3.15, v3.3.16 versions
of sysctl:
 ...
 # selftests: livepatch: test-ftrace.sh
 # TEST: livepatch interaction with ftrace_enabled sysctl ... ok
 ok 5 selftests: livepatch: test-ftrace.sh

Signed-off-by: Kamalesh Babulal <kamalesh@linux.vnet.ibm.com>
---
Based on livepatching/for-5.9/selftests-cleanup, to be merged
through livepatching.git

 tools/testing/selftests/livepatch/functions.sh   | 3 ++-
 tools/testing/selftests/livepatch/test-ftrace.sh | 2 +-
 2 files changed, 3 insertions(+), 2 deletions(-)

diff --git a/tools/testing/selftests/livepatch/functions.sh b/tools/testing/selftests/livepatch/functions.sh
index 36648ca367c2..e3c0490d5a45 100644
--- a/tools/testing/selftests/livepatch/functions.sh
+++ b/tools/testing/selftests/livepatch/functions.sh
@@ -75,7 +75,8 @@ function set_dynamic_debug() {
 }
 
 function set_ftrace_enabled() {
-	result=$(sysctl kernel.ftrace_enabled="$1" 2>&1 | paste --serial --delimiters=' ')
+	result=$(sysctl kernel.ftrace_enabled="$1" 2>&1 | paste --serial --delimiters=' ' | \
+		 cut -d" " -f1-8)
 	echo "livepatch: $result" > /dev/kmsg
 }
 
diff --git a/tools/testing/selftests/livepatch/test-ftrace.sh b/tools/testing/selftests/livepatch/test-ftrace.sh
index 9160c9ec3b6f..552e165512f4 100755
--- a/tools/testing/selftests/livepatch/test-ftrace.sh
+++ b/tools/testing/selftests/livepatch/test-ftrace.sh
@@ -51,7 +51,7 @@ livepatch: '$MOD_LIVEPATCH': initializing patching transition
 livepatch: '$MOD_LIVEPATCH': starting patching transition
 livepatch: '$MOD_LIVEPATCH': completing patching transition
 livepatch: '$MOD_LIVEPATCH': patching complete
-livepatch: sysctl: setting key \"kernel.ftrace_enabled\": Device or resource busy kernel.ftrace_enabled = 0
+livepatch: sysctl: setting key \"kernel.ftrace_enabled\": Device or resource busy
 % echo 0 > /sys/kernel/livepatch/$MOD_LIVEPATCH/enabled
 livepatch: '$MOD_LIVEPATCH': initializing unpatching transition
 livepatch: '$MOD_LIVEPATCH': starting unpatching transition

base-commit: 3fd9bd8b7e41a1908bf8bc0cd06606f2b787cd39
-- 
2.26.2

Re: [PATCH] selftests/livepatch: adopt to newer sysctl error format

[Petr Mladek]

On Fri 2020-07-10 10:40:43, Kamalesh Babulal wrote:
> With procfs v3.3.16, the sysctl command doesn't prints the set key and
> value on error.  This change breaks livepatch selftest test-ftrace.sh,
> that tests the interaction of sysctl ftrace_enabled:
> 
>  # selftests: livepatch: test-ftrace.sh
>  # TEST: livepatch interaction with ftrace_enabled sysctl ... not ok
>  #
>  # --- expected
>  # +++ result
>  # @@ -16,7 +16,7 @@ livepatch: 'test_klp_livepatch': initial
>  #  livepatch: 'test_klp_livepatch': starting patching transition
>  #  livepatch: 'test_klp_livepatch': completing patching transition
>  #  livepatch: 'test_klp_livepatch': patching complete
>  # -livepatch: sysctl: setting key "kernel.ftrace_enabled": Device or
>     resource busy kernel.ftrace_enabled = 0
>  # +livepatch: sysctl: setting key "kernel.ftrace_enabled": Device or
>     resource busy
>  #  % echo 0 > /sys/kernel/livepatch/test_klp_livepatch/enabled
>  #  livepatch: 'test_klp_livepatch': initializing unpatching transition
>  #  livepatch: 'test_klp_livepatch': starting unpatching transition
>  #
>  # ERROR: livepatch kselftest(s) failed
> 
> on setting sysctl kernel.ftrace_enabled={0,1} value successfully, the
> set key and value is displayed.
> 
> This patch fixes it by limiting the output from both the cases to eight
> words, that includes the error message or set key and value on failure
> and success. The upper bound of eight words is enough to display the
> only tracked error message. Also, adjust the check_result string in
> test-ftrace.sh to match the expected output.

This looks really tricky.

I wonder if we could use "sysctl -q" to refuse printing the value
even with older versions. The following patch works here with
sysctl 3.3.15:

diff --git a/tools/testing/selftests/livepatch/functions.sh b/tools/testing/selftests/livepatch/functions.sh
index 2aab9791791d..47aa4c762bb4 100644
--- a/tools/testing/selftests/livepatch/functions.sh
+++ b/tools/testing/selftests/livepatch/functions.sh
@@ -64,7 +64,8 @@ function set_dynamic_debug() {
 }
 
 function set_ftrace_enabled() {
-	result=$(sysctl kernel.ftrace_enabled="$1" 2>&1 | paste --serial --delimiters=' ')
+	result=$(sysctl -q kernel.ftrace_enabled="$1" 2>&1 && \
+		 sysctl kernel.ftrace_enabled 2>&1)
 	echo "livepatch: $result" > /dev/kmsg
 }
 
diff --git a/tools/testing/selftests/livepatch/test-ftrace.sh b/tools/testing/selftests/livepatch/test-ftrace.sh
index e2a76887f40a..aa967c5d0558 100755
--- a/tools/testing/selftests/livepatch/test-ftrace.sh
+++ b/tools/testing/selftests/livepatch/test-ftrace.sh
@@ -53,7 +53,7 @@ livepatch: '$MOD_LIVEPATCH': initializing patching transition
 livepatch: '$MOD_LIVEPATCH': starting patching transition
 livepatch: '$MOD_LIVEPATCH': completing patching transition
 livepatch: '$MOD_LIVEPATCH': patching complete
-livepatch: sysctl: setting key \"kernel.ftrace_enabled\": Device or resource busy kernel.ftrace_enabled = 0
+livepatch: sysctl: setting key \"kernel.ftrace_enabled\": Device or resource busy
 % echo 0 > /sys/kernel/livepatch/$MOD_LIVEPATCH/enabled
 livepatch: '$MOD_LIVEPATCH': initializing unpatching transition
 livepatch: '$MOD_LIVEPATCH': starting unpatching transition


Best Regards,
Petr

Re: [PATCH] selftests/livepatch: adopt to newer sysctl error format

[Joe Lawrence]

On Fri, Jul 10, 2020 at 05:27:35PM +0200, Petr Mladek wrote:
> On Fri 2020-07-10 10:40:43, Kamalesh Babulal wrote:
> > With procfs v3.3.16, the sysctl command doesn't prints the set key and
> > value on error.  This change breaks livepatch selftest test-ftrace.sh,
> > that tests the interaction of sysctl ftrace_enabled:
> > 

Good catch, it looks like it was this procps commit that modified that
behavior:

  commit da82fe49b1476d227874905068adb69577e11d96
  Author: Patrick Steinhardt <ps@pks.im>
  Date:   Tue May 29 13:29:03 2018 +0200
  
      sysctl: do not report set key in case `close_stream` fails
      
      As we're using buffered I/O when writing kernel parameters, write errors
      may get delayed until we close the `FILE` stream. As we are currently
      outputting the key that is to be set disregarding the return value of
      `close_stream`, we may end up in a situation where we report error and
      success:
      
          $ sysctl kernel.printk_ratelimit=100000000000000
          sysctl: setting key "kernel.printk_ratelimit": error code 22
          kernel.printk_ratelimit = 100000000000000
      
      Fix the issue by only outputting the updated value in case
      `close_stream` does not report an error.
      
      Signed-off-by: Patrick Steinhardt <ps@pks.im>

And I'd agree that echoing the failed new value was confusing to see
from a user's perspective.

> >  # selftests: livepatch: test-ftrace.sh
> >  # TEST: livepatch interaction with ftrace_enabled sysctl ... not ok
> >  #
> >  # --- expected
> >  # +++ result
> >  # @@ -16,7 +16,7 @@ livepatch: 'test_klp_livepatch': initial
> >  #  livepatch: 'test_klp_livepatch': starting patching transition
> >  #  livepatch: 'test_klp_livepatch': completing patching transition
> >  #  livepatch: 'test_klp_livepatch': patching complete
> >  # -livepatch: sysctl: setting key "kernel.ftrace_enabled": Device or
> >     resource busy kernel.ftrace_enabled = 0
> >  # +livepatch: sysctl: setting key "kernel.ftrace_enabled": Device or
> >     resource busy
> >  #  % echo 0 > /sys/kernel/livepatch/test_klp_livepatch/enabled
> >  #  livepatch: 'test_klp_livepatch': initializing unpatching transition
> >  #  livepatch: 'test_klp_livepatch': starting unpatching transition
> >  #
> >  # ERROR: livepatch kselftest(s) failed
> > 
> > on setting sysctl kernel.ftrace_enabled={0,1} value successfully, the
> > set key and value is displayed.
> > 
> > This patch fixes it by limiting the output from both the cases to eight
> > words, that includes the error message or set key and value on failure
> > and success. The upper bound of eight words is enough to display the
> > only tracked error message. Also, adjust the check_result string in
> > test-ftrace.sh to match the expected output.
> 
> This looks really tricky.
> 
> I wonder if we could use "sysctl -q" to refuse printing the value
> even with older versions. The following patch works here with
> sysctl 3.3.15:
> 

FWIW, --quiet was added to procps way back in 2004, so it should be safe
to use... and there's already a bunch of net selftests using it.

> diff --git a/tools/testing/selftests/livepatch/functions.sh b/tools/testing/selftests/livepatch/functions.sh
> index 2aab9791791d..47aa4c762bb4 100644
> --- a/tools/testing/selftests/livepatch/functions.sh
> +++ b/tools/testing/selftests/livepatch/functions.sh
> @@ -64,7 +64,8 @@ function set_dynamic_debug() {
>  }
>  
>  function set_ftrace_enabled() {
> -	result=$(sysctl kernel.ftrace_enabled="$1" 2>&1 | paste --serial --delimiters=' ')
> +	result=$(sysctl -q kernel.ftrace_enabled="$1" 2>&1 && \
> +		 sysctl kernel.ftrace_enabled 2>&1)
>  	echo "livepatch: $result" > /dev/kmsg
>  }
>  
> diff --git a/tools/testing/selftests/livepatch/test-ftrace.sh b/tools/testing/selftests/livepatch/test-ftrace.sh
> index e2a76887f40a..aa967c5d0558 100755
> --- a/tools/testing/selftests/livepatch/test-ftrace.sh
> +++ b/tools/testing/selftests/livepatch/test-ftrace.sh
> @@ -53,7 +53,7 @@ livepatch: '$MOD_LIVEPATCH': initializing patching transition
>  livepatch: '$MOD_LIVEPATCH': starting patching transition
>  livepatch: '$MOD_LIVEPATCH': completing patching transition
>  livepatch: '$MOD_LIVEPATCH': patching complete
> -livepatch: sysctl: setting key \"kernel.ftrace_enabled\": Device or resource busy kernel.ftrace_enabled = 0
> +livepatch: sysctl: setting key \"kernel.ftrace_enabled\": Device or resource busy
>  % echo 0 > /sys/kernel/livepatch/$MOD_LIVEPATCH/enabled
>  livepatch: '$MOD_LIVEPATCH': initializing unpatching transition
>  livepatch: '$MOD_LIVEPATCH': starting unpatching transition
> 
> 

I think this method is less fragile than word count / cutting and we get
to drop that strange 'paste' invocation (I had to look that up in the
mapages to remember why we used it).

Regards,

-- Joe

Re: [PATCH] selftests/livepatch: adopt to newer sysctl error format

[Kamalesh Babulal]

On 11/07/20 12:01 am, Joe Lawrence wrote:
> On Fri, Jul 10, 2020 at 05:27:35PM +0200, Petr Mladek wrote:
>> On Fri 2020-07-10 10:40:43, Kamalesh Babulal wrote:
>>> With procfs v3.3.16, the sysctl command doesn't prints the set key and
>>> value on error.  This change breaks livepatch selftest test-ftrace.sh,
>>> that tests the interaction of sysctl ftrace_enabled:
>>>
> 
> Good catch, it looks like it was this procps commit that modified that
> behavior:
> 
>   commit da82fe49b1476d227874905068adb69577e11d96
>   Author: Patrick Steinhardt <ps@pks.im>
>   Date:   Tue May 29 13:29:03 2018 +0200
>   
>       sysctl: do not report set key in case `close_stream` fails
>       
>       As we're using buffered I/O when writing kernel parameters, write errors
>       may get delayed until we close the `FILE` stream. As we are currently
>       outputting the key that is to be set disregarding the return value of
>       `close_stream`, we may end up in a situation where we report error and
>       success:
>       
>           $ sysctl kernel.printk_ratelimit=100000000000000
>           sysctl: setting key "kernel.printk_ratelimit": error code 22
>           kernel.printk_ratelimit = 100000000000000
>       
>       Fix the issue by only outputting the updated value in case
>       `close_stream` does not report an error.
>       
>       Signed-off-by: Patrick Steinhardt <ps@pks.im>
> 
> And I'd agree that echoing the failed new value was confusing to see
> from a user's perspective.
> 
>>>  # selftests: livepatch: test-ftrace.sh
>>>  # TEST: livepatch interaction with ftrace_enabled sysctl ... not ok
>>>  #
>>>  # --- expected
>>>  # +++ result
>>>  # @@ -16,7 +16,7 @@ livepatch: 'test_klp_livepatch': initial
>>>  #  livepatch: 'test_klp_livepatch': starting patching transition
>>>  #  livepatch: 'test_klp_livepatch': completing patching transition
>>>  #  livepatch: 'test_klp_livepatch': patching complete
>>>  # -livepatch: sysctl: setting key "kernel.ftrace_enabled": Device or
>>>     resource busy kernel.ftrace_enabled = 0
>>>  # +livepatch: sysctl: setting key "kernel.ftrace_enabled": Device or
>>>     resource busy
>>>  #  % echo 0 > /sys/kernel/livepatch/test_klp_livepatch/enabled
>>>  #  livepatch: 'test_klp_livepatch': initializing unpatching transition
>>>  #  livepatch: 'test_klp_livepatch': starting unpatching transition
>>>  #
>>>  # ERROR: livepatch kselftest(s) failed
>>>
>>> on setting sysctl kernel.ftrace_enabled={0,1} value successfully, the
>>> set key and value is displayed.
>>>
>>> This patch fixes it by limiting the output from both the cases to eight
>>> words, that includes the error message or set key and value on failure
>>> and success. The upper bound of eight words is enough to display the
>>> only tracked error message. Also, adjust the check_result string in
>>> test-ftrace.sh to match the expected output.
>>
>> This looks really tricky.
>>
>> I wonder if we could use "sysctl -q" to refuse printing the value
>> even with older versions. The following patch works here with
>> sysctl 3.3.15:

Agree, "sysctl -q" is more robust, I tested it with sysctl v3.3.16 and the test
passes.  Can you please send the patch?

>>
> 
> FWIW, --quiet was added to procps way back in 2004, so it should be safe
> to use... and there's already a bunch of net selftests using it.

a couple of tests is using the "-q" options to set the sysctl values.

> 
>> diff --git a/tools/testing/selftests/livepatch/functions.sh b/tools/testing/selftests/livepatch/functions.sh
>> index 2aab9791791d..47aa4c762bb4 100644
>> --- a/tools/testing/selftests/livepatch/functions.sh
>> +++ b/tools/testing/selftests/livepatch/functions.sh
>> @@ -64,7 +64,8 @@ function set_dynamic_debug() {
>>  }
>>  
>>  function set_ftrace_enabled() {
>> -	result=$(sysctl kernel.ftrace_enabled="$1" 2>&1 | paste --serial --delimiters=' ')
>> +	result=$(sysctl -q kernel.ftrace_enabled="$1" 2>&1 && \
>> +		 sysctl kernel.ftrace_enabled 2>&1)
>>  	echo "livepatch: $result" > /dev/kmsg
>>  }
>>  
>> diff --git a/tools/testing/selftests/livepatch/test-ftrace.sh b/tools/testing/selftests/livepatch/test-ftrace.sh
>> index e2a76887f40a..aa967c5d0558 100755
>> --- a/tools/testing/selftests/livepatch/test-ftrace.sh
>> +++ b/tools/testing/selftests/livepatch/test-ftrace.sh
>> @@ -53,7 +53,7 @@ livepatch: '$MOD_LIVEPATCH': initializing patching transition
>>  livepatch: '$MOD_LIVEPATCH': starting patching transition
>>  livepatch: '$MOD_LIVEPATCH': completing patching transition
>>  livepatch: '$MOD_LIVEPATCH': patching complete
>> -livepatch: sysctl: setting key \"kernel.ftrace_enabled\": Device or resource busy kernel.ftrace_enabled = 0
>> +livepatch: sysctl: setting key \"kernel.ftrace_enabled\": Device or resource busy
>>  % echo 0 > /sys/kernel/livepatch/$MOD_LIVEPATCH/enabled
>>  livepatch: '$MOD_LIVEPATCH': initializing unpatching transition
>>  livepatch: '$MOD_LIVEPATCH': starting unpatching transition
>>
>>
> 
> I think this method is less fragile than word count / cutting and we get
> to drop that strange 'paste' invocation (I had to look that up in the
> mapages to remember why we used it).
> 

-- 
Kamalesh