2021-01-25 18:25:57

by Oleg Nesterov

[permalink] [raw]
Subject: Re: [PATCH v3] tracing: precise log info for kretprobe addr err

On 01/26, Jianlin Lv wrote:
>
> When trying to create kretprobe with the wrong function symbol in tracefs;
> The error is triggered in the register_trace_kprobe() and recorded as
> FAIL_REG_PROBE issue,
>
> Example:
> $ cd /sys/kernel/debug/tracing
> $ echo 'r:myprobe ERROR_SYMBOL_XXX ret=%x0' >> kprobe_events
> bash: echo: write error: Invalid argument
> $ cat error_log
> [142797.347877] trace_kprobe: error: Failed to register probe event
> Command: r:myprobe ERROR_SYMBOL_XXX ret=%x0
> ^
>
> This error can be detected in the parameter parsing stage, the effect of
> applying this patch is as follows:
>
> $ echo 'r:myprobe ERROR_SYMBOL_XXX ret=%x0' >> kprobe_events
> bash: echo: write error: Invalid argument
> $ cat error_log
> [415.89]trace_kprobe: error: Retprobe address must be an function entry
> Command: r:myprobe ERROR_SYMBOL_XXX ret=%x0

IOW, the "offset != 0" check removed by this patch is obviously wrong, right?

Agreed, but...

> --- a/kernel/trace/trace_kprobe.c
> +++ b/kernel/trace/trace_kprobe.c
> @@ -830,7 +830,7 @@ static int trace_kprobe_create(int argc, const char *argv[])
> flags |= TPARG_FL_RETURN;
> if (kprobe_on_func_entry(NULL, symbol, offset))
> flags |= TPARG_FL_FENTRY;
> - if (offset && is_return && !(flags & TPARG_FL_FENTRY)) {
> + if (!strchr(symbol, ':') && is_return && !(flags & TPARG_FL_FENTRY)) {

but why did you add the strchr(':') check instead?

I was really puzzled until I found the this email from Masami:
https://lore.kernel.org/lkml/[email protected]/

So I leave this to you and Masami, but perhaps you can document this check at
least in the changelog?

Oleg.


2021-01-25 18:41:56

by Steven Rostedt

[permalink] [raw]
Subject: Re: [PATCH v3] tracing: precise log info for kretprobe addr err

On Mon, 25 Jan 2021 19:19:27 +0100
Oleg Nesterov <[email protected]> wrote:

> On 01/26, Jianlin Lv wrote:
> >
> > When trying to create kretprobe with the wrong function symbol in tracefs;
> > The error is triggered in the register_trace_kprobe() and recorded as
> > FAIL_REG_PROBE issue,
> >
> > Example:
> > $ cd /sys/kernel/debug/tracing
> > $ echo 'r:myprobe ERROR_SYMBOL_XXX ret=%x0' >> kprobe_events
> > bash: echo: write error: Invalid argument
> > $ cat error_log
> > [142797.347877] trace_kprobe: error: Failed to register probe event
> > Command: r:myprobe ERROR_SYMBOL_XXX ret=%x0
> > ^
> >
> > This error can be detected in the parameter parsing stage, the effect of
> > applying this patch is as follows:
> >
> > $ echo 'r:myprobe ERROR_SYMBOL_XXX ret=%x0' >> kprobe_events
> > bash: echo: write error: Invalid argument
> > $ cat error_log
> > [415.89]trace_kprobe: error: Retprobe address must be an function entry
> > Command: r:myprobe ERROR_SYMBOL_XXX ret=%x0
>
> IOW, the "offset != 0" check removed by this patch is obviously wrong, right?
>
> Agreed, but...
>
> > --- a/kernel/trace/trace_kprobe.c
> > +++ b/kernel/trace/trace_kprobe.c
> > @@ -830,7 +830,7 @@ static int trace_kprobe_create(int argc, const char *argv[])
> > flags |= TPARG_FL_RETURN;
> > if (kprobe_on_func_entry(NULL, symbol, offset))
> > flags |= TPARG_FL_FENTRY;
> > - if (offset && is_return && !(flags & TPARG_FL_FENTRY)) {
> > + if (!strchr(symbol, ':') && is_return && !(flags & TPARG_FL_FENTRY)) {
>
> but why did you add the strchr(':') check instead?
>
> I was really puzzled until I found the this email from Masami:
> https://lore.kernel.org/lkml/[email protected]/
>
> So I leave this to you and Masami, but perhaps you can document this check at
> least in the changelog?
>

No, you are correct. That needs to be documented in the code.

I was about to comment that the check requires a comment ;-)

Jianlin,

Care to send a v4 of the patch with a comment to why we are checking the
symbol for ':'.

Thanks!

-- Steve

2021-01-26 11:05:05

by Masami Hiramatsu

[permalink] [raw]
Subject: Re: [PATCH v3] tracing: precise log info for kretprobe addr err

On Mon, 25 Jan 2021 13:38:40 -0500
Steven Rostedt <[email protected]> wrote:

> On Mon, 25 Jan 2021 19:19:27 +0100
> Oleg Nesterov <[email protected]> wrote:
>
> > On 01/26, Jianlin Lv wrote:
> > >
> > > When trying to create kretprobe with the wrong function symbol in tracefs;
> > > The error is triggered in the register_trace_kprobe() and recorded as
> > > FAIL_REG_PROBE issue,
> > >
> > > Example:
> > > $ cd /sys/kernel/debug/tracing
> > > $ echo 'r:myprobe ERROR_SYMBOL_XXX ret=%x0' >> kprobe_events
> > > bash: echo: write error: Invalid argument
> > > $ cat error_log
> > > [142797.347877] trace_kprobe: error: Failed to register probe event
> > > Command: r:myprobe ERROR_SYMBOL_XXX ret=%x0
> > > ^
> > >
> > > This error can be detected in the parameter parsing stage, the effect of
> > > applying this patch is as follows:
> > >
> > > $ echo 'r:myprobe ERROR_SYMBOL_XXX ret=%x0' >> kprobe_events
> > > bash: echo: write error: Invalid argument
> > > $ cat error_log
> > > [415.89]trace_kprobe: error: Retprobe address must be an function entry
> > > Command: r:myprobe ERROR_SYMBOL_XXX ret=%x0
> >
> > IOW, the "offset != 0" check removed by this patch is obviously wrong, right?
> >

No, not wrong. Even offset != 0, if the symbol exists in the kernel,
kprobe_on_func_entry() will check it.

> > Agreed, but...
> >
> > > --- a/kernel/trace/trace_kprobe.c
> > > +++ b/kernel/trace/trace_kprobe.c
> > > @@ -830,7 +830,7 @@ static int trace_kprobe_create(int argc, const char *argv[])
> > > flags |= TPARG_FL_RETURN;
> > > if (kprobe_on_func_entry(NULL, symbol, offset))
> > > flags |= TPARG_FL_FENTRY;
> > > - if (offset && is_return && !(flags & TPARG_FL_FENTRY)) {
> > > + if (!strchr(symbol, ':') && is_return && !(flags & TPARG_FL_FENTRY)) {
> >
> > but why did you add the strchr(':') check instead?
> >
> > I was really puzzled until I found the this email from Masami:
> > https://lore.kernel.org/lkml/[email protected]/
> >
> > So I leave this to you and Masami, but perhaps you can document this check at
> > least in the changelog?
> >
>
> No, you are correct. That needs to be documented in the code.

Agreed. There should be commented that is defered until the module is loaded.

>
> I was about to comment that the check requires a comment ;-)
>
> Jianlin,
>
> Care to send a v4 of the patch with a comment to why we are checking the
> symbol for ':'.

Thank you!

>
> Thanks!
>
> -- Steve
>


--
Masami Hiramatsu <[email protected]>

2021-01-26 12:49:02

by Jianlin Lv

[permalink] [raw]
Subject: RE: [PATCH v3] tracing: precise log info for kretprobe addr err



> -----Original Message-----
> From: Masami Hiramatsu <[email protected]>
> Sent: Tuesday, January 26, 2021 12:16 PM
> To: Steven Rostedt <[email protected]>
> Cc: Oleg Nesterov <[email protected]>; Jianlin Lv <[email protected]>;
> [email protected]; [email protected]; [email protected]
> Subject: Re: [PATCH v3] tracing: precise log info for kretprobe addr err
>
> On Mon, 25 Jan 2021 13:38:40 -0500
> Steven Rostedt <[email protected]> wrote:
>
> > On Mon, 25 Jan 2021 19:19:27 +0100
> > Oleg Nesterov <[email protected]> wrote:
> >
> > > On 01/26, Jianlin Lv wrote:
> > > >
> > > > When trying to create kretprobe with the wrong function symbol in
> > > > tracefs; The error is triggered in the register_trace_kprobe() and
> > > > recorded as FAIL_REG_PROBE issue,
> > > >
> > > > Example:
> > > > $ cd /sys/kernel/debug/tracing
> > > > $ echo 'r:myprobe ERROR_SYMBOL_XXX ret=%x0' >> kprobe_events
> > > > bash: echo: write error: Invalid argument
> > > > $ cat error_log
> > > > [142797.347877] trace_kprobe: error: Failed to register probe event
> > > > Command: r:myprobe ERROR_SYMBOL_XXX ret=%x0
> > > > ^
> > > >
> > > > This error can be detected in the parameter parsing stage, the
> > > > effect of applying this patch is as follows:
> > > >
> > > > $ echo 'r:myprobe ERROR_SYMBOL_XXX ret=%x0' >> kprobe_events
> > > > bash: echo: write error: Invalid argument
> > > > $ cat error_log
> > > > [415.89]trace_kprobe: error: Retprobe address must be an function
> entry
> > > > Command: r:myprobe ERROR_SYMBOL_XXX ret=%x0
> > >
> > > IOW, the "offset != 0" check removed by this patch is obviously wrong,
> right?
> > >
>
> No, not wrong. Even offset != 0, if the symbol exists in the kernel,
> kprobe_on_func_entry() will check it.
>
> > > Agreed, but...
> > >
> > > > --- a/kernel/trace/trace_kprobe.c
> > > > +++ b/kernel/trace/trace_kprobe.c
> > > > @@ -830,7 +830,7 @@ static int trace_kprobe_create(int argc, const
> char *argv[])
> > > > flags |= TPARG_FL_RETURN;
> > > > if (kprobe_on_func_entry(NULL, symbol, offset))
> > > > flags |= TPARG_FL_FENTRY;
> > > > -if (offset && is_return && !(flags & TPARG_FL_FENTRY)) {
> > > > +if (!strchr(symbol, ':') && is_return && !(flags &
> > > > +TPARG_FL_FENTRY)) {
> > >
> > > but why did you add the strchr(':') check instead?
> > >
> > > I was really puzzled until I found the this email from Masami:
> > >
> https://lore.kernel.org/lkml/20210120131406.5a992c1e434681750a0cd5d4
> > > @kernel.org/
> > >
> > > So I leave this to you and Masami, but perhaps you can document this
> > > check at least in the changelog?
> > >
> >
> > No, you are correct. That needs to be documented in the code.
>
> Agreed. There should be commented that is defered until the module is
> loaded.
>
> >
> > I was about to comment that the check requires a comment ;-)
> >
> > Jianlin,
> >
> > Care to send a v4 of the patch with a comment to why we are checking
> > the symbol for ':'.
>
> Thank you!
>
> >
> > Thanks!
> >
> > -- Steve
> >

Thanks for everyone's comments; I will update this patch.
In addition, I have another question.

perf-probe can add a probe on a module which has not been loaded yet.
But I still get an error when I execute the following command:
# perf probe -m /lib/modules/5.11.0-rc2+/kernel/drivers/net/vxlan.ko
'vxlan_xmit%return $retval'
Failed to write event: Invalid argument
Error: Failed to add events.

According to my investigation, __register_trace_kprobe will return -EINVAL,
because the vxlan module is not loaded;

__register_trace_kprobe
->register_kretprobe
->kprobe_on_func_entry
->return -EINVAL;

The following code snippet shows that the probe of the offline module can be
registered successfully only when the ret value is -ENOENT.

ret = __register_trace_kprobe(tk);
if (ret == -ENOENT && !trace_kprobe_module_exist(tk)) {
pr_warn("This probe might be able to register after target module is loaded. Continue.\n");
ret = 0;
}

kretprobe events not work with Offline Modules.
Is this a bug?

Jianlin

>
>
> --
> Masami Hiramatsu <[email protected]>
IMPORTANT NOTICE: The contents of this email and any attachments are confidential and may also be privileged. If you are not the intended recipient, please notify the sender immediately and do not disclose the contents to any other person, use it for any purpose, or store or copy the information in any medium. Thank you.

2021-01-27 19:50:32

by Oleg Nesterov

[permalink] [raw]
Subject: Re: [PATCH v3] tracing: precise log info for kretprobe addr err

On 01/26, Masami Hiramatsu wrote:
>
> > >
> > > IOW, the "offset != 0" check removed by this patch is obviously wrong, right?
> > >
>
> No, not wrong. Even offset != 0, if the symbol exists in the kernel,
> kprobe_on_func_entry() will check it.

Yes, but unless I am totally confused... if kprobe_on_func_entry() returns false,
then trace_kprobe_create() should fail with BAD_RETPROBE even if offset == 0 ?

Oleg.

2021-01-27 19:51:40

by Steven Rostedt

[permalink] [raw]
Subject: Re: [PATCH v3] tracing: precise log info for kretprobe addr err

On Tue, 26 Jan 2021 21:20:59 +0100
Oleg Nesterov <[email protected]> wrote:

> > No, not wrong. Even offset != 0, if the symbol exists in the kernel,
> > kprobe_on_func_entry() will check it.
>
> Yes, but unless I am totally confused... if kprobe_on_func_entry() returns false,
> then trace_kprobe_create() should fail with BAD_RETPROBE even if offset == 0 ?

From what I understand. kprobe_on_func_entry() can return false if you pass
in: "MOD:not_yet_loaded_module_func", but this is OK, because when the
module is loaded, and the "not_yet_loaded_module_func" exists, the
kretprobe will then be added.

The strchr(symbol,":") check is to see if "MOD:" (or some other ":" command)
is in the name, and we don't want it to fail if it is. Which is why we
should have that commented.

-- Steve

2021-01-27 19:53:35

by Oleg Nesterov

[permalink] [raw]
Subject: Re: [PATCH v3] tracing: precise log info for kretprobe addr err

On 01/26, Steven Rostedt wrote:
>
> On Tue, 26 Jan 2021 21:20:59 +0100
> Oleg Nesterov <[email protected]> wrote:
>
> > > No, not wrong. Even offset != 0, if the symbol exists in the kernel,
> > > kprobe_on_func_entry() will check it.
> >
> > Yes, but unless I am totally confused... if kprobe_on_func_entry() returns false,
> > then trace_kprobe_create() should fail with BAD_RETPROBE even if offset == 0 ?
>
> From what I understand. kprobe_on_func_entry() can return false if you pass
> in: "MOD:not_yet_loaded_module_func", but this is OK, because when the
> module is loaded, and the "not_yet_loaded_module_func" exists, the
> kretprobe will then be added.
>
> The strchr(symbol,":") check is to see if "MOD:" (or some other ":" command)
> is in the name, and we don't want it to fail if it is. Which is why we
> should have that commented.

Agreed, this matches my understanding.

But just in case... not sure I read this code correctly, but I think that
module_kallsyms_lookup_name("not_yet_loaded_module_func") should work even
without the "MOD:" prefix.

IOW, kprobe_on_func_entry("not_yet_loaded_module_func") can fail, and then
later succeed if you load the module which provides this symbol.

But even if I am right, I agree with the strchr(symbol,":") check.

Oleg.

2021-01-27 19:57:09

by Steven Rostedt

[permalink] [raw]
Subject: Re: [PATCH v3] tracing: precise log info for kretprobe addr err

On Tue, 26 Jan 2021 22:17:23 +0100
Oleg Nesterov <[email protected]> wrote:

> On 01/26, Steven Rostedt wrote:
> >
> > On Tue, 26 Jan 2021 21:20:59 +0100
> > Oleg Nesterov <[email protected]> wrote:
> >
> > > > No, not wrong. Even offset != 0, if the symbol exists in the kernel,
> > > > kprobe_on_func_entry() will check it.
> > >
> > > Yes, but unless I am totally confused... if kprobe_on_func_entry() returns false,
> > > then trace_kprobe_create() should fail with BAD_RETPROBE even if offset == 0 ?
> >
> > From what I understand. kprobe_on_func_entry() can return false if you pass
> > in: "MOD:not_yet_loaded_module_func", but this is OK, because when the
> > module is loaded, and the "not_yet_loaded_module_func" exists, the
> > kretprobe will then be added.
> >
> > The strchr(symbol,":") check is to see if "MOD:" (or some other ":" command)
> > is in the name, and we don't want it to fail if it is. Which is why we
> > should have that commented.
>
> Agreed, this matches my understanding.
>
> But just in case... not sure I read this code correctly, but I think that
> module_kallsyms_lookup_name("not_yet_loaded_module_func") should work even
> without the "MOD:" prefix.
>
> IOW, kprobe_on_func_entry("not_yet_loaded_module_func") can fail, and then
> later succeed if you load the module which provides this symbol.
>
> But even if I am right, I agree with the strchr(symbol,":") check.

I see what you are saying. If "MOD" is not loaded yet, the
kprobe_on_func_entry() should succeed.

kprobe_on_func_entry(name) {
_kprobe_addr(name) {
_kprobe_lookup_name(name) {
kallsyms_lookup_name(name) {
module_kallsyms_lookup_name(name) {

Which is:

unsigned long module_kallsyms_lookup_name(const char *name)
{
struct module *mod;
char *colon;
unsigned long ret = 0;

/* Don't lock: we're in enough trouble already. */
preempt_disable();
if ((colon = strnchr(name, MODULE_NAME_LEN, ':')) != NULL) {
if ((mod = find_module_all(name, colon - name, false)) != NULL)
ret = find_kallsyms_symbol_value(mod, colon+1);
} else {
list_for_each_entry_rcu(mod, &modules, list) {
if (mod->state == MODULE_STATE_UNFORMED)
continue;
if ((ret = find_kallsyms_symbol_value(mod, name)) != 0)
break;
}
}
preempt_enable();
return ret;
}


And if find_module_all() fails, ret isn't updated, and "return ret" will
return zero.

That is, the ":" check may not be needed, but its at least good to have?

-- Steve

2021-01-27 20:59:15

by Masami Hiramatsu

[permalink] [raw]
Subject: Re: [PATCH v3] tracing: precise log info for kretprobe addr err

On Tue, 26 Jan 2021 16:40:38 -0500
Steven Rostedt <[email protected]> wrote:

> On Tue, 26 Jan 2021 22:17:23 +0100
> Oleg Nesterov <[email protected]> wrote:
>
> > On 01/26, Steven Rostedt wrote:
> > >
> > > On Tue, 26 Jan 2021 21:20:59 +0100
> > > Oleg Nesterov <[email protected]> wrote:
> > >
> > > > > No, not wrong. Even offset != 0, if the symbol exists in the kernel,
> > > > > kprobe_on_func_entry() will check it.
> > > >
> > > > Yes, but unless I am totally confused... if kprobe_on_func_entry() returns false,
> > > > then trace_kprobe_create() should fail with BAD_RETPROBE even if offset == 0 ?
> > >
> > > From what I understand. kprobe_on_func_entry() can return false if you pass
> > > in: "MOD:not_yet_loaded_module_func", but this is OK, because when the
> > > module is loaded, and the "not_yet_loaded_module_func" exists, the
> > > kretprobe will then be added.
> > >
> > > The strchr(symbol,":") check is to see if "MOD:" (or some other ":" command)
> > > is in the name, and we don't want it to fail if it is. Which is why we
> > > should have that commented.
> >
> > Agreed, this matches my understanding.
> >
> > But just in case... not sure I read this code correctly, but I think that
> > module_kallsyms_lookup_name("not_yet_loaded_module_func") should work even
> > without the "MOD:" prefix.
> >
> > IOW, kprobe_on_func_entry("not_yet_loaded_module_func") can fail, and then
> > later succeed if you load the module which provides this symbol.
> >
> > But even if I am right, I agree with the strchr(symbol,":") check.
>
> I see what you are saying. If "MOD" is not loaded yet, the
> kprobe_on_func_entry() should succeed.

No, that makes me more confused. kprobes_on_func_entry() returns true
only if it confirms the given address is on the function entry, because
it is used in the register_kretprobe() too.

OK, I will make a separate check which detects an error that the
module is loaded but the symbol does not exist.
(current code doesn't check the module is loaded or not)

That makes the code clearer.

Thank you,

--
Masami Hiramatsu <[email protected]>

2021-01-27 21:16:11

by Masami Hiramatsu

[permalink] [raw]
Subject: Re: [PATCH v3] tracing: precise log info for kretprobe addr err

On Tue, 26 Jan 2021 21:20:59 +0100
Oleg Nesterov <[email protected]> wrote:

> On 01/26, Masami Hiramatsu wrote:
> >
> > > >
> > > > IOW, the "offset != 0" check removed by this patch is obviously wrong, right?
> > > >
> >
> > No, not wrong. Even offset != 0, if the symbol exists in the kernel,
> > kprobe_on_func_entry() will check it.
>
> Yes, but unless I am totally confused... if kprobe_on_func_entry() returns false,
> then trace_kprobe_create() should fail with BAD_RETPROBE even if offset == 0 ?

Yes, if kprobe_on_func_entry() returns false, register_kretprobe() also returns
an error.

-----
int register_kretprobe(struct kretprobe *rp)
{
int ret = 0;
struct kretprobe_instance *inst;
int i;
void *addr;

if (!kprobe_on_func_entry(rp->kp.addr, rp->kp.symbol_name, rp->kp.offset))
return -EINVAL;

-----

Thank you,

--
Masami Hiramatsu <[email protected]>