oVirt system tests currently failing to AddHost on master
It hard to tell currently when did this start b/c we had so package issues that made the tests fail before reaching that point most of the day. Since we currently have an issue in Lago with collecting AddHost logs (Hopefully we'll resolve this in the next release early next week), I`ve ran the tests locally and attached the bundle of generated logs to this message. Included in the attached file are engine logs, host-deploy logs and VDSM logs for both test hosts.
From a quick look inside it seems the issue is with VDSM failing to start.
Thanks, -- Barak Korren bkorren@redhat.com RHCE, RHCi, RHV-DevOps Team https://ifireball.wordpress.com/
SuperVdsm fails to starts : MainThread::ERROR::2016-12-22 12:42:08,699::supervdsmServer::317::SuperVdsm.Server::(main) Could not start Super Vdsm Traceback (most recent call last): File "/usr/share/vdsm/supervdsmServer", line 297, in main server = manager.get_server() File "/usr/lib64/python2.7/multiprocessing/managers.py", line 493, in get_server self._authkey, self._serializer) File "/usr/lib64/python2.7/multiprocessing/managers.py", line 162, in __init__ self.listener = Listener(address=address, backlog=16) File "/usr/lib64/python2.7/multiprocessing/connection.py", line 136, in __init__ self._listener = SocketListener(address, family, backlog) File "/usr/lib64/python2.7/multiprocessing/connection.py", line 260, in __init__ self._socket.bind(address) File "/usr/lib64/python2.7/socket.py", line 224, in meth return getattr(self._sock,name)(*args) error: [Errno 2] No such file or directory On Thu, Dec 22, 2016 at 7:54 PM, Barak Korren <bkorren@redhat.com> wrote:
It hard to tell currently when did this start b/c we had so package issues that made the tests fail before reaching that point most of the day.
Since we currently have an issue in Lago with collecting AddHost logs (Hopefully we'll resolve this in the next release early next week), I`ve ran the tests locally and attached the bundle of generated logs to this message.
Included in the attached file are engine logs, host-deploy logs and VDSM logs for both test hosts.
From a quick look inside it seems the issue is with VDSM failing to start.
Thanks,
-- Barak Korren bkorren@redhat.com RHCE, RHCi, RHV-DevOps Team https://ifireball.wordpress.com/
_______________________________________________ Devel mailing list Devel@ovirt.org http://lists.ovirt.org/mailman/listinfo/devel
On Thu, Dec 22, 2016 at 9:12 PM, Fred Rolland <frolland@redhat.com> wrote:
SuperVdsm fails to starts :
MainThread::ERROR::2016-12-22 12:42:08,699::supervdsmServer::317::SuperVdsm.Server::(main) Could not start Super Vdsm Traceback (most recent call last): File "/usr/share/vdsm/supervdsmServer", line 297, in main server = manager.get_server() File "/usr/lib64/python2.7/multiprocessing/managers.py", line 493, in get_server self._authkey, self._serializer) File "/usr/lib64/python2.7/multiprocessing/managers.py", line 162, in __init__ self.listener = Listener(address=address, backlog=16) File "/usr/lib64/python2.7/multiprocessing/connection.py", line 136, in __init__ self._listener = SocketListener(address, family, backlog) File "/usr/lib64/python2.7/multiprocessing/connection.py", line 260, in __init__ self._socket.bind(address) File "/usr/lib64/python2.7/socket.py", line 224, in meth return getattr(self._sock,name)(*args) error: [Errno 2] No such file or directory
On Thu, Dec 22, 2016 at 7:54 PM, Barak Korren <bkorren@redhat.com> wrote:
It hard to tell currently when did this start b/c we had so package issues that made the tests fail before reaching that point most of the day.
Since we currently have an issue in Lago with collecting AddHost logs (Hopefully we'll resolve this in the next release early next week), I`ve ran the tests locally and attached the bundle of generated logs to this message.
Included in the attached file are engine logs, host-deploy logs and VDSM logs for both test hosts.
From a quick look inside it seems the issue is with VDSM failing to start.
From host-deploy/ovirt-host-deploy-20161222124209-192.168.203.4-604a4799.log:
2016-12-22 12:42:05 DEBUG otopi.plugins.otopi.services.systemd plugin.executeRaw:813 execute: ('/bin/systemctl', 'start', 'vdsmd.service'), executable='None', cwd='None', env=None 2016-12-22 12:42:09 DEBUG otopi.plugins.otopi.services.systemd plugin.executeRaw:863 execute-result: ('/bin/systemctl', 'start', 'vdsmd.service'), rc=1 2016-12-22 12:42:09 DEBUG otopi.plugins.otopi.services.systemd plugin.execute:921 execute-output: ('/bin/systemctl', 'start', 'vdsmd.service') stdout: 2016-12-22 12:42:09 DEBUG otopi.plugins.otopi.services.systemd plugin.execute:926 execute-output: ('/bin/systemctl', 'start', 'vdsmd.service') stderr: A dependency job for vdsmd.service failed. See 'journalctl -xe' for details. This means that one of the services vdsm depends on could not start. 2016-12-22 12:42:09 DEBUG otopi.context context._executeMethod:142 method exception Traceback (most recent call last): File "/tmp/ovirt-bUCuRxXXzU/pythonlib/otopi/context.py", line 132, in _executeMethod method['method']() File "/tmp/ovirt-bUCuRxXXzU/otopi-plugins/ovirt-host-deploy/vdsm/packages.py", line 209, in _start self.services.state('vdsmd', True) File "/tmp/ovirt-bUCuRxXXzU/otopi-plugins/otopi/services/systemd.py", line 141, in state service=name, RuntimeError: Failed to start service 'vdsmd' This error is not very useful for anyone. What we need in otopi log is the output of journalctl -xe (suggested by systemctl). Didi, can we collect this info when starting a service fail? Barak, can you log in to the host with this error and collect the output?
Thanks,
-- Barak Korren bkorren@redhat.com RHCE, RHCi, RHV-DevOps Team https://ifireball.wordpress.com/
_______________________________________________ Devel mailing list Devel@ovirt.org http://lists.ovirt.org/mailman/listinfo/devel
_______________________________________________ Devel mailing list Devel@ovirt.org http://lists.ovirt.org/mailman/listinfo/devel
On 22 December 2016 at 21:56, Nir Soffer <nsoffer@redhat.com> wrote:
On Thu, Dec 22, 2016 at 9:12 PM, Fred Rolland <frolland@redhat.com> wrote:
SuperVdsm fails to starts :
MainThread::ERROR::2016-12-22 12:42:08,699::supervdsmServer::317::SuperVdsm.Server::(main) Could not start Super Vdsm Traceback (most recent call last): File "/usr/share/vdsm/supervdsmServer", line 297, in main server = manager.get_server() File "/usr/lib64/python2.7/multiprocessing/managers.py", line 493, in get_server self._authkey, self._serializer) File "/usr/lib64/python2.7/multiprocessing/managers.py", line 162, in __init__ self.listener = Listener(address=address, backlog=16) File "/usr/lib64/python2.7/multiprocessing/connection.py", line 136, in __init__ self._listener = SocketListener(address, family, backlog) File "/usr/lib64/python2.7/multiprocessing/connection.py", line 260, in __init__ self._socket.bind(address) File "/usr/lib64/python2.7/socket.py", line 224, in meth return getattr(self._sock,name)(*args) error: [Errno 2] No such file or directory
On Thu, Dec 22, 2016 at 7:54 PM, Barak Korren <bkorren@redhat.com> wrote:
It hard to tell currently when did this start b/c we had so package issues that made the tests fail before reaching that point most of the day.
Since we currently have an issue in Lago with collecting AddHost logs (Hopefully we'll resolve this in the next release early next week), I`ve ran the tests locally and attached the bundle of generated logs to this message.
Included in the attached file are engine logs, host-deploy logs and VDSM logs for both test hosts.
From a quick look inside it seems the issue is with VDSM failing to start.
From host-deploy/ovirt-host-deploy-20161222124209-192.168.203.4-604a4799.log:
2016-12-22 12:42:05 DEBUG otopi.plugins.otopi.services.systemd plugin.executeRaw:813 execute: ('/bin/systemctl', 'start', 'vdsmd.service'), executable='None', cwd='None', env=None 2016-12-22 12:42:09 DEBUG otopi.plugins.otopi.services.systemd plugin.executeRaw:863 execute-result: ('/bin/systemctl', 'start', 'vdsmd.service'), rc=1 2016-12-22 12:42:09 DEBUG otopi.plugins.otopi.services.systemd plugin.execute:921 execute-output: ('/bin/systemctl', 'start', 'vdsmd.service') stdout:
2016-12-22 12:42:09 DEBUG otopi.plugins.otopi.services.systemd plugin.execute:926 execute-output: ('/bin/systemctl', 'start', 'vdsmd.service') stderr: A dependency job for vdsmd.service failed. See 'journalctl -xe' for details.
This means that one of the services vdsm depends on could not start.
2016-12-22 12:42:09 DEBUG otopi.context context._executeMethod:142 method exception Traceback (most recent call last): File "/tmp/ovirt-bUCuRxXXzU/pythonlib/otopi/context.py", line 132, in _executeMethod method['method']() File "/tmp/ovirt-bUCuRxXXzU/otopi-plugins/ovirt-host-deploy/vdsm/packages.py", line 209, in _start self.services.state('vdsmd', True) File "/tmp/ovirt-bUCuRxXXzU/otopi-plugins/otopi/services/systemd.py", line 141, in state service=name, RuntimeError: Failed to start service 'vdsmd'
This error is not very useful for anyone. What we need in otopi log is the output of journalctl -xe (suggested by systemctl).
Didi, can we collect this info when starting a service fail?
Barak, can you log in to the host with this error and collect the output?
By the time I looged in to the host, all IP addresses are gone (I'm guessing the setup process killed dhclient), so I'm having to work via the serial console) 1: lo: <LOOPBACK,UP,LOWER_UP> mtu 65536 qdisc noqueue state UNKNOWN link/loopback 00:00:00:00:00:00 brd 00:00:00:00:00:00 inet 127.0.0.1/8 scope host lo valid_lft forever preferred_lft forever inet6 ::1/128 scope host valid_lft forever preferred_lft forever 2: eth0: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc pfifo_fast state UP qlen 1000 link/ether 54:52:c0:a8:cb:02 brd ff:ff:ff:ff:ff:ff inet6 fe80::5652:c0ff:fea8:cb02/64 scope link valid_lft forever preferred_lft forever 3: eth1: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc pfifo_fast state UP qlen 1000 link/ether 54:52:c0:a8:cc:02 brd ff:ff:ff:ff:ff:ff inet6 fe80::5652:c0ff:fea8:cc02/64 scope link valid_lft forever preferred_lft forever 4: eth2: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc pfifo_fast state UP qlen 1000 link/ether 54:52:c0:a8:cc:03 brd ff:ff:ff:ff:ff:ff inet6 fe80::5652:c0ff:fea8:cc03/64 scope link valid_lft forever preferred_lft forever 5: eth3: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc pfifo_fast state UP qlen 1000 link/ether 54:52:c0:a8:ca:02 brd ff:ff:ff:ff:ff:ff inet6 fe80::5652:c0ff:fea8:ca02/64 scope link valid_lft forever preferred_lft forever Here is the interesting stuff I can gather from journalctl: Dec 22 12:42:06 lago-basic-suite-master-host0 ovirt-imageio-daemon[5007]: Traceback (most recent call last): Dec 22 12:42:06 lago-basic-suite-master-host0 ovirt-imageio-daemon[5007]: File "/usr/bin/ovirt-imageio-daemon", line 14, in <module> Dec 22 12:42:06 lago-basic-suite-master-host0 ovirt-imageio-daemon[5007]: server.main(sys.argv) Dec 22 12:42:06 lago-basic-suite-master-host0 ovirt-imageio-daemon[5007]: File "/usr/lib/python2.7/site-packages/ovirt_imageio_daemon/server.py", line 51, in main Dec 22 12:42:06 lago-basic-suite-master-host0 ovirt-imageio-daemon[5007]: configure_logger() Dec 22 12:42:06 lago-basic-suite-master-host0 ovirt-imageio-daemon[5007]: File "/usr/lib/python2.7/site-packages/ovirt_imageio_daemon/server.py", line 69, in configure_logger Dec 22 12:42:06 lago-basic-suite-master-host0 ovirt-imageio-daemon[5007]: logging.config.fileConfig(conf, disable_existing_loggers=False) Dec 22 12:42:06 lago-basic-suite-master-host0 ovirt-imageio-daemon[5007]: File "/usr/lib64/python2.7/logging/config.py", line 78, in fileConfig Dec 22 12:42:06 lago-basic-suite-master-host0 iscsid[5043]: iSCSI daemon with pid=5044 started! Dec 22 12:42:06 lago-basic-suite-master-host0 ovirt-imageio-daemon[5007]: handlers = _install_handlers(cp, formatters) Dec 22 12:42:06 lago-basic-suite-master-host0 ovirt-imageio-daemon[5007]: File "/usr/lib64/python2.7/logging/config.py", line 156, in _install_handlers Dec 22 12:42:06 lago-basic-suite-master-host0 ovirt-imageio-daemon[5007]: h = klass(*args) Dec 22 12:42:06 lago-basic-suite-master-host0 ovirt-imageio-daemon[5007]: File "/usr/lib64/python2.7/logging/handlers.py", line 117, in __init__ Dec 22 12:42:06 lago-basic-suite-master-host0 ovirt-imageio-daemon[5007]: BaseRotatingHandler.__init__(self, filename, mode, encoding, delay) Dec 22 12:42:06 lago-basic-suite-master-host0 ovirt-imageio-daemon[5007]: File "/usr/lib64/python2.7/logging/handlers.py", line 64, in __init__ Dec 22 12:42:06 lago-basic-suite-master-host0 ovirt-imageio-daemon[5007]: logging.FileHandler.__init__(self, filename, mode, encoding, delay) Dec 22 12:42:06 lago-basic-suite-master-host0 ovirt-imageio-daemon[5007]: File "/usr/lib64/python2.7/logging/__init__.py", line 902, in __init__ Dec 22 12:42:06 lago-basic-suite-master-host0 ovirt-imageio-daemon[5007]: StreamHandler.__init__(self, self._open()) Dec 22 12:42:06 lago-basic-suite-master-host0 ovirt-imageio-daemon[5007]: File "/usr/lib64/python2.7/logging/__init__.py", line 925, in _open Dec 22 12:42:06 lago-basic-suite-master-host0 ovirt-imageio-daemon[5007]: stream = open(self.baseFilename, self.mode) Dec 22 12:42:06 lago-basic-suite-master-host0 ovirt-imageio-daemon[5007]: IOError: [Errno 13] Permission denied: '/var/log/ovirt-imageio-daemon/daemon.log' Dec 22 12:42:06 lago-basic-suite-master-host0 systemd[1]: ovirt-imageio-daemon.service: main process exited, code=exited, status=1/FAILURE Dec 22 12:42:06 lago-basic-suite-master-host0 systemd[1]: Failed to start oVirt ImageIO Daemon. -- Subject: Unit ovirt-imageio-daemon.service has failed -- Defined-By: systemd -- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel -- -- Unit ovirt-imageio-daemon.service has failed. -- -- The result is failed. Dec 22 12:42:06 lago-basic-suite-master-host0 systemd[1]: Unit ovirt-imageio-daemon.service entered failed state. Dec 22 12:42:06 lago-basic-suite-master-host0 systemd[1]: ovirt-imageio-daemon.service failed. Dec 22 12:42:06 lago-basic-suite-master-host0 systemd[1]: supervdsmd.service: main process exited, code=exited, status=1/FAILURE Dec 22 12:42:06 lago-basic-suite-master-host0 systemd[1]: Unit supervdsmd.service entered failed state. Dec 22 12:42:06 lago-basic-suite-master-host0 systemd[1]: supervdsmd.service failed. Dec 22 12:42:07 lago-basic-suite-master-host0 systemd[1]: Started Virtualization daemon. -- Subject: Unit libvirtd.service has finished start-up -- Defined-By: systemd -- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel -- -- Unit libvirtd.service has finished starting up. -- -- The start-up result is done. Dec 22 12:42:07 lago-basic-suite-master-host0 systemd[1]: ovirt-imageio-daemon.service holdoff time over, scheduling restart. Dec 22 12:42:07 lago-basic-suite-master-host0 systemd[1]: supervdsmd.service holdoff time over, scheduling restart. Dec 22 12:42:07 lago-basic-suite-master-host0 systemd[1]: Starting oVirt ImageIO Daemon... -- Subject: Unit ovirt-imageio-daemon.service has begun start-up -- Defined-By: systemd -- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel -- -- Unit ovirt-imageio-daemon.service has begun starting up. Dec 22 12:42:07 lago-basic-suite-master-host0 systemd[1]: Started Auxiliary vdsm service for running helper functions as root. -- Subject: Unit supervdsmd.service has finished start-up -- Defined-By: systemd -- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel -- -- Unit supervdsmd.service has finished starting up. -- -- The start-up result is done. Dec 22 12:42:07 lago-basic-suite-master-host0 systemd[1]: Starting Auxiliary vdsm service for running helper functions as root... -- Subject: Unit supervdsmd.service has begun start-up -- Defined-By: systemd -- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel -- -- Unit supervdsmd.service has begun starting up. Dec 22 12:42:07 lago-basic-suite-master-host0 systemd[1]: Starting Virtual Desktop Server Manager network restoration... -- Subject: Unit vdsm-network.service has begun start-up -- Defined-By: systemd -- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel -- -- Unit vdsm-network.service has begun starting up. Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5082]: Traceback (most recent call last): Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5082]: File "/usr/bin/ovirt-imageio-daemon", line 14, in <module> Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5082]: server.main(sys.argv) Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5082]: File "/usr/lib/python2.7/site-packages/ovirt_imageio_daemon/server.py", line 51, in main Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5082]: configure_logger() Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5082]: File "/usr/lib/python2.7/site-packages/ovirt_imageio_daemon/server.py", line 69, in configure_logger Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5082]: logging.config.fileConfig(conf, disable_existing_loggers=False) Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5082]: File "/usr/lib64/python2.7/logging/config.py", line 78, in fileConfig Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5082]: handlers = _install_handlers(cp, formatters) Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5082]: File "/usr/lib64/python2.7/logging/config.py", line 156, in _install_handlers Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5082]: h = klass(*args) Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5082]: File "/usr/lib64/python2.7/logging/handlers.py", line 117, in __init__ Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5082]: BaseRotatingHandler.__init__(self, filename, mode, encoding, delay) Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5082]: File "/usr/lib64/python2.7/logging/handlers.py", line 64, in __init__ Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5082]: logging.FileHandler.__init__(self, filename, mode, encoding, delay) Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5082]: File "/usr/lib64/python2.7/logging/__init__.py", line 902, in __init__ Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5082]: StreamHandler.__init__(self, self._open()) Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5082]: File "/usr/lib64/python2.7/logging/__init__.py", line 925, in _open Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5082]: stream = open(self.baseFilename, self.mode) Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5082]: IOError: [Errno 13] Permission denied: '/var/log/ovirt-imageio-daemon/daemon.log' Dec 22 12:42:07 lago-basic-suite-master-host0 systemd[1]: ovirt-imageio-daemon.service: main process exited, code=exited, status=1/FAILURE Dec 22 12:42:07 lago-basic-suite-master-host0 systemd[1]: Failed to start oVirt ImageIO Daemon. -- Subject: Unit ovirt-imageio-daemon.service has failed -- Defined-By: systemd -- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel -- -- Unit ovirt-imageio-daemon.service has failed. -- -- The result is failed. Dec 22 12:42:07 lago-basic-suite-master-host0 systemd[1]: Unit ovirt-imageio-daemon.service entered failed state. Dec 22 12:42:07 lago-basic-suite-master-host0 systemd[1]: ovirt-imageio-daemon.service failed. Dec 22 12:42:07 lago-basic-suite-master-host0 systemd[1]: supervdsmd.service: main process exited, code=exited, status=1/FAILURE Dec 22 12:42:07 lago-basic-suite-master-host0 systemd[1]: Unit supervdsmd.service entered failed state. Dec 22 12:42:07 lago-basic-suite-master-host0 systemd[1]: supervdsmd.service failed. Dec 22 12:42:07 lago-basic-suite-master-host0 systemd[1]: ovirt-imageio-daemon.service holdoff time over, scheduling restart. Dec 22 12:42:07 lago-basic-suite-master-host0 systemd[1]: supervdsmd.service holdoff time over, scheduling restart. Dec 22 12:42:07 lago-basic-suite-master-host0 systemd[1]: Started Auxiliary vdsm service for running helper functions as root. -- Subject: Unit supervdsmd.service has finished start-up -- Defined-By: systemd -- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel -- -- Unit supervdsmd.service has finished starting up. -- -- The start-up result is done. Dec 22 12:42:07 lago-basic-suite-master-host0 systemd[1]: Starting Auxiliary vdsm service for running helper functions as root... -- Subject: Unit supervdsmd.service has begun start-up -- Defined-By: systemd -- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel -- -- Unit supervdsmd.service has begun starting up. Dec 22 12:42:07 lago-basic-suite-master-host0 systemd[1]: Starting oVirt ImageIO Daemon... -- Subject: Unit ovirt-imageio-daemon.service has begun start-up -- Defined-By: systemd -- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel -- -- Unit ovirt-imageio-daemon.service has begun starting up. Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5110]: Traceback (most recent call last): Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5110]: File "/usr/bin/ovirt-imageio-daemon", line 14, in <module> Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5110]: server.main(sys.argv) Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5110]: File "/usr/lib/python2.7/site-packages/ovirt_imageio_daemon/server.py", line 51, in main Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5110]: configure_logger() Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5110]: File "/usr/lib/python2.7/site-packages/ovirt_imageio_daemon/server.py", line 69, in configure_logger Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5110]: logging.config.fileConfig(conf, disable_existing_loggers=False) Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5110]: File "/usr/lib64/python2.7/logging/config.py", line 78, in fileConfig Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5110]: handlers = _install_handlers(cp, formatters) Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5110]: File "/usr/lib64/python2.7/logging/config.py", line 156, in _install_handlers Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5110]: h = klass(*args) Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5110]: File "/usr/lib64/python2.7/logging/handlers.py", line 117, in __init__ Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5110]: BaseRotatingHandler.__init__(self, filename, mode, encoding, delay) Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5110]: File "/usr/lib64/python2.7/logging/handlers.py", line 64, in __init__ Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5110]: logging.FileHandler.__init__(self, filename, mode, encoding, delay) Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5110]: File "/usr/lib64/python2.7/logging/__init__.py", line 902, in __init__ Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5110]: StreamHandler.__init__(self, self._open()) Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5110]: File "/usr/lib64/python2.7/logging/__init__.py", line 925, in _open Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5110]: stream = open(self.baseFilename, self.mode) Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5110]: IOError: [Errno 13] Permission denied: '/var/log/ovirt-imageio-daemon/daemon.log' Dec 22 12:42:07 lago-basic-suite-master-host0 systemd[1]: ovirt-imageio-daemon.service: main process exited, code=exited, status=1/FAILURE Dec 22 12:42:07 lago-basic-suite-master-host0 systemd[1]: Failed to start oVirt ImageIO Daemon. -- Subject: Unit ovirt-imageio-daemon.service has failed -- Defined-By: systemd -- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel -- -- Unit ovirt-imageio-daemon.service has failed. -- -- The result is failed. Dec 22 12:42:07 lago-basic-suite-master-host0 systemd[1]: Unit ovirt-imageio-daemon.service entered failed state. Dec 22 12:42:07 lago-basic-suite-master-host0 systemd[1]: ovirt-imageio-daemon.service failed. Dec 22 12:42:07 lago-basic-suite-master-host0 systemd[1]: supervdsmd.service: main process exited, code=exited, status=1/FAILURE Dec 22 12:42:07 lago-basic-suite-master-host0 systemd[1]: Unit supervdsmd.service entered failed state. Dec 22 12:42:07 lago-basic-suite-master-host0 systemd[1]: supervdsmd.service failed. Dec 22 12:42:07 lago-basic-suite-master-host0 systemd[1]: ovirt-imageio-daemon.service holdoff time over, scheduling restart. Dec 22 12:42:07 lago-basic-suite-master-host0 systemd[1]: Starting oVirt ImageIO Daemon... -- Subject: Unit ovirt-imageio-daemon.service has begun start-up -- Defined-By: systemd -- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel -- -- Unit ovirt-imageio-daemon.service has begun starting up. Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5125]: Traceback (most recent call last): Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5125]: File "/usr/bin/ovirt-imageio-daemon", line 14, in <module> Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5125]: server.main(sys.argv) Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5125]: File "/usr/lib/python2.7/site-packages/ovirt_imageio_daemon/server.py", line 51, in main Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5125]: configure_logger() Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5125]: File "/usr/lib/python2.7/site-packages/ovirt_imageio_daemon/server.py", line 69, in configure_logger Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5125]: logging.config.fileConfig(conf, disable_existing_loggers=False) Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5125]: File "/usr/lib64/python2.7/logging/config.py", line 78, in fileConfig Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5125]: handlers = _install_handlers(cp, formatters) Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5125]: File "/usr/lib64/python2.7/logging/config.py", line 156, in _install_handlers Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5125]: h = klass(*args) Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5125]: File "/usr/lib64/python2.7/logging/handlers.py", line 117, in __init__ Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5125]: BaseRotatingHandler.__init__(self, filename, mode, encoding, delay) Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5125]: File "/usr/lib64/python2.7/logging/handlers.py", line 64, in __init__ Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5125]: logging.FileHandler.__init__(self, filename, mode, encoding, delay) Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5125]: File "/usr/lib64/python2.7/logging/__init__.py", line 902, in __init__ Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5125]: StreamHandler.__init__(self, self._open()) Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5125]: File "/usr/lib64/python2.7/logging/__init__.py", line 925, in _open Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5125]: stream = open(self.baseFilename, self.mode) Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5125]: IOError: [Errno 13] Permission denied: '/var/log/ovirt-imageio-daemon/daemon.log' Dec 22 12:42:07 lago-basic-suite-master-host0 systemd[1]: ovirt-imageio-daemon.service: main process exited, code=exited, status=1/FAILURE Dec 22 12:42:07 lago-basic-suite-master-host0 systemd[1]: Failed to start oVirt ImageIO Daemon. -- Subject: Unit ovirt-imageio-daemon.service has failed -- Defined-By: systemd -- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel -- -- Unit ovirt-imageio-daemon.service has failed. -- -- The result is failed. Dec 22 12:42:07 lago-basic-suite-master-host0 systemd[1]: Unit ovirt-imageio-daemon.service entered failed state. Dec 22 12:42:07 lago-basic-suite-master-host0 systemd[1]: ovirt-imageio-daemon.service failed. Dec 22 12:42:08 lago-basic-suite-master-host0 systemd[1]: ovirt-imageio-daemon.service holdoff time over, scheduling restart. Dec 22 12:42:08 lago-basic-suite-master-host0 systemd[1]: supervdsmd.service holdoff time over, scheduling restart. Dec 22 12:42:08 lago-basic-suite-master-host0 systemd[1]: Started Auxiliary vdsm service for running helper functions as root. -- Subject: Unit supervdsmd.service has finished start-up -- Defined-By: systemd -- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel -- -- Unit supervdsmd.service has finished starting up. -- -- The start-up result is done. Dec 22 12:42:08 lago-basic-suite-master-host0 systemd[1]: Starting Auxiliary vdsm service for running helper functions as root... -- Subject: Unit supervdsmd.service has begun start-up -- Defined-By: systemd -- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel -- -- Unit supervdsmd.service has begun starting up. Dec 22 12:42:08 lago-basic-suite-master-host0 systemd[1]: Starting oVirt ImageIO Daemon... -- Subject: Unit ovirt-imageio-daemon.service has begun start-up -- Defined-By: systemd -- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel -- -- Unit ovirt-imageio-daemon.service has begun starting up. Dec 22 12:42:08 lago-basic-suite-master-host0 systemd[1]: ovirt-imageio-daemon.service: main process exited, code=exited, status=1/FAILURE Dec 22 12:42:08 lago-basic-suite-master-host0 systemd[1]: Failed to start oVirt ImageIO Daemon. -- Subject: Unit ovirt-imageio-daemon.service has failed -- Defined-By: systemd -- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel -- -- Unit ovirt-imageio-daemon.service has failed. -- -- The result is failed. ... snip ... keeps repeating .... Dec 22 12:42:09 lago-basic-suite-master-host0 systemd[1]: start request repeated too quickly for supervdsmd.service Dec 22 12:42:09 lago-basic-suite-master-host0 systemd[1]: Failed to start Auxiliary vdsm service for running helper functions as root. -- Subject: Unit supervdsmd.service has failed -- Defined-By: systemd -- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel -- -- Unit supervdsmd.service has failed. -- -- The result is failed. Dec 22 12:42:09 lago-basic-suite-master-host0 systemd[1]: Dependency failed for Virtual Desktop Server Manager. -- Subject: Unit vdsmd.service has failed -- Defined-By: systemd -- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel -- -- Unit vdsmd.service has failed. -- -- The result is dependency. Dec 22 12:42:09 lago-basic-suite-master-host0 systemd[1]: Dependency failed for MOM instance configured for VDSM purposes. -- Subject: Unit mom-vdsm.service has failed -- Defined-By: systemd -- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel -- -- Unit mom-vdsm.service has failed. -- -- The result is dependency. Dec 22 12:42:09 lago-basic-suite-master-host0 systemd[1]: Job mom-vdsm.service/start failed with result 'dependency'. Dec 22 12:42:09 lago-basic-suite-master-host0 systemd[1]: Job vdsmd.service/start failed with result 'dependency'. Dec 22 12:42:09 lago-basic-suite-master-host0 systemd[1]: Unit supervdsmd.service entered failed state. Dec 22 12:42:09 lago-basic-suite-master-host0 systemd[1]: supervdsmd.service failed. ... snip ... unrelated stuff .... Dec 22 12:42:11 lago-basic-suite-master-host0 vdsm-tool[5175]: Traceback (most recent call last): Dec 22 12:42:11 lago-basic-suite-master-host0 vdsm-tool[5175]: File "/usr/share/vdsm/vdsm-restore-net-config", line 482, in <module> Dec 22 12:42:11 lago-basic-suite-master-host0 vdsm-tool[5175]: restore(args) Dec 22 12:42:11 lago-basic-suite-master-host0 vdsm-tool[5175]: File "/usr/share/vdsm/vdsm-restore-net-config", line 455, in restore Dec 22 12:42:11 lago-basic-suite-master-host0 vdsm-tool[5175]: touch_file(NETS_RESTORED_MARK) Dec 22 12:42:11 lago-basic-suite-master-host0 vdsm-tool[5175]: File "/usr/share/vdsm/vdsm-restore-net-config", line 431, in touch_file Dec 22 12:42:11 lago-basic-suite-master-host0 vdsm-tool[5175]: with open(file_path, 'a'): Dec 22 12:42:11 lago-basic-suite-master-host0 vdsm-tool[5175]: IOError: [Errno 2] No such file or directory: '/var/run/vdsm/nets_restored' Dec 22 12:42:11 lago-basic-suite-master-host0 vdsm-tool[5175]: Traceback (most recent call last): Dec 22 12:42:11 lago-basic-suite-master-host0 vdsm-tool[5175]: File "/usr/bin/vdsm-tool", line 219, in main Dec 22 12:42:11 lago-basic-suite-master-host0 vdsm-tool[5175]: return tool_command[cmd]["command"](*args) Dec 22 12:42:11 lago-basic-suite-master-host0 vdsm-tool[5175]: File "/usr/lib/python2.7/site-packages/vdsm/tool/restore_nets.py", line 41, in restore_command Dec 22 12:42:11 lago-basic-suite-master-host0 vdsm-tool[5175]: exec_restore(cmd) Dec 22 12:42:11 lago-basic-suite-master-host0 vdsm-tool[5175]: File "/usr/lib/python2.7/site-packages/vdsm/tool/restore_nets.py", line 54, in exec_restore Dec 22 12:42:11 lago-basic-suite-master-host0 vdsm-tool[5175]: raise EnvironmentError('Failed to restore the persisted networks') Dec 22 12:42:11 lago-basic-suite-master-host0 vdsm-tool[5175]: EnvironmentError: Failed to restore the persisted networks Dec 22 12:42:11 lago-basic-suite-master-host0 systemd[1]: vdsm-network.service: main process exited, code=exited, status=1/FAILURE Dec 22 12:42:11 lago-basic-suite-master-host0 systemd[1]: Failed to start Virtual Desktop Server Manager network restoration. -- Subject: Unit vdsm-network.service has failed -- Defined-By: systemd -- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel -- -- Unit vdsm-network.service has failed. -- -- The result is failed. Dec 22 12:42:11 lago-basic-suite-master-host0 systemd[1]: Unit vdsm-network.service entered failed state. Dec 22 12:42:11 lago-basic-suite-master-host0 systemd[1]: vdsm-network.service failed. HTH, Barak. -- Barak Korren bkorren@redhat.com RHCE, RHCi, RHV-DevOps Team https://ifireball.wordpress.com/
On Fri, Dec 23, 2016 at 6:20 PM, Barak Korren <bkorren@redhat.com> wrote:
On 22 December 2016 at 21:56, Nir Soffer <nsoffer@redhat.com> wrote:
On Thu, Dec 22, 2016 at 9:12 PM, Fred Rolland <frolland@redhat.com> wrote:
SuperVdsm fails to starts :
MainThread::ERROR::2016-12-22 12:42:08,699::supervdsmServer::317::SuperVdsm.Server::(main) Could not start Super Vdsm Traceback (most recent call last): File "/usr/share/vdsm/supervdsmServer", line 297, in main server = manager.get_server() File "/usr/lib64/python2.7/multiprocessing/managers.py", line 493, in get_server self._authkey, self._serializer) File "/usr/lib64/python2.7/multiprocessing/managers.py", line 162, in __init__ self.listener = Listener(address=address, backlog=16) File "/usr/lib64/python2.7/multiprocessing/connection.py", line 136, in __init__ self._listener = SocketListener(address, family, backlog) File "/usr/lib64/python2.7/multiprocessing/connection.py", line 260, in __init__ self._socket.bind(address) File "/usr/lib64/python2.7/socket.py", line 224, in meth return getattr(self._sock,name)(*args) error: [Errno 2] No such file or directory
On Thu, Dec 22, 2016 at 7:54 PM, Barak Korren <bkorren@redhat.com> wrote:
It hard to tell currently when did this start b/c we had so package issues that made the tests fail before reaching that point most of the day.
Since we currently have an issue in Lago with collecting AddHost logs (Hopefully we'll resolve this in the next release early next week), I`ve ran the tests locally and attached the bundle of generated logs to this message.
Included in the attached file are engine logs, host-deploy logs and VDSM logs for both test hosts.
From a quick look inside it seems the issue is with VDSM failing to start.
From host-deploy/ovirt-host-deploy-20161222124209-192.168.203.4-604a4799.log:
2016-12-22 12:42:05 DEBUG otopi.plugins.otopi.services.systemd plugin.executeRaw:813 execute: ('/bin/systemctl', 'start', 'vdsmd.service'), executable='None', cwd='None', env=None 2016-12-22 12:42:09 DEBUG otopi.plugins.otopi.services.systemd plugin.executeRaw:863 execute-result: ('/bin/systemctl', 'start', 'vdsmd.service'), rc=1 2016-12-22 12:42:09 DEBUG otopi.plugins.otopi.services.systemd plugin.execute:921 execute-output: ('/bin/systemctl', 'start', 'vdsmd.service') stdout:
2016-12-22 12:42:09 DEBUG otopi.plugins.otopi.services.systemd plugin.execute:926 execute-output: ('/bin/systemctl', 'start', 'vdsmd.service') stderr: A dependency job for vdsmd.service failed. See 'journalctl -xe' for details.
This means that one of the services vdsm depends on could not start.
2016-12-22 12:42:09 DEBUG otopi.context context._executeMethod:142 method exception Traceback (most recent call last): File "/tmp/ovirt-bUCuRxXXzU/pythonlib/otopi/context.py", line 132, in _executeMethod method['method']() File "/tmp/ovirt-bUCuRxXXzU/otopi-plugins/ovirt-host-deploy/vdsm/packages.py", line 209, in _start self.services.state('vdsmd', True) File "/tmp/ovirt-bUCuRxXXzU/otopi-plugins/otopi/services/systemd.py", line 141, in state service=name, RuntimeError: Failed to start service 'vdsmd'
This error is not very useful for anyone. What we need in otopi log is the output of journalctl -xe (suggested by systemctl).
Didi, can we collect this info when starting a service fail?
Barak, can you log in to the host with this error and collect the output?
By the time I looged in to the host, all IP addresses are gone (I'm guessing the setup process killed dhclient), so I'm having to work via the serial console)
1: lo: <LOOPBACK,UP,LOWER_UP> mtu 65536 qdisc noqueue state UNKNOWN link/loopback 00:00:00:00:00:00 brd 00:00:00:00:00:00 inet 127.0.0.1/8 scope host lo valid_lft forever preferred_lft forever inet6 ::1/128 scope host valid_lft forever preferred_lft forever 2: eth0: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc pfifo_fast state UP qlen 1000 link/ether 54:52:c0:a8:cb:02 brd ff:ff:ff:ff:ff:ff inet6 fe80::5652:c0ff:fea8:cb02/64 scope link valid_lft forever preferred_lft forever 3: eth1: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc pfifo_fast state UP qlen 1000 link/ether 54:52:c0:a8:cc:02 brd ff:ff:ff:ff:ff:ff inet6 fe80::5652:c0ff:fea8:cc02/64 scope link valid_lft forever preferred_lft forever 4: eth2: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc pfifo_fast state UP qlen 1000 link/ether 54:52:c0:a8:cc:03 brd ff:ff:ff:ff:ff:ff inet6 fe80::5652:c0ff:fea8:cc03/64 scope link valid_lft forever preferred_lft forever 5: eth3: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc pfifo_fast state UP qlen 1000 link/ether 54:52:c0:a8:ca:02 brd ff:ff:ff:ff:ff:ff inet6 fe80::5652:c0ff:fea8:ca02/64 scope link valid_lft forever preferred_lft forever
Here is the interesting stuff I can gather from journalctl:
Dec 22 12:42:06 lago-basic-suite-master-host0 ovirt-imageio-daemon[5007]: Traceback (most recent call last): Dec 22 12:42:06 lago-basic-suite-master-host0 ovirt-imageio-daemon[5007]: File "/usr/bin/ovirt-imageio-daemon", line 14, in <module>
Thanks, Barak. My guess stays with Bug 1400003 - imageio fails during system startup as the culprit.
On Fri, Dec 23, 2016 at 6:20 PM, Barak Korren <bkorren@redhat.com> wrote:
On 22 December 2016 at 21:56, Nir Soffer <nsoffer@redhat.com> wrote:
On Thu, Dec 22, 2016 at 9:12 PM, Fred Rolland <frolland@redhat.com> wrote:
SuperVdsm fails to starts :
MainThread::ERROR::2016-12-22 12:42:08,699::supervdsmServer::317::SuperVdsm.Server::(main) Could not start Super Vdsm Traceback (most recent call last): File "/usr/share/vdsm/supervdsmServer", line 297, in main server = manager.get_server() File "/usr/lib64/python2.7/multiprocessing/managers.py", line 493, in get_server self._authkey, self._serializer) File "/usr/lib64/python2.7/multiprocessing/managers.py", line 162, in __init__ self.listener = Listener(address=address, backlog=16) File "/usr/lib64/python2.7/multiprocessing/connection.py", line 136, in __init__ self._listener = SocketListener(address, family, backlog) File "/usr/lib64/python2.7/multiprocessing/connection.py", line 260, in __init__ self._socket.bind(address) File "/usr/lib64/python2.7/socket.py", line 224, in meth return getattr(self._sock,name)(*args) error: [Errno 2] No such file or directory
On Thu, Dec 22, 2016 at 7:54 PM, Barak Korren <bkorren@redhat.com> wrote:
It hard to tell currently when did this start b/c we had so package issues that made the tests fail before reaching that point most of the day.
Since we currently have an issue in Lago with collecting AddHost logs (Hopefully we'll resolve this in the next release early next week), I`ve ran the tests locally and attached the bundle of generated logs to this message.
Included in the attached file are engine logs, host-deploy logs and VDSM logs for both test hosts.
From a quick look inside it seems the issue is with VDSM failing to start.
From host-deploy/ovirt-host-deploy-20161222124209-192.168.203.4-604a4799.log:
2016-12-22 12:42:05 DEBUG otopi.plugins.otopi.services.systemd plugin.executeRaw:813 execute: ('/bin/systemctl', 'start', 'vdsmd.service'), executable='None', cwd='None', env=None 2016-12-22 12:42:09 DEBUG otopi.plugins.otopi.services.systemd plugin.executeRaw:863 execute-result: ('/bin/systemctl', 'start', 'vdsmd.service'), rc=1 2016-12-22 12:42:09 DEBUG otopi.plugins.otopi.services.systemd plugin.execute:921 execute-output: ('/bin/systemctl', 'start', 'vdsmd.service') stdout:
2016-12-22 12:42:09 DEBUG otopi.plugins.otopi.services.systemd plugin.execute:926 execute-output: ('/bin/systemctl', 'start', 'vdsmd.service') stderr: A dependency job for vdsmd.service failed. See 'journalctl -xe' for details.
This means that one of the services vdsm depends on could not start.
2016-12-22 12:42:09 DEBUG otopi.context context._executeMethod:142 method exception Traceback (most recent call last): File "/tmp/ovirt-bUCuRxXXzU/pythonlib/otopi/context.py", line 132, in _executeMethod method['method']() File "/tmp/ovirt-bUCuRxXXzU/otopi-plugins/ovirt-host-deploy/vdsm/packages.py", line 209, in _start self.services.state('vdsmd', True) File "/tmp/ovirt-bUCuRxXXzU/otopi-plugins/otopi/services/systemd.py", line 141, in state service=name, RuntimeError: Failed to start service 'vdsmd'
This error is not very useful for anyone. What we need in otopi log is the output of journalctl -xe (suggested by systemctl).
Didi, can we collect this info when starting a service fail?
Barak, can you log in to the host with this error and collect the output?
By the time I looged in to the host, all IP addresses are gone (I'm guessing the setup process killed dhclient), so I'm having to work via the serial console)
1: lo: <LOOPBACK,UP,LOWER_UP> mtu 65536 qdisc noqueue state UNKNOWN link/loopback 00:00:00:00:00:00 brd 00:00:00:00:00:00 inet 127.0.0.1/8 scope host lo valid_lft forever preferred_lft forever inet6 ::1/128 scope host valid_lft forever preferred_lft forever 2: eth0: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc pfifo_fast state UP qlen 1000 link/ether 54:52:c0:a8:cb:02 brd ff:ff:ff:ff:ff:ff inet6 fe80::5652:c0ff:fea8:cb02/64 scope link valid_lft forever preferred_lft forever 3: eth1: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc pfifo_fast state UP qlen 1000 link/ether 54:52:c0:a8:cc:02 brd ff:ff:ff:ff:ff:ff inet6 fe80::5652:c0ff:fea8:cc02/64 scope link valid_lft forever preferred_lft forever 4: eth2: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc pfifo_fast state UP qlen 1000 link/ether 54:52:c0:a8:cc:03 brd ff:ff:ff:ff:ff:ff inet6 fe80::5652:c0ff:fea8:cc03/64 scope link valid_lft forever preferred_lft forever 5: eth3: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc pfifo_fast state UP qlen 1000 link/ether 54:52:c0:a8:ca:02 brd ff:ff:ff:ff:ff:ff inet6 fe80::5652:c0ff:fea8:ca02/64 scope link valid_lft forever preferred_lft forever
Here is the interesting stuff I can gather from journalctl:
Dec 22 12:42:06 lago-basic-suite-master-host0 ovirt-imageio-daemon[5007]: Traceback (most recent call last): Dec 22 12:42:06 lago-basic-suite-master-host0 ovirt-imageio-daemon[5007]: File "/usr/bin/ovirt-imageio-daemon", line 14, in <module> Dec 22 12:42:06 lago-basic-suite-master-host0 ovirt-imageio-daemon[5007]: server.main(sys.argv) Dec 22 12:42:06 lago-basic-suite-master-host0 ovirt-imageio-daemon[5007]: File "/usr/lib/python2.7/site-packages/ovirt_imageio_daemon/server.py", line 51, in main Dec 22 12:42:06 lago-basic-suite-master-host0 ovirt-imageio-daemon[5007]: configure_logger() Dec 22 12:42:06 lago-basic-suite-master-host0 ovirt-imageio-daemon[5007]: File "/usr/lib/python2.7/site-packages/ovirt_imageio_daemon/server.py", line 69, in configure_logger Dec 22 12:42:06 lago-basic-suite-master-host0 ovirt-imageio-daemon[5007]: logging.config.fileConfig(conf, disable_existing_loggers=False) Dec 22 12:42:06 lago-basic-suite-master-host0 ovirt-imageio-daemon[5007]: File "/usr/lib64/python2.7/logging/config.py", line 78, in fileConfig Dec 22 12:42:06 lago-basic-suite-master-host0 iscsid[5043]: iSCSI daemon with pid=5044 started! Dec 22 12:42:06 lago-basic-suite-master-host0 ovirt-imageio-daemon[5007]: handlers = _install_handlers(cp, formatters) Dec 22 12:42:06 lago-basic-suite-master-host0 ovirt-imageio-daemon[5007]: File "/usr/lib64/python2.7/logging/config.py", line 156, in _install_handlers Dec 22 12:42:06 lago-basic-suite-master-host0 ovirt-imageio-daemon[5007]: h = klass(*args) Dec 22 12:42:06 lago-basic-suite-master-host0 ovirt-imageio-daemon[5007]: File "/usr/lib64/python2.7/logging/handlers.py", line 117, in __init__ Dec 22 12:42:06 lago-basic-suite-master-host0 ovirt-imageio-daemon[5007]: BaseRotatingHandler.__init__(self, filename, mode, encoding, delay) Dec 22 12:42:06 lago-basic-suite-master-host0 ovirt-imageio-daemon[5007]: File "/usr/lib64/python2.7/logging/handlers.py", line 64, in __init__ Dec 22 12:42:06 lago-basic-suite-master-host0 ovirt-imageio-daemon[5007]: logging.FileHandler.__init__(self, filename, mode, encoding, delay) Dec 22 12:42:06 lago-basic-suite-master-host0 ovirt-imageio-daemon[5007]: File "/usr/lib64/python2.7/logging/__init__.py", line 902, in __init__ Dec 22 12:42:06 lago-basic-suite-master-host0 ovirt-imageio-daemon[5007]: StreamHandler.__init__(self, self._open()) Dec 22 12:42:06 lago-basic-suite-master-host0 ovirt-imageio-daemon[5007]: File "/usr/lib64/python2.7/logging/__init__.py", line 925, in _open Dec 22 12:42:06 lago-basic-suite-master-host0 ovirt-imageio-daemon[5007]: stream = open(self.baseFilename, self.mode) Dec 22 12:42:06 lago-basic-suite-master-host0 ovirt-imageio-daemon[5007]: IOError: [Errno 13] Permission denied: '/var/log/ovirt-imageio-daemon/daemon.log'
This smells like https://bugzilla.redhat.com/1401901 Can you share the output of: ls -ld /var/log/ovirt-imageio-daemon ls -l /var/log/ovirt-imageio-daemon/
Dec 22 12:42:06 lago-basic-suite-master-host0 systemd[1]: ovirt-imageio-daemon.service: main process exited, code=exited, status=1/FAILURE Dec 22 12:42:06 lago-basic-suite-master-host0 systemd[1]: Failed to start oVirt ImageIO Daemon. -- Subject: Unit ovirt-imageio-daemon.service has failed -- Defined-By: systemd -- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel -- -- Unit ovirt-imageio-daemon.service has failed. -- -- The result is failed. Dec 22 12:42:06 lago-basic-suite-master-host0 systemd[1]: Unit ovirt-imageio-daemon.service entered failed state. Dec 22 12:42:06 lago-basic-suite-master-host0 systemd[1]: ovirt-imageio-daemon.service failed. Dec 22 12:42:06 lago-basic-suite-master-host0 systemd[1]: supervdsmd.service: main process exited, code=exited, status=1/FAILURE Dec 22 12:42:06 lago-basic-suite-master-host0 systemd[1]: Unit supervdsmd.service entered failed state. Dec 22 12:42:06 lago-basic-suite-master-host0 systemd[1]: supervdsmd.service failed. Dec 22 12:42:07 lago-basic-suite-master-host0 systemd[1]: Started Virtualization daemon. -- Subject: Unit libvirtd.service has finished start-up -- Defined-By: systemd -- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel -- -- Unit libvirtd.service has finished starting up. -- -- The start-up result is done. Dec 22 12:42:07 lago-basic-suite-master-host0 systemd[1]: ovirt-imageio-daemon.service holdoff time over, scheduling restart. Dec 22 12:42:07 lago-basic-suite-master-host0 systemd[1]: supervdsmd.service holdoff time over, scheduling restart. Dec 22 12:42:07 lago-basic-suite-master-host0 systemd[1]: Starting oVirt ImageIO Daemon... -- Subject: Unit ovirt-imageio-daemon.service has begun start-up -- Defined-By: systemd -- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel -- -- Unit ovirt-imageio-daemon.service has begun starting up. Dec 22 12:42:07 lago-basic-suite-master-host0 systemd[1]: Started Auxiliary vdsm service for running helper functions as root. -- Subject: Unit supervdsmd.service has finished start-up -- Defined-By: systemd -- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel -- -- Unit supervdsmd.service has finished starting up. -- -- The start-up result is done. Dec 22 12:42:07 lago-basic-suite-master-host0 systemd[1]: Starting Auxiliary vdsm service for running helper functions as root... -- Subject: Unit supervdsmd.service has begun start-up -- Defined-By: systemd -- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel -- -- Unit supervdsmd.service has begun starting up. Dec 22 12:42:07 lago-basic-suite-master-host0 systemd[1]: Starting Virtual Desktop Server Manager network restoration... -- Subject: Unit vdsm-network.service has begun start-up -- Defined-By: systemd -- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel -- -- Unit vdsm-network.service has begun starting up. Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5082]: Traceback (most recent call last): Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5082]: File "/usr/bin/ovirt-imageio-daemon", line 14, in <module> Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5082]: server.main(sys.argv) Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5082]: File "/usr/lib/python2.7/site-packages/ovirt_imageio_daemon/server.py", line 51, in main Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5082]: configure_logger() Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5082]: File "/usr/lib/python2.7/site-packages/ovirt_imageio_daemon/server.py", line 69, in configure_logger Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5082]: logging.config.fileConfig(conf, disable_existing_loggers=False) Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5082]: File "/usr/lib64/python2.7/logging/config.py", line 78, in fileConfig Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5082]: handlers = _install_handlers(cp, formatters) Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5082]: File "/usr/lib64/python2.7/logging/config.py", line 156, in _install_handlers Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5082]: h = klass(*args) Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5082]: File "/usr/lib64/python2.7/logging/handlers.py", line 117, in __init__ Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5082]: BaseRotatingHandler.__init__(self, filename, mode, encoding, delay) Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5082]: File "/usr/lib64/python2.7/logging/handlers.py", line 64, in __init__ Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5082]: logging.FileHandler.__init__(self, filename, mode, encoding, delay) Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5082]: File "/usr/lib64/python2.7/logging/__init__.py", line 902, in __init__ Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5082]: StreamHandler.__init__(self, self._open()) Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5082]: File "/usr/lib64/python2.7/logging/__init__.py", line 925, in _open Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5082]: stream = open(self.baseFilename, self.mode) Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5082]: IOError: [Errno 13] Permission denied: '/var/log/ovirt-imageio-daemon/daemon.log' Dec 22 12:42:07 lago-basic-suite-master-host0 systemd[1]: ovirt-imageio-daemon.service: main process exited, code=exited, status=1/FAILURE Dec 22 12:42:07 lago-basic-suite-master-host0 systemd[1]: Failed to start oVirt ImageIO Daemon. -- Subject: Unit ovirt-imageio-daemon.service has failed -- Defined-By: systemd -- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel -- -- Unit ovirt-imageio-daemon.service has failed. -- -- The result is failed. Dec 22 12:42:07 lago-basic-suite-master-host0 systemd[1]: Unit ovirt-imageio-daemon.service entered failed state. Dec 22 12:42:07 lago-basic-suite-master-host0 systemd[1]: ovirt-imageio-daemon.service failed. Dec 22 12:42:07 lago-basic-suite-master-host0 systemd[1]: supervdsmd.service: main process exited, code=exited, status=1/FAILURE Dec 22 12:42:07 lago-basic-suite-master-host0 systemd[1]: Unit supervdsmd.service entered failed state. Dec 22 12:42:07 lago-basic-suite-master-host0 systemd[1]: supervdsmd.service failed. Dec 22 12:42:07 lago-basic-suite-master-host0 systemd[1]: ovirt-imageio-daemon.service holdoff time over, scheduling restart. Dec 22 12:42:07 lago-basic-suite-master-host0 systemd[1]: supervdsmd.service holdoff time over, scheduling restart. Dec 22 12:42:07 lago-basic-suite-master-host0 systemd[1]: Started Auxiliary vdsm service for running helper functions as root. -- Subject: Unit supervdsmd.service has finished start-up -- Defined-By: systemd -- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel -- -- Unit supervdsmd.service has finished starting up. -- -- The start-up result is done. Dec 22 12:42:07 lago-basic-suite-master-host0 systemd[1]: Starting Auxiliary vdsm service for running helper functions as root... -- Subject: Unit supervdsmd.service has begun start-up -- Defined-By: systemd -- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel -- -- Unit supervdsmd.service has begun starting up. Dec 22 12:42:07 lago-basic-suite-master-host0 systemd[1]: Starting oVirt ImageIO Daemon... -- Subject: Unit ovirt-imageio-daemon.service has begun start-up -- Defined-By: systemd -- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel -- -- Unit ovirt-imageio-daemon.service has begun starting up. Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5110]: Traceback (most recent call last): Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5110]: File "/usr/bin/ovirt-imageio-daemon", line 14, in <module> Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5110]: server.main(sys.argv) Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5110]: File "/usr/lib/python2.7/site-packages/ovirt_imageio_daemon/server.py", line 51, in main Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5110]: configure_logger() Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5110]: File "/usr/lib/python2.7/site-packages/ovirt_imageio_daemon/server.py", line 69, in configure_logger Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5110]: logging.config.fileConfig(conf, disable_existing_loggers=False) Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5110]: File "/usr/lib64/python2.7/logging/config.py", line 78, in fileConfig Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5110]: handlers = _install_handlers(cp, formatters) Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5110]: File "/usr/lib64/python2.7/logging/config.py", line 156, in _install_handlers Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5110]: h = klass(*args) Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5110]: File "/usr/lib64/python2.7/logging/handlers.py", line 117, in __init__ Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5110]: BaseRotatingHandler.__init__(self, filename, mode, encoding, delay) Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5110]: File "/usr/lib64/python2.7/logging/handlers.py", line 64, in __init__ Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5110]: logging.FileHandler.__init__(self, filename, mode, encoding, delay) Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5110]: File "/usr/lib64/python2.7/logging/__init__.py", line 902, in __init__ Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5110]: StreamHandler.__init__(self, self._open()) Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5110]: File "/usr/lib64/python2.7/logging/__init__.py", line 925, in _open Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5110]: stream = open(self.baseFilename, self.mode) Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5110]: IOError: [Errno 13] Permission denied: '/var/log/ovirt-imageio-daemon/daemon.log' Dec 22 12:42:07 lago-basic-suite-master-host0 systemd[1]: ovirt-imageio-daemon.service: main process exited, code=exited, status=1/FAILURE Dec 22 12:42:07 lago-basic-suite-master-host0 systemd[1]: Failed to start oVirt ImageIO Daemon. -- Subject: Unit ovirt-imageio-daemon.service has failed -- Defined-By: systemd -- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel -- -- Unit ovirt-imageio-daemon.service has failed. -- -- The result is failed. Dec 22 12:42:07 lago-basic-suite-master-host0 systemd[1]: Unit ovirt-imageio-daemon.service entered failed state. Dec 22 12:42:07 lago-basic-suite-master-host0 systemd[1]: ovirt-imageio-daemon.service failed. Dec 22 12:42:07 lago-basic-suite-master-host0 systemd[1]: supervdsmd.service: main process exited, code=exited, status=1/FAILURE Dec 22 12:42:07 lago-basic-suite-master-host0 systemd[1]: Unit supervdsmd.service entered failed state. Dec 22 12:42:07 lago-basic-suite-master-host0 systemd[1]: supervdsmd.service failed. Dec 22 12:42:07 lago-basic-suite-master-host0 systemd[1]: ovirt-imageio-daemon.service holdoff time over, scheduling restart. Dec 22 12:42:07 lago-basic-suite-master-host0 systemd[1]: Starting oVirt ImageIO Daemon... -- Subject: Unit ovirt-imageio-daemon.service has begun start-up -- Defined-By: systemd -- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel -- -- Unit ovirt-imageio-daemon.service has begun starting up. Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5125]: Traceback (most recent call last): Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5125]: File "/usr/bin/ovirt-imageio-daemon", line 14, in <module> Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5125]: server.main(sys.argv) Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5125]: File "/usr/lib/python2.7/site-packages/ovirt_imageio_daemon/server.py", line 51, in main Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5125]: configure_logger() Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5125]: File "/usr/lib/python2.7/site-packages/ovirt_imageio_daemon/server.py", line 69, in configure_logger Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5125]: logging.config.fileConfig(conf, disable_existing_loggers=False) Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5125]: File "/usr/lib64/python2.7/logging/config.py", line 78, in fileConfig Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5125]: handlers = _install_handlers(cp, formatters) Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5125]: File "/usr/lib64/python2.7/logging/config.py", line 156, in _install_handlers Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5125]: h = klass(*args) Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5125]: File "/usr/lib64/python2.7/logging/handlers.py", line 117, in __init__ Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5125]: BaseRotatingHandler.__init__(self, filename, mode, encoding, delay) Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5125]: File "/usr/lib64/python2.7/logging/handlers.py", line 64, in __init__ Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5125]: logging.FileHandler.__init__(self, filename, mode, encoding, delay) Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5125]: File "/usr/lib64/python2.7/logging/__init__.py", line 902, in __init__ Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5125]: StreamHandler.__init__(self, self._open()) Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5125]: File "/usr/lib64/python2.7/logging/__init__.py", line 925, in _open Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5125]: stream = open(self.baseFilename, self.mode) Dec 22 12:42:07 lago-basic-suite-master-host0 ovirt-imageio-daemon[5125]: IOError: [Errno 13] Permission denied: '/var/log/ovirt-imageio-daemon/daemon.log' Dec 22 12:42:07 lago-basic-suite-master-host0 systemd[1]: ovirt-imageio-daemon.service: main process exited, code=exited, status=1/FAILURE Dec 22 12:42:07 lago-basic-suite-master-host0 systemd[1]: Failed to start oVirt ImageIO Daemon. -- Subject: Unit ovirt-imageio-daemon.service has failed -- Defined-By: systemd -- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel -- -- Unit ovirt-imageio-daemon.service has failed. -- -- The result is failed. Dec 22 12:42:07 lago-basic-suite-master-host0 systemd[1]: Unit ovirt-imageio-daemon.service entered failed state. Dec 22 12:42:07 lago-basic-suite-master-host0 systemd[1]: ovirt-imageio-daemon.service failed. Dec 22 12:42:08 lago-basic-suite-master-host0 systemd[1]: ovirt-imageio-daemon.service holdoff time over, scheduling restart. Dec 22 12:42:08 lago-basic-suite-master-host0 systemd[1]: supervdsmd.service holdoff time over, scheduling restart. Dec 22 12:42:08 lago-basic-suite-master-host0 systemd[1]: Started Auxiliary vdsm service for running helper functions as root. -- Subject: Unit supervdsmd.service has finished start-up -- Defined-By: systemd -- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel -- -- Unit supervdsmd.service has finished starting up. -- -- The start-up result is done. Dec 22 12:42:08 lago-basic-suite-master-host0 systemd[1]: Starting Auxiliary vdsm service for running helper functions as root... -- Subject: Unit supervdsmd.service has begun start-up -- Defined-By: systemd -- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel -- -- Unit supervdsmd.service has begun starting up. Dec 22 12:42:08 lago-basic-suite-master-host0 systemd[1]: Starting oVirt ImageIO Daemon... -- Subject: Unit ovirt-imageio-daemon.service has begun start-up -- Defined-By: systemd -- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel -- -- Unit ovirt-imageio-daemon.service has begun starting up. Dec 22 12:42:08 lago-basic-suite-master-host0 systemd[1]: ovirt-imageio-daemon.service: main process exited, code=exited, status=1/FAILURE Dec 22 12:42:08 lago-basic-suite-master-host0 systemd[1]: Failed to start oVirt ImageIO Daemon. -- Subject: Unit ovirt-imageio-daemon.service has failed -- Defined-By: systemd -- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel -- -- Unit ovirt-imageio-daemon.service has failed. -- -- The result is failed.
... snip ... keeps repeating ....
Dec 22 12:42:09 lago-basic-suite-master-host0 systemd[1]: start request repeated too quickly for supervdsmd.service Dec 22 12:42:09 lago-basic-suite-master-host0 systemd[1]: Failed to start Auxiliary vdsm service for running helper functions as root. -- Subject: Unit supervdsmd.service has failed -- Defined-By: systemd -- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel -- -- Unit supervdsmd.service has failed. -- -- The result is failed. Dec 22 12:42:09 lago-basic-suite-master-host0 systemd[1]: Dependency failed for Virtual Desktop Server Manager. -- Subject: Unit vdsmd.service has failed -- Defined-By: systemd -- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel -- -- Unit vdsmd.service has failed. -- -- The result is dependency. Dec 22 12:42:09 lago-basic-suite-master-host0 systemd[1]: Dependency failed for MOM instance configured for VDSM purposes. -- Subject: Unit mom-vdsm.service has failed -- Defined-By: systemd -- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel -- -- Unit mom-vdsm.service has failed. -- -- The result is dependency. Dec 22 12:42:09 lago-basic-suite-master-host0 systemd[1]: Job mom-vdsm.service/start failed with result 'dependency'. Dec 22 12:42:09 lago-basic-suite-master-host0 systemd[1]: Job vdsmd.service/start failed with result 'dependency'. Dec 22 12:42:09 lago-basic-suite-master-host0 systemd[1]: Unit supervdsmd.service entered failed state. Dec 22 12:42:09 lago-basic-suite-master-host0 systemd[1]: supervdsmd.service failed.
... snip ... unrelated stuff ....
Dec 22 12:42:11 lago-basic-suite-master-host0 vdsm-tool[5175]: Traceback (most recent call last): Dec 22 12:42:11 lago-basic-suite-master-host0 vdsm-tool[5175]: File "/usr/share/vdsm/vdsm-restore-net-config", line 482, in <module> Dec 22 12:42:11 lago-basic-suite-master-host0 vdsm-tool[5175]: restore(args) Dec 22 12:42:11 lago-basic-suite-master-host0 vdsm-tool[5175]: File "/usr/share/vdsm/vdsm-restore-net-config", line 455, in restore Dec 22 12:42:11 lago-basic-suite-master-host0 vdsm-tool[5175]: touch_file(NETS_RESTORED_MARK) Dec 22 12:42:11 lago-basic-suite-master-host0 vdsm-tool[5175]: File "/usr/share/vdsm/vdsm-restore-net-config", line 431, in touch_file Dec 22 12:42:11 lago-basic-suite-master-host0 vdsm-tool[5175]: with open(file_path, 'a'): Dec 22 12:42:11 lago-basic-suite-master-host0 vdsm-tool[5175]: IOError: [Errno 2] No such file or directory: '/var/run/vdsm/nets_restored' Dec 22 12:42:11 lago-basic-suite-master-host0 vdsm-tool[5175]: Traceback (most recent call last): Dec 22 12:42:11 lago-basic-suite-master-host0 vdsm-tool[5175]: File "/usr/bin/vdsm-tool", line 219, in main Dec 22 12:42:11 lago-basic-suite-master-host0 vdsm-tool[5175]: return tool_command[cmd]["command"](*args) Dec 22 12:42:11 lago-basic-suite-master-host0 vdsm-tool[5175]: File "/usr/lib/python2.7/site-packages/vdsm/tool/restore_nets.py", line 41, in restore_command Dec 22 12:42:11 lago-basic-suite-master-host0 vdsm-tool[5175]: exec_restore(cmd) Dec 22 12:42:11 lago-basic-suite-master-host0 vdsm-tool[5175]: File "/usr/lib/python2.7/site-packages/vdsm/tool/restore_nets.py", line 54, in exec_restore Dec 22 12:42:11 lago-basic-suite-master-host0 vdsm-tool[5175]: raise EnvironmentError('Failed to restore the persisted networks') Dec 22 12:42:11 lago-basic-suite-master-host0 vdsm-tool[5175]: EnvironmentError: Failed to restore the persisted networks Dec 22 12:42:11 lago-basic-suite-master-host0 systemd[1]: vdsm-network.service: main process exited, code=exited, status=1/FAILURE Dec 22 12:42:11 lago-basic-suite-master-host0 systemd[1]: Failed to start Virtual Desktop Server Manager network restoration. -- Subject: Unit vdsm-network.service has failed -- Defined-By: systemd -- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel -- -- Unit vdsm-network.service has failed. -- -- The result is failed. Dec 22 12:42:11 lago-basic-suite-master-host0 systemd[1]: Unit vdsm-network.service entered failed state. Dec 22 12:42:11 lago-basic-suite-master-host0 systemd[1]: vdsm-network.service failed.
HTH, Barak.
-- Barak Korren bkorren@redhat.com RHCE, RHCi, RHV-DevOps Team https://ifireball.wordpress.com/
On 23 December 2016 at 20:25, Nir Soffer <nsoffer@redhat.com> wrote:
This smells like https://bugzilla.redhat.com/1401901
Can you share the output of:
ls -ld /var/log/ovirt-imageio-daemon
drwxr-xr-x. 2 root root 4096 Dec 21 08:45 /var/log/ovirt-imageio-daemon
ls -l /var/log/ovirt-imageio-daemon/
total 0 HTH, -- Barak Korren bkorren@redhat.com RHCE, RHCi, RHV-DevOps Team https://ifireball.wordpress.com/
On Fri, Dec 23, 2016 at 8:59 PM, Barak Korren <bkorren@redhat.com> wrote:
On 23 December 2016 at 20:25, Nir Soffer <nsoffer@redhat.com> wrote:
This smells like https://bugzilla.redhat.com/1401901
Can you share the output of:
ls -ld /var/log/ovirt-imageio-daemon
drwxr-xr-x. 2 root root 4096 Dec 21 08:45 /var/log/ovirt-imageio-daemon
ls -l /var/log/ovirt-imageio-daemon/
total 0
Thanks, so this is 1401901. I'm testing a fix. Nir
On Fri, Dec 23, 2016 at 9:32 PM, Nir Soffer <nsoffer@redhat.com> wrote:
On Fri, Dec 23, 2016 at 8:59 PM, Barak Korren <bkorren@redhat.com> wrote:
On 23 December 2016 at 20:25, Nir Soffer <nsoffer@redhat.com> wrote:
This smells like https://bugzilla.redhat.com/1401901
Can you share the output of:
ls -ld /var/log/ovirt-imageio-daemon
drwxr-xr-x. 2 root root 4096 Dec 21 08:45 /var/log/ovirt-imageio-daemon
ls -l /var/log/ovirt-imageio-daemon/
total 0
Thanks, so this is 1401901.
I'm testing a fix.
The fix seems to work, do you want to review or test it? https://gerrit.ovirt.org/69052 Nir
On 23 December 2016 at 21:43, Nir Soffer <nsoffer@redhat.com> wrote:
The fix seems to work, do you want to review or test it? https://gerrit.ovirt.org/69052
Fix merged, and looking at hosts it seems to do what it was supposed to: # ls -ld /var/log/ovirt-imageio-daemon/ drwxr-xr-x. 2 vdsm kvm 4096 Dec 25 07:45 /var/log/ovirt-imageio-daemon/ But now we have a new failure, SuperVDSM not starting with this in the logs: MainThread::DEBUG::2016-12-25 07:45:36,018::supervdsmServer::275::SuperVdsm.Server::(main) Making sure I'm root - SuperVdsm MainThread::DEBUG::2016-12-25 07:45:36,018::supervdsmServer::284::SuperVdsm.Server::(main) Parsing cmd args MainThread::DEBUG::2016-12-25 07:45:36,018::supervdsmServer::287::SuperVdsm.Server::(main) Cleaning old socket /var/run/vdsm/svdsm.sock MainThread::DEBUG::2016-12-25 07:45:36,018::supervdsmServer::291::SuperVdsm.Server::(main) Setting up keep alive thread MainThread::DEBUG::2016-12-25 07:45:36,018::supervdsmServer::297::SuperVdsm.Server::(main) Creating remote object manager MainThread::ERROR::2016-12-25 07:45:36,018::supervdsmServer::321::SuperVdsm.Server::(main) Could not start Super Vdsm Traceback (most recent call last): File "/usr/share/vdsm/supervdsmServer", line 301, in main server = anager.get_server() File "/usr/lib64/python2.7/multiprocessing/managers.py", line 493, in get_server self._authkey, self._serializer) File "/usr/lib64/python2.7/multiprocessing/managers.py", line 162, in __init__ self.listener = Listener(address=address, backlog=16) File "/usr/lib64/python2.7/multiprocessing/connection.py", line 136, in __init__ self._listener = SocketListener(address, family, backlog) File "/usr/lib64/python2.7/multiprocessing/connection.py", line 260, in __init__ self._socket.bind(address) File "/usr/lib64/python2.7/socket.py", line 224, in meth return getattr(self._sock,name)(*args) error: [Errno 2] No such file or directory MainThread::DEBUG::2016-12-25 07:45:36,338::supervdsmServer::275::SuperVdsm.Server::(main) Making sure I'm root - SuperVdsm ... Repeat ... -- Barak Korren bkorren@redhat.com RHCE, RHCi, RHV-DevOps Team https://ifireball.wordpress.com/
On Sun, Dec 25, 2016 at 3:01 PM, Barak Korren <bkorren@redhat.com> wrote:
On 23 December 2016 at 21:43, Nir Soffer <nsoffer@redhat.com> wrote:
The fix seems to work, do you want to review or test it? https://gerrit.ovirt.org/69052
Fix merged, and looking at hosts it seems to do what it was supposed to:
# ls -ld /var/log/ovirt-imageio-daemon/ drwxr-xr-x. 2 vdsm kvm 4096 Dec 25 07:45 /var/log/ovirt-imageio-daemon/
But now we have a new failure, SuperVDSM not starting with this in the logs:
MainThread::DEBUG::2016-12-25 07:45:36,018::supervdsmServer::275::SuperVdsm.Server::(main) Making sure I'm root - SuperVdsm MainThread::DEBUG::2016-12-25 07:45:36,018::supervdsmServer::284::SuperVdsm.Server::(main) Parsing cmd args MainThread::DEBUG::2016-12-25 07:45:36,018::supervdsmServer::287::SuperVdsm.Server::(main) Cleaning old socket /var/run/vdsm/svdsm.sock MainThread::DEBUG::2016-12-25 07:45:36,018::supervdsmServer::291::SuperVdsm.Server::(main) Setting up keep alive thread MainThread::DEBUG::2016-12-25 07:45:36,018::supervdsmServer::297::SuperVdsm.Server::(main) Creating remote object manager MainThread::ERROR::2016-12-25 07:45:36,018::supervdsmServer::321::SuperVdsm.Server::(main) Could not start Super Vdsm Traceback (most recent call last): File "/usr/share/vdsm/supervdsmServer", line 301, in main server = anager.get_server() File "/usr/lib64/python2.7/multiprocessing/managers.py", line 493, in get_server self._authkey, self._serializer) File "/usr/lib64/python2.7/multiprocessing/managers.py", line 162, in __init__ self.listener = Listener(address=address, backlog=16) File "/usr/lib64/python2.7/multiprocessing/connection.py", line 136, in __init__ self._listener = SocketListener(address, family, backlog) File "/usr/lib64/python2.7/multiprocessing/connection.py", line 260, in __init__ self._socket.bind(address) File "/usr/lib64/python2.7/socket.py", line 224, in meth return getattr(self._sock,name)(*args) error: [Errno 2] No such file or directory MainThread::DEBUG::2016-12-25 07:45:36,338::supervdsmServer::275::SuperVdsm.Server::(main) Making sure I'm root - SuperVdsm
Can you tell if /var/run/vdsm/svdsm.sock exists? What's `ls -lZ /var/run/vdsm` ? Can you manually run supervdsmServer --sockfile=/var/run/vdsm/svdsm.sock on that host?
Can you tell if /var/run/vdsm/svdsm.sock exists?
# ls -l /var/run/vdsm/svdsm.sock ls: cannot access /var/run/vdsm/svdsm.sock: No such file or directory
What's `ls -lZ /var/run/vdsm` ?
# ls -lZ /var/run/vdsm ls: cannot access /var/run/vdsm: No such file or directory
Can you manually run supervdsmServer --sockfile=/var/run/vdsm/svdsm.sock on that host?
I get this: [2016-12-25 08:39:01,224 pyinotify ERROR] add_watch: cannot watch /var/run/vdsm/sourceRoutes WD=-1, Errno=Not a directory (ENOTDIR) Exception in thread sourceRoute: Traceback (most recent call last): File "/usr/lib64/python2.7/threading.py", line 811, in __bootstrap_inner self.run() File "/usr/lib64/python2.7/threading.py", line 764, in run self.__target(*self.__args, **self.__kwargs) File "/usr/lib/python2.7/site-packages/vdsm/utils.py", line 368, in wrapper return f(*a, **kw) File "/usr/lib/python2.7/site-packages/vdsm/network/sourceroutethread.py", line 90, in _subscribeToInotifyLoop for filePath in sorted(os.listdir(SOURCE_ROUTES_FOLDER)): OSError: [Errno 20] Not a directory: '/var/run/vdsm/sourceRoutes' -- Barak Korren bkorren@redhat.com RHCE, RHCi, RHV-DevOps Team https://ifireball.wordpress.com/
On Sun, Dec 25, 2016 at 3:40 PM, Barak Korren <bkorren@redhat.com> wrote:
Can you tell if /var/run/vdsm/svdsm.sock exists?
# ls -l /var/run/vdsm/svdsm.sock ls: cannot access /var/run/vdsm/svdsm.sock: No such file or directory
What's `ls -lZ /var/run/vdsm` ?
# ls -lZ /var/run/vdsm ls: cannot access /var/run/vdsm: No such file or directory
Can you manually run supervdsmServer --sockfile=/var/run/vdsm/svdsm.sock on that host?
I get this:
[2016-12-25 08:39:01,224 pyinotify ERROR] add_watch: cannot watch /var/run/vdsm/sourceRoutes WD=-1, Errno=Not a directory (ENOTDIR) Exception in thread sourceRoute: Traceback (most recent call last): File "/usr/lib64/python2.7/threading.py", line 811, in __bootstrap_inner self.run() File "/usr/lib64/python2.7/threading.py", line 764, in run self.__target(*self.__args, **self.__kwargs) File "/usr/lib/python2.7/site-packages/vdsm/utils.py", line 368, in wrapper return f(*a, **kw) File "/usr/lib/python2.7/site-packages/vdsm/network/sourceroutethread.py", line 90, in _subscribeToInotifyLoop for filePath in sorted(os.listdir(SOURCE_ROUTES_FOLDER)): OSError: [Errno 20] Not a directory: '/var/run/vdsm/sourceRoutes'
Now that's completely my fault. I probably did not verify https://gerrit.ovirt.org/#/c/68662/ on a clean installation. Barak, do you know if there's a standard way of triggering systemd-tmpfiles in %post ? https://gerrit.ovirt.org/#/c/69092/ would revert my offending patch.
On Sun, Dec 25, 2016 at 3:59 PM, Dan Kenigsberg <danken@redhat.com> wrote:
On Sun, Dec 25, 2016 at 3:40 PM, Barak Korren <bkorren@redhat.com> wrote:
Can you tell if /var/run/vdsm/svdsm.sock exists?
# ls -l /var/run/vdsm/svdsm.sock ls: cannot access /var/run/vdsm/svdsm.sock: No such file or directory
What's `ls -lZ /var/run/vdsm` ?
# ls -lZ /var/run/vdsm ls: cannot access /var/run/vdsm: No such file or directory
Can you manually run supervdsmServer --sockfile=/var/run/vdsm/svdsm.sock on that host?
I get this:
[2016-12-25 08:39:01,224 pyinotify ERROR] add_watch: cannot watch /var/run/vdsm/sourceRoutes WD=-1, Errno=Not a directory (ENOTDIR) Exception in thread sourceRoute: Traceback (most recent call last): File "/usr/lib64/python2.7/threading.py", line 811, in __bootstrap_inner self.run() File "/usr/lib64/python2.7/threading.py", line 764, in run self.__target(*self.__args, **self.__kwargs) File "/usr/lib/python2.7/site-packages/vdsm/utils.py", line 368, in wrapper return f(*a, **kw) File "/usr/lib/python2.7/site-packages/vdsm/network/sourceroutethread.py", line 90, in _subscribeToInotifyLoop for filePath in sorted(os.listdir(SOURCE_ROUTES_FOLDER)): OSError: [Errno 20] Not a directory: '/var/run/vdsm/sourceRoutes'
Now that's completely my fault.
I probably did not verify https://gerrit.ovirt.org/#/c/68662/ on a clean installation.
Barak, do you know if there's a standard way of triggering systemd-tmpfiles in %post ?
https://gerrit.ovirt.org/#/c/69092/ would revert my offending patch.
But https://gerrit.ovirt.org/#/c/69093/1/vdsm.spec.in may be a proper fix. Would you care to review?
Why do we need to wait for a review and not revert the offending patch in the meantime? On Sun, Dec 25, 2016 at 4:26 PM, Dan Kenigsberg <danken@redhat.com> wrote:
On Sun, Dec 25, 2016 at 3:40 PM, Barak Korren <bkorren@redhat.com> wrote:
Can you tell if /var/run/vdsm/svdsm.sock exists?
# ls -l /var/run/vdsm/svdsm.sock ls: cannot access /var/run/vdsm/svdsm.sock: No such file or directory
What's `ls -lZ /var/run/vdsm` ?
# ls -lZ /var/run/vdsm ls: cannot access /var/run/vdsm: No such file or directory
Can you manually run supervdsmServer --sockfile=/var/run/vdsm/ svdsm.sock on that host?
I get this:
[2016-12-25 08:39:01,224 pyinotify ERROR] add_watch: cannot watch /var/run/vdsm/sourceRoutes WD=-1, Errno=Not a directory (ENOTDIR) Exception in thread sourceRoute: Traceback (most recent call last): File "/usr/lib64/python2.7/threading.py", line 811, in __bootstrap_inner self.run() File "/usr/lib64/python2.7/threading.py", line 764, in run self.__target(*self.__args, **self.__kwargs) File "/usr/lib/python2.7/site-packages/vdsm/utils.py", line 368, in wrapper return f(*a, **kw) File "/usr/lib/python2.7/site-packages/vdsm/network/
On Sun, Dec 25, 2016 at 3:59 PM, Dan Kenigsberg <danken@redhat.com> wrote: sourceroutethread.py",
line 90, in _subscribeToInotifyLoop for filePath in sorted(os.listdir(SOURCE_ROUTES_FOLDER)): OSError: [Errno 20] Not a directory: '/var/run/vdsm/sourceRoutes'
Now that's completely my fault.
I probably did not verify https://gerrit.ovirt.org/#/c/68662/ on a clean installation.
Barak, do you know if there's a standard way of triggering systemd-tmpfiles in %post ?
https://gerrit.ovirt.org/#/c/69092/ would revert my offending patch.
But https://gerrit.ovirt.org/#/c/69093/1/vdsm.spec.in may be a proper fix. Would you care to review? _______________________________________________ Devel mailing list Devel@ovirt.org http://lists.ovirt.org/mailman/listinfo/devel
-- Eyal Edri Associate Manager RHV DevOps EMEA ENG Virtualization R&D Red Hat Israel phone: +972-9-7692018 irc: eedri (on #tlv #rhev-dev #rhev-integ)
On Sun, Dec 25, 2016 at 4:53 PM, Eyal Edri <eedri@redhat.com> wrote:
Why do we need to wait for a review and not revert the offending patch in the meantime?
I want to verify that a revert helps. but I'm getting 14:41:29 > git -c core.askpass=true fetch --tags --progress git://gerrit.ovirt.org/vdsm.git refs/changes/93/69093/1 --prune 14:41:29 ERROR: Error fetching remote repo 'origin' 14:41:29 hudson.plugins.git.GitException: Failed to fetch from git://gerrit.ovirt.org/vdsm.git review of a forward-looking fix can be done in parallel.
participants (5)
-
Barak Korren -
Dan Kenigsberg -
Eyal Edri -
Fred Rolland -
Nir Soffer