runtime error: slice bounds out of range

[peppy]

Running under some degree of load (30-40mbit) I occasionally get the following error. I believe after some period this affects the server's ability to process requests at all. It seems like it could be a go-level issue, and on reading up it may be related to keepalives. I'll try some other options, but here is the exception for the time being:

2014/05/26 14:03:20 http: panic serving 141.101.96.59:21920: runtime error: slice bounds out of range
goroutine 437 [running]:
net/http.func·009()
        /usr/lib/go/src/pkg/net/http/server.go:1093 +0xae
runtime.panic(0x657800, 0x95af4a)
        /usr/lib/go/src/pkg/runtime/panic.c:248 +0x106
github.com/cactus/go-camo/camo.(*Proxy).ServeHTTP(0xc210051400, 0x7fa83d0c9720, 0xc210623000, 0xc2105e1a90)
        /root/go-camo/build/src/github.com/cactus/go-camo/camo/proxy.go:196 +0x1b25
github.com/gorilla/mux.(*Router).ServeHTTP(0xc21000a550, 0x7fa83d0c9720, 0xc210623000, 0xc2105e1a90)
        /root/go-camo/build/src/github.com/gorilla/mux/mux.go:98 +0x217
net/http.(*ServeMux).ServeHTTP(0xc2100376c0, 0x7fa83d0c9720, 0xc210623000, 0xc2105e1a90)
        /usr/lib/go/src/pkg/net/http/server.go:1496 +0x163
net/http.serverHandler.ServeHTTP(0xc21000a1e0, 0x7fa83d0c9720, 0xc210623000, 0xc2105e1a90)
        /usr/lib/go/src/pkg/net/http/server.go:1597 +0x16e
net/http.(*conn).serve(0xc2105f7180)
        /usr/lib/go/src/pkg/net/http/server.go:1167 +0x7b7
created by net/http.(*Server).Serve
        /usr/lib/go/src/pkg/net/http/server.go:1644 +0x28b

Running with fairly basic options: go-camo --max-size=2048 --listen=:80 -k <key>

[peppy]

As an update, on latest master 48bf0ccbbe838be4b3c4df00f08cfca585b2fe61 I am still getting the above exceptions, plus in addition:

2014/05/26 15:13:43 Unsolicited response received on idle HTTP channel starting with "H"; err=<nil>
2014/05/26 15:13:43 Unsolicited response received on idle HTTP channel starting with "H"; err=<nil>
2014/05/26 15:13:44 Unsolicited response received on idle HTTP channel starting with "H"; err=<nil>

Also I'm not sure if these are related, but I get a constant stream of these kinds of errors:

2014/05/26 15:15:03 Error writing response: use of closed network connection
2014/05/26 15:15:10 Error writing response: use of closed network connection
2014/05/26 15:15:14 Error writing response: read tcp 23.19.67.82:80: use of closed network connection
2014/05/26 15:15:17 Error writing response: use of closed network connection
2014/05/26 15:15:46 Error writing response: write tcp 108.162.254.109:29924: connection reset by peer
2014/05/26 15:16:00 Error writing response: write tcp 141.101.99.137:24058: connection reset by peer
2014/05/26 15:16:07 Error writing response: read tcp 149.210.145.56:80: use of closed network connection

[dropwhile]

What go version and what os/arch are you running? (go-camo -V output has good info)

[peppy]

root@camo:~/go-camo/build/bin# ./go-camo -V
go-camo 0.4.0-18-g48bf0cc (go1.2.1,gc-amd64)

Linux camo 3.13.0-24-generic #46-Ubuntu SMP Thu Apr 10 19:11:08 UTC 2014 x86_64 x86_64 x86_64 GNU/Linux

[dropwhile]

Do you have go-camo behind a proxy (haproxy, nginx, etc) or CDN, or directly exposed?

The "use of closed network connection" errors may be related to the transport timeout code -- if a client request takes too long and triggers a timeout while copying the response body from an upstream (if the upstream read is slow or waiting for example), I could see that happening. The connection reset by peer should be harmless (handled error condition).

The unsolicited response error may be related to issue 5522 -- effectively a poorly compliant image server responding in an unexpected way. You could try the workaround in the issue noted and see if it is still relevant. I found a ML thread that said that workaround did not end up in any releases as it was due to noncompliant server. To not pass on the client accept header, comment out the accept-header line in camo/vars.go.

The panic is certainly concerning! I am not sure what is causing it.

[dropwhile]

If you are not interested in http keepalives, I could make a branch that doesn't support keepalives at all and see if it helps as well.

[dropwhile]

added a branch with the keepalive changes (disable them from go-camo to image servers), as well as the potential workaround noted in Go issue 5522. https://github.com/cactus/go-camo/tree/issue-3

[peppy]

Thanks for the detailed response.

I'm hosting this behind Cloudflare currently. Will consider adding nginx to the mix if necessary, but figured things should work okay as-is with cloudflare's caching.

Yeah, I'm really unsure about the panic. If you did make a no-keepalive branch I'd be more than happy to test it out.

[dropwhile]

Ah cool. Cloudflare should (hopefully) be sending you decent requests. I can also disable client keepalives too, but I am thinking server side (upstream) keepalives are likely more problematic given you are running behind Cloudflare.

[dropwhile]

I think I fixed the stacktrace issue with current HEAD (7d2d8454ca20e98346219b31030aa3489687cdf6).

If a response header was not at least 6 chars long, it would have caused that error.

[peppy]

Updated and testing now! Will let you know how it goes.

[peppy]

Things are looking great since updating!

root@camo:~# ./run.sh
2014/05/26 20:05:41 Enabling stats at /status
2014/05/26 20:05:41 Starting server on :80
2014/05/26 20:08:08 Error writing response: write tcp 173.245.53.93:61119: connection reset by peer
2014/05/26 20:11:31 Error writing response: write tcp 108.162.210.240:44094: connection reset by peer
2014/05/26 20:11:31 Error writing response: write tcp 108.162.212.191:51226: connection reset by peer
2014/05/26 20:11:32 Error writing response: write tcp 108.162.212.187:54586: connection reset by peer
2014/05/26 20:11:32 Error writing response: write tcp 108.162.212.187:34761: connection reset by peer
2014/05/26 20:11:32 Error writing response: write tcp 108.162.210.234:61558: connection reset by peer
2014/05/26 20:13:32 Error writing response: write tcp 141.101.98.119:45485: connection reset by peer
2014/05/26 20:16:29 Error writing response: write tcp 103.22.200.241:60954: connection reset by peer
2014/05/26 20:17:36 Unsolicited response received on idle HTTP channel starting with "H"; err=<nil>
2014/05/26 20:17:36 Unsolicited response received on idle HTTP channel starting with "H"; err=<nil>
2014/05/26 20:21:42 Error writing response: read tcp 141.101.113.193:80: use of closed network connection
2014/05/26 20:24:29 Error writing response: write tcp 141.101.93.65:42731: connection reset by peer
2014/05/26 20:24:29 Error writing response: write tcp 141.101.93.68:55598: connection reset by peer
2014/05/26 20:25:22 Error writing response: write tcp 173.245.54.119:27826: connection reset by peer
2014/05/26 20:26:09 Error writing response: read tcp 101.28.252.14:80: use of closed network connection
2014/05/26 20:27:02 Error writing response: write tcp 108.162.222.220:63537: connection reset by peer
2014/05/26 20:28:28 Error writing response: write tcp 108.162.225.244:31576: connection reset by peer
2014/05/26 20:31:03 Error writing response: write tcp 141.101.89.68:24785: connection reset by peer
2014/05/26 20:32:21 Unsolicited response received on idle HTTP channel starting with "H"; err=<nil>
2014/05/26 20:33:10 Error writing response: write tcp 173.245.49.239:32932: connection reset by peer
2014/05/26 20:33:43 Error writing response: write tcp 199.27.128.225:63111: connection reset by peer

I'll assume all the remaining errors are expected, but provided a log in case that's not the case. Thanks for the fix.