[3/3] tracing/probes: Fix return value when "(fault)" is injected

  From: Masami Hiramatsu (Google) <mhiramat@kernel.org>

When the "(fault)" is injected, the return value of fetch_store_string*()
should be the length of the "(fault)", but an error code is returned.
Fix it to return the correct length and update the data_loc according the
updated length.
This needs to update a ftracetest test case, which expects trace output
to appear as '(fault)' instead of '"(fault)"'.

Fixes: 2e9906f84fc7 ("tracing: Add "(fault)" name injection to kernel probes")
Cc: stable@vger.kernel.org
Signed-off-by: Masami Hiramatsu (Google) <mhiramat@kernel.org>
---
 kernel/trace/trace_probe_kernel.h                  |   17 +++++++----------
 .../ftrace/test.d/kprobe/kprobe_args_user.tc       |    2 +-
 2 files changed, 8 insertions(+), 11 deletions(-)
  

On Sun,  2 Jul 2023 23:47:35 +0900
"Masami Hiramatsu (Google)" <mhiramat@kernel.org> wrote:

> From: Masami Hiramatsu (Google) <mhiramat@kernel.org>
> 
> When the "(fault)" is injected, the return value of fetch_store_string*()
> should be the length of the "(fault)", but an error code is returned.
> Fix it to return the correct length and update the data_loc according the
> updated length.
> This needs to update a ftracetest test case, which expects trace output
> to appear as '(fault)' instead of '"(fault)"'.
> 

Ah, because of patch 2, the ret < 0 makes it return without printing the
"fault"?

Reviewed-by: Steven Rostedt (Google) <rostedt@goodmis.org>

-- Steve


> Fixes: 2e9906f84fc7 ("tracing: Add "(fault)" name injection to kernel probes")
> Cc: stable@vger.kernel.org
> Signed-off-by: Masami Hiramatsu (Google) <mhiramat@kernel.org>
> ---
  

On Wed, 5 Jul 2023 22:49:56 -0400
Steven Rostedt <rostedt@goodmis.org> wrote:

> On Sun,  2 Jul 2023 23:47:35 +0900
> "Masami Hiramatsu (Google)" <mhiramat@kernel.org> wrote:
> 
> > From: Masami Hiramatsu (Google) <mhiramat@kernel.org>
> > 
> > When the "(fault)" is injected, the return value of fetch_store_string*()
> > should be the length of the "(fault)", but an error code is returned.
> > Fix it to return the correct length and update the data_loc according the
> > updated length.
> > This needs to update a ftracetest test case, which expects trace output
> > to appear as '(fault)' instead of '"(fault)"'.
> > 
> 
> Ah, because of patch 2, the ret < 0 makes it return without printing the
> "fault"?

No, actually set_data_loc() updates the 'ret' argument, but it is just
disposed... (not returned to the caller)

-static nokprobe_inline void set_data_loc(int ret, void *dest, void *__dest, void *base, int len)
+static nokprobe_inline int set_data_loc(int ret, void *dest, void *__dest, void *base, int len)
 {
-	if (ret >= 0) {
-		*(u32 *)dest = make_data_loc(ret, __dest - base);
-	} else {
+	if (ret < 0) {
 		strscpy(__dest, FAULT_STRING, len);
 		ret = strlen(__dest) + 1;
 	}
+
+	*(u32 *)dest = make_data_loc(ret, __dest - base);
+	return ret;
 }

So this returns updated 'ret', and also update data_loc to use the
updated 'ret' value (which is the length of the stored data).

> 
> Reviewed-by: Steven Rostedt (Google) <rostedt@goodmis.org>

Thank you!

> 
> -- Steve
> 
> 
> > Fixes: 2e9906f84fc7 ("tracing: Add "(fault)" name injection to kernel probes")
> > Cc: stable@vger.kernel.org
> > Signed-off-by: Masami Hiramatsu (Google) <mhiramat@kernel.org>
> > ---
  

On Thu, 6 Jul 2023 13:40:36 +0900
Masami Hiramatsu (Google) <mhiramat@kernel.org> wrote:

> On Wed, 5 Jul 2023 22:49:56 -0400
> Steven Rostedt <rostedt@goodmis.org> wrote:
> 
> > On Sun,  2 Jul 2023 23:47:35 +0900
> > "Masami Hiramatsu (Google)" <mhiramat@kernel.org> wrote:
> >   
> > > From: Masami Hiramatsu (Google) <mhiramat@kernel.org>
> > > 
> > > When the "(fault)" is injected, the return value of fetch_store_string*()
> > > should be the length of the "(fault)", but an error code is returned.
> > > Fix it to return the correct length and update the data_loc according the
> > > updated length.
> > > This needs to update a ftracetest test case, which expects trace output
> > > to appear as '(fault)' instead of '"(fault)"'.
> > >   
> > 
> > Ah, because of patch 2, the ret < 0 makes it return without printing the
> > "fault"?  
> 
> No, actually set_data_loc() updates the 'ret' argument, but it is just
> disposed... (not returned to the caller)

That's not what I was talking about.

We have:

process_fetch_insn_bottom() {
	[..]
	case FETCH_OP_ST_STRING:
		loc = *(u32 *)dest;
		ret = fetch_store_string(val + code->offset, dest, base);
		break;
	[..]

// And from patch 2 we have:

@@ -193,6 +193,8 @@ process_fetch_insn_bottom(struct fetch_insn *code, unsigned long val,
 	default:
 		return -EILSEQ;
 	}
+	if (ret < 0)
+		return ret;
 	code++;

And now that the return value of fetch_store_string() is being checked, and
if it returns negative, it ends the function before being processed
further. And if there's a fault, it happens to return negative!

This patch now changes fetch_store_string() and fetch_store_string_user()
to not return negative if there's a fault. As this patch has:

@@ -107,9 +106,7 @@ fetch_store_string(unsigned long addr, void *dest, void *base)
 	 * probing.
 	 */
 	ret = strncpy_from_kernel_nofault(__dest, (void *)addr, maxlen);
-	set_data_loc(ret, dest, __dest, base, maxlen);
-
-	return ret;
+	return set_data_loc(ret, dest, __dest, base, maxlen);
 }

But to do that, you needed to update set_data_loc() to return a value.

*that's* what I meant by 

'Ah, because of patch 2, the ret < 0 makes it return without printing the "fault"?'


-- Steve

> 
> -static nokprobe_inline void set_data_loc(int ret, void *dest, void *__dest, void *base, int len)
> +static nokprobe_inline int set_data_loc(int ret, void *dest, void *__dest, void *base, int len)
>  {
> -	if (ret >= 0) {
> -		*(u32 *)dest = make_data_loc(ret, __dest - base);
> -	} else {
> +	if (ret < 0) {
>  		strscpy(__dest, FAULT_STRING, len);
>  		ret = strlen(__dest) + 1;
>  	}
> +
> +	*(u32 *)dest = make_data_loc(ret, __dest - base);
> +	return ret;
>  }
> 
> So this returns updated 'ret', and also update data_loc to use the
> updated 'ret' value (which is the length of the stored data).
> 
> > 
> > Reviewed-by: Steven Rostedt (Google) <rostedt@goodmis.org>  
> 
> Thank you!
> 
> > 
> > -- Steve
> > 
> >   
> > > Fixes: 2e9906f84fc7 ("tracing: Add "(fault)" name injection to kernel probes")
> > > Cc: stable@vger.kernel.org
> > > Signed-off-by: Masami Hiramatsu (Google) <mhiramat@kernel.org>
> > > ---  
> 
>
  

On Thu, 6 Jul 2023 09:50:39 -0400
Steven Rostedt <rostedt@goodmis.org> wrote:

> On Thu, 6 Jul 2023 13:40:36 +0900
> Masami Hiramatsu (Google) <mhiramat@kernel.org> wrote:
> 
> > On Wed, 5 Jul 2023 22:49:56 -0400
> > Steven Rostedt <rostedt@goodmis.org> wrote:
> > 
> > > On Sun,  2 Jul 2023 23:47:35 +0900
> > > "Masami Hiramatsu (Google)" <mhiramat@kernel.org> wrote:
> > >   
> > > > From: Masami Hiramatsu (Google) <mhiramat@kernel.org>
> > > > 
> > > > When the "(fault)" is injected, the return value of fetch_store_string*()
> > > > should be the length of the "(fault)", but an error code is returned.
> > > > Fix it to return the correct length and update the data_loc according the
> > > > updated length.
> > > > This needs to update a ftracetest test case, which expects trace output
> > > > to appear as '(fault)' instead of '"(fault)"'.
> > > >   
> > > 
> > > Ah, because of patch 2, the ret < 0 makes it return without printing the
> > > "fault"?  
> > 
> > No, actually set_data_loc() updates the 'ret' argument, but it is just
> > disposed... (not returned to the caller)
> 
> That's not what I was talking about.
> 
> We have:
> 
> process_fetch_insn_bottom() {
> 	[..]
> 	case FETCH_OP_ST_STRING:
> 		loc = *(u32 *)dest;
> 		ret = fetch_store_string(val + code->offset, dest, base);
> 		break;
> 	[..]
> 
> // And from patch 2 we have:
> 
> @@ -193,6 +193,8 @@ process_fetch_insn_bottom(struct fetch_insn *code, unsigned long val,
>  	default:
>  		return -EILSEQ;
>  	}
> +	if (ret < 0)
> +		return ret;
>  	code++;
> 
> And now that the return value of fetch_store_string() is being checked, and
> if it returns negative, it ends the function before being processed
> further. And if there's a fault, it happens to return negative!
> 
> This patch now changes fetch_store_string() and fetch_store_string_user()
> to not return negative if there's a fault. As this patch has:
> 
> @@ -107,9 +106,7 @@ fetch_store_string(unsigned long addr, void *dest, void *base)
>  	 * probing.
>  	 */
>  	ret = strncpy_from_kernel_nofault(__dest, (void *)addr, maxlen);
> -	set_data_loc(ret, dest, __dest, base, maxlen);
> -
> -	return ret;
> +	return set_data_loc(ret, dest, __dest, base, maxlen);
>  }
> 
> But to do that, you needed to update set_data_loc() to return a value.
> 
> *that's* what I meant by 
> 
> 'Ah, because of patch 2, the ret < 0 makes it return without printing the "fault"?'

Yes, that's correct. Actually, the data ("(fault)") is stored, but ignored
because data_loc is not updated.

But wait, it seems that the print function shows (fault), so commit 2e9906f84fc7
("tracing: Add "(fault)" name injection to kernel probes") may not needed?

----
/* Print type function for string type */
int PRINT_TYPE_FUNC_NAME(string)(struct trace_seq *s, void *data, void *ent)
{
        int len = *(u32 *)data >> 16;

        if (!len)
                trace_seq_puts(s, "(fault)");
        else
----

In this case, what we need is to set data_loc length = 0 if ret < 0.

Do you really need to get '"(fault)"' (with double quotation) or
just '(fault)' (no double quotation) is OK?

Thank you,
> 
> 
> -- Steve
> 
> > 
> > -static nokprobe_inline void set_data_loc(int ret, void *dest, void *__dest, void *base, int len)
> > +static nokprobe_inline int set_data_loc(int ret, void *dest, void *__dest, void *base, int len)
> >  {
> > -	if (ret >= 0) {
> > -		*(u32 *)dest = make_data_loc(ret, __dest - base);
> > -	} else {
> > +	if (ret < 0) {
> >  		strscpy(__dest, FAULT_STRING, len);
> >  		ret = strlen(__dest) + 1;
> >  	}
> > +
> > +	*(u32 *)dest = make_data_loc(ret, __dest - base);
> > +	return ret;
> >  }
> > 
> > So this returns updated 'ret', and also update data_loc to use the
> > updated 'ret' value (which is the length of the stored data).
> > 
> > > 
> > > Reviewed-by: Steven Rostedt (Google) <rostedt@goodmis.org>  
> > 
> > Thank you!
> > 
> > > 
> > > -- Steve
> > > 
> > >   
> > > > Fixes: 2e9906f84fc7 ("tracing: Add "(fault)" name injection to kernel probes")
> > > > Cc: stable@vger.kernel.org
> > > > Signed-off-by: Masami Hiramatsu (Google) <mhiramat@kernel.org>
> > > > ---  
> > 
> > 
>
  

On Fri, 7 Jul 2023 11:02:10 +0900
Masami Hiramatsu (Google) <mhiramat@kernel.org> wrote:

> /* Print type function for string type */
> int PRINT_TYPE_FUNC_NAME(string)(struct trace_seq *s, void *data, void *ent)
> {
>         int len = *(u32 *)data >> 16;
> 
>         if (!len)
>                 trace_seq_puts(s, "(fault)");
>         else
> ----
> 
> In this case, what we need is to set data_loc length = 0 if ret < 0.
> 
> Do you really need to get '"(fault)"' (with double quotation) or
> just '(fault)' (no double quotation) is OK?

 ># echo 'e:myopen syscalls/sys_enter_openat file=+0($filename):ustring' >> /sys/kernel/tracing/dynamic_events
 ># trace-cmd start -e myopen
 ># trace-cmd show
# tracer: nop
#
# entries-in-buffer/entries-written: 19/19   #P:4
#
#                                _-----=> irqs-off/BH-disabled
#                               / _----=> need-resched
#                              | / _---=> hardirq/softirq
#                              || / _--=> preempt-depth
#                              ||| / _-=> migrate-disable
#                              |||| /     delay
#           TASK-PID     CPU#  |||||  TIMESTAMP  FUNCTION
#              | |         |   |||||     |         |
       trace-cmd-4688    [000] ...1. 466968.015784: myopen: (syscalls.sys_enter_openat) file=(fault)
       trace-cmd-4688    [000] ...1. 466968.015816: myopen: (syscalls.sys_enter_openat) file=(fault)
       trace-cmd-4688    [000] ...1. 466968.015833: myopen: (syscalls.sys_enter_openat) file=(fault)
       trace-cmd-4688    [000] ...1. 466968.015849: myopen: (syscalls.sys_enter_openat) file=(fault)
       trace-cmd-4688    [000] ...1. 466968.015864: myopen: (syscalls.sys_enter_openat) file=(fault)
       trace-cmd-4688    [000] ...1. 466968.015879: myopen: (syscalls.sys_enter_openat) file=(fault)


Does that answer your question? ;-)

-- Steve
  

On Thu, 6 Jul 2023 22:20:20 -0400
Steven Rostedt <rostedt@goodmis.org> wrote:

> On Fri, 7 Jul 2023 11:02:10 +0900
> Masami Hiramatsu (Google) <mhiramat@kernel.org> wrote:
> 
> > /* Print type function for string type */
> > int PRINT_TYPE_FUNC_NAME(string)(struct trace_seq *s, void *data, void *ent)
> > {
> >         int len = *(u32 *)data >> 16;
> > 
> >         if (!len)
> >                 trace_seq_puts(s, "(fault)");
> >         else
> > ----
> > 
> > In this case, what we need is to set data_loc length = 0 if ret < 0.
> > 
> > Do you really need to get '"(fault)"' (with double quotation) or
> > just '(fault)' (no double quotation) is OK?
> 
>  ># echo 'e:myopen syscalls/sys_enter_openat file=+0($filename):ustring' >> /sys/kernel/tracing/dynamic_events
>  ># trace-cmd start -e myopen
>  ># trace-cmd show
> # tracer: nop
> #
> # entries-in-buffer/entries-written: 19/19   #P:4
> #
> #                                _-----=> irqs-off/BH-disabled
> #                               / _----=> need-resched
> #                              | / _---=> hardirq/softirq
> #                              || / _--=> preempt-depth
> #                              ||| / _-=> migrate-disable
> #                              |||| /     delay
> #           TASK-PID     CPU#  |||||  TIMESTAMP  FUNCTION
> #              | |         |   |||||     |         |
>        trace-cmd-4688    [000] ...1. 466968.015784: myopen: (syscalls.sys_enter_openat) file=(fault)
>        trace-cmd-4688    [000] ...1. 466968.015816: myopen: (syscalls.sys_enter_openat) file=(fault)
>        trace-cmd-4688    [000] ...1. 466968.015833: myopen: (syscalls.sys_enter_openat) file=(fault)
>        trace-cmd-4688    [000] ...1. 466968.015849: myopen: (syscalls.sys_enter_openat) file=(fault)
>        trace-cmd-4688    [000] ...1. 466968.015864: myopen: (syscalls.sys_enter_openat) file=(fault)
>        trace-cmd-4688    [000] ...1. 466968.015879: myopen: (syscalls.sys_enter_openat) file=(fault)
> 
> 
> Does that answer your question? ;-)

Ah, I meant that your commit 2e9906f84fc7 ("tracing: Add "(fault)" name injection
 to kernel probes") tries to make it '"(fault)"', So it makes 

       trace-cmd-4688    [000] ...1. 466968.015879: myopen: (syscalls.sys_enter_openat) file="(fault)"

Keeping it current '(fault)' makes easy to identify which one is failed to fetch,
but it may require user to parse both "some string" and (fault). I thought that
was the reason why you added that commit.

Thank you,

> 
> -- Steve
  

On Fri, 7 Jul 2023 11:51:28 +0900
Masami Hiramatsu (Google) <mhiramat@kernel.org> wrote:

> Ah, I meant that your commit 2e9906f84fc7 ("tracing: Add "(fault)" name injection
>  to kernel probes") tries to make it '"(fault)"', So it makes 
> 
>        trace-cmd-4688    [000] ...1. 466968.015879: myopen: (syscalls.sys_enter_openat) file="(fault)"
> 
> Keeping it current '(fault)' makes easy to identify which one is failed to fetch,
> but it may require user to parse both "some string" and (fault). I thought that
> was the reason why you added that commit.

Hmm, That commit didn't explicitly add the double quotes. That may just
have been a side effect of passing back the string?

But I agree, just (fault) instead of "(fault)" is more explicit that it
faulted.

-- Steve
  

On Thu, 6 Jul 2023 23:06:42 -0400
Steven Rostedt <rostedt@goodmis.org> wrote:

> On Fri, 7 Jul 2023 11:51:28 +0900
> Masami Hiramatsu (Google) <mhiramat@kernel.org> wrote:
> 
> > Ah, I meant that your commit 2e9906f84fc7 ("tracing: Add "(fault)" name injection
> >  to kernel probes") tries to make it '"(fault)"', So it makes 
> > 
> >        trace-cmd-4688    [000] ...1. 466968.015879: myopen: (syscalls.sys_enter_openat) file="(fault)"
> > 
> > Keeping it current '(fault)' makes easy to identify which one is failed to fetch,
> > but it may require user to parse both "some string" and (fault). I thought that
> > was the reason why you added that commit.
> 
> Hmm, That commit didn't explicitly add the double quotes. That may just
> have been a side effect of passing back the string?
> 
> But I agree, just (fault) instead of "(fault)" is more explicit that it
> faulted.

OK, let me revert that commit and clarify what the data_loc data should be
with fault case.

Thank you,

> 
> -- Steve