linux-next: runtime warning in next-20220125

linux-next: runtime warning in next-20220125

[Stephen Rothwell]

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

Hi all,

My qemu boot test of a powerpc pseries_le_defconfig kernel produces the
following trace:

------------[ cut here ]------------
WARNING: CPU: 0 PID: 0 at kernel/trace/trace_events.c:417 trace_event_raw_init+0x194/0x730
Modules linked in:
CPU: 0 PID: 0 Comm: swapper/0 Not tainted 5.17.0-rc1 #2
NIP:  c0000000002bdbb4 LR: c0000000002bdcb0 CTR: c0000000002bdb70
REGS: c00000000278ba10 TRAP: 0700   Not tainted  (5.17.0-rc1)
MSR:  8000000002021033 <SF,VEC,ME,IR,DR,RI,LE>  CR: 44000282  XER: 20000000
CFAR: c0000000002bdb38 IRQMASK: 1 
GPR00: c0000000002bdc98 c00000000278bcb0 c00000000278d300 0000000000000000 
GPR04: 000000000000002c 0000000000000005 000000000000023f c0000000002bdb3c 
GPR08: 0000000000000000 0000000000000000 0000000000000000 0000000000000000 
GPR12: c0000000002bda20 c000000002960000 0000000000000000 0000000000000000 
GPR16: 0000000002bf00d0 000000007e68ebc8 ffffffffffffffff 000508b58019388f 
GPR20: 0000000000000001 c000000000faf800 0000000000000005 0000000000000000 
GPR24: 0000000000000000 0000000000000003 0000000000000000 0000000000000000 
GPR28: c0000000026fefc0 c0000000026f8050 0000000000000251 c0000000026f82a1 
NIP [c0000000002bdbb4] trace_event_raw_init+0x194/0x730
LR [c0000000002bdcb0] trace_event_raw_init+0x290/0x730
Call Trace:
[c00000000278bcb0] [c0000000002bdc98] trace_event_raw_init+0x278/0x730 (unreliable)
[c00000000278bda0] [c0000000002badb8] event_init+0x68/0xf0
[c00000000278be10] [c000000002033990] trace_event_init+0xc8/0x334
[c00000000278beb0] [c000000002033004] trace_init+0x18/0x2c
[c00000000278bed0] [c0000000020042e0] start_kernel+0x590/0x8cc
[c00000000278bf90] [c00000000000d19c] start_here_common+0x1c/0x600
Instruction dump:
41800438 60000000 60420000 3bde0001 7fdf07b4 7ffdfa14 891f0000 710a00ff 
4082ff5c 2c390000 38600000 41820320 <0fe00000> f9c10060 f9e10068 fa010070 
---[ end trace 0000000000000000 ]---
event svc_xprt_accept has unsafe dereference of argument 1
print_fmt: "server=%pISpc client=%pISpc flags=%s protocol=%s service=%s", __get_sockaddr(server), __get_sockaddr(client), __print_flags(REC->flags, "|", { (1UL << 0), "XPT_BUSY"}, { (1UL << 1), "XPT_CONN"}, { (1UL << 2), "XPT_CLOSE"}, { (1UL << 3), "XPT_DATA"}, { (1UL << 4), "XPT_TEMP"}, { (1UL << 6), "XPT_DEAD"}, { (1UL << 7), "XPT_CHNGBUF"}, { (1UL << 8), "XPT_DEFERRED"}, { (1UL << 9), "XPT_OLD"}, { (1UL << 10), "XPT_LISTENER"}, { (1UL << 11), "XPT_CACHE_AUTH"}, { (1UL << 12), "XPT_LOCAL"}, { (1UL << 13), "XPT_KILL_TEMP"}, { (1UL << 14), "XPT_CONG_CTRL"}), __get_str(protocol), __get_str(service)
event svc_xprt_free has unsafe dereference of argument 1
print_fmt: "server=%pISpc client=%pISpc flags=%s", __get_sockaddr(server), __get_sockaddr(client), __print_flags(REC->flags, "|", { (1UL << 0), "XPT_BUSY"}, { (1UL << 1), "XPT_CONN"}, { (1UL << 2), "XPT_CLOSE"}, { (1UL << 3), "XPT_DATA"}, { (1UL << 4), "XPT_TEMP"}, { (1UL << 6), "XPT_DEAD"}, { (1UL << 7), "XPT_CHNGBUF"}, { (1UL << 8), "XPT_DEFERRED"}, { (1UL << 9), "XPT_OLD"}, { (1UL << 10), "XPT_LISTENER"}, { (1UL << 11), "XPT_CACHE_AUTH"}, { (1UL << 12), "XPT_LOCAL"}, { (1UL << 13), "XPT_KILL_TEMP"}, { (1UL << 14), "XPT_CONG_CTRL"})
event svc_xprt_detach has unsafe dereference of argument 1
print_fmt: "server=%pISpc client=%pISpc flags=%s", __get_sockaddr(server), __get_sockaddr(client), __print_flags(REC->flags, "|", { (1UL << 0), "XPT_BUSY"}, { (1UL << 1), "XPT_CONN"}, { (1UL << 2), "XPT_CLOSE"}, { (1UL << 3), "XPT_DATA"}, { (1UL << 4), "XPT_TEMP"}, { (1UL << 6), "XPT_DEAD"}, { (1UL << 7), "XPT_CHNGBUF"}, { (1UL << 8), "XPT_DEFERRED"}, { (1UL << 9), "XPT_OLD"}, { (1UL << 10), "XPT_LISTENER"}, { (1UL << 11), "XPT_CACHE_AUTH"}, { (1UL << 12), "XPT_LOCAL"}, { (1UL << 13), "XPT_KILL_TEMP"}, { (1UL << 14), "XPT_CONG_CTRL"})
event svc_xprt_close has unsafe dereference of argument 1
print_fmt: "server=%pISpc client=%pISpc flags=%s", __get_sockaddr(server), __get_sockaddr(client), __print_flags(REC->flags, "|", { (1UL << 0), "XPT_BUSY"}, { (1UL << 1), "XPT_CONN"}, { (1UL << 2), "XPT_CLOSE"}, { (1UL << 3), "XPT_DATA"}, { (1UL << 4), "XPT_TEMP"}, { (1UL << 6), "XPT_DEAD"}, { (1UL << 7), "XPT_CHNGBUF"}, { (1UL << 8), "XPT_DEFERRED"}, { (1UL << 9), "XPT_OLD"}, { (1UL << 10), "XPT_LISTENER"}, { (1UL << 11), "XPT_CACHE_AUTH"}, { (1UL << 12), "XPT_LOCAL"}, { (1UL << 13), "XPT_KILL_TEMP"}, { (1UL << 14), "XPT_CONG_CTRL"})
event svc_xprt_no_write_space has unsafe dereference of argument 1
print_fmt: "server=%pISpc client=%pISpc flags=%s", __get_sockaddr(server), __get_sockaddr(client), __print_flags(REC->flags, "|", { (1UL << 0), "XPT_BUSY"}, { (1UL << 1), "XPT_CONN"}, { (1UL << 2), "XPT_CLOSE"}, { (1UL << 3), "XPT_DATA"}, { (1UL << 4), "XPT_TEMP"}, { (1UL << 6), "XPT_DEAD"}, { (1UL << 7), "XPT_CHNGBUF"}, { (1UL << 8), "XPT_DEFERRED"}, { (1UL << 9), "XPT_OLD"}, { (1UL << 10), "XPT_LISTENER"}, { (1UL << 11), "XPT_CACHE_AUTH"}, { (1UL << 12), "XPT_LOCAL"}, { (1UL << 13), "XPT_KILL_TEMP"}, { (1UL << 14), "XPT_CONG_CTRL"})
event svc_xprt_dequeue has unsafe dereference of argument 1
print_fmt: "server=%pISpc client=%pISpc flags=%s wakeup-us=%lu", __get_sockaddr(server), __get_sockaddr(client), __print_flags(REC->flags, "|", { (1UL << 0), "XPT_BUSY"}, { (1UL << 1), "XPT_CONN"}, { (1UL << 2), "XPT_CLOSE"}, { (1UL << 3), "XPT_DATA"}, { (1UL << 4), "XPT_TEMP"}, { (1UL << 6), "XPT_DEAD"}, { (1UL << 7), "XPT_CHNGBUF"}, { (1UL << 8), "XPT_DEFERRED"}, { (1UL << 9), "XPT_OLD"}, { (1UL << 10), "XPT_LISTENER"}, { (1UL << 11), "XPT_CACHE_AUTH"}, { (1UL << 12), "XPT_LOCAL"}, { (1UL << 13), "XPT_KILL_TEMP"}, { (1UL << 14), "XPT_CONG_CTRL"}), REC->wakeup
event svc_xprt_enqueue has unsafe dereference of argument 1
print_fmt: "server=%pISpc client=%pISpc flags=%s pid=%d", __get_sockaddr(server), __get_sockaddr(client), __print_flags(REC->flags, "|", { (1UL << 0), "XPT_BUSY"}, { (1UL << 1), "XPT_CONN"}, { (1UL << 2), "XPT_CLOSE"}, { (1UL << 3), "XPT_DATA"}, { (1UL << 4), "XPT_TEMP"}, { (1UL << 6), "XPT_DEAD"}, { (1UL << 7), "XPT_CHNGBUF"}, { (1UL << 8), "XPT_DEFERRED"}, { (1UL << 9), "XPT_OLD"}, { (1UL << 10), "XPT_LISTENER"}, { (1UL << 11), "XPT_CACHE_AUTH"}, { (1UL << 12), "XPT_LOCAL"}, { (1UL << 13), "XPT_KILL_TEMP"}, { (1UL << 14), "XPT_CONG_CTRL"}), REC->pid
event svc_xprt_create_err has unsafe dereference of argument 1
print_fmt: "addr=%pISpc program=%s protocol=%s error=%ld", __get_sockaddr(addr), __get_str(program), __get_str(protocol), REC->error
event svc_stats_latency has unsafe dereference of argument 2
print_fmt: "xid=0x%08x server=%pISpc client=%pISpc proc=%s execute-us=%lu", REC->xid, __get_sockaddr(server), __get_sockaddr(client), __get_str(procedure), REC->execute
event svc_send has unsafe dereference of argument 2
print_fmt: "xid=0x%08x server=%pISpc client=%pISpc status=%d flags=%s", REC->xid, __get_sockaddr(server), __get_sockaddr(client), REC->status, __print_flags(REC->flags, "|", { ((((1UL))) << ((0))), "SECURE" }, { ((((1UL))) << ((1))), "LOCAL" }, { ((((1UL))) << ((2))), "USEDEFERRAL" }, { ((((1UL))) << ((3))), "DROPME" }, { ((((1UL))) << ((4))), "SPLICE_OK" }, { ((((1UL))) << ((5))), "VICTIM" }, { ((((1UL))) << ((6))), "BUSY" }, { ((((1UL))) << ((7))), "DATA" })
event svc_drop has unsafe dereference of argument 2
print_fmt: "xid=0x%08x server=%pISpc client=%pISpc flags=%s", REC->xid, __get_sockaddr(server), __get_sockaddr(client), __print_flags(REC->flags, "|", { ((((1UL))) << ((0))), "SECURE" }, { ((((1UL))) << ((1))), "LOCAL" }, { ((((1UL))) << ((2))), "USEDEFERRAL" }, { ((((1UL))) << ((3))), "DROPME" }, { ((((1UL))) << ((4))), "SPLICE_OK" }, { ((((1UL))) << ((5))), "VICTIM" }, { ((((1UL))) << ((6))), "BUSY" }, { ((((1UL))) << ((7))), "DATA" })
event svc_defer has unsafe dereference of argument 2
print_fmt: "xid=0x%08x server=%pISpc client=%pISpc flags=%s", REC->xid, __get_sockaddr(server), __get_sockaddr(client), __print_flags(REC->flags, "|", { ((((1UL))) << ((0))), "SECURE" }, { ((((1UL))) << ((1))), "LOCAL" }, { ((((1UL))) << ((2))), "USEDEFERRAL" }, { ((((1UL))) << ((3))), "DROPME" }, { ((((1UL))) << ((4))), "SPLICE_OK" }, { ((((1UL))) << ((5))), "VICTIM" }, { ((((1UL))) << ((6))), "BUSY" }, { ((((1UL))) << ((7))), "DATA" })
event svc_authenticate has unsafe dereference of argument 2
print_fmt: "xid=0x%08x server=%pISpc client=%pISpc auth_res=%s auth_stat=%s", REC->xid, __get_sockaddr(server), __get_sockaddr(client), __print_symbolic(REC->svc_status, { 1, "SVC_GARBAGE" }, { 2, "SVC_SYSERR" }, { 3, "SVC_VALID" }, { 4, "SVC_NEGATIVE" }, { 5, "SVC_OK" }, { 6, "SVC_DROP" }, { 7, "SVC_CLOSE" }, { 8, "SVC_DENIED" }, { 9, "SVC_PENDING" }, { 10, "SVC_COMPLETE" }), __print_symbolic(REC->auth_stat, { RPC_AUTH_OK, "AUTH_OK" }, { RPC_AUTH_BADCRED, "BADCRED" }, { RPC_AUTH_REJECTEDCRED, "REJECTEDCRED" }, { RPC_AUTH_BADVERF, "BADVERF" }, { RPC_AUTH_REJECTEDVERF, "REJECTEDVERF" }, { RPC_AUTH_TOOWEAK, "TOOWEAK" }, { RPCSEC_GSS_CREDPROBLEM, "GSS_CREDPROBLEM" }, { RPCSEC_GSS_CTXPROBLEM, "GSS_CTXPROBLEM" })

I have no idea what has caused this :-(  Maybe commit

  5544d5318802 ("SUNRPC: Same as SVC_RQST_ENDPOINT, but without the xid")

-- 
Cheers,
Stephen Rothwell

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

Re: linux-next: runtime warning in next-20220125

[Stephen Rothwell]

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

Hi all,

On Tue, 25 Jan 2022 16:05:05 +1100 Stephen Rothwell <sfr@canb.auug.org.au> wrote:
>
> My qemu boot test of a powerpc pseries_le_defconfig kernel produces the
> following trace:
> 
> ------------[ cut here ]------------
> WARNING: CPU: 0 PID: 0 at kernel/trace/trace_events.c:417 trace_event_raw_init+0x194/0x730
> Modules linked in:
> CPU: 0 PID: 0 Comm: swapper/0 Not tainted 5.17.0-rc1 #2
> NIP:  c0000000002bdbb4 LR: c0000000002bdcb0 CTR: c0000000002bdb70
> 
> I have no idea what has caused this :-(  Maybe commit
> 
>   5544d5318802 ("SUNRPC: Same as SVC_RQST_ENDPOINT, but without the xid")

Actually, reverting commits

  6ff851d98af8 ("SUNRPC: Improve sockaddr handling in the svc_xprt_create_error trace point")
  5544d5318802 ("SUNRPC: Same as SVC_RQST_ENDPOINT, but without the xid")
  e2d3613db12a ("SUNRPC: Record endpoint information in trace log")

makes the warning go away.

-- 
Cheers,
Stephen Rothwell

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

Re: linux-next: runtime warning in next-20220125

[Steven Rostedt]

On Tue, 25 Jan 2022 16:21:46 +1100
Stephen Rothwell <sfr@canb.auug.org.au> wrote:

> Hi all,
> 
> On Tue, 25 Jan 2022 16:05:05 +1100 Stephen Rothwell <sfr@canb.auug.org.au> wrote:
> >
> > My qemu boot test of a powerpc pseries_le_defconfig kernel produces the
> > following trace:
> > 
> > ------------[ cut here ]------------
> > WARNING: CPU: 0 PID: 0 at kernel/trace/trace_events.c:417 trace_event_raw_init+0x194/0x730
> > Modules linked in:
> > CPU: 0 PID: 0 Comm: swapper/0 Not tainted 5.17.0-rc1 #2
> > NIP:  c0000000002bdbb4 LR: c0000000002bdcb0 CTR: c0000000002bdb70
> > 
> > I have no idea what has caused this :-(  Maybe commit
> > 
> >   5544d5318802 ("SUNRPC: Same as SVC_RQST_ENDPOINT, but without the xid")  
> 
> Actually, reverting commits
> 
>   6ff851d98af8 ("SUNRPC: Improve sockaddr handling in the svc_xprt_create_error trace point")
>   5544d5318802 ("SUNRPC: Same as SVC_RQST_ENDPOINT, but without the xid")
>   e2d3613db12a ("SUNRPC: Record endpoint information in trace log")
> 
> makes the warning go away.
> 

We added a new way to save items on the ring buffer, but did not update the
safety checks to know about them. I'll fix this shortly.

-- Steve

Re: linux-next: runtime warning in next-20220125

[Steven Rostedt]

On Tue, 25 Jan 2022 10:01:38 -0500
Steven Rostedt <rostedt@goodmis.org> wrote:

> On Tue, 25 Jan 2022 16:21:46 +1100
> Stephen Rothwell <sfr@canb.auug.org.au> wrote:
> 
> > Hi all,
> > 
> > On Tue, 25 Jan 2022 16:05:05 +1100 Stephen Rothwell <sfr@canb.auug.org.au> wrote:  
> > >
> > > My qemu boot test of a powerpc pseries_le_defconfig kernel produces the
> > > following trace:
> > > 
> > > ------------[ cut here ]------------
> > > WARNING: CPU: 0 PID: 0 at kernel/trace/trace_events.c:417 trace_event_raw_init+0x194/0x730
> > > Modules linked in:
> > > CPU: 0 PID: 0 Comm: swapper/0 Not tainted 5.17.0-rc1 #2
> > > NIP:  c0000000002bdbb4 LR: c0000000002bdcb0 CTR: c0000000002bdb70
> > > 
> > > I have no idea what has caused this :-(  Maybe commit
> > > 
> > >   5544d5318802 ("SUNRPC: Same as SVC_RQST_ENDPOINT, but without the xid")    
> > 
> > Actually, reverting commits
> > 
> >   6ff851d98af8 ("SUNRPC: Improve sockaddr handling in the svc_xprt_create_error trace point")
> >   5544d5318802 ("SUNRPC: Same as SVC_RQST_ENDPOINT, but without the xid")
> >   e2d3613db12a ("SUNRPC: Record endpoint information in trace log")
> > 
> > makes the warning go away.
> >   
> 
> We added a new way to save items on the ring buffer, but did not update the
> safety checks to know about them. I'll fix this shortly.
> 

This should fix it:

I'll make it a real patch and start running it through my tests.

-- Steve


diff --git a/kernel/trace/trace_events.c b/kernel/trace/trace_events.c
index 3147614c1812..f527ae807e77 100644
--- a/kernel/trace/trace_events.c
+++ b/kernel/trace/trace_events.c
@@ -384,6 +384,12 @@ 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->");

Re: linux-next: runtime warning in next-20220125

[Chuck Lever III]

> On Jan 25, 2022, at 10:36 AM, Steven Rostedt <rostedt@goodmis.org> wrote:
> 
> On Tue, 25 Jan 2022 10:01:38 -0500
> Steven Rostedt <rostedt@goodmis.org> wrote:
> 
>> On Tue, 25 Jan 2022 16:21:46 +1100
>> Stephen Rothwell <sfr@canb.auug.org.au> wrote:
>> 
>>> Hi all,
>>> 
>>> On Tue, 25 Jan 2022 16:05:05 +1100 Stephen Rothwell <sfr@canb.auug.org.au> wrote:  
>>>> 
>>>> My qemu boot test of a powerpc pseries_le_defconfig kernel produces the
>>>> following trace:
>>>> 
>>>> ------------[ cut here ]------------
>>>> WARNING: CPU: 0 PID: 0 at kernel/trace/trace_events.c:417 trace_event_raw_init+0x194/0x730
>>>> Modules linked in:
>>>> CPU: 0 PID: 0 Comm: swapper/0 Not tainted 5.17.0-rc1 #2
>>>> NIP:  c0000000002bdbb4 LR: c0000000002bdcb0 CTR: c0000000002bdb70
>>>> 
>>>> I have no idea what has caused this :-(  Maybe commit
>>>> 
>>>>  5544d5318802 ("SUNRPC: Same as SVC_RQST_ENDPOINT, but without the xid")    
>>> 
>>> Actually, reverting commits
>>> 
>>>  6ff851d98af8 ("SUNRPC: Improve sockaddr handling in the svc_xprt_create_error trace point")
>>>  5544d5318802 ("SUNRPC: Same as SVC_RQST_ENDPOINT, but without the xid")
>>>  e2d3613db12a ("SUNRPC: Record endpoint information in trace log")
>>> 
>>> makes the warning go away.
>>> 
>> 
>> We added a new way to save items on the ring buffer, but did not update the
>> safety checks to know about them. I'll fix this shortly.
>> 
> 
> This should fix it:
> 
> I'll make it a real patch and start running it through my tests.

Should this be squashed into the patch that adds __get_sockaddr() ?

I have an updated version of that patch that applies on kernels
that have __rel_dynamic_array.


> -- Steve
> 
> 
> diff --git a/kernel/trace/trace_events.c b/kernel/trace/trace_events.c
> index 3147614c1812..f527ae807e77 100644
> --- a/kernel/trace/trace_events.c
> +++ b/kernel/trace/trace_events.c
> @@ -384,6 +384,12 @@ 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->");

--
Chuck Lever

Re: linux-next: runtime warning in next-20220125

[Steven Rostedt]

On Tue, 25 Jan 2022 15:38:22 +0000
Chuck Lever III <chuck.lever@oracle.com> wrote:

> > This should fix it:
> > 
> > I'll make it a real patch and start running it through my tests.  
> 
> Should this be squashed into the patch that adds __get_sockaddr() ?
> 
> I have an updated version of that patch that applies on kernels
> that have __rel_dynamic_array.

Heh, I thought the patch was already in mainline. I just posted the fix.

Just add it to your queue. No need to squash it.

You can remove the Fixes: tag, as it may not reference the right commit.

-- Steve

Re: linux-next: runtime warning in next-20220125

[Chuck Lever III]

> On Jan 25, 2022, at 10:46 AM, Steven Rostedt <rostedt@goodmis.org> wrote:
> 
> On Tue, 25 Jan 2022 15:38:22 +0000
> Chuck Lever III <chuck.lever@oracle.com> wrote:
> 
>>> This should fix it:
>>> 
>>> I'll make it a real patch and start running it through my tests.  
>> 
>> Should this be squashed into the patch that adds __get_sockaddr() ?
>> 
>> I have an updated version of that patch that applies on kernels
>> that have __rel_dynamic_array.
> 
> Heh, I thought the patch was already in mainline.

Nope, you said you might still be testing it, so I held it back
from v5.17. But it is in linux-next now via the nfsd tree.


> I just posted the fix.
> 
> Just add it to your queue. No need to squash it.
> 
> You can remove the Fixes: tag, as it may not reference the right commit.

Thanks!


--
Chuck Lever