484298 - Need to be able to see logs from xpcshell tests

Status: VERIFIED FIXED

(Testing :: XPCShell Harness, defect)

Description

[Dave Townsend [:mossop]]

Losing the logging of xpcshell tests except when failures happen is a regression IMHO. I used the feature all the time to help me debug tests as I was writing them. Now that it is gone, sure I can put in random failures to get the log up to a certain point, but that really doesn't help me get an idea of what went on up to the point that a test hangs.

We should spit out a log when doing check-one or when the test is interrupted by Ctrl-C I think.

Comment 1

[Dave Townsend [:mossop]]

This also makes it impossible to see interesting things that happen even when a test passes, like thread safety assertions.

Comment 2

[Jeff Walden [:Waldo]]

Not to quibble about the more generic case, but threadsafety assertions should already be caught by the XPCOM_DEBUG_BREAK=stack-and-abort that's in place when xpcshell tests run, no?

Comment 3

[jag (Peter Annema)]

Are there reasons not to save these logs? Does it slow the tests down a lot? Do they take up a lot of disk space?

In that case, how about adding a var (similar to how we handle SOLO_FILE) that adds --log to check, check-interactive, and check-one and have that trigger saving the log files?

Comment 4

[(not currently active) Ted Mielczarek]

jag: no, just that when I rewrote the harness, I didn't see the point in dumping them on success, and just wrote the code to read stdout to memory, since it was easier. The previous harness was a shell script, so of course dumping the log to disk is the natural thing to do there.

I don't particularly care either way here. I'd take a patch to remove the print that insinuates we produce a log, or a patch to actually make us dump the log. I don't think we need a special argument, we should just always write the log or never write the log.

Comment 5

[jag (Peter Annema)]

Attachment: Write out the log file

Comment 6

[Serge Gautherie (:sgautherie)]

(Eh ted, we already talked about these log files when I did bug 469523...)

jag, fwiw, the leak report used to be dumped to the log file too:
bug 469523 now handles this in a cleaner way, but you may still want to copy it to the log file ?

Comment 7

[Serge Gautherie (:sgautherie)]

(In reply to comment #4)
> I'd take a patch to remove the print that insinuates we produce a log

I already did that in bug 469523 ... You may want to restore it (or not) ?

Comment 8

[jag (Peter Annema)]

Oh, I missed that you removed it. I'll undo that. And yeah, I'll append the leaklog output too, good catch.

Speaking of the leaklog, I noticed that we're checking whether the file exists in two places; we could just check it once and not call processLeakLog if it doesn't exist.

Comment 9

[Serge Gautherie (:sgautherie)]

(In reply to comment #8)
> Speaking of the leaklog, I noticed that we're checking whether the file exists
> in two places; we could just check it once and not call processLeakLog if it
> doesn't exist.

(I had the same idea when I wrote it, but:)
No, that's on purpose: the current processLeakLog() is only a stub until I enable the version which parse the log.

Comment 10

[jag (Peter Annema)]

Serge: for the new one you still want to skip parsing if the leak log doesn't exist, right? Or are you aiming to always have a leak log?

I guess I'm not quite sure what the following prevents you from doing:

      if os.path.exists(leakLogFile):
        processLeakLog(leakLogFile)
        os.remove(leakLogFile)

Comment 11

[Serge Gautherie (:sgautherie)]

(In reply to comment #10)
> Or are you aiming to always have a leak log?

"Yes", see for example:
{
http://mxr.mozilla.org/mozilla-central/source/build/automation.py.in

435   if not os.path.exists(leakLogFile):
436     log.info("WARNING refcount logging is off, so leaks can't be detected!")
}

Comment 12

[jag (Peter Annema)]

So in that case you can remove both "exists" tests, no? (Or with the change in comment 10, just the single test).

Comment 13

[Serge Gautherie (:sgautherie)]

No! Just fix this bug without touching the leak stuff, which I'm taking care of in that other bug(s).
Read the relevant bugs if you do want to find out what purpose each check has.
(You can comment there if need be, but let's proceed here.)

Comment 14

[(not currently active) Ted Mielczarek]

Comment on attachment 369966 [details] [diff] [review]
Write out the log file

+      try:
+        f = open(test + '.log', 'w')
+        try:
+          f.write(stdout)
+        finally:
+          f.close()
+      except IOError:
+        pass

Ditch the nested try blocks, and just do:
finally:
 if f:
   f.close()

r=me with that change

Comment 15

[Serge Gautherie (:sgautherie)]

(In reply to comment #4)
> [...] just wrote the code to read stdout to memory,
> since it was easier. The previous harness was a shell script, so of course
> dumping the log to disk is the natural thing to do there.

What you may (or not, I don't know) want to restore too here is to replace the new stdout pipe directly with the log file ??

Comment 16

[(not currently active) Ted Mielczarek]

Eh, doesn't matter to me. It's the same thing either way. Either we write directly to the log and then have to read it back in to print it out, or we log to memory and have to write the log to file.

Comment 17

[Serge Gautherie (:sgautherie)]

I don't now if python provides an easy way to get a |tee| like behavior, which I would probably prefer.
With the current pipe(-only), it looks like in case of a hanging/aborted/etc test (= probably a timeout on buildbot) the in-memory log is lost, is it not ?

I wanted to at least mention it ftr as it could be considered a regression too compared to the behavior we had with the shell version.

Comment 18

[jag (Peter Annema)]

Ted: I figured that would probably work, but I'm still learning Python, so I searched Google for the recommend safe pattern.

Serge: I guess the script doesn't automatically kill hung tests. I figure at that point you're gonna want to debug it interactively anyway, and not having the log file isn't such a big deal. I'll write the patch for appending the leaklog, though.

Comment 19

[jag (Peter Annema)]

Attachment: Write out stdout and the leak report to <test>.log [Checkin: See comment 28 & 29]

Comment 20

[Serge Gautherie (:sgautherie)]

Comment on attachment 372903 [details] [diff] [review]
Write out stdout and the leak report to <test>.log
[Checkin: See comment 28 & 29]

>   def processLeakLog(leakLogFile):

You should not modify this (stub) function, as automation.py function does/will not have this feature.

>+        if leakReport:
>+          f.write(leakReport)

I suggest to drop the 'if' and simply copy 'leakLogFile' content.

You may also want to support bug 469509...

Comment 21

[Serge Gautherie (:sgautherie)]

Comment on attachment 372903 [details] [diff] [review]
Write out stdout and the leak report to <test>.log
[Checkin: See comment 28 & 29]

>+      try:
>+        f = open(test + '.log', 'w')

Nit: I prefer
>+      f = open(test + '.log', 'w')
>+      try:

Comment 22

[jag (Peter Annema)]

Ok, so I was trying to avoid reading the contents of leakLogFile twice. If processLeakLog is going to look more like the version in automation.py (it looks a lot like dumpLeakLog right now), then I'll just read and write the contents of leakLogFile as you suggest.

I put the open inside the try 'coz open can fail and I don't want that to interfere with the rest of the testing, since the log file is a nice side-effect.

Comment 23

[Serge Gautherie (:sgautherie)]

(In reply to comment #22)
> If processLeakLog is going to look more like the version in automation.py
> (it looks a lot like dumpLeakLog right now)

Indeed: the leak detection feature was mochitests only; it is now shared with reftests; hopefully, it will be shared with xpcshell-tests too in the "near" future.

Comment 24

[Serge Gautherie (:sgautherie)]

(In reply to comment #22)
> I put the open inside the try 'coz open can fail and I don't want that to
> interfere with the rest of the testing, since the log file is a nice
> side-effect.

Ah. You might add an |except + warning| then?

Comment 25

[jag (Peter Annema)]

It seems silly though to read the contents of the leak log file twice. I'd rather split up processLeakLog (both here and in automation.py) into readLeakLog (which returns a string or None) and processLeakLog (which does the actual processing).

We are allowed to modify automation.py.in, right?

Comment 26

[Serge Gautherie (:sgautherie)]

(In reply to comment #25)
> It seems silly though to read the contents of the leak log file twice. I'd

I agree.

> rather split up processLeakLog (both here and in automation.py) into
> readLeakLog (which returns a string or None) and processLeakLog (which does the
> actual processing).

Maybe...
But have you noticed that processLeakLog() is already reading it twice itself and Jeff refused to change that? :-/

> We are allowed to modify automation.py.in, right?

Sure.
Yet, I stand by my previous comments that a dumb solution is enough atm,
as this will be revisited later anyway.

Comment 27

[(not currently active) Ted Mielczarek]

Comment on attachment 372903 [details] [diff] [review]
Write out stdout and the leak report to <test>.log
[Checkin: See comment 28 & 29]

I don't really care what you do here. I figure Serge will wind up rewriting half of it as he refactors things anyway.

Comment 28

[jag (Peter Annema)]

http://hg.mozilla.org/mozilla-central/rev/206c42d5b017

Serge, feel free to re-do all of this as part of your refactoring. I hope you can get Jeff to change his mind about reading the file twice. When running a large number of tests that kinda stuff will start to add up.

Comment 29

[Serge Gautherie (:sgautherie)]

Comment on attachment 372903 [details] [diff] [review]
Write out stdout and the leak report to <test>.log
[Checkin: See comment 28 & 29]


http://hg.mozilla.org/releases/mozilla-1.9.1/rev/51450142f83b

after fixing context for
{
patching file testing/xpcshell/runxpcshelltests.py
Hunk #2 FAILED at 186
1 out of 2 hunks FAILED
}

Comment 30

[Serge Gautherie (:sgautherie)]

[Mozilla/5.0 (Windows; U; Windows NT 5.0; en-US; rv:1.9.2a1pre) Gecko/20090601 Minefield/3.6a1pre] (home, optim default) (W2Ksp4)
(http://hg.mozilla.org/mozilla-central/rev/ab395a1916be)

V.Fixed

Comment 31

[Dave Townsend [:mossop]]

I probably should have paid more attention but the "fix" here didn't actually fix the main problem I was talking about in comment 0. Filed bug 500388