Rework debug logging

We have various places with overly simple if statements that could be
handled by our logging library. Also a lot of those logs are not marked
as debug logs but as info logs, which can cause confusion during
debugging.

This patch removed unneeded if clauses around debug logging statements,
reworks debug log messages towards ECMA templates and add some new
logging statements which might be helpful in order to debug things like
image uploads.

Signed-off-by: Sheogorath <sheogorath@shivering-isles.com>
This commit is contained in:
Sheogorath 2019-06-08 20:51:24 +02:00
parent 6462968e84
commit b5fc6db75d
No known key found for this signature in database
GPG key ID: 1F05CC3635CDDFFD
15 changed files with 56 additions and 71 deletions

View file

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

View file

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

View file

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

View file

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

View file

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

View file

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

View file

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

View file

@ -7,13 +7,13 @@ const logger = require('../../logger')
const azure = require('azure-storage') const azure = require('azure-storage')
exports.uploadImage = function (imagePath, callback) { 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 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 return
} }

View file

@ -6,15 +6,15 @@ const config = require('../../config')
const logger = require('../../logger') const logger = require('../../logger')
exports.uploadImage = function (imagePath, callback) { 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') { if (!callback || typeof callback !== 'function') {
logger.error('Callback has to be a function') logger.error('Callback has to be a function')
return 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) callback(null, (new URL(path.basename(imagePath), config.serverURL + '/uploads/')).href)
} }

View file

@ -5,22 +5,20 @@ const logger = require('../../logger')
const imgur = require('imgur') const imgur = require('imgur')
exports.uploadImage = function (imagePath, callback) { 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 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 return
} }
imgur.setClientId(config.imgur.clientID) imgur.setClientId(config.imgur.clientID)
imgur.uploadFile(imagePath) imgur.uploadFile(imagePath)
.then(function (json) { .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://')) callback(null, json.data.link.replace(/^http:\/\//i, 'https://'))
}).catch(function (err) { }).catch(function (err) {
callback(new Error(err), null) callback(new Error(err), null)

View file

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

View file

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

View file

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

View file

@ -68,9 +68,7 @@ statusRouter.post('/temp', urlencodedParser, function (req, res) {
if (!data) { if (!data) {
response.errorForbidden(res) response.errorForbidden(res)
} else { } 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({ models.Temp.create({
data: data data: data
}).then(function (temp) { }).then(function (temp) {

View file

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