xpeng Reporter
	Description • 7 years ago

User Agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:56.0) Gecko/20100101 Firefox/56.0
Build ID: 20170926190823

Steps to reproduce:

Enter a video conferene(webrtc) with H264 codec (1080P),


Actual results:

There is no video in conference(webrtc) even if we open a new tab and reenter the conference , It will be fine if  disable and enable openh264 plugin, and reenter conference. This issue happens frequently in firefox 56 especially using 1080P resolution.  


Expected results:

the video should be decoded normally.

	Andreas Pehrson [:pehrsons] (back on Aug 5)
	Comment 1 • 7 years ago

Randell, who should I assign to investigate OpenH264 issues? I'm marking it GMP for now, as that cannot be ruled out.

xpeng, if you could provide a minimal testcase, perhaps a jsfiddle, that reproduces this, that would help us a lot, thanks.

	Randell Jesup [:jesup] (needinfo me)
	Comment 2 • 7 years ago

Also: logs with signaling:4,GMP:5 would help a lot.  If it's the codec itself, then one of the people from Cisco/OpenH264.

	xpeng Reporter
	Comment 3 • 7 years ago

we set the log option in about:networking when the issue is reproduced :  
the log option should not all take effect in about:networking.
(timestamp,signaling:5,mediapipeline:5,nICEr:5,stun:5,net:5,stunserver:5,UDPSocket:5,third_party:5,GMP:5,ice:5,MediaSample:5,logging:5,CMP:5,extra:5,nicer:5,syslog:5,webrtc_trace:65535,generic:5,MediaPipelineFactory:5,sdp:5,jsep:5,stderr:5,mtransport:5)

2017-11-01 07:32:20.931000 UTC - [Main Thread]: D/webrtc_trace (bitrate_prober.cc:55): Bandwidth probing enabled, set to inactive
2017-11-01 07:32:20.931000 UTC - [Main Thread]: D/webrtc_trace (remote_bitrate_estimator_single_stream.cc:61): RemoteBitrateEstimatorSingleStream: Instantiating.
2017-11-01 07:32:20.932000 UTC - [Main Thread]: D/webrtc_trace (congestion_controller.cc:294): SignalNetworkState Down
2017-11-01 07:32:20.932000 UTC - [Main Thread]: D/webrtc_trace (paced_sender.cc:276): PacedSender paused.
2017-11-01 07:32:20.933000 UTC - [Unnamed thread 2E611710]: D/signaling [|WebrtcAudioSessionConduit] AudioConduit.cpp:673: mozilla::WebrtcAudioConduit::GetAudioFrame 
2017-11-01 07:32:20.933000 UTC - [Unnamed thread 2E611710]: D/signaling [|WebrtcAudioSessionConduit] AudioConduit.cpp:773: mozilla::WebrtcAudioConduit::GetAudioFrame GetAudioFrame:Got samples: length 640 
2017-11-01 07:32:20.933000 UTC - [Unnamed thread 2E611710]: V/mediapipeline Audio conduit returned buffer of length 640
2017-11-01 07:32:20.933000 UTC - [Unnamed thread 2E611710]: V/mediapipeline MediaPipeline::NotifyRealtimeTrackData() listener=25D30470, offset=0, duration=512
2017-11-01 07:32:20.940000 UTC - [Socket Thread]: V/nicer (ice/DEBUG) ICE(PC:1509520581377000 (id=92 url=https://meetings.ipvideotalk.com/rtc/meetings?xwebid=XWeb-p5pXIfe3RDmVauLkKcDzog)): Socket ready to read
2017-11-01 07:32:20.940000 UTC - [Socket Thread]: V/nicer (ice/DEBUG) ICE(PC:1509520581377000 (id=92 url=https://meetings.ipvideotalk.com/rtc/meetings?xwebid=XWeb-p5pXIfe3RDmVauLkKcDzog)): rearming
2017-11-01 07:32:20.940000 UTC - [Socket Thread]: V/nicer (ice/DEBUG) ICE(PC:1509520581377000 (id=92 url=https://meetings.ipvideotalk.com/rtc/meetings?xwebid=XWeb-p5pXIfe3RDmVauLkKcDzog)): Read 58 bytes from IP4:54.223.34.112:21460/UDP
2017-11-01 07:32:20.940000 UTC - [Socket Thread]: V/nicer (ice/DEBUG) ICE(PC:1509520581377000 (id=92 url=https://meetings.ipvideotalk.com/rtc/meetings?xwebid=XWeb-p5pXIfe3RDmVauLkKcDzog)): Message is not STUN
2017-11-01 07:32:20.940000 UTC - [Socket Thread]: V/nicer (ice/DEBUG) ICE-PEER(PC:1509520581377000 (id=92 url=https://meetings.ipvideotalk.com/rtc/meetings?xwebid=XWeb-p5pXIfe3RDmVauLkKcDzog):default): Delivering data
2017-11-01 07:32:20.940000 UTC - [Socket Thread]: V/mtransport Flow[ca18bd762c696076:0,rtp(none)]; Layer[ice]: PacketReceived(0-1509520581377000 (id=92 url=https://meetings.ipvideotalk.com/rtc/meetings?xwebid=XWeb-p5pXIfe3RDmVauLkKcDzog) aLevel=0,1,58)
2017-11-01 07:32:20.940000 UTC - [Socket Thread]: V/mtransport Flow[ca18bd762c696076:0,rtp(none)]; Layer[dtls]: PacketReceived(58)
2017-11-01 07:32:20.940000 UTC - [Socket Thread]: V/mediapipeline Successfully unprotected an SRTP packet of len 48
2017-11-01 07:32:20.940000 UTC - [Socket Thread]: V/mediapipeline ca18bd762c696076| Receive audio[{5b27d143-6ea5-4565-8f1a-827dd02b639e}] received RTP packet.
2017-11-01 07:32:20.940000 UTC - [Socket Thread]: D/signaling [Socket Thread|WebrtcAudioSessionConduit] AudioConduit.cpp:781: mozilla::WebrtcAudioConduit::ReceivedRTPPacket : channel 0
2017-11-01 07:32:20.942000 UTC - [Socket Thread]: V/nicer (ice/DEBUG) ICE(PC:1509520619589000 (id=92 url=https://meetings.ipvideotalk.com/rtc/meetings?xwebid=XWeb-p5pXIfe3RDmVauLkKcDzog)): Socket ready to read
2017-11-01 07:32:20.942000 UTC - [Socket Thread]: V/nicer (ice/DEBUG) ICE(PC:1509520619589000 (id=92 url=https://meetings.ipvideotalk.com/rtc/meetings?xwebid=XWeb-p5pXIfe3RDmVauLkKcDzog)): rearming
2017-11-01 07:32:20.942000 UTC - [Socket Thread]: V/nicer (ice/DEBUG) ICE(PC:1509520619589000 (id=92 url=https://meetings.ipvideotalk.com/rtc/meetings?xwebid=XWeb-p5pXIfe3RDmVauLkKcDzog)): Read 134 bytes from IP4:54.223.34.112:51548/UDP
2017-11-01 07:32:20.942000 UTC - [Socket Thread]: V/nicer (ice/DEBUG) ICE(PC:1509520619589000 (id=92 url=https://meetings.ipvideotalk.com/rtc/meetings?xwebid=XWeb-p5pXIfe3RDmVauLkKcDzog)): Message is not STUN
2017-11-01 07:32:20.942000 UTC - [Socket Thread]: V/nicer (ice/DEBUG) ICE-PEER(PC:1509520619589000 (id=92 url=https://meetings.ipvideotalk.com/rtc/meetings?xwebid=XWeb-p5pXIfe3RDmVauLkKcDzog):default): Delivering data
2017-11-01 07:32:20.942000 UTC - [Socket Thread]: V/mtransport Flow[ae370d2efbee1a8b:0,rtp(none)]; Layer[ice]: PacketReceived(0-1509520619589000 (id=92 url=https://meetings.ipvideotalk.com/rtc/meetings?xwebid=XWeb-p5pXIfe3RDmVauLkKcDzog) aLevel=0,1,134)
2017-11-01 07:32:20.942000 UTC - [Socket Thread]: V/mtransport Flow[ae370d2efbee1a8b:0,rtp(none)]; Layer[dtls]: PacketReceived(134)
2017-11-01 07:32:20.942000 UTC - [Socket Thread]: D/webrtc_trace (rtp_utility.cc:354): Failed to find extension id: 1
2017-11-01 07:32:20.942000 UTC - [Socket Thread]: V/mediapipeline Successfully unprotected an SRTP packet of len 124
2017-11-01 07:32:20.942000 UTC - [Socket Thread]: V/mediapipeline ae370d2efbee1a8b| Receive video[{c36a27cf-0c7b-48cb-aaa8-144afb58e850}] received RTP packet.
2017-11-01 07:32:20.942000 UTC - [Socket Thread]: V/signaling [Socket Thread|WebrtcVideoSessionConduit] VideoConduit.cpp:2120: mozilla::WebrtcVideoConduit::ReceivedRTPPacket: seq# 36215, Len 124, SSRC 1780755553 (0x6a242c61) 
2017-11-01 07:32:20.943000 UTC - [Socket Thread]: V/nicer (ice/DEBUG) ICE(PC:1509520619589000 (id=92 url=https://meetings.ipvideotalk.com/rtc/meetings?xwebid=XWeb-p5pXIfe3RDmVauLkKcDzog)): Socket ready to read
2017-11-01 07:32:20.943000 UTC - [Socket Thread]: V/nicer (ice/DEBUG) ICE(PC:1509520619589000 (id=92 url=https://meetings.ipvideotalk.com/rtc/meetings?xwebid=XWeb-p5pXIfe3RDmVauLkKcDzog)): rearming
2017-11-01 07:32:20.943000 UTC - [Socket Thread]: V/nicer (ice/DEBUG) ICE(PC:1509520619589000 (id=92 url=https://meetings.ipvideotalk.com/rtc/meetings?xwebid=XWeb-p5pXIfe3RDmVauLkKcDzog)): Read 327 bytes from IP4:54.223.34.112:51548/UDP
2017-11-01 07:32:20.943000 UTC - [Socket Thread]: V/nicer (ice/DEBUG) ICE(PC:1509520619589000 (id=92 url=https://meetings.ipvideotalk.com/rtc/meetings?xwebid=XWeb-p5pXIfe3RDmVauLkKcDzog)): Message is not STUN
2017-11-01 07:32:20.943000 UTC - [Socket Thread]: V/nicer (ice/DEBUG) ICE-PEER(PC:1509520619589000 (id=92 url=https://meetings.ipvideotalk.com/rtc/meetings?xwebid=XWeb-p5pXIfe3RDmVauLkKcDzog):default): Delivering data
2017-11-01 07:32:20.943000 UTC - [Socket Thread]: V/mtransport Flow[ae370d2efbee1a8b:0,rtp(none)]; Layer[ice]: PacketReceived(0-1509520619589000 (id=92 url=https://meetings.ipvideotalk.com/rtc/meetings?xwebid=XWeb-p5pXIfe3RDmVauLkKcDzog) aLevel=0,1,327)
2017-11-01 07:32:20.943000 UTC - [Socket Thread]: V/mtransport Flow[ae370d2efbee1a8b:0,rtp(none)]; Layer[dtls]: PacketReceived(327)
2017-11-01 07:32:20.943000 UTC - [Socket Thread]: D/webrtc_trace (rtp_utility.cc:354): Failed to find extension id: 1
2017-11-01 07:32:20.943000 UTC - [Socket Thread]: V/mediapipeline Successfully unprotected an SRTP packet of len 317
2017-11-01 07:32:20.943000 UTC - [Socket Thread]: V/mediapipeline ae370d2efbee1a8b| Receive video[{c36a27cf-0c7b-48cb-aaa8-144afb58e850}] received RTP packet.
2017-11-01 07:32:20.943000 UTC - [Socket Thread]: V/signaling [Socket Thread|WebrtcVideoSessionConduit] VideoConduit.cpp:2120: mozilla::WebrtcVideoConduit::ReceivedRTPPacket: seq# 36216, Len 317, SSRC 1780755553 (0x6a242c61) 
2017-11-01 07:32:20.943000 UTC - [Unnamed thread 2E611710]: D/signaling [|WebrtcAudioSessionConduit] AudioConduit.cpp:673: mozilla::WebrtcAudioConduit::GetAudioFrame 
2017-11-01 07:32:20.943000 UTC - [Unnamed thread 2E611710]: D/signaling [|WebrtcAudioSessionConduit] AudioConduit.cpp:773: mozilla::WebrtcAudioConduit::GetAudioFrame GetAudioFrame:Got samples: length 640 
2017-11-01 07:32:20.943000 UTC - [Unnamed thread 2E611710]: V/mediapipeline Audio conduit returned buffer of length 640

	xpeng Reporter
	Comment 5 • 7 years ago

we reproduced the issue again using the log flag : timestamp,signaling:5,mediapipeline:5,nICEr:5,stun:5,net:5,stunserver:5,UDPSocket:5,third_party:5,GMP:5,ice:5,MediaSample:5,logging:5,CMP:5,extra:5,nicer:5,syslog:5,webrtc_trace:65535,generic:5,MediaPipelineFactory:5,sdp:5,jsep:5,stderr:5,mtransport:5

the log file has been uploaded.

	Randell Jesup [:jesup] (needinfo me)
	Comment 6 • 7 years ago

It appears we're running out of shmem buffers:

2017-11-01 08:00:13.432000 UTC - [GMPThread]: V/GMP GMPVideoDecoderParent[27B83D60]::Decode() timestamp=1466622 keyframe=0
2017-11-01 08:00:13.432000 UTC - [GMPThread]: E/GMP GMPVideoDecoderParent[27B83D60]::Decode() ERROR; shmem buffer limit hit frame=60 encoded=21
2017-11-01 08:00:13.433000 UTC - [Unnamed thread 0F2FD210]: D/webrtc_trace (generic_decoder.cc:164): Failed to decode frame with timestamp 131996, error code: -1

	Randell Jesup [:jesup] (needinfo me)
	Comment 7 • 7 years ago

And this is where it comes from:
  // Very rough kill-switch if the plugin stops processing.  If it's merely
  // hung and continues, we'll come back to life eventually.
  // 3* is because we're using 3 buffers per frame for i420 data for now.
  if ((NumInUse(GMPSharedMem::kGMPFrameData) > 3*GMPSharedMem::kGMPBufLimit) ||
      (NumInUse(GMPSharedMem::kGMPEncodedData) > GMPSharedMem::kGMPBufLimit)) {
    LOGE(("GMPVideoDecoderParent[%p]::Decode() ERROR; shmem buffer limit hit frame=%d encoded=%d",
          this, NumInUse(GMPSharedMem::kGMPFrameData), NumInUse(GMPSharedMem::kGMPEncodedData)));
    return NS_ERROR_FAILURE;
  }

	Randell Jesup [:jesup] (needinfo me)
	Comment 8 • 7 years ago

so at the end of the previous stream at 08:00:10.37, we Close()/UnblockResetAndDrain()/Shutdown()/UnblockResetAndDrain(). 

We then later InitDecode() and start calling Decode(), but none of the frames are decoded, so after ~7 frames we run out of shmem buffers and it correctly stops trying to decode.

Note this is not the 2nd call -- I see the decoder successfully shut down 3 times before it hangs.  On the successful ones, the above sequence is followed by:
  38447:2017-11-01 07:58:56.416000 UTC - [GMPThread]: D/GMP GMPVideoDecoderParent[2AFF4DC0]::Recv__delete__()
  38451:2017-11-01 07:58:56.419000 UTC - [GMPThread]: D/GMP GMPVideoDecoderParent[2AFF4DC0]::ActorDestroy reason=1
  38452:2017-11-01 07:58:56.419000 UTC - [GMPThread]: D/GMP GMPVideoDecoderParent[2AFF4DC0]::UnblockResetAndDrain() awaitingResetComplete=0 awaitingDrainComplete=0

	xpeng Reporter
	Comment 9 • 7 years ago

what should we do next?
when the issue occurred , we can not encode and decode with h264 codec.

	Andreas Pehrson [:pehrsons] (back on Aug 5)
	Comment 10 • 7 years ago

Nils, this sounds like something for the OpenH264 folks to look at.

	Nils Ohlmeier [:drno]
	Comment 11 • 7 years ago

I'm wondering if this is the same problem as in bug 1397539.
xpeng can you check if you are able to repro the problem with the test here https://bugzilla.mozilla.org/show_bug.cgi?id=1397539#c1

	xpeng Reporter
	Comment 12 • 7 years ago

(In reply to Nils Ohlmeier [:drno] from comment #11)
> I'm wondering if this is the same problem as in bug 1397539.
> xpeng can you check if you are able to repro the problem with the test here
> https://bugzilla.mozilla.org/show_bug.cgi?id=1397539#c1
yes , we can reproduce the issue using the demo. but can not find the log : "shmem buffer limit hit "
I think it should not be the same problem. I will upload the log to the bug:  1397539.