Chrome cancels URL_REQUEST after exactly 3 seconds

Ok, so this is a weird one.

I am working on a php script that does a lot of work when requested (image processing). So this is not unusual it issues a response in 10 seconds, up to 30 seconds sometimes : it's a long script, and this is important for the next part.

While logging the image processing code, I noticed that processes that should be called only once were called twice.

The reason : Chrome is cancelling the first request after 3s, then requests the same URL again.

The sequence is always the same.

URL requested
Cancel after 3 seconds sharp
Auto-reload with http scheme
307 due to HSTS on our server
URL requested again with https
This one loads correctly

The cancelled request is shown as Stalled in "Timing" tab.

This is only happening in Chrome (92.0.4515.107 for me). I don't see this behavior in Firefox.

Now how can one reproduce this witchcraft ? Easy, I can reproduce on 2 different servers on 2 different providers (GCE, and OVH) and it has a weird link with the duration of the initial request to this URL.

Create a new php script on your webserver only containing

<?php sleep(10); echo 'Done'; ?>
Call your script URL in Chrome
The first call will succeed
But all the next calls will certainly trigger "the sequence"

By checking on Chrome logs, I came to think this has a link with HTTP2_SESSION

t=235805 [st=   5]     +HTTP_TRANSACTION_SEND_REQUEST  [dt=1]
t=235806 [st=   6]        HTTP_TRANSACTION_HTTP2_SEND_REQUEST_HEADERS
                          --> :method: GET
                              :authority: my.server.com
                              :scheme: https
                              :path: /admin/ot/test1.php
                              pragma: no-cache
                              cache-control: no-cache
                              authorization: [38 bytes were stripped]
                              sec-ch-ua: "Chromium";v="92", " Not A;Brand";v="99", "Google Chrome";v="92"
                              sec-ch-ua-mobile: ?0
                              upgrade-insecure-requests: 1
                              user-agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/92.0.4515.107 Safari/537.36
                              accept: text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.9
                              sec-fetch-site: none
                              sec-fetch-mode: navigate
                              sec-fetch-user: ?1
                              sec-fetch-dest: document
                              accept-encoding: gzip, deflate, br
                              accept-language: fr-FR,fr;q=0.9,en-US;q=0.8,en;q=0.7
                              cookie: [409 bytes were stripped]
t=235806 [st=   6]     -HTTP_TRANSACTION_SEND_REQUEST
t=235806 [st=   6]     +HTTP_TRANSACTION_READ_HEADERS  [dt=3012]
t=238818 [st=3018]        CANCELLED
t=238818 [st=3018] -REQUEST_ALIVE

On the URL_REQUEST above, we don't learn much. We just see "CANCELLED" after 3s.

But the HTTP2_SESSION shows a strange error :

27185: HTTP2_SESSION
my.server.com:443 (DIRECT)
Start Time: 2021-07-22 17:13:09.460

t=222444 [st=    0] +HTTP2_SESSION  [dt=28616+]
                     --> host = "my.server.com:443"
                     --> proxy = "DIRECT"
t=222444 [st=    0]    HTTP2_SESSION_INITIALIZED
                       --> protocol = "h2"
                       --> source_dependency = 27181 (SOCKET)
t=222445 [st=    1]    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]","[id:6 (SETTINGS_MAX_HEADER_LIST_SIZE) value:262144]"]
t=222445 [st=    1]    HTTP2_SESSION_UPDATE_RECV_WINDOW
                       --> delta = 15663105
                       --> window_size = 15728640
t=222445 [st=    1]    HTTP2_SESSION_SEND_WINDOW_UPDATE
                       --> delta = 15663105
                       --> stream_id = 0
t=222446 [st=    2]    HTTP2_SESSION_SEND_HEADERS
                       --> exclusive = true
                       --> fin = true
                       --> has_priority = true
                       --> :method: GET
                           :authority: my.server.com
                           :scheme: https
                           :path: /admin/ot/test1.php
                           pragma: no-cache
                           cache-control: no-cache
                           authorization: [38 bytes were stripped]
                           sec-ch-ua: "Chromium";v="92", " Not A;Brand";v="99", "Google Chrome";v="92"
                           sec-ch-ua-mobile: ?0
                           upgrade-insecure-requests: 1
                           user-agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/92.0.4515.107 Safari/537.36
                           accept: text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.9
                           sec-fetch-site: none
                           sec-fetch-mode: navigate
                           sec-fetch-user: ?1
                           sec-fetch-dest: document
                           accept-encoding: gzip, deflate, br
                           accept-language: fr-FR,fr;q=0.9,en-US;q=0.8,en;q=0.7
                           cookie: [409 bytes were stripped]
                       --> parent_stream_id = 0
                       --> source_dependency = 27179 (HTTP_STREAM_JOB)
                       --> stream_id = 1
                       --> weight = 256
t=222471 [st=   27]    HTTP2_SESSION_RECV_SETTINGS
t=222471 [st=   27]    HTTP2_SESSION_SEND_SETTINGS_ACK
t=222471 [st=   27]    HTTP2_SESSION_RECV_SETTING
                       --> id = "3 (SETTINGS_MAX_CONCURRENT_STREAMS)"
                       --> value = 100
t=222471 [st=   27]    HTTP2_SESSION_UPDATE_STREAMS_SEND_WINDOW_SIZE
                       --> delta_window_size = 983041
t=222471 [st=   27]    HTTP2_SESSION_RECV_SETTING
                       --> id = "4 (SETTINGS_INITIAL_WINDOW_SIZE)"
                       --> value = 1048576
t=222471 [st=   27]    HTTP2_SESSION_RECV_SETTING
                       --> id = "6 (SETTINGS_MAX_HEADER_LIST_SIZE)"
                       --> value = 65536
t=222471 [st=   27]    HTTP2_SESSION_RECV_WINDOW_UPDATE
                       --> delta = 983041
                       --> stream_id = 0
t=222471 [st=   27]    HTTP2_SESSION_UPDATE_SEND_WINDOW
                       --> delta = 983041
                       --> window_size = 1048576
t=222471 [st=   27]    HTTP2_SESSION_RECV_SETTINGS_ACK
t=232550 [st=10106]    HTTP2_SESSION_RECV_HEADERS
                       --> fin = false
                       --> :status: 200
                           date: Thu, 22 Jul 2021 15:13:09 GMT
                           vary: Accept-Encoding
                           content-encoding: gzip
                           strict-transport-security: max-age=63072000; includeSubDomains; preload
                           x-ua-compatible: IE=Edge
                           x-frame-options: sameorigin
                           x-content-type-options: nosniff
                           x-xss-protection: 1; mode=block
                           content-length: 24
                           content-type: text/html; charset=CP1252
                           cache-control: 
                           age: 0
                           x-cache: NOT CACHABLE
                           accept-ranges: bytes
                           via: 1.1 google
                           alt-svc: clear
                       --> stream_id = 1
t=232550 [st=10106]    HTTP2_SESSION_UPDATE_RECV_WINDOW
                       --> delta = -1
                       --> window_size = 15728639
t=232550 [st=10106]    HTTP2_SESSION_UPDATE_RECV_WINDOW
                       --> delta = 1
                       --> window_size = 15728640
t=232550 [st=10106]    HTTP2_SESSION_RECV_DATA
                       --> fin = false
                       --> size = 24
                       --> stream_id = 1
t=232550 [st=10106]    HTTP2_SESSION_UPDATE_RECV_WINDOW
                       --> delta = -24
                       --> window_size = 15728616
t=232550 [st=10106]    HTTP2_SESSION_UPDATE_RECV_WINDOW
                       --> delta = -110
                       --> window_size = 15728506
t=232550 [st=10106]    HTTP2_SESSION_UPDATE_RECV_WINDOW
                       --> delta = 110
                       --> window_size = 15728616
t=232550 [st=10106]    HTTP2_SESSION_UPDATE_RECV_WINDOW
                       --> delta = -1
                       --> window_size = 15728615
t=232550 [st=10106]    HTTP2_SESSION_UPDATE_RECV_WINDOW
                       --> delta = 1
                       --> window_size = 15728616
t=232550 [st=10106]    HTTP2_SESSION_UPDATE_RECV_WINDOW
                       --> delta = -71
                       --> window_size = 15728545
t=232551 [st=10107]    HTTP2_SESSION_UPDATE_RECV_WINDOW
                       --> delta = 71
                       --> window_size = 15728616
t=232551 [st=10107]    HTTP2_SESSION_RECV_DATA
                       --> fin = true
                       --> size = 0
                       --> stream_id = 1
t=232551 [st=10107]    HTTP2_SESSION_PING
                       --> is_ack = false
                       --> type = "received"
                       --> unique_id = 0
t=232551 [st=10107]    HTTP2_SESSION_PING
                       --> is_ack = true
                       --> type = "sent"
                       --> unique_id = 0
t=232552 [st=10108]    HTTP2_SESSION_UPDATE_RECV_WINDOW
                       --> delta = 24
                       --> window_size = 15728640
t=235806 [st=13362]    HTTP2_SESSION_SEND_HEADERS
                       --> exclusive = true
                       --> fin = true
                       --> has_priority = true
                       --> :method: GET
                           :authority: my.server.com
                           :scheme: https
                           :path: /admin/ot/test1.php
                           pragma: no-cache
                           cache-control: no-cache
                           authorization: [38 bytes were stripped]
                           sec-ch-ua: "Chromium";v="92", " Not A;Brand";v="99", "Google Chrome";v="92"
                           sec-ch-ua-mobile: ?0
                           upgrade-insecure-requests: 1
                           user-agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/92.0.4515.107 Safari/537.36
                           accept: text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.9
                           sec-fetch-site: none
                           sec-fetch-mode: navigate
                           sec-fetch-user: ?1
                           sec-fetch-dest: document
                           accept-encoding: gzip, deflate, br
                           accept-language: fr-FR,fr;q=0.9,en-US;q=0.8,en;q=0.7
                           cookie: [409 bytes were stripped]
                       --> parent_stream_id = 0
                       --> source_dependency = 27212 (HTTP_STREAM_JOB)
                       --> stream_id = 3
                       --> weight = 256
t=238818 [st=16374]    HTTP2_SESSION_SEND_RST_STREAM
                       --> description = ""
                       --> error_code = "8 (CANCEL)"
                       --> stream_id = 3
t=238846 [st=16402]    HTTP2_SESSION_SEND_HEADERS
                       --> exclusive = true
                       --> fin = true
                       --> has_priority = true
                       --> :method: GET
                           :authority: my.server.com
                           :scheme: https
                           :path: /admin/ot/test1.php
                           pragma: no-cache
                           cache-control: no-cache
                           authorization: [38 bytes were stripped]
                           upgrade-insecure-requests: 1
                           user-agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/92.0.4515.107 Safari/537.36
                           accept: text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.9
                           sec-fetch-site: none
                           sec-fetch-mode: navigate
                           sec-fetch-user: ?1
                           sec-fetch-dest: document
                           sec-ch-ua: "Chromium";v="92", " Not A;Brand";v="99", "Google Chrome";v="92"
                           sec-ch-ua-mobile: ?0
                           accept-encoding: gzip, deflate, br
                           accept-language: fr-FR,fr;q=0.9,en-US;q=0.8,en;q=0.7
                           cookie: [409 bytes were stripped]
                       --> parent_stream_id = 0
                       --> source_dependency = 27225 (HTTP_STREAM_JOB)
                       --> stream_id = 5
                       --> weight = 256
t=249924 [st=27480]    HTTP2_SESSION_RECV_HEADERS
                       --> fin = false
                       --> :status: 200
                           date: Thu, 22 Jul 2021 15:13:25 GMT
                           vary: Accept-Encoding
                           content-encoding: gzip
                           strict-transport-security: max-age=63072000; includeSubDomains; preload
                           x-ua-compatible: IE=Edge
                           x-frame-options: sameorigin
                           x-content-type-options: nosniff
                           x-xss-protection: 1; mode=block
                           content-length: 24
                           content-type: text/html; charset=CP1252
                           cache-control: 
                           age: 0
                           x-cache: NOT CACHABLE
                           accept-ranges: bytes
                           via: 1.1 google
                           alt-svc: clear
                       --> stream_id = 5
t=249924 [st=27480]    HTTP2_SESSION_UPDATE_RECV_WINDOW
                       --> delta = -1
                       --> window_size = 15728639
t=249924 [st=27480]    HTTP2_SESSION_UPDATE_RECV_WINDOW
                       --> delta = 1
                       --> window_size = 15728640
t=249924 [st=27480]    HTTP2_SESSION_RECV_DATA
                       --> fin = false
                       --> size = 24
                       --> stream_id = 5
t=249924 [st=27480]    HTTP2_SESSION_UPDATE_RECV_WINDOW
                       --> delta = -24
                       --> window_size = 15728616
t=249925 [st=27481]    HTTP2_SESSION_UPDATE_RECV_WINDOW
                       --> delta = -94
                       --> window_size = 15728522
t=249925 [st=27481]    HTTP2_SESSION_UPDATE_RECV_WINDOW
                       --> delta = 94
                       --> window_size = 15728616
t=249925 [st=27481]    HTTP2_SESSION_UPDATE_RECV_WINDOW
                       --> delta = -1
                       --> window_size = 15728615
t=249925 [st=27481]    HTTP2_SESSION_UPDATE_RECV_WINDOW
                       --> delta = 1
                       --> window_size = 15728616
t=249925 [st=27481]    HTTP2_SESSION_UPDATE_RECV_WINDOW
                       --> delta = -104
                       --> window_size = 15728512
t=249925 [st=27481]    HTTP2_SESSION_UPDATE_RECV_WINDOW
                       --> delta = 104
                       --> window_size = 15728616
t=249925 [st=27481]    HTTP2_SESSION_RECV_DATA
                       --> fin = true
                       --> size = 0
                       --> stream_id = 5
t=249925 [st=27481]    HTTP2_SESSION_PING
                       --> is_ack = false
                       --> type = "received"
                       --> unique_id = 2
t=249925 [st=27481]    HTTP2_SESSION_PING
                       --> is_ack = true
                       --> type = "sent"
                       --> unique_id = 2
t=249927 [st=27483]    HTTP2_SESSION_UPDATE_RECV_WINDOW
                       --> delta = 24
                       --> window_size = 15728640

Walkthrough :

Initial request (the one that worked) starts at st=0, ends at st=10106 (10 seconds of sleep)
The second request (the one that gets automatically cancelled) starts at st=13362, ends at st=16374 (3s later) with this

t=238818 [st=16374]    HTTP2_SESSION_SEND_RST_STREAM
                       --> description = ""
                       --> error_code = "8 (CANCEL)"
                       --> stream_id = 3

Then the request gets reloaded at st=16402, and finally gets back at st=27480 with its 10s sleep delay

I honestly don't know what to do with this. This can be reproduced easily but I can't figure out why it happens.

Chrome is largely used in my company for our internal tools, so I'm bugged it reloads heavy processing URL 2 times in a row for mysterious reasons.

Any help would be greatly appreciated.

OH, and I did disable every extensions I have. It does not help. I don't see any mention to any extension intervention in Chrome logs anyway.

Solution

I think this problem can be reproduced on any domain which responses with longer than 3s delay and with any technology at the server side. I suppose this is a chrome issue. I reproduced it with ASP.net MVC and AWS Beanstalk hosting. I also reproduced it differently on https://example.com/ when you throttle connection to get slower response times.

To reproduce it (on Chrome Version 92.0.4515.159 (Official Build) (64-bit)):

Open Dev Tools and add Very Slow Network Throttling Profile as follows
go to url by pasting: https://example.com/ -> this should work
refresh page by pressing F5 -> this should work as well
now, very important, just click the address bar twice so you can see: and then press enter. Now chrome behaves differently and first it tries the https url and if there is no response within 3s it redirects to http. The cancelled request is the one I am talking about.

Maybe this will help sb resolving the issue.