Occasional server crash on Consumer.pause(): Consumer not found

Decode · February 20, 2021, 4:23pm

I am building a prototype video chat app where the volume of peers depends on the distance between users. Very similar to spatial.chat in fact. As soon as the distance between users exceeds a threshold, I call pause() on the consumer to stop transferring data. Once users get closer I call resume(). So far this has worked really well, except for one issue.

Every so often (usually only after a couple of hours of testing with 5 to 15 people, which makes this hard to reproduce) the entire server crashes with the following error:

/home/user/proximity-chat/node_modules/mediasoup/lib/Channel.js:199
                        sent.reject(new Error(msg.reason));
                                    ^

Error: Consumer not found

Server log 1

user disconnected e8703f81-e08a-49ad-99f4-c63ffdb92e61
  mediasoup:Transport close() +7m
  mediasoup:Channel request() [method:transport.close, id:8600] +406ms
  mediasoup:Producer transportClosed() +7m
  mediasoup:Producer transportClosed() +0ms
  mediasoup:Transport close() +0ms
  mediasoup:Channel request() [method:transport.close, id:8601] +0ms
  mediasoup:Consumer transportClosed() +407ms
  mediasoup:Consumer transportClosed() +1ms
  mediasoup:Consumer transportClosed() +0ms
  mediasoup:Consumer transportClosed() +0ms
  mediasoup:Consumer transportClosed() +0ms
  mediasoup:Consumer transportClosed() +0ms
  mediasoup:Consumer transportClosed() +0ms
  mediasoup:Consumer transportClosed() +0ms
  mediasoup:Consumer transportClosed() +0ms
  mediasoup:Consumer transportClosed() +0ms
  mediasoup:Consumer transportClosed() +0ms
  mediasoup:Consumer transportClosed() +0ms
  mediasoup:Consumer transportClosed() +0ms
  mediasoup:Consumer transportClosed() +0ms
  mediasoup:Consumer resume() +0ms
  mediasoup:Channel request() [method:consumer.resume, id:8602] +1ms
  mediasoup:Consumer resume() +1ms
  mediasoup:Channel request() [method:consumer.resume, id:8603] +1ms
  mediasoup:Consumer pause() +11ms
  mediasoup:Channel request() [method:consumer.pause, id:8604] +12ms
  mediasoup:Consumer pause() +1ms
  mediasoup:Channel request() [method:consumer.pause, id:8605] +0ms
  mediasoup:Channel request succeeded [method:transport.close, id:8600] +10ms
  mediasoup:Channel request succeeded [method:transport.close, id:8601] +15ms
  mediasoup:Channel request succeeded [method:consumer.resume, id:8602] +1ms
  mediasoup:Channel request succeeded [method:consumer.resume, id:8603] +1ms
  mediasoup:Channel request succeeded [method:consumer.pause, id:8604] +8ms
  mediasoup:Channel request succeeded [method:consumer.pause, id:8605] +1ms
  mediasoup:Consumer pause() +105ms
  mediasoup:Channel request() [method:consumer.pause, id:8606] +69ms
  mediasoup:Consumer pause() +1ms
  mediasoup:Channel request() [method:consumer.pause, id:8607] +1ms
  mediasoup:Channel request succeeded [method:consumer.pause, id:8606] +2ms
  mediasoup:Consumer pause() +4ms
  mediasoup:Channel request() [method:consumer.pause, id:8608] +2ms
  mediasoup:Consumer pause() +0ms
  mediasoup:Channel request() [method:consumer.pause, id:8609] +0ms
  mediasoup:Channel request succeeded [method:consumer.pause, id:8607] +0ms
  mediasoup:Channel request succeeded [method:consumer.pause, id:8608] +2ms
  mediasoup:Channel request succeeded [method:consumer.pause, id:8609] +2ms
  mediasoup:Consumer pause() +43ms
  mediasoup:Channel request() [method:consumer.pause, id:8610] +40ms
  mediasoup:Consumer pause() +1ms
  mediasoup:Channel request() [method:consumer.pause, id:8611] +0ms
  mediasoup:Channel request succeeded [method:consumer.pause, id:8610] +0ms
  mediasoup:Channel request succeeded [method:consumer.pause, id:8611] +3ms
  mediasoup:Consumer resume() +12ms
  mediasoup:Channel request() [method:consumer.resume, id:8612] +9ms
  mediasoup:Consumer resume() +0ms
  mediasoup:Channel request() [method:consumer.resume, id:8613] +0ms
  mediasoup:Channel request succeeded [method:consumer.resume, id:8612] +1ms
  mediasoup:Channel request succeeded [method:consumer.resume, id:8613] +1ms
  mediasoup:Consumer pause() +15ms
  mediasoup:Channel request() [method:consumer.pause, id:8614] +14ms
  mediasoup:Consumer pause() +1ms
  mediasoup:Channel request() [method:consumer.pause, id:8615] +0ms
  mediasoup:Channel request succeeded [method:consumer.pause, id:8614] +0ms
  mediasoup:Channel request succeeded [method:consumer.pause, id:8615] +2ms
  mediasoup:Consumer pause() +24ms
  mediasoup:Channel request() [method:consumer.pause, id:8616] +23ms
  mediasoup:Consumer pause() +1ms
  mediasoup:Channel request() [method:consumer.pause, id:8617] +0ms
  mediasoup:ERROR:Channel [pid:31201 RTC::Transport::GetConsumerFromInternal() | throwing MediaSoupError: Consumer not found +0ms
  mediasoup:WARN:Channel request failed [method:consumer.pause, id:8616]: Consumer not found +55s
/home/user/proximity-chat/node_modules/mediasoup/lib/Channel.js:199
                        sent.reject(new Error(msg.reason));
                                    ^

Error: Consumer not found
    at Channel._processMessage (/home/user/proximity-chat/node_modules/mediasoup/lib/Channel.js:199:37)
    at Socket.<anonymous> (/home/user/proximity-chat/node_modules/mediasoup/lib/Channel.js:61:34)
    at Socket.emit (node:events:376:20)
    at addChunk (node:internal/streams/readable:305:12)
    at readableAddChunk (node:internal/streams/readable:280:9)
    at Socket.Readable.push (node:internal/streams/readable:219:10)
    at Pipe.onStreamRead (node:internal/stream_base_commons:192:23)
error Command failed with exit code 1.

Server log 2

 mediasoup:Channel request() [method:consumer.pause, id:14698] +0ms
  mediasoup:Channel request succeeded [method:consumer.pause, id:14695] +1ms
  mediasoup:Channel request succeeded [method:consumer.pause, id:14696] +1ms
  mediasoup:Channel request succeeded [method:consumer.pause, id:14697] +1ms
  mediasoup:Channel request succeeded [method:consumer.pause, id:14698] +1ms
  mediasoup:Consumer pause() +32ms
  mediasoup:Channel request() [method:consumer.pause, id:14699] +28ms
  mediasoup:Consumer pause() +1ms
  mediasoup:Channel request() [method:consumer.pause, id:14700] +1ms
  mediasoup:Channel request succeeded [method:consumer.pause, id:14699] +0ms
  mediasoup:Channel request succeeded [method:consumer.pause, id:14700] +2ms
  mediasoup:Consumer pause() +51ms
  mediasoup:Channel request() [method:consumer.pause, id:14701] +49ms
  mediasoup:Consumer pause() +0ms
  mediasoup:Channel request() [method:consumer.pause, id:14702] +0ms
  mediasoup:Channel request succeeded [method:consumer.pause, id:14701] +2ms
  mediasoup:Consumer pause() +5ms
  mediasoup:Channel request() [method:consumer.pause, id:14703] +3ms
  mediasoup:Consumer pause() +0ms
  mediasoup:Channel request() [method:consumer.pause, id:14704] +0ms
  mediasoup:Channel request succeeded [method:consumer.pause, id:14702] +1ms
  mediasoup:Channel request succeeded [method:consumer.pause, id:14703] +0ms
  mediasoup:Channel request succeeded [method:consumer.pause, id:14704] +3ms
user disconnected 6e1e4367-0a6a-457a-96e3-7989e9ee6dce
  mediasoup:Transport close() +661ms
  mediasoup:Channel request() [method:transport.close, id:14705] +282ms
  mediasoup:Producer transportClosed() +1s
  mediasoup:Producer transportClosed() +0ms
  mediasoup:Transport close() +0ms
  mediasoup:Channel request() [method:transport.close, id:14706] +0ms
  mediasoup:Consumer transportClosed() +287ms
  mediasoup:Consumer transportClosed() +0ms
  mediasoup:Consumer transportClosed() +0ms
  mediasoup:Consumer transportClosed() +0ms
  mediasoup:Consumer transportClosed() +0ms
  mediasoup:Consumer transportClosed() +0ms
  mediasoup:Consumer transportClosed() +0ms
  mediasoup:Consumer transportClosed() +0ms
  mediasoup:Consumer transportClosed() +0ms
  mediasoup:Consumer transportClosed() +0ms
  mediasoup:Consumer transportClosed() +0ms
  mediasoup:Consumer transportClosed() +0ms
  mediasoup:Consumer transportClosed() +0ms
  mediasoup:Consumer transportClosed() +0ms
  mediasoup:Consumer transportClosed() +0ms
  mediasoup:Consumer transportClosed() +0ms
  mediasoup:Consumer pause() +6ms
  mediasoup:Channel request() [method:consumer.pause, id:14707] +7ms
  mediasoup:Channel request succeeded [method:transport.close, id:14705] +4ms
  mediasoup:Channel request succeeded [method:transport.close, id:14706] +8ms
  mediasoup:ERROR:Channel [pid:25812 RTC::Transport::GetConsumerFromInternal() | throwing MediaSoupError: Consumer not found +0ms
  mediasoup:WARN:Channel request failed [method:consumer.pause, id:14707]: Consumer not found +1s
/home/user/proximity-chat/node_modules/mediasoup/lib/Channel.js:199
                        sent.reject(new Error(msg.reason));
                                    ^

Error: Consumer not found
    at Channel._processMessage (/home/user/proximity-chat/node_modules/mediasoup/lib/Channel.js:199:37)
    at Socket.<anonymous> (/home/user/proximity-chat/node_modules/mediasoup/lib/Channel.js:61:34)
    at Socket.emit (node:events:376:20)
    at addChunk (node:internal/streams/readable:305:12)
    at readableAddChunk (node:internal/streams/readable:280:9)
    at Socket.Readable.push (node:internal/streams/readable:219:10)
    at Pipe.onStreamRead (node:internal/stream_base_commons:192:23)
error Command failed with exit code 1.
info Visit https://yarnpkg.com/en/docs/cli/run for documentation about this command.

My current theory is that a user disconnects, and at almost the same time some other uses pauses its consumer of the disconnecting user. In this case I would assume that checking if the consumer is closed would be sufficient. Next, I also expect that a try catch would be able to catch this error. However, even with the following code, the server crashes beyond recovery:

  const userId = param[2];
  const user = this.users.get(ws.id);  // this.users is a es6 Map, a user have this form:
  /**
    * {
    *   producer: {
    *     transport: WebRtcTransport,
    *     audio: Producer,
    *     video: Producer
    *   },
    *   consumer {
    *     transport: WebRtcTransport,
    *     userId: {
    *       audio: Consumer,
    *       video: Consumer
    *     }
    *   }
    * }
  */

  if (user != null) {
    const consumers = user.consumer[userId]; 

    if (consumers != null) {
      for (const key in consumers) {
        if (
          consumers.hasOwnProperty(key) &&
          consumers[key] != null &&
          consumers[key].closed === false  // I assumed this would fix it
        ) {
          try {  // I also assumed this try would catch this error
            consumers[key].pause();
          } catch (e) {
          }
        }
      }
    }
  }

Is this perhaps an issue with mediasoup itself, or am I doing something wrong? Let me know if I can provide more details.

ibc · February 20, 2021, 4:24pm

This is not “whole server crashes” but your app crashes. You must be ready for “Consumer not found” error by using try/catch in pause() and resume() calls.

Decode · February 20, 2021, 4:33pm

Thanks for the quick reply.

My pause() and resume() calls are already wrapped in a try/catch block, as you can see in the final code snippet (scroll down a bit). Even with that try/catch block the app crashes. It seems the pause error cannot be caught?

ibc · February 20, 2021, 4:52pm

No, they are not. You are not adding await consumer.pause() so those try/catch are useless. Please check how async functions work in JavaScript.

Decode · February 20, 2021, 6:29pm

Ah damn, I overlooked that, my bad! Seems to be working now

Topic		Replies	Views
consumer not found Error mediasoup libraries	11	2149	January 28, 2021
Consumer not found error message mediasoup libraries	4	1255	March 19, 2021
Pause dataConsumer mediasoup libraries	2	586	February 21, 2021
Messages in Log file Off Topic	3	395	April 27, 2021
Advices on dealing with unreliable networks Deployment & Scalability	7	1375	September 29, 2024

Occasional server crash on Consumer.pause(): Consumer not found

Related topics