test: add logging to TestWorkspaceActivityBump/Dial #15089
Merged
Conversation
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
If a test is running slow, the workspace deadline check can be slow. Since we use 'now' as a reference point, any time drift will affect the results.
If the hypothesis of a 10s time drift is true, this loop might be acting slow.
Emyrk
commented
Oct 15, 2024
| waitedFor := time.Now() | ||
| // lastChecked is for logging within the Eventually loop. | ||
| // Debouncing log lines to every second to prevent spam. | ||
| lastChecked := time.Time{} |
There was a problem hiding this comment.
Made to time.Time so the first loop is always logged.
spikecurtis
approved these changes
Oct 16, 2024
Sign up for free
to subscribe to this conversation on GitHub.
Already have an account?
Sign in.
Add this suggestion to a batch that can be applied as a single commit.
This suggestion is invalid because no changes were made to the code.
Suggestions cannot be applied while the pull request is closed.
Suggestions cannot be applied while viewing a subset of changes.
Only one suggestion per line can be applied in a batch.
Add this suggestion to a batch that can be applied as a single commit.
Applying suggestions on deleted lines is not supported.
You must change the existing code in this line in order to create a valid suggestion.
Outdated suggestions cannot be applied.
This suggestion has been applied or marked resolved.
Suggestions cannot be applied from pending reviews.
Suggestions cannot be applied on multi-line comments.
Suggestions cannot be applied while the pull request is queued to merge.
Suggestion cannot be applied right now. Please check back later.
My initial notes: coder/internal#102 (comment)
I am a bit split on how best to solve this. It is a classic problem of what is
now.At it's core, what is happening is:
nowdeadeline-now=1hrFor an unknown reason,
Detect Bumpseems to have taken 10s in the flake failure. Sonowhas drifted 10s later then step 1.Our time tolerance is 10s, so the test fails.
Without more logs, it's difficult to know for certain. What makes this more confusing, is the
Detect bumpshould detect when the bump happens, meaningnowshould be relative to when this loop unblocks.So the implementation of taking
nowafter the loop is correct.What did I do then?
I added logging information to output timing information of this for loop. If we get another failure, this timing information should be helpful.
I also made the time drift allowed (was 10s) to match the maximum waiting time of the for loop. It's not perfect, but now the loop should take max ~15s, and the time comparison will allow 15s leeway.
Just a note that I do not believe there is any bugs in the production code. Looking at the failure logs, the activity bump works as expected.