Client Application stops receiving messages after processing 2-3 million messages

[sumit-k-aggarwal]

Hi, We have been doing some performance testing and facing an issue almost on daily basis. After close to 2-3 million message processing via MQTT broker using AWS Java based Client SDK, our application stops receiving messages. In CloudWatch Management Logs we are able to see below messages.

Please provide inputs why this may be happening. We are Using AWSIOT Connect with timeout and Subscribe method with timeout and blocking as shown below:

awsIotClient.connect(timeout); if(logger.isDebugEnabled()) { logger.debug("Successfully Connected to AWS Broker");
} awsIotClient.subscribe(mqttMessageCallback, timeout, blocking);

-Sumit

[liuszeng]

Hi @Sumit-IOT ,

Thank you very much for your interest in AWS IoT Device SDK for Java.

From the cloudwatch logs, it seems that there was a client side disconnect. It could be either an explicit client MQTT DISCONNECT request or a socket closure. Do you have any client-side SDK logs when the issue happened? At the same time, I want to confirm the following client configuration details:

1. What type of authentication you are using here, X.509 certificate based mutual auth., or WebSocket with SigV4?
2. What is the keep-alive interval you are using?
3. Other than connect and subscribe, is the client doing anything else?

Thanks, Liusu

[sumit-k-aggarwal]

Hi Liusu,

There is no explicit disconnect call initiated from Client Application. Since application up and running even when application not receiving any message from Broker, so i am assuming no Shut down hook invoked to disconnect even if it is written within AWS SDK. So no code base known to me calling disconnect request from Client. But yes you are right logs reflects a disconnect initiated from client machine only. I dont have any Client side SDK logs, I can get it enabled if you can specify exact package name which i will utilize in log4j settings. Please try to limit number of SDK classes wherein you want logging. Publisher sending messages at the rate of 20ms so it would lead to huge logging statements which i want to limit.

Client configuration details: 1) WebSocket with SigV4. 2) Not setting explicitly. So Default as 30000 ms. 3) Connect and Subscribe... Message being listened, processed and job done. Since using blocking api so even few callBack methods not in use.

Please see attached ThreadDump if it helps. AWS.log

[sumit-k-aggarwal]

Additional details for you, please see below logs:

Dec 18, 2017 5:48:12 AM com.amazonaws.services.iot.client.core.AwsIotConnection onConnectionSuccess INFO: Connection successfully established Dec 18, 2017 5:48:12 AM com.amazonaws.services.iot.client.core.AbstractAwsIotClient onConnectionSuccess INFO: Client connection active: XXXXXSubscriber Dec 19, 2017 5:48:12 AM com.amazonaws.services.iot.client.core.AwsIotConnection onConnectionFailure INFO: Connection temporarily lost Dec 19, 2017 5:48:12 AM com.amazonaws.services.iot.client.core.AbstractAwsIotClient onConnectionFailure INFO: Client connection lost: XXXXXSubscriber Dec 19, 2017 5:48:15 AM com.amazonaws.services.iot.client.core.AwsIotConnection$1 run INFO: Connection is being retried Dec 19, 2017 5:48:15 AM com.amazonaws.services.iot.client.core.AbstractAwsIotClient onConnectionClosed INFO: Client connection closed: XXXXXSubscriber

[sumit-k-aggarwal]

Just FYI, we are not setting different properties like maxConnectionRetries etc. So default values are being used.

[sumit-k-aggarwal]

I have some more updates for you: I ran two different application instances pointed to be same broker, different Client Ids and different Topic Names as well.

1st instance errors:

Dec 19, 2017 6:26:42 AM com.amazonaws.services.iot.client.core.AwsIotConnection onConnectionSuccess INFO: Connection successfully established Dec 19, 2017 6:26:42 AM com.amazonaws.services.iot.client.core.AbstractAwsIotClient onConnectionSuccess INFO: Client connection active: ABCDSubscriber Dec 19, 2017 6:26:42 AM com.amazonaws.services.iot.client.core.AbstractAwsIotClient dispatch WARNING: Unexpected message received from topic XYZORG_IOT_Test Dec 20, 2017 6:26:42 AM com.amazonaws.services.iot.client.core.AwsIotConnection onConnectionFailure INFO: Connection temporarily lost Dec 20, 2017 6:26:42 AM com.amazonaws.services.iot.client.core.AbstractAwsIotClient onConnectionFailure INFO: Client connection lost: ABCDSubscriber Dec 20, 2017 6:26:45 AM com.amazonaws.services.iot.client.core.AwsIotConnection$1 run INFO: Connection is being retried Dec 20, 2017 6:26:45 AM com.amazonaws.services.iot.client.core.AbstractAwsIotClient onConnectionClosed INFO: Client connection closed: ABCDSubscriber

2nd Instance errors: Dec 20, 2017 4:54:02 AM com.amazonaws.services.iot.client.core.AwsIotConnection onConnectionSuccess INFO: Connection successfully established Dec 20, 2017 4:54:02 AM com.amazonaws.services.iot.client.core.AbstractAwsIotClient onConnectionSuccess INFO: Client connection active: ABCDSubscriber_Client_Test Dec 20, 2017 3:12:32 PM org.eclipse.paho.client.mqttv3.internal.ClientState checkForActivity SEVERE: ABCDSubscriber_Client_Test: Timed out as no activity, keepAlive=30,000 lastOutboundActivity=1,513,800,722,781 lastInboundActivity=1,513,800,692,873 time=1,513,800,752,781 lastPing=1,513,800,722,781 (END)

To summarize, 2nd instance was up and running without any disconnection while 1st instance got disconnected with Broker at Dec 20, 2017 6:26:45 AM. 2nd Instance went down after time out due to inactivity at Dec 20, 2017 3:12:32 PM only.

So for sure AWT MQTT connection has not been disconnected or there is no network glitch as well. In my view specific Topic got disconnected only. Somehow is this due to some-type of AWS SDK internal limits imposed on number of messages processed by Broker on a topic at 1 run-time ? Is this related to AWS MQTT metering ?

Additionally there is no error message reporting in retryConnection() method of AwsIotConnection class. If error reporting would have present it would be easier to find why while retrying connection, it got failed.

-Sumit

[sumit-k-aggarwal]

I think i have found the issue, it is related to Issue #39. I made a change in retryConnection() of AwsIotConnection to log the error reported by openConnection(null) method.

Now see logs: Dec 21, 2017 4:09:16 AM com.amazonaws.services.iot.client.core.AwsIotConnection onConnectionSuccess INFO: Connection successfully established Dec 21, 2017 4:09:16 AM com.amazonaws.services.iot.client.core.AwsIotConnection onConnectionSuccess INFO: new Connection successfully established Dec 21, 2017 4:09:16 AM com.amazonaws.services.iot.client.core.AbstractAwsIotClient onConnectionSuccess INFO: Client connection active: ABCDSubscriber Dec 22, 2017 4:09:17 AM com.amazonaws.services.iot.client.core.AwsIotConnection onConnectionFailure INFO: Connection temporarily lost Dec 22, 2017 4:09:17 AM com.amazonaws.services.iot.client.core.AbstractAwsIotClient onConnectionFailure INFO: Client connection lost: ABCDSubscriber Dec 22, 2017 4:09:20 AM com.amazonaws.services.iot.client.core.AwsIotConnection$1 run INFO: Connection is being retried com.amazonaws.services.iot.client.AWSIotException: MqttException (0) - java.io.IOException: Invalid keystore format Dec 22, 2017 4:09:20 AM com.amazonaws.services.iot.client.core.AwsIotConnection$1 run WARNING: Error : MqttException (0) - java.io.IOException: Invalid keystore format Dec 22, 2017 4:09:20 AM com.amazonaws.services.iot.client.core.AbstractAwsIotClient onConnectionClosed INFO: Client connection closed: ABCDSubscriber

Log clearly suggests, While re-connection, it falls into trap of Issue #39. FYI, i am using below code to resolve Issue#39 :+1: System.clearProperty("javax.net.ssl.trustStore"); awsIotClient.connect(timeout); awsIotClient.subscribe(mqttMessageCallback, timeout, blocking); System.setProperty("javax.net.ssl.trustStore", trustStore);

Hi @fengsongAWS , can you please review this ticket and provide your inputs.

[fengsongAWS]

Hi @Sumit-IOT , If I am understanding correctly, you modify the retry connection logic. Did this have anything related to the changes you made?

[github-actions[bot]]

Greetings! Sorry to say but this is a very old issue that is probably not getting as much attention as it deservers. We encourage you to check if this is still an issue in the latest release and if you find that this is still a problem, please feel free to open a new one.