action #17664

Whitespace in auth module config causes webui to fail to start

Added by ktsamis almost 3 years ago. Updated almost 3 years ago.

Status:ResolvedStart date:10/03/2017
Priority:NormalDue date:
Assignee:oholecek% Done:

100%

Category:Concrete Bugs
Target version:Milestone 6
Difficulty:
Duration:

Description

Changed in /etc/openqa/openqa.ini:

[auth]
method = Fake

restart the openqa-webui service and I get:

503 error on webui. I see the following errors in the logs and the service fails to start.

Service:

e251:~ # systemctl status openqa-webui -l
● openqa-webui.service - The openQA web UI
   Loaded: loaded (/usr/lib/systemd/system/openqa-webui.service; enabled; vendor preset: disabled)
   Active: failed (Result: exit-code) since Fri 2017-03-10 14:56:41 CET; 11min ago
  Process: 2964 ExecStart=/usr/share/openqa/script/openqa prefork -m production --proxy -i 100 -H 400 -w 10 -a 100 -G 1000 -r 20 (code=exited, status=255)
 Main PID: 2964 (code=exited, status=255)

Mar 10 14:56:41 e251 openqa[2964]: Undefined subroutine &OpenQA::WebAPI::auth_config called at /usr/lib/perl5/vendor_perl/5.18.2/Mojo/Server.pm line 17.
Mar 10 14:56:41 e251 openqa[2964]: Mojolicious::AUTOLOAD('HASH(0x80043d8)') called at /usr/share/openqa/script/../lib/OpenQA/WebAPI.pm line 156
Mar 10 14:56:41 e251 openqa[2964]: OpenQA::WebAPI::startup('OpenQA::WebAPI=HASH(0x1a35988)') called at /usr/lib/perl5/vendor_perl/5.18.2/Mojolicious.pm line 179
Mar 10 14:56:41 e251 openqa[2964]: Mojolicious::new('OpenQA::WebAPI') called at /usr/lib/perl5/vendor_perl/5.18.2/Mojo/Server.pm line 17
Mar 10 14:56:41 e251 openqa[2964]: Mojo::Server::build_app('Mojo::Server=HASH(0x192af38)', 'OpenQA::WebAPI') called at /usr/lib/perl5/vendor_perl/5.18.2/Mojolicious/Commands.pm line 71
Mar 10 14:56:41 e251 openqa[2964]: Mojolicious::Commands::start_app('Mojolicious::Commands', 'OpenQA::WebAPI') called at /usr/share/openqa/script/../lib/OpenQA/WebAPI.pm line 501
Mar 10 14:56:41 e251 openqa[2964]: OpenQA::WebAPI::run() called at /usr/share/openqa/script/openqa line 35
Mar 10 14:56:41 e251 systemd[1]: openqa-webui.service: Main process exited, code=exited, status=255/n/a
Mar 10 14:56:41 e251 systemd[1]: openqa-webui.service: Unit entered failed state.
Mar 10 14:56:41 e251 systemd[1]: openqa-webui.service: Failed with result 'exit-code'.

logs:


2017-03-10T14:56:40.967877+01:00 e251 systemd[1]: Stopped The openQA web UI.
2017-03-10T14:56:40.985467+01:00 e251 systemd[1]: Started The openQA web UI.
2017-03-10T14:56:41.704731+01:00 e251 kernel: [  379.611924] audit: type=1400 audit(1489154201.700:47): apparmor="DENIED" operation="exec" profile="/usr/share/openqa/script/openqa" name="/usr/bin/unzip-plain" pid=2973 comm="openqa" requested_mask="x" denied_mask="x" fsuid=480 ouid=0
2017-03-10T14:56:41.933945+01:00 e251 openqa[2964]: Use of inherited AUTOLOAD for non-method OpenQA::WebAPI::auth_config() is
2017-03-10T14:56:41.934165+01:00 e251 openqa[2964]: deprecated at /usr/share/openqa/script/../lib/OpenQA/WebAPI.pm line 156 (#1)
2017-03-10T14:56:41.934277+01:00 e251 openqa[2964]: (D deprecated) As an (ahem) accidental feature, AUTOLOAD
2017-03-10T14:56:41.934381+01:00 e251 openqa[2964]: subroutines are looked up as methods (using the @ISA hierarchy)
2017-03-10T14:56:41.934480+01:00 e251 openqa[2964]: even when the subroutines to be autoloaded were called as plain
2017-03-10T14:56:41.934577+01:00 e251 openqa[2964]: functions (e.g. Foo::bar()), not as methods (e.g. Foo->bar() or
2017-03-10T14:56:41.934680+01:00 e251 openqa[2964]: $obj->bar()).
2017-03-10T14:56:41.934779+01:00 e251 openqa[2964]: This bug will be rectified in future by using method lookup only for
2017-03-10T14:56:41.934878+01:00 e251 openqa[2964]: methods' AUTOLOADs.  However, there is a significant base of existing
2017-03-10T14:56:41.934975+01:00 e251 openqa[2964]: code that may be using the old behavior.  So, as an interim step, Perl
2017-03-10T14:56:41.935071+01:00 e251 openqa[2964]: currently issues an optional warning when non-methods use inherited
2017-03-10T14:56:41.935167+01:00 e251 openqa[2964]: AUTOLOADs.
2017-03-10T14:56:41.935264+01:00 e251 openqa[2964]: The simple rule is:  Inheritance will not work when autoloading
2017-03-10T14:56:41.935361+01:00 e251 openqa[2964]: non-methods.  The simple fix for old code is:  In any module that used
2017-03-10T14:56:41.935459+01:00 e251 openqa[2964]: to depend on inheriting AUTOLOAD for non-methods from a base class
2017-03-10T14:56:41.935556+01:00 e251 openqa[2964]: named BaseClass, execute *AUTOLOAD = \&BaseClass::AUTOLOAD during
2017-03-10T14:56:41.935651+01:00 e251 openqa[2964]: startup.
2017-03-10T14:56:41.935750+01:00 e251 openqa[2964]: In code that currently says use AutoLoader; @ISA = qw(AutoLoader);
2017-03-10T14:56:41.935847+01:00 e251 openqa[2964]: you should remove AutoLoader from @ISA and change use AutoLoader; to
2017-03-10T14:56:41.935943+01:00 e251 openqa[2964]: use AutoLoader 'AUTOLOAD';.
2017-03-10T14:56:41.936096+01:00 e251 openqa[2964]: Undefined subroutine &OpenQA::WebAPI::auth_config called at
2017-03-10T14:56:41.936208+01:00 e251 openqa[2964]: /usr/lib/perl5/vendor_perl/5.18.2/Mojo/Server.pm line 17 (#2)
2017-03-10T14:56:41.936317+01:00 e251 openqa[2964]: (F) The subroutine indicated hasn't been defined, or if it was, it has
2017-03-10T14:56:41.936428+01:00 e251 openqa[2964]: since been undefined.
2017-03-10T14:56:41.936541+01:00 e251 openqa[2964]: Uncaught exception from user code:
2017-03-10T14:56:41.936656+01:00 e251 openqa[2964]: Undefined subroutine &OpenQA::WebAPI::auth_config called at /usr/lib/perl5/vendor_perl/5.18.2/Mojo/Server.pm line 17.
2017-03-10T14:56:41.936816+01:00 e251 openqa[2964]: Mojolicious::AUTOLOAD('HASH(0x80043d8)') called at /usr/share/openqa/script/../lib/OpenQA/WebAPI.pm line 156
2017-03-10T14:56:41.936930+01:00 e251 openqa[2964]: OpenQA::WebAPI::startup('OpenQA::WebAPI=HASH(0x1a35988)') called at /usr/lib/perl5/vendor_perl/5.18.2/Mojolicious.pm line 179
2017-03-10T14:56:41.937042+01:00 e251 openqa[2964]: Mojolicious::new('OpenQA::WebAPI') called at /usr/lib/perl5/vendor_perl/5.18.2/Mojo/Server.pm line 17
2017-03-10T14:56:41.937157+01:00 e251 openqa[2964]: Mojo::Server::build_app('Mojo::Server=HASH(0x192af38)', 'OpenQA::WebAPI') called at /usr/lib/perl5/vendor_perl/5.18.2/Mojolicious/Commands.pm line 71
2017-03-10T14:56:41.937268+01:00 e251 openqa[2964]: Mojolicious::Commands::start_app('Mojolicious::Commands', 'OpenQA::WebAPI') called at /usr/share/openqa/script/../lib/OpenQA/WebAPI.pm line 501
2017-03-10T14:56:41.937377+01:00 e251 openqa[2964]: OpenQA::WebAPI::run() called at /usr/share/openqa/script/openqa line 35
2017-03-10T14:56:41.952612+01:00 e251 systemd[1]: openqa-webui.service: Main process exited, code=exited, status=255/n/a
2017-03-10T14:56:41.953335+01:00 e251 systemd[1]: openqa-webui.service: Unit entered failed state.
2017-03-10T14:56:41.953501+01:00 e251 systemd[1]: openqa-webui.service: Failed with result 'exit-code'.

If I have OpenID in auth, I see the webui but can't authenticate/login because of action #17652. I get 500 from the microfocus openID. So I basically can't login in my instance. Retrying doesn't work.
openQA-4.4.1488895973.56121a4-103.1.noarch

Let me know if you need any logs.

History

#1 Updated by ktsamis almost 3 years ago

Since the first failure, I can't start the service again, I rebooted and nothing. It's dead. Not just the webui but the scheduler and all. I can't use it at all now. Not even with auth = OpenID. The service doesn't start at all. I can't even edit the Category of this issue, since it looks like a concrete bug.

#2 Updated by oholecek almost 3 years ago

I will need more details - journal log for scheduler and webui. Scheduler doesn't even need auth plugin.
Can you verify your installation is correct? So far I'm unable to reproduce the problem. Btw. this part of code wasn't touched last few months, maybe some conflicting update? Also there seems to be an apparmor issue (seems unrelated, but for a test try to temporarily disable it).

#3 Updated by ktsamis almost 3 years ago

I am using SLE12-SP2, fully updated and openqa fully updated.

e251:/var/log # journalctl -u openqa-scheduler.service
-- Logs begin at Fri 2017-03-10 15:14:07 CET, end at Fri 2017-03-10 15:48:25 CET. --
Mar 10 15:14:08 linux-x5uj systemd[1]: Starting The openQA Scheduler...
Mar 10 15:14:09 linux-x5uj openqa-scheduler[998]: Archive::Extract will be removed from the Perl core distribution in the next major release. Please install it from CPAN. It is being used at /usr/share/openqa/sc
Mar 10 15:14:09 linux-x5uj systemd[1]: Started The openQA Scheduler.
Mar 10 15:14:09 linux-x5uj openqa-scheduler[998]: [Fri Mar 10 15:14:09 2017] [scheduler:debug] Scheduler started
Mar 10 15:20:11 e251 systemd[1]: Stopping The openQA Scheduler...
Mar 10 15:20:11 e251 systemd[1]: Stopped The openQA Scheduler.
Mar 10 15:20:11 e251 systemd[1]: Starting The openQA Scheduler...
Mar 10 15:20:12 e251 systemd[1]: Started The openQA Scheduler.
Mar 10 15:20:12 e251 openqa-scheduler[2822]: [Fri Mar 10 15:20:12 2017] [scheduler:debug] Scheduler started
Mar 10 15:21:28 e251 systemd[1]: Stopping The openQA Scheduler...
Mar 10 15:21:28 e251 systemd[1]: Stopped The openQA Scheduler.
Mar 10 15:21:28 e251 systemd[1]: Starting The openQA Scheduler...
Mar 10 15:21:29 e251 openqa-scheduler[3008]: Archive::Extract will be removed from the Perl core distribution in the next major release. Please install it from CPAN. It is being used at /usr/share/openqa/script/
Mar 10 15:21:29 e251 systemd[1]: Started The openQA Scheduler.
Mar 10 15:21:29 e251 openqa-scheduler[3008]: [Fri Mar 10 15:21:29 2017] [scheduler:debug] Scheduler started

The last lines (since the last service restart) of webui log:

journalctl -u openqa-webui.service

Mar 10 15:21:28 e251 systemd[1]: Stopped The openQA web UI.
Mar 10 15:21:30 e251 systemd[1]: Started The openQA web UI.
Mar 10 15:21:31 e251 openqa[3016]: Archive::Extract will be removed from the Perl core distribution in the next major release. Please install it from CPAN. It is being used at /usr/share/openqa/script/../lib/Ope
Mar 10 15:21:31 e251 openqa[3016]: Use of inherited AUTOLOAD for non-method OpenQA::WebAPI::auth_config() is
Mar 10 15:21:31 e251 openqa[3016]: deprecated at /usr/share/openqa/script/../lib/OpenQA/WebAPI.pm line 156 (#1)
Mar 10 15:21:31 e251 openqa[3016]: (D deprecated) As an (ahem) accidental feature, AUTOLOAD
Mar 10 15:21:31 e251 openqa[3016]: subroutines are looked up as methods (using the @ISA hierarchy)
Mar 10 15:21:31 e251 openqa[3016]: even when the subroutines to be autoloaded were called as plain
Mar 10 15:21:31 e251 openqa[3016]: functions (e.g. Foo::bar()), not as methods (e.g. Foo->bar() or
Mar 10 15:21:31 e251 openqa[3016]: $obj->bar()).
Mar 10 15:21:31 e251 openqa[3016]: This bug will be rectified in future by using method lookup only for
Mar 10 15:21:31 e251 openqa[3016]: methods' AUTOLOADs.  However, there is a significant base of existing
Mar 10 15:21:31 e251 openqa[3016]: code that may be using the old behavior.  So, as an interim step, Perl
Mar 10 15:21:31 e251 openqa[3016]: currently issues an optional warning when non-methods use inherited
Mar 10 15:21:31 e251 openqa[3016]: AUTOLOADs.
Mar 10 15:21:31 e251 openqa[3016]: The simple rule is:  Inheritance will not work when autoloading
Mar 10 15:21:31 e251 openqa[3016]: non-methods.  The simple fix for old code is:  In any module that used
Mar 10 15:21:31 e251 openqa[3016]: to depend on inheriting AUTOLOAD for non-methods from a base class
Mar 10 15:21:31 e251 openqa[3016]: named BaseClass, execute *AUTOLOAD = \&BaseClass::AUTOLOAD during
Mar 10 15:21:31 e251 openqa[3016]: startup.
Mar 10 15:21:31 e251 openqa[3016]: In code that currently says use AutoLoader; @ISA = qw(AutoLoader);
Mar 10 15:21:31 e251 openqa[3016]: you should remove AutoLoader from @ISA and change use AutoLoader; to
Mar 10 15:21:31 e251 openqa[3016]: use AutoLoader 'AUTOLOAD';.
Mar 10 15:21:31 e251 openqa[3016]: Undefined subroutine &OpenQA::WebAPI::auth_config called at
Mar 10 15:21:31 e251 openqa[3016]: /usr/lib/perl5/vendor_perl/5.18.2/Mojo/Server.pm line 17 (#2)
Mar 10 15:21:31 e251 openqa[3016]: (F) The subroutine indicated hasn't been defined, or if it was, it has
Mar 10 15:21:31 e251 openqa[3016]: since been undefined.
Mar 10 15:21:31 e251 openqa[3016]: Uncaught exception from user code:
Mar 10 15:21:31 e251 openqa[3016]: Undefined subroutine &OpenQA::WebAPI::auth_config called at /usr/lib/perl5/vendor_perl/5.18.2/Mojo/Server.pm line 17.
Mar 10 15:21:31 e251 openqa[3016]: Mojolicious::AUTOLOAD('HASH(0x7971eb8)') called at /usr/share/openqa/script/../lib/OpenQA/WebAPI.pm line 156
Mar 10 15:21:31 e251 openqa[3016]: OpenQA::WebAPI::startup('OpenQA::WebAPI=HASH(0x1376988)') called at /usr/lib/perl5/vendor_perl/5.18.2/Mojolicious.pm line 179
Mar 10 15:21:31 e251 openqa[3016]: Mojolicious::new('OpenQA::WebAPI') called at /usr/lib/perl5/vendor_perl/5.18.2/Mojo/Server.pm line 17
Mar 10 15:21:31 e251 openqa[3016]: Mojo::Server::build_app('Mojo::Server=HASH(0x126bf38)', 'OpenQA::WebAPI') called at /usr/lib/perl5/vendor_perl/5.18.2/Mojolicious/Commands.pm line 71
Mar 10 15:21:31 e251 openqa[3016]: Mojolicious::Commands::start_app('Mojolicious::Commands', 'OpenQA::WebAPI') called at /usr/share/openqa/script/../lib/OpenQA/WebAPI.pm line 501
Mar 10 15:21:31 e251 openqa[3016]: OpenQA::WebAPI::run() called at /usr/share/openqa/script/openqa line 35
Mar 10 15:21:31 e251 systemd[1]: openqa-webui.service: Main process exited, code=exited, status=255/n/a
Mar 10 15:21:31 e251 systemd[1]: openqa-webui.service: Unit entered failed state.
Mar 10 15:21:31 e251 systemd[1]: openqa-webui.service: Failed with result 'exit-code'.
Mar 10 15:34:01 e251 systemd[1]: Stopped The openQA web UI.

I disabled apparmor and tried to restart, same result.

Available packages to be installed:

e251:/var/log # zypper dup
Warning: You are about to do a distribution upgrade with all enabled repositories. Make sure these repositories are compatible before you continue. See 'man zypper' for more information about this command.
Loading repository data...
Reading installed packages...
Computing distribution upgrade...

The following 6 NEW packages are going to be installed:
  bdftopcf gstreamer-plugins-cogl libtidyp-1_04-0 perl-HTML-Tidy sles-release-POOL twm

The following 5 packages are going to be upgraded:
  libsgutils2-2 sg3_utils xf86-video-qxl xorg-x11-server xorg-x11-server-extra

The following 5 packages are not supported by their vendor:
  bdftopcf gstreamer-plugins-cogl libtidyp-1_04-0 perl-HTML-Tidy twm

5 packages to upgrade, 6 new.
Overall download size: 3.9 MiB. Already cached: 0 B. After the operation, additional 696.8 KiB will be used.
Continue? [y/n/? shows all options] (y): n

Should I update them and try again? zypper patch does not show the perl package. This is a new installation, of both the server and openQA.

#4 Updated by oholecek almost 3 years ago

  • Category changed from 130 to Concrete Bugs

To verify if installation is correct you can use rpm -qV openQA. Any suspicious log entries in journal itself? Is the error message same in case of openID authentication? This seems like damaged /usr/share/openqa/lib/OpenQA/WebAPI/Auth/Fake.pm.

#5 Updated by ktsamis almost 3 years ago

e251:/var/log # rpm -qV openQA
.......T.  c /etc/apache2/vhosts.d/openqa-common.inc
S.5....T.  c /etc/openqa/openqa.ini

The first file was a try on an option to see if it fixed it and reverting the change. The file is the original.
I don't see anything in journal that would be suspicious or even relevant.
Should I reinstall and see what happens?

#6 Updated by oholecek almost 3 years ago

Hmm.. just patched out auth_config from my OpenID.pm and got very similar error and interestingly rpm -qV didn't notice a change. Please try to reinstall and/or provide the copy of your /usr/share/openqa/lib/OpenQA/WebAPI/Auth/Fake.pm. You can use paste.opensuse.org for it, for example.

#7 Updated by ktsamis almost 3 years ago

/usr/share/openqa/lib/OpenQA/WebAPI/Auth/Fake.pm:
http://paste.opensuse.org/49969109

I will reinstall openQA and let you know the results.

#8 Updated by ktsamis almost 3 years ago

So I reinstalled the openQA and openQA-worker packages and interestingly enough the configuration files were not overwritten. So I still have the old ones (modified from before) and I still get the same errors. What should I try next?
zypper log and service status:
http://paste.opensuse.org/56577025

#9 Updated by okurz almost 3 years ago

  • Category changed from Concrete Bugs to Support
  • Status changed from New to Feedback
  • Assignee set to okurz

ktsamis wrote:

What should I try next?

I suggest you install openQA on a clean SLES12SP2 and see if it works there. openSUSE Leap 42.2 is a more common setup so there might be something we miss here which is special to your environment.

#10 Updated by ktsamis almost 3 years ago

I tried to install again on SLE12-SP2 and it failed again, with the same error, same setup, everything. I deliberately did not update SLE packages, only the latest openqa. So it doesn't look like a package conflict unless it's something fundamentally wrong. You can reproduce the bug, if you follow these instructions: https://pes.suse.de/QA_Maintenance/Deployment_of_openQA/

The step that it failed, is the login with OpenID is not working (anymore?) so I change /etc/openqa/openqa.ini into:

[auth]
method = Fake

restart openqa and apache2 and I get the above errors. So this seems like a bug.

#11 Updated by ktsamis almost 3 years ago

I will install a new VM with Leap and set up openQA there. If you need access to the old SLE ones, I can give you access to debug what's going on there. If not, let me know to destroy them. btw any idea what's going on with OpenID? I saw action #17652 has been filed but it still does not work for me. I will try with Leap and comment in that action ticket if it still does not work.

#12 Updated by oholecek almost 3 years ago

I would appreciate access to the machine. I'm curios what's going on there.

#13 Updated by oholecek almost 3 years ago

  • Subject changed from 503 with auth = Fake to Whitespace in auth module config causes webui to fail to start
  • Category changed from Support to Concrete Bugs
  • Status changed from Feedback to In Progress
  • Assignee changed from okurz to oholecek

There is a bug or special behaviour in Config::IniFiles. There was a whitespace character after 'Fake' which was causing this. I'll fix the plugin loading.

#14 Updated by oholecek almost 3 years ago

  • % Done changed from 0 to 90

#15 Updated by oholecek almost 3 years ago

  • Status changed from In Progress to Resolved
  • % Done changed from 90 to 100

#16 Updated by oholecek almost 3 years ago

  • Target version set to Milestone 6

Also available in: Atom PDF