WebRtcBrowserTest.RunsAudioVideoWebRTCCallInTwoTabsWithClonedCertificate* tests timing out flakily on WebRTC Win8 Tester bot |
|||
Issue descriptionFirst 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)
,
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)
,
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_".
,
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.)
,
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
,
Aug 5 2016
Possible fix, not sure: https://codereview.chromium.org/2222553002/
,
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
,
Aug 17 2016
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 |
|||
Comment 1 by hbos@chromium.org
, Aug 5 2016