mirror of
https://github.com/golang/go
synced 2024-09-24 11:10:12 -06:00
net/http: unflake TestTimeoutHandlerSuperfluousLogs
Uses 2 channels to synchronize that test, because relying on sleeps creates flaky behavior, thus: a) 1 buffered channel to send back the last spurious line without having to reason about "happens before" behavior a) 1 buffered channel at the end of the handler; it'll be controlled by whether we expect to timeout or not, but will always be closed when the test ends Fixes #35051 Change-Id: Iff735aa8d1ed9de8d92b792374ec161cc0a72798 Reviewed-on: https://go-review.googlesource.com/c/go/+/208477 Run-TryBot: Emmanuel Odeke <emm.odeke@gmail.com> TryBot-Result: Gobot Gobot <gobot@golang.org> Reviewed-by: Bryan C. Mills <bcmills@google.com>
This commit is contained in:
parent
33d20760a2
commit
bff4ebb7aa
@ -6306,6 +6306,10 @@ func testContentEncodingNoSniffing(t *testing.T, h2 bool) {
|
|||||||
// Issue 30803: ensure that TimeoutHandler logs spurious
|
// Issue 30803: ensure that TimeoutHandler logs spurious
|
||||||
// WriteHeader calls, for consistency with other Handlers.
|
// WriteHeader calls, for consistency with other Handlers.
|
||||||
func TestTimeoutHandlerSuperfluousLogs(t *testing.T) {
|
func TestTimeoutHandlerSuperfluousLogs(t *testing.T) {
|
||||||
|
if testing.Short() {
|
||||||
|
t.Skip("skipping in short mode")
|
||||||
|
}
|
||||||
|
|
||||||
setParallel(t)
|
setParallel(t)
|
||||||
defer afterTest(t)
|
defer afterTest(t)
|
||||||
|
|
||||||
@ -6314,29 +6318,30 @@ func TestTimeoutHandlerSuperfluousLogs(t *testing.T) {
|
|||||||
testFuncName := runtime.FuncForPC(pc).Name()
|
testFuncName := runtime.FuncForPC(pc).Name()
|
||||||
|
|
||||||
timeoutMsg := "timed out here!"
|
timeoutMsg := "timed out here!"
|
||||||
maxTimeout := 200 * time.Millisecond
|
|
||||||
|
|
||||||
tests := []struct {
|
tests := []struct {
|
||||||
name string
|
name string
|
||||||
sleepTime time.Duration
|
mustTimeout bool
|
||||||
wantResp string
|
wantResp string
|
||||||
}{
|
}{
|
||||||
{
|
{
|
||||||
name: "return before timeout",
|
name: "return before timeout",
|
||||||
sleepTime: 0,
|
wantResp: "HTTP/1.1 404 Not Found\r\nContent-Length: 0\r\n\r\n",
|
||||||
wantResp: "HTTP/1.1 404 Not Found\r\nContent-Length: 0\r\n\r\n",
|
|
||||||
},
|
},
|
||||||
{
|
{
|
||||||
name: "return after timeout",
|
name: "return after timeout",
|
||||||
sleepTime: maxTimeout * 2,
|
mustTimeout: true,
|
||||||
wantResp: fmt.Sprintf("HTTP/1.1 503 Service Unavailable\r\nContent-Length: %d\r\n\r\n%s",
|
wantResp: fmt.Sprintf("HTTP/1.1 503 Service Unavailable\r\nContent-Length: %d\r\n\r\n%s",
|
||||||
len(timeoutMsg), timeoutMsg),
|
len(timeoutMsg), timeoutMsg),
|
||||||
},
|
},
|
||||||
}
|
}
|
||||||
|
|
||||||
for _, tt := range tests {
|
for _, tt := range tests {
|
||||||
|
tt := tt
|
||||||
t.Run(tt.name, func(t *testing.T) {
|
t.Run(tt.name, func(t *testing.T) {
|
||||||
var lastSpuriousLine int32
|
exitHandler := make(chan bool, 1)
|
||||||
|
defer close(exitHandler)
|
||||||
|
lastLine := make(chan int, 1)
|
||||||
|
|
||||||
sh := HandlerFunc(func(w ResponseWriter, r *Request) {
|
sh := HandlerFunc(func(w ResponseWriter, r *Request) {
|
||||||
w.WriteHeader(404)
|
w.WriteHeader(404)
|
||||||
@ -6344,14 +6349,23 @@ func TestTimeoutHandlerSuperfluousLogs(t *testing.T) {
|
|||||||
w.WriteHeader(404)
|
w.WriteHeader(404)
|
||||||
w.WriteHeader(404)
|
w.WriteHeader(404)
|
||||||
_, _, line, _ := runtime.Caller(0)
|
_, _, line, _ := runtime.Caller(0)
|
||||||
atomic.StoreInt32(&lastSpuriousLine, int32(line))
|
lastLine <- line
|
||||||
|
<-exitHandler
|
||||||
<-time.After(tt.sleepTime)
|
|
||||||
})
|
})
|
||||||
|
|
||||||
|
if !tt.mustTimeout {
|
||||||
|
exitHandler <- true
|
||||||
|
}
|
||||||
|
|
||||||
logBuf := new(bytes.Buffer)
|
logBuf := new(bytes.Buffer)
|
||||||
srvLog := log.New(logBuf, "", 0)
|
srvLog := log.New(logBuf, "", 0)
|
||||||
th := TimeoutHandler(sh, maxTimeout, timeoutMsg)
|
// When expecting to timeout, we'll keep the duration short.
|
||||||
|
dur := 20 * time.Millisecond
|
||||||
|
if !tt.mustTimeout {
|
||||||
|
// Otherwise, make it arbitrarily long to reduce the risk of flakes.
|
||||||
|
dur = 10 * time.Second
|
||||||
|
}
|
||||||
|
th := TimeoutHandler(sh, dur, timeoutMsg)
|
||||||
cst := newClientServerTest(t, h1Mode /* the test is protocol-agnostic */, th, optWithServerLog(srvLog))
|
cst := newClientServerTest(t, h1Mode /* the test is protocol-agnostic */, th, optWithServerLog(srvLog))
|
||||||
defer cst.close()
|
defer cst.close()
|
||||||
|
|
||||||
@ -6379,10 +6393,12 @@ func TestTimeoutHandlerSuperfluousLogs(t *testing.T) {
|
|||||||
t.Fatalf("Server logs count mismatch\ngot %d, want %d\n\nGot\n%s\n", g, w, blob)
|
t.Fatalf("Server logs count mismatch\ngot %d, want %d\n\nGot\n%s\n", g, w, blob)
|
||||||
}
|
}
|
||||||
|
|
||||||
|
lastSpuriousLine := <-lastLine
|
||||||
|
firstSpuriousLine := lastSpuriousLine - 3
|
||||||
// Now ensure that the regexes match exactly.
|
// Now ensure that the regexes match exactly.
|
||||||
// "http: superfluous response.WriteHeader call from <fn>.func\d.\d (<curFile>:lastSpuriousLine-[1, 3]"
|
// "http: superfluous response.WriteHeader call from <fn>.func\d.\d (<curFile>:lastSpuriousLine-[1, 3]"
|
||||||
for i, logEntry := range logEntries {
|
for i, logEntry := range logEntries {
|
||||||
wantLine := atomic.LoadInt32(&lastSpuriousLine) - 3 + int32(i)
|
wantLine := firstSpuriousLine + i
|
||||||
pat := fmt.Sprintf("^http: superfluous response.WriteHeader call from %s.func\\d+.\\d+ \\(%s:%d\\)$",
|
pat := fmt.Sprintf("^http: superfluous response.WriteHeader call from %s.func\\d+.\\d+ \\(%s:%d\\)$",
|
||||||
testFuncName, curFileBaseName, wantLine)
|
testFuncName, curFileBaseName, wantLine)
|
||||||
re := regexp.MustCompile(pat)
|
re := regexp.MustCompile(pat)
|
||||||
|
Loading…
Reference in New Issue
Block a user