net::ERR_QUIC_PROTOCOL_ERROR while streaming audio from Google Cloud Storage |
|||||||||
Issue descriptionFor the past few weeks, I've been seeing seeing frequent networking errors in stable-channel Chrome (e.g. 49.0.2623.95, I think) while trying to stream audio files from Google Cloud Storage using <audio>. These manifest as net::ERR_QUIC_PROTOCOL_ERROR errors in the JS console. They don't happen continually, but when they're happening I see them every few minutes. I've seen this both at home on a Chromebook connected to Comcast via wifi and on my corp workstation, so I suspect that it's either a Cloud Storage issue or a cross-platform Chrome networking issue rather than a problem somewhere in between. I hopefully captured the errors in a few chrome://net-internals traces at home last night, which I've uploaded to https://drive.google.com/corp/drive/u/0/folders/0ByeZYyW9WlyvVkl5VDY0Z1NtSjQ -- please let me know if you need access or if there's more data I can provide. Thanks!
,
Apr 7 2016
Thanks, I saw this a few more times while running with --enable-logging --v=1 --log-net-log=/some/path. I've uploaded the log file to the same folder as before (http://drive/corp/drive/u/0/folders/0ByeZYyW9WlyvVkl5VDY0Z1NtSjQ) with the name quic-chrome-net.txt. I'm not sure if you get local timestamps in the log, but the rough timeline of events was: ~08:15:26 - first stream started [1:1:0407/081734:ERROR:render_media_log.cc(20)] MediaEvent: PIPELINE_ERROR pipeline: read error [1:1:0407/081735:ERROR:render_media_log.cc(20)] MediaEvent: PIPELINE_ERROR pipeline: read error [1:1:0407/081735:ERROR:render_media_log.cc(20)] MediaEvent: PIPELINE_ERROR pipeline: read error ~08:17:42 - first stream errored out; switched to second file [1:1:0407/082106:ERROR:render_media_log.cc(20)] MediaEvent: PIPELINE_ERROR pipeline: read error [1:1:0407/082108:ERROR:render_media_log.cc(20)] MediaEvent: PIPELINE_ERROR pipeline: read error [1:1:0407/082109:ERROR:render_media_log.cc(20)] MediaEvent: PIPELINE_ERROR pipeline: read error ~08:21:09 - second stream errored out; switched to third file
,
Apr 7 2016
I'm having a hard time lining up the logs, but is it correct that the requests are timing out after receiving a fair amount of data? I don't see any indication a PING frame is being sent.
,
Apr 7 2016
Yes, this often (but maybe not always) happens after multiple megabytes of the file have been received, I believe.
,
Apr 7 2016
> ~08:15:26 - first stream started In the logs, header response is around Thu, 07 Apr 2016 14:15:25 GMT. Wondering if the clocks are off by an hour. The following session received a response at the above time and didn't receive data for another 30secs and it timed out. 561: QUIC_SESSION derat-music.appspot.com Start Time: 2016-04-07 07:14:54.127 t= 5582 [st= 0] +QUIC_SESSION [dt=384055+] ... t= 37402 [st= 31820] QUIC_HTTP_STREAM_READ_RESPONSE_HEADERS --> :status: 304 alt-svc: quic=":443"; ma=2592000; v="32,31,30,29,28,27,26,25" alternate-protocol: 443:quic cache-control: no-cache, must-revalidate date: Thu, 07 Apr 2016 14:15:25 GMT ... t= 37424 [st= 31842] QUIC_SESSION_PACKET_SENT --> packet_number = "24" --> sent_time_us = "852583571122" --> size = 37 --> transmission_type = 0 t= 66425 [st= 60843] QUIC_SESSION_CLOSED --> from_peer = false --> quic_error = 25 (QUIC_CONNECTION_TIMED_OUT)
,
Apr 7 2016
Sorry, should've mentioned that I'm bucking the trend and living in a non-PDT time zone. :-P UTC-6 right now. I can file an internal bug if this appears to be a Cloud Storage problem. (I know nothing about QUIC. Does the lack of automatic retries here indicate an implementation problem?)
,
Apr 7 2016
Here's a minimal test case: https://www.erat.org/temp/20160407/crbug_600001.html When you click the "Play" button, it tries to play a 5-minute empty MP3 file (4800811 bytes, originally downloaded from http://www.xamuel.com/blank-mp3s/) that's publicly shared from Cloud Storage. I've gotten "GET https://storage.googleapis.com/derat-test/5min.mp3 net::ERR_QUIC_PROTOCOL_ERROR" on two out of two tries, the first time after maybe a minute (~1 MB) and the second time after two minutes (~2 MB). I think that the alert() on error isn't working, but the error is visible on the JS console. I'm on my corp Linux workstation running 49.0.2623.110 (Official Build) (64-bit).
,
Apr 8 2016
At 2016-04-07 07:15:25.12, we get ERR_QUIC_PROTOCOL_ERROR (because there was no activity on QUIC_SESSION for 30secs). 30 secs before that was the last time we receive data for both errors. 764: URL_REQUEST https://storage.cloud.google.com/derat-music-songs/explosions_in_the_sky%2Fthe_wilderness%2F05%20-%20Disintegration%20Anxiety.mp3 Start Time: 2016-04-07 07:15:22.791 ... t=150388 [st=116142] HTTP_TRANSACTION_READ_BODY [dt=0] t=150388 [st=116142] URL_REQUEST_JOB_BYTES_READ --> byte_count = 32768 t=151202 [st=116956] HTTP_TRANSACTION_READ_BODY [dt=0] --> net_error = -356 (ERR_QUIC_PROTOCOL_ERROR) t=151202 [st=116956] FAILED --> net_error = -356 (ERR_QUIC_PROTOCOL_ERROR) t=151203 [st=116957] -REQUEST_ALIVE --> net_error = -356 (ERR_QUIC_PROTOCOL_ERROR) ---------------------- 788: QUIC_SESSION 00e9e64bacae7b81a9461cfe80a334abb7e17485b05a28983e-apidata.googleusercontent.com Start Time: 2016-04-07 07:15:22.988 ... t=121864 [st= 87421] QUIC_SESSION_ACK_FRAME_SENT --> delta_time_largest_observed_us = "17" --> entropy_hash = 216 --> largest_observed = "8001" --> latest_revived_packet = "0" --> missing_packets = [] --> received_packet_times = [{"packet_number":8000,"received":"852668010855"},{"packet_number":8001,"received":"852668011013"}] --> truncated = false t=121864 [st= 87421] QUIC_SESSION_STOP_WAITING_FRAME_SENT --> sent_info = {"least_unacked":"3907"} t=121864 [st= 87421] QUIC_SESSION_PACKET_SENT --> packet_number = "4002" --> sent_time_us = "852668011061" --> size = 43 --> transmission_type = 0 .... t=121894 [st= 87451] QUIC_SESSION_UNAUTHENTICATED_PACKET_HEADER_RECEIVED --> connection_id = "11695398942949354114" --> entropy_flag = 0 --> fec_flag = 0 --> fec_group = 0 --> packet_number = "8005" --> reset_flag = 0 --> version_flag = 0 t=121894 [st= 87451] QUIC_SESSION_PACKET_AUTHENTICATED t=121894 [st= 87451] QUIC_SESSION_ACK_FRAME_RECEIVED --> delta_time_largest_observed_us = "0" --> entropy_hash = 197 --> largest_observed = "3989" --> latest_revived_packet = "0" --> missing_packets = [] --> received_packet_times = [...{"packet_number":3989,"received":"852667998704"}] --> truncated = false t=121894 [st= 87451] QUIC_SESSION_STOP_WAITING_FRAME_RECEIVED --> sent_info = {"least_unacked":"7976"} t=150896 [st=116453] QUIC_SESSION_CLOSED --> from_peer = false --> quic_error = 25 (QUIC_CONNECTION_TIMED_OUT --------- 787: UDP_SOCKET [2607:f8b0:400f:803::2001]:443 Start Time: 2016-04-07 07:15:22.988 ... t=121894 [st= 87451] UDP_BYTES_RECEIVED --> address = "[2607:f8b0:400f:803::2001]:443" --> byte_count = 95 t=150896 [st=116453] -SOCKET_ALIVE =========================================== 2nd error happens at 07:17:39.746. At 07:17:38.028 QUIC_SESSION times out because it was idle for 30secs. 1032: URL_REQUEST https://storage.cloud.google.com/derat-music-songs/explosions_in_the_sky%2Fthe_wilderness%2F06%20-%20Losing%20the%20Light.mp3 Start Time: 2016-04-07 07:17:35.874 ... t=363753 [st=196424] HTTP_TRANSACTION_READ_BODY [dt=0] --> net_error = -356 (ERR_QUIC_PROTOCOL_ERROR) 970: QUIC_SESSION 00e9e64bac65c43b2fbca3ab9f90e79c611422cdf219077106-apidata.googleusercontent.com Start Time: 2016-04-07 07:17:34.159 t=334644 [st=169030] QUIC_SESSION_ACK_FRAME_RECEIVED --> delta_time_largest_observed_us = "0" --> entropy_hash = 3 --> largest_observed = "6185" --> latest_revived_packet = "0" --> missing_packets = [] --> received_packet_times = [...{"packet_number":6185,"received":"852880748681"}] --> truncated = false t=334644 [st=169030] QUIC_SESSION_STOP_WAITING_FRAME_RECEIVED --> sent_info = {"least_unacked":"12373"} t=363644 [st=198030] QUIC_SESSION_CLOSED --> from_peer = false --> quic_error = 25 (QUIC_CONNECTION_TIMED_OUT) ... 969: UDP_SOCKET [2607:f8b0:400f:803::2001]:443 Start Time: 2016-04-07 07:17:34.159 ... t=334640 [st=169026] UDP_BYTES_SENT --> byte_count = 49 t=334644 [st=169030] UDP_BYTES_RECEIVED --> address = "[2607:f8b0:400f:803::2001]:443" --> byte_count = 89 t=363645 [st=198031] -SOCKET_ALIVE
,
Apr 9 2016
Nice repro case, that errors out for me as well. Raman, I notice that the application is still slowly reading data in the URL_REQUEST, even though the request has finished in the QUIC_SESSION(the fin was received). It appears that as soon as the QUIC_SESSION times out, and the request immediately fails, even though it was already completed successfully.
,
Apr 13 2016
Thanks for looking at this! Does that suggest that this is a problem in Chrome's QUIC implementation (perhaps specific to media streaming), or should I try to loop in someone from Cloud Storage?
,
Apr 13 2016
The issue is definitely in Chrome. I believe Ryan has a solution in mind.
,
Apr 27 2016
Sorry to be a nag, but any updates here? Is disabling the #enable-quic flag (which results in a pretty painful login experience on Chrome OS) the only workaround?
,
May 3 2016
Buck said he would work on this. There is a proposed approach to fix it, but it's not trivial.
,
Jun 21 2016
The following revision refers to this bug: https://chromium.googlesource.com/chromium/src.git/+/03b32983a8ceb3a1da374cf34ce26b6085abd7b8 commit 03b32983a8ceb3a1da374cf34ce26b6085abd7b8 Author: rch <rch@chromium.org> Date: Tue Jun 21 00:08:33 2016 Send QUIC ping packets when there are draining streams, even if there are no open streams. BUG= 600001 Review-Url: https://codereview.chromium.org/2085633003 Cr-Commit-Position: refs/heads/master@{#400846} [modify] https://crrev.com/03b32983a8ceb3a1da374cf34ce26b6085abd7b8/net/quic/quic_chromium_client_session.cc [modify] https://crrev.com/03b32983a8ceb3a1da374cf34ce26b6085abd7b8/net/quic/quic_chromium_client_session.h
,
Jun 21 2016
,
Jun 21 2016
I've verified this works on the newest version of Chrome Canary.
,
Jun 21 2016
Your change meets the bar and is auto-approved for M52 (branch: 2743)
,
Jun 22 2016
The following revision refers to this bug: https://chromium.googlesource.com/chromium/src.git/+/e291b4f8f2997fe1b9c82b3183fe4297f1552053 commit e291b4f8f2997fe1b9c82b3183fe4297f1552053 Author: Ryan Hamilton <rch@chromium.org> Date: Wed Jun 22 04:00:16 2016 [m52] Send QUIC ping packets when there are draining streams, even if there are no open streams. BUG= 600001 Review-Url: https://codereview.chromium.org/2085633003 Cr-Commit-Position: refs/heads/master@{#400846} (cherry picked from commit 03b32983a8ceb3a1da374cf34ce26b6085abd7b8) Review URL: https://codereview.chromium.org/2082223002 . Cr-Commit-Position: refs/branch-heads/2743@{#446} Cr-Branched-From: 2b3ae3b8090361f8af5a611712fc1a5ab2de53cb-refs/heads/master@{#394939} [modify] https://crrev.com/e291b4f8f2997fe1b9c82b3183fe4297f1552053/net/quic/quic_chromium_client_session.cc [modify] https://crrev.com/e291b4f8f2997fe1b9c82b3183fe4297f1552053/net/quic/quic_chromium_client_session.h
,
Jun 27 2016
Thanks! I take it that this should be fixed now, right?
,
Jul 29 2016
Confirming that this seems to no longer be broken in M52 on both Linux and Chrome OS. |
|||||||||
►
Sign in to add a comment |
|||||||||
Comment 1 by rtenneti@chromium.org
, Apr 2 2016