internal/log: Improve API for testing #916

felixge · 2021-05-03T15:15:01Z

I just noticed that d9472a0 caused the profiler package to always emit
some log output, regardless of go test -v being used or not. I'm very
sorry about this. IMO tests should never print to stdout unless
requested.

This patch is my attempt to fix this by making it easy for individual
tests to capture the log output (see UseLogger, RecordLogger). I've also
added DiscardLogger since it can be very convenient for tests that want
to ignore log output without capturing it. Arguably RecordLogger could
be used for this as well, but that would do a poor job of capturing the
intend of such code.

I just noticed that d9472a0 caused the profiler package to always emit some log output, regardless of `go test -v` being used or not. I'm very sorry about this. IMO tests should never print to stdout unless requested. This patch is my attempt to fix this by making it easy for individual tests to capture the log output (see UseLogger, RecordLogger). I've also added DiscardLogger since it can be very convenient for tests that want to ignore log output without capturing it. Arguably RecordLogger could be used for this as well, but that would do a poor job of capturing the intend of such code.

gbbr · 2021-05-04T07:05:07Z

internal/log/log.go

+// RecordLogger appends every call to Log() to Logs.
+type RecordLogger struct {
+	m    sync.Mutex
+	Logs []string


We should have some sort of accessor/getter for this, under the mutex. Otherwise we'll get race conditions in tests if someone tries to log and assert output at the same time...

Done in 8c61d7d.

Personally I would not have done this, but I don't feel strongly enough to start a discussion. My initial reaction was that this is solving a problem we don't have yet. Additionally it's encouraging a testing pattern that might not suffer from memory race conditions, but encourages other data races. IMO asserting log output before the test is done is an anti-pattern.

Anyway, as I said, I don't feel strongly about it, so I just made the change.

gbbr · 2021-05-04T07:05:20Z

profiler/profiler_test.go

@@ -17,6 +17,7 @@ import (

 	"github.com/stretchr/testify/assert"
 	"github.com/stretchr/testify/require"
+	"gopkg.in/DataDog/dd-trace-go.v1/internal/log"


Please group these in the right place...

Done in bc28e2a - would you be able to explain the rational behind this? I'll have an easier time to remember this if I'm motivated to do it : p.

gbbr · 2021-05-04T07:08:32Z

internal/log/log.go

+// UseLogger sets l as the active logger and returns the previously configured
+// logger.
+func UseLogger(l ddtrace.Logger) ddtrace.Logger {


Since this only makes sense in tests (returning the old logger), why not:

Suggested change

// UseLogger sets l as the active logger and returns the previously configured

// logger.

func UseLogger(l ddtrace.Logger) ddtrace.Logger {

// UseLogger sets l as the active logger and returns a function to restore the previous

// logger. The return value is mostly useful when testing.

func UseLogger(l ddtrace.Logger) (undo func()) {

Then, in tests, you could do:

defer UseLogger(rc)()

Much shorter and cleaner imho.

Done in bce3c86. I considered this but figured it might be overfitting the API to a singular use case. That being said, since we only have this use case for now and it's easy to iterate on an internal package like this, why not : )?

felixge

@gbbr thanks for the review! I addressed all your feedback. PTAL

felixge · 2021-05-04T07:25:33Z

internal/log/log.go

+// RecordLogger appends every call to Log() to Logs.
+type RecordLogger struct {
+	m    sync.Mutex
+	Logs []string


Done in 8c61d7d.

Personally I would not have done this, but I don't feel strongly enough to start a discussion. My initial reaction was that this is solving a problem we don't have yet. Additionally it's encouraging a testing pattern that might not suffer from memory race conditions, but encourages other data races. IMO asserting log output before the test is done is an anti-pattern.

Anyway, as I said, I don't feel strongly about it, so I just made the change.

felixge · 2021-05-04T08:18:50Z

profiler/profiler_test.go

@@ -17,6 +17,7 @@ import (

 	"github.com/stretchr/testify/assert"
 	"github.com/stretchr/testify/require"
+	"gopkg.in/DataDog/dd-trace-go.v1/internal/log"


Done in bc28e2a - would you be able to explain the rational behind this? I'll have an easier time to remember this if I'm motivated to do it : p.

felixge · 2021-05-04T08:22:49Z

internal/log/log.go

+// UseLogger sets l as the active logger and returns the previously configured
+// logger.
+func UseLogger(l ddtrace.Logger) ddtrace.Logger {


Done in bce3c86. I considered this but figured it might be overfitting the API to a singular use case. That being said, since we only have this use case for now and it's easy to iterate on an internal package like this, why not : )?

gbbr

All good. Feel free to ignore the nit.

gbbr · 2021-05-04T08:39:56Z

profiler/profiler_test.go

@@ -59,20 +61,30 @@ func TestStart(t *testing.T) {
 	})

 	t.Run("options/GoodAPIKey/Agent", func(t *testing.T) {
+		rl := &log.RecordLogger{}


There isn't really a need for a pointer. This could well be

Suggested change

rl := &log.RecordLogger{}

var rl log.RecordLogger

internal/log: Improve API for testing I just noticed that d9472a0 caused the profiler package to always emit some log output, regardless of `go test -v` being used or not. I'm very sorry about this. IMO tests should never print to stdout unless requested. This patch is my attempt to fix this by making it easy for individual tests to capture the log output (see UseLogger, RecordLogger). I've also added DiscardLogger since it can be very convenient for tests that want to ignore log output without capturing it. Arguably RecordLogger could be used for this as well, but that would do a poor job of capturing the intend of such code.

* 'v1' of https://github.com/DataDog/dd-trace-go: Implement DD_PROFILING_OUTPUT_DIR for dev/debug (DataDog#924) contrib/go-pg/pg.v10: add INTEGRATION flag check for tests (DataDog#921) contrib/go-redis/redis.v8: optimize BeforeProcess and BeforeProcessPipeline (DataDog#920) CI: check go.sum is up-to-date (DataDog#918) README: Fix go get instructions (DataDog#913) internal/log: Improve API for testing (DataDog#916) ddtrace/tracer: add support for agent discovery endpoint, feature flags, stats & drops (DataDog#859) internal/version: bump to v1.31.0 (DataDog#910) CONTRIBUTING.md: add link to contrib/README.md (DataDog#802) profiler: Disable agentless mode for WithAPIKey (DataDog#906) contrib/Shopify/sarama: fix possible deadlock in WrapAsyncProducer (DataDog#907) contrib/database/sql.tracedConn implement driver.SessionResetter (DataDog#908) ddtrace/opentracer: consider FollowsFrom references as children (DataDog#905) ddtrace/opentracer: add support for opentracing.TracerContextWithSpanExtension (DataDog#855) ddtrace/tracer: follow noDebugStack setting when using SetTag with an error (DataDog#900) contrib/net/http: add a getter to retrieve original round tripper (DataDog#903) ddtrace/tracer: ensure Flush call is synchronous (DataDog#901)

felixge requested review from knusbaum and gbbr May 3, 2021 15:15

felixge added this to the 1.31.0 milestone May 3, 2021

felixge force-pushed the felix.geisendoerfer/profiler-log-testing branch from ef5a674 to fd28bf2 Compare May 3, 2021 15:16

gbbr reviewed May 4, 2021

View reviewed changes

felixge added 3 commits May 4, 2021 10:13

Implement RecordLogger.Logs() as getter func

8c61d7d

Move import line

bc28e2a

Make log.UseLogger return undo func

bce3c86

felixge commented May 4, 2021

View reviewed changes

felixge requested a review from gbbr May 4, 2021 08:26

gbbr approved these changes May 4, 2021

View reviewed changes

felixge merged commit 91fbc34 into v1 May 4, 2021

felixge deleted the felix.geisendoerfer/profiler-log-testing branch May 4, 2021 11:32

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

internal/log: Improve API for testing #916

internal/log: Improve API for testing #916

felixge commented May 3, 2021

gbbr May 4, 2021

felixge May 4, 2021

gbbr May 4, 2021

felixge May 4, 2021

gbbr May 4, 2021 •

edited

Loading

felixge May 4, 2021

felixge left a comment

felixge May 4, 2021

felixge May 4, 2021

felixge May 4, 2021

gbbr left a comment

gbbr May 4, 2021

internal/log: Improve API for testing #916

internal/log: Improve API for testing #916

Conversation

felixge commented May 3, 2021

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

gbbr May 4, 2021 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

felixge left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

gbbr left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

gbbr May 4, 2021 •

edited

Loading