[PATCH 0/7] of: unittest: new node lifecycle tests

[PATCH 0/7] of: unittest: new node lifecycle tests

[Frank Rowand]

Create new devicetree node lifecycle tests.

The tests introduce use of EXPECT_NOT messages, similar to EXPECT
messages.  This requires updating scripts/dtc/of_unittest_expect
to process EXPECT_NOT messages.

The new tests revealed an issue in printk formatting when using
format "%pOF" on a node with a reference count of zero.  A patch
is included to the fix the caller which revealed the issue.

Update kconfig unittest help to further explain that unittests
should only be enabled for developer kernels.  Also add info
about using scripts/dtc/of_unittest_expect to process the output
of unittests.

Add an additional consistency check to of_node_release(), which
is the function that potentially frees node related memory when
the node's reference count is decremented to zero.

Add docbook documentation to the devicetree node creation functions
about caller responsibility to call of_node_put() and how the
memory free process works.

Frank Rowand (7):
  of: prepare to add processing of EXPECT_NOT to of_unittest_expect
  of: add processing of EXPECT_NOT to of_unittest_expect
  of: update kconfig unittest help
  of: unittest: add node lifecycle tests
  of: do not use "%pOF" printk format on node with refcount of zero
  of: add consistency check to of_node_release()
  of: dynamic: add lifecycle docbook info to node creation functions

 drivers/of/Kconfig                            |  14 +-
 drivers/of/dynamic.c                          |  31 ++-
 .../of/unittest-data/testcases_common.dtsi    |   1 +
 drivers/of/unittest-data/tests-lifecycle.dtsi |   8 +
 drivers/of/unittest.c                         | 148 +++++++++++++-
 include/linux/of.h                            |  11 ++
 scripts/dtc/of_unittest_expect                | 183 +++++++++++++++---
 7 files changed, 365 insertions(+), 31 deletions(-)
 create mode 100644 drivers/of/unittest-data/tests-lifecycle.dtsi

-- 
Frank Rowand <frowand.list@gmail.com>

[PATCH 1/7] of: prepare to add processing of EXPECT_NOT to of_unittest_expect

[Frank Rowand]

scripts/dtc/of_unittest_expect processes EXPECT messages that
document expected kernel messages triggered by unittest.  Add
processing of EXPECT_NOT messages that document kernel messages
triggered by unittest that are not expected.

This is commit 1 of 2, renaming existing variables in anticipation
of the changes needed to process EXPECT_NOT, so that commit 2 of 2
will be smaller and easier to read.  This commit is not intended
to make any functional changes.

Signed-off-by: Frank Rowand <frowand.list@gmail.com>
---
 scripts/dtc/of_unittest_expect | 40 +++++++++++++++++-----------------
 1 file changed, 20 insertions(+), 20 deletions(-)

diff --git a/scripts/dtc/of_unittest_expect b/scripts/dtc/of_unittest_expect
index 96b12d9ea606..7b25bb693162 100755
--- a/scripts/dtc/of_unittest_expect
+++ b/scripts/dtc/of_unittest_expect
@@ -9,7 +9,7 @@
 # on the console log that results from executing the Linux kernel
 # devicetree unittest (drivers/of/unitest.c).
 
-$VUFX = "220201a";
+$VUFX = "230121a";
 
 use strict 'refs';
 use strict subs;
@@ -274,7 +274,7 @@ while ($line = <ARGV>) {
 	if ($line =~ /^\s*$exp_begin/) {
 		$data = $line;
 		$data =~ s/^\s*$exp_begin//;
-		push @begin, $data;
+		push @exp_begin_stack, $data;
 
 		if ($verbose) {
 			if ($print_line_num) {
@@ -302,20 +302,20 @@ while ($line = <ARGV>) {
 
 		$found = 0;
 		$no_begin = 0;
-		if (@found_or_begin > 0) {
-			$begin = pop @found_or_begin;
+		if (@exp_found_or_begin > 0) {
+			$begin = pop @exp_found_or_begin;
 			if (compare($data, $begin)) {
 				$found = 1;
 			}
 		} elsif (@begin > 0) {
-			$begin = pop @begin;
+			$begin = pop @exp_begin_stack;
 		} else {
 			$no_begin = 1;
 		}
 
 		if ($no_begin) {
 
-			$expect_missing_begin++;
+			$exp_missing_begin++;
 			print "** ERROR: EXPECT end without any EXPECT begin:\n";
 			print "       end ---> $line\n";
 
@@ -325,20 +325,20 @@ while ($line = <ARGV>) {
 				$line_num = sprintf("%4s ", $.);
 			}
 
-			$expect_not_found++;
+			$exp_missing++;
 			printf "** %s%s$script_name WARNING - not found ---> %s\n",
 					$line_num,  $timestamp, $data;
 
 		} elsif (! compare($data, $begin)) {
 
-			$expect_missing_end++;
+			$exp_missing_end++;
 			print "** ERROR: EXPECT end does not match EXPECT begin:\n";
 			print "       begin -> $begin\n";
 			print "       end ---> $line\n";
 
 		} else {
 
-			$expect_found++;
+			$exp_found++;
 
 		}
 
@@ -357,7 +357,7 @@ while ($line = <ARGV>) {
 	}
 
 	$found = 0;
-	foreach $begin (@begin) {
+	foreach $begin (@exp_begin_stack) {
 		if (compare($begin, $line)) {
 			$found = 1;
 			last;
@@ -365,12 +365,12 @@ while ($line = <ARGV>) {
 	}
 
 	if ($found) {
-		$begin = shift @begin;
+		$begin = shift @exp_begin_stack;
 		while (! compare($begin, $line)) {
-			push @found_or_begin, $begin;
-			$begin = shift @begin;
+			push @exp_found_or_begin, $begin;
+			$begin = shift @exp_begin_stack;
 		}
-		push @found_or_begin, $line;
+		push @exp_found_or_begin, $line;
 
 		if ($hide_expect) {
 			$suppress_line = 1;
@@ -391,18 +391,18 @@ if (! $no_expect_stats) {
 	print  "\n";
 	print  "** EXPECT statistics:\n";
 	print  "**\n";
-	printf "**   EXPECT found          : %4i\n", $expect_found;
-	printf "**   EXPECT not found      : %4i\n", $expect_not_found;
-	printf "**   missing EXPECT begin  : %4i\n", $expect_missing_begin;
-	printf "**   missing EXPECT end    : %4i\n", $expect_missing_end;
+	printf "**   EXPECT found          : %4i\n", $exp_found;
+	printf "**   EXPECT not found      : %4i\n", $exp_missing;
+	printf "**   missing EXPECT begin  : %4i\n", $exp_missing_begin;
+	printf "**   missing EXPECT end    : %4i\n", $exp_missing_end;
 	printf "**   unittest FAIL         : %4i\n", $unittest_fail;
 	printf "**   internal error        : %4i\n", $internal_err;
 }
 
-if (@begin) {
+if (@exp_begin_stack) {
 	print "** ERROR: EXPECT begin without any EXPECT end:\n";
 	print "          This list may be misleading.\n";
-	foreach $begin (@begin) {
+	foreach $begin (@exp_begin_stack) {
 		print "       begin ---> $begin\n";
 	}
 }
-- 
Frank Rowand <frowand.list@gmail.com>

[PATCH 2/7] of: add processing of EXPECT_NOT to of_unittest_expect

[Frank Rowand]

scripts/dtc/of_unittest_expect processes EXPECT messages that
document expected kernel messages triggered by unittest.  Add
processing of EXPECT_NOT messages that document kernel messages
triggered by unittest that are not expected.

This is commit 2 of 2, implementing the processing of EXPECT_NOT
messages.

Signed-off-by: Frank Rowand <frowand.list@gmail.com>
---
 scripts/dtc/of_unittest_expect | 157 ++++++++++++++++++++++++++++++---
 1 file changed, 145 insertions(+), 12 deletions(-)

diff --git a/scripts/dtc/of_unittest_expect b/scripts/dtc/of_unittest_expect
index 7b25bb693162..0a535a8e9821 100755
--- a/scripts/dtc/of_unittest_expect
+++ b/scripts/dtc/of_unittest_expect
@@ -9,7 +9,7 @@
 # on the console log that results from executing the Linux kernel
 # devicetree unittest (drivers/of/unitest.c).
 
-$VUFX = "230121a";
+$VUFX = "230211a";
 
 use strict 'refs';
 use strict subs;
@@ -62,6 +62,8 @@ sub compare {
 			} else {
 				return 0;
 			}
+		} elsif ($type eq "all") {
+			return 1;
 		} elsif ($type eq "") {
 			if ($expect_next ne $got_next) {
 				return 0;
@@ -130,6 +132,7 @@ usage:
 
      <<int>> matches: [+-]*[0-9]+
      <<hex>> matches: (0x)*[0-9a-f]+
+     <<all>> matches: anything to end of line
 
   'EXPECT \\' (begin) and 'EXPECT /' (end) lines are suppressed.
 
@@ -240,6 +243,8 @@ if ($#ARGV != 0) {
 $pr_fmt = "### dt-test ### ";
 $exp_begin = "${pr_fmt}EXPECT \\\\ : ";
 $exp_end   = "${pr_fmt}EXPECT / : ";
+$expnot_begin = "${pr_fmt}EXPECT_NOT \\\\ : ";
+$expnot_end   = "${pr_fmt}EXPECT_NOT / : ";
 
 
 $line_num = "";
@@ -250,6 +255,8 @@ while ($line = <ARGV>) {
 
 	chomp $line;
 
+	$suppress_line = 0;
+
 	$prefix = "  ";  ## 2 characters
 
 
@@ -306,6 +313,7 @@ while ($line = <ARGV>) {
 			$begin = pop @exp_found_or_begin;
 			if (compare($data, $begin)) {
 				$found = 1;
+				$exp_found++;
 			}
 		} elsif (@begin > 0) {
 			$begin = pop @exp_begin_stack;
@@ -316,7 +324,7 @@ while ($line = <ARGV>) {
 		if ($no_begin) {
 
 			$exp_missing_begin++;
-			print "** ERROR: EXPECT end without any EXPECT begin:\n";
+			print "** ERROR: EXPECT end without matching EXPECT begin:\n";
 			print "       end ---> $line\n";
 
 		} elsif (! $found) {
@@ -329,17 +337,97 @@ while ($line = <ARGV>) {
 			printf "** %s%s$script_name WARNING - not found ---> %s\n",
 					$line_num,  $timestamp, $data;
 
-		} elsif (! compare($data, $begin)) {
+		} elsif (! compare($data, $begin) and ($data ne $begin)) {
 
 			$exp_missing_end++;
 			print "** ERROR: EXPECT end does not match EXPECT begin:\n";
 			print "       begin -> $begin\n";
 			print "       end ---> $line\n";
 
+		}
+
+		next LINE;
+	}
+
+
+	# -----  find EXPECT_NOT begin
+
+	if ($line =~ /^\s*$expnot_begin/) {
+		$data = $line;
+		$data =~ s/^\s*$expnot_begin//;
+		push @expnot_begin_stack, $data;
+
+		if ($verbose) {
+			if ($print_line_num) {
+				$line_num = sprintf("%4s ", $.);
+			}
+			printf "%s %s%s%s\n", $prefix, $line_num,  $timestamp, $line;
+		}
+
+		next LINE;
+	}
+
+
+	# -----  find EXPECT_NOT end
+
+	if ($line =~ /^\s*$expnot_end/) {
+		$data = $line;
+		$data =~ s/^\s*$expnot_end//;
+
+		if ($verbose) {
+			if ($print_line_num) {
+				$line_num = sprintf("%4s ", $.);
+			}
+			printf "%s %s%s%s\n", $prefix, $line_num,  $timestamp, $line;
+		}
+
+		$found = 0;
+		$no_begin = 0;
+		if (@expnot_found_or_begin > 0) {
+			$begin = pop @expnot_found_or_begin;
+			if (compare($data, $begin)) {
+				$found = 1;
+				$expnot_found++;
+			}
+		} elsif (@expnot_begin_stack <= 0) {
+			$no_begin = 1;
+		}
+
+		if ($no_begin) {
+
+			$expnot_missing_begin++;
+			print "** ERROR: EXPECT_NOT end without matching EXPECT_NOT begin:\n";
+			print "       end ---> $line\n";
+
+		}
+
+		if ($found) {
+
+			if ($print_line_num) {
+				$line_num = sprintf("%4s ", $.);
+			}
+
+			printf "** %s%s$script_name WARNING - next line matches EXPECT_NOT\n",
+					$line_num,  $timestamp;
+			printf "** %s%s%s\n", $line_num,  $timestamp, $line;
+
 		} else {
 
-			$exp_found++;
+			$expnot_missing++;
+
+		}
+
+		if (@expnot_begin_stack > 0) {
+			$begin = pop @expnot_begin_stack;
+
+			if (! compare($data, $begin) and ($data ne $begin)) {
 
+				$expnot_missing_end++;
+				print "** ERROR: EXPECT_NOT end does not match EXPECT_NOT begin:\n";
+				print "       begin -> $begin\n";
+				print "       end ---> $line\n";
+
+			}
 		}
 
 		next LINE;
@@ -374,12 +462,38 @@ while ($line = <ARGV>) {
 
 		if ($hide_expect) {
 			$suppress_line = 1;
-			next LINE;
 		}
 		$prefix = "ok"; # 2 characters
 	}
 
 
+	$found = 0;
+	foreach $begin (@expnot_begin_stack) {
+		if (compare($begin, $line)) {
+			$found = 1;
+			last;
+		}
+	}
+
+	if ($found) {
+		$begin = shift @begin;
+		while (! compare($begin, $line)) {
+			push @expnot_found_or_begin, $begin;
+			$begin = shift @begin;
+		}
+		push @expnot_found_or_begin, $line;
+
+		if ($hide_expect) {
+			$suppress_line = 1;
+		}
+		$prefix = "**"; # 2 characters
+	}
+
+
+	if ($suppress_line) {
+		next LINE;
+	}
+
 	if ($print_line_num) {
 		$line_num = sprintf("%4s ", $.);
 	}
@@ -391,18 +505,37 @@ if (! $no_expect_stats) {
 	print  "\n";
 	print  "** EXPECT statistics:\n";
 	print  "**\n";
-	printf "**   EXPECT found          : %4i\n", $exp_found;
-	printf "**   EXPECT not found      : %4i\n", $exp_missing;
-	printf "**   missing EXPECT begin  : %4i\n", $exp_missing_begin;
-	printf "**   missing EXPECT end    : %4i\n", $exp_missing_end;
-	printf "**   unittest FAIL         : %4i\n", $unittest_fail;
-	printf "**   internal error        : %4i\n", $internal_err;
+	printf "**   non-zero values expected:\n";
+	print  "**\n";
+	printf "**     EXPECT found              : %4i\n", $exp_found;
+	printf "**     EXPECT_NOT not found      : %4i\n", $expnot_missing;
+	print  "**\n";
+	printf "**   zero values expected:\n";
+	print  "**\n";
+	printf "**     EXPECT not found          : %4i\n", $exp_missing;
+	printf "**     missing EXPECT begin      : %4i\n", $exp_missing_begin;
+	printf "**     missing EXPECT end        : %4i\n", $exp_missing_end;
+	print  "**\n";
+	printf "**     EXPECT_NOT found          : %4i\n", $expnot_found;
+	printf "**     missing EXPECT_NOT begin  : %4i\n", $expnot_missing_begin;
+	printf "**     missing EXPECT_NOT end    : %4i\n", $expnot_missing_end;
+	print  "**\n";
+	printf "**     unittest FAIL             : %4i\n", $unittest_fail;
+	printf "**     internal error            : %4i\n", $internal_err;
 }
 
 if (@exp_begin_stack) {
-	print "** ERROR: EXPECT begin without any EXPECT end:\n";
+	print "** ERROR: EXPECT begin without matching EXPECT end:\n";
 	print "          This list may be misleading.\n";
 	foreach $begin (@exp_begin_stack) {
 		print "       begin ---> $begin\n";
 	}
 }
+
+if (@expnot_begin_stack) {
+	print "** ERROR: EXPECT_NOT begin without matching EXPECT_NOT end:\n";
+	print "          This list may be misleading.\n";
+	foreach $begin (@expnot_begin_stack) {
+		print "       begin ---> $begin\n";
+	}
+}
-- 
Frank Rowand <frowand.list@gmail.com>

[PATCH 3/7] of: update kconfig unittest help

[Frank Rowand]

Add more information about the impact the of unittests have on the
live devicetree and why the tests should only be enabled for developer
kernels.

Add information about processing the test output such that the
results are more complete and comprehendable.

Signed-off-by: Frank Rowand <frowand.list@gmail.com>
---
 drivers/of/Kconfig | 14 +++++++++++++-
 1 file changed, 13 insertions(+), 1 deletion(-)

diff --git a/drivers/of/Kconfig b/drivers/of/Kconfig
index 80b5fd44ab1c..644386833a7b 100644
--- a/drivers/of/Kconfig
+++ b/drivers/of/Kconfig
@@ -23,7 +23,19 @@ config OF_UNITTEST
 	  that are executed once at boot time, and the results dumped to the
 	  console.
 
-	  If unsure, say N here, but this option is safe to enable.
+	  This option should only be enabled for a development kernel. The tests
+	  will taint the kernel with TAINT_TEST. The tests will cause ERROR and
+	  WARNING messages to print on the console. The tests will cause stack
+	  traces to print on the console.  It is possible that the tests will
+	  leave the devicetree in a corrupted state.
+
+	  The unittest output will be verbose.  Copy the output to a file
+	  via capturing the console output or via the dmesg command.  Process
+	  this file with scripts/dtc/of_unittest_expect to reduce the
+	  verbosity, test whether expected output is present, and to
+	  summarize the results.
+
+	  If unsure, say N here. This option is not safe to enable.
 
 config OF_ALL_DTBS
 	bool "Build all Device Tree Blobs"
-- 
Frank Rowand <frowand.list@gmail.com>

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

[Frank Rowand]

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@gmail.com>
---

There are checkpatch warnings.  I have reviewed them and feel
they can be ignored.

Stack traces from the pr_err() issue:

------------[ 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@gmail.com>

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

[Guenter Roeck]

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@gmail.com>
> ---
> 
> 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@gmail.com>
> 

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

[Frank Rowand]

On 2/25/23 18:07, Guenter Roeck wrote:
> 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@gmail.com>
>> ---
>>
>> 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.

Thank you for letting me know about this issue.  I was a bit concerned about
causing stack traces.

I do not want to lose your testing!

I'll submit a patch to disable any test that causes a backtrace, then add a
boot command line option to enable those tests.  That was most people will
not see the backtrace, the test will be reported as skipped, and people
like me can go to the extra effort to enable the tests.

Hopefully the patch get a good reception.

-Frank

> 
> 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@gmail.com>
>>

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

[Frank Rowand]

On 2/25/23 18:07, Guenter Roeck wrote:
> 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@gmail.com>
>> ---
>>
>> 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.

Thank you for letting me know about this.

I'll create a patch to make the default action be skip the tests that cause
a backtrace, and create a command line option to enable those tests.  Then
you can resume your valuable testing and people like me can enable the extra
tests.

Hopefully the patch will be well received.

-Frank

> 
> 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@gmail.com>
>>

[PATCH 5/7] of: do not use "%pOF" printk format on node with refcount of zero

[Frank Rowand]

of_node_release() can not use the "%pOF" printk format to report
the node name of a node when the node reference count is zero.
This is because the formatter device_node_string() calls
fwnode_full_name_string() which indirectly calls of_node_get().
Calling of_node_get() on the node with a zero reference count
results in a WARNING and stack trace.

When the reference count has been decremented to zero, this function
is in the subsequent call path which frees memory related to the node.

This commit resolves the unittest EXPECT errors that were created in
the previous commmit.

Signed-off-by: Frank Rowand <frowand.list@gmail.com>
---

The scripts/dtc/of_unittest_expect summary statistics before this commit:

** EXPECT statistics:
**
**   non-zero values expected:
**
**     EXPECT found              :   50
**     EXPECT_NOT not found      :    4
**
**   zero values expected:
**
**     EXPECT not found          :    0
**     missing EXPECT begin      :    5
**     missing EXPECT end        :    0
**
**     EXPECT_NOT found          :    0
**     missing EXPECT_NOT begin  :    0
**     missing EXPECT_NOT end    :    0
**
**     unittest FAIL             :    0
**     internal error            :    0

The scripts/dtc/of_unittest_expect summary statistics after this commit:

** EXPECT statistics:
**
**   non-zero values expected:
**
**     EXPECT found              :   55
**     EXPECT_NOT not found      :    4
**
**   zero values expected:
**
**     EXPECT not found          :    0
**     missing EXPECT begin      :    0
**     missing EXPECT end        :    0
**
**     EXPECT_NOT found          :    0
**     missing EXPECT_NOT begin  :    0
**     missing EXPECT_NOT end    :    0
**
**     unittest FAIL             :    0
**     internal error            :    0

 drivers/of/dynamic.c | 10 +++++++++-
 1 file changed, 9 insertions(+), 1 deletion(-)

diff --git a/drivers/of/dynamic.c b/drivers/of/dynamic.c
index becb80f762c8..dbcbc41f3465 100644
--- a/drivers/of/dynamic.c
+++ b/drivers/of/dynamic.c
@@ -329,9 +329,17 @@ void of_node_release(struct kobject *kobj)
 {
 	struct device_node *node = kobj_to_device_node(kobj);
 
+	/*
+	 * can not use '"%pOF", node' in pr_err() calls from this function
+	 * because an of_node_get(node) when refcount is already zero
+	 * will result in an error and a stack dump
+	 */
+
 	/* 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);
+
+		pr_err("ERROR: %s() detected bad of_node_put() on %pOF/%s\n",
+			__func__, node->parent, node->full_name);
 
 		/*
 		 * of unittests will test this path.  Do not print the stack
-- 
Frank Rowand <frowand.list@gmail.com>

Re: [PATCH 5/7] of: do not use "%pOF" printk format on node with refcount of zero

[Frank Rowand]

On 2/13/23 12:57, Frank Rowand wrote:
> of_node_release() can not use the "%pOF" printk format to report
> the node name of a node when the node reference count is zero.
> This is because the formatter device_node_string() calls
> fwnode_full_name_string() which indirectly calls of_node_get().
> Calling of_node_get() on the node with a zero reference count
> results in a WARNING and stack trace.
> 
> When the reference count has been decremented to zero, this function
> is in the subsequent call path which frees memory related to the node.
> 
> This commit resolves the unittest EXPECT errors that were created in
> the previous commmit.
> 
> Signed-off-by: Frank Rowand <frowand.list@gmail.com>
> ---

< snip >

After applying this commit, the output of unittests, as processed by
scripts/dtc/of_unittest_expect, including the new lifecycle tests is:




<< pre-test console output deleted >>

-> ### dt-test ### start of unittest - you will see error messages
   l16: Bringing 0uV into 2700000-2700000uV
ok Duplicate name in testcase-data, renamed to "duplicate-name#1"
   l17: Bringing 0uV into 2700000-2700000uV
   l18: Bringing 0uV into 2850000-2850000uV
   ### dt-test ### pass of_unittest_check_tree_linkage():270
   l19: Bringing 0uV into 3300000-3300000uV
   ### dt-test ### pass of_unittest_check_tree_linkage():271
   sdhci_msm f98a4900.mmc: Got CD GPIO
   ### dt-test ### pass of_unittest_check_phandles():379
   l20: Bringing 0uV into 2950000-2950000uV
   ### dt-test ### pass of_unittest_find_node_by_name():80
   sdhci_msm f98a4900.mmc: Got CD GPIO
   ### dt-test ### pass of_unittest_find_node_by_name():87
   l21: Bringing 0uV into 2950000-2950000uV
   ### dt-test ### pass of_unittest_find_node_by_name():91
   l22: Bringing 0uV into 3000000-3000000uV
   sdhci_msm f98a4900.mmc: Got CD GPIO
   l23: Bringing 0uV into 3000000-3000000uV
   ### dt-test ### pass of_unittest_find_node_by_name():98
   l24: Bringing 0uV into 3075000-3075000uV
   ### dt-test ### pass of_unittest_find_node_by_name():105
   ### dt-test ### pass of_unittest_find_node_by_name():109
   ### dt-test ### pass of_unittest_find_node_by_name():115
   ### dt-test ### pass of_unittest_find_node_by_name():119
   ### dt-test ### pass of_unittest_find_node_by_name():123
   ### dt-test ### pass of_unittest_find_node_by_name():127
   mmc0: SDHCI controller on f9824900.mmc [f9824900.mmc] using ADMA
   ### dt-test ### pass of_unittest_find_node_by_name():132
   ### dt-test ### pass of_unittest_find_node_by_name():137
   ### dt-test ### pass of_unittest_find_node_by_name():142
   ### dt-test ### pass of_unittest_find_node_by_name():147
   ### dt-test ### pass of_unittest_find_node_by_name():153
   mmc1: SDHCI controller on f98a4900.mmc [f98a4900.mmc] using ADMA
   ### dt-test ### pass of_unittest_find_node_by_name():158
   ### dt-test ### pass of_unittest_find_node_by_name():163
   ### dt-test ### pass of_unittest_find_node_by_name():168
   ### dt-test ### pass of_unittest_dynamic():194
   ### dt-test ### pass of_unittest_dynamic():201
   ### dt-test ### pass of_unittest_dynamic():207
   mmc0: new HS200 MMC card at address 0001
   ### dt-test ### pass of_unittest_dynamic():215
   ### dt-test ### pass of_unittest_dynamic():219
   mmcblk0: mmc0:0001 SEM16G 14.7 GiB 
   ### dt-test ### pass of_unittest_dynamic():227
   mmc1: new ultra high speed DDR50 SDHC card at address aaaa
   ### dt-test ### pass of_unittest_dynamic():229
   ### dt-test ### pass of_unittest_parse_phandle_with_args():402
   mmcblk1: mmc1:aaaa SU16G 14.8 GiB 
   ### dt-test ### pass of_unittest_parse_phandle_with_args():456
    mmcblk0: p1 p2 p3 p4 p5 p6 p7 p8 p9 p10 p11 p12 p13 p14 p15 p16 p17 p18 p19 p20
   ### dt-test ### pass of_unittest_parse_phandle_with_args():456
    mmcblk1: p1
   ### dt-test ### pass of_unittest_parse_phandle_with_args():456
   ### dt-test ### pass of_unittest_parse_phandle_with_args():456
   ### dt-test ### pass of_unittest_parse_phandle_with_args():456
   ### dt-test ### pass of_unittest_parse_phandle_with_args():456
   ### dt-test ### pass of_unittest_parse_phandle_with_args():456
   ### dt-test ### pass of_unittest_parse_phandle_with_args():456
   ### dt-test ### pass of_unittest_parse_phandle_with_args():464
   ### dt-test ### pass of_unittest_parse_phandle_with_args():467
ok OF: /testcase-data/phandle-tests/consumer-a: could not get #phandle-cells-missing for /testcase-data/phandle-tests/provider1
   mmcblk0boot0: mmc0:0001 SEM16G 4.00 MiB 
   ### dt-test ### pass of_unittest_parse_phandle_with_args():481
   mmcblk0boot1: mmc0:0001 SEM16G 4.00 MiB 
ok OF: /testcase-data/phandle-tests/consumer-a: could not get #phandle-cells-missing for /testcase-data/phandle-tests/provider1
   mmcblk0rpmb: mmc0:0001 SEM16G 4.00 MiB, chardev (241:0)
   ### dt-test ### pass of_unittest_parse_phandle_with_args():492
ok OF: /testcase-data/phandle-tests/consumer-a: could not find phandle 12345678
   ### dt-test ### pass of_unittest_parse_phandle_with_args():506
ok OF: /testcase-data/phandle-tests/consumer-a: could not find phandle 12345678
   ### dt-test ### pass of_unittest_parse_phandle_with_args():517
ok OF: /testcase-data/phandle-tests/consumer-a: #phandle-cells = 3 found 1
   ### dt-test ### pass of_unittest_parse_phandle_with_args():531
ok OF: /testcase-data/phandle-tests/consumer-a: #phandle-cells = 3 found 1
   ### dt-test ### pass of_unittest_parse_phandle_with_args():542
   ### dt-test ### pass of_unittest_parse_phandle_with_args_map():582
   ### dt-test ### pass of_unittest_parse_phandle_with_args_map():640
   ### dt-test ### pass of_unittest_parse_phandle_with_args_map():640
   ### dt-test ### pass of_unittest_parse_phandle_with_args_map():640
   ### dt-test ### pass of_unittest_parse_phandle_with_args_map():640
   ### dt-test ### pass of_unittest_parse_phandle_with_args_map():640
   ### dt-test ### pass of_unittest_parse_phandle_with_args_map():640
   ### dt-test ### pass of_unittest_parse_phandle_with_args_map():640
   ### dt-test ### pass of_unittest_parse_phandle_with_args_map():640
   ### dt-test ### pass of_unittest_parse_phandle_with_args_map():648
ok OF: /testcase-data/phandle-tests/consumer-b: could not get #phandle-missing-cells for /testcase-data/phandle-tests/provider1
   ### dt-test ### pass of_unittest_parse_phandle_with_args_map():661
ok OF: /testcase-data/phandle-tests/consumer-b: could not find phandle 12345678
   ### dt-test ### pass of_unittest_parse_phandle_with_args_map():674
ok OF: /testcase-data/phandle-tests/consumer-b: #phandle-cells = 2 found 1
   ### dt-test ### pass of_unittest_parse_phandle_with_args_map():687
   ### dt-test ### pass of_unittest_printf_one():294
   ### dt-test ### pass of_unittest_printf_one():304
   ### dt-test ### pass of_unittest_printf_one():304
   ### dt-test ### pass of_unittest_printf_one():294
   ### dt-test ### pass of_unittest_printf_one():304
   ### dt-test ### pass of_unittest_printf_one():304
   ### dt-test ### pass of_unittest_printf_one():294
   ### dt-test ### pass of_unittest_printf_one():304
   ### dt-test ### pass of_unittest_printf_one():304
   ### dt-test ### pass of_unittest_printf_one():294
   ### dt-test ### pass of_unittest_printf_one():304
   ### dt-test ### pass of_unittest_printf_one():304
   ### dt-test ### pass of_unittest_printf_one():294
   ### dt-test ### pass of_unittest_printf_one():304
   ### dt-test ### pass of_unittest_printf_one():304
   ### dt-test ### pass of_unittest_printf_one():294
   ### dt-test ### pass of_unittest_printf_one():304
   ### dt-test ### pass of_unittest_printf_one():304
   ### dt-test ### pass of_unittest_printf_one():294
   ### dt-test ### pass of_unittest_printf_one():304
   ### dt-test ### pass of_unittest_printf_one():304
   ### dt-test ### pass of_unittest_printf_one():294
   ### dt-test ### pass of_unittest_printf_one():304
   ### dt-test ### pass of_unittest_printf_one():304
   ### dt-test ### pass of_unittest_printf_one():294
   ### dt-test ### pass of_unittest_printf_one():304
   ### dt-test ### pass of_unittest_printf_one():304
   ### dt-test ### pass of_unittest_printf_one():294
   ### dt-test ### pass of_unittest_printf_one():304
   ### dt-test ### pass of_unittest_printf_one():304
   ### dt-test ### pass of_unittest_printf_one():294
   ### dt-test ### pass of_unittest_printf_one():304
   ### dt-test ### pass of_unittest_printf_one():304
   ### dt-test ### pass of_unittest_printf_one():294
   ### dt-test ### pass of_unittest_printf_one():304
   ### dt-test ### pass of_unittest_printf_one():304
   ### dt-test ### pass of_unittest_printf_one():294
   ### dt-test ### pass of_unittest_printf_one():304
   ### dt-test ### pass of_unittest_printf_one():304
   ### dt-test ### pass of_unittest_printf_one():294
   ### dt-test ### pass of_unittest_printf_one():304
   ### dt-test ### pass of_unittest_printf_one():304
   ### dt-test ### pass of_unittest_printf_one():294
   ### dt-test ### pass of_unittest_printf_one():304
   ### dt-test ### pass of_unittest_printf_one():304
   ### dt-test ### pass of_unittest_printf_one():294
   ### dt-test ### pass of_unittest_printf_one():304
   ### dt-test ### pass of_unittest_printf_one():304
   ### dt-test ### pass of_unittest_printf_one():294
   ### dt-test ### pass of_unittest_printf_one():304
   ### dt-test ### pass of_unittest_printf_one():304
   ### dt-test ### pass of_unittest_property_string():703
   ### dt-test ### pass of_unittest_property_string():705
   ### dt-test ### pass of_unittest_property_string():707
   ### dt-test ### pass of_unittest_property_string():709
   ### dt-test ### pass of_unittest_property_string():711
   ### dt-test ### pass of_unittest_property_string():713
   ### dt-test ### pass of_unittest_property_string():715
   ### dt-test ### pass of_unittest_property_string():719
   ### dt-test ### pass of_unittest_property_string():721
   ### dt-test ### pass of_unittest_property_string():723
   ### dt-test ### pass of_unittest_property_string():725
   ### dt-test ### pass of_unittest_property_string():729
   ### dt-test ### pass of_unittest_property_string():732
   ### dt-test ### pass of_unittest_property_string():734
   ### dt-test ### pass of_unittest_property_string():736
   ### dt-test ### pass of_unittest_property_string():738
   ### dt-test ### pass of_unittest_property_string():741
   ### dt-test ### pass of_unittest_property_string():744
   ### dt-test ### pass of_unittest_property_string():746
   ### dt-test ### pass of_unittest_property_string():749
   ### dt-test ### pass of_unittest_property_string():754
   ### dt-test ### pass of_unittest_property_string():756
   ### dt-test ### pass of_unittest_property_string():758
   ### dt-test ### pass of_unittest_property_string():761
   ### dt-test ### pass of_unittest_property_string():765
   ### dt-test ### pass of_unittest_property_string():768
   ### dt-test ### pass of_unittest_property_copy():783
   ### dt-test ### pass of_unittest_property_copy():789
   ### dt-test ### pass of_unittest_changeset():809
   ### dt-test ### pass of_unittest_changeset():812
   ### dt-test ### pass of_unittest_changeset():815
   ### dt-test ### pass of_unittest_changeset():819
   ### dt-test ### pass of_unittest_changeset():822
   ### dt-test ### pass of_unittest_changeset():825
   ### dt-test ### pass of_unittest_changeset():828
   ### dt-test ### pass of_unittest_changeset():831
   ### dt-test ### pass of_unittest_changeset():834
   ### dt-test ### pass of_unittest_changeset():842
   ### dt-test ### pass of_unittest_changeset():846
   ### dt-test ### pass of_unittest_changeset():847
   ### dt-test ### pass of_unittest_changeset():849
   ### dt-test ### pass of_unittest_changeset():850
   ### dt-test ### pass of_unittest_changeset():852
   ### dt-test ### pass of_unittest_changeset():853
   ### dt-test ### pass of_unittest_changeset():855
   ### dt-test ### pass of_unittest_changeset():857
   ### dt-test ### pass of_unittest_changeset():858
   ### dt-test ### pass of_unittest_changeset():859
   ### dt-test ### pass of_unittest_changeset():861
   ### dt-test ### pass of_unittest_changeset():866
   ### dt-test ### pass of_unittest_changeset():870
   ### dt-test ### pass of_unittest_parse_interrupts():1036
   ### dt-test ### pass of_unittest_parse_interrupts():1036
   ### dt-test ### pass of_unittest_parse_interrupts():1036
   ### dt-test ### pass of_unittest_parse_interrupts():1036
   ### dt-test ### pass of_unittest_parse_interrupts():1082
   ### dt-test ### pass of_unittest_parse_interrupts():1082
   ### dt-test ### pass of_unittest_parse_interrupts():1082
   ### dt-test ### pass of_unittest_parse_interrupts():1082
   ### dt-test ### pass of_unittest_parse_interrupts_extended():1162
   ### dt-test ### pass of_unittest_parse_interrupts_extended():1162
   ### dt-test ### pass of_unittest_parse_interrupts_extended():1162
   ### dt-test ### pass of_unittest_parse_interrupts_extended():1162
   ### dt-test ### pass of_unittest_parse_interrupts_extended():1162
   ### dt-test ### pass of_unittest_parse_interrupts_extended():1162
   ### dt-test ### pass of_unittest_parse_interrupts_extended():1162
   ### dt-test ### pass of_unittest_dma_get_max_cpu_address():895
   ### dt-test ### pass of_unittest_dma_ranges_one():916
   ### dt-test ### pass of_unittest_dma_ranges_one():934
   ### dt-test ### pass of_unittest_dma_ranges_one():937
   ### dt-test ### pass of_unittest_dma_ranges_one():916
   ### dt-test ### pass of_unittest_dma_ranges_one():934
   ### dt-test ### pass of_unittest_dma_ranges_one():937
   ### dt-test ### pass of_unittest_pci_dma_ranges():985
   ### dt-test ### pass of_unittest_pci_dma_ranges():988
   ### dt-test ### pass of_unittest_pci_dma_ranges():991
   ### dt-test ### pass of_unittest_pci_dma_ranges():995
   ### dt-test ### pass of_unittest_pci_dma_ranges():998
   ### dt-test ### pass of_unittest_pci_dma_ranges():1001
   ### dt-test ### pass of_unittest_match_node():1230
   ### dt-test ### pass of_unittest_match_node():1230
   ### dt-test ### pass of_unittest_match_node():1230
   ### dt-test ### pass of_unittest_match_node():1230
   ### dt-test ### pass of_unittest_match_node():1230
   ### dt-test ### pass of_unittest_match_node():1230
   ### dt-test ### pass of_unittest_match_node():1230
   ### dt-test ### pass of_unittest_match_node():1230
   ### dt-test ### pass of_unittest_match_node():1230
   ### dt-test ### pass of_unittest_match_node():1230
   ### dt-test ### pass of_unittest_match_node():1230
   ### dt-test ### pass of_unittest_match_node():1230
   ### dt-test ### pass of_unittest_platform_populate():1254
   ### dt-test ### pass of_unittest_platform_populate():1258
   ### dt-test ### pass of_unittest_platform_populate():1264
ok platform testcase-data:testcase-device2: error -ENXIO: IRQ index 0 not found
   ### dt-test ### pass of_unittest_platform_populate():1274
   ### dt-test ### pass of_unittest_platform_populate():1279
   ### dt-test ### pass of_unittest_platform_populate():1285
   ### dt-test ### pass of_unittest_platform_populate():1305
   ### dt-test ### pass of_unittest_platform_populate():1305
   ### dt-test ### pass of_unittest_platform_populate():1315
   ### dt-test ### pass of_unittest_platform_populate():1315
   ### dt-test ### pass of_unittest_overlay():2968
ok OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest0/status
   ### dt-test ### pass of_unittest_overlay_0():2099
ok OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest1/status
   ### dt-test ### pass of_unittest_overlay_1():2119
ok OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest2/status
   ### dt-test ### pass of_unittest_overlay_2():2139
ok OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest3/status
   ### dt-test ### pass of_unittest_overlay_3():2159
   ### dt-test ### pass of_unittest_overlay_4():2169
ok OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest5/status
   ### dt-test ### pass of_unittest_overlay_5():2189
ok OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest6/status
ok OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest7/status
   ### dt-test ### pass of_unittest_overlay_6():2290
ok OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest8/status
ok OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest8/property-foo
ok OF: overlay: node_overlaps_later_cs: #6 overlaps with #7 @/testcase-data/overlay-node/test-bus/test-unittest8
ok OF: overlay: overlay #6 is not topmost
   ### dt-test ### pass of_unittest_overlay_8():2383
   ### dt-test ### pass of_unittest_overlay_10():2395
   ### dt-test ### pass of_unittest_overlay_10():2401
   ### dt-test ### pass of_unittest_overlay_10():2407
   ### dt-test ### pass of_unittest_overlay_11():2419
   ### dt-test ### pass of_unittest_overlay_i2c_init():2640
   ### dt-test ### pass of_unittest_overlay_i2c_init():2646
ok i2c i2c-1: Added multiplexed i2c bus 2
   ### dt-test ### pass of_unittest_overlay_i2c_init():2660
   ### dt-test ### pass of_unittest_overlay():2984
ok OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/i2c-test-bus/test-unittest12/status
   ### dt-test ### pass of_unittest_overlay_i2c_12():2693
ok OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/i2c-test-bus/test-unittest13/status
   ### dt-test ### pass of_unittest_overlay_i2c_13():2713
ok i2c i2c-1: Added multiplexed i2c bus 3
   ### dt-test ### pass of_unittest_overlay_i2c_15():2737
   ### dt-test ### pass of_unittest_overlay_gpio():1698
   ### dt-test ### pass of_unittest_overlay_gpio():1701
   ### dt-test ### pass of_unittest_overlay_gpio():1704
ok gpio-708 (line-B-input): hogged as input
   ### dt-test ### pass unittest_gpio_probe():1621
ok gpio-712 (line-A-input): hogged as input
   ### dt-test ### pass unittest_gpio_probe():1621
   ### dt-test ### pass of_unittest_overlay_gpio():1719
   ### dt-test ### pass of_unittest_overlay_gpio():1727
   ### dt-test ### pass of_unittest_overlay_gpio():1730
ok gpio-720 (line-D-input): hogged as input
   ### dt-test ### pass unittest_gpio_probe():1621
   ### dt-test ### pass of_unittest_overlay_gpio():1756
   ### dt-test ### pass of_unittest_overlay_gpio():1762
   ### dt-test ### pass of_unittest_overlay_gpio():1765
   ### dt-test ### pass unittest_gpio_probe():1621
   ### dt-test ### pass of_unittest_overlay_gpio():1783
   ### dt-test ### pass of_unittest_overlay_gpio():1786
ok gpio-724 (line-C-input): hogged as input
   ### dt-test ### pass of_unittest_overlay_gpio():1803
   ### dt-test ### pass of_unittest_overlay_gpio():1809
   ### dt-test ### pass of_unittest_overlay_notify():2825
ok OF: overlay: overlay changeset pre-apply notifier error -16, target: /testcase-data/overlay-node/test-bus
   ### dt-test ### pass of_unittest_overlay_notify():2846
   ### dt-test ### pass of_unittest_overlay_notify():2851
ok OF: overlay: overlay changeset post-apply notifier error -17, target: /testcase-data/overlay-node/test-bus
   ### dt-test ### pass of_unittest_overlay_notify():2857
   ### dt-test ### pass of_unittest_overlay_notify():2862
   ### dt-test ### pass of_unittest_overlay_notify():2866
   ### dt-test ### pass of_unittest_overlay_notify():2872
   ### dt-test ### pass of_unittest_overlay_notify():2875
ok OF: overlay: overlay changeset pre-remove notifier error -18, target: /testcase-data/overlay-node/test-bus
   ### dt-test ### pass of_unittest_overlay_notify():2886
   ### dt-test ### pass of_unittest_overlay_notify():2894
   ### dt-test ### pass of_unittest_overlay_notify():2898
   ### dt-test ### pass of_unittest_overlay_notify():2901
ok OF: overlay: overlay changeset post-remove notifier error -19, target: /testcase-data/overlay-node/test-bus
   ### dt-test ### pass of_unittest_overlay_notify():2908
   ### dt-test ### pass of_unittest_overlay_notify():2915
   ### dt-test ### pass of_unittest_overlay_notify():2920
   ### dt-test ### pass of_unittest_overlay_notify():2932
   ### dt-test ### pass of_unittest_lifecycle():3031
   ### dt-test ### pass of_unittest_lifecycle():3056
ok OF: ERROR: of_node_release() detected bad of_node_put() on /testcase-data/refcount-node
   ### dt-test ### pass of_unittest_lifecycle():3076
ok ------------[ cut here ]------------
ok WARNING: CPU: 1 PID: 1 at lib/refcount.c:28 of_unittest+0x25d0/0x2eb8
ok refcount_t: underflow; use-after-free.
   Modules linked in:
   CPU: 1 PID: 1 Comm: swapper/0 Tainted: G                 N 6.2.0-rc1-00008-g0ad108551489 #23
   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 of_unittest+0x25d0/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
ok ---[ end trace 0000000000000000 ]---
   ### dt-test ### pass of_unittest_lifecycle():3093
   ### dt-test ### pass of_unittest_lifecycle():3119
   ### dt-test ### pass of_unittest_lifecycle():3120
   ### dt-test ### pass of_unittest_check_tree_linkage():270
   ### dt-test ### pass of_unittest_check_tree_linkage():271
ok OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data-2/substation@100/status
ok OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data-2/fairway-1/status
ok OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data-2/fairway-1/ride@100/track@30/incline-up
ok OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data-2/fairway-1/ride@100/track@40/incline-up
ok OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data-2/lights@40000/status
ok OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data-2/lights@40000/color
ok OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data-2/lights@40000/rate
ok OF: overlay: WARNING: memory leak will occur if overlay removed, property: /__symbols__/hvac_2
ok OF: overlay: WARNING: memory leak will occur if overlay removed, property: /__symbols__/ride_200
ok OF: overlay: WARNING: memory leak will occur if overlay removed, property: /__symbols__/ride_200_left
ok OF: overlay: WARNING: memory leak will occur if overlay removed, property: /__symbols__/ride_200_right
   ### dt-test ### pass of_unittest_overlay_high_level():3552
ok OF: overlay: ERROR: multiple fragments add and/or delete node /testcase-data-2/substation@100/motor-1/controller
ok OF: overlay: ERROR: multiple fragments add, update, and/or delete property /testcase-data-2/substation@100/motor-1/controller/name
   ### dt-test ### pass of_unittest_overlay_high_level():3559
ok OF: overlay: ERROR: multiple fragments add and/or delete node /testcase-data-2/substation@100/motor-1/electric
ok OF: overlay: ERROR: multiple fragments add, update, and/or delete property /testcase-data-2/substation@100/motor-1/electric/rpm_avail
ok OF: overlay: ERROR: multiple fragments add, update, and/or delete property /testcase-data-2/substation@100/motor-1/electric/name
   ### dt-test ### pass of_unittest_overlay_high_level():3574
   ### dt-test ### pass of_unittest_overlay_high_level():3584
   ### dt-test ### pass of_unittest_overlay_high_level():3587
-> ### dt-test ### end of unittest - 276 passed, 0 failed


<< post-test console output deleted >>

   / # cat /proc/version
   Linux version 6.2.0-rc1-00008-g0ad108551489 (frowand@xps8900) (arm-linux-gnueabi-gcc (Ubuntu 9.4.0-1ubuntu1~20.04.1) 9.4.0, GNU ld (GNU Binutils for Ubuntu) 2.34) #23 SMP PREEMPT Mon Feb 13 12:52:35 CST 2023
   / # 

** EXPECT statistics:
**
**   non-zero values expected:
**
**     EXPECT found              :   55
**     EXPECT_NOT not found      :    4
**
**   zero values expected:
**
**     EXPECT not found          :    0
**     missing EXPECT begin      :    0
**     missing EXPECT end        :    0
**
**     EXPECT_NOT found          :    0
**     missing EXPECT_NOT begin  :    0
**     missing EXPECT_NOT end    :    0
**
**     unittest FAIL             :    0
**     internal error            :    0

Re: [PATCH 5/7] of: do not use "%pOF" printk format on node with refcount of zero

[Frank Rowand]

On 2/13/23 13:23, Frank Rowand wrote:
> On 2/13/23 12:57, Frank Rowand wrote:
>> of_node_release() can not use the "%pOF" printk format to report
>> the node name of a node when the node reference count is zero.
>> This is because the formatter device_node_string() calls
>> fwnode_full_name_string() which indirectly calls of_node_get().
>> Calling of_node_get() on the node with a zero reference count
>> results in a WARNING and stack trace.
>>
>> When the reference count has been decremented to zero, this function
>> is in the subsequent call path which frees memory related to the node.
>>
>> This commit resolves the unittest EXPECT errors that were created in
>> the previous commmit.
>>
>> Signed-off-by: Frank Rowand <frowand.list@gmail.com>
>> ---
> 
> < snip >
> 
> After applying this commit, the output of unittests, as processed by
> scripts/dtc/of_unittest_expect, including the new lifecycle tests is:

< snip >

And the more verbose, ugly, full console output before processing by
scripts/dtc/of_unittest_expect is:



<< pre-test console output deleted >>

### dt-test ### start of unittest - you will see error messages
l16: Bringing 0uV into 2700000-2700000uV
### dt-test ### EXPECT \ : Duplicate name in testcase-data, renamed to "duplicate-name#1"
Duplicate name in testcase-data, renamed to "duplicate-name#1"
l17: Bringing 0uV into 2700000-2700000uV
### dt-test ### EXPECT / : Duplicate name in testcase-data, renamed to "duplicate-name#1"
l18: Bringing 0uV into 2850000-2850000uV
### dt-test ### pass of_unittest_check_tree_linkage():270
l19: Bringing 0uV into 3300000-3300000uV
### dt-test ### pass of_unittest_check_tree_linkage():271
sdhci_msm f98a4900.mmc: Got CD GPIO
### dt-test ### pass of_unittest_check_phandles():379
l20: Bringing 0uV into 2950000-2950000uV
### dt-test ### pass of_unittest_find_node_by_name():80
sdhci_msm f98a4900.mmc: Got CD GPIO
### dt-test ### pass of_unittest_find_node_by_name():87
l21: Bringing 0uV into 2950000-2950000uV
### dt-test ### pass of_unittest_find_node_by_name():91
l22: Bringing 0uV into 3000000-3000000uV
sdhci_msm f98a4900.mmc: Got CD GPIO
l23: Bringing 0uV into 3000000-3000000uV
### dt-test ### pass of_unittest_find_node_by_name():98
l24: Bringing 0uV into 3075000-3075000uV
### dt-test ### pass of_unittest_find_node_by_name():105
### dt-test ### pass of_unittest_find_node_by_name():109
### dt-test ### pass of_unittest_find_node_by_name():115
### dt-test ### pass of_unittest_find_node_by_name():119
### dt-test ### pass of_unittest_find_node_by_name():123
### dt-test ### pass of_unittest_find_node_by_name():127
mmc0: SDHCI controller on f9824900.mmc [f9824900.mmc] using ADMA
### dt-test ### pass of_unittest_find_node_by_name():132
### dt-test ### pass of_unittest_find_node_by_name():137
### dt-test ### pass of_unittest_find_node_by_name():142
### dt-test ### pass of_unittest_find_node_by_name():147
### dt-test ### pass of_unittest_find_node_by_name():153
mmc1: SDHCI controller on f98a4900.mmc [f98a4900.mmc] using ADMA
### dt-test ### pass of_unittest_find_node_by_name():158
### dt-test ### pass of_unittest_find_node_by_name():163
### dt-test ### pass of_unittest_find_node_by_name():168
### dt-test ### pass of_unittest_dynamic():194
### dt-test ### pass of_unittest_dynamic():201
### dt-test ### pass of_unittest_dynamic():207
mmc0: new HS200 MMC card at address 0001
### dt-test ### pass of_unittest_dynamic():215
### dt-test ### pass of_unittest_dynamic():219
mmcblk0: mmc0:0001 SEM16G 14.7 GiB 
### dt-test ### pass of_unittest_dynamic():227
mmc1: new ultra high speed DDR50 SDHC card at address aaaa
### dt-test ### pass of_unittest_dynamic():229
### dt-test ### pass of_unittest_parse_phandle_with_args():402
mmcblk1: mmc1:aaaa SU16G 14.8 GiB 
### dt-test ### pass of_unittest_parse_phandle_with_args():456
 mmcblk0: p1 p2 p3 p4 p5 p6 p7 p8 p9 p10 p11 p12 p13 p14 p15 p16 p17 p18 p19 p20
### dt-test ### pass of_unittest_parse_phandle_with_args():456
 mmcblk1: p1
### dt-test ### pass of_unittest_parse_phandle_with_args():456
### dt-test ### pass of_unittest_parse_phandle_with_args():456
### dt-test ### pass of_unittest_parse_phandle_with_args():456
### dt-test ### pass of_unittest_parse_phandle_with_args():456
### dt-test ### pass of_unittest_parse_phandle_with_args():456
### dt-test ### pass of_unittest_parse_phandle_with_args():456
### dt-test ### pass of_unittest_parse_phandle_with_args():464
### dt-test ### pass of_unittest_parse_phandle_with_args():467
### dt-test ### EXPECT \ : OF: /testcase-data/phandle-tests/consumer-a: could not get #phandle-cells-missing for /testcase-data/phandle-tests/provider1
OF: /testcase-data/phandle-tests/consumer-a: could not get #phandle-cells-missing for /testcase-data/phandle-tests/provider1
mmcblk0boot0: mmc0:0001 SEM16G 4.00 MiB 
### dt-test ### EXPECT / : OF: /testcase-data/phandle-tests/consumer-a: could not get #phandle-cells-missing for /testcase-data/phandle-tests/provider1
### dt-test ### pass of_unittest_parse_phandle_with_args():481
### dt-test ### EXPECT \ : OF: /testcase-data/phandle-tests/consumer-a: could not get #phandle-cells-missing for /testcase-data/phandle-tests/provider1
mmcblk0boot1: mmc0:0001 SEM16G 4.00 MiB 
OF: /testcase-data/phandle-tests/consumer-a: could not get #phandle-cells-missing for /testcase-data/phandle-tests/provider1
mmcblk0rpmb: mmc0:0001 SEM16G 4.00 MiB, chardev (241:0)
### dt-test ### EXPECT / : OF: /testcase-data/phandle-tests/consumer-a: could not get #phandle-cells-missing for /testcase-data/phandle-tests/provider1
### dt-test ### pass of_unittest_parse_phandle_with_args():492
### dt-test ### EXPECT \ : OF: /testcase-data/phandle-tests/consumer-a: could not find phandle
OF: /testcase-data/phandle-tests/consumer-a: could not find phandle 12345678
### dt-test ### EXPECT / : OF: /testcase-data/phandle-tests/consumer-a: could not find phandle
### dt-test ### pass of_unittest_parse_phandle_with_args():506
### dt-test ### EXPECT \ : OF: /testcase-data/phandle-tests/consumer-a: could not find phandle
OF: /testcase-data/phandle-tests/consumer-a: could not find phandle 12345678
### dt-test ### EXPECT / : OF: /testcase-data/phandle-tests/consumer-a: could not find phandle
### dt-test ### pass of_unittest_parse_phandle_with_args():517
### dt-test ### EXPECT \ : OF: /testcase-data/phandle-tests/consumer-a: #phandle-cells = 3 found 1
OF: /testcase-data/phandle-tests/consumer-a: #phandle-cells = 3 found 1
### dt-test ### EXPECT / : OF: /testcase-data/phandle-tests/consumer-a: #phandle-cells = 3 found 1
### dt-test ### pass of_unittest_parse_phandle_with_args():531
### dt-test ### EXPECT \ : OF: /testcase-data/phandle-tests/consumer-a: #phandle-cells = 3 found 1
OF: /testcase-data/phandle-tests/consumer-a: #phandle-cells = 3 found 1
### dt-test ### EXPECT / : OF: /testcase-data/phandle-tests/consumer-a: #phandle-cells = 3 found 1
### dt-test ### pass of_unittest_parse_phandle_with_args():542
### dt-test ### pass of_unittest_parse_phandle_with_args_map():582
### dt-test ### pass of_unittest_parse_phandle_with_args_map():640
### dt-test ### pass of_unittest_parse_phandle_with_args_map():640
### dt-test ### pass of_unittest_parse_phandle_with_args_map():640
### dt-test ### pass of_unittest_parse_phandle_with_args_map():640
### dt-test ### pass of_unittest_parse_phandle_with_args_map():640
### dt-test ### pass of_unittest_parse_phandle_with_args_map():640
### dt-test ### pass of_unittest_parse_phandle_with_args_map():640
### dt-test ### pass of_unittest_parse_phandle_with_args_map():640
### dt-test ### pass of_unittest_parse_phandle_with_args_map():648
### dt-test ### EXPECT \ : OF: /testcase-data/phandle-tests/consumer-b: could not get #phandle-missing-cells for /testcase-data/phandle-tests/provider1
OF: /testcase-data/phandle-tests/consumer-b: could not get #phandle-missing-cells for /testcase-data/phandle-tests/provider1
### dt-test ### EXPECT / : OF: /testcase-data/phandle-tests/consumer-b: could not get #phandle-missing-cells for /testcase-data/phandle-tests/provider1
### dt-test ### pass of_unittest_parse_phandle_with_args_map():661
### dt-test ### EXPECT \ : OF: /testcase-data/phandle-tests/consumer-b: could not find phandle
OF: /testcase-data/phandle-tests/consumer-b: could not find phandle 12345678
### dt-test ### EXPECT / : OF: /testcase-data/phandle-tests/consumer-b: could not find phandle
### dt-test ### pass of_unittest_parse_phandle_with_args_map():674
### dt-test ### EXPECT \ : OF: /testcase-data/phandle-tests/consumer-b: #phandle-cells = 2 found 1
OF: /testcase-data/phandle-tests/consumer-b: #phandle-cells = 2 found 1
### dt-test ### EXPECT / : OF: /testcase-data/phandle-tests/consumer-b: #phandle-cells = 2 found 1
### dt-test ### pass of_unittest_parse_phandle_with_args_map():687
### dt-test ### pass of_unittest_printf_one():294
### dt-test ### pass of_unittest_printf_one():304
### dt-test ### pass of_unittest_printf_one():304
### dt-test ### pass of_unittest_printf_one():294
### dt-test ### pass of_unittest_printf_one():304
### dt-test ### pass of_unittest_printf_one():304
### dt-test ### pass of_unittest_printf_one():294
### dt-test ### pass of_unittest_printf_one():304
### dt-test ### pass of_unittest_printf_one():304
### dt-test ### pass of_unittest_printf_one():294
### dt-test ### pass of_unittest_printf_one():304
### dt-test ### pass of_unittest_printf_one():304
### dt-test ### pass of_unittest_printf_one():294
### dt-test ### pass of_unittest_printf_one():304
### dt-test ### pass of_unittest_printf_one():304
### dt-test ### pass of_unittest_printf_one():294
### dt-test ### pass of_unittest_printf_one():304
### dt-test ### pass of_unittest_printf_one():304
### dt-test ### pass of_unittest_printf_one():294
### dt-test ### pass of_unittest_printf_one():304
### dt-test ### pass of_unittest_printf_one():304
### dt-test ### pass of_unittest_printf_one():294
### dt-test ### pass of_unittest_printf_one():304
### dt-test ### pass of_unittest_printf_one():304
### dt-test ### pass of_unittest_printf_one():294
### dt-test ### pass of_unittest_printf_one():304
### dt-test ### pass of_unittest_printf_one():304
### dt-test ### pass of_unittest_printf_one():294
### dt-test ### pass of_unittest_printf_one():304
### dt-test ### pass of_unittest_printf_one():304
### dt-test ### pass of_unittest_printf_one():294
### dt-test ### pass of_unittest_printf_one():304
### dt-test ### pass of_unittest_printf_one():304
### dt-test ### pass of_unittest_printf_one():294
### dt-test ### pass of_unittest_printf_one():304
### dt-test ### pass of_unittest_printf_one():304
### dt-test ### pass of_unittest_printf_one():294
### dt-test ### pass of_unittest_printf_one():304
### dt-test ### pass of_unittest_printf_one():304
### dt-test ### pass of_unittest_printf_one():294
### dt-test ### pass of_unittest_printf_one():304
### dt-test ### pass of_unittest_printf_one():304
### dt-test ### pass of_unittest_printf_one():294
### dt-test ### pass of_unittest_printf_one():304
### dt-test ### pass of_unittest_printf_one():304
### dt-test ### pass of_unittest_printf_one():294
### dt-test ### pass of_unittest_printf_one():304
### dt-test ### pass of_unittest_printf_one():304
### dt-test ### pass of_unittest_printf_one():294
### dt-test ### pass of_unittest_printf_one():304
### dt-test ### pass of_unittest_printf_one():304
### dt-test ### pass of_unittest_property_string():703
### dt-test ### pass of_unittest_property_string():705
### dt-test ### pass of_unittest_property_string():707
### dt-test ### pass of_unittest_property_string():709
### dt-test ### pass of_unittest_property_string():711
### dt-test ### pass of_unittest_property_string():713
### dt-test ### pass of_unittest_property_string():715
### dt-test ### pass of_unittest_property_string():719
### dt-test ### pass of_unittest_property_string():721
### dt-test ### pass of_unittest_property_string():723
### dt-test ### pass of_unittest_property_string():725
### dt-test ### pass of_unittest_property_string():729
### dt-test ### pass of_unittest_property_string():732
### dt-test ### pass of_unittest_property_string():734
### dt-test ### pass of_unittest_property_string():736
### dt-test ### pass of_unittest_property_string():738
### dt-test ### pass of_unittest_property_string():741
### dt-test ### pass of_unittest_property_string():744
### dt-test ### pass of_unittest_property_string():746
### dt-test ### pass of_unittest_property_string():749
### dt-test ### pass of_unittest_property_string():754
### dt-test ### pass of_unittest_property_string():756
### dt-test ### pass of_unittest_property_string():758
### dt-test ### pass of_unittest_property_string():761
### dt-test ### pass of_unittest_property_string():765
### dt-test ### pass of_unittest_property_string():768
### dt-test ### pass of_unittest_property_copy():783
### dt-test ### pass of_unittest_property_copy():789
### dt-test ### pass of_unittest_changeset():809
### dt-test ### pass of_unittest_changeset():812
### dt-test ### pass of_unittest_changeset():815
### dt-test ### pass of_unittest_changeset():819
### dt-test ### pass of_unittest_changeset():822
### dt-test ### pass of_unittest_changeset():825
### dt-test ### pass of_unittest_changeset():828
### dt-test ### pass of_unittest_changeset():831
### dt-test ### pass of_unittest_changeset():834
### dt-test ### pass of_unittest_changeset():842
### dt-test ### pass of_unittest_changeset():846
### dt-test ### pass of_unittest_changeset():847
### dt-test ### pass of_unittest_changeset():849
### dt-test ### pass of_unittest_changeset():850
### dt-test ### pass of_unittest_changeset():852
### dt-test ### pass of_unittest_changeset():853
### dt-test ### pass of_unittest_changeset():855
### dt-test ### pass of_unittest_changeset():857
### dt-test ### pass of_unittest_changeset():858
### dt-test ### pass of_unittest_changeset():859
### dt-test ### pass of_unittest_changeset():861
### dt-test ### pass of_unittest_changeset():866
### dt-test ### pass of_unittest_changeset():870
### dt-test ### pass of_unittest_parse_interrupts():1036
### dt-test ### pass of_unittest_parse_interrupts():1036
### dt-test ### pass of_unittest_parse_interrupts():1036
### dt-test ### pass of_unittest_parse_interrupts():1036
### dt-test ### pass of_unittest_parse_interrupts():1082
### dt-test ### pass of_unittest_parse_interrupts():1082
### dt-test ### pass of_unittest_parse_interrupts():1082
### dt-test ### pass of_unittest_parse_interrupts():1082
### dt-test ### pass of_unittest_parse_interrupts_extended():1162
### dt-test ### pass of_unittest_parse_interrupts_extended():1162
### dt-test ### pass of_unittest_parse_interrupts_extended():1162
### dt-test ### pass of_unittest_parse_interrupts_extended():1162
### dt-test ### pass of_unittest_parse_interrupts_extended():1162
### dt-test ### pass of_unittest_parse_interrupts_extended():1162
### dt-test ### pass of_unittest_parse_interrupts_extended():1162
### dt-test ### pass of_unittest_dma_get_max_cpu_address():895
### dt-test ### pass of_unittest_dma_ranges_one():916
### dt-test ### pass of_unittest_dma_ranges_one():934
### dt-test ### pass of_unittest_dma_ranges_one():937
### dt-test ### pass of_unittest_dma_ranges_one():916
### dt-test ### pass of_unittest_dma_ranges_one():934
### dt-test ### pass of_unittest_dma_ranges_one():937
### dt-test ### pass of_unittest_pci_dma_ranges():985
### dt-test ### pass of_unittest_pci_dma_ranges():988
### dt-test ### pass of_unittest_pci_dma_ranges():991
### dt-test ### pass of_unittest_pci_dma_ranges():995
### dt-test ### pass of_unittest_pci_dma_ranges():998
### dt-test ### pass of_unittest_pci_dma_ranges():1001
### dt-test ### pass of_unittest_match_node():1230
### dt-test ### pass of_unittest_match_node():1230
### dt-test ### pass of_unittest_match_node():1230
### dt-test ### pass of_unittest_match_node():1230
### dt-test ### pass of_unittest_match_node():1230
### dt-test ### pass of_unittest_match_node():1230
### dt-test ### pass of_unittest_match_node():1230
### dt-test ### pass of_unittest_match_node():1230
### dt-test ### pass of_unittest_match_node():1230
### dt-test ### pass of_unittest_match_node():1230
### dt-test ### pass of_unittest_match_node():1230
### dt-test ### pass of_unittest_match_node():1230
### dt-test ### pass of_unittest_platform_populate():1254
### dt-test ### pass of_unittest_platform_populate():1258
### dt-test ### pass of_unittest_platform_populate():1264
### dt-test ### EXPECT \ : platform testcase-data:testcase-device2: error -ENXIO: IRQ index 0 not found
platform testcase-data:testcase-device2: error -ENXIO: IRQ index 0 not found
### dt-test ### EXPECT / : platform testcase-data:testcase-device2: error -ENXIO: IRQ index 0 not found
### dt-test ### pass of_unittest_platform_populate():1274
### dt-test ### pass of_unittest_platform_populate():1279
### dt-test ### pass of_unittest_platform_populate():1285
### dt-test ### pass of_unittest_platform_populate():1305
### dt-test ### pass of_unittest_platform_populate():1305
### dt-test ### pass of_unittest_platform_populate():1315
### dt-test ### pass of_unittest_platform_populate():1315
### dt-test ### pass of_unittest_overlay():2968
### dt-test ### EXPECT \ : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest0/status
OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest0/status
### dt-test ### EXPECT / : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest0/status
### dt-test ### pass of_unittest_overlay_0():2099
### dt-test ### EXPECT \ : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest1/status
OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest1/status
### dt-test ### EXPECT / : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest1/status
### dt-test ### pass of_unittest_overlay_1():2119
### dt-test ### EXPECT \ : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest2/status
OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest2/status
### dt-test ### EXPECT / : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest2/status
### dt-test ### pass of_unittest_overlay_2():2139
### dt-test ### EXPECT \ : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest3/status
OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest3/status
### dt-test ### EXPECT / : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest3/status
### dt-test ### pass of_unittest_overlay_3():2159
### dt-test ### pass of_unittest_overlay_4():2169
### dt-test ### EXPECT \ : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest5/status
OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest5/status
### dt-test ### EXPECT / : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest5/status
### dt-test ### pass of_unittest_overlay_5():2189
### dt-test ### EXPECT \ : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest6/status
OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest6/status
### dt-test ### EXPECT / : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest6/status
### dt-test ### EXPECT \ : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest7/status
OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest7/status
### dt-test ### EXPECT / : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest7/status
### dt-test ### pass of_unittest_overlay_6():2290
### dt-test ### EXPECT \ : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest8/status
OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest8/status
### dt-test ### EXPECT / : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest8/status
### dt-test ### EXPECT \ : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest8/property-foo
OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest8/property-foo
### dt-test ### EXPECT / : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest8/property-foo
### dt-test ### EXPECT \ : OF: overlay: node_overlaps_later_cs: #6 overlaps with #7 @/testcase-data/overlay-node/test-bus/test-unittest8
### dt-test ### EXPECT \ : OF: overlay: overlay #6 is not topmost
OF: overlay: node_overlaps_later_cs: #6 overlaps with #7 @/testcase-data/overlay-node/test-bus/test-unittest8
OF: overlay: overlay #6 is not topmost
### dt-test ### EXPECT / : OF: overlay: overlay #6 is not topmost
### dt-test ### EXPECT / : OF: overlay: node_overlaps_later_cs: #6 overlaps with #7 @/testcase-data/overlay-node/test-bus/test-unittest8
### dt-test ### pass of_unittest_overlay_8():2383
### dt-test ### pass of_unittest_overlay_10():2395
### dt-test ### pass of_unittest_overlay_10():2401
### dt-test ### pass of_unittest_overlay_10():2407
### dt-test ### pass of_unittest_overlay_11():2419
### dt-test ### pass of_unittest_overlay_i2c_init():2640
### dt-test ### pass of_unittest_overlay_i2c_init():2646
### dt-test ### EXPECT \ : i2c i2c-1: Added multiplexed i2c bus 2
i2c i2c-1: Added multiplexed i2c bus 2
### dt-test ### EXPECT / : i2c i2c-1: Added multiplexed i2c bus 2
### dt-test ### pass of_unittest_overlay_i2c_init():2660
### dt-test ### pass of_unittest_overlay():2984
### dt-test ### EXPECT \ : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/i2c-test-bus/test-unittest12/status
OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/i2c-test-bus/test-unittest12/status
### dt-test ### EXPECT / : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/i2c-test-bus/test-unittest12/status
### dt-test ### pass of_unittest_overlay_i2c_12():2693
### dt-test ### EXPECT \ : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/i2c-test-bus/test-unittest13/status
OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/i2c-test-bus/test-unittest13/status
### dt-test ### EXPECT / : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/i2c-test-bus/test-unittest13/status
### dt-test ### pass of_unittest_overlay_i2c_13():2713
### dt-test ### EXPECT \ : i2c i2c-1: Added multiplexed i2c bus 3
i2c i2c-1: Added multiplexed i2c bus 3
### dt-test ### EXPECT / : i2c i2c-1: Added multiplexed i2c bus 3
### dt-test ### pass of_unittest_overlay_i2c_15():2737
### dt-test ### pass of_unittest_overlay_gpio():1698
### dt-test ### pass of_unittest_overlay_gpio():1701
### dt-test ### pass of_unittest_overlay_gpio():1704
### dt-test ### EXPECT \ : gpio-<<int>> (line-B-input): hogged as input
### dt-test ### EXPECT \ : gpio-<<int>> (line-A-input): hogged as input
gpio-708 (line-B-input): hogged as input
### dt-test ### pass unittest_gpio_probe():1621
gpio-712 (line-A-input): hogged as input
### dt-test ### pass unittest_gpio_probe():1621
### dt-test ### pass of_unittest_overlay_gpio():1719
### dt-test ### EXPECT / : gpio-<<int>> (line-A-input): hogged as input
### dt-test ### EXPECT / : gpio-<<int>> (line-B-input): hogged as input
### dt-test ### pass of_unittest_overlay_gpio():1727
### dt-test ### pass of_unittest_overlay_gpio():1730
### dt-test ### EXPECT \ : gpio-<<int>> (line-D-input): hogged as input
gpio-720 (line-D-input): hogged as input
### dt-test ### pass unittest_gpio_probe():1621
### dt-test ### pass of_unittest_overlay_gpio():1756
### dt-test ### EXPECT / : gpio-<<int>> (line-D-input): hogged as input
### dt-test ### pass of_unittest_overlay_gpio():1762
### dt-test ### pass of_unittest_overlay_gpio():1765
### dt-test ### pass unittest_gpio_probe():1621
### dt-test ### pass of_unittest_overlay_gpio():1783
### dt-test ### pass of_unittest_overlay_gpio():1786
### dt-test ### EXPECT \ : gpio-<<int>> (line-C-input): hogged as input
gpio-724 (line-C-input): hogged as input
### dt-test ### pass of_unittest_overlay_gpio():1803
### dt-test ### EXPECT / : gpio-<<int>> (line-C-input): hogged as input
### dt-test ### pass of_unittest_overlay_gpio():1809
### dt-test ### pass of_unittest_overlay_notify():2825
### dt-test ### EXPECT \ : OF: overlay: overlay changeset pre-apply notifier error -16, target: /testcase-data/overlay-node/test-bus
OF: overlay: overlay changeset pre-apply notifier error -16, target: /testcase-data/overlay-node/test-bus
### dt-test ### pass of_unittest_overlay_notify():2846
### dt-test ### EXPECT / : OF: overlay: overlay changeset pre-apply notifier error -16, target: /testcase-data/overlay-node/test-bus
### dt-test ### pass of_unittest_overlay_notify():2851
### dt-test ### EXPECT \ : OF: overlay: overlay changeset post-apply notifier error -17, target: /testcase-data/overlay-node/test-bus
OF: overlay: overlay changeset post-apply notifier error -17, target: /testcase-data/overlay-node/test-bus
### dt-test ### pass of_unittest_overlay_notify():2857
### dt-test ### EXPECT / : OF: overlay: overlay changeset post-apply notifier error -17, target: /testcase-data/overlay-node/test-bus
### dt-test ### pass of_unittest_overlay_notify():2862
### dt-test ### pass of_unittest_overlay_notify():2866
### dt-test ### pass of_unittest_overlay_notify():2872
### dt-test ### pass of_unittest_overlay_notify():2875
### dt-test ### EXPECT \ : OF: overlay: overlay changeset pre-remove notifier error -18, target: /testcase-data/overlay-node/test-bus
OF: overlay: overlay changeset pre-remove notifier error -18, target: /testcase-data/overlay-node/test-bus
### dt-test ### EXPECT / : OF: overlay: overlay changeset pre-remove notifier error -18, target: /testcase-data/overlay-node/test-bus
### dt-test ### pass of_unittest_overlay_notify():2886
### dt-test ### pass of_unittest_overlay_notify():2894
### dt-test ### pass of_unittest_overlay_notify():2898
### dt-test ### pass of_unittest_overlay_notify():2901
### dt-test ### EXPECT \ : OF: overlay: overlay changeset post-remove notifier error -19, target: /testcase-data/overlay-node/test-bus
OF: overlay: overlay changeset post-remove notifier error -19, target: /testcase-data/overlay-node/test-bus
### dt-test ### EXPECT / : OF: overlay: overlay changeset post-remove notifier error -19, target: /testcase-data/overlay-node/test-bus
### dt-test ### pass of_unittest_overlay_notify():2908
### dt-test ### pass of_unittest_overlay_notify():2915
### dt-test ### pass of_unittest_overlay_notify():2920
### dt-test ### pass of_unittest_overlay_notify():2932
### dt-test ### pass of_unittest_lifecycle():3031
### dt-test ### EXPECT \ : OF: ERROR: of_node_release() detected bad of_node_put() on /testcase-data/refcount-node
### dt-test ### pass of_unittest_lifecycle():3056
OF: ERROR: of_node_release() detected bad of_node_put() on /testcase-data/refcount-node
### dt-test ### EXPECT / : OF: ERROR: of_node_release() detected bad of_node_put() on /testcase-data/refcount-node
### dt-test ### EXPECT \ : ------------[ cut here ]------------
### dt-test ### EXPECT \ : WARNING: <<all>>
### dt-test ### EXPECT \ : refcount_t: underflow; use-after-free.
### dt-test ### EXPECT \ : ---[ end trace <<int>> ]---
### dt-test ### pass of_unittest_lifecycle():3076
------------[ cut here ]------------
WARNING: CPU: 1 PID: 1 at lib/refcount.c:28 of_unittest+0x25d0/0x2eb8
refcount_t: underflow; use-after-free.
Modules linked in:
CPU: 1 PID: 1 Comm: swapper/0 Tainted: G                 N 6.2.0-rc1-00008-g0ad108551489 #23
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 of_unittest+0x25d0/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 ]---
### dt-test ### EXPECT / : ---[ end trace <<int>> ]---
### dt-test ### EXPECT / : refcount_t: underflow; use-after-free.
### dt-test ### EXPECT / : WARNING: <<all>>
### dt-test ### EXPECT / : ------------[ cut here ]------------
### dt-test ### EXPECT_NOT \ : ------------[ cut here ]------------
### dt-test ### EXPECT_NOT \ : WARNING: <<all>>
### dt-test ### EXPECT_NOT \ : refcount_t: underflow; use-after-free.
### dt-test ### EXPECT_NOT \ : ---[ end trace <<int>> ]---
### dt-test ### pass of_unittest_lifecycle():3093
### dt-test ### EXPECT_NOT / : ---[ end trace <<int>> ]---
### dt-test ### EXPECT_NOT / : refcount_t: underflow; use-after-free.
### dt-test ### EXPECT_NOT / : WARNING: <<all>>
### dt-test ### EXPECT_NOT / : ------------[ cut here ]------------
### dt-test ### pass of_unittest_lifecycle():3119
### dt-test ### pass of_unittest_lifecycle():3120
### dt-test ### pass of_unittest_check_tree_linkage():270
### dt-test ### pass of_unittest_check_tree_linkage():271
### dt-test ### EXPECT \ : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data-2/substation@100/status
### dt-test ### EXPECT \ : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data-2/fairway-1/status
### dt-test ### EXPECT \ : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data-2/fairway-1/ride@100/track@30/incline-up
### dt-test ### EXPECT \ : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data-2/fairway-1/ride@100/track@40/incline-up
### dt-test ### EXPECT \ : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data-2/lights@40000/status
### dt-test ### EXPECT \ : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data-2/lights@40000/color
### dt-test ### EXPECT \ : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data-2/lights@40000/rate
### dt-test ### EXPECT \ : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /__symbols__/hvac_2
### dt-test ### EXPECT \ : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /__symbols__/ride_200
### dt-test ### EXPECT \ : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /__symbols__/ride_200_left
### dt-test ### EXPECT \ : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /__symbols__/ride_200_right
OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data-2/substation@100/status
OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data-2/fairway-1/status
OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data-2/fairway-1/ride@100/track@30/incline-up
OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data-2/fairway-1/ride@100/track@40/incline-up
OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data-2/lights@40000/status
OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data-2/lights@40000/color
OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data-2/lights@40000/rate
OF: overlay: WARNING: memory leak will occur if overlay removed, property: /__symbols__/hvac_2
OF: overlay: WARNING: memory leak will occur if overlay removed, property: /__symbols__/ride_200
OF: overlay: WARNING: memory leak will occur if overlay removed, property: /__symbols__/ride_200_left
OF: overlay: WARNING: memory leak will occur if overlay removed, property: /__symbols__/ride_200_right
### dt-test ### EXPECT / : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /__symbols__/ride_200_right
### dt-test ### EXPECT / : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /__symbols__/ride_200_left
### dt-test ### EXPECT / : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /__symbols__/ride_200
### dt-test ### EXPECT / : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /__symbols__/hvac_2
### dt-test ### EXPECT / : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data-2/lights@40000/rate
### dt-test ### EXPECT / : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data-2/lights@40000/color
### dt-test ### EXPECT / : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data-2/lights@40000/status
### dt-test ### EXPECT / : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data-2/fairway-1/ride@100/track@40/incline-up
### dt-test ### EXPECT / : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data-2/fairway-1/ride@100/track@30/incline-up
### dt-test ### EXPECT / : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data-2/fairway-1/status
### dt-test ### EXPECT / : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data-2/substation@100/status
### dt-test ### pass of_unittest_overlay_high_level():3552
### dt-test ### EXPECT \ : OF: overlay: ERROR: multiple fragments add and/or delete node /testcase-data-2/substation@100/motor-1/controller
### dt-test ### EXPECT \ : OF: overlay: ERROR: multiple fragments add, update, and/or delete property /testcase-data-2/substation@100/motor-1/controller/name
OF: overlay: ERROR: multiple fragments add and/or delete node /testcase-data-2/substation@100/motor-1/controller
OF: overlay: ERROR: multiple fragments add, update, and/or delete property /testcase-data-2/substation@100/motor-1/controller/name
### dt-test ### pass of_unittest_overlay_high_level():3559
### dt-test ### EXPECT / : OF: overlay: ERROR: multiple fragments add, update, and/or delete property /testcase-data-2/substation@100/motor-1/controller/name
### dt-test ### EXPECT / : OF: overlay: ERROR: multiple fragments add and/or delete node /testcase-data-2/substation@100/motor-1/controller
### dt-test ### EXPECT \ : OF: overlay: ERROR: multiple fragments add and/or delete node /testcase-data-2/substation@100/motor-1/electric
### dt-test ### EXPECT \ : OF: overlay: ERROR: multiple fragments add, update, and/or delete property /testcase-data-2/substation@100/motor-1/electric/rpm_avail
### dt-test ### EXPECT \ : OF: overlay: ERROR: multiple fragments add, update, and/or delete property /testcase-data-2/substation@100/motor-1/electric/name
OF: overlay: ERROR: multiple fragments add and/or delete node /testcase-data-2/substation@100/motor-1/electric
OF: overlay: ERROR: multiple fragments add, update, and/or delete property /testcase-data-2/substation@100/motor-1/electric/rpm_avail
OF: overlay: ERROR: multiple fragments add, update, and/or delete property /testcase-data-2/substation@100/motor-1/electric/name
### dt-test ### pass of_unittest_overlay_high_level():3574
### dt-test ### EXPECT / : OF: overlay: ERROR: multiple fragments add, update, and/or delete property /testcase-data-2/substation@100/motor-1/electric/name
### dt-test ### EXPECT / : OF: overlay: ERROR: multiple fragments add, update, and/or delete property /testcase-data-2/substation@100/motor-1/electric/rpm_avail
### dt-test ### EXPECT / : OF: overlay: ERROR: multiple fragments add and/or delete node /testcase-data-2/substation@100/motor-1/electric
### dt-test ### pass of_unittest_overlay_high_level():3584
### dt-test ### pass of_unittest_overlay_high_level():3587
### dt-test ### end of unittest - 276 passed, 0 failed


<< post-test console output deleted >>

/ # cat /proc/version
Linux version 6.2.0-rc1-00008-g0ad108551489 (frowand@xps8900) (arm-linux-gnueabi-gcc (Ubuntu 9.4.0-1ubuntu1~20.04.1) 9.4.0, GNU ld (GNU Binutils for Ubuntu) 2.34) #23 SMP PREEMPT Mon Feb 13 12:52:35 CST 2023

[PATCH 6/7] of: add consistency check to of_node_release()

[Frank Rowand]

Add an additional consistency check to of_node_release(), which is
called when the reference count of a devicetree node is decremented
to zero.  The node's children should have been deleted before the
node is deleted so check that no children exist.

Signed-off-by: Frank Rowand <frowand.list@gmail.com>
---
 drivers/of/dynamic.c | 4 ++++
 1 file changed, 4 insertions(+)

diff --git a/drivers/of/dynamic.c b/drivers/of/dynamic.c
index dbcbc41f3465..657a65006056 100644
--- a/drivers/of/dynamic.c
+++ b/drivers/of/dynamic.c
@@ -377,6 +377,10 @@ void of_node_release(struct kobject *kobj)
 			       __func__, node);
 	}
 
+	if (node->child)
+		pr_err("ERROR: %s() unexpected children for %pOF/%s\n",
+			__func__, node->parent, node->full_name);
+
 	property_list_free(node->properties);
 	property_list_free(node->deadprops);
 	fwnode_links_purge(of_fwnode_handle(node));
-- 
Frank Rowand <frowand.list@gmail.com>

[PATCH 7/7] of: dynamic: add lifecycle docbook info to node creation functions

[Frank Rowand]

The existing docbook comments for the functions related to creating
a devicetree node do not explain the reference count of a newly
created node, how decrementing the reference count to zero will
free the associated memory, and the caller's responsibility to
call of_node_put() on the node.  Explain what happens when the
reference count is decremented to zero.

Signed-off-by: Frank Rowand <frowand.list@gmail.com>
---
 drivers/of/dynamic.c |  3 ++-
 include/linux/of.h   | 11 +++++++++++
 2 files changed, 13 insertions(+), 1 deletion(-)

diff --git a/drivers/of/dynamic.c b/drivers/of/dynamic.c
index 657a65006056..12aa99018969 100644
--- a/drivers/of/dynamic.c
+++ b/drivers/of/dynamic.c
@@ -443,7 +443,8 @@ struct property *__of_prop_dup(const struct property *prop, gfp_t allocflags)
  * another node.  The node data are dynamically allocated and all the node
  * flags have the OF_DYNAMIC & OF_DETACHED bits set.
  *
- * Return: The newly allocated node or NULL on out of memory error.
+ * Return: The newly allocated node or NULL on out of memory error.  Use
+ * of_node_put() on it when done to free the memory allocated for it.
  */
 struct device_node *__of_node_dup(const struct device_node *np,
 				  const char *full_name)
diff --git a/include/linux/of.h b/include/linux/of.h
index 8b9f94386dc3..e20a08c8a8c8 100644
--- a/include/linux/of.h
+++ b/include/linux/of.h
@@ -100,6 +100,17 @@ struct of_reconfig_data {
 	struct property		*old_prop;
 };
 
+/**
+ * of_node_init - initialize a devicetree node
+ * @node: Pointer to device node that has been created by kzalloc()
+ * @phandle_name: Name of property holding a phandle value
+ *
+ * On return the device_node refcount is set to one.  Use of_node_put()
+ * on @node when done to free the memory allocated for it.  If the node
+ * is NOT a dynamic node the memory will not be freed. The decision of
+ * whether to free the memory will be done by node->release(), which is
+ * of_node_release().
+ */
 /* initialize a node */
 extern struct kobj_type of_node_ktype;
 extern const struct fwnode_operations of_fwnode_ops;
-- 
Frank Rowand <frowand.list@gmail.com>

Re: [PATCH 0/7] of: unittest: new node lifecycle tests

[Rob Herring]

On Mon, Feb 13, 2023 at 12:56:55PM -0600, Frank Rowand wrote:
> Create new devicetree node lifecycle tests.
> 
> The tests introduce use of EXPECT_NOT messages, similar to EXPECT
> messages.  This requires updating scripts/dtc/of_unittest_expect
> to process EXPECT_NOT messages.
> 
> The new tests revealed an issue in printk formatting when using
> format "%pOF" on a node with a reference count of zero.  A patch
> is included to the fix the caller which revealed the issue.
> 
> Update kconfig unittest help to further explain that unittests
> should only be enabled for developer kernels.  Also add info
> about using scripts/dtc/of_unittest_expect to process the output
> of unittests.
> 
> Add an additional consistency check to of_node_release(), which
> is the function that potentially frees node related memory when
> the node's reference count is decremented to zero.
> 
> Add docbook documentation to the devicetree node creation functions
> about caller responsibility to call of_node_put() and how the
> memory free process works.
> 
> Frank Rowand (7):
>   of: prepare to add processing of EXPECT_NOT to of_unittest_expect
>   of: add processing of EXPECT_NOT to of_unittest_expect
>   of: update kconfig unittest help
>   of: unittest: add node lifecycle tests
>   of: do not use "%pOF" printk format on node with refcount of zero
>   of: add consistency check to of_node_release()
>   of: dynamic: add lifecycle docbook info to node creation functions

Series applied.

Rob