gh-157161: Fix test_rollover_based_on_st_birthtime_only on slow machines - #157162
gh-157161: Fix test_rollover_based_on_st_birthtime_only on slow machines#157162iamsharduld wants to merge 2 commits into
Conversation
… machines The rotated file is named after the creation time of the log file, but the test only looked for it within a fixed 5 seconds before the end of the test. On a slow CI runner the test took 6 seconds, so the file was found nowhere and the test failed although the rollover was correct. Derive the search window from the time the test actually took.
| now = datetime.datetime.now() | ||
| GO_BACK = 5 # seconds | ||
| for secs in range(GO_BACK + 1): | ||
| go_back = int((now - start).total_seconds()) + 2 |
There was a problem hiding this comment.
Would it make sense to include an inline comment on how this number is derived?
edit: or maybe rename s/go_back/total_time_spent (total_test_time, test_duration)
There was a problem hiding this comment.
Good point, done. The window is now built in two named steps: test_duration from the measured elapsed time, then oldest = test_duration + 2, with a comment saying where the two seconds come from (the log file is created in setUp(), a moment before the test starts, and the suffix has a one second resolution).
| GO_BACK = 5 # seconds | ||
| for secs in range(GO_BACK + 1): | ||
| go_back = int((now - start).total_seconds()) + 2 | ||
| for secs in range(go_back + 1): |
There was a problem hiding this comment.
Why add 2 on the line above, just to add 1 here?
There was a problem hiding this comment.
They were doing two different jobs, which is exactly why it read badly. The + 2 is the margin described above; the + 1 only makes range() cover oldest itself, since it is exclusive. The margin now has its own named variable and the loop carries an # inclusive of oldest comment, so neither number is bare arithmetic any more.
Split the search window into the measured duration of the test and an explicit two second margin, and note that the range covers the oldest second as well.
|
I have made the requested changes; please review again |
|
Thanks for making the requested changes! : please review the changes made to this pull request. |
2 participants
The test looks for the rotated file by trying the timestamps of the last 5 seconds. The rotated file is named after the creation time of the log file (
rolloverAt - interval, whererolloverAtwas computed from the file's creation time), so it can only be found if the whole test took less than 5 seconds. Its nominal duration is 4.2 seconds of sleeps plus three handler set-ups, and on the failing CI job (diagnostics quoted in the issue) it took 6.07 seconds, so the file named after second 45 was never checked from second 51.This derives the search window from the time the test actually took, plus two seconds: one because the log file is created in
setUp(), slightly before the test starts, and one for the one-second resolution of the names.Verified:
add_record()(a 7.8 s test), the current test fails with exactly the CI message,No rotated files found, went back 5 seconds; with this change it passes.test_loggingmodule passes with-u walltime.The June change in GH-150954 widened the window by one timestamp; this makes it follow the actual duration so that no fixed value needs to be tuned again.