Bug 1673101

Summary: failure to restart libvirt service
Product: Red Hat Enterprise Linux 7 Reporter: David Sariel <dsariel>
Component: libvirtAssignee: Libvirt Maintainers <libvirt-maint>
Status: CLOSED DUPLICATE QA Contact:
Severity: unspecified Docs Contact:
Priority: unspecified    
Version: 7.6CC: abregman, berrange, dsariel, geguileo, libvirt-maint, mpryc, tburke, tenobreg
Target Milestone: rc   
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2019-02-20 14:41:56 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Bug Depends On:    
Bug Blocks: 1670798    

Description David Sariel 2019-02-06 17:05:30 UTC 
Description of problem:
failure to restart libvirt service 


Version-Release number of selected component (if applicable):
libvirt.x86_64                   4.5.0-10.el7_6.4       @rhelosp-rhel-7.6-server




Steps to Reproduce:
1. 
Rebuild the job https://url.corp.redhat.com/cinder-for-rhos-7 for any simple change e.g. for 89860,37. 

2. 
Log to the undercloud machine and run sudo journalctl -xe


Actual results:
stack@undercloud-0 ~]$ sudo systemctl status libvirtd.service
● libvirtd.service - Virtualization daemon
   Loaded: loaded (/usr/lib/systemd/system/libvirtd.service; enabled; vendor preset: enabled)
   Active: failed (Result: start-limit) since Tue 2019-02-05 04:05:11 EST; 2min 21s ago
     Docs: man:libvirtd(8)
           https://libvirt.org
  Process: 9410 ExecStart=/usr/sbin/libvirtd $LIBVIRTD_ARGS (code=exited, status=3)
 Main PID: 9410 (code=exited, status=3)

Feb 05 04:05:11 undercloud-0.redhat.local systemd[1]: Failed to start Virtualization daemon.
Feb 05 04:05:11 undercloud-0.redhat.local systemd[1]: Unit libvirtd.service entered failed state.
Feb 05 04:05:11 undercloud-0.redhat.local systemd[1]: libvirtd.service failed.
Feb 05 04:05:11 undercloud-0.redhat.local systemd[1]: libvirtd.service holdoff time over, scheduling restart.
Feb 05 04:05:11 undercloud-0.redhat.local systemd[1]: Stopped Virtualization daemon.
Feb 05 04:05:11 undercloud-0.redhat.local systemd[1]: start request repeated too quickly for libvirtd.service
Feb 05 04:05:11 undercloud-0.redhat.local systemd[1]: Failed to start Virtualization daemon.
Feb 05 04:05:11 undercloud-0.redhat.local systemd[1]: Unit libvirtd.service entered failed state.
Feb 05 04:05:11 undercloud-0.redhat.local systemd[1]: libvirtd.service failed.




[stack@undercloud-0 ~]$ sudo journalctl -xe
Feb 05 04:08:09 undercloud-0.redhat.local ironic-api[2053]: 192.168.24.1 - - [05/Feb/2019 04:08:09] "GET / HTTP/1.0" 200 348
Feb 05 04:08:09 undercloud-0.redhat.local ironic-api[2053]: Traceback (most recent call last):
Feb 05 04:08:09 undercloud-0.redhat.local ironic-api[2053]: File "/usr/lib64/python2.7/wsgiref/handlers.py", line 86, in run
Feb 05 04:08:09 undercloud-0.redhat.local ironic-api[2053]: self.finish_response()
Feb 05 04:08:09 undercloud-0.redhat.local ironic-api[2053]: File "/usr/lib64/python2.7/wsgiref/handlers.py", line 128, in finish_response
Feb 05 04:08:09 undercloud-0.redhat.local ironic-api[2053]: self.write(data)
Feb 05 04:08:09 undercloud-0.redhat.local ironic-api[2053]: File "/usr/lib64/python2.7/wsgiref/handlers.py", line 212, in write
Feb 05 04:08:09 undercloud-0.redhat.local ironic-api[2053]: self.send_headers()
Feb 05 04:08:09 undercloud-0.redhat.local ironic-api[2053]: File "/usr/lib64/python2.7/wsgiref/handlers.py", line 271, in send_headers
Feb 05 04:08:09 undercloud-0.redhat.local ironic-api[2053]: self._write(str(self.headers))
Feb 05 04:08:09 undercloud-0.redhat.local ironic-api[2053]: File "/usr/lib64/python2.7/socket.py", line 324, in write
Feb 05 04:08:09 undercloud-0.redhat.local ironic-api[2053]: self.flush()
Feb 05 04:08:09 undercloud-0.redhat.local ironic-api[2053]: File "/usr/lib64/python2.7/socket.py", line 303, in flush
Feb 05 04:08:09 undercloud-0.redhat.local ironic-api[2053]: self._sock.sendall(view[write_offset:write_offset+buffer_size])
Feb 05 04:08:09 undercloud-0.redhat.local ironic-api[2053]: File "/usr/lib/python2.7/site-packages/eventlet/greenio/base.py", line 377, in sendall
Feb 05 04:08:09 undercloud-0.redhat.local ironic-api[2053]: tail = self.send(data, flags)
Feb 05 04:08:09 undercloud-0.redhat.local ironic-api[2053]: File "/usr/lib/python2.7/site-packages/eventlet/greenio/base.py", line 359, in send
Feb 05 04:08:09 undercloud-0.redhat.local ironic-api[2053]: total_sent += fd.send(data[total_sent:], flags)
Feb 05 04:08:09 undercloud-0.redhat.local ironic-api[2053]: error: [Errno 104] Connection reset by peer
Feb 05 04:08:09 undercloud-0.redhat.local ironic-api[2053]: 192.168.24.1 - - [05/Feb/2019 04:08:09] "GET / HTTP/1.0" 500 59
Feb 05 04:08:09 undercloud-0.redhat.local ironic-api[2053]: Traceback (most recent call last):
Feb 05 04:08:09 undercloud-0.redhat.local ironic-api[2053]: File "/usr/lib64/python2.7/SocketServer.py", line 593, in process_request_thread
Feb 05 04:08:09 undercloud-0.redhat.local ironic-api[2053]: self.finish_request(request, client_address)
Feb 05 04:08:09 undercloud-0.redhat.local ironic-api[2053]: File "/usr/lib64/python2.7/SocketServer.py", line 334, in finish_request
Feb 05 04:08:09 undercloud-0.redhat.local ironic-api[2053]: self.RequestHandlerClass(request, client_address, self)
Feb 05 04:08:09 undercloud-0.redhat.local ironic-api[2053]: File "/usr/lib64/python2.7/SocketServer.py", line 651, in __init__
Feb 05 04:08:09 undercloud-0.redhat.local ironic-api[2053]: self.finish()
Feb 05 04:08:09 undercloud-0.redhat.local ironic-api[2053]: File "/usr/lib64/python2.7/SocketServer.py", line 710, in finish
Feb 05 04:08:09 undercloud-0.redhat.local ironic-api[2053]: self.wfile.close()
Feb 05 04:08:09 undercloud-0.redhat.local ironic-api[2053]: File "/usr/lib64/python2.7/socket.py", line 279, in close
Feb 05 04:08:09 undercloud-0.redhat.local ironic-api[2053]: self.flush()
Feb 05 04:08:09 undercloud-0.redhat.local ironic-api[2053]: File "/usr/lib64/python2.7/socket.py", line 303, in flush
Feb 05 04:08:09 undercloud-0.redhat.local ironic-api[2053]: self._sock.sendall(view[write_offset:write_offset+buffer_size])
Feb 05 04:08:09 undercloud-0.redhat.local ironic-api[2053]: File "/usr/lib/python2.7/site-packages/eventlet/greenio/base.py", line 377, in sendall
Feb 05 04:08:09 undercloud-0.redhat.local ironic-api[2053]: tail = self.send(data, flags)
Feb 05 04:08:09 undercloud-0.redhat.local ironic-api[2053]: File "/usr/lib/python2.7/site-packages/eventlet/greenio/base.py", line 359, in send
Feb 05 04:08:09 undercloud-0.redhat.local ironic-api[2053]: total_sent += fd.send(data[total_sent:], flags)
Feb 05 04:08:09 undercloud-0.redhat.local ironic-api[2053]: error: [Errno 32] Broken pipe
Feb 05 04:08:09 undercloud-0.redhat.local sudo[10023]:    stack : TTY=pts/0 ; PWD=/home/stack ; USER=root ; COMMAND=/bin/journalctl -xe
Feb 05 04:08:09 undercloud-0.redhat.local sudo[10023]: pam_unix(sudo:session): session opened for user root by stack(uid=0)
[stack@undercloud-0 ~]$ 



Expected results:
libvirtd to restart with no errors
Comment 1 Peter Krempa 2019-02-07 07:20:26 UTC 
Please provide actual libvirtd logs. There's nothing libvirt related in the log dump above.
Comment 2 David Sariel 2019-02-20 14:07:29 UTC 
Sorry. Copy pasted the wrong section. The problem can be seen from here:

Feb 20 08:57:26 undercloud-0.redhat.local polkitd[3203]: Registered Authentication Agent for unix-process:12797:8889640 (system bus name :1.521 [/usr/bin/pkttyagent --notify-fd 5 --fallback], object path /org/freedesktop/PolicyKit1/AuthenticationAgent, locale en_US.UTF-8)
Feb 20 08:57:26 undercloud-0.redhat.local systemd[1]: Starting Virtualization daemon...
-- Subject: Unit libvirtd.service has begun start-up
-- Defined-By: systemd
-- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel
--
-- Unit libvirtd.service has begun starting up.
Feb 20 08:57:26 undercloud-0.redhat.local libvirtd[12803]: 2019-02-20 13:57:26.627+0000: 12803: info : libvirt version: 4.5.0, package: 10.el7_6.4 (Red Hat, Inc. <http://bugzilla.redhat.com/bugzilla>, 2019-01-10-06:11:18, x86-017.build.eng.bos.redhat.com)
Feb 20 08:57:26 undercloud-0.redhat.local libvirtd[12803]: 2019-02-20 13:57:26.627+0000: 12803: info : hostname: undercloud-0.redhat.local
Feb 20 08:57:26 undercloud-0.redhat.local libvirtd[12803]: 2019-02-20 13:57:26.627+0000: 12803: error : virModuleLoadFile:53 : internal error: Failed to load module '/usr/lib64/libvirt/storage-backend/libvirt_storage_backend_rbd.so': /usr/lib64/libvirt/storage-backend/libvirt_storage_backend_rbd.so: undefined symbol: rbd_diff_iterate2
Feb 20 08:57:26 undercloud-0.redhat.local systemd[1]: libvirtd.service: main process exited, code=exited, status=3/NOTIMPLEMENTED
Feb 20 08:57:26 undercloud-0.redhat.local systemd[1]: Failed to start Virtualization daemon.



Entire output of the "journal -xe" command is attached here: https://paste.fedoraproject.org/paste/miZSoqBYVlZxvCMpiDQ4eQ

This problem was encountered for other Openstack releases as well. E.g. rhos9 (https://bugzilla.redhat.com/show_bug.cgi?id=1670798) and seems to happen due to the jump in libvirt version from 3.9.0 to 4.5.0
Comment 5 Daniel Berrangé 2019-02-20 14:19:02 UTC 
*** Bug 1679160 has been marked as a duplicate of this bug. ***
Comment 6 Daniel Berrangé 2019-02-20 14:41:56 UTC 

*** This bug has been marked as a duplicate of bug 1658652 ***