From aba36b04f19a9cca43327abc4ef866c50fdbc2fb Mon Sep 17 00:00:00 2001 From: "Matthew B. White" Date: Thu, 28 Feb 2019 15:23:14 +0000 Subject: [PATCH] [FAB-14490] Logging from chaincode Change-Id: Ibeb5119e468cf28492e517d9a5c785c1425c2134 Signed-off-by: Matthew B. White Signed-off-by: James Taylor --- README.md | 4 +- fabric-contract-api/lib/logger.js | 2 +- fabric-contract-api/test/unit/logger.js | 18 +-- fabric-contract-api/types/index.d.ts | 10 +- .../lib/contract-spi/chaincodefromcontract.js | 6 + fabric-shim/lib/logger.js | 26 +++- .../contract-spi/chaincodefromcontract.js | 125 +++++++++++++++--- fabric-shim/test/unit/logger.js | 18 +-- fabric-shim/test/unit/mocha_before.js | 21 +++ 9 files changed, 182 insertions(+), 48 deletions(-) create mode 100644 fabric-shim/test/unit/mocha_before.js diff --git a/README.md b/README.md index c7495500..cf895bc6 100644 --- 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 index 1f6ddefd..e0e80a0e 100644 --- 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 index ec83c65d..30606b80 100644 --- 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 index c83dba96..23d5b97f 100644 --- 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 index 6d66c1c7..4adc069d 100644 --- 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 index 536ea243..50304336 100644 --- 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 index 3ce96f1a..98cae0e2 100644 --- 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 index 05962433..12d5d36d 100644 --- a/fabric-shim/test/unit/logger.js +++ b/fabric-shim/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-shim/test/unit/mocha_before.js b/fabric-shim/test/unit/mocha_before.js new file mode 100644 index 00000000..d1f03b33 --- /dev/null +++ b/fabric-shim/test/unit/mocha_before.js @@ -0,0 +1,21 @@ +/* + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ +'use strict'; +const sinon = require('sinon'); + +before(() => { + process.on('unhandledRejection', (e) => { + sinon.assert.fail(`You forgot to return a Promise! Check your tests! ${e.message}`); + }); +}); \ No newline at end of file