Repository navigation
investigate flaky test-crypto-timing-safe-equal-benchmarks #38226
Description
Activity
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
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 +0200lib: 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
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
numTimesfrom1e5to a larger value help or does that defeat the purpose of the test?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
timingSafeEqualis 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
numTrialswould 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.timingSafeEqualin #8040, we considered using a "double HMAC" implementation rather thanCRYPTO_memcmp, but decided onCRYPTO_memcmpbecause 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.timingSafeEqualto use both double HMAC andCRYPTO_memcmp(i.e. given buffersaandb, return the result ofCRYPTO_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_memcmpand double HMAC wouldn't make anything worse in that regard.Reacted by Rich TrottBisect 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 MThe 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)
In this case, it seems like the t-values are routinely 9 and above, which wouldn't plausibly happen by chance.
When I increase
numTimesto1e6, I got a whoppingtvalue of37.871320438939634which I imagine is not moving in the right direction.....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.
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).
- added a commit that references this issue
on Apr 30, 2021 26 remaining items
- added a commit that references this issue
on Nov 27, 2023 - added 2 commits that reference this issue
on Apr 25, 2024 Seems to be failing a lot on MacOS now. An example:
https://github.com/nodejs/node/actions/runs/8822600805/job/24221172295?pr=52671
=== release test-crypto-timing-safe-equal-benchmarks === Path: pummel/test-crypto-timing-safe-equal-benchmarks Error: --- stderr --- node:assert:408 throw err; ^ AssertionError [ERR_ASSERTION]: timingSafeEqual should not leak information from its execution time (t=8.54045763079109) at Object.<anonymous> (/Users/runner/work/node/node/test/pummel/test-crypto-timing-safe-equal-benchmarks.js:109:1) at Module._compile (node:internal/modules/cjs/loader:1476:14) at Module._extensions..js (node:internal/modules/cjs/loader:1555:10) at Module.load (node:internal/modules/cjs/loader:1288:32) at Module._load (node:internal/modules/cjs/loader:1104:12) at Function.executeUserEntryPoint [as runMain] (node:internal/modules/run_main:191:14) at node:internal/main/run_main_module:30:49 { generatedMessage: false, code: 'ERR_ASSERTION', actual: false, expected: true, operator: '==' }- added a commit that references this issue
on May 1, 2024 - added a commit that references this issue
on May 8, 2024 - added a commit that references this issue
on Jun 17, 2024 - added a commit that references this issue
on Jun 20, 2024 - added a commit that references this issue
on May 22, 2026 - added a commit that references this issue
on Sep 5, 2026
pummel/test-crypto-timing-safe-equal-benchmarksseems 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.