investigate flaky test-crypto-timing-safe-equal-benchmarks

[Trott]

pummel/test-crypto-timing-safe-equal-benchmarks seems to fail frequently on LinuxONE. That's often a sign that a test (or some Node.js internal code) is not prepared to run on very fast CPUs. (In CI, our LinuxONE host is very fast and often finds race conditions of the "oh, I didn't expect it to run that quickly" variety).

Is this a bug in crypto? A bug in the test? Something else?

@nodejs/crypto @nodejs/testing

Doesn't seem to be a LinuxONE platform team so pinging a few IBM/Red Hat folks who are active in the Build team: @richardlau @AshCripps @mhdawson Probably not the exact right people, but they probably know who to loop in.

• Test: test-crypto-timing-safe-equal-benchmarks
• Platform: linuxone
• Console Output:

00:09:15 not ok 2944 pummel/test-crypto-timing-safe-equal-benchmarks
00:09:18   ---
00:09:18   duration_ms: 2.136
00:09:18   severity: fail
00:09:18   exitcode: 1
00:09:18   stack: |-
00:09:18     node:assert:402
00:09:18         throw err;
00:09:18         ^
00:09:18     
00:09:18     AssertionError [ERR_ASSERTION]: timingSafeEqual should not leak information from its execution time (t=5.715867808741522)
00:09:18         at Object.<anonymous> (/home/iojs/build/workspace/node-test-commit-linuxone/nodes/rhel7-s390x/test/pummel/test-crypto-timing-safe-equal-benchmarks.js:109:1)
00:09:18         at Module._compile (node:internal/modules/cjs/loader:1108:14)
00:09:18         at Object.Module._extensions..js (node:internal/modules/cjs/loader:1137:10)
00:09:18         at Module.load (node:internal/modules/cjs/loader:988:32)
00:09:18         at Function.Module._load (node:internal/modules/cjs/loader:828:14)
00:09:18         at Function.executeUserEntryPoint [as runMain] (node:internal/modules/run_main:76:12)
00:09:18         at node:internal/main/run_main_module:17:47 {
00:09:18       generatedMessage: false,
00:09:18       code: 'ERR_ASSERTION',
00:09:18       actual: false,
00:09:18       expected: true,
00:09:18       operator: '=='
00:09:18     }
00:09:18   ...

• Build Links: https://ci.nodejs.org/job/node-test-commit-linuxone/26667/nodes=rhel7-s390x/console

[Trott]

This has now started failing somewhat consistently on LinuxONE in CI. I don't know if that means the test just isn't reliable or if it means there's a timing issue with faster processors or what. @nodejs/crypto

not ok 2961 pummel/test-crypto-timing-safe-equal-benchmarks
  ---
  duration_ms: 2.12
  severity: fail
  exitcode: 1
  stack: |-
    node:assert:412
        throw err;
        ^
    
    AssertionError [ERR_ASSERTION]: timingSafeEqual should not leak information from its execution time (t=7.219867083599476)
        at Object.<anonymous> (/home/iojs/build/workspace/node-test-commit-linuxone/nodes/rhel7-s390x/test/pummel/test-crypto-timing-safe-equal-benchmarks.js:109:1)
        at Module._compile (node:internal/modules/cjs/loader:1109:14)
        at Object.Module._extensions..js (node:internal/modules/cjs/loader:1138:10)
        at Module.load (node:internal/modules/cjs/loader:989:32)
        at Function.Module._load (node:internal/modules/cjs/loader:829:14)
        at Function.executeUserEntryPoint [as runMain] (node:internal/modules/run_main:76:12)
        at node:internal/main/run_main_module:17:47 {
      generatedMessage: false,
      code: 'ERR_ASSERTION',
      actual: false,
      expected: true,
      operator: '=='
    }
  ...

https://ci.nodejs.org/job/node-test-commit-linuxone/nodes=rhel7-s390x/26963/consoleText

[Trott]

Stress tests for bisecting:

• https://ci.nodejs.org/job/node-stress-single-test/273/ (6% success, 94% failure) 6ca785b BAD
• https://ci.nodejs.org/job/node-stress-single-test/274/ (52% success, 48% failure) 13c931a GOOD (normally, this would be marked "BAD" but uh, we're grading on a curve)

Bisecting: 70 revisions left to test after this (roughly 6 steps)
[4f11b8b] doc: fix typo in buffer.md

• https://ci.nodejs.org/job/node-stress-single-test/275/ (100% success, 0% failure) 4f11b8b GOOD (but this commit is between the other two commits so that's surprising. This one ran on test-ibm-rhel7-s390x-4 whereas the other two ran on test-ibm-rhel7-s390x-3 so maybe that's a difference that matters?)

Bisecting: 35 revisions left to test after this (roughly 5 steps)
[f27b7cf] fs: aggregate errors in fsPromises to avoid error swallowing

• https://ci.nodejs.org/job/node-stress-single-test/276/ (100% success, 0% failure) f27b7cf GOOD (and this one was on test-ibm-rhel7-s390x-3, so that host itself isn't the problem)

Bisecting: 17 revisions left to test after this (roughly 4 steps)
[87aca07] doc: clarify that fs.Dir async iterator closes automatically

• https://ci.nodejs.org/job/node-stress-single-test/277/ (99% success, 1% failure) 87aca07 GOOD (again, grading on a curve here, as current HEAD has 94% failure)

Bisecting: 8 revisions left to test after this (roughly 3 steps)
[896e5af] tools: remove fixer for non-ascii-character ESLint custom rule

• https://ci.nodejs.org/job/node-stress-single-test/278/ (99% success, 1% failure) 896e5af GOOD (on a curve)

Bisecting: 4 revisions left to test after this (roughly 2 steps)
[1adcae9] doc: add try/catch in http2 respondWithFile example

• https://ci.nodejs.org/job/node-stress-single-test/279/ (14% success, 86% failure) 1adcae9 BAD

Bisecting: 1 revision left to test after this (roughly 1 step)
[7919ced] lib: harden lint checks for globals

• https://ci.nodejs.org/job/node-stress-single-test/280/ (38% success, 62% failure) 7919ced BAD

Bisecting: 0 revisions left to test after this (roughly 0 steps)
[4af15df] src: fix validation of negative offset to avoid abort

• https://ci.nodejs.org/job/node-stress-single-test/281/ (99% success, 1% failure) 4af15df GOOD (curve)

7919ced is the first bad commit
commit 7919ced
Author: Antoine du Hamel duhamelantoine1995@gmail.com
Date: Mon Apr 26 18:03:54 2021 +0200

lib: harden lint checks for globals

PR-URL: https://github.com/nodejs/node/pull/38419
Reviewed-By: James M Snell <jasnell@gmail.com>
Reviewed-By: Darshan Sen <raisinten@gmail.com>

:040000 040000 8080a76b162a40209ec5b9397db3945fa36ee143 247e5c50613229df3f9776ce9637237146682dd0 M

[Trott]

I know they're not active in this repo anymore, but ping @not-an-aardvark: Hey, does this look like an issue with the crypto safe timing test? Or does it look like a bug? The machine that it's failing on is very fast, if that helps. Would increasing numTimes from 1e5 to a larger value help or does that defeat the purpose of the test?

[not-an-aardvark]

From looking at a few of the failing cases, it seems like the error message is always "timingSafeEqual should not leak information from its execution time (t=<some positive number>)". Assuming that the test is working properly, this would be a signal that timingSafeEqual is consistently running faster for equal inputs than for unequal inputs (at least on some hardware/builds), which would be bad and might be worth investigating. That said, in the past this test has had various false positives due to artifacts of the test setup itself.

The test fails if it determines that a timing difference is statistically significant. In general, increasing numTrials would make the test more sensitive to small timing differences (i.e. maybe even more likely to fail), since it would have a larger dataset to do statistical analysis on.

In this case, it seems like the t-values are routinely 9 and above, which wouldn't plausibly happen by chance. So we can be pretty confident that it's either (a) a legitimate bug in crypto.timingSafeEqual, or (b) a bug in the test setup, which wouldn't be fixed by changing numTrials.

---

Incidentally, when we were originally implementing crypto.timingSafeEqual in #8040, we considered using a "double HMAC" implementation rather than CRYPTO_memcmp, but decided on CRYPTO_memcmp because we didn't want to leak the boolean condition of whether the comparison was successful.*

Since then, there have been significant advances in side-channel attacks (Meltdown/Spectre and others), which has led me to believe that double HMAC could be a good defense-in-depth measure against increasingly powerful compilers and CPU branch prediction that could optimize away CRYPTO_memcmp.

It might be worth updating crypto.timingSafeEqual to use both double HMAC and CRYPTO_memcmp (i.e. given buffers a and b, return the result of CRYPTO_memcmp(sha256hmac(randomKey, a), sha256hmac(randomKey, b))).

*I also have some doubts about whether it's really possible to avoid leaking the boolean result, due to branch prediction. This might also be why this test keeps failing. In any case, combining CRYPTO_memcmp and double HMAC wouldn't make anything worse in that regard.

[Trott]

Bisect results:

7919ced0c97e9a5b17e6042e0b57bc911d23583d is the first bad commit
commit 7919ced0c97e9a5b17e6042e0b57bc911d23583d
Author: Antoine du Hamel <duhamelantoine1995@gmail.com>
Date:   Mon Apr 26 18:03:54 2021 +0200

    lib: harden lint checks for globals
    
    PR-URL: https://github.com/nodejs/node/pull/38419
    Reviewed-By: James M Snell <jasnell@gmail.com>
    Reviewed-By: Darshan Sen <raisinten@gmail.com>

:040000 040000 8080a76b162a40209ec5b9397db3945fa36ee143 247e5c50613229df3f9776ce9637237146682dd0 M

[Trott]

The bisect results are certainly surprising. Going to run a bunch more tests to confirm them.

Stress tests against 7919ced:

• https://ci.nodejs.org/job/node-stress-single-test/282/ (77% failures)
• https://ci.nodejs.org/job/node-stress-single-test/283/ (72% failures)
• https://ci.nodejs.org/job/node-stress-single-test/284/ (42% failures)

Stress tests on 4af15df (the last change before the one above that is being tentatively blamed for the problem):

• https://ci.nodejs.org/job/node-stress-single-test/285/ (16% failures)
• https://ci.nodejs.org/job/node-stress-single-test/286/ (19% failures)
• https://ci.nodejs.org/job/node-stress-single-test/287/ (11% failures)

[Trott]

In this case, it seems like the t-values are routinely 9 and above, which wouldn't plausibly happen by chance.

When I increase numTimes to 1e6, I got a whopping t value of 37.871320438939634 which I imagine is not moving in the right direction.....

[Trott]

The bisect results are certainly surprising. Going to run a bunch more tests to confirm them.

Stress tests against 7919ced:

• https://ci.nodejs.org/job/node-stress-single-test/282/ (77% failures)
• https://ci.nodejs.org/job/node-stress-single-test/283/ (72% failures)
• https://ci.nodejs.org/job/node-stress-single-test/284/ (42% failures)

Stress tests on 4af15df (the last change before the one above that is being tentatively blamed for the problem):

• https://ci.nodejs.org/job/node-stress-single-test/285/ (16% failures)
• https://ci.nodejs.org/job/node-stress-single-test/286/ (19% failures)
• https://ci.nodejs.org/job/node-stress-single-test/287/ (11% failures)

Those sure seem consistent with 7919ced making the problem much worse, presumably as some indirect side effect. I wonder if the next step is to sorta bisect the individual line changes in that commit (since outside of the lint tool changes, they are mostly self-contained) to get to the bottom of which one (if it's indeed only one) is causing the issue.

[Trott]

So, I bisected on individual file changes and the one that is causing the issue is Trott@845adb7 which is totally puzzling to me, but maybe @not-an-aardvark or @aduh95 would have a reasonable explanation (assuming my results hold up to further scrutiny, which I will definitely be applying to confirm).