Trond Norbye's Weblog

Debugging memcached UDF for MySQL

I got an email yesterday about a user experiencing problems when using memcached UDF for MySQL, so today I spent some time trying to recreate the problem. It turned out that the bug was caused by using uninitialized memory, so I guessed it could be a good blog documenting how I found it...

The first thing I did was to compile and install libmemcached and the udf:

trond@opensolaris> ./config/bootstrap
trond@opensolaris> ./configure --prefix=/opt/memcached --enable-dependency-tracking --enable-debug --without-memcached
trond@opensolaris> gmake all install
trond@opensolaris> ./config/bootstrap
trond@opensolaris> ./configure --prefix=/opt/memcached --with-mysql=/usr/mysql/bin/mysql_config --with-libmemcached=/opt/memcached CFLAGS=-g
trond@opensolaris> gmake all install

The next thing to do is to instruct MySQL to look in /opt/memcached/lib for dynamic libraries by adding the following line in my.cfg (trond@opensolaris> pfexec vi /etc/mysql/my.cfg):

plugin_dir=/opt/memcached/lib

I wanted to use libumem.so to do memory checking in MySQL/libmemcached/UDFs, and the easiest way to do this is to just replace the mysql binary with the following script:

trond@opensolaris> cd /usr/mysql/bin
trond@opensolaris> pfexec mv mysqld mysqld.bin
trond@opensolaris> cat /tmp/mysqld
#! /bin/ksh
export UMEM_DEBUG=default
export UMEM_LOGGING=transaction
export LD_PRELOAD=libumem.so
exec /usr/mysql/bin/mysqld.bin --skip-stack-trace "$@"
trond@opensolaris> mv /tmp/mysqld .
trond@opensolaris> chmod +x mysqld

So let's start MySQL and verify that it use libumem and locate the current directory (so we now where to look for the corefiles).

trond@opensolaris> svcadm enable mysql
trond@opensolaris> pfexec pldd `pgrep -x mysqld.bin`
8790:   /usr/mysql/bin/mysqld.bin --skip-stack-trace --user=mysql --datadir=/v
/lib/libumem.so.1
/usr/lib/libmtmalloc.so.1
/usr/lib/libCrun.so.1
/lib/librt.so.1
/lib/libz.so.1
/lib/libdl.so.1
/lib/libpthread.so.1
/lib/libthread.so.1
/lib/libgen.so.1
/lib/libsocket.so.1
/lib/libnsl.so.1
/lib/libm.so.2
/usr/lib/libCstd.so.1
/usr/lib/libc/libc_hwcap1.so.1
trond@opensolaris> pfexec pwdx `pgrep -x mysqld.bin`
8790:   /var/mysql/5.0/data

So let's install the UDFs:

trond@opensolaris> /usr/mysql/bin/mysql -u root < install_functions.sql
trond@opensolaris> /usr/mysql/bin/mysql -u root
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 2
Server version: 5.0.67 Source distribution

Type 'help;' or '\h' for help. Type '\c' to clear the buffer.

mysql> select memc_servers_set('localhost:11211');
mysql> select memc_get("foobar");
ERROR 2006 (HY000): MySQL server has gone away

So the server went away? I guessed it dumped core, so let's look for a corefile:

trond@opensolaris> pfexec su -
root@razor:/var/mysql/data# ls -l 
total 81452
-rw------- 1 mysql mysql 62261434 2009-03-27 20:44 core.mysqld.bin.8790
-rw-rw---- 1 mysql mysql 10485760 2009-03-27 20:38 ibdata1
-rw-rw---- 1 mysql mysql  5242880 2009-03-27 20:44 ib_logfile0
-rw-rw---- 1 mysql mysql  5242880 2009-02-16 10:58 ib_logfile1
drwx------ 2 mysql mysql       53 2009-02-16 10:58 mysql
-rw-rw---- 1 mysql mysql        5 2009-03-27 20:44 razor.pid
drwx------ 2 mysql mysql      125 2009-02-16 11:24 test

So let's start debugging the corefile to try to figure out what happened:

root@razor:/var/mysql/data# dbx - core.mysqld.bin.8790 
Corefile specified executable: "/usr/mysql/5.0/bin/mysqld.bin"
For information about new features see `help changes'
Reading mysqld.bin
core file header read successfully
Reading ld.so.1
Reading libumem.so.1
Reading libmtmalloc.so.1
Reading libCrun.so.1
Reading librt.so.1
Reading libz.so.1
Reading libdl.so.1
Reading libpthread.so.1
Reading libthread.so.1
Reading libgen.so.1
Reading libsocket.so.1
Reading libnsl.so.1
Reading libm.so.2
Reading libCstd.so.1
Reading libc.so.1
Reading libmemcached_functions_mysql.so.0.0.0
Reading libmemcached.so.2.0.0
Reading libscf.so.1
Reading libuutil.so.1
Reading libmd.so.1
Reading libmp.so.2
t@13 (l@13) terminated by signal SEGV (no mapping at the fault address)
Current function is memcached_quit_server
   14     if (ptr->fd != -1)

It seems that the pointer is invalid, so let's take a look at it:

(dbx) print ptr
ptr = 0xbaddcafe

If you look at the documentation for libumem, it will write the pattern 0xbaddcafe when you allocate memory, and 0xdeadbeef when you free memory. To me this sounds like we are using uninitialized memory. Let's take a look at the callstack:

(dbx) where
current thread: t@13
=>[1] memcached_quit_server(ptr = 0xbaddcafe, io_death = '\0'), line 14 in "memcached_quit.c"
  [2] memcached_quit(ptr = 0x9e2d450), line 65 in "memcached_quit.c"
  [3] memcached_free(ptr = 0x9e2d450), line 41 in "memcached.c"
  [4] memc_get_deinit(initid = 0x8963edc), line 82 in "get.c"
  [5] Item_udf_func::cleanup(0x8963e40, 0x1, 0x871f2b9, 0x822958e), at 0x81bbfa4 
  [6] THD::cleanup_after_query(0x9e34008, 0x9e34008, 0x8963d18, 0x19), at 0x82295f3 
  [7] dispatch_command(0x3, 0x9e34008, 0x9e41589, 0x1a), at 0x825ab32 
  [8] handle_one_connection(0x9e34008, 0xce76f000, 0xce4fefec, 0xce6dca5e), at 0x8256f96 
  [9] _thrp_setup(0xce804a00), at 0xce6dca96 
  [10] _lwp_start(0xcdc8eaff, 0xce6d540a, 0x40, 0x64, 0x40, 0xce804a00), at 0xce6dcd20 

I think we should start to look at frame 4 (frame 1, 2, 3 is inside libmemcached, but frame 4 is the first "external" call to libmemcached):

(dbx) frame 4
Current function is memc_get_deinit
   82     memcached_free(&container->memc);
(dbx) print container
container = 0x9e2d448
(dbx) examine container/10
0x09e2d448:      0xbaddcafe 0xbaddcafe 0xbaddcafe 0xbaddcafe
0x09e2d458:      0xbaddcafe 0xbaddcafe 0xbaddcafe 0xbaddcafe
0x09e2d468:      0xbaddcafe 0xbaddcafe

It looks like the complete container-structure isn't initialized at all. Luckily we can find out where it was allocated:

root@razor:/var/mysql/data# mdb core.mysqld.bin.8790 
Loading modules: [ libumem.so.1 libuutil.so.1 ld.so.1 ]
> $G
C++ symbol demangling enabled
> ::umalog

T-0.000000000  addr=9e2d440  umem_alloc_896
         libumem.so.1`umem_cache_alloc_debug+0x144
         libumem.so.1`umem_cache_alloc+0x19a
         libumem.so.1`umem_alloc+0xcd
         libumem.so.1`malloc+0x2a
         libmemcached_functions_mysql.so.0.0.0`memc_get_init+0x73
         bool udf_handler::fix_fields+0x66c
         bool Item_udf_func::fix_fields+0x2a
         bool setup_fields+0xe8
         int JOIN::prepare+0x1e0
         bool mysql_select+0x33e
         bool handle_select+0xf7
         int mysql_execute_command+0x4ac3
         bool dispatch_command+0x2b9b
         handle_one_connection+0x516
         libc_hwcap1.so.1`_thrp_setup+0x7e
[ ... cut ... ]

Luckily for us this was the most recent memory allocation (you might have to search a loooong list to find the allocation you looked for), and we can see that the allocation came from memc_get_init. It was pretty easy to spot the allocation, since there is only one in the function:

  [... cut ...]
  container= (memc_function_st *)malloc(sizeof(memc_function_st));
  rc= memc_get_servers(&container->memc);
  memcached_result_create(&container->memc, &container->results);
  initid->ptr= (char *)container;
  return 0;
}

Here we spot bug number 1.. we don't check the return value from memc_get_server, and if you read on you will see that it is what happens. So let's look at the function memc_get_servers:

int memc_get_servers(memcached_st *clone)
{
  int retval;
  memcached_st *test;

  pthread_mutex_lock(&memc_servers_mutex);
  test= memcached_clone(clone, master_memc);
  pthread_mutex_unlock(&memc_servers_mutex);
  retval= test ? 1 : 0;

  return retval ;
}

This seems correct enough, but let's look at the memcached_clone function?

memcached_st *memcached_clone(memcached_st *clone, memcached_st *source)
{
  memcached_return rc= MEMCACHED_SUCCESS;
  memcached_st *new_clone;

  if (source == NULL)
    return memcached_create(clone);

  if (clone && clone->is_allocated)
  {
    return NULL;
  }
[ ... cut ... ]

Now here is something interesting. We check the member is_allocated in the clone if we should abort the cloning process. Remember that we pass in a memory chunk we allocated with malloc, so we don't know the value of this (==> undefined behavior). We do return the "error" to the caller, but the caller doesn't check the return code resulting in the fact that we have a structure of uninitialized memory (and all use of it will be "undefined").

The manual section for memcached_clone isn't clear on the above fact, so I am going to update the documentation. It is not difficult to fix the source, just replace the call to (memc_function_st *)malloc(sizeof(memc_function_st)) with calloc(1, sizeof(memc_function_st)) (no need for the cast there).. I'll be pushing a patch to the author of the UDFs .

Posted at 10:02PM Mar 27, 2009 by trond in Memcached  |  Comments[3]