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
On Tue, 25 Jan 2022 10:01:38 -0500
Steven Rostedt <[email protected]> wrote:
> On Tue, 25 Jan 2022 16:21:46 +1100
> Stephen Rothwell <[email protected]> wrote:
>
> > Hi all,
> >
> > On Tue, 25 Jan 2022 16:05:05 +1100 Stephen Rothwell <[email protected]> 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->");
> On Jan 25, 2022, at 10:36 AM, Steven Rostedt <[email protected]> wrote:
>
> On Tue, 25 Jan 2022 10:01:38 -0500
> Steven Rostedt <[email protected]> wrote:
>
>> On Tue, 25 Jan 2022 16:21:46 +1100
>> Stephen Rothwell <[email protected]> wrote:
>>
>>> Hi all,
>>>
>>> On Tue, 25 Jan 2022 16:05:05 +1100 Stephen Rothwell <[email protected]> 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