Skip to content

Instantly share code, notes, and snippets.

@martinheidegger
Last active July 20, 2017 01:30
Show Gist options
  • Star 1 You must be signed in to star a gist
  • Fork 0 You must be signed in to fork a gist
  • Save martinheidegger/4c2b7908005f65f9a53b25d5fec65f63 to your computer and use it in GitHub Desktop.
Save martinheidegger/4c2b7908005f65f9a53b25d5fec65f63 to your computer and use it in GitHub Desktop.
An approach to debug promises that have not yet finished when the process is exited.
'use strict'
const DATE_MAX = (36 * 36 * 36 * 36 * 36) // Since we use base 36 this should give us 5 characters
const RANDOM_MAX = 100000
function createId () {
// ID consistent of a time aspect as well as a random aspect to make sure two Promises
return `${(Date.now() % DATE_MAX).toString(36)}-${(Math.random() * RANDOM_MAX | 0).toString(36)}`
}
function maxLines (max, input) {
var lines = String(input).split('\n')
if (lines.length > max) {
return `${lines.slice(0, max - 1).join('\n')}
... ${lines.length - max - 1} more lines ...`
}
return lines.join('\n')
}
const RUNNING = {}
function intercept (result, parent) {
result.thenHandler = 0
result._then = result.then
result.then = handler => {
result.thenHandler += 1
return result._then(data => {
var next = handler(data)
if (next instanceof Promise) {
return wrap(() => next, null, parent)
}
return next
})
}
result._catch = result.catch
result.catchHandler = 0
result.catch = handler => {
result.catchHandler += 1
return result._catch(err => {
var next = handler(err)
if (next instanceof Promise) {
return wrap(() => next, null, parent)
}
return next
})
}
return result
}
function wrap (initPromise, options, parent) {
const id = createId()
const stack = (new Error().stack).split('\n').slice(2).map((line) => line.trim())
var promise
try {
promise = initPromise(options, id)
if (!(promise instanceof Promise)) {
promise = Promise.resolve(promise)
}
} catch (e) {
promise = Promise.reject(e)
}
var result = promise
.catch(e => {
result.catchHandler = 0
delete RUNNING[id]
console.log(`DEBUG: Rejection ${e.stack || e}`)
return Promise.reject(e)
})
.then(res => {
result.thenHandler = 0
delete RUNNING[id]
return res
})
result.id = id
result.parent = parent
result.stack = stack
result.initPromise = initPromise
result.options = options
RUNNING[id] = result
return intercept(result, id)
}
process.on('exit', () => {
const ids = Object.keys(RUNNING)
if (ids.length > 0) {
if (ids.length === 1) {
console.log(`1 Promise is still unfullfilled!`)
} else {
console.log(`${ids.length} Promises are still unfullfilled!`)
}
ids.forEach((id) => {
var promise = RUNNING[id]
var ids = [id.toUpperCase()]
var parent = promise.parent
while (parent) {
ids.unshift(parent)
var running = RUNNING[parent]
parent = running && running.parent
}
var options = ''
if (promise.options) {
options = `
OPTIONS
${JSON.stringify(promise.options, null, 2).split('\n').join('\n ')}`
}
console.log(`--- (${ids.join(' / ')}) ---
${promise.stack.slice(0, 3).join('\n ')}
CODE
${maxLines(3, promise.initPromise.toString()).split('\n').join('\n ')}
${options}`)
if (promise.thenHandler > 1 || promise.catchhandler > 1) {
console.log(`
WARNING:
WARNING: There has been more than one then/catch handler attached to ${id.toUpperCase()}.
WARNING: This is indicative of a recursive Promise dependency.
WARNING:`)
}
console.log('---')
})
}
console.log()
})
exports.wrap = wrap
'use strict'
;(new Promise(() => {})).then(() => console.log('a executed'))
;(Promise.resolve('x')).then(() => console.log('b executed'))
//
// This will output "b executed". "a executed" will not be triggered because the first promise will be never resolved!
//
'use strict'
var debug = require('./debug-promise')
debug.wrap(() => new Promise(() => {})).then(() => console.log('a executed'))
debug.wrap(() => Promise.resolve('x')).then(() => console.log('b executed'))
//
// This will output something like:
//
// b executed
// 1 Promise is still unfullfilled!
// --- (V347P-M6K) ---
// at Object.<anonymous> (/debug-test2.js:5:7)
// at Module._compile (module.js:571:32)
// at Object.Module._extensions..js (module.js:580:10)
//
// CODE
// () => new Promise(() => {})
//
// ---
//
'use strict'
var all = {
a: ['b', 'c'],
b: ['d'],
c: ['a'], // <- recursive
d: []
}
var cache = {}
function getDeep (key) {
var promise = cache[key]
if (promise) {
return promise
}
console.log(`Examining ${key}`)
promise = new Promise((resolve, reject) => {
setImmediate(() => {
Promise.all(all[key].map(getDeep)).then(resolve).catch(reject)
})
})
cache[key] = promise
return promise
}
getDeep('a').then(allDeps => {
console.log(`All dependencies of 'a': ${allDeps}`)
}).catch(e => console.log(e.stack || e))
//
// This will output something like:
//
// Examining a
// Examining b
// Examining c
// Examining d
//
// Because at one point a waits on the result of a which means there
// is no background process for the promise left running: the nodejs app closes
//
'use strict'
const debug = require('./debug-promise')
var all = {
a: ['b', 'c'],
b: ['d'],
c: ['a'], // <- recursive
d: []
}
var cache = {}
function getDeep (key) {
var promise = cache[key]
if (promise) {
return promise
}
console.log(`Examining ${key}`)
promise = debug.wrap(() => new Promise((resolve, reject) => {
setImmediate(() => {
Promise.all(all[key].map(getDeep)).then(resolve).catch(reject)
})
}))
cache[key] = promise
return promise
}
getDeep('a').then(allDeps => {
console.log(`All dependencies of 'a': ${allDeps}`)
}).catch(e => console.log(e.stack || e))
//
// This will output something like:
//
// Examining a
// Examining b
// Examining c
// Examining d
// 2 Promises are still unfullfilled!
// --- (VQCRD-POO) ---
// at getDeep (/debug-test4.js:20:19)
// at Object.<anonymous> (/debug-test4.js:29:1)
// at Module._compile (module.js:571:32)
//
// CODE
// () => new Promise((resolve, reject) => {
// setImmediate(() => {
// ... 1 more lines ...
//
//
// WARNING:
// WARNING: There has been more than one then/catch handler attached to VQCRD-POO.
// WARNING: This is indicative of a recursive Promise dependency.
// WARNING:
// ---
// --- (VQCRJ-UCQ) ---
// at getDeep (/debug-test-4.js:20:19)
// at Array.map (native)
// at Immediate.setImmediate (/debug-test-4.js:22:28)
//
// CODE
// () => new Promise((resolve, reject) => {
// setImmediate(() => {
// ... 1 more lines ...
//
// ---
//
// It is an uncommon case that a Promise has two "then" handler. This debug script checks how many handlers are attached and
// shows the error message. Usually it should be indicative and helpful when debugging.
//
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment