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.

[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