InvalidAsn1Error: Expected 0x2: got 0x1

[johannish]

I'm experiencing this error after several minutes of a bad connection. The LDAP server I'm connecting to successfully establishes a TCP connection (connect event is fired and onConnect executes, removing the connectTimeout timer), but then doesn't respond for about 7 minutes, at which point I experience one of two conditions:

1. The uncaught error in the title of this issue: InvalidAsn1Error: Expected 0x2: got 0x1 or
2. This log output from my own bunyan-semi-compatible logger:
   [TRACE] { '0': { err: { [Error: read ECONNRESET] code: 'ECONNRESET', errno: 'ECONNRESET', syscall: 'read' } }, '1': 'error event: %s', '2': 'Error\n at Socket.onError ...
[TRACE] { '0': 'close event had_err=%s', '1': 'yes' }

Condition (1), which causes my application to crash, is more common. Here is a simplified excerpt of my code:

var client = ldap.createClient({
  url: 'ldap://oid:3061/',
  timeout: "2000",
  connectTimeout: "5000"
});

//...

client.bind('', '', function (err) { // anonymous bind
  if (err) {
    callback(err, null); // correctly returns `request timeout (client interrupt)`
    return;
  }
  //...
});

I can send you the wireshark output of this conversation, if you'd like.

One hack that solves this issue for me, but which is obviously incorrect, is to add conn.destroy() in function onRequestTimeout() (about line 868).

[pfmooney]

Some of the code related to timeout events has been fixed up.
If the current code is still afflicted by the symptoms you describe, please reopen the issue.

[johannish]

I can confirm that this still happens, using ldapjs@0.7.0 from npmjs.org on node v0.10.24. I am now on OS X, whereas I was using Linux the last time I reported this issue. The symptom is still the same: half the time I get: { [Error: read ECONNRESET] code: 'ECONNRESET', errno: 'ECONNRESET', syscall: 'read' } and the other half of the time I get: InvalidAsn1Error: Expected 0x2: got 0x1, which crashes my node process.

Here is the stacktrace in the case of the latter error:

/Users/raztus/myproject/node_modules/ldapjs/node_modules/asn1/lib/ber/reader.js:234
    throw newInvalidAsn1Error('Expected 0x' + tag.toString(16) +
          ^
InvalidAsn1Error: Expected 0x2: got 0x1
    at module.exports.newInvalidAsn1Error (/Users/raztus/myproject/node_modules/ldapjs/node_modules/asn1/lib/ber/errors.js:7:13)
    at Reader._readTag (/Users/raztus/myproject/node_modules/ldapjs/node_modules/asn1/lib/ber/reader.js:234:11)
    at Reader.readInt (/Users/raztus/myproject/node_modules/ldapjs/node_modules/asn1/lib/ber/reader.js:137:15)
    at Parser.getMessage (/Users/raztus/myproject/node_modules/ldapjs/lib/messages/parser.js:119:23)
    at Parser.write (/Users/raztus/myproject/node_modules/ldapjs/lib/messages/parser.js:98:22)
    at Socket.onData (/Users/raztus/myproject/node_modules/ldapjs/lib/client/client.js:152:24)
    at Socket.EventEmitter.emit (events.js:95:17)
    at Socket.<anonymous> (_stream_readable.js:746:14)
    at Socket.EventEmitter.emit (events.js:92:17)
    at emitReadable_ (_stream_readable.js:408:10)

My code looks like this (minus the sanitized search string):

var client = ldap.createClient({
    url: 'ldap://oid:361/',
    timeout: "2000",
    connectTimeout: "5000",
    logLevel: 'trace'
});

var opts = {
    scope: 'base', // Return only the exact object, no sub-objects
    attributes: ['orclnetdescstring'] // Return only these attributes
};

var username = '', password = '';

client.on('error', function(err){
    console.log("Client experienced this error:", err);
});
client.on('timeout', function(err){
    console.log("Client timed out.");
});
client.on('connectTimeout', function(err){
    console.log("Connection timed out.");
});

client.bind(username, password, function (err) {
    if (err) {
        callback(err, null);
        return;
    }

    var searchBase = 'CN=myDatabaseAlias,CN=OracleContext,DC=my,DC=company,DC=com';

    client.search(searchBase, opts, function (err, res) {
        //...
    })
});

This is against an Oracle OID server, which is either broken or misconfigured (this is just the backup server, our primary server works fine). I am happy to provide a new Wireshark output of this conversation. Please reopen this issue, as I lack the permissions to do so.

[pfmooney]

Yeah, the wireshark dump would be helpful.
Thanks

[johannish]

By email, pfmooney wrote:

As far as I can tell from the exception dumps, the service you're connecting to responds invalidly to your bind.
I'm not sure why it intermittently resets the connection prior to sending the bizarre result. Perhaps just timing luck.
Either way, it's because of that unanticipated response that the client tosses an exception and bails out.

Let me know if that analysis is adequate.

That analysis is adequate, though I'm still not quite sure how to solve this. Regardless of the unanticipated response, I would expect ldapjs to handle it gracefully and not crash. I believe there are two independent fixes here, which are not mutually exclusive:

1. After the connectTimeout milliseconds, the ldapjs client should close the connection.
2. Upon receiving 0x2 when expecting 0x1, the ldapjs client should fire the 'error' event, rather than crashing.

[pfmooney]

When the connectTimeout is reached, the client will fire that event if the calling code has registered for it. I believe it's an acceptable result given the circumstances.

I'll look into what it will take to provide mechanisms to prevent protocol-related exceptions from bubbling up like in this case.

[pfmooney]

At your leisure, could give 7c7c480 a try and see if it more gracefully handles the bogus data from that backup OID server?

I don't have good testing resources available at the moment, but when I'm back in the office on Monday, I'll do more verification to ensure I haven't broken other things with the change.

Thanks

[pfmooney]

@raztus Have you had a chance to test that minor patch to parser error handling?

This is one of the few remaining bugs I want to close out before a new release is tagged.

[johannish]

I apologize, last week was busy. I'm ready to test this now, but when I attempt to checkout 7c7c480, I get fatal: reference is not a tree: 7c7c480eb895cb3d1ad9b02c890bbbb1d0a961eb. Trying to do git log 7c7c480... returns fatal: bad object 7c7c480eb895cb3d1ad9b02c890bbbb1d0a961eb.

[pfmooney]

No problem.

The commit is over in my repository: https://github.com/pfmooney/node-ldapjs.git

[johannish]

Gotcha. It looks like it also made it into mcavage somehow, and now I just learned that Git doesn't clone dangling commits. Now I know!

Scratch that. Now I've also learned that Github will show you commits from other forks as if they exist in the main repo. Now I know that too!

[johannish]

Okay, I can confirm that that fix appears to solve the more serious issue, namely throwing an uncaught exception (condition (1)). However, the side-effect is that now condition (1) fires two "error" events, handled twice by the registered handler. Condition (2) (the ECONNRESET event) still fires just one "error" event. This is acceptable for my use case, but does seem funky.

It seems to me that a more appropriate solution would be for the client to close the connection after connectTimeout ms. In this way it totally severs the link, and doesn't have to care what the server sends. As a consumer of ldapjs, this is what I expected to happen; that is, after connectTimeout ms, consider it a lost cause and move on, rather than still listening for further data.

[pfmooney]

Yeah, the commit linking was a little weird.

Regarding the error behavior, I have a couple comments:

1. Send me the two errors that are firing in the case of condition 1. I'll look into if that should be pared down to a single event.
2. Using connectTimeout is not proper in this case. That event is used for timing out when making an initial TCP connection. In this case, the TCP connection is established without any issues. It does not dictate a timeout for a successful bind.

[johannish]

Ahh, I understand what you're saying. I really meant to say "close the connection after timeout ms", but now I understand that even that is certainly not the right solution, since you wouldn't want to close the TCP connection just because one LDAP operation timed out. I think what I actually wanted was a way to force the client to unbind and close the connection, which looks like is available as client.unbind().

I just discovered that if I put client.unbind() in the 'timeout' event handler, the two error events fire immediately, rather than roughly 7 minutes later. I'm not sure if this is relevant to this discussion, but it seems strange.

Below is the output from the two error events:

Client experienced this error: { [InvalidAsn1Error: Expected 0x2: got 0x1] name: 'InvalidAsn1Error', message: 'Expected 0x2: got 0x1' }
Client experienced this error: [Error: protocolOp 0x?? not supported]

[johannish]

Thanks for your work on this, @pfmooney! It will be helpful.

[ORESoftware]

I see this

les/ldapjs/lib/client/client.js:1282:14\n    at Array.forEach (native)\n    at Client._onClose (/home/amills/AdminUI/node_modules/ldapjs/lib/client/client.js:1272:19)\n    at TLSSocket.g (events.js:260:16)\n    at emitOne (events.js:77:13)\n    at TLSSocket.emit (events.js:169:7)\n    at TCP._onclose (net.js:469:12)","time":"2016-03-24T03:01:39.750Z","src":{"file":"/home/amills/AdminUI/app.js","line":265},"v":0}
uncaughtException--->Error: read ECONNRESET
    at exports._errnoException (util.js:856:11)
    at TLSWrap.onread (net.js:544:26)
/home/amills/AdminUI/bin/www.js:17
        throw err; //this should crash the server
        ^

Error: read ECONNRESET
    at exports._errnoException (util.js:856:11)
    at TLSWrap.onread (net.js:544:26)

an ECONNRESET throws an uncatchable exception or should I be able to catch it somehow?