RSDK-6473 - Create all graph node loggers before errors (viamrobotics#3466)

Author: cheukt

resource/graph_node.go

@@ -111,12 +111,19 @@ func (w *GraphNode) Resource() (Resource, error) {
 	return w.current, nil
 }
 
-// SetLogger associates a logger object with this resource node. This is expected to be the logger
-// passed into the `Constructor` when registering component resources.
-func (w *GraphNode) SetLogger(logger logging.Logger) {
+// InitializeLogger initializes the logger object associated with this resource node.
+func (w *GraphNode) InitializeLogger(parent logging.Logger, subname string, level logging.Level) {
+	logger := parent.Sublogger(subname)
+	logger.SetLevel(level)
 	w.logger = logger
 }
 
+// Logger returns the logger object associated with this resource node. This is expected to be the logger
+// passed into the `Constructor` when registering resources.
+func (w *GraphNode) Logger() logging.Logger {
+	return w.logger
+}
+
 // SetLogLevel changes the log level of the logger (if available). Processing configs is the main
 // entry point for changing log levels. Which will affect whether models making log calls are
 // suppressed or not.

robot/impl/local_robot.go

@@ -643,17 +643,14 @@ func (r *localRobot) newResource(
 		}
 	}
 
-	resLogger := r.logger.Sublogger(conf.ResourceName().String())
-	resLogger.SetLevel(conf.LogConfiguration.Level)
-	gNode.SetLogger(resLogger)
 	if resInfo.Constructor != nil {
-		return resInfo.Constructor(ctx, deps, conf, resLogger)
+		return resInfo.Constructor(ctx, deps, conf, gNode.Logger())
 	}
 	if resInfo.DeprecatedRobotConstructor == nil {
 		return nil, errors.Errorf("invariant: no constructor for %q", conf.API)
 	}
 	r.logger.CWarnw(ctx, "using deprecated robot constructor", "api", resName.API, "model", conf.Model)
-	return resInfo.DeprecatedRobotConstructor(ctx, r, conf, resLogger)
+	return resInfo.DeprecatedRobotConstructor(ctx, r, conf, gNode.Logger())
 }
 
 func (r *localRobot) updateWeakDependents(ctx context.Context) {

robot/impl/resource_manager.go

@@ -508,13 +508,18 @@ func (manager *resourceManager) completeConfig(
 				)
 				continue
 			}
+			if gNode.IsUninitialized() {
+				gNode.InitializeLogger(
+					manager.logger, fromRemoteNameToRemoteNodeName(remConf.Name).String(), manager.logger.GetLevel(),
+				)
+			}
 			// this is done in config validation but partial start rules require us to check again
 			if _, err := remConf.Validate(""); err != nil {
 				gNode.LogAndSetLastError(
 					fmt.Errorf("remote config validation error: %w", err), "remote", remConf.Name)
 				continue
 			}
-			rr, err := manager.processRemote(ctx, *remConf)
+			rr, err := manager.processRemote(ctx, *remConf, gNode)
 			if err != nil {
 				gNode.LogAndSetLastError(
 					fmt.Errorf("error connecting to remote: %w", err), "remote", remConf.Name)
@@ -573,14 +578,18 @@ func (manager *resourceManager) completeConfig(
 			if !(resName.API.IsComponent() || resName.API.IsService()) {
 				return
 			}
+
 			var verb string
+			conf := gNode.Config()
 			if gNode.IsUninitialized() {
 				verb = "configuring"
+				gNode.InitializeLogger(
+					manager.logger, resName.String(), conf.LogConfiguration.Level,
+				)
 			} else {
 				verb = "reconfiguring"
 			}
 			manager.logger.CDebugw(ctx, fmt.Sprintf("now %s resource", verb), "resource", resName)
-			conf := gNode.Config()
 
 			// this is done in config validation but partial start rules require us to check again
 			if _, err := conf.Validate("", resName.API.Type.Name); err != nil {
@@ -722,10 +731,11 @@ func cleanAppImageEnv() error {
 func (manager *resourceManager) processRemote(
 	ctx context.Context,
 	config config.Remote,
+	gNode *resource.GraphNode,
 ) (*client.RobotClient, error) {
 	dialOpts := remoteDialOptions(config, manager.opts)
 	manager.logger.CDebugw(ctx, "connecting now to remote", "remote", config.Name)
-	robotClient, err := dialRobotClient(ctx, config, manager.logger, dialOpts...)
+	robotClient, err := dialRobotClient(ctx, config, gNode.Logger(), dialOpts...)
 	if err != nil {
 		if errors.Is(err, rpc.ErrInsecureWithCredentials) {
 			if manager.opts.fromCommand {

robot/impl/resource_manager_test.go

@@ -1301,17 +1301,19 @@ func TestConfigRemoteAllowInsecureCreds(t *testing.T) {
 		tlsConfig: remoteTLSConfig,
 	}, logger)
 
-	_, err = manager.processRemote(context.Background(), remote)
+	gNode := resource.NewUninitializedNode()
+	gNode.InitializeLogger(logger, "remote", logger.GetLevel())
+	_, err = manager.processRemote(context.Background(), remote, gNode)
 	test.That(t, err, test.ShouldNotBeNil)
 	test.That(t, err.Error(), test.ShouldContainSubstring, "authentication required")
 
 	remote.Auth.Entity = "wrong"
-	_, err = manager.processRemote(context.Background(), remote)
+	_, err = manager.processRemote(context.Background(), remote, gNode)
 	test.That(t, err, test.ShouldNotBeNil)
 	test.That(t, err.Error(), test.ShouldContainSubstring, "authentication required")
 
 	remote.Auth.Entity = options.FQDN
-	_, err = manager.processRemote(context.Background(), remote)
+	_, err = manager.processRemote(context.Background(), remote, gNode)
 	test.That(t, err, test.ShouldNotBeNil)
 	test.That(t, err.Error(), test.ShouldContainSubstring, "authentication required")
 }