I am trying to upload a 57.86GB file to an azure storage blob container and noticing that it fails regularly only on Chrome 75.0.3770.100 (Official Build) (64-bit) on MacOS Mojave 10.14.3
We are splitting the file into 4MB blocks and have 6 connections open.
When it fails, the PUT request stalls/timesout and the upload halts.
Has anyone run across similar issues? Does anyone have an idea as to where to look next to debug this issue?
Here are the logs that we got from 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
The difference between this and a successfull URL_request is that the URL_REQUEST doesn't time out and we are properly able to read the response headers as seen below:
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
The socket does timeout after about 30 seconds.
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
And in our azure storage blob logs, we can see that it returns a 500 SasNetworkError on the PUT block which shows that the client closed the connection before the timeout expiration.
Our web app will normally retry the PUT request on 500 errors. However, on Mac Chrome it seems that we didn't detect it.
Also, not sure if the following information is relevant, but after the timed out URL_REQUEST, we started to make requests to "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)