libwebsocket over SSL connectivity issue, connection closed due to LWS_SSL_CAPABLE_ERROR

[rtcote]

Hello. I have a libwebsockets client that was based on the example test client attempting to connect to a basic ws ssl server written in python over localhost with a self signed cert. I can connect to this server when ssl is disabled on both sides (i.e. the python server and libwebsockets are using ws instead of wss) and everything works as expected. When I enable SSL on both sides I see that libwebsockets connection closing with the log message "Closing when error" which based on the source indicates LWS_SSL_CAPABLE_ERROR which corresponds to an SSL_read() returning -1. I'm not sure what this means though and when I enable debug level logging I get flooded with call-back messages. Any ideas on what I can do to further troubleshoot this? Based on the a wireshark trace, I see the libwebsockets client closing the connection to the python server with a fin ack. Any help would be appreciated. Thank you.

[2017/02/16 10:43:49:1398] NOTICE: Initial logging level 15 [2017/02/16 10:43:49:1398] NOTICE: Libwebsockets version: 2.1.1 rcote@ubuntuvm- [2017/02/16 10:43:49:1398] NOTICE: IPV6 not compiled in [2017/02/16 10:43:49:1398] NOTICE: libev support not compiled in [2017/02/16 10:43:49:1398] NOTICE: libuv support not compiled in [2017/02/16 10:43:49:1398] INFO: LWS_DEF_HEADER_LEN : 4096 [2017/02/16 10:43:49:1398] INFO: LWS_MAX_PROTOCOLS : 5 [2017/02/16 10:43:49:1398] INFO: LWS_MAX_SMP : 32 [2017/02/16 10:43:49:1398] INFO: SPEC_LATEST_SUPPORTED : 13 [2017/02/16 10:43:49:1398] INFO: sizeof (*info) : 320 [2017/02/16 10:43:49:1398] INFO: SYSTEM_RANDOM_FILEPATH: '/dev/urandom' [2017/02/16 10:43:49:1398] INFO: default timeout (secs): 20 [2017/02/16 10:43:49:1399] NOTICE: Threads: 1 each 1024 fds [2017/02/16 10:43:49:1399] INFO: mem: context: 9272 bytes (5176 ctx + (1 thr x 4096)) [2017/02/16 10:43:49:1399] INFO: mem: http hdr rsvd: 30720 bytes (1 thr x (4096 + 3584) x 4)) [2017/02/16 10:43:49:1399] INFO: mem: pollfd map: 8192 [2017/02/16 10:43:49:1399] NOTICE: mem: platform fd map: 8192 bytes [2017/02/16 10:43:49:1399] NOTICE: Compiled with OpenSSL support [2017/02/16 10:43:49:1474] NOTICE: Creating Vhost 'default' port -1, 1 protocols, IPv6 off [2017/02/16 10:43:49:1478] INFO: SSL options 0x3520004 [2017/02/16 10:43:49:1492] INFO: LWS_MAX_EXTENSIONS_ACTIVE: 2 [2017/02/16 10:43:49:1492] NOTICE: mem: per-conn: 512 bytes + protocol rx buf [2017/02/16 10:43:49:1492] NOTICE: canonical_hostname = ubuntuvm [2017/02/16 10:43:49:6523] NOTICE: lws_protocol_init [2017/02/16 10:43:49:6526] INFO: lws_header_table_attach: wsi 0x23de620: ah (nil) (tsi 0, count = 0) in [2017/02/16 10:43:49:6527] INFO: lws_header_table_attach: wsi 0x23de620: ah 0x23b61e0: count 1 (on exit) [2017/02/16 10:43:54:6924] INFO: lws_header_table_attach: wsi 0x23f1690: ah (nil) (tsi 0, count = 1) in [2017/02/16 10:43:54:6924] INFO: lws_header_table_attach: wsi 0x23f1690: ah 0x23b6fe0: count 2 (on exit) [2017/02/16 10:43:59:6938] NOTICE: accepting self-signed certificate [2017/02/16 10:43:59:6955] INFO: lws_ensure_user_space: 0x23de620 protocol 0x6497c0 [2017/02/16 10:43:59:6956] INFO: lws_ensure_user_space: 0x23de620 protocol pss 0, user_space=(nil) [2017/02/16 10:43:59:6956] INFO: lws_header_table_detach: wsi 0x23de620: ah 0x23b61e0 (tsi=0, count = 2) [2017/02/16 10:43:59:6956] NOTICE: lws_header_table_detach: wsi 0x23de620: ah held 10s, ah.rxpos 0, ah.rxlen 0, mode/state 40 7,wsi->more_rx_waiting 0 [2017/02/16 10:43:59:6956] INFO: lws_header_table_detach: wsi 0x23de620: ah 0x23b61e0 (tsi=0, count = 1) [2017/02/16 10:43:59:6956] INFO: Allocating client RX buffer 4112 [2017/02/16 10:44:04:7037] INFO: Closing when error [2017/02/16 10:44:04:7046] INFO: lws_close_free_wsi: shutting down connection: 0x23de620 (sock 8, state 5) [2017/02/16 10:44:04:7047] INFO: Closing when error [2017/02/16 10:44:04:7047] INFO: lws_close_free_wsi: real just_kill_connection: 0x23de620 (sockfd 8) [2017/02/16 10:44:04:7047] INFO: remove_wsi_socket_from_fds: removing same prot wsi 0x23de620 [2017/02/16 10:44:04:7048] INFO: have prev 0x23da1e0, setting him to our next (nil) [2017/02/16 10:44:04:7123] INFO: ah det due to close [2017/02/16 10:44:04:7123] INFO: lws_header_table_detach: wsi 0x23de620: ah (nil) (tsi=0, count = 1) [2017/02/16 10:44:04:7123] INFO: lws_header_table_detach: wsi 0x23de620: ah (nil) (tsi=0, count = 1) [2017/02/16 10:44:04:7147] NOTICE: accepting self-signed certificate [2017/02/16 10:44:04:7148] INFO: lws_header_table_attach: wsi 0x23f4160: ah (nil) (tsi 0, count = 1) in [2017/02/16 10:44:04:7148] INFO: lws_header_table_attach: wsi 0x23f4160: ah 0x23b61e0: count 2 (on exit) [2017/02/16 10:44:09:7161] INFO: lws_ensure_user_space: 0x23f1690 protocol 0x6497c0 [2017/02/16 10:44:09:7162] INFO: lws_ensure_user_space: 0x23f1690 protocol pss 0, user_space=(nil) [2017/02/16 10:44:09:7163] INFO: lws_header_table_detach: wsi 0x23f1690: ah 0x23b6fe0 (tsi=0, count = 2) [2017/02/16 10:44:09:7163] NOTICE: lws_header_table_detach: wsi 0x23f1690: ah held 15s, ah.rxpos 0, ah.rxlen 0, mode/state 40 7,wsi->more_rx_waiting 0 [2017/02/16 10:44:09:7163] INFO: lws_header_table_detach: wsi 0x23f1690: ah 0x23b6fe0 (tsi=0, count = 1) [2017/02/16 10:44:09:7163] INFO: Allocating client RX buffer 4112 [2017/02/16 10:44:09:7199] INFO: Closing when error [2017/02/16 10:44:09:7199] INFO: lws_close_free_wsi: shutting down connection: 0x23f1690 (sock 9, state 5) [2017/02/16 10:44:09:7200] INFO: Closing when error [2017/02/16 10:44:09:7200] INFO: lws_close_free_wsi: real just_kill_connection: 0x23f1690 (sockfd 9) [2017/02/16 10:44:09:7200] INFO: remove_wsi_socket_from_fds: removing same prot wsi 0x23f1690 [2017/02/16 10:44:09:7200] INFO: have prev 0x23da1e0, setting him to our next (nil) [2017/02/16 10:44:09:7205] INFO: ah det due to close [2017/02/16 10:44:09:7205] INFO: lws_header_table_detach: wsi 0x23f1690: ah (nil) (tsi=0, count = 1) [2017/02/16 10:44:09:7205] INFO: lws_header_table_detach: wsi 0x23f1690: ah (nil) (tsi=0, count = 1) [2017/02/16 10:44:09:7206] INFO: lws_header_table_attach: wsi 0x23df650: ah (nil) (tsi 0, count = 1) in [2017/02/16 10:44:09:7206] INFO: lws_header_table_attach: wsi 0x23df650: ah 0x23b6fe0: count 2 (on exit) [2017/02/16 10:44:14:7278] NOTICE: accepting self-signed certificate [2017/02/16 10:44:14:7280] INFO: lws_header_table_attach: wsi 0x23f29b0: ah (nil) (tsi 0, count = 2) in [2017/02/16 10:44:14:7280] INFO: lws_header_table_attach: wsi 0x23f29b0: ah 0x23b7de0: count 3 (on exit) [2017/02/16 10:44:19:7289] INFO: lws_ensure_user_space: 0x23f4160 protocol 0x6497c0 [2017/02/16 10:44:19:7289] INFO: lws_ensure_user_space: 0x23f4160 protocol pss 0, user_space=(nil) [2017/02/16 10:44:19:7289] INFO: lws_header_table_detach: wsi 0x23f4160: ah 0x23b61e0 (tsi=0, count = 3) [2017/02/16 10:44:19:7290] NOTICE: lws_header_table_detach: wsi 0x23f4160: ah held 15s, ah.rxpos 0, ah.rxlen 0, mode/state 40 7,wsi->more_rx_waiting 0 [2017/02/16 10:44:19:7290] INFO: lws_header_table_detach: wsi 0x23f4160: ah 0x23b61e0 (tsi=0, count = 2) [2017/02/16 10:44:19:7290] INFO: Allocating client RX buffer 4112 [2017/02/16 10:44:19:7324] INFO: Closing when error [2017/02/16 10:44:19:7324] INFO: lws_close_free_wsi: shutting down connection: 0x23f4160 (sock 8, state 5) [2017/02/16 10:44:19:7325] INFO: Closing when error [2017/02/16 10:44:19:7325] INFO: lws_close_free_wsi: real just_kill_connection: 0x23f4160 (sockfd 8) [2017/02/16 10:44:19:7325] INFO: remove_wsi_socket_from_fds: removing same prot wsi 0x23f4160 [2017/02/16 10:44:19:7325] INFO: have prev 0x23da1e0, setting him to our next (nil) [2017/02/16 10:44:19:7327] INFO: ah det due to close [2017/02/16 10:44:19:7327] INFO: lws_header_table_detach: wsi 0x23f4160: ah (nil) (tsi=0, count = 2) [2017/02/16 10:44:19:7327] INFO: lws_header_table_detach: wsi 0x23f4160: ah (nil) (tsi=0, count = 2) [2017/02/16 10:44:19:7332] INFO: lws_header_table_attach: wsi 0x23f1850: ah (nil) (tsi 0, count = 2) in [2017/02/16 10:44:19:7332] INFO: lws_header_table_attach: wsi 0x23f1850: ah 0x23b61e0: count 3 (on exit) [2017/02/16 10:44:24:7344] NOTICE: accepting self-signed certificate [2017/02/16 10:44:24:7359] INFO: lws_ensure_user_space: 0x23df650 protocol 0x6497c0 [2017/02/16 10:44:24:7361] INFO: lws_ensure_user_space: 0x23df650 protocol pss 0, user_space=(nil) [2017/02/16 10:44:24:7362] INFO: lws_header_table_detach: wsi 0x23df650: ah 0x23b6fe0 (tsi=0, count = 3) [2017/02/16 10:44:24:7362] NOTICE: lws_header_table_detach: wsi 0x23df650: ah held 15s, ah.rxpos 0, ah.rxlen 0, mode/state 40 7,wsi->more_rx_waiting 0 [2017/02/16 10:44:24:7362] INFO: lws_header_table_detach: wsi 0x23df650: ah 0x23b6fe0 (tsi=0, count = 2) [2017/02/16 10:44:24:7363] INFO: Allocating client RX buffer 4112 [2017/02/16 10:44:29:7419] INFO: Closing when error [2017/02/16 10:44:29:7419] INFO: lws_close_free_wsi: shutting down connection: 0x23df650 (sock 9, state 5) [2017/02/16 10:44:29:7419] INFO: Closing when error [2017/02/16 10:44:29:7419] INFO: lws_close_free_wsi: real just_kill_connection: 0x23df650 (sockfd 9) [2017/02/16 10:44:29:7419] INFO: remove_wsi_socket_from_fds: removing same prot wsi 0x23df650 [2017/02/16 10:44:29:7419] INFO: have prev 0x23da1e0, setting him to our next (nil) [2017/02/16 10:44:29:7421] INFO: ah det due to close [2017/02/16 10:44:29:7421] INFO: lws_header_table_detach: wsi 0x23df650: ah (nil) (tsi=0, count = 2) [2017/02/16 10:44:29:7421] INFO: lws_header_table_detach: wsi 0x23df650: ah (nil) (tsi=0, count = 2) [2017/02/16 10:44:29:7426] INFO: lws_header_table_attach: wsi 0x23f40b0: ah (nil) (tsi 0, count = 2) in [2017/02/16 10:44:29:7426] INFO: lws_header_table_attach: wsi 0x23f40b0: ah 0x23b6fe0: count 3 (on exit) [2017/02/16 10:44:34:7435] NOTICE: accepting self-signed certificate [2017/02/16 10:44:34:7450] INFO: lws_ensure_user_space: 0x23f1850 protocol 0x6497c0 [2017/02/16 10:44:34:7450] INFO: lws_ensure_user_space: 0x23f1850 protocol pss 0, user_space=(nil) [2017/02/16 10:44:34:7451] INFO: lws_header_table_detach: wsi 0x23f1850: ah 0x23b61e0 (tsi=0, count = 3) [2017/02/16 10:44:34:7451] NOTICE: lws_header_table_detach: wsi 0x23f1850: ah held 15s, ah.rxpos 0, ah.rxlen 0, mode/state 40 7,wsi->more_rx_waiting 0 [2017/02/16 10:44:34:7451] INFO: lws_header_table_detach: wsi 0x23f1850: ah 0x23b61e0 (tsi=0, count = 2) [2017/02/16 10:44:34:7451] INFO: Allocating client RX buffer 4112 [2017/02/16 10:44:39:7506] INFO: Closing when error [2017/02/16 10:44:39:7511] INFO: lws_close_free_wsi: shutting down connection: 0x23f1850 (sock 8, state 5) [2017/02/16 10:44:39:7543] INFO: Closing when error [2017/02/16 10:44:39:7543] INFO: lws_close_free_wsi: real just_kill_connection: 0x23f1850 (sockfd 8) [2017/02/16 10:44:39:7543] INFO: remove_wsi_socket_from_fds: removing same prot wsi 0x23f1850 [2017/02/16 10:44:39:7543] INFO: have prev 0x23da1e0, setting him to our next (nil) [2017/02/16 10:44:39:7545] INFO: ah det due to close [2017/02/16 10:44:39:7545] INFO: lws_header_table_detach: wsi 0x23f1850: ah (nil) (tsi=0, count = 2) [2017/02/16 10:44:39:7545] INFO: lws_header_table_detach: wsi 0x23f1850: ah (nil) (tsi=0, count = 2) [2017/02/16 10:44:39:7547] INFO: lws_header_table_attach: wsi 0x2406e90: ah (nil) (tsi 0, count = 2) in [2017/02/16 10:44:39:7547] INFO: lws_header_table_attach: wsi 0x2406e90: ah 0x23b61e0: count 3 (on exit) ^C[2017/02/16 10:44:40:9894] NOTICE: wsi 0x23f29b0: TIMEDOUT WAITING on 8 (did hdr 0, ah 0x23b7de0, wl 0, pfd events 1) [2017/02/16 10:44:40:9899] INFO: lws_close_free_wsi: real just_kill_connection: 0x23f29b0 (sockfd 10) [2017/02/16 10:44:40:9899] INFO: remove_wsi_socket_from_fds: removing same prot wsi 0x23f29b0 [2017/02/16 10:44:40:9900] INFO: ah det due to close [2017/02/16 10:44:40:9900] INFO: lws_header_table_detach: wsi 0x23f29b0: ah 0x23b7de0 (tsi=0, count = 3) [2017/02/16 10:44:40:9900] NOTICE: lws_header_table_detach: wsi 0x23f29b0: ah held 26s, ah.rxpos 0, ah.rxlen 0, mode/state 39 4,wsi->more_rx_waiting 0 [2017/02/16 10:44:40:9900] INFO: lws_header_table_detach: wsi 0x23f29b0: ah 0x23b7de0 (tsi=0, count = 2) [2017/02/16 10:44:40:9903] NOTICE: accepting self-signed certificate [2017/02/16 10:44:40:9904] NOTICE: lws_context_destroy [2017/02/16 10:44:40:9905] INFO: lws_close_free_wsi: real just_kill_connection: 0x2406e90 (sockfd 8) [2017/02/16 10:44:40:9905] INFO: remove_wsi_socket_from_fds: removing same prot wsi 0x2406e90 [2017/02/16 10:44:40:9908] INFO: ah det due to close [2017/02/16 10:44:40:9908] INFO: lws_header_table_detach: wsi 0x2406e90: ah 0x23b61e0 (tsi=0, count = 2) [2017/02/16 10:44:40:9908] INFO: lws_header_table_detach: wsi 0x2406e90: ah 0x23b61e0 (tsi=0, count = 1) [2017/02/16 10:44:40:9908] INFO: lws_close_free_wsi: real just_kill_connection: 0x23f40b0 (sockfd 9) [2017/02/16 10:44:40:9908] INFO: remove_wsi_socket_from_fds: removing same prot wsi 0x23f40b0 [2017/02/16 10:44:40:9911] INFO: ah det due to close [2017/02/16 10:44:40:9911] INFO: lws_header_table_detach: wsi 0x23f40b0: ah 0x23b6fe0 (tsi=0, count = 1) [2017/02/16 10:44:40:9911] NOTICE: lws_header_table_detach: wsi 0x23f40b0: ah held 11s, ah.rxpos 0, ah.rxlen 0, mode/state 40 4,wsi->more_rx_waiting 0 [2017/02/16 10:44:40:9911] INFO: lws_header_table_detach: wsi 0x23f40b0: ah 0x23b6fe0 (tsi=0, count = 0)

[lws-team]

Couple of ideas... can you try it on lws master? It seems the error paths should dump the openssl error stack.

Also does the test client show the same problem?

[rtcote]

Hi Andy,

I'll try it with the master branch here shortly. Using the test client with v2.1.1 release, I am seeing the same behavior that I see with my version of the client. I'll get back to you shortly. Thank you!

./libwebsockets-test-client wss://localhost:8081 --ssl -d 15 [2017/02/16 12:04:10:1132] NOTICE: libwebsockets test client - license LGPL2.1+SLE [2017/02/16 12:04:10:1133] NOTICE: (C) Copyright 2010-2016 Andy Green andy@warmcat.com [2017/02/16 12:04:10:1134] NOTICE: Using SSL [2017/02/16 12:04:10:1134] NOTICE: Selfsigned certs allowed [2017/02/16 12:04:10:1134] NOTICE: Skipping peer cert hostname check [2017/02/16 12:04:10:1134] NOTICE: Initial logging level 15 [2017/02/16 12:04:10:1135] NOTICE: Libwebsockets version: 2.1.1 rcote@ubuntuvm-v2.0.0-209-gd317a96 [2017/02/16 12:04:10:1135] NOTICE: IPV6 not compiled in [2017/02/16 12:04:10:1135] NOTICE: libev support not compiled in [2017/02/16 12:04:10:1135] NOTICE: libuv support not compiled in [2017/02/16 12:04:10:1135] INFO: LWS_DEF_HEADER_LEN : 4096 [2017/02/16 12:04:10:1135] INFO: LWS_MAX_PROTOCOLS : 5 [2017/02/16 12:04:10:1136] INFO: LWS_MAX_SMP : 32 [2017/02/16 12:04:10:1136] INFO: SPEC_LATEST_SUPPORTED : 13 [2017/02/16 12:04:10:1136] INFO: sizeof (*info) : 320 [2017/02/16 12:04:10:1136] INFO: SYSTEM_RANDOM_FILEPATH: '/dev/urandom' [2017/02/16 12:04:10:1137] INFO: default timeout (secs): 20 [2017/02/16 12:04:10:1138] NOTICE: Threads: 1 each 1024 fds [2017/02/16 12:04:10:1138] INFO: mem: context: 9272 bytes (5176 ctx + (1 thr x 4096)) [2017/02/16 12:04:10:1138] INFO: mem: http hdr rsvd: 30720 bytes (1 thr x (4096 + 3584) x 4)) [2017/02/16 12:04:10:1139] INFO: mem: pollfd map: 8192 [2017/02/16 12:04:10:1140] NOTICE: mem: platform fd map: 8192 bytes [2017/02/16 12:04:10:1141] NOTICE: Compiled with OpenSSL support [2017/02/16 12:04:10:1229] NOTICE: Creating Vhost 'default' port -1, 2 protocols, IPv6 off [2017/02/16 12:04:10:1248] INFO: SSL options 0x3520004 [2017/02/16 12:04:10:1263] INFO: LWS_MAX_EXTENSIONS_ACTIVE: 2 [2017/02/16 12:04:10:1263] NOTICE: mem: per-conn: 512 bytes + protocol rx buf [2017/02/16 12:04:10:1263] NOTICE: canonical_hostname = ubuntuvm [2017/02/16 12:04:10:1263] NOTICE: using wss mode (ws) [2017/02/16 12:04:10:1263] NOTICE: dumb: connecting [2017/02/16 12:04:10:1263] NOTICE: lws_protocol_init [2017/02/16 12:04:10:1264] INFO: lws_header_table_attach: wsi 0x1c30b40: ah (nil) (tsi 0, count = 0) in [2017/02/16 12:04:10:1264] INFO: lws_header_table_attach: wsi 0x1c30b40: ah 0x1c09cf0: count 1 (on exit) [2017/02/16 12:04:10:1288] NOTICE: mirror: connecting [2017/02/16 12:04:10:1288] INFO: lws_header_table_attach: wsi 0x1c31b70: ah (nil) (tsi 0, count = 1) in [2017/02/16 12:04:10:1289] INFO: lws_header_table_attach: wsi 0x1c31b70: ah 0x1c0aaf0: count 2 (on exit) [2017/02/16 12:04:10:1932] NOTICE: accepting self-signed certificate [2017/02/16 12:04:10:1962] INFO: lws_client_int_s_hs: WSI_TOKEN_PROTOCOL is null [2017/02/16 12:04:10:1962] INFO: lws_ensure_user_space: 0x1c30b40 protocol 0x6304e0 [2017/02/16 12:04:10:1962] INFO: lws_ensure_user_space: 0x1c30b40 protocol pss 0, user_space=(nil) [2017/02/16 12:04:10:1962] INFO: lws_header_table_detach: wsi 0x1c30b40: ah 0x1c09cf0 (tsi=0, count = 2) [2017/02/16 12:04:10:1962] INFO: lws_header_table_detach: wsi 0x1c30b40: ah 0x1c09cf0 (tsi=0, count = 1) [2017/02/16 12:04:10:1962] INFO: Allocating client RX buffer 36 [2017/02/16 12:04:10:1962] INFO: dumb: LWS_CALLBACK_CLIENT_ESTABLISHED [2017/02/16 12:04:15:2126] INFO: Closing when error [2017/02/16 12:04:15:2126] INFO: lws_close_free_wsi: shutting down connection: 0x1c30b40 (sock 6, state 5) [2017/02/16 12:04:15:2127] INFO: Closing when error [2017/02/16 12:04:15:2127] INFO: lws_close_free_wsi: real just_kill_connection: 0x1c30b40 (sockfd 6) [2017/02/16 12:04:15:2127] INFO: remove_wsi_socket_from_fds: removing same prot wsi 0x1c30b40 [2017/02/16 12:04:15:2127] INFO: have prev 0x1c2e1f0, setting him to our next (nil) [2017/02/16 12:04:15:2127] NOTICE: dumb: LWS_CALLBACK_CLOSED [2017/02/16 12:04:15:2128] INFO: ah det due to close [2017/02/16 12:04:15:2128] INFO: lws_header_table_detach: wsi 0x1c30b40: ah (nil) (tsi=0, count = 1) [2017/02/16 12:04:15:2128] INFO: lws_header_table_detach: wsi 0x1c30b40: ah (nil) (tsi=0, count = 1) [2017/02/16 12:04:15:2128] NOTICE: dumb: connecting [2017/02/16 12:04:15:2128] INFO: lws_header_table_attach: wsi 0x1c30b40: ah (nil) (tsi 0, count = 1) in [2017/02/16 12:04:15:2128] INFO: lws_header_table_attach: wsi 0x1c30b40: ah 0x1c09cf0: count 2 (on exit) [2017/02/16 12:04:15:2764] NOTICE: accepting self-signed certificate [2017/02/16 12:04:15:2768] INFO: lws_client_int_s_hs: WSI_TOKEN_PROTOCOL is null [2017/02/16 12:04:15:2768] INFO: lws_ensure_user_space: 0x1c31b70 protocol 0x6304e0 [2017/02/16 12:04:15:2768] INFO: lws_ensure_user_space: 0x1c31b70 protocol pss 0, user_space=(nil) [2017/02/16 12:04:15:2768] INFO: lws_header_table_detach: wsi 0x1c31b70: ah 0x1c0aaf0 (tsi=0, count = 2) [2017/02/16 12:04:15:2768] NOTICE: lws_header_table_detach: wsi 0x1c31b70: ah held 5s, ah.rxpos 0, ah.rxlen 0, mode/state 40 7,wsi->more_rx_waiting 0 [2017/02/16 12:04:15:2768] INFO: lws_header_table_detach: wsi 0x1c31b70: ah 0x1c0aaf0 (tsi=0, count = 1) [2017/02/16 12:04:15:2768] INFO: Allocating client RX buffer 36 [2017/02/16 12:04:15:2768] INFO: dumb: LWS_CALLBACK_CLIENT_ESTABLISHED [2017/02/16 12:04:20:2817] INFO: Closing when error [2017/02/16 12:04:20:2818] INFO: lws_close_free_wsi: shutting down connection: 0x1c31b70 (sock 7, state 5) [2017/02/16 12:04:20:2819] INFO: Closing when error [2017/02/16 12:04:20:2819] INFO: lws_close_free_wsi: real just_kill_connection: 0x1c31b70 (sockfd 7) [2017/02/16 12:04:20:2820] INFO: remove_wsi_socket_from_fds: removing same prot wsi 0x1c31b70 [2017/02/16 12:04:20:2820] INFO: have prev 0x1c2e1f0, setting him to our next (nil) [2017/02/16 12:04:20:2820] NOTICE: dumb: LWS_CALLBACK_CLOSED [2017/02/16 12:04:20:2822] INFO: ah det due to close [2017/02/16 12:04:20:2823] INFO: lws_header_table_detach: wsi 0x1c31b70: ah (nil) (tsi=0, count = 1) [2017/02/16 12:04:20:2824] INFO: lws_header_table_detach: wsi 0x1c31b70: ah (nil) (tsi=0, count = 1) [2017/02/16 12:04:20:2824] NOTICE: dumb: connecting [2017/02/16 12:04:20:2824] INFO: lws_header_table_attach: wsi 0x1c50ec0: ah (nil) (tsi 0, count = 1) in [2017/02/16 12:04:20:2825] INFO: lws_header_table_attach: wsi 0x1c50ec0: ah 0x1c0aaf0: count 2 (on exit) [2017/02/16 12:04:20:3299] NOTICE: accepting self-signed certificate [2017/02/16 12:04:20:3306] INFO: lws_client_int_s_hs: WSI_TOKEN_PROTOCOL is null [2017/02/16 12:04:20:3306] INFO: lws_ensure_user_space: 0x1c30b40 protocol 0x6304e0 [2017/02/16 12:04:20:3306] INFO: lws_ensure_user_space: 0x1c30b40 protocol pss 0, user_space=(nil) [2017/02/16 12:04:20:3306] INFO: lws_header_table_detach: wsi 0x1c30b40: ah 0x1c09cf0 (tsi=0, count = 2) [2017/02/16 12:04:20:3306] NOTICE: lws_header_table_detach: wsi 0x1c30b40: ah held 5s, ah.rxpos 0, ah.rxlen 0, mode/state 40 7,wsi->more_rx_waiting 0 [2017/02/16 12:04:20:3306] INFO: lws_header_table_detach: wsi 0x1c30b40: ah 0x1c09cf0 (tsi=0, count = 1) [2017/02/16 12:04:20:3306] INFO: Allocating client RX buffer 36 [2017/02/16 12:04:20:3306] INFO: dumb: LWS_CALLBACK_CLIENT_ESTABLISHED [2017/02/16 12:04:25:3382] INFO: Closing when error [2017/02/16 12:04:25:3383] INFO: lws_close_free_wsi: shutting down connection: 0x1c30b40 (sock 6, state 5) [2017/02/16 12:04:25:3384] INFO: Closing when error [2017/02/16 12:04:25:3384] INFO: lws_close_free_wsi: real just_kill_connection: 0x1c30b40 (sockfd 6) [2017/02/16 12:04:25:3384] INFO: remove_wsi_socket_from_fds: removing same prot wsi 0x1c30b40 [2017/02/16 12:04:25:3385] INFO: have prev 0x1c2e1f0, setting him to our next (nil) [2017/02/16 12:04:25:3386] NOTICE: dumb: LWS_CALLBACK_CLOSED [2017/02/16 12:04:25:3387] INFO: ah det due to close [2017/02/16 12:04:25:3387] INFO: lws_header_table_detach: wsi 0x1c30b40: ah (nil) (tsi=0, count = 1) [2017/02/16 12:04:25:3388] INFO: lws_header_table_detach: wsi 0x1c30b40: ah (nil) (tsi=0, count = 1) [2017/02/16 12:04:25:3388] NOTICE: dumb: connecting [2017/02/16 12:04:25:3388] INFO: lws_header_table_attach: wsi 0x1c31f10: ah (nil) (tsi 0, count = 1) in [2017/02/16 12:04:25:3389] INFO: lws_header_table_attach: wsi 0x1c31f10: ah 0x1c09cf0: count 2 (on exit) [2017/02/16 12:04:25:3900] NOTICE: accepting self-signed certificate [2017/02/16 12:04:25:3909] INFO: lws_client_int_s_hs: WSI_TOKEN_PROTOCOL is null [2017/02/16 12:04:25:3910] INFO: lws_ensure_user_space: 0x1c50ec0 protocol 0x6304e0 [2017/02/16 12:04:25:3910] INFO: lws_ensure_user_space: 0x1c50ec0 protocol pss 0, user_space=(nil) [2017/02/16 12:04:25:3910] INFO: lws_header_table_detach: wsi 0x1c50ec0: ah 0x1c0aaf0 (tsi=0, count = 2) [2017/02/16 12:04:25:3910] NOTICE: lws_header_table_detach: wsi 0x1c50ec0: ah held 5s, ah.rxpos 0, ah.rxlen 0, mode/state 40 7,wsi->more_rx_waiting 0 [2017/02/16 12:04:25:3911] INFO: lws_header_table_detach: wsi 0x1c50ec0: ah 0x1c0aaf0 (tsi=0, count = 1) [2017/02/16 12:04:25:3911] INFO: Allocating client RX buffer 36 [2017/02/16 12:04:25:3911] INFO: dumb: LWS_CALLBACK_CLIENT_ESTABLISHED [2017/02/16 12:04:30:3982] INFO: Closing when error [2017/02/16 12:04:30:3982] INFO: lws_close_free_wsi: shutting down connection: 0x1c50ec0 (sock 7, state 5) [2017/02/16 12:04:30:3990] INFO: Closing when error [2017/02/16 12:04:30:3991] INFO: lws_close_free_wsi: real just_kill_connection: 0x1c50ec0 (sockfd 7) [2017/02/16 12:04:30:3991] INFO: remove_wsi_socket_from_fds: removing same prot wsi 0x1c50ec0 [2017/02/16 12:04:30:3991] INFO: have prev 0x1c2e1f0, setting him to our next (nil) [2017/02/16 12:04:30:3992] NOTICE: dumb: LWS_CALLBACK_CLOSED [2017/02/16 12:04:30:3993] INFO: ah det due to close [2017/02/16 12:04:30:3993] INFO: lws_header_table_detach: wsi 0x1c50ec0: ah (nil) (tsi=0, count = 1) [2017/02/16 12:04:30:3993] INFO: lws_header_table_detach: wsi 0x1c50ec0: ah (nil) (tsi=0, count = 1) [2017/02/16 12:04:30:3994] NOTICE: dumb: connecting [2017/02/16 12:04:30:3994] INFO: lws_header_table_attach: wsi 0x1c4f8f0: ah (nil) (tsi 0, count = 1) in [2017/02/16 12:04:30:3994] INFO: lws_header_table_attach: wsi 0x1c4f8f0: ah 0x1c0aaf0: count 2 (on exit) [2017/02/16 12:04:30:4434] NOTICE: accepting self-signed certificate [2017/02/16 12:04:30:4440] INFO: lws_client_int_s_hs: WSI_TOKEN_PROTOCOL is null [2017/02/16 12:04:30:4441] INFO: lws_ensure_user_space: 0x1c31f10 protocol 0x6304e0 [2017/02/16 12:04:30:4441] INFO: lws_ensure_user_space: 0x1c31f10 protocol pss 0, user_space=(nil) [2017/02/16 12:04:30:4441] INFO: lws_header_table_detach: wsi 0x1c31f10: ah 0x1c09cf0 (tsi=0, count = 2) [2017/02/16 12:04:30:4442] NOTICE: lws_header_table_detach: wsi 0x1c31f10: ah held 5s, ah.rxpos 0, ah.rxlen 0, mode/state 40 7,wsi->more_rx_waiting 0 [2017/02/16 12:04:30:4442] INFO: lws_header_table_detach: wsi 0x1c31f10: ah 0x1c09cf0 (tsi=0, count = 1) [2017/02/16 12:04:30:4442] INFO: Allocating client RX buffer 36 [2017/02/16 12:04:30:4442] INFO: dumb: LWS_CALLBACK_CLIENT_ESTABLISHED ^C[2017/02/16 12:04:34:3023] ERR: Exiting [2017/02/16 12:04:34:3024] NOTICE: lws_context_destroy [2017/02/16 12:04:34:3024] INFO: lws_close_free_wsi: real just_kill_connection: 0x1c31f10 (sockfd 6) [2017/02/16 12:04:34:3024] INFO: remove_wsi_socket_from_fds: removing same prot wsi 0x1c31f10 [2017/02/16 12:04:34:3024] INFO: have prev 0x1c2e1f0, setting him to our next (nil) [2017/02/16 12:04:34:3025] NOTICE: dumb: LWS_CALLBACK_CLOSED [2017/02/16 12:04:34:3027] INFO: ah det due to close [2017/02/16 12:04:34:3028] INFO: lws_header_table_detach: wsi 0x1c31f10: ah (nil) (tsi=0, count = 1) [2017/02/16 12:04:34:3028] INFO: lws_header_table_detach: wsi 0x1c31f10: ah (nil) (tsi=0, count = 1) [2017/02/16 12:04:34:3028] INFO: lws_close_free_wsi: real just_kill_connection: 0x1c4f8f0 (sockfd 7) [2017/02/16 12:04:34:3028] INFO: remove_wsi_socket_from_fds: removing same prot wsi 0x1c4f8f0 [2017/02/16 12:04:34:3029] INFO: ah det due to close [2017/02/16 12:04:34:3029] INFO: lws_header_table_detach: wsi 0x1c4f8f0: ah 0x1c0aaf0 (tsi=0, count = 1) [2017/02/16 12:04:34:3029] NOTICE: lws_header_table_detach: wsi 0x1c4f8f0: ah held 4s, ah.rxpos 0, ah.rxlen 0, mode/state 39 4,wsi->more_rx_waiting 0 [2017/02/16 12:04:34:3029] INFO: lws_header_table_detach: wsi 0x1c4f8f0: ah 0x1c0aaf0 (tsi=0, count = 0)

[rtcote]

WIth the master branch version, I see the following SSL error prior to the callback being closed: error:00000005:lib(0):func(0):DH lib. A Google search didn't provide any significant insight into what could be causing this. Any other ideas Andy? Thank you.

[2017/02/16 13:33:46:9015] NOTICE: libwebsockets test client - license LGPL2.1+SLE [2017/02/16 13:33:46:9016] NOTICE: (C) Copyright 2010-2016 Andy Green andy@warmcat.com [2017/02/16 13:33:46:9016] NOTICE: Using SSL [2017/02/16 13:33:46:9016] NOTICE: Selfsigned certs allowed [2017/02/16 13:33:46:9016] NOTICE: Skipping peer cert hostname check [2017/02/16 13:33:46:9016] NOTICE: Initial logging level 7 [2017/02/16 13:33:46:9016] NOTICE: Libwebsockets version: 2.1.0 rcote@ubuntuvm-v2.0.0-268-gc3faa7e [2017/02/16 13:33:46:9016] NOTICE: IPV6 not compiled in [2017/02/16 13:33:46:9016] NOTICE: libev support not compiled in [2017/02/16 13:33:46:9016] NOTICE: libuv support not compiled in [2017/02/16 13:33:46:9017] NOTICE: Threads: 1 each 1024 fds [2017/02/16 13:33:46:9017] NOTICE: mem: platform fd map: 8192 bytes [2017/02/16 13:33:46:9017] NOTICE: Compiled with OpenSSL support [2017/02/16 13:33:46:9017] NOTICE: Doing SSL library init [2017/02/16 13:33:46:9043] NOTICE: Creating Vhost 'default' port -1, 2 protocols, IPv6 off [2017/02/16 13:33:46:9074] NOTICE: mem: per-conn: 568 bytes + protocol rx buf [2017/02/16 13:33:46:9075] NOTICE: canonical_hostname = ubuntuvm [2017/02/16 13:33:46:9075] NOTICE: using wss mode (ws) [2017/02/16 13:33:46:9075] NOTICE: dumb: connecting [2017/02/16 13:33:46:9075] NOTICE: lws_client_connect_2: address localhost [2017/02/16 13:33:46:9081] NOTICE: mirror: connecting [2017/02/16 13:33:46:9081] NOTICE: lws_client_connect_2: address localhost [2017/02/16 13:33:46:9083] NOTICE: lws_client_connect_2: address localhost [2017/02/16 13:33:46:9085] NOTICE: lws_client_connect_2: address localhost [2017/02/16 13:33:46:9236] NOTICE: accepting self-signed certificate [2017/02/16 13:33:46:9241] NOTICE: lws_ssl_client_connect2: SSL_connect says -1 [2017/02/16 13:33:46:9368] NOTICE: lws_ssl_client_connect2: SSL_connect says 1 [2017/02/16 13:33:51:9503] ERR: lws_ssl_capable_read failed: error:00000005:lib(0):func(0):DH lib [2017/02/16 13:33:51:9507] ERR: lws_ssl_capable_read failed: error:00000005:lib(0):func(0):DH lib [2017/02/16 13:33:51:9507] NOTICE: dumb: LWS_CALLBACK_CLOSED [2017/02/16 13:33:51:9509] NOTICE: dumb: connecting [2017/02/16 13:33:51:9510] NOTICE: lws_client_connect_2: address localhost [2017/02/16 13:33:51:9518] NOTICE: accepting self-signed certificate [2017/02/16 13:33:51:9534] NOTICE: lws_ssl_client_connect2: SSL_connect says -1 [2017/02/16 13:33:51:9534] NOTICE: lws_client_connect_2: address localhost [2017/02/16 13:33:51:0002] NOTICE: lws_ssl_client_connect2: SSL_connect says 1 [2017/02/16 13:33:51:0007] NOTICE: lws_header_table_detach: wsi 0x1449b40: ah held 5s, ah.rxpos 0, ah.rxlen 0, mode/state 40 7,wsi->more_rx_waiting 0 [2017/02/16 13:33:57:0071] ERR: lws_ssl_capable_read failed: error:00000005:lib(0):func(0):DH lib [2017/02/16 13:33:57:0073] NOTICE: dumb: LWS_CALLBACK_CLOSED [2017/02/16 13:33:57:0075] NOTICE: dumb: connecting [2017/02/16 13:33:57:0075] NOTICE: lws_client_connect_2: address localhost [2017/02/16 13:33:57:0080] NOTICE: lws_client_connect_2: address localhost [2017/02/16 13:33:57:0093] NOTICE: accepting self-signed certificate [2017/02/16 13:33:57:0112] NOTICE: lws_ssl_client_connect2: SSL_connect says -1 [2017/02/16 13:33:57:0651] NOTICE: lws_ssl_client_connect2: SSL_connect says 1 [2017/02/16 13:33:57:0653] NOTICE: lws_header_table_detach: wsi 0x1448ae0: ah held 6s, ah.rxpos 0, ah.rxlen 0, mode/state 40 7,wsi->more_rx_waiting 0 [2017/02/16 13:34:02:0721] ERR: lws_ssl_capable_read failed: error:00000005:lib(0):func(0):DH lib [2017/02/16 13:34:02:0723] NOTICE: dumb: LWS_CALLBACK_CLOSED [2017/02/16 13:34:02:0724] NOTICE: dumb: connecting [2017/02/16 13:34:02:0724] NOTICE: lws_client_connect_2: address localhost [2017/02/16 13:34:02:0728] NOTICE: lws_client_connect_2: address localhost [2017/02/16 13:34:02:0742] NOTICE: accepting self-signed certificate [2017/02/16 13:34:02:0759] NOTICE: lws_ssl_client_connect2: SSL_connect says -1 [2017/02/16 13:34:02:1199] NOTICE: lws_ssl_client_connect2: SSL_connect says 1 [2017/02/16 13:34:02:1212] NOTICE: lws_header_table_detach: wsi 0x144b3d0: ah held 5s, ah.rxpos 0, ah.rxlen 0, mode/state 40 7,wsi->more_rx_waiting 0 ^C[2017/02/16 13:34:06:7969] ERR: Exiting [2017/02/16 13:34:06:7970] NOTICE: lws_context_destroy: ctx 0x141b890 [2017/02/16 13:34:06:7970] NOTICE: dumb: LWS_CALLBACK_CLOSED [2017/02/16 13:34:06:7971] NOTICE: lws_header_table_detach: wsi 0x1448ae0: ah held 4s, ah.rxpos 0, ah.rxlen 0, mode/state 39 4,wsi->more_rx_waiting 0 [2017/02/16 13:34:06:7971] NOTICE: lws_context_destroy2: ctx 0x141b890

[lws-team]

Is your ssl lib possibly broken? What's the platform, the openssl vrrsion and where did it come from?

[rtcote]

I don't think so. It came with Ubuntu I believe.

uname -a Linux ubuntuvm 4.4.0-62-generic #83~14.04.1-Ubuntu SMP Wed Jan 18 18:10:30 UTC 2017 x86_64 x86_64 x86_64 GNU/Linux

openssl version -a OpenSSL 1.0.1f 6 Jan 2014 built on: Mon Jan 30 20:38:38 UTC 2017 platform: debian-amd64 options: bn(64,64) rc4(16x,int) des(idx,cisc,16,int) blowfish(idx) compiler: cc -fPIC -DOPENSSL_PIC -DOPENSSL_THREADS -D_REENTRANT -DDSO_DLFCN -DHAVE_DLFCN_H -m64 -DL_ENDIAN -DTERMIO -g -O2 -fstack-protector --param=ssp-buffer-size=4 -Wformat -Werror=format-security -D_FORTIFY_SOURCE=2 -Wl,-Bsymbolic-functions -Wl,-z,relro -Wa,--noexecstack -Wall -DMD32_REG_T=int -DOPENSSL_IA32_SSE2 -DOPENSSL_BN_ASM_MONT -DOPENSSL_BN_ASM_MONT5 -DOPENSSL_BN_ASM_GF2m -DSHA1_ASM -DSHA256_ASM -DSHA512_ASM -DMD5_ASM -DAES_ASM -DVPAES_ASM -DBSAES_ASM -DWHIRLPOOL_ASM -DGHASH_ASM OPENSSLDIR: "/usr/lib/ssl"

[lws-team]

Fair enough, distro ssl should be good. What about the peer's ssl lib?

How about lws test apps talking over ssl? So

 $ libwebsockets-test-server --ssl

conntect browser to https://localhost:7681 and in another window

 $ libwebsockets-test-client --ssl localhost

Should spam circles in the mirror canvas in fits and starts. But should be no errors about ssl.

[rtcote]

That works just fine. Is it possible that traffic frequency or lack thereof could be causing this issue for me. I have minimal traffic going through the WS interface (a single websocket packet every 10 to 30 seconds).

[lws-team]

The SSL negotiation passes OK but it seems the crypto fails during the link... it could be something messing with data flow inbetween. Or could be peer SSL lib is strange or broken.

How about some kind of timeout somewhere? In lws the lib doesn't apply a timeout to an established ws / wss session. And it supposedly works without ssl... anyway if the test apps are OK in ssl with those ssl libs, I think the issue is outside lws and outside your machine's ssl libs.

[lws-team]

I can't really move this on unless something I can reproduce turns up.