Saturday, 12 January 2013

Debugging threaded application crash

The story

Some time ago I had a nasty issue of an application crashing due to heap corruption. Quite quickly I discovered it was related to the intensively multi-threaded nature of the test case that reproduced the crash that happened in the field. The call stacks used to end up somewhere in malloc()/free() pair. I said they used to, as there where different ways it was crashing (different call stacks in the back trace). It was another reason to think that multiple threads were making harm to each other. To make this story more exciting (or painful to me at that time), the problem couldn't be reproduced on x86 PC. Only some specific timing conditions on the MIPSEL system could make the crash happen.

The malloc()/free() functions are thread safe (even in uClibc). I proved it to myself by looking at the back traces showing some internal locking functions called from within malloc()/free() (obviously this could also be inferred from the code). Once the memory is malloc-ed in one thread, there's no harm the other thread can do as there's no way malloc() can have internal structures corrupted from the other thread. The free() function is a different story. Although it is not possible to free memory simultaneously (corrupt allocator structures), it is possible to do it twice. Once per thread. This was my theory from the day one.

Tools

First thing to do is to throw some ready to use tools at the problem. Ideally I'd have looked at some reverse debugging tool, had I known at that time they existed for real. Recently someone I worked with referred me to UndoDB which I'd have at least evaluated, had I known about it and if it were available for MIPSEL (it's not as of the time of this writing). Most memory debugging tools have receded having their functionality taken over by Valgrind. As I was (un)lucky to observe the problem only on the MIPSEL platform, there was no chance to use it as it does not support MIPS(EL) and is not likely to support it in the near future. Another one is efence which is excellent in detecting memory corruption but it uses memory very intensively (every malloc() call results in at least two pages allocated due to the way it works). In my particular case the system was running out of memory when using efence.

It was time to get a grip and write my own rough and ready tool.

Let's crack on with it

The idea was to interpose malloc()/free() and their friends. Once they are interposed, I could put my own housekeeping information in allocated blocks to help analyse the cause of the crash. And even more, I could detect some conditions, e. g. double free() calls (thanks to Tish for the inspiration).

First of all I wanted to have some counter incremented on every free() call and once the non-zero value was detected I wanted it to abort immediately so I could analyse the state and the context. It was also useful to store some information (return address, thread ID) about the caller that malloc-ed the memory chunk and the caller that free-ed it.

To make easier finding my housekeeping information when examining memory, I wanted to put some magic and easy to spot values there. They would also serve as execution fences, i. e. with LSB set on a value interpreted as a function pointer, the call on many platforms would result in SIGBUS.

Implementation

I got to the final implementation in few iterations after making some mistakes. At least it might save someone's else time although getting through all these mistakes was enriching. The implementation is (intended to be) thread safe. Note that a naive use of mutexes here causes a lot of problems (atomic operations are used directly instead). Similarly calling printf()-like functions is not easy/possible as they call malloc()/free().

The intention of this implementation is to detect double free() call under the control of the debugger (similar to the way efence works). It is MIPSEL specific but it should be easy to adapt for other platforms. It's available here. Below I only present the gist of it.

template<class Fn>
Fn getNextFunction(char const* const name) {
  ::dlerror();
  if (void* const sym = ::dlsym(RTLD_NEXT, name)) {
    return reinterpret_cast<Fn>(sym);
  }
  
  ABORT_HERE;
}

void* malloc(size_t size) {
  size_t ra;
  asm volatile("move %0, $ra" : "=r" (ra)); // get the return address

  typedef void*(*fn_malloc_t)(size_t);
  static fn_malloc_t fn_malloc = getNextFunction<fn_malloc_t>("malloc");

  char* const ptr =
    static_cast<char*>(fn_malloc(sizeof(MallocInfo) +
    size +
    sizeof(MallocInfoBack)));

  if (!ptr) {
    return ptr;
  }

  const MallocInfo info = {
    { MAGIC1, MAGIC1, MAGIC1, MAGIC1 },
    ra, pthread_self(), 0u, 0u, size, 0u,
    { MAGIC2, MAGIC2, MAGIC2, MAGIC2 }
    };

  const MallocInfoBack infoBack = {
    { MAGIC3, MAGIC3, MAGIC3, MAGIC3 },
    pthread_self(), size,
    { MAGIC4, MAGIC4, MAGIC4, MAGIC4 }
  };

  *reinterpret_cast<MallocInfo*>(ptr) = info;
  *reinterpret_cast<MallocInfoBack*>(ptr + sizeof(MallocInfo) + size) =
    infoBack;

  return ptr + sizeof(MallocInfo);
}

void free(void* ptr) {
  size_t ra;
  asm volatile("move %0, $ra" : "=r" (ra)); // get the return address
  typedef void (*fn_free_t)(void*);
  static fn_free_t fn_free = getNextFunction<fn_free_t>("free");

  if (ptr) {
    ptr = static_cast<char*>(ptr) - sizeof(MallocInfo);
    MallocInfo* const mi = reinterpret_cast<MallocInfo*>(ptr);

    if (0 != __sync_fetch_and_add(&mi->freeCnt, 1)) {
      // this is it - someone alreade freed the memory

      // now these two bits of information are preserved in the global variables
      // as the compiler may (re)use registers and stack heavily and it's easier
      // to find out in the disassembly where these values are stored when they
      // are assigned to global variables
      gRaFree = mi->raFree;
      gTidTerminator = mi->tidTerminator;

      ABORT_HERE;
    }

    mi->raFree = ra;
    mi->tidTerminator = pthread_self();
  }

  fn_free(ptr);
}
To compile/build:
mipsel-linux-g++ \
  -shared -fPIC -O2 -o libkrismalloc.so \
  kris-malloc-mipsel.cpp -pthread -ldl
Now you can LD_PRELOAD it after transferring it onto the target system:
gdb \
  -ex "set exec-wrapper env LD_PRELOAD=/kris/libkrismalloc.so" \
  --args <app> <args>
You can also compile it into an object file and link it statically into your executable, although it's slightly less flexible.

Usage

Basically you need a bit of luck if the problem is strongly related to thread race conditions. You can make yourself luckier by reducing the test case to the very minimum and making it more thread intensive if possible. This will let you get to the crash point sooner so you can repeat attempts more often.

On my MIPSEL system I got something like this:

Program received signal SIGSEGV, Segmentation fault.
[Switching to Thread 0x42361520 (LWP 28702)]
0x2aac09d0 in free () from /kris/libkrismalloc.so
Lucky me. I did x/i $pc and got:
0x2aac09d0 <free+196>:  sw  zero,0(zero)
I was very lucky. I could examine the housekeeping information in the allocated block and it's still not clobbered.

How to examine preserved information? The argument passed to free() should be passed in the $a0 register due to MIPS(EL) calling convention. If you compile the interposing library with -O2, which is useful to keep the speed and to not affect the race conditions between threads, then you may be a wee bit less lucky. The $a0 register might get reused for something else and you need to look around in the disassembly for the register where the $a0 is copied to (it has to be copied if $a0 gets reused). In my case it used to be $s0 register with additional bonus of offsetting the memory block pointer to the housekeeping information. Hence I was examining it like this (I marked some elements with (1), (2), ... to comment on them later on):

(gdb) x/20xw $s0
0xbd96c8: (1) 0xaaaaaaaa     0xaaaaaaaa     0xaaaaaaaa     0xaaaaaaaa
0xbd96d8: (2) 0x2b566d84 (3) 0x2cf21520 (4) 0x2b6ae248 (5) 0x2cf21520
0xbd96e8: (6) 0x00000088 (7) 0x00000002 (8) 0xbbbbbbbb     0xbbbbbbbb
0xbd96f8:     0xbbbbbbbb     0xbbbbbbbb     0x00000000     0x00000000
0xbd9708:     0x0025002f     0x00450037     0x006c0066     0x00730061

##
# get the name of the function that originally freed the memory
# (note that I have release build with debug information)
#

(gdb) x/i 0x2b6ae248
0x2b6ae248 <operator delete(void *, unsigned int, const char *, int, struct {...} *)+120>:  lw  gp,16(s8)
A legend (memory interpretation according to the MallocInfo structure): (1) - MallocInfo begin marker (2) - the address of the caller that malloc-ed memory (3) - the thread ID of the caller that malloc-ed memory (4) - the address of the caller that originally free-ed memory (5) - the thread ID of the caller that originally free-ed memory (6) - the size of the allocated block (7) - free() calls counter (8) - MallocInfo end marker Moving forwards and backwards with memory examination you should also find the MallocInfoBack structure. It helps a lot if you are unlucky and some part of any housekeeping information gets clobbered.

The happy end

This method helped me to track the problem down to a std::string variable being not locked properly. Adding a lock on a mutex when accessing it solved the problem. The code base was large enough to make it impossible to find the problem by simple code inspection and adding to that thread unsafe use of this particular variable wasn't obvious from the code at a first glance. So having a nice crash and a right approach can set you right on the track.

No comments:

Post a Comment