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,

The job version that version mismatch reacts to is not the same as fwversion, but the version of the job execution. This will be the field "versionNumber" in a JobExecution object, which can for example look like:

{
"execution" : {
    "jobId" : "022",
    "thingName" : "MyThing",
    "jobDocument" : "< contents of job document >",
    "status" : "IN_PROGRESS",
    "queuedAt" : 1489096123309,
    "lastUpdatedAt" : 1489096123309,
    "versionNumber" : 1,
    "executionNumber" : 1234567890
},
"clientToken" : "client-1",
"timestamp" : 1489088524284,
}

You can read more about job executions here and here. I have not been able to figure out what might cause this error, as there is not much information about it unfortunately.

The device will subscribe to the topic, and if it receives a message it will go into the case MQTT_EVT_PUBLISH in mqtt_evt_handler(). It does not check the topic for messages and see if it is empty or if there is a message there. When it subscribes to a topic it will only receive a message when one is sent, and that is when it will react and handle that message. If you want to disconnect if it does not receive any messages on that topic for some time you can create some sort of timer or timeout, and then disconnect if it times out without any new messages being received on the topic.

Best regards,

Marte

[Adeel]

Hi Marte,

Thanks for clarifying this for me. I actually am no longer getting the Version Mismatch error.

I am getting a different error which i will try to briefly explain to get some inputs from you:   

I am actually connecting to a different server and subscribing to it via MQTT and getting a command from the server. The command is received by the device when it subscribes to the server. I try to initiate my FOTA update through this command (FOTA). When I do it, the FOTA works perfectly once and updates. When I try to do it the next time, I get a Job rejected error inspite of having a job available in the AWS IoT. 

I get an error that I think is mostly due a conflict with the MQTT payload buf. 

Fullscreen Error in 2nd FOTA update.txt Download

2021-05-12T12:05:11.478Z INFO Application data folder: C:\Users\adeel\AppData\Roaming\nrfconnect\pc-nrfconnect-linkmonitor
2021-05-12T12:05:11.494Z VERBOSE Could not fetch serial number for serial port at COM3
2021-05-12T12:05:11.494Z VERBOSE Could not fetch serial number for serial port at COM1
2021-05-12T12:05:11.578Z DEBUG App pc-nrfconnect-linkmonitor v1.1.10 official
2021-05-12T12:05:11.579Z DEBUG App path: C:\Users\adeel\.nrfconnect-apps\node_modules\pc-nrfconnect-linkmonitor
2021-05-12T12:05:11.579Z DEBUG nRFConnect 3.6.1 is supported by the app (^3.6.0)
2021-05-12T12:05:11.579Z DEBUG nRFConnect path: C:\Users\adeel\AppData\Local\Programs\nrfconnect\resources\app.asar
2021-05-12T12:05:11.580Z DEBUG HomeDir: C:\Users\adeel
2021-05-12T12:05:11.580Z DEBUG TmpDir: C:\Users\adeel\AppData\Local\Temp
2021-05-12T12:05:30.576Z INFO Modem port is opened
2021-05-12T12:05:30.582Z DEBUG modem >> AT+CFUN?
2021-05-12T12:05:30.608Z DEBUG modem << +CFUN: 1
2021-05-12T12:05:30.611Z DEBUG modem << OK
2021-05-12T12:05:30.628Z DEBUG modem >> AT+CGSN=1
2021-05-12T12:05:30.637Z DEBUG modem << +CGSN: "352656101119801"
2021-05-12T12:05:30.639Z DEBUG modem << OK
2021-05-12T12:05:30.642Z DEBUG modem >> AT+CGMI
2021-05-12T12:05:30.650Z DEBUG modem << Nordic Semiconductor ASA
2021-05-12T12:05:30.652Z DEBUG modem << OK
2021-05-12T12:05:30.659Z DEBUG modem >> AT+CGMM
2021-05-12T12:05:30.666Z DEBUG modem << nRF9160-SICA
2021-05-12T12:05:30.668Z DEBUG modem << OK
2021-05-12T12:05:30.670Z DEBUG modem >> AT+CGMR
2021-05-12T12:05:30.678Z DEBUG modem << mfw_nrf9160_1.2.2-FOTA-TEST
2021-05-12T12:05:30.680Z DEBUG modem << OK
2021-05-12T12:05:30.681Z INFO Nordic Semiconductor ASA nRF9160-SICA [mfw_nrf9160_1.2.2-FOTA-TEST] SerNr: 352656101119801
2021-05-12T12:05:30.683Z DEBUG modem >> AT+CEMODE?
2021-05-12T12:05:30.690Z DEBUG modem << +CEMODE: 0
2021-05-12T12:05:30.692Z DEBUG modem << OK
2021-05-12T12:05:30.699Z DEBUG modem >> AT%XCBAND=?
2021-05-12T12:05:30.711Z DEBUG modem << %XCBAND: (1,2,3,4,5,8,12,13,17,19,20,25,26,28,66)
2021-05-12T12:05:30.715Z DEBUG modem << OK
2021-05-12T12:05:30.730Z DEBUG modem >> AT+CMEE?
2021-05-12T12:05:30.737Z DEBUG modem << +CMEE: 0
2021-05-12T12:05:30.739Z DEBUG modem << OK
2021-05-12T12:05:30.742Z DEBUG modem >> AT+CMEE=1
2021-05-12T12:05:30.749Z DEBUG modem << OK
2021-05-12T12:05:30.755Z DEBUG modem >> AT+CNEC?
2021-05-12T12:05:30.763Z DEBUG modem << +CNEC: 0
2021-05-12T12:05:30.764Z DEBUG modem << OK
2021-05-12T12:05:30.768Z DEBUG modem >> AT+CNEC=24
2021-05-12T12:05:30.775Z DEBUG modem << OK
2021-05-12T12:05:30.779Z DEBUG modem >> AT+CGEREP?
2021-05-12T12:05:30.789Z DEBUG modem << +CGEREP: 0,0
2021-05-12T12:05:30.794Z DEBUG modem << OK
2021-05-12T12:05:30.798Z DEBUG modem >> AT+CGDCONT?
2021-05-12T12:05:30.805Z DEBUG modem << OK
2021-05-12T12:05:30.808Z DEBUG modem >> AT+CGACT?
2021-05-12T12:05:30.814Z DEBUG modem << OK
2021-05-12T12:05:30.819Z DEBUG modem >> AT+CGEREP=1
2021-05-12T12:05:30.826Z DEBUG modem << OK
2021-05-12T12:05:30.830Z DEBUG modem >> AT+CIND=1,1,1
2021-05-12T12:05:30.836Z DEBUG modem << OK
2021-05-12T12:05:30.841Z DEBUG modem >> AT+CEREG=5
2021-05-12T12:05:30.855Z DEBUG modem << OK
2021-05-12T12:05:30.859Z DEBUG modem >> AT+CEREG?
2021-05-12T12:05:30.872Z DEBUG modem << +CEREG: 5,4,"FFFE","FFFFFFFF",9,0,0,"00000000","00000000"
2021-05-12T12:05:30.873Z DEBUG modem << OK
2021-05-12T12:05:30.879Z DEBUG modem >> AT%CESQ=1
2021-05-12T12:05:30.887Z DEBUG modem << OK
2021-05-12T12:05:30.891Z DEBUG modem >> AT+CESQ
2021-05-12T12:05:30.900Z DEBUG modem << +CESQ: 99,99,255,255,255,255
2021-05-12T12:05:30.902Z DEBUG modem << OK
2021-05-12T12:05:30.907Z DEBUG modem >> AT%XSIM=1
2021-05-12T12:05:30.913Z DEBUG modem << OK
2021-05-12T12:05:30.919Z DEBUG modem >> AT%XSIM?
2021-05-12T12:05:30.926Z DEBUG modem << %XSIM: 0
2021-05-12T12:05:30.927Z DEBUG modem << OK
2021-05-12T12:05:33.879Z DEBUG modem << meter_modem_data_init()...
2021-05-12T12:05:33.880Z DEBUG modem << LTE connection established!
2021-05-12T12:05:33.911Z DEBUG modem << E: Link data not obtained: 20 -22
2021-05-12T12:05:33.913Z DEBUG modem << E: Network data not obtained: -22
2021-05-12T12:05:33.914Z DEBUG modem << Modem Infos:
2021-05-12T12:05:33.915Z DEBUG modem <<          IP: 10.205.85.10
2021-05-12T12:05:33.915Z DEBUG modem <<     ue_mode: 0
2021-05-12T12:05:33.916Z DEBUG modem <<    lte_mode: 0
2021-05-12T12:05:33.916Z DEBUG modem <<    current_band: 8
2021-05-12T12:05:33.917Z DEBUG modem <<    area_code: 52015
2021-05-12T12:05:33.918Z DEBUG modem <<    operator: 26201
2021-05-12T12:05:33.918Z DEBUG modem <<    dev imei: 352656101119801
2021-05-12T12:05:33.918Z DEBUG modem <<    modem_firmware: 
2021-05-12T12:05:34.430Z DEBUG modem << DATE_TIME: got time from NTP.
2021-05-12T12:05:34.432Z DEBUG modem << Initialize cJSON...done!
2021-05-12T12:05:34.434Z DEBUG modem <<   Using cJSON ver. 1.7.12
2021-05-12T12:05:44.440Z DEBUG modem << ----------------------------------------------------------------
2021-05-12T12:05:44.441Z DEBUG modem << work_handler_collect_data started!
2021-05-12T12:05:44.948Z DEBUG modem << Getting latest time...done!
2021-05-12T12:05:44.949Z DEBUG modem << Reading out bosch sensor...done!
2021-05-12T12:05:44.959Z DEBUG modem << Reading out modem info...done!
2021-05-12T12:05:46.992Z DEBUG modem << Reading out Teros12 sensor...done!
2021-05-12T12:05:46.993Z DEBUG modem << ++++++++++++++++++++++++++++++++++++++++++++
2021-05-12T12:05:46.997Z DEBUG modem << Measured data:
2021-05-12T12:05:46.999Z DEBUG modem <<        Timer: 2021-05-12 12:05:44
2021-05-12T12:05:47.000Z DEBUG modem <<  #msg queued: 0
2021-05-12T12:05:47.002Z DEBUG modem <<  Temperature: 27.000 degC
2021-05-12T12:05:47.003Z DEBUG modem <<     Pressure: 94.785 
2021-05-12T12:05:47.004Z DEBUG modem <<     Humidity: 28.921 
2021-05-12T12:05:47.005Z DEBUG modem <<     SoilTemp: 0.000 degC
2021-05-12T12:05:47.006Z DEBUG modem <<    VolWaterC: 0.000
2021-05-12T12:05:47.006Z DEBUG modem <<   Modem bat.: 4.394 V
2021-05-12T12:05:47.007Z DEBUG modem <<   Current band: 8
2021-05-12T12:05:47.008Z DEBUG modem <<         RSRP: -141
2021-05-12T12:05:47.008Z DEBUG modem << ++++++++++++++++++++++++++++++++++++++++++++
2021-05-12T12:05:49.442Z DEBUG modem << ----------------------------------------------------------------
2021-05-12T12:05:49.444Z DEBUG modem << work_handler_send_data started!
2021-05-12T12:05:49.445Z DEBUG modem << Length of message queue : 1
2021-05-12T12:05:49.944Z DEBUG modem << mqtt_meter_init running...
2021-05-12T12:05:51.632Z DEBUG modem << IPv4 Address 13.80.240.194
2021-05-12T12:05:51.633Z DEBUG modem << MQTT Meter client id: Meter
2021-05-12T12:05:51.730Z DEBUG modem << Using device imei: 352656101119801
2021-05-12T12:05:51.731Z DEBUG modem << mqtt_meter_init finished!
2021-05-12T12:05:51.735Z DEBUG modem << Starting to send 1 messages:
2021-05-12T12:05:51.737Z DEBUG modem << Need to send 1 more messages:
2021-05-12T12:05:51.832Z DEBUG modem << [mqtt_evt_handler:179] MQTT client connected!
2021-05-12T12:05:51.837Z DEBUG modem << Subscribing to: sensorstest1/nrf352656101119801/command
2021-05-12T12:05:51.922Z DEBUG modem << [mqtt_evt_handler:287] SUBACK packet id: 1234
2021-05-12T12:05:52.027Z DEBUG modem << [mqtt_evt_handler:276] PUBACK packet id: 40847
2021-05-12T12:05:52.138Z DEBUG modem << [mqtt_evt_handler:276] PUBACK packet id: 20109
2021-05-12T12:05:52.250Z DEBUG modem << [mqtt_evt_handler:276] PUBACK packet id: 4352
2021-05-12T12:05:52.370Z DEBUG modem << [mqtt_evt_handler:276] PUBACK packet id: 58206
2021-05-12T12:05:52.482Z DEBUG modem << [mqtt_evt_handler:276] PUBACK packet id: 51472
2021-05-12T12:05:52.593Z DEBUG modem << [mqtt_evt_handler:276] PUBACK packet id: 60475
2021-05-12T12:05:52.697Z DEBUG modem << [mqtt_evt_handler:276] PUBACK packet id: 41695
2021-05-12T12:05:52.852Z DEBUG modem << [mqtt_evt_handler:197] MQTT client disconnected 0
2021-05-12T12:05:52.857Z DEBUG modem << All messages have been send!
2021-05-12T12:06:44.437Z DEBUG modem << ----------------------------------------------------------------
2021-05-12T12:06:44.439Z DEBUG modem << work_handler_collect_data started!
2021-05-12T12:06:44.946Z DEBUG modem << Getting latest time...done!
2021-05-12T12:06:44.946Z DEBUG modem << Reading out bosch sensor...done!
2021-05-12T12:06:44.957Z DEBUG modem << Reading out modem info...done!
2021-05-12T12:06:46.989Z DEBUG modem << Reading out Teros12 sensor...done!
2021-05-12T12:06:46.990Z DEBUG modem << ++++++++++++++++++++++++++++++++++++++++++++
2021-05-12T12:06:46.995Z DEBUG modem << Measured data:
2021-05-12T12:06:46.996Z DEBUG modem <<        Timer: 2021-05-12 12:06:44
2021-05-12T12:06:46.998Z DEBUG modem <<  #msg queued: 0
2021-05-12T12:06:46.999Z DEBUG modem <<  Temperature: 27.020 degC
2021-05-12T12:06:46.999Z DEBUG modem <<     Pressure: 94.783 
2021-05-12T12:06:47.000Z DEBUG modem <<     Humidity: 29.003 
2021-05-12T12:06:47.000Z DEBUG modem <<     SoilTemp: 0.000 degC
2021-05-12T12:06:47.001Z DEBUG modem <<    VolWaterC: 0.000
2021-05-12T12:06:47.001Z DEBUG modem <<   Modem bat.: 4.394 V
2021-05-12T12:06:47.001Z DEBUG modem <<   Current band: 8
2021-05-12T12:06:47.002Z DEBUG modem <<         RSRP: -100
2021-05-12T12:06:47.002Z DEBUG modem << ++++++++++++++++++++++++++++++++++++++++++++
2021-05-12T12:07:44.435Z DEBUG modem << ----------------------------------------------------------------
2021-05-12T12:07:44.436Z DEBUG modem << work_handler_collect_data started!
2021-05-12T12:07:44.944Z DEBUG modem << Getting latest time...done!
2021-05-12T12:07:44.945Z DEBUG modem << Reading out bosch sensor...done!
2021-05-12T12:07:44.955Z DEBUG modem << Reading out modem info...done!
2021-05-12T12:07:46.987Z DEBUG modem << Reading out Teros12 sensor...done!
2021-05-12T12:07:46.988Z DEBUG modem << ++++++++++++++++++++++++++++++++++++++++++++
2021-05-12T12:07:46.994Z DEBUG modem << Measured data:
2021-05-12T12:07:46.995Z DEBUG modem <<        Timer: 2021-05-12 12:07:44
2021-05-12T12:07:46.996Z DEBUG modem <<  #msg queued: 1
2021-05-12T12:07:46.997Z DEBUG modem <<  Temperature: 26.640 degC
2021-05-12T12:07:46.997Z DEBUG modem <<     Pressure: 94.783 
2021-05-12T12:07:46.998Z DEBUG modem <<     Humidity: 29.384 
2021-05-12T12:07:46.998Z DEBUG modem <<     SoilTemp: 0.000 degC
2021-05-12T12:07:46.999Z DEBUG modem <<    VolWaterC: 0.000
2021-05-12T12:07:47.000Z DEBUG modem <<   Modem bat.: 4.394 V
2021-05-12T12:07:47.001Z DEBUG modem <<   Current band: 8
2021-05-12T12:07:47.001Z DEBUG modem <<         RSRP: -100
2021-05-12T12:07:47.002Z DEBUG modem << ++++++++++++++++++++++++++++++++++++++++++++
2021-05-12T12:07:49.438Z DEBUG modem << ----------------------------------------------------------------
2021-05-12T12:07:49.439Z DEBUG modem << work_handler_send_data started!
2021-05-12T12:07:49.445Z DEBUG modem << Length of message queue : 2
2021-05-12T12:07:49.940Z DEBUG modem << mqtt_meter_init running...
2021-05-12T12:07:49.954Z DEBUG modem << IPv4 Address 13.80.240.194
2021-05-12T12:07:49.955Z DEBUG modem << MQTT Meter client id: Meter
2021-05-12T12:07:52.409Z DEBUG modem << Using device imei: 352656101119801
2021-05-12T12:07:52.411Z DEBUG modem << mqtt_meter_init finished!
2021-05-12T12:07:52.417Z DEBUG modem << Starting to send 2 messages:
2021-05-12T12:07:52.418Z DEBUG modem << Need to send 2 more messages:
2021-05-12T12:07:52.511Z DEBUG modem << [mqtt_evt_handler:179] MQTT client connected!
2021-05-12T12:07:52.512Z DEBUG modem << Subscribing to: sensorstest1/nrf352656101119801/command
2021-05-12T12:07:52.634Z DEBUG modem << MQTT PUBLISH result=0 len=4
2021-05-12T12:07:52.635Z DEBUG modem << Received MQTT Buf: 
2021-05-12T12:07:52.635Z DEBUG modem << FOTA
2021-05-12T12:07:52.636Z DEBUG modem << Payload buf is : FOTA
2021-05-12T12:07:52.736Z DEBUG modem << [mqtt_evt_handler:287] SUBACK packet id: 1234
2021-05-12T12:07:52.841Z DEBUG modem << [mqtt_evt_handler:276] PUBACK packet id: 16585
2021-05-12T12:07:52.946Z DEBUG modem << [mqtt_evt_handler:276] PUBACK packet id: 3144
2021-05-12T12:07:53.066Z DEBUG modem << [mqtt_evt_handler:276] PUBACK packet id: 51224
2021-05-12T12:07:53.169Z DEBUG modem << [mqtt_evt_handler:276] PUBACK packet id: 56557
2021-05-12T12:07:53.281Z DEBUG modem << [mqtt_evt_handler:276] PUBACK packet id: 11750
2021-05-12T12:07:53.394Z DEBUG modem << [mqtt_evt_handler:276] PUBACK packet id: 59118
2021-05-12T12:07:53.548Z DEBUG modem << Need to send 1 more messages:
2021-05-12T12:07:53.557Z DEBUG modem << [mqtt_evt_handler:276] PUBACK packet id: 48968
2021-05-12T12:07:53.610Z DEBUG modem << [mqtt_evt_handler:276] PUBACK packet id: 29619
2021-05-12T12:07:53.721Z DEBUG modem << [mqtt_evt_handler:276] PUBACK packet id: 18647
2021-05-12T12:07:53.826Z DEBUG modem << [mqtt_evt_handler:276] PUBACK packet id: 44297
2021-05-12T12:07:53.936Z DEBUG modem << [mqtt_evt_handler:276] PUBACK packet id: 56929
2021-05-12T12:07:54.048Z DEBUG modem << [mqtt_evt_handler:276] PUBACK packet id: 63531
2021-05-12T12:07:54.161Z DEBUG modem << [mqtt_evt_handler:276] PUBACK packet id: 22827
2021-05-12T12:07:54.266Z DEBUG modem << [mqtt_evt_handler:276] PUBACK packet id: 43565
2021-05-12T12:07:54.386Z DEBUG modem << [mqtt_evt_handler:276] PUBACK packet id: 43866
2021-05-12T12:07:54.540Z DEBUG modem << [mqtt_evt_handler:197] MQTT client disconnected 0
2021-05-12T12:07:54.542Z DEBUG modem << All messages have been send!
2021-05-12T12:08:02.643Z DEBUG modem << ----------------------------------------------------------------
2021-05-12T12:08:02.644Z DEBUG modem << work_handler_fota started!
2021-05-12T12:08:03.147Z DEBUG modem << Initializing MQTT AWS broker via mqtt_aws_init()...
2021-05-12T12:08:05.267Z DEBUG modem << IPv4 Address 18.159.13.101
2021-05-12T12:08:05.268Z DEBUG modem << MQTT AWS client id: nrf-testing1
2021-05-12T12:08:11.033Z DEBUG modem << Initializing aws_fota_init()...
2021-05-12T12:08:11.274Z DEBUG modem << [mqtt_evt_handler:179] MQTT client connected!
2021-05-12T12:08:11.686Z DEBUG modem << [mqtt_evt_handler:276] PUBACK packet id: 55247
2021-05-12T12:08:12.034Z DEBUG modem << [mqtt_evt_handler:276] PUBACK packet id: 59550
2021-05-12T12:09:12.291Z DEBUG modem << [mqtt_evt_handler:276] PUBACK packet id: 16638
2021-05-12T12:09:14.471Z DEBUG modem << I: Configuring socket timeout (30 s)
2021-05-12T12:09:14.477Z DEBUG modem << I: Connecting to nrfbuc.s3.eu-central-1.amazonaws.com
2021-05-12T12:09:14.796Z DEBUG modem << I: Downloading: app_update.bin [0]
2021-05-12T12:09:14.803Z DEBUG modem << AWS_FOTA_EVT_START, job id = 3
2021-05-12T12:09:14.805Z DEBUG modem << [mqtt_evt_handler:276] PUBACK packet id: 22132
2021-05-12T12:09:14.807Z DEBUG modem << E: Job document update was rejected
2021-05-12T12:09:14.808Z DEBUG modem << E: Job document update was rejected
2021-05-12T12:09:14.846Z DEBUG modem << [mqtt_evt_handler:197] MQTT client disconnected 0
2021-05-12T12:09:14.848Z DEBUG modem << Disconnecting MQTT client again again...
2021-05-12T12:09:14.849Z DEBUG modem << E: Error -5 when getting the payload
2021-05-12T12:09:14.849Z DEBUG modem << aws_fota_mqtt_evt_handler: Failed! -5
2021-05-12T12:09:14.851Z DEBUG modem << [mqtt_evt_handler:210] MQTT PUBLISH result=0 len=177
2021-05-12T12:09:14.852Z DEBUG modem << mqtt_read_publish_payload: Failed! -5
2021-05-12T12:09:14.852Z DEBUG modem << Disconnecting MQTT client...
2021-05-12T12:09:14.852Z DEBUG modem << Could not disconnect: -128
2021-05-12T12:09:14.853Z DEBUG modem << Received AWS Buf: {"state":{"reported":{"nrfcloud__dfu_v1__app_v":"v1.0.0"}}}
2021-05-12T12:09:14.854Z DEBUG modem << ERROR: mqtt_live -128
2021-05-12T12:09:14.855Z DEBUG modem << mqtt_aws_run failed!
2021-05-12T12:09:14.856Z DEBUG modem << ----------------------------------------------------------------
2021-05-12T12:09:14.857Z DEBUG modem << work_handler_collect_data started!
2021-05-12T12:09:15.348Z DEBUG modem << Getting latest time...done!
2021-05-12T12:09:15.359Z DEBUG modem << Reading out bosch sensor...done!
2021-05-12T12:09:15.360Z DEBUG modem << Reading out modem info...done!
2021-05-12T12:09:16.153Z DEBUG modem << Reading out Teros12 sensor...I: Downloaded 2048/234807 bytes (0%)
2021-05-12T12:09:16.162Z DEBUG modem << I: 2 Sectors of 4096 bytes
2021-05-12T12:09:16.163Z DEBUG modem << I: alloc wra: 0, ff0
2021-05-12T12:09:16.165Z DEBUG modem << I: data wra: 0, 0
2021-05-12T12:09:17.390Z DEBUG modem << done!
2021-05-12T12:09:17.391Z DEBUG modem << ++++++++++++++++++++++++++++++++++++++++++++
2021-05-12T12:09:17.398Z DEBUG modem << Measured data:
2021-05-12T12:09:17.399Z DEBUG modem <<        Timer: 2021-05-12 12:09:14
2021-05-12T12:09:17.400Z DEBUG modem <<  #msg queued: 0
2021-05-12T12:09:17.400Z DEBUG modem <<  Temperature: 26.230 degC
2021-05-12T12:09:17.401Z DEBUG modem <<     Pressure: 94.785 
2021-05-12T12:09:17.401Z DEBUG modem <<     Humidity: 30.000 
2021-05-12T12:09:17.401Z DEBUG modem <<     SoilTemp: 0.000 degC
2021-05-12T12:09:17.402Z DEBUG modem <<    VolWaterC: 0.000
2021-05-12T12:09:17.402Z DEBUG modem <<   Modem bat.: 4.394 V
2021-05-12T12:09:17.402Z DEBUG modem <<   Current band: 8
2021-05-12T12:09:17.403Z DEBUG modem <<         RSRP: -99
2021-05-12T12:09:17.403Z DEBUG modem << ++++++++++++++++++++++++++++++++++++++++++++
2021-05-12T12:09:20.008Z DEBUG modem << I: Downloaded 4096/234807 bytes (1%)

Could you help me understand where the issue could be ? I have integrated the AWS_FOTA sample (for my FOTA updates) in my application along with the mqtt_simple application (for my MQTT data) as well.

Regards,

Adeel

[Marte Myrvold]

Hi Adeel,

I see you are getting errors -5 and -128. -5 is EIO (input/output error), and -128 is ENOTCONN (socket is not connected). In cellular examples, EIO can be returned if you are sending an AT command to the modem and the function failed to send the command, but I am not certain why you are getting that error in your case.

Could you get a modem trace of when this happens and attach it here?

Best regards,

Marte

[Adeel]

Hi Marte,

Sorry for the late reply. Actually the issue that I have noticed is that if I keep a job in queue before connecting to the AWS IoT, then the job is not picked up by the Thingy.

However, if I create the job when the Thingy is subscribed to the AWS , then it works perfectly. So, as a work around for now, I am creating the job when I am subscribing to the FOTA and that works for now.

What I am curious to see is why does the issue occur when the job is already created and queued in the Job section of AWS IoT:

Also, could you let me know how to get the modem trace from the Link monitor ?

Regards,

Adeel.

[Marte Myrvold]

Hi Adeel,

Good to hear that you figured out what was causing the issue, and that you were able to create a workaround for now.

Have you tested how this works with the AWS FOTA sample, is the behavior the same there when you have a job in queue before your device connects? It might be related to how AWS IoT notifies your device about a job. As I have mentioned before, in the sample the device receives notifications about available jobs through MQTT, by subscribing to the app_fw_update job topic. So it might be that AWS IoT only sends a notification on this topic when the job is created. If so, you should see the same behavior in the AWS FOTA sample as well, and you will have to implement something so that it will notify your device later if it is not connected when the job is created. The other possibility is that there is something on the application side that causes you to not receive this notification.

Modem trace is used by us to look at the communication with the modem, to try and figure out what is wrong if for example a disconnect happens. Since it seems like you have figured out what the problem it, I am not sure a modem trace is necessary, but you can still get one if you are still seeing errors from the modem in your log. You must use the Trace Collector in nRF Connect for Desktop to get a modem trace. The guide for doing this with Thingy:91 can be found here. Make sure that you have updated the board controller firmware and enabled tracing in the application.

Best regards,

Marte