Merge pull request #103 from SISheogorath/feature/improve-logging

Rework debug logging

lib/history.js

@@ -4,7 +4,6 @@
 var LZString = require('lz-string')
 
 // core
-var config = require('./config')
 var logger = require('./logger')
 var response = require('./response')
 var models = require('./models')
@@ -56,9 +55,7 @@ function getHistory (userid, callback) {
       }
       history = parseHistoryToObject(history)
     }
-    if (config.debug) {
+    logger.debug(`read history success: ${user.id}`)
-      logger.info('read history success: ' + user.id)
-    }
     return callback(null, history)
   }).catch(function (err) {
     logger.error('read history failed: ' + err)
@@ -140,7 +137,7 @@ function historyPost (req, res) {
     var noteId = req.params.noteId
     if (!noteId) {
       if (typeof req.body['history'] === 'undefined') return response.errorBadRequest(res)
-      if (config.debug) { logger.info('SERVER received history from [' + req.user.id + ']: ' + req.body.history) }
+      logger.debug(`SERVER received history from [${req.user.id}]: ${req.body.history}`)
       try {
         var history = JSON.parse(req.body.history)
       } catch (err) {

lib/models/revision.js

@@ -8,7 +8,6 @@ var shortId = require('shortid')
 var path = require('path')
 
 // core
-var config = require('../config')
 var logger = require('../logger')
 
 var dmpWorker = createDmpWorker()
@@ -18,7 +17,7 @@ function createDmpWorker () {
   var worker = childProcess.fork(path.resolve(__dirname, '../workers/dmpWorker.js'), {
     stdio: 'ignore'
   })
-  if (config.debug) logger.info('dmp worker process started')
+  logger.debug('dmp worker process started')
   worker.on('message', function (data) {
     if (!data || !data.msg || !data.cacheKey) {
       return logger.error('dmp worker error: not enough data on message')
@@ -36,7 +35,7 @@ function createDmpWorker () {
   })
   worker.on('close', function (code) {
     dmpWorker = null
-    if (config.debug) logger.info('dmp worker process exited with code ' + code)
+    logger.debug(`dmp worker process exited with code ${code}`)
   })
   return worker
 }

lib/realtime.js

@@ -49,7 +49,7 @@ function secure (socket, next) {
       if (handshakeData.sessionID &&
                 handshakeData.cookie[config.sessionName] &&
                 handshakeData.cookie[config.sessionName] !== handshakeData.sessionID) {
-        if (config.debug) { logger.info('AUTH success cookie: ' + handshakeData.sessionID) }
+        logger.debug(`AUTH success cookie: ${handshakeData.sessionID}`)
         return next()
       } else {
         next(new Error('AUTH failed: Cookie is invalid.'))
@@ -82,7 +82,7 @@ setInterval(function () {
   async.each(Object.keys(notes), function (key, callback) {
     var note = notes[key]
     if (note.server.isDirty) {
-      if (config.debug) logger.info('updater found dirty note: ' + key)
+      logger.debug(`updater found dirty note: ${key}`)
       note.server.isDirty = false
       updateNote(note, function (err, _note) {
         // handle when note already been clean up
@@ -182,7 +182,7 @@ setInterval(function () {
     var socket = realtime.io.sockets.connected[key]
     if ((!socket && users[key]) ||
       (socket && (!socket.rooms || socket.rooms.length <= 0))) {
-      if (config.debug) { logger.info('cleaner found redundant user: ' + key) }
+      logger.debug(`cleaner found redundant user: ${key}`)
       if (!socket) {
         socket = {
           id: key
@@ -429,11 +429,11 @@ function finishConnection (socket, noteId, socketId) {
 
   if (config.debug) {
     let noteId = socket.noteId
-    logger.info('SERVER connected a client to [' + noteId + ']:')
+    logger.debug(`SERVER connected a client to [${noteId}]:`)
-    logger.info(JSON.stringify(user))
+    logger.debug(JSON.stringify(user))
-    // logger.info(notes);
+    logger.debug(notes)
     getStatus(function (data) {
-      logger.info(JSON.stringify(data))
+      logger.debug(JSON.stringify(data))
     })
   }
 }
@@ -541,10 +541,8 @@ function disconnect (socket) {
   if (isDisconnectBusy) return
   isDisconnectBusy = true
 
-  if (config.debug) {
+  logger.debug('SERVER disconnected a client')
-    logger.info('SERVER disconnected a client')
+  logger.debug(JSON.stringify(users[socket.id]))
-    logger.info(JSON.stringify(users[socket.id]))
-  }
 
   if (users[socket.id]) {
     delete users[socket.id]
@@ -574,9 +572,9 @@ function disconnect (socket) {
           delete note.server
           delete notes[noteId]
           if (config.debug) {
-            // logger.info(notes);
+            logger.debug(notes)
             getStatus(function (data) {
-              logger.info(JSON.stringify(data))
+              logger.debug(JSON.stringify(data))
             })
           }
         })
@@ -595,9 +593,9 @@ function disconnect (socket) {
   if (disconnectSocketQueue.length > 0) { disconnect(disconnectSocketQueue[0]) }
 
   if (config.debug) {
-    // logger.info(notes);
+    logger.debug(notes)
     getStatus(function (data) {
-      logger.info(JSON.stringify(data))
+      logger.debug(JSON.stringify(data))
     })
   }
 }
@@ -774,7 +772,7 @@ function connection (socket) {
     var noteId = socket.noteId
     var user = users[socket.id]
     if (!noteId || !notes[noteId] || !user) return
-    if (config.debug) { logger.info('SERVER received [' + noteId + '] user status from [' + socket.id + ']: ' + JSON.stringify(data)) }
+    logger.debug(`SERVER received [${noteId}] user status from [${socket.id}]: ${JSON.stringify(data)}`)
     if (data) {
       user.idle = data.idle
       user.type = data.type

lib/web/auth/ldap/index.js

@@ -66,11 +66,11 @@ passport.use(new LDAPStrategy({
       }
       if (needSave) {
         user.save().then(function () {
-          if (config.debug) { logger.debug('user login: ' + user.id) }
+          logger.debug(`user login: ${user.id}`)
           return done(null, user)
         })
       } else {
-        if (config.debug) { logger.debug('user login: ' + user.id) }
+        logger.debug(`user login: ${user.id}`)
         return done(null, user)
       }
     }

lib/web/auth/openid/index.js

@@ -33,11 +33,11 @@ passport.use(new OpenIDStrategy({
       }
       if (needSave) {
         user.save().then(function () {
-          if (config.debug) { logger.info('user login: ' + user.id) }
+          logger.debug(`user login: ${user.id}`)
           return done(null, user)
         })
       } else {
-        if (config.debug) { logger.info('user login: ' + user.id) }
+        logger.debug(`user login: ${user.id}`)
         return done(null, user)
       }
     }

lib/web/auth/saml/index.js

@@ -62,11 +62,11 @@ passport.use(new SamlStrategy({
       }
       if (needSave) {
         user.save().then(function () {
-          if (config.debug) { logger.debug('user login: ' + user.id) }
+          logger.debug(`user login: ${user.id}`)
           return done(null, user)
         })
       } else {
-        if (config.debug) { logger.debug('user login: ' + user.id) }
+        logger.debug(`user login: ${user.id}`)
         return done(null, user)
       }
     }

lib/web/auth/utils.js

@@ -1,7 +1,6 @@
 'use strict'
 
 const models = require('../../models')
-const config = require('../../config')
 const logger = require('../../logger')
 
 exports.setReturnToFromReferer = function setReturnToFromReferer (req) {
@@ -38,11 +37,11 @@ exports.passportGeneralCallback = function callback (accessToken, refreshToken,
       }
       if (needSave) {
         user.save().then(function () {
-          if (config.debug) { logger.info('user login: ' + user.id) }
+          logger.debug(`user login: ${user.id}`)
           return done(null, user)
         })
       } else {
-        if (config.debug) { logger.info('user login: ' + user.id) }
+        logger.debug(`user login: ${user.id}`)
         return done(null, user)
       }
     }

lib/web/imageRouter/azure.js

@@ -7,13 +7,13 @@ const logger = require('../../logger')
 const azure = require('azure-storage')
 
 exports.uploadImage = function (imagePath, callback) {
-  if (!imagePath || typeof imagePath !== 'string') {
+  if (!callback || typeof callback !== 'function') {
-    callback(new Error('Image path is missing or wrong'), null)
+    logger.error('Callback has to be a function')
     return
   }
 
-  if (!callback || typeof callback !== 'function') {
+  if (!imagePath || typeof imagePath !== 'string') {
-    logger.error('Callback has to be a function')
+    callback(new Error('Image path is missing or wrong'), null)
     return
   }
 

lib/web/imageRouter/filesystem.js

@@ -6,15 +6,15 @@ const config = require('../../config')
 const logger = require('../../logger')
 
 exports.uploadImage = function (imagePath, callback) {
-  if (!imagePath || typeof imagePath !== 'string') {
-    callback(new Error('Image path is missing or wrong'), null)
-    return
-  }
-
   if (!callback || typeof callback !== 'function') {
     logger.error('Callback has to be a function')
     return
   }
 
+  if (!imagePath || typeof imagePath !== 'string') {
+    callback(new Error('Image path is missing or wrong'), null)
+    return
+  }
+
   callback(null, (new URL(path.basename(imagePath), config.serverURL + '/uploads/')).href)
 }

lib/web/imageRouter/imgur.js

@@ -5,22 +5,20 @@ const logger = require('../../logger')
 const imgur = require('imgur')
 
 exports.uploadImage = function (imagePath, callback) {
-  if (!imagePath || typeof imagePath !== 'string') {
+  if (!callback || typeof callback !== 'function') {
-    callback(new Error('Image path is missing or wrong'), null)
+    logger.error('Callback has to be a function')
     return
   }
 
-  if (!callback || typeof callback !== 'function') {
+  if (!imagePath || typeof imagePath !== 'string') {
-    logger.error('Callback has to be a function')
+    callback(new Error('Image path is missing or wrong'), null)
     return
   }
 
   imgur.setClientId(config.imgur.clientID)
   imgur.uploadFile(imagePath)
     .then(function (json) {
-      if (config.debug) {
+      logger.debug(`SERVER uploadimage success: ${JSON.stringify(json)}`)
-        logger.info('SERVER uploadimage success: ' + JSON.stringify(json))
-      }
       callback(null, json.data.link.replace(/^http:\/\//i, 'https://'))
     }).catch(function (err) {
       callback(new Error(err), null)

lib/web/imageRouter/index.js

@@ -21,18 +21,19 @@ imageRouter.post('/uploadimage', function (req, res) {
 
   form.parse(req, function (err, fields, files) {
     if (err || !files.image || !files.image.path) {
+      logger.error(`formidable error: ${err}`)
       response.errorForbidden(res)
     } else {
-      if (config.debug) {
+      logger.debug(`SERVER received uploadimage: ${JSON.stringify(files.image)}`)
-        logger.info('SERVER received uploadimage: ' + JSON.stringify(files.image))
-      }
 
       const uploadProvider = require('./' + config.imageUploadType)
+      logger.debug(`imageRouter: Uploading ${files.image.path} using ${config.imageUploadType}`)
       uploadProvider.uploadImage(files.image.path, function (err, url) {
         if (err !== null) {
           logger.error(err)
           return res.status(500).end('upload image error')
         }
+        logger.debug(`SERVER sending ${url} to client`)
         res.send({
           link: url
         })

lib/web/imageRouter/lutim.js

@@ -5,25 +5,24 @@ const logger = require('../../logger')
 const lutim = require('lutim')
 
 exports.uploadImage = function (imagePath, callback) {
-  if (!imagePath || typeof imagePath !== 'string') {
-    callback(new Error('Image path is missing or wrong'), null)
-    return
-  }
-
   if (!callback || typeof callback !== 'function') {
     logger.error('Callback has to be a function')
     return
   }
 
+  if (!imagePath || typeof imagePath !== 'string') {
+    callback(new Error('Image path is missing or wrong'), null)
+    return
+  }
+
   if (config.lutim && config.lutim.url) {
     lutim.setAPIUrl(config.lutim.url)
+    logger.debug(`Set lutim URL to ${lutim.getApiUrl()}`)
   }
 
   lutim.uploadImage(imagePath)
     .then(function (json) {
-      if (config.debug) {
+      logger.debug(`SERVER uploadimage success: ${JSON.stringify(json)}`)
-        logger.info('SERVER uploadimage success: ' + JSON.stringify(json))
-      }
       callback(null, lutim.getAPIUrl() + json.msg.short)
     }).catch(function (err) {
       callback(new Error(err), null)

lib/web/imageRouter/s3.js

@@ -35,6 +35,7 @@ exports.uploadImage = function (imagePath, callback) {
     const mimeType = getImageMimeType(imagePath)
     if (mimeType) { params.ContentType = mimeType }
 
+    logger.debug(`S3 object parameters: ${JSON.stringify(params)}`)
     s3.putObject(params, function (err, data) {
       if (err) {
         callback(new Error(err), null)

lib/web/statusRouter.js

@@ -68,9 +68,7 @@ statusRouter.post('/temp', urlencodedParser, function (req, res) {
     if (!data) {
       response.errorForbidden(res)
     } else {
-      if (config.debug) {
+      logger.debug(`SERVER received temp from [${host}]: ${req.body.data}`)
-        logger.info('SERVER received temp from [' + host + ']: ' + req.body.data)
-      }
       models.Temp.create({
         data: data
       }).then(function (temp) {

lib/workers/dmpWorker.js

@@ -4,7 +4,6 @@ var DiffMatchPatch = require('diff-match-patch')
 var dmp = new DiffMatchPatch()
 
 // core
-var config = require('../config')
 var logger = require('../logger')
 
 process.on('message', function (data) {
@@ -61,10 +60,8 @@ function createPatch (lastDoc, currDoc) {
   var patch = dmp.patch_make(lastDoc, diff)
   patch = dmp.patch_toText(patch)
   var msEnd = (new Date()).getTime()
-  if (config.debug) {
+  logger.debug(patch)
-    logger.info(patch)
+  logger.debug((msEnd - msStart) + 'ms')
-    logger.info((msEnd - msStart) + 'ms')
-  }
   return patch
 }
 
@@ -123,9 +120,7 @@ function getRevision (revisions, count) {
     authorship: authorship
   }
   var msEnd = (new Date()).getTime()
-  if (config.debug) {
+  logger.debug((msEnd - msStart) + 'ms')
-    logger.info((msEnd - msStart) + 'ms')
-  }
   return data
 }