TypeError: cb is not a function

[Akuukis]

Problem

I've stumbled upon non-flaky but random bug - I have hundreds of similar calls, but only for few of them the bug applies. See below the code snippet and error.

class MyCommsWrapper {
    ...
    call(methodName, args) {
        return new Promise((resolve, reject) => {
            try {
                const cb = (err, res) => err ? reject(err) : resolve(res)
                console.assert(typeof cb === 'function')
                this.socket.emit(methodName, JSON.stringify(args), cb);
            } catch(err) {
                console.log(err)  // <-- Here originates the logs below.
                throw err
            }
        });
    }
    ...
}

    TypeError: cb is not a function
        at afterWrite (_stream_writable.js:463:3)
        at onwrite (_stream_writable.js:454:7)
        at Socket._writeGeneric (net.js:777:5)
        at Socket._writev (net.js:782:8)
        at doWrite (_stream_writable.js:394:12)
        at clearBuffer (_stream_writable.js:500:5)
        at Socket.Writable.uncork (_stream_writable.js:312:7)
        at Sender.sendFrame (./node_modules/socketcluster-client/node_modules/ws/lib/sender.js:353:20)
        at Sender.send (./node_modules/socketcluster-client/node_modules/ws/lib/sender.js:272:12)
        at WebSocket.send (./node_modules/socketcluster-client/node_modules/ws/lib/websocket.js:354:18)

Expected behavior

I'd expect it to just work, or at least give more informative error how to fix it.

I'm clueless how the callback function created exactly the same way, and asserted to be a function, may sometimes be an function and sometimes not. Also did some digging along stack trace to no avail.

Details

Please advice how to debug this in first place and what other details would be useful.

[Akuukis]

That was on node v8.16.2. For node v10.17.0 error is different:

Error [ERR_MULTIPLE_CALLBACK]: Callback called multiple times
    at onwrite (_stream_writable.js:456:11)
    at afterWriteDispatched (internal/stream_base_commons.js:81:5)
    at writevGeneric (internal/stream_base_commons.js:67:3)
    at Socket._writeGeneric (net.js:712:5)
    at Socket._writev (net.js:721:8)
    at doWrite (_stream_writable.js:413:12)
    at clearBuffer (_stream_writable.js:522:5)
    at Socket.Writable.uncork (_stream_writable.js:319:7)
    at Sender.sendFrame (./node_modules/socketcluster-client/node_modules/ws/lib/sender.js:353:20)
    at Sender.send (./node_modules/socketcluster-client/node_modules/ws/lib/sender.js:272:12)
    at WebSocket.send (./node_modules/socketcluster-client/node_modules/ws/lib/websocket.js:354:18)

[jondubois]

I'm not sure what could be causing the first error maybe related to the Node.js version and the use of fat arrow function syntax.

The second error Callback called multiple times seems very different. It looks like the problem is on the receiving end of the message not the sender side; maybe the responder callback for the same remote event is called multiple times.

[Akuukis]

@jondubois Thanks for insights! The only difference between both cases we underlying nodejs version for client, no code was changed. I'd rule out fat arrow syntax, because for other near-identical calls it works, and I use arrows everywhere.

The second error Callback called multiple times seems very different. It looks like the problem is on the receiving end of the message not the sender side; maybe the responder callback for the same remote event is called multiple times.

Sounds interesting - would you please advice how to debug (e.g. inject console.log somewhere) to confirm this? I've got both client and server sides hosted locally.

[jondubois]

Is the new error Callback called multiple times logged on the same line as where the TypeError: cb is not a function was logged before?

In any case you can try logging the methodName and args when it happens. Then you can check on the receiving socket if the res(...) callback is called multiple times for that methodName. See the second snippet on this page for receiver logic: https://socketcluster.io/#!/docs/handling-failure

On the sender/emitter side, could make a wrapper function around the callback which you pass to the emit method to check if/when it is called twice.

[jondubois]

The error ERR_MULTIPLE_CALLBACK is not emitted by SC, it appears to come from Node.js streams. So maybe the callback from your snippet is causing a stream's callback function to be called twice and thus throwing the error. But as mentioned, the root cause is most likely because your receiver logic is calling res multiple times for certain methods/args.

[Akuukis]

Is the new error Callback called multiple times logged on the same line as where the TypeError: cb is not a function was logged before?

See in stacktraces that three last lines are equal, but other's are not. Furthermore, I put a console.log((new Error()).stack) deep in websocket and got longer stack

console.log ../../node_modules/socketcluster-client/node_modules/ws/lib/websocket.js:355
    at WebSocket.send (./node_modules/socketcluster-client/node_modules/ws/lib/websocket.js:354:16)
    at Emitter.Object.<anonymous>.SCTransport.send (./node_modules/socketcluster-client/lib/sctransport.js:391:17)
    at Emitter.Object.<anonymous>.SCTransport.sendObjectSingle (./node_modules/socketcluster-client/lib/sctransport.js:432:10)
    at Emitter.Object.<anonymous>.SCTransport.sendObject (./node_modules/socketcluster-client/lib/sctransport.js:440:10)
    at Emitter.Object.<anonymous>.SCTransport.emitObject (./node_modules/socketcluster-client/lib/sctransport.js:319:8)
    at Emitter.Object.<anonymous>.SCClientSocket._flushEmitBuffer (./node_modules/socketcluster-client/lib/scclientsocket.js:664:20)
    at Emitter.Object.<anonymous>.SCClientSocket._emit (./node_modules/socketcluster-client/lib/scclientsocket.js:713:10)
    at Emitter.Object.<anonymous>.SCClientSocket.emit (./node_modules/socketcluster-client/lib/scclientsocket.js:723:10)
    at initializePromise (./node_modules/es6-promise/dist/lib/es6-promise/-internal.js:216:5)
    at new Promise (./node_modules/es6-promise/dist/lib/es6-promise/promise.js:133:33)
    at Generator.next (<anonymous>)
    at ./node_modules/tslib/tslib.js:110:75
    at initializePromise (./node_modules/es6-promise/dist/lib/es6-promise/-internal.js:216:5)
    at new Promise (./node_modules/es6-promise/dist/lib/es6-promise/promise.js:133:33)

In any case you can try logging the methodName and args when it happens.

Here you go. Is there anything suspicious?

    methodname: addSignature
    data: {"event":"addSignature","data":"[\"2e3791361b90eed14b97de852aa81b2354e39ef42b7db3700f88f9f2272b6458\",\"tLCnPwAAAEBox0y061+phYFva/NZ3AGG3lqcq36d9RDsNhkaKM6RKwdfhtZVKqNcxGt50xN81noAoypAj75XIUg9P17g0DcH\"]","cid":8}

Then you can check on the receiving socket if the res(...) callback is called multiple times for that methodName.

N/A, see next answer

On the sender/emitter side, could make a wrapper function around the callback which you pass to the emit method to check if/when it is called twice.

My callback is not called at all. See the snippet - it throws error synchronously. To double confirm, on server I don't see that request logged (first line of handler function is logging).

[Akuukis]

@jondubois Thanks for the feedback. I looked into this problem from browser environment, and still the same event name addSignature was failing but differently now. In browser's network tab I can clearly see that it returns within few miliseconds (as well in server logs), but in the end the client fails with timeout error. Here are the details

; Browser in-built network viewer.
10:42:31.934  sent     {"event":"addSignature","data":"[\"7bb86e032c49da56afd4176f05cbda4cd1a06277fd487a07e60b6d4016ab3acc\",\"s1GWhwAAAEAfu08ylHLq0NBbJQabG7mmFoU70zGtxvdXnSkZRwF9gMUWYcm31hI859DMyg6K30WxuzmYzQJjPjG3gnftbIoE\"]","cid":82}
10:42:32.436  received {"rid":82,"data":"lol"}

; Client-side logs.
10:42:31.931  addSignature trigger
10:42:32.436  event<"onMessage">: {"rid":44,"data":"lol"}
10:42:41.936  addSignature {name: "TimeoutError", message: "Event response for 'addSignature' timed out"}

// Client snippet
this.socket.on('message', (msg) => this.log.warn(`event<"onMessage">:`, msg))
this.socket.on('error', (err) => this.log.warn(`event<"onError">:`, err))
this.log.warn(methodName, 'trigger')
this.socket.emit(methodName, JSON.stringify(args), (err, res) => {
    if(!err) {
        resolve(res)
    } else {
        this.log.warn(methodName, err)
        reject(err)
    }
});

// Server snippet
this.socket.on(methodName, (data, cb) => {
    console.log(`called ${methodName}`)
    try {
        const result = 'lol'  // server-side logic simplified.
        cb(null, result);
        console.log(`returned ${methodName}`)
    }
    catch (err) {
        cb(JSON.stringify(err));
    }
}));

I hope this is enough concrete feedback for you to have some insights. Here's what I tried but none changed the behavior:

• add 500ms delay at server side
• rename addSignature to fooBarBaz
• change the return value (originally it's undefined)
• do something before it so that cid/rid is different

Perhaps both of cases are unrelated, but suspiciously these problems are exclusively with call only.

Here's a clear formulation of the problem: server returns value (and browser network tab confirms it received) but emit callback misses it and throws timeout in the end.

EDIT: added more logs, updated log timestamps.

[Akuukis]

I refactored to asyngual, but it behaves just the same as in the last comment. What else can I try?