[Libwebsockets] Settings Frame size above max / Flow control exceeded max

Andreas Lobbes Andreas.Lobbes at thinprint.com
Mon Jul 8 09:19:17 CEST 2019


Hello Andy,

with the latest patch I still get this error:

2019-07-08 09:06:46 INF lws_role_call_alpn_negotiated: 'h2'
2019-07-08 09:06:46 DBG rops_alpn_negotiated_h2: client 1
2019-07-08 09:06:46 INF rops_alpn_negotiated_h2: upgraded to H2
2019-07-08 09:06:46 DBG lws_role_transition: 0x555dc7a20a20: wsistate 0x2000020b, ops h2
2019-07-08 09:06:46 DBG _realloc: size 216: h2n
2019-07-08 09:06:46 INF lws_hpack_dynamic_size: from 0 to 65536, lim 65536
2019-07-08 09:06:46 DBG _realloc: size 131088: dynamic table entries
2019-07-08 09:06:46 INF rops_alpn_negotiated_h2: wsi 0x555dc7a20a20: configured for h2
2019-07-08 09:06:46 INF client connect OK
2019-07-08 09:06:46 INF lws_openssl_describe_cipher: wsi 0x555dc7a20a20: ECDHE-RSA-AES256-GCM-SHA384, ECDHE-RSA-AES256-GCM-SHA384, 256 bits, TLSv1.2
2019-07-08 09:06:46 DBG lws_ssl_client_connect2: SSL_connect says 0
2019-07-08 09:06:46 DBG get_verify says 0
2019-07-08 09:06:46 INF negotiated 'h2' using ALPN
2019-07-08 09:06:46 INF lws_role_call_alpn_negotiated: 'h2'
2019-07-08 09:06:46 DBG rops_alpn_negotiated_h2: client 0
2019-07-08 09:06:46 DBG lws_role_transition: 0x555dc7a20a20: wsistate 0x2000020b, ops h2
2019-07-08 09:06:46 INF lws_hpack_dynamic_size: from 8192 to 65536, lim 65536
2019-07-08 09:06:46 INF rops_alpn_negotiated_h2: wsi 0x555dc7a20a20: configured for h2
2019-07-08 09:06:46 INF lws_issue_raw: ssl_capable_write (24) says 24
2019-07-08 09:06:46 DBG lws_role_transition: 0x555dc7a20a20: wsistate 0x1000010e, ops h2
2019-07-08 09:06:46 DBG _realloc: size 56: pps
2019-07-08 09:06:46 INF mark 0x555dc7a20a20 pending writable
2019-07-08 09:06:46 DBG lws_callback(context=0x555dc7a02b50, state=0x10e, reason=35, user=(nil))
2019-07-08 09:06:46 DBG _lws_change_pollfd: wsi 0x555dc7a20a20: fd 8 events 1 -> 5
2019-07-08 09:06:46 DBG lws_callback(context=0x555dc7a02b50, state=0x10e, reason=34, user=(nil))
2019-07-08 09:06:46 DBG lws_callback(context=0x555dc7a02b50, state=0x10e, reason=36, user=(nil))
2019-07-08 09:06:46 INF lws_h2_issue_preface: h2 client sending settings
2019-07-08 09:06:46 INF rops_handle_POLLIN_h2: wsistate 0x1000010e, pollout 4
2019-07-08 09:06:46 INF servicing pps
2019-07-08 09:06:46 INF lws_h2_do_pps_send: 0x555dc7a20a20: 1
2019-07-08 09:06:46 DBG sending SETTING 1 0x10000
2019-07-08 09:06:46 DBG sending SETTING 3 0x18
2019-07-08 09:06:46 DBG sending SETTING 6 0x1000
2019-07-08 09:06:46 DBG sending SETTING 8 0x1
2019-07-08 09:06:46 DBG lws_h2_frame_write: 0x555dc7a20a20 (eff 0x555dc7a20a20). typ 4, fl 0x0, sid=0, len=24, txcr=65535, nwsi->txcr=65535
2019-07-08 09:06:46 INF lws_issue_raw: ssl_capable_write (33) says 33
2019-07-08 09:06:46 DBG 0x555dc7a20a20: SSL_read says 40
2019-07-08 09:06:46 DBG __lws_set_timeout: 0x555dc7a20a20: 31 secs (reason 15)
2019-07-08 09:06:46 DBG 0x555dc7a20a20 (0x555dc7a20a20): fr hdr: typ 0x4, fla 0x0, sid 0x0, len 0x12
2019-07-08 09:06:46 INF lws_h2_parse_frame_header: wsi 0x555dc7a20a20, State: LWS_H2S_IDLE, received cmd 4
2019-07-08 09:06:46 INF LWS_H2_FRAME_TYPE_SETTINGS complete frame
2019-07-08 09:06:46 DBG _realloc: size 56: pps
2019-07-08 09:06:46 INF mark 0x555dc7a20a20 pending writable
2019-07-08 09:06:46 DBG lws_callback(context=0x555dc7a02b50, state=0x10e, reason=35, user=(nil))
2019-07-08 09:06:46 DBG _lws_change_pollfd: wsi 0x555dc7a20a20: fd 8 events 5 -> 5
2019-07-08 09:06:46 DBG lws_callback(context=0x555dc7a02b50, state=0x10e, reason=34, user=(nil))
2019-07-08 09:06:46 DBG lws_callback(context=0x555dc7a02b50, state=0x10e, reason=36, user=(nil))
2019-07-08 09:06:46 INF http2 settings 3 <- 0x80
2019-07-08 09:06:46 INF http2 settings 4 <- 0x10000
2019-07-08 09:06:46 INF http2 settings 5 <- 0xffffff
2019-07-08 09:06:46 INF initial tx credit on master 0x555dc7a20a20: 65536
2019-07-08 09:06:46 DBG _realloc: size 544: new server wsi
2019-07-08 09:06:46 DBG new wsi 0x555dc7a39640 joining vhost default, tsi 0
2019-07-08 09:06:46 INF lws_vhost_bind_wsi: vh default: count_bound_wsi 2
2019-07-08 09:06:46 DBG lwsi_set_state(0x555dc7a39640, 0x200)
2019-07-08 09:06:46 DBG lws_callback(context=0x555dc7a02b50, state=0x200, reason=29, user=(nil))
2019-07-08 09:06:46 DBG lwsi_set_state(0x555dc7a39640, 0x117)
2019-07-08 09:06:46 DBG lwsi_set_role(0x555dc7a39640, 0x10000117)
2019-07-08 09:06:46 DBG lws_ensure_user_space: 0x555dc7a39640 protocol pss 0, user_space=(nil)
2019-07-08 09:06:46 INF lws_wsi_server_new: 0x555dc7a20a20 new ch 0x555dc7a39640, sid 1, usersp=(nil), tx cr 65536, peer_credit 65535 (nwsi tx_cr 65536)
2019-07-08 09:06:46 DBG lws_role_transition: 0x555dc7a20a20: wsistate 0x1000010e, ops h2
2019-07-08 09:06:46 DBG lws_role_transition: 0x555dc7a39640: wsistate 0x1000010e, ops h2
2019-07-08 09:06:46 INF lws_h2_parse_end_of_frame: MIGRATING nwsi 0x555dc7a20a20: swsi 0x555dc7a39640
2019-07-08 09:06:46 INF initial tx credit on conn 0x555dc7a39640: 65536
2019-07-08 09:06:46 INF mark 0x555dc7a39640 pending writable
2019-07-08 09:06:46 INF mark 0x555dc7a20a20 pending writable
2019-07-08 09:06:46 DBG lws_callback(context=0x555dc7a02b50, state=0x10e, reason=35, user=(nil))
2019-07-08 09:06:46 DBG _lws_change_pollfd: wsi 0x555dc7a20a20: fd 8 events 5 -> 5
2019-07-08 09:06:46 DBG lws_callback(context=0x555dc7a02b50, state=0x10e, reason=34, user=(nil))
2019-07-08 09:06:46 DBG lws_callback(context=0x555dc7a02b50, state=0x10e, reason=36, user=(nil))
2019-07-08 09:06:46 DBG _realloc: size 56: pps
2019-07-08 09:06:46 INF mark 0x555dc7a20a20 pending writable
2019-07-08 09:06:46 DBG lws_callback(context=0x555dc7a02b50, state=0x10e, reason=35, user=(nil))
2019-07-08 09:06:46 DBG _lws_change_pollfd: wsi 0x555dc7a20a20: fd 8 events 5 -> 5
2019-07-08 09:06:46 DBG lws_callback(context=0x555dc7a02b50, state=0x10e, reason=34, user=(nil))
2019-07-08 09:06:46 DBG lws_callback(context=0x555dc7a02b50, state=0x10e, reason=36, user=(nil))
2019-07-08 09:06:46 INF lws_h2_parse_end_of_frame: scheduled settings ack PPS
2019-07-08 09:06:46 DBG __lws_set_timeout: 0x555dc7a20a20: 31 secs (reason 15)
2019-07-08 09:06:46 DBG 0x555dc7a20a20 (0x555dc7a20a20): fr hdr: typ 0x8, fla 0x0, sid 0x0, len 0x4
2019-07-08 09:06:46 INF lws_h2_parse_frame_header: wsi 0x555dc7a20a20, State: LWS_H2S_IDLE, received cmd 8
2019-07-08 09:06:46 INF LWS_H2_FRAME_TYPE_WINDOW_UPDATE
2019-07-08 09:06:46 INF WINDOW_UPDATE: sid 0 2147418112 (0x7fff0000)
2019-07-08 09:06:46 DBG _realloc: size 56: pps
2019-07-08 09:06:46 INF lws_h2_goaway: 0x555dc7a20a20: ERR 0x3, 'Flow control exceeded max'

Andreas

________________________________________
From: Andy Green [andy at warmcat.com]
Sent: Sunday, July 07, 2019 6:51 PM
To: Andreas Lobbes; libwebsockets at ml.libwebsockets.org
Subject: Re: [Libwebsockets] Settings Frame size above max / Flow control exceeded max

On 7/7/19 5:20 PM, Andreas Lobbes wrote:
> Hello Andy,
>
> wouldn't it be better, to handle those strange, but legal parameter per option?

At least for the 16M-1 thing, we should accept it even though it's kind
of unrealistic.  It's a bug we drew the line at 8M-1, so no... fixing
the bug and matching the spec as I did earlier is definitely ideal
there.  It's just telling us about its frame size limit... we don't have
to go up to the limit or anything.  However we are required to actively
reject anything above 16M-1.

> OpenSSL for example offers such a feature, to work around dozens of mickysoft implementation bugs:
> https://www.openssl.org/docs/man1.1.0/man3/SSL_CTX_clear_options.html
> see macro SSL_OP_ALL and all defs above.

I understand but for this first problem, we don't need to get into it
assuming the peer sends a compliant 16M-1 or less max frame size.  That
problem should go away with the fix I pushed.

> If OpenSSL did not offer such workarounds, a lot developer were not able to use it.
> This in turn would neither have helped the developers nor the OpenSSL project to become widely accepted..

For the second case, I fear the both the implementation bugs are on my
side... as it says in the spec when we hear about the SETTINGS change
(6.9.2)

  In addition to changing the flow-control window for streams that are
    not yet active, a SETTINGS frame can alter the initial flow-control
    window size for streams with active flow-control windows (that is,
    streams in the "open" or "half-closed (remote)" state).  When the
    value of SETTINGS_INITIAL_WINDOW_SIZE changes, a receiver MUST adjust
    the size of all stream flow-control windows that it maintains by the
    difference between the new value and the old value.

Looking closely at what we do, we do try to do that, but we're adapting
our own outgoing tx credit... but it says "a receiver".  So I think we
should perhaps have adapted our estimate of the peer's tx credit towards
us... I pushed a patch on v3.1-stable and master changing to do that.

If so, that'll also make this off-by-one WINDOW_UPDATE problem go away.

-Andy


> Kind regards,
> Andreas
>
> ________________________________________
> From: Andy Green [andy at warmcat.com]
> Sent: Sunday, July 07, 2019 1:42 PM
> To: Andreas Lobbes; libwebsockets at ml.libwebsockets.org
> Subject: Re: [Libwebsockets] Settings Frame size above max / Flow control exceeded max
>
> On 7/7/19 11:42 AM, Andreas Lobbes wrote:
>> Hi,
>>
>> I try to make a https-request. In contrast to other sites, for this
>> specific site the request does not succeed.
>> The only hint I found in the log (see below) is "INF lws_h2_goaway:
>> 0x55ebbce7ca20: ERR 0x1, 'Settings Frame size above max'". I suppose
>> this is the root cause. Any I idea what that does mean?
>
> Well, props for sending usable logs from the get-go.
>
>> 2019-07-07 11:34:56 INF http2 settings 3 <- 0x80
>> 2019-07-07 11:34:56 INF http2 settings 4 <- 0x10000
>> 2019-07-07 11:34:56 DBG _realloc: size 56: pps
>> 2019-07-07 11:34:56 INF lws_h2_goaway: 0x55ebbce7ca20: ERR 0x1,
>> 'Settings Frame size above max'
>
> The peer is sending a huge max frame size... above 16M-1 we're supposed
> to reject it with PROTOCOL_ERROR like this.  But actually, we reject it
> at 8M-1 as it is... it's a bug... I pushed a patch on v3.1-stable and
> master that fixes it.
>
> Although it's a bug to reject it... actually huge frame sizes 16M or 8M
> generally don't make any sense... not just for latency (they would block
> muxing until all 8M or 16M was sent) but for scalability, 1000 peers
> taking it up on these monster frames and sending the on different
> connections could allocate up to 16GB heap then.  So the peer should not
> really be advertising this even though it's legal.
>
>> 2019-07-07 11:34:56 INF LWS_H2_FRAME_TYPE_WINDOW_UPDATE
>> 2019-07-07 11:34:56 INF WINDOW_UPDATE: sid 0 2147418112 (0x7fff0000)
>> 2019-07-07 11:34:56 DBG _realloc: size 56: pps
>> 2019-07-07 11:34:56 INF lws_h2_goaway: 0x55ebbce7ca20: ERR 0x3, 'Flow
>> control exceeded max'
>
> The tx credit window is not allowed to exceed 0x7fffffff.  The peer also
> took a maximalist approach and told us we should bump our tx credit by
> 0x7fff0000.  Unfortunately it told us its tx credit was 0x10000 and we
> adjusted our side to that already, so it comes to 0x80000000 IIUI.
>
> Again tx credit window is a scheme to dynamically stop streams
> monopolizing the multiplexed wire protocol... the combination of huge
> frames and a license for any stream to spam 128 of those in succession
> won't give good results for other streams or latency if the peer takes
> them up on it.
>
> -Andy
>


More information about the Libwebsockets mailing list