-
-
Notifications
You must be signed in to change notification settings - Fork 124
feat: add request layer lifecycle TracingChannels #196
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
base: master
Are you sure you want to change the base?
Changes from 13 commits
95e23ba
858399c
9f1aea7
dea81ae
1f6bc25
1ad1b9c
28b3213
90ed7e2
758030e
9c9b4a7
67c3851
6aa0575
5e80078
da0da14
8fd857f
337e212
232143b
10a47bc
cc5deb7
9aa666a
04b2f72
97da6d8
583c8c4
d0d8f7e
File filter
Filter by extension
Conversations
Jump to
Diff view
Diff view
There are no files selected for viewing
| Original file line number | Diff line number | Diff line change | ||||
|---|---|---|---|---|---|---|
|
|
@@ -400,6 +400,56 @@ router.route('/pet/:id') | |||||
| server.listen(8080) | ||||||
| ``` | ||||||
|
|
||||||
| ## Diagnostics | ||||||
|
|
||||||
| `router` integrates with Node.js [`diagnostics_channel`](https://nodejs.org/api/diagnostics_channel.html) | ||||||
| via a [`TracingChannel`](https://nodejs.org/api/diagnostics_channel.html#class-tracingchannel) | ||||||
| named `express.router.request`. This lets observability tools (APMs, tracers, | ||||||
| loggers) hook into middleware and route handler execution without monkey-patching. | ||||||
|
|
||||||
| Each layer's handler invocation publishes the standard tracing channel sub-events | ||||||
| (`start`, `end`, `asyncStart`, `asyncEnd`, `error`). The published context object | ||||||
| contains: | ||||||
|
|
||||||
| - `req`: the incoming `http.IncomingMessage` | ||||||
| - `res`: the `http.ServerResponse` | ||||||
| - `layer`: the internal `Layer` instance being invoked (exposes `.name`, `.path`, `.handle`, etc.). Note that `Layer` is an internal implementation detail and its shape may change between releases. | ||||||
| - `error`: the error passed to `next(err)`, when applicable | ||||||
| - `handled`: `true` when the layer is an error-handling middleware (4-arg signature) | ||||||
|
Member
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. I think we should rename it to something like
Suggested change
Author
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. That's fair, the clearer the better I suppose. Maybe |
||||||
|
|
||||||
| The `error` event is also published when a handler calls `next(err)` with a real | ||||||
| error. The control-flow sentinels `'route'` and `'router'` are not treated as | ||||||
| errors and will not publish to the `error` channel. | ||||||
|
|
||||||
| When no subscribers are attached, tracing is bypassed entirely, so there is no | ||||||
| context allocation or channel publishing overhead on the hot path. | ||||||
|
|
||||||
| ```js | ||||||
| const dc = require('node:diagnostics_channel') | ||||||
|
|
||||||
| const channel = dc.tracingChannel('express.router.request') | ||||||
|
|
||||||
| channel.subscribe({ | ||||||
| start (ctx) { | ||||||
| ctx.startTime = process.hrtime.bigint() | ||||||
| }, | ||||||
| end (ctx) { | ||||||
| // do whatever you need on synchronous completion | ||||||
| }, | ||||||
| asyncStart (ctx) { | ||||||
| // do whatever you need when the async portion begins | ||||||
| }, | ||||||
| asyncEnd (ctx) { | ||||||
| const durationNs = process.hrtime.bigint() - ctx.startTime | ||||||
| console.log('%s %s -> %s (%dns)', | ||||||
| ctx.req.method, ctx.req.url, ctx.layer.name, durationNs) | ||||||
| }, | ||||||
| error (ctx) { | ||||||
| console.error('handler error in %s:', ctx.layer.name, ctx.error) | ||||||
| } | ||||||
| }) | ||||||
| ``` | ||||||
|
|
||||||
| ## License | ||||||
|
|
||||||
| [MIT](LICENSE) | ||||||
|
|
||||||
| Original file line number | Diff line number | Diff line change |
|---|---|---|
|
|
@@ -12,6 +12,7 @@ | |
| * @private | ||
| */ | ||
|
|
||
| const dc = require('node:diagnostics_channel') | ||
| const isPromise = require('is-promise') | ||
| const pathRegexp = require('path-to-regexp') | ||
| const debug = require('debug')('router:layer') | ||
|
|
@@ -25,6 +26,20 @@ const deprecate = require('depd')('router') | |
| const TRAILING_SLASH_REGEXP = /\/+$/ | ||
| const MATCHING_GROUP_REGEXP = /\((?:\?<(.*?)>)?(?!\?)/g | ||
|
|
||
| /** | ||
| * TracingChannel setup. | ||
| * @private | ||
| */ | ||
|
|
||
| const requestChannel = dc.tracingChannel && dc.tracingChannel('express.router.request') | ||
|
|
||
| /** | ||
| * Check if the channel has subscribers. | ||
| */ | ||
| function shouldTrace (ch) { | ||
| return ch && ch.hasSubscribers !== false | ||
|
Member
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Since we support Node 18.0.0, users on those versions will get true, because (undefined !== false) === true. https://nodejs.org/api/diagnostics_channel.html#diagnostics_channeltracingchannelnameorchannels
Author
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Yep this is a trade off I suppose. I think we should then check for all channels own subscribers in that case. |
||
| } | ||
|
|
||
| /** | ||
| * Expose `Layer`. | ||
| */ | ||
|
|
@@ -111,23 +126,12 @@ Layer.prototype.handleError = function handleError (error, req, res, next) { | |
| return next(error) | ||
| } | ||
|
|
||
| try { | ||
| // invoke function | ||
| const ret = fn(error, req, res, next) | ||
|
|
||
| // wait for returned promise | ||
| if (isPromise(ret)) { | ||
| if (!(ret instanceof Promise)) { | ||
| deprecate('handlers that are Promise-like are deprecated, use a native Promise instead') | ||
| } | ||
|
|
||
| ret.then(null, function (error) { | ||
| next(error || new Error('Rejected promise')) | ||
| }) | ||
| } | ||
| } catch (err) { | ||
| next(err) | ||
| } | ||
| const layer = this | ||
| invokeWithTrace(function (wrappedNext) { | ||
| return fn(error, req, res, wrappedNext) | ||
| }, function () { | ||
| return { req, res, layer, error, handled: true } | ||
| }, next) | ||
|
logaretm marked this conversation as resolved.
Outdated
|
||
| } | ||
|
|
||
| /** | ||
|
|
@@ -147,16 +151,52 @@ Layer.prototype.handleRequest = function handleRequest (req, res, next) { | |
| return next() | ||
| } | ||
|
|
||
| try { | ||
| // invoke function | ||
| const ret = fn(req, res, next) | ||
| // Skip tracing for route dispatch wrappers (this.route is only set on | ||
| // the internal layer that calls route.dispatch). The actual user handlers | ||
| // inside the route are traced individually. | ||
| if (this.route) { | ||
| return invokeWithTrace(function (wrappedNext) { | ||
| return fn(req, res, wrappedNext) | ||
| }, null, next) | ||
| } | ||
|
|
||
| const layer = this | ||
| invokeWithTrace(function (wrappedNext) { | ||
| return fn(req, res, wrappedNext) | ||
| }, function () { | ||
| return { req, res, layer } | ||
| }, next) | ||
|
logaretm marked this conversation as resolved.
Outdated
|
||
| } | ||
|
|
||
| /** | ||
| * Invoke a handler function, optionally wrapping it in TracingChannel. | ||
| * The ctxFactory is only called when tracing is active, ensuring zero | ||
| * allocation overhead when no subscribers are registered. | ||
| * @private | ||
| */ | ||
|
|
||
| // wait for returned promise | ||
| if (isPromise(ret)) { | ||
| if (!(ret instanceof Promise)) { | ||
| deprecate('handlers that are Promise-like are deprecated, use a native Promise instead') | ||
| function invokeWithTrace (exec, ctxFactory, next) { | ||
| const tracing = ctxFactory && shouldTrace(requestChannel) | ||
| const ctx = tracing ? ctxFactory() : null | ||
| const wrappedNext = tracing | ||
| ? function (err) { | ||
| // 'route' and 'router' are control-flow sentinels (skip route / exit router), | ||
| // not real errors — don't pollute the error channel with them. | ||
| if (err && err !== 'route' && err !== 'router') { | ||
| ctx.error = err | ||
| // Explicitly publish the error to the error channel | ||
| requestChannel.error.publish(ctx) | ||
|
Member
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Okay, we have a small bug here. When there are mounted sub-routers, if an error occurs, the parent router ends up publishing a duplicate error event. For example: const http = require('node:http')
const dc = require('node:diagnostics_channel')
const Router = require('/home/bjohansebas/Dev/oss/pillarjs/router')
const errorEvents = []
dc.tracingChannel('express.router.request').subscribe({
error (ctx) {
errorEvents.push({
layer: ctx.layer && ctx.layer.name,
handled: !!ctx.handled,
message: ctx.error && ctx.error.message
})
}
})
function report (title) {
console.log('\n%s', title)
console.log(' error events published: %d %s', errorEvents.length,
errorEvents.length === 1 ? '(OK)' : '(BUG: should be exactly 1, on the origin layer)')
for (const e of errorEvents) {
console.log(' layer=%s handled=%s message=%j', e.layer, e.handled, e.message)
}
errorEvents.length = 0
}
async function run (router, path) {
const server = http.createServer(function (req, res) {
router(req, res, function (err) {
res.statusCode = err ? 500 : 404
res.end(String(err || 'not found'))
})
})
await new Promise(r => server.listen(0, r))
await fetch('http://localhost:' + server.address().port + path)
await new Promise(r => setImmediate(r))
server.close()
}
async function main () {
// Scenario A: mounted sub-router — a single next(err) in the inner handler,
// recovered by an outer error handler.
{
const outer = new Router()
const nested = new Router()
nested.get('/bar', function innerHandler (req, res, next) {
next(new Error('boom'))
})
outer.use('/foo', nested)
outer.use(function recover (err, req, res, next) { // eslint-disable-line no-unused-vars
res.statusCode = 500
res.end(err.message)
})
await run(outer, '/foo/bar')
report('Scenario A: nested router (1 mount level)')
}
// Scenario A2: two mount levels — the error is republished on EVERY ancestor.
{
const outer = new Router()
const mid = new Router()
const deep = new Router()
deep.get('/baz', function deepHandler (req, res, next) {
next(new Error('boom'))
})
mid.use('/bar', deep)
outer.use('/foo', mid)
outer.use(function recover (err, req, res, next) { // eslint-disable-line no-unused-vars
res.statusCode = 500
res.end(err.message)
})
await run(outer, '/foo/bar/baz')
report('Scenario A2: nested router (2 mount levels)')
}
// Scenario B: error handler that forwards the error with next(err).
{
const router = new Router()
router.get('/fail', function origin (req, res, next) {
next(new Error('boom'))
})
router.use(function forwardingHandler (err, req, res, next) {
next(err) // does not handle it, delegates to the next one
})
router.use(function recover (err, req, res, next) { // eslint-disable-line no-unused-vars
res.statusCode = 500
res.end(err.message)
})
await run(router, '/fail')
report('Scenario B: error handler forwarding with next(err)')
}
}
main()In principle, the error event should only be published once.
Author
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. That's a good catch. I will dedup the errors published in relation to the request object. |
||
| } | ||
| next(err) | ||
| } | ||
| : next | ||
|
|
||
| try { | ||
| const ret = tracing | ||
| ? requestChannel.tracePromise(function () { return handlePromise(exec(wrappedNext)) }, ctx) | ||
|
logaretm marked this conversation as resolved.
Outdated
logaretm marked this conversation as resolved.
Outdated
|
||
| : handlePromise(exec(wrappedNext)) | ||
|
|
||
| if (ret) { | ||
| ret.then(null, function (error) { | ||
| next(error || new Error('Rejected promise')) | ||
| }) | ||
|
|
@@ -166,6 +206,20 @@ Layer.prototype.handleRequest = function handleRequest (req, res, next) { | |
| } | ||
| } | ||
|
|
||
| /** | ||
| * If the return value is a promise, validate it and return it. | ||
| * @private | ||
| */ | ||
|
|
||
| function handlePromise (ret) { | ||
| if (isPromise(ret)) { | ||
| if (!(ret instanceof Promise)) { | ||
| deprecate('handlers that are Promise-like are deprecated, use a native Promise instead') | ||
| } | ||
| return ret | ||
| } | ||
| } | ||
|
|
||
| /** | ||
| * Check if this route matches `path`, if so | ||
| * populate `.params`. | ||
|
|
||
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
If someone did something like this, I know it's a very edge case, but it's still something we should fix since it's allowed by the way the router is designed:
the error event would still be emitted, so it wouldn't be limited to just
next(err). Even so, the request would still end up returning a200.There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
I added an exception for these routing signals, should be ignored now.