11:10 a.m.
Hi !
I'm submitting my messages on this mailing list to request a bit of
help on a case that I have
where a Python application makes a call to virDomainIsActive, and the
call never returns.
I have tried to investigate, but as there are no debug symbols for
libvirt on Debian Stretch,
i can only have the following GDB backtrace:
(gdb) bt
#0 pthread_cond_wait@(a)GLIBC_2.3.2 () at
../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
#1 0x00007f49026f5b76 in virCondWait () from /usr/lib/libvirt.so.0
#2 0x00007f4902808bab in ?? () from /usr/lib/libvirt.so.0
#3 0x00007f490280a433 in virNetClientSendWithReply () from
/usr/lib/libvirt.so.0
#4 0x00007f490280abe2 in virNetClientProgramCall () from /usr/lib/libvirt.so.0
#5 0x00007f49027e0ea4 in ?? () from /usr/lib/libvirt.so.0
#6 0x00007f49027ea1bb in ?? () from /usr/lib/libvirt.so.0
#7 0x00007f49027b0ef3 in virDomainIsActive () from /usr/lib/libvirt.so.0
#8 0x00007f4902b7fbd0 in libvirt_virDomainIsActive () from
/usr/lib/python3/dist-packages/libvirtmod.cpython-35m-x86_64-linux-gnu.so
#9 0x0000558eeec696df in PyCFunction_Call () at ../Objects/methodobject.c:109
The libvirt driver used is QEMU, and i have a specific monitoring in
place using virtual machine introspection:
https://github.com/KVM-VMI/kvm-vmi
Now this specific monitoring somehow triggers this bug, and at this
point, i don't know if
it's a corner case in the libvirt QEMU driver or not.
That's why i would like to have your lights on this.
libvirt version: 3.0.0-4
-> Could you tell me where i should look in the code ?
-> Do you have more information about this virCondWait ? Which
condition is it waiting for ?
-> How can i get the symbols without having the recompile libvirt and
install it system wide, erasing the binaries installed by the package
?
Best regards,
--
Mathieu Tarral
12:20 p.m.
Hi,
On Thursday, 22 March 2018 17:10:49 CET Mathieu Tarral wrote:
I have tried to investigate, but as there are no debug symbols for
libvirt on Debian Stretch,
Yes there are: Stretch started the migration to automatically generated
packages with debug symbols -- see:
https://wiki.debian.org/AutomaticDebugPackages
After adding the right repository, for a $pkg binary is a $pkg-dbgsym
package, if the automatic generation was enabled for the source of
$pkg (which is the case for libvirt).
--
Pino Toscano
7:24 a.m.
On Thu, Mar 22, 2018 at 06:10:49PM +0200, Mathieu Tarral wrote:
Hi !
I'm submitting my messages on this mailing list to request a bit of
help on a case that I have
where a Python application makes a call to virDomainIsActive, and the
call never returns.
I have tried to investigate, but as there are no debug symbols for
libvirt on Debian Stretch,
i can only have the following GDB backtrace:
(gdb) bt
#0 pthread_cond_wait@(a)GLIBC_2.3.2 () at
../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
#1 0x00007f49026f5b76 in virCondWait () from /usr/lib/libvirt.so.0
#2 0x00007f4902808bab in ?? () from /usr/lib/libvirt.so.0
#3 0x00007f490280a433 in virNetClientSendWithReply () from
/usr/lib/libvirt.so.0
#4 0x00007f490280abe2 in virNetClientProgramCall () from /usr/lib/libvirt.so.0
#5 0x00007f49027e0ea4 in ?? () from /usr/lib/libvirt.so.0
#6 0x00007f49027ea1bb in ?? () from /usr/lib/libvirt.so.0
#7 0x00007f49027b0ef3 in virDomainIsActive () from /usr/lib/libvirt.so.0
#8 0x00007f4902b7fbd0 in libvirt_virDomainIsActive () from
/usr/lib/python3/dist-packages/libvirtmod.cpython-35m-x86_64-linux-gnu.so
#9 0x0000558eeec696df in PyCFunction_Call () at ../Objects/methodobject.c:109
The libvirt driver used is QEMU, and i have a specific monitoring in
place using virtual machine introspection:
https://github.com/KVM-VMI/kvm-vmi
Now this specific monitoring somehow triggers this bug, and at this
point, i don't know if
it's a corner case in the libvirt QEMU driver or not.
That's why i would like to have your lights on this.
libvirt version: 3.0.0-4
-> Could you tell me where i should look in the code ?
You're probably looking at virLogManagerDomain* methods located in
src/logging/log_manager.c and the wait call is issued from virNetClientIO.
-> Do you have more information about this virCondWait ? Which
condition is it waiting for ?
-> How can i get the symbols without having the recompile libvirt and
install it system wide, erasing the binaries installed by the package
?
To be honest, I think it's always worth debugging a custom built binary from
sources, since the debug symbols shipped via distro package are most likely
generated with optimizations which makes any kind of interactive debugging
painful. The problem is that you're going to built v3.0.0 tag on a new distro,
since new GCCs will complain about a lot of stuff, I looked at the code, tried
a few things, but honestly I didn't see a path where you could get to
virNetClientProgrammCall from virDomainIsActive (since I don't know what the
original call was), so unless you post a full backtrace, we can't help you much
here.
One more thing, yes, you'd have to compile libvirt from git, but you don't have
to install it, in fact, I'm always running upstream daemon, but haven't
installed it system-wide, on the contrary, I've got a distro-provided version
installed in the system which is disabled most of the time.
Regards,
Erik
5:16 a.m.
On Fri, Mar 23, 2018 at 01:24:46PM +0100, Erik Skultety wrote:
On Thu, Mar 22, 2018 at 06:10:49PM +0200, Mathieu Tarral wrote:
> Hi !
>
> I'm submitting my messages on this mailing list to request a bit of
> help on a case that I have
> where a Python application makes a call to virDomainIsActive, and the
> call never returns.
>
> I have tried to investigate, but as there are no debug symbols for
> libvirt on Debian Stretch,
> i can only have the following GDB backtrace:
>
> (gdb) bt
> #0 pthread_cond_wait@(a)GLIBC_2.3.2 () at
> ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
> #1 0x00007f49026f5b76 in virCondWait () from /usr/lib/libvirt.so.0
> #2 0x00007f4902808bab in ?? () from /usr/lib/libvirt.so.0
> #3 0x00007f490280a433 in virNetClientSendWithReply () from
> /usr/lib/libvirt.so.0
> #4 0x00007f490280abe2 in virNetClientProgramCall () from /usr/lib/libvirt.so.0
> #5 0x00007f49027e0ea4 in ?? () from /usr/lib/libvirt.so.0
> #6 0x00007f49027ea1bb in ?? () from /usr/lib/libvirt.so.0
> #7 0x00007f49027b0ef3 in virDomainIsActive () from /usr/lib/libvirt.so.0
> #8 0x00007f4902b7fbd0 in libvirt_virDomainIsActive () from
> /usr/lib/python3/dist-packages/libvirtmod.cpython-35m-x86_64-linux-gnu.so
> #9 0x0000558eeec696df in PyCFunction_Call () at ../Objects/methodobject.c:109
>
> The libvirt driver used is QEMU, and i have a specific monitoring in
> place using virtual machine introspection:
> https://github.com/KVM-VMI/kvm-vmi
>
> Now this specific monitoring somehow triggers this bug, and at this
> point, i don't know if
> it's a corner case in the libvirt QEMU driver or not.
> That's why i would like to have your lights on this.
>
> libvirt version: 3.0.0-4
>
> -> Could you tell me where i should look in the code ?
You're probably looking at virLogManagerDomain* methods located in
src/logging/log_manager.c and the wait call is issued from virNetClientIO.
> -> Do you have more information about this virCondWait ? Which
> condition is it waiting for ?
> -> How can i get the symbols without having the recompile libvirt and
> install it system wide, erasing the binaries installed by the package
> ?
To be honest, I think it's always worth debugging a custom built binary from
sources, since the debug symbols shipped via distro package are most likely
generated with optimizations which makes any kind of interactive debugging
painful. The problem is that you're going to built v3.0.0 tag on a new distro,
since new GCCs will complain about a lot of stuff, I looked at the code, tried
a few things, but honestly I didn't see a path where you could get to
virNetClientProgrammCall from virDomainIsActive (since I don't know what the
original call was), so unless you post a full backtrace, we can't help you much
here.
That's easy - virDomainIsActive() calls into the driver APIs. This is client
side trace, so will get into the remote driver client, which will then call
virNetClientProgramCall.
Regards,
Daniel
--
|: https://berrange.com -o- https://www.flickr.com/photos/dberrange :|
|: https://libvirt.org -o- https://fstop138.berrange.com :|
|: https://entangle-photo.org -o- https://www.instagram.com/dberrange :|
7:30 a.m.
I have installed the following debug symbols:
- libvirt-daemon-dbgsym_3.0.0-4+deb9u3_amd64.deb
- libvirt-daemon-system-dbgsym_3.0.0-4+deb9u3_amd64.deb
- libvirt-clients-dbgsym_3.0.0-4+deb9u3_amd64.deb
- libvirt0-dbgsym_3.0.0-4+deb9u3_amd64.deb
- python3-libvirt-dbgsym_3.0.0-2_amd64.deb
And i was able to reproduce my bug.
In my Python application, i had 2 threads hanging on a libvirt call.
(sorry for the verbosity)
Thread 1:
(gdb) py-bt
Traceback (most recent call first):
<built-in method virDomainGetState of module object at remote 0x7f508e6b1278>
File "/usr/lib/python3/dist-packages/libvirt.py", line 2551, in state
ret = libvirtmod.virDomainGetState(self._o, flags)
(gdb) bt
pthread_cond_wait@(a)GLIBC_2.3.2 () at
../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
#1 0x00007f508dfe2b86 in virCondWait (c=c@entry=0x55a1fe420728,
m=m@entry=0x55a1fde4d2c0) at ../../../src/util/virthread.c:154
#2 0x00007f508e0f5bbb in virNetClientIO (thiscall=0x55a1fe420710,
client=0x55a1fde4d2b0) at ../../../src/rpc/virnetclient.c:1894
#3 virNetClientSendInternal (client=client@entry=0x55a1fde4d2b0,
msg=msg@entry=0x55a1fdd798f0, expectReply=expectReply@entry=true,
nonBlock=nonBlock@entry=false) at ../../../src/rpc/virnetclient.c:2116
#4 0x00007f508e0f7443 in virNetClientSendWithReply
(client=client@entry=0x55a1fde4d2b0, msg=msg@entry=0x55a1fdd798f0) at
../../../src/rpc/virnetclient.c:2144
#5 0x00007f508e0f7bf2 in virNetClientProgramCall
(prog=prog@entry=0x55a1fdff0f90, client=client@entry=0x55a1fde4d2b0,
serial=serial@entry=108, proc=proc@entry=212, noutfds=noutfds@entry=0,
outfds=outfds@entry=0x0, ninfds=0x0,
infds=0x0, args_filter=0x7f508e0f13e0
<xdr_remote_domain_get_state_args>, args=0x7ffd1518cfd0,
ret_filter=0x7f508e0f1410 <xdr_remote_domain_get_state_ret>,
ret=0x7ffd1518cfc8) at ../../../src/rpc/virnetclientprogram.c:329
#6 0x00007f508e0cdeb4 in callFull (priv=priv@entry=0x55a1fe5ac460,
flags=flags@entry=0, fdin=fdin@entry=0x0, fdinlen=fdinlen@entry=0,
fdout=fdout@entry=0x0, fdoutlen=fdoutlen@entry=0x0, proc_nr=212,
args_filter=0x7f508e0f13e0 <xdr_remote_domain_get_state_args>,
args=0x7ffd1518cfd0 "`k.\376\241U", ret_filter=0x7f508e0f1410
<xdr_remote_domain_get_state_ret>, ret=0x7ffd1518cfc8 "",
conn=<optimized out>)
at ../../../src/remote/remote_driver.c:6636
#7 0x00007f508e0d7f90 in call (conn=<optimized out>,
ret=0x7ffd1518cfc8 "", ret_filter=<optimized out>, args=0x7ffd1518cfd0
"`k.\376\241U", args_filter=<optimized out>, proc_nr=212, flags=0,
priv=0x55a1fe5ac460)
at ../../../src/remote/remote_driver.c:6658
#8 remoteDomainGetState (domain=0x55a1fe212da0, state=0x7ffd1518d0a4,
reason=0x7ffd1518d0a8, flags=0) at
../../../src/remote/remote_driver.c:2458
#9 0x00007f508e08e248 in virDomainGetState
(domain=domain@entry=0x55a1fe212da0, state=state@entry=0x7ffd1518d0a4,
reason=reason@entry=0x7ffd1518d0a8, flags=0) at
../../../src/libvirt-domain.c:2495
#10 0x00007f508e466f28 in libvirt_virDomainGetState (self=<optimized
out>, args=<optimized out>) at libvirt-override.c:2539
#11 0x000055a1fb4cb6df in PyCFunction_Call () at ../Objects/methodobject.c:109
And Thread 2:
(gdb) py-bt
<built-in method virDomainIsActive of module object at remote 0x7f508e6b1278>
File "/usr/lib/python3/dist-packages/libvirt.py", line 1340, in isActive
ret = libvirtmod.virDomainIsActive(self._o)
(gdb) bt
#0 pthread_cond_wait@(a)GLIBC_2.3.2 () at
../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
#1 0x00007f508dfe2b86 in virCondWait (c=c@entry=0x7f4ff051fdc8,
m=m@entry=0x55a1fde4d2c0) at ../../../src/util/virthread.c:154
#2 0x00007f508e0f5bbb in virNetClientIO (thiscall=0x7f4ff051fdb0,
client=0x55a1fde4d2b0) at ../../../src/rpc/virnetclient.c:1894
#3 virNetClientSendInternal (client=client@entry=0x55a1fde4d2b0,
msg=msg@entry=0x7f4ff051fa10, expectReply=expectReply@entry=true,
nonBlock=nonBlock@entry=false) at ../../../src/rpc/virnetclient.c:2116
#4 0x00007f508e0f7443 in virNetClientSendWithReply
(client=client@entry=0x55a1fde4d2b0, msg=msg@entry=0x7f4ff051fa10) at
../../../src/rpc/virnetclient.c:2144
#5 0x00007f508e0f7bf2 in virNetClientProgramCall
(prog=prog@entry=0x55a1fdff0f90, client=client@entry=0x55a1fde4d2b0,
serial=serial@entry=107, proc=proc@entry=150, noutfds=noutfds@entry=0,
outfds=outfds@entry=0x0, ninfds=0x0,
infds=0x0, args_filter=0x7f508e0efe70
<xdr_remote_domain_is_active_args>, args=0x7f4fff7fd040,
ret_filter=0x7f508e0efe90 <xdr_remote_domain_is_active_ret>,
ret=0x7f4fff7fd03c) at ../../../src/rpc/virnetclientprogram.c:329
#6 0x00007f508e0cdeb4 in callFull (priv=priv@entry=0x55a1fe5ac460,
flags=flags@entry=0, fdin=fdin@entry=0x0, fdinlen=fdinlen@entry=0,
fdout=fdout@entry=0x0, fdoutlen=fdoutlen@entry=0x0, proc_nr=150,
args_filter=0x7f508e0efe70 <xdr_remote_domain_is_active_args>,
args=0x7f4fff7fd040 "`k.\376\241U", ret_filter=0x7f508e0efe90
<xdr_remote_domain_is_active_ret>, ret=0x7f4fff7fd03c "",
conn=<optimized out>)
at ../../../src/remote/remote_driver.c:6636
#7 0x00007f508e0d71cb in call (conn=<optimized out>,
ret=0x7f4fff7fd03c "", ret_filter=<optimized out>, args=0x7f4fff7fd040
"`k.\376\241U", args_filter=<optimized out>, proc_nr=150, flags=0,
priv=0x55a1fe5ac460)
at ../../../src/remote/remote_driver.c:6658
#8 remoteDomainIsActive (dom=0x55a1fe212da0) at
../../../src/remote/remote_client_bodies.h:2842
#9 0x00007f508e09df03 in virDomainIsActive
(dom=dom@entry=0x55a1fe212da0) at ../../../src/libvirt-domain.c:8467
#10 0x00007f508e46cbd0 in libvirt_virDomainIsActive (self=<optimized
out>, args=<optimized out>) at build/libvirt.c:1288
#11 0x000055a1fb4cb6df in PyCFunction_Call () at ../Objects/methodobject.c:109
So i ran GDB on /usr/sbin/libvirtd to know what was happening:
(gdb) thread all apply bt
Thread 17 (Thread 0x7f241dd40700 (LWP 5100)):
#0 pthread_cond_wait@(a)GLIBC_2.3.2 () at
../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
#1 0x00007f2448240b86 in virCondWait (c=c@entry=0x7f24183eeba8,
m=m@entry=0x7f24183eeb80) at ../../../src/util/virthread.c:154
#2 0x00007f24482416d3 in virThreadPoolWorker
(opaque=opaque@entry=0x55705071a350) at
../../../src/util/virthreadpool.c:124
#3 0x00007f2448240928 in virThreadHelper (data=<optimized out>) at
../../../src/util/virthread.c:206
#4 0x00007f2444b1a494 in start_thread (arg=0x7f241dd40700) at
pthread_create.c:333
#5 0x00007f244485cacf in clone () at
../sysdeps/unix/sysv/linux/x86_64/clone.S:97
Thread 16 (Thread 0x7f241fdfd700 (LWP 3518)):
#0 pthread_cond_wait@(a)GLIBC_2.3.2 () at
../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
#1 0x00007f2448240b86 in virCondWait (c=c@entry=0x55705073e728,
m=m@entry=0x55705073e700) at ../../../src/util/virthread.c:154
#2 0x00007f24482416d3 in virThreadPoolWorker
(opaque=opaque@entry=0x55705073e4b0) at
../../../src/util/virthreadpool.c:124
#3 0x00007f2448240928 in virThreadHelper (data=<optimized out>) at
../../../src/util/virthread.c:206
#4 0x00007f2444b1a494 in start_thread (arg=0x7f241fdfd700) at
pthread_create.c:333
#5 0x00007f244485cacf in clone () at
../sysdeps/unix/sysv/linux/x86_64/clone.S:97
Thread 15 (Thread 0x7f24205fe700 (LWP 3517)):
#0 pthread_cond_wait@(a)GLIBC_2.3.2 () at
../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
#1 0x00007f2448240b86 in virCondWait (c=c@entry=0x55705073e728,
m=m@entry=0x55705073e700) at ../../../src/util/virthread.c:154
#2 0x00007f24482416d3 in virThreadPoolWorker
(opaque=opaque@entry=0x55705071e310) at
../../../src/util/virthreadpool.c:124
#3 0x00007f2448240928 in virThreadHelper (data=<optimized out>) at
../../../src/util/virthread.c:206
#4 0x00007f2444b1a494 in start_thread (arg=0x7f24205fe700) at
pthread_create.c:333
#5 0x00007f244485cacf in clone () at
../sysdeps/unix/sysv/linux/x86_64/clone.S:97
Thread 14 (Thread 0x7f2420dff700 (LWP 3516)):
#0 pthread_cond_wait@(a)GLIBC_2.3.2 () at
../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
#1 0x00007f2448240b86 in virCondWait (c=c@entry=0x55705073e728,
m=m@entry=0x55705073e700) at ../../../src/util/virthread.c:154
#2 0x00007f24482416d3 in virThreadPoolWorker
(opaque=opaque@entry=0x55705073e4b0) at
../../../src/util/virthreadpool.c:124
#3 0x00007f2448240928 in virThreadHelper (data=<optimized out>) at
../../../src/util/virthread.c:206
#4 0x00007f2444b1a494 in start_thread (arg=0x7f2420dff700) at
pthread_create.c:333
#5 0x00007f244485cacf in clone () at
../sysdeps/unix/sysv/linux/x86_64/clone.S:97
Thread 13 (Thread 0x7f2421600700 (LWP 3515)):
#0 pthread_cond_wait@(a)GLIBC_2.3.2 () at
../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
#1 0x00007f2448240b86 in virCondWait (c=c@entry=0x55705073e728,
m=m@entry=0x55705073e700) at ../../../src/util/virthread.c:154
#2 0x00007f24482416d3 in virThreadPoolWorker
(opaque=opaque@entry=0x55705071e250) at
../../../src/util/virthreadpool.c:124
#3 0x00007f2448240928 in virThreadHelper (data=<optimized out>) at
../../../src/util/virthread.c:206
#4 0x00007f2444b1a494 in start_thread (arg=0x7f2421600700) at
pthread_create.c:333
#5 0x00007f244485cacf in clone () at
../sysdeps/unix/sysv/linux/x86_64/clone.S:97
Thread 12 (Thread 0x7f2421e01700 (LWP 3514)):
#0 pthread_cond_wait@(a)GLIBC_2.3.2 () at
../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
#1 0x00007f2448240b86 in virCondWait (c=c@entry=0x55705073e728,
m=m@entry=0x55705073e700) at ../../../src/util/virthread.c:154
#2 0x00007f24482416d3 in virThreadPoolWorker
(opaque=opaque@entry=0x55705073e4b0) at
../../../src/util/virthreadpool.c:124
#3 0x00007f2448240928 in virThreadHelper (data=<optimized out>) at
../../../src/util/virthread.c:206
#4 0x00007f2444b1a494 in start_thread (arg=0x7f2421e01700) at
pthread_create.c:333
#5 0x00007f244485cacf in clone () at
../sysdeps/unix/sysv/linux/x86_64/clone.S:97
Thread 11 (Thread 0x7f2439e14700 (LWP 3513)):
#0 pthread_cond_wait@(a)GLIBC_2.3.2 () at
../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
#1 0x00007f2448240b86 in virCondWait (c=c@entry=0x557050729358,
m=m@entry=0x557050729290) at ../../../src/util/virthread.c:154
#2 0x00007f2448241694 in virThreadPoolWorker
(opaque=opaque@entry=0x55705071b8d0) at
../../../src/util/virthreadpool.c:124
#3 0x00007f2448240928 in virThreadHelper (data=<optimized out>) at
../../../src/util/virthread.c:206
#4 0x00007f2444b1a494 in start_thread (arg=0x7f2439e14700) at
pthread_create.c:333
#5 0x00007f244485cacf in clone () at
../sysdeps/unix/sysv/linux/x86_64/clone.S:97
Thread 10 (Thread 0x7f243a615700 (LWP 3512)):
#0 pthread_cond_wait@(a)GLIBC_2.3.2 () at
../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
#1 0x00007f2448240b86 in virCondWait (c=c@entry=0x557050729358,
m=m@entry=0x557050729290) at ../../../src/util/virthread.c:154
#2 0x00007f2448241694 in virThreadPoolWorker
(opaque=opaque@entry=0x55705071bb10) at
../../../src/util/virthreadpool.c:124
#3 0x00007f2448240928 in virThreadHelper (data=<optimized out>) at
../../../src/util/virthread.c:206
#4 0x00007f2444b1a494 in start_thread (arg=0x7f243a615700) at
pthread_create.c:333
#5 0x00007f244485cacf in clone () at
../sysdeps/unix/sysv/linux/x86_64/clone.S:97
Thread 9 (Thread 0x7f243ae16700 (LWP 3511)):
#0 pthread_cond_wait@(a)GLIBC_2.3.2 () at
../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
#1 0x00007f2448240b86 in virCondWait (c=c@entry=0x557050729358,
m=m@entry=0x557050729290) at ../../../src/util/virthread.c:154
#2 0x00007f2448241694 in virThreadPoolWorker
(opaque=opaque@entry=0x55705071b810) at
../../../src/util/virthreadpool.c:124
#3 0x00007f2448240928 in virThreadHelper (data=<optimized out>) at
../../../src/util/virthread.c:206
#4 0x00007f2444b1a494 in start_thread (arg=0x7f243ae16700) at
pthread_create.c:333
#5 0x00007f244485cacf in clone () at
../sysdeps/unix/sysv/linux/x86_64/clone.S:97
Thread 8 (Thread 0x7f243b617700 (LWP 3510)):
#0 pthread_cond_wait@(a)GLIBC_2.3.2 () at
../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
#1 0x00007f2448240b86 in virCondWait (c=c@entry=0x557050729358,
m=m@entry=0x557050729290) at ../../../src/util/virthread.c:154
#2 0x00007f2448241694 in virThreadPoolWorker
(opaque=opaque@entry=0x55705071b8d0) at
../../../src/util/virthreadpool.c:124
#3 0x00007f2448240928 in virThreadHelper (data=<optimized out>) at
../../../src/util/virthread.c:206
#4 0x00007f2444b1a494 in start_thread (arg=0x7f243b617700) at
pthread_create.c:333
#5 0x00007f244485cacf in clone () at
../sysdeps/unix/sysv/linux/x86_64/clone.S:97
Thread 7 (Thread 0x7f243be18700 (LWP 3509)):
#0 pthread_cond_wait@(a)GLIBC_2.3.2 () at
../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
#1 0x00007f2448240b86 in virCondWait (c=c@entry=0x557050729358,
m=m@entry=0x557050729290) at ../../../src/util/virthread.c:154
#2 0x00007f2448241694 in virThreadPoolWorker
(opaque=opaque@entry=0x55705071bb10) at
../../../src/util/virthreadpool.c:124
#3 0x00007f2448240928 in virThreadHelper (data=<optimized out>) at
../../../src/util/virthread.c:206
#4 0x00007f2444b1a494 in start_thread (arg=0x7f243be18700) at
pthread_create.c:333
#5 0x00007f244485cacf in clone () at
../sysdeps/unix/sysv/linux/x86_64/clone.S:97
Thread 6 (Thread 0x7f243c619700 (LWP 3508)):
#0 pthread_cond_wait@(a)GLIBC_2.3.2 () at
../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
#1 0x00007f2448240b86 in virCondWait (c=c@entry=0x5570507292b8,
m=m@entry=0x557050729290) at ../../../src/util/virthread.c:154
#2 0x00007f24482416d3 in virThreadPoolWorker
(opaque=opaque@entry=0x55705071b810) at
../../../src/util/virthreadpool.c:124
#3 0x00007f2448240928 in virThreadHelper (data=<optimized out>) at
../../../src/util/virthread.c:206
#4 0x00007f2444b1a494 in start_thread (arg=0x7f243c619700) at
pthread_create.c:333
#5 0x00007f244485cacf in clone () at
../sysdeps/unix/sysv/linux/x86_64/clone.S:97
Thread 5 (Thread 0x7f243ce1a700 (LWP 3507)):
#0 pthread_cond_wait@(a)GLIBC_2.3.2 () at
../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
#1 0x00007f2448240b86 in virCondWait (c=c@entry=0x5570507292b8,
m=m@entry=0x557050729290) at ../../../src/util/virthread.c:154
#2 0x00007f24482416d3 in virThreadPoolWorker
(opaque=opaque@entry=0x55705071b8d0) at
../../../src/util/virthreadpool.c:124
#3 0x00007f2448240928 in virThreadHelper (data=<optimized out>) at
../../../src/util/virthread.c:206
#4 0x00007f2444b1a494 in start_thread (arg=0x7f243ce1a700) at
pthread_create.c:333
#5 0x00007f244485cacf in clone () at
../sysdeps/unix/sysv/linux/x86_64/clone.S:97
Thread 4 (Thread 0x7f243d61b700 (LWP 3506)):
#0 pthread_cond_wait@(a)GLIBC_2.3.2 () at
../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
#1 0x00007f2448240b86 in virCondWait (c=c@entry=0x5570507292b8,
m=m@entry=0x557050729290) at ../../../src/util/virthread.c:154
#2 0x00007f24482416d3 in virThreadPoolWorker
(opaque=opaque@entry=0x55705071b990) at
../../../src/util/virthreadpool.c:124
#3 0x00007f2448240928 in virThreadHelper (data=<optimized out>) at
../../../src/util/virthread.c:206
#4 0x00007f2444b1a494 in start_thread (arg=0x7f243d61b700) at
pthread_create.c:333
#5 0x00007f244485cacf in clone () at
../sysdeps/unix/sysv/linux/x86_64/clone.S:97
Thread 3 (Thread 0x7f243de1c700 (LWP 3505)):
#0 pthread_cond_wait@(a)GLIBC_2.3.2 () at
../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
#1 0x00007f2448240b86 in virCondWait (c=c@entry=0x5570507292b8,
m=m@entry=0x557050729290) at ../../../src/util/virthread.c:154
#2 0x00007f24482416d3 in virThreadPoolWorker
(opaque=opaque@entry=0x55705071ba50) at
../../../src/util/virthreadpool.c:124
#3 0x00007f2448240928 in virThreadHelper (data=<optimized out>) at
../../../src/util/virthread.c:206
#4 0x00007f2444b1a494 in start_thread (arg=0x7f243de1c700) at
pthread_create.c:333
#5 0x00007f244485cacf in clone () at
../sysdeps/unix/sysv/linux/x86_64/clone.S:97
Thread 2 (Thread 0x7f243e61d700 (LWP 3504)):
#0 pthread_cond_wait@(a)GLIBC_2.3.2 () at
../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
#1 0x00007f2448240b86 in virCondWait (c=c@entry=0x5570507292b8,
m=m@entry=0x557050729290) at ../../../src/util/virthread.c:154
#2 0x00007f24482416d3 in virThreadPoolWorker
(opaque=opaque@entry=0x55705071bb10) at
../../../src/util/virthreadpool.c:124
#3 0x00007f2448240928 in virThreadHelper (data=<optimized out>) at
../../../src/util/virthread.c:206
#4 0x00007f2444b1a494 in start_thread (arg=0x7f243e61d700) at
pthread_create.c:333
#5 0x00007f244485cacf in clone () at
../sysdeps/unix/sysv/linux/x86_64/clone.S:97
Thread 1 (Thread 0x7f24489f3940 (LWP 3502)):
#0 0x00007f244485367d in poll () at ../sysdeps/unix/syscall-template.S:84
#1 0x00007f24481f304f in poll (__timeout=-1, __nfds=50,
__fds=<optimized out>) at
/usr/include/x86_64-linux-gnu/bits/poll2.h:46
#2 virEventPollRunOnce () at ../../../src/util/vireventpoll.c:641
#3 0x00007f24481f1c21 in virEventRunDefaultImpl () at
../../../src/util/virevent.c:314
#4 0x00007f244835837d in virNetDaemonRun (dmn=0x55705072a330) at
../../../src/rpc/virnetdaemon.c:818
#5 0x000055704f773b87 in main (argc=<optimized out>, argv=<optimized
out>) at ../../../daemon/libvirtd.c:1547
But this doesn't really help me understand why it hangs,
or which threads is processing the client requests that are hanging.
Does this information provides you any help ?
If i should run other commands, please, let me know,
libvirt will be hanging forever.
Best regards,
2018-03-26 13:16 GMT+03:00 Daniel P. Berrangé <berrange(a)redhat.com>:
On Fri, Mar 23, 2018 at 01:24:46PM +0100, Erik Skultety wrote:
> On Thu, Mar 22, 2018 at 06:10:49PM +0200, Mathieu Tarral wrote:
> > Hi !
> >
> > I'm submitting my messages on this mailing list to request a bit of
> > help on a case that I have
> > where a Python application makes a call to virDomainIsActive, and the
> > call never returns.
> >
> > I have tried to investigate, but as there are no debug symbols for
> > libvirt on Debian Stretch,
> > i can only have the following GDB backtrace:
> >
> > (gdb) bt
> > #0 pthread_cond_wait@(a)GLIBC_2.3.2 () at
> > ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
> > #1 0x00007f49026f5b76 in virCondWait () from /usr/lib/libvirt.so.0
> > #2 0x00007f4902808bab in ?? () from /usr/lib/libvirt.so.0
> > #3 0x00007f490280a433 in virNetClientSendWithReply () from
> > /usr/lib/libvirt.so.0
> > #4 0x00007f490280abe2 in virNetClientProgramCall () from /usr/lib/libvirt.so.0
> > #5 0x00007f49027e0ea4 in ?? () from /usr/lib/libvirt.so.0
> > #6 0x00007f49027ea1bb in ?? () from /usr/lib/libvirt.so.0
> > #7 0x00007f49027b0ef3 in virDomainIsActive () from /usr/lib/libvirt.so.0
> > #8 0x00007f4902b7fbd0 in libvirt_virDomainIsActive () from
> > /usr/lib/python3/dist-packages/libvirtmod.cpython-35m-x86_64-linux-gnu.so
> > #9 0x0000558eeec696df in PyCFunction_Call () at ../Objects/methodobject.c:109
> >
> > The libvirt driver used is QEMU, and i have a specific monitoring in
> > place using virtual machine introspection:
> > https://github.com/KVM-VMI/kvm-vmi
> >
> > Now this specific monitoring somehow triggers this bug, and at this
> > point, i don't know if
> > it's a corner case in the libvirt QEMU driver or not.
> > That's why i would like to have your lights on this.
> >
> > libvirt version: 3.0.0-4
> >
> > -> Could you tell me where i should look in the code ?
>
> You're probably looking at virLogManagerDomain* methods located in
> src/logging/log_manager.c and the wait call is issued from virNetClientIO.
>
> > -> Do you have more information about this virCondWait ? Which
> > condition is it waiting for ?
> > -> How can i get the symbols without having the recompile libvirt and
> > install it system wide, erasing the binaries installed by the package
> > ?
>
> To be honest, I think it's always worth debugging a custom built binary from
> sources, since the debug symbols shipped via distro package are most likely
> generated with optimizations which makes any kind of interactive debugging
> painful. The problem is that you're going to built v3.0.0 tag on a new distro,
> since new GCCs will complain about a lot of stuff, I looked at the code, tried
> a few things, but honestly I didn't see a path where you could get to
> virNetClientProgrammCall from virDomainIsActive (since I don't know what the
> original call was), so unless you post a full backtrace, we can't help you much
> here.
That's easy - virDomainIsActive() calls into the driver APIs. This is client
side trace, so will get into the remote driver client, which will then call
virNetClientProgramCall.
Regards,
Daniel
--
|: https://berrange.com -o- https://www.flickr.com/photos/dberrange :|
|: https://libvirt.org -o- https://fstop138.berrange.com :|
|: https://entangle-photo.org -o- https://www.instagram.com/dberrange :|
--
Mathieu Tarral
7:45 a.m.
On Tue, Mar 27, 2018 at 03:30:14PM +0300, Mathieu Tarral wrote:
I have installed the following debug symbols:
- libvirt-daemon-dbgsym_3.0.0-4+deb9u3_amd64.deb
- libvirt-daemon-system-dbgsym_3.0.0-4+deb9u3_amd64.deb
- libvirt-clients-dbgsym_3.0.0-4+deb9u3_amd64.deb
- libvirt0-dbgsym_3.0.0-4+deb9u3_amd64.deb
- python3-libvirt-dbgsym_3.0.0-2_amd64.deb
And i was able to reproduce my bug.
In my Python application, i had 2 threads hanging on a libvirt call.
(sorry for the verbosity)
Thread 1:
(gdb) py-bt
Traceback (most recent call first):
<built-in method virDomainGetState of module object at remote 0x7f508e6b1278>
File "/usr/lib/python3/dist-packages/libvirt.py", line 2551, in state
ret = libvirtmod.virDomainGetState(self._o, flags)
(gdb) bt
pthread_cond_wait@(a)GLIBC_2.3.2 () at
../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
#1 0x00007f508dfe2b86 in virCondWait (c=c@entry=0x55a1fe420728,
m=m@entry=0x55a1fde4d2c0) at ../../../src/util/virthread.c:154
#2 0x00007f508e0f5bbb in virNetClientIO (thiscall=0x55a1fe420710,
client=0x55a1fde4d2b0) at ../../../src/rpc/virnetclient.c:1894
#3 virNetClientSendInternal (client=client@entry=0x55a1fde4d2b0,
msg=msg@entry=0x55a1fdd798f0, expectReply=expectReply@entry=true,
nonBlock=nonBlock@entry=false) at ../../../src/rpc/virnetclient.c:2116
#4 0x00007f508e0f7443 in virNetClientSendWithReply
(client=client@entry=0x55a1fde4d2b0, msg=msg@entry=0x55a1fdd798f0) at
../../../src/rpc/virnetclient.c:2144
#5 0x00007f508e0f7bf2 in virNetClientProgramCall
(prog=prog@entry=0x55a1fdff0f90, client=client@entry=0x55a1fde4d2b0,
serial=serial@entry=108, proc=proc@entry=212, noutfds=noutfds@entry=0,
outfds=outfds@entry=0x0, ninfds=0x0,
infds=0x0, args_filter=0x7f508e0f13e0
<xdr_remote_domain_get_state_args>, args=0x7ffd1518cfd0,
ret_filter=0x7f508e0f1410 <xdr_remote_domain_get_state_ret>,
ret=0x7ffd1518cfc8) at ../../../src/rpc/virnetclientprogram.c:329
#6 0x00007f508e0cdeb4 in callFull (priv=priv@entry=0x55a1fe5ac460,
flags=flags@entry=0, fdin=fdin@entry=0x0, fdinlen=fdinlen@entry=0,
fdout=fdout@entry=0x0, fdoutlen=fdoutlen@entry=0x0, proc_nr=212,
args_filter=0x7f508e0f13e0 <xdr_remote_domain_get_state_args>,
args=0x7ffd1518cfd0 "`k.\376\241U", ret_filter=0x7f508e0f1410
<xdr_remote_domain_get_state_ret>, ret=0x7ffd1518cfc8 "",
conn=<optimized out>)
at ../../../src/remote/remote_driver.c:6636
#7 0x00007f508e0d7f90 in call (conn=<optimized out>,
ret=0x7ffd1518cfc8 "", ret_filter=<optimized out>, args=0x7ffd1518cfd0
"`k.\376\241U", args_filter=<optimized out>, proc_nr=212, flags=0,
priv=0x55a1fe5ac460)
at ../../../src/remote/remote_driver.c:6658
#8 remoteDomainGetState (domain=0x55a1fe212da0, state=0x7ffd1518d0a4,
reason=0x7ffd1518d0a8, flags=0) at
../../../src/remote/remote_driver.c:2458
#9 0x00007f508e08e248 in virDomainGetState
(domain=domain@entry=0x55a1fe212da0, state=state@entry=0x7ffd1518d0a4,
reason=reason@entry=0x7ffd1518d0a8, flags=0) at
../../../src/libvirt-domain.c:2495
#10 0x00007f508e466f28 in libvirt_virDomainGetState (self=<optimized
out>, args=<optimized out>) at libvirt-override.c:2539
#11 0x000055a1fb4cb6df in PyCFunction_Call () at ../Objects/methodobject.c:109
That's pretty much as expected - just remote client waiting for a reply
from the daemon.
And Thread 2:
(gdb) py-bt
<built-in method virDomainIsActive of module object at remote 0x7f508e6b1278>
File "/usr/lib/python3/dist-packages/libvirt.py", line 1340, in isActive
ret = libvirtmod.virDomainIsActive(self._o)
(gdb) bt
Are you sure this isa different thread ? It looks identical to the first
stack trace you give above.
#0 pthread_cond_wait@(a)GLIBC_2.3.2 () at
../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
#1 0x00007f508dfe2b86 in virCondWait (c=c@entry=0x7f4ff051fdc8,
m=m@entry=0x55a1fde4d2c0) at ../../../src/util/virthread.c:154
#2 0x00007f508e0f5bbb in virNetClientIO (thiscall=0x7f4ff051fdb0,
client=0x55a1fde4d2b0) at ../../../src/rpc/virnetclient.c:1894
#3 virNetClientSendInternal (client=client@entry=0x55a1fde4d2b0,
msg=msg@entry=0x7f4ff051fa10, expectReply=expectReply@entry=true,
nonBlock=nonBlock@entry=false) at ../../../src/rpc/virnetclient.c:2116
#4 0x00007f508e0f7443 in virNetClientSendWithReply
(client=client@entry=0x55a1fde4d2b0, msg=msg@entry=0x7f4ff051fa10) at
../../../src/rpc/virnetclient.c:2144
#5 0x00007f508e0f7bf2 in virNetClientProgramCall
(prog=prog@entry=0x55a1fdff0f90, client=client@entry=0x55a1fde4d2b0,
serial=serial@entry=107, proc=proc@entry=150, noutfds=noutfds@entry=0,
outfds=outfds@entry=0x0, ninfds=0x0,
infds=0x0, args_filter=0x7f508e0efe70
<xdr_remote_domain_is_active_args>, args=0x7f4fff7fd040,
ret_filter=0x7f508e0efe90 <xdr_remote_domain_is_active_ret>,
ret=0x7f4fff7fd03c) at ../../../src/rpc/virnetclientprogram.c:329
#6 0x00007f508e0cdeb4 in callFull (priv=priv@entry=0x55a1fe5ac460,
flags=flags@entry=0, fdin=fdin@entry=0x0, fdinlen=fdinlen@entry=0,
fdout=fdout@entry=0x0, fdoutlen=fdoutlen@entry=0x0, proc_nr=150,
args_filter=0x7f508e0efe70 <xdr_remote_domain_is_active_args>,
args=0x7f4fff7fd040 "`k.\376\241U", ret_filter=0x7f508e0efe90
<xdr_remote_domain_is_active_ret>, ret=0x7f4fff7fd03c "",
conn=<optimized out>)
at ../../../src/remote/remote_driver.c:6636
#7 0x00007f508e0d71cb in call (conn=<optimized out>,
ret=0x7f4fff7fd03c "", ret_filter=<optimized out>, args=0x7f4fff7fd040
"`k.\376\241U", args_filter=<optimized out>, proc_nr=150, flags=0,
priv=0x55a1fe5ac460)
at ../../../src/remote/remote_driver.c:6658
#8 remoteDomainIsActive (dom=0x55a1fe212da0) at
../../../src/remote/remote_client_bodies.h:2842
#9 0x00007f508e09df03 in virDomainIsActive
(dom=dom@entry=0x55a1fe212da0) at ../../../src/libvirt-domain.c:8467
#10 0x00007f508e46cbd0 in libvirt_virDomainIsActive (self=<optimized
out>, args=<optimized out>) at build/libvirt.c:1288
#11 0x000055a1fb4cb6df in PyCFunction_Call () at ../Objects/methodobject.c:109
Interesting. This is an identical stack trace - so we have 2 python
threads both calling virDomainIsActive(). Nothing wrong with that
per-se - we support multithreaded usage like this.
Curious why it would break.
Can you confirm there are no other threads running libvirt code
in your python app ? Did you have any thread running the libvirt
event loop perhaps ?
So i ran GDB on /usr/sbin/libvirtd to know what was happening:
(gdb) thread all apply bt
Thread 17 (Thread 0x7f241dd40700 (LWP 5100)):
#0 pthread_cond_wait@(a)GLIBC_2.3.2 () at
../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
#1 0x00007f2448240b86 in virCondWait (c=c@entry=0x7f24183eeba8,
m=m@entry=0x7f24183eeb80) at ../../../src/util/virthread.c:154
#2 0x00007f24482416d3 in virThreadPoolWorker
(opaque=opaque@entry=0x55705071a350) at
../../../src/util/virthreadpool.c:124
#3 0x00007f2448240928 in virThreadHelper (data=<optimized out>) at
../../../src/util/virthread.c:206
#4 0x00007f2444b1a494 in start_thread (arg=0x7f241dd40700) at
pthread_create.c:333
#5 0x00007f244485cacf in clone () at
../sysdeps/unix/sysv/linux/x86_64/clone.S:97
Thread 16 (Thread 0x7f241fdfd700 (LWP 3518)):
#0 pthread_cond_wait@(a)GLIBC_2.3.2 () at
../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
#1 0x00007f2448240b86 in virCondWait (c=c@entry=0x55705073e728,
m=m@entry=0x55705073e700) at ../../../src/util/virthread.c:154
#2 0x00007f24482416d3 in virThreadPoolWorker
(opaque=opaque@entry=0x55705073e4b0) at
../../../src/util/virthreadpool.c:124
#3 0x00007f2448240928 in virThreadHelper (data=<optimized out>) at
../../../src/util/virthread.c:206
#4 0x00007f2444b1a494 in start_thread (arg=0x7f241fdfd700) at
pthread_create.c:333
#5 0x00007f244485cacf in clone () at
../sysdeps/unix/sysv/linux/x86_64/clone.S:97
Thread 15 (Thread 0x7f24205fe700 (LWP 3517)):
#0 pthread_cond_wait@(a)GLIBC_2.3.2 () at
../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
#1 0x00007f2448240b86 in virCondWait (c=c@entry=0x55705073e728,
m=m@entry=0x55705073e700) at ../../../src/util/virthread.c:154
#2 0x00007f24482416d3 in virThreadPoolWorker
(opaque=opaque@entry=0x55705071e310) at
../../../src/util/virthreadpool.c:124
#3 0x00007f2448240928 in virThreadHelper (data=<optimized out>) at
../../../src/util/virthread.c:206
#4 0x00007f2444b1a494 in start_thread (arg=0x7f24205fe700) at
pthread_create.c:333
#5 0x00007f244485cacf in clone () at
../sysdeps/unix/sysv/linux/x86_64/clone.S:97
Thread 14 (Thread 0x7f2420dff700 (LWP 3516)):
#0 pthread_cond_wait@(a)GLIBC_2.3.2 () at
../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
#1 0x00007f2448240b86 in virCondWait (c=c@entry=0x55705073e728,
m=m@entry=0x55705073e700) at ../../../src/util/virthread.c:154
#2 0x00007f24482416d3 in virThreadPoolWorker
(opaque=opaque@entry=0x55705073e4b0) at
../../../src/util/virthreadpool.c:124
#3 0x00007f2448240928 in virThreadHelper (data=<optimized out>) at
../../../src/util/virthread.c:206
#4 0x00007f2444b1a494 in start_thread (arg=0x7f2420dff700) at
pthread_create.c:333
#5 0x00007f244485cacf in clone () at
../sysdeps/unix/sysv/linux/x86_64/clone.S:97
Thread 13 (Thread 0x7f2421600700 (LWP 3515)):
#0 pthread_cond_wait@(a)GLIBC_2.3.2 () at
../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
#1 0x00007f2448240b86 in virCondWait (c=c@entry=0x55705073e728,
m=m@entry=0x55705073e700) at ../../../src/util/virthread.c:154
#2 0x00007f24482416d3 in virThreadPoolWorker
(opaque=opaque@entry=0x55705071e250) at
../../../src/util/virthreadpool.c:124
#3 0x00007f2448240928 in virThreadHelper (data=<optimized out>) at
../../../src/util/virthread.c:206
#4 0x00007f2444b1a494 in start_thread (arg=0x7f2421600700) at
pthread_create.c:333
#5 0x00007f244485cacf in clone () at
../sysdeps/unix/sysv/linux/x86_64/clone.S:97
Thread 12 (Thread 0x7f2421e01700 (LWP 3514)):
#0 pthread_cond_wait@(a)GLIBC_2.3.2 () at
../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
#1 0x00007f2448240b86 in virCondWait (c=c@entry=0x55705073e728,
m=m@entry=0x55705073e700) at ../../../src/util/virthread.c:154
#2 0x00007f24482416d3 in virThreadPoolWorker
(opaque=opaque@entry=0x55705073e4b0) at
../../../src/util/virthreadpool.c:124
#3 0x00007f2448240928 in virThreadHelper (data=<optimized out>) at
../../../src/util/virthread.c:206
#4 0x00007f2444b1a494 in start_thread (arg=0x7f2421e01700) at
pthread_create.c:333
#5 0x00007f244485cacf in clone () at
../sysdeps/unix/sysv/linux/x86_64/clone.S:97
Thread 11 (Thread 0x7f2439e14700 (LWP 3513)):
#0 pthread_cond_wait@(a)GLIBC_2.3.2 () at
../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
#1 0x00007f2448240b86 in virCondWait (c=c@entry=0x557050729358,
m=m@entry=0x557050729290) at ../../../src/util/virthread.c:154
#2 0x00007f2448241694 in virThreadPoolWorker
(opaque=opaque@entry=0x55705071b8d0) at
../../../src/util/virthreadpool.c:124
#3 0x00007f2448240928 in virThreadHelper (data=<optimized out>) at
../../../src/util/virthread.c:206
#4 0x00007f2444b1a494 in start_thread (arg=0x7f2439e14700) at
pthread_create.c:333
#5 0x00007f244485cacf in clone () at
../sysdeps/unix/sysv/linux/x86_64/clone.S:97
Thread 10 (Thread 0x7f243a615700 (LWP 3512)):
#0 pthread_cond_wait@(a)GLIBC_2.3.2 () at
../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
#1 0x00007f2448240b86 in virCondWait (c=c@entry=0x557050729358,
m=m@entry=0x557050729290) at ../../../src/util/virthread.c:154
#2 0x00007f2448241694 in virThreadPoolWorker
(opaque=opaque@entry=0x55705071bb10) at
../../../src/util/virthreadpool.c:124
#3 0x00007f2448240928 in virThreadHelper (data=<optimized out>) at
../../../src/util/virthread.c:206
#4 0x00007f2444b1a494 in start_thread (arg=0x7f243a615700) at
pthread_create.c:333
#5 0x00007f244485cacf in clone () at
../sysdeps/unix/sysv/linux/x86_64/clone.S:97
Thread 9 (Thread 0x7f243ae16700 (LWP 3511)):
#0 pthread_cond_wait@(a)GLIBC_2.3.2 () at
../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
#1 0x00007f2448240b86 in virCondWait (c=c@entry=0x557050729358,
m=m@entry=0x557050729290) at ../../../src/util/virthread.c:154
#2 0x00007f2448241694 in virThreadPoolWorker
(opaque=opaque@entry=0x55705071b810) at
../../../src/util/virthreadpool.c:124
#3 0x00007f2448240928 in virThreadHelper (data=<optimized out>) at
../../../src/util/virthread.c:206
#4 0x00007f2444b1a494 in start_thread (arg=0x7f243ae16700) at
pthread_create.c:333
#5 0x00007f244485cacf in clone () at
../sysdeps/unix/sysv/linux/x86_64/clone.S:97
Thread 8 (Thread 0x7f243b617700 (LWP 3510)):
#0 pthread_cond_wait@(a)GLIBC_2.3.2 () at
../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
#1 0x00007f2448240b86 in virCondWait (c=c@entry=0x557050729358,
m=m@entry=0x557050729290) at ../../../src/util/virthread.c:154
#2 0x00007f2448241694 in virThreadPoolWorker
(opaque=opaque@entry=0x55705071b8d0) at
../../../src/util/virthreadpool.c:124
#3 0x00007f2448240928 in virThreadHelper (data=<optimized out>) at
../../../src/util/virthread.c:206
#4 0x00007f2444b1a494 in start_thread (arg=0x7f243b617700) at
pthread_create.c:333
#5 0x00007f244485cacf in clone () at
../sysdeps/unix/sysv/linux/x86_64/clone.S:97
Thread 7 (Thread 0x7f243be18700 (LWP 3509)):
#0 pthread_cond_wait@(a)GLIBC_2.3.2 () at
../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
#1 0x00007f2448240b86 in virCondWait (c=c@entry=0x557050729358,
m=m@entry=0x557050729290) at ../../../src/util/virthread.c:154
#2 0x00007f2448241694 in virThreadPoolWorker
(opaque=opaque@entry=0x55705071bb10) at
../../../src/util/virthreadpool.c:124
#3 0x00007f2448240928 in virThreadHelper (data=<optimized out>) at
../../../src/util/virthread.c:206
#4 0x00007f2444b1a494 in start_thread (arg=0x7f243be18700) at
pthread_create.c:333
#5 0x00007f244485cacf in clone () at
../sysdeps/unix/sysv/linux/x86_64/clone.S:97
Thread 6 (Thread 0x7f243c619700 (LWP 3508)):
#0 pthread_cond_wait@(a)GLIBC_2.3.2 () at
../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
#1 0x00007f2448240b86 in virCondWait (c=c@entry=0x5570507292b8,
m=m@entry=0x557050729290) at ../../../src/util/virthread.c:154
#2 0x00007f24482416d3 in virThreadPoolWorker
(opaque=opaque@entry=0x55705071b810) at
../../../src/util/virthreadpool.c:124
#3 0x00007f2448240928 in virThreadHelper (data=<optimized out>) at
../../../src/util/virthread.c:206
#4 0x00007f2444b1a494 in start_thread (arg=0x7f243c619700) at
pthread_create.c:333
#5 0x00007f244485cacf in clone () at
../sysdeps/unix/sysv/linux/x86_64/clone.S:97
Thread 5 (Thread 0x7f243ce1a700 (LWP 3507)):
#0 pthread_cond_wait@(a)GLIBC_2.3.2 () at
../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
#1 0x00007f2448240b86 in virCondWait (c=c@entry=0x5570507292b8,
m=m@entry=0x557050729290) at ../../../src/util/virthread.c:154
#2 0x00007f24482416d3 in virThreadPoolWorker
(opaque=opaque@entry=0x55705071b8d0) at
../../../src/util/virthreadpool.c:124
#3 0x00007f2448240928 in virThreadHelper (data=<optimized out>) at
../../../src/util/virthread.c:206
#4 0x00007f2444b1a494 in start_thread (arg=0x7f243ce1a700) at
pthread_create.c:333
#5 0x00007f244485cacf in clone () at
../sysdeps/unix/sysv/linux/x86_64/clone.S:97
Thread 4 (Thread 0x7f243d61b700 (LWP 3506)):
#0 pthread_cond_wait@(a)GLIBC_2.3.2 () at
../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
#1 0x00007f2448240b86 in virCondWait (c=c@entry=0x5570507292b8,
m=m@entry=0x557050729290) at ../../../src/util/virthread.c:154
#2 0x00007f24482416d3 in virThreadPoolWorker
(opaque=opaque@entry=0x55705071b990) at
../../../src/util/virthreadpool.c:124
#3 0x00007f2448240928 in virThreadHelper (data=<optimized out>) at
../../../src/util/virthread.c:206
#4 0x00007f2444b1a494 in start_thread (arg=0x7f243d61b700) at
pthread_create.c:333
#5 0x00007f244485cacf in clone () at
../sysdeps/unix/sysv/linux/x86_64/clone.S:97
Thread 3 (Thread 0x7f243de1c700 (LWP 3505)):
#0 pthread_cond_wait@(a)GLIBC_2.3.2 () at
../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
#1 0x00007f2448240b86 in virCondWait (c=c@entry=0x5570507292b8,
m=m@entry=0x557050729290) at ../../../src/util/virthread.c:154
#2 0x00007f24482416d3 in virThreadPoolWorker
(opaque=opaque@entry=0x55705071ba50) at
../../../src/util/virthreadpool.c:124
#3 0x00007f2448240928 in virThreadHelper (data=<optimized out>) at
../../../src/util/virthread.c:206
#4 0x00007f2444b1a494 in start_thread (arg=0x7f243de1c700) at
pthread_create.c:333
#5 0x00007f244485cacf in clone () at
../sysdeps/unix/sysv/linux/x86_64/clone.S:97
Thread 2 (Thread 0x7f243e61d700 (LWP 3504)):
#0 pthread_cond_wait@(a)GLIBC_2.3.2 () at
../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
#1 0x00007f2448240b86 in virCondWait (c=c@entry=0x5570507292b8,
m=m@entry=0x557050729290) at ../../../src/util/virthread.c:154
#2 0x00007f24482416d3 in virThreadPoolWorker
(opaque=opaque@entry=0x55705071bb10) at
../../../src/util/virthreadpool.c:124
#3 0x00007f2448240928 in virThreadHelper (data=<optimized out>) at
../../../src/util/virthread.c:206
#4 0x00007f2444b1a494 in start_thread (arg=0x7f243e61d700) at
pthread_create.c:333
#5 0x00007f244485cacf in clone () at
../sysdeps/unix/sysv/linux/x86_64/clone.S:97
Thread 1 (Thread 0x7f24489f3940 (LWP 3502)):
#0 0x00007f244485367d in poll () at ../sysdeps/unix/syscall-template.S:84
#1 0x00007f24481f304f in poll (__timeout=-1, __nfds=50,
__fds=<optimized out>) at
/usr/include/x86_64-linux-gnu/bits/poll2.h:46
#2 virEventPollRunOnce () at ../../../src/util/vireventpoll.c:641
#3 0x00007f24481f1c21 in virEventRunDefaultImpl () at
../../../src/util/virevent.c:314
#4 0x00007f244835837d in virNetDaemonRun (dmn=0x55705072a330) at
../../../src/rpc/virnetdaemon.c:818
#5 0x000055704f773b87 in main (argc=<optimized out>, argv=<optimized
out>) at ../../../daemon/libvirtd.c:1547
But this doesn't really help me understand why it hangs,
or which threads is processing the client requests that are hanging.
This shows that libvirtd is entirely idle. Thread 1 is the event loop
and waiting for I/O. All the other threads are API workers waiting for
any API call to process. So all completely normal.
Regards,
Daniel
--
|: https://berrange.com -o- https://www.flickr.com/photos/dberrange :|
|: https://libvirt.org -o- https://fstop138.berrange.com :|
|: https://entangle-photo.org -o- https://www.instagram.com/dberrange :|
8:04 a.m.
Are you sure this isa different thread ? It looks identical to the
first
stack trace you give above.
Yes, the first one is calling libvirtmod.virDomainGetState
and the second one libvirtmod.virDomainIsActive.
Interesting. This is an identical stack trace - so we have 2 python
threads both calling virDomainIsActive(). Nothing wrong with that
per-se - we support multithreaded usage like this.
virDomainGetState()
and
virDomainIsActive()
Can you confirm there are no other threads running libvirt code
in your python app ? Did you have any thread running the libvirt
event loop perhaps ?
Actually i found 2 others threads in Python app calling libvirt.
So, as a recap:
Thread 1 - calling virDomainGetState
(gdb) py-bt
Traceback (most recent call first):
<built-in method virDomainGetState of module object at remote 0x7f508e6b1278>
File "/usr/lib/python3/dist-packages/libvirt.py", line 2551, in state
ret = libvirtmod.virDomainGetState(self._o, flags)
(gdb) bt
pthread_cond_wait@(a)GLIBC_2.3.2 () at
../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
#1 0x00007f508dfe2b86 in virCondWait (c=c@entry=0x55a1fe420728,
m=m@entry=0x55a1fde4d2c0) at ../../../src/util/virthread.c:154
#2 0x00007f508e0f5bbb in virNetClientIO (thiscall=0x55a1fe420710,
client=0x55a1fde4d2b0) at ../../../src/rpc/virnetclient.c:1894
#3 virNetClientSendInternal (client=client@entry=0x55a1fde4d2b0,
msg=msg@entry=0x55a1fdd798f0, expectReply=expectReply@entry=true,
nonBlock=nonBlock@entry=false) at ../../../src/rpc/virnetclient.c:2116
#4 0x00007f508e0f7443 in virNetClientSendWithReply
(client=client@entry=0x55a1fde4d2b0, msg=msg@entry=0x55a1fdd798f0) at
../../../src/rpc/virnetclient.c:2144
#5 0x00007f508e0f7bf2 in virNetClientProgramCall
(prog=prog@entry=0x55a1fdff0f90, client=client@entry=0x55a1fde4d2b0,
serial=serial@entry=108, proc=proc@entry=212, noutfds=noutfds@entry=0,
outfds=outfds@entry=0x0, ninfds=0x0,
infds=0x0, args_filter=0x7f508e0f13e0
<xdr_remote_domain_get_state_args>, args=0x7ffd1518cfd0,
ret_filter=0x7f508e0f1410 <xdr_remote_domain_get_state_ret>,
ret=0x7ffd1518cfc8) at ../../../src/rpc/virnetclientprogram.c:329
#6 0x00007f508e0cdeb4 in callFull (priv=priv@entry=0x55a1fe5ac460,
flags=flags@entry=0, fdin=fdin@entry=0x0, fdinlen=fdinlen@entry=0,
fdout=fdout@entry=0x0, fdoutlen=fdoutlen@entry=0x0, proc_nr=212,
args_filter=0x7f508e0f13e0 <xdr_remote_domain_get_state_args>,
args=0x7ffd1518cfd0 "`k.\376\241U", ret_filter=0x7f508e0f1410
<xdr_remote_domain_get_state_ret>, ret=0x7ffd1518cfc8 "",
conn=<optimized out>)
at ../../../src/remote/remote_driver.c:6636
#7 0x00007f508e0d7f90 in call (conn=<optimized out>,
ret=0x7ffd1518cfc8 "", ret_filter=<optimized out>, args=0x7ffd1518cfd0
"`k.\376\241U", args_filter=<optimized out>, proc_nr=212, flags=0,
priv=0x55a1fe5ac460)
at ../../../src/remote/remote_driver.c:6658
#8 remoteDomainGetState (domain=0x55a1fe212da0, state=0x7ffd1518d0a4,
reason=0x7ffd1518d0a8, flags=0) at
../../../src/remote/remote_driver.c:2458
#9 0x00007f508e08e248 in virDomainGetState
(domain=domain@entry=0x55a1fe212da0, state=state@entry=0x7ffd1518d0a4,
reason=reason@entry=0x7ffd1518d0a8, flags=0) at
../../../src/libvirt-domain.c:2495
#10 0x00007f508e466f28 in libvirt_virDomainGetState (self=<optimized
out>, args=<optimized out>) at libvirt-override.c:2539
#11 0x000055a1fb4cb6df in PyCFunction_Call () at ../Objects/methodobject.c:109
Thread 32 - calling virDomainIsActive
(gdb) py-bt
Traceback (most recent call first):
<built-in method virDomainIsActive of module object at remote 0x7f508e6b1278>
File "/usr/lib/python3/dist-packages/libvirt.py", line 1340, in isActive
ret = libvirtmod.virDomainIsActive(self._o)
(gdb) bt
#0 pthread_cond_wait@(a)GLIBC_2.3.2 () at
../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
#1 0x00007f508dfe2b86 in virCondWait (c=c@entry=0x7f4ff051fdc8,
m=m@entry=0x55a1fde4d2c0) at ../../../src/util/virthread.c:154
#2 0x00007f508e0f5bbb in virNetClientIO (thiscall=0x7f4ff051fdb0,
client=0x55a1fde4d2b0) at ../../../src/rpc/virnetclient.c:1894
#3 virNetClientSendInternal (client=client@entry=0x55a1fde4d2b0,
msg=msg@entry=0x7f4ff051fa10, expectReply=expectReply@entry=true,
nonBlock=nonBlock@entry=false) at ../../../src/rpc/virnetclient.c:2116
#4 0x00007f508e0f7443 in virNetClientSendWithReply
(client=client@entry=0x55a1fde4d2b0, msg=msg@entry=0x7f4ff051fa10) at
../../../src/rpc/virnetclient.c:2144
#5 0x00007f508e0f7bf2 in virNetClientProgramCall
(prog=prog@entry=0x55a1fdff0f90, client=client@entry=0x55a1fde4d2b0,
serial=serial@entry=107, proc=proc@entry=150, noutfds=noutfds@entry=0,
outfds=outfds@entry=0x0, ninfds=0x0,
infds=0x0, args_filter=0x7f508e0efe70
<xdr_remote_domain_is_active_args>, args=0x7f4fff7fd040,
ret_filter=0x7f508e0efe90 <xdr_remote_domain_is_active_ret>,
ret=0x7f4fff7fd03c) at ../../../src/rpc/virnetclientprogram.c:329
#6 0x00007f508e0cdeb4 in callFull (priv=priv@entry=0x55a1fe5ac460,
flags=flags@entry=0, fdin=fdin@entry=0x0, fdinlen=fdinlen@entry=0,
fdout=fdout@entry=0x0, fdoutlen=fdoutlen@entry=0x0, proc_nr=150,
args_filter=0x7f508e0efe70 <xdr_remote_domain_is_active_args>,
args=0x7f4fff7fd040 "`k.\376\241U", ret_filter=0x7f508e0efe90
<xdr_remote_domain_is_active_ret>, ret=0x7f4fff7fd03c "",
conn=<optimized out>)
at ../../../src/remote/remote_driver.c:6636
#7 0x00007f508e0d71cb in call (conn=<optimized out>,
ret=0x7f4fff7fd03c "", ret_filter=<optimized out>, args=0x7f4fff7fd040
"`k.\376\241U", args_filter=<optimized out>, proc_nr=150, flags=0,
priv=0x55a1fe5ac460)
at ../../../src/remote/remote_driver.c:6658
#8 remoteDomainIsActive (dom=0x55a1fe212da0) at
../../../src/remote/remote_client_bodies.h:2842
#9 0x00007f508e09df03 in virDomainIsActive
(dom=dom@entry=0x55a1fe212da0) at ../../../src/libvirt-domain.c:8467
#10 0x00007f508e46cbd0 in libvirt_virDomainIsActive (self=<optimized
out>, args=<optimized out>) at build/libvirt.c:1288
#11 0x000055a1fb4cb6df in PyCFunction_Call () at ../Objects/methodobject.c:109
Thread 35 - calling virDomainGetXMLDesc
(gdb) py-bt
<built-in method virDomainGetXMLDesc of module object at remote
0x7f508e6b1278>
File "/usr/lib/python3/dist-packages/libvirt.py", line 491, in XMLDesc
ret = libvirtmod.virDomainGetXMLDesc(self._o, flags)
(gdb) bt
#0 pthread_sigmask (how=how@entry=0, newmask=<optimized out>,
newmask@entry=0x7f4ffd7f8d10, oldmask=oldmask@entry=0x7f4ffd7f8c90) at
../sysdeps/unix/sysv/linux/pthread_sigmask.c:50
#1 0x00007f508e0f52fa in virNetClientIOEventLoop
(client=client@entry=0x55a1fde4d2b0,
thiscall=thiscall@entry=0x7f4fe005a350) at
../../../src/rpc/virnetclient.c:1659
#2 0x00007f508e0f5a16 in virNetClientIO (thiscall=0x7f4fe005a350,
client=0x55a1fde4d2b0) at ../../../src/rpc/virnetclient.c:1944
#3 virNetClientSendInternal (client=client@entry=0x55a1fde4d2b0,
msg=msg@entry=0x7f4fe0031f50, expectReply=expectReply@entry=true,
nonBlock=nonBlock@entry=false) at ../../../src/rpc/virnetclient.c:2116
#4 0x00007f508e0f7443 in virNetClientSendWithReply
(client=client@entry=0x55a1fde4d2b0, msg=msg@entry=0x7f4fe0031f50) at
../../../src/rpc/virnetclient.c:2144
#5 0x00007f508e0f7bf2 in virNetClientProgramCall
(prog=prog@entry=0x55a1fdff0f90, client=client@entry=0x55a1fde4d2b0,
serial=serial@entry=105, proc=proc@entry=14, noutfds=noutfds@entry=0,
outfds=outfds@entry=0x0, ninfds=0x0,
infds=0x0, args_filter=0x7f508e0ecba0
<xdr_remote_domain_get_xml_desc_args>, args=0x7f4ffd7f8fe0,
ret_filter=0x7f508e0ecbd0 <xdr_remote_domain_get_xml_desc_ret>,
ret=0x7f4ffd7f8fd8)
at ../../../src/rpc/virnetclientprogram.c:329
#6 0x00007f508e0cdeb4 in callFull (priv=priv@entry=0x55a1fe5ac460,
flags=flags@entry=0, fdin=fdin@entry=0x0, fdinlen=fdinlen@entry=0,
fdout=fdout@entry=0x0, fdoutlen=fdoutlen@entry=0x0, proc_nr=14,
args_filter=0x7f508e0ecba0 <xdr_remote_domain_get_xml_desc_args>,
args=0x7f4ffd7f8fe0 "`k.\376\241U", ret_filter=0x7f508e0ecbd0
<xdr_remote_domain_get_xml_desc_ret>, ret=0x7f4ffd7f8fd8 "",
conn=<optimized out>)
at ../../../src/remote/remote_driver.c:6636
#7 0x00007f508e0d7b58 in call (conn=<optimized out>,
ret=0x7f4ffd7f8fd8 "", ret_filter=<optimized out>, args=0x7f4ffd7f8fe0
"`k.\376\241U", args_filter=<optimized out>, proc_nr=14, flags=0,
priv=0x55a1fe5ac460)
at ../../../src/remote/remote_driver.c:6658
#8 remoteDomainGetXMLDesc (dom=<optimized out>, flags=0) at
../../../src/remote/remote_client_bodies.h:2698
#9 0x00007f508e08f5c1 in virDomainGetXMLDesc
(domain=domain@entry=0x55a1fe212da0, flags=0) at
../../../src/libvirt-domain.c:2592
#10 0x00007f508e46c8c0 in libvirt_virDomainGetXMLDesc (self=<optimized
out>, args=<optimized out>) at build/libvirt.c:1212
#11 0x000055a1fb4cb6df in PyCFunction_Call () at ../Objects/methodobject.c:109
Thread 36 - calling virDomainQemuMonitorCommand
(gdb) py-bt
<built-in method virDomainQemuMonitorCommand of module object at
remote 0x7f506e317908>
File "/usr/lib/python3/dist-packages/libvirt_qemu.py", line 71, in
qemuMonitorCommand
ret = libvirtmod_qemu.virDomainQemuMonitorCommand(domain._o, cmd, flags)
(gdb)
#0 pthread_cond_wait@(a)GLIBC_2.3.2 () at
../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
#1 0x00007f508dfe2b86 in virCondWait (c=c@entry=0x7f4fe80da208,
m=m@entry=0x55a1fde4d2c0) at ../../../src/util/virthread.c:154
#2 0x00007f508e0f5bbb in virNetClientIO (thiscall=0x7f4fe80da1f0,
client=0x55a1fde4d2b0) at ../../../src/rpc/virnetclient.c:1894
#3 virNetClientSendInternal (client=client@entry=0x55a1fde4d2b0,
msg=msg@entry=0x7f4fe80da160, expectReply=expectReply@entry=true,
nonBlock=nonBlock@entry=false) at ../../../src/rpc/virnetclient.c:2116
#4 0x00007f508e0f7443 in virNetClientSendWithReply
(client=client@entry=0x55a1fde4d2b0, msg=msg@entry=0x7f4fe80da160) at
../../../src/rpc/virnetclient.c:2144
#5 0x00007f508e0f7bf2 in virNetClientProgramCall
(prog=prog@entry=0x55a1fe2b5ae0, client=client@entry=0x55a1fde4d2b0,
serial=serial@entry=106, proc=proc@entry=1, noutfds=noutfds@entry=0,
outfds=outfds@entry=0x0, ninfds=0x0,
infds=0x0, args_filter=0x7f508e0f34f0
<xdr_qemu_domain_monitor_command_args>, args=0x7f4ffe7fb1a0,
ret_filter=0x7f508e0f3540 <xdr_qemu_domain_monitor_command_ret>,
ret=0x7f4ffe7fb198)
at ../../../src/rpc/virnetclientprogram.c:329
#6 0x00007f508e0cdeb4 in callFull (priv=priv@entry=0x55a1fe5ac460,
flags=flags@entry=1, fdin=fdin@entry=0x0, fdinlen=fdinlen@entry=0,
fdout=fdout@entry=0x0, fdoutlen=fdoutlen@entry=0x0, proc_nr=1,
args_filter=0x7f508e0f34f0 <xdr_qemu_domain_monitor_command_args>,
args=0x7f4ffe7fb1a0 "`k.\376\241U", ret_filter=0x7f508e0f3540
<xdr_qemu_domain_monitor_command_ret>, ret=0x7f4ffe7fb198 "",
conn=<optimized out>)
at ../../../src/remote/remote_driver.c:6636
#7 0x00007f508e0dda39 in call (conn=<optimized out>, ret=<optimized
out>, ret_filter=<optimized out>, args=<optimized out>,
args_filter=<optimized out>, proc_nr=1, flags=1, priv=0x55a1fe5ac460)
at ../../../src/remote/remote_driver.c:6658
#8 remoteDomainQemuMonitorCommand (domain=0x55a1fe212da0,
cmd=<optimized out>, result=0x7f4ffe7fb290, flags=<optimized out>) at
../../../src/remote/remote_driver.c:5993
#9 0x00007f506deaeda5 in virDomainQemuMonitorCommand
(domain=domain@entry=0x55a1fe212da0, cmd=0x7f506c9b3690 "mouse_move
385 212", result=result@entry=0x7f4ffe7fb290, flags=1) at
../../../src/libvirt-qemu.c:86
#10 0x00007f506e0b50cc in libvirt_qemu_virDomainQemuMonitorCommand
(self=<optimized out>, args=<optimized out>) at
libvirt-qemu-override.c:146
#11 0x000055a1fb4cb6df in PyCFunction_Call () at ../Objects/methodobject.c:109
Thank you.
--
Mathieu Tarral
8:12 a.m.
On Tue, Mar 27, 2018 at 04:04:33PM +0300, Mathieu Tarral wrote:
> Are you sure this isa different thread ? It looks identical to
the first
> stack trace you give above.
Yes, the first one is calling libvirtmod.virDomainGetState
and the second one libvirtmod.virDomainIsActive.
> Interesting. This is an identical stack trace - so we have 2 python
> threads both calling virDomainIsActive(). Nothing wrong with that
> per-se - we support multithreaded usage like this.
virDomainGetState()
and
virDomainIsActive()
Opps, yes i see.
> Can you confirm there are no other threads running libvirt code
> in your python app ? Did you have any thread running the libvirt
> event loop perhaps ?
Actually i found 2 others threads in Python app calling libvirt.
So, as a recap:
(gdb) bt
#0 pthread_sigmask (how=how@entry=0, newmask=<optimized out>,
newmask@entry=0x7f4ffd7f8d10, oldmask=oldmask@entry=0x7f4ffd7f8c90) at
../sysdeps/unix/sysv/linux/pthread_sigmask.c:50
This is slightly unusual - pthread_sigmask() should complete in a tiny
fraction of a second, so seeing it in the stack trace is odd unless you
have very fortuitous timing when taking the stack trace.
#1 0x00007f508e0f52fa in virNetClientIOEventLoop
(client=client@entry=0x55a1fde4d2b0,
thiscall=thiscall@entry=0x7f4fe005a350) at
../../../src/rpc/virnetclient.c:1659
#2 0x00007f508e0f5a16 in virNetClientIO (thiscall=0x7f4fe005a350,
client=0x55a1fde4d2b0) at ../../../src/rpc/virnetclient.c:1944
#3 virNetClientSendInternal (client=client@entry=0x55a1fde4d2b0,
msg=msg@entry=0x7f4fe0031f50, expectReply=expectReply@entry=true,
nonBlock=nonBlock@entry=false) at ../../../src/rpc/virnetclient.c:2116
#4 0x00007f508e0f7443 in virNetClientSendWithReply
(client=client@entry=0x55a1fde4d2b0, msg=msg@entry=0x7f4fe0031f50) at
../../../src/rpc/virnetclient.c:2144
#5 0x00007f508e0f7bf2 in virNetClientProgramCall
(prog=prog@entry=0x55a1fdff0f90, client=client@entry=0x55a1fde4d2b0,
serial=serial@entry=105, proc=proc@entry=14, noutfds=noutfds@entry=0,
outfds=outfds@entry=0x0, ninfds=0x0,
infds=0x0, args_filter=0x7f508e0ecba0
<xdr_remote_domain_get_xml_desc_args>, args=0x7f4ffd7f8fe0,
ret_filter=0x7f508e0ecbd0 <xdr_remote_domain_get_xml_desc_ret>,
ret=0x7f4ffd7f8fd8)
at ../../../src/rpc/virnetclientprogram.c:329
#6 0x00007f508e0cdeb4 in callFull (priv=priv@entry=0x55a1fe5ac460,
flags=flags@entry=0, fdin=fdin@entry=0x0, fdinlen=fdinlen@entry=0,
fdout=fdout@entry=0x0, fdoutlen=fdoutlen@entry=0x0, proc_nr=14,
args_filter=0x7f508e0ecba0 <xdr_remote_domain_get_xml_desc_args>,
args=0x7f4ffd7f8fe0 "`k.\376\241U", ret_filter=0x7f508e0ecbd0
<xdr_remote_domain_get_xml_desc_ret>, ret=0x7f4ffd7f8fd8 "",
conn=<optimized out>)
at ../../../src/remote/remote_driver.c:6636
#7 0x00007f508e0d7b58 in call (conn=<optimized out>,
ret=0x7f4ffd7f8fd8 "", ret_filter=<optimized out>, args=0x7f4ffd7f8fe0
"`k.\376\241U", args_filter=<optimized out>, proc_nr=14, flags=0,
priv=0x55a1fe5ac460)
at ../../../src/remote/remote_driver.c:6658
#8 remoteDomainGetXMLDesc (dom=<optimized out>, flags=0) at
../../../src/remote/remote_client_bodies.h:2698
#9 0x00007f508e08f5c1 in virDomainGetXMLDesc
(domain=domain@entry=0x55a1fe212da0, flags=0) at
../../../src/libvirt-domain.c:2592
#10 0x00007f508e46c8c0 in libvirt_virDomainGetXMLDesc (self=<optimized
out>, args=<optimized out>) at build/libvirt.c:1212
#11 0x000055a1fb4cb6df in PyCFunction_Call () at ../Objects/methodobject.c:109
Aside from the thing mentioned above I don't see any reason why you would
have bad problems here.
I don't have much more useful to suggest, other than to try using the very
latest libvirt to see if you get the same behaviour. If not, then it would
point to a bug in old libvirt, but I don't recall anything that would cause
this behaviour you see offhand.
Regards,
Daniel
--
|: https://berrange.com -o- https://www.flickr.com/photos/dberrange :|
|: https://libvirt.org -o- https://fstop138.berrange.com :|
|: https://entangle-photo.org -o- https://www.instagram.com/dberrange :|
5:13 a.m.
Hi,
thanks for your answer Daniel.
I think the best way to get more information about this bug is to reproduce it
with libvirt master branch.
However, i'm facing an issue when i try to run my own daemon: there is
a chid process
which is failing in a loop.
I used sudo strace -f ./libvirtd to watch all child processes, and
this is the output:
https://gist.github.com/Wenzel/620327a9b3b7e13454108c2e472eaa77
One of them is continously failing, and i don't clearly understand why.
Does this log file can help you identify the cause maybe ?
I'm here to provide more information if needed.
Thank you !
2018-03-27 16:12 GMT+03:00 Daniel P. Berrangé <berrange(a)redhat.com>:
On Tue, Mar 27, 2018 at 04:04:33PM +0300, Mathieu Tarral wrote:
> > Are you sure this isa different thread ? It looks identical to the first
> > stack trace you give above.
>
> Yes, the first one is calling libvirtmod.virDomainGetState
> and the second one libvirtmod.virDomainIsActive.
>
> > Interesting. This is an identical stack trace - so we have 2 python
> > threads both calling virDomainIsActive(). Nothing wrong with that
> > per-se - we support multithreaded usage like this.
>
> virDomainGetState()
> and
> virDomainIsActive()
Opps, yes i see.
> > Can you confirm there are no other threads running libvirt code
> > in your python app ? Did you have any thread running the libvirt
> > event loop perhaps ?
>
> Actually i found 2 others threads in Python app calling libvirt.
>
> So, as a recap:
>
> (gdb) bt
> #0 pthread_sigmask (how=how@entry=0, newmask=<optimized out>,
> newmask@entry=0x7f4ffd7f8d10, oldmask=oldmask@entry=0x7f4ffd7f8c90) at
> ../sysdeps/unix/sysv/linux/pthread_sigmask.c:50
This is slightly unusual - pthread_sigmask() should complete in a tiny
fraction of a second, so seeing it in the stack trace is odd unless you
have very fortuitous timing when taking the stack trace.
> #1 0x00007f508e0f52fa in virNetClientIOEventLoop
> (client=client@entry=0x55a1fde4d2b0,
> thiscall=thiscall@entry=0x7f4fe005a350) at
> ../../../src/rpc/virnetclient.c:1659
> #2 0x00007f508e0f5a16 in virNetClientIO (thiscall=0x7f4fe005a350,
> client=0x55a1fde4d2b0) at ../../../src/rpc/virnetclient.c:1944
> #3 virNetClientSendInternal (client=client@entry=0x55a1fde4d2b0,
> msg=msg@entry=0x7f4fe0031f50, expectReply=expectReply@entry=true,
> nonBlock=nonBlock@entry=false) at ../../../src/rpc/virnetclient.c:2116
> #4 0x00007f508e0f7443 in virNetClientSendWithReply
> (client=client@entry=0x55a1fde4d2b0, msg=msg@entry=0x7f4fe0031f50) at
> ../../../src/rpc/virnetclient.c:2144
> #5 0x00007f508e0f7bf2 in virNetClientProgramCall
> (prog=prog@entry=0x55a1fdff0f90, client=client@entry=0x55a1fde4d2b0,
> serial=serial@entry=105, proc=proc@entry=14, noutfds=noutfds@entry=0,
> outfds=outfds@entry=0x0, ninfds=0x0,
> infds=0x0, args_filter=0x7f508e0ecba0
> <xdr_remote_domain_get_xml_desc_args>, args=0x7f4ffd7f8fe0,
> ret_filter=0x7f508e0ecbd0 <xdr_remote_domain_get_xml_desc_ret>,
> ret=0x7f4ffd7f8fd8)
> at ../../../src/rpc/virnetclientprogram.c:329
> #6 0x00007f508e0cdeb4 in callFull (priv=priv@entry=0x55a1fe5ac460,
> flags=flags@entry=0, fdin=fdin@entry=0x0, fdinlen=fdinlen@entry=0,
> fdout=fdout@entry=0x0, fdoutlen=fdoutlen@entry=0x0, proc_nr=14,
> args_filter=0x7f508e0ecba0 <xdr_remote_domain_get_xml_desc_args>,
> args=0x7f4ffd7f8fe0 "`k.\376\241U", ret_filter=0x7f508e0ecbd0
> <xdr_remote_domain_get_xml_desc_ret>, ret=0x7f4ffd7f8fd8 "",
> conn=<optimized out>)
> at ../../../src/remote/remote_driver.c:6636
> #7 0x00007f508e0d7b58 in call (conn=<optimized out>,
> ret=0x7f4ffd7f8fd8 "", ret_filter=<optimized out>,
args=0x7f4ffd7f8fe0
> "`k.\376\241U", args_filter=<optimized out>, proc_nr=14, flags=0,
> priv=0x55a1fe5ac460)
> at ../../../src/remote/remote_driver.c:6658
> #8 remoteDomainGetXMLDesc (dom=<optimized out>, flags=0) at
> ../../../src/remote/remote_client_bodies.h:2698
> #9 0x00007f508e08f5c1 in virDomainGetXMLDesc
> (domain=domain@entry=0x55a1fe212da0, flags=0) at
> ../../../src/libvirt-domain.c:2592
> #10 0x00007f508e46c8c0 in libvirt_virDomainGetXMLDesc (self=<optimized
> out>, args=<optimized out>) at build/libvirt.c:1212
> #11 0x000055a1fb4cb6df in PyCFunction_Call () at ../Objects/methodobject.c:109
Aside from the thing mentioned above I don't see any reason why you would
have bad problems here.
I don't have much more useful to suggest, other than to try using the very
latest libvirt to see if you get the same behaviour. If not, then it would
point to a bug in old libvirt, but I don't recall anything that would cause
this behaviour you see offhand.
Regards,
Daniel
--
|: https://berrange.com -o- https://www.flickr.com/photos/dberrange :|
|: https://libvirt.org -o- https://fstop138.berrange.com :|
|: https://entangle-photo.org -o- https://www.instagram.com/dberrange :|
--
Mathieu Tarral
8:31 a.m.
Hi Daniel,
Thanks for your help, i was able to run the libvirt daemon from master,
and after add some debug messages, i understood that the call
to virDomainIsActive was actually hanging from the client.
It never reached the daemon.
Looking back at the call again:
https://gist.github.com/Wenzel/624cb8c0746c05bd824d2b3c04b6b9f9
The call is waiting for pthread_sigmask to return.
Looking into the libvirt source code (3.0.0) at the location of the call:
https://github.com/libvirt/libvirt/blob/v3.0.0/src/rpc/virnetclient.c?utf...
Is this supposed to be an instant call, or does it wait for specific
conditions/event to return ?
Any idea what might go wrong ?
Thank you.
--
Mathieu Tarral
8:52 a.m.
On Thu, Jun 14, 2018 at 04:31:57PM +0300, Mathieu Tarral wrote:
Hi Daniel,
Thanks for your help, i was able to run the libvirt daemon from master,
and after add some debug messages, i understood that the call
to virDomainIsActive was actually hanging from the client.
It never reached the daemon.
Looking back at the call again:
https://gist.github.com/Wenzel/624cb8c0746c05bd824d2b3c04b6b9f9
The call is waiting for pthread_sigmask to return.
Looking into the libvirt source code (3.0.0) at the location of the call:
https://github.com/libvirt/libvirt/blob/v3.0.0/src/rpc/virnetclient.c?utf...
Is this supposed to be an instant call, or does it wait for specific
conditions/event to return ?
Yeah this is very bad - pthread_sigmask should be instantaneous, and I
can't imagine what would make it hang besides severe memory corruption
somewhere :-(
Regards,
Daniel
--
|: https://berrange.com -o- https://www.flickr.com/photos/dberrange :|
|: https://libvirt.org -o- https://fstop138.berrange.com :|
|: https://entangle-photo.org -o- https://www.instagram.com/dberrange :|
8:56 a.m.
On 03/22/2018 05:10 PM, Mathieu Tarral wrote:
Hi !
I'm submitting my messages on this mailing list to request a bit of
help on a case that I have
where a Python application makes a call to virDomainIsActive, and the
call never returns.
I have tried to investigate, but as there are no debug symbols for
libvirt on Debian Stretch,
i can only have the following GDB backtrace:
(gdb) bt
#0 pthread_cond_wait@(a)GLIBC_2.3.2 () at
../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
#1 0x00007f49026f5b76 in virCondWait () from /usr/lib/libvirt.so.0
#2 0x00007f4902808bab in ?? () from /usr/lib/libvirt.so.0
#3 0x00007f490280a433 in virNetClientSendWithReply () from
/usr/lib/libvirt.so.0
#4 0x00007f490280abe2 in virNetClientProgramCall () from /usr/lib/libvirt.so.0
#5 0x00007f49027e0ea4 in ?? () from /usr/lib/libvirt.so.0
#6 0x00007f49027ea1bb in ?? () from /usr/lib/libvirt.so.0
#7 0x00007f49027b0ef3 in virDomainIsActive () from /usr/lib/libvirt.so.0
#8 0x00007f4902b7fbd0 in libvirt_virDomainIsActive () from
/usr/lib/python3/dist-packages/libvirtmod.cpython-35m-x86_64-linux-gnu.so
#9 0x0000558eeec696df in PyCFunction_Call () at ../Objects/methodobject.c:109
This is just a client waiting for server's reply. You want to attach gdb
to corresponding daemon and run 't a a bt' (thread apply all backtrace).
Libvirtd is multithreaded and one of the threads will be executing your API.
Michal
2352
days inactive
2436
days old
11 comments
5 participants
participants (5)
-
Daniel P. Berrangé -
Erik Skultety -
Mathieu Tarral -
Michal Privoznik -
Pino Toscano