Re: [PATCH bpf-next] selftests/bpf: relax expected log messages to allow emitting BPF_ST

[Yonghong Song <yonghong.song@linux.dev>]

On 8/8/23 4:04 PM, Eduard Zingerman wrote:
> On Tue, 2023-08-08 at 15:51 -0700, Yonghong Song wrote:
>>
>> On 8/8/23 9:27 AM, Eduard Zingerman wrote:
>>> Update [1] to LLVM BPF backend seeks to enable generation of BPF_ST
>>> instruction when CPUv4 is selected. This affects expected log messages
>>> for the following selftests:
>>> - log_fixup/missing_map
>>> - spin_lock/lock_id_mapval_preserve
>>> - spin_lock/lock_id_innermapval_preserve
>>>
>>> Expected messages in these tests hard-code instruction numbers for BPF
>>> programs compiled from C. These instruction numbers change when
>>> BPF_ST is allowed because single BPF_ST instruction replaces a pair of
>>> BPF_MOV/BPF_STX instructions, e.g.:
>>>
>>>       r1 = 42;
>>>       *(u32 *)(r10 - 8) = r1;  --->  *(u32 *)(r10 - 8) = 42;
>>>
>>> This commit updates expected log messages to avoid matching specific
>>> instruction numbers (program position still could be uniquely
>>> identified).
>>>
>>> [1] https://reviews.llvm.org/D140804
>>>       "[BPF] support for BPF_ST instruction in codegen"
>>>
>>> Signed-off-by: Eduard Zingerman <eddyz87@gmail.com>
>>> ---
>>>    .../selftests/bpf/prog_tests/log_fixup.c      |  2 +-
>>>    .../selftests/bpf/prog_tests/spin_lock.c      | 37 ++++++++++++++++---
>>>    2 files changed, 33 insertions(+), 6 deletions(-)
>>>
>>> diff --git a/tools/testing/selftests/bpf/prog_tests/log_fixup.c b/tools/testing/selftests/bpf/prog_tests/log_fixup.c
>>> index dba71d98a227..effd78b2a657 100644
>>> --- a/tools/testing/selftests/bpf/prog_tests/log_fixup.c
>>> +++ b/tools/testing/selftests/bpf/prog_tests/log_fixup.c
>>> @@ -124,7 +124,7 @@ static void missing_map(void)
>>>    	ASSERT_FALSE(bpf_map__autocreate(skel->maps.missing_map), "missing_map_autocreate");
>>>    
>>>    	ASSERT_HAS_SUBSTR(log_buf,
>>> -			  "8: <invalid BPF map reference>\n"
>>> +			  ": <invalid BPF map reference>\n"
>>>    			  "BPF map 'missing_map' is referenced but wasn't created\n",
>>>    			  "log_buf");
>>>    
>>> diff --git a/tools/testing/selftests/bpf/prog_tests/spin_lock.c b/tools/testing/selftests/bpf/prog_tests/spin_lock.c
>>> index d9270bd3d920..f29c08d93beb 100644
>>> --- a/tools/testing/selftests/bpf/prog_tests/spin_lock.c
>>> +++ b/tools/testing/selftests/bpf/prog_tests/spin_lock.c
>>> @@ -1,4 +1,5 @@
>>>    // SPDX-License-Identifier: GPL-2.0
>>> +#include <regex.h>
>>>    #include <test_progs.h>
>>>    #include <network_helpers.h>
>>>    
>>> @@ -19,12 +20,16 @@ static struct {
>>>    	  "; R1_w=map_value(off=0,ks=4,vs=4,imm=0)\n2: (85) call bpf_this_cpu_ptr#154\n"
>>>    	  "R1 type=map_value expected=percpu_ptr_" },
>>>    	{ "lock_id_mapval_preserve",
>>> -	  "8: (bf) r1 = r0                       ; R0_w=map_value(id=1,off=0,ks=4,vs=8,imm=0) "
>>> -	  "R1_w=map_value(id=1,off=0,ks=4,vs=8,imm=0)\n9: (85) call bpf_this_cpu_ptr#154\n"
>>> +	  "[0-9]\\+: (bf) r1 = r0                       ;"
>>> +	  " R0_w=map_value(id=1,off=0,ks=4,vs=8,imm=0)"
>>> +	  " R1_w=map_value(id=1,off=0,ks=4,vs=8,imm=0)\n"
>>> +	  "[0-9]\\+: (85) call bpf_this_cpu_ptr#154\n"
>>>    	  "R1 type=map_value expected=percpu_ptr_" },
>>>    	{ "lock_id_innermapval_preserve",
>>> -	  "13: (bf) r1 = r0                      ; R0=map_value(id=2,off=0,ks=4,vs=8,imm=0) "
>>> -	  "R1_w=map_value(id=2,off=0,ks=4,vs=8,imm=0)\n14: (85) call bpf_this_cpu_ptr#154\n"
>>> +	  "[0-9]\\+: (bf) r1 = r0                      ;"
>>> +	  " R0=map_value(id=2,off=0,ks=4,vs=8,imm=0)"
>>> +	  " R1_w=map_value(id=2,off=0,ks=4,vs=8,imm=0)\n"
>>> +	  "[0-9]\\+: (85) call bpf_this_cpu_ptr#154\n"
>>>    	  "R1 type=map_value expected=percpu_ptr_" },
>>>    	{ "lock_id_mismatch_kptr_kptr", "bpf_spin_unlock of different lock" },
>>>    	{ "lock_id_mismatch_kptr_global", "bpf_spin_unlock of different lock" },
>>> @@ -45,6 +50,24 @@ static struct {
>>>    	{ "lock_id_mismatch_innermapval_mapval", "bpf_spin_unlock of different lock" },
>>>    };
>>>    
>>> +static int match_regex(const char *pattern, const char *string)
>>> +{
>>> +	int err, rc;
>>> +	regex_t re;
>>> +
>>> +	err = regcomp(&re, pattern, REG_NOSUB);
>>> +	if (err) {
>>> +		char errbuf[512];
>>> +
>>> +		regerror(err, &re, errbuf, sizeof(errbuf));
>>> +		PRINT_FAIL("Can't compile regex: %s\n", errbuf);
>>> +		return -1;
>>> +	}
>>> +	rc = regexec(&re, string, 0, NULL, 0);
>>> +	regfree(&re);
>>> +	return rc == 0 ? 1 : 0;
>>> +}
>>> +
>>>    static void test_spin_lock_fail_prog(const char *prog_name, const char *err_msg)
>>>    {
>>>    	LIBBPF_OPTS(bpf_object_open_opts, opts, .kernel_log_buf = log_buf,
>>> @@ -74,7 +97,11 @@ static void test_spin_lock_fail_prog(const char *prog_name, const char *err_msg)
>>>    		goto end;
>>>    	}
>>>    
>>> -	if (!ASSERT_OK_PTR(strstr(log_buf, err_msg), "expected error message")) {
>>> +	ret = match_regex(err_msg, log_buf);
>>> +	if (!ASSERT_GE(ret, 0, "match_regex"))
>>
>> Should this be ASSERT_GT(ret, 0) or ASSERT_EQ(ret, 1)?
>> If IIUC, regexec return 0 means a successful match.
>> So in 'match_regex', a successful match will return 1, right?
> 
> Right `match_regex` has three possible return values:
> . -1 if regex could not be compiled
> .  0 if regex is ok but match fails
> .  1 if regex is ok and match is found
> 
> I check for -1 in this ASSERT_GE, and for 1 in the ASSERT_TRUE right
> below in order to have two separate error messages.
> 
> But maybe that is not necessary as I already have PRINT_FAIL in the
> match_regex for -1 exit. So it would be possible to figure out what
> failed: regcomp or regexec even if I replace ASSERT_GE/ASSERT_TRUE
> with a single ASSERT_TRUE (or ASSERT_EQ(ret, 1)) as you suggest.

Sorry, I think I missed the below change. It looks original intention
is to print out expected/actual in case of failure. So your patch
looks good to me.

Acked-by: Yonghong Song <yonghong.song@linux.dev>

> 
>>
>>> +		goto end;
>>> +
>>> +	if (!ASSERT_TRUE(ret, "no match for expected error message")) {
>>>    		fprintf(stderr, "Expected: %s\n", err_msg);
>>>    		fprintf(stderr, "Verifier: %s\n", log_buf);
>>>    	}
>