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,

Here is the terminal log.

Thanks,

Dermot

Fullscreen 2021-03-19T12_07_08.380Z-log.txt Download

2021-03-19T12:07:08.858Z INFO Application data folder: C:\Users\tgerg\AppData\Roaming\nrfconnect\pc-nrfconnect-linkmonitor
2021-03-19T12:07:08.882Z DEBUG App pc-nrfconnect-linkmonitor v1.1.10 official
2021-03-19T12:07:08.882Z DEBUG App path: C:\Users\tgerg\.nrfconnect-apps\node_modules\pc-nrfconnect-linkmonitor
2021-03-19T12:07:08.882Z DEBUG nRFConnect 3.6.1 is supported by the app (^3.6.0)
2021-03-19T12:07:08.882Z DEBUG nRFConnect path: C:\Users\tgerg\AppData\Local\Programs\nrfconnect\resources\app.asar
2021-03-19T12:07:08.882Z DEBUG HomeDir: C:\Users\tgerg
2021-03-19T12:07:08.882Z DEBUG TmpDir: C:\Users\tgerg\AppData\Local\Temp
2021-03-19T12:07:11.325Z INFO Modem port is opened
2021-03-19T12:07:11.331Z DEBUG modem >> AT+CFUN?
2021-03-19T12:07:11.394Z DEBUG modem << +CFUN: 1
2021-03-19T12:07:11.396Z DEBUG modem << OK
2021-03-19T12:07:11.407Z DEBUG modem >> AT+CGSN=1
2021-03-19T12:07:11.424Z DEBUG modem << +CGSN: "352656100373862"
2021-03-19T12:07:11.427Z DEBUG modem << OK
2021-03-19T12:07:11.432Z DEBUG modem >> AT+CGMI
2021-03-19T12:07:11.451Z DEBUG modem << Nordic Semiconductor ASA
2021-03-19T12:07:11.452Z DEBUG modem << OK
2021-03-19T12:07:11.455Z DEBUG modem >> AT+CGMM
2021-03-19T12:07:11.471Z DEBUG modem << nRF9160-SICA
2021-03-19T12:07:11.473Z DEBUG modem << OK
2021-03-19T12:07:11.477Z DEBUG modem >> AT+CGMR
2021-03-19T12:07:11.491Z DEBUG modem << mfw_nrf9160_1.2.0
2021-03-19T12:07:11.493Z DEBUG modem << 
2021-03-19T12:07:11.494Z DEBUG modem << OK
2021-03-19T12:07:11.495Z INFO Nordic Semiconductor ASA nRF9160-SICA [mfw_nrf9160_1.2.0] SerNr: 352656100373862
2021-03-19T12:07:11.498Z DEBUG modem >> AT+CEMODE?
2021-03-19T12:07:11.516Z DEBUG modem << +CEMODE: 0
2021-03-19T12:07:11.517Z DEBUG modem << OK
2021-03-19T12:07:11.522Z DEBUG modem >> AT%XCBAND=?
2021-03-19T12:07:11.542Z DEBUG modem << %XCBAND: (1,2,3,4,5,8,12,13,17,19,20,25,26,28,66)
2021-03-19T12:07:11.543Z DEBUG modem << OK
2021-03-19T12:07:11.552Z DEBUG modem >> AT+CMEE?
2021-03-19T12:07:11.566Z DEBUG modem << +CMEE: 0
2021-03-19T12:07:11.567Z DEBUG modem << OK
2021-03-19T12:07:11.570Z DEBUG modem >> AT+CMEE=1
2021-03-19T12:07:11.582Z DEBUG modem << OK
2021-03-19T12:07:11.586Z DEBUG modem >> AT+CNEC?
2021-03-19T12:07:11.599Z DEBUG modem << +CNEC: 0
2021-03-19T12:07:11.600Z DEBUG modem << OK
2021-03-19T12:07:11.603Z DEBUG modem >> AT+CNEC=24
2021-03-19T12:07:11.615Z DEBUG modem << OK
2021-03-19T12:07:11.618Z DEBUG modem >> AT+CGEREP?
2021-03-19T12:07:11.633Z DEBUG modem << +CGEREP: 0,0
2021-03-19T12:07:11.637Z DEBUG modem << OK
2021-03-19T12:07:11.640Z DEBUG modem >> AT+CGDCONT?
2021-03-19T12:07:11.659Z DEBUG modem << +CGDCONT: 0,"IP","arkessalp.com","10.72.0.10",0,0
2021-03-19T12:07:11.661Z DEBUG modem << 
2021-03-19T12:07:11.668Z DEBUG modem << +CGDCONT: 1,"IP","arkessalp.com","",0,0
2021-03-19T12:07:11.669Z DEBUG modem << OK
2021-03-19T12:07:11.675Z DEBUG modem >> AT+CGACT?
2021-03-19T12:07:11.691Z DEBUG modem << +CGACT: 0,1
2021-03-19T12:07:11.693Z DEBUG modem << +CGACT: 1,0
2021-03-19T12:07:11.694Z DEBUG modem << OK
2021-03-19T12:07:11.703Z DEBUG modem >> AT+CGEREP=1
2021-03-19T12:07:11.717Z DEBUG modem << OK
2021-03-19T12:07:11.720Z DEBUG modem >> AT+CIND=1,1,1
2021-03-19T12:07:11.726Z DEBUG modem << OK
2021-03-19T12:07:11.728Z DEBUG modem >> AT+CEREG=5
2021-03-19T12:07:11.734Z DEBUG modem << OK
2021-03-19T12:07:11.737Z DEBUG modem >> AT+CEREG?
2021-03-19T12:07:11.755Z DEBUG modem << +CEREG: 5,5,"2332","0250601F",9,,,"00011110","00000111"
2021-03-19T12:07:11.756Z DEBUG modem << 
2021-03-19T12:07:11.757Z DEBUG modem << OK
2021-03-19T12:07:11.759Z DEBUG modem >> AT+COPS=3,2
2021-03-19T12:07:11.773Z DEBUG modem << OK
2021-03-19T12:07:11.775Z DEBUG modem >> AT+COPS?
2021-03-19T12:07:11.784Z DEBUG modem << +COPS: 1,2,"27201",9
2021-03-19T12:07:11.785Z DEBUG modem << OK
2021-03-19T12:07:11.788Z DEBUG modem >> AT%XCBAND
2021-03-19T12:07:11.803Z DEBUG modem << %XCBAND: 20
2021-03-19T12:07:11.804Z DEBUG modem << 
2021-03-19T12:07:11.804Z DEBUG modem << OK
2021-03-19T12:07:11.807Z DEBUG modem >> AT+CGDCONT?
2021-03-19T12:07:11.824Z DEBUG modem << +CGDCONT: 0,"IP","arkessalp.com","10.72.0.10",0,0
2021-03-19T12:07:11.828Z DEBUG modem << +CGDCONT: 1,"IP","arkessalp.com","",0,0
2021-03-19T12:07:11.833Z DEBUG modem << 
2021-03-19T12:07:11.834Z DEBUG modem << OK
2021-03-19T12:07:11.839Z DEBUG modem >> AT+CGACT?
2021-03-19T12:07:11.853Z DEBUG modem << +CGACT: 0,1
2021-03-19T12:07:11.855Z DEBUG modem << +CGACT: 1,0
2021-03-19T12:07:11.856Z DEBUG modem << OK
2021-03-19T12:07:11.859Z DEBUG modem >> AT%CESQ=1
2021-03-19T12:07:11.872Z DEBUG modem << OK
2021-03-19T12:07:11.876Z DEBUG modem >> AT+CESQ
2021-03-19T12:07:11.890Z DEBUG modem << +CESQ: 99,99,255,255,255,255
2021-03-19T12:07:11.891Z DEBUG modem << OK
2021-03-19T12:07:11.895Z DEBUG modem >> AT%XSIM=1
2021-03-19T12:07:11.908Z DEBUG modem << OK
2021-03-19T12:07:11.911Z DEBUG modem >> AT%XSIM?
2021-03-19T12:07:11.918Z DEBUG modem << %XSIM: 1
2021-03-19T12:07:11.919Z DEBUG modem << OK
2021-03-19T12:07:11.922Z DEBUG modem >> AT+CPIN?
2021-03-19T12:07:11.934Z DEBUG modem << +CPIN: READY
2021-03-19T12:07:11.936Z DEBUG modem << OK
2021-03-19T12:07:11.939Z DEBUG modem >> AT+CPINR="SIM PIN"
2021-03-19T12:07:11.955Z DEBUG modem << +CME ERROR: 0
2021-03-19T12:07:45.637Z DEBUG modem << *** Booting Zephyr OS build v2.4.0-ncs2  ***
2021-03-19T12:07:45.643Z DEBUG modem << [00:00:00.525,390] [0m<inf> mcuboot: Starting bootloader[0m
2021-03-19T12:07:45.659Z DEBUG modem << [00:00:00.531,646] [0m<inf> mcuboot: Primary image: magic=unset, swap_type=0x1, copy_done=0x3, image_ok=0x1[0m
2021-03-19T12:07:45.660Z DEBUG modem << [00:00:00.541,778] [0m<inf> mcuboot: Boot source: none[0m
2021-03-19T12:07:45.664Z DEBUG modem << [00:00:00.547,332] [0m<inf> mcuboot: Swap type: none[0m
2021-03-19T12:07:45.718Z DEBUG modem << [00:00:00.598,236] [0m<inf> mcuboot: Bootloader chainload address offset: 0x10000[0m
2021-03-19T12:07:45.724Z DEBUG modem << [00:00:00.606,079] [0m<inf> mcuboot: Jumping to the first image slot[0m
2021-03-19T12:07:45.734Z DEBUG modem << *** Booting Zephyr OS build v2.4.0-ncs2  ***
2021-03-19T12:07:45.734Z DEBUG modem << Flash regionsDomainPermissions
2021-03-19T12:07:45.735Z DEBUG modem << 00 02 0x00000 0x18000 Securerwxl
2021-03-19T12:07:45.739Z DEBUG modem << 03 31 0x18000 0x100000 Non-Securerwxl
2021-03-19T12:07:45.745Z DEBUG modem << Non-secure callable region 0 placed in flash region 2 with size 32.
2021-03-19T12:07:45.918Z DEBUG modem << SRAM regionDomainPermissions
2021-03-19T12:07:45.921Z DEBUG modem << 00 07 0x00000 0x10000 Securerwxl
2021-03-19T12:07:45.925Z DEBUG modem << 08 31 0x10000 0x40000 Non-Securerwxl
2021-03-19T12:07:45.927Z DEBUG modem << PeripheralDomainStatus
2021-03-19T12:07:45.932Z DEBUG modem << 00 NRF_P0               Non-SecureOK
2021-03-19T12:07:45.934Z DEBUG modem << 01 NRF_CLOCK            Non-SecureOK
2021-03-19T12:07:45.938Z DEBUG modem << 02 NRF_RTC0             Non-SecureOK
2021-03-19T12:07:45.941Z DEBUG modem << 03 NRF_RTC1             Non-SecureOK
2021-03-19T12:07:45.944Z DEBUG modem << 04 NRF_NVMC             Non-SecureOK
2021-03-19T12:07:45.951Z DEBUG modem << 05 NRF_UARTE1           Non-SecureOK
2021-03-19T12:07:45.952Z DEBUG modem << 06 NRF_UARTE2           SecureSKIP
2021-03-19T12:07:45.955Z DEBUG modem << 07 NRF_TWIM2            Non-SecureOK
2021-03-19T12:07:45.958Z DEBUG modem << 08 NRF_SPIM3            Non-SecureOK
2021-03-19T12:07:45.967Z DEBUG modem << 09 NRF_TIMER0           Non-SecureOK
2021-03-19T12:07:45.968Z DEBUG modem << 10 NRF_TIMER1           Non-SecureOK
2021-03-19T12:07:45.969Z DEBUG modem << 11 NRF_TIMER2           Non-SecureOK
2021-03-19T12:07:45.972Z DEBUG modem << 12 NRF_SAADC            Non-SecureOK
2021-03-19T12:07:45.975Z DEBUG modem << 13 NRF_PWM0             Non-SecureOK
2021-03-19T12:07:45.983Z DEBUG modem << 14 NRF_PWM1             Non-SecureOK
2021-03-19T12:07:45.984Z DEBUG modem << 15 NRF_PWM2             Non-SecureOK
2021-03-19T12:07:45.986Z DEBUG modem << 16 NRF_PWM3             Non-SecureOK
2021-03-19T12:07:45.989Z DEBUG modem << 17 NRF_WDT              Non-SecureOK
2021-03-19T12:07:45.993Z DEBUG modem << 18 NRF_IPC              Non-SecureOK
2021-03-19T12:07:46.000Z DEBUG modem << 19 NRF_VMC              Non-SecureOK
2021-03-19T12:07:46.001Z DEBUG modem << 20 NRF_FPU              Non-SecureOK
2021-03-19T12:07:46.003Z DEBUG modem << 21 NRF_EGU1             Non-SecureOK
2021-03-19T12:07:46.006Z DEBUG modem << 22 NRF_EGU2             Non-SecureOK
2021-03-19T12:07:46.010Z DEBUG modem << 23 NRF_DPPIC            Non-SecureOK
2021-03-19T12:07:46.017Z DEBUG modem << 24 NRF_GPIOTE1          Non-SecureOK
2021-03-19T12:07:46.018Z DEBUG modem << 25 NRF_REGULATORS       Non-SecureOK
2021-03-19T12:07:46.019Z DEBUG modem << SPM: NS image at 0x1c200
2021-03-19T12:07:46.022Z DEBUG modem << SPM: NS MSP at 0x20027fb8
2021-03-19T12:07:46.025Z DEBUG modem << SPM: NS reset vector at 0x218ad
2021-03-19T12:07:46.028Z DEBUG modem << SPM: prepare to jump to Non-Secure image.
2021-03-19T12:07:46.036Z DEBUG modem << *** Booting Zephyr OS build v2.4.0-ncs2  ***
2021-03-19T12:07:46.039Z DEBUG modem << MQTT AWS Jobs FOTA Sample, version: 2.0.0
2021-03-19T12:07:46.041Z DEBUG modem << Initializing bsdlib
2021-03-19T12:07:46.282Z DEBUG modem << Initialized bsdlib
2021-03-19T12:07:46.292Z DEBUG modem << LTE Link Connecting ...
2021-03-19T12:07:46.306Z DEBUG modem << D: Preferred system mode (2) is already configured
2021-03-19T12:07:46.343Z DEBUG modem << I: PDP Context: AT+CGDCONT=1,"IP","arkessalp.com"
2021-03-19T12:07:46.353Z DEBUG modem << D: Sending AT command to set system mode: AT%XSYSTEMMODE=0,1,0,0
2021-03-19T12:07:48.988Z DEBUG modem << D: +CEREG notification: +CEREG: 2,"2332","0250601F",9,0,0,"11100000","11100000"
2021-03-19T12:07:49.244Z DEBUG modem << D: +CSCON notification
2021-03-19T12:07:50.269Z DEBUG modem << D: +CEREG notification: +CEREG: 5,"2332","0250601F",9,,,"00011110","00000111"
2021-03-19T12:07:50.276Z DEBUG modem << D: TAU: 4200 sec, active time: 60 sec
2021-03-19T12:07:50.278Z DEBUG modem << LTE Link Connected!
2021-03-19T12:07:50.957Z DEBUG modem << IPv4 Address 52.212.177.176
2021-03-19T12:07:50.961Z DEBUG modem << client_id: TDG_logger_thing
2021-03-19T12:07:50.965Z DEBUG modem << hostname: a3vecosqszzrnz-ats.iot.eu-west-1.amazonaws.com
2021-03-19T12:07:50.969Z DEBUG modem << D: (0x20022078): Created socket 1
2021-03-19T12:07:57.187Z DEBUG modem << D: (0x20022078): Connect completed
2021-03-19T12:07:57.197Z DEBUG modem << D: (0x20022078): Encoding Protocol Description. Str:MQTT Size:00000004.
2021-03-19T12:07:57.203Z DEBUG modem << D: (0x20022078): >> str_size:00000006 cur:0x20024113, end:0x2002418e
2021-03-19T12:07:57.225Z DEBUG modem << D: (0x20022078): >> val:0004 cur:0x20024113, end:0x2002418e
2021-03-19T12:07:57.233Z DEBUG modem << D: (0x20022078): Encoding Protocol Version 04.
2021-03-19T12:07:57.235Z DEBUG modem << D: (0x20022078): >> val:04 cur:0x20024119, end:0x2002418e
2021-03-19T12:07:57.240Z DEBUG modem << D: (0x20022078): >> val:00 cur:0x2002411a, end:0x2002418e
2021-03-19T12:07:57.244Z DEBUG modem << D: (0x20022078): Encoding Keep Alive Time 04b0.
2021-03-19T12:07:57.250Z DEBUG modem << D: (0x20022078): >> val:04b0 cur:0x2002411b, end:0x2002418e
2021-03-19T12:07:57.256Z DEBUG modem << D: (0x20022078): Encoding Client Id. Str:TDG_logger_thing Size:00000010.
2021-03-19T12:07:57.267Z DEBUG modem << D: (0x20022078): >> str_size:00000012 cur:0x2002411d, end:0x2002418e
2021-03-19T12:07:57.268Z DEBUG modem << D: (0x20022078): >> val:0010 cur:0x2002411d, end:0x2002418e
2021-03-19T12:07:57.272Z DEBUG modem << D: (0x20022078): << msg type:0x10 length:0x0000001c
2021-03-19T12:07:57.283Z DEBUG modem << D: (0x20022078): >> length:0x0000001c cur:0x00000000, end:0x00000000
2021-03-19T12:07:57.284Z DEBUG modem << D: (0x20022078): Fixed header length = 02
2021-03-19T12:07:57.288Z DEBUG modem << D: (0x20022078): >> val:10 cur:0x20024111, end:0x2002418e
2021-03-19T12:07:57.294Z DEBUG modem << D: (0x20022078): >> length:0x0000001c cur:0x20024112, end:0x2002418e
2021-03-19T12:07:57.314Z DEBUG modem << D: (0x20022078): Connect completed
2021-03-19T12:07:57.713Z DEBUG modem << D: (0x20022078): state:0x00000002
2021-03-19T12:07:57.718Z DEBUG modem << D: (0x20022078): >> cur:0x2002408e, end:0x20024090
2021-03-19T12:07:57.722Z DEBUG modem << D: (0x20022078): << val:20
2021-03-19T12:07:57.725Z DEBUG modem << D: (0x20022078): length:0x00000002
2021-03-19T12:07:57.735Z DEBUG modem << D: (0x20022078): [CID 0x20027f10]: Received MQTT_PKT_TYPE_CONNACK!
2021-03-19T12:07:57.739Z DEBUG modem << D: (0x20022078): >> cur:0x20024090, end:0x20024092
2021-03-19T12:07:57.742Z DEBUG modem << D: (0x20022078): << val:00
2021-03-19T12:07:57.751Z DEBUG modem << D: (0x20022078): >> cur:0x20024091, end:0x20024092
2021-03-19T12:07:57.752Z DEBUG modem << D: (0x20022078): << val:00
2021-03-19T12:07:57.754Z DEBUG modem << D: (0x20022078): [CID 0x20027f10]: session_present_flag: 0
2021-03-19T12:07:57.759Z DEBUG modem << D: (0x20022078): [CID 0x20027f10]: return_code: 0
2021-03-19T12:07:57.767Z DEBUG modem << D: (0x20022078): [CID 0x20027f10]:[State 0x06]: >> message id 0x0840 topic count 0x0001
2021-03-19T12:07:57.772Z DEBUG modem << D: (0x20022078): >> val:0840 cur:0x20024113, end:0x2002418e
2021-03-19T12:07:57.784Z DEBUG modem << D: (0x20022078): >> str_size:0000002f cur:0x20024115, end:0x2002418e
2021-03-19T12:07:57.785Z DEBUG modem << D: (0x20022078): >> val:002d cur:0x20024115, end:0x2002418e
2021-03-19T12:07:57.789Z DEBUG modem << D: (0x20022078): >> val:01 cur:0x20024144, end:0x2002418e
2021-03-19T12:07:57.794Z DEBUG modem << D: (0x20022078): << msg type:0x82 length:0x00000032
2021-03-19T12:07:57.801Z DEBUG modem << D: (0x20022078): >> length:0x00000032 cur:0x00000000, end:0x00000000
2021-03-19T12:07:57.804Z DEBUG modem << D: (0x20022078): Fixed header length = 02
2021-03-19T12:07:57.810Z DEBUG modem << D: (0x20022078): >> val:82 cur:0x20024111, end:0x2002418e
2021-03-19T12:07:57.818Z DEBUG modem << D: (0x20022078): >> length:0x00000032 cur:0x20024112, end:0x2002418e
2021-03-19T12:07:57.821Z DEBUG modem << D: (0x20022078): [0x20027f10]: Transport writing 52 bytes.
2021-03-19T12:07:57.844Z DEBUG modem << D: (0x20022078): [0x20027f10]: Transport write complete.
2021-03-19T12:07:57.851Z DEBUG modem << D: (0x20022078): [CID 0x20027f10]:[State 0x06]: << result 0x00000000
2021-03-19T12:07:57.858Z DEBUG modem << D: (0x20022078): [CID 0x20027f10]:[State 0x06]: >> message id 0x0842 topic count 0x0001
2021-03-19T12:07:57.868Z DEBUG modem << D: (0x20022078): >> val:0842 cur:0x20024113, end:0x2002418e
2021-03-19T12:07:57.869Z DEBUG modem << D: (0x20022078): >> str_size:0000002f cur:0x20024115, end:0x2002418e
2021-03-19T12:07:57.875Z DEBUG modem << D: (0x20022078): >> val:002d cur:0x20024115, end:0x2002418e
2021-03-19T12:07:57.885Z DEBUG modem << D: (0x20022078): >> val:01 cur:0x20024144, end:0x2002418e
2021-03-19T12:07:57.887Z DEBUG modem << D: (0x20022078): << msg type:0x82 length:0x00000032
2021-03-19T12:07:57.902Z DEBUG modem << D: (0x20022078): >> length:0x00000032 cur:0x00000000, end:0x00000000
2021-03-19T12:07:57.904Z DEBUG modem << D: (0x20022078): Fixed header length = 02
2021-03-19T12:07:57.909Z DEBUG modem << D: (0x20022078): >> val:82 cur:0x20024111, end:0x2002418e
2021-03-19T12:07:57.917Z DEBUG modem << D: (0x20022078): >> length:0x00000032 cur:0x20024112, end:0x2002418e
2021-03-19T12:07:57.921Z DEBUG modem << D: (0x20022078): [0x20027f10]: Transport writing 52 bytes.
2021-03-19T12:07:57.927Z DEBUG modem << D: (0x20022078): [0x20027f10]: Transport write complete.
2021-03-19T12:07:57.940Z DEBUG modem << D: (0x20022078): [CID 0x20027f10]:[State 0x06]: << result 0x00000000
2021-03-19T12:07:57.944Z DEBUG modem << [mqtt_evt_handler:182] MQTT client connected!
2021-03-19T12:07:57.999Z DEBUG modem << D: (0x20022078): [CID 0x20027f10]:[State 0x06]: >> Topic size 0x0000002a, Data size 0x0000003a
2021-03-19T12:07:58.005Z DEBUG modem << D: (0x20022078): >> str_size:0000002c cur:0x20024113, end:0x2002418e
2021-03-19T12:07:58.011Z DEBUG modem << D: (0x20022078): >> val:002a cur:0x20024113, end:0x2002418e
2021-03-19T12:07:58.016Z DEBUG modem << D: (0x20022078): >> val:5d3e cur:0x2002413f, end:0x2002418e
2021-03-19T12:07:58.021Z DEBUG modem << D: (0x20022078): << msg type:0x32 length:0x00000068
2021-03-19T12:07:58.027Z DEBUG modem << D: (0x20022078): >> length:0x00000068 cur:0x00000000, end:0x00000000
2021-03-19T12:07:58.034Z DEBUG modem << D: (0x20022078): Fixed header length = 02
2021-03-19T12:07:58.036Z DEBUG modem << D: (0x20022078): >> val:32 cur:0x20024111, end:0x2002418e
2021-03-19T12:07:58.042Z DEBUG modem << D: (0x20022078): >> length:0x00000068 cur:0x20024112, end:0x2002418e
2021-03-19T12:07:58.050Z DEBUG modem << D: (0x20022078): [0x20027f10]: Transport writing message.
2021-03-19T12:07:58.056Z DEBUG modem << D: (0x20022078): [0x20027f10]: Transport write complete.
2021-03-19T12:07:58.071Z DEBUG modem << D: (0x20022078): [CID 0x20027f10]:[State 0x06]: << result 0x00000000
2021-03-19T12:07:58.334Z DEBUG modem << D: (0x20022078): state:0x00000006
2021-03-19T12:07:58.340Z DEBUG modem << D: (0x20022078): >> cur:0x2002408e, end:0x20024090
2021-03-19T12:07:58.344Z DEBUG modem << D: (0x20022078): << val:90
2021-03-19T12:07:58.350Z DEBUG modem << D: (0x20022078): length:0x00000003
2021-03-19T12:07:58.355Z DEBUG modem << D: (0x20022078): [CID 0x20027f10]: Received MQTT_PKT_TYPE_SUBACK!
2021-03-19T12:07:58.376Z DEBUG modem << D: (0x20022078): >> cur:0x20024090, end:0x20024093
2021-03-19T12:07:58.378Z DEBUG modem << D: (0x20022078): << val:0840
2021-03-19T12:07:58.384Z DEBUG modem << D: (0x20022078): >> cur:0x20024092, end:0x20024093
2021-03-19T12:07:58.386Z DEBUG modem << D: (0x20022078): << bin len:00000001
2021-03-19T12:07:58.389Z DEBUG modem << D: subscribed to notify-next topic
2021-03-19T12:07:58.401Z DEBUG modem << D: (0x20022078): [CID 0x20027f10]:[State 0x06]: >> Topic size 0x0000002d, Data size 0x00000013
2021-03-19T12:07:58.404Z DEBUG modem << D: (0x20022078): >> str_size:0000002f cur:0x20024113, end:0x2002418e
2021-03-19T12:07:58.410Z DEBUG modem << D: (0x20022078): >> val:002d cur:0x20024113, end:0x2002418e
2021-03-19T12:07:58.418Z DEBUG modem << D: (0x20022078): >> val:2ddf cur:0x20024142, end:0x2002418e
2021-03-19T12:07:58.420Z DEBUG modem << D: (0x20022078): << msg type:0x32 length:0x00000044
2021-03-19T12:07:58.426Z DEBUG modem << D: (0x20022078): >> length:0x00000044 cur:0x00000000, end:0x00000000
2021-03-19T12:07:58.435Z DEBUG modem << D: (0x20022078): Fixed header length = 02
2021-03-19T12:07:58.436Z DEBUG modem << D: (0x20022078): >> val:32 cur:0x20024111, end:0x2002418e
2021-03-19T12:07:58.443Z DEBUG modem << D: (0x20022078): >> length:0x00000044 cur:0x20024112, end:0x2002418e
2021-03-19T12:07:58.451Z DEBUG modem << D: (0x20022078): [0x20027f10]: Transport writing message.
2021-03-19T12:07:58.457Z DEBUG modem << D: (0x20022078): [0x20027f10]: Transport write complete.
2021-03-19T12:07:58.469Z DEBUG modem << D: (0x20022078): [CID 0x20027f10]:[State 0x06]: << result 0x00000000
2021-03-19T12:07:58.497Z DEBUG modem << D: (0x20022078): state:0x00000006
2021-03-19T12:07:58.504Z DEBUG modem << D: (0x20022078): >> cur:0x2002408e, end:0x20024090
2021-03-19T12:07:58.507Z DEBUG modem << D: (0x20022078): << val:40
2021-03-19T12:07:58.510Z DEBUG modem << D: (0x20022078): length:0x00000002
2021-03-19T12:07:58.519Z DEBUG modem << D: (0x20022078): [CID 0x20027f10]: Received MQTT_PKT_TYPE_PUBACK!
2021-03-19T12:07:58.560Z DEBUG modem << D: (0x20022078): >> cur:0x20024090, end:0x20024092
2021-03-19T12:07:58.588Z DEBUG modem << D: (0x20022078): << val:5d3e
2021-03-19T12:07:58.591Z DEBUG modem << [mqtt_evt_handler:235] PUBACK packet id: 23870
2021-03-19T12:07:58.594Z DEBUG modem << D: (0x20022078): state:0x00000006
2021-03-19T12:07:58.600Z DEBUG modem << D: (0x20022078): >> cur:0x2002408e, end:0x20024090
2021-03-19T12:07:58.605Z DEBUG modem << D: (0x20022078): << val:90
2021-03-19T12:07:58.607Z DEBUG modem << D: (0x20022078): length:0x00000003
2021-03-19T12:07:58.622Z DEBUG modem << D: (0x20022078): [CID 0x20027f10]: Received MQTT_PKT_TYPE_SUBACK!
2021-03-19T12:07:58.623Z DEBUG modem << D: (0x20022078): >> cur:0x20024090, end:0x20024093
2021-03-19T12:07:58.624Z DEBUG modem << D: (0x20022078): << val:0842
2021-03-19T12:07:58.624Z DEBUG modem << D: (0x20022078): >> cur:0x20024092, end:0x20024093
2021-03-19T12:07:58.626Z DEBUG modem << D: (0x20022078): << bin len:00000001
2021-03-19T12:07:58.632Z DEBUG modem << [mqtt_evt_handler:245] SUBACK packet id: 2114
2021-03-19T12:08:00.685Z DEBUG modem << D: (0x20022078): state:0x00000006
2021-03-19T12:08:00.693Z DEBUG modem << D: (0x20022078): [CID 0x20027f10]: Connection closed.
2021-03-19T12:08:00.700Z DEBUG modem << D: (0x20022078): Closing socket 1
2021-03-19T12:08:00.734Z DEBUG modem << [mqtt_evt_handler:193] MQTT client disconnected -128
2021-03-19T12:08:00.736Z DEBUG modem << ERROR: mqtt_input -128
2021-03-19T12:08:00.738Z DEBUG modem << Disconnecting MQTT client...
2021-03-19T12:08:00.742Z DEBUG modem << Could not disconnect MQTT client. Error: -128
2021-03-19T12:08:11.239Z DEBUG modem << D: +CSCON notification
2021-03-19T12:08:39.580Z DEBUG modem << *** Booting Zephyr OS build v2.4.0-ncs2  ***
2021-03-19T12:08:39.586Z DEBUG modem << [00:00:00.334,289] [0m<inf> mcuboot: Starting bootloader[0m
2021-03-19T12:08:39.602Z DEBUG modem << [00:00:00.340,606] [0m<inf> mcuboot: Primary image: magic=unset, swap_type=0x1, copy_done=0x3, image_ok=0x1[0m
2021-03-19T12:08:39.603Z DEBUG modem << [00:00:00.350,769] [0m<inf> mcuboot: Boot source: none[0m
2021-03-19T12:08:39.607Z DEBUG modem << [00:00:00.356,353] [0m<inf> mcuboot: Swap type: none[0m
2021-03-19T12:08:39.661Z DEBUG modem << [00:00:00.407,623] [0m<inf> mcuboot: Bootloader chainload address offset: 0x10000[0m
2021-03-19T12:08:39.668Z DEBUG modem << [00:00:00.415,496] [0m<inf> mcuboot: Jumping to the first image slot[0m
2021-03-19T12:08:39.672Z DEBUG modem << *** Booting Zephyr OS build v2.4.0-ncs2  ***
2021-03-19T12:08:39.675Z DEBUG modem << Flash regionsDomainPermissions
2021-03-19T12:08:39.678Z DEBUG modem << 00 02 0x00000 0x18000 Securerwxl
2021-03-19T12:08:39.684Z DEBUG modem << 03 31 0x18000 0x100000 Non-Securerwxl
2021-03-19T12:08:39.688Z DEBUG modem << Non-secure callable region 0 placed in flash region 2 with size 32.
2021-03-19T12:08:39.862Z DEBUG modem << SRAM regionDomainPermissions
2021-03-19T12:08:39.868Z DEBUG modem << 00 07 0x00000 0x10000 Securerwxl
2021-03-19T12:08:39.869Z DEBUG modem << 08 31 0x10000 0x40000 Non-Securerwxl
2021-03-19T12:08:39.872Z DEBUG modem << PeripheralDomainStatus
2021-03-19T12:08:39.876Z DEBUG modem << 00 NRF_P0               Non-SecureOK
2021-03-19T12:08:39.884Z DEBUG modem << 01 NRF_CLOCK            Non-SecureOK
2021-03-19T12:08:39.885Z DEBUG modem << 02 NRF_RTC0             Non-SecureOK
2021-03-19T12:08:39.886Z DEBUG modem << 03 NRF_RTC1             Non-SecureOK
2021-03-19T12:08:39.889Z DEBUG modem << 04 NRF_NVMC             Non-SecureOK
2021-03-19T12:08:39.893Z DEBUG modem << 05 NRF_UARTE1           Non-SecureOK
2021-03-19T12:08:39.902Z DEBUG modem << 06 NRF_UARTE2           SecureSKIP
2021-03-19T12:08:39.903Z DEBUG modem << 07 NRF_TWIM2            Non-SecureOK
2021-03-19T12:08:39.904Z DEBUG modem << 08 NRF_SPIM3            Non-SecureOK
2021-03-19T12:08:39.907Z DEBUG modem << 09 NRF_TIMER0           Non-SecureOK
2021-03-19T12:08:39.910Z DEBUG modem << 10 NRF_TIMER1           Non-SecureOK
2021-03-19T12:08:39.919Z DEBUG modem << 11 NRF_TIMER2           Non-SecureOK
2021-03-19T12:08:39.920Z DEBUG modem << 12 NRF_SAADC            Non-SecureOK
2021-03-19T12:08:39.921Z DEBUG modem << 13 NRF_PWM0             Non-SecureOK
2021-03-19T12:08:39.924Z DEBUG modem << 14 NRF_PWM1             Non-SecureOK
2021-03-19T12:08:39.927Z DEBUG modem << 15 NRF_PWM2             Non-SecureOK
2021-03-19T12:08:39.936Z DEBUG modem << 16 NRF_PWM3             Non-SecureOK
2021-03-19T12:08:39.937Z DEBUG modem << 17 NRF_WDT              Non-SecureOK
2021-03-19T12:08:39.939Z DEBUG modem << 18 NRF_IPC              Non-SecureOK
2021-03-19T12:08:39.941Z DEBUG modem << 19 NRF_VMC              Non-SecureOK
2021-03-19T12:08:39.945Z DEBUG modem << 20 NRF_FPU              Non-SecureOK
2021-03-19T12:08:39.952Z DEBUG modem << 21 NRF_EGU1             Non-SecureOK
2021-03-19T12:08:39.953Z DEBUG modem << 22 NRF_EGU2             Non-SecureOK
2021-03-19T12:08:39.955Z DEBUG modem << 23 NRF_DPPIC            Non-SecureOK
2021-03-19T12:08:39.959Z DEBUG modem << 24 NRF_GPIOTE1          Non-SecureOK
2021-03-19T12:08:39.969Z DEBUG modem << 25 NRF_REGULATORS       Non-SecureOK
2021-03-19T12:08:39.970Z DEBUG modem << SPM: NS image at 0x1c200
2021-03-19T12:08:39.971Z DEBUG modem << SPM: NS MSP at 0x20027fb8
2021-03-19T12:08:39.971Z DEBUG modem << SPM: NS reset vector at 0x218ad
2021-03-19T12:08:39.974Z DEBUG modem << SPM: prepare to jump to Non-Secure image.
2021-03-19T12:08:39.986Z DEBUG modem << *** Booting Zephyr OS build v2.4.0-ncs2  ***
2021-03-19T12:08:39.987Z DEBUG modem << MQTT AWS Jobs FOTA Sample, version: 2.0.0
2021-03-19T12:08:39.987Z DEBUG modem << Initializing bsdlib
2021-03-19T12:08:40.231Z DEBUG modem << Initialized bsdlib
2021-03-19T12:08:40.241Z DEBUG modem << LTE Link Connecting ...
2021-03-19T12:08:40.254Z DEBUG modem << D: Preferred system mode (2) is already configured
2021-03-19T12:08:40.292Z DEBUG modem << I: PDP Context: AT+CGDCONT=1,"IP","arkessalp.com"
2021-03-19T12:08:40.302Z DEBUG modem << D: Sending AT command to set system mode: AT%XSYSTEMMODE=0,1,0,0
2021-03-19T12:08:45.308Z DEBUG modem << D: +CEREG notification: +CEREG: 2,"2332","0250601F",9,0,0,"11100000","11100000"
2021-03-19T12:08:45.564Z DEBUG modem << D: +CSCON notification
2021-03-19T12:08:46.845Z DEBUG modem << D: +CEREG notification: +CEREG: 5,"2332","0250601F",9,,,"00011110","00000111"
2021-03-19T12:08:46.851Z DEBUG modem << D: TAU: 4200 sec, active time: 60 sec
2021-03-19T12:08:46.854Z DEBUG modem << LTE Link Connected!
2021-03-19T12:08:47.277Z DEBUG modem << IPv4 Address 34.253.25.169
2021-03-19T12:08:47.283Z DEBUG modem << client_id: TDG_logger_thing
2021-03-19T12:08:47.285Z DEBUG modem << hostname: a3vecosqszzrnz-ats.iot.eu-west-1.amazonaws.com
2021-03-19T12:08:47.289Z DEBUG modem << D: (0x20022078): Created socket 1
2021-03-19T12:08:53.508Z DEBUG modem << D: (0x20022078): Connect completed
2021-03-19T12:08:53.518Z DEBUG modem << D: (0x20022078): Encoding Protocol Description. Str:MQTT Size:00000004.
2021-03-19T12:08:53.524Z DEBUG modem << D: (0x20022078): >> str_size:00000006 cur:0x20024113, end:0x2002418e
2021-03-19T12:08:53.546Z DEBUG modem << D: (0x20022078): >> val:0004 cur:0x20024113, end:0x2002418e
2021-03-19T12:08:53.551Z DEBUG modem << D: (0x20022078): Encoding Protocol Version 04.
2021-03-19T12:08:53.556Z DEBUG modem << D: (0x20022078): >> val:04 cur:0x20024119, end:0x2002418e
2021-03-19T12:08:53.561Z DEBUG modem << D: (0x20022078): >> val:00 cur:0x2002411a, end:0x2002418e
2021-03-19T12:08:53.568Z DEBUG modem << D: (0x20022078): Encoding Keep Alive Time 04b0.
2021-03-19T12:08:53.571Z DEBUG modem << D: (0x20022078): >> val:04b0 cur:0x2002411b, end:0x2002418e
2021-03-19T12:08:53.577Z DEBUG modem << D: (0x20022078): Encoding Client Id. Str:TDG_logger_thing Size:00000010.
2021-03-19T12:08:53.585Z DEBUG modem << D: (0x20022078): >> str_size:00000012 cur:0x2002411d, end:0x2002418e
2021-03-19T12:08:53.589Z DEBUG modem << D: (0x20022078): >> val:0010 cur:0x2002411d, end:0x2002418e
2021-03-19T12:08:53.594Z DEBUG modem << D: (0x20022078): << msg type:0x10 length:0x0000001c
2021-03-19T12:08:53.602Z DEBUG modem << D: (0x20022078): >> length:0x0000001c cur:0x00000000, end:0x00000000
2021-03-19T12:08:53.604Z DEBUG modem << D: (0x20022078): Fixed header length = 02
2021-03-19T12:08:53.609Z DEBUG modem << D: (0x20022078): >> val:10 cur:0x20024111, end:0x2002418e
2021-03-19T12:08:53.619Z DEBUG modem << D: (0x20022078): >> length:0x0000001c cur:0x20024112, end:0x2002418e
2021-03-19T12:08:53.637Z DEBUG modem << D: (0x20022078): Connect completed
2021-03-19T12:08:54.034Z DEBUG modem << D: (0x20022078): state:0x00000002
2021-03-19T12:08:54.040Z DEBUG modem << D: (0x20022078): >> cur:0x2002408e, end:0x20024090
2021-03-19T12:08:54.042Z DEBUG modem << D: (0x20022078): << val:20
2021-03-19T12:08:54.045Z DEBUG modem << D: (0x20022078): length:0x00000002
2021-03-19T12:08:54.055Z DEBUG modem << D: (0x20022078): [CID 0x20027f10]: Received MQTT_PKT_TYPE_CONNACK!
2021-03-19T12:08:54.059Z DEBUG modem << D: (0x20022078): >> cur:0x20024090, end:0x20024092
2021-03-19T12:08:54.062Z DEBUG modem << D: (0x20022078): << val:01
2021-03-19T12:08:54.069Z DEBUG modem << D: (0x20022078): >> cur:0x20024091, end:0x20024092
2021-03-19T12:08:54.070Z DEBUG modem << D: (0x20022078): << val:00
2021-03-19T12:08:54.074Z DEBUG modem << D: (0x20022078): [CID 0x20027f10]: session_present_flag: 1
2021-03-19T12:08:54.085Z DEBUG modem << D: (0x20022078): [CID 0x20027f10]: return_code: 0
2021-03-19T12:08:54.087Z DEBUG modem << D: Previous session valid; skipping FOTA subscriptions
2021-03-19T12:08:54.091Z DEBUG modem << D: Created notify_next_topic $aws/things/TDG_logger_thing/jobs/notify-next
2021-03-19T12:08:54.103Z DEBUG modem << D: Created get_topic $aws/things/TDG_logger_thing/jobs/notify-next
2021-03-19T12:08:54.104Z DEBUG modem << D: previously subscribed to notify-next topic
2021-03-19T12:08:54.109Z DEBUG modem << D: (0x20022078): [CID 0x20027f10]:[State 0x06]: >> Topic size 0x0000002d, Data size 0x00000013
2021-03-19T12:08:54.119Z DEBUG modem << D: (0x20022078): >> str_size:0000002f cur:0x20024113, end:0x2002418e
2021-03-19T12:08:54.121Z DEBUG modem << D: (0x20022078): >> val:002d cur:0x20024113, end:0x2002418e
2021-03-19T12:08:54.126Z DEBUG modem << D: (0x20022078): >> val:0ff3 cur:0x20024142, end:0x2002418e
2021-03-19T12:08:54.136Z DEBUG modem << D: (0x20022078): << msg type:0x32 length:0x00000044
2021-03-19T12:08:54.137Z DEBUG modem << D: (0x20022078): >> length:0x00000044 cur:0x00000000, end:0x00000000
2021-03-19T12:08:54.141Z DEBUG modem << D: (0x20022078): Fixed header length = 02
2021-03-19T12:08:54.153Z DEBUG modem << D: (0x20022078): >> val:32 cur:0x20024111, end:0x2002418e
2021-03-19T12:08:54.170Z DEBUG modem << D: (0x20022078): >> length:0x00000044 cur:0x20024112, end:0x2002418e
2021-03-19T12:08:54.171Z DEBUG modem << D: (0x20022078): [0x20027f10]: Transport writing message.
2021-03-19T12:08:54.193Z DEBUG modem << D: (0x20022078): [0x20027f10]: Transport write complete.
2021-03-19T12:08:54.202Z DEBUG modem << D: (0x20022078): [CID 0x20027f10]:[State 0x06]: << result 0x00000000
2021-03-19T12:08:54.204Z DEBUG modem << [mqtt_evt_handler:182] MQTT client connected!
2021-03-19T12:08:54.271Z DEBUG modem << D: (0x20022078): [CID 0x20027f10]:[State 0x06]: >> Topic size 0x0000002a, Data size 0x0000003a
2021-03-19T12:08:54.277Z DEBUG modem << D: (0x20022078): >> str_size:0000002c cur:0x20024113, end:0x2002418e
2021-03-19T12:08:54.285Z DEBUG modem << D: (0x20022078): >> val:002a cur:0x20024113, end:0x2002418e
2021-03-19T12:08:54.288Z DEBUG modem << D: (0x20022078): >> val:7eb5 cur:0x2002413f, end:0x2002418e
2021-03-19T12:08:54.293Z DEBUG modem << D: (0x20022078): << msg type:0x32 length:0x00000068
2021-03-19T12:08:54.302Z DEBUG modem << D: (0x20022078): >> length:0x00000068 cur:0x00000000, end:0x00000000
2021-03-19T12:08:54.304Z DEBUG modem << D: (0x20022078): Fixed header length = 02
2021-03-19T12:08:54.308Z DEBUG modem << D: (0x20022078): >> val:32 cur:0x20024111, end:0x2002418e
2021-03-19T12:08:54.320Z DEBUG modem << D: (0x20022078): >> length:0x00000068 cur:0x20024112, end:0x2002418e
2021-03-19T12:08:54.321Z DEBUG modem << D: (0x20022078): [0x20027f10]: Transport writing message.
2021-03-19T12:08:54.326Z DEBUG modem << D: (0x20022078): [0x20027f10]: Transport write complete.
2021-03-19T12:08:54.336Z DEBUG modem << D: (0x20022078): [CID 0x20027f10]:[State 0x06]: << result 0x00000000
2021-03-19T12:08:54.786Z DEBUG modem << D: (0x20022078): state:0x00000006
2021-03-19T12:08:54.793Z DEBUG modem << D: (0x20022078): [CID 0x20027f10]: Connection closed.
2021-03-19T12:08:54.795Z DEBUG modem << D: (0x20022078): Closing socket 1
2021-03-19T12:08:54.838Z DEBUG modem << [mqtt_evt_handler:193] MQTT client disconnected -128
2021-03-19T12:08:54.845Z DEBUG modem << ERROR: mqtt_input -128
2021-03-19T12:08:54.846Z DEBUG modem << Disconnecting MQTT client...
2021-03-19T12:08:54.848Z DEBUG modem << Could not disconnect MQTT client. Error: -128
2021-03-19T12:09:05.332Z DEBUG modem << D: +CSCON notification

[dermot geraghty]

Hi Marte

Got a bit further with this.

But now the download gets stuck as can be seen in the attached log file.

Any idea why this might be?

Tks

log_24_03_nbr1.txt

[Marte Myrvold]

Hi,

Good to hear that you got a bit further. I have started looking at your log, but I will need some more time before I can say what is wrong. I also have some questions that might help me figuring this out.

I see that your device restarted several times during the log. Did you restart it yourself, or did it restart on its own? Does the download get stuck every time, or only sometimes? Can you point me to when in the log it gets stuck, is it when you get "Job document update was rejected", or is it somewhere else?

Best regards,

Marte

[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