net/http: check that http2 logs no more than http1

[karmeye]

Why are these logged by default?

...
2016/01/12 18:47:58 http2: server closing client connection; error reading frame from client 54.213.93.184:35476: read tcp 172.31.25.225:8000->54.213.93.184:35476: i/o timeout
2016/01/12 18:47:58 http2: server closing client connection; error reading frame from client 54.213.93.184:35477: read tcp 172.31.25.225:8000->54.213.93.184:35477: i/o timeout
2016/01/12 18:47:58 http2: server closing client connection; error reading frame from client 54.213.93.184:35478: read tcp 172.31.25.225:8000->54.213.93.184:35478: i/o timeout
2016/01/12 18:47:58 http2: server closing client connection; error reading frame from client 54.213.93.184:35480: read tcp 172.31.25.225:8000->54.213.93.184:35480: i/o timeout
2016/01/12 18:47:58 http2: server closing client connection; error reading frame from client 54.213.93.184:35481: read tcp 172.31.25.225:8000->54.213.93.184:35481: i/o timeout
...

If I understand it correctly, it's not an error; it's just that the client wants to keep a connection open for a longer time than the server (the ReadDeadline times out).

[bradfitz]

How are you starting your http server? Do you have explicit configuration, or the default?

[karmeye]

Explicit. I am setting the timeouts.

func NewServer(addr string, handler http.Handler) *Server {
    s := &Server{
        Server: http.Server{
            Addr: addr,
            Handler: &serverHandler{
                Handler: handler,
            },
            MaxHeaderBytes: 4096,

            // Maximum duration before timing out read of the request
            ReadTimeout: 3 * 60 * time.Second, //60e9,

            // Maximum duration before timing out write of the response
            WriteTimeout: 3 * 60 * time.Second, //60e9,
        },
    }
    s.ConnState = func(conn net.Conn, state http.ConnState) {
        switch state {

        // StateNew represents a new connection that is expected to
        // send a request immediately. Connections begin at this
        // state and then transition to either StateActive or
        // StateClosed
        case http.StateNew:

            // StateActive represents a connection that has read 1 or more
            // bytes of a request. The Server.ConnState hook for
            // StateActive fires before the request has entered a handler
            // and doesn't fire again until the request has been
            // handled. After the request is handled, the state
            // transitions to StateClosed, StateHijacked, or StateIdle.
        case http.StateActive:

            conn.SetReadDeadline(time.Now().Add(s.ReadTimeout))
            conn.SetWriteDeadline(time.Now().Add(s.WriteTimeout))

            // StateIdle represents a connection that has finished
            // handling a request and is in the keep-alive state, waiting
            // for a new request. Connections transition from StateIdle
            // to either StateActive or StateClosed.
        case http.StateIdle:

            // StateHijacked represents a hijacked connection.
            // This is a terminal state. It does not transition to StateClosed.
            // 
            // StateClosed represents a closed connection.
            // This is a terminal state. Hijacked connections do not
            // transition to StateClosed.
        case http.StateHijacked, http.StateClosed:

        }
    }
    return s
}

[bradfitz]

I've clarified the docs for ConnState StateActive in https://go-review.googlesource.com/18575:

        // For HTTP/2, StateActive fires on the transition from zero
        // to one active request, and only transitions away once all
        // active requests are complete. That means that ConnState
        // can not be used to do per-request work; ConnState only notes
        // the overall state of the connection.
        StateActive

ConnState is mostly used for graceful shutdowns of servers. If you want to adjust read and write deadlines per-request, you'll also need to install a http.Handler wrapper which does that (cooperating with the ConnState hook to map between the net.Conn and the http.Request.RemoteAddr)

[gopherbot]

CL https://golang.org/cl/18575 mentions this issue.

[bradfitz]

I'll audit the http2 logging paths and make sure they're not any more verbose than http1 for Go 1.6.

[gopherbot]

CL https://golang.org/cl/18932 mentions this issue.

[gopherbot]

CL https://golang.org/cl/18934 mentions this issue.