How to use aws_fota program in nRF9160?

[Yusuke]

I'm trying to use aws_fota, but it doesn't work. Any help?

I was able to set a job on AWS IoT, but the download job doesn't start. The job status is always "in progress". I logged out and logged in and got the same result.

***** Booting Zephyr OS v1.14.99-ncs2 *****
The MQTT AWS Jobs FOTA Sample
LTE Link Connecting ...
LTE Link Connected!
IPv4 Address 0x4980a023
client_id: nrf-352656100218455
[mqtt_evt_handler:131] MQTT client connected!
[mqtt_evt_handler:196] SUBACK packet id: 2112
[mqtt_evt_handler:186] PUBACK packet id: 62996

I use the same region in AWS IoT and S3

I've already checked this thread.
https://devzone.nordicsemi.com/f/nordic-q-a/52039/aws-fota-sample/210098#210098

[Øyvind]

Hello, 

Good to see that the connection is working. 

Can you please provide your AWS Job file as well? And where is the .bin file located?

Thanks!

Kind regards,
Øyvind

[Yusuke]

Thank you for your help!

I'm using Oregon region.

This is a job file

{
  "operation": "app_fw_update",
  "fwversion": "v1.0.2",
  "size": 64300,
  "location": {
    "protocol": "https:",
    "host": "******.s3-us-west-2.amazonaws.com",
    "path": "/20190929_test_update.bin"
   }
}

.bin file is located in S3 in Oregon region.

[sigvartmh]

Yes,/no is my answer. If you are on the tagged version, A Job must be created after the MQTT connection. If you are on the master branch, this should no longer be the case as the device should fetch any queued jobs for the device and will take the first job queued for the device.

It could be that AWS has changed their policy configurations from when the documentation was written and the current thing policy is not seen as valid.  Could you try to attach the following policy to the certificates your device uses? See if it is then able to accept jobs.

[Yusuke]

My ncs version is v1.0.1, is this tagged version?

[sigvartmh]

As far as I know, the only tagged version is v1.0.0 for NCS could you do "git show --no-patch" in the nrf repository/folder and post the commit SHA. It's easier to check where you are at in the git history.

[Yusuke]

Yea, you're right. My version is v1.0.0. Modem fw is v1.0.1.

>In addition, now I can't update bucket>permissions>bucket policy.

I solved this issue. You must configure bucket access controls both in account level and bucket level.

However, downloading does not start yet.... The same result so far, even if I created a job after MQTT connection.

[sigvartmh]

Did you attach the policy I suggested to the certificates of the thing in AWS IoT Core? Does your job ever go from Queued to In progress if you click on it and see the status fields?

It should progress from Queued, In progress then to either Failed or Successful.

For v1.0.0 your device has to be connected and subscribed 
[mqtt_evt_handler:196] SUBACK packet id: 2112
before you create the job. Also, ensure that all your old jobs are canceled and deleted as a device can only have 1 active job at the time. So if there is a job already for the device it will block any new jobs created.

[Yusuke]

>Did you attach the policy I suggested to the certificates of the thing in AWS IoT Core?

I did it and the device doesn't subscribe and stops processing on the way.

***** Booting Zephyr OS v1.14.99-ncs2 *****
The MQTT AWS Jobs FOTA Sample
LTE Link Connecting ...
LTE Link Connected!
IPv4 Address 0x27e71934
client_id: nrf-352656100218455

[sigvartmh]

This is usually caused by client_id: nrf-352656100218455 not being the same as the clientId attached to your certificates. Have you set nrf-352656100218455 as the thing name in AWS?

What do you mean with stops processing on the way? What happens?

[Yusuke]

I use the same name as thing name.

<Kconfig>

config USE_CLOUD_CLIENT_ID
	bool "Custom MQTT Client Id"

config DOWNLOAD_CLIENT_LOG_LEVEL_DBG
	bool "degbug level"

config DOWNLOAD_CLIENT_LOG_HEADER
	bool "log header"

if USE_CLOUD_CLIENT_ID

config CLOUD_CLIENT_ID
	string "Client ID"
	default "device01"
endif

>What do you mean with stops processing on the way? What happens?

I expected "MQTT client connected!" message will show up after "client_id: nrf-352656100218455" message, but "MQTT client connected!" does not show up and process stops.

[sigvartmh]

You have to select CONFIG_USE_CLOUD_CLIENT_ID=y in prj.conf if not it will default to a combination of nrf- and your modem IMEI as you can see by the client_id: nrf-352656100218455 output in the log. Also, you should probably set CONFIG_CLOUD_CLIENT_ID="device01" in prj.conf instead of editing the default in Kconfig.

So your device is using the nrf-352656100218455 as client ID which explains why it won't connect. The reason it worked before is the permissive policy allows anyone with a valid certificate to connect and subscribe.

[Yusuke]

>You have to select CONFIG_USE_CLOUD_CLIENT_ID=y in prj.conf

This solved the issue. Thank you.
Nordic may explain this on github or originally enable it.
https://github.com/NordicPlayground/fw-nrfconnect-nrf/tree/master/samples/nrf9160/aws_fota

>you should probably set CONFIG_CLOUD_CLIENT_ID="device01" in prj.conf 

I agree with you. Client ID is configured in Kconfig in the original aws_fota. I didn't want to change the original code.

However, I got  a next error. Could you give me any advice?

***** Booting Zephyr OS v1.14.99-ncs2 *****
The MQTT AWS Jobs FOTA Sample
LTE Link Connecting ...
LTE Link Connected!
IPv4 Address 0xb790bf36
CONFIG_CLOUD_CLIENT_ID: device01
client_id: device01
[mqtt_evt_handler:131] MQTT client connected!
[mqtt_evt_handler:196] SUBACK packet id: 2112
[mqtt_evt_handler:186] PUBACK packet id: 51235
[mqtt_evt_handler:201] default: 8
[mqtt_evt_handler:186] PUBACK packet id: 55531
[00:00:41.850,646] <inf> aws_fota: Start downloading firmware from *******.s3-us-west-2.amazonaws.com20190929_test_update.bin
[00:00:42.500,915] <inf> download_client: Attempting to connect over IPv4
[00:00:43.096,771] <inf> download_client: Connected
[00:00:43.096,771] <inf> download_client: Downloading: 20190929_test_update.bin [0]
[00:00:43.782,196] <inf> download_client: Downloaded bytes: 0/65804
[00:00:44.183,471] <inf> download_client: Downloaded bytes: 1024/65804
[00:00:45.003,082] <inf> download_client: Downloaded bytes: 1584/65804
[00:00:45.003,753] <inf> download_client: Downloaded bytes: 3632/65804
[00:00:45.004,913] <inf> download_client: Downloaded bytes: 4096/65804
[00:00:45.004,943] <inf> fota_flash_block: Erasing sector at offset 0x0
[00:00:45.691,192] <inf> download_client: Downloaded bytes: 4096/65804
[00:00:45.749,053] <inf> download_client: Downloaded bytes: 4804/65804
[00:00:45.883,728] <inf> download_client: Downloaded bytes: 5828/65804
[00:00:45.921,936] <inf> download_client: Downloaded bytes: 6540/65804
[00:00:45.922,302] <inf> download_client: Downloaded bytes: 7564/65804
[00:00:45.923,370] <inf> download_client: Downloaded bytes: 7636/65804
[00:00:46.321,868] <inf> download_client: Downloaded bytes: 8192/65804
[00:00:46.321,868] <inf> fota_flash_block: Erasing sector at offset 0x1000
[00:00:47.121,093] <wrn> download_client: Copying 600 payload bytes
[00:00:47.121,124] <inf> download_client: Downloaded bytes: 8792/65804
[00:00:47.629,760] <inf> download_client: Downloaded bytes: 9504/65804
[00:00:47.630,065] <inf> download_client: Downloaded bytes: 10528/65804
[00:00:47.630,340] <inf> download_client: Downloaded bytes: 11552/65804
[00:00:47.631,561] <inf> download_client: Downloaded bytes: 11732/65804
[00:00:47.695,861] <inf> download_client: Downloaded bytes: 12288/65804
[00:00:47.695,861] <inf> fota_flash_block: Erasing sector at offset 0x2000
[00:00:48.639,923] <inf> download_client: Downloaded bytes: 12288/65804
[00:00:48.674,987] <inf> download_client: Downloaded bytes: 13312/65804
[00:00:48.704,010] <inf> download_client: Downloaded bytes: 14336/65804
[00:00:49.894,805] <inf> download_client: Downloaded bytes: 15048/65804
[00:00:49.896,148] <inf> download_client: Downloaded bytes: 15828/65804
[00:00:49.936,492] <inf> download_client: Downloaded bytes: 16384/65804
[00:00:49.936,492] <inf> fota_flash_block: Erasing sector at offset 0x3000
[00:00:50.907,958] <inf> download_client: Downloaded bytes: 16384/65804
[00:00:50.961,059] <inf> download_client: Downloaded bytes: 17408/65804
[00:00:51.013,153] <inf> download_client: Downloaded bytes: 18432/65804
[00:00:51.770,874] <inf> download_client: Downloaded bytes: 19144/65804
[00:00:51.772,216] <inf> download_client: Downloaded bytes: 19924/65804
[00:00:51.830,993] <inf> download_client: Downloaded bytes: 20480/65804
[00:00:51.830,993] <inf> fota_flash_block: Erasing sector at offset 0x4000
[00:00:52.891,052] <inf> download_client: Downloaded bytes: 20480/65804
[00:00:52.927,124] <inf> download_client: Downloaded bytes: 21504/65804
[00:00:53.750,976] <inf> download_client: Downloaded bytes: 22528/65804
AWS_FOTA_EVT_ERROR
[00:01:16.228,393] <inf> download_client: Downloaded bytes: 23552/65804
[00:01:16.228,454] <inf> download_client: Downloaded bytes: 24576/65804
[00:01:16.228,485] <inf> fota_flash_block: Erasing sector at offset 0x5000
[00:01:16.369,415] <err> download_client: Failed to send HTTP request, errno 57
[00:01:16.369,476] <err> fota_download: Download client error
[00:01:16.369,476] <err> aws_fota: FOTA download failed, report back
[mqtt_evt_handler:186] PUBACK packet id: 36218
[00:01:17.691,528] <inf> aws_fota: Start downloading firmware from *******.s3-us-west-2.amazonaws.com20190929_test_update.bin
[00:01:18.055,786] <inf> download_client: Attempting to connect over IPv4
[00:01:18.617,645] <inf> download_client: Connected
[00:01:18.617,645] <inf> download_client: Downloading: 20190929_test_update.bin [0]
[00:01:19.589,080] <wrn> download_client: Copying 604 payload bytes
[00:01:19.589,111] <inf> download_client: Downloaded bytes: 604/65804
[00:01:19.671,264] <inf> download_client: Downloaded bytes: 1628/65804
[00:01:19.748,352] <inf> download_client: Downloaded bytes: 2652/65804
[00:01:20.272,949] <inf> download_client: Downloaded bytes: 3212/65804
[00:01:20.274,475] <inf> download_client: Downloaded bytes: 4096/65804
[00:01:20.274,505] <inf> fota_flash_block: Erasing sector at offset 0x0
[00:01:20.935,089] <inf> download_client: Downloaded bytes: 4096/65804
[00:01:21.001,159] <inf> download_client: Downloaded bytes: 4804/65804
[00:01:21.254,241] <inf> download_client: Downloaded bytes: 5828/65804
[00:01:21.331,604] <inf> download_client: Downloaded bytes: 6852/65804
[00:01:21.489,715] <inf> download_client: Downloaded bytes: 8192/65804
[00:01:21.489,715] <inf> fota_flash_block: Erasing sector at offset 0x1000
[00:01:22.378,753] <inf> download_client: Downloaded bytes: 8192/65804
[00:01:22.413,940] <inf> download_client: Downloaded bytes: 9216/65804
[00:01:22.885,711] <inf> download_client: Downloaded bytes: 9776/65804
[00:01:22.885,925] <inf> download_client: Downloaded bytes: 10800/65804
[00:01:22.886,230] <inf> download_client: Downloaded bytes: 11824/65804
[00:01:22.887,451] <inf> download_client: Downloaded bytes: 12288/65804
[00:01:22.887,451] <inf> fota_flash_block: Erasing sector at offset 0x2000
[00:01:23.840,789] <inf> download_client: Downloaded bytes: 12288/65804
[00:01:23.931,915] <inf> download_client: Downloaded bytes: 13312/65804
[00:01:24.403,900] <inf> download_client: Downloaded bytes: 13872/65804
[00:01:24.403,991] <inf> download_client: Downloaded bytes: 14896/65804
[00:01:24.404,266] <inf> download_client: Downloaded bytes: 15920/65804
[00:01:24.405,487] <inf> download_client: Downloaded bytes: 16384/65804
[00:01:24.405,517] <inf> fota_flash_block: Erasing sector at offset 0x3000
[00:01:25.134,796] <inf> download_client: Downloaded bytes: 16384/65804
[00:01:25.180,358] <inf> download_client: Downloaded bytes: 17408/65804
[00:01:25.207,702] <inf> download_client: Downloaded bytes: 18432/65804
[00:01:25.242,858] <inf> download_client: Downloaded bytes: 19144/65804
[00:01:25.244,232] <inf> download_client: Downloaded bytes: 19924/65804
[00:01:25.696,838] <inf> download_client: Downloaded bytes: 20480/65804
[00:01:25.696,838] <inf> fota_flash_block: Erasing sector at offset 0x4000
[00:01:26.420,837] <inf> download_client: Downloaded bytes: 20480/65804
[00:01:26.465,911] <inf> download_client: Downloaded bytes: 21504/65804
[00:01:26.512,878] <inf> download_client: Downloaded bytes: 22528/65804
[00:01:26.981,750] <inf> download_client: Downloaded bytes: 23240/65804
[00:01:26.983,093] <inf> download_client: Downloaded bytes: 24020/65804
[00:01:27.028,900] <inf> download_client: Downloaded bytes: 24576/65804
[00:01:27.028,900] <inf> fota_flash_block: Erasing sector at offset 0x5000
[00:01:28.234,893] <inf> download_client: Downloaded bytes: 24576/65804
[00:01:28.270,965] <inf> download_client: Downloaded bytes: 25284/65804
[00:01:28.384,887] <inf> download_client: Downloaded bytes: 25992/65804
[00:01:28.428,009] <inf> download_client: Downloaded bytes: 27016/65804
[00:01:28.902,954] <inf> download_client: Downloaded bytes: 27728/65804
[00:01:28.904,052] <inf> download_client: Downloaded bytes: 28116/65804
[00:01:28.953,887] <inf> download_client: Downloaded bytes: 28672/65804
[00:01:28.953,918] <inf> fota_flash_block: Erasing sector at offset 0x6000
[00:01:29.842,987] <inf> download_client: Downloaded bytes: 28672/65804
[00:01:29.897,125] <inf> download_client: Downloaded bytes: 29380/65804
[00:01:30.061,859] <inf> download_client: Downloaded bytes: 30404/65804
[00:01:30.106,994] <inf> download_client: Downloaded bytes: 31428/65804
[00:01:30.492,980] <inf> download_client: Downloaded bytes: 31988/65804
[00:01:30.494,140] <inf> download_client: Downloaded bytes: 32768/65804
[00:01:30.494,140] <inf> fota_flash_block: Erasing sector at offset 0x7000
[00:01:31.165,954] <inf> download_client: Downloaded bytes: 32768/65804
[00:01:31.221,130] <inf> download_client: Downloaded bytes: 33476/65804
[00:01:31.418,029] <inf> download_client: Downloaded bytes: 34500/65804
[00:01:31.694,091] <inf> download_client: Downloaded bytes: 35060/65804
[00:01:31.694,183] <inf> download_client: Downloaded bytes: 36084/65804
[00:01:31.695,495] <inf> download_client: Downloaded bytes: 36864/65804
[00:01:31.695,495] <inf> fota_flash_block: Erasing sector at offset 0x8000
[00:01:32.404,083] <inf> download_client: Downloaded bytes: 36864/65804
[00:01:32.457,183] <inf> download_client: Downloaded bytes: 37572/65804
[00:01:32.493,988] <inf> download_client: Downloaded bytes: 38280/65804
[00:01:32.587,921] <inf> download_client: Downloaded bytes: 39304/65804
[00:01:32.626,098] <inf> download_client: Downloaded bytes: 40016/65804
[00:01:32.627,319] <inf> download_client: Downloaded bytes: 40404/65804
[00:01:33.042,999] <inf> download_client: Downloaded bytes: 40960/65804
[00:01:33.043,029] <inf> fota_flash_block: Erasing sector at offset 0x9000
[00:01:33.706,054] <inf> download_client: Downloaded bytes: 40960/65804
[00:01:33.741,912] <inf> download_client: Downloaded bytes: 41668/65804
[00:01:33.795,928] <inf> download_client: Downloaded bytes: 42692/65804
[00:01:33.833,129] <inf> download_client: Downloaded bytes: 43404/65804
[00:01:33.834,320] <inf> download_client: Downloaded bytes: 43792/65804
[00:01:34.341,979] <inf> download_client: Downloaded bytes: 44816/65804
AWS_FOTA_EVT_ERROR
[00:01:57.326,202] <inf> download_client: Downloaded bytes: 45056/65804
[00:01:57.326,232] <inf> fota_flash_block: Erasing sector at offset 0xa000
[00:01:57.466,918] <err> download_client: Failed to send HTTP request, errno 57
[00:01:57.468,475] <err> fota_download: Download client error
[00:01:57.468,475] <err> aws_fota: FOTA download failed, report back
[mqtt_evt_handler:186] PUBACK packet id: 58419
AWS_FOTA_EVT_ERROR
aws_fota_mqtt_evt_handler: Failed! -14
Disconnecting MQTT client...
[mqtt_evt_handler:151] MQTT PUBLISH result=0 len=254
mqtt_read_publish_payload: Failed! -36
Disconnecting MQTT client...
Could not disconnect: -57
Received: 
[00:01:58.661,682] <err> aws_fota: Job document update was rejected
[mqtt_evt_handler:144] MQTT client disconnected 0
POLLNVAL
Disconnecting MQTT client...
Could not disconnect MQTT client. Error: -57