Re: [PATCH 4/7] of: unittest: add node lifecycle tests

From: Guenter Roeck
Date: Sat Feb 25 2023 - 19:07:52 EST

Next message: Abhinav Kumar: "Re: [RFC PATCH 1/2] drm/msm/dpu: add dsc helper functions"
Previous message: Yury Norov: "Re: [PATCH 3/5] lib/bitmap: add test for bitmap_{from,to}_arr64"
Next in thread: Frank Rowand: "Re: [PATCH 4/7] of: unittest: add node lifecycle tests"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]

On Mon, Feb 13, 2023 at 12:56:59PM -0600, Frank Rowand wrote:
> Add tests to exercise the actions that occur when the reference count
> of devicetree nodes decrement to zero and beyond. Decrementing to
> zero triggers freeing memory allocated for the node.
>
> This commit will expose a pr_err() issue in of_node_release(), resulting
> in some kernal warnings and stack traces.
>
> When scripts/dtc/of_unittest_expect processes the console messages,
> it will also report related problems for EXPECT messages due to the
> pr_err() issue:
> ** missing EXPECT begin : 5
> Signed-off-by: Frank Rowand <frowand.list@xxxxxxxxx>
> ---
>
> There are checkpatch warnings. I have reviewed them and feel
> they can be ignored.
>
> Stack traces from the pr_err() issue:
>

Unfortunately my test beds trigger a warning if they encounter a backtrace
in a log. Trying to implement workarounds would be just too time consuming,
so I had to disable OF_UNITTEST in my boot tests as consequence of this
patch.

Guenter

> ------------[ cut here ]------------
> WARNING: CPU: 0 PID: 1 at lib/refcount.c:25 kobject_get+0xa0/0xa4
> refcount_t: addition on 0; use-after-free.
> Modules linked in:
> CPU: 0 PID: 1 Comm: swapper/0 Tainted: G N 6.2.0-rc1-00005-g774057a35a67 #21
> Hardware name: Generic DT based system
> unwind_backtrace from show_stack+0x10/0x14
> show_stack from dump_stack_lvl+0x40/0x4c
> dump_stack_lvl from __warn+0x7c/0x15c
> __warn from warn_slowpath_fmt+0x98/0xcc
> warn_slowpath_fmt from kobject_get+0xa0/0xa4
> kobject_get from of_node_get+0x14/0x1c
> of_node_get from of_fwnode_get+0x34/0x40
> of_fwnode_get from fwnode_full_name_string+0x34/0xa0
> fwnode_full_name_string from device_node_string+0x4dc/0x4f4
> device_node_string from pointer+0x364/0x598
> pointer from vsnprintf+0x1f8/0x3d0
> vsnprintf from vprintk_store+0x134/0x410
> vprintk_store from vprintk_emit+0x6c/0x234
> vprintk_emit from vprintk_default+0x20/0x28
> vprintk_default from _printk+0x30/0x60
> _printk from of_node_release+0xb0/0xf4
> of_node_release from kobject_put+0xc4/0x29c
> kobject_put from of_unittest+0x256c/0x2eb8
> of_unittest from do_one_initcall+0x4c/0x268
> do_one_initcall from kernel_init_freeable+0x1b4/0x214
> kernel_init_freeable from kernel_init+0x18/0x130
> kernel_init from ret_from_fork+0x14/0x2c
> Exception stack(0xf0821fb0 to 0xf0821ff8)
> 1fa0: 00000000 00000000 00000000 00000000
> 1fc0: 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
> 1fe0: 00000000 00000000 00000000 00000000 00000013 00000000
> ---[ end trace 0000000000000000 ]---
> ------------[ cut here ]------------
> WARNING: CPU: 0 PID: 1 at lib/refcount.c:28 fwnode_full_name_string+0x8c/0xa0
> refcount_t: underflow; use-after-free.
> Modules linked in:
> CPU: 0 PID: 1 Comm: swapper/0 Tainted: G W N 6.2.0-rc1-00005-g774057a35a67 #21
> Hardware name: Generic DT based system
> unwind_backtrace from show_stack+0x10/0x14
> show_stack from dump_stack_lvl+0x40/0x4c
> dump_stack_lvl from __warn+0x7c/0x15c
> __warn from warn_slowpath_fmt+0x98/0xcc
> warn_slowpath_fmt from fwnode_full_name_string+0x8c/0xa0
> fwnode_full_name_string from device_node_string+0x4dc/0x4f4
> device_node_string from pointer+0x364/0x598
> pointer from vsnprintf+0x1f8/0x3d0
> vsnprintf from vprintk_store+0x134/0x410
> vprintk_store from vprintk_emit+0x6c/0x234
> vprintk_emit from vprintk_default+0x20/0x28
> vprintk_default from _printk+0x30/0x60
> _printk from of_node_release+0xb0/0xf4
> of_node_release from kobject_put+0xc4/0x29c
> kobject_put from of_unittest+0x256c/0x2eb8
> of_unittest from do_one_initcall+0x4c/0x268
> do_one_initcall from kernel_init_freeable+0x1b4/0x214
> kernel_init_freeable from kernel_init+0x18/0x130
> kernel_init from ret_from_fork+0x14/0x2c
> Exception stack(0xf0821fb0 to 0xf0821ff8)
> 1fa0: 00000000 00000000 00000000 00000000
> 1fc0: 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
> 1fe0: 00000000 00000000 00000000 00000000 00000013 00000000
> ---[ end trace 0000000000000000 ]---
> ------------[ cut here ]------------
> WARNING: CPU: 0 PID: 1 at lib/refcount.c:22 kobject_get+0x8c/0xa4
> refcount_t: saturated; leaking memory.
> Modules linked in:
> CPU: 0 PID: 1 Comm: swapper/0 Tainted: G W N 6.2.0-rc1-00005-g774057a35a67 #21
> Hardware name: Generic DT based system
> unwind_backtrace from show_stack+0x10/0x14
> show_stack from dump_stack_lvl+0x40/0x4c
> dump_stack_lvl from __warn+0x7c/0x15c
> __warn from warn_slowpath_fmt+0x98/0xcc
> warn_slowpath_fmt from kobject_get+0x8c/0xa4
> kobject_get from of_node_get+0x14/0x1c
> of_node_get from of_fwnode_get+0x34/0x40
> of_fwnode_get from fwnode_full_name_string+0x34/0xa0
> fwnode_full_name_string from device_node_string+0x4dc/0x4f4
> device_node_string from pointer+0x364/0x598
> pointer from vsnprintf+0x1f8/0x3d0
> vsnprintf from vscnprintf+0x10/0x24
> vscnprintf from printk_sprint+0x18/0x194
> printk_sprint from vprintk_store+0x378/0x410
> vprintk_store from vprintk_emit+0x6c/0x234
> vprintk_emit from vprintk_default+0x20/0x28
> vprintk_default from _printk+0x30/0x60
> _printk from of_node_release+0xb0/0xf4
> of_node_release from kobject_put+0xc4/0x29c
> kobject_put from of_unittest+0x256c/0x2eb8
> of_unittest from do_one_initcall+0x4c/0x268
> do_one_initcall from kernel_init_freeable+0x1b4/0x214
> kernel_init_freeable from kernel_init+0x18/0x130
> kernel_init from ret_from_fork+0x14/0x2c
> Exception stack(0xf0821fb0 to 0xf0821ff8)
> 1fa0: 00000000 00000000 00000000 00000000
> 1fc0: 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
> 1fe0: 00000000 00000000 00000000 00000000 00000013 00000000
> ---[ end trace 0000000000000000 ]---
>
>
> drivers/of/dynamic.c | 14 +-
> .../of/unittest-data/testcases_common.dtsi | 1 +
> drivers/of/unittest-data/tests-lifecycle.dtsi | 8 +
> drivers/of/unittest.c | 148 +++++++++++++++++-
> 4 files changed, 168 insertions(+), 3 deletions(-)
> create mode 100644 drivers/of/unittest-data/tests-lifecycle.dtsi
>
> diff --git a/drivers/of/dynamic.c b/drivers/of/dynamic.c
> index cd3821a6444f..becb80f762c8 100644
> --- a/drivers/of/dynamic.c
> +++ b/drivers/of/dynamic.c
> @@ -332,7 +332,19 @@ void of_node_release(struct kobject *kobj)
> /* We should never be releasing nodes that haven't been detached. */
> if (!of_node_check_flag(node, OF_DETACHED)) {
> pr_err("ERROR: Bad of_node_put() on %pOF\n", node);
> - dump_stack();
> +
> + /*
> + * of unittests will test this path. Do not print the stack
> + * trace when the error is caused by unittest so that we do
> + * not display what a normal developer might reasonably
> + * consider a real bug.
> + */
> + if (!IS_ENABLED(CONFIG_OF_UNITTEST) ||
> + strcmp(node->parent->full_name, "testcase-data")) {
> + dump_stack();
> + pr_err("ERROR: next of_node_put() on this node will result in a kboject warning 'refcount_t: underflow; use-after-free.'\n");
> + }
> +
> return;
> }
> if (!of_node_check_flag(node, OF_DYNAMIC))
> diff --git a/drivers/of/unittest-data/testcases_common.dtsi b/drivers/of/unittest-data/testcases_common.dtsi
> index 19292bbb4cbb..e7887f2301c1 100644
> --- a/drivers/of/unittest-data/testcases_common.dtsi
> +++ b/drivers/of/unittest-data/testcases_common.dtsi
> @@ -17,3 +17,4 @@ node-remove {
> #include "tests-address.dtsi"
> #include "tests-platform.dtsi"
> #include "tests-overlay.dtsi"
> +#include "tests-lifecycle.dtsi"
> diff --git a/drivers/of/unittest-data/tests-lifecycle.dtsi b/drivers/of/unittest-data/tests-lifecycle.dtsi
> new file mode 100644
> index 000000000000..28509a8783a7
> --- /dev/null
> +++ b/drivers/of/unittest-data/tests-lifecycle.dtsi
> @@ -0,0 +1,8 @@
> +// SPDX-License-Identifier: GPL-2.0
> +
> +/ {
> + testcase-data {
> + refcount-node {
> + };
> + };
> +};
> diff --git a/drivers/of/unittest.c b/drivers/of/unittest.c
> index bc0f1e50a4be..db72e208819c 100644
> --- a/drivers/of/unittest.c
> +++ b/drivers/of/unittest.c
> @@ -54,8 +54,9 @@ static struct unittest_results {
> * Print the expected message only if the current loglevel will allow
> * the actual message to print.
> *
> - * Do not use EXPECT_BEGIN() or EXPECT_END() for messages generated by
> - * pr_debug().
> + * Do not use EXPECT_BEGIN(), EXPECT_END(), EXPECT_NOT_BEGIN(), or
> + * EXPECT_NOT_END() to report messages expected to be reported or not
> + * reported by pr_debug().
> */
> #define EXPECT_BEGIN(level, fmt, ...) \
> printk(level pr_fmt("EXPECT \\ : ") fmt, ##__VA_ARGS__)
> @@ -63,6 +64,12 @@ static struct unittest_results {
> #define EXPECT_END(level, fmt, ...) \
> printk(level pr_fmt("EXPECT / : ") fmt, ##__VA_ARGS__)
>
> +#define EXPECT_NOT_BEGIN(level, fmt, ...) \
> + printk(level pr_fmt("EXPECT_NOT \\ : ") fmt, ##__VA_ARGS__)
> +
> +#define EXPECT_NOT_END(level, fmt, ...) \
> + printk(level pr_fmt("EXPECT_NOT / : ") fmt, ##__VA_ARGS__)
> +
> static void __init of_unittest_find_node_by_name(void)
> {
> struct device_node *np;
> @@ -1488,6 +1495,7 @@ static int __init unittest_data_add(void)
> struct device_node *next = np->sibling;
>
> np->parent = of_root;
> + /* this will clear OF_DETACHED in np and children */
> attach_node_and_children(np);
> np = next;
> }
> @@ -2998,6 +3006,141 @@ static void __init of_unittest_overlay(void)
> static inline void __init of_unittest_overlay(void) { }
> #endif
>
> +static void __init of_unittest_lifecycle(void)
> +{
> + unsigned int refcount;
> + int found_refcount_one = 0;
> + int put_count = 0;
> + struct device_node *np;
> + struct device_node *prev_sibling, *next_sibling;
> + const char *refcount_path = "/testcase-data/refcount-node";
> + const char *refcount_parent_path = "/testcase-data";
> +
> + /*
> + * Node lifecycle tests, non-dynamic node:
> + *
> + * - Decrementing refcount to zero via of_node_put() should cause the
> + * attempt to free the node memory by of_node_release() to fail
> + * because the node is not a dynamic node.
> + *
> + * - Decrementing refcount past zero should result in additional
> + * errors reported.
> + */
> +
> + np = of_find_node_by_path(refcount_path);
> + unittest(np, "find refcount_path \"%s\"\n", refcount_path);
> + if (np == NULL)
> + goto out_skip_tests;
> +
> + while (!found_refcount_one) {
> +
> + if (put_count++ > 10) {
> + unittest(0, "guardrail to avoid infinite loop\n");
> + goto out_skip_tests;
> + }
> +
> + refcount = kref_read(&np->kobj.kref);
> + if (refcount == 1)
> + found_refcount_one = 1;
> + else
> + of_node_put(np);
> + }
> +
> + EXPECT_BEGIN(KERN_INFO, "OF: ERROR: of_node_release() detected bad of_node_put() on /testcase-data/refcount-node");
> +
> + /*
> + * refcount is now one, decrementing to zero will result in a call to
> + * of_node_release() to free the node's memory, which should result
> + * in an error
> + */
> + unittest(1, "/testcase-data/refcount-node is one");
> + of_node_put(np);
> +
> + EXPECT_END(KERN_INFO, "OF: ERROR: of_node_release() detected bad of_node_put() on /testcase-data/refcount-node");
> +
> +
> + /*
> + * expect stack trace for subsequent of_node_put():
> + * __refcount_sub_and_test() calls:
> + * refcount_warn_saturate(r, REFCOUNT_SUB_UAF)
> + *
> + * Not capturing entire WARN_ONCE() trace with EXPECT_*(), just
> + * the first three lines, and the last line.
> + */
> + EXPECT_BEGIN(KERN_INFO, "------------[ cut here ]------------");
> + EXPECT_BEGIN(KERN_INFO, "WARNING: <<all>>");
> + EXPECT_BEGIN(KERN_INFO, "refcount_t: underflow; use-after-free.");
> + EXPECT_BEGIN(KERN_INFO, "---[ end trace <<int>> ]---");
> +
> + /* refcount is now zero, this should fail */
> + unittest(1, "/testcase-data/refcount-node is zero");
> + of_node_put(np);
> +
> + EXPECT_END(KERN_INFO, "---[ end trace <<int>> ]---");
> + EXPECT_END(KERN_INFO, "refcount_t: underflow; use-after-free.");
> + EXPECT_END(KERN_INFO, "WARNING: <<all>>");
> + EXPECT_END(KERN_INFO, "------------[ cut here ]------------");
> +
> + /*
> + * Q. do we expect to get yet another warning?
> + * A. no, the WARNING is from WARN_ONCE()
> + */
> + EXPECT_NOT_BEGIN(KERN_INFO, "------------[ cut here ]------------");
> + EXPECT_NOT_BEGIN(KERN_INFO, "WARNING: <<all>>");
> + EXPECT_NOT_BEGIN(KERN_INFO, "refcount_t: underflow; use-after-free.");
> + EXPECT_NOT_BEGIN(KERN_INFO, "---[ end trace <<int>> ]---");
> +
> + unittest(1, "/testcase-data/refcount-node is zero, second time");
> + of_node_put(np);
> +
> + EXPECT_NOT_END(KERN_INFO, "---[ end trace <<int>> ]---");
> + EXPECT_NOT_END(KERN_INFO, "refcount_t: underflow; use-after-free.");
> + EXPECT_NOT_END(KERN_INFO, "WARNING: <<all>>");
> + EXPECT_NOT_END(KERN_INFO, "------------[ cut here ]------------");
> +
> + /*
> + * refcount of zero will trigger stack traces from any further
> + * attempt to of_node_get() node "refcount-node". One example of
> + * this is where of_unittest_check_node_linkage() will recursively
> + * scan the tree, with 'for_each_child_of_node()' doing an
> + * of_node_get() of the children of a node.
> + *
> + * Prevent the stack trace by removing node "refcount-node" from
> + * its parent's child list.
> + *
> + * WARNING: EVIL, EVIL, EVIL:
> + *
> + * Directly manipulate the child list of node /testcase-data to
> + * remove child refcount-node. This is ignoring all proper methods
> + * of removing a child and will leak a small amount of memory.
> + */
> +
> + np = of_find_node_by_path(refcount_parent_path);
> + unittest(np, "find refcount_parent_path \"%s\"\n", refcount_parent_path);
> + unittest(np, "ERROR: devicetree live tree left in a 'bad state' if test fail\n");
> + if (np == NULL)
> + return;
> +
> + prev_sibling = np->child;
> + next_sibling = prev_sibling->sibling;
> + if (!strcmp(prev_sibling->full_name, "refcount-node")) {
> + np->child = next_sibling;
> + next_sibling = next_sibling->sibling;
> + }
> + while (next_sibling) {
> + if (!strcmp(next_sibling->full_name, "refcount-node"))
> + prev_sibling->sibling = next_sibling->sibling;
> + prev_sibling = next_sibling;
> + next_sibling = next_sibling->sibling;
> + }
> + of_node_put(np);
> +
> + return;
> +
> +out_skip_tests:
> + unittest(0, "One or more lifecycle tests skipped\n");
> +}
> +
> #ifdef CONFIG_OF_OVERLAY
>
> /*
> @@ -3502,6 +3645,7 @@ static int __init of_unittest(void)
> of_unittest_match_node();
> of_unittest_platform_populate();
> of_unittest_overlay();
> + of_unittest_lifecycle();
>
> /* Double check linkage after removing testcase data */
> of_unittest_check_tree_linkage();
> --
> Frank Rowand <frowand.list@xxxxxxxxx>
>

Next message: Abhinav Kumar: "Re: [RFC PATCH 1/2] drm/msm/dpu: add dsc helper functions"
Previous message: Yury Norov: "Re: [PATCH 3/5] lib/bitmap: add test for bitmap_{from,to}_arr64"
Next in thread: Frank Rowand: "Re: [PATCH 4/7] of: unittest: add node lifecycle tests"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]