Debugging SPDY/3 in Firefox Sandbox Builds

‹prev | My Chain | next›

Yesterday, I started playing with a sandbox version of Firefox to see how it handles the SPDY / version 3 implementation in node-spdy.

Most of my recent exploration of SPDY has surrounded the new flow control features in spdy/3 and I have an implementation that works with both Chrome and spdylay. Unfortunately, Firefox does not seem like it.

One of the differences between the Firefox implementation and the Chrome and spdylay implementations is that Firefox is not using the default 64kb receive window as laid out in the specification. In fact, it specifies a whopping 256 MB. Given that none of the images in my test page (show in Chrome) are more than 1MB in size, let alone 256mb, then flow control should never enter the equation:

In other words, my spdy/3 conversation should behave very much like a spdy/2 conversation. This should just work in that case, since node-spdy has long boasted a robust spdy/2 implementation. But, as I found last night, Firefox behaves as if only small parts of the image is being sent:

That would seem to suggest that Firefox is struggling with flow control, but how can it if it is not using flow control?

I do wonder if 256mb is reasonable for a receive window, especially given that the default is only 64kb. As Patrick McManus stated in comments, it does not seem unreasonable. I am running on the loopback interface of localhost, so the BDP is not network constrained. I would say that the receive window ought to be some fraction of BDP since the receive window is per-SPDY stream, not for the entire connection. If a web site is trying to transfer 100 items, then the maximum the receive window could be without risking data loss is 1/100th of the BDP.

I have seen what setting the receive window too low can do data transfer—it's not good. The result is noticeable slowness in processing of images. So setting the receive window as high as possible makes some sense.

Regardless, that does not help me answer the question at hand.

So I again start my sandbox version of Firefox with the necessary environment variable to obtain copious logging information:

export NSPR_LOG_MODULES=nsHttp:5,nsSocketTransport:5,nsHostResolver:5
export NSPR_LOG_FILE=/tmp/log.txt
./firefox

In my node-spdy output, I see some of the logging that I enabled yesterday:

Express server listening on port 3000 in development mode
settings.initial_window_size: 268435456
sending 1: 599 (false)
sending 1: 0 (false)
sending 1: 0 (true)
sending 3: 110 (false)
sending 3: 0 (false)
sending 3: 0 (true)
sending 5: 19 (false)
sending 5: 0 (false)
sending 5: 0 (true)
sending 7: 1300 (false)
sending 7: 1300 (false)
sending 7: 1300 (false)
sending 7: 1300 (false)
....

The value in parentheses is DATA FIN, indicating whether or not the stream in complete. In my example, streams #7 (which is I see starting above) and #9 are the streams carrying the large images. After a little while, stream #7 stops transferring and #9 starts:

...
sending 7: 1300 (false)
sending 7: 660 (false)
sending 9: 1300 (false)
sending 9: 1300 (false)
sending 9: 1300 (false)
sending 9: 1300 (false)
...

This goes on for a while until the first image is complete:

...
sending 7: 1300 (false)
sending 7: 369 (false)
sending 9: 1300 (false)
sending 9: 1300 (false)
...
sending 9: 1300 (false)
sending 9: 660 (false)
sending 7: 0 (false)
sending 7: 0 (true)
sending 9: 1300 (false)
...

I am unsure why stream #7 transmits a zero-length DATA packet just before the DATA FIN. I do not think that would cause a problem, but I am not positive.

Eventually, the second image is also completely transferred:

...
sending 9: 1300 (false)
sending 9: 1300 (false)
sending 9: 28 (false)
sending 9: 0 (false)
sending 9: 0 (true)
settings.initial_window_size: 268435456

Interestingly, Firefox seems to be sending another SETTINGS frame reaffirming that the initial receive window size for new streams should be 256mb.

Patrick also indicated in comments that if I search for SpdySession3::UpdateLocalRwin in the log output, then I would see Firefox acknowledging receipt of the DATA frames. I do see them, but... I see none of the stream #9 DATA frames until much of stream #7 has been processed:

...
➜  node-spdy git:(spdy-v3) ✗ grep SpdySession3::UpdateLocalRwin /tmp/log.txt
SpdySession3::UpdateLocalRwin 7ffbd2e69400 0x1 599
SpdySession3::UpdateLocalRwin 7ffbd2e69400 0x1 0
SpdySession3::UpdateLocalRwin 7ffbd2e69400 0x3 110
SpdySession3::UpdateLocalRwin 7ffbd2e69400 0x3 0
SpdySession3::UpdateLocalRwin 7ffbd2e69400 0x5 19
SpdySession3::UpdateLocalRwin 7ffbd2e69400 0x5 0
SpdySession3::UpdateLocalRwin 7ffbd2e69400 0x7 1300
SpdySession3::UpdateLocalRwin 7ffbd2e69400 0x7 1300
SpdySession3::UpdateLocalRwin 7ffbd2e69400 0x7 1300
SpdySession3::UpdateLocalRwin 7ffbd2e69400 0x7 1300
SpdySession3::UpdateLocalRwin 7ffbd2e69400 0x7 1300
....
SpdySession3::UpdateLocalRwin 7ffbd2e69400 0x7 1300
SpdySession3::UpdateLocalRwin 7ffbd2e69400 0x7 1300
SpdySession3::UpdateLocalRwin Ack 7ffbd2e69400 0x7 65660
SpdySession3::UpdateLocalRwin 7ffbd2e69400 0x7 1300
SpdySession3::UpdateLocalRwin 7ffbd2e69400 0x7 1300
...
SpdySession3::UpdateLocalRwin 7ffbd2e69400 0x7 1300
SpdySession3::UpdateLocalRwin Ack 7ffbd2e69400 0x7 66320
SpdySession3::UpdateLocalRwin 7ffbd2e69400 0x7 1300
...
SpdySession3::UpdateLocalRwin 7ffbd2e69400 0x7 1300
SpdySession3::UpdateLocalRwin 7ffbd2e69400 0x7 660
...

Then I see a little bit of stream #9 and then.. nothing more:

...
SpdySession3::UpdateLocalRwin 7ffbd2e69400 0x7 1300
SpdySession3::UpdateLocalRwin 7ffbd2e69400 0x7 660
SpdySession3::UpdateLocalRwin 7ffbd2e69400 0x9 1300
SpdySession3::UpdateLocalRwin 7ffbd2e69400 0x9 1300
SpdySession3::UpdateLocalRwin 7ffbd2e69400 0x9 1300
SpdySession3::UpdateLocalRwin 7ffbd2e69400 0x9 1300
SpdySession3::UpdateLocalRwin 7ffbd2e69400 0x9 1300
SpdySession3::UpdateLocalRwin 7ffbd2e69400 0x9 1300
SpdySession3::UpdateLocalRwin 7ffbd2e69400 0x9 1300
SpdySession3::UpdateLocalRwin 7ffbd2e69400 0x9 1300
SpdySession3::UpdateLocalRwin 7ffbd2e69400 0x9 1300
SpdySession3::UpdateLocalRwin 7ffbd2e69400 0x9 1300
SpdySession3::UpdateLocalRwin 7ffbd2e69400 0x9 1300
SpdySession3::UpdateLocalRwin 7ffbd2e69400 0x9 1300
SpdySession3::UpdateLocalRwin 7ffbd2e69400 0x9 1300
SpdySession3::UpdateLocalRwin 7ffbd2e69400 0x9 1300
SpdySession3::UpdateLocalRwin 7ffbd2e69400 0x9 1300
SpdySession3::UpdateLocalRwin 7ffbd2e69400 0x9 1300
SpdySession3::UpdateLocalRwin 7ffbd2e69400 0x9 1300
SpdySession3::UpdateLocalRwin 7ffbd2e69400 0x9 1300
SpdySession3::UpdateLocalRwin 7ffbd2e69400 0x9 1300
SpdySession3::UpdateLocalRwin 7ffbd2e69400 0x9 1300

I see no error after the last acknowledged 0x7 stream reception nor after the 0x9 reception. Node-spdy keeps transferring, but Firefox does not seem to be answering.

At this point it's probably best for me to put a public server up so that others can try it...

Day #384