Skip to content

Flaky test: TestAuthZPluginAllowEventStream produces panic, but passes, and concurrency issues #46523

New issue
New issue
Open
Open
Flaky test: TestAuthZPluginAllowEventStream produces panic, but passes, and concurrency issues#46523
Labels
area/pluginsarea/testing
@thaJeztah

Description

@thaJeztah
thaJeztah
opened on Sep 21, 2023

Description

I noticed this test showing a panic, but the test itself passing
https://ci-next.docker.com/public/blue/organizations/jenkins/moby/detail/PR-46522/2/pipeline

The TestAuthZPluginAllowEventStream test produces a panic during the test, but the test itself passes. There's a couple of panics listed;

[2023-09-21T07:37:39.335Z] 2023/09/21 07:37:39 http: panic serving 127.0.0.1:34084: runtime error: invalid memory address or nil pointer dereference
[2023-09-21T07:37:40.274Z] 2023/09/21 07:37:40 http: panic serving 127.0.0.1:34074: could not unmarshal json for /AuthZPlugin.AuthZRes: unexpected end of JSON input
[2023-09-21T07:37:42.182Z] 2023/09/21 07:37:42 http: panic serving 127.0.0.1:34098: could not unmarshal json for /AuthZPlugin.AuthZRes: unexpected end of JSON input

[2023-09-21T07:37:38.396Z] === RUN   TestAuthZPluginAllowEventStream
[2023-09-21T07:37:39.335Z] 2023/09/21 07:37:39 http: panic serving 127.0.0.1:34084: runtime error: invalid memory address or nil pointer dereference
[2023-09-21T07:37:39.335Z] goroutine 127 [running]:
[2023-09-21T07:37:39.335Z] net/http.(*conn).serve.func1()
[2023-09-21T07:37:39.335Z] 	/usr/local/go/src/net/http/server.go:1854 +0xb0
[2023-09-21T07:37:39.335Z] panic({0xb157a0, 0x164c2d0})
[2023-09-21T07:37:39.335Z] 	/usr/local/go/src/runtime/panic.go:890 +0x248
[2023-09-21T07:37:39.335Z] github.com/docker/docker/integration/plugin/authz.setupSuite.func3({0xe10a90, 0x400044d920}, 0xffff5a3ab488?)
[2023-09-21T07:37:39.335Z] 	/go/src/github.com/docker/docker/integration/plugin/authz/main_test.go:159 +0x14c
[2023-09-21T07:37:39.335Z] net/http.HandlerFunc.ServeHTTP(0x40002a8300?, {0xe10a90?, 0x400044d920?}, 0x412cf4?)
[2023-09-21T07:37:39.335Z] 	/usr/local/go/src/net/http/server.go:2122 +0x38
[2023-09-21T07:37:39.335Z] net/http.(*ServeMux).ServeHTTP(0xe10f58?, {0xe10a90, 0x400044d920}, 0x40002a8300)
[2023-09-21T07:37:39.335Z] 	/usr/local/go/src/net/http/server.go:2500 +0x13c
[2023-09-21T07:37:39.335Z] github.com/docker/docker/vendor/go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp.(*Handler).ServeHTTP(0x40001441e0, {0xe0fe60?, 0x40002750a0}, 0x40002a8000)
[2023-09-21T07:37:39.335Z] 	/go/src/github.com/docker/docker/vendor/go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp/handler.go:189 +0x9ac
[2023-09-21T07:37:39.335Z] net/http.serverHandler.ServeHTTP({0xe069d0?}, {0xe0fe60, 0x40002750a0}, 0x40002a8000)
[2023-09-21T07:37:39.335Z] 	/usr/local/go/src/net/http/server.go:2936 +0x2c0
[2023-09-21T07:37:39.335Z] net/http.(*conn).serve(0x4000232e10, {0xe10f58, 0x400011a6c0})
[2023-09-21T07:37:39.335Z] 	/usr/local/go/src/net/http/server.go:1995 +0x518
[2023-09-21T07:37:39.335Z] created by net/http.(*Server).Serve
[2023-09-21T07:37:39.335Z] 	/usr/local/go/src/net/http/server.go:3089 +0x4e8
[2023-09-21T07:37:40.274Z] 2023/09/21 07:37:40 http: panic serving 127.0.0.1:34074: could not unmarshal json for /AuthZPlugin.AuthZRes: unexpected end of JSON input
[2023-09-21T07:37:40.274Z] goroutine 162 [running]:
[2023-09-21T07:37:40.274Z] net/http.(*conn).serve.func1()
[2023-09-21T07:37:40.274Z] 	/usr/local/go/src/net/http/server.go:1854 +0xb0
[2023-09-21T07:37:40.274Z] panic({0xab9e20, 0x4000124b80})
[2023-09-21T07:37:40.274Z] 	/usr/local/go/src/runtime/panic.go:890 +0x248
[2023-09-21T07:37:40.274Z] github.com/docker/docker/integration/plugin/authz.setupSuite.func3({0xe10a90, 0x400044da40}, 0xffff5a3ab488?)
[2023-09-21T07:37:40.274Z] 	/go/src/github.com/docker/docker/integration/plugin/authz/main_test.go:149 +0x36c
[2023-09-21T07:37:40.274Z] net/http.HandlerFunc.ServeHTTP(0x40002a8800?, {0xe10a90?, 0x400044da40?}, 0x412cf4?)
[2023-09-21T07:37:40.274Z] 	/usr/local/go/src/net/http/server.go:2122 +0x38
[2023-09-21T07:37:40.274Z] net/http.(*ServeMux).ServeHTTP(0xe10f58?, {0xe10a90, 0x400044da40}, 0x40002a8800)
[2023-09-21T07:37:40.274Z] 	/usr/local/go/src/net/http/server.go:2500 +0x13c
[2023-09-21T07:37:40.274Z] github.com/docker/docker/vendor/go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp.(*Handler).ServeHTTP(0x40001441e0, {0xe0fe60?, 0x4000275180}, 0x40002a8400)
[2023-09-21T07:37:40.274Z] 	/go/src/github.com/docker/docker/vendor/go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp/handler.go:189 +0x9ac
[2023-09-21T07:37:40.274Z] net/http.serverHandler.ServeHTTP({0x40002f4600?}, {0xe0fe60, 0x4000275180}, 0x40002a8400)
[2023-09-21T07:37:40.274Z] 	/usr/local/go/src/net/http/server.go:2936 +0x2c0
[2023-09-21T07:37:40.274Z] net/http.(*conn).serve(0x400012f950, {0xe10f58, 0x400011a6c0})
[2023-09-21T07:37:40.274Z] 	/usr/local/go/src/net/http/server.go:1995 +0x518
[2023-09-21T07:37:40.274Z] created by net/http.(*Server).Serve
[2023-09-21T07:37:40.274Z] 	/usr/local/go/src/net/http/server.go:3089 +0x4e8
[2023-09-21T07:37:42.182Z] 2023/09/21 07:37:42 http: panic serving 127.0.0.1:34098: could not unmarshal json for /AuthZPlugin.AuthZRes: unexpected end of JSON input
[2023-09-21T07:37:42.182Z] goroutine 181 [running]:
[2023-09-21T07:37:42.182Z] net/http.(*conn).serve.func1()
[2023-09-21T07:37:42.182Z] 	/usr/local/go/src/net/http/server.go:1854 +0xb0
[2023-09-21T07:37:42.182Z] panic({0xab9e20, 0x4000124c70})
[2023-09-21T07:37:42.182Z] 	/usr/local/go/src/runtime/panic.go:890 +0x248
[2023-09-21T07:37:42.182Z] github.com/docker/docker/integration/plugin/authz.setupSuite.func3({0xe10a90, 0x400044db60}, 0xffff5a3ab488?)
[2023-09-21T07:37:42.182Z] 	/go/src/github.com/docker/docker/integration/plugin/authz/main_test.go:149 +0x36c
[2023-09-21T07:37:42.182Z] net/http.HandlerFunc.ServeHTTP(0x40002a8d00?, {0xe10a90?, 0x400044db60?}, 0x412cf4?)
[2023-09-21T07:37:42.182Z] 	/usr/local/go/src/net/http/server.go:2122 +0x38
[2023-09-21T07:37:42.182Z] net/http.(*ServeMux).ServeHTTP(0xe10f58?, {0xe10a90, 0x400044db60}, 0x40002a8d00)
[2023-09-21T07:37:42.182Z] 	/usr/local/go/src/net/http/server.go:2500 +0x13c
[2023-09-21T07:37:42.182Z] github.com/docker/docker/vendor/go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp.(*Handler).ServeHTTP(0x40001441e0, {0xe0fe60?, 0x4000275260}, 0x40002a8900)
[2023-09-21T07:37:42.182Z] 	/go/src/github.com/docker/docker/vendor/go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp/handler.go:189 +0x9ac
[2023-09-21T07:37:42.182Z] net/http.serverHandler.ServeHTTP({0x4000295350?}, {0xe0fe60, 0x4000275260}, 0x40002a8900)
[2023-09-21T07:37:42.182Z] 	/usr/local/go/src/net/http/server.go:2936 +0x2c0
[2023-09-21T07:37:42.182Z] net/http.(*conn).serve(0x40005feab0, {0xe10f58, 0x400011a6c0})
[2023-09-21T07:37:42.182Z] 	/usr/local/go/src/net/http/server.go:1995 +0x518
[2023-09-21T07:37:42.182Z] created by net/http.(*Server).Serve
[2023-09-21T07:37:42.182Z] 	/usr/local/go/src/net/http/server.go:3089 +0x4e8
[2023-09-21T07:37:44.721Z] --- PASS: TestAuthZPluginAllowEventStream (6.05s)

Those are happening around this code;

moby/integration/plugin/authz/main_test.go

Lines 140 to 172 in 3a520c1

mux.HandleFunc("/AuthZPlugin.AuthZRes", func(w http.ResponseWriter, r *http.Request) {
defer r.Body.Close()
body, err := io.ReadAll(r.Body)
if err != nil {
panic("could not read body for /AuthZPlugin.AuthZRes: " + err.Error())
}
authReq := authorization.Request{}
err = json.Unmarshal(body, &authReq)
if err != nil {
panic("could not unmarshal json for /AuthZPlugin.AuthZRes: " + err.Error())
}
assertBody(authReq.RequestURI, authReq.ResponseHeaders, authReq.ResponseBody)
assertAuthHeaders(authReq.ResponseHeaders)
// Count only server version api
if strings.HasSuffix(authReq.RequestURI, serverVersionAPI) {
ctrl.versionResCount++
}
resRes := ctrl.resRes
if isAllowed(authReq.RequestURI) {
resRes = authorization.Response{Allow: true}
}
if resRes.Err != "" {
w.WriteHeader(http.StatusInternalServerError)
}
b, err := json.Marshal(resRes)
if err != nil {
panic("could not marshal json for /AuthZPlugin.AuthZRes: " + err.Error())
}
ctrl.resUser = authReq.User
w.Write(b)
})

Some of those panics may be just "noise" if the test doesn't actually send a proper request (which could explain the EOF errors when unmarshaling JSON), but there's also some weird things happening in that test-suite (at a quick glance), which at least wouldn't work well concurrently;

There is a setupTestV1 function which is used to set up the tests, and both creates and cleans up the /etc/docker/plugins (hard-coded path);

moby/integration/plugin/authz/authz_plugin_test.go

Lines 53 to 71 in 5e7eade

func setupTestV1(t *testing.T) context.Context {
ctx := setupTest(t)
ctrl = &authorizationController{}
err := os.MkdirAll("/etc/docker/plugins", 0o755)
assert.NilError(t, err)
fileName := fmt.Sprintf("/etc/docker/plugins/%s.spec", testAuthZPlugin)
err = os.WriteFile(fileName, []byte(server.URL), 0o644)
assert.NilError(t, err)
t.Cleanup(func() {
err := os.RemoveAll("/etc/docker/plugins")
assert.NilError(t, err)
ctrl = nil
})
return ctx
}

That function is called by various tests;

git grep 'setupTestV1'
integration/plugin/authz/authz_plugin_test.go:func setupTestV1(t *testing.T) context.Context {
integration/plugin/authz/authz_plugin_test.go:  ctx := setupTestV1(t)
integration/plugin/authz/authz_plugin_test.go:  ctx := setupTestV1(t)
integration/plugin/authz/authz_plugin_test.go:  ctx := setupTestV1(t)
integration/plugin/authz/authz_plugin_test.go:  ctx := setupTestV1(t)
integration/plugin/authz/authz_plugin_test.go:  ctx := setupTestV1(t)
integration/plugin/authz/authz_plugin_test.go:  ctx := setupTestV1(t)
integration/plugin/authz/authz_plugin_test.go:  ctx := setupTestV1(t)
integration/plugin/authz/authz_plugin_test.go:  ctx := setupTestV1(t)
integration/plugin/authz/authz_plugin_test.go:  ctx := setupTestV1(t)
integration/plugin/authz/authz_plugin_test.go:  ctx := setupTestV1(t)
integration/plugin/authz/authz_plugin_test.go:  ctx := setupTestV1(t)
integration/plugin/authz/authz_plugin_test.go:  ctx := setupTestV1(t)

Similar to using the same /etc/docker/plugins directory, there's also a package-level ctrl variable, which is initialized (and reset) in that function, which is used (and mutated) by all tests;

moby/integration/plugin/authz/authz_plugin_test.go

Lines 39 to 40 in 5e7eade

alwaysAllowed = []string{"/_ping", "/info"}
ctrl *authorizationController

Each test spins up its own daemon, so probably these part could be separated. No idea though if any of this is related; I don't see tests running in parallel, but the hard-coded /etc/docker/plugins path on its own looks scary (if other suites may be running in parallel).

Metadata

Metadata

Assignees

No one assigned

    Labels

    area/pluginsarea/testing

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions