Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

RTC::Consumer::GetStats crash #185

Closed
artushin opened this issue Jan 27, 2018 · 10 comments
Closed

RTC::Consumer::GetStats crash #185

artushin opened this issue Jan 27, 2018 · 10 comments
Assignees
@jmillan
Labels
bug
Milestone
v2 updates

Comments

@artushin
Copy link

artushin commented Jan 27, 2018 •
edited
Loading

Crashing with

mediasoup-worker's stderr: ABORT[id:ciocdrvn#1] RTC::Consumer::GetStats() | failed assertion `it != this->mapProfileRtpStream.end()': effective profile does not map to a rtp stream

on mediasoup v2.0.10 in OSX.

I don't know if this is relevant based on the error, but the getStats implementation I have is polling for stats:

_handleMediaConsumer(peer, consumer) {
		const consumerInterval = setInterval(() => {
			consumer.getStats()
			...
		}, STATS_INTERVAL);

		consumer.on('close', (originator) => {
			clearInterval(consumerInterval);
			...
		});
}

I don't know if there could be a race internally in mediasoup between the consumer closing and getStats being called with such an implementation.

Also, don't know if it helps but here are some sfu logs that come before it:

{"level":"info","time":"Jan 26, 2018 10:31 PM","message":"mediaPeer \"newtransport\" event","id":41734828,"direction":"send"}
{"level":"info","time":"Jan 26, 2018 10:31 PM","message":"updateMaxBitrate","numPeers":1,"previousBitrate":6000,"newBitrate":6000}
{"level":"info","time":"Jan 26, 2018 10:31 PM","message":"mediaPeer \"newproducer\" event","id":86907934,"peer":"9937816002e811e8846369a9d3514ca5","rtpParameters":{"muxId":{},"codecs":[{"name":"opus","mimeType":"audio/opus","clockRate":48000,"payloadType":111,"channels":2,"rtcpFeedback":[],"parameters":{"useinbandfec":1}}],"headerExtensions":[{"uri":"urn:ietf:params:rtp-hdrext:ssrc-audio-level","id":1}],"encodings":[{"ssrc":3495059388}],"rtcp":{"cname":"15EGh++ZVWk2TDRf","reducedSize":true,"mux":true}}}
{"level":"info","time":"Jan 26, 2018 10:31 PM","message":"new active speaker","activePeer":"ca41612a-8ea9-4013-98ce-26d1c17ad0ce"}
{"level":"info","time":"Jan 26, 2018 10:31 PM","message":"mediaPeer \"newproducer\" event","id":96991310,"peer":"9937816002e811e8846369a9d3514ca5","rtpParameters":{"muxId":{},"codecs":[{"name":"H264","mimeType":"video/H264","clockRate":90000,"payloadType":100,"rtcpFeedback":[{"type":"ccm","parameter":"fir"},{"type":"nack"},{"type":"nack","parameter":"pli"},{"type":"goog-remb"}],"parameters":{"packetization-mode":1,"level-asymmetry-allowed":1}},{"name":"rtx","mimeType":"video/rtx","clockRate":90000,"payloadType":101,"parameters":{"apt":100}}],"headerExtensions":[{"uri":"urn:ietf:params:rtp-hdrext:toffset","id":2},{"uri":"http://www.webrtc.org/experiments/rtp-hdrext/abs-send-time","id":3},{"uri":"urn:3gpp:video-orientation","id":4}],"encodings":[{"ssrc":181559130,"rtx":{"ssrc":1261119719}}],"rtcp":{"cname":"15EGh++ZVWk2TDRf","reducedSize":true,"mux":true}}}
{"level":"info","time":"Jan 26, 2018 10:31 PM","message":"mediaPeer existing \"consumer\"","id":81560664}
{"level":"info","time":"Jan 26, 2018 10:31 PM","message":"mediaPeer existing \"consumer\"","id":20384823}
{"level":"info","time":"Jan 26, 2018 10:31 PM","message":"mediaPeer \"newtransport\" event","id":35955819,"direction":"recv"}
{"level":"info","time":"Jan 26, 2018 10:31 PM","message":"mediaPeer \"newtransport\" event","id":32083454,"direction":"send"}
{"level":"info","time":"Jan 26, 2018 10:31 PM","message":"updateMaxBitrate","numPeers":2,"previousBitrate":6000,"newBitrate":6000}
{"level":"info","time":"Jan 26, 2018 10:31 PM","message":"mediaPeer \"newconsumer\" event","id":32664258,"peer":"9937816002e811e8846369a9d3514ca5","rtpParameters":{"muxId":{},"codecs":[{"name":"opus","mimeType":"audio/opus","clockRate":48000,"payloadType":100,"channels":2,"rtcpFeedback":[],"parameters":{"useinbandfec":1}}],"headerExtensions":[{"uri":"urn:ietf:params:rtp-hdrext:ssrc-audio-level","id":1}],"encodings":[{"ssrc":34033865}],"rtcp":{"cname":"t9F0kWxVbrLPAeWQ","reducedSize":true,"mux":true}}}
{"level":"info","time":"Jan 26, 2018 10:31 PM","message":"mediaPeer \"newproducer\" event","id":20520190,"peer":"993cffa002e811e8846369a9d3514ca5","rtpParameters":{"muxId":{},"codecs":[{"name":"opus","mimeType":"audio/opus","clockRate":48000,"payloadType":111,"channels":2,"rtcpFeedback":[],"parameters":{"useinbandfec":1}}],"headerExtensions":[{"uri":"urn:ietf:params:rtp-hdrext:ssrc-audio-level","id":1}],"encodings":[{"ssrc":855685515}],"rtcp":{"cname":"t9F0kWxVbrLPAeWQ","reducedSize":true,"mux":true}}}
{"level":"info","time":"Jan 26, 2018 10:31 PM","message":"mediaPeer \"newtransport\" event","id":46848742,"direction":"recv"}
{"level":"info","time":"Jan 26, 2018 10:31 PM","message":"mediaPeer \"newconsumer\" event","id":32342254,"peer":"9937816002e811e8846369a9d3514ca5","rtpParameters":{"muxId":{},"codecs":[{"name":"H264","mimeType":"video/H264","clockRate":90000,"payloadType":101,"rtcpFeedback":[{"type":"ccm","parameter":"fir"},{"type":"nack"},{"type":"nack","parameter":"pli"},{"type":"goog-remb"}],"parameters":{"packetization-mode":1,"level-asymmetry-allowed":1}},{"name":"rtx","mimeType":"video/rtx","clockRate":90000,"payloadType":102,"parameters":{"apt":101}}],"headerExtensions":[{"uri":"urn:ietf:params:rtp-hdrext:toffset","id":2},{"uri":"http://www.webrtc.org/experiments/rtp-hdrext/abs-send-time","id":3},{"uri":"urn:3gpp:video-orientation","id":4}],"encodings":[{"ssrc":80116604,"rtx":{"ssrc":52234223}}],"rtcp":{"cname":"t9F0kWxVbrLPAeWQ","reducedSize":true,"mux":true}}}
{"level":"info","time":"Jan 26, 2018 10:31 PM","message":"mediaPeer \"newproducer\" event","id":13225941,"peer":"993cffa002e811e8846369a9d3514ca5","rtpParameters":{"muxId":{},"codecs":[{"name":"H264","mimeType":"video/H264","clockRate":90000,"payloadType":100,"rtcpFeedback":[{"type":"ccm","parameter":"fir"},{"type":"nack"},{"type":"nack","parameter":"pli"},{"type":"goog-remb"}],"parameters":{"packetization-mode":1,"level-asymmetry-allowed":1}},{"name":"rtx","mimeType":"video/rtx","clockRate":90000,"payloadType":101,"parameters":{"apt":100}}],"headerExtensions":[{"uri":"urn:ietf:params:rtp-hdrext:toffset","id":2},{"uri":"http://www.webrtc.org/experiments/rtp-hdrext/abs-send-time","id":3},{"uri":"urn:3gpp:video-orientation","id":4}],"encodings":[{"ssrc":2930517379,"rtx":{"ssrc":2917031800}}],"rtcp":{"cname":"t9F0kWxVbrLPAeWQ","reducedSize":true,"mux":true}}}
@ibc
Copy link
Member

ibc commented Jan 27, 2018

Thanks. Those logs look like your app's custom logs. May you please set full logging in mediasoup please?:

https://mediasoup.org/documentation/mediasoup/debugging/

Also, could you affirm that the crash happens when closing the Consumer (due to sender or receiver peer closure)?

@ibc ibc added the bug label Jan 27, 2018
@ibc ibc added this to the v2 updates milestone Jan 27, 2018
@ibc
Copy link
Member

ibc commented Jan 27, 2018

@jmillan let's have this issue in the radar. We may have to redesign the profiles design since we are having many problems like this one. I think we should also pass the "default" profile from the Producer to the Consumer rather than assuming that, if no profiles have been set, then the default is used. Just wondering.

@artushin
Copy link
Author

Here are the mediasoup logs. I'm working on some client logic at the moment for reconnects to the sfu, and this is happening pretty consistently when I kill the sfu process, restart it, and the client auto-reconnects.

  mediasoup mediasoup version 2.0.10 +0ms
  mediasoup Server() +4ms
  mediasoup:Server constructor() [options:{ numWorkers: 1, logLevel: 'debug', logTags: [ 'info', 'ice', 'dlts', 'rtp', 'srtp', 'rtcp', 'rbe', 'rtx' ], rtcIPv4: true, rtcIPv6: false, rtcAnnouncedIPv4: null, rtcAnnouncedIPv6: null, rtcMinPort: 40000, rtcMaxPort: 49999 }] +0ms
  mediasoup:Worker constructor() [id:hdbauorz#1, parameters:"--logLevel=debug --logTag=info --logTag=ice --logTag=dlts --logTag=rtp --logTag=srtp --logTag=rtcp --logTag=rbe --logTag=rtx --rtcIPv4=true --rtcIPv6=false --rtcMinPort=40000 --rtcMaxPort=49999"] +0ms
  mediasoup:Channel constructor() +0ms
  mediasoup:mediasoup-worker [id:hdbauorz#1] Settings::PrintConfiguration() | <configuration> +0ms
  mediasoup:mediasoup-worker [id:hdbauorz#1] Settings::PrintConfiguration() |   logLevel            : "debug" +0ms
  mediasoup:mediasoup-worker [id:hdbauorz#1] Settings::PrintConfiguration() |   logTags             : "info,ice,rtp,srtp,rtcp,rtx,rbe" +0ms
  mediasoup:mediasoup-worker [id:hdbauorz#1] Settings::PrintConfiguration() |   rtcIPv4             : "192.168.0.171" +0ms
  mediasoup:mediasoup-worker [id:hdbauorz#1] Settings::PrintConfiguration() |   rtcIPv6             : (unavailable) +0ms
  mediasoup:mediasoup-worker [id:hdbauorz#1] Settings::PrintConfiguration() |   rtcAnnouncedIPv4    : (unset) +0ms
  mediasoup:mediasoup-worker [id:hdbauorz#1] Settings::PrintConfiguration() |   rtcAnnouncedIPv6    : (unset) +0ms
  mediasoup:mediasoup-worker [id:hdbauorz#1] Settings::PrintConfiguration() |   rtcMinPort          : 40000 +0ms
  mediasoup:mediasoup-worker [id:hdbauorz#1] Settings::PrintConfiguration() |   rtcMaxPort          : 49999 +0ms
  mediasoup:mediasoup-worker [id:hdbauorz#1] Settings::PrintConfiguration() | </configuration> +0ms
  mediasoup:mediasoup-worker [id:hdbauorz#1] main::main() | starting mediasoup-worker [pid:97762] +0ms
  mediasoup:mediasoup-worker [id:hdbauorz#1] main::main() | Little-Endian CPU detected +0ms
  mediasoup:mediasoup-worker [id:hdbauorz#1] main::main() | 64 bits architecture detected +1ms
  mediasoup:mediasoup-worker [id:hdbauorz#1] DepLibUV::PrintVersion() | loaded libuv version: "1.18.0" +0ms
  mediasoup:mediasoup-worker [id:hdbauorz#1] DepOpenSSL::ClassInit() | loaded openssl version: "OpenSSL 1.0.2j  26 Sep 2016" +0ms
  mediasoup:mediasoup-worker [id:hdbauorz#1] DepLibSRTP::ClassInit() | loaded libsrtp version: "libsrtp 2.0.0" +0msdevcaller","peerId":"5a40517003a211e8a2c487215c3dc670"}
  mediasoup:Server Room() +913ms
  mediasoup:Worker Room() +912ms
  mediasoup:Room constructor() +0ms
  mediasoup:Channel request() [method:worker.createRouter, id:30357701] +909ms
  mediasoup:Room createActiveSpeakerDetector() +1ms
  mediasoup:ActiveSpeakerDetector constructor() +0ms
  mediasoup:Channel request() [method:router.setAudioLevelsEvent, id:73609245] +1ms
  mediasoup:Channel request succeeded [id:30357701] +3ms
  mediasoup:Channel request succeeded [id:73609245] +0ms
  mediasoup:Worker "worker.createRouter" request succeeded +5ms
  mediasoup:Room "router.setAudioLevelsEvent" request succeeded +3mspeers:","peerId":"5a40517003a211e8a2c487215c3dc670","userId":"devcaller","scope":"privcalls_caller"}added","session":"5a8d38f003a211e8a2c487215c3dc670","callId":"BB5BF750039F11E8A02187874335DDF3","userId":"devcaller","displayName":"Caller AKA devcaller","peerId":"5a40517003a211e8a2c487215c3dc670","scope":"privcalls_caller"}
  mediasoup:Room receiveRequest() [method:queryRoom] +18ms
  mediasoup:Room receiveRequest() [method:join] +7ms
  mediasoup:Room _createPeer() [peerName:"af33c5ab-e19a-478f-8e73-5fdc8e81d549] +0ms
  mediasoup:Peer constructor() [internal:{ routerId: 63003407, peerName: 'af33c5ab-e19a-478f-8e73-5fdc8e81d549' }] +0ms
  mediasoup:Peer receiveRequest() [method:createTransport] +16ms
  mediasoup:Peer _createWebRtcTransport() [id:81003121, direction:send] +0ms
  mediasoup:Channel request() [method:router.createWebRtcTransport, id:37598747] +43ms
  mediasoup:mediasoup-worker [id:hdbauorz#1] RTC::IceServer::IceServer() | [usernameFragment:rm1bgq4ed27cr7r2, password:kfqox3lnir4xokw3hwnhmc6sfodqh1xs] +659ms
  mediasoup:Channel request succeeded [id:37598747] +0ms
  mediasoup:Peer "router.createWebRtcTransport" request succeeded +1ms
  mediasoup:WebRtcTransport constructor() +0ms
  mediasoup:WebRtcTransport setMaxBitrate() [bitrate:6000000] +1ms
  mediasoup:Channel request() [method:transport.setMaxBitrate, id:41214161] +1ms
  mediasoup:WebRtcTransport setRemoteDtlsParameters() +1ms
  mediasoup:Channel request() [method:transport.setRemoteDtlsParameters, id:56984946] +1ms
  mediasoup:mediasoup-worker [id:hdbauorz#1] RTC::WebRtcTransport::SetMaxBitrate() | Transport max bitrate set to 6000000bps +2ms
  mediasoup:Channel request succeeded [id:41214161] +0ms
  mediasoup:Channel request succeeded [id:56984946] +0ms
  mediasoup:WebRtcTransport "transport.setMaxBitrate" request succeeded +0ms
  mediasoup:WebRtcTransport "transport.setRemoteDtlsParameters" request succeeded +0ms
  mediasoup:mediasoup-worker [id:hdbauorz#1] RTC::IceServer::HandleTuple() | transition from state 'new' to 'connected' +2ms
  mediasoup:mediasoup-worker [id:hdbauorz#1] RTC::WebRtcTransport::OnIceConnected() | ICE connected +1ms
  mediasoup:Peer receiveRequest() [method:createProducer] +5ms
  mediasoup:Peer _createProducer() [id:37390238, kind:audio] +1ms
  mediasoup:Channel request() [method:router.createProducer, id:20461452] +5ms
  mediasoup:Channel request succeeded [id:20461452] +0ms
  mediasoup:Peer "router.createProducer" request succeeded +2ms
  mediasoup:Producer constructor() +0msevent","id":37390238,"peer":"5a40517003a211e8a2c487215c3dc670","rtpParameters":{"muxId":{},"codecs":[{"name":"opus","mimeType":"audio/opus","clockRate":48000,"payloadType":111,"channels":2,"rtcpFeedback":[],"parameters":{"useinbandfec":1}}],"headerExtensions":[{"uri":"urn:ietf:params:rtp-hdrext:ssrc-audio-level","id":1}],"encodings":[{"ssrc":582481086}],"rtcp":{"cname":"C4K3OH39AHTzH/S9","reducedSize":true,"mux":true}}}
  mediasoup:mediasoup-worker [id:hdbauorz#1] RTC::IceServer::HandleTuple() | transition from state 'connected' to 'completed' +48ms
  mediasoup:mediasoup-worker [id:hdbauorz#1] RTC::WebRtcTransport::OnIceCompleted() | ICE completed +0msadded","session":"5a8d38f003a211e8a2c487215c3dc670","callId":"BB5BF750039F11E8A02187874335DDF3","userId":"devreceiver","displayName":"Receiver AKA devreceiver","peerId":"5a5ade5003a211e8a2c487215c3dc670","scope":"privcalls_receiver"}
  mediasoup:Room receiveRequest() [method:queryRoom] +102ms
  mediasoup:Peer receiveRequest() [method:createProducer] +84ms
  mediasoup:Peer _createProducer() [id:20001489, kind:video] +0ms
  mediasoup:Channel request() [method:router.createProducer, id:87731541] +85ms
  mediasoup:Channel request succeeded [id:87731541] +0ms
  mediasoup:Peer "router.createProducer" request succeeded +1ms
  mediasoup:Producer constructor() +84msevent","id":20001489,"peer":"5a40517003a211e8a2c487215c3dc670","rtpParameters":{"muxId":{},"codecs":[{"name":"H264","mimeType":"video/H264","clockRate":90000,"payloadType":100,"rtcpFeedback":[{"type":"ccm","parameter":"fir"},{"type":"nack"},{"type":"nack","parameter":"pli"},{"type":"goog-remb"}],"parameters":{"packetization-mode":1,"level-asymmetry-allowed":1}},{"name":"rtx","mimeType":"video/rtx","clockRate":90000,"payloadType":101,"parameters":{"apt":100}}],"headerExtensions":[{"uri":"urn:ietf:params:rtp-hdrext:toffset","id":2},{"uri":"http://www.webrtc.org/experiments/rtp-hdrext/abs-send-time","id":3},{"uri":"urn:3gpp:video-orientation","id":4}],"encodings":[{"ssrc":2433559194,"rtx":{"ssrc":2981272241}}],"rtcp":{"cname":"C4K3OH39AHTzH/S9","reducedSize":true,"mux":true}}}
  mediasoup:Room receiveRequest() [method:join] +54ms
  mediasoup:Room _createPeer() [peerName:"cc50747e-c312-4720-bce5-f7e2351fc037] +1ms
  mediasoup:Peer constructor() [internal:{ routerId: 63003407, peerName: 'cc50747e-c312-4720-bce5-f7e2351fc037' }] +46ms
  mediasoup:Consumer constructor() +0ms
  mediasoup:Channel request() [method:router.createConsumer, id:23050926] +48ms
  mediasoup:Consumer constructor() +0ms
  mediasoup:Channel request() [method:router.createConsumer, id:35136177] +1ms
  mediasoup:Peer _sendNotification() [method:newPeer] +2ms
  mediasoup:mediasoup-worker [id:hdbauorz#1] RTC::Consumer::AddProfile() | profile added [profile:default] +89ms
  mediasoup:Channel request succeeded [id:23050926] +2ms
  mediasoup:Channel request succeeded [id:35136177] +0ms
  mediasoup:Peer "router.createConsumer" request succeeded +2ms
  mediasoup:Peer "router.createConsumer" request succeeded +0ms
  mediasoup:Peer receiveRequest() [method:createTransport] +79ms
  mediasoup:Peer _createWebRtcTransport() [id:72995400, direction:recv] +1ms
  mediasoup:Channel request() [method:router.createWebRtcTransport, id:64571410] +80ms
  mediasoup:mediasoup-worker [id:hdbauorz#1] RTC::IceServer::IceServer() | [usernameFragment:udng2oq9ufsfr76s, password:vm05ndb634do44bt8z96wi4v49a9hd4y] +82ms
  mediasoup:Channel request succeeded [id:64571410] +2ms
  mediasoup:Peer "router.createWebRtcTransport" request succeeded +2ms
  mediasoup:WebRtcTransport constructor() +223ms
  mediasoup:Peer receiveNotification() [method:updateTransport] +26ms
  mediasoup:WebRtcTransport setRemoteDtlsParameters() +26ms
  mediasoup:Channel request() [method:transport.setRemoteDtlsParameters, id:92008769] +26ms
  mediasoup:Peer receiveRequest() [method:enableConsumer] +1ms
  mediasoup:Consumer enable() +112ms
  mediasoup:Consumer remoteSetPreferredProfile() [profile:default] +215ms
  mediasoup:Channel request() [method:consumer.enable, id:80314161] +216ms
  mediasoup:Peer receiveRequest() [method:createTransport] +216ms
  mediasoup:Peer _createWebRtcTransport() [id:77450001, direction:send] +0ms
  mediasoup:Channel request() [method:router.createWebRtcTransport, id:97832141] +1ms
  mediasoup:Channel request succeeded [id:92008769] +0ms
  mediasoup:mediasoup-worker [id:hdbauorz#1] RTC::IceServer::HandleTuple() | transition from state 'new' to 'connected' +244ms
  mediasoup:mediasoup-worker [id:hdbauorz#1] RTC::WebRtcTransport::OnIceConnected() | ICE connected +1ms
  mediasoup:mediasoup-worker [id:hdbauorz#1] RTC::IceServer::HandleTuple() | transition from state 'connected' to 'completed' +0ms
  mediasoup:mediasoup-worker [id:hdbauorz#1] RTC::WebRtcTransport::OnIceCompleted() | ICE completed +0ms
  mediasoup:ActiveSpeakerDetector emitting "activespeakerchange" [peerName:"af33c5ab-e19a-478f-8e73-5fdc8e81d549"] +516ms
  mediasoup:Consumer setPreferredProfile() [profile:high] +4ms
  mediasoup:Channel request() [method:consumer.setPreferredProfile, id:46543329] +3ms
  mediasoup:mediasoup-worker [id:hdbauorz#1] RTC::Consumer::CreateRtpStream() | NACK supported +2ms
  mediasoup:mediasoup-worker [id:hdbauorz#1] RTC::Consumer::CreateRtpStream() | PLI supported +0ms
  mediasoup:WebRtcTransport "transport.setRemoteDtlsParameters" request succeeded +220ms
  mediasoup:mediasoup-worker [id:hdbauorz#1] RTC::Transport::HandleConsumer() | requesting key frame for new Consumer since Transport already connected +2ms
  mediasoup:Channel request succeeded [id:80314161] +2ms
  mediasoup:mediasoup-worker [id:hdbauorz#1] RTC::IceServer::IceServer() | [usernameFragment:r4egedyvozrrqc7q, password:klj53e3ch0g87xsj9qoegrwp6pl1gmpo] +0ms
  mediasoup:Channel request succeeded [id:97832141] +0ms
  mediasoup:mediasoup-worker [id:hdbauorz#1] RTC::Consumer::SetPreferredProfile() | preferred profile set [profile:high] +1ms
  mediasoup:Channel request succeeded [id:46543329] +1ms
  mediasoup:Consumer "consumer.enable" request succeeded +3ms
  mediasoup:Peer "router.createWebRtcTransport" request succeeded +6ms
  mediasoup:WebRtcTransport constructor() +3ms
  mediasoup:WebRtcTransport setMaxBitrate() [bitrate:6000000] +1ms
  mediasoup:Channel request() [method:transport.setMaxBitrate, id:70604118] +1ms
  mediasoup:WebRtcTransport setMaxBitrate() [bitrate:6000000] +0ms
  mediasoup:Channel request() [method:transport.setMaxBitrate, id:27876544] +0ms
  mediasoup:Consumer "consumer.setPreferredProfile" request succeeded +2ms
  mediasoup:Peer _sendNotification() [method:consumerPreferredProfileSet] +2ms
  mediasoup:WebRtcTransport setRemoteDtlsParameters() +1ms
  mediasoup:Channel request() [method:transport.setRemoteDtlsParameters, id:78779609] +1ms
  mediasoup:mediasoup-worker [id:hdbauorz#1] RTC::WebRtcTransport::SetMaxBitrate() | Transport max bitrate set to 6000000bps +3ms
  mediasoup:Channel request succeeded [id:70604118] +1ms
  mediasoup:mediasoup-worker [id:hdbauorz#1] RTC::WebRtcTransport::SetMaxBitrate() | Transport max bitrate set to 6000000bps +0ms
  mediasoup:Channel request succeeded [id:27876544] +0ms
  mediasoup:Channel request succeeded [id:78779609] +0ms
  mediasoup:WebRtcTransport "transport.setMaxBitrate" request succeeded +1ms
  mediasoup:WebRtcTransport "transport.setMaxBitrate" request succeeded +0ms
  mediasoup:WebRtcTransport "transport.setRemoteDtlsParameters" request succeeded +0ms
  mediasoup:mediasoup-worker [id:hdbauorz#1] RTC::IceServer::HandleTuple() | transition from state 'new' to 'connected' +20ms
  mediasoup:mediasoup-worker [id:hdbauorz#1] RTC::WebRtcTransport::OnIceConnected() | ICE connected +0ms
  mediasoup:Peer receiveRequest() [method:createProducer] +26ms
  mediasoup:Peer _createProducer() [id:62475467, kind:audio] +0ms
  mediasoup:Channel request() [method:router.createProducer, id:14528906] +26ms
  mediasoup:Channel request succeeded [id:14528906] +1ms
  mediasoup:Peer "router.createProducer" request succeeded +2ms
  mediasoup:Producer constructor() +412ms
  mediasoup:Consumer constructor() +29ms
  mediasoup:Channel request() [method:router.createConsumer, id:23600514] +1ms
  mediasoup:Channel request succeeded [id:23600514] +48ms
  mediasoup:mediasoup-worker [id:hdbauorz#1] RTC::Consumer::AddProfile() | profile added [profile:default] +56ms
  mediasoup:mediasoup-worker [id:hdbauorz#1] RTC::IceServer::HandleTuple() | transition from state 'connected' to 'completed' +0ms
  mediasoup:mediasoup-worker [id:hdbauorz#1] RTC::WebRtcTransport::OnIceCompleted() | ICE completed +0ms
  mediasoup:Peer "router.createConsumer" request succeeded +48ms
  mediasoup:Peer receiveRequest() [method:enableConsumer] +1ms
  mediasoup:Consumer enable() +49ms
  mediasoup:Consumer remoteSetPreferredProfile() [profile:default] +0ms
  mediasoup:Channel request() [method:consumer.enable, id:37102232] +1ms
  mediasoup:Channel request succeeded [id:37102232] +1ms
  mediasoup:Consumer "consumer.enable" request succeeded +1ms
  mediasoup:Peer receiveRequest() [method:createTransport] +5ms
  mediasoup:Peer _createWebRtcTransport() [id:82216461, direction:recv] +0ms
  mediasoup:Channel request() [method:router.createWebRtcTransport, id:79070729] +4ms
  mediasoup:mediasoup-worker [id:hdbauorz#1] RTC::IceServer::IceServer() | [usernameFragment:r1bmf410kcflor9a, password:su0zklexxdoyl8qrp3podanam29z6df4] +6ms
  mediasoup:Channel request succeeded [id:79070729] +1ms
  mediasoup:Peer "router.createWebRtcTransport" request succeeded +1ms
  mediasoup:WebRtcTransport constructor() +83ms
  mediasoup:Peer receiveNotification() [method:updateTransport] +8ms
  mediasoup:WebRtcTransport setRemoteDtlsParameters() +8ms
  mediasoup:Channel request() [method:transport.setRemoteDtlsParameters, id:38077456] +8ms
  mediasoup:Peer receiveRequest() [method:enableConsumer] +3ms
  mediasoup:Consumer enable() +17ms
  mediasoup:Consumer remoteSetPreferredProfile() [profile:default] +0ms
  mediasoup:Channel request() [method:consumer.enable, id:20125353] +5ms
  mediasoup:mediasoup-worker [id:hdbauorz#1] RTC::IceServer::HandleTuple() | transition from state 'new' to 'connected' +14ms
  mediasoup:mediasoup-worker [id:hdbauorz#1] RTC::WebRtcTransport::OnIceConnected() | ICE connected +1ms
  mediasoup:Channel request succeeded [id:38077456] +1ms
  mediasoup:WebRtcTransport "transport.setRemoteDtlsParameters" request succeeded +7ms
  mediasoup:Channel request succeeded [id:20125353] +1ms
  mediasoup:Consumer "consumer.enable" request succeeded +3ms
  mediasoup:mediasoup-worker [id:hdbauorz#1] RTC::Consumer::SendRtpPacket() | sending sync packet [ssrc:20022765, seq:1, ts:1, profile:default] from original [seq:9394, ts:3418366170] +4ms
  mediasoup:mediasoup-worker [id:hdbauorz#1] RTC::Consumer::SendRtpPacket() | sending sync packet [ssrc:98357273, seq:1, ts:1, profile:default] from original [seq:8522, ts:827550875] +61ms
  mediasoup:mediasoup-worker [id:hdbauorz#1] RTC::IceServer::HandleTuple() | transition from state 'connected' to 'completed' +0ms
  mediasoup:mediasoup-worker [id:hdbauorz#1] RTC::WebRtcTransport::OnIceCompleted() | ICE completed +0ms
  mediasoup:Peer receiveRequest() [method:createProducer] +70ms
  mediasoup:Peer _createProducer() [id:19193139, kind:video] +0ms
  mediasoup:Channel request() [method:router.createProducer, id:80358768] +66ms
  mediasoup:Channel request succeeded [id:80358768] +1ms
  mediasoup:Peer "router.createProducer" request succeeded +1ms
  mediasoup:Producer constructor() +137ms
  mediasoup:Consumer constructor() +67ms
  mediasoup:Channel request() [method:router.createConsumer, id:53226988] +0ms
  mediasoup:Channel request succeeded [id:53226988] +7ms
  mediasoup:Peer "router.createConsumer" request succeeded +1ms
  mediasoup:Peer receiveRequest() [method:enableConsumer] +26ms
  mediasoup:Consumer enable() +34ms
  mediasoup:Consumer remoteSetPreferredProfile() [profile:default] +0ms
  mediasoup:Channel request() [method:consumer.enable, id:34046340] +27ms
  mediasoup:mediasoup-worker [id:hdbauorz#1] RTC::Consumer::CreateRtpStream() | NACK supported +38ms
  mediasoup:mediasoup-worker [id:hdbauorz#1] RTC::Consumer::CreateRtpStream() | PLI supported +0ms
  mediasoup:mediasoup-worker [id:hdbauorz#1] RTC::Transport::HandleConsumer() | requesting key frame for new Consumer since Transport already connected +4ms
  mediasoup:Channel request succeeded [id:34046340] +6ms
  mediasoup:Consumer "consumer.enable" request succeeded +6ms
  mediasoup:Producer getStats() +373ms
  mediasoup:Channel request() [method:producer.getStats, id:91302383] +333ms
  mediasoup:Channel request succeeded [id:91302383] +1ms
  mediasoup:Producer "producer.getStats" request succeeded +1ms
  mediasoup:Producer getStats() +80ms
  mediasoup:Channel request() [method:producer.getStats, id:81364002] +80ms
  mediasoup:Channel request succeeded [id:81364002] +1ms
  mediasoup:Producer "producer.getStats" request succeeded +1ms
  mediasoup:Consumer getStats() +464ms
  mediasoup:Channel request() [method:consumer.getStats, id:79859455] +49ms
  mediasoup:Consumer getStats() +0ms
  mediasoup:Channel request() [method:consumer.getStats, id:73519181] +0ms
  mediasoup:Channel request succeeded [id:79859455] +0ms
  mediasoup:Consumer "consumer.getStats" request succeeded +0ms
  mediasoup:Channel channel ended by the other side +1ms
mediasoup-worker's stderr: ABORT[id:hdbauorz#1] RTC::Consumer::GetStats() | failed assertion `it != this->mapProfileRtpStream.end()': effective profile does not map to a rtp stream
  mediasoup:ERROR:Worker child process exited [id:hdbauorz#1, code:null, signal:SIGABRT] +0ms

@artushin
Copy link
Author

So the answer to your prior question I think is, no, I now don't think that the crash is happening when closing the consumer, because in the case above the consumer was never closed.

@jmillan
Copy link
Member

jmillan commented Jan 28, 2018

@ibc, I definitely agree with the fact that we are assuming things here.

Consumer::effectiveProfile is initialized to Profile::Default on construction.., suddenly Consumer::GetStats() asserts the following:

auto it = this->mapProfileRtpStream.find(this->effectiveProfile);

MS_ASSERT( it != this->mapProfileRtpStream.end(), "effective profile does not map to a rtp stream");

Yeah, Consumer::effectiveProfile must be set by its own merits... It must be initialized with Profiles:NONE and be upgraded by the corresponding a RTP packet.

Will check it as soon as possible.

@artushin
Copy link
Author

I'm tending to run into this more and more. Is there a workaround that could alleviate the issue for me?

My understanding of what @jmillan mentioned is that getStats is being called before Consumer internally resolves its effectiveProfile. Would waiting until some event occurs to query for stats solve the issue in the meantime?

@jmillan
Copy link
Member

jmillan commented Jan 30, 2018

Hi,

I'll look into this today.

You may for now just wait some time since consumer creation to requesting its stats.

After this is fixed, the consumer's profile will tell whether there are any stats to retrieve: Ie: 'NONE: no RTP is being sent to the consumer'

@jmillan
Copy link
Member

jmillan commented Jan 30, 2018

@artushin,

May you please try the latest master revision?

@artushin
Copy link
Author

artushin commented Jan 30, 2018 •
edited
Loading

Seems good so far. I'll let you know if I encounter it again.

@jmillan
Copy link
Member

jmillan commented Jan 30, 2018

Thanks for reporting!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@jmillan jmillan

Labels
bug
Milestone
v2 updates
Development

No branches or pull requests
3 participants
@ibc @jmillan @artushin