Not sure if too many active clients error from log is related to the second process being spawned.  They may be separate events.  I have changed my program behavior not to use so many sockets, but occasionally the software still wedges.

Notice the CPU time on the forked process is quite high.  This ps was taken ~1-2 minutes after the system wedged.

ignore comment #2, the 2nd process in the list wasn't the forked child.

When this happens could you try attaching gdb to the 2nd libvirtd process and executing the command "thread apply all bt"? That will give us more of a clue what is (isn't) happening.

Laine,

Next time it happens, I'll do that for you.  I noticed there often appears a dmidecode error when this occurs which is documented in Bug #754909.  I am going to try running with dmidecode installed to see if that eliminates the problem.  Fedora 16 does not by default install dmidecode.

Regards
-steve

__lll_lock_wait_private ()
    at ../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:96
96	2:	movl	%edx, %eax
(gdb) thread apply all bt
Thread 1 (Thread 0x7f8b9e029700 (LWP 5904)):
#0  __lll_lock_wait_private ()
    at ../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:96
#1  0x00000031246ad2d4 in _L_lock_2197 () from /lib64/libc.so.6
#2  0x00000031246ad0e7 in __tz_convert (timer=0x31249b0ee8, use_localtime=1, 
    tp=0x7f8b9e027910) at tzset.c:619
#3  0x0000003e90c5552f in virLogMessage (
    category=0x3e90de9fea "file.util/command.c", priority=1, 
    funcname=0x3e90deac33 "virCommandHook", linenr=1962, flags=0, 
    fmt=<optimized out>) at util/logging.c:734
#4  0x0000003e90c45cce in virCommandHook (data=0x7f8b880c3280)
    at util/command.c:1962
#5  0x0000003e90c466cc in virExecWithHook (argv=0x7f8b88071920, 
    envp=0x7f8b880c08a0, keepfd=<optimized out>, retpid=<optimized out>, 
    infd=27, outfd=0x7f8b880c33e8, errfd=0x7f8b880c33ec, flags=4, 
    data=0x7f8b880c3280, pidfile=0x0, hook=0x3e90c45a10 <virCommandHook>)
    at util/command.c:527
#6  0x0000003e90c482cc in virCommandRunAsync (cmd=0x7f8b880c3280, pid=0x0)
    at util/command.c:2046
#7  0x0000003e90c48acc in virCommandRun (cmd=0x7f8b880c3280, exitstatus=0x0)
    at util/command.c:1841
#8  0x0000000000465d92 in qemuCapsExtractVersionInfo (

    qemu=0x7f8b880c0e90 "/usr/bin/qemu", arch=0x4f9db6 "i686", retversion=0x0, 
    retflags=0x7f8b9e028448) at qemu/qemu_capabilities.c:1297
#9  0x00000000004665ed in qemuCapsInitGuest (caps=0x7f8b880c1b10, 
    old_caps=0x7f8b8c000a70, hostmachine=<optimized out>, info=0x733440, hvm=1)
    at qemu/qemu_capabilities.c:592
#10 0x0000000000466e09 in qemuCapsInit (old_caps=0x7f8b8c000a70)
    at qemu/qemu_capabilities.c:846
#11 0x000000000044c8a0 in qemuCreateCapabilities (oldcaps=<optimized out>, 
    driver=0x7f8b940146b0) at qemu/qemu_driver.c:242
#12 0x000000000045fb86 in qemudGetCapabilities (conn=<optimized out>)
    at qemu/qemu_driver.c:1004
#13 0x0000003e90cc835e in virConnectGetCapabilities (conn=0x7f8b84000b60)
    at libvirt.c:5877
#14 0x0000000000434ea3 in remoteDispatchGetCapabilities (ret=0x7f8b880adbf0, 
    rerr=0x7f8b9e028c70, hdr=<optimized out>, client=0x1834970, 
    server=<optimized out>) at remote_dispatch.h:5555
#15 remoteDispatchGetCapabilitiesHelper (server=<optimized out>, 
    client=0x1834970, hdr=<optimized out>, rerr=0x7f8b9e028c70, 
    args=<optimized out>, ret=0x7f8b880adbf0) at remote_dispatch.h:5536
#16 0x000000000043f42e in virNetServerProgramDispatchCall (msg=0x1877430, 
    client=0x1834970, server=0x182c410, prog=0x182c3e0)
    at rpc/virnetserverprogram.c:401
#17 virNetServerProgramDispatch (prog=0x182c3e0, server=0x182c410, 

#18 0x000000000044169c in virNetServerHandleJob (jobOpaque=<optimized out>, 
    opaque=0x182c410) at rpc/virnetserver.c:136
#19 0x0000003e90c65eae in virThreadPoolWorker (opaque=<optimized out>)
    at util/threadpool.c:144
#20 0x0000003e90c65962 in virThreadHelper (data=<optimized out>)
    at util/threads-pthread.c:157
#21 0x0000003124a07d90 in start_thread (arg=0x7f8b9e029700)
    at pthread_create.c:309
#22 0x00000031246eed8d in clone ()
    at ../sysdeps/unix/sysv/linux/x86_64/clone.S:115

FYI, been down this path with the glibc maintainers.  Their claim is that localtime_r while reentrant cannot be used in threaded programs, because it is not thread safe according to POSIX.

See:
http://oss.clusterlabs.org/pipermail/pacemaker/2010-February/004710.html

Which explains the problem in more detail.  Perhaps my memory is fuzzy, it was getenv/setenv that may not be used in multithreaded programs at all (you are probably getenv in one program thread, forking, then localtime_r in another), and hence their use (which I see libvirt uses alot of) can and will result in deadlocks.

Regards
-steve

See Bug #544022 which helped work around part of this problem.  I'm not sure if it entirely resolved it - eventually we just reworked our code to remove threads entirely.

Regards
-steve

> 11:25:21.784: 24375: error : virNetServerDispatchNewClient:220 : Too many
> active clients (20), dropping connection from 127.0.0.1;0

This is the interesting error message. When this occurs, libvirtd will immediately close the client socket. 

> 11:25:23.926: 24375: error : virNetSocketReadWire:912 : End of file while
> reading data: Input/output error
> 11:25:23.926: 24375: error : virNetSocketReadWire:912 : End of file while
> reading data: Input/output error
> 11:25:23.926: 24375: error : virNetSocketReadWire:912 : End of file while
> reading data: Input/output error

This suggests, after closing the client socket, we have left a I/O watch  registered against the socket FD, and are now spinning 100% in poll().

To avoid hitting this problem in the first place you can simply update max_clients in /etc/libvirt/libvirtd.conf.

Of course we still want to fix the resulting bug.

> FYI, been down this path with the glibc maintainers.  Their claim is that
> localtime_r while reentrant cannot be used in threaded programs, because it is
> not thread safe according to POSIX.

IIUC the issue here is not one of "thread safety", but rather whether the function is "async signal safe".

If you have a multi-threaded application, and you fork a child process, then you are only allowed to use async-signal safe functions, until you execve(). The reason is as you describe

 1. Thread A acquires lock L
 2. Thread B forks process process C
 3. Child process C attempts to acquire lock L
 4. Thread A releases lock L

....child process C can never see results of step 4, since it is no longer in the same memory address space as Thread A.

Unfortunately libvirt is not complying for the async signal safety rules here.

This series upstream improves libvirt's async signal safety by avoiding localtime_r() completely

https://www.redhat.com/archives/libvir-list/2011-November/msg01609.html

Re Comment #11, I am no longer hittiing the limit on FDs after changing my program.  It is some other log message.

Daniel,

Thanks for a pointer to the upstream fixes.  I'll apply them on the fedora 16 rpm, build a scratch rpm, and see if that fixes the problem.

As I recall, what happened in our case was both the localtime_r problem you describe as well as the following:

getenv/setenv take a lock in the timezone code (I am not sure why it does this, read the glibc code for more details).
another thread forks (with the timezeone thread locked)
getenv/setenv do not have at_fork handlers for getenv/setenv leaving the lock locked in the child process.
getlocaltime_r takes lock and deadlocks (because it uses the same tzget lock)

Regards
-steve

Daniel,

I applied the patches and rebuilt a libvirt from git.  The lockup seems to no longer occur.  Not sure if its the patches or a change in libvirt 0.9.7.  I couldn't get the older libvirt to build/patches backported in a timely manner.  thanks for the quick response.

Regards
-steve

This package has changed ownership in the Fedora Package Database.  Reassigning to the new owner of this component.

This package has changed ownership in the Fedora Package Database.  Reassigning to the new owner of this component.

This package has changed ownership in the Fedora Package Database.  Reassigning to the new owner of this component.

This package has changed ownership in the Fedora Package Database.  Reassigning to the new owner of this component.

We should backport the following patches to F16:

3ec12898
32d3ec74
a8bb75a3
b265beda

libvirt-0.9.6-4.fc16 has been submitted as an update for Fedora 16.
https://admin.fedoraproject.org/updates/libvirt-0.9.6-4.fc16

Package libvirt-0.9.6-4.fc16:
* should fix your issue,
* was pushed to the Fedora 16 testing repository,
* should be available at your local mirror within two days.
Update it with:
# su -c 'yum update --enablerepo=updates-testing libvirt-0.9.6-4.fc16'
as soon as you are able to.
Please go to the following url:
https://admin.fedoraproject.org/updates/FEDORA-2011-17267/libvirt-0.9.6-4.fc16
then log in and leave karma (feedback).

libvirt-0.9.6-4.fc16 has been pushed to the Fedora 16 stable repository.  If problems still persist, please make note of it in this bug report.