Skip to content

Try to fix flakes in query history scrubber tests #2667

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
robertbrignull merged 4 commits into from
Aug 3, 2023
Merged

Try to fix flakes in query history scrubber tests #2667

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
4 commits
Select commit Hold shift + click to select a range
428014c
Move timestamp constants to be outside of describe block
robertbrignull Aug 3, 2023
28a0075
Move creation of the mock context to a function
robertbrignull Aug 3, 2023
8bce7b5
Use a jest.fn() to track calls to the scrubber, instead of a local va…
robertbrignull Aug 3, 2023
2ffbb9c
Perform dirSync inside beforeEach block
robertbrignull Aug 3, 2023
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
14 changes: 5 additions & 9 deletions extensions/ql-vscode/src/query-history/query-history-scrubber.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -10,10 +10,6 @@ import { getErrorMessage } from "../common/helpers-pure";

const LAST_SCRUB_TIME_KEY = "lastScrubTime";

type Counter = {
increment: () => void;
};

/**
* Registers an interval timer that will periodically check for queries old enought
* to be deleted.
Expand All @@ -37,8 +33,8 @@ export function registerQueryHistoryScrubber(
qhm: QueryHistoryManager,
ctx: ExtensionContext,

// optional counter to keep track of how many times the scrubber has run
counter?: Counter,
// optional callback to keep track of how many times the scrubber has run
onScrubberRun?: () => void,
): Disposable {
const deregister = setInterval(
scrubQueries,
Expand All @@ -48,7 +44,7 @@ export function registerQueryHistoryScrubber(
queryHistoryDirs,
qhm,
ctx,
counter,
onScrubberRun,
);

return {
Expand All @@ -64,7 +60,7 @@ async function scrubQueries(
queryHistoryDirs: QueryHistoryDirs,
qhm: QueryHistoryManager,
ctx: ExtensionContext,
counter?: Counter,
onScrubberRun?: () => void,
) {
const lastScrubTime = ctx.globalState.get<number>(LAST_SCRUB_TIME_KEY);
const now = Date.now();
Expand All @@ -76,7 +72,7 @@ async function scrubQueries(

let scrubCount = 0; // total number of directories deleted
try {
counter?.increment();
onScrubberRun?.();
void extLogger.log(
"Cleaning up query history directories. Removing old entries.",
);
Expand Down
87 changes: 47 additions & 40 deletions ...ons/ql-vscode/test/vscode-tests/no-workspace/query-history/query-history-scrubber.test.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -13,77 +13,61 @@ import {
TWO_HOURS_IN_MS,
} from "../../../../src/common/time";
import { mockedObject } from "../../utils/mocking.helpers";
import { DirResult } from "tmp";

describe("query history scrubber", () => {
const now = Date.now();
const now = Date.now();
// We don't want our times to align exactly with the hour,
// so we can better mimic real life
const LESS_THAN_ONE_DAY = ONE_DAY_IN_MS - 1000;

describe("query history scrubber", () => {
let deregister: vscode.Disposable | undefined;
let mockCtx: vscode.ExtensionContext;
let runCount = 0;
Copy link
Copy Markdown
Contributor

@aeisenberg aeisenberg Aug 3, 2023

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Wait...this was never reset? How did this ever work?

Copy link
Copy Markdown
Contributor Author

@robertbrignull robertbrignull Aug 3, 2023

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I confess I don't really understand the semantics of jest. I think I went a bit far there saying it's never reset between tests and you make a good point that how would it ever work, so it must have been reset most/some of the time.

Copy link
Copy Markdown
Contributor Author

@robertbrignull robertbrignull Aug 3, 2023

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Ok from a bit of research it appears I was right and variables like this are not reset between tests. So the reason it worked is that only the first of the two tests in this file references this variable, and tests within a file are run sequentially in order (at least by default).

The reason it was failing like this is that we have jest configured to retry failed tests, and on the second try it would fail because runCount wasn't reset. The full log, which I'm embarrassed I didn't read more fully earlier on, is:

PASS test/vscode-tests/no-workspace/query-history/variant-analysis-history.test.ts
 LOGGING RETRY ERRORS  query history scrubber should not throw an error when the query directory does not exist
 RETRY 1 

    TreeError [codeQLQueryHistory] Data tree node not found: [object Object]

      at we.A (../../../vscode-file:/vscode-app/home/runner/work/vscode-codeql/vscode-codeql/extensions/ql-vscode/.vscode-test/vscode-linux-x64-1.77.3/resources/app/out/vs/workbench/workbench.desktop.main.js:554:18061)
      at we.reveal (../../../vscode-file:/vscode-app/home/runner/work/vscode-codeql/vscode-codeql/extensions/ql-vscode/.vscode-test/vscode-linux-x64-1.77.3/resources/app/out/vs/workbench/workbench.desktop.main.js:554:17723)
      at Me.reveal (../../../vscode-file:/vscode-app/home/runner/work/vscode-codeql/vscode-codeql/extensions/ql-vscode/.vscode-test/vscode-linux-x64-1.77.3/resources/app/out/vs/workbench/workbench.desktop.main.js:2526:13663)
      at g.j (../../../vscode-file:/vscode-app/home/runner/work/vscode-codeql/vscode-codeql/extensions/ql-vscode/.vscode-test/vscode-linux-x64-1.77.3/resources/app/out/vs/workbench/workbench.desktop.main.js:1586:70284)

 RETRY 2 

    expect(received).toBe(expected) // Object.is equality

    Expected: 0
    Received: 16

      69 |     await wait();
      70 |     // "Should not have called the scrubber"
    > 71 |     expect(runCount).toBe(0);
         |                      ^
      72 |
      73 |     jest.advanceTimersByTime(ONE_HOUR_IN_MS - 1);
      74 |     await wait();

      at Object.<anonymous> (query-history/query-history-scrubber.test.ts:71:22)

So you can see the first failure had a different reason, and then the subsequent failures were because of runCount.

So with this in mind I'm pretty confident this PR will at least make the test behave consistently on retries. It appears we may have another reason for test failure, but if that's not consistent then it may be handled by the automatic retries.


// We don't want our times to align exactly with the hour,
// so we can better mimic real life
const LESS_THAN_ONE_DAY = ONE_DAY_IN_MS - 1000;
const tmpDir = dirSync({
unsafeCleanup: true,
});
let tmpDir: DirResult;

beforeEach(() => {
tmpDir = dirSync({
unsafeCleanup: true,
});

jest.spyOn(extLogger, "log").mockResolvedValue(undefined);

jest.useFakeTimers({
doNotFake: ["setTimeout"],
now,
});

mockCtx = {
globalState: {
lastScrubTime: now,
get(key: string) {
if (key !== "lastScrubTime") {
throw new Error(`Unexpected key: ${key}`);
}
return this.lastScrubTime;
},
async update(key: string, value: any) {
if (key !== "lastScrubTime") {
throw new Error(`Unexpected key: ${key}`);
}
this.lastScrubTime = value;
},
},
} as any as vscode.ExtensionContext;
});

afterEach(() => {
if (deregister) {
deregister.dispose();
deregister = undefined;
}
tmpDir.removeCallback();
});

it("should not throw an error when the query directory does not exist", async () => {
registerScrubber("idontexist");
const mockCtx = createMockContext();
const runCounter = registerScrubber("idontexist", mockCtx);

jest.advanceTimersByTime(ONE_HOUR_IN_MS);
await wait();
// "Should not have called the scrubber"
expect(runCount).toBe(0);
expect(runCounter).toHaveBeenCalledTimes(0);

jest.advanceTimersByTime(ONE_HOUR_IN_MS - 1);
await wait();
// "Should not have called the scrubber"
expect(runCount).toBe(0);
expect(runCounter).toHaveBeenCalledTimes(0);

jest.advanceTimersByTime(1);
await wait();
// "Should have called the scrubber once"
expect(runCount).toBe(1);
expect(runCounter).toHaveBeenCalledTimes(1);

jest.advanceTimersByTime(TWO_HOURS_IN_MS);
await wait();
// "Should have called the scrubber a second time"
expect(runCount).toBe(2);
expect(runCounter).toHaveBeenCalledTimes(2);

expect((mockCtx.globalState as any).lastScrubTime).toBe(
now + TWO_HOURS_IN_MS * 2,
Expand All @@ -97,7 +81,7 @@ describe("query history scrubber", () => {
TWO_HOURS_IN_MS,
THREE_HOURS_IN_MS,
);
registerScrubber(queryDir);
registerScrubber(queryDir, createMockContext());

jest.advanceTimersByTime(TWO_HOURS_IN_MS);
await wait();
Expand Down Expand Up @@ -176,7 +160,31 @@ describe("query history scrubber", () => {
return `query-${timestamp}`;
}

function registerScrubber(dir: string) {
function createMockContext(): vscode.ExtensionContext {
return {
globalState: {
lastScrubTime: now,
get(key: string) {
if (key !== "lastScrubTime") {
throw new Error(`Unexpected key: ${key}`);
}
return this.lastScrubTime;
},
async update(key: string, value: any) {
if (key !== "lastScrubTime") {
throw new Error(`Unexpected key: ${key}`);
}
this.lastScrubTime = value;
},
},
} as any as vscode.ExtensionContext;
}

function registerScrubber(
dir: string,
ctx: vscode.ExtensionContext,
): jest.Mock {
const onScrubberRun = jest.fn();
deregister = registerQueryHistoryScrubber(
ONE_HOUR_IN_MS,
TWO_HOURS_IN_MS,
Expand All @@ -187,11 +195,10 @@ describe("query history scrubber", () => {
return Promise.resolve();
},
}),
mockCtx,
{
increment: () => runCount++,
},
ctx,
onScrubberRun,
);
return onScrubberRun;
}

async function wait(ms = 500) {
Expand Down