QA » openQA Project

There are really no errors in the lgos. However, normally the livehandler is expected to log errors in case of unhandled exceptions (leading to 500 errors). From when were the 500 responses according to Apache? Does the log of the livehandler go far enough so these errors would even be visible (right now it starts at Apr 17, so it goes 13 days into the past).

Yes - they were from around 2024-04-25 (the integer at the output from influxdb that I included in the ticket where this was copied from is a unix based timestamp, if you remove enough digits on the right).

I just simulated this locally by putting a die "foo" somewhere in the code and an error was definitely logged:

script/openqa-livehandler daemon -m production
[2024-04-30 16:59:19.34722] [29935] [warn] Deprecated use of config key '[audit]: blacklist'. Use '[audit]: blocklist' instead
[info] Listening at "http://127.0.0.1:9528"
Web application available at http://127.0.0.1:9528
[info] Listening at "http://[::1]:9528"
Web application available at http://[::1]:9528
[debug] attempt to open ws proxy for job opensuse-Tumbleweed-DVD-x86_64-Build20240322-wireguard_client@64bit (4266) where URL to os-autoinst command server is unknown
[error] foo at /hdd/openqa-devel/repos/openQA/script/../lib/OpenQA/LiveHandler/Controller/LiveViewHandler.pm line 66.

For this I invoked the web socket route mentioned in the ticket description like this:

wsdump ws://127.0.0.1:9528/liveviewhandler/tests/4266/developer/ws-proxy/status
Traceback (most recent call last):
…
  File "/usr/lib/python3.11/site-packages/websocket/_handshake.py", line 150, in _get_resp_headers
    raise WebSocketBadStatusException(
websocket._exceptions.WebSocketBadStatusException: Handshake status 500 Internal Server Error -+-+- {'connection': 'Upgrade', 'content-length': '14', 'content-type': 'text/html;charset=UTF-8', 'date': 'Tue, 30 Apr 2024 14:59:24 GMT', 'sec-websocket-accept': '…', 'server': 'Mojolicious (Perl)', 'strict-transport-security': 'max-age=31536000; includeSubDomains', 'upgrade': 'websocket'} -+-+- b'internal error'

(Without the -m production the actual error is returned to the ws client instead of just "internal error".)

I did the same test as in #159792#note-4 with the web socket server and also here errors are definitely logged:

script/openqa-websockets daemon
[2024-05-15 17:17:21.69383] [13123] [warn] Deprecated use of config key '[audit]: blacklist'. Use '[audit]: blocklist' instead
[info] Listening at "http://127.0.0.1:9527"
Web application available at http://127.0.0.1:9527
[info] Listening at "http://[::1]:9527"
Web application available at http://[::1]:9527
Mojo::Reactor::Poll: I/O watcher failed: foo at /hdd/openqa-devel/repos/openQA/script/../lib/OpenQA/WebSockets/Controller/Worker.pm line 58.

I connected via wsdump ws://127.0.0.1:9527/api/v1/ws/20.

I also put the die in a few other places and tested other routes. This changed the error message a little bit (e.g. to [error] foo at /hdd/openqa-devel/repos/openQA/script/../lib/OpenQA/WebSockets/Controller/Worker.pm line 31.) but there was still always an error logged.

Maybe those 500 errors came just from Apache after all? Maybe, once we setup the Grafana panel for NGINX, we don't see this discrepancy between 500 responses and actual errors being logged anymore?