AWSIoTTopic constant disconnected/reconnected messages

[davidmco65]

Hi, I'm using the SDK on a Raspberry PI 3, Java 8 and having issues with listening on a Topic.

Basically, my code is:

public class TestTopicListener extends AWSIotTopic {

    public TestTopicListener(String topic, AWSIotQos qos) {
        super(topic, qos);
        System.out.println("Listener: Connecting to " + topic);
    }

    @Override
    public void onMessage(AWSIotMessage message) {
        System.out.println(System.currentTimeMillis() + ": <<< " + message.getStringPayload());
        if ( message.getStringPayload().equalsIgnoreCase("restart"))
                System.exit(0);
    }

}

And I'm just getting the following messages on the console:
Jul 19, 2016 11:07:07 AM com.amazonaws.services.iot.client.core.AwsIotConnection onConnectionFailure INFO: Connection temporarily lost Jul 19, 2016 11:07:07 AM com.amazonaws.services.iot.client.core.AbstractAwsIotClient onConnectionFailure INFO: Client connection lost: rpi001 Jul 19, 2016 11:07:10 AM com.amazonaws.services.iot.client.core.AwsIotConnection$1 run INFO: Connection is being retried Jul 19, 2016 11:07:11 AM com.amazonaws.services.iot.client.core.AwsIotConnection onConnectionSuccess INFO: Connection successfully established Jul 19, 2016 11:07:11 AM com.amazonaws.services.iot.client.core.AbstractAwsIotClient onConnectionSuccess INFO: Client connection active: rpi001 Jul 19, 2016 11:07:12 AM com.amazonaws.services.iot.client.mqtt.AwsIotMqttMessageListener onFailure WARNING: Request failed for topic $aws/things/rpi001/shadow/update: Connection lost (32109) - java.io.EOFException Jul 19, 2016 11:07:12 AM com.amazonaws.services.iot.client.core.AwsIotConnection onConnectionFailure INFO: Connection temporarily lost Jul 19, 2016 11:07:12 AM com.amazonaws.services.iot.client.core.AbstractAwsIotClient onConnectionFailure INFO: Client connection lost: rpi001 Jul 19, 2016 11:07:15 AM com.amazonaws.services.iot.client.core.AwsIotConnection$1 run INFO: Connection is being retried Jul 19, 2016 11:07:15 AM com.amazonaws.services.iot.client.core.AwsIotConnection onConnectionSuccess INFO: Connection successfully established
I'm subscribing to $aws/things/rpi001/shadow/update. It does seem like the very first message I publish on that topic from the client, the client also receives. But after that one, nothing...

The strange thing is that my publications to another topic seem to be working fine along with publishing to $aws/things/rpi001/shadow/update from the client. I'm seeing the updates in the IoT console.

Any help would be appreciated!

Thanks,
Mac

[rongsaws]

It looks like you have quite some connection errors, do you always get these errors when your application starts?

[davidmco65]

Yes, every time. I have figured out one thing, that I was subscribing to the wrong topic and I've fixed that. I now subscribe to $aws/things/rpi001/shadow/update/delta. And I also see java.io.EOFExceptions on the topic sometimes.

[rongsaws]

Do you start your application when the wifi or ethernet connection is just established? Do the errors also happen when the network connection is stable?

[davidmco65]

Mostly, I'm starting the application with the network connection well established. Like for hours. I still get the messages I publish on my app-specific topic, and pretty quickly. It seems to be just the subscriptions that have issues.

[davidmco65]

I have a thread running a blocking publish for heartbeat and it doesn't take long for that message to get published.

[rongsaws]

There are two things to rule out first when it comes to connection issues. One is client side issues, such as intermittent network issues; another one is server side disconnect, which can be caused by various reasons, such as policy violation, protocol violations and so on. Can you check your CloudWatch logs for IoT to see if you see any errors there? Another check worth doing is to do a packet capture using tcpdump on your rPi and check how the TCP connection is terminated. If you could share your packet capture file, I'm happy to take a look at it.

[davidmco65]

I don't believe there are client side network issues. I've had a PuTTY terminal running to this thing for hours on end without being disconnected.

I checked all log streams under AWSIotLogs and didn't see any errors. Every operation has status SUCCESS. Here's a part of the log:
2016-07-20 00:09:31.034 TRACEID:097a033d-8cf6-46a2-8b67-f1dcf046b062 PRINCIPALID:b439d9313e93f298792d0c2fc4b1bf682b39cbf512684cce03c3e21e7629ca87 [INFO] EVENT:PublishEvent TOPICNAME:scans MESSAGE:PublishIn Status: SUCCESS 2016-07-20 00:09:31.095 TRACEID:097a033d-8cf6-46a2-8b67-f1dcf046b062 PRINCIPALID:b439d9313e93f298792d0c2fc4b1bf682b39cbf512684cce03c3e21e7629ca87 [INFO] EVENT:MatchingRuleFound TOPICNAME:scans CLIENTID:rpi001 MESSAGE:Matching rule found: ToDynamo 2016-07-20 00:09:31.097 TRACEID:91b92373-a619-4671-93cb-249b45a30bcb PRINCIPALID:b439d9313e93f298792d0c2fc4b1bf682b39cbf512684cce03c3e21e7629ca87 [INFO] EVENT:MQTTClient Subscribe TOPICNAME:$aws/things/rpi001/shadow/update/delta MESSAGE:Subscribe Status: SUCCESS 2016-07-20 00:09:31.114 TRACEID:097a033d-8cf6-46a2-8b67-f1dcf046b062 PRINCIPALID:b439d9313e93f298792d0c2fc4b1bf682b39cbf512684cce03c3e21e7629ca87 [INFO] EVENT:MatchingRuleFound TOPICNAME:scans CLIENTID:rpi001 MESSAGE:Matching rule found: EmployeeScan 2016-07-20 00:09:31.117 TRACEID:097a033d-8cf6-46a2-8b67-f1dcf046b062 PRINCIPALID:b439d9313e93f298792d0c2fc4b1bf682b39cbf512684cce03c3e21e7629ca87 [INFO] EVENT:MatchingRuleFound TOPICNAME:scans CLIENTID:rpi001 MESSAGE:Matching rule found: SNS 2016-07-20 00:09:31.238 TRACEID:097a033d-8cf6-46a2-8b67-f1dcf046b062 PRINCIPALID:b439d9313e93f298792d0c2fc4b1bf682b39cbf512684cce03c3e21e7629ca87 [INFO] EVENT:LambdaActionSuccess TOPICNAME:scans CLIENTID:rpi001 MESSAGE:Successfully invoked lambda function. Message arrived on: scans, Action: lambda, Function: arn:aws:lambda:us-west-2:450017183792:function:ScanToDB StatusCode: 202, Function error: null 2016-07-20 00:09:31.698 TRACEID:097a033d-8cf6-46a2-8b67-f1dcf046b062 PRINCIPALID:b439d9313e93f298792d0c2fc4b1bf682b39cbf512684cce03c3e21e7629ca87 [INFO] EVENT:DynamoActionSuccess TOPICNAME:scans CLIENTID:rpi001 MESSAGE:Dynamo Insert record successful. Message arrived on: scans, Action: dynamo, Table: rawscans, HashKeyField: serialNumber, HashKeyValue: 818094003001, RangeKeyField: Some(clickType), RangeKeyValue: 1468973370995 2016-07-20 00:09:31.772 TRACEID:097a033d-8cf6-46a2-8b67-f1dcf046b062 PRINCIPALID:b439d9313e93f298792d0c2fc4b1bf682b39cbf512684cce03c3e21e7629ca87 [INFO] EVENT:SNSActionSuccess TOPICNAME:scans CLIENTID:rpi001 MESSAGE:Successfully published to SNS topic. Message arrived on: scans, Action: sns, Target Arn: arn:aws:sns:us-west-2:450017183792:BadEmails SNS Message Id: 15d79c0a-e1c0-5d96-b75c-cc0222bbedbe 2016-07-20 00:09:35.240 TRACEID:860faa2f-171c-4fae-8393-0d973b15a3f7 PRINCIPALID:b439d9313e93f298792d0c2fc4b1bf682b39cbf512684cce03c3e21e7629ca87 [INFO] EVENT:MQTT Client Connect MESSAGE:Connect Status: SUCCESS 2016-07-20 00:09:39.153 TRACEID:6ac02c75-1d8f-458e-bb6e-80b1eb4361b9 PRINCIPALID:b439d9313e93f298792d0c2fc4b1bf682b39cbf512684cce03c3e21e7629ca87 [INFO] EVENT:MQTT Client Connect MESSAGE:Connect Status: SUCCESS 2016-07-20 00:09:43.485 TRACEID:ca2dfde1-7b71-4dd7-b08b-100c9fd5f048 PRINCIPALID:b439d9313e93f298792d0c2fc4b1bf682b39cbf512684cce03c3e21e7629ca87 [INFO] EVENT:MQTT Client Connect MESSAGE:Connect Status: SUCCESS 2016-07-20 00:09:43.639 TRACEID:db8660ac-6cbc-4aa4-914c-f2f7b18379d9 PRINCIPALID:b439d9313e93f298792d0c2fc4b1bf682b39cbf512684cce03c3e21e7629ca87 [INFO] EVENT:MQTTClient Subscribe TOPICNAME:$aws/things/rpi001/shadow/update/delta MESSAGE:Subscribe Status: SUCCESS 2016-07-20 00:10:48.998 TRACEID:cb3fc6f5-345a-4912-a520-95d472c2dc64 PRINCIPALID:b439d9313e93f298792d0c2fc4b1bf682b39cbf512684cce03c3e21e7629ca87 [INFO] EVENT:MQTT Client Connect MESSAGE:Connect Status: SUCCESS 2016-07-20 00:10:49.064 TRACEID:d4737d74-9ced-4032-9d51-f7e6944ac0bc PRINCIPALID:b439d9313e93f298792d0c2fc4b1bf682b39cbf512684cce03c3e21e7629ca87 [INFO] EVENT:PublishEvent TOPICNAME:$aws/things/rpi001/shadow/update MESSAGE:PublishIn Status: SUCCESS 2016-07-20 00:10:49.215 TRACEID:a19bbb83-f0c9-48d1-a90a-73cffec9235e PRINCIPALID:b439d9313e93f298792d0c2fc4b1bf682b39cbf512684cce03c3e21e7629ca87 [INFO] EVENT:MQTTClient Subscribe TOPICNAME:$aws/things/rpi001/shadow/update/delta MESSAGE:Subscribe Status: SUCCESS 2016-07-20 00:10:53.500 TRACEID:8910f598-6da0-4775-8b1b-738a5c77474d PRINCIPALID:b439d9313e93f298792d0c2fc4b1bf682b39cbf512684cce03c3e21e7629ca87 [INFO] EVENT:MQTT Client Connect MESSAGE:Connect Status: SUCCESS 2016-07-20 00:10:53.722 TRACEID:8a646829-7d95-475a-87d9-a7dba53f7cd6 PRINCIPALID:b439d9313e93f298792d0c2fc4b1bf682b39cbf512684cce03c3e21e7629ca87 [INFO] EVENT:MQTTClient Subscribe TOPICNAME:$aws/things/rpi001/shadow/update/delta MESSAGE:Subscribe Status: SUCCESS 2016-07-20 00:10:58.387 TRACEID:e706b5a0-3582-436c-a269-189d94f53156 PRINCIPALID:b439d9313e93f298792d0c2fc4b1bf682b39cbf512684cce03c3e21e7629ca87 [INFO] EVENT:MQTT Client Connect MESSAGE:Connect Status: SUCCESS 2016-07-20 00:10:58.726 TRACEID:420368d9-5489-49f8-a23e-66305c3963e9 PRINCIPALID:b439d9313e93f298792d0c2fc4b1bf682b39cbf512684cce03c3e21e7629ca87 [INFO] EVENT:MQTTClient Subscribe TOPICNAME:$aws/things/rpi001/shadow/update/delta MESSAGE:Subscribe Status: SUCCESS 2016-07-20 00:11:03.272 TRACEID:a3fd5cd1-e017-421d-8229-5c752e94e77c PRINCIPALID:b439d9313e93f298792d0c2fc4b1bf682b39cbf512684cce03c3e21e7629ca87 [INFO] EVENT:MQTT Client Connect MESSAGE:Connect Status: SUCCESS
I'll look into doing the packet capture as well.

Thanks!
Mac

[rongsaws]

Do you have two devices or two copies of application running using the same client Id to connect to AWS IoT?

[davidmco65]

No, only one. Sometimes I'll connect the Mqtt Client on the console, but most of the time, I'm not using that.

[rongsaws]

From the ClouldWatch log, there were multiple connects for a short period, with 4 or 5 seconds apart. Did you set a very short keep-alive (https://github.com/aws/aws-iot-device-sdk-java/blob/master/aws-iot-device-sdk-java/src/main/java/com/amazonaws/services/iot/client/AWSIotConfig.java#L47) interval? Could you try the sample applications and see if you can reproduce the errors?

[davidmco65]

I didn't set any keep-alive or other timeouts/intervals at all, just using defaults. I'll try with a 30-second keep-alive in a few minutes.

[davidmco65]

Well, that did it! Seems like maybe the default keep-alive shouldn't be 0?

Thanks so much for your help!!

Mac

[rongsaws]

Hmmm, the default keep-alive interval is 30s - https://github.com/aws/aws-iot-device-sdk-java/blob/master/aws-iot-device-sdk-java/src/main/java/com/amazonaws/services/iot/client/core/AbstractAwsIotClient.java#L56, you should't need to set it if you didn't change it.

How did you initialize the client?

[davidmco65]

That's the only change I made to make it work. Here's my init code, but it's all directly from the PubSub sample that came with the SDK.

String clientEndpoint = arguments.getNotNull("clientEndpoint", SampleUtil.getConfig("clientEndpoint"));
        String clientId = arguments.getNotNull("clientId", SampleUtil.getConfig("clientId"));
        System.out.println("### Endpoint: " + clientEndpoint);
        System.out.println("### ClientID: " + clientId);

        String certificateFile = arguments.get("certificateFile", SampleUtil.getConfig("certificateFile"));
        String privateKeyFile = arguments.get("privateKeyFile", SampleUtil.getConfig("privateKeyFile"));
        if (awsIotClient == null && certificateFile != null && privateKeyFile != null)
        {
            String algorithm = arguments.get("keyAlgorithm", SampleUtil.getConfig("keyAlgorithm"));
            KeyStorePasswordPair pair = SampleUtil.getKeyStorePasswordPair(certificateFile, privateKeyFile, algorithm);

            awsIotClient = new AWSIotMqttClient(clientEndpoint, clientId, pair.keyStore, pair.keyPassword);
            System.out.println("Got awsIoTClient using key pair");
            awsIotClient.setKeepAliveInterval(30);
        }

        if (awsIotClient == null)
        {
            String awsAccessKeyId = arguments.get("awsAccessKeyId", SampleUtil.getConfig("awsAccessKeyId"));
            String awsSecretAccessKey = arguments.get("awsSecretAccessKey", SampleUtil.getConfig("awsSecretAccessKey"));
            String sessionToken = arguments.get("sessionToken", SampleUtil.getConfig("sessionToken"));

            if (awsAccessKeyId != null && awsSecretAccessKey != null)
            {
                awsIotClient = new AWSIotMqttClient(clientEndpoint, clientId, awsAccessKeyId, awsSecretAccessKey,
                        sessionToken);
            }
        }

        if (awsIotClient == null)
        {
            throw new IllegalArgumentException("Failed to construct client due to missing certificate or credentials.");
        }

[rongsaws]

Since awsIotClient.setKeepAliveInterval() takes milliseconds input, setting it to 30 basically disables keep-alive pings. But I still don't understand how disabling keep-alive would fix it. It'd be good to take a look at the tcpdump.