Bug 1388244

(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.

Created attachment 1216459 [details]
LoginOnBehalfCommand failed

(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 )

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

(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.

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>

(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
#

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).

Created attachment 1219013 [details]
Engine SSO/AAA log

(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

Created attachment 1219027 [details]
patched ovirt-vmconsole helper

(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

(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.

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

(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.

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?