AWS FOTA downlaods but fails when writing the file

[hmichel]

The AWS FOTA sample starts the download of my app_update.bin file that I created and loaded into an s3 bucket.

The file downloads (you can see in the attached logs) but after erasing / downloading  some of the data the 

process fails apparently for different reasons each time

Fullscreen log02062020_01.txt Download

nrf_inbuilt_key_delete(12345678, 2) => result=0
nrf_inbuilt_key_write => result=0
nrf_inbuilt_key_write => result=0
nrf_inbuilt_key_write => result=0
LTE Link Connecting ...
LTE Link Connected!
IPv4 Address 52.15.223.13
client_id: nrf-352656100047698
[mqtt_evt_handler:209] MQTT client connected!
[mqtt_evt_handler:262] PUBACK packet id: 54346
[mqtt_evt_handler:272] SUBACK packet id: 2114
[00:00:15.651,611] [1B][0m<inf> aws_jobs: Subscribe: $aws/things/nrf-352656100047698/jobs/notify-next[1B][0m
[00:00:15.653,503] [1B][0m<inf> aws_jobs: Subscribe: $aws/things/nrf-352656100047698/jobs/$next/get/#[1B][0m
[00:00:16.072,509] [1B][0m<inf> aws_fota: subscribed to notify-next topic[1B][0m
[00:00:16.072,601] [1B][0m<inf> aws_jobs: Publish topic: $aws/things/nrf-352656100047698/jobs/$next/get[1B][0m
[00:00:16.072,601] [1B][0m<inf> aws_jobs: Publish payload {"clientToken": ""}[1B][0m
[mqtt_evt_handler:262] PUBACK packet id: 2379
***** Booting Zephyr OS build v2.0.99-ncs1 *****
[00:00:00.004,394] [1B][0m<inf> mcuboot: Starting bootloader[1B][0m
[00:00:00.012,939] [1B][0m<inf> mcuboot: Primary image: magic=good, swap_type=0x0, copy_done=0x1, image_ok=0x1[1B][0m
[00:00:00.026,214] [1B][0m<inf> mcuboot: Scratch: magic=unset, swap_type=0x1, copy_done=0x3, image_ok=0x3[1B][0m
[00:00:00.038,909] [1B][0m<inf> mcuboot: Boot source: none[1B][0m
[00:00:00.046,173] [1B][0m<inf> mcuboot: Swap type: none[1B][0m
[00:00:00.444,519] [1B][0m<inf> mcuboot: Bootloader chainload address offset: 0xc000[1B][0m
[00:00:00.452,178] [1B][0m<inf> mcuboot: Jumping to the first image slot[1B][0m
***** Booting Zephyr OS build v2.0.99-ncs1 *****
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_RTC1             Non-Secure	OK
03 NRF_NVMC             Non-Secure	OK
04 NRF_UARTE1           Non-Secure	OK
05 NRF_UARTE2           Secure		SKIP
06 NRF_TWIM2            Non-Secure	OK
07 NRF_SPIM3            Non-Secure	OK
08 NRF_TIMER0           Non-Secure	OK
09 NRF_TIMER1           Non-Secure	OK
10 NRF_TIMER2           Non-Secure	OK
11 NRF_SAADC            Non-Secure	OK
12 NRF_PWM0             Non-Secure	OK
13 NRF_PWM1             Non-Secure	OK
14 NRF_PWM2             Non-Secure	OK
15 NRF_PWM3             Non-Secure	OK
16 NRF_WDT              Secure		SKIP
17 NRF_IPC              Non-Secure	OK
18 NRF_VMC              Non-Secure	OK
19 NRF_FPU              Non-Secure	OK
20 NRF_EGU1             Non-Secure	OK
21 NRF_EGU2             Non-Secure	OK
22 NRF_DPPIC            Non-Secure	OK
23 NRF_GPIOTE1          Non-Secure	OK
24 NRF_REGULATORS       Secure		SKIP

SPM: NS image at 0x18200
SPM: NS MSP at 0x200285f0
SPM: NS reset vector at 0x1c8dd
SPM: prepare to jump to Non-Secure image.
***** Booting Zephyr OS build v2.0.99-ncs1 *****
MQTT AWS Jobs FOTA Sample, version: v1.1.0
Initializing bsdlib
Initialized bsdlib
The MQTT AWS Jobs FOTA Sample Start Image
************************* 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 *************************
nrf_inbuilt_key_delete(12345678, 0) => result=0
nrf_inbuilt_key_delete(12345678, 1) => result=0
nrf_inbuilt_key_delete(12345678, 2) => result=0
nrf_inbuilt_key_write => result=0
nrf_inbuilt_key_write => result=0
nrf_inbuilt_key_write => result=0
LTE Link Connecting ...
LTE Link Connected!
IPv4 Address 18.218.87.11
client_id: nrf-352656100047698
[mqtt_evt_handler:209] MQTT client connected!
[mqtt_evt_handler:262] PUBACK packet id: 65274
[mqtt_evt_handler:272] SUBACK packet id: 2114
[00:00:25.985,382] [1B][0m<inf> aws_jobs: Subscribe: $aws/things/nrf-352656100047698/jobs/notify-next[1B][0m
[00:00:25.987,152] [1B][0m<inf> aws_jobs: Subscribe: $aws/things/nrf-3526561[mqtt_evt_handler:262] PUBACK packet id: 11232
00047698/jobs/$next/get/#[1B][0m
[00:00:26.342,681] [1B][0m<inf> aws_fota: subscribed to notify-next topic[1B][0m
[00:00:26.342,742] [1B][0m<inf> aws_jobs: Publish topic: $aws/things/nrf-352656100047698/jobs/$next/get[1B][0m
[00:00:26.342,773] [1B][0m<inf> aws_jobs: Publish payload {"clientToken": ""}[1B][0m
***** Booting Zephyr OS build v2.0.99-ncs1 *****
[00:00:00.004,394] [1B][0m<inf> mcuboot: Starting bootloader[1B][0m
[00:00:00.012,969] [1B][0m<inf> mcuboot: Primary image: magic=good, swap_type=0x0, copy_done=0x1, image_ok=0x1[1B][0m
[00:00:00.026,214] [1B][0m<inf> mcuboot: Scratch: magic=unset, swap_type=0x1, copy_done=0x3, image_ok=0x3[1B][0m
[00:00:00.038,909] [1B][0m<inf> mcuboot: Boot source: none[1B][0m
[00:00:00.046,173] [1B][0m<inf> mcuboot: Swap type: none[1B][0m
[00:00:00.444,488] [1B][0m<inf> mcuboot: Bootloader chainload address offset: 0xc000[1B][0m
[00:00:00.452,148] [1B][0m<inf> mcuboot: Jumping to the first image slot[1B][0m
***** Booting Zephyr OS build v2.0.99-ncs1 *****
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_RTC1             Non-Secure	OK
03 NRF_NVMC             Non-Secure	OK
04 NRF_UARTE1           Non-Secure	OK
05 NRF_UARTE2           Secure		SKIP
06 NRF_TWIM2            Non-Secure	OK
07 NRF_SPIM3            Non-Secure	OK
08 NRF_TIMER0           Non-Secure	OK
09 NRF_TIMER1           Non-Secure	OK
10 NRF_TIMER2           Non-Secure	OK
11 NRF_SAADC            Non-Secure	OK
12 NRF_PWM0             Non-Secure	OK
13 NRF_PWM1             Non-Secure	OK
14 NRF_PWM2             Non-Secure	OK
15 NRF_PWM3             Non-Secure	OK
16 NRF_WDT              Secure		SKIP
17 NRF_IPC              Non-Secure	OK
18 NRF_VMC              Non-Secure	OK
19 NRF_FPU              Non-Secure	OK
20 NRF_EGU1             Non-Secure	OK
21 NRF_EGU2             Non-Secure	OK
22 NRF_DPPIC            Non-Secure	OK
23 NRF_GPIOTE1          Non-Secure	OK
24 NRF_REGULATORS       Secure		SKIP

SPM: NS image at 0x18200
SPM: NS MSP at 0x200285f0
SPM: NS reset vector at 0x1c8dd
SPM: prepare to jump to Non-Secure image.
***** Booting Zephyr OS build v2.0.99-ncs1 *****
MQTT AWS Jobs FOTA Sample, version: v1.1.0
Initializing bsdlib
Initialized bsdlib
The MQTT AWS Jobs FOTA Sample Start Image
************************* 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 *************************
nrf_inbuilt_key_delete(12345678, 0) => result=0
nrf_inbuilt_key_delete(12345678, 1) => result=0
nrf_inbuilt_key_delete(12345678, 2) => result=0
nrf_inbuilt_key_write => result=0
nrf_inbuilt_key_write => result=0
nrf_inbuilt_key_write => result=0
LTE Link Connecting ...
LTE Link Connected!
IPv4 Address 18.190.22.49
client_id: nrf-352656100047698
[mqtt_evt_handler:209] MQTT client connected!
[mqtt_evt_handler:262] PUBACK packet id: 38209
[mqtt_evt_handler:272] SUBACK packet id: 2114
[mqtt_evt_handler:262] PUBACK packet id: 51989
[00:00:15.159,423] [1B][0m<inf> aws_jobs: Subscribe: $aws/things/nrf-352656100047698/jobs/notify-next[1B][0m
[00:00:15.161,193] [1B][0m<inf> aws_jobs: Subscribe: $aws/things/nrf-352656100047698/jobs/$next/get/#[1B][0m
[00:00:15.586,456] [1B][0m<inf> aws_fota: subscribed to notify-next topic[1B][0m
[00:00:15.586,547] [1B][0m<inf> aws_jobs: Publish topic: $aws/things/nrf-352656100047698/jobs/$next/get[1B][0m
[00:00:15.586,547] [1B][0m<inf> aws_jobs: Publish payload {"clientToken": ""}[1B][0m
[00:00:16.179,077] [1B][0m<inf> aws_fota: Received topic: $aws/things/nrf-352656100047698/jobs/$next/get/accepted[1B][0m
[00:00:16.179,260] [1B][0m<inf> aws_fota: Got only one field: {"clientToken":"","timestamp":1581041025}[1B][0m
[mqtt_evt_handler:277] default: 8
[00:04:41.437,316] [1B][0m<inf> aws_fota: Received topic: $aws/things/nrf-352656100047698/jobs/notify-next[1B][0m
[00:04:41.437,927] [1B][0m<inf> aws_jobs: Unsubscribe: $aws/things/nrf-352656100047698/jobs/notify-next[1B][0m
[00:04:41.438,903] [1B][0m<inf> aws_jobs: Subscribe: $aws/things/nrf-352656100047698/jobs/nrf9160fwota_020620_09/update/#[1B][0m
[00:04:42.116,577] [1B][0m<inf> aws_jobs: Publish topic: $aws/things/nrf-352656100047698/jobs/nrf9160fwota_020620_09/update[1B][0m
[00:04:42.116,607] [1B][0m<inf> aws_jobs: Publish payload {"status":"IN_PROGRESS","statusDetails": {"nextState":"download_firmware"},"expectedVersion": "1","clientToken": ""}[1B][0m
[mqtt_evt_handler:262] PUBACK packet id: 3821
[00:04:43.891,937] [1B][0m<inf> aws_fota: Received topic: $aws/things/nrf-352656100047698/jobs/nrf9160fwota_020620_09/update/accepted[1B][0m
[00:04:43.892,028] [1B][0m<dbg> aws_fota.aws_fota_on_publish_evt: Job document update was accepted[1B][0m
[00:04:43.892,120] [1B][0m<inf> aws_fota: Start downloading firmware from mynrf9160fwupdatev2.s3.us-east-2.amazonaws.comapp_update.bin[1B][0m
[00:04:44.623,260] [1B][0m<inf> download_client: Attempting to connect over IPv4[1B][0m
[00:04:44.924,926] [1B][0m<inf> download_client: Connected to mynrf9160fwupdatev2.s3.us-east-2.amazonaws.com[1B][0m
[00:04:44.924,957] [1B][0m<inf> download_client: Downloading: app_update.bin [0][1B][0m
[00:04:47.827,484] [1B][0m<inf> download_client: Downloaded 4096/232128 bytes (1%)[1B][0m
[00:04:47.827,514] [1B][0m<inf> fota_download: Offset: 0x0[1B][0m
[00:04:47.827,575] [1B][0m<inf> fota_flash_block: Erasing sector at offset 0x00000000[1B][0m
[00:04:47.962,371] [1B][0m<inf> fota_flash_block: Erasing sector at offset 0x00001000[1B][0m
[00:04:51.225,555] [1B][0m<inf> download_client: Downloaded 8192/232128 bytes (3%)[1B][0m
[00:04:51.273,437] [1B][0m<inf> fota_flash_block: Erasing sector at offset 0x00002000[1B][0m
[00:04:53.075,103] [1B][0m<inf> download_client: Downloaded 12288/232128 bytes (5%)[1B][0m
[00:04:53.122,924] [1B][0m<inf> fota_flash_block: Erasing sector at offset 0x00003000[1B][0m
[00:04:55.257,843] [1B][0m<inf> download_client: Downloaded 16384/232128 bytes (7%)[1B][0m
[00:04:55.305,633] [1B][0m<inf> fota_flash_block: Erasing sector at offset 0x00004000[1B][0m
[00:04:56.800,872] [1B][0m<inf> download_client: Downloaded 20480/232128 bytes (8%)[1B][0m
[00:04:56.848,724] [1B][0m<inf> fota_flash_block: Erasing sector at offset 0x00005000[1B][0m
[00:04:58.425,811] [1B][0m<inf> download_client: Downloaded 24576/232128 bytes (10%)[1B][0m
[00:04:58.473,632] [1B][0m<inf> fota_flash_block: Erasing sector at offset 0x00006000[1B][0m
[00:04:59.658,935] [1B][0m<inf> download_client: Downloaded 28672/232128 bytes (12%)[1B][0m
[00:04:59.706,787] [1B][0m<inf> fota_flash_block: Erasing sector at offset 0x00007000[1B][0m
[00:05:01.148,712] [1B][0m<inf> download_client: Downloaded 32768/232128 bytes (14%)[1B][0m
[00:05:01.196,594] [1B][0m<inf> fota_flash_block: Erasing sector at offset 0x00008000[1B][0m
[00:05:02.399,810] [1B][0m<inf> download_client: Downloaded 36864/232128 bytes (15%)[1B][0m
[00:05:02.447,692] [1B][0m<inf> fota_flash_block: Erasing sector at offset 0x00009000[1B][0m
[00:05:03.722,778] [1B][0m<inf> download_client: Downloaded 40960/232128 bytes (17%)[1B][0m
[00:05:03.770,599] [1B][0m<inf> fota_flash_block: Erasing sector at offset 0x0000a000[1B][0m
[00:05:05.297,790] [1B][0m<inf> download_client: Downloaded 45056/232128 bytes (19%)[1B][0m
[00:05:05.345,672] [1B][0m<inf> fota_flash_block: Erasing sector at offset 0x0000b000[1B][0m
[00:05:06.710,906] [1B][0m<inf> download_client: Downloaded 49152/232128 bytes (21%)[1B][0m
[00:05:06.758,728] [1B][0m<inf> fota_flash_block: Erasing sector at offset 0x0000c000[1B][0m
[00:05:09.014,953] [1B][0m<inf> download_client: Downloaded 53248/232128 bytes (22%)[1B][0m
[00:05:09.062,774] [1B][0m<inf> fota_flash_block: Erasing sector at offset 0x0000d000[1B][0m
[00:05:11.427,978] [1B][0m<inf> download_client: Downloaded 57344/232128 bytes (24%)[1B][0m
[00:05:11.475,799] [1B][0m<inf> fota_flash_block: Erasing sector at offset 0x0000e000[1B][0m
[00:05:13.080,993] [1B][0m<inf> download_client: Downloaded 61440/232128 bytes (26%)[1B][0m
[00:05:13.128,845] [1B][0m<inf> fota_flash_block: Erasing sector at offset 0x0000f000[1B][0m
[00:05:14.687,164] [1B][0m<inf> download_client: Downloaded 65536/232128 bytes (28%)[1B][0m
[00:05:14.735,015] [1B][0m<inf> fota_flash_block: Erasing sector at offset 0x00010000[1B][0m
[00:05:16.387,969] [1B][0m<inf> download_client: Downloaded 69632/232128 bytes (29%)[1B][0m
[00:05:16.435,821] [1B][0m<inf> fota_flash_block: Erasing sector at offset 0x00011000[1B][0m
[00:05:17.789,154] [1B][0m<inf> download_client: Downloaded 73728/232128 bytes (31%)[1B][0m
[00:05:17.836,975] [1B][0m<inf> fota_flash_block: Erasing sector at offset 0x00012000[1B][0m
[00:05:18.996,063] [1B][0m<inf> download_client: Downloaded 77824/232128 bytes (33%)[1B][0m
[00:05:19.043,884] [1B][0m<inf> fota_flash_block: Erasing sector at offset 0x00013000[1B][0m
[00:05:20.787,963] [1B][0m<inf> download_client: Downloaded 81920/232128 bytes (35%)[1B][0m
[00:05:20.835,815] [1B][0m<inf> fota_flash_block: Erasing sector at offset 0x00014000[1B][0m
[00:05:22.153,350] [1B][0m<inf> download_client: Downloaded 86016/232128 bytes (37%)[1B][0m
[00:05:22.201,171] [1B][0m<inf> fota_flash_block: Erasing sector at offset 0x00015000[1B][0m
[00:05:23.695,251] [1B][0m<inf> download_client: Downloaded 90112/232128 bytes (38%)[1B][0m
[00:05:23.743,103] [1B][0m<inf> fota_flash_block: Erasing sector at offset 0x00016000[1B][0m
[00:05:24.628,051] [1B][1;33m<wrn> download_client: Copying 4 payload bytes[1B][0m
[00:05:25.775,238] [1B][0m<inf> download_client: Downloaded 94208/232128 bytes (40%)[1B][0m
[00:05:25.823,059] [1B][0m<inf> fota_flash_block: Erasing sector at offset 0x00017000[1B][0m
[00:05:27.179,199] [1B][0m<inf> download_client: Downloaded 98304/232128 bytes (42%)[1B][0m
[00:05:27.227,020] [1B][0m<inf> fota_flash_block: Erasing sector at offset 0x00018000[1B][0m
[00:05:28.657,196] [1B][0m<inf> download_client: Downloaded 102400/232128 bytes (44%)[1B][0m
[00:05:28.705,078] [1B][0m<inf> fota_flash_block: Erasing sector at offset 0x00019000[1B][0m
[00:05:30.015,197] [1B][0m<inf> download_client: Downloaded 106496/232128 bytes (45%)[1B][0m
[00:05:30.063,049] [1B][0m<inf> fota_flash_block: Erasing sector at offset 0x0001a000[1B][0m
[00:05:31.346,343] [1B][0m<inf> download_client: Downloaded 110592/232128 bytes (47%)[1B][0m
[00:05:31.394,195] [1B][0m<inf> fota_flash_block: Erasing sector at offset 0x0001b000[1B][0m
[00:05:32.758,392] [1B][0m<inf> download_client: Downloaded 114688/232128 bytes (49%)[1B][0m
[00:05:32.806,243] [1B][0m<inf> fota_flash_block: Erasing sector at offset 0x0001c000[1B][0m
[00:05:34.536,590] [1B][0m<inf> download_client: Downloaded 118784/232128 bytes (51%)[1B][0m
[00:05:34.584,442] [1B][0m<inf> fota_flash_block: Erasing sector at offset 0x0001d000[1B][0m
[00:05:36.037,353] [1B][0m<inf> download_client: Downloaded 122880/232128 bytes (52%)[1B][0m
[00:05:36.085,235] [1B][0m<inf> fota_flash_block: Erasing sector at offset 0x0001e000[1B][0m
[00:05:37.375,640] [1B][0m<inf> download_client: Downloaded 126976/232128 bytes (54%)[1B][0m
[00:05:37.423,492] [1B][0m<inf> fota_flash_block: Erasing sector at offset 0x0001f000[1B][0m
[00:05:39.482,543] [1B][0m<inf> download_client: Downloaded 131072/232128 bytes (56%)[1B][0m
[00:05:39.530,395] [1B][0m<inf> fota_flash_block: Erasing sector at offset 0x00020000[1B][0m
[00:05:40.835,327] [1B][0m<inf> download_client: Downloaded 135168/232128 bytes (58%)[1B][0m
[00:05:40.883,209] [1B][0m<inf> fota_flash_block: Erasing sector at offset 0x00021000[1B][0m
[00:05:42.050,598] [1B][0m<inf> download_client: Downloaded 139264/232128 bytes (59%)[1B][0m
[00:05:42.098,480] [1B][0m<inf> fota_flash_block: Erasing sector at offset 0x00022000[1B][0m
[00:05:43.498,779] [1B][0m<inf> download_client: Downloaded 143360/232128 bytes (61%)[1B][0m
[00:05:43.546,691] [1B][0m<inf> fota_flash_block: Erasing sector at offset 0x00023000[1B][0m
[00:05:45.039,611] [1B][0m<inf> download_client: Downloaded 147456/232128 bytes (63%)[1B][0m
[00:05:45.087,463] [1B][0m<inf> fota_flash_block: Erasing sector at offset 0x00024000[1B][0m
[00:05:46.218,627] [1B][0m<inf> download_client: Downloaded 151552/232128 bytes (65%)[1B][0m
[00:05:46.266,510] [1B][0m<inf> fota_flash_block: Erasing sector at offset 0x00025000[1B][0m
[00:05:47.311,584] [1B][0m<inf> download_client: Downloaded 155648/232128 bytes (67%)[1B][0m
[00:05:47.359,466] [1B][0m<inf> fota_flash_block: Erasing sector at offset 0x00026000[1B][0m
AWS_FOTA_EVT_ERROR
[00:06:11.441,375] [1B][1;33m<wrn> download_client: Peer closed connection![1B][0m
[00:06:11.441,864] [1B][1;31m<err> fota_download: Download client error[1B][0m
[00:06:11.441,864] [1B][0m<inf> dfu_target_mcuboot: MCUBoot image upgrade aborted.[1B][0m
[00:06:11.441,864] [1B][1;31m<err> aws_fota: FOTA download failed, report back[1B][0m
[00:06:11.442,077] [1B][0m<inf> aws_jobs: Publish topic: $aws/things/nrf-352656100047698/jobs/nrf9160fwota_020620_09/update[1B][0m
[00:06:11.442,108] [1B][0m<inf> aws_jobs: Publish payload {"status":"FAILED","statusDetails": {"nextState":"download_firmware"},"expectedVersion": "2","clientToken": ""}[1B][0m
[mqtt_evt_handler:262] PUBACK packet id: 47255
[00:06:18.633,087] [1B][0m<inf> aws_fota: Received topic: $aws/things/nrf-352656100047698/jobs/nrf9160fwota_020620_09/update/accepted[1B][0m
[00:06:18.633,178] [1B][0m<dbg> aws_fota.aws_fota_on_publish_evt: Job document update was accepted[1B][0m
[00:06:18.633,270] [1B][0m<inf> aws_fota: Start downloading firmware from mynrf9160fwupdatev2.s3.us-east-2.amazonaws.comapp_update.bin[1B][0m
aws_fota_mqtt_evt_handler: Failed! -22
[mqtt_evt_handler:227] MQTT PUBLISH result=0 len=41
mqtt_read_publish_payload: Failed! -5
Disconnecting MQTT client...
Received: 
[00:06:42.636,932] [1B][1;33m<wrn> download_client: Failed to resolve hostname mynrf9160fwupdatev2.s3.us-east-2.amazonaws.com on IPv4[1B][0m
[00:06:42.636,962] [1B][1;31m<err> aws_fota: Error when trying to start firmwaredownload: -22[1B][0m
[mqtt_evt_handler:220] MQTT client disconnected 0
POLLNVAL
Disconnecting MQTT client...
Could not disconnect MQTT client. Error: -57

Fullscreen log02062020_02.txt Download

nrf_inbuilt_key_delete(12345678, 2) => result=0
nrf_inbuilt_key_write => result=0
nrf_inbuilt_key_write => result=0
nrf_inbuilt_key_write => result=0
LTE Link Connecting ...
LTE Link Connected!
IPv4 Address 3.20.75.29
client_id: nrf-352656100047698
[mqtt_evt_handler:209] MQTT client connected!
[00:00:17.611,968] [1B][0m<inf> aws_jobs: Subscribe: $aws/things/nrf-352[mqtt_evt_handler:272] SUBACK packet id: 2114
656100047698/jobs/notify-next[1B][0m
[00:00:17.613,952] [1B][0m<inf> aws_jobs: Subscribe: $aws/things/nrf-352656100047698/jobs/$next/get/#[1B][0m
[00:00:18.241,455] [1B][0m<inf> aws_fota: subscribed to notify-next topic[1B][0m
[00:00:18.241,516] [1B][0m<inf> aws_jobs: Publish topic: $aws/things/nrf-352656100047698/jobs/$next/get[1B][0m
[00:00:18.241,546] [1B][0m<inf> aws_jobs: Publish payload {"clientToken": ""}[1B][0m
[mqtt_evt_handler:262] PUBACK packet id: 53050
[mqtt_evt_handler:262] PUBACK packet id: 7915
[00:00:19.143,218] [1B][0m<inf> aws_fota: Received topic: $aws/things/nrf-352656100047698/jobs/$next/get/accepted[1B][0m
[00:00:19.143,432] [1B][0m<inf> aws_fota: Got only one field: {"clientToken":"","timestamp":1581041635}[1B][0m
[00:01:14.914,306] [1B][0m<inf> aws_fota: Received topic: $aws/things/nrf-352656100047698/jobs/notify-next[1B][0m
[00:01:14.914,916] [1B][0m<inf> aws_jobs: Unsubscribe: $aws/things/nrf-352656100047698/jobs/notify-next[1B][0m
[00:01:14.916,168] [1B][0m<inf> aws_jobs: Subscribe: $aws/things/nrf-352656100047698/jobs/nrf9160fwota_020620_10/update/#[1B][0m
[mqtt_evt_handler:277] default: 8
[mqtt_evt_handler:262] PUBACK packet id: 36513
[00:01:23.114,227] [1B][0m<inf> aws_jobs: Publish topic: $aws/things/nrf-352656100047698/jobs/nrf9160fwota_020620_10/update[1B][0m
[00:01:23.114,288] [1B][0m<inf> aws_jobs: Publish payload {"status":"IN_PROGRESS","statusDetails": {"nextState":"download_firmware"},"expectedVersion": "1","clientToken": ""}[1B][0m
[00:01:24.052,520] [1B][0m<inf> aws_fota: Received topic: $aws/things/nrf-352656100047698/jobs/nrf9160fwota_020620_10/update/accepted[1B][0m
[00:01:24.052,581] [1B][0m<dbg> aws_fota.aws_fota_on_publish_evt: Job document update was accepted[1B][0m
[00:01:24.052,703] [1B][0m<inf> aws_fota: Start downloading firmware from mynrf9160fwupdatev2.s3.us-east-2.amazonaws.comapp_update.bin[1B][0m
[00:01:24.415,771] [1B][0m<inf> download_client: Attempting to connect over IPv4[1B][0m
[00:01:24.735,900] [1B][0m<inf> download_client: Connected to mynrf9160fwupdatev2.s3.us-east-2.amazonaws.com[1B][0m
[00:01:24.735,931] [1B][0m<inf> download_client: Downloading: app_update.bin [0][1B][0m
[00:01:27.352,691] [1B][0m<inf> download_client: Downloaded 4096/232128 bytes (1%)[1B][0m
[00:01:27.352,752] [1B][0m<inf> fota_download: Offset: 0x0[1B][0m
[00:01:27.352,783] [1B][0m<inf> fota_flash_block: Erasing sector at offset 0x00000000[1B][0m
[00:01:27.487,548] [1B][0m<inf> fota_flash_block: Erasing sector at offset 0x00001000[1B][0m
[00:01:29.064,788] [1B][0m<inf> download_client: Downloaded 8192/232128 bytes (3%)[1B][0m
[00:01:29.112,640] [1B][0m<inf> fota_flash_block: Erasing sector at offset 0x00002000[1B][0m
[00:01:30.438,171] [1B][0m<inf> download_client: Downloaded 12288/232128 bytes (5%)[1B][0m
[00:01:30.485,992] [1B][0m<inf> fota_flash_block: Erasing sector at offset 0x00003000[1B][0m
[00:01:31.860,076] [1B][0m<inf> download_client: Downloaded 16384/232128 bytes (7%)[1B][0m
[00:01:31.907,867] [1B][0m<inf> fota_flash_block: Erasing sector at offset 0x00004000[1B][0m
[00:01:33.092,071] [1B][0m<inf> download_client: Downloaded 20480/232128 bytes (8%)[1B][0m
[00:01:33.139,892] [1B][0m<inf> fota_flash_block: Erasing sector at offset 0x00005000[1B][0m
[00:01:34.494,720] [1B][0m<inf> download_client: Downloaded 24576/232128 bytes (10%)[1B][0m
[00:01:34.542,541] [1B][0m<inf> fota_flash_block: Erasing sector at offset 0x00006000[1B][0m
[00:01:36.416,290] [1B][0m<inf> download_client: Downloaded 28672/232128 bytes (12%)[1B][0m
[00:01:36.464,111] [1B][0m<inf> fota_flash_block: Erasing sector at offset 0x00007000[1B][0m
[00:01:38.053,405] [1B][0m<inf> download_client: Downloaded 32768/232128 bytes (14%)[1B][0m
[00:01:38.101,226] [1B][0m<inf> fota_flash_block: Erasing sector at offset 0x00008000[1B][0m
AWS_FOTA_EVT_ERROR
[mqtt_evt_handler:262] PUBACK packet id: 50810
[00:02:09.407,928] [1B][0m<inf> download_client: Downloaded 36864/232128 bytes (15%)[1B][0m
[00:02:09.455,810] [1B][0m<inf> fota_flash_block: Erasing sector at offset 0x00009000[1B][0m
[00:02:09.549,804] [1B][1;31m<err> download_client: Failed to send HTTP request, errno 57[1B][0m
[00:02:09.550,323] [1B][1;31m<err> fota_download: Download client error[1B][0m
[00:02:09.550,323] [1B][0m<inf> dfu_target_mcuboot: MCUBoot image upgrade aborted.[1B][0m
[00:02:09.550,354] [1B][1;31m<err> aws_fota: FOTA download failed, report back[1B][0m
[00:02:09.550,537] [1B][0m<inf> aws_jobs: Publish topic: $aws/things/nrf-352656100047698/jobs/nrf9160fwota_020620_10/update[1B][0m
[00:02:09.550,567] [1B][0m<inf> aws_jobs: Publish payload {"status":"FAILED","statusDetails": {"nextState":"download_firmware"},"expectedVersion": "2","clientToken": ""}[1B][0m
[00:02:10.327,423] [1B][0m<inf> aws_fota: Received topic: $aws/things/nrf-352656100047698/jobs/nrf9160fwota_020620_10/update/accepted[1B][0m
[00:02:10.327,484] [1B][0m<dbg> aws_fota.aws_fota_on_publish_evt: Job document update was accepted[1B][0m
[00:02:10.327,606] [1B][0m<inf> aws_fota: Start downloading firmware from mynrf9160fwupdatev2.s3.us-east-2.amazonaws.comapp_update.bin[1B][0m
[00:02:10.627,746] [1B][0m<inf> download_client: Attempting to connect over IPv4[1B][0m
[00:02:10.963,500] [1B][0m<inf> download_client: Connected to mynrf9160fwupdatev2.s3.us-east-2.amazonaws.com[1B][0m
[00:02:10.963,531] [1B][0m<inf> download_client: Downloading: app_update.bin [0][1B][0m
[00:02:12.616,943] [1B][0m<inf> download_client: Downloaded 4096/232128 bytes (1%)[1B][0m
[00:02:12.617,004] [1B][0m<inf> fota_download: Offset: 0x9000[1B][0m
[00:02:12.617,004] [1B][0m<inf> fota_download: Refuse fragment, restart with offset[1B][0m
[00:02:12.617,034] [1B][0m<inf> download_client: Fragment refused, download stopped.[1B][0m
[00:02:13.617,126] [1B][0m<inf> download_client: Downloading: app_update.bin [36864][1B][0m
[00:02:13.617,950] [1B][0m<inf> fota_download: Downloading from offset: 0x9000[1B][0m
[00:02:14.849,060] [1B][0m<inf> download_client: Downloaded 40960/232128 bytes (17%)[1B][0m
[00:02:14.896,942] [1B][0m<inf> fota_flash_block: Erasing sector at offset 0x0000a000[1B][0m
[00:02:16.294,006] [1B][0m<inf> download_client: Downloaded 45056/232128 bytes (19%)[1B][0m
[00:02:16.341,827] [1B][0m<inf> fota_flash_block: Erasing sector at offset 0x0000b000[1B][0m
[00:02:18.171,936] [1B][0m<inf> download_client: Downloaded 49152/232128 bytes (21%)[1B][0m
[00:02:18.219,757] [1B][0m<inf> fota_flash_block: Erasing sector at offset 0x0000c000[1B][0m
[00:02:19.450,012] [1B][0m<inf> download_client: Downloaded 53248/232128 bytes (22%)[1B][0m
[00:02:19.497,802] [1B][0m<inf> fota_flash_block: Erasing sector at offset 0x0000d000[1B][0m
[00:02:25.538,299] [1B][0m<inf> download_client: Downloaded 57344/232128 bytes (24%)[1B][0m
[00:02:25.586,120] [1B][0m<inf> fota_flash_block: Erasing sector at offset 0x0000e000[1B][0m
[00:02:30.490,814] [1B][0m<inf> download_client: Downloaded 61440/232128 bytes (26%)[1B][0m
[00:02:30.538,635] [1B][0m<inf> fota_flash_block: Erasing sector at offset 0x0000f000[1B][0m
[00:02:32.848,663] [1B][0m<inf> download_client: Downloaded 65536/232128 bytes (28%)[1B][0m
[00:02:32.896,514] [1B][0m<inf> fota_flash_block: Erasing sector at offset 0x00010000[1B][0m
[00:02:37.170,013] [1B][0m<inf> download_client: Downloaded 69632/232128 bytes (29%)[1B][0m
[00:02:37.217,834] [1B][0m<inf> fota_flash_block: Erasing sector at offset 0x00011000[1B][0m
AWS_FOTA_EVT_ERROR
[mqtt_evt_handler:262] PUBACK packet id: 44828
[00:03:31.225,616] [1B][0m<inf> download_client: Downloaded 73728/232128 bytes (31%)[1B][0m
[00:03:31.273,437] [1B][0m<inf> fota_flash_block: Erasing sector at offset 0x00012000[1B][0m
[00:03:31.367,340] [1B][1;31m<err> download_client: Failed to send HTTP request, errno 57[1B][0m
[00:03:31.367,797] [1B][1;31m<err> fota_download: Download client error[1B][0m
[00:03:31.367,797] [1B][0m<inf> dfu_target_mcuboot: MCUBoot image upgrade aborted.[1B][0m
[00:03:31.367,797] [1B][1;31m<err> aws_fota: FOTA download failed, report back[1B][0m
[00:03:31.368,011] [1B][0m<inf> aws_jobs: Publish topic: $aws/things/nrf-352656100047698/jobs/nrf9160fwota_020620_10/update[1B][0m
[00:03:31.368,041] [1B][0m<inf> aws_jobs: Publish payload {"status":"FAILED","statusDetails": {"nextState":"download_firmware"},"expectedVersion": "3","clientToken": ""}[1B][0m
AWS_FOTA_EVT_ERROR
aws_fota_mqtt_evt_handler: Failed! -14
[mqtt_evt_handler:227] MQTT PUBLISH result=0 len=281
mqtt_read_publish_payload: Failed! -36
Disconnecting MQTT client...
Received: 
[mqtt_evt_handler:220] MQTT client disconnected 0
POLLNVAL
Disconnecting MQTT client...
Could not disconnect MQTT client. Error: -57
[00:03:32.653,045] [1B][0m<inf> aws_fota: Received topic: $aws/things/nrf-352656100047698/jobs/nrf9160fwota_020620_10/update/rejected[1B][0m
[00:03:32.653,167] [1B][1;31m<err> aws_fota: Job document update was rejected[1B][0m

[Heidi]

Hi!

Could you take a modem trace when this happens - it will be easier to see what's going on? 

See this post for how to get a modem trace.

Best regards,

Heidi

[hmichel]

Hi Heidi,

Which of the 3 com ports should I use? Do I need to disconnect the Termite terminal program?

[hmichel]

Sorry I see that I need to update Modem FW to version 1.1.1. I will do that now

[hmichel]

Firmware updated

[hmichel]

I am still unable to connect to AWS with the board that had the successful download. I am using the debugger to load the software unto the board but it gets a timeout error (- 60).

I have a second board that I have not used until this point. I activated the SIM and the LTE device on nrfCloud for the 2nd board. After that when I run the FOTA code (except I am NOT trying to perform an FOTA just run the application) on the 2nd board it connects to AWS.

Something happened to the first board when I had a successful download using the FOTA sample. And now I am very concerned that if I get the download to work on the second board it will be corrupted and not able to connect again to AWS. Both boards have Modem version v1.1.1. 

I will be working at 0900 Norway time / 0200 Nashville time in the hope you have an answer.

[Heidi]

Hi, could you get me a modem trace when the OTA fails.

As I understood it, the trace you attached came from the time it completed.

Best regards,

Heidi

[hmichel]

Yes I can. Did the trace that I sent contain any useful information? The reason I ask is that I am not sure I set up the trace correctly based on step 2 of the instructons

2. Ensure proper board control (nRF52) to set up that second UART is connected to modem.

            This board controller f/w can be downloaded here.

            Please make sure SW5 to nRF52 before programming and switch back to nRF91 after flashing.

            To program it, you can simply do it with below command in your console window.**

            nrfjprog --program nRF9160_DK_board_controller_FW.hex --sectorerase -f nrf52 -r --verify

In particular I was not sure which of my hex files corresponded to nRF9160_DK_board_controller_FW.hex

So I ran the trace without running that command. And that is why I wondering if the trace had any useful information. I ran it from debug instead.

[hmichel]

Here is the trace that corresponds to the timeout error

trace-2020-02-10T09-47-07.317Z.bin

[hmichel]

Here is a second attempt

trace-2020-02-10T09-50-08.697Z.bin

[Heidi]

Hi! Your traces are unfortunately empty.

Step two shouldn't be the problem, as long as you haven't flashed any new applications to the nRF52840 on your nRF91 DK?

Are you sure about the MFW version on the device? Could you run %SHORTSWVER to be sure?

When you did step four, did you receive "OK" from the modem?

And did you see the size of the trace increasing as the application was running?

(And please note: a log file from your application when you are capturing the modem trace is also essential)

Best regards,

Heidi

[hmichel]

FW version is correct

Step 4 did respond with OK although the first attempt had a timeout

Build was set up correctly

Capture started

File size does not change during capture

Fails to connect (although this time it is not a timeout)

Tried a second run and still fails to connect (back to timeout error -60) and also no change in file size. 

[Heidi]

Could you try with this application? Send random AT commands to the modem via LTE Link Monitor while capturing the modem trace and see if the file size of the trace increases. 

 nrf91dk_at_client_modemtrace.hex

And which version of the DK do you have? The version number is printed on the white sticker on the back under the line "PCA10090". 

Best regards,

Heidi