1408258 - OpenH264 Plugin does not work frequently in firefox 56

Status: UNCONFIRMED

(Core :: Audio/Video: GMP, defect, P2)

Description

[xpeng]

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.

Comment 1

[Andreas Pehrson [:pehrsons]]

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.

Comment 2

[Randell Jesup [:jesup] (needinfo me)]

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.

Comment 3

[xpeng]

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

Comment 4

[xpeng]

Attachment: openh264_do_not_work.rar

Comment 5

[xpeng]

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.

Comment 6

[Randell Jesup [:jesup] (needinfo me)]

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

Comment 7

[Randell Jesup [:jesup] (needinfo me)]

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;
  }

Comment 8

[Randell Jesup [:jesup] (needinfo me)]

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

Comment 9

[xpeng]

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

Comment 10

[Andreas Pehrson [:pehrsons]]

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

Comment 11

[Nils Ohlmeier [:drno]]

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

Comment 12

[xpeng]

(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.