Consumer not found error message

[subham]

Hello,
I have a working project based on top of the official mediasoup demo to connect with my family and friends in this pandemic using mediasoup which is working great. Thanks for this library.

OS : Ubuntu 20.04 LTS.
Scenario : Single room with 25-28 peers.

So occasionally I see the following message log on mediasoup server side implementation, when a certain peer performs unmute/mute mic and/or webcam on/off.
Also to trace out when we carried out simultaneous mic and webcam toggling, I could see a flood of same logs.

19/03/2021 04:18:18 warn: _createConsumer() | failed:Error: Consumer not found
    at Channel._processMessage (/snapshot/server/node_modules/mediasoup/lib/Channel.js:199:37)
    at Socket.<anonymous> (/snapshot/server/node_modules/mediasoup/lib/Channel.js:61:34)
    at Socket.emit (events.js:315:20)
    at Socket.EventEmitter.emit (domain.js:485:12)
    at addChunk (_stream_readable.js:302:12)
    at readableAddChunk (_stream_readable.js:278:9)
    at Socket.Readable.push (_stream_readable.js:217:10)
    at Pipe.onStreamRead (internal/stream_base_commons.js:186:23) {
  [stack]: 'Error: Consumer not found\n' +
    '    at Channel._processMessage (/snapshot/server/node_modules/mediasoup/lib/Channel.js:199:37)\n' +
    '    at Socket.<anonymous> (/snapshot/server/node_modules/mediasoup/lib/Channel.js:61:34)\n' +
    '    at Socket.emit (events.js:315:20)\n' +
    '    at Socket.EventEmitter.emit (domain.js:485:12)\n' +
    '    at addChunk (_stream_readable.js:302:12)\n' +
    '    at readableAddChunk (_stream_readable.js:278:9)\n' +
    '    at Socket.Readable.push (_stream_readable.js:217:10)\n' +
    '    at Pipe.onStreamRead (internal/stream_base_commons.js:186:23)',
  [message]: 'Consumer not found'
}

19/03/2021 04:53:02 warn: _createDataConsumer() | failed:Error: request timeout
    at Timeout._onTimeout (/snapshot/server/node_modules/protoo-server/lib/Peer.js:156:14)
    at listOnTimeout (internal/timers.js:549:17)
    at processTimers (internal/timers.js:492:7) {
  [stack]: 'Error: request timeout\n' +
    '    at Timeout._onTimeout (/snapshot/server/node_modules/protoo-server/lib/Peer.js:156:14)\n' +
    '    at listOnTimeout (internal/timers.js:549:17)\n' +
    '    at processTimers (internal/timers.js:492:7)',
  [message]: 'request timeout'
}

19/03/2021 05:29:24 error: request failed:Error: producer with id "e4088dc2-3d53-4660-b35d-7f30d77cd0c6" not found
    at Room._handleProtooRequest (/snapshot/server/lib/Room.js)
    at Peer.<anonymous> (/snapshot/server/lib/Room.js)
    at Peer.emit (events.js:315:20)
    at Peer.EventEmitter.emit (domain.js:485:12)
    at Peer._handleRequest (/snapshot/server/node_modules/protoo-server/lib/Peer.js:224:9)
    at WebSocketTransport.<anonymous> (/snapshot/server/node_modules/protoo-server/lib/Peer.js:212:10)
    at WebSocketTransport.emit (events.js:315:20)
    at WebSocketTransport.EventEmitter.emit (domain.js:485:12)
    at WebSocketTransport.safeEmit (/snapshot/server/node_modules/protoo-server/lib/EnhancedEventEmitter.js:18:9)
    at WebSocketConnection.<anonymous> (/snapshot/server/node_modules/protoo-server/lib/transports/WebSocketTransport.js:129:9) {
  [stack]: 'Error: producer with id "e4088dc2-3d53-4660-b35d-7f30d77cd0c6" not found\n' +
    '    at Room._handleProtooRequest (/snapshot/server/lib/Room.js)\n' +
    '    at Peer.<anonymous> (/snapshot/server/lib/Room.js)\n' +
    '    at Peer.emit (events.js:315:20)\n' +
    '    at Peer.EventEmitter.emit (domain.js:485:12)\n' +
    '    at Peer._handleRequest (/snapshot/server/node_modules/protoo-server/lib/Peer.js:224:9)\n' +
    '    at WebSocketTransport.<anonymous> (/snapshot/server/node_modules/protoo-server/lib/Peer.js:212:10)\n' +
    '    at WebSocketTransport.emit (events.js:315:20)\n' +
    '    at WebSocketTransport.EventEmitter.emit (domain.js:485:12)\n' +
    '    at WebSocketTransport.safeEmit (/snapshot/server/node_modules/protoo-server/lib/EnhancedEventEmitter.js:18:9)\n' +
    '    at WebSocketConnection.<anonymous> (/snapshot/server/node_modules/protoo-server/lib/transports/WebSocketTransport.js:129:9)',
  [message]: 'producer with id "e4088dc2-3d53-4660-b35d-7f30d77cd0c6" not found'
}

On mediasoup lib side I get the following logs

2021-03-19T04:18:18.174Z mediasoup:Consumer resume()
2021-03-19T04:18:18.174Z mediasoup:Channel request() [method:consumer.resume, id:701]
2021-03-19T04:18:18.174Z mediasoup:ERROR:Channel [pid:99583 RTC::Transport::GetConsumerFromInternal() | throwing MediaSoupError: Consumer not found
2021-03-19T04:18:18.175Z mediasoup:WARN:Channel request failed [method:consumer.resume, id:701]: Consumer not found

2021-03-19T04:53:13.901Z protoo-server:ERROR:Peer received response does not match any sent request [id:4391368]
2021-03-19T04:53:13.909Z protoo-server:ERROR:Peer received response does not match any sent request [id:9978912]

I hoped to solve the problem using directions provided in this thread and updated to 3.6.35

consumer not found Error

This is not true and I’ve confirmed it: videoProducer.close(); try { await videoConsumer.setPreferredLayers({ spatialLayer: 1 }); } catch (error) { console.warn('-------- catch(): %s', error); console.warn('-------- 2 videoConsumer.closed:', videoConsumer.closed); } videoConsumer.closed === true in the catch block as expected. This is super tested. No where in the docs it’s said that any mediasoup close() method throws if the entity is already closed. Nowhere. Not true. Really.

But still see those errors.
Currently I don’t have a lead on what might be possibly causing this.
I will still check this with more testing and report for probably someone else might be facing this same issue.

Thanks.

[ibc (Iñaki Baz Castillo)]

The consumer was al ready closed (probably because its associated producer was closed) at C++ level and you are calling methods in the Consumer at JS level. Just that. You must be ready for those cases as closure of consumers happen immediately when the producer is closed and you get the consumer “producerclose” event a few ms later due the communication between C++ and anode. Nothing wrong here.

[subham]

Thanks for the reply . I understand the concept.

I was also wondering about these request timeout logs. Do they occur because of the consumer not found scenario ?

19/03/2021 05:47:13 warn: _createConsumer() | failed:Error: request timeout
    at Timeout._onTimeout (/snapshot/server/node_modules/protoo-server/lib/Peer.js:156:14)
    at listOnTimeout (internal/timers.js:549:17)
    at processTimers (internal/timers.js:492:7) {
  [stack]: 'Error: request timeout\n' +
    '    at Timeout._onTimeout (/snapshot/server/node_modules/protoo-server/lib/Peer.js:156:14)\n' +
    '    at listOnTimeout (internal/timers.js:549:17)\n' +
    '    at processTimers (internal/timers.js:492:7)',
  [message]: 'request timeout'
}

18/03/2021 05:46:41  warn: _createConsumer() | failed:Error: Channel request timeout
    at Timeout._onTimeout (/snapshot/server/node_modules/mediasoup/lib/Channel.js:169:29)
    at listOnTimeout (internal/timers.js:549:17)
    at processTimers (internal/timers.js:492:7) {
  [stack]: 'Error: Channel request timeout\n' +
    '    at Timeout._onTimeout (/snapshot/server/node_modules/mediasoup/lib/Channel.js:169:29)\n' +
    '    at listOnTimeout (internal/timers.js:549:17)\n' +
    '    at processTimers (internal/timers.js:492:7)',
  [message]: 'Channel request timeout'
}

This one looks like a genuine error.

18/03/2021 06:56:55 error: request failed:Error: Channel request timeout
    at Timeout._onTimeout (/snapshot/server/node_modules/mediasoup/lib/Channel.js:169:29)
    at listOnTimeout (internal/timers.js:549:17)
    at processTimers (internal/timers.js:492:7) {
  [stack]: 'Error: Channel request timeout\n' +
    '    at Timeout._onTimeout (/snapshot/server/node_modules/mediasoup/lib/Channel.js:169:29)\n' +
    '    at listOnTimeout (internal/timers.js:549:17)\n' +
    '    at processTimers (internal/timers.js:492:7)',
  [message]: 'Channel request timeout'
}

As per my findings looks like the response is received back from the remote peer after the timeout duration exhausts which looks like around 30 seconds and more depending on the number of requests sent as I investigated it within the Peer.js file.

const timeout = 2000 * (15 + (0.1 * this._sents.size));

But I couldn’t find the reason for “error: request failed:Error: Channel request timeout” log.
Will still generate more logs and check for any patterns.

[ibc (Iñaki Baz Castillo)]

Cannot help with timeouts due to signaling as that is not part of mediasoup.

But I couldn’t find the reason for “error: request failed:Error: Channel request timeout” log.

The only reason for that to happen is that your app is sending too many commands to mediasoup which become messages (requests that expect a response) from mediasoup Node layer to mediasoup C++ layer. And/or because there is too much RTP traffic and your CPU usage is terribly high.

For instance, ensure you are not enabling full mediasoup-worker logs in production and things like that. Those logs are not for free. They are sent from C++ to Node via the same signaling path used to transmit requests/responses/notifications between mediasoup Node and mediasoup C++.

[subham]

Thanks a lot. I have got the idea. This gives me good direction.
Thanks a ton once again for this library. It has helped me a lot for connecting with people remotely in a hassle free manner.