[Libwebsockets] HS: UPGRADE malformed

Paolo Denti paolo.denti at gmail.com
Mon Apr 29 04:54:00 CEST 2019


Andy, In both logs I get back a correct
Connection Upgrade: websocket

And at the end, on the bad log, I get a connection close

However what could be meaningful is that
on the Ok Log I get
Connection*:8080* Upgrade: websocket
while on the bad log I get
Connection Upgrade: websocket

Where 8080 is the web server port, proxied by a haproxy on port 443, with
SSL termination on it
I do not know if that could mean anything but that is the only meaningful
difference I see apart from the connection close right after the XFrame
options section

This is the portion if the log where the connection is closed
DEBUG: 0x559119c38a30: SSL_read says 1
PARSER: WSI_TOKEN_NAME_PART 'C' 0x43 (role=0x10000000) wsi->lextable_pos=0
DEBUG: 0x559119c38a30: SSL_read says 1
PARSER: WSI_TOKEN_NAME_PART 'o' 0x6F (role=0x10000000) wsi->lextable_pos=117
DEBUG: 0x559119c38a30: SSL_read says 1
PARSER: WSI_TOKEN_NAME_PART 'n' 0x6E (role=0x10000000) wsi->lextable_pos=124
DEBUG: 0x559119c38a30: SSL_read says 1
PARSER: WSI_TOKEN_NAME_PART 'n' 0x6E (role=0x10000000) wsi->lextable_pos=131
DEBUG: 0x559119c38a30: SSL_read says 1
PARSER: WSI_TOKEN_NAME_PART 'e' 0x65 (role=0x10000000) wsi->lextable_pos=138
DEBUG: 0x559119c38a30: SSL_read says 1
PARSER: WSI_TOKEN_NAME_PART 'c' 0x63 (role=0x10000000) wsi->lextable_pos=139
DEBUG: 0x559119c38a30: SSL_read says 1
PARSER: WSI_TOKEN_NAME_PART 't' 0x74 (role=0x10000000) wsi->lextable_pos=140
DEBUG: 0x559119c38a30: SSL_read says 1
PARSER: WSI_TOKEN_NAME_PART 'i' 0x69 (role=0x10000000) wsi->lextable_pos=141
DEBUG: 0x559119c38a30: SSL_read says 1
PARSER: WSI_TOKEN_NAME_PART 'o' 0x6F (role=0x10000000) wsi->lextable_pos=148
DEBUG: 0x559119c38a30: SSL_read says 1
PARSER: WSI_TOKEN_NAME_PART 'n' 0x6E (role=0x10000000) wsi->lextable_pos=149
DEBUG: 0x559119c38a30: SSL_read says 1
PARSER: WSI_TOKEN_NAME_PART ':' 0x3A (role=0x10000000) wsi->lextable_pos=150
PARSER: known hdr 4
DEBUG: 0x559119c38a30: SSL_read says 1
PARSER: WSI_TOK_(4) ' '
DEBUG: 0x559119c38a30: SSL_read says 1
PARSER: WSI_TOK_(4) 'c'
DEBUG: 0x559119c38a30: SSL_read says 1
PARSER: WSI_TOK_(4) 'l'
DEBUG: 0x559119c38a30: SSL_read says 1
PARSER: WSI_TOK_(4) 'o'
DEBUG: 0x559119c38a30: SSL_read says 1
PARSER: WSI_TOK_(4) 's'
DEBUG: 0x559119c38a30: SSL_read says 1
PARSER: WSI_TOK_(4) 'e'
DEBUG: 0x559119c38a30: SSL_read says 1
PARSER: WSI_TOK_(4) '



On Fri, Apr 26, 2019 at 11:24 PM Andy Green <andy at warmcat.com> wrote:

>
>
> 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
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://libwebsockets.org/pipermail/libwebsockets/attachments/20190428/53020ca4/attachment-0001.htm>


More information about the Libwebsockets mailing list