Need to be able to see logs from xpcshell tests

VERIFIED FIXED in mozilla1.9.2a1

Status

Testing
XPCShell Harness
--
major
VERIFIED FIXED
9 years ago
9 years ago

People

(Reporter: mossop, Assigned: jag (Peter Annema))

Tracking

(Blocks: 2 bugs, {fixed1.9.1, regression})

Trunk
mozilla1.9.2a1
fixed1.9.1, regression
Points:
---
Dependency tree / graph
Bug Flags:
in-testsuite -

Firefox Tracking Flags

(Not tracked)

Details

(Whiteboard: [fixed1.9.1b99])

Attachments

(1 attachment, 1 obsolete attachment)

(Reporter)

Description

9 years ago
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.
(Reporter)

Comment 1

9 years ago
This also makes it impossible to see interesting things that happen even when a test passes, like thread safety assertions.
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?
(Assignee)

Comment 3

9 years ago
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?
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.
(Assignee)

Comment 5

9 years ago
Created attachment 369966 [details] [diff] [review]
Write out the log file
Assignee: nobody → jag
Attachment #369966 - Flags: review?(ted.mielczarek)
(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 ?
Version: unspecified → Trunk
(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) ?
(Assignee)

Comment 8

9 years ago
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.
(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.
(Assignee)

Comment 10

9 years ago
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)
(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!")
}
(Assignee)

Comment 12

9 years ago
So in that case you can remove both "exists" tests, no? (Or with the change in comment 10, just the single test).
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.)
Attachment #369966 - Flags: review?(ted.mielczarek) → review+
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
(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 ??
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.
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.
Blocks: 482084
Status: NEW → ASSIGNED
(Assignee)

Comment 18

9 years ago
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.
(Assignee)

Comment 19

9 years ago
Created attachment 372903 [details] [diff] [review]
Write out stdout and the leak report to <test>.log
[Checkin: See comment 28 & 29]
Attachment #369966 - Attachment is obsolete: true
Attachment #372903 - Flags: review?(ted.mielczarek)
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 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:
(Assignee)

Comment 22

9 years ago
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.
(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.
(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?
(Assignee)

Comment 25

9 years ago
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?
(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 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.
Attachment #372903 - Flags: review?(ted.mielczarek) → review+
(Assignee)

Comment 28

9 years ago
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.
(Assignee)

Updated

9 years ago
Status: ASSIGNED → RESOLVED
Last Resolved: 9 years ago
Resolution: --- → FIXED
Flags: in-testsuite-
Whiteboard: [needs 1.9.1 landing]
Target Milestone: --- → mozilla1.9.2a1
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
}
Attachment #372903 - Attachment description: Write out stdout and the leak report to <test>.log → Write out stdout and the leak report to <test>.log [Checkin: See comment 28 & 29]
[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
Severity: normal → major
Status: RESOLVED → VERIFIED
Keywords: fixed1.9.1, regression
Whiteboard: [needs 1.9.1 landing] → [fixed1.9.1rc1]
Whiteboard: [fixed1.9.1rc1] → [fixed1.9.1b99]
(Reporter)

Comment 31

9 years ago
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
You need to log in before you can comment on or make changes to this bug.