[FAB-14490] Logging from chaincode

mbwhite · mbwhite · commit aba36b04f19a · 2019-04-26T13:00:39.000Z
Change-Id: Ibeb5119e468cf28492e517d9a5c785c1425c2134
Signed-off-by: Matthew B. White &lt;whitemat@uk.ibm.com&gt;
Signed-off-by: James Taylor &lt;jamest@uk.ibm.com&gt;
diff --git a/README.md b/README.md
@@ -117,7 +117,7 @@ FABRIC_CFG_PATH=./sampleconfig .build/bin/configtxgen -outputCreateChannelTx sam
 
 Then you can launch a peer node with the following commands:
 ```
-FABRIC_CFG_PATH=./sampleconfig CORE_CHAINCODE_LOGGING_SHIM=debug FABRIC_LOGGING_SPEC=debug CORE_PEER_ADDRESSAUTODETECT=true .build/bin/peer node start --peer-chaincodedev
+FABRIC_CFG_PATH=./sampleconfig CORE_CHAINCODE_LOGGING_LEVEL=debug FABRIC_LOGGING_SPEC=debug CORE_PEER_ADDRESSAUTODETECT=true .build/bin/peer node start --peer-chaincodedev
 ```
 
 Then you can launch an orderer node with the following commands:
@@ -353,7 +353,7 @@ rm -r /var/hyperledger/production
 
 When launching a peer node, eliminate the `--peer-chaincodev` program argument to start the peer process in network mode.
 ```
-FABRIC_CFG_PATH=./sampleconfig CORE_CHAINCODE_LOGGING_SHIM=debug FABRIC_LOGGING_SPEC=debug CORE_PEER_ADDRESSAUTODETECT=true .build/bin/peer node start
+FABRIC_CFG_PATH=./sampleconfig CORE_CHAINCODE_LOGGING_LEVEL=debug FABRIC_LOGGING_SPEC=debug CORE_PEER_ADDRESSAUTODETECT=true .build/bin/peer node start
 ```
 
 Install and instantiate the chaincode with the following commands.
diff --git a/fabric-contract-api/lib/logger.js b/fabric-contract-api/lib/logger.js
@@ -36,7 +36,7 @@ function createLogger(level, name) {
 module.exports.getLogger = function (name = '') {
     // set the logging level based on the environment variable
     // configured by the peer
-    const level = process.env.CORE_CHAINCODE_LOGGING_SHIM;
+    const level = process.env.CORE_CHAINCODE_LOGGING_LEVEL;
     let loglevel = 'info';
     if (typeof level === 'string') {
         switch (level.toUpperCase()) {
diff --git a/fabric-contract-api/test/unit/logger.js b/fabric-contract-api/test/unit/logger.js
@@ -18,15 +18,15 @@ describe('Logger', () => {
 
         let logLevel;
         before(() => {
-            logLevel = process.env.CORE_CHAINCODE_LOGGING_SHIM;
+            logLevel = process.env.CORE_CHAINCODE_LOGGING_LEVEL;
         });
 
         after(() => {
-            process.env.CORE_CHAINCODE_LOGGING_SHIM = logLevel;
+            process.env.CORE_CHAINCODE_LOGGING_LEVEL = logLevel;
         });
 
         it ('should create a new logger name unknown', () => {
-            process.env.CORE_CHAINCODE_LOGGING_SHIM = null;
+            process.env.CORE_CHAINCODE_LOGGING_LEVEL = null;
 
             const log = Logger.getLogger('unknown name');
 
@@ -50,7 +50,7 @@ describe('Logger', () => {
         });
 
         it ('should set the log level to fatal when env var set to CRITICAL', () => {
-            process.env.CORE_CHAINCODE_LOGGING_SHIM = 'CRITICAL';
+            process.env.CORE_CHAINCODE_LOGGING_LEVEL = 'CRITICAL';
 
             const log = Logger.getLogger();
 
@@ -59,7 +59,7 @@ describe('Logger', () => {
         });
 
         it ('should set the log level to error when env var set to ERROR', () => {
-            process.env.CORE_CHAINCODE_LOGGING_SHIM = 'ERROR';
+            process.env.CORE_CHAINCODE_LOGGING_LEVEL = 'ERROR';
 
             const log = Logger.getLogger();
 
@@ -68,7 +68,7 @@ describe('Logger', () => {
         });
 
         it ('should set the log level to warn when env var set to WARNING', () => {
-            process.env.CORE_CHAINCODE_LOGGING_SHIM = 'WARNING';
+            process.env.CORE_CHAINCODE_LOGGING_LEVEL = 'WARNING';
 
             const log = Logger.getLogger();
 
@@ -77,7 +77,7 @@ describe('Logger', () => {
         });
 
         it ('should set the log level to debug when env var set to DEBUG', () => {
-            process.env.CORE_CHAINCODE_LOGGING_SHIM = 'DEBUG';
+            process.env.CORE_CHAINCODE_LOGGING_LEVEL = 'DEBUG';
 
             const log = Logger.getLogger();
 
@@ -88,7 +88,7 @@ describe('Logger', () => {
 
     describe('formatter', () => {
         it ('', () => {
-            process.env.CORE_CHAINCODE_LOGGING_SHIM = 'DEBUG';
+            process.env.CORE_CHAINCODE_LOGGING_LEVEL = 'DEBUG';
 
             const log = Logger.getLogger();
             log.debug();
@@ -98,7 +98,7 @@ describe('Logger', () => {
         });
 
         it ('', () => {
-            process.env.CORE_CHAINCODE_LOGGING_SHIM = 'DEBUG';
+            process.env.CORE_CHAINCODE_LOGGING_LEVEL = 'DEBUG';
 
             const log = Logger.getLogger('fred');
             log.debug('hello', 'fred');
diff --git a/fabric-contract-api/types/index.d.ts b/fabric-contract-api/types/index.d.ts
@@ -4,14 +4,20 @@
  SPDX-License-Identifier: Apache-2.0
 
 */
-declare module 'fabric-contract-api' {
 
+declare module 'fabric-contract-api' {
+    import { LoggerInstance } from 'winston';
     import { ChaincodeStub, ClientIdentity } from 'fabric-shim';
+    
     export class Context {
         stub: ChaincodeStub;
         clientIdentity: ClientIdentity;
+        logger: {
+            setLevel: (level: string) => void,
+            getLogger: (name?: string) => LoggerInstance
+        }
     }
-
+    
     export class Contract {
         constructor(name?: string);
 
diff --git a/fabric-shim/lib/contract-spi/chaincodefromcontract.js b/fabric-shim/lib/contract-spi/chaincodefromcontract.js
@@ -316,6 +316,12 @@ class ChaincodeFromContract {
             const ctx = contractInstance.createContext();
             ctx.setChaincodeStub(stub);
             ctx.setClientIdentity(new ClientIdentity(stub));
+            ctx.logging = {
+                setLevel : Logger.setLevel,
+                getLogger : (name) => {
+                    return Logger.getLogger(name ? `${cn}:${name}` : cn);
+                }
+            };
 
             // get the specific information for this tx function
             const functionExists = transactionDescriptor.transactions.find((transaction) => {
diff --git a/fabric-shim/lib/logger.js b/fabric-shim/lib/logger.js
@@ -33,10 +33,7 @@ function createLogger(level, name) {
     return logger;
 }
 
-module.exports.getLogger = function (name = '') {
-    // set the logging level based on the environment variable
-    // configured by the peer
-    const level = process.env.CORE_CHAINCODE_LOGGING_SHIM;
+const levelMapping = (level) => {
     let loglevel = 'info';
     if (typeof level === 'string') {
         switch (level.toUpperCase()) {
@@ -51,10 +48,20 @@ module.exports.getLogger = function (name = '') {
                 break;
             case 'DEBUG':
                 loglevel = 'debug';
+                break;
+            case 'INFO':
+                loglevel = 'info';
         }
     }
+    return loglevel;
+};
 
+module.exports.getLogger = function (name = '') {
+    // set the logging level based on the environment variable
+    // configured by the peer
+    const loglevel = levelMapping(process.env.CORE_CHAINCODE_LOGGING_LEVEL);
     let logger;
+
     if (loggers[name]) {
         logger = loggers[name];
         logger.level = loglevel;
@@ -65,3 +72,14 @@ module.exports.getLogger = function (name = '') {
 
     return logger;
 };
+
+module.exports.setLevel = (level) => {
+    // set the level of all the loggers currently active
+    const loglevel = levelMapping(level);
+    process.env.CORE_CHAINCODE_LOGGING_LEVEL = loglevel;
+
+    Object.keys(loggers).forEach((name) => {
+        loggers[name].level = loglevel;
+    });
+};
+
diff --git a/fabric-shim/test/unit/contract-spi/chaincodefromcontract.js b/fabric-shim/test/unit/contract-spi/chaincodefromcontract.js
@@ -23,6 +23,8 @@ chai.use(require('chai-things'));
 const sinon = require('sinon');
 
 const mockery = require('mockery');
+const Logger = require('../../../lib/logger.js');
+
 
 // standard utility fns
 const path = require('path');
@@ -61,6 +63,22 @@ function log(...e) {
     console.log(...e);
 }
 
+const certWithoutAttrs = '-----BEGIN CERTIFICATE-----' +
+'MIICXTCCAgSgAwIBAgIUeLy6uQnq8wwyElU/jCKRYz3tJiQwCgYIKoZIzj0EAwIw' +
+'eTELMAkGA1UEBhMCVVMxEzARBgNVBAgTCkNhbGlmb3JuaWExFjAUBgNVBAcTDVNh' +
+'biBGcmFuY2lzY28xGTAXBgNVBAoTEEludGVybmV0IFdpZGdldHMxDDAKBgNVBAsT' +
+'A1dXVzEUMBIGA1UEAxMLZXhhbXBsZS5jb20wHhcNMTcwOTA4MDAxNTAwWhcNMTgw' +
+'OTA4MDAxNTAwWjBdMQswCQYDVQQGEwJVUzEXMBUGA1UECBMOTm9ydGggQ2Fyb2xp' +
+'bmExFDASBgNVBAoTC0h5cGVybGVkZ2VyMQ8wDQYDVQQLEwZGYWJyaWMxDjAMBgNV' +
+'BAMTBWFkbWluMFkwEwYHKoZIzj0CAQYIKoZIzj0DAQcDQgAEFq/90YMuH4tWugHa' +
+'oyZtt4Mbwgv6CkBSDfYulVO1CVInw1i/k16DocQ/KSDTeTfgJxrX1Ree1tjpaodG' +
+'1wWyM6OBhTCBgjAOBgNVHQ8BAf8EBAMCB4AwDAYDVR0TAQH/BAIwADAdBgNVHQ4E' +
+'FgQUhKs/VJ9IWJd+wer6sgsgtZmxZNwwHwYDVR0jBBgwFoAUIUd4i/sLTwYWvpVr' +
+'TApzcT8zv/kwIgYDVR0RBBswGYIXQW5pbHMtTWFjQm9vay1Qcm8ubG9jYWwwCgYI' +
+'KoZIzj0EAwIDRwAwRAIgCoXaCdU8ZiRKkai0QiXJM/GL5fysLnmG2oZ6XOIdwtsC' +
+'IEmCsI8Mhrvx1doTbEOm7kmIrhQwUVDBNXCWX1t3kJVN' +
+'-----END CERTIFICATE-----';
+
 describe('chaincodefromcontract', () => {
 
     class MockDataMarhsall {
@@ -356,11 +374,11 @@ describe('chaincodefromcontract', () => {
 
         beforeEach(() => {
             fakeSuccess = sinon.fake((e) => {
-                sinon.assert.fail(e);
+                log(e);
             });
 
             fakeError = sinon.fake((e) => {
-                log(e);
+                sinon.assert.fail(e);
             });
 
             sandbox.replace(shim, 'success', fakeSuccess);
@@ -384,7 +402,7 @@ describe('chaincodefromcontract', () => {
 
             const mockStub = {getBufferArgs: sandbox.stub().returns([])};
             cc.invokeFunctionality = sandbox.stub();
-            cc.Init(mockStub);
+            return cc.Init(mockStub);
 
         });
         it('should handle a single class being passed as a contract', () => {
@@ -405,7 +423,7 @@ describe('chaincodefromcontract', () => {
 
             const mockStub = {getBufferArgs: sandbox.stub().returns([Buffer.from('Hello')])};
             cc.invokeFunctionality = sandbox.stub();
-            cc.Init(mockStub);
+            return cc.Init(mockStub);
 
         });
     });
@@ -427,9 +445,88 @@ describe('chaincodefromcontract', () => {
             sinon.assert.calledOnce(_checkSuppliedStub);
 
 
-            const mockStub = {getBufferArgs: sandbox.stub().returns([Buffer.from('arg1'), Buffer.from('args2')])};
+            const mockStub = {getBufferArgs: sandbox.stub().returns([Buffer.from('arg1'), Buffer.from('args2')]),
+                getTxID: sandbox.stub().returns(12345)};
             cc.invokeFunctionality = sandbox.stub();
-            cc.Invoke(mockStub);
+            return cc.Invoke(mockStub);
+
+        });
+
+        it('should pass the logging object to contracts', async () => {
+            const idBytes = {
+                toBuffer: () => {
+                    return new Buffer(certWithoutAttrs);
+                }
+            };
+            const tempClass =  class  extends Contract {
+                constructor() {
+                    super('logging');
+                }
+                /**
+                    * @param {object} api api
+                    * @param {String} arg1 arg1
+                    * @param {String} arg2 arg2
+                    */
+                async alpha(ctx, arg1, arg2) {
+                    return alphaStub(ctx, arg1, arg2);
+                }
+            };
+            const systemContract = new SystemContract();
+            const appClass = new tempClass();
+            sandbox.stub(ChaincodeFromContract.prototype, '_resolveContractImplementations')
+                .returns({
+                    'org.hyperledger.fabric': {
+                        contractInstance: systemContract
+                    },
+                    'logging':{
+                        contractInstance: appClass,
+                        transactions: [
+                            {
+                                name:'alpha'
+                            }
+                        ],
+                        dataMarshall:{
+                            handleParameters: sandbox.stub().returns([]),
+                            toWireBuffer: sandbox.stub()
+                        }
+                    }
+                });
+            sandbox.stub(ChaincodeFromContract.prototype, '_checkAgainstSuppliedMetadata').returns([]);
+            sandbox.stub(ChaincodeFromContract.prototype, '_compileSchemas');
+
+            const mockSigningId = {
+                getMspid: sinon.stub(),
+                getIdBytes: sinon.stub().returns(idBytes)
+            };
+            const cc = new ChaincodeFromContract([tempClass], defaultSerialization);
+            const mockStub = {getBufferArgs: sandbox.stub().returns(['logging:alpha']),
+                getTxID: sandbox.stub().returns('12345897asd7a7a77v7b77'),
+                getChannelID: sandbox.stub().returns('channel-id-fake'),
+                getCreator: sandbox.stub().returns(mockSigningId)
+            };
+            //
+            const levelSpy = sinon.spy(Logger, 'setLevel');
+            await cc.Invoke(mockStub);
+            const ctx = alphaStub.getCall(0).args[0];
+            ctx.logging.setLevel('DEBUG');
+            sinon.assert.called(levelSpy);
+            sinon.assert.calledWith(levelSpy, 'DEBUG');
+            const cclogger = ctx.logging.getLogger();
+            const logger = Logger.getLogger('logging');
+            const infospy = sinon.spy(logger, 'info');
+            cclogger.info('info');
+            sinon.assert.calledWith(infospy, 'info');
+
+            ctx.logging.setLevel('INFO');
+            sinon.assert.called(levelSpy);
+            sinon.assert.calledWith(levelSpy, 'INFO');
+
+
+            const ccloggerNamed = ctx.logging.getLogger('wibble');
+            const debugSpy = sinon.spy(Logger.getLogger('logging:wibble'), 'debug');
+            ccloggerNamed.debug('Named logger');
+            sinon.assert.calledWith(debugSpy, 'Named logger');
+
 
         });
     });
@@ -474,21 +571,7 @@ describe('chaincodefromcontract', () => {
         let fakeSuccess;
         let fakeError;
 
-        const certWithoutAttrs = '-----BEGIN CERTIFICATE-----' +
-        'MIICXTCCAgSgAwIBAgIUeLy6uQnq8wwyElU/jCKRYz3tJiQwCgYIKoZIzj0EAwIw' +
-        'eTELMAkGA1UEBhMCVVMxEzARBgNVBAgTCkNhbGlmb3JuaWExFjAUBgNVBAcTDVNh' +
-        'biBGcmFuY2lzY28xGTAXBgNVBAoTEEludGVybmV0IFdpZGdldHMxDDAKBgNVBAsT' +
-        'A1dXVzEUMBIGA1UEAxMLZXhhbXBsZS5jb20wHhcNMTcwOTA4MDAxNTAwWhcNMTgw' +
-        'OTA4MDAxNTAwWjBdMQswCQYDVQQGEwJVUzEXMBUGA1UECBMOTm9ydGggQ2Fyb2xp' +
-        'bmExFDASBgNVBAoTC0h5cGVybGVkZ2VyMQ8wDQYDVQQLEwZGYWJyaWMxDjAMBgNV' +
-        'BAMTBWFkbWluMFkwEwYHKoZIzj0CAQYIKoZIzj0DAQcDQgAEFq/90YMuH4tWugHa' +
-        'oyZtt4Mbwgv6CkBSDfYulVO1CVInw1i/k16DocQ/KSDTeTfgJxrX1Ree1tjpaodG' +
-        '1wWyM6OBhTCBgjAOBgNVHQ8BAf8EBAMCB4AwDAYDVR0TAQH/BAIwADAdBgNVHQ4E' +
-        'FgQUhKs/VJ9IWJd+wer6sgsgtZmxZNwwHwYDVR0jBBgwFoAUIUd4i/sLTwYWvpVr' +
-        'TApzcT8zv/kwIgYDVR0RBBswGYIXQW5pbHMtTWFjQm9vay1Qcm8ubG9jYWwwCgYI' +
-        'KoZIzj0EAwIDRwAwRAIgCoXaCdU8ZiRKkai0QiXJM/GL5fysLnmG2oZ6XOIdwtsC' +
-        'IEmCsI8Mhrvx1doTbEOm7kmIrhQwUVDBNXCWX1t3kJVN' +
-        '-----END CERTIFICATE-----';
+
 
         beforeEach(() => {
             fakeSuccess = sinon.fake((e) => {
diff --git a/fabric-shim/test/unit/logger.js b/fabric-shim/test/unit/logger.js
diff --git a/fabric-shim/test/unit/mocha_before.js b/fabric-shim/test/unit/mocha_before.js
