1047753 - Failing run is green

Status: RESOLVED DUPLICATE of bug 1028327

(Release Engineering :: General, defect)

Description

[Kyle Huey (Exited; not receiving bugmail, old account, do not use)]

https://tbpl.mozilla.org/?tree=Try&rev=e35cae6fe410

See that lonely green M9 on my try push.  It has

17:19:39     INFO -  DeviceRunner TEST-UNEXPECTED-FAIL | /tests/dom/media/tests/mochitest/test_peerConnection_setRemoteAnswerInStable.html | application timed out after 450.0 seconds with no output

In the log.  Why didn't it turn orange?

Comment 1

[[:mmc] Monica Chew (no longer reading bugmail)]

I'm getting possibly related behavior. Orange mochitest other, no failing tests.

https://tbpl.mozilla.org/?tree=Try&rev=8ca0f03f614b
https://tbpl.mozilla.org/php/getParsedLog.php?id=45074896&tree=Try

Log

Ubuntu VM 12.04 try debug test mochitest-other on 2014-08-01 10:45:41 PDT for push 8ca0f03f614b

slave: tst-linux32-spot-444

View Full Log

Download Full Log

No errors or warnings found.

Comment 2

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

(In reply to Kyle Huey [:khuey] ([e-mail]) from comment #0)
> https://tbpl.mozilla.org/?tree=Try&rev=e35cae6fe410
> 
> See that lonely green M9 on my try push.  It has
> 
> 17:19:39     INFO -  DeviceRunner TEST-UNEXPECTED-FAIL |
> /tests/dom/media/tests/mochitest/test_peerConnection_setRemoteAnswerInStable.
> html | application timed out after 450.0 seconds with no output
> 
> In the log.  Why didn't it turn orange?

Is it skipping over it because the line starts with "DeviceRunner"?



(In reply to [:mmc] Monica Chew (please use needinfo) from comment #1)
> I'm getting possibly related behavior. Orange mochitest other, no failing
> tests.
> 
> https://tbpl.mozilla.org/?tree=Try&rev=8ca0f03f614b
> https://tbpl.mozilla.org/php/getParsedLog.php?id=45074896&tree=Try
> 
> Log
> 
> Ubuntu VM 12.04 try debug test mochitest-other on 2014-08-01 10:45:41 PDT
> for push 8ca0f03f614b
> 
> slave: tst-linux32-spot-444
> 
> View Full Log
> 
> Download Full Log
> 
> No errors or warnings found.

I see things like the following in the log:

00:32:21     INFO -  1210 INFO [3836] WARNING: NS_ENSURE_TRUE(aURI) failed: file c:/builds/moz2_slave/try-w32-d-00000000000000000000/build/netwerk/dns/nsEffectiveTLDService.cpp, line 162
00:32:21     INFO -  1211 INFO [3836] WARNING: CacheIndex::SetupDirectoryEnumerator() - Entries directory doesn't exist!: file c:/builds/moz2_slave/try-w32-d-00000000000000000000/build/netwerk/cache2/CacheIndex.cpp, line 2574
00:32:21     INFO -  1212 INFO [3836] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80070057: file c:\builds\moz2_slave\try-w32-d-00000000000000000000\build\content\base\src\ThirdPartyUtil.cpp, line 296
00:32:21     INFO -  1213 INFO [3836] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80040111: file c:/builds/moz2_slave/try-w32-d-00000000000000000000/build/netwerk/cache2/CacheFileIOManager.cpp, line 2703
00:32:21     INFO -  1214 INFO [3836] ###!!! ASSERTION: null URI!: 'aSecondURI', file c:\builds\moz2_slave\try-w32-d-00000000000000000000\build\content\base\src\ThirdPartyUtil.cpp, line 35
00:32:21     INFO -  1215 INFO ThirdPartyUtil::IsThirdPartyWindow(nsIDOMWindow *,nsIURI *,bool *) [content/base/src/ThirdPartyUtil.cpp:135]
00:32:21     INFO -  1216 INFO ThirdPartyUtil::IsThirdPartyChannel(nsIChannel *,nsIURI *,bool *) [content/base/src/ThirdPartyUtil.cpp:250]
00:32:21     INFO -  1217 INFO nsChannelClassifier::ShouldEnableTrackingProtection(nsIChannel *,bool *) [netwerk/base/src/nsChannelClassifier.cpp:56]
00:32:21     INFO -  1218 INFO nsChannelClassifier::Start(nsIChannel *) [netwerk/base/src/nsChannelClassifier.cpp:192]
00:32:21     INFO -  1219 INFO mozilla::net::nsHttpChannel::BeginConnect() [netwerk/protocol/http/nsHttpChannel.cpp:4627]
00:32:21     INFO -  1220 INFO mozilla::net::nsHttpChannel::OnProxyAvailable(nsICancelable *,nsIURI *,nsIProxyInfo *,tag_nsresult) [netwerk/protocol/http/nsHttpChannel.cpp:4697]
00:32:21     INFO -  1221 INFO nsAsyncResolveRequest::DoCallback() [netwerk/base/src/nsProtocolProxyService.cpp:226]

Unsure if that assertion (or any of the multiple other instances where it asserts like that) could cause the suite to fail.

Comment 3

[Ryan VanderMeulen [:RyanVM]]

(In reply to Kyle Huey [:khuey] ([e-mail]) from comment #0)
> https://tbpl.mozilla.org/?tree=Try&rev=e35cae6fe410
> 
> See that lonely green M9 on my try push.  It has
> 
> 17:19:39     INFO -  DeviceRunner TEST-UNEXPECTED-FAIL |
> /tests/dom/media/tests/mochitest/test_peerConnection_setRemoteAnswerInStable.
> html | application timed out after 450.0 seconds with no output
> 
> In the log.  Why didn't it turn orange?

This bug 1028327 if I'm not mistaken.

(In reply to [:mmc] Monica Chew (please use needinfo) from comment #1)
> I'm getting possibly related behavior. Orange mochitest other, no failing
> tests.
> 
> https://tbpl.mozilla.org/?tree=Try&rev=8ca0f03f614b
> https://tbpl.mozilla.org/php/getParsedLog.php?id=45074896&tree=Try
> 
> Log
> 
> Ubuntu VM 12.04 try debug test mochitest-other on 2014-08-01 10:45:41 PDT
> for push 8ca0f03f614b
> 
> slave: tst-linux32-spot-444
> 
> View Full Log
> 
> Download Full Log
> 
> No errors or warnings found.

As mentioned by Wes, the issues are in the full log. Basically, TBPL uses the return code from the test harness to go orange, red, green, or whatever. From there, it parses the log looking for various failure patterns to highlight in the summary. In this case, you hit a combination of the harness failing but the log parser not finding anything in particular to highlight.

When I look at the full log, I see some lines like this:

11:41:23     INFO -  2227 INFO ###!!! [Parent][OnMaybeDequeueOne] Error: Channel closing: too late to send/recv, messages will be lost

Which suggests that the parent or child process crashed, which is sadmaking. However, I'm not seeing anything horribly obvious in there at first glance :(.

Anyway, the issue you're hitting is unrelated to Kyle's. It would be better to track it in a different bug as either the harness isn't outputting useful information for TBPL's log parser to catch or TBPL's log parser isn't catching what the harness is giving it, and either sounds like something that needs investigating :)

Comment 4

[Ed Morley [:emorley]]

Just to give some additional context:

TBPL does not determine the job result (and thus colour used for the job symbol) - it simply uses the buildbot result code. This is derived in buildbotcustom from a combination of harness, mozharness & buildbotcustom logic (not just the return code from the harness).

TBPL does however have to parse the logs to determine what subset of it to display in the error summary. In the comment 0 case, the TBPL log parser regex is catching a case that was missed by the harness/buildbot - bug 1028327 is filed for this. In the comment 1 case, the problem is the complete opposite: the TBPL log parser is not matching against a case that the harness/buildbot has determined is a failure. For this latter case, as Ryan said, either the TBPL (/treeherder) log parser regex could be supplemented, or else the harness could output something more useful. Either way a new bug filed marked blocking bug 778688 would be ideal :-)