AOP plugin causing potentially unhandled rejections

[rimassa]

Hello!

I am using promise aware AOP plugin from wire.js to log messages before and after promise are resolved/rejected. This is a simple example of what I am attempting to do:

var when = require('when')
var wire = require('wire')
var logger = require('winston');
var express = require('express');

var contextDefinition = {
    $plugins: [
        { module: 'wire/aop' }
    ],

    logger: {
        before: function () { 
            logger.info('Before returning a promise', arguments) 
        },
        afterFulfill: function () { 
            logger.info('Sucessfully fulfilled promise', arguments) 
        },
        afterReject: function (err) { 
            logger.error('Failed to fulfill promise', err.stack || err) 
        }                   
    },

    myInst: {
        create: {
            test: function () {
                return when.reject(new Error('Test rejecting'))
            }
        },
        before: {
            test: 'logger.before'
        },
        afterFulfilling: {
            test: 'logger.afterFulfill'
        },
        afterRejecting: {
            test: 'logger.afterReject'
        }
    }
}

wire(contextDefinition, { require: require })
    .then(function (ctx) {
        var app = express();
        app.get('/test', function (req, res, next) {
            ctx.myInst.test()
                .then(function (r) {
                    res.status(200).send('ok')
                })
                .catch(function (e) {
                    res.status(500).send('err')
                })
                .done();    
        })
        app.listen(8080)
        logger.info('Server listening on port 8080')
    }, 
    function (e) {
        logger.error('Component wiring failed', e.stack || e);
    })
    .otherwise(function (e) {
        logger.error('Error initializing app', e.stack || e)
    });

Once I started this server, when I request the following route:

curl http://localhost:8080/test

I get the following messages logged on server:

info: Server listening on port 8080
info: Before returning a promise
error: Failed to fulfill promise Error: Test rejecting
    at Object.contextDefinition.myInst.create.test (/Volumes/Ri Data/iG/projects/pigmento/tmp/request.js:26:36)
    at callOrig (/Volumes/Ri Data/iG/projects/pigmento/node_modules/wire/node_modules/meld/meld.js:111:18)
    at callOrigAndOn (/Volumes/Ri Data/iG/projects/pigmento/node_modules/wire/node_modules/meld/meld.js:154:18)
    at callNext (/Volumes/Ri Data/iG/projects/pigmento/node_modules/wire/node_modules/meld/meld.js:220:8)
    at Object.Advisor._callAroundAdvice (/Volumes/Ri Data/iG/projects/pigmento/node_modules/wire/node_modules/meld/meld.js:290:11)
    at Object.Advisor.advised.advised [as test] (/Volumes/Ri Data/iG/projects/pigmento/node_modules/wire/node_modules/meld/meld.js:130:33)
    at /Volumes/Ri Data/iG/projects/pigmento/tmp/request.js:45:24
    at Layer.handle [as handle_request] (/Volumes/Ri Data/iG/projects/pigmento/node_modules/express/lib/router/layer.js:82:5)
    at next (/Volumes/Ri Data/iG/projects/pigmento/node_modules/express/lib/router/route.js:110:13)
    at Route.dispatch (/Volumes/Ri Data/iG/projects/pigmento/node_modules/express/lib/router/route.js:91:3)
Potentially unhandled rejection [11] Error: Test rejecting
    at Object.contextDefinition.myInst.create.test (/Volumes/Ri Data/iG/projects/pigmento/tmp/request.js:26:36)
    at callOrig (/Volumes/Ri Data/iG/projects/pigmento/node_modules/wire/node_modules/meld/meld.js:111:18)
    at callOrigAndOn (/Volumes/Ri Data/iG/projects/pigmento/node_modules/wire/node_modules/meld/meld.js:154:18)
    at callNext (/Volumes/Ri Data/iG/projects/pigmento/node_modules/wire/node_modules/meld/meld.js:220:8)
    at Object.Advisor._callAroundAdvice (/Volumes/Ri Data/iG/projects/pigmento/node_modules/wire/node_modules/meld/meld.js:290:11)
    at Object.Advisor.advised.advised [as test] (/Volumes/Ri Data/iG/projects/pigmento/node_modules/wire/node_modules/meld/meld.js:130:33)
    at /Volumes/Ri Data/iG/projects/pigmento/tmp/request.js:45:24
    at Layer.handle [as handle_request] (/Volumes/Ri Data/iG/projects/pigmento/node_modules/express/lib/router/layer.js:82:5)
    at next (/Volumes/Ri Data/iG/projects/pigmento/node_modules/express/lib/router/route.js:110:13)
    at Route.dispatch (/Volumes/Ri Data/iG/projects/pigmento/node_modules/express/lib/router/route.js:91:3)

Should I worry about that Potentially unhandled rejection [11] message, even if it never reports the related message "Handled previous rejection" for that rejection, from then on?

And, surprisingly (at least to me) is that if I comment the following lines from the script above:

        // afterFulfilling: {
        //  test: 'logger.afterFulfill'
        // },

and repeat the test, I no longer get the message about the potentially unhandled rejection. Thus, it seems that this message appears only when both "afterFulfilling" and "afterRejecting" advices are used together on a function.

I'm using the following node.js and module versions: "express": "^4.12.3", "wire": "^0.10.10" "when": "^3.7.3" node v0.12.0

Thanks in advance Ricardo

[briancavalier]

Hey @rimassa thanks for all the detail! You def shouldn't get unhandled rejection warnings under normal circumstances unless there's actually a rejected promise escaping somewhere. I'll dig into your example this weekend and hopefully we can figure out what's going on.

[briancavalier]

@rimassa Here's a gist of a simplified version of your example. I've run it in node 0.12 and iojs 2.0, and haven't been able to reproduce the issue. The result I get only has the logger.error output, and doesn't report an unhandled rejection.

Could you try that gist and see what you get? What version of node/iojs are you using? Maybe there is some environment difference, or maybe it has something to do with express being in the mix (although it's not clear to me how that would affect it).

Do you have any more info that might help us track this down?

Thanks!