Revert "use pino (#517)"

This reverts commit 0a431ae.
u-wave · May 20, 2022 · 24b2cfe · 24b2cfe
1 parent 00858ec
commit 24b2cfe
Show file tree

Hide file tree

Showing 19 changed files with 142 additions and 158 deletions.
diff --git 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
@@ -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
@@ -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
@@ -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);
     });
   }