loading never stops due to slow SPDY push

RESOLVED FIXED in mozilla37

Status

()

defect
RESOLVED FIXED
5 years ago
5 years ago

People

(Reporter: amwebdk, Assigned: mcmanus)

Tracking

32 Branch
mozilla37
x86_64
macOS
Points:
---
Dependency tree / graph

Firefox Tracking Flags

(Not tracked)

Details

(Whiteboard: [spdy])

Attachments

(4 attachments, 5 obsolete attachments)

Posted file server.js
User Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_9_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/37.0.2062.122 Safari/537.36

Steps to reproduce:

Consider this SPDY enabled website:
<!DOCTYPE html>
<link rel="stylesheet" href="/slow.css">

where slow.css is send using SPDY PUSH, but the content is delayed.
(When running a localhost just delaying it 10ms is enough to cause the issue)

Now go to the site an observe that the site never stops loading and the layout is as if /slow.css isn't yet loaded.

The test server (in node.js using node-spdy) is attached.

I think this is caused by an race condition between the PUSH stream and the parsing of the <link ...> tag. Because if I remove the <link> tag the page loading stops quite quickly.

The test pass in Chrome.


Actual results:

1) Firefox send a request for the main HTML page.
2) It then acknowledge the push stream for /slow.css.
3) The slow.css file content is send, but not received by firefox. For instance it dosn't show up in the inspector.

The test server output is:
test server: https://localhost:8000
- Request for / send
- push content send



Expected results:

1) Firefox send a request for the main HTML page.
2) It then acknowledge the push stream for /slow.css.
3) The slow.css file content is send, firefox rerenders the page and stops showing the loading animation.

The test server output should not change:
test server: https://localhost:8000
- Request for / send
- push content send
Whiteboard: [spdy]
Hardware: x86 → x86_64
Component: Networking → Networking: HTTP
Summary: loading never stops dude to slow SPDY push → loading never stops due to slow SPDY push
this is spdy/3.1.. I can confirm the str
Status: UNCONFIRMED → NEW
Ever confirmed: true
Assignee: nobody → mcmanus
Status: NEW → ASSIGNED
primarily this is triggered by an invalid server side config. (btw - thanks for including the server code!)

You server sends a settings for MAX_CONCURRENT of 0.

Firefox requests / 0x1 before receiving that settings.. so it sends it based on the default MAX_CONCURRENT of 100. But that's just a race condition - we certainly may never send the request for / either.

by the time firefox needs to generate the request for slow.css it has processed the MAX_CONCURRENT of 0 and queues the request, waiting for the server to recover. (we treat this as a server request to slow down for a minute).

I think that's a firefox bug too in the sense that the pushed stream has been accepted and will not count against the MAX_CONCURRENT number.. so queueing is premature. I will pursue this.

This is the node-spdy code that sets it to 0
https://github.com/indutny/node-spdy/blob/808270dac4804aaef328062cc084745a8169da83/lib/spdy/connection.js#L30

you can workaround it and have your test work fine by adding maxStreams : 100 to your options in your server code.
I must admit that I haven't checked the actual network traffic, so it possible that MAX_CONCURRENT is 0. But from what I can see (using console.log(state.maxStreams)), the maxStreams was set to 100 (spdy version 1.28.1). Also explicitly setting maxStreams : 100, makes no difference in the test.
(In reply to Andreas Madsen from comment #3)
>
> console.log(state.maxStreams)), the maxStreams was set to 100 (spdy version
> 1.28.1). 

interestingly, 1.28.1 sends maxStreams 100.. 1.29.0 sent 0. That's probably a node-spdy bug.
Indutny (author of node-spdy) have confirmed there is a bug in node-spdy 1.29.0: https://github.com/indutny/node-spdy/issues/180 . But since the testcase fails with node-spdy 1.28.1 too, this doesn't solve the entire problem.
ack.. I had to update the timeout to 1000 to see it locally
Attachment #8506397 - Flags: review?(hurley)
Attachment #8506398 - Flags: review?(hurley)
the original problem turned out to be much simpler... in the case where the push fin arrives arrives after all the data bytes have been by a synthetic pull (i.e. the css parser in this case - not the push cache) then when the fin does arrive it gets stuck in the pipe between the push and css parser.

we've got patches here for that problem as well as the max_concurrent problem.

Thanks andrea - can you confirm the fix from the try builds (they'll take a couple hours to complete) 
https://ftp.mozilla.org/pub/mozilla.org/firefox/try-builds/mcmanus@ducksong.com-5f20d62a1740/

https://tbpl.mozilla.org/?tree=Try&rev=5f20d62a1740
Thanks

The Mac build appears to be corrupted, but the Windows build works fine. I will consider this bug fixed.
thanks.. I've started a more thorough try run just to make sure nothing bad is going on with the patches and mac.

https://tbpl.mozilla.org/?tree=Try&rev=1f06cc0e98ee
Attachment #8506398 - Flags: review?(hurley) → review+
Comment on attachment 8506397 [details] [diff] [review]
h2 push hit not subject to max_concurrent 2/2

Review of attachment 8506397 [details] [diff] [review]:
-----------------------------------------------------------------

So the two big comments apply equally to spdy and h2, but I didn't feel like duplicating myself :)

::: netwerk/protocol/http/Http2Session.cpp
@@ +437,5 @@
> +  mReadyForWrite.Push(stream);
> +  SetWriteCallbacks();
> +
> +  // Kick off the SYN transmit without waiting for the poll loop
> +  // This won't work for stream id=1 because there is no segment reader

nit: stream id=3 for h2 :)

::: netwerk/protocol/http/Http2Stream.cpp
@@ +341,4 @@
>        // RegisterStreamID (below) because of the push match.
>        // Release that semaphore count immediately (instead of waiting for
>        // cleanup stream) so we can initiate more pull streams.
>        mSession->MaybeDecrementConcurrent(this);

It's not clear to me that this is still necessary. It won't hurt anything, but I'm fairly certain it will always be a no-op (we don't call IncrementConcurrent until after this code has executed).

@@ +1100,5 @@
> +      }
> +    }
> +
> +    if (mRequestHeadersDone && !mOpenGenerated) {
> +      if (!mSession->RoomForMoreConcurrent()) {

So I'm not crazy about the stream having to explicitly manage the concurrency situation in the session. I know these two things don't have the greatest separation in the code already, but this seems a bit much. How would you feel about doing something like

if (!mSession->TryToActivate(this)) {
  return NS_OK;
}

and Http2Session::TryToActivate (or whatever you want to call it) will take care of the RoomForMoreConcurrent ? IncrementConcurrent : QueueStream logic. It doesn't change the logic any, but it leaves a little more separation in terms of managing the concurrency count (and actually separates it entirely, if we remove the call to MaybeDecrementConcurrent noted above).

@@ +1105,5 @@
> +        LOG3(("Http2Stream::OnReadSegment %p no room for more concurrent "
> +              "streams %d\n", this));
> +          mSession->QueueStream(this);
> +          return NS_OK;
> +        }

nit: indentation

::: netwerk/protocol/http/SpdyStream3.cpp
@@ +1462,5 @@
> +        LOG3(("SpdyStream3::OnReadSegment %p no room for more concurrent "
> +              "streams %d\n", this));
> +          mSession->QueueStream(this);
> +          return NS_OK;
> +        }

nit: indentation

::: netwerk/protocol/http/SpdyStream31.cpp
@@ +1480,5 @@
> +        LOG3(("SpdyStream31::OnReadSegment %p no room for more concurrent "
> +              "streams %d\n", this));
> +          mSession->QueueStream(this);
> +          return NS_OK;
> +        }

nit: indentation
Attachment #8506397 - Flags: review?(hurley)
Attachment #8544141 - Flags: review?(hurley)
Attachment #8506397 - Attachment is obsolete: true
Comment on attachment 8544139 [details] [diff] [review]
h2 push loses fin bit race condition 1/2

updated for bitrot
Attachment #8544139 - Flags: review+
nick - good suggestions. thanks.
Attachment #8544141 - Flags: review?(hurley) → review+
https://hg.mozilla.org/mozilla-central/rev/047afa953b9c
https://hg.mozilla.org/mozilla-central/rev/28fff54451dd
Status: ASSIGNED → RESOLVED
Closed: 5 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla37
Depends on: 1119810
Depends on: 1119926
I'm going to backout the pushes in 18
Status: RESOLVED → REOPENED
Keywords: leave-open
Resolution: FIXED → ---
from bug 1119926 a good test before relanding: https://www.httpvshttps.com/
Depends on: 1120096
these were backed out of mozilla-central with parent b098bff0d341 (gecko37)
Keywords: leave-open
Attachment #8544139 - Attachment is obsolete: true
Attachment #8549995 - Flags: review?(hurley)
Attachment #8544141 - Attachment is obsolete: true
Comment on attachment 8506398 [details] [diff] [review]
h2 push loses fin bit race condition 1/2

># HG changeset patch
># User Patrick McManus <mcmanus@ducksong.com>
># Date 1413492134 14400
>#      Thu Oct 16 16:42:14 2014 -0400
># Node ID ad5bb05c17fa2416e18008636d14e0bf7c2b8ab7
># Parent  b2162376e0656484eafa8b61418979084786b347
>bug 1072478 - h2 push loses fin bit race condition 1/2 r=hurley
>
>diff --git a/netwerk/protocol/http/Http2Push.cpp b/netwerk/protocol/http/Http2Push.cpp
>--- a/netwerk/protocol/http/Http2Push.cpp
>+++ b/netwerk/protocol/http/Http2Push.cpp
>@@ -255,23 +255,23 @@ Http2PushTransactionBuffer::WriteSegment
>                                        count, countWritten);
>   if (NS_SUCCEEDED(rv)) {
>     mBufferedHTTP1Used += *countWritten;
>   }
>   else if (rv == NS_BASE_STREAM_CLOSED) {
>     mIsDone = true;
>   }
> 
>-  if (Available()) {
>+  if (Available() || mIsDone) {
>     Http2Stream *consumer = mPushStream->GetConsumerStream();
> 
>     if (consumer) {
>       LOG3(("Http2PushTransactionBuffer::WriteSegments notifying connection "
>-            "consumer data available 0x%X [%u]\n",
>-            mPushStream->StreamID(), Available()));
>+            "consumer data available 0x%X [%u] done=%d\n",
>+            mPushStream->StreamID(), Available(), mIsDone));
>       mPushStream->ConnectPushedStream(consumer);
>     }
>   }
> 
>   return rv;
> }
> 
> uint32_t
>diff --git a/netwerk/protocol/http/SpdyPush3.cpp b/netwerk/protocol/http/SpdyPush3.cpp
>--- a/netwerk/protocol/http/SpdyPush3.cpp
>+++ b/netwerk/protocol/http/SpdyPush3.cpp
>@@ -279,23 +279,23 @@ SpdyPush3TransactionBuffer::WriteSegment
>                                        count, countWritten);
>   if (NS_SUCCEEDED(rv)) {
>     mBufferedHTTP1Used += *countWritten;
>   }
>   else if (rv == NS_BASE_STREAM_CLOSED) {
>     mIsDone = true;
>   }
> 
>-  if (Available()) {
>+  if (Available() || mIsDone) {
>     SpdyStream3 *consumer = mPushStream->GetConsumerStream();
> 
>     if (consumer) {
>       LOG3(("SpdyPush3TransactionBuffer::WriteSegments notifying connection "
>-            "consumer data available 0x%X [%u]\n",
>-            mPushStream->StreamID(), Available()));
>+            "consumer data available 0x%X [%u] done=%d\n",
>+            mPushStream->StreamID(), Available(), mIsDone));
>       mPushStream->ConnectPushedStream(consumer);
>     }
>   }
> 
>   return rv;
> }
> 
> uint32_t
>diff --git a/netwerk/protocol/http/SpdyPush31.cpp b/netwerk/protocol/http/SpdyPush31.cpp
>--- a/netwerk/protocol/http/SpdyPush31.cpp
>+++ b/netwerk/protocol/http/SpdyPush31.cpp
>@@ -277,23 +277,23 @@ SpdyPush31TransactionBuffer::WriteSegmen
>                                        count, countWritten);
>   if (NS_SUCCEEDED(rv)) {
>     mBufferedHTTP1Used += *countWritten;
>   }
>   else if (rv == NS_BASE_STREAM_CLOSED) {
>     mIsDone = true;
>   }
> 
>-  if (Available()) {
>+  if (Available() || mIsDone) {
>     SpdyStream31 *consumer = mPushStream->GetConsumerStream();
> 
>     if (consumer) {
>       LOG3(("SpdyPush31TransactionBuffer::WriteSegments notifying connection "
>-            "consumer data available 0x%X [%u]\n",
>-            mPushStream->StreamID(), Available()));
>+            "consumer data available 0x%X [%u] done=%d\n",
>+            mPushStream->StreamID(), Available(), mIsDone));
>       mPushStream->ConnectPushedStream(consumer);
>     }
>   }
> 
>   return rv;
> }
> 
> uint32_t
Attachment #8506398 - Attachment is obsolete: true
Attachment #8549994 - Flags: review+
Posted patch INTERDIFFSplinter Review
this is the interdiff of patch 2 from its previous r+'d version until now - this is rolled into the r?'d patch.
Comment on attachment 8549998 [details] [diff] [review]
INTERDIFF

Review of attachment 8549998 [details] [diff] [review]:
-----------------------------------------------------------------

Will r+ the new part 2, but that's dependent on fixing the things here (especially that duplicated code bit)

::: netwerk/protocol/http/Http2Stream.cpp
@@ +171,5 @@
>      if (rv == NS_BASE_STREAM_WOULD_BLOCK && !mTxInlineFrameUsed)
>        mRequestBlockedOnRead = 1;
>  
> +    // A transaction that had already generated its headers before it was
> +    // queued at the spdy level (due to concurrency concerns) may not call

nit: s/spdy/session/

::: netwerk/protocol/http/SpdyStream31.cpp
@@ +157,5 @@
> +      OnReadSegment("", 0, &wasted);
> +      mSegmentReader = nullptr;
> +    }
> +
> +    // A transaction that had already generated its headers before it was

This seems to be duplicate code.

::: testing/xpcshell/moz-http2/moz-http2.js
@@ +92,5 @@
> +  resp : null,
> +
> +  onTimeout : function onTimeout() {
> +    this.resp.writeHead(200);
> +    this.resp.end("It's all good 75ms.");

nit: 750, not 75

::: testing/xpcshell/moz-spdy/moz-spdy.js
@@ +80,5 @@
> +  resp : null,
> +
> +  onTimeout : function onTimeout() {
> +    this.resp.writeHead(200);
> +    this.resp.end("It's all good spdy 75ms.");

nit: 750, not 75
Comment on attachment 8549995 [details] [diff] [review]
h2 push hit not subject to max_concurrent 2/2

Review of attachment 8549995 [details] [diff] [review]:
-----------------------------------------------------------------

Dependent on fixes mentioned in interdiff comment, r=me
Attachment #8549995 - Flags: review?(hurley) → review+
(In reply to Nicholas Hurley [:hurley] from comment #28)
>
> 
> This seems to be duplicate code.
>

good catch - thanks!
Attachment #8549995 - Attachment is obsolete: true
Attachment #8550374 - Flags: review+
https://hg.mozilla.org/mozilla-central/rev/5ec4e66b6b6f
https://hg.mozilla.org/mozilla-central/rev/4aefc5bf7ec4
Status: REOPENED → RESOLVED
Closed: 5 years ago5 years ago
Resolution: --- → FIXED
Depends on: 1124717
Duplicate of this bug: 1139910
You need to log in before you can comment on or make changes to this bug.