[Libwebsockets] http client: seeing delayed SSL connection

Andy Green andy at warmcat.com
Tue Feb 21 22:58:11 CET 2017



On February 22, 2017 3:31:00 AM GMT+09:00, Joel Winarske <joel.winarske at gmail.com> wrote:
>Hi Andy,
>
>I'm looking for some insight.  I'm seeing the http client delay it's
>SSL
>attempt to connect for some time.  During which I get a "connection
>refused" entry in my browser debug session.  Log below.  I was
>expecting
>the SSL session would connect immediately.
>
>A.  How does this work
>B.  How do I prevent a refused connection?

Connection Refused is probably coming because the listen socket backlog queue has been exceeded at the server.  If you are spamming it with connections it implies the server went an abnormally long while without accepting new incoming connections.

The logs you sent all happen inside 400ms so I'm not seeing any 'delay'.

I can see stuff like

>[2017/02/21 09:55:17:5916] INFO: lws_http_transaction_completed:
>wsi->more_rx_waiting=1
>[2017/02/21 09:55:17:5916] INFO: lws_http_transaction_completed:
>032333C8:
>keep-alive await new transaction

That suggests http keepalive pipelining is happening with the POSTs.  Under those conditions the wsi keeps the ah, because it sees it already has more rx waiting.  However I don't see it run out of ah (you get messages like 'adding to ah waiting list') and that doesn't stop it accepting new connections either, they are accepted and wait with POLLIN disabled until they can acquire an ah to process the http headers with.

Is it windows?  That has an ugly limit on number of sockets it can handle by default, unless you use libuv.

Otherwise dunno need more clues... it's not normal, you can spam lwsws with thousands of simultaneous connections for millions of times total without seeing this using, eg, ab on Linux.

-Andy

>
>Thanks,
>Joel
>
>[2017/02/21 09:55:17:5571] INFO: Method: POST request for '/rest/send'
>[2017/02/21 09:55:17:5576] INFO: lws_ensure_user_space: 03236950
>protocol
>02F05ED8
>/send
>[2017/02/21 09:55:17:5576] INFO: lws_read: read_ok, used 465
>[2017/02/21 09:55:17:5576] NOTICE: lws_server_socket_service: wsi
>03236950
>read 402
>
>[2017/02/21 09:55:17:5576] NOTICE: lws_spa_create: Created SPA 032831C0
>[2017/02/21 09:55:17:5576] NOTICE: Send Request:
>[2017/02/21 09:55:17:5576] NOTICE: url: https://uas-api.inrix.com/...
>[2017/02/21 09:55:17:5576] NOTICE: method: POST
>[2017/02/21 09:55:17:5576] NOTICE: mimetype: application/json
>[2017/02/21 09:55:17:5576] NOTICE: payload: {...}
>[2017/02/21 09:55:17:5576] NOTICE:  Using SSL
>[2017/02/21 09:55:17:5576] NOTICE:  Selfsigned certs allowed
>[2017/02/21 09:55:17:5581] NOTICE:  Skipping peer cert hostname check
>[2017/02/21 09:55:17:5581] NOTICE: using https mode (non-ws)
>[2017/02/21 09:55:17:5581] NOTICE: POST mode
>[2017/02/21 09:55:17:5581] NOTICE: http client: connecting
>[2017/02/21 09:55:17:5581] INFO: lws_ensure_user_space: 032F3058
>protocol
>02F05ED8
>[2017/02/21 09:55:17:5581] INFO: lws_header_table_attach: wsi 032F3058:
>ah
>00000000 (tsi 0, count = 2) in
>[2017/02/21 09:55:17:5581] INFO: lws_header_table_attach: wsi 032F3058:
>ah
>011F5478: count 3 (on exit)
>[2017/02/21 09:55:17:5581] NOTICE: lws_client_connect_2: address
>uas-api.inrix.com
>[2017/02/21 09:55:17:5891] INFO: lws_client_connect_via_info: created
>child
>032F3058 of parent 03236950
>[2017/02/21 09:55:17:5896] NOTICE: lws_client_connect_via_info
>sucessful
>wsi=32f3058
>[2017/02/21 09:55:17:5896] INFO: lws_read: read_ok, used 402
>[2017/02/21 09:55:17:5896] INFO: lws_header_table_attach: wsi 03236C60:
>ah
>00000000 (tsi 0, count = 3) in
>[2017/02/21 09:55:17:5896] INFO: lws_header_table_attach: wsi 03236C60:
>ah
>011F6290: count 4 (on exit)
>[2017/02/21 09:55:17:5896] INFO: No upgrade
>[2017/02/21 09:55:17:5896] INFO: lws_ensure_user_space: 03236C60
>protocol
>02F05E30
>[2017/02/21 09:55:17:5896] INFO: lws_ensure_user_space: 03236C60
>protocol
>pss 0, user_space=00000000
>[2017/02/21 09:55:17:5896] INFO: Method: GET request for
>'/ui/apps/system/inrix.system.home/images/music-icon.svg'
>[2017/02/21 09:55:17:5901] ERR: 169.254.225.161 - -
>[21/Feb/2017:09:55:17
>-0800] "GET /ui/apps/system/inrix.system.home/images/music-icon.svg
>http/1.1" 304 68 Mozilla/5.0 (Linux; Android 6.0; Nexus 5 Build/MRA58N)
>AppleWebKit/537.36 (KHTML, like Gecko) Chrome/56.0.2924.87 Mobile
>Safari[2017/02/21 09:55:17:5901] INFO: lws_http_transaction_completed:
>wsi
>03236C60
>[2017/02/21 09:55:17:5901] INFO: lws_ensure_user_space: 03236C60
>protocol
>02F05E30
>[2017/02/21 09:55:17:5901] INFO: lws_ensure_user_space: 03236C60
>protocol
>pss 0, user_space=00000000
>[2017/02/21 09:55:17:5901] INFO: lws_http_transaction_completed:
>wsi->more_rx_waiting=0
>[2017/02/21 09:55:17:5901] INFO: lws_header_table_detach: wsi 03236C60:
>ah
>011F6290 (tsi=0, count = 4)
>[2017/02/21 09:55:17:5901] INFO: lws_header_table_detach: wsi 03236C60:
>ah
>011F6290 (tsi=0, count = 3)
>[2017/02/21 09:55:17:5901] INFO: lws_http_transaction_completed:
>03236C60:
>keep-alive await new transaction
>[2017/02/21 09:55:17:5901] INFO: lws_read: read_ok, used 440
>[2017/02/21 09:55:17:5901] INFO: lws_header_table_attach: wsi 032333C8:
>ah
>00000000 (tsi 0, count = 3) in
>[2017/02/21 09:55:17:5901] INFO: lws_header_table_attach: wsi 032333C8:
>ah
>011F6290: count 4 (on exit)
>[2017/02/21 09:55:17:5901] INFO: No upgrade
>[2017/02/21 09:55:17:5901] INFO: lws_ensure_user_space: 032333C8
>protocol
>02F05E30
>[2017/02/21 09:55:17:5901] INFO: lws_ensure_user_space: 032333C8
>protocol
>pss 0, user_space=00000000
>[2017/02/21 09:55:17:5901] INFO: Method: POST request for '/prop/get'
>[2017/02/21 09:55:17:5906] INFO: lws_ensure_user_space: 032333C8
>protocol
>02F05ED8
>/get
>[2017/02/21 09:55:17:5906] NOTICE: lws_spa_create: Created SPA 03282EA8
>[2017/02/21 09:55:17:5906] INFO: lws_read: read_ok, used 519
>[2017/02/21 09:55:17:5906] INFO: lws_header_table_attach: wsi 03236C60:
>ah
>00000000 (tsi 0, count = 4) in
>[2017/02/21 09:55:17:5911] INFO: lws_header_table_attach: wsi 03236C60:
>ah
>011F7EC0: count 5 (on exit)
>[2017/02/21 09:55:17:5911] ERR: 169.254.225.161 - -
>[21/Feb/2017:09:55:17
>-0800] "POST /prop/get http/1.1" 200 175 Mozilla/5.0 (Linux; Android
>6.0;
>Nexus 5 Build/MRA58N) AppleWebKit/537.36 (KHTML, like Gecko)
>Chrome/56.0.2924.87 Mobile Safari/537.36
>[2017/02/21 09:55:17:5911] INFO: lws_http_transaction_completed: wsi
>032333C8
>[2017/02/21 09:55:17:5911] INFO: lws_ensure_user_space: 032333C8
>protocol
>02F05E30
>[2017/02/21 09:55:17:5911] INFO: lws_ensure_user_space: 032333C8
>protocol
>pss 0, user_space=00000000
>[2017/02/21 09:55:17:5916] INFO: lws_http_transaction_completed:
>wsi->more_rx_waiting=1
>[2017/02/21 09:55:17:5916] INFO: lws_http_transaction_completed:
>032333C8:
>keep-alive await new transaction
>[2017/02/21 09:55:17:5951] INFO: No upgrade
>[2017/02/21 09:55:17:5956] INFO: lws_ensure_user_space: 032333C8
>protocol
>02F05E30
>[2017/02/21 09:55:17:5956] INFO: lws_ensure_user_space: 032333C8
>protocol
>pss 0, user_space=00000000
>[2017/02/21 09:55:17:5956] INFO: Method: POST request for '/prop/get'
>[2017/02/21 09:55:17:5956] INFO: lws_ensure_user_space: 032333C8
>protocol
>02F05ED8
>/get
>[2017/02/21 09:55:17:5956] INFO: lws_read: read_ok, used 463
>[2017/02/21 09:55:17:5956] NOTICE: lws_server_socket_service: wsi
>032333C8
>read 55
>
>[2017/02/21 09:55:17:5956] NOTICE: lws_spa_create: Created SPA 03283168
>[2017/02/21 09:55:17:5961] INFO: lws_read: read_ok, used 55
>[2017/02/21 09:55:17:5961] ERR: 169.254.225.161 - -
>[21/Feb/2017:09:55:17
>-0800] "POST /prop/get http/1.1" 200 262 Mozilla/5.0 (Linux; Android
>6.0;
>Nexus 5 Build/MRA58N) AppleWebKit/537.36 (KHTML, like Gecko)
>Chrome/56.0.2924.87 Mobile Safari/537.36
>[2017/02/21 09:55:17:5961] INFO: lws_http_transaction_completed: wsi
>032333C8
>[2017/02/21 09:55:17:5961] INFO: lws_ensure_user_space: 032333C8
>protocol
>02F05E30
>[2017/02/21 09:55:17:5961] INFO: lws_ensure_user_space: 032333C8
>protocol
>pss 0, user_space=00000000
>[2017/02/21 09:55:17:5961] INFO: lws_http_transaction_completed:
>wsi->more_rx_waiting=0
>[2017/02/21 09:55:17:5966] INFO: lws_header_table_detach: wsi 032333C8:
>ah
>011F6290 (tsi=0, count = 5)
>[2017/02/21 09:55:17:5966] INFO: lws_header_table_detach: wsi 032333C8:
>ah
>011F6290 (tsi=0, count = 4)
>[2017/02/21 09:55:17:5966] INFO: lws_http_transaction_completed:
>032333C8:
>keep-alive await new transaction
>[2017/02/21 09:55:17:6021] INFO: lws_header_table_attach: wsi 032333C8:
>ah
>00000000 (tsi 0, count = 4) in
>[2017/02/21 09:55:17:6021] INFO: lws_header_table_attach: wsi 032333C8:
>ah
>011F6290: count 5 (on exit)
>[2017/02/21 09:55:17:6021] INFO: No upgrade
>[2017/02/21 09:55:17:6021] INFO: lws_ensure_user_space: 032333C8
>protocol
>02F05E30
>[2017/02/21 09:55:17:6021] INFO: lws_ensure_user_space: 032333C8
>protocol
>pss 0, user_space=00000000
>[2017/02/21 09:55:17:6021] INFO: Method: POST request for '/prop/get'
>[2017/02/21 09:55:17:6026] INFO: lws_ensure_user_space: 032333C8
>protocol
>02F05ED8
>/get
>[2017/02/21 09:55:17:6026] NOTICE: lws_spa_create: Created SPA 03283530
>[2017/02/21 09:55:17:6031] INFO: lws_read: read_ok, used 526
>[2017/02/21 09:55:17:6031] ERR: 169.254.225.161 - -
>[21/Feb/2017:09:55:17
>-0800] "POST /prop/get http/1.1" 200 202 Mozilla/5.0 (Linux; Android
>6.0;
>Nexus 5 Build/MRA58N) AppleWebKit/537.36 (KHTML, like Gecko)
>Chrome/56.0.2924.87 Mobile Safari/537.36
>[2017/02/21 09:55:17:6031] INFO: lws_http_transaction_completed: wsi
>032333C8
>[2017/02/21 09:55:17:6031] INFO: lws_ensure_user_space: 032333C8
>protocol
>02F05E30
>[2017/02/21 09:55:17:6031] INFO: lws_ensure_user_space: 032333C8
>protocol
>pss 0, user_space=00000000
>[2017/02/21 09:55:17:6031] INFO: lws_http_transaction_completed:
>wsi->more_rx_waiting=1
>[2017/02/21 09:55:17:6031] INFO: lws_http_transaction_completed:
>032333C8:
>keep-alive await new transaction
>[2017/02/21 09:55:17:6076] INFO: No upgrade
>[2017/02/21 09:55:17:6081] INFO: lws_ensure_user_space: 032333C8
>protocol
>02F05E30
>[2017/02/21 09:55:17:6081] INFO: lws_ensure_user_space: 032333C8
>protocol
>pss 0, user_space=00000000
>[2017/02/21 09:55:17:6081] INFO: Method: POST request for '/prop/set'
>[2017/02/21 09:55:17:6081] INFO: lws_ensure_user_space: 032333C8
>protocol
>02F05ED8
>/set
>[2017/02/21 09:55:17:6081] INFO: lws_read: read_ok, used 463
>[2017/02/21 09:55:17:6081] NOTICE: lws_server_socket_service: wsi
>032333C8
>read 84
>
>[2017/02/21 09:55:17:6081] NOTICE: lws_spa_create: Created SPA 03283690
>[2017/02/21 09:55:17:6086] INFO: lws_read: read_ok, used 84
>[2017/02/21 09:55:17:6086] ERR: 169.254.225.161 - -
>[21/Feb/2017:09:55:17
>-0800] "POST /prop/set http/1.1" 200 136 Mozilla/5.0 (Linux; Android
>6.0;
>Nexus 5 Build/MRA58N) AppleWebKit/537.36 (KHTML, like Gecko)
>Chrome/56.0.2924.87 Mobile Safari/537.36
>[2017/02/21 09:55:17:6086] INFO: lws_http_transaction_completed: wsi
>032333C8
>[2017/02/21 09:55:17:6086] INFO: lws_ensure_user_space: 032333C8
>protocol
>02F05E30
>[2017/02/21 09:55:17:6086] INFO: lws_ensure_user_space: 032333C8
>protocol
>pss 0, user_space=00000000
>[2017/02/21 09:55:17:6086] INFO: lws_http_transaction_completed:
>wsi->more_rx_waiting=0
>[2017/02/21 09:55:17:6091] INFO: lws_header_table_detach: wsi 032333C8:
>ah
>011F6290 (tsi=0, count = 5)
>[2017/02/21 09:55:17:6091] INFO: lws_header_table_detach: wsi 032333C8:
>ah
>011F6290 (tsi=0, count = 4)
>[2017/02/21 09:55:17:6091] INFO: lws_http_transaction_completed:
>032333C8:
>keep-alive await new transaction
>[2017/02/21 09:55:17:6091] NOTICE: lws_client_connect_2: address
>uas-api.inrix.com
>[2017/02/21 09:55:17:6126] INFO: lws_header_table_attach: wsi 032333C8:
>ah
>00000000 (tsi 0, count = 4) in
>[2017/02/21 09:55:17:6126] INFO: lws_header_table_attach: wsi 032333C8:
>ah
>011F6290: count 5 (on exit)
>[2017/02/21 09:55:17:6131] INFO: No upgrade
>[2017/02/21 09:55:17:6131] INFO: lws_ensure_user_space: 032333C8
>protocol
>02F05E30
>[2017/02/21 09:55:17:6131] INFO: lws_ensure_user_space: 032333C8
>protocol
>pss 0, user_space=00000000
>[2017/02/21 09:55:17:6131] INFO: Method: POST request for '/prop/set'
>[2017/02/21 09:55:17:6131] INFO: lws_ensure_user_space: 032333C8
>protocol
>02F05ED8
>/set
>[2017/02/21 09:55:17:6131] NOTICE: lws_spa_create: Created SPA 03283218
>[2017/02/21 09:55:17:6136] INFO: lws_read: read_ok, used 652
>[2017/02/21 09:55:17:6136] ERR: 169.254.225.161 - -
>[21/Feb/2017:09:55:17
>-0800] "POST /prop/set http/1.1" 200 136 Mozilla/5.0 (Linux; Android
>6.0;
>Nexus 5 Build/MRA58N) AppleWebKit/537.36 (KHTML, like Gecko)
>Chrome/56.0.2924.87 Mobile Safari/537.36
>[2017/02/21 09:55:17:6136] INFO: lws_http_transaction_completed: wsi
>032333C8
>[2017/02/21 09:55:17:6136] INFO: lws_ensure_user_space: 032333C8
>protocol
>02F05E30
>[2017/02/21 09:55:17:6136] INFO: lws_ensure_user_space: 032333C8
>protocol
>pss 0, user_space=00000000
>[2017/02/21 09:55:17:6136] INFO: lws_http_transaction_completed:
>wsi->more_rx_waiting=1
>[2017/02/21 09:55:17:6136] INFO: lws_http_transaction_completed:
>032333C8:
>keep-alive await new transaction
>[2017/02/21 09:55:17:6201] INFO: No upgrade
>[2017/02/21 09:55:17:6201] INFO: lws_ensure_user_space: 032333C8
>protocol
>02F05E30
>[2017/02/21 09:55:17:6201] INFO: lws_ensure_user_space: 032333C8
>protocol
>pss 0, user_space=00000000
>[2017/02/21 09:55:17:6201] INFO: Method: POST request for '/prop/set'
>[2017/02/21 09:55:17:6206] INFO: lws_ensure_user_space: 032333C8
>protocol
>02F05ED8
>/set
>[2017/02/21 09:55:17:6206] INFO: lws_read: read_ok, used 464
>[2017/02/21 09:55:17:6206] NOTICE: lws_server_socket_service: wsi
>032333C8
>read 110
>
>[2017/02/21 09:55:17:6206] NOTICE: lws_spa_create: Created SPA 032833D0
>[2017/02/21 09:55:17:6211] INFO: lws_read: read_ok, used 110
>[2017/02/21 09:55:17:6211] ERR: 169.254.225.161 - -
>[21/Feb/2017:09:55:17
>-0800] "POST /prop/set http/1.1" 200 136 Mozilla/5.0 (Linux; Android
>6.0;
>Nexus 5 Build/MRA58N) AppleWebKit/537.36 (KHTML, like Gecko)
>Chrome/56.0.2924.87 Mobile Safari/537.36
>[2017/02/21 09:55:17:6211] INFO: lws_http_transaction_completed: wsi
>032333C8
>[2017/02/21 09:55:17:6211] INFO: lws_ensure_user_space: 032333C8
>protocol
>02F05E30
>[2017/02/21 09:55:17:6211] INFO: lws_ensure_user_space: 032333C8
>protocol
>pss 0, user_space=00000000
>[2017/02/21 09:55:17:6211] INFO: lws_http_transaction_completed:
>wsi->more_rx_waiting=0
>[2017/02/21 09:55:17:6211] INFO: lws_header_table_detach: wsi 032333C8:
>ah
>011F6290 (tsi=0, count = 5)
>[2017/02/21 09:55:17:6211] INFO: lws_header_table_detach: wsi 032333C8:
>ah
>011F6290 (tsi=0, count = 4)
>[2017/02/21 09:55:17:6216] INFO: lws_http_transaction_completed:
>032333C8:
>keep-alive await new transaction
>[2017/02/21 09:55:17:6326] NOTICE: lws_ssl_client_connect2: SSL_connect
>says -1
>[2017/02/21 09:55:17:6326] INFO: SSL_connect WANT_READ... retrying
>[2017/02/21 09:55:17:6341] NOTICE: lws_ssl_client_connect2: SSL_connect
>says -1
>[2017/02/21 09:55:17:6341] INFO: SSL_connect WANT_READ... retrying
>[2017/02/21 09:55:17:6381] NOTICE: lws_ssl_client_connect2: SSL_connect
>says -1
>[2017/02/21 09:55:17:6381] INFO: SSL_connect WANT_READ... retrying
>[2017/02/21 09:55:17:6581] NOTICE: lws_ssl_client_connect2: SSL_connect
>says 1
>[2017/02/21 09:55:17:8831] INFO: lws_ensure_user_space: 032F3058
>protocol
>02F05ED8
>[2017/02/21 09:55:17:8831] INFO: lws_ensure_user_space: 032F3058
>protocol
>pss 11308, user_space=032F5038
>[2017/02/21 09:55:17:8831] NOTICE:
>lws_client_interpret_server_handshake:
>incoming content length 1244
>[2017/02/21 09:55:17:8836] INFO: lws_header_table_detach: wsi 032F3058:
>ah
>011F5478 (tsi=0, count = 4)
>[2017/02/21 09:55:17:8836] INFO: lws_header_table_detach: wsi 032F3058:
>ah
>011F5478 (tsi=0, count = 3)
>[2017/02/21 09:55:17:8836] NOTICE:
>lws_client_interpret_server_handshake:
>client connection up
>[2017/02/21 09:55:17:8836] INFO: ssl buffered read
>[2017/02/21 09:55:17:8836] INFO: lws_http_transaction_completed_client:
>032F3058: keep-alive await new transaction
>[2017/02/21 09:55:17:8841] INFO: lws_close_free_wsi: real
>just_kill_connection: 032F3058 (sockfd 604)
>[2017/02/21 09:55:17:8841] INFO: remove_wsi_socket_from_fds: removing
>same
>prot wsi 032F3058
>[2017/02/21 09:55:17:8841] INFO: ah det due to close
>[2017/02/21 09:55:17:8841] INFO: lws_header_table_detach: wsi 032F3058:
>ah
>00000000 (tsi=0, count = 3)
>[2017/02/21 09:55:17:8846] INFO: lws_header_table_detach: wsi 032F3058:
>ah
>00000000 (tsi=0, count = 3)
>[2017/02/21 09:55:17:9061] NOTICE: lws_server_socket_service: wsi
>03236950
>read 465
>
>
>[2017/02/21 09:55:17:9061] INFO: lws_read: read_ok, used 0
>[2017/02/21 09:55:17:9066] NOTICE: lws_server_socket_service: wsi
>03236950
>read 441



More information about the Libwebsockets mailing list