A Case Study of Debugging

In the previous post, I mentioned two great books about debugging. In this article, I want to share a real case which is solved by using some tricks. Last week, one of my colleague came to me and asked me a question: There is a Python script running. But can not use "kill process_pid" to kill it. Only "kill -9 process_id" works. Why?

My first guess is that the script installing a signal handler and not exit. My colleague promised it did exit. OK, let's check. First step, we observe the process's status by using ps:

shit 17392 99.7  0.2 244216 23300 ?        Rl   Aug10 9149:48 python /shit.py /shit.config

Hey, it is running and occupying almost CPU time. This means it may trap into some infinite loop. But there is no loop in the handler. Hmmm, some bug hidden in lower level? How to identify this?

We use gdb to attach the process and see where it is:

(gdb) attach 17392

(gdb) where

#0  adns_forallqueries_next (ads=0xb5d6500, context_r=0x7fff2ffe9b68) at ../src/setup.c:706

#1  0x00002ac062aa3d92 in PyDict_New () from /usr/lib64/python2.6/site-packages/adns.so

#2  0x0000003b5ead8e19 in PyEval_EvalFrameEx () from /usr/lib64/libpython2.6.so.1.0

...

And use "si" to step on assembly level since the adns.so compiled without any debug info. We make sure the value of IP is limited in adns_forallqueries_next()'s address range. We got the bug!! Check the source code of adns library(adns-1.2/src/setup.c):

1. adns_query adns_forallqueries_next(adns_state ads, void **context_r) {
2.   adns_query qu, nqu;
4.   adns__consistency(ads,0,cc_entex);
5.   nqu= ads->forallnext;
6.   for (;;) {
7.     qu= nqu;
8.     if (!qu) return 0;
9.     if (qu->next) {
10.       nqu= qu->next;
11.     } else if (qu == ads->udpw.tail) {
12.       nqu=
13.         ads->tcpw.head ? ads->tcpw.head :
14.         ads->childw.head ? ads->childw.head :
15.         ads->output.head;
16.     } else if (qu == ads->tcpw.tail) {
17.       nqu=
18.         ads->childw.head ? ads->childw.head :
19.         ads->output.head;
20.     } else if (qu == ads->childw.tail) {
21.       nqu= ads->output.head;
22.     } else {
23.       nqu= 0;
24.     }
25.     if (!qu->parent) break;
26.   }
27.   ads->forallnext= nqu;
28.   if (context_r) *context_r= qu->ctx.ext;
29.   return qu;
30. }

We know process is in this loop. But why? The reason is easy: in the signal handler, my colleague deletes an object which contains objects which invokes this C function when the object is destroyed. However, signal is sent to process at any possible time, if there is some object works on the list above and receives the signal, the list would not be complete...results in this strange behavior.

So how to solve this? It is easy. Just do not delete the object explicitly and let OS recycle the resource is enough. And remind colleague make sure every function calls in the signal handlers, no matter explicitly or implicitly, should be async-signal-safe. :-)