Error: Callback was already called

[rajsolanki73]

Randomly i m getting following error.

at node_modules/activedirectory2/node_modules/async/dist/async.js:318:36 at GroupMembersForDN [as callback] (/node_modules/activedirectory2/lib/components/getGroupMembershipForDN.js:47:16)

i m using

ad.getGroupMembershipForUser(username, function(err, role) {}

[jsumners]

Without a way to reproduce it we cannot assist.

[rajsolanki73]

thanks. Let me explain in detail.

this is my code snippet.

ad.getGroupMembershipForUser(username, function(err, role) {

    if (err) {

      logger.info("getUserRole_error" + username,  err);
      return;
    }

    if (! role) 
    {

      logger.log("getUserRole_error",  "User: " + sAMAccountName + " not found.");
    } 
    else 
    {
    //logger.log("info",  "User: " + username + " found.");
    return callback(err,role);
    }
  });

So my this AD API gets around 50 to 60K requests in an hour and in a randomly i get above error and my nodejs app crashes. I do use PM2 so process does start back up but it crashes in randomly. before crash i always see following error.

Error: Callback was already called.
    at /home/myapi/node_modules/activedirectory2/node_modules/async/dist/async.js:318:36
    at GroupMembersForDN [as callback] (/home/myapi/node_modules/activedirectory2/lib/components/getGroupMembershipForDN.js:47:16)
    at Searcher.search [as callback] (/home/myapi/node_modules/activedirectory2/lib/components/getGroupMembershipForDN.js:113:12)
    at Client.Searcher.client.on (/home/myapi/node_modules/activedirectory2/lib/components/search.js:67:10)
    at Client.emit (events.js:198:13)
    at Backoff.<anonymous> (/home/myapi/node_modules/ldapjs/lib/client/client.js:1036:12)
    at Backoff.emit (events.js:198:13)
    at Backoff.backoff (/home/myapi/node_modules/backoff/lib/backoff.js:41:14)
    at /home/myapi/node_modules/ldapjs/lib/client/client.js:1020:15
    at f (/home/myapi/node_modules/once/once.js:25:25)
    at f (/home/myapi/node_modules/once/once.js:25:25)
    at /home/myapi/node_modules/ldapjs/lib/client/client.js:945:7
    at next (/home/myapi/node_modules/vasync/lib/vasync.js:843:6)
    at /home/myapi/node_modules/ldapjs/lib/client/client.js:162:9
    at callbackWrapper (/home/myapi/node_modules/ldapjs/lib/client/client.js:292:5)
    at sendResult (/home/myapi/node_modules/ldapjs/lib/client/client.js:1193:37)
    at messageCallback (/home/myapi/node_modules/ldapjs/lib/client/client.js:1216:18)
    at Parser.onMessage (/home/myapi/node_modules/ldapjs/lib/client/client.js:884:14)
    at Parser.emit (events.js:198:13)
    at Parser.write (/home/myapi/node_modules/ldapjs/lib/messages/parser.js:107:8)
    at Socket.onData (/home/myapi/node_modules/ldapjs/lib/client/client.js:871:22)
    at Socket.emit (events.js:198:13)
    at addChunk (_stream_readable.js:288:12)
    at readableAddChunk (_stream_readable.js:269:11)
    at Socket.Readable.push (_stream_readable.js:224:10)
    at TCP.onStreamRead (internal/stream_base_commons.js:94:17)

Please let me know what more details i can provide.

[davidrapin]

We had the same issue, the worse being that the error is not reported correctly and generates an uncaught error which crashes the library. So far, our strategy is to fork the library and implement a warning instead of a hard crash when this happens by wrapping the callback in a function that prevents multiple calls and warns.

[gmasclet]

I suspect this comes from the Searcher class.

This class performs searches agains an AD server, using a ldap.js client. It listens to error events emitted by the client:

https://github.com/jsumners/node-activedirectory/blob/194dda33531df6863c9e7e66bcddf65e9035a602/lib/components/search.js#L65-L68

But also to error and end events emitted by the search result:

https://github.com/jsumners/node-activedirectory/blob/194dda33531df6863c9e7e66bcddf65e9035a602/lib/components/search.js#L146-L151

When an error happens, looks like events from both the client and the search result are emitted, causing this.callback to be called twice (as it is indirectly called by errCallback and onSearchEnd).

[jsumners]

Are you providing a PR to address this issue? Please remember to include unit tests.

[gmasclet]

hello @jsumners. We've merged a PR addressing this issue in our fork of node-activedirectory (see https://github.com/Linkurious/node-activedirectory2/pull/4). I can provide a PR backporting it in this repository, so that everyone benefits from it.

Note this issue happens when a socket emit an error event (as far as we understand). We have experienced it sporadically in production, but we haven't been able to reproduce it consistently in a development environment. As such, I won't be able to provide complete unit tests. Yet, I can unit test the callOnlyOnce() utility function.

Let me know what you think.

[jsumners]

Looking at onSearchEnd, it seems that function never does anything with any parameters passed to it. So a more appropriate solution may be that the end handler should invoke the errCallback if err is set before invoking onSearchEnd.

[gmasclet]

Indeed, onSearchEnd doesn't use the res or err parameter sometimes passed to it. Considering that, your proposal clearly makes sense. I note that the end handler should either invoke errCallback or onSearchEnd, but not both of them: this would result in calling this.callback twice, which is what we want to avoid. So maybe we could change the end handler to something like:

    res.on('end', (err) => {
      this.searchComplete = true
      if (err) {
        errCallback(err)
      } else {
        this.onSearchEnd()
      }
    })

I have some doubts this is enough to fix this bug: unless I'm missing something, this change doesn't guarantee the error' event (on the client and/or the result) and theend` event won't be both triggered.

[jsumners]

What I can say is that this code is quite old and I am sure I would approach the whole thing much differently if I started writing it today. In particular, I would structure things for actual unit testing. That said, I am open to whatever approach solve the problem.

As for how to test any solution, I would create a new test suite that injects a mock object to the Searcher which has a client that generates a client error. Something like (does not work, it is just an outline):

const mockquire = require('mock-require')
mockquire('../path/to/utilities.js', {
  createClient () {
    return {
      // all necessary methods, including:
      search(...params) {
        this.emit('error', Error('bad client error'))
      }
    }
  }
})

const searchFactory = require('../path/to/search.js')

tap.test('new test', async t => {
  const searcher = searchFactory({ url: 'ldap://example.com' })

  // perform the search and look for the client error making sure
  // only one error is received for one search.
})

Note: detecting the errors can get complicated and I would imagine it could look something like the test found at https://github.com/ldapjs/node-ldapjs/blob/e2d516f6bb95f60de103e5c6fb812b8522f09134/test/issue-890.test.js

[jurjendijkstra]

I think the root cause is in ldapjs.

I have the problem now too, since nodejs 18 (which links a stricter OpenSSL than nodejs 16), but only on some AD servers, and only when using LDAPS protocol, not with LDAP. I dont know what's so special about those failing AD servers, but the problem did not happen in nodejs 16.

I see in the tracelog that the LDAPS server sends an "UnbindRequest" message and soon after that the AD server closes its end of the socket which raises an ECONNRESET error. In my opinion that ECONNRESET can safely be ignored after UnbindRequest. If it is not ignored, then this whole mechanism comes in motion that ends with "callback was already called" and nodejs quits after three of those warnings.

It is easy to fix in ldapjs/lib/client/clientjs line 967:

    socket.on('error', function onSocketError (err) {
      if (!(self.unbound && err.code==="ECONNRESET")) {
        log.trace({err: err}, 'error event: %s', new Error().stack)
        self.emit('error', err)
      }
      socket.destroy()
    })

it was simply:

    socket.on('error', function onSocketError (err) {
      log.trace({err: err}, 'error event: %s', new Error().stack)
      self.emit('error', err)
      socket.destroy()
    })

My problem is: I must find a way to NOT edit the code in the ldapjs module, but instead do something in my own application code. But what can I do?

[jsumners]

Why aren't you able to participate in the upstream project?

[jurjendijkstra]

In project node-ldapjs you mean?

Well, perhaps I am able to do that, but I had three thoughts:

1. I thought it made sense to add my comment here, because here is where the "Callback was already called" issue was reported and investigated.
2. I dont know how to make a unit test to validate my change, so you'd probably not accept the change anyway?
3. and I am trying to figure out if I can catch the error in my application code, which depends on activedirectroy2, not depends directly on ldapjs, so I thought this is the place to search

[jurjendijkstra]

I just find github confusing with forks and pull requests. I am an old man still using subversion :-) What should I do if you think the snippet I posted is ok?

[jsumners]

2. I dont know how to make a unit test to validate my change, so you'd probably not accept the change anyway?

A unit test for such a change will definitely be difficult. I suspect it would look something like https://github.com/ldapjs/node-ldapjs/blob/6ceef130145b38ba33b5ccc798bf49304194fb0f/test/issue-890.test.js. The code in that project is so difficult that if there is a really good reason, and we notate it correctly, then I am willing to consider not having a test to cover it. But we really need to exhaust efforts to get code coverage first.

I just find github confusing with forks and pull requests. I am an old man still using subversion :-)

At least in the projects I participate in, a willingness to learn is welcomed and questions will be answered. I would suggest starting by reading https://jrfom.com/posts/2017/03/08/a-primer-on-contributing-to-projects-with-git/.

[jurjendijkstra]

Thanks!!

I start reading

For me I think it is best when I first begin by editing that "if" statement directly in the node_modules/ldapjs code at our customer, who's operation is blocked by this problem. See if it is indeed the fix for their problem.

[Drilmo]

hi 😃 have you any update for this bug ?

[jurjendijkstra]

@Drilmo what works for me is maybe not the solution for you, but you can temporarily try to add a dependency to my temporary fork of ldapjs version 2: "ldapjs": "github:jurjendijkstra/vanmeijel-ldapjs#v2.x" But only to see if it helps. I will not keep or maintain that fork, it is just temporary.

[Drilmo]

@Drilmo what works for me is maybe not the solution for you, but you can temporarily try to add a dependency to my temporary fork of ldapjs version 2: "ldapjs": "github:jurjendijkstra/vanmeijel-ldapjs#v2.x" But only to see if it helps. I will not keep or maintain that fork, it is just temporary.

@jurjendijkstra Thks for your answer 😄 but i have the same error with your fork :

C:\Users\xxx\Git\xxx\node_modules\.pnpm\async@3.2.5\node_modules\async\dist\async.js:326
            if (fn === null) throw new Error("Callback was already called.");
                             ^

Error: Callback was already called.
    at C:\Users\xxx\Git\xxx\node_modules\.pnpm\async@3.2.5\node_modules\async\dist\async.js:326:36
    at GroupMembersForDN.callback (C:\Users\xxx\Git\xxx\node_modules\.pnpm\activedirectory2@2.2.0\node_modules\activedirectory2\lib\components\getGroupMembershipForDN.js:47:16)
    at Searcher.callback (C:\Users\xxx\Git\xxx\node_modules\.pnpm\activedirectory2@2.2.0\node_modules\activedirectory2\lib\components\getGroupMembershipForDN.js:113:12)
    at CorkedEmitter.errCallback (C:\Users\xxx\Git\xxx\node_modules\.pnpm\activedirectory2@2.2.0\node_modules\activedirectory2\lib\components\search.js:140:14)
    at CorkedEmitter.emit (node:events:513:28)
    at CorkedEmitter.emit (C:\Users\xxx\Git\xxx\vanmeijel-ldapjs-2.x\lib\corked_emitter.js:44:33)
    at sendResult (C:\Users\xxx\Git\xxx\vanmeijel-ldapjs-2.x\lib\client\client.js:1195:22)
    at messageCallback (C:\Users\xxx\Git\xxx\vanmeijel-ldapjs-2.x\lib\client\client.js:1225:16)
    at C:\Users\xxx\Git\xxx\vanmeijel-ldapjs-2.x\lib\client\client.js:1084:14
    at C:\Users\xxx\Git\xxx\vanmeijel-ldapjs-2.x\lib\client\message-tracker\index.js:113:7

[davidrapin]

Hi, we’ve created a fork of this repository that:

• adds support for nested groups
• fixes the “callback called twice” error (it’s a workaround but we use it in production, and found it to be reliable)
• adds some unit tests for both these improvements

We did not take the time to contribute our code back into this repo yet, but feel free to take a look and merge back any of our changes: https://github.com/Linkurious/node-activedirectory2

[davidrapin]

@jsumners i suppose you marked my previous comment as “off topic” (I cannot see who did), but it is not clear to me why. I did literally provide a link our fork that fixes the very bug that is the topic of this discussion.

[Drilmo]

Hi, we’ve created a fork of this repository that:

• adds support for nested groups
• fixes the “callback called twice” error (it’s a workaround but we use it in production, and found it to be reliable)
• adds some unit tests for both these improvements

We did not take the time to contribute our code back into this repo yet, but feel free to take a look and merge back any of our changes: https://github.com/Linkurious/node-activedirectory2

Hi @davidrapin, your fork resolve the "Error: Callback was already called" 😃

[davidrapin]

@Drilmo yes, it does, thank you for confirming :)