Tracking Page Request Metrics With Framework One (FW/1) And Lucee CFML
At work, we use StatsD to record page request metrics in our Lucee CFML and Framework One (FW/1) application. One of the great features of FW/1 is that it favors convention over configuration. This makes it simple in terms of getting started with the happy path; but, when it comes to recording request metrics, this flexibility creates a problem: unbounded metric cardinality. To work-around this, I have to reach under-the-hood and make a calculated trade-off in order to ensure that we only record metrics for valid end-points.
To set the context, every FW/1 request is driven by an "action" value. This action value determines which Subsystems, Sections, and Items get queued-up for Controller execution. So, for example, if I made the following request to a FW/1 application:
GET my.app/api:company.identification/id/4
... it would result in an "action" value of api:company.identification. This is reducible down to:
- Subsystem:
api - Section:
company - Item:
identification
When processing this request, FW/1 would then attempt to invoke the controller method:
/subsystems/api/controllers/company.cfc :: identification()
Now, because FW/1 is super flexible, this controller method doesn't actually need to exist. As long as there is a corresponding View template for this "action", the request will be satisfied. This means that, at the point that the Controller is executing, I can't really tell if the incoming request is going to result in a 404 Not Found error.
So, for example, if a malicious user made a request like:
GET my.app/foo:bar.baz
... I wouldn't be able to tell if the action, foo:bar.baz, was legitimate from within the Controller. I wouldn't be able to tell until the request either ended with a success or an error (due to a missing View template). This is problematic if I am attempting to record a StatsD metric for each incoming action. If I were to record foo:bar.baz, assuming it to be valid, I would open the door for an infinite number of StatsD metrics (which would be very expensive to store).
As an imperfect solution, I've made the compromise to only record StatsD metrics for actions that have a corresponding Controller method. This means that I won't record a StatsD metric for View-only requests; however, since Controller-based requests make up the vast majority of requests into our application, this seems good enough.
Unfortunately, FW/1 doesn't really expose information about which Controllers have been queued-up for execution. As such, I am reaching into the FW/1 internals and reading data that is not really "public". This is a bad thing; but, it's the only approach that I could figure out.
To do this, in the before() life-cycle method of the Application.cfc, I am inspecting the last queued-up Controller; and, if - and only if - the Controller has a method that corresponds to the .item portion of the Action, I will record a StatsD metric for it.
Here's a snippet of my Application.cfc ColdFusion component - notice that my tracking is managed by two methods, .recordRequestStart() and .recordRequestEnd(), called within the .before() and .after() application life-cycle methods, respectively:
public void function before( required struct rc ) {
rc.requestInitiatedAt = getTickCount();
rc.actionToTrack = getActionToTrack();
if ( rc.actionToTrack.len() ) {
getBeanFactory()
.getBean( "RequestMetricsService" )
.recordRequestStart( rc.actionToTrack )
;
}
}
public void function after( required struct rc ) {
if ( rc.actionToTrack.len() ) {
getBeanFactory()
.getBean( "RequestMetricsService" )
.recordRequestEnd( rc.actionToTrack, ( getTickCount() - rc.requestInitiatedAt ) )
;
}
}
// ---
// PRIVATE METHODS.
// ---
/**
* I return the action to track as part of the request-metrics tracking. Returns an
* empty-string if there is no action to track.
*/
private string function getActionToTrack() {
// NOTE: I'm using Try/Catch because I'm using a non-public API, which makes
// me nervous!
try {
// Get the last queued controller - this should be the controller that
// represents the actual request intent.
var lastController = request._fw1.controllers.last();
// Since FW1 uses convention over configuration, it allows the user to make
// requests to controller methods that don't exist. However, for the purposes
// of request tracking, we're only going to care about controllers that have
// a corresponding item handler.
// --
// NOTE: This will disregard any requests for View-Only end-points; but, we
// don't yet know if the view even exists at this point in the controller
// processing workflow.
if ( ! structKeyExists( lastController.controller, lastController.item ) ) {
return( "" );
}
return( "#lastController.subsystem#:#lastController.section#.#lastController.item#" );
} catch ( any error ) {
return( "" );
}
}
As you can see, the .getActionToTrack() method reaches into the private variable, request._fw1.controllers, in order to inspect the last queued-up Controller. Really, I shouldn't be doing this - _fw1 is intended to be an "opaque" payload; however, it was the only approach that I could figure out. Once I have a reference to the last queued-up Controller, I just check to see if it has a member method that matches the associated item.
ASIDE: Why use the
.after()method, and not something like.setupResponse(), which would take view-rendering time into account? Welcome to the land of legacy code! This application predates the introduction of the.setupResponse()method; and, refactoring the life-cycle tracking has not been a priority for our product team.
Now, malicious requests for actions like foo:bar.baz will be handled by FW/1 but, will not get recorded as a request metric. You could argue that not recording this information is a problem, and hides meaningful application insights; and, I would tend to agree with you. But, like I said before, this is benefit / cost trade-off: in an actual dollars-and-cents way, we have to limit the number of StatsD metrics we record.
This is certainly an imperfect approach. And, if anyone has suggestions for improvement, I am absolutely open to them! Really, what I need to do is make time to look at the latest Framework One API and figure out how to clean-up some of our request handling. Unfortunately, I have like a million things to do; and fixing something that isn't really broken is not very high on that list.
Want to use code from this post? Check out the license.
Reader Comments
Interesting, I'll add a ticket to the project to investigate further as a possible enhancement once I've gone through a few outstanding bug tickets.
@Steven,
Part of my problem is that our FW/1 code is like 7-years old at this point :D We have the latest FW/1 version; but, the consuming code itself is super old and has only been updated to not break. As such, I'm not very familiar with how all the latest-and-greatest stuff works. If my mental model was better, there might very-well be more straightforward ways to approach this.
We've also made some poor choices in our app, like using
.setView()inside a.before()method so that a valid view is used no matter what.itemis actually provided. This is part of our problem that lead to unbounded StatsD metrics, even when we tried to move tracking to our error-handler (some end-points simply don't error because of View-overriding).So, a lot of our problems are self-inflicted technical debt :D
What we've always done in all of our apps is:
We do that in our legacy ColdBox apps. We used to do it in all of our legacy FW/1 apps. We do it today in all our Clojure apps.
We use New Relic for metrics in production (and we started doing that years ago in our CFML days) and we override the default "transaction name" in our "not found" code (New Relic records requests at the end of each one).
That way malicious requests (or just plain fat-fingering) all end up mapped onto a single not-found fake URI.
Redirects can make that a little trickier, depending on the framework, as can exceptions, and returning data without rendering a view: you need to ensure that you're able to record the request in all of those cases too, in order to get accurate metrics. And of course, you need to ensure that you set that per-request flag in any and all situations where you have generic request handling that can end up at a "not found" situation (on missing event/action/method etc).
@Sean,
Yeah, we actually just ran into the same issue with New Relic. We do use the custom Transaction name; but, we were basing it on the FW/1 action variable, which can be formed with malicious requests as well. New Relic started "clamping" our Transaction so like half of them are suddenly missing. I actually have a JIRA ticket to go fix that after the long weekend.
I think I should be able to implement an
onAbort()event handler for cases where people use the nativelocation()method. Between that and the FW/1setupResponse(), I think I should be able to catch most of the things.We'll see, I'm also trying to touch as little code as possible since I was never really strong on how all the request routing happens. For example, when Jamie Krug put in the foundational code, he overrode the
onError()handler; and, to this day, I can't really understand what it is doing, so I am afraid to touch it :D No disparity of Jamie - I think he replicated the internal FW/1onError()handler because something was getting called twice (based on some comments in the code). But, I am nervous touching it too much.