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

Andreas Lobbes Andreas.Lobbes at thinprint.com
Tue Jul 9 17:53:12 CEST 2019


Hello Andy,

regarding "frame size", this is not the end, unfortunately.
When using my implementation to generate a bit more complicate request,
I receive this log:

2019-07-09 17:20:15 INF lws_client_connect_2: 0x557ddd120a20: address account.dev.azdev.ezeep.com
2019-07-09 17:20:15 DBG connected
2019-07-09 17:20:15 INF lws_client_connect_2: wsi 0x557ddd120a20: client creating own connection
2019-07-09 17:20:15 DBG lwsi_set_state(0x557ddd120a20, 0x10000011)
2019-07-09 17:20:15 DBG __lws_set_timeout: 0x557ddd120a20: 20 secs (reason 8)
2019-07-09 17:20:15 DBG lws_callback(context=0x557ddd102b50, state=0x11, reason=35, user=(nil))
2019-07-09 17:20:15 DBG _lws_change_pollfd: wsi 0x557ddd120a20: fd 8 events 1 -> 1
2019-07-09 17:20:15 DBG lws_callback(context=0x557ddd102b50, state=0x11, reason=34, user=(nil))
2019-07-09 17:20:15 DBG lws_callback(context=0x557ddd102b50, state=0x11, reason=36, user=(nil))
2019-07-09 17:20:15 INF client conn using alpn list 'h2,http/1.1'
2019-07-09 17:20:15 DBG lws_ssl_get_error: 0x557ddd123b30 -1 -> 2 (errno 11)
2019-07-09 17:20:15 DBG lwsi_set_state(0x557ddd120a20, 0x10000203)
2019-07-09 17:20:15 DBG lws_callback(context=0x557ddd102b50, state=0x203, reason=58, user=0x557ddd138d70)
2019-07-09 17:20:15 DBG lws_callback(context=0x557ddd102b50, state=0x203, reason=58, user=0x557ddd138d70)
2019-07-09 17:20:15 DBG lws_callback(context=0x557ddd102b50, state=0x203, reason=58, user=0x557ddd138d70)
2019-07-09 17:20:15 DBG lws_ssl_get_error: 0x557ddd123b30 -1 -> 2 (errno 11)
2019-07-09 17:20:15 DBG lws_ssl_client_connect2: SSL_connect says -2
2019-07-09 17:20:15 DBG lwsi_set_state(0x557ddd120a20, 0x10000203)
2019-07-09 17:20:15 INF lws_role_call_alpn_negotiated: 'h2'
2019-07-09 17:20:15 DBG rops_alpn_negotiated_h2: client 1
2019-07-09 17:20:15 INF rops_alpn_negotiated_h2: upgraded to H2
2019-07-09 17:20:15 DBG lws_role_transition: 0x557ddd120a20: wsistate 0x2000020b, ops h2
2019-07-09 17:20:15 DBG _realloc: size 216: h2n
2019-07-09 17:20:15 INF lws_hpack_dynamic_size: from 0 to 65536, lim 65536
2019-07-09 17:20:15 DBG _realloc: size 131088: dynamic table entries
2019-07-09 17:20:15 INF rops_alpn_negotiated_h2: wsi 0x557ddd120a20: configured for h2
2019-07-09 17:20:15 INF client connect OK
2019-07-09 17:20:15 INF lws_openssl_describe_cipher: wsi 0x557ddd120a20: ECDHE-RSA-AES256-GCM-SHA384, ECDHE-RSA-AES256-GCM-SHA384, 256 bits, TLSv1.2
2019-07-09 17:20:15 DBG lws_ssl_client_connect2: SSL_connect says 0
2019-07-09 17:20:15 DBG get_verify says 0
2019-07-09 17:20:15 INF negotiated 'h2' using ALPN
2019-07-09 17:20:15 INF lws_role_call_alpn_negotiated: 'h2'
2019-07-09 17:20:15 DBG rops_alpn_negotiated_h2: client 0
2019-07-09 17:20:15 DBG lws_role_transition: 0x557ddd120a20: wsistate 0x2000020b, ops h2
2019-07-09 17:20:15 INF lws_hpack_dynamic_size: from 8192 to 65536, lim 65536
2019-07-09 17:20:15 INF rops_alpn_negotiated_h2: wsi 0x557ddd120a20: configured for h2
2019-07-09 17:20:15 INF lws_issue_raw: ssl_capable_write (24) says 24
2019-07-09 17:20:15 DBG lws_role_transition: 0x557ddd120a20: wsistate 0x1000010e, ops h2
2019-07-09 17:20:15 DBG _realloc: size 56: pps
2019-07-09 17:20:15 INF mark 0x557ddd120a20 pending writable
2019-07-09 17:20:15 DBG lws_callback(context=0x557ddd102b50, state=0x10e, reason=35, user=(nil))
2019-07-09 17:20:15 DBG _lws_change_pollfd: wsi 0x557ddd120a20: fd 8 events 1 -> 5
2019-07-09 17:20:15 DBG lws_callback(context=0x557ddd102b50, state=0x10e, reason=34, user=(nil))
2019-07-09 17:20:15 DBG lws_callback(context=0x557ddd102b50, state=0x10e, reason=36, user=(nil))
2019-07-09 17:20:15 INF lws_h2_issue_preface: h2 client sending settings
2019-07-09 17:20:15 INF rops_handle_POLLIN_h2: wsistate 0x1000010e, pollout 4
2019-07-09 17:20:15 INF servicing pps
2019-07-09 17:20:15 INF lws_h2_do_pps_send: 0x557ddd120a20: 1
2019-07-09 17:20:15 DBG sending SETTING 1 0x10000
2019-07-09 17:20:15 DBG sending SETTING 3 0x18
2019-07-09 17:20:15 DBG sending SETTING 6 0x1000
2019-07-09 17:20:15 DBG sending SETTING 8 0x1
2019-07-09 17:20:15 DBG lws_h2_frame_write: 0x557ddd120a20 (eff 0x557ddd120a20). typ 4, fl 0x0, sid=0, len=24, txcr=65535, nwsi->txcr=65535
2019-07-09 17:20:15 INF lws_issue_raw: ssl_capable_write (33) says 33
2019-07-09 17:20:15 DBG 0x557ddd120a20: SSL_read says 40
2019-07-09 17:20:15 DBG 
2019-07-09 17:20:15 DBG 0000: 00 00 12 04 00 00 00 00 00 00 03 00 00 00 80 00    ................
2019-07-09 17:20:15 DBG 0010: 04 00 01 00 00 00 05 00 FF FF FF 00 00 04 08 00    ................
2019-07-09 17:20:15 DBG 0020: 00 00 00 00 7F FF 00 00                            ........        
2019-07-09 17:20:15 DBG 
2019-07-09 17:20:15 DBG __lws_set_timeout: 0x557ddd120a20: 31 secs (reason 15)
2019-07-09 17:20:15 DBG 0x557ddd120a20 (0x557ddd120a20): fr hdr: typ 0x4, fla 0x0, sid 0x0, len 0x12
2019-07-09 17:20:15 INF lws_h2_parse_frame_header: wsi 0x557ddd120a20, State: LWS_H2S_IDLE, received cmd 4
2019-07-09 17:20:15 INF LWS_H2_FRAME_TYPE_SETTINGS complete frame
2019-07-09 17:20:15 DBG _realloc: size 56: pps
2019-07-09 17:20:15 INF mark 0x557ddd120a20 pending writable
2019-07-09 17:20:15 DBG lws_callback(context=0x557ddd102b50, state=0x10e, reason=35, user=(nil))
2019-07-09 17:20:15 DBG _lws_change_pollfd: wsi 0x557ddd120a20: fd 8 events 5 -> 5
2019-07-09 17:20:15 DBG lws_callback(context=0x557ddd102b50, state=0x10e, reason=34, user=(nil))
2019-07-09 17:20:15 DBG lws_callback(context=0x557ddd102b50, state=0x10e, reason=36, user=(nil))
2019-07-09 17:20:15 INF http2 settings 3 <- 0x80
2019-07-09 17:20:15 INF http2 settings 4 <- 0x10000
2019-07-09 17:20:15 INF http2 settings 5 <- 0xffffff
2019-07-09 17:20:15 INF initial tx credit on master 0x557ddd120a20: 65536
2019-07-09 17:20:15 DBG _realloc: size 544: new server wsi
2019-07-09 17:20:15 DBG new wsi 0x557ddd1395e0 joining vhost default, tsi 0
2019-07-09 17:20:15 INF lws_vhost_bind_wsi: vh default: count_bound_wsi 2
2019-07-09 17:20:15 DBG lwsi_set_state(0x557ddd1395e0, 0x200)
2019-07-09 17:20:15 DBG lws_callback(context=0x557ddd102b50, state=0x200, reason=29, user=(nil))
2019-07-09 17:20:15 DBG lwsi_set_state(0x557ddd1395e0, 0x117)
2019-07-09 17:20:15 DBG lwsi_set_role(0x557ddd1395e0, 0x10000117)
2019-07-09 17:20:15 DBG lws_ensure_user_space: 0x557ddd1395e0 protocol pss 0, user_space=(nil)
2019-07-09 17:20:15 INF lws_wsi_server_new: 0x557ddd120a20 new ch 0x557ddd1395e0, sid 1, usersp=(nil), tx cr 65536, peer_credit 65535 (nwsi tx_cr 65536)
2019-07-09 17:20:15 DBG lws_role_transition: 0x557ddd120a20: wsistate 0x1000010e, ops h2
2019-07-09 17:20:15 DBG lws_role_transition: 0x557ddd1395e0: wsistate 0x1000010e, ops h2
2019-07-09 17:20:15 INF lws_h2_parse_end_of_frame: MIGRATING nwsi 0x557ddd120a20: swsi 0x557ddd1395e0
2019-07-09 17:20:15 INF initial tx credit on conn 0x557ddd1395e0: 65536
2019-07-09 17:20:15 INF mark 0x557ddd1395e0 pending writable
2019-07-09 17:20:15 INF mark 0x557ddd120a20 pending writable
2019-07-09 17:20:15 DBG lws_callback(context=0x557ddd102b50, state=0x10e, reason=35, user=(nil))
2019-07-09 17:20:15 DBG _lws_change_pollfd: wsi 0x557ddd120a20: fd 8 events 5 -> 5
2019-07-09 17:20:15 DBG lws_callback(context=0x557ddd102b50, state=0x10e, reason=34, user=(nil))
2019-07-09 17:20:15 DBG lws_callback(context=0x557ddd102b50, state=0x10e, reason=36, user=(nil))
2019-07-09 17:20:15 DBG _realloc: size 56: pps
2019-07-09 17:20:15 INF mark 0x557ddd120a20 pending writable
2019-07-09 17:20:15 DBG lws_callback(context=0x557ddd102b50, state=0x10e, reason=35, user=(nil))
2019-07-09 17:20:15 DBG _lws_change_pollfd: wsi 0x557ddd120a20: fd 8 events 5 -> 5
2019-07-09 17:20:15 DBG lws_callback(context=0x557ddd102b50, state=0x10e, reason=34, user=(nil))
2019-07-09 17:20:15 DBG lws_callback(context=0x557ddd102b50, state=0x10e, reason=36, user=(nil))
2019-07-09 17:20:15 INF lws_h2_parse_end_of_frame: scheduled settings ack PPS
2019-07-09 17:20:15 DBG __lws_set_timeout: 0x557ddd120a20: 31 secs (reason 15)
2019-07-09 17:20:15 DBG 0x557ddd120a20 (0x557ddd120a20): fr hdr: typ 0x8, fla 0x0, sid 0x0, len 0x4
2019-07-09 17:20:15 INF lws_h2_parse_frame_header: wsi 0x557ddd120a20, State: LWS_H2S_IDLE, received cmd 8
2019-07-09 17:20:15 INF LWS_H2_FRAME_TYPE_WINDOW_UPDATE
2019-07-09 17:20:15 INF WINDOW_UPDATE: sid 0 2147418112 (0x7fff0000)
2019-07-09 17:20:15 DBG already pending writable
2019-07-09 17:20:15 INF rops_handle_POLLIN_h2: wsistate 0x1000010e, pollout 4
2019-07-09 17:20:15 INF servicing pps
2019-07-09 17:20:15 INF lws_h2_do_pps_send: 0x557ddd120a20: 2
2019-07-09 17:20:15 DBG lws_h2_frame_write: 0x557ddd120a20 (eff 0x557ddd120a20). typ 4, fl 0x1, sid=0, len=0, txcr=2147483647, nwsi->txcr=2147483647
2019-07-09 17:20:15 INF lws_issue_raw: ssl_capable_write (9) says 9
2019-07-09 17:20:15 INF rops_handle_POLLIN_h2: wsistate 0x1000010e, pollout 4
2019-07-09 17:20:15 INF servicing pps
2019-07-09 17:20:15 INF lws_h2_do_pps_send: 0x557ddd120a20: 2
2019-07-09 17:20:15 DBG lws_h2_frame_write: 0x557ddd120a20 (eff 0x557ddd120a20). typ 4, fl 0x1, sid=0, len=0, txcr=2147483647, nwsi->txcr=2147483647
2019-07-09 17:20:15 INF lws_issue_raw: ssl_capable_write (9) says 9
2019-07-09 17:20:15 INF rops_handle_POLLIN_h2: wsistate 0x1000010e, pollout 4
2019-07-09 17:20:15 DBG lws_callback(context=0x557ddd102b50, state=0x10e, reason=35, user=(nil))
2019-07-09 17:20:15 DBG _lws_change_pollfd: wsi 0x557ddd120a20: fd 8 events 5 -> 1
2019-07-09 17:20:15 DBG lws_callback(context=0x557ddd102b50, state=0x10e, reason=34, user=(nil))
2019-07-09 17:20:15 DBG lws_callback(context=0x557ddd102b50, state=0x10e, reason=36, user=(nil))
2019-07-09 17:20:15 INF lws_h2_dump_waiting_children: 0x557ddd120a20: children waiting for POLLOUT service:
2019-07-09 17:20:15 INF   * 0x557ddd1395e0 h2 (null)
2019-07-09 17:20:15 DBG servicing child 0x557ddd1395e0
2019-07-09 17:20:15 DBG w=0x557ddd1395e0, *wsi2 = 0x557ddd1395e0
2019-07-09 17:20:15 INF rops_perform_user_POLLOUT_h2: child 0x557ddd1395e0 (wsistate 0x1000010e)
2019-07-09 17:20:15 INF lws_h2_client_handshake: CLIENT_WAITING_TO_SEND_HEADERS: pollout (sid 3)
2019-07-09 17:20:15 DBG _realloc: size 56: pps
2019-07-09 17:20:15 INF mark 0x557ddd1395e0 pending writable
2019-07-09 17:20:15 INF mark 0x557ddd120a20 pending writable
2019-07-09 17:20:15 DBG lws_callback(context=0x557ddd102b50, state=0x10e, reason=35, user=(nil))
2019-07-09 17:20:15 DBG _lws_change_pollfd: wsi 0x557ddd120a20: fd 8 events 1 -> 5
2019-07-09 17:20:15 DBG lws_callback(context=0x557ddd102b50, state=0x10e, reason=34, user=(nil))
2019-07-09 17:20:15 DBG lws_callback(context=0x557ddd102b50, state=0x10e, reason=36, user=(nil))
2019-07-09 17:20:15 DBG _realloc: size 56: pps
2019-07-09 17:20:15 DBG already pending writable
2019-07-09 17:20:15 DBG lws_add_http2_header_by_name: 0x557ddd102ea0  :method:POST
2019-07-09 17:20:15 DBG lws_add_http2_header_by_name: 0x557ddd102eae  :scheme:https
2019-07-09 17:20:15 DBG lws_add_http2_header_by_name: 0x557ddd102ebc  :path:/oauth/access_token/
2019-07-09 17:20:15 DBG lws_add_http2_header_by_name: 0x557ddd102ed8  :authority:account.dev.azdev.ezeep.com
2019-07-09 17:20:15 DBG lws_callback(context=0x557ddd102b50, state=0x10e, reason=24, user=(nil))
2019-07-09 17:20:15 DBG lws_poll(4080) = 86
2019-07-09 17:20:15 DBG already pending writable
2019-07-09 17:20:15 DBG lws_h2_frame_write: 0x557ddd1395e0 (eff 0x557ddd120a20). typ 1, fl 0x4, sid=3, len=270, txcr=65536, nwsi->txcr=2147483647
2019-07-09 17:20:15 INF lws_issue_raw: ssl_capable_write (279) says 279
2019-07-09 17:20:15 INF lws_h2_state: wsi 0x557ddd1395e0: state LWS_H2S_IDLE -> LWS_H2S_OPEN
2019-07-09 17:20:15 DBG lwsi_set_state(0x557ddd1395e0, 0x10000117)
2019-07-09 17:20:15 DBG lws_callback(context=0x557ddd102b50, state=0x10e, reason=35, user=(nil))
2019-07-09 17:20:15 DBG _lws_change_pollfd: wsi 0x557ddd120a20: fd 8 events 5 -> 5
2019-07-09 17:20:15 DBG lws_callback(context=0x557ddd102b50, state=0x10e, reason=34, user=(nil))
2019-07-09 17:20:15 DBG lws_callback(context=0x557ddd102b50, state=0x10e, reason=36, user=(nil))
2019-07-09 17:20:15 INF rops_handle_POLLIN_h2: wsistate 0x1000010e, pollout 4
2019-07-09 17:20:15 INF servicing pps
2019-07-09 17:20:15 INF lws_h2_do_pps_send: 0x557ddd120a20: 6
2019-07-09 17:20:15 DBG Issuing LWS_H2_PPS_UPDATE_WINDOW: sid 3: add 262144
2019-07-09 17:20:15 DBG lws_h2_frame_write: 0x557ddd120a20 (eff 0x557ddd120a20). typ 8, fl 0x0, sid=3, len=4, txcr=2147483647, nwsi->txcr=2147483647
2019-07-09 17:20:15 INF lws_issue_raw: ssl_capable_write (13) says 13
2019-07-09 17:20:15 INF rops_handle_POLLIN_h2: wsistate 0x1000010e, pollout 4
2019-07-09 17:20:15 INF servicing pps
2019-07-09 17:20:15 INF lws_h2_do_pps_send: 0x557ddd120a20: 6
2019-07-09 17:20:15 DBG Issuing LWS_H2_PPS_UPDATE_WINDOW: sid 0: add 262144
2019-07-09 17:20:15 DBG lws_h2_frame_write: 0x557ddd120a20 (eff 0x557ddd120a20). typ 8, fl 0x0, sid=0, len=4, txcr=2147483647, nwsi->txcr=2147483647
2019-07-09 17:20:15 INF lws_issue_raw: ssl_capable_write (13) says 13
2019-07-09 17:20:15 INF rops_handle_POLLIN_h2: wsistate 0x1000010e, pollout 4
2019-07-09 17:20:15 DBG lws_callback(context=0x557ddd102b50, state=0x10e, reason=35, user=(nil))
2019-07-09 17:20:15 DBG _lws_change_pollfd: wsi 0x557ddd120a20: fd 8 events 5 -> 1
2019-07-09 17:20:15 DBG lws_callback(context=0x557ddd102b50, state=0x10e, reason=34, user=(nil))
2019-07-09 17:20:15 DBG lws_callback(context=0x557ddd102b50, state=0x10e, reason=36, user=(nil))
2019-07-09 17:20:15 INF lws_h2_dump_waiting_children: 0x557ddd120a20: children waiting for POLLOUT service:
2019-07-09 17:20:15 INF   * 0x557ddd1395e0 h2 (null)
2019-07-09 17:20:15 DBG servicing child 0x557ddd1395e0
2019-07-09 17:20:15 DBG w=0x557ddd1395e0, *wsi2 = 0x557ddd1395e0
2019-07-09 17:20:15 INF rops_perform_user_POLLOUT_h2: child 0x557ddd1395e0 (wsistate 0x10000117)
2019-07-09 17:20:15 DBG lws_callback(context=0x557ddd102b50, state=0x117, reason=57, user=(nil))
2019-07-09 17:20:15 DBG lws_h2_frame_write: 0x557ddd1395e0 (eff 0x557ddd120a20). typ 0, fl 0x0, sid=3, len=86, txcr=65536, nwsi->txcr=2147483647
2019-07-09 17:20:15 INF lws_issue_raw: ssl_capable_write (95) says 95
2019-07-09 17:20:15 DBG lws_write(86) = 86
2019-07-09 17:20:15 DBG lws_poll(4080) = 0
2019-07-09 17:20:15 INF mark 0x557ddd1395e0 pending writable
2019-07-09 17:20:15 INF mark 0x557ddd120a20 pending writable
2019-07-09 17:20:15 DBG lws_callback(context=0x557ddd102b50, state=0x10e, reason=35, user=(nil))
2019-07-09 17:20:15 DBG _lws_change_pollfd: wsi 0x557ddd120a20: fd 8 events 1 -> 5
2019-07-09 17:20:15 DBG lws_callback(context=0x557ddd102b50, state=0x10e, reason=34, user=(nil))
2019-07-09 17:20:15 DBG lws_callback(context=0x557ddd102b50, state=0x10e, reason=36, user=(nil))
2019-07-09 17:20:15 DBG lws_callback(context=0x557ddd102b50, state=0x10e, reason=35, user=(nil))
2019-07-09 17:20:15 DBG _lws_change_pollfd: wsi 0x557ddd120a20: fd 8 events 5 -> 5
2019-07-09 17:20:15 DBG lws_callback(context=0x557ddd102b50, state=0x10e, reason=34, user=(nil))
2019-07-09 17:20:15 DBG lws_callback(context=0x557ddd102b50, state=0x10e, reason=36, user=(nil))
2019-07-09 17:20:15 INF rops_handle_POLLIN_h2: wsistate 0x1000010e, pollout 4
2019-07-09 17:20:15 DBG lws_callback(context=0x557ddd102b50, state=0x10e, reason=35, user=(nil))
2019-07-09 17:20:15 DBG _lws_change_pollfd: wsi 0x557ddd120a20: fd 8 events 5 -> 1
2019-07-09 17:20:15 DBG lws_callback(context=0x557ddd102b50, state=0x10e, reason=34, user=(nil))
2019-07-09 17:20:15 DBG lws_callback(context=0x557ddd102b50, state=0x10e, reason=36, user=(nil))
2019-07-09 17:20:15 INF lws_h2_dump_waiting_children: 0x557ddd120a20: children waiting for POLLOUT service:
2019-07-09 17:20:15 INF   * 0x557ddd1395e0 h2 (null)
2019-07-09 17:20:15 DBG servicing child 0x557ddd1395e0
2019-07-09 17:20:15 DBG w=0x557ddd1395e0, *wsi2 = 0x557ddd1395e0
2019-07-09 17:20:15 INF rops_perform_user_POLLOUT_h2: child 0x557ddd1395e0 (wsistate 0x10000117)
2019-07-09 17:20:15 DBG lws_callback(context=0x557ddd102b50, state=0x117, reason=57, user=(nil))
2019-07-09 17:20:15 INF rops_write_role_protocol_h2: 0x557ddd1395e0: setting END_STREAM
2019-07-09 17:20:15 DBG lws_h2_frame_write: 0x557ddd1395e0 (eff 0x557ddd120a20). typ 0, fl 0x1, sid=3, len=0, txcr=65450, nwsi->txcr=2147483561
2019-07-09 17:20:15 INF lws_issue_raw: ssl_capable_write (9) says 9
2019-07-09 17:20:15 INF lws_h2_state: wsi 0x557ddd1395e0: state LWS_H2S_OPEN -> LWS_H2S_HALF_CLOSED_LOCAL
2019-07-09 17:20:15 INF rops_handle_POLLIN_h2: wsistate 0x1000010e, pollout 0
2019-07-09 17:20:15 DBG 0x557ddd120a20: SSL_read says 9
2019-07-09 17:20:15 DBG 
2019-07-09 17:20:15 DBG 0000: 00 00 00 04 01 00 00 00 00                         .........       
2019-07-09 17:20:15 DBG 
2019-07-09 17:20:15 DBG __lws_set_timeout: 0x557ddd120a20: 31 secs (reason 15)
2019-07-09 17:20:15 DBG 0x557ddd120a20 (0x557ddd120a20): fr hdr: typ 0x4, fla 0x1, sid 0x0, len 0x0
2019-07-09 17:20:15 INF lws_h2_parse_frame_header: wsi 0x557ddd120a20, State: LWS_H2S_IDLE, received cmd 4
2019-07-09 17:20:15 INF LWS_H2_FRAME_TYPE_SETTINGS complete frame
2019-07-09 17:20:15 INF rops_handle_POLLIN_h2: wsistate 0x1000010e, pollout 0
2019-07-09 17:20:15 DBG 0x557ddd120a20: SSL_read says 30
2019-07-09 17:20:15 DBG 
2019-07-09 17:20:15 DBG 0000: 00 00 04 03 00 00 00 00 03 00 00 00 01 00 00 08    ................
2019-07-09 17:20:15 DBG 0010: 07 00 00 00 00 00 00 00 00 03 00 00 00 06          ..............  
2019-07-09 17:20:15 DBG 
2019-07-09 17:20:15 DBG __lws_set_timeout: 0x557ddd120a20: 31 secs (reason 15)
2019-07-09 17:20:15 DBG 0x557ddd120a20 (0x557ddd1395e0): fr hdr: typ 0x3, fla 0x0, sid 0x3, len 0x4
2019-07-09 17:20:15 INF lws_h2_parse_frame_header: wsi 0x557ddd1395e0, State: LWS_H2S_HALF_CLOSED_LOCAL, received cmd 3
2019-07-09 17:20:15 INF lws_h2_state: wsi 0x557ddd1395e0: state LWS_H2S_HALF_CLOSED_LOCAL -> LWS_H2S_CLOSED
2019-07-09 17:20:15 INF LWS_H2_FRAME_TYPE_RST_STREAM: sid 3: reason 0x1
2019-07-09 17:20:15 DBG __lws_set_timeout: 0x557ddd120a20: 31 secs (reason 15)
2019-07-09 17:20:15 DBG 0x557ddd120a20 (0x557ddd120a20): fr hdr: typ 0x7, fla 0x0, sid 0x0, len 0x8
2019-07-09 17:20:15 INF lws_h2_parse_frame_header: wsi 0x557ddd120a20, State: LWS_H2S_IDLE, received cmd 7
2019-07-09 17:20:15 DBG LWS_H2_FRAME_TYPE_GOAWAY received
2019-07-09 17:20:15 INF GOAWAY: last sid 3, error 0x00000006, string ''

I re-enabled hexdump in lws_ssl_capable_read().
The error code 6 in last line of log does mean "Frame size incorrect"
according to: https://www.iana.org/assignments/http2-parameters/http2-parameters.xhtml#error-code
I'm also on it..

State of the library source is: HEAD of branch 3.1 (73a4f86b) + cherry pick 3b44a745 of master

Regards,
Andreas

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

On 7/8/19 3:58 PM, Andreas Lobbes wrote:
> Hello Andy,
>
> success, I get the same response (400).
> OAuth is just a small subtask, to secure access to a WSS-Server (via bearer access token).

OAUTH2 isn't that small a task... I wanted to point out lws has JOSE
pieces, and there is a new tool on master, 'lws_sequencer_t' that should
help sequence and coordinate the various connections and states needed,
while still operating on the event loop, with its own timeout.

This may not seem particularly relevant at first, but consider OAUTH
sequencing wants three separate http conversations that have to happen
sequentially and each using information from the previous step.  Since
there's no single wsi involved, without lws_sequencer_t it is actually
difficult to coordinate this, and not really possible to do it in the
same event loop context.  Which means the alternative solutions are not
really reusable.

lws_sequencer_t is designed to sit above wsi lifetimes and receive
messages from the wsi protocols (or other threads) which are queued
until the sequencer receives them in the event loop.  From there it can
track state for a task (eg, OAUTH) that is longer-lived than any one wsi
it's using, manage retry / reconnect etc.

https://libwebsockets.org/git/libwebsockets/tree/READMEs/README.lws_sequencer.md
https://libwebsockets.org/git/libwebsockets/tree/include/libwebsockets/lws-sequencer.h

API unit test fetching 5 x URLs in sequence, one of which is expected to
time out and another which is expected to fail to connect

https://libwebsockets.org/git/libwebsockets/tree/minimal-examples/api-tests/api-test-lws_sequencer/main.c

> Main part is to bridge traffic from pipe/socket to WSS.

Not sure what that means to you, but eg lws supports RAW unix domain
sockets... that can put stuff in a ringbuffer (lws_ring) that's taken
out by a wss protocol wsi... or vice versa... this is the easier part
compared to OAUTH2 I think.

-Andy

> Andreas
>
>
> ________________________________________
> From: Andy Green [andy at warmcat.com]
> Sent: Monday, July 08, 2019 12:43 PM
> To: Andreas Lobbes; libwebsockets at ml.libwebsockets.org
> Subject: Re: [Libwebsockets] Settings Frame size above max / Flow control exceeded max
>
> On 7/8/19 10:56 AM, Andreas Lobbes wrote:
>
> Thanks.
>
>> ./libwebsockets-test-client -ohttps://account.dev.azdev.ezeep.com/oauth/access_token
>
> I can reproduce it... it's setting the HPACK dynamic size to 0
>
> [2019/07/08 11:16:10:4279] INFO: lws_hpack_dynamic_size: from 8192 to 0,
> lim 65536
>
> https://tools.ietf.org/html/rfc7541#section-6.3
>
> doesn't seem to say that has any special meaning other than the dynamic
> table should be emptied out and get a size of 0.  Then it sends a new
> entry for the now zero-sized dynamic table
>
> [2019/07/08 11:16:10:4281] HEADER:  HPKT_INDEXED_HDR_6_VALUE_INCR (hdr 54)
>
> ... I assume it's a convention that 0 means it should empty the dynamic
> HPACK table while keeping the allocation the same.
>
> I pushed on master a patch to implement that and another to add a vhost
> option flag to fix up overflowed WINDOW_UPDATE (and added the flag to
> the test client).
>
> With that I can get a 400 cleanly.
>
> Are you interested in implementing OAUTH client?
>
> -Andy
>


More information about the Libwebsockets mailing list