[PATCH] kasan: test: Improve failure message in KUNIT_EXPECT_KASAN_FAIL()

7 views
Skip to first unread message

David Gow

unread,
Jun 4, 2021, 1:26:02 AMJun 4
to Andrey Ryabinin, Dmitry Vyukov, Daniel Axtens, Brendan Higgins, David Gow, kasa...@googlegroups.com, kuni...@googlegroups.com, linux-...@vger.kernel.org
The KUNIT_EXPECT_KASAN_FAIL() macro currently uses KUNIT_EXPECT_EQ() to
compare fail_data.report_expected and fail_data.report_found. This
always gave a somewhat useless error message on failure, but the
addition of extra compile-time checking with READ_ONCE() has caused it
to get much longer, and be truncated before anything useful is displayed.

Instead, just check fail_data.report_found by hand (we've just test
report_expected to 'true'), and print a better failure message with
KUNIT_FAIL()

Beforehand, a failure in:
KUNIT_EXPECT_KASAN_FAIL(test, ((volatile char *)area)[3100]);
would looked like:
[22:00:34] [FAILED] vmalloc_oob
[22:00:34] # vmalloc_oob: EXPECTATION FAILED at lib/test_kasan.c:991
[22:00:34] Expected ({ do { extern void __compiletime_assert_705(void) __attribute__((__error__("Unsupported access size for {READ,WRITE}_ONCE()."))); if (!((sizeof(fail_data.report_expected) == sizeof(char) || sizeof(fail_data.repp
[22:00:34] not ok 45 - vmalloc_oob

With this change, it instead looks like:
[22:04:04] [FAILED] vmalloc_oob
[22:04:04] # vmalloc_oob: EXPECTATION FAILED at lib/test_kasan.c:993
[22:04:04] KASAN failure expected in "((volatile char *)area)[3100]", but none occurred
[22:04:04] not ok 45 - vmalloc_oob

Signed-off-by: David Gow <davi...@google.com>
---

Stumbled across this because the vmalloc_oob test is failing (i.e.,
KASAN isn't picking up an error) under qemu on my system, and the
message above was horrifying. (I'll file a Bugzilla bug for the test
failure today.)

Cheers,
-- David

lib/test_kasan.c | 8 +++++---
1 file changed, 5 insertions(+), 3 deletions(-)

diff --git a/lib/test_kasan.c b/lib/test_kasan.c
index cacbbbdef768..deda13c9d9ff 100644
--- a/lib/test_kasan.c
+++ b/lib/test_kasan.c
@@ -98,9 +98,11 @@ static void kasan_test_exit(struct kunit *test)
barrier(); \
expression; \
barrier(); \
- KUNIT_EXPECT_EQ(test, \
- READ_ONCE(fail_data.report_expected), \
- READ_ONCE(fail_data.report_found)); \
+ if (READ_ONCE(fail_data.report_found) == false) { \
+ KUNIT_FAIL(test, KUNIT_SUBTEST_INDENT "KASAN failure " \
+ "expected in \"" #expression \
+ "\", but none occurred"); \
+ } \
if (IS_ENABLED(CONFIG_KASAN_HW_TAGS)) { \
if (READ_ONCE(fail_data.report_found)) \
kasan_enable_tagging_sync(); \
--
2.32.0.rc1.229.g3e70b5a671-goog

Marco Elver

unread,
Jun 4, 2021, 3:55:21 AMJun 4
to David Gow, Andrey Ryabinin, Dmitry Vyukov, Daniel Axtens, Brendan Higgins, kasan-dev, KUnit Development, LKML
What do we have fail_data.report_expected for? Could we remove it now?
I think it's unused now.

> - READ_ONCE(fail_data.report_found)); \
> + if (READ_ONCE(fail_data.report_found) == false) { \

if (!READ_ONCE(fail_data.report_found)) {
?

> + KUNIT_FAIL(test, KUNIT_SUBTEST_INDENT "KASAN failure " \
> + "expected in \"" #expression \
> + "\", but none occurred"); \
> + } \

Thanks,
-- Marco

David Gow

unread,
Jun 4, 2021, 4:34:13 AMJun 4
to Marco Elver, Andrey Ryabinin, Dmitry Vyukov, Daniel Axtens, Brendan Higgins, kasan-dev, KUnit Development, LKML
I thought this was being used in kasan_update_kunit_status() (in
mm/kasan/report.c), but it looks like I was mistaken. We should be
able to get rid of it, then/

> > - READ_ONCE(fail_data.report_found)); \
> > + if (READ_ONCE(fail_data.report_found) == false) { \
>
> if (!READ_ONCE(fail_data.report_found)) {
> ?
>

I'll change this for v2.

David Gow

unread,
Jun 4, 2021, 11:48:28 PMJun 4
to Andrey Ryabinin, Dmitry Vyukov, Daniel Axtens, Brendan Higgins, David Gow, kasa...@googlegroups.com, kuni...@googlegroups.com, linux-...@vger.kernel.org
The KUNIT_EXPECT_KASAN_FAIL() macro currently uses KUNIT_EXPECT_EQ() to
compare fail_data.report_expected and fail_data.report_found. This
always gave a somewhat useless error message on failure, but the
addition of extra compile-time checking with READ_ONCE() has caused it
to get much longer, and be truncated before anything useful is displayed.

Instead, just check fail_data.report_found by hand (we've just set
report_expected to 'true'), and print a better failure message with
KUNIT_FAIL(). Because of this, report_expected is no longer used
anywhere, and can be removed.

Beforehand, a failure in:
KUNIT_EXPECT_KASAN_FAIL(test, ((volatile char *)area)[3100]);
would have looked like:
[22:00:34] [FAILED] vmalloc_oob
[22:00:34] # vmalloc_oob: EXPECTATION FAILED at lib/test_kasan.c:991
[22:00:34] Expected ({ do { extern void __compiletime_assert_705(void) __attribute__((__error__("Unsupported access size for {READ,WRITE}_ONCE()."))); if (!((sizeof(fail_data.report_expected) == sizeof(char) || sizeof(fail_data.repp
[22:00:34] not ok 45 - vmalloc_oob

With this change, it instead looks like:
[22:04:04] [FAILED] vmalloc_oob
[22:04:04] # vmalloc_oob: EXPECTATION FAILED at lib/test_kasan.c:993
[22:04:04] KASAN failure expected in "((volatile char *)area)[3100]", but none occurred
[22:04:04] not ok 45 - vmalloc_oob

Signed-off-by: David Gow <davi...@google.com>
---
Changes since v1:
https://groups.google.com/g/kasan-dev/c/CbabdwoXGlE
- Remove fail_data.report_expected now that it's unused.
- Use '!' instead of '== false' in the comparison.
- Minor typo fixes in the commit message.

The test failure being used as an example is tracked in:
https://bugzilla.kernel.org/show_bug.cgi?id=213335

Cheers,
-- David

include/linux/kasan.h | 1 -
lib/test_kasan.c | 11 +++++------
2 files changed, 5 insertions(+), 7 deletions(-)

diff --git a/include/linux/kasan.h b/include/linux/kasan.h
index b1678a61e6a7..18cd5ec2f469 100644
--- a/include/linux/kasan.h
+++ b/include/linux/kasan.h
@@ -17,7 +17,6 @@ struct task_struct;

/* kasan_data struct is used in KUnit tests for KASAN expected failures */
struct kunit_kasan_expectation {
- bool report_expected;
bool report_found;
};

diff --git a/lib/test_kasan.c b/lib/test_kasan.c
index cacbbbdef768..44e08f4d9c52 100644
--- a/lib/test_kasan.c
+++ b/lib/test_kasan.c
@@ -55,7 +55,6 @@ static int kasan_test_init(struct kunit *test)
multishot = kasan_save_enable_multi_shot();
kasan_set_tagging_report_once(false);
fail_data.report_found = false;
- fail_data.report_expected = false;
kunit_add_named_resource(test, NULL, NULL, &resource,
"kasan_data", &fail_data);
return 0;
@@ -94,20 +93,20 @@ static void kasan_test_exit(struct kunit *test)
!kasan_async_mode_enabled()) \
migrate_disable(); \
KUNIT_EXPECT_FALSE(test, READ_ONCE(fail_data.report_found)); \
- WRITE_ONCE(fail_data.report_expected, true); \
barrier(); \
expression; \
barrier(); \
- KUNIT_EXPECT_EQ(test, \
- READ_ONCE(fail_data.report_expected), \
- READ_ONCE(fail_data.report_found)); \
+ if (!READ_ONCE(fail_data.report_found)) { \
+ KUNIT_FAIL(test, KUNIT_SUBTEST_INDENT "KASAN failure " \
+ "expected in \"" #expression \
+ "\", but none occurred"); \
+ } \
if (IS_ENABLED(CONFIG_KASAN_HW_TAGS)) { \
if (READ_ONCE(fail_data.report_found)) \
kasan_enable_tagging_sync(); \
migrate_enable(); \
} \
WRITE_ONCE(fail_data.report_found, false); \
- WRITE_ONCE(fail_data.report_expected, false); \
} while (0)

#define KASAN_TEST_NEEDS_CONFIG_ON(test, config) do { \
--
2.32.0.rc1.229.g3e70b5a671-goog

Andrey Konovalov

unread,
Jun 5, 2021, 7:25:25 PMJun 5
to David Gow, Andrey Ryabinin, Dmitry Vyukov, Daniel Axtens, Brendan Higgins, kasan-dev, kuni...@googlegroups.com, LKML
On Sat, Jun 5, 2021 at 6:48 AM 'David Gow' via kasan-dev
<kasa...@googlegroups.com> wrote:
>
> The KUNIT_EXPECT_KASAN_FAIL() macro currently uses KUNIT_EXPECT_EQ() to
> compare fail_data.report_expected and fail_data.report_found. This
> always gave a somewhat useless error message on failure, but the
> addition of extra compile-time checking with READ_ONCE() has caused it
> to get much longer, and be truncated before anything useful is displayed.
>
> Instead, just check fail_data.report_found by hand (we've just set
> report_expected to 'true'), and print a better failure message with
> KUNIT_FAIL(). Because of this, report_expected is no longer used
> anywhere, and can be removed.
>
> Beforehand, a failure in:
> KUNIT_EXPECT_KASAN_FAIL(test, ((volatile char *)area)[3100]);
> would have looked like:
> [22:00:34] [FAILED] vmalloc_oob
> [22:00:34] # vmalloc_oob: EXPECTATION FAILED at lib/test_kasan.c:991
> [22:00:34] Expected ({ do { extern void __compiletime_assert_705(void) __attribute__((__error__("Unsupported access size for {READ,WRITE}_ONCE()."))); if (!((sizeof(fail_data.report_expected) == sizeof(char) || sizeof(fail_data.repp
> [22:00:34] not ok 45 - vmalloc_oob
>
> With this change, it instead looks like:
> [22:04:04] [FAILED] vmalloc_oob
> [22:04:04] # vmalloc_oob: EXPECTATION FAILED at lib/test_kasan.c:993
> [22:04:04] KASAN failure expected in "((volatile char *)area)[3100]", but none occurred
> [22:04:04] not ok 45 - vmalloc_oob
>
> Signed-off-by: David Gow <davi...@google.com>

Hi David,

Please also update the failure message in Documentation/dev-tools/kasan.rst.

Thank you!
> --
> You received this message because you are subscribed to the Google Groups "kasan-dev" group.
> To unsubscribe from this group and stop receiving emails from it, send an email to kasan-dev+...@googlegroups.com.
> To view this discussion on the web visit https://groups.google.com/d/msgid/kasan-dev/20210605034821.2098034-1-davidgow%40google.com.

David Gow

unread,
Jun 5, 2021, 8:55:36 PMJun 5
to Andrey Ryabinin, Dmitry Vyukov, Daniel Axtens, Brendan Higgins, David Gow, kasa...@googlegroups.com, kuni...@googlegroups.com, linux-...@vger.kernel.org, Jonathan Corbet, linu...@vger.kernel.org
The KUNIT_EXPECT_KASAN_FAIL() macro currently uses KUNIT_EXPECT_EQ() to
compare fail_data.report_expected and fail_data.report_found. This
always gave a somewhat useless error message on failure, but the
addition of extra compile-time checking with READ_ONCE() has caused it
to get much longer, and be truncated before anything useful is displayed.

Instead, just check fail_data.report_found by hand (we've just set
report_expected to 'true'), and print a better failure message with
KUNIT_FAIL(). Because of this, report_expected is no longer used
anywhere, and can be removed.

Beforehand, a failure in:
KUNIT_EXPECT_KASAN_FAIL(test, ((volatile char *)area)[3100]);
would have looked like:
[22:00:34] [FAILED] vmalloc_oob
[22:00:34] # vmalloc_oob: EXPECTATION FAILED at lib/test_kasan.c:991
[22:00:34] Expected ({ do { extern void __compiletime_assert_705(void) __attribute__((__error__("Unsupported access size for {READ,WRITE}_ONCE()."))); if (!((sizeof(fail_data.report_expected) == sizeof(char) || sizeof(fail_data.repp
[22:00:34] not ok 45 - vmalloc_oob

With this change, it instead looks like:
[22:04:04] [FAILED] vmalloc_oob
[22:04:04] # vmalloc_oob: EXPECTATION FAILED at lib/test_kasan.c:993
[22:04:04] KASAN failure expected in "((volatile char *)area)[3100]", but none occurred
[22:04:04] not ok 45 - vmalloc_oob

Also update the example failure in the documentation to reflect this.

Signed-off-by: David Gow <davi...@google.com>
---

Changes since v2:
https://lkml.org/lkml/2021/6/4/1264
- Update the example error in the documentation

Changes since v1:
https://groups.google.com/g/kasan-dev/c/CbabdwoXGlE
- Remove fail_data.report_expected now that it's unused.
- Use '!' instead of '== false' in the comparison.
- Minor typo fixes in the commit message.

The test failure being used as an example is tracked in:
https://bugzilla.kernel.org/show_bug.cgi?id=213335



Documentation/dev-tools/kasan.rst | 9 ++++-----
include/linux/kasan.h | 1 -
lib/test_kasan.c | 11 +++++------
3 files changed, 9 insertions(+), 12 deletions(-)

diff --git a/Documentation/dev-tools/kasan.rst b/Documentation/dev-tools/kasan.rst
index d3f335ffc751..83ec4a556c19 100644
--- a/Documentation/dev-tools/kasan.rst
+++ b/Documentation/dev-tools/kasan.rst
@@ -447,11 +447,10 @@ When a test fails due to a failed ``kmalloc``::

When a test fails due to a missing KASAN report::

- # kmalloc_double_kzfree: EXPECTATION FAILED at lib/test_kasan.c:629
- Expected kasan_data->report_expected == kasan_data->report_found, but
- kasan_data->report_expected == 1
- kasan_data->report_found == 0
- not ok 28 - kmalloc_double_kzfree
+ # kmalloc_double_kzfree: EXPECTATION FAILED at lib/test_kasan.c:974
+ KASAN failure expected in "kfree_sensitive(ptr)", but none occurred
+ not ok 44 - kmalloc_double_kzfree
+

At the end the cumulative status of all KASAN tests is printed. On success::

Andrey Konovalov

unread,
Jun 6, 2021, 5:57:06 AMJun 6
to David Gow, Andrey Ryabinin, Dmitry Vyukov, Daniel Axtens, Brendan Higgins, kasan-dev, kuni...@googlegroups.com, LKML, Jonathan Corbet, open list:DOCUMENTATION
Reviewed-by: Andrey Konovalov <andre...@gmail.com>

Thanks!

Marco Elver

unread,
Jun 7, 2021, 5:15:50 AMJun 7
to Andrey Konovalov, David Gow, Andrey Ryabinin, Dmitry Vyukov, Daniel Axtens, Brendan Higgins, kasan-dev, KUnit Development, LKML, Jonathan Corbet, open list:DOCUMENTATION, Andrew Morton
Reviewed-by: Marco Elver <el...@google.com>

Brendan Higgins

unread,
Jun 7, 2021, 4:02:51 PMJun 7
to David Gow, Andrey Ryabinin, Dmitry Vyukov, Daniel Axtens, kasan-dev, KUnit Development, Linux Kernel Mailing List, Jonathan Corbet, open list:DOCUMENTATION
On Sat, Jun 5, 2021 at 5:55 PM David Gow <davi...@google.com> wrote:
>
> The KUNIT_EXPECT_KASAN_FAIL() macro currently uses KUNIT_EXPECT_EQ() to
> compare fail_data.report_expected and fail_data.report_found. This
> always gave a somewhat useless error message on failure, but the
> addition of extra compile-time checking with READ_ONCE() has caused it
> to get much longer, and be truncated before anything useful is displayed.
>
> Instead, just check fail_data.report_found by hand (we've just set
> report_expected to 'true'), and print a better failure message with
> KUNIT_FAIL(). Because of this, report_expected is no longer used
> anywhere, and can be removed.
>
> Beforehand, a failure in:
> KUNIT_EXPECT_KASAN_FAIL(test, ((volatile char *)area)[3100]);
> would have looked like:
> [22:00:34] [FAILED] vmalloc_oob
> [22:00:34] # vmalloc_oob: EXPECTATION FAILED at lib/test_kasan.c:991
> [22:00:34] Expected ({ do { extern void __compiletime_assert_705(void) __attribute__((__error__("Unsupported access size for {READ,WRITE}_ONCE()."))); if (!((sizeof(fail_data.report_expected) == sizeof(char) || sizeof(fail_data.repp
> [22:00:34] not ok 45 - vmalloc_oob
>
> With this change, it instead looks like:
> [22:04:04] [FAILED] vmalloc_oob
> [22:04:04] # vmalloc_oob: EXPECTATION FAILED at lib/test_kasan.c:993
> [22:04:04] KASAN failure expected in "((volatile char *)area)[3100]", but none occurred
> [22:04:04] not ok 45 - vmalloc_oob
>
> Also update the example failure in the documentation to reflect this.
>
> Signed-off-by: David Gow <davi...@google.com>

Nice work!

Acked-by: Brendan Higgins <brendan...@google.com>
Reply all
Reply to author
Forward
0 new messages