Node-ldapjs: Paged Queries in Parallel

[jvanalst]

If you do multiple queries against the same client (or client connection pool) with paged: true the two searches seem to corrupt one another resulting in

ProtocolError: paged results cookie is invalid

As long as you limit yourself to one search at a time you're ok.

Am I doing something wrong? Is this expected behaviour? I need to know if I need to abandon the persistent connection pool and build/tear down a connection for every search.

  var _LDAPSearch = function (opts) {
    return new Promise(function (resolve, reject) {
      var client = opts.client;
      var base = opts.base;
      var options = opts.options;

      return client.search(base, options, function (err, res) {
        if (err) return reject(err);

        var entries = [];

        res.on('searchEntry', function (entry) {
          return entries.push(entry);
        });
        res.on('error', function (err) {
          if (err) sails.log.warn(err);
        });
        res.on('end', function (result) {
          if (result.errorMessage) return reject(result.errorMessage);

          return resolve(entries);
        });
      });
    });
  };

[pfmooney]

It would be useful to know the specific version of ldapjs you're using for this.
Additionally, collecting bunyan logs at the debug or trace level would help shed some light on what is occurring.

[jvanalst]

It's an LDAP v3 server (I can't give you an exact version number because we have no control over it). At least we think it's an LDAP v3 server since it does v3 things in PHP.

[jvanalst]

Proof of concept code:

var ldap = require('ldap');
var Promise = require('bluebird');
var _ = require('lodash');
var bunyan = require('bunyan');

var connectionPool = ldap.createClient({
  url: 'ldaps://directory.srv.ualberta.ca',
  //maxConnections: 10,
  secure: true,
  log: bunyan.createLogger({
    name: 'ldap',
    stream: process.stdout,
    level: 'trace'
  })
});

var _LDAPSearch = function (opts) {
  return new Promise(function (resolve, reject) {
    var client = opts.client;
    var base = opts.base;
    var options = opts.options;

    return client.search(base, options, function (err, res) {
      if (err) return reject(err);

      var entries = [];

      res.on('searchEntry', function (entry) {
        return entries.push(entry);
      });
      res.on('error', function (err) {
        if (err) console.log(err);
      });
      res.on('end', function (result) {
        if (result.errorMessage) return reject(result.errorMessage);

        return resolve(entries);
      });
    });
  });
};

Promise.all([
  _LDAPSearch({
    client: connectionPool,
    base: 'ou=calendar,dc=ualberta,dc=ca',
    options: {
      scope: 'sub',
      filter: '(&(term=1540)(facultyCode=ED))',
      paged: true
    }
  }),
  _LDAPSearch({
    client: connectionPool,
    base: 'ou=calendar,dc=ualberta,dc=ca',
    options: {
      scope: 'sub',
      filter: '(&(term=1530)(facultyCode=ED))',
      paged: true
    }
  })
]).spread(function (first, second) {
  console.log(_.pluck(first, 'object'));
  console.log(_.pluck(second, 'object'));
}).then(function () {
  connectionPool.unbind();
});

[jvanalst]

Here's the trace level log:
https://gist.github.com/jvanalst/08fd247fab17e680fc10

Here's the error output thrown:

events.js:72
throw er; // Unhandled 'error' event
^
ProtocolError: paged results cookie is invalid
at messageCallback (/Users/vanalsti/Projects/test/node_modules/ldap/lib/client/client.js:1423:40)
at Parser.onMessage (/Users/vanalsti/Projects/test/node_modules/ldap/lib/client/client.js:1089:14)
at Parser.emit (events.js:95:17)
at Parser.write (/Users/vanalsti/Projects/test/node_modules/ldap/lib/messages/parser.js:117:8)
at end (/Users/vanalsti/Projects/test/node_modules/ldap/lib/messages/parser.js:72:19)
at Parser.write (/Users/vanalsti/Projects/test/node_modules/ldap/lib/messages/parser.js:118:10)
at end (/Users/vanalsti/Projects/test/node_modules/ldap/lib/messages/parser.js:72:19)
at Parser.write (/Users/vanalsti/Projects/test/node_modules/ldap/lib/messages/parser.js:118:10)
at end (/Users/vanalsti/Projects/test/node_modules/ldap/lib/messages/parser.js:72:19)
at Parser.write (/Users/vanalsti/Projects/test/node_modules/ldap/lib/messages/parser.js:118:10)
at end (/Users/vanalsti/Projects/test/node_modules/ldap/lib/messages/parser.js:72:19)
at Parser.write (/Users/vanalsti/Projects/test/node_modules/ldap/lib/messages/parser.js:118:10)
at end (/Users/vanalsti/Projects/test/node_modules/ldap/lib/messages/parser.js:72:19)
at Parser.write (/Users/vanalsti/Projects/test/node_modules/ldap/lib/messages/parser.js:118:10)
at end (/Users/vanalsti/Projects/test/node_modules/ldap/lib/messages/parser.js:72:19)
at Parser.write (/Users/vanalsti/Projects/test/node_modules/ldap/lib/messages/parser.js:118:10)

[pfmooney]

I suspect that the LDAP server you're communicating with does not support concurrent paged requests for the same search criteria on the same connection. Paged searches in LDAP function by passing an opaque cookie back and forth between the server and the client. This cookie identifies the specific search to the server, allowing it to continue serving results where it left off in the search. Since you have two searches for the _exact same_ thing going on simultaneously, it could be that the server believes the cookie(s) you're passing back are invalid.

You will likely need to ensure, via your own custom logic, that two identical paged searches do not occur on the the same client connection simultaneously.

[jvanalst]

Alright, good to know.
I'll abandon the persistent connection pool and just build/teardown a client for every query.