First: all of those backtrace is our private libvirt version backtrace. I find opensource also have this problem
1、backtrace of child
(gdb) bt
#0 __lll_lock_wait_private () at ../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:95
#1 0x00007fcd26f7299c in _L_lock_2462 () at tzset.c:621
#2 0x00007fcd26f727d7 in __tz_convert (timer=0x7fcd2727fec0 <tzset_lock>, timer@entry=0x7fcd1a694068, use_localtime=use_localtime@entry=0, tp=tp@entry=0x7fcd1a694070) at tzset.c:624
#3 0x00007fcd26f7075a in __GI___gmtime_r (t=t@entry=0x7fcd1a694068, tp=tp@entry=0x7fcd1a694070) at gmtime.c:28
#4 0x00007fcd2a06b41d in virTimeLocalOffsetFromUTC (offset=offset@entry=0x7fcd1a6940e0) at util/virtime.c:385
#5 0x00007fcd2a06b560 in virTimeStringNowRaw (buf=buf@entry=0x7fcd1a6941a0 "\023") at util/virtime.c:222
#6 0x00007fcd2a034e7e in virLogVMessage (source=<optimized out>, priority=VIR_LOG_INFO, filename=0x7fcd2a28c04a "security/security_dac.c", linenr=556, funcname=0x7fcd2a28c940 <__func__.22722> "virSecurityDACSetOwnershipInternal", metadata=0x0, fmt=fmt@entry=0x7fcd2a28c2f8 "Setting DAC user and group on '%s' to '%ld:%ld'", vargs=vargs@entry=0x7fcd1a694220) at util/virlog.c:585
#7 0x00007fcd2a035427 in virLogMessage (source=source@entry=0x7fcd2a519d90 <virLogSelf>, priority=priority@entry=VIR_LOG_INFO, filename=filename@entry=0x7fcd2a28c04a "security/security_dac.c", linenr=linenr@entry=556, funcname=funcname@entry=0x7fcd2a28c940 <__func__.22722> "virSecurityDACSetOwnershipInternal", metadata=metadata@entry=0x0, fmt=fmt@entry=0x7fcd2a28c2f8 "Setting DAC user and group on '%s' to '%ld:%ld'") at util/virlog.c:515
#8 0x00007fcd2a1f878f in virSecurityDACSetOwnershipInternal (priv=0x7fcd2bb4ad50, src=0x7fcd2bcf9bb0, path=0x7fcd2bb5bd30 "/dev/mapper/plc_suse12_sp2_64_2", uid=0, gid=0) at security/security_dac.c:555
#9 0x00007fcd2a1f95f1 in virSecurityDACTransactionRun (pid=pid@entry=59281, opaque=opaque@entry=0x7fcd2bb95380) at security/security_dac.c:202
#10 0x00007fcd2a05320e in virProcessNamespaceHelper (opaque=0x7fcd2bb95380, cb=0x7fcd2a1f95b0 <virSecurityDACTransactionRun>, pid=59281, errfd=48) at util/virprocess.c:1102
#11 virProcessRunInMountNamespace (pid=pid@entry=59281, cb=cb@entry=0x7fcd2a1f95b0 <virSecurityDACTransactionRun>, opaque=opaque@entry=0x7fcd2bb95380) at util/virprocess.c:1143
#12 0x00007fcd2a1f8116 in virSecurityDACTransactionCommit (mgr=<optimized out>, pid=59281) at security/security_dac.c:506
#13 0x00007fcd2a1fac56 in virSecurityManagerTransactionCommit (mgr=0x7fcd2bb4ad80, pid=pid@entry=59281) at security/security_manager.c:284
#14 0x00007fcd2a1f76c3 in virSecurityStackTransactionCommit (mgr=<optimized out>, pid=59281) at security/security_stack.c:166
#15 0x00007fcd2a1fac56 in virSecurityManagerTransactionCommit (mgr=0x7fcd2bb4acd0, pid=59281) at security/security_manager.c:284
#16 0x00007fcd0ff07ef2 in qemuSecuritySetAllLabel (driver=driver@entry=0x7fcd2bb0a690, vm=vm@entry=0x7fcd2bb6b4b0, stdin_path=stdin_path@entry=0x0) at qemu/qemu_security.c:52
#17 0x00007fcd0fe9e2d9 in qemuProcessLaunch (conn=conn@entry=0x7fccf80011c0, driver=driver@entry=0x7fcd2bb0a690, vm=vm@entry=0x7fcd2bb6b4b0, asyncJob=asyncJob@entry=QEMU_ASYNC_JOB_START, incoming=incoming@entry=0x0, snapshot=snapshot@entry=0x0, vmop=vmop@entry=VIR_NETDEV_VPORT_PROFILE_OP_CREATE, flags=flags@entry=17) at qemu/qemu_process.c:5792
#18 0x00007fcd0fe9f87a in qemuProcessStart (conn=conn@entry=0x7fccf80011c0, driver=driver@entry=0x7fcd2bb0a690, vm=vm@entry=0x7fcd2bb6b4b0, asyncJob=asyncJob@entry=QEMU_ASYNC_JOB_START, migrateFrom=migrateFrom@entry=0x0, migrateFd=migrateFd@entry=-1, migratePath=migratePath@entry=0x0, snapshot=snapshot@entry=0x0, vmop=vmop@entry=VIR_NETDEV_VPORT_PROFILE_OP_CREATE, flags=17, flags@entry=1) at qemu/qemu_process.c:6037
#19 0x00007fcd0ff008d1 in qemuDomainObjStart (conn=0x7fccf80011c0, driver=driver@entry=0x7fcd2bb0a690, vm=0x7fcd2bb6b4b0, flags=flags@entry=0, asyncJob=QEMU_ASYNC_JOB_START) at qemu/qemu_driver.c:7023
#20 0x00007fcd0ff01046 in qemuDomainCreateWithFlags (dom=0x7fcd08003af0, flags=0) at qemu/qemu_driver.c:7077
#21 0x00007fcd2a11872b in virDomainCreate (domain=domain@entry=0x7fcd08003af0) at libvirt-domain.c:6595
#22 0x00007fcd2ad9e4be in remoteDispatchDomainCreate (server=0x7fcd2ba002c0, msg=0x7fcd080026b0, args=<optimized out>, rerr=0x7fcd1a694c90, client=0x7fcd08001160) at remote_dispatch.h:4354
#23 remoteDispatchDomainCreateHelper (server=0x7fcd2ba002c0, client=0x7fcd08001160, msg=0x7fcd080026b0, rerr=0x7fcd1a694c90, args=<optimized out>, ret=0x7fcd08002ef0) at remote_dispatch.h:4330
#24 0x00007fcd2a188392 in virNetServerProgramDispatchCall (msg=0x7fcd080026b0, client=0x7fcd08001160, server=0x7fcd2ba002c0, prog=0x7fcd2ba17640) at rpc/virnetserverprogram.c:437
#25 virNetServerProgramDispatch (prog=0x7fcd2ba17640, server=server@entry=0x7fcd2ba002c0, client=0x7fcd08001160, msg=0x7fcd080026b0) at rpc/virnetserverprogram.c:307
#26 0x00007fcd2adaf34d in virNetServerProcessMsg (msg=<optimized out>, prog=<optimized out>, client=<optimized out>, srv=0x7fcd2ba002c0) at rpc/virnetserver.c:148
#27 virNetServerHandleJob (jobOpaque=<optimized out>, opaque=0x7fcd2ba002c0) at rpc/virnetserver.c:169
#28 0x00007fcd2a06a371 in virThreadPoolWorker (opaque=opaque@entry=0x7fcd2ba0c740) at util/virthreadpool.c:167
#29 0x00007fcd2a069688 in virThreadHelper (data=<optimized out>) at util/virthread.c:219
#30 0x00007fcd2728bdc5 in start_thread (arg=0x7fcd1a695700) at pthread_create.c:308
#31 0x00007fcd26fb972d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:113
2、libvirtd thread info and backtrace of thr 16
* 16 Thread 0x7fcd1a695700 (LWP 36728) "libvirtd" 0x00007fcd2a053043 in virProcessRunInMountNamespace (pid=pid@entry=59281,
cb=cb@entry=0x7fcd2a1f95b0 <virSecurityDACTransactionRun>, opaque=opaque@entry=0x7fcd2bb95380) at util/virprocess.c:1152
15 Thread 0x7fcd19e94700 (LWP 36729) "libvirtd" pthread_cond_wait@@GLIBC_2.3.2 ()
at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
14 Thread 0x7fcd19693700 (LWP 36730) "libvirtd" pthread_cond_wait@@GLIBC_2.3.2 ()
at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
13 Thread 0x7fcd18e92700 (LWP 36731) "libvirtd" pthread_cond_wait@@GLIBC_2.3.2 ()
at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
12 Thread 0x7fcd18691700 (LWP 36732) "libvirtd" pthread_cond_wait@@GLIBC_2.3.2 ()
at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
11 Thread 0x7fcd17e90700 (LWP 36733) "libvirtd" pthread_cond_wait@@GLIBC_2.3.2 ()
at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
10 Thread 0x7fcd1768f700 (LWP 36734) "libvirtd" __lll_lock_wait () at ../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:135
9 Thread 0x7fcd16e8e700 (LWP 36735) "libvirtd" pthread_cond_wait@@GLIBC_2.3.2 ()
at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
8 Thread 0x7fcd1668d700 (LWP 36736) "libvirtd" pthread_cond_wait@@GLIBC_2.3.2 ()
at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
7 Thread 0x7fcd15e8c700 (LWP 36737) "libvirtd" __lll_lock_wait () at ../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:135
6 Thread 0x7fcd0fdf4700 (LWP 36738) "libvirtd" pthread_cond_wait@@GLIBC_2.3.2 ()
at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
5 Thread 0x7fcd0f5f3700 (LWP 36739) "libvirtd" pthread_cond_wait@@GLIBC_2.3.2 ()
at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
4 Thread 0x7fcd0edf2700 (LWP 36740) "libvirtd" pthread_cond_wait@@GLIBC_2.3.2 ()
at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
3 Thread 0x7fcd0e5f1700 (LWP 36741) "libvirtd" pthread_cond_wait@@GLIBC_2.3.2 ()
at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
2 Thread 0x7fcd0ddf0700 (LWP 36742) "libvirtd" pthread_cond_wait@@GLIBC_2.3.2 ()
at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
1 Thread 0x7fcd2ad0f840 (LWP 36724) "libvirtd" 0x00007fcd26f8097d in nanosleep () at ../sysdeps/unix/syscall-template.S:81
(gdb) bt
#0 0x00007fcd2729222d in read () at ../sysdeps/unix/syscall-template.S:81
#1 0x00007fcd2a01a0ae in read (__nbytes=1024, __buf=0x7fcd2bc82770, __fd=47) at /usr/include/bits/unistd.h:44
#2 saferead (fd=fd@entry=47, buf=0x7fcd2bc82770, count=count@entry=1024) at util/virfile.c:1044
#3 0x00007fcd2a01a1bc in saferead_lim (fd=47, max_len=max_len@entry=1024, length=length@entry=0x7fcd1a694440) at util/virfile.c:1320
#4 0x00007fcd2a01a577 in virFileReadHeaderFD (fd=<optimized out>, maxlen=maxlen@entry=1024, buf=buf@entry=0x7fcd1a694490) at util/virfile.c:1351
#5 0x00007fcd2a053043 in virProcessRunInMountNamespace (pid=pid@entry=59281, cb=cb@entry=0x7fcd2a1f95b0 <virSecurityDACTransactionRun>, opaque=opaque@entry=0x7fcd2bb95380) at util/virprocess.c:1152
#6 0x00007fcd2a1f8116 in virSecurityDACTransactionCommit (mgr=<optimized out>, pid=59281) at security/security_dac.c:506
#7 0x00007fcd2a1fac56 in virSecurityManagerTransactionCommit (mgr=0x7fcd2bb4ad80, pid=pid@entry=59281) at security/security_manager.c:284
#8 0x00007fcd2a1f76c3 in virSecurityStackTransactionCommit (mgr=<optimized out>, pid=59281) at security/security_stack.c:166
#9 0x00007fcd2a1fac56 in virSecurityManagerTransactionCommit (mgr=0x7fcd2bb4acd0, pid=59281) at security/security_manager.c:284
#10 0x00007fcd0ff07ef2 in qemuSecuritySetAllLabel (driver=driver@entry=0x7fcd2bb0a690, vm=vm@entry=0x7fcd2bb6b4b0, stdin_path=stdin_path@entry=0x0) at qemu/qemu_security.c:52
#11 0x00007fcd0fe9e2d9 in qemuProcessLaunch (conn=conn@entry=0x7fccf80011c0, driver=driver@entry=0x7fcd2bb0a690, vm=vm@entry=0x7fcd2bb6b4b0, asyncJob=asyncJob@entry=QEMU_ASYNC_JOB_START, incoming=incoming@entry=0x0, snapshot=snapshot@entry=0x0, vmop=vmop@entry=VIR_NETDEV_VPORT_PROFILE_OP_CREATE, flags=flags@entry=17) at qemu/qemu_process.c:5792
#12 0x00007fcd0fe9f87a in qemuProcessStart (conn=conn@entry=0x7fccf80011c0, driver=driver@entry=0x7fcd2bb0a690, vm=vm@entry=0x7fcd2bb6b4b0, asyncJob=asyncJob@entry=QEMU_ASYNC_JOB_START, migrateFrom=migrateFrom@entry=0x0, migrateFd=migrateFd@entry=-1, migratePath=migratePath@entry=0x0, snapshot=snapshot@entry=0x0, vmop=vmop@entry=VIR_NETDEV_VPORT_PROFILE_OP_CREATE, flags=17, flags@entry=1) at qemu/qemu_process.c:6037
#13 0x00007fcd0ff008d1 in qemuDomainObjStart (conn=0x7fccf80011c0, driver=driver@entry=0x7fcd2bb0a690, vm=0x7fcd2bb6b4b0, flags=flags@entry=0, asyncJob=QEMU_ASYNC_JOB_START) at qemu/qemu_driver.c:7023
#14 0x00007fcd0ff01046 in qemuDomainCreateWithFlags (dom=0x7fcd08003af0, flags=0) at qemu/qemu_driver.c:7077
#15 0x00007fcd2a11872b in virDomainCreate (domain=domain@entry=0x7fcd08003af0) at libvirt-domain.c:6595
#16 0x00007fcd2ad9e4be in remoteDispatchDomainCreate (server=0x7fcd2ba002c0, msg=0x7fcd080026b0, args=<optimized out>, rerr=0x7fcd1a694c90, client=0x7fcd08001160) at remote_dispatch.h:4354
#17 remoteDispatchDomainCreateHelper (server=0x7fcd2ba002c0, client=0x7fcd08001160, msg=0x7fcd080026b0, rerr=0x7fcd1a694c90, args=<optimized out>, ret=0x7fcd08002ef0) at remote_dispatch.h:4330
#18 0x00007fcd2a188392 in virNetServerProgramDispatchCall (msg=0x7fcd080026b0, client=0x7fcd08001160, server=0x7fcd2ba002c0, prog=0x7fcd2ba17640) at rpc/virnetserverprogram.c:437
#19 virNetServerProgramDispatch (prog=0x7fcd2ba17640, server=server@entry=0x7fcd2ba002c0, client=0x7fcd08001160, msg=0x7fcd080026b0) at rpc/virnetserverprogram.c:307
#20 0x00007fcd2adaf34d in virNetServerProcessMsg (msg=<optimized out>, prog=<optimized out>, client=<optimized out>, srv=0x7fcd2ba002c0) at rpc/virnetserver.c:148
#21 virNetServerHandleJob (jobOpaque=<optimized out>, opaque=0x7fcd2ba002c0) at rpc/virnetserver.c:169
#22 0x00007fcd2a06a371 in virThreadPoolWorker (opaque=opaque@entry=0x7fcd2ba0c740) at util/virthreadpool.c:167
#23 0x00007fcd2a069688 in virThreadHelper (data=<optimized out>) at util/virthread.c:219
#24 0x00007fcd2728bdc5 in start_thread (arg=0x7fcd1a695700) at pthread_create.c:308
#25 0x00007fcd26fb972d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:113
We can see in libvirtd 16th thread, it wait a message from child process. But child process is deadlocked at virTimeLocalOffsetFromUTC point.
If we use VIR_DEBUG, and our loglevel is info, then VIR_DEBUG will not call virTimeLocalOffsetFromUTC, then avoid deadlock.
I Know this resolution is not the best resolution, I think If we use Debug loglevel, We are in debug, then we can accept this deadlock, and resolve it by restart libvirtd and kill child process.
Or delete those log at child process.
-----邮件原件-----
发件人: Peter Krempa [mailto:pkrempa@xxxxxxxxxx]
发送时间: 2017年7月17日 18:12
收件人: Caoxinhua
抄送: libvir-list@xxxxxxxxxx; jferlan@xxxxxxxxxx; Yanqiangjun; Huangweidong (C); weifuqiang
主题: Re: [PATCH] security: Use VIR_DEBUG instead of VIR_INFO in virSecurityDACSetOwnershipInternal
On Sat, Jul 15, 2017 at 16:31:39 +0800, xinhua.Cao wrote:
> virSecurityDACSetOwnershipInternal was called by libvirt child
> process, so if we log message by VIR_INFO at normal scene, it would
> probability occurs dead lock sence, then libvirtd will also by dead lock because libvirtd is waitting for child message.
> so our suggest is use VIR_DEBUG instead of VIR_INFO to avoid this sence.
This won't help. VIR_DEBUG and VIR_INFO macros both translate into a virLogMessage call thus follow the same code path. So this patch definitely will not fix it completely.
If you've witnessed a deadlock, please post a backtrace and a debug log somewhere, since this needs to be fixed at the root.
> ---
> src/security/security_dac.c | 22 +++++++++++-----------
> 1 file changed, 11 insertions(+), 11 deletions(-)
>
> diff --git a/src/security/security_dac.c b/src/security/security_dac.c
> index ca7a6af..7bfd090 100644
> --- a/src/security/security_dac.c
> +++ b/src/security/security_dac.c
> @@ -552,8 +552,8 @@ virSecurityDACSetOwnershipInternal(const virSecurityDACData *priv,
> else if (rc > 0)
> return 0;
>
> - VIR_INFO("Setting DAC user and group on '%s' to '%ld:%ld'",
> - NULLSTR(src ? src->path : path), (long) uid, (long) gid);
> + VIR_DEBUG("Setting DAC user and group on '%s' to '%ld:%ld'",
> + NULLSTR(src ? src->path : path), (long) uid, (long)
> + gid);
>
> if (priv && src && priv->chownCallback) {
> rc = priv->chownCallback(src, uid, gid); @@ -591,17 +591,17
> @@ virSecurityDACSetOwnershipInternal(const virSecurityDACData *priv,
>
> if (rc < 0) {
> if (errno == EOPNOTSUPP || errno == EINVAL) {
> - VIR_INFO("Setting user and group to '%ld:%ld' on '%s' not "
> - "supported by filesystem",
> - (long) uid, (long) gid, path);
> + VIR_DEBUG("Setting user and group to '%ld:%ld' on '%s' not "
> + "supported by filesystem",
> + (long) uid, (long) gid, path);
> } else if (errno == EPERM) {
> - VIR_INFO("Setting user and group to '%ld:%ld' on '%s' not "
> - "permitted",
> - (long) uid, (long) gid, path);
> + VIR_DEBUG("Setting user and group to '%ld:%ld' on '%s' not "
> + "permitted",
> + (long) uid, (long) gid, path);
> } else if (errno == EROFS) {
> - VIR_INFO("Setting user and group to '%ld:%ld' on '%s' not "
> - "possible on readonly filesystem",
> - (long) uid, (long) gid, path);
> + VIR_DEBUG("Setting user and group to '%ld:%ld' on '%s' not "
> + "possible on readonly filesystem",
> + (long) uid, (long) gid, path);
NACK
--
libvir-list mailing list
libvir-list@xxxxxxxxxx
https://www.redhat.com/mailman/listinfo/libvir-list
