net/http: TestServerSetKeepAlivesEnabledClosesConns failures #55195

gopherbot · 2022-09-20T04:39:36Z

#!watchflakes
post <- pkg == "net/http" && test == "TestServerSetKeepAlivesEnabledClosesConns"

Bug automatically created to track these flakes.

— watchflakes

The text was updated successfully, but these errors were encountered:

gopherbot · 2022-09-20T04:39:37Z

Found new matching flaky dashboard failures for:

#!watchflakes
post <- pkg == "net/http" && test == "TestServerSetKeepAlivesEnabledClosesConns"

2022-08-08 16:37 aix-ppc64 go@52d0667e net/http.TestServerSetKeepAlivesEnabledClosesConns (log)

--- FAIL: TestServerSetKeepAlivesEnabledClosesConns (2.04s)
    serve_test.go:5582: idle count after SetKeepAlivesEnabled called = 1; want 0

2022-08-12 17:25 aix-ppc64 go@ebbf2b44 net/http.TestServerSetKeepAlivesEnabledClosesConns (log)

--- FAIL: TestServerSetKeepAlivesEnabledClosesConns (2.04s)
    serve_test.go:5583: idle count after SetKeepAlivesEnabled called = 1; want 0

— watchflakes

rsc · 2022-09-20T04:42:43Z

Stopped.

gopherbot · 2022-12-17T02:18:42Z

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "net/http" && test == "TestServerSetKeepAlivesEnabledClosesConns"

2022-12-09 10:49 freebsd-arm-paulzhol go@e76c87b1 net/http.TestServerSetKeepAlivesEnabledClosesConns (log)

--- FAIL: TestServerSetKeepAlivesEnabledClosesConns (0.00s)
    --- FAIL: TestServerSetKeepAlivesEnabledClosesConns/h1 (0.15s)
        serve_test.go:5554: expected first two requests on same connection

— watchflakes

gopherbot · 2023-01-04T21:16:58Z

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "net/http" && test == "TestServerSetKeepAlivesEnabledClosesConns"

2022-12-06 18:32 freebsd-arm-paulzhol go@dfd13ce5 net/http.TestServerSetKeepAlivesEnabledClosesConns (log)

--- FAIL: TestServerSetKeepAlivesEnabledClosesConns (0.00s)
    --- FAIL: TestServerSetKeepAlivesEnabledClosesConns/h1 (0.12s)
        serve_test.go:5564: idle count for "127.0.0.1:59121" after 2 gets = 0, want 1
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false

— watchflakes

gopherbot · 2023-01-25T16:37:22Z

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "net/http" && test == "TestServerSetKeepAlivesEnabledClosesConns"

2023-01-23 10:02 darwin-amd64-13 go@e2fe3536 net/http.TestServerSetKeepAlivesEnabledClosesConns (log)

--- FAIL: TestServerSetKeepAlivesEnabledClosesConns (0.00s)
    --- FAIL: TestServerSetKeepAlivesEnabledClosesConns/h1 (0.26s)
        serve_test.go:5564: idle count for "127.0.0.1:50370" after 2 gets = 0, want 1

2023-01-23 10:02 freebsd-arm-paulzhol go@e2fe3536 net/http.TestServerSetKeepAlivesEnabledClosesConns (log)

--- FAIL: TestServerSetKeepAlivesEnabledClosesConns (0.00s)
    --- FAIL: TestServerSetKeepAlivesEnabledClosesConns/h1 (0.08s)
        serve_test.go:5564: idle count for "127.0.0.1:48451" after 2 gets = 0, want 1

— watchflakes

gopherbot · 2023-02-02T19:57:02Z

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "net/http" && test == "TestServerSetKeepAlivesEnabledClosesConns"

2023-01-27 00:42 darwin-amd64-nocgo go@5ad799ef net/http.TestServerSetKeepAlivesEnabledClosesConns (log)

--- FAIL: TestServerSetKeepAlivesEnabledClosesConns (0.00s)
    --- FAIL: TestServerSetKeepAlivesEnabledClosesConns/h1 (0.13s)
        serve_test.go:5554: expected first two requests on same connection

2023-01-27 14:33 darwin-amd64-11_0 go@21b4e014 net/http.TestServerSetKeepAlivesEnabledClosesConns (log)

--- FAIL: TestServerSetKeepAlivesEnabledClosesConns (0.00s)
    --- FAIL: TestServerSetKeepAlivesEnabledClosesConns/h1 (0.19s)
        serve_test.go:5554: expected first two requests on same connection

2023-01-31 18:47 darwin-amd64-11_0 go@bb4ea80b net/http.TestServerSetKeepAlivesEnabledClosesConns (log)

--- FAIL: TestServerSetKeepAlivesEnabledClosesConns (0.00s)
    --- FAIL: TestServerSetKeepAlivesEnabledClosesConns/h1 (0.10s)
        serve_test.go:5554: expected first two requests on same connection

2023-02-01 21:30 darwin-amd64-race go@4b7f7eef net/http.TestServerSetKeepAlivesEnabledClosesConns (log)

--- FAIL: TestServerSetKeepAlivesEnabledClosesConns (0.00s)

— watchflakes

gopherbot · 2023-02-10T18:50:57Z

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "net/http" && test == "TestServerSetKeepAlivesEnabledClosesConns"

2023-02-10 17:19 darwin-amd64-13 go@a943fd0c net/http.TestServerSetKeepAlivesEnabledClosesConns (log)

--- FAIL: TestServerSetKeepAlivesEnabledClosesConns (0.00s)
    --- FAIL: TestServerSetKeepAlivesEnabledClosesConns/h1 (0.10s)
        serve_test.go:5554: expected first two requests on same connection

— watchflakes

gopherbot · 2023-02-24T16:37:05Z

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "net/http" && test == "TestServerSetKeepAlivesEnabledClosesConns"

2023-02-02 19:27 freebsd-arm-paulzhol go@4b43d668 net/http.TestServerSetKeepAlivesEnabledClosesConns (log)

--- FAIL: TestServerSetKeepAlivesEnabledClosesConns (0.00s)
    --- FAIL: TestServerSetKeepAlivesEnabledClosesConns/h1 (0.09s)
        serve_test.go:5550: expected first two requests on same connection

2023-02-09 21:13 darwin-amd64-race go@da47cd61 net/http.TestServerSetKeepAlivesEnabledClosesConns (log)

--- FAIL: TestServerSetKeepAlivesEnabledClosesConns (0.01s)

2023-02-14 16:58 darwin-amd64-nocgo go@53b43607 net/http.TestServerSetKeepAlivesEnabledClosesConns (log)

--- FAIL: TestServerSetKeepAlivesEnabledClosesConns (0.00s)
    --- FAIL: TestServerSetKeepAlivesEnabledClosesConns/h1 (0.15s)
        serve_test.go:5564: idle count for "127.0.0.1:50434" after 2 gets = 0, want 1

— watchflakes

gopherbot · 2023-03-07T22:14:21Z

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "net/http" && test == "TestServerSetKeepAlivesEnabledClosesConns"

2023-03-07 20:02 darwin-amd64-12_0 go@a4cf4fde net/http.TestServerSetKeepAlivesEnabledClosesConns (log)

--- FAIL: TestServerSetKeepAlivesEnabledClosesConns (0.00s)
    --- FAIL: TestServerSetKeepAlivesEnabledClosesConns/h1 (0.07s)
        serve_test.go:5550: expected first two requests on same connection

— watchflakes

bcmills · 2023-03-08T14:30:25Z

(attn @neild)

This was previously reported in #34792.

bcmills · 2023-03-08T14:31:54Z

From #34792 (comment):

A couple of different failure modes. aix and plan9 tend to be
    serve_test.go:5541: idle count after SetKeepAlivesEnabled called = 1; want 0
while the others tend to be
    serve_test.go:5520: expected first two requests on same connection
It's not obvious to me whether those two failure modes share an underlying cause.

fraenkel · 2023-03-08T15:18:29Z

It's different.
The second error is caused by two requests sent one after the other and expecting the connection for the first to be used on the second.

The first failure is after the two requests have used the same single connection, that it is closed after the idle timeout. I believe the issue here is timing. We hope that in 2s the connection is closed.

bcmills · 2023-03-08T15:31:02Z

We hope that in 2s the connection is closed.

Hmm, yeah — that's problematic in a test environment under load. Is there some way we could remove the arbitrary 2s limit?

gopherbot · 2023-03-08T18:18:25Z

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "net/http" && test == "TestServerSetKeepAlivesEnabledClosesConns"

2023-02-23 23:09 freebsd-arm-paulzhol go@52fea4b3 net/http.TestServerSetKeepAlivesEnabledClosesConns (log)

--- FAIL: TestServerSetKeepAlivesEnabledClosesConns (0.00s)
    --- FAIL: TestServerSetKeepAlivesEnabledClosesConns/h1 (0.12s)
        serve_test.go:5550: expected first two requests on same connection

2023-02-28 17:00 darwin-amd64-nocgo go@dfe4591f net/http.TestServerSetKeepAlivesEnabledClosesConns (log)

--- FAIL: TestServerSetKeepAlivesEnabledClosesConns (0.00s)
    --- FAIL: TestServerSetKeepAlivesEnabledClosesConns/h1 (0.07s)
        serve_test.go:5560: idle count for "127.0.0.1:50631" after 2 gets = 0, want 1

— watchflakes

gopherbot · 2023-03-09T01:40:38Z

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "net/http" && test == "TestServerSetKeepAlivesEnabledClosesConns"

2023-03-08 23:17 netbsd-arm64-bsiegert go@d6fa0d2e net/http.TestServerSetKeepAlivesEnabledClosesConns (log)

--- FAIL: TestServerSetKeepAlivesEnabledClosesConns (0.00s)
    --- FAIL: TestServerSetKeepAlivesEnabledClosesConns/h1 (0.06s)
        serve_test.go:5554: idle count for "127.0.0.1:60687" after 2 gets = 0, want 1

— watchflakes

fraenkel · 2023-03-09T01:49:28Z

@bcmills I think we can. There is only one other test that uses the waitCondition but has never failed because of how the test is structured. But it too shouldn't care about how long it takes.

gopherbot · 2023-03-09T03:21:14Z

Change https://go.dev/cl/474835 mentions this issue: net/http: waitCondition sets no timeout

gopherbot · 2023-03-09T20:55:20Z

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "net/http" && test == "TestServerSetKeepAlivesEnabledClosesConns"

2023-03-09 17:47 netbsd-arm-bsiegert go@afbcf213 net/http.TestServerSetKeepAlivesEnabledClosesConns (log)

--- FAIL: TestServerSetKeepAlivesEnabledClosesConns (0.00s)
    --- FAIL: TestServerSetKeepAlivesEnabledClosesConns/h1 (0.27s)
        serve_test.go:5544: expected first two requests on same connection

— watchflakes

gopherbot · 2023-03-15T21:09:55Z

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "net/http" && test == "TestServerSetKeepAlivesEnabledClosesConns"

2023-03-09 22:48 darwin-amd64-11_0 go@b852f395 net/http.TestServerSetKeepAlivesEnabledClosesConns (log)

--- FAIL: TestServerSetKeepAlivesEnabledClosesConns (0.00s)
    --- FAIL: TestServerSetKeepAlivesEnabledClosesConns/h1 (0.09s)
        serve_test.go:5554: expected first two requests on same connection

— watchflakes

gopherbot · 2023-03-22T12:14:43Z

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "net/http" && test == "TestServerSetKeepAlivesEnabledClosesConns"

2023-03-22 11:15 darwin-amd64-nocgo go@bd20bf48 net/http.TestServerSetKeepAlivesEnabledClosesConns (log)

--- FAIL: TestServerSetKeepAlivesEnabledClosesConns (0.00s)
    --- FAIL: TestServerSetKeepAlivesEnabledClosesConns/h1 (0.08s)
        serve_test.go:5425: expected first two requests on same connection

— watchflakes

gopherbot · 2023-03-22T16:31:56Z

Change https://go.dev/cl/478515 mentions this issue: net/http: improve logging in TestServerSetKeepAlivesEnabledClosesConns

- Log the actual addresses reported, in case that information is relevant. - Keep going after the first error, so that we report more information about the idle connections after they have been used. (Was the first connection dropped completely, or did it later show up as idle?) - Remove the third request at the end of the test. It had been assuming that the address for a new connection would always be different from the address for the just-closed connection; however, that assumption does not hold in general. Removing the third request addresses one of the two failure modes seen in #55195. It may help in investigating the other failure mode, but I do not expect it to fix the failures entirely. (I suspect that the other failure mode is a synchronization bug in returning the idle connection from the first request.) For #55195. Change-Id: If9604ea68db0697268288ce9812dd57633e83fbd Reviewed-on: https://go-review.googlesource.com/c/go/+/478515 Reviewed-by: Damien Neil <dneil@google.com> Auto-Submit: Bryan Mills <bcmills@google.com> TryBot-Result: Gopher Robot <gobot@golang.org> Run-TryBot: Bryan Mills <bcmills@google.com>

gopherbot · 2023-03-29T23:43:36Z

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "net/http" && test == "TestServerSetKeepAlivesEnabledClosesConns"

2023-03-29 22:44 darwin-amd64-11_0 go@fde1b139 net/http.TestServerSetKeepAlivesEnabledClosesConns (log)

--- FAIL: TestServerSetKeepAlivesEnabledClosesConns (0.00s)
    --- FAIL: TestServerSetKeepAlivesEnabledClosesConns/h1 (0.06s)
        serve_test.go:5425: made two requests from a single conn "127.0.0.1:51076" (as expected)
        serve_test.go:5435: found 0 idle conns ([]); want 1

— watchflakes

gopherbot · 2023-03-30T02:01:07Z

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "net/http" && test == "TestServerSetKeepAlivesEnabledClosesConns"

2023-03-29 22:56 darwin-amd64-10_15 go@09408a5b net/http.TestServerSetKeepAlivesEnabledClosesConns (log)

--- FAIL: TestServerSetKeepAlivesEnabledClosesConns (0.00s)
    --- FAIL: TestServerSetKeepAlivesEnabledClosesConns/h1 (0.07s)
        serve_test.go:5425: made two requests from a single conn "127.0.0.1:51083" (as expected)
        serve_test.go:5435: found 0 idle conns ([]); want 1

— watchflakes

gopherbot · 2023-04-04T23:45:22Z

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "net/http" && test == "TestServerSetKeepAlivesEnabledClosesConns"

2023-04-04 22:46 darwin-amd64-nocgo go@19409663 net/http.TestServerSetKeepAlivesEnabledClosesConns (log)

--- FAIL: TestServerSetKeepAlivesEnabledClosesConns (0.01s)
    --- FAIL: TestServerSetKeepAlivesEnabledClosesConns/h1 (0.06s)
        serve_test.go:5425: made two requests from a single conn "127.0.0.1:50634" (as expected)
        serve_test.go:5435: found 0 idle conns ([]); want 1

— watchflakes

gopherbot · 2023-06-21T17:14:44Z

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "net/http" && test == "TestServerSetKeepAlivesEnabledClosesConns"

2023-06-20 00:36 darwin-amd64-nocgo go@d51e322a net/http.TestServerSetKeepAlivesEnabledClosesConns (log)

--- FAIL: TestServerSetKeepAlivesEnabledClosesConns (0.00s)
    --- FAIL: TestServerSetKeepAlivesEnabledClosesConns/h1 (0.11s)
        serve_test.go:5554: expected first two requests on same connection

— watchflakes

gopherbot · 2023-12-05T19:14:55Z

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "net/http" && test == "TestServerSetKeepAlivesEnabledClosesConns"

2023-12-05 17:18 darwin-amd64-13 go@6446af94 net/http.TestServerSetKeepAlivesEnabledClosesConns (log)

--- FAIL: TestServerSetKeepAlivesEnabledClosesConns (0.00s)
    --- FAIL: TestServerSetKeepAlivesEnabledClosesConns/h1 (0.13s)
        serve_test.go:5564: idle count for "127.0.0.1:50519" after 2 gets = 0, want 1

— watchflakes

gopherbot added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Sep 20, 2022

rsc closed this as completed Sep 20, 2022

gopherbot changed the title ~~net/http: flaky TestServerSetKeepAlivesEnabledClosesConns~~ net/http: TestServerSetKeepAlivesEnabledClosesConns failures Sep 20, 2022

gopherbot reopened this Dec 17, 2022

bcmills mentioned this issue Mar 8, 2023

net/http: TestServerSetKeepAlivesEnabledClosesConns is flaky #34792

Closed

bcmills added this to the Backlog milestone Mar 8, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

net/http: TestServerSetKeepAlivesEnabledClosesConns failures #55195

net/http: TestServerSetKeepAlivesEnabledClosesConns failures #55195

gopherbot commented Sep 20, 2022

gopherbot commented Sep 20, 2022 •

edited

rsc commented Sep 20, 2022

gopherbot commented Dec 17, 2022

gopherbot commented Jan 4, 2023

gopherbot commented Jan 25, 2023

gopherbot commented Feb 2, 2023

gopherbot commented Feb 10, 2023

gopherbot commented Feb 24, 2023

gopherbot commented Mar 7, 2023

bcmills commented Mar 8, 2023 •

edited

bcmills commented Mar 8, 2023

fraenkel commented Mar 8, 2023

bcmills commented Mar 8, 2023

gopherbot commented Mar 8, 2023

gopherbot commented Mar 9, 2023

fraenkel commented Mar 9, 2023

gopherbot commented Mar 9, 2023

gopherbot commented Mar 9, 2023

gopherbot commented Mar 15, 2023

gopherbot commented Mar 22, 2023

gopherbot commented Mar 22, 2023

gopherbot commented Mar 29, 2023

gopherbot commented Mar 30, 2023

gopherbot commented Apr 4, 2023

gopherbot commented Jun 21, 2023

gopherbot commented Dec 5, 2023

net/http: TestServerSetKeepAlivesEnabledClosesConns failures #55195

net/http: TestServerSetKeepAlivesEnabledClosesConns failures #55195

Comments

gopherbot commented Sep 20, 2022

gopherbot commented Sep 20, 2022 • edited

rsc commented Sep 20, 2022

gopherbot commented Dec 17, 2022

gopherbot commented Jan 4, 2023

gopherbot commented Jan 25, 2023

gopherbot commented Feb 2, 2023

gopherbot commented Feb 10, 2023

gopherbot commented Feb 24, 2023

gopherbot commented Mar 7, 2023

bcmills commented Mar 8, 2023 • edited

bcmills commented Mar 8, 2023

fraenkel commented Mar 8, 2023

bcmills commented Mar 8, 2023

gopherbot commented Mar 8, 2023

gopherbot commented Mar 9, 2023

fraenkel commented Mar 9, 2023

gopherbot commented Mar 9, 2023

gopherbot commented Mar 9, 2023

gopherbot commented Mar 15, 2023

gopherbot commented Mar 22, 2023

gopherbot commented Mar 22, 2023

gopherbot commented Mar 29, 2023

gopherbot commented Mar 30, 2023

gopherbot commented Apr 4, 2023

gopherbot commented Jun 21, 2023

gopherbot commented Dec 5, 2023

gopherbot commented Sep 20, 2022 •

edited

bcmills commented Mar 8, 2023 •

edited