nrF9160 sample aws_fota

[dermot geraghty]

I am trying to implement the AWS FOTA sample from SDK V1.4.2.

I have already implemented the AWS IOT sample which works fine.

However, the AWS FOTA fails with mqtt_connect errror -22.

The log is shown below:

*** Booting Zephyr OS build v2.4.0-ncs2  ***

MQTT AWS Jobs FOTA Sample, version: 2.0.0

Initializing bsdlib

Initialized bsdlib

LTE Link Connecting ...

I: PDP Context: AT+CGDCONT=1,"IP","arkessalp.com"

LTE Link Connected!

IPv4 Address 54.154.11.137

client_id: TDG_logger_thing

mqtt_transport_connect FAILED

ERROR: mqtt_connect -22

My prj.cfg file is attached:

5270.prj.conf

Can you point out where it's gone wrong?

[dermot geraghty]

Hi Marte,

Thanks for your help.

I have changed the prj.conf file as per your directions and moved things on a bit.

It does successfully connect to the MQTT broker but I'm not seeing that it is susbcribing to the topic (as per Nordic documentation)

[mqtt_evt_handler:129] MQTT client connected!
[00:00:14.106,140] <inf> aws_jobs: Subscribe: $aws/things/nrf-aws-fota/jobs/notify-next

My topic is:

$aws/things/TDG_logger_thing/jobs/notify-next

Here is what I am seeing:

client_id: TDG_logger_thing

hostname: a3vecosqszzrnz-ats.iot.eu-west-1.amazonaws.com

[mqtt_evt_handler:182] MQTT client connected!

[mqtt_evt_handler:235] PUBACK packet id: 50475

[mqtt_evt_handler:245] SUBACK packet id: 2114

[mqtt_evt_handler:193] MQTT client disconnected -128

ERROR: mqtt_input -128

Disconnecting MQTT client...

Could not disconnect MQTT client. Error: -128

Can you tell me what is wrong here?

Many thanks

[dermot geraghty]

Hi Marte,

We did follow the guide for setting up the S2 bucket and creating a thing in AWS IoT - and correctly I think.

I'm attaching the modem trace.

I am using nrF9160DK.

trace-2021-03-17T16-20-13.110Z.bin

,Thanks for your help,

Dermot

[dermot geraghty]

Hi Marte,

Sorry I meant to send you just the log from the most recent rest - attached now.

The previous resets I did myself.

For this log I deleted all job files on AWS and started a new one.

It looks like it is starting to do the down load but gets stuck.

On AWS its says the download is 'in progress'

Fullscreen log_24_03_nbr2.txt Download

2021-03-24T12:25:24.220Z DEBUG modem << *** Booting Zephyr OS build v2.4.0-ncs2  ***
2021-03-24T12:25:24.223Z DEBUG modem << MQTT AWS Jobs FOTA Sample, version: 2.0.0
2021-03-24T12:25:24.225Z DEBUG modem << Initializing bsdlib
2021-03-24T12:25:24.385Z DEBUG modem << Initialized bsdlib
2021-03-24T12:25:24.495Z DEBUG modem << LTE Link Connecting ...
2021-03-24T12:25:24.498Z DEBUG modem << D: Preferred system mode (2) is already configured
2021-03-24T12:25:24.500Z DEBUG modem << I: PDP Context: AT+CGDCONT=1,"IP","arkessalp.com"
2021-03-24T12:25:24.502Z DEBUG modem << D: Sending AT command to set system mode: AT%XSYSTEMMODE=0,1,0,0
2021-03-24T12:25:31.294Z DEBUG modem << D: +CEREG notification: +CEREG: 2,"2332","024A8E20",9,0,0,"11100000","11100000"
2021-03-24T12:25:31.518Z DEBUG modem << D: +CSCON notification
2021-03-24T12:25:32.454Z DEBUG modem << D: +CEREG notification: +CEREG: 5,"2332","024A8E20",9,,,"00011110","00000111"
2021-03-24T12:25:32.572Z DEBUG modem << D: TAU: 4200 sec, active time: 60 sec
2021-03-24T12:25:32.576Z DEBUG modem << LTE Link Connected!
2021-03-24T12:25:32.949Z DEBUG modem << IPv4 Address 34.253.2.95
2021-03-24T12:25:33.081Z DEBUG modem << client_id: TDG_logger_thing
2021-03-24T12:25:33.083Z DEBUG modem << D: (0x20022078): Created socket 1
2021-03-24T12:25:39.315Z DEBUG modem << D: (0x20022078): Connect completed
2021-03-24T12:25:39.414Z DEBUG modem << D: (0x20022078): Encoding Protocol Description. Str:MQTT Size:00000004.
2021-03-24T12:25:39.417Z DEBUG modem << D: (0x20022078): >> str_size:00000006 cur:0x20024113, end:0x2002418e
2021-03-24T12:25:39.421Z DEBUG modem << D: (0x20022078): >> val:0004 cur:0x20024113, end:0x2002418e
2021-03-24T12:25:39.424Z DEBUG modem << D: (0x20022078): Encoding Protocol Version 04.
2021-03-24T12:25:39.426Z DEBUG modem << D: (0x20022078): >> val:04 cur:0x20024119, end:0x2002418e
2021-03-24T12:25:39.428Z DEBUG modem << D: (0x20022078): >> val:00 cur:0x2002411a, end:0x2002418e
2021-03-24T12:25:39.430Z DEBUG modem << D: (0x20022078): Encoding Keep Alive Time 04b0.
2021-03-24T12:25:39.432Z DEBUG modem << D: (0x20022078): >> val:04b0 cur:0x2002411b, end:0x2002418e
2021-03-24T12:25:39.434Z DEBUG modem << D: (0x20022078): Encoding Client Id. Str:TDG_logger_thing Size:00000010.
2021-03-24T12:25:39.436Z DEBUG modem << D: (0x20022078): >> str_size:00000012 cur:0x2002411d, end:0x2002418e
2021-03-24T12:25:39.438Z DEBUG modem << D: (0x20022078): >> val:0010 cur:0x2002411d, end:0x2002418e
2021-03-24T12:25:39.441Z DEBUG modem << D: (0x20022078): << msg type:0x10 length:0x0000001c
2021-03-24T12:25:39.443Z DEBUG modem << D: (0x20022078): >> length:0x0000001c cur:0x00000000, end:0x00000000
2021-03-24T12:25:39.445Z DEBUG modem << D: (0x20022078): Fixed header length = 02
2021-03-24T12:25:39.447Z DEBUG modem << D: (0x20022078): >> val:10 cur:0x20024111, end:0x2002418e
2021-03-24T12:25:39.552Z DEBUG modem << D: (0x20022078): >> length:0x0000001c cur:0x20024112, end:0x2002418e
2021-03-24T12:25:39.556Z DEBUG modem << D: (0x20022078): Connect completed
2021-03-24T12:25:39.928Z DEBUG modem << D: (0x20022078): state:0x00000002
2021-03-24T12:25:40.055Z DEBUG modem << D: (0x20022078): >> cur:0x2002408e, end:0x20024090
2021-03-24T12:25:40.059Z DEBUG modem << D: (0x20022078): << val:20
2021-03-24T12:25:40.061Z DEBUG modem << D: (0x20022078): length:0x00000002
2021-03-24T12:25:40.063Z DEBUG modem << D: (0x20022078): [CID 0x20027f10]: Received MQTT_PKT_TYPE_CONNACK!
2021-03-24T12:25:40.066Z DEBUG modem << D: (0x20022078): >> cur:0x20024090, end:0x20024092
2021-03-24T12:25:40.068Z DEBUG modem << D: (0x20022078): << val:01
2021-03-24T12:25:40.070Z DEBUG modem << D: (0x20022078): >> cur:0x20024091, end:0x20024092
2021-03-24T12:25:40.073Z DEBUG modem << D: (0x20022078): << val:00
2021-03-24T12:25:40.075Z DEBUG modem << D: (0x20022078): [CID 0x20027f10]: session_present_flag: 1
2021-03-24T12:25:40.077Z DEBUG modem << D: (0x20022078): [CID 0x20027f10]: return_code: 0
2021-03-24T12:25:40.079Z DEBUG modem << D: Previous session valid; skipping FOTA subscriptions
2021-03-24T12:25:40.081Z DEBUG modem << D: Created notify_next_topic $aws/things/TDG_logger_thing/jobs/notify-next
2021-03-24T12:25:40.083Z DEBUG modem << D: Created get_topic $aws/things/TDG_logger_thing/jobs/$next/get/#
2021-03-24T12:25:40.085Z DEBUG modem << D: previously subscribed to notify-next topic
2021-03-24T12:25:40.087Z DEBUG modem << D: (0x20022078): [CID 0x20027f10]:[State 0x06]: >> Topic size 0x0000002b, Data size 0x00000013
2021-03-24T12:25:40.090Z DEBUG modem << D: (0x20022078): >> str_size:0000002d cur:0x20024113, end:0x2002418e
2021-03-24T12:25:40.092Z DEBUG modem << D: (0x20022078): >> val:002b cur:0x20024113, end:0x2002418e
2021-03-24T12:25:40.095Z DEBUG modem << D: (0x20022078): >> val:efdd cur:0x20024140, end:0x2002418e
2021-03-24T12:25:40.097Z DEBUG modem << D: (0x20022078): << msg type:0x32 length:0x00000042
2021-03-24T12:25:40.099Z DEBUG modem << D: (0x20022078): >> length:0x00000042 cur:0x00000000, end:0x00000000
2021-03-24T12:25:40.102Z DEBUG modem << D: (0x20022078): Fixed header length = 02
2021-03-24T12:25:40.208Z DEBUG modem << D: (0x20022078): >> val:32 cur:0x20024111, end:0x2002418e
2021-03-24T12:25:40.212Z DEBUG modem << D: (0x20022078): >> length:0x00000042 cur:0x20024112, end:0x2002418e
2021-03-24T12:25:40.214Z DEBUG modem << D: (0x20022078): [0x20027f10]: Transport writing message.
2021-03-24T12:25:40.216Z DEBUG modem << D: (0x20022078): [0x20027f10]: Transport write complete.
2021-03-24T12:25:40.218Z DEBUG modem << D: (0x20022078): [CID 0x20027f10]:[State 0x06]: << result 0x00000000
2021-03-24T12:25:40.220Z DEBUG modem << [mqtt_evt_handler:182] MQTT client connected!
2021-03-24T12:25:40.323Z DEBUG modem << D: (0x20022078): [CID 0x20027f10]:[State 0x06]: >> Topic size 0x0000002a, Data size 0x0000003a
2021-03-24T12:25:40.326Z DEBUG modem << D: (0x20022078): >> str_size:0000002c cur:0x20024113, end:0x2002418e
2021-03-24T12:25:40.328Z DEBUG modem << D: (0x20022078): >> val:002a cur:0x20024113, end:0x2002418e
2021-03-24T12:25:40.330Z DEBUG modem << D: (0x20022078): >> val:d889 cur:0x2002413f, end:0x2002418e
2021-03-24T12:25:40.333Z DEBUG modem << D: (0x20022078): << msg type:0x32 length:0x00000068
2021-03-24T12:25:40.335Z DEBUG modem << D: (0x20022078): >> length:0x00000068 cur:0x00000000, end:0x00000000
2021-03-24T12:25:40.337Z DEBUG modem << D: (0x20022078): Fixed header length = 02
2021-03-24T12:25:40.340Z DEBUG modem << D: (0x20022078): >> val:32 cur:0x20024111, end:0x2002418e
2021-03-24T12:25:40.343Z DEBUG modem << D: (0x20022078): >> length:0x00000068 cur:0x20024112, end:0x2002418e
2021-03-24T12:25:40.345Z DEBUG modem << D: (0x20022078): [0x20027f10]: Transport writing message.
2021-03-24T12:25:40.446Z DEBUG modem << D: (0x20022078): [0x20027f10]: Transport write complete.
2021-03-24T12:25:40.449Z DEBUG modem << D: (0x20022078): [CID 0x20027f10]:[State 0x06]: << result 0x00000000
2021-03-24T12:25:40.452Z DEBUG modem << D: (0x20022078): state:0x00000006
2021-03-24T12:25:40.454Z DEBUG modem << D: (0x20022078): >> cur:0x2002408e, end:0x20024090
2021-03-24T12:25:40.457Z DEBUG modem << D: (0x20022078): << val:32
2021-03-24T12:25:40.459Z DEBUG modem << D: (0x20022078): >> cur:0x2002408e, end:0x20024091
2021-03-24T12:25:40.461Z DEBUG modem << D: (0x20022078): << val:32
2021-03-24T12:25:40.463Z DEBUG modem << D: (0x20022078): length:0x0000018f
2021-03-24T12:25:40.465Z DEBUG modem << D: (0x20022078): [CID 0x20027f10]: Received MQTT_PKT_TYPE_PUBLISH
2021-03-24T12:25:40.467Z DEBUG modem << D: (0x20022078): >> cur:0x20024091, end:0x200240c2
2021-03-24T12:25:40.469Z DEBUG modem << D: (0x20022078): >> cur:0x20024091, end:0x200240c2
2021-03-24T12:25:40.471Z DEBUG modem << D: (0x20022078): << val:002d
2021-03-24T12:25:40.474Z DEBUG modem << D: (0x20022078): << str_size:0000002f
2021-03-24T12:25:40.477Z DEBUG modem << D: (0x20022078): >> cur:0x200240c0, end:0x200240c2
2021-03-24T12:25:40.479Z DEBUG modem << D: (0x20022078): << val:0001
2021-03-24T12:25:40.482Z DEBUG modem << D: (0x20022078): PUB QoS:01, message len 0000015e, topic len 0000002d
2021-03-24T12:25:40.484Z DEBUG modem << D: Received topic: $aws/things/TDG_logger_thing/jobs/notify-next
2021-03-24T12:25:40.486Z DEBUG modem << D: Checking for an available job
2021-03-24T12:25:40.590Z DEBUG modem << D: Job doc: {"timestamp":1616588697,"execution":{"jobId":"v6","status":"QUEUED","queuedAt":1616588696,"lastUpdatedAt":1616588696,"versionNumber":1,"executionNumber":1,"jobDocument":{"operation":"app_fw_update","fwversion":"v2.0.0","size":193500,"location":{"protocol":"http:","host":"logger-firmware-bucket.s3.eu-west-1.amazonaws.com","path":"app_update.bin"}}}}
2021-03-24T12:25:40.594Z DEBUG modem << D: Job ID: v6
2021-03-24T12:25:40.596Z DEBUG modem << D: hostname: logger-firmware-bucket.s3.eu-west-1.amazonaws.com
2021-03-24T12:25:40.599Z DEBUG modem << D: file_path app_update.bin
2021-03-24T12:25:40.601Z DEBUG modem << D: execution_version_number: 1 
2021-03-24T12:25:40.603Z DEBUG modem << D: (0x20022078): [CID 0x20027f10]:[State 0x06]: >> message id 0x0843 topic count 0x0001
2021-03-24T12:25:40.605Z DEBUG modem << D: (0x20022078): >> val:0843 cur:0x20024113, end:0x2002418e
2021-03-24T12:25:40.608Z DEBUG modem << D: (0x20022078): >> str_size:0000002f cur:0x20024115, end:0x2002418e
2021-03-24T12:25:40.610Z DEBUG modem << D: (0x20022078): >> val:002d cur:0x20024115, end:0x2002418e
2021-03-24T12:25:40.612Z DEBUG modem << D: (0x20022078): >> val:01 cur:0x20024144, end:0x2002418e
2021-03-24T12:25:40.615Z DEBUG modem << D: (0x20022078): << msg type:0x82 length:0x00000032
2021-03-24T12:25:40.617Z DEBUG modem << D: (0x20022078): >> length:0x00000032 cur:0x00000000, end:0x00000000
2021-03-24T12:25:40.619Z DEBUG modem << D: (0x20022078): Fixed header length = 02
2021-03-24T12:25:40.621Z DEBUG modem << D: (0x20022078): >> val:82 cur:0x20024111, end:0x2002418e
2021-03-24T12:25:40.623Z DEBUG modem << D: (0x20022078): >> length:0x00000032 cur:0x20024112, end:0x2002418e
2021-03-24T12:25:40.730Z DEBUG modem << D: (0x20022078): [0x20027f10]: Transport writing 52 bytes.
2021-03-24T12:25:40.733Z DEBUG modem << D: (0x20022078): [0x20027f10]: Transport write complete.
2021-03-24T12:25:40.735Z DEBUG modem << D: (0x20022078): [CID 0x20027f10]:[State 0x06]: << result 0x00000000
2021-03-24T12:25:40.738Z DEBUG modem << D: Subscribed to FOTA update topic $aws/things/TDG_logger_thing/jobs/v6/update/#
2021-03-24T12:25:40.741Z DEBUG modem << D: (0x20022078): [CID 0x20027f10]:[State 0x06]: >> Message id 0x0001
2021-03-24T12:25:40.743Z DEBUG modem << D: (0x20022078): >> val:0001 cur:0x20024113, end:0x2002418e
2021-03-24T12:25:40.745Z DEBUG modem << D: (0x20022078): << msg type:0x40 length:0x00000002
2021-03-24T12:25:40.747Z DEBUG modem << D: (0x20022078): >> length:0x00000002 cur:0x00000000, end:0x00000000
2021-03-24T12:25:40.749Z DEBUG modem << D: (0x20022078): Fixed header length = 02
2021-03-24T12:25:40.751Z DEBUG modem << D: (0x20022078): >> val:40 cur:0x20024111, end:0x2002418e
2021-03-24T12:25:40.753Z DEBUG modem << D: (0x20022078): >> length:0x00000002 cur:0x20024112, end:0x2002418e
2021-03-24T12:25:40.756Z DEBUG modem << D: (0x20022078): [0x20027f10]: Transport writing 4 bytes.
2021-03-24T12:25:40.758Z DEBUG modem << D: (0x20022078): [0x20027f10]: Transport write complete.
2021-03-24T12:25:40.760Z DEBUG modem << D: (0x20022078): [CID 0x20027f10]:[State 0x06]: << result 0x00000000
2021-03-24T12:25:40.762Z DEBUG modem << D: (0x20022078): state:0x00000006
2021-03-24T12:25:40.764Z DEBUG modem << D: (0x20022078): >> cur:0x2002408e, end:0x20024090
2021-03-24T12:25:40.766Z DEBUG modem << D: (0x20022078): << val:40
2021-03-24T12:25:40.872Z DEBUG modem << D: (0x20022078): length:0x00000002
2021-03-24T12:25:40.875Z DEBUG modem << D: (0x20022078): [CID 0x20027f10]: Received MQTT_PKT_TYPE_PUBACK!
2021-03-24T12:25:40.879Z DEBUG modem << D: (0x20022078): >> cur:0x20024090, end:0x20024092
2021-03-24T12:25:40.882Z DEBUG modem << D: (0x20022078): << val:efdd
2021-03-24T12:25:40.885Z DEBUG modem << [mqtt_evt_handler:235] PUBACK packet id: 61405
2021-03-24T12:25:40.887Z DEBUG modem << D: (0x20022078): state:0x00000006
2021-03-24T12:25:40.890Z DEBUG modem << D: (0x20022078): >> cur:0x2002408e, end:0x20024090
2021-03-24T12:25:40.893Z DEBUG modem << D: (0x20022078): << val:30
2021-03-24T12:25:40.895Z DEBUG modem << D: (0x20022078): >> cur:0x2002408e, end:0x20024091
2021-03-24T12:25:40.897Z DEBUG modem << D: (0x20022078): << val:30
2021-03-24T12:25:40.899Z DEBUG modem << D: (0x20022078): length:0x000001a5
2021-03-24T12:25:40.901Z DEBUG modem << D: (0x20022078): [CID 0x20027f10]: Received MQTT_PKT_TYPE_PUBLISH
2021-03-24T12:25:40.903Z DEBUG modem << D: (0x20022078): >> cur:0x20024091, end:0x200240c7
2021-03-24T12:25:40.906Z DEBUG modem << D: (0x20022078): >> cur:0x20024091, end:0x200240c7
2021-03-24T12:25:40.908Z DEBUG modem << D: (0x20022078): << val:0034
2021-03-24T12:25:40.910Z DEBUG modem << D: (0x20022078): << str_size:00000036
2021-03-24T12:25:40.912Z DEBUG modem << D: (0x20022078): PUB QoS:00, message len 0000016f, topic len 00000034
2021-03-24T12:25:40.914Z DEBUG modem << D: Received topic: $aws/things/TDG_logger_thing/jobs/$next/get/accepted
2021-03-24T12:25:40.916Z DEBUG modem << D: Checking for an available job
2021-03-24T12:25:41.033Z DEBUG modem << D: Job doc: {"clientToken":"","timestamp":1616588739,"execution":{"jobId":"v6","status":"QUEUED","queuedAt":1616588696,"lastUpdatedAt":1616588696,"versionNumber":1,"executionNumber":1,"jobDocument":{"operation":"app_fw_update","fwversion":"v2.0.0","size":193500,"location":{"protocol":"http:","host":"logger-firmware-bucket.s3.eu-west-1.amazonaws.com","path":"app_update.bin"}}}}
2021-03-24T12:25:41.036Z DEBUG modem << D: Job ID: v6
2021-03-24T12:25:41.040Z DEBUG modem << D: hostname: logger-firmware-bucket.s3.eu-west-1.amazonaws.com
2021-03-24T12:25:41.042Z DEBUG modem << D: file_path app_update.bin
2021-03-24T12:25:41.044Z DEBUG modem << D: execution_version_number: 1 
2021-03-24T12:25:41.047Z DEBUG modem << D: (0x20022078): [CID 0x20027f10]:[State 0x06]: >> message id 0x0843 topic count 0x0001
2021-03-24T12:25:41.049Z DEBUG modem << D: (0x20022078): >> val:0843 cur:0x20024113, end:0x2002418e
2021-03-24T12:25:41.051Z DEBUG modem << D: (0x20022078): >> str_size:0000002f cur:0x20024115, end:0x2002418e
2021-03-24T12:25:41.053Z DEBUG modem << D: (0x20022078): >> val:002d cur:0x20024115, end:0x2002418e
2021-03-24T12:25:41.055Z DEBUG modem << D: (0x20022078): >> val:01 cur:0x20024144, end:0x2002418e
2021-03-24T12:25:41.058Z DEBUG modem << D: (0x20022078): << msg type:0x82 length:0x00000032
2021-03-24T12:25:41.060Z DEBUG modem << D: (0x20022078): >> length:0x00000032 cur:0x00000000, end:0x00000000
2021-03-24T12:25:41.063Z DEBUG modem << D: (0x20022078): Fixed header length = 02
2021-03-24T12:25:41.065Z DEBUG modem << D: (0x20022078): >> val:82 cur:0x20024111, end:0x2002418e
2021-03-24T12:25:41.067Z DEBUG modem << D: (0x20022078): >> length:0x00000032 cur:0x20024112, end:0x2002418e
2021-03-24T12:25:41.069Z DEBUG modem << D: (0x20022078): [0x20027f10]: Transport writing 52 bytes.
2021-03-24T12:25:41.071Z DEBUG modem << D: (0x20022078): [0x20027f10]: Transport write complete.
2021-03-24T12:25:41.074Z DEBUG modem << D: (0x20022078): [CID 0x20027f10]:[State 0x06]: << result 0x00000000
2021-03-24T12:25:41.186Z DEBUG modem << D: Subscribed to FOTA update topic $aws/things/TDG_logger_thing/jobs/v6/update/#
2021-03-24T12:25:41.189Z DEBUG modem << D: (0x20022078): state:0x00000006
2021-03-24T12:25:41.191Z DEBUG modem << D: (0x20022078): >> cur:0x2002408e, end:0x20024090
2021-03-24T12:25:41.194Z DEBUG modem << D: (0x20022078): << val:40
2021-03-24T12:25:41.196Z DEBUG modem << D: (0x20022078): length:0x00000002
2021-03-24T12:25:41.198Z DEBUG modem << D: (0x20022078): [CID 0x20027f10]: Received MQTT_PKT_TYPE_PUBACK!
2021-03-24T12:25:41.200Z DEBUG modem << D: (0x20022078): >> cur:0x20024090, end:0x20024092
2021-03-24T12:25:41.202Z DEBUG modem << D: (0x20022078): << val:d889
2021-03-24T12:25:41.204Z DEBUG modem << [mqtt_evt_handler:235] PUBACK packet id: 55433
2021-03-24T12:25:41.207Z DEBUG modem << D: (0x20022078): state:0x00000006
2021-03-24T12:25:41.209Z DEBUG modem << D: (0x20022078): >> cur:0x2002408e, end:0x20024090
2021-03-24T12:25:41.211Z DEBUG modem << D: (0x20022078): << val:90
2021-03-24T12:25:41.213Z DEBUG modem << D: (0x20022078): length:0x00000003
2021-03-24T12:25:41.215Z DEBUG modem << D: (0x20022078): [CID 0x20027f10]: Received MQTT_PKT_TYPE_SUBACK!
2021-03-24T12:25:41.218Z DEBUG modem << D: (0x20022078): >> cur:0x20024090, end:0x20024093
2021-03-24T12:25:41.220Z DEBUG modem << D: (0x20022078): << val:0843
2021-03-24T12:25:41.222Z DEBUG modem << D: (0x20022078): >> cur:0x20024092, end:0x20024093
2021-03-24T12:25:41.224Z DEBUG modem << D: (0x20022078): << bin len:00000001
2021-03-24T12:25:41.226Z DEBUG modem << D: update_job_execution, state: 1, version_number: 1
2021-03-24T12:25:41.228Z DEBUG modem << D: (0x20022078): [CID 0x20027f10]:[State 0x06]: >> Topic size 0x0000002b, Data size 0x00000057
2021-03-24T12:25:41.231Z DEBUG modem << D: (0x20022078): >> str_size:0000002d cur:0x20024113, end:0x2002418e
2021-03-24T12:25:41.234Z DEBUG modem << D: (0x20022078): >> val:002b cur:0x20024113, end:0x2002418e
2021-03-24T12:25:41.236Z DEBUG modem << D: (0x20022078): >> val:7dd7 cur:0x20024140, end:0x2002418e
2021-03-24T12:25:41.238Z DEBUG modem << D: (0x20022078): << msg type:0x32 length:0x00000086
2021-03-24T12:25:41.240Z DEBUG modem << D: (0x20022078): >> length:0x00000086 cur:0x00000000, end:0x00000000
2021-03-24T12:25:41.242Z DEBUG modem << D: (0x20022078): Fixed header length = 03
2021-03-24T12:25:41.245Z DEBUG modem << D: (0x20022078): >> val:32 cur:0x20024110, end:0x2002418e
2021-03-24T12:25:41.247Z DEBUG modem << D: (0x20022078): >> length:0x00000086 cur:0x20024111, end:0x2002418e
2021-03-24T12:25:41.249Z DEBUG modem << D: (0x20022078): [0x20027f10]: Transport writing message.
2021-03-24T12:25:41.251Z DEBUG modem << D: (0x20022078): [0x20027f10]: Transport write complete.
2021-03-24T12:25:41.359Z DEBUG modem << D: (0x20022078): [CID 0x20027f10]:[State 0x06]: << result 0x00000000
2021-03-24T12:25:41.526Z DEBUG modem << D: (0x20022078): state:0x00000006
2021-03-24T12:25:41.533Z DEBUG modem << D: (0x20022078): >> cur:0x2002408e, end:0x20024090
2021-03-24T12:25:41.537Z DEBUG modem << D: (0x20022078): << val:90
2021-03-24T12:25:41.645Z DEBUG modem << D: (0x20022078): length:0x00000003
2021-03-24T12:25:41.649Z DEBUG modem << D: (0x20022078): [CID 0x20027f10]: Received MQTT_PKT_TYPE_SUBACK!
2021-03-24T12:25:41.651Z DEBUG modem << D: (0x20022078): >> cur:0x20024090, end:0x20024093
2021-03-24T12:25:41.653Z DEBUG modem << D: (0x20022078): << val:0843
2021-03-24T12:25:41.656Z DEBUG modem << D: (0x20022078): >> cur:0x20024092, end:0x20024093
2021-03-24T12:25:41.658Z DEBUG modem << D: (0x20022078): << bin len:00000001

[Marte Myrvold]

Hi,

Thank you for clarifying. I have asked our developers for help with this, so I will get back to you when I have more information.

Best regards,

Marte

[Marte Myrvold]

Hi,

The developers said that it looks like you are receiving the job twice. This was an issue that was fixed before the 1.5.0 release of NCS. The changes that were done in regards to this can be found here, where you can also find a description of the issue and what was done to fix this, which I have copied below:

When entering PSM the network will cache TCP packets. This lead to
multiple notify-next messages being sent when the device was in PSM as
the MQTT ack was never recived so the server would do retrasmission.

To combat this we check what state we are in when we receive a
notify-next topic so that we won't accept it and break the download.

Addition to this we add a timeout on accepted so that things running in
the same context won't be blocked forever.

To solve this issue you can either update to NCS v1.5.0, or add the changes to your SDK. All the necessary changes can be found in the link above, but I have also added them myself in v1.4.2 and attached them here, so you can just replace the relevant files. The zip file contains the files Kconfig and aws_fota.c. Replace them with the corresponding files found in <ncs_folder>/nrf/subsys/net/lib/aws_fota and <ncs_folder>/nrf/subsys/net/lib/aws_fota/src

aws_fota.zip

Best regards,

Marte

[dermot geraghty]

Hi Marte,

Thanks you for that.

I updated to V1.5.0.

The FOTA has now worked.

I have tested it multiple times and it downloads and resets correctly.

However, sometimes the MQTT client disconnects and the download doesn't complete as can be seen in the attached log.

can you advise why this might be?

The AT command at the end i triggered myself to see if the system was still alive

Thanks

Dermotlog_28_03.txt

[Marte Myrvold]

Hi,

Good to hear that updating to v1.5.0 fixed your previous issue!

How often does the disconnect happen?

The only difference I can see between when it succeeded and when it failed is that right after the transport write is complete, the modem sends the AT command +CSCON: 0 to the MCU, which indicates that the modem is in idle mode. This happens on line line 795 in your log (compared to line 157 and after, where the download succeeded). I also see that the modem starts switching between being in idle and connected (+CSCON: 1) mode after some time, from line 708 and on. I am not sure why this is happening.

Could you get a modem trace of this happening?

Best regards,

Marte

[dermot geraghty]

Hi Marte,

I reset the system and queued a job which downloaded and rebooted the system.

Then I queued a new job. 

There was a long delay and then it seemed to start the new job - but then failed.

Attaching the modem trace.

Thanks

Dtrace-2021-03-29T14-06-40.238Z.bin

[Marte Myrvold]

Hi,

I have started looking at your log and modem trace, but I have not been able to figure out what the issue is yet. Due to Easter we are short staffed, so response time might be longer than usual, but I will get back to you.

Best regards,

Marte

[Marte Myrvold]

Hi,

It seems like the trace doesn't show the whole exchange, but it looks like the server closes the connection for some reason. I haven't figured out why yet, but it might be that the server times out. If so, requesting smaller fragments might help.

You could also try to see if AWS IoT has reported the reason for the disconnect. AWS IoT publishes connect and disconnect events to some MQTT topics, and you can also see this in your device's shadow, as I mentioned in an earlier reply. Go to AWS IoT, Manage, Things, <your thing>, Shadows. A disconnect message will contain the element "disconnectReason", which will have one of the following valid values as the reason for the disconnect:

Disconnect reason	Description
AUTH_ERROR	The client failed to authenticate or authorization failed.
CLIENT_INITIATED_DISCONNECT	The client indicates that it will disconnect. The client can do this by sending either a MQTT DISCONNECT control packet or a Close frame if the client is using a WebSocket connection.
CLIENT_ERROR	The client did something wrong that causes it to disconnect. For example, a client will be disconnected for sending more than 1 MQTT CONNECT packet on the same connection or if the client attempts to publish with a payload that exceeds the payload limit.
CONNECTION_LOST	The client-server connection is cut off. This can happen during a period of high network latency or when the internet connection is lost.
DUPLICATE_CLIENTID	The client is using a client ID that is already in use. In this case, the client that is already connected will be disconnected with this disconnect reason.
FORBIDDEN_ACCESS	The client is not allowed to be connected. For example, a client with a denied IP address will fail to connect.
MQTT_KEEP_ALIVE_TIMEOUT	If there is no client-server communication for 1.5x of the client's keep-alive time, the client is disconnected.
SERVER_ERROR	Disconnected due to unexpected server issues.
SERVER_INITIATED_DISCONNECT	Server intentionally disconnects a client for operational reasons.
THROTTLED	The client is disconnected for exceeding a throttling limit.
WEBSOCKET_TTL_EXPIRATION	The client is disconnected because a WebSocket has been connected longer than its time-to-live value.

This can also be found here.

Best regards,

Marte