537739 - Fix INFO string parsing for xpcshell test log files

Status: VERIFIED FIXED

(Release Engineering :: General, defect, P2)

Description

[Chris Cooper [:coop] (he/him)]

jmaher hit this issue on try server. The logs for his xpcshell tests came back looking like this:

INFO | Result summary:
    INFO | Passed: 725
    INFO | Failed: 0

The leading space was not parsed correctly by buildbot, so it got marked as T-FAIL.

Patch coming up.

Comment 1

[Chris Cooper [:coop] (he/him)]

Attachment: Add (potential) whitespace to INFO regexp

Tested fine locally.

Comment 2

[Chris Cooper [:coop] (he/him)]

Comment on attachment 419933 [details] [diff] [review]
Add (potential) whitespace to INFO regexp

http://hg.mozilla.org/build/buildbotcustom/rev/980e7f27daab

Comment 3

[Chris Cooper [:coop] (he/him)]

Try server is running the updated code now. Still waiting on a window to reconfig the production-masters, but the problem doesn't appear to be present on them anyway.

Comment 4

[Serge Gautherie (:sgautherie)]

(In reply to comment #0)

Any idea how that happened?
Iirc, this is unexpected.

Comment 5

[Joel Maher ( :jmaher ) (UTC -8)]

I think there is still one more issue.  I get no indication of failure or error, but still orange:
http://tinderbox.mozilla.org/showlog.cgi?log=MozillaTry/1262787880.1262795397.4983.gz&fulltext=1

I have been seeing this since the patch was checked in almost 2 days ago.

Comment 6

[Chris Cooper [:coop] (he/him)]

Attachment: Add (potential) whitespace to status regexp

(In reply to comment #5)
> I think there is still one more issue.  I get no indication of failure or
> error, but still orange:

There's a corresponding regexp error in the code that sets the return status. Patch attached.

Comment 7

[Serge Gautherie (:sgautherie)]

(In reply to comment #1)
> Add (potential) whitespace to INFO regexp

Why is this suddenly needed? Why is it the right fix?
I'm all for backing your patch out asap!


(In reply to comment #4)
> Any idea how that happened?
> Iirc, this is unexpected.

Any of you care to answer?


(In reply to comment #5)

I don't know about that orange,
but afaict your patch is just breaking the test suites (summary and leaks
parts):
{
INFO | Result summary:
    INFO | Passed: 728
    INFO | Failed: 0
TinderboxPrint: xpcshell-tests<br/>728/0

== BloatView: ALL (cumulative) LEAK AND BLOAT STATISTICS, default process 19084
== BloatView: ALL (cumulative) LEAK AND BLOAT STATISTICS, default process 19084
== BloatView: ALL (cumulative) LEAK AND BLOAT STATISTICS, default process 19084
[...]
TinderboxPrint: mochitest-plain<br/>148252/0/1389

Same for:
TinderboxPrint: mochitest-chrome<br/>7644/0/108
TinderboxPrint: mochitest-browser-chrome<br/>4326/0/5
TinderboxPrint: mochitest-a11y<br/>13189/0/6
}

I checked the previous ([e-mail] bug-531802-v02-Dec29-delay-13) and
next ([e-mail] 1262788390) build logs and they are just fine.

Care to at least point to the bug/patch that is involved?


(In reply to comment #6)
> Created an attachment (id=420351) [details]
> Add (potential) whitespace to status regexp

Please, no!
This bug, as it is (= with no details), is just nonsense!!

Comment 8

[Chris Cooper [:coop] (he/him)]

(In reply to comment #7)
> Please, no!
> This bug, as it is (= with no details), is just nonsense!!

Serge, just calm down, please.

Why is it nonsense to make the regexp more robust in a non-destructive way? jmaher has posted 2 sets of logs (out of what I assume is a larger set) that exhibit this behavior.

Comment 9

[Joel Maher ( :jmaher ) (UTC -8)]

I have been confused by this as well.  I look in the log files and don't see
any indication of failures, errors or leaks.  But my stuff comes back as Orange
all the time.  I test with and without my patch locally and diff the output
logs and there is no difference, so for me it looks more and more like
something on the tinderbox parsing end.

Comment 10

[Chris Cooper [:coop] (he/him)]

(In reply to comment #9)
> I have been confused by this as well.  I look in the log files and don't see
> any indication of failures, errors or leaks.  But my stuff comes back as Orange
> all the time.  I test with and without my patch locally and diff the output
> logs and there is no difference, so for me it looks more and more like
> something on the tinderbox parsing end.

My gut feeling is that this is a scratchbox-related issue, but I have no data to back that up.

Comment 11

[Serge Gautherie (:sgautherie)]

(In reply to comment #8)

> Serge, just calm down, please.

I'd be happy to, if only (both of) you would answer my questions...

> Why is it nonsense to make the regexp more robust in a non-destructive way?

More robust to _what_?
From my point of view, you're just breaking what the suite is designed to do: detect failures!
And these spaces at the beginning of the lines are a failure, as there should _not_ be any!!

> jmaher has posted 2 sets of logs (out of what I assume is a larger set) that
> exhibit this behavior.

Where?
I can only see comment 5 example, and that log is way broken.


(In reply to comment #9)
> it looks more and more like something on the tinderbox parsing end.

Joel: maybe. My question _is_ still "_what_ in your patch triggers this issue?".
Chris: but, again, _what_ would that have to do with the test suites?


(In reply to comment #10)
> My gut feeling is that this is a scratchbox-related issue, but I have no data
> to back that up.

Then, _why_ mess around the test suites until the cause is understood?

Comment 12

[Chris Cooper [:coop] (he/him)]

Here's the root cause:

http://hg.mozilla.org/mozilla-central/rev/85cd0f297421#l7.442

Standard8 is pushing a fix.

Serge: while I appreciate all the work you've done to standardize the test output, I think you're losing sight of what's most important here. Developers want to see the results of their tests. Harness failures don't interest them at all, so if we can avoid showing them spurious ones, we should.

That said, I'll back out the first patch and won't land the second one once Standard8 pushes his fix.

Comment 13

[Joel Maher ( :jmaher ) (UTC -8)]

I would like to say thanks for looking into this.  These tools are great and they work for everything else, yet spending hours looking at the logs yield no reason why there was a failure.  

Maybe a future update to tinderbox would be something that at least pointed out in the log what general area was failing "xpcshell log didn't parse as expected".

I will say I spent a lot of time trying to figure this out, it wasn't a point fingers first type of problem.

Comment 14

[Chris Cooper [:coop] (he/him)]

Comment on attachment 419933 [details] [diff] [review]
Add (potential) whitespace to INFO regexp

Backed out.

http://hg.mozilla.org/build/buildbotcustom/rev/8d9dc4bf77f4

Comment 15

[Chris Cooper [:coop] (he/him)]

Root cause has been fixed:

http://hg.mozilla.org/mozilla-central/rev/aa6337822028

Comment 16

[Serge Gautherie (:sgautherie)]

(In reply to comment #12)

> I appreciate all the work you've done

And that's exactly why I'm not calm whenever someone just breaks it without
even explaining/understanding what he's doing, as much as it looks like.
Moreover, when it's so easy to just ask me in the first place!

> I think you're losing sight of what's most important here.

Am I?

> Harness failures don't interest them at all,

When did the harness fail??
(Anyway, harness failures have got to interest someone, I would hope!
And that someone would better be the one modifying the harness!!)

> so if we can avoid showing them spurious ones, we should.

What "spurious"???
The lines in that changeset are wrong: getting orange is the _right_ result to
expect!
(Otherwise, how would one detect the regression?)


(In reply to comment #13)

> These tools are great and they work for everything else,
> yet spending hours looking at the logs yield no
> reason why there was a failure.  

unittest.py is designed to report "T-FAIL".
Afaict, it didn't in comment 5 because of the very regression from comment 2.
That's why *I* spent nearly a hour checking various logs when the harness
should have been "explicit" (as it was in comment 0).

> Maybe a future update to tinderbox would be something that at least pointed out
> in the log what general area was failing "xpcshell log didn't parse as
> expected".

No need for an update: just need _not_ to break what _is_ working!
I believe modifying the harness is an edge case and "T-FAIL" is a good enough
pointer,
that said, if you actually would like an additional and more detailed log
entry, I agree it wouldn't hurt: just file a bug about it.

> I will say I spent a lot of time trying to figure this out, it wasn't a point
> fingers first type of problem.

It was in comment 0 ... though obviously neither of you knew what "T-FAIL"
meant: maybe it's documentation that needs updating most?

As a side note, I find it amusing that you complain about the harness not
telling you what was wrong (even) more explicitly ... when you never said (in
this bug) what you submitted to the Try Server :-|


Anyway, V.Fixed after comment (12,) 14 and 15 :-)

PS: Were the duplicated leak log lines I noticed in comment 7 explained/fixed
too? (though that part was not this bug subject)

Comment 17

[Serge Gautherie (:sgautherie)]

(In reply to comment #15)
> Root cause has been fixed:
> 
> http://hg.mozilla.org/mozilla-central/rev/aa6337822028

Backed out (with bug 430475 too):
http://hg.mozilla.org/mozilla-central/rev/4ee1dc317588

Comment 18

[Serge Gautherie (:sgautherie)]

(In reply to comment #16)
> PS: Were the duplicated leak log lines I noticed in comment 7 explained/fixed
> too? (though that part was not this bug subject)

It looks like not: bug 540617 :-[

(In reply to comment #17)
> Backed out (with bug 430475 too):

Bug 530475 !