Lots of "failed to wait for awaited action to change" errors on main branch

[cormacrelf]

Version = main branch. This happens quite frequently, but randomly. It's a bit more consistent for actions that take a bit longer, sometimes it will fail a few times in a row on the same action (one that takes about 3 minutes, and it fails after about 1 minute). Workaround is just to run the build again a few times and hope for the best (or just go back to v0.4.0, which I have done).

Failed to wait for awaited action to change 
Error { 
  code: Internal, 
  messages: [\"Failed to wait for awaited action to change RecvError(())\"] 
}: In SimpleSchedulerActionListener::changed getting receiver

This obviously comes from

nativelink/nativelink-scheduler/src/simple_scheduler.rs

Lines 83 to 87 in 5798761

	let action_state = self
	.action_state_result
	.changed()
	.await
	.err_tip(|| "In SimpleSchedulerActionListener::changed getting receiver")?;

nativelink/nativelink-scheduler/src/memory_awaited_action_db.rs

Lines 154 to 161 in 5798761

	let changed_fut = self.awaited_action_rx.changed().map(|r| {
	r.map_err(|e| {
	make_err!(
	Code::Internal,
	"Failed to wait for awaited action to change {e:?}"
	)
	})
	});

(And another place in that file)

I don't see any other useful logs that would tell us why the Sender half was dropped. But this comment in the lines just after the error sure seems like it's onto something:

nativelink/nativelink-scheduler/src/memory_awaited_action_db.rs

Lines 180 to 183 in 5798761

	_ = tokio::time::sleep(CLIENT_KEEPALIVE_DURATION) => {
	// If we haven't received any updates for a while, we should
	// let the database know that we are still listening to prevent
	// the action from being dropped.

Configuration is basically what I described in #963, i.e. basic_cas.json with a couple of tweaks to paths / entrypoints etc. Buck2 is in the driver's seat.

[allada]

Thanks for the report, we detected this late yesterday as well. I believe we have identified the cause and I'll try to push a fix in a bit.

It has to do with the scheduler refactor recently. When a client disconnected then reconnected, it would not hold the connection alive as active and eventually it'd get cleaned up, causing down-stream listeners to get disconnected and close the stream.