"Transport with same transportId already exists" (should not happen)

[ibc]

Issue and some rationale described here: #47

[ibc]

I've coded a test app trying to reproduce the bug. I'm not able to reproduce it:

https://github.com/ibc/CommandQueueTest

[ibc]

Ok, I've added transport related logs in the mediasoup demo server, and got something wrong:

2018-10-27T03:33:51.952Z mediasoup-demo-server:INFO:Room "createTransport" request [peer.name:f5o0acpk, transport.id:21838585, direction:recv]

2018-10-27T03:33:51.952Z protoo-server:ERROR:Peer received response does not match any sent request

2018-10-27T03:33:51.952Z protoo-server:ERROR:Peer received response does not match any sent request

2018-10-27T03:33:51.954Z mediasoup:ERROR:mediasoup-worker [id:rtyuzzos#1] RTC::Router::GetNewTransportIdFromRequest() | throwing MediaSoupError | a Transport with same transportId already exists

2018-10-27T03:33:51.954Z mediasoup:ERROR:Channel request failed [id:74112245, reason:"a Transport with same transportId already exists"]

2018-10-27T03:33:51.955Z mediasoup:ERROR:Peer "router.createWebRtcTransport" request failed: Error: a Transport with same transportId already exists

2018-10-27T03:33:51.958Z mediasoup:ERROR:Peer receiveRequest() failed [method:createTransport]: Error: a Transport with same transportId already exists at Channel._processMessage (/home/ibc/src/mediasoup-deploy/lib/Channel.js:280:17) at Socket.Channel._socket.on.error (/home/ibc/src/mediasoup-deploy/lib/Channel.js:97:14) at emitOne (events.js:96:13) at Socket.emit (events.js:188:7) at readableAddChunk (_stream_readable.js:176:18) at Socket.Readable.push (_stream_readable.js:134:10) at Pipe.onread (net.js:547:20)

2018-10-27T03:33:51.953Z mediasoup-demo-server:INFO:Room "createTransport" request [peer.name:f5o0acpk, transport.id:21838585, direction:recv]

2018-10-27T03:33:51.953Z mediasoup-demo-server:INFO:Room mediaPeer "newtransport" event [peer.name:f5o0acpk, transport.id:21838585, direction:recv]

So basically, the server receives two "createTransport" requests for peer.name:f5o0acpk and transport.id:21838585 in these times:

• 2018-10-27T03:33:51.952Z
• 2018-10-27T03:33:51.953Z

[ibc]

I've tried to reproduce the issue running the demo with lot of debugs. Calls to transport.addConsumer() are always executed serially and cannot reproduce the issue at all.

[ibc]

Regarding the error logs above, I don't even know if those are produced by the mediasoup-demo web application. I'm aware of some people connecting to this demo server using their own mediasoup clients.

[james-maloney]

Do you know if the third party clients hitting your demo use the mediasoup-client package?

[james-maloney]

The peer.name matches the random ID scheme of the demo, of course that is in no way definitive to what client is being used.

[ibc]

Good question. I think (but I cannot confirm) that there are some guys testing custom native versions of mediasoup-client.

BTW I've added some logs to the demo server:

logger.info(
		'connection request [roomId:%s, peerName:%s, address:%s, origin:%s]',
		roomId, peerName, info.socket.remoteAddress, info.origin);

I hope those will help us identifying which kind of clients are producing the error.

[ibc]

News:

By default mediasoup-client uses requestTimeout: 10000, meaning 10 seconds to wait for responses once the corresponding request event has been emitted by the mediasoupClient.Room: https://mediasoup.org/documentation/mediasoup-client/api/#Room-dictionaries

I've changed it to 300000 in mediasoup-client right now.

If the server si too busy (it can happen if there are many rooms and, specially, if the logLevel is "debug" (avoid that in production), or if the client is too busy, or the network connection is not good enough, it may happen that:

• Once joined, the client app iterates lot of consumers and call consumer.receive(recvTransport) on them.
• The first call to consumer.receive() will internally trigger the @needcreatetransport event (related to the handler _createTransport() method, which involves a mediasoup request with method createTransport and the corresponding transport.id as parameter (id in the request).
• Let's assume that the server receives it and creates the corresponding Transport in server side with that id. But the response does not arrive to the client within 10 seconds, so mediasoup client produces a Timeout error and such a call to consumer.receive() fails.
  • @james-maloney you should see such an error in your client app.
  • This means that this._transportCreated is false yet.
  • If the server response arrives after those 10 seconds, it's just discarded by mediasoup client since the internal promise was already rejected with an internally created timeout error).
• After that, the CommandQueue processes the second call to consumer.receive(recvTransport).
• Since this._transportCreated is false, it attempts again to send a mediasoup request createTransport, which now is rejected by the mediasoup server since "a transport with same transportId already exists".

This makes sense and explains the problem.

Please, increase the requestTimeout of your mediasoupClient.Room and set it to 20000 (20 seconds) or more, which is more realistic than the default value.

[ibc]

@james-maloney, if you can reproduce the issue, please try to find such a timeout error in your client side. If you see it, it means that probably the explanation above is accurate.

[james-maloney]

Looking at my logs I do see some timeout errors that occurred trying to receive a new consumer.

Also saw a bunch of these timeouts on the SFU Error: request timeout | at Timeout.sent.timer.setTimeout [as _onTimeout] (node_modules/mediasoup/lib/Channel.js:243:14)

[ibc]

I assume you have lot of debugging logs enabled in your mediasoup. Am I right?

[james-maloney]

No debug logs but a lot of reqs are made to get stats from the worker.

[ibc]

Performance in the Channel when stats are enabled and there are many participants can be discussed in another topic (if it produces timeout errors). However, I think we can close this issue and the related #47, right?

[artushin]

@james-maloney, looks like those were from node. The request timeout there is hard coded to 5 seconds (https://github.com/versatica/mediasoup/blob/master/lib/Channel.js#L12). In fact, I just checked and we've been running with a custom 30 second timeout on the frontend for a while.

[james-maloney]

@ibc It seems like the requestTimeout in the client should be the same or similar to the worker timeout. Could we make the worker timeout configurable?

[ibc]

I agree that 5 seconds is too low. Wouldn't it just better if we increase it to 20 seconds? I don't get the point in making it configurable instead of choosing a value that works fine always.

[james-maloney]

20s seems okay to me. I ask because it seems somewhat coupled to the client's requestTimeout and that's configurable. Maybe just a doc update would clarify things.

[ibc]

I think that client's requestTimeout is a bit different since it's also affected by network conditions and CPU usage by the JavaScript main thread.

IMHO more than 20 seconds in Channel.js is no acceptable. If it produces timeout errors then there is something else to fix (such as stats JSON generations).

[james-maloney]

Sounds good.

[artushin]

Yep, I think 20 seconds is good.

[ibc]

Thanks a lot, guys. mediasoup 2.3.2 released right now with REQUEST_TIMEOUT in Channel.js set to 20 seconds.

[seetharaghavan]

I am using mediasoup client in angular and I keep getting this issue when i navigate from one from the video call component and came back to the same component. When I refresh the page, everything is working fine. I am closing the room properly in the server