RSDK-5972: Have modular resources obey log configuration levels. (#3307)

Author: dgottlieb

module/module.go

@@ -154,6 +154,7 @@ type Module struct {
 	activeBackgroundWorkers sync.WaitGroup
 	handlers                HandlerMap
 	collections             map[resource.API]resource.APIResourceCollection[resource.Resource]
+	resLoggers              map[resource.Resource]logging.Logger
 	closeOnce               sync.Once
 	pb.UnimplementedModuleServiceServer
 }
@@ -176,6 +177,7 @@ func NewModule(ctx context.Context, address string, logger logging.Logger) (*Mod
 		ready:       true,
 		handlers:    HandlerMap{},
 		collections: map[resource.API]resource.APIResourceCollection[resource.Resource]{},
+		resLoggers:  map[resource.Resource]logging.Logger{},
 	}
 	if err := m.server.RegisterServiceServer(ctx, &pb.ModuleService_ServiceDesc, m); err != nil {
 		return nil, err
@@ -332,7 +334,8 @@ func (m *Module) AddResource(ctx context.Context, req *pb.AddResourceRequest) (*
 	if resInfo.Constructor == nil {
 		return nil, errors.Errorf("invariant: no constructor for %q", conf.API)
 	}
-	res, err := resInfo.Constructor(ctx, deps, *conf, m.logger)
+	resLogger := m.logger.Sublogger(conf.ResourceName().String())
+	res, err := resInfo.Constructor(ctx, deps, *conf, resLogger)
 	if err != nil {
 		return nil, err
 	}
@@ -343,6 +346,7 @@ func (m *Module) AddResource(ctx context.Context, req *pb.AddResourceRequest) (*
 	if !ok {
 		return nil, errors.Errorf("module cannot service api: %s", conf.API)
 	}
+	m.resLoggers[res] = resLogger
 
 	return &pb.AddResourceResponse{}, coll.Add(conf.ResourceName(), res)
 }
@@ -385,6 +389,15 @@ func (m *Module) ReconfigureResource(ctx context.Context, req *pb.ReconfigureRes
 		return nil, err
 	}
 
+	if logger, ok := m.resLoggers[res]; ok {
+		levelStr := req.GetConfig().GetLogConfiguration().GetLevel()
+		if level, err := logging.LevelFromString(levelStr); err == nil {
+			logger.SetLevel(level)
+		} else {
+			m.logger.Warnw("LogConfiguration does not contain a valid level.", "resource", res.Name().Name, "level", levelStr)
+		}
+	}
+
 	reconfErr := res.Reconfigure(ctx, deps, *conf)
 	if reconfErr == nil {
 		return &pb.ReconfigureResourceResponse{}, nil

module/testmodule/main.go

@@ -133,6 +133,25 @@ func (h *helper) DoCommand(ctx context.Context, req map[string]interface{}) (map
 			return map[string]interface{}{}, err
 		}
 		return map[string]interface{}{"path": workingDir}, nil
+	case "log":
+		level, err := logging.LevelFromString(req["level"].(string))
+		if err != nil {
+			return nil, err
+		}
+
+		msg := req["msg"].(string)
+		switch level {
+		case logging.DEBUG:
+			h.logger.Debug(msg)
+		case logging.INFO:
+			h.logger.Info(msg)
+		case logging.WARN:
+			h.logger.Warn(msg)
+		case logging.ERROR:
+			h.logger.Error(msg)
+		}
+
+		return map[string]any{}, nil
 	default:
 		return nil, fmt.Errorf("unknown command string %s", cmd)
 	}

robot/impl/resource_manager_modular_test.go

@@ -9,6 +9,7 @@ import (
 	"github.com/pkg/errors"
 	"go.viam.com/test"
 
+	"go.viam.com/rdk/components/generic"
 	"go.viam.com/rdk/components/motor"
 	"go.viam.com/rdk/components/motor/fake"
 	"go.viam.com/rdk/config"
@@ -19,6 +20,7 @@ import (
 	"go.viam.com/rdk/robot/framesystem"
 	"go.viam.com/rdk/services/motion"
 	motionBuiltin "go.viam.com/rdk/services/motion/builtin"
+	rtestutils "go.viam.com/rdk/testutils"
 	"go.viam.com/rdk/utils"
 )
 
@@ -471,3 +473,71 @@ func (m *dummyModMan) Close(ctx context.Context) error {
 	}
 	return nil
 }
+
+func TestDynamicModuleLogging(t *testing.T) {
+	modPath, err := rtestutils.BuildTempModule(t, "module/testmodule")
+	test.That(t, err, test.ShouldBeNil)
+
+	ctx := context.Background()
+	logger, observer := logging.NewObservedTestLogger(t)
+
+	helperConf := resource.Config{
+		Name:  "helper",
+		API:   generic.API,
+		Model: resource.NewModel("rdk", "test", "helper"),
+		LogConfiguration: resource.LogConfig{
+			Level: logging.INFO,
+		},
+	}
+	cfg := &config.Config{
+		Components: []resource.Config{helperConf},
+		Modules: []config.Module{{
+			Name:     "helperModule",
+			ExePath:  modPath,
+			LogLevel: "info",
+			Type:     "local",
+		}},
+	}
+
+	myRobot, err := RobotFromConfig(ctx, cfg, logger)
+	test.That(t, err, test.ShouldBeNil)
+	defer myRobot.Close(ctx)
+
+	client, err := generic.FromRobot(myRobot, "helper")
+	test.That(t, err, test.ShouldBeNil)
+	defer client.Close(ctx)
+
+	//nolint:lll
+	// Have the module log a line at info. It should appear as:
+	// 2023-12-06T15:55:32.590-0500	INFO	process.helperModule_/tmp/TestDynamicModuleLogging3790223620/001/testmodule.StdOut	pexec/managed_process.go:244
+	// \_ 2023-12-06T15:55:32.590-0500	INFO	TestModule.rdk:component:generic/helper	testmodule/main.go:147	special rare log line
+	logLine := "special rare log line"
+	testCmd := map[string]interface{}{"command": "log", "msg": logLine, "level": "info"}
+	_, err = client.DoCommand(ctx, testCmd)
+	test.That(t, err, test.ShouldBeNil)
+
+	// Our log observer should find one occurrence of the log line.
+	test.That(t, observer.FilterMessageSnippet(logLine).Len(), test.ShouldEqual, 1)
+
+	// The module is currently configured to log at info. If the module tries to log at debug,
+	// nothing new should be observed.
+	testCmd = map[string]interface{}{"command": "log", "msg": logLine, "level": "debug"}
+	_, err = client.DoCommand(ctx, testCmd)
+	test.That(t, err, test.ShouldBeNil)
+
+	test.That(t, observer.FilterMessageSnippet(logLine).Len(), test.ShouldEqual, 1)
+	test.That(t, observer.FilterMessageSnippet(logLine).FilterMessageSnippet("DEBUG").Len(), test.ShouldEqual, 0)
+
+	// Change the modular component to log at DEBUG instead of INFO.
+	cfg.Components[0].LogConfiguration.Level = logging.DEBUG
+	myRobot.Reconfigure(ctx, cfg)
+
+	// Trying to log again at DEBUG should see our log line pattern show up a second time. Now with
+	// DEBUG in the output string.
+	testCmd = map[string]interface{}{"command": "log", "msg": logLine, "level": "debug"}
+	_, err = client.DoCommand(ctx, testCmd)
+	test.That(t, err, test.ShouldBeNil)
+
+	test.That(t, observer.FilterMessageSnippet(logLine).Len(), test.ShouldEqual, 2)
+	test.That(t, observer.FilterMessageSnippet(logLine).FilterMessageSnippet("DEBUG").Len(), test.ShouldEqual, 1)
+}