[Master] Improve perf logging (#4495)

* Log connect/disconnect, improve query perf log

Signed-off-by: Dave Kelsey <d_kelsey@uk.ibm.com>

* Improvements based on example

Signed-off-by: Dave Kelsey <d_kelsey@uk.ibm.com>

Author: Dave Kelsey

packages/composer-connector-hlfv1/lib/hlfconnection.js

@@ -102,6 +102,12 @@ class HLFConnection extends Connection {
         // don't log the client, channel, caClient objects here they're too big
         LOG.entry(method, connectionManager, connectionProfile, businessNetworkIdentifier, connectOptions);
 
+        if (this.businessNetworkIdentifier) {
+            LOG.info(method, `Creating a connection using profile ${connectionProfile} to network ${businessNetworkIdentifier}`);
+        } else {
+            LOG.info(method, `Creating a connection using profile ${connectionProfile} to fabric (no business network)`);
+        }
+
         // Validate all the arguments.
         if (!connectOptions) {
             throw new Error('connectOptions not specified');
@@ -141,6 +147,11 @@ class HLFConnection extends Connection {
     disconnect() {
         const method = 'disconnect';
         LOG.entry(method);
+        if (this.businessNetworkIdentifier) {
+            LOG.info(method, `Disconnecting the connection to ${this.businessNetworkIdentifier}`);
+        } else {
+            LOG.info(method, 'Disconnecting the connection to fabric (no business network)');
+        }
 
         if (this.exitListener) {
             process.removeListener('exit', this.exitListener);
@@ -922,7 +933,11 @@ class HLFConnection extends Connection {
         let txId = this.client.newTransactionID();
 
         const t0 = Date.now();
+        LOG.perf(method, `start of querying chaincode ${functionName}(${args})`, txId, t0);
+
         let result = await this.queryHandler.queryChaincode(txId, functionName, args);
+
+        // need to know which query was executed, otherwise just need to know which function was executed.
         LOG.perf(method, `Total duration for queryChaincode to ${functionName}: `, txId, t0);
         LOG.exit(method, result ? result : null);
         return result ? result : null;
@@ -978,8 +993,8 @@ class HLFConnection extends Connection {
 
         let eventHandler;
         let validResponses;
-
         let t0 = Date.now();
+        LOG.perf(method, `start of chaincode invocation ${functionName}(${args})`, txId, t0);
         try {
             LOG.debug(method, 'checking the event hub strategy');
             await this._checkEventHubStrategy();
@@ -1000,7 +1015,7 @@ class HLFConnection extends Connection {
                 fcn: functionName,
                 args: args
             };
-            LOG.perf(method, 'Total duration to initialize channel: ', txId, t0);
+            LOG.perf(method, 'Total duration to initialize: ', txId, t0);
             t0 = Date.now();
 
             let results;

packages/composer-connector-hlfv1/lib/hlfqueryhandler.js

@@ -139,7 +139,9 @@ class HLFQueryHandler {
             args: args
         };
 
+        const t0 = Date.now();
         let payloads = await this.connection.channel.queryByChaincode(request);
+        LOG.perf(method, `Total duration for node-sdk queryByChaincode to ${functionName}: `, txId, t0);
         LOG.debug(method, `Received ${payloads.length} payloads(s) from querying the composer runtime chaincode`);
         if (!payloads.length) {
             LOG.error(method, 'No payloads were returned from the query request:' + functionName);

packages/composer-connector-hlfv1/lib/hlftxeventhandler.js

@@ -120,9 +120,9 @@ class HLFTxEventHandler {
                 LOG.error(method, msg);
                 throw Error(msg);
             }
-            LOG.exit(method);
+        } else {
+            LOG.warn(method, `No event hubs available to listen on to wait for a commit for transaction '${this.txId}'`);
         }
-        LOG.warn(method, `No event hubs available to listen on to wait for a commit for transaction '${this.txId}'`);
         LOG.exit(method);
     }
 

packages/composer-connector-hlfv1/test/hlfconnection.js

@@ -56,12 +56,12 @@ describe('HLFConnection', () => {
     let mockPeer1, mockPeer2, mockPeer3, mockEventHub1, mockEventHub2, mockEventHub3, mockQueryHandler;
     let connectOptions;
     let connection;
-    let mockTransactionID, logWarnSpy, logErrorSpy;
+    let mockTransactionID, logWarnSpy, logErrorSpy, logInfoSpy, LOG;
 
     beforeEach(() => {
         sandbox = sinon.sandbox.create();
         clock = sinon.useFakeTimers();
-        const LOG = Logger.getLog('HLFConnection');
+        LOG = Logger.getLog('HLFConnection');
         logWarnSpy = sandbox.spy(LOG, 'warn');
         logErrorSpy = sandbox.spy(LOG, 'error');
         mockConnectionManager = sinon.createStubInstance(HLFConnectionManager);
@@ -194,6 +194,18 @@ describe('HLFConnection', () => {
             connection = new HLFConnection(mockConnectionManager, 'hlfabric1', mockBusinessNetwork.getName(), {'x-requiredEventHubs': 'fred'}, mockClient, mockChannel, mockCAClient);
             connection.requiredEventHubs.should.equal(1);
         });
+
+        it('should log at info a fabric level connection being created', () => {
+            logInfoSpy = sandbox.spy(LOG, 'info');
+            connection = new HLFConnection(mockConnectionManager, 'hlfabric1', null, {'x-requiredEventHubs': 'fred'}, mockClient, mockChannel, mockCAClient);
+            sinon.assert.calledWith(logInfoSpy, 'constructor', sinon.match(/no business network/));
+        });
+
+        it('should log at info a business network level connection being created', () => {
+            logInfoSpy = sandbox.spy(LOG, 'info');
+            connection = new HLFConnection(mockConnectionManager, 'hlfabric1', 'test-business-network', {'x-requiredEventHubs': 'fred'}, mockClient, mockChannel, mockCAClient);
+            sinon.assert.calledWith(logInfoSpy, 'constructor', sinon.match(/test-business-network/));
+        });
     });
 
     describe('#_connectToEventHubs', () => {
@@ -638,6 +650,20 @@ describe('HLFConnection', () => {
             sinon.assert.calledTwice(connection._disconnect);
         });
 
+        it('should log at info a fabric level connection being disconnected', () => {
+            logInfoSpy = sandbox.spy(LOG, 'info');
+            connection = new HLFConnection(mockConnectionManager, 'hlfabric1', null, {'x-requiredEventHubs': 'fred'}, mockClient, mockChannel, mockCAClient);
+            connection.disconnect();
+            sinon.assert.calledWith(logInfoSpy.secondCall, 'disconnect', sinon.match(/no business network/));
+        });
+
+        it('should log at info a business network level connection being created', () => {
+            logInfoSpy = sandbox.spy(LOG, 'info');
+            connection = new HLFConnection(mockConnectionManager, 'hlfabric1', 'test-business-network', {'x-requiredEventHubs': 'fred'}, mockClient, mockChannel, mockCAClient);
+            connection.disconnect();
+            sinon.assert.calledWith(logInfoSpy.secondCall, 'disconnect', sinon.match(/test-business-network/));
+        });
+
     });
 
     describe('#_disconnect', () => {

packages/composer-connector-hlfv1/test/hlfqueryhandler.js

@@ -46,6 +46,7 @@ describe('HLFQueryHandler', () => {
         mockPeer3.index = 3;
         mockConnection = sinon.createStubInstance(HLFConnection);
         mockTransactionID = sinon.createStubInstance(TransactionID);
+        mockTransactionID.getTransactionID.returns('0987654321');
         mockChannel = sinon.createStubInstance(Channel);
         mockConnection.channel = mockChannel;
         mockConnection.getChannelPeersInOrg.withArgs([FABRIC_CONSTANTS.NetworkConfig.CHAINCODE_QUERY_ROLE]).returns([mockPeer2, mockPeer1, mockPeer3]);

packages/composer-connector-hlfv1/test/hlftxeventhandler.js

@@ -175,7 +175,7 @@ describe('HLFTxEventHandler', () => {
         });
     });
 
-    it('Should handle a transaction listener error response all event hubs and event hubs required', async () => {
+    it('Should handle a transaction listener error response from all event hubs and event hubs required', async () => {
         sandbox.stub(global, 'setTimeout');
         sandbox.stub(global, 'clearTimeout');
         const ehc = sandbox.stub(HLFUtil, 'eventHubConnected');
@@ -194,7 +194,7 @@ describe('HLFTxEventHandler', () => {
         sinon.assert.calledTwice(logWarnSpy);
     });
 
-    it('Should handle a transaction listener error response all event hubs but no event hubs required', async () => {
+    it('Should handle a transaction listener error response from all event hubs but no event hubs required', async () => {
         sandbox.stub(global, 'setTimeout');
         sandbox.stub(global, 'clearTimeout');
         const ehc = sandbox.stub(HLFUtil, 'eventHubConnected');
@@ -214,7 +214,7 @@ describe('HLFTxEventHandler', () => {
         } catch(err) {
             should.fail(null,null,`${err} unexpected`);
         }
-        sinon.assert.calledThrice(logWarnSpy);
+        sinon.assert.calledTwice(logWarnSpy);
     });
 
     it('Should handle a transaction listener error response on one but not all of the event hubs', async () => {