diff --git a/config.json b/config.json index 126c213..1217810 100644 --- a/config.json +++ b/config.json @@ -282,5 +282,9 @@ "type": "device-actions" } ] + }, + "logger": { + "logFormat": "simple", + "accessLogFormat": "simple" } } diff --git a/server/api.js b/server/api.js index 6c2fca3..0843fbd 100644 --- a/server/api.js +++ b/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 = ""; }); diff --git a/server/logger.js b/server/logger.js new file mode 100644 index 0000000..7e388e8 --- /dev/null +++ b/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; diff --git a/server/server.js b/server/server.js index dfda269..d0a8894 100644 --- a/server/server.js +++ b/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 + }); });