bufio: nil pointer dereference #53808
Comments
seankhliao
added
the
WaitingForInfo
mdlayher
changed the title
|
It looks like your program may have a data race causing memory corruption. Please try running your program with |
|
A segmentation violation means you tried to dereference a bad pointer. Unless your code uses unsafe, that is most likely caused by memory corruption, often caused by data races. |
|
I feel the need to clarify @mvdan's statement. An ordinary nil pointer dereference also causes a segmentation violation, and that of course doesn't only happen due to unsafe or data races. But as @szuecs points out, in this instance, the bad pointer has address 0x18, not 0, which would indeed point towards memory corruption of some sort. The access that panics is in and I don't see any safe way in which Edit: both @mvdan and I need to freshen up on what nil pointer dereferences can look like. 0x18 is of course the offset of the field being accessed. |
|
The cause looks to be body read after connection close which nullifies Line 1698 in 4068be5 The read then fails on attempt to write Line 908 in 4068be5 Could be reproduced via: package main
import (
"log"
"net/http"
"time"
)
func main() {
s := &http.Server{
Addr: ":8888",
Handler: http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
go func() {
time.Sleep(1000 * time.Millisecond)
r.Body.Read(make([]byte, 1))
}()
}),
}
log.Fatal(s.ListenAndServe())
} |
|
@AlexanderYastrebov thanks. I also tested with 1.18.4 same panic triggered. |
|
does it trigger with a race detector? |
yes |
|
To me that example looks like #30580, which right now doesn't really look like the reported issue |
|
The example #53808 (comment) is clearly wrong as it reuses body after leaving The subject software (Skipper) is an HTTP proxy and passes incoming request to the |
|
I can't easily reproduce the problem with skipper build with |
seankhliao
added
WaitingForInfo
|
@seankhliao what info are you looking for? |
That comment (and the one above) points to data corruption which more likely comes from your code rather than anything in the standard library (or we'd see more reports of similar problems). |
|
@seankhliao I have to disagree if the panic traces are only showing up stdlib code. It would be something else if the trigger would be part of our code in the trace. It's one of the issues you won't see if you would not run hundreds of instances with high traffic. Most people will not follow up if you have a one time occurrence like this. |
seankhliao
added
WaitingForInfo
|
Timed out in state WaitingForInfo. Closing. (I am just a bot, though. Please speak up if this is a mistake or you have the requested information.) |
|
I have no way how to reproduce it but bugs won't disappear if a bot closes them. I think it's not a healthy strategy to have bots closing bugs. The panic doesn't show code related to my project so unlikely to be a bug on our side. |
|
I'll reopen, no problem. But I don't think we have any way to move forward with diagnosing/fixing this bug without more information. Particularly, with a way to reproduce. |
mvdan
removed
the
WaitingForInfo
|
To add to what @randall77 said: if you're the only user running into a segmentation violation panic, and there are no steps to reproduce the panic, that usually means that there's a problem with the end user code, like a data race or memory corruption. You're right that bots closing issues doesn't mean the bug disappears. But leaving the issue open without more information or investigation on your part means that no progress will be made. That's why the "waiting for info" label was added, and the issue automatically closed after some time. |
|
@randall77 @mvdan I agree with you, but if we find another occurrence then it will be easier to correlate if this is open. Finding closed issues is hard because you have to filter all issues that were fixed, too. |
|
@szuecs Ok, I'm going to assign you as owner so no one has to look at this until more information arrives. |
seankhliao
added
the
NeedsInvestigation
|
Found another occurrence with Go v1.21.1 |
|
We observed this 2 times again (fleet size is 700 instances so it's really rare edge case also given 6 Months later from the last report): |
|
@neild |
|
@randall77 I also suspect that this is related to the proxy usecase where incoming request body is sent to the backend and backend response is sent to the server client. |
|
I've found a reproducer: package main
import (
"bytes"
"io"
"log"
"net/http"
"strings"
"time"
)
// Broken backend returns a response with a truncated body.
func brokenBackend() {
http.HandleFunc("/", func(w http.ResponseWriter, r *http.Request) {
conn, bfw, err := w.(http.Hijacker).Hijack()
if err != nil {
log.Fatalf("hijack failed: %v", err)
}
bfw.WriteString("HTTP/1.1 200 OK\r\n")
bfw.WriteString("Content-Length: 10\r\n\r\n")
// body truncated
bfw.Flush()
conn.Close()
})
http.ListenAndServe("localhost:8081", nil)
}
// Proxy forwards requests to the broken backend.
func proxy() {
tr := http.Transport{}
p := http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
pr, _ := http.NewRequestWithContext(r.Context(), r.Method, "http://localhost:8081", r.Body)
pr.ContentLength = r.ContentLength
resp, err := tr.RoundTrip(pr)
if err != nil {
w.WriteHeader(http.StatusBadGateway)
return
}
w.WriteHeader(resp.StatusCode)
io.Copy(w, resp.Body)
resp.Body.Close()
})
http.ListenAndServe("localhost:8080", p)
}
func main() {
log.Println("Starting proxy and backend")
go brokenBackend()
go proxy()
// wait for the servers to start
time.Sleep(1 * time.Second)
log.Println("Start sending requests")
const contentLength = 100
body := make([]byte, contentLength)
for {
req, err := http.NewRequest("PUT", "http://localhost:8080", bytes.NewReader(body))
if err != nil {
log.Fatalf("create request failed: %v", err)
}
// activate use of *expectContinueReader
req.Header.Set("Expect", "100-continue")
// without Content-Length, the proxy will panic
// at a different place inside of net/http.(*transferWriter).writeBody
req.ContentLength = contentLength
resp, err := http.DefaultClient.Do(req)
if err != nil {
if strings.Contains(err.Error(), "connection refused") {
log.Println("Done sending requests")
break
}
} else {
resp.Body.Close()
}
}
} |
|
I could not reproduce with stdlib reverse proxy func httputilProxy() {
target, _ := url.Parse("http://localhost:8081")
p := httputil.NewSingleHostReverseProxy(target)
p.ErrorLog = log.New(io.Discard, "", 0)
http.ListenAndServe("localhost:8080", p)
}and it looks like because proxy request body is closed before returning from the handler, see https://go-review.googlesource.com/c/go/+/333191 and #46866 (comment) The reproducer also does not work anymore after I added: if pr.Body != nil {
defer pr.Body.Close()
} |
Broken backend that closes connection before sending response body may trigger proxy panic if client sends `Expect: 100-continue` header, see golang/go#53808 Signed-off-by: Alexander Yastrebov <alexander.yastrebov@zalando.de>
Broken backend that closes connection before sending response body may trigger proxy panic if client sends `Expect: 100-continue` header, see golang/go#53808 Signed-off-by: Alexander Yastrebov <alexander.yastrebov@zalando.de>
OTOH from https://pkg.go.dev/net/http#Request
I.e. we have a valid reproducer #53808 (comment) that causes panic. |
Broken backend that closes connection before sending response body may trigger proxy panic if client sends `Expect: 100-continue` header, see golang/go#53808 Signed-off-by: Alexander Yastrebov <alexander.yastrebov@zalando.de>
|
Simpler reproduction case: As a general statement, writing to a response body after a server handler returns can panic. Reading from a request body when In the reverse proxy case, the body of an inbound request is being used as the body of an outbound request,
It does seem to be the case that it's safe to read from a request body after closing it, even after the server handler has returned. I believe what's happening here is a race condition where the outbound I'm not immediately sure what the right fix is. A fairly limited fix might be to say that closing an inbound request body and returning from a server handler should always be safe, no matter what operations are in progress on that body. This would, I think, fix ReverseProxy. I think this might just require a bit better synchronization between Or perhaps we should step back a bit and say that operations on request/response bodies after a handler returns should be safe: They can return errors, but they shouldn't panic. This would be a larger change, but would make it harder for misbehaving server handlers to cause crashes. (By redefining current "misbehavior" as "perfectly safe".) |
Broken backend that closes connection before sending response body may trigger proxy panic if client sends `Expect: 100-continue` header, see golang/go#53808 Signed-off-by: Alexander Yastrebov <alexander.yastrebov@zalando.de>
Broken backend that closes connection before sending response body may trigger proxy panic if client sends `Expect: 100-continue` header, see golang/go#53808 Signed-off-by: Alexander Yastrebov <alexander.yastrebov@zalando.de>
Looks like diff --git a/src/net/http/server.go b/src/net/http/server.go
index 32b4130c22..18bd091b1e 100644
--- a/src/net/http/server.go
+++ b/src/net/http/server.go
@@ -935,8 +935,7 @@ func (ecr *expectContinueReader) Read(p []byte) (n int, err error) {
}
func (ecr *expectContinueReader) Close() error {
- ecr.closed.Store(true)
- return ecr.readCloser.Close()
+ panic("expectContinueReader.Close")
}and tests still pass. This is because server stores and closes reference to the original request body only (added by https://go-review.googlesource.com/c/go/+/16572) Lines 1673 to 1675 in bb523c9 If it would close Subject Line 924 in bb523c9 which is nullified by finalFlushLine 1744 in bb523c9 called from either deferred connection c.closeLines 1894 to 1912 in bb523c9 or from Lines 1982 to 1985 in bb523c9 or after w.finishRequest() that closes original request body:Lines 2048 to 2055 in bb523c9 all of which happen at Maybe the proper fix would be to close To avoid double closing of original request body Another option is to reset if w.canWriteContinue.Load() {
w.writeContinueMu.Lock()
w.canWriteContinue.Store(false)
w.writeContinueMu.Unlock()
}like its done in couple of places already (added by https://go-review.googlesource.com/c/go/+/242598 and https://go-review.googlesource.com/c/go/+/269997). |
When client supplies "Expect: 100-continue" header, server wraps request body into expectContinueReader that writes 100 Continue status on the first body read. When handler acts as a reverse proxy and passes incoming request (or body) to the client (or transport) it may happen that request body is read after handler exists which may cause nil pointer panic on connection write if server already closed the connection. This change disables write of 100 Continue status by expectContinueReader after handler exist and before connection is closed. It also fixes racy access to w.wroteContinue. Fixes golang#53808 Updates golang#46866
When client supplies "Expect: 100-continue" header, server wraps request body into expectContinueReader that writes 100 Continue status on the first body read. When handler acts as a reverse proxy and passes incoming request (or body) to the client (or transport) it may happen that request body is read after handler exists which may cause nil pointer panic on connection write if server already closed the connection. This change disables write of 100 Continue status by expectContinueReader after handler finished and before connection is closed. It also fixes racy access to w.wroteContinue. Fixes golang#53808 Updates golang#46866
|
Change https://go.dev/cl/575196 mentions this issue: |
Implemented this in https://go.dev/cl/575196 |
When client supplies "Expect: 100-continue" header, server wraps request body into expectContinueReader that writes 100 Continue status on the first body read. When handler acts as a reverse proxy and passes incoming request (or body) to the client (or transport) it may happen that request body is read after handler exists which may cause nil pointer panic on connection write if server already closed the connection. This change disables write of 100 Continue status by expectContinueReader after handler finished and before connection is closed. It also fixes racy access to w.wroteContinue. Fixes golang#53808 Updates golang#46866
When client supplies "Expect: 100-continue" header, server wraps request body into expectContinueReader that writes 100 Continue status on the first body read. When handler acts as a reverse proxy and passes incoming request (or body) to the client (or transport) it may happen that request body is read after handler exists which may cause nil pointer panic on connection write if server already closed the connection. This change disables write of 100 Continue status by expectContinueReader after handler finished and before connection is closed. It also fixes racy access to w.wroteContinue. Fixes golang#53808 Updates golang#46866
When client supplies "Expect: 100-continue" header, server wraps request body into expectContinueReader that writes 100 Continue status on the first body read. When handler acts as a reverse proxy and passes incoming request (or body) to the client (or transport) it may happen that request body is read after handler exists which may cause nil pointer panic on connection write if server already closed the connection. This change disables write of 100 Continue status by expectContinueReader after handler finished and before connection is closed. It also fixes racy access to w.wroteContinue. Fixes golang#53808 Updates golang#46866
When client supplies "Expect: 100-continue" header, server wraps request body into expectContinueReader that writes 100 Continue status on the first body read. When handler acts as a reverse proxy and passes incoming request (or body) to the client (or transport) it may happen that request body is read after handler exists which may cause nil pointer panic on connection write if server already closed the connection. This change disables write of 100 Continue status by expectContinueReader after handler finished and before connection is closed. It also fixes racy access to w.wroteContinue. Fixes golang#53808 Updates golang#46866
When client supplies "Expect: 100-continue" header, server wraps request body into expectContinueReader that writes 100 Continue status on the first body read. When handler acts as a reverse proxy and passes incoming request (or body) to the client (or transport) it may happen that request body is read after handler exists which may cause nil pointer panic on connection write if server already closed the connection. This change disables write of 100 Continue status by expectContinueReader after handler finished and before connection is closed. It also fixes racy access to w.wroteContinue. Fixes golang#53808 Updates golang#46866
When client supplies "Expect: 100-continue" header, server wraps request body into expectContinueReader that writes 100 Continue status on the first body read. When handler acts as a reverse proxy and passes incoming request (or body) to the client (or transport) it may happen that request body is read after handler exists which may cause nil pointer panic on connection write if server already closed the connection. This change disables write of 100 Continue status by expectContinueReader after handler finished and before connection is closed. It also fixes racy access to w.wroteContinue. Fixes golang#53808 Updates golang#46866
What version of Go are you using (
go version)?Does this issue reproduce with the latest release?
I don't no it's a single occurrence in a system running about 500 instances every day 24x7.
What operating system and processor architecture are you using (
go env)?go envOutputWhat did you do?
Run the binary in a container and this was a single occurrence after months of running different versions of the binary (we regularly update it ~weekly).
What did you expect to see?
no panic withing the stdlib
What did you see instead?
A panic
The text was updated successfully, but these errors were encountered: