diff --git a/dev/u-wave-dev-server b/dev/u-wave-dev-server index 3d3bd258..7757229e 100755 --- a/dev/u-wave-dev-server +++ b/dev/u-wave-dev-server @@ -9,19 +9,17 @@ const announce = require('u-wave-announce'); const ytSource = require('u-wave-source-youtube'); const scSource = require('u-wave-source-soundcloud'); const recaptchaTestKeys = require('recaptcha-test-keys'); -const pino = require('pino'); +const debug = require('debug')('uwave:dev-server'); const dotenv = require('dotenv'); dotenv.config(); -const logger = pino({ level: 'trace' }); - const testTransport = { name: 'test', version: '0.0.0', send(mail, callback) { mail.message.createReadStream().pipe(concat((message) => { - logger.info('send test email', { to: mail.message.getEnvelope().to, contents: message.toString('utf8') }); + debug(mail.message.getEnvelope().to, message.toString('utf8')); callback(null, { envelope: mail.message.getEnvelope(), messageId: mail.message.messageId(), @@ -44,7 +42,6 @@ async function start() { port, redis: process.env.REDIS_URL, mongo: process.env.MONGODB_URL ?? 'mongodb://localhost/uwave', - logger, secret, mailTransport: testTransport, timeout: 10, @@ -79,10 +76,10 @@ async function start() { }); await uw.listen(); - logger.info('Now listening', { port }); + console.log(`Now listening on ${port}`); } start().catch((error) => { - logger.error(error); + console.error(error.stack); process.exit(1); }); diff --git a/package.json b/package.json index 23539951..ba4b5ec1 100644 --- a/package.json +++ b/package.json @@ -34,6 +34,7 @@ "cookie": "^0.5.0", "cookie-parser": "^1.4.4", "cors": "^2.8.5", + "debug": "^4.1.1", "escape-string-regexp": "^4.0.0", "explain-error": "^1.0.4", "express": "^4.17.1", @@ -54,8 +55,6 @@ "passport": "^0.5.0", "passport-google-oauth20": "^2.0.0", "passport-local": "^1.0.0", - "pino": "^7.11.0", - "pino-http": "^7.0.0", "qs": "^6.9.1", "random-string": "^0.2.0", "ratelimiter": "^3.4.0", @@ -76,6 +75,7 @@ "@types/cookie": "^0.5.0", "@types/cookie-parser": "^1.4.2", "@types/cors": "^2.8.10", + "@types/debug": "^4.1.5", "@types/express": "^4.17.11", "@types/has": "^1.0.0", "@types/htmlescape": "^1.1.1", @@ -102,6 +102,7 @@ "@typescript-eslint/parser": "^5.3.0", "c8": "^7.10.0", "concat-stream": "^2.0.0", + "cross-env": "^7.0.0", "delay": "^5.0.0", "dotenv": "^16.0.0", "eslint": "^8.2.0", @@ -112,7 +113,6 @@ "mocha": "^10.0.0", "nock": "^13.2.0", "nodemon": "^2.0.2", - "pino-colada": "^2.2.2", "recaptcha-test-keys": "^1.0.0", "sinon": "^14.0.0", "supertest": "^6.1.3", @@ -124,6 +124,6 @@ "test": "npm run tests-only && npm run lint", "tests-only": "c8 --reporter lcov --src src mocha --exit", "types": "tsc -p tsconfig.json", - "start": "nodemon dev/u-wave-dev-server | pino-colada" + "start": "cross-env DEBUG=uwave:* nodemon dev/u-wave-dev-server" } } diff --git a/src/HttpApi.js b/src/HttpApi.js index a200fd25..ac3c722c 100644 --- a/src/HttpApi.js +++ b/src/HttpApi.js @@ -1,13 +1,13 @@ 'use strict'; -const { randomUUID } = require('crypto'); +const { URL } = require('url'); const express = require('express'); const bodyParser = require('body-parser'); const cookieParser = require('cookie-parser'); const cors = require('cors'); const helmet = require('helmet').default; const http = require('http'); -const pinoHttp = require('pino-http').default; +const debug = require('debug')('uwave:http-api'); // routes const authenticate = require('./routes/authenticate'); @@ -82,8 +82,6 @@ async function httpApi(uw, options) { throw new TypeError('"options.onError" must be a function.'); } - const logger = uw.logger.child({ ns: 'uwave:http-api' }); - uw.config.register(optionsSchema['uw:key'], optionsSchema); /** @type {HttpApiSettings} */ @@ -95,17 +93,12 @@ async function httpApi(uw, options) { } }); - logger.debug('setup', runtimeOptions); + debug('setup', runtimeOptions); uw.httpApi = Object.assign(express.Router(), { authRegistry: new AuthRegistry(uw.redis), }); uw.httpApi - .use(pinoHttp({ - genReqId: () => randomUUID(), - quietReqLogger: true, - logger, - })) .use(bodyParser.json()) .use(cookieParser()) .use(uw.passport.initialize()) @@ -156,10 +149,10 @@ async function httpApi(uw, options) { * @param {import('./Uwave')} uw */ async function errorHandling(uw) { - uw.logger.debug('error handling', { name: 'httpApi' }); + debug('after'); uw.httpApi.use(errorHandler()); uw.express.use(/** @type {import('express').ErrorRequestHandler} */ (error, req, res, next) => { - uw.logger.error({ error, name: 'httpApi' }); + debug(error); next(error); }); } diff --git a/src/SocketServer.js b/src/SocketServer.js index e969d0c5..76942a11 100644 --- a/src/SocketServer.js +++ b/src/SocketServer.js @@ -6,6 +6,7 @@ const sjson = require('secure-json-parse'); const WebSocket = require('ws'); const Ajv = require('ajv').default; const ms = require('ms'); +const debug = require('debug')('uwave:api:sockets'); const { socketVote } = require('./controllers/booth'); const { disconnectUser } = require('./controllers/users'); const AuthRegistry = require('./AuthRegistry'); @@ -107,8 +108,6 @@ class SocketServer { #uw; - #logger; - #redisSubscription; #wss; @@ -166,7 +165,6 @@ class SocketServer { } this.#uw = uw; - this.#logger = uw.logger.child({ ns: 'uwave:sockets' }); this.#redisSubscription = uw.redis.duplicate(); this.options = { @@ -187,7 +185,7 @@ class SocketServer { }); this.#redisSubscription.subscribe('uwave', 'v1').catch((error) => { - this.#logger.error(error); + debug(error); }); this.#redisSubscription.on('message', (channel, command) => { // this returns a promise, but we don't handle the error case: @@ -198,8 +196,8 @@ class SocketServer { this.#wss.on('error', (error) => { this.onError(error); }); - this.#wss.on('connection', (socket, request) => { - this.onSocketConnected(socket, request); + this.#wss.on('connection', (socket) => { + this.onSocketConnected(socket); }); this.#pinger = setInterval(() => { @@ -208,13 +206,13 @@ class SocketServer { this.recountGuests = debounce(() => { this.recountGuestsInternal().catch((error) => { - this.#logger.error('counting guests failed', { error }); + debug('counting guests failed:', error); }); }, ms('2 seconds')); this.#clientActions = { sendChat: (user, message) => { - this.#logger.trace('sendChat', user, message); + debug('sendChat', user, message); this.#uw.chat.send(user, message); }, vote: (user, direction) => { @@ -477,11 +475,10 @@ class SocketServer { /** * @param {import('ws')} socket - * @param {import('http').IncomingMessage} request * @private */ - onSocketConnected(socket, request) { - this.#logger.info('new connection', { req: request }); + onSocketConnected(socket) { + debug('new connection'); socket.on('error', (error) => { this.onSocketError(socket, error); @@ -495,7 +492,7 @@ class SocketServer { * @private */ onSocketError(socket, error) { - this.#logger.warn('socket error', { error }); + debug('socket error:', error); this.options.onError(socket, error); } @@ -505,7 +502,7 @@ class SocketServer { * @private */ onError(error) { - this.#logger.error('server error', { error }); + debug('server error:', error); this.options.onError(undefined, error); } @@ -536,9 +533,10 @@ class SocketServer { this.remove(connection); }); connection.on('authenticate', async (user) => { + debug('connecting', user.id, user.username); const isReconnect = await connection.isReconnect(user); - this.#logger.info('authenticated socket', { userId: user.id, isReconnect }); if (isReconnect) { + debug('is reconnection'); const previousConnection = this.getLostConnection(user); if (previousConnection) this.remove(previousConnection); } @@ -564,11 +562,11 @@ class SocketServer { const connection = new AuthedConnection(this.#uw, socket, user); connection.on('close', ({ banned }) => { if (banned) { - this.#logger.info('removing connection after ban', { userId: user.id }); + debug('removing connection after ban', user.id, user.username); this.remove(connection); disconnectUser(this.#uw, user._id); } else { - this.#logger.info('lost connection', { userId: user.id }); + debug('lost connection', user.id, user.username); this.replace(connection, this.createLostConnection(user)); } }); @@ -579,7 +577,7 @@ class SocketServer { * @param {import('type-fest').JsonValue} data */ (command, data) => { - this.#logger.trace('command', { userId: user.id, command, data }); + debug('command', user.id, user.username, command, data); if (has(this.#clientActions, command)) { // Ignore incorrect input const validate = this.#clientActionSchemas[command]; @@ -606,7 +604,7 @@ class SocketServer { createLostConnection(user) { const connection = new LostConnection(this.#uw, user, this.options.timeout); connection.on('close', () => { - this.#logger.info('user left', { userId: user.id }); + debug('left', user.id, user.username); this.remove(connection); // Only register that the user left if they didn't have another connection // still open. @@ -624,8 +622,7 @@ class SocketServer { * @private */ add(connection) { - const userId = 'user' in connection ? connection.user.id : null; - this.#logger.trace('add connection', { type: connection.constructor.name, userId }); + debug('adding', String(connection)); this.#connections.push(connection); this.recountGuests(); @@ -638,8 +635,7 @@ class SocketServer { * @private */ remove(connection) { - const userId = 'user' in connection ? connection.user.id : null; - this.#logger.trace('remove connection', { type: connection.constructor.name, userId }); + debug('removing', String(connection)); const i = this.#connections.indexOf(connection); this.#connections.splice(i, 1); @@ -681,7 +677,7 @@ class SocketServer { } const { command, data } = json; - this.#logger.trace('server message', { channel, command, data }); + debug(channel, command, data); if (channel === 'v1') { this.broadcast(command, data); @@ -739,15 +735,10 @@ class SocketServer { * @param {import('type-fest').JsonValue} data Command data. */ broadcast(command, data) { - this.#logger.trace('broadcast', { - command, - data, - to: this.#connections.map((connection) => ( - 'user' in connection ? connection.user.id : null - )), - }); + debug('broadcast', command, data); this.#connections.forEach((connection) => { + debug(' to', connection.toString()); connection.send(command, data); }); } diff --git a/src/Uwave.js b/src/Uwave.js index 80c1fed8..54c08e38 100644 --- a/src/Uwave.js +++ b/src/Uwave.js @@ -4,8 +4,8 @@ const EventEmitter = require('events'); const { promisify } = require('util'); const mongoose = require('mongoose'); const Redis = require('ioredis').default; +const debug = require('debug'); const avvio = require('avvio'); -const { pino } = require('pino'); const httpApi = require('./HttpApi'); const SocketServer = require('./SocketServer'); @@ -43,7 +43,6 @@ const DEFAULT_REDIS_URL = 'redis://localhost:6379'; * port?: number, * mongo?: string, * redis?: string | RedisOptions, - * logger?: import('pino').Logger, * } & httpApi.HttpApiOptions} Options */ @@ -124,9 +123,6 @@ class UwaveServer extends EventEmitter { */ #sources = new Map(); - /** @type {import('pino').Logger} */ - #mongoLogger; - /** * @param {Options} options */ @@ -135,7 +131,6 @@ class UwaveServer extends EventEmitter { const boot = avvio(this); - this.logger = options.logger ?? pino(); this.locale = i18n.cloneInstance(); this.options = { @@ -152,7 +147,9 @@ class UwaveServer extends EventEmitter { this.redis = new Redis({ ...options.redis, lazyConnect: true }); } - this.#mongoLogger = this.logger.child({ ns: 'uwave:mongo' }); + this.log = debug('uwave:core'); + this.mongoLog = debug('uwave:core:mongo'); + this.redisLog = debug('uwave:core:redis'); this.configureRedis(); this.configureMongoose(); @@ -164,7 +161,7 @@ class UwaveServer extends EventEmitter { // Wait for the connections to be set up. boot.use(async () => { - this.#mongoLogger.debug('waiting for mongodb...'); + this.mongoLog('waiting for mongodb...'); await this.mongo.asPromise(); }); @@ -255,23 +252,18 @@ class UwaveServer extends EventEmitter { * @private */ configureRedis() { - const log = this.logger.child({ ns: 'uwave:redis' }); - - this.redis.on('error', (error) => { - log.error(error); - this.emit('redisError', error); - }); - this.redis.on('reconnecting', () => { - log.info('trying to reconnect...'); + this.redis.on('error', (e) => { + this.emit('redisError', e); }); + this.redis.on('reconnecting', () => this.redisLog('trying to reconnect...')); this.redis.on('end', () => { - log.info('disconnected'); + this.redisLog('disconnected'); this.emit('redisDisconnect'); }); this.redis.on('connect', () => { - log.info('connected'); + this.redisLog('connected'); this.emit('redisConnect'); }); } @@ -280,23 +272,23 @@ class UwaveServer extends EventEmitter { * @private */ configureMongoose() { - this.mongo.on('error', (error) => { - this.#mongoLogger.error(error); - this.emit('mongoError', error); + this.mongo.on('error', (e) => { + this.mongoLog(e); + this.emit('mongoError', e); }); this.mongo.on('reconnected', () => { - this.#mongoLogger.info('reconnected'); + this.mongoLog('reconnected'); this.emit('mongoReconnect'); }); this.mongo.on('disconnected', () => { - this.#mongoLogger.info('disconnected'); + this.mongoLog('disconnected'); this.emit('mongoDisconnect'); }); this.mongo.on('connected', () => { - this.#mongoLogger.info('connected'); + this.mongoLog('connected'); this.emit('mongoConnect'); }); } diff --git a/src/controllers/authenticate.js b/src/controllers/authenticate.js index 4419be9a..8f6116b4 100644 --- a/src/controllers/authenticate.js +++ b/src/controllers/authenticate.js @@ -2,6 +2,7 @@ const { URLSearchParams } = require('url'); const cookie = require('cookie'); +const debug = require('debug')('uwave:http:auth'); const jwt = require('jsonwebtoken'); const randomString = require('random-string'); const fetch = require('node-fetch').default; @@ -287,10 +288,10 @@ async function getSocketToken(req) { /** * @param {string} responseString - * @param {{ secret: string, logger?: import('pino').Logger }} options + * @param {Required['recaptcha']} options */ async function verifyCaptcha(responseString, options) { - options.logger?.info('recaptcha: sending siteverify request'); + debug('recaptcha: sending siteverify request'); const response = await fetch('https://www.google.com/recaptcha/api/siteverify', { method: 'post', headers: { @@ -305,10 +306,10 @@ async function verifyCaptcha(responseString, options) { const body = await response.json(); if (!body.success) { - options.logger?.warn('recaptcha: validation failure', body); + debug('recaptcha: validation failure', body); throw new ReCaptchaError(); } else { - options.logger?.info('recaptcha: ok'); + debug('recaptcha: ok'); } } @@ -333,12 +334,8 @@ async function register(req) { const recaptchaOptions = req.authOptions.recaptcha; if (recaptchaOptions && recaptchaOptions.secret) { if (grecaptcha) { - await verifyCaptcha(grecaptcha, { - secret: recaptchaOptions.secret, - logger: req.log, - }); + await verifyCaptcha(grecaptcha, recaptchaOptions); } else { - req.log.warn('missing client-side captcha response'); throw new ReCaptchaError(); } } diff --git a/src/controllers/now.js b/src/controllers/now.js index 6e9eca60..310393e7 100644 --- a/src/controllers/now.js +++ b/src/controllers/now.js @@ -1,5 +1,6 @@ 'use strict'; +const debug = require('debug')('uwave:http-api:now'); const { ObjectId } = require('mongoose').mongo; const { getBoothData } = require('./booth'); const { @@ -91,16 +92,16 @@ async function getState(req) { if (activePlaylist != null) { activePlaylist = activePlaylist .then((playlist) => playlist?.id) - .catch((error) => { + .catch((err) => { // If the playlist was not found, our database is inconsistent. A deleted or nonexistent // playlist should never be listed as the active playlist. Most likely this is not the // user's fault, so we should not error out on `/api/now`. Instead, pretend they don't have // an active playlist at all. Clients can then let them select a new playlist to activate. - if (error.code === 'NOT_FOUND' || error.code === 'playlist-not-found') { - req.log.warn('The active playlist does not exist', { error }); + if (err.code === 'NOT_FOUND' || err.code === 'playlist-not-found') { + debug('The active playlist does not exist', err); return null; } - throw error; + throw err; }); } diff --git a/src/controllers/search.js b/src/controllers/search.js index 7d490fe8..00eb0cd2 100644 --- a/src/controllers/search.js +++ b/src/controllers/search.js @@ -1,5 +1,6 @@ 'use strict'; +const debug = require('debug')('uwave:http:search'); const { isEqual } = require('lodash'); const { SourceNotFoundError } = require('../errors'); const toListResponse = require('../utils/toListResponse'); @@ -18,7 +19,7 @@ async function searchAll(req) { const sourceNames = uw.sources.map((source) => source.type); const searches = uw.sources.map((source) => ( source.search(user, query).catch((error) => { - req.log.warn(error, { name: 'search' }); + debug(error); // Default to empty search on failure, for now. return []; }) @@ -40,7 +41,7 @@ async function searchAll(req) { async function updateSourceData(uw, updates) { const { Media } = uw.models; const ops = []; - uw.logger.debug('updating source data', { name: 'search', forMedia: [...updates.keys()] }); + debug('updating source data', [...updates.keys()]); for (const [id, sourceData] of updates.entries()) { ops.push({ updateOne: { @@ -110,7 +111,7 @@ async function search(req) { // don't wait for this to complete updateSourceData(uw, mediasNeedSourceDataUpdate).catch((error) => { - uw.logger.error('sourceData update failed', { name: 'search', error }); + debug('sourceData update failed', error); }); // Only include related playlists if requested @@ -119,7 +120,7 @@ async function search(req) { mediasInSearchResults.map((media) => media._id), { author: user._id }, ).catch((error) => { - uw.logger.error('playlists containing media lookup failed', { name: 'search', error }); + debug('playlists containing media lookup failed', error); // just omit the related playlists if we timed out or crashed return new Map(); }); diff --git a/src/controllers/users.js b/src/controllers/users.js index 97ff43d6..c91163cf 100644 --- a/src/controllers/users.js +++ b/src/controllers/users.js @@ -1,5 +1,6 @@ 'use strict'; +const createDebug = require('debug'); const { HTTPError, PermissionError, @@ -14,6 +15,8 @@ const toPaginatedResponse = require('../utils/toPaginatedResponse'); const beautifyDuplicateKeyError = require('../utils/beautifyDuplicateKeyError'); const { muteUser, unmuteUser } = require('./chat'); +const debug = createDebug('uwave:http:users'); + /** * @typedef {object} GetUsersQuery * @prop {string} filter @@ -29,6 +32,8 @@ async function getUsers(req) { }); const { users } = req.uwave; + debug('getUsers', filter, pagination); + const userList = await users.getUsers(filter, pagination); return toPaginatedResponse(userList, { diff --git a/src/middleware/errorHandler.js b/src/middleware/errorHandler.js index 1f6853f4..f950875b 100644 --- a/src/middleware/errorHandler.js +++ b/src/middleware/errorHandler.js @@ -1,11 +1,14 @@ 'use strict'; +const createDebug = require('debug'); const { APIError, CombinedError, RateLimitError, } = require('../errors'); +const debug = createDebug('uwave:http:error'); + /** * @typedef {object} SerializedError * @prop {number} status @@ -34,6 +37,8 @@ function serializeError(err) { return err.errors.flatMap((error) => serializeError(error)); } + debug(err); + if (err instanceof APIError) { return [{ status: err.status ?? 500, diff --git a/src/plugins/acl.js b/src/plugins/acl.js index 7bb343a9..af3c5bb0 100644 --- a/src/plugins/acl.js +++ b/src/plugins/acl.js @@ -1,5 +1,6 @@ 'use strict'; +const debug = require('debug')('uwave:acl'); const defaultRoles = require('../config/defaultRoles'); const routes = require('../routes/acl'); @@ -23,23 +24,20 @@ const SUPER_ROLE = '*'; class Acl { #uw; - #logger; - /** * @param {import('../Uwave')} uw */ constructor(uw) { this.#uw = uw; - this.#logger = uw.logger.child({ ns: 'uwave:acl' }); } async maybeAddDefaultRoles() { const { AclRole } = this.#uw.models; const existingRoles = await AclRole.estimatedDocumentCount(); - this.#logger.debug('existing roles', { roles: existingRoles }); + debug('existing roles', existingRoles); if (existingRoles === 0) { - this.#logger.info('no roles found, adding defaults'); + debug('no roles found, adding defaults'); for (const [roleName, permissions] of Object.entries(defaultRoles)) { // eslint-disable-next-line no-await-in-loop await this.createRole(roleName, permissions); @@ -212,16 +210,10 @@ class Acl { } const userRoles = await this.getSubRoles(user.roles.map(getRoleName)); - const isAllowed = userRoles.includes(role.id) || userRoles.includes(SUPER_ROLE); - this.#logger.trace('user allowed check', { - userId: user.id, - roleId: role.id, - userRoles, - isAllowed, - }); + debug('role ids', userRoles, 'check', user.id, role.id, 'super', SUPER_ROLE); - return isAllowed; + return userRoles.includes(role.id) || userRoles.includes(SUPER_ROLE); } } diff --git a/src/plugins/booth.js b/src/plugins/booth.js index e1139491..8580baf9 100644 --- a/src/plugins/booth.js +++ b/src/plugins/booth.js @@ -2,6 +2,7 @@ const assert = require('assert'); const RedLock = require('redlock').default; +const createDebug = require('debug'); const { omit } = require('lodash'); const { EmptyPlaylistError, PlaylistItemNotFoundError } = require('../errors'); const routes = require('../routes/booth'); @@ -20,6 +21,8 @@ const routes = require('../routes/booth'); * & PopulateUser & PopulatePlaylist & PopulateMedia} PopulatedHistoryEntry */ +const debug = createDebug('uwave:advance'); + /** * @param {Playlist} playlist * @returns {Promise} @@ -35,8 +38,6 @@ async function cyclePlaylist(playlist) { class Booth { #uw; - #logger; - /** @type {ReturnType|null} */ #timeout = null; @@ -48,7 +49,6 @@ class Booth { constructor(uw) { this.#uw = uw; this.#locker = new RedLock([this.#uw.redis]); - this.#logger = uw.logger.child({ ns: 'uwave:booth' }); } /** @internal */ @@ -309,9 +309,9 @@ class Booth { const { sourceID, sourceType } = entry.media.media; const source = this.#uw.source(sourceType); if (source) { - this.#logger.trace('running pre-play hook', { sourceType: source.type, sourceID }); + debug('Running %s pre-play hook for %s', source.type, sourceID); const sourceData = await source.play(entry.user, entry.media.media); - this.#logger.trace('pre-play hook result', { sourceType: source.type, sourceID, sourceData }); + debug('sourceData', sourceData); return sourceData; } @@ -347,7 +347,7 @@ class Booth { // If the next user's playlist was empty, remove them from the waitlist // and try advancing again. if (err.code === 'PLAYLIST_IS_EMPTY') { - this.#logger.info('user has empty playlist, skipping on to the next'); + debug('user has empty playlist, skipping on to the next'); await this.cycleWaitlist(previous, opts); return this.advance({ ...opts, remove: true }, lock); } @@ -357,22 +357,18 @@ class Booth { if (previous) { await this.saveStats(previous); - this.#logger.info('previous track stats', { - id: previous._id, - artist: previous.media.artist, - title: previous.media.title, - upvotes: previous.upvotes.length, - favorites: previous.favorites.length, - downvotes: previous.downvotes.length, - }); + debug( + 'previous track:', + previous.media.artist, + '—', + previous.media.title, + `👍 ${previous.upvotes.length} ` + + `★ ${previous.favorites.length} ` + + `👎 ${previous.downvotes.length}`, + ); } if (next) { - this.#logger.info('next track', { - id: next._id, - artist: next.media.artist, - title: next.media.title, - }); const sourceData = await this.getSourceDataForPlayback(next); if (sourceData) { next.media.sourceData = sourceData; diff --git a/src/plugins/migrations.js b/src/plugins/migrations.js index 65570e55..ffe3dd14 100644 --- a/src/plugins/migrations.js +++ b/src/plugins/migrations.js @@ -3,6 +3,14 @@ const path = require('path'); const RedLock = require('redlock').default; const { Umzug } = require('umzug'); +const debug = require('debug')('uwave:migrate'); + +/** + * @type {import('umzug').LogFn} + */ +function log(record) { + debug(record.event, record.name || record.path || record); +} /** * @typedef {import('../Uwave')} Uwave @@ -65,7 +73,14 @@ async function migrationsPlugin(uw) { migrations, context: uw, storage: mongooseStorage, - logger: uw.logger.child({ ns: 'uwave:migrations' }), + logger: { + // Only `info` is used right now. When Umzug actually implements the warn/error + // levels we could pass in different logging functions. + debug: log, + info: log, + warn: log, + error: log, + }, }); await redLock.using(['migrate'], 10000, async () => { diff --git a/src/plugins/passport.js b/src/plugins/passport.js index ead662d6..b1f4840c 100644 --- a/src/plugins/passport.js +++ b/src/plugins/passport.js @@ -4,6 +4,7 @@ const { Passport } = require('passport'); const { Strategy: LocalStrategy } = require('passport-local'); const { Strategy: GoogleStrategy } = require('passport-google-oauth20'); const { callbackify } = require('util'); +const debug = require('debug')('uwave:passport'); const JWTStrategy = require('../auth/JWTStrategy'); const schema = require('../schemas/socialAuth.json'); @@ -28,8 +29,6 @@ const schema = require('../schemas/socialAuth.json'); class PassportPlugin extends Passport { #uw; - #logger; - /** * @param {import('../Uwave')} uw * @param {{ secret: Buffer|string }} options @@ -38,7 +37,6 @@ class PassportPlugin extends Passport { super(); this.#uw = uw; - this.#logger = uw.logger.child({ ns: 'uwave:authentication' }); /** * @param {Express.User} user @@ -97,7 +95,7 @@ class PassportPlugin extends Passport { this.applyAuthStrategies(settings); } catch (error) { // The schema doesn't _quite_ protect against all possible misconfiguration - this.#logger.error('applying social auth settings failed', { error }); + debug('applying social auth settings failed', error); } } @@ -140,11 +138,11 @@ class PassportPlugin extends Passport { * @private */ applyAuthStrategies(settings) { - this.#logger.info('reapplying settings'); + debug('reapplying settings'); this.unuse('google'); if (settings && settings.google && settings.google.enabled) { - this.#logger.info('enable google'); + debug('enable google'); this.use('google', new GoogleStrategy({ callbackURL: '/auth/service/google/callback', ...settings.google, @@ -159,6 +157,7 @@ class PassportPlugin extends Passport { * @param {{ secret: Buffer|string }} options */ async function passportPlugin(uw, options) { + debug('setup'); uw.passport = new PassportPlugin(uw, options); await uw.passport.loadRuntimeConfiguration(); } diff --git a/src/plugins/playlists.js b/src/plugins/playlists.js index a558c61d..33cd7371 100644 --- a/src/plugins/playlists.js +++ b/src/plugins/playlists.js @@ -2,6 +2,7 @@ const { groupBy, shuffle } = require('lodash'); const escapeStringRegExp = require('escape-string-regexp'); +const debug = require('debug')('uwave:playlists'); const { PlaylistNotFoundError, PlaylistItemNotFoundError, @@ -84,14 +85,11 @@ function toPlaylistItem(itemProps, media) { class PlaylistsRepository { #uw; - #logger; - /** * @param {import('../Uwave')} uw */ constructor(uw) { this.#uw = uw; - this.#logger = uw.logger.child({ ns: 'uwave:playlists' }); } /** @@ -155,7 +153,7 @@ class PlaylistsRepository { // If this is the user's first playlist, immediately activate it. if (user.activePlaylist == null) { - this.#logger.info('activating first playlist', { userId: user.id, playlistId: playlist.id }); + debug(`activating first playlist for ${user.id} ${user.username}`); user.activePlaylist = playlist._id; await user.save(); } diff --git a/src/plugins/users.js b/src/plugins/users.js index af846f37..cb20d1fd 100644 --- a/src/plugins/users.js +++ b/src/plugins/users.js @@ -1,6 +1,7 @@ 'use strict'; const bcrypt = require('bcryptjs'); +const debug = require('debug')('uwave:users'); const escapeStringRegExp = require('escape-string-regexp'); const Page = require('../Page'); const { IncorrectPasswordError, UserNotFoundError } = require('../errors'); @@ -26,14 +27,11 @@ function getDefaultAvatar(user) { class UsersRepository { #uw; - #logger; - /** * @param {import('../Uwave')} uw */ constructor(uw) { this.#uw = uw; - this.#logger = uw.logger.child({ ns: 'uwave:users' }); } /** @@ -176,7 +174,7 @@ class UsersRepository { }) { const { User, Authentication } = this.#uw.models; - this.#logger.info('find or create social', { type, id }); + debug('find or create social', type, id); // we need this type assertion because the `user` property actually contains // an ObjectId in this return value. We are definitely filling in a User object @@ -244,7 +242,7 @@ class UsersRepository { }) { const { User, Authentication } = this.#uw.models; - this.#logger.info('create user', { username, email: email.toLowerCase() }); + debug('create user', username, email.toLowerCase()); const hash = await encryptPassword(password); @@ -318,7 +316,7 @@ class UsersRepository { const user = await this.getUser(id); if (!user) throw new UserNotFoundError({ id }); - this.#logger.info('update user', { userId: user.id, update }); + debug('update user', user.id, user.username, update); const moderator = options && options.moderator; diff --git a/src/sockets/AuthedConnection.js b/src/sockets/AuthedConnection.js index 15bb3d74..353aead9 100644 --- a/src/sockets/AuthedConnection.js +++ b/src/sockets/AuthedConnection.js @@ -3,11 +3,12 @@ const EventEmitter = require('events'); const Ultron = require('ultron'); const WebSocket = require('ws'); +const createDebug = require('debug'); const sjson = require('secure-json-parse'); -class AuthedConnection extends EventEmitter { - #logger; +const debug = createDebug('uwave:api:sockets:authed'); +class AuthedConnection extends EventEmitter { /** * @param {import('../Uwave')} uw * @param {import('ws')} socket @@ -19,7 +20,6 @@ class AuthedConnection extends EventEmitter { this.socket = socket; this.events = new Ultron(this.socket); this.user = user; - this.#logger = uw.logger.child({ ns: 'uwave:sockets', connectionType: 'AuthedConnection', userId: this.user.id }); this.events.on('close', () => { this.emit('close', { banned: this.banned }); @@ -54,7 +54,11 @@ class AuthedConnection extends EventEmitter { } /** @type {string[]} */ const messages = await this.uw.redis.lrange(this.messagesKey, 0, -1); - this.#logger.info('queued messages', { count: messages.length }); + if (messages.length) { + debug('queued', this.user.id, this.user.username, ...messages); + } else { + debug('no queued messages', this.user.id, this.user.username); + } messages.forEach((message) => { const { command, data } = sjson.parse(message); this.send(command, data); @@ -90,14 +94,14 @@ class AuthedConnection extends EventEmitter { } ban() { - this.#logger.info('ban'); + debug('ban', this.toString()); this.banned = true; this.send('error', 'You have been banned'); this.socket.close(4001, 'ban'); } close() { - this.#logger.info('close'); + debug('close', this.toString()); this.socket.close(); } diff --git a/src/sockets/GuestConnection.js b/src/sockets/GuestConnection.js index da39be97..ded39436 100644 --- a/src/sockets/GuestConnection.js +++ b/src/sockets/GuestConnection.js @@ -2,10 +2,11 @@ const EventEmitter = require('events'); const Ultron = require('ultron'); +const createDebug = require('debug'); -class GuestConnection extends EventEmitter { - #logger; +const debug = createDebug('uwave:api:sockets:guest'); +class GuestConnection extends EventEmitter { /** * @param {import('../Uwave')} uw * @param {import('ws')} socket @@ -16,7 +17,6 @@ class GuestConnection extends EventEmitter { this.uw = uw; this.socket = socket; this.options = options; - this.#logger = uw.logger.child({ ns: 'uwave:sockets', connectionType: 'GuestConnection', userId: null }); this.events = new Ultron(socket); @@ -86,7 +86,7 @@ class GuestConnection extends EventEmitter { } close() { - this.#logger.info('close'); + debug('close'); this.socket.close(); } diff --git a/src/sockets/LostConnection.js b/src/sockets/LostConnection.js index 586f54a3..76ef1da2 100644 --- a/src/sockets/LostConnection.js +++ b/src/sockets/LostConnection.js @@ -1,10 +1,11 @@ 'use strict'; const EventEmitter = require('events'); +const createDebug = require('debug'); -class LostConnection extends EventEmitter { - #logger; +const debug = createDebug('uwave:api:sockets:lost'); +class LostConnection extends EventEmitter { /** * @param {import('../Uwave')} uw * @param {import('../models').User} user @@ -14,7 +15,6 @@ class LostConnection extends EventEmitter { this.uw = uw; this.user = user; this.timeout = timeout; - this.#logger = uw.logger.child({ ns: 'uwave:sockets', connectionType: 'LostConnection', userId: this.user.id }); this.initQueued(); this.setTimeout(timeout); @@ -66,7 +66,7 @@ class LostConnection extends EventEmitter { * @param {import('type-fest').JsonValue} data */ send(command, data) { - this.#logger.info('queue command', { command, data }); + debug('queueing', command, data); this.uw.redis.rpush( this.messagesKey, @@ -75,7 +75,7 @@ class LostConnection extends EventEmitter { } close() { - this.#logger.info('close'); + debug('close', this.toString()); this.emit('close'); }