This post is older than 2 years and might not be relevant anymore
More Info: Consider searching for newer posts

AT#XHTTPCREQ serial_lte_modem does not handle chunked HTTP response

if a response to the http request is chunked (https://en.wikipedia.org/wiki/Chunked_transfer_encoding), it is not handled correctly by the serial_lte_modem.

Sometimes - e.g. if cloudflare is used, it is not possible to disable chunk encoding, so the serial_lte_modem app is unusable in these scenarios.

00> [00:03:22.707,031] <inf> httpc: Partial data received (743 bytes)
00> [00:03:22.707,061] <inf> httpc: All the data received (743 bytes)
00> [00:03:22.707,489] <inf> at_host: TX
00> 23 58 48 54 54 50 43 52  53 50 3a 37 34 33 2c 30 |#XHTTPCR SP:743,0
00> 0d 0a                                            |..               
00> [00:03:22.709,625] <inf> at_host: TX
00> 22 7d 5d 2c 22 67 72 6f  75 70 22 3a 22 63 66 2d |"}],"gro up":"cf-
00> 6e 65 6c 22 2c 22 6d 61  78 5f 61 67 65 22 3a 36 |nel","ma x_age":6
00> 30 34 38 30 30 7d 0d 0a  4e 45 4c 3a 20 7b 22 72 |04800}.. NEL: {"r
00> 65 70 6f 72 74 5f 74 6f  22 3a 22 63 66 2d 6e 65 |eport_to ":"cf-ne
00> 6c 22 2c 22 6d 61 78 5f  61 67 65 22 3a 36 30 34 |l","max_ age":604
00> 38 30 30 7d 0d 0a 53 65  72 76 65 72 3a 20 63 6c |800}..Se rver: cl
00> 6f 75 64 66 6c 61 72 65  0d 0a 43 46 2d 52 41 59 |oudflare ..CF-RAY
00> 3a 20 35 66 31 62 30 35  63 34 39 66 63 35 64 34 |: 5f1b05 c49fc5d4
00> 33 66 2d 48 41 4d 0d 0a  0d 0a 44 65 76 69 63 65 |3f-HAM.. ..Device
00> 20 31 38 32 30 65 66 66  64 20 77 61 73 20 6e 6f | 1820eff d was no
00> 74 20 66 6f 75 6e 64 64  34 39 37 36 63 30 32 39 |t foundd 4976c029
00> 37 37 37 30 38 64 39 66  62 35 36 33 31 30 34 65 |77708d9f b563104e
00> 36 62 30 61 31 31 31 34  31 36 30 35 32 39 37 30 |6b0a1114 16052970
00> 33 34 3b 20 65 78 70 69  72 65 73 3d 53 75 6e 2c |34; expi res=Sun,
00> 20 31 33 2d 44 65 63 2d  32 30 20 31 39 3a 35 30 | 13-Dec- 20 19:50
00> 3a 33 34 20 47 4d 54 3b  20 70 61 74 68 3d 2f 3b |:34 GMT;  path=/;
00> 20 64 6f 6d 61 69 6e 3d  2e 67 77 78 63 6c 6f 75 | domain= .gwxclou
00> 64 2e 63 6f 6d 3b 20 48  74 74 70 4f 6e 6c 79 3b |d.com; H ttpOnly;
00> 20 53 61 6d 65 53 69 74  65 3d 4c 61 78 0d 0a 43 | SameSit e=Lax..C
00> 46 2d 43 61 63 68 65 2d  53 74 61 74 75 73 3a 20 |F-Cache- Status: 
00> 44 59 4e 41 4d 49 43 0d  0a 63 66 2d 72 65 71 75 |DYNAMIC. .cf-requ
00> 65 73 74 2d 69 64 3a 20  30 36 36 34 63 31 65 65 |est-id:  0664c1ee
00> 64 63 30 30 30 30 64 34  33 66 36 38 38 37 30 30 |dc0000d4 3f688700
00> 30 30 30 30 30 30 30 31  0d 0a 52 65 70 6f 72 74 |00000001 ..Report
00> 2d 54 6f 3a 20 7b 22 65  6e 64 70 6f 69 6e 74 73 |-To: {"e ndpoints
00> 22 3a 5b 7b 22 75 72 6c  22 3a 22 68 74 74 70 73 |":[{"url ":"https
00> 3a 5c 2f 5c 2f 61 2e 6e  65 6c 2e 63 6c 6f 75 64 |:\/\/a.n el.cloud
00> 66 6c 61 72 65 2e 63 6f  6d 5c 2f 72 65 70 6f 72 |flare.co m\/repor
00> 74 3f 73 3d 4e 65 75 57  66 46 50 6b 75 47 25 32 |t?s=NeuW fFPkuG%2
00> 46 4e 61 61 4f 4f 43 65  69 70 41 51 4d 59 75 53 |FNaaOOCe ipAQMYuS
00> 75 61 69 39 36 25 32 46  7a 4e 6c 61 49 6d 50 49 |uai96%2F zNlaImPI
00> 74 72 52 44 67 7a 45 4f  55 61 4a 41 6e 78 66 51 |trRDgzEO UaJAnxfQ
00> 75 47 4f 74 34 75 34 73  52 48 46 5a 65 74 49 67 |uGOt4u4s RHFZetIg
00> 34 34 7a 34 74 6c 54 53  45 32 57 62 49 70 42 38 |44z4tlTS E2WbIpB8
00> 46 58 43 36 67 71 57 52  5a 4c 43 38 4f 69 41 41 |FXC6gqWR ZLC8OiAA
00> 44 43 7a 70 59 77 58 49  34 77 25 33 44 25 33 44 |DCzpYwXI 4w%3D%3D
00> 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00 |........ ........
00> 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00 |........ ........
00> 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00 |........ ........
00> 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00 |........ ........
00> 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00 |........ ........
00> 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00 |........ ........
00> 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00 |........ ........
00> 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00 |........ ........
00> 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00 |........ ........
00> 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00 |........ ........
00> 00 00 00 00 00 00 00                             |.......      

  • Hi, Michal!

    Thank you for reporting this. I will bring the info to the developers. 

    Best regards,
    Carl Richard

  • Hi Carl,

    do you have any info or ETA when this might be fixed? It is a big problem for us, basically making the serial_lte_modem unsusable in production and therefore delaying production of nrf91 based devices.

    Best regards, Michal V.

  • Hi again, Michal.

    I have yet to receive a response from the developers and have pinged them now. I'll make sure the issue (and your corresponding SLM case) is prioritized. 

    My apologies for the delay and thank you for your patience. 

    Best regards,
    Carl Richard

  • Hi again!

    The developer requested some logs to be able to determine why the chunked responses are handled incorrectly. Could you add the following to your prj.conf: 

    CONFIG_LOG_IMMEDIATE=y
    CONFIG_NET_LOG=y
    CONFIG_NET_SOCKETS_LOG_LEVEL_DBG=n
    CONFIG_NET_HTTP_LOG_LEVEL_DBG=y


    And try to reproduce the issue? 

    Best regards,
    Carl Richard

  • OK, so I've tried that, due to various limitations (such as domain whitelisting on our SIM, DNS config etc..) I've only been able to test it with gwxcloud.com, that is not set up and returns an error. But this error goes through cloudflare, so it is returned with chunked encoding.

    "Log" from LTE link monitor:

    AT#XHTTPCCON=1,"gwxcloud.com",80#XHTTPCCON:1OKAT#XHTTPCREQ="GET","/",""OK#XHTTPCREQ:0#XHTTPCRSP:3489,0</div></body></html>0f="https://docs.microsoft.com/en-us/azure/app-service-web/app-service-web-tutorial-custom-domain">how to map an existing domain</a> to resolve this.</li>                <li>Client cache is still pointing the domain to old IP address. Clear the cache by running the command <i>ipconfig/flushdns.</i></li>            </ul>            <p>Checkout <a href="https://blogs.msdn.microsoft.com/appserviceteam/2017/08/08/faq-app-service-domain-preview-and-custom-domains/">App Service Domain FAQ</a> for more questions.</p>        </div>     5b8): Calling callback for partitioned 33 len data[0m[00:14:11.286,865] [0m<dbg> net_http.on_message_complete: (0x200215b8): -- HTTP GET response (complete) --[0m,723] [0m<dbg> net_http.on_body: (0x200215b8): Calling callback for partitioned 180 len data[0m[00:14:11.017,303] [0m<dbg> net_http.on_body: (0x200215b8): Processed 2128 length 528[0m[00:14:11.017,700] [0m<dbg> net_http.on_body: (0x200215b8): Calling callback for partitioned 528 len data[0m[00:14:11.284,210] [0m<dbg> net_http.on_body: (0x200215b8): Processed 2176 length 48[0m[00:14:11.284,606] [0m<dbg> net_http.on_body: (0x200215b8): Calling callback for partitioned 48 len data[0m[00:14:11.285,125] [0m<dbg> net_http.on_body: (0x200215b8): Processed 2752 length 576[0m[00:14:11.285,491] [0m<dbg> net_http.on_body: (0x200215b8): Calling callback for partitioned 576 len data[0m[00:14:11.286,010] [0m<dbg> net_http.on_body: (0x200215b8): Processed 2778 length 26[0m[00:14:11.286,407] [0m<dbg> net_http.on_body: (0x20021901288004468357KKK

    Log collected over J-Link:

    00> [00:13:56.049,255] <inf> at_cmd: Enqueueing response for sync call
    00> [00:13:56.049,621] <inf> at_cmd: Writing any pending command
    00> [00:13:56.049,896] <inf> at_cmd: Listening on socket
    00> [00:14:05.527,923] <inf> httpc: Attempting to connect over IPv6
    00> [00:14:05.528,625] <err> httpc: Unable to connect, errno 114
    00> [00:14:05.529,449] <inf> httpc: Attempting to connect over IPv4
    00> [00:14:06.104,309] <inf> httpc: Connected to gwxcloud.com
    00> [00:14:09.014,923] <dbg> net_http.Data to send
    00> 47 45 54 20 2f 20 48 54  54 50 2f 31 2e 31 0d 0a |GET / HT TP/1.1..
    00> 48 6f 73 74 3a 20 67 77  78 63 6c 6f 75 64 2e 63 |Host: gw xcloud.c
    00> 6f 6d 0d 0a                                      |om..             
    00> [00:14:09.016,693] <dbg> net_http.Data to send
    00> 0d 0a                                            |..               
    00> [00:14:09.017,578] <dbg> net_http.http_client_req: (0x200215b8): Sent 54 bytes
    00> [00:14:10.118,286] <dbg> net_http.on_message_begin: (0x200215b8): -- HTTP GET response (headers) --
    00> [00:14:10.118,743] <dbg> net_http.on_status: (0x200215b8): HTTP response status 404 Site Not Found
    00> [00:14:10.119,415] <dbg> net_http.print_header_field: (0x200215b8): [4] Date
    00> [00:14:10.120,056] <dbg> net_http.print_header_field: (0x200215b8): [29] Thu, 26 Nov 2020 10:39:44 GMT
    00> [00:14:10.120,758] <dbg> net_http.print_header_field: (0x200215b8): [12] Content-Type
    00> [00:14:10.121,398] <dbg> net_http.print_header_field: (0x200215b8): [9] text/html
    00> [00:14:10.122,039] <dbg> net_http.print_header_field: (0x200215b8): [17] Transfer-Encoding
    00> [00:14:10.122,680] <dbg> net_http.print_header_field: (0x200215b8): [7] chunked
    00> [00:14:10.123,291] <dbg> net_http.print_header_field: (0x200215b8): [10] Connection
    00> [00:14:10.123,931] <dbg> net_http.print_header_field: (0x200215b8): [10] keep-alive
    00> [00:14:10.124,511] <dbg> net_http.print_header_field: (0x200215b8): [10] Set-Cookie
    00> [00:14:10.125,183] <dbg> net_http.print_header_field: (0x200215b8): [127] __cfduid=d4df0e26ea5b2e8ad1dadbe95da3bc9aa1606387183; expires=Sat, 26-Dec-20 10:39:43 GMT; path=/; domain=.gwxcloud.com; HttpOn
    00> [00:14:10.126,068] <dbg> net_http.print_header_field: (0x200215b8): [15] CF-Cache-Status
    00> [00:14:10.131,835] <dbg> net_http.print_header_field: (0x200215b8): [7] DYNAMIC
    00> [00:14:10.132,324] <dbg> net_http.print_header_field: (0x200215b8): [13] cf-request-id
    00> [00:14:10.132,873] <dbg> net_http.print_header_field: (0x200215b8): [32] 06a5bc48ce0000fa18d4292000000001
    00> [00:14:10.133,392] <dbg> net_http.print_header_field: (0x200215b8): [9] Report-To
    00> [00:14:10.133,972] <dbg> net_http.print_header_field: (0x200215b8): [127] {"endpoints":[{"url":"https:\/\/a.nel.cloudflare.com\/report?s=WxfmvBeE3cOvi%2BNieDfBJUAiKLX1LXjjJy3Gv%2FAt4nx8hR2W5ko69d0fKvmC
    00> [00:14:10.135,070] <dbg> net_http.print_header_field: (0x200215b8): [23] -nel","max_age":604800}
    00> [00:14:10.135,772] <dbg> net_http.print_header_field: (0x200215b8): [3] NEL
    00> [00:14:10.136,413] <dbg> net_http.print_header_field: (0x200215b8): [39] {"report_to":"cf-nel","max_age":604800}
    00> [00:14:10.137,145] <dbg> net_http.print_header_field: (0x200215b8): [6] Server
    00> [00:14:10.137,786] <dbg> net_http.print_header_field: (0x200215b8): [10] cloudflare
    00> [00:14:10.138,397] <dbg> net_http.print_header_field: (0x200215b8): [6] CF-RAY
    00> [00:14:10.139,007] <dbg> net_http.print_header_field: (0x200215b8): [20] 5f82fcbae8d9fa18-AMS
    00> [00:14:10.139,404] <dbg> net_http.on_headers_complete: (0x200215b8): Headers complete
    00> [00:14:10.145,050] <dbg> net_http.on_body: (0x200215b8): Processed 4 length 4
    00> [00:14:10.145,385] <dbg> net_http.on_body: (0x200215b8): Calling callback for partitioned 708 len data
    00> [00:14:10.413,330] <dbg> net_http.on_body: (0x200215b8): Processed 448 length 444
    00> [00:14:10.413,757] <dbg> net_http.on_body: (0x200215b8): Calling callback for partitioned 444 len data
    00> [00:14:10.414,276] <dbg> net_http.on_body: (0x200215b8): Processed 712 length 264
    00> [00:14:10.414,642] <dbg> net_http.on_body: (0x200215b8): Calling callback for partitioned 264 len data
    00> [00:14:10.712,280] <dbg> net_http.on_body: (0x200215b8): Processed 1024 length 312
    00> [00:14:10.712,677] <dbg> net_http.on_body: (0x200215b8): Calling callback for partitioned 312 len data
    00> [00:14:10.713,226] <dbg> net_http.on_body: (0x200215b8): Processed 1420 length 396
    00> [00:14:10.713,623] <dbg> net_http.on_body: (0x200215b8): Calling callback for partitioned 396 len data
    00> [00:14:11.016,357] <dbg> net_http.on_body: (0x200215b8): Processed 1600 length 180
    00> [00:14:11.016,723] <dbg> net_http.on_body: (0x200215b8): Calling callback for partitioned 180 len data
    00> [00:14:11.017,303] <dbg> net_http.on_body: (0x200215b8): Processed 2128 length 528
    00> [00:14:11.017,700] <dbg> net_http.on_body: (0x200215b8): Calling callback for partitioned 528 len data
    00> [00:14:11.284,210] <dbg> net_http.on_body: (0x200215b8): Processed 2176 length 48
    00> [00:14:11.284,606] <dbg> net_http.on_body: (0x200215b8): Calling callback for partitioned 48 len data
    00> [00:14:11.285,125] <dbg> net_http.on_body: (0x200215b8): Processed 2752 length 576
    00> [00:14:11.285,491] <dbg> net_http.on_body: (0x200215b8): Calling callback for partitioned 576 len data
    00> [00:14:11.286,010] <dbg> net_http.on_body: (0x200215b8): Processed 2778 length 26
    00> [00:14:11.286,407] <dbg> net_http.on_body: (0x200215b8): Calling callback for partitioned 33 len data
    00> [00:14:11.286,865] <dbg> net_http.on_message_complete: (0x200215b8): -- HTTP GET response (complete) --
    00> [00:14:11.289,337] <dbg> net_http.http_client_req: (0x200215b8): Received 3489 bytes

Related