[libvirt] [PATCH] security: Use VIR_DEBUG instead of VIR_INFO in virSecurityDACSetOwnershipInternal
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. --- 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); } else { virReportSystemError(errno, _("unable to set user and group to '%ld:%ld' " -- 2.8.3
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
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@redhat.com] 发送时间: 2017年7月17日 18:12 收件人: Caoxinhua 抄送: libvir-list@redhat.com; jferlan@redhat.com; Yanqiangjun; Huangweidong (C); weifuqiang 主题: Re: [libvirt] [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
On Mon, Jul 17, 2017 at 12:41:41 +0000, Caoxinhua wrote:
First: all of those backtrace is our private libvirt version backtrace. I find opensource also have this problem 1、backtrace of child
Does your 'private' version contain any changes to the logging code?
(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
So this is fishy. virTimeStringNowRaw is specifically designed not to call any time conversion functions, so it should not call virTimeLocalOffsetFromUTC at all. Those functions should ever be called only from the main process.
#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
This is called even from VIR_DEBUG, thus your patch wouldn't fix this. [...]
We can see in libvirtd 16th thread, it wait a message from child process. But child process is deadlocked at virTimeLocalOffsetFromUTC point.
This shouldn't ever happen. The logging code should not call this function and it doesn't seem it does in the upstream repo.
If we use VIR_DEBUG, and our loglevel is info, then VIR_DEBUG will not call virTimeLocalOffsetFromUTC, then avoid deadlock.
It will call it if you enable debug logging. The only reason such change would fix it is that the message was not displayed.
No, All logging code is opensource code. And deadlock is locked at virTimeStringNowRaw, this is never changed at our version. -----邮件原件----- 发件人: Peter Krempa [mailto:pkrempa@redhat.com] 发送时间: 2017年7月17日 20:59 收件人: Caoxinhua 抄送: libvir-list@redhat.com; Yanqiangjun; Huangweidong (C); weifuqiang 主题: Re: [libvirt] 答复: [PATCH] security: Use VIR_DEBUG instead of VIR_INFO in virSecurityDACSetOwnershipInternal On Mon, Jul 17, 2017 at 12:41:41 +0000, Caoxinhua wrote:
First: all of those backtrace is our private libvirt version backtrace. I find opensource also have this problem 1、backtrace of child
Does your 'private' version contain any changes to the logging code?
(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
So this is fishy. virTimeStringNowRaw is specifically designed not to call any time conversion functions, so it should not call virTimeLocalOffsetFromUTC at all. Those functions should ever be called only from the main process.
#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
This is called even from VIR_DEBUG, thus your patch wouldn't fix this. [...]
We can see in libvirtd 16th thread, it wait a message from child process. But child process is deadlocked at virTimeLocalOffsetFromUTC point.
This shouldn't ever happen. The logging code should not call this function and it doesn't seem it does in the upstream repo.
If we use VIR_DEBUG, and our loglevel is info, then VIR_DEBUG will not call virTimeLocalOffsetFromUTC, then avoid deadlock.
It will call it if you enable debug logging. The only reason such change would fix it is that the message was not displayed.
Sorry ,I reseached our code and opensource code, our private version is changed virTimeStringNowRaw. It called time(NULL). And it deadlock. Haha~~ -----邮件原件----- 发件人: Peter Krempa [mailto:pkrempa@redhat.com] 发送时间: 2017年7月17日 20:59 收件人: Caoxinhua 抄送: libvir-list@redhat.com; Yanqiangjun; Huangweidong (C); weifuqiang 主题: Re: [libvirt] 答复: [PATCH] security: Use VIR_DEBUG instead of VIR_INFO in virSecurityDACSetOwnershipInternal On Mon, Jul 17, 2017 at 12:41:41 +0000, Caoxinhua wrote:
First: all of those backtrace is our private libvirt version backtrace. I find opensource also have this problem 1、backtrace of child
Does your 'private' version contain any changes to the logging code?
(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
So this is fishy. virTimeStringNowRaw is specifically designed not to call any time conversion functions, so it should not call virTimeLocalOffsetFromUTC at all. Those functions should ever be called only from the main process.
#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
This is called even from VIR_DEBUG, thus your patch wouldn't fix this. [...]
We can see in libvirtd 16th thread, it wait a message from child process. But child process is deadlocked at virTimeLocalOffsetFromUTC point.
This shouldn't ever happen. The logging code should not call this function and it doesn't seem it does in the upstream repo.
If we use VIR_DEBUG, and our loglevel is info, then VIR_DEBUG will not call virTimeLocalOffsetFromUTC, then avoid deadlock.
It will call it if you enable debug logging. The only reason such change would fix it is that the message was not displayed.
On Mon, Jul 17, 2017 at 13:24:47 +0000, Caoxinhua wrote:
Sorry ,I reseached our code and opensource code, our private version is changed virTimeStringNowRaw. It called time(NULL). And it deadlock. Haha~~
[please don't top-post on techincal lists] Well, there's your problem. Upstream code is correct. We specifically report the log entries in UTC so that we don't need to call that function.
participants (3)
-
Caoxinhua -
Peter Krempa -
xinhua.Cao