I think I've finally figured out what's going on with my bacula-sd
hangs. At the risk of repeating myself, this post is adapted from
the bug report I've just filed.
Here's the situation: with the latest Bacula release (5.0.1), I
regularly see bacula-sd hang when running jobs; it happens often and
at seemingly random times; and when this happens, I see two bacula
processes, a parent and a child. (Since bacula is multi-threaded, I
usually just see one storage daemon process.) This came to my
attention when I came back from vacation to find a week's worth of
backups stalled (sigh).
When bacula-sd hangs, the traceback of the relevant thread in the
parent process's looks like this:
Thread 10 (Thread 0x466c0940 (LWP 12926)):
#0 0x00000035aa4c5f3b in read () from /lib64/libc.so.6
#1 0x00000035aa46cc07 in _IO_new_file_underflow (fp=<value optimized out>) at fileops.c:590
#2 0x00000035aa46d5ce in _IO_default_uflow (fp=<value optimized out>) at genops.c:435
#3 0x00000035aa468e8b in _IO_getc (fp=<value optimized out>) at getc.c:41
#4 0x00002b76479565c0 in bfgets (s=0x466bf710 "", size=<value optimized out>, fd=0x60080a0) at bsys.c:617
#5 0x000000000040d432 in release_device (dcr=0x60988b8) at acquire.c:533
[snip]
Here, bacula's storage daemon has just finished running a job, and
before it releases the tape drive to someone else runs the "Alert"
command. This is specified in the config file for the storage daemon,
and is meant to see if the drive has, say, run out of magnetism during
the last job. Here's the source code in stored/acquire.c:
alert = get_pool_memory(PM_FNAME);
alert = edit_device_codes(dcr, alert, dcr->device->alert_command, "");
bpipe = open_bpipe(alert, 0, "r");
if (bpipe) {
while (fgets(line, sizeof(line), bpipe->rfd)) { /* AardvarkNote: This is where the parent hangs */
Jmsg(jcr, M_ALERT, 0, _("Alert: %s"), line);
}
status = close_bpipe(bpipe);
}
Meanwhile, the child process stack looks like this:
Thread 1 (Thread 0x466c0940 (LWP 13000)):
#0 0x00000035aa4df9ee in __lll_lock_wait_private () from /lib64/libc.so.6
#1 0x00000035aa4d06a5 in _L_lock_1206 () from /lib64/libc.so.6
#2 0x00000035aa4d05be in closelog () at ../misc/syslog.c:419
#3 0x00002b764795cd35 in open_bpipe (prog=<value optimized out>, wait=0, mode=<value optimized out>) at bpipe.c:138
#4 0x000000000040d3f1 in release_device (dcr=0x60988b8) at acquire.c:531
[snip]
open_bpipe() can be found in lib/bpipe.c; it's a routine for forking
a child process (FORESHADOWING: not another thread!) and sets up a
pipe between parent and child. The relevant bits look like this:
/* Start worker process */
switch (bpipe->worker_pid = fork()) {
[snip]
case 0: /* child */
if (mode_write) {
close(writep[1]);
dup2(writep[0], 0); /* Dup our write to his stdin */
}
if (mode_read) {
close(readp[0]); /* Close unused child fds */
dup2(readp[1], 1); /* dup our read to his stdout */
dup2(readp[1], 2); /* and his stderr */
}
/* AardvarkNote: This is where the child hangs: */
closelog(); /* close syslog if open */
for (i=3; i<=32; i++) { /* close any open file descriptors */
close(i);
}
execvp(bargv[0], bargv); /* call the program */
closelog() itself is simple: it "closes the current Syslog
connection, if there is one." But running strace on the child
process just shows a lot of futex calls...nothing very useful there
at all. So what the hell is going on, and why it hanging at
closelog()?
Some background info on threads: In Linux at least, they're user-land
things, and the kernel doesn't know about them. To the kernel, it's
just another process with a PID. Implementing threads is left as an
exercise to the reader...or in this case, to glibc and NPTL.
Since threads are part of the same process, they share memory. (A
fork(), by contrast, copies over parent memory to the child -- and
then the child has its own copy of everything, separate from the
parent.) glibc/NPTL implements locks for certain things to make sure
that one thread doesn't stomp all over another thread's memory
willy-nilly. And those locks are done with futexes, which are
provided by the kernel...which explains why it would show up in
strace, which tracks system calls.
Why is this relevant? Because in the glibc code, closelog() looks
like this:
void
closelog ()
{
/* Protect against multiple users and cancellation. */
__libc_cleanup_push (cancel_handler, NULL);
__libc_lock_lock (syslog_lock); /* AardvarkNote: This is where things hang */
closelog_internal ();
LogTag = NULL;
LogType = SOCK_DGRAM; /* this is the default */
/* Free the lock. */
__libc_cleanup_pop (1);
}
That __libc_lock_lock (syslog_lock) call is there to prevent two
threads trying to mess with the syslog file handle at one time. Sure
enough, the info for frame #2 of the child process shows that the
process is trying to get the syslog_lock mutex:
#2 0x00000035aa4d05be in closelog () at ../misc/syslog.c:419
419 __libc_lock_lock (syslog_lock);
ignore1 = <value optimized out>
ignore2 = <value optimized out>
ignore3 = <value optimized out>
As noted in the mailing list discussion, closelog() should be a noop
if there's no descriptor open to syslog. However, in my case there
is such a file descriptor, because I've got bacula-sd configured to
log to syslog.
Well, as the Bible notes, mixing fork() and threading is
problematic:
There are at least two serious problems with the semantics of fork() in
a multi-threaded program. One problem has to do with state (for
example, memory) covered by mutexes. Consider the case where one
thread has a mutex locked and the state covered by that mutex is
inconsistent while another thread calls fork(). In the child, the
mutex is in the locked state (locked by a nonexistent thread and thus
can never be unlocked). Having the child simply reinitialize the mutex
is unsatisfactory since this approach does not resolve the question
about how to correct or otherwise deal with the inconsistent state in
the child.
And hey, doesn't that sound familiar?
Now that I had an idea of what was going on, I was able to find a
number of similar problems that people have encountered:
This post describes a multi-threaded app that hung when a signal was
received during a syslog() call
This thread from the libc-alpha mailing list, describes a
similar problem:
The particular problem I'm seeing is with syslog_lock.
If another thread is writing to syslog when the fork happens,
the syslog_lock mutex is cloned in a locked state.
This Debian bug describes a multithreaded app deadlocking when
syslog() is called after a fork()
The Bible describes the POSIX-ish way around this, the pthread_atfork()
call.
This blog entry has an overview of the problem with threads and
fork(), and of pthread_atfork()
So: what seems to be happening is that, when the stars align, the
child process is being created at the same moment that the parent
process is logging to syslog. The child is created with a locked
syslog_lock mutex, but without the thread that had been holding
it...and thus, without anything that can release it. The child
blocks waiting for the mutex, the parent blocks on the child, and
backup jobs halt (well, at least the spooling of jobs to tape) until I
kill the child manually.
This was complicated to find for a number of reasons:
My gut feeling (see also: handwavy assertion) is that logging to
syslog is relatively unusual, which would explain why this problem
has taken a while to surface.
It's a race condition that's exacerbated by having multiple jobs
running at once; I'd only recently implemented this in my Bacula
setup.
btraceback, a shell wrapper around gdb that comes with
Bacula, is meant to run the debugger on a hung Bacula process. I
used it to get the tracebacks shown above. It's great if you don't
know what you're doing with gdb (and I certainly don't!). But it
has a number of problems.
In my setup, bacula-sd ran as root; however, for reasons I don't
fully understand, btraceback is usually called by the unprivileged
bacula user. That meant I had to modify the script to run gdb with
sudo, and change sudoers to allow bacula to run "sudo gdb" without a
password. Otherwise, the dump was useless -- particularly
frustrating before I'd figured out how to duplicate the problem.
btraceback can be triggered by sending a fatal signal to the
bacula-sd process (say, "kill -6"). That's great when you notice a
hang and can run the script. But it won't trace child processes --
which was where the interesting things were -- and it was a while
before it occured to me to do that manually.
Bacula has an --enable-lockmgr option that's meant to catch
deadlocks, kill itself and run btraceback. However, it's not
enabled by default in the SRPMs I was using to build bacula, and in
any case it watches for deadlocks on Bacula's own locks -- not
external locks like syslog_lock.
So what to do?
For now, I'm removing the log-to-syslog option from bacula-sd.conf.
When I do that, I see no problems at all running jobs.
On the programming side -- and keep in mind I'm no programmer -- it
looks like there are a number of options here:
Don't call closelog() after fork() in open_bpipe(). This may
leave an open descriptor to syslog, which may be a problem. (Or maybe
it's just ugly. Don't know.)
Don't fork() a child process when running the alert command, but
start another thread instead. I have no idea why a fork() is
preferred over a new thread in this scenario, but I presume there's a
good reason.
Use pthread_atfork() to set things up for a fork(). That's
what The Bible says to do, but I don't know what Bacula would
actually need to do with it in order to make this deadlock go away.
Good lord, I'm closing in on 1700 words here. If you've stuck with me
this long, I hope it was interesting; once I got over the panic it was
a fascinating problem, and it's taught me a lot about processes,
threads and deadlocks. And how can that be a bad thing?
