Investigate flaky test-webcrypto-encrypt-decrypt-aes on rhe17-s390x

[jasnell]

The aes encrypt/decrypt webcrypto test appears to be periodically flaky only on rhe17-s390x. Definitely unable to reproduce reliably. Will be investigating.

https://ci.nodejs.org/job/node-test-commit-linuxone/23391/nodes=rhel7-s390x/testReport/junit/(root)/test/parallel_test_webcrypto_encrypt_decrypt_aes/

• Test: parallel/test-webcrypto-encrypt-decrypt-aes
• Platform: rhe17-s390x
• Console Output:

node:internal/process/promises:218
          triggerUncaughtException(err, true /* fromPromise */);
          ^

AssertionError [ERR_ASSERTION]: Expected values to be strictly equal:
+ actual - expected

+ '546869732073706563696669636174696f6e206465736372696265732061204a6176615363726970742041504920666f7220706572666f726d696e672062617369632063727970746f67726170686963206f7065726174696f6e7320696e20776562206170706c69636174696f6e732c20737563682061732068617368696e672c207369676e61747572652067656e65726174696f6e20616e6420766572696669636174696f6e2c20616e6420656e6372797074696f6e20616e642064656372797074696f6e2e204164646974696f6e616c6c792c2069742064657363726962657320616e2041504920666f72206170706c69636174696f6e7320746f2067656e657261746520616e642f6f72206d616e61676520746865206b6579696e67206d6174657269616c206e656365737361727920746f20706572666f726d207468657365206f7065726174696f6e732e205573657320666f722074686973204150492072616e67652066726f6d2075736572206f7220736572766963652061757468656e7469636174696f6e2c20646f63756d656e74206f7220636f6465207369676e696e672c20616e642074686520636f6e666964656e7469616c69747920616e6420696e74656772697479206f6620636f6d6d756e69636174696f6e732e'
- 'ab6869732073706563696669636174696f6e206465736372696265732061204a6176615363726970742041504920666f7220706572666f726d696e672062617369632063727970746f67726170686963206f7065726174696f6e7320696e20776562206170706c69636174696f6e732c20737563682061732068617368696e672c207369676e61747572652067656e65726174696f6e20616e6420766572696669636174696f6e2c20616e6420656e6372797074696f6e20616e642064656372797074696f6e2e204164646974696f6e616c6c792c2069742064657363726962657320616e2041504920666f72206170706c69636174696f6e7320746f2067656e657261746520616e642f6f72206d616e61676520746865206b6579696e67206d6174657269616c206e656365737361727920746f20706572666f726d207468657365206f7065726174696f6e732e205573657320666f722074686973204150492072616e67652066726f6d2075736572206f7220736572766963652061757468656e7469636174696f6e2c20646f63756d656e74206f7220636f6465207369676e696e672c20616e642074686520636f6e666964656e7469616c69747920616e6420696e74656772697479206f6620636f6d6d756e69636174696f6e732e'
    at testEncrypt (/home/iojs/build/workspace/node-test-commit-linuxone/nodes/rhel7-s390x/test/parallel/test-webcrypto-encrypt-decrypt-aes.js:29:10)
    at async Promise.all (index 4)
    at async /home/iojs/build/workspace/node-test-commit-linuxone/nodes/rhel7-s390x/test/parallel/test-webcrypto-encrypt-decrypt-aes.js:196:5 {
  generatedMessage: true,
  code: 'ERR_ASSERTION',
  actual: '546869732073706563696669636174696f6e206465736372696265732061204a6176615363726970742041504920666f7220706572666f726d696e672062617369632063727970746f67726170686963206f7065726174696f6e7320696e20776562206170706c69636174696f6e732c20737563682061732068617368696e672c207369676e61747572652067656e65726174696f6e20616e6420766572696669636174696f6e2c20616e6420656e6372797074696f6e20616e642064656372797074696f6e2e204164646974696f6e616c6c792c2069742064657363726962657320616e2041504920666f72206170706c69636174696f6e7320746f2067656e657261746520616e642f6f72206d616e61676520746865206b6579696e67206d6174657269616c206e656365737361727920746f20706572666f726d207468657365206f7065726174696f6e732e205573657320666f722074686973204150492072616e67652066726f6d2075736572206f7220736572766963652061757468656e7469636174696f6e2c20646f63756d656e74206f7220636f6465207369676e696e672c20616e642074686520636f6e666964656e7469616c69747920616e6420696e74656772697479206f6620636f6d6d756e69636174696f6e732e',
  expected: 'ab6869732073706563696669636174696f6e206465736372696265732061204a6176615363726970742041504920666f7220706572666f726d696e672062617369632063727970746f67726170686963206f7065726174696f6e7320696e20776562206170706c69636174696f6e732c20737563682061732068617368696e672c207369676e61747572652067656e65726174696f6e20616e6420766572696669636174696f6e2c20616e6420656e6372797074696f6e20616e642064656372797074696f6e2e204164646974696f6e616c6c792c2069742064657363726962657320616e2041504920666f72206170706c69636174696f6e7320746f2067656e657261746520616e642f6f72206d616e61676520746865206b6579696e67206d6174657269616c206e656365737361727920746f20706572666f726d207468657365206f7065726174696f6e732e205573657320666f722074686973204150492072616e67652066726f6d2075736572206f7220736572766963652061757468656e7469636174696f6e2c20646f63756d656e74206f7220636f6465207369676e696e672c20616e642074686520636f6e666964656e7469616c69747920616e6420696e74656772697479206f6620636f6d6d756e69636174696f6e732e',
  operator: 'strictEqual'
}

• Build Links: https://ci.nodejs.org/job/node-test-commit-linuxone/23391/nodes=rhel7-s390x/testReport/junit/(root)/test/parallel_test_webcrypto_encrypt_decrypt_aes/

[sxa]

How frequently is it failing? Just tried on one my my RHEL7 s390x boxes (from master) and it seems to have got through a few hundred iterations without a failure but I'll leave it running a while longer :-)

[jasnell]

Really unclear to be honest. I got through 1000+ iterations without it failing, but then again, I've only seen it fail in full CI runs so it's possible that it only fails when there are other tests running concurrently?

[sxa]

OK I did get my first failure after probably about 10,000 runs so it definitely is NOT specific to your system (I'm not certain if there might have been other activity at the time, but it is failing every so often). Interesting that it's just the first two digits that seem to be different (unless my eyes have missed another difference - quite possible) and it's always the same mismatch.

[sxa]

Also checked on an Ubuntu machine (as well as the RHEL7 one while not running anything else) and it has reproduced there to. I've also seen it occurring on line 120 and 159 in the test case as well as 196. Note that on Ubuntu I used a binary compiled on the Ubuntu machine itself so was likely using a slightly different toolchain for the build (although it was still against openssl 1.0.2g so not 1.1)

process/promises:218
          triggerUncaughtException(err, true /* fromPromise */);
          ^

AssertionError [ERR_ASSERTION]: Expected values to be strictly equal:
+ actual - expected

+ '546869732073706563696669636174696f6e206465736372696265732061204a6176615363726970742041504920666f7220706572666f726d696e672062617369632063727970746f67726170686963206f7065726174696f6e7320696e20776562206170706c69636174696f6e732c20737563682061732068617368696e672c207369676e61747572652067656e65726174696f6e20616e6420766572696669636174696f6e2c20616e6420656e6372797074696f6e20616e642064656372797074696f6e2e204164646974696f6e616c6c792c2069742064657363726962657320616e2041504920666f72206170706c69636174696f6e7320746f2067656e657261746520616e642f6f72206d616e61676520746865206b6579696e67206d6174657269616c206e656365737361727920746f20706572666f726d207468657365206f7065726174696f6e732e205573657320666f722074686973204150492072616e67652066726f6d2075736572206f7220736572766963652061757468656e7469636174696f6e2c20646f63756d656e74206f7220636f6465207369676e696e672c20616e642074686520636f6e666964656e7469616c69747920616e6420696e74656772697479206f6620636f6d6d756e69636174696f6e732e'
- 'ab6869732073706563696669636174696f6e206465736372696265732061204a6176615363726970742041504920666f7220706572666f726d696e672062617369632063727970746f67726170686963206f7065726174696f6e7320696e20776562206170706c69636174696f6e732c20737563682061732068617368696e672c207369676e61747572652067656e65726174696f6e20616e6420766572696669636174696f6e2c20616e6420656e6372797074696f6e20616e642064656372797074696f6e2e204164646974696f6e616c6c792c2069742064657363726962657320616e2041504920666f72206170706c69636174696f6e7320746f2067656e657261746520616e642f6f72206d616e61676520746865206b6579696e67206d6174657269616c206e656365737361727920746f20706572666f726d207468657365206f7065726174696f6e732e205573657320666f722074686973204150492072616e67652066726f6d2075736572206f7220736572766963652061757468656e7469636174696f6e2c20646f63756d656e74206f7220636f6465207369676e696e672c20616e642074686520636f6e666964656e7469616c69747920616e6420696e74656772697479206f6620636f6d6d756e69636174696f6e732e'
    at testEncrypt (/home/sxa/node/test/parallel/test-webcrypto-encrypt-decrypt-aes.js:29:10)
    at async Promise.all (index 0)
    at async /home/sxa/node/test/parallel/test-webcrypto-encrypt-decrypt-aes.js:120:5 {
  generatedMessage: true,
  code: 'ERR_ASSERTION',
  actual: '546869732073706563696669636174696f6e206465736372696265732061204a6176615363726970742041504920666f7220706572666f726d696e672062617369632063727970746f67726170686963206f7065726174696f6e7320696e20776562206170706c69636174696f6e732c20737563682061732068617368696e672c207369676e61747572652067656e65726174696f6e20616e6420766572696669636174696f6e2c20616e6420656e6372797074696f6e20616e642064656372797074696f6e2e204164646974696f6e616c6c792c2069742064657363726962657320616e2041504920666f72206170706c69636174696f6e7320746f2067656e657261746520616e642f6f72206d616e61676520746865206b6579696e67206d6174657269616c206e656365737361727920746f20706572666f726d207468657365206f7065726174696f6e732e205573657320666f722074686973204150492072616e67652066726f6d2075736572206f7220736572766963652061757468656e7469636174696f6e2c20646f63756d656e74206f7220636f6465207369676e696e672c20616e642074686520636f6e666964656e7469616c69747920616e6420696e74656772697479206f6620636f6d6d756e69636174696f6e732e',
  expected: 'ab6869732073706563696669636174696f6e206465736372696265732061204a6176615363726970742041504920666f7220706572666f726d696e672062617369632063727970746f67726170686963206f7065726174696f6e7320696e20776562206170706c69636174696f6e732c20737563682061732068617368696e672c207369676e61747572652067656e65726174696f6e20616e6420766572696669636174696f6e2c20616e6420656e6372797074696f6e20616e642064656372797074696f6e2e204164646974696f6e616c6c792c2069742064657363726962657320616e2041504920666f72206170706c69636174696f6e7320746f2067656e657261746520616e642f6f72206d616e61676520746865206b6579696e67206d6174657269616c206e656365737361727920746f20706572666f726d207468657365206f7065726174696f6e732e205573657320666f722074686973204150492072616e67652066726f6d2075736572206f7220736572766963652061757468656e7469636174696f6e2c20646f63756d656e74206f7220636f6465207369676e696e672c20616e642074686520636f6e666964656e7469616c69747920616e6420696e74656772697479206f6620636f6d6d756e69636174696f6e732e',
  operator: 'strictEqual'
}

[miladfarca]

Hello, here is what's causing the issue. I have modified the test as such to make it easier to explain:

var global=0; /* added global */
async function testEncrypt({ keyBuffer, algorithm, plaintext, result }, i /* passing global */) {
.
.
.

  const output = await subtle.encrypt(algorithm, key, plaintext);   console.log(i, "a");
  plaintext[0] = 255 - plaintext[0];                                console.log(i, "b");
.
.
.

  const check = await subtle.decrypt(algorithm, key, output);        console.log(i, "c");
  output[0] = 255 - output[0];                                       console.log(i, "d");

  assert.strictEqual(
    Buffer.from(check).toString('hex'),
    Buffer.from(plaintext).toString('hex'));
}
.
.
.
 passing.forEach((vector) => {
    testEncrypt(vector, global++ /* incrementing global */);
 });

Running the test would normally give this output:

0 a
0 b
1 a
1 b
0 c
0 d
1 c
1 d

But on s390x, this pattern might happen which causes the failure:

0 a
0 b
0 c
0 d
...

I'm not sure why the test case is written as it is, the first async execution of plaintext[0] = 255 - plaintext[0]; changes first byte of plaintext from 0x54 to 0xab and the second async execution of testEncrypt is supposed to change it back to normal by essentially doing another 255 - plaintext[0]; (which turns 0xab to 0x54)?

In this case, a single async execution of testEncrypt is finished before the other async execution has even started. First byte of plaintext is changed from 0x54 to 0xab (with 255 - plaintext[0]) and the assertion fails.

The actual decryption is heppening here: https://github.com/nodejs/node/blob/master/deps/openssl/config/archs/linux64-s390x/asm/crypto/aes/aes-s390x.S#L817

[mhdawson]

@jasnell ping

[Trott]

Still a thing:

https://ci.nodejs.org/job/node-test-commit-linux/nodes=centos7-64-gcc8/39912/console

00:15:08 not ok 2592 parallel/test-webcrypto-encrypt-decrypt-aes # TODO : Fix flaky test
00:15:09   ---
00:15:09   duration_ms: 0.695
00:15:09   severity: flaky
00:15:09   exitcode: 1
00:15:09   stack: |-
00:15:09     node:internal/process/promises:245
00:15:09               triggerUncaughtException(err, true /* fromPromise */);
00:15:09               ^
00:15:09     
00:15:09     AssertionError [ERR_ASSERTION]: Expected values to be strictly equal:
00:15:09     + actual - expected
00:15:09     
00:15:09     + '546869732073706563696669636174696f6e206465736372696265732061204a6176615363726970742041504920666f7220706572666f726d696e672062617369632063727970746f67726170686963206f7065726174696f6e7320696e20776562206170706c69636174696f6e732c20737563682061732068617368696e672c207369676e61747572652067656e65726174696f6e20616e6420766572696669636174696f6e2c20616e6420656e6372797074696f6e20616e642064656372797074696f6e2e204164646974696f6e616c6c792c2069742064657363726962657320616e2041504920666f72206170706c69636174696f6e7320746f2067656e657261746520616e642f6f72206d616e61676520746865206b6579696e67206d6174657269616c206e656365737361727920746f20706572666f726d207468657365206f7065726174696f6e732e205573657320666f722074686973204150492072616e67652066726f6d2075736572206f7220736572766963652061757468656e7469636174696f6e2c20646f63756d656e74206f7220636f6465207369676e696e672c20616e642074686520636f6e666964656e7469616c69747920616e6420696e74656772697479206f6620636f6d6d756e69636174696f6e732e'
00:15:09     - 'ab6869732073706563696669636174696f6e206465736372696265732061204a6176615363726970742041504920666f7220706572666f726d696e672062617369632063727970746f67726170686963206f7065726174696f6e7320696e20776562206170706c69636174696f6e732c20737563682061732068617368696e672c207369676e61747572652067656e65726174696f6e20616e6420766572696669636174696f6e2c20616e6420656e6372797074696f6e20616e642064656372797074696f6e2e204164646974696f6e616c6c792c2069742064657363726962657320616e2041504920666f72206170706c69636174696f6e7320746f2067656e657261746520616e642f6f72206d616e61676520746865206b6579696e67206d6174657269616c206e656365737361727920746f20706572666f726d207468657365206f7065726174696f6e732e205573657320666f722074686973204150492072616e67652066726f6d2075736572206f7220736572766963652061757468656e7469636174696f6e2c20646f63756d656e74206f7220636f6465207369676e696e672c20616e642074686520636f6e666964656e7469616c69747920616e6420696e74656772697479206f6620636f6d6d756e69636174696f6e732e'
00:15:09         at testEncrypt (/home/iojs/build/workspace/node-test-commit-linux/nodes/centos7-64-gcc8/test/parallel/test-webcrypto-encrypt-decrypt-aes.js:29:10)
00:15:09         at async Promise.all (index 4)
00:15:09         at async /home/iojs/build/workspace/node-test-commit-linux/nodes/centos7-64-gcc8/test/parallel/test-webcrypto-encrypt-decrypt-aes.js:196:5 {
00:15:09       generatedMessage: true,
00:15:09       code: 'ERR_ASSERTION',
00:15:09       actual: '546869732073706563696669636174696f6e206465736372696265732061204a6176615363726970742041504920666f7220706572666f726d696e672062617369632063727970746f67726170686963206f7065726174696f6e7320696e20776562206170706c69636174696f6e732c20737563682061732068617368696e672c207369676e61747572652067656e65726174696f6e20616e6420766572696669636174696f6e2c20616e6420656e6372797074696f6e20616e642064656372797074696f6e2e204164646974696f6e616c6c792c2069742064657363726962657320616e2041504920666f72206170706c69636174696f6e7320746f2067656e657261746520616e642f6f72206d616e61676520746865206b6579696e67206d6174657269616c206e656365737361727920746f20706572666f726d207468657365206f7065726174696f6e732e205573657320666f722074686973204150492072616e67652066726f6d2075736572206f7220736572766963652061757468656e7469636174696f6e2c20646f63756d656e74206f7220636f6465207369676e696e672c20616e642074686520636f6e666964656e7469616c69747920616e6420696e74656772697479206f6620636f6d6d756e69636174696f6e732e',
00:15:09       expected: 'ab6869732073706563696669636174696f6e206465736372696265732061204a6176615363726970742041504920666f7220706572666f726d696e672062617369632063727970746f67726170686963206f7065726174696f6e7320696e20776562206170706c69636174696f6e732c20737563682061732068617368696e672c207369676e61747572652067656e65726174696f6e20616e6420766572696669636174696f6e2c20616e6420656e6372797074696f6e20616e642064656372797074696f6e2e204164646974696f6e616c6c792c2069742064657363726962657320616e2041504920666f72206170706c69636174696f6e7320746f2067656e657261746520616e642f6f72206d616e61676520746865206b6579696e67206d6174657269616c206e656365737361727920746f20706572666f726d207468657365206f7065726174696f6e732e205573657320666f722074686973204150492072616e67652066726f6d2075736572206f7220736572766963652061757468656e7469636174696f6e2c20646f63756d656e74206f7220636f6465207369676e696e672c20616e642074686520636f6e666964656e7469616c69747920616e6420696e74656772697479206f6620636f6d6d756e69636174696f6e732e',
00:15:09       operator: 'strictEqual'
00:15:09     }
00:15:09   ...