Node: Promise execution differs migrating from node v6.10.2 to 7.x.x (breaking existing code)

[pintux]

• Version: v7.9.0
• Platform: Darwin pxmac.local 16.5.0 Darwin Kernel Version 16.5.0: Fri Mar 3 16:52:33 PST 2017; root:xnu-3789.51.2~3/RELEASE_X86_64 x86_64
• Subsystem: Promise, Event Loop (?)

We've written an evented Finite State Automata based on Promises, see file:index.js below.
Code in samplethen.js file (see below) shows a basic usage, where a Machine (the FSA) is instantiated with two states and two "deferring" events.

Then, 6 events are "queued" (deferred) and finally Machine's state2 is entered.
After the series of process() calls we expect that all the 6 events are correctly enqueued in the Machine's deferredEvents array.

It works in all node 6.x versions, including v6.10.2 where (see console.log() lines) expected deferredEvents length is 6, and actual length is: 6.

It also works on Chrome (Version 57.0.2987.133 (64-bit)) console.

It works differently (actually, for us it doesn't work) on node versions starting from 7.0.0, where executing samplethen.js file results in expecting deferredEvents length to equal to 6, where reported actual length is always: 4.

Investigating on execution order of Promises in our Machine implementation seems that something's changed in Promises execution by node core. Could it be a bug?
Many thanks.

FILE index.js

"use strict";
class Machine {
    constructor(states = {}, initialState) {
        this.states = states;
        this.ready = Promise.resolve(true);
        this.deferredEvents = [];
        if (initialState) {
            this.ready = this.enter(initialState);
        }
    }
    defer(event) {
        return (...args) => {
            this.deferredEvents.push({ event, args });
        };
    }
    flushDeferred() {
        let p = Promise.resolve();
        if (this.deferredEvents.length) {
            let e = this.deferredEvents;
            this.deferredEvents = [];
            e.forEach(e => {
                p = p.catch(() => { }).then(() => this.process(e.event, ...e.args));
            });
        }
        return p.catch(() => { });
    }
    process(name, ...args) {        
        if (name) {
            let handler;
            if (this.state && this.states[this.state]) {
                let tmp = this.states[this.state][name] || this.states[this.state]['*'];
                switch (tmp) {
                    case 'defer':
                        handler = this.defer(name);
                        break;
                    case 'noop':
                        handler = () => { };
                        break;
                    default:
                        handler = tmp;
                        break;
                }
            }
            if (handler) {
                this.lastEvent = name;
                return Promise.resolve(handler.apply(this, args));
            }
            else {
                return Promise.reject(new Error('unhandled'));
            }
        }
        else {
            return Promise.reject(new Error('bad_event'));
        }
    }
    enter(state, ...args) {
        if (!state) {
            return Promise.reject(new Error('invalid_state'));
        }
        let oldState = this.state ? this.states[this.state] : undefined;
        let newState = this.states[state];
        if (this.state === state) {
            return Promise.resolve(true);
        }
        else if (!newState) {
            return Promise.reject(new Error('unknown_state'));
        }
        else {
            let p = Promise.resolve(true);
            p = p.then(() => {
                if (oldState && oldState.exit) {
                    return Promise.resolve(oldState.exit.apply(this, args));
                }
            });
            this.state = state;
            p = p.then(() => {
                if (newState.entry) {
                    return Promise.resolve(newState.entry.apply(this, args));
                }
            });
            return p.then(() => this.flushDeferred());
        }
    }
    eventHandler(nameOrStateHandlers) {
        return (...args) => {
            if (typeof (nameOrStateHandlers) === 'string') {
                return this.process(nameOrStateHandlers, ...args);
            }
            else {
                if (this.state && nameOrStateHandlers[this.state]) {
                    return Promise.resolve(nameOrStateHandlers[this.state].apply(this, args));
                }
                else if (nameOrStateHandlers['*']) {
                    return Promise.resolve(nameOrStateHandlers['*'].apply(this, args));
                }
                else {
                    return Promise.reject(new Error('unhandled'));
                }
            }
        };
    }
    callbackEventHandler(nameOrStateHandlers) {
        let h = this.eventHandler(nameOrStateHandlers);
        return (...args) => {
            if (args.length && typeof args[args.length - 1] === 'function') {
                let cb = args.pop();
                h(args).then((...args) => {
                    cb(null, ...args);
                }, err => {
                    cb(err);
                });
            }
            else {
                h(...args);
            }
        };
    }
}
exports.Machine = Machine;

FILE samplethen.js

const Machine = require('./index').Machine

let m = new Machine({
    state1: {
        event1: 'defer',
        event2: 'defer'
    },
    state2: {
        event1: () => { throw new Error('a') },
        event2: () => "hello state2-event2",
    }
}, 'state1');

m.process('event2')
    .then(() => m.process('event1'))
    .then(() => m.process('event2'))
    .then(() => m.process('event1'))
    .then(() => m.process('event2'))
    .then(() => m.process('event1'))
    .then(() => {
        console.log('\nDeferred Events')
        console.log('   array: ', m.deferredEvents);
        console.log('   expected length: 6, actual: ',m.deferredEvents.length);
        m.enter('state2').then(() => {
            console.log('\n Deferred Events')
            console.log('   array: ', m.deferredEvents);
            console.log('   expected length: 0, actual:', m.deferredEvents.length);
        });
    });

[evanlucas]

@pintux I went ahead and updated your post to include proper formatting to make the code snippets more readable.

[addaleax]

You are racing two promise chains against each other – that’s kind of bound to go wrong.

Anyway, here’s a reduced version:

function process(name) {
  console.log(name);
  return Promise.resolve(); // removing this line gives consistent behaviour
}

Promise.resolve()
  .then(() => {})
  .then(() => {})
  .then(() => console.log('flush'));

Promise.resolve()
  .then(() => process('event1'))
  .then(() => process('event2'))
  .then(() => process('event1'));

I’m not sure whether this is a bug or not.

[Fishrock123]

cc @domenic or @bmeck? I'm not sure what the behavior should be and if anything is wrong.

[bmeck]

return Promise.resolve(); // removing this line gives consistent behaviour

Adds ticks as per spec, not sure that reduced test case is correct.

@pintux do you have a minimal test case?

[addaleax]

@bmeck It still exposes the same difference between Node v6 and Node v7 that the original issue description here provides.

Also, bisecting node yields 90efff6000ea24641417cd0c700b60281cd2d453 (V8 5.4.500.27), I’ll try to bisect V8 now.

[bmeck]

@addaleax i'm pretty sure that is v8 just adopting Promise state without new ticks in the newer version.

[addaleax]

@bmeck Are you saying that that is the bug here? Is it a bug?

[bmeck]

I don't think so

[addaleax]

Ok, looks like this is just a V8 change that’s not forbidden by the spec and/or even moves V8 closer to the spec. I’m closing this, but feel free to ask any follow-up questions.

Like I said above, relying on the timing of different promise chains is going to be brittle anyway, and it’s best to avoid that completely.

[pintux]

Thank you.

Anyway, rewriting the following line in process() (see index.js above):

return Promise.resolve(handler.apply(this, args));

as

return Promise.resolve().then( () => { return handler(args); } );

works as expected, resulting in the same behaviour on node v6 and v7 and on Chrome browser.