shrpx with fast chunked backend and slow frontent connection

[molnarg]

I've been toying with shrpx, and I think it's great, but I've run into an issue. I have backend server with a fast HTTP connection to shrpx, and it always sends chunked data. The connection on the frontend (which is SPDY) is much slower.

The client successfully connects to the server, starts downloading data, but it halts after a while (with stream reset). Here's what I see in verbose mode:

$ ./spdylay/src/spdycat -nv -3 --window-bits=16 -H 'Host: www.origo.hu' 'http://localhost:5555/index.html'
[  0.205] NPN select next protocol: the remote server offers:
          * spdy/3
          * spdy/2
          * http/1.1
          NPN selected the protocol: spdy/3
[  0.318] recv SETTINGS frame <version=3, flags=0, length=20>
          (niv=2)
          [4(0):100]
          [7(0):32]
[  0.318] send SETTINGS frame <version=3, flags=0, length=12>
          (niv=1)
          [7(0):65536]
[  0.318] send SYN_STREAM frame <version=3, flags=1, length=228>
          (stream_id=1, assoc_stream_id=0, pri=3)
          :host: www.origo.hu
          :method: GET
          :path: /index.html
          :scheme: http
          :version: HTTP/1.1
          accept: */*
          accept-encoding: gzip, deflate
          user-agent: spdylay/0.3.8-DEV
[  0.483] recv SYN_REPLY frame <version=3, flags=0, length=247>
          (stream_id=1)
          :status: 200 OK
          :version: HTTP/1.1
          content-type: text/html
          date: Wed, 27 Feb 2013 17:04:33 GMT
          pragma: no-cache
          server: Apache
          set-cookie: axelero=SLFDJLVENJJGGENGMPNLHFOTIHLLGRQTLELJGTIRPHKBDFADCIIFHMPNPAHMKJGQHIMTCCSHRBDFADCIIFHBDFADCIIFH;path=/;domain=.origo.hu;expires=Thu, 31-Dec-2015 23:59:59 GMT
          x-ua-compatible: IE=edge,chrome=1
[  0.485] recv DATA frame (stream_id=1, flags=0, length=1448)
[  0.485] recv DATA frame (stream_id=1, flags=0, length=1067)
[  0.507] recv DATA frame (stream_id=1, flags=0, length=1448)
[  0.583] recv DATA frame (stream_id=1, flags=0, length=1448)
[  0.613] recv DATA frame (stream_id=1, flags=0, length=1448)
[  0.613] recv DATA frame (stream_id=1, flags=0, length=1448)
[  0.613] recv DATA frame (stream_id=1, flags=0, length=1448)
[  0.648] recv DATA frame (stream_id=1, flags=0, length=1448)
[  0.648] recv DATA frame (stream_id=1, flags=0, length=1448)
[  0.690] recv DATA frame (stream_id=1, flags=0, length=1448)
[  0.690] recv DATA frame (stream_id=1, flags=0, length=1448)
[  0.690] recv DATA frame (stream_id=1, flags=0, length=1448)
[  0.718] recv DATA frame (stream_id=1, flags=0, length=1448)
[  0.718] recv DATA frame (stream_id=1, flags=0, length=1448)
[  0.718] recv DATA frame (stream_id=1, flags=0, length=1448)
[  0.754] recv DATA frame (stream_id=1, flags=0, length=1448)
[  0.754] recv DATA frame (stream_id=1, flags=0, length=1448)
[  0.754] recv DATA frame (stream_id=1, flags=0, length=1448)
[  0.790] recv DATA frame (stream_id=1, flags=0, length=1448)
[  0.790] recv DATA frame (stream_id=1, flags=0, length=1448)
[  0.790] recv DATA frame (stream_id=1, flags=0, length=1448)
[  0.837] recv DATA frame (stream_id=1, flags=0, length=1448)
[  0.837] recv DATA frame (stream_id=1, flags=0, length=1448)
[  0.837] send WINDOW_UPDATE frame <version=3, flags=0, length=8>
          (stream_id=1, delta_window_size=32923)
[  0.858] recv DATA frame (stream_id=1, flags=0, length=1448)
[  0.858] recv DATA frame (stream_id=1, flags=0, length=1448)
[  0.858] recv DATA frame (stream_id=1, flags=0, length=1448)
[  0.902] recv DATA frame (stream_id=1, flags=0, length=1448)
[  0.902] recv DATA frame (stream_id=1, flags=0, length=1448)
[  0.902] recv DATA frame (stream_id=1, flags=0, length=1448)
[  0.938] recv DATA frame (stream_id=1, flags=0, length=1448)
[  0.938] recv DATA frame (stream_id=1, flags=0, length=1448)
[  0.938] recv DATA frame (stream_id=1, flags=0, length=1448)
[  0.969] recv DATA frame (stream_id=1, flags=0, length=1448)
[  0.969] recv DATA frame (stream_id=1, flags=0, length=1448)
[  1.011] recv DATA frame (stream_id=1, flags=0, length=1448)
[  1.011] recv DATA frame (stream_id=1, flags=0, length=1448)
[  1.011] recv DATA frame (stream_id=1, flags=0, length=1448)
[  1.045] recv DATA frame (stream_id=1, flags=0, length=1448)
[  1.045] recv DATA frame (stream_id=1, flags=0, length=1448)
[  1.045] recv DATA frame (stream_id=1, flags=0, length=1448)
[  1.080] recv DATA frame (stream_id=1, flags=0, length=1448)
[  1.080] recv DATA frame (stream_id=1, flags=0, length=1448)
[  1.080] recv DATA frame (stream_id=1, flags=0, length=1448)
[  1.113] recv DATA frame (stream_id=1, flags=0, length=1448)
[  1.113] recv DATA frame (stream_id=1, flags=0, length=1448)
[  1.113] recv DATA frame (stream_id=1, flags=0, length=757)
[  1.113] recv RST_STREAM frame <version=3, flags=0, length=8>
          (stream_id=1, status_code=6)
[  1.114] send GOAWAY frame <version=3, flags=0, length=8>
          (last_good_stream_id=0)

The log on the server:

$ ./spdylay/src/shrpx --spdy-proxy --no-via --log-level=INFO -b 127.0.0.1,3333 -f 0.0.0.0,5555 --private-key-passwd-file=../keys/www.spdy.hu.key.password --spdy-max-concurrent-streams=100 ../keys/www.spdy.hu.key ../keys/www.spdy.hu.crt

[INFO] Resolving backend address
       (shrpx.cc:904)
[INFO] Address resolution for 127.0.0.1 succeeded: 127.0.0.1
       (shrpx.cc:105)
[INFO] Unable to get IPv6 address for 0.0.0.0: Address family for hostname not supported
       (shrpx.cc:148)
[INFO] Listening on 0.0.0.0, port 5555
       (shrpx.cc:186)
[INFO] Entering event loop
       (shrpx.cc:281)
[INFO] [LISTEN:0x2589320] Accepted connection. fd=7
       (shrpx_listen_handler.cc:97)
[INFO] [CLIENT_HANDLER:0x2587f40] SSL/TLS handleshake completed
       (shrpx_client_handler.cc:103)
[INFO] [CLIENT_HANDLER:0x2587f40] The negotiated next protocol: spdy/3
       (shrpx_client_handler.cc:205)
[INFO] [UPSTREAM:0x259fa20] Received upstream SYN_STREAM stream_id=1
       (shrpx_spdy_upstream.cc:147)
[INFO] [UPSTREAM:0x259fa20] HTTP request headers. stream_id=1
:host: www.origo.hu
:method: GET
:path: /index.html
:scheme: http
:version: HTTP/1.1
accept: */*
accept-encoding: gzip, deflate
user-agent: spdylay/0.3.8-DEV
       (shrpx_spdy_upstream.cc:201)
[INFO] [CLIENT_HANDLER:0x2587f40] Downstream connection pool is empty. Create new one
       (shrpx_client_handler.cc:272)
[INFO] [DCONN:0x259ec50] Attaching to DOWNSTREAM:0x25a0270
       (shrpx_http_downstream_connection.cc:70)
[INFO] [DCONN:0x259ec50] Connecting to downstream server
       (shrpx_http_downstream_connection.cc:89)
[INFO] [DCONN:0x259ec50] HTTP request headers. stream_id=1
Accept: */*
Accept-Encoding: gzip, deflate
User-Agent: spdylay/0.3.8-DEV
Host: www.origo.hu
X-Forwarded-Proto: http
       (shrpx_http_downstream_connection.cc:202)
[INFO] [DCONN:0x259ec50] Connection established. stream_id=1
       (shrpx_spdy_upstream.cc:514)
[INFO] [DOWNSTREAM:0x25a0270] HTTP response header completed
       (shrpx_spdy_upstream.cc:769)
[INFO] [UPSTREAM:0x259fa20] HTTP response headers. stream_id=1
:status: 200 OK
:version: HTTP/1.1
server: Apache
set-cookie: axelero=SLFDJLVENJJGGENGMPNLHFOTIHLLGRQTLELJGTIRPHKBDFADCIIFHMPNPAHMKJGQHIMTCCSHRBDFADCIIFHBDFADCIIFH;path=/;domain=.origo.hu;expires=Thu, 31-Dec-2015 23:59:59 GMT
content-type: text/html
pragma: no-cache
x-ua-compatible: IE=edge,chrome=1
date: Wed, 27 Feb 2013 17:06:29 GMT
       (shrpx_spdy_upstream.cc:810)
[INFO] [DOWNSTREAM:0x25a0270] HTTP response completed
       (shrpx_spdy_upstream.cc:860)
[INFO] [DCONN:0x259ec50] EOF. stream_id=1
       (shrpx_spdy_upstream.cc:526)
[INFO] [UPSTREAM:0x259fa20] RST_STREAM stream_id=1
       (shrpx_spdy_upstream.cc:625)
[INFO] [UPSTREAM:0x259fa20] Stream stream_id=1 is being closed
       (shrpx_spdy_upstream.cc:99)
[INFO] [DOWNSTREAM:0x25a0270] Deleting
       (shrpx_downstream.cc:67)
[INFO] [DOWNSTREAM:0x25a0270] Deleted
       (shrpx_downstream.cc:77)
[INFO] [UPSTREAM:0x259fa20] No more read/write for this SPDY session
       (shrpx_spdy_upstream.cc:393)
[INFO] [CLIENT_HANDLER:0x2587f40] Deleting
       (shrpx_client_handler.cc:147)
[INFO] [CLIENT_HANDLER:0x2587f40] Deleted
       (shrpx_client_handler.cc:165)

The successfully downloaded data is exactly 65536 bytes which is strange. I think it has to something with buffering... If I change window size on the client, the downloaded size changes, but never reaches the full file size, which is 89460 (even when it is set to 30).

When the backend link is slower, say I change the delay from 10ms to 50ms (it is simulated on localhost) then the problem goes away. When my backend server sends the whole content in one big chunk, the problem goes away again.

I do have a pcap trace as well, I uploaded it here: https://docs.google.com/file/d/0Bzj2UbMqUIfrRGdXZVZLRjFUdmc/edit?usp=sharing

[tatsuhiro-t]

I fixed this issue in master repo. Please pull the latest changes and if it works, please close this issue.

[molnarg]

Thanks, it seems to work! Btw, what was the problem?

[tatsuhiro-t]

The problem is that whenever backend connection got eof from backend server, frontend spdy connection issues rst_stream. It is valid for http1.1 to indicate the end of response body by eof. The fix is if response seems complete, don't issue rst_stream.

The weird 64k size is caused by flow control as you guessed.

[molnarg]

Thx for the explanation :)