Tedious: Library (node-mssql) doesnt recover after db outage

Created on 7 Sep 2018 · 19Comments · Source: tediousjs/tedious

I have an issue i cannot find a solution for (https://github.com/tediousjs/node-mssql/issues/701), and I would like to try here as well, maybe someone could help.
I am using node-mssql, and my problem is that if the database goes down, and then recovers, the library doesn't recover and keeps returning TimeoutError: ResourceRequest timed out. I have enabled debugging, and what i see is that, after the database is up again, a prelogin message is sent, and the socket is ended. Compared to at the beginning, when the database is up, it responds to the prelogin:

connected to localhost:1433

Received
type:0x04(TABULAR_RESULT), status:0x01(EOM), length:0x002B, spid:0x0000, packetId:0x01, window:0x00
0000 00001A00 06010020 00010200 21000103 00220000 04002200 01FF0E00 0BDD0000 ....... ....!... ."....". ........
0020 020000 ...
PreLogin - version:14.0.11.221 0, encryption:0x02(NOT_SUP), instopt:0x00, threadId:0x00000000, mars:0x00(OFF)

..... (stop & start the database)

onPoolError listener
Failed to connect to localhost:1433 - Could not connect (sequence)
State change: Connecting -> Final
names err: TimeoutError: ResourceRequest timed out
at ResourceRequest._fireTimeout (/Users/alex/projects/sofy-unit2/node_modules/generic-pool/lib/ResourceRequest.js:62:17)
at Timeout.bound (/Users/alex/projects/sofy-unit2/node_modules/generic-pool/lib/ResourceRequest.js:8:15)
at ontimeout (timers.js:475:11)
at tryOnTimeout (timers.js:310:5)
at Timer.listOnTimeout (timers.js:270:5)
onPoolError listener
Failed to connect to localhost:1433 - Could not connect (sequence)
State change: Connecting -> Final
next
connected to localhost:1433

Sent
type:0x12(PRELOGIN), status:0x01(EOM), length:0x002F, spid:0x0000, packetId:0x01, window:0x00
0000 00001A00 06010020 00010200 21000103 00220004 04002600 01FF0000 00010001 ....... ....!... ."....&. ........
0020 02000000 000000 .......
PreLogin - version:0.0.0.1 1, encryption:0x02(NOT_SUP), instopt:0x00, threadId:0x00000000, mars:0x00(OFF)
State change: Connecting -> SentPrelogin
socket ended
State change: SentPrelogin -> Final
connection to localhost:1433 closed
State is already Final
names err: TimeoutError: ResourceRequest timed out
at ResourceRequest._fireTimeout (/Users/alex/projects/sofy-unit2/node_modules/generic-pool/lib/ResourceRequest.js:62:17)
at Timeout.bound (/Users/alex/projects/sofy-unit2/node_modules/generic-pool/lib/ResourceRequest.js:8:15)
at ontimeout (timers.js:475:11)
at tryOnTimeout (timers.js:310:5)
at Timer.listOnTimeout (timers.js:270:5)

This is the code i am testing with:

index.js

const app = require('./app');
app(3);

app.js

const sql = require('mssql');

class Repo {
    constructor(connectionPool) {
        /**
         * @private
         */
        this.connectionSett = connectionPool;
    }

    async names() {
        const pool = await this.connectionSett;

        const queryRes = await pool
            .request()
            .query(
                'select name from names'
            );

        return queryRes['recordset'].map(r => r.name);
    }
}

function createConn() {
    const user = 'sa';
    const password = 'P@55w0rd';
    const server = 'localhost';
    const database = 'test';

    const pool = new sql.ConnectionPool({user, password, server, database, debug: true, pool: {acquireTimeoutMillis: 5000}});

    pool.on('error', err => {
        console.error('onPoolError listener');
        //console.error(err);
    });

    pool.on('debug', (connection, message) => {
        //console.log(connection);
        console.log(message);
    });

    return pool.connect();
}

module.exports = (
    intervalSeconds,
    repo = new Repo(createConn())
) => {
    const main = () => run().catch(console.error);
    main();
    setInterval(
        main,
        intervalSeconds * 1000
    );

    async function run() {
        console.log("next");

        await repo.names()
            .then(res => console.log(`names res: ${res}`))
            .catch(err => console.error(`names err: ${err.stack}`));
    }
};

Idle

Source

madal3x

Most helpful comment

Hey @madal3x, this issue is fixed by PR https://github.com/tediousjs/tedious/pull/769. I tested the PR with your repro code in docker, driver throws connection lost error and cleans things up. Issue you see in tediousjs/node-mssql should vanish once #769 gets merged.

Suraiya-Hameed on 19 Sep 2018

🎉1 👍1

All 19 comments

@madal3x Can you try reproducing this issue directly via tedious? If you are able to connect from tedious after db recovery, then origin of issue must be either generic-pool or node-mssql.

Suraiya-Hameed on 13 Sep 2018

@Suraiya-Hameed yes, true, though i thought one would replace the connection if it had an error. So i recreated the scenario just by using tedious, starting the script when db is up, then stopping the db and starting it again while the script was running. And the results were that after the db was up, the library kept outputting the same error:

RequestError: Requests can only be made in the LoggedIn state, not the Final state
at RequestError (/Users/alex/projects/sofy-unit2/node_modules/tedious/lib/errors.js:34:12)
at Connection.makeRequest (/Users/alex/projects/sofy-unit2/node_modules/tedious/lib/connection.js:1584:26)
at Connection.execSql (/Users/alex/projects/sofy-unit2/node_modules/tedious/lib/connection.js:1347:12)
at Promise (/Users/alex/projects/sofy-unit2/testpromise/app-tedious.js:66:24)
at new Promise ()
at Repo.names (/Users/alex/projects/sofy-unit2/testpromise/app-tedious.js:17:16)
at
at process._tickCallback (internal/process/next_tick.js:188:7)

In the process i've discovered that the request.on('done') was not called, but the doneInProc and doneProc were called. Unfortunately these were called with the value of rows being an empty array. Therefore I had to aggregate the rows inside the row event for request.

Code:

app.js

const Connection = require('tedious').Connection;
const Request = require('tedious').Request;

class Repo {
    constructor(connection) {
        /**
         * @private
         * @type {Promise<Connection>}
         */
        this.connection = connection;
    }

    async names() {
        const connection = await this.connection;
        const allRows = [];

        return new Promise(((resolve, reject) => {
            const request = new Request("select name from names", function(err, rowCount) {
                if (err) {
                    return reject(err);
                } else {
                    console.log(rowCount + ' rows');
                }
            });

            request.on('row', function(columns) {
                console.log('onRow');

                columns.forEach(function(column) {
                    const row = [];
                    row.push({
                        metadata: column.metadata,
                        value: column.value,
                        toString: () => column.value
                    });
                    allRows.push(row);
                });
            });

            /*
            request.on('done', function(rowCount, more) {
                console.log('onDone');

                return resolve(rows);
            });
            */

            /*
            request.on('doneInProc', function (rowCount, more, rows) {
                console.log('onDoneInProc');

                console.log(rows);

                return resolve(rows);
            });
            */

            request.on('doneProc', function (rowCount, more, returnStatus, rows) {
                console.log('onDoneProc');

                //console.log(rows);

                return resolve(allRows);
            });

            connection.execSql(request);
        }));
    }
}

/**
 *
 * @return {Promise<Connection>}
 */
function createConn() {
    const user = 'sa';
    const password = 'P@55w0rd';
    const server = 'localhost';
    const database = 'test';

    const config = {
        server: server,
        userName: user,
        password: password,
        options: {
          debug: {
            packet: true,
            data: true,
            payload: true,
            token: false,
            log: true
          },
          database: database,
          //encrypt: true // for Azure users
        }
    };

    const connection = new Connection(config);

    connection.on('errorMessage', err => {
        console.error('onError')
        //console.error(err);
    });

    return new Promise(((resolve, reject) => {
        connection.on('connect', err => {
            if (err) {
                console.error('onConnectionError');

                reject(err)
            } else {
                resolve(connection);
            }
        });
    }));
}

module.exports = (
    intervalSeconds,
    repo = new Repo(createConn())
) => {
    const main = () => run().catch(console.error);
    main();
    setInterval(
        main,
        intervalSeconds * 1000
    );

    async function run() {
        console.log("next");

        await repo.names()
            .then(res => console.log(`names res: ${res}`))
            .catch(err => console.error(`names err: ${err.stack}`));
    }
};

index.js

const app = require('./app');
app(3);

madal3x on 13 Sep 2018

👍1

The moment I take db offline, I get ConnectionError: Connection lost - read ECONNRESET from the repro code. Is there any special settings you have in place? Because if the db is offline, I assume it is natural for driver to throw Connection lost message, but you are getting a RequestError, which doesn't make sense.

Is the data set you're reading very large?

btw, I tried taking db offline both via SSMS and T-SQL.

Suraiya-Hameed on 18 Sep 2018

The dataset has one row. The db is a docker container that i stop through kitematic. The only client code that i am running is the one i posted above.

madal3x on 18 Sep 2018

Are you referring to SQL Server in this line?

The db is a docker container that i stop through kitematic.

When I mention db, I'm referring to the individual database inside the Server. Can you share tedious debug logs? Enable them in connection config

options: {
    debug: {
    packet:  true,
    data:  true,
    payload:  true,
    token:  true,
    log:  true
    }
}

Suraiya-Hameed on 18 Sep 2018

👍1

Yes, i was referring to the SQL Server which is in the docker container.

I have attached the stdout and stderr piped to a log file, starting with SQL Server running, stopping after ~5 seconds, and starting again after 2-3 seconds and leaving it for another 10-15 seconds (with SQL server restarted, up and running).
tedious.log

madal3x on 18 Sep 2018

Thanks for the logs.

Expected behaviour when Server stops is for the driver to throw connection error, as socket gets closed. From the logs you shared, I see that socket has ended, but for some reason connection is not getting cleaned up. It would be great if you can add some debug statements in cleanupConnection and see why closeConnection is not getting called.
https://github.com/tediousjs/tedious/blob/d5b9a7c0a9416bb4f6611e8ded8d2594330a10c9/src/connection.js#L528-L533

I don't have a SQL Server on docker setup so can't debug it right now. Cleanup is working fine with the local server I have.

Suraiya-Hameed on 18 Sep 2018

What debug statements would you add here?

I have used the tutorial here to install SQL Server on OSx: https://medium.com/@reverentgeek/sql-server-running-on-a-mac-3efafda48861

madal3x on 18 Sep 2018

Suraiya-Hameed on 19 Sep 2018

🎉1 👍1

Hi Suraiya, that’s awesome, thanks a lot :)

madal3x on 20 Sep 2018

@Suraiya-Hameed Should this issue be closed then?

kibertoad on 21 Oct 2018

Sorry, i found now the time to test this. I tested with 2.7.1 and it seems it still doesn't recover after stopping and starting again the db. This is the output:

connected to localhost:1433
State change: Connecting -> SentPrelogin
State change: SentPrelogin -> SentLogin7WithStandardLogin
Packet size changed from 4096 to 4096
State change: SentLogin7WithStandardLogin -> LoggedInSendingInitialSql
State change: LoggedInSendingInitialSql -> LoggedIn
State change: LoggedIn -> SentClientRequest
onRow
onDoneProc
State change: SentClientRequest -> LoggedIn
1 rows
names res: Alex
next
State change: LoggedIn -> SentClientRequest
onRow
onDoneProc
State change: SentClientRequest -> LoggedIn
1 rows
names res: Alex
next
State change: LoggedIn -> SentClientRequest
onRow
onDoneProc
State change: SentClientRequest -> LoggedIn
1 rows
names res: Alex
next
State change: LoggedIn -> SentClientRequest
onRow
onDoneProc
State change: SentClientRequest -> LoggedIn
1 rows
names res: Alex
socket ended
Connection lost - socket hang up
onConnectionError2
{ ConnectionError: Connection lost - socket hang up
    at ConnectionError (/Users/alex/projects/sofy-unit2/node_modules/tedious/lib/errors.js:12:12)
    at Connection.socketError (/Users/alex/projects/sofy-unit2/node_modules/tedious/lib/connection.js:1028:28)
    at Connection.socketEnd (/Users/alex/projects/sofy-unit2/node_modules/tedious/lib/connection.js:1047:14)
    at Socket.<anonymous> (/Users/alex/projects/sofy-unit2/node_modules/tedious/lib/connection.js:884:18)
    at emitNone (events.js:111:20)
    at Socket.emit (events.js:208:7)
    at endReadableNT (_stream_readable.js:1055:12)
    at _combinedTickCallback (internal/process/next_tick.js:138:11)
    at process._tickCallback (internal/process/next_tick.js:180:9) message: 'Connection lost - socket hang up', code: 'ESOCKET' }
State change: LoggedIn -> Final
connection to localhost:1433 closed
State is already Final
next
Requests can only be made in the LoggedIn state, not the Final state
names err: RequestError: Requests can only be made in the LoggedIn state, not the Final state
    at RequestError (/Users/alex/projects/sofy-unit2/node_modules/tedious/lib/errors.js:34:12)
    at Connection.makeRequest (/Users/alex/projects/sofy-unit2/node_modules/tedious/lib/connection.js:1606:26)
    at Connection.execSql (/Users/alex/projects/sofy-unit2/node_modules/tedious/lib/connection.js:1369:12)
    at Promise (/Users/alex/projects/sofy-unit2/testpromise/app-tedious.js:66:24)
    at new Promise (<anonymous>)
    at Repo.names (/Users/alex/projects/sofy-unit2/testpromise/app-tedious.js:17:16)
    at <anonymous>
    at process._tickCallback (internal/process/next_tick.js:188:7)
next
Requests can only be made in the LoggedIn state, not the Final state
names err: RequestError: Requests can only be made in the LoggedIn state, not the Final state
    at RequestError (/Users/alex/projects/sofy-unit2/node_modules/tedious/lib/errors.js:34:12)
    at Connection.makeRequest (/Users/alex/projects/sofy-unit2/node_modules/tedious/lib/connection.js:1606:26)
    at Connection.execSql (/Users/alex/projects/sofy-unit2/node_modules/tedious/lib/connection.js:1369:12)
    at Promise (/Users/alex/projects/sofy-unit2/testpromise/app-tedious.js:66:24)
    at new Promise (<anonymous>)
    at Repo.names (/Users/alex/projects/sofy-unit2/testpromise/app-tedious.js:17:16)
    at <anonymous>
    at process._tickCallback (internal/process/next_tick.js:188:7)
next
Requests can only be made in the LoggedIn state, not the Final state
names err: RequestError: Requests can only be made in the LoggedIn state, not the Final state
    at RequestError (/Users/alex/projects/sofy-unit2/node_modules/tedious/lib/errors.js:34:12)
    at Connection.makeRequest (/Users/alex/projects/sofy-unit2/node_modules/tedious/lib/connection.js:1606:26)
    at Connection.execSql (/Users/alex/projects/sofy-unit2/node_modules/tedious/lib/connection.js:1369:12)
    at Promise (/Users/alex/projects/sofy-unit2/testpromise/app-tedious.js:66:24)
    at new Promise (<anonymous>)
    at Repo.names (/Users/alex/projects/sofy-unit2/testpromise/app-tedious.js:17:16)
    at <anonymous>
    at process._tickCallback (internal/process/next_tick.js:188:7)
next
Requests can only be made in the LoggedIn state, not the Final state
names err: RequestError: Requests can only be made in the LoggedIn state, not the Final state
    at RequestError (/Users/alex/projects/sofy-unit2/node_modules/tedious/lib/errors.js:34:12)
    at Connection.makeRequest (/Users/alex/projects/sofy-unit2/node_modules/tedious/lib/connection.js:1606:26)
    at Connection.execSql (/Users/alex/projects/sofy-unit2/node_modules/tedious/lib/connection.js:1369:12)
    at Promise (/Users/alex/projects/sofy-unit2/testpromise/app-tedious.js:66:24)
    at new Promise (<anonymous>)
    at Repo.names (/Users/alex/projects/sofy-unit2/testpromise/app-tedious.js:17:16)
    at <anonymous>
    at process._tickCallback (internal/process/next_tick.js:188:7)
next
Requests can only be made in the LoggedIn state, not the Final state
names err: RequestError: Requests can only be made in the LoggedIn state, not the Final state
    at RequestError (/Users/alex/projects/sofy-unit2/node_modules/tedious/lib/errors.js:34:12)
    at Connection.makeRequest (/Users/alex/projects/sofy-unit2/node_modules/tedious/lib/connection.js:1606:26)
    at Connection.execSql (/Users/alex/projects/sofy-unit2/node_modules/tedious/lib/connection.js:1369:12)
    at Promise (/Users/alex/projects/sofy-unit2/testpromise/app-tedious.js:66:24)
    at new Promise (<anonymous>)
    at Repo.names (/Users/alex/projects/sofy-unit2/testpromise/app-tedious.js:17:16)
    at <anonymous>
    at process._tickCallback (internal/process/next_tick.js:188:7)
next
Requests can only be made in the LoggedIn state, not the Final state
names err: RequestError: Requests can only be made in the LoggedIn state, not the Final state
    at RequestError (/Users/alex/projects/sofy-unit2/node_modules/tedious/lib/errors.js:34:12)
    at Connection.makeRequest (/Users/alex/projects/sofy-unit2/node_modules/tedious/lib/connection.js:1606:26)
    at Connection.execSql (/Users/alex/projects/sofy-unit2/node_modules/tedious/lib/connection.js:1369:12)
    at Promise (/Users/alex/projects/sofy-unit2/testpromise/app-tedious.js:66:24)
    at new Promise (<anonymous>)
    at Repo.names (/Users/alex/projects/sofy-unit2/testpromise/app-tedious.js:17:16)
    at <anonymous>
    at process._tickCallback (internal/process/next_tick.js:188:7)
next
Requests can only be made in the LoggedIn state, not the Final state
names err: RequestError: Requests can only be made in the LoggedIn state, not the Final state
    at RequestError (/Users/alex/projects/sofy-unit2/node_modules/tedious/lib/errors.js:34:12)
    at Connection.makeRequest (/Users/alex/projects/sofy-unit2/node_modules/tedious/lib/connection.js:1606:26)
    at Connection.execSql (/Users/alex/projects/sofy-unit2/node_modules/tedious/lib/connection.js:1369:12)
    at Promise (/Users/alex/projects/sofy-unit2/testpromise/app-tedious.js:66:24)
    at new Promise (<anonymous>)
    at Repo.names (/Users/alex/projects/sofy-unit2/testpromise/app-tedious.js:17:16)
    at <anonymous>
    at process._tickCallback (internal/process/next_tick.js:188:7)

madal3x on 22 Oct 2018

@madal3x Thanks for testing it! Can you double check the tedious version being tested? I get the error you posted on versions prior to 2.7.1 and not in 2.7.1 😅

Suraiya-Hameed on 23 Oct 2018

@Suraiya-Hameed I have reconfirmed that the version i am using is indeed 2.7.1. I can also see the code you've added for the fix in my node_modules/tedious/lib/connection.js lines 1044:1048

madal3x on 23 Oct 2018

Right, socket hang up error message was added in 2.7.1. Its hard to figure the cause since I'm not able to reproduce it 😕 which version of nodejs are you using?

Suraiya-Hameed on 24 Oct 2018

i am using node 8.9.4

madal3x on 24 Oct 2018

Hi @madal3x, are you still seeing this issue with the latest Tedious version?

IanChokS on 13 Dec 2019

Hi @IanChokS unfortunately it would be hard for me to retest this as i don't have the setup anymore and don't know if/when i would have the time.

madal3x on 14 Dec 2019

No worries, It seems like the PR #769 has fixed the issue for Suraiya, so if anyone else encounters the same problem after this fix, feel free then to reopen this issue.

IanChokS on 14 Dec 2019

Was this page helpful?

0 / 5 - 0 ratings