[ovirt-devel] Re: engine-setup failing on restarting ovirt-imageio

On pondělí 27. dubna 2020 16:47:56 CEST Nir Soffer wrote: > On Mon, Apr 27, 2020 at 5:37 PM Sandro Bonazzola <sbonazzo(a)redhat.com&gt; wrote: > > Il giorno lun 27 apr 2020 alle ore 16:28 Nir Soffer < nsoffer(a)redhat.com&gt; ha scritto: > >> On Mon, Apr 27, 2020 at 5:22 PM Vojtech Juranek <vjuranek(a)redhat.com&gt; wrote: > >> > On pondělí 27. dubna 2020 16:10:11 CEST Nir Soffer wrote: > >> > > On Mon, Apr 27, 2020 at 5:01 PM Liran Rotenberg < lrotenbe(a)redhat.com&gt; wrote: > >> > > > On Mon, Apr 27, 2020 at 4:58 PM Sandro Bonazzola > >> > > > <sbonazzo(a)redhat.com&gt; > >> > > > > >> > > > wrote: > >> > > >> Il giorno lun 27 apr 2020 alle ore 15:52 Nir Soffer > >> > > >> <nsoffer(a)redhat.com&gt; > >> > > >> > >> > > >> ha scritto: > >> > > >>> On Mon, Apr 27, 2020 at 4:42 PM Sandro Bonazzola > >> > > >>> <sbonazzo(a)redhat.com&gt; > >> > > >>> > >> > > >>> wrote: > >> > > >>>> Failing job is > >> > > >>>> https://jenkins.ovirt.org/job/ovirt-system-tests_manual/6794/ > >> > > >>>> > >> > > >>>> Here's the relevant log in engine-setup: > >> > > >>>> > >> > > >>>> > >> > > >>>> 2020-04-27 09:25:35,457-0400 DEBUG > >> > > >>>> otopi.plugins.otopi.services.systemd > >> > > >>>> plugin.executeRaw:813 execute: ('/usr/bin/systemctl', 'stop', > >> > > >>>> 'ovirt-imageio.service'), executable='None', cwd='None', > >> > > >>>> env=None > >> > > >>>> 2020-04-27 09:25:35,652-0400 DEBUG > >> > > >>>> otopi.plugins.otopi.services.systemd plugin.executeRaw:863 > >> > > >>>> execute-result: ('/usr/bin/systemctl', 'stop', > >> > > >>>> 'ovirt-imageio.service'), rc=0 2020-04-27 09:25:35,653-0400 > >> > > >>>> DEBUG > >> > > >>>> otopi.plugins.otopi.services.systemd plugin.execute:921 > >> > > >>>> execute-output: ('/usr/bin/systemctl', 'stop', > >> > > >>>> 'ovirt-imageio.service') stdout: > >> > > >>>> > >> > > >>>> > >> > > >>>> 2020-04-27 09:25:35,653-0400 DEBUG > >> > > >>>> otopi.plugins.otopi.services.systemd > >> > > >>>> plugin.execute:926 execute-output: ('/usr/bin/systemctl', > >> > > >>>> 'stop', > >> > > >>>> 'ovirt-imageio.service') stderr: > >> > > >>>> > >> > > >>>> > >> > > >>>> 2020-04-27 09:25:35,653-0400 DEBUG > >> > > >>>> otopi.plugins.otopi.services.systemd > >> > > >>>> systemd.state:170 starting service ovirt-imageio 2020-04-27 > >> > > >>>> 09:25:35,654-0400 DEBUG otopi.plugins.otopi.services.systemd > >> > > >>>> plugin.executeRaw:813 execute: ('/usr/bin/systemctl', 'start', > >> > > >>>> 'ovirt-imageio.service'), executable='None', cwd='None', > >> > > >>>> env=None > >> > > >>>> 2020-04-27 09:25:36,631-0400 DEBUG > >> > > >>>> otopi.plugins.otopi.services.systemd plugin.executeRaw:863 > >> > > >>>> execute-result: ('/usr/bin/systemctl', 'start', > >> > > >>>> 'ovirt-imageio.service'), rc=1 2020-04-27 09:25:36,632-0400 > >> > > >>>> DEBUG > >> > > >>>> otopi.plugins.otopi.services.systemd plugin.execute:921 > >> > > >>>> execute-output: ('/usr/bin/systemctl', 'start', > >> > > >>>> 'ovirt-imageio.service') stdout: > >> > > >>>> > >> > > >>>> > >> > > >>>> 2020-04-27 09:25:36,632-0400 DEBUG > >> > > >>>> otopi.plugins.otopi.services.systemd > >> > > >>>> plugin.execute:926 execute-output: ('/usr/bin/systemctl', > >> > > >>>> 'start', > >> > > >>>> 'ovirt-imageio.service') stderr: Job for ovirt-imageio.service > >> > > >>>> failed > >> > > >>>> because the control process exited with error code. See > >> > > >>>> "systemctl > >> > > >>>> status ovirt-imageio.service" and "journalctl -xe" for details. > >> > > >>>> > >> > > >>>> 2020-04-27 09:25:36,633-0400 DEBUG otopi.context > >> > > >>>> context._executeMethod:145 method exception>>>> > >> > > >>>> > >> > > >>>> Traceback (most recent call last): > >> > > >>>> File "/usr/lib/python3.6/site-packages/otopi/context.py", line > >> > > >>>> 132, > >> > > >>>> in _executeMethod>>>> > >> > > >>>> > >> > > >>>> method['method']() > >> > > >>>> > >> > > >>>> File > >> > > >>>> "/usr/share/ovirt-engine/setup/bin/../plugins/ovirt-engine-set > >> > > >>>> up/ovi > >> > > >>>> rt_imageio/config.py", line 190, in > >> > > >>>> _closeup_resatrt_service>>>> > >> > > >>>> > >> > > >>>> state=state, > >> > > >>>> > >> > > >>>> File "/usr/share/otopi/plugins/otopi/services/systemd.py", > >> > > >>>> line 181, > >> > > >>>> in state>>>> > >> > > >>>> > >> > > >>>> service=name, > >> > > >>>> > >> > > >>>> RuntimeError: Failed to start service 'ovirt-imageio' > >> > > >>>> 2020-04-27 09:25:36,636-0400 ERROR otopi.context > >> > > >>>> context._executeMethod:154 Failed to execute stage 'Closing up': > >> > > >>>> Failed to start service 'ovirt-imageio'>>> > >> > > >>> > >> > > >>> Looking at the logs at: > >> > > >>> > >> > > >>> https://jenkins.ovirt.org/job/ovirt-system-tests_manual/6794/arti > >> > > >>> fact/ex > >> > > >>> ported-artifacts/test_logs/basic-suite-master/post-001_initialize > >> > > >>> _engine > >> > > >>> _ pytest.py/lago-basic-suite-master-engine/_var_log/ovirt-imageio/ > >> > > >>> daemon. > >> > > >>> log > >> > > >>> > >> > > >>> 2020-04-27 09:25:39,887 INFO (MainThread) [server] Starting > >> > > >>> (pid=17137, version=2.0.5) 2020-04-27 09:25:39,944 ERROR > >> > > >>> (MainThread) > >> > > >>> [server] Server failed>>> > >> > > >>> > >> > > >>> Traceback (most recent call last): > >> > > >>> File > >> > > >>> "/usr/lib64/python3.6/site-packages/ovirt_imageio/server.py", > >> > > >>> line 37, in main>>> > >> > > >>> > >> > > >>> server = Server(cfg) > >> > > >>> > >> > > >>> File > >> > > >>> "/usr/lib64/python3.6/site-packages/ovirt_imageio/server.py", > >> > > >>> line 76, in __init__>>> > >> > > >>> > >> > > >>> self.remote_service = services.RemoteService(self.config, > >> > > >>> self.auth) > >> > > >>> > >> > > >>> File > >> > > >>> "/usr/lib64/python3.6/site-packages/ovirt_imageio/services.py" > >> > > >>> , > >> > > >>> line 80, in __init__>>> > >> > > >>> > >> > > >>> self._secure_server() > >> > > >>> > >> > > >>> File > >> > > >>> "/usr/lib64/python3.6/site-packages/ovirt_imageio/services.py" > >> > > >>> , > >> > > >>> line 95, in _secure_server>>> > >> > > >>> > >> > > >>> raise errors.TlsConfigurationError(*required_config) > >> > > >>> > >> > > >>> ovirt_imageio.errors.TlsConfigurationError: TLS enabled (see > >> > > >>> [tls] > >> > > >>> section in daemon.conf), but not configured: ca_file = , > >> > > >>> cert_file = , > >> > > >>> key_file = > >> > > >>> > >> > > >>> This means engine-setup did not create correct configuration > >> > > >>> file. > >> > > >>> > >> > > >>> Looking in > >> > > >>> https://jenkins.ovirt.org/job/ovirt-system-tests_manual/6794/ > >> > > >>> I don't see /etc/ovirt-imageio directory, maybe the collections > >> > > >>> scripts > >> > > >>> need update? > >> > > >>> > >> > > >>> This works in real setup, so I guess this is another OST > >> > > >>> environment > >> > > >>> issue. > >> > > >> > >> > > >> looking at dnf logs: > >> > > >> https://jenkins.ovirt.org/job/ovirt-system-tests_manual/6794/artif > >> > > >> act/exp > >> > > >> orted-artifacts/test_logs/basic-suite-master/post-001_initialize_e > >> > > >> ngine_p > >> > > >> ytest.py/lago-basic-suite-master-engine/_var_log/dnf.rpm.log > >> > > >> > >> > > >> 2020-04-27T13:16:13Z SUBDEBUG Installed: > >> > > >> ovirt-imageio-common-2.0.5-0.202004260154.gitaf86468.el8.x86_64 > >> > > >> 2020-04-27T13:16:13Z SUBDEBUG Installed: > >> > > >> ovirt-imageio-common-2.0.5-0.202004260154.gitaf86468.el8.x86_64 > >> > > >> 2020-04-27T13:16:13Z SUBDEBUG Installed: > >> > > >> ovirt-imageio-daemon-2.0.5-0.202004260154.gitaf86468.el8.x86_64 > >> > > >> 2020-04-27T13:16:14Z SUBDEBUG Installed: > >> > > >> ovirt-imageio-daemon-2.0.5-0.202004260154.gitaf86468.el8.x86_64 > >> > > >> 2020-04-27T13:16:14Z INFO warning: group Development/Debug does > >> > > >> not > >> > > >> exist - using root > >> > > >> > >> > > >> seems like it's getting a recent enough version. What about above > >> > > >> warning? > >> > > > > >> > > > I had this problem in my local environment. I was running > >> > > > engine-setup > >> > > > with an unprivileged user. > >> > > > >> > > For make install-dev? > >> > > > >> > > I think this was fixed here: > >> > > > >> > > commit 81a5e757fd8768ace825140ca7dc701cc2e011ce > >> > > Author: Vojtech Juranek <vjuranek(a)redhat.com&gt; > >> > > Date: Thu Apr 23 11:44:41 2020 +0200 > >> > > > >> > > spec: allow imageio config in dev env > >> > > > >> > > Add $PREFIX into imageio config directory to allow imageio > >> > > configuration > >> > > > >> > > in development environment when config files are installed into a > >> > > specified > >> > > directory. > >> > > > >> > > Currently it fails with: > >> > > [Errno 13] Permission denied: '/etc/ovirt-imageio' > >> > > > >> > > Change-Id: I9e13bba0e97f681b0b07d5a135be76113e391ddc > >> > > Signed-off-by: Vojtech Juranek <vjuranek(a)redhat.com&gt; > >> > > > >> > > Maybe this OST runs old engine without this fix? > >> > > >> > OST runs in install-dev environment? IIRC not. > >> > > >> > Looking into the logs, imageio wasn't properly configured, it seems there's no certificate configuration: > >> > ovirt_imageio.errors.TlsConfigurationError: TLS enabled (see [tls] > >> > section in daemon.conf), but not configured: ca_file = , cert_file > >> > = , key_file =>> > > >> > (from > >> > https://jenkins.ovirt.org/job/ovirt-system-tests_manual/6794/artifact/ > >> > exported-artifacts/test_logs/basic-suite-master/post-001_initialize_eng > >> > ine_pytest.py/lago-basic-suite-master-engine/_var_log/ovirt-imageio/dae > >> > mon.log) > >> > > >> > and as Nir wrote, /etc/ovirt-imageio is not archived > >> > > >> > looking into otopi log > >> > ( https://jenkins.ovirt.org/job/ovirt-system-tests_manual/6794/artifact > >> > /exported-artifacts/test_logs/basic-suite-master/post-001_initialize_en > >> > gine_pytest.py/lago-basic-suite-master-engine/_var_log/ovirt-engine/set > >> > up/ovirt-engine-setup-20200427091928-9e7d0z.log) it looks like the > >> > config ws installed into /usr/etc/ovirt-imageio instead of into > >> > /usr/etc>> > >> Maybe PREFIX was /usr when generating the rpms? > >> > >> This is the trouble with code that does not have automated tests. This > >> means endless > >> time spent on manual debugging. > >> > >> (so far no idea why, also I guess we need to throw clear exception if > > > >> the config file is not found): > > Looking at Makefile: > > IMAGEIO_SYSCONF_DIR=$(PREFIX)/etc/ovirt-imageio > > > > and this make sense to resolve to /usr/etc/ovirt-imageio. > > > > should have been: > > IMAGEIO_SYSCONF_DIR=$(SYSCONF_DIR)/ovirt-imageio > > > > In spec file: > > PREFIX=%{_prefix} > > and rpm resolves: > > $ rpm --eval "%{_prefix}" > > /usr > > > > so this couldn't have worked before at all. > > Looks like the patch adding $PREFIX was not tested with real setup, > only with development setup. yes, and actually I haven't finished testing it even in dev setup yet > Vojta, do you want to test a fix? I'll, but need to look more into it, replacing $(PREFIX) with $(SYSCONF_DIR) doesn't seem to work as SYSCONF_DIR=$(PREFIX)/etc (see https://github.com/ oVirt/ovirt-engine/blob/master/Makefile#L41 <https://github.com/oVirt/ovirt-engine/blob/master/Makefile#L41>), so we will end up again with / usr/etc. We will probably have to do it as VMCONSOLE_* variable - hardcode config file and define new just install-dev environment (and do the proper testing before merge)