diff --git a/lib/appFactory.js b/lib/appFactory.js index 255b711a..8ca3c31d 100644 --- a/lib/appFactory.js +++ b/lib/appFactory.js @@ -1,6 +1,6 @@ const express = require('express'); const path = require('path'); -const logger = require('morgan'); +const { loggingMiddleware } = require('./logger'); const indexRouter = require('./routes/index'); const signupRouter = require('./routes/signup'); const webFingerRouter = require('./routes/webfinger'); @@ -26,7 +26,7 @@ module.exports = function ({ hostIdentity, jwtSecret, account, store, basePath = app.set('account', account); - app.use(logger('dev')); + app.use(loggingMiddleware); app.use(helmet({ contentSecurityPolicy: { directives: { @@ -73,9 +73,10 @@ module.exports = function ({ hostIdentity, jwtSecret, account, store, basePath = // error handler app.use(function (err, req, res, _next) { + const message = err?.message || err?.errors?.find(e => e.message).message || err?.cause?.message || 'indescribable error'; errorPage(req, res, err.status || 500, { - title: shorten(err.message, 30), - message: err.message, + title: shorten(message, 30), + message, error: req.app.get('env') === 'development' ? err : {} }); }); diff --git a/lib/logger.js b/lib/logger.js index 67046a2b..9c28e7ed 100644 --- a/lib/logger.js +++ b/lib/logger.js @@ -90,14 +90,29 @@ function getLogger () { return logger; } +function loggingMiddleware (req, res, next) { + res.logNotes = new Set(); + res.on('finish', () => { + logRequest(req, req.data?.username || req.params?.username || '-', res.statusCode, + res._contentLength ?? res.get('Content-Length') ?? '-', Array.from(res.logNotes).join(' '), res.logLevel); + }); + next(); +} + function logRequest (req, username, status, numBytesWritten, logNote, logLevel) { let level; if (logLevel) { level = logLevel; + } else if ([502, 504, 507].includes(status)) { // Bad Gateway, Gateway Timeout, Insufficient Storage + level = 'error'; // problem with backing store + } else if (status === 503) { // Service Unavailable + level = 'warning'; } else if (!status || status >= 500) { // presumably a coding error level = 'crit'; - } else if ([401].includes(status)) { // user authentication is notable + } else if ([401, 201].includes(status)) { // user authentication & blob creation are notable level = 'notice'; + } else if (req.originalUrl === '/favicon.ico') { // browsers request this too often + level = 'debug'; } else if (status >= 400) { // client error level = 'warning'; } else if ([302, 307, 308].includes(status)) { // redirects are boring @@ -110,7 +125,7 @@ function logRequest (req, username, status, numBytesWritten, logNote, logLevel) const appHost = getOriginator(req); - let line = `${clientAddress} ${appHost} ${username} ${req.method} ${req.url} ${status} ${numBytesWritten}`; + let line = `${clientAddress} ${appHost} ${username} ${req.method} ${req.originalUrl ?? req.url} ${status} ${numBytesWritten}`; if (logNote) { if (logNote instanceof Error) { logNote = logNote.message || logNote.code || logNote.name || logNote.toString(); @@ -120,4 +135,4 @@ function logRequest (req, username, status, numBytesWritten, logNote, logLevel) logger.log(level, line); } -module.exports = { configureLogger, getLogger, logRequest }; +module.exports = { configureLogger, getLogger, loggingMiddleware, logRequest }; diff --git a/lib/middleware/redirectToSSL.js b/lib/middleware/redirectToSSL.js index fbf60076..76669530 100644 --- a/lib/middleware/redirectToSSL.js +++ b/lib/middleware/redirectToSSL.js @@ -1,6 +1,5 @@ const isSecureRequest = require('../util/isSecureRequest'); const { getHost } = require('../util/getHost'); -const { logRequest } = require('../logger'); /** redirects to HTTPS server if needed */ module.exports = function redirectToSSL (req, res, next) { @@ -11,6 +10,6 @@ module.exports = function redirectToSSL (req, res, next) { const host = getHost(req).split(':')[0] + (req.app.get('httpsPort') ? ':' + req.app.get('httpsPort') : ''); const newUrl = 'https://' + host + req.url; + res.logNotes.add('-> ' + newUrl); res.redirect(302, newUrl); - logRequest(req, '-', 302, 0, '-> ' + newUrl); }; diff --git a/lib/middleware/sanityCheckUsername.js b/lib/middleware/sanityCheckUsername.js index 0c63fa41..d9e52ac1 100644 --- a/lib/middleware/sanityCheckUsername.js +++ b/lib/middleware/sanityCheckUsername.js @@ -1,5 +1,3 @@ -const { logRequest } = require('../logger'); - /** sanity check of username, to defend against ".." and whatnot */ module.exports = function sanityCheckUsername (req, res, next) { const username = req.params.username || req.data.username || ''; @@ -7,7 +5,6 @@ module.exports = function sanityCheckUsername (req, res, next) { return next(); } - res.status(400).type('text/plain').end(); - - logRequest(req, req.data.username, 400, 0, 'invalid user'); + res.logNotes.add('invalid user'); + res.status(400).end(); }; diff --git a/lib/middleware/secureRequest.js b/lib/middleware/secureRequest.js index 7e4bf77c..62208211 100644 --- a/lib/middleware/secureRequest.js +++ b/lib/middleware/secureRequest.js @@ -1,5 +1,4 @@ const isSecureRequest = require('../util/isSecureRequest'); -const { logRequest } = require('../logger'); /** ensures request is secure, if required */ module.exports = function secureRequest (req, res, next) { @@ -7,6 +6,6 @@ module.exports = function secureRequest (req, res, next) { return next(); } - res.status(400).end(); // TODO: add an explanatory message - logRequest(req, '-', 400, 0, 'blocked insecure'); + res.logNotes.add('blocked insecure'); + res.status(400).type('text/plain').send('The request did not use HTTPS.'); }; diff --git a/lib/routes/S3_store_handler.js b/lib/routes/S3_store_handler.js index 6a975537..747e461d 100644 --- a/lib/routes/S3_store_handler.js +++ b/lib/routes/S3_store_handler.js @@ -2,6 +2,7 @@ /* eslint-env node */ /* eslint-disable camelcase */ +const errToMessages = require('../util/errToMessages'); const { createHash } = require('node:crypto'); const express = require('express'); const { posix } = require('node:path'); @@ -72,8 +73,8 @@ module.exports = function (endPoint = 'play.min.io', accessKey = 'Q3AM3UQ867SPQQ } getLogger().info(`${endPoint} ${accessKey} has ${users.length} users: ` + users.join(', ')); getLogger().info(`${endPoint} ${accessKey} has ${numOtherBuckets} buckets that are not accounts (don't end with “${userNameSuffix}”)`); - }).catch(err => { // it's really bad if storage can't be reached - getLogger().alert('while listing buckets:', err); + }).catch(err => { // it's bad if storage can't be reached + getLogger().alert(Array.from(errToMessages(err, new Set(['while listing buckets:']))).join(' ')); }); let pauseUntil = 0; // TODO: actually pause requests until this datetime. How to test? @@ -121,8 +122,9 @@ module.exports = function (endPoint = 'play.min.io', accessKey = 'Q3AM3UQ867SPQQ } else if (['NotModified', '304'].includes(err.name) || err.$metadata?.httpStatusCode === 304) { return res.status(304).end(); } else if (err.name === 'EndResponseError') { - getLogger().log(err.logLevel || 'info', err.statusCode, err.message, req.params.username, req.params[0]); - return res.status(err.statusCode).end(); + res.logNotes.add(err.message); + res.logLevel = err.logLevel; + return res.status(err.statusCode).type('text/plain').send(err.message); } else { return next(Object.assign(err, { status: 502 })); } @@ -187,8 +189,9 @@ module.exports = function (endPoint = 'play.min.io', accessKey = 'Q3AM3UQ867SPQQ setPauseUntil(res.get('Retry-After')); return next(Object.assign(err, { status: err?.$metadata?.httpStatusCode || 502 })); } else if (err.name === 'EndResponseError') { - getLogger().log(err.logLevel || 'info', err.statusCode, err.message, req.params.username, req.params[0]); - return res.status(err.statusCode).end(); + res.logNotes.add(err.message); + res.logLevel = err.logLevel; + return res.status(err.statusCode).type('text/plain').send(err.message); } else if (err.name === 'TimeoutError') { return res.status(504).end(); } else if (err.$metadata?.httpStatusCode === 400 || ['400', 'NoSuchBucket'].includes(err.name)) { @@ -232,10 +235,12 @@ module.exports = function (endPoint = 'play.min.io', accessKey = 'Q3AM3UQ867SPQQ err.$metadata?.httpStatusCode === 403) { res.status(404).end(); } else if (err.$metadata?.httpStatusCode === 400 || err.name === '400' || /\bBucket\b/.test(err.message)) { + errToMessages(err, res.logNotes); res.status(400).type('text/plain').send('A parameter value is bad'); } else if (err.name === 'EndResponseError') { - getLogger().log(err.logLevel || 'info', err.statusCode, err.message, req.params.username, req.params[0]); - return res.status(err.statusCode).end(); + res.logNotes.add(err.message); + res.logLevel = err.logLevel; + return res.status(err.statusCode).type('text/plain').send(err.message); } else { return next(Object.assign(err, { status: 502 })); } @@ -254,7 +259,7 @@ module.exports = function (endPoint = 'play.min.io', accessKey = 'Q3AM3UQ867SPQQ * @param {string} params.password * @returns {Promise} name of bucket */ - router.createUser = async function createUser (params) { + router.createUser = async function createUser (params, logNotes) { let { username, email, password } = params; username = username.trim(); @@ -307,7 +312,7 @@ module.exports = function (endPoint = 'play.min.io', accessKey = 'Q3AM3UQ867SPQQ } })); } catch (err) { - getLogger().warning('Couldn\'t set bucket to expire old blob versions:', err); + errToMessages(err, logNotes.add('Couldn\'t set bucket to expire old blob versions:')); } const config = await core.hashPassword(password, null); @@ -325,7 +330,6 @@ module.exports = function (endPoint = 'play.min.io', accessKey = 'Q3AM3UQ867SPQQ if (err.name === 'BucketAlreadyOwnedByYou') { throw new Error(`Username “${username}” is already taken`, { cause: err }); } else { - getLogger().error('while creating or configuring bucket', err); throw new Error('while creating or configuring bucket: ' + err, { cause: err }); } } @@ -336,7 +340,7 @@ module.exports = function (endPoint = 'play.min.io', accessKey = 'Q3AM3UQ867SPQQ * @param username * @returns {Promise} number of files deleted */ - router.deleteUser = async function deleteUser (username) { + router.deleteUser = async function deleteUser (username, logNotes) { let numObjectsDeleted = 0; let numObjectsFailedToDelete = 0; @@ -350,7 +354,7 @@ module.exports = function (endPoint = 'play.min.io', accessKey = 'Q3AM3UQ867SPQQ /* const { DeleteMarker } = */ await s3client.send(new DeleteObjectCommand({ Bucket: bucketName, Key: item.Key, VersionId: item.VersionId })); ++numObjectsDeleted; } catch (err) { - console.warn('while deleting', bucketName, item.Key, item.VersionId, err); + errToMessages(err, logNotes.add('while deleting:').add(bucketName).add(item.Key).add(item.VersionId)); ++numObjectsFailedToDelete; } } @@ -402,7 +406,7 @@ module.exports = function (endPoint = 'play.min.io', accessKey = 'Q3AM3UQ867SPQQ * @returns {Promise} true if correct * @throws if user doesn't exist, password doesn't match, or any error */ - router.authenticate = async function authenticate ({ username, password }) { + router.authenticate = async function authenticate ({ username, password }, logNotes) { let storedKey, presentedKey; try { const bucketName = calcBucketName(username); @@ -412,9 +416,11 @@ module.exports = function (endPoint = 'play.min.io', accessKey = 'Q3AM3UQ867SPQQ presentedKey = (await core.hashPassword(password, storedConfig)).key; } catch (err) { if (err.name === 'NoSuchBucket') { - getLogger().info(`attempt to log in with nonexistent user “${username}”`); + errToMessages(err, logNotes.add(`attempt to log in with nonexistent user “${username}”`)); + // can't set log level to 'info' } else { - getLogger().error(`while validating password for “${username}”:`, err); + errToMessages(err, logNotes.add(`while validating password for “${username}”:`)); + // can't set log level to 'error' } throw new Error('Password and username do not match'); } @@ -570,7 +576,7 @@ module.exports = function (endPoint = 'play.min.io', accessKey = 'Q3AM3UQ867SPQQ }); // Upload allows you to pass ContentLength, but then fails for streams longer than about 5.1MB, with a message about XML. - parallelUpload.on('httpUploadProgress', (progress) => { + parallelUpload.on('httpUploadProgress', (progress) => { // TODO: does this add value? console.debug(bucketName, s3Path, `part ${progress.part} ${progress.loaded?.toLocaleString()} / ${progress.total?.toLocaleString()} bytes`); }); diff --git a/lib/routes/oauth.js b/lib/routes/oauth.js index 013414a0..1e1d6405 100644 --- a/lib/routes/oauth.js +++ b/lib/routes/oauth.js @@ -1,12 +1,12 @@ /* eslint-env node */ /* eslint-disable camelcase */ +const errToMessages = require('../util/errToMessages'); const express = require('express'); const formOrQueryData = require('../middleware/formOrQueryData'); const redirectToSSL = require('../middleware/redirectToSSL'); const sanityCheckUsername = require('../middleware/sanityCheckUsername'); const secureRequest = require('../middleware/secureRequest'); const jwt = require('jsonwebtoken'); -const { logRequest, getLogger } = require('../logger'); const qs = require('querystring'); const accessStrings = { r: 'Read', rw: 'Read/write' }; @@ -31,7 +31,6 @@ module.exports = function (hostIdentity, jwtSecret) { username: req.params.username, access_strings: accessStrings }); - logRequest(req, req.params.username, 200); }); router.post('/', @@ -44,11 +43,11 @@ module.exports = function (hostIdentity, jwtSecret) { const username = locals.username.split('@')[0]; if (locals.deny) { - return error(req, res, 'access_denied', 'The user did not grant permission'); + return error(req, res, 'access_denied', 'The user did not grant permission to'); } try { - await req.app.get('account').authenticate({ username, password: locals.password }); + await req.app.get('account').authenticate({ username, password: locals.password }, res.logNotes); let redirectOrigin; try { redirectOrigin = new URL(req.data.redirect_uri).origin; @@ -69,7 +68,7 @@ module.exports = function (hostIdentity, jwtSecret) { jwtSecret, { algorithm: 'HS512', issuer: hostIdentity, audience: redirectOrigin, subject: username, expiresIn: '30d' } ); - getLogger().info(`created JWT for ${username} on ${redirectOrigin} w/ scope ${locals.scope}`); + res.logNotes.add(`created JWT for ${username} on ${redirectOrigin} w/ scope ${locals.scope}`); const args = { access_token: token, token_type: 'bearer', @@ -84,8 +83,8 @@ module.exports = function (hostIdentity, jwtSecret) { locals.access_strings = accessStrings; locals.state = locals.state || ''; + errToMessages(error, res.logNotes); res.status(401).render('auth.html', locals); - logRequest(req, req.params.username, 401); } } ); @@ -117,24 +116,25 @@ module.exports = function (hostIdentity, jwtSecret) { function error (req, res, error, error_description) { redirect(req, res, { error, error_description }, - `${req.data.username} ${error_description} ${req.data.client_id}`); + `${error_description} ${req.data.client_id}`); } function redirect (req, res, args, logNote) { const hash = qs.stringify(args); if (req.data.redirect_uri) { const location = req.data.redirect_uri + '#' + hash; - res.redirect(location); if (logNote) { - logRequest(req, req.data.username || '-', 302, 0, logNote, 'warning'); + res.logNotes.add(logNote); + res.logLevel = 'warning'; } else { - logRequest(req, req.data.username || '-', 302, 0, '-> ' + req.data.redirect_uri, 'notice'); + res.logNotes.add('-> ' + req.data.redirect_uri); + res.logLevel = 'notice'; } + res.redirect(location); } else { + res.logNotes.add(logNote || args?.error_description || 'no redirect_uri'); res.status(400).type('text/plain').send(hash); - logRequest(req, req.data.username || '-', 400, hash.length, - logNote || args?.error_description || 'no redirect_uri'); } } diff --git a/lib/routes/signup.js b/lib/routes/signup.js index 8912851f..e5f1b179 100644 --- a/lib/routes/signup.js +++ b/lib/routes/signup.js @@ -1,8 +1,8 @@ const express = require('express'); const router = express.Router(); const { getHost } = require('../util/getHost'); +const errToMessages = require('../util/errToMessages'); const errorPage = require('../util/errorPage'); -const { getLogger } = require('../logger'); const DISABLED_LOCALS = { title: 'Forbidden', message: 'Signing up is not allowed currently' }; const DISABLED_LOG_NOTE = 'signups disabled'; @@ -26,19 +26,20 @@ router.post('/', async function (req, res) { if (req.app?.locals?.signup) { try { - const storageName = await req.app?.get('account').createUser(req.body); - getLogger().notice(`created storage “${storageName}” for user “${req.body.username}”`); + const storageName = await req.app?.get('account').createUser(req.body, res.logNotes); + res.logNotes.add(`created storage “${storageName}” for user “${req.body.username}”`); res.status(201).render('signup-success.html', { title: 'Signup Success', params: req.body, host: getHost(req) }); } catch (err) { - getLogger().error(`while creating user “${req.body?.username}”`, err); + errToMessages(err, res.logNotes.add(`while creating user “${req.body?.username}”:`)); + const errChain = [err, ...(err.errors || []), ...(err.cause ? [err.cause] : []), new Error('indescribable error')]; res.status(409).render('signup.html', { title: 'Signup Failure', params: req.body, - error: err, + error: errChain.find(e => e.message), host: getHost(req) }); } diff --git a/lib/routes/storage_common.js b/lib/routes/storage_common.js index ea6eaa82..9761ec6d 100644 --- a/lib/routes/storage_common.js +++ b/lib/routes/storage_common.js @@ -5,7 +5,6 @@ const { corsAllowPrivate, corsRS } = require('../util/corsMiddleware'); const sanityCheckUsername = require('../middleware/sanityCheckUsername'); const isSecureRequest = require('../util/isSecureRequest'); const { expressjwt: jwt } = require('express-jwt'); -const { logRequest } = require('../logger'); const { getHost } = require('../util/getHost'); module.exports = function (hostIdentity, jwtSecret) { @@ -89,8 +88,8 @@ module.exports = function (hostIdentity, jwtSecret) { if (path.length > 0) { for (const segment of path.split('/')) { if (segment.length === 0 || /^\.+$|\0/.test(segment)) { + res.logNotes.add('invalid path'); res.status(400).end(); - logRequest(req, req.params.username, 400, 0, 'invalid path'); return; } } @@ -100,8 +99,8 @@ module.exports = function (hostIdentity, jwtSecret) { function validWritePath (req, res, next) { if (req.blobPath.endsWith('/')) { - res.status(400).end(); - return logRequest(req, req.params.username, 400, 0, 'can\'t write to directory'); + res.logNotes.add('can\'t write to directory'); + res.status(400).type('text/plain').send('can\'t write to directory'); } else { next(); } @@ -132,7 +131,7 @@ module.exports = function (hostIdentity, jwtSecret) { } if (!req.auth) { // request was sent without authentication - return unauthorized(req, res, 401, '', requiredScope); + return unauthorized(req, res, 401, '', requiredScope, 'no authentication'); } if (req.auth.sub !== req.params.username || req.auth.aud !== req.headers.origin) { @@ -160,8 +159,8 @@ module.exports = function (hostIdentity, jwtSecret) { function noRanges (req, res, next) { if (req.get('Content-Range')) { const msg = 'Content-Range not allowed in PUT'; + res.logNotes.add(msg); res.status(400).type('text/plain').send(msg); - logRequest(req, req.params.username, 400, msg.length, msg); } else { next(); } @@ -179,8 +178,8 @@ module.exports = function (hostIdentity, jwtSecret) { function unauthorized (req, res, status, errMsg, requiredScope, logMsg) { const value = `Bearer realm="${getHost(req)}" scope="${requiredScope}"` + (errMsg ? ` error="${errMsg}"` : ''); res.set('WWW-Authenticate', value); + res.logNotes.add(logMsg || errMsg); res.status(status).end(); - logRequest(req, req.params.username, status, 0, logMsg || errMsg || ''); } return router; diff --git a/lib/util/EndResponseError.js b/lib/util/EndResponseError.js index aea3df8a..c8110ec3 100644 --- a/lib/util/EndResponseError.js +++ b/lib/util/EndResponseError.js @@ -1,5 +1,7 @@ +/** Thrown to tell the top-level handler what to respond with. */ + module.exports = class EndResponseError extends Error { - constructor (message, options, statusCode, logLevel) { + constructor (message, options, statusCode, logLevel = undefined) { super(...arguments); this.name = 'EndResponseError'; this.statusCode = statusCode; diff --git a/lib/util/errToMessages.js b/lib/util/errToMessages.js new file mode 100644 index 00000000..00ce2d24 --- /dev/null +++ b/lib/util/errToMessages.js @@ -0,0 +1,31 @@ +module.exports = function errToMessages (err, messages) { + try { + if (err.name !== 'AggregateError') { + if (err.name && !err.message?.includes(err.name) && + !Array.from(messages).some(msg => typeof msg === 'string' && msg?.includes(err.name))) { + messages.add(err.name); + } + if (err.message) { + messages.add(err.message); + } + if (err.code && !Array.from(messages).some(msg => typeof msg === 'string' && msg?.includes(err.code))) { + messages.add(err.code); + } + const errno = err.errno ? String(err.errno) : ''; + if (errno && !Array.from(messages).some(msg => typeof msg === 'string' && msg?.includes(errno))) { + messages.add(errno); + } + } + if (err.errors?.[Symbol.iterator]) { + for (const e of err.errors) { + errToMessages(e, messages); + } + } + if (err.cause) { + errToMessages(err.cause, messages); + } + } catch (err2) { + messages.add(err2); + } + return messages; +}; diff --git a/lib/util/errorPage.js b/lib/util/errorPage.js index 9abc1426..cb36801c 100644 --- a/lib/util/errorPage.js +++ b/lib/util/errorPage.js @@ -1,5 +1,4 @@ const { getHost } = require('./getHost'); -const { logRequest } = require('../logger'); function errorPage (req, res, status = 500, messageOrLocals, logNote = '', logLevel = undefined) { res.status(status); @@ -13,10 +12,12 @@ function errorPage (req, res, status = 500, messageOrLocals, logNote = '', logLe ...(typeof messageOrLocals === 'string' ? { message: messageOrLocals } : messageOrLocals) }; - res.render('error.html', locals); + if (logNote || locals.error || locals.message) { + res.logNotes.add(logNote || locals.error || locals.message); + } + res.logLevel = logLevel; - const username = locals.username || (locals.params?.username) || '-'; - logRequest(req, username, status, 'n/a', logNote || locals.error || locals.message, logLevel); + res.render('error.html', locals); } module.exports = errorPage; diff --git a/lib/util/timeoutError.js b/lib/util/timeoutError.js index 9f4ca106..38cba9cf 100644 --- a/lib/util/timeoutError.js +++ b/lib/util/timeoutError.js @@ -1,3 +1,5 @@ +/** TODO: replace this with EndResponseError */ + module.exports = class TimeoutError extends Error { constructor () { super(...arguments); diff --git a/notes/modular-server.md b/notes/modular-server.md index 6e2a3d4a..15bbafcd 100644 --- a/notes/modular-server.md +++ b/notes/modular-server.md @@ -7,7 +7,7 @@ There's an NPM module for almost anything worth doing in a Node.js server (albei ## Configuration Your configuration file *MUST* set `host_identity`. -It's typically the domain name of the host. +It's normally the usual domain name of the host. Changing `host_identity` will invalidate all grants of access, and make unavailable accounts stored in S3-compatible storage (unless you set `s3.user_name_suffix` to the old value). ### Modular Server Factory @@ -35,5 +35,25 @@ You *MUST* set `app.locals.title` and `app.locals.signup` or the web pages won't Production servers typically outsource TLS to a proxy server — nginx and Apache are both well-documented. A proxy server can also cache static content. Armadietto sets caching headers to tell caches what they can and can't cache. -If the modular server is behind a proxy, you *MUST* set +If the modular server is behind a proxy, you **MUST** set `app.set('trust proxy', 1)` + +## Development + +### Logging + +A successful request doesn't need extra info to be logged, +unless it's something notable like an account being created. +An unsuccessful request should log enough detail to recreate +why it failed. + +Log info is much more helpful when it's clear what request +it's associated with. Code does not call the logger directly. Instead, messages are added to the set `res.logNotes`. +Multiple pieces of information don't need to be concatenated before adding to `logNotes`. The logging middleware will +concatenate them when logging the request. +When an error has been thrown, the function `errToMessages` +is useful to extract fields from the error and its cause +(if any), eliminated duplicated messages. + +A few activities not associated with requests do call the +logger directly. diff --git a/package-lock.json b/package-lock.json index 8ee61ae4..00735843 100644 --- a/package-lock.json +++ b/package-lock.json @@ -21,7 +21,6 @@ "jsonwebtoken": "^9.0.2", "lockfile": "^1.0.4", "mkdirp": "^1.0.4", - "morgan": "^1.10.0", "node-mocks-http": "^1.14.1", "pug": "^3.0.2", "winston": "^3.11.0", @@ -2210,17 +2209,6 @@ } ] }, - "node_modules/basic-auth": { - "version": "2.0.1", - "resolved": "https://registry.npmjs.org/basic-auth/-/basic-auth-2.0.1.tgz", - "integrity": "sha512-NF+epuEdnUYVlGuhaxbbq+dvJttwLnGY+YixlXlME5KpQ5W3CnXA5cVTneY3SPbPDRkcjMbifrwmFYcClgOZeg==", - "dependencies": { - "safe-buffer": "5.1.2" - }, - "engines": { - "node": ">= 0.8" - } - }, "node_modules/bdd-lazy-var": { "version": "2.6.1", "resolved": "https://registry.npmjs.org/bdd-lazy-var/-/bdd-lazy-var-2.6.1.tgz", @@ -5140,45 +5128,6 @@ "node": ">=10" } }, - "node_modules/morgan": { - "version": "1.10.0", - "resolved": "https://registry.npmjs.org/morgan/-/morgan-1.10.0.tgz", - "integrity": "sha512-AbegBVI4sh6El+1gNwvD5YIck7nSA36weD7xvIxG4in80j/UoK8AEGaWnnz8v1GxonMCltmlNs5ZKbGvl9b1XQ==", - "dependencies": { - "basic-auth": "~2.0.1", - "debug": "2.6.9", - "depd": "~2.0.0", - "on-finished": "~2.3.0", - "on-headers": "~1.0.2" - }, - "engines": { - "node": ">= 0.8.0" - } - }, - "node_modules/morgan/node_modules/debug": { - "version": "2.6.9", - "resolved": "https://registry.npmjs.org/debug/-/debug-2.6.9.tgz", - "integrity": "sha512-bC7ElrdJaJnPbAP+1EotYvqZsb3ecl5wi6Bfi6BJTUcNowp6cvspg0jXznRTKDjm/E7AdgFBVeAPVMNcKGsHMA==", - "dependencies": { - "ms": "2.0.0" - } - }, - "node_modules/morgan/node_modules/ms": { - "version": "2.0.0", - "resolved": "https://registry.npmjs.org/ms/-/ms-2.0.0.tgz", - "integrity": "sha512-Tpp60P6IUJDTuOq/5Z8cdskzJujfwqfOTkrwIwj7IRISpnkJnT6SyJ4PCPnGMoFjC9ddhal5KVIYtAt97ix05A==" - }, - "node_modules/morgan/node_modules/on-finished": { - "version": "2.3.0", - "resolved": "https://registry.npmjs.org/on-finished/-/on-finished-2.3.0.tgz", - "integrity": "sha512-ikqdkGAAyf/X/gPhXGvfgAytDZtDbr+bkNUJ0N9h5MI/dmdgCs3l6hoHrcUv41sRKew3jIwrp4qQDXiK99Utww==", - "dependencies": { - "ee-first": "1.1.1" - }, - "engines": { - "node": ">= 0.8" - } - }, "node_modules/ms": { "version": "2.1.3", "resolved": "https://registry.npmjs.org/ms/-/ms-2.1.3.tgz", @@ -5404,14 +5353,6 @@ "node": ">= 0.8" } }, - "node_modules/on-headers": { - "version": "1.0.2", - "resolved": "https://registry.npmjs.org/on-headers/-/on-headers-1.0.2.tgz", - "integrity": "sha512-pZAE+FJLoyITytdqK0U5s+FIpjN0JP3OzFi/u8Rx+EV5/W+JTWGXG8xFzevE7AjBfDqHv/8vL8qQsIhHnqRkrA==", - "engines": { - "node": ">= 0.8" - } - }, "node_modules/once": { "version": "1.4.0", "resolved": "https://registry.npmjs.org/once/-/once-1.4.0.tgz", @@ -8587,14 +8528,6 @@ "resolved": "https://registry.npmjs.org/base64-js/-/base64-js-1.5.1.tgz", "integrity": "sha512-AKpaYlHn8t4SVbOHCy+b5+KKgvR4vrsD8vbvrbiQJps7fKDTkjkDry6ji0rUJjC0kzbNePLwzxq8iypo41qeWA==" }, - "basic-auth": { - "version": "2.0.1", - "resolved": "https://registry.npmjs.org/basic-auth/-/basic-auth-2.0.1.tgz", - "integrity": "sha512-NF+epuEdnUYVlGuhaxbbq+dvJttwLnGY+YixlXlME5KpQ5W3CnXA5cVTneY3SPbPDRkcjMbifrwmFYcClgOZeg==", - "requires": { - "safe-buffer": "5.1.2" - } - }, "bdd-lazy-var": { "version": "2.6.1", "resolved": "https://registry.npmjs.org/bdd-lazy-var/-/bdd-lazy-var-2.6.1.tgz", @@ -10726,41 +10659,6 @@ } } }, - "morgan": { - "version": "1.10.0", - "resolved": "https://registry.npmjs.org/morgan/-/morgan-1.10.0.tgz", - "integrity": "sha512-AbegBVI4sh6El+1gNwvD5YIck7nSA36weD7xvIxG4in80j/UoK8AEGaWnnz8v1GxonMCltmlNs5ZKbGvl9b1XQ==", - "requires": { - "basic-auth": "~2.0.1", - "debug": "2.6.9", - "depd": "~2.0.0", - "on-finished": "~2.3.0", - "on-headers": "~1.0.2" - }, - "dependencies": { - "debug": { - "version": "2.6.9", - "resolved": "https://registry.npmjs.org/debug/-/debug-2.6.9.tgz", - "integrity": "sha512-bC7ElrdJaJnPbAP+1EotYvqZsb3ecl5wi6Bfi6BJTUcNowp6cvspg0jXznRTKDjm/E7AdgFBVeAPVMNcKGsHMA==", - "requires": { - "ms": "2.0.0" - } - }, - "ms": { - "version": "2.0.0", - "resolved": "https://registry.npmjs.org/ms/-/ms-2.0.0.tgz", - "integrity": "sha512-Tpp60P6IUJDTuOq/5Z8cdskzJujfwqfOTkrwIwj7IRISpnkJnT6SyJ4PCPnGMoFjC9ddhal5KVIYtAt97ix05A==" - }, - "on-finished": { - "version": "2.3.0", - "resolved": "https://registry.npmjs.org/on-finished/-/on-finished-2.3.0.tgz", - "integrity": "sha512-ikqdkGAAyf/X/gPhXGvfgAytDZtDbr+bkNUJ0N9h5MI/dmdgCs3l6hoHrcUv41sRKew3jIwrp4qQDXiK99Utww==", - "requires": { - "ee-first": "1.1.1" - } - } - } - }, "ms": { "version": "2.1.3", "resolved": "https://registry.npmjs.org/ms/-/ms-2.1.3.tgz", @@ -10923,11 +10821,6 @@ "ee-first": "1.1.1" } }, - "on-headers": { - "version": "1.0.2", - "resolved": "https://registry.npmjs.org/on-headers/-/on-headers-1.0.2.tgz", - "integrity": "sha512-pZAE+FJLoyITytdqK0U5s+FIpjN0JP3OzFi/u8Rx+EV5/W+JTWGXG8xFzevE7AjBfDqHv/8vL8qQsIhHnqRkrA==" - }, "once": { "version": "1.4.0", "resolved": "https://registry.npmjs.org/once/-/once-1.4.0.tgz", diff --git a/package.json b/package.json index 059a8859..07744bdf 100644 --- a/package.json +++ b/package.json @@ -34,7 +34,6 @@ "jsonwebtoken": "^9.0.2", "lockfile": "^1.0.4", "mkdirp": "^1.0.4", - "morgan": "^1.10.0", "node-mocks-http": "^1.14.1", "pug": "^3.0.2", "winston": "^3.11.0", diff --git a/spec/account.spec.js b/spec/account.spec.js index 312c40c1..6f065f00 100644 --- a/spec/account.spec.js +++ b/spec/account.spec.js @@ -13,34 +13,40 @@ module.exports.shouldCreateDeleteAndReadAccounts = function () { after(async function () { this.timeout(10_000); - await this.store.deleteUser(this.username); + await this.store.deleteUser(this.username, new Set()); }); it('rejects a user with too short a name', async function () { const params = { username: 'aa', email: 'a@b.c', password: 'swordfish' }; - await expect(this.store.createUser(params)).to.be.rejectedWith(Error, /user\s?name/i); + const logNotes = new Set(); + await expect(this.store.createUser(params, logNotes)).to.be.rejectedWith(Error, /user\s?name/i); }); it('rejects creating a user with illegal characters in username', async function () { const params = { username: this.username + '\\q', email: 'a@b.c', password: 'swordfish' }; - await expect(this.store.createUser(params)).to.be.rejectedWith(Error, /user\s?name/i); + const logNotes = new Set(); + await expect(this.store.createUser(params, logNotes)).to.be.rejectedWith(Error, /user\s?name/i); }); it('rejects creating a user with bad email', async function () { const params = { username: this.username + 'j', email: 'a@b', password: 'swordfish' }; - await expect(this.store.createUser(params)).to.be.rejectedWith(Error, /email/i); + const logNotes = new Set(); + await expect(this.store.createUser(params, logNotes)).to.be.rejectedWith(Error, /email/i); }); it('rejects creating a user without password', async function () { const params = { username: this.username + 'h', email: 'a@b.c', password: '' }; - await expect(this.store.createUser(params)).to.be.rejectedWith(Error, /password/i); + const logNotes = new Set(); + await expect(this.store.createUser(params, logNotes)).to.be.rejectedWith(Error, /password/i); }); it('creates a user & rejects creating a new user with an existing name', async function () { const params1 = { username: this.username, email: 'a@b.c', password: 'swordfish' }; - await expect(this.store.createUser(params1)).to.eventually.eql(this.username + this.USER_NAME_SUFFIX); + const logNotes1 = new Set(); + await expect(this.store.createUser(params1, logNotes1)).to.eventually.eql(this.username + this.USER_NAME_SUFFIX); const params2 = { username: this.username, email: 'd@e.f', password: 'iloveyou' }; - await expect(this.store.createUser(params2)).to.be.rejectedWith(Error, 'is already taken'); + const logNotes2 = new Set(); + await expect(this.store.createUser(params2, logNotes2)).to.be.rejectedWith(Error, 'is already taken'); }); }); @@ -51,15 +57,16 @@ module.exports.shouldCreateDeleteAndReadAccounts = function () { after(async function () { this.timeout(10_000); - await this.store.deleteUser(this.username2); + await this.store.deleteUser(this.username2, new Set()); }); it('deletes a user', async function () { this.timeout(10_000); const params = { username: this.username2, email: 'a@b.c', password: 'swordfish' }; - await expect(this.store.createUser(params)).to.eventually.eql(this.username2 + this.USER_NAME_SUFFIX); - const result = await this.store.deleteUser(this.username2); + const logNotes = new Set(); + await expect(this.store.createUser(params, logNotes)).to.eventually.eql(this.username2 + this.USER_NAME_SUFFIX); + const result = await this.store.deleteUser(this.username2, new Set()); await expect(result?.[0]).to.be.greaterThanOrEqual(2); await expect(result?.[1]).to.equal(0); }); @@ -74,17 +81,19 @@ module.exports.shouldCreateDeleteAndReadAccounts = function () { email: 'g@h.i', password: 'dictionary' }; - return this.store.createUser(goodParams); + return this.store.createUser(goodParams, new Set()); }); after(async function () { this.timeout(10_000); - return this.store.deleteUser(goodParams.username); + return this.store.deleteUser(goodParams.username, new Set()); }); it('throws a cagey error if the user does not exist', async function () { const badParams = { username: 'nonexisting', email: 'g@h.i', password: 'dictionary' }; - await expect(this.store.authenticate(badParams)).to.be.rejectedWith('Password and username do not match'); + const logNotes = new Set(); + await expect(this.store.authenticate(badParams, logNotes)).to.be.rejectedWith('Password and username do not match'); + expect(Array.from(logNotes)).to.include('attempt to log in with nonexistent user “nonexisting”'); }); it('throws a cagey error for a wrong password for an existing user', async function () { diff --git a/spec/modular/m_oauth.spec.js b/spec/modular/m_oauth.spec.js index 7abd59ec..222afac1 100644 --- a/spec/modular/m_oauth.spec.js +++ b/spec/modular/m_oauth.spec.js @@ -36,6 +36,10 @@ describe('OAuth (modular)', function () { this.app.set('view engine', 'html'); this.app.set('views', path.join(__dirname, '../../lib/views')); + this.app.use((_req, res, next) => { + res.logNotes = new Set(); + next(); + }); this.app.use(helmet({ contentSecurityPolicy: { directives: { diff --git a/spec/modular/m_storage_common.spec.js b/spec/modular/m_storage_common.spec.js index 00643208..2c961ece 100644 --- a/spec/modular/m_storage_common.spec.js +++ b/spec/modular/m_storage_common.spec.js @@ -111,6 +111,10 @@ describe('Storage (modular)', function () { this.hostIdentity = 'testhost'; this.app = express(); + this.app.use((_req, res, next) => { + res.logNotes = new Set(); + next(); + }); this.app.use('/storage', streamingStorageRouter(this.hostIdentity, JWT_SECRET)); this.app.use('/storage', mockStoreHandler); this.app.locals.title = 'Test Armadietto'; diff --git a/spec/storage_common.spec.js b/spec/storage_common.spec.js index 4df3187a..84ee738b 100644 --- a/spec/storage_common.spec.js +++ b/spec/storage_common.spec.js @@ -249,7 +249,7 @@ module.exports.shouldCrudBlobs = function () { it('does not tell the store to save a directory', async function () { const res = await put(this.app, '/storage/zebcoe/locog/seats/', this.good_token, 'a value'); expect(res).to.have.status(400); - expect(res.text).to.equal(''); + expect(res.text).to.match(/can't write to directory|^$/); expect(res).to.have.header('Access-Control-Allow-Origin', 'https://rs-app.com:2112'); }); diff --git a/spec/store_handler.spec.js b/spec/store_handler.spec.js index bed872c7..0d054fcc 100644 --- a/spec/store_handler.spec.js +++ b/spec/store_handler.spec.js @@ -48,6 +48,7 @@ module.exports.shouldStoreStreams = function () { const res = httpMocks.createResponse({ req }); res.req = req; req.res = res; + res.logNotes = new Set(); const next = chai.spy(err => { let status; if (err.Code === 'SlowDown') { @@ -66,12 +67,12 @@ module.exports.shouldStoreStreams = function () { }; this.username = 'automated-test-' + Math.round(Math.random() * Number.MAX_SAFE_INTEGER); - await this.store.createUser({ username: this.username, email: 'l@m.no', password: '12345678' }); + await this.store.createUser({ username: this.username, email: 'l@m.no', password: '12345678' }, new Set()); }); after(async function () { this.timeout(360_000); - await this.store.deleteUser(this.username); + await this.store.deleteUser(this.username, new Set()); }); describe('GET', function () { @@ -845,8 +846,7 @@ module.exports.shouldStoreStreams = function () { const [dirRes2] = await this.doHandle({ method: 'GET', url: `/${this.username}/photos/collection/` }); expect(dirRes2.statusCode).to.equal(409); expect(putRes2.get('ETag')).to.be.undefined; - expect(putRes2.get('Content-Type')).to.be.undefined; - expect(putRes2._getBuffer().toString()).to.equal(''); + expect(putRes2._getData()).to.match(/existing document/); const [getRes] = await this.doHandle({ method: 'GET', url: `/${this.username}/photos/collection` }); expect(getRes.statusCode).to.equal(200); diff --git a/spec/store_handlers/S3_store_handler.spec.js b/spec/store_handlers/S3_store_handler.spec.js index 9a71062a..70ba6f0d 100644 --- a/spec/store_handlers/S3_store_handler.spec.js +++ b/spec/store_handlers/S3_store_handler.spec.js @@ -23,7 +23,8 @@ describe('S3 store handler', function () { describe('createUser (S3-specific)', function () { it('rejects a user with too long a name for the user name suffix', async function () { const params = { username: 'a-------10--------20--------30--------40-', email: 'a@b.c', password: 'swordfish' }; - await expect(this.store.createUser(params)).to.be.rejectedWith(Error, '3–40 characters long'); + const logNotes = new Set(); + await expect(this.store.createUser(params, logNotes)).to.be.rejectedWith(Error, '3–40 characters long'); }); }); diff --git a/spec/util/LongStream.js b/spec/util/LongStream.js index 4376e1a7..d4f1b739 100644 --- a/spec/util/LongStream.js +++ b/spec/util/LongStream.js @@ -14,9 +14,7 @@ module.exports = class LongStream extends Readable { this.total += 100; const numberStr = this.total.toLocaleString(); line = line.slice(0, -numberStr.length) + numberStr; - if (this.total % 1_000_000 === 0) { - console.log(line); - } + // if (this.total % 1_000_000 === 0) { console.log(line); } this.push(line, 'utf8'); if (this.total >= this.limit) { this.push(null);