Unsolicited response received on idle HTTP channel…

[davidmz]

go1.8 windows/amd64

What did you do?

I run this simple program:

package main

import (
	"fmt"
	"net/http"
)

func main() {
	resp, err := http.Head("http://t.co/2LhlOo2EtX")
	if err != nil {
		fmt.Println(err)
		return
	}
	resp.Body.Close()
	fmt.Println(resp.Request.URL.String())
}

What did you expect to see?

A single line with unshorten t.co URL:

https://golang.org/dl/

What did you see instead?

Some log message before expected output:

2017/04/08 16:39:00 Unsolicited response received on idle HTTP channel starting with "0\r\n\r\n"; err=<nil>
https://golang.org/dl/

[davidmz]

This message doesnt appear when I use https:// (https://t.co/2LhlOo2EtX) instead http:// or when I use http.Get instead of http.Head.

[bradfitz]

Their server is indeed sending that "0\r\n" in response to a HEAD request. That's bogus. See https://www.w3.org/Protocols/rfc2616/rfc2616-sec9.html#sec9.4

The "0\r\n" they're sending is part of the chunked transport encoding of the message body. It should not be present in a HEAD response.

$ telnet t.co 80
Trying 199.59.150.44...
Connected to t.co.
Escape character is '^]'.
HEAD /2LhlOo2EtX HTTP/1.1 
Host: t.co

HTTP/1.1 301 Moved Permanently
cache-control: private,max-age=300
date: Sat, 08 Apr 2017 16:29:34 GMT
expires: Sat, 08 Apr 2017 16:34:34 GMT
location: http://golang.org/dl
server: tsa_a
set-cookie: muc=6cf21681-df6e-4d16-8cf2-831f27f3b3ec; Expires=Thu, 21 Mar 2019 16:29:34 UTC; Domain=t.co
transfer-encoding: chunked
x-connection-hash: 45b6fb66d3af7254212cd53c10fdeead
x-response-time: 11

0

^]q

So, Go seems to be doing the correct thing here.

I note their server also returns bogus stuff over https (using openssl s_client -connect and typing the same thing).

If it worked for you sometimes, maybe their caching is busted and when the response falls out of their cache, then HEAD works, but if a GET happened to them recently, they reply with that response to HEAD responses? Just guessing how they have this bug. But it seems their server is busted.

[davidmz]

I agree that this is a bug of the remote server. But I would then expect to get err != nil as a result of http.Head call. Instead, I got a normal response and an unexpected debug output, and there is nothing about it in the documentation. What if I use another logger in my program? What if my program should not write anything in stderr? There is no way to configure this, we always get a debug output in stderr.

Therefore, it seems to me that the behavior of Go net/http in this case is incorrect. If this is an error, it must be in err. Now this message can only be seen with the eyes, but can not be handled in the program.

[bradfitz]

But I would then expect to get err != nil as a result of http.Head call

Because everything is fine for the Head call. The server's response is exactly what Head needs to return.

The problem is what happens in-between two requests on the same connection. Go keeps that TCP connection open for your next requests to that server, but after your Head and before you do anything else, then it sees that "0\r\n", not associated with any call of yours, so there's nobody to return an error too.

You can change the log output using https://golang.org/pkg/log/#SetOutput if you don't use the standard library logger at all.