search

nodeshift / opossum-prometheus

Prometheus metrics for opossum circuit breakers
Apache License 2.0
21 stars 13 forks source link

Getting warning during circuit breaker usage "Warning: Possible perf_hooks memory leak detected." #65

Open abhinavgoel91 opened 2 years ago

abhinavgoel91 commented 2 years ago

Node.js Version: v8.12.0

Operating System: Mac OS 10.14.6

Steps to Produce Error:

  1. Create a new directory mkdir test
  2. cd into the new directory cd test
  3. check if node version is 8.12.0 nvm ls
  4. run npm init npm init, use defaults
  5. Install expressjs npm install --save express
  6. Install opposum npm install --save opossum
  7. Install opposum prometheus npm install --save opossum-prometheus
  8. create a new file circuit_breaker_metrics.js touch circuit_breaker_metrics.js
  9. Add the following content to circuit_breaker_metrics.js -
'use strict'

const PrometheusMetrics = require('opossum-prometheus')
var prometheus = new PrometheusMetrics()

class CircuitBreakerMetrics {
  static registerOpossumCustomMetrics (funcName, circuit) {
    prometheus.add(circuit);
    ['success', 'timeout', 'reject', 'open', 'halfOpen', 'close', 'fallback'].forEach(function (event) {
      circuit.on(event, (result) => {
        console.log(`OPOSSUM_EVENT api: ${funcName} event: ${event} result: ${JSON.stringify(result)}`)
      })
    })
  }
}

module.exports = CircuitBreakerMetrics
  1. Create a new file circuit_breaker_test.js touch circuit_breaker_test.js
  2. Add the following code to circuit_breaker_test.js -
'use strict'

const CircuitBreaker = require('opossum')
var CircuitBreakerMetrics = require('./circuit_breaker_metrics')

async function randomErrorAsync () {
  if (Math.random() < 0.3) {
    console.error('Throwing random error')
    throw new Error('random error')
  } else {
    console.log('Returning a string')
    return 'abcd'
  }
}

let config = {
  timeout: 3600000, // really high timeout
  errorThresholdPercentage: 20, // When 20% of requests fail, trip the circuit
  resetTimeout: 30000, // After 30 seconds, try again.
  rollingCountTimeout: 60, // total number of seconds for which the stats are being maintained,
  rollingCountBuckets: 10 // buckets value is the number of slots in the window
}

var testBreaker = new CircuitBreaker(randomErrorAsync, config)

console.log(`testBreaker = ${testBreaker}`)
CircuitBreakerMetrics.registerOpossumCustomMetrics('circuit_breaker_test', testBreaker)

testBreaker.fallback(function (result) {
  console.error(`result = ${result === undefined ? undefined : JSON.stringify(result)}`)

  if (result === null || result === undefined || result.code === undefined) {
    console.error(`returning new Error('CIRCUIT_BRK')`)
    throw new Error('CIRCUIT_BRK')
  } else {
    console.error(`returning new Error('${result.code}')`)
    throw new Error(result.code)
  }
})

module.exports.testBreaker = testBreaker

module.exports.middleware = function (req, res, next) {
  try {
    testBreaker.fire()
      .then(function (result) {
        res.json({
          'result': result
        })
      })
      .catch(function (err) {
        console.error(err)
        res.json({
          'error': err.message
        })
      })
  } catch (ex) {
    res.json({
      'error': ex
    })
  }
}

process.on('warning', e => console.warn(e.stack))
  1. Create a new file server.js touch server.js
  2. Add the following code to server.js -
'use strict'

const express = require('express')
const app = express()
const port = 3000
const CircuitBreakerTest = require('./circuit_breaker_test')

app.get('/circuit_breaker_test', CircuitBreakerTest.middleware)

app.listen(port, () => {
  console.log(`Example app listening on port ${port}`)
})
  1. Run the app node server.js
  2. Make requests to the app curl -XGET 'http://localhost:3000/circuit_breaker_test'
  3. The code is designed to intentionally trip the circuit breaker by throwing error 30% of the time. Make repeated requests and trip the circuit breaker.
  4. After about 6 minutes, you'll see the issue logs. Here's the request logs -

$ abhinavgoel in ~ 
➜ curl -XGET 'http://localhost:3000/circuit_breaker_test'
{"result":"abcd"}%

$ abhinavgoel in ~
➜ curl -XGET 'http://localhost:3000/circuit_breaker_test'
{"result":"abcd"}%

$ abhinavgoel in ~
➜ curl -XGET 'http://localhost:3000/circuit_breaker_test'
{"error":"CIRCUIT_BRK"}%

$ abhinavgoel in ~
➜ curl -XGET 'http://localhost:3000/circuit_breaker_test'
{"error":"EOPENBREAKER"}%

$ abhinavgoel in ~
➜ curl -XGET 'http://localhost:3000/circuit_breaker_test'
{"error":"EOPENBREAKER"}%

$ abhinavgoel in ~
➜ curl -XGET 'http://localhost:3000/circuit_breaker_test'
{"error":"EOPENBREAKER"}%

$ abhinavgoel in ~
➜ curl -XGET 'http://localhost:3000/circuit_breaker_test'
{"result":"abcd"}%
  1. Here are the application logs -
$ abhinavgoel in ~/Documents/repos/test  C:1
➜ node server.js
testBreaker = [object Object]
Example app listening on port 3000
Returning a string
OPOSSUM_EVENT api: circuit_breaker_test event: success result: "abcd"
Returning a string
OPOSSUM_EVENT api: circuit_breaker_test event: success result: "abcd"
Throwing random error
OPOSSUM_EVENT api: circuit_breaker_test event: open result: undefined
result = {}
returning new Error('CIRCUIT_BRK')
Error: CIRCUIT_BRK
    at Function.<anonymous> (/Users/abhinavgoel/Documents/repos/test/circuit_breaker_test.js:34:11)
    at fallback (/Users/abhinavgoel/Documents/repos/test/node_modules/opossum/lib/circuit.js:756:10)
    at handleError (/Users/abhinavgoel/Documents/repos/test/node_modules/opossum/lib/circuit.js:744:16)
    at promise.then.catch.error (/Users/abhinavgoel/Documents/repos/test/node_modules/opossum/lib/circuit.js:630:17)
    at <anonymous>
    at runMicrotasksCallback (internal/process/next_tick.js:122:5)
    at _combinedTickCallback (internal/process/next_tick.js:132:7)
    at process._tickCallback (internal/process/next_tick.js:181:9)
OPOSSUM_EVENT api: circuit_breaker_test event: reject result: {"code":"EOPENBREAKER"}
result = {"code":"EOPENBREAKER"}
returning new Error('EOPENBREAKER')
Error: EOPENBREAKER
    at Function.<anonymous> (/Users/abhinavgoel/Documents/repos/test/circuit_breaker_test.js:37:11)
    at fallback (/Users/abhinavgoel/Documents/repos/test/node_modules/opossum/lib/circuit.js:756:10)
    at CircuitBreaker.call (/Users/abhinavgoel/Documents/repos/test/node_modules/opossum/lib/circuit.js:574:14)
    at CircuitBreaker.fire (/Users/abhinavgoel/Documents/repos/test/node_modules/opossum/lib/circuit.js:499:22)
    at module.exports.middleware (/Users/abhinavgoel/Documents/repos/test/circuit_breaker_test.js:45:17)
    at Layer.handle [as handle_request] (/Users/abhinavgoel/Documents/repos/test/node_modules/express/lib/router/layer.js:95:5)
    at next (/Users/abhinavgoel/Documents/repos/test/node_modules/express/lib/router/route.js:137:13)
    at Route.dispatch (/Users/abhinavgoel/Documents/repos/test/node_modules/express/lib/router/route.js:112:3)
    at Layer.handle [as handle_request] (/Users/abhinavgoel/Documents/repos/test/node_modules/express/lib/router/layer.js:95:5)
    at /Users/abhinavgoel/Documents/repos/test/node_modules/express/lib/router/index.js:281:22
OPOSSUM_EVENT api: circuit_breaker_test event: reject result: {"code":"EOPENBREAKER"}
result = {"code":"EOPENBREAKER"}
returning new Error('EOPENBREAKER')
Error: EOPENBREAKER
    at Function.<anonymous> (/Users/abhinavgoel/Documents/repos/test/circuit_breaker_test.js:37:11)
    at fallback (/Users/abhinavgoel/Documents/repos/test/node_modules/opossum/lib/circuit.js:756:10)
    at CircuitBreaker.call (/Users/abhinavgoel/Documents/repos/test/node_modules/opossum/lib/circuit.js:574:14)
    at CircuitBreaker.fire (/Users/abhinavgoel/Documents/repos/test/node_modules/opossum/lib/circuit.js:499:22)
    at module.exports.middleware (/Users/abhinavgoel/Documents/repos/test/circuit_breaker_test.js:45:17)
    at Layer.handle [as handle_request] (/Users/abhinavgoel/Documents/repos/test/node_modules/express/lib/router/layer.js:95:5)
    at next (/Users/abhinavgoel/Documents/repos/test/node_modules/express/lib/router/route.js:137:13)
    at Route.dispatch (/Users/abhinavgoel/Documents/repos/test/node_modules/express/lib/router/route.js:112:3)
    at Layer.handle [as handle_request] (/Users/abhinavgoel/Documents/repos/test/node_modules/express/lib/router/layer.js:95:5)
    at /Users/abhinavgoel/Documents/repos/test/node_modules/express/lib/router/index.js:281:22
OPOSSUM_EVENT api: circuit_breaker_test event: reject result: {"code":"EOPENBREAKER"}
result = {"code":"EOPENBREAKER"}
returning new Error('EOPENBREAKER')
Error: EOPENBREAKER
    at Function.<anonymous> (/Users/abhinavgoel/Documents/repos/test/circuit_breaker_test.js:37:11)
    at fallback (/Users/abhinavgoel/Documents/repos/test/node_modules/opossum/lib/circuit.js:756:10)
    at CircuitBreaker.call (/Users/abhinavgoel/Documents/repos/test/node_modules/opossum/lib/circuit.js:574:14)
    at CircuitBreaker.fire (/Users/abhinavgoel/Documents/repos/test/node_modules/opossum/lib/circuit.js:499:22)
    at module.exports.middleware (/Users/abhinavgoel/Documents/repos/test/circuit_breaker_test.js:45:17)
    at Layer.handle [as handle_request] (/Users/abhinavgoel/Documents/repos/test/node_modules/express/lib/router/layer.js:95:5)
    at next (/Users/abhinavgoel/Documents/repos/test/node_modules/express/lib/router/route.js:137:13)
    at Route.dispatch (/Users/abhinavgoel/Documents/repos/test/node_modules/express/lib/router/route.js:112:3)
    at Layer.handle [as handle_request] (/Users/abhinavgoel/Documents/repos/test/node_modules/express/lib/router/layer.js:95:5)
    at /Users/abhinavgoel/Documents/repos/test/node_modules/express/lib/router/index.js:281:22
OPOSSUM_EVENT api: circuit_breaker_test event: halfOpen result: 30000
Returning a string
OPOSSUM_EVENT api: circuit_breaker_test event: close result: undefined
OPOSSUM_EVENT api: circuit_breaker_test event: success result: "abcd"
(node:79589) Warning: Possible perf_hooks memory leak detected. There are 151 entries in the Performance Timeline. Use the clear methods to remove entries that are no longer needed or set performance.maxEntries equal to a higher value (currently the maxEntries is 150).
Warning: Possible perf_hooks memory leak detected. There are 151 entries in the Performance Timeline. Use the clear methods to remove entries that are no longer needed or set performance.maxEntries equal to a higher value (currently the maxEntries is 150).
    at Performance.[index-entry] (perf_hooks.js:444:15)
    at Performance.[insert-entry] (perf_hooks.js:288:22)
    at process.observersCallback (perf_hooks.js:597:28)
(node:79589) Warning: Possible perf_hooks memory leak detected. There are 152 entries in the Performance Timeline. Use the clear methods to remove entries that are no longer needed or set performance.maxEntries equal to a higher value (currently the maxEntries is 150).
Warning: Possible perf_hooks memory leak detected. There are 152 entries in the Performance Timeline. Use the clear methods to remove entries that are no longer needed or set performance.maxEntries equal to a higher value (currently the maxEntries is 150).
    at Performance.[index-entry] (perf_hooks.js:444:15)
    at Performance.[insert-entry] (perf_hooks.js:288:22)
    at process.observersCallback (perf_hooks.js:597:28)
(node:79589) Warning: Possible perf_hooks memory leak detected. There are 153 entries in the Performance Timeline. Use the clear methods to remove entries that are no longer needed or set performance.maxEntries equal to a higher value (currently the maxEntries is 150).
Warning: Possible perf_hooks memory leak detected. There are 153 entries in the Performance Timeline. Use the clear methods to remove entries that are no longer needed or set performance.maxEntries equal to a higher value (currently the maxEntries is 150).
    at Performance.[index-entry] (perf_hooks.js:444:15)
    at Performance.[insert-entry] (perf_hooks.js:288:22)
    at process.observersCallback (perf_hooks.js:597:28)
(node:79589) Warning: Possible perf_hooks memory leak detected. There are 154 entries in the Performance Timeline. Use the clear methods to remove entries that are no longer needed or set performance.maxEntries equal to a higher value (currently the maxEntries is 150).
Warning: Possible perf_hooks memory leak detected. There are 154 entries in the Performance Timeline. Use the clear methods to remove entries that are no longer needed or set performance.maxEntries equal to a higher value (currently the maxEntries is 150).
    at Performance.[index-entry] (perf_hooks.js:444:15)
    at Performance.[insert-entry] (perf_hooks.js:288:22)
    at process.observersCallback (perf_hooks.js:597:28)

The above warning is confusing me. Is it because of some issue opposum or opposum-prometheus ?

abhinavgoel91 commented 2 years ago

Reading about NodeJS Performance Timeline, and searching for "perf_hooks" in the code I get this -

➜ grep -rn "perf_hooks" .
./node_modules/prom-client/lib/metrics/gc.js:4:let perf_hooks;
./node_modules/prom-client/lib/metrics/gc.js:8: perf_hooks = require('perf_hooks');
./node_modules/prom-client/lib/metrics/gc.js:17:kinds[perf_hooks.constants.NODE_PERFORMANCE_GC_MAJOR] = 'major';
./node_modules/prom-client/lib/metrics/gc.js:18:kinds[perf_hooks.constants.NODE_PERFORMANCE_GC_MINOR] = 'minor';
./node_modules/prom-client/lib/metrics/gc.js:19:kinds[perf_hooks.constants.NODE_PERFORMANCE_GC_INCREMENTAL] = 'incremental';
./node_modules/prom-client/lib/metrics/gc.js:20:kinds[perf_hooks.constants.NODE_PERFORMANCE_GC_WEAKCB] = 'weakcb';
./node_modules/prom-client/lib/metrics/gc.js:23:    if (!perf_hooks) {
./node_modules/prom-client/lib/metrics/gc.js:40:    const obs = new perf_hooks.PerformanceObserver(list => {
./node_modules/prom-client/lib/metrics/eventLoopLag.js:5:// Check if perf_hooks module is available
./node_modules/prom-client/lib/metrics/eventLoopLag.js:6:let perf_hooks;
./node_modules/prom-client/lib/metrics/eventLoopLag.js:9:   perf_hooks = require('perf_hooks');
./node_modules/prom-client/lib/metrics/eventLoopLag.js:18:// Reported only when perf_hooks is available.
./node_modules/prom-client/lib/metrics/eventLoopLag.js:80:  if (!perf_hooks || !perf_hooks.monitorEventLoopDelay) {
./node_modules/prom-client/lib/metrics/eventLoopLag.js:87:  const histogram = perf_hooks.monitorEventLoopDelay({

And searching for "prom-client" gives this -

➜ grep -rn "prom-client" .
./node_modules/tdigest/package.json:19:    "/prom-client"
./node_modules/tdigest/package.json:24:  "_where": "/Users/abhinavgoel/Documents/repos/test/node_modules/prom-client",
./node_modules/opossum-prometheus/test/prometheus-test.js:6:const client = require('prom-client');
./node_modules/opossum-prometheus/test/prometheus-test.js:64:test('The factory function uses a custom prom-client registry', async t => {
./node_modules/opossum-prometheus/index.js:3:const client = require('prom-client');
./node_modules/opossum-prometheus/README.md:45:[prom-client](https://github.com/siimon/prom-client) registry.
./node_modules/opossum-prometheus/README.md:48:The [default metrics](https://github.com/siimon/prom-client#default-metrics)
./node_modules/opossum-prometheus/README.md:54:const { Registry } = require('prom-client');
./node_modules/opossum-prometheus/package.json:31:    "prom-client": "^12.0.0"
./node_modules/prom-client/CHANGELOG.md:276:[unreleased]: https://github.com/siimon/prom-client/compare/v10.2.2...HEAD
./node_modules/prom-client/CHANGELOG.md:277:[10.2.2]: https://github.com/siimon/prom-client/compare/v10.2.1...v10.2.2
./node_modules/prom-client/CHANGELOG.md:278:[10.2.1]: https://github.com/siimon/prom-client/compare/v10.2.0...v10.2.1
./node_modules/prom-client/CHANGELOG.md:279:[10.2.0]: https://github.com/siimon/prom-client/compare/v10.1.1...v10.2.0
./node_modules/prom-client/CHANGELOG.md:280:[10.1.1]: https://github.com/siimon/prom-client/compare/v10.1.0...v10.1.1
./node_modules/prom-client/CHANGELOG.md:281:[10.1.0]: https://github.com/siimon/prom-client/compare/v10.0.4...v10.1.0
./node_modules/prom-client/CHANGELOG.md:282:[10.0.4]: https://github.com/siimon/prom-client/compare/v10.0.3...v10.0.4
./node_modules/prom-client/CHANGELOG.md:283:[10.0.3]: https://github.com/siimon/prom-client/compare/v10.0.2...v10.0.3
./node_modules/prom-client/CHANGELOG.md:284:[10.0.2]: https://github.com/siimon/prom-client/compare/v10.0.1...v10.0.2
./node_modules/prom-client/CHANGELOG.md:285:[10.0.1]: https://github.com/siimon/prom-client/compare/v10.0.0...v10.0.1
./node_modules/prom-client/CHANGELOG.md:286:[10.0.0]: https://github.com/siimon/prom-client/compare/v9.1.1...v10.0.0
./node_modules/prom-client/CHANGELOG.md:287:[9.1.1]: https://github.com/siimon/prom-client/compare/v9.1.0...v9.1.1
./node_modules/prom-client/CHANGELOG.md:288:[9.1.0]: https://github.com/siimon/prom-client/compare/v9.0.0...v9.1.0
./node_modules/prom-client/CHANGELOG.md:289:[9.0.0]: https://github.com/siimon/prom-client/commit/1ef835f908e1a5032f228bbc754479fe7ccf5201
./node_modules/prom-client/README.md:1:# Prometheus client for node.js [![Build Status](https://travis-ci.org/siimon/prom-client.svg?branch=master)](https://travis-ci.org/siimon/prom-client) [![Build status](https://ci.appveyor.com/api/projects/status/k2e0gwonkcee3lp9/branch/master?svg=true)](https://ci.appveyor.com/project/siimon/prom-client/branch/master) [![Actions Status](https://github.com/siimon/prom-client/workflows/Node.js%20CI/badge.svg?branch=master)](https://github.com/siimon/prom-client/actions)
./node_modules/prom-client/README.md:64:const client = require('prom-client');
./node_modules/prom-client/README.md:75:const client = require('prom-client');
./node_modules/prom-client/README.md:85:const client = require('prom-client');
./node_modules/prom-client/README.md:102:const client = require('prom-client');
./node_modules/prom-client/README.md:123:const client = require('prom-client');
./node_modules/prom-client/README.md:136:const client = require('prom-client');
./node_modules/prom-client/README.md:150:const client = require('prom-client');
./node_modules/prom-client/README.md:180:const client = require('prom-client');
./node_modules/prom-client/README.md:191:const client = require('prom-client');
./node_modules/prom-client/README.md:203:const client = require('prom-client');
./node_modules/prom-client/README.md:230:const client = require('prom-client');
./node_modules/prom-client/README.md:242:const client = require('prom-client');
./node_modules/prom-client/README.md:258:const client = require('prom-client');
./node_modules/prom-client/README.md:282:const client = require('prom-client');
./node_modules/prom-client/README.md:312:const client = require('prom-client');
./node_modules/prom-client/README.md:332:at `require('prom-client').register`). You can prevent this by setting last
./node_modules/prom-client/README.md:345:const client = require('prom-client');
./node_modules/prom-client/README.md:430:const client = require('prom-client');
./node_modules/prom-client/README.md:454:const client = require('prom-client');
./node_modules/prom-client/package.json:2:  "_from": "prom-client@^12.0.0",
./node_modules/prom-client/package.json:3:  "_id": "prom-client@12.0.0",
./node_modules/prom-client/package.json:6:  "_location": "/prom-client",
./node_modules/prom-client/package.json:11:    "raw": "prom-client@^12.0.0",
./node_modules/prom-client/package.json:12:    "name": "prom-client",
./node_modules/prom-client/package.json:13:    "escapedName": "prom-client",
./node_modules/prom-client/package.json:21:  "_resolved": "https://registry.npmjs.org/prom-client/-/prom-client-12.0.0.tgz",
./node_modules/prom-client/package.json:23:  "_spec": "prom-client@^12.0.0",
./node_modules/prom-client/package.json:29:    "url": "https://github.com/siimon/prom-client/issues"
./node_modules/prom-client/package.json:59:  "homepage": "https://github.com/siimon/prom-client",
./node_modules/prom-client/package.json:81:  "name": "prom-client",
./node_modules/prom-client/package.json:102:    "url": "git+ssh://git@github.com/siimon/prom-client.git"
./node_modules/prom-client/package.json:119:      "pkgid": "prom-client@12.0.0"
./node_modules/prom-client/lib/cluster.js:22:const GET_METRICS_REQ = 'prom-client:getMetricsReq';
./node_modules/prom-client/lib/cluster.js:23:const GET_METRICS_RES = 'prom-client:getMetricsRes';
./node_modules/prom-client/index.d.ts:1:// Type definitions for prom-client
./package-lock.json:261:        "prom-client": "^12.0.0"
./package-lock.json:274:    "prom-client": {
./package-lock.json:276:      "resolved": "https://registry.npmjs.org/prom-client/-/prom-client-12.0.0.tgz",

So it's the opposum-prometheus library which is using prom-client, which uses NodeJS Performance Timeline. Why is is this warning being printed? Because metrics haven't been collected from the timeline?

abhinavgoel91 commented 2 years ago

After reading this issue - https://github.com/siimon/prom-client/issues/429 & this issue - https://github.com/bfmatei/apollo-prometheus-exporter/issues/17

It's seems like something related to Node 8.