Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

TypeError: cb is not a function #135

Open
Akuukis opened this issue Nov 25, 2019 · 8 comments
Open

TypeError: cb is not a function #135

Akuukis opened this issue Nov 25, 2019 · 8 comments

Comments

@Akuukis
Copy link

Akuukis commented Nov 25, 2019

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
Copy link
Author

Akuukis commented Nov 26, 2019

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
Copy link
Member

jondubois commented Nov 26, 2019

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
Copy link
Author

Akuukis commented Nov 26, 2019

@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
Copy link
Member

jondubois commented Nov 26, 2019

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
Copy link
Member

jondubois commented Nov 26, 2019

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
Copy link
Author

Akuukis commented Nov 26, 2019

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
Copy link
Author

Akuukis commented Nov 28, 2019

@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
Copy link
Author

Akuukis commented Nov 29, 2019

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

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants