わかりました、これは奇妙なものです。
私は、要求されたときに多くの作業を行う php スクリプトに取り組んでいます (画像処理)。したがって、これは珍しいことではなく、10 秒、場合によっては最大 30 秒で応答を発行します。これは長いスクリプトであり、これは次の部分で重要です。
画像処理コードをログに記録しているときに、1 回だけ呼び出されるはずのプロセスが 2 回呼び出されていることに気付きました。
理由: Chrome は 3 秒後に最初のリクエストをキャンセルし、同じ URL を再度リクエストします。
シーケンスは常に同じです。
- 要求された URL
- 3秒切れたらキャンセル
- http スキームによる自動リロード
- サーバーのHSTSによる307
- URL が https で再度リクエストされました
- これは正しくロードされます
キャンセルされたリクエストは、[タイミング] タブで [停止] として表示されます。
これはChromeでのみ発生しています（私にとっては92.0.4515.107）。この動作は Firefox では見られません。
では、この魔術をどのように再現できるでしょうか。簡単です。2 つの異なるプロバイダー (GCE と OVH) の 2 つの異なるサーバーで再現でき、この URL への最初のリクエストの期間に奇妙なリンクがあります。
Web サーバーに新しい php スクリプトを作成し、
<?php sleep(10); echo 'Done'; ?>Chrome でスクリプト URL を呼び出す
最初の呼び出しは成功します
しかし、次のすべての呼び出しは確かに「シーケンス」をトリガーします
Chrome のログを確認したところ、これには 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
上記の URL_REQUEST では、あまり学習しません。3 秒後に「CANCELLED」が表示されます。
しかし、HTTP2_SESSION には奇妙なエラーが表示されます。
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
チュートリアル:
- 最初のリクエスト (機能したリクエスト) は st=0 で開始し、st=10106 で終了します (10 秒間のスリープ)
- 2 番目のリクエスト (自動的にキャンセルされるリクエスト) は st=13362 で始まり、st=16374 (3 秒後) で終了します。
t=238818 [st=16374] HTTP2_SESSION_SEND_RST_STREAM
--> description = ""
--> error_code = "8 (CANCEL)"
--> stream_id = 3
- その後、リクエストは st=16402 でリロードされ、最終的に st=27480 に戻り、10 秒のスリープ遅延が発生します。
正直なところ、これをどうするかわかりません。これは簡単に再現できますが、なぜ起こるのかわかりません。
私の会社では内部ツールとして Chrome が主に使用されているため、不可解な理由で重い処理の URL を 2 回続けてリロードするバグが発生しています。
どんな助けでも大歓迎です。
ああ、私は持っているすべての拡張機能を無効にしました。それは役に立ちません。とにかく、Chrome ログに拡張機能の介入についての言及はありません。