2022-11-22 08:12:38

by Song Shuai

[permalink] [raw]
Subject: [PATCH] riscv/ftrace: fix ftrace_modify_call bug

With this commit (riscv: ftrace: Reduce the detour code size to half)
patched, ftrace bug occurred When hosting kprobe and function tracer
at the same function.

Obviously, the variable caller in ftrace_modify_call was assigned by
rec->ip with 4 offset failing the code replacing at function entry.
And the caller should be assigned by rec->ip directly to indicate
the function entry.

The following is the ftrace bug log.

```
[ 419.632855] 00000000f8776803: expected (ffe00297 1a4282e7) but got (1a8282e7 f0227179)
[ 419.633390] ------------[ ftrace bug ]------------
[ 419.633553] ftrace failed to modify
[ 419.633569] [<ffffffff802091cc>] kernel_read+0x0/0x52
[ 419.633863] actual: 97:02:e0:ff:e7:82:82:1a
[ 419.634087] Updating ftrace call site to call a different ftrace function
[ 419.634279] ftrace record flags: e0000002
[ 419.634487] (2) R
[ 419.634487] expected tramp: ffffffff800093cc
[ 419.634935] ------------[ cut here ]------------
```

Signed-off-by: Song Shuai <[email protected]>
---
arch/riscv/kernel/ftrace.c | 2 +-
1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/arch/riscv/kernel/ftrace.c b/arch/riscv/kernel/ftrace.c
index 8c77f236fc71..61b24d767e2e 100644
--- a/arch/riscv/kernel/ftrace.c
+++ b/arch/riscv/kernel/ftrace.c
@@ -132,7 +132,7 @@ int ftrace_modify_call(struct dyn_ftrace *rec, unsigned long old_addr,
unsigned long addr)
{
unsigned int call[2];
- unsigned long caller = rec->ip + 4;
+ unsigned long caller = rec->ip;
int ret;

make_call_t0(caller, old_addr, call);
--
2.20.1


2022-11-22 09:01:37

by Conor Dooley

[permalink] [raw]
Subject: Re: [PATCH] riscv/ftrace: fix ftrace_modify_call bug

On Tue, Nov 22, 2022 at 03:54:40PM +0800, Song Shuai wrote:
> With this commit (riscv: ftrace: Reduce the detour code size to half)

AFAICT the above patch has not been applied & this patch here should be
folded into the offending patch?
I've marked this one as "Not Applicable" in patchwork as a result, but
let me know if that is an incorrect assumption.

Thanks,
Conor.

> patched, ftrace bug occurred When hosting kprobe and function tracer
> at the same function.
>
> Obviously, the variable caller in ftrace_modify_call was assigned by
> rec->ip with 4 offset failing the code replacing at function entry.
> And the caller should be assigned by rec->ip directly to indicate
> the function entry.
>
> The following is the ftrace bug log.
>
> ```
> [ 419.632855] 00000000f8776803: expected (ffe00297 1a4282e7) but got (1a8282e7 f0227179)
> [ 419.633390] ------------[ ftrace bug ]------------
> [ 419.633553] ftrace failed to modify
> [ 419.633569] [<ffffffff802091cc>] kernel_read+0x0/0x52
> [ 419.633863] actual: 97:02:e0:ff:e7:82:82:1a
> [ 419.634087] Updating ftrace call site to call a different ftrace function
> [ 419.634279] ftrace record flags: e0000002
> [ 419.634487] (2) R
> [ 419.634487] expected tramp: ffffffff800093cc
> [ 419.634935] ------------[ cut here ]------------
> ```
>
> Signed-off-by: Song Shuai <[email protected]>
> ---
> arch/riscv/kernel/ftrace.c | 2 +-
> 1 file changed, 1 insertion(+), 1 deletion(-)
>
> diff --git a/arch/riscv/kernel/ftrace.c b/arch/riscv/kernel/ftrace.c
> index 8c77f236fc71..61b24d767e2e 100644
> --- a/arch/riscv/kernel/ftrace.c
> +++ b/arch/riscv/kernel/ftrace.c
> @@ -132,7 +132,7 @@ int ftrace_modify_call(struct dyn_ftrace *rec, unsigned long old_addr,
> unsigned long addr)
> {
> unsigned int call[2];
> - unsigned long caller = rec->ip + 4;
> + unsigned long caller = rec->ip;
> int ret;
>
> make_call_t0(caller, old_addr, call);
> --
> 2.20.1
>

2022-11-22 09:28:27

by Song Shuai

[permalink] [raw]
Subject: Re: [PATCH] riscv/ftrace: fix ftrace_modify_call bug

Guo Ren <[email protected]> 于2022年11月22日周二 08:57写道:
>
> On Tue, Nov 22, 2022 at 3:54 PM Song Shuai <[email protected]> wrote:
> >
> > With this commit (riscv: ftrace: Reduce the detour code size to half)
> > patched, ftrace bug occurred When hosting kprobe and function tracer
> > at the same function.
> >
> > Obviously, the variable caller in ftrace_modify_call was assigned by
> > rec->ip with 4 offset failing the code replacing at function entry.
> > And the caller should be assigned by rec->ip directly to indicate
> > the function entry.
> Thank you, it's my fault, but I think the problem is:
>
> Before (riscv: ftrace: Reduce the detour code size to half)
> 0: REG_S ra, -SZREG(sp)
> 4: auipc ra, ? <- We need "rec->ip + 4" here
> 8: jalr ?(ra)
> 12: REG_L ra, -SZREG(sp)
>
> After (riscv: ftrace: Reduce the detour code size to half)
> 0: auipc t0, ? <- We needn't "rec->ip + 4" anymore
> 4: jalr t0, ?(t0)
>
> I copied rec->ip + 4 blindly, then caused the bug. Right?
>
Yes, you're right.

Here's my simple test case for your convenience.
```
echo kernel_read > set_ftrace_filter
echo function > current_tracer
echo 'p:myp kernel_read' > kprobe_events
echo 1 > events/kprobes/myp/enable # ftrace bug
```
> >
> > The following is the ftrace bug log.
> >
> > ```
> > [ 419.632855] 00000000f8776803: expected (ffe00297 1a4282e7) but got (1a8282e7 f0227179)
> > [ 419.633390] ------------[ ftrace bug ]------------
> > [ 419.633553] ftrace failed to modify
> > [ 419.633569] [<ffffffff802091cc>] kernel_read+0x0/0x52
> > [ 419.633863] actual: 97:02:e0:ff:e7:82:82:1a
> > [ 419.634087] Updating ftrace call site to call a different ftrace function
> > [ 419.634279] ftrace record flags: e0000002
> > [ 419.634487] (2) R
> > [ 419.634487] expected tramp: ffffffff800093cc
> > [ 419.634935] ------------[ cut here ]------------
> > ```
> >
> > Signed-off-by: Song Shuai <[email protected]>
> > ---
> > arch/riscv/kernel/ftrace.c | 2 +-
> > 1 file changed, 1 insertion(+), 1 deletion(-)
> >
> > diff --git a/arch/riscv/kernel/ftrace.c b/arch/riscv/kernel/ftrace.c
> > index 8c77f236fc71..61b24d767e2e 100644
> > --- a/arch/riscv/kernel/ftrace.c
> > +++ b/arch/riscv/kernel/ftrace.c
> > @@ -132,7 +132,7 @@ int ftrace_modify_call(struct dyn_ftrace *rec, unsigned long old_addr,
> > unsigned long addr)
> > {
> > unsigned int call[2];
> > - unsigned long caller = rec->ip + 4;
> > + unsigned long caller = rec->ip;
> > int ret;
> >
> > make_call_t0(caller, old_addr, call);
> > --
> > 2.20.1
> >
>
>
> --
> Best Regards
> Guo Ren
Thanks,
Song

2022-11-22 09:38:12

by Guo Ren

[permalink] [raw]
Subject: Re: [PATCH] riscv/ftrace: fix ftrace_modify_call bug

On Tue, Nov 22, 2022 at 3:54 PM Song Shuai <[email protected]> wrote:
>
> With this commit (riscv: ftrace: Reduce the detour code size to half)
> patched, ftrace bug occurred When hosting kprobe and function tracer
> at the same function.
>
> Obviously, the variable caller in ftrace_modify_call was assigned by
> rec->ip with 4 offset failing the code replacing at function entry.
> And the caller should be assigned by rec->ip directly to indicate
> the function entry.
Thank you, it's my fault, but I think the problem is:

Before (riscv: ftrace: Reduce the detour code size to half)
0: REG_S ra, -SZREG(sp)
4: auipc ra, ? <- We need "rec->ip + 4" here
8: jalr ?(ra)
12: REG_L ra, -SZREG(sp)

After (riscv: ftrace: Reduce the detour code size to half)
0: auipc t0, ? <- We needn't "rec->ip + 4" anymore
4: jalr t0, ?(t0)

I copied rec->ip + 4 blindly, then caused the bug. Right?

>
> The following is the ftrace bug log.
>
> ```
> [ 419.632855] 00000000f8776803: expected (ffe00297 1a4282e7) but got (1a8282e7 f0227179)
> [ 419.633390] ------------[ ftrace bug ]------------
> [ 419.633553] ftrace failed to modify
> [ 419.633569] [<ffffffff802091cc>] kernel_read+0x0/0x52
> [ 419.633863] actual: 97:02:e0:ff:e7:82:82:1a
> [ 419.634087] Updating ftrace call site to call a different ftrace function
> [ 419.634279] ftrace record flags: e0000002
> [ 419.634487] (2) R
> [ 419.634487] expected tramp: ffffffff800093cc
> [ 419.634935] ------------[ cut here ]------------
> ```
>
> Signed-off-by: Song Shuai <[email protected]>
> ---
> arch/riscv/kernel/ftrace.c | 2 +-
> 1 file changed, 1 insertion(+), 1 deletion(-)
>
> diff --git a/arch/riscv/kernel/ftrace.c b/arch/riscv/kernel/ftrace.c
> index 8c77f236fc71..61b24d767e2e 100644
> --- a/arch/riscv/kernel/ftrace.c
> +++ b/arch/riscv/kernel/ftrace.c
> @@ -132,7 +132,7 @@ int ftrace_modify_call(struct dyn_ftrace *rec, unsigned long old_addr,
> unsigned long addr)
> {
> unsigned int call[2];
> - unsigned long caller = rec->ip + 4;
> + unsigned long caller = rec->ip;
> int ret;
>
> make_call_t0(caller, old_addr, call);
> --
> 2.20.1
>


--
Best Regards
Guo Ren

2022-11-22 10:12:02

by Song Shuai

[permalink] [raw]
Subject: Re: [PATCH] riscv/ftrace: fix ftrace_modify_call bug

Guo Ren <[email protected]> 于2022年11月22日周二 09:29写道:
>
>
>
> On Tue, Nov 22, 2022 at 5:11 PM Song Shuai <[email protected]> wrote:
>>
>> Guo Ren <[email protected]> 于2022年11月22日周二 08:57写道:
>> >
>> > On Tue, Nov 22, 2022 at 3:54 PM Song Shuai <[email protected]> wrote:
>> > >
>> > > With this commit (riscv: ftrace: Reduce the detour code size to half)
>> > > patched, ftrace bug occurred When hosting kprobe and function tracer
>> > > at the same function.
>> > >
>> > > Obviously, the variable caller in ftrace_modify_call was assigned by
>> > > rec->ip with 4 offset failing the code replacing at function entry.
>> > > And the caller should be assigned by rec->ip directly to indicate
>> > > the function entry.
>> > Thank you, it's my fault, but I think the problem is:
>> >
>> > Before (riscv: ftrace: Reduce the detour code size to half)
>> > 0: REG_S ra, -SZREG(sp)
>> > 4: auipc ra, ? <- We need "rec->ip + 4" here
>> > 8: jalr ?(ra)
>> > 12: REG_L ra, -SZREG(sp)
>> >
>> > After (riscv: ftrace: Reduce the detour code size to half)
>> > 0: auipc t0, ? <- We needn't "rec->ip + 4" anymore
>> > 4: jalr t0, ?(t0)
>> >
>> > I copied rec->ip + 4 blindly, then caused the bug. Right?
>> >
>> Yes, you're right.
>>
>> Here's my simple test case for your convenience.
>> ```
>> echo kernel_read > set_ftrace_filter
>> echo function > current_tracer
>> echo 'p:myp kernel_read' > kprobe_events
>> echo 1 > events/kprobes/myp/enable # ftrace bug
>
>
> Thx, I would fold the patch into (riscv: ftrace: Reduce the detour code size to half). And add Co-developed-by: Song Shuai <[email protected]> tag on that.
>
> I would send the v3 series involving your patches.
>
That's an honor for me.

Thanks,
Song
>>
>> ```
>> > >
>> > > The following is the ftrace bug log.
>> > >
>> > > ```
>> > > [ 419.632855] 00000000f8776803: expected (ffe00297 1a4282e7) but got (1a8282e7 f0227179)
>> > > [ 419.633390] ------------[ ftrace bug ]------------
>> > > [ 419.633553] ftrace failed to modify
>> > > [ 419.633569] [<ffffffff802091cc>] kernel_read+0x0/0x52
>> > > [ 419.633863] actual: 97:02:e0:ff:e7:82:82:1a
>> > > [ 419.634087] Updating ftrace call site to call a different ftrace function
>> > > [ 419.634279] ftrace record flags: e0000002
>> > > [ 419.634487] (2) R
>> > > [ 419.634487] expected tramp: ffffffff800093cc
>> > > [ 419.634935] ------------[ cut here ]------------
>> > > ```
>> > >
>> > > Signed-off-by: Song Shuai <[email protected]>
>> > > ---
>> > > arch/riscv/kernel/ftrace.c | 2 +-
>> > > 1 file changed, 1 insertion(+), 1 deletion(-)
>> > >
>> > > diff --git a/arch/riscv/kernel/ftrace.c b/arch/riscv/kernel/ftrace.c
>> > > index 8c77f236fc71..61b24d767e2e 100644
>> > > --- a/arch/riscv/kernel/ftrace.c
>> > > +++ b/arch/riscv/kernel/ftrace.c
>> > > @@ -132,7 +132,7 @@ int ftrace_modify_call(struct dyn_ftrace *rec, unsigned long old_addr,
>> > > unsigned long addr)
>> > > {
>> > > unsigned int call[2];
>> > > - unsigned long caller = rec->ip + 4;
>> > > + unsigned long caller = rec->ip;
>> > > int ret;
>> > >
>> > > make_call_t0(caller, old_addr, call);
>> > > --
>> > > 2.20.1
>> > >
>> >
>> >
>> > --
>> > Best Regards
>> > Guo Ren
>> Thanks,
>> Song
>
>
>
> --
> Best Regards
> Guo Ren

2022-11-22 10:35:51

by Song Shuai

[permalink] [raw]
Subject: Re: [PATCH] riscv/ftrace: fix ftrace_modify_call bug

Conor Dooley <[email protected]> 于2022年11月22日周二 08:57写道:
>
> On Tue, Nov 22, 2022 at 03:54:40PM +0800, Song Shuai wrote:
> > With this commit (riscv: ftrace: Reduce the detour code size to half)
>
> AFAICT the above patch has not been applied & this patch here should be
> folded into the offending patch?
> I've marked this one as "Not Applicable" in patchwork as a result, but
> let me know if that is an incorrect assumption.
>
> Thanks,
> Conor.
>
Hi, Conor:

Sorry to disturb you with this patch without against the merged commit list,

This patch actually is created for fixing (riscv: ftrace: Reduce the
detour code size to half)
which has not been merged yet.

As Guo replied, he will fold it in the target patch. You can ignore
this one. Sorry again.

BTW, for dispelling your confusion about my email name.
Actually, it was misspelled when registering, but I keep it for daily use.
So you can send it without concern. :P

-- Song


Sorry for bothering you with the
> > patched, ftrace bug occurred When hosting kprobe and function tracer
> > at the same function.
> >
> > Obviously, the variable caller in ftrace_modify_call was assigned by
> > rec->ip with 4 offset failing the code replacing at function entry.
> > And the caller should be assigned by rec->ip directly to indicate
> > the function entry.
> >
> > The following is the ftrace bug log.
> >
> > ```
> > [ 419.632855] 00000000f8776803: expected (ffe00297 1a4282e7) but got (1a8282e7 f0227179)
> > [ 419.633390] ------------[ ftrace bug ]------------
> > [ 419.633553] ftrace failed to modify
> > [ 419.633569] [<ffffffff802091cc>] kernel_read+0x0/0x52
> > [ 419.633863] actual: 97:02:e0:ff:e7:82:82:1a
> > [ 419.634087] Updating ftrace call site to call a different ftrace function
> > [ 419.634279] ftrace record flags: e0000002
> > [ 419.634487] (2) R
> > [ 419.634487] expected tramp: ffffffff800093cc
> > [ 419.634935] ------------[ cut here ]------------
> > ```
> >
> > Signed-off-by: Song Shuai <[email protected]>
> > ---
> > arch/riscv/kernel/ftrace.c | 2 +-
> > 1 file changed, 1 insertion(+), 1 deletion(-)
> >
> > diff --git a/arch/riscv/kernel/ftrace.c b/arch/riscv/kernel/ftrace.c
> > index 8c77f236fc71..61b24d767e2e 100644
> > --- a/arch/riscv/kernel/ftrace.c
> > +++ b/arch/riscv/kernel/ftrace.c
> > @@ -132,7 +132,7 @@ int ftrace_modify_call(struct dyn_ftrace *rec, unsigned long old_addr,
> > unsigned long addr)
> > {
> > unsigned int call[2];
> > - unsigned long caller = rec->ip + 4;
> > + unsigned long caller = rec->ip;
> > int ret;
> >
> > make_call_t0(caller, old_addr, call);
> > --
> > 2.20.1
> >