[Master] ensure logging files are flushed for CLI (#4480)

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

packages/composer-cli/cli.js

@@ -21,6 +21,9 @@ const cmdUtil = require('./lib/cmds/utils/cmdutils');
 const yargs = require('yargs');
 const chalk = require('chalk');
 const version = 'v' +require('./package.json').version;
+const Logger = require('composer-common').Logger;
+const LOG = Logger.getLog('CLI');
+LOG.info('CLI', 'CLI Launched with', process.argv);
 
 let results = yargs
     .commandDir('./lib/cmds')
@@ -41,11 +44,11 @@ if (typeof(results.thePromise) !== 'undefined'){
         if (!results.quiet) {
             cmdUtil.log(chalk.green('\nCommand succeeded\n'));
         }
-        process.exit(0);
+        Logger.flushLogFileAndExit(0);
     }).catch((error) => {
         cmdUtil.log(error+chalk.red('\nCommand failed\n'));
-        process.exit(1);
+        Logger.flushLogFileAndExit(1);
     });
 } else {
-    process.exit(0);
+    Logger.flushLogFileAndExit(0);
 }

packages/composer-cli/test/cli.js

@@ -20,6 +20,7 @@ chai.should();
 chai.use(require('chai-things'));
 chai.use(require('chai-as-promised'));
 const path = require('path');
+const Logger = require('composer-common').Logger;
 
 const yargs = require('yargs');
 const chalk = require('chalk');
@@ -66,7 +67,7 @@ describe('composer cli', () => {
         sandbox.stub(yargs, 'alias').returns(yargs);
         sandbox.stub(yargs, 'version').returns(yargs);
 
-        sandbox.stub(process, 'exit');
+        sandbox.stub(Logger, 'flushLogFileAndExit');
         sandbox.stub(chalk, 'green');
         sandbox.stub(chalk, 'red');
     });
@@ -92,27 +93,27 @@ describe('composer cli', () => {
             sinon.assert.calledOnce(yargs.alias);
             sinon.assert.calledOnce(yargs.version);
             sinon.assert.calledOnce(yargs.describe);
-            sinon.assert.calledWith(process.exit, 0);
+            sinon.assert.calledWith(Logger.flushLogFileAndExit, 0);
 
         });
 
         it('Should handle resolved promise', () => {
             sandbox.stub(yargs, 'describe').returns({ argv: {thePromise: new fakePromise()} });
             delete require.cache[path.resolve(__dirname, '../cli.js')];
             require('../cli.js');
-            sinon.assert.calledWith(process.exit, 0);
+            sinon.assert.calledWith(Logger.flushLogFileAndExit, 0);
         });
         it('Should handle resolved promise, with the quiet setting', () => {
             sandbox.stub(yargs, 'describe').returns({ argv: {thePromise: new fakePromise(),quiet:true} });
             delete require.cache[path.resolve(__dirname, '../cli.js')];
             require('../cli.js');
-            sinon.assert.calledWith(process.exit, 0);
+            sinon.assert.calledWith(Logger.flushLogFileAndExit, 0);
         });
         it('Should handle rejected promise', () => {
             sandbox.stub(yargs, 'describe').returns({ argv: {thePromise: new fakePromise()} });
             delete require.cache[path.resolve(__dirname, '../cli.js')];
             require('../cli.js');
-            sinon.assert.calledWith(process.exit, 1);
+            sinon.assert.calledWith(Logger.flushLogFileAndExit, 1);
         });
 
     });

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

@@ -431,6 +431,26 @@ class Logger {
         return _config;
     }
 
+    /**
+     * flush out the standard composer log file and exit. This is only of use to CLI
+     * applications which will log to the file system.
+     * @param {*} err the exit value
+     */
+    static flushLogFileAndExit(err) {
+        const fileTransport = _logger && _logger.transports ? _logger.transports['debug-file'] : null;
+        if (fileTransport && fileTransport._stream) {
+            fileTransport.on('flush', () => {
+                process.exit(err);
+            });
+            // calling close on the logger sometimes hung the cli
+            // flush could fail if there was no stream, but appears to be more reliable.
+            fileTransport.flush();
+        } else {
+            process.exit(err);
+        }
+
+    }
+
     /**
      * return the log configuration that is in force, note that this method just returns the information
      * it does create, modify or delete it
@@ -667,9 +687,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/test/log/logger.js

@@ -459,7 +459,7 @@ describe('Logger', () => {
 
     });
 
-    describe('#getLoggerCfg', () => {
+    describe('#processLoggerConfig', () => {
         let sandbox;
 
         beforeEach(()=>{
@@ -869,6 +869,88 @@ describe('Logger', () => {
 
     });
 
+    describe('#flushLogFileAndExit', () => {
+        let sandbox;
+
+        beforeEach(()=>{
+            Logger.__reset();
+            sandbox = sinon.sandbox.create();
+        });
+
+        afterEach(()=>{
+            Logger.__reset();
+            sandbox.restore();
+        });
+
+        it('should just exit with error code if no transports defined', () => {
+            sandbox.stub(process, 'exit');
+            let stubLogger = {
+            };
+
+            Logger.setFunctionalLogger(stubLogger);
+            Logger.flushLogFileAndExit(99);
+            sinon.assert.calledOnce(process.exit);
+            sinon.assert.calledWith(process.exit, 99);
+        });
+
+        it('should just exit with error code if no file logger transport defined', () => {
+            sandbox.stub(process, 'exit');
+            let stubTransport = {
+                on: sinon.stub(),
+                flush: sinon.stub()
+            };
+            let stubLogger = {
+                transports: {'info-file': stubTransport}
+            };
+
+            Logger.setFunctionalLogger(stubLogger);
+            Logger.flushLogFileAndExit(0);
+            sinon.assert.calledOnce(process.exit);
+            sinon.assert.calledWith(process.exit, 0);
+            sinon.assert.notCalled(stubTransport.on);
+            sinon.assert.notCalled(stubTransport.flush);
+        });
+
+        it('should just exit with error code if file logger transport defined, but no stream exists', () => {
+            sandbox.stub(process, 'exit');
+            let stubTransport = {
+                on: sinon.stub(),
+                flush: sinon.stub()
+            };
+            let stubLogger = {
+                transports: {'debug-file': stubTransport}
+            };
+
+            Logger.setFunctionalLogger(stubLogger);
+            Logger.flushLogFileAndExit(0);
+            sinon.assert.calledOnce(process.exit);
+            sinon.assert.calledWith(process.exit, 0);
+            sinon.assert.notCalled(stubTransport.on);
+            sinon.assert.notCalled(stubTransport.flush);
+        });
+
+
+        it('should register a flush handler and exit only when that exit handler is called if file logger transport defined', () => {
+            sandbox.stub(process, 'exit');
+            let stubTransport = {
+                on: sinon.stub().yields(),
+                flush: sinon.stub(),
+                _stream: {}
+            };
+            let stubLogger = {
+                close: sinon.stub(),
+                transports: {'debug-file': stubTransport}
+            };
+
+            Logger.setFunctionalLogger(stubLogger);
+            Logger.flushLogFileAndExit(77);
+            sinon.assert.calledOnce(process.exit);
+            sinon.assert.calledWith(process.exit, 77);
+            sinon.assert.calledOnce(stubTransport.flush);
+            sinon.assert.calledOnce(stubTransport.on);
+        });
+    });
+
     describe('#invokeAllLevels', ()=>{
         let logger = {
             debug:   sinon.stub(),