SPDY Firefox

‹prev | My Chain | next›

I am still unsure how best to test my data transfer window code in the spdy-v3 branch of node-spdy. So tonight, I take a break from SPDY version 3 goodness. Instead, I would like to mess about with Firefox's SPDY support.

I am using Firefox 12, which only supports spdy/2. If I have the spdy-v3 branch done right, then Firefox should recognize the advertised backwards compatibility with spdy/2 and interact with the spdy/2 protocol that is still in node-spdy. Actually, I do not have much hope that this will work as I think that I have hard-coded a spdy/3 thing or two into node-spdy's server implementation, but maybe I'll get lucky.

I do not.

When I load up the site in Firefox, I get:

(there should be two full images, but they are only partially loaded)

To try to track down the problem I enable Firefox logging:

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

And then run Firefox from the same command line. After accessing the site, I look at the log to find a lot of information. Firefox's text logging is a seriously exciting dump of data. Among the nuggets, I find that Firefox is, indeed, opting to use spdy/2:

1418721024[7f4d669148c0]: nsHttpConnection::EnsureNPNComplete 7f4d50d2c520 negotiated to 'spdy/2'

I also see both uncompressed requests:

1741141824[7f4d66914480]: http request [
1741141824[7f4d66914480]:   GET / HTTP/1.1
1741141824[7f4d66914480]:   Host: localhost:3000
1741141824[7f4d66914480]:   User-Agent: Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:12.0) Gecko/20100101 Firefox/12.0
1741141824[7f4d66914480]:   Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
1741141824[7f4d66914480]:   Accept-Language: en-us,en;q=0.5
1741141824[7f4d66914480]:   Accept-Encoding: gzip, deflate
1741141824[7f4d66914480]:   Connection: keep-alive
1741141824[7f4d66914480]: ]

And compressed SYN_STREAMs:

1418721024[7f4d669148c0]: SpdySession::LogIO 7f4d42924400 stream=7f4d42af0fc0 id=0x1 [Writing from Inline Buffer]
1418721024[7f4d669148c0]: 00000000: 80 02 00 01 01 00 00 CE 00 00 00 01 00 00 00 00 
1418721024[7f4d669148c0]: 00000010: 80 00 78 BB DF A2 51 B2 62 E0 60 60 CB 05 E6 C3 
1418721024[7f4d669148c0]: 00000020: FC 14 06 66 77 D7 10 06 B6 62 60 D4 E5 A6 32 B0 
1418721024[7f4d669148c0]: 00000030: 66 94 94 14 14 33 30 83 D4 30 EA 33 B0 43 B5 30 
1418721024[7f4d669148c0]: 00000040: 70 C0 4C 62 60 01 65 2E 06 3E 50 0C E4 80 98 56 
...

That is super helpful. Usually when I need to debug SPDY parsing and framing issues, I am forced to break out Wireshark, which further requires access to the server certificate. This is fantastic!

As for the problem at hand, I also find that Firefox makes the request for the images properly and that the server begins the response correctly:

...
1418721024[7f4d669148c0]: SpdySession::LogIO 7f4d42924400 stream=0 id=0x0 [Reading Control Frame]
1418721024[7f4d669148c0]: 00000000: 00 00 00 07 15 32 C2 17 18 C8 E9 97 41 32 A9 B2 
1418721024[7f4d669148c0]: 00000010: 24 B5 58 C1 CC 04 E8 09 5D 0B 13 4B 13 33 0B 7D 
1418721024[7f4d669148c0]: 00000020: 30 65 89 EE 0C 58 6A 4A 4D 67 E0 45 29 01 18 58 
1418721024[7f4d669148c0]: 00000030: C1 66 C0 1D 27 0C 2C 82 14 02 12 8B 4A 32 13 73 
1418721024[7f4d669148c0]: 00000040: 14 9C 21 66 60 71 22 00 00 00 FF FF 
1418721024[7f4d669148c0]: nsHttpTransaction::OnSocketStatus [this=454797b0 status=804b0006 progress=76]
1418721024[7f4d669148c0]: SpdySession::HandleSynReply 7f4d42924400 SYN_REPLY for 0x7 fin=0
1418721024[7f4d669148c0]: decoded response headers are:
HTTP/1.1 206 Partial Content
x-powered-by: Express
content-range: bytes 64360-849468/849469
content-type: image/jpeg
accept-ranges: bytes
X-Firefox-Spdy: 1
...

Eventually, the data stalls and the connection times out:

...
1418721024[7f4d669148c0]: poll timeout: 65535
1418721024[7f4d669148c0]:     timeout = 65535000 milliseconds
1418721024[7f4d669148c0]:     ...returned after 13287 milliseconds
...

I think I know the cause of this. That spdy/3 stuff embedded in the server code that I mentioned earlier? Yeah, I think that might be it.

So, back in node-spdy's Server class, I add a condition to handle control flow only for spdy/3:

Stream.prototype._writeData = function _writeData(fin, buffer) {
  if (this.framer.version == 3) {
    if (this._transferWindowSize > 0)
      this._transferWindowSize -= buffer.length;

    if (this._transferWindowSize < 0) {
      this._transferWindowBuffer.push([fin, buffer]);
      return;
    }
  }

  // Actually write the data here
};

And that does the trick! Now, I can load up the site in Firefox's spdy/2 browser:

And I can load up the site in Chrome's (about:flag enabled) spdy/3 browser:

That's a nice milestone for my spdy-v3 branch in node-spdy. I am also pretty darn excited about the debugging facilities that I have discovered in Firefox. Tonight was a good night.


Day #379