Page MenuHomePhabricator

net::ERR_HTTP2_PROTOCOL_ERROR 200 on Docker MediaWiki hosted on Cloud VPS
Open, Needs TriagePublic

Description

When attempting to access a MediaWiki path in Chrome that sets a session cookie like https://thegoodplace.wmflabs.org/wiki/Special:CreateAccount the request fails with the following error:

net::ERR_HTTP2_PROTOCOL_ERROR 200

Accessing other pages like https://thegoodplace.wmflabs.org/wiki/Mars works fine.

This is only a problem in Chrome, it does not happen in Firefox or Safari. Also, this problem does not seem to happen locally or in production, the only place this seems to happen is on a Cloud VPS.

Here is a captured network log:


that can be browsed by uploading it to https://netlog-viewer.appspot.com

Event Timeline

dbarratt created this task.Oct 15 2019, 7:52 PM
Restricted Application added subscribers: MGChecker, Aklapper. · View Herald TranscriptOct 15 2019, 7:52 PM

Output of https://netlog-viewer.appspot.com/#events&q=type:HTTP2_SESSION%20is:active with the attached dump file:

246: HTTP2_SESSION
thegoodplace.wmflabs.org:443 (DIRECT)
Start Time: 2019-10-15 13:41:34.760

t=10058 [st=   0] +HTTP2_SESSION  [dt=4014+]
                   --> host = "thegoodplace.wmflabs.org:443"
                   --> proxy = "DIRECT"
t=10058 [st=   0]    HTTP2_SESSION_INITIALIZED
                     --> protocol = "h2"
                     --> source_dependency = 244 (SOCKET)
t=10058 [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=10058 [st=   0]    HTTP2_SESSION_UPDATE_RECV_WINDOW
                     --> delta = 15663105
                     --> window_size = 15728640
t=10058 [st=   0]    HTTP2_SESSION_SEND_WINDOW_UPDATE
                     --> delta = 15663105
                     --> stream_id = 0
t=10059 [st=   1]    HTTP2_SESSION_SEND_HEADERS
                     --> exclusive = true
                     --> fin = true
                     --> has_priority = true
                     --> :method: GET
                         :authority: thegoodplace.wmflabs.org
                         :scheme: https
                         :path: /wiki/Special:CreateAccount
                         upgrade-insecure-requests: 1
                         user-agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_14_0) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/77.0.3865.120 Safari/537.36
                         sec-fetch-mode: navigate
                         accept: text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3
                         sec-fetch-site: none
                         accept-encoding: gzip, deflate, br
                         accept-language: en-US,en;q=0.9,es;q=0.8,ja;q=0.7
                     --> parent_stream_id = 0
                     --> source_dependency = 240 (HTTP_STREAM_JOB)
                     --> stream_id = 1
                     --> weight = 256
t=10097 [st=  39]    HTTP2_SESSION_RECV_SETTINGS
t=10097 [st=  39]    HTTP2_SESSION_SEND_SETTINGS_ACK
t=10097 [st=  39]    HTTP2_SESSION_RECV_SETTING
                     --> id = "3 (SETTINGS_MAX_CONCURRENT_STREAMS)"
                     --> value = 128
t=10097 [st=  39]    HTTP2_SESSION_UPDATE_STREAMS_SEND_WINDOW_SIZE
                     --> delta_window_size = 1
t=10097 [st=  39]    HTTP2_SESSION_RECV_SETTING
                     --> id = "4 (SETTINGS_INITIAL_WINDOW_SIZE)"
                     --> value = 65536
t=10097 [st=  39]    HTTP2_SESSION_RECV_SETTING
                     --> id = "5 (SETTINGS_MAX_FRAME_SIZE)"
                     --> value = 16777215
t=10097 [st=  39]    HTTP2_SESSION_RECV_WINDOW_UPDATE
                     --> delta = 2147418112
                     --> stream_id = 0
t=10097 [st=  39]    HTTP2_SESSION_UPDATE_SEND_WINDOW
                     --> delta = 2147418112
                     --> window_size = 2147483647
t=10097 [st=  39]    HTTP2_SESSION_RECV_SETTINGS_ACK
t=10140 [st=  82]    HTTP2_SESSION_RECV_HEADERS
                     --> fin = false
                     --> :status: 200
                         server: nginx/1.13.6
                         date: Tue, 15 Oct 2019 19:41:34 GMT
                         content-type: text/html; charset=UTF-8
                         content-length: 14304
                         x-powered-by: PHP/7.2.23
                         x-content-type-options: nosniff
                         set-cookie: [79 bytes were stripped]
                         content-language: en
                         x-frame-options: DENY
                         vary: Accept-Encoding,Cookie
                         expires: Thu, 01 Jan 1970 00:00:00 GMT
                         cache-control: no-cache, no-store, max-age=0, must-revalidate
                         pragma: no-cache
                         content-encoding: gzip
                         x-clacks-overhead: GNU Terry Pratchett
                     --> stream_id = 1
t=10141 [st=  83]    HTTP2_SESSION_RECV_DATA
                     --> fin = false
                     --> size = 3554
                     --> stream_id = 1
t=10141 [st=  83]    HTTP2_SESSION_UPDATE_RECV_WINDOW
                     --> delta = -3554
                     --> window_size = 15725086
t=10142 [st=  84]    HTTP2_SESSION_UPDATE_RECV_WINDOW
                     --> delta = 3554
                     --> window_size = 15728640
t=10142 [st=  84]    HTTP2_SESSION_RECV_DATA
                     --> fin = false
                     --> size = 757
                     --> stream_id = 1
t=10142 [st=  84]    HTTP2_SESSION_UPDATE_RECV_WINDOW
                     --> delta = -757
                     --> window_size = 15727883
t=10142 [st=  84]    HTTP2_SESSION_RECV_RST_STREAM
                     --> error_code = "2 (INTERNAL_ERROR)"
                     --> stream_id = 1
t=10143 [st=  85]    HTTP2_SESSION_UPDATE_RECV_WINDOW
                     --> delta = 757
                     --> window_size = 15728640
t=14072 [st=4014]

Here is the part where the HTTP/2 server (the nginx front proxy) sends the browser the bad news that something has gone horribly wrong:

t=10142 [st=  84]    HTTP2_SESSION_RECV_RST_STREAM
                     --> error_code = "2 (INTERNAL_ERROR)"
                     --> stream_id = 1

The docs on RST_STREAM frames do not help us out a lot here. The INTERNAL_ERROR code is a generic "something bad happened on my side" message.

Output of https://netlog-viewer.appspot.com/#events&s=236:

236: URL_REQUEST
https://thegoodplace.wmflabs.org/wiki/Special:CreateAccount
Start Time: 2019-10-15 13:41:34.574

t= 9872 [st=  0] +REQUEST_ALIVE  [dt=271]
                  --> priority = "HIGHEST"
                  --> traffic_annotation = 63171670
                  --> url = "https://thegoodplace.wmflabs.org/wiki/Special:CreateAccount"
t= 9872 [st=  0]    NETWORK_DELEGATE_BEFORE_URL_REQUEST  [dt=0]
t= 9872 [st=  0]   +URL_REQUEST_START_JOB  [dt=268]
                    --> load_flags = 1024 (MAIN_FRAME_DEPRECATED)
                    --> method = "GET"
                    --> privacy_mode = 0
                    --> url = "https://thegoodplace.wmflabs.org/wiki/Special:CreateAccount"
t= 9872 [st=  0]      NETWORK_DELEGATE_BEFORE_START_TRANSACTION  [dt=0]
t= 9873 [st=  1]      HTTP_CACHE_GET_BACKEND  [dt=0]
t= 9873 [st=  1]      HTTP_CACHE_OPEN_OR_CREATE_ENTRY  [dt=0]
t= 9873 [st=  1]      HTTP_CACHE_ADD_TO_ENTRY  [dt=0]
t= 9873 [st=  1]     +HTTP_STREAM_REQUEST  [dt=185]
t= 9873 [st=  1]        HTTP_STREAM_JOB_CONTROLLER_BOUND
                        --> source_dependency = 238 (HTTP_STREAM_JOB_CONTROLLER)
t=10058 [st=186]        HTTP_STREAM_REQUEST_BOUND_TO_JOB
                        --> source_dependency = 240 (HTTP_STREAM_JOB)
t=10058 [st=186]     -HTTP_STREAM_REQUEST
t=10059 [st=187]     +HTTP_TRANSACTION_SEND_REQUEST  [dt=0]
t=10059 [st=187]        HTTP_TRANSACTION_HTTP2_SEND_REQUEST_HEADERS
                        --> :method: GET
                            :authority: thegoodplace.wmflabs.org
                            :scheme: https
                            :path: /wiki/Special:CreateAccount
                            upgrade-insecure-requests: 1
                            user-agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_14_0) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/77.0.3865.120 Safari/537.36
                            sec-fetch-mode: navigate
                            accept: text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3
                            sec-fetch-site: none
                            accept-encoding: gzip, deflate, br
                            accept-language: en-US,en;q=0.9,es;q=0.8,ja;q=0.7
t=10059 [st=187]     -HTTP_TRANSACTION_SEND_REQUEST
t=10059 [st=187]     +HTTP_TRANSACTION_READ_HEADERS  [dt=81]
t=10097 [st=225]        HTTP2_STREAM_UPDATE_SEND_WINDOW
                        --> delta = 1
                        --> stream_id = 1
                        --> window_size = 65536
t=10140 [st=268]        HTTP_TRANSACTION_READ_RESPONSE_HEADERS
                        --> HTTP/1.1 200
                            status: 200
                            server: nginx/1.13.6
                            date: Tue, 15 Oct 2019 19:41:34 GMT
                            content-type: text/html; charset=UTF-8
                            content-length: 14304
                            x-powered-by: PHP/7.2.23
                            x-content-type-options: nosniff
                            set-cookie: [79 bytes were stripped]
                            content-language: en
                            x-frame-options: DENY
                            vary: Accept-Encoding,Cookie
                            expires: Thu, 01 Jan 1970 00:00:00 GMT
                            cache-control: no-cache, no-store, max-age=0, must-revalidate
                            pragma: no-cache
                            content-encoding: gzip
                            x-clacks-overhead: GNU Terry Pratchett
t=10140 [st=268]     -HTTP_TRANSACTION_READ_HEADERS
t=10140 [st=268]      HTTP_CACHE_WRITE_INFO  [dt=0]
t=10140 [st=268]      NETWORK_DELEGATE_HEADERS_RECEIVED  [dt=0]
t=10140 [st=268]      URL_REQUEST_FILTERS_SET
                      --> filters = "GZIP"
t=10140 [st=268]   -URL_REQUEST_START_JOB
t=10140 [st=268]    URL_REQUEST_DELEGATE_RESPONSE_STARTED  [dt=1]
t=10141 [st=269]   +HTTP_TRANSACTION_READ_BODY  [dt=1]
t=10141 [st=269]      HTTP2_STREAM_UPDATE_RECV_WINDOW
                      --> delta = -3554
                      --> stream_id = 1
                      --> window_size = 6287902
t=10142 [st=270]      HTTP2_STREAM_UPDATE_RECV_WINDOW
                      --> delta = 3554
                      --> stream_id = 1
                      --> window_size = 6291456
t=10142 [st=270]   -HTTP_TRANSACTION_READ_BODY
t=10142 [st=270]    URL_REQUEST_JOB_BYTES_READ
                    --> byte_count = 3554
t=10142 [st=270]    URL_REQUEST_JOB_FILTERED_BYTES_READ
                    --> byte_count = 11520
t=10142 [st=270]   +HTTP_TRANSACTION_READ_BODY  [dt=1]
t=10142 [st=270]      HTTP2_STREAM_UPDATE_RECV_WINDOW
                      --> delta = -757
                      --> stream_id = 1
                      --> window_size = 6290699
t=10142 [st=270]      HTTP2_STREAM_ERROR
                      --> description = "Server reset stream."
                      --> net_error = "ERR_HTTP2_PROTOCOL_ERROR"
                      --> stream_id = 1
t=10143 [st=271]   -HTTP_TRANSACTION_READ_BODY
                    --> net_error = -337 (ERR_HTTP2_PROTOCOL_ERROR)
t=10143 [st=271]    FAILED
                    --> net_error = -337 (ERR_HTTP2_PROTOCOL_ERROR)
t=10143 [st=271] -REQUEST_ALIVE
                  --> net_error = -337 (ERR_HTTP2_PROTOCOL_ERROR)

The interesting area is:

t=10142 [st=270]   +HTTP_TRANSACTION_READ_BODY  [dt=1]
t=10142 [st=270]      HTTP2_STREAM_UPDATE_RECV_WINDOW
                      --> delta = -757
                      --> stream_id = 1
                      --> window_size = 6290699
t=10142 [st=270]      HTTP2_STREAM_ERROR
                      --> description = "Server reset stream."
                      --> net_error = "ERR_HTTP2_PROTOCOL_ERROR"
                      --> stream_id = 1
t=10143 [st=271]   -HTTP_TRANSACTION_READ_BODY
                    --> net_error = -337 (ERR_HTTP2_PROTOCOL_ERROR)

At this point, Chrome has read the response headers and is attempting to read the 14304 bytes of body payload they describe. It then read a 3554 byte chunk of gzip compressed data and determined that the uncompressed size of that read was 11520 bytes. The section I highlighted then tries to read another 757 bytes and gets the error frame that we looked at above in reply.

When I use curl -svo ./dump.html --http2 https://thegoodplace.wmflabs.org/wiki/Special:CreateAccount to see what curl does with the same request, it also appears to read 3554 bytes of compressed payload and then stops. The difference is that curl's decompressed output of that 3554 byte chunk matches the content-length header size and it does not try to fetch more data.

Is this some strange HTTP/2 + gzip bug in Chrome 77.0.3865.120? Are curl and Firefox just more lenient in dealing with HTTP/2 stream events? Inquiring minds want to know.

bd808 renamed this task from net::ERR_HTTP2_PROTOCOL_ERROR 200 on MediaWiki hosted on Cloud VPS to net::ERR_HTTP2_PROTOCOL_ERROR 200 on Docker MediaWiki hosted on Cloud VPS.Sun, Nov 10, 11:38 PM
bd808 moved this task from Backlog to Dynamicproxy on the Cloud-VPS board.