Как отладить URL_REQUEST, истекший при загрузке большого файла в браузере MacOS Chrome? - PullRequest
4 голосов
/ 26 июня 2019

Я пытаюсь загрузить файл размером 57,86 ГБ в контейнер BLOB-объектов Azure Storage и замечаю, что он регулярно выходит из строя только на Chrome 75.0.3770.100 (официальная сборка) (64-разрядная версия) на MacOS Mojave 10.14.3

Мы разбиваем файл на блоки по 4 МБ и имеем 6 открытых соединений.

При сбое запрос PUT останавливается / время ожидания и загрузка останавливается.

Кто-нибудь сталкивался с подобными проблемами? У кого-нибудь есть идеи относительно того, где искать следующую проблему для устранения этой проблемы?

Вот журналы, которые мы получили от chrome: // net-export

285748: URL_REQUEST
https://i_removed_this.blob.core.windows.net/i_removed_this
Start Time: 2019-06-21 14:34:34.320

t=178854 [st=    0] +REQUEST_ALIVE  [dt=30624]
                     --> priority = "MEDIUM"
                     --> url = "https://i_removed_this.blob.core.windows.net/i_removed_this"
t=178855 [st=    1]    NETWORK_DELEGATE_BEFORE_URL_REQUEST  [dt=0]
t=178855 [st=    1]   +URL_REQUEST_START_JOB  [dt=30623]
                       --> load_flags = 832 (DO_NOT_SAVE_COOKIES | DO_NOT_SEND_AUTH_DATA | DO_NOT_SEND_COOKIES)
                       --> method = "PUT"
                       --> privacy_mode = 1
                       --> upload_id = "0"
                       --> url = "https://i_removed_this.blob.core.windows.net/i_removed_this"
t=178855 [st=    1]      NETWORK_DELEGATE_BEFORE_START_TRANSACTION  [dt=0]
t=178855 [st=    1]      HTTP_CACHE_GET_BACKEND  [dt=0]
t=178855 [st=    1]      HTTP_CACHE_OPEN_OR_CREATE_ENTRY  [dt=0]
                         --> net_error = -2 (ERR_FAILED)
t=178855 [st=    1]     +HTTP_STREAM_REQUEST  [dt=0]
t=178855 [st=    1]        HTTP_STREAM_JOB_CONTROLLER_BOUND
                           --> source_dependency = 285750 (HTTP_STREAM_JOB_CONTROLLER)
t=178855 [st=    1]        HTTP_STREAM_REQUEST_BOUND_TO_JOB
                           --> source_dependency = 285751 (HTTP_STREAM_JOB)
t=178855 [st=    1]     -HTTP_STREAM_REQUEST
t=178855 [st=    1]      UPLOAD_DATA_STREAM_INIT  [dt=1]
                         --> is_chunked = false
                         --> net_error = 0 (?)
                         --> total_size = 4000000
t=178856 [st=    2]     +HTTP_TRANSACTION_SEND_REQUEST  [dt=185]
t=178856 [st=    2]        HTTP_TRANSACTION_SEND_REQUEST_HEADERS
                           --> PUT /i_removed_this HTTP/1.1
                               Host: i_removed_this.blob.core.windows.net
                               Connection: keep-alive
                               Content-Length: 4000000
                               Accept: application/json, text/plain, */*
                               Origin: https://i_removed_this.com/
                               User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_14_3) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/75.0.3770.100 Safari/537.36
                               Content-Type: application/json;charset=utf-8
                               Referer: https://i_removed_this.com/
                               Accept-Encoding: gzip, deflate, br
                               Accept-Language: en-US,en;q=0.9
t=178856 [st=    2]        HTTP_TRANSACTION_SEND_REQUEST_BODY
                           --> did_merge = false
                           --> is_chunked = false
                           --> length = 4000000
t=178856 [st=    2]        UPLOAD_DATA_STREAM_READ  [dt=1]
                           --> current_position = 0
t=178857 [st=    3]        UPLOAD_DATA_STREAM_READ  [dt=0]
                           --> current_position = 16384
t=178857 [st=    3]        UPLOAD_DATA_STREAM_READ  [dt=0]
                           --> current_position = 32768

 ... removed most of the UPLOAD_DATE_STREAM_READ events for conciceness

t=179040 [st=  186]        UPLOAD_DATA_STREAM_READ  [dt=0]
                           --> current_position = 3981312
t=179041 [st=  187]        UPLOAD_DATA_STREAM_READ  [dt=0]
                           --> current_position = 3997696
t=179041 [st=  187]        UPLOAD_DATA_STREAM_READ  [dt=0]
                           --> current_position = 4000000
t=179041 [st=  187]     -HTTP_TRANSACTION_SEND_REQUEST
t=179041 [st=  187]     +HTTP_TRANSACTION_READ_HEADERS  [dt=30437]
t=179041 [st=  187]        HTTP_STREAM_PARSER_READ_HEADERS  [dt=30437]
                           --> net_error = -7 (ERR_TIMED_OUT)
t=209478 [st=30624]     -HTTP_TRANSACTION_READ_HEADERS
                         --> net_error = -7 (ERR_TIMED_OUT)
t=209478 [st=30624]   -URL_REQUEST_START_JOB
                       --> net_error = -7 (ERR_TIMED_OUT)
t=209478 [st=30624]    URL_REQUEST_DELEGATE_RESPONSE_STARTED  [dt=0]
t=209478 [st=30624] -REQUEST_ALIVE
                     --> net_error = -7 (ERR_TIMED_OUT)


285750: HTTP_STREAM_JOB_CONTROLLER
https://i_removed_this.blob.core.windows.net/i_removed_this
Start Time: 2019-06-21 14:34:34.321

t=178855 [st=0] +HTTP_STREAM_JOB_CONTROLLER  [dt=0]
                 --> is_preconnect = false
                 --> url = "https://i_removed_this.blob.core.windows.net/i_removed_this"
t=178855 [st=0]    HTTP_STREAM_JOB_CONTROLLER_BOUND
                   --> source_dependency = 285748 (URL_REQUEST)
t=178855 [st=0]   +PROXY_RESOLUTION_SERVICE  [dt=0]
t=178855 [st=0]      PROXY_RESOLUTION_SERVICE_RESOLVED_PROXY_LIST
                     --> pac_string = "DIRECT"
t=178855 [st=0]   -PROXY_RESOLUTION_SERVICE
t=178855 [st=0]    HTTP_STREAM_JOB_CONTROLLER_PROXY_SERVER_RESOLVED
                   --> proxy_server = "DIRECT"
t=178855 [st=0]    HTTP_STREAM_REQUEST_STARTED_JOB
                   --> source_dependency = 285751 (HTTP_STREAM_JOB)
t=178855 [st=0] -HTTP_STREAM_JOB_CONTROLLER


285751: HTTP_STREAM_JOB
https://i_removed_this.blob.core.windows.net/
Start Time: 2019-06-21 14:34:34.321

t=178855 [st=0] +HTTP_STREAM_JOB  [dt=0]
                 --> expect_spdy = false
                 --> original_url = "https://i_removed_this.blob.core.windows.net/"
                 --> priority = "MEDIUM"
                 --> source_dependency = 285750 (HTTP_STREAM_JOB_CONTROLLER)
                 --> url = "https://i_removed_thisblob.core.windows.net/"
                 --> using_quic = false
t=178855 [st=0]    HTTP_STREAM_JOB_WAITING  [dt=0]
                   --> should_wait = false
t=178855 [st=0]   +HTTP_STREAM_JOB_INIT_CONNECTION  [dt=0]
t=178855 [st=0]     +HOST_RESOLVER_IMPL_REQUEST  [dt=0]
                     --> address_family = 0
                     --> allow_cached_response = true
                     --> host = "i_removed_this.windows.net:443"
                     --> is_speculative = false
t=178855 [st=0]        HOST_RESOLVER_IMPL_IPV6_REACHABILITY_CHECK
                       --> cached = true
                       --> ipv6_available = false
t=178855 [st=0]     -HOST_RESOLVER_IMPL_REQUEST
                     --> net_error = -804 (ERR_DNS_CACHE_MISS)
t=178855 [st=0]      TCP_CLIENT_SOCKET_POOL_REQUESTED_SOCKET
                     --> group_id = "i_removed_this.blob.core.windows.net:443"
t=178855 [st=0]     +SOCKET_POOL  [dt=0]
t=178855 [st=0]        SOCKET_POOL_REUSED_AN_EXISTING_SOCKET
                       --> idle_ms = 3
t=178855 [st=0]        SOCKET_POOL_BOUND_TO_SOCKET
                       --> source_dependency = 253875 (SOCKET)
t=178855 [st=0]     -SOCKET_POOL
t=178855 [st=0]   -HTTP_STREAM_JOB_INIT_CONNECTION
t=178855 [st=0]    HTTP_STREAM_JOB_BOUND_TO_REQUEST
                   --> source_dependency = 285748 (URL_REQUEST)
t=178855 [st=0] -HTTP_STREAM_JOB

Разница между этим и успешным URL_request заключается в том, что URL_REQUEST не истекает, и мы можем правильно прочитать заголовки ответа, как показано ниже:

t=179171 [st=321]     +HTTP_TRANSACTION_READ_HEADERS  [dt=225]
t=179171 [st=321]        HTTP_STREAM_PARSER_READ_HEADERS  [dt=225]
t=179396 [st=546]        HTTP_TRANSACTION_READ_RESPONSE_HEADERS
                         --> HTTP/1.1 201 Created
                             Content-Length: 0
                             Content-MD5: i_removed_this
                             Server: Windows-Azure-Blob/1.0 Microsoft-HTTPAPI/2.0
                             x-ms-request-id: i_removed_this
                             x-ms-version: 2017-04-17
                             x-ms-request-server-encrypted: true
                             Access-Control-Expose-Headers: x-ms-request-id,Server,x-ms-version,Content-MD5,x-ms-request-server-encrypted,Content-Length,Date,Transfer-Encoding
                             Access-Control-Allow-Origin: *
                             Date: Fri, 21 Jun 2019 21:34:34 GMT
t=179396 [st=546]     -HTTP_TRANSACTION_READ_HEADERS
t=179396 [st=546]      NETWORK_DELEGATE_HEADERS_RECEIVED  [dt=0]
t=179396 [st=546]   -URL_REQUEST_START_JOB
t=179396 [st=546]    URL_REQUEST_DELEGATE_RESPONSE_STARTED  [dt=0]
t=179396 [st=546]    HTTP_TRANSACTION_READ_BODY  [dt=0]
t=179396 [st=546] -REQUEST_ALIVE

Время ожидания истекает через 30 секунд.

t=179042 [st=179041]    SOCKET_BYTES_SENT
                        --> byte_count = 3128
t=179042 [st=179041]    SOCKET_BYTES_SENT
                        --> byte_count = 2449
t=209478 [st=209477]    SOCKET_READ_ERROR
                        --> net_error = -7 (ERR_TIMED_OUT)
                        --> os_error = 60
t=209478 [st=209477]    SSL_READ_ERROR
                        --> error_lib = 33
                        --> error_reason = 7
                        --> file = "../../net/socket/socket_bio_adapter.cc"
                        --> line = 154
                        --> net_error = -7 (ERR_TIMED_OUT)
                        --> ssl_error = 1

И в наших журналах BLOB-объектов Azure мы видим, что он возвращает 500 SasNetworkError в блоке PUT, который показывает, что клиент закрыл соединение до истечения времени ожидания.

Наше веб-приложение обычно повторяет запрос PUT при 500 ошибках. Однако на Mac Chrome кажется, что мы его не обнаружили.

Кроме того, мы не уверены в актуальности следующей информации, но после истечения времени ожидания URL_REQUEST мы начали делать запросы к «ws: //127.0.0.1: 6263/4»:

285774: URL_REQUEST
ws://127.0.0.1:6263/4
Start Time: 2019-06-21 14:34:35.929

t=180463 [st=0] +REQUEST_ALIVE  [dt=1]
                 --> priority = "LOWEST"
                 --> url = "ws://127.0.0.1:6263/4"
t=180463 [st=0]    NETWORK_DELEGATE_BEFORE_URL_REQUEST  [dt=0]
t=180463 [st=0]   +URL_REQUEST_START_JOB  [dt=1]
                   --> load_flags = 18 (BYPASS_CACHE | DISABLE_CACHE)
                   --> method = "GET"
                   --> privacy_mode = 0
                   --> url = "ws://127.0.0.1:6263/4"
t=180463 [st=0]      NETWORK_DELEGATE_BEFORE_START_TRANSACTION  [dt=0]
t=180463 [st=0]      HTTP_CACHE_GET_BACKEND  [dt=0]
t=180463 [st=0]     +HTTP_STREAM_REQUEST  [dt=1]
t=180463 [st=0]        HTTP_STREAM_JOB_CONTROLLER_BOUND
                       --> source_dependency = 285775 (HTTP_STREAM_JOB_CONTROLLER)
t=180464 [st=1]        HTTP_STREAM_REQUEST_BOUND_TO_JOB
                       --> source_dependency = 285776 (HTTP_STREAM_JOB)
t=180464 [st=1]     -HTTP_STREAM_REQUEST
t=180464 [st=1]   -URL_REQUEST_START_JOB
                   --> net_error = -102 (ERR_CONNECTION_REFUSED)
t=180464 [st=1]    URL_REQUEST_DELEGATE_RESPONSE_STARTED  [dt=0]
t=180464 [st=1] -REQUEST_ALIVE
                 --> net_error = -102 (ERR_CONNECTION_REFUSED)
...