Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

compress/gzip: panic in Writer.Close() #18883

Closed
WillSewell opened this issue Feb 1, 2017 · 5 comments
Closed

compress/gzip: panic in Writer.Close() #18883

WillSewell opened this issue Feb 1, 2017 · 5 comments
Labels
FrozenDueToAge WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided.

Comments

@WillSewell
Copy link

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
Copy link
Author

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
Copy link
Member

dsnet commented Feb 1, 2017 •
edited

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

@ALTree ALTree changed the title panic in compress/gzip Writer.Close() compress/gzip: panic in Writer.Close() Feb 1, 2017
@dsnet
Copy link
Member

dsnet commented Feb 1, 2017

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.

@dsnet dsnet added the WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided. label Feb 1, 2017
@WillSewell
Copy link
Author

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
Copy link
Author

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.

@hashbender hashbender mentioned this issue Jan 8, 2018
Open
@golang golang locked and limited conversation to collaborators Feb 3, 2018
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
FrozenDueToAge WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided.
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@WillSewell @dsnet @gopherbot