Console proxy doesn't work since the beginning of May

[vladimirpetrov]

ISSUE TYPE

• Bug Report

COMPONENT NAME

Console proxy

CLOUDSTACK VERSION

4.19

CONFIGURATION

N/A

OS / ENVIRONMENT

N/A

SUMMARY

After the beginning of May the console proxy is not working. Tried several PRs (fresh install and upgrade) - #6979, #7009, #7489 and #7344 (Health check).

STEPS TO REPRODUCE

Go to a running VM and try to open its virtual console.

EXPECTED RESULTS

The virtual console must be opened.

ACTUAL RESULTS

Cloudstack shows the following error message when trying to connect to the vitrual console:
Failed to connect to server / access token has expired

[rohityadavcloud]

cc @nvazquez @DaanHoogland

[nvazquez]

@vladimirpetrov @shwstppr I was able to reproduce the issue, I suspect the issue is introduced by the PR #7414

2023-05-24 19:03:06,005 DEBUG [c.c.c.AgentHookBase] (AgentManager-Handler-8:null) (logid:) Acquiring session [cbc024b7-209a-4518-b582-7cc45272a29b] as it was just used.
2023-05-24 19:03:06,007 DEBUG [c.c.u.d.T.Transaction] (AgentManager-Handler-8:null) (logid:) Rolling back the transaction: Time = 1 Name =  -ClusteredAgentManagerImpl$ClusteredAgentHandler.doTask:624-Task.call:83-Task.call:29-FutureTask.run:264-ThreadPoolExecutor.runWorker:1128-ThreadPoolExecutor$Worker.run:628-Thread.run:829; called by -TransactionLegacy.rollback:888-TransactionLegacy.removeUpTo:831-TransactionLegacy.close:655-TransactionContextInterceptor.invoke:36-ReflectiveMethodInvocation.proceed:175-ExposeInvocationInterceptor.invoke:97-ReflectiveMethodInvocation.proceed:186-JdkDynamicAopProxy.invoke:215-$Proxy251.acquireSession:-1-ConsoleAccessManagerImpl.acquireSession:251-AgentHookBase.onConsoleAccessAuthentication:114-ConsoleProxyListener.processControlCommand:61
2023-05-24 19:03:06,009 WARN  [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-8:null) (logid:) Caught: 
com.cloud.utils.exception.CloudRuntimeException: DB Exception on: com.mysql.cj.jdbc.ClientPreparedStatement: UPDATE console_session SET console_session.acquired=** NOT SPECIFIED ** WHERE console_session.id = 13 
	at com.cloud.utils.db.GenericDaoBase.update(GenericDaoBase.java:847)
	at com.cloud.utils.db.GenericDaoBase.update(GenericDaoBase.java:802)
	at com.cloud.utils.db.GenericDaoBase.update(GenericDaoBase.java:1399)
	at com.cloud.vm.dao.ConsoleSessionDaoImpl.acquireSession(ConsoleSessionDaoImpl.java:65)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:566)
	at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:344)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:198)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163)
	at com.cloud.utils.db.TransactionContextInterceptor.invoke(TransactionContextInterceptor.java:34)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:175)
	at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:97)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
	at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:215)
	at com.sun.proxy.$Proxy251.acquireSession(Unknown Source)
	at org.apache.cloudstack.consoleproxy.ConsoleAccessManagerImpl.acquireSession(ConsoleAccessManagerImpl.java:251)
	at com.cloud.consoleproxy.AgentHookBase.onConsoleAccessAuthentication(AgentHookBase.java:114)
	at com.cloud.consoleproxy.ConsoleProxyListener.processControlCommand(ConsoleProxyListener.java:61)
	at com.cloud.agent.manager.AgentManagerImpl.handleControlCommand(AgentManagerImpl.java:300)
	at com.cloud.agent.manager.AgentManagerImpl$AgentHandler.processRequest(AgentManagerImpl.java:1364)
	at com.cloud.agent.manager.AgentManagerImpl$AgentHandler.doTask(AgentManagerImpl.java:1450)
	at com.cloud.agent.manager.ClusteredAgentManagerImpl$ClusteredAgentHandler.doTask(ClusteredAgentManagerImpl.java:709)
	at com.cloud.utils.nio.Task.call(Task.java:83)
	at com.cloud.utils.nio.Task.call(Task.java:29)
	at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
	at java.base/java.lang.Thread.run(Thread.java:829)
Caused by: java.sql.SQLException: No value specified for parameter 1
	at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:129)
	at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:97)
	at com.mysql.cj.jdbc.exceptions.SQLExceptionsMapping.translateException(SQLExceptionsMapping.java:122)
	... 36 more
2023-05-24 19:03:06,011 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-8:null) (logid:) SeqA 3-126: Sending Seq 3-126:  { Ans: , MgmtId: 167781138, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.Answer":{"result":"false","details":"DB Exception on: com.mysql.cj.jdbc.ClientPreparedStatement: UPDATE console_session SET console_session.acquired=** NOT SPECIFIED ** WHERE console_session.id = 13 ","wait":"0","bypassHostMaintenance":"false"}}] }

[weizhouapache]

following @nvazquez 's investigation, I checked the source code which looks ok

https://github.com/apache/cloudstack/blob/main/engine/schema/src/main/java/com/cloud/vm/dao/ConsoleSessionDaoImpl.java#LL61C1-L66C6

    @Override
    public void acquireSession(String sessionUuid) {
        ConsoleSessionVO consoleSessionVO = findByUuid(sessionUuid);
        consoleSessionVO.setAcquired(new Date());
        update(consoleSessionVO.getId(), consoleSessionVO);
    }

database looks ok as well

mysql> desc console_session;
+-------------+-----------------+------+-----+---------+----------------+
| Field       | Type            | Null | Key | Default | Extra          |
+-------------+-----------------+------+-----+---------+----------------+
| id          | bigint unsigned | NO   | PRI | NULL    | auto_increment |
| uuid        | varchar(40)     | NO   | UNI | NULL    |                |
| created     | datetime        | NO   |     | NULL    |                |
| account_id  | bigint unsigned | NO   | MUL | NULL    |                |
| user_id     | bigint unsigned | NO   | MUL | NULL    |                |
| instance_id | bigint unsigned | NO   | MUL | NULL    |                |
| host_id     | bigint unsigned | NO   | MUL | NULL    |                |
| acquired    | datetime        | YES  |     | NULL    |                |
| removed     | datetime        | YES  |     | NULL    |                |
+-------------+-----------------+------+-----+---------+----------------+
9 rows in set (0.01 sec)

[nvazquez]

Yes @weizhouapache - the code section seems correct but the underlying implementation of the update only sets the id field but not the acquired field on the prepared statement

[nvazquez]

I have created this fix: #7558, can you please review? @vladimirpetrov @weizhouapache @rohityadavcloud

[DaanHoogland]

I saw your fix Nicolas, and it seems ok, but also addressing an isolated issue while the problem seems more generic. Do we know what caused the issue to begin with?

[nvazquez]

@DaanHoogland looks like the generic dao logic was missing an annotation for the date field, I have refactored the solution to add the missing annotation