Request Logging Middleware for bx-express

Intro

For a while now, user metrics on this site have been powered by a third-party analytics service. It worked, mostly — until it didn't. That service's API is rate-limited, and I was calling it synchronously — right there inside the request handler, through a small client I'd built for it. When their API got slow or throttled me, my server got slow right along with it. A third-party outage taking down my own site's response times was never a trade I meant to make.

So I ripped it out and wrote my own access logger instead: RequestLogger.bx. This weekend felt like a good time to actually write up how it works — partly because the design is worth explaining beyond "it logs requests now," and partly because the whole class doubles as a decent tour of boxlang-express middleware for anyone who hasn't written any yet.

The problem with logging synchronously

The obvious way to log a request is: request comes in, you write a row to the database, then you respond. Simple, but it means every single request now depends on your database being fast and available. A slow query, a connection pool exhausted, a brief network blip — and suddenly your logging is the reason your actual pages are slow to load.

That's exactly the failure mode that third-party API gave me, just one layer further out. I didn't want to trade one version of that problem for another. The fix is pretty old-school, honestly: decouple the writing from the request entirely — queue now, write later.

Building it: a walkthrough for boxlang-express newcomers

Here's the whole class, broken up as I go.

The shape of the class

class {

	variables.queue                 = createObject( "java", "java.util.concurrent.ConcurrentLinkedQueue" ).init();
	variables.maxQueueSize          = 5000;
	variables.maxBatchPerFlush      = 500;
	variables.flushIntervalSeconds  = 5;
	variables.retentionDays         = 90;
	variables.flushesBetweenCleanup = 360;
	variables.flushesSinceCleanup   = 0;

	function init( numeric flushIntervalSeconds = 5, numeric retentionDays = 90 ){
		variables.flushIntervalSeconds = arguments.flushIntervalSeconds;
		variables.retentionDays        = arguments.retentionDays;
		_startFlushLoop();
		return this;
	}

	// ...
}

A .bx file that boils down to one top-level class { } block is BoxLang's component syntax — this is the whole file. Instance state lives in the variables scope, which is exactly what you see at the top: the queue itself, plus every tunable (queue cap, batch size, flush interval, retention). init() is the constructor boxlang-express calls when you new the class in app.bxs; the only thing it does beyond storing its two config arguments is kick off the background flush loop.

Worth calling out for anyone new to BoxLang: createObject( "java", "java.util.concurrent.ConcurrentLinkedQueue" ) reaches straight into the JVM standard library. No wrapper class, no import — if java.util.concurrent has it, createObject() gets you there directly.

middleware()

function middleware(){
	return ( req, res, next ) => {
		var startedAt = getTickCount();
		next();
		_enqueue( req, res, getTickCount() - startedAt );
	};
}

boxlang-express middleware follows the same (req, res, next) shape you'd recognize from Express — next() hands off to whatever's registered after you. middleware() itself isn't the middleware; it's a factory that returns the closure app.use() actually registers. That's the pattern to reach for any time your middleware needs setup state — here, the timer — that shouldn't leak into every request as an argument.

Calling next() before _enqueue() is the whole trick: the response has already gone out by the time execution reaches the line that queues anything, so nothing in this function can add latency to it.

_enqueue()

private function _enqueue( req, res, durationMs ){
	try {
		if ( variables.queue.size() >= variables.maxQueueSize ){
			return;
		}

		variables.queue.add( {
			requestedAt: now(),
			method     : req.method,
			path       : req.path,
			queryString: _rawQueryString( req ),
			statusCode : _statusCodeOf( res ),
			durationMs : durationMs,
			ip         : req.ip ?: "",
			referrer   : req.get( "Referer" ) ?: "",
			userAgent  : req.get( "User-Agent" ) ?: ""
		} );
	} catch ( any e ){
		// A logging bug should never surface as a request failure.
	}
}

Two defensive choices worth naming. First, the size check: past 5000 pending rows, new ones just get dropped instead of growing the queue without bound — an unbounded queue under sustained load is just a slower path to the same kind of outage this whole design exists to avoid. Losing a few rows during a bad stretch is a trade I'm happy to make.

Second, the entire body sits inside a try/catch that swallows everything. That's deliberate, not sloppy — this function runs on every single request, so a bug here can't be allowed to turn into a 500 for a visitor. Note also ?:, BoxLang's elvis operator, on req.ip and req.get( "Referer" ) — it falls back to an empty string rather than letting a missing value propagate as null.

_rawQueryString()

private function _rawQueryString( req ){
	var qPos = req.originalUrl.find( "?" );
	return qPos ? req.originalUrl.mid( qPos + 1, req.originalUrl.len() - qPos ) : "";
}

This exists because of a gotcha I hit building this: req.originalUrl carries the query string exactly as it came in over the wire — still URL-encoded. I was tempted to rebuild it from req.query instead, but that struct holds already-decoded values, and re-encoding them risks mangling a & or = that was part of an encoded value rather than an actual delimiter. Slicing the raw string straight off originalUrl sidesteps the problem entirely.

_statusCodeOf()

private function _statusCodeOf( res ){
	if ( !structKeyExists( res, "getStatusCode" ) ){
		return javacast( "null", "" );
	}
	try {
		return res.getStatusCode();
	} catch ( any e ){
		return javacast( "null", "" );
	}
}

The other gotcha: res.getStatusCode() doesn't exist in older versions of boxlang-express. structKeyExists() lets you check a method exists before calling it, so rather than block on a dependency bump, this just falls back to a null status code — javacast( "null", "" ) is how you hand BoxLang an actual null instead of an empty string — and leaves everything else working.

Wiring up the background thread

private function _startFlushLoop(){
	var scheduler = createObject( "java", "java.util.concurrent.Executors" ).newSingleThreadScheduledExecutor();
	var runnable  = createDynamicProxy( new models.util.Runnable( () => _flush() ), [ "java.lang.Runnable" ] );
	var seconds   = createObject( "java", "java.util.concurrent.TimeUnit" ).SECONDS;
	scheduler.scheduleAtFixedRate( runnable, variables.flushIntervalSeconds, variables.flushIntervalSeconds, seconds );
}

This is the part that'll look least familiar coming from a scripting-language background. scheduleAtFixedRate() is a genuine java.util.concurrent.ScheduledExecutorService call, and it wants a real java.lang.Runnable instance — not just anything callable. createDynamicProxy() is BoxLang's bridge for that: it wraps a closure in a proxy object that satisfies a Java interface, so () => _flush() can stand in for Runnable.run(). Reach for this pattern any time a Java API expects an interface implementation and all you've got is a closure.

_flush()

private function _flush(){
	try {
		var batch = [];
		var entry = variables.queue.poll();
		while ( !isNull( entry ) && batch.len() < variables.maxBatchPerFlush ){
			batch.append( entry );
			entry = variables.queue.poll();
		}
		if ( batch.isEmpty() ){
			return;
		}

		for ( var row in batch ){
			_insertRow( row );
		}

		_cleanupOldRowsPeriodically();
	} catch ( any e ){
		println( "[RequestLogger] flush failed: " & e.message );
	}
}

This runs on the scheduler thread every 5 seconds — never on a request thread. poll() drains the queue non-blockingly, up to 500 rows at a time; that cap means one huge backlog can't turn a single flush into a long-running transaction, it just takes a few more ticks to fully drain. If anything in the batch throws, the whole flush is caught and logged, and the next tick just picks up wherever the queue is by then. One bad batch doesn't wedge the pipeline.

_insertRow()

private function _insertRow( required struct row ){
	queryExecute(
		"INSERT INTO RequestLog
			(requested_at, method, path, query_string, status_code, duration_ms, ip_address, referrer, user_agent)
		VALUES
			(:requestedAt, :method, :path, :queryString, :statusCode, :durationMs, :ip, :referrer, :userAgent)",
		{
			"requestedAt": { value: row.requestedAt, cfsqltype: "cf_sql_timestamp" },
			"method"     : { value: row.method,      cfsqltype: "cf_sql_varchar" },
			"path"       : { value: row.path,        cfsqltype: "cf_sql_varchar" },
			"queryString": { value: row.queryString, cfsqltype: "cf_sql_longvarchar" },
			"statusCode" : isNull( row.statusCode )
				? { value: "", cfsqltype: "cf_sql_integer", null: true }
				: { value: row.statusCode, cfsqltype: "cf_sql_integer" },
			"durationMs" : { value: row.durationMs, cfsqltype: "cf_sql_integer" },
			"ip"         : { value: row.ip,         cfsqltype: "cf_sql_varchar" },
			"referrer"   : { value: row.referrer,   cfsqltype: "cf_sql_longvarchar" },
			"userAgent"  : { value: row.userAgent,  cfsqltype: "cf_sql_longvarchar" }
		}
	);
}

Nothing exotic here — it's queryExecute() with a struct of { value, cfsqltype } pairs per parameter, the standard CFML/BoxLang idiom for parameterized queries. Worth using even here, where every value is internally generated, just as habit: it's what keeps a raw INSERT from turning into a SQL-injection footgun the day someone reuses the pattern somewhere the input isn't trusted.

_cleanupOldRowsPeriodically()

private function _cleanupOldRowsPeriodically(){
	variables.flushesSinceCleanup++;
	if ( variables.flushesSinceCleanup < variables.flushesBetweenCleanup ){
		return;
	}
	variables.flushesSinceCleanup = 0;

	queryExecute(
		"DELETE FROM RequestLog WHERE requested_at < DATE_SUB(NOW(), INTERVAL :days DAY)",
		{ "days": { value: variables.retentionDays, cfsqltype: "cf_sql_integer" } }
	);
}

This is a plain counter, not a timer — it increments on every flush and only fires the DELETE once every 360 flushes, which at the default 5-second interval works out to roughly once every 30 minutes. Running a DELETE on every single flush would be a lot of wasted queries for housekeeping that only needs to happen occasionally; a 90-day retention window doesn't need to be enforced to the second.

Registering it

None of this matters if the middleware doesn't run first — ahead of everything else — so its next() wraps the entire chain below it:

// requestLogger goes first, ahead of everything else, so its next() wraps
// the entire chain below — every request this server handles gets a row,
// static assets included, same scope as an actual Apache access log.
app.use( requestLogger.middleware() )

app.use(
	boxExpressJSON(),
	boxExpressUrlencoded(),
	boxExpressSession( { store: boxExpressCacheStore("sessionCache"), maxAge: 30 * 24 * 60 * 60 } ),
	boxExpressStatic( expandPath( "./public" ), { maxAge: 86400 } ),
	boxExpressHelmet( { referrerPolicy: "strict-origin-when-cross-origin" } )
)

requestLogger.middleware() gets its own app.use() call, registered before the JSON/session/static-file/helmet stack. That split is deliberate — it's what makes this a true access log rather than just a page-view counter: static assets get logged too, since nothing downstream of it is skipped.

Where the data goes

All of this feeds a couple of internal dashboards I actually look at: one is the direct replacement for that old third-party service — page views, referrers, that kind of thing — and the other runs some heuristic scans over the same table looking for attack patterns rather than visitor stats. Same data, two very different lenses on it.

It's a small piece of infrastructure, but I like that it's one I fully understand now, top to bottom — no more wondering what a third-party API is doing to my response times behind the scenes.