[libvirt] [PATCH v4 00/23] Introduce metadata locking

Thu Sep 27 07:57:43 UTC 2018

On Thu, Sep 27, 2018 at 09:01 AM +0200, Bjoern Walk <bwalk at linux.ibm.com> wrote:
> Michal Privoznik <mprivozn at redhat.com> [2018-09-19, 11:45AM +0200]:
>> On 09/19/2018 11:17 AM, Bjoern Walk wrote:
>> > Bjoern Walk <bwalk at linux.ibm.com> [2018-09-12, 01:17PM +0200]:
>> >> Michal Privoznik <mprivozn at redhat.com> [2018-09-12, 11:32AM +0200]:
>>
>> >>
>> >
>> > Still seeing the same timeout. Is this expected behaviour?
>> >
>>
>> Nope. I wonder if something has locked the path and forgot to unlock it
>> (however, virtlockd should have unlocked all the paths owned by PID on
>> connection close), or something is still holding the lock and connection
>> opened.
>>
>> Can you see the timeout even when you turn off the selinux driver
>> (security_driver="none' in qemu.conf)? I tried to reproduce the issue
>> yesterday and was unsuccessful. Do you have any steps to reproduce?
>
> So, I haven't been able to actually dig into the debugging but we have
> been able to reproduce this behaviour on x86 (both with SELinux and
> DAC). Looks like a general problem, if a problem at all, because from
> what I can see in the code, the 60 seconds timeout is actually intended,
> or not? The security manager does try for 60 seconds to acquire the lock
> and only then bails out. Why is this?

Backtrace of libvirtd where it’s hanging (in thread A)

(gdb) bt
#0 read () from /lib64/libpthread.so.0
#1 read (__nbytes=1024, __buf=0x7f84e401afd0, __fd=31) at /usr/include/bits/unistd.h:44
#2 saferead (fd=fd at entry=31, buf=0x7f84e401afd0, count=count at entry=1024) at util/virfile.c:1061
#3 saferead_lim (fd=31, max_len=max_len at entry=1024, length=length at entry=0x7f84f3fa8240) at util/virfile.c:1345
#4 virFileReadHeaderFD (fd=<optimized out>, maxlen=maxlen at entry=1024, buf=buf at entry=0x7f84f3fa8278) at util/virfile.c:1376
#5 virProcessRunInMountNamespace () at util/virprocess.c:1149
#6 virSecuritySELinuxTransactionCommit (mgr=<optimized out>, pid=23977) at security/security_selinux.c:1106
#7 virSecurityManagerTransactionCommit (mgr=0x7f848c0ffd60, pid=pid at entry=23977) at security/security_manager.c:324
#8 virSecurityStackTransactionCommit (mgr=<optimized out>, pid=23977) at security/security_stack.c:166
#9 virSecurityManagerTransactionCommit (mgr=0x7f848c183760, pid=pid at entry=23977) at security/security_manager.c:324
#10 qemuSecuritySetAllLabel (driver=driver at entry=0x7f848c108c60, vm=vm at entry=0x7f848c1c3a50, stdin_path=stdin_path at entry=0x0) at _security.c:56
#11 in qemuProcessLaunch (conn=conn at entry=0x7f84c0003e40, driver=driver at entry=0x7f848c108c60, vm=vm at entry=0x7f848c1c3a50, asyncJob=a=QEMU_ASYNC_JOB_START, incoming=incoming at entry=0x0, snapshot=snapshot at entry=0x0, vmop=VIR_NETDEV_VPORT_PROFILE_OP_CREATE, flags=1 qemu/qemu_process.c:6329
#12 in qemuProcessStart (conn=conn at entry=0x7f84c0003e40,
driver=driver at entry=0x7f848c108c60, vm=vm at entry=0x7f848c1c3a50,
updatedCPU==0x0, asyncJob=asyncJob at entry=QEMU_ASYNC_JOB_START,
migrateFrom=migrateFrom at entry=0x0, migrateFd=-1, migratePath=0x0,
snapshot=0x=VIR_NETDEV_VPORT_PROFILE_OP_CREATE, flags=17) at
qemu/qemu_process.c:6816

…

#25 in start_thread () from /lib64/libpthread.so.0
#26 in clone () from /lib64/libc.so.6

Backtrace of the forked process where the process is trying to get the
meta data lock for 60 seconds.

#0  0x00007f8508572730 in nanosleep () from target:/lib64/libc.so.6
#1  0x00007f850859dff4 in usleep () from target:/lib64/libc.so.6
#2  0x00007f850c26efea in virTimeBackOffWait (var=var at entry=0x7f84f3fa81a0) at util/virtime.c:453
#3  0x00007f850c3108d8 in virSecurityManagerMetadataLock (mgr=0x7f848c183850, paths=<optimized out>, npaths=<optimized out>) at security/security_manager.c:1345
#4  0x00007f850c30e44b in virSecurityDACTransactionRun (pid=pid at entry=23977, opaque=opaque at entry=0x7f84e4021450) at security/security_dac.c:226
#5  0x00007f850c250021 in virProcessNamespaceHelper (opaque=0x7f84e4021450, cb=0x7f850c30e330 <virSecurityDACTransactionRun>, pid=23977, errfd=33) at util/virprocess.c:1100
#6  virProcessRunInMountNamespace () at util/virprocess.c:1140
#7  0x00007f850c30e55c in virSecurityDACTransactionCommit (mgr=<optimized out>, pid=23977) at security/security_dac.c:565
#8  0x00007f850c30eeca in virSecurityManagerTransactionCommit (mgr=0x7f848c183850, pid=pid at entry=23977) at security/security_manager.c:324
#9  0x00007f850c30b36b in virSecurityStackTransactionCommit (mgr=<optimized out>, pid=23977) at security/security_stack.c:166
#10 0x00007f850c30eeca in virSecurityManagerTransactionCommit (mgr=0x7f848c183760, pid=pid at entry=23977) at security/security_manager.c:324
#11 0x00007f84e0586bf2 in qemuSecuritySetAllLabel (driver=driver at entry=0x7f848c108c60, vm=vm at entry=0x7f848c1c3a50, stdin_path=stdin_path at entry=0x0) at qemu/qemu_security.c:56
#12 0x00007f84e051b7fd in qemuProcessLaunch (conn=conn at entry=0x7f84c0003e40, driver=driver at entry=0x7f848c108c60, vm=vm at entry=0x7f848c1c3a50, asyncJob=asyncJob at entry=QEMU_ASYNC_JOB_START, incoming=incoming at entry=0x0, snapshot=snapshot at entry=0x0, vmop=VIR_NETDEV_VPORT_PROFILE_OP_CREATE, flags=17) at qemu/qemu_process.c:6329
#13 0x00007f84e051ee2e in qemuProcessStart (conn=conn at entry=0x7f84c0003e40, driver=driver at entry=0x7f848c108c60, vm=vm at entry=0x7f848c1c3a50, updatedCPU=updatedCPU at entry=0x0, asyncJob=asyncJob at entry=QEMU_ASYNC_JOB_START, migrateFrom=migrateFrom at entry=0x0, migrateFd=-1, migratePath=0x0, snapshot=0x0, vmop=VIR_NETDEV_VPORT_PROFILE_OP_CREATE, flags=17) at qemu/qemu_process.c:6816
#14 0x00007f84e057f5cd in qemuDomainObjStart (conn=0x7f84c0003e40, driver=driver at entry=0x7f848c108c60, vm=0x7f848c1c3a50, flags=flags at entry=0, asyncJob=QEMU_ASYNC_JOB_START) at qemu/qemu_driver.c:7296
#15 0x00007f84e057fc19 in qemuDomainCreateWithFlags (dom=0x7f84e4001620, flags=0) at qemu/qemu_driver.c:7349
#16 0x00007f850c426d57 in virDomainCreate (domain=domain at entry=0x7f84e4001620) at libvirt-domain.c:6534
#17 0x000055a82b2f1cae in remoteDispatchDomainCreate (server=0x55a82c9e16d0, msg=0x55a82ca53e00, args=<optimized out>, rerr=0x7f84f3fa8960, client=0x55a82ca5d180) at remote/remote_daemon_dispatch_stubs.h:4434
#18 remoteDispatchDomainCreateHelper (server=0x55a82c9e16d0, client=0x55a82ca5d180, msg=0x55a82ca53e00, rerr=0x7f84f3fa8960, args=<optimized out>, ret=0x7f84e4003800) at remote/remote_daemon_dispatch_stubs.h:4410
#19 0x00007f850c338734 in virNetServerProgramDispatchCall (msg=0x55a82ca53e00, client=0x55a82ca5d180, server=0x55a82c9e16d0, prog=0x55a82ca4be70) at rpc/virnetserverprogram.c:437
#20 virNetServerProgramDispatch (prog=0x55a82ca4be70, server=server at entry=0x55a82c9e16d0, client=0x55a82ca5d180, msg=0x55a82ca53e00) at rpc/virnetserverprogram.c:304
#21 0x00007f850c33ec3c in virNetServerProcessMsg (msg=<optimized out>, prog=<optimized out>, client=<optimized out>, srv=0x55a82c9e16d0) at rpc/virnetserver.c:144
#22 virNetServerHandleJob (jobOpaque=<optimized out>, opaque=0x55a82c9e16d0) at rpc/virnetserver.c:165
#23 0x00007f850c26db20 in virThreadPoolWorker (opaque=opaque at entry=0x55a82c9ebe30) at util/virthreadpool.c:167
#24 0x00007f850c26ce2c in virThreadHelper (data=<optimized out>) at util/virthread.c:206
#25 0x00007f8508872594 in start_thread () from target:/lib64/libpthread.so.0
#26 0x00007f85085a5e6f in clone () from target:/lib64/libc.so.6

>
> However, an actual bug is that while the security manager waits for the
> lock acquire the whole libvirtd hangs, but from what I understood and
> Marc explained to me, this is more of a pathological error in libvirt
> behaviour with various domain locks.

Since thread A owns the lock for the virDomainObjList other operations
like 'virsh list' won’t return for about 60s.

Hope this information will help :)

>
> --
> IBM Systems
> Linux on Z & Virtualization Development
> --------------------------------------------------
> IBM Deutschland Research & Development GmbH
> Schönaicher Str. 220, 71032 Böblingen
> Phone: +49 7031 16 1819
> --------------------------------------------------
> Vorsitzende des Aufsichtsrats: Martina Koederitz
> Geschäftsführung: Dirk Wittkopp
> Sitz der Gesellschaft: Böblingen
> Registergericht: Amtsgericht Stuttgart, HRB 243294
--
Kind regards / Beste Grüße
   Marc Hartmayer

IBM Deutschland Research & Development GmbH
Vorsitzende des Aufsichtsrats: Martina Koederitz
Geschäftsführung: Dirk Wittkopp
Sitz der Gesellschaft: Böblingen
Registergericht: Amtsgericht Stuttgart, HRB 243294