[Libwebsockets] HS: UPGRADE malformed

Andy Green andy at warmcat.com
Mon Apr 29 22:31:45 CEST 2019



On 29/04/2019 03:54, Paolo Denti wrote:
> Andy, In both logs I get back a correct
> Connection Upgrade: websocket

If I take that literally, it's not right... RFC6455 (1.2) says the 
server should reply with

         Upgrade: websocket
         Connection: Upgrade

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

Hum... the "connection" header existed before ws, it's job was to manage 
connection keepalive or not for http/1.0.  With http/1.1, the default 
(ie, no connection header) became keepalive and supporting keepalive is 
mandatory.

It can normally contain "close" or "keep-alive"... in ws they added a 
new token "upgrade" that should appear when the server is agreeing to 
the ws upgrade.

In fact it's not told in RFC6455 it's illegal for connection: to mix the 
old and new tokens, the old tokens still tell the two sides what to do 
about keep-alive if the ws upgrade failed and it remains in http mode.

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

That's not a legal ws upgrade coming from your server if that's 
literally what it replies with.

> 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

That sounds like a pretty confused response from the server if that's 
literally what it sends.

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

It might be worth pasting the whole of this header parsing so we can see 
the stuff mentioned above.

-Andy

> 
> 
> On Fri, Apr 26, 2019 at 11:24 PM Andy Green <andy at warmcat.com 
> <mailto: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>
>      > <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