[libvirt] 答复: [PATCH] security: Use VIR_DEBUG instead of VIR_INFO in virSecurityDACSetOwnershipInternal

Caoxinhua caoxinhua at huawei.com
Mon Jul 17 12:41:41 UTC 2017 

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 at entry=0x7fcd1a694068, use_localtime=use_localtime at entry=0, tp=tp at entry=0x7fcd1a694070) at tzset.c:624
#3  0x00007fcd26f7075a in __GI___gmtime_r (t=t at entry=0x7fcd1a694068, tp=tp at entry=0x7fcd1a694070) at gmtime.c:28
#4  0x00007fcd2a06b41d in virTimeLocalOffsetFromUTC (offset=offset at entry=0x7fcd1a6940e0) at util/virtime.c:385
#5  0x00007fcd2a06b560 in virTimeStringNowRaw (buf=buf at 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 at entry=0x7fcd2a28c2f8 "Setting DAC user and group on '%s' to '%ld:%ld'", vargs=vargs at entry=0x7fcd1a694220) at util/virlog.c:585
#7  0x00007fcd2a035427 in virLogMessage (source=source at entry=0x7fcd2a519d90 <virLogSelf>, priority=priority at entry=VIR_LOG_INFO, filename=filename at entry=0x7fcd2a28c04a "security/security_dac.c", linenr=linenr at entry=556, funcname=funcname at entry=0x7fcd2a28c940 <__func__.22722> "virSecurityDACSetOwnershipInternal", metadata=metadata at entry=0x0, fmt=fmt at 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 at entry=59281, opaque=opaque at 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 at entry=59281, cb=cb at entry=0x7fcd2a1f95b0 <virSecurityDACTransactionRun>, opaque=opaque at 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 at 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 at entry=0x7fcd2bb0a690, vm=vm at entry=0x7fcd2bb6b4b0, stdin_path=stdin_path at entry=0x0) at qemu/qemu_security.c:52
#17 0x00007fcd0fe9e2d9 in qemuProcessLaunch (conn=conn at entry=0x7fccf80011c0, driver=driver at entry=0x7fcd2bb0a690, vm=vm at entry=0x7fcd2bb6b4b0, asyncJob=asyncJob at entry=QEMU_ASYNC_JOB_START, incoming=incoming at entry=0x0, snapshot=snapshot at entry=0x0, vmop=vmop at entry=VIR_NETDEV_VPORT_PROFILE_OP_CREATE, flags=flags at entry=17) at qemu/qemu_process.c:5792
#18 0x00007fcd0fe9f87a in qemuProcessStart (conn=conn at entry=0x7fccf80011c0, driver=driver at entry=0x7fcd2bb0a690, vm=vm at entry=0x7fcd2bb6b4b0, asyncJob=asyncJob at entry=QEMU_ASYNC_JOB_START, migrateFrom=migrateFrom at entry=0x0, migrateFd=migrateFd at entry=-1, migratePath=migratePath at entry=0x0, snapshot=snapshot at entry=0x0, vmop=vmop at entry=VIR_NETDEV_VPORT_PROFILE_OP_CREATE, flags=17, flags at entry=1) at qemu/qemu_process.c:6037
#19 0x00007fcd0ff008d1 in qemuDomainObjStart (conn=0x7fccf80011c0, driver=driver at entry=0x7fcd2bb0a690, vm=0x7fcd2bb6b4b0, flags=flags at 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 at 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 at 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 at 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 at entry=59281,
    cb=cb at entry=0x7fcd2a1f95b0 <virSecurityDACTransactionRun>, opaque=opaque at 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 at entry=47, buf=0x7fcd2bc82770, count=count at entry=1024) at util/virfile.c:1044
#3  0x00007fcd2a01a1bc in saferead_lim (fd=47, max_len=max_len at entry=1024, length=length at entry=0x7fcd1a694440) at util/virfile.c:1320
#4  0x00007fcd2a01a577 in virFileReadHeaderFD (fd=<optimized out>, maxlen=maxlen at entry=1024, buf=buf at entry=0x7fcd1a694490) at util/virfile.c:1351
#5  0x00007fcd2a053043 in virProcessRunInMountNamespace (pid=pid at entry=59281, cb=cb at entry=0x7fcd2a1f95b0 <virSecurityDACTransactionRun>, opaque=opaque at 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 at 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 at entry=0x7fcd2bb0a690, vm=vm at entry=0x7fcd2bb6b4b0, stdin_path=stdin_path at entry=0x0) at qemu/qemu_security.c:52
#11 0x00007fcd0fe9e2d9 in qemuProcessLaunch (conn=conn at entry=0x7fccf80011c0, driver=driver at entry=0x7fcd2bb0a690, vm=vm at entry=0x7fcd2bb6b4b0, asyncJob=asyncJob at entry=QEMU_ASYNC_JOB_START, incoming=incoming at entry=0x0, snapshot=snapshot at entry=0x0, vmop=vmop at entry=VIR_NETDEV_VPORT_PROFILE_OP_CREATE, flags=flags at entry=17) at qemu/qemu_process.c:5792
#12 0x00007fcd0fe9f87a in qemuProcessStart (conn=conn at entry=0x7fccf80011c0, driver=driver at entry=0x7fcd2bb0a690, vm=vm at entry=0x7fcd2bb6b4b0, asyncJob=asyncJob at entry=QEMU_ASYNC_JOB_START, migrateFrom=migrateFrom at entry=0x0, migrateFd=migrateFd at entry=-1, migratePath=migratePath at entry=0x0, snapshot=snapshot at entry=0x0, vmop=vmop at entry=VIR_NETDEV_VPORT_PROFILE_OP_CREATE, flags=17, flags at entry=1) at qemu/qemu_process.c:6037
#13 0x00007fcd0ff008d1 in qemuDomainObjStart (conn=0x7fccf80011c0, driver=driver at entry=0x7fcd2bb0a690, vm=0x7fcd2bb6b4b0, flags=flags at 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 at 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 at 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 at 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 at redhat.com] 
发送时间: 2017年7月17日 18:12
收件人: Caoxinhua
抄送: libvir-list at redhat.com; jferlan at 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

More information about the libvir-list mailing list