From b5fb9aad8434eed5e4e5383b9093129caf523a2c Mon Sep 17 00:00:00 2001 From: Seebs Date: Thu, 20 Jan 2022 13:10:15 -0600 Subject: [PATCH 1/6] bump test timeouts ridiculously gitlab CI runs as much as 5x slower sometimes during business hours, resulting in tests failing due to 10-11 minute timeouts that would succeed in under 2-3 minutes outside of business hours. to allow us to do anything at all, let's just set that to half an hour, and 90 minutes for `go test -race`. Concern: It's possible there's a timeout that's a gitlab CI configuration thing involved too, because we see some go test timeout panics, but we also see some weird messages about SIGQUIT at 11 minutes, which isn't the go test timeout, so we may need to address that too. Note that we're changing the Makefile, and also the config for the gitlab CI passes, which don't use the Makefile. The Makefile changes are just to be careful and avoid retriggering this later. We may want to revert these if we get the other issues fixed. --- .gitlab/.gitlab-ci.yml | 10 +++++----- Makefile | 16 +++++++++------- 2 files changed, 14 insertions(+), 12 deletions(-) diff --git a/.gitlab/.gitlab-ci.yml b/.gitlab/.gitlab-ci.yml index 793e70aae..09987cadd 100644 --- a/.gitlab/.gitlab-ci.yml +++ b/.gitlab/.gitlab-ci.yml @@ -66,7 +66,7 @@ run go tests: - if: '$CI_PIPELINE_SOURCE == "push" || $CI_PIPELINE_SOURCE == "schedule" || $CI_PIPELINE_SOURCE == "web"' script: - echo "Running featurebase unit tests..." - - go test ./... + - go test -timeout=30m ./... tags: - aws @@ -77,7 +77,7 @@ run go tests race: - if: '$CI_PIPELINE_SOURCE == "push" || $CI_PIPELINE_SOURCE == "schedule" || $CI_PIPELINE_SOURCE == "web"' script: - echo "Running featurebase race tests..." - - go test -race -timeout=30m ./... + - go test -race -timeout=90m ./... tags: - aws @@ -88,10 +88,10 @@ run go tests shardwidth22: - if: '$CI_PIPELINE_SOURCE == "push" || $CI_PIPELINE_SOURCE == "schedule" || $CI_PIPELINE_SOURCE == "web"' script: - echo "Running featurebase race tests..." - - go test -tags=shardwidth22 ./... + - go test -timeout=30m -tags=shardwidth22 ./... tags: - aws - + # we do coverage reporting from the future tests because the json # output is very difficult to human-read. The alternative would be to # run the regular tests twice and also run the future tests. @@ -103,7 +103,7 @@ run go tests future: script: - echo "Running featurebase unit tests..." - PKG_LIST=$(go list ./... | grep -v internal/clustertests | paste -s -d, -) - - go test -json -coverprofile=coverage.out -covermode=atomic -coverpkg=${PKG_LIST} ./... | tee test-report.out + - go test -timeout=30m -json -coverprofile=coverage.out -covermode=atomic -coverpkg=${PKG_LIST} ./... | tee test-report.out artifacts: paths: - coverage.out diff --git a/Makefile b/Makefile index 8545c0cb8..540c1f9b7 100644 --- a/Makefile +++ b/Makefile @@ -19,6 +19,8 @@ DOCKER_BUILD= # set to 1 to use `docker-build` instead of `build` when creating BUILD_TAGS += shardwidth$(SHARD_WIDTH) TEST_TAGS = roaringparanoia UNAME := $(shell uname -s) +TEST_TIMEOUT=30m +RACE_TEST_TIMEOUT=90m ifeq ($(UNAME), Darwin) IS_MACOS:=1 else @@ -45,11 +47,11 @@ version: # Run test suite test: - $(GO) test ./... -tags='$(BUILD_TAGS) $(TEST_TAGS)' $(TESTFLAGS) -v + $(GO) test ./... -tags='$(BUILD_TAGS) $(TEST_TAGS)' $(TESTFLAGS) -v -timeout $(TEST_TIMEOUT) # Run test suite with race flag test-race: - CGO_ENABLED=1 $(GO) test ./... -tags='$(BUILD_TAGS) $(TEST_TAGS)' $(TESTFLAGS) -race -timeout 60m -v + CGO_ENABLED=1 $(GO) test ./... -tags='$(BUILD_TAGS) $(TEST_TAGS)' $(TESTFLAGS) -race -timeout $(RACE_TEST_TIMEOUT) -v testv: topt testvsub @@ -64,7 +66,7 @@ testvsub: set -e; for i in boltdb client ctl http pg pql rbf roaring server sql txkey; do \ echo; echo "___ testing subpkg $$i"; \ cd $$i; pwd; \ - $(GO) test -tags='$(BUILD_TAGS) $(TEST_TAGS)' $(TESTFLAGS) -v -timeout 60m || break; \ + $(GO) test -tags='$(BUILD_TAGS) $(TEST_TAGS)' $(TESTFLAGS) -v -timeout $(RACE_TEST_TIMEOUT) || break; \ echo; echo "999 done testing subpkg $$i"; \ cd ..; \ done @@ -73,7 +75,7 @@ testvsub-race: set -e; for i in boltdb client ctl http pg pql rbf roaring server sql txkey; do \ echo; echo "___ testing subpkg $$i -race"; \ cd $$i; pwd; \ - CGO_ENABLED=1 $(GO) test -tags='$(BUILD_TAGS) $(TEST_TAGS)' $(TESTFLAGS) -v -race -timeout 60m || break; \ + CGO_ENABLED=1 $(GO) test -tags='$(BUILD_TAGS) $(TEST_TAGS)' $(TESTFLAGS) -v -race -timeout $(RACE_TEST_TIMEOUT) || break; \ echo; echo "999 done testing subpkg $$i -race"; \ cd ..; \ done @@ -248,20 +250,20 @@ pilosa-fsck: # Run Pilosa tests inside Docker container docker-test: - docker run --rm -v $(PWD):/go/src/$(CLONE_URL) -w /go/src/$(CLONE_URL) golang:$(GO_VERSION) go test -tags='$(BUILD_TAGS) $(TEST_TAGS)' $(TESTFLAGS) ./... + docker run --rm -v $(PWD):/go/src/$(CLONE_URL) -w /go/src/$(CLONE_URL) golang:$(GO_VERSION) go test -tags='$(BUILD_TAGS) $(TEST_TAGS)' $(TESTFLAGS) -timeout $(TEST_TIMEOUT) ./... # Must use bash in order to -o pipefail; otherwise the tee will hide red tests. # run top tests, not subdirs. print summary red/green after. # The \-\-\- FAIL avoids counting the extra two FAIL strings at then bottom of log.topt. topt: mv log.topt.roar log.topt.roar.prev || true - $(eval SHELL:=/bin/bash) set -o pipefail; $(GO) test -v -timeout 60m -tags='$(BUILD_TAGS) $(TEST_TAGS)' $(TESTFLAGS) 2>&1 | tee log.topt.roar + $(eval SHELL:=/bin/bash) set -o pipefail; $(GO) test -v -timeout $(RACE_TEST_TIMEOUT) -tags='$(BUILD_TAGS) $(TEST_TAGS)' $(TESTFLAGS) 2>&1 | tee log.topt.roar @echo " log.topt.roar green: \c"; cat log.topt.roar | grep PASS |wc -l @echo " log.topt.roar red: \c"; cat log.topt.roar | grep '\-\-\- FAIL' | wc -l topt-race: mv log.topt.race log.topt.race.prev || true - $(eval SHELL:=/bin/bash) set -o pipefail; CGO_ENABLED=1 $(GO) test -race -timeout 60m -v -tags='$(BUILD_TAGS) $(TEST_TAGS)' $(TESTFLAGS) 2>&1 | tee log.topt.race + $(eval SHELL:=/bin/bash) set -o pipefail; CGO_ENABLED=1 $(GO) test -race -timeout $(RACE_TEST_TIMEOUT) -v -tags='$(BUILD_TAGS) $(TEST_TAGS)' $(TESTFLAGS) 2>&1 | tee log.topt.race @echo " log.topt.race green: \c"; cat log.topt.race | grep PASS |wc -l @echo " log.topt.race red: \c"; cat log.topt.race | grep '\-\-\- FAIL' | wc -l From b40c86c278ed3fa94740500636357be452b81832 Mon Sep 17 00:00:00 2001 From: Seebs Date: Thu, 20 Jan 2022 14:46:17 -0600 Subject: [PATCH 2/6] retry etcd leader on "etcdserver: leader changed" This should always be etcdserver.ErrLeaderChanged, but actually apparently it's not always: non-retryable error: etcdserver: leader changed The "non-retryable" comes from our code. The "leader changed" message appears to come from etcdserver, but there appear to be circumstances where it has a suffix, or it could get wrapped, so we check for the string being contained in an error. This is not pretty. --- etcd/embed.go | 41 ++++++++++++++++++++++++++--------------- 1 file changed, 26 insertions(+), 15 deletions(-) diff --git a/etcd/embed.go b/etcd/embed.go index 0167f6b42..696c85df2 100644 --- a/etcd/embed.go +++ b/etcd/embed.go @@ -187,6 +187,22 @@ func (e *Etcd) Close() error { // New feature: retryClient can also retry on errTimeout. const etcdRetryTimes = 3 +// newClient requests a new client which is different from the one +// passed in. if we've already changed our client (say, because someone +// else already did that) we just return that new one. +func (e *Etcd) newClient(cli *clientv3.Client) *clientv3.Client { + e.cliMu.Lock() + defer e.cliMu.Unlock() + if cli != e.cli { + cli = e.cli + // someone else already reopened. retry. + return cli + } + _ = cli.Close() + e.cli = v3client.New(e.e.Server) + return e.cli +} + func (e *Etcd) retryClient(fn func(cli *clientv3.Client) error) (err error) { e.cliMu.Lock() cli := e.cli @@ -196,29 +212,24 @@ func (e *Etcd) retryClient(fn func(cli *clientv3.Client) error) (err error) { err = fn(cli) switch err { case etcdserver.ErrLeaderChanged: - // we can't do much with an error from closing e.cli at this point, so - // we try again. - e.cliMu.Lock() - if cli != e.cli { - cli = e.cli - e.cliMu.Unlock() - // someone else already reopened. retry. - continue - } - _ = cli.Close() - cli = v3client.New(e.e.Server) - e.cli = cli - e.cliMu.Unlock() + cli = e.newClient(cli) break case nil: return nil default: msg := err.Error() - if !strings.HasPrefix(msg, "etcdserver: request timed out") { + // this shouldn't be necessary, but empirically, we sometimes + // get an error message which has this text, but the error itself + // isn't actually etcdserver.ErrLeaderChanged. + if strings.Contains(msg, "etcdserver: leader changed") { + cli = e.newClient(cli) + break + } + if !strings.Contains(msg, "etcdserver: request timed out") { // not a known error, also not a wrapped timeout return errors.Wrap(err, "non-retryable error") } - fallthrough // treat this as being like a timeout error + fallthrough // treat this as being one of the ErrTimeout derivatives, possibly wrapped. case etcdserver.ErrTimeout, etcdserver.ErrTimeoutDueToLeaderFail, etcdserver.ErrTimeoutDueToConnectionLost, etcdserver.ErrTimeoutLeaderTransfer: // sporadic timeouts are concerning but not necessarily fatal // and can usually be retried. From d50065a16f29901281d41e59ab03e4bd0ede4365 Mon Sep 17 00:00:00 2001 From: Seebs Date: Thu, 20 Jan 2022 14:50:45 -0600 Subject: [PATCH 3/6] bump timeouts on single-writer RBF Tx test There's no correct timeout value here, really, but the intent of this is that we first want to be sure that a second tx doesn't successfully start before the first exits, and then that the second *does* successfully start *after* the first exits. Unfortunately, there's no guarantees on timely processing, and in reality, CI can break us by waiting more than 10ms before we get enough CPU time to do something. More generally, there's no way to make a test like this work correctly -- no matter how long you wait for the second Tx to start before closing the first one, it's always possible that it *would* have started just a millisecond later even without you closing the first one. And similarly, no matter how long you give it to start when it's *supposed* to, it could always take longer. We could in principle just set this to wait for the second Tx to start and rely on the test timeout killing us if it doesn't, but then we don't get a useful message. Let's optimistically hope that 10 seconds is long enough for a trivial rollback to happen, since that doesn't need to imply writes. And I think 50ms is a better bet for the first test, although that does make this test close to 5x slower on non-CI hardware. --- rbf/tx_test.go | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/rbf/tx_test.go b/rbf/tx_test.go index 14626ce00..6f98a0fb0 100644 --- a/rbf/tx_test.go +++ b/rbf/tx_test.go @@ -140,14 +140,14 @@ func TestTx_CommitRollback(t *testing.T) { select { case <-ch1: t.Fatal("second tx started while first tx active") - case <-time.After(10 * time.Millisecond): + case <-time.After(50 * time.Millisecond): } // Finish first transaction. close(ch0) select { case <-ch1: - case <-time.After(10 * time.Millisecond): + case <-time.After(10 * time.Second): t.Fatal("second tx should have started after first tx closed") } }) From 375aaf8fbc896797478d35de29985a1a27c6f603 Mon Sep 17 00:00:00 2001 From: Seebs Date: Thu, 20 Jan 2022 16:49:20 -0600 Subject: [PATCH 4/6] don't hardcode local port for backup and restore pprof service If we hardcode a port, we can't run on a crowded machine, like in CI. If we use :0, we can print the value actually picked. --- ctl/backup.go | 2 +- ctl/restore.go | 2 +- ctl/util.go | 2 +- 3 files changed, 3 insertions(+), 3 deletions(-) diff --git a/ctl/backup.go b/ctl/backup.go index 302041dfe..519a604fd 100644 --- a/ctl/backup.go +++ b/ctl/backup.go @@ -60,7 +60,7 @@ func NewBackupCommand(stdin io.Reader, stdout, stderr io.Writer) *BackupCommand CmdIO: pilosa.NewCmdIO(stdin, stdout, stderr), Concurrency: 1, RetryPeriod: time.Minute, - Pprof: "localhost:43809", + Pprof: "localhost:0", } } diff --git a/ctl/restore.go b/ctl/restore.go index 9c12434f8..6cbf700b0 100644 --- a/ctl/restore.go +++ b/ctl/restore.go @@ -56,7 +56,7 @@ func NewRestoreCommand(stdin io.Reader, stdout, stderr io.Writer) *RestoreComman CmdIO: pilosa.NewCmdIO(stdin, stdout, stderr), RetryPeriod: time.Second * 30, Concurrency: 1, - Pprof: "localhost:43809", + Pprof: "localhost:0", } } diff --git a/ctl/util.go b/ctl/util.go index 60ac082c9..2a5611df6 100644 --- a/ctl/util.go +++ b/ctl/util.go @@ -40,7 +40,7 @@ func startProfilingServer(addr string, logger logger.Logger) (close func() error return nil, err } go func() { - logger.Printf("Listening for /debug/pprof/ and /debug/fgprof on '%s'", addr) + logger.Printf("Listening for /debug/pprof/ and /debug/fgprof on '%s'", ln.Addr().String()) logger.Printf("%v", s.Serve(ln)) }() From 096c44884acddfed561b3f949e25b1d0e4e6d825 Mon Sep 17 00:00:00 2001 From: Seebs Date: Fri, 21 Jan 2022 10:38:51 -0600 Subject: [PATCH 5/6] fix typo in doc comment --- test/disco.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/test/disco.go b/test/disco.go index 847d78258..7609fea9f 100644 --- a/test/disco.go +++ b/test/disco.go @@ -38,7 +38,7 @@ func (ports *Ports) Close() error { return err3 } -// listenerPortURL builds a TCP listener and corresponding http://localhost:%d +// listenerWithURL builds a TCP listener and corresponding http://localhost:%d // URL, and returns those. func listenerWithURL() (listener *net.TCPListener, url string, err error) { l, err := net.Listen("tcp", ":0") From 03a18e9beb76d6f6fb23c94784c9fe7b3fc0fe3e Mon Sep 17 00:00:00 2001 From: Seebs Date: Fri, 21 Jan 2022 10:38:56 -0600 Subject: [PATCH 6/6] for leasedkv tests, don't use default etcd config The default etcd config means that if two of this test run around the same time, we end up with one of them failing because it can't bind. Elsewhere, we resolve this by binding to ephemeral ports and fixing up the config to use them, so we duplicate that here. This includes duplicating the existing listenerWithURL from test/, because that package has to import us, so we can't import it, and I don't really want to make a separate package for one trivial function. --- etcd/leasedkv_test.go | 35 ++++++++++++++++++++++++++++++++++- 1 file changed, 34 insertions(+), 1 deletion(-) diff --git a/etcd/leasedkv_test.go b/etcd/leasedkv_test.go index 5d8a9444f..0366d7dd2 100644 --- a/etcd/leasedkv_test.go +++ b/etcd/leasedkv_test.go @@ -3,7 +3,8 @@ package etcd import ( "context" - "errors" + "fmt" + "net" "os" "testing" "time" @@ -11,16 +12,48 @@ import ( "github.com/molecula/featurebase/v2/disco" "github.com/molecula/featurebase/v2/logger" "github.com/molecula/featurebase/v2/testhook" + "github.com/pkg/errors" "go.etcd.io/etcd/embed" "go.etcd.io/etcd/etcdserver/api/v3client" + "go.etcd.io/etcd/pkg/types" ) const initVal = "test" const newVal = "newValue" +// listenerWithURL builds a TCP listener and corresponding http://localhost:%d +// URL, and returns those. Identical to the copy in /test, except we can't +// import that because it imports us. +func listenerWithURL() (listener *net.TCPListener, url string, err error) { + l, err := net.Listen("tcp", ":0") + if err != nil { + return listener, url, err + } + listener = l.(*net.TCPListener) + port := listener.Addr().(*net.TCPAddr).Port + url = fmt.Sprintf("http://localhost:%d", port) + return listener, url, err +} + func TestLeasedKv(t *testing.T) { cfg := embed.NewConfig() + clientListener, clientURL, err := listenerWithURL() + if err != nil { + t.Fatal(errors.Wrap(err, "creating client listener")) + } + peerListener, peerURL, err := listenerWithURL() + if err != nil { + t.Fatal(errors.Wrap(err, "creating peer listener")) + } + cfg.LPUrls = types.MustNewURLs([]string{peerURL}) + cfg.LPeerSocket = []*net.TCPListener{peerListener} + cfg.APUrls = types.MustNewURLs([]string{peerURL}) + cfg.LCUrls = types.MustNewURLs([]string{clientURL}) + cfg.LClientSocket = []*net.TCPListener{clientListener} + cfg.ACUrls = types.MustNewURLs([]string{clientURL}) + cfg.InitialCluster = cfg.Name + "=" + peerURL + dir, err := testhook.TempDir(t, "leasedkv-*") if err != nil { t.Fatal(err)