[Libwebsockets] HS: UPGRADE malformed

Andy Green andy at warmcat.com
Sat Apr 27 08:23:59 CEST 2019



On 27/04/2019 04:14, Paolo Denti wrote:
> I reproduced the problem using ona of the providex examples just 
> changing the host (default was 'libwebsockets.org 
> <http://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

Testing master is good, but it's always possible I can break master 
since I am working on it.

> I hope it helps

Diffing it isn't a bad idea if one works and the other doesn't, but in 
this case the question boils down to what did it actually send on the 
"connection" header... the code related to this in lws causes the 
"UPGRADE malformed" result, and it's different between v3 (it's best to 
use v3.whatever-stable, it has fixes since the original release[1]) and 
master.

v3.0:

         p = lws_hdr_simple_ptr(wsi, WSI_TOKEN_CONNECTION);
         if (!p) {
                 lwsl_info("no Connection hdr\n");
                 *cce = "HS: CONNECTION missing";
                 goto bail3;
         }
         strtolower(p);
         if (strcmp(p, "upgrade")) {
                 lwsl_warn("lws_client_int_s_hs: bad header %s\n", p);
                 *cce = "HS: UPGRADE malformed";
                 goto bail3;
         }

v3.1+

	/* connection: must have "upgrade" */

	lws_tokenize_init(&ts, buf, LWS_TOKENIZE_F_COMMA_SEP_LIST |
				    LWS_TOKENIZE_F_MINUS_NONTERM);
	ts.len = lws_hdr_copy(wsi, buf, sizeof(buf) - 1, WSI_TOKEN_CONNECTION);
	if (ts.len <= 0) /* won't fit, or absent */
		goto bad_conn_format;

	do {
		e = lws_tokenize(&ts);
		switch (e) {
		case LWS_TOKZE_TOKEN:
			if (!strcasecmp(ts.token, "upgrade"))
				e = LWS_TOKZE_ENDED;
			break;

		case LWS_TOKZE_DELIMITER:
			break;

		default: /* includes ENDED */
bad_conn_format:
			*cce = "HS: UPGRADE malformed";
			goto bail3;
		}
	} while (e > 0);

If you look in either log, it should verbosely spell out character by 
character what was returned by the server for "Connection" header... it 
looks like it should be "Connection: upgrade" to pass on v3.0.  But that 
should pass OK on the tokenizer as well.

Can you paste that part please from either log.

> < 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

Hmmm on master only, h2 is enabled.

>  > DEBUG: _realloc: size 880: context
>  > INFO: context created
> 
> < INFO: Default ALPN advertisment: http/1.1
> ---
>  > INFO: Default ALPN advertisment: h2,http/1.1

I guess the server doesn't support h2, or the logging diff would be much 
larger.

> < 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

Well, I guess it's not the problem at the moment.

> < 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)

-Andy

[1] 
https://libwebsockets.org/git/libwebsockets/tree/READMEs/README.release-policy.md


More information about the Libwebsockets mailing list