RSDK-5278: Add context logger methods. (#3286)

Author: dgottlieb

components/arm/client.go

@@ -51,7 +51,7 @@ func NewClientFromConn(
 	}
 	clientFrame, err := c.updateKinematics(ctx, nil)
 	if err != nil {
-		logger.Errorw("error getting model for arm; will not allow certain methods", "err", err)
+		logger.CErrorw(ctx, "error getting model for arm; will not allow certain methods", "err", err)
 	} else {
 		c.model = clientFrame
 	}

components/arm/eva/eva.go

@@ -124,7 +124,7 @@ func NewEva(ctx context.Context, conf resource.Config, logger logging.Logger) (a
 		return nil, err
 	}
 
-	e.logger.Debugf("connected to eva: %v", name)
+	e.logger.CDebugf(ctx, "connected to eva: %v", name)
 
 	return e, nil
 }
@@ -372,7 +372,7 @@ func (e *eva) apiLock(ctx context.Context) error {
 func (e *eva) apiUnlock(ctx context.Context) {
 	err := e.apiRequest(ctx, "DELETE", "controls/lock", nil, true, nil)
 	if err != nil {
-		e.logger.Debugf("eva unlock failed: %s", err)
+		e.logger.CDebugf(ctx, "eva unlock failed: %s", err)
 	}
 }
 

components/arm/universalrobots/ur.go

@@ -129,14 +129,14 @@ func (ua *URArm) Close(ctx context.Context) error {
 
 	closeConn := func() {
 		if err := ua.dashboardConnection.Close(); err != nil && !errors.Is(err, net.ErrClosed) {
-			ua.logger.Errorw("error closing arm's Dashboard connection", "error", err)
+			ua.logger.CErrorw(ctx, "error closing arm's Dashboard connection", "error", err)
 		}
 		if err := ua.readRobotStateConnection.Close(); err != nil && !errors.Is(err, net.ErrClosed) {
-			ua.logger.Errorw("error closing arm's State connection", "error", err)
+			ua.logger.CErrorw(ctx, "error closing arm's State connection", "error", err)
 		}
 		if ua.connControl != nil {
 			if err := ua.connControl.Close(); err != nil && !errors.Is(err, net.ErrClosed) {
-				ua.logger.Errorw("error closing arm's control connection", "error", err)
+				ua.logger.CErrorw(ctx, "error closing arm's control connection", "error", err)
 			}
 		}
 	}
@@ -216,7 +216,7 @@ func URArmConnect(ctx context.Context, conf resource.Config, logger logging.Logg
 					if err := cancelCtx.Err(); err != nil {
 						return
 					}
-					logger.Debug("attempting to reconnect to ur arm dashboard")
+					logger.CDebug(ctx, "attempting to reconnect to ur arm dashboard")
 					time.Sleep(1 * time.Second)
 					connDashboard, err = d.DialContext(cancelCtx, "tcp", newArm.host+":29999")
 					if err == nil {
@@ -235,7 +235,7 @@ func URArmConnect(ctx context.Context, conf resource.Config, logger logging.Logg
 					}
 				}
 			} else if err != nil {
-				logger.Errorw("dashboard reader failed", "error", err)
+				logger.CErrorw(ctx, "dashboard reader failed", "error", err)
 				newArm.mu.Lock()
 				newArm.isConnected = false
 				newArm.mu.Unlock()
@@ -260,7 +260,7 @@ func URArmConnect(ctx context.Context, conf resource.Config, logger logging.Logg
 					if err := cancelCtx.Err(); err != nil {
 						return
 					}
-					logger.Debug("attempting to reconnect to ur arm 30011")
+					logger.CDebug(ctx, "attempting to reconnect to ur arm 30011")
 					connReadRobotState, err = d.DialContext(cancelCtx, "tcp", newArm.host+":30011")
 					if err == nil {
 						newArm.mu.Lock()
@@ -273,7 +273,7 @@ func URArmConnect(ctx context.Context, conf resource.Config, logger logging.Logg
 					}
 				}
 			} else if err != nil {
-				logger.Errorw("reader failed", "error", err)
+				logger.CErrorw(ctx, "reader failed", "error", err)
 				return
 			}
 		}
@@ -616,14 +616,14 @@ func reader(ctx context.Context, conn net.Conn, ua *URArm, onHaveData func()) er
 
 		switch buf[0] {
 		case 16:
-			state, err := readRobotStateMessage(buf[1:], ua.logger)
+			state, err := readRobotStateMessage(ctx, buf[1:], ua.logger)
 			if err != nil {
 				return err
 			}
 			ua.setState(state)
 			onHaveData()
 			if ua.debug {
-				ua.logger.Debugf("isOn: %v stopped: %v joints: %f %f %f %f %f %f cartesian: %f %f %f %f %f %f\n",
+				ua.logger.CDebugf(ctx, "isOn: %v stopped: %v joints: %f %f %f %f %f %f cartesian: %f %f %f %f %f %f\n",
 					state.RobotModeData.IsRobotPowerOn,
 					state.RobotModeData.IsEmergencyStopped || state.RobotModeData.IsProtectiveStopped,
 					state.Joints[0].AngleValues(),
@@ -640,31 +640,31 @@ func reader(ctx context.Context, conn net.Conn, ua *URArm, onHaveData func()) er
 					state.CartesianInfo.Rz)
 			}
 		case 20:
-			userErr := readURRobotMessage(buf, ua.logger)
+			userErr := readURRobotMessage(ctx, buf, ua.logger)
 			if userErr != nil {
 				ua.setRuntimeError(userErr)
 			}
 		case 5: // MODBUS_INFO_MESSAGE
 			data := binary.BigEndian.Uint32(buf[1:])
 			if data != 0 {
-				ua.logger.Debugf("got unexpected MODBUS_INFO_MESSAGE %d\n", data)
+				ua.logger.CDebugf(ctx, "got unexpected MODBUS_INFO_MESSAGE %d\n", data)
 			}
 		case 23: // SAFETY_SETUP_BROADCAST_MESSAGE
 		case 24: // SAFETY_COMPLIANCE_TOLERANCES_MESSAGE
 		case 25: // PROGRAM_STATE_MESSAGE
 			if len(buf) != 12 {
-				ua.logger.Debug("got bad PROGRAM_STATE_MESSAGE ??")
+				ua.logger.CDebug(ctx, "got bad PROGRAM_STATE_MESSAGE ??")
 			} else {
 				a := binary.BigEndian.Uint32(buf[1:])
 				b := buf[9]
 				c := buf[10]
 				d := buf[11]
 				if a != 4294967295 || b != 1 || c != 0 || d != 0 {
-					ua.logger.Debugf("got unknown PROGRAM_STATE_MESSAGE %v %v %v %v\n", a, b, c, d)
+					ua.logger.CDebugf(ctx, "got unknown PROGRAM_STATE_MESSAGE %v %v %v %v\n", a, b, c, d)
 				}
 			}
 		default:
-			ua.logger.Debugf("ur: unknown messageType: %v size: %d %v\n", buf[0], len(buf), buf)
+			ua.logger.CDebugf(ctx, "ur: unknown messageType: %v size: %d %v\n", buf[0], len(buf), buf)
 		}
 	}
 }

components/arm/universalrobots/ur_parser.go

@@ -2,6 +2,7 @@ package universalrobots
 
 import (
 	"bytes"
+	"context"
 	"encoding/binary"
 	"fmt"
 	"io"
@@ -154,7 +155,7 @@ type RobotState struct {
 	creationTime time.Time
 }
 
-func readRobotStateMessage(buf []byte, logger logging.Logger) (RobotState, error) {
+func readRobotStateMessage(ctx context.Context, buf []byte, logger logging.Logger) (RobotState, error) {
 	state := RobotState{
 		creationTime: time.Now(),
 	}
@@ -227,15 +228,15 @@ func readRobotStateMessage(buf []byte, logger logging.Logger) (RobotState, error
 		case 12:
 			// Tool mode info, skipping, don't think we need
 		default:
-			logger.Debugf("unknown packageType: %d size: %d content size: %d\n", packageType, sz, len(content))
+			logger.CDebugf(ctx, "unknown packageType: %d size: %d content size: %d\n", packageType, sz, len(content))
 		}
 	}
 
 	return state, nil
 }
 
 // return userErr, error.
-func readURRobotMessage(buf []byte, logger logging.Logger) error {
+func readURRobotMessage(ctx context.Context, buf []byte, logger logging.Logger) error {
 	ts := binary.BigEndian.Uint64(buf[1:])
 	// messageSource := buf[9]
 	robotMessageType := buf[10]
@@ -244,7 +245,7 @@ func readURRobotMessage(buf []byte, logger logging.Logger) error {
 
 	switch robotMessageType {
 	case 0: // text?
-		logger.Debugf("ur log: %s\n", string(buf))
+		logger.CDebugf(ctx, "ur log: %s\n", string(buf))
 
 	case 6: // error
 		robotMessageCode := binary.BigEndian.Uint32(buf)
@@ -254,7 +255,7 @@ func readURRobotMessage(buf []byte, logger logging.Logger) error {
 		robotMessageData := binary.BigEndian.Uint32(buf[16:])
 		robotCommTextMessage := string(buf[20:])
 
-		logger.Debugf("robot error! code: C%dA%d reportLevel: %d, dataType: %d, data: %d, msg: %s\n",
+		logger.CDebugf(ctx, "robot error! code: C%dA%d reportLevel: %d, dataType: %d, data: %d, msg: %s\n",
 			robotMessageCode, robotMessageArgument, robotMessageReportLevel, robotMessageDataType, robotMessageData, robotCommTextMessage)
 
 	case 3: // Version
@@ -267,16 +268,16 @@ func readURRobotMessage(buf []byte, logger logging.Logger) error {
 		bugFixVersion := binary.BigEndian.Uint32(buf[pos+2:])
 		buildNumber := binary.BigEndian.Uint32(buf[pos+8:])
 
-		logger.Debugf("UR version %v.%v.%v.%v\n", majorVersion, minorVersion, bugFixVersion, buildNumber)
+		logger.CDebugf(ctx, "UR version %v.%v.%v.%v\n", majorVersion, minorVersion, bugFixVersion, buildNumber)
 
 	case 12: // i have no idea what this is
 		if len(buf) != 9 {
-			logger.Debugf("got a weird robot message of type 12 with bad length: %d\n", len(buf))
+			logger.CDebugf(ctx, "got a weird robot message of type 12 with bad length: %d\n", len(buf))
 		} else {
 			a := binary.BigEndian.Uint64(buf)
 			b := buf[8]
 			if a != 0 || b != 1 {
-				logger.Debugf("got a weird robot message of type 12 with bad data: %v %v\n", a, b)
+				logger.CDebugf(ctx, "got a weird robot message of type 12 with bad data: %v %v\n", a, b)
 			}
 		}
 
@@ -289,7 +290,7 @@ func readURRobotMessage(buf []byte, logger logging.Logger) error {
 
 		if false {
 			// TODO(erh): this is better than sleeping in other code, be smart!!
-			logger.Debugf("KeyMessage robotMessageCode: %d robotMessageArgument: %d robotMessageTitle: %s keyTextMessage: %s\n",
+			logger.CDebugf(ctx, "KeyMessage robotMessageCode: %d robotMessageArgument: %d robotMessageTitle: %s keyTextMessage: %s\n",
 				robotMessageCode, robotMessageArgument, robotMessageTitle, keyTextMessage)
 		}
 	case 10: // ROBOT_MESSAGE_TYPE_RUNTIME_EXCEPTION
@@ -299,7 +300,7 @@ func readURRobotMessage(buf []byte, logger logging.Logger) error {
 		runtimeErr := errors.Errorf("runtime error at line: %d col: %d msg: %s", scriptLineNumber, scriptColumnNumber, msg)
 		return runtimeErr
 	default:
-		logger.Debugf("unknown robotMessageType: %d ts: %v %v\n", robotMessageType, ts, buf)
+		logger.CDebugf(ctx, "unknown robotMessageType: %d ts: %v %v\n", robotMessageType, ts, buf)
 		return nil
 	}
 

components/arm/universalrobots/ur_parser_test.go

@@ -1,6 +1,7 @@
 package universalrobots
 
 import (
+	"context"
 	"math"
 	"os"
 	"testing"
@@ -16,7 +17,7 @@ func Test1(t *testing.T) {
 	data, err := os.ReadFile(artifact.MustPath("robots/universalrobots/test1.raw"))
 	test.That(t, err, test.ShouldBeNil)
 
-	state, err := readRobotStateMessage(data, logger)
+	state, err := readRobotStateMessage(context.Background(), data, logger)
 	test.That(t, err, test.ShouldBeNil)
 
 	test.That(t, int(math.Round(state.Joints[0].AngleValues())), test.ShouldEqual, 90)

components/arm/xarm/xarm.go

@@ -166,7 +166,7 @@ func (x *xArm) Reconfigure(ctx context.Context, deps resource.Dependencies, conf
 		}
 		if x.conn != nil {
 			if err := x.conn.Close(); err != nil {
-				x.logger.Warnw("error closing old connection but will continue with reconfiguration", "error", err)
+				x.logger.CWarnw(ctx, "error closing old connection but will continue with reconfiguration", "error", err)
 			}
 		}
 		x.conn = newConn

components/audioinput/client.go

@@ -62,7 +62,7 @@ func (c *client) Read(ctx context.Context) (wave.Audio, func(), error) {
 	}
 	defer func() {
 		if err := stream.Close(ctx); err != nil {
-			c.logger.Errorw("error closing stream", "error", err)
+			c.logger.CErrorw(ctx, "error closing stream", "error", err)
 		}
 	}()
 	return stream.Next(ctx)

components/base/kinematicbase/differentialDrive.go

@@ -59,7 +59,7 @@ func wrapWithDifferentialDriveKinematics(
 	// RSDK-4131 will update this so it is no longer necessary
 	var geometry, boundingSphere spatialmath.Geometry
 	if len(geometries) > 1 {
-		ddk.logger.Warn("multiple geometries specified for differential drive kinematic base, only can use the first at this time")
+		ddk.logger.CWarn(ctx, "multiple geometries specified for differential drive kinematic base, only can use the first at this time")
 	}
 	if len(geometries) > 0 {
 		geometry = geometries[0]
@@ -68,7 +68,7 @@ func wrapWithDifferentialDriveKinematics(
 		boundingSphere, err = spatialmath.BoundingSphere(geometry)
 	}
 	if boundingSphere == nil || err != nil {
-		logger.Warn("base %s not configured with a geometry, will be considered a point mass for collision detection purposes.")
+		logger.CWarn(ctx, "base %s not configured with a geometry, will be considered a point mass for collision detection purposes.")
 		boundingSphere = spatialmath.NewPoint(r3.Vector{}, b.Name().Name)
 	}
 
@@ -197,7 +197,7 @@ func (ddk *differentialDriveKinematics) GoToInputs(ctx context.Context, desired
 				movementErr <- err
 				return
 			}
-			ddk.logger.Infof("current inputs: %v", current)
+			ddk.logger.CInfof(ctx, "current inputs: %v", current)
 		}
 		movementErr <- err
 	})
@@ -246,7 +246,7 @@ func (ddk *differentialDriveKinematics) issueCommand(ctx context.Context, curren
 	if err != nil {
 		return false, err
 	}
-	ddk.logger.Debugf("distErr: %.2f\theadingErr %.2f", distErr, headingErr)
+	ddk.logger.CDebugf(ctx, "distErr: %.2f\theadingErr %.2f", distErr, headingErr)
 	if distErr > ddk.options.GoalRadiusMM && math.Abs(headingErr) > ddk.options.HeadingThresholdDegrees {
 		// base is headed off course; spin to correct
 		err := ddk.Spin(ctx, math.Min(headingErr, ddk.options.MaxSpinAngleDeg), ddk.options.AngularVelocityDegsPerSec, nil)

components/base/kinematicbase/ptgKinematics.go

@@ -64,7 +64,7 @@ func wrapWithPTGKinematics(
 
 	baseTurningRadiusMeters := properties.TurningRadiusMeters
 
-	logger.Infof(
+	logger.CInfof(ctx,
 		"using baseMillimetersPerSecond %f and baseTurningRadius %f for PTG base kinematics",
 		baseMillimetersPerSecond,
 		baseTurningRadiusMeters,
@@ -140,7 +140,7 @@ func (ptgk *ptgBaseKinematics) GoToInputs(ctx context.Context, inputs []referenc
 		ptgk.inputLock.Unlock()
 	}()
 
-	ptgk.logger.Debugf("GoToInputs going to %v", inputs)
+	ptgk.logger.CDebugf(ctx, "GoToInputs going to %v", inputs)
 
 	selectedPTG := ptgk.ptgs[int(math.Round(inputs[ptgIndex].Value))]
 	selectedTraj, err := selectedPTG.Trajectory(inputs[trajectoryIndexWithinPTG].Value, inputs[distanceAlongTrajectoryIndex].Value)
@@ -170,7 +170,7 @@ func (ptgk *ptgBaseKinematics) GoToInputs(ctx context.Context, inputs []referenc
 		// 1) this is the first iteration of the loop, or
 		// 2) either of the linear or angular velocities has changed
 		if i == 0 || !(linVel.ApproxEqual(lastLinVel) && angVel.ApproxEqual(lastAngVel)) {
-			ptgk.logger.Debugf(
+			ptgk.logger.CDebugf(ctx,
 				"setting velocity to linear %v angular %v and running velocity step for %s",
 				linVel,
 				angVel,
@@ -192,7 +192,7 @@ func (ptgk *ptgBaseKinematics) GoToInputs(ctx context.Context, inputs []referenc
 			lastAngVel = angVel
 		}
 		if !utils.SelectContextOrWait(ctx, timestep) {
-			ptgk.logger.Debug(ctx.Err().Error())
+			ptgk.logger.CDebug(ctx, ctx.Err().Error())
 			// context cancelled
 			break
 		}

components/base/sensorcontrolled/sensorcontrolled.go

@@ -129,7 +129,7 @@ func (sb *sensorBase) Reconfigure(ctx context.Context, deps resource.Dependencie
 		if err == nil && props.OrientationSupported {
 			// return first sensor that does not error that satisfies the properties wanted
 			sb.orientation = ms
-			sb.logger.Infof("using sensor %s as orientation sensor for base", sb.orientation.Name().ShortName())
+			sb.logger.CInfof(ctx, "using sensor %s as orientation sensor for base", sb.orientation.Name().ShortName())
 			break
 		}
 	}
@@ -139,7 +139,7 @@ func (sb *sensorBase) Reconfigure(ctx context.Context, deps resource.Dependencie
 		if err == nil && props.AngularVelocitySupported && props.LinearVelocitySupported {
 			// return first sensor that does not error that satisfies the properties wanted
 			sb.velocities = ms
-			sb.logger.Infof("using sensor %s as velocity sensor for base", sb.velocities.Name().ShortName())
+			sb.logger.CInfof(ctx, "using sensor %s as velocity sensor for base", sb.velocities.Name().ShortName())
 			break
 		}
 	}