Cumulocity - CumulocityLongPollingTransport Idle

Question

I'm using the 7.40.0 Cumulocity Java Client SDK to subscribe to real-time notifications. I'm able to get notifications but after leaving the client running for a while, it seems to stop listening and I'm no longer able to retrieve notifications.

Has anyone encountered this scenario?

WARN  2017-01-03 08:44:49,727 [CumulocityLongPollingTransport-scheduler-0] com.cumulocity.sdk.client.notification.ConnectionHeartBeatWatcher: canceling the long poll request because of inactivity
DEBUG 2017-01-03 08:44:49,727 [CumulocityLongPollingTransport-scheduler-0] com.cumulocity.sdk.client.notification.MessageExchange: canceling [{clientId=4b11irnlptb55g4rs3hauu1ctjpy, channel=/meta/connect, id=16, connectionType=long-polling}]
DEBUG 2017-01-03 08:44:49,727 [CumulocityLongPollingTransport-scheduler-0] com.cumulocity.sdk.client.notification.MessageExchange: stopping heartbeat watcher [{clientId=4b11irnlptb55g4rs3hauu1ctjpy, channel=/meta/connect, id=16, connectionType=long-polling}]
DEBUG 2017-01-03 08:44:50,728 [pool-21-thread-1] com.cumulocity.sdk.client.notification.CumulocityLongPollingTransport.1365985548: sending messages [{clientId=4b11irnlptb55g4rs3hauu1ctjpy, advice={timeout=0}, channel=/meta/connect, id=19, connectionType=long-polling}] 
DEBUG 2017-01-03 08:44:50,728 [pool-21-thread-1] com.cumulocity.sdk.client.notification.MessageExchange: starting heartbeat watcher [{clientId=4b11irnlptb55g4rs3hauu1ctjpy, advice={timeout=0}, channel=/meta/connect, id=19, connectionType=long-polling}]
DEBUG 2017-01-03 08:44:51,710 [CumulocityLongPollingTransport-scheduler-1] com.cumulocity.sdk.client.notification.MessageExchange: wait for response headers [{clientId=4b11irnlptb55g4rs3hauu1ctjpy, advice={timeout=0}, channel=/meta/connect, id=19, connectionType=long-polling}]
DEBUG 2017-01-03 08:44:51,710 [CumulocityLongPollingTransport-scheduler-1] com.cumulocity.sdk.client.notification.MessageExchange: recived response headers [{clientId=4b11irnlptb55g4rs3hauu1ctjpy, advice={timeout=0}, channel=/meta/connect, id=19, connectionType=long-polling}] 
DEBUG 2017-01-03 08:44:51,710 [CumulocityLongPollingTransport-scheduler-1] com.cumulocity.sdk.client.notification.MessageExchange: getting heartbeants  POST https://msc.cumulocity.com//cep/realtime returned a response status of 200 OK
DEBUG 2017-01-03 08:44:51,710 [CumulocityLongPollingTransport-scheduler-1] com.cumulocity.sdk.client.notification.MessageExchange: new messages recived
DEBUG 2017-01-03 08:44:51,711 [CumulocityLongPollingTransport-scheduler-1] com.cumulocity.sdk.client.notification.MessageExchange: Received messages [{channel=/meta/connect, id=19, advice={reconnect=retry, interval=0, timeout=5400000}, successful=true}]
DEBUG 2017-01-03 08:44:51,711 [CumulocityLongPollingTransport-scheduler-1] com.cumulocity.sdk.client.notification.MessageExchange: stopping heartbeat watcher [{clientId=4b11irnlptb55g4rs3hauu1ctjpy, advice={timeout=0}, channel=/meta/connect, id=19, connectionType=long-polling}]
DEBUG 2017-01-03 08:44:51,711 [pool-21-thread-1] com.cumulocity.sdk.client.notification.CumulocityLongPollingTransport.1365985548: sending messages [{clientId=4b11irnlptb55g4rs3hauu1ctjpy, channel=/meta/connect, id=23, connectionType=long-polling}] 
DEBUG 2017-01-03 08:44:51,711 [pool-21-thread-1] com.cumulocity.sdk.client.notification.MessageExchange: starting heartbeat watcher [{clientId=4b11irnlptb55g4rs3hauu1ctjpy, channel=/meta/connect, id=23, connectionType=long-polling}]
DEBUG 2017-01-03 08:56:51,711 [CumulocityLongPollingTransport-scheduler-0] com.cumulocity.sdk.client.notification.MessageExchange: canceling [{clientId=4b11irnlptb55g4rs3hauu1ctjpy, channel=/meta/connect, id=23, connectionType=long-polling}]
DEBUG 2017-01-03 08:56:51,711 [CumulocityLongPollingTransport-scheduler-0] com.cumulocity.sdk.client.notification.MessageExchange: stopping heartbeat watcher [{clientId=4b11irnlptb55g4rs3hauu1ctjpy, channel=/meta/connect, id=23, connectionType=long-polling}]
DEBUG 2017-01-03 08:56:52,711 [pool-21-thread-1] com.cumulocity.sdk.client.notification.CumulocityLongPollingTransport.1365985548: sending messages [{clientId=4b11irnlptb55g4rs3hauu1ctjpy, advice={timeout=0}, channel=/meta/connect, id=26, connectionType=long-polling}] 
DEBUG 2017-01-03 08:56:52,712 [pool-21-thread-1] com.cumulocity.sdk.client.notification.MessageExchange: starting heartbeat watcher [{clientId=4b11irnlptb55g4rs3hauu1ctjpy, advice={timeout=0}, channel=/meta/connect, id=26, connectionType=long-polling}]
DEBUG 2017-01-03 08:56:53,659 [CumulocityLongPollingTransport-scheduler-0] com.cumulocity.sdk.client.notification.MessageExchange: wait for response headers [{clientId=4b11irnlptb55g4rs3hauu1ctjpy, advice={timeout=0}, channel=/meta/connect, id=26, connectionType=long-polling}]
DEBUG 2017-01-03 08:56:53,659 [CumulocityLongPollingTransport-scheduler-0] com.cumulocity.sdk.client.notification.MessageExchange: recived response headers [{clientId=4b11irnlptb55g4rs3hauu1ctjpy, advice={timeout=0}, channel=/meta/connect, id=26, connectionType=long-polling}] 
DEBUG 2017-01-03 08:56:53,659 [CumulocityLongPollingTransport-scheduler-0] com.cumulocity.sdk.client.notification.MessageExchange: getting heartbeants  POST https://msc.cumulocity.com//cep/realtime returned a response status of 200 OK
DEBUG 2017-01-03 08:56:53,660 [CumulocityLongPollingTransport-scheduler-0] com.cumulocity.sdk.client.notification.MessageExchange: new messages recived
DEBUG 2017-01-03 08:56:53,661 [CumulocityLongPollingTransport-scheduler-0] com.cumulocity.sdk.client.notification.MessageExchange: Received messages [{channel=/meta/connect, id=26, advice={reconnect=retry, interval=0, timeout=5400000}, successful=true}]
DEBUG 2017-01-03 08:56:53,661 [CumulocityLongPollingTransport-scheduler-0] com.cumulocity.sdk.client.notification.MessageExchange: stopping heartbeat watcher [{clientId=4b11irnlptb55g4rs3hauu1ctjpy, advice={timeout=0}, channel=/meta/connect, id=26, connectionType=long-polling}]
DEBUG 2017-01-03 08:56:53,661 [pool-21-thread-1] com.cumulocity.sdk.client.notification.CumulocityLongPollingTransport.1365985548: sending messages [{clientId=4b11irnlptb55g4rs3hauu1ctjpy, channel=/meta/connect, id=28, connectionType=long-polling}] 
DEBUG 2017-01-03 08:56:53,661 [pool-21-thread-1] com.cumulocity.sdk.client.notification.MessageExchange: starting heartbeat watcher [{clientId=4b11irnlptb55g4rs3hauu1ctjpy, channel=/meta/connect, id=28, connectionType=long-polling}]

Answer 1

I have experienced the same. Apparently in our case some middlebox dropped the long-polling TCP connection before the server sent the keepalive packet (by default after 10 minutes).

Futhermore, when testing with 7.26 version the Java reference agent we saw that if the agent did not receive the server-side keepalives, it stopped re-establishing the long-polling connection after three attempts. Haven't checked if this has changed in later releases.

We run our own instance of Cumulocity, and are able to configure the server side keepalive timer. We set the keepalive timer to 3 minutes which solved the issue.

Answer 2

This kind of scenario can happen when you have intermediate network equipment that is configured to drop or cut network traffic for long lasting connections. Examples are corporate HTTP proxies, but also mobile network providers may have such configurations.

This is difficult to troubleshoot, often you have to go on low-level wireshark or network protocol means. We had success with the following mechanisms:

• Use a different network, e.g., direct DSL line instead of corporate Intranet.
• Raise a ticket with your IT or the network provider to not cut connections too early or not drop packets.
• If you are running Cumulocity yourself, you can configure it to send server-side heartbeats more frequently. That makes intermediate network equipment regard the connection as live, but at the expense of additional traffic for all clients.
• Use the MQTT API and set a higher ping rate.

Sorry for no easy answers here :-)