test,crypto: sequential/test-crypto-timing-safe-equal-benchmarks flaky locally

[bnoordhuis]

Running make test on master I occasionally get this:

=== release test-crypto-timing-safe-equal-benchmarks ===                       
Path: sequential/test-crypto-timing-safe-equal-benchmarks
assert.js:85
  throw new assert.AssertionError({
  ^
AssertionError: Buffer#equals should leak information from its execution time (t=3.868786978019678)
    at Object.<anonymous> (/home/bnoordhuis/src/v1.x/test/sequential/test-crypto-timing-safe-equal-benchmarks.js:120:1)
    at Module._compile (module.js:560:32)
    at Object.Module._extensions..js (module.js:569:10)
    at Module.load (module.js:477:32)
    at tryModuleLoad (module.js:436:12)
    at Function.Module._load (module.js:428:3)
    at Module.runMain (module.js:594:10)
    at run (bootstrap_node.js:382:7)
    at startup (bootstrap_node.js:137:9)
    at bootstrap_node.js:497:3

cc @not-an-aardvark

[not-an-aardvark]

How often does this happen, roughly?

Is it always that error (Buffer#equals should leak information from its execution time) and not the other one?

[bnoordhuis]

Reasonably often. It's quite reliably fails on one machine:

$ for i in {1..5}; do time python tools/test.py sequential/test-crypto-timing-safe-equal-benchmarks; done
=== release test-crypto-timing-safe-equal-benchmarks ===
Path: sequential/test-crypto-timing-safe-equal-benchmarks
assert.js:85
  throw new assert.AssertionError({
  ^
AssertionError: Buffer#equals should leak information from its execution time (t=3.8164856358232466)
    at Object.<anonymous> (/home/bnoordhuis/src/v1.x/test/sequential/test-crypto-timing-safe-equal-benchmarks.js:120:1)
    at Module._compile (module.js:560:32)
    at Object.Module._extensions..js (module.js:569:10)
    at Module.load (module.js:477:32)
    at tryModuleLoad (module.js:436:12)
    at Function.Module._load (module.js:428:3)
    at Module.runMain (module.js:594:10)
    at run (bootstrap_node.js:382:7)
    at startup (bootstrap_node.js:137:9)
    at bootstrap_node.js:497:3
Command: out/Release/node /home/bnoordhuis/src/v1.x/test/sequential/test-crypto-timing-safe-equal-benchmarks.js
[00:06|% 100|+   0|-   1]: Done

real    0m6.430s
user    0m5.574s
sys     0m0.757s
=== release test-crypto-timing-safe-equal-benchmarks ===
Path: sequential/test-crypto-timing-safe-equal-benchmarks
assert.js:85
  throw new assert.AssertionError({
  ^
AssertionError: Buffer#equals should leak information from its execution time (t=1.814077479690536)
    at Object.<anonymous> (/home/bnoordhuis/src/v1.x/test/sequential/test-crypto-timing-safe-equal-benchmarks.js:120:1)
    at Module._compile (module.js:560:32)
    at Object.Module._extensions..js (module.js:569:10)
    at Module.load (module.js:477:32)
    at tryModuleLoad (module.js:436:12)
    at Function.Module._load (module.js:428:3)
    at Module.runMain (module.js:594:10)
    at run (bootstrap_node.js:382:7)
    at startup (bootstrap_node.js:137:9)
    at bootstrap_node.js:497:3   
Command: out/Release/node /home/bnoordhuis/src/v1.x/test/sequential/test-crypto-timing-safe-equal-benchmarks.js
[00:06|% 100|+   0|-   1]: Done  

real    0m6.829s
user    0m6.065s
sys     0m0.765s
[00:06|% 100|+   1|-   0]: Done  

real    0m6.614s
user    0m6.153s
sys     0m0.363s
=== release test-crypto-timing-safe-equal-benchmarks ===
Path: sequential/test-crypto-timing-safe-equal-benchmarks
assert.js:85
  throw new assert.AssertionError({
  ^
AssertionError: Buffer#equals should leak information from its execution time (t=0.5730173061217123)
    at Object.<anonymous> (/home/bnoordhuis/src/v1.x/test/sequential/test-crypto-timing-safe-equal-benchmarks.js:120:1)
    at Module._compile (module.js:560:32)
    at Object.Module._extensions..js (module.js:569:10)
    at Module.load (module.js:477:32)
    at tryModuleLoad (module.js:436:12)
    at Function.Module._load (module.js:428:3)
    at Module.runMain (module.js:594:10)
    at run (bootstrap_node.js:382:7)
    at startup (bootstrap_node.js:137:9)
    at bootstrap_node.js:497:3   
Command: out/Release/node /home/bnoordhuis/src/v1.x/test/sequential/test-crypto-timing-safe-equal-benchmarks.js
[00:06|% 100|+   0|-   1]: Done  

real    0m6.357s
user    0m6.167s
sys     0m0.146s

real    0m6.626s
user    0m5.833s
sys     0m0.772s

The other test seems solid:

$ for i in {1..5}; do time python tools/test.py sequential/test-crypto-timing-safe-equal; done
[00:00|% 100|+   1|-   0]: Done                                  

real    0m0.507s
user    0m0.327s
sys     0m0.069s
[00:00|% 100|+   1|-   0]: Done                                  

real    0m0.510s
user    0m0.331s
sys     0m0.067s
[00:00|% 100|+   1|-   0]: Done                                  

real    0m0.498s
user    0m0.321s
sys     0m0.077s
[00:00|% 100|+   1|-   0]: Done                                  

real    0m0.500s
user    0m0.328s
sys     0m0.061s
[00:00|% 100|+   1|-   0]: Done                                  

real    0m0.498s
user    0m0.327s
sys     0m0.071s

[not-an-aardvark]

Within test-crypto-timing-safe-equal-benchmarks, there are two assertions; one of them runs a statistical test to make sure crypto.timingSafeEqual is timing-safe, and the other runs the same statistical test to make sure Buffer#equals is not timing-safe (which is a sanity check to make sure the statistical test is working correctly).

It looks like the Buffer#equals sanity check is failing for some reason. I'll investigate it soon.

[not-an-aardvark]

I can't seem to reproduce the issue on OS X El Capitan 10.11.6, on the current version of master (782620f). Is the issue happening for you on Linux?

edit: Also, is the issue happening on any of the CI machines? If so, that will make it easier to debug.

[bnoordhuis]

Yes, this is on an otherwise unremarkable x86_64 FC24 laptop. I don't have an OS X machine at hand at the moment. I haven't (personally) seen the test fail on the CI recently.

[bnoordhuis]

Still fails for me every now and then on that one machine. Just now:

=== release test-crypto-timing-safe-equal-benchmarks ===
Path: sequential/test-crypto-timing-safe-equal-benchmarks
assert.js:85
  throw new assert.AssertionError({
  ^
AssertionError: Buffer#equals should leak information from its execution time (t=1.540870292754572)
    at Object.<anonymous> (/home/bnoordhuis/src/v1.x/test/sequential/test-crypto-timing-safe-equal-benchmarks.js:120:1)
    at Module._compile (module.js:573:32)
    at Object.Module._extensions..js (module.js:582:10)
    at Module.load (module.js:490:32)
    at tryModuleLoad (module.js:449:12)
    at Function.Module._load (module.js:441:3)
    at Module.runMain (module.js:607:10)
    at run (bootstrap_node.js:382:7)
    at startup (bootstrap_node.js:137:9)
    at bootstrap_node.js:497:3
Command: out/Release/node /home/bnoordhuis/src/v1.x/test/sequential/test-crypto-timing-safe-equal-benchmarks.js

[not-an-aardvark]

Could you try increasing this number by an order of magnitude or so, to see if that fixes the issue on that machine?

[bnoordhuis]

With numTrials = 1e5, the test passes five times in a row:

$ for i in {1..5}; do time python tools/test.py sequential/test-crypto-timing-safe-equal-benchmarks; done
[00:52|% 100|+   1|-   0]: Done                                             

real    0m52.511s
user    0m13.320s
sys     0m39.825s
[00:54|% 100|+   1|-   0]: Done                                             

real    0m55.037s
user    0m13.662s
sys     0m42.174s
[00:56|% 100|+   1|-   0]: Done                                             

real    0m57.227s
user    0m13.053s
sys     0m44.714s
[00:58|% 100|+   1|-   0]: Done                                             

real    0m58.835s
user    0m13.237s
sys     0m46.104s
[00:56|% 100|+   1|-   0]: Done                                             

real    0m56.657s
user    0m14.682s
sys     0m42.380s

Aside: 6 seconds for a sequential test is really too long. Sequential tests should ideally finish in under a second.

[not-an-aardvark]

Where should the test go instead? Pummel?

This is sort of an unusual test in that it requires running a very large number of benchmarks, so reducing the runtime without making it flakier is probably going to be non-trivial. But I'd be happy to move it to a different place if that makes it less annoying while developing.

[bnoordhuis]

Pummel is probably the best place for it. The one downside is that pummel tests aren't run regularly.

[MylesBorins]

here's a fail https://ci.nodejs.org/job/node-test-commit-smartos/4836/nodes=smartos15-64/tapTestReport/