[Libwebsockets] http client: seeing delayed SSL connection

Joel Winarske joel.winarske at gmail.com
Tue Feb 21 19:31:00 CET 2017


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?


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
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://libwebsockets.org/pipermail/libwebsockets/attachments/20170221/fafce17b/attachment-0001.html>


More information about the Libwebsockets mailing list