fix: Infinite logs in case of non-existent stream logs

[beingnoble03]

Description

In GetWorkflows() we use the following algo while collecting logs for a workflow.
We first sort all the streams of each shard by streamID in ASC order. Now, we call fetchStreamLogs for each workflow. Inside fetchStreamLogs, we fetch the streamLogs from each tablet. Now, we run a for loop across all the tablets we got from results (from query for fetching logs and results sorted by streamID in ASC order). Now, as we have already sorted the shardStreams by streamID and logs are also ordered by streamID, so we use a variable streamIdx which starts from 0. Now, we run a for loop across stream log results from that particular tablet (we got from the outer loop). In this loop, we update streamIdx in this code block:

for streamIdx < len(streams) {
	stream := streams[streamIdx]
	if stream.Id < streamLog.StreamId {
		streamIdx++
		continue
	}

	if stream.Id > streamLog.StreamId {
		s.Logger().Warningf("Found stream log for nonexistent stream: %+v", streamLog)
		// This can happen on manual/failed workflow cleanup so keep going.
		continue
	}

	// stream.Id == streamLog.StreamId
	stream.Logs = append(stream.Logs, streamLog)
	break
}

So, basically if we increase the streamIdx (i.e. streamIdx++ ) , the next streamID will be greater than the last one because we already sorted the streams of each shard. We can consider that continue in this loop means that we are finding the stream that matches the particular streamLog.StreamID, and break means jumping to next log. But, in the following condition:

if stream.Id > streamLog.StreamId {
      s.Logger().Warningf("Found stream log for nonexistent stream: %+v", streamLog)
      // This can happen on manual/failed workflow cleanup so keep going.
      continue
}

Instead of jumping to the next log, we are continuing the search for matching stream.Id even when we know it's not possible to find it, because even if we increase the streamIdx, stream.Id will increase as the results are already sorted. This results in an infinite loop. Instead we should break the for loop and jump to the next log.

Failing Case: If the streamIDs are: 1, 2, 4, 6 and logs have streamIDs in this order: 1, 1, 1, 3, 3, 3, 4. Now, inside the loop when we are at log with streamID 3, right now we will be stuck. And, if we increase the streamIdx it won't be right, as we would already be at stream.Id = 4 and this will skip the logs for stream 4 and stream 6. But, if we break, we'll be accessing the next log, which would be the correct approach.

Related Issue(s)

• Fixes vtctld: infinite loop on "Found stream log for nonexistent stream" #16195

Checklist

• "Backport to:" labels have been added if this change should be back-ported to release branches
• If this change is to be back-ported to previous releases, a justification is included in the PR description
• Tests were added or are not required
• Did the new or modified tests pass consistently locally and on CI?
• Documentation was added or is not required

Deployment Notes

[vitess-bot]

Review Checklist

Hello reviewers! 👋 Please follow this checklist when reviewing this Pull Request.

General

• Ensure that the Pull Request has a descriptive title.
• Ensure there is a link to an issue (except for internal cleanup and flaky test fixes), new features should have an RFC that documents use cases and test cases.

Tests

• Bug fixes should have at least one unit or end-to-end test, enhancement and new features should have a sufficient number of tests.

Documentation

• Apply the release notes (needs details) label if users need to know about this change.
• New features should be documented.
• There should be some code comments as to why things are implemented the way they are.
• There should be a comment at the top of each new or modified test to explain what the test does.

New flags

• Is this flag really necessary?
• Flag names must be clear and intuitive, use dashes (-), and have a clear help text.

If a workflow is added or modified:

• Each item in Jobs should be named in order to mark it as required.
• If the workflow needs to be marked as required, the maintainer team must be notified.

Backward compatibility

• Protobuf changes should be wire-compatible.
• Changes to _vt tables and RPCs need to be backward compatible.
• RPC changes should be compatible with vitess-operator
• If a flag is removed, then it should also be removed from vitess-operator and arewefastyet, if used there.
• vtctl command output order should be stable and awk-able.

[codecov]

Codecov Report

All modified and coverable lines are covered by tests ✅

Project coverage is 67.14%. Comparing base (7eaf236) to head (ccc95ad).
Report is 13 commits behind head on main.

Additional details and impacted files

@@            Coverage Diff             @@
##             main   #17004      +/-   ##
==========================================
- Coverage   69.34%   67.14%   -2.20%     
==========================================
  Files        1571     1571              
  Lines      204179   251763   +47584     
==========================================
+ Hits       141586   169048   +27462     
- Misses      62593    82715   +20122     

☔ View full report in Codecov by Sentry.
📢 Have feedback on the report? Share it here.

[mattlord]

Excellent work (as usual), @beingnoble03 ! Thank you. ❤️ I only had the very minor note about adding a comment for the new unit test.

I confirmed that it tests what we want. When running it against main:

❯ go test -timeout 10s -run ^TestGetWorkflowsSingleStream$ vitess.io/vitess/go/vt/vtctl/workflow
... MANY of these
W1018 16:36:43.159766   58815 server.go:865] Found stream log for nonexistent stream: id:1 type:"State Change" state:"Running" created_at:{seconds:1136214245} updated_at:{seconds:1136214245} message:"test message for non-existent 1" count:1
W1018 16:36:43.159768   58815 server.go:865] Found stream log for nonexistent stream: id:1 type:"State Change" state:"Running" created_at:{seconds:1136214245} updated_at:{seconds:1136214245} message:"test message for non-existent 1" count:1
W1018 16:36:43.159771   58815 server.go:865] Found stream log for nonexistent stream: id:1 type:"State Change" state:"Running" created_at:{seconds:1136214245} updated_at:{seconds:1136214245} message:"test message for non-existent 1" count:1
W1018 16:36:43.159774   58815 server.go:865] Found stream log for nonexistent stream: id:1 type:"State Change" state:"Running" created_at:{seconds:1136214245} updated_at:{seconds:1136214245} message:"test message for non-existent 1" count:1
W1018 16:36:43.159776   58815 server.go:865] Found stream log for nonexistent stream: id:1 type:"State Change" state:"Running" created_at:{seconds:1136214245} updated_at:{seconds:1136214245} message:"test message for non-existent 1" count:1
panic: test timed out after 10s
	running tests:
		TestGetWorkflowsSingleStream (10s)

It demonstrates perfectly what had been seen — spinning in a tight loop spewing that warning forever — and that it works as expected/desired in the PR branch.

[mattlord]

We should add a brief comment about what this is testing as it's not obvious from the name.

[beingnoble03]

Thanks for pointing out that @mattlord! I've changed the test func name and added the comment.