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

[Marte Myrvold]

Hi,

The server is sending an encrypted alert that closes the TLS session. This happens right after something is sent, so the problem might be what is being sent. Could you enable more logging so we can see what is being sent right before the connection is closed? You can enable it by adding the following to prj.conf:

CONFIG_NET_LOG=y
CONFIG_MQTT_LOG_LEVEL_DBG=y
CONFIG_LTE_LINK_CONTROL_LOG_LEVEL_DBG=y
CONFIG_AWS_FOTA_LOG_LEVEL_DBG=y

Best regards,

Marte

[dermot geraghty]

Hi Marte,

I have done that and attached the new log file.

Thanks

Dermottrace-2021-03-19T12-08-38.774Z.bin

[Marte Myrvold]

Hi,

Could you share the output log from the terminal? If you are using LTE Link Monitor you can get this by clicking on the "Open log file" button.

Best regards,

Marte

[Marte Myrvold]

Hi,

Could you also try going into AWS IoT, Manage, Tings, <your thing>, Shadows and look at the device's shadow there? You might be able to find a reason for the disconnect there, under "disconnectReason". The description of the different disconnect reasons can be found here.

Best regards,

Marte

[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