Repository: gomods/athens
Pull request #1941 (2024-04-10 09:53:01)

correcting the misuse of the context in the copyContextWithCustomTime…
…out method

<!-- 
    Welcome, Athenian! Can you do us two quick favors before you submit your PR?
    
    1. Briefly fill out the sections below. It will make it easy for us to review your code
    2. Put "[WIP]" at the beginning of your PR title if you're not ready to have this merged yet (we have a bot that will tell everyone that it's a work in progress)
-->

## What is the problem I am trying to address?

This is a fundamental error, and its misuse here prevents the correct output of debug logs in `stasher.Stash`.

https://github.com/gomods/athens/blob/a5277a3e7a8ee412c1ff9ea8e51a8a09d8e0ffb1/pkg/stash/stasher.go#L47-L51

## How is the fix applied?

output that logs:
`DEBUG[5:35PM]: saving xxx to storage...	http-method=GET http-path=xxx.info request-id=58cfecb1-df43-46b1-9b3f-cfb59e6c937b `

## What GitHub issue(s) does this PR fix or close?

<!--
    If it doesn't fix any GitHub Issues, that's ok. Can you please delete the below "Fixes #" line for us? It would help us out a lot. Thanks!

    Your PR might fix one or more GitHub issues. If so, please use the below "Fixes #<issue number>" notation below. If your PR fixes multiple issues, please put multiple lines of "Fixes #<issue number>", one for each issue. If you do that, when this PR is merged, it'll automatically close the issue(s) you reference.
-->

Fixes #

<!-- 
example: Fixes #123
-->



Patch:
diff --git a/pkg/download/protocol.go b/pkg/download/protocol.go
index b9d5945e..a6942a9c 100644
--- a/pkg/download/protocol.go
+++ b/pkg/download/protocol.go
@@ -298,7 +298,7 @@ func union(list1, list2 []string) []string {
 
 func copyContextWithCustomTimeout(ctx context.Context, timeout time.Duration) (context.Context, context.CancelFunc) {
 	ctxCopy, cancel := context.WithTimeout(context.Background(), timeout)
-	requestid.SetInContext(ctxCopy, requestid.FromContext(ctx))
-	log.SetEntryInContext(ctxCopy, log.EntryFromContext(ctx))
+	ctxCopy = requestid.SetInContext(ctxCopy, requestid.FromContext(ctx))
+	ctxCopy = log.SetEntryInContext(ctxCopy, log.EntryFromContext(ctx))
 	return ctxCopy, cancel
 }


Test patch:
diff --git a/pkg/download/protocol_test.go b/pkg/download/protocol_test.go
index 40134a49..d2f91068 100644
--- a/pkg/download/protocol_test.go
+++ b/pkg/download/protocol_test.go
@@ -17,6 +17,7 @@ import (
 	"github.com/gomods/athens/pkg/download/mode"
 	"github.com/gomods/athens/pkg/errors"
 	"github.com/gomods/athens/pkg/index/nop"
+	"github.com/gomods/athens/pkg/log"
 	"github.com/gomods/athens/pkg/module"
 	"github.com/gomods/athens/pkg/stash"
 	"github.com/gomods/athens/pkg/storage"
@@ -495,3 +496,38 @@ func (ml *mockLister) List(ctx context.Context, mod string) (*storage.RevInfo, [
 	ml.called = true
 	return nil, ml.list, ml.err
 }
+
+type testEntry struct {
+	msg string
+}
+
+var _ log.Entry = &testEntry{}
+
+func (e *testEntry) Debugf(format string, args ...any) {
+	e.msg = format
+}
+func (*testEntry) Infof(format string, args ...any)           {}
+func (*testEntry) Warnf(format string, args ...any)           {}
+func (*testEntry) Errorf(format string, args ...any)          {}
+func (*testEntry) WithFields(fields map[string]any) log.Entry { return nil }
+func (*testEntry) SystemErr(err error)                        {}
+
+func Test_copyContextWithCustomTimeout(t *testing.T) {
+	testEntry := &testEntry{}
+
+	// create a context with a logger entry
+	logctx := log.SetEntryInContext(context.Background(), testEntry)
+
+	// check the log work as expected
+	log.EntryFromContext(logctx).Debugf("first test")
+	require.Equal(t, "first test", testEntry.msg)
+
+	// use copyContextWithCustomTimeout to create a new context with a custom timeout,
+	// and the returned context should have the same logger entry
+	newCtx, cancel := copyContextWithCustomTimeout(logctx, 10*time.Second)
+	defer cancel()
+
+	// check the log work as expected
+	log.EntryFromContext(newCtx).Debugf("second test")
+	require.Equal(t, "second test", testEntry.msg)
+}