AWS_FOTA: ERROR: mqtt_connect -22

[icampbell]

Hello, I've been having problems getting the AWS_FOTA sample working on a nrf9160 DK.

At first, the device got stuck as it was downloading the firmware update, at 2%. I was able to fix this by setting CONFIG_DFU_TARGET_MCUBOOT_SAVE_PROGRESS=n. After that, the download got stuck at around 11%, though that number changed a bit each time I ran it. While I was trying to fix that, the device stopped being able to connect to AWS at all, even though I didn't change anything. The device waits for a long time after the "client_id:" line, and then seems to time out and print "ERROR: mqtt_connect -22". The timeout/error seems to come from mqtt_connect -> mqtt_client_tls_connect -> connect (line 87 in mqtt_transport_socket_tls.c). I am able to connect to AWS IoT from a python client on my computer using the same credentials and MQTT broker, so I don't think it's a problem with the AWS server.

Here are the changes I made to prj.conf:
CONFIG_DFU_TARGET_MCUBOOT_SAVE_PROGRESS=n
CONFIG_CLOUD_CERT_SEC_TAG=5
CONFIG_APP_VERSION="v1"
CONFIG_MQTT_BROKER_HOSTNAME="ahykgwaormc93-ats.iot.us-west-2.amazonaws.com"
CONFIG_USE_CLOUD_CLIENT_ID=y
CONFIG_CLOUD_CLIENT_ID="nrf9160dk"
CONFIG_USE_NRF_CLOUD=n

Besides that and the credentials (ran once with CONFIG_PROVISION_CERTIFICATES), I didn't make any changes to the AWS_FOTA sample.

I tried both the master branch and the v1.2.0 branch. I also stuff like turning CONFIG_DFU_TARGET_MCUBOOT_SAVE_PROGRESS on again, and re-flashing the credentials with CONFIG_PROVISION_CERTIFICATES again.

[Øyvind]

Hello, 

From nrfxlib\bsdlib\include\nrf_errno.h

#define NRF_EINVAL          22  /**< Invalid argument */

I've had no issues with the AWS FOTA sample (tested yesterday). Can you please provide the output from i.e. LTE Link Monitor? 

Kind regards,
Øyvind

[icampbell]

OK, here's the output

[icampbell]

I removed the extra spaces, but unfortunately it still says "ERROR: mqtt_connect -22".

The project should build. I'm on the "master" branch of the sdk, if that helps (I have also tried v1.2.0, rebased off of the v1.2.0 aws_fota sample, but it had the same problem).

[Øyvind]

I was able to build on master, not on tag v1.2.0. And the project worked as intended. Below is the output from LTE Link Monitor. (Missed the first part of startup)

2020-03-31T07:05:42.719Z DEBUG modem << LTE Link Connected!\x0D\x0A
2020-03-31T07:05:42.879Z DEBUG modem << IPv4 Address 52.27.234.97\x0D\x0A
2020-03-31T07:05:42.890Z DEBUG modem << client_id: nrf9160dk\x0D\x0A
2020-03-31T07:05:47.980Z DEBUG modem << I: Subscribe: $aws/things/nrf9160dk/jobs/notify-next\x0D\x0A
2020-03-31T07:05:47.990Z DEBUG modem << I: Subscribe: $aws/things/nrf9160dk/jobs/$next/get/#\x0D
2020-03-31T07:05:47.995Z DEBUG modem << [mqtt_evt_handler:174] MQTT client connected!\x0D\x0A
2020-03-31T07:05:48.243Z DEBUG modem << I: subscribed to notify-next topic\x0D\x0A
2020-03-31T07:05:48.248Z DEBUG modem << I: Publish topic: $aws/things/nrf9160dk/jobs/$next/get\x0D\x0A
2020-03-31T07:05:48.252Z DEBUG modem << I: Publish payload {"clientToken": ""}\x0D\x0A
2020-03-31T07:05:48.628Z DEBUG modem << [mqtt_evt_handler:227] PUBACK packet id: 10768\x0D\x0A
2020-03-31T07:05:48.633Z DEBUG modem << [mqtt_evt_handler:237] SUBACK packet id: 2114\x0D\x0A
2020-03-31T07:05:48.923Z DEBUG modem << [mqtt_evt_handler:227] PUBACK packet id: 19180\x0D\x0A
2020-03-31T07:05:49.003Z DEBUG modem << I: Checking for an available job\x0D\x0A
2020-03-31T07:05:49.010Z DEBUG modem << I: Subscribe: $aws/things/nrf9160dk/jobs/fotatest_v2/update/#\x0D\x0A
2020-03-31T07:05:49.262Z DEBUG modem << I: Publish topic: $aws/things/nrf9160dk/jobs/fotatest_v2/update\x0D\x0A
2020-03-31T07:05:49.274Z DEBUG modem << I: Publish payload {"status":"IN_PROGRESS","statusDetails": null,"expectedVersion": "1","clientToken": ""}\x0D
2020-03-31T07:05:49.914Z DEBUG modem << [mqtt_evt_handler:227] PUBACK packet id: 52671\x0D
2020-03-31T07:05:49.922Z DEBUG modem << I: Start downloading firmware from nrf9160dktest.s3-us-west-2.amazonaws.com/app_update.bin\x0D
2020-03-31T07:05:49.983Z DEBUG modem << I: Attempting to connect over IPv4\x0D\x0A
2020-03-31T07:05:50.520Z DEBUG modem << I: Connected to nrf9160dktest.s3-us-west-2.amazonaws.com\x0D\x0A
2020-03-31T07:05:50.524Z DEBUG modem << I: Downloading: app_update.bin [0]\x0D\x0A
2020-03-31T07:05:50.533Z DEBUG modem << AWS_FOTA_EVT_START, job id = fotatest_v2\x0D\x0A
2020-03-31T07:05:52.119Z DEBUG modem << I: Downloaded 4096/183300 bytes (2%)\x0D\x0A
2020-03-31T07:05:52.126Z DEBUG modem << I: 2 Sectors of 4096 bytes\x0D\x0A
2020-03-31T07:05:52.128Z DEBUG modem << I: alloc wra: 0, fb0\x0D\x0A
2020-03-31T07:05:52.130Z DEBUG modem << I: data wra: 0, c7c\x0D\x0A
2020-03-31T07:05:52.136Z DEBUG modem << I: Refuse fragment, restart with offset\x0D\x0A
2020-03-31T07:05:52.141Z DEBUG modem << I: Fragment refused, download stopped.\x0D\x0A
2020-03-31T07:05:53.134Z DEBUG modem << I: Downloading: app_update.bin [2508627009]\x0D\x0A
2020-03-31T07:05:53.149Z DEBUG modem << I: Downloading from offset: 0x95869c41\x0D\x0A
2020-03-31T07:05:53.779Z DEBUG modem << E: Server did not send "Content-Range" in response\x0D\x0A
2020-03-31T07:05:53.785Z DEBUG modem << E: Download client error\x0D\x0A
2020-03-31T07:05:53.789Z DEBUG modem << I: MCUBoot image upgrade aborted.\x0D
2020-03-31T07:05:53.793Z DEBUG modem << E: FOTA download failed, report back\x0D\x0A
2020-03-31T07:05:53.801Z DEBUG modem << I: Publish topic: $aws/things/nrf9160dk/jobs/fotatest_v2/update\x0D
2020-03-31T07:05:53.815Z DEBUG modem << I: Publish payload {"status":"FAILED","statusDetails": null,"expectedVersion": "2","clientToken": ""}\x0D\x0A
2020-03-31T07:05:53.823Z DEBUG modem << AWS_FOTA_EVT_ERROR\x0D\x0A
2020-03-31T07:05:54.394Z DEBUG modem << [mqtt_evt_handler:227] PUBACK packet id: 4808\x0D
2020-03-31T07:05:55.364Z DEBUG modem << I: Checking for an available job\x0D
2020-03-31T07:05:55.368Z DEBUG modem << I: No queued jobs for this device\x0D\x0A
2020-03-31T07:06:17.446Z DEBUG modem << *** Booting Zephyr OS build v2.1.99-ncs1-15-g9e7299a38e12  ***\x0D
2020-03-31T07:06:17.452Z DEBUG modem << [00:00:00.006,683] \x1B[0m<inf> mcuboot: Starting bootloader\x1B[0m\x0D\x0A
2020-03-31T07:06:17.463Z DEBUG modem << [00:00:00.014,923] \x1B[0m<inf> mcuboot: Primary image: magic=bad, swap_type=0x1, copy_done=0x2, image_ok=0x2\x1B[0m\x0D\x0A
2020-03-31T07:06:17.468Z DEBUG modem << [00:00:00.027,984] \x1B[0m<inf> mcuboot: Boot source: none\x1B[0m\x0D\x0A
2020-03-31T07:06:17.473Z DEBUG modem << [00:00:00.035,217] \x1B[0m<inf> mcuboot: Swap type: none\x1B[0m\x0D\x0A
2020-03-31T07:06:17.757Z DEBUG modem << [00:00:00.387,512] \x1B[0m<inf> mcuboot: Bootloader chainload address offset: 0x10000\x1B[0m\x0D\x0A
2020-03-31T07:06:17.767Z DEBUG modem << [00:00:00.395,202] \x1B[0m<inf> mcuboot: Jumping to the first image slot\x1B[0m\x0D\x0A
2020-03-31T07:06:17.769Z DEBUG modem << *** Booting Zephyr OS build v2.1.99-ncs1-15-g9e7299a38e12  ***\x0D\x0A
2020-03-31T07:06:17.770Z DEBUG modem << Flash regions\x09\x09Domain\x09\x09Permissions\x0D\x0A
2020-03-31T07:06:17.772Z DEBUG modem << 00 02 0x00000 0x18000 \x09Secure\x09\x09rwxl\x0D
2020-03-31T07:06:17.776Z DEBUG modem << 03 31 0x18000 0x100000 \x09Non-Secure\x09rwxl\x0D\x0A\x0D
2020-03-31T07:06:17.788Z DEBUG modem << Non-secure callable region 0 placed in flash region 2 with size 32.\x0D\x0A\x0D\x0A
2020-03-31T07:06:17.952Z DEBUG modem << SRAM region\x09\x09Domain\x09\x09Permissions\x0D
2020-03-31T07:06:17.957Z DEBUG modem << 00 07 0x00000 0x10000 \x09Secure\x09\x09rwxl\x0D\x0A
2020-03-31T07:06:17.960Z DEBUG modem << 08 31 0x10000 0x40000 \x09Non-Secure\x09rwxl\x0D\x0A\x0D\x0A
2020-03-31T07:06:17.963Z DEBUG modem << Peripheral\x09\x09Domain\x09\x09Status\x0D\x0A
2020-03-31T07:06:17.968Z DEBUG modem << 00 NRF_P0               Non-Secure\x09OK\x0D\x0A
2020-03-31T07:06:17.969Z DEBUG modem << 01 NRF_CLOCK            Non-Secure\x09OK\x0D\x0A
2020-03-31T07:06:17.973Z DEBUG modem << 02 NRF_RTC0             Non-Secure\x09OK\x0D\x0A
2020-03-31T07:06:17.976Z DEBUG modem << 03 NRF_RTC1             Non-Secure\x09OK\x0D
2020-03-31T07:06:17.979Z DEBUG modem << 04 NRF_NVMC             Non-Secure\x09OK\x0D\x0A
2020-03-31T07:06:17.987Z DEBUG modem << 05 NRF_UARTE1           Non-Secure\x09OK\x0D\x0A
2020-03-31T07:06:17.988Z DEBUG modem << 06 NRF_UARTE2           Secure\x09\x09SKIP\x0D\x0A
2020-03-31T07:06:17.990Z DEBUG modem << 07 NRF_TWIM2            Non-Secure\x09OK\x0D\x0A
2020-03-31T07:06:17.992Z DEBUG modem << 08 NRF_SPIM3            Non-Secure\x09OK\x0D
2020-03-31T07:06:18.000Z DEBUG modem << 09 NRF_TIMER0           Non-Secure\x09OK\x0D\x0A
2020-03-31T07:06:18.001Z DEBUG modem << 10 NRF_TIMER1           Non-Secure\x09OK\x0D\x0A
2020-03-31T07:06:18.003Z DEBUG modem << 11 NRF_TIMER2           Non-Secure\x09OK\x0D\x0A
2020-03-31T07:06:18.006Z DEBUG modem << 12 NRF_SAADC            Non-Secure\x09OK\x0D
2020-03-31T07:06:18.010Z DEBUG modem << 13 NRF_PWM0             Non-Secure\x09OK\x0D\x0A
2020-03-31T07:06:18.017Z DEBUG modem << 14 NRF_PWM1             Non-Secure\x09OK\x0D\x0A
2020-03-31T07:06:18.018Z DEBUG modem << 15 NRF_PWM2             Non-Secure\x09OK\x0D\x0A
2020-03-31T07:06:18.020Z DEBUG modem << 16 NRF_PWM3             Non-Secure\x09OK\x0D
2020-03-31T07:06:18.023Z DEBUG modem << 17 NRF_WDT              Non-Secure\x09OK\x0D\x0A
2020-03-31T07:06:18.027Z DEBUG modem << 18 NRF_IPC              Non-Secure\x09OK\x0D
2020-03-31T07:06:18.033Z DEBUG modem << 19 NRF_VMC              Non-Secure\x09OK\x0D\x0A
2020-03-31T07:06:18.035Z DEBUG modem << 20 NRF_FPU              Non-Secure\x09OK\x0D\x0A
2020-03-31T07:06:18.037Z DEBUG modem << 21 NRF_EGU1             Non-Secure\x09OK\x0D\x0A
2020-03-31T07:06:18.040Z DEBUG modem << 22 NRF_EGU2             Non-Secure\x09OK\x0D\x0A
2020-03-31T07:06:18.044Z DEBUG modem << 23 NRF_DPPIC            Non-Secure\x09OK\x0D
2020-03-31T07:06:18.050Z DEBUG modem << 24 NRF_GPIOTE1          Non-Secure\x09OK\x0D\x0A
2020-03-31T07:06:18.052Z DEBUG modem << 25 NRF_REGULATORS       Non-Secure\x09OK\x0D\x0A\x0D\x0A
2020-03-31T07:06:18.054Z DEBUG modem << SPM: NS image at 0x1c200\x0D\x0A
2020-03-31T07:06:18.056Z DEBUG modem << SPM: NS MSP at 0x200282c8\x0D\x0A
2020-03-31T07:06:18.058Z DEBUG modem << SPM: NS reset vector at 0x20469\x0D
2020-03-31T07:06:18.062Z DEBUG modem << SPM: prepare to jump to Non-Secure image.\x0D\x0A
2020-03-31T07:06:18.072Z DEBUG modem << *** Booting Zephyr OS build v2.1.99-ncs1-15-g9e7299a38e12  ***\x0D\x0A
2020-03-31T07:06:18.075Z DEBUG modem << MQTT AWS Jobs FOTA Sample, version: v1\x0D\x0A
2020-03-31T07:06:18.077Z DEBUG modem << Initializing bsdlib\x0D
2020-03-31T07:06:18.296Z DEBUG modem << Initialized bsdlib\x0D
2020-03-31T07:06:18.309Z DEBUG modem << ************************* WARNING *************************\x0D\x0A
2020-03-31T07:06:18.317Z DEBUG modem << provision_certificates called do not use this in production!\x0D\x0A
2020-03-31T07:06:18.320Z DEBUG modem << This will store the certificates in readable flash and leave\x0D\x0A
2020-03-31T07:06:18.325Z DEBUG modem << them exposed on modem_traces. Only use this once for\x0D\x0A
2020-03-31T07:06:18.333Z DEBUG modem << provisioning certificates for development to reduce flash tear.\x0D\x0A
2020-03-31T07:06:18.336Z DEBUG modem << ************************* WARNING *************************\x0D\x0A
2020-03-31T07:06:18.468Z DEBUG modem << modem_key_mgmt_delete(1337, 0) => result=0\x0D\x0A
2020-03-31T07:06:18.501Z DEBUG modem << modem_key_mgmt_delete(1337, 1) => result=0\x0D\x0A
2020-03-31T07:06:18.604Z DEBUG modem << modem_key_mgmt_delete(1337, 2) => result=0\x0D\x0A
2020-03-31T07:06:18.716Z DEBUG modem << modem_key_mgmt_write => result=0\x0D\x0A
2020-03-31T07:06:18.851Z DEBUG modem << modem_key_mgmt_write => result=0\x0D
2020-03-31T07:06:18.918Z DEBUG modem << modem_key_mgmt_write => result=0\x0D\x0A
2020-03-31T07:06:18.922Z DEBUG modem << LTE Link Connecting ...\x0D\x0A
2020-03-31T07:06:21.202Z DEBUG modem << LTE Link Connected!\x0D\x0A
2020-03-31T07:06:21.367Z DEBUG modem << IPv4 Address 52.27.234.97\x0D\x0A
2020-03-31T07:06:21.372Z DEBUG modem << client_id: nrf9160dk\x0D\x0A
2020-03-31T07:06:26.969Z DEBUG modem << I: Subscribe: $aws/things/nrf9160dk/jobs/notify-next\x0D
2020-03-31T07:06:26.985Z DEBUG modem << I: Subscribe: $aws/things/nrf9160dk/jobs/$next/get/#\x0D\x0A
2020-03-31T07:06:26.986Z DEBUG modem << [mqtt_evt_handler:174] MQTT client connected!\x0D\x0A
2020-03-31T07:06:27.276Z DEBUG modem << I: subscribed to notify-next topic\x0D\x0A
2020-03-31T07:06:27.282Z DEBUG modem << I: Publish topic: $aws/things/nrf9160dk/jobs/$next/get\x0D
2020-03-31T07:06:27.285Z DEBUG modem << I: Publish payload {"clientToken": ""}\x0D
2020-03-31T07:06:27.617Z DEBUG modem << [mqtt_evt_handler:227] PUBACK packet id: 30113\x0D\x0A
2020-03-31T07:06:27.621Z DEBUG modem << [mqtt_evt_handler:237] SUBACK packet id: 2114\x0D\x0A
2020-03-31T07:06:27.878Z DEBUG modem << [mqtt_evt_handler:227] PUBACK packet id: 39954\x0D\x0A
2020-03-31T07:06:27.912Z DEBUG modem << I: Checking for an available job\x0D
2020-03-31T07:06:27.917Z DEBUG modem << I: No queued jobs for this device\x0D\x0A

I see I'm getting the same issue as you did at first, stopping at 2%. 

2020-03-31T07:05:52.119Z DEBUG modem << I: Downloaded 4096/183300 bytes (2%)\x0D\x0A
2020-03-31T07:05:52.126Z DEBUG modem << I: 2 Sectors of 4096 bytes\x0D\x0A
2020-03-31T07:05:52.128Z DEBUG modem << I: alloc wra: 0, fb0\x0D\x0A
2020-03-31T07:05:52.130Z DEBUG modem << I: data wra: 0, c7c\x0D\x0A
2020-03-31T07:05:52.136Z DEBUG modem << I: Refuse fragment, restart with offset\x0D\x0A
2020-03-31T07:05:52.141Z DEBUG modem << I: Fragment refused, download stopped.\x0D\x0A
2020-03-31T07:05:53.134Z DEBUG modem << I: Downloading: app_update.bin [2508627009]\x0D\x0A
2020-03-31T07:05:53.149Z DEBUG modem << I: Downloading from offset: 0x95869c41\x0D\x0A
2020-03-31T07:05:53.779Z DEBUG modem << E: Server did not send "Content-Range" in response\x0D\x0A
2020-03-31T07:05:53.785Z DEBUG modem << E: Download client error\x0D\x0A

" Server did not send "Content-Range" in response" 

[icampbell]

Yes, building it on master is expected (I changed the code when I built it on v1.2.0).

The project working is strange, considering my device still doesn't work. Any idea what might be causing this?

Also, I remember when my device got to 2%, it just hung on that line ("Downloaded 4096/183300 bytes (2%)"), not printed out an error after. Did it hang a really long time on that line for you?

[Øyvind]

icampbell said:

Did it hang a really long time on that line for you?

 No, the log shows that it failed immediately. 

What does your job file look like?

[icampbell]

So, I tested it today and it spontaneously started working again. I didn't even have to re-flash the device, the code that wasn't working earlier started working again today. I don't think I made any changes on AWS, either. I even tested a FOTA update and it worked.

Here's the logs from when it worked

*** Booting Zephyr OS build v2.1.99-ncs1-4-gc025ef3dd566  ***
MQTT AWS Jobs FOTA Sample, version: v1
Initializing bsdlib
Initialized bsdlib
LTE Link Connecting ...
LTE Link Connected!
IPv4 Address 52.39.0.142
client_id: nrf9160dk
I: Subscribe: $aws/things/nrf9160dk/jobs/notify-next
I: Subscribe: $aws/things/nrf9160dk/jobs/$next/get/#
[mqtt_evt_handler:174] MQTT client connected!
I: subscribed to notify-next topic
I: Publish topic: $aws/things/nrf9160dk/jobs/$next/get
I: Publish payload {"clientToken": ""}
[mqtt_evt_handler:227] PUBACK packet id: 39715
[mqtt_evt_handler:237] SUBACK packet id: 2114
[mqtt_evt_handler:227] PUBACK packet id: 61524
I: Checking for an available job
I: Subscribe: $aws/things/nrf9160dk/jobs/fota3/update/#
I: Publish topic: $aws/things/nrf9160dk/jobs/fota3/update
I: Publish payload {"status":"IN_PROGRESS","statusDetails": null,"expectedVersion": "1","clientToken": ""}
[mqtt_evt_handler:227] PUBACK packet id: 11375
I: Start downloading firmware from nrf9160dktest.s3-us-west-2.amazonaws.com/app_update.bin
I: Attempting to connect over IPv4
I: Connected to nrf9160dktest.s3-us-west-2.amazonaws.com
I: Downloading: app_update.bin [0]
AWS_FOTA_EVT_START, job id = fota3
I: Downloaded 4096/183300 bytes (2%)
I: 2 Sectors of 4096 bytes
I: alloc wra: 0, ff0
I: data wra: 0, 0
I: Erasing sector at offset 0x00087000
I: Erasing sector at offset 0x00088000
E: Failed to send HTTP request, errno 128
W: Download socket error. 2 retries left...
I: Reconnecting..
I: Attempting to connect over IPv4
I: Connected to nrf9160dktest.s3-us-west-2.amazonaws.com
I: Downloaded 8192/183300 bytes (4%)
I: Erasing sector at offset 0x00089000
I: Downloaded 12288/183300 bytes (6%)
I: Erasing sector at offset 0x0008a000
I: Downloaded 16384/183300 bytes (8%)
I: Erasing sector at offset 0x0008b000
I: Downloaded 20480/183300 bytes (11%)
I: Erasing sector at offset 0x0008c000
I: Downloaded 24576/183300 bytes (13%)
I: Erasing sector at offset 0x0008d000
I: Downloaded 28672/183300 bytes (15%)
I: Erasing sector at offset 0x0008e000
I: Downloaded 32768/183300 bytes (17%)
I: Erasing sector at offset 0x0008f000
I: Downloaded 36864/183300 bytes (20%)
I: Erasing sector at offset 0x00090000
I: Downloaded 40960/183300 bytes (22%)
I: Erasing sector at offset 0x00091000
I: Downloaded 45056/183300 bytes (24%)
I: Erasing sector at offset 0x00092000
I: Downloaded 49152/183300 bytes (26%)
I: Erasing sector at offset 0x00093000
I: Downloaded 53248/183300 bytes (29%)
I: Erasing sector at offset 0x00094000
I: Downloaded 57344/183300 bytes (31%)
I: Erasing sector at offset 0x00095000
I: Downloaded 61440/183300 bytes (33%)
I: Erasing sector at offset 0x00096000
I: Downloaded 65536/183300 bytes (35%)
I: Erasing sector at offset 0x00097000
I: Downloaded 69632/183300 bytes (37%)
I: Erasing sector at offset 0x00098000
I: Downloaded 73728/183300 bytes (40%)
I: Erasing sector at offset 0x00099000
I: Downloaded 77824/183300 bytes (42%)
I: Erasing sector at offset 0x0009a000
I: Downloaded 81920/183300 bytes (44%)
I: Erasing sector at offset 0x0009b000
I: Downloaded 86016/183300 bytes (46%)
I: Erasing sector at offset 0x0009c000
I: Downloaded 90112/183300 bytes (49%)
I: Erasing sector at offset 0x0009d000
I: Downloaded 94208/183300 bytes (51%)
I: Erasing sector at offset 0x0009e000
I: Downloaded 98304/183300 bytes (53%)
I: Erasing sector at offset 0x0009f000
I: Downloaded 102400/183300 bytes (55%)
I: Erasing sector at offset 0x000a0000
I: Downloaded 106496/183300 bytes (58%)
I: Erasing sector at offset 0x000a1000
I: Downloaded 110592/183300 bytes (60%)
I: Erasing sector at offset 0x000a2000
I: Downloaded 114688/183300 bytes (62%)
I: Erasing sector at offset 0x000a3000
I: Downloaded 118784/183300 bytes (64%)
I: Erasing sector at offset 0x000a4000
I: Downloaded 122880/183300 bytes (67%)
I: Erasing sector at offset 0x000a5000
I: Downloaded 126976/183300 bytes (69%)
I: Erasing sector at offset 0x000a6000
I: Downloaded 131072/183300 bytes (71%)
I: Erasing sector at offset 0x000a7000
I: Downloaded 135168/183300 bytes (73%)
I: Erasing sector at offset 0x000a8000
I: Downloaded 139264/183300 bytes (75%)
I: Erasing sector at offset 0x000a9000
I: Downloaded 143360/183300 bytes (78%)
I: Erasing sector at offset 0x000aa000
I: Downloaded 147456/183300 bytes (80%)
I: Erasing sector at offset 0x000ab000
I: Downloaded 151552/183300 bytes (82%)
I: Erasing sector at offset 0x000ac000
I: Downloaded 155648/183300 bytes (84%)
I: Erasing sector at offset 0x000ad000
I: Downloaded 159744/183300 bytes (87%)
I: Erasing sector at offset 0x000ae000
I: Downloaded 163840/183300 bytes (89%)
I: Erasing sector at offset 0x000af000
I: Downloaded 167936/183300 bytes (91%)
I: Erasing sector at offset 0x000b0000
I: Downloaded 172032/183300 bytes (93%)
I: Erasing sector at offset 0x000b1000
I: Downloaded 176128/183300 bytes (96%)
I: Erasing sector at offset 0x000b2000
I: Downloaded 180224/183300 bytes (98%)
I: Erasing sector at offset 0x000b3000
I: Downloaded 183300/183300 bytes (100%)
I: Download complete
I: Erasing sector at offset 0x000fd000
I: MCUBoot image upgrade scheduled. Reset the device to apply
I: FOTA download completed evt received
AWS_FOTA_EVT_DL_PROGRESS, 100% downloaded
I: Publish topic: $aws/things/nrf9160dk/jobs/fota3/update
I: Publish payload {"status":"IN_PROGRESS","statusDetails": null,"expectedVersion": "2","clientToken": ""}
[mqtt_evt_handler:227] PUBACK packet id: 23027
I: Firmware download completed
I: Publish topic: $aws/things/nrf9160dk/jobs/fota3/update
I: Publish payload {"status":"SUCCEEDED","statusDetails": null,"expectedVersion": "3","clientToken": ""}
[mqtt_evt_handler:227] PUBACK packet id: 65327
AWS_FOTA_EVT_DONE, rebooting to apply update
I: Job document updated with SUCCEDED
I: Ready to reboot
[mqtt_evt_handler:185] MQTT client disconnected 0
*** Booting Zephyr OS build v2.1.99-ncs1-4-gc025ef3dd566  ***
[00:00:00.005,279] <inf> mcuboot: Starting bootloader
[00:00:00.011,413] <inf> mcuboot: Primary image: magic=unset, swap_type=0x1, copy_done=0x3, image_ok=0x1
[00:00:00.021,453] <inf> mcuboot: Boot source: none
[00:00:00.026,885] <inf> mcuboot: Swap type: test
[00:00:18.782,348] <inf> mcuboot: Bootloader chainload address offset: 0x10000
[00:00:18.790,069] <inf> mcuboot: Jumping to the first image slot
*** Booting Zephyr OS build v2.1.99-ncs1-3-g7ddab664b04b  ***
Flash region		Domain		Permissions
00 0x00000 0x08000 	Secure		rwxl
01 0x08000 0x10000 	Secure		rwxl
02 0x10000 0x18000 	Secure		rwxl
03 0x18000 0x20000 	Non-Secure	rwxl
04 0x20000 0x28000 	Non-Secure	rwxl
05 0x28000 0x30000 	Non-Secure	rwxl
06 0x30000 0x38000 	Non-Secure	rwxl
07 0x38000 0x40000 	Non-Secure	rwxl
08 0x40000 0x48000 	Non-Secure	rwxl
09 0x48000 0x50000 	Non-Secure	rwxl
10 0x50000 0x58000 	Non-Secure	rwxl
11 0x58000 0x60000 	Non-Secure	rwxl
12 0x60000 0x68000 	Non-Secure	rwxl
13 0x68000 0x70000 	Non-Secure	rwxl
14 0x70000 0x78000 	Non-Secure	rwxl
15 0x78000 0x80000 	Non-Secure	rwxl
16 0x80000 0x88000 	Non-Secure	rwxl
17 0x88000 0x90000 	Non-Secure	rwxl
18 0x90000 0x98000 	Non-Secure	rwxl
19 0x98000 0xa0000 	Non-Secure	rwxl
20 0xa0000 0xa8000 	Non-Secure	rwxl
21 0xa8000 0xb0000 	Non-Secure	rwxl
22 0xb0000 0xb8000 	Non-Secure	rwxl
23 0xb8000 0xc0000 	Non-Secure	rwxl
24 0xc0000 0xc8000 	Non-Secure	rwxl
25 0xc8000 0xd0000 	Non-Secure	rwxl
26 0xd0000 0xd8000 	Non-Secure	rwxl
27 0xd8000 0xe0000 	Non-Secure	rwxl
28 0xe0000 0xe8000 	Non-Secure	rwxl
29 0xe8000 0xf0000 	Non-Secure	rwxl
30 0xf0000 0xf8000 	Non-Secure	rwxl
31 0xf8000 0x100000 	Non-Secure	rwxl
Non-secure callable region 0 placed in flash region 2 with size 32.


SRAM region		Domain		Permissions
00 0x00000 0x02000	Secure		rwxl
01 0x02000 0x04000	Secure		rwxl
02 0x04000 0x06000	Secure		rwxl
03 0x06000 0x08000	Secure		rwxl
04 0x08000 0x0a000	Secure		rwxl
05 0x0a000 0x0c000	Secure		rwxl
06 0x0c000 0x0e000	Secure		rwxl
07 0x0e000 0x10000	Secure		rwxl
08 0x10000 0x12000	Non-Secure	rwxl
09 0x12000 0x14000	Non-Secure	rwxl
10 0x14000 0x16000	Non-Secure	rwxl
11 0x16000 0x18000	Non-Secure	rwxl
12 0x18000 0x1a000	Non-Secure	rwxl
13 0x1a000 0x1c000	Non-Secure	rwxl
14 0x1c000 0x1e000	Non-Secure	rwxl
15 0x1e000 0x20000	Non-Secure	rwxl
16 0x20000 0x22000	Non-Secure	rwxl
17 0x22000 0x24000	Non-Secure	rwxl
18 0x24000 0x26000	Non-Secure	rwxl
19 0x26000 0x28000	Non-Secure	rwxl
20 0x28000 0x2a000	Non-Secure	rwxl
21 0x2a000 0x2c000	Non-Secure	rwxl
22 0x2c000 0x2e000	Non-Secure	rwxl
23 0x2e000 0x30000	Non-Secure	rwxl
24 0x30000 0x32000	Non-Secure	rwxl
25 0x32000 0x34000	Non-Secure	rwxl
26 0x34000 0x36000	Non-Secure	rwxl
27 0x36000 0x38000	Non-Secure	rwxl
28 0x38000 0x3a000	Non-Secure	rwxl
29 0x3a000 0x3c000	Non-Secure	rwxl
30 0x3c000 0x3e000	Non-Secure	rwxl
31 0x3e000 0x40000	Non-Secure	rwxl

Peripheral		Domain		Status
00 NRF_P0               Non-Secure	OK
01 NRF_CLOCK            Non-Secure	OK
02 NRF_RTC0             Non-Secure	OK
03 NRF_RTC1             Non-Secure	OK
04 NRF_NVMC             Non-Secure	OK
05 NRF_UARTE1           Non-Secure	OK
06 NRF_UARTE2           Secure		SKIP
07 NRF_TWIM2            Non-Secure	OK
08 NRF_SPIM3            Non-Secure	OK
09 NRF_TIMER0           Non-Secure	OK
10 NRF_TIMER1           Non-Secure	OK
11 NRF_TIMER2           Non-Secure	OK
12 NRF_SAADC            Non-Secure	OK
13 NRF_PWM0             Non-Secure	OK
14 NRF_PWM1             Non-Secure	OK
15 NRF_PWM2             Non-Secure	OK
16 NRF_PWM3             Non-Secure	OK
17 NRF_WDT              Non-Secure	OK
18 NRF_IPC              Non-Secure	OK
19 NRF_VMC              Non-Secure	OK
20 NRF_FPU              Non-Secure	OK
21 NRF_EGU1             Non-Secure	OK
22 NRF_EGU2             Non-Secure	OK
23 NRF_DPPIC            Non-Secure	OK
24 NRF_GPIOTE1          Non-Secure	OK
25 NRF_REGULATORS       Non-Secure	OK

SPM: NS image at 0x1c200
SPM: NS MSP at 0x20028278
SPM: NS reset vector at 0x2040d
SPM: prepare to jump to Non-Secure image.
*** Booting Zephyr OS build v2.1.99-ncs1-3-g7ddab664b04b  ***
MQTT AWS Jobs FOTA Sample, version: v2
Initializing bsdlib
Initialized bsdlib
************************* WARNING *************************
provision_certificates called do not use this in production!
This will store the certificates in readable flash and leave
them exposed on modem_traces. Only use this once for
provisioning certificates for development to reduce flash tear.
************************* WARNING *************************
modem_key_mgmt_delete(5, 0) => result=0
modem_key_mgmt_delete(5, 1) => result=0
modem_key_mgmt_delete(5, 2) => result=0
modem_key_mgmt_write => result=0
modem_key_mgmt_write => result=0
modem_key_mgmt_write => result=0
LTE Link Connecting ...
LTE Link Connected!
IPv4 Address 52.39.0.142
client_id: nrf9160dk
I: Subscribe: $aws/things/nrf9160dk/jobs/notify-next
I: Subscribe: $aws/things/nrf9160dk/jobs/$next/get/#
[mqtt_evt_handler:172] MQTT client connected!
I: subscribed to notify-next topic
I: Publish topic: $aws/things/nrf9160dk/jobs/$next/get
I: Publish payload {"clientToken": ""}
[mqtt_evt_handler:225] PUBACK packet id: 6469
[mqtt_evt_handler:235] SUBACK packet id: 2114
[mqtt_evt_handler:225] PUBACK packet id: 24502
I: Checking for an available job
I: No queued jobs for this device

Here's the job file you asked about

{
  "operation": "app_fw_update",
  "fwversion": "v1.0.2",
  "size": 181124,
  "location": {
    "protocol": "http:",
    "host": "nrf9160dktest.s3-us-west-2.amazonaws.com",
    "path": "app_update.bin"
  }
}

So I guess the problem is fixed now?

[Øyvind]

This looks very promising. I'm a little baffled why it suddenly started to work, but nothing is better than this result. 

Let's close for now, and if it does occur again please let us know. 

Kind regards,
Øyvind