New issue
Advanced search Search tips
Note: Color blocks (like or ) mean that a user may not be available. Tooltip shows the reason.

Issue 634342 link

Starred by 3 users

Issue metadata

Status: Fixed
Owner:
Closed: Aug 2016
Cc:
EstimatedDays: ----
NextAction: ----
OS: ----
Pri: 1
Type: Bug



Sign in to add a comment

WebRtcBrowserTest.RunsAudioVideoWebRTCCallInTwoTabsWithClonedCertificate* tests timing out flakily on WebRTC Win8 Tester bot

Project Member Reported by guidou@chromium.org, Aug 4 2016

Issue description

First failure seems to be https://build.chromium.org/p/chromium.webrtc/builders/Win8%20Tester/builds/27286

Sample error output:

1 test timed out:
   WebRtcBrowserTest.RunsAudioVideoWebRTCCallInTwoTabsWithClonedCertificateEcdsa (e:\b\c\b\win_builder\src\chrome\browser\media\webrtc_browsertest.cc:178)

1 test timed out:
    WebRtcBrowserTest.RunsAudioVideoWebRTCCallInTwoTabsWithClonedCertificateRsa (e:\b\c\b\win_builder\src\chrome\browser\media\webrtc_browsertest.cc:172)

 

Comment 1 by hbos@chromium.org, Aug 5 2016

Cc: hbos@chromium.org pbos@chromium.org
 Issue 628107  has been merged into this issue.

Comment 2 by hbos@chromium.org, Aug 5 2016

WebRtcTestBase::NegotiateCall[1] fails because GatherAndSendIceCandidates[2] aka receiveIceCandidates[3] is unable to parse the JSON argument.
It comes from getAllIceCandidates[4].

This is not specific to the certificate stuff, I would expect more webrtc browser tests should be failing? All of webrtc_browsertest.cc uses NegotiateCall.

These logs confuse me. receiveIceCandidates() should be called after getAllIceCandidates() with the results but it looks like getAllIceCandidates() returns to test AFTER receiveIceCandidates() fails because the ice candidates are undefined. Also, how can it continue the test after we have a Check failed crash? And how come when getAllIceCandidates() finally finishes it does return a valid JSON string.

[1] https://cs.chromium.org/chromium/src/chrome/browser/media/webrtc_browsertest_base.cc?sq=package:chromium&dr=C&rcl=1470381592&l=401
[2] https://cs.chromium.org/chromium/src/chrome/browser/media/webrtc_browsertest_base.cc?sq=package:chromium&dr=C&rcl=1470381592&l=396
[3] https://cs.chromium.org/chromium/src/chrome/test/data/webrtc/peerconnection.js?type=cs&q=peerconnection.js:251&sq=package:chromium&l=251
[4] https://cs.chromium.org/chromium/src/chrome/test/data/webrtc/peerconnection.js?type=cs&q=peerconnection.js:251&sq=package:chromium&l=232

[5044:2428:0802/110509:FATAL:rtc_peer_connection_handler.cc(444)] Check failed: main_thread_->BelongsToCurrentThread(). 
Backtrace:
	base::debug::StackTrace::StackTrace [0x01F7E3A7+23]
	logging::LogMessage::~LogMessage [0x01F38C71+49]
	content::RTCPeerConnectionHandler::~RTCPeerConnectionHandler [0x042443DD+659]
	rtc::RefCountedObject<content::`anonymous namespace'::SetSessionDescriptionRequest>::`vector deleting destructor' [0x0424459A+17]
	rtc::RefCountedObject<content::`anonymous namespace'::CreateSessionDescriptionRequest>::Release [0x042477CC+23]
	webrtc::PeerConnection::OnMessage [0x01CD6FD2+154]
	jingle_glue::JingleThreadWrapper::Dispatch [0x048815AC+131]
	jingle_glue::JingleThreadWrapper::RunTask [0x04881BCC+244]
	base::internal::InvokeHelper<1,void>::MakeItSo<void (__thiscall media::AudioRendererImpl::*const &)(enum media::BufferingState),base::WeakPtr<media::AudioRendererImpl> const &,enum media::BufferingState const &> [0x02123ACF+43]
	base::internal::Invoker<base::internal::BindState<void (__thiscall media::AudioRendererImpl::*)(enum media::BufferingState),base::WeakPtr<media::AudioRendererImpl>,enum media::BufferingState>,void __cdecl(void)>::Run [0x0459F6D3+23]
	base::debug::TaskAnnotator::RunTask [0x01FA7BF7+247]
	base::MessageLoop::RunTask [0x01F4891B+1211]
	base::MessageLoop::DoWork [0x01F47A9E+606]
	base::MessagePumpDefault::Run [0x01F7F7C8+424]
	base::MessageLoop::RunHandler [0x01F48457+103]
	base::RunLoop::Run [0x01F4AD99+41]
	base::Thread::Run [0x01F6C24C+92]
	base::Thread::ThreadMain [0x01F6C9F5+469]
	base::PlatformThread::Sleep [0x01F55742+290]
	BaseThreadInitThunk [0x76917C04+36]
	RtlInitializeExceptionChain [0x771FAB8F+143]
	RtlInitializeExceptionChain [0x771FAB5A+90]

Backtrace:
	base::debug::BreakDebugger [0x01FA4569+9]
	logging::InitChromeLogging [0x031B5970+759]
	logging::LogMessage::~LogMessage [0x01F38E07+455]
	content::RTCPeerConnectionHandler::~RTCPeerConnectionHandler [0x042443DD+659]
	rtc::RefCountedObject<content::`anonymous namespace'::SetSessionDescriptionRequest>::`vector deleting destructor' [0x0424459A+17]
	rtc::RefCountedObject<content::`anonymous namespace'::CreateSessionDescriptionRequest>::Release [0x042477CC+23]
	`anonymous namespace'::CreateSessionDescriptionMsg::`vector deleting destructor' [0x01CD337C+30]
	webrtc::PeerConnection::OnMessage [0x01CD6FD2+154]
	jingle_glue::JingleThreadWrapper::Dispatch [0x048815AC+131]
	jingle_glue::JingleThreadWrapper::RunTask [0x04881BCC+244]
	base::internal::InvokeHelper<1,void>::MakeItSo<void (__thiscall media::AudioRendererImpl::*const &)(enum media::BufferingState),base::WeakPtr<media::AudioRendererImpl> const &,enum media::BufferingState const &> [0x02123ACF+43]
	base::internal::Invoker<base::internal::BindState<void (__thiscall media::AudioRendererImpl::*)(enum media::BufferingState),base::WeakPtr<media::AudioRendererImpl>,enum media::BufferingState>,void __cdecl(void)>::Run [0x0459F6D3+23]
	base::debug::TaskAnnotator::RunTask [0x01FA7BF7+247]
	base::MessageLoop::RunTask [0x01F4891B+1211]
	base::MessageLoop::DoWork [0x01F47A9E+606]
	base::MessagePumpDefault::Run [0x01F7F7C8+424]
	base::MessageLoop::RunHandler [0x01F48457+103]
	base::RunLoop::Run [0x01F4AD99+41]
	base::Thread::Run [0x01F6C24C+92]
	base::Thread::ThreadMain [0x01F6C9F5+469]
	base::PlatformThread::Sleep [0x01F55742+290]
	BaseThreadInitThunk [0x76917C04+36]
	RtlInitializeExceptionChain [0x771FAB8F+143]
	RtlInitializeExceptionChain [0x771FAB5A+90]
[4804:3108:0802/110510:INFO:node_controller.cc(1099)] Could not be introduced to peer 927BC7907E6CC450.63E7705736E6CD86
[2328:2136:0802/110510:ERROR:browser_test_utils.cc(175)] Cannot communicate with DOMOperationObserver.
e:\b\c\b\win_builder\src\chrome\browser\media\webrtc_browsertest_base.cc(304): error: Value of: content::ExecuteScriptAndExtractString( tab_contents, javascript, &result)
  Actual: false
Expected: true
[2328:2136:0802/110510:INFO:CONSOLE(13)] "Returning Test failed: Error: Failed to parse JSON: , got SyntaxError: Unexpected end of JSON input
    at failTest (http://127.0.0.1:51539/webrtc/test_functions.js:46:15)
    at parseJson_ (http://127.0.0.1:51539/webrtc/peerconnection.js:380:5)
    at receiveIceCandidates (http://127.0.0.1:51539/webrtc/peerconnection.js:250:23)
    at <anonymous>:1:51 to test.", source: http://127.0.0.1:51539/webrtc/test_functions.js (13)
e:\b\c\b\win_builder\src\chrome\browser\media\webrtc_browsertest_base.cc(398): error: Value of: ExecuteJavascript( base::StringPrintf("receiveIceCandidates('%s')", ice_candidates.c_str()), to_tab)
  Actual: "Test failed: Error: Failed to parse JSON: , got SyntaxError: Unexpected end of JSON input\n    at failTest (http://127.0.0.1:51539/webrtc/test_functions.js:46:15)\n    at parseJson_ (http://127.0.0.1:51539/webrtc/peerconnection.js:380:5)\n    at receiveIceCandidates (http://127.0.0.1:51539/webrtc/peerconnection.js:250:23)\n    at <anonymous>:1:51"
Expected: "ok-received-candidates"
With diff:
@@ -1,1 +1,5 @@
-ok-received-candidates
+Test failed: Error: Failed to parse JSON: , got SyntaxError: Unexpected end of JSON input
+    at failTest (http://127.0.0.1:51539/webrtc/test_functions.js:46:15)
+    at parseJson_ (http://127.0.0.1:51539/webrtc/peerconnection.js:380:5)
+    at receiveIceCandidates (http://127.0.0.1:51539/webrtc/peerconnection.js:250:23)
+    at <anonymous>:1:51

[2328:2136:0802/110510:INFO:CONSOLE(251)] "Uncaught TypeError: Cannot read property 'length' of undefined", source: http://127.0.0.1:51539/webrtc/peerconnection.js (251)
[2328:2136:0802/110510:INFO:CONSOLE(13)] "Returning [{"candidate":"candidate:278816273 1 udp 2122260223 192.168.195.147 60708 typ host generation 0 ufrag t3X2 network-id 1","sdpMid":"audio","sdpMLineIndex":0},{"candidate":"candidate:278816273 2 udp 2122260222 192.168.195.147 60709 typ host generation 0 ufrag t3X2 network-id 1","sdpMid":"audio","sdpMLineIndex":0},{"candidate":"candidate:278816273 1 udp 2122260223 192.168.195.147 60710 typ host generation 0 ufrag t3X2 network-id 1","sdpMid":"video","sdpMLineIndex":1},{"candidate":"candidate:278816273 2 udp 2122260222 192.168.195.147 60711 typ host generation 0 ufrag t3X2 network-id 1","sdpMid":"video","sdpMLineIndex":1},{"candidate":"candidate:1578998497 1 tcp 1518280447 192.168.195.147 9 typ host tcptype active generation 0 ufrag t3X2 network-id 1","sdpMid":"audio","sdpMLineIndex":0}] to test.", source: http://127.0.0.1:51539/webrtc/test_functions.js (13)
[97/97] WebRtcBrowserTest.RunsAudioVideoWebRTCCallInTwoTabsWithClonedCertificateRsa (TIMED OUT)

Comment 3 by hbos@chromium.org, Aug 5 2016

If this...

    console.log('Still ICE gathering - waiting...');
    setTimeout(getAllIceCandidates, 100);
    return;

Somehow leads to it returning to test the log makes more sense. But this skips returnToTest(JSON.stringify(gIceCandidates));

It makes sense that the test continues even though the check fails because the EXPECT_TRUE that fails is a "GTEST_NONFATAL_FAILURE_".

Comment 4 by hbos@chromium.org, Aug 5 2016

Oh well, should just focus on the "rtc_peer_connection_handler.cc(444)] Check failed: main_thread_->BelongsToCurrentThread()", this happens before every failed test.
(Maybe returning to test is a side-effect of crashing? That bit is probably a red herring.)

Comment 5 by hbos@chromium.org, Aug 5 2016

setLocalDescription[1] and setRemoteDescription[2] takes the scoped_refptr<SetSessionDescriptionRequest> and posts to other threads as a raw pointer. I think it's a mistake that it here and in other places is passed around as a raw pointer and not a scoped_refptr.

[1] https://cs.chromium.org/chromium/src/content/renderer/media/rtc_peer_connection_handler.cc?sq=package:chromium&dr=CSs&rcl=1470381592&l=1225
[2] https://cs.chromium.org/chromium/src/content/renderer/media/rtc_peer_connection_handler.cc?sq=package:chromium&dr=CSs&rcl=1470381592&l=1279

Comment 6 by hbos@chromium.org, Aug 5 2016

Status: Started (was: Available)
Possible fix, not sure: https://codereview.chromium.org/2222553002/
Project Member

Comment 7 by bugdroid1@chromium.org, Aug 17 2016

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/4d31d2e1163f6f3125470695ccd60a30830a1cde

commit 4d31d2e1163f6f3125470695ccd60a30830a1cde
Author: hbos <hbos@chromium.org>
Date: Wed Aug 17 14:35:47 2016

Removed CreateSessionDescriptionRequest and SetSessionDescriptionRequest
main-thread DCHECKs from their destructors.

CreateSessionDescriptionRequest and SetSessionDescriptionRequest are
reference counted and have callback methods that are invoked on the
signaling thread. If invoked on a non-main thread a post occurs to the
main thread, referencing the object until the callback has completed on
the main thread. There was an incorrect assumption that the object would
also be destroyed on the main thread. But because the callback may
sometimes complete before the signaling thread has had an opportunity to
dereference the object it can be destroyed on the signaling thread.
This CL allows it to be destroyed on any thread.

BUG= 634342 

Review-Url: https://codereview.chromium.org/2222553002
Cr-Commit-Position: refs/heads/master@{#412523}

[modify] https://crrev.com/4d31d2e1163f6f3125470695ccd60a30830a1cde/content/renderer/media/rtc_peer_connection_handler.cc

Comment 8 by hbos@chromium.org, Aug 17 2016

Status: Fixed (was: Started)
The bug was identified and should be fixed by the above landed CL. (The problem was not relating to passing a raw pointer, ref counting was used correctly. The problem was with having references on two threads and no guarantee which thread would release its reference first. So we allow it to be destroyed on any thread, DCHECK removed.)

Sign in to add a comment