JPC: Local ID not found; Unhandled promise rejection

[benbucksch]

2 separate issues, which might be related:

• "Local object with ID ... is unknown here"
• UnhandledPromiseRejection (somewhere, we're missing an await or try/catch)

Error {
  "id": 47,
  "success": false,
  "message": "Local object with ID 73742007272437137408 is unknown here.",
  "stack": "Error: Local object with ID 73742007272437137408 is unknown here.\n    at assert (http://localhost:5454/@fs.../mustang/client/lib/jpc/util.js:7:11)\n    at JPCWebSocket.getLocalObject (http://localhost:5454/@fs.../mustang/client/lib/jpc/obj.js:661:5)\n    at JPCWebSocket.callListener (http://localhost:5454/@fs.../mustang/client/lib/jpc/obj.js:341:21)\n    at WSCall._incomingMessage (http://localhost:5454/@fs.../mustang/client/lib/jpc/message.js:96:26)\n    at http://localhost:5454/@fs.../mustang/client/lib/jpc-ws/WSCall.js:16:12\n    at WebSocket.<anonymous> (http://localhost:5454/@fs.../mustang/client/lib/jpc-ws/protocol.js:84:58)",
  "originalCall": {
    "id": 47,
    "path": "call",
    "arg": {
      "obj": "73742007272437137408",
      "args": []
    }
  }
}
Error {
  "id": 48,
  "success": false,
  "message": "Local object with ID 24283683456460570624 is unknown here.",
  "stack": "Error: Local object with ID 24283683456460570624 is unknown here.\n    at assert (http://localhost:5454/@fs.../mustang/client/lib/jpc/util.js:7:11)\n    at JPCWebSocket.getLocalObject (http://localhost:5454/@fs.../mustang/client/lib/jpc/obj.js:661:5)\n    at JPCWebSocket.callListener (http://localhost:5454/@fs.../mustang/client/lib/jpc/obj.js:341:21)\n    at WSCall._incomingMessage (http://localhost:5454/@fs.../mustang/client/lib/jpc/message.js:96:26)\n    at http://localhost:5454/@fs.../mustang/client/lib/jpc-ws/WSCall.js:16:12\n    at WebSocket.<anonymous> (http://localhost:5454/@fs.../mustang/client/lib/jpc-ws/protocol.js:84:58)",
  "originalCall": {
    "id": 48,
    "path": "call",
    "arg": {
      "obj": "24283683456460570624",
      "args": [
        {
          "idSender": "27642003464666697728",
          "className": "Error",
          "properties": {
            "stack": "Error: Local object with ID 73742007272437137408 is unknown here.\n    at assert (http://localhost:5454/@fs.../mustang/client/lib/jpc/util.js:7:11)\n    at JPCWebSocket.getLocalObject (http://localhost:5454/@fs.../mustang/client/lib/jpc/obj.js:661:5)\n    at JPCWebSocket.callListener (http://localhost:5454/@fs.../mustang/client/lib/jpc/obj.js:341:21)\n    at WSCall._incomingMessage (http://localhost:5454/@fs.../mustang/client/lib/jpc/message.js:96:26)\n    at http://localhost:5454/@fs.../mustang/client/lib/jpc-ws/WSCall.js:16:12\n    at WebSocket.<anonymous> (http://localhost:5454/@fs.../mustang/client/lib/jpc-ws/protocol.js:84:58)",
            "message": "Local object with ID 73742007272437137408 is unknown here."
          }
        }
      ]
    }
  }
}
(node:1852009) UnhandledPromiseRejectionWarning: Error: Local object with ID 24283683456460570624 is unknown here.
    at assert (http://localhost:5454/@fs.../mustang/client/lib/jpc/util.js:7:11)
    at JPCWebSocket.getLocalObject (http://localhost:5454/@fs.../mustang/client/lib/jpc/obj.js:661:5)
    at JPCWebSocket.callListener (http://localhost:5454/@fs.../mustang/client/lib/jpc/obj.js:341:21)
    at WSCall._incomingMessage (http://localhost:5454/@fs.../mustang/client/lib/jpc/message.js:96:26)
    at http://localhost:5454/@fs.../mustang/client/lib/jpc-ws/WSCall.js:16:12
    at WebSocket.<anonymous> (http://localhost:5454/@fs.../mustang/client/lib/jpc-ws/protocol.js:84:58)
(node:1852009) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 11)

[NeilRashbrook]

at assert (http://localhost:5454/@fs.../mustang/client/lib/jpc/util.js:7:11)
at JPCWebSocket.getLocalObject (http://localhost:5454/@fs.../mustang/client/lib/jpc/obj.js:661:5)

These aren't async functions so they'll just throw the exception immediately.

at JPCWebSocket.callListener (http://localhost:5454/@fs.../mustang/client/lib/jpc/obj.js:341:21)

This function is async, but its caller...

at WSCall._incomingMessage (http://localhost:5454/@fs.../mustang/client/lib/jpc/message.js:96:26)

awaits it inside a try/catch, so I don't know where the unhandled Promise is coming from.

Now, what's interesting is that the code is trying to pass an Error to a remote function. What error? Well, the error has the same stack as this one, which means it's one that we've serialised across to the client. Which means that we succeeded in catching the error the last time around...

I tried updating mustang to see if I could reproduce the error. The update didn't like my mail.db so I stupidly deleted it and lost all of my account settings. Furthermore, your switch to SQL accounts broke what little EWS support there was. I've pushed some partial fixes to branch ews-sql; currently I'm still storing the refresh token in local storage as I don't know any better for now.

[NeilRashbrook]

I was unable to reproduce the bug within mustang itself using the [email protected] account.

It shouldn't be possible for a local object to be unknown... I even tried writing a test for JPC which created an Event Emitter, added an event listener to it, tried to collect garbage, and arranged for an event to be fired on it, but nothing got garbage collected, and the event fired as expected. The sequence of events that deletes a local object is as follows:

• We pass a previously unseen local object to a remote function or method call, so we add the local object to our local object table and assign an id to it.
• The remote side creates a stub from the object's description (which it calls back to obtain) and creates a weak referents to the stub in its remote object table.
• The remote side uses the stub in some way.
• When the remote side is finished with the stub and it gets garbage collected, it notifies the local side.
• Since the remote side no longer has the stub, it shouldn't be possible for its id to appear in a protocol message.
• After the local side receives the notification, it downgrades its local object table to hold a weak reference.
• After the local side is finished with the local object and it gets garbage collected, the weak reference is removed from the local object table.

You might be able to get more information as to what's going on by logging the relevant id in deleteLocalObject (which is the notification I mentioned above) but also possibly at line 68 of obj.js.

[benbucksch]

Together, Neil and me found that this happens when the frontend reloads, but the backend keeps running. The backend doesn't know that the frontend is gone, and the IMAP lib keeps the IMAP connection open. When a notification from the IMAP server arrives, the IMAP lib calls the event handlers (connection.on("flags") etc.), but the new frontend doesn't know those object IDs. That's when the error message happens.

That means:

• The error message itself is not harmful. But the fact that we keep the IMAP connections open is harmful. It costs server resources.
• This shouldn't happen in production, on desktop. But it can happen when the frontend has a serious error and reloads. Also, more importantly, it will happen routinely on Android and iOS, because those OS kill the frontend all the time.

[NeilRashbrook]

Do you want to differentiate between a transient disconnection and a reload? You could simplify matters by just reloading if the client gets disconnected.

There are two aspects to this.

From the point of view of JPC itself, it would like to know that the client has gone away for good, so that it can clear out its object tables. If you're not going to support transient connections, then it can do this on every connection, otherwise the best place to do this would seem to be on the call to get the remote start object, if it can be arranged that this only happens once per reload.

From the point of view of the client/server code, the server would also like to know when the client has reloaded. One way to do this would be to have a function that the client calls after it reloads and gets the start object. Other options could be for the server to have a callback to get the start object, or an event when the server clears its object tables.