new logging api

lib/log.js

@@ -0,0 +1,99 @@
+/*jshint esversion: 6 */
+var Store = require("../storage/file");
+
+var Logger = module.exports;
+
+/* Every line in the log should contain:
+    * timestamp
+    * public key of initiator
+    * the action
+    * the event's tag
+*/
+var messageTemplate = function (type, time, tag, info) {
+    return JSON.stringify([type.toUpperCase(), time, tag, info]);
+};
+
+var write = function (ctx, content) {
+    ctx.store.log(ctx.channelName, content);
+};
+
+// various degrees of logging
+const logLevels = ['silly', 'debug', 'verbose', 'feedback', 'info', 'warn', 'error'];
+
+var handlers = {
+    silly: function (ctx, time, tag, info) {
+        console.log('[SILLY]', time, tag, info);
+    },
+    debug: function (ctx, time, tag, info) {
+        console.log('[DEBUG]', time, tag, info);
+    },
+    verbose: function (ctx, time, tag, info) {
+        console.log('[VERBOSE]', time, tag, info);
+    },
+    feedback: function (ctx, time, tag, info) {
+        console.log('[FEEDBACK]', time, tag, info);
+    },
+    info: function (ctx, time, tag, info) {
+        console.info('[INFO]', time, tag, info);
+    },
+    warn: function (ctx, time, tag, info) {
+        console.warn('[WARN]', time, tag, info);
+    },
+    error: function (ctx, time, tag, info) {
+        console.error('[ERROR]', time, tag, info);
+    }
+};
+
+var createLogType = function (ctx, type) {
+    return function (tag, info) {
+        var time = new Date().toISOString();
+        var content;
+        try {
+            content = messageTemplate(type, time, tag, info);
+        } catch (e) {
+            return;
+        }
+
+        if (ctx.logToStdout && typeof(handlers[type]) === 'function') {
+            handlers[type](ctx, time, tag, info);
+        }
+        write(ctx, content);
+    };
+};
+
+// Log.verbose('THING', x);
+Logger.create = function (config, cb) {
+    if (!config.logPath) {
+        // XXX don't crash, print that you won't log to file
+        throw new Error("Logger: Expected filePath");
+    }
+
+    /* config: {
+        filePath: '???',
+        logLevel: 'silly',
+    } */
+
+    var date = new Date();
+    var launchTime = ('' + date.getUTCFullYear()).slice(-2) + date.toISOString();
+
+    Store.create({
+        filePath: config.logPath,
+    }, function (store) {
+        var ctx = {
+            store: store,
+            channelName: launchTime,
+            logFeedback: Boolean(config.logFeedback),
+    // TODO respect configured log settings
+            logLevel: logLevels.indexOf(config.logLevel), // 0 for silly, 1 for debug
+        };
+
+        var log = {};
+        logLevels.forEach(function (type) {
+            log[type] = createLogType(ctx, type);
+        });
+
+        cb(Object.freeze(log));
+    });
+};
+
+

rpc.js

@@ -27,6 +27,8 @@ var DEFAULT_LIMIT = 50 * 1024 * 1024;
 var SESSION_EXPIRATION_TIME = 60 * 1000;
 var SUPPRESS_RPC_ERRORS = false;
 
+var Log;
+
 var WARN = function (e, output) {
     if (!SUPPRESS_RPC_ERRORS && e && output) {
         console.error(new Date().toISOString() + ' [' + String(e) + ']', output);
@@ -199,8 +201,7 @@ var checkSignature = function (signedMsg, signature, publicKey) {
     try {
         signedBuffer = Nacl.util.decodeUTF8(signedMsg);
     } catch (e) {
-        console.log('invalid signedBuffer'); // FIXME logging
+        Log.error('INVALID_SIGNED_BUFFER', signedMsg);
-        console.log(signedMsg);
         return null;
     }
 
@@ -217,8 +218,7 @@ var checkSignature = function (signedMsg, signature, publicKey) {
     }
 
     if (pubBuffer.length !== 32) {
-        console.log('public key length: ' + pubBuffer.length); // FIXME logging
+        Log.error('PUBLIC_KEY_LENGTH', publicKey);
-        console.log(publicKey);
         return false;
     }
 
@@ -269,10 +269,10 @@ var loadUserPins = function (Env, publicKey, cb) {
                     }
                     break;
                 default:
-                    WARN('invalid message read from store', msg); // FIXME logging
+                    Log.warn('INVALID_STORED_MESSAGE', msg);
             }
         } catch (e) {
-            WARN('invalid message read from store', e); // FIXME logging
+            Log.warn('STORED_PARSE_ERROR', e);
         }
     }, function () {
         // no more messages
@@ -969,8 +969,11 @@ var upload_cancel = function (Env, publicKey, fileSize, cb) {
 
     var path = makeFilePath(paths.staging, publicKey);
     if (!path) {
-        console.log(paths.staging, publicKey); // FIXME logging
+        Log.error('UPLOAD_CANCEL_INVALID_PATH', {
-        console.log(path);
+            staging: paths.staging,
+            key: publicKey,
+            path: path,
+        });
         return void cb('NO_FILE');
     }
 
@@ -1313,7 +1316,7 @@ var validateLoginBlock = function (Env, publicKey, signature, block, cb) {
     try {
         u8_signature = Nacl.util.decodeBase64(signature);
     } catch (e) {
-        console.error(e); // FIXME logging
+        Log.error('INVALID_BLOCK_SIGNATURE', e);
         return void cb('E_INVALID_SIGNATURE');
     }
 
@@ -1414,7 +1417,6 @@ var removeLoginBlock = function (Env, msg, cb) {
     var block = Nacl.util.decodeUTF8('DELETE_BLOCK'); // clients and the server will have to agree on this constant
 
     // FIXME deletion
-    // FIXME logging
     validateLoginBlock(Env, publicKey, signature, block, function (e /*::, validatedBlock */) {
         if (e) { return void cb(e); }
         // derive the filepath
@@ -1524,16 +1526,7 @@ var getActiveSessions = function (Env, ctx, cb) {
 };
 
 var adminCommand = function (Env, ctx, publicKey, config, data, cb) {
-    var admins = [];
+    var admins = Env.admins;
-    try {
-        admins = (config.adminKeys || []).map(function (k) {
-            k = k.replace(/\/+$/, '');
-            var s = k.split('/');
-            return s[s.length-1];
-        });
-    } catch (e) {
-        console.error("Can't parse admin keys. Please update or fix your config.js file!"); // FIXME logging
-    }
     if (admins.indexOf(publicKey) === -1) {
         return void cb("FORBIDDEN");
     }
@@ -1631,8 +1624,10 @@ RPC.create = function (
     debuggable /*:<T>(string, T)=>T*/,
     cb /*:(?Error, ?Function)=>void*/
 ) {
+    Log = config.log;
+
     // load pin-store...
-    console.log('loading rpc module...'); // FIXME logging
+    Log.silly('LOADING RPC MODULE');
 
     if (config.suppressRPCErrors) { SUPPRESS_RPC_ERRORS = true; }
 
@@ -1649,8 +1644,20 @@ RPC.create = function (
         pinStore: (undefined /*:any*/),
         pinnedPads: {},
         evPinnedPadsReady: mkEvent(true),
-        limits: {}
+        limits: {},
+        admins: [],
     };
+
+    try {
+        Env.admins = (config.adminKeys || []).map(function (k) {
+            k = k.replace(/\/+$/, '');
+            var s = k.split('/');
+            return s[s.length-1];
+        });
+    } catch (e) {
+        console.error("Can't parse admin keys. Please update or fix your config.js file!");
+    }
+
     debuggable('rpc_env', Env);
 
     var Sessions = Env.Sessions;
@@ -1718,7 +1725,7 @@ RPC.create = function (
                     respond(e, [null, isNew, null]);
                 });
             default:
-                console.error("unsupported!"); // FIXME logging
+                Log.warn("UNSUPPORTED_RPC_CALL", msg);
                 return respond('UNSUPPORTED_RPC_CALL', msg);
         }
     };
@@ -1727,13 +1734,14 @@ RPC.create = function (
         if (!Env.msgStore) { Env.msgStore = ctx.store; }
 
         if (!Array.isArray(data)) {
-            return void respond('INVALID_ARG_FORMAT'); // FIXME logging
+            Log.debug('INVALID_ARG_FORMET', data);
+            return void respond('INVALID_ARG_FORMAT');
         }
 
         if (!data.length) {
             return void respond("INSUFFICIENT_ARGS");
         } else if (data.length !== 1) {
-            console.log('[UNEXPECTED_ARGUMENTS_LENGTH] %s', data.length); // FIXME logging
+            Log.debug('UNEXPECTED_ARGUMENTS_LENGTH', data);
         }
 
         var msg = data[0].slice(0);
@@ -1753,7 +1761,7 @@ RPC.create = function (
         if (publicKey) {
             getSession(Sessions, publicKey);
         } else {
-            console.log("No public key"); // FIXME logging
+            Log.debug("NO_PUBLIC_KEY_PROVIDED", publicKey);
         }
 
         var cookie = msg[0];
@@ -1775,7 +1783,7 @@ RPC.create = function (
                 return void respond("INVALID_SIGNATURE_OR_PUBLIC_KEY");
             }
         } else if (msg[1] !== 'UPLOAD') {
-            console.error("INVALID_RPC CALL:", msg[1]); // FIXME logging
+            Log.warn('INVALID_RPC_CALL', msg[1]);
             return void respond("INVALID_RPC_CALL");
         }
 
@@ -1804,7 +1812,7 @@ RPC.create = function (
         }
 
         var handleMessage = function () {
-            if (config.logRPC) { console.log(msg[0]); }
+            Log.silly('LOG_RPC', msg[0]);
         switch (msg[0]) {
             case 'COOKIE': return void Respond(void 0);
             case 'RESET':

server.js

@@ -104,7 +104,7 @@ if (!config.logFeedback) { return; }
 
 const logFeedback = function (url) {
     url.replace(/\?(.*?)=/, function (all, fb) {
-        console.log('[FEEDBACK] %s', fb);
+        config.log.feedback(fb, '');
     });
 };
 
@@ -254,6 +254,13 @@ var historyKeeper;
 
 // Initialize tasks, then rpc, then store, then history keeper and then start the server
 var nt = nThen(function (w) {
+    // set up logger
+    var Logger = require("./lib/log");
+    console.log("Loading logging module");
+    Logger.create(config, w(function (_log) {
+        config.log = _log;
+    }));
+}).nThen(function (w) {
     var Tasks = require("./storage/tasks");
     console.log("loading task scheduler");
     Tasks.create(config, w(function (e, tasks) {

storage/file.js

@@ -468,6 +468,9 @@ module.exports.create = function (
                 if (!isValidChannelId(channelName)) { return void cb(new Error('EINVAL')); }
                 clearChannel(env, channelName, cb);
             },
+            log: function (channelName, content, cb) {
+                message(env, channelName, content, cb);
+            },
             shutdown: function () {
                 clearInterval(it);
             }