32 logging (#1870)

* pino enabled, still need to fix logging behavior though * fix flow errors * pino support seems to be working * one minor fix for %s strings. Closes #32 * fix some error logging in pubsub + remove hapi-pino
okTurtles · Feb 28, 2024 · 65b1874 · 65b1874
1 parent 67891d4
commit 65b1874
Show file tree

Hide file tree

Showing 11 changed files with 1,041 additions and 503 deletions.
diff --git a/Gruntfile.js b/Gruntfile.js
@@ -417,7 +417,7 @@ module.exports = (grunt) => {
     const fork2 = function () {
       grunt.log.writeln('backend: forking...')
       child = fork(backendIndex, process.argv, {
-        env: process.env,
+        env: { NODE_ENV, ...process.env },
         execArgv: ['--require', '@babel/register']
       })
       child.on('error', (err) => {

diff --git a/backend/database-sqlite.js b/backend/database-sqlite.js
@@ -39,7 +39,7 @@ export async function initStorage (options: Object = {}): Promise<void> {
     })
   })
   await run('CREATE TABLE IF NOT EXISTS Data(key TEXT NOT NULL PRIMARY KEY, value TEXT NOT NULL)')
-  console.log('Connected to the %s SQLite database.', filename)
+  console.info(`Connected to the ${filename} SQLite database.`)
   readStatement = db.prepare('SELECT value FROM Data WHERE key = ?')
   writeStatement = db.prepare('REPLACE INTO Data(key, value) VALUES(?, ?)')
 }

diff --git a/backend/database.js b/backend/database.js
@@ -61,7 +61,7 @@ sbp('sbp/selectors/register', {
             this.push(null)
           }
         } catch (e) {
-          console.error(`read(): ${e.message}:`, e)
+          console.error(e, `read(): ${e.message}`)
           this.push(']')
           this.push(null)
         }
@@ -94,7 +94,7 @@ sbp('sbp/selectors/register', {
           }
         } catch (e) {
           // TODO: properly return an error to caller, see https://nodejs.org/api/stream.html#errors-while-reading
-          console.error(`read(): ${e.message}:`, e)
+          console.error(e, `read(): ${e.message}:`)
           this.push(']')
           this.push(null)
         }
@@ -132,7 +132,7 @@ sbp('sbp/selectors/register', {
           }
         } catch (e) {
           // TODO: properly return an error to caller, see https://nodejs.org/api/stream.html#errors-while-reading
-          console.error(`read(): ${e.message}:`, e)
+          console.error(e, `read(): ${e.message}:`)
           this.push(']')
           this.push(null)
         }
@@ -227,7 +227,7 @@ export default async () => {
     let numVisitedKeys = 0
     let numNewKeys = 0
 
-    console.log('[chelonia.db] Preloading...')
+    console.info('[chelonia.db] Preloading...')
     for (const key of keys) {
       // Skip keys which are already in the DB.
       if (!persistence || !await sbp('chelonia/db/get', key)) {
@@ -240,10 +240,10 @@ export default async () => {
       }
       numVisitedKeys++
       if (numVisitedKeys % Math.floor(numKeys / 10) === 0) {
-        console.log(`[chelonia.db] Preloading... ${numVisitedKeys / Math.floor(numKeys / 10)}0% done`)
+        console.info(`[chelonia.db] Preloading... ${numVisitedKeys / Math.floor(numKeys / 10)}0% done`)
       }
     }
-    numNewKeys && console.log(`[chelonia.db] Preloaded ${numNewKeys} new entries`)
+    numNewKeys && console.info(`[chelonia.db] Preloaded ${numNewKeys} new entries`)
   }
   await initZkpp()
 }
diff --git a/backend/index.js b/backend/index.js
@@ -6,27 +6,69 @@ import '@sbp/okturtles.events'
 import { SERVER_RUNNING } from './events.js'
 import { PUBSUB_INSTANCE } from './instance-keys.js'
 import chalk from 'chalk'
+import pino from 'pino'
 
-global.logger = function (err) {
-  console.error(err)
-  err.stack && console.error(err.stack)
-  return err // routes.js is written in a way that depends on this returning the error
+// NOTE: enabling pretty print does add a slight bit of overhead to logging and therefore is not recommended in production
+// Learn more about the Pino API here: https://github.com/pinojs/pino/blob/master/docs/api.md
+const prettyPrint = process.env.NODE_ENV === 'development' || process.env.CI || process.env.CYPRESS_RECORD_KEY || process.env.PRETTY
+// support regular console.log('asdf', 'adsf', 'adsf') style logging that might be used by libraries
+// https://github.com/pinojs/pino/blob/master/docs/api.md#interpolationvalues-any
+function logMethod (args, method) {
+  const stringIdx = typeof args[0] === 'string' ? 0 : 1
+  if (args.length > 1) {
+    for (let i = stringIdx + 1; i < args.length; ++i) {
+      args[stringIdx] += typeof args[i] === 'string' ? ' %s' : ' %o'
+    }
+  }
+  method.apply(this, args)
+}
+const logger = pino(prettyPrint
+  ? {
+      hooks: { logMethod },
+      transport: {
+        target: 'pino-pretty',
+        options: {
+          colorize: true
+        }
+      }
+    }
+  : { hooks: { logMethod } })
+
+const logLevel = process.env.LOG_LEVEL || (prettyPrint ? 'debug' : 'info')
+if (Object.keys(logger.levels.values).includes(logLevel)) {
+  logger.level = logLevel
+} else {
+  logger.warn(`Unknown log level: ${logLevel}`)
 }
 
+global.logger = logger // $FlowExpectedError
+console.debug = logger.debug.bind(logger) // $FlowExpectedError
+console.info = logger.info.bind(logger) // $FlowExpectedError
+console.log = logger.info.bind(logger) // $FlowExpectedError
+console.warn = logger.warn.bind(logger) // $FlowExpectedError
+console.error = logger.error.bind(logger)
+
+console.info('NODE_ENV =', process.env.NODE_ENV)
+
 const dontLog = { 'backend/server/broadcastEntry': true }
 
-function logSBP (domain, selector, data) {
+function logSBP (domain, selector, data: Array<*>) {
   if (!dontLog[selector]) {
-    console.log(chalk.bold(`[sbp] ${selector}`), data)
+    if (selector === 'backend/server/handleEntry') {
+      console.debug(chalk.bold(`[sbp] ${selector}`), data[0].description())
+    } else {
+      console.debug(chalk.bold(`[sbp] ${selector}`), data)
+    }
   }
 }
 
 ;['backend'].forEach(domain => sbp('sbp/filters/domain/add', domain, logSBP))
+// any specific selectors outside of backend namespace to log
 ;[].forEach(sel => sbp('sbp/filters/selector/add', sel, logSBP))
 
 module.exports = (new Promise((resolve, reject) => {
   sbp('okTurtles.events/on', SERVER_RUNNING, function () {
-    console.log(chalk.bold('backend startup sequence complete.'))
+    console.info(chalk.bold('backend startup sequence complete.'))
     resolve()
   })
   // call this after we've registered listener for SERVER_RUNNING
@@ -35,17 +77,17 @@ module.exports = (new Promise((resolve, reject) => {
 
 const shutdownFn = function (message) {
   sbp('okTurtles.data/apply', PUBSUB_INSTANCE, function (pubsub) {
-    console.log('message received in child, shutting down...', message)
+    console.info('message received in child, shutting down...', message)
     pubsub.on('close', async function () {
       try {
         await sbp('backend/server/stop')
-        console.log('Hapi server down')
+        console.info('Hapi server down')
         // await db.stop()
-        // console.log('database stopped')
+        // console.info('database stopped')
         process.send({}) // tell grunt we've successfully shutdown the server
         process.nextTick(() => process.exit(0)) // triple-check we quit :P
       } catch (err) {
-        console.error('Error during shutdown:', err)
+        console.error(err, 'Error during shutdown')
         process.exit(1)
       }
     })
@@ -63,12 +105,12 @@ process.on('SIGUSR2', shutdownFn)
 process.on('message', shutdownFn)
 
 process.on('uncaughtException', (err) => {
-  console.error('[server] Unhandled exception:', err, err.stack)
+  console.error(err, '[server] Unhandled exception')
   process.exit(1)
 })
 
 process.on('unhandledRejection', (reason, p) => {
-  console.error('[server] Unhandled promise rejection:', p, 'reason:', reason)
+  console.error(reason, '[server] Unhandled promise rejection:', reason)
   process.exit(1)
 })
 

diff --git a/backend/pubsub.js b/backend/pubsub.js
@@ -44,10 +44,10 @@ const generateSocketID = (() => {
   return (debugID) => String(counter++) + (debugID ? '-' + debugID : '')
 })()
 
-const log = console.log.bind(console, tag)
-log.bold = (...args) => console.log(bold(tag, ...args))
-log.debug = console.debug.bind(console, tag)
-log.error = (...args) => console.error(bold.red(tag, ...args))
+const log = logger.info.bind(logger, tag)
+log.bold = (...args) => logger.debug(bold(tag, ...args))
+log.debug = logger.debug.bind(logger, tag)
+log.error = (error, ...args) => logger.error(error, bold.red(tag, ...args))
 
 // ====== API ====== //
 
@@ -175,21 +175,20 @@ const defaultServerHandlers = {
       socket.on(eventName, (...args) => {
         // Logging of 'message' events is handled in the default 'message' event handler.
         if (eventName !== 'message') {
-          log(`Event '${eventName}' on socket ${socket.id}`, ...args.map(arg => String(arg)))
+          log.debug(`Event '${eventName}' on socket ${socket.id}`, ...args.map(arg => String(arg)))
         }
         try {
           (defaultSocketEventHandlers: Object)[eventName]?.call(socket, ...args)
           socket.server.customSocketEventHandlers[eventName]?.call(socket, ...args)
         } catch (error) {
-          socket.server.emit('error', error)
+          socket.server.emit(error, 'error in socket connection')
           socket.terminate()
         }
       })
     })
   },
   error (error: Error) {
-    log.error('Server error:', error)
-    logger(error)
+    log.error(error, 'Server error')
   },
   headers () {
   },
@@ -221,13 +220,13 @@ const defaultSocketEventHandlers = {
     try {
       msg = messageParser(text)
     } catch (error) {
-      log.error(`Malformed message: ${error.message}`)
+      log.error(error, `Malformed message: ${error.message}`)
       server.rejectMessageAndTerminateSocket(msg, socket)
       return
     }
     // Now that we have successfully parsed the message, we can log it.
     if (msg.type !== 'pong' || server.options.logPongMessages) {
-      log(`Received '${msg.type}' on socket ${socket.id}`, text)
+      log.debug(`Received '${msg.type}' on socket ${socket.id}`, text)
     }
     // The socket can be marked as active since it just received a message.
     socket.activeSinceLastPing = true
@@ -238,7 +237,7 @@ const defaultSocketEventHandlers = {
         handler.call(socket, msg)
       } catch (error) {
         // Log the error message and stack trace but do not send it to the client.
-        logger(error)
+        log.error(error, 'onMesage')
         server.rejectMessageAndTerminateSocket(msg, socket)
       }
     } else {
@@ -282,7 +281,7 @@ const defaultMessageHandlers = {
       // Add this socket to the channel subscribers.
       server.subscribersByChannelID[channelID].add(socket)
     } else {
-      log('Already subscribed to', channelID)
+      log.debug('Already subscribed to', channelID)
     }
     socket.send(createOkResponse({ type: SUB, channelID }))
   },