Removal of old HTTP API is causing errors and faults

[mbolivar]

Something is not quite right with d1675bf, which removed the old HTTP API. The removal is causing regressions on an existing application which was already using the new API.

The following are observed regressions when using the new-style API routine http_client_send_get_req() on an nRF52 using BTLE 6lo to provide a network interface:

• Errnos -12 and -58
• Application hangs followed by usage faults

The application sends an HTTP GET, followed by a POST. The POST fails. The first bad commit was identified as d1675bf by git bisect.

Testing with the commit reverted restores the working behavior.

With extra logging enabled, the usage faults happened twice in a row (I didn't see the errno cases with a logging config. I saw both usage faults and errnos without extra net logging.). Here are details.

Logs were obtained with:

CONFIG_NET_LOG=y
CONFIG_NET_DEBUG_HTTP=y
CONFIG_SYS_LOG_NET_LEVEL=4

• Logs with d1675bf present: https://gist.github.com/mbolivar/781fe92bf28ea33c120e4bc995bfe3d3
• Logs with it reverted: https://gist.github.com/mbolivar/e8215bb618c972ab2e1c554af8bbbc90

Note the following differences in POST response status:

• Bad request with the commit: https://gist.github.com/mbolivar/781fe92bf28ea33c120e4bc995bfe3d3#file-gistfile1-txt-L132
• OK without it: https://gist.github.com/mbolivar/e8215bb618c972ab2e1c554af8bbbc90#file-gistfile1-txt-L123

Note that the host, mgmt.foundries.io, is not a real host, nor is it net-addressable. The Bluetooth device at the other end of the link is acting as a gateway to another host on the LAN. The gateway is proxying HTTP traffic to this host based a preconfigured address.

The [fota/hawkbit] lines are from the application, an Eclipse hawkBit client, some of which were deleted as not relevant. The [http] and [http/client] lines are from Zephyr. The numbers before the log domains are timestamps (based on uptime).

[jukkar]

I have been trying to reproduce this with samples/net/http_client sample app but so far has not been successful. I am using frdm_k64 and ethernet so slightly different setup but the used hw should not matter much here.

Couple of questions:

• When you revert the offending commit, do you start to use the old API or do you always use the new API? The offending commit just removes API so it is weird if it could cause issues like this.
• Would you happen to have a simple application that could demonstrate this issue? It is a bit difficult to debug this from logs only.

[jukkar]

BTW, could you activate also net-app debugging, the option is CONFIG_NET_DEBUG_APP=y and paste the log somewhere.

[jukkar]

I managed to get this output from http-client sample when running the sample without any net stack debugging so perhaps this is a timing issue, the error code is same as yours so could be related issue.

[http-client] [INF] main: --------Sending 20 sync request--------
[http-client] [INF] do_sync_http_req: [1] Send /index.html
[http-client] [INF] do_sync_http_req: HTTP server response status: OK
[http-client] [INF] do_sync_http_req: HTTP body: 178 bytes, expected: 178 bytes
[http-client] [INF] do_sync_http_req: [1] Send /post_test.php
[http-client] [ERR] do_sync_http_req: Cannot send POST request (-12)
[http-client] [INF] main: Done!

[jukkar]

@rveerama1 is fixing http issue in 7273b9a
That commit needs to split in smaller pieces thou so it cannot be applied yet. Anyway looks like related issue to me. The root cause is that sometimes we are not able to select correct net_context in net_app which then causes this -ENOMEM (12) to be returned and possibly could cause NULL pointer access (although I was not able to trigger anything like this).

[pfalcon]

sometimes we are not able to select correct net_context in net_app which then causes this -ENOMEM (12)

Can this issue be handled/ticketed separately? Not selecting correct net_context apparently should't lead to ENOMEM, but e.g. to EINVAL or more specific error. That sounds like an opposite of #5864, where EINVAL was returned instead of ENOMEM. (Unless I'm missing what "correct net_context" means above.)

[mbolivar]

I'll respond to questions in this first comment, and provide some additional infomation in a follow-up.

When you revert the offending commit, do you start to use the old API or do you always use the new API? The offending commit just removes API so it is weird if it could cause issues like this.

We only ever use the new API in our application.

Would you happen to have a simple application that could demonstrate this issue? It is a bit difficult to debug this from logs only.

I don't right now, no, sorry. If this remains an issue I will try to make a smaller reproducer, though it sounds like you may have some leads.

BTW, could you activate also net-app debugging, the option is CONFIG_NET_DEBUG_APP=y and paste the log somewhere.

https://gist.github.com/mbolivar/a064e022112b0334106d40a8f1ce877b

@rveerama1 is fixing http issue in 7273b9a

This looks like an API break as well, right

[mbolivar]

As noted in my initial report, the regression involves a "Bad request" response from the server.

To look into this further, I captured the traffic and followed the HTTP stream in wireshark. There are indeed different traffic patterns on the wire with and without the revert.

• Regressed case, without revert (note the "Bad request" appears after a broken JSON fragment, and there appears to be a retransmision of the entire JSON packet afterwards): https://imgur.com/a/LCDyk

• Working case, with revert: https://imgur.com/a/WOQwu

I've still got the .pcap files lying around if the gory details are useful to you.

[jukkar]

@rveerama1 is fixing http issue in 7273b9a

This looks like an API break as well, right

Yes, we need to add a parameter to a existing function to fix the issue @rveerama1 found out, it is not certain if this really fixes the issue you are seeing.

[rveerama1]

@mbolivar @jukkar I have noticed some issues with #5035. To fix http related issue, I proposed some changes #6167. Please take a look.