nRF9160, File upload via HTTP

[Stas Jis]

We are using nRF9160 DK (SDK 1.9.1) with "serial lte modem" firmware.
We are trying to test downloading files from a server using AT commands to work with HTTP.
The file is large (more than 850 kilobytes), but it is supposed to be downloaded in parts (1 kilobyte each) using the "Range" parameter in the Header to indicate how many bytes should be downloaded.
But each time we get a response code: -104.

#XHTTPCRSP: 0,-104
#XHTTPCCON: 0

I am attaching the logs from the LTE terminal:

2022-04-12T14:55:33.495Z DEBUG modem << Ready
2022-04-12T14:55:33.498Z DEBUG modem << [00:00:00.205,780] [0m<inf> slm: Serial LTE Modem[0m
2022-04-12T14:55:33.501Z DEBUG modem << [00:00:00.212,799] [0m<dbg> slm_at_host.slm_at_host_init: UART baud: 115200 d/p/s-bits: 3/0/1 HWFC: 1[0m
2022-04-12T14:55:33.532Z DEBUG modem << [00:00:00.212,799] [0m<dbg> slm_at_host.slm_uart_configure: Set uart baudrate to: 115200, hw flow control 1[0m
2022-04-12T14:55:33.534Z DEBUG modem << [00:00:00.229,461] [0m<dbg> nrf_cloud_transport.nct_client_id_set: client_id = nrf-352656108600480[0m
2022-04-12T14:55:33.568Z DEBUG modem << [00:00:00.230,163] [0m<dbg> nrf_cloud_transport.nct_topics_populate: accepted_topic: nrf-352656108600480/shadow/get/accepted[0m
2022-04-12T14:55:33.573Z DEBUG modem << [00:00:00.230,163] [0m<dbg> nrf_cloud_transport.nct_topics_populate: rejected_topic: $aws/things/nrf-352656108600480/shadow/get/re~[0m
2022-04-12T14:55:33.593Z DEBUG modem << [00:00:00.230,163] [0m<dbg> nrf_cloud_transport.nct_topics_populate: update_delta_topic: $aws/things/nrf-352656108600480/shadow/update~[0m
2022-04-12T14:55:33.616Z DEBUG modem << [00:00:00.230,224] [0m<dbg> nrf_cloud_transport.nct_topics_populate: update_topic: <log_strdup alloc failed>[0m
2022-04-12T14:55:33.636Z DEBUG modem << [00:00:00.230,224] [0m<dbg> nrf_cloud_transport.nct_topics_populate: shadow_get_topic: <log_strdup alloc failed>[0m
2022-04-12T14:55:33.641Z DEBUG modem << [00:00:00.230,255] [0m<dbg> nrf_cloud.nfsm_set_current_state_and_notify: state: 1[0m
2022-04-12T14:55:33.643Z DEBUG modem << [00:00:00.230,377] [0m<dbg> slm_at_host: TX
2022-04-12T14:55:33.673Z DEBUG modem <<                                       52 65 61 64 79 0d 0a                             |Ready..          [0m
2022-04-12T14:55:33.677Z DEBUG modem << [00:00:00.230,468] [0m<dbg> slm_fota.slm_fota_post_process: FOTA result 0,0,0[0m
2022-04-12T14:55:33.699Z DEBUG modem << [00:00:00.237,304] [0m<inf> slm_at_host: at_host init done[0m
2022-04-12T14:55:34.992Z DEBUG modem >> AT
2022-04-12T14:55:35.003Z DEBUG modem << OK
2022-04-12T14:55:36.002Z DEBUG modem << [00:00:11.435,943] [0m<dbg> slm_at_host: RX
2022-04-12T14:55:36.030Z DEBUG modem <<                                       41 54                                            |AT               [0m
2022-04-12T14:55:36.033Z DEBUG modem << [00:00:11.442,565] [0m<dbg> slm_at_host: TX
2022-04-12T14:55:36.035Z DEBUG modem <<                                       0d 0a                                            |..               [0m
2022-04-12T14:55:36.077Z DEBUG modem << [00:00:11.442,626] [0m<dbg> slm_at_host: TX
2022-04-12T14:55:36.081Z DEBUG modem <<                                       4f 4b 0d 0a                                      |OK..             [0m
2022-04-12T14:55:45.792Z DEBUG modem >> AT%XSYSTEMMODE=1,0,1,0
2022-04-12T14:55:45.806Z DEBUG modem << OK
2022-04-12T14:55:46.802Z DEBUG modem << [00:00:22.237,915] [0m<dbg> slm_at_host: RX
2022-04-12T14:55:46.815Z DEBUG modem <<                                       41 54 25 58 53 59 53 54  45 4d 4d 4f 44 45 3d 31 |AT%XSYST EMMODE=1
2022-04-12T14:55:46.830Z DEBUG modem <<                                       2c 30 2c 31 2c 30                                |,0,1,0           [0m
2022-04-12T14:55:46.848Z DEBUG modem << [00:00:22.238,433] [0m<dbg> slm_at_host.uart_callback: RX_DISABLED[0m
2022-04-12T14:55:46.855Z DEBUG modem << [00:00:22.246,063] [0m<dbg> slm_at_host: TX
2022-04-12T14:55:46.886Z DEBUG modem <<                                       0d 0a                                            |..               [0m
2022-04-12T14:55:46.890Z DEBUG modem << [00:00:22.246,093] [0m<dbg> slm_at_host: TX
2022-04-12T14:55:46.894Z DEBUG modem <<                                       4f 4b 0d 0a                                      |OK..             [0m
2022-04-12T14:55:50.008Z DEBUG modem >> AT%XCOEX0=1,1,1565,1586
2022-04-12T14:55:50.026Z DEBUG modem << OK
2022-04-12T14:55:51.018Z DEBUG modem << [00:00:26.454,284] [0m<dbg> slm_at_host: RX
2022-04-12T14:55:51.031Z DEBUG modem <<                                       41 54 25 58 43 4f 45 58  30 3d 31 2c 31 2c 31 35 |AT%XCOEX 0=1,1,15
2022-04-12T14:55:51.045Z DEBUG modem <<                                       36 35 2c 31 35 38 36                             |65,1586          [0m
2022-04-12T14:55:51.062Z DEBUG modem << [00:00:26.454,803] [0m<dbg> slm_at_host.uart_callback: RX_DISABLED[0m
2022-04-12T14:55:51.063Z DEBUG modem << [00:00:26.463,439] [0m<dbg> slm_at_host: TX
2022-04-12T14:55:51.083Z DEBUG modem <<                                       0d 0a                                            |..               [0m
2022-04-12T14:55:51.085Z DEBUG modem << [00:00:26.463,500] [0m<dbg> slm_at_host: TX
2022-04-12T14:55:51.101Z DEBUG modem <<                                       4f 4b 0d 0a                                      |OK..             [0m
2022-04-12T14:55:53.928Z DEBUG modem >> AT+CPSMS=1
2022-04-12T14:55:53.947Z DEBUG modem << OK
2022-04-12T14:55:54.938Z DEBUG modem << [00:00:30.373,718] [0m<dbg> slm_at_host: RX
2022-04-12T14:55:54.952Z DEBUG modem <<                                       41 54 2b 43 50 53 4d 53  3d 31                   |AT+CPSMS =1      [0m
2022-04-12T14:55:54.968Z DEBUG modem << [00:00:30.374,237] [0m<dbg> slm_at_host.uart_callback: RX_DISABLED[0m
2022-04-12T14:55:54.970Z DEBUG modem << [00:00:30.382,751] [0m<dbg> slm_at_host: TX
2022-04-12T14:55:54.988Z DEBUG modem <<                                       0d 0a                                            |..               [0m
2022-04-12T14:55:54.990Z DEBUG modem << [00:00:30.382,781] [0m<dbg> slm_at_host: TX
2022-04-12T14:55:55.002Z DEBUG modem <<                                       4f 4b 0d 0a                                      |OK..             [0m
2022-04-12T14:55:58.192Z DEBUG modem >> AT+CFUN=1
2022-04-12T14:55:58.237Z DEBUG modem << OK
2022-04-12T14:55:59.201Z DEBUG modem << [00:00:34.637,145] [0m<dbg> slm_at_host: RX
2022-04-12T14:55:59.220Z DEBUG modem <<                                       41 54 2b 43 46 55 4e 3d  31                      |AT+CFUN= 1       [0m
2022-04-12T14:55:59.224Z DEBUG modem << [00:00:34.637,664] [0m<dbg> slm_at_host.uart_callback: RX_DISABLED[0m
2022-04-12T14:55:59.240Z DEBUG modem << [00:00:34.678,497] [0m<dbg> slm_at_host: TX
2022-04-12T14:55:59.243Z DEBUG modem <<                                       0d 0a                                            |..               [0m
2022-04-12T14:55:59.260Z DEBUG modem << [00:00:34.678,558] [0m<dbg> slm_at_host: TX
2022-04-12T14:55:59.274Z DEBUG modem <<                                       4f 4b 0d 0a                                      |OK..             [0m
2022-04-12T14:56:12.551Z DEBUG modem >> AT#XHTTPCCON=1,"petpace.s3.amazonaws.com",443
2022-04-12T14:56:12.993Z DEBUG modem << #XHTTPCCON: 1
2022-04-12T14:56:13.001Z DEBUG modem << OK
2022-04-12T14:56:13.564Z DEBUG modem << [00:00:49.001,190] [0m<dbg> slm_at_host: RX
2022-04-12T14:56:13.604Z DEBUG modem <<                                       41 54 23 58 48 54 54 50  43 43 4f 4e 3d 31 2c 22 |AT#XHTTP CCON=1,"                                      70 65 74 70 61 63 65 2e  73 33 2e 61 6d 61 7a 6f |petpace. s3.amazo                                      6e 61 77 73 2e 63 6f 6d  22 2c 34 34 33          |naws.com ",443   [0m
2022-04-12T14:56:13.614Z DEBUG modem << [00:00:49.001,678] [0m<dbg> slm_at_host.uart_callback: RX_DISABLED[0m
2022-04-12T14:56:13.625Z DEBUG modem << [00:00:49.010,650] [0m<dbg> slm_httpc.do_http_connect: Configuring socket timeout (10 s)[0m
2022-04-12T14:56:13.638Z DEBUG modem << [00:00:49.433,959] [0m<dbg> slm_at_host: TX
2022-04-12T14:56:13.657Z DEBUG modem <<                                       0d 0a 23 58 48 54 54 50  43 43 4f 4e 3a 20 31 0d |..#XHTTP CCON: 1.
2022-04-12T14:56:13.659Z DEBUG modem <<                                       0a                                               |.                [0m
2022-04-12T14:56:13.675Z DEBUG modem << [00:00:49.433,990] [0m<dbg> slm_at_host: TX
2022-04-12T14:56:13.696Z DEBUG modem <<                                       0d 0a 4f 4b 0d 0a                                |..OK..           [0m
2022-04-12T14:56:26.320Z DEBUG modem >> T#XHTTPCREQ="GET","collar-fw.bin HTTP/1.1","Range: bytes=1-100\r\n"
2022-04-12T14:56:26.330Z DEBUG modem << ERROR
2022-04-12T14:56:26.335Z ERROR Error: T#XHTTPCREQ="GET","collar-fw.bin HTTP/1.1","Range: bytes=1-100\r\n"
 failed
2022-04-12T14:56:27.335Z DEBUG modem << [00:01:02.772,949] [0m<dbg> slm_at_host: RX
2022-04-12T14:56:27.401Z DEBUG modem <<                                       54 23 58 48 54 54 50 43  52 45 51 3d 22 47 45 54 |T#XHTTPC REQ="GET                                      22 2c 22 63 6f 6c 6c 61  72 2d 66 77 2e 62 69 6e |","colla r-fw.bin                                      20 48 54 54 50 2f 31 2e  31 22 2c 22 52 61 6e 67 | HTTP/1. 1","Rang                                      65 3a 20 62 79 74 65 73  3d 31 2d 31 30 30 5c 72 |e: bytes =1-100\r                                      5c 6e 22                                         |\n"              [0m
2022-04-12T14:56:27.411Z DEBUG modem << [00:01:02.772,949] [1;31m<err> slm_at_host: AT command invalid[0m
2022-04-12T14:56:27.416Z DEBUG modem << [00:01:02.772,979] [0m<dbg> slm_at_host: TX
2022-04-12T14:56:27.432Z DEBUG modem <<                                       0d 0a 45 52 52 4f 52 0d  0a                      |..ERROR. .       [0m
2022-04-12T14:56:32.384Z DEBUG modem >> AT#XHTTPCREQ="GET","collar-fw.bin HTTP/1.1","Range: bytes=1-100\r\n"
2022-04-12T14:56:32.401Z DEBUG modem << OK
2022-04-12T14:56:32.405Z DEBUG modem << #XHTTPCREQ: 0
2022-04-12T14:56:33.398Z DEBUG modem << [00:01:08.836,578] [0m<dbg> slm_at_host: RX
2022-04-12T14:56:33.464Z DEBUG modem <<                                       41 54 23 58 48 54 54 50  43 52 45 51 3d 22 47 45 |AT#XHTTP CREQ="GE                                      54 22 2c 22 63 6f 6c 6c  61 72 2d 66 77 2e 62 69 |T","coll ar-fw.bi                                      6e 20 48 54 54 50 2f 31  2e 31 22 2c 22 52 61 6e |n HTTP/1 .1","Ran                                      67 65 3a 20 62 79 74 65  73 3d 31 2d 31 30 30 5c |ge: byte s=1-100\                                      72 5c 6e 22                                      |r\n"             [0m
2022-04-12T14:56:33.474Z DEBUG modem << [00:01:08.837,066] [0m<dbg> slm_at_host.uart_callback: RX_DISABLED[0m
2022-04-12T14:56:33.491Z DEBUG modem << [00:01:08.837,585] [0m<dbg> slm_at_host: TX
2022-04-12T14:56:33.493Z DEBUG modem <<                                       0d 0a 4f 4b 0d 0a                                |..OK..           [0m
2022-04-12T14:56:33.509Z DEBUG modem << [00:01:08.846,954] [0m<dbg> slm_httpc.headers_cb: send header: 20 bytes[0m
2022-04-12T14:56:33.510Z DEBUG modem << [00:01:08.847,625] [0m<dbg> slm_at_host: TX
2022-04-12T14:56:33.526Z DEBUG modem <<                                       0d 0a 23 58 48 54 54 50  43 52 45 51 3a 20 30 0d |..#XHTTP CREQ: 0.
2022-04-12T14:56:33.541Z DEBUG modem <<                                       0a                                               |.                [0m
2022-04-12T14:56:42.406Z DEBUG modem << #XHTTPCRSP: 0,-104
2022-04-12T14:56:42.414Z DEBUG modem << #XHTTPCCON: 0
2022-04-12T14:56:43.409Z DEBUG modem << [00:01:18.847,961] [0m<dbg> slm_at_host: TX
2022-04-12T14:56:43.423Z DEBUG modem <<                                       0d 0a 23 58 48 54 54 50  43 52 53 50 3a 20 30 2c |..#XHTTP CRSP: 0,
2022-04-12T14:56:43.436Z DEBUG modem <<                                       2d 31 30 34 0d 0a                                |-104..           [0m
2022-04-12T14:56:43.447Z DEBUG modem << [00:01:18.848,022] [1;31m<err> slm_httpc: do_http_request fail:-104[0m
2022-04-12T14:56:43.450Z DEBUG modem << [00:01:18.848,693] [0m<dbg> slm_at_host: TX
2022-04-12T14:56:43.466Z DEBUG modem <<                                       0d 0a 23 58 48 54 54 50  43 43 4f 4e 3a 20 30 0d |..#XHTTP CCON: 0.
2022-04-12T14:56:43.484Z DEBUG modem <<                                       0a                                               |.                [0m
2022-04-12T14:56:43.486Z DEBUG modem << [00:01:18.850,036] [0m<inf> slm_httpc: HTTP thread terminated[0m

[Øyvind]

Hello, 

The technical support team will be out due to Easter Holiday until Tuesday April 19. We're sorry for the inconvenience. 

---

I will have a look at the issue but due to Easter holiday will not have answers from our developers. 

Kind regards;
Øyvind

[Øyvind]

Hi Stas Jis, 

my apologies for the late replay. Have you been able to solve this?

First of all, from nrfxlib\nrf_modem\include\nrf_errno.h #define NRF_ECONNRESET 104      /**< Connection reset */

Could you please provide a modem trace from when you are seeing this issue?

Thanks.

Kind regards,
Øyvind

[Stas Jis]

Øyvind,
No, the problem hasn't been resolved.
What kind of tracing are we talking about, I have already attached the logs above with the tracing settings enabled:
CONFIG_SLM_LOG_LEVEL_DBG=y
CONFIG_NRF_CLOUD_LOG_LEVEL_DBG=y
CONFIG_USE_SEGGER_RTT=y
CONFIG_RTT_CONSOLE=y

Or are there other options required?

[Øyvind]

Yes, please attach modem traces as well, to see what goes on inside the modem. 

[Øyvind]

Looking through the log you have provided, I can see that the error is returned by the function do_http_request() in nrf\applications\serial_lte_modem\src\http_c\slm_at_httpc.c

} else if (httpc.state != HTTPC_COMPLETE) {
		/* Socket was closed by remote */
		err = -ECONNRESET;
		sprintf(rsp_buf, "\r\n#XHTTPCRSP: 0,%d\r\n", err);
		rsp_send(rsp_buf, strlen(rsp_buf));

The log is difficult to read, would it be possible to provide the log as a .txt file? 

Are you able to download the same file using e.g. nRF9160: Download Client?

[Øyvind]

Done some testing here using nRF Connect SDK v1.9.1 and connecting to the server in the log output you have provided

2022-04-27T12:28:25.767Z DEBUG modem >> AT#XHTTPCCON=1,"petpace.s3.amazonaws.com",443
2022-04-27T12:28:26.301Z DEBUG modem << #XHTTPCCON: 1
2022-04-27T12:28:26.303Z DEBUG modem << OK
2022-04-27T12:28:27.576Z DEBUG modem << %CESQ: 65,3,17,2
2022-04-27T12:28:29.496Z DEBUG modem << %CESQ: 65,3,23,3
2022-04-27T12:28:38.718Z DEBUG modem >> AT#XHTTPCREQ="GET","/collar-fw.bin","Range: bytes=0-100\r\n"
2022-04-27T12:28:38.728Z DEBUG modem << OK
2022-04-27T12:28:38.737Z DEBUG modem << #XHTTPCREQ: 0
2022-04-27T12:28:38.825Z DEBUG modem << %CESQ: 64,3,18,2
2022-04-27T12:28:48.736Z DEBUG modem << #XHTTPCRSP: 0,-104
2022-04-27T12:28:48.744Z DEBUG modem << #XHTTPCCON: 0

Changing the port to 80 and retrying:

2022-04-27T12:34:36.421Z DEBUG modem >> AT#XHTTPCCON=1,"petpace.s3.amazonaws.com",80
2022-04-27T12:34:37.020Z DEBUG modem << #XHTTPCCON: 1
2022-04-27T12:34:37.024Z DEBUG modem << OK
2022-04-27T12:34:37.978Z DEBUG modem << %CESQ: 64,3,23,3
2022-04-27T12:34:49.691Z DEBUG modem >> AT#XHTTPCREQ="GET","/collar-fw.bin","Range: bytes=0-100\r\n"
2022-04-27T12:34:49.701Z DEBUG modem << OK
2022-04-27T12:34:49.711Z DEBUG modem << #XHTTPCREQ: 0
2022-04-27T12:34:54.143Z DEBUG modem << #XHTTPCRSP:419,1
2022-04-27T12:34:54.148Z DEBUG modem << HTTP/1.1 206 Partial Content
2022-04-27T12:34:54.154Z DEBUG modem << x-amz-id-2: 1GnhGqeMWHk2C/dC8PdTmnID4EEdnx7R/PijytOv5x1YkOta4RDrGswvCGyHuqIkxo0KbffBoUI=
2022-04-27T12:34:54.157Z DEBUG modem << x-amz-request-id: 82WZQAAXF0P8ERJ3
2022-04-27T12:34:54.160Z DEBUG modem << Date: Wed, 27 Apr 2022 12:34:54 GMT
2022-04-27T12:34:54.166Z DEBUG modem << Last-Modified: Sun, 03 Apr 2022 17:09:24 GMT
2022-04-27T12:34:54.168Z DEBUG modem << ETag: "071225a831fc361678aead84b0e34393"
2022-04-27T12:34:54.170Z DEBUG modem << Accept-Ranges: bytes
2022-04-27T12:34:54.172Z DEBUG modem << Content-Range: bytes 0-100/864544
2022-04-27T12:34:54.176Z DEBUG modem << Content-Type: application/octet-stream
2022-04-27T12:34:54.178Z DEBUG modem << Server: AmazonS3
2022-04-27T12:34:54.183Z DEBUG modem << Content-Length: 101
2022-04-27T12:34:54.184Z DEBUG modem << #XHTTPCRSP:101,1
2022-04-27T12:34:54.185Z DEBUG modem << 
2022-04-27T12:34:54.186Z DEBUG modem <<  9E
2022-04-27T12:34:54.187Z DEBUG modem << 5E
2022-04-27T12:34:54.188Z DEBUG modem << 5E
2022-04-27T12:34:54.189Z DEBUG modem << 5E
2022-04-27T12:34:54.190Z DEBUG modem << 5E
2022-04-27T12:34:54.191Z DEBUG modem << 5E
2022-04-27T12:34:54.192Z DEBUG modem << 5E
2022-04-27T12:34:54.192Z DEBUG modem << 5E
2022-04-27T12:34:54.193Z DEBUG modem << 5E
2022-04-27T12:34:54.194Z DEBUG modem << 5E
2022-04-27T12:34:54.195Z DEBUG modem << 5E
2022-04-27T12:34:54.196Z DEBUG modem << 5E
2022-04-27T12:34:54.196Z DEBUG modem << 4Ú
2022-04-27T12:34:54.197Z DEBUG modem << è
2022-04-27T12:34:54.226Z DEBUG modem << 5E
2022-04-27T12:34:54.227Z DEBUG modem << 5E
2022-04-27T12:34:54.227Z DEBUG modem << !º
2022-04-27T12:34:54.228Z DEBUG modem << 5E
2022-04-27T12:34:54.228Z DEBUG modem << 5E
2022-04-27T12:34:54.229Z DEBUG modem << ‰²
2022-04-27T12:34:54.229Z DEBUG modem << yº
2022-04-27T12:34:54.230Z DEBUG modem << -º
2022-04-27T12:34:54.230Z DEBUG modem << Eº
2022-04-27T12:34:54.232Z DEBUG modem << %º
2022-04-27T12:34:54.232Z DEBUG modem << ù
2022-04-27T12:34:54.233Z DEBUG modem << #XHTTPCRSP:0,1

As you are connecting to port 443, there might be an issue with certificates or the S3 bucket configuration. Have you added AWS credentials to your device?