Continuations do not work across callbacks unless wrapped with namespace.run()

[parasyte]

At first glance, the docs indicated this module is exactly what I've been looking for!

So I went digging through the code to get an understanding of the black magic that makes this work. Looks like it just relies on closures and a stack ... But closures are totally useless across callbacks, so there must be something more tricky going on. I see async-listener is used, and its documentation is pretty clear; this is the witchcraft that does the stuff!

Let's validate:

"use strict";

const cls = require('continuation-local-storage');
let ns = cls.createNamespace('test');

const tee   = "\u251c\u2500\u2500";
const angle = "\u2514\u2500\u2500";
const pipe  = "\u2502";

function output(log) {
    log.forEach(function (line) {
        console.log(line);
    });
}

ns.run(function () {
    let log = [];

    ns.set('value', 0);
    log[0] = `start: -> ${ns.get('value')}`;

    setTimeout(function () {
        let first = ns.get('value');
        ns.set('value', 1);
        log[1] = `${tee} first: ${first} -> ${ns.get('value')}`;

        setTimeout(function () {
            let third = ns.get('value');
            ns.set('value', 3);
            log[2] = `${pipe}   ${angle} third: ${third} -> ${ns.get('value')}`;
        }, 200);
    }, 100);

    setTimeout(function () {
        let second = ns.get('value');
        ns.set('value', 2);
        log[3] = `${angle} second: ${second} -> ${ns.get('value')}`;

        setTimeout(function () {
            let fourth = ns.get('value');
            ns.set('value', 4);
            log[4] = `    ${angle} fourth: ${fourth} -> ${ns.get('value')}`;

            output(log);
        }, 200);
    }, 200);
});

With this, I should expect four callbacks to run, each about 100ms apart. And I should expect the output to be:

start: -> 0
├── first: 0 -> 1
│   └── third: 1 -> 3
└── second: 0 -> 2
    └── fourth: 2 -> 4

This would be proof that the context really does retain its parent's value.

Run it and ... NOPE! :cry: Actual output is:

start: -> 0
├── first: 0 -> 1
│   └── third: 2 -> 3
└── second: 1 -> 2
    └── fourth: 3 -> 4

The context is not retaining its parent's value at all; it is retaining the value from the last assignment. This is no better than replacing the ns reference with a mock:

function NS() {
    this.data = {};
}

NS.prototype.run = function(callback) {
    callback();
}

NS.prototype.get = function (key) {
    return this.data[key];
};

NS.prototype.set = function (key, value) {
    this.data[key] = value;
};

let ns = new NS();

(This mock "namespace" object will return the same output.)

But what about that ns.run() method? I only use it once to initialize the context ... Let's see what happens when I wrap all my callbacks with it!

"use strict";

const cls = require('continuation-local-storage');
let ns = cls.createNamespace('test');

const tee   = "\u251c\u2500\u2500";
const angle = "\u2514\u2500\u2500";
const pipe  = "\u2502";

function output(log) {
    log.forEach(function (line) {
        console.log(line);
    });
}

ns.run(function () {
    let log = [];

    ns.set('value', 0);
    log[0] = `start: -> ${ns.get('value')}`;

    setTimeout(function () {
        ns.run(function() {
            let first = ns.get('value');
            ns.set('value', 1);
            log[1] = `${tee} first: ${first} -> ${ns.get('value')}`;

            setTimeout(function () {
                ns.run(function() {
                    let third = ns.get('value');
                    ns.set('value', 3);
                    log[2] = `${pipe}   ${angle} third: ${third} -> ${ns.get('value')}`;
                });
            }, 200);
        });
    }, 100);

    setTimeout(function () {
        ns.run(function() {
            let second = ns.get('value');
            ns.set('value', 2);
            log[3] = `${angle} second: ${second} -> ${ns.get('value')}`;

            setTimeout(function () {
                ns.run(function() {
                    let fourth = ns.get('value');
                    ns.set('value', 4);
                    log[4] = `    ${angle} fourth: ${fourth} -> ${ns.get('value')}`;

                    output(log);
                });
            }, 200);
        });
    }, 200);
});

😳 It works! It's exactly what I need... kind of ugly, though. But what kind of voodoo is this... ?!

... Oh, it's the stack! Of course. So in the first example, the context isn't being pushed to the stack when callbacks are created. But I thought that was the whole purpose of using async-listener in the first place?

Welp: https://github.com/othiym23/node-continuation-local-storage/blob/4b5cfc4f47d97611fc5238e18c8b5abf2d5bb669/context.js#L168 It isn't pushing anything to the stack when the callbacks are created! It's just getting a reference to the current context...

Let's patch it up to push the context for each callback created:

--- a/context.js    2016-06-03 01:57:31.000000000 -0700
+++ b/context.js    2016-06-03 01:57:46.000000000 -0700
@@ -165,7 +165,7 @@ function create(name) {

   var namespace = new Namespace(name);
   namespace.id = process.addAsyncListener({
-    create : function () { return namespace.active; },
+    create : function () { return namespace.createContext(); },
     before : function (context, storage) { if (storage) namespace.enter(storage); },
     after  : function (context, storage) { if (storage) namespace.exit(storage); },
     error  : function (storage) { if (storage) namespace.exit(storage); }

Run the first example with the patch and ... problem solved! :tada:

One more test just to ensure the nested functions aren't doing something funny ... I should be able to use this patch with functions defined in a separate scope and it should still work the same:

"use strict";

const cls = require('continuation-local-storage');
let ns = cls.createNamespace('test');

const tee   = "\u251c\u2500\u2500";
const angle = "\u2514\u2500\u2500";
const pipe  = "\u2502";

function output(log) {
    log.forEach(function (line) {
        console.log(line);
    });
}

ns.run(function () {
    let log = [];

    function fn1() {
        let first = ns.get('value');
        ns.set('value', 1);
        log[1] = `${tee} first: ${first} -> ${ns.get('value')}`;

        setTimeout(fn3, 200);
    }

    function fn2() {
        let second = ns.get('value');
        ns.set('value', 2);
        log[3] = `${angle} second: ${second} -> ${ns.get('value')}`;

        setTimeout(fn4, 200);
    }

    function fn3() {
        let third = ns.get('value');
        ns.set('value', 3);
        log[2] = `${pipe}   ${angle} third: ${third} -> ${ns.get('value')}`;
    }

    function fn4() {
        let fourth = ns.get('value');
        ns.set('value', 4);
        log[4] = `    ${angle} fourth: ${fourth} -> ${ns.get('value')}`;

        output(log);
    }

    ns.set('value', 0);
    log[0] = `start: -> ${ns.get('value')}`;

    setTimeout(fn1, 100);
    setTimeout(fn2, 200);
});

The patch even works with this variant, so async-listener is doing its job at the setTimeout calls, not on function declaration. perfect

[Jeff-Lewis]

@parasyte interesting find! How does it do with cls's tests?

[parasyte]

@Jeff-Lewis I was super lazy and didn't run the test suite last night...

I'm getting 5 test failures on master (just after clone, not patched yet) node 6.2.1, OSX 10.11.5: https://gist.github.com/parasyte/78792c38d628b2ef619c3041871e2b3b

Hmm, same failures on Ubuntu 14.04 and node 4.4.5 ...

Well, anyway... There is one new failure with the patch:

test/nesting.tap.js ................................. 17/18
  the example from the docs
  not ok writer.active == outer
    +++ found
    --- wanted
    -{
    -  "value": 1
    -}
    +{}
    compare: ===
    at:
      line: 52
      column: 13
      file: test/nesting.tap.js
    stack: |
      test/nesting.tap.js:52:13
      node_modules/async-listener/glue.js:188:31
      _combinedTickCallback (internal/process/next_tick.js:67:7)
      process._tickCallback (internal/process/next_tick.js:98:9)
    source: |
      t.equal(writer.active, outer, "writer.active == outer");

So process.nextTick() is expecting the context to be identical inside and outside of the callback. The context value should be the same, but the reference should not necessarily be identical, like this:

process.nextTick(function () {
  t.equal(writer.active.value, outer.value, "writer.active.value == outer.value");
});

Give me a bit and I'll submit a PR with tests.

[overlookmotel]

@parasyte In my opinion, your first example is the desired behavior.

CLS guarantees that once a context is bound (with ns.run() or ns.bind()) it will then be propagated to all callbacks that follow from within the bound function. But it doesn't claim to or attempt to create a new context for every callback.

ns.run() creates a "fork" in the context. i.e. it says "all code that executes from this function synchronously or asyncronously is in this context".

Probably the most common use case for CLS is setting a unique ID for each request received by an HTTP server. So then e.g. any console.log output can include the requestId, allowing you sift a log to trace what happened in a single request/response cycle.

In such cases, the requestId is only set once and thereafter is read-only. So it's totally fine for the context to be the same for all branches of async action that start from the point where ns.run() is called.

If you want to fork the context, you can always do so with a 2nd ns.run() call.

CLS is on a very hot code path. I expect that the performance impact of creating a new context on every single callback could be pretty bad.

[overlookmotel]

I think this would be a more common example of kind of structure that CLS supports, and demonstrates it's usefulness (note the addition of 2nd ns.run()):

"use strict";

const cls = require('continuation-local-storage');
let ns = cls.createNamespace('test');

const tee   = "\u251c\u2500\u2500";
const angle = "\u2514\u2500\u2500";
const pipe  = "\u2502";

let log = [];

function output(log) {
    log.forEach(function (line) {
        console.log(line);
    });
}

ns.run(function () {
    ns.set('value', 0);
    log[0] = `start: -> ${ns.get('value')}`;

    setTimeout(function () {
        let first = ns.get('value');
        ns.set('value', 1);
        log[1] = `${tee} first: ${first} -> ${ns.get('value')}`;

        setTimeout(function () {
            let third = ns.get('value');
            ns.set('value', 3);
            log[2] = `${pipe}   ${angle} third: ${third} -> ${ns.get('value')}`;
        }, 200);
    }, 100);
});

ns.run(function () {
    ns.set('value', 0);

    setTimeout(function () {
        let second = ns.get('value');
        ns.set('value', 2);
        log[3] = `${angle} second: ${second} -> ${ns.get('value')}`;

        setTimeout(function () {
            let fourth = ns.get('value');
            ns.set('value', 4);
            log[4] = `    ${angle} fourth: ${fourth} -> ${ns.get('value')}`;

            output(log);
        }, 200);
    }, 200);
});

The two blocks inside ns.run() calls are analogous to two requests hitting a server simultaneously.

This would produce your desired output:

start: -> 0
├── first: 0 -> 1
│   └── third: 1 -> 3
└── second: 0 -> 2
    └── fourth: 2 -> 4

NB this is better than you'd get from the mock you provided.

Am I making any sense? This stuff is quite hard to get your head around. And when you try to reason how it should behave with promises... ahahahahaaa!

[parasyte]

CLS guarantees that once a context is bound (with ns.run() or ns.bind()) it will then be propagated to all callbacks that follow from within the bound function. But it doesn't claim to or attempt to create a new context for every callback.

Ah! Thanks @overlookmotel, that makes perfect sense. I misunderstood the subtlety of where run is expected to be used in the callback chain, and its interaction with async-listener.

As for how to reason about CLS behavior with promises, that's easy! "Convention 1" that you described in #64 is the obvious expected behavior. To quote one of the Promises/A+ authors:

... then is not a mechanism for attaching callbacks to an aggregate collection. It’s a mechanism for applying a transformation to a promise, and yielding a new promise from that transformation.

Convention 1 is the only one of the three which behaves as a transformation. But I digress!

Thanks again for clearing up my understanding of CLS! This ticket (and the linked PR) are irrelevant.

[overlookmotel]

No worries. Glad I could help.

Concerning your opinion on which is the right convention for cls/promises, would you mind making your views known in a comment on #64? It'd be good to get some discussion going and/or people's views to be there for anyone who comes across the thread later on.