AWS IoT FOTA job gets queued but never starts

[Oli]

I followed the DevAcademy lesson on WiFi FOTA with AWS IoT, with some modifications to work with my board.

The device correctly connects to the AWS mqtt server and published events, etc. However, I followed the instructions for creating a FOTA job and I submitted the job. But it seems the job is stuck in "queued" mode and never starts. What might be the issue?

Device logs:

*** Booting MCUboot v2.1.0-dev-ae1ee57f3906 ***
*** Using nRF Connect SDK v3.0.1-9eb5615da66b ***
*** Using Zephyr OS v4.0.99-347f4f256cbc ***
I: Starting bootloader
I: Primary image: magic=unset, swap_type=0x1, copy_done=0x3, image_ok=0x3
I: Secondary image: magic=unset, swap_type=0x1, copy_done=0x3, image_ok=0x3
I: Boot source: none
I: Image index: 0, Swap type: none
I: Bootloader chainload address offset: 0xc000
I: Image version: v0.0.0
I: Jumping to the first image slot
*** Booting nRF Connect SDK v3.0.1-9eb5615da66b ***
*** Using Zephyr OS v4.0.99-347f4f256cbc ***
[00:00:00.015,472] <inf> aws_iot_sample: The AWS IoT sample started, version: v1.0.0
[00:00:00.015,777] <inf> aws_iot_sample: Hardware ID: 80380020C920
[00:00:00.015,808] <inf> aws_iot_sample: Bringing network interface up and connecting to the network
[00:00:00.016,632] <dbg> mqtt_helper: mqtt_state_set: State transition: MQTT_STATE_UNINIT --> MQTT_STATE_DISCONNECTED
[00:00:00.017,211] <dbg> mqtt_helper: mqtt_helper_poll_loop: Waiting for connection_poll_sem
[00:00:24.187,286] <inf> aws_iot_sample: Network connectivity established
[00:00:29.187,408] <inf> aws_iot_sample: Connecting to AWS IoT
[00:00:29.187,469] <dbg> aws_iot: aws_iot_connect: No hostname provided, using Kconfig value: a9a20x0t82j8w-ats.iot.us-east-2.amazonaws.com
[00:00:29.187,713] <dbg> mqtt_helper: broker_init: Resolving IP address for a9a20x0t82j8w-ats.iot.us-east-2.amazonaws.com
[00:00:29.310,974] <dbg> mqtt_helper: broker_init: IPv4 Address found 13.59.89.240 (AF_INET)
[00:00:29.311,096] <dbg> mqtt_helper: mqtt_state_set: State transition: MQTT_STATE_DISCONNECTED --> MQTT_STATE_TRANSPORT_CONNECTING
[00:00:33.327,728] <dbg> mqtt_helper: mqtt_state_set: State transition: MQTT_STATE_TRANSPORT_CONNECTING --> MQTT_STATE_TRANSPORT_CONNECTED
[00:00:33.327,789] <dbg> mqtt_helper: mqtt_state_set: State transition: MQTT_STATE_TRANSPORT_CONNECTED --> MQTT_STATE_CONNECTING
[00:00:33.327,819] <dbg> mqtt_helper: client_connect: Using send socket timeout of 60 seconds
[00:00:33.327,850] <dbg> mqtt_helper: mqtt_helper_connect: MQTT connection request sent
[00:00:33.327,880] <dbg> mqtt_helper: mqtt_helper_poll_loop: Took connection_poll_sem
[00:00:33.327,911] <dbg> mqtt_helper: mqtt_helper_poll_loop: Starting to poll on socket, fd: 2
[00:00:33.327,911] <dbg> mqtt_helper: mqtt_helper_poll_loop: Polling on socket fd: 2
[00:00:33.536,468] <dbg> mqtt_helper: mqtt_evt_handler: MQTT mqtt_client connected
[00:00:33.536,529] <dbg> mqtt_helper: mqtt_state_set: State transition: MQTT_STATE_CONNECTING --> MQTT_STATE_CONNECTED
[00:00:33.536,560] <dbg> aws_iot: on_connack: MQTT client connected!
[00:00:33.536,621] <dbg> aws_iot: subscribe: Subscribing to topic: my-custom-topic/exampl
[00:00:33.536,651] <dbg> aws_iot: subscribe: Subscribing to topic: my-custom-topic/example_
[00:00:33.536,682] <dbg> mqtt_helper: mqtt_helper_subscribe: Subscribing to: my-custom-topic/example
[00:00:33.536,743] <dbg> mqtt_helper: mqtt_helper_subscribe: Subscribing to: my-custom-topic/example_2
[00:00:33.537,750] <dbg> aws_iot: subscribe: Subscribing to topic: $aws/things/80380020C920/shadow/get/accepted
[00:00:33.537,811] <dbg> aws_iot: subscribe: Subscribing to topic: $aws/things/80380020C920/shadow/get/rejected
[00:00:33.537,872] <dbg> aws_iot: subscribe: Subscribing to topic: $aws/things/80380020C920/shadow/update/delta
[00:00:33.537,902] <dbg> mqtt_helper: mqtt_helper_subscribe: Subscribing to: $aws/things/80380020C920/shadow/get/accepted
[00:00:33.537,963] <dbg> mqtt_helper: mqtt_helper_subscribe: Subscribing to: $aws/things/80380020C920/shadow/get/rejected
[00:00:33.538,024] <dbg> mqtt_helper: mqtt_helper_subscribe: Subscribing to: $aws/things/80380020C920/shadow/update/delta
[00:00:33.539,947] <dbg> mqtt_helper: mqtt_helper_poll_loop: Polling on socket fd: 2
[00:00:33.711,761] <dbg> mqtt_helper: mqtt_helper_poll_loop: Polling on socket fd: 2
[00:00:33.898,651] <dbg> mqtt_helper: mqtt_helper_poll_loop: Polling on socket fd: 2
[00:00:33.899,353] <dbg> mqtt_helper: mqtt_evt_handler: MQTT_EVT_SUBACK: id = 1984 result = 0
[00:00:33.899,383] <dbg> aws_iot: on_suback: Received ACK for subscribe message: id = 1984 result = 0
[00:00:33.899,414] <dbg> mqtt_helper: mqtt_helper_poll_loop: Polling on socket fd: 2
[00:00:33.912,078] <dbg> mqtt_helper: mqtt_evt_handler: MQTT_EVT_SUBACK: id = 2469 result = 0
[00:00:33.912,078] <dbg> aws_iot: on_suback: Received ACK for subscribe message: id = 2469 result = 0
[00:00:33.912,109] <dbg> aws_iot: aws_iot_send: Using message ID 1
[00:00:33.912,170] <dbg> aws_iot: aws_iot_send: Publishing to topic: $aws/things/80380020C920/shadow/get
[00:00:33.912,231] <dbg> mqtt_helper: mqtt_helper_publish: Publishing to topic: $aws/things/80380020C920/shadow/get
[00:00:33.913,055] <dbg> aws_iot: device_shadow_document_request: Device shadow document requested
[00:00:33.913,116] <inf> aws_iot_sample: AWS_IOT_EVT_CONNECTED
[00:00:33.913,146] <inf> aws_iot_sample: Confirming image
[00:00:33.913,208] <dbg> mqtt_helper: mqtt_helper_poll_loop: Polling on socket fd: 2
[00:00:33.913,452] <inf> aws_iot_sample: Publishing message: {"state":{"reported":{"uptime":33913,"app_version":"v1.0.0"}}} to AWS IoT shadow
[00:00:33.913,482] <dbg> aws_iot: aws_iot_send: Using message ID 2
[00:00:33.913,543] <dbg> aws_iot: aws_iot_send: Publishing to topic: $aws/things/80380020C920/shadow/update
[00:00:33.913,574] <dbg> mqtt_helper: mqtt_helper_publish: Publishing to topic: $aws/things/80380020C920/shadow/update
[00:00:34.052,764] <dbg> mqtt_helper: mqtt_evt_handler: MQTT_EVT_PUBACK: id = 56042 result = 0
[00:00:34.052,795] <dbg> aws_iot: on_puback: Received ACK for published message: id = 56042 result = 0
[00:00:34.052,825] <inf> aws_iot_sample: AWS_IOT_EVT_PUBACK, message ID: 56042
[00:00:34.052,856] <dbg> mqtt_helper: mqtt_helper_poll_loop: Polling on socket fd: 2
[00:00:34.067,047] <dbg> mqtt_helper: mqtt_helper_poll_loop: Polling on socket fd: 2
[00:00:34.357,421] <dbg> mqtt_helper: mqtt_evt_handler: MQTT_EVT_PUBLISH, message ID: 1, len = 199
[00:00:34.359,466] <dbg> mqtt_helper: send_ack: PUBACK sent for message ID 1
[00:00:34.359,558] <dbg> aws_iot: on_publish: Received message: topic = $aws/things/80380020C920/shadow/get/accepted and len = 199 
[00:00:34.359,588] <inf> aws_iot_sample: AWS_IOT_EVT_DATA_RECEIVED
[00:00:34.359,710] <inf> aws_iot_sample: Received message: "{"state":{"reported":{"uptime":333818,"app_version":"v1.0.0"}},"metadata":{"reported":{"uptime":{"timestamp":1747611048},"app_version":{"timestamp":1747611048}}},"version":103,"timestamp":1747611140}" on topic: "$aws/things/80380020C920/shadow/get/accepted"
[00:00:34.359,741] <dbg> mqtt_helper: mqtt_helper_poll_loop: Polling on socket fd: 2
[00:01:33.915,588] <inf> aws_iot_sample: Publishing message: {"state":{"reported":{"uptime":93915,"app_version":"v1.0.0"}}} to AWS IoT shadow
[00:01:33.915,649] <dbg> aws_iot: aws_iot_send: Using message ID 3
[00:01:33.915,679] <dbg> aws_iot: aws_iot_send: Publishing to topic: $aws/things/80380020C920/shadow/update
[00:01:33.915,740] <dbg> mqtt_helper: mqtt_helper_publish: Publishing to topic: $aws/things/80380020C920/shadow/update
[00:02:33.919,708] <inf> aws_iot_sample: Publishing message: {"state":{"reported":{"uptime":153919,"app_version":"v1.0.0"}}} to AWS IoT shadow
[00:02:33.919,738] <dbg> aws_iot: aws_iot_send: Using message ID 4
[00:02:33.919,769] <dbg> aws_iot: aws_iot_send: Publishing to topic: $aws/things/80380020C920/shadow/update
[00:02:33.919,830] <dbg> mqtt_helper: mqtt_helper_publish: Publishing to topic: $aws/things/80380020C920/shadow/update
[00:03:33.923,797] <inf> aws_iot_sample: Publishing message: {"state":{"reported":{"uptime":213923,"app_version":"v1.0.0"}}} to AWS IoT shadow
[00:03:33.923,828] <dbg> aws_iot: aws_iot_send: Using message ID 5
[00:03:33.923,858] <dbg> aws_iot: aws_iot_send: Publishing to topic: $aws/things/80380020C920/shadow/update
[00:03:33.923,919] <dbg> mqtt_helper: mqtt_helper_publish: Publishing to topic: $aws/things/80380020C920/shadow/update

[Oli]

I  enabled AWS FOTA debug logging and am seeing this:

00:00:34.211,944] <dbg> aws_fota: topic_type_get: Received topic: $aws/things/80380020C920/jobs/$next/get/accepted
[00:00:34.211,975] <dbg> aws_fota: on_publish_evt: Checking for an available job
[00:00:34.212,066] <dbg> aws_fota: parse_job_execution: Job doc: {"clientToken":"","timestamp":1747612515}
[00:00:34.212,371] <dbg> aws_fota: parse_job_execution: Got only one field
[00:00:34.212,402] <dbg> aws_fota: parse_job_execution: No queued jobs for this device

Not sure what it means. It looks like it is receiving an incorrect job document?

I added some logging and it seems that the job document is indeed

{"clientToken":"","timestamp":1747613442}

Which is weird because in the AWS IOT job document page it shows:

{
  "operation": "app_fw_update",
  "fwversion": "v1.0.1",
  "size": 402884,
  "location": {
    "protocol": "http",
    "host": "my-bucket.s3.us-east-2.amazonaws.com",
    "path": "/v1.0.1.bin"
  }
}

[Oli]

The issue was that I was passing a client_id in my main.c based on hardware id so the CONFIG_AWS_IOT_CLIENT_ID_STATIC configuration option was getting ignored. I scheduled the job for "academy_thing" but the client was connecting as "80380020C920".