Problem with concurrent connections

[patriksimek]

Hi, first of all thanks for your efforts on making this lib up to date with latest node releases. I'm in the process of implementing support into node-mssql and during that I found some glitches. I'm going to create a separate issues for each of them.

var msnodesql = require('msnodesqlv8');
msnodesql.open("Driver={SQL Server Native Client 11.0};Server=localhost;Database=xsp;Uid=xsp_test;Pwd=...;Trusted_Connection=No;", function(err, conn1) {
    if (err) return console.error(err);

    msnodesql.open("Driver={SQL Server Native Client 11.0};Server=localhost;Database=xsp;Uid=xsp_test2;Pwd=...;Trusted_Connection=No;", function(err, conn2) {
        if (err) return console.error(err);

        conn1.query("select @@SPID as id, CURRENT_USER as name", function(err, res) {
            if (err) return console.error(err);

            console.log('CONN1', res);
        });

        conn2.query("select @@SPID as id, CURRENT_USER as name", function(err, res) {
            if (err) return console.error(err);

            console.log('CONN2', res);
        });
    });
});

Got:

CONN1 [ { id: 56, name: 'xsp_test2' } ]
CONN2 [ { id: 56, name: 'xsp_test2' } ]

Expected:

CONN1 [ { id: 56, name: 'xsp_test' } ]
CONN2 [ { id: 57, name: 'xsp_test2' } ]

This problem was not present in original msnodesql.

[TimelordUK]

thanks for the precise description of this problem - I will look at this issue first as it is perhaps the most serious. I will keep you posted with progress.

[TimelordUK]

OK, this issue should now be sorted please update from npm - it seems that this lay entirely in the javascript so I did not need to patch the driver. Unfortunately, in breaking the code down into smaller files, the connection objects returned back to the client code were not unique. I have added your snippet as the start of a new test suite in test folder.

I will take a look at the remaining 2 issues, looks like the buffer[0] one would be simpler, so I will have a go at that one first.

[patriksimek]

Thanks, found another problem with concurrent connection. When I open multiple connections at once, I always get the same connection object.

var msnodesql = require('msnodesqlv8');

var open = function(done) {
    msnodesql.open("Driver={SQL Server Native Client 11.0};Server=localhost;Database=xsp;Uid=xsp_test;Pwd=...;Trusted_Connection=No;", function(err, conn) {
        if (err) { console.error(err); process.exit(); };
        done(conn);
    });
};

var array = [];

open(function(conn1) {
    array.push(conn1);
    if (array.length === 3) done();
});

open(function(conn2) {
    array.push(conn2);
    if (array.length === 3) done();
});

open(function(conn3) {
    array.push(conn3);
    if (array.length === 3) done();
});

function done() {
    console.log(array[0] === array[1] && array[1] === array[2]);
}

Returns true, should be false.

var array = [];

open(function(conn1) {
    array.push(conn1);

    open(function(conn2) {
        array.push(conn2);

        open(function(conn3) {
            array.push(conn3);

            done();
        });
    });
});

function done() {
    console.log(array[0] === array[1] && array[1] === array[2]);
}

Result is false in this case, as expected.

[patriksimek]

I also randomly meet this error message. I was not able to create a code to reliably reproduce this yet.

[TimelordUK]

have you updated to the latest version,this should not still be happening? hmm, yes your code does still break the concurrent connection code, OK let me take another look.

[TimelordUK]

OK can you update again to 0.1.19 - these are really very good tests, I have added these to the concurrent suite, they should now pass.

[patriksimek]

Thanks, now I'm able to run most of my tests against msnodesqlv8. There is one more thing that bothers me. Consider this code:

var start = Date.now();
open(function(conn1) {
    console.log(Date.now() - start, 'a');
    process.nextTick(function() {
        console.log(Date.now() - start, 'c');
    });
    query(conn1, "waitfor delay \'00:00:02\';", function(res) {
       console.log(Date.now() - start, 'e');
    });
    console.log(Date.now() - start, 'b');
    process.nextTick(function() {
        console.log(Date.now() - start, 'd');
    });
});

Surprisingly I have this result:

80 'a'
94 'b'
2095 'e'
2095 'c'
2095 'd'

As you can see, process.nextTick is blocked for the time of executing the query. Code that led me to this was successful in original msnodesql.

If I replace process.nextTick with setImmediate, the result is as expected.

94 'a'
94 'b'
94 'c'
94 'd'
2110 'e'

[TimelordUK]

on Node 4.1.3 if I run code below (note no query call at all) I get the same effect. In pushTest in my environment if I uncomment the console.log call, the code works as expected. i.e.

using setTimeout and commented out console.log

{ seq: [ 'a', 'b', 'e', 'c', 'd' ],
delays: [ 0, 1, 2001, 2002, 2002 ] }

using setTimeout and uncommented out console.log

pushing a
pushing b
pushing c
pushing d
pushing e
{ seq: [ 'a', 'b', 'c', 'd', 'e' ],
delays: [ 1, 1, 1, 1, 2001 ] }

interesting to see if you get same result, I have not yet tried other node versions. My point is, the behavior does not seem to be due to the c++ driver, but more how Node is working? I am very new to node and javascript so still learning. But I am not sure currently I can see the C++ driver causing this issue? I get the same effect if I use the query call rather than setTimeout i.e. it works with the console.log as you expect it too but not otherwise.

0.12.7 seems to give me the same behavior in both cases above.

open(function (conn1) {

        var seq = [];
        var delays = [];
        var start = Date.now();

        function test()
        {
            var expected = ['a', 'b', 'c', 'd', 'e'];
            var state = {
                seq : seq,
                delays : delays
            }
            console.log(state);
            assert.deepEqual(expected, seq);
            test_done();
        }

        function pushTest(c) {
            //console.log('pushing ' + c);
            seq.push(c);
            delays.push(Date.now() - start);
            if (seq.length === 5) {
                test();
            }
        }

        pushTest('a');
        process.nextTick(function () {
            pushTest('c');
        });

        setTimeout(function () {
            pushTest('e');
        }, 2000);

        /*
        conn1.query("waitfor delay \'00:00:02\';", function (res) {
            pushTest('e');
        });*/

        pushTest('b');
        process.nextTick(function () {
            pushTest('d');
        });
    });

[patriksimek]

For me uncommenting the console.log changes nothing (Node 4.2.3). But if I omit the open part completly, it works.

var seq = [];
var delays = [];
var start = Date.now();

function test()
{
    var expected = ['a', 'b', 'c', 'd', 'e'];
    var state = {
        seq : seq,
        delays : delays
    }
    console.log(state);
    assert.deepEqual(expected, seq);
    test_done();
}

function pushTest(c) {
    //console.log('pushing ' + c);
    seq.push(c);
    delays.push(Date.now() - start);
    if (seq.length === 5) {
        test();
    }
}

pushTest('a');
process.nextTick(function () {
    pushTest('c');
});

setTimeout(function () {
    pushTest('e');
}, 2000);

pushTest('b');
process.nextTick(function () {
    pushTest('d');
});

Result:

{ seq: [ 'a', 'b', 'c', 'd', 'e' ],
  delays: [ 0, 0, 0, 0, 2001 ] }

I like this explanation of how process.nextTick works:

Callbacks passed to process.nextTick will usually be called at the end of the current flow of execution, and are thus approximately as fast as calling a function synchronously. Left unchecked, this would starve the event loop, preventing any I/O from occurring. setImmediates are queued in the order created, and are popped off the queue once per loop iteration. This is different from process.nextTick which will execute process.maxTickDepth queued callbacks per iteration. setImmediate will yield to the event loop after firing a queued callback to make sure I/O is not being starved.

Source: Stack-Overflow

I'm javascript/nodejs developer for quite some time and never seen similar behavior with process.nextTick before. C++ development is not my strongest part so I don't think I can help you figuring out whether it is a native lib problem or not, but please tell me if I can help you with something else.

[TimelordUK]

OK, can you update to 0.1.20 from npm and try again. I have added this test to the concurrent suite. I will have to investigate this further but it seems like the c++ calls back into node, in particular the open call need to be queued with setimmediate. In theory your code should not know the difference, as in the async api behaves the same, but the c++ driver is now no longer blocked at all.

this test now passes on my system.

[patriksimek]

Thanks, it's better now but still not perfect. I'm having the same problem when nesting callbacks.

open(function(conn1) {
    var start = Date.now();
    console.log(Date.now() - start, 'a');
    process.nextTick(function() {
        console.log(Date.now() - start, 'c');
    });
    query(conn1, "waitfor delay \'00:00:02\';", [], function(res) {
        console.log(Date.now() - start, 'e');

        console.log(Date.now() - start, 'f');
        process.nextTick(function() {
            console.log(Date.now() - start, 'h');
        });
        query(conn1, "waitfor delay \'00:00:02\';", [], function(res) {
           console.log(Date.now() - start, 'j');
        });
        console.log(Date.now() - start, 'g');
        process.nextTick(function() {
            console.log(Date.now() - start, 'i');
        });
    });
    console.log(Date.now() - start, 'b');
    process.nextTick(function() {
        console.log(Date.now() - start, 'd');
    });
});

Result:

14 'a'
14 'b'
14 'c'
14 'd'
2031 'e'
2031 'f'
2031 'g'
4047 'j' <---
4047 'h'
4047 'i'

[TimelordUK]

OK, can you update to 0.1.21 from npm and try again. I have added this test into concurrent, I have pushed all data callbacks from c++ now through setimmediate just like the open. This test now works in my environment.

[patriksimek]

Another way how to reproduce this - event handlers.

open(function(conn1) {
    var req = conn1.query("waitfor delay \'00:00:02\';");
    req.on('done', function() {
        console.log('a');
        process.nextTick(function() {
            console.log('b');
        });
        setImmediate(function() {
            console.log('d');
        });
        process.nextTick(function() {
            console.log('c');
        });
    })
});

Result:

a
d
b
c

[TimelordUK]

yes, thanks for the new test case. I have now fixed this issue and added the test case into the concurrent suite. Please update and try again. My apologies, this is quite tricky to get right to cover all cases.

[patriksimek]

Perfect, now all the tests that were passing with original msnodesql are passing with msnodesqlv8. Thanks.