Closed Bug 1398308 Opened 7 years ago Closed 6 years ago

Intermittent RTCDTMFSender-ontonechange-long.html | insertDTMF with duration greater than 6000 should be clamped to 6000 - assert_approx_equals: Expect tonechange event for "" to be fired approximately after 6070 seconds expected 6070 +/- 50 but got 6180

Categories

(Core :: WebRTC, defect, P5)

Product:
Core
Component:
WebRTC
Type:
defect

Tracking

()

Status:
RESOLVED INCOMPLETE

People

(Reporter: intermittent-bug-filer, Unassigned)

References

Details

(Keywords: intermittent-failure, Whiteboard: [stockwell unknown]) 

this has reduced a bit in frequency.
Whiteboard: [stockwell unknown]
this is following the same pattern of failures over the last few weeks.

here is a log for linux32 debug:
https://treeherder.mozilla.org/logviewer.html#?repo=mozilla-inbound&job_id=137010155

here is related data from that log:
[task 2017-10-14T16:27:53.515Z] 16:27:53     INFO - TEST-START | /webrtc/RTCDTMFSender-ontonechange-long.html
[task 2017-10-14T16:27:53.946Z] 16:27:53     INFO - PID 14470 | --DOCSHELL 0xc613ac00 == 3 [pid = 14516] [id = {21587bd4-58d6-4212-9352-fa0384d22444}]
[task 2017-10-14T16:27:54.419Z] 16:27:54     INFO - PID 14470 | ++DOCSHELL 0xc6122c00 == 4 [pid = 14516] [id = {46e15939-5e79-42f3-a384-6a2935babed6}]
[task 2017-10-14T16:27:54.419Z] 16:27:54     INFO - PID 14470 | ++DOMWINDOW == 29 (0xc6123000) [pid = 14516] [serial = 29] [outer = (nil)]
[task 2017-10-14T16:27:54.435Z] 16:27:54     INFO - PID 14470 | [Parent 14470, Main Thread] WARNING: [nsFrameLoader] ReallyStartLoadingInternal tried but couldn't show remote browser.
[task 2017-10-14T16:27:54.436Z] 16:27:54     INFO - PID 14470 | : file /builds/worker/workspace/build/src/dom/base/nsFrameLoader.cpp, line 904
[task 2017-10-14T16:27:54.441Z] 16:27:54     INFO - PID 14470 | ++DOMWINDOW == 30 (0xc6125c00) [pid = 14516] [serial = 30] [outer = 0xc6123000]
[task 2017-10-14T16:27:54.518Z] 16:27:54     INFO - PID 14470 | 1507998474510	Marionette	DEBUG	Register listener.js for window 2147483677
[task 2017-10-14T16:27:54.615Z] 16:27:54     INFO - PID 14470 | ++DOMWINDOW == 31 (0xc6128000) [pid = 14516] [serial = 31] [outer = 0xc6123000]
[task 2017-10-14T16:27:54.737Z] 16:27:54     INFO - PID 14470 | [Child 14516, Main Thread] WARNING: stylo: Web Components not supported yet: file /builds/worker/workspace/build/src/dom/base/nsDocument.cpp, line 6457
[task 2017-10-14T16:27:54.738Z] 16:27:54     INFO - PID 14470 | [Child 14516, Main Thread] WARNING: stylo: Web Components not supported yet: file /builds/worker/workspace/build/src/dom/base/nsDocument.cpp, line 6457
[task 2017-10-14T16:27:55.449Z] 16:27:55     INFO - PID 14470 | --DOMWINDOW == 30 (0xd1d31c00) [pid = 14516] [serial = 14] [outer = (nil)] [url = http://web-platform.test:8000/webrtc/RTCConfiguration-iceCandidatePoolSize.html]
[task 2017-10-14T16:27:55.450Z] 16:27:55     INFO - PID 14470 | --DOMWINDOW == 29 (0xd1e01400) [pid = 14516] [serial = 11] [outer = (nil)] [url = http://web-platform.test:8000/webrtc/RTCConfiguration-bundlePolicy.html]
[task 2017-10-14T16:27:55.450Z] 16:27:55     INFO - PID 14470 | --DOMWINDOW == 28 (0xc613d000) [pid = 14516] [serial = 20] [outer = (nil)] [url = http://web-platform.test:8000/webrtc/RTCConfiguration-iceTransportPolicy.html]
[task 2017-10-14T16:27:55.451Z] 16:27:55     INFO - PID 14470 | --DOMWINDOW == 27 (0xc613b400) [pid = 14516] [serial = 23] [outer = (nil)] [url = http://web-platform.test:8000/webrtc/RTCConfiguration-rtcpMuxPolicy.html]
[task 2017-10-14T16:27:55.452Z] 16:27:55     INFO - PID 14470 | --DOMWINDOW == 26 (0xd3410c00) [pid = 14516] [serial = 17] [outer = (nil)] [url = http://web-platform.test:8000/webrtc/RTCConfiguration-iceServers.html]
[task 2017-10-14T16:27:55.453Z] 16:27:55     INFO - PID 14470 | --DOMWINDOW == 25 (0xd820ec00) [pid = 14516] [serial = 5] [outer = (nil)] [url = http://web-platform.test:8000/webrtc/RTCCertificate.html]
[task 2017-10-14T16:27:55.558Z] 16:27:55     INFO - PID 14470 | [Child 14516, MediaManager] WARNING: Cannot query channel count on a AudioSegment with no chunks.: '!mChunks.IsEmpty()', file /builds/worker/workspace/build/src/dom/media/AudioSegment.h, line 395
[task 2017-10-14T16:27:57.516Z] 16:27:57     INFO - PID 14470 | --DOMWINDOW == 8 (0xe4e8ac00) [pid = 14470] [serial = 2] [outer = (nil)] [url = about:blank]
[task 2017-10-14T16:27:57.899Z] 16:27:57     INFO - PID 14470 | --DOCSHELL 0xc61ed800 == 3 [pid = 14516] [id = {6f50135b-e206-456a-b9d6-8cbba161359f}]
[task 2017-10-14T16:28:01.268Z] 16:28:01     INFO - PID 14470 | --DOMWINDOW == 24 (0xd782c800) [pid = 14516] [serial = 9] [outer = (nil)] [url = about:blank]
[task 2017-10-14T16:28:01.270Z] 16:28:01     INFO - PID 14470 | --DOMWINDOW == 23 (0xc61f4000) [pid = 14516] [serial = 24] [outer = (nil)] [url = about:blank]
[task 2017-10-14T16:28:01.270Z] 16:28:01     INFO - PID 14470 | --DOMWINDOW == 22 (0xce2c9000) [pid = 14516] [serial = 25] [outer = (nil)] [url = about:blank]
[task 2017-10-14T16:28:01.271Z] 16:28:01     INFO - PID 14470 | --DOMWINDOW == 21 (0xc613dc00) [pid = 14516] [serial = 21] [outer = (nil)] [url = about:blank]
[task 2017-10-14T16:28:01.271Z] 16:28:01     INFO - PID 14470 | --DOMWINDOW == 20 (0xce2c4800) [pid = 14516] [serial = 22] [outer = (nil)] [url = about:blank]
[task 2017-10-14T16:28:01.272Z] 16:28:01     INFO - PID 14470 | --DOMWINDOW == 19 (0xd34ea000) [pid = 14516] [serial = 18] [outer = (nil)] [url = about:blank]
[task 2017-10-14T16:28:01.274Z] 16:28:01     INFO - PID 14470 | --DOMWINDOW == 18 (0xd3405000) [pid = 14516] [serial = 19] [outer = (nil)] [url = about:blank]
[task 2017-10-14T16:28:01.274Z] 16:28:01     INFO - PID 14470 | --DOMWINDOW == 17 (0xd249b400) [pid = 14516] [serial = 15] [outer = (nil)] [url = about:blank]
[task 2017-10-14T16:28:01.274Z] 16:28:01     INFO - PID 14470 | --DOMWINDOW == 16 (0xd1d38000) [pid = 14516] [serial = 16] [outer = (nil)] [url = about:blank]
[task 2017-10-14T16:28:01.275Z] 16:28:01     INFO - PID 14470 | --DOMWINDOW == 15 (0xd993b400) [pid = 14516] [serial = 12] [outer = (nil)] [url = about:blank]
[task 2017-10-14T16:28:01.275Z] 16:28:01     INFO - PID 14470 | --DOMWINDOW == 14 (0xd1d35400) [pid = 14516] [serial = 13] [outer = (nil)] [url = about:blank]
[task 2017-10-14T16:28:01.275Z] 16:28:01     INFO - PID 14470 | --DOMWINDOW == 13 (0xd820f800) [pid = 14516] [serial = 6] [outer = (nil)] [url = about:blank]
[task 2017-10-14T16:28:01.276Z] 16:28:01     INFO - PID 14470 | --DOMWINDOW == 12 (0xd9702400) [pid = 14516] [serial = 7] [outer = (nil)] [url = about:blank]
[task 2017-10-14T16:28:01.276Z] 16:28:01     INFO - PID 14470 | --DOMWINDOW == 11 (0xd96e9400) [pid = 14516] [serial = 2] [outer = (nil)] [url = about:blank]
[task 2017-10-14T16:28:01.276Z] 16:28:01     INFO - PID 14470 | --DOMWINDOW == 10 (0xd8c23c00) [pid = 14516] [serial = 3] [outer = (nil)] [url = about:blank]
[task 2017-10-14T16:28:01.737Z] 16:28:01     INFO - 
[task 2017-10-14T16:28:01.738Z] 16:28:01     INFO - TEST-UNEXPECTED-FAIL | /webrtc/RTCDTMFSender-ontonechange-long.html | insertDTMF with duration greater than 6000 should be clamped to 6000 - assert_approx_equals: Expect tonechange event for "" to be fired approximately after 6070 seconds expected 6070 +/- 50 but got 6125
[task 2017-10-14T16:28:01.738Z] 16:28:01     INFO - test_tone_change_events/</</onToneChange<@http://web-platform.test:8000/webrtc/RTCDTMFSender-helper.js:79:9
[task 2017-10-14T16:28:01.738Z] 16:28:01     INFO - Test.prototype.step@http://web-platform.test:8000/resources/testharness.js:1485:20
[task 2017-10-14T16:28:01.739Z] 16:28:01     INFO - Test.prototype.step_func/<@http://web-platform.test:8000/resources/testharness.js:1509:20
[task 2017-10-14T16:28:01.740Z] 16:28:01     INFO - TEST-OK | /webrtc/RTCDTMFSender-ontonechange-long.html | took 8228ms


:drno, can you take a quick look at this and see if there is something to do here?
Flags: needinfo?(drno)
Whiteboard: [stockwell unknown] → [stockwell needswork]
My guess is that it's just poor VM performance. Indicator is that it happens mostly on debug builds. I have doubts how feasible it is to expect from our really slow test machines to deliver something with +/-50ms.
The only strange thing to me is: why isn't this happening on Windows at all?

Dan, Michael: as you guys implemented the DTMF support, what do you think?
Flags: needinfo?(mfroman)
Flags: needinfo?(drno)
Flags: needinfo?(dminor)
It looks like this was added upstream and imported into web-platform tests so it's not surprising that their timing expectations are different than ours. In the example above it looks like we missed by just 5ms.

I'm not sure if we're free to just loosen the timing and try to get it merged back upstream or if there is some sort of review process or what. The other alternative would be to just disable the test. We have coverage for this in the DTMF mochitest.
Flags: needinfo?(dminor)
(In reply to Dan Minor [:dminor] from comment #10)
> I'm not sure if we're free to just loosen the timing and try to get it
> merged back upstream or if there is some sort of review process or what. The
> other alternative would be to just disable the test. We have coverage for
> this in the DTMF mochitest.
I agree with Dan's assessment, and I think I'd lean toward disabling it given the mochitest coverage.
Flags: needinfo?(mfroman)
If you both think the timeout value is too low I would prefer if we would complain upstream and ask them to increase the value. And we could land a patch for a bigger timeout here to speed up the resolution.
See Also: → 1411822
https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
Status: NEW → RESOLVED
Closed: 6 years ago
Resolution: --- → INCOMPLETE
You need to log in before you can comment on or make changes to this bug.