Bug 1388244 - ovirt-vmconsole fails to get SSH keys due to HTTP 405 error
Summary: ovirt-vmconsole fails to get SSH keys due to HTTP 405 error
Keywords:
Status: CLOSED NOTABUG
Alias: None
Product: ovirt-vmconsole
Classification: oVirt
Component: Proxy.Keys
Version: 1.0.4
Hardware: Unspecified
OS: Unspecified
unspecified
unspecified vote
Target Milestone: ---
: ---
Assignee: Francesco Romani
QA Contact: Nikolai Sednev
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2016-10-24 20:28 UTC by Marcus Sundberg
Modified: 2016-11-15 22:20 UTC (History)
6 users (show)

Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2016-11-09 17:38:48 UTC
oVirt Team: Virt
rule-engine: planning_ack?
rule-engine: devel_ack?
rule-engine: testing_ack?


Attachments (Terms of Use)
LoginOnBehalfCommand failed (7.70 KB, text/plain)
2016-11-02 10:18 UTC, Francesco Romani
no flags Details
engine.log from start of engine (141.35 KB, text/plain)
2016-11-08 21:49 UTC, Marcus Sundberg
no flags Details
Engine SSO/AAA log (15.91 KB, text/plain)
2016-11-09 16:49 UTC, Francesco Romani
no flags Details
patched ovirt-vmconsole helper (8.36 KB, text/x-python)
2016-11-09 17:03 UTC, Francesco Romani
no flags Details


Links
System ID Private Priority Status Summary Last Updated
oVirt gerrit 66343 0 'None' 'MERGED' 'ovirt-vmconsole-helper: more debug logs' 2019-11-27 22:07:31 UTC

Description Marcus Sundberg 2016-10-24 20:28:07 UTC
Description of problem:
When trying to ssh to ovirt-vmconsole it fails to list the allowed ssh keys
with the following output:
Oct 24 22:23:43 <host> ovirt-vmconsole[20797]: 2016-10-24 22:23:43,581 ovirt-vmconsole-list: ERROR main:274 Error: HTTP Error 405: Method Not Allowed
Oct 24 22:23:43 <host> ovirt-vmconsole-proxy-keys[20793]: ERROR Key list execution failed rc=1
Oct 24 22:23:43 <host> sshd[20787]: error: AuthorizedKeysCommand /usr/libexec/ovirt-vmconsole-proxy-keys returned status 1
Oct 24 22:23:43 <host> ovirt-vmconsole[20895]: 2016-10-24 22:23:43,810 ovirt-vmconsole-list: ERROR main:274 Error: HTTP Error 405: Method Not Allowed
Oct 24 22:23:43 <host> ovirt-vmconsole-proxy-keys[20869]: ERROR Key list execution failed rc=1
Oct 24 22:23:43 <host> sshd[20787]: error: AuthorizedKeysCommand /usr/libexec/ovirt-vmconsole-proxy-keys returned status 1
Oct 24 22:23:44 <host> ovirt-vmconsole[20919]: 2016-10-24 22:23:44,033 ovirt-vmconsole-list: ERROR main:274 Error: HTTP Error 405: Method Not Allowed
Oct 24 22:23:44 <host> ovirt-vmconsole-proxy-keys[20912]: ERROR Key list execution failed rc=1
Oct 24 22:23:44 <host> sshd[20787]: error: AuthorizedKeysCommand /usr/libexec/ovirt-vmconsole-proxy-keys returned status 1
Oct 24 22:23:44 <host> ovirt-vmconsole[20929]: 2016-10-24 22:23:44,240 ovirt-vmconsole-list: ERROR main:274 Error: HTTP Error 405: Method Not Allowed
Oct 24 22:23:44 <host> ovirt-vmconsole-proxy-keys[20925]: ERROR Key list execution failed rc=1
Oct 24 22:23:44 <host> sshd[20787]: error: AuthorizedKeysCommand /usr/libexec/ovirt-vmconsole-proxy-keys returned status 1
Oct 24 22:23:44 <host> sshd[20787]: Connection closed by 192.168.125.223 [preauth]


Version-Release number of selected component (if applicable):
oVirt 4.0.4:
ovirt-engine-setup-plugin-vmconsole-proxy-helper-4.0.4.4-1.el7.centos.noarch
ovirt-engine-vmconsole-proxy-helper-4.0.4.4-1.el7.centos.noarch
ovirt-vmconsole-1.0.4-1.el7.centos.noarch
ovirt-vmconsole-proxy-1.0.4-1.el7.centos.noarch

How reproducible: Always

Steps to Reproduce:
1. Add SSH key in GUI
2. ssh ovirt-vmconsole@<host> -p 2222

Actual results: Permission denied.

Expected results: Successful login.

Comment 1 Francesco Romani 2016-11-02 08:55:19 UTC
(In reply to Marcus Sundberg from comment #0)
> Description of problem:
> When trying to ssh to ovirt-vmconsole it fails to list the allowed ssh keys
> with the following output:
> Oct 24 22:23:43 <host> ovirt-vmconsole[20797]: 2016-10-24 22:23:43,581
> ovirt-vmconsole-list: ERROR main:274 Error: HTTP Error 405: Method Not
> Allowed
> Oct 24 22:23:43 <host> ovirt-vmconsole-proxy-keys[20793]: ERROR Key list
> execution failed rc=1
> Oct 24 22:23:43 <host> sshd[20787]: error: AuthorizedKeysCommand
> /usr/libexec/ovirt-vmconsole-proxy-keys returned status 1
> Oct 24 22:23:43 <host> ovirt-vmconsole[20895]: 2016-10-24 22:23:43,810
> ovirt-vmconsole-list: ERROR main:274 Error: HTTP Error 405: Method Not
> Allowed
> Oct 24 22:23:43 <host> ovirt-vmconsole-proxy-keys[20869]: ERROR Key list
> execution failed rc=1
> Oct 24 22:23:43 <host> sshd[20787]: error: AuthorizedKeysCommand
> /usr/libexec/ovirt-vmconsole-proxy-keys returned status 1
> Oct 24 22:23:44 <host> ovirt-vmconsole[20919]: 2016-10-24 22:23:44,033
> ovirt-vmconsole-list: ERROR main:274 Error: HTTP Error 405: Method Not
> Allowed
> Oct 24 22:23:44 <host> ovirt-vmconsole-proxy-keys[20912]: ERROR Key list
> execution failed rc=1
> Oct 24 22:23:44 <host> sshd[20787]: error: AuthorizedKeysCommand
> /usr/libexec/ovirt-vmconsole-proxy-keys returned status 1
> Oct 24 22:23:44 <host> ovirt-vmconsole[20929]: 2016-10-24 22:23:44,240
> ovirt-vmconsole-list: ERROR main:274 Error: HTTP Error 405: Method Not
> Allowed
> Oct 24 22:23:44 <host> ovirt-vmconsole-proxy-keys[20925]: ERROR Key list
> execution failed rc=1
> Oct 24 22:23:44 <host> sshd[20787]: error: AuthorizedKeysCommand
> /usr/libexec/ovirt-vmconsole-proxy-keys returned status 1
> Oct 24 22:23:44 <host> sshd[20787]: Connection closed by 192.168.125.223
> [preauth]

Hi, we are investigating this issue.
Could you please share the ovirt engine logs? A snippet of log corresponding to failed connection attempt would be fine.

Comment 2 Francesco Romani 2016-11-02 10:18:53 UTC
Created attachment 1216459 [details]
LoginOnBehalfCommand failed

Comment 3 Francesco Romani 2016-11-02 10:20:51 UTC
(In reply to Francesco Romani from comment #2)
> Created attachment 1216459 [details]
> LoginOnBehalfCommand failed

While investigating this issue I found this error. Not sure it is the same root cause,  but it is in the same flow, so we need to understand this.
I'm running this on a basic CentOS 7.2 box with packages from ovirt, everything up to date according to both yum and engine-setup.

[root@rel40x ~]# rpm -qa | grep ovirt
ovirt-engine-vmconsole-proxy-helper-4.0.5.5-1.el7.centos.noarch
ovirt-imageio-common-0.4.0-1.el7.noarch
ovirt-engine-webadmin-portal-4.0.0.4-1.el7.centos.noarch
ovirt-engine-userportal-4.0.0.4-1.el7.centos.noarch
ovirt-setup-lib-1.0.2-1.el7.centos.noarch
ovirt-iso-uploader-4.0.2-1.el7.centos.noarch
ovirt-engine-setup-plugin-vmconsole-proxy-helper-4.0.5.5-1.el7.centos.noarch
ovirt-engine-extension-aaa-jdbc-1.1.1-1.el7.noarch
ovirt-vmconsole-1.0.4-1.el7.centos.noarch
ovirt-host-deploy-java-1.5.3-1.el7.centos.noarch
ovirt-engine-setup-base-4.0.5.5-1.el7.centos.noarch
ovirt-engine-wildfly-overlay-10.0.0-1.el7.noarch
ovirt-engine-setup-plugin-websocket-proxy-4.0.5.5-1.el7.centos.noarch
ovirt-engine-extensions-api-impl-4.0.5.5-1.el7.centos.noarch
ovirt-engine-tools-backup-4.0.0.4-1.el7.centos.noarch
ovirt-engine-wildfly-10.1.0-1.el7.x86_64
ovirt-imageio-proxy-0.4.0-0.201608310602.gita9b573b.el7.centos.noarch
ovirt-engine-backend-4.0.0.4-1.el7.centos.noarch
ovirt-engine-4.0.0.4-1.el7.centos.noarch
ovirt-engine-cli-3.6.8.1-1.el7.centos.noarch
ovirt-release36-3.6.7-1.noarch
ovirt-engine-dwh-4.0.2-1.el7.centos.noarch
ovirt-host-deploy-1.5.3-1.el7.centos.noarch
ovirt-engine-dwh-setup-4.0.5-1.el7.centos.noarch
ovirt-release40-pre-4.0.5-2.noarch
ovirt-engine-setup-plugin-ovirt-engine-common-4.0.5.5-1.el7.centos.noarch
ovirt-engine-websocket-proxy-4.0.5.5-1.el7.centos.noarch
ovirt-engine-dashboard-1.0.0-0.2.20160610git5d210ea.el7.centos.noarch
ovirt-engine-tools-4.0.0.4-1.el7.centos.noarch
ovirt-engine-sdk-python-3.6.9.1-1.el7.centos.noarch
ovirt-imageio-proxy-setup-0.4.0-0.201608310602.gita9b573b.el7.centos.noarch
ovirt-image-uploader-4.0.1-1.el7.centos.noarch
python-ovirt-engine-sdk4-4.0.2-1.el7.centos.x86_64
ovirt-engine-setup-plugin-ovirt-engine-4.0.5.5-1.el7.centos.noarch
ovirt-vmconsole-proxy-1.0.4-1.el7.centos.noarch
ovirt-engine-lib-4.0.5.5-1.el7.centos.noarch
ovirt-engine-setup-4.0.5.5-1.el7.centos.noarch
ovirt-engine-dbscripts-4.0.0.4-1.el7.centos.noarch
ovirt-engine-restapi-4.0.0.4-1.el7.centos.noarch


Ravi, could you please have a look (see stacktrace in https://bugzilla.redhat.com/attachment.cgi?id=1216459 )

Comment 4 Tomas Jelinek 2016-11-04 09:38:32 UTC
just pasting the relevant part of the log here for easier googling:

2016-11-02 06:16:19,702 INFO  [org.ovirt.engine.core.bll.aaa.LoginOnBehalfCommand] (default task-3) [276a776c] Running command: LoginOnBehalfCommand internal: true.
2016-11-02 06:16:19,864 ERROR [org.ovirt.engine.core.sso.utils.SsoUtils] (default task-4) [] OAuthException invalid_request: Invalid request, parameter 'token' not found or contains invalid value.
2016-11-02 06:16:19,883 ERROR [org.ovirt.engine.core.bll.aaa.LoginOnBehalfCommand] (default task-3) [276a776c] Unable to create engine session: EngineException:  user admin in domain 'internal-authz (Failed with error PRINCIPAL_NOT_FOUND and code 5200)
2016-11-02 06:16:19,900 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (default task-3) [276a776c] Correlation ID: 276a776c, Call Stack: null, Custom Event ID: -1, Message: Failed to execute login on behalf - for user admin.
2016-11-02 06:16:19,901 ERROR [org.ovirt.engine.core.services.VMConsoleProxyServlet] (default task-3) [276a776c] Error processing request: : java.lang.RuntimeException: Unable to create session using LoginOnBehalf

Comment 5 Marcus Sundberg 2016-11-04 10:13:02 UTC
(In reply to Francesco Romani from comment #1)

You already got them - the engine logs are completely silent according to:

tail -F /var/log/ovirt-engine/*.log /var/log/ovirt-engine/*/*.log

Let me know if there is anything I can do to enable some debug logs.

Comment 6 Ravi Nori 2016-11-07 13:38:24 UTC
You can add the following to ovirt-engine.xml.in and restart engine to enable debug logs. Debug logs in this case would help figure out what is going on

       <logger category="org.ovirt.engine.core.sso">
        <level name="DEBUG"/>
      </logger>

       <logger category="org.ovirt.engine.core.aaa">
        <level name="DEBUG"/>
      </logger>

Comment 7 Marcus Sundberg 2016-11-08 21:34:03 UTC
(In reply to Ravi Nori from comment #6)
Sorry I still get nothing in the logs when trying to login via ssh.
I have confirmed that I get DEBUG messages for both sso and aaa components:

# grep -E "DEBUG..org.ovirt.engine.core.(sso|aaa)" /var/log/ovirt-engine/engine.log | wc -l
504
#

Comment 8 Marcus Sundberg 2016-11-08 21:49:44 UTC
Created attachment 1218732 [details]
engine.log from start of engine

Attaching engine.log from the start of the engine and including an attempted
ssh login to vmconsole (which produce nothing in the log).

Comment 9 Francesco Romani 2016-11-09 16:49:42 UTC
Created attachment 1219013 [details]
Engine SSO/AAA log

Comment 10 Francesco Romani 2016-11-09 16:50:13 UTC
(In reply to Ravi Nori from comment #6)
> You can add the following to ovirt-engine.xml.in and restart engine to
> enable debug logs. Debug logs in this case would help figure out what is
> going on
> 
>        <logger category="org.ovirt.engine.core.sso">
>         <level name="DEBUG"/>
>       </logger>
> 
>        <logger category="org.ovirt.engine.core.aaa">
>         <level name="DEBUG"/>
>       </logger>

Done, please check https://bugzilla.redhat.com/attachment.cgi?id=1219013

Comment 11 Francesco Romani 2016-11-09 17:03:03 UTC
Created attachment 1219027 [details]
patched ovirt-vmconsole helper

Comment 12 Francesco Romani 2016-11-09 17:03:23 UTC
(In reply to Marcus Sundberg from comment #8)
> Created attachment 1218732 [details]
> engine.log from start of engine
> 
> Attaching engine.log from the start of the engine and including an attempted
> ssh login to vmconsole (which produce nothing in the log).

Indeed nothing is in the logs, and this is suspicious.
The issue I've discovered (https://bugzilla.redhat.com/show_bug.cgi?id=1388244#c3) is related to this flow and will be investigated separately, but besides that I can't reproduce your issue;
Furthermore, the error I got happens *after* the connection, so I past the point on which I should get 405 like you get.

So, let's enable the ovirt-vmconsole debug logs, starting with the engine helper.
Please add this file (or edit if already exists):

  /etc/ovirt-engine/ovirt-vmconsole-proxy-helper.conf

add this key-value pair to enable the debug log

  DEBUG=true

I strongly advise to replace your

  /usr/libexec/ovirt-vmconsole-proxy-helper/ovirt-vmconsole-list.py

with the one I attached in https://bugzilla.redhat.com/attachment.cgi?id=1219027

to have even more logs (those changes will be part of a near-future release).

Please retry to connect to the console, and check the journal/logs for lines like

Nov 09 12:01:56 rel40x.rokugan.lan ovirt-vmconsole[3711]: 2016-11-09 12:01:56,067 ovirt-vmconsole-list: DEBUG main:243 using engine base url: http://rel40x.rokugan.lan:80/ovirt-engine/
Nov 09 12:01:56 rel40x.rokugan.lan ovirt-vmconsole[3711]: 2016-11-09 12:01:56,071 ovirt-vmconsole-list: DEBUG main:255 will send 'POST' to 'http://rel40x.rokugan.lan:80/ovirt-engine/services/vmconsole-proxy'
Nov 09 12:01:56 rel40x.rokugan.lan ovirt-vmconsole[3717]: 2016-11-09 12:01:56,174 ovirt-vmconsole-list: DEBUG main:243 using engine base url: http://rel40x.rokugan.lan:80/ovirt-engine/
Nov 09 12:01:56 rel40x.rokugan.lan ovirt-vmconsole[3717]: 2016-11-09 12:01:56,176 ovirt-vmconsole-list: DEBUG main:255 will send 'POST' to 'http://rel40x.rokugan.lan:80/ovirt-engine/services/vmconsole-proxy'
Nov 09 12:01:56 rel40x.rokugan.lan sshd[3705]: Accepted publickey for ovirt-vmconsole from 192.168.1.177 port 54084 ssh2: RSA f6:cb:19:22:99:34:c8:fc:c1:ed:e9:b0:37:b4:bb:07
Nov 09 12:01:56 rel40x.rokugan.lan sshd[3705]: Attempt to write login records by non-root user (aborting)
Nov 09 12:01:56 rel40x.rokugan.lan ovirt-vmconsole[3724]: 2016-11-09 12:01:56,402 ovirt-vmconsole-list: DEBUG main:243 using engine base url: http://rel40x.rokugan.lan:80/ovirt-engine/
Nov 09 12:01:56 rel40x.rokugan.lan ovirt-vmconsole[3724]: 2016-11-09 12:01:56,404 ovirt-vmconsole-list: DEBUG main:255 will send 'POST' to 'http://rel40x.rokugan.lan:80/ovirt-engine/services/vmconsole-proxy'
Nov 09 12:01:56 rel40x.rokugan.lan ovirt-vmconsole[3724]: 2016-11-09 12:01:56,442 ovirt-vmconsole-list: ERROR main:275 Error: HTTP Error 500: Internal Server Error
Nov 09 12:01:56 rel40x.rokugan.lan ovirt-vmconsole[3724]: 2016-11-09 12:01:56,442 ovirt-vmconsole-list: DEBUG main:276 Exception | Traceback (most recent call last): |   File "/usr/libexec/ovirt-vmconsole-proxy-helper/ovirt-vmconsole-list.py", line 266, in main |     verify_host=cfg_file.getboolean('ENGINE_VERIFY_HOST') |   File "/usr/libexec/ovirt-vmconsole-proxy-helper/ovirt-vmconsole-list.py", line 69, in urlopen |     build_opener(HTTPSHandler(context=context)).open(url) |   File "/usr/lib64/python2.7/urllib2.py", line 437, in open |     response = meth(req, response) |   File "/usr/lib64/python2.7/urllib2.py", line 550, in http_response |     'http', request, response, code, msg, hdrs) |   File "/usr/lib64/python2.7/urllib2.py", line 475, in error |     return self._call_chain(*args) |   File "/usr/lib64/python2.7/urllib2.py", line 409, in _call_chain |     result = func(*args) |   File "/usr/lib64/python2.7/urllib2.py", line 558, in http_error_default |     raise HTTPError(req.get_full_url(), code, msg, hdrs, fp) | HTTPError: HTTP Error 500: Internal Server Error
Nov 09 12:01:56 rel40x.rokugan.lan ovirt-vmconsole-proxy-shell[3720]: ERROR Console list execution failed rc=1

Comment 13 Marcus Sundberg 2016-11-09 17:38:48 UTC
(In reply to Francesco Romani from comment #12)
> Please add this file (or edit if already exists):
> 
>   /etc/ovirt-engine/ovirt-vmconsole-proxy-helper.conf

Ah! That led me to find the file:
/etc/ovirt-engine/ovirt-vmconsole-proxy-helper.conf.d/10-setup.conf
and inspecting that i found the following:
ENGINE_BASE_URL=http://<enginehost>:80/ovirt-engine/

After changing the URL to the correct https://<enginehost>/ovirt-engine/
the vmconsole started to work just fine.

Terribly sorry for wasting everyone's time. :-(

The reason for the error was that our apache frontend is configured to
redirect HTTP requests to the same HTTPS URL, and when the vmconsole proxy
got the redirect it did the (HTTP wise) correct thing and converted the
POST to /ovirt-engine/services/vmconsole-proxy into a GET, which is 
apparently not supported by that endpoint and thus resulted in a 405.

Comment 14 Marcus Sundberg 2016-11-09 17:41:50 UTC
I really don't know where the http: URL came from though? We're running
HTTPS and everything else works fine, and I don't see any reference
to that http: URL in engine-config -a

Comment 15 Francesco Romani 2016-11-10 07:16:37 UTC
(In reply to Marcus Sundberg from comment #14)
> I really don't know where the http: URL came from though? We're running
> HTTPS and everything else works fine, and I don't see any reference
> to that http: URL in engine-config -a

No problem, glad it makes sense in the end :)

engine-setup should use SSL/TLS by default, so I'm not sure either where that URL come from. Perhaps old run with devel mode enabled?
The URL is not public; it is one service URL which must be used by programs (not humans), we have few others like it.

Comment 16 Marcus Sundberg 2016-11-15 22:20:54 UTC
I just upgraded engine from 4.0.4 to 4.0.5, and when running engine-setup
it again reverted ENGINE_BASE_URL=https://<enginehost>/ovirt-engine/
to ENGINE_BASE_URL=http://<enginehost>:80/ovirt-engine/ in
/etc/ovirt-engine/ovirt-vmconsole-proxy-helper.conf.d/10-setup.conf

Any Idea where that might be coming from?


Note You need to log in before you can comment on or make changes to this bug.