Debugging variable arguments functions (stdarg)

Debugging variable arguments functions (stdarg)

[G]

Hello,

How can I look at the values of "..." in a function which can
take a variable number of arguments (i.e. uses va_start(),
va_end() etc.) in gdb?

I have a core dump of a program which I try to analyze in gdb:

debian:~ $ gdb /usr/local/bin/teamlogs core-teamlogs
GNU gdb 6.8-debian
[snip]
Loaded symbols for /lib/libnss_files.so.2
Core was generated by `/usr/local/bin/teamlogs'.
Program terminated with signal 11, Segmentation fault.
[New process 31754]
#0  0x00002ac4de25f030 in strlen () from /lib/libc.so.6
(gdb) bt
#0  0x00002ac4de25f030 in strlen () from /lib/libc.so.6
#1  0x00002ac4de22bcb1 in vfprintf () from /lib/libc.so.6
#2  0x00002ac4de2affbe in __vsyslog_chk () from /lib/libc.so.6
#3  0x00000000004062cb in WriteLog (facility=128, level=4,
    fmt=0x406bf0 "MysqlWrapper(): Query failed: \"%s\": %s")
    at src/teamlogs.cpp:119
#4  0x00000000004041e2 in MysqlWrapper (
    query=0x7c8e80 "INSERT INTO results.matches (time, team, won)
VALUES (1257353711, 'Juniors1', 0)")
    at src/teamlogs.cpp:563
[snip]
(gdb) frame 3
#3  0x00000000004062cb in WriteLog (facility=128, level=4,
    fmt=0x406bf0 "MysqlWrapper(): Query failed: \"%s\": %s")
    at src/teamlogs.cpp:119
119     vsyslog(facility, level, fmt, ap);
(gdb) print facility
$2 = 128
(gdb) print level
$3 = 4
(gdb) print fmt
$4 = 0x406bf0 "MysqlWrapper(): Query failed: \"%s\": %s"
(gdb) print ap
$5 = {{gp_offset = 40, fp_offset = 48, overflow_arg_area = 0x7fffcd89ce80,
    reg_save_area = 0x7fffcd89cdb0}}
(gdb) frame 2
#2  0x00002ac4de2affbe in __vsyslog_chk () from /lib/libc.so.6
(gdb) print priority
No symbol "priority" in current context.
(gdb) print flag
No symbol "flag" in current context.
(gdb) print format
No symbol "format" in current context.
(gdb) print ap
No symbol "ap" in current context.

I need to look at the values in "..." to see what was being
passed on in my call to vsyslog(). How do I do that? I haven't
discovered how to despite googling and reading the gdb manual.

The source of the function WriteLog looks like this:

void
WriteLog(int facility, int level, const char *fmt, ...)
{
        va_list ap;
        va_start(ap, fmt);
        vsyslog(facility, level, fmt, ap);
        va_end(ap);
        return;
}

and it is called like this:
        WriteLog(LOG_LOCAL0, LOG_WARNING, "MysqlWrapper(): Query failed: "
                \"%s\": %s", query, mysql_error(sql_handle));

openlog() has been called earlier, like this:
        openlog(argv[0], LOG_CONS | LOG_ODELAY | LOG_PID, LOG_LOCAL0);

So I really need to look at all arguments to WriteLog() to see if
mysql_error() have returned something weird to cause strlen() to
misbehave. My fmt argument is good, as can be seen in the gdb
output.

Unfortunately I haven't found a way to reproduce the crash (it
happens very rarely), which is why I really need to try and track
the bug down using this core dump. To further complicate things,
it's taken from a production machine with all the difficulties
that can bring (no debug libraries etc.).

(Apologies if this is the wrong place to ask, and if the formatting
gets screwed up.)

Re: Debugging variable arguments functions (stdarg)

[Michael Snyder]

G wrote:
> Hello,
> 
> How can I look at the values of "..." in a function which can
> take a variable number of arguments (i.e. uses va_start(),
> va_end() etc.) in gdb?

I don't think you can, other than at low level (regs and stack).

> 
> I have a core dump of a program which I try to analyze in gdb:
> 
> debian:~ $ gdb /usr/local/bin/teamlogs core-teamlogs
> GNU gdb 6.8-debian
> [snip]
> Loaded symbols for /lib/libnss_files.so.2
> Core was generated by `/usr/local/bin/teamlogs'.
> Program terminated with signal 11, Segmentation fault.
> [New process 31754]
> #0  0x00002ac4de25f030 in strlen () from /lib/libc.so.6
> (gdb) bt
> #0  0x00002ac4de25f030 in strlen () from /lib/libc.so.6
> #1  0x00002ac4de22bcb1 in vfprintf () from /lib/libc.so.6
> #2  0x00002ac4de2affbe in __vsyslog_chk () from /lib/libc.so.6
> #3  0x00000000004062cb in WriteLog (facility=128, level=4,
>     fmt=0x406bf0 "MysqlWrapper(): Query failed: \"%s\": %s")
>     at src/teamlogs.cpp:119
> #4  0x00000000004041e2 in MysqlWrapper (
>     query=0x7c8e80 "INSERT INTO results.matches (time, team, won)
> VALUES (1257353711, 'Juniors1', 0)")
>     at src/teamlogs.cpp:563
> [snip]
> (gdb) frame 3
> #3  0x00000000004062cb in WriteLog (facility=128, level=4,
>     fmt=0x406bf0 "MysqlWrapper(): Query failed: \"%s\": %s")
>     at src/teamlogs.cpp:119
> 119     vsyslog(facility, level, fmt, ap);
> (gdb) print facility
> $2 = 128
> (gdb) print level
> $3 = 4
> (gdb) print fmt
> $4 = 0x406bf0 "MysqlWrapper(): Query failed: \"%s\": %s"
> (gdb) print ap
> $5 = {{gp_offset = 40, fp_offset = 48, overflow_arg_area = 0x7fffcd89ce80,
>     reg_save_area = 0x7fffcd89cdb0}}
> (gdb) frame 2
> #2  0x00002ac4de2affbe in __vsyslog_chk () from /lib/libc.so.6
> (gdb) print priority
> No symbol "priority" in current context.
> (gdb) print flag
> No symbol "flag" in current context.
> (gdb) print format
> No symbol "format" in current context.
> (gdb) print ap
> No symbol "ap" in current context.
> 
> I need to look at the values in "..." to see what was being
> passed on in my call to vsyslog(). How do I do that? I haven't
> discovered how to despite googling and reading the gdb manual.
> 
> The source of the function WriteLog looks like this:
> 
> void
> WriteLog(int facility, int level, const char *fmt, ...)
> {
>         va_list ap;
>         va_start(ap, fmt);
>         vsyslog(facility, level, fmt, ap);
>         va_end(ap);
>         return;
> }
> 
> and it is called like this:
>         WriteLog(LOG_LOCAL0, LOG_WARNING, "MysqlWrapper(): Query failed: "
>                 \"%s\": %s", query, mysql_error(sql_handle));
> 
> openlog() has been called earlier, like this:
>         openlog(argv[0], LOG_CONS | LOG_ODELAY | LOG_PID, LOG_LOCAL0);
> 
> So I really need to look at all arguments to WriteLog() to see if
> mysql_error() have returned something weird to cause strlen() to
> misbehave. My fmt argument is good, as can be seen in the gdb
> output.
> 
> Unfortunately I haven't found a way to reproduce the crash (it
> happens very rarely), which is why I really need to try and track
> the bug down using this core dump. To further complicate things,
> it's taken from a production machine with all the difficulties
> that can bring (no debug libraries etc.).
> 
> (Apologies if this is the wrong place to ask, and if the formatting
> gets screwed up.)

Re: Debugging variable arguments functions (stdarg)

[Petr Hluzín]

On 15 July 2010 17:47, G <tjmadwja@gmail.com> wrote:
> Hello,
>
> How can I look at the values of "..." in a function which can
> take a variable number of arguments (i.e. uses va_start(),
> va_end() etc.) in gdb?

There is no nice way to do that. GCC does not record the actual types
used in a call site of a variadic function, e.g. what is on the
call-site of WriteLog(int,int,char*,...) in MysqlWrapper.

Workaround A:
Alter source code of the caller to:
const char * msg = mysql_error(sql_handle)
WriteLog(stuff1,stuff1,stuff3, query, msg);
and hope the compiler does not optimize the local variable.

Workaround B:
Get value of stack pointer (RSP?) of frame MysqlWrapper() and dump raw
memory around the address. You should see these values somewhere
around:
0x00000000004041e2 (return address in MysqlWrapper)
0x406bf0 (the third argument to WriteLog)
Between these two values should be the values of 3rd and 4th argument.
(You have to cast them to char*.)

-- 
Petr Hluzin

Re: Debugging variable arguments functions (stdarg)

[Jan Kratochvil]

On Fri, 16 Jul 2010 20:57:57 +0200, Petr Hluzín wrote:
> Workaround B:
> Get value of stack pointer (RSP?) of frame MysqlWrapper() and dump raw
> memory around the address. You should see these values somewhere
> around:
> 0x00000000004041e2 (return address in MysqlWrapper)
> 0x406bf0 (the third argument to WriteLog)
> Between these two values should be the values of 3rd and 4th argument.

This is not so simple on x86_64, it passes even (first few) stdarg parameters
in registers.
	http://www.x86-64.org/documentation/abi.pdf


Regards,
Jan

Re: Debugging variable arguments functions (stdarg)

[Petr Hluzín]

On 16 July 2010 21:12, Jan Kratochvil <jan.kratochvil@redhat.com> wrote:
> On Fri, 16 Jul 2010 20:57:57 +0200, Petr Hluzín wrote:
>> Workaround B:
>> Get value of stack pointer (RSP?) of frame MysqlWrapper() and dump raw
>> memory around the address. You should see these values somewhere
>> around:
>> 0x00000000004041e2 (return address in MysqlWrapper)
>> 0x406bf0 (the third argument to WriteLog)
>> Between these two values should be the values of 3rd and 4th argument.
>
> This is not so simple on x86_64, it passes even (first few) stdarg parameters
> in registers.
>        http://www.x86-64.org/documentation/abi.pdf

Nice reading.
I suppose it is documented section "3.5.7 Variable Argument Lists".
Unfortunately I was not able to find any specific wording.
But it makes sense. You are probably right.

It should be possible by reading the document to determine if the two
arguments go to stack or remained in registers. I failed to figure
that out.

Ok, this means that G has to examine stack memory of all frames - infeasible.

-- 
Petr Hluzin

Re: Debugging variable arguments functions (stdarg)

[G]

On Sun, Jul 18, 2010 at 9:27 PM, Petr Hluzín <petr.hluzin@gmail.com> wrote:
> On 16 July 2010 21:12, Jan Kratochvil <jan.kratochvil@redhat.com> wrote:
>> On Fri, 16 Jul 2010 20:57:57 +0200, Petr Hluzín wrote:
>>> Workaround B:
>>> Get value of stack pointer (RSP?) of frame MysqlWrapper() and dump raw
>>> memory around the address. You should see these values somewhere
>>> around:
>>> 0x00000000004041e2 (return address in MysqlWrapper)
>>> 0x406bf0 (the third argument to WriteLog)
>>> Between these two values should be the values of 3rd and 4th argument.
>>
>> This is not so simple on x86_64, it passes even (first few) stdarg parameters
>> in registers.
>>        http://www.x86-64.org/documentation/abi.pdf
>
> Nice reading.
> I suppose it is documented section "3.5.7 Variable Argument Lists".
> Unfortunately I was not able to find any specific wording.
> But it makes sense. You are probably right.
>
> It should be possible by reading the document to determine if the two
> arguments go to stack or remained in registers. I failed to figure
> that out.
>
> Ok, this means that G has to examine stack memory of all frames - infeasible.

First, thanks for the replies. I've actually found a solution which
lets me look at the arguments passed in the "..." list without too
much effort, and thought I'd share it. A Google search for "gdb
variadic" instead of "gdb variable arguments" turned up a blog post at
http://www.moythreads.com/wordpress/2008/05/ which contained an almost
complete solution.

In case that blog post disappears, and for archiving reasons, I'm
including a very short writeup/example here. First some simple code:


#include <stdarg.h>
#include <stdio.h>

void myfunc(const char *fmt, ...)
{
        va_list args;
        va_start(args, fmt);
        vprintf(fmt, args);
        va_end(args);
        return;
}

int main(int argc, char *argv[])
{
        myfunc("test 1: %s %s\n", "one", "two");
        myfunc("test 2: %s %d %c\n", "apple", 222, 'y');
        return 0;
}


A short debugging session with some comments so that some gdb novice
like myself might get an idea of what is happening (I hope my comments
are correct...):


$ gdb testprog
GNU gdb (GDB) 7.1-debian
[snip]
Reading symbols from /home/user/testprog...done.
(gdb) break myfunc
Breakpoint 1 at 0x400552: file testprog.c, line 7.
(gdb) run
Starting program: /home/user/testprog

Breakpoint 1, myfunc (fmt=0x4006f4 "test 1: %s %s\n") at testprog.c:7
7               va_start(args, fmt);
(gdb) # initialize args to hold correct values:
(gdb) step
8               vprintf(fmt, args);
(gdb) # print first argument in "..." list which we know is a char*:
(gdb) p *(char **)(((char *)args[0].reg_save_area)+args[0].gp_offset)
$1 = 0x4006f0 "one"
(gdb) # print first byte in argument in "..." list which we know is a char*:
(gdb) p **(char **)(((char *)args[0].reg_save_area)+args[0].gp_offset)
$2 = 111 'o'
(gdb) # print first byte in second argument in "..." list which is also a char*
(gdb) # (we use +8 since this is a 64-bit machine):
(gdb) p **(char **)(((char *)args[0].reg_save_area)+args[0].gp_offset+8)
$3 = 116 't'
(gdb) # print second argument in "..." list:
(gdb) p *(char **)(((char *)args[0].reg_save_area)+args[0].gp_offset+8)
$4 = 0x4006ec "two"
(gdb) # look at what lies beyond:
(gdb) p *(long *)(((char *)args[0].reg_save_area)+args[0].gp_offset+16)
$5 = 0
(gdb) # step program to execute the vprintf() call:
(gdb) next
test 1: one two
11      }
(gdb) # return to main():
(gdb) next
main (argc=1, argv=0x7fffffffeb58) at testprog.c:16
16              myfunc("test 2: %s %d %c\n", "apple", 222, 'y');
(gdb) # execute call to myfunc() a second time with different arguments:
(gdb) next

Breakpoint 1, myfunc (fmt=0x400715 "test 2: %s %s %s\n") at testprog.c:7
7               va_start(args, fmt);
(gdb) # initialize args to hold correct values:
(gdb) step
8               vprintf(fmt, args);
(gdb) # print first argument in "..." list which again we know is a char*:
(gdb) p *(char **)(((char *)args[0].reg_save_area)+args[0].gp_offset)
$6 = 0x40070f "apple"
(gdb) # print second argument in "..." list which is an int:
(gdb) p *(int *)(((char *)args[0].reg_save_area)+args[0].gp_offset+8)
$7 = 222
(gdb) # print third argument in "..." list which is a char:
(gdb) p *(char *)(((char *)args[0].reg_save_area)+args[0].gp_offset+16)
$8 = 121 'y'
(gdb) # look at what lies beyond:
(gdb) p *(long *)(((char *)args[0].reg_save_area)+args[0].gp_offset+24)
$9 = 1
(gdb) # OK, so the 0 at the end of the last "..." list seems like just a
(gdb) # coincidence, not an intentional NULL value.
(gdb) # let program finish:
(gdb) cont
Continuing.
test 2: apple 222 y

Program exited normally.
(gdb)