After seeing that an unsafe string dereference in a trace event made
it into the kernel, I decided it's time to add some sanity checks to
catch these cases without needing me to supervise.
The first patch scans the print fmts of the trace events looking for
dereferencing pointers from %p*, and making sure that they refer back
to the trace event itself.
The second patch handles strings "%s", as there are cases that are
fine with dereferencing the string outside the trace event. On reading
of the trace file, the %s is looked for and when found, the logic checks
the pointer that it is about to be dereferenced to see if it is a
valid location. This check would have caught the last unsafe dereference
committed into the kernel.
Steven Rostedt (VMware) (2):
tracing: Add check of trace event print fmts for dereferencing pointers
tracing: Add a verifier to check string pointers for trace events
----
kernel/trace/trace.c | 148 +++++++++++++++++++++++++++++++++
kernel/trace/trace.h | 2 +
kernel/trace/trace_events.c | 198 ++++++++++++++++++++++++++++++++++++++++++++
kernel/trace/trace_output.c | 2 +-
4 files changed, 349 insertions(+), 1 deletion(-)
On Fri, Feb 26, 2021 at 11:07 AM Steven Rostedt <[email protected]> wrote:
>
> The first patch scans the print fmts of the trace events looking for
> dereferencing pointers from %p*, and making sure that they refer back
> to the trace event itself.
>
> The second patch handles strings "%s" [..]
Doing this at runtime really feels like the wrong thing to do.
It won't even protect us from what happened - people like me and
Andrew won't even run those tracepoints in the first place, so we
won't notice.
It really would be much better in every respect to have this done by
checkpatch, I think.
Linus
On Fri, 26 Feb 2021 14:21:00 -0800
Linus Torvalds <[email protected]> wrote:
> > The second patch handles strings "%s" [..]
>
> Doing this at runtime really feels like the wrong thing to do.
>
> It won't even protect us from what happened - people like me and
> Andrew won't even run those tracepoints in the first place, so we
> won't notice.
>
> It really would be much better in every respect to have this done by
> checkpatch, I think.
They are not mutually exclusive. We could have both. One thing that's nice
about this patch is that it removes the possibility of a real bug. That is,
it will catch the dereferencing of a string that is not valid, WARN about
it, but it wont try to dereference it (outside of the
strcpy_from_kernel_nofault()). And hopefully the warning and lack of data
they want, will have this get caught during development.
Also, there's cases that %s is allowed to reference data that I don't know
if checkpatch would be able to differentiate.
As for the other pointer dereferences (the first patch), those get caught
at boot up if they are compiled in. That is, you don't need to have the
events enabled. The boot up code will do the verification on all events
that are loaded (allyesconfig will catch all of them, which I need to try
to boot with this code).
-- Steve
On Fri, 2021-02-26 at 18:33 -0500, Steven Rostedt wrote:
> On Fri, 26 Feb 2021 14:21:00 -0800
> Linus Torvalds <[email protected]> wrote:
>
> > > The second patch handles strings "%s" [..]
> >
> > Doing this at runtime really feels like the wrong thing to do.
> >
> > It won't even protect us from what happened - people like me and
> > Andrew won't even run those tracepoints in the first place, so we
> > won't notice.
> >
> > It really would be much better in every respect to have this done by
> > checkpatch, I think.
>
> They are not mutually exclusive. We could have both. One thing that's nice
> about this patch is that it removes the possibility of a real bug. That is,
> it will catch the dereferencing of a string that is not valid, WARN about
> it, but it wont try to dereference it (outside of the
> strcpy_from_kernel_nofault()). And hopefully the warning and lack of data
> they want, will have this get caught during development.
>
> Also, there's cases that %s is allowed to reference data that I don't know
> if checkpatch would be able to differentiate.
It's not obvious to me how to do that.
On Fri, 26 Feb 2021 14:21:00 -0800
Linus Torvalds <[email protected]> wrote:
> On Fri, Feb 26, 2021 at 11:07 AM Steven Rostedt <[email protected]> wrote:
> >
> > The first patch scans the print fmts of the trace events looking for
> > dereferencing pointers from %p*, and making sure that they refer back
> > to the trace event itself.
> >
> > The second patch handles strings "%s" [..]
>
> Doing this at runtime really feels like the wrong thing to do.
>
> It won't even protect us from what happened - people like me and
> Andrew won't even run those tracepoints in the first place, so we
> won't notice.
>
> It really would be much better in every respect to have this done by
> checkpatch, I think.
And after fixing the parsing to not trigger false positives, an
allyesconfig boot found this:
event cdns3_gadget_giveback has unsafe dereference of argument 11
print_fmt: "%s: req: %p, req buff %p, length: %u/%u %s%s%s, status: %d, trb: [start:%d, end:%d: virt addr %pa], flags:%x SID: %u", __get_str(name), REC->req, REC->buf,
REC->actual, REC->length, REC->zero ? "Z" : "z", REC->short_not_ok ? "S" : "s", REC->no_interrupt ? "I" : "i", REC->status, REC->start_trb, REC->end_trb, REC->start_trb_addr, REC->flags, RE
C->stream_id
(as the above is from a trace event class, it triggered for every event
in that class).
As it looks like it uses %pa which IIUC from the printk code, it
dereferences the pointer to find it's virtual address. The event has
this as the field:
__field(struct cdns3_trb *, start_trb_addr)
Assigns it with:
__entry->start_trb_addr = req->trb;
And prints that with %pa, which will dereference pointer at the time of
reading, where the address in question may no longer be around. That
looks to me as a potential bug.
[ Cc'd the people responsible for that code. ]
-- Steve
[ Resending with an address that should work for Felipe ]
On Sat, 27 Feb 2021 14:18:02 -0500
Steven Rostedt <[email protected]> wrote:
> On Fri, 26 Feb 2021 14:21:00 -0800
> Linus Torvalds <[email protected]> wrote:
>
> > On Fri, Feb 26, 2021 at 11:07 AM Steven Rostedt <[email protected]> wrote:
> > >
> > > The first patch scans the print fmts of the trace events looking for
> > > dereferencing pointers from %p*, and making sure that they refer back
> > > to the trace event itself.
> > >
> > > The second patch handles strings "%s" [..]
> >
> > Doing this at runtime really feels like the wrong thing to do.
> >
> > It won't even protect us from what happened - people like me and
> > Andrew won't even run those tracepoints in the first place, so we
> > won't notice.
> >
> > It really would be much better in every respect to have this done by
> > checkpatch, I think.
>
> And after fixing the parsing to not trigger false positives, an
> allyesconfig boot found this:
>
> event cdns3_gadget_giveback has unsafe dereference of argument 11
> print_fmt: "%s: req: %p, req buff %p, length: %u/%u %s%s%s, status: %d, trb: [start:%d, end:%d: virt addr %pa], flags:%x SID: %u", __get_str(name), REC->req, REC->buf,
> REC->actual, REC->length, REC->zero ? "Z" : "z", REC->short_not_ok ? "S" : "s", REC->no_interrupt ? "I" : "i", REC->status, REC->start_trb, REC->end_trb, REC->start_trb_addr, REC->flags, RE
> C->stream_id
>
> (as the above is from a trace event class, it triggered for every event
> in that class).
>
> As it looks like it uses %pa which IIUC from the printk code, it
> dereferences the pointer to find it's virtual address. The event has
> this as the field:
>
> __field(struct cdns3_trb *, start_trb_addr)
>
> Assigns it with:
>
> __entry->start_trb_addr = req->trb;
>
> And prints that with %pa, which will dereference pointer at the time of
> reading, where the address in question may no longer be around. That
> looks to me as a potential bug.
>
> [ Cc'd the people responsible for that code. ]
>
> -- Steve
+ Peter Chen - Maintainer of CDNS3 driver
>
>[ Resending with an address that should work for Felipe ]
>
>On Sat, 27 Feb 2021 14:18:02 -0500
>Steven Rostedt <[email protected]> wrote:
>
>> On Fri, 26 Feb 2021 14:21:00 -0800
>> Linus Torvalds <[email protected]> wrote:
>>
>> > On Fri, Feb 26, 2021 at 11:07 AM Steven Rostedt <[email protected]> wrote:
>> > >
>> > > The first patch scans the print fmts of the trace events looking for
>> > > dereferencing pointers from %p*, and making sure that they refer back
>> > > to the trace event itself.
>> > >
>> > > The second patch handles strings "%s" [..]
>> >
>> > Doing this at runtime really feels like the wrong thing to do.
>> >
>> > It won't even protect us from what happened - people like me and
>> > Andrew won't even run those tracepoints in the first place, so we
>> > won't notice.
>> >
>> > It really would be much better in every respect to have this done by
>> > checkpatch, I think.
>>
>> And after fixing the parsing to not trigger false positives, an
>> allyesconfig boot found this:
>>
>> event cdns3_gadget_giveback has unsafe dereference of argument 11
>> print_fmt: "%s: req: %p, req buff %p, length: %u/%u %s%s%s, status: %d, trb: [start:%d, end:%d: virt addr %pa], flags:%x SID: %u",
>__get_str(name), REC->req, REC->buf,
>> REC->actual, REC->length, REC->zero ? "Z" : "z", REC->short_not_ok ? "S" : "s", REC->no_interrupt ? "I" : "i", REC->status, REC-
>>start_trb, REC->end_trb, REC->start_trb_addr, REC->flags, RE
>> C->stream_id
>>
>> (as the above is from a trace event class, it triggered for every event
>> in that class).
>>
>> As it looks like it uses %pa which IIUC from the printk code, it
>> dereferences the pointer to find it's virtual address. The event has
>> this as the field:
>>
>> __field(struct cdns3_trb *, start_trb_addr)
>>
>> Assigns it with:
>>
>> __entry->start_trb_addr = req->trb;
>>
>> And prints that with %pa, which will dereference pointer at the time of
>> reading, where the address in question may no longer be around. That
>> looks to me as a potential bug.
>>
>> [ Cc'd the people responsible for that code. ]
>>
>> -- Steve
On 21-03-01 05:27:04, Pawel Laszczak wrote:
>
> + Peter Chen - Maintainer of CDNS3 driver
>
> >
> >[ Resending with an address that should work for Felipe ]
> >
> >On Sat, 27 Feb 2021 14:18:02 -0500
> >Steven Rostedt <[email protected]> wrote:
> >
> >> On Fri, 26 Feb 2021 14:21:00 -0800
> >> Linus Torvalds <[email protected]> wrote:
> >>
> >> > On Fri, Feb 26, 2021 at 11:07 AM Steven Rostedt <[email protected]> wrote:
> >> > >
> >> > > The first patch scans the print fmts of the trace events looking for
> >> > > dereferencing pointers from %p*, and making sure that they refer back
> >> > > to the trace event itself.
> >> > >
> >> > > The second patch handles strings "%s" [..]
> >> >
> >> > Doing this at runtime really feels like the wrong thing to do.
> >> >
> >> > It won't even protect us from what happened - people like me and
> >> > Andrew won't even run those tracepoints in the first place, so we
> >> > won't notice.
> >> >
> >> > It really would be much better in every respect to have this done by
> >> > checkpatch, I think.
> >>
> >> And after fixing the parsing to not trigger false positives, an
> >> allyesconfig boot found this:
> >>
> >> event cdns3_gadget_giveback has unsafe dereference of argument 11
> >> print_fmt: "%s: req: %p, req buff %p, length: %u/%u %s%s%s, status: %d, trb: [start:%d, end:%d: virt addr %pa], flags:%x SID: %u",
> >__get_str(name), REC->req, REC->buf,
> >> REC->actual, REC->length, REC->zero ? "Z" : "z", REC->short_not_ok ? "S" : "s", REC->no_interrupt ? "I" : "i", REC->status, REC-
> >>start_trb, REC->end_trb, REC->start_trb_addr, REC->flags, RE
> >> C->stream_id
> >>
> >> (as the above is from a trace event class, it triggered for every event
> >> in that class).
> >>
> >> As it looks like it uses %pa which IIUC from the printk code, it
> >> dereferences the pointer to find it's virtual address. The event has
> >> this as the field:
> >>
> >> __field(struct cdns3_trb *, start_trb_addr)
> >>
> >> Assigns it with:
> >>
> >> __entry->start_trb_addr = req->trb;
> >>
> >> And prints that with %pa, which will dereference pointer at the time of
> >> reading, where the address in question may no longer be around. That
> >> looks to me as a potential bug.
Steven, thanks for reporting. Do you mind sending patch to fix it?
If you have no time to do it, I will do it later.
--
Thanks,
Peter Chen
On Tue, 2 Mar 2021 16:23:55 +0800
Peter Chen <[email protected]> wrote:
s it looks like it uses %pa which IIUC from the printk code, it
> > >> dereferences the pointer to find it's virtual address. The event has
> > >> this as the field:
> > >>
> > >> __field(struct cdns3_trb *, start_trb_addr)
> > >>
> > >> Assigns it with:
> > >>
> > >> __entry->start_trb_addr = req->trb;
> > >>
> > >> And prints that with %pa, which will dereference pointer at the time of
> > >> reading, where the address in question may no longer be around. That
> > >> looks to me as a potential bug.
>
> Steven, thanks for reporting. Do you mind sending patch to fix it?
> If you have no time to do it, I will do it later.
>
I would have already fixed it, but I wasn't exactly sure how this is used.
In Documentation/core-api/printk-formats.rst we have:
Physical address types phys_addr_t
----------------------------------
::
%pa[p] 0x01234567 or 0x0123456789abcdef
For printing a phys_addr_t type (and its derivatives, such as
resource_size_t) which can vary based on build options, regardless of the
width of the CPU data path.
So it only looks like it is used to for the size of the pointer.
I guess something like this might work:
diff --git a/drivers/usb/cdns3/cdns3-trace.h b/drivers/usb/cdns3/cdns3-trace.h
index 8648c7a7a9dd..d3b8624fc427 100644
--- a/drivers/usb/cdns3/cdns3-trace.h
+++ b/drivers/usb/cdns3/cdns3-trace.h
@@ -214,7 +214,7 @@ DECLARE_EVENT_CLASS(cdns3_log_request,
__field(int, no_interrupt)
__field(int, start_trb)
__field(int, end_trb)
- __field(struct cdns3_trb *, start_trb_addr)
+ __field(phys_addr_t, start_trb_addr)
__field(int, flags)
__field(unsigned int, stream_id)
),
@@ -230,7 +230,7 @@ DECLARE_EVENT_CLASS(cdns3_log_request,
__entry->no_interrupt = req->request.no_interrupt;
__entry->start_trb = req->start_trb;
__entry->end_trb = req->end_trb;
- __entry->start_trb_addr = req->trb;
+ __entry->start_trb_addr = *(const phys_addr_t *)req->trb;
__entry->flags = req->flags;
__entry->stream_id = req->request.stream_id;
),
@@ -244,7 +244,7 @@ DECLARE_EVENT_CLASS(cdns3_log_request,
__entry->status,
__entry->start_trb,
__entry->end_trb,
- __entry->start_trb_addr,
+ /* %pa dereferences */ &__entry->start_trb_addr,
__entry->flags,
__entry->stream_id
)
Can you please test it? I don't have the hardware, but I also want to make
sure I don't break anything.
Thanks,
-- Steve
On 21-03-02 09:56:05, Steven Rostedt wrote:
> On Tue, 2 Mar 2021 16:23:55 +0800
> Peter Chen <[email protected]> wrote:
>
> s it looks like it uses %pa which IIUC from the printk code, it
> > > >> dereferences the pointer to find it's virtual address. The event has
> > > >> this as the field:
> > > >>
> > > >> __field(struct cdns3_trb *, start_trb_addr)
> > > >>
> > > >> Assigns it with:
> > > >>
> > > >> __entry->start_trb_addr = req->trb;
> > > >>
> > > >> And prints that with %pa, which will dereference pointer at the time of
> > > >> reading, where the address in question may no longer be around. That
> > > >> looks to me as a potential bug.
> >
> > Steven, thanks for reporting. Do you mind sending patch to fix it?
> > If you have no time to do it, I will do it later.
> >
>
> I would have already fixed it, but I wasn't exactly sure how this is used.
>
> In Documentation/core-api/printk-formats.rst we have:
>
> Physical address types phys_addr_t
> ----------------------------------
>
> ::
>
> %pa[p] 0x01234567 or 0x0123456789abcdef
>
> For printing a phys_addr_t type (and its derivatives, such as
> resource_size_t) which can vary based on build options, regardless of the
> width of the CPU data path.
>
> So it only looks like it is used to for the size of the pointer.
>
> I guess something like this might work:
>
> diff --git a/drivers/usb/cdns3/cdns3-trace.h b/drivers/usb/cdns3/cdns3-trace.h
> index 8648c7a7a9dd..d3b8624fc427 100644
> --- a/drivers/usb/cdns3/cdns3-trace.h
> +++ b/drivers/usb/cdns3/cdns3-trace.h
> @@ -214,7 +214,7 @@ DECLARE_EVENT_CLASS(cdns3_log_request,
> __field(int, no_interrupt)
> __field(int, start_trb)
> __field(int, end_trb)
> - __field(struct cdns3_trb *, start_trb_addr)
> + __field(phys_addr_t, start_trb_addr)
> __field(int, flags)
> __field(unsigned int, stream_id)
> ),
> @@ -230,7 +230,7 @@ DECLARE_EVENT_CLASS(cdns3_log_request,
> __entry->no_interrupt = req->request.no_interrupt;
> __entry->start_trb = req->start_trb;
> __entry->end_trb = req->end_trb;
> - __entry->start_trb_addr = req->trb;
> + __entry->start_trb_addr = *(const phys_addr_t *)req->trb;
> __entry->flags = req->flags;
> __entry->stream_id = req->request.stream_id;
> ),
> @@ -244,7 +244,7 @@ DECLARE_EVENT_CLASS(cdns3_log_request,
> __entry->status,
> __entry->start_trb,
> __entry->end_trb,
> - __entry->start_trb_addr,
> + /* %pa dereferences */ &__entry->start_trb_addr,
> __entry->flags,
> __entry->stream_id
> )
>
>
> Can you please test it? I don't have the hardware, but I also want to make
> sure I don't break anything.
>
Hi Steve,
Regarding this issue, I have one question:
- If the virtual address is got from dma_alloc_coherent, can't we print
this address using %pa to get its physical address (the same with DMA address),
or its DMA address using %pad? req->trb is the virtual address got from
dma_alloc_coherent. And what's the logic for this "unsafe dereference" warning?
Thanks.
--
Thanks,
Peter Chen
On Wed, 3 Mar 2021 09:21:39 +0800
Peter Chen <[email protected]> wrote:
> On 21-03-02 09:56:05, Steven Rostedt wrote:
> > On Tue, 2 Mar 2021 16:23:55 +0800
> > Peter Chen <[email protected]> wrote:
> >
> > s it looks like it uses %pa which IIUC from the printk code, it
> > > > >> dereferences the pointer to find it's virtual address. The event has
> > > > >> this as the field:
> > > > >>
> > > > >> __field(struct cdns3_trb *, start_trb_addr)
> > > > >>
> > > > >> Assigns it with:
> > > > >>
> > > > >> __entry->start_trb_addr = req->trb;
> > > > >>
> > > > >> And prints that with %pa, which will dereference pointer at the time of
> > > > >> reading, where the address in question may no longer be around. That
> > > > >> looks to me as a potential bug.
> > >
> > > Steven, thanks for reporting. Do you mind sending patch to fix it?
> > > If you have no time to do it, I will do it later.
> > >
> >
> > I would have already fixed it, but I wasn't exactly sure how this is used.
> >
> > In Documentation/core-api/printk-formats.rst we have:
> >
> > Physical address types phys_addr_t
> > ----------------------------------
> >
> > ::
> >
> > %pa[p] 0x01234567 or 0x0123456789abcdef
> >
> > For printing a phys_addr_t type (and its derivatives, such as
> > resource_size_t) which can vary based on build options, regardless of the
> > width of the CPU data path.
> >
> > So it only looks like it is used to for the size of the pointer.
> >
> > I guess something like this might work:
> >
> > diff --git a/drivers/usb/cdns3/cdns3-trace.h b/drivers/usb/cdns3/cdns3-trace.h
> > index 8648c7a7a9dd..d3b8624fc427 100644
> > --- a/drivers/usb/cdns3/cdns3-trace.h
> > +++ b/drivers/usb/cdns3/cdns3-trace.h
> > @@ -214,7 +214,7 @@ DECLARE_EVENT_CLASS(cdns3_log_request,
> > __field(int, no_interrupt)
> > __field(int, start_trb)
> > __field(int, end_trb)
> > - __field(struct cdns3_trb *, start_trb_addr)
> > + __field(phys_addr_t, start_trb_addr)
> > __field(int, flags)
> > __field(unsigned int, stream_id)
> > ),
> > @@ -230,7 +230,7 @@ DECLARE_EVENT_CLASS(cdns3_log_request,
> > __entry->no_interrupt = req->request.no_interrupt;
> > __entry->start_trb = req->start_trb;
> > __entry->end_trb = req->end_trb;
> > - __entry->start_trb_addr = req->trb;
> > + __entry->start_trb_addr = *(const phys_addr_t *)req->trb;
> > __entry->flags = req->flags;
> > __entry->stream_id = req->request.stream_id;
> > ),
> > @@ -244,7 +244,7 @@ DECLARE_EVENT_CLASS(cdns3_log_request,
> > __entry->status,
> > __entry->start_trb,
> > __entry->end_trb,
> > - __entry->start_trb_addr,
> > + /* %pa dereferences */ &__entry->start_trb_addr,
> > __entry->flags,
> > __entry->stream_id
> > )
> >
> >
> > Can you please test it? I don't have the hardware, but I also want to make
> > sure I don't break anything.
> >
>
> Hi Steve,
>
> Regarding this issue, I have one question:
> - If the virtual address is got from dma_alloc_coherent, can't we print
> this address using %pa to get its physical address (the same with DMA address),
> or its DMA address using %pad? req->trb is the virtual address got from
I'm not sure. I just looked at the vsprintf code, which simply does:
> static noinline_for_stack
> char *address_val(char *buf, char *end, const void *addr,
> struct printf_spec spec, const char *fmt)
> {
> unsigned long long num;
> int size;
>
> if (check_pointer(&buf, end, addr, spec))
> return buf;
>
> switch (fmt[1]) {
> case 'd':
> num = *(const dma_addr_t *)addr;
> size = sizeof(dma_addr_t);
The above is what is called, which dereferences addr and places it into num.
> break;
> case 'p':
> default:
> num = *(const phys_addr_t *)addr;
> size = sizeof(phys_addr_t);
> break;
> }
>
> return special_hex_number(buf, end, num, size);
This just prints the hex number defined by num. There's no physical address
calculations done via vsprintf that I'm aware of.
> }
> dma_alloc_coherent. And what's the logic for this "unsafe dereference" warning?
The actions done in TP_fast_assign() are executed at the time of the trace
event (i.e. when trace_cdns3_ep_queue() is called), but the actions of
TP_printk() are executed when the user reads the trace file (minutes,
hours, days later!). Thus, when you have a TP_printk("... %pa ...", and a
__entry->start_trb_addr referenced, that start_trb_addr may be pointing to
something that is long gone, and when you use a kernel vsnprintf()
dereferencing pointer like %pa (or %pU, %pM, etc), it may read something
that no longer exists, and is obviously unsafe.
So I created this patch series (in this thread, you can use lore to see it)
that analyzes the trace events as they get register, parses the TP_printk()
for any dereferencing pointers, and makes sure that what it is dereferencing
lives on the ring buffer. Otherwise it is likely referencing something that
may no longer be around when it gets dereferenced.
I booted an allyesconfig with this logic and your event triggered the
warning, and it was the only event in the kernel to do so. Thus, I've been
pretty good at policing trace events from doing such things (I've stopped a
lot of them from getting into the kernel by manually reviewing every trace
event that is Cc'd to me).
I hope that answers your question.
-- Steve
On 21-03-02 09:56:05, Steven Rostedt wrote:
> On Tue, 2 Mar 2021 16:23:55 +0800
> Peter Chen <[email protected]> wrote:
>
> s it looks like it uses %pa which IIUC from the printk code, it
> > > >> dereferences the pointer to find it's virtual address. The event has
> > > >> this as the field:
> > > >>
> > > >> __field(struct cdns3_trb *, start_trb_addr)
> > > >>
> > > >> Assigns it with:
> > > >>
> > > >> __entry->start_trb_addr = req->trb;
> > > >>
> > > >> And prints that with %pa, which will dereference pointer at the time of
> > > >> reading, where the address in question may no longer be around. That
> > > >> looks to me as a potential bug.
> >
> > Steven, thanks for reporting. Do you mind sending patch to fix it?
> > If you have no time to do it, I will do it later.
> >
>
> I would have already fixed it, but I wasn't exactly sure how this is used.
>
> In Documentation/core-api/printk-formats.rst we have:
>
> Physical address types phys_addr_t
> ----------------------------------
>
> ::
>
> %pa[p] 0x01234567 or 0x0123456789abcdef
>
> For printing a phys_addr_t type (and its derivatives, such as
> resource_size_t) which can vary based on build options, regardless of the
> width of the CPU data path.
>
> So it only looks like it is used to for the size of the pointer.
>
> I guess something like this might work:
>
> diff --git a/drivers/usb/cdns3/cdns3-trace.h b/drivers/usb/cdns3/cdns3-trace.h
> index 8648c7a7a9dd..d3b8624fc427 100644
> --- a/drivers/usb/cdns3/cdns3-trace.h
> +++ b/drivers/usb/cdns3/cdns3-trace.h
> @@ -214,7 +214,7 @@ DECLARE_EVENT_CLASS(cdns3_log_request,
> __field(int, no_interrupt)
> __field(int, start_trb)
> __field(int, end_trb)
> - __field(struct cdns3_trb *, start_trb_addr)
> + __field(phys_addr_t, start_trb_addr)
> __field(int, flags)
> __field(unsigned int, stream_id)
> ),
> @@ -230,7 +230,7 @@ DECLARE_EVENT_CLASS(cdns3_log_request,
> __entry->no_interrupt = req->request.no_interrupt;
> __entry->start_trb = req->start_trb;
> __entry->end_trb = req->end_trb;
> - __entry->start_trb_addr = req->trb;
> + __entry->start_trb_addr = *(const phys_addr_t *)req->trb;
> __entry->flags = req->flags;
> __entry->stream_id = req->request.stream_id;
> ),
> @@ -244,7 +244,7 @@ DECLARE_EVENT_CLASS(cdns3_log_request,
> __entry->status,
> __entry->start_trb,
> __entry->end_trb,
> - __entry->start_trb_addr,
> + /* %pa dereferences */ &__entry->start_trb_addr,
> __entry->flags,
> __entry->stream_id
> )
>
>
> Can you please test it? I don't have the hardware, but I also want to make
> sure I don't break anything.
>
> Thanks,
>
Since the virtual address for req->trb is NULL before using it. It will
trigger below oops using your change. There is already index
(start_trb/end_trb) for which TRB it has handled, it is not necessary
to trace information for its physical address. I decide to delete this
trace entry, thanks for reporting it.
[ 61.695160] Unable to handle kernel NULL pointer dereference at virtual address 0000000000000000
[ 61.704066] Mem abort info:
[ 61.706910] ESR = 0x96000006
[ 61.710000] EC = 0x25: DABT (current EL), IL = 32 bits
[ 61.715339] SET = 0, FnV = 0
[ 61.718416] EA = 0, S1PTW = 0
[ 61.721575] Data abort info:
[ 61.724482] ISV = 0, ISS = 0x00000006
[ 61.728323] CM = 0, WnR = 0
[ 61.731324] user pgtable: 4k pages, 48-bit VAs, pgdp=00000008856dd000
[ 61.737816] [0000000000000000] pgd=000000088577a003, p4d=000000088577a003, pud=000000088477c003, pmd=0000000000000000
[ 61.748532] Internal error: Oops: 96000006 [#1] PREEMPT SMP
[ 61.754113] Modules linked in: fsl_jr_uio caam_jr caamkeyblob_desc caamhash_desc caamalg_desc crypto_engine rng_core authenc libdes crct10dif_ce mxc_jpeg_encdec imx8_media_dev(C) caam error
Message from syslogd@imx8qmmek at Fri Jul 10 06:52:44 2020 ...
imx8qmmek kernel: [ 61.748532] Internal error: Oops: 96000006 [#1] PREEMPT SMP
[ 61.784245] CPU: 3 PID: 188 Comm: 1-0050 Tainted: G C 5.10.0-rc7-04451-gfcfe23a5424-dirty #3
[ 61.793993] Hardware name: Freescale i.MX8QXP MEK (DT)
[ 61.799139] pstate: 80000005 (Nzcv daif -PAN -UAO -TCO BTYPE=--)
[ 61.805162] pc : trace_event_raw_event_cdns3_log_request+0xf4/0x170
[ 61.811440] lr : trace_event_raw_event_cdns3_log_request+0x94/0x170
[ 61.817707] sp : ffff80001387ba40
[ 61.821019] x29: ffff80001387ba40 x28: 0000000000000002
[ 61.826336] x27: ffff000801e20080 x26: ffff000800e5c8c8
[ 61.831652] x25: ffff0008044e0c00 x24: ffff000800505308
[ 61.836969] x23: ffff800012464000 x22: 0000000000040050
[ 61.842286] x21: ffff000801e0aa00 x20: ffff0008002e7f18
[ 61.847603] x19: ffff000805131300 x18: 0000000000000000
[ 61.852919] x17: 0000000000000000 x16: 0000000000000000
[ 61.858245] x15: ffff00080081ca78 x14: ffffffffffffffff
[ 61.863570] x13: ffff800012404778 x12: 0000000000000018
[ 61.868896] x11: 0101010101010101 x10: 7f7f7f7f7f7f7f7f
[ 61.874213] x9 : fefefefeff2f6f64 x8 : ffffffffffffffff
[ 61.879529] x7 : ffff8000122b05b8 x6 : 0000000000000001
[ 61.884846] x5 : 0000000000000020 x4 : 0000000000000000
[ 61.890163] x3 : 0000000000000000 x2 : 0000000000000004
[ 61.895479] x1 : 0000000000000000 x0 : ffff80001387ba70
[ 61.900806] Call trace:
[ 61.903260] trace_event_raw_event_cdns3_log_request+0xf4/0x170
[ 61.909183] __traceiter_cdns3_free_request+0x34/0x50
[ 61.914241] cdns3_gadget_ep_free_request+0xa8/0xd8
[ 61.919123] usb_ep_free_request+0x34/0xd8
[ 61.923223] composite_dev_cleanup+0xd0/0x170
[ 61.927583] configfs_composite_unbind+0x68/0xa0
[ 61.932205] usb_gadget_remove_driver+0x4c/0xd0
[ 61.936737] usb_del_gadget+0x6c/0xc8
[ 61.940404] cdns3_gadget_exit+0x4c/0x120
[ 61.944420] cdns3_role_stop+0x60/0x90
[ 61.948174] cdns3_role_set+0x64/0xe0
[ 61.951841] usb_role_switch_set_role.part.0+0x3c/0x90
[ 61.956984] usb_role_switch_set_role+0x20/0x30
[ 61.961519] tcpm_mux_set+0x60/0x80
[ 61.965008] tcpm_reset_port+0xa4/0x108
[ 61.968851] tcpm_detach+0x6c/0xa0
[ 61.972256] tcpm_state_machine_work+0x13e0/0x24a0
[ 61.977052] kthread_worker_fn+0x9c/0x168
[ 61.981064] kthread+0x148/0x168
[ 61.984296] ret_from_fork+0x10/0x18
[ 61.987881] Code: b9003a81 b9407661 b9003e81 f9403661 (f9400021)
[ 61.993983] ---[ end trace c8f1af57d3c61281 ]---
[ 61.998669] note: 1-0050[188] exited with preempt_count 2
--
Thanks,
Peter Chen
On Sun, 7 Mar 2021 12:01:42 +0800
Peter Chen <[email protected]> wrote:
> On 21-03-02 09:56:05, Steven Rostedt wrote:
> > On Tue, 2 Mar 2021 16:23:55 +0800
> > Peter Chen <[email protected]> wrote:
> >
> > s it looks like it uses %pa which IIUC from the printk code, it
> > > > >> dereferences the pointer to find it's virtual address. The event has
> > > > >> this as the field:
> > > > >>
> > > > >> __field(struct cdns3_trb *, start_trb_addr)
> > > > >>
> > > > >> Assigns it with:
> > > > >>
> > > > >> __entry->start_trb_addr = req->trb;
> > > > >>
> > > > >> And prints that with %pa, which will dereference pointer at the time of
> > > > >> reading, where the address in question may no longer be around. That
> > > > >> looks to me as a potential bug.
> > >
> > > Steven, thanks for reporting. Do you mind sending patch to fix it?
> > > If you have no time to do it, I will do it later.
> > >
> >
> > I would have already fixed it, but I wasn't exactly sure how this is used.
> >
> > In Documentation/core-api/printk-formats.rst we have:
> >
> > Physical address types phys_addr_t
> > ----------------------------------
> >
> > ::
> >
> > %pa[p] 0x01234567 or 0x0123456789abcdef
> >
> > For printing a phys_addr_t type (and its derivatives, such as
> > resource_size_t) which can vary based on build options, regardless of the
> > width of the CPU data path.
> >
> > So it only looks like it is used to for the size of the pointer.
> >
> > I guess something like this might work:
> >
> > diff --git a/drivers/usb/cdns3/cdns3-trace.h b/drivers/usb/cdns3/cdns3-trace.h
> > index 8648c7a7a9dd..d3b8624fc427 100644
> > --- a/drivers/usb/cdns3/cdns3-trace.h
> > +++ b/drivers/usb/cdns3/cdns3-trace.h
> > @@ -214,7 +214,7 @@ DECLARE_EVENT_CLASS(cdns3_log_request,
> > __field(int, no_interrupt)
> > __field(int, start_trb)
> > __field(int, end_trb)
> > - __field(struct cdns3_trb *, start_trb_addr)
> > + __field(phys_addr_t, start_trb_addr)
> > __field(int, flags)
> > __field(unsigned int, stream_id)
> > ),
> > @@ -230,7 +230,7 @@ DECLARE_EVENT_CLASS(cdns3_log_request,
> > __entry->no_interrupt = req->request.no_interrupt;
> > __entry->start_trb = req->start_trb;
> > __entry->end_trb = req->end_trb;
> > - __entry->start_trb_addr = req->trb;
> > + __entry->start_trb_addr = *(const phys_addr_t *)req->trb;
> > __entry->flags = req->flags;
> > __entry->stream_id = req->request.stream_id;
> > ),
> > @@ -244,7 +244,7 @@ DECLARE_EVENT_CLASS(cdns3_log_request,
> > __entry->status,
> > __entry->start_trb,
> > __entry->end_trb,
> > - __entry->start_trb_addr,
> > + /* %pa dereferences */ &__entry->start_trb_addr,
> > __entry->flags,
> > __entry->stream_id
> > )
> >
> >
> > Can you please test it? I don't have the hardware, but I also want to make
> > sure I don't break anything.
> >
> > Thanks,
> >
>
> Since the virtual address for req->trb is NULL before using it. It will
> trigger below oops using your change. There is already index
> (start_trb/end_trb) for which TRB it has handled, it is not necessary
> to trace information for its physical address. I decide to delete this
> trace entry, thanks for reporting it.
Thanks for fixing / removing it. But I should have added a NULL check before
dereferencing, because that's what the vsnprintf() code does.
-- Steve