printk() format %pS wrong symbol

printk() format %pS wrong symbol

[William Tambe]

[-- Attachment #1.1: Type: text/plain, Size: 586 bytes --]

I am seeing an issue in our Linux port where printk() format %pS will print
a symbol as:
kernel_init+0x120/0x120
where the offset within the function 0x120, is the same as the function
size 0x120; in fact, the largest offset within the function should be 0x11f.

When printing above symbol+offset in gdb, the correct symbol is
displayed as follow:

(gdb) p (void*)(kernel_init+0x120)
$1 = (void *) 0x589a28 <ret_for_syscall>

What could be the cause of printk() format %pS printing an incorrect symbol.

Where can I find in the Linux source code, the function handling the format
%pS ?

[-- Attachment #1.2: Type: text/html, Size: 803 bytes --]

[-- Attachment #2: Type: text/plain, Size: 170 bytes --]

_______________________________________________
Kernelnewbies mailing list
Kernelnewbies@kernelnewbies.org
https://lists.kernelnewbies.org/mailman/listinfo/kernelnewbies

Re: printk() format %pS wrong symbol

[Valentin Vidić]

On Sat, Jul 04, 2020 at 06:11:19AM -0400, William Tambe wrote:
> I am seeing an issue in our Linux port where printk() format %pS will print
> a symbol as:
> kernel_init+0x120/0x120
> where the offset within the function 0x120, is the same as the function
> size 0x120; in fact, the largest offset within the function should be 0x11f.
> 
> When printing above symbol+offset in gdb, the correct symbol is
> displayed as follow:
> 
> (gdb) p (void*)(kernel_init+0x120)
> $1 = (void *) 0x589a28 <ret_for_syscall>
> 
> What could be the cause of printk() format %pS printing an incorrect symbol.
> 
> Where can I find in the Linux source code, the function handling the format
> %pS ?

Check lib/vsprintf.c

-- 
Valentin

_______________________________________________
Kernelnewbies mailing list
Kernelnewbies@kernelnewbies.org
https://lists.kernelnewbies.org/mailman/listinfo/kernelnewbies

Re: printk() format %pS wrong symbol

[William Tambe]

[-- Attachment #1.1: Type: text/plain, Size: 1187 bytes --]

On Sat, Jul 4, 2020 at 6:29 AM Valentin Vidić <vvidic@valentin-vidic.from.hr>
wrote:

> On Sat, Jul 04, 2020 at 06:11:19AM -0400, William Tambe wrote:
> > I am seeing an issue in our Linux port where printk() format %pS will
> print
> > a symbol as:
> > kernel_init+0x120/0x120
> > where the offset within the function 0x120, is the same as the function
> > size 0x120; in fact, the largest offset within the function should be
> 0x11f.
> >
> > When printing above symbol+offset in gdb, the correct symbol is
> > displayed as follow:
> >
> > (gdb) p (void*)(kernel_init+0x120)
> > $1 = (void *) 0x589a28 <ret_for_syscall>
> >
> > What could be the cause of printk() format %pS printing an incorrect
> symbol.
> >
> > Where can I find in the Linux source code, the function handling the
> format
> > %pS ?
>
> Check lib/vsprintf.c
>

How or which function within that file translates an address to the string
symbol+offset for the format %pS ?


>
> --
> Valentin
>
> _______________________________________________
> Kernelnewbies mailing list
> Kernelnewbies@kernelnewbies.org
> https://lists.kernelnewbies.org/mailman/listinfo/kernelnewbies
>

[-- Attachment #1.2: Type: text/html, Size: 1791 bytes --]

[-- Attachment #2: Type: text/plain, Size: 170 bytes --]

_______________________________________________
Kernelnewbies mailing list
Kernelnewbies@kernelnewbies.org
https://lists.kernelnewbies.org/mailman/listinfo/kernelnewbies

Re: printk() format %pS wrong symbol

[Valentin Vidić]

On Sat, Jul 04, 2020 at 12:04:59PM -0400, William Tambe wrote:
> How or which function within that file translates an address to the string
> symbol+offset for the format %pS ?

%pS seems to end up in here:

static int __sprint_symbol(char *buffer, unsigned long address,
                           int symbol_offset, int add_offset)
{
        char *modname;
        const char *name;
        unsigned long offset, size;
        int len;

        address += symbol_offset;
        name = kallsyms_lookup(address, &size, &offset, &modname, buffer);
        if (!name)
                return sprintf(buffer, "0x%lx", address - symbol_offset);

        if (name != buffer)
                strcpy(buffer, name);
        len = strlen(buffer);
        offset -= symbol_offset;

        if (add_offset)
                len += sprintf(buffer + len, "+%#lx/%#lx", offset, size);

        if (modname)
                len += sprintf(buffer + len, " [%s]", modname);

        return len;
}

-- 
Valentin

_______________________________________________
Kernelnewbies mailing list
Kernelnewbies@kernelnewbies.org
https://lists.kernelnewbies.org/mailman/listinfo/kernelnewbies

Re: printk() format %pS wrong symbol

[William Tambe]

On Sat, Jul 4, 2020 at 1:15 PM Valentin Vidić
<vvidic@valentin-vidic.from.hr> wrote:
>
> On Sat, Jul 04, 2020 at 12:04:59PM -0400, William Tambe wrote:
> > How or which function within that file translates an address to the string
> > symbol+offset for the format %pS ?
>
> %pS seems to end up in here:

Thanks,
the issue I am having is due to sprint_backtrace() calling
__sprint_symbol() with its argument symbol_offset == -1.
Despite the comment above its definition, it is hard to understand why
sprint_backtrace() calls __sprint_symbol() that way; in our port it
results in printing incorrect symbols.
As a workaround, we have made sprint_backtrace() to be the same as
sprint_symbol().

>
> static int __sprint_symbol(char *buffer, unsigned long address,
>                            int symbol_offset, int add_offset)
> {
>         char *modname;
>         const char *name;
>         unsigned long offset, size;
>         int len;
>
>         address += symbol_offset;
>         name = kallsyms_lookup(address, &size, &offset, &modname, buffer);
>         if (!name)
>                 return sprintf(buffer, "0x%lx", address - symbol_offset);
>
>         if (name != buffer)
>                 strcpy(buffer, name);
>         len = strlen(buffer);
>         offset -= symbol_offset;
>
>         if (add_offset)
>                 len += sprintf(buffer + len, "+%#lx/%#lx", offset, size);
>
>         if (modname)
>                 len += sprintf(buffer + len, " [%s]", modname);
>
>         return len;
> }
>
> --
> Valentin
>
> _______________________________________________
> Kernelnewbies mailing list
> Kernelnewbies@kernelnewbies.org
> https://lists.kernelnewbies.org/mailman/listinfo/kernelnewbies

_______________________________________________
Kernelnewbies mailing list
Kernelnewbies@kernelnewbies.org
https://lists.kernelnewbies.org/mailman/listinfo/kernelnewbies

Re: printk() format %pS wrong symbol

[Valentin Vidić]

On Mon, Jul 06, 2020 at 06:06:42PM -0400, William Tambe wrote:
> the issue I am having is due to sprint_backtrace() calling
> __sprint_symbol() with its argument symbol_offset == -1.
> Despite the comment above its definition, it is hard to understand why
> sprint_backtrace() calls __sprint_symbol() that way; in our port it
> results in printing incorrect symbols.
> As a workaround, we have made sprint_backtrace() to be the same as
> sprint_symbol().

From what I understand print_backtrace() tries to handle the case when
call is the last instruction in a function:

func1: ...
       ...
       ...
       call noret_func3()
func2: ...
       ...
       ...

Return value on the stack points to the next instruction after the call. 
But in this case a new function already starts on that address so they
add -1 to make the address point back to func1.

Not sure what goes wrong in your case, could you share an example and
more info on the port?

-- 
Valentin

_______________________________________________
Kernelnewbies mailing list
Kernelnewbies@kernelnewbies.org
https://lists.kernelnewbies.org/mailman/listinfo/kernelnewbies

Re: printk() format %pS wrong symbol

[Valentin Vidić]

On Tue, Jul 07, 2020 at 08:39:27PM +0200, Valentin Vidić wrote:
> From what I understand print_backtrace() tries to handle the case when
> call is the last instruction in a function:
> 
> func1: ...
>        ...
>        ...
>        call noret_func3()
> func2: ...
>        ...
>        ...
> 
> Return value on the stack points to the next instruction after the call. 
> But in this case a new function already starts on that address so they
> add -1 to make the address point back to func1.
> 
> Not sure what goes wrong in your case, could you share an example and
> more info on the port?

This could go wrong if the return address on the stack points to the
first instruction of ret_for_syscall:

kernel_init:     ...
                 ...
                 ...
ret_for_syscall: ... <-- return address
                 ...
                 ...

In this case kernel_init would be printed instead. Not sure how this
address would end up on the stack unless ret_for_syscall is placed
directly on the stack for some reason?

-- 
Valentin

_______________________________________________
Kernelnewbies mailing list
Kernelnewbies@kernelnewbies.org
https://lists.kernelnewbies.org/mailman/listinfo/kernelnewbies