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

Andreas Lobbes Andreas.Lobbes at thinprint.com
Wed Jul 10 08:18:17 CEST 2019


Now ssl writes get logged too:

2019-07-10 08:08:54 DBG connected
2019-07-10 08:08:54 INF lws_client_connect_2: wsi 0x5587c55f4a20: client creating own connection
2019-07-10 08:08:54 DBG lwsi_set_state(0x5587c55f4a20, 0x10000011)
2019-07-10 08:08:54 DBG __lws_set_timeout: 0x5587c55f4a20: 20 secs (reason 8)
2019-07-10 08:08:54 DBG lws_callback(context=0x5587c55d6b50, state=0x11, reason=35, user=(nil))
2019-07-10 08:08:54 DBG _lws_change_pollfd: wsi 0x5587c55f4a20: fd 8 events 1 -> 1
2019-07-10 08:08:54 DBG lws_callback(context=0x5587c55d6b50, state=0x11, reason=34, user=(nil))
2019-07-10 08:08:54 DBG lws_callback(context=0x5587c55d6b50, state=0x11, reason=36, user=(nil))
2019-07-10 08:08:54 INF client conn using alpn list 'h2,http/1.1'
2019-07-10 08:08:54 DBG lws_ssl_get_error: 0x5587c55f7b30 -1 -> 2 (errno 11)
2019-07-10 08:08:54 DBG lwsi_set_state(0x5587c55f4a20, 0x10000203)
2019-07-10 08:08:54 DBG lws_callback(context=0x5587c55d6b50, state=0x203, reason=58, user=0x5587c560cd70)
2019-07-10 08:08:54 DBG lws_callback(context=0x5587c55d6b50, state=0x203, reason=58, user=0x5587c560cd70)
2019-07-10 08:08:54 DBG lws_callback(context=0x5587c55d6b50, state=0x203, reason=58, user=0x5587c560cd70)
2019-07-10 08:08:54 DBG lws_ssl_get_error: 0x5587c55f7b30 -1 -> 2 (errno 11)
2019-07-10 08:08:54 DBG lws_ssl_client_connect2: SSL_connect says -2
2019-07-10 08:08:54 DBG lwsi_set_state(0x5587c55f4a20, 0x10000203)
2019-07-10 08:08:55 INF lws_role_call_alpn_negotiated: 'h2'
2019-07-10 08:08:55 DBG rops_alpn_negotiated_h2: client 1
2019-07-10 08:08:55 INF rops_alpn_negotiated_h2: upgraded to H2
2019-07-10 08:08:55 DBG lws_role_transition: 0x5587c55f4a20: wsistate 0x2000020b, ops h2
2019-07-10 08:08:55 DBG _realloc: size 216: h2n
2019-07-10 08:08:55 INF lws_hpack_dynamic_size: from 0 to 65536, lim 65536
2019-07-10 08:08:55 DBG _realloc: size 131088: dynamic table entries
2019-07-10 08:08:55 INF rops_alpn_negotiated_h2: wsi 0x5587c55f4a20: configured for h2
2019-07-10 08:08:55 INF client connect OK
2019-07-10 08:08:55 INF lws_openssl_describe_cipher: wsi 0x5587c55f4a20: ECDHE-RSA-AES256-GCM-SHA384, ECDHE-RSA-AES256-GCM-SHA384, 256 bits, TLSv1.2
2019-07-10 08:08:55 DBG lws_ssl_client_connect2: SSL_connect says 0
2019-07-10 08:08:55 DBG get_verify says 0
2019-07-10 08:08:55 INF negotiated 'h2' using ALPN
2019-07-10 08:08:55 INF lws_role_call_alpn_negotiated: 'h2'
2019-07-10 08:08:55 DBG rops_alpn_negotiated_h2: client 0
2019-07-10 08:08:55 DBG lws_role_transition: 0x5587c55f4a20: wsistate 0x2000020b, ops h2
2019-07-10 08:08:55 INF lws_hpack_dynamic_size: from 8192 to 65536, lim 65536
2019-07-10 08:08:55 INF rops_alpn_negotiated_h2: wsi 0x5587c55f4a20: configured for h2
2019-07-10 08:08:55 DBG 
2019-07-10 08:08:55 DBG 0000: 50 52 49 20 2A 20 48 54 54 50 2F 32 2E 30 0D 0A    PRI * HTTP/2.0..
2019-07-10 08:08:55 DBG 0010: 0D 0A 53 4D 0D 0A 0D 0A                            ..SM....        
2019-07-10 08:08:55 DBG 
2019-07-10 08:08:55 INF lws_issue_raw: ssl_capable_write (24) says 24
2019-07-10 08:08:55 DBG lws_role_transition: 0x5587c55f4a20: wsistate 0x1000010e, ops h2
2019-07-10 08:08:55 DBG _realloc: size 56: pps
2019-07-10 08:08:55 INF mark 0x5587c55f4a20 pending writable
2019-07-10 08:08:55 DBG lws_callback(context=0x5587c55d6b50, state=0x10e, reason=35, user=(nil))
2019-07-10 08:08:55 DBG _lws_change_pollfd: wsi 0x5587c55f4a20: fd 8 events 1 -> 5
2019-07-10 08:08:55 DBG lws_callback(context=0x5587c55d6b50, state=0x10e, reason=34, user=(nil))
2019-07-10 08:08:55 DBG lws_callback(context=0x5587c55d6b50, state=0x10e, reason=36, user=(nil))
2019-07-10 08:08:55 INF lws_h2_issue_preface: h2 client sending settings
2019-07-10 08:08:55 INF rops_handle_POLLIN_h2: wsistate 0x1000010e, pollout 4
2019-07-10 08:08:55 INF servicing pps
2019-07-10 08:08:55 INF lws_h2_do_pps_send: 0x5587c55f4a20: 1
2019-07-10 08:08:55 DBG sending SETTING 1 0x10000
2019-07-10 08:08:55 DBG sending SETTING 3 0x18
2019-07-10 08:08:55 DBG sending SETTING 6 0x1000
2019-07-10 08:08:55 DBG sending SETTING 8 0x1
2019-07-10 08:08:55 DBG lws_h2_frame_write: 0x5587c55f4a20 (eff 0x5587c55f4a20). typ 4, fl 0x0, sid=0, len=24, txcr=65535, nwsi->txcr=65535
2019-07-10 08:08:55 DBG 
2019-07-10 08:08:55 DBG 0000: 00 00 18 04 00 00 00 00 00 00 01 00 01 00 00 00    ................
2019-07-10 08:08:55 DBG 0010: 03 00 00 00 18 00 06 00 00 10 00 00 08 00 00 00    ................
2019-07-10 08:08:55 DBG 0020: 01                                                 .               
2019-07-10 08:08:55 DBG 
2019-07-10 08:08:55 INF lws_issue_raw: ssl_capable_write (33) says 33
2019-07-10 08:08:55 DBG 0x5587c55f4a20: SSL_read says 40
2019-07-10 08:08:55 DBG 
2019-07-10 08:08:55 DBG 0000: 00 00 12 04 00 00 00 00 00 00 03 00 00 00 80 00    ................
2019-07-10 08:08:55 DBG 0010: 04 00 01 00 00 00 05 00 FF FF FF 00 00 04 08 00    ................
2019-07-10 08:08:55 DBG 0020: 00 00 00 00 7F FF 00 00                            ........        
2019-07-10 08:08:55 DBG 
2019-07-10 08:08:55 DBG __lws_set_timeout: 0x5587c55f4a20: 31 secs (reason 15)
2019-07-10 08:08:55 DBG 0x5587c55f4a20 (0x5587c55f4a20): fr hdr: typ 0x4, fla 0x0, sid 0x0, len 0x12
2019-07-10 08:08:55 INF lws_h2_parse_frame_header: wsi 0x5587c55f4a20, State: LWS_H2S_IDLE, received cmd 4
2019-07-10 08:08:55 INF LWS_H2_FRAME_TYPE_SETTINGS complete frame
2019-07-10 08:08:55 DBG _realloc: size 56: pps
2019-07-10 08:08:55 INF mark 0x5587c55f4a20 pending writable
2019-07-10 08:08:55 DBG lws_callback(context=0x5587c55d6b50, state=0x10e, reason=35, user=(nil))
2019-07-10 08:08:55 DBG _lws_change_pollfd: wsi 0x5587c55f4a20: fd 8 events 5 -> 5
2019-07-10 08:08:55 DBG lws_callback(context=0x5587c55d6b50, state=0x10e, reason=34, user=(nil))
2019-07-10 08:08:55 DBG lws_callback(context=0x5587c55d6b50, state=0x10e, reason=36, user=(nil))
2019-07-10 08:08:55 INF http2 settings 3 <- 0x80
2019-07-10 08:08:55 INF http2 settings 4 <- 0x10000
2019-07-10 08:08:55 INF http2 settings 5 <- 0xffffff
2019-07-10 08:08:55 INF initial tx credit on master 0x5587c55f4a20: 65536
2019-07-10 08:08:55 DBG _realloc: size 544: new server wsi
2019-07-10 08:08:55 DBG new wsi 0x5587c560d5e0 joining vhost default, tsi 0
2019-07-10 08:08:55 INF lws_vhost_bind_wsi: vh default: count_bound_wsi 2
2019-07-10 08:08:55 DBG lwsi_set_state(0x5587c560d5e0, 0x200)
2019-07-10 08:08:55 DBG lws_callback(context=0x5587c55d6b50, state=0x200, reason=29, user=(nil))
2019-07-10 08:08:55 DBG lwsi_set_state(0x5587c560d5e0, 0x117)
2019-07-10 08:08:55 DBG lwsi_set_role(0x5587c560d5e0, 0x10000117)
2019-07-10 08:08:55 DBG lws_ensure_user_space: 0x5587c560d5e0 protocol pss 0, user_space=(nil)
2019-07-10 08:08:55 INF lws_wsi_server_new: 0x5587c55f4a20 new ch 0x5587c560d5e0, sid 1, usersp=(nil), tx cr 65536, peer_credit 65535 (nwsi tx_cr 65536)
2019-07-10 08:08:55 DBG lws_role_transition: 0x5587c55f4a20: wsistate 0x1000010e, ops h2
2019-07-10 08:08:55 DBG lws_role_transition: 0x5587c560d5e0: wsistate 0x1000010e, ops h2
2019-07-10 08:08:55 INF lws_h2_parse_end_of_frame: MIGRATING nwsi 0x5587c55f4a20: swsi 0x5587c560d5e0
2019-07-10 08:08:55 INF initial tx credit on conn 0x5587c560d5e0: 65536
2019-07-10 08:08:55 INF mark 0x5587c560d5e0 pending writable
2019-07-10 08:08:55 INF mark 0x5587c55f4a20 pending writable
2019-07-10 08:08:55 DBG lws_callback(context=0x5587c55d6b50, state=0x10e, reason=35, user=(nil))
2019-07-10 08:08:55 DBG _lws_change_pollfd: wsi 0x5587c55f4a20: fd 8 events 5 -> 5
2019-07-10 08:08:55 DBG lws_callback(context=0x5587c55d6b50, state=0x10e, reason=34, user=(nil))
2019-07-10 08:08:55 DBG lws_callback(context=0x5587c55d6b50, state=0x10e, reason=36, user=(nil))
2019-07-10 08:08:55 DBG _realloc: size 56: pps
2019-07-10 08:08:55 INF mark 0x5587c55f4a20 pending writable
2019-07-10 08:08:55 DBG lws_callback(context=0x5587c55d6b50, state=0x10e, reason=35, user=(nil))
2019-07-10 08:08:55 DBG _lws_change_pollfd: wsi 0x5587c55f4a20: fd 8 events 5 -> 5
2019-07-10 08:08:55 DBG lws_callback(context=0x5587c55d6b50, state=0x10e, reason=34, user=(nil))
2019-07-10 08:08:55 DBG lws_callback(context=0x5587c55d6b50, state=0x10e, reason=36, user=(nil))
2019-07-10 08:08:55 INF lws_h2_parse_end_of_frame: scheduled settings ack PPS
2019-07-10 08:08:55 DBG __lws_set_timeout: 0x5587c55f4a20: 31 secs (reason 15)
2019-07-10 08:08:55 DBG 0x5587c55f4a20 (0x5587c55f4a20): fr hdr: typ 0x8, fla 0x0, sid 0x0, len 0x4
2019-07-10 08:08:55 INF lws_h2_parse_frame_header: wsi 0x5587c55f4a20, State: LWS_H2S_IDLE, received cmd 8
2019-07-10 08:08:55 INF LWS_H2_FRAME_TYPE_WINDOW_UPDATE
2019-07-10 08:08:55 INF WINDOW_UPDATE: sid 0 2147418112 (0x7fff0000)
2019-07-10 08:08:55 DBG already pending writable
2019-07-10 08:08:55 INF rops_handle_POLLIN_h2: wsistate 0x1000010e, pollout 4
2019-07-10 08:08:55 INF servicing pps
2019-07-10 08:08:55 INF lws_h2_do_pps_send: 0x5587c55f4a20: 2
2019-07-10 08:08:55 DBG lws_h2_frame_write: 0x5587c55f4a20 (eff 0x5587c55f4a20). typ 4, fl 0x1, sid=0, len=0, txcr=2147483647, nwsi->txcr=2147483647
2019-07-10 08:08:55 DBG 
2019-07-10 08:08:55 DBG 0000: 00 00 00 04 01 00 00 00 00                         .........       
2019-07-10 08:08:55 DBG 
2019-07-10 08:08:55 INF lws_issue_raw: ssl_capable_write (9) says 9
2019-07-10 08:08:55 INF rops_handle_POLLIN_h2: wsistate 0x1000010e, pollout 4
2019-07-10 08:08:55 INF servicing pps
2019-07-10 08:08:55 INF lws_h2_do_pps_send: 0x5587c55f4a20: 2
2019-07-10 08:08:55 DBG lws_h2_frame_write: 0x5587c55f4a20 (eff 0x5587c55f4a20). typ 4, fl 0x1, sid=0, len=0, txcr=2147483647, nwsi->txcr=2147483647
2019-07-10 08:08:55 DBG 
2019-07-10 08:08:55 DBG 0000: 00 00 00 04 01 00 00 00 00                         .........       
2019-07-10 08:08:55 DBG 
2019-07-10 08:08:55 INF lws_issue_raw: ssl_capable_write (9) says 9
2019-07-10 08:08:55 INF rops_handle_POLLIN_h2: wsistate 0x1000010e, pollout 4
2019-07-10 08:08:55 DBG lws_callback(context=0x5587c55d6b50, state=0x10e, reason=35, user=(nil))
2019-07-10 08:08:55 DBG _lws_change_pollfd: wsi 0x5587c55f4a20: fd 8 events 5 -> 1
2019-07-10 08:08:55 DBG lws_callback(context=0x5587c55d6b50, state=0x10e, reason=34, user=(nil))
2019-07-10 08:08:55 DBG lws_callback(context=0x5587c55d6b50, state=0x10e, reason=36, user=(nil))
2019-07-10 08:08:55 INF lws_h2_dump_waiting_children: 0x5587c55f4a20: children waiting for POLLOUT service:
2019-07-10 08:08:55 INF   * 0x5587c560d5e0 h2 (null)
2019-07-10 08:08:55 DBG servicing child 0x5587c560d5e0
2019-07-10 08:08:55 DBG w=0x5587c560d5e0, *wsi2 = 0x5587c560d5e0
2019-07-10 08:08:55 INF rops_perform_user_POLLOUT_h2: child 0x5587c560d5e0 (wsistate 0x1000010e)
2019-07-10 08:08:55 INF lws_h2_client_handshake: CLIENT_WAITING_TO_SEND_HEADERS: pollout (sid 3)
2019-07-10 08:08:55 DBG _realloc: size 56: pps
2019-07-10 08:08:55 INF mark 0x5587c560d5e0 pending writable
2019-07-10 08:08:55 INF mark 0x5587c55f4a20 pending writable
2019-07-10 08:08:55 DBG lws_callback(context=0x5587c55d6b50, state=0x10e, reason=35, user=(nil))
2019-07-10 08:08:55 DBG _lws_change_pollfd: wsi 0x5587c55f4a20: fd 8 events 1 -> 5
2019-07-10 08:08:55 DBG lws_callback(context=0x5587c55d6b50, state=0x10e, reason=34, user=(nil))
2019-07-10 08:08:55 DBG lws_callback(context=0x5587c55d6b50, state=0x10e, reason=36, user=(nil))
2019-07-10 08:08:55 DBG _realloc: size 56: pps
2019-07-10 08:08:55 DBG already pending writable
2019-07-10 08:08:55 DBG lws_add_http2_header_by_name: 0x5587c55d6ea0  :method:POST
2019-07-10 08:08:55 DBG lws_add_http2_header_by_name: 0x5587c55d6eae  :scheme:https
2019-07-10 08:08:55 DBG lws_add_http2_header_by_name: 0x5587c55d6ebc  :path:/oauth/access_token/
2019-07-10 08:08:55 DBG lws_add_http2_header_by_name: 0x5587c55d6ed8  :authority:account.dev.azdev.ezeep.com
2019-07-10 08:08:55 DBG lws_callback(context=0x5587c55d6b50, state=0x10e, reason=24, user=(nil))
2019-07-10 08:08:55 DBG lws_poll(4080) = 86
2019-07-10 08:08:55 DBG already pending writable
2019-07-10 08:08:55 DBG lws_h2_frame_write: 0x5587c560d5e0 (eff 0x5587c55f4a20). typ 1, fl 0x4, sid=3, len=270, txcr=65536, nwsi->txcr=2147483647
2019-07-10 08:08:55 DBG 
2019-07-10 08:08:55 DBG 0000: 00 01 0E 01 04 00 00 00 03 00 07 3A 6D 65 74 68    ...........:meth
2019-07-10 08:08:55 DBG 0010: 6F 64 04 50 4F 53 54 00 07 3A 73 63 68 65 6D 65    od.POST..:scheme
2019-07-10 08:08:55 DBG 0020: 04 68 74 74 70 00 05 3A 70 61 74 68 14 2F 6F 61    .http..:path./oa
2019-07-10 08:08:55 DBG 0030: 75 74 68 2F 61 63 63 65 73 73 5F 74 6F 6B 65 6E    uth/access_token
2019-07-10 08:08:55 DBG 0040: 2F 00 0A 3A 61 75 74 68 6F 72 69 74 79 1B 61 63    /..:authority.ac
2019-07-10 08:08:55 DBG 0050: 63 6F 75 6E 74 2E 64 65 76 2E 61 7A 64 65 76 2E    count.dev.azdev.
2019-07-10 08:08:55 DBG 0060: 65 7A 65 65 70 2E 63 6F 6D 61 75 74 68 6F 72 69    ezeep.comauthori
2019-07-10 08:08:55 DBG 0070: 7A 61 74 69 6F 6E 3A 20 42 61 73 69 63 20 XX XX    zation: Basic XX
2019-07-10 08:08:55 DBG 0080: XX XX XX XX XX XX XX XX XX XX XX XX XX XX XX XX    XXXXXXXXXXXXXXXX
2019-07-10 08:08:55 DBG 0090: XX XX XX XX XX XX XX XX XX XX XX XX XX XX XX XX    XXXXXXXXXXXXXXXX
2019-07-10 08:08:55 DBG 00A0: XX XX XX XX XX XX XX XX XX XX XX XX XX XX XX XX    XXXXXXXXXXXXXXXX
2019-07-10 08:08:55 DBG 00B0: XX XX XX XX XX XX 0D 0A 61 63 63 65 70 74 3A 20    XXXXXX..accept: 
2019-07-10 08:08:55 DBG 00C0: 61 70 70 6C 69 63 61 74 69 6F 6E 2F 6A 73 6F 6E    application/json
2019-07-10 08:08:55 DBG 00D0: 0D 0A 63 6F 6E 74 65 6E 74 2D 74 79 70 65 3A 20    ..content-type: 
2019-07-10 08:08:55 DBG 00E0: 61 70 70 6C 69 63 61 74 69 6F 6E 2F 78 2D 77 77    application/x-ww
2019-07-10 08:08:55 DBG 00F0: 77 2D 66 6F 72 6D 2D 75 72 6C 65 6E 63 6F 64 65    w-form-urlencode
2019-07-10 08:08:55 DBG 0100: 64 0D 0A 63 6F 6E 74 65 6E 74 2D 6C 65 6E 67 74    d..content-lengt
2019-07-10 08:08:55 DBG 0110: 68 3A 20 38 36 0D 0A                               h: 86..         
2019-07-10 08:08:55 DBG 
2019-07-10 08:08:55 INF lws_issue_raw: ssl_capable_write (279) says 279
2019-07-10 08:08:55 INF lws_h2_state: wsi 0x5587c560d5e0: state LWS_H2S_IDLE -> LWS_H2S_OPEN
2019-07-10 08:08:55 DBG lwsi_set_state(0x5587c560d5e0, 0x10000117)
2019-07-10 08:08:55 DBG lws_callback(context=0x5587c55d6b50, state=0x10e, reason=35, user=(nil))
2019-07-10 08:08:55 DBG _lws_change_pollfd: wsi 0x5587c55f4a20: fd 8 events 5 -> 5
2019-07-10 08:08:55 DBG lws_callback(context=0x5587c55d6b50, state=0x10e, reason=34, user=(nil))
2019-07-10 08:08:55 DBG lws_callback(context=0x5587c55d6b50, state=0x10e, reason=36, user=(nil))
2019-07-10 08:08:55 INF rops_handle_POLLIN_h2: wsistate 0x1000010e, pollout 4
2019-07-10 08:08:55 INF servicing pps
2019-07-10 08:08:55 INF lws_h2_do_pps_send: 0x5587c55f4a20: 6
2019-07-10 08:08:55 DBG Issuing LWS_H2_PPS_UPDATE_WINDOW: sid 3: add 262144
2019-07-10 08:08:55 DBG lws_h2_frame_write: 0x5587c55f4a20 (eff 0x5587c55f4a20). typ 8, fl 0x0, sid=3, len=4, txcr=2147483647, nwsi->txcr=2147483647
2019-07-10 08:08:55 DBG 
2019-07-10 08:08:55 DBG 0000: 00 00 04 08 00 00 00 00 03 00 04 00 00             .............   
2019-07-10 08:08:55 DBG 
2019-07-10 08:08:55 INF lws_issue_raw: ssl_capable_write (13) says 13
2019-07-10 08:08:55 INF rops_handle_POLLIN_h2: wsistate 0x1000010e, pollout 4
2019-07-10 08:08:55 INF servicing pps
2019-07-10 08:08:55 INF lws_h2_do_pps_send: 0x5587c55f4a20: 6
2019-07-10 08:08:55 DBG Issuing LWS_H2_PPS_UPDATE_WINDOW: sid 0: add 262144
2019-07-10 08:08:55 DBG lws_h2_frame_write: 0x5587c55f4a20 (eff 0x5587c55f4a20). typ 8, fl 0x0, sid=0, len=4, txcr=2147483647, nwsi->txcr=2147483647
2019-07-10 08:08:55 DBG 
2019-07-10 08:08:55 DBG 0000: 00 00 04 08 00 00 00 00 00 00 04 00 00             .............   
2019-07-10 08:08:55 DBG 
2019-07-10 08:08:55 INF lws_issue_raw: ssl_capable_write (13) says 13
2019-07-10 08:08:55 INF rops_handle_POLLIN_h2: wsistate 0x1000010e, pollout 4
2019-07-10 08:08:55 DBG lws_callback(context=0x5587c55d6b50, state=0x10e, reason=35, user=(nil))
2019-07-10 08:08:55 DBG _lws_change_pollfd: wsi 0x5587c55f4a20: fd 8 events 5 -> 1
2019-07-10 08:08:55 DBG lws_callback(context=0x5587c55d6b50, state=0x10e, reason=34, user=(nil))
2019-07-10 08:08:55 DBG lws_callback(context=0x5587c55d6b50, state=0x10e, reason=36, user=(nil))
2019-07-10 08:08:55 INF lws_h2_dump_waiting_children: 0x5587c55f4a20: children waiting for POLLOUT service:
2019-07-10 08:08:55 INF   * 0x5587c560d5e0 h2 (null)
2019-07-10 08:08:55 DBG servicing child 0x5587c560d5e0
2019-07-10 08:08:55 DBG w=0x5587c560d5e0, *wsi2 = 0x5587c560d5e0
2019-07-10 08:08:55 INF rops_perform_user_POLLOUT_h2: child 0x5587c560d5e0 (wsistate 0x10000117)
2019-07-10 08:08:55 DBG lws_callback(context=0x5587c55d6b50, state=0x117, reason=57, user=(nil))
2019-07-10 08:08:55 DBG lws_h2_frame_write: 0x5587c560d5e0 (eff 0x5587c55f4a20). typ 0, fl 0x0, sid=3, len=86, txcr=65536, nwsi->txcr=2147483647
2019-07-10 08:08:55 DBG 
2019-07-10 08:08:55 DBG 0000: 00 00 56 00 00 00 00 00 03 67 72 61 6E 74 5F 74    ..V......grant_t
2019-07-10 08:08:55 DBG 0010: 79 70 65 3D 72 65 66 72 65 73 68 5F 74 6F 6B 65    ype=refresh_toke
2019-07-10 08:08:55 DBG 0020: 6E 26 73 63 6F 70 65 3D 70 72 69 6E 74 69 6E 67    n&scope=printing
2019-07-10 08:08:55 DBG 0030: 26 72 65 66 72 65 73 68 5F 74 6F 6B 65 6E 3D 55    &refresh_token=U
2019-07-10 08:08:55 DBG 0040: 58 32 67 4F 52 78 66 51 35 6E 41 4E 74 6B 6D 43    X2gORxfQ5nANtkmC
2019-07-10 08:08:55 DBG 0050: 51 64 4C 51 4B 5A 4A 35 65 41 39 4E 4D 6A 58       QdLQKZJ5eA9NMjX 
2019-07-10 08:08:55 DBG 
2019-07-10 08:08:55 INF lws_issue_raw: ssl_capable_write (95) says 95
2019-07-10 08:08:55 DBG lws_write(86) = 86
2019-07-10 08:08:55 DBG lws_poll(4080) = 0
2019-07-10 08:08:55 INF mark 0x5587c560d5e0 pending writable
2019-07-10 08:08:55 INF mark 0x5587c55f4a20 pending writable
2019-07-10 08:08:55 DBG lws_callback(context=0x5587c55d6b50, state=0x10e, reason=35, user=(nil))
2019-07-10 08:08:55 DBG _lws_change_pollfd: wsi 0x5587c55f4a20: fd 8 events 1 -> 5
2019-07-10 08:08:55 DBG lws_callback(context=0x5587c55d6b50, state=0x10e, reason=34, user=(nil))
2019-07-10 08:08:55 DBG lws_callback(context=0x5587c55d6b50, state=0x10e, reason=36, user=(nil))
2019-07-10 08:08:55 DBG lws_callback(context=0x5587c55d6b50, state=0x10e, reason=35, user=(nil))
2019-07-10 08:08:55 DBG _lws_change_pollfd: wsi 0x5587c55f4a20: fd 8 events 5 -> 5
2019-07-10 08:08:55 DBG lws_callback(context=0x5587c55d6b50, state=0x10e, reason=34, user=(nil))
2019-07-10 08:08:55 DBG lws_callback(context=0x5587c55d6b50, state=0x10e, reason=36, user=(nil))
2019-07-10 08:08:55 INF rops_handle_POLLIN_h2: wsistate 0x1000010e, pollout 4
2019-07-10 08:08:55 DBG lws_callback(context=0x5587c55d6b50, state=0x10e, reason=35, user=(nil))
2019-07-10 08:08:55 DBG _lws_change_pollfd: wsi 0x5587c55f4a20: fd 8 events 5 -> 1
2019-07-10 08:08:55 DBG lws_callback(context=0x5587c55d6b50, state=0x10e, reason=34, user=(nil))
2019-07-10 08:08:55 DBG lws_callback(context=0x5587c55d6b50, state=0x10e, reason=36, user=(nil))
2019-07-10 08:08:55 INF lws_h2_dump_waiting_children: 0x5587c55f4a20: children waiting for POLLOUT service:
2019-07-10 08:08:55 INF   * 0x5587c560d5e0 h2 (null)
2019-07-10 08:08:55 DBG servicing child 0x5587c560d5e0
2019-07-10 08:08:55 DBG w=0x5587c560d5e0, *wsi2 = 0x5587c560d5e0
2019-07-10 08:08:55 INF rops_perform_user_POLLOUT_h2: child 0x5587c560d5e0 (wsistate 0x10000117)
2019-07-10 08:08:55 DBG lws_callback(context=0x5587c55d6b50, state=0x117, reason=57, user=(nil))
2019-07-10 08:08:55 INF rops_write_role_protocol_h2: 0x5587c560d5e0: setting END_STREAM
2019-07-10 08:08:55 DBG lws_h2_frame_write: 0x5587c560d5e0 (eff 0x5587c55f4a20). typ 0, fl 0x1, sid=3, len=0, txcr=65450, nwsi->txcr=2147483561
2019-07-10 08:08:55 DBG 
2019-07-10 08:08:55 DBG 0000: 00 00 00 00 01 00 00 00 03                         .........       
2019-07-10 08:08:55 DBG 
2019-07-10 08:08:55 INF lws_issue_raw: ssl_capable_write (9) says 9
2019-07-10 08:08:55 INF lws_h2_state: wsi 0x5587c560d5e0: state LWS_H2S_OPEN -> LWS_H2S_HALF_CLOSED_LOCAL
2019-07-10 08:08:55 INF rops_handle_POLLIN_h2: wsistate 0x1000010e, pollout 0
2019-07-10 08:08:55 DBG 0x5587c55f4a20: SSL_read says 9
2019-07-10 08:08:55 DBG 
2019-07-10 08:08:55 DBG 0000: 00 00 00 04 01 00 00 00 00                         .........       
2019-07-10 08:08:55 DBG 
2019-07-10 08:08:55 DBG __lws_set_timeout: 0x5587c55f4a20: 31 secs (reason 15)
2019-07-10 08:08:55 DBG 0x5587c55f4a20 (0x5587c55f4a20): fr hdr: typ 0x4, fla 0x1, sid 0x0, len 0x0
2019-07-10 08:08:55 INF lws_h2_parse_frame_header: wsi 0x5587c55f4a20, State: LWS_H2S_IDLE, received cmd 4
2019-07-10 08:08:55 INF LWS_H2_FRAME_TYPE_SETTINGS complete frame
2019-07-10 08:08:55 INF rops_handle_POLLIN_h2: wsistate 0x1000010e, pollout 0
2019-07-10 08:08:55 DBG 0x5587c55f4a20: SSL_read says 30
2019-07-10 08:08:55 DBG 
2019-07-10 08:08:55 DBG 0000: 00 00 04 03 00 00 00 00 03 00 00 00 01 00 00 08    ................
2019-07-10 08:08:55 DBG 0010: 07 00 00 00 00 00 00 00 00 03 00 00 00 06          ..............  
2019-07-10 08:08:55 DBG 
2019-07-10 08:08:55 DBG __lws_set_timeout: 0x5587c55f4a20: 31 secs (reason 15)
2019-07-10 08:08:55 DBG 0x5587c55f4a20 (0x5587c560d5e0): fr hdr: typ 0x3, fla 0x0, sid 0x3, len 0x4
2019-07-10 08:08:55 INF lws_h2_parse_frame_header: wsi 0x5587c560d5e0, State: LWS_H2S_HALF_CLOSED_LOCAL, received cmd 3
2019-07-10 08:08:55 INF lws_h2_state: wsi 0x5587c560d5e0: state LWS_H2S_HALF_CLOSED_LOCAL -> LWS_H2S_CLOSED
2019-07-10 08:08:55 INF LWS_H2_FRAME_TYPE_RST_STREAM: sid 3: reason 0x1
2019-07-10 08:08:55 DBG __lws_set_timeout: 0x5587c55f4a20: 31 secs (reason 15)
2019-07-10 08:08:55 DBG 0x5587c55f4a20 (0x5587c55f4a20): fr hdr: typ 0x7, fla 0x0, sid 0x0, len 0x8
2019-07-10 08:08:55 INF lws_h2_parse_frame_header: wsi 0x5587c55f4a20, State: LWS_H2S_IDLE, received cmd 7
2019-07-10 08:08:55 DBG LWS_H2_FRAME_TYPE_GOAWAY received
2019-07-10 08:08:55 INF GOAWAY: last sid 3, error 0x00000006, string ''
2019-07-10 08:08:55 DBG lws_read_h2: http2_parser bail: 1

Andreas

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

On 7/9/19 4:53 PM, Andreas Lobbes wrote:

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

You probably want to do the same on the write...  -->

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

If it's complaining about frame size, presumably it thinks something
wrong with what we sent it.

-Andy

> 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