Library doesn't recover after db recovers

[madal3x]

Hello,

Since i couldn't reopen #610 I am creating a new one, as according to my tests, the issue persists. I made some tests (on 4.2.1) and it seems that i cannot have the script recover after the database had errors for more than a while (1 min in my case). I've put at the end of this message the two files with which i tested, and here are the tests and the results i had:

Test1 (without setting acquireTimeoutMillis; stop and start db after 10s)

• start sql db
• run node index.js
  script is outputting the word "tick" and the content of the db table
• stop sql db and start sql db again after ~10seconds
  script is outputting the connection error and the word "tick"
  after sql db is started again, all the promises of the queries that were previously run will now resolve

Test2 (without acquireTimeoutMillis; stop and start db after >1min)

• start sql db
• run node index.js
  script is outputting the word "tick" and the content of the db table
• stop sql db and start sql db again after >1min
  script is outputting the connection error and the word "tick"
  after sql db is started again, the script continues to output "tick" without resolving nor rejecting neither the previous promises, nor new promises

Test3 (with acquireTimeoutMillis set to 10000; stop and start db after >1min)

• start sql db
• run node index.js
  script is outputting the word "tick" and the content of the db table
• stop sql db and start sql db again after >1min
  script is outputting the connection error, the word "tick"
  and the promises of queries that took longer than 10seconds to acquire a connection are rejected with the error: TimeoutError: ResourceRequest timed out
  after sql db is started again, the promises of queries continue to be rejected with the error: TimeoutError: ResourceRequest timed out

I would expect that in all these 3 types of tests, after the database is back up, to start resolving promises again. How could i achieve this, am i missing something?

index.js

process
    .on('unhandledRejection', (reason, promise) => {
        console.error(`unhandled rejection`);
        console.error(promise);
        console.error(reason);

        process.exit(1);
    })
    .on('uncaughtException', err => {
        const msg = `Uncaught exception: ${err.stack}\n exiting...`;

        console.error(msg);

        process.exit(1);
    });

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

app.js

const sql = require('mssql');

class Repo {
    constructor(connectionPool) {
        this.connectionPool = connectionPool;
    }

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

        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, pool: {acquireTimeoutMillis: 10000}});

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

    return pool.connect();
}

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

    setInterval(
        () => console.log('tick'),
        1500
    );

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

[madal3x]

I have enabled debugging, and here it how it looks like, maybe someone could see something in this. 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

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

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)

[madal3x]

I have recreated the same scenario just by using tedious and the library kept outputting: RequestError: Requests can only be made in the LoggedIn state, not the Final state. Looks like after the connection object had an error, and it went to Final state, it should be dropped/cleaned/evicted and not reused. Details in the ticket of tedious: tediousjs/tedious#788

[madal3x]

This issue should be fixed in tedious 2.7.1 (ticket tediousjs/tedious#788 PR tediousjs/tedious#769)

[willmorgan]

More recent versions of node-mssql have improved lifecycle management which I think should resolve this issue, so I'm closing it. Please upgrade to v4.2.2 (most recent at time of writing). If this doesn't improve things then please feel free to reopen.

Particularly this could have been fixed by #683.