Unsolicited response - http.Head

[Ben]

"Unsolicited response received on idle HTTP channel starting with"

Source: https://gist.github.com/c2817d4aa05dc0a1c1f4
Problem: http://cl.ly/052G1a2a3M0B1m160p3t

When running the code to check a large number of domains for their
HTTP status, a following stream of "Unsolicited response" messages
follow shortly after.

It appears as if the http.Head connection is being held open until the
web server drops it.

Is this the expected behavior?

[Brad Fitzpatrick]

Are you on Windows?

What webserver runs the URLs that you're fetching?

[Benjamin Phelps]

The code is running on Linux (debian i386), and OS X (lion 10.7.2).

The servers are all different for the URLs im fetching.

[Brad Fitzpatrick]

Hm. Which version of Go? (6g -V)

[Benjamin Phelps]

8g version release.r60.3 9516 - Linux
6g version release.r60.1 9781 - OS X

On Nov 10, 11:01 am, Brad Fitzpatrick <bradf...@google.com> wrote:
> Hm. Which version of Go? (6g -V)
>

[Josef]

I see this also with the latest weekly (8g).

Think it's related to the reusing of connections inside transport.go,
but as I recall, it was all about waiting a little bit before handling
the data.

[Daniel Theophanes]

I'm using an http rev-proxy on Windows, also getting this message.  I haven't looked into it yet, but it's happening at tip.  Doesn't appear to hinder anything for me.

[Benjamin Phelps]

Yeah, it isn't causing any problems (for me anyways, im not sure about
the left open connections to the server).

Its just a lot of logging when checking a lot of domains (10k+).

[Brad Fitzpatrick]

I'll look into it.

[Josef Johansson]

I'll will most likely see what I can find also, it seems as the
connections isn't closing nicely.

The problem arises because the number of expected responses is zero,
so the server has not sent a request yet.

So the http.readLoop() receives a packet on a channel, where it tries
to read, but in my case, the ServeHTTP in reverseproxy.go and
RoundTrip()/roundTrip in transport.go, hasn't sent the request yet.

It feels like it appears when a client disconnects, and the connection
to the reversproxy is closed, but the connection from the reverseproxy
to backend is still up. But that's just a thought.

/Josef

[DisposaBoy]

FWIW I've only ever seen these types of errors when I attempt to make a large number of requests to a remote server in a very short space of time. From that log I can see several errors from the same ip so that might be something else to look at.

[DisposaBoy]

More info: increasing GOMAXPROCS to >= the number of worker goroutines seems to reduce the problems to (near) zero so it might, at least in my test case  it looks more like legitimate errors from possibly idle requests not being read fast enough.

env:

testing hundreds of unique requests to the same server (by url so might be load balanced) over 128 goroutines.

GOMAXPROCS 1, 8 yields a lot of failures on every run while GOMAXPROCS 128,256 yielded 1 failure in about 4 runs

the test case was done against real remote servers through a NAT via VPN connection using https

the remote is amongst the busiest server on the web but shall remain unidentified

[Josef Johansson]

I can verify this. From a number of errors showing, there's nothing now.

[Benjamin Phelps]

I'm making a lot of request, but only ever a single request to each
server.

When testing with a database containing 10k hosts to check, it
executes using 50 goroutines in just under 25 seconds (~200 requests
per second, most to unique IP addresses).

[Benjamin Phelps]

Just tested it with GOMAXPROCS and couldn't see any change in the
number of errors.

[Josef Johansson]

Regarding GOMAXPROCS, further tests showed that this was not the case
for me either.

If I would hammer the rproxy with connections from the same IP, and at
the same time run "watch -n 0 'ss | grep https'",  I see that
connections to the backend is left behind, and new ones are created.
So it seems that pconn.Close(), which in affect is called when the
number of idlepconns has been reached, is not terminating the backend
connection.
If I would take it easy, the keep-alive is working properly.

[Josef]

My browser fired up connections with keep-alive to my rproxy, but only
one connection was kept to the backend.
So I changed MaxKeepAlivePerHost to 10, and it was able to have more
connections.

When they timed out I received "Unsolicited response", due to
connection reset by peer.
We shouldn't warn for this, it should fall under
LocalSideCloseConnection, if I'm getting this correctly.

I did a small timer, that just put ints on a channel, and the readLoop
ate them. But I think you need to have the timeout much higher, or
rather, one on pconn, and one on the client connection.
What is holding the keep-alive connections to the client now?

[Josef Johansson]

So when I took a look at what error I received inside the readLoop, it
was a *net.OpError, so I simply ignored it. Seems to work at least ;)

--- a/src/pkg/net/http/transport.go Sat Nov 19 15:17:40 2011 +0900
+++ b/src/pkg/net/http/transport.go Sat Nov 19 23:46:36 2011 +0100
@@ -507,6 +507,9 @@
if err == io.EOF {
return true
}
+ if e,ok := err.(*net.OpError); ok && e.Op == "read" {
+ return true
+ }
if remoteSideClosedFunc != nil {
return remoteSideClosedFunc(err)

[Josef Johansson]

Btw,

I think this was solved in an other way in some weekly before
December. So the latest should not show this behavior.