[0.19.x] Backport perf logging improvements (#4497)

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

Author: davek-at-ibm

packages/composer-common/lib/log/logger.js

@@ -70,7 +70,9 @@ const _logLevelAsString = {
 
 // If  composer[debug]:acls is provided, the debug level of trace will be used for specified string.
 const PROFILES = {
-    'acls' : ['composer[#]:AccessController']
+    'acls' : ['composer[#]:AccessController'],
+    'hlfv1': ['composer[#]:HLFConnectionManager','composer[#]:HLFConnection',
+        'composer[#]:HLFQueryHandler', 'composer[#]:HLFTxEventHandler']
 };
 
 /**
@@ -304,7 +306,7 @@ class Logger {
      *
      * @param {String} method calling method
      * @param {String} msg Text Message
-     * @param {TransactionID} txId The node-sdk transaction id
+     * @param {TransactionID} txId The node-sdk transaction id or null if no txid
      * @param {Date} startTime Date object representing the start of the timed block
      *
      * @private
@@ -314,7 +316,11 @@ class Logger {
             return;
         }
         const timeTaken = (Date.now() - startTime).toFixed(2);
-        this.intlog('verbose', method, `[${txId.getTransactionID().substring(0, 8)}] ${msg} ${timeTaken}ms`);
+        if (txId && txId.getTransactionID) {
+            this.intlog('verbose', method, `[${txId.getTransactionID().substring(0, 8)}] ${msg} ${timeTaken}ms`);
+        } else {
+            this.intlog('verbose', method, `[NO TXID ] ${msg} ${timeTaken}ms`);
+        }
     }
 
     /**
@@ -659,9 +665,7 @@ class Logger {
         const loggerToUse = localConfig.logger;
         let myLogger;
         try {
-            // const mod = 'config';
             const req = require;
-            // const config = req(mod);
             myLogger = req(loggerToUse);
         } catch (e) {
              // Print the error to the console and just use the null logger instead.

packages/composer-common/lib/log/winstonInjector.js

@@ -62,6 +62,8 @@ exports.getLogger = function (config){
         colorize: true,
         label: PRODUCT_LABEL,
         silent: (consoleLevel===null),
+        timestamp: timestampFn,
+        formatter: formatterFn,
         level: consoleLevel
     };
 

packages/composer-common/test/log/logger.js

@@ -24,6 +24,7 @@ const Identifiable = require('../../lib/model/identifiable');
 const Typed = require('../../lib/model/typed');
 
 const chai = require('chai');
+
 chai.use(require('chai-things'));
 const mockery = require('mockery');
 const sinon = require('sinon');
@@ -287,6 +288,11 @@ describe('Logger', () => {
             sinon.assert.calledWith(logger.intlog, 'verbose', 'Method', sinon.match.string);
         });
 
+        it('perf method should call verbose level and work without a txid, no args', () => {
+            logger.perf('Method', 'Perf message', null, 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');

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');
@@ -139,6 +145,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);
@@ -197,8 +208,10 @@ class HLFConnection extends Connection {
         LOG.debug(method, 'Submitting enrollment request');
         let options = { enrollmentID: enrollmentID, enrollmentSecret: enrollmentSecret };
         let user;
+        const t0 = Date.now();
         return this.caClient.enroll(options)
             .then((enrollment) => {
+                LOG.perf(method, `Total duration to enroll ${enrollmentID}: `, null, t0);
                 // Store the certificate data in a new user object.
                 LOG.debug(method, 'Successfully enrolled, creating user object');
                 user = HLFConnection.createUser(enrollmentID, this.client);
@@ -216,12 +229,13 @@ class HLFConnection extends Connection {
                 return this._initializeChannel();
             })
             .then(() => {
-                LOG.exit(method, user);
+                // Don't log the user, it's too big
+                LOG.exit(method);
                 return user;
             })
             .catch((error) => {
+                LOG.error(method, error);
                 const newError = new Error('Error trying to enroll user or load channel configuration. ' + error);
-                LOG.error(method, newError);
                 throw newError;
             });
     }
@@ -876,8 +890,10 @@ 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);
-        LOG.perf(method, 'Total duration for queryChaincode: ', txId, t0);
+        LOG.perf(method, `Total duration for queryChaincode to ${functionName}: `, txId, t0);
         LOG.exit(method, result ? result : null);
         return result ? result : null;
     }
@@ -934,6 +950,8 @@ class HLFConnection extends Connection {
         let validResponses;
 
         let t0 = Date.now();
+        LOG.perf(method, `start of chaincode invocation ${functionName}(${args})`, txId, t0);
+
         try {
 
             // initialize the channel if it hasn't been initialized already otherwise verification will fail.
@@ -950,7 +968,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;
@@ -960,11 +978,11 @@ class HLFConnection extends Connection {
                 LOG.error(method, error);
                 throw new Error(`Error received from sendTransactionProposal: ${error}`);
             }
-            LOG.perf(method, 'Total duration for sendTransactionProposal: ', txId, t0);
+            LOG.perf(method, `Total duration for sendTransactionProposal ${functionName}: `, txId, t0);
             t0 = Date.now();
 
             // Validate the endorsement results.
-            LOG.debug(method, `Received ${results.length} result(s) from invoking the composer runtime chaincode`, results);
+            LOG.debug(method, `Received ${results.length} result(s) from invoking the composer runtime chaincode`);
             const proposalResponses = results[0];
             validResponses = this._validatePeerResponses(proposalResponses, true).validResponses;
 

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

@@ -259,7 +259,7 @@ class HLFConnectionManager extends ConnectionManager {
      */
     static async setupWallet(client, wallet) {
         const method = 'setupWallet';
-        LOG.entry(method, client, wallet);
+        LOG.entry(method, wallet);
         try {
             let store = await new HLFWalletProxy(wallet);
             client.setStateStore(store);
@@ -285,7 +285,7 @@ class HLFConnectionManager extends ConnectionManager {
      */
     static async setupHSM(client, ccp, wallet) {
         const method = 'setupHSM';
-        LOG.entry(method, client, wallet);
+        LOG.entry(method, wallet);
         let keyValStorePath = HLFConnectionManager.getStoreLocation(ccp);
         let store;
         try {

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

@@ -130,7 +130,7 @@ class HLFQueryHandler {
      */
     async querySinglePeer(peer, txId, functionName, args) {
         const method = 'querySinglePeer';
-        LOG.entry(method, peer, txId, functionName, args);
+        LOG.entry(method, peer.getName(), txId, functionName, args);
         const request = {
             targets: [peer],
             chaincodeId: this.connection.businessNetworkIdentifier,
@@ -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

@@ -103,7 +103,7 @@ class HLFTxEventHandler {
             LOG.exit(method);
             return Promise.all(this.listenerPromises);
         }
-        LOG.warn(method, 'No event hubs available to listen on to wait for transaction commits');
+        LOG.warn(method, `No event hubs available to listen on to wait for a commit for transaction '${this.txId}'`);
         LOG.exit(method);
         return Promise.resolve();
     }

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

@@ -57,12 +57,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);
@@ -161,19 +161,32 @@ describe('HLFConnection', () => {
             }).should.throw(/channel not specified/);
         });
 
-
         it('should throw if caClient not specified', () => {
             (() => {
                 new HLFConnection(mockConnectionManager, 'hlfabric1', mockBusinessNetwork.getName(), { type: 'hlfv1' }, mockClient, mockChannel, null);
             }).should.throw(/caClient not specified/);
         });
+
+        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', () => {
         beforeEach(() => {
             mockChannel.getPeers.returns([mockPeer1]);
             mockPeer1.isInRole.withArgs(FABRIC_CONSTANTS.NetworkConfig.EVENT_SOURCE_ROLE).returns(true);
-            mockChannel.newChannelEventHub.withArgs(mockPeer1).returns(mockEventHub1);        });
+            mockChannel.newChannelEventHub.withArgs(mockPeer1).returns(mockEventHub1);
+        });
 
         it('should ignore a disconnected event hub on process exit', () => {
             sandbox.stub(process, 'on').withArgs('exit').yields();
@@ -497,8 +510,6 @@ describe('HLFConnection', () => {
                 });
         });
 
-
-
         it('should handle being called twice', () => {
             mockEventHub1.isconnected.returns(true);
             connection._connectToEventHubs();
@@ -512,6 +523,20 @@ describe('HLFConnection', () => {
                 });
         });
 
+        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('#enroll', () => {

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]);
@@ -222,7 +223,7 @@ describe('HLFQueryHandler', () => {
         });
 
         it('should throw any responses that are errors and code 1 being unavailable.', () => {
-            const response = new Error('14 UNAVAILABLE: Connect Failed');
+            const response = new Error('1 UNAVAILABLE: Connect Failed');
             response.code = 1;
             mockChannel.queryByChaincode.resolves([response]);
             mockConnection.businessNetworkIdentifier = 'org-acme-biznet';
@@ -231,7 +232,7 @@ describe('HLFQueryHandler', () => {
         });
 
         it('should throw any responses that are errors and code 4 being unavailable.', () => {
-            const response = new Error('14 UNAVAILABLE: Connect Failed');
+            const response = new Error('4 UNAVAILABLE: Connect Failed');
             response.code = 4;
             mockChannel.queryByChaincode.resolves([response]);
             mockConnection.businessNetworkIdentifier = 'org-acme-biznet';