RSDK-10833 Added slow shutdown logs and TestSlowShutdownTicker test

module/modmanager/manager.go

@@ -349,7 +349,7 @@ func (mgr *Manager) startModule(ctx context.Context, mod *module) error {
 		}
 	}
 
-	cleanup := rutils.SlowStartupLogger(
+	cleanup := rutils.SlowLogger(
 		ctx, "Waiting for module to complete startup and registration", "module", mod.cfg.Name, mod.logger)
 	defer cleanup()
 
@@ -472,6 +472,10 @@ func (mgr *Manager) closeModule(mod *module, reconfigure bool) error {
 		mod.logger.Warnw("Forcing removal of module with active resources", "module", mod.cfg.Name)
 	}
 
+	cleanup := rutils.SlowLogger(
+		context.Background(), "Waiting for module to complete shutdown", "module", mod.cfg.Name, mod.logger)
+	defer cleanup()
+
 	// need to actually close the resources within the module itself before stopping
 	for res := range mod.resources {
 		_, err := mod.client.RemoveResource(context.Background(), &pb.RemoveResourceRequest{Name: res.String()})
@@ -988,7 +992,7 @@ func (mgr *Manager) attemptRestart(ctx context.Context, mod *module) error {
 	// No need to check mgr.untrustedEnv, as we're restarting the same
 	// executable we were given for initial module addition.
 
-	cleanup := rutils.SlowStartupLogger(
+	cleanup := rutils.SlowLogger(
 		ctx, "Waiting for module to complete restart and re-registration", "module", mod.cfg.Name, mod.logger)
 	defer cleanup()
 

module/testmodule/main.go

@@ -88,6 +88,18 @@ func mainWithArgs(ctx context.Context, args []string, logger logging.Logger) err
 		return err
 	}
 	<-ctx.Done()
+
+	// If this is set, sleep to catch module slow shutdown logs.
+	sleepTime := os.Getenv("VIAM_TESTMODULE_SLOW_CLOSE")
+
+	if sleepTime != "" {
+		sleepDuration, err := time.ParseDuration(sleepTime)
+		if err != nil {
+			return err
+		}
+		time.Sleep(sleepDuration)
+	}
+
 	return nil
 }
 
@@ -351,7 +363,6 @@ func newSlow(
 
 type slow struct {
 	resource.Named
-	resource.TriviallyCloseable
 	configDuration time.Duration
 }
 
@@ -360,3 +371,9 @@ func (s *slow) Reconfigure(ctx context.Context, deps resource.Dependencies, conf
 	time.Sleep(s.configDuration)
 	return nil
 }
+
+// Close does nothing but is slow.
+func (s *slow) Close(ctx context.Context) error {
+	time.Sleep(s.configDuration)
+	return nil
+}

robot/impl/local_robot.go

@@ -826,7 +826,7 @@ func (r *localRobot) updateWeakAndOptionalDependents(ctx context.Context) {
 		ctxWithTimeout, timeoutCancel := context.WithTimeout(ctx, timeout)
 		defer timeoutCancel()
 
-		cleanup := utils.SlowStartupLogger(
+		cleanup := utils.SlowLogger(
 			ctx,
 			"Waiting for internal resource to complete reconfiguration during weak/optional dependencies update",
 			"resource", resName.String(),
@@ -966,7 +966,7 @@ func (r *localRobot) updateWeakAndOptionalDependents(ctx context.Context) {
 		ctxWithTimeout, timeoutCancel := context.WithTimeout(ctx, timeout)
 		defer timeoutCancel()
 
-		cleanup := utils.SlowStartupLogger(
+		cleanup := utils.SlowLogger(
 			ctx,
 			"Waiting for resource to complete reconfiguration during weak/optional dependencies update",
 			"resource",

robot/impl/local_robot_test.go

@@ -1678,6 +1678,47 @@ func TestDependentResources(t *testing.T) {
 	test.That(t, err, test.ShouldBeNil)
 }
 
+func TestSlowShutdownTicker(t *testing.T) {
+	ctx := context.Background()
+	logger, logs := logging.NewObservedTestLogger(t)
+
+	t.Setenv("VIAM_TESTMODULE_SLOW_CLOSE", "5s")
+	slowModel := resource.NewModel("rdk", "test", "slow")
+	testPath := rtestutils.BuildTempModule(t, "module/testmodule")
+	cfg := &config.Config{
+		Modules: []config.Module{
+			{
+				Name:    "mod",
+				ExePath: testPath,
+			},
+		},
+		Components: []resource.Config{
+			{
+				Name:  "h",
+				Model: slowModel,
+				API:   generic.API,
+				Attributes: rutils.AttributeMap{
+					"config_duration": "5s",
+				},
+			},
+		},
+	}
+
+	r, err := New(ctx, cfg, nil, logger)
+	test.That(t, err, test.ShouldBeNil)
+
+	r.Close(ctx)
+
+	// Assert that if a module is taking a while to close, we will see slow logger messages.
+	testutils.WaitForAssertionWithSleep(t, time.Second, 20, func(tb testing.TB) {
+		tb.Helper()
+		test.That(tb, logs.FilterMessage("Waiting for resource to close").Len(),
+			test.ShouldBeGreaterThanOrEqualTo, 1)
+		test.That(tb, logs.FilterMessage("Waiting for module to complete shutdown").Len(),
+			test.ShouldBeGreaterThanOrEqualTo, 1)
+	})
+}
+
 func TestOrphanedResources(t *testing.T) {
 	ctx := context.Background()
 	logger, logs := logging.NewObservedTestLogger(t)

robot/impl/resource_manager.go

@@ -511,6 +511,14 @@ func (manager *resourceManager) closeResource(ctx context.Context, res resource.
 	closeCtx, cancel := context.WithTimeout(ctx, resourceCloseTimeout)
 	defer cancel()
 
+	cleanup := rutils.SlowLogger(
+		closeCtx,
+		"Waiting for resource to close",
+		"resource", res.Name().String(),
+		manager.logger,
+	)
+	defer cleanup()
+
 	allErrs := res.Close(closeCtx)
 
 	resName := res.Name()
@@ -686,7 +694,7 @@ func (manager *resourceManager) completeConfig(
 				ctxWithTimeout, timeoutCancel := context.WithTimeout(context.WithoutCancel(ctx), timeout)
 				defer timeoutCancel()
 
-				stopSlowLogger := rutils.SlowStartupLogger(
+				stopSlowLogger := rutils.SlowLogger(
 					ctx, "Waiting for resource to complete (re)configuration", "resource", resName.String(), manager.logger)
 
 				lr.reconfigureWorkers.Add(1)

utils/ticker.go

@@ -7,8 +7,8 @@ import (
 	"go.viam.com/rdk/logging"
 )
 
-// SlowStartupLogger starts a goroutine that logs every few seconds as long as the context has not timed out or was not cancelled.
-func SlowStartupLogger(ctx context.Context, msg, fieldName, fieldVal string, logger logging.Logger) func() {
+// SlowLogger starts a goroutine that logs every few seconds as long as the context has not timed out or was not cancelled.
+func SlowLogger(ctx context.Context, msg, fieldName, fieldVal string, logger logging.Logger) func() {
 	slowTicker := time.NewTicker(2 * time.Second)
 	firstTick := true