We have worked through getting AWS MQTT working and have the FOTA job file loading properly. When the HTTP request is made the file begins downloading but fails to download after a seemingly random period of time. Anywhere between 3-30% complete. The failure happens when the receiving bytes step takes a considerable amount of time and then the next http request fails. The FOTA library then resets and tries to download the file again with the same result.
Hello,
Can you post the log so I can see what's happening?
Here is the associated log
[mqtt_evt_handler:211] MQTT client connected! [00:00:54.764,282] [1B][0m<inf> download_client: Attempting to connect over IPv4[1B][0m [00:01:12.650,878] [1B][1;31m<err> download_client: Unable to connect, errno 119[1B][0m [00:01:12.659,454] [1B][1;31m<err> fota_download: download_client_connect error -22[1B][0m [mqtt_evt_handler:281] SUBACK packet id: 2112 [mqtt_evt_handler:271] PUBACK packet id: 11045 [00:01:58.280,120] [1B][0m<inf> aws_fota: Job document with only timestamp on notify_next meaning that the current device job was canceled[1B][0m FOTA LIBRARY HANDLED EVENT FOTA LIBRARY HANDLED EVENT [mqtt_evt_handler:286] default: 8 FOTA LIBRARY HANDLED EVENT [mqtt_evt_handler:271] PUBACK packet id: 5253 [00:02:01.980,194] [1B][0m<inf> aws_fota: Start downloading firmware from xxxx.s3-us-west-2.amazonaws.comxxxxx.bin[1B][0m [00:02:02.273,773] [1B][0m<inf> download_client: Attempting to connect over IPv4[1B][0m [00:02:02.695,556] [1B][0m<inf> download_client: Connected to xxxxx.s3-us-west-2.amazonaws.com[1B][0m [00:02:02.704,742] [1B][0m<inf> download_client: Downloading: xxxxx/xxx.bin [0][1B][0m [00:02:02.712,829] [1B][0m<inf> download_client: Sending HTTP request [1B][0m FOTA LIBRARY HANDLED EVENT [00:02:02.722,351] [1B][0m<inf> download_client: Receiving bytes..[1B][0m [00:02:03.296,783] [1B][0m<inf> download_client: Receiving bytes done..[1B][0m [00:02:03.303,253] [1B][0m<inf> download_client: Read 473 bytes from socket[1B][0m [00:02:03.311,126] [1B][0m<inf> download_client: Downloaded 0/246636 bytes (0%)[1B][0m [00:02:03.318,298] [1B][0m<inf> download_client: Awaiting full fragment (0)[1B][0m [00:02:03.325,134] [1B][0m<inf> download_client: Receiving bytes..[1B][0m [00:02:03.337,524] [1B][0m<inf> download_client: Receiving bytes done..[1B][0m [00:02:03.344,024] [1B][0m<inf> download_client: Read 708 bytes from socket[1B][0m [00:02:03.350,830] [1B][0m<inf> download_client: Downloaded 708/246636 bytes (0%)[1B][0m [00:02:03.358,184] [1B][0m<inf> download_client: Awaiting full fragment (708)[1B][0m [00:02:03.365,173] [1B][0m<inf> download_client: Receiving bytes..[1B][0m [00:02:03.479,064] [1B][0m<inf> download_client: Receiving bytes done..[1B][0m [00:02:03.485,534] [1B][0m<inf> download_client: Read 1024 bytes from socket[1B][0m [00:02:03.492,462] [1B][0m<inf> download_client: Downloaded 1732/246636 bytes (0%)[1B][0m [00:02:03.499,908] [1B][0m<inf> download_client: Awaiting full fragment (1732)[1B][0m [00:02:03.506,988] [1B][0m<inf> download_client: Receiving bytes..[1B][0m [00:02:03.516,082] [1B][0m<inf> download_client: Receiving bytes done..[1B][0m [00:02:03.522,552] [1B][0m<inf> download_client: Read 1024 bytes from socket[1B][0m [00:02:03.529,479] [1B][0m<inf> download_client: Downloaded 2756/246636 bytes (1%)[1B][0m [00:02:03.536,926] [1B][0m<inf> download_client: Awaiting full fragment (2756)[1B][0m [00:02:03.544,006] [1B][0m<inf> download_client: Receiving bytes..[1B][0m [00:02:03.999,053] [1B][0m<inf> download_client: Receiving bytes done..[1B][0m [00:02:04.005,676] [1B][0m<inf> download_client: Read 560 bytes from socket[1B][0m [00:02:04.012,512] [1B][0m<inf> download_client: Downloaded 3316/246636 bytes (1%)[1B][0m [00:02:04.019,958] [1B][0m<inf> download_client: Awaiting full fragment (3316)[1B][0m [00:02:04.027,038] [1B][0m<inf> download_client: Receiving bytes..[1B][0m [00:02:04.033,111] [1B][0m<inf> download_client: Receiving bytes done..[1B][0m [00:02:04.039,581] [1B][0m<inf> download_client: Read 780 bytes from socket[1B][0m [00:02:04.046,417] [1B][0m<inf> download_client: Downloaded 4096/246636 bytes (1%)[1B][0m [00:02:04.053,863] [1B][0m<inf> fota_flash_block: Erasing sector at offset 0x0[1B][0m [00:02:04.192,596] [1B][0m<inf> download_client: Sending HTTP request [1B][0m [00:02:04.199,584] [1B][0m<inf> download_client: Receiving bytes..[1B][0m [00:02:04.735,992] [1B][0m<inf> download_client: Receiving bytes done..[1B][0m [00:02:04.742,492] [1B][0m<inf> download_client: Read 1024 bytes from socket[1B][0m [00:02:04.750,122] [1B][1;33m<wrn> download_client: Copying 548 payload bytes[1B][0m [00:02:04.757,141] [1B][0m<inf> download_client: Downloaded 4644/246636 bytes (1%)[1B][0m [00:02:04.764,556] [1B][0m<inf> download_client: Awaiting full fragment (548)[1B][0m [00:02:04.771,575] [1B][0m<inf> download_client: Receiving bytes..[1B][0m [00:02:04.989,135] [1B][0m<inf> download_client: Receiving bytes done..[1B][0m [00:02:04.995,605] [1B][0m<inf> download_client: Read 1024 bytes from socket[1B][0m [00:02:05.002,532] [1B][0m<inf> download_client: Downloaded 5668/246636 bytes (2%)[1B][0m [00:02:05.009,979] [1B][0m<inf> download_client: Awaiting full fragment (1572)[1B][0m [00:02:05.017,059] [1B][0m<inf> download_client: Receiving bytes..[1B][0m [00:02:05.039,093] [1B][0m<inf> download_client: Receiving bytes done..[1B][0m [00:02:05.045,562] [1B][0m<inf> download_client: Read 1024 bytes from socket[1B][0m [00:02:05.052,490] [1B][0m<inf> download_client: Downloaded 6692/246636 bytes (2%)[1B][0m [00:02:05.059,936] [1B][0m<inf> download_client: Awaiting full fragment (2596)[1B][0m [00:02:05.067,016] [1B][0m<inf> download_client: Receiving bytes..[1B][0m [00:02:05.213,134] [1B][0m<inf> download_client: Receiving bytes done..[1B][0m [00:02:05.219,757] [1B][0m<inf> download_client: Read 560 bytes from socket[1B][0m [00:02:05.226,593] [1B][0m<inf> download_client: Downloaded 7252/246636 bytes (2%)[1B][0m [00:02:05.234,039] [1B][0m<inf> download_client: Awaiting full fragment (3156)[1B][0m [00:02:05.241,119] [1B][0m<inf> download_client: Receiving bytes..[1B][0m [00:02:05.247,192] [1B][0m<inf> download_client: Receiving bytes done..[1B][0m [00:02:05.253,662] [1B][0m<inf> download_client: Read 940 bytes from socket[1B][0m [00:02:05.260,498] [1B][0m<inf> download_client: Downloaded 8192/246636 bytes (3%)[1B][0m [00:02:05.267,944] [1B][0m<inf> fota_flash_block: Erasing sector at offset 0x1000[1B][0m [00:02:05.413,360] [1B][0m<inf> download_client: Sending HTTP request [1B][0m [00:02:05.420,227] [1B][0m<inf> download_client: Receiving bytes..[1B][0m [00:02:06.075,988] [1B][0m<inf> download_client: Receiving bytes done..[1B][0m [00:02:06.082,458] [1B][0m<inf> download_client: Read 1024 bytes from socket[1B][0m [00:02:06.090,118] [1B][1;33m<wrn> download_client: Copying 547 payload bytes[1B][0m [00:02:06.097,137] [1B][0m<inf> download_client: Downloaded 8739/246636 bytes (3%)[1B][0m [00:02:06.104,583] [1B][0m<inf> download_client: Awaiting full fragment (547)[1B][0m [00:02:06.111,572] [1B][0m<inf> download_client: Receiving bytes..[1B][0m [00:02:06.136,199] [1B][0m<inf> download_client: Receiving bytes done..[1B][0m [00:02:06.142,883] [1B][0m<inf> download_client: Read 712 bytes from socket[1B][0m [00:02:06.149,719] [1B][0m<inf> download_client: Downloaded 9451/246636 bytes (3%)[1B][0m [00:02:06.157,165] [1B][0m<inf> download_client: Awaiting full fragment (1259)[1B][0m [00:02:06.164,245] [1B][0m<inf> download_client: Receiving bytes..[1B][0m [00:02:06.170,410] [1B][0m<inf> download_client: Receiving bytes done..[1B][0m [00:02:06.176,879] [1B][0m<inf> download_client: Read 2281 bytes from socket[1B][0m [00:02:06.183,776] [1B][0m<inf> download_client: Downloaded 11732/246636 bytes (4%)[1B][0m [00:02:06.191,314] [1B][0m<inf> download_client: Awaiting full fragment (3540)[1B][0m [00:02:06.198,394] [1B][0m<inf> download_client: Receiving bytes..[1B][0m [00:02:06.600,189] [1B][0m<inf> download_client: Receiving bytes done..[1B][0m [00:02:06.606,689] [1B][0m<inf> download_client: Read 556 bytes from socket[1B][0m [00:02:06.613,525] [1B][0m<inf> download_client: Downloaded 12288/246636 bytes (4%)[1B][0m [00:02:06.621,063] [1B][0m<inf> fota_flash_block: Erasing sector at offset 0x2000[1B][0m [00:02:06.766,754] [1B][0m<inf> download_client: Sending HTTP request [1B][0m [00:02:06.773,803] [1B][0m<inf> download_client: Receiving bytes..[1B][0m [00:02:07.320,281] [1B][0m<inf> download_client: Receiving bytes done..[1B][0m [00:02:07.326,751] [1B][0m<inf> download_client: Read 1024 bytes from socket[1B][0m [00:02:07.334,411] [1B][1;33m<wrn> download_client: Copying 546 payload bytes[1B][0m [00:02:07.341,400] [1B][0m<inf> download_client: Downloaded 12834/246636 bytes (5%)[1B][0m [00:02:07.348,937] [1B][0m<inf> download_client: Awaiting full fragment (546)[1B][0m [00:02:07.355,926] [1B][0m<inf> download_client: Receiving bytes..[1B][0m [00:02:07.376,129] [1B][0m<inf> download_client: Receiving bytes done..[1B][0m [00:02:07.382,720] [1B][0m<inf> download_client: Read 712 bytes from socket[1B][0m [00:02:07.389,556] [1B][0m<inf> download_client: Downloaded 13546/246636 bytes (5%)[1B][0m [00:02:07.397,094] [1B][0m<inf> download_client: Awaiting full fragment (1258)[1B][0m [00:02:07.404,174] [1B][0m<inf> download_client: Receiving bytes..[1B][0m [00:02:07.410,247] [1B][0m<inf> download_client: Receiving bytes done..[1B][0m [00:02:07.416,870] [1B][0m<inf> download_client: Read 158 bytes from socket[1B][0m [00:02:07.423,706] [1B][0m<inf> download_client: Downloaded 13704/246636 bytes (5%)[1B][0m [00:02:07.431,243] [1B][0m<inf> download_client: Awaiting full fragment (1416)[1B][0m [00:02:07.438,323] [1B][0m<inf> download_client: Receiving bytes..[1B][0m [00:02:07.444,396] [1B][0m<inf> download_client: Receiving bytes done..[1B][0m [00:02:07.450,866] [1B][0m<inf> download_client: Read 1024 bytes from socket[1B][0m [00:02:07.457,763] [1B][0m<inf> download_client: Downloaded 14728/246636 bytes (5%)[1B][0m [00:02:07.465,270] [1B][0m<inf> download_client: Awaiting full fragment (2440)[1B][0m [00:02:07.472,351] [1B][0m<inf> download_client: Receiving bytes..[1B][0m [00:02:07.848,297] [1B][0m<inf> download_client: Receiving bytes done..[1B][0m [00:02:07.854,766] [1B][0m<inf> download_client: Read 1024 bytes from socket[1B][0m [00:02:07.861,663] [1B][0m<inf> download_client: Downloaded 15752/246636 bytes (6%)[1B][0m [00:02:07.869,201] [1B][0m<inf> download_client: Awaiting full fragment (3464)[1B][0m [00:02:07.876,281] [1B][0m<inf> download_client: Receiving bytes..[1B][0m [00:02:31.618,164] [1B][0m<inf> download_client: Receiving bytes done..[1B][0m [00:02:31.624,633] [1B][0m<inf> download_client: Read 632 bytes from socket[1B][0m [00:02:31.631,469] [1B][0m<inf> download_client: Downloaded 16384/246636 bytes (6%)[1B][0m [00:02:31.639,007] [1B][0m<inf> fota_flash_block: Erasing sector at offset 0x3000[1B][0m [00:02:31.784,545] [1B][0m<inf> download_client: Sending HTTP request [1B][0m [00:02:31.790,924] [1B][0m<inf> download_client: Connection state: 0 - 139 [1B][0m [00:02:31.797,760] [1B][1;31m<err> download_client: Failed to send HTTP request, errno 128[1B][0m [00:02:31.807,403] [1B][1;31m<err> fota_download: Download client error[1B][0m [00:02:31.813,903] [1B][1;31m<err> aws_fota: FOTA download failed, report back[1B][0m AWS_FOTA_EVT_ERROR [mqtt_evt_handler:271] PUBACK packet id: 18240 [00:02:32.777,130] [1B][0m<inf> aws_fota: Start downloading firmware from xxxx.s3-us-west-2.amazonaws.comxxxxx.bin[1B][0m [00:02:33.074,798] [1B][0m<inf> download_client: Attempting to connect over IPv4[1B][0m [00:02:33.481,689] [1B][0m<inf> download_client: Connected to xxxxx.s3-us-west-2.amazonaws.com[1B][0m [00:02:33.490,844] [1B][0m<inf> download_client: Downloading: xxxx/xxxx.bin [0][1B][0m [00:02:33.498,962] [1B][0m<inf> download_client: Sending HTTP request [1B][0m FOTA LIBRARY HANDLED EVENT
Are you using the latest tag (1.0.0)? Please make sure to checkout the latest tag and also keep the repos and modem firmware updated.
We are using the latest tag, as well as trying master in a few other locations.
Using the latest tag (v1.0.0) even the samples don't seem to build. Java script errors about files not existing as well as python dependencies referencing projects that no longer exist. Hacking around them seems to only cause more issues.
On master things actually build but the aws FOTA sample on its own still fails in the same way as the log above.
From a surface level it looks like the download thread stops trying to receive after an indeterminant amount of time or perhaps suddenly we are hitting some sort of timeout on a socket. Looking through some documentation it looks like the download_client_start should be able to start a connection back up from where it was but this doesn't seem to be used in the examples, completely restarting the download on this error. Also it is unclear what the error 128 is as it isn't enumerated in the errno.
