Hi everybody,
We recently ran into an issue where new http2 sessions were getting
immediately closed, causing the initial set of requests to fail, and we
think it has to do with an websocket upgrade request that's included in the
initial handshake with haproxy. We have one haproxy cluster that handles
both http2 requests and websocket requests.
We have a page on our site that has a websocket connection running for a
long while. What's happening is that if you don't interact with the page
for a bit, long enough for the http2 session to be closed (which we see in
chrome's net internals <chrome://net-internals>), that if the next
interaction with the webpage kicks off http requests, they will all fail
with error `err_spdy_protocol_error`. Looking at the failed connection
attempt in net internals, we see that there was a COMPRESSION_ERROR. The
logs for the whole session are attached.
Turning off http2 seems to have fixed the issue, but we'd like to reenable
it. Have others experienced this? Is this something we can tune in our
configuration?
Thanks!
-- Yonatan
--
[image: Tock]
<https://www.exploretock.com/?utm_source=email&utm_medium=signature>
Yonatan Kogan
Staff Software Engineer
Tock / exploretock.com
<https://www.exploretock.com/?utm_source=email&utm_medium=signature>
1047806: HTTP2_SESSION
dashboard-staging.exploretock.com:443 (DIRECT)
Start Time: 2018-07-11 14:52:34.700
t=538927 [st= 0] +HTTP2_SESSION [dt=42]
--> host = "dashboard-staging.exploretock.com:443"
--> proxy = "DIRECT"
t=538927 [st= 0] HTTP2_SESSION_INITIALIZED
--> protocol = "h2"
--> source_dependency = 1047804 (SOCKET)
t=538927 [st= 0] HTTP2_SESSION_SEND_SETTINGS
--> settings = ["[id:1 (SETTINGS_HEADER_TABLE_SIZE)
value:65536]","[id:3 (SETTINGS_MAX_CONCURRENT_STREAMS) value:1000]","[id:4
(SETTINGS_INITIAL_WINDOW_SIZE) value:6291456]"]
t=538927 [st= 0] HTTP2_SESSION_UPDATE_RECV_WINDOW
--> delta = 15663105
--> window_size = 15728640
t=538927 [st= 0] HTTP2_SESSION_SEND_WINDOW_UPDATE
--> delta = 15663105
--> stream_id = 0
t=538930 [st= 3] HTTP2_SESSION_SEND_HEADERS
--> exclusive = true
--> fin = true
--> has_priority = true
--> :method: GET
:authority: dashboard-staging.exploretock.com
:scheme: https
:path: /assets/7388/images/favicon/favicon-32x32.png
pragma: no-cache
cache-control: no-cache
authorization: REDACTED
dnt: 1
user-agent: Mozilla/5.0 (Macintosh; Intel Mac OS X
10_13_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/67.0.3396.99
Safari/537.36
accept: image/webp,image/apng,image/*,*/*;q=0.8
referer: https://dashboard-staging.exploretock.com/
accept-encoding: gzip, deflate, br
accept-language: en-US,en;q=0.9
cookie: REDACTED
--> parent_stream_id = 0
--> source_dependency = 1047781 (HTTP_STREAM_JOB)
--> stream_id = 1
--> weight = 220
t=538930 [st= 3] HTTP2_SESSION_SEND_HEADERS
--> exclusive = true
--> fin = true
--> has_priority = true
--> :method: GET
:authority: dashboard-staging.exploretock.com
:scheme: https
:path: /api/business/day/note?date=2018-07-16
pragma: no-cache
cache-control: no-cache
authorization: REDACTED
x-tock-authorization: REDACTED
x-tock-build-number: 7388
x-tock-path: #/app/2018-07-16/calendar/day
dnt: 1
x-tock-scope: {"businessId":"4","businessGroupId":"2"}
user-agent: Mozilla/5.0 (Macintosh; Intel Mac OS X
10_13_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/67.0.3396.99
Safari/537.36
content-type: application/octet-stream
accept: application/octet-stream
x-tock-stream-format: proto
referer: https://dashboard-staging.exploretock.com/
accept-encoding: gzip, deflate, br
accept-language: en-US,en;q=0.9
cookie: REDACTED
--> parent_stream_id = 1
--> source_dependency = 1047781 (HTTP_STREAM_JOB)
--> stream_id = 3
--> weight = 220
t=538930 [st= 3] HTTP2_SESSION_SEND_HEADERS
--> exclusive = true
--> fin = false
--> has_priority = true
--> :method: POST
:authority: dashboard-staging.exploretock.com
:scheme: https
:path: /api/admin/calendar/integrations
content-length: 14
pragma: no-cache
cache-control: no-cache
authorization: REDACTED
x-tock-authorization: REDACTED
x-tock-build-number: 7388
x-tock-path: #/app/2018-07-16/calendar/day
origin: https://dashboard-staging.exploretock.com
x-tock-scope: {"businessId":"4","businessGroupId":"2"}
user-agent: Mozilla/5.0 (Macintosh; Intel Mac OS X
10_13_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/67.0.3396.99
Safari/537.36
content-type: application/octet-stream
accept: application/octet-stream
x-tock-stream-format: proto
dnt: 1
referer: https://dashboard-staging.exploretock.com/
accept-encoding: gzip, deflate, br
accept-language: en-US,en;q=0.9
cookie: REDACTED
--> parent_stream_id = 3
--> source_dependency = 1047781 (HTTP_STREAM_JOB)
--> stream_id = 5
--> weight = 220
t=538930 [st= 3] HTTP2_SESSION_SEND_DATA
--> fin = true
--> size = 14
--> stream_id = 5
t=538930 [st= 3] HTTP2_SESSION_UPDATE_SEND_WINDOW
--> delta = -14
--> window_size = 65521
t=538930 [st= 3] HTTP2_SESSION_SEND_HEADERS
--> exclusive = true
--> fin = true
--> has_priority = true
--> :method: GET
:authority: dashboard-staging.exploretock.com
:scheme: https
:path: /api/table
pragma: no-cache
cache-control: no-cache
authorization: REDACTED
x-tock-authorization: REDACTED
x-tock-build-number: 7388
x-tock-path: #/app/2018-07-16/calendar/day
dnt: 1
x-tock-scope: {"businessId":"4","businessGroupId":"2"}
user-agent: Mozilla/5.0 (Macintosh; Intel Mac OS X
10_13_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/67.0.3396.99
Safari/537.36
content-type: application/octet-stream
accept: application/octet-stream
x-tock-stream-format: proto
referer: https://dashboard-staging.exploretock.com/
accept-encoding: gzip, deflate, br
accept-language: en-US,en;q=0.9
cookie: REDACTED
--> parent_stream_id = 5
--> source_dependency = 1047781 (HTTP_STREAM_JOB)
--> stream_id = 7
--> weight = 220
t=538931 [st= 4] HTTP2_SESSION_SEND_HEADERS
--> exclusive = true
--> fin = false
--> has_priority = true
--> :method: POST
:authority: dashboard-staging.exploretock.com
:scheme: https
:path: /api/admin/calendar
content-length: 16
pragma: no-cache
cache-control: no-cache
authorization: REDACTED
x-tock-authorization: REDACTED
x-tock-build-number: 7388
x-tock-path: #/app/2018-07-16/calendar/day
origin: https://dashboard-staging.exploretock.com
x-tock-scope: {"businessId":"4","businessGroupId":"2"}
user-agent: Mozilla/5.0 (Macintosh; Intel Mac OS X
10_13_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/67.0.3396.99
Safari/537.36
content-type: application/octet-stream
accept: application/octet-stream
x-tock-stream-format: proto
dnt: 1
referer: https://dashboard-staging.exploretock.com/
accept-encoding: gzip, deflate, br
accept-language: en-US,en;q=0.9
cookie: REDACTED
--> parent_stream_id = 7
--> source_dependency = 1047781 (HTTP_STREAM_JOB)
--> stream_id = 9
--> weight = 220
t=538931 [st= 4] HTTP2_SESSION_SEND_DATA
--> fin = true
--> size = 16
--> stream_id = 9
t=538931 [st= 4] HTTP2_SESSION_UPDATE_SEND_WINDOW
--> delta = -16
--> window_size = 65505
t=538931 [st= 4] HTTP2_SESSION_SEND_HEADERS
--> exclusive = true
--> fin = true
--> has_priority = true
--> :method: GET
:authority: dashboard-staging.exploretock.com
:scheme: wss
:path: /ws/proto/2/4
pragma: no-cache
cache-control: no-cache
authorization: REDACTED
upgrade: websocket
origin: https://dashboard-staging.exploretock.com
sec-websocket-version: 13
user-agent: Mozilla/5.0 (Macintosh; Intel Mac OS X
10_13_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/67.0.3396.99
Safari/537.36
accept-encoding: gzip, deflate, br
accept-language: en-US,en;q=0.9
cookie: REDACTED
--> parent_stream_id = 9
--> source_dependency = 1047781 (HTTP_STREAM_JOB)
--> stream_id = 11
--> weight = 147
t=538963 [st=36] HTTP2_SESSION_RECV_SETTINGS
t=538963 [st=36] HTTP2_SESSION_SEND_SETTINGS_ACK
t=538963 [st=36] HTTP2_SESSION_RECV_SETTING
--> id = "3 (SETTINGS_MAX_CONCURRENT_STREAMS)"
--> value = 100
t=538963 [st=36] HTTP2_SESSION_RECV_SETTINGS_ACK
t=538963 [st=36] HTTP2_SESSION_RECV_WINDOW_UPDATE
--> delta = 14
--> stream_id = 5
t=538963 [st=36] HTTP2_SESSION_RECV_WINDOW_UPDATE
--> delta = 14
--> stream_id = 0
t=538963 [st=36] HTTP2_SESSION_UPDATE_SEND_WINDOW
--> delta = 14
--> window_size = 65519
t=538963 [st=36] HTTP2_SESSION_RECV_WINDOW_UPDATE
--> delta = 16
--> stream_id = 9
t=538963 [st=36] HTTP2_SESSION_RECV_WINDOW_UPDATE
--> delta = 16
--> stream_id = 0
t=538963 [st=36] HTTP2_SESSION_UPDATE_SEND_WINDOW
--> delta = 16
--> window_size = 65535
t=538965 [st=38] HTTP2_SESSION_RECV_GOAWAY
--> active_streams = 6
--> debug_data = ""
--> error_code = "9 (COMPRESSION_ERROR)"
--> last_accepted_stream_id = 11
--> unclaimed_streams = 0
t=538965 [st=38] HTTP2_SESSION_CLOSE
--> description = "Connection closed"
--> net_error = -100 (ERR_CONNECTION_CLOSED)
t=538968 [st=41] HTTP2_SESSION_POOL_REMOVE_SESSION
t=538969 [st=42] -HTTP2_SESSION
