This is a pretty top level description of the problem. I've not dug very deep, but what I've observed is that when deployed against an AWS instance set up per the instructions at:
The device is booted shortly after connecting and subscribing to topics.
With a 1.6.0 build, it works as expected.
It looks to me like the instructions for AWS have not been updated for the 1.7.0 SDK. Is this the case, and if so, are updated instructions forthcoming?
The device is booted shortly after connecting and subscribing to topics.
Could you provide the serial output from the application when the device reboots?
The device is booted shortly after connecting and subscribing to topics.
Could you provide the serial output from the application when the device reboots?
Sorry, my terminology was unclear. It doesn't actually reboot, it is simply disconnected, and then retries later.
Here's a log showing an boot, and then several cycles of connect/subscribe/disconnect.
[00:00:00.780,120] [0m<dbg> aws_iot_integration.cloud_wrap_init: ********************************************[0m [00:00:00.790,252] [0m<dbg> aws_iot_integration.cloud_wrap_init: The Asset Tracker v2 has started[0m [00:00:00.799,438] [0m<dbg> aws_iot_integration.cloud_wrap_init: Version: 0.0.0-development[0m [00:00:00.808,471] [0m<dbg> aws_iot_integration.cloud_wrap_init: Client ID: 352656100747511[0m [00:00:00.817,321] [0m<dbg> aws_iot_integration.cloud_wrap_init: Cloud: AWS IoT[0m [00:00:00.825,500] [0m<dbg> aws_iot_integration.cloud_wrap_init: Endpoint: a9za702rfmit2-ats.iot.us-east-1.amazonaws.com[0m [00:00:00.836,975] [0m<dbg> aws_iot_integration.cloud_wrap_init: ********************************************[0m [00:00:00.874,237] [0m<dbg> modem_module.configure_low_power: PSM requested[0m [00:00:00.888,153] [0m<dbg> modules_common.module_get_next_msg: modem module: Dequeued APP_EVT_START[0m [00:00:00.958,099] [0m<inf> event_manager: MODEM_EVT_LTE_CONNECTING[0m [00:00:00.964,630] [0m<dbg> modules_common.module_enqueue_msg: modem module: Enqueued: MODEM_EVT_LTE_CONNECTING[0m [00:00:00.975,067] [0m<dbg> modules_common.module_enqueue_msg: data module: Enqueued: MODEM_EVT_LTE_CONNECTING[0m [00:00:00.985,382] [0m<dbg> modules_common.module_enqueue_msg: cloud module: Enqueued: MODEM_EVT_LTE_CONNECTING[0m [00:00:00.995,788] [0m<dbg> modules_common.module_enqueue_msg: app module: Enqueued: MODEM_EVT_LTE_CONNECTING[0m [00:00:01.006,042] [0m<dbg> modules_common.module_get_next_msg: app module: Dequeued MODEM_EVT_LTE_CONNECTING[0m [00:00:01.016,204] [0m<dbg> modules_common.module_get_next_msg: modem module: Dequeued APP_EVT_ACTIVITY_DETECTION_DISABLE[0m [00:00:01.027,374] [0m<dbg> modules_common.module_get_next_msg: modem module: Dequeued MODEM_EVT_INITIALIZED[0m [00:00:01.037,414] [0m<dbg> modules_common.module_get_next_msg: modem module: Dequeued MODEM_EVT_LTE_CONNECTING[0m [00:00:01.047,760] [0m<dbg> modem_module.state_set: State transition STATE_DISCONNECTED --> STATE_CONNECTING[0m [00:00:01.057,830] [0m<dbg> modules_common.module_get_next_msg: data module: Dequeued MODEM_EVT_LTE_CONNECTING[0m [00:00:01.068,054] [0m<dbg> modules_common.module_get_next_msg: cloud module: Dequeued MODEM_EVT_LTE_CONNECTING[0m %CESQ: 27,1,14,2 [00:00:01.781,341] [0m<dbg> modem_module.modem_rsrp_handler: Incoming RSRP status message, RSRP value is -113[0m +CEREG: 2,"BEFF","09A02300",7 [00:00:01.794,586] [0m<inf> event_manager: MODEM_EVT_LTE_DISCONNECTED[0m [00:00:01.801,300] [0m<dbg> modules_common.module_enqueue_msg: modem module: Enqueued: MODEM_EVT_LTE_DISCONNECTED[0m [00:00:01.811,920] [0m<dbg> modules_common.module_enqueue_msg: data module: Enqueued: MODEM_EVT_LTE_DISCONNECTED[0m [00:00:01.822,479] [0m<dbg> modules_common.module_enqueue_msg: cloud module: Enqueued: MODEM_EVT_LTE_DISCONNECTED[0m [00:00:01.833,099] [0m<dbg> modules_common.module_enqueue_msg: app module: Enqueued: MODEM_EVT_LTE_DISCONNECTED[0m [00:00:01.843,444] [0m<dbg> modules_common.module_get_next_msg: app module: Dequeued MODEM_EVT_LTE_DISCONNECTED[0m [00:00:01.853,729] [0m<dbg> modem_module.lte_evt_handler: LTE cell changed: Cell ID: 161489664, Tracking area: 48895[0m [00:00:01.864,593] [0m<inf> event_manager: MODEM_EVT_LTE_CELL_UPDATE[0m [00:00:01.871,215] [0m<dbg> modules_common.module_enqueue_msg: modem module: Enqueued: MODEM_EVT_LTE_CELL_UPDATE[0m [00:00:01.881,744] [0m<dbg> modules_common.module_enqueue_msg: data module: Enqueued: MODEM_EVT_LTE_CELL_UPDATE[0m [00:00:01.892,181] [0m<dbg> modules_common.module_enqueue_msg: cloud module: Enqueued: MODEM_EVT_LTE_CELL_UPDATE[0m [00:00:01.902,709] [0m<dbg> modules_common.module_enqueue_msg: app module: Enqueued: MODEM_EVT_LTE_CELL_UPDATE[0m [00:00:01.912,994] [0m<dbg> modules_common.module_get_next_msg: app module: Dequeued MODEM_EVT_LTE_CELL_UPDATE[0m [00:00:01.923,309] [0m<dbg> modules_common.module_get_next_msg: modem module: Dequeued MODEM_EVT_LTE_DISCONNECTED[0m [00:00:01.933,807] [0m<dbg> modules_common.module_get_next_msg: modem module: Dequeued MODEM_EVT_LTE_CELL_UPDATE[0m [00:00:01.944,244] [0m<dbg> modules_common.module_get_next_msg: data module: Dequeued MODEM_EVT_LTE_DISCONNECTED[0m [00:00:01.954,681] [0m<dbg> modules_common.module_get_next_msg: data module: Dequeued MODEM_EVT_LTE_CELL_UPDATE[0m [00:00:01.964,996] [0m<dbg> modules_common.module_get_next_msg: cloud module: Dequeued MODEM_EVT_LTE_DISCONNECTED[0m [00:00:01.975,524] [0m<dbg> modules_common.module_get_next_msg: cloud module: Dequeued MODEM_EVT_LTE_CELL_UPDATE[0m +CSCON: 1 [00:00:02.519,989] [0m<dbg> modem_module.lte_evt_handler: RRC mode: Connected[0m +CEREG: 5,"BEFF","09A02300",7,0,18,"11100000","11100000" [00:00:04.628,875] [0m<dbg> modem_module.lte_evt_handler: Network registration status: Connected - roaming[0m [00:00:04.638,763] [0m<inf> event_manager: MODEM_EVT_LTE_CONNECTED[0m [00:00:04.645,202] [0m<dbg> modules_common.module_enqueue_msg: modem module: Enqueued: MODEM_EVT_LTE_CONNECTED[0m [00:00:04.655,517] [0m<dbg> modules_common.module_enqueue_msg: data module: Enqueued: MODEM_EVT_LTE_CONNECTED[0m [00:00:04.665,740] [0m<dbg> modules_common.module_enqueue_msg: cloud module: Enqueued: MODEM_EVT_LTE_CONNECTED[0m [00:00:04.676,055] [0m<dbg> modules_common.module_enqueue_msg: app module: Enqueued: MODEM_EVT_LTE_CONNECTED[0m [00:00:04.686,096] [0m<dbg> modules_common.module_get_next_msg: app module: Dequeued MODEM_EVT_LTE_CONNECTED[0m [00:00:04.696,105] [0m<dbg> modem_module.lte_evt_handler: PSM parameter update: TAU: -1, Active time: -1[0m [00:00:04.705,841] [0m<inf> event_manager: MODEM_EVT_LTE_PSM_UPDATE[0m [00:00:04.712,371] [0m<dbg> modules_common.module_enqueue_msg: modem module: Enqueued: MODEM_EVT_LTE_PSM_UPDATE[0m [00:00:04.722,778] [0m<dbg> modules_common.module_enqueue_msg: data module: Enqueued: MODEM_EVT_LTE_PSM_UPDATE[0m [00:00:04.733,093] [0m<dbg> modules_common.module_enqueue_msg: cloud module: Enqueued: MODEM_EVT_LTE_PSM_UPDATE[0m [00:00:04.743,469] [0m<dbg> modules_common.module_enqueue_msg: app module: Enqueued: MODEM_EVT_LTE_PSM_UPDATE[0m [00:00:04.753,601] [0m<dbg> modules_common.module_get_next_msg: app module: Dequeued MODEM_EVT_LTE_PSM_UPDATE[0m [00:00:04.763,824] [0m<dbg> modules_common.module_get_next_msg: modem module: Dequeued MODEM_EVT_LTE_CONNECTED[0m [00:00:04.773,956] [0m<dbg> modem_module.state_set: State transition STATE_CONNECTING --> STATE_CONNECTED[0m [00:00:04.783,813] [0m<dbg> modules_common.module_get_next_msg: modem module: Dequeued MODEM_EVT_LTE_PSM_UPDATE[0m [00:00:04.794,067] [0m<dbg> modules_common.module_get_next_msg: data module: Dequeued MODEM_EVT_LTE_CONNECTED[0m [00:00:04.804,229] [0m<dbg> modules_common.module_get_next_msg: data module: Dequeued MODEM_EVT_LTE_PSM_UPDATE[0m [00:00:04.814,422] [0m<dbg> modules_common.module_get_next_msg: cloud module: Dequeued MODEM_EVT_LTE_CONNECTED[0m [00:00:04.824,584] [0m<dbg> cloud_module.state_set: State transition STATE_LTE_DISCONNECTED --> STATE_LTE_CONNECTED[0m [00:00:04.835,235] [0m<dbg> cloud_module.connect_cloud: Connecting to cloud[0m [00:00:04.842,407] [1;33m<wrn> cloud_module: Cloud connection establishment in progress[0m [00:00:04.850,616] [1;33m<wrn> cloud_module: New connection attempt in 32 seconds if not successful[0m [00:00:04.859,924] [0m<dbg> modules_common.module_get_next_msg: cloud module: Dequeued MODEM_EVT_LTE_PSM_UPDATE[0m [00:00:04.870,178] [0m<dbg> aws_iot_integration.aws_iot_event_handler: AWS_IOT_EVT_CONNECTING[0m [00:00:04.878,906] [0m<dbg> cloud_module.cloud_wrap_event_handler: CLOUD_WRAP_EVT_CONNECTING[0m [00:00:04.887,634] [0m<inf> event_manager: CLOUD_EVT_CONNECTING[0m [00:00:04.893,768] [0m<dbg> modules_common.module_enqueue_msg: app module: Enqueued: CLOUD_EVT_CONNECTING[0m [00:00:04.903,594] [0m<dbg> modules_common.module_enqueue_msg: data module: Enqueued: CLOUD_EVT_CONNECTING[0m [00:00:04.913,543] [0m<dbg> modules_common.module_enqueue_msg: cloud module: Enqueued: CLOUD_EVT_CONNECTING[0m [00:00:04.923,553] [0m<dbg> modules_common.module_enqueue_msg: modem module: Enqueued: CLOUD_EVT_CONNECTING[0m [00:00:04.933,502] [0m<dbg> modules_common.module_get_next_msg: app module: Dequeued CLOUD_EVT_CONNECTING[0m [00:00:04.943,359] [0m<dbg> modules_common.module_get_next_msg: data module: Dequeued CLOUD_EVT_CONNECTING[0m [00:00:04.953,277] [0m<dbg> modules_common.module_get_next_msg: cloud module: Dequeued CLOUD_EVT_CONNECTING[0m [00:00:04.963,226] [0m<dbg> modules_common.module_get_next_msg: modem module: Dequeued CLOUD_EVT_CONNECTING[0m [00:00:05.246,398] [0m<dbg> aws_iot.broker_init: IPv4 Address found 54.146.134.176[0m [00:00:11.262,847] [0m<dbg> aws_iot.connect_client: Using send socket timeout of 60 seconds[0m [00:00:11.271,331] [0m<dbg> aws_iot.aws_iot_cloud_poll: AWS IoT broker connection request sent[0m [00:00:11.637,054] [0m<dbg> aws_iot.mqtt_evt_handler: MQTT client connected![0m [00:00:11.644,226] [0m<dbg> aws_iot_integration.aws_iot_event_handler: AWS_IOT_EVT_CONNECTED[0m [00:00:11.652,893] [0m<dbg> aws_iot.topic_subscribe: Subscribing to application topic: $aws/things/352656100747511/shadow/get/accepted/desired/cfg[0m [00:00:11.666,229] [0m<dbg> aws_iot.topic_subscribe: Subscribing to application topic: 352656100747511/agps[0m [00:00:11.676,208] [0m<dbg> aws_iot.topic_subscribe: Subscribing to application topic: 352656100747511/pgps[0m [00:00:12.037,750] [0m<dbg> aws_iot.mqtt_evt_handler: MQTT_EVT_SUBACK: id = 2112 result = 0[0m [00:00:12.642,517] [0m<dbg> aws_iot.mqtt_evt_handler: MQTT_EVT_DISCONNECT: result = -128[0m [00:00:12.650,848] [0m<dbg> aws_iot_integration.aws_iot_event_handler: AWS_IOT_EVT_DISCONNECTED[0m [00:00:12.659,729] [0m<dbg> cloud_module.cloud_wrap_event_handler: CLOUD_WRAP_EVT_DISCONNECTED[0m [00:00:12.668,640] [0m<inf> event_manager: CLOUD_EVT_DISCONNECTED[0m [00:00:12.674,957] [0m<dbg> modules_common.module_enqueue_msg: app module: Enqueued: CLOUD_EVT_DISCONNECTED[0m [00:00:12.684,967] [0m<dbg> modules_common.module_enqueue_msg: data module: Enqueued: CLOUD_EVT_DISCONNECTED[0m [00:00:12.695,098] [0m<dbg> modules_common.module_enqueue_msg: cloud module: Enqueued: CLOUD_EVT_DISCONNECTED[0m [00:00:12.705,261] [0m<dbg> modules_common.module_enqueue_msg: modem module: Enqueued: CLOUD_EVT_DISCONNECTED[0m [00:00:12.715,393] [0m<dbg> modules_common.module_get_next_msg: app module: Dequeued CLOUD_EVT_DISCONNECTED[0m [00:00:12.725,311] [0m<dbg> aws_iot.aws_iot_cloud_poll: The cloud socket is already closed.[0m [00:00:12.733,856] [0m<dbg> modules_common.module_get_next_msg: data module: Dequeued CLOUD_EVT_DISCONNECTED[0m [00:00:12.743,896] [0m<dbg> modules_common.module_get_next_msg: cloud module: Dequeued CLOUD_EVT_DISCONNECTED[0m [00:00:12.754,028] [0m<dbg> modules_common.module_get_next_msg: modem module: Dequeued CLOUD_EVT_DISCONNECTED[0m [00:00:36.859,954] [0m<dbg> cloud_module.connect_check_work_fn: Cloud connection timeout occurred[0m [00:00:36.869,110] [0m<inf> event_manager: CLOUD_EVT_CONNECTION_TIMEOUT[0m [00:00:36.875,946] [0m<dbg> modules_common.module_enqueue_msg: app module: Enqueued: CLOUD_EVT_CONNECTION_TIMEOUT[0m [00:00:36.886,474] [0m<dbg> modules_common.module_enqueue_msg: data module: Enqueued: CLOUD_EVT_CONNECTION_TIMEOUT[0m [00:00:36.897,125] [0m<dbg> modules_common.module_enqueue_msg: cloud module: Enqueued: CLOUD_EVT_CONNECTION_TIMEOUT[0m [00:00:36.907,806] [0m<dbg> modules_common.module_enqueue_msg: modem module: Enqueued: CLOUD_EVT_CONNECTION_TIMEOUT[0m [00:00:36.918,518] [0m<dbg> modules_common.module_get_next_msg: app module: Dequeued CLOUD_EVT_CONNECTION_TIMEOUT[0m [00:00:36.928,955] [0m<dbg> modules_common.module_get_next_msg: data module: Dequeued CLOUD_EVT_CONNECTION_TIMEOUT[0m [00:00:36.939,514] [0m<dbg> modules_common.module_get_next_msg: cloud module: Dequeued CLOUD_EVT_CONNECTION_TIMEOUT[0m [00:00:36.950,134] [0m<dbg> cloud_module.connect_cloud: Connecting to cloud[0m [00:00:36.957,336] [1;33m<wrn> cloud_module: Cloud connection establishment in progress[0m [00:00:36.965,545] [1;33m<wrn> cloud_module: New connection attempt in 64 seconds if not successful[0m [00:00:36.974,853] [0m<dbg> modules_common.module_get_next_msg: modem module: Dequeued CLOUD_EVT_CONNECTION_TIMEOUT[0m [00:00:36.985,473] [0m<dbg> aws_iot_integration.aws_iot_event_handler: AWS_IOT_EVT_CONNECTING[0m [00:00:36.994,171] [0m<dbg> cloud_module.cloud_wrap_event_handler: CLOUD_WRAP_EVT_CONNECTING[0m [00:00:37.002,899] [0m<inf> event_manager: CLOUD_EVT_CONNECTING[0m [00:00:37.009,033] [0m<dbg> modules_common.module_enqueue_msg: app module: Enqueued: CLOUD_EVT_CONNECTING[0m [00:00:37.018,859] [0m<dbg> modules_common.module_enqueue_msg: data module: Enqueued: CLOUD_EVT_CONNECTING[0m [00:00:37.028,808] [0m<dbg> modules_common.module_enqueue_msg: cloud module: Enqueued: CLOUD_EVT_CONNECTING[0m [00:00:37.038,787] [0m<dbg> modules_common.module_enqueue_msg: modem module: Enqueued: CLOUD_EVT_CONNECTING[0m [00:00:37.048,736] [0m<dbg> modules_common.module_get_next_msg: app module: Dequeued CLOUD_EVT_CONNECTING[0m [00:00:37.058,624] [0m<dbg> modules_common.module_get_next_msg: data module: Dequeued CLOUD_EVT_CONNECTING[0m [00:00:37.068,603] [0m<dbg> modules_common.module_get_next_msg: cloud module: Dequeued CLOUD_EVT_CONNECTING[0m [00:00:37.078,552] [0m<dbg> modules_common.module_get_next_msg: modem module: Dequeued CLOUD_EVT_CONNECTING[0m [00:00:37.088,592] [0m<dbg> aws_iot.broker_init: IPv4 Address found 54.146.134.176[0m [00:00:40.077,728] [0m<dbg> aws_iot.connect_client: Using send socket timeout of 60 seconds[0m [00:00:40.086,212] [0m<dbg> aws_iot.aws_iot_cloud_poll: AWS IoT broker connection request sent[0m [00:00:40.447,662] [0m<dbg> aws_iot.mqtt_evt_handler: MQTT client connected![0m [00:00:40.454,833] [0m<dbg> aws_iot_integration.aws_iot_event_handler: AWS_IOT_EVT_CONNECTED[0m [00:00:40.463,500] [0m<dbg> aws_iot.topic_subscribe: Subscribing to application topic: $aws/things/352656100747511/shadow/get/accepted/desired/cfg[0m [00:00:40.476,837] [0m<dbg> aws_iot.topic_subscribe: Subscribing to application topic: 352656100747511/agps[0m [00:00:40.486,785] [0m<dbg> aws_iot.topic_subscribe: Subscribing to application topic: 352656100747511/pgps[0m [00:00:40.848,815] [0m<dbg> aws_iot.mqtt_evt_handler: MQTT_EVT_SUBACK: id = 2112 result = 0[0m [00:00:41.499,145] [0m<dbg> aws_iot.mqtt_evt_handler: MQTT_EVT_DISCONNECT: result = -128[0m [00:00:41.507,507] [0m<dbg> aws_iot_integration.aws_iot_event_handler: AWS_IOT_EVT_DISCONNECTED[0m [00:00:41.516,418] [0m<dbg> cloud_module.cloud_wrap_event_handler: CLOUD_WRAP_EVT_DISCONNECTED[0m [00:00:41.525,299] [0m<inf> event_manager: CLOUD_EVT_DISCONNECTED[0m [00:00:41.531,646] [0m<dbg> modules_common.module_enqueue_msg: app module: Enqueued: CLOUD_EVT_DISCONNECTED[0m [00:00:41.541,625] [0m<dbg> modules_common.module_enqueue_msg: data module: Enqueued: CLOUD_EVT_DISCONNECTED[0m [00:00:41.551,757] [0m<dbg> modules_common.module_enqueue_msg: cloud module: Enqueued: CLOUD_EVT_DISCONNECTED[0m [00:00:41.561,920] [0m<dbg> modules_common.module_enqueue_msg: modem module: Enqueued: CLOUD_EVT_DISCONNECTED[0m [00:00:41.572,113] [0m<dbg> modules_common.module_get_next_msg: app module: Dequeued CLOUD_EVT_DISCONNECTED[0m [00:00:41.582,031] [0m<dbg> aws_iot.aws_iot_cloud_poll: The cloud socket is already closed.[0m [00:00:41.590,606] [0m<dbg> modules_common.module_get_next_msg: data module: Dequeued CLOUD_EVT_DISCONNECTED[0m [00:00:41.600,646] [0m<dbg> modules_common.module_get_next_msg: cloud module: Dequeued CLOUD_EVT_DISCONNECTED[0m [00:00:41.610,778] [0m<dbg> modules_common.module_get_next_msg: modem module: Dequeued CLOUD_EVT_DISCONNECTED[0m +CSCON: 0 [00:01:14.554,199] [0m<dbg> modem_module.lte_evt_handler: RRC mode: Idle[0m
Thanks for the log. Could you take a modem trace during this event, so we can see more of the communication between the device and the MQTT broker? I suspect the host might be sending the disconnect and a modem trace might tell us why.
Did you get any further with this?
I'm having the same problem (I think):
[00:01:41.695,159] <dbg> aws_jobs.publish: Publish payload {"clientToken": ""}
[00:01:41.703,704] <dbg> aws_iot.mqtt_evt_handler: MQTT_EVT_SUBACK: id = 2112 result = 0
[00:01:41.850,708] <dbg> aws_iot.mqtt_evt_handler: MQTT_EVT_DISCONNECT: result = -128
[00:01:41.858,978] <inf> event_manager: CLOUD_EVT_DISCONNECTED
Does anyone know how to solve this? (I'm on 1.7.0)
Macthestack,
No, no further progress. The project that involves this problem is on hold on our end, so I've been unable to spend time on it.