[Libwebsockets] Possible bugs - minimal-http-client-multi example

Dorit Mari Dorit.Mari at audiocodes.com
Wed Sep 16 16:21:08 CEST 2020


Hi,

I found 3 possible problems when running the minimal example "minimal-examples\http-client\minimal-http-client-multi", which I'd like to report.
I used version v4.1.0, on PC running Windows 10.


  1.  Crash:

Without any code changes, when running "minimal-http-client-multi" example with cmd line input:
--no-tls --h1 --port 80 --path /api/MVC/status/current --server 10.33.70.85 -c 3
lws crashes.
It sends 3 Get requests, and receives 401 response for all 3.
The crash also happens with "-c 1" (only 1 Get request is sent, and lws receives 1 401 response).

the 401 response looks like:

HTTP/1.1 401 Unauthorized
WWW-Authenticate: Basic realm="Realm1"
Content-Type: application/json
Transfer-Encoding: chunked
Server: Web-Server
Connection: close

The crash is in __lws_close_free_wsi_final(struct lws *wsi), in the clause
                if (wsi->a.vhost)
                                wsi->a.vhost->protocols[0].callback(wsi, LWS_CALLBACK_WSI_DESTROY,
                                                                                                  wsi->user_space, NULL, 0);


The console output from the run is:

[2020/09/16 14:38:56:1630] U: LWS minimal http client [-s (staggered)] [-p (pipeline)]
[2020/09/16 14:38:56:1690] U:    [--h1 (http/1 only)] [-l (localhost)] [-d <logs>]
[2020/09/16 14:38:56:1730] U:    [-n (numbered)] [--post]
[2020/09/16 14:38:56:1760] N: LWS: 4.1.99-v4.1.0-12-g18d4ac4e, loglevel 1031
[2020/09/16 14:38:56:1790] N: NET CLI SRV H1 H2 WS IPv6-absent
[2020/09/16 14:38:56:4493] U: started connection 0067f630: idx 0 (/api/MVC/status/current)
[2020/09/16 14:38:56:4582] U: started connection 00680f18: idx 1 (/api/MVC/status/current)
[2020/09/16 14:38:56:4652] U: started connection 00682618: idx 2 (/api/MVC/status/current)
[2020/09/16 14:38:56:4702] U: callback_http: doing GET flow
[2020/09/16 14:38:56:4742] U: callback_http: doing GET flow
[2020/09/16 14:38:56:4772] U: callback_http: doing GET flow
[2020/09/16 14:38:56:4832] U: LWS_CALLBACK_ESTABLISHED_CLIENT_HTTP: idx: 0, resp 401
[2020/09/16 14:38:56:5111] U: LWS_CALLBACK_ESTABLISHED_CLIENT_HTTP: idx: 1, resp 401
[2020/09/16 14:38:56:5161] U: LWS_CALLBACK_ESTABLISHED_CLIENT_HTTP: idx: 2, resp 401
[2020/09/16 14:38:56:5391] E: Done: failed: 3


If I change the code, and add in "case LWS_CALLBACK_CLIENT_APPEND_HANDSHAKE_HEADER" an Authorization header, so that instead of 401, we receive 200 OK responses -> there is no crash.




  1.  HTTP Requests aren't sent when pipelining in http 1.1 is used, without "staggering" (the command line input doesn't include "-s"):

I tried sending 4 Get requests, with pipelining enabled, with http 1.1, no "staggering":
with cmd line input:
--no-tls --h1 -p --port 80 --path /api/MVC/status/current --server 10.33.70.85 -c 4

==>> no HTTP request was sent out. The server does listen at the IP address and port I set, and would respond with 200 OK to a Get request to the path I set.

console output:

[2020/09/16 14:50:34:4482] U: LWS minimal http client [-s (staggered)] [-p (pipeline)]
[2020/09/16 14:50:34:4561] U:    [--h1 (http/1 only)] [-l (localhost)] [-d <logs>]
[2020/09/16 14:50:34:4611] U:    [-n (numbered)] [--post]
[2020/09/16 14:50:34:4631] N: LWS: 4.1.99-v4.1.0-12-g18d4ac4e, loglevel 1031
[2020/09/16 14:50:34:4661] N: NET CLI SRV H1 H2 WS IPv6-absent
[2020/09/16 14:50:34:7544] U: started connection 0067f660: idx 0 (/api/MVC/status/current)
[2020/09/16 14:50:34:7613] N: lws_vhost_active_conns: apply 00680f48 to txn queue on 0067f660 state 0x10000202
[2020/09/16 14:50:34:7673] U: started connection 00680f48: idx 1 (/api/MVC/status/current)
[2020/09/16 14:50:34:7703] N: lws_vhost_active_conns: apply 00682620 to txn queue on 0067f660 state 0x10000202
[2020/09/16 14:50:34:7753] U: started connection 00682620: idx 2 (/api/MVC/status/current)
[2020/09/16 14:50:34:7803] N: lws_vhost_active_conns: apply 00683cf8 to txn queue on 0067f660 state 0x10000202
[2020/09/16 14:50:34:7853] U: started connection 00683cf8: idx 3 (/api/MVC/status/current)
[2020/09/16 14:50:34:7893] E: CLIENT_CONNECTION_ERROR: Unable to connect
[2020/09/16 14:50:34:7932] E: Done: failed: 4
[2020/09/16 14:50:34:7952] U: Duration: 6ms
[2020/09/16 14:50:34:8631] U: Exiting with 1
Press <RETURN> to close this window...


If I do use Staggering (this is the only change from above scenario which fails), so the cmd line input is:
--no-tls -s --h1 -p --port 80 --path /api/MVC/status/current --server 10.33.70.85 -c 4
All 4 Get requests succeed.

The only code change I made to minimal-http-client-multi.c was in callback_http(), to add Authorization header (since my server expects it):
                case LWS_CALLBACK_CLIENT_APPEND_HANDSHAKE_HEADER:
                                /*
                                * Tell lws we are going to send the body next...
                                */
                                if (posting && !lws_http_is_redirected_to_get(wsi)) {
                                                lwsl_user("%s: doing POST flow\n", __func__);
                                                lws_client_http_body_pending(wsi, 1);
                                                lws_callback_on_writable(wsi);
                                } else
                                {
                                                lwsl_user("%s: doing GET flow\n", __func__);
                                                unsigned char **p = (unsigned char **)in, *end = (*p) + len;
                                                char buff[128];
                                                if (lws_http_basic_auth_gen("Admin", "Admin", buff, sizeof(buff)))
                                                                break;
                                                if (lws_add_http_header_by_token(wsi, WSI_TOKEN_HTTP_AUTHORIZATION,
                                                                                (unsigned char *)buff, (int)strlen(buff), p, end))
                                                                return -1;

                                }
                                break;



  1.  I am not sure that pipelining in http 1.1  actually works:

I changed the "staggering" code, so lws will only wait 1 millisecond between requests, like this:

static void
stagger_cb(lws_sorted_usec_list_t *sul)
{
                lws_usec_t next;

                /*
                * open the connections at 100ms intervals, with the
                * last one being after 1s, testing both queuing, and
                * direct H2 stream addition stability
                */
                lws_try_client_connection(&i, stagger_idx++);

                if (stagger_idx == count)
                                return;

                next = 1 * LWS_US_PER_MS;

                lws_sul_schedule(context, 0, &sul_stagger, stagger_cb, next);
}

and also added a print log in "case LWS_CALLBACK_CLIENT_APPEND_HANDSHAKE_HEADER":

                case LWS_CALLBACK_CLIENT_APPEND_HANDSHAKE_HEADER:
                                lwsl_user("LWS_CALLBACK_CLIENT_APPEND_HANDSHAKE_HEADER %p: idx %d\n",
                                                  wsi, idx);


and used cmd line input:
--no-tls -s --h1 -p --port 80 --path /api/MVC/status/current --server 10.33.70.55 -c 6

6 Get requests were sent and succeeded, but they were sent serially. Each request was sent only after the previous request completed
successfully with 200 OK - I saw this in wireshark capture. In the console output, I also saw that lws_client_connect_via_info()
("started connection ..." line) was called 5 times before the first request succeeded. But each request is done serially.
When pipelining is enabled, next request should be sent before the response for the last request is received.

The Console output:

[2020/09/16 15:30:48:7920] U: LWS minimal http client [-s (staggered)] [-p (pipeline)]
[2020/09/16 15:30:48:8030] U:    [--h1 (http/1 only)] [-l (localhost)] [-d <logs>]
[2020/09/16 15:30:48:8070] U:    [-n (numbered)] [--post]
[2020/09/16 15:30:48:8109] N: LWS: 4.1.99-v4.1.0-12-g18d4ac4e, loglevel 1031
[2020/09/16 15:30:48:8139] N: NET CLI SRV H1 H2 WS IPv6-absent
[2020/09/16 15:30:49:1939] U: started connection 0067f690: idx 0 (/api/MVC/status/current)
[2020/09/16 15:30:49:2009] U: LWS_CALLBACK_CLIENT_APPEND_HANDSHAKE_HEADER 0067f690: idx 0
[2020/09/16 15:30:49:2059] U: callback_http: doing GET flow
[2020/09/16 15:30:49:2089] N: lws_vhost_active_conns: apply 00680f78 to txn queue on 0067f690 state 0x1000020b
[2020/09/16 15:30:49:2159] U: started connection 00680f78: idx 1 (/api/MVC/status/current)
[2020/09/16 15:30:49:2248] N: lws_vhost_active_conns: apply 00682650 to txn queue on 0067f690 state 0x1000020b
[2020/09/16 15:30:49:2318] U: started connection 00682650: idx 2 (/api/MVC/status/current)
[2020/09/16 15:30:49:2358] U: LWS_CALLBACK_ESTABLISHED_CLIENT_HTTP: idx: 0, resp 200
[2020/09/16 15:30:49:2388] N: lws_vhost_active_conns: apply 00683d28 to txn queue on 0067f690 state 0x10000119
[2020/09/16 15:30:49:2448] U: started connection 00683d28: idx 3 (/api/MVC/status/current)
[2020/09/16 15:30:49:2538] N: lws_vhost_active_conns: apply 00685370 to txn queue on 0067f690 state 0x10000119
[2020/09/16 15:30:49:2597] U: started connection 00685370: idx 4 (/api/MVC/status/current)
[2020/09/16 15:30:49:2647] U: RECEIVE_CLIENT_HTTP_READ: conn 0: read 219
[2020/09/16 15:30:49:2697] U: LWS_CALLBACK_COMPLETED_CLIENT_HTTP 0067f690: idx 0
[2020/09/16 15:30:49:2747] N: _lws_generic_transaction_completed_active_conn: pipeline queue passed wsi 0067f690 on to queued wsi 00680f78
[2020/09/16 15:30:49:2827] U: LWS_CALLBACK_CLIENT_APPEND_HANDSHAKE_HEADER 00680f78: idx 1
[2020/09/16 15:30:49:2877] U: callback_http: doing GET flow
[2020/09/16 15:30:49:2907] N: lws_vhost_active_conns: apply 00686a48 to txn queue on 00680f78 state 0x1000020b
[2020/09/16 15:30:49:2966] U: started connection 00686a48: idx 5 (/api/MVC/status/current)
[2020/09/16 15:30:49:3086] U: LWS_CALLBACK_ESTABLISHED_CLIENT_HTTP: idx: 1, resp 200
[2020/09/16 15:30:49:3335] U: RECEIVE_CLIENT_HTTP_READ: conn 1: read 219
[2020/09/16 15:30:49:3365] U: LWS_CALLBACK_COMPLETED_CLIENT_HTTP 00680f78: idx 1
[2020/09/16 15:30:49:3395] N: _lws_generic_transaction_completed_active_conn: pipeline queue passed wsi 00680f78 on to queued wsi 00682650
[2020/09/16 15:30:49:3465] U: LWS_CALLBACK_CLIENT_APPEND_HANDSHAKE_HEADER 00682650: idx 2
[2020/09/16 15:30:49:3505] U: callback_http: doing GET flow
[2020/09/16 15:30:49:3854] U: LWS_CALLBACK_ESTABLISHED_CLIENT_HTTP: idx: 2, resp 200
[2020/09/16 15:30:49:4233] U: RECEIVE_CLIENT_HTTP_READ: conn 2: read 219
[2020/09/16 15:30:49:4433] U: LWS_CALLBACK_COMPLETED_CLIENT_HTTP 00682650: idx 2
[2020/09/16 15:30:49:4492] N: _lws_generic_transaction_completed_active_conn: pipeline queue passed wsi 00682650 on to queued wsi 00683d28
[2020/09/16 15:30:49:4552] U: LWS_CALLBACK_CLIENT_APPEND_HANDSHAKE_HEADER 00683d28: idx 3
[2020/09/16 15:30:49:4582] U: callback_http: doing GET flow
[2020/09/16 15:30:49:4881] U: LWS_CALLBACK_ESTABLISHED_CLIENT_HTTP: idx: 3, resp 200
[2020/09/16 15:30:49:5161] U: RECEIVE_CLIENT_HTTP_READ: conn 3: read 219
[2020/09/16 15:30:49:5290] U: LWS_CALLBACK_COMPLETED_CLIENT_HTTP 00683d28: idx 3
[2020/09/16 15:30:49:5480] N: _lws_generic_transaction_completed_active_conn: pipeline queue passed wsi 00683d28 on to queued wsi 00685370
[2020/09/16 15:30:49:5609] U: LWS_CALLBACK_CLIENT_APPEND_HANDSHAKE_HEADER 00685370: idx 4
[2020/09/16 15:30:49:5659] U: callback_http: doing GET flow
[2020/09/16 15:30:49:5929] U: LWS_CALLBACK_ESTABLISHED_CLIENT_HTTP: idx: 4, resp 200
[2020/09/16 15:30:49:6178] U: RECEIVE_CLIENT_HTTP_READ: conn 4: read 219
[2020/09/16 15:30:49:6338] U: LWS_CALLBACK_COMPLETED_CLIENT_HTTP 00685370: idx 4
[2020/09/16 15:30:49:6527] N: _lws_generic_transaction_completed_active_conn: pipeline queue passed wsi 00685370 on to queued wsi 00686a48
[2020/09/16 15:30:49:6677] U: LWS_CALLBACK_CLIENT_APPEND_HANDSHAKE_HEADER 00686a48: idx 5
[2020/09/16 15:30:49:6747] U: callback_http: doing GET flow
[2020/09/16 15:30:49:7086] U: LWS_CALLBACK_ESTABLISHED_CLIENT_HTTP: idx: 5, resp 200
[2020/09/16 15:30:49:7285] U: RECEIVE_CLIENT_HTTP_READ: conn 5: read 219
[2020/09/16 15:30:49:7325] U: LWS_CALLBACK_COMPLETED_CLIENT_HTTP 00686a48: idx 5
[2020/09/16 15:30:49:7365] U: Done: all OK
[2020/09/16 15:30:49:7405] U: Duration: 650ms
[2020/09/16 15:30:49:8133] U: Exiting with 0
Press <RETURN> to close this window...


Thanks,
Dorit
This email and any files transmitted with it are confidential material. They are intended solely for the use of the designated individual or entity to whom they are addressed. If the reader of this message is not the intended recipient, you are hereby notified that any dissemination, use, distribution or copying of this communication is strictly prohibited and may be unlawful.

If you have received this email in error please immediately notify the sender and delete or destroy any copy of this message
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://libwebsockets.org/pipermail/libwebsockets/attachments/20200916/0e639d43/attachment-0001.htm>


More information about the Libwebsockets mailing list