The Appalling Events of 6 November 2014

This page archives and comments an extremely unhelpful trace received from the framework during the process of working on the GPII's FlowManager. We should improve the framework in a few ways so that problems of this kind can't occur again, and/or are reported with sensible and readable diagnostics.

This log was received by running node UpdateTests.js from GPII universal's gpii/node_modules/flowManager/test :

The commit involved is at https://github.com/kaspermarkus/universal/tree/b9bde973258ccb135f39061ef8f4d62d7e98d09e

The cause of the problem is this line: https://github.com/kaspermarkus/universal/blob/b9bde973258ccb135f39061ef8f4d62d7e98d09e/gpii/node_modules/flowManager/src/FlowManagerUtilities.js#L122 as follows:

        listeners: {
            onToken: "{that}.getPreferences",
            onReadyToMatch: "{that}.runMatchMakerFramework",
            onDevice: "{that}.getSolutions",
            "{gpii.matchMakerFramework}.events.onMatch": "{that}.fireOnMatch"  // <--- ERROR HERE
        }

This supplies a request scope listener to an injects an application scope event. As a result, when the event is fired, EVERY such request's listeners will be notified.

The test sequence executing is as follows (at https://github.com/kaspermarkus/universal/blob/b9bde973258ccb135f39061ef8f4d62d7e98d09e/gpii/node_modules/flowManager/test/UpdateTests.js#L167 ) -

    sequence: [{ // point 1
        func: "{invalidUpdateRequest}.send",
        args: "You shall not pass!!"
    }, { // point 2
        event: "{invalidUpdateRequest}.events.onError",
        listener: "gpii.tests.flowManager.update.testInvalidUpdateRequest"
    }, { // point 3
        func: "{login}.send"
    }, { // point 4
        event: "{login}.events.onComplete",
        listener: "gpii.tests.flowManager.update.testLoginResponse"
    }, { // point 5
        func: "{updateRequest}.send",
        args: gpii.tests.flowManager.update.payload1
    }, { // point 6
        event: "{updateRequest}.events.onComplete",
        listener: "gpii.tests.flowManager.update.testFirstUpdateRequest"
    }, {

The first failure report occurs at sequence point 5 during "send" for the 2nd request:

20:21:38.417:  ASSERTION FAILED: Cannot resolve reference {that}.events.onMatch from component { typeName: "kettle.requests.request.handler" gradeNames: ["kettle.requests.request.handler.userLogin","gpii.request.flowManager.token","kettle.requests.request.handler","{request}.handlerContext","fluid.applyGradeLinkage"] id: 9wrq5kv4-629} which has been destroyed
20:21:38.417:  Current activity: 
    while resolving context value {that}.events.onMatch
    while expanding context value {that}.events.onMatch held at path ""
20:21:38.418:  FATAL ERROR: Uncaught exception: Object Cannot resolve reference {that}.events.onMatch from component { typeName: "kettle.requests.request.handler" gradeNames: ["kettle.requests.request.handler.userLogin","gpii.request.flowManager.token","kettle.requests.request.handler","{request}.handlerContext","fluid.applyGradeLinkage"] id: 9wrq5kv4-629} which has been destroyed has no method 'Assertion failure - check console for details'
TypeError: Object Cannot resolve reference {that}.events.onMatch from component { typeName: "kettle.requests.request.handler" gradeNames: ["kettle.requests.request.handler.userLogin","gpii.request.flowManager.token","kettle.requests.request.handler","{request}.handlerContext","fluid.applyGradeLinkage"] id: 9wrq5kv4-629} which has been destroyed has no method 'Assertion failure - check console for details'
    at Object.fluid.builtinFail (E:\source\gits\gpii\node_modules\universal\node_modules\infusion\src\framework\core\js\Fluid.js:163:69)
    at kettle.utils.failureHandler (E:\source\gits\gpii\node_modules\universal\node_modules\kettle\lib\utils.js:98:15)
    at Object.fluid.fail (E:\source\gits\gpii\node_modules\universal\node_modules\infusion\src\framework\core\js\Fluid.js:184:13)
    at Object.fluid.makeStackFetcher.fetcher (E:\source\gits\gpii\node_modules\universal\node_modules\infusion\src\framework\core\js\FluidIoC.js:726:23)
    at fetch (E:\source\gits\gpii\node_modules\universal\node_modules\infusion\src\framework\core\js\FluidIoC.js:2053:32)
    at Object.fluid.resolveContextValue (E:\source\gits\gpii\node_modules\universal\node_modules\infusion\src\framework\core\js\FluidIoC.js:2061:20)
    at Object.fluid.expandSource (E:\source\gits\gpii\node_modules\universal\node_modules\infusion\src\framework\core\js\FluidIoC.js:2158:34)
    at Object.fluid.makeExpandOptions.options.expandSource (E:\source\gits\gpii\node_modules\universal\node_modules\infusion\src\framework\core\js\FluidIoC.js:2234:26)
    at Object.fluid.makeExpandOptions (E:\source\gits\gpii\node_modules\universal\node_modules\infusion\src\framework\core\js\FluidIoC.js:2249:42)
    at Object.fluid.expand (E:\source\gits\gpii\node_modules\universal\node_modules\infusion\src\framework\core\js\FluidIoC.js:2259:35)
    at Object.fluid.embodyDemands (E:\source\gits\gpii\node_modules\universal\node_modules\infusion\src\framework\core\js\FluidIoC.js:1226:37)
    at invokeInvoker (E:\source\gits\gpii\node_modules\universal\node_modules\infusion\src\framework\core\js\FluidIoC.js:1655:40)
    at fireToListeners (E:\source\gits\gpii\node_modules\universal\node_modules\infusion\src\framework\core\js\Fluid.js:1106:68)
    at Object.fluid.makeEventFirer.that.fire (E:\source\gits\gpii\node_modules\universal\node_modules\infusion\src\framework\core\js\Fluid.js:1205:24)
    at Array.gpii.matchMakerFramework.matchMakerDispatcher [as 0] (E:\source\gits\gpii\node_modules\universal\gpii\node_modules\matchMakerFramework\src\MatchMakerFramework.js:91:19)
    at Object.fluid.promise.that.complete (E:\source\gits\gpii\node_modules\universal\node_modules\infusion\src\framework\core\js\FluidPromises.js:65:25)
    at fluid.promise.that.resolve (E:\source\gits\gpii\node_modules\universal\node_modules\infusion\src\framework\core\js\FluidPromises.js:49:22)
    at Object.fluid.promise.that.then (E:\source\gits\gpii\node_modules\universal\node_modules\infusion\src\framework\core\js\FluidPromises.js:31:21)
    at Function.fluid.promise.follow (E:\source\gits\gpii\node_modules\universal\node_modules\infusion\src\framework\core\js\FluidPromises.js:83:16)
    at Array.kettle.dataSource.set [as 0] (E:\source\gits\gpii\node_modules\universal\node_modules\kettle\lib\dataSource.js:220:31)
    at Object.fluid.promise.that.complete (E:\source\gits\gpii\node_modules\universal\node_modules\infusion\src\framework\core\js\FluidPromises.js:65:25)
    at Object.fluid.promise.that.resolve (E:\source\gits\gpii\node_modules\universal\node_modules\infusion\src\framework\core\js\FluidPromises.js:49:22)
    at onEnd (E:\source\gits\gpii\node_modules\universal\node_modules\kettle\lib\dataSource.js:325:33)
    at applyCallback (E:\source\gits\gpii\node_modules\universal\node_modules\kettle\lib\utils.js:57:37)
    at fluid.withEnvironment (E:\source\gits\gpii\node_modules\universal\node_modules\infusion\src\framework\core\js\FluidIoC.js:1880:20)
    at Object.fluid.tryCatch (E:\source\gits\gpii\node_modules\universal\node_modules\infusion\src\framework\core\js\Fluid.js:219:24)
    at Object.fluid.withEnvironment (E:\source\gits\gpii\node_modules\universal\node_modules\infusion\src\framework\core\js\FluidIoC.js:1875:22)
    at IncomingMessage.wrapCallback (E:\source\gits\gpii\node_modules\universal\node_modules\kettle\lib\utils.js:54:30)
    at IncomingMessage.EventEmitter.emit (events.js:115:20)
    at IncomingMessage._emitEnd (http.js:366:10)
    at HTTPParser.parserOnMessageComplete [as onMessageComplete] (http.js:149:23)
    at Socket.socketOnData [as ondata] (http.js:1366:20)
    at TCP.onread (net.js:402:27)

This is of course highly puzzling to the user since they can see no logical path by which their request may be destroyed by this early point in request handling.

The sequence that occurs is this:

The invalid update request from sequence points 1 and 2 resolves - it fires onError at the following point (line 398 of the trace):

&&&&&&&&&&&&&&&&& FIRING SESSIONAWARE ONERROR FROM Error
    at gpii.request.flowManager.sessionAware.withSession (E:\source\gits\gpii\node_modules\universal\gpii\node_modules\flowManager\src\FlowManagerUtilities.js:151:81)
    at Object.invoke (E:\source\gits\gpii\node_modules\universal\node_modules\infusion\src\framework\core\js\FluidIoC.js:1623:25)
    at Object.invokeInvoker [as withSession] (E:\source\gits\gpii\node_modules\universal\node_modules\infusion\src\framework\core\js\FluidIoC.js:1650:32)
    at gpii.request.flowManager.onMatchUpdateHandler (E:\source\gits\gpii\node_modules\universal\gpii\node_modules\flowManager\src\UserUpdate.js:111:14)
    at invokeInvoker (E:\source\gits\gpii\node_modules\universal\node_modules\infusion\src\framework\core\js\FluidIoC.js:1664:29)
    at fireToListeners (E:\source\gits\gpii\node_modules\universal\node_modules\infusion\src\framework\core\js\Fluid.js:1106:68)
    at fluid.makeEventFirer.that.fire (E:\source\gits\gpii\node_modules\universal\node_modules\infusion\src\framework\core\js\Fluid.js:1205:24)
    at gpii.request.flowManager.fireOnMatch (E:\source\gits\gpii\node_modules\universal\gpii\node_modules\flowManager\src\FlowManagerUtilities.js:145:20)
    at invokeInvoker (E:\source\gits\gpii\node_modules\universal\node_modules\infusion\src\framework\core\js\FluidIoC.js:1664:29)
    at fireToListeners (E:\source\gits\gpii\node_modules\universal\node_modules\infusion\src\framework\core\js\Fluid.js:1106:68)
    at Object.fluid.makeEventFirer.that.fire (E:\source\gits\gpii\node_modules\universal\node_modules\infusion\src\framework\core\js\Fluid.js:1205:24)
    at Array.gpii.matchMakerFramework.matchMakerDispatcher [as 0] (E:\source\gits\gpii\node_modules\universal\gpii\node_modules\matchMakerFramework\src\MatchMakerFramework.js:91:19)
    at Object.fluid.promise.that.complete (E:\source\gits\gpii\node_modules\universal\node_modules\infusion\src\framework\core\js\FluidPromises.js:65:25)
    at fluid.promise.that.resolve (E:\source\gits\gpii\node_modules\universal\node_modules\infusion\src\framework\core\js\FluidPromises.js:49:22)
    at Object.fluid.promise.that.then (E:\source\gits\gpii\node_modules\universal\node_modules\infusion\src\framework\core\js\FluidPromises.js:31:21)
    at Function.fluid.promise.follow (E:\source\gits\gpii\node_modules\universal\node_modules\infusion\src\framework\core\js\FluidPromises.js:83:16)
    at Array.kettle.dataSource.set [as 0] (E:\source\gits\gpii\node_modules\universal\node_modules\kettle\lib\dataSource.js:220:31)
    at Object.fluid.promise.that.complete (E:\source\gits\gpii\node_modules\universal\node_modules\infusion\src\framework\core\js\FluidPromises.js:65:25)
    at Object.fluid.promise.that.resolve (E:\source\gits\gpii\node_modules\universal\node_modules\infusion\src\framework\core\js\FluidPromises.js:49:22)
    at onEnd (E:\source\gits\gpii\node_modules\universal\node_modules\kettle\lib\dataSource.js:325:33)
    at applyCallback (E:\source\gits\gpii\node_modules\universal\node_modules\kettle\lib\utils.js:57:37)
    at fluid.withEnvironment (E:\source\gits\gpii\node_modules\universal\node_modules\infusion\src\framework\core\js\FluidIoC.js:1880:20)
    at Object.fluid.tryCatch (E:\source\gits\gpii\node_modules\universal\node_modules\infusion\src\framework\core\js\Fluid.js:219:24)
    at Object.fluid.withEnvironment (E:\source\gits\gpii\node_modules\universal\node_modules\infusion\src\framework\core\js\FluidIoC.js:1875:22)
    at IncomingMessage.wrapCallback (E:\source\gits\gpii\node_modules\universal\node_modules\kettle\lib\utils.js:54:30)
    at IncomingMessage.EventEmitter.emit (events.js:115:20)
    at IncomingMessage._emitEnd (http.js:366:10)
    at HTTPParser.parserOnMessageComplete [as onMessageComplete] (http.js:149:23)
    at Socket.socketOnData [as ondata] (http.js:1366:20)
    at TCP.onread (net.js:402:27)

2. Unfortunately, resolution of this listener is synchronous - and the IoC Testing framework immediately moves on to sequence point 3 and issues a further request whilst the invalid update request is still on the stack - as well as still being an active request with a registered handler to onMatch. At this point we raised http://issues.fluidproject.org/browse/FLUID-5546 but as it turns out resolving this issue would leave this particular outcome unchanged. It is "too late" to clear the listener since we are already in the middle of dispatching it (from MatchMakerFramework.js line 91).

3. The second request then causes the application scope onMatch event to fire.

4. This, due to synchronous resolution, dispatches to the onMatch listener of the invalid update request which is still on the stack, and partway through its own destruction.

5. This attempts to fire a further error - since there is still no session atta