Glacier2 session expires even though heartbeat is enabled

[j-w-jones]

Hi,

I have a web site client communicating via Glacier to a C++ server (all using Ice 3.7.9). On the client I have ACM enabled with a timeout of 60 seconds and I have set a Glacier session timeout of 1 hour. I can see in the Chrome console and the Glacier logs that a heartbeat message is sent every 30 seconds - as expected.

However, if I don't interact with the server (i.e. call any methods on the server) the session still expires after the 1 hour. I thought if Glacier received heartbeats it would stop the session expiring.

What have I done wrong?

Thanks,

Jason

[pepone]

Hi Jason,

The session might also expire if the connection to the server is closed or lost. However, you don't need to set an excessively large Glacier2 session timeout. The ACM heartbeats should keep the session alive under normal circumstances. I recommend setting both the client ACM timeout and the Glacier2 session timeout to the same value, such as 60 seconds.

Additionally, it would be useful to enable protocol, and network tracing by setting Ice.Trace.Network=2 and Ice.Trace.Protocol=1 on both the client and Glacier2, and then attach the logs.

[j-w-jones]

Hi Jose

Thanks for getting back to me so quickly.

At the moment, the only reason for the long session timeout is because the heartbeats don't seem to be doing their job. So, for now, it allows me to carry on developing and testing my code.

I have set the network and protocol traces to the values you suggested and attached the log files. I also changed the session timeout to 300 so it would fail more quickly.

console_output.txt is from the client running on the web browser console
glacier_log.txt is the log from Glacier2. I also have IceGrid running to start the server processes so there are some messages coming from IceGrid in this log file.
ProjectServer_3_ice.txt is the log file from the server. My client is not talking to the server at this point so it must be Glacier/IceGrid sending these heartbeats. I'll investigate this further in the morning.

Everything is running on the same host so the timestamps will be synchronised almost perfectly.

As you can see, there are heartbeat messages being sent every 30 seconds and received by Glacier and then after 5 minutes, Glacier closes the session.

Any help would be appreciated and if you need anything else then please let me know.

Jason

console_output.txt
glacier_log.txt
ProjectServer_3_ice.txt

[pepone]

Glacier2 attempts to contact the session object each time it receives a heartbeat by sending a ping message. In the Glacier2 logs, it shows that this call is failing with “object not exists”. As a result of this failure, the session is being destroyed.

-- 09/19/24 21:18:30.870 C:/Program Files/ZeroC/Ice-3.7.9/bin/glacier2router.exe: Protocol: sending request 
   message type = 0 (request)
   compression status = 0 (not compressed; do not compress response, if any)
   message size = 81
   request id = 12
   identity = IceGrid/f2205c96-74dd-49fa-9f98-dec37a8c5afa
   facet = 
   operation = ice_ping
   mode = 1 (nonmutating)
   context = 
   encoding = 1.1
-- 09/19/24 21:18:30.873 C:/Program Files/ZeroC/Ice-3.7.9/bin/glacier2router.exe: Protocol: received reply 
   message type = 2 (reply)
   compression status = 0 (not compressed; do not compress response, if any)
   message size = 74
   request id = 12
   reply status = 2 (object not exist)
   identity = IceGrid/f2205c96-74dd-49fa-9f98-dec37a8c5afa
   facet = 
   operation = ice_ping
-- 09/19/24 21:18:30.873 C:/Program Files/ZeroC/Ice-3.7.9/bin/glacier2router.exe: Glacier2: destroying session
   id = WebSimTest
   category = _<%>zsflWMz|sj:D|+L~
   local address = ::ffff:127.0.0.1:4063
   remote address = ::ffff:127.0.0.1:50872

This suggests there is an issue with the session manager, the object is not longer alive, the fact that you get "object not exists" suggest that it was unregistered.

It would be easier to pinpoint the issue if you could provide some sample code for your session manager.

[j-w-jones]

I don't have a custom SessionManager. I have attached the complete config files for Glacier and IceGrid. (I've just noticed that the IceGrid SessionTimeout is still the 8200 seconds but since it fails at 300 seconds I guess that is not the issue right now).

The lines commented out with "#JJ" were commented out for the last set of log files I sent to you - just to try to simplify things.

During all of this, Glacier, IceGrid and the server stays running - nothing crashes.
glacier2-config.txt
grid-registry-node-config.txt

[pepone]

Hi Jason

Can you try enabling ACM in your Glacier2 configuration by setting:

Ice.ACM.Heartbeat=3
Ice.ACM.Timeout=30

IceGrid reaps sessions that doesn't get any heartbeats in the configured session timeout. The ping messages send by Glacier2 are not having the desired effect of keeping the session alive.

It seems this could be a bug in the IceGrid session manager. Sending a ping (or any other message) should be enough to keep the session alive. Enabling ACM on Glacier2 router should allow you to workaround the issue.

[j-w-jones]

Hi Jose

I've added that and it still closes rhe connection after 5 minutes.

I also enabled IceGrid logging to a file and enabled session tracing and I can see the messages being sent every 15 seconds. The log files are attached including the new IceGrid Registry/Node log file.

I then called the ice_ping() function on my server proxy from the client (through Glacier) at about 4 minutes and it didn't delay the connection closure.
I then tried calling one of my servers functions from the client at about 4 minutes and that didn't delay the closure either. It's all very strange.

chrome-console.txt
glacier2-config.txt
grid-registry-node-config.txt
log-ice-glacier.txt
log-ice-registry-node.txt

[pepone]

Hi Jason

are you using IceGrid/SessionManager on purpose, for example are you trying to allocate IceGrid server behind a Glacier2 router?

See https://doc.zeroc.com/ice/3.7/ice-services/icegrid/glacier2-integration-with-icegrid#Glacier2IntegrationwithIceGrid-ResourceAllocationusingGlacier2andIceGrid

There is a bug in the code that handle IceGrid Glacier2 sessions that is causing the session to be destroyed even if Glacier2 periodically pings the sessions.

[j-w-jones]

Hi Jose

I am using it on purpose - at least I think I am..

The structure of my application is as follows:

I have a farm of servers on a private network with one public server having two network interfaces - one for the private network and one for the Internet.

The public server runs a web server and Glacier (which span the two networks) and IceGrid (which is only accessible on the private network).
Essentially, users of the website can create tasks. These tasks are actually C++ apps that are started via IceGrid. The web browser communicates with these apps through an NGINX websocket proxy, and then through Glacier. This way, only the HTTPS port needs to be exposed to the world.

So, Glacier is used because the C++ apps run on a private network, and IceGrid is used to start these apps on the least loaded server on an as-needed basis. I use the "on-demand" feature of Icegrid to start the apps but never use IceGrid to stop idle apps - I do that by calling my own quit() function from the web server via the C++ apps Ice proxies when the web login session expires.

I hope that makes sense. Please let me know if not.

I have started creating a simple project (a C++ server and client, and config files for Glacier and Icegrid) that will, hopefully, give the same behaviour but be small enough to zip up and attach. Would that be useful to test for the bug you mentioned? Or is the issue already known and being investigated?

Thanks for all your help so far,

Jason

[pepone]

Hi Jason,

We were able to reproduce the issue with a setup that mimics your configuration, thanks for the details.

I have opened a PR with a fix for the 3.7 branch, see #2756
If you are comfortable building Ice from source you can test if it solves your issue.

It is not clear to me that you need to use IceGrid/SessionManager, if you are not using any of the operations defined in

ice/slice/IceGrid/Session.ice

Line 26 in 290d529

interface Session extends Glacier2::Session

you are likely to not need it, and you can probably use the default Glacier2 session manager

[j-w-jones]

Hi Jose

I tried removing the Glacier2.SessionManager=IceGrid/SessionManager entry but then the client couldn't create a Glacier session. This is probably because I have Ice.Default.Locator=IceGrid/Locator:tcp -p 4061.

And I think I need this because the proxies returned from IceGrid when it starts a new server need the Locator. But, again, I could be wrong.

I think I'll wait for a binary to become available - I'll just increase the SessionTimeout back up to a large value in the meantime.

Thanks for all your help with this.

Jason

[pepone]

What error do you get when trying to create the session? I don't think that setting the locator in Glacier2 is the problem here.

[j-w-jones]

I simply get a null session.. I have attached my latest config and logs as usual.

The client code is:

      let r = this._communicator.getDefaultRouter();
      console.log("Got default Router", r);

      this._router = await Glacier2.RouterPrx.checkedCast(r);
      this._connection = this._router.ice_getCachedConnection();

      console.log("Router Connection", this._connection);

      let session = await this._router.createSession("WebSimTest", "WebSimTest");
      console.log("Initialised Session as WebSimTest", session);

You can see in the chrome-console.txt - the final console.log prints null.

I have also attached a snapshot of the Connection object in Chrome.

chrome-console.txt
glacier2-config.txt
grid-registry-node-config.txt
log-ice-glacier.txt
log-ice-registry-node.txt

[pepone]

The default session manager returns a null session proxy, the router still maintains an internal session and calls should be correctly forwarded from Glacier2 to your servers.

[j-w-jones]

Wow.. You are a star!!
That works perfectly.. 😄😄
The connection is staying alive and everything still works even after I leave it idle for 20-30 minutes.