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

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.

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

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.

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

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

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