Add event limits

Author: ehmicky

README.md

@@ -51,7 +51,9 @@ lead to conflicts between libraries. Libraries should use the
 [`-r log-process-errors` CLI flag](#usage-preferred) instead of
 [`require()`](#usage-custom).
 
-# Duplicate warnings
+# Duplicate events
+
+Duplicate events are only logged once.
 
 It is recommended to use the
 [`--no-warnings` CLI flag](https://nodejs.org/api/cli.html#cli_no_warnings) or

package-lock.json

@@ -43,7 +43,8 @@
   },
   "dependencies": {
     "chalk": "^2.4.1",
-    "jest-validate": "^23.6.0"
+    "jest-validate": "^23.6.0",
+    "moize": "^5.4.1"
   },
   "devDependencies": {
     "eslint": "^5.7.0",

package.json

@@ -1,6 +1,8 @@
 'use strict'
 
 const { getInfo } = require('./info')
+const { isLimited } = require('./limit')
+const { isRepeated } = require('./repeat')
 const { getColors } = require('./colors')
 const { getLevel } = require('./level')
 const { getMessage } = require('./message')
@@ -10,12 +12,17 @@ const { exitProcess } = require('./exit')
 const handleEvent = async function({
   opts,
   eventName,
+  previousEvents,
   error,
   promise,
   promiseValue,
   secondPromiseState,
   secondPromiseValue,
 }) {
+  if (isLimited({ previousEvents, eventName, error })) {
+    return
+  }
+
   const info = await getInfo({
     eventName,
     error,
@@ -25,10 +32,20 @@ const handleEvent = async function({
     secondPromiseValue,
   })
 
+  if (isRepeated({ info, previousEvents })) {
+    return
+  }
+
   if (opts.skipEvent(info)) {
     return
   }
 
+  await logEvent({ opts, info })
+
+  await exitProcess({ eventName, opts })
+}
+
+const logEvent = async function({ opts, info }) {
   const colors = getColors({ opts })
   const level = getLevel({ opts, info })
   const message = getMessage({ opts, info, level, colors })
@@ -39,8 +56,6 @@ const handleEvent = async function({
   // But there are some cases where it will not. In those cases, `opts.log()`
   // should be either synchronous or return a promise.
   await opts.log(message, level, info)
-
-  await exitProcess({ eventName, opts })
 }
 
 module.exports = {

src/handle.js

@@ -0,0 +1,54 @@
+'use strict'
+
+const { emitWarning } = require('process')
+
+const moize = require('moize').default
+
+// We only allow 100 events (per `eventName`) for the global process because:
+//   - process errors are exceptional and if more than 100 happen, this is
+//     probably due to some infinite recursion.
+//   - the `repeated` logic should prevent reaching the threshold
+//   - `previousEvents` might otherwise take too much memory and/or create a
+//     memory leak.
+//  - it prevents infinite recursions if
+//    `opts.log|getLevel|getMessage|skipEvent()` triggers itself an event.
+//    The `repeated` logic should prevent it most of the times, but it can still
+//    happen when `error` or `[second]promiseValue` is not an `Error` instance
+//    and contain dynamic content.
+const isLimited = function({ previousEvents, eventName, error }) {
+  if (isLimitedWarning({ eventName, error })) {
+    return
+  }
+
+  const isLimitedEvent = [...previousEvents].length >= MAX_EVENTS
+
+  if (isLimitedEvent) {
+    mEmitLimitedWarning(eventName)
+  }
+
+  return isLimitedEvent
+}
+
+const MAX_EVENTS = 1e2
+
+// Notify that limit has been reached with a `warning` event
+const emitLimitedWarning = function(eventName) {
+  emitWarning(ERROR_MESSAGE(eventName), ERROR_NAME, ERROR_CODE)
+}
+
+// The `warning` itself should not be skipped
+const isLimitedWarning = function({ eventName, error: { name, code } = {} }) {
+  return eventName === 'warning' && name === ERROR_NAME && code === ERROR_CODE
+}
+
+const ERROR_MESSAGE = eventName =>
+  `Cannot log more than ${MAX_EVENTS} '${eventName}' until process is restarted`
+const ERROR_NAME = 'LogProcessError'
+const ERROR_CODE = 'TooManyErrors'
+
+// Should only emit the warning once per `eventName`
+const mEmitLimitedWarning = moize(emitLimitedWarning)
+
+module.exports = {
+  isLimited,
+}

src/limit.js

@@ -0,0 +1,103 @@
+'use strict'
+
+const { inspect } = require('util')
+
+// Events with the same `info` are only logged once because:
+//  - it makes logs clearer
+//  - it prevents creating too much CPU load or too many microtasks
+//  - it prevents creating too many logs, which can be expensive if logs are
+//    hosted remotely
+//  - it prevents infinite recursions if
+//    `opts.log|getLevel|getMessage|skipEvent()` triggers itself an event
+//    (while still reporting that event once)
+const isRepeated = function({ info, previousEvents }) {
+  const fingerprint = getFingerprint({ info })
+
+  const isRepeatedEvent = previousEvents.has(fingerprint)
+
+  if (!isRepeatedEvent) {
+    previousEvents.add(fingerprint)
+  }
+
+  return isRepeatedEvent
+}
+
+// Serialize `info` into a short fingerprint
+const getFingerprint = function({ info }) {
+  const entries = INFO_PROPS.map(propName => serializeEntry({ info, propName }))
+  const infoA = Object.assign({}, ...entries)
+
+  const fingerprint = JSON.stringify(infoA)
+
+  // We truncate fingerprints to prevent consuming too much memory in case some
+  // `info` properties are huge.
+  // This introduces higher risk of false positives (see comment below).
+  // We do not hash as it would be too CPU-intensive if the value is huge.
+  const fingerprintA = fingerprint.slice(0, FINGERPRINT_MAX_LENGTH)
+  return fingerprintA
+}
+
+// We do not serialize `info.eventName` since this is already `eventName-wise`
+// Key order matters since fingerprint might be truncated: we serialize short
+// and non-dynamic values first.
+const INFO_PROPS = [
+  'secondPromiseState',
+  'promiseState',
+  'error',
+  'secondPromiseValue',
+  'promiseValue',
+]
+
+const FINGERPRINT_MAX_LENGTH = 1e4
+
+const serializeEntry = function({ info, propName }) {
+  const value = info[propName]
+
+  if (value === undefined) {
+    return
+  }
+
+  const valueA = serializeValue({ value })
+  return { [propName]: valueA }
+}
+
+const serializeValue = function({ value }) {
+  if (value instanceof Error) {
+    return serializeError({ error: value })
+  }
+
+  // We use `util.inspect()` instead of `JSON.stringify()` to support more
+  // types and circular references.
+  // `sorted` prevents the same event using different keys order from having
+  // a different fingerprint. It is only `Node.js 10` but is backward-compatible
+  // Big arrays, objects or buffers will be truncated, which makes this call
+  // less CPU-intensive and the result value smaller in memory. However it
+  // introduces higher risk of false positives (event being flagged as repeated
+  // even though it's different). Process errors should be exceptional, so this
+  // is ok.
+  return inspect(value, { sorted: true })
+}
+
+// We do not serialize `error.message` as it may contain dynamic values like
+// timestamps. This means errors are only `error.name` + `error.stack`, which
+// should be a good fingerprint.
+// Also we only keep first 10 callsites in case of infinitely recursive stack.
+const serializeError = function({ error: { name, stack } }) {
+  const stackA = filterErrorStack({ stack })
+  return `${name}\n${stackA}`
+}
+
+const filterErrorStack = function({ stack }) {
+  return stack
+    .split('\n')
+    .filter(line => STACK_TRACE_LINE_REGEXP.test(line))
+    .slice(0, STACK_TRACE_MAX_LENGTH)
+    .join('\n')
+}
+
+const STACK_TRACE_LINE_REGEXP = /^\s+at /u
+const STACK_TRACE_MAX_LENGTH = 10
+
+module.exports = {
+  isRepeated,
+}

src/repeat.js

@@ -21,7 +21,17 @@ const addListeners = function({ opts }) {
 }
 
 const addListener = function({ opts, eventName, eventFunc }) {
-  const eventListener = eventFunc.bind(null, { opts, eventName })
+  // `previousEvents` is `eventName`-specific so that if events of a given
+  // `eventName` stopped being emitted, others still are.
+  // `previousEvents` can take up some memory, but it should be cleaned up
+  // by `removeListener()`, i.e. once `eventListener` is garbage collected.
+  const previousEvents = new Set()
+
+  const eventListener = eventFunc.bind(null, {
+    opts,
+    eventName,
+    previousEvents,
+  })
   process.on(eventName, eventListener)
 
   return { eventListener, eventName }