Skip to content

Conversation

@lukemassa
Copy link
Contributor

@lukemassa lukemassa commented Oct 16, 2025

what

Add a helper to close close metrics scope when tests are finished, use it throughout tests.

why

I was trying to use go's race detector on the unit tests, and running into these errors:

atlantis % go test ./... -short -race
?   	github.com/runatlantis/atlantis	[no test files]
ok  	github.com/runatlantis/atlantis/cmd	(cached)
ok  	github.com/runatlantis/atlantis/server	2.899s
PASS
panic: Log in goroutine after TestAPIController_Plan has completed: 2025-10-15T20:28:02.707-0400	DEBUG	gauge	{"name": "tally_internal_counter_cardinality", "value": 0, "tags": {"host":"global","instance":"global","version":"4.1.17"}, "type": "gauge"}
	

goroutine 22 [running]:
testing.(*common).log(0xc00009ac40, {0xc0000ec840, 0xb6})
	/Users/lmassa/go/pkg/mod/golang.org/[email protected]/src/testing/testing.go:1030 +0x178
testing.(*common).Logf(0xc00009ac40, {0x10515c2c8, 0x2}, {0xc0004aa410, 0x1, 0x1})
	/Users/lmassa/go/pkg/mod/golang.org/[email protected]/src/testing/testing.go:1191 +0x80
go.uber.org/zap/zaptest.TestingWriter.Write({{0x10547b050?, 0xc00009ac40?}, 0x0?}, {0xc0001b5400, 0xb7, 0x400})
	/Users/lmassa/go/pkg/mod/go.uber.org/[email protected]/zaptest/logger.go:146 +0xf0
go.uber.org/zap/zapcore.(*ioCore).Write(0xc0001a3c80, {0xff, {0xc2342ce4aa2a28b0, 0x3ce12682, 0x105a22fc0}, {0x0, 0x0}, {0x10516232e, 0x5}, {0x0, ...}, ...}, ...)
	/Users/lmassa/go/pkg/mod/go.uber.org/[email protected]/zapcore/core.go:99 +0x114
go.uber.org/zap/zapcore.(*CheckedEntry).Write(0xc0003c6b60, {0x0, 0x0, 0x0})
	/Users/lmassa/go/pkg/mod/go.uber.org/[email protected]/zapcore/entry.go:253 +0x154
go.uber.org/zap.(*SugaredLogger).log(0xc00006ec00, 0xff, {0x10516232e, 0x5}, {0x0, 0x0, 0x0}, {0x0, 0x0, 0x0})
	/Users/lmassa/go/pkg/mod/go.uber.org/[email protected]/sugar.go:355 +0x108
go.uber.org/zap.(*SugaredLogger).Debugf(...)
	/Users/lmassa/go/pkg/mod/go.uber.org/[email protected]/sugar.go:198
github.com/runatlantis/atlantis/server/logging.(*StructuredLogger).Debug(0xc0004dd640, {0x10516232e, 0x5}, {0x0, 0x0, 0x0})
	/Users/lmassa/atlantis/server/logging/simple_logger.go:134 +0x74
github.com/runatlantis/atlantis/server/metrics.(*debugReporter).ReportGauge(0xc00012a420, {0xc000035350, 0x22}, 0xc0000f8d20, 0x0)
	/Users/lmassa/atlantis/server/metrics/debug.go:47 +0x2b8
github.com/uber-go/tally/v4.(*scopeRegistry).reportInternalMetrics(0xc00053a180)
	/Users/lmassa/go/pkg/mod/github.com/uber-go/tally/[email protected]/scope_registry.go:339 +0x1ec
github.com/uber-go/tally/v4.(*scopeRegistry).Report(0xc00053a180, {0x10547c680, 0xc00012a420})
	/Users/lmassa/go/pkg/mod/github.com/uber-go/tally/[email protected]/scope_registry.go:115 +0x74
github.com/uber-go/tally/v4.(*scope).reportRegistry(0xc000174900)
	/Users/lmassa/go/pkg/mod/github.com/uber-go/tally/[email protected]/scope.go:275 +0x70
github.com/uber-go/tally/v4.(*scope).reportLoopRun(0xc000174900)
	/Users/lmassa/go/pkg/mod/github.com/uber-go/tally/[email protected]/scope.go:270 +0x5c
github.com/uber-go/tally/v4.(*scope).reportLoop(0xc000174900, 0x3b9aca00)
	/Users/lmassa/go/pkg/mod/github.com/uber-go/tally/[email protected]/scope.go:258 +0x90
github.com/uber-go/tally/v4.newRootScope.func1()
	/Users/lmassa/go/pkg/mod/github.com/uber-go/tally/[email protected]/scope.go:198 +0x7c
created by github.com/uber-go/tally/v4.newRootScope in goroutine 21
	/Users/lmassa/go/pkg/mod/github.com/uber-go/tally/[email protected]/scope.go:196 +0xa48
FAIL	github.com/runatlantis/atlantis/server/controllers	1.470s

I dug into it and the issue wasn't with the race detector itself, it's because the race detector reordered some code exposing a bug where we in many places create a new scope but then discard its closer. Metrics are emitted during the tests, so if we don't close it, with the reordering, the metrics try to write to t.Log() in test that has already ended.

This code consolidates the places where we create a new metrics scope, and properly calls a Cleanup() handler to close the scope when the test is done.

I did most of the conversions

#!/bin/bash

for file in $(git grep -l '_, _.*metrics.NewLogging')
do
    echo $file
    cat $file | perl -pe 's/(.*), _, _ := metrics\.NewLoggingScope\((.*), (.*)/\1 := metricstest.NewLoggingScope(t, \2, \3/g' | sponge $file
    ~/go/bin/goimports -w $file
done

tests

Running CI

references

N/A

@github-actions github-actions bot added the go Pull requests that update Go code label Oct 16, 2025
@dosubot dosubot bot added the bug Something isn't working label Oct 16, 2025
@lukemassa lukemassa force-pushed the close_logger_after_test_finishes branch from 503f22f to 18279b4 Compare October 16, 2025 01:29
@lukemassa lukemassa changed the title fix: Close logger after test finishes fix: Close metric scope after tests finish Oct 16, 2025
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

bug Something isn't working go Pull requests that update Go code

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant