[0.19.x] Fix TxId logging for performance logging (hyperledger-archiv…

…es#4536) This doesn’t fix it for any other logging as all trace points in composer-runtime will need to be changed, also somehow the context would have to be passed to apis in composer-common as well. Signed-off-by: Dave Kelsey <[email protected]>
jai2033shankar · Dec 4, 2018 · 4cc9d5a · 4cc9d5a
1 parent 1e67fbf
commit 4cc9d5a
Show file tree

Hide file tree

Showing 19 changed files with 155 additions and 105 deletions.
diff --git a/packages/composer-common/lib/log/logger.js b/packages/composer-common/lib/log/logger.js
@@ -318,6 +318,8 @@ class Logger {
         const timeTaken = (Date.now() - startTime).toFixed(2);
         if (txId && txId.getTransactionID) {
             this.intlog('verbose', method, `[${txId.getTransactionID().substring(0, 8)}] ${msg} ${timeTaken}ms`);
+        } else if (txId && txId.length > 0) {
+            this.intlog('verbose', method, `[${txId.substring(0, 8)}] ${msg} ${timeTaken}ms`);
         } else {
             this.intlog('verbose', method, `[NO TXID ] ${msg} ${timeTaken}ms`);
         }

diff --git a/packages/composer-common/test/log/logger.js b/packages/composer-common/test/log/logger.js
@@ -282,13 +282,20 @@ describe('Logger', () => {
             sinon.assert.calledWith(logger.intlog, 'verbose', 'Method','Message','Data');
         });
 
-        it('perf method should call verbose level, no args', () => {
+        it('perf method should call verbose level, handling a transaction id object', () => {
             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('perf method should call verbose level and work without a txid, no args', () => {
+        it('perf method should call verbose level, handling a transaction id string', () => {
+            logger.perf('Method', 'Perf message', 'A-TxId-value', new Date());
+            sinon.assert.calledOnce(logger.intlog);
+            sinon.assert.calledWith(logger.intlog, 'verbose', 'Method', sinon.match.string);
+        });
+
+
+        it('perf method should call verbose level and work without a txid', () => {
             logger.perf('Method', 'Perf message', null, new Date());
             sinon.assert.calledOnce(logger.intlog);
             sinon.assert.calledWith(logger.intlog, 'verbose', 'Method', sinon.match.string);

diff --git a/packages/composer-runtime-hlfv1/lib/composer.js b/packages/composer-runtime-hlfv1/lib/composer.js
@@ -97,12 +97,12 @@ class Composer {
             let nodeContext = this._createContext(engine, stub);
             await engine.init(nodeContext, fcn, params);
             LOG.exit(method);
-            LOG.verbose('@PERF ' + method, 'Total (ms) duration for txnID [' + stub.getTxID() + ']: ' + (Date.now() - t0).toFixed(2));
+            LOG.perf(method, 'Total (ms) duration for txnID [' + stub.getTxID() + ']: ', stub.getTxID(), t0);
             return shim.success();
         }
         catch(err) {
             LOG.error(method, err);
-            LOG.verbose('@PERF ' + method, 'Total (ms) duration for txnID [' + stub.getTxID() + ']: ' + (Date.now() - t0).toFixed(2));
+            LOG.perf(method, 'Total (ms) duration for txnID [' + stub.getTxID() + ']: ', stub.getTxID(), t0);
             return shim.error(err);
         }
     }
@@ -127,16 +127,16 @@ class Composer {
             let payload = await engine.invoke(nodeContext, fcn, params);
             if (payload !== null && payload !== undefined) {
                 LOG.exit(method, payload);
-                LOG.verbose('@PERF ' + method, 'Total (ms) duration for txnID [' + stub.getTxID() + ']: ' + (Date.now() - t0).toFixed(2));
+                LOG.perf(method, 'Total (ms) duration for txnID [' + stub.getTxID() + ']: ', stub.getTxID(), t0);
                 return shim.success(Buffer.from(JSON.stringify(payload)));
             }
             LOG.exit(method);
-            LOG.verbose('@PERF ' + method, 'Total (ms) duration for txnID [' + stub.getTxID() + ']: ' + (Date.now() - t0).toFixed(2));
+            LOG.perf(method, 'Total (ms) duration for txnID [' + stub.getTxID() + ']: ', stub.getTxID(), t0);
             return shim.success();
         }
         catch(err) {
             LOG.error(method, err);
-            LOG.verbose('@PERF ' + method, 'Total (ms) duration for txnID [' + stub.getTxID() + ']: ' + (Date.now() - t0).toFixed(2));
+            LOG.perf(method, 'Total (ms) duration for txnID [' + stub.getTxID() + ']: ', stub.getTxID(), t0);
             return shim.error(err);
         }
     }

diff --git a/packages/composer-runtime-hlfv1/lib/nodecontext.js b/packages/composer-runtime-hlfv1/lib/nodecontext.js
@@ -43,6 +43,7 @@ class NodeContext extends Context {
         this.stub = stub;
         this.dataService = new NodeDataService(this.stub);
         this.identityService = new NodeIdentityService(this.stub);
+        this.setContextId(stub.getTxID());
         LOG.exit(method);
     }
 

diff --git a/packages/composer-runtime-hlfv1/lib/nodedatacollection.js b/packages/composer-runtime-hlfv1/lib/nodedatacollection.js
@@ -50,9 +50,9 @@ class NodeDataCollection extends DataCollection {
         const t0 = Date.now();
 
         let iterator = await this.stub.getStateByPartialCompositeKey(this.collectionID, []);
-        let results = await NodeUtils.getAllResults(iterator);
+        let results = await NodeUtils.getAllResults(iterator, this.stub);
         LOG.exit(method, results);
-        LOG.verbose('@PERF ' + method, 'Total (ms) duration: ' + (Date.now() - t0).toFixed(2));
+        LOG.perf(method, 'Total (ms) duration: ', this.stub.getTxID(), t0);
         return results;
     }
 
@@ -72,12 +72,12 @@ class NodeDataCollection extends DataCollection {
         if (value.length === 0) {
             const newErr = new Error(`Object with ID '${id}' in collection with ID '${this.collectionID}' does not exist`);
             LOG.error(method, newErr);
-            LOG.verbose('@PERF ' + method, 'Total (ms) duration: ' + (Date.now() - t0).toFixed(2));
+            LOG.perf(method, 'Total (ms) duration: ', this.stub.getTxID(), t0);
             throw newErr;
         }
         let retVal = JSON.parse(value.toString('utf8'));
         LOG.exit(method, retVal);
-        LOG.verbose('@PERF ' + method, 'Total (ms) duration: ' + (Date.now() - t0).toFixed(2));
+        LOG.perf(method, 'Total (ms) duration: ', this.stub.getTxID(), t0);
         return retVal;
     }
 
@@ -96,7 +96,7 @@ class NodeDataCollection extends DataCollection {
         let value = await this.stub.getState(key);
         let retVal = value.length !== 0;
         LOG.exit(method, retVal);
-        LOG.verbose('@PERF ' + method, 'Total (ms) duration: ' + (Date.now() - t0).toFixed(2));
+        LOG.perf(method, 'Total (ms) duration: ', this.stub.getTxID(), t0);
         return retVal;
     }
 
@@ -120,14 +120,14 @@ class NodeDataCollection extends DataCollection {
             if (value.length !== 0) {
                 const newErr =  new Error(`Failed to add object with ID '${id}' in collection with ID '${this.collectionID}' as the object already exists`);
                 LOG.error(method, newErr);
-                LOG.verbose('@PERF ' + method, 'Total (ms) duration: ' + (Date.now() - t0).toFixed(2));
+                LOG.perf(method, 'Total (ms) duration: ', this.stub.getTxID(), t0);
                 throw newErr;
             }
         }
         await this.stub.putState(key, Buffer.from(JSON.stringify(object)));
 
         LOG.exit(method);
-        LOG.verbose('@PERF ' + method, 'Total (ms) duration: ' + (Date.now() - t0).toFixed(2));
+        LOG.perf(method, 'Total (ms) duration: ', this.stub.getTxID(), t0);
     }
 
     /**
@@ -148,12 +148,12 @@ class NodeDataCollection extends DataCollection {
         if (value.length === 0) {
             const newErr = new Error(`Failed to update object with ID '${id}' in collection with ID '${this.collectionID}' as the object does not exist`);
             LOG.error(method, newErr);
-            LOG.verbose('@PERF ' + method, 'Total (ms) duration: ' + (Date.now() - t0).toFixed(2));
+            LOG.perf(method, 'Total (ms) duration: ', this.stub.getTxID(), t0);
             throw newErr;
         }
         await this.stub.putState(key, Buffer.from(JSON.stringify(object)));
         LOG.exit(method);
-        LOG.verbose('@PERF ' + method, 'Total (ms) duration: ' + (Date.now() - t0).toFixed(2));
+        LOG.perf(method, 'Total (ms) duration: ', this.stub.getTxID(), t0);
     }
 
     /**
@@ -170,12 +170,12 @@ class NodeDataCollection extends DataCollection {
         if (value.length === 0) {
             const newErr = new Error(`Failed to delete object with ID '${id}' in collection with ID '${this.collectionID}' as the object does not exist`);
             LOG.error(method, newErr);
-            LOG.verbose('@PERF ' + method, 'Total (ms) duration: ' + (Date.now() - t0).toFixed(2));
+            LOG.perf(method, 'Total (ms) duration: ', this.stub.getTxID(), t0);
             throw newErr;
         }
         await this.stub.deleteState(key);
         LOG.exit(method);
-        LOG.verbose('@PERF ' + method, 'Total (ms) duration: ' + (Date.now() - t0).toFixed(2));
+        LOG.perf(method, 'Total (ms) duration: ', this.stub.getTxID(), t0);
     }
 }
 

diff --git a/packages/composer-runtime-hlfv1/lib/nodedataservice.js b/packages/composer-runtime-hlfv1/lib/nodedataservice.js
@@ -57,17 +57,17 @@ class NodeDataService extends DataService {
             if (value.length === 0) {
                 let result = await this._storeCollection(key, id);
                 LOG.exit(method, result);
-                LOG.verbose('@PERF ' + method, 'Total (ms) duration: ' + (Date.now() - t0).toFixed(2));
+                LOG.perf(method, 'Total (ms) duration: ', this.stub.getTxID(), t0);
                 return result;
             }
             else {
-                LOG.verbose('@PERF ' + method, 'Total (ms) duration: ' + (Date.now() - t0).toFixed(2));
+                LOG.perf(method, 'Total (ms) duration: ', this.stub.getTxID(), t0);
                 throw new Error(`Failed to create collection with ID ${id} as it already exists`);
             }
         } else {
             let result = await this._storeCollection(key, id);
             LOG.exit(method, result);
-            LOG.verbose('@PERF ' + method, 'Total (ms) duration: ' + (Date.now() - t0).toFixed(2));
+            LOG.perf(method, 'Total (ms) duration: ', this.stub.getTxID(), t0);
             return result;
         }
     }
@@ -88,7 +88,7 @@ class NodeDataService extends DataService {
         await this.stub.putState(key, Buffer.from(JSON.stringify({'id': id})));
         let retVal = new NodeDataCollection(this, this.stub, id);
         LOG.exit(method, retVal);
-        LOG.verbose('@PERF ' + method, 'Total (ms) duration: ' + (Date.now() - t0).toFixed(2));
+        LOG.perf(method, 'Total (ms) duration: ', this.stub.getTxID(), t0);
         return retVal;
     }
 
@@ -104,13 +104,13 @@ class NodeDataService extends DataService {
         let key = this.stub.createCompositeKey(collectionObjectType, [id]);
         let exists = await this.existsCollection(id);
         if (!exists) {
-            LOG.verbose('@PERF ' + method, 'Total (ms) duration: ' + (Date.now() - t0).toFixed(2));
+            LOG.perf(method, 'Total (ms) duration: ', this.stub.getTxID(), t0);
             throw new Error(`Collection with ID ${id} does not exist`);
         }
         await this.clearCollection(id);
         await this.stub.deleteState(key);
         LOG.exit(method);
-        LOG.verbose('@PERF ' + method, 'Total (ms) duration: ' + (Date.now() - t0).toFixed(2));
+        LOG.perf(method, 'Total (ms) duration: ', this.stub.getTxID(), t0);
     }
 
    /**
@@ -128,18 +128,18 @@ class NodeDataService extends DataService {
         if (bypass) {
             let retVal = new NodeDataCollection(this, this.stub, id);
             LOG.exit(method, retVal);
-            LOG.verbose('@PERF ' + method, 'Total (ms) duration: ' + (Date.now() - t0).toFixed(2));
+            LOG.perf(method, 'Total (ms) duration: ', this.stub.getTxID(), t0);
             return retVal;
         } else {
             let key = this.stub.createCompositeKey(collectionObjectType, [id]);
             let value = await this.stub.getState(key);
             if (value.length === 0) {
-                LOG.verbose('@PERF ' + method, 'Total (ms) duration: ' + (Date.now() - t0).toFixed(2));
+                LOG.perf(method, 'Total (ms) duration: ', this.stub.getTxID(), t0);
                 throw new Error(`Collection with ID ${id} does not exist`);
             }
             let retVal = new NodeDataCollection(this, this.stub, id);
             LOG.exit(method, retVal);
-            LOG.verbose('@PERF ' + method, 'Total (ms) duration: ' + (Date.now() - t0).toFixed(2));
+            LOG.perf(method, 'Total (ms) duration: ', this.stub.getTxID(), t0);
             return retVal;
         }
     }
@@ -159,7 +159,7 @@ class NodeDataService extends DataService {
         let value = await this.stub.getState(key);
         let retVal = value.length !== 0;
         LOG.exit(method, retVal);
-        LOG.verbose('@PERF ' + method, 'Total (ms) duration: ' + (Date.now() - t0).toFixed(2));
+        LOG.perf(method, 'Total (ms) duration: ', this.stub.getTxID(), t0);
         return retVal;
     }
 
@@ -176,9 +176,9 @@ class NodeDataService extends DataService {
         const t0 = Date.now();
 
         let iterator = await this.stub.getQueryResult(query);
-        let results = await NodeUtils.getAllResults(iterator);
+        let results = await NodeUtils.getAllResults(iterator, this.stub);
         LOG.exit(method, results);
-        LOG.verbose('@PERF ' + method, 'Total (ms) duration: ' + (Date.now() - t0).toFixed(2));
+        LOG.perf(method, 'Total (ms) duration: ', this.stub.getTxID(), t0);
         return results;
     }
 
@@ -194,7 +194,7 @@ class NodeDataService extends DataService {
         let iterator = await this.stub.getStateByPartialCompositeKey(id, []);
         await NodeUtils.deleteAllResults(iterator, this.stub);
         LOG.exit(method);
-        LOG.verbose('@PERF ' + method, 'Total (ms) duration: ' + (Date.now() - t0).toFixed(2));
+        LOG.perf(method, 'Total (ms) duration: ', this.stub.getTxID(), t0);
     }
 }
 

diff --git a/packages/composer-runtime-hlfv1/lib/nodeloggingservice.js b/packages/composer-runtime-hlfv1/lib/nodeloggingservice.js
@@ -17,6 +17,13 @@
 const LoggingService = require('composer-runtime').LoggingService;
 const LOGLEVEL_KEY = 'ComposerLogCfg';
 const Logger = require('composer-common').Logger;
+
+Logger.setCallBack(function(logLevel) {
+    const timestamp = new Date().toISOString();
+    return `${timestamp} ${logLevel.toUpperCase().padEnd(8)} `;
+});
+
+
 /**
  * Base class representing the logging service provided by a {@link Container}.
  * @protected
@@ -29,6 +36,7 @@ class NodeLoggingService extends LoggingService {
     constructor() {
         super();
         this.stub = null;
+        this.loggerInitialized = false;
     }
 
     /**
@@ -41,15 +49,19 @@ class NodeLoggingService extends LoggingService {
     async initLogging(stub) {
         this.stub = stub;
 
-        let logCFG = await this.getLoggerCfg();
-        Logger.setLoggerCfg(logCFG, true);
-
-        Logger.setCallBack(function(logLevel) {
-            const timestamp = new Date().toISOString();
-            const shortTxId = stub.getTxID().substring(0, 8);
-            return `${timestamp} [${shortTxId}] ${logLevel.toUpperCase().padEnd(8)} `;
-        });
-
+        // we only want to do this once for the first request that comes
+        // in so we can look at the initial state of the logger and set it
+        // appropriately. Any change to the logger state is handled so doesn't
+        // need to be checked at initLogging. The theory is that as this is
+        // called constantly in interleaved requests it stops some log points
+        // being logged.
+        if (!this.loggerInitialized) {
+            // set the initialized flag first to stop another interleaved request
+            // coming in trying to do the same thing.
+            this.loggerInitialized = true;
+            let logCFG = await this.getLoggerCfg();
+            Logger.setLoggerCfg(logCFG, true);
+        }
     }
 
     /**
@@ -66,14 +78,14 @@ class NodeLoggingService extends LoggingService {
      *
      * @returns {Object} configuration
      */
-    async getLoggerCfg(){
+    async getLoggerCfg() {
         let result = await this.stub.getState(LOGLEVEL_KEY);
         if (result.length === 0) {
             let defCfg = this.getDefaultCfg();
             return defCfg;
         } else {
             let json = JSON.parse(result.toString());
-            if( json.origin && json.origin==='default-logger-module'){
+            if( json.origin && json.origin === 'default-logger-module'){
                 json = this.getDefaultCfg();
             }
             return json;
@@ -83,7 +95,7 @@ class NodeLoggingService extends LoggingService {
     /**
      * @return {Object} the default cfg
      */
-    getDefaultCfg(){
+    getDefaultCfg() {
 
         let envVariable = process.env.CORE_CHAINCODE_LOGGING_LEVEL;
         let debugString = this.mapFabricDebug(envVariable);
@@ -97,7 +109,7 @@ class NodeLoggingService extends LoggingService {
             },
             'debug' : debugString,
             'logger': './consolelogger.js',
-            'origin':'default-runtime-hlfv1'
+            'origin': 'default-runtime-hlfv1'
         };
     }
 
@@ -109,7 +121,7 @@ class NodeLoggingService extends LoggingService {
      * @param {String} string input value to process
      * @return {String} clean string that can be used for setting up logging.
      */
-    mapCfg(string){
+    mapCfg(string) {
         let DEFAULT = 'composer[warn]:*';
         // first split it up into elements based on ,
         let details = string.split(/[\s,]+/);

diff --git a/packages/composer-runtime-hlfv1/lib/nodeutils.js b/packages/composer-runtime-hlfv1/lib/nodeutils.js
@@ -28,9 +28,10 @@ class NodeUtils {
      *
      * @static
      * @param {any} iterator the chaincode iterator
+     * @param {any} stub the stub for this invocation
      * @returns {promise} a promise that is resolved with the results or rejected or error
      */
-    static async getAllResults(iterator) {
+    static async getAllResults(iterator, stub) {
         const method = 'getAllResults';
         LOG.entry(method, iterator);
         const t0 = Date.now();
@@ -56,7 +57,7 @@ class NodeUtils {
                     LOG.warn(warnMsg);
                 }
                 LOG.exit(method);
-                LOG.verbose('@PERF ' + method, 'Total (ms) duration: ' + (Date.now() - t0).toFixed(2));
+                LOG.perf(method, 'Total (ms) duration: ', stub.getTxID(), t0);
                 return results;
             }
         }
@@ -94,7 +95,7 @@ class NodeUtils {
                     LOG.warn(warnMsg);
                 }
                 LOG.exit(method);
-                LOG.verbose('@PERF ' + method, 'Total (ms) duration: ' + (Date.now() - t0).toFixed(2));
+                LOG.perf(method, 'Total (ms) duration: ', stub.getTxID(), t0);
                 return results;
             }
         }