search

gdt-dev / gdt

Go Declarative Testing
Apache License 2.0
3 stars 2 forks source link

testing.T panics on timeout #37

Closed jaypipes closed 2 days ago

jaypipes commented 3 days ago

We should catch the panic that occurs when timeouts happen:

[gdt] [happy-path/1:cluster-ready] run: attempt 18 after 7m47.179740126s failure: assertion failed: match field not equal: $.status.provisioningStatus.status had different values. expected Succeeded but found InProgress
[gdt] [happy-path/1:cluster-ready] kube.get: kubernetesclusters/cluster-test100a (ns: nc-system)
[gdt] [happy-path/1:cluster-ready] run: attempt 19 after 8m47.364864667s ok: false
[gdt] [happy-path/1:cluster-ready] run: attempt 19 after 8m47.364864667s failure: assertion failed: match field not equal: $.status.provisioningStatus.status had different values. expected Succeeded but found InProgress
panic: test timed out after 10m0s
running tests:
        TestKubernetesClusterHappyPath (10m0s)
        TestKubernetesClusterHappyPath/happy-path (10m0s)

goroutine 220 [running]:
testing.(*M).startAlarm.func1()
        /usr/local/go/src/testing/testing.go:2366 +0x385
created by time.goFunc
        /usr/local/go/src/time/sleep.go:177 +0x2d

goroutine 1 [chan receive, 10 minutes]:
testing.(*T).Run(0xc00026a680, {0x1692d98?, 0x0?}, 0x1763d48)
        /usr/local/go/src/testing/testing.go:1750 +0x3ab
testing.runTests.func1(0xc00026a680)
        /usr/local/go/src/testing/testing.go:2161 +0x37
testing.tRunner(0xc00026a680, 0xc0004d1c70)
        /usr/local/go/src/testing/testing.go:1689 +0xfb
testing.runTests(0xc000482138, {0x2393b50, 0x1, 0x1}, {0x1?, 0x514d4e?, 0x23bc320?})
        /usr/local/go/src/testing/testing.go:2159 +0x445
testing.(*M).Run(0xc000521ae0)
        /usr/local/go/src/testing/testing.go:2027 +0x68b
main.main()
        _testmain.go:47 +0x16c

goroutine 28 [chan receive, 9 minutes]:
testing.(*T).Run(0xc00026a820, {0xc000478194?, 0x167d0cb?}, 0xc0003f3ae0)
        /usr/local/go/src/testing/testing.go:1750 +0x3ab
github.com/gdt-dev/gdt/scenario.(*Scenario).Run(0xc00020eea0, {0x18c94e8, 0xc000517ef0}, 0xc00026a820)
        /home/azureuser/go/pkg/mod/github.com/gdt-dev/gdt@v1.9.0/scenario/run.go:66 +0x510
github.com/gdt-dev/gdt/suite.(*Suite).Run(0x18c94e8?, {0x18c94e8, 0xc000517ef0}, 0xc00026a820)
        /home/azureuser/go/pkg/mod/github.com/gdt-dev/gdt@v1.9.0/suite/run.go:15 +0x6a
command-line-arguments_test.TestKubernetesClusterHappyPath(0xc00026a820)
        /home/azureuser/src/dev.azure.com/msazuredev/AzureForOperatorsIndustry/nc-aks/test/func/kubernetes_cluster_test.go:27 +0x195
testing.tRunner(0xc00026a820, 0x1763d48)
        /usr/local/go/src/testing/testing.go:1689 +0xfb
created by testing.(*T).Run in goroutine 1
        /usr/local/go/src/testing/testing.go:1742 +0x390

goroutine 52 [chan receive]:
github.com/gdt-dev/gdt/scenario.(*Scenario).runSpec(0xc00069bc00?, {0x18c94e8, 0xc0009a5ce0}, 0xc000270b80, 0x241e380?, 0x1, {0x18cb020, 0xc0000fe640})
        /home/azureuser/go/pkg/mod/github.com/gdt-dev/gdt@v1.9.0/scenario/run.go:177 +0x585
github.com/gdt-dev/gdt/scenario.(*Scenario).Run.func1(0xc00026a1a0)
        /home/azureuser/go/pkg/mod/github.com/gdt-dev/gdt@v1.9.0/scenario/run.go:96 +0x38d
testing.tRunner(0xc00026a1a0, 0xc0003f3ae0)
        /usr/local/go/src/testing/testing.go:1689 +0xfb
created by testing.(*T).Run in goroutine 28
        /usr/local/go/src/testing/testing.go:1742 +0x390

goroutine 16 [IO wait]:
internal/poll.runtime_pollWait(0x7de3282256d0, 0x72)
        /usr/local/go/src/runtime/netpoll.go:345 +0x85
internal/poll.(*pollDesc).wait(0xc000429e80?, 0xc000704000?, 0x0)
        /usr/local/go/src/internal/poll/fd_poll_runtime.go:84 +0x27
internal/poll.(*pollDesc).waitRead(...)
        /usr/local/go/src/internal/poll/fd_poll_runtime.go:89
internal/poll.(*FD).Read(0xc000429e80, {0xc000704000, 0xa000, 0xa000})
        /usr/local/go/src/internal/poll/fd_unix.go:164 +0x27a
net.(*netFD).Read(0xc000429e80, {0xc000704000?, 0x7de328262488?, 0xc00025cd80?})
        /usr/local/go/src/net/fd_posix.go:55 +0x25
net.(*conn).Read(0xc00051d3c0, {0xc000704000?, 0xc000173938?, 0x413d5b?})
        /usr/local/go/src/net/net.go:179 +0x45
crypto/tls.(*atLeastReader).Read(0xc00025cd80, {0xc000704000?, 0x0?, 0xc00025cd80?})
        /usr/local/go/src/crypto/tls/conn.go:806 +0x3b
bytes.(*Buffer).ReadFrom(0xc0004b97b0, {0x18b39e0, 0xc00025cd80})
        /usr/local/go/src/bytes/buffer.go:211 +0x98
crypto/tls.(*Conn).readFromUntil(0xc0004b9508, {0x18b3b60, 0xc00051d3c0}, 0xc000173980?)
        /usr/local/go/src/crypto/tls/conn.go:828 +0xde
crypto/tls.(*Conn).readRecordOrCCS(0xc0004b9508, 0x0)
        /usr/local/go/src/crypto/tls/conn.go:626 +0x3cf
crypto/tls.(*Conn).readRecord(...)
        /usr/local/go/src/crypto/tls/conn.go:588
crypto/tls.(*Conn).Read(0xc0004b9508, {0xc0004fb000, 0x1000, 0xc000583500?})
        /usr/local/go/src/crypto/tls/conn.go:1370 +0x156
bufio.(*Reader).Read(0xc0004f4060, {0xc0004e0200, 0x9, 0x2391860?})
        /usr/local/go/src/bufio/bufio.go:241 +0x197
io.ReadAtLeast({0x18b2740, 0xc0004f4060}, {0xc0004e0200, 0x9, 0x9}, 0x9)
        /usr/local/go/src/io/io.go:335 +0x90
io.ReadFull(...)
        /usr/local/go/src/io/io.go:354
golang.org/x/net/http2.readFrameHeader({0xc0004e0200, 0x9, 0xc000173dc0?}, {0x18b2740?, 0xc0004f4060?})
        /home/azureuser/go/pkg/mod/golang.org/x/net@v0.23.0/http2/frame.go:237 +0x65
golang.org/x/net/http2.(*Framer).ReadFrame(0xc0004e01c0)
        /home/azureuser/go/pkg/mod/golang.org/x/net@v0.23.0/http2/frame.go:498 +0x85
golang.org/x/net/http2.(*clientConnReadLoop).run(0xc000173fa8)
        /home/azureuser/go/pkg/mod/golang.org/x/net@v0.23.0/http2/transport.go:2429 +0xd8
golang.org/x/net/http2.(*ClientConn).readLoop(0xc000514780)
        /home/azureuser/go/pkg/mod/golang.org/x/net@v0.23.0/http2/transport.go:2325 +0x65
created by golang.org/x/net/http2.(*ClientConn).goRun in goroutine 15
        /home/azureuser/go/pkg/mod/golang.org/x/net@v0.23.0/http2/transport.go:369 +0x2d

goroutine 57 [select]:
github.com/cenkalti/backoff.(*Ticker).run(0xc0009a6600)
        /home/azureuser/go/pkg/mod/github.com/cenkalti/backoff@v2.2.1+incompatible/ticker.go:56 +0x153
created by github.com/cenkalti/backoff.NewTicker in goroutine 52
        /home/azureuser/go/pkg/mod/github.com/cenkalti/backoff@v2.2.1+incompatible/ticker.go:35 +0x1d6
FAIL    command-line-arguments  600.036s
FAIL
jaypipes commented 2 days ago

After bringing in gdt@v1.9.1, I'm seeing different behaviour but still get the panic:

[gdt] [happy-path] using timeout of 5s [plugin default]
[gdt] [happy-path/0:create-cluster] kube.create: kubernetesclusters (ns: nc-system)
[gdt] [happy-path/0:create-cluster] run: single-shot (no retries) ok: true
[gdt] [happy-path] wait: 10m before
panic: test timed out after 10m0s
running tests:
        TestKubernetesClusterHappyPath (10m0s)
        TestKubernetesClusterHappyPath/happy-path (10m0s)

goroutine 114 [running]:
testing.(*M).startAlarm.func1()
        /usr/local/go/src/testing/testing.go:2366 +0x385
created by time.goFunc
        /usr/local/go/src/time/sleep.go:177 +0x2d

goroutine 1 [chan receive, 10 minutes]:
testing.(*T).Run(0xc000130340, {0x1693113?, 0x0?}, 0x17640d0)
        /usr/local/go/src/testing/testing.go:1750 +0x3ab
testing.runTests.func1(0xc000130340)
        /usr/local/go/src/testing/testing.go:2161 +0x37
testing.tRunner(0xc000130340, 0xc0004d3c70)
        /usr/local/go/src/testing/testing.go:1689 +0xfb
testing.runTests(0xc000484138, {0x2393b50, 0x1, 0x1}, {0x1?, 0x514d4e?, 0x23bc320?})
        /usr/local/go/src/testing/testing.go:2159 +0x445
testing.(*M).Run(0xc000129900)
        /usr/local/go/src/testing/testing.go:2027 +0x68b
main.main()
        _testmain.go:47 +0x16c

goroutine 58 [chan receive, 10 minutes]:
testing.(*T).Run(0xc0001304e0, {0xc00047a180?, 0x167d42b?}, 0xc00015dad0)
        /usr/local/go/src/testing/testing.go:1750 +0x3ab
github.com/gdt-dev/gdt/scenario.(*Scenario).Run(0xc000160090, {0x18c9908, 0xc0004a3e90}, 0xc0001304e0)
        /home/azureuser/go/pkg/mod/github.com/gdt-dev/gdt@v1.9.1/scenario/run.go:66 +0x547
github.com/gdt-dev/gdt/suite.(*Suite).Run(0x18c9908?, {0x18c9908, 0xc0004a3e90}, 0xc0001304e0)
        /home/azureuser/go/pkg/mod/github.com/gdt-dev/gdt@v1.9.1/suite/run.go:15 +0x6a
command-line-arguments_test.TestKubernetesClusterHappyPath(0xc0001304e0)
        /home/azureuser/src/dev.azure.com/msazuredev/AzureForOperatorsIndustry/nc-aks/test/func/kubernetes_cluster_test.go:27 +0x195
testing.tRunner(0xc0001304e0, 0x17640d0)
        /usr/local/go/src/testing/testing.go:1689 +0xfb
created by testing.(*T).Run in goroutine 1
        /usr/local/go/src/testing/testing.go:1742 +0x390

goroutine 68 [sleep, 10 minutes]:
time.Sleep(0x8bb2c97000)
        /usr/local/go/src/runtime/time.go:195 +0x115
github.com/gdt-dev/gdt/scenario.(*Scenario).Run.func1(0xc00027a1a0)
        /home/azureuser/go/pkg/mod/github.com/gdt-dev/gdt@v1.9.1/scenario/run.go:76 +0x20a
testing.tRunner(0xc00027a1a0, 0xc00015dad0)
        /usr/local/go/src/testing/testing.go:1689 +0xfb
created by testing.(*T).Run in goroutine 58
        /usr/local/go/src/testing/testing.go:1742 +0x390
FAIL    command-line-arguments  600.115s
FAIL
jaypipes commented 2 days ago

sigh.. turns out 10 minutes is Go's test tool standard timeout :(

https://pkg.go.dev/cmd/go#hdr-Testing_flags