Tracking: openSSL with asm on arm64

[refack]

• Version: master
• Platform: CI arm64
• Subsystem: test,crypto

https://github.com/nodejs/node/blob/master/test/parallel/test-https-client-get-url.js

Look nasty, hopefully 🤞 it is just a flake

https://ci.nodejs.org/job/node-test-commit-arm/19511/nodes=centos7-arm64-gcc6/testReport/junit/(root)/test/parallel_test_https_client_get_url/

Error Message
fail (1)

Stacktrace
(node:57030) Warning: Setting the NODE_TLS_REJECT_UNAUTHORIZED environment variable to '0' makes TLS connections and HTTPS requests insecure by disabling certificate verification.
events.js:167
      throw er; // Unhandled 'error' event
      ^

Error: 4396790469872:error:1408F119:SSL routines:ssl3_get_record:decryption failed or bad record mac:../deps/openssl/openssl/ssl/record/ssl3_record.c:469:

Emitted 'error' event at:
    at TLSSocket.socketErrorListener (_http_client.js:399:9)
    at TLSSocket.emit (events.js:182:13)
    at TLSSocket._emitTLSError (_tls_wrap.js:600:10)
    at TLSWrap.onerror (_tls_wrap.js:268:11)

/CC @nodejs/testing @nodejs/crypto

[ryzokuken]

@tniessen @bnoordhuis "bad record mac"? That shouldn't happen, right (especially intermittently).

[refack]

test.parallel/test-tls-pfx-authorizationerror

Error Message
fail (1)
Stacktrace
events.js:167
      throw er; // Unhandled 'error' event
      ^

Error: 281472993497088:error:1408F119:SSL routines:ssl3_get_record:decryption failed or bad record mac:../deps/openssl/openssl/ssl/record/ssl3_record.c:469:

Emitted 'error' event at:
    at TLSSocket._emitTLSError (_tls_wrap.js:600:10)
    at TLSWrap.onerror (_tls_wrap.js:268:11)

[refack]

test.parallel/test-https-client-checkServerIdentity

Error Message
fail (1)
Stacktrace
/home/iojs/build/workspace/node-test-commit-arm/nodes/ubuntu1604-arm64/test/parallel/test-https-client-checkServerIdentity.js:71
    throw err;
    ^

Error: 281472838037504:error:1408F119:SSL routines:ssl3_get_record:decryption failed or bad record mac:../deps/openssl/openssl/ssl/record/ssl3_record.c:469:

[refack]

Ref: #23241

[refack]

Ref: #23422

[refack]

Ref: #23261

[refack]

ping @nodejs/platform-arm @nodejs/crypto

Any recommendation how to workaround this?

[bnoordhuis]

If it only happens on arm64, it might be worthwhile to turn off assembly for a while on that architecture (./configure --openssl-no-asm) and see if the problem goes away.

[refack]

If it only happens on arm64, it might be worthwhile to turn off assembly for a while

Done, nodejs/build#1556.
I'll try to remember to report of outcome...

[shigeki]

I've never tested openssl asms of Node working on centos-arm64.

@refack Can I log in the machine and testing build openssl-1.1.0 and node?

[refack]

@shigeki does:
https://ci.nodejs.org/job/node-test-commit-arm/nodes=centos7-arm64-gcc6/19655/consoleFull (✔️)

12:24:34 python ./configure --verbose  --openssl-no-asm

enough?

[refack]

Haven't seen this fail on centos7-arm64-gcc6 since, but now it shows on ubuntu1604-arm64:

https://ci.nodejs.org/job/node-test-commit-arm/19612/nodes=ubuntu1604-arm64/console
test.parallel/test-https-eof-for-eom

Error Message
fail (1)

Stacktrace
1) Making Request
2) Server got request
3) Client got response headers.
events.js:167
      throw er; // Unhandled 'error' event
      ^

Error: 281473409806336:error:1408F119:SSL routines:ssl3_get_record:decryption failed or bad record mac:../deps/openssl/openssl/ssl/record/ssl3_record.c:469:

Emitted 'error' event at:
    at TLSSocket.socketErrorListener (_http_client.js:399:9)
    at TLSSocket.emit (events.js:182:13)
    at TLSSocket._emitTLSError (_tls_wrap.js:600:10)
    at TLSWrap.onerror (_tls_wrap.js:268:11)

[rvagg]

@refack if you're keeping track of this can you also record which arm64 machine it's happening on? I think this is the same as the error we had previously and it ended up occuring mainly (or only?) on one of the machines we have. There was a whole thread where I roped in openssl folks and packet.net folks but it was never fully resolved. IIRC it kind of died down. I'm sure the thread is still active somewhere, nodejs/build maybe.

[rvagg]

ftr test-packetnet-ubuntu1604-arm64-1 had a ton of node zombies on it. I bet this is related (don't know which way it's related). It may be that this machine is dodgy. If we get enough evidence of this one being a culprit we can get packet.net to get into it and figure out what the problem might be, likely hardware IMO.

[refack]

ftr test-packetnet-ubuntu1604-arm64-1 had a ton of node zombies on it.

I had a feeling that I've seen the failed or bad record mac mostly on test-packetnet-centos7-arm64-1, but the records point to more reports from test-packetnet-ubuntu1604-arm64-1 with some from test-packetnet-ubuntu1604-arm64-1

For the time being I added --openssl-no-asm for *centos7-arm64* (nodejs/build#1556)
Per: #23913 (comment)

[refack]

Last 48 hour:

test-packetnet-ubuntu1604-arm64-2 - https://ci.nodejs.org/job/node-test-commit-arm/nodes=ubuntu1604-arm64/19741/testReport/junit/(root)/test/parallel_test_tls_fast_writing/

test-packetnet-ubuntu1604-arm64-1 https://ci.nodejs.org/job/node-test-commit-arm/nodes=ubuntu1604-arm64/19556/testReport/junit/(root)/test/parallel_test_tls_pfx_authorizationerror/

(I'm hesitant to add --openssl-no-asm to these since it's the only coverage we have for openSSL asm on ARM64)

[rvagg]

yeah, let's not turn asm off totally for arm64 since we're shipping arm64 binaries without this option at the moment and it's not something we want left uncovered!

[bnoordhuis]

Does it happen on all arm64 machines or on a subset? I see only the ones mentioned in this issue on ci.nodejs.org so I'm guessing it's all of them?

If that's the case, the prudent thing to do is turn off assembly in release binaries for a while until we get to the bottom of this. Better slow than broken.

[refack]

Does it happen on all arm64 machines or on a subset?

Initially I saw it only on one specific machine, but since it seems to be happening on all 4 arm64 public CI workers (2 x centos7 + 2 x ubuntu1604).

[vielmetti]

@refack it took 4 hr 26 min but the Ubuntu stress test came back green. https://ci.nodejs.org/job/node-stress-single-test/2154/nodes=ubuntu1604-arm64/

CentOS took 2 hr 12 min and also came back green.
https://ci.nodejs.org/job/node-stress-single-test/nodes=centos7-arm64-gcc6/2154/

[vielmetti]

@shigeki are we confident that this is solved in the latest master? i see we have several tests with green, but I don't know that is enough.

[refack]

@vielmetti PTAL at https://ci.nodejs.org/job/node-test-commit-arm/23201/nodes=ubuntu1604-arm64/consoleText
The worker we call test-packetnet-ubuntu1604-arm64-1 (a.k.a. 147.75.77.130) is failing to calculate a checksum.

    #
    # Fatal error in , line 0
    # Check failed: VerifyChecksum(blob).
    #
    #
    #
    #FailureMessage Object: 0xffffd69589d8

No openSSL, just C++ stdlib.
Code line:

node/deps/v8/src/snapshot/snapshot-common.cc

Line 42 in 01b112a

CHECK(VerifyChecksum(blob));

Implementation:

node/deps/v8/src/snapshot/snapshot-common.cc

Lines 204 to 215 in 01b112a

	bool Snapshot::VerifyChecksum(const v8::StartupData* data) {
	base::ElapsedTimer timer;
	if (FLAG_profile_deserialization) timer.Start();
	uint32_t expected_a = GetHeaderValue(data, kChecksumPartAOffset);
	uint32_t expected_b = GetHeaderValue(data, kChecksumPartBOffset);
	Checksum checksum(ChecksummedContent(data));
	if (FLAG_profile_deserialization) {
	double ms = timer.Elapsed().InMillisecondsF();
	PrintF("[Verifying snapshot checksum took %0.3f ms]\n", ms);
	}
	return checksum.Check(expected_a, expected_b);
	}

node/deps/v8/src/snapshot/serializer-common.h

Lines 349 to 386 in 01b112a

	class Checksum {
	public:
	explicit Checksum(Vector<const byte> payload) {
	#ifdef MEMORY_SANITIZER
	// Computing the checksum includes padding bytes for objects like strings.
	// Mark every object as initialized in the code serializer.
	MSAN_MEMORY_IS_INITIALIZED(payload.start(), payload.length());
	#endif // MEMORY_SANITIZER
	// Fletcher's checksum. Modified to reduce 64-bit sums to 32-bit.
	uintptr_t a = 1;
	uintptr_t b = 0;
	const uintptr_t* cur = reinterpret_cast<const uintptr_t*>(payload.start());
	DCHECK(IsAligned(payload.length(), kIntptrSize));
	const uintptr_t* end = cur + payload.length() / kIntptrSize;
	while (cur < end) {
	// Unsigned overflow expected and intended.
	a += *cur++;
	b += a;
	}
	#if V8_HOST_ARCH_64_BIT
	a ^= a >> 32;
	b ^= b >> 32;
	#endif // V8_HOST_ARCH_64_BIT
	a_ = static_cast<uint32_t>(a);
	b_ = static_cast<uint32_t>(b);
	}
	bool Check(uint32_t a, uint32_t b) const { return a == a_ && b == b_; }
	uint32_t a() const { return a_; }
	uint32_t b() const { return b_; }
	private:
	uint32_t a_;
	uint32_t b_;
	DISALLOW_COPY_AND_ASSIGN(Checksum);
	};

[vielmetti]

I see a warning at the top

python ./configure --verbose 
WARNING: C++ compiler too old, need g++ 6.3.0 or clang++ 8.0.0 (CXX=ccache g++)

Is this related, @refack ?

[refack]

No, that warning was added in preparation for the next version of node due next month.
P.S. AFAICT from the logs this happened once for build 23201 at 7:08AM UTC 2019-03-26.

• The same binary is used for all tests
• 50 tests are run in parallel (50 procs from the same binary)
• It seemed to work up till test 707
• Once it started failing it persisted till the end of the run
• Next job run two hour later, all ok
• Same code was tested on other workers and passed - https://ci.nodejs.org/job/node-test-commit-arm/23201/

[vielmetti]

@refack - do you have access to any of the system logs for this machine? I'm wondering if there are contemporary console logs that would hint at temporary hardware failures.

On at least one similarly equipped system we were seeing flakes as a result of thermal issues under heavy sustained load, which ended up being chased back to a problem with a fan.

How is storage configured here ( are you using directly attached storage, or is it running off of an attached network block storage )? I want to also rule out drive failures.

[vielmetti]

Alternatively (and perhaps easier on everyone) if there are any indications that this is a hardware flake at all we should look at swapping out the hardware.

[rvagg]

A candidate for hardware problems: #25028, same machine shigeki was testing openssl on. Not confirmed, could be something else, worth watching though.

[vielmetti]

Is there an update on this issue?

I have some flexibility now (that I didn't have then) in swapping out hardware if it turns out that a particular piece of gear is having issues. Let me know if that would be appealing, now or in the future.

[rvagg]

@sam-github and @Trott correct me if I'm wrong but I don't think we've seen any systematic OpenSSL failures on ARM in a while now, either because of OpenSSL upgrades, the way we're using it, or something else! In fact I don't think we've had to do a whole lot of ARM64-specific work in a while now, quite stable. This is good news I think but we'll keep you informed @vielmetti, thanks for being a resource as always.

[richardlau]

@sam-github and @Trott correct me if I'm wrong but I don't think we've seen any systematic OpenSSL failures on ARM in a while now, either because of OpenSSL upgrades, the way we're using it, or something else! In fact I don't think we've had to do a whole lot of ARM64-specific work in a while now, quite stable. This is good news I think but we'll keep you informed @vielmetti, thanks for being a resource as always.

We haven't seen any failures but we turned off asm support for arm64 in #24270 and haven't reenabled it:

node/common.gypi

Lines 81 to 86 in 5c61c5d

	['target_arch=="arm64"', {
	# Disabled pending https://github.com/nodejs/node/issues/23913.
	'openssl_no_asm%': 1,
	}, {
	'openssl_no_asm%': 0,
	}],

[vielmetti]

Thanks @richardlau @rvagg - it's good that the system is stable, so that we can rule out infrastructure issues. However of course I'd always prefer not to see a performance regression.

Would it be worthwhile to test a new PR to turn asm support back on? And if you get any flakiness, I'm happy to look upstream for some more specialized vendor support and resources to take a look at what's going on.

[sam-github]

@vielmetti Definitely worthwhile, #23913 (comment) points to what would need changing, thanks for looking at this.

[vielmetti]

Thanks. The smallest PR I could imagine is in #28180 and the goal I see is to identify any flakiness associated with that one particular commit.

[rvagg]

I came across this today in the Jenkins setup, associated with the opening of this issue, invoked for arm64 centos:

    # temporary mesure to evaluate https://github.com/nodejs/node/issues/23913
    export CONFIG_FLAGS="$CONFIG_FLAGS --openssl-no-asm"

Runs in here: https://ci.nodejs.org/job/node-test-commit-arm

So I guess even with it re-enabled in #28180, we've still been compiling without asm.

@sam-github @vielmetti should I just yank it out and see what happens?

[sam-github]

Yes

[rvagg]

done, we shall see if anything shows up

[jasnell]

@nodejs/build @nodejs/crypto ... does this issue need to remain open?

[rvagg]

Have just confirmed the config entry is removed from CI (it was commented out but is now removed), so with #28180 in place and no reported problems since I think we can call this done!

[sxa]

Initially I saw it only on one specific machine, but since it seems to be happening on all 4 arm64 public CI workers (2 x centos7 + 2 x ubuntu1604).

FYI @vielmetti @refack this may be related to the issues I was seeing specifically on ThunderX systems unless OpenSSL was build without no-asm Ref adoptium/infrastructure#1897