Closed Bug 980497 Opened 10 years ago Closed 10 years ago

Intermittent test_peerConnection_basicAudioVideoCombined.html | No more than sent | No more than sent bytes

Categories

(Core :: WebRTC: Audio/Video, defect)

Product:
Core
Component:
WebRTC: Audio/Video
Platform:
x86_64
Linux
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

()

Status:
RESOLVED FIXED
Milestone:
mozilla30
Tracking Flags:
Tracking Status
firefox28 --- unaffected
firefox29 --- unaffected
firefox30 --- fixed
firefox-esr24 --- unaffected

People

(Reporter: RyanVM, Assigned: jib)

References

Details

(Keywords: intermittent-failure)

Attachments

(1 file)

Temporarily mute test
1.95 KB, patch
jesup
: review+
Details | Diff | Splinter Review 
https://tbpl.mozilla.org/php/getParsedLog.php?id=35739555&tree=Mozilla-Inbound

Ubuntu VM 12.04 x64 mozilla-inbound debug test mochitest-3 on 2014-03-06 11:22:13 PST for push a0c4fa6338dc
slave: tst-linux64-spot-633

11:26:31     INFO -  234 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudioVideoCombined.html | Ssrc not lengthy
11:26:31     INFO -  235 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudioVideoCombined.html | Ssrc numeric
11:26:31     INFO -  236 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudioVideoCombined.html | Ssrc within limits
11:26:31     INFO -  237 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudioVideoCombined.html | Rtp packetsSent
11:26:31     INFO -  238 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudioVideoCombined.html | Rtp bytesSent
11:26:31     INFO -  -502106368[11e0d60]: Flow[58de60d139c3e20f:1,rtp(none)]; Layer[dtls]: Would have blocked
11:26:31     INFO -  239 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudioVideoCombined.html | Remote is rtcp
11:26:31     INFO -  240 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudioVideoCombined.html | Remote backlink match
11:26:31     INFO -  241 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudioVideoCombined.html | Rtcp is inbound
11:26:31     INFO -  242 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudioVideoCombined.html | Rtcp packetsReceived
11:26:31     INFO -  243 INFO TEST-UNEXPECTED-FAIL | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudioVideoCombined.html | No more than sent
11:26:31     INFO -  -502106368[11e0d60]: Flow[9c24952cd7d41de1:1,rtp(none)]; Layer[dtls]: Would have blocked
11:26:31     INFO -  244 INFO TEST-INFO | dumping last 2 message(s)
11:26:31     INFO -  245 INFO TEST-INFO | if you need more context, please use SimpleTest.requestCompleteLog() in your test
11:26:31     INFO -  246 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudioVideoCombined.html | Rtcp packetsLost
11:26:31     INFO -  247 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudioVideoCombined.html | Rtcp bytesReceived
11:26:31     INFO -  248 INFO TEST-UNEXPECTED-FAIL | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudioVideoCombined.html | No more than sent bytes
11:26:31     INFO -  -502106368[11e0d60]: Flow[58de60d139c3e20f:1,rtp(none)]; Layer[dtls]: Would have blocked
11:26:31     INFO -  -502106368[11e0d60]: Flow[9c24952cd7d41de1:1,rtp(none)]; Layer[dtls]: Would have blocked
11:26:31     INFO -  -502106368[11e0d60]: Flow[58de60d139c3e20f:1,rtp(none)]; Layer[dtls]: Would have blocked
11:26:31     INFO -  -502106368[11e0d60]: Flow[58de60d139c3e20f:2,rtp(none)]; Layer[dtls]: Would have blocked
11:26:31     INFO -  -502106368[11e0d60]: Flow[9c24952cd7d41de1:1,rtp(none)]; Layer[dtls]: Would have blocked
11:26:31     INFO -  -502106368[11e0d60]: Flow[58de60d139c3e20f:1,rtp(none)]; Layer[dtls]: Would have blocked
11:26:31     INFO -  -502106368[11e0d60]: Flow[9c24952cd7d41de1:1,rtp(none)]; Layer[dtls]: Would have blocked
Summary: Add media packet loss and RTT statistics to the stats API → Intermittent test_peerConnection_basicAudioVideoCombined.html | No more than sent | No more than sent bytes
This is certainly unexpected, as I've never seen this assert hit before on any of the tries. How can RTCP receiver-reports returned to sender-side show 3 packets received by remote end, when local side says only 2 were sent?

11:26:30     INFO -  196 INFO TEST-INFO | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudioVideoCombined.html | PeerConnectionWrapper (pcRemote): Got stats: 
{
  "outbound_rtcp_video_1":
  {"id":"outbound_rtcp_video_1",
    "timestamp":1394133990687.429,
    "type":"inboundrtp",
    "isRemote":true,
    "remoteId":"outbound_rtp_video_1",
    "ssrc":"3951278357",
    "bytesReceived":675,
    "jitter":0,
    "packetsLost":0,
    "packetsReceived":3
  },
  "outbound_rtp_video_1":
  {"id":"outbound_rtp_video_1",
    "timestamp":1394133990710.6594,
    "type":"outboundrtp",
    "isRemote":false,
    "remoteId":"outbound_rtcp_video_1",
    "ssrc":"3951278357",
    "bytesSent":664,
    "packetsSent":2
  },

I can add a cushion, but anyone have any ideas how this can occur?
That extra packet was apparently 11 bytes. Very odd.
Might a packet have been split by IPv4 fragmentation? The received byte overage is just 11 bytes. 12 bytes would be an rtp header...

I suggest we leave this open for a bit to see how often this happens.

I also started a new try to test on - https://tbpl.mozilla.org/?tree=Try&rev=de4cdcb21786
You can drop the logging level for SendRTCPPacket/ReceiveRTCPPacket in AudioConduit/VideoConduit so they get logged at the default signaling log level, and modify the log to dump the length and the identifier byte for the first RTCP chunk.

example:

+ CSFLogDebug(logTag, "%s : channel %d , len %d, first rtcp = %u ",
+ __FUNCTION__, channel, len, ((uint8_t *) data)[1]);
This doesn't look right:

http://dxr.mozilla.org/mozilla-central/source/media/webrtc/signaling/src/media-conduit/AudioConduit.cpp#177

From what I can tell, GetRemoteRTCPData is for grabbing information from sender reports, not receiver reports. No matter what it does though, we're also calling GetRemoteRTCPData for the inbound stats, and using the same packetsReceived outparam in both cases:

http://dxr.mozilla.org/mozilla-central/source/media/webrtc/signaling/src/media-conduit/AudioConduit.cpp#184
http://dxr.mozilla.org/mozilla-central/source/media/webrtc/signaling/src/media-conduit/AudioConduit.cpp#202
(In reply to Byron Campen [:bwc] from comment #8)
> From what I can tell, GetRemoteRTCPData is for grabbing information from
> sender reports, not receiver reports. No matter what it does though, we're
> also calling GetRemoteRTCPData for the inbound stats, and using the same
> packetsReceived outparam in both cases:

Yup, you're right. I see what's going on now. I got some pretty basic assumptions wrong about what senderReports holds in the outbound case from observing them being populated in what I thought was a single-direction context (It looked to me like some layer was conveniently caching the last outgoing SR for me!) Instead I now see it's the other direction co-mingled in at a low level (!) - I'm surprised this worked as well as it did. I just did a send-only test and rtcp doesn't work on either end then. Very clarifying.

New patch coming up. Looks like I'll have to cache the last outgoing SR info (packetsSent) in order to calculate the remote-side packetsReceived number that the stats-spec expects, as the RRs don't have this.
(In reply to Byron Campen [:bwc] from comment #9)
> I suspect that what we actually want to be using is this:
> 
> http://dxr.mozilla.org/mozilla-central/source/media/webrtc/trunk/webrtc/
> voice_engine/include/voe_rtp_rtcp.h#198

No, this one's a typo. It calls GetRTPStatistics (not GetRTCPStatistics) here http://dxr.mozilla.org/mozilla-central/source/media/webrtc/trunk/webrtc/voice_engine/voe_rtp_rtcp_impl.cc#467

It appears to have been removed or renamed upstream.
Noisy robot. Working on fix, but feel free to land this in the meantime.
Attachment #8387770 - Flags: review?(rjesup)
Attachment #8387770 - Flags: review?(rjesup) → review+
Properly fixed with test re-enabled in Bug 970686 comment 42:
> https://hg.mozilla.org/mozilla-central/rev/c8e80efab6fb
> https://hg.mozilla.org/mozilla-central/rev/80fad01e53bb
No longer blocks: 970686
Status: NEW → RESOLVED
Closed: 10 years ago
Depends on: 970686
Resolution: --- → FIXED
Whiteboard: [leave open]
Target Milestone: --- → mozilla30
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: