grpc: Concurrent RPCs over TLS with nodejs client fail due to TLS errors

What version of gRPC and what language are you using?

• grpc 1.6.0

What operating system (Linux, Windows, …) and version?

• Ubuntu Linux 16.04.3 LTS
• Kernel: Linux 4.4.0-1022-aws #31-Ubuntu (x86_64)
• OpenSSL 1.0.2g

What runtime / compiler are you using (e.g. python version or version of gcc)

• node v6.11.2

What did you do?

We ran a simple grpc server and client, both written in nodejs, on the same host. (See below for codes) The client repeatedly invoked RPCs concurrently to the same server, and we increased the number of the simultaneous requests.

Server source code:

'use strict';

process.env.GRPC_SSL_CIPHER_SUITES = "ECDHE-RSA-AES128-GCM-SHA256:ECDHE-RSA-AES128-SHA256:ECDHE-RSA-AES256-SHA384:ECDHE-RSA-AES256-GCM-SHA384:ECDHE-ECDSA-AES128-GCM-SHA256:ECDHE-ECDSA-AES128-SHA256:ECDHE-ECDSA-AES256-SHA384:ECDHE-ECDSA-AES256-GCM-SHA384";

const grpc = require('grpc');
const crypto = require('crypto');
const fs = require('fs');

const testProto = grpc.load(__dirname + '/test.proto');
const test = testProto.test;

const server = new grpc.Server();
server.addService(test.TestService.service, { GetHashedValue: getHashedValue });

const rootCA = fs.readFileSync(__dirname + '/tls/ca.crt');
const serverpem = fs.readFileSync(__dirname + '/tls/server.crt');
const privkey = fs.readFileSync(__dirname + '/tls/server.key');
const cred = grpc.ServerCredentials.createSsl(rootCA, [{ private_key : privkey, cert_chain : serverpem }], false);

server.bind('0.0.0.0:9998', cred);
server.start();

function getHashedValue(call, callback) {
	callback(null, __getHashedValue(call.request));
}

function __getHashedValue(input) {
	// Dummy calculation
	var i = 0;
	while (!crypto.createHash('sha256').update(input.data + i).digest('hex').startsWith('00')) {
		i++;
	}
	
	return {
		hash_md5 : crypto.createHash('md5').update(input.data).digest('hex'),
		hash_sha256 : crypto.createHash('sha256').update(input.data).digest('hex'),
		nonce : i.toString()
	};
}

Client source code (mutliclient.js)

'use strict';

const grpc = require('grpc');
const fs = require('fs');
const util = require('util');

const testProto = grpc.load(__dirname + '/test.proto');
const test = testProto.test;

process.env.GRPC_SSL_CIPHER_SUITES = "ECDHE-RSA-AES128-GCM-SHA256:ECDHE-RSA-AES128-SHA256:ECDHE-RSA-AES256-SHA384:ECDHE-RSA-AES256-GCM-SHA384:ECDHE-ECDSA-AES128-GCM-SHA256:ECDHE-ECDSA-AES128-SHA256:ECDHE-ECDSA-AES256-SHA384:ECDHE-ECDSA-AES256-GCM-SHA384";

var opts = { 'grpc.ssl_target_name_override' : 'orderer0.example.com',
             'grpc.default_authority' : 'orderer0.example.com' };

function GetHashedValue(stub, data) {
	return new Promise((resolve, reject) => {
		let t = setTimeout(() => { reject('timeout'); }, 10000);
		stub.getHashedValue({ data : data }, (err, output) => {
			clearTimeout(t);
			if (err) {
				reject(err);
			} else {
				resolve(output);
			}
		});
	});
}

function getStub(addr) {
	const rootCA = fs.readFileSync(__dirname + '/tls/ca.crt');
	const cred = grpc.credentials.createSsl(rootCA);
	
	return new test.TestService(addr, cred, opts);
}

var mainPromise = Promise.resolve();
for (let i = 0; i < 1000; i++) {
	mainPromise = mainPromise.then(() => {
		let promises = [];
		for (let c = 0; c < 10; c++) {
			promises.push(GetHashedValue(getStub(util.format('localhost:%d', 9998)), 'abcde')
			              .then(
				              (output) => {
				              },
				              (err) => {
					              console.log(util.format("Error : i = %d, c = %d", i, c));
					              console.log(err);
				              }
			              ));
		}
		return Promise.all(promises);
	});
}

What did you expect to see?

All RPCs finished successfully with no error message.

What did you see instead?

SSL-related error messages in the client side as below:

(10 simultaneous requests for 1000 loops)
$ node multiclient.js
E0918 19:15:13.549735953    9191 ssl_transport_security.c:575] Could not add root certificate to ssl context.
E0918 19:15:13.549784041    9191 ssl_transport_security.c:1297] Cannot load server root certificates.
E0918 19:15:13.549809507    9191 security_connector.c:857]   Handshaker factory creation failed with TSI_INTERNAL_ERROR.
E0918 19:15:13.549817436    9191 secure_channel_create.c:112] Failed to create secure subchannel for secure name 'localhost:9998'
E0918 19:15:13.549823886    9191 secure_channel_create.c:143] Failed to create subchannel arguments during subchannel creation.
Error : i = 298, c = 9
timeout
E0918 19:15:23.555298724    9191 ssl_transport_security.c:575] Could not add root certificate to ssl context.
E0918 19:15:23.555327694    9191 ssl_transport_security.c:1297] Cannot load server root certificates.
E0918 19:15:23.555343490    9191 security_connector.c:857]   Handshaker factory creation failed with TSI_INTERNAL_ERROR.
E0918 19:15:23.555348706    9191 secure_channel_create.c:112] Failed to create secure subchannel for secure name 'localhost:9998'
E0918 19:15:23.555352415    9191 secure_channel_create.c:143] Failed to create subchannel arguments during subchannel creation.
E0918 19:15:23.555987397    9191 ssl_transport_security.c:575] Could not add root certificate to ssl context.
E0918 19:15:23.556007633    9191 ssl_transport_security.c:1297] Cannot load server root certificates.
E0918 19:15:23.556021100    9191 security_connector.c:857]   Handshaker factory creation failed with TSI_INTERNAL_ERROR.
E0918 19:15:23.556024783    9191 secure_channel_create.c:112] Failed to create secure subchannel for secure name 'localhost:9998'
E0918 19:15:23.556027500    9191 secure_channel_create.c:143] Failed to create subchannel arguments during subchannel creation.
E0918 19:15:23.556827941    9191 ssl_transport_security.c:575] Could not add root certificate to ssl context.
E0918 19:15:23.556849317    9191 ssl_transport_security.c:1297] Cannot load server root certificates.
E0918 19:15:23.556863770    9191 security_connector.c:857]   Handshaker factory creation failed with TSI_INTERNAL_ERROR.
E0918 19:15:23.556867610    9191 secure_channel_create.c:112] Failed to create secure subchannel for secure name 'localhost:9998'
E0918 19:15:23.556870305    9191 secure_channel_create.c:143] Failed to create subchannel arguments during subchannel creation.
E0918 19:15:23.557518465    9191 ssl_transport_security.c:575] Could not add root certificate to ssl context.
E0918 19:15:23.557534417    9191 ssl_transport_security.c:1297] Cannot load server root certificates.
E0918 19:15:23.557547464    9191 security_connector.c:857]   Handshaker factory creation failed with TSI_INTERNAL_ERROR.
E0918 19:15:23.557551147    9191 secure_channel_create.c:112] Failed to create secure subchannel for secure name 'localhost:9998'
E0918 19:15:23.557553896    9191 secure_channel_create.c:143] Failed to create subchannel arguments during subchannel creation.
E0918 19:15:23.558236543    9191 ssl_transport_security.c:575] Could not add root certificate to ssl context.
E0918 19:15:23.558256848    9191 ssl_transport_security.c:1297] Cannot load server root certificates.
E0918 19:15:23.558271198    9191 security_connector.c:857]   Handshaker factory creation failed with TSI_INTERNAL_ERROR.
E0918 19:15:23.558275183    9191 secure_channel_create.c:112] Failed to create secure subchannel for secure name 'localhost:9998'
E0918 19:15:23.558277977    9191 secure_channel_create.c:143] Failed to create subchannel arguments during subchannel creation.
E0918 19:15:23.558943764    9191 ssl_transport_security.c:575] Could not add root certificate to ssl context.
E0918 19:15:23.558964145    9191 ssl_transport_security.c:1297] Cannot load server root certificates.
E0918 19:15:23.558977869    9191 security_connector.c:857]   Handshaker factory creation failed with TSI_INTERNAL_ERROR.
E0918 19:15:23.558981556    9191 secure_channel_create.c:112] Failed to create secure subchannel for secure name 'localhost:9998'
E0918 19:15:23.558984202    9191 secure_channel_create.c:143] Failed to create subchannel arguments during subchannel creation.
Error : i = 299, c = 0
timeout
Error : i = 299, c = 1
timeout
Error : i = 299, c = 2
timeout
Error : i = 299, c = 3
timeout
Error : i = 299, c = 4
timeout
Error : i = 299, c = 5
timeout
E0918 19:15:36.283131370    9191 ssl_transport_security.c:575] Could not add root certificate to ssl context.
E0918 19:15:36.283162646    9191 ssl_transport_security.c:1297] Cannot load server root certificates.
E0918 19:15:36.283180800    9191 security_connector.c:857]   Handshaker factory creation failed with TSI_INTERNAL_ERROR.
E0918 19:15:36.283188059    9191 secure_channel_create.c:112] Failed to create secure subchannel for secure name 'localhost:9998'
E0918 19:15:36.283194759    9191 secure_channel_create.c:143] Failed to create subchannel arguments during subchannel creation.
Error : i = 353, c = 9
timeout
E0918 19:15:46.281421324    9191 ssl_transport_security.c:575] Could not add root certificate to ssl context.
E0918 19:15:46.281450162    9191 ssl_transport_security.c:1297] Cannot load server root certificates.
E0918 19:15:46.281465908    9191 security_connector.c:857]   Handshaker factory creation failed with TSI_INTERNAL_ERROR.
E0918 19:15:46.281470151    9191 secure_channel_create.c:112] Failed to create secure subchannel for secure name 'localhost:9998'
E0918 19:15:46.281473335    9191 secure_channel_create.c:143] Failed to create subchannel arguments during subchannel creation.
Error : i = 354, c = 0
timeout

No error messages are shown in the server.

Anything else we should know about your project / environment?

The error occurred probabilistically (so looks like due to some timing bug), and we observed that this can happen even with a small number of concurrency(such as c = 2).

We have got another type of error message like:

E0918 16:31:23.879222619    8681 ssl_transport_security.c:575] Could not add root certificate to ssl context.
E0918 16:31:23.879252246    8681 ssl_transport_security.c:1297] Cannot load server root certificates.
E0918 16:31:23.879300087    8681 security_connector.c:857]   Handshaker factory creation failed with TSI_INTERNAL_ERROR.
E0918 16:31:23.879306545    8681 secure_channel_create.c:112] Failed to create secure subchannel for secure name 'localhost:9998'
E0918 16:31:23.879309814    8681 secure_channel_create.c:143] Failed to create subchannel arguments during subchannel creation.
E0918 16:31:23.880015758    8681 ssl_transport_security.c:575] Could not add root certificate to ssl context.
E0918 16:31:23.880037639    8681 ssl_transport_security.c:1297] Cannot load server root certificates.
E0918 16:31:23.880055859    8681 security_connector.c:857]   Handshaker factory creation failed with TSI_INTERNAL_ERROR.
E0918 16:31:23.880063476    8681 secure_channel_create.c:112] Failed to create secure subchannel for secure name 'localhost:9998'
E0918 16:31:23.880069342    8681 secure_channel_create.c:143] Failed to create subchannel arguments during subchannel creation.
E0918 16:31:23.880760460    8681 ssl_transport_security.c:575] Could not add root certificate to ssl context.
E0918 16:31:23.880782242    8681 ssl_transport_security.c:1297] Cannot load server root certificates.
E0918 16:31:23.880801987    8681 security_connector.c:857]   Handshaker factory creation failed with TSI_INTERNAL_ERROR.
E0918 16:31:23.880809411    8681 secure_channel_create.c:112] Failed to create secure subchannel for secure name 'localhost:9998'
E0918 16:31:23.880815629    8681 secure_channel_create.c:143] Failed to create subchannel arguments during subchannel creation.
E0918 16:31:23.881436947    8681 ssl_transport_security.c:427] Corruption detected.
E0918 16:31:23.881468099    8681 ssl_transport_security.c:403] error:0B07C065:x509 certificate routines:X509_STORE_add_cert:cert already in hash table
E0918 16:31:23.881476868    8681 ssl_transport_security.c:403] error:0B07C065:x509 certificate routines:X509_STORE_add_cert:cert already in hash table
E0918 16:31:23.881484395    8681 ssl_transport_security.c:403] error:0B07C065:x509 certificate routines:X509_STORE_add_cert:cert already in hash table
E0918 16:31:23.881491065    8681 secure_endpoint.c:177]      Decryption error: TSI_DATA_CORRUPTED
Error : i = 514, c = 7
timeout
Error : i = 514, c = 8
timeout
Error : i = 514, c = 9
timeout