Readthedocs.org: ERR_HTTP2_PROTOCOL_ERROR when loading theme.css

[strophy]

Details

Loading https://docs.dash.org/ for the first time results in the project theme.css failing to load due to a ERR_HTTP2_PROTOCOL_ERROR in Chrome and Edge 86. Reloading the page causes the asset to load, and the problem goes away. The problem does not occur under Firefox.

• Read the Docs project URL: https://docs.dash.org/
• Build URL (if applicable): https://readthedocs.org/projects/dash-docs/builds/
• Read the Docs username (if applicable): strophy

Expected Result

The page should load all assets properly the first time.

Actual Result

The theme.css asset does not load until the page is refreshed.

Possible causes

This seems to be caused by server misconfiguration or low disk space, or possibly having gzip enabled/disabled in nginx. More research here and here. I recorded a NetLog as described here, output below:

47408: URL_REQUEST
https://docs.dash.org/en/stable/_static/css/theme.css
Start Time: 2020-10-15 11:57:27.470

t=2340 [st=  0] +REQUEST_ALIVE  [dt=795]
                 --> priority = "HIGHEST"
                 --> traffic_annotation = 101845102
                 --> url = "https://docs.dash.org/en/stable/_static/css/theme.css"
t=2340 [st=  0]    NETWORK_DELEGATE_BEFORE_URL_REQUEST  [dt=0]
t=2340 [st=  0]   +URL_REQUEST_START_JOB  [dt=794]
                   --> initiator = "https://docs.dash.org"
                   --> load_flags = 65538 (BYPASS_CACHE | SUPPORT_ASYNC_REVALIDATION)
                   --> method = "GET"
                   --> network_isolation_key = "https://dash.org https://dash.org"
                   --> privacy_mode = "disabled"
                   --> site_for_cookies = "SiteForCookies: {scheme=https; registrable_domain=dash.org; schemefully_same=true}"
                   --> url = "https://docs.dash.org/en/stable/_static/css/theme.css"
t=2340 [st=  0]      COOKIE_INCLUSION_STATUS
                     --> operation = "send"
                     --> status = "INCLUDE, DO_NOT_WARN"
t=2340 [st=  0]      COOKIE_INCLUSION_STATUS
                     --> operation = "send"
                     --> status = "INCLUDE, DO_NOT_WARN"
t=2340 [st=  0]      NETWORK_DELEGATE_BEFORE_START_TRANSACTION  [dt=4]
t=2344 [st=  4]      HTTP_CACHE_GET_BACKEND  [dt=0]
t=2344 [st=  4]      HTTP_CACHE_DOOM_ENTRY  [dt=0]
                     --> net_error = -2 (ERR_FAILED)
t=2344 [st=  4]      HTTP_CACHE_CREATE_ENTRY  [dt=0]
t=2344 [st=  4]      HTTP_CACHE_ADD_TO_ENTRY  [dt=0]
t=2344 [st=  4]     +HTTP_STREAM_REQUEST  [dt=1]
t=2344 [st=  4]        HTTP_STREAM_JOB_CONTROLLER_BOUND
                       --> source_dependency = 47442 (HTTP_STREAM_JOB_CONTROLLER)
t=2345 [st=  5]        HTTP_STREAM_REQUEST_BOUND_TO_JOB
                       --> source_dependency = 47443 (HTTP_STREAM_JOB)
t=2345 [st=  5]     -HTTP_STREAM_REQUEST
t=2345 [st=  5]     +HTTP_TRANSACTION_SEND_REQUEST  [dt=1]
t=2345 [st=  5]        HTTP_TRANSACTION_HTTP2_SEND_REQUEST_HEADERS
                       --> :method: GET
                           :authority: docs.dash.org
                           :scheme: https
                           :path: /en/stable/_static/css/theme.css
                           pragma: no-cache
                           cache-control: no-cache
                           user-agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/86.0.4240.75 Safari/537.36
                           accept: text/css,*/*;q=0.1
                           sec-fetch-site: same-origin
                           sec-fetch-mode: no-cors
                           sec-fetch-dest: style
                           referer: https://docs.dash.org/en/stable/
                           accept-encoding: gzip, deflate, br
                           accept-language: en
                           cookie: [63 bytes were stripped]
t=2346 [st=  6]     -HTTP_TRANSACTION_SEND_REQUEST
t=2346 [st=  6]     +HTTP_TRANSACTION_READ_HEADERS  [dt=786]
t=3132 [st=792]        HTTP_TRANSACTION_READ_RESPONSE_HEADERS
                       --> HTTP/1.1 200
                           status: 200
                           server: nginx/1.10.3 (Ubuntu)
                           date: Wed, 14 Oct 2020 22:57:29 GMT
                           content-type: text/css
                           set-cookie: [145 bytes were stripped]
                           vary: Accept-Encoding
                           x-ms-request-id: 2b3bab60-201e-00e6-257d-a24ccb000000
                           x-ms-version: 2009-09-19
                           x-ms-lease-status: unlocked
                           x-ms-blob-type: BlockBlob
                           access-control-allow-origin: *
                           x-served: Nginx-Proxito-Sendfile
                           x-backend: web0001ul
                           x-rtd-project: dash-docs
                           x-rtd-version: stable
                           x-rtd-path: /proxito/media/html/dash-docs/stable/_static/css/theme.css
                           x-rtd-domain: dash-docs.readthedocs.io
                           x-rtd-version-method: path
                           x-rtd-project-method: rtdheader
                           referrer-policy: no-referrer-when-downgrade
                           strict-transport-security: max-age=31536000; includeSubDomains; preload
                           cf-cache-status: MISS
                           expires: Wed, 14 Oct 2020 23:57:29 GMT
                           cache-control: public, max-age=3600
                           cf-request-id: 05caee42ca000002316c95c000000001
                           expect-ct: max-age=604800, report-uri="https://report-uri.cloudflare.com/cdn-cgi/beacon/expect-ct"
                           cf-ray: 5e24e64adcdc0231-SJC
t=3132 [st=792]     -HTTP_TRANSACTION_READ_HEADERS
t=3132 [st=792]      HTTP_CACHE_WRITE_INFO  [dt=0]
t=3132 [st=792]      HTTP_CACHE_WRITE_DATA  [dt=0]
t=3132 [st=792]      HTTP_CACHE_WRITE_INFO  [dt=0]
t=3132 [st=792]     +NETWORK_DELEGATE_HEADERS_RECEIVED  [dt=2]
t=3132 [st=792]        HTTP2_STREAM_UPDATE_RECV_WINDOW
                       --> delta = -2866
                       --> stream_id = 21
                       --> window_size = 6288590
t=3133 [st=793]        HTTP2_STREAM_UPDATE_RECV_WINDOW
                       --> delta = -8183
                       --> stream_id = 21
                       --> window_size = 6280407
t=3133 [st=793]        HTTP2_STREAM_UPDATE_RECV_WINDOW
                       --> delta = -1
                       --> stream_id = 21
                       --> window_size = 6280406
t=3133 [st=793]        HTTP2_STREAM_UPDATE_RECV_WINDOW
                       --> delta = -8182
                       --> stream_id = 21
                       --> window_size = 6272224
t=3133 [st=793]        HTTP2_STREAM_UPDATE_RECV_WINDOW
                       --> delta = -10
                       --> stream_id = 21
                       --> window_size = 6272214
t=3133 [st=793]        HTTP2_STREAM_ERROR
                       --> description = "Server reset stream."
                       --> net_error = "ERR_HTTP2_PROTOCOL_ERROR"
                       --> stream_id = 21
t=3134 [st=794]     -NETWORK_DELEGATE_HEADERS_RECEIVED
t=3134 [st=794]      COOKIE_INCLUSION_STATUS
                     --> operation = "store"
                     --> status = "EXCLUDE_INVALID_DOMAIN, DO_NOT_WARN"
t=3134 [st=794]   -URL_REQUEST_START_JOB
t=3134 [st=794]    URL_REQUEST_DELEGATE_RESPONSE_STARTED  [dt=1]
t=3135 [st=795]    HTTP_TRANSACTION_READ_BODY  [dt=0]
t=3135 [st=795]    URL_REQUEST_JOB_FILTERED_BYTES_READ
                   --> byte_count = 19242
t=3135 [st=795]    HTTP_TRANSACTION_READ_BODY  [dt=0]
                   --> net_error = -337 (ERR_HTTP2_PROTOCOL_ERROR)
t=3135 [st=795]    FAILED
                   --> net_error = -337 (ERR_HTTP2_PROTOCOL_ERROR)
t=3135 [st=795] -REQUEST_ALIVE
                 --> net_error = -337 (ERR_HTTP2_PROTOCOL_ERROR)

[humitos]

Thanks for reporting this issue. I was able to reproduce it by opening an incognito tab in Google Chrome Version 86.0.4240.75 (Official Build) (64-bit). I think it will be a hard one to debug.

What does that file have over the others that make it special and not loading correctly?

I haven't seen this issue in other projects hosted on Read the Docs, which is strange if it would be a misconfiguration of the servers.

I'm not sure how to debug/research about this problem yet, but I think this issue could be a good place to collect more data and try to figure it out what's happening here.

[strophy]

I agree, this looks like a tough one to debug. The project was loading correctly until very recently. I forked the docs to add a 0.16 branch, which (as the highest version number) is currently also the stable branch on RTD, as specified in my configuration. When I noticed the build wasn't loading correctly, I added a .readthedocs.yml and requirements.txt to try and bump the versions to match what I am using on my build server, but this didn't seem to fix (or break) anything. Is it possible to look into what other assets are loading on the same HTTP2 connection? Is it possible the size of the file is being determined incorrectly, could the window_size be wrong?

[strophy]

A bit more research on this:

• Other assets also fail to load on image-heavy pages like this one
• It's usually the same assets each time, e.g. theme.css, jquery.js, dash_logo_white.png, overview.png, masternodes.png, transactions.png, peers.png, wallet-repair.png
• The problem is also occurring on different versions of the built site, including older builds and non-English language version, both of which definitely did not exhibit this problem in the past (0.13, 0.14, 0.15, 0.16/stable, French)
• It's always the same ERR_HTTP2_PROTOCOL_ERROR error
• Most assets appear on a second reload, some need a third reload
• Sometimes the reloads take 60+ seconds to deliver all assets. No other RTD site I have tested has this problem.
• Using a VPN does not help
• Loading a fresh page in separate incognito sessions shortly after one another sometimes makes the problem go away, indicating the properly resolved asset is being cached somewhere?

This looks like some problem in the use of HTTP2 on the server. Is there an option available to force HTTP1.1 only? Could we load some JS to trigger a reload as a temporary fix for the problem? Could it be something to do with the custom domain, our gold membership to remove ads or the small amount of JS we load for a customized language switcher?

Thanks for any help resolving this!

[strophy]

@humitos could you help us by providing the nginx config and log output while reproducing the error? Is nginx actually serving the content or acting as a reverse proxy to some other app on RTD? Other people have encountered this problem being caused because nginx and another app were gzipping the data twice, so setting gzip off; could be a solution? The http2_max_field_size and http2_max_header_size fields from nginx config would also be of interest to me, increasing these may help resolve the problem. This thread remains the best resource for troubleshooting.

Another thought I had was that this could be related to a misconfiguration between our custom domain and Cloudflare, which some other people have seen. I am seeing several __cfduid cookies failing to load with the .readthedocs.io domain, showing the error This Set-Cookie was blocked because its Domain attribute was invalid with regards to the current host url.. This might explain why the error is so sporadic, if Cloudflare is in the middle trying to cache some of these assets? Some Cloudflare users have also reported problems, and Cloudflare maintains a huge page to help troubleshooting HTTP2 problems.

[ericholscher]

@humitos pinged me to look at this. I'm not currently seeing the issue when loading in a Chrome incognito tab. It's 200'ing all of the files fine. Are you still able to reproduce this? Is there a CLI or any other non-browser way to reproduce this with curl for example?

We do have a backend proxy which is doing an nginx X-Accel-Redirect (nginx's Sendfile implementation) of the file. All of the files should be treated the same. They are also likely being cached by Cloudflare. If there is a way to reproduce this with a script or similar, I can try hitting the backend directly vs. Cloudflare, to see if we can get more data on it.

[ericholscher]

Looking at the response above, it looks like it was a cf-cache-status: MISS -- meaning it came from our backend. So that at least helps with debugging. Perhaps I'm not seeing the issue because the pages I'm loading are all cached by CF.

[strophy]

I've just heard from our DevOps engineer that the problem was caused by one of our servers (or maybe a cloudflare server under our control?) which was proxying the content and ran out of disk space. This has been fixed and the problem is no longer reproducible. I wasn't aware this caching was taking place, but I guess it helps that the initial assessment of this being a disk space problem was correct. Hopefully this also helps someone else in the future, and thanks to RTD staff for your willingness to help debug this!

[ericholscher]

@strophy I'd recommend that you remove the CF caching if possible, and just point directly to us. We're already using CF caching and have logic on our side to bust the cache intelligently. Docs here: https://docs.readthedocs.io/en/latest/custom_domains.html#custom-domain-support