Getting NullPointerException on receiving /meta/subscribe message about cometd HOT 5 CLOSED

This is very strange because the call to notifyOnMessage() is protected by an instanceof check in notifyMessageListeners(), so the listener can never be null.

If you have further information please comment on this issue.

from cometd.

Hi, I have some more information on this. I managed to get the sequence where it happened. Here it goes:

We have a listener connected to Salesforce. Time to time we get the "Unknown client" error which happens due to expiry of cookie and CometD always reconnects itself. But here the case was little different.

First we got the "Unknown client" error:

2024-01-18 05:18:09.465 UTC [CHANNEL:META_CONNECT:myListener]: {"advice":{"reconnect":"handshake","interval":0},"channel":"/meta/connect","id":"1156557","error":"403::Unknown client","successful":false}

CometD client started recoverying, but after successful calls of /meta/handshake & /meta/subscribe, the /meta/connect call failed again with "Unknown client" error. This is unexpected and never seen before. Could be some issue with the backend, but we are not sure, we will need to enable Jetty client log to confirm on this.

2024-01-18 05:18:09.567 UTC [CHANNEL:META_HANDSHAKE:myListener]: {"ext":{"replay":true,"payload.format":true},"minimumVersion":"1.0","clientId":"919pvb1azk1d141wbi2vlmr4kx0","supportedConnectionTypes":["long-polling"],"channel":"/meta/handshake","id":"1156558","version":"1.0","successful":true}

2024-01-18 05:18:09.868 UTC [CHANNEL:META_SUBSCRIBE:myListener]: {"clientId":"919pvb1azk1d141wbi2vlmr4kx0","channel":"/meta/subscribe","id":"1156559","subscription":"/data/CaseChangeEvent","successful":true}

2024-01-18 05:18:09.983 UTC
[CHANNEL:META_CONNECT:myListener]: {"advice":{"reconnect":"handshake","interval":0},"channel":"/meta/connect","id":"1156560","error":"403::Unknown client","successful":false}

As the /meta/connect failed, the CometD client tried to initiate the subscription again. Here the /meta/connect failed again with "Unknown client", but /meta/subscribe took little longer than before and the call came back after /meta/connect failed. Generally we have seen that first /meta/subscribe returns on which we initiate /meta/subscrtibe which returns and then /meta/connect returns, as we have seen in the 1st retry.

2024-01-18 05:18:10.081 UTC
[CHANNEL:META_HANDSHAKE:myListener]: {"ext":{"replay":true,"payload.format":true},"minimumVersion":"1.0","clientId":"919pvb1azk1d141wbi2vlmr4kx0","supportedConnectionTypes":["long-polling"],"channel":"/meta/handshake","id":"1156563","version":"1.0","successful":true}

2024-01-18 05:18:10.168 UTC
[CHANNEL:META_CONNECT:myListener]: {"advice":{"reconnect":"handshake","interval":0},"channel":"/meta/connect","id":"1156565","error":"403::Unknown client","successful":false}

2024-01-18 05:18:10.194 UTC
[CHANNEL:META_SUBSCRIBE:myListener]: {"clientId":"919pvb1azk1d141wbi2vlmr4kx0","channel":"/meta/subscribe","id":"1156564","subscription":"/data/CaseChangeEvent","successful":true}

As the /meta/connect failed (again), CometD client again tried to establish the connection. Now the /meta/handshake came back sucess and /meta/subscribe initiated. Before /meta/subscribe returned, /meta/connect returned succsess, but /meta/subscribe failed with the reported NullPointerException.

2024-01-18 05:18:10.265 UTC
[CHANNEL:META_HANDSHAKE:myListener]: {"ext":{"replay":true,"payload.format":true},"minimumVersion":"1.0","clientId":"81ebslhazswyfa8tvndislr8rk","supportedConnectionTypes":["long-polling"],"channel":"/meta/handshake","id":"1156566","version":"1.0","successful":true}

2024-01-18 05:18:10.351 UTC
[CHANNEL:META_CONNECT:myListener]: {"clientId":"81ebslhazswyfa8tvndislr8rk","advice":{"reconnect":"retry","interval":0,"timeout":110000},"channel":"/meta/connect","id":"1156568","successful":true}

2024-01-18 05:18:10.355 UTC
[CHANNEL:META_SUBSCRIBE:myListener]: {"failure":{"exception":"java.lang.NullPointerException","message":{"ext":{"replay":{"/data/CaseChangeEvent":2108855}},"clientId":"81ebslhazswyfa8tvndislr8rk","channel":"/meta/subscribe","id":"1156567","subscription":"/data/CaseChangeEvent"},"connectionType":"long-polling"},"channel":"/meta/subscribe","id":"1156567","subscription":"/data/CaseChangeEvent","successful":false}

There could be issue with the backend as we never seen the /meta/connect failed with "Unknown client" on fresh subscription. This issue we started seeing recently. We have fail safe mechanism by which we are able to re-connect the listener. But I just wanted to report the issue to make you aware.

Currently I have only this much. It is hard to reprduce and we are not able to enable the debug log in production. But if you need more traces please let me know, I will try my best to gather logs from both CometD and Jetty in debug mode.

• thanks

from cometd.

@dyutiman thanks for the detailed report, and yes, I am afraid this is a server-side issue.

Perhaps can you try this workaround: when you see a /meta/connect response with successful=false, try to completely disconnect CometD via a call to disconnect(), and then try to handshake again, and see if it works better.

I recommend that you contact SalesForce and report the issue to them.
Just to be clear, the server side cannot accept a subscription for clientId=919pvb1azk1d141wbi2vlmr4kx0 if the correspondent /meta/connect fails with unknown client.

Having said that, CometD should avoid the NPE. I'll try to replicate it and fix the NPE.

from cometd.

@dyutiman this is the same issue as #1229, which has been fixed in 7.0.11, so the NPE can be avoided by upgrading to the latest CometD.

However, there is not much that we can do regarding the server-side behavior, for which you have to contact SalesForce.

from cometd.

Thanks a lot @sbordet for looking into it.

We do have a mechanism to disconnect and reconnect the client only when the /meta/connect error is not "Unknown client". In this case CometD itself reconnect itself.

And I believe if we upgrade the library we do not have to disconnect and reconnect for "Unknon client". Our reconnect logic does not need to change then.

I will check how soon we can upgrade.

• thanks

from cometd.