Bug 757382 - libvirt occasionally has a failure and is non-operational afterwards
libvirt occasionally has a failure and is non-operational afterwards
Status: CLOSED ERRATA
Product: Fedora
Classification: Fedora
Component: libvirt (Show other bugs)
16
x86_64 Linux
unspecified Severity unspecified
: ---
: ---
Assigned To: Libvirt Maintainers
Fedora Extras Quality Assurance
:
Depends On:
Blocks:
  Show dependency treegraph
 
Reported: 2011-11-26 14:00 EST by Steven Dake
Modified: 2016-04-27 01:19 EDT (History)
11 users (show)

See Also:
Fixed In Version: libvirt-0.9.6-4.fc16
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2012-01-05 15:59:42 EST
Type: ---
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)

  None (edit)
Description Steven Dake 2011-11-26 14:00:51 EST
Description of problem:
Not exactly sure how to reproduce the problem.  I am doing quite a bit of heavy development that uses libvirt.  The libvirtd.log file prints out:

11:25:21.784: 24375: error : virNetServerDispatchNewClient:220 : Too many active clients (20), dropping connection from 127.0.0.1;0
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
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
11:25:23.935: 24375: error : virNetSocketReadWire:912 : End of file while reading data: Input/output error
11:25:41.648: 24375: error : virNetSocketReadWire:912 : End of file while reading data: Input/output error
11:25:41.648: 24375: error : virNetSocketReadWire:912 : End of file while reading data: Input/output error
11:25:41.648: 24375: error : virNetSocketReadWire:912 : End of file while reading data: Input/output error
11:25:41.648: 24375: error : virNetSocketReadWire:912 : End of file while reading data: Input/output error
11:25:41.648: 24375: error : virNetSocketReadWire:912 : End of file while reading data: Input/output error
11:25:41.648: 24375: error : virNetSocketReadWire:912 : End of file while reading data: Input/output error
11:25:41.648: 24375: error : virNetSocketReadWire:912 : End of file while reading data: Input/output error
11:25:41.648: 24375: error : virNetSocketReadWire:912 : End of file while reading data: Input/output error
11:25:41.655: 24375: error : virNetSocketReadWire:912 : End of file while reading data: Input/output error
11:25:41.656: 24375: error : virNetSocketReadWire:912 : End of file while reading data: Input/output error
11:25:41.656: 24375: error : virNetSocketReadWire:912 : End of file while reading data: Input/output error
11:25:41.656: 24375: error : virNetSocketReadWire:912 : End of file while reading data: Input/output error
11:33:39.736: 24375: error : virNetSocketReadWire:912 : End of file while reading data: Input/output error
11:33:39.736: 24375: error : virNetSocketReadWire:912 : End of file while reading data: Input/output error

A second process is spawned by libvirt as well:
root     22049 24375  0 11:49 ?        00:00:00 libvirtd --daemon
root     22353 22671  0 11:58 pts/4    00:00:00 grep --color=auto libvirt
root     24375     1  2 11:00 ?        00:01:40 libvirtd --daemon

kill -9 of the non-init parented libvirt unsticks the system ie:
[root@beast libvirt]# kill -9 22049

Then things start working again.


Version-Release number of selected component (if applicable):
[root@beast libvirt]# rpm -qa | grep libvirt
libvirt-0.9.6-2.fc16.x86_64
libvirt-python-0.9.6-2.fc16.x86_64
libvirt-client-0.9.6-2.fc16.x86_64


How reproducible:
hard to reproduce

Steps to Reproduce:
1. execute vm starts/stops 
2.
3.
  
Actual results:
libvirt launches a second process and wedges

Expected results:
libvirt should not wedge

Additional info:

killing the second process unwedges libvirt
Comment 1 Steven Dake 2011-11-28 18:08:25 EST
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.
Comment 2 Steven Dake 2011-11-28 18:10:51 EST
Notice the CPU time on the forked process is quite high.  This ps was taken ~1-2 minutes after the system wedged.
Comment 3 Steven Dake 2011-11-28 18:13:20 EST
ignore comment #2, the 2nd process in the list wasn't the forked child.
Comment 4 Laine Stump 2011-11-28 20:54:33 EST
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.
Comment 5 Steven Dake 2011-11-28 21:08:36 EST
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
Comment 6 Steven Dake 2011-11-28 21:28:31 EST
__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
Comment 7 Steven Dake 2011-11-28 21:33:06 EST
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.
Comment 8 Steven Dake 2011-11-28 21:35:22 EST
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
Comment 9 Steven Dake 2011-11-28 23:42:24 EST
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
Comment 10 Daniel Berrange 2011-11-29 03:41:35 EST
> 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().
Comment 11 Daniel Berrange 2011-11-29 03:42:20 EST
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.
Comment 12 Daniel Berrange 2011-11-29 04:12:26 EST
> 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.
Comment 13 Daniel Berrange 2011-11-29 07:40:01 EST
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
Comment 14 Steven Dake 2011-11-29 09:02:54 EST
Re Comment #11, I am no longer hittiing the limit on FDs after changing my program.  It is some other log message.
Comment 15 Steven Dake 2011-11-29 09:11:11 EST
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
Comment 16 Steven Dake 2011-11-29 22:41:11 EST
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
Comment 17 Fedora Admin XMLRPC Client 2011-11-30 14:33:34 EST
This package has changed ownership in the Fedora Package Database.  Reassigning to the new owner of this component.
Comment 18 Fedora Admin XMLRPC Client 2011-11-30 14:37:08 EST
This package has changed ownership in the Fedora Package Database.  Reassigning to the new owner of this component.
Comment 19 Fedora Admin XMLRPC Client 2011-11-30 14:44:41 EST
This package has changed ownership in the Fedora Package Database.  Reassigning to the new owner of this component.
Comment 20 Fedora Admin XMLRPC Client 2011-11-30 14:55:13 EST
This package has changed ownership in the Fedora Package Database.  Reassigning to the new owner of this component.
Comment 21 Eric Blake 2011-12-05 13:21:01 EST
We should backport the following patches to F16:

3ec12898
32d3ec74
a8bb75a3
b265beda
Comment 22 Fedora Update System 2011-12-19 21:08:51 EST
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
Comment 23 Fedora Update System 2011-12-22 17:34:58 EST
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).
Comment 24 Fedora Update System 2012-01-05 15:59:42 EST
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.

Note You need to log in before you can comment on or make changes to this bug.