Transports and Node server shut downs with error when two users produce and consume each other's video at the same time

mediasoup libraries
1

I updated an old version of a mediasoup server app, because some packages had a lot of security issues.

I am able to show (produce) my video as a user (user1) and see (consume) the user1 with another user (user2). I can also open my cam with user2. Everything goes fine until there.

Now, the moment user1 consumes user2’s video, both producing and sending transport shut down immediately and I have this error popping from the server:

# My code sending console.log...
Consumer score:  ConsumerScoreT { score: 10, producerScore: 10, producerScores: [ 10 ] }
Leaving: 30pBKZMChthMH_rWAAAD stop
Consumer transportclose: 3d89b8a9-f88d-4c7e-8538-d58aa298fd39
Consumer transportclose: da8fd49e-667b-4f4f-8055-e4ba08c3eeca
Leaving: N4YuOzSBcCtgRam8AAAB stop
Consumer transportclose: 04cc2b91-6c2e-4ef1-9217-09df23996f30
Consumer transportclose: 266d232e-dc9e-4f95-98d5-3a247d0399a6
# The error
/home/ploi/v4.dudesnude.com/node_modules/mediasoup/node/lib/Channel.js:251
                    sent.reject(new Error(response.reason()));
                                ^

Error: Channel request handler with ID 266d232e-dc9e-4f95-98d5-3a247d0399a6 not found [method:consumer.resume]
    at Channel.processResponse (/home/ploi/v4.dudesnude.com/node_modules/mediasoup/node/lib/Channel.js:251:33)
    at Socket.<anonymous> (/home/ploi/v4.dudesnude.com/node_modules/mediasoup/node/lib/Channel.js:76:34)
    at Socket.emit (node:events:518:28)
    at addChunk (node:internal/streams/readable:561:12)
    at readableAddChunkPushByteMode (node:internal/streams/readable:512:3)
    at Readable.push (node:internal/streams/readable:392:5)
    at Pipe.onStreamRead (node:internal/stream_base_commons:189:23)

Node.js v22.14.0

Maybe it is coming from the code I have - with entities like Room and Peer, looks like it was built in an older version of mediasoup - but does that sound a bell to anyone of you?

Thanks!

EDIT: Looks like the error comes from a consumer.resume() command. Checking why this error pops up there.

EDIT 2: Finally, the consumer.resume() is not causing the shutdown but provokes the error anyway since transports are shut down before it runs. I still don’t know what causes the sudden transport shutdown.

2

It’s hard to see anything if you don’t enable mediasoup worker logs.

3

Here is the mediasoup debug logs when I open the WebRtcTransport that fails.

mediasoup:Router createWebRtcTransport() +16s
  mediasoup:Channel request() [method:ROUTER_CREATE_WEBRTCTRANSPORT] +12s
  mediasoup:Channel [pid:37031] RTC::WebRtcTransport::WebRtcTransport() | TCP sockets buffer sizes [send:131072, recv:131072] +1ms
  mediasoup:Channel request succeeded [method:ROUTER_CREATE_WEBRTCTRANSPORT, id:23] +0ms
  mediasoup:Transport constructor() +16s
  mediasoup:WebRtcTransport constructor() +16s
  mediasoup:Transport setMaxIncomingBitrate() [bitrate:1500000] +0ms
  mediasoup:Channel request() [method:TRANSPORT_SET_MAX_INCOMING_BITRATE] +1ms
  mediasoup:Channel [pid:37031] RTC::Transport::HandleRequest() | maximum incoming bitrate set to 1500000 +1ms
  mediasoup:Channel request succeeded [method:TRANSPORT_SET_MAX_INCOMING_BITRATE, id:24] +0ms
subscribeReady: publisherPeer id =  4364ee12-9f77-47b4-a3dd-2da0a2018c25
_createConsumer() [consumerPeer:y3mM9WkrhCuxQxeLAAAF, producerPeer:4364ee12-9f77-47b4-a3dd-2da0a2018c25, producer:a4cfda1b-bd47-4d13-bdbb-1e70f61e2418]
  mediasoup:Transport consume() +16ms
  mediasoup:Channel request() [method:TRANSPORT_CONSUME] +17ms
_createConsumer() [consumerPeer:y3mM9WkrhCuxQxeLAAAF, producerPeer:4364ee12-9f77-47b4-a3dd-2da0a2018c25, producer:d2c52c84-1d08-4583-8a7e-cb4a6bdd4726]
  mediasoup:Transport consume() +3ms
  mediasoup:Channel request() [method:TRANSPORT_CONSUME] +5ms
  mediasoup:Channel [pid:37031] RTC::SimpleConsumer::CreateRtpStream() | [ssrc:483330709, payloadType:100] +10ms
  mediasoup:Channel [pid:37031] RTC::SimpleConsumer::CreateRtpStream() | in band FEC enabled +0ms
  mediasoup:Channel request succeeded [method:TRANSPORT_CONSUME, id:25] +0ms
  mediasoup:Consumer constructor() +15s
new consumer [transport.id:5d42c164-bebf-409c-b830-3fd243cf86b2, consumer.id:02ac380c-6a15-42e3-bcf7-6d554480039f]
y3mM9WkrhCuxQxeLAAAF is consuming 4364ee12-9f77-47b4-a3dd-2da0a2018c25's producer:a4cfda1b-bd47-4d13-bdbb-1e70f61e2418
New consumer:  ConsumerImpl {
  _events: [Object: null prototype] {
    listenererror: [Function (anonymous)],
    '@close': [Function (anonymous)],
    '@producerclose': [Function (anonymous)]
  },
  _eventsCount: 3,
  _maxListeners: Infinity,
  [Symbol(shapeMode)]: false,
  [Symbol(kCapture)]: false
}
Consumer score:  ConsumerScoreT { score: 10, producerScore: 10, producerScores: [ 10 ] }
  mediasoup:Channel [pid:37031] RTC::SimpleConsumer::CreateRtpStream() | [ssrc:529136445, payloadType:101] +2ms
  mediasoup:Channel [pid:37031] RTC::SimpleConsumer::CreateRtpStream() | FIR supported +0ms
  mediasoup:Channel [pid:37031] RTC::SimpleConsumer::CreateRtpStream() | NACK supported +0ms
  mediasoup:Channel [pid:37031] RTC::SimpleConsumer::CreateRtpStream() | PLI supported +0ms
  mediasoup:Channel request succeeded [method:TRANSPORT_CONSUME, id:26] +0ms
  mediasoup:Channel [pid:37031] RTC::Transport::HandleRequest() | enabling TransportCongestionControlClient with transport-cc +0ms
  mediasoup:Consumer constructor() +2ms
new consumer [transport.id:5d42c164-bebf-409c-b830-3fd243cf86b2, consumer.id:1bd8e0da-f7b1-4c56-bb1b-b4ca2e53b448]
y3mM9WkrhCuxQxeLAAAF is consuming 4364ee12-9f77-47b4-a3dd-2da0a2018c25's producer:d2c52c84-1d08-4583-8a7e-cb4a6bdd4726
New consumer:  ConsumerImpl {
  _events: [Object: null prototype] {
    listenererror: [Function (anonymous)],
    '@close': [Function (anonymous)],
    '@producerclose': [Function (anonymous)]
  },
  _eventsCount: 3,
  _maxListeners: Infinity,
  [Symbol(shapeMode)]: false,
  [Symbol(kCapture)]: false
}
Consumer score:  ConsumerScoreT { score: 10, producerScore: 10, producerScores: [ 10 ] }
MS_STOP:  aYvwUKocSk5spF9BAAAD { session: 2, streamId: 'f67af6e0-1b8a-4b72-8eee-c25eb45319b7' }
stop: [socketId: aYvwUKocSk5spF9BAAAD, session: 2, streamId: f67af6e0-1b8a-4b72-8eee-c25eb45319b7]
Leaving: aYvwUKocSk5spF9BAAAD stop
  mediasoup:Transport close() +21ms
  mediasoup:Channel request() [method:ROUTER_CLOSE_TRANSPORT] +5ms
  mediasoup:Consumer transportClosed() +4ms
Consumer transportclose: f4fa24dc-abf9-45ef-928f-c23b10df625b
  mediasoup:Consumer transportClosed() +0ms
Consumer transportclose: c0ba31c1-7692-4725-bd4d-cc3028755073
transport closed [transport.id:77ea5fc4-c2d0-4ccc-b13f-5b9273cdd015]
  mediasoup:Channel [pid:37031] RTC::DtlsTransport::OnSslInfo() | sending DTLS warning alert: close notify +1ms
  mediasoup:Channel request succeeded [method:ROUTER_CLOSE_TRANSPORT, id:27] +0ms
  mediasoup:WebRtcTransport connect() +53ms
  mediasoup:Channel request() [method:WEBRTCTRANSPORT_CONNECT] +13ms
  mediasoup:Channel request succeeded [method:WEBRTCTRANSPORT_CONNECT, id:28] +0ms
MS_STOP:  y3mM9WkrhCuxQxeLAAAF { session: 2, streamId: '4364ee12-9f77-47b4-a3dd-2da0a2018c25' }
stop: [socketId: y3mM9WkrhCuxQxeLAAAF, session: 2, streamId: 4364ee12-9f77-47b4-a3dd-2da0a2018c25]
Leaving: y3mM9WkrhCuxQxeLAAAF stop
  mediasoup:Transport close() +97ms
  mediasoup:Channel request() [method:ROUTER_CLOSE_TRANSPORT] +83ms
  mediasoup:Consumer transportClosed() +97ms
Consumer transportclose: 02ac380c-6a15-42e3-bcf7-6d554480039f
  mediasoup:Consumer transportClosed() +0ms
Consumer transportclose: 1bd8e0da-f7b1-4c56-bb1b-b4ca2e53b448
transport closed [transport.id:5d42c164-bebf-409c-b830-3fd243cf86b2]
  mediasoup:Channel request succeeded [method:ROUTER_CLOSE_TRANSPORT, id:29] +2ms
  mediasoup:Consumer resume() +900ms
  mediasoup:Channel request() [method:CONSUMER_RESUME] +899ms
  mediasoup:ERROR:Channel [pid:37031] Worker::HandleRequest() | throwing MediaSoupError: Channel request handler with ID 1bd8e0da-f7b1-4c56-bb1b-b4ca2e53b448 not found undefined +0ms
  mediasoup:ERROR:Channel [pid:37031] Worker::HandleRequest() | throwing MediaSoupError: Channel request handler with ID 1bd8e0da-f7b1-4c56-bb1b-b4ca2e53b448 not found [method:consumer.resume] undefined +1ms
  mediasoup:WARN:Channel request failed [method:CONSUMER_RESUME, id:30]: Channel request handler with ID 1bd8e0da-f7b1-4c56-bb1b-b4ca2e53b448 not found [method:consumer.resume] +16s
_createConsumer() | consumer.resume():Error: Channel request handler with ID 1bd8e0da-f7b1-4c56-bb1b-b4ca2e53b448 not found [method:consumer.resume]
    at Channel.processResponse (/Users/frederic_chiasson/Sites/chat-server/node_modules/mediasoup/node/lib/Channel.js:251:33)
    at Socket.<anonymous> (/Users/frederic_chiasson/Sites/chat-server/node_modules/mediasoup/node/lib/Channel.js:76:34)
    at Socket.emit (node:events:524:28)
    at addChunk (node:internal/streams/readable:561:12)
    at readableAddChunkPushByteMode (node:internal/streams/readable:512:3)
    at Readable.push (node:internal/streams/readable:392:5)
    at Pipe.onStreamRead (node:internal/stream_base_commons:189:23) {
  [stack]: [Getter/Setter],
  [message]: 'Channel request handler with ID 1bd8e0da-f7b1-4c56-bb1b-b4ca2e53b448 not found [method:consumer.resume]'
}

I don’t see any error coming from mediasoup itself, but please correct me if I’m wrong.

4

Your application is literally calling transport.close(). Why? I don’t know, but it’s not mediasoup but your own application logic.

5

Makes sense when you look at the logs. Thanks for confirming me! Will check my code…

6

Finally found the bug! It was on my frontend app where, when receiving a non-related-to-mediasoup event, was closing the transport! So sorry for the waste of time and thanks for the help!

1 Like