search

apache / cloudstack

Apache CloudStack is an opensource Infrastructure as a Service (IaaS) cloud computing platform
https://cloudstack.apache.org/
Apache License 2.0
2.06k stars 1.1k forks source link

Cannot open console: ConsoleProxyServlet NullPointerException #3164

Closed AndreaGHG closed 5 years ago

AndreaGHG commented 5 years ago
ISSUE TYPE
COMPONENT NAME
Console proxy
CLOUDSTACK VERSION
4.11.2.0
CONFIGURATION

N/A

OS / ENVIRONMENT

CentOS 7.6.1810

SUMMARY

I've upgraded CloudStack from version 4.9.3.1 to ver. 4.11.2.0 on CentOS 7.6.1810. I use VMWare as hypervisor with system VM images and CS package from Shape Blue. From VM console in Console Proxy's VM console I can see version 4.11.2.0 banner, so the system VM look upgraded. Since the upgrade when I try to open an instance's console I get a "Server Internal Error" message inside the new window. In the management server log I'm getting this exception:

ERROR [c.c.s.ConsoleProxyServlet] (qtp510113906-18:null) (logid Unexepected exception in ConsoleProxyServlet java.lang.NullPointerException at com.cloud.info.ConsoleProxyInfo.formatProxyAddress(ConsoleProxyInfo.java:59) at com.cloud.info.ConsoleProxyInfo.(ConsoleProxyInfo.java:40) at com.cloud.consoleproxy.ConsoleProxyManagerImpl.assignProxy(ConsoleProxyManagerImpl.java:389) at com.cloud.server.ManagementServerImpl.getConsoleProxyForVm(ManagementServerImpl.java:2274) at com.cloud.server.ManagementServerImpl.getConsoleAccessUrlRoot(ManagementServerImpl.java:2305) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:498) at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:338) at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:197) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163) at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:92) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:185) at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:212) at com.sun.proxy.$Proxy193.getConsoleAccessUrlRoot(Unknown Source) at com.cloud.servlet.ConsoleProxyServlet.handleAccessRequest(ConsoleProxyServlet.java:275) at com.cloud.servlet.ConsoleProxyServlet.doGet(ConsoleProxyServlet.java:188) at javax.servlet.http.HttpServlet.service(HttpServlet.java:686) at javax.servlet.http.HttpServlet.service(HttpServlet.java:791) at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:852) at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:535) at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143) at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:548) at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132) at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:190) at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1595) at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:188) at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1253) at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:168) at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:473) at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1564) at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:166) at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1155) at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141) at org.eclipse.jetty.server.handler.gzip.GzipHandler.handle(GzipHandler.java:527) at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:126) at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132) at org.eclipse.jetty.server.Server.handle(Server.java:530) at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:347) at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:256) at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:279) at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:102) at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:124) at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:247) at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.produce(EatWhatYouKill.java:140) at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:131) at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:382) at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:708) at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:626) at java.lang.Thread.run(Thread.java:748)

STEPS TO REPRODUCE
EXPECTED RESULTS
ACTUAL RESULTS
kioie commented 5 years ago

How is your network configured?

AndreaGHG commented 5 years ago

Network type is "advanced" with those network:

public network - 10.100.1.1/24 (tagged 330) management network - 10.168.1.1-10.168.1.50 (untagged, GW 10.168.1.93) storage network - 10.168.1.51-10.168.1.70 (untagged, GW 10.168.1.93) guest networks on vlan 2001-2050

In this PDF you can see the network schema:

cs-console-proxy.pdf

Network configuration is the same setted before the Cloudstack upgrade, when Console Proxy was working fine.

Thank you for your support!

ustcweizhou commented 5 years ago

@AndreaGHG have you configured consoleproxy.url.domain in global settings ?

AndreaGHG commented 5 years ago

@ustcweizhou consoleproxy.url.domain was not configured.

I've resolved both private and public proxy's IPs, setting the public ip's name in consoleproxy.url.domain returns a connection deny when I try to open the console. Setting the private ip's name in consoleproxy.url.domain returns a connection timeout in the console window.

ustcweizhou commented 5 years ago

@AndreaGHG could you provide more details ? the value of global setting consoleproxy.url.domain and consoleproxy.sslEnabled and some screenshots of errors ?

AndreaGHG commented 5 years ago

I have created 2 DNS records: cs-proxy1-priv.example.it - 10.168.1.1 (console proxy private IP) cs-proxy1-pub.example.it - 10.100.1.54 (console proxy public IP)

I have tried to put in consoleproxy.url.domain both records:

consoleproxy.sslEnabled is set to false, I don't use HTTPS.

ustcweizhou commented 5 years ago

@AndreaGHG could you check errors in /var/log/cloud.log in consoleproxy vm ?

AndreaGHG commented 5 years ago

@ustcweizhou There are no errors in /var/log/cloud.log on ssvm even when I try to open a console. There is only this info message repeated every minute:

2019-02-26 16:36:07,036 INFO [storage.resource.NfsSecondaryStorageResource] (agentRequest-Handler-4:null) Determined host rn.example.it corresponds to IP 10.168.1.252

ustcweizhou commented 5 years ago

@AndreaGHG is there any log in management-server.log ?

When I open a console, I got the following logs

2019-02-26 21:28:36,506 DEBUG [c.c.a.t.Request] (qtp858242339-18:null) (logid:) Seq 1-2750010522463109132: Sending  { Cmd , MgmtId: 6827823599962, via: 1(node32), Ver: v1, Flags: 100011, [{"com.cloud.agent.api.GetVncPortCommand":{"id":3,"name":"s-3-VM","wait":0}}] }
2019-02-26 21:28:36,514 DEBUG [c.c.a.t.Request] (AgentManager-Handler-14:null) (logid:) Seq 1-2750010522463109132: Processing:  { Ans: , MgmtId: 6827823599962, via: 1, Ver: v1, Flags: 10, [{"com.cloud.agent.api.GetVncPortAnswer":{"address":"10.11.118.32","port":5900,"result":true,"wait":0}}] }
2019-02-26 21:28:36,514 DEBUG [c.c.a.t.Request] (qtp858242339-18:null) (logid:) Seq 1-2750010522463109132: Received:  { Ans: , MgmtId: 6827823599962, via: 1(node32), Ver: v1, Flags: 10, { GetVncPortAnswer } }
2019-02-26 21:28:36,514 DEBUG [c.c.s.ConsoleProxyServlet] (qtp858242339-18:null) (logid:) Port info 10.11.118.32
2019-02-26 21:28:36,514 INFO  [c.c.s.ConsoleProxyServlet] (qtp858242339-18:null) (logid:) Parse host info returned from executing GetVNCPortCommand. host info: 10.11.118.32
2019-02-26 21:28:36,524 DEBUG [c.c.s.ConsoleProxyServlet] (qtp858242339-18:null) (logid:) Compose console url: http://10-11-118-125.cloud.leaseweb.net/ajax?token=QzfjXWRklXcLqh0NMp-uVMds87zWmdAEe427UG-0kqz-dRRlXZbP5VQL2Ch4WOym47w3Xogh0VEs5I-ZieOYGOWKRRhYeVeq7Isq9ocasPBa-kQ8cCb_rc7oGcC5HYJenAwgaN5xmIVyemyjgTlS6zt7e4PLqeMKH7vd_vgzyqUvJnHLOvygzcoZjT_AsqU-mwHuXnRxNaBroduX-F20wCBxwmYNqIH7Mg07XNDTb_HHa9zFp_ZbD6E3YgvjJdf_aJb8PBrS1DOCt5U5LsGpNw
2019-02-26 21:28:36,525 DEBUG [c.c.s.ConsoleProxyServlet] (qtp858242339-18:null) (logid:) the console url is :: <html><title>s-3-VM</title><frameset><frame src="http://10-11-118-125.cloud.leaseweb.net/ajax?token=QzfjXWRklXcLqh0NMp-uVMds87zWmdAEe427UG-0kqz-dRRlXZbP5VQL2Ch4WOym47w3Xogh0VEs5I-ZieOYGOWKRRhYeVeq7Isq9ocasPBa-kQ8cCb_rc7oGcC5HYJenAwgaN5xmIVyemyjgTlS6zt7e4PLqeMKH7vd_vgzyqUvJnHLOvygzcoZjT_AsqU-mwHuXnRxNaBroduX-F20wCBxwmYNqIH7Mg07XNDTb_HHa9zFp_ZbD6E3YgvjJdf_aJb8PBrS1DOCt5U5LsGpNw"></frame></frameset></html>
2019-02-26 21:28:36,726 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-15:null) (logid:) SeqA 4-757: Processing Seq 4-757:  { Cmd , MgmtId: -1, via: 4, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleAccessAuthenticationCommand":{"_host":"10.11.118.32","_port":"5900","_vmId":"800c35b2-5eb9-4ed5-b167-bcacee909862","_sid":"kAJX5Sno8j3t47L_0LJjNg","_ticket":"gSZ/UHkRkFVjleZ2J0tjNbMZiK4=","_isReauthenticating":false,"wait":0}}] }
2019-02-26 21:28:36,726 DEBUG [c.c.c.AgentHookBase] (AgentManager-Handler-15:null) (logid:) Console authentication. Ticket in url for 10.11.118.32:5900-800c35b2-5eb9-4ed5-b167-bcacee909862 is gSZ/UHkRkFVjleZ2J0tjNbMZiK4=
2019-02-26 21:28:36,726 DEBUG [c.c.c.AgentHookBase] (AgentManager-Handler-15:null) (logid:) Console authentication. Ticket in 1 minute boundary for 10.11.118.32:5900-800c35b2-5eb9-4ed5-b167-bcacee909862 is gSZ/UHkRkFVjleZ2J0tjNbMZiK4=
2019-02-26 21:28:36,734 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-15:null) (logid:) SeqA 4-757: Sending Seq 4-757:  { Ans: , MgmtId: 6827823599962, via: 4, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.ConsoleAccessAuthenticationAnswer":{"_success":true,"_isReauthenticating":false,"_port":0,"result":true,"wait":0}}] }
AndreaGHG commented 5 years ago

@ustcweizhou

This is my management-server.log when try to opening a console:

`2019-02-27 09:08:55,483 DEBUG [c.c.a.t.Request] (qtp510113906-11:null) (logid:) Seq 1-5167036147477515108: Sending { Cmd , MgmtId: 345052229470, via: 1(cs-esxy3-san.example.it), Ver: v1, Flags: 100011, [{"com.cloud.agent.api.GetVncPortCommand":{"id":46,"name":"i-10-46-VM","wait":0}}] }

2019-02-27 09:08:55,483 DEBUG [c.c.a.t.Request] (qtp510113906-11:null) (logid:) Seq 1-5167036147477515108: Executing: { Cmd , MgmtId: 345052229470, via: 1(cs-esxy3-san.example.it), Ver: v1, Flags: 100011, [{"com.cloud.agent.api.GetVncPortCommand":{"id":46,"name":"i-10-46-VM","wait":0}}] }

2019-02-27 09:08:55,484 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-71:ctx-423a0a8c) (logid:207652e3) Seq 1-5167036147477515108: Executing request

2019-02-27 09:08:55,515 DEBUG [c.c.h.v.m.HostMO] (DirectAgent-71:ctx-423a0a8c cs-esxy3-san.example.it, cmd: GetVncPortCommand) (logid:207652e3) find VM i-10-46-VM on host

2019-02-27 09:08:55,515 INFO [c.c.h.v.m.HostMO] (DirectAgent-71:ctx-423a0a8c cs-esxy3-san.example.it, cmd: GetVncPortCommand) (logid:207652e3) VM i-10-46-VM not found in host cache

2019-02-27 09:08:55,515 DEBUG [c.c.h.v.m.HostMO] (DirectAgent-71:ctx-423a0a8c cs-esxy3-san.example.it, cmd: GetVncPortCommand) (logid:207652e3) load VM cache on host

2019-02-27 09:08:55,647 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-71:ctx-423a0a8c) (logid:207652e3) Seq 1-5167036147477515108: Response Received:

2019-02-27 09:08:55,647 DEBUG [c.c.a.t.Request] (DirectAgent-71:ctx-423a0a8c) (logid:207652e3) Seq 1-5167036147477515108: Processing: { Ans: , MgmtId: 345052229470, via: 1(cs-esxy3-san.example.it), Ver: v1, Flags: 10, [{"com.cloud.agent.api.GetVncPortAnswer":{"address":"10.168.1.173","port":5950,"result":true,"wait":0}}] }

2019-02-27 09:08:55,648 DEBUG [c.c.a.t.Request] (qtp510113906-11:null) (logid:) Seq 1-5167036147477515108: Received: { Ans: , MgmtId: 345052229470, via: 1(cs-esxy3-san.example.it), Ver: v1, Flags: 10, { GetVncPortAnswer } }

2019-02-27 09:08:55,648 DEBUG [c.c.s.ConsoleProxyServlet] (qtp510113906-11:null) (logid:) Port info 10.168.1.173

2019-02-27 09:08:55,653 INFO [c.c.s.ConsoleProxyServlet] (qtp510113906-11:null) (logid:) Parse host info returned from executing GetVNCPortCommand. host info: 10.168.1.173

2019-02-27 09:08:55,660 DEBUG [c.c.s.ConsoleProxyServlet] (qtp510113906-11:null) (logid:) Compose console url: http://cs-proxy1-pub.example.it/ajax?token=Nb4P4M53ZEwJ7ommgbcBCAfcNCpx2uOjUJxhExVQh8Xk_nbJlbVMdE9hNOeX8lyUe-icsH4QB8Xz8Qpa68EjwJS5BFW6gT_56kO7uD0nJoUxG7G51SXtKU7O3UTb2MpoexKgXP9of98foLvF0VFJZXUKcbuaSuhx-G4awJEa3kELov6zSmtT2Lskttf0nACO95KTldFwP6Il4r5b6UIuKJBPPKmIQFh7dIZlLbXS4fp9Tc3xzdFbiUekCho0FXXEpduAn2jTquLkJvcibHhvwxRs14FJ-e7DFsSJLB3XSeo

2019-02-27 09:08:55,660 DEBUG [c.c.s.ConsoleProxyServlet] (qtp510113906-11:null) (logid:) the console url is :: galera4

2019-02-27 09:08:56,224 INFO [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-9ed3deda) (logid:8d4562a7) Begin cleanup expired async-jobs

2019-02-27 09:08:56,231 INFO [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-9ed3deda) (logid:8d4562a7) End cleanup expired async-jobs

2019-02-27 09:08:56,671 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-1bdc133a) (logid:77575973) Found 6 routers to update status.

2019-02-27 09:08:56,673 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-1bdc133a) (logid:77575973) Found 0 VPC networks to update Redundant State.

2019-02-27 09:08:56,674 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-1bdc133a) (logid:77575973) Found 0 networks to update RvR status.

2019-02-27 09:09:01,663 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager Timer:ctx-80103e67) (logid:5648ecae) Resetting hosts suitable for reconnect

2019-02-27 09:09:01,666 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager Timer:ctx-80103e67) (logid:5648ecae) Completed resetting hosts suitable for reconnect

2019-02-27 09:09:01,666 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager Timer:ctx-80103e67) (logid:5648ecae) Acquiring hosts for clusters already owned by this management server

2019-02-27 09:09:01,669 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager Timer:ctx-80103e67) (logid:5648ecae) Completed acquiring hosts for clusters already owned by this management server `

Connecting on the Console Proxy with the VMWare console I cannot any service listening on 80 or 8080 ports. Can you show me your "netstat -lntp" output on the Console Proxy?

ustcweizhou commented 5 years ago

@AndreaGHG it seems java process is not running in cpvm. you can restart it by "/etc/init.d/cloud restart" logs can be found at /var/log/cloud.log

here is my output

root@v-4-VM:~# netstat -lntp
Active Internet connections (only servers)
Proto Recv-Q Send-Q Local Address           Foreign Address         State       PID/Program name
tcp        0      0 0.0.0.0:80              0.0.0.0:*               LISTEN      2538/java
tcp        0      0 169.254.3.151:3922      0.0.0.0:*               LISTEN      1170/sshd
tcp        0      0 0.0.0.0:8001            0.0.0.0:*               LISTEN      2538/java
AndreaGHG commented 5 years ago

@ustcweizhou

I don't have a "cloud" start script in /etc/init.d/

I've downloaded system image from BluShape site: http://packages.shapeblue.com/systemvmtemplate/4.11/

Now I'm trying to use image from CloudStack , this http://download.cloudstack.org/systemvm/4.11/systemvmtemplate-4.11.2-vmware.ova, but I cannot replace the installed system image, even if I use "cloud-install-sys-tmplt" script on the management server.

Have you any suggestion?

AndreaGHG commented 5 years ago

I've verified that system images from ShapeBlue and from CloudtStack are the same, I don't understand why there isn't the start script "cloud" in my Console Proxy.

ustcweizhou commented 5 years ago

@AndreaGHG sorry my mistake, cloud service has been changed to /etc/systemd/system/cloud.service you can restart it via "systemctl restart cloud"

AndreaGHG commented 5 years ago

@ustcweizhou cloud service is running and also if I restart it there is nothing listening on port 80 and 8001.

ustcweizhou commented 5 years ago

@AndreaGHG any log in /var/log/cloud.log and output of "systemctl status cloud" ?

AndreaGHG commented 5 years ago

This the output of 'systemctl status cloud':

root@v-69-VM:~# systemctl status cloud
‚óè cloud.service - CloudStack Agent service
   Loaded: loaded (/etc/systemd/system/cloud.service; enabled; vendor preset: enabled)
   Active: active (running) since Tue 2019-03-05 15:25:48 UTC; 5s ago
 Main PID: 2140 (bash)
    Tasks: 29 (limit: 4915)
   CGroup: /system.slice/cloud.service
           ├─2140 bash /usr/local/cloud/systemvm/_run.sh
           └─2289 java -Djavax.net.ssl.trustStore=./certs/realhostip.keystore -Djdk.tls.ephemeralDHKeySize=2048 -Djsse.enableSN

Mar 05 15:25:51 v-69-VM _run.sh[2140]: 15:25:51,391  INFO Agent:565 - Startup Response Received: agent id = 0
Mar 05 15:25:51 v-69-VM _run.sh[2140]: 15:25:51,459  INFO Agent:839 - Processing agent ready command, agent id = 11
Mar 05 15:25:51 v-69-VM _run.sh[2140]: 15:25:51,466  INFO Agent:370 - Set agent id 11
Mar 05 15:25:51 v-69-VM _run.sh[2140]: 15:25:51,477  INFO Agent:846 - Ready command is processed for agent id = 11
Mar 05 15:25:51 v-69-VM _run.sh[2140]: 15:25:51,478  INFO ConsoleProxyResource:104 - Receive ReadyCommand, response with ReadyA
Mar 05 15:25:51 v-69-VM _run.sh[2140]: 15:25:51,553  INFO Agent:839 - Processing agent ready command, agent id = 11
Mar 05 15:25:51 v-69-VM _run.sh[2140]: 15:25:51,555  INFO Agent:370 - Set agent id 11
Mar 05 15:25:51 v-69-VM _run.sh[2140]: 15:25:51,564  INFO Agent:800 - Processed new management server list: 10.168.1.248@static
Mar 05 15:25:51 v-69-VM _run.sh[2140]: 15:25:51,568  INFO Agent:846 - Ready command is processed for agent id = 11
Mar 05 15:25:51 v-69-VM _run.sh[2140]: 15:25:51,569  INFO ConsoleProxyResource:104 - Receive ReadyCommand, response with ReadyA

This is the log after service restart:

2019-03-05 15:25:47,904 INFO  [cloud.agent.Agent] (AgentShutdownThread:null) Stopping the agent: Reason = sig.kill
2019-03-05 15:25:50,085 INFO  [cloud.agent.AgentShell] (main:null) Agent started
2019-03-05 15:25:50,090 INFO  [cloud.agent.AgentShell] (main:null) Implementation Version is 4.11.2.0
2019-03-05 15:25:50,091 INFO  [cloud.agent.AgentShell] (main:null) agent.properties found at /usr/local/cloud/systemvm/conf/agent.properties
2019-03-05 15:25:50,109 INFO  [cloud.agent.AgentShell] (main:null) Defaulting to using properties file for storage
2019-03-05 15:25:50,116 INFO  [cloud.agent.AgentShell] (main:null) Defaulting to the constant time backoff algorithm
2019-03-05 15:25:50,140 INFO  [cloud.utils.LogUtils] (main:null) log4j configuration found at /usr/local/cloud/systemvm/conf/log4j-cloud.xml
2019-03-05 15:25:50,191 INFO  [cloud.agent.AgentShell] (main:null) Using default Java settings for IPv6 preference for agent connection
2019-03-05 15:25:50,416 INFO  [cloud.agent.Agent] (main:null) id is 11
2019-03-05 15:25:50,465 INFO  [resource.consoleproxy.ConsoleProxyResource] (main:null) Receive proxyVmId in ConsoleProxyResource configuration as 69
2019-03-05 15:25:50,468 INFO  [cloud.agent.Agent] (main:null) Agent [id = 11 : type = ConsoleProxyResource : zone = 2 : pod = 2 : workers = 5 : host = 10.168.1.248 : port = 8250
2019-03-05 15:25:50,480 INFO  [utils.nio.NioClient] (main:null) Connecting to 10.168.1.248:8250
2019-03-05 15:25:50,491 INFO  [utils.nio.Link] (main:null) Conf file found: /usr/local/cloud/systemvm/conf/agent.properties
2019-03-05 15:25:51,122 INFO  [utils.nio.NioClient] (main:null) SSL: Handshake done
2019-03-05 15:25:51,126 INFO  [utils.nio.NioClient] (main:null) Connected to 10.168.1.248:8250
2019-03-05 15:25:51,243 INFO  [cloud.serializer.GsonHelper] (Agent-Handler-1:null) Default Builder inited.
2019-03-05 15:25:51,369 INFO  [cloud.agent.Agent] (Agent-Handler-2:null) Proccess agent startup answer, agent id = 0
2019-03-05 15:25:51,372 INFO  [cloud.agent.Agent] (Agent-Handler-2:null) Set agent id 0
2019-03-05 15:25:51,391 INFO  [cloud.agent.Agent] (Agent-Handler-2:null) Startup Response Received: agent id = 0
2019-03-05 15:25:51,459 INFO  [cloud.agent.Agent] (agentRequest-Handler-2:null) Processing agent ready command, agent id = 11
2019-03-05 15:25:51,466 INFO  [cloud.agent.Agent] (agentRequest-Handler-2:null) Set agent id 11
2019-03-05 15:25:51,477 INFO  [cloud.agent.Agent] (agentRequest-Handler-2:null) Ready command is processed for agent id = 11
2019-03-05 15:25:51,478 INFO  [resource.consoleproxy.ConsoleProxyResource] (agentRequest-Handler-2:null) Receive ReadyCommand, response with ReadyAnswer
2019-03-05 15:25:51,553 INFO  [cloud.agent.Agent] (agentRequest-Handler-3:null) Processing agent ready command, agent id = 11
2019-03-05 15:25:51,555 INFO  [cloud.agent.Agent] (agentRequest-Handler-3:null) Set agent id 11
2019-03-05 15:25:51,564 INFO  [cloud.agent.Agent] (agentRequest-Handler-3:null) Processed new management server list: 10.168.1.248@static
2019-03-05 15:25:51,568 INFO  [cloud.agent.Agent] (agentRequest-Handler-3:null) Ready command is processed for agent id = 11
2019-03-05 15:25:51,569 INFO  [resource.consoleproxy.ConsoleProxyResource] (agentRequest-Handler-3:null) Receive ReadyCommand, response with ReadyAnswer

Here you can see that there is nothing listening on ports 80 and 8001:

root@v-69-VM:~# netstat -lnpt
Active Internet connections (only servers)
Proto Recv-Q Send-Q Local Address           Foreign Address         State       PID/Program name    
tcp        0      0 10.168.1.21:3922        0.0.0.0:*               LISTEN      1189/sshd           
root@v-69-VM:~#
ustcweizhou commented 5 years ago

@AndreaGHG is there log like below in management-server.log ?

2019-03-05 15:16:04,232 DEBUG [c.c.a.m.AgentManagerImpl] (AgentConnectTaskPool-6:ctx-69bc1e72) (logid:640138b9) Sending Connect to listener: ConsoleProxyListener
2019-03-05 15:16:04,258 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-8:null) (logid:) Ping from 5(v-2-VM)
2019-03-05 15:16:04,260 DEBUG [c.c.a.t.Request] (AgentConnectTaskPool-6:ctx-69bc1e72) (logid:640138b9) Seq 5-7071777314878521345: Sending  { Cmd , MgmtId: 7019620733284, via: 5(v-2-VM), Ver: v1, Flags: 100111, [{"com.cloud.agent.api.proxy.StartConsoleProxyAgentHttpHandlerCommand":{"wait":0}}] }
2019-03-05 15:16:04,516 DEBUG [c.c.a.t.Request] (AgentManager-Handler-11:null) (logid:) Seq 5-7071777314878521345: Processing:  { Ans: , MgmtId: 7019620733284, via: 5, Ver: v1, Flags: 110, [{"com.cloud.agent.api.Answer":{"result":true,"wait":0}}] }
2019-03-05 15:16:04,517 DEBUG [c.c.a.m.AgentAttache] (AgentManager-Handler-11:null) (logid:) Seq 5-7071777314878521345: No more commands found
2019-03-05 15:16:04,517 DEBUG [c.c.a.t.Request] (AgentConnectTaskPool-6:ctx-69bc1e72) (logid:640138b9) Seq 5-7071777314878521345: Received:  { Ans: , MgmtId: 7019620733284, via: 5(v-2-VM), Ver: v1, Flags: 110, { Answer } }
2019-03-05 15:16:04,517 INFO  [c.c.c.AgentHookBase] (AgentConnectTaskPool-6:ctx-69bc1e72) (logid:640138b9) Successfully sent out command to start HTTP handling in console proxy agent

There should be StartConsoleProxyAgentHttpHandlerCommand sent from mgt server to cloud agent in cpvm. However I did not see related logs in your cloud.log

AndreaGHG commented 5 years ago

This is the managemente-server.log when I try to open an instance console:

2019-03-05 17:09:38,224 DEBUG [c.c.a.t.Request] (qtp510113906-14:null) (logid:) Seq 1-5531546242317840041: Sending  { Cmd , MgmtId: 345052229470, via: 1(cs-esxy3-san.hypergrid.it), Ver: v1, Flags: 100011, [{"com.cloud.agent.api.GetVncPortCommand":{"id":46,"name":"i-10-46-VM","wait":0}}] }
2019-03-05 17:09:38,224 DEBUG [c.c.a.t.Request] (qtp510113906-14:null) (logid:) Seq 1-5531546242317840041: Executing:  { Cmd , MgmtId: 345052229470, via: 1(cs-esxy3-san.hypergrid.it), Ver: v1, Flags: 100011, [{"com.cloud.agent.api.GetVncPortCommand":{"id":46,"name":"i-10-46-VM","wait":0}}] }
2019-03-05 17:09:38,224 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-302:ctx-39f3edba) (logid:e9ae50da) Seq 1-5531546242317840041: Executing request
2019-03-05 17:09:38,242 DEBUG [c.c.h.v.m.HostMO] (DirectAgent-302:ctx-39f3edba cs-esxy3-san.hypergrid.it, cmd: GetVncPortCommand) (logid:e9ae50da) find VM i-10-46-VM on host
2019-03-05 17:09:38,242 INFO  [c.c.h.v.m.HostMO] (DirectAgent-302:ctx-39f3edba cs-esxy3-san.hypergrid.it, cmd: GetVncPortCommand) (logid:e9ae50da) VM i-10-46-VM not found in host cache
2019-03-05 17:09:38,242 DEBUG [c.c.h.v.m.HostMO] (DirectAgent-302:ctx-39f3edba cs-esxy3-san.hypergrid.it, cmd: GetVncPortCommand) (logid:e9ae50da) load VM cache on host
2019-03-05 17:09:38,394 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-302:ctx-39f3edba) (logid:e9ae50da) Seq 1-5531546242317840041: Response Received: 
2019-03-05 17:09:38,394 DEBUG [c.c.a.t.Request] (DirectAgent-302:ctx-39f3edba) (logid:e9ae50da) Seq 1-5531546242317840041: Processing:  { Ans: , MgmtId: 345052229470, via: 1(cs-esxy3-san.hypergrid.it), Ver: v1, Flags: 10, [{"com.cloud.agent.api.GetVncPortAnswer":{"address":"10.168.1.173","port":5950,"result":true,"wait":0}}] }
2019-03-05 17:09:38,394 DEBUG [c.c.a.t.Request] (qtp510113906-14:null) (logid:) Seq 1-5531546242317840041: Received:  { Ans: , MgmtId: 345052229470, via: 1(cs-esxy3-san.hypergrid.it), Ver: v1, Flags: 10, { GetVncPortAnswer } }
2019-03-05 17:09:38,394 DEBUG [c.c.s.ConsoleProxyServlet] (qtp510113906-14:null) (logid:) Port info 10.168.1.173
2019-03-05 17:09:38,394 INFO  [c.c.s.ConsoleProxyServlet] (qtp510113906-14:null) (logid:) Parse host info returned from executing GetVNCPortCommand. host info: 10.168.1.173
2019-03-05 17:09:38,400 DEBUG [c.c.s.ConsoleProxyServlet] (qtp510113906-14:null) (logid:) Compose console url: http://cs-proxy1-pub.hypergrid.it/ajax?token=Nb4P4M53ZEwJ7ommgbcBCAfcNCpx2uOjUJxhExVQh8Xk_nbJlbVMdE9hNOeX8lyUe-icsH4QB8Xz8Qpa68EjwJS5BFW6gT_56kO7uD0nJoUxG7G51SXtKU7O3UTb2MpoexKgXP9of98foLvF0VFJZXUKcbuaSuhx-G4awJEa3kELov6zSmtT2Lskttf0nACO95KTldFwP6Il4r5b6UIuKOQgAMleopW7SCgJjkeZu6rdq-0NguhkJBfs3NY7YG1Pb-FKiKQ5MjbZI_K3v697_arQ1U0gZn6xSwmTdaY4EFI
2019-03-05 17:09:38,401 DEBUG [c.c.s.ConsoleProxyServlet] (qtp510113906-14:null) (logid:) the console url is :: galera4
2019-03-05 17:09:42,411 DEBUG [o.a.c.s.SecondaryStorageManagerImpl] (secstorage-1:ctx-c08f9763) (logid:33004849) Zone 2 is ready to launch secondary storage VM
2019-03-05 17:09:42,565 DEBUG [c.c.c.ConsoleProxyManagerImpl] (consoleproxy-1:ctx-0acfabfb) (logid:fc01f57f) Zone 2 is ready to launch console proxy
2019-03-05 17:09:42,820 DEBUG [c.c.s.StatsCollector] (StatsCollector-4:ctx-8e9a73b3) (logid:0d6f34c2) AutoScaling Monitor is running...

This is the section of 'Sending Connect to listener: ConsoleProxyListener' in the management-server.log:

2019-03-05 15:36:51,608 DEBUG [c.c.a.m.AgentManagerImpl] (AgentConnectTaskPool-7:ctx-75349498) (logid:bba0aad4) Sending Connect to listener: ConsoleProxyListener
2019-03-05 15:36:51,612 ERROR [c.c.c.AgentHookBase] (AgentConnectTaskPool-7:ctx-75349498) (logid:bba0aad4) Unexpected exception when sending http handling startup command(time out) to the console proxy resource for proxy:69
com.cloud.utils.exception.CloudRuntimeException: Unable to find keystore CPVMCertificate
        at org.apache.cloudstack.framework.security.keystore.KeystoreManagerImpl.getKeystoreBits(KeystoreManagerImpl.java:96)
        at com.cloud.consoleproxy.AgentHookBase.startAgentHttpHandlerInVM(AgentHookBase.java:205)
        at com.cloud.consoleproxy.ConsoleProxyListener.processConnect(ConsoleProxyListener.java:75)
        at com.cloud.agent.manager.AgentManagerImpl.notifyMonitorsOfConnection(AgentManagerImpl.java:570)
        at com.cloud.agent.manager.AgentManagerImpl.handleConnectedAgent(AgentManagerImpl.java:1111)
        at com.cloud.agent.manager.AgentManagerImpl.access$000(AgentManagerImpl.java:126)
        at com.cloud.agent.manager.AgentManagerImpl$HandleAgentConnectTask.runInContext(AgentManagerImpl.java:1195)
        at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:49)
        at org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:56)
        at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:103)
        at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:53)
        at org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:46)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at java.lang.Thread.run(Thread.java:748)
2019-03-05 15:36:51,613 DEBUG [c.c.a.m.AgentManagerImpl] (AgentConnectTaskPool-7:ctx-75349498) (logid:bba0aad4) Sending Connect to listener: DownloadListener
2019-03-05 15:36:51,614 DEBUG [c.c.a.m.AgentManagerImpl] (AgentConnectTaskPool-7:ctx-75349498) (logid:bba0aad4) Sending Connect to listener: UploadListener
2019-03-05 15:36:51,620 DEBUG [c.c.a.t.Request] (AgentConnectTaskPool-7:ctx-75349498) (logid:bba0aad4) Seq 11-5734771175502905345: Sending  { Cmd , MgmtId: 345052229470, via: 11(v-69-VM), Ver: v1, Flags: 100111, [{"com.cloud.agent.api.ReadyCommand":{"dcId":2,"hostId":11,"wait":0}}] }
2019-03-05 15:36:51,687 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-15:null) (logid:) Ping from 11(v-69-VM)
2019-03-05 15:36:51,745 DEBUG [c.c.a.t.Request] (AgentManager-Handler-1:null) (logid:) Seq 11-5734771175502905345: Processing:  { Ans: , MgmtId: 345052229470, via: 11, Ver: v1, Flags: 110, [{"com.cloud.agent.api.ReadyAnswer":{"result":true,"wait":0}}] }
2019-03-05 15:36:51,745 DEBUG [c.c.a.t.Request] (AgentConnectTaskPool-7:ctx-75349498) (logid:bba0aad4) Seq 11-5734771175502905345: Received:  { Ans: , MgmtId: 345052229470, via: 11(v-69-VM), Ver: v1, Flags: 110, { ReadyAnswer } }
2019-03-05 15:36:51,750 DEBUG [c.c.h.Status] (AgentConnectTaskPool-7:ctx-75349498) (logid:bba0aad4) Transition:[Resource state = Enabled, Agent event = Ready, Host id = 11, name = v-69-VM]
2019-03-05 15:36:51,751 DEBUG [c.c.a.m.AgentAttache] (AgentManager-Handler-1:null) (logid:) Seq 11-5734771175502905345: No more commands found
2019-03-05 15:36:51,775 DEBUG [c.c.a.t.Request] (AgentConnectTaskPool-7:ctx-75349498) (logid:bba0aad4) Seq 11-5734771175502905346: Sending  { Cmd , MgmtId: 345052229470, via: 11(v-69-VM), Ver: v1, Flags: 100111, [{"com.cloud.agent.api.ReadyCommand":{"dcId":2,"hostId":11,"msHostList":["10.168.1.248"],"lbAlgorithm":"static","lbCheckInterval":0,"wait":0}}] }
ustcweizhou commented 5 years ago

@AndreaGHG you need to upload ssl certificate please refer to http://docs.cloudstack.apache.org/en/4.11.1.0/adminguide/systemvm.html#changing-the-console-proxy-ssl-certificate-and-domain

AndreaGHG commented 5 years ago

@ustcweizhou

After installing SSL certificate console proxy works again. Thank you so much for your support!