Lock session TTL never gets renewed about node-consul

[silas]

Mind adding the exact options you're using and the version of consul and node-consul.

[danwkennedy]

Here's an example of what I'm sending:

{
    key: `my-key`,
    value: `my-leader-value`,
    session: {
      lockdelay: '1s',
      checks: ['serfHealth'],
      name: 'leader-election',
      ttl: '10s'
    }
  }

[jwalton]

I think I might be running into this same problem. I wrote this handy little class:

class Distributed {
    ...
    
    electLeader(key) {
        const lock = this.consulClient.lock({
            key: `${this.deployKey}/leader/${key}`,
            session: {
                name: `${this.deployKey}-${key}`,
                ttl: "15s"
            },
        });

        lock.acquire();
        return lock;
    }
        
    withLock(key, fn) {
        const deferred = promiseTools.defer();
        let done = false;
        const lock = this.electLeader(key);

        lock.on('acquire', () => {
            if (done) {return;}
            done = true;

            return Promise.resolve()
            .then(fn)
            .then(
                result => {
                    lock.release();
                    deferred.resolve(result);
                },
                err => {
                    lock.release();
                    deferred.reject(err);
                }
            );
        });

        lock.on('err', err => {
            if (done) {return;}
            done = true;
            log.error({err: err}, "Error acquiring upgrade lock");
            deferred.error(err);
        });

        return deferred.promise;
    };
}

So I can do distributed.withLock(() => /* do stuff here */). And today I discovered in my logs:

ERROR: ./l/app: Potentially Unhandled Rejection at: Promise [object Promise]
  err: Error: no lock in use
      at create (./node_modules/consul/lib/errors.js:14:5)
      at Object.validation (./node_modules/consul/lib/errors.js:26:15)
      at Lock.release (./node_modules/consul/lib/lock.js:110:32)

Which sounds a bit terrifying. :P I'm on node-consul 0.28.0, and consul 0.7.2.

[jwalton]

Hmm... I tried running my "withLock()" with a 15 minute delay in the middle, and it worked correctly. Maybe I'm just doing too much stuff and starving out sending the session update. I'll try again with a longer-than-15s session timeout.

[jwalton]

Ok, with some console.logging, I've discovered a little more about what's going on:

Apr 19 16:51:57 [89211] INFO:  ./l/s/u/Upgrader: Waiting for upgrade lock...

...

**** lock.monitor error { Error: consul: kv.get: request timed out (16000ms)
    at create (/Users/jwalton/benbria/loop-common/node_modules/papi/lib/errors.js:14:5)
    at Object.timeout (/Users/jwalton/benbria/loop-common/node_modules/papi/lib/errors.js:62:15)
    at ClientRequest.<anonymous> (/Users/jwalton/benbria/loop-common/node_modules/papi/lib/client.js:532:20)
    at emitNone (events.js:86:13)
    at ClientRequest.emit (events.js:185:7)
    at Timeout.<anonymous> (/Users/jwalton/benbria/loop-common/node_modules/papi/lib/client.js:520:11)
    at ontimeout (timers.js:365:14)
    at tryOnTimeout (timers.js:237:5)
    at Timer.listOnTimeout (timers.js:207:5)
 isPapi: true, isTimeout: true }
**** lock.monitor error { Error: consul: kv.get: request aborted
    at create (/Users/jwalton/benbria/loop-common/node_modules/papi/lib/errors.js:14:5)
    at Object.abort (/Users/jwalton/benbria/loop-common/node_modules/papi/lib/errors.js:50:15)
    at Watch.abort (/Users/jwalton/benbria/loop-common/node_modules/papi/lib/client.js:511:32)
    at Watch.g (events.js:291:16)
    at emitNone (events.js:86:13)
    at Watch.emit (events.js:185:7)
    at Watch.end (/Users/jwalton/benbria/loop-common/node_modules/consul/lib/watch.js:84:8)
    at /Users/jwalton/benbria/loop-common/node_modules/consul/lib/lock.js:315:17
    at Timeout._onTimeout (/Users/jwalton/benbria/loop-common/node_modules/consul/lib/utils.js:198:33)
    at ontimeout (timers.js:365:14)
    at tryOnTimeout (timers.js:237:5)
    at Timer.listOnTimeout (timers.js:207:5)
 isPapi: true, isAbort: true }
**** lock.monitor end
**** Lock._end() err=undefined
Apr 19 16:52:16 [89211] ERROR: /U/j/b/l/l/distributed: End for held lock!

So the monitor created by the Lock is timing out, and as a result my lock emits an "end" with no "error" out from under me.

[silas]

@jwalton Yeah, the lock error event is for error reporting and not really useful for tracking the status of the lock. You want to listen to lock.on('end') and immediately assume the lock is lost/released when that's emitted.

It would be useful to look at the consul logs for the agent when the timeout occurred, it might shed some light into why the timeout is happening.

Also, FYI, you can get really detailed logs from the consul http client by listening on log.

Example:

var consul = require('consul')();
consul.on('log', console.log);