Flake in waitingPeriodThreshold tests #5404

gnprice · 2022-06-08T16:52:49Z

It looks like:

Summary of all failing tests
FAIL src/__tests__/permissionSelectors-test.js
  ● getCanCreatePublicStreams › returns true when policy is 3; role is 400; waitingPeriodPassed is true
    expect(received).toBe(expected) // Object.is equality
    Expected: true
    Received: false
      132 |       }
      133 |
    > 134 |       expect(getCanCreatePublicStreams(newState)).toBe(expected);
          |                                                                  ^
      135 |     },
      136 |   );
      137 | });
      at _callee$ (src/__tests__/permissionSelectors-test.js:134:83)
      at tryCatch (node_modules/regenerator-runtime/runtime.js:63:40)
      at Generator.invoke [as _invoke] (node_modules/regenerator-runtime/runtime.js:294:22)
      at Generator.next (node_modules/regenerator-runtime/runtime.js:119:21)
      at tryCatch (node_modules/regenerator-runtime/runtime.js:63:40)
      at invoke (node_modules/regenerator-runtime/runtime.js:155:20)
      at node_modules/regenerator-runtime/runtime.js:190:11
      at callInvokeWithMethodAndArg (node_modules/regenerator-runtime/runtime.js:189:16)
      at AsyncIterator.enqueue (node_modules/regenerator-runtime/runtime.js:212:13)

plus a similar one at:

      at _callee2$ (src/__tests__/permissionSelectors-test.js:221:84)

#5402 cleaned up the date arithmetic, but the flake remains: #5393 (comment)

The code in question looks like:

      if (waitingPeriodPassed !== undefined) {
        // TODO(?): jest.mock getHasUserPassedWaitingPeriod instead (how?)
        const daysToAdd =
          getRealm(newState).waitingPeriodThreshold + (waitingPeriodPassed ? 2 : -2);
        jest.setSystemTime(Date.parse(getOwnUser(newState).date_joined) + daysToAdd * 86400_000);

Given that we've seen it a couple of times just this week, it seems to be a fairly high-frequency flake. That means it's a priority to fix -- but it's also good news for debugging it and testing potential fixes, because it suggests it may be reproducible just by running the test a small number of times.

The text was updated successfully, but these errors were encountered:

chrisbobbe · 2022-06-14T15:18:56Z

Hmm. Have you ever seen this locally? I don't think I have.

If it has a higher chance of occurring in CI than locally, I'm not sure what the story would be. My first thought would be that we're failing to use maybePretendUtc when we should be, just because we built that to resolve differences seen in CI vs. locally. But looking at the implementation and the test, I don't see that anything about timezones could be a trigger for this flake.

My best idea, I think, would be to resolve the TODO:

// TODO(?): jest.mock getHasUserPassedWaitingPeriod instead (how?)

because then we don't have to mess around with dates/times, like with jest.setSystemTime, which is probably a factor in the flake. But I've given up trying to get that working today and would be glad for some help. In general, I've had such bad luck trying to do useful things with jest.mock that I wonder if I just don't understand what mocks are for.

My plan for the TODO would be:

if waitingPeriodPassed is set (not undefined), mock getHasUserPassedWaitingPeriod to return waitingPeriodPassed once
run the existing line expect(getCanCreatePublicStreams(newState)).toBe(expected)
(maybe) assert that getHasUserPassedWaitingPeriod was called once, if we'd expect it to be
make sure the real getHasUserPassedWaitingPeriod is used everywhere except as described here

gnprice · 2022-06-14T16:45:44Z

Hmm. Have you ever seen this locally? I don't think I have.

I haven't naturally, but OTOH the only-what-changed behavior of tools/test means I probably haven't run that test many times locally.

I just tried it in a loop, and it failed 2 times out of 10:

$ for i in {1..10}; do time npx jest /permissionSele; done
 PASS   ios  src/__tests__/permissionSelectors-test.js
 PASS   android  src/__tests__/permissionSelectors-test.js

Test Suites: 2 passed, 2 total
Tests:       190 passed, 190 total
Snapshots:   0 total
Time:        3.069 s
Ran all test suites matching /\/permissionSele/i in 2 projects.

time: 4.677s wall (10.806s u, 0.705s s)
…
 PASS   ios  src/__tests__/permissionSelectors-test.js
 FAIL   android  src/__tests__/permissionSelectors-test.js
  ● getCanCreatePublicStreams › returns true when policy is 3; role is 400; waitingPeriodPassed is true

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

    Expected: true
    Received: false

      124 |       }
      125 |
    > 126 |       expect(getCanCreatePublicStreams(newState)).toBe(expected);
          |                                                                                   ^
      127 |     },
      128 |   );
      129 | });

      at _callee$ (src/__tests__/permissionSelectors-test.js:126:83)
      at tryCatch (src/__tests__/permissionSelectors-test.js:25:4543)
      at Generator._invoke (src/__tests__/permissionSelectors-test.js:25:4115)
      at Generator.next (src/__tests__/permissionSelectors-test.js:25:5373)
      at tryCatch (src/__tests__/permissionSelectors-test.js:25:4543)
      at invoke (src/__tests__/permissionSelectors-test.js:25:5509)
      at src/__tests__/permissionSelectors-test.js:25:6200
      at callInvokeWithMethodAndArg (src/__tests__/permissionSelectors-test.js:25:6156)
      at AsyncIterator._invoke (src/__tests__/permissionSelectors-test.js:25:6363)

  ● getCanCreatePrivateStreams › returns true when policy is 3; role is 400; waitingPeriodPassed is true

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

    Expected: true
    Received: false

      204 |       }
      205 |
    > 206 |       expect(getCanCreatePrivateStreams(newState)).toBe(expected);
          |                                                                                    ^
      207 |     },
      208 |   );
      209 | });

      at _callee2$ (src/__tests__/permissionSelectors-test.js:206:84)
      at tryCatch (src/__tests__/permissionSelectors-test.js:25:4543)
      at Generator._invoke (src/__tests__/permissionSelectors-test.js:25:4115)
      at Generator.next (src/__tests__/permissionSelectors-test.js:25:5373)
      at tryCatch (src/__tests__/permissionSelectors-test.js:25:4543)
      at invoke (src/__tests__/permissionSelectors-test.js:25:5509)
      at src/__tests__/permissionSelectors-test.js:25:6200
      at callInvokeWithMethodAndArg (src/__tests__/permissionSelectors-test.js:25:6156)
      at AsyncIterator._invoke (src/__tests__/permissionSelectors-test.js:25:6363)

Test Suites: 1 failed, 1 passed, 2 total
Tests:       2 failed, 188 passed, 190 total
Snapshots:   0 total
Time:        3.034 s
Ran all test suites matching /\/permissionSele/i in 2 projects.

time: 4.766s wall (10.910s u, 0.695s s)
…
[and later a second failure]

gnprice · 2022-06-14T16:55:15Z

My best idea, I think, would be to resolve the TODO:
// TODO(?): jest.mock getHasUserPassedWaitingPeriod instead (how?)

That seems like a reasonable plan. Want to describe in a chat thread what you've tried and how it hasn't worked?

The other possible direction is to debug why jest.setSystemTime isn't getting the desired result. I checked its docs:
https://jestjs.io/docs/jest-object#jestsetsystemtimenow-number--date
and it doesn't seem like we're misusing it. I'll spend a little time looking into that direction now.

gnprice · 2022-06-14T17:02:35Z

Ha, well, here it is! Added this debug-logging:

         const daysToAdd =
           getRealm(newState).waitingPeriodThreshold + (waitingPeriodPassed ? 2 : -2);
-        jest.setSystemTime(Date.parse(getOwnUser(newState).date_joined) + daysToAdd * 86400_000);
+        const target = Date.parse(getOwnUser(newState).date_joined) + daysToAdd * 86400_000;
+        console.log('setting time:', target, 'after joined:', getOwnUser(newState).date_joined);
+        jest.setSystemTime(target);
…
   const { date_joined } = getUserForId(state, userId);
 
-  const intervalLengthInDays = (Date.now() - Date.parse(date_joined)) / 86400_000;
+  const now = Date.now();
+  const intervalLengthInDays = (now - Date.parse(date_joined)) / 86400_000;
+  console.log('now is:', now, 'joined:', date_joined, 'interval days:', intervalLengthInDays);

Then ran those tests in a loop:

$ time { for i in {1..40}; do npx jest /permissionSele -t 'waitingPeriodPassed is [tf]' || break; done; }

Successful iterations:

 PASS   android  src/__tests__/permissionSelectors-test.js
  ● Console

    console.log
      setting time: 1404518400000 after joined: 2014-04-04

      at _callee$ (src/__tests__/permissionSelectors-test.js:124:23)

    console.log
      now is: 1404518400000 joined: 2014-04-04 interval days: 92

      at getHasUserPassedWaitingPeriod (src/permissionSelectors.js:63:11)

    console.log
      setting time: 1404172800000 after joined: 2014-04-04

      at _callee$ (src/__tests__/permissionSelectors-test.js:124:23)

    console.log
      now is: 1404172800000 joined: 2014-04-04 interval days: 88

      at getHasUserPassedWaitingPeriod (src/permissionSelectors.js:63:11)

    console.log
      now is: 1404518400000 joined: 2014-04-04 interval days: 92

      at getHasUserPassedWaitingPeriod (src/permissionSelectors.js:63:11)

    console.log
      now is: 1404172800000 joined: 2014-04-04 interval days: 88

      at getHasUserPassedWaitingPeriod (src/permissionSelectors.js:63:11)

 PASS   ios  src/__tests__/permissionSelectors-test.js
  ● Console

    console.log
      setting time: 1405987200000 after joined: 2014-04-21

      at _callee$ (src/__tests__/permissionSelectors-test.js:124:23)

    console.log
      now is: 1405987200000 joined: 2014-04-21 interval days: 92

      at getHasUserPassedWaitingPeriod (src/permissionSelectors.js:63:11)

    console.log
      setting time: 1405641600000 after joined: 2014-04-21

      at _callee$ (src/__tests__/permissionSelectors-test.js:124:23)

    console.log
      now is: 1405641600000 joined: 2014-04-21 interval days: 88

      at getHasUserPassedWaitingPeriod (src/permissionSelectors.js:63:11)

    console.log
      now is: 1405987200000 joined: 2014-04-21 interval days: 92

      at getHasUserPassedWaitingPeriod (src/permissionSelectors.js:63:11)

    console.log
      now is: 1405641600000 joined: 2014-04-21 interval days: 88

      at getHasUserPassedWaitingPeriod (src/permissionSelectors.js:63:11)


Test Suites: 2 passed, 2 total
Tests:       182 skipped, 8 passed, 190 total
Snapshots:   0 total
Time:        3.145 s
Ran all test suites matching /\/permissionSele/i with tests matching "waitingPeriodPassed is [tf]" in 2 projects.

Unsuccessful iteration:

 FAIL   ios  src/__tests__/permissionSelectors-test.js
  ● Console

    console.log
      setting time: NaN after joined: 2014-04-00

      at _callee$ (src/__tests__/permissionSelectors-test.js:124:23)

    console.log
      now is: 0 joined: 2014-04-00 interval days: NaN

      at getHasUserPassedWaitingPeriod (src/permissionSelectors.js:63:11)

    console.log
      setting time: NaN after joined: 2014-04-00

      at _callee$ (src/__tests__/permissionSelectors-test.js:124:23)

    console.log
      now is: 0 joined: 2014-04-00 interval days: NaN

      at getHasUserPassedWaitingPeriod (src/permissionSelectors.js:63:11)

    console.log
      now is: 0 joined: 2014-04-00 interval days: NaN

      at getHasUserPassedWaitingPeriod (src/permissionSelectors.js:63:11)

    console.log
      now is: 0 joined: 2014-04-00 interval days: NaN

      at getHasUserPassedWaitingPeriod (src/permissionSelectors.js:63:11)

  ● getCanCreatePublicStreams › returns true when policy is 3; role is 400; waitingPeriodPassed is true

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

    Expected: true
    Received: false

So the problem is that date_joined is invalid, and parsing it gives NaN.

I.e. it's this line in exampleData.js:

    date_joined: `2014-04-${randInt(30).toString().padStart(2, '0')}`,

where oops, randInt can return 0.

I'll fix.

gnprice · 2022-06-14T17:11:47Z

The NaN also explains why the flake was always in one direction: always false where we expected true, never (as far as I saw) vice versa. It's because NaN has the peculiar property that all comparison operators return false -- like the one at the end of getHasUserPassedWaitingPeriod.

gnprice added the P1 high-priority label Jun 8, 2022

This was referenced Jun 8, 2022

js: Update prettier-eslint, etc., to latest!! #5393

Merged

msglist diffing tests: Fix a flake with stream-subscribed status changing #5415

Merged

gnprice self-assigned this Jun 14, 2022

gnprice mentioned this issue Jun 14, 2022

example data: Fix date_joined on users to always be valid #5416

Merged

chrisbobbe closed this as completed in 9affb59 Jun 14, 2022

chrisbobbe closed this as completed in #5416 Jun 14, 2022

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Flake in waitingPeriodThreshold tests #5404

Flake in waitingPeriodThreshold tests #5404

gnprice commented Jun 8, 2022

chrisbobbe commented Jun 14, 2022 •

edited

Loading

gnprice commented Jun 14, 2022

gnprice commented Jun 14, 2022

gnprice commented Jun 14, 2022 •

edited

Loading

gnprice commented Jun 14, 2022

Flake in waitingPeriodThreshold tests #5404

Flake in waitingPeriodThreshold tests #5404

Comments

gnprice commented Jun 8, 2022

chrisbobbe commented Jun 14, 2022 • edited Loading

gnprice commented Jun 14, 2022

gnprice commented Jun 14, 2022

gnprice commented Jun 14, 2022 • edited Loading

gnprice commented Jun 14, 2022

chrisbobbe commented Jun 14, 2022 •

edited

Loading

gnprice commented Jun 14, 2022 •

edited

Loading