See #924. Add more verbose debugging to beautifyFilePath

src/beautifiers/beautifier.coffee

@@ -20,27 +20,27 @@ module.exports = class Beautifier
 
   ###
   Supported Options
-  
+
   Enable options for supported languages.
   - <string:language>:<boolean:all_options_enabled>
   - <string:language>:<string:option_key>:<boolean:enabled>
   - <string:language>:<string:option_key>:<string:rename>
   - <string:language>:<string:option_key>:<function:transform>
   - <string:language>:<string:option_key>:<array:mapper>
-  
+
   ###
   options: {}
 
   ###
   Supported languages by this Beautifier
-  
+
   Extracted from the keys of the `options` field.
   ###
   languages: null
 
   ###
   Beautify text
-  
+
   Override this method in subclasses
   ###
   beautify: null
@@ -87,7 +87,7 @@ module.exports = class Beautifier
 
   ###
   Get Shell Environment variables
-  
+
   Special thank you to @ioquatix
   See https://github.com/ioquatix/script-runner/blob/v1.5.0/lib/script-runner.coffee#L45-L63
   ###
@@ -139,7 +139,7 @@ module.exports = class Beautifier
 
   ###
   Like the unix which utility.
-  
+
   Finds the first instance of a specified executable in the PATH environment variable.
   Does not cache the results,
   so hash -r is not needed when the PATH changes.
@@ -165,7 +165,7 @@ module.exports = class Beautifier
 
   ###
   Add help to error.description
-  
+
   Note: error.description is not officially used in JavaScript,
   however it is used internally for Atom Beautify when displaying errors.
   ###
@@ -319,7 +319,7 @@ module.exports = class Beautifier
     for key, method of @logger
       # @verbose(key, method)
       @[key] = method
-    @verbose("Beautifier logger has been initialized.")
+    @verbose("#{@name} beautifier logger has been initialized.")
 
   ###
   Constructor to setup beautifer

src/beautify.coffee

@@ -180,6 +180,7 @@ beautify = ({onSave}) ->
   return
 
 beautifyFilePath = (filePath, callback) ->
+  logger.verbose('beautifyFilePath', filePath)
 
   # Show in progress indicate on file's tree-view entry
   $ ?= require("atom-space-pen-views").$
@@ -188,28 +189,35 @@ beautifyFilePath = (filePath, callback) ->
 
   # Cleanup and return callback function
   cb = (err, result) ->
+    logger.verbose('Cleanup beautifyFilePath', err, result)
     $el = $(".icon-file-text[data-path=\"#{filePath}\"]")
     $el.removeClass('beautifying')
     return callback(err, result)
 
   # Get contents of file
   fs ?= require "fs"
+  logger.verbose('readFile', filePath)
   fs.readFile(filePath, (err, data) ->
+    logger.verbose('readFile completed', err, filePath)
     return cb(err) if err
     input = data?.toString()
     grammar = atom.grammars.selectGrammar(filePath, input)
     grammarName = grammar.name
 
     # Get the options
     allOptions = beautifier.getOptionsForPath(filePath)
+    logger.verbose('beautifyFilePath allOptions', allOptions)
 
     # Beautify File
     completionFun = (output) ->
+      logger.verbose('beautifyFilePath completionFun', output)
       if output instanceof Error
         return cb(output, null ) # output == Error
       else if typeof output is "string"
         # do not allow empty string
-        return cb(null, output) if output is ''
+        if output.trim() is ''
+          logger.verbose('beautifyFilePath, output was empty string!')
+          return cb(null, output)
         # save to file
         fs.writeFile(filePath, output, (err) ->
           return cb(err) if err
@@ -218,6 +226,7 @@ beautifyFilePath = (filePath, callback) ->
       else
         return cb( new Error("Unknown beautification result #{output}."), output)
     try
+      logger.verbose('beautify', input, allOptions, grammarName, filePath)
       beautifier.beautify(input, allOptions, grammarName, filePath)
       .then(completionFun)
       .catch(completionFun)
@@ -470,8 +479,9 @@ debug = () ->
 
 handleSaveEvent = ->
   atom.workspace.observeTextEditors (editor) ->
-    buffer = editor.getBuffer()
-    disposable = buffer.onDidSave(({path : filePath}) ->
+    disposable = editor.onDidSave(({path : filePath}) ->
+      logger.verbose('Should beautify on this save?')
+      buffer = editor.getBuffer()
       path ?= require('path')
       # Get Grammar
       grammar = editor.getGrammar().name
@@ -492,14 +502,18 @@ handleSaveEvent = ->
       if beautifyOnSave
         posArray = getCursors(editor)
         origScrollTop = getScrollTop(editor)
+        logger.verbose('Beautifying file', filePath)
         beautifyFilePath(filePath, ->
+          logger.verbose('Done beautifying file', filePath)
           if editor.isAlive() is true
+            logger.verbose('Reloading TextEditor buffer...')
             buffer.reload()
-            logger.verbose('restore editor positions', posArray,origScrollTop)
+            logger.verbose('Reloaded TextEditor buffer.')
             # Let the scrollTop setting run after all the save related stuff is run,
             # otherwise setScrollTop is not working, probably because the cursor
             # addition happens asynchronously
             setTimeout ( ->
+              logger.verbose('restore editor positions', posArray,origScrollTop)
               setCursors(editor, posArray)
               setScrollTop(editor, origScrollTop)
               # console.log "setScrollTop"

src/logger.coffee

@@ -57,7 +57,8 @@ module.exports = do ->
         label = "#{path.dirname(transport.label)\
                     .split(path.sep).reverse()[0]}\
                     #{path.sep}#{path.basename(transport.label)}"
-        console.log("#{label} [#{level}]: #{msg}", meta)
+        d = new Date()
+        console.log("#{d.toLocaleDateString()} #{d.toLocaleTimeString()} - #{label} [#{level}]: #{msg}", meta)
     )
     # Export logger methods
     loggerMethods = ['silly','debug','verbose','info','warn','error']