Tracking Static Asset Request Duration In Express.js And Node.js
I'm just starting to learn about using Express.js to build web applications in Node.js. As such, a lot of stuff that may be obvious to Express aficionados still leaves me scratching my head. For example, I was curious about how to track the request timing / duration of requests that were served-up using Express' static file server. Since the static files weren't attached to a particular route prefix, I didn't see how I could attach middleware specifically to those static asset requests. But, then it occurred to me: I don't have to care about how the request starts, I only need to care about how the request ends. And, in the end, I can differentiate between route and non-route requests.
As a request, in Express.js, is passed down through the tree of middleware handlers, both the Express framework and the individual middlewares each have an opportunity to augment and monkeypatch the various streams as they deem necessary. This means that at the end of a request, the properties on each stream represent the request's path through the application and its registered middleware.
We can see this behavior when it comes to routing. When Express matches a request to a registered route handler, it populates the request object with a "route" property. This means that at the end of the request processing, the existence of - or lack of - a "request.route" property will give us an indication of how the request flowed through the Express framework. If "request.route" exists, the request was handled by a route handler; if "request.route" is missing, the request was likely handled by the static server or, fell-through to the "not found" handler.
Given this request-based indicator, we can track static file request duration by simply tracking all request duration; then, when we go to calculate the request / response time delta, we can inspect the request object to see if it looks like it was handled by a route handler or, possibly, by the static file server.
To see this in action, I created a simple Express.js application in which the very first middleware is the request duration tracking. I am setting this up as the first middleware so that the rest of the request processing (such as body and cookie parsing) will be taken into account when calculating the overall duration. Notice that in the onFinished() callback, I'm inspecting the "request.route" property to shed some light on how the Express.js application routed the incoming request:
// Require our core node modules.
var bodyParser = require( "body-parser" );
var chalk = require( "chalk" );
var cookieParser = require( "cookie-parser" );
var express = require( "express" );
var onFinished = require( "on-finished" );
var path = require( "path" );
// ----------------------------------------------------------------------------------- //
// ----------------------------------------------------------------------------------- //
var app = module.exports = express();
// Setup the view-rendering engine.
app.set( "views", path.join( __dirname, "views" ) );
app.set( "view engine", "pug" );
// Setup the request timing as the first middleware. This way, it will take the entirety
// of the middleware stack (such as the request parsing) into account when calculating
// the request / response duration. Furthermore, since this isn't attached to a
// particular route, this middleware will be capable of recording the processing time
// for both Route and Non-Route requests (such as static assets and not-found responses).
app.use(
function applyTiming( request, response, next ) {
var startedAt = Date.now();
// This callback will be invoked exactly once, whether or not the underlying
// Response stream event is "finish", "close", "end", or "error".
// --
// NOTE: The "error" argument will only be defined for "close" and "error" events
// in the underlying stream.
// --
// CAUTION: Errors thrown in this callback will NOT BE CAUGHT by the Express
// server and may crash your process.
onFinished(
response,
function logRequestDuration( error ) {
var requestDuration = ( Date.now() - startedAt );
// Since we're starting the request tracking as the first middleware, we
// don't know if this request will match a route or a static asset. If
// the request ended up matching a route, the "route" property will exist
// by the time the request has completed.
if ( request.route ) {
// request.route.path.
console.log(
chalk.red.bold( "Route:" ),
chalk.red.italic( request.route.path ),
chalk.dim( "-", requestDuration, "ms" ),
chalk.dim( "[ HTTP", ( response.statusCode || "???" ), "]" )
);
// If there is no route, the request ended with either a static asset or
// fell-through to the "Not Found" middleware.
} else {
// request.path.
console.log(
chalk.red.bold( "Non-Route:" ),
chalk.red.italic( request.path ),
chalk.dim( "-", requestDuration, "ms" ) ,
chalk.dim( "[ HTTP", ( response.statusCode || "???" ), "]" )
);
}
}
);
next();
}
);
// Setup standard request parsing.
app.use( bodyParser.json() );
app.use(
bodyParser.urlencoded({
extended: false
})
);
app.use( cookieParser() );
// Setup route handler.
app.get(
"/",
function handleRoute( request, response, next ) {
response.locals.title = "Welcome";
response.render( "index" );
}
);
// Setup route handler.
app.get(
"/about",
function handleRoute( request, response, next ) {
response.locals.title = "About";
response.render( "about" );
}
);
// Setup the static-file server.
// --
// NOTE: I am setting it up as one of the last middleware since I only want it to look
// at the file-system if none of the routes matched.
app.use( express.static( path.join( __dirname, "public" ) ) );
// Setup our request fall-through (Not Found) handler. This will only get invoked when
// none of the previous middle-ware or route handlers finalized the response.
app.use(
function handleNotFound( request, response, next ) {
var error = new Error( "Not Found" );
error.status = 404;
throw( error );
}
);
// Setup our request error handler.
// --
// CAUTION: The error handler is denoted by FOUR arguments - do not remove any of the
// arguments in this method signature, even if they are not used.
app.use(
function handleError( error, request, response, next ) {
// Setup the template variables.
response.locals.error = error;
response.locals.message = error.message;
// Render the error template.
// --
// NOTE: It is a common practice for Express errors to contain the HTTP status
// code that should be used in the response.
response.status( error.status || 500 );
response.render( "error" );
}
);
The onFinished() binding doesn't care how the underlying stream was consumed, whether it resulted in a JSON response, a rendered HTML template response, or a static file server response. To the onFinished() utility, it's all just "stream events." This works in our favor because we also don't care how the request / response streams were consumed - we just care how long they took to consume, which is the delta between the first middleware and the shipping of the last byte to the client.
Now, in my request-duration middleware, I'm not exactly focusing on static file response. Rather, I'm differentiating between route and non-route responses. A non-route response doesn't necessarily mean the request was handled by the static file server (such as in the case of a Not Found handler). But, if the non-route request also ended with a "200 OK" or a "304 Not Modified", it could be a good indicator that it was handled by the static file server.
When we load this Express.js application and request a few pages in the browser, we get the following terminal output:
As you can see, our request tracking middleware is able to differentiate between the requests handled by the route-handlers and the requests handled by the static file server. Well, mostly. Not all of the non-route requests end up routing through the static file server. "Not Found" requests, for example, lack a "request.route" property but aren't static files; that said, we can always inspect the HTTP status code of the response to make an educated guess based on the rest of application configuration.
Now, we might not want to actually track all static file responses. But, we might want to track threshold responses. Meaning, we might want to log a static file requests that takes over 50ms to serve (for example). This could be an indication that the application is having file I/O problems or that the event loop is struggling to distribute processing effectively.
I'm basically on day 4 of Express.js learning. So, I'm in the process of building up a better mental model of how Express handles requests. This is the first time I've really dealt with a plugin / middleware based system. So, for me, it was not obvious how I might go about tracking the request duration of static file response. But, the more I wrap my head around middleware, the more clear this is becoming.
Want to use code from this post? Check out the license.
Reader Comments
Interesting exploration,
One of the good things (imho) about the Express model is that it is "modules all the way down" - so if you want to have a different approach for statics than default,
you either configure static a bit more ref https://github.com/expressjs/serve-static/blob/master/index.js
Or just replace it with another middleware for your use case (electricity, ...?)
@Atleb,
Yeah, it is pretty cool. I'm starting to get a better mental model for it. It's basically just a stack of Functions that can do whatever they want. The next thing I want to try and do is create a middleware that creates a more seamless mapping between routes and views to see how a view might be rendered implicitly rather than explicitly.
Just having fun with it :D