Bug 1039991

+++ This bug was initially created as a clone of Bug #1034312 +++

Description of problem:

During hosted-engine --deploy, '/bin/systemctl start vdsmd.service' fails.

vdsm-4.13.0-196.gitb871832.fc19.x86_64
libvirt-1.0.5.7-2.fc19.x86_64

Reproduced by command line:

 # /usr/libexec/vdsm/vdsmd_init_common.sh --pre-start
 vdsm: Running mkdirs
 vdsm: Running configure_coredump
 vdsm: Running run_init_hooks
 vdsm: Running gencerts
 vdsm: Running check_is_configured
 libvirt is already configured for vdsm
 sanlock service is already configured
 vdsm: Running validate_configuration
 SUCCESS: ssl configured to true. No conflicts
 vdsm: Running prepare_transient_repository
 vdsm: Running syslog_available
 vdsm: Running nwfilter
 /usr/libexec/vdsm/vdsmd_init_common.sh: line 70:  8708 Errore di segmentazione "${VDSM_TOOL}" nwfilter
 vdsm: failed to execute nwfilter, error code 139

dmesg:
[ 2099.578442] python[11612]: segfault at 340b38aa40 ip 000000340b38aa40 sp 00007fb5c0e6bf38 error 15 in libpython2.7.so.1.0[340b375000+3e000]

gdb:

 [Thread debugging using libthread_db enabled]
 Using host libthread_db library "/lib64/libthread_db.so.1".
 Core was generated by `/usr/bin/python /usr/bin/vdsm-tool nwfilter'.
 Program terminated with signal 11, Segmentation fault.
 #0  0x0000000000000007 in ?? ()
 (gdb) py-bt
 #13 Frame 0x7f72680010b0, for file /usr/lib64/python2.7/site-packages/libvirt.py, line 299, in virEventRunDefaultImpl ()
    ret = libvirtmod.virEventRunDefaultImpl()

(gdb) bt
 #0  0x0000000000000007 in ?? ()
 #1  0x000000312480c2ce in _sasl_log (conn=<optimized out>, level=5, fmt=0x7f7267398218 "DIGEST-MD5 client mech dispose") at common.c:1985
 #2  0x00007f7267391d38 in digestmd5_client_mech_dispose (conn_context=0x143c5b0, utils=0x10ddec0) at digestmd5.c:4580
 #3  0x00000031248084c4 in client_dispose (pconn=0x10dcac0) at client.c:332
 #4  0x000000312480b4fb in sasl_dispose (pconn=0xe63338) at common.c:851
 #5  0x0000003411885a3b in virObjectUnref (anyobj=<optimized out>) at util/virobject.c:264
 #6  0x0000003411970908 in virNetSocketDispose (obj=0xe5dc50) at rpc/virnetsocket.c:1026
 #7  0x0000003411885a3b in virObjectUnref (anyobj=<optimized out>) at util/virobject.c:264
 #8  0x000000341186d182 in virEventPollCleanupHandles () at util/vireventpoll.c:582
 #9  0x000000341186e3cf in virEventPollRunOnce () at util/vireventpoll.c:651
 #10 0x000000341186cd0d in virEventRunDefaultImpl () at util/virevent.c:273
 #11 0x00007f726ce6cd06 in libvirt_virEventRunDefaultImpl (self=<optimized out>, args=<optimized out>) at libvirt.c:3076
 #12 0x000000340b0ddcee in call_function (oparg=<optimized out>, pp_stack=0x7f726ca02390) at /usr/src/debug/Python-2.7.5/Python/ceval.c:4098
 #13 PyEval_EvalFrameEx (f=f@entry=Frame 0x7f72680010b0, for file /usr/lib64/python2.7/site-packages/libvirt.py, line 299, in virEventRunDefaultImpl (), throwflag=throwflag@entry=0)
    at /usr/src/debug/Python-2.7.5/Python/ceval.c:2740

(gdb) t 2
 [Switching to thread 2 (Thread 0x7f72771b5740 (LWP 3295))]
 #0  _PyType_Lookup (type=type@entry=0x340b3875c0 <PyInt_Type>, name=name@entry='__class__') at /usr/src/debug/Python-2.7.5/Objects/typeobject.c:2518
2518	            dict = ((PyTypeObject *)base)->tp_dict;
 (gdb) py-bt
 #10 Frame 0x14b5e30, for file /usr/lib64/python2.7/site-packages/vdsm/libvirtconnection.py, line 78, in wrapper (args=(), kwargs={}, ret=0)
    if isinstance(ret, libvirt.virDomain):
 #14 Frame 0x13f73e0, for file /usr/lib64/python2.7/site-packages/vdsm/tool/nwfilter.py, line 35, in main (conn=<virConnect(restore=<function at remote 0x140a8c0>, nodeDeviceLookupSCSIHostByWWN=<function at remote 0x140a0c8>, listAllSecrets=<function at remote 0x1406398>, saveImageGetXMLDesc=<function at remote 0x140aa28>, virConnGetLastError=<function at remote 0x1433230>, listDomainsID=<function at remote 0x14066e0>, storagePoolLookupByUUIDString=<function at remote 0x140af50>, getCPUMap=<function at remote 0x13b56e0>, setKeepAlive=<function at remote 0x140ac80>, pingLibvirt=<instancemethod at remote 0xf60a00>, changeBegin=<function at remote 0x1432ed8>, dispatchDomainEventBlockPullCallback=<function at remote 0x13b5320>, _o=None, saveImageDefineXML=<function at remote 0x140a9b0>, listDefinedDomains=<function at remote 0x1406488>, getCapabilities=<function at remote 0x13b57d0>, getFreeMemory=<function at remote 0x13b58c0>, numOfDomains=<function at remote 0x140a398>, networkCreateXML=<function at remote 0x1406c8...(truncated)
    conn.close()
 #19 Frame 0xe62d90, for file /usr/bin/vdsm-tool, line 142, in main (opts=[], args=['nwfilter'], cmd='nwfilter')
    return tool_command[cmd]["command"](*args[1:])
 #22 Frame 0xe3d530, for file /usr/bin/vdsm-tool, line 145, in <module> ()
    sys.exit(main())

 bt
 #0  _PyType_Lookup (type=type@entry=0x340b3875c0 <PyInt_Type>, name=name@entry='__class__') at /usr/src/debug/Python-2.7.5/Objects/typeobject.c:2518
 #1  0x000000340b0847a5 in _PyObject_GenericGetAttrWithDict (obj=0, name='__class__', dict=0x0) at /usr/src/debug/Python-2.7.5/Objects/object.c:1389
 #2  0x000000340b046a2e in recursive_isinstance (inst=0, cls=<type at remote 0x1363850>) at /usr/src/debug/Python-2.7.5/Objects/abstract.c:2892
 #3  0x000000340b04af55 in _PyObject_RealIsInstance (inst=<optimized out>, cls=<optimized out>) at /usr/src/debug/Python-2.7.5/Objects/abstract.c:3060
 #4  0x000000340b09caf2 in type___instancecheck__ (type=<optimized out>, inst=<optimized out>) at /usr/src/debug/Python-2.7.5/Objects/typeobject.c:595
 #5  0x000000340b049dd3 in PyObject_Call (func=func@entry=<built-in method __instancecheck__ of type object at remote 0x1363850>, arg=arg@entry=(0,), kw=kw@entry=0x0)
    at /usr/src/debug/Python-2.7.5/Objects/abstract.c:2529
 #6  0x000000340b04a65f in PyObject_CallFunctionObjArgs (callable=callable@entry=<built-in method __instancecheck__ of type object at remote 0x1363850>)
    at /usr/src/debug/Python-2.7.5/Objects/abstract.c:2760
 #7  0x000000340b04ac5f in PyObject_IsInstance (inst=0, cls=<type at remote 0x1363850>) at /usr/src/debug/Python-2.7.5/Objects/abstract.c:2963
 #8  0x000000340b0d50c9 in builtin_isinstance (self=<optimized out>, args=<optimized out>) at /usr/src/debug/Python-2.7.5/Python/bltinmodule.c:2452
 #9  0x000000340b0ddcee in call_function (oparg=<optimized out>, pp_stack=0x7fffaed4b120) at /usr/src/debug/Python-2.7.5/Python/ceval.c:4098
 #10 PyEval_EvalFrameEx (f=f@entry=Frame 0x14b5e30, for file /usr/lib64/python2.7/site-packages/vdsm/libvirtconnection.py, line 78, in wrapper (args=(), kwargs={}, ret=0), 
    throwflag=throwflag@entry=0) at /usr/src/debug/Python-2.7.5/Python/ceval.c:2740

--- Additional comment from Jiri Denemark on 2013-12-02 13:13:49 UTC ---

The backtrace looks very similar to the following commit (v1.2.0-rc1-3-g13fdc6d):

commit 13fdc6d63ef64f8e231a087e1dab7d90145c3c10
Author: Christophe Fergeau <cfergeau>
Date:   Fri Nov 22 17:27:21 2013 +0100

    Tie SASL callbacks lifecycle to virNetSessionSASLContext
    
    The array of sasl_callback_t callbacks which is passed to sasl_client_new()
    must be kept alive as long as the created sasl_conn_t object is alive as
    cyrus-sasl uses this structure internally for things like logging, so
    the memory used for callbacks must only be freed after sasl_dispose() has
    been called.
    
    During testing of successful SASL logins with
    virsh -c qemu+tls:///system list --all
    I've been getting invalid read reports from valgrind
    
    ==9237== Invalid read of size 8
    ==9237==    at 0x6E93B6F: _sasl_getcallback (common.c:1745)
    ==9237==    by 0x6E95430: _sasl_log (common.c:1850)
    ==9237==    by 0x16593D87: digestmd5_client_mech_dispose (digestmd5.c:4580)
    ==9237==    by 0x6E91653: client_dispose (client.c:332)
    ==9237==    by 0x6E9476A: sasl_dispose (common.c:851)
    ==9237==    by 0x4E225A1: virNetSASLSessionDispose (virnetsaslcontext.c:678)
    ==9237==    by 0x4CBC551: virObjectUnref (virobject.c:262)
    ==9237==    by 0x4E254D1: virNetSocketDispose (virnetsocket.c:1042)
    ==9237==    by 0x4CBC551: virObjectUnref (virobject.c:262)
    ==9237==    by 0x4E2701C: virNetSocketEventFree (virnetsocket.c:1794)
    ==9237==    by 0x4C965D3: virEventPollCleanupHandles (vireventpoll.c:583)
    ==9237==    by 0x4C96987: virEventPollRunOnce (vireventpoll.c:652)
    ==9237==    by 0x4C94730: virEventRunDefaultImpl (virevent.c:274)
    ==9237==    by 0x12C7BA: vshEventLoop (virsh.c:2407)
    ==9237==    by 0x4CD3D04: virThreadHelper (virthreadpthread.c:161)
    ==9237==    by 0x7DAEF32: start_thread (pthread_create.c:309)
    ==9237==    by 0x8C86EAC: clone (clone.S:111)
    ==9237==  Address 0xe2d61b0 is 0 bytes inside a block of size 168 free'd
    ==9237==    at 0x4A07577: free (in /usr/lib64/valgrind/vgpreload_memcheck-amd64-linux.so)
    ==9237==    by 0x4C73827: virFree (viralloc.c:580)
    ==9237==    by 0x4DE4BC7: remoteAuthSASL (remote_driver.c:4219)
    ==9237==    by 0x4DE33D0: remoteAuthenticate (remote_driver.c:3639)
    ==9237==    by 0x4DDBFAA: doRemoteOpen (remote_driver.c:832)
    ==9237==    by 0x4DDC8DC: remoteConnectOpen (remote_driver.c:1031)
    ==9237==    by 0x4D8595F: do_open (libvirt.c:1239)
    ==9237==    by 0x4D863F3: virConnectOpenAuth (libvirt.c:1481)
    ==9237==    by 0x12762B: vshReconnect (virsh.c:337)
    ==9237==    by 0x12C9B0: vshInit (virsh.c:2470)
    ==9237==    by 0x12E9A5: main (virsh.c:3338)
    
    This commit changes virNetSASLSessionNewClient() to take ownership of the SASL
    callbacks. Then we can free them in virNetSASLSessionDispose() after the corresponding
    sasl_conn_t has been freed.

--- Additional comment from Sandro Bonazzola on 2013-12-02 14:18:13 UTC ---

(In reply to Yaniv Bronhaim from comment #9)
> Dan, this relates to nwfilter which uses libvirt. This looks like the
> segfault happens internally in libvirt code. doesn't it?
> 
> Sandro, reproducible or just happened?

reproducible quite often especially just after the boot.