fork() and syslog() locks each other. How to avoid?

["Peter Volkov (pva)" <pva at gentoo dot org>]

Hello.

I've encounter problem with rather known daemon arpwatch. Sometimes it
freeze and strace shows that it waits for mutex:

# strace -p 18153
Process 18153 attached - interrupt to quit
futex(0xb7ede120, FUTEX_WAIT, 2, NULL

I've investigated the problem and while I found the reason for lock I
need suggestion on how to fix the problem. If this is the wrong list to
discuss such things, please, point me to the right one.

*** Short version (which may be less understandable):
arpwatch register reaper() callback function with sigaction on SIGCHLD.
From time to time this callback interrupts fork() function. In this case
syslog() call in reaper function locks the process. What is the right
way to avoid?

*** Long version:
arpwatch sends notifications by mail and to do this it creates child
process which just executes sendmail and exits. To avoid zombies it
register "RETSIGTYPE reaper(int signo);" function with

sigaction( SIGCHLD, &new, &old);

So every time child process exits reaper function calls 

waitpid((pid_t)0, &status, WNOHANG);

and in cycle cleans all zombies and reports about this with syslog.

Now back to the problem. So I've ran the program in gdb and reproduced
lock. Take a look at backtrace:

#0  0xffffe410 in __kernel_vsyscall ()
#1  0xb7f28cfe in __lll_mutex_lock_wait () from /lib/libc.so.6
#2  0xb7ec9391 in _L_mutex_lock_10426 () from /lib/libc.so.6
#3  0xb7eb85ba in _IO_seekoff_unlocked (fp=0xb7f28cfe, offset=-5190468990828281809, dir=-1208495840,
    mode=136020272) at ioseekoff.c:71
#4  0xb7ebdd78 in _IO_mem_finish (fp=0x81b8130, dummy=0) at memstream.c:132
#5  0xb7eb617a in _IO_new_fclose (fp=0x81b8130) at iofclose.c:66
#6  0xb7f199aa in *__GI___vsyslog_chk (pri=7, flag=-1, fmt=0x804d97a "reaper: pid %d", ap=0xbfe8d298 "d\f")
    at ../misc/syslog.c:228
#7  0xb7f19dfb in __syslog (pri=7, fmt=0x804d97a "reaper: pid %d") at ../misc/syslog.c:119
#8  0x0804ce94 in reaper (signo=17) at ./report.c:214
#9  <signal handler called>
#10 0xffffe410 in __kernel_vsyscall ()
#11 0xb7eec3f9 in __libc_fork () at ../nptl/sysdeps/unix/sysv/linux/i386/../fork.c:127
#12 0x0804c889 in report (title=0x804d4fc "new station", a=1418856970, e1=0x818f218 "", e2=0x0,
    t1p=0xbfe8d818, t2p=0x0, interface=0xbfe8e632 "eth0") at ./report.c:286
#13 0x0804b69f in ent_add (a=1418856970, e=0x818f218 "", t=1159013662, h=0x0, interface=0xbfe8e632 "eth0")
    at ./db.c:121
#14 0x0804a3f2 in process_ether (u=0x0, h=0xbfe8d8a8, p=0x818f212 "") at ./arpwatch.c:506
#15 0xb7f9283e in pcap_read_linux (handle=0x818f008, max_packets=0, callback=0x804a220 <process_ether>,
    user=0x0) at ./pcap-linux.c:702
#16 0xb7f9343b in pcap_loop (p=0x818f008, cnt=0, callback=0x804a220 <process_ether>, user=0x0)
    at ./pcap.c:107
#17 0x0804abd7 in main (argc=6, argv=0xbfe8daf4) at ./arpwatch.c:427

So if I understood this backtrace correctly #12 arpwatch call fork() to
create child process and (#10) this request was passed to the kernel. At
this time previous child process finished and generates SIGCHLD which in
turn calls reaper function #8. Execution continues there and reaper
function called syslog... then some subsequent calls in glibc and #1
__mutex_lock_wait in kernel, locks the process.

I did not checked but seems that fork function takes mutex which syslog
will waits for it. If I'm right then the question is what is the right
way to avoid such situations but to keep program behavior?

Thank you for your time,
Peter.

Attachment: signature.asc
Description: This is a digitally signed message part