Add logging functionality

Add logging on every API call, and on server starting and listenning.

config.json

@@ -282,5 +282,9 @@
         "type": "device-actions"
       }
     ]
+  },
+  "logger": {
+    "logFormat": "simple",
+    "accessLogFormat": "simple"
   }
 }

server/api.js

@@ -6,9 +6,15 @@ const config = require("./config");
 const db = require("./db");
 const apiFunctions = require("./api-functions");
 const expression = require("../common/expression");
+const logger = require("./logger");
 
 const router = new Router();
 
+function logUnauthorizedWarning(log) {
+  log.message += " not authorized";
+  logger.accessWarn(log);
+}
+
 const RESOURCE_DELETE = 1 << 0;
 
 const RESOURCE_IDS = {
@@ -37,7 +43,16 @@ for (let [resource, flags] of Object.entries(resources)) {
     if (ctx.request.query.filter)
       filter = expression.parse(ctx.request.query.filter);
 
-    if (!ctx.state.authorizer.hasAccess(resource, 1)) return next();
+    const log = {
+      message: `Count ${resource}`,
+      context: ctx,
+      filter: ctx.request.query.filter
+    };
+
+    if (!ctx.state.authorizer.hasAccess(resource, 1)) {
+      logUnauthorizedWarning(log);
+      return next();
+    }
 
     // Exclude temporary tasks and faults
     if (resource === "tasks" || resource === "faults")
@@ -50,6 +65,9 @@ for (let [resource, flags] of Object.entries(resources)) {
 
     ctx.set("X-Total-Count", count);
     ctx.body = "";
+
+    log.count = count;
+    logger.accessInfo(log);
   });
 
   router.get(`/${resource}`, async (ctx, next) => {
@@ -66,7 +84,20 @@ for (let [resource, flags] of Object.entries(resources)) {
         .split(",")
         .reduce((obj, k) => Object.assign(obj, { [k]: 1 }), {});
 
-    if (!ctx.state.authorizer.hasAccess(resource, 2)) return next();
+    const log = {
+      message: `Query ${resource}`,
+      context: ctx,
+      filter: ctx.request.query.filter,
+      limit: options.limit,
+      skip: options.skip,
+      sort: options.sort,
+      projection: options.projection
+    };
+
+    if (!ctx.state.authorizer.hasAccess(resource, 2)) {
+      logUnauthorizedWarning(log);
+      return next();
+    }
 
     // Exclude temporary tasks and faults
     if (resource === "tasks" || resource === "faults")
@@ -101,6 +132,8 @@ for (let [resource, flags] of Object.entries(resources)) {
       stream.write((c++ ? "," : "") + JSON.stringify(obj) + "\n");
     });
     stream.end("]");
+
+    logger.accessInfo(log);
   });
 
   // CSV download
@@ -114,7 +147,20 @@ for (let [resource, flags] of Object.entries(resources)) {
     if (ctx.request.query.sort)
       options.sort = JSON.parse(ctx.request.query.sort);
 
-    if (!ctx.state.authorizer.hasAccess(resource, 2)) return next();
+    const log = {
+      message: `Query ${resource} (CSV)`,
+      context: ctx,
+      filter: ctx.request.query.filter,
+      limit: options.limit,
+      skip: options.skip,
+      sort: options.sort,
+      projection: options.projection
+    };
+
+    if (!ctx.state.authorizer.hasAccess(resource, 2)) {
+      logUnauthorizedWarning(log);
+      return next();
+    }
 
     const columns = JSON.parse(ctx.request.query.columns);
     const now = Date.now();
@@ -188,72 +234,144 @@ for (let [resource, flags] of Object.entries(resources)) {
       stream.write(arr.join(",") + "\n");
     });
     stream.end();
+
+    logger.accessInfo(log);
   });
 
   router.head(`/${resource}/:id`, async (ctx, next) => {
+    const log = {
+      message: `Count ${resource}`,
+      context: ctx,
+      filter: `${RESOURCE_IDS[resource]} = "${ctx.params.id}"`
+    };
+
     let filter = ["=", ["PARAM", RESOURCE_IDS[resource]], ctx.params.id];
-    if (!ctx.state.authorizer.hasAccess(resource, 2)) return next();
+    if (!ctx.state.authorizer.hasAccess(resource, 2)) {
+      logUnauthorizedWarning(log);
+      return next();
+    }
 
     let res = await db.query(resource, filter);
 
     if (!res.length) return next();
+
+    logger.accessInfo(log);
     ctx.body = "";
   });
 
   router.get(`/${resource}/:id`, async (ctx, next) => {
+    const log = {
+      message: `Query ${resource}`,
+      context: ctx,
+      filter: `${RESOURCE_IDS[resource]} = "${ctx.params.id}"`
+    };
+
     let filter = ["=", ["PARAM", RESOURCE_IDS[resource]], ctx.params.id];
-    if (!ctx.state.authorizer.hasAccess(resource, 2)) return next();
+    if (!ctx.state.authorizer.hasAccess(resource, 2)) {
+      logUnauthorizedWarning(log);
+      return next();
+    }
 
     let res = await db.query(resource, filter);
 
     if (!res.length) return next();
+
+    logger.accessInfo(log);
     ctx.body = res[0];
   });
 
   // TODO add PUT, PATCH routes
   if (flags & RESOURCE_DELETE)
     router.delete(`/${resource}/:id`, async (ctx, next) => {
+      const log = {
+        message: `Delete ${resource}`,
+        context: ctx,
+        id: ctx.params.id
+      };
+
       const authorizer = ctx.state.authorizer;
       let filter = ["=", ["PARAM", RESOURCE_IDS[resource]], ctx.params.id];
-      if (!authorizer.hasAccess(resource, 2)) return next();
+      if (!authorizer.hasAccess(resource, 2)) {
+        logUnauthorizedWarning(log);
+        return next();
+      }
       let res = await db.query(resource, filter);
       if (!res.length) return next();
 
       const validate = authorizer.getValidator(resource, res[0]);
-      if (!validate("delete")) return (ctx.status = 403);
+      if (!validate("delete")) {
+        logUnauthorizedWarning(log);
+        return (ctx.status = 403);
+      }
 
       await apiFunctions.deleteResource(resource, ctx.params.id);
+
+      logger.accessInfo(log);
+
       ctx.body = "";
     });
 }
 
 router.post("/devices/:id/tasks", async (ctx, next) => {
+  const log = {
+    message: "Commit tasks",
+    context: ctx,
+    deviceId: ctx.params.id
+  };
+
   const authorizer = ctx.state.authorizer;
   let filter = ["=", ["PARAM", "DeviceID.ID"], ctx.params.id];
-  if (!authorizer.hasAccess("devices", 2)) return next();
+  if (!authorizer.hasAccess("devices", 2)) {
+    logUnauthorizedWarning(log);
+    return next();
+  }
   let devices = await db.query("devices", filter);
   if (!devices.length) return next();
 
   const validate = authorizer.getValidator("devices", devices[0]);
   for (let t of ctx.request.body)
-    if (!validate("task", t)) return (ctx.status = 403);
+    if (!validate("task", t)) {
+      logUnauthorizedWarning(log);
+      return (ctx.status = 403);
+    }
 
   let res = await apiFunctions.postTasks(ctx.params.id, ctx.request.body);
+
+  log.tasks = res.tasks.map(t => t._id).join(",");
+
+  logger.accessInfo(log);
+
   ctx.set("Connection-Request", res.connectionRequest);
   ctx.body = res.tasks;
 });
 
 router.post("/devices/:id/tags", async (ctx, next) => {
+  const log = {
+    message: "Update tags",
+    context: ctx,
+    deviceId: ctx.params.id,
+    tags: ctx.request.body
+  };
+
   const authorizer = ctx.state.authorizer;
   let filter = ["=", ["PARAM", "DeviceID.ID"], ctx.params.id];
-  if (!authorizer.hasAccess("devices", 2)) return next();
+  if (!authorizer.hasAccess("devices", 2)) {
+    logUnauthorizedWarning(log);
+    return next();
+  }
   let res = await db.query("devices", filter);
   if (!res.length) return next();
 
   const validate = authorizer.getValidator("devices", res[0]);
-  if (!validate("tags", ctx.request.body)) return (ctx.status = 403);
+  if (!validate("tags", ctx.request.body)) {
+    logUnauthorizedWarning(log);
+    return (ctx.status = 403);
+  }
 
   await apiFunctions.updateTags(ctx.params.id, ctx.request.body);
+
+  logger.accessInfo(log);
+
   ctx.body = "";
 });
 

server/logger.js

@@ -0,0 +1,248 @@
+"use strict";
+
+const fs = require("fs");
+const os = require("os");
+
+const config = require("../config");
+
+const REOPEN_EVERY = 60000;
+
+const LOG_FORMAT = config.logger.logFormat;
+const ACCESS_LOG_FORMAT = config.logger.accessLogFormat || LOG_FORMAT;
+
+const defaultMeta = {};
+
+let LOG_SYSTEMD = false;
+let ACCESS_LOG_SYSTEMD = false;
+
+let LOG_FILE, ACCESS_LOG_FILE;
+
+let logStream = fs.createWriteStream(null, { fd: process.stderr.fd });
+let logStat = fs.fstatSync(logStream.fd);
+let accessLogStream = fs.createWriteStream(null, { fd: process.stdout.fd });
+let accessLogStat = fs.fstatSync(accessLogStream.fd);
+
+// Reopen if original files have been moved (e.g. logrotate)
+function reopen() {
+  let counter = 1;
+
+  if (LOG_FILE) {
+    ++counter;
+    fs.stat(LOG_FILE, (err, stat) => {
+      if (err && !err.message.startsWith("ENOENT:")) throw err;
+
+      if (!(stat && stat.dev === logStat.dev && stat.ino === logStat.ino)) {
+        logStream.end();
+        logStream = fs.createWriteStream(null, {
+          fd: fs.openSync(LOG_FILE, "a")
+        });
+        logStat = fs.fstatSync(logStream.fd);
+      }
+
+      if (--counter === 0)
+        setTimeout(reopen, REOPEN_EVERY - (Date.now() % REOPEN_EVERY)).unref();
+    });
+  }
+
+  if (ACCESS_LOG_FILE) {
+    ++counter;
+    fs.stat(ACCESS_LOG_FILE, (err, stat) => {
+      if (err && !err.message.startsWith("ENOENT:")) throw err;
+
+      if (
+        !(
+          stat &&
+          stat.dev === accessLogStat.dev &&
+          stat.ino === accessLogStat.ino
+        )
+      ) {
+        accessLogStream.end();
+        accessLogStream = fs.createWriteStream(null, {
+          fd: fs.openSync(ACCESS_LOG_FILE, "a")
+        });
+        accessLogStat = fs.fstatSync(accessLogStream.fd);
+      }
+
+      if (--counter === 0)
+        setTimeout(reopen, REOPEN_EVERY - (Date.now() % REOPEN_EVERY)).unref();
+    });
+  }
+
+  if (--counter === 0)
+    setTimeout(reopen, REOPEN_EVERY - (Date.now() % REOPEN_EVERY)).unref();
+}
+
+function init(service, version) {
+  defaultMeta.hostname = os.hostname();
+  defaultMeta.pid = process.pid;
+  defaultMeta.name = `genieacs-ui-${service}`;
+  defaultMeta.version = version;
+
+  LOG_FILE = config.logger[`${service}LogFile`];
+  ACCESS_LOG_FILE = config.logger[`${service}AccessLogFile`];
+
+  if (LOG_FILE) {
+    logStream = fs.createWriteStream(null, { fd: fs.openSync(LOG_FILE, "a") });
+    logStat = fs.fstatSync(logStream.fd);
+  }
+
+  if (ACCESS_LOG_FILE) {
+    accessLogStream = fs.createWriteStream(null, {
+      fd: fs.openSync(ACCESS_LOG_FILE, "a")
+    });
+    accessLogStat = fs.fstatSync(accessLogStream.fd);
+  }
+
+  // Determine if logs are going to journald
+  const JOURNAL_STREAM = process.env["JOURNAL_STREAM"];
+
+  if (JOURNAL_STREAM) {
+    let [dev, inode] = JOURNAL_STREAM.split(":");
+    dev = parseInt(dev);
+    inode = parseInt(inode);
+
+    LOG_SYSTEMD = logStat.dev === dev && logStat.ino === inode;
+    ACCESS_LOG_SYSTEMD =
+      accessLogStat.dev === dev && accessLogStat.ino === inode;
+  }
+
+  if (LOG_FILE || ACCESS_LOG_FILE)
+    setTimeout(reopen, REOPEN_EVERY - (Date.now() % REOPEN_EVERY)).unref();
+}
+
+function close() {
+  accessLogStream.end();
+  logStream.end();
+}
+
+function flatten(details) {
+  if (details.exception) {
+    details.exceptionName = details.exception.name;
+    details.exceptionMessage = details.exception.message;
+    details.exceptionStack = details.exception.stack;
+    delete details.exception;
+  }
+
+  if (details.context) {
+    details.remoteAddress = details.context.request.ip;
+    if (details.context.state.user)
+      details.user = details.context.state.user.username;
+    delete details.context;
+  }
+
+  for (const [k, v] of Object.entries(details))
+    if (v == null) delete details[k];
+
+  return details;
+}
+
+function formatJson(details, systemd) {
+  if (systemd) {
+    let severity = "";
+    if (details.severity === "info") severity = "<6>";
+    else if (details.severity === "warn") severity = "<4>";
+    else if (details.severity === "error") severity = "<3>";
+
+    return `${severity}${JSON.stringify(flatten(details))}${os.EOL}`;
+  }
+
+  return `${JSON.stringify(flatten(details))}${os.EOL}`;
+}
+
+function formatSimple(details, systemd) {
+  flatten(details);
+
+  let remote = "";
+  if (details.remoteAddress)
+    if (details.user) remote = `${details.user}@${details.remoteAddress}: `;
+    else remote = `${details.remoteAddress}: `;
+
+  const keys = Object.keys(details);
+  const skip = {
+    user: 1,
+    remoteAddress: 1,
+    severity: 1,
+    timestamp: 1,
+    message: 1
+  };
+
+  let meta = "";
+
+  let kv = [];
+  for (let k of keys)
+    if (!skip[k]) kv.push(`${k}=${JSON.stringify(details[k])}`);
+
+  if (kv.length) meta = `; ${kv.join(" ")}`;
+
+  if (systemd) {
+    let severity = "";
+    if (details.severity === "info") severity = "<6>";
+    else if (details.severity === "warn") severity = "<4>";
+    else if (details.severity === "error") severity = "<3>";
+
+    return `${severity}${remote}${details.message}${meta}${os.EOL}`;
+  }
+
+  return `${details.timestamp} [${details.severity.toUpperCase()}] ${remote}${
+    details.message
+  }${meta}${os.EOL}`;
+}
+
+function log(details) {
+  details.timestamp = new Date().toISOString();
+  if (LOG_FORMAT === "json") {
+    details = Object.assign({}, defaultMeta, details);
+    logStream.write(formatJson(details, LOG_SYSTEMD));
+  } else {
+    logStream.write(formatSimple(details, LOG_SYSTEMD));
+  }
+}
+
+function info(details) {
+  details.severity = "info";
+  log(details);
+}
+
+function warn(details) {
+  details.severity = "warn";
+  log(details);
+}
+
+function error(details) {
+  details.severity = "error";
+  log(details);
+}
+
+function accessLog(details) {
+  details.timestamp = new Date().toISOString();
+  if (ACCESS_LOG_FORMAT === "json") {
+    Object.assign(details, defaultMeta);
+    accessLogStream.write(formatJson(details, ACCESS_LOG_SYSTEMD));
+  } else {
+    accessLogStream.write(formatSimple(details, ACCESS_LOG_SYSTEMD));
+  }
+}
+
+function accessInfo(details) {
+  details.severity = "info";
+  accessLog(details);
+}
+
+function accessWarn(details) {
+  details.severity = "warn";
+  accessLog(details);
+}
+
+function accessError(details) {
+  details.severity = "error";
+  accessLog(details);
+}
+
+exports.init = init;
+exports.close = close;
+exports.info = info;
+exports.warn = warn;
+exports.error = error;
+exports.accessInfo = accessInfo;
+exports.accessWarn = accessWarn;
+exports.accessError = accessError;

server/server.js

@@ -12,6 +12,7 @@ const config = require("./config");
 const api = require("./api");
 const Authorizer = require("../common/authorizer");
 const expression = require("../common/expression");
+const logger = require("./logger");
 
 const koa = new Koa();
 const router = new Router();
@@ -19,6 +20,14 @@ const router = new Router();
 const JWT_SECRET = config.server.jwtSecret;
 const JWT_COOKIE = "genieacs-ui-jwt";
 
+const VERSION = require("../package.json")["version"];
+
+logger.info({
+  message: "GenieACS UI starting",
+  pid: process.pid,
+  version: VERSION
+});
+
 function getPermissionSets(roles) {
   const allPermissions = config.permissions;
   const permissionSets = roles.map(role => {
@@ -69,9 +78,17 @@ router.post("/login", async ctx => {
 
   const user = config.auth.simple.users[username];
 
+  let log = {
+    message: "Log in",
+    context: ctx,
+    username: username
+  };
+
   if (!user || user.password !== password) {
     ctx.status = 400;
     ctx.body = "Incorrect username or password";
+    log.message += " - invalid credentials";
+    logger.accessWarn(log);
     return;
   }
 
@@ -81,11 +98,18 @@ router.post("/login", async ctx => {
   );
   ctx.cookies.set(JWT_COOKIE, token);
   ctx.body = JSON.stringify(token);
+
+  logger.accessInfo(log);
 });
 
 router.post("/logout", async ctx => {
   ctx.cookies.set(JWT_COOKIE); // Delete cookie
   ctx.body = "";
+
+  logger.accessInfo({
+    message: "Log out",
+    context: ctx
+  });
 });
 
 koa.use(koaBodyParser());
@@ -125,7 +149,10 @@ koa.use(
 koa.use(router.routes());
 koa.use(koaStatic("./public"));
 
-koa.listen(config.server.port, () => {
-  // eslint-disable-next-line no-console
-  console.log(`Server listening on port ${config.server.port}`);
+koa.listen(config.server.port, "0.0.0.0", () => {
+  logger.info({
+    message: "Worker litening",
+    port: config.server.port,
+    pid: process.pid
+  });
 });