AWS FOTA Update inconsistent

[Adeel]

Hi dev team,

I am using a Thingy91 device along with the NCS v1.5.1.

I used the AWS FOTA example for firmware upgrades and I integrated the example in my code.

The FOTA update works for me but sometimes it hangs. It works for me once and the next time it hangs and says job rejected. 

I am attaching the log of the behavior I am seeing. The FOTA works the first time and then when I try to do a FOTA once again, it says job rejected.

FOTA updates once, fails once.txt

I also tried using the AWS_FOTA sample and experienced the same behavior. Can anyone in the team who has used FOTA through AWS try and check this out ?

Regards,

Adeel. 

[Marte Myrvold]

Hi Adeel,

From the log it seems like you are receiving the job twice the times it is rejected:

[mqtt_evt_handler:162] MQTT client connected!
Subscribing to: sensorstest1/nrf352656100980047/commands2
[mqtt_evt_handler:190] MQTT PUBLISH result=0 len=4
Received: FOTA
Payload buf is : FOTA
[mqtt_evt_handler:190] MQTT PUBLISH result=0 len=4
Received: FOTA
Payload buf is : FOTA

Here the application goes into mqtt_evt_handler() and the case MQTT_EVT_PUBLISH twice, so you are receiving two publish events on your device.

There was a known issue where the device received multiple notify-next messages in AWS FOTA before, but this was fixed before NCS v1.5.0, so you should not get this error when you are using v1.5.1. The changes that were done to fix this issue can be found here, but this part in nrf/subsys/net/lib/aws_fota/src/aws_fota.c has been changed since then, so it does not look the same in v1.5.1 as in that change. However, the for when get_job_execution() is called is the same in v1.5.1:

	if (is_notify_next_topic) {
		if (fota_state == NONE) {
			LOG_DBG("Checking for an available job");

			return get_job_execution(client, payload_len);
		}
		
...

	} else if (is_get_next_topic || is_get_accepted) {
		LOG_DBG("Checking for an available job");
		return get_job_execution(client, payload_len);
	}

You can also try to check your device's shadow in AWS IoT, to get more information about why the job is rejected. The device should be publishing to the /update topic, which will create and update the shadow of your device. When the job is rejected, AWS IoT will publish a message to the $aws/things/thingName/shadow/name/shadowName/update/rejected. This message contains an error response document that describes the error. For more information about this you can check out Interacting with shadows, Device Shadow service documents, and Device Shadow error messages.

Please check that your application has the correct behavior in regards to multiple notify-next messages. If this issue persists, could you please get a modem trace of this behavior?

Best regards,

Marte

[Adeel]

Hi Marte,

Marte Myrvold said:

Here the application goes into mqtt_evt_handler() and the case MQTT_EVT_PUBLISH twice, so you are receiving two publish events on your device.

This is a command that I send through MQTT to start the FOTA, so it should not interfere with the issue here.

However, I see an error that is logged after the job is rejected.

Fullscreen Rejected with error message.txt Download

2021-05-06T13:09:27.685Z DEBUG modem << *** Booting Zephyr OS build v2.4.99-ncs2  ***
2021-05-06T13:09:27.705Z DEBUG modem << Flash regionsDomainPermissions
2021-05-06T13:09:27.707Z DEBUG modem << 00 02 0x00000 0x18000 Securerwxl
2021-05-06T13:09:27.708Z DEBUG modem << 03 31 0x18000 0x100000 Non-Securerwxl
2021-05-06T13:09:27.709Z DEBUG modem << Non-secure callable region 0 placed in flash region 2 with size 32.
2021-05-06T13:09:27.917Z DEBUG modem << SRAM regionDomainPermissions
2021-05-06T13:09:27.919Z DEBUG modem << 00 07 0x00000 0x10000 Securerwxl
2021-05-06T13:09:27.920Z DEBUG modem << 08 31 0x10000 0x40000 Non-Securerwxl
2021-05-06T13:09:27.922Z DEBUG modem << PeripheralDomainStatus
2021-05-06T13:09:27.923Z DEBUG modem << 00 NRF_P0               Non-SecureOK
2021-05-06T13:14:14.560Z DEBUG modem << work_handler_collect_data started!
2021-05-06T13:14:14.562Z DEBUG modem << Getting latest time...done!
2021-05-06T13:14:14.563Z DEBUG modem << Reading out bosch sensor...done!
2021-05-06T13:14:14.588Z DEBUG modem << Reading out modem info...done!
2021-05-06T13:14:15.559Z DEBUG modem << Reading out Teros12 sensor...done!
2021-05-06T13:14:15.561Z DEBUG modem << ++++++++++++++++++++++++++++++++++++++++++++
2021-05-06T13:14:15.567Z DEBUG modem << Measured data:
2021-05-06T13:14:15.569Z DEBUG modem <<        Timer: 2021-05-06 13:14:14
2021-05-06T13:14:15.571Z DEBUG modem <<  #msg queued: 0
2021-05-06T13:14:15.573Z DEBUG modem <<  Temperature: 27.250 degC
2021-05-06T13:14:15.575Z DEBUG modem <<     Pressure: 94.502 
2021-05-06T13:14:15.611Z DEBUG modem <<     Humidity: 23.533 
2021-05-06T13:14:15.612Z DEBUG modem <<     SoilTemp: 23.100 degC
2021-05-06T13:14:15.613Z DEBUG modem <<    VolWaterC: 1788.900
2021-05-06T13:14:15.614Z DEBUG modem <<   Modem bat.: 4.417 V
2021-05-06T13:14:15.614Z DEBUG modem <<   Current band: 8
2021-05-06T13:14:15.615Z DEBUG modem <<         RSRP: 89
2021-05-06T13:14:15.615Z DEBUG modem << ++++++++++++++++++++++++++++++++++++++++++++
2021-05-06T13:14:15.801Z DEBUG modem << 1788.5 23.1 -0
2021-05-06T13:14:15.833Z DEBUG modem << g90
2021-05-06T13:14:18.383Z DEBUG modem >> AT+CESQ
2021-05-06T13:14:18.420Z DEBUG modem << +CESQ: 99,99,255,255,255,255
2021-05-06T13:14:18.421Z DEBUG modem << OK
2021-05-06T13:14:32.383Z DEBUG modem >> AT+CESQ
2021-05-06T13:14:32.404Z DEBUG modem << +CESQ: 99,99,255,255,255,255
2021-05-06T13:14:32.405Z DEBUG modem << OK
2021-05-06T13:14:44.513Z DEBUG modem << ----------------------------------------------------------------
2021-05-06T13:14:44.515Z DEBUG modem << work_handler_collect_data started!
2021-05-06T13:14:44.516Z DEBUG modem << Getting latest time...done!
2021-05-06T13:14:44.517Z DEBUG modem << Reading out bosch sensor...done!
2021-05-06T13:14:44.544Z DEBUG modem << Reading out modem info...done!
2021-05-06T13:14:45.558Z DEBUG modem << Reading out Teros12 sensor...done!
2021-05-06T13:14:45.559Z DEBUG modem << ++++++++++++++++++++++++++++++++++++++++++++
2021-05-06T13:14:45.560Z DEBUG modem << Measured data:
2021-05-06T13:14:45.561Z DEBUG modem <<        Timer: 2021-05-06 13:14:44
2021-05-06T13:14:45.561Z DEBUG modem <<  #msg queued: 1
2021-05-06T13:14:45.562Z DEBUG modem <<  Temperature: 27.130 degC
2021-05-06T13:14:45.562Z DEBUG modem <<     Pressure: 94.500 
2021-05-06T13:14:45.563Z DEBUG modem <<     Humidity: 23.621 
2021-05-06T13:14:45.563Z DEBUG modem <<     SoilTemp: 23.100 degC
2021-05-06T13:14:45.564Z DEBUG modem <<    VolWaterC: 1788.500
2021-05-06T13:14:45.564Z DEBUG modem <<   Modem bat.: 4.417 V
2021-05-06T13:14:45.565Z DEBUG modem <<   Current band: 8
2021-05-06T13:14:45.565Z DEBUG modem <<         RSRP: 89
2021-05-06T13:14:45.566Z DEBUG modem << ++++++++++++++++++++++++++++++++++++++++++++
2021-05-06T13:14:45.794Z DEBUG modem << 1775.3 23.1 -1
2021-05-06T13:14:45.827Z DEBUG modem << g4n
2021-05-06T13:14:46.384Z DEBUG modem >> AT+CESQ
2021-05-06T13:14:46.411Z DEBUG modem << +CESQ: 99,99,255,255,255,255
2021-05-06T13:14:46.413Z DEBUG modem << OK
2021-05-06T13:14:49.509Z DEBUG modem << ----------------------------------------------------------------
2021-05-06T13:14:49.510Z DEBUG modem << work_handler_send_data started!
2021-05-06T13:14:49.511Z DEBUG modem << Length of message queue : 2
2021-05-06T13:14:49.512Z DEBUG modem << mqtt_meter_init running...
2021-05-06T13:14:49.534Z DEBUG modem << IPv4 Address 13.80.240.194
2021-05-06T13:14:49.535Z DEBUG modem << MQTT Meter client id: Meter
2021-05-06T13:14:51.217Z DEBUG modem << Using device imei: 352656100980047
2021-05-06T13:14:51.219Z DEBUG modem << mqtt_meter_init finished!
2021-05-06T13:14:51.219Z DEBUG modem << Starting to send 2 messages:
2021-05-06T13:14:51.220Z DEBUG modem << Need to send 2 more messages:
2021-05-06T13:14:51.319Z DEBUG modem << [mqtt_evt_handler:162] MQTT client connected!
2021-05-06T13:14:51.320Z DEBUG modem << Subscribing to: sensorstest1/nrf352656100980047/commands2
2021-05-06T13:14:51.444Z DEBUG modem << [mqtt_evt_handler:190] MQTT PUBLISH result=0 len=4
2021-05-06T13:14:51.446Z DEBUG modem << Received: FOTA
2021-05-06T13:14:51.448Z DEBUG modem << Payload buf is : FOTA
2021-05-06T13:14:51.649Z DEBUG modem << [mqtt_evt_handler:228] PUBACK packet id: 41542
2021-05-06T13:14:51.754Z DEBUG modem << [mqtt_evt_handler:228] PUBACK packet id: 16809
2021-05-06T13:14:51.863Z DEBUG modem << [mqtt_evt_handler:228] PUBACK packet id: 3579
2021-05-06T13:14:51.969Z DEBUG modem << [mqtt_evt_handler:228] PUBACK packet id: 35140
2021-05-06T13:14:52.075Z DEBUG modem << [mqtt_evt_handler:228] PUBACK packet id: 48740
2021-05-06T13:14:52.184Z DEBUG modem << [mqtt_evt_handler:228] PUBACK packet id: 36110
2021-05-06T13:14:52.338Z DEBUG modem << Need to send 1 more messages:
2021-05-06T13:14:52.340Z DEBUG modem << [mqtt_evt_handler:228] PUBACK packet id: 57842
2021-05-06T13:14:52.394Z DEBUG modem << [mqtt_evt_handler:228] PUBACK packet id: 40203
2021-05-06T13:14:52.504Z DEBUG modem << [mqtt_evt_handler:228] PUBACK packet id: 64638
2021-05-06T13:14:52.610Z DEBUG modem << [mqtt_evt_handler:228] PUBACK packet id: 16928
2021-05-06T13:14:52.714Z DEBUG modem << [mqtt_evt_handler:228] PUBACK packet id: 2013
2021-05-06T13:14:52.824Z DEBUG modem << [mqtt_evt_handler:228] PUBACK packet id: 33027
2021-05-06T13:14:52.929Z DEBUG modem << [mqtt_evt_handler:228] PUBACK packet id: 35107
2021-05-06T13:14:53.034Z DEBUG modem << [mqtt_evt_handler:228] PUBACK packet id: 41187
2021-05-06T13:14:53.144Z DEBUG modem << [mqtt_evt_handler:228] PUBACK packet id: 12934
2021-05-06T13:14:53.299Z DEBUG modem << [mqtt_evt_handler:178] MQTT client disconnected 0
2021-05-06T13:14:53.300Z DEBUG modem << All messages have been send!
2021-05-06T13:15:00.384Z DEBUG modem >> AT+CESQ
2021-05-06T13:15:00.408Z DEBUG modem << +CESQ: 99,99,255,255,255,255
2021-05-06T13:15:00.410Z DEBUG modem << OK
2021-05-06T13:15:01.456Z DEBUG modem << ----------------------------------------------------------------
2021-05-06T13:15:01.458Z DEBUG modem << work_handler_fota started!
2021-05-06T13:15:01.458Z DEBUG modem << Initializing MQTT AWS broker via mqtt_aws_init()...
2021-05-06T13:15:02.953Z DEBUG modem << IPv4 Address 18.194.135.217
2021-05-06T13:15:02.955Z DEBUG modem << MQTT AWS client id: nrf-testing1
2021-05-06T13:15:09.881Z DEBUG modem << Initializing aws_fota_init()...
2021-05-06T13:15:10.104Z DEBUG modem << [mqtt_evt_handler:162] MQTT client connected!
2021-05-06T13:15:10.105Z DEBUG modem << Subscribing to: sensorstest1/nrf352656100980047/commands2
2021-05-06T13:15:10.508Z DEBUG modem << [mqtt_evt_handler:228] PUBACK packet id: 15325
2021-05-06T13:15:10.892Z DEBUG modem << [mqtt_evt_handler:228] PUBACK packet id: 10780
2021-05-06T13:15:14.384Z DEBUG modem >> AT+CESQ
2021-05-06T13:15:14.404Z DEBUG modem << +CESQ: 99,99,255,255,19,51
2021-05-06T13:15:14.405Z DEBUG modem << OK
2021-05-06T13:15:28.384Z DEBUG modem >> AT+CESQ
2021-05-06T13:15:28.404Z DEBUG modem << +CESQ: 99,99,255,255,255,255
2021-05-06T13:15:28.406Z DEBUG modem << OK
2021-05-06T13:15:42.383Z DEBUG modem >> AT+CESQ
2021-05-06T13:15:42.411Z DEBUG modem << +CESQ: 99,99,255,255,255,255
2021-05-06T13:15:42.413Z DEBUG modem << OK
2021-05-06T13:15:56.384Z DEBUG modem >> AT+CESQ
2021-05-06T13:15:56.406Z DEBUG modem << +CESQ: 99,99,255,255,255,255
2021-05-06T13:15:56.407Z DEBUG modem << OK
2021-05-06T13:16:10.384Z DEBUG modem >> AT+CESQ
2021-05-06T13:16:10.405Z DEBUG modem << +CESQ: 99,99,255,255,255,255
2021-05-06T13:16:10.407Z DEBUG modem << OK
2021-05-06T13:16:11.154Z DEBUG modem << [mqtt_evt_handler:228] PUBACK packet id: 43339
2021-05-06T13:16:12.717Z DEBUG modem << I: Configuring socket timeout (30 s)
2021-05-06T13:16:12.719Z DEBUG modem << I: Connecting to nrfbuc.s3.eu-central-1.amazonaws.com
2021-05-06T13:16:13.151Z DEBUG modem << I: Downloading: app_update.bin [0]
2021-05-06T13:16:13.159Z DEBUG modem << AWS_FOTA_EVT_START, job id = 0605check5
2021-05-06T13:16:13.161Z DEBUG modem << [mqtt_evt_handler:228] PUBACK packet id: 49032
2021-05-06T13:16:13.163Z DEBUG modem << E: Job document update was rejected
2021-05-06T13:16:13.164Z DEBUG modem << E: Job document update was rejected
2021-05-06T13:16:13.165Z DEBUG modem << E: {"clientToken":"","timestamp":1620306972,"executionState":{"status":"IN_PROGRESS","versionNumber":2},"code":"VersionMismatch","message":"Expected version 1 but found version 2"}:1,"jobDocument":{"operation":"app_fw_update","fwversion":"v1.0.2","size":181124,"location":{"protocol":"http:","host":"nrfbuc.s3.eu-central-1.amazonaws.com","path":"app_update.bin"}}}}
2021-05-06T13:16:13.167Z DEBUG modem << AWS_FOTA_EVT_ERROR
2021-05-06T13:16:13.168Z DEBUG modem << aws_fota_mqtt_evt_handler: Failed! -14
2021-05-06T13:16:13.172Z DEBUG modem << [mqtt_evt_handler:190] MQTT PUBLISH result=0 len=177
2021-05-06T13:16:13.206Z DEBUG modem << mqtt_read_publish_payload: Failed! -122
2021-05-06T13:16:13.207Z DEBUG modem << Disconnecting MQTT client...
2021-05-06T13:16:13.208Z DEBUG modem << [mqtt_evt_handler:178] MQTT client disconnected 0
2021-05-06T13:16:13.208Z DEBUG modem << Received: FOTA
2021-05-06T13:16:13.208Z DEBUG modem << Payload buf is : FOTA
2021-05-06T13:16:13.209Z DEBUG modem << ERROR: mqtt_live -128
2021-05-06T13:16:13.209Z DEBUG modem << mqtt_aws_run failed!
2021-05-06T13:16:13.209Z DEBUG modem << ----------------------------------------------------------------
2021-05-06T13:16:13.210Z DEBUG modem << work_handler_collect_data started!
2021-05-06T13:16:13.210Z DEBUG modem << Getting latest time...done!
2021-05-06T13:16:13.210Z DEBUG modem << Reading out bosch sensor...done!
2021-05-06T13:16:13.211Z DEBUG modem << Reading out modem info...done!
2021-05-06T13:16:14.243Z DEBUG modem << Reading out Teros12 sensor...done!
2021-05-06T13:16:14.245Z DEBUG modem << ++++++++++++++++++++++++++++++++++++++++++++
2021-05-06T13:16:14.246Z DEBUG modem << Measured data:
2021-05-06T13:16:14.247Z DEBUG modem <<        Timer: 2021-05-06 13:16:12
2021-05-06T13:16:14.248Z DEBUG modem <<  #msg queued: 0
2021-05-06T13:16:14.249Z DEBUG modem <<  Temperature: 27.030 degC
2021-05-06T13:16:14.250Z DEBUG modem <<     Pressure: 94.500 
2021-05-06T13:16:14.251Z DEBUG modem <<     Humidity: 23.633 
2021-05-06T13:16:14.252Z DEBUG modem <<     SoilTemp: 23.100 degC
2021-05-06T13:16:14.254Z DEBUG modem <<    VolWaterC: 1775.300
2021-05-06T13:16:14.255Z DEBUG modem <<   Modem bat.: 4.414 V
2021-05-06T13:16:14.256Z DEBUG modem <<   Current band: 8
2021-05-06T13:16:14.257Z DEBUG modem <<         RSRP: 88
2021-05-06T13:16:14.258Z DEBUG modem << ++++++++++++++++++++++++++++++++++++++++++++
2021-05-06T13:16:14.259Z DEBUG modem << ----------------------------------------------------------------
2021-05-06T13:16:14.260Z DEBUG modem << work_handler_send_data started!
2021-05-06T13:16:14.261Z DEBUG modem << Length of message queue : 1
2021-05-06T13:16:14.262Z DEBUG modem << mqtt_meter_init running...
2021-05-06T13:16:14.263Z DEBUG modem << IPv4 Address 13.80.240.194
2021-05-06T13:16:14.264Z DEBUG modem << MQTT Meter client id: Meter
2021-05-06T13:16:14.459Z DEBUG modem << 1785.6 23.1 0
2021-05-06T13:16:14.482Z DEBUG modem << gI: Downloaded 2048/237247 bytes (0%)
2021-05-06T13:16:14.486Z DEBUG modem << JI: 2 Sectors of 4096 bytes
2021-05-06T13:16:14.487Z DEBUG modem << I: alloc wra: 0, ff0
2021-05-06T13:16:14.488Z DEBUG modem << I: data wra: 0, 0
2021-05-06T13:16:14.571Z DEBUG modem << V
2021-05-06T13:16:17.050Z DEBUG modem << Using device imei: 352656100980047
2021-05-06T13:16:17.052Z DEBUG modem << mqtt_meter_init finished!
2021-05-06T13:16:17.052Z DEBUG modem << Starting to send 1 messages:
2021-05-06T13:16:17.052Z DEBUG modem << Need to send 1 more messages:

It says a mismatch error but I could not understand what that is. This could maybe be related to my Job file as it says a mismatch.

I am attaching my job file for reference.

Fullscreen Job.txt Download

{
  "operation": "app_fw_update",
  "fwversion": "v1.0.2",
  "size": 181124,
  "location": {
    "protocol": "http:",
    "host": "nrfbuc.s3.eu-central-1.amazonaws.com",
    "path": "app_update.bin"
   }
}

Could you let me know what this error means ? 

One thing that is peculiar here is that : FOTA update is successful once, but is rejected the next time.

Its happening in an alternate way (once successful, once rejected) which is really weird.

Regards,

Adeel.

[Marte Myrvold]

Hi,

From your log I can see that is says VersionMismatch. You get this error if the version of the job executed stored in Jobs does not match expected version. Each time you update the job execution, its version is incremented. So it seems like the version has incremented for some reason when it should not have, or that the expected version is incorrect. I am not certain why there is a mismatch, as I have not seen this error happening in NCS before. There could be a problem if you are running multiple instances of the same job simultaneously. I did find someone experiencing the same issue on the AWS forum, so you can try the suggestion there. I will keep looking into this and see if I can find any reasons for why you are getting VersionMismatch.

Best regards,

Marte

[Adeel]

Hi Marte,

Thanks, that would be great. Also, I sometimes face an issue where I have no job available and the AWS MQTT stays connected. I want it to disconnect gracefully if there is no job in the server. 

How can I have a do an implementation wherein the MQTT can gracefully disconnect if it cannot find any job in the AWS IoT jobs ? Currently, it stays connected all the time and does not disconnect.

Regards,

Adeel.

[Marte Myrvold]

Hi,

Are you experiencing the VersionMismatch issue if you use a clean version of the AWS FOTA sample, or only with your own application?

You can disconnect from the MQTT client with the function mqtt_disconnect(). What you want the trigger that causes your device to disconnect to be is up to you. In the AWS FOTA sample the device subscribes to the app_fw_update job topic, so it will be notified when a update job is created. In this case you can for example disconnect if you do not receive any messages on this topic.

Best regards,

Marte