microsoftarchive/http2-katana

Server hangs on 2nd or subsequent requests

akalin-chromium opened this issue · 5 comments

Now it seems that the first request succeeds, but the 2nd and subsequent one hangs. Here's what I see:

t=1375785408547 [st= 0] +SPDY_SESSION [dt=44355+] --> host = "http2katanatest.cloudapp.net:8443" --> proxy = "DIRECT" t=1375785408547 [st= 0] SPDY_SESSION_INITIALIZED --> source_dependency = 959 (SOCKET) t=1375785408547 [st= 0] SPDY_SESSION_SEND_SETTINGS --> settings = ["[id:4 flags:0 value:1000]","[id:7 flags:0 value:10485760]"] t=1375785408547 [st= 0] SPDY_STREAM_UPDATE_RECV_WINDOW --> delta = 10420224 --> window_size = 10485760 t=1375785408547 [st= 0] SPDY_SESSION_SENT_WINDOW_UPDATE_FRAME --> delta = 10420224 --> stream_id = 0 t=1375785408549 [st= 2] SPDY_SESSION_SYN_STREAM --> fin = true --> :host: http2katanatest.cloudapp.net:8443 :method: GET :path: / :scheme: https :version: HTTP/1.1 accept: text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,*/*;q=0.8 accept-encoding: gzip,deflate,sdch accept-language: en-US,en;q=0.8 cache-control: max-age=0 user-agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_8_4) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/30.0.1588.0 Safari/537.36 --> stream_id = 1 --> unidirectional = false t=1375785408599 [st= 52] SPDY_SESSION_RECV_SETTINGS --> clear_persisted = false --> host = "http2katanatest.cloudapp.net:8443" t=1375785408599 [st= 52] SPDY_SESSION_UPDATE_STREAMS_SEND_WINDOW_SIZE --> delta_window_size = 134464 t=1375785408599 [st= 52] SPDY_SESSION_RECV_SETTING --> flags = 0 --> id = 7 --> value = 200000 t=1375785408648 [st= 101] SPDY_SESSION_SYN_REPLY --> fin = false --> :status: 200 --> stream_id = 1 --> unidirectional = false t=1375785408649 [st= 102] SPDY_SESSION_RECV_DATA --> fin = false --> size = 148 --> stream_id = 1 t=1375785408649 [st= 102] SPDY_SESSION_UPDATE_RECV_WINDOW --> delta = -148 --> window_size = 10485612 t=1375785408649 [st= 102] SPDY_SESSION_RECV_DATA --> fin = true --> size = 0 --> stream_id = 1 t=1375785408650 [st= 103] SPDY_STREAM_UPDATE_RECV_WINDOW --> delta = 148 --> window_size = 10485760 t=1375785408804 [st= 257] SPDY_SESSION_SYN_STREAM --> fin = true --> :host: http2katanatest.cloudapp.net:8443 :method: GET :path: /favicon.ico :scheme: https :version: HTTP/1.1 accept: */* accept-encoding: gzip,deflate,sdch accept-language: en-US,en;q=0.8 user-agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_8_4) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/30.0.1588.0 Safari/537.36 --> stream_id = 3 --> unidirectional = false t=1375785411020 [st= 2473] SPDY_SESSION_SYN_STREAM --> fin = true --> :host: http2katanatest.cloudapp.net:8443 :method: GET :path: / :scheme: https :version: HTTP/1.1 accept: text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,*/*;q=0.8 accept-encoding: gzip,deflate,sdch accept-language: en-US,en;q=0.8 cache-control: max-age=0 user-agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_8_4) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/30.0.1588.0 Safari/537.36 --> stream_id = 5 --> unidirectional = false t=1375785448716 [st=40169] SPDY_SESSION_SEND_RST_STREAM --> description = "" --> status = 5 --> stream_id = 3 t=1375785448717 [st=40170] SPDY_SESSION_SEND_RST_STREAM --> description = "" --> status = 5 --> stream_id = 5 t=1375785452902 [st=44355]

So I load http://http2katanatest.cloudapp.net:8443, then hit 'refresh', at which point it hangs.

There was 5 sec timeout on socket, after that connection would terminate. Timeout increased to 60 sec.

I don't think that's the problem -- the connection doesn't close, it hangs. In fact, the problem still persists.

Here's a full log, so you can see where it hangs:

582: SPDY_SESSION
http2katanatest.cloudapp.net:8443 (DIRECT)
Start Time: 2013-08-07 00:42:10.567

t=1375828930567 [st=   0] +SPDY_SESSION  [dt=6635+]
                           --> host = "http2katanatest.cloudapp.net:8443"
                           --> proxy = "DIRECT"
t=1375828930567 [st=   0]    SPDY_SESSION_INITIALIZED
                             --> source_dependency = 579 (SOCKET)
t=1375828930567 [st=   0]    SPDY_SESSION_SEND_SETTINGS
                             --> settings = ["[id:4 flags:0 value:1000]","[id:7 flags:0 value:10485760]"]
t=1375828930567 [st=   0]    SPDY_STREAM_UPDATE_RECV_WINDOW
                             --> delta = 10420224
                             --> window_size = 10485760
t=1375828930568 [st=   1]    SPDY_SESSION_SENT_WINDOW_UPDATE_FRAME
                             --> delta = 10420224
                             --> stream_id = 0
t=1375828930569 [st=   2]    SPDY_SESSION_SYN_STREAM
                             --> fin = true
                             --> :host: http2katanatest.cloudapp.net:8443
                                 :method: GET
                                 :path: /
                                 :scheme: https
                                 :version: HTTP/1.1
                                 accept: text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,*/*;q=0.8
                                 accept-encoding: gzip,deflate,sdch
                                 accept-language: en-US,en;q=0.8
                                 user-agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_8_4) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/30.0.1589.0 Safari/537.36
                             --> stream_id = 1
                             --> unidirectional = false
t=1375828930635 [st=  68]    SPDY_SESSION_RECV_SETTINGS
                             --> clear_persisted = false
                             --> host = "http2katanatest.cloudapp.net:8443"
t=1375828930635 [st=  68]    SPDY_SESSION_UPDATE_STREAMS_SEND_WINDOW_SIZE
                             --> delta_window_size = 134464
t=1375828930635 [st=  68]    SPDY_SESSION_RECV_SETTING
                             --> flags = 0
                             --> id = 7
                             --> value = 200000
t=1375828930706 [st= 139]    SPDY_SESSION_SYN_REPLY
                             --> fin = false
                             --> :status: 200
                             --> stream_id = 1
                             --> unidirectional = false
t=1375828930707 [st= 140]    SPDY_SESSION_RECV_DATA
                             --> fin = false
                             --> size = 148
                             --> stream_id = 1
t=1375828930707 [st= 140]    SPDY_SESSION_UPDATE_RECV_WINDOW
                             --> delta = -148
                             --> window_size = 10485612
t=1375828930707 [st= 140]    SPDY_SESSION_RECV_DATA
                             --> fin = true
                             --> size = 0
                             --> stream_id = 1
t=1375828930707 [st= 140]    SPDY_STREAM_UPDATE_RECV_WINDOW
                             --> delta = 148
                             --> window_size = 10485760
t=1375828930860 [st= 293]    SPDY_SESSION_SYN_STREAM
                             --> fin = true
                             --> :host: http2katanatest.cloudapp.net:8443
                                 :method: GET
                                 :path: /favicon.ico
                                 :scheme: https
                                 :version: HTTP/1.1
                                 accept: */*
                                 accept-encoding: gzip,deflate,sdch
                                 accept-language: en-US,en;q=0.8
                                 user-agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_8_4) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/30.0.1589.0 Safari/537.36
                             --> stream_id = 3
                             --> unidirectional = false
t=1375828932438 [st=1871]    SPDY_SESSION_SYN_STREAM
                             --> fin = true
                             --> :host: http2katanatest.cloudapp.net:8443
                                 :method: GET
                                 :path: /
                                 :scheme: https
                                 :version: HTTP/1.1
                                 accept: text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,*/*;q=0.8
                                 accept-encoding: gzip,deflate,sdch
                                 accept-language: en-US,en;q=0.8
                                 cache-control: max-age=0
                                 user-agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_8_4) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/30.0.1589.0 Safari/537.36
                             --> stream_id = 5
                             --> unidirectional = false
t=1375828937202 [st=6635]

Reopening