diff mbox series

[bpf,11/12] selftests/bpf: add __not_msg annotation for test_loader based tests

Message ID 20231116021803.9982-12-eddyz87@gmail.com (mailing list archive)
State Superseded
Delegated to: BPF
Headers show
Series verify callbacks as if they are called unknown number of times | expand

Checks

Context Check Description
netdev/series_format success Posting correctly formatted
netdev/tree_selection success Clearly marked for bpf, async
netdev/fixes_present fail Series targets non-next tree, but doesn't contain any Fixes tags
netdev/header_inline success No static functions without inline keyword in header files
netdev/build_32bit success Errors and warnings before: 8 this patch: 8
netdev/cc_maintainers warning 13 maintainers not CCed: haoluo@google.com song@kernel.org jolsa@kernel.org nathan@kernel.org trix@redhat.com john.fastabend@gmail.com linux-kselftest@vger.kernel.org shuah@kernel.org kpsingh@kernel.org mykolal@fb.com sdf@google.com ndesaulniers@google.com llvm@lists.linux.dev
netdev/build_clang success Errors and warnings before: 8 this patch: 8
netdev/verify_signedoff success Signed-off-by tag matches author and committer
netdev/deprecated_api success None detected
netdev/check_selftest success No net selftest shell script
netdev/verify_fixes success No Fixes tag
netdev/build_allmodconfig_warn success Errors and warnings before: 8 this patch: 8
netdev/checkpatch warning WARNING: line length of 81 exceeds 80 columns WARNING: line length of 82 exceeds 80 columns WARNING: line length of 83 exceeds 80 columns WARNING: line length of 85 exceeds 80 columns WARNING: line length of 92 exceeds 80 columns WARNING: line length of 94 exceeds 80 columns WARNING: line length of 96 exceeds 80 columns WARNING: line length of 98 exceeds 80 columns
netdev/build_clang_rust success No Rust files in patch. Skipping build
netdev/kdoc success Errors and warnings before: 0 this patch: 0
netdev/source_inline success Was 0 now: 0
bpf/vmtest-bpf-VM_Test-0 success Logs for Lint
bpf/vmtest-bpf-VM_Test-1 success Logs for ShellCheck
bpf/vmtest-bpf-VM_Test-2 success Logs for Validate matrix.py
bpf/vmtest-bpf-VM_Test-3 success Logs for aarch64-gcc / build / build for aarch64 with gcc
bpf/vmtest-bpf-VM_Test-7 success Logs for aarch64-gcc / test (test_verifier, false, 360) / test_verifier on aarch64 with gcc
bpf/vmtest-bpf-VM_Test-8 success Logs for aarch64-gcc / veristat
bpf/vmtest-bpf-VM_Test-4 success Logs for aarch64-gcc / test (test_maps, false, 360) / test_maps on aarch64 with gcc
bpf/vmtest-bpf-VM_Test-5 success Logs for aarch64-gcc / test (test_progs, false, 360) / test_progs on aarch64 with gcc
bpf/vmtest-bpf-VM_Test-6 success Logs for aarch64-gcc / test (test_progs_no_alu32, false, 360) / test_progs_no_alu32 on aarch64 with gcc
bpf/vmtest-bpf-VM_Test-9 success Logs for s390x-gcc / build / build for s390x with gcc
bpf/vmtest-bpf-VM_Test-14 success Logs for s390x-gcc / veristat
bpf/vmtest-bpf-VM_Test-15 success Logs for set-matrix
bpf/vmtest-bpf-VM_Test-16 success Logs for x86_64-gcc / build / build for x86_64 with gcc
bpf/vmtest-bpf-VM_Test-17 success Logs for x86_64-gcc / test (test_maps, false, 360) / test_maps on x86_64 with gcc
bpf/vmtest-bpf-VM_Test-18 success Logs for x86_64-gcc / test (test_progs, false, 360) / test_progs on x86_64 with gcc
bpf/vmtest-bpf-VM_Test-19 success Logs for x86_64-gcc / test (test_progs_no_alu32, false, 360) / test_progs_no_alu32 on x86_64 with gcc
bpf/vmtest-bpf-VM_Test-20 success Logs for x86_64-gcc / test (test_progs_no_alu32_parallel, true, 30) / test_progs_no_alu32_parallel on x86_64 with gcc
bpf/vmtest-bpf-VM_Test-21 success Logs for x86_64-gcc / test (test_progs_parallel, true, 30) / test_progs_parallel on x86_64 with gcc
bpf/vmtest-bpf-VM_Test-22 success Logs for x86_64-gcc / test (test_verifier, false, 360) / test_verifier on x86_64 with gcc
bpf/vmtest-bpf-VM_Test-23 success Logs for x86_64-gcc / veristat / veristat on x86_64 with gcc
bpf/vmtest-bpf-VM_Test-24 success Logs for x86_64-llvm-16 / build / build for x86_64 with llvm-16
bpf/vmtest-bpf-VM_Test-25 success Logs for x86_64-llvm-16 / test (test_maps, false, 360) / test_maps on x86_64 with llvm-16
bpf/vmtest-bpf-VM_Test-26 success Logs for x86_64-llvm-16 / test (test_progs, false, 360) / test_progs on x86_64 with llvm-16
bpf/vmtest-bpf-VM_Test-27 success Logs for x86_64-llvm-16 / test (test_progs_no_alu32, false, 360) / test_progs_no_alu32 on x86_64 with llvm-16
bpf/vmtest-bpf-VM_Test-28 success Logs for x86_64-llvm-16 / test (test_verifier, false, 360) / test_verifier on x86_64 with llvm-16
bpf/vmtest-bpf-VM_Test-29 success Logs for x86_64-llvm-16 / veristat
bpf/vmtest-bpf-VM_Test-13 success Logs for s390x-gcc / test (test_verifier, false, 360) / test_verifier on s390x with gcc
bpf/vmtest-bpf-VM_Test-12 success Logs for s390x-gcc / test (test_progs_no_alu32, false, 360) / test_progs_no_alu32 on s390x with gcc
bpf/vmtest-bpf-VM_Test-11 success Logs for s390x-gcc / test (test_progs, false, 360) / test_progs on s390x with gcc
bpf/vmtest-bpf-PR success PR summary
bpf/vmtest-bpf-VM_Test-10 success Logs for s390x-gcc / test (test_maps, false, 360) / test_maps on s390x with gcc

Commit Message

Eduard Zingerman Nov. 16, 2023, 2:18 a.m. UTC 
Add an ability to specify messages that should not be found in the
test verifier log. Similar to LLVM's FileCheck tool for the following
test specification:

    __success
    __msg("a")
    __not_msg("b")
    __msg("c")
    void foo(...) { ... }

- message "a" is expected to be in the log;
- message "b" is not expected after message "a"
  (but could be present before "a");
- message "c" is expected to be in the log after message "a".

Signed-off-by: Eduard Zingerman <eddyz87@gmail.com>
---
 tools/testing/selftests/bpf/progs/bpf_misc.h |  9 +++
 tools/testing/selftests/bpf/test_loader.c    | 82 ++++++++++++++------
 2 files changed, 68 insertions(+), 23 deletions(-)

Comments

Andrii Nakryiko Nov. 17, 2023, 4:45 p.m. UTC | #1 
On Wed, Nov 15, 2023 at 9:18 PM Eduard Zingerman <eddyz87@gmail.com> wrote:
>
> Add an ability to specify messages that should not be found in the
> test verifier log. Similar to LLVM's FileCheck tool for the following
> test specification:
>
>     __success
>     __msg("a")
>     __not_msg("b")
>     __msg("c")
>     void foo(...) { ... }
>
> - message "a" is expected to be in the log;
> - message "b" is not expected after message "a"
>   (but could be present before "a");
> - message "c" is expected to be in the log after message "a".

I think this implementation has an undesired surprising behavior.
Imagine you have a log like this:

A
C
D
B


And you specify

__msg("A")
__nomsg("B")
__msg("C")
__msg("D")
__msg("B")

Log matches the spec, right? But your implementation will eagerly reject it.

I think you can implement more coherent behavior if you only strstr()
__msg() specs, skipping __nomsg() first. But on each __msg one, if
successful, you go back and validate that there are no matches for all
__nomsg() specs that you skipped, taking into account matched
positions for current __msg() and last __msg() (or the start of the
log, of course).

Not sure if I explained clearly, but the idea is to postpone __nomsg()
until we anchor ourselves between two __msg()s. And beginning/end of
verifier log are two other anchoring positions.

>
> Signed-off-by: Eduard Zingerman <eddyz87@gmail.com>
> ---
>  tools/testing/selftests/bpf/progs/bpf_misc.h |  9 +++
>  tools/testing/selftests/bpf/test_loader.c    | 82 ++++++++++++++------
>  2 files changed, 68 insertions(+), 23 deletions(-)
>
> diff --git a/tools/testing/selftests/bpf/progs/bpf_misc.h b/tools/testing/selftests/bpf/progs/bpf_misc.h
> index 799fff4995d8..f24fcda6fc0b 100644
> --- a/tools/testing/selftests/bpf/progs/bpf_misc.h
> +++ b/tools/testing/selftests/bpf/progs/bpf_misc.h
> @@ -22,7 +22,13 @@
>   *
>   * __msg             Message expected to be found in the verifier log.
>   *                   Multiple __msg attributes could be specified.
> + *                   When multiple messages are specified they are
> + *                   matched one after another.
> + * __not_msg        Message not expected to be found in the verifier log.
> + *                   Matched from the end of the last checked __msg or
> + *                   from log start, if no __msg had been matched yet.
>   * __msg_unpriv      Same as __msg but for unprivileged mode.
> + * __not_msg_unpriv  Same as __not_msg but for unprivileged mode.

ok, it's bikeshedding, but __nomsg and __nomsg_unpriv seems a bit
nicer names for this (very subjective, of course)

>   *
>   * __success         Expect program load success in privileged mode.
>   * __success_unpriv  Expect program load success in unprivileged mode.
> @@ -59,10 +65,13 @@
>   * __auxiliary_unpriv  Same, but load program in unprivileged mode.
>   */
>  #define __msg(msg)             __attribute__((btf_decl_tag("comment:test_expect_msg=" msg)))
> +#define __not_msg(msg)         __attribute__((btf_decl_tag("comment:test_dont_expect_msg=" msg)))
>  #define __failure              __attribute__((btf_decl_tag("comment:test_expect_failure")))
>  #define __success              __attribute__((btf_decl_tag("comment:test_expect_success")))
>  #define __description(desc)    __attribute__((btf_decl_tag("comment:test_description=" desc)))
>  #define __msg_unpriv(msg)      __attribute__((btf_decl_tag("comment:test_expect_msg_unpriv=" msg)))
> +#define __not_msg_unpriv(msg)                                          \
> +       __attribute__((btf_decl_tag("comment:test_dont_expect_msg_unpriv=" msg)))

test_expect_no_msg ?

>  #define __failure_unpriv       __attribute__((btf_decl_tag("comment:test_expect_failure_unpriv")))
>  #define __success_unpriv       __attribute__((btf_decl_tag("comment:test_expect_success_unpriv")))
>  #define __log_level(lvl)       __attribute__((btf_decl_tag("comment:test_log_level="#lvl)))
> diff --git a/tools/testing/selftests/bpf/test_loader.c b/tools/testing/selftests/bpf/test_loader.c
> index 37ffa57f28a1..def16d9aeae2 100644
> --- a/tools/testing/selftests/bpf/test_loader.c
> +++ b/tools/testing/selftests/bpf/test_loader.c

[...]

> -static int push_msg(const char *msg, struct test_subspec *subspec)
> +static int push_msg(const char *msg, struct test_subspec *subspec, bool expected)
>  {
> +       size_t cnt = subspec->expect_msg_cnt;
>         void *tmp;
>
> -       tmp = realloc(subspec->expect_msgs, (1 + subspec->expect_msg_cnt) * sizeof(void *));
> +       tmp = realloc(subspec->expect_msgs,
> +                     (1 + subspec->expect_msg_cnt) * sizeof(*subspec->expect_msgs));

nit: 1 + cnt ?

>         if (!tmp) {
>                 ASSERT_FAIL("failed to realloc memory for messages\n");
>                 return -ENOMEM;
>         }
>         subspec->expect_msgs = tmp;
> -       subspec->expect_msgs[subspec->expect_msg_cnt++] = msg;
> +       subspec->expect_msgs[cnt].str = msg;
> +       subspec->expect_msgs[cnt].expected = expected;
> +       subspec->expect_msg_cnt++;
>
>         return 0;
>  }

[...]
Eduard Zingerman Nov. 17, 2023, 6:53 p.m. UTC | #2 
On Fri, 2023-11-17 at 11:45 -0500, Andrii Nakryiko wrote:
[...]
> I think this implementation has an undesired surprising behavior.
> Imagine you have a log like this:
> 
> A
> C
> D
> B
> 
> 
> And you specify
> 
> __msg("A")
> __nomsg("B")
> __msg("C")
> __msg("D")
> __msg("B")
> 
> Log matches the spec, right? But your implementation will eagerly reject it.
> 
> I think you can implement more coherent behavior if you only strstr()
> __msg() specs, skipping __nomsg() first. But on each __msg one, if
> successful, you go back and validate that there are no matches for all
> __nomsg() specs that you skipped, taking into account matched
> positions for current __msg() and last __msg() (or the start of the
> log, of course).
> 
> Not sure if I explained clearly, but the idea is to postpone __nomsg()
> until we anchor ourselves between two __msg()s. And beginning/end of
> verifier log are two other anchoring positions.

Yes, makes total sense, thank you for spotting it. I can fix this and
submit this patch as an unrelated change or just drop it, what would
you prefer?
Andrii Nakryiko Nov. 17, 2023, 8:31 p.m. UTC | #3 
On Fri, Nov 17, 2023 at 1:53 PM Eduard Zingerman <eddyz87@gmail.com> wrote:
>
> On Fri, 2023-11-17 at 11:45 -0500, Andrii Nakryiko wrote:
> [...]
> > I think this implementation has an undesired surprising behavior.
> > Imagine you have a log like this:
> >
> > A
> > C
> > D
> > B
> >
> >
> > And you specify
> >
> > __msg("A")
> > __nomsg("B")
> > __msg("C")
> > __msg("D")
> > __msg("B")
> >
> > Log matches the spec, right? But your implementation will eagerly reject it.
> >
> > I think you can implement more coherent behavior if you only strstr()
> > __msg() specs, skipping __nomsg() first. But on each __msg one, if
> > successful, you go back and validate that there are no matches for all
> > __nomsg() specs that you skipped, taking into account matched
> > positions for current __msg() and last __msg() (or the start of the
> > log, of course).
> >
> > Not sure if I explained clearly, but the idea is to postpone __nomsg()
> > until we anchor ourselves between two __msg()s. And beginning/end of
> > verifier log are two other anchoring positions.
>
> Yes, makes total sense, thank you for spotting it. I can fix this and
> submit this patch as an unrelated change or just drop it, what would
> you prefer?
>
>

I think it's useful in general, I believe I had few cases where this
would be helpful. So submitting separately makes sense. But I think
this patch set doesn't need it if we can validate logic in last patch
without relying on this feature.
Eduard Zingerman Nov. 17, 2023, 9:10 p.m. UTC | #4 
On Fri, 2023-11-17 at 15:31 -0500, Andrii Nakryiko wrote:
[...]
> > > I think this implementation has an undesired surprising behavior.
> > > Imagine you have a log like this:
> > > 
> > > A
> > > C
> > > D
> > > B
> > > 
> > > And you specify
> > > 
> > > __msg("A")
> > > __nomsg("B")
> > > __msg("C")
> > > __msg("D")
> > > __msg("B")
[...]
> I think it's useful in general, I believe I had few cases where this
> would be helpful. So submitting separately makes sense. But I think
> this patch set doesn't need it if we can validate logic in last patch
> without relying on this feature.

Ok, will do it separately. While at it can also add two more features:
- __msg_next, again mimicking FileCheck [0], which would require match to
  be on a line subsequent to previous match;
- __msg_re, with support for regular expressions (using [1]).

[0] https://llvm.org/docs/CommandGuide/FileCheck.html
[1] https://www.gnu.org/software/libc/manual/html_node/Regular-Expressions.html
Alexei Starovoitov Nov. 17, 2023, 9:33 p.m. UTC | #5 
On Fri, Nov 17, 2023 at 1:10 PM Eduard Zingerman <eddyz87@gmail.com> wrote:
>
> On Fri, 2023-11-17 at 15:31 -0500, Andrii Nakryiko wrote:
> [...]
> > > > I think this implementation has an undesired surprising behavior.
> > > > Imagine you have a log like this:
> > > >
> > > > A
> > > > C
> > > > D
> > > > B
> > > >
> > > > And you specify
> > > >
> > > > __msg("A")
> > > > __nomsg("B")
> > > > __msg("C")
> > > > __msg("D")
> > > > __msg("B")
> [...]
> > I think it's useful in general, I believe I had few cases where this
> > would be helpful. So submitting separately makes sense. But I think
> > this patch set doesn't need it if we can validate logic in last patch
> > without relying on this feature.
>
> Ok, will do it separately. While at it can also add two more features:
> - __msg_next, again mimicking FileCheck [0], which would require match to
>   be on a line subsequent to previous match;
> - __msg_re, with support for regular expressions (using [1]).
>
> [0] https://llvm.org/docs/CommandGuide/FileCheck.html
> [1] https://www.gnu.org/software/libc/manual/html_node/Regular-Expressions.html

So far this patch set didn't have conflicts with bpf-next and
we need to land it in the bpf tree and backport later,
so pls minimize the changes.
_nomsg, _msg* extensions are certainly useful, but let's add them
later via bpf-next when trees converge.
diff mbox series

Patch

diff --git a/tools/testing/selftests/bpf/progs/bpf_misc.h b/tools/testing/selftests/bpf/progs/bpf_misc.h
index 799fff4995d8..f24fcda6fc0b 100644
--- a/tools/testing/selftests/bpf/progs/bpf_misc.h
+++ b/tools/testing/selftests/bpf/progs/bpf_misc.h
@@ -22,7 +22,13 @@ 
  *
  * __msg             Message expected to be found in the verifier log.
  *                   Multiple __msg attributes could be specified.
+ *                   When multiple messages are specified they are
+ *                   matched one after another.
+ * __not_msg	     Message not expected to be found in the verifier log.
+ *                   Matched from the end of the last checked __msg or
+ *                   from log start, if no __msg had been matched yet.
  * __msg_unpriv      Same as __msg but for unprivileged mode.
+ * __not_msg_unpriv  Same as __not_msg but for unprivileged mode.
  *
  * __success         Expect program load success in privileged mode.
  * __success_unpriv  Expect program load success in unprivileged mode.
@@ -59,10 +65,13 @@ 
  * __auxiliary_unpriv  Same, but load program in unprivileged mode.
  */
 #define __msg(msg)		__attribute__((btf_decl_tag("comment:test_expect_msg=" msg)))
+#define __not_msg(msg)		__attribute__((btf_decl_tag("comment:test_dont_expect_msg=" msg)))
 #define __failure		__attribute__((btf_decl_tag("comment:test_expect_failure")))
 #define __success		__attribute__((btf_decl_tag("comment:test_expect_success")))
 #define __description(desc)	__attribute__((btf_decl_tag("comment:test_description=" desc)))
 #define __msg_unpriv(msg)	__attribute__((btf_decl_tag("comment:test_expect_msg_unpriv=" msg)))
+#define __not_msg_unpriv(msg)						\
+	__attribute__((btf_decl_tag("comment:test_dont_expect_msg_unpriv=" msg)))
 #define __failure_unpriv	__attribute__((btf_decl_tag("comment:test_expect_failure_unpriv")))
 #define __success_unpriv	__attribute__((btf_decl_tag("comment:test_expect_success_unpriv")))
 #define __log_level(lvl)	__attribute__((btf_decl_tag("comment:test_log_level="#lvl)))
diff --git a/tools/testing/selftests/bpf/test_loader.c b/tools/testing/selftests/bpf/test_loader.c
index 37ffa57f28a1..def16d9aeae2 100644
--- a/tools/testing/selftests/bpf/test_loader.c
+++ b/tools/testing/selftests/bpf/test_loader.c
@@ -17,9 +17,11 @@ 
 #define TEST_TAG_EXPECT_FAILURE "comment:test_expect_failure"
 #define TEST_TAG_EXPECT_SUCCESS "comment:test_expect_success"
 #define TEST_TAG_EXPECT_MSG_PFX "comment:test_expect_msg="
+#define TEST_TAG_DONT_EXPECT_MSG_PFX "comment:test_dont_expect_msg="
 #define TEST_TAG_EXPECT_FAILURE_UNPRIV "comment:test_expect_failure_unpriv"
 #define TEST_TAG_EXPECT_SUCCESS_UNPRIV "comment:test_expect_success_unpriv"
 #define TEST_TAG_EXPECT_MSG_PFX_UNPRIV "comment:test_expect_msg_unpriv="
+#define TEST_TAG_DONT_EXPECT_MSG_PFX_UNPRIV "comment:test_dont_expect_msg_unpriv="
 #define TEST_TAG_LOG_LEVEL_PFX "comment:test_log_level="
 #define TEST_TAG_PROG_FLAGS_PFX "comment:test_prog_flags="
 #define TEST_TAG_DESCRIPTION_PFX "comment:test_description="
@@ -45,10 +47,15 @@  enum mode {
 	UNPRIV = 2
 };
 
+struct pattern {
+	const char *str;
+	bool expected;
+};
+
 struct test_subspec {
 	char *name;
 	bool expect_failure;
-	const char **expect_msgs;
+	struct pattern *expect_msgs;
 	size_t expect_msg_cnt;
 	int retval;
 	bool execute;
@@ -98,17 +105,21 @@  static void free_test_spec(struct test_spec *spec)
 	spec->unpriv.expect_msgs = NULL;
 }
 
-static int push_msg(const char *msg, struct test_subspec *subspec)
+static int push_msg(const char *msg, struct test_subspec *subspec, bool expected)
 {
+	size_t cnt = subspec->expect_msg_cnt;
 	void *tmp;
 
-	tmp = realloc(subspec->expect_msgs, (1 + subspec->expect_msg_cnt) * sizeof(void *));
+	tmp = realloc(subspec->expect_msgs,
+		      (1 + subspec->expect_msg_cnt) * sizeof(*subspec->expect_msgs));
 	if (!tmp) {
 		ASSERT_FAIL("failed to realloc memory for messages\n");
 		return -ENOMEM;
 	}
 	subspec->expect_msgs = tmp;
-	subspec->expect_msgs[subspec->expect_msg_cnt++] = msg;
+	subspec->expect_msgs[cnt].str = msg;
+	subspec->expect_msgs[cnt].expected = expected;
+	subspec->expect_msg_cnt++;
 
 	return 0;
 }
@@ -221,13 +232,25 @@  static int parse_test_spec(struct test_loader *tester,
 			spec->mode_mask |= UNPRIV;
 		} else if (str_has_pfx(s, TEST_TAG_EXPECT_MSG_PFX)) {
 			msg = s + sizeof(TEST_TAG_EXPECT_MSG_PFX) - 1;
-			err = push_msg(msg, &spec->priv);
+			err = push_msg(msg, &spec->priv, true);
 			if (err)
 				goto cleanup;
 			spec->mode_mask |= PRIV;
 		} else if (str_has_pfx(s, TEST_TAG_EXPECT_MSG_PFX_UNPRIV)) {
 			msg = s + sizeof(TEST_TAG_EXPECT_MSG_PFX_UNPRIV) - 1;
-			err = push_msg(msg, &spec->unpriv);
+			err = push_msg(msg, &spec->unpriv, true);
+			if (err)
+				goto cleanup;
+			spec->mode_mask |= UNPRIV;
+		} else if (str_has_pfx(s, TEST_TAG_DONT_EXPECT_MSG_PFX)) {
+			msg = s + sizeof(TEST_TAG_DONT_EXPECT_MSG_PFX) - 1;
+			err = push_msg(msg, &spec->priv, false);
+			if (err)
+				goto cleanup;
+			spec->mode_mask |= PRIV;
+		} else if (str_has_pfx(s, TEST_TAG_DONT_EXPECT_MSG_PFX_UNPRIV)) {
+			msg = s + sizeof(TEST_TAG_DONT_EXPECT_MSG_PFX_UNPRIV) - 1;
+			err = push_msg(msg, &spec->unpriv, false);
 			if (err)
 				goto cleanup;
 			spec->mode_mask |= UNPRIV;
@@ -316,7 +339,7 @@  static int parse_test_spec(struct test_loader *tester,
 		}
 
 		if (!spec->unpriv.expect_msgs) {
-			size_t sz = spec->priv.expect_msg_cnt * sizeof(void *);
+			size_t sz = spec->priv.expect_msg_cnt * sizeof(*spec->priv.expect_msgs);
 
 			spec->unpriv.expect_msgs = malloc(sz);
 			if (!spec->unpriv.expect_msgs) {
@@ -375,33 +398,46 @@  static void emit_verifier_log(const char *log_buf, bool force)
 	fprintf(stdout, "VERIFIER LOG:\n=============\n%s=============\n", log_buf);
 }
 
+static void show_log_and_msgs(struct test_loader *tester, struct test_subspec *subspec, int n)
+{
+	struct pattern *pat;
+	int i;
+
+	if (env.verbosity == VERBOSE_NONE)
+		emit_verifier_log(tester->log_buf, true /*force*/);
+	for (i = 0; i < n; i++) {
+		pat = &subspec->expect_msgs[i];
+		fprintf(stderr, "   MATCHED MSG: %s'%s'\n", pat->expected ? "" : "!", pat->str);
+	}
+}
+
 static void validate_case(struct test_loader *tester,
 			  struct test_subspec *subspec,
 			  struct bpf_object *obj,
 			  struct bpf_program *prog,
 			  int load_err)
 {
-	int i, j;
+	int i;
 
 	for (i = 0; i < subspec->expect_msg_cnt; i++) {
+		struct pattern *pat = &subspec->expect_msgs[i];
 		char *match;
-		const char *expect_msg;
-
-		expect_msg = subspec->expect_msgs[i];
-
-		match = strstr(tester->log_buf + tester->next_match_pos, expect_msg);
-		if (!ASSERT_OK_PTR(match, "expect_msg")) {
-			/* if we are in verbose mode, we've already emitted log */
-			if (env.verbosity == VERBOSE_NONE)
-				emit_verifier_log(tester->log_buf, true /*force*/);
-			for (j = 0; j < i; j++)
-				fprintf(stderr,
-					"MATCHED  MSG: '%s'\n", subspec->expect_msgs[j]);
-			fprintf(stderr, "EXPECTED MSG: '%s'\n", expect_msg);
+
+		match = strstr(tester->log_buf + tester->next_match_pos, pat->str);
+		if (pat->expected && !match) {
+			PRINT_FAIL("Expected log message not found\n");
+			show_log_and_msgs(tester, subspec, i);
+			fprintf(stderr, "  EXPECTED MSG: '%s'\n", pat->str);
 			return;
 		}
-
-		tester->next_match_pos = match - tester->log_buf + strlen(expect_msg);
+		if (!pat->expected && match) {
+			PRINT_FAIL("Unexpected log message found\n");
+			show_log_and_msgs(tester, subspec, i);
+			fprintf(stderr, "UNEXPECTED MSG: '%s'\n", pat->str);
+			return;
+		}
+		if (pat->expected)
+			tester->next_match_pos = match - tester->log_buf + strlen(pat->str);
 	}
 }