[Libwebsockets] HS: UPGRADE malformed

Paolo Denti paolo.denti at gmail.com
Sat Apr 27 05:14:59 CEST 2019


I reproduced the problem using ona of the providex examples just changing
the host (default was 'libwebsockets.org') and the url (defauilt was '/')

I rebuilt both the two versions with -DCMAKE_BUILD_TYPE=DEBUG and enabling
extensions and ZLIB
i ran the example with "-d 1151"

i compared the two outputs, cleaned from looked to me as neglectable and
below is the diff between the two logs.
I still have the original full logs and I can add additional information

diff left < (3.0.0) is working
diff right > (3.1.99) is not working

I hope it helps

< INFO: Libwebsockets version: 3.0.0 unknown-build-hash
---
> INFO: Libwebsockets version: 3.1.99 v3.1.0-150-gdd759d10

< INFO:  HTTP2 support         : not configured
< DEBUG: _realloc: size 792: context
---
> INFO:  HTTP2 support         : available
> DEBUG: _realloc: size 880: context
> INFO: context created

< INFO: Default ALPN advertisment: http/1.1
---
> INFO: Default ALPN advertisment: h2,http/1.1

< DEBUG: _realloc: size 640: create vhost
< DEBUG: _realloc: size 112: vhost-specific plugin table
< DEBUG: _realloc: size 8: same vh list
< NOTICE: Creating Vhost 'default' (serving disabled), 1 protocols, IPv6 off
---
> DEBUG: _realloc: size 720: create vhost
> DEBUG: _realloc: size 168: vhost-specific plugin table
> DEBUG: _realloc: size 32: same vh list
> INFO: Creating Vhost 'default' (serving disabled), 2 protocols, IPv6 off
> DEBUG: _realloc: size 64: client ctx tcr
> INFO: lws_tls_client_create_vhost_context: vh default: created new client
ctx 0

< INFO: _lws_create_ah: created ah 0x5581dbbe78b0 (size 4096): pool length 1
< INFO: lws_header_table_attach: did attach wsi 0x5581dbbe74c0: ah
0x5581dbbe78b0: count 1 (on exit)
< DEBUG: __lws_set_timeout: 0x5581dbbe74c0: 10 secs
< INFO: lws_client_connect_2: 0x5581dbbe74c0: address MYSERVER
< DEBUG: lwsi_set_state(0x5581dbbe74c0, 0x10000201)
< DEBUG: __insert_wsi_socket_into_fds: 0x5581dbbe74c0: tsi=0, sock=6,
pos-in-fds=1
< DEBUG: _lws_change_pollfd: wsi 0x5581dbbe74c0: fd 6 events 1 -> 1
< DEBUG: __lws_set_timeout: 0x5581dbbe74c0: 20 secs
< DEBUG: _lws_change_pollfd: wsi 0x5581dbbe74c0: fd 6 events 1 -> 5
< DEBUG: _lws_change_pollfd: wsi 0x5581dbbe74c0: fd 6 events 5 -> 1
< INFO: lws_client_connect_2: 0x5581dbbe74c0: address MYSERVER
< INFO: lws_client_connect_2: wsi 0x5581dbbe74c0: client creating own
connection
< DEBUG: lwsi_set_state(0x5581dbbe74c0, 0x10000011)
< DEBUG: __lws_set_timeout: 0x5581dbbe74c0: 20 secs
< DEBUG: _lws_change_pollfd: wsi 0x5581dbbe74c0: fd 6 events 1 -> 1
---
> INFO: _lws_create_ah: created ah 0x559119c38ec0 (size 4096): pool length 1
> INFO: lws_header_table_attach: did attach wsi 0x559119c38a30: ah
0x559119c38ec0: count 1 (on exit)
> DEBUG: __lws_set_timeout: 0x559119c38a30: 10 secs (reason 25)
> DEBUG: lws_http_client_connect_via_info2: 0x559119c38a30 (stash
0x559119c38d80)
> DEBUG: _realloc: size 27: strdup
> INFO: lws_client_connect_2: 0x559119c38a30: address MYSERVER:443
> DEBUG: lwsi_set_state(0x559119c38a30, 0x10000201)
> DEBUG: __insert_wsi_socket_into_fds: 0x559119c38a30: tsi=0, sock=6,
pos-in-fds=1
> DEBUG: _lws_change_pollfd: wsi 0x559119c38a30: fd 6 events 1 -> 1
> DEBUG: __lws_set_timeout: 0x559119c38a30: 20 secs (reason 2)
> DEBUG: _lws_change_pollfd: wsi 0x559119c38a30: fd 6 events 1 -> 5
> DEBUG: lws_client_connect_via_info: wsi 0x559119c38a30: cb 19 to h1
dumb-increment-protocol
> NOTICE: lws_broadcast: 0 dumb-increment-protocol
> NOTICE: lws_broadcast: 1 lws-abs-cli-raw-skt
> DEBUG: _lws_change_pollfd: wsi 0x559119c38a30: fd 6 events 5 -> 1
> INFO: lws_client_connect_2: 0x559119c38a30: address MYSERVER:443
> INFO: lws_client_connect_3: wsi 0x559119c38a30: h1
dumb-increment-protocol client created own conn (raw 0)
> DEBUG: lwsi_set_state(0x559119c38a30, 0x10000011)
> DEBUG: __lws_set_timeout: 0x559119c38a30: 20 secs (reason 8)
> DEBUG: _lws_change_pollfd: wsi 0x559119c38a30: fd 6 events 1 -> 1
70,72c85,87
< DEBUG: lws_ssl_get_error: 0x5581dbbeb240 -1 -> 2 (errno 11)
< DEBUG: lwsi_set_state(0x5581dbbe74c0, 0x10000203)
< DEBUG: lws_ssl_get_error: 0x5581dbbeb240 -1 -> 2 (errno 11)
---
> DEBUG: lws_ssl_get_error: 0x559119c3c620 -1 -> 2 (errno 11)
> DEBUG: lwsi_set_state(0x559119c38a30, 0x10000203)
> DEBUG: lws_ssl_get_error: 0x559119c3c620 -1 -> 2 (errno 11)
74c89,93
< DEBUG: lwsi_set_state(0x5581dbbe74c0, 0x10000203)
---
> DEBUG: lwsi_set_state(0x559119c38a30, 0x10000203)
> DEBUG: _realloc: size 592: cbwsi
> DEBUG: _realloc: size 40: cbtmr
> DEBUG: lws_service_periodic_checks: timed cb: vh default, protocol
lws-abs-cli-raw-skt, reason 1000
> DEBUG: _realloc: size 40: timed_vh
76a96
> INFO: lws_openssl_describe_cipher: wsi 0x559119c38a30:
ECDHE-RSA-AES256-GCM-SHA384, ECDHE-RSA-AES256-GCM-SHA384, 256 bits, TLSv1.2
79,88c99,108
< DEBUG: lwsi_set_state(0x5581dbbe74c0, 0x10000012)
< DEBUG: __lws_set_timeout: 0x5581dbbe74c0: 20 secs
< INFO: lws_client_socket_service: HANDSHAKE2: 0x5581dbbe74c0: sending
headers on 0x5581dbbe74c0 (wsistate 0x10000012 0x10000012)
< DEBUG: lwsi_set_state(0x5581dbbe74c0, 0x1000020a)
< DEBUG: __lws_set_timeout: 0x5581dbbe74c0: 20 secs
< DEBUG: _lws_change_pollfd: wsi 0x5581dbbe74c0: fd 6 events 1 -> 5
< DEBUG: lwsi_set_state(0x5581dbbe74c0, 0x1000020a)
< DEBUG: __lws_set_timeout: 0x5581dbbe74c0: 20 secs
< DEBUG: _lws_change_pollfd: wsi 0x5581dbbe74c0: fd 6 events 5 -> 1
< DEBUG: 0x5581dbbe74c0: SSL_read says 1
---
> DEBUG: lwsi_set_state(0x559119c38a30, 0x10000012)
> DEBUG: __lws_set_timeout: 0x559119c38a30: 20 secs (reason 11)
> INFO: lws_client_socket_service: HANDSHAKE2: 0x559119c38a30: sending
headers on 0x559119c38a30 (wsistate 0x10000012 0x10000012), w sock 6, wsi
sock 6
> DEBUG: lwsi_set_state(0x559119c38a30, 0x1000020a)
> DEBUG: __lws_set_timeout: 0x559119c38a30: 20 secs (reason 4)
> DEBUG: _lws_change_pollfd: wsi 0x559119c38a30: fd 6 events 1 -> 5
> DEBUG: lwsi_set_state(0x559119c38a30, 0x1000020a)
> DEBUG: __lws_set_timeout: 0x559119c38a30: 20 secs (reason 4)
> DEBUG: _lws_change_pollfd: wsi 0x559119c38a30: fd 6 events 5 -> 1
> DEBUG: 0x559119c38a30: SSL_read says 1

< PARSER: lws_client_int_s_hs: protocol list 'dumb-increment-protocol'
< INFO: lws_client_ws_upgrade: WSI_TOKEN_PROTOCOL is null
< DEBUG: lws_ensure_user_space: 0x5581dbbe74c0 protocol pss 0,
user_space=(nil)
< DEBUG: __lws_set_timeout: 0x5581dbbe74c0: 0 secs
< INFO: __lws_header_table_detach: wsi 0x5581dbbe74c0: ah 0x5581dbbe78b0
(tsi=0, count = 1)
---
> ERR: CLIENT_CONNECTION_ERROR: HS: UPGRADE malformed
> INFO: closing connection (prot dumb-increment-protocol) due to bail2
connection error: HS: UPGRADE malformed
> INFO: __lws_close_free_wsi: 0x559119c38a30: caller: c hs interp
> DEBUG: __lws_close_free_wsi: real just_kill_connection: 0x559119c38a30
(sockfd 6)
> DEBUG: lwsi_set_state(0x559119c38a30, 0x1000001e)
> INFO: __lws_header_table_detach: wsi 0x559119c38a30: ah 0x559119c38ec0
(tsi=0, count = 1)


On Fri, Apr 26, 2019 at 3:14 PM Paolo Denti <paolo.denti at gmail.com> wrote:

> I have been struggling for a very long time with error HS: UPGRADE
> malformed, even with very basic examples.
>
> I just was not able to write even a single super basic example, not even
> starting from the existing examples.
>
> Whatever I tried to do, I just got this error, on my server (Java, Spring
> based) fully working, with several clients, node.js. python, perl,
> javascript of course, ...
> But I was not able to have it working with libwebsockets.
>
> I was about to give up when, today, I browsed a little bit and I found out
> someone was having the same issue while upgrading to 3.1.0
>
> I tried to build 3.0.0 and everything magically worked, without changing a
> single bit from my last experiment, out of the 200K zillions I wrote.
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://libwebsockets.org/pipermail/libwebsockets/attachments/20190426/3999e40d/attachment-0001.htm>


More information about the Libwebsockets mailing list