From a82b66c6370c1be8c8d5a45bf16481b95e2df2e3 Mon Sep 17 00:00:00 2001 From: baldo Date: Tue, 24 May 2016 16:40:57 +0200 Subject: [PATCH] Added logging framework. --- config.json.example | 4 ++ package.json | 1 + server/app.js | 2 +- server/config.js | 4 ++ server/db/database.js | 32 ++++++++++-- server/jobs/mailQueueJob.js | 4 +- server/jobs/nodeInformationRetrievalJob.js | 4 +- server/jobs/scheduler.js | 22 ++++++-- server/logger.js | 30 +++++++++++ server/main.js | 6 ++- server/services/mailService.js | 30 +++++++---- server/services/monitoringService.js | 61 ++++++++++++++++++++-- 12 files changed, 171 insertions(+), 29 deletions(-) create mode 100644 server/logger.js diff --git a/config.json.example b/config.json.example index 9a87c81..38cdf48 100644 --- a/config.json.example +++ b/config.json.example @@ -6,6 +6,10 @@ "databaseFile": "/tmp/ffffng.sqlite", "peersPath": "/tmp/peers", + "logging": { + "directory": "/tmp/logs" + }, + "email": { "from": "Freifunk Knotenformular ", diff --git a/package.json b/package.json index f9f14ae..d28d365 100644 --- a/package.json +++ b/package.json @@ -45,6 +45,7 @@ "nodemailer": "~2.4.1", "nodemailer-html-to-text": "~2.1.0", "request": "~2.72.0", + "scribe-js": "~2.0.4", "serve-static": "~1.10.2", "sqlite3": "~3.1.4", "time-grunt": "~1.3.0" diff --git a/server/app.js b/server/app.js index cf4dd8d..c24e315 100644 --- a/server/app.js +++ b/server/app.js @@ -31,7 +31,7 @@ angular.module('ffffng').factory('app', function (fs, config, _) { }); } - app.use( function (req, res, next) { + app.use(function (req, res, next) { if (jsTemplateFiles.indexOf(req.path) >= 0) { return serveTemplate('application/javascript', req, res, next); } diff --git a/server/config.js b/server/config.js index b40b95f..4ca96b0 100644 --- a/server/config.js +++ b/server/config.js @@ -11,6 +11,10 @@ var defaultConfig = { databaseFile: '/tmp/ffffng.sqlite', peersPath: '/tmp/peers', + logging: { + directory: '/tmp/logs' + }, + email: { from: 'Freifunk Knotenformular ', diff --git a/server/db/database.js b/server/db/database.js index d24de34..b121ebd 100644 --- a/server/db/database.js +++ b/server/db/database.js @@ -6,8 +6,11 @@ var glob = require('glob'); var path = require('path'); var config = require('../config'); +var Logger = require('../logger'); function applyPatch(db, file, callback) { + Logger.tag('database', 'migration').info('Checking if patch need to be applied: ' + file); + fs.readFile(file, function (err, contents) { if (err) { return callback(err); @@ -22,6 +25,7 @@ function applyPatch(db, file, callback) { if (row) { // patch is already applied. skip! + Logger.tag('database', 'migration').info('Patch already applied, skipping: ' + file); return callback(null); } @@ -30,12 +34,22 @@ function applyPatch(db, file, callback) { + 'INSERT INTO schema_version (version) VALUES (\'' + version + '\');\n' + 'END TRANSACTION;'; - db.exec(sql, callback); + db.exec(sql, function (err) { + if (err) { + return callback(err); + } + + Logger.tag('database', 'migration').info('Patch successfully applied: ' + file); + + callback(null); + }); }); }); } function applyMigrations(db, callback) { + Logger.tag('database', 'migration').info('Migrating database...'); + var sql = 'BEGIN TRANSACTION; CREATE TABLE IF NOT EXISTS schema_version (\n' + ' version VARCHAR(255) PRIMARY KEY ASC,\n' + ' applied_at DATETIME DEFAULT CURRENT_TIMESTAMP NOT NULL\n' @@ -50,7 +64,7 @@ function applyMigrations(db, callback) { return callback(err); } - async.each( + async.eachSeries( files, function (file, fileCallback) { applyPatch(db, file, fileCallback); @@ -64,10 +78,22 @@ function applyMigrations(db, callback) { module.exports = { init: function (callback) { var SQLite3 = require('sqlite3'); - var db = new SQLite3.Database(config.server.databaseFile); + + var file = config.server.databaseFile; + Logger.tag('database').info('Setting up database: ' + file); + + var db; + try { + db = new SQLite3.Database(file); + } + catch (error) { + Logger.tag('database').error('Error initialzing database:', error); + throw error; + } applyMigrations(db, function (err) { if (err) { + Logger.tag('database').error('Error migrating database:', err); throw err; } diff --git a/server/jobs/mailQueueJob.js b/server/jobs/mailQueueJob.js index 2846ba0..77ab217 100644 --- a/server/jobs/mailQueueJob.js +++ b/server/jobs/mailQueueJob.js @@ -1,11 +1,11 @@ 'use strict'; -angular.module('ffffng').factory('MailQueueJob', function (MailService) { +angular.module('ffffng').factory('MailQueueJob', function (MailService, Logger) { return { run: function () { MailService.sendPendingMails(function (err) { if (err) { - console.error(err); + Logger.tag('mail', 'queue').error('Error sending pending mails:', err); } }); } diff --git a/server/jobs/nodeInformationRetrievalJob.js b/server/jobs/nodeInformationRetrievalJob.js index 1cbe9e9..52da5bb 100644 --- a/server/jobs/nodeInformationRetrievalJob.js +++ b/server/jobs/nodeInformationRetrievalJob.js @@ -1,11 +1,11 @@ 'use strict'; -angular.module('ffffng').factory('NodeInformationRetrievalJob', function (MonitoringService) { +angular.module('ffffng').factory('NodeInformationRetrievalJob', function (MonitoringService, Logger) { return { run: function () { MonitoringService.retrieveNodeInformation(function (err) { if (err) { - console.error(err); + Logger.tag('monitoring', 'information-retrieval').error('Error retrieving node data:', err); } }); } diff --git a/server/jobs/scheduler.js b/server/jobs/scheduler.js index 24da90c..d8a87ab 100644 --- a/server/jobs/scheduler.js +++ b/server/jobs/scheduler.js @@ -8,10 +8,12 @@ _.each(jobFiles, function (jobFile) { require(jobFile); }); -angular.module('ffffng').factory('Scheduler', function ($injector) { +angular.module('ffffng').factory('Scheduler', function ($injector, Logger) { var cron = require('node-cron'); function schedule(expr, jobName) { + Logger.tag('jobs').info('Scheduling job: ' + expr + ' ' + jobName); + var job = $injector.get(jobName); if (!_.isFunction(job.run)) { @@ -23,10 +25,20 @@ angular.module('ffffng').factory('Scheduler', function ($injector) { return { init: function () { - schedule('*/5 * * * * *', 'MailQueueJob'); - // schedule('0 */1 * * * *', 'NodeInformationRetrievalJob'); - schedule('*/10 * * * * *', 'NodeInformationRetrievalJob'); - // schedule('0 */1 * * * *', 'NodeInformationCleanupJob'); + Logger.tag('jobs').info('Scheduling background jobs...'); + + try { + schedule('0 */1 * * * *', 'MailQueueJob'); + // schedule('0 */5 * * * *', 'NodeInformationRetrievalJob'); + schedule('*/10 * * * * *', 'NodeInformationRetrievalJob'); + // schedule('0 */1 * * * *', 'NodeInformationCleanupJob'); + } + catch (error) { + Logger.tag('jobs').error('Error during scheduling of background jobs:', error); + throw error; + } + + Logger.tag('jobs').info('Scheduling of background jobs done.'); } }; }); diff --git a/server/logger.js b/server/logger.js new file mode 100644 index 0000000..2967399 --- /dev/null +++ b/server/logger.js @@ -0,0 +1,30 @@ +'use strict'; + +var config = require('./config'); + +var scribe = require('scribe-js')({ + app: 'ffffng', + id: process.pid, + + rootPath: config.server.logging.directory, + + module: { + 'router/Viewer': { + username: false, + password: false + } + } +}); + +process.console.addLogger('debug', 'grey', { + logInConsole: false +}); + +angular.module('ffffng').factory('Logger', function (app) { + app.use(scribe.express.logger()); + app.use('/internal/logs', scribe.webPanel()); + + return process.console; +}); + +module.exports = process.console; diff --git a/server/main.js b/server/main.js index ab51fce..aba2bf9 100644 --- a/server/main.js +++ b/server/main.js @@ -8,6 +8,8 @@ angular.module('ffffng', []); require('./config'); +require('./logger').tag('main', 'startup').info('Server starting up...'); + require('./app'); require('./router'); require('./libs'); @@ -32,7 +34,9 @@ require('./jobs/scheduler'); var db = require('./db/database'); db.init(function () { - angular.injector(['ffffng']).invoke(function (config, app, Scheduler, Router) { + angular.injector(['ffffng']).invoke(function (config, app, Logger, Scheduler, Router) { + Logger.tag('main').info('Initializing...'); + Scheduler.init(); Router.init(); diff --git a/server/services/mailService.js b/server/services/mailService.js index 4f7e488..2e7d1ae 100644 --- a/server/services/mailService.js +++ b/server/services/mailService.js @@ -1,7 +1,7 @@ 'use strict'; angular.module('ffffng') -.service('MailService', function (Database, UrlBuilder, config, _, async, deepExtend, fs, moment) { +.service('MailService', function (Database, UrlBuilder, config, _, async, deepExtend, fs, moment, Logger) { var MAIL_QUEUE_DB_BATCH_SIZE = 2; var MAIL_QUEUE_MAX_PARALLEL_SENDING = 3; @@ -20,6 +20,13 @@ angular.module('ffffng') })); function sendMail(options, callback) { + Logger + .tag('mail', 'queue') + .info( + 'Sending pending mail[' + options.id + '] of type ' + options.email + '. ' + + 'Had ' + options.failures + ' failures before.' + ); + var templateBasePath = __dirname + '/../mailTemplates/' + options.email; async.parallel({ subject: _.partial(fs.readFile, templateBasePath + '.subject.txt'), @@ -39,13 +46,8 @@ angular.module('ffffng') } ); - console.log(data); - function render(field) { - console.log(field); - var rendered = _.template(templates[field].toString())(data); - console.log(rendered); - return rendered; + return _.template(templates[field].toString())(data); } var mailOptions; @@ -58,6 +60,9 @@ angular.module('ffffng') }; } catch (error) { + Logger + .tag('mail', 'queue') + .error('Error rendering template for pending mail[' + options.id + ']:', error); return callback(error); } @@ -66,6 +71,8 @@ angular.module('ffffng') return callback(err); } + Logger.tag('mail', 'queue').info('Mail[' + options.id +'] has been send.'); + callback(null); }); } @@ -116,11 +123,10 @@ angular.module('ffffng') } function sendPendingMail(pendingMail, callback) { - console.log(pendingMail); sendMail(pendingMail, function (err) { if (err) { // we only log the error and increment the failure counter as we want to continue with pending mails - console.error(err); + Logger.tag('mail', 'queue').error('Error sending pending mail[' + pendingMail.id + ']:', err); return incrementFailureCounterForPendingEmail(pendingMail.id, function (err) { if (err) { @@ -151,7 +157,7 @@ angular.module('ffffng') }, sendPendingMails: function (callback) { - console.info('Start sending pending mails.'); + Logger.tag('mail', 'queue').info('Start sending pending mails...'); var startTime = moment(); @@ -160,13 +166,15 @@ angular.module('ffffng') return callback(err); } + Logger.tag('mail', 'queue').info('Sending next batch...'); + findPendingMailsBefore(startTime, MAIL_QUEUE_DB_BATCH_SIZE, function (err, pendingMails) { if (err) { return callback(err); } if (_.isEmpty(pendingMails)) { - console.info('Done sending pending mails.'); + Logger.tag('mail', 'queue').info('Done sending pending mails.'); return callback(null); } diff --git a/server/services/monitoringService.js b/server/services/monitoringService.js index 21c1dc1..c5ec448 100644 --- a/server/services/monitoringService.js +++ b/server/services/monitoringService.js @@ -7,6 +7,7 @@ angular.module('ffffng') config, Database, ErrorTypes, + Logger, moment, NodeService, request, @@ -17,6 +18,10 @@ angular.module('ffffng') var previousImportTimestamp = null; function insertNodeInformation(nodeData, node, callback) { + Logger + .tag('monitoring', 'information-retrieval') + .debug('Node is new in monitoring, creating data:', nodeData.mac); + return Database.run( 'INSERT INTO node_state ' + '(mac, state, last_seen, import_timestamp, last_status_mail_send) ' + @@ -33,11 +38,21 @@ angular.module('ffffng') } function updateNodeInformation(nodeData, node, row, callback) { - debugger; + Logger + .tag('monitoring', 'information-retrieval') + .debug('Node is known in monitoring:', nodeData.mac); + if (!moment(row.import_timestamp).isBefore(nodeData.importTimestamp)) { + Logger + .tag('monitoring', 'information-retrieval') + .debug('No new data for node, skipping:', nodeData.mac); return callback(); } + Logger + .tag('monitoring', 'information-retrieval') + .debug('New data for node, updating:', nodeData.mac); + return Database.run( 'UPDATE node_state ' + 'WHERE id = ? AND mac = ?' + @@ -51,6 +66,9 @@ angular.module('ffffng') } function deleteNodeInformation(nodeData, node, callback) { + Logger + .tag('monitoring', 'information-retrieval') + .debug('Node is not being monitored, deleting monitoring data:', nodeData.mac); return Database.run( 'DELETE FROM node_state WHERE mac = ? AND import_timestamp < ?', [node.mac, nodeData.importTimestamp.unix()], @@ -60,6 +78,8 @@ angular.module('ffffng') function storeNodeInformation(nodeData, node, callback) { if (node.monitoring && node.monitoringConfirmed) { + Logger.tag('monitoring', 'information-retrieval').debug('Node is being monitored:', nodeData.mac); + return Database.get('SELECT * FROM node_state WHERE mac = ?', [node.mac], function (err, row) { if (err) { return callback(err); @@ -79,6 +99,8 @@ angular.module('ffffng') var isValidMac = Validator.forConstraint(Constraints.node.mac); function parseNodesJson(body, callback) { + Logger.tag('monitoring', 'information-retrieval').info('Parsing nodes.json...'); + function parseTimestamp(timestamp) { if (!_.isString(json.timestamp)) { return moment.invalid(); @@ -212,8 +234,9 @@ angular.module('ffffng') }, retrieveNodeInformation: function (callback) { - console.info(); - request(config.server.map.nodesJsonUrl, function (err, response, body) { + var url = config.server.map.nodesJsonUrl; + Logger.tag('monitoring', 'information-retrieval').info('Retrieving nodes.json:', url); + request(url, function (err, response, body) { if (err) { return callback(err); } @@ -224,6 +247,15 @@ angular.module('ffffng') } if (previousImportTimestamp !== null && !data.importTimestamp.isAfter(previousImportTimestamp)) { + Logger + .tag('monitoring', 'information-retrieval') + .info( + 'No new data, skipping.', + 'Current timestamp:', + data.importTimestamp.format(), + 'Previous timestamp:', + previousImportTimestamp.format() + ); return callback(); } previousImportTimestamp = data.importTimestamp; @@ -231,16 +263,37 @@ angular.module('ffffng') async.each( data.nodes, function (nodeData, nodeCallback) { + Logger.tag('monitoring', 'information-retrieval').debug('Importing:', nodeData.mac); + NodeService.findNodeDataByMac(nodeData.mac, function (err, node) { if (err) { + Logger + .tag('monitoring', 'information-retrieval') + .error('Error importing:', nodeData.mac, err); return nodeCallback(err); } if (!node) { + Logger + .tag('monitoring', 'information-retrieval') + .debug('Unknown node, skipping:', nodeData.mac); return nodeCallback(null); } - storeNodeInformation(nodeData, node, nodeCallback); + storeNodeInformation(nodeData, node, function (err) { + if (err) { + Logger + .tag('monitoring', 'information-retrieval') + .debug('Could not update / deleting node data:', nodeData.mac, err); + return nodeCallback(err); + } + + Logger + .tag('monitoring', 'information-retrieval') + .debug('Updating / deleting node data done:', nodeData.mac); + + nodeCallback(); + }); }); }, callback