RSDK-12369: TCP mode: don't get stuck on checkReady if module crashes after 100ms

[aldenh-viam]

If a module starts up in TCP mode and crashes after 100ms (module exited too quickly after attempted startup), the startup process will proceed and get stuck on checkReady, which repeatedly tries making a grpc Ready call until it either succeeds or times out in ~5 minutes (it does not know that the process has already exited). OUE cannot restart the module at this stage, because it's waiting on the same ModManager lock that checkReady is holding: Add, Reconfigure

This PR adds a background watcher to checkReady that will help it exit early if the process exits early.

[aldenh-viam]

Basically all I'm trying to do is check errors.Is(m.process.Status(), os.ErrProcessDone) before each retry, and if true, cancel ctxTimeout. A background goroutine for this feels slightly excessive, but also seems to be the simplest option compared to:

1. manually retrying here in a nested loop (instead of using grpc_retry.WithMax).
2. having ManagedProcess cancel the context being used here if the process exits abruptly.

[cheukt]

ya, I like 1 because then we wouldn't need an extra goroutine, but the responsiveness allowed by the current setup is better I think

[aldenh-viam]

Sure, I can change it to manually retry to get rid of the extra goroutine. I guess recreating grpc's internal backoff here is unnecessary, and I can just have it retry say every 2s?

It will be something like:

	for {
		for {
			if errors.Is(m.process.Status(), os.ErrProcessDone) {
				cancelFunc()
			}
			resp, err := m.client.Ready(ctxTimeout, req)
			// if err == not yet available { sleep 2s }
		}
	...

[cheukt]

do you know if the Ready request retries at all? like if the tcp server just took a bit longer than expected to come online, would this code work or would we still stall out here?

[aldenh-viam]

The m.client.Ready with the grpc_retry.WithMax(5000) CallOption means it will internally Retry 5000 times or until the context is cancelled. The default number of retry attempts is 5 if you don't specify that CallOption. minor correction: this is go-grpc-middleware's retry that's implemented via interceptors with a linear 50ms with +-10% backoff. By default it's deactivated (doesn't retry). gRPC-go internally retries 5x if dialing fails.

If the TCP server is fine, but just takes a moment to start up (e.g. if the module has a long setup process), there is no change to the existing behavior with this PR.

[cheukt]

ya, I like 1 because then we wouldn't need an extra goroutine, but the responsiveness allowed by the current setup is better I think

[cheukt]

will this solve the issue reported? I thought part of the issue was that tcp mode wasn't getting picked up

[aldenh-viam]

The report was "tcp_mode taking a long time to be respected", not that it it never gets picked up. At least for my repro on the Windows machine, toggling TCP mode on/off with this change now gets picked up asap.

[cheukt]

chatted offline, if statement was removed and design/change makes sense

[aldenh-viam]

If statement in question is this: https://github.com/viamrobotics/rdk/compare/c1eb6b6d50e77ebe8a60da2339c7169844a7a52d..58cd3261b1a215efdc5b0407a36eb4409b744293

Initially missed because modlib.CheckSocketOwner in UNIX mode on Linux causes the it to wait until the .sock is created so we're less likely to get stuck on checkReady, but on Windows it always returns err==nil causing it to break early.

rdk/module/modmanager/module.go

Lines 270 to 278 in 1c3e1f9

	err = modlib.CheckSocketOwner(m.addr)
	if errors.Is(err, fs.ErrNotExist) {
	continue
	}
	if err != nil {
	return errors.WithMessage(err, "module startup failed")
	}
	}
	break

[aldenh-viam]

Trying to figure out why tests are flaking with the latest changes. They pass on my machine & changes look good on the Windows dev machines.

[cheukt]

generally looks good, can you add a test?

[cheukt]

logic looks good, just have a question around how it's getting surfaced

[cheukt]

don't think we need this assertion (the assertion on the error should be enough). mostly concerned with the possibility of a flaky test even when the time given is generous (definitely have run into that before)

[aldenh-viam]

Is there a good way to test that the error is returned shortly after the process unexpectedly exits rather than after 5 mins (DefaultModuleStartupTimeout)? The module used for this test crashes after 2s, so I'd expect it to return with error <1s after that.

[cheukt]

I don't think so - the issue is that the test process/scheduler could sometimes randomly pause execution of the test, which will cause flakes. The best assertion is that the error returned is different from one that would return after 5 mins.

[aldenh-viam]

Oh you're right; if it fails due to DefaultModuleStartupTimeout the error returned is error while waiting for module to be ready test: context deadline exceeded, so this assert is not needed.

[cheukt]

thanks for adding this extra note!

[cheukt]

shouldn't we return the info log as an error instead of a context canceled error? seems like a bit of an obfuscation

[aldenh-viam]

checkReady's two callers (startModule & attemptRestart) prefix the error with error while waiting for module to be ready *name* *err* and the fact that it's due to the module process unexpectedly exiting is also already logged. Is it worth adding another ERROR log to repeat the same info?

2025-11-13T15:59:19.020Z	INFO	rdk	impl/local_robot.go:1505	(Re)configuring robot
2025-11-13T15:59:19.020Z	INFO	rdk.modmanager.viam_rsdk12369-3	modmanager/manager.go:268	Now adding module	{"module":"viam_rsdk12369-3"}
. . .
2025-11-13T15:59:29.023Z	WARN	rdk.modmanager.viam_rsdk12369-3	utils/ticker.go:22	Waiting for module to complete startup and registration	{"module":"viam_rsdk12369-3","time_elapsed":"10s"}
(OUE) 2025-11-13T15:59:29.025Z	ERROR	rdk.modmanager.viam_rsdk12369-3	modmanager/manager.go:845	Module has unexpectedly exited.	{"module":"viam_rsdk12369-3","exit_code":1}
(checkReady) 2025-11-13T15:59:29.175Z	INFO	rdk.modmanager.viam_rsdk12369-3	modmanager/module.go:150	Module process exited unexpectedly while waiting for ready.
2025-11-13T15:59:29.176Z	INFO	rdk.modmanager.viam_rsdk12369-3	modmanager/module.go:332	Stopping module: viam_rsdk12369-3 process
2025-11-13T15:59:29.176Z	INFO	rdk.modmanager.viam_rsdk12369-3.viam_rsdk12369-3	pexec/managed_process_unix.go:100	stopping process 336248 with signal terminated
2025-11-13T15:59:29.176Z	WARN	rdk.modmanager.viam_rsdk12369-3.viam_rsdk12369-3	pexec/managed_process.go:539	Stopped module did not exit cleanly	{"err":"exit status 1"}
(checkReady's caller) 2025-11-13T15:59:29.176Z	ERROR	rdk.modmanager.viam_rsdk12369-3	modmanager/manager.go:271	Error adding module	{"module":"viam_rsdk12369-3","error":"error while waiting for module to be ready viam_rsdk12369-3: context canceled","errorVerbose":"context canceled\nerror while waiting for module to be ready viam_rsdk12369-3"}
2025-11-13T15:59:29.176Z	ERROR	rdk.resource_manager	impl/resource_manager.go:1246	error adding modules	{"error":"error while waiting for module to be ready viam_rsdk12369-3: context canceled","errorVerbose":"context canceled\nerror while waiting for module to be ready viam_rsdk12369-3"}
2025-11-13T15:59:29.176Z	INFO	rdk.modmanager.viam_rsdk12369-3	modmanager/manager.go:886	Restart context canceled, abandoning restart attempt	{"err":"context canceled"}
2025-11-13T15:59:29.177Z	INFO	rdk.modmanager	modmanager/manager.go:807	Removing module data parent directory	{"parent dir":"/home/alden/.viam/module-data/67d2e9f5-29f8-4b57-963b-c94780a53825"}
2025-11-13T15:59:29.177Z	INFO	rdk	impl/local_robot.go:1561	Robot (re)configured
2025-11-13T15:59:29.226Z	INFO	rdk	impl/local_robot.go:1505	(Re)configuring robot
2025-11-13T15:59:29.226Z	INFO	rdk.modmanager.viam_rsdk12369-3	modmanager/manager.go:268	Now adding module	{"module":"viam_rsdk12369-3"}

IMO context canceled is technically not inaccurate, because we've cancelled the checkReady context early since we noticed the process no longer exists, and therefore is not worth continuing to ping it.

Actually, this could probably even be at Debug level, because it more explains the checkReady implementation than anything.

[cheukt]

I don't mean to log m.logger.Info("Module process exited unexpectedly while waiting for ready.") as an error level log, more that the returned error should be "module process exited unexpectedly while waiting for ready." IMO or "module process exited unexpectedly so that the full message would be error while waiting for module to be ready viam_rsdk12369-3: module process exited unexpectedly