spdy after a single connect send data big than 65535 , last frame size is invalid

[bin tom]

I use spdy for benchmark, my test html size is 2011, when i use okhttp to call the url in 32 count,
the client halt . so I add some debug code to nginx here is the error_log

The bug is frame size in frame 2011 ,but send size small than 2011 ,so the client wait all along

2014/12/02 10:21:42 [debug] 25041#0: epoll: fd:3 ev:0001 d:00007FAC6D893298
2014/12/02 10:21:42 [debug] 25041#0: *2 spdy keepalive handler
2014/12/02 10:21:42 [debug] 25041#0: *2 reusable connection: 0
2014/12/02 10:21:42 [debug] 25041#0: *2 posix_memalign: 000000000221A230:4096 @16
2014/12/02 10:21:42 [debug] 25041#0: *2 spdy read handler
2014/12/02 10:21:42 [debug] 25041#0: *2 SSL_read: 1
2014/12/02 10:21:42 [debug] 25041#0: *2 SSL_read: 29
2014/12/02 10:21:42 [debug] 25041#0: *2 SSL_read: -1
2014/12/02 10:21:42 [debug] 25041#0: *2 SSL_get_error: 2
2014/12/02 10:21:42 [debug] 25041#0: *2 process spdy frame head:80030001 f:1 l:22
2014/12/02 10:21:42 [debug] 25041#0: *2 spdy SYN_STREAM frame sid:65 prio:0
2014/12/02 10:21:42 [debug] 25041#0: *2 posix_memalign: 000000000221B240:4096 @16
2014/12/02 10:21:42 [debug] 25041#0: *2 process spdy header block 12 of 12
2014/12/02 10:21:42 [debug] 25041#0: *2 spdy inflate out: ni:00007FAC6D85202E no:000000000221BE32 ai:0 ao:869 rc:0
2014/12/02 10:21:42 [debug] 25041#0: *2 spdy header block has 6 entries
2014/12/02 10:21:42 [debug] 25041#0: *2 posix_memalign: 00000000022347B0:4096 @16
2014/12/02 10:21:42 [debug] 25041#0: *2 http uri: "/json.html.bak"
2014/12/02 10:21:42 [debug] 25041#0: *2 http args: "32"
2014/12/02 10:21:42 [debug] 25041#0: *2 http exten: "bak"
2014/12/02 10:21:42 [debug] 25041#0: *2 spdy http request line: "GET /json.html.bak?32 HTTP/1.1"
2014/12/02 10:21:42 [debug] 25041#0: *2 spdy http header: "host: spdy.94v5.com:8443"
2014/12/02 10:21:42 [debug] 25041#0: *2 spdy http header: "accept-encoding: gzip"
2014/12/02 10:21:42 [debug] 25041#0: *2 rewrite phase: 0
2014/12/02 10:21:42 [debug] 25041#0: *2 test location: "/"
2014/12/02 10:21:42 [debug] 25041#0: *2 using configuration "/"
2014/12/02 10:21:42 [debug] 25041#0: *2 http cl:-1 max:1048576
2014/12/02 10:21:42 [debug] 25041#0: *2 rewrite phase: 2
2014/12/02 10:21:42 [debug] 25041#0: *2 post rewrite phase: 3
2014/12/02 10:21:42 [debug] 25041#0: *2 generic phase: 4
2014/12/02 10:21:42 [debug] 25041#0: *2 generic phase: 5
2014/12/02 10:21:42 [debug] 25041#0: *2 access phase: 6
2014/12/02 10:21:42 [debug] 25041#0: *2 access phase: 7
2014/12/02 10:21:42 [debug] 25041#0: *2 post access phase: 8
2014/12/02 10:21:42 [debug] 25041#0: *2 content phase: 9
2014/12/02 10:21:42 [debug] 25041#0: *2 content phase: 10
2014/12/02 10:21:42 [debug] 25041#0: *2 content phase: 11
2014/12/02 10:21:42 [debug] 25041#0: *2 http filename: "/home/song/nginx-1.7.7/html/json.html.bak"
2014/12/02 10:21:42 [debug] 25041#0: *2 add cleanup: 0000000002234BC0
2014/12/02 10:21:42 [debug] 25041#0: *2 http static fd: 4
2014/12/02 10:21:42 [debug] 25041#0: *2 spdy header filter
2014/12/02 10:21:42 [debug] 25041#0: *2 malloc: 000000000222CEF0:343
2014/12/02 10:21:42 [debug] 25041#0: *2 spdy deflate out: ni:000000000222D037 no:0000000002234EE5 ai:0 ao:52 rc:0
2014/12/02 10:21:42 [debug] 25041#0: *2 spdy:65 create SYN_REPLY frame 0000000002234F30: len:341
2014/12/02 10:21:42 [debug] 25041#0: *2 http cleanup add: 0000000002234F70
2014/12/02 10:21:42 [debug] 25041#0: *2 spdy frame out: 0000000002234F30 sid:65 prio:0 bl:1 len:341
2014/12/02 10:21:42 [debug] 25041#0: *2 malloc: 00000000022357C0:16384
2014/12/02 10:21:42 [debug] 25041#0: *2 SSL buf copy: 349
2014/12/02 10:21:42 [debug] 25041#0: *2 spdy:65 SYN_REPLY frame 0000000002234F30 was sent
2014/12/02 10:21:42 [debug] 25041#0: *2 spdy frame sent: 0000000002234F30 sid:65 bl:1 len:341
2014/12/02 10:21:42 [debug] 25041#0: *2 http output filter "/json.html.bak?32"
2014/12/02 10:21:42 [debug] 25041#0: *2 http copy filter: "/json.html.bak?32"
2014/12/02 10:21:42 [debug] 25041#0: *2 posix_memalign: 000000000228C300:4096 @16
2014/12/02 10:21:42 [debug] 25041#0: *2 read: 4, 000000000228C320, 2011, 0
2014/12/02 10:21:42 [debug] 25041#0: *2 http postpone filter "/json.html.bak?32" 0000000002235040
2014/12/02 10:21:42 [debug] 25041#0: *2 write new buf t:1 f:1 000000000228C320, pos 000000000228C320, size: 2011 file: 0, size: 2011
2014/12/02 10:21:42 [debug] 25041#0: *2 http write filter: l:1 f:0 s:2011
2014/12/02 10:21:42 [debug] 25041#0: *2 http write filter limit 0
2014/12/02 10:21:42 [debug] 25041#0: *2 spdy:65 debug 1 send_window:1184 limit:0 size:2011
2014/12/02 10:21:42 [debug] 25041#0: *2 spdy:65 debug 2 frame size:1184 chunk_size:8192 limit:1184
2014/12/02 10:21:42 [debug] 25041#0: *2 spdy:65 create DATA rest:1184
2014/12/02 10:21:42 [debug] 25041#0: *2 spdy:65 create DATA frame 0000000002234F30: len:1184 flags:0
2014/12/02 10:21:42 [debug] 25041#0: *2 spdy frame out: 0000000002234F30 sid:65 prio:0 bl:0 len:1184
2014/12/02 10:21:42 [debug] 25041#0: *2 SSL buf copy: 8
2014/12/02 10:21:42 [debug] 25041#0: *2 SSL buf copy: 1184
2014/12/02 10:21:42 [debug] 25041#0: *2 SSL to write: 1541
2014/12/02 10:21:42 [debug] 25041#0: *2 SSL_write: 1541
2014/12/02 10:21:42 [debug] 25041#0: *2 spdy:65 DATA frame 0000000002234F30 was sent
2014/12/02 10:21:42 [debug] 25041#0: *2 spdy frame sent: 0000000002234F30 sid:65 bl:0 len:1184
2014/12/02 10:21:42 [debug] 25041#0: *2 http write filter 0000000002235050
2014/12/02 10:21:42 [debug] 25041#0: *2 http copy filter: -2 "/json.html.bak?32"
2014/12/02 10:21:42 [debug] 25041#0: *2 http finalize request: -2, "/json.html.bak?32" a:1, c:1
2014/12/02 10:21:42 [debug] 25041#0: *2 spdy frame complete pos:00007FAC6D85202E end:00007FAC6D85202E
2014/12/02 10:21:42 [debug] 25041#0: *2 event timer del: 3: 1417515882593
2014/12/02 10:21:42 [debug] 25041#0: timer delta: 182

[Valentin V. Bartenev]

It's limited by the SPDY flow control mechanism. From your debug log the available window size is only 1184 bytes, so nginx cannot construct frame bigger than that.

[bin tom]

Replying to Valentin V. Bartenev:

It's limited by the SPDY flow control mechanism. From your debug log the available window size is only 1184 bytes, so nginx cannot construct frame bigger than that.

sorry nginx frame is ok

The bug is Nginx tell okhttp to set INIT_WINDOW = 16777216

2014/12/03 05:42:33 [debug] 11921#0: *27 spdy SETTINGS entry fl:0 id:7 val:16777216

okhttp send window update only when read data size big than 16777216/2 ,so nginx do not receive update send_window (send_window max is 65536)

but nginx check send_window <= 0 ,nginx stop send ,so dead lock

      synchronized (SpdyStream.this) {
        waitUntilReadable();
        checkNotClosed();
        if (readBuffer.size() == 0) return -1; // This source is exhausted.

        // Move bytes from the read buffer into the caller's buffer.
        read = readBuffer.read(sink, Math.min(byteCount, readBuffer.size()));

        // Flow control: notify the peer that we're ready for more data!
        unacknowledgedBytesRead += read;
        if (unacknowledgedBytesRead
            >= connection.peerSettings.getInitialWindowSize(DEFAULT_INITIAL_WINDOW_SIZE) / 2) {
          connection.writeWindowUpdateLater(id, unacknowledgedBytesRead);
          unacknowledgedBytesRead = 0;
        }
      }

[Valentin V. Bartenev]

Replying to bin tom <tom8888889@gmail.com>:

..
The bug is Nginx tell okhttp to set INIT_WINDOW = 16777216

2014/12/03 05:42:33 [debug] 11921#0: *27 spdy SETTINGS entry fl:0 id:7 val:16777216

okhttp send window update only when read data size big than 16777216/2 ,so nginx do not receive update send_window (send_window max is 65536)

This means that the spdy implementation in okhttp is completely broken. The send window is maintained per endpoint. Nginx is only able to set initial window size for a client, that limits how many bytes the client is able to send in POST/PUT requests from the start. It doesn't related to responses at all.