test-tls-root-certificates fails consistently on test-rackspace-win2012r2_vs2017-x64-3

[sam-github]

• Version: master
• Platform: windows
• Subsystem: tls

What steps will reproduce the bug?

Its failing consistently enough in CI it might be actually broken, not just flaky.

See:

• Consistent failures on windows js suites node#32507
• https://ci.nodejs.org/job/node-test-binary-windows-js-suites/RUN_SUBSET=1,nodes=win2012r2-COMPILED_BY-vs2019-x86/ the few reds I checked there were this issue
• https://ci.nodejs.org/job/node-test-binary-windows-js-suites/2670/RUN_SUBSET=1,nodes=win2012r2-COMPILED_BY-vs2019-x86/console this is an unrelated PR, should not have failed

Can anyone with access to Windows, @nodejs/platform-windows , bisect and see if one of the recent changes to tls root certs introduced this?

What do you see instead?

14:06:05 not ok 556 parallel/test-tls-root-certificates
14:06:05   ---
14:06:05   duration_ms: 0.375
14:06:05   severity: fail
14:06:05   exitcode: 1
14:06:05   stack: |-
14:06:05     assert.js:384
14:06:05         throw err;
14:06:05         ^
14:06:05     
14:06:05     AssertionError [ERR_ASSERTION]: The expression evaluated to a falsy value:
14:06:05     
14:06:05       assert(tls.rootCertificates.includes(extraCert))
14:06:05     
14:06:05         at Object.<anonymous> (C:\workspace\node-test-binary-windows-js-suites\node\test\parallel\test-tls-root-certificates.js:49:3)
14:06:05         at Module._compile (internal/modules/cjs/loader.js:1202:30)
14:06:05         at Object.Module._extensions..js (internal/modules/cjs/loader.js:1222:10)
14:06:05         at Module.load (internal/modules/cjs/loader.js:1051:32)
14:06:05         at Function.Module._load (internal/modules/cjs/loader.js:947:14)
14:06:05         at Function.executeUserEntryPoint [as runMain] (internal/modules/run_main.js:71:12)
14:06:05         at internal/main/run_main_module.js:17:47 {
14:06:05       generatedMessage: true,
14:06:05       code: 'ERR_ASSERTION',
14:06:05       actual: false,
14:06:05       expected: true,
14:06:05       operator: '=='
14:06:05     }
14:06:05     assert.js:102
14:06:05       throw new AssertionError(obj);
14:06:05       ^
14:06:05     
14:06:05     AssertionError [ERR_ASSERTION]: Expected values to be strictly equal:
14:06:05     
14:06:05     1 !== 0
14:06:05     
14:06:05         at ChildProcess.<anonymous> (C:\workspace\node-test-binary-windows-js-suites\node\test\parallel\test-tls-root-certificates.js:19:12)
14:06:05         at ChildProcess.<anonymous> (C:\workspace\node-test-binary-windows-js-suites\node\test\common\index.js:362:15)
14:06:05         at ChildProcess.emit (events.js:315:20)
14:06:05         at Process.ChildProcess._handle.onexit (internal/child_process.js:276:12) {
14:06:05       generatedMessage: true,
14:06:05       code: 'ERR_ASSERTION',
14:06:05       actual: 1,
14:06:05       expected: 0,
14:06:05       operator: 'strictEqual'
14:06:05     }
14:06:05   ...

[Trott]

@nodejs/testing @nodejs/platform-windows @nodejs/crypto

[Trott]

Can anyone with access to Windows, @nodejs/platform-windows , bisect and see if one of the recent changes to tls root certs introduced this?

Last node-daily-master without this failure was run on f4153c2fe7b54744e2201e397e1ac8345f222432.

First node-daily-master with this failure was run on f0a33d99ec4656b87bebb97162837047b52eb6f8.

Currently running a bisect locally but getting my "good"/"bad" results from runs on CI. Will comment again when I have some results.

[lpinca]

I can't reproduce locally (Windows 10).

[Trott]

It looks like the problem may not be the test itself but the host. The pattern I'm seeing is that when the test runs on test-rackspace-win2012r2_vs2017-x64-3, it seems to fail, but when it runs on test-rackspace-win2012r2_vs2017-x64-1, it passes. I'm not sure why it almost always runs on test-rackspace-win2012r2_vs2017-x64-3 lately, though.

I'm going to test this hypothesis now by marking test-rackspace-win2012r2_vs2017-x64-3 offline and re-running the things that failed while bisecting.

(The end result of the bisect was that 9e3eddc75dde9df9356264b42bd30facb82583cd was identified as the bad commit and that doesn't seem likely at all, which is why I started looking at which host was failing.)

Here are the failures on test-rackspace-win2012r2_vs2017-x64-3 from the bisect and their re-runs with test-rackspace-win2012r2_vs2017-x64-3 offline:

388cef61e8a4859b7505f7b5cf988eba27ce17b4: https://ci.nodejs.org/job/node-test-commit-windows-fanned/34925/ ❌
Re-run: https://ci.nodejs.org/job/node-test-commit-windows-fanned/34933/ ✅

05f1df520064475a255d8956f9e1b6f4bf4c8543: https://ci.nodejs.org/job/node-test-commit-windows-fanned/34927/ ❌
Re-run: https://ci.nodejs.org/job/node-test-commit-windows-fanned/34934/ ✅

9e3eddc75dde9df9356264b42bd30facb82583cd: https://ci.nodejs.org/job/node-test-commit-windows-fanned/34928/ ❌
Re-run: https://ci.nodejs.org/job/node-test-commit-windows-fanned/34935/ ✅

[Trott]

(And for good measure, here's a Resume Build for the node-daily-master that ran a few hours ago and had the test fail on rackspace-win2012r2_vs2017-x64-3.

https://ci.nodejs.org/job/node-daily-master/1885/ ✅

[Trott]

3 of the 4 have finished and they've all passed. The fourth one is still compiling, but I'm feeling good enough about this to change the name of the issue to reflect this and transfer it to the Build repo.

@nodejs/build Maybe someone needs to re-provision test-rackspace-win2012r2_vs2017-x64-3?

[Trott]

(And now it's passed on the fourth one as well.)

[sam-github]

@Trott thanks for all the trouble-shooting. @joaocgreis any ideas?

I ran ansible-playbook --limit test-rackspace-win2012r2_vs2017-x64-3 ./playbooks/jenkins/worker/create.yml -C and it looks like I have the auth to re-ansible that host, and its likely the correct playbook because it did make some checks, but I'm not sure if that is risky. Then again, if the host is already not suitable for CI, maybe it can't get worse?

[joaocgreis]

The issue was that test/fixtures/keys/ca1-cert.pem was changed to CRLF line endings. There is a .gitattributes file in that folder that should make it have LF line endings, but git did not notice the change in line endings.

This seems to happen when changing to a v10 branch, the .gitattributes file is not there. When checking out, git applies the autocrlf setting as it should, but when changing branches it does not. I'll have to take a look at the git issues to find if we should file an issue there or change something on our end. For now, I've added a workaround in the job config.

Test run: https://ci.nodejs.org/job/node-test-binary-windows-js-suites/2792/RUN_SUBSET=1,nodes=win2012r2-COMPILED_BY-vs2019-x86/ ✔️ (looks like Jenkins picked the node again for the same job as soon as it became available)

[Trott]

This seems to happen when changing to a v10 branch, the .gitattributes file is not there.

Wow! Not the root cause I was imagining. Thanks for the explanation!

[sam-github]

Thanks for the troubleshooting!

Maybe it is possible that we rework the test to not be sensitive to line-endings? That would allow the tests to be more robust independently of job config.

I'll take a look, from a quick glance, it looks like a return s.startsWith('-----BEGIN CERTIFICATE-----\n'); might just need to be changed to a regex that allows a CRLF or LF as a line ending.