Repository: scionproto/scion
Pull request #4201 (2022-05-27 14:27:33)

refactor: remove logger struct field from BFD
remove embedded logger and move to logger from context

GitOrigin-RevId: 710329ccfc28e832ed8e948bb74e2de90661d141

<!-- Reviewable:start -->
---
This change is [<img src="https://reviewable.io/review_button.svg" height="34" align="absmiddle" alt="Reviewable"/>](https://reviewable.io/reviews/scionproto/scion/4201)
<!-- Reviewable:end -->



Patch:
diff --git a/router/bfd/BUILD.bazel b/router/bfd/BUILD.bazel
index 20406beec..eb684bb82 100644
--- a/router/bfd/BUILD.bazel
+++ b/router/bfd/BUILD.bazel
@@ -32,6 +32,7 @@ go_test(
     ],
     embed = [":go_default_library"],
     deps = [
+        "//pkg/log:go_default_library",
         "//pkg/log/testlog:go_default_library",
         "//router/bfd/mock_bfd:go_default_library",
         "@com_github_golang_mock//gomock:go_default_library",
diff --git a/router/bfd/session.go b/router/bfd/session.go
index 50b06c29d..d5a06d4f8 100644
--- a/router/bfd/session.go
+++ b/router/bfd/session.go
@@ -15,6 +15,7 @@
 package bfd
 
 import (
+	"context"
 	"fmt"
 	"math"
 	"sync"
@@ -117,9 +118,6 @@ type Session struct {
 	// must be non-zero.
 	DetectMult layers.BFDDetectMultiplier
 
-	// Logger to which the session should send logging entries. If nil, logging is disabled.
-	Logger log.Logger
-
 	// ReceiveQueueSize is the size of the Session's receive messages queue. The default is 0,
 	// but this is often not desirable as writing to the Session's message queue will block
 	// until the session is ready to read it.
@@ -157,10 +155,10 @@ type Session struct {
 	// If a metric is not initialized, it is not reported.
 	Metrics Metrics
 
-	// testingLogs means that more logs are generated, specifically, logs about
+	// testLogger is set if more logs should be generated, specifically, logs about
 	// periodic events that would in production environment clog the logs. Use
-	// this option only in tests.
-	testingLogs bool
+	// this field only in tests.
+	testLogger log.Logger
 }
 
 func (s *Session) String() string {
@@ -172,7 +170,8 @@ func (s *Session) String() string {
 // packets on the point to point link.
 //
 // Run must only be called once.
-func (s *Session) Run() error {
+func (s *Session) Run(ctx context.Context) error {
+	logger := log.FromCtx(ctx)
 	if err := s.runOnceCheck(); err != nil {
 		return err
 	}
@@ -217,9 +216,9 @@ MainLoop:
 				bfdIntervalToDuration(msg.DesiredMinTxInterval))
 			detectionTimer.Reset(detectionTime)
 
-			if s.testingLogs {
-				s.debug("heartbeat received", "desired_min_tx_interval", msg.DesiredMinTxInterval,
-					"required_min_rx_interval", msg.RequiredMinRxInterval)
+			if s.testLogger != nil {
+				s.testLogger.Debug("heartbeat received", "desired_min_tx_interval",
+					msg.DesiredMinTxInterval, "required_min_rx_interval", msg.RequiredMinRxInterval)
 			}
 			if s.Metrics.PacketsReceived != nil {
 				s.Metrics.PacketsReceived.Add(1)
@@ -229,14 +228,14 @@ MainLoop:
 			s.remoteMinRxInterval = bfdIntervalToDuration(msg.RequiredMinRxInterval)
 			if s.getRemoteDiscriminator() == 0 {
 				s.setRemoteDiscriminator(msg.MyDiscriminator)
-				s.debug("Bootstrapped")
+				logger.Debug("Bootstrapped")
 			}
 
 			// If we transitioned out of the down state, we cancel the current send timer
 			// (because it might send too late to keep the session up) and set up a new
 			// send timer based on the remote's preferences.
 			oldState := s.getLocalState()
-			s.transition(event(s.remoteState))
+			s.transition(ctx, event(s.remoteState))
 			if oldState == stateDown && s.getLocalState() != stateDown {
 				s.desiredMinTXInterval = s.DesiredMinTxInterval
 				// Cancel any pending send to accelerate the timer.
@@ -265,12 +264,12 @@ MainLoop:
 			}
 
 			if err := s.Sender.Send(pkt); err != nil {
-				s.debug("error sending message", "err", err)
+				logger.Debug("error sending message", "err", err)
 				continue
 			}
-			if s.testingLogs {
-				s.debug("heartbeat sent", "desired_min_tx_interval", pkt.DesiredMinTxInterval,
-					"required_min_rx_interval", pkt.RequiredMinRxInterval)
+			if s.testLogger != nil {
+				s.testLogger.Debug("heartbeat sent", "desired_min_tx_interval",
+					pkt.DesiredMinTxInterval, "required_min_rx_interval", pkt.RequiredMinRxInterval)
 			}
 			if s.Metrics.PacketsSent != nil {
 				s.Metrics.PacketsSent.Add(1)
@@ -280,7 +279,7 @@ MainLoop:
 			// other branch wants to stop this timer, it can assume it hasn't been drained.
 			detectionTimer.Reset(defaultDetectionTimeout)
 
-			s.transition(eventTimer)
+			s.transition(ctx, eventTimer)
 			s.setRemoteDiscriminator(0)
 			if s.getLocalState() == stateDown {
 				// Change the desired interval back to the default transmission interval, to
@@ -344,8 +343,8 @@ func (s *Session) computeNextSendInterval() time.Duration {
 // while Run is executed.
 func (s *Session) IsUp() bool {
 	up := s.getLocalState() == stateUp
-	if s.testingLogs {
-		s.debug("IsUp called", "up", up)
+	if s.testLogger != nil {
+		s.testLogger.Debug("IsUp called", "up", up)
 	}
 	return up
 }
@@ -376,7 +375,7 @@ func (s *Session) setRemoteDiscriminator(d layers.BFDDiscriminator) {
 	s.remoteDiscriminator = d
 }
 
-// ReceiveMessage validates a message and enques it for processing.
+// ReceiveMessage validates a message and enqueues it for processing.
 // Callers pass the message received from the network.
 // The actual processing of the messages is asynchronous; the relevant message
 // content is passed over a channel and the Run method continuously processes
@@ -390,8 +389,8 @@ func (s *Session) ReceiveMessage(msg *layers.BFD) {
 
 	discard, discardReason := shouldDiscard(msg)
 	if discard {
-		if discardReason != "" && s.Logger != nil {
-			s.Logger.Debug(discardReason) // no session identifier to avoid data race
+		if discardReason != "" && s.testLogger != nil {
+			s.testLogger.Debug(discardReason) // no session identifier to avoid data race
 		}
 		return
 	}
@@ -428,19 +427,14 @@ func (s *Session) initMessages() {
 	})
 }
 
-// debug logs a debug message if a logger is configured.
-func (s *Session) debug(msg string, ctx ...interface{}) {
-	if s.Logger != nil {
-		s.Logger.Debug(msg, append([]interface{}{"session", s}, ctx...)...)
-	}
-}
-
-func (s *Session) transition(e event) {
+func (s *Session) transition(ctx context.Context, e event) {
 	// The only writer is the single Run method which also calls this, so we don't care
 	// about making the state transition a transaction.
+
+	logger := log.FromCtx(ctx)
 	newState := transition(s.getLocalState(), e)
 	if newState != s.localState {
-		s.debug(fmt.Sprintf("Transitioned from state %v to state %v on event %v",
+		logger.Debug(fmt.Sprintf("Transitioned from state %v to state %v on event %v",
 			s.localState, newState, e))
 		s.setLocalState(newState)
 		if s.Metrics.Up != nil {
diff --git a/router/dataplane.go b/router/dataplane.go
index 6b49f8a7d..e1892d7a9 100644
--- a/router/dataplane.go
+++ b/router/dataplane.go
@@ -68,7 +68,7 @@ const (
 )
 
 type bfdSession interface {
-	Run() error
+	Run(ctx context.Context) error
 	ReceiveMessage(*layers.BFD)
 	IsUp() bool
 }
@@ -309,7 +309,6 @@ func (d *DataPlane) addBFDController(ifID uint16, s *bfdSend, cfg control.BFD,
 	d.bfdSessions[ifID] = &bfd.Session{
 		Sender:                s,
 		DetectMult:            layers.BFDDetectMultiplier(cfg.DetectMult),
-		Logger:                log.New("component", "BFD"),
 		DesiredMinTxInterval:  cfg.DesiredMinTxInterval,
 		RequiredMinRxInterval: cfg.RequiredMinRxInterval,
 		LocalDiscriminator:    disc,
@@ -507,7 +506,7 @@ func (d *DataPlane) Run(ctx context.Context) error {
 	for k, v := range d.bfdSessions {
 		go func(ifID uint16, c bfdSession) {
 			defer log.HandlePanic()
-			if err := c.Run(); err != nil && err != bfd.AlreadyRunning {
+			if err := c.Run(ctx); err != nil && err != bfd.AlreadyRunning {
 				log.Error("BFD session failed to start", "ifID", ifID, "err", err)
 			}
 		}(k, v)


Test patch:
diff --git a/router/bfd/common_test.go b/router/bfd/common_test.go
index 8d5858204..d4ef84fc2 100644
--- a/router/bfd/common_test.go
+++ b/router/bfd/common_test.go
@@ -17,11 +17,10 @@ package bfd_test
 import "github.com/scionproto/scion/router/bfd"
 
 type sessionTestCase struct {
-	sessionA       *bfd.Session
-	sessionB       *bfd.Session
-	expectedUpA    bool
-	expectedUpB    bool
-	disableLogging bool
+	sessionA    *bfd.Session
+	sessionB    *bfd.Session
+	expectedUpA bool
+	expectedUpB bool
 
 	// testBehavior runs after sessions are set up, and chooses whether to take links down or
 	// wait.
diff --git a/router/bfd/export_test.go b/router/bfd/export_test.go
index df2d99eb9..a376336b4 100644
--- a/router/bfd/export_test.go
+++ b/router/bfd/export_test.go
@@ -14,6 +14,8 @@
 
 package bfd
 
+import "github.com/scionproto/scion/pkg/log"
+
 const (
 	MinJitter            = minJitter
 	MinJitterDetectMult1 = minJitterDetectMult1
@@ -47,6 +49,6 @@ type (
 	Event                    = event
 )
 
-func (s *Session) TestingLogs(enable bool) {
-	s.testingLogs = enable
+func (s *Session) SetLogger(logger log.Logger) {
+	s.testLogger = logger
 }
diff --git a/router/bfd/metrics_test.go b/router/bfd/metrics_test.go
index d83001a82..023e0c6a6 100644
--- a/router/bfd/metrics_test.go
+++ b/router/bfd/metrics_test.go
@@ -15,6 +15,7 @@
 package bfd_test
 
 import (
+	"context"
 	"sync"
 	"testing"
 	"time"
@@ -24,7 +25,6 @@ import (
 	"github.com/stretchr/testify/assert"
 	"github.com/stretchr/testify/require"
 
-	"github.com/scionproto/scion/pkg/log/testlog"
 	"github.com/scionproto/scion/router/bfd"
 )
 
@@ -39,7 +39,6 @@ func TestMetrics(t *testing.T) {
 		DetectMult:            1,
 		DesiredMinTxInterval:  200 * time.Millisecond,
 		RequiredMinRxInterval: 100 * time.Millisecond,
-		Logger:                testlog.NewLogger(t).New("session", "a"),
 		LocalDiscriminator:    1,
 		ReceiveQueueSize:      10,
 		Metrics: bfd.Metrics{
@@ -54,7 +53,6 @@ func TestMetrics(t *testing.T) {
 		DetectMult:            1,
 		DesiredMinTxInterval:  200 * time.Millisecond,
 		RequiredMinRxInterval: 100 * time.Millisecond,
-		Logger:                testlog.NewLogger(t).New("session", "b"),
 		LocalDiscriminator:    2,
 		ReceiveQueueSize:      10,
 	}
@@ -68,13 +66,13 @@ func TestMetrics(t *testing.T) {
 	wg.Add(2)
 	go func() {
 		defer wg.Done()
-		err := sessionA.Run()
+		err := sessionA.Run(context.Background())
 		require.NoError(t, err)
 	}()
 
 	go func() {
 		defer wg.Done()
-		err := sessionB.Run()
+		err := sessionB.Run(context.Background())
 		require.NoError(t, err)
 	}()
 
diff --git a/router/bfd/session_test.go b/router/bfd/session_test.go
index be022f4fa..3b094e8ac 100644
--- a/router/bfd/session_test.go
+++ b/router/bfd/session_test.go
@@ -15,6 +15,7 @@
 package bfd_test
 
 import (
+	"context"
 	"fmt"
 	"math"
 	"sync"
@@ -25,6 +26,7 @@ import (
 	"github.com/stretchr/testify/assert"
 	"github.com/stretchr/testify/require"
 
+	"github.com/scionproto/scion/pkg/log"
 	"github.com/scionproto/scion/pkg/log/testlog"
 	"github.com/scionproto/scion/router/bfd"
 )
@@ -263,32 +265,6 @@ func TestSession(t *testing.T) {
 				time.Sleep(2 * time.Second)
 			},
 		},
-		"run without logging (bootstrapped)": {
-			sessionA: &bfd.Session{
-				DetectMult:            1,
-				DesiredMinTxInterval:  200 * time.Millisecond,
-				RequiredMinRxInterval: 100 * time.Millisecond,
-				LocalDiscriminator:    1,
-				RemoteDiscriminator:   2,
-				ReceiveQueueSize:      10,
-			},
-			sessionB: &bfd.Session{
-				DetectMult:            1,
-				DesiredMinTxInterval:  200 * time.Millisecond,
-				RequiredMinRxInterval: 100 * time.Millisecond,
-				LocalDiscriminator:    2,
-				RemoteDiscriminator:   1,
-				ReceiveQueueSize:      10,
-			},
-			expectedUpA: true,
-			expectedUpB: true,
-			testBehavior: func(linkAToB, linkBToA *redirectSender) {
-				linkAToB.Sending(true)
-				linkBToA.Sending(true)
-				time.Sleep(2 * time.Second)
-			},
-			disableLogging: true,
-		},
 	}
 
 	for name, tc := range testCases {
@@ -303,27 +279,25 @@ func sessionSubtest(name string, tc *sessionTestCase) func(t *testing.T) {
 
 		linkAToB := &redirectSender{Destination: tc.sessionB}
 		linkBToA := &redirectSender{Destination: tc.sessionA}
-
 		tc.sessionA.Sender = linkAToB
 		tc.sessionB.Sender = linkBToA
-		if !tc.disableLogging {
-			tc.sessionA.Logger = testlog.NewLogger(t).New("session", "a")
-			tc.sessionA.TestingLogs(true)
-			tc.sessionB.Logger = testlog.NewLogger(t).New("session", "b")
-			tc.sessionB.TestingLogs(true)
-		}
+
+		loggerA := testlog.NewLogger(t).New("session", "loggerA")
+		loggerB := testlog.NewLogger(t).New("session", "loggerB")
+		tc.sessionA.SetLogger(loggerA)
+		tc.sessionB.SetLogger(loggerB)
 
 		var wg sync.WaitGroup
 		wg.Add(2)
 		go func() {
 			defer wg.Done()
-			err := tc.sessionA.Run()
+			err := tc.sessionA.Run(log.CtxWith(context.Background(), loggerA))
 			require.NoError(t, err)
 		}()
 
 		go func() {
 			defer wg.Done()
-			err := tc.sessionB.Run()
+			err := tc.sessionB.Run(log.CtxWith(context.Background(), loggerB))
 			require.NoError(t, err)
 		}()
 
@@ -345,33 +319,35 @@ func TestSessionDebootstrap(t *testing.T) {
 	//
 	// We check this by having a session A1 be up initially, crashing (simulated by blocking its
 	// forwarding), and coming up with a different local discriminator as session A2.
+
 	sessionA1 := &bfd.Session{
 		DetectMult:            1,
 		DesiredMinTxInterval:  200 * time.Millisecond,
 		RequiredMinRxInterval: 100 * time.Millisecond,
-		Logger:                testlog.NewLogger(t).New("session", "a1"),
 		LocalDiscriminator:    1234,
 		ReceiveQueueSize:      10,
 	}
-	sessionA1.TestingLogs(true)
 	sessionA2 := &bfd.Session{
 		DetectMult:            1,
 		DesiredMinTxInterval:  200 * time.Millisecond,
 		RequiredMinRxInterval: 100 * time.Millisecond,
-		Logger:                testlog.NewLogger(t).New("session", "a2"),
 		LocalDiscriminator:    4321,
 		ReceiveQueueSize:      10,
 	}
-	sessionA2.TestingLogs(true)
 	sessionB := &bfd.Session{
 		DetectMult:            1,
 		DesiredMinTxInterval:  200 * time.Millisecond,
 		RequiredMinRxInterval: 100 * time.Millisecond,
-		Logger:                testlog.NewLogger(t).New("session", "b"),
 		LocalDiscriminator:    2,
 		ReceiveQueueSize:      10,
 	}
-	sessionB.TestingLogs(true)
+	loggerA1 := testlog.NewLogger(t).New("session", "loggerA1")
+	loggerA2 := testlog.NewLogger(t).New("session", "loggerA2")
+	loggerB := testlog.NewLogger(t).New("session", "loggerB")
+
+	sessionA1.SetLogger(loggerA1)
+	sessionA2.SetLogger(loggerA2)
+	sessionB.SetLogger(loggerB)
 
 	linkA1ToB := &redirectSender{Destination: sessionB}
 	linkA2ToB := &redirectSender{Destination: sessionB}
@@ -386,13 +362,13 @@ func TestSessionDebootstrap(t *testing.T) {
 
 	go func() {
 		defer wg.Done()
-		err := sessionA1.Run()
+		err := sessionA1.Run(log.CtxWith(context.Background(), loggerA1))
 		require.NoError(t, err)
 	}()
 
 	go func() {
 		defer wg.Done()
-		err := sessionB.Run()
+		err := sessionB.Run(log.CtxWith(context.Background(), loggerB))
 		require.NoError(t, err)
 	}()
 
@@ -410,7 +386,7 @@ func TestSessionDebootstrap(t *testing.T) {
 	// Router A "restarts", this time A2 starts with a different local discriminator.
 	go func() {
 		defer wg.Done()
-		err := sessionA2.Run()
+		err := sessionA2.Run(log.CtxWith(context.Background(), loggerA2))
 		require.NoError(t, err)
 	}()
 	linkBToA.SetDestination(sessionA2)
@@ -505,7 +481,11 @@ func TestSessionRun(t *testing.T) {
 	}
 	for name, tc := range testCases {
 		t.Run(name, func(t *testing.T) {
-			assert.Error(t, tc.session.Run())
+			logger := testlog.NewLogger(t)
+			tc.session.SetLogger(logger)
+			assert.Error(t,
+				tc.session.Run(log.CtxWith(context.Background(), logger)),
+			)
 		})
 	}
 }
@@ -519,15 +499,16 @@ func TestSessionRunMultiple(t *testing.T) {
 		RemoteDiscriminator:   2,
 		Sender:                &redirectSender{},
 	}
-
+	logger := testlog.NewLogger(t)
+	session.SetLogger(logger)
 	go func() {
-		err := session.Run()
+		err := session.Run(log.CtxWith(context.Background(), logger))
 		require.NoError(t, err)
 	}()
 	time.Sleep(200 * time.Millisecond)
 	err := session.Close()
 	require.NoError(t, err)
-	err = session.Run()
+	err = session.Run(log.CtxWith(context.Background(), logger))
 	assert.Error(t, err)
 }
 
@@ -540,14 +521,13 @@ func TestSessionRunInit(t *testing.T) {
 		LocalDiscriminator:    1,
 		RemoteDiscriminator:   2,
 		Sender:                &redirectSender{},
-		Logger:                testlog.NewLogger(t),
 	}
-	session.TestingLogs(true)
-
+	logger := testlog.NewLogger(t)
+	session.SetLogger(logger)
 	barrier := make(chan struct{})
 
 	go func() {
-		err := session.Run()
+		err := session.Run(log.CtxWith(context.Background(), logger))
 		assert.NoError(t, err)
 		close(barrier)
 	}()