linux-next: runtime warning after merge of the cel-fixes tree

linux-next: runtime warning after merge of the cel-fixes tree

[Stephen Rothwell]

[-- Attachment #1: Type: text/plain, Size: 3260 bytes --]

Hi all,

After merging the cel-fixes tree, today's linux-next build (powerpc
pseries_le_defconfig) produced this warning:

ftrace: allocating 33539 entries in 13 pages
ftrace: allocated 13 pages with 3 groups
trace event string verifier disabled
rcu: Hierarchical RCU implementation.
rcu: 	RCU event tracing is enabled.
rcu: 	RCU restricting CPUs from NR_CPUS=2048 to nr_cpu_ids=1.
	Rude variant of Tasks RCU enabled.
	Tracing variant of Tasks RCU enabled.
rcu: RCU calculated value of scheduler-enlistment delay is 10 jiffies.
rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=1
------------[ cut here ]------------
WARNING: CPU: 0 PID: 0 at kernel/trace/trace_events.c:431 trace_event_raw_init+0x1a4/0x7d0
Modules linked in:
CPU: 0 PID: 0 Comm: swapper/0 Not tainted 5.18.0-rc1 #2
NIP:  c0000000002c0924 LR: c0000000002c0ce8 CTR: c0000000002c0990
REGS: c000000002787a00 TRAP: 0700   Not tainted  (5.18.0-rc1)
MSR:  8000000002021033 <SF,VEC,ME,IR,DR,RI,LE>  CR: 44000282  XER: 20000000
CFAR: c0000000002c0b34 IRQMASK: 1 
GPR00: c0000000002c0cd0 c000000002787ca0 c00000000278ae00 0000000000000000 
GPR04: 000000000000002c 0000000000000005 0000000000000057 c0000000002c08ac 
GPR08: 0000000000000000 0000000000000000 0000000000000000 0000000000000000 
GPR12: c0000000002c0780 c000000002950000 0000000000000003 0000000000000000 
GPR16: 0000000002bf00d0 000000007e68ebc8 c000000000fb0758 000508b58019388f 
GPR20: 0000000000000000 0000000000000001 c000000000fb0748 0000000000000003 
GPR24: 0000000000000000 0000000000000000 0000000000000001 0000000000000000 
GPR28: c0000000026fcde0 c0000000026f60e0 000000000000005f c0000000026f613f 
NIP [c0000000002c0924] trace_event_raw_init+0x1a4/0x7d0
LR [c0000000002c0ce8] trace_event_raw_init+0x568/0x7d0
Call Trace:
[c000000002787ca0] [c0000000002c0cd0] trace_event_raw_init+0x550/0x7d0 (unreliable)
[c000000002787da0] [c0000000002bd908] event_init+0x78/0x100
[c000000002787e10] [c0000000020346ac] trace_event_init+0xc8/0x334
[c000000002787eb0] [c000000002033d20] trace_init+0x18/0x2c
[c000000002787ed0] [c000000002004318] start_kernel+0x598/0x8d8
[c000000002787f90] [c00000000000d19c] start_here_common+0x1c/0x600
Instruction dump:
41800348 60000000 60420000 3bde0001 7fdf07b4 7ffdfa14 891f0000 710a00ff 
4082ff5c 2c3a0000 38600000 41820230 <0fe00000> f9c10070 f9e10078 fa010080 
---[ end trace 0000000000000000 ]---
event svc_defer_recv has unsafe dereference of argument 1
print_fmt: "addr=%pISpc dr=%p xid=0x%08x", (struct sockaddr *)__get_dynamic_array(addr), REC->dr, REC->xid
event svc_defer_queue has unsafe dereference of argument 1
print_fmt: "addr=%pISpc dr=%p xid=0x%08x", (struct sockaddr *)__get_dynamic_array(addr), REC->dr, REC->xid
event svc_defer_drop has unsafe dereference of argument 1
print_fmt: "addr=%pISpc dr=%p xid=0x%08x", (struct sockaddr *)__get_dynamic_array(addr), REC->dr, REC->xid
NR_IRQS: 512, nr_irqs: 512, preallocated irqs: 16
rcu: srcu_init: Setting srcu_struct sizes based on contention.

Introduced by commit

  e2e917f8677d ("SUNRPC: Fix the svc_deferred_event trace class")

At least reverting that commit makes the warning go away.

I have left that commit reverted for today.

-- 
Cheers,
Stephen Rothwell

[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 488 bytes --]

Re: linux-next: runtime warning after merge of the cel-fixes tree

[Chuck Lever III]

> On Apr 7, 2022, at 12:45 AM, Stephen Rothwell <sfr@canb.auug.org.au> wrote:
> 
> Hi all,
> 
> After merging the cel-fixes tree, today's linux-next build (powerpc
> pseries_le_defconfig) produced this warning:
> 
> ftrace: allocating 33539 entries in 13 pages
> ftrace: allocated 13 pages with 3 groups
> trace event string verifier disabled
> rcu: Hierarchical RCU implementation.
> rcu: 	RCU event tracing is enabled.
> rcu: 	RCU restricting CPUs from NR_CPUS=2048 to nr_cpu_ids=1.
> 	Rude variant of Tasks RCU enabled.
> 	Tracing variant of Tasks RCU enabled.
> rcu: RCU calculated value of scheduler-enlistment delay is 10 jiffies.
> rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=1
> ------------[ cut here ]------------
> WARNING: CPU: 0 PID: 0 at kernel/trace/trace_events.c:431 trace_event_raw_init+0x1a4/0x7d0
> Modules linked in:
> CPU: 0 PID: 0 Comm: swapper/0 Not tainted 5.18.0-rc1 #2
> NIP:  c0000000002c0924 LR: c0000000002c0ce8 CTR: c0000000002c0990
> REGS: c000000002787a00 TRAP: 0700   Not tainted  (5.18.0-rc1)
> MSR:  8000000002021033 <SF,VEC,ME,IR,DR,RI,LE>  CR: 44000282  XER: 20000000
> CFAR: c0000000002c0b34 IRQMASK: 1 
> GPR00: c0000000002c0cd0 c000000002787ca0 c00000000278ae00 0000000000000000 
> GPR04: 000000000000002c 0000000000000005 0000000000000057 c0000000002c08ac 
> GPR08: 0000000000000000 0000000000000000 0000000000000000 0000000000000000 
> GPR12: c0000000002c0780 c000000002950000 0000000000000003 0000000000000000 
> GPR16: 0000000002bf00d0 000000007e68ebc8 c000000000fb0758 000508b58019388f 
> GPR20: 0000000000000000 0000000000000001 c000000000fb0748 0000000000000003 
> GPR24: 0000000000000000 0000000000000000 0000000000000001 0000000000000000 
> GPR28: c0000000026fcde0 c0000000026f60e0 000000000000005f c0000000026f613f 
> NIP [c0000000002c0924] trace_event_raw_init+0x1a4/0x7d0
> LR [c0000000002c0ce8] trace_event_raw_init+0x568/0x7d0
> Call Trace:
> [c000000002787ca0] [c0000000002c0cd0] trace_event_raw_init+0x550/0x7d0 (unreliable)
> [c000000002787da0] [c0000000002bd908] event_init+0x78/0x100
> [c000000002787e10] [c0000000020346ac] trace_event_init+0xc8/0x334
> [c000000002787eb0] [c000000002033d20] trace_init+0x18/0x2c
> [c000000002787ed0] [c000000002004318] start_kernel+0x598/0x8d8
> [c000000002787f90] [c00000000000d19c] start_here_common+0x1c/0x600
> Instruction dump:
> 41800348 60000000 60420000 3bde0001 7fdf07b4 7ffdfa14 891f0000 710a00ff 
> 4082ff5c 2c3a0000 38600000 41820230 <0fe00000> f9c10070 f9e10078 fa010080 
> ---[ end trace 0000000000000000 ]---
> event svc_defer_recv has unsafe dereference of argument 1
> print_fmt: "addr=%pISpc dr=%p xid=0x%08x", (struct sockaddr *)__get_dynamic_array(addr), REC->dr, REC->xid
> event svc_defer_queue has unsafe dereference of argument 1
> print_fmt: "addr=%pISpc dr=%p xid=0x%08x", (struct sockaddr *)__get_dynamic_array(addr), REC->dr, REC->xid
> event svc_defer_drop has unsafe dereference of argument 1
> print_fmt: "addr=%pISpc dr=%p xid=0x%08x", (struct sockaddr *)__get_dynamic_array(addr), REC->dr, REC->xid
> NR_IRQS: 512, nr_irqs: 512, preallocated irqs: 16
> rcu: srcu_init: Setting srcu_struct sizes based on contention.
> 
> Introduced by commit
> 
>  e2e917f8677d ("SUNRPC: Fix the svc_deferred_event trace class")
> 
> At least reverting that commit makes the warning go away.
> 
> I have left that commit reverted for today.

Thank you, Stephen. The NFS community has already discussed a
fix for this issue. I'll push it out as soon as I can.


--
Chuck Lever

Re: linux-next: runtime warning after merge of the cel-fixes tree

[Steven Rostedt]

On Thu, 7 Apr 2022 13:48:54 +0000
Chuck Lever III <chuck.lever@oracle.com> wrote:

> > event svc_defer_recv has unsafe dereference of argument 1
> > print_fmt: "addr=%pISpc dr=%p xid=0x%08x", (struct sockaddr *)__get_dynamic_array(addr), REC->dr, REC->xid
> > event svc_defer_queue has unsafe dereference of argument 1
> > print_fmt: "addr=%pISpc dr=%p xid=0x%08x", (struct sockaddr *)__get_dynamic_array(addr), REC->dr, REC->xid
> > event svc_defer_drop has unsafe dereference of argument 1
> > print_fmt: "addr=%pISpc dr=%p xid=0x%08x", (struct sockaddr *)__get_dynamic_array(addr), REC->dr, REC->xid
> > NR_IRQS: 512, nr_irqs: 512, preallocated irqs: 16
> > rcu: srcu_init: Setting srcu_struct sizes based on contention.
> > 
> > Introduced by commit
> > 
> >  e2e917f8677d ("SUNRPC: Fix the svc_deferred_event trace class")
> > 
> > At least reverting that commit makes the warning go away.
> > 
> > I have left that commit reverted for today.  
> 
> Thank you, Stephen. The NFS community has already discussed a
> fix for this issue. I'll push it out as soon as I can.

Hmm, I know we added code to handle "__get_sockaddr()" but I guess this
should also be fine for "__get_dynamic_array()" as well.

I could write a patch to cover those too.

-- Steve

Re: linux-next: runtime warning after merge of the cel-fixes tree

[Steven Rostedt]

On Thu, 7 Apr 2022 10:54:46 -0400
Steven Rostedt <rostedt@goodmis.org> wrote:

> Hmm, I know we added code to handle "__get_sockaddr()" but I guess this
> should also be fine for "__get_dynamic_array()" as well.

Does the below patch fix it?

(not even compiled tested)

-- Steve

diff --git a/kernel/trace/trace_events.c b/kernel/trace/trace_events.c
index e11e167b7809..043b80f3e19a 100644
--- a/kernel/trace/trace_events.c
+++ b/kernel/trace/trace_events.c
@@ -392,8 +392,9 @@ static void test_event_printk(struct trace_event_call *call)
 			if (!(dereference_flags & (1ULL << arg)))
 				goto next_arg;
 
-			/* Check for __get_sockaddr */;
-			if (str_has_prefix(fmt + i, "__get_sockaddr(")) {
+			/* Check for __get_sockaddr or __get_dynamic_array */;
+			if (str_has_prefix(fmt + i, "__get_sockaddr(") ||
+			    str_has_prefix(fmt + i, "__get_dynamic_array(")) {
 				dereference_flags &= ~(1ULL << arg);
 				goto next_arg;
 			}

Re: linux-next: runtime warning after merge of the cel-fixes tree

[Chuck Lever III]

Hi Steven-

> On Apr 7, 2022, at 11:13 AM, Steven Rostedt <rostedt@goodmis.org> wrote:
> 
> On Thu, 7 Apr 2022 10:54:46 -0400
> Steven Rostedt <rostedt@goodmis.org> wrote:
> 
>> Hmm, I know we added code to handle "__get_sockaddr()" but I guess this
>> should also be fine for "__get_dynamic_array()" as well.
> 
> Does the below patch fix it?
> 
> (not even compiled tested)
> 
> -- Steve
> 
> diff --git a/kernel/trace/trace_events.c b/kernel/trace/trace_events.c
> index e11e167b7809..043b80f3e19a 100644
> --- a/kernel/trace/trace_events.c
> +++ b/kernel/trace/trace_events.c
> @@ -392,8 +392,9 @@ static void test_event_printk(struct trace_event_call *call)
> 			if (!(dereference_flags & (1ULL << arg)))
> 				goto next_arg;
> 
> -			/* Check for __get_sockaddr */;
> -			if (str_has_prefix(fmt + i, "__get_sockaddr(")) {
> +			/* Check for __get_sockaddr or __get_dynamic_array */;
> +			if (str_has_prefix(fmt + i, "__get_sockaddr(") ||
> +			    str_has_prefix(fmt + i, "__get_dynamic_array(")) {
> 				dereference_flags &= ~(1ULL << arg);
> 				goto next_arg;
> 			}

That looks reasonable for present and future kernels.

We're looking for a solution that can be back-ported to stable,
however, because the patch Mr. Rothwell had to revert is meant
to address a NULL pointer deref that was introduced several years
ago. (Otherwise I would have just used __get_sockaddr() and put
my pencil down).

The simplest option is to take a brute-force approach and
convert the sockaddr to a presentation address with an snprintf()
call in the TP_fast_assign() arm of the tracepoints. Allow that
to be carried into -stable as needed; then in v5.19 apply a
clean-up that converts that mess into a proper __get_sockaddr().

That way, it stays my issue to address without needing to
co-ordinate with fixes in other areas.


--
Chuck Lever

Re: linux-next: runtime warning after merge of the cel-fixes tree

[Steven Rostedt]

On Thu, 7 Apr 2022 15:35:24 +0000
Chuck Lever III <chuck.lever@oracle.com> wrote:

> > --- a/kernel/trace/trace_events.c
> > +++ b/kernel/trace/trace_events.c
> > @@ -392,8 +392,9 @@ static void test_event_printk(struct trace_event_call *call)
> > 			if (!(dereference_flags & (1ULL << arg)))
> > 				goto next_arg;
> > 
> > -			/* Check for __get_sockaddr */;
> > -			if (str_has_prefix(fmt + i, "__get_sockaddr(")) {
> > +			/* Check for __get_sockaddr or __get_dynamic_array */;
> > +			if (str_has_prefix(fmt + i, "__get_sockaddr(") ||
> > +			    str_has_prefix(fmt + i, "__get_dynamic_array(")) {
> > 				dereference_flags &= ~(1ULL << arg);
> > 				goto next_arg;
> > 			}  
> 
> That looks reasonable for present and future kernels.

Actually, I found an issue with the above that will not fix it, but the fix
to that is not that difficult (currently testing it this time).

> 
> We're looking for a solution that can be back-ported to stable,
> however, because the patch Mr. Rothwell had to revert is meant
> to address a NULL pointer deref that was introduced several years
> ago. (Otherwise I would have just used __get_sockaddr() and put
> my pencil down).

I can make a stable version of this patch, as __get_dynamic_array() has
been around for a long time. We could even keep the check for
"__get_sock_addr()" even though it does not exist in older kernels, but
this is just a string check, so that doesn't matter.

> 
> The simplest option is to take a brute-force approach and
> convert the sockaddr to a presentation address with an snprintf()
> call in the TP_fast_assign() arm of the tracepoints. Allow that
> to be carried into -stable as needed; then in v5.19 apply a
> clean-up that converts that mess into a proper __get_sockaddr().
> 
> That way, it stays my issue to address without needing to
> co-ordinate with fixes in other areas.

This change makes the tracing system more robust, which means it's not just
changing to solve an issue with your code. I'm happy to get this working
and backported.

-- Steve

Re: linux-next: runtime warning after merge of the cel-fixes tree

[Steven Rostedt]

On Thu, 7 Apr 2022 11:42:41 -0400
Steven Rostedt <rostedt@goodmis.org> wrote:

> Actually, I found an issue with the above that will not fix it, but the fix
> to that is not that difficult (currently testing it this time).

Take two:

diff --git a/kernel/trace/trace_events.c b/kernel/trace/trace_events.c
index e11e167b7809..55d3ed6656ac 100644
--- a/kernel/trace/trace_events.c
+++ b/kernel/trace/trace_events.c
@@ -392,12 +392,6 @@ static void test_event_printk(struct trace_event_call *call)
 			if (!(dereference_flags & (1ULL << arg)))
 				goto next_arg;
 
-			/* Check for __get_sockaddr */;
-			if (str_has_prefix(fmt + i, "__get_sockaddr(")) {
-				dereference_flags &= ~(1ULL << arg);
-				goto next_arg;
-			}
-
 			/* Find the REC-> in the argument */
 			c = strchr(fmt + i, ',');
 			r = strstr(fmt + i, "REC->");
@@ -413,7 +407,23 @@ static void test_event_printk(struct trace_event_call *call)
 				a = strchr(fmt + i, '&');
 				if ((a && (a < r)) || test_field(r, call))
 					dereference_flags &= ~(1ULL << arg);
+			} else {
+				/* Check for type casts */
+				if (fmt[i] == '(') {
+					while (fmt[i] && fmt[i] != ')')
+						i++;
+					if (fmt[i])
+						i++;
+					while (isspace(fmt[i]))
+						i++;
+				}
+				/* Check for __get_sockaddr or __get_dynamic_array */;
+				if (str_has_prefix(fmt + i, "__get_sockaddr(") ||
+				    str_has_prefix(fmt + i, "__get_dynamic_array(")) {
+					dereference_flags &= ~(1ULL << arg);
+				}
 			}
+
 		next_arg:
 			i--;
 			arg++;

Re: linux-next: runtime warning after merge of the cel-fixes tree

[Chuck Lever III]

> On Apr 7, 2022, at 11:42 AM, Steven Rostedt <rostedt@goodmis.org> wrote:
> 
> On Thu, 7 Apr 2022 15:35:24 +0000
> Chuck Lever III <chuck.lever@oracle.com> wrote:
> 
>>> --- a/kernel/trace/trace_events.c
>>> +++ b/kernel/trace/trace_events.c
>>> @@ -392,8 +392,9 @@ static void test_event_printk(struct trace_event_call *call)
>>> 			if (!(dereference_flags & (1ULL << arg)))
>>> 				goto next_arg;
>>> 
>>> -			/* Check for __get_sockaddr */;
>>> -			if (str_has_prefix(fmt + i, "__get_sockaddr(")) {
>>> +			/* Check for __get_sockaddr or __get_dynamic_array */;
>>> +			if (str_has_prefix(fmt + i, "__get_sockaddr(") ||
>>> +			    str_has_prefix(fmt + i, "__get_dynamic_array(")) {
>>> 				dereference_flags &= ~(1ULL << arg);
>>> 				goto next_arg;
>>> 			}  
>> 
>> That looks reasonable for present and future kernels.
> 
> Actually, I found an issue with the above that will not fix it, but the fix
> to that is not that difficult (currently testing it this time).

If you'd like to test it yourself, the commit that hits this
check is:

https://git.kernel.org/pub/scm/linux/kernel/git/cel/linux.git/commit/?h=for-rc&id=e2e917f8677da3a2c486c32a19964b3428024ce9


>> We're looking for a solution that can be back-ported to stable,
>> however, because the patch Mr. Rothwell had to revert is meant
>> to address a NULL pointer deref that was introduced several years
>> ago. (Otherwise I would have just used __get_sockaddr() and put
>> my pencil down).
> 
> I can make a stable version of this patch, as __get_dynamic_array() has
> been around for a long time. We could even keep the check for
> "__get_sock_addr()" even though it does not exist in older kernels, but
> this is just a string check, so that doesn't matter.
> 
>> 
>> The simplest option is to take a brute-force approach and
>> convert the sockaddr to a presentation address with an snprintf()
>> call in the TP_fast_assign() arm of the tracepoints. Allow that
>> to be carried into -stable as needed; then in v5.19 apply a
>> clean-up that converts that mess into a proper __get_sockaddr().
>> 
>> That way, it stays my issue to address without needing to
>> co-ordinate with fixes in other areas.
> 
> This change makes the tracing system more robust, which means it's not just
> changing to solve an issue with your code. I'm happy to get this working
> and backported.

I'm not saying "don't bother fixing the deref check". Backporting
it if you can would be awesome!

But /depending/ on that fix makes fixing my NULL crash into a two-
patch cross-subsystem fix. We would have to document that carefully
so distributors can see that dependency if they need the NULL deref
fix in their kernels.

A narrow single patch fix for my NULL crash would be better for
them IMO, so I'm going to go with the snprintf() version of the
fix.


--
Chuck Lever

Re: linux-next: runtime warning after merge of the cel-fixes tree

[Steven Rostedt]

On Thu, 7 Apr 2022 11:50:30 -0400
Steven Rostedt <rostedt@goodmis.org> wrote:

> > Actually, I found an issue with the above that will not fix it, but the fix
> > to that is not that difficult (currently testing it this time).  
> 
> Take two:

I found a way that can even make it more robust and easier to backport:

Take three:

diff --git a/kernel/trace/trace_events.c b/kernel/trace/trace_events.c
index e11e167b7809..c060ae35f785 100644
--- a/kernel/trace/trace_events.c
+++ b/kernel/trace/trace_events.c
@@ -392,12 +392,6 @@ static void test_event_printk(struct trace_event_call *call)
 			if (!(dereference_flags & (1ULL << arg)))
 				goto next_arg;
 
-			/* Check for __get_sockaddr */;
-			if (str_has_prefix(fmt + i, "__get_sockaddr(")) {
-				dereference_flags &= ~(1ULL << arg);
-				goto next_arg;
-			}
-
 			/* Find the REC-> in the argument */
 			c = strchr(fmt + i, ',');
 			r = strstr(fmt + i, "REC->");
@@ -413,7 +407,14 @@ static void test_event_printk(struct trace_event_call *call)
 				a = strchr(fmt + i, '&');
 				if ((a && (a < r)) || test_field(r, call))
 					dereference_flags &= ~(1ULL << arg);
+			} else if ((r = strstr(fmt + i, "__get_dynamic_array(")) &&
+				   (!c || r < c)) {
+				dereference_flags &= ~(1ULL << arg);
+			} else if ((r = strstr(fmt + i, "__get_sockaddr(")) &&
+				   (!c || r < c)) {
+				dereference_flags &= ~(1ULL << arg);
 			}
+
 		next_arg:
 			i--;
 			arg++;