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

Question

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

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.

Answer 1

After days of debugging I've finally found the culprit, and it was hiding in the most unlikely of places: the view!

Context

The view loads a masonry display of condo buildings that can be filtered by neighborhood. Below is a relevant snippet of the masonry itself:

<!-- Condo List Masonry -->
<div class="condo-items">
{{#each condoBuildings}}
    <div class="condo-item {{neighborhood.key}}">
        <div class="condo-thumb">
            <span class="condo-tag tag-art">{{neighborhood.name}}</span>
            <a href="/{{condoUrl}}"><img src="{{{cloudinaryUrl image}}}" alt="{{name}}" /></a>
        </div>
        <div class="condo-body">
            <h3><a class="condo-name" href="#">{{name}}</a></h3>
            <p>{{condoDescription}}</p>
        </div>
    </div>
{{/each}}
</div>

The issue was caused by the cloudinaryUrl helper in this line:

<a href="/{{condoUrl}}"><img src="{{{cloudinaryUrl image}}}" alt="{{name}}" /></a>

Here is the helper code:

_helpers.cloudinaryUrl = function (context, options) {

    // if we dont pass in a context and just kwargs
    // then `this` refers to our default scope block and kwargs
    // are stored in context.hash
    if (!options && context.hasOwnProperty('hash')) {
        // strategy is to place context kwargs into options
        options = context;
        // bind our default inherited scope into context
        context = this;
    }

    // safe guard to ensure context is never null
    context = context === null ? undefined : context;

    if ((context) && (context.public_id)) {
        options.hash.secure = keystone.get('cloudinary secure') || false;
        var imageName = context.public_id.concat('.', context.format);
        return cloudinary.url(imageName, options.hash);
    }
    else {
        return null;
    }
};

The Issue

Some CondoBuilding models did not have an image defined yet. This causes the context argument in the _helpers.cloudinaryUrl method to be undefined. In those cases, the helper will return null. I am still unsure as to why this leads to a page reload, but I am certain that this was the culprit.

The Fix

Updating the Handlebars template to only render the <img> element if an image exists on the CondoBuilding model. The updated template code looks as follows:

<!-- Condo List Masonry -->
<div class="condo-items">
{{#each condoBuildings}}
    <div class="condo-item {{neighborhood.key}}">
        <div class="condo-thumb">
            <span class="condo-tag tag-art">{{neighborhood.name}}</span>
            <a href="/{{condoUrl}}">{{#if image}}<img src="{{{cloudinaryUrl image}}}" alt="{{name}}" />{{/if}}</a>
        </div>
        <div class="condo-body">
            <h3><a class="condo-name" href="#">{{name}}</a></h3>
            <p>{{condoDescription}}</p>
        </div>
    </div>
{{/each}}

With the addition of the {{#if image}} block to the template the route only runs once, as expected!

Next Steps

An improvement over this implementation would be to use a placeholder image for all CondoBuildings that do not have an image defined. I will add this functionality shortly, but I couldn't resist updating with an answer as I've been banging my head against this issue for days now.

Thanks to everyone for your time and attention.