Skip to content
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.

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

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

Closed
bnoordhuis opened this issue Sep 23, 2016 · 13 comments
Closed
Labels
crypto Issues and PRs related to the crypto subsystem. test Issues and PRs related to the tests.

Comments

@bnoordhuis
Copy link
Member

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

@bnoordhuis bnoordhuis added crypto Issues and PRs related to the crypto subsystem. test Issues and PRs related to the tests. labels Sep 23, 2016
@not-an-aardvark
Copy link
Contributor

not-an-aardvark commented Sep 23, 2016

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
Copy link
Member Author

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
Copy link
Contributor

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
Copy link
Contributor

not-an-aardvark commented Sep 23, 2016

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
Copy link
Member Author

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
Copy link
Member Author

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
Copy link
Contributor

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

@bnoordhuis
Copy link
Member Author

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
Copy link
Contributor

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
Copy link
Member Author

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

@MylesBorins
Copy link
Contributor

@bnoordhuis
Copy link
Member Author

#9241

@jasnell
Copy link
Member

jasnell commented Oct 22, 2016

fyi... it just failed here also: https://ci.nodejs.org/job/node-test-commit-freebsd/4945/nodes=freebsd10-64/console ... this flakiness seems relatively new.

bnoordhuis added a commit to bnoordhuis/io.js that referenced this issue Oct 24, 2016
Increase the number of iterations from 1e4 to 1e5.  Makes the test pass
for me locally when previously it would fail 9 out of 10 times because
the running time was not enough to smooth away the outliers.

Fixes: nodejs#8744
PR-URL: nodejs#9241
Reviewed-By: Colin Ihrig <cjihrig@gmail.com>
Reviewed-By: James M Snell <jasnell@gmail.com>
Reviewed-By: not-an-aardvark <not-an-aardvark@users.noreply.github.com>
evanlucas pushed a commit that referenced this issue Nov 2, 2016
Move sequential/test-crypto-timing-safe-equal-benchmarks to test/pummel
because it fails for me locally quite frequently and because it takes
about five or six seconds to complete, which is too long for a test in
test/sequential.

Fixes: #8744
PR-URL: #9241
Reviewed-By: Colin Ihrig <cjihrig@gmail.com>
Reviewed-By: James M Snell <jasnell@gmail.com>
Reviewed-By: not-an-aardvark <not-an-aardvark@users.noreply.github.com>
evanlucas pushed a commit that referenced this issue Nov 2, 2016
Increase the number of iterations from 1e4 to 1e5.  Makes the test pass
for me locally when previously it would fail 9 out of 10 times because
the running time was not enough to smooth away the outliers.

Fixes: #8744
PR-URL: #9241
Reviewed-By: Colin Ihrig <cjihrig@gmail.com>
Reviewed-By: James M Snell <jasnell@gmail.com>
Reviewed-By: not-an-aardvark <not-an-aardvark@users.noreply.github.com>
MylesBorins pushed a commit that referenced this issue Nov 17, 2016
Move sequential/test-crypto-timing-safe-equal-benchmarks to test/pummel
because it fails for me locally quite frequently and because it takes
about five or six seconds to complete, which is too long for a test in
test/sequential.

Fixes: #8744
PR-URL: #9241
Reviewed-By: Colin Ihrig <cjihrig@gmail.com>
Reviewed-By: James M Snell <jasnell@gmail.com>
Reviewed-By: not-an-aardvark <not-an-aardvark@users.noreply.github.com>
MylesBorins pushed a commit that referenced this issue Nov 17, 2016
Increase the number of iterations from 1e4 to 1e5.  Makes the test pass
for me locally when previously it would fail 9 out of 10 times because
the running time was not enough to smooth away the outliers.

Fixes: #8744
PR-URL: #9241
Reviewed-By: Colin Ihrig <cjihrig@gmail.com>
Reviewed-By: James M Snell <jasnell@gmail.com>
Reviewed-By: not-an-aardvark <not-an-aardvark@users.noreply.github.com>
MylesBorins pushed a commit that referenced this issue Nov 19, 2016
Move sequential/test-crypto-timing-safe-equal-benchmarks to test/pummel
because it fails for me locally quite frequently and because it takes
about five or six seconds to complete, which is too long for a test in
test/sequential.

Fixes: #8744
PR-URL: #9241
Reviewed-By: Colin Ihrig <cjihrig@gmail.com>
Reviewed-By: James M Snell <jasnell@gmail.com>
Reviewed-By: not-an-aardvark <not-an-aardvark@users.noreply.github.com>
MylesBorins pushed a commit that referenced this issue Nov 19, 2016
Increase the number of iterations from 1e4 to 1e5.  Makes the test pass
for me locally when previously it would fail 9 out of 10 times because
the running time was not enough to smooth away the outliers.

Fixes: #8744
PR-URL: #9241
Reviewed-By: Colin Ihrig <cjihrig@gmail.com>
Reviewed-By: James M Snell <jasnell@gmail.com>
Reviewed-By: not-an-aardvark <not-an-aardvark@users.noreply.github.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
crypto Issues and PRs related to the crypto subsystem. test Issues and PRs related to the tests.
Projects
None yet
Development

No branches or pull requests

4 participants