freifunk/ffffng
0
0
Fork 0
Code Issues Pull requests Packages Projects Releases Wiki Activity

Added logging framework.

Browse source
This commit is contained in:
baldo 2016-05-24 16:40:57 +02:00
parent ad3f075d93
commit a82b66c637
12 changed files with 171 additions and 29 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

4
config.json.example
View file

@ -6,6 +6,10 @@
"databaseFile": "/tmp/ffffng.sqlite", "databaseFile": "/tmp/ffffng.sqlite",
"peersPath": "/tmp/peers", "peersPath": "/tmp/peers",
"logging": {
"directory": "/tmp/logs"
},
"email": { "email": {
"from": "Freifunk Knotenformular <no-reply@musterstadt.freifunk.net>", "from": "Freifunk Knotenformular <no-reply@musterstadt.freifunk.net>",

1
package.json
View file

@ -45,6 +45,7 @@
"nodemailer": "~2.4.1", "nodemailer": "~2.4.1",
"nodemailer-html-to-text": "~2.1.0", "nodemailer-html-to-text": "~2.1.0",
"request": "~2.72.0", "request": "~2.72.0",
"scribe-js": "~2.0.4",
"serve-static": "~1.10.2", "serve-static": "~1.10.2",
"sqlite3": "~3.1.4", "sqlite3": "~3.1.4",
"time-grunt": "~1.3.0" "time-grunt": "~1.3.0"

2
server/app.js
View file

@ -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) { if (jsTemplateFiles.indexOf(req.path) >= 0) {
return serveTemplate('application/javascript', req, res, next); return serveTemplate('application/javascript', req, res, next);
} }

4
server/config.js
View file

@ -11,6 +11,10 @@ var defaultConfig = {
databaseFile: '/tmp/ffffng.sqlite', databaseFile: '/tmp/ffffng.sqlite',
peersPath: '/tmp/peers', peersPath: '/tmp/peers',
logging: {
directory: '/tmp/logs'
},
email: { email: {
from: 'Freifunk Knotenformular <no-reply@musterstadt.freifunk.net>', from: 'Freifunk Knotenformular <no-reply@musterstadt.freifunk.net>',

32
server/db/database.js
View file

@ -6,8 +6,11 @@ var glob = require('glob');
var path = require('path'); var path = require('path');
var config = require('../config'); var config = require('../config');
var Logger = require('../logger');
function applyPatch(db, file, callback) { function applyPatch(db, file, callback) {
Logger.tag('database', 'migration').info('Checking if patch need to be applied: ' + file);
fs.readFile(file, function (err, contents) { fs.readFile(file, function (err, contents) {
if (err) { if (err) {
return callback(err); return callback(err);
@ -22,6 +25,7 @@ function applyPatch(db, file, callback) {
if (row) { if (row) {
// patch is already applied. skip! // patch is already applied. skip!
Logger.tag('database', 'migration').info('Patch already applied, skipping: ' + file);
return callback(null); return callback(null);
} }
@ -30,12 +34,22 @@ function applyPatch(db, file, callback) {
+ 'INSERT INTO schema_version (version) VALUES (\'' + version + '\');\n' + 'INSERT INTO schema_version (version) VALUES (\'' + version + '\');\n'
+ 'END TRANSACTION;'; + '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) { function applyMigrations(db, callback) {
Logger.tag('database', 'migration').info('Migrating database...');
var sql = 'BEGIN TRANSACTION; CREATE TABLE IF NOT EXISTS schema_version (\n' var sql = 'BEGIN TRANSACTION; CREATE TABLE IF NOT EXISTS schema_version (\n'
+ ' version VARCHAR(255) PRIMARY KEY ASC,\n' + ' version VARCHAR(255) PRIMARY KEY ASC,\n'
+ ' applied_at DATETIME DEFAULT CURRENT_TIMESTAMP NOT NULL\n' + ' applied_at DATETIME DEFAULT CURRENT_TIMESTAMP NOT NULL\n'
@ -50,7 +64,7 @@ function applyMigrations(db, callback) {
return callback(err); return callback(err);
} }
async.each( async.eachSeries(
files, files,
function (file, fileCallback) { function (file, fileCallback) {
applyPatch(db, file, fileCallback); applyPatch(db, file, fileCallback);
@ -64,10 +78,22 @@ function applyMigrations(db, callback) {
module.exports = { module.exports = {
init: function (callback) { init: function (callback) {
var SQLite3 = require('sqlite3'); 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) { applyMigrations(db, function (err) {
if (err) { if (err) {
Logger.tag('database').error('Error migrating database:', err);
throw err; throw err;
} }

4
server/jobs/mailQueueJob.js
View file

@ -1,11 +1,11 @@
'use strict'; 'use strict';
angular.module('ffffng').factory('MailQueueJob', function (MailService) { angular.module('ffffng').factory('MailQueueJob', function (MailService, Logger) {
return { return {
run: function () { run: function () {
MailService.sendPendingMails(function (err) { MailService.sendPendingMails(function (err) {
if (err) { if (err) {
console.error(err); Logger.tag('mail', 'queue').error('Error sending pending mails:', err);
} }
}); });
} }

4
server/jobs/nodeInformationRetrievalJob.js
View file

@ -1,11 +1,11 @@
'use strict'; 'use strict';
angular.module('ffffng').factory('NodeInformationRetrievalJob', function (MonitoringService) { angular.module('ffffng').factory('NodeInformationRetrievalJob', function (MonitoringService, Logger) {
return { return {
run: function () { run: function () {
MonitoringService.retrieveNodeInformation(function (err) { MonitoringService.retrieveNodeInformation(function (err) {
if (err) { if (err) {
console.error(err); Logger.tag('monitoring', 'information-retrieval').error('Error retrieving node data:', err);
} }
}); });
} }

22
server/jobs/scheduler.js
View file

@ -8,10 +8,12 @@ _.each(jobFiles, function (jobFile) {
require(jobFile); require(jobFile);
}); });
angular.module('ffffng').factory('Scheduler', function ($injector) { angular.module('ffffng').factory('Scheduler', function ($injector, Logger) {
var cron = require('node-cron'); var cron = require('node-cron');
function schedule(expr, jobName) { function schedule(expr, jobName) {
Logger.tag('jobs').info('Scheduling job: ' + expr + ' ' + jobName);
var job = $injector.get(jobName); var job = $injector.get(jobName);
if (!_.isFunction(job.run)) { if (!_.isFunction(job.run)) {
@ -23,10 +25,20 @@ angular.module('ffffng').factory('Scheduler', function ($injector) {
return { return {
init: function () { init: function () {
schedule('*/5 * * * * *', 'MailQueueJob'); Logger.tag('jobs').info('Scheduling background jobs...');
// schedule('0 */1 * * * *', 'NodeInformationRetrievalJob');
schedule('*/10 * * * * *', 'NodeInformationRetrievalJob'); try {
// schedule('0 */1 * * * *', 'NodeInformationCleanupJob'); 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.');
} }
}; };
}); });

30
server/logger.js Normal file
View file

@ -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;

6
server/main.js
View file

@ -8,6 +8,8 @@ angular.module('ffffng', []);
require('./config'); require('./config');
require('./logger').tag('main', 'startup').info('Server starting up...');
require('./app'); require('./app');
require('./router'); require('./router');
require('./libs'); require('./libs');
@ -32,7 +34,9 @@ require('./jobs/scheduler');
var db = require('./db/database'); var db = require('./db/database');
db.init(function () { 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(); Scheduler.init();
Router.init(); Router.init();

30
server/services/mailService.js
View file

@ -1,7 +1,7 @@
'use strict'; 'use strict';
angular.module('ffffng') 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_DB_BATCH_SIZE = 2;
var MAIL_QUEUE_MAX_PARALLEL_SENDING = 3; var MAIL_QUEUE_MAX_PARALLEL_SENDING = 3;
@ -20,6 +20,13 @@ angular.module('ffffng')
})); }));
function sendMail(options, callback) { 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; var templateBasePath = __dirname + '/../mailTemplates/' + options.email;
async.parallel({ async.parallel({
subject: _.partial(fs.readFile, templateBasePath + '.subject.txt'), subject: _.partial(fs.readFile, templateBasePath + '.subject.txt'),
@ -39,13 +46,8 @@ angular.module('ffffng')
} }
); );
console.log(data);
function render(field) { function render(field) {
console.log(field); return _.template(templates[field].toString())(data);
var rendered = _.template(templates[field].toString())(data);
console.log(rendered);
return rendered;
} }
var mailOptions; var mailOptions;
@ -58,6 +60,9 @@ angular.module('ffffng')
}; };
} }
catch (error) { catch (error) {
Logger
.tag('mail', 'queue')
.error('Error rendering template for pending mail[' + options.id + ']:', error);
return callback(error); return callback(error);
} }
@ -66,6 +71,8 @@ angular.module('ffffng')
return callback(err); return callback(err);
} }
Logger.tag('mail', 'queue').info('Mail[' + options.id +'] has been send.');
callback(null); callback(null);
}); });
} }
@ -116,11 +123,10 @@ angular.module('ffffng')
} }
function sendPendingMail(pendingMail, callback) { function sendPendingMail(pendingMail, callback) {
console.log(pendingMail);
sendMail(pendingMail, function (err) { sendMail(pendingMail, function (err) {
if (err) { if (err) {
// we only log the error and increment the failure counter as we want to continue with pending mails // 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) { return incrementFailureCounterForPendingEmail(pendingMail.id, function (err) {
if (err) { if (err) {
@ -151,7 +157,7 @@ angular.module('ffffng')
}, },
sendPendingMails: function (callback) { sendPendingMails: function (callback) {
console.info('Start sending pending mails.'); Logger.tag('mail', 'queue').info('Start sending pending mails...');
var startTime = moment(); var startTime = moment();
@ -160,13 +166,15 @@ angular.module('ffffng')
return callback(err); return callback(err);
} }
Logger.tag('mail', 'queue').info('Sending next batch...');
findPendingMailsBefore(startTime, MAIL_QUEUE_DB_BATCH_SIZE, function (err, pendingMails) { findPendingMailsBefore(startTime, MAIL_QUEUE_DB_BATCH_SIZE, function (err, pendingMails) {
if (err) { if (err) {
return callback(err); return callback(err);
} }
if (_.isEmpty(pendingMails)) { if (_.isEmpty(pendingMails)) {
console.info('Done sending pending mails.'); Logger.tag('mail', 'queue').info('Done sending pending mails.');
return callback(null); return callback(null);
} }

61
server/services/monitoringService.js
View file

@ -7,6 +7,7 @@ angular.module('ffffng')
config, config,
Database, Database,
ErrorTypes, ErrorTypes,
Logger,
moment, moment,
NodeService, NodeService,
request, request,
@ -17,6 +18,10 @@ angular.module('ffffng')
var previousImportTimestamp = null; var previousImportTimestamp = null;
function insertNodeInformation(nodeData, node, callback) { function insertNodeInformation(nodeData, node, callback) {
Logger
.tag('monitoring', 'information-retrieval')
.debug('Node is new in monitoring, creating data:', nodeData.mac);
return Database.run( return Database.run(
'INSERT INTO node_state ' + 'INSERT INTO node_state ' +
'(mac, state, last_seen, import_timestamp, last_status_mail_send) ' + '(mac, state, last_seen, import_timestamp, last_status_mail_send) ' +
@ -33,11 +38,21 @@ angular.module('ffffng')
} }
function updateNodeInformation(nodeData, node, row, callback) { 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)) { if (!moment(row.import_timestamp).isBefore(nodeData.importTimestamp)) {
Logger
.tag('monitoring', 'information-retrieval')
.debug('No new data for node, skipping:', nodeData.mac);
return callback(); return callback();
} }
Logger
.tag('monitoring', 'information-retrieval')
.debug('New data for node, updating:', nodeData.mac);
return Database.run( return Database.run(
'UPDATE node_state ' + 'UPDATE node_state ' +
'WHERE id = ? AND mac = ?' + 'WHERE id = ? AND mac = ?' +
@ -51,6 +66,9 @@ angular.module('ffffng')
} }
function deleteNodeInformation(nodeData, node, callback) { function deleteNodeInformation(nodeData, node, callback) {
Logger
.tag('monitoring', 'information-retrieval')
.debug('Node is not being monitored, deleting monitoring data:', nodeData.mac);
return Database.run( return Database.run(
'DELETE FROM node_state WHERE mac = ? AND import_timestamp < ?', 'DELETE FROM node_state WHERE mac = ? AND import_timestamp < ?',
[node.mac, nodeData.importTimestamp.unix()], [node.mac, nodeData.importTimestamp.unix()],
@ -60,6 +78,8 @@ angular.module('ffffng')
function storeNodeInformation(nodeData, node, callback) { function storeNodeInformation(nodeData, node, callback) {
if (node.monitoring && node.monitoringConfirmed) { 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) { return Database.get('SELECT * FROM node_state WHERE mac = ?', [node.mac], function (err, row) {
if (err) { if (err) {
return callback(err); return callback(err);
@ -79,6 +99,8 @@ angular.module('ffffng')
var isValidMac = Validator.forConstraint(Constraints.node.mac); var isValidMac = Validator.forConstraint(Constraints.node.mac);
function parseNodesJson(body, callback) { function parseNodesJson(body, callback) {
Logger.tag('monitoring', 'information-retrieval').info('Parsing nodes.json...');
function parseTimestamp(timestamp) { function parseTimestamp(timestamp) {
if (!_.isString(json.timestamp)) { if (!_.isString(json.timestamp)) {
return moment.invalid(); return moment.invalid();
@ -212,8 +234,9 @@ angular.module('ffffng')
}, },
retrieveNodeInformation: function (callback) { retrieveNodeInformation: function (callback) {
console.info(); var url = config.server.map.nodesJsonUrl;
request(config.server.map.nodesJsonUrl, function (err, response, body) { Logger.tag('monitoring', 'information-retrieval').info('Retrieving nodes.json:', url);
request(url, function (err, response, body) {
if (err) { if (err) {
return callback(err); return callback(err);
} }
@ -224,6 +247,15 @@ angular.module('ffffng')
} }
if (previousImportTimestamp !== null && !data.importTimestamp.isAfter(previousImportTimestamp)) { 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(); return callback();
} }
previousImportTimestamp = data.importTimestamp; previousImportTimestamp = data.importTimestamp;
@ -231,16 +263,37 @@ angular.module('ffffng')
async.each( async.each(
data.nodes, data.nodes,
function (nodeData, nodeCallback) { function (nodeData, nodeCallback) {
Logger.tag('monitoring', 'information-retrieval').debug('Importing:', nodeData.mac);
NodeService.findNodeDataByMac(nodeData.mac, function (err, node) { NodeService.findNodeDataByMac(nodeData.mac, function (err, node) {
if (err) { if (err) {
Logger
.tag('monitoring', 'information-retrieval')
.error('Error importing:', nodeData.mac, err);
return nodeCallback(err); return nodeCallback(err);
} }
if (!node) { if (!node) {
Logger
.tag('monitoring', 'information-retrieval')
.debug('Unknown node, skipping:', nodeData.mac);
return nodeCallback(null); 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 callback