compress/gzip: panic in Writer.Close()

[WillSewell]

What version of Go are you using (go version)?

go1.7.5 darwin/amd64

What operating system and processor architecture are you using (go env)?

GOARCH="amd64"
GOBIN=""
GOEXE=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GOOS="darwin"
GOPATH="/Users/will/src/go"
GORACE=""
GOROOT="/usr/local/Cellar/go/1.7.5/libexec"
GOTOOLDIR="/usr/local/Cellar/go/1.7.5/libexec/pkg/tool/darwin_amd64"
CC="clang"
GOGCCFLAGS="-fPIC -m64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/bm/zycksyvx1h39404g4v7wk42c0000gn/T/go-build363334644=/tmp/go-build -gno-record-gcc-switches -fno-common"
CXX="clang++"
CGO_ENABLED="1"

But I was cross compiling with CGO_ENABLED=0 GOOS=linux GOARCH=amd64 go build -a -installsuffix cgo.

And ran it on

cat /etc/lsb-release
DISTRIB_ID=Ubuntu
DISTRIB_RELEASE=16.04
DISTRIB_CODENAME=xenial
DISTRIB_DESCRIPTION="Ubuntu 16.04.1 LTS"

On that machine, it is running in docker container (docker version: Docker version 1.13.0, build 49bf474) using the base image alpine:3.3.

What did you do?

We wrap an http.ResponseWriter in gzip.Writer. When the CloseNotifer of the http.ResponseWriter fires, we call Writer.Close().

The source code of this file is here.

I am aware this might not be the correct thing to do since closing the gzip.Writer will attempt to flush to a closed connection, but I wouldn't have expected such a low-level panic as the symptom.

What did you expect to see?

Either it to have no effect, or return an error.

What did you see instead?

This code will have been executed tens of thousands of times, and this panic only occurred a single time. The single time it paniced, the error was:

Jan 29 08:09:00 ip-10-10-30-29 docker[17374]: panic: runtime error: index out of range
Jan 29 08:09:00 ip-10-10-30-29 docker[17374]: goroutine 4987 [running]:
Jan 29 08:09:00 ip-10-10-30-29 docker[17374]: panic(0x8186e0, 0xc420016060)
Jan 29 08:09:00 ip-10-10-30-29 docker[17374]: #011/usr/local/Cellar/go/1.7.4_2/libexec/src/runtime/panic.go:500 +0x1a1
Jan 29 08:09:00 ip-10-10-30-29 docker[17374]: compress/flate.(*huffmanBitWriter).indexTokens(0xc420f743c0, 0xc422be4000, 0x2, 0x4001, 0xd, 0x76ba80)
Jan 29 08:09:00 ip-10-10-30-29 docker[17374]: #011/usr/local/Cellar/go/1.7.4_2/libexec/src/compress/flate/huffman_bit_writer.go:559 +0x2a8
Jan 29 08:09:00 ip-10-10-30-29 docker[17374]: compress/flate.(*huffmanBitWriter).writeBlock(0xc420f743c0, 0xc422be4000, 0x2, 0x4001, 0x0, 0xc423456841, 0x7, 0xf7bf)
Jan 29 08:09:00 ip-10-10-30-29 docker[17374]: #011/usr/local/Cellar/go/1.7.4_2/libexec/src/compress/flate/huffman_bit_writer.go:448 +0xa3
Jan 29 08:09:00 ip-10-10-30-29 docker[17374]: compress/flate.(*compressor).writeBlock(0xc4262c4000, 0xc422be4000, 0x1, 0x4001, 0x848, 0x7, 0x0)
Jan 29 08:09:00 ip-10-10-30-29 docker[17374]: #011/usr/local/Cellar/go/1.7.4_2/libexec/src/compress/flate/deflate.go:166 +0xba
Jan 29 08:09:00 ip-10-10-30-29 docker[17374]: compress/flate.(*compressor).deflate(0xc4262c4000)
Jan 29 08:09:00 ip-10-10-30-29 docker[17374]: #011/usr/local/Cellar/go/1.7.4_2/libexec/src/compress/flate/deflate.go:410 +0xb27
Jan 29 08:09:00 ip-10-10-30-29 docker[17374]: compress/flate.(*compressor).close(0xc4262c4000, 0xc4202e0dc0, 0xc42035cc98)
Jan 29 08:09:00 ip-10-10-30-29 docker[17374]: #011/usr/local/Cellar/go/1.7.4_2/libexec/src/compress/flate/deflate.go:636 +0x50
Jan 29 08:09:00 ip-10-10-30-29 docker[17374]: compress/flate.(*Writer).Close(0xc4262c4000, 0x405fb5, 0x7efea0)
Jan 29 08:09:00 ip-10-10-30-29 docker[17374]: #011/usr/local/Cellar/go/1.7.4_2/libexec/src/compress/flate/deflate.go:720 +0x2d
Jan 29 08:09:00 ip-10-10-30-29 docker[17374]: compress/gzip.(*Writer).Close(0xc4262a3810, 0xc42035cc40, 0x0)
Jan 29 08:09:00 ip-10-10-30-29 docker[17374]: #011/usr/local/Cellar/go/1.7.4_2/libexec/src/compress/gzip/gzip.go:240 +0x6c
Jan 29 08:09:00 ip-10-10-30-29 docker[17374]: github.com/pusher/feeds/vendor/github.com/pusher/httputil2.(*gzipResponseWriter).CloseNotify.func1(0xc42035cc40, 0xc4201fcf50, 0xc42035cbd0)
Jan 29 08:09:00 ip-10-10-30-29 docker[17374]: #011/Users/will/src/go/src/github.com/pusher/feeds/vendor/github.com/pusher/httputil2/gzip_middleware.go:119 +0x51
Jan 29 08:09:00 ip-10-10-30-29 docker[17374]: created by github.com/pusher/feeds/vendor/github.com/pusher/httputil2.(*gzipResponseWriter).CloseNotify
Jan 29 08:09:00 ip-10-10-30-29 docker[17374]: #011/Users/will/src/go/src/github.com/pusher/feeds/vendor/github.com/pusher/httputil2/gzip_middleware.go:121 +0xf1

This is where the panic returned from.

[WillSewell]

I have also observed a panic that is even more problematic: it can occur from a call to Writer.Flush(). I am posting it as a comment here because it seems related.

Maybe it is caused by attempting to flush to a closed connection? The reason I'm saying it's more problematic is because we do not know at the point at calling Flush whether the underlying Writer has been closed.

Here's is the panic:

Feb 01 10:14:25 ip-10-10-24-233 docker[1525]: panic: runtime error: index out of range
Feb 01 10:14:25 ip-10-10-24-233 docker[1525]: goroutine 23215 [running]:
Feb 01 10:14:25 ip-10-10-24-233 docker[1525]: panic(0x8196e0, 0xc420016060)
Feb 01 10:14:25 ip-10-10-24-233 docker[1525]:         /usr/local/Cellar/go/1.7.5/libexec/src/runtime/panic.go:500 +0x1a1
Feb 01 10:14:25 ip-10-10-24-233 docker[1525]: compress/flate.(*huffmanBitWriter).flush(0xc422294b40)
Feb 01 10:14:25 ip-10-10-24-233 docker[1525]:         /usr/local/Cellar/go/1.7.5/libexec/src/compress/flate/huffman_bit_writer.go:126 +0xec
Feb 01 10:14:25 ip-10-10-24-233 docker[1525]: compress/flate.(*compressor).syncFlush(0xc420f08000, 0x7, 0x40)
Feb 01 10:14:25 ip-10-10-24-233 docker[1525]:         /usr/local/Cellar/go/1.7.5/libexec/src/compress/flate/deflate.go:563 +0xb4
Feb 01 10:14:25 ip-10-10-24-233 docker[1525]: compress/flate.(*Writer).Flush(0xc420f08000, 0x7, 0xc4216e9600)
Feb 01 10:14:25 ip-10-10-24-233 docker[1525]:         /usr/local/Cellar/go/1.7.5/libexec/src/compress/flate/deflate.go:715 +0x2d
Feb 01 10:14:25 ip-10-10-24-233 docker[1525]: compress/gzip.(*Writer).Flush(0xc422542c60, 0x0, 0x100)
Feb 01 10:14:25 ip-10-10-24-233 docker[1525]:         /usr/local/Cellar/go/1.7.5/libexec/src/compress/gzip/gzip.go:220 +0x61
Feb 01 10:14:25 ip-10-10-24-233 docker[1525]: github.com/pusher/feeds/vendor/github.com/pusher/httputil2.(*gzipResponseWriter).Flush(0xc4202f5f90)
Feb 01 10:14:25 ip-10-10-24-233 docker[1525]:         /Users/will/src/go/src/github.com/pusher/feeds/vendor/github.com/pusher/httputil2/gzip_middleware.go:106 +0x2e
Feb 01 10:14:25 ip-10-10-24-233 docker[1525]: github.com/pusher/feeds/vendor/github.com/pusher/httputil2.(*recoverResponseWriter).Flush(0xc42022cfc0)
Feb 01 10:14:25 ip-10-10-24-233 docker[1525]:         /Users/will/src/go/src/github.com/pusher/feeds/vendor/github.com/pusher/httputil2/recovery_middleware.go:70 +0x73
Feb 01 10:14:25 ip-10-10-24-233 docker[1525]: github.com/pusher/feeds/vendor/github.com/pusher/elements-server-go.sendMessage(0x7f9205599928, 0xc42022cfc0, 0xad5a20, 0xaf82b0, 0x0, 0x0)
Feb 01 10:14:25 ip-10-10-24-233 docker[1525]:         /Users/will/src/go/src/github.com/pusher/feeds/vendor/github.com/pusher/elements-server-go/event_writer.go:337 +0xcf
Feb 01 10:14:25 ip-10-10-24-233 docker[1525]: github.com/pusher/feeds/vendor/github.com/pusher/elements-server-go.(*EventWriter).openState(0xc42028a770)
Feb 01 10:14:25 ip-10-10-24-233 docker[1525]:         /Users/will/src/go/src/github.com/pusher/feeds/vendor/github.com/pusher/elements-server-go/event_writer.go:269 +0x661
Feb 01 10:14:25 ip-10-10-24-233 docker[1525]: github.com/pusher/feeds/vendor/github.com/pusher/elements-server-go.(*EventWriter).initState(0xc42028a770)
Feb 01 10:14:25 ip-10-10-24-233 docker[1525]:         /Users/will/src/go/src/github.com/pusher/feeds/vendor/github.com/pusher/elements-server-go/event_writer.go:193 +0xaa8
Feb 01 10:14:25 ip-10-10-24-233 docker[1525]: created by github.com/pusher/feeds/vendor/github.com/pusher/elements-server-go.newEventWriter
Feb 01 10:14:25 ip-10-10-24-233 docker[1525]:         /Users/will/src/go/src/github.com/pusher/feeds/vendor/github.com/pusher/elements-server-go/event_writer.go:138 +0x305

Flush() is called for every write to a response body, so again, this code will have been executed tens of thousands of times, and I have only observed this panic a single time.

[dsnet]

Can you run your code with the race detector enabled, the failures that you are getting in compress/flate are unlikely to happen.

[dsnet]

Your logic looks racy. self.gz.Close is called in a separate goroutine and can potentially run at exactly the same time as any of the other gzip operations.

[WillSewell]

I wasn't clear whether the library was threadsafe or not. I will wrap the Close in a mutex.

I will also leave it running with the race detector on. It could be a while before I have any results.

I'm not sure the "racy" behaviour (when closing) explains the second panic (when flushing) however. This should only be executed in the same goroutine. Again, hopefully the race detected will provide a definitive answer on this.

I will keep you posted.

[WillSewell]

Ok, I managed to catch a data race with the race checker enabled. It does look like it was caused by the call to Close flushing data concurrently with data being written to the underlying Writer. I will close this issue. Thanks for your help.