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

[Øyvind]

I think we need to have a look at the modem connection. Can you please provide a modem trace?

Thanks!
-Øyvind

[icampbell]

trace-2020-03-26T14-58-36.611Z.bin

Here you go. I rebooted the device just after I started the trace, and ended the trace just after it printed "mqtt_connect -22".

[Øyvind]

Thank you! I will look into the modem trace and the log output to see if there is anything causing this issue. 

Will get back to you asap.

Kind regards,

Øyvind

[Øyvind]

Hello again, 

I'm sorry, so far I've got nothing from the modem trace or log. Can you please try updating the modem FW to mfw 1.1.1? If this does not fix the issue, can you please provide your project?

Thanks!

Kind regards,
Øyvind

[icampbell]

Hello,

I updated the modem firmware to 1.1.1, but I still have the same problem.

I sent you a PM with a link to my project. To use it you would have to uncomment CONFIG_PROVISION_CERTIFICATES=y.

[Øyvind]

Hello, 

I was not able to build your project, but am working on a solution. However, I found that your CLOUD_CLIENT_PRIVATE_KEY in certificates.h had an extra space after \n". This can cause issues with certificates. 
Please remove and let me know how it goes!

Kind regards,
Øyvind

[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?