1573391 - Intermittent Tier 2 TEST-UNEXPECTED-TIMEOUT | dom/media/tests/mochitest/test_dataChannel_basicAudio.html | application timed out after 370 seconds with no output

Status: RESOLVED INCOMPLETE

(Core :: WebRTC, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: btara [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=261276540&repo=mozilla-central
Full log: https://queue.taskcluster.net/v1/task/AoCcx5CyRROr2rkP2A6WZQ/runs/0/artifacts/public/logs/live_backing.log

---

06:40:12 INFO - TEST-START | dom/media/tests/mochitest/test_dataChannel_basicAudio.html
06:40:12 INFO - GECKO(9828) | TEST DEVICES: No test device found in media.audio_loopback_dev, using fake audio streams.
06:40:12 INFO - GECKO(9828) | TEST DEVICES: No test device found in media.video_loopback_dev, using fake video streams.
06:40:13 INFO - GECKO(9828) | [Child 7536: Main Thread]: I/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:330: PeerConnectionImpl: PeerConnectionImpl constructor for
06:40:13 INFO - GECKO(9828) | [Parent 2628: Socket Thread]: D/mtransport NrIceCtx static call to find local stun addresses
06:40:13 INFO - GECKO(9828) | [Child 7536: Main Thread]: I/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:330: PeerConnectionImpl: PeerConnectionImpl constructor for
06:40:13 INFO - GECKO(9828) | [Parent 2628: Socket Thread]: D/mtransport NrIceCtx static call to find local stun addresses
06:40:13 INFO - GECKO(9828) | TEST DEVICES: No test device found in media.audio_loopback_dev, using fake audio streams.
06:40:13 INFO - GECKO(9828) | TEST DEVICES: No test device found in media.video_loopback_dev, using fake video streams.
06:40:13 INFO - GECKO(9828) | (unknown/INFO) insert '' (registry) succeeded:
06:40:13 INFO - GECKO(9828) | (registry/INFO) Initialized registry
06:40:13 INFO - GECKO(9828) | (registry/INFO) insert 'ice' (registry) succeeded: ice
06:40:13 INFO - GECKO(9828) | (registry/INFO) insert 'ice.pref' (registry) succeeded: ice.pref
06:40:13 INFO - GECKO(9828) | (registry/INFO) insert 'ice.pref.type' (registry) succeeded: ice.pref.type
06:40:13 INFO - GECKO(9828) | (registry/INFO) insert 'ice.pref.type.srv_rflx' (UCHAR) succeeded: 0x64
06:40:13 INFO - GECKO(9828) | (registry/INFO) insert 'ice.pref.type.peer_rflx' (UCHAR) succeeded: 0x6e
06:40:13 INFO - GECKO(9828) | (registry/INFO) insert 'ice.pref.type.host' (UCHAR) succeeded: 0x7e
06:40:13 INFO - GECKO(9828) | (registry/INFO) insert 'ice.pref.type.relayed' (UCHAR) succeeded: 0x05
06:40:13 INFO - GECKO(9828) | (registry/INFO) insert 'ice.pref.type.srv_rflx_tcp' (UCHAR) succeeded: 0x63
06:40:13 INFO - GECKO(9828) | (registry/INFO) insert 'ice.pref.type.peer_rflx_tcp' (UCHAR) succeeded: 0x6d
06:40:13 INFO - GECKO(9828) | (registry/INFO) insert 'ice.pref.type.host_tcp' (UCHAR) succeeded: 0x7d
06:40:13 INFO - GECKO(9828) | (registry/INFO) insert 'ice.pref.type.relayed_tcp' (UCHAR) succeeded: 0x00
06:40:13 INFO - GECKO(9828) | (registry/INFO) insert 'stun' (registry) succeeded: stun
06:40:13 INFO - GECKO(9828) | (registry/INFO) insert 'stun.client' (registry) succeeded: stun.client
06:40:13 INFO - GECKO(9828) | (registry/INFO) insert 'stun.client.maximum_transmits' (UINT4) succeeded: 14
06:40:13 INFO - GECKO(9828) | (registry/INFO) insert 'ice.trickle_grace_period' (UINT4) succeeded: 30000
06:40:13 INFO - GECKO(9828) | (registry/INFO) insert 'ice.tcp' (registry) succeeded: ice.tcp
06:40:13 INFO - GECKO(9828) | (registry/INFO) insert 'ice.tcp.so_sock_count' (INT4) succeeded: 0
06:40:13 INFO - GECKO(9828) | (registry/INFO) insert 'ice.tcp.listen_backlog' (INT4) succeeded: 10
06:40:13 INFO - GECKO(9828) | (registry/INFO) insert 'ice.tcp.disable' (char) succeeded: \000
06:40:13 INFO - GECKO(9828) | [Child 7536: Main Thread]: I/signaling [main|PeerConnectionMedia] PeerConnectionMedia.cpp:729: SetProxy: Had proxyinfo
06:40:13 INFO - GECKO(9828) | [Child 7536: Main Thread]: I/signaling [main|PeerConnectionMedia] PeerConnectionMedia.cpp:729: SetProxy: Had proxyinfo
06:40:13 INFO - GECKO(9828) | [Child 7536: Main Thread]: I/signaling [main|PeerConnectionMedia] PeerConnectionMedia.cpp:50: OnStunAddrsAvailable: receiving (4) stun addrs
06:40:13 INFO - GECKO(9828) | [Child 7536: Main Thread]: I/signaling [main|PeerConnectionMedia] PeerConnectionMedia.cpp:50: OnStunAddrsAvailable: receiving (4) stun addrs
06:46:23 INFO - Buffered messages logged at 06:40:12
06:46:23 INFO - TEST-PASS | dom/media/tests/mochitest/test_dataChannel_basicAudio.html | A valid string reason is expected
06:46:23 INFO - TEST-PASS | dom/media/tests/mochitest/test_dataChannel_basicAudio.html | Reason cannot be empty
06:46:23 INFO - TEST-PASS | dom/media/tests/mochitest/test_dataChannel_basicAudio.html | A valid string reason is expected
06:46:23 INFO - TEST-PASS | dom/media/tests/mochitest/test_dataChannel_basicAudio.html | Reason cannot be empty
06:46:23 INFO - Buffered messages logged at 06:40:13
06:46:23 INFO - Skipping ICE Server for this test
06:46:23 INFO - Creating PeerConnectionWrapper (pcLocal)
06:46:23 INFO - Creating PeerConnectionWrapper (pcRemote)
06:46:23 INFO - Run step 1: PC_SETUP_SIGNALING_CLIENT
06:46:23 INFO - Run step 2: PC_LOCAL_SETUP_ICE_LOGGER
06:46:23 INFO - Run step 3: PC_REMOTE_SETUP_ICE_LOGGER
06:46:23 INFO - Run step 4: PC_LOCAL_SETUP_SIGNALING_LOGGER
06:46:23 INFO - Run step 5: PC_REMOTE_SETUP_SIGNALING_LOGGER
06:46:23 INFO - Run step 6: PC_LOCAL_SETUP_TRACK_HANDLER
06:46:23 INFO - Run step 7: PC_REMOTE_SETUP_TRACK_HANDLER
06:46:23 INFO - Run step 8: PC_LOCAL_CHECK_INITIAL_SIGNALINGSTATE
06:46:23 INFO - TEST-PASS | dom/media/tests/mochitest/test_dataChannel_basicAudio.html | Initial local signalingState is 'stable'
06:46:23 INFO - Run step 9: PC_REMOTE_CHECK_INITIAL_SIGNALINGSTATE
06:46:23 INFO - TEST-PASS | dom/media/tests/mochitest/test_dataChannel_basicAudio.html | Initial remote signalingState is 'stable'
06:46:23 INFO - Run step 10: PC_LOCAL_CHECK_INITIAL_ICE_STATE
06:46:23 INFO - TEST-PASS | dom/media/tests/mochitest/test_dataChannel_basicAudio.html | Initial local ICE connection state is 'new'
06:46:23 INFO - Run step 11: PC_REMOTE_CHECK_INITIAL_ICE_STATE
06:46:23 INFO - TEST-PASS | dom/media/tests/mochitest/test_dataChannel_basicAudio.html | Initial remote ICE connection state is 'new'
06:46:23 INFO - Run step 12: PC_LOCAL_CHECK_INITIAL_CAN_TRICKLE_SYNC
06:46:23 INFO - TEST-PASS | dom/media/tests/mochitest/test_dataChannel_basicAudio.html | Local trickle status should start out unknown
06:46:23 INFO - Run step 13: PC_REMOTE_CHECK_INITIAL_CAN_TRICKLE_SYNC
06:46:23 INFO - TEST-PASS | dom/media/tests/mochitest/test_dataChannel_basicAudio.html | Remote trickle status should start out unknown
06:46:23 INFO - Run step 14: PC_LOCAL_GUM
06:46:23 INFO - Get 1 local streams
06:46:23 INFO - Call getUserMedia for {"audio":true}
06:46:23 INFO - TEST-PASS | dom/media/tests/mochitest/test_dataChannel_basicAudio.html | One audio track shall be present
06:46:23 INFO - TEST-PASS | dom/media/tests/mochitest/test_dataChannel_basicAudio.html | Track kind should be audio
06:46:23 INFO - TEST-PASS | dom/media/tests/mochitest/test_dataChannel_basicAudio.html | Track id should be defined
06:46:23 INFO - TEST-PASS | dom/media/tests/mochitest/test_dataChannel_basicAudio.html | Track should not be muted
06:46:23 INFO - TEST-PASS | dom/media/tests/mochitest/test_dataChannel_basicAudio.html | No video tracks shall be present
06:46:23 INFO - PeerConnectionWrapper (pcLocal) gUM local stream {346a5882-5854-4e3e-ba61-ee06862b94fc} with audio track {17822b73-7d84-4d2f-afc9-30a2c1162983}
06:46:23 INFO - Got local media stream: ({346a5882-5854-4e3e-ba61-ee06862b94fc})
06:46:23 INFO - Using addTrack (on PC).
06:46:23 INFO - TEST-PASS | dom/media/tests/mochitest/test_dataChannel_basicAudio.html | addTrack returns sender
06:46:23 INFO - TEST-PASS | dom/media/tests/mochitest/test_dataChannel_basicAudio.html | track has id
06:46:23 INFO - TEST-PASS | dom/media/tests/mochitest/test_dataChannel_basicAudio.html | track has kind
06:46:23 INFO - TEST-PASS | dom/media/tests/mochitest/test_dataChannel_basicAudio.html | track has a sender
06:46:23 INFO - Buffered messages finished
06:46:23 ERROR - TEST-UNEXPECTED-TIMEOUT | dom/media/tests/mochitest/test_dataChannel_basicAudio.html | application timed out after 370 seconds with no output
06:46:23 ERROR - Force-terminating active process(es).
06:46:23 INFO - Determining child pids from psutil...
06:46:23 INFO - [2628]
06:46:23 INFO - ==> process 2628 launched child process 1004 ("C:\tasks\task_1565672163\build\application\firefox\firefox.exe" -contentproc --channel="2628.0.917926925\1572491334" -parentBuildID 20190813034722 -prefsHandle 1676 -prefMapHandle 1668 -prefsLen 1 -prefMapSize 220418 -greomni "C:\tasks\task_1565672163\build\application\firefox\omni.ja" -appomni "C:\tasks\task_1565672163\build\application\firefox\browser\omni.ja" -appdir "C:\tasks\task_1565672163\build\application\firefox\browser" - 2628 "\.\pipe\gecko-crash-server-pipe.2628" 1764 gpu)
06:46:23 INFO - ==> process 2628 launched child process 7536 ("C:\tasks\task_1565672163\build\application\firefox\firefox.exe" -contentproc --channel="2628.3.354335220\1328305951" -childID 1 -isForBrowser -prefsHandle 2408 -prefMapHandle 2412 -prefsLen 107 -prefMapSize 220418 -parentBuildID 20190813034722 -greomni "C:\tasks\task_1565672163\build\application\firefox\omni.ja" -appomni "C:\tasks\task_1565672163\build\application\firefox\browser\omni.ja" -appdir "C:\tasks\task_1565672163\build\application\firefox\browser" - 2628 "\.\pipe\gecko-crash-server-pipe.2628" 2424 tab)
06:46:23 INFO - ==> process 2628 launched child process 2996 ("C:\tasks\task_1565672163\build\application\firefox\firefox.exe" -contentproc --channel="2628.13.2131808596\1803328049" -childID 2 -isForBrowser -prefsHandle 3668 -prefMapHandle 3680 -prefsLen 6946 -prefMapSize 220418 -parentBuildID 20190813034722 -greomni "C:\tasks\task_1565672163\build\application\firefox\omni.ja" -appomni "C:\tasks\task_1565672163\build\application\firefox\browser\omni.ja" -appdir "C:\tasks\task_1565672163\build\application\firefox\browser" - 2628 "\.\pipe\gecko-crash-server-pipe.2628" 3692 tab)
06:46:23 INFO - ==> process 2628 launched child process 3636 ("C:\tasks\task_1565672163\build\application\firefox\firefox.exe" -contentproc --channel="2628.20.845334816\1460738422" -childID 3 -isForBrowser -prefsHandle 4288 -prefMapHandle 4284 -prefsLen 7678 -prefMapSize 220418 -parentBuildID 20190813034722 -greomni "C:\tasks\task_1565672163\build\application\firefox\omni.ja" -appomni "C:\tasks\task_1565672163\build\application\firefox\browser\omni.ja" -appdir "C:\tasks\task_1565672163\build\application\firefox\browser" - 2628 "\.\pipe\gecko-crash-server-pipe.2628" 3592 tab)
06:46:23 INFO - ==> process 2628 launched child process 1108 ("C:\tasks\task_1565672163\build\application\firefox\firefox.exe" -contentproc --channel="2628.27.1373264696\1575865705" -childID 4 -isForBrowser -prefsHandle 4484 -prefMapHandle 4488 -prefsLen 7678 -prefMapSize 220418 -parentBuildID 20190813034722 -greomni "C:\tasks\task_1565672163\build\application\firefox\omni.ja" -appomni "C:\tasks\task_1565672163\build\application\firefox\browser\omni.ja" -appdir "C:\tasks\task_1565672163\build\application\firefox\browser" - 2628 "\.\pipe\gecko-crash-server-pipe.2628" 4436 tab)
06:46:23 INFO - Found child pids: set([2628, 1004, 3636, 7536, 1108, 2996])
06:46:23 INFO - Killing process: 2628
06:46:23 INFO - TEST-INFO | started process screenshot
06:46:23 INFO - TEST-INFO | screenshot: exit 0
06:46:23 INFO - mozcrash Using C:\tasks\task_1565672163\build\tests\bin\minidumpwriter.exe to write a dump to c:\users\testdr1\appdata\local\temp\tmpo3ivlv.mozrunner\minidumps\06a39e76-7bb5-481d-bb9b-8eec9ca855ba.dmp for [2628]
06:46:24 INFO - Killing process: 1004
06:46:24 INFO - Not taking screenshot here: see the one that was previously logged
06:46:24 INFO - mozcrash Using C:\tasks\task_1565672163\build\tests\bin\minidumpwriter.exe to write a dump to c:\users\testdr1\appdata\local\temp\tmpo3ivlv.mozrunner\minidumps\d0a685cf-4544-4d03-a5f8-7b8669a23763.dmp for [1004]
06:46:24 INFO - Error 0x8007012B in MiniDumpWriteDump
06:46:24 ERROR - mozcrash minidumpwriter exited with status: 1
06:46:24 WARNING - mozcrash kill_pid(): unable to terminate pid 1004: 5
06:46:24 INFO - Killing process: 3636

Comment 1

[Intermittent Failures Robot]

1 failures in 4839 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 1

Platform breakdown:

• windows10-aarch64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1573391&startday=2019-08-12&endday=2019-08-18&tree=all

Comment 2

[Firefox Bug Husbandry Bot]

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup

Comment 3

[Intermittent Failures Robot]

1 failures in 4637 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 1

Platform breakdown:

• windows10-aarch64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1573391&startday=2019-09-09&endday=2019-09-15&tree=all