(gdb) break *0x972

Today my URxvt terminals are stuck. All of them, at the same time.

I know they're just clients (urxvtc) for the main daemon (urxvtd) so I'm not surprised that all of them are stuck, but I don't know why.

URxvt standalone version (urxvt) works well, so I can start inverstigating (by the way, in my i3 environment I mainly use URxvt client (bound to Mod+Shift+Enter), because it's faster to start, but I have a backup binding Mod+Ctrl+Enter for the standalone version, just in case things like that happen :).

Then, with the right tool, it's easy to find the problem:

 $ strace -p $(pidof urxvtd)
 strace: Process 1518 attached
 wait4(20063, 
 ^C
strace: Process 1518 detached
 <detached ...>

So PID 20063 is the problem, urxvtd is waiting for it forever. But who is that?

$ ps aux | grep 20063 
kevin    20063  0.0  0.0  13628  2920 ?        S    10:45   0:00 sh -c echo -en toto\.ods | xsel -i -b -p

Alright, it's my clipboard management script that doesn't return ...

$ kill -9 20063

Bye bye clipboard, and hello again my terminals :-)

At the moment, I'm playing with thread checkpoint-restart, implemented somehow like setjmp/longjmp :

REGS = "rax","rbx","rcx","rdx","rsi","rdi","rbp","rsp","r8","r9", ...

def checkpoint(): 
  reg_values = map(gdb.newest_frame().read_register, REGS))
  return reg_values

def restart(reg_values):
  for reg, val in zip(REGS, reg_values):
    gdb.execute("set ${} = {}".format(reg, val), to_string=True)

This a naive implementation, but with a few more tricks, it does work (what I have to do is save/restore rip and rbp for the frame above, I'm not sure why).

However this code works for Python 2, but not for Python 3. Can you find why?

I'll let you guess, the answer is written below in white:

The map function in Python 3 returns a generator, which is lazily evaluated. Thus in Python 3, the registers are actually read ... in the restart function! So, of course, they don't hold the values of the check-point, and hence the restart function does nothing!

Using pdb in PyGTK applications

If you try to run pdb.set_trace() on a PyGTK application, the command-line prompt will be unusable, certainly because of (native) multithreading. Solution is simple once you got it, but not necessarily easy to find on the Internet:

def import_pdb_set_trace():
  '''Set a tracepoint in PDB that works with Qt'''
  from PyQt5.QtCore import pyqtRemoveInputHook
  pyqtRemoveInputHook()

  import pdb; pdb.set_trace() 

PDB aliases [for gdb.py scripting]

# gdb.py
alias ge import gdb;gdb.execute("%*") #  gdb execute
alias gq import gdb;gdb.execute("quit") # gdb quit

# force quit
alias fq import os;os._exit(0) 

# quick print
alias pr print(%1)

# dir()
alias dir for k in dir(%1): print("{}".format(k))
alias dirv for k in dir(%1): print("{} --> {}".format(k, getattr(%1, k)))

alias ds dir self

A situation that occurred recently to a colleague of mine:

I don't understand what's the problem, I never use that variable, but if I comment it out, my program crashes! If I let it, it runs fine!

Of course, when you're used C programming and know a bit of memory layout, you already know that "it runs fine" is subjective and that there is buffer overflow somewhere in the code.

Nonetheless, I think the situation is interesting to study, just to remember that this can lead to tricky incomprehensible behaviors.

The problem

Consider this small C code:

 #include "stdio.h"

 #define SIZE 4

 //#define DO_NOT_CRASH

 int *i_ptr;

 #ifdef DO_NOT_CRASH
 int *not_used;
 #endif
 int array[SIZE];

 int main() {
   int i;
   i_ptr = &i;

   for (i = 0; i <= SIZE; i++) {
     array[i] = -1;
   }

   printf("*i_ptr   is ...");
   fflush(stdout);
   printf(" %d\n", *i_ptr);
 }

Run it:

gcc test.c -g -O0 && ./a.out \
echo ==============================; \
gcc test.c -g -O0 -DDO_NOT_CRASH && ./a.out

&i_ptr   is     0x7ffeac4708d0
*i_ptr   is ...[1]    8127 segmentation fault (core dumped)  ./a.out
==============================
&i_ptr   is     0x7ffd5056f508
*i_ptr   is ... 5

(I must admit that it was harder than expected to reproduce the bug. I first put all the variable on the stack (contrary to my colleague), but did not manage to have a clean and buggy behavior! Certainly memory alignment constraints that I don't understand well.)

Surprise! (or not)

Surprise, an unused variable can trigger a segmentation fault!

Last year I presented the definitions of a bug, according to Andreas Zeller. In this definition, he makes the distinction between

• a defect (an invalid piece of code),
• an infection (the execution of this defect, leading to an invalid memory area)
• the propagation of that infection (the augmentation of the invalid memory are size)
• and the failure, the externally observable error.

Here we've got an illustration of the purpose of these definition: with -DDO_NOT_CRASH, but program doesn't bug, but we now it's bugged. Yep, totally clear :-)

So what we really have is a program with a defect, whose memory space gets infected, but the infection does not propagate enough to lead to a failure.

How to detect it: with Valgrind

 valgrind ./a.out
 ==17545== Memcheck, a memory error detector
 ==17545== Copyright (C) 2002-2015, and GNU GPL'd, by Julian Seward et al.
 ==17545== Using Valgrind-3.11.0 and LibVEX; rerun with -h for copyright info
 ==17545== Command: ./a.out
 ==17545== 
 *i_ptr   is ... 5
 ==17545== 
 ==17545== HEAP SUMMARY:
 ==17545==     in use at exit: 0 bytes in 0 blocks
 ==17545==   total heap usage: 0 allocs, 0 frees, 0 bytes allocated
 ==17545== 
 ==17545== All heap blocks were freed -- no leaks are possible
 ==17545== 
 ==17545== For counts of detected and suppressed errors, rerun with: -v
 ==17545== ERROR SUMMARY: 0 errors from 0 contexts (suppressed: 0 from 0)

Nop! I expected to see something with valgrind, but apparently it's not illegal enough! (or I missed an option ...?)

How to detect it: with GDB

That that we understand the situation, we know that there is a buffer overflow, but we need to find the infection point!

(gdb) start
(gdb) watch not_used 
Hardware watchpoint 2: not_used
(gdb) cont
Continuing.
Hardware watchpoint 2: not_used

Old value = (int *) 0x0
New value = (int *) 0xffffffff
main () at overflow-long.c:18
18    for (i = 0; i <= SIZE; i++) {
19      array[i] = -1;
(gdb) print i
$1 = 4

There we are, for i=4, array[i] overflows into not_used. Our defect contaminates a memory area that is never read, so it never propagated to a failure.

Unexpected behavior of GDB watchpoint

At the beginning of the execution, the value of not_used is 0. In the overflow of the for loop, I set it to -1, so the watchpoint is triggered.

But in the first code I wrote, I set it to 0, and the watchpoint was ... not triggered. That's a bit unexpected to me, a write is a write, so I wanted the watchpoint to trigger!

So, just to confirm, I tried with rwatch, to set a read watchpoint ... and it worked!

 (gdb) rwatch not_used 
 Hardware read watchpoint 2: not_used
 (gdb) cont
 Continuing.
 Hardware read watchpoint 2: not_used

 Value = (int *) 0x0
 main () at overflow-long.c:18
 18   for (i = 0; i <= SIZE; i++) {
 (gdb)

That's also surprising to me, as my code is not supposed to read anything at this address!

Just to make it stranger, using rwatch with 0 <- -1 and watch with 0 <- 0 (the reverse of what works) doesn't work! (For the record, it's always the mov instruction that triggers my watchpoints).

(from @fortes on Tweeter)

Since quite a while now, I'm a big fan of GDB, the debugger of the GNU project. I did my Master project (User level DB: a debugging API for user-level thread libraries , PDF) and PhD thesis (Programming-Model Centric Debugging for multicore embedded systems) on the topic of source-level interactive debugging, so I'm getting quite confident in how to use GDB. I find its command-line interface (CLI) easy to use, intuitive, powerful, etc., but I know that's not a commonly shared opinion :-) So I'd like to describe, with this 'real-life' bug, how I use it, and at the same time how I did this debugging investigation.

The Minimal Application

I wrote for this article a minimal working example (MWE) that mimics the behavior of the buggy application. Don't forget that at the time I write this post, I already know where the bug is, so I'll go straight to the point, and skip some of the dead-ends of the initial investigation. That will save us time :-) Also note that I did not write the original code myself, and I don't know anything about libevent. I just got my hand on it, and wanted to get rid of this bug.

You can get the source code from this GIST, with the fix or without (if you want to try to solve it yourself :-). Compile it with:

g++ bug.cpp -std=c++11 -levent -levent_pthreads -lpthread -g -O2

You'll need libevent debugging information if you want to reproduce the investigation.

Its (expected) behavior is quite simple:

1. Configure and enable libevent.
2. Create an second thread dispatching the events. We'll call it the dispatcher thread.
3. Wait WAIT_TIME seconds to mockup the application execution.
4. Decide it's time to leave and tell the other thread/libevent to quit the event dispatching loop.
5. Wait for the other thread to report its end of activity, join it and quit.

The Visible Error

Step 5. is the one with the visible error: the main thread loops forever, waiting for the dispatcher thread:

PID is 19425
Setting thread usage a bit late
Sleeping for 2 seconds ...
Running the dispatcher ...
And killing the application.
Waiting for the thread to die ... (try ^z/fg, SIGSTOP/SIGINT)
Waiting for the thread to die ... (try ^z/fg, SIGSTOP/SIGINT)
Waiting for the thread to die ... (try ^z/fg, SIGSTOP/SIGINT)
^C

It won't terminate, so we call it with a ^C.

Understand the Situation: The Downwards Investigation

In the first part of the investigation, we'll try to understand why the application is blocked. We'll dive into the code to figure out what drives the execution into that bug.

Let's run the application with GDB.

$ gdb a.aout
(gdb) run
PID is 24468
Setting thread usage a bit late
[New Thread 0x7ffff6b37700 (LWP 24472)]
Running the dispatcher ...
Sleeping for 2 seconds ...
And killing the application.
Waiting for the thread to die ... (try ^z/fg, SIGSTOP/SIGINT)
Waiting for the thread to die ... (try ^z/fg, SIGSTOP/SIGINT)
...
^C

The execution is now interrupted in the middle of the infinite loop, so let's check the state of the threads.

(gdb) thread 1
$ where n
#0  0x... in nanosleep () from /usr/lib/libpthread.so.0
#1  0x... in sleep_for<long, std::ratio<1l, 1000l> > (...) 
#2  main () at bug.cpp:82

(gdb) frame 2
(gdb) l # for list
81      while (true) {
82        std::this_thread::sleep_for(std::chrono::milliseconds(1000));
83        if (not m_active_thread.load()) {
84          break;
85        }
86        std::cout << "Waiting for the thread to die ... (try ^z/fg, SIGSTOP/SIGINT)" << std::endl;

Right, thread 1 is inside the waiting loop, that was expected.

(gdb) thread 2
(gdb )where 4
#0  0x... in epoll_wait () from /usr/lib/libc.so.6
#1  0x... in epoll_dispatch (...) at epoll.c:407
#2  0x... in event_base_loop (...) at event.c:1633
#3  0x... in server_thread () at bug.cpp:21
(More stack frames follow...)

Hum, thread 2 is still blocked in epoll_wait, that's why it doesn't return from event_base_loop and unlocks the main thread from the waiting loop:

void server_thread(){
  std::cout << "Running the dispatcher ..." << std::endl;
  event_base_dispatch(base); // still in this function
  event_base_free(base);

  m_active_thread.store(false);
  std::cout << "Dead" << std::endl;
}

Clue 1: the dispatcher thread is blocked in epoll_wait system call.

Side remark: I won't go into details into the probe effect that can happen here, check my previous post.

New lead: why the dispatcher thread doesn't quit the dispatching loop?

A quick search on the Internet tells us that event_base_loopbreak should break that loop.

Hypothese to verify: Is event_base_loopbreak actually called?

(gdb) break event_base_loopbreak
(gdb) run
...
Breakpoint 1, event_base_loopbreak (event_base=0x617c50) at event.c:1511

(gdb) up
#1  0x... in main () at bug.cpp:79
79      event_base_loopbreak(base);

Yes, at bug.cpp:79.

Hypothese to verify: Is event_base_loopbreak action actually done?

int
event_base_loopbreak(struct event_base *event_base)
{
  int r = 0;
  if (event_base == NULL)
    return (-1);

  EVBASE_ACQUIRE_LOCK(event_base, th_base_lock);
  event_base->event_break = 1;

  if (EVBASE_NEED_NOTIFY(event_base)) {
    r = evthread_notify_base(event_base);
  } else {
    r = (0);
  }
  EVBASE_RELEASE_LOCK(event_base, th_base_lock);
  return r;
}

Is base not NULL? (otherwise we'll return too quickly)

(gdb) p base # for print
$1 = (event_base *) 0x617c50

(gdb) p *base
$2 = {
  evsel = 0x7ffff7dd9140 <epollops>, 
  evbase = 0x617ee0, 
  changelist = {
    changes = 0x0, 
    n_changes = 0, 
    changes_size = 0
  }, 
  evsigsel = 0x7ffff7dd9180 <evsigops>, 
  sig = {
    ev_signal = {
...

Yes, and its content seem right (base->evsel is epollops, which makes sense, so it's not a dangling pointer).

So the event_break flag will be set:

(gdb) n # for next
1513        if (event_base == NULL)
(gdb) n
1516        EVBASE_ACQUIRE_LOCK(event_base, th_base_lock);
(gdb) n
1519        if (EVBASE_NEED_NOTIFY(event_base)) {
(gdb) n
1517        event_base->event_break = 1;

Wait, what!? event_break = 1 should be before NEED_NOTIFY! Don't pay attention to that, it's because of compiler optimizations. Recompile libevent with -O0 flag or ignore it!

(gdb) n
1519        if (EVBASE_NEED_NOTIFY(event_base)) {

This one is the real test ;-)

Now let's make sure that it's the right flag we set. With a quick search in event.c, we found:

int
event_base_got_break(struct event_base *event_base)
{
    int res;
    EVBASE_ACQUIRE_LOCK(event_base, th_base_lock);
    res = event_base->event_break;
    EVBASE_RELEASE_LOCK(event_base, th_base_lock);
    return res;
}

That looks good. Is it ever called?

(gdb) start
(gdb) b event_base_got_break
Breakpoint 2 at 0x7ffff7ba05a0: file event.c, line 1530.

(gdb) cont
Running the dispatcher ...
Sleeping for 2 seconds ...
And killing the application.
Waiting for the thread to die ... (try ^z/fg, SIGSTOP/SIGINT)
Waiting for the thread to die ... (try ^z/fg, SIGSTOP/SIGINT)
Waiting for the thread to die ... (try ^z/fg, SIGSTOP/SIGINT)
^C
Program received signal SIGINT, Interrupt.
0x00007ffff778465d in nanosleep () from /usr/lib/libpthread.so.0

Not before the infinite loop apparently,

(gdb) cont
Dead
[Thread 0x7ffff6b39700 (LWP 20947) exited]
Bye everybody.
[Inferior 1 (process 20852) exited normally]

... and not after either. (That's the probe effect we see here). So that's certainly a dead-end.

That could also be the reason of the bug, but the fact that the debugger interrupt makes the application finish properly tells me to let that idea aside.

Next candidate?

int
event_base_loop(struct event_base *base, int flags)
{
    ...
    base->event_gotterm = base->event_break = 0;
    ...
    while (!done) {
        if (base->event_break) {
            break;
        }
        ...
        res = evsel->dispatch(base, tv_p);
        ...
    }
}

(gdb) p evsel->dispatch
$1 = (int (*)(struct event_base *, struct timeval *)) 0x7ffff7bb7d80 <epoll_dispatch>

Yes, that seems to be the right flag: it breaks the loop when set, and just a bit after, the epoll_dispatch function is called (that's the one that blocks forever on epoll_wait).

New lead: How is epoll supposed to quit its polling loop?

(gdb) thread 2
Thread ID 2 not known.

Damn, it's gone, that's the probe effect ...

(gdb) run # that restarts the execution from the beginning
...
Sleeping for 2 seconds ...
^C
Program received signal SIGINT, Interrupt.
0x... in nanosleep () from /usr/lib/libpthread.so.0

(gdb) thread 2
[Switching to thread 2 (Thread 0x7ffff6b39700 (LWP 3962))]
#0  0x... in epoll_wait () from /usr/lib/libc.so.6

(gdb) where 3
#0  0x... in epoll_wait () at /usr/lib/libc.so.6
#1  0x... in epoll_dispatch (base=0x617c50, tv=<optimized out>) at epoll.c:407
#2  0x... in event_base_loop (base=0x617c50, flags=0) at event.c:1629
#3  0x... in server_thread() () at bug.cpp:21

(gdb) up
#1  0x... in epoll_dispatch (base=0x617c50, tv=<optimized out>) at epoll.c:407
407        res = epoll_wait(epollop->epfd, events, epollop->nevents, timeout);

(gdb) p timeout
$1 = <optimized out>

Nope, we can't get the timeout value ... Let's try to see how it's computed:

(gdb) l 397
391     long timeout = -1;
392
393        if (tv != NULL) {
394            timeout = evutil_tv_to_msec(tv);
395            if (timeout < 0 || timeout > MAX_EPOLL_TIMEOUT_MSEC) {
396                /* Linux kernels can wait forever if the timeout is
397                 * too big; see comment on MAX_EPOLL_TIMEOUT_MSEC. */
398                timeout = MAX_EPOLL_TIMEOUT_MSEC;
399            }
400        }

(gdb) p tv
$2 = <optimized out>

Nope again, but let's try to outsmart it!

(gdb) up
#2  0x00007ffff7ba2a0d in event_base_loop (base=0x617c50, flags=0) at event.c:1629
1629            res = evsel->dispatch(base, tv_p);

(gdb) p tv_p
$3 = (struct timeval *) 0x0

Soon enough! So timeout remains -1. And that's a valid value for epoll_wait:

The timeout argument specifies the minimum number of milliseconds that epoll_wait() will block. [...] Specifying a timeout of -1 causes epoll_wait() to block indefinitely [...].

So epoll_wait won't return until it receives something from its event listeners ...

Clue 2: The dispatcher thread waits for a notification.

We saw something like that earlier on, where was that ... Oh, yes, EVBASE_NEED_NOTIFY(event_base) inside event_base_loopbreak. But the name looks like a preprocessor macro ... Indeed:

(gdb) p EVBASE_NEED_NOTIFY
No symbol "EVBASE_NEED_NOTIFY" in current context.

So let's get back to the source:

$ cd $PATH_TO_LIBEVENT_SRC
$ grep "define EVBASE_NEED_NOTIFY" . --after-context=2 --include='*.h' -r
./evthread-internal.h:#define EVBASE_NEED_NOTIFY(base)             \
./evthread-internal.h-    (_evthread_id_fn != NULL &&             \
./evthread-internal.h-        (base)->running_loop &&             \
--
./evthread-internal.h:#define EVBASE_NEED_NOTIFY(base)             \
./evthread-internal.h-    ((base)->running_loop &&             \
./evthread-internal.h-        ((base)->th_owner_id != _evthreadimpl_get_id()))
--
./evthread-internal.h:#define EVBASE_NEED_NOTIFY(base) 0
./evthread-internal.h-#define EVBASE_ACQUIRE_LOCK(base, lock) _EVUTIL_NIL_STMT
./evthread-internal.h-#define EVBASE_RELEASE_LOCK(base, lock) _EVUTIL_NIL_STMT

According to the macro names, it seems to be the first one. If you can recompile the code, you can add a #error to ensure it:

#error "Compilation will crash if we pass here."
#define EVBASE_NEED_NOTIFY(base) ...

If you can recompile the code, while you're at it, you can do a bit of printf debugging (that's what I did :-/) to get it's value:

printf("need notify ? %d\n", EVBASE_NEED_NOTIFY(event_base));

Otherwise, let's check the values with GDB:

(gdb) p _evthread_id_fn
$5 = (unsigned long (*)(void)) 0x7ffff7991d50 <evthread_posix_get_id>

(gdb) p base->running_loop
$6 = 1

Looks good. We can continue that investigation:

(gdb) b evthread_notify_base
(gdb) continue
Breakpoint 2, evthread_notify_base (base=0x617c50) at event.c:2039
2039    {

Where are we? at the begiining of this function:

(gdb) l
2038    evthread_notify_base(struct event_base *base)
2039    {
2040        EVENT_BASE_ASSERT_LOCKED(base);
2041        if (!base->th_notify_fn) {
2042            return -1;
2043        }
2044        if (base->is_notify_pending)
2045            return 0;
2046        
2047        base->is_notify_pending = 1;
2048        return base->th_notify_fn(base);
2049    }

Great, so, do we have a notification function?

(gdb) p base->th_notify_fn
$7 = (int (*)(struct event_base *)) 0x0

No, there is no notification function!

Now it makes sense:

Intermediate conclusion regarding the visible error:

• the dispatcher thread is blocked forever:
  • and waits for an epoll notification that never comes,
  • then it should check a flag for breaking its listening loop
• the main thread sets the loop-breaking flag,
  • but fails to notify epoll, so the dispatcher thread never checks the flag
  • then it waits forever for the dispatcher thread completion.

Problem solved! Or maybe not, maybe we just understood the situation.

Understanding the Reason of the Invalid State: Backwards Investigation

Now that we are at the bottom of the callstacks, we need to go backwards in time: The state of the application is invalid, the notify function pointer has to be set, so why is it empty? which decision(s) set it to NULL instead of the actual notification function?

New lead: Why is this th_notify_fn empty?

$ cd $PATH_TO_LIBEVENT_SRC
grep th_notify_fn * -n
grep: autom4te.cache: Is a directory
grep: compat: Is a directory
event.c:2037:    if (!base->th_notify_fn) {
event.c:2045:    return base->th_notify_fn(base);
event.c:2829:    base->th_notify_fn = notify;
event-internal.h:293:    int (*th_notify_fn)(struct event_base *base);

The instruction at event.c:2829 looks interesting. It is inside function evthread_make_base_notifiable. Is this function ever called?

(gdb) start
(gdb) break evthread_make_base_notifiable
Breakpoint 2 at 0x7ffff7ba6220: file event.c, line 2780.

(gdb) cont
PID is 28680
Setting thread usage a bit late
[New Thread 0x7ffff6b39700 (LWP 28778)]
Running the dispatcher ...
Sleeping for 2 seconds ...
And killing the application.
Waiting for the thread to die ... (try ^z/fg, SIGSTOP/SIGINT)
^C

Apparently, no. So th_notify_fn is empty because it is never set.

New lead: How to 'make the base notifiable'?

$ grep evthread_make_base_notifiable *.c -n
event.c:640:        r = evthread_make_base_notifiable(base);
event.c:884:        res = evthread_make_base_notifiable(base);
event.c:2775:evthread_make_base_notifiable(struct event_base *base)

Line 2775 is the function definition, line 884 is inside a function called event_reinit, so that's certainly not what we can. Line 640 looks more interesting:

struct event_base *
event_base_new_with_config(const struct event_config *cfg)
{
    ...
#ifndef _EVENT_DISABLE_THREAD_SUPPORT
    if (EVTHREAD_LOCKING_ENABLED() &&
        (!cfg || !(cfg->flags & EVENT_BASE_FLAG_NOLOCK))) {
            int r;
            EVTHREAD_ALLOC_LOCK(base->th_base_lock,
            EVTHREAD_LOCKTYPE_RECURSIVE);
            base->defer_queue.lock = base->th_base_lock;
            EVTHREAD_ALLOC_COND(base->current_event_cond);
            r = evthread_make_base_notifiable(base);
            if (r<0) {
                event_warnx("%s: Unable to make base notifiable.", __func__);
                event_base_free(base);
                return NULL;
            }
        }
#endif

Macro _EVENT_DISABLE_THREAD_SUPPORT is not defined (so the block is executed), but what is EVTHREAD_LOCKING_ENABLED()?

grep EVTHREAD_LOCKING_ENABLED * --after-context=1 --include='*.h'
evthread-internal.h:#define EVTHREAD_LOCKING_ENABLED()        \
evthread-internal.h-    (_evthread_lock_fns.lock != NULL)

... and this thread-locking function table is ... empty!

(gdb) p _evthread_lock_fns.lock
$1 = (int (*)(unsigned int, void *)) 0x0

(gdb) p _evthread_lock_fns
$2 = {
    lock_api_version = 0, 
    supported_locktypes = 0, 
    alloc = 0x0, 
    free = 0x0, 
    lock = 0x0, 
    unlock = 0x0
}

So to make the base notifiable ...

New lead: Thread locking should be enabled.

Let's check if it already done ..., and let's do it with GDB, instead of grep, with a memory watchpoint:

(gdb) start
(gdb) p _evthread_lock_fns 
$1 = { lock_api_version = 0,  supported_locktypes = 0,  ... }
# that's the defaut value

(gdb) watch _evthread_lock_fns
Watchpoint 2: _evthread_lock_fns

(gdb) run
... takes forever ...

Wait, there is a problem here, it takes forever. And it doesn't say 'Hardware watchpoint', although I know my CPU is capable of it ...

Side remark: That's because _evthread_lock_fns is a structure, and HW watchpoints can only watch a few addresses. So software watchpoints are used instead, which are very very very slow (each time a machine instruction is executed, GDB analyses the memory address(es) involved, and continues the execution if they are not covered by a watchpoint).

Let's try again:

(gdb) start
(gdb) p &_evthread_lock_fns
$1 = (struct evthread_lock_callbacks *) 0x7ffff7dda320 <_evthread_lock_fns>

(gdb) watch *0x7ffff7dda320
Hardware watchpoint 2: *0x7ffff7dda320
# good, a HW breakpoint
# it only watches the first bits of the structure, but that's enough

# OR that would do the same:
(gdb) watch _evthread_lock_fns->lock_api_version
Hardware watchpoint 3: _evthread_lock_fns->lock_api_version

(gdb) cont
Hardware watchpoint 2: *0x7ffff7dda320
Old value = 0
New value = 1
Hardware watchpoint 3: _evthread_lock_fns->lock_api_version

Old value = 0
New value = 1
0x00007ffff7ba7472 in evthread_set_lock_callbacks (cbs=cbs@entry=0x7fffffffe4b0) at evthread.c:101
101            memcpy(target, cbs, sizeof(_evthread_lock_fns));

(gdb) p *cbs
$3 = {
    lock_api_version = 1, 
    supported_locktypes = 1, 
    alloc = 0x7ffff7991e60 <evthread_posix_lock_alloc>, 
    free = 0x7ffff7991e40 <evthread_posix_lock_free>, 
    lock = 0x7ffff7991e20 <evthread_posix_lock>, 
    unlock = 0x7ffff7991e10 <evthread_posix_unlock>
}

So we do set the thread locking functions ...

New lead: but why were they empty earlier on? when/where do we set them?

(gdb) where
#0  0x00007ffff7ba7390 in evthread_set_lock_callbacks (cbs=cbs@entry=0x7fffffffe4b0) at evthread.c:76
#1  0x00007ffff799202b in evthread_use_pthreads () at evthread_pthread.c:185
#2  0x000000000040162a in main() () at bug.cpp:69

oh, that's from the main, at bug.cpp:69. Where were we when we saw them empty?

(gdb) break event_base_new_with_config
(gdb) run
(gdb) where
#0  0x00007ffff7ba63c0 in event_base_new_with_config (cfg=cfg@entry=0x617c20) at event.c:553
#1  0x00007ffff7ba680b in event_base_new () at event.c:452
#2  0x0000000000401553 in main() () at bug.cpp:50

Oh, I see, we were at bug.cpp:50, so 19 lines before.

Defect explanation and fix: it happens that the application created and configured libevent's base (event_base_new()) before configuring its thread-support. So the notification could not be sent, and hence the dispatcher thread remained blocked in epoll forever.

This is obviously an 'application bug', libevent was used incorrectly. Furthermore, event_base_loopbreak did returned at error code, but that was not checked and hence never noticed. We can verify that very quickly with GDB:

(gdb) start
(gdb) break bug.cpp:79
(gdb) cont
Breakpoint 2, main () at bug.cpp:79
79      event_base_loopbreak(base);

(gdb) p event_base_loopbreak(base)
$1 = -1

This way, we ask GDB to call the function event_base_loopbreak and print its result. Another way is to set a breakpoint inside the function, and ask GDB to finish it:

(gdb) break event_base_loopbreak
(gdb) cont
Breakpoint 2, event_base_loopbreak (event_base=0x617c50) at event.c:1511
1511    {

(gdb) finish
Run till exit from #0  event_base_loopbreak (event_base=0x617c50) at event.c:1511
main () at bug.cpp:82
82      std::this_thread::sleep_for(std::chrono::milliseconds(1000));
Value returned is $1 = -1

Both ways show that the return value is -1...

Of course the application from which I base this example was in development, with no bug-free guarantee, so no one to blame! I actually quite enjoyed this work of investigation :)

You can change #define DO_BUG to false at the beginning the source code, and see that is solves the problem.

Conclusion

In this article I tried to highlight the usage of GDB with a real debugging example, on which I spend my last Friday afternoon. I showed the way I performed this investigation, although I must admit that I used a bit more printf than I show here. That's mainly because of the probe effect that occurs with this bug, that complicates the use of GDB.

If ever you don't like interactive debuggers, or you would have done this debugging with different tools and techniques, let me know, I'm curious! Just keep in mind that I didn't write the original code and I didn't want to spend my afternoon reading libevent documentation! (I didn't even know for sure that the bug was related to this library).

Also, this is not an 'advanced' usage of GDB, I only used the very basic functionalities. Maybe one day I'll encounter a trickier bug that requires a more subtle juggling with GDB commands, and I'll post a new article on the topic!

Probe effect is unintended alteration in system behavior caused by measuring that system. (according to Wikipedia)

I had such a problem yesterday while debugging a tool based on libevent :

1. in a multi-threaded application, the main thread receives the quit order,
2. it transmits the information to the helper thread,
   • the helper thread quits
3. the main thread wait for the end of the secondary thread execution
4. and terminates the process.

But that didn't work, because the helper thread never quits, and the main one waits forever.

MWE: Minimal Working Example

Here is a slightly simplified reconstruction of this bug. Don't pay attention to the epoll configuration, I don't know how to use it and didn't learn!

#include <sys/epoll.h>
#include <stdio.h>
#include <stdlib.h>
#include <unistd.h>

#define MAXEVENTS 64
#define TIMEOUT -1

void main () {
  struct epoll_event event; struct epoll_event *events;
  int fd = 0; int efd = epoll_create1 (0);

  printf("OH, HAI!\n");
  printf("BTW pid = %d\n", getpid());

  /* I never learnt how to use epoll...  */
  event.events = EPOLLIN | EPOLLET; event.data.fd = fd;
  epoll_ctl (efd, EPOLL_CTL_ADD, fd, &event);
  events = calloc (MAXEVENTS, sizeof event);

  /* Wait forever for an event.  */
  epoll_wait (efd, events, MAXEVENTS, TIMEOUT);

  printf("KTHXBYE\n");
}

then run it:

$ ./a.out
OH, HAI!
BTW pid = 4900

yes, it's blocked, that was expected. Ctrl-C to quit.

The probe effect

Now run it again, and attach GDB to it:

$ gdb --pid $THE_PID
GNU gdb (GDB) 7.9.50.20150505-cvs
...
0x00007fdb33ac7703 in __epoll_wait_nocancel () from /usr/lib/libc.so.6
(gdb) continue
KTHXBYE
[Inferior 1 (process 6957) exited with code 010]

What !? the application now prints KTHXBYE and exits normally ... ! That's the probe effect !

The probe effect ... may not be directly related to the probe!

There is another way to get get the application finish properly, it's with a SIGSTOP/SIGCONT combo:

$ ./a.out
OH, HAI!
BTW pid = 7997
^Z
[1]  + 7997 suspended  ./a.out
$ fg
[1]  + 7997 continued  ./a.out
KTHXBYE

So that probe effect is not actually due to the probe, but to ...

Explanation of this probe effect

... to the fact that GDB (and signals) interrupt system calls !

That's (obviously) in epoll_wait man page:

ERRORS

EINTR : The call was interrupted by a signal handler before either (1) any of the requested events occurred or (2) the timeout expired; see signal(7).

In my libevent application, the thread was blocked in this epoll_wait syscall, which was interrupted by the debugger/signals. Then it checks for the exit flag and terminates as expected.

(It was a configuration problem, not a bug in libevent. The function that should notify the epoll listener was not correctly configured.)

TL;DR

Debuggers (and signals) may and will interrupt system calls. Your code should take that in consideration, that's a normal behavior of system calls. But that may also introduce "probe effects" when you try to study your code with a debugger!

When extending through its Python API (or directly in C), the situation where you have to use threads may pop up. For instance with GUIs, or when using another library or module.

Unfortunately, GDB doesn't like that much. First of all, you cannot call GDB Python functions from another thread. GDB itself not multithreaded, and hence not thread safe. Python is though, so you should be able to block the main thread in Python, and call GDB functions in the other thread, but outside from that, GDB will simply crash! And there is nothing to do against that, as far as I know.

But worth (kind of), GDB doesn't support that your code spawns a thread.

TL;DR: solution

In C (GDB bug #17247, patch and discussion):

sigemptyset (&sigchld_mask);
sigaddset (&sigchld_mask, SIGCHLD);
sigprocmask (SIG_BLOCK, &sigchld_mask, &prev_mask);

scm_with_guile (call_initialize_gdb_module, NULL);
sigprocmask (SIG_SETMASK, &prev_mask, NULL);

In Python:

import pysigset, signal

with pysigset.suspended_signals(signal.SIGCHLD):
    # start threads, they will inherit the signal mask
    pass

Description of the bug

When you create (in Python) a thread, and then run the application (in my case it happens mainly when the application itself spawns threads), GDB freezes with the following callstack:

(gdb) where
#0 sigsuspend () from /usr/lib/libc.so.6
#1 wait_lwp (lp=lp@entry=0x21f63b0) at ../../gdb/gdb/linux-na
#2 stop_wait_callback (lp=0x21f63b0, data=<optimized out>) at
#3 iterate_over_lwps (filter=..., callback=callback@entry=0x4
#4 linux_nat_wait_1 (ops=<optimized out>, target_options=1, o
#5 linux_nat_wait (ops=<optimized out>, ptid=..., ourstatus=0
#6 thread_db_wait (ops=<optimized out>, ptid=..., ourstatus=0
...

Explanation of the bug

The function in which GDB is blocked is sigsuspend:

NAME

sigsuspend, rt_sigsuspend - wait for a signal

SYNOPSIS

int sigsuspend(const sigset_t * mask);

DESCRIPTION

sigsuspend() temporarily replaces the signal mask of the calling process with the mask given by mask and then suspends the process until delivery of a signal whose action is to invoke a signal handler or to terminate a process.

GDB uses this function to wait for new events from the application execution: when something occurs in the debuggee (see how debuggers work), the kernel will inform GDB of it by sending a SIGCHLD signal. When it's received, GDB awakes and check what happened.

However, the signal is delivered to GDB process, but not necessarily to its main thread. And it practise, it occurs often that it's delivered to the second thread, who doesn't care about it (that's the default behavior), and continues its life as if nothing occurred.

Solution of the problem

We cannot change the behavior of the thread. However, we have a bit of control over its default signal handling behavior: it is inherited from its parent! So, in Python, we can go this way:

import pysigset, signal

# with SIGCHLD blocked,
with pysigset.suspended_signals(signal.SIGCHLD):
    # start threads,
    # they will inherit the signal mask
    pass
# SIGCHLD is unblocked after the with statement,
# so that GDB can operate properly afterwards

When I script GDB to develop model-centric debugging support, I often need to execute code upon specific events, namely after breakpoints hits. It looks like that:

import gdb

class MyBP(gdb.Breakpoint):
    def __init__(self):
        gdb.Breakpoint.__init__(self, "a_function")
        self.silent = True

    def stop(self):
        print "##### breakpoint"
        return True # stop the execution at this point

MyBP()

However, in this Breakpoint::stop callback, you're not free to do what ever you want:

Thou shalt not:

• alter the execution state of the inferior (i.e., step, next, etc.),
• alter the current frame context (i.e., change the current active frame), or
• alter, add or delete any breakpoint.

As a general rule, you should not alter any data within gdb or the inferior at this time.

That's a "general rule" in the documentation, however it's not enforced at runtime, so in practice, there are many things you can do, but the result in not guaranteed!

What can go wrong?

I sometimes have to delete breakpoint, and I thought that gdb.post_event(this_bp.delete) would be safe. And it is, if your GDB is configured with set height 0. You don't see the link? Fair enough, it's very tricky! set height 0 tells GDB not to stop when the screen is full, which is an artifact of the past.

When GDB does stop at the end of the window, it processes the "posted events", and actually deletes the breakpoint structure. However the breakpoint is not removed from all GDB low-level lists, and than leads to a segmentation fault when GDB tries to access it. Here are the stack traces (deletion and invalid access) from Valgrind that helped me to figure out what was happening:

 Address 0x18c0bd40 is 0 bytes inside a block of size 200 free'd  # stack of the free(breakpoint)
   at 0x4A07577: free (in /usr/lib64/valgrind/vgpreload_memcheck-amd64-linux.so)
   by 0x763558: xfree (common-utils.c:98) # here the breakpoint structure is freed
   by 0x58D49D: delete_breakpoint (breakpoint.c:14074)
   by 0x525F92: bppy_delete_breakpoint (py-breakpoint.c:287) # that's the breakpoint delete function
   by 0x3BB384A0D2: PyObject_Call (in /usr/lib64/libpython2.7.so.1.0)
   by 0x3BB38DC026: PyEval_CallObjectWithKeywords (in /usr/lib64/libpython2.7.so.1.0)
   by 0x522C9C: gdbpy_run_events (python.c:934) # process Python events
   by 0x4AC258: run_async_handler_and_reschedule (ser-base.c:137)
   by 0x4AC328: fd_event (ser-base.c:182)
   by 0x61C281: handle_file_event (event-loop.c:762)
   by 0x61B768: process_event (event-loop.c:339)
   by 0x61B80A: gdb_do_one_event (event-loop.c:391)

Invalid read of size 8 # stack of the illegal memory access
   at 0x57C2B9: bpstat_explains_signal (breakpoint.c:4430) # here the breakpoint structure is accessed
   by 0x5FCFE3: handle_signal_stop (infrun.c:4474)
   by 0x5FC484: handle_inferior_event (infrun.c:4110)
   by 0x5FA831: fetch_inferior_event (infrun.c:3261)
   by 0x61E506: inferior_event_handler (inf-loop.c:57)
   by 0x4BC10E: handle_target_event (linux-nat.c:4448)
   by 0x61C281: handle_file_event (event-loop.c:762)
   by 0x61B768: process_event (event-loop.c:339)
   by 0x61B80A: gdb_do_one_event (event-loop.c:391)
   by 0x727F0D: maybe_wait_sync_command_done (top.c:386)
   by 0x728199: execute_command (top.c:478)
   by 0x6148E7: catch_command_errors (main.c:373)

Among the other thing that cannot be done (and that I wanted to do), we find thread switching:

def stop(self):
    print("##### breakpoint")
    gdb.selected_inferior().threads()[1].switch()
    gdb.selected_inferior().threads()[0].switch()
    return False # don't stop

which leads to another segfault:

[New Thread 0x7ffff7fca700 (LWP 22661)]
##### breakpoint
[Thread 0x7ffff7fca700 (LWP 22661) exited]
[Inferior 1 (process 22657) exited normally]
[2]    22651 segmentation fault (core dumped)  gdb-fedora -ex "source test.py" ./thread -ex run

or altering the instruction pointer of the inferior:

[New Thread 0x7ffff7fca700 (LWP 23100)]
##### breakpoint
Traceback (most recent call last):
  File "test.py", line 11, in stop
    gdb.execute("next")
gdb.error: Cannot execute this command while the selected thread is running.

Alternatives

But what if you really what to do it ?! Then you have to find alternatives! and there are a few (but they assume you want to stop the execution at this breakpoint, and give the prompt back to the user).

class MyBP(gdb.Breakpoint):
    def stop(self):
        print("##### breakpoint")
        gdb.events.stop.connect(stop_event)
        gdb.prompt_hook = prompt
        gdb.post_event(posted_event)
        return True

Subscribing to the stop events

def stop_event(evt):
    print("#### stop event")
    gdb.events.stop.disconnect(stop_event)

Hooking the prompt:

def prompt(current):
    print("#### prompt")
    gdb.prompt_hook = current

Posting events (which seem to work well when height=0)

def posted_event():
    print("#### posted event")

These callbacks are executed in this order:

##### breakpoint
#### stop event
#### prompt
(gdb) #### posted event

Note that the prompt hook is executed right before giving the control to the user, so gdb.execute("<command>") works very close to what you can expect from the command line. That saved the work of my afternoon yesterday!

C preprocessor macro are quite convenient while programming, however they can quickly become a burden while compiling and debugging. Consider this little C program:

#define str(s) #s
#define xstr(s) str(s)

#define A 10
#define B 15

#ifndef C
#define C 15
#endif

#define MIN(x, y) (x > y ? y : x)
int printf (const char * format, ... );

void main(int argc, char **argv) {
  printf("test1 " xstr(A) " vs " xstr(B) " -> %d\n", MIN(A, B));
#undef A
#undef B
#define A 0
    printf("test2 " xstr(A) " vs " xstr(C) " -> %d\n", MIN(A, C));
}

It outputs, as expected:

$ gcc test.c && ./a.out
test1 10 vs 15 -> 10
test2 0 vs 15 -> 0
$ gcc test.c -DC=-5 && ./a.out
test1 10 vs 15 -> 10
test2 0 vs -5 -> -5

Let's add a -g in the compiler flags and see how we can follow its execution with GDB.

Debugging macros with GDB, the hard way

$ gcc test.c -DC=-5 -g && gdb ./a.out
GNU gdb (GDB) 7.8.1
Reading symbols from ./a.out...done.
(gdb) start
Starting program: /tmp/a.out
Temporary breakpoint 1, main (argc=1, argv=0x7fffffffe998) at test.c:15
15    printf("test1 " xstr(A) " vs " xstr(B) " -> %d\n", MIN(A, B));
(gdb) print A
No symbol "A" in current context.
(gdb) p B
No symbol "B" in current context.

Okay, so we can't go anywhere so easily. So let's continue the hard way:

(gdb) x/4i $pc # print 4 i-instructions after the current address of the program counter/instruction pointer $pc
=> 0x400515 <main+15>:  mov    $0xa,%esi
   0x40051a <main+20>:  mov    $0x4005c4,%edi
   0x40051f <main+25>:  mov    $0x0,%eax
   0x400524 <main+30>:  callq  0x4003e0 <printf@plt>
(gdb) p/d 0xa # print hexadecimal number 0xa in d-igits
$2 = 10
(gdb) p (char *) 0x4005c4 # cast this address in char* and print it
$3 = 0x4005c4 "test1 10 vs 15 -> %d\n"

There we are, the processor is going to execute printf("test1 10 vs 15 -> %d\n", 10). Naively I expected to see the comparison between 10 and 15, but the compiler optimizes that automatically, even with -O0 flag. Change one operand to a 'real' C variable to see the comparison in the code.

That works, but that's a bit hardcore, and not easy to apply in all the situation. Nonetheless, it can be useful for instance to see which functions(s) will be called by a preprocessor macro function.

What can we do to better understand such pieces of code ?

First, let's remember how the preprocessor works: it preprocesses the source file, before passing it to the actual C compiler.

So let's intercept this step.

Debugging macros with GCC, an easier way

GCC can dump this intermediate step with the flag -E, or directly apply cpp to your file:

$ cpp test.c -DC=-5 # OR # gcc -E test.c -DC=-5
# 1 "test.c"
# 1 "<built-in>"
# 1 "<command-line>"
# 1 "/usr/include/stdc-predef.h" 1 3 4
# 1 "<command-line>" 2
# 1 "test.c"
# 12 "test.c"
int printf (const char * format, ... );

void main(int argc, char **argv) {
  printf("test1 " "10" " vs " "15" " -> %d\n", (10 > 15 ? 15 : 10));
  printf("test2 " "0" " vs " "-5" " -> %d\n", (0 > -5 ? -5 : 0));
}

And there we can see what is exactly fed to the C compiler. Note that the comparison is still here, so it's (obviously) not the preprocessor which optimized it out.

But this is not very interactive ... and we said that we want to use GDB!

Debugging macros with GDB, the nice way

The lasts versions of GCC+GDB (I can't say since when it's in place, just that it works with my up-to-date Archlinux) can respectively include and interpret preprocessor macro definitions inside the binary's debugging information. It's not included in the standard -g debugging flag, but in -g3, certainly because of the quantity of information that need to be included with dozens of header files are included in a C file.

$ gcc -g3 test.c -DC=-5  && gdb a.out 
GNU gdb (GDB) 7.8.1
Reading symbols from a.out...done.
(gdb) info macro A
The symbol `A' has no definition as a C/C++ preprocessor macro
at <user-defined>:-1

Argl, what's that? all the article was a lie? all of that to come to 'A' has no definition as a C/C++ preprocessor macro? That's what I though until yesterday. I tried to play with macros in GDB a couple of time, but always failed this hard. Until I read this forum post, that says in a more polite way: RTFM!

gdb uses the current listing position to decide which macro definitions are in scope.

Oh, yes, indeed, it makes sense ... !

(gdb) start
Temporary breakpoint 1 at 0x400515: file test.c, line 15.
Starting program: /tmp/a.out 
Temporary breakpoint 1, main (argc=1, argv=0x7fffffffe998) at test.c:15
15    printf("test1 " xstr(A) " vs " xstr(B) " -> %d\n", MIN(A, B));
(gdb) info macro A
Defined at /tmp/test.c:4
#define A 10
(gdb) next
test1 10 vs 15 -> 10
19      printf("test2 " xstr(A) " vs " xstr(C) " -> %d\n", MIN(A, C));
(gdb) info macro A
Defined at /tmp/test.c:18
#define A 0
(gdb) info macro C
Defined at /tmp/test.c:0
-DC=-5
(gdb) info macro MIN
Defined at /tmp/test.c:11
#define MIN(x, y) (x > y ? y : x)

GDB can also expand macro functions:

(gdb) macro expand MIN(A, B)
expands to: (10 > 15 ? 15 : 10)
(gdb) macro expand MIN(A,  MIN(A, 15))
expands to: (10 > (10 > 15 ? 15 : 10) ? (10 > 15 ? 15 : 10) : 10)
(gdb) p (10 > (10 > 15 ? 15 : 10) ? (10 > 15 ? 15 : 10) : 10)
$1 = 10

There we are, and that's working well, cool :-) (if you run gcc -E test.c -DC=-5 -g3 you'll see that the preprocessor passes the #defines to the compiler, including the builtin ones.

However, I couldn't get macro define|list|undef to work. According to the help, GDB should be able to change the value of macro-definitions, but that seems very hard to implement, maybe that's why it doesn't work ...

(gdb) help macro define
Define a new C/C++ preprocessor macro.
The GDB command `macro define DEFINITION' is equivalent to placing a
preprocessor directive of the form `#define DEFINITION' such that the
definition is visible in all the inferior's source files.
For example:
  (gdb) macro define PI (3.1415926)
  (gdb) macro define MIN(x,y) ((x) < (y) ? (x) : (y))
(gdb) start
Temporary breakpoint 1 at 0x400515: file test.c, line 15.
Starting program: /tmp/a.out 
Temporary breakpoint 1, main (argc=1, argv=0x7fffffffe998) at test.c:15
15    printf("test1 " xstr(A) " vs " xstr(B) " -> %d\n", MIN(A, B));
(gdb) macro define A -5
(gdb) macro define B -10
(gdb) n
test1 10 vs 15 -> 10