This is a bug report for the NRF9160 AWS FOTA implementation tested with nrf-sdk at 25c4404f1
My application is based on the asset_tracker_v2 example.
When I initiate a fota update and the download client fails with `Unable to connect, errno 119`, the application gets to a state where the update failed, but no new updates can be started since the application ignores any new jobs since a fota update is still in progress.
The download client failed because of a miss-configuration on the network side (unrelated to the NRF91). (server wasn't reachable)
Firmware keeps running, but only a hard reset will bring it out of fota update state.
Logs:
[00:00:55.272,644] <dbg> aws_fota.on_publish_evt: Received topic: $aws/things/352656105076676/jobs/notify-next
[00:00:55.282,806] <dbg> aws_fota.on_publish_evt: Checking for an available job
[00:00:55.290,588] <dbg> aws_fota.get_job_execution: Job doc: {"timestamp":1618093664,"execution":{"jobId":"test_fota_352656105076676_1618093662","status":"QUEUED","queuedAt":1618093663,"lastUpdatedAt":1618093663,"versionNumber":1,"executionNumber":1,"jobDocument":{"operation":"app_fw_update","fwversion":"v1.0.1","size":1,"location":{"protocol":"http:","host":"******-fota-test.s3-eu-west-1.amazonaws.com","path":"fota/app_update.bin"}}}}
[00:00:55.330,841] <dbg> aws_fota.get_job_execution: Job ID: test_fota_352656105076676_1618093662
[00:00:55.339,904] <dbg> aws_fota.get_job_execution: hostname: ******-fota-test.s3-eu-west-1.amazonaws.com
[00:00:55.349,792] <dbg> aws_fota.get_job_execution: file_path fota/app_update.bin
[00:00:55.357,635] <dbg> aws_fota.get_job_execution: execution_version_number: 1
[00:00:55.366,455] <dbg> aws_fota.get_job_execution: Subscribed to FOTA update topic $aws/things/352656105076676/jobs/test_fota_352656105076676_1618093662/update/#
[00:00:56.293,334] <dbg> aws_fota.update_job_execution: update_job_execution, state: 1, version_number: 1
[00:00:56.742,767] <dbg> aws_iot.mqtt_evt_handler: MQTT_EVT_PUBACK: id = 9937 result = 0
[00:00:56.838,043] <dbg> aws_fota.on_publish_evt: Received topic: $aws/things/352656105076676/jobs/test_fota_352656105076676_1618093662/update/accepted
[00:00:56.851,837] <dbg> aws_fota.job_update_accepted: Start downloading firmware from ******-fota-test.s3-eu-west-1.amazonaws.com/fota/app_update.bin
[00:00:57.238,403] <inf> download_client: Configuring socket timeout (30 s)
[00:00:57.245,605] <inf> download_client: Connecting to ******-fota-test.s3-eu-west-1.amazonaws.com
[00:01:20.523,040] <err> download_client: Unable to connect, errno 116
[00:01:20.536,560] <err> aws_fota: Error (-116) when trying to start firmware download
[00:01:20.544,982] <dbg> aws_fota.update_job_execution: update_job_execution, state: 3, version_number: 2
[00:01:20.562,988] <dbg> aws_iot.aws_fota_cb_handler: AWS_FOTA_EVT_START
[00:01:20.569,946] <dbg> aws_iot_integration.aws_iot_event_handler: AWS_IOT_EVT_FOTA_START
[00:01:20.578,796] <dbg> cloud_module.cloud_wrap_event_handler: CLOUD_WRAP_EVT_FOTA_START
[00:01:22.007,324] <dbg> aws_iot.mqtt_evt_handler: MQTT_EVT_PUBACK: id = 18187 result = 0
[00:01:22.103,515] <dbg> aws_fota.on_publish_evt: Received topic: $aws/things/352656105076676/jobs/test_fota_352656105076676_1618093662/update/accepted
[00:01:22.117,309] <dbg> aws_fota.job_update_accepted: Start downloading firmware from ******-fota-test.s3-eu-west-1.amazonaws.com/fota/app_update.bin
[00:01:22.487,976] <inf> download_client: Configuring socket timeout (30 s)
[00:01:22.495,208] <inf> download_client: Connecting to ******-fota-test.s3-eu-west-1.amazonaws.com
[00:01:47.526,702] <err> download_client: Unable to connect, errno 119
[00:01:47.540,191] <err> aws_fota: Error (-119) when trying to start firmware download
[00:01:47.548,645] <dbg> aws_fota.update_job_execution: update_job_execution, state: 3, version_number: 3
[00:01:47.566,650] <dbg> aws_iot.aws_fota_cb_handler: AWS_FOTA_EVT_START
[00:01:47.573,608] <dbg> aws_iot_integration.aws_iot_event_handler: AWS_IOT_EVT_FOTA_START
[00:01:47.582,183] <dbg> cloud_module.cloud_wrap_event_handler: CLOUD_WRAP_EVT_FOTA_START
[00:01:47.590,850] <dbg> aws_fota.on_publish_evt: Received topic: $aws/things/352656105076676/jobs/notify-next
[00:01:47.601,135] <dbg> aws_fota.on_publish_evt: FOTA already in progress, message is ignored
[00:01:48.712,921] <dbg> aws_iot.mqtt_evt_handler: MQTT_EVT_PUBACK: id = 51075 result = 0
[00:01:48.949,310] <dbg> aws_fota.on_publish_evt: Received topic: $aws/things/352656105076676/jobs/test_fota_352656105076676_1618093662/update/rejected
[00:01:48.962,982] <err> aws_fota: Job document update was rejected
[00:01:48.969,818] <err> aws_fota: Job document update was rejected
[00:01:48.976,806] <err> aws_fota: {"clientToken":"","timestamp":1618093718,"executionState":{"status":"FAILED","versionNumber":3},"code":"InvalidStateTransition","message":"Job test_fota_352656105076676_1618093662 for 352656105076676 has already finished with status FAILED"}n":"v1.0.1","size":1,"location":{"protocol":"http:","host":"******-fota-test.s3-eu-west-1.amazonaws.com","path":"fota/app_update.bin"}}}}
[00:01:49.012,939] <err> aws_iot: AWS_FOTA_EVT_ERROR
[00:01:49.018,493] <dbg> aws_iot_integration.aws_iot_event_handler: AWS_IOT_EVT_FOTA_ERROR
[00:01:49.027,038] <dbg> cloud_module.cloud_wrap_event_handler: CLOUD_WRAP_EVT_FOTA_ERROR
[00:01:49.035,491] <err> aws_iot: aws_fota_mqtt_evt_handler, error: -14
[00:01:49.042,694] <dbg> aws_iot_integration.aws_iot_event_handler: AWS_IOT_EVT_FOTA_ERROR
[00:01:49.051,208] <dbg> cloud_module.cloud_wrap_event_handler: CLOUD_WRAP_EVT_FOTA_ERROR
[00:01:49.059,661] <dbg> aws_iot.mqtt_evt_handler: MQTT_EVT_PUBLISH: id = 18696 len = 241
[00:01:49.068,237] <err> aws_iot: publish_get_payload, error: -5
After this the job is marked as failed in AWS, but any consequent fota jobs get ignored.
