memcachier / memjs

A memcache client for node using the binary protocol and SASL authentication
MIT License
197 stars 52 forks source link

Operation timeouts do not work as expected #119

Open RagnisTS opened 5 years ago

RagnisTS commented 5 years ago

I've written a small program to demonstrate the problem:

It configures the client's timeout to 1 second and then performs an operation every 0.5 seconds, each of which is expected to time out.

const memjs = require('memjs');
const net = require('net');

const wait = delay => new Promise(resolve => setTimeout(resolve, delay));
const time = () => (new Date()).getTime();

function getKey(client, key) {
    const start = time();
    return client.get(key).catch(() => {
        // Print how long it took for the operation to return a timeout error
        process.stdout.write(`${key} errored after ${time() - start} ms\n`);
    });
}

async function main() {
    const client = memjs.Client.create('localhost:9999', {
        retries: 0,
        timeout: 1, // timeout configured to 1 second
    });

    getKey(client, 'foo');

    await wait(500);
    getKey(client, 'bar');

    await wait(500);
    getKey(client, 'baz');

    await wait(500);
    getKey(client, 'qux');
}

// Create a TCP server which never responds, so that all operations against it
// will time out.
net.createServer(() => undefined).listen(9999, main);

From the output it's clearly visible that the operations did not time out after 1 second, as was expected. Instead, every new operation caused the previous one's timeout timer to be reset.

foo errored after 2511 ms
bar errored after 2007 ms
baz errored after 1506 ms
qux errored after 1005 ms

If I keep sending a steady stream of operations every 0.5 seconds, then none of them will ever time out and the callbacks will be left hanging forever.

saschat commented 5 years ago

If I understand correctly, you are delaying the callback. The timeout is for the actual Memcache operation, not what you do with the result.

RagnisTS commented 5 years ago

The error callback is not being intentionally delayed in any way. The "main" function is sending a new "GET" command every 500 ms and the error callback is printing out how long it took for the operation to return a timeout error.

Here is another example. From the output it can be seen that a new "GET" command is being sent every 500 ms, however none of the commands ever return a response nor an error.

const memjs = require('memjs');
const net = require('net');

const client = memjs.Client.create('localhost:9999', {
    retries: 0,
    timeout: 1, // timeout configured to 1 second
});

// Create a TCP server which never responds, so that all operations against it
// will time out.
net.createServer(() => undefined).listen(9999, () => {
    setInterval(() => {
        console.log('GET');

        client.get('foo')
            .then(() => console.log('never resolves'))
            .catch(() => console.log('never rejects'));
    }, 500);
});
saschat commented 5 years ago

I totally misread your example yesterday, sorry, I must have been tired.

You are right, the timeout do not work as they should in your example. It seems like each new request cancels the timeout of the previous one. My initial guess is that it has something to do with the connection setup logic (there are some calls to cancel timeouts in there). This would mean the timeout work as intended once a connection is established successfully. I will dig some more to see why this happens exactly.