Skip to content
This repository has been archived by the owner on Mar 8, 2020. It is now read-only.

Commit

Permalink
Add performance logging to connector (#4434)
Browse files Browse the repository at this point in the history 
contributes to #4428

Signed-off-by: Dave Kelsey <[email protected]>
  • Loading branch information
Dave Kelsey authored Oct 2, 2018
1 parent 0379752 commit 6d6a71a
Show file tree
Hide file tree
Showing 11 changed files with 133 additions and 47 deletions.
3 changes: 2 additions & 1 deletion packages/composer-common/lib/idcard.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -155,7 +155,8 @@ class IdCard {
*/
setCredentials(credentials) {
const method = 'setCredentials';
LOG.entry(method, credentials);
// Don't log the credentials
LOG.entry(method);

this.credentials = credentials || { };

Expand Down
20 changes: 19 additions & 1 deletion packages/composer-common/lib/log/logger.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -280,7 +280,7 @@ class Logger {
/**
* @description Log a message at the _verbose_ level
*
* @param {String} method cupdateLoggerCfgalling method
* @param {String} method calling method
* @param {String} msg Text Message
* @param {stuff} data Data to log at a verbose level
*
Expand All @@ -299,6 +299,24 @@ class Logger {
this.intlog.apply(this, args);
}

/**
* @description Log a performance message at the _verbose_ level
*
* @param {String} method calling method
* @param {String} msg Text Message
* @param {TransactionID} txId The node-sdk transaction id
* @param {Date} startTime Date object representing the start of the timed block
*
* @private
*/
perf(method, msg, txId, startTime) {
if (!(this.include && this.logLevel >= LOG_LEVEL_VERBOSE)) {
return;
}
const timeTaken = (Date.now() - startTime).toFixed(2);
this.intlog('verbose', method, `[${txId.getTransactionID().substring(0, 8)}] ${msg} ${timeTaken}ms`);
}

/**
* @description Log a message at the _error_ level
*
Expand Down
2 changes: 1 addition & 1 deletion packages/composer-common/lib/modelmanager.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -78,7 +78,7 @@ class ModelManager {

// add the system model
SYSTEM_MODELS.forEach((SYSTEM_MODEL) => {
LOG.info(method, SYSTEM_MODEL);
LOG.debug(method, SYSTEM_MODEL);
let m = new ModelFile(this, SYSTEM_MODEL.contents, SYSTEM_MODEL.fileName);
this.modelFiles[m.getNamespace()] = m;
});
Expand Down
36 changes: 24 additions & 12 deletions packages/composer-common/test/log/logger.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -269,31 +269,38 @@ describe('Logger', () => {
sinon.assert.calledWith(logger.intlog, 'debug', 'Method','Message','Data');
});

it('info method should call debug level, no args', () => {
it('info method should call info level, no args', () => {
logger.info('Method', 'Message', 'Data');
sinon.assert.calledOnce(logger.intlog);
sinon.assert.calledWith(logger.intlog, 'info', 'Method','Message','Data');
});

it('verbose method should call debug level, no args', () => {
it('verbose method should call verbose level, no args', () => {
logger.verbose('Method', 'Message', 'Data');
sinon.assert.calledOnce(logger.intlog);
sinon.assert.calledWith(logger.intlog, 'verbose', 'Method','Message','Data');
});

it('error method should call debug level, no args', () => {
it('perf method should call verbose level, no args', () => {
logger.perf('Method', 'Perf message', {getTransactionID: () => {return 'txid';}}, new Date());
sinon.assert.calledOnce(logger.intlog);
sinon.assert.calledWith(logger.intlog, 'verbose', 'Method', sinon.match.string);
});


it('error method should call error level, no args', () => {
logger.error('Method', 'Message', 'Data');
sinon.assert.calledOnce(logger.intlog);
sinon.assert.calledWith(logger.intlog, 'error', 'Method','Message','Data');
});

it('entry method should call debug level, no args', () => {
it('entry method should call entry level, no args', () => {
logger.entry('Method', 'Message', 'Data');
sinon.assert.calledOnce(logger.intlog);
sinon.assert.calledWith(logger.intlog, 'debug', 'Method','>','Message','Data');
});

it('exit method should call debug level, no args', () => {
it('exit method should call exit level, no args', () => {
logger.exit('Method', 'Message', 'Data');
sinon.assert.calledOnce(logger.intlog);
sinon.assert.calledWith(logger.intlog, 'debug', 'Method','<','Message','Data');
Expand Down Expand Up @@ -321,37 +328,42 @@ describe('Logger', () => {
levelsandbox.restore();
});

it('warn method should call warn level, no args', () => {
it('warn method should not call warn level, no args', () => {
logger.warn('Method', 'Message', 'Data');
sinon.assert.notCalled(logger.intlog);
});

it('debug method should call debug level, no args', () => {
it('debug method should not call debug level, no args', () => {
logger.debug('Method', 'Message', 'Data');
sinon.assert.notCalled(logger.intlog);
});

it('info method should call debug level, no args', () => {
it('info method should not call info level, no args', () => {
logger.info('Method', 'Message', 'Data');
sinon.assert.notCalled(logger.intlog);
});

it('verbose method should call debug level, no args', () => {
it('verbose method should not call verbose level, no args', () => {
logger.verbose('Method', 'Message', 'Data');
sinon.assert.notCalled(logger.intlog);
});

it('error method should call debug level, no args', () => {
it('perf method should not call verbose level, no args', () => {
logger.perf('Method', 'Perf message', {getTransactionID: () => {return 'txid';}}, new Date());
sinon.assert.notCalled(logger.intlog);
});

it('error method should not call error level, no args', () => {
logger.error('Method', 'Message', 'Data');
sinon.assert.notCalled(logger.intlog);
});

it('entry method should call debug level, no args', () => {
it('entry method should not call entry level, no args', () => {
logger.entry('Method', 'Message', 'Data');
sinon.assert.notCalled(logger.intlog);
});

it('exit method should call debug level, no args', () => {
it('exit method should not call exit level, no args', () => {
logger.exit('Method', 'Message', 'Data');
sinon.assert.notCalled(logger.intlog);
});
Expand Down
68 changes: 49 additions & 19 deletions packages/composer-connector-hlfv1/lib/hlfconnection.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -99,7 +99,8 @@ class HLFConnection extends Connection {
constructor(connectionManager, connectionProfile, businessNetworkIdentifier, connectOptions, client, channel, caClient) {
super(connectionManager, connectionProfile, businessNetworkIdentifier);
const method = 'constructor';
LOG.entry(method, connectionManager, connectionProfile, businessNetworkIdentifier, connectOptions, client, channel, caClient);
// don't log the client, channel, caClient objects here they're too big
LOG.entry(method, connectionManager, connectionProfile, businessNetworkIdentifier, connectOptions);

// Validate all the arguments.
if (!connectOptions) {
Expand Down Expand Up @@ -389,7 +390,8 @@ class HLFConnection extends Connection {
};
pollCCListener();

LOG.exit(method, result);
// don't log the result object it's too large
LOG.exit(method);
return result;

})
Expand All @@ -412,7 +414,7 @@ class HLFConnection extends Connection {
*/
async install(securityContext, businessNetworkDefinition, installOptions) {
const method = 'install';
LOG.entry(method, securityContext, businessNetworkDefinition, installOptions);
LOG.entry(method, businessNetworkDefinition, installOptions);

if (!businessNetworkDefinition) {
throw new Error('businessNetworkDefinition not specified');
Expand Down Expand Up @@ -639,7 +641,7 @@ class HLFConnection extends Connection {
*/
async start(securityContext, businessNetworkName, businessNetworkVersion, startTransaction, startOptions) {
const method = 'start';
LOG.entry(method, securityContext, businessNetworkName, startTransaction, startOptions);
LOG.entry(method, businessNetworkName, startTransaction, startOptions);

if (!businessNetworkName) {
throw new Error('Business network name not specified');
Expand Down Expand Up @@ -785,7 +787,7 @@ class HLFConnection extends Connection {
*/
ping(securityContext) {
const method = 'ping';
LOG.entry(method, securityContext);
LOG.entry(method);

// Check that a valid security context has been specified.
HLFUtil.securityCheck(securityContext);
Expand Down Expand Up @@ -818,7 +820,7 @@ class HLFConnection extends Connection {
*/
_checkRuntimeVersions(securityContext) {
const method = '_checkRuntimeVersions';
LOG.entry(method, securityContext);
LOG.entry(method);

return this.queryChainCode(securityContext, 'ping', [])
.then((buffer) => {
Expand Down Expand Up @@ -846,7 +848,7 @@ class HLFConnection extends Connection {
*/
async queryChainCode(securityContext, functionName, args) {
const method = 'queryChainCode';
LOG.entry(method, securityContext, functionName, args);
LOG.entry(method, functionName, args);

if (!this.businessNetworkIdentifier) {
throw new Error('No business network has been specified for this connection');
Expand All @@ -872,7 +874,10 @@ class HLFConnection extends Connection {
}

let txId = this.client.newTransactionID();

const t0 = Date.now();
let result = await this.queryHandler.queryChaincode(txId, functionName, args);
LOG.perf(method, 'Total duration for queryChaincode: ', txId, t0);
LOG.exit(method, result ? result : null);
return result ? result : null;
}
Expand All @@ -889,7 +894,7 @@ class HLFConnection extends Connection {
*/
async invokeChainCode(securityContext, functionName, args, options = {}) {
const method = 'invokeChainCode';
LOG.entry(method, securityContext, functionName, args, options);
LOG.entry(method, functionName, args, options);

// If commit has been set to false, we do not want to order the transaction or wait for any events.
if (options.commit === false) {
Expand Down Expand Up @@ -928,6 +933,7 @@ class HLFConnection extends Connection {
let eventHandler;
let validResponses;

let t0 = Date.now();
try {

// initialize the channel if it hasn't been initialized already otherwise verification will fail.
Expand All @@ -944,7 +950,18 @@ class HLFConnection extends Connection {
fcn: functionName,
args: args
};
const results = await this.channel.sendTransactionProposal(request); // node sdk will target all peers on the channel that are endorsingPeer
LOG.perf(method, 'Total duration to initialize channel: ', txId, t0);
t0 = Date.now();

let results;
try {
results = await this.channel.sendTransactionProposal(request); // node sdk will target all peers on the channel that are endorsingPeer
} catch(error) {
LOG.error(method, error);
throw new Error(`Error received from sendTransactionProposal: ${error}`);
}
LOG.perf(method, 'Total duration for sendTransactionProposal: ', txId, t0);
t0 = Date.now();

// Validate the endorsement results.
LOG.debug(method, `Received ${results.length} result(s) from invoking the composer runtime chaincode`, results);
Expand All @@ -970,11 +987,22 @@ class HLFConnection extends Connection {
eventHandler = HLFConnection.createTxEventHandler(this.eventHubs, txId.getTransactionID(), this.commitTimeout);
eventHandler.startListening();
LOG.debug(method, 'TxEventHandler started listening, sending valid responses to the orderer');
const response = await this.channel.sendTransaction({
proposalResponses: validResponses,
proposal: proposal,
header: header
});
LOG.perf(method, 'Total duration to prepare proposals for orderer: ', txId, t0);
t0 = Date.now();

let response;
try {
response = await this.channel.sendTransaction({
proposalResponses: validResponses,
proposal: proposal,
header: header
});
} catch(error) {
LOG.error(method, error);
throw new Error(`Error received from sendTransaction: ${error} `);
}
LOG.perf(method, 'Total duration for sendTransaction: ', txId, t0);
t0 = Date.now();

// If the transaction was successful, wait for it to be committed.
LOG.debug(method, 'Received response from orderer', response);
Expand All @@ -984,21 +1012,23 @@ class HLFConnection extends Connection {
throw new Error(`Failed to send peer responses for transaction '${txId.getTransactionID()}' to orderer. Response status '${response.status}'`);
}
await eventHandler.waitForEvents();
LOG.perf(method, 'Total duration for commit notification : ', txId, t0);

LOG.exit(method, result);
return result;

} catch (error) {
// Log first in case anything below fails and masks the original error
LOG.error(method, `Failed to invoke business network with transaction id: ${txId.getTransactionID()}`);
LOG.error(method, error);

// Investigate proposal response results and log if they differ and rethrow
// Investigate proposal response results and log if they differ
if (validResponses && validResponses.length >= 2 && !this.channel.compareProposalResponseResults(validResponses)) {
const warning = 'Peers did not agree, Read Write sets differed';
LOG.warn(method, warning);
}

const newError = new Error('Error trying invoke business network. ' + error);
const newError = new Error(`Error trying invoke business network with transaction id ${txId.getTransactionID()}. ${error}`);
throw newError;
}
}
Expand All @@ -1020,7 +1050,7 @@ class HLFConnection extends Connection {
*/
createIdentity(securityContext, userID, options) {
const method = 'createIdentity';
LOG.entry(method, securityContext, userID, options);
LOG.entry(method, userID, options);

// Check that a valid security context has been specified.
HLFUtil.securityCheck(securityContext);
Expand Down Expand Up @@ -1095,7 +1125,7 @@ class HLFConnection extends Connection {
*/
list(securityContext) {
const method = 'list';
LOG.entry(method, securityContext);
LOG.entry(method);

// Check that a valid security context has been specified.
HLFUtil.securityCheck(securityContext);
Expand Down Expand Up @@ -1140,7 +1170,7 @@ class HLFConnection extends Connection {
*/
async upgrade(securityContext, businessNetworkName, businessNetworkVersion, upgradeOptions) {
const method = 'upgrade';
LOG.entry(method, securityContext, businessNetworkName, upgradeOptions);
LOG.entry(method, businessNetworkName, upgradeOptions);

if (!businessNetworkName) {
throw new Error('Business network name not specified');
Expand Down
Loading

0 comments on commit 6d6a71a

Please sign in to comment.