Upgrade from 4.19.1.0 to 4.19.1.2 login issues "Unauthorized Session expired"

[DerekHarter]

Usually I defer upgrading cloudstack-management packages until ready, but wasn't paying attention on last apt upgrade and the cloudstack-management package was upgraded from 4.19.1.0 to 4.19.1.2.

The cloudstack-management service came up successfully. However we are experiencing an error when attempting to login to the management gui. We get the following error message in the web browser on login:

Unauthorized
Session expired, authorization verification failed.

And the following is I believe the relevant output from the cloudstack/management/management-server.log file. It appears that the login initally succeeds, but then on listZones when doing service discovery, we are getting a "Session destroyed" from some unspecified javax servlet error happenning. Any help or suggestions to clear or debug this would be appreciated.

2024-10-30 14:52:19,743 DEBUG [o.a.c.s.a.PBKDF2UserAuthenticator] (qtp364604394-595:ctx-3248c904) (logid:cc51d465) Retrieving user: admin
2024-10-30 14:52:20,240 DEBUG [c.c.u.AccountManagerImpl] (qtp364604394-595:ctx-3248c904) (logid:cc51d465) CIDRs from which account 'Account [{"accountName":"admin","id":2,"uuid":"089520b8-19f5-11ef-9062-62ce04319667"}]' is allowed to perform API calls: 0.0.0.0/0,::/0
2024-10-30 14:52:20,240 DEBUG [c.c.u.AccountManagerImpl] (qtp364604394-595:ctx-3248c904) (logid:cc51d465) User: admin in domain 1 has successfully logged in
2024-10-30 14:52:20,253 INFO  [c.c.a.ApiServer] (qtp364604394-595:ctx-3248c904) (logid:cc51d465) Current user logged in under America/Chicago timezone
2024-10-30 14:52:20,253 INFO  [c.c.a.ApiServer] (qtp364604394-595:ctx-3248c904) (logid:cc51d465) Timezone offset from UTC is: -5.0

2024-10-30 14:52:20,390 DEBUG [c.c.a.ApiServlet] (qtp364604394-318:ctx-40905d41) (logid:cb70f222) ===START===  10.8.0.1 -- GET  command=listZones&response=json
2024-10-30 14:52:20,391 DEBUG [c.c.a.ApiServlet] (qtp364604394-318:ctx-40905d41) (logid:cb70f222) Two factor authentication is already verified for the user 2, so skipping
2024-10-30 14:52:20,393 DEBUG [c.c.a.ApiSessionListener] (qtp364604394-318:ctx-40905d41) (logid:cb70f222) Session destroyed by Id : node0ujszoa88moju1brtuz34u2paj1 , session: Session@632d4db3{id=node0ujszoa88moju1brtuz34u2paj1,x=node0ujszoa88moju1brtuz34u2paj1.node0,req=1,res=true} , source: Session@632d4db3{id=node0ujszoa88moju1brtuz34u2paj1,x=node0ujszoa88moju1brtuz34u2paj1.node0,req=1,res=true} , event: javax.servlet.http.HttpSessionEvent[source=Session@632d4db3{id=node0ujszoa88moju1brtuz34u2paj1,x=node0ujszoa88moju1brtuz34u2paj1.node0,req=1,res=true}]
2024-10-30 14:52:20,397 DEBUG [c.c.a.ApiServlet] (qtp364604394-318:ctx-40905d41) (logid:cb70f222) ===END===  10.8.0.1 -- GET  command=listZones&response=json
2024-10-30 14:52:20,401 DEBUG [c.c.a.ApiServlet] (qtp364604394-323:ctx-481244f3) (logid:7289069a) ===START===  10.8.0.1 -- GET  command=listApis&response=json
2024-10-30 14:52:20,402 DEBUG [c.c.a.ApiServer] (qtp364604394-323:ctx-481244f3 ctx-9502fd34) (logid:7289069a) Expired session, missing signature, or missing apiKey -- ignoring request. Signature: null, apiKey: null
2024-10-30 14:52:20,402 DEBUG [c.c.a.ApiServlet] (qtp364604394-323:ctx-481244f3 ctx-9502fd34) (logid:7289069a) ===END===  10.8.0.1 -- GET  command=listApis&response=json

[DerekHarter]

Just a little more information. I notice that sometimes (not always) I get a java stacktrace associated with the Session destroyed, like the following. It indicates an IllegalStateException, invalid for read:

2024-10-30 15:06:27,563 DEBUG [c.c.a.ApiSessionListener] (qtp364604394-635:ctx-176e7103) (logid:c0e3d007) Session destroyed by Id : node0jlrmpu3vw5zgou5aknnkvv7x2 , session: Session@4e1702ef
{id=node0jlrmpu3vw5zgou5aknnkvv7x2,x=node0jlrmpu3vw5zgou5aknnkvv7x2.node0,req=2,res=true} , source: Session@4e1702ef{id=node0jlrmpu3vw5zgou5aknnkvv7x2,x=node0jlrmpu3vw5zgou5aknnkvv7x2.node0,
req=2,res=true} , event: javax.servlet.http.HttpSessionEvent[source=Session@4e1702ef{id=node0jlrmpu3vw5zgou5aknnkvv7x2,x=node0jlrmpu3vw5zgou5aknnkvv7x2.node0,req=2,res=true}]
2024-10-30 15:06:27,565 ERROR [c.c.a.ApiServlet] (qtp364604394-318:ctx-2b8e7a39) (logid:0fcc0327) unknown exception writing api response
java.lang.IllegalStateException: Invalid for read: id=node0jlrmpu3vw5zgou5aknnkvv7x2 created=1730318786848 accessed=1730318787559 lastaccessed=1730318787558 maxInactiveMs=3600000 expiry=1730
322387559
        at org.eclipse.jetty.server.session.Session.checkValidForRead(Session.java:689)
        at org.eclipse.jetty.server.session.Session.getAttribute(Session.java:712)
        at com.cloud.utils.HttpUtils.validateSessionKey(HttpUtils.java:124)
        at com.cloud.api.ApiServlet.invalidateHttpSessionIfNeeded(ApiServlet.java:534)
        at com.cloud.api.ApiServlet.processRequestInContext(ApiServlet.java:324)
        at com.cloud.api.ApiServlet$1.run(ApiServlet.java:152)
        at org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:55)
        at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:102)
        at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:52)
        at com.cloud.api.ApiServlet.processRequest(ApiServlet.java:149)
        at com.cloud.api.ApiServlet.doGet(ApiServlet.java:103)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:645)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:750)
        at org.eclipse.jetty.servlet.ServletHolder$NotAsync.service(ServletHolder.java:1450)
        at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:799)
        at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:554)
        at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)
        at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:600)
        at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
        at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:235)
        at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1624)
        at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233)
        at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1440)
        at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:188)
        at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:505)
        at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1594)
        at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:186)
        at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1355)
        at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
        at org.eclipse.jetty.server.handler.gzip.GzipHandler.handle(GzipHandler.java:772)
        at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:146)
        at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
        at org.eclipse.jetty.server.Server.handle(Server.java:516)
        at org.eclipse.jetty.server.HttpChannel.lambda$handle$1(HttpChannel.java:487)
        at org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:732)
        at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:479)
        at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:277)
        at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311)
        at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105)
        at org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.onFillable(SslConnection.java:555)
        at org.eclipse.jetty.io.ssl.SslConnection.onFillable(SslConnection.java:410)
        at org.eclipse.jetty.io.ssl.SslConnection$2.succeeded(SslConnection.java:164)
        at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105)
        at org.eclipse.jetty.io.ChannelEndPoint$1.run(ChannelEndPoint.java:104)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:338)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:315)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:173)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:131)
        at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:409)
        at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:883)
        at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1034)
        at java.base/java.lang.Thread.run(Thread.java:829)

[weizhouapache]

hi @DerekHarter
Can you refer to #9848 and #9856 ?

Workaround could be
#9848 (comment)

[DerekHarter]

Hi thanks, yes I hadn't seen that.

Just checked and looks like that setting is already false for me:

(tlc) 🐱 > list configurations name=enable.secure.session.cookie
{
  "configuration": [
    {
      "category": "Advanced",
      "component": "ApiServer",
      "defaultvalue": "false",
      "description": "Session cookie is marked as secure if this is enabled. Secure cookies only work when HTTPS is used.",
      "displaytext": "Enable secure session cookie",
      "group": "Management Server",
      "isdynamic": false,
      "name": "enable.secure.session.cookie",
      "subgroup": "Security",
      "type": "Boolean",
      "value": "false"
    }
  ],
  "count": 1
}

But I tried anyway

(tlc) 🐱 > update configuration set value='false' where name='enable.secure.session.cookie'
{
  "configuration": {
    "category": "Advanced",
    "component": "ApiServer",
    "defaultvalue": "false",
    "description": "Session cookie is marked as secure if this is enabled. Secure cookies only work when HTTPS is used.",
    "displaytext": "Enable secure session cookie",
    "group": "Management Server",
    "isdynamic": false,
    "name": "enable.secure.session.cookie",
    "subgroup": "Security",
    "type": "Boolean",
    "value": "false"
  }
}

and restarted cloudstack-management service, and that did solve my issue as well. So thanks, though not sure what changed there, but we do have access again.

[weizhouapache]

probably just a browser/caching issue
anyway, it is good the issue is resolved.