Closed Bug 845538 Opened 12 years ago Closed 12 years ago

Intermittent test_peerConnection_basicAudioVideoCombined.html | Test timed out | Exited with code 1 during test run | application crashed [@ gsmsdp_negotiate_media_lines]

Categories

(Core :: WebRTC: Networking, defect, P2)

Product:
Core
Component:
WebRTC: Networking
Platform:
x86_64
macOS
Type:
defect

Tracking

()

Status:
RESOLVED DUPLICATE of bug 853858

People

(Reporter: RyanVM, Assigned: abr)

Details

(Keywords: crash, intermittent-failure, Whiteboard: [WebRTC], [blocking-webrtc-])

Crash Data

https://tbpl.mozilla.org/php/getParsedLog.php?id=20114034&tree=Firefox Rev4 MacOSX Snow Leopard 10.6 mozilla-central debug test mochitest-3 on 2013-02-26 12:14:04 PST for push 55d8934477f6 slave: talos-r4-snow-079 12:22:24 INFO - 341 INFO TEST-INFO | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudioVideoCombined.html | Calling addStream on local peer connection 12:22:24 INFO - 7884800[108807de0]: cpr SIPCC-CC_API: 1/5, cc_int_feature2: UI -> GSM: ADDSTREAM 12:22:24 INFO - 7884800[108807de0]: cpr SIPCC-CC_API: 1/5, cc_int_feature2: UI -> GSM: ADDSTREAM 12:22:24 INFO - 8105984[1001d9160]: cpr SIPCC-DCSM: dcsm_process_event: DCSM 23 :(DCSM_READY:ADDSTREAM ) 12:22:24 INFO - 342 INFO TEST-INFO | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudioVideoCombined.html | Calling addStream on remote peer connection 12:22:24 INFO - 8105984[1001d9160]: cpr SIPCC-GSM: 1/5, sm_process_event: DEF :(IDLE:ADDSTREAM ) 12:22:25 INFO - 8105984[1001d9160]: cpr SIPCC-DCSM: dcsm_process_event: DCSM 23 :(DCSM_READY:ADDSTREAM ) 12:22:25 INFO - 8105984[1001d9160]: cpr SIPCC-GSM: 1/5, sm_process_event: DEF :(IDLE:ADDSTREAM ) 12:22:30 INFO - 7884800[108807de0]: cpr SIPCC-CC_API: 2/6, cc_int_feature2: UI -> GSM: ADDSTREAM 12:22:35 INFO - 7884800[108807de0]: cpr SIPCC-CC_API: 2/6, cc_int_feature2: UI -> GSM: ADDSTREAM 12:22:35 INFO - 8105984[1001d9160]: cpr SIPCC-DCSM: dcsm_process_event: DCSM 23 :(DCSM_READY:ADDSTREAM ) 12:22:35 INFO - 8105984[1001d9160]: cpr SIPCC-GSM: 2/6, sm_process_event: DEF :(IDLE:ADDSTREAM ) 12:22:35 INFO - 8105984[1001d9160]: cpr SIPCC-DCSM: dcsm_process_event: DCSM 23 :(DCSM_READY:ADDSTREAM ) 12:22:35 INFO - 8105984[1001d9160]: cpr SIPCC-GSM: 2/6, sm_process_event: DEF :(IDLE:ADDSTREAM ) 12:22:36 INFO - 343 INFO TEST-INFO | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudioVideoCombined.html | Calling createOffer on local peer connection 12:22:38 INFO - 7884800[108807de0]: cpr SIPCC-CC_API: 1/5, send_message_helper: UI -> GSM: CREATEOFFER 12:22:38 INFO - 8105984[1001d9160]: cpr SIPCC-DCSM: dcsm_process_event: DCSM 18 :(DCSM_READY:CREATEOFFER ) 12:25:19 INFO - 344 ERROR TEST-UNEXPECTED-FAIL | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudioVideoCombined.html | Test timed out. 12:25:24 INFO - args: ['/usr/sbin/screencapture', '-C', '-x', '-t', 'png', '/var/folders/Hs/HsDn6a9SG8idoIya6p9mtE+++TI/-Tmp-/mozilla-test-fail_eZc3fC'] 12:26:04 INFO - SCREENSHOT: <see log> 12:26:17 INFO - WARNING: 1 sort operation has occurred for the SQL statement '0x12b9cd1c0'. See https://developer.mozilla.org/En/Storage/Warnings details.: file ../../../storage/src/mozStoragePrivateHelpers.cpp, line 110 12:26:20 INFO - 345 ERROR TEST-UNEXPECTED-FAIL | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudioVideoCombined.html | Test timed out. 12:26:20 INFO - Not taking screenshot here: see the one that was previously logged 12:26:20 INFO - WARNING: 1 sort operation has occurred for the SQL statement '0x1088f8140'. See https://developer.mozilla.org/En/Storage/Warnings details.: file ../../../storage/src/mozStoragePrivateHelpers.cpp, line 110 12:26:20 INFO - WARNING: 1 sort operation has occurred for the SQL statement '0x144de7990'. See https://developer.mozilla.org/En/Storage/Warnings details.: file ../../../storage/src/mozStoragePrivateHelpers.cpp, line 110 12:26:20 INFO - 346 ERROR TEST-UNEXPECTED-FAIL | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudioVideoCombined.html | [SimpleTest.finish()] this test already called finish! 12:26:20 INFO - 347 ERROR TEST-UNEXPECTED-FAIL | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudioVideoCombined.html | called finish() multiple times 12:26:20 INFO - WARNING: 1 sort operation has occurred for the SQL statement '0x12b9cd1c0'. See https://developer.mozilla.org/En/Storage/Warnings details.: file ../../../storage/src/mozStoragePrivateHelpers.cpp, line 110 12:26:36 INFO - --DOMWINDOW == 19 (0x1001edc78) [serial = 46] [outer = 0x12b1afe98] [url = http://mochi.test:8888/tests/SimpleTest/iframe-between-tests.html] 12:26:36 INFO - --DOMWINDOW == 18 (0x1081146e8) [serial = 44] [outer = 0x12b1afe98] [url = http://mochi.test:8888/tests/SimpleTest/iframe-between-tests.html] 12:26:36 INFO - --DOMWINDOW == 17 (0x12860c188) [serial = 42] [outer = 0x12b1afe98] [url = http://mochi.test:8888/tests/SimpleTest/iframe-between-tests.html] 12:26:36 INFO - --DOMWINDOW == 16 (0x1088ad5d8) [serial = 40] [outer = 0x12b1afe98] [url = http://mochi.test:8888/tests/SimpleTest/iframe-between-tests.html] 12:26:38 INFO - --DOMWINDOW == 15 (0x12a4c9978) [serial = 39] [outer = 0x12b1afe98] [url = http://mochi.test:8888/tests/dom/media/tests/mochitest/test_getUserMedia_stopVideoStream.html] 12:26:38 INFO - --DOMWINDOW == 14 (0x1286caee8) [serial = 41] [outer = 0x12b1afe98] [url = http://mochi.test:8888/tests/dom/media/tests/mochitest/test_getUserMedia_stopVideoStreamWithFollowupVideo.html] 12:26:39 INFO - 7884800[108807de0]: cpr SIPCC-CC_API: 1/1, cc_int_onhook: UI -> GSM: ONHOOK 12:26:40 INFO - 7884800[108807de0]: cpr SIPCC-CC_API: 2/2, cc_int_onhook: UI -> GSM: ONHOOK 12:26:40 INFO - 7884800[108807de0]: cpr SIPCC-CC_API: 1/3, cc_int_onhook: UI -> GSM: ONHOOK 12:26:40 INFO - 7884800[108807de0]: cpr SIPCC-CC_API: 2/4, cc_int_onhook: UI -> GSM: ONHOOK 12:26:44 INFO - 348 ERROR TEST-UNEXPECTED-FAIL | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudioVideoCombined.html | Test timed out. 12:26:44 INFO - Not taking screenshot here: see the one that was previously logged 12:26:44 INFO - WARNING: 1 sort operation has occurred for the SQL statement '0x12b908230'. See https://developer.mozilla.org/En/Storage/Warnings details.: file ../../../storage/src/mozStoragePrivateHelpers.cpp, line 110 12:26:44 INFO - 8105984[1001d9160]: cpr SIPCC-GSM: 1/5, sm_process_event: DEF :(IDLE:CREATEOFFER ) 12:26:44 INFO - 8105984[1001d9160]: cpr SIPCC-DCSM: dcsm_process_event: DCSM 11 :(DCSM_READY:ONHOOK ) 12:26:44 INFO - 8105984[1001d9160]: cpr SIPCC-DCSM: dcsm_process_event: DCSM 11 :(DCSM_READY:ONHOOK ) 12:26:44 INFO - 8105984[1001d9160]: cpr SIPCC-DCSM: dcsm_process_event: DCSM 11 :(DCSM_READY:ONHOOK ) 12:26:44 INFO - 8105984[1001d9160]: cpr SIPCC-DCSM: dcsm_process_event: DCSM 11 :(DCSM_READY:ONHOOK ) 12:26:44 INFO - 7884800[108807de0]: CC_SIPCCCallInfo State 22 not handled in generateCapabilities() 12:26:44 INFO - 7884800[108807de0]: CC_SIPCCService onCallEvent(CCAPI_CALL_EV_CREATED, 10005, [UNKNOWN|] 12:26:45 INFO - 349 ERROR TEST-UNEXPECTED-FAIL | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudioVideoCombined.html | [SimpleTest.finish()] this test already called finish! 12:26:45 INFO - 350 ERROR TEST-UNEXPECTED-FAIL | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudioVideoCombined.html | called finish() multiple times 12:26:45 INFO - 7884800[108807de0]: cpr SIPCC-SIP_CC_PROV: CCAPI_Call_releaseCallInfo: ref=0xd6469e0: count=2 12:26:46 INFO - 351 INFO TEST-END | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudioVideoCombined.html | finished in 673699ms 12:26:52 INFO - WARNING: 1 sort operation has occurred for the SQL statement '0x10d514f10'. See https://developer.mozilla.org/En/Storage/Warnings details.: file ../../../storage/src/mozStoragePrivateHelpers.cpp, line 110 12:26:52 INFO - 352 INFO TEST-INFO | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudioVideoCombined.html | Calling setLocalDescription on local peer connection 12:26:52 INFO - 7884800[108807de0]: cpr SIPCC-CC_API: 1/5, send_message_helper: UI -> GSM: SETLOCALDESC 12:26:52 INFO - 8105984[1001d9160]: cpr SIPCC-DCSM: dcsm_process_event: DCSM 20 :(DCSM_READY:SETLOCALDESC ) 12:26:52 INFO - 8105984[1001d9160]: cpr SIPCC-FSM: 1/5, fsm_change_state: DEF: IDLE -> CALL_SENT 12:26:52 INFO - 8105984[1001d9160]: cpr SIPCC-DCSM: dcsm_update_gsm_state: 5 : DCSM_READY --> DCSM_READY 12:26:52 INFO - 8105984[1001d9160]: cpr SIPCC-GSM: 1/5, sm_process_event: DEF :(IDLE:SETLOCALDESC ) 12:26:52 INFO - 7884800[108807de0]: CC_SIPCCCallInfo State 26 not handled in generateCapabilities() 12:26:52 INFO - 7884800[108807de0]: CC_SIPCCService onCallEvent(CCAPI_CALL_EV_STATE, 10005, [UNKNOWN|] 12:26:56 INFO - 7884800[108807de0]: cpr SIPCC-SIP_CC_PROV: CCAPI_Call_releaseCallInfo: ref=0xca0cff0: count=2 12:26:57 INFO - 353 INFO TEST-INFO | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudioVideoCombined.html | Calling setRemoteDescription on remote peer connection 12:26:57 INFO - 7884800[108807de0]: cpr SIPCC-CC_API: 2/6, send_message_helper: UI -> GSM: SETREMOTEDESC 12:26:57 INFO - 8105984[1001d9160]: cpr SIPCC-DCSM: dcsm_process_event: DCSM 21 :(DCSM_READY:SETREMOTEDESC ) 12:27:04 INFO - ++DOMWINDOW == 15 (0x1001af798) [serial = 48] [outer = 0x12b1afe98] 12:27:07 INFO - WARNING: 1 sort operation has occurred for the SQL statement '0x12a429140'. See https://developer.mozilla.org/En/Storage/Warnings details.: file ../../../storage/src/mozStoragePrivateHelpers.cpp, line 110 12:27:07 INFO - 7884800[108807de0]: cpr SIPCC-CC_API: 1/5, cc_int_onhook: UI -> GSM: ONHOOK 12:27:07 INFO - 7884800[108807de0]: cpr SIPCC-CC_API: 2/6, cc_int_onhook: UI -> GSM: ONHOOK 12:27:08 INFO - 8105984[1001d9160]: cpr GSM : 2/6 : gsmsdp_add_media_line : allocate rx port failed 12:27:08 INFO - 8105984[1001d9160]: sdp_attr_access Attribute label, level 1 instance 1 not found. 12:27:08 INFO - 8105984[1001d9160]: sdp_attr_access Attribute maxptime, level 1 instance 1 not found. 12:27:08 INFO - 8105984[1001d9160]: sdp_attr_access rtcp-mux attribute, level 1 instance 1 not found. 12:27:09 INFO - 354 INFO TEST-START | /tests/dom/media/tests/mochitest/test_peerConnection_basicVideo.html 12:27:09 INFO - Assertion failure: pc_stream_id == 0, at ../../../../../media/webrtc/signaling/src/sipcc/core/gsm/gsm_sdp.c:4621 12:27:19 WARNING - TEST-UNEXPECTED-FAIL | /tests/dom/media/tests/mochitest/test_peerConnection_basicVideo.html | Exited with code 1 during test run 12:27:19 WARNING - This is a harness error. 12:27:20 INFO - INFO | automation.py | Application ran for: 0:12:15.496258 12:27:20 INFO - INFO | automation.py | Reading PID log: /var/folders/Hs/HsDn6a9SG8idoIya6p9mtE+++TI/-Tmp-/tmpOjwvn3pidlog 12:28:03 INFO - PROCESS-CRASH | /tests/dom/media/tests/mochitest/test_peerConnection_basicVideo.html | application crashed [@ gsmsdp_negotiate_media_lines] 12:28:03 INFO - Crash dump filename: /var/folders/Hs/HsDn6a9SG8idoIya6p9mtE+++TI/-Tmp-/tmpQ9FAxr/minidumps/99D545B0-7158-4F30-8FE5-ED17E34C0976.dmp 12:28:03 INFO - Operating system: Mac OS X 12:28:03 INFO - 10.6.8 10K549 12:28:03 INFO - CPU: amd64 12:28:03 INFO - family 6 model 23 stepping 10 12:28:03 INFO - 2 CPUs 12:28:03 INFO - Crash reason: EXC_BAD_ACCESS / KERN_INVALID_ADDRESS 12:28:03 INFO - Crash address: 0x0 12:28:03 INFO - Thread 27 (crashed) 12:28:03 INFO - 0 XUL!gsmsdp_negotiate_media_lines [gsm_sdp.c:55d8934477f6 : 4621 + 0x0] 12:28:03 INFO - rbx = 0x00007fff7107d2f8 r12 = 0x000000010c067648 12:28:03 INFO - r13 = 0x0000000000000001 r14 = 0x000000010d525970 12:28:03 INFO - r15 = 0x00000001056b3eb8 rip = 0x000000010395a5fb 12:28:03 INFO - rsp = 0x00000001007ba060 rbp = 0x00000001007ba4a0 12:28:03 INFO - Found by: given as instruction pointer in context 12:28:03 INFO - 1 XUL!vcmRxReleasePort [VcmSIPCCBinding.cpp:55d8934477f6 : 1537 + 0x35] 12:28:03 INFO - rip = 0x00000001038f4668 rsp = 0x00000001007ba090 12:28:03 INFO - rbp = 0x00000001007ba4a0 12:28:03 INFO - Found by: stack scanning 12:28:03 INFO - 2 XUL!gsmsdp_remove_media [gsm_sdp.c:55d8934477f6 : 637 + 0x7] 12:28:03 INFO - rip = 0x000000010395ab7f rsp = 0x00000001007ba0d0 12:28:03 INFO - rbp = 0x00000001007ba4a0 12:28:03 INFO - Found by: stack scanning 12:28:03 INFO - 3 XUL!sdp_find_attr [sdp_attr_access.c:55d8934477f6 : 1770 + 0x7] 12:28:03 INFO - rip = 0x0000000103975df2 rsp = 0x00000001007ba1b0 12:28:03 INFO - rbp = 0x00000001007ba4a0 12:28:03 INFO - Found by: stack scanning 12:28:03 INFO - 4 XUL!sdp_attr_set_ice_attribute [sdp_attr_access.c:55d8934477f6 : 4001 + 0x13] 12:28:03 INFO - rip = 0x0000000103976f5a rsp = 0x00000001007ba1e0 12:28:03 INFO - rbp = 0x00000001007ba4a0 12:28:03 INFO - Found by: stack scanning 12:28:03 INFO - 5 XUL!gsmsdp_get_new_media [gsm_sdp.c:55d8934477f6 : 586 + 0xa] 12:28:03 INFO - rip = 0x000000010395ea61 rsp = 0x00000001007ba1f0 12:28:03 INFO - rbp = 0x00000001007ba4a0 12:28:03 INFO - Found by: stack scanning 12:28:03 INFO - 6 libSystem.B.dylib + 0xa7ba 12:28:03 INFO - rip = 0x00007fff88cc67bb rsp = 0x00000001007ba290 12:28:03 INFO - rbp = 0x00000001007ba4a0 12:28:03 INFO - Found by: stack scanning
Note that the crash (assert) should go away when Bug 837523 lands on m-c.
Adam - please double-check the full log. This looks to have gone wrong earlier in the test, and this may simply be fallout. 12:22:24 INFO - 338 INFO TEST-END | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudioVideo.html | finished in 2461ms 12:22:24 INFO - 7884800[108807de0]: cpr SIPCC-SIP_CC_PROV: CCAPI_Call_releaseCallInfo: ref=0xd51d0c0: count=2 12:22:24 INFO - 7884800[108807de0]: CC_SIPCCService onLineEvent(CCAPI_LINE_EV_CAPSET_CHANGED, 1, [564213752|OOS] 12:22:24 INFO - ++DOMWINDOW == 19 (0x1001edc78) [serial = 46] [outer = 0x12b1afe98] 12:22:24 INFO - 1896398016[100116a90]: WebrtcVideoSessionConduit SendRTCPPacket : channel 0 , len 16 12:22:24 INFO - 1896398016[100116a90]: WebrtcVideoSessionConduit SendRTCPPacket Failed
Some IRC musings on the problem: [4:08pm] abr: What's really bizarre is the lack of sipCC logging between TEST-START and the assert. [4:10pm] abr: There's no legal way to get to that line without logging an incoming event. [4:10pm] ekr: Log levels? [4:11pm] abr: No, because those log messages are there from previous tests. [4:11pm] abr: Oh, this whole log has bad mojo written all over it. [4:11pm] ekr: I hate mojo [4:11pm] abr: Things start going off the rails here: 12:26:20 INFO - 345 ERROR TEST-UNEXPECTED-FAIL | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudioVideoCombined.html | Test timed out. [4:11pm] ekr: OK [4:12pm] abr: I think my pending patch will prevent the assert from happening, but what's gone wrong went wrong well before the assert. [4:14pm] ekr: huh [4:16pm] ekr: Yeaj, it's weird [4:17pm] abr: It's almost like the CCApp thread got stuck somewhere, and didn't break loose until some time after the next test started running. [4:17pm] ekr: it is weird [4:21pm] abr: In fact, there's a bunch of crap that looks like call setup processing that happens between TEST-END and TEST-START. The CCApp thread is definitely off the reservation here.
Assignee: nobody → adam
Whiteboard: [WebRTC], [blocking-webrtc+]
Priority: -- → P2
Whiteboard: [WebRTC], [blocking-webrtc+] → [WebRTC], [blocking-webrtc-]
Status: NEW → RESOLVED
Closed: 12 years ago
Resolution: --- → DUPLICATE
You need to log in before you can comment on or make changes to this bug.