twitter/twemproxy — pull request #231 by idning (2014-06-14 09:16:45+00:00)
Title: fix deadlock in sighandler

``localtime()`` used in ``_log()`` is not signal-safe.

if nutcracker run with a lot of log(``-v 5`` and heavy load) and use ``kill -HUP`` to reopen the logfile, nutcracker will dead lock with this:

Loaded symbols for /lib64/ld-linux-x86-64.so.2
__lll_lock_wait_private () at ../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:97
97 ../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S: No such file or directory.
in ../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S
(gdb) bt
#0 __lll_lock_wait_private () at ../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:97
#1 0x00007f0393918b2d in _L_lock_1934 () at tzset.c:138
#2 0x00007f03939188e7 in __tz_convert (timer=0x7f0393bfd9f4, use_localtime=1, tp=0x7f0393c00360) at tzset.c:619
#3 0x0000000000410fba in _log (file=0x431036 "nc_signal.c", line=122, panic=0, fmt=0x43101c "signal %d (%s) received%s") at nc_log.c:140
#4 0x000000000041016c in signal_handler (signo=) at nc_signal.c:122
#5

#6 0x00007f03939552d5 in *__GI___xstat (vers=, name=, buf=0x7fff2a266fc0) at ../sysdeps/unix/sysv/linux/wordsize-64/xstat.c:38
#7 0x00007f03939193f0 in __tzfile_read (file=0x7f03939c5b7c "/etc/localtime", extra=0, extrap=) at tzfile.c:173
#8 0x00007f03939187a4 in tzset_internal (always=, explicit=) at tzset.c:439
#9 0x00007f0393918909 in __tz_convert (timer=0x7fff2a267158, use_localtime=1, tp=0x7f0393c00360) at tzset.c:624
#10 0x0000000000410fba in _log (file=0x42ed0c "nc_server.c", line=645, panic=0, fmt=0x42ece0 "key '%.*s' on dist %d maps to server '%.*s'") at nc_log.c:140

#11 0x000000000040887e in server_pool_server (ctx=0x1c0e090, pool=0x1c0e360, key=0x1c150c2 "key:__rand_int__\r\n", keylen=16) at nc_server.c:644
#12 server_pool_conn (ctx=0x1c0e090, pool=0x1c0e360, key=0x1c150c2 "key:__rand_int__\r\n", keylen=16) at nc_server.c:668
#13 0x000000000040ae04 in req_forward (ctx=0x1c0e090, conn=0x1c14e70, msg=0x1c14f70, nmsg=) at nc_request.c:482
#14 req_recv_done (ctx=0x1c0e090, conn=0x1c14e70, msg=0x1c14f70, nmsg=) at nc_request.c:524
#15 0x0000000000409f00 in msg_parsed (ctx=0x1c0e090, conn=0x1c14e70) at nc_message.c:451
#16 msg_parse (ctx=0x1c0e090, conn=0x1c14e70) at nc_message.c:581
#17 msg_recv_chain (ctx=0x1c0e090, conn=0x1c14e70) at nc_message.c:642
#18 msg_recv (ctx=0x1c0e090, conn=0x1c14e70) at nc_message.c:681
#19 0x0000000000406179 in core_recv (arg=0x1c14e70, events=) at nc_core.c:158
#20 core_core (arg=0x1c14e70, events=) at nc_core.c:293
#21 0x000000000041bbb8 in event_wait (evb=0x1c0e570, timeout=) at nc_epoll.c:269
#22 0x0000000000405f89 in core_loop (ctx=0x1c0e090) at nc_core.c:316
#23 0x0000000000412a38 in nc_run (argc=, argv=0x7fff2a267690) at nc.c:531
#24 main (argc=, argv=0x7fff2a267690) at nc.c:580
(gdb)

this can reproduction with::

ning@ning-laptop /tmp/r/nutcracker-4000$ cat reopen.sh
pkill -HUP -f "^bin/nutcracker -c /tmp/r/nutcracker-4000/conf/nutcracker.conf -o /tmp/r/nutcracker-4000/log/nutcracker.log -p /tmp/r/nutcracker-4000/log/nutcracker.pid -s 5000" && ls -l log
ning@ning-laptop /tmp/r/nutcracker-4000$ for i in `seq 1 100` ; do sh reopen.sh && sleep 1 ; done ;

we should use signal-safe function in signal_handler.

redis has the same problem long time ago: https://github.com/antirez/redis/issues/213

the new logline of this patch:

signal SIGHUP received, reopening log file