KeystoneJS middleware running twice when making a call to MongoDB using Model.find()

Viewed 335

I have a route that loads a list of Condos and displays them:

app.get( '/condo-list', middleware.loadCondoList, routes.views.condolist );

The loadCondoList middleware makes a call to the CondoBuilding model and sets the results on res.locals:

exports.loadCondoList = function loadCondoList( req, res, next ) {

console.log( 'request url: ' + req.url );
console.log( 'getting condo buildings...' );

CondoBuilding.model
    .find()
    .exec( ( err, condos ) => {
        if ( err ) {
            // pass error along
            next( err );
        } else {
            // add CondoBuildings to locals
            res.locals.condoBuildings = condos;
            next();
        }
    });
};

The call to the database is successful and the page renders as expected. However, for some reason, the route is running twice. The console output is as follows:

request url: /condo-list
getting condo buildings...
GET /condo-list 304 344.532 ms
request url: /condo-list
getting condo buildings...
GET /condo-list 304 317.631 ms

I have reproduced this behavior in multiple browsers ( Chrome, Safari, Firefox ) and verified that this does not happen on any other routes.

If I delete the call to CondoBuilding.model.find() and just call next() in the body of loadCondoList() this behavior does not occur.

I am running Keystone 4 "keystone": "4.0.0-beta.5" which leverages Express 4 "express": "4.14.0"

Below is the full list of routes I am running in the app, in case it is relevant:

// Setup Route Bindings
exports = module.exports = function ( app ) {

// Views
app.get( '/', routes.views.index );
app.get( '/condo-list', middleware.loadCondoList, routes.views.condolist );
app.get( '/blog/:category?', routes.views.blog );
app.get( '/blog/post/:post', routes.views.post );
app.get( '/about', routes.views.about );
app.get( '/search', middleware.getAccountType, routes.views.search );

app.all( '/contact', routes.views.contact );

};

CondoList view:

var keystone = require('keystone');

exports = module.exports = function (req, res) {

var view = new keystone.View(req, res);
var locals = res.locals;

// locals.section is used to set the currently selected
// item in the header navigation.
locals.section = 'condolist';

// Render the view
view.render('condolist');
};

I have been debugging this issue for a while but I am at my wits end as to what could be causing this. Any help would be appreciated.

UPDATE

I followed @phuhgh's advice and ran the application in Express debug mode. While nothing jumped out at me immediately, I did notice something strange during application startup.

Here is a sequence of a few routes being prepared that behave normally:

express:router:layer new / +0ms
express:router:route new /blog/post/:post +0ms
express:router:layer new /blog/post/:post +0ms
express:router:route get /blog/post/:post +0ms
express:router:layer new / +0ms
express:router:route new /about +0ms
express:router:layer new /about +0ms
express:router:route get /about +0ms
express:router:layer new / +0ms
express:router:route new /search +1ms
express:router:layer new /search +0ms
express:router:route get /search +0ms

Here is the sequence of the condo-list route being prepared:

express:router:layer new / +0ms
express:router:route new /condo-list +0ms
express:router:layer new /condo-list +0ms
express:router:route get /condo-list +0ms
express:router:layer new / +0ms
express:router:route get /condo-list +0ms

As you may notice, the express:router:route get /condo-list +0ms line is repeated. I have no idea why, but I am assuming this has something to do with the issue I am running into. I am digging into this angle a bit more, but again, any help from someone with a bit more knowledge in this area would be greatly appreciated.

Update 2 - Stack Trace

Stack Trace

I've debugged and gone through the stack step by step. I can follow the path from function to function and everything appears normal, but my baseline for normal was looking at other routes that worked properly. I honestly wouldn't know what to look for once I'm that deep into the guts of Express.

Observations I have made while going through the stack:

  • The stack trace is exactly the same both times the /condo-list route runs.
  • The stack trace ( minus the loadCondoList middleware, of course ) is exactly the same for other routes that run properly ( i.e. only once ).
  • If I add a call to loadCondoList in another route, it also runs properly.
    • e.g. I updated the /about route definition to the following: app.get( '/about', middleware.loadCondoList, routes.views.about ); and it loads the data properly and only runs once.

Is there anything I should be paying particular attention to as I'm stepping through the Express lib code? I feel a bit out of my depth there and I'm not sure what to look for.

1 Answers
Related