search

warmcat / libwebsockets

canonical libwebsockets.org networking library
https://libwebsockets.org
Other
4.78k stars 1.49k forks source link

Cannot connect wss, ssl error 6 errno 0 #1412

Closed jetgem closed 6 years ago

jetgem commented 6 years ago

Hi, I was able to connect to ws, but no luck with wss. Can you check what's wrong? I'm using v3-stable branch.

Attached full source and logs.

int main()
{
    lws_set_log_level(31, NULL); // We don't need to see the notice messages

    signal(SIGINT, onSigInt); // Register the SIGINT handler

    // Connection info
    char inputURL[300] = "wss://echo.websocket.org";
    int inputPort = 9000;

    struct lws_context_creation_info ctxCreationInfo; // Context creation info
    struct lws_client_connect_info clientConnectInfo; // Client creation info
    struct lws_context *ctx; // The context to use

    struct lws *wsiTest; // WebSocket interface
    const char *urlProtocol, *urlTempPath; // the protocol of the URL, and a temporary pointer to the path
    char urlPath[300]; // The final path string

    // Set both information to empty and allocate it's memory
    memset(&ctxCreationInfo, 0, sizeof(ctxCreationInfo));
    memset(&clientConnectInfo, 0, sizeof(clientConnectInfo));

    clientConnectInfo.port = inputPort; // Set the client info's port to the input port

    // Parse the input url (e.g. wss://echo.websocket.org:1234/test)
    //   the protocol (wss)
    //   the address (echo.websocket.org)
    //   the port (1234)
    //   the path (/test)
    if (lws_parse_uri(inputURL, &urlProtocol, &clientConnectInfo.address, &clientConnectInfo.port, &urlTempPath))
    {
        printf("Couldn't parse URL\n");
    }

    // Fix up the urlPath by adding a / at the beginning, copy the temp path, and add a \0 at the end
    urlPath[0] = '/';
    strncpy(urlPath + 1, urlTempPath, sizeof(urlPath) - 2);
    urlPath[sizeof(urlPath) - 1] = '\0';
//  urlPath[0] = '\0';
    clientConnectInfo.path = urlPath; // Set the info's path to the fixed up url path

    // Set up the context creation info
    ctxCreationInfo.port = CONTEXT_PORT_NO_LISTEN; // We don't want this client to listen
    ctxCreationInfo.protocols = protocols; // Use our protocol list
    ctxCreationInfo.gid = -1; // Set the gid and uid to -1, isn't used much
    ctxCreationInfo.uid = -1;
    ctxCreationInfo.extensions = extensions; // Use our extensions list

    // Create the context with the info
    printf("%d\n", ctxCreationInfo.options);
    ctxCreationInfo.options = LWS_SERVER_OPTION_DO_SSL_GLOBAL_INIT;
    ctx = lws_create_context(&ctxCreationInfo);

    if (ctx == NULL)
    {
        printf("Error creating context\n");
        return 1;
    }
    // LCCSCF_USE_SSL               = (1 << 0),
    // LCCSCF_ALLOW_SELFSIGNED          = (1 << 1),
    // LCCSCF_SKIP_SERVER_CERT_HOSTNAME_CHECK   = (1 << 2),
    // LCCSCF_ALLOW_EXPIRED         = (1 << 3),

    // LCCSCF_PIPELINE              = (1 << 16),
    // Set up the client creation info
    clientConnectInfo.context = ctx; // Use our created context
    clientConnectInfo.ssl_connection = LCCSCF_USE_SSL | LCCSCF_ALLOW_SELFSIGNED | LCCSCF_SKIP_SERVER_CERT_HOSTNAME_CHECK; // Don't use SSL for this test
    clientConnectInfo.host = clientConnectInfo.address; // Set the connections host to the address
    clientConnectInfo.origin = clientConnectInfo.address; // Set the conntections origin to the address
    clientConnectInfo.ietf_version_or_minus_one = -1; // IETF version is -1 (the latest one)
    clientConnectInfo.protocol = protocols[PROTOCOL_TEST].name; // We use our test protocol
    clientConnectInfo.pwsi = &wsiTest; // The created client should be fed inside the wsi_test variable

    printf("Connecting to %s://%s:%d%s \n\n", urlProtocol, clientConnectInfo.address, clientConnectInfo.port, urlPath);

    // Connect with the client info
    lws_client_connect_via_info(&clientConnectInfo);
    if (wsiTest == NULL)
    {
        printf("Error creating the client\n");
        return 1;
    }

    // Main loop runs till bExit is true, which forces an exit of this loop
    while (!bExit)
    {
        // LWS' function to run the message loop, which polls in this example every 50 milliseconds on our created context
        lws_service(ctx, 50);
    }

    // Destroy the context
    lws_context_destroy(ctx);

    printf("\nDone executing.\n");

    return 0;
}
kendo@kendo-virtual-machine:~/pjproject-2.6/libwebsockets/build$ ./bin/libwebsockets-test-client
0
[2018/09/22 04:56:12:1777] INFO: Initial logging level 31
[2018/09/22 04:56:12:1777] INFO: Libwebsockets version: 3.0.99 v3.0.0-138-g64ea98f
[2018/09/22 04:56:12:1777] INFO: IPV6 not compiled in
[2018/09/22 04:56:12:1777] INFO:  LWS_DEF_HEADER_LEN    : 4096
[2018/09/22 04:56:12:1777] INFO:  LWS_MAX_PROTOCOLS     : 5
[2018/09/22 04:56:12:1777] INFO:  LWS_MAX_SMP           : 1
[2018/09/22 04:56:12:1777] INFO:  sizeof (*info)        : 496
[2018/09/22 04:56:12:1777] INFO:  SYSTEM_RANDOM_FILEPATH: '/dev/urandom'
[2018/09/22 04:56:12:1777] INFO:  HTTP2 support         : not configured
[2018/09/22 04:56:12:1777] DEBUG: _realloc: size 776: context
[2018/09/22 04:56:12:1777] INFO: Using event loop: poll
[2018/09/22 04:56:12:1777] INFO: Default ALPN advertisment: http/1.1
[2018/09/22 04:56:12:1777] INFO:  default timeout (secs): 20
[2018/09/22 04:56:12:1777] DEBUG: _realloc: size 4096: pt_serv_buf
[2018/09/22 04:56:12:1777] INFO:  Threads: 1 each 1024 fds
[2018/09/22 04:56:12:1777] INFO:  mem: context:          4872 B (776 ctx + (1 thr x 4096))
[2018/09/22 04:56:12:1777] INFO:  mem: http hdr rsvd:   5177344 B (1 thr x (4096 + 960) x 1024))
[2018/09/22 04:56:12:1778] DEBUG: _realloc: size 8192: fds table
[2018/09/22 04:56:12:1778] INFO:  mem: pollfd map:       8192
[2018/09/22 04:56:12:1778] DEBUG: _realloc: size 8192: lws_lookup
[2018/09/22 04:56:12:1778] INFO:  mem: platform fd map:  8192 bytes
[2018/09/22 04:56:12:1778] DEBUG: _realloc: size 472: event pipe wsi
[2018/09/22 04:56:12:1778] DEBUG: lws_role_transition: 0x11147d0: wsistate 0x200, ops pipe
[2018/09/22 04:56:12:1778] DEBUG: event pipe fd 5
[2018/09/22 04:56:12:1778] DEBUG: __insert_wsi_socket_into_fds: 0x11147d0: tsi=0, sock=5, pos-in-fds=0
[2018/09/22 04:56:12:1778] INFO:  Compiled with OpenSSL support
[2018/09/22 04:56:12:1778] INFO: Doing SSL library init
[2018/09/22 04:56:12:1789] DEBUG: _realloc: size 648: create vhost
[2018/09/22 04:56:12:1789] DEBUG: _realloc: size 112: vhost-specific plugin table
[2018/09/22 04:56:12:1789] DEBUG: _realloc: size 8: same vh list
[2018/09/22 04:56:12:1789] NOTICE: Creating Vhost 'default' (serving disabled), 1 protocols, IPv6 off
[2018/09/22 04:56:12:1791] NOTICE: created client ssl context for default
[2018/09/22 04:56:12:1791] INFO:  mem: per-conn:          472 bytes + protocol rx buf
[2018/09/22 04:56:12:1791] INFO:  canonical_hostname = kendo-virtual-machine
[2018/09/22 04:56:12:1791] INFO: lws_cancel_service
Connecting to wss://echo.websocket.org:443//

[2018/09/22 04:56:12:1792] INFO: lws_protocol_init
[2018/09/22 04:56:12:1792] DEBUG: _realloc: size 472: client wsi
[2018/09/22 04:56:12:1792] INFO: lws_vhost_bind_wsi: vh default: count_bound_wsi 1
[2018/09/22 04:56:12:1792] DEBUG: _realloc: size 200: client ws struct
[2018/09/22 04:56:12:1792] DEBUG: lws_role_transition: 0x1139350: wsistate 0x10000200, ops h1
[2018/09/22 04:56:12:1792] INFO: lws_client_connect_via_info: protocol binding to test-protocol
[2018/09/22 04:56:12:1792] INFO: lws_same_vh_protocol_remove: removing same prot wsi 0x1139350
[2018/09/22 04:56:12:1792] DEBUG: lws_ensure_user_space: 0x1139350 protocol pss 0, user_space=(nil)
[Test Protocol] Connection client closed.
[2018/09/22 04:56:12:1792] DEBUG: _realloc: size 64: client stash
[2018/09/22 04:56:12:1792] DEBUG: _realloc: size 19: strdup
[2018/09/22 04:56:12:1792] DEBUG: _realloc: size 3: strdup
[2018/09/22 04:56:12:1792] DEBUG: _realloc: size 19: strdup
[2018/09/22 04:56:12:1793] DEBUG: _realloc: size 19: strdup
[2018/09/22 04:56:12:1793] DEBUG: _realloc: size 14: strdup
[2018/09/22 04:56:12:1793] DEBUG: _realloc: size 9: strdup
[2018/09/22 04:56:12:1793] INFO: lws_header_table_attach: wsi 0x1139350: ah (nil) (tsi 0, count = 0) in
[2018/09/22 04:56:12:1793] DEBUG: _realloc: size 960: ah struct
[2018/09/22 04:56:12:1793] DEBUG: _realloc: size 4096: ah data
[2018/09/22 04:56:12:1793] INFO: _lws_create_ah: created ah 0x1139710 (size 4096): pool length 1
[2018/09/22 04:56:12:1793] INFO: lws_header_table_attach: did attach wsi 0x1139350: ah 0x1139710: count 1 (on exit)
[2018/09/22 04:56:12:1793] DEBUG: __lws_set_timeout: 0x1139350: 10 secs (reason 25)
[2018/09/22 04:56:12:1793] DEBUG: _realloc: size 19: strdup
[2018/09/22 04:56:12:1793] INFO: lws_client_connect_2: 0x1139350: address echo.websocket.org
[2018/09/22 04:56:12:3132] DEBUG: lwsi_set_state(0x1139350, 0x10000201)
[2018/09/22 04:56:12:3132] DEBUG: __insert_wsi_socket_into_fds: 0x1139350: tsi=0, sock=17, pos-in-fds=1
[2018/09/22 04:56:12:3132] DEBUG: _lws_change_pollfd: wsi 0x1139350: fd 17 events 1 -> 1
[2018/09/22 04:56:12:3132] DEBUG: __lws_set_timeout: 0x1139350: 20 secs (reason 2)
[2018/09/22 04:56:12:3133] DEBUG: _lws_change_pollfd: wsi 0x1139350: fd 17 events 1 -> 5
[2018/09/22 04:56:12:5441] DEBUG: _lws_change_pollfd: wsi 0x1139350: fd 17 events 5 -> 1
[2018/09/22 04:56:12:5441] INFO: lws_client_connect_2: 0x1139350: address echo.websocket.org
[2018/09/22 04:56:12:6521] INFO: lws_client_connect_2: wsi 0x1139350: client creating own connection
[2018/09/22 04:56:12:6521] DEBUG: lwsi_set_state(0x1139350, 0x10000011)
[2018/09/22 04:56:12:6521] DEBUG: __lws_set_timeout: 0x1139350: 20 secs (reason 8)
[2018/09/22 04:56:12:6521] DEBUG: _lws_change_pollfd: wsi 0x1139350: fd 17 events 1 -> 1
[2018/09/22 04:56:12:6521] INFO: client conn using alpn list 'http/1.1'
[2018/09/22 04:56:12:6523] DEBUG: lws_ssl_get_error: 0x113d0f0 -1 -> 2 (errno 11)
[2018/09/22 04:56:12:6523] DEBUG: lwsi_set_state(0x1139350, 0x10000203)
[2018/09/22 04:56:12:8860] DEBUG: lws_ssl_get_error: 0x113d0f0 -1 -> 2 (errno 11)
[2018/09/22 04:56:12:8861] DEBUG: lws_ssl_client_connect2: SSL_connect says -2
[2018/09/22 04:56:12:8861] DEBUG: lwsi_set_state(0x1139350, 0x10000203)
[2018/09/22 04:56:12:8865] NOTICE: accepting self-signed certificate (verify_callback)
[2018/09/22 04:56:12:8869] DEBUG: lws_ssl_get_error: 0x113d0f0 -1 -> 2 (errno 11)
[2018/09/22 04:56:12:8869] DEBUG: lws_ssl_client_connect2: SSL_connect says -2
[2018/09/22 04:56:12:8869] DEBUG: lwsi_set_state(0x1139350, 0x10000203)
[2018/09/22 04:56:13:1245] INFO: lws_role_call_alpn_negotiated: ''
[2018/09/22 04:56:13:1245] INFO: client connect OK
[2018/09/22 04:56:13:1245] DEBUG: lws_ssl_client_connect2: SSL_connect says 0
[2018/09/22 04:56:13:1245] DEBUG: get_verify says 0
[2018/09/22 04:56:13:1245] DEBUG: lwsi_set_state(0x1139350, 0x10000012)
[2018/09/22 04:56:13:1245] DEBUG: __lws_set_timeout: 0x1139350: 20 secs (reason 11)
[2018/09/22 04:56:13:1245] INFO: lws_client_socket_service: HANDSHAKE2: 0x1139350: sending headers on 0x1139350 (wsistate 0x10000012 0x10000012)
[2018/09/22 04:56:13:1246] DEBUG: lwsi_set_state(0x1139350, 0x1000020a)
[2018/09/22 04:56:13:1246] DEBUG: __lws_set_timeout: 0x1139350: 20 secs (reason 4)
[2018/09/22 04:56:13:1246] DEBUG: _lws_change_pollfd: wsi 0x1139350: fd 17 events 1 -> 5
[2018/09/22 04:56:13:1246] DEBUG: lwsi_set_state(0x1139350, 0x1000020a)
[2018/09/22 04:56:13:1246] DEBUG: __lws_set_timeout: 0x1139350: 20 secs (reason 4)
[2018/09/22 04:56:13:1246] DEBUG: _lws_change_pollfd: wsi 0x1139350: fd 17 events 5 -> 1
[2018/09/22 04:56:13:3566] DEBUG: 0x1139350: SSL_read says 1
[2018/09/22 04:56:13:3567] DEBUG: 0x1139350: SSL_read says 1
...
[2018/09/22 04:56:13:3651] DEBUG: 0x1139350: SSL_read says 1
[2018/09/22 04:56:13:3651] DEBUG: 0x1139350: SSL_read says 1
[2018/09/22 04:56:13:3651] INFO: lws_client_ws_upgrade: WSI_TOKEN_PROTOCOL is null
[2018/09/22 04:56:13:3651] DEBUG: lws_ensure_user_space: 0x1139350 protocol pss 0, user_space=(nil)
[2018/09/22 04:56:13:3651] DEBUG: __lws_set_timeout: 0x1139350: 0 secs (reason 0)
[2018/09/22 04:56:13:3651] INFO: __lws_header_table_detach: wsi 0x1139350: ah 0x1139710 (tsi=0, count = 1)
[2018/09/22 04:56:13:3651] INFO: __lws_header_table_detach: nobody usable waiting
[2018/09/22 04:56:13:3797] INFO: _lws_destroy_ah: freed ah 0x1139710 : pool length 0
[2018/09/22 04:56:13:3797] INFO: __lws_header_table_detach: wsi 0x1139350: ah 0x1139710 (tsi=0, count = 0)
[2018/09/22 04:56:13:3797] DEBUG: lws_role_transition: 0x1139350: wsistate 0x10000117, ops ws
[2018/09/22 04:56:13:3797] DEBUG: _realloc: size 532: client frame buffer
[2018/09/22 04:56:13:3797] INFO: Allocating client RX buffer 528
[2018/09/22 04:56:13:3797] DEBUG: handshake OK for protocol test-protocol
[Test Protocol] Connection to server established.
[Test Protocol] Writing "Simple webserver echo test!" to server.
[2018/09/22 04:56:13:3799] DEBUG: 0x1139350: SSL_read says 0
[2018/09/22 04:56:13:3799] DEBUG: lws_ssl_get_error: 0x113d0f0 0 -> 6 (errno 0) <----error here
[2018/09/22 04:56:13:3799] NOTICE: 0x1139350: ssl err 6 errno 0  <----error here
[2018/09/22 04:56:13:3799] INFO: rops_handle_POLLIN_ws: LWS_SSL_CAPABLE_ERROR
[2018/09/22 04:56:13:3799] DEBUG: 0x1139350: Close and handled
[2018/09/22 04:56:13:3799] INFO: __lws_close_free_wsi: 0x1139350: caller: close_and_handled
[2018/09/22 04:56:13:3799] DEBUG: __lws_close_free_wsi: real just_kill_connection: 0x1139350 (sockfd 17)
[2018/09/22 04:56:13:3799] INFO: lws_same_vh_protocol_remove: removing same prot wsi 0x1139350
[2018/09/22 04:56:13:3799] INFO: have prev 0x1139418, setting him to our next 0x1139350
[2018/09/22 04:56:13:3799] DEBUG: __remove_wsi_socket_from_fds: wsi=0x1139350, sock=17, fds pos=1, end guy pos=2, endfd=0
[2018/09/22 04:56:13:3799] DEBUG: lwsi_set_state(0x1139350, 0x1000001e)
lws-team commented 6 years ago

Sorry for the long delay.

I can reproduce it... the situation from lws side is immediately after the connection succeeds, we get a zero-length SSL_read()

[2018/09/22 04:56:13:3799] DEBUG: 0x1139350: SSL_read says 0
RETURN VALUES

The following return values can occur:

> 0

    The read operation was successful. The return value is the number of bytes actually read from the TLS/SSL connection.
<= 0
<0

    The read operation was not successful, because either the connection was closed, an error occurred or action must be taken by the calling process. Call SSL_get_error with the return value ret to find out the reason.
...
Old documentation indicated a difference between 0 and -1, and that -1 was retryable. You should instead call SSL_get_error() to find out if it's retryable.

https://www.openssl.org/docs/man1.0.2/ssl/SSL_read.html

The reason that comes back is

SSL_ERROR_ZERO_RETURN

    The TLS/SSL connection has been closed. If the protocol version is SSL 3.0 or higher, this result code is returned only if a closure alert has occurred in the protocol, i.e. if the connection has been closed cleanly. Note that in this case SSL_ERROR_ZERO_RETURN does not necessarily indicate that the underlying transport has been closed.

https://www.openssl.org/docs/man1.1.0/ssl/SSL_get_error.html

We respond to that by closing the connection too.

I get the same thing without tls... hacking the close response out to confirm it's real or not, it just spins like this

[2018/11/01 08:21:34:4623] INFO: rops_handle_POLLIN_ws: zero length read

So no doubt the other side closed.

I did these tests with a slightly modified (to allow --ssl flag) minimal-ws-client-echo example... that doesn't actually send anything as it is. So it should just stay up silently until the other side times it out.

Lws can talk to itself and talk to browsers with and without tls as you can easily confirm. So without any more info from their server logs, I guess this is a problem their end.