Re: libvirt crashes with Caught Segmentation violation

Minami Katsumata <princessrainicorndev@xxxxxxxxx> · Fri, 14 Feb 2014 13:19:22 +0900



    Hi, 

      Thank you Michal for your advice. 

      I went ahead and used gdb, and this is the result I got:

      2014-02-14 00:54:11.109+0000: 34958: info :
        remoteDispatchAuthList:2091 : Bypass polkit auth for privileged
        client pid:58466,uid:0

        2014-02-14 00:54:11.125+0000: 34958: error :
        qemudDomainInterfaceStats:7865 : 無効な引数: 無効なパス、'Interface'
        は不明なインターフェイスです

        2014-02-14 00:54:11.155+0000: 34960: info :
        remoteDispatchAuthList:2091 : Bypass polkit auth for privileged
        client pid:58474,uid:0

        2014-02-14 00:54:11.218+0000: 34967: info :
        remoteDispatchAuthList:2091 : Bypass polkit auth for privileged
        client pid:58489,uid:0

        2014-02-14 00:54:11.282+0000: 34961: info :
        remoteDispatchAuthList:2091 : Bypass polkit auth for privileged
        client pid:58506,uid:0

        2014-02-14 00:54:11.392+0000: 34967: info :
        remoteDispatchAuthList:2091 : Bypass polkit auth for privileged
        client pid:58514,uid:0

        2014-02-14 00:54:11.408+0000: 34967: error :
        qemudDomainInterfaceStats:7865 : 無効な引数: 無効なパス、'Interface'
        は不明なインターフェイスです

        2014-02-14 00:54:11.438+0000: 34960: info :
        remoteDispatchAuthList:2091 : Bypass polkit auth for privileged
        client pid:58522,uid:0

        2014-02-14 00:54:11.502+0000: 34959: info :
        remoteDispatchAuthList:2091 : Bypass polkit auth for privileged
        client pid:58536,uid:0

        2014-02-14 00:54:11.612+0000: 34961: info :
        remoteDispatchAuthList:2091 : Bypass polkit auth for privileged
        client pid:58573,uid:0

        2014-02-14 00:54:11.707+0000: 34960: info :
        remoteDispatchAuthList:2091 : Bypass polkit auth for privileged
        client pid:58600,uid:0

        2014-02-14 00:54:12.007+0000: 34962: info :
        remoteDispatchAuthList:2091 : Bypass polkit auth for privileged
        client pid:58642,uid:0

        2014-02-14 00:54:12.072+0000: 34958: info :
        remoteDispatchAuthList:2091 : Bypass polkit auth for privileged
        client pid:58653,uid:0

        2014-02-14 00:54:12.197+0000: 34960: info :
        remoteDispatchAuthList:2091 : Bypass polkit auth for privileged
        client pid:58666,uid:0

        2014-02-14 00:54:12.264+0000: 34966: info :
        remoteDispatchAuthList:2091 : Bypass polkit auth for privileged
        client pid:58678,uid:0

        2014-02-14 00:54:12.355+0000: 34967: info :
        remoteDispatchAuthList:2091 : Bypass polkit auth for privileged
        client pid:58685,uid:0

        2014-02-14 00:54:12.508+0000: 34964: info :
        remoteDispatchAuthList:2091 : Bypass polkit auth for privileged
        client pid:58693,uid:0

        2014-02-14 00:54:12.677+0000: 34961: info :
        remoteDispatchAuthList:2091 : Bypass polkit auth for privileged
        client pid:58707,uid:0

        2014-02-14 00:54:12.744+0000: 34960: info :
        remoteDispatchAuthList:2091 : Bypass polkit auth for privileged
        client pid:58719,uid:0

        2014-02-14 00:54:12.843+0000: 34965: info :
        remoteDispatchAuthList:2091 : Bypass polkit auth for privileged
        client pid:58726,uid:0

        
        Program received signal SIGSEGV, Segmentation fault.

        [Switching to Thread 0x7f77cd80d700 (LWP 34958)]

        0x00007f77d81b696c in free () from /lib64/libc.so.6

      
      Here's the result of the backtrace:

      (gdb) backtrace

        #0  0x00007f77d81b696c in free () from /lib64/libc.so.6

        #1  0x00007f77db790159 in virFree (ptrptr=0x7f77a0020088) at
        util/memory.c:310

        #2  0x00007f77db7a1072 in virTypedParameterArrayClear
        (params=<value optimized out>,

            nparams=5) at util/virtypedparam.c:58

        #3  0x0000000000425bec in remoteDispatchDomainBlockStatsFlags (

            server=<value optimized out>, client=<value
        optimized out>,

            msg=<value optimized out>, rerr=0x7f77cd80cbc0,
        args=<value optimized out>,

            ret=0x7f77a0021730) at remote.c:1186

        #4  remoteDispatchDomainBlockStatsFlagsHelper (server=<value
        optimized out>,

            client=<value optimized out>, msg=<value optimized
        out>, rerr=0x7f77cd80cbc0,

            args=<value optimized out>, ret=0x7f77a0021730) at
        remote_dispatch.h:757

        #5  0x00007f77db856e65 in virNetServerProgramDispatchCall
        (prog=0xf1f220,

            server=0xf13ce0, client=0xf1b570, msg=0xf1f3d0) at
        rpc/virnetserverprogram.c:416

        #6  virNetServerProgramDispatch (prog=0xf1f220, server=0xf13ce0,
        client=0xf1b570,

            msg=0xf1f3d0) at rpc/virnetserverprogram.c:289

        #7  0x00007f77db8580f1 in virNetServerHandleJob
        (jobOpaque=<value optimized out>,

            opaque=0xf13ce0) at rpc/virnetserver.c:164

        #8  0x00007f77db79a45c in virThreadPoolWorker (opaque=<value
        optimized out>)

            at util/threadpool.c:144

        #9  0x00007f77db799d79 in virThreadHelper (data=""
        optimized out>)

            at util/threads-pthread.c:161

        #10 0x00007f77d88dc851 in start_thread () from
        /lib64/libpthread.so.0

        #11 0x00007f77d822367d in clone () from /lib64/libc.so.6

      
      And util/virtypedparam.c:58 looks like this for libvirt-0.9.10:

       49 virTypedParameterArrayClear(virTypedParameterPtr params, int
      nparams)

       50 {

       51     int i;

       52

       53     if (!params)

       54         return;

       55

       56     for (i = 0; i < nparams; i++) {

       57         if (params[i].type == VIR_TYPED_PARAM_STRING)

       58             VIR_FREE(params[i].value.s);

       59     }

       60 }

       61

      
      I'm very unfamiliar with C so I would again appreciate any input
      on why this is happening, and what I can do to solve this issue.

      By the way this segfault can be 100% reproduced with CentOS 6.3
      but not CentOS 6.2.

      
      Thank you and regards,

      Minami

      
      On 2014/02/07 18:30, Michal Privoznik wrote:

    
    On
      07.02.2014 09:47, Minami Katsumata wrote:
      

      Hi,
        

        I'm having problems with libvirt crashing after a couple hours
        when a
        

        specific domain monitoring program is running.
        

        I have pasted below the following:
        

        1. libvirt version
        

        2. qemu-kvm version
        

        3. OS version
        

        4. Kernel version
        

        5. libvirt status post-crash
        

        6. libvirtd.log (info level dump around crash; too long to post
        

        everything so just the beginning and end. UTC)
        

        7. custom.log (on what this domain monitoring program was doing
        around
        

        the time of the crash. JST)
        

        8. FYI on the program being executed
        

        9. other related server settings
        

        Please, if anyone can look through these and give some insight
        as to
        

        what is causing libvirt to crash, that would be greatly
        appreciated.
        

        1.) libvirt version:
        

        # rpm -q libvirt
        

        libvirt-0.9.10-21.el6.x86_64
        

      This is rather ancient libvirt, can you please update and see if
      the issue was fixed?
      

        2.) qemu-kvm version:
        

        qemu-kvm-0.12.1.2-3.295.el6.10.x86_64
        

        3.) OS version:
        

        # cat /etc/redhat-release
        

        CentOS release 6.3 (Final)
        

      Ah, this explains the libvirt version. AFAIK there's been
      Centos-6.5 released.
      

        4.) Kernel version:
        

        # uname -r
        

        2.6.32-279.22.1.el6.x86_64
        

        5.) libvirt status after crash:
        

        # service libvirtd status
        

        libvirtd dead but pid file exists
        

        6.) libvirtd.log
        

        2014-02-06 10:25:05.173+0000: 1187: info :
        remoteDispatchAuthList:2091 : Bypass polkit auth for privileged
        client pid:58626,uid:0
        

        2014-02-06 10:25:05.237+0000: 1184: info :
        remoteDispatchAuthList:2091 : Bypass polkit auth for privileged
        client pid:58636,uid:0
        

        2014-02-06 10:25:05.271+0000: 1185: info :
        remoteDispatchAuthList:2091 : Bypass polkit auth for privileged
        client pid:58646,uid:0
        

        2014-02-06 10:25:05.301+0000: 1184: info :
        remoteDispatchAuthList:2091 : Bypass polkit auth for privileged
        client pid:58648,uid:0
        

        2014-02-06 10:25:05.400+0000: 1184: info :
        remoteDispatchAuthList:2091 : Bypass polkit auth for privileged
        client pid:58650,uid:0
        

        Caught Segmentation violation dumping internal log buffer:
        

             ====== start of log =====
        

        ^@05.412+00001182: debug : virEventPollMakePollFDs:383 : Prepare
        n=19 w=21, f=32 e=25 d=0
        

        2014-02-06 10:25:05.412+00001182: debug :
        virEventPollMakePollFDs:383 : Prepare n=20 w=22, f=34 e=25 d=0
        

        2014-02-06 10:25:05.412+00001182: debug :
        virEventPollMakePollFDs:383 : Prepare n=21 w=23, f=33 e=25 d=0
        

        2014-02-06 10:25:05.412+00001182: debug :
        virEventPollMakePollFDs:383 : Prepare n=22 w=24, f=36 e=25 d=0
        

        2014-02-06 10:25:05.412+00001182: debug :
        virEventPollMakePollFDs:383 : Prepare n=23 w=25, f=38 e=25 d=0
        

        2014-02-06 10:25:05.412+00001182: debug :
        virEventPollMakePollFDs:383 : Prepare n=24 w=26, f=39 e=25 d=0
        

        2014-02-06 10:25:05.412+00001182: debug :
        virEventPollMakePollFDs:383 : Prepare n=25 w=27, f=41 e=25 d=0
        

        2014-02-06 10:25:05.412+00001182: debug :
        virEventPollMakePollFDs:383 : Prepare n=26 w=28, f=40 e=25 d=0
        

        (cut out due to length)
        

        2014-02-06 10:25:05.423+00001182: debug :
        virEventPollDispatchHandles:488 : EVENT_POLL_DISPATCH_HANDLE:
        watch=2791 events=2
        

        2014-02-06 10:25:05.423+00001182: debug : virNetMessageFree:75 :
        msg=0x2326a20 nfds=0 cb=(nil)
        

        2014-02-06 10:25:05.423+00001182: debug :
        virNetServerClientCalculateHandleMode:137 : tls=(nil) hs=-1,
        rx=0x2266390 tx=(nil)
        

        2014-02-06 10:25:05.423+00001182: debug :
        virNetServerClientCalculateHandleMode:167 : mode=1
        

        2014-02-06 10:25:05.423+00001182: debug :
        virEventPollUpdateHandle:151 : EVENT_POLL_UPDATE_HANDLE:
        watch=2791 events=1
        

        2014-02-06 10:25:05.423+00001182: debug :
        virEventPollInterruptLocked:702 : Skip interrupt, 1 -1675536288
        

        2014-02-06 10:25:05.423+00001182: debug :
        virEventPollDispatchHandles:474 : i=33 w=2793
        

        2014-02-06 10:25:05.423+00001182: debug :
        virEventPollCleanupTimeouts:506 : Cleanup 12
        

        2014-02-06 10:25:05.423+00001182: debug :
        virEventPollCleanupHandles:554 : Cleanup 34
        

        2014-02-06 10:25:05.423+00001182: debug :
        virNetServerClientClose:632 : client=0x22e6860 refs=3
        

        2014-02-06 10:25:05.423+00001182: debug : virKeepAliveStop:382 :
        RPC_KEEPALIVE_STOP: ka=0x225bf20 client=0x22e6860
        

        2014-02-06 10:25:05.423+00001182: debug :
        virEventPollRemoveTimeout:293 : EVENT_POLL_REMOVE_TIMEOUT:
        timer=8290
        

        2014-02-06 10:25:05.423+00001182: debug :
        virEventPollInterruptLocked:702 : Skip interrupt, 0 -1675536288
        

        2014-02-06 10:25:05.423+00001182: debug :
        virEventPollRemoveTimeout:293 : EVENT_POLL_REMOVE_TIMEOUT:
        timer=8289
        

        2014-02-06 10:25:05.423+00001182: debug :
        virEventPollInterruptLocked:702 : Skip interrupt, 0 -1675536288
        

        2014-02-06 10:25:05.423+00001182: debug : virKeepAliveFree:304 :
        RPC_KEEPALIVE_FREE: ka=0x225bf20 client=0x22e6860 refs=3
        

        2014-02-06 10:25:05.423+00001182: debug :
        daemonRemoveAllClientStreams:493 : stream=(nil)
        

        2014-02-06 10:25:05.423+00001182: debug :
        virEventPollRemoveHandle:180 : EVENT_POLL_REMOVE_HANDLE:
        watch=2791
        

        2014-02-06 10:25:05.423+00001182: debug :
        virEventPollRemoveHandle:193 : mark delete 32 50
        

        2014-02-06 10:25:05.423+00001182: debug :
        virEventPollInterruptLocked:702 : Skip interrupt, 0 -1675536288
        

        2014-02-06 10:25:05.423+00001182: debug : virNetMessageFree:75 :
        msg=0x2266390 nfds=0 cb=(nil)
        

        2014-02-06 10:25:05.423+00001182: debug : virNetSocketFree:722 :
        RPC_SOCKET_FREE: sock=0x22e66a0 refs=2
        

        2014-02-06 10:25:05.423+00001182: debug :
        virNetServerClientFree:591 : RPC_SERVER_CLIENT_FREE:
        client=0x22e6860 refs=3
        

        2014-02-06 10:25:05.423+00001182: debug :
        virEventRunDefaultImpl:244 : running default event
        implementation
        

        2014-02-06 10:25:05.423+00001182: debug :
        virEventPollCleanupTimeouts:506 : Cleanup 12
        

        2014-02-06 10:25:05.423+00001182: debug :
        virEventPollCleanupTimeouts:519 : EVENT_POLL_PURGE_TIMEOUT:
        timer=8289
        

        2014-02-06 10:25:05.423+00001182: debug : virKeepAliveFree:304 :
        RPC_KEEPALIVE_FREE: ka=0x225bf20 client=0x22e6860 refs=2
        

        2014-02-06 10:25:05.423+00001182: debug :
        virEventPollCleanupTimeouts:519 : EVENT_POLL_PURGE_TIMEOUT:
        timer=8290
        

        2014-02-06 10:25:05.423+00001182: debug : virKeepAliveFree:304 :
        RPC_KEEPALIVE_FREE: ka=0x225bf20 client=0x22e6860 refs=1
        

        2014-02-06 10:25:05.423+00001182: debug :
        virNetServerClientFree:591 : RPC_SERVER_CLIENT_FREE:
        client=0x22e6860 refs=2
        

        2014-02-06 10:25:05.423+00001182: debug :
        virEventPollCleanupHandles:554 : Cleanup 34
        

        2014-02-06 10:25:05.423+00001182: debug :
        virEventPollCleanupHandles:567 : EVENT_POLL_PURGE_HANDLE:
        watch=2791
        

        2014-02-06 10:25:05.423+00001182: debug :
        virNetServerClientFree:591 : RPC_SERVER_CLIENT_FREE:
        client=0x22e6860 refs=1
        

        2014-02-06 10:25:05.423+00001182: debug : virConnectClose:1462 :
        conn=0x7f1b380c4630
        

        2014-02-06 10:25:05.423+00001182: debug : virUnrefConnect:145 :
        unref connection 0x7f1b380c4630 1
        

        2014-02-06 10:25:05.423+00001182: debug : virReleaseConnect:94 :
        release connection 0x7f1b380c4630
        

              ====== end of log =====
        

      These logs are pretty much useless (not your fault). On one hand,
      they may help us to see what libvirt was doing just before the
      crash. On the other hand:
      

      a) it completely misses TID
      

      b) it ends just before SIGSEGV occurs (so for example if
      segmentation fault happens in one thread, the logs may as well
      been showing completely unrelated thread).
      

      Therefore I think attaching gdb to the libvirtd, then reproducing
      the crash would gain more data, IMO.
      

      Michal
      

_______________________________________________
libvirt-users mailing list
libvirt-users@xxxxxxxxxx
https://www.redhat.com/mailman/listinfo/libvirt-users