Closed
Bug 981256
Opened 10 years ago
Closed 10 years ago
Intermittent test_peerConnection_basicAudio.html | Valid rtcp timestamp 1394239477041.543 <= 1394239476533 (508.54296875 ms)
Categories
(Core :: WebRTC, defect)
Tracking
()
RESOLVED
FIXED
mozilla30
Tracking | Status | |
---|---|---|
firefox28 | --- | unaffected |
firefox29 | --- | unaffected |
firefox30 | --- | fixed |
firefox-esr24 | --- | unaffected |
People
(Reporter: philor, Assigned: jib)
References
Details
(Keywords: intermittent-failure)
https://tbpl.mozilla.org/php/getParsedLog.php?id=35822002&tree=Mozilla-Inbound Windows XP 32-bit mozilla-inbound debug test mochitest-3 on 2014-03-07 16:39:28 PST for push f80cd801c0e3 slave: t-xp32-ix-128 16:44:26 INFO - 240 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudio.html | Valid rtcp timestamp 1394239477041.543 >= 1394239455433 (21608.54296875 ms) 16:44:26 INFO - 241 INFO TEST-UNEXPECTED-FAIL | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudio.html | Valid rtcp timestamp 1394239477041.543 <= 1394239476533 (508.54296875 ms) 16:44:26 INFO - System JS : WARNING http://mochi.test:8888/tests/dom/media/tests/mochitest/pc.js:1608 - reference to undefined property counters[res.type] 16:44:26 INFO - 3636[1300480]: Flow[e5645937eb581070:1,rtp(none)]; Layer[dtls]: Would have blocked 16:44:26 INFO - 3636[1300480]: Flow[239edd254a7c78d1:1,rtp(none)]; Layer[dtls]: Would have blocked 16:44:26 INFO - 242 INFO TEST-INFO | dumping last 34 message(s) 16:44:26 INFO - 243 INFO TEST-INFO | if you need more context, please use SimpleTest.requestCompleteLog() in your test 16:44:26 INFO - 244 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudio.html | Coherent stats id 16:44:26 INFO - 245 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudio.html | Valid rtp timestamp 1394239466641.3794 >= 1394239455433 (11208.37939453125 ms) 16:44:26 INFO - 246 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudio.html | Valid rtp timestamp 1394239466641.3794 <= 1394239476583 (-9941.62060546875 ms) 16:44:26 INFO - 247 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudio.html | Ssrc has length 16:44:26 INFO - 248 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudio.html | Ssrc not lengthy 16:44:26 INFO - 249 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudio.html | Ssrc numeric 16:44:26 INFO - 250 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudio.html | Ssrc within limits 16:44:26 INFO - 251 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudio.html | Rtp packetsReceived 16:44:26 INFO - 252 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudio.html | Rtp bytesReceived 16:44:26 INFO - 253 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudio.html | Remote is rtcp 16:44:26 INFO - 254 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudio.html | Remote backlink match 16:44:26 INFO - 255 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudio.html | Rtcp is outbound 16:44:26 INFO - 256 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudio.html | Rtcp packetsSent 16:44:26 INFO - 257 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudio.html | Rtcp bytesSent 16:44:26 INFO - 258 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudio.html | Remote ssrc match 16:44:26 INFO - 259 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudio.html | Coherent stats id 16:44:26 INFO - 260 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudio.html | Valid rtp timestamp 1394239466641.3794 >= 1394239455433 (11208.37939453125 ms) 16:44:26 INFO - 261 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudio.html | Valid rtp timestamp 1394239466641.3794 <= 1394239476586 (-9944.62060546875 ms) 16:44:26 INFO - 262 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudio.html | Ssrc has length 16:44:26 INFO - 263 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudio.html | Ssrc not lengthy 16:44:26 INFO - 264 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudio.html | Ssrc numeric 16:44:26 INFO - 265 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudio.html | Ssrc within limits 16:44:26 INFO - 266 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudio.html | Rtp packetsSent 16:44:26 INFO - 267 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudio.html | Rtp bytesSent 16:44:26 INFO - 268 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudio.html | Remote is rtcp 16:44:26 INFO - 269 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudio.html | Remote backlink match 16:44:26 INFO - 270 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudio.html | Rtcp is inbound 16:44:26 INFO - 271 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudio.html | Rtcp packetsReceived 16:44:26 INFO - 272 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudio.html | Rtcp packetsLost 16:44:26 INFO - 273 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudio.html | Rtcp bytesReceived 16:44:26 INFO - 274 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudio.html | Rtcp jitter 16:44:26 INFO - 275 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudio.html | Remote ssrc match 16:44:26 INFO - 276 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudio.html | Coherent stats id 16:44:26 INFO - 277 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudio.html | Valid rtcp timestamp 1394239477041.543 >= 1394239455433 (21608.54296875 ms) 16:44:26 INFO - 278 INFO TEST-UNEXPECTED-FAIL | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudio.html | Valid rtcp timestamp 1394239477041.543 <= 1394239476588 (453.54296875 ms) 16:44:26 INFO - 3636[1300480]: Flow[e5645937eb581070:1,rtp(none)]; Layer[dtls]: Would have blocked 16:44:26 INFO - System JS : WARNING http://mochi.test:8888/tests/dom/media/tests/mochitest/pc.js:1662 - reference to undefined property counters2[res.type] 16:44:26 INFO - 3636[1300480]: Flow[239edd254a7c78d1:1,rtp(none)]; Layer[dtls]: Would have blocked 16:44:26 INFO - 3636[1300480]: Flow[e5645937eb581070:1,rtp(none)]; Layer[dtls]: Would have blocked 16:44:26 INFO - 3636[1300480]: Flow[239edd254a7c78d1:1,rtp(none)]; Layer[dtls]: Would have blocked 16:44:26 INFO - 3636[1300480]: Flow[e5645937eb581070:1,rtp(none)]; Layer[dtls]: Would have blocked 16:44:26 INFO - 3636[1300480]: Flow[239edd254a7c78d1:1,rtp(none)]; Layer[dtls]: Would have blocked 16:44:26 INFO - 3636[1300480]: Flow[e5645937eb581070:1,rtp(none)]; Layer[dtls]: Would have blocked 16:44:26 INFO - 3636[1300480]: Flow[239edd254a7c78d1:1,rtp(none)]; Layer[dtls]: Would have blocked 16:44:26 INFO - 0[28ab98]: [main|PeerConnectionImpl] PeerConnectionImpl.cpp:1596: sipcc::PeerConnectionImpl::CloseInt: Closing PeerConnectionImpl 239edd254a7c78d1; ending call 16:44:26 INFO - 0[f448c68]: [CCAPP Task|def] ccapi.c:1445: SIPCC-CC_API: 1/20, cc_int_onhook: UI -> GSM: ONHOOK 16:44:26 INFO - 0[f448c68]: [CCAPP Task|def] ccapi.c:1447: (1/20) On-hook called from c:/builds/moz2_slave/m-in-w32-d-0000000000000000000/build/media/webrtc/signaling/src/sipcc/core/ccapp/ccprovider.c:657 16:44:26 INFO - 0[c155850]: [GSM Task|def] dcsm.c:532: SIPCC-DCSM: dcsm_process_event: DCSM 11 :(DCSM_READY:ONHOOK ) 16:44:26 INFO - 0[c155850]: [GSM Task|fsm_sm] sm.c:46: SIPCC-FSM: sm_process_event: DEF 20 : 01EF7B2Fx: sm entry: (STABLE:ONHOOK) 16:44:26 INFO - 0[28ab98]: [main|PeerConnectionImpl] PeerConnectionImpl.cpp:1596: sipcc::PeerConnectionImpl::CloseInt: Closing PeerConnectionImpl e5645937eb581070; ending call 16:44:26 INFO - 0[c155850]: [GSM Task|fsm_sm] fsmdef.c:6711: SIPCC-FSM: fsmdef_ev_onhook: Entered. 16:44:26 INFO - 0[f448c68]: [CCAPP Task|def] ccapi.c:1445: SIPCC-CC_API: 1/21, cc_int_onhook: UI -> GSM: ONHOOK 16:44:26 INFO - 0[c155850]: [GSM Task|fsm_sm] fsmdef.c:1986: SIPCC-FSM: 1/20, fsmdef_release: Entered. cause= NORMAL 16:44:26 INFO - 0[f448c68]: [CCAPP Task|def] ccapi.c:1447: (1/21) On-hook called from c:/builds/moz2_slave/m-in-w32-d-0000000000000000000/build/media/webrtc/signaling/src/sipcc/core/ccapp/ccprovider.c:657 16:44:26 INFO - 0[c155850]: [GSM Task|fsm_sm] fsmdef.c:9197: SIPCC-FSM: fsmdef_notify_hook_event: Entered. 16:44:26 INFO - 0[c155850]: [GSM Task|def] ccapi.c:1445: SIPCC-CC_API: 1/20, cc_int_onhook: GSM -> SIP: ONHOOK 16:44:26 INFO - 0[c155850]: [GSM Task|def] ccapi.c:1447: (1/20) On-hook called from c:/builds/moz2_slave/m-in-w32-d-0000000000000000000/build/media/webrtc/signaling/src/sipcc/core/gsm/fsmdef.c:9206 16:44:26 INFO - 0[c155850]: [GSM Task|tnp] ui.c:1023: SIPCC-UI_API: ui_get_idle_prompt_string: called 16:44:26 INFO - 0[c155850]: [GSM Task|tnp] ui.c:654: SIPCC-UI_API: 1/20, ui_set_call_status: the stat string = 16:44:26 INFO - 0[c155850]: [GSM Task|tnp] ui.c:616: SIPCC-UI_API: 1/20, ui_set_call_status_display: the stat string =, timeout= 0, priority=0 16:44:26 INFO - 0[c155850]: [GSM Task|tnp] ui.c:104: SIPCC-UI_API: 1/20, ui_call_state: event=1 16:44:26 INFO - 0[c155850]: [GSM Task|def] fsm.c:346: SIPCC-FSM: 1/20, fsm_change_state: DEF: STABLE -> CLOSED 16:44:26 INFO - 0[f448c68]: [CCAPP Task|def] ccprovider.c:1613: SIPCC-SIP_CC_PROV: ccappUpdateSessionData: Call_STATE:. state=1, attr=0, cause=5, instance=0 16:44:26 INFO - 0[c155850]: [GSM Task|def] dcsm.c:397: SIPCC-DCSM: dcsm_update_gsm_state: 20 : DCSM_READY --> DCSM_READY 16:44:26 INFO - 0[f448c68]: [CCAPP Task|CC_SIPCCService] CC_SIPCCService.cpp:724: onCallEvent(CCAPI_CALL_EV_STATE, 10014, [ONHOOK|] 16:44:26 INFO - 0[c155850]: [GSM Task|fsm_sm] fsmdef.c:1293: SIPCC-FSM: 0/0, fsmdef_init_dcb: call_not_counted_in_mnc_bt = FALSE 16:44:26 INFO - 0[f448c68]: [CCAPP Task|def] ccapi_call.c:57: SIPCC-SIP_CC_PROV: CCAPI_Call_releaseCallInfo: ref=0F0D59B8: count=2 16:44:26 INFO - 0[c155850]: [GSM Task|def] fsm.c:346: SIPCC-FSM: 0/20, fsm_change_state: DEF: CLOSED -> IDLE 16:44:26 INFO - 0[f448c68]: [CCAPP Task|def] ccapi_call.c:57: SIPCC-SIP_CC_PROV: CCAPI_Call_releaseCallInfo: ref=0DB80718: count=1 16:44:26 INFO - 0[c155850]: [GSM Task|def] dcsm.c:397: SIPCC-DCSM: dcsm_update_gsm_state: 20 : DCSM_READY --> DCSM_READY 16:44:26 INFO - 0[c155850]: [GSM Task|def] sm.c:65: SIPCC-GSM: 1/20, sm_process_event: DEF :(STABLE:ONHOOK ) 16:44:26 INFO - 0[c155850]: [GSM Task|fsm_sm] fsm.c:157: SIPCC-GSM_DBG_PTR: FSM 20 : fsm_get_fcb_by_call_id_and_type : fcb= 0C1595B0 16:44:26 INFO - 0[c155850]: [GSM Task|fsm_sm] fsm.c:157: SIPCC-GSM_DBG_PTR: FSM 20 : fsm_get_fcb_by_call_id_and_type : fcb= 00000000 16:44:26 INFO - 0[c155850]: [GSM Task|def] fsm.c:346: SIPCC-FSM: 0/20, fsm_change_state: CNF: IDLE -> IDLE ... https://tbpl.mozilla.org/php/getParsedLog.php?id=35826976&tree=Mozilla-Central Windows XP 32-bit mozilla-central debug test mochitest-3 on 2014-03-07 18:40:46 PST for push 3bb690f96b92 slave: t-xp32-ix-126 241 INFO TEST-UNEXPECTED-FAIL | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudio.html | Valid rtcp timestamp 1394246747147.9841 <= 1394246744899 (2248.984130859375 ms)
Assignee | ||
Updated•10 years ago
|
Assignee: nobody → jib
Comment hidden (Legacy TBPL/Treeherder Robot) |
Comment hidden (Legacy TBPL/Treeherder Robot) |
Comment hidden (Legacy TBPL/Treeherder Robot) |
Assignee | ||
Comment 4•10 years ago
|
||
All XP. Fixed by disabling test on XP in Bug 970686. XP clock drift issue is Bug 979649.
Updated•10 years ago
|
status-firefox28:
--- → unaffected
status-firefox29:
--- → unaffected
status-firefox30:
--- → fixed
status-firefox-esr24:
--- → unaffected
Target Milestone: --- → mozilla30
Comment hidden (Legacy TBPL/Treeherder Robot) |
Comment hidden (Legacy TBPL/Treeherder Robot) |
Comment hidden (Legacy TBPL/Treeherder Robot) |
Assignee | ||
Comment 8•10 years ago
|
||
Sigh, now Windows 7. This is the same serious multi-second growing "drift" we've only seen on XP till now. Did some new webrtc test land around 2014-04-04 03am? The test that fails is that rtcp timestamps must not be before connection opened, with a 1 second cushion. How well are tests isolated? 4 seconds is enough to make me think we're seeing rtcp packets from an earlier test (though it's curious why this would happen only on Windows). Re-open or new bug?
Reporter | ||
Comment 9•10 years ago
|
||
The way to answer "was that a code change?" is to open the link to the log in the comment in the bug, then click the "for push (cset hash)" link at the top of the log, which opens tbpl for that push, then hit the down-arrow on tbpl. But... that's going to give you fx-team in the middle of the night, plus mozilla-aurora about 70 seconds later. Extremely unlikely. Better bets? A scheduled task, since 3am is the sort of time that Windows likes to schedule things; a failure to disable adjusting the clock while things are running; a timebomb in your code; an uncaught failure in a previous test. The latter is certainly likely: there's pretty much no outside enforcement of isolation between tests, so if your code doesn't have a way to synchronously shut everything down, or if it does but your tests don't use it at the end of every test, well, you're just being loaded in an iframe on top of the previous test.
Comment 10•10 years ago
|
||
I agree: leave closed for now unless we get more reports. Thanks philor
You need to log in
before you can comment on or make changes to this bug.
Description
•