feat: Add extensive 'verbose', 'debug', and 'silly' logging

CONTRIBUTING.md

@@ -173,10 +173,9 @@ If you want to build something on top of the Apiary Reporter, note that it uses
 - [Apiary Tests API for anonymous test reports][]
 - [Apiary Tests API for authenticated test reports][]
 
-There are also some environment variables you could find useful:
+There is also one environment variable you could find useful:
 
 - `APIARY_API_URL='https://api.apiary.io'` - Allows to override host of the Apiary Tests API.
-- `DREDD_REST_DEBUG=true` - Turns on some additional logging. Useful for debugging.
 
 
 [Apiary]: https://apiary.io/

docs/how-to-guides.md

@@ -535,8 +535,7 @@ Command-line output of complex HTTP responses and expectations can be hard to re
 
 ```
 $ dredd apiary.apib http://localhost --reporter=apiary
-info: Using apiary reporter.
-warn: Apiary reporter environment variable APIARY_API_KEY or APIARY_API_NAME not defined.
+warn: Apiary API Key or API Project Subdomain were not provided. Configure Dredd to be able to save test reports alongside your Apiary API project: http://dredd.readthedocs.io/en/latest/how-to-guides/#using-apiary-reporter-and-apiary-tests
 info: Beginning Dredd testing...
 pass: DELETE /honey duration: 884ms
 complete: 1 passing, 0 failing, 0 errors, 0 skipped, 1 total

src/add-hooks.coffee

@@ -44,11 +44,12 @@ addHooks = (runner, transactions, callback) ->
       fixLegacyTransactionNames runner.hooks
 
     catch error
-      logger.warn 'Skipping hook loading...'
-      logger.warn 'Error reading hook file "' + filePath + '"'
-      logger.warn 'This probably means one or more of your hookfiles is invalid.'
-      logger.warn 'Message: ' + error.message if error.message?
-      logger.warn 'Stack: ' + error.stack if error.stack?
+      logger.warn("""\
+        Skipping hook loading. Error reading hook file '#{filePath}'. \
+        This probably means one or more of your hook files is invalid.
+        Message: #{error.message}
+        Stack: #{error.stack}
+      """)
 
   loadSandboxHooksFromStrings = (callback) ->
     if typeof(runner.configuration.hooksData) != 'object' or Array.isArray(runner.configuration.hooksData) != false
@@ -87,9 +88,9 @@ addHooks = (runner, transactions, callback) ->
         loadSandboxHooksFromStrings(callback)
       else
         # not sandboxed code can't be loaded from the string
-        msg = """
-        Not sandboxed hooks loading from strings is not implemented,
-        Sandbox mode must be enabled when loading hooks from strings."
+        msg = """\
+          Not sandboxed hooks loading from strings is not implemented, \
+          Sandbox mode must be enabled when loading hooks from strings.\
         """
         callback(new Error(msg))
     else
@@ -110,7 +111,7 @@ addHooks = (runner, transactions, callback) ->
     for globItem in globs
       files = files.concat glob.sync(globItem)
 
-    logger.info 'Found Hookfiles: ' + files
+    logger.info('Found Hookfiles:', files)
 
     # Loading files in non sandboxed nodejs
     if not runner.configuration.options.sandbox == true
@@ -137,7 +138,7 @@ addHooks = (runner, transactions, callback) ->
     else
 
       # load sandbox files from fs
-      logger.info 'Loading hookfiles in sandboxed context: ' + files
+      logger.info('Loading hook files in sandboxed context:', files)
       async.eachSeries files, (fileName, nextFile) ->
         resolvedPath = path.resolve((customConfigCwd or process.cwd()), fileName)
         # load hook file content

src/configure-reporters.coffee

@@ -7,7 +7,7 @@ HtmlReporter = require './reporters/html-reporter'
 MarkdownReporter = require './reporters/markdown-reporter'
 ApiaryReporter = require './reporters/apiary-reporter'
 
-logger = require './logger'
+logger = require('./logger')
 
 fileReporters = ['junit', 'html', 'markdown', 'apiary']
 cliReporters = ['dot', 'nyan']
@@ -18,8 +18,10 @@ intersection = (a, b) ->
 
 configureReporters = (config, stats, tests, runner) ->
   baseReporter = new BaseReporter(config.emitter, stats, tests)
+
   reporters = config.options.reporter
   outputs = config.options.output
+  logger.debug('Configuring reporters:', reporters, outputs)
 
   addCli = (reporters) ->
     if reporters.length > 0
@@ -62,10 +64,10 @@ configureReporters = (config, stats, tests, runner) ->
       usedFileReportersLength = usedFileReportersLength - 1
 
     if usedFileReportersLength > outputs.length
-      logger.warn """
-      There are more reporters requiring output paths than there are output paths \
-      provided, using default paths for additional file-based reporters.
-      """
+      logger.warn('''\
+        There are more reporters requiring output paths than there are output paths \
+        provided. Using default paths for additional file-based reporters.\
+      ''')
 
     for reporter, i in usedFileReporters
       path = if outputs[i] then outputs[i] else null

src/dredd-command.coffee

@@ -9,13 +9,15 @@ spawnArgs = require 'spawn-args'
 Dredd = require './dredd'
 interactiveConfig = require './interactive-config'
 configUtils = require './config-utils'
-logger = require './logger'
+logger = require('./logger')
 
 packageData = require('../package.json')
 
+
 TERM_TIMEOUT = 1000
 TERM_RETRY = 500
 
+
 class DreddCommand
   constructor: (options = {}, @cb) ->
     @finished = false
@@ -54,17 +56,19 @@ class DreddCommand
 
     @argv = @optimist.argv
 
-
   # Gracefully terminate server
   stopServer: (callback) ->
-    return callback() unless @serverProcess?
+    logger.verbose('Gracefully terminating backend server process.')
+    unless @serverProcess?
+      logger.verbose('No backend server process.')
+      return callback()
 
     term = =>
-      logger.info 'Sending SIGTERM to the backend server'
+      logger.info('Sending SIGTERM to backend server process.')
       @serverProcess.kill 'SIGTERM'
 
     kill = =>
-      logger.info 'Killing backend server'
+      logger.info('Killing backend server process.')
       @serverProcess.kill 'SIGKILL'
 
     start = Date.now()
@@ -73,8 +77,10 @@ class DreddCommand
     waitForServerTermOrKill = =>
       if @serverProcessEnded == true
         clearTimeout timeout
+        logger.debug('Backend server process successfully terminated.')
         callback()
       else
+        logger.debug('Backend server process haven\'t terminated yet.')
         if (Date.now() - start) < TERM_TIMEOUT
           term()
           timeout = setTimeout waitForServerTermOrKill, TERM_RETRY
@@ -85,7 +91,6 @@ class DreddCommand
 
     timeout = setTimeout waitForServerTermOrKill, TERM_RETRY
 
-
   # This thing-a-ma-bob here is only for purpose of testing
   # It's basically a dependency injection for the process.exit function
   setExitOrCallback: ->
@@ -95,33 +100,36 @@ class DreddCommand
 
       if @exit
         @_processExit = (exitStatus) =>
+          logger.verbose("Exiting Dredd process with status '#{exitStatus}'.")
+          logger.debug('Using configured custom exit() method to terminate the Dredd process.')
           @finished = true
-
-          @stopServer () =>
+          @stopServer =>
             @exit(exitStatus)
-
       else
         @_processExit = (exitStatus) =>
-
-          @stopServer () ->
+          logger.verbose("Exiting Dredd process with status '#{exitStatus}'.")
+          logger.debug('Using native process.exit() method to terminate the Dredd process.')
+          @stopServer ->
             process.exit exitStatus
-
     else
       @_processExit = (exitStatus) =>
+        logger.verbose("Exiting Dredd process with status '#{exitStatus}'.")
+        logger.debug('Using configured custom callback to terminate the Dredd process.')
         @finished = true
         if @sigIntEventAdded
-          @serverProcess.kill('SIGKILL') if @serverProcess?
-
+          if @serverProcess?
+            logger.verbose('Killing backend server process before Dredd exits.')
+            @serverProcess.kill('SIGKILL')
           process.removeEventListener 'SIGINT', @commandSigInt
         @cb exitStatus
         return @
 
-  moveBlueprintArgToPath: () ->
+  moveBlueprintArgToPath: ->
     # transform path and p argument to array if it's not
     if !Array.isArray(@argv['path'])
       @argv['path'] = @argv['p'] = [@argv['path']]
 
-  checkRequiredArgs: () ->
+  checkRequiredArgs: ->
     argError = false
 
     # if 'blueprint' is missing
@@ -140,10 +148,10 @@ class DreddCommand
       @optimist.showHelp(console.error)
       return @_processExit(1)
 
-
-  runExitingActions: () ->
+  runExitingActions: ->
     # run interactive config
     if @argv["_"][0] == "init" or @argv.init == true
+      logger.silly('Starting interactive configuration.')
       @finished = true
       interactiveConfig.run @argv, (config) =>
         configUtils.save(config)
@@ -173,18 +181,21 @@ class DreddCommand
 
     # show help
     else if @argv.help is true
+      logger.silly('Printing help.')
       @optimist.showHelp(console.error)
       return @_processExit(0)
 
     # show version
     else if @argv.version is true
+      logger.silly('Printing version.')
       console.log("""\
         #{packageData.name} v#{packageData.version} \
         (#{os.type()} #{os.release()}; #{os.arch()})
       """)
       return @_processExit(0)
 
   loadDreddFile: ->
+    logger.verbose('Loading configuration file.')
     configPath = @argv.config
     if configPath and fs.existsSync configPath
       logger.info("Configuration '#{configPath}' found, ignoring other arguments.")
@@ -195,20 +206,22 @@ class DreddCommand
       if key != "_" and key != "$0"
         @argv[key] = value
 
-
-  parseCustomConfig: () ->
+  parseCustomConfig: ->
     @argv.custom = configUtils.parseCustom @argv.custom
 
   runServerAndThenDredd: (callback) ->
     if not @argv['server']?
+      logger.verbose('No backend server process specified, starting testing at once.')
       @runDredd @dreddInstance
     else
+      logger.verbose('Backend server process specified, starting backend server and then testing.')
+
       parsedArgs = spawnArgs(@argv['server'])
       command = parsedArgs.shift()
 
       @serverProcess = spawn command, parsedArgs
 
-      logger.info "Starting server with command: #{@argv['server']}"
+      logger.info("Starting backend server process with command: #{@argv['server']}")
 
       @serverProcess.stdout.setEncoding 'utf8'
 
@@ -223,32 +236,37 @@ class DreddCommand
       @serverProcess.on 'close' , (status) =>
         @serverProcessEnded = true
         if status?
-          logger.info 'Backend server exited'
+          logger.info('Backend server process exited.')
         else
-          logger.info 'Backend server was killed'
+          logger.info('Backend server process was killed.')
 
 
       @serverProcess.on 'error', (error) =>
-        logger.error "Server command failed, exiting Dredd..."
+        logger.error('Command to start backend server process failed, exiting Dredd.')
         @_processExit(2)
 
       # Ensure server is not running when dredd exits prematurely somewhere
-      process.on 'beforeExit', () =>
-        @serverProcess.kill('SIGKILL') if @serverProcess?
+      process.on 'beforeExit', =>
+        if @serverProcess?
+          logger.verbose('Killing backend server process before Dredd exits.')
+          @serverProcess.kill('SIGKILL')
 
       # Ensure server is not running when dredd exits prematurely somewhere
-      process.on 'exit', () =>
-        @serverProcess.kill('SIGKILL') if @serverProcess?
+      process.on 'exit', =>
+        if @serverProcess?
+          logger.verbose('Killing backend server process on Dredd\'s exit.')
+          @serverProcess.kill('SIGKILL')
 
       waitSecs = parseInt(@argv['server-wait'], 10)
       waitMilis = waitSecs * 1000
-      logger.info "Waiting #{waitSecs} seconds for server command to start..."
+      logger.info("Waiting #{waitSecs} seconds for backend server process to start.")
 
       @wait = setTimeout =>
         @runDredd @dreddInstance
       , waitMilis
 
   run: ->
+    logger.verbose('Preparing for start of testing.')
     for task in [
       @setOptimistArgv
       @parseCustomConfig
@@ -266,14 +284,11 @@ class DreddCommand
     try
       @runServerAndThenDredd()
     catch e
-      logger.error e.message
-      logger.error e.stack
-      @stopServer () =>
+      logger.error(e.message, e.stack)
+      @stopServer =>
         @_processExit(2)
     return
 
-
-
   lastArgvIsApiEndpoint: ->
     # when API description path is a glob, some shells are automatically expanding globs and concating
     # result as arguments so I'm taking last argument as API endpoint server URL and removing it
@@ -288,9 +303,7 @@ class DreddCommand
     return @
 
   initConfig: ->
-    @
-    .lastArgvIsApiEndpoint()
-    .takeRestOfParamsAsPath()
+    @lastArgvIsApiEndpoint().takeRestOfParamsAsPath()
 
     configuration =
       'server': @server
@@ -305,11 +318,10 @@ class DreddCommand
     return configuration
 
   initDredd: (configuration) ->
-    dredd = new Dredd configuration
-    return dredd
+    return new Dredd(configuration)
 
   commandSigInt: ->
-    logger.error "\nShutting down from SIGINT (Ctrl-C)"
+    logger.error('\nShutting down from keyboard interruption (Ctrl+C)')
     @dreddInstance.transactionsComplete => @_processExit(0)
 
   runDredd: (dreddInstance) ->
@@ -318,16 +330,16 @@ class DreddCommand
       @sigIntEventAdded = !@sigIntEventAdd = false
       process.on 'SIGINT', @commandSigInt
 
+    logger.verbose('Running Dredd instance.')
     dreddInstance.run (error, stats) =>
+      logger.verbose('Dredd instance run finished.')
       @exitWithStatus(error, stats)
 
     return @
 
   exitWithStatus: (error, stats) ->
     if error
-      if error.message
-        logger.error error.message
-
+      logger.error(error.message) if error.message
       return @_processExit(1)
 
     if (stats.failures + stats.errors) > 0
@@ -336,4 +348,5 @@ class DreddCommand
       @_processExit(0)
     return
 
+
 exports = module.exports = DreddCommand