Clean up extreme verbosity of logs in test harness.

Clean up extreme verbosity of logs in test harness.

In addition fix a bug where we track the wrong parallel job on the job pool.

In addition fix bug where we unittest harnesses randomly hangs while trying to write to stderr while finding update candidates.

Change-Id: I1449501606a57c5324eafc74c4fc388fbbe2bee3

BUG=chromium-os:12950
TEST=Ran with -q and full test suite and emulated errors
when necessary to see errors printed out only failures.

Committed: http://chrome-svn/viewvc/chromeos?view=rev&revision=8bc6eb9

[sosa, 2011-04-14 22:54:43]

This cleans up a lot of the test harness logs.

Instead we now just print out meta info about the operation rather than printing
out all the cmds.  I've also fixed message passing to exceptions so that the cmd
is shown correctly at the end of a stack trace showing the exact cmd that failed
if it does.

[davidjames, 2011-04-15 17:52:08]

http://codereview.chromium.org/6857004/diff/2001/au_test_harness/au_worker.py
File au_test_harness/au_worker.py (right):

http://codereview.chromium.org/6857004/diff/2001/au_test_harness/au_worker.py...
au_test_harness/au_worker.py:209: cmd, log_to_file=os.path.join(log_directory,
'update.log'),
I wish that there were only one version of cros_build_lib... you're using
features here that are specific to scripts/lib/cros_build_lib but aren't in
chromite/lib/cros_build_lib :(

http://codereview.chromium.org/6857004/diff/2001/au_test_harness/au_worker.py...
au_test_harness/au_worker.py:214: raise update_exception.UpdateException(1,
str(e))
Since you're logging to a file, I think the output and error won't be included
in str(e). Where does it get printed?

This seems decidedly less verbose than the non-verbose case.

http://codereview.chromium.org/6857004/diff/2001/au_test_harness/au_worker.py...
au_test_harness/au_worker.py:216: (code, stdout, stderr) =
cros_lib.RunCommandCaptureOutput(
Maybe rename stdout to 'output' and stderr to '_unused' because it's not used
and is always included in output?

http://codereview.chromium.org/6857004/diff/2001/au_test_harness/cros_au_test...
File au_test_harness/cros_au_test_harness.py (right):

http://codereview.chromium.org/6857004/diff/2001/au_test_harness/cros_au_test...
au_test_harness/cros_au_test_harness.py:72: str = 'delta update payload from %s
to %s' % (target, src)
Can we use a different name for the variable? str aliases a builtin (str)

http://codereview.chromium.org/6857004/diff/2001/au_test_harness/parallel_tes...
File au_test_harness/parallel_test_job.py (right):

http://codereview.chromium.org/6857004/diff/2001/au_test_harness/parallel_tes...
au_test_harness/parallel_test_job.py:67: return (active_count, active_job)
Looks like this is a bug fix. Could you mention this in the log message?

http://codereview.chromium.org/6857004/diff/2001/au_test_harness/update_excep...
File au_test_harness/update_exception.py (left):

http://codereview.chromium.org/6857004/diff/2001/au_test_harness/update_excep...
au_test_harness/update_exception.py:9: def __init__(self, code, stdout):
s/stdout/output/ since it includes all output. Can you also add documentation
explaining that output should contain both stdout and stderr all combined into
one variable?

http://codereview.chromium.org/6857004/diff/2001/au_test_harness/vm_au_worker.py
File au_test_harness/vm_au_worker.py (right):

http://codereview.chromium.org/6857004/diff/2001/au_test_harness/vm_au_worker...
au_test_harness/vm_au_worker.py:105: redirect_stdout=True, redirect_stderr=True,
cwd=self.crosutilsbin,
Two comments:
1. Looks like stderr is getting redirected now. Can we make this function print
out both stdout and stderr when the tests  fail? Right now it looks like it only
prints stderr... 
2. When the tests succeed output should contain stderr. Combining stdout and
stderr would be a good solution here.

[sosa, 2011-04-18 21:12:44]

http://codereview.chromium.org/6857004/diff/2001/au_test_harness/au_worker.py
File au_test_harness/au_worker.py (right):

http://codereview.chromium.org/6857004/diff/2001/au_test_harness/au_worker.py...
au_test_harness/au_worker.py:214: raise update_exception.UpdateException(1,
str(e))
It doesn't, however the logs are archived or a developercan look at the log.

On 2011/04/15 17:52:09, davidjames wrote:
> Since you're logging to a file, I think the output and error won't be included
> in str(e). Where does it get printed?
> 
> This seems decidedly less verbose than the non-verbose case.

http://codereview.chromium.org/6857004/diff/2001/au_test_harness/au_worker.py...
au_test_harness/au_worker.py:216: (code, stdout, stderr) =
cros_lib.RunCommandCaptureOutput(
On 2011/04/15 17:52:09, davidjames wrote:
> Maybe rename stdout to 'output' and stderr to '_unused' because it's not used
> and is always included in output?

Done.

http://codereview.chromium.org/6857004/diff/2001/au_test_harness/cros_au_test...
File au_test_harness/cros_au_test_harness.py (right):

http://codereview.chromium.org/6857004/diff/2001/au_test_harness/cros_au_test...
au_test_harness/cros_au_test_harness.py:72: str = 'delta update payload from %s
to %s' % (target, src)
On 2011/04/15 17:52:09, davidjames wrote:
> Can we use a different name for the variable? str aliases a builtin (str)

Done.

http://codereview.chromium.org/6857004/diff/2001/au_test_harness/parallel_tes...
File au_test_harness/parallel_test_job.py (right):

http://codereview.chromium.org/6857004/diff/2001/au_test_harness/parallel_tes...
au_test_harness/parallel_test_job.py:67: return (active_count, active_job)
On 2011/04/15 17:52:09, davidjames wrote:
> Looks like this is a bug fix. Could you mention this in the log message?

Done.

http://codereview.chromium.org/6857004/diff/2001/au_test_harness/update_excep...
File au_test_harness/update_exception.py (left):

http://codereview.chromium.org/6857004/diff/2001/au_test_harness/update_excep...
au_test_harness/update_exception.py:9: def __init__(self, code, stdout):
On 2011/04/15 17:52:09, davidjames wrote:
> s/stdout/output/ since it includes all output. Can you also add documentation
> explaining that output should contain both stdout and stderr all combined into
> one variable?

Done.  Changed to output to be more vague.  Doesn't necessarily require both
depending on what the dev wants to show.

http://codereview.chromium.org/6857004/diff/2001/au_test_harness/vm_au_worker.py
File au_test_harness/vm_au_worker.py (right):

http://codereview.chromium.org/6857004/diff/2001/au_test_harness/vm_au_worker...
au_test_harness/vm_au_worker.py:105: redirect_stdout=True, redirect_stderr=True,
cwd=self.crosutilsbin,
Not sure.  stderr is pretty useless here unless the test failed.  I think what
is being done is correct.

On 2011/04/15 17:52:09, davidjames wrote:
> Two comments:
> 1. Looks like stderr is getting redirected now. Can we make this function
print
> out both stdout and stderr when the tests  fail? Right now it looks like it
only
> prints stderr... 
> 2. When the tests succeed output should contain stderr. Combining stdout and
> stderr would be a good solution here.

[dgarrett, 2011-04-18 22:01:39]

http://codereview.chromium.org/6857004/diff/7001/au_test_harness/cros_au_test...
File au_test_harness/cros_au_test_harness.py (right):

http://codereview.chromium.org/6857004/diff/7001/au_test_harness/cros_au_test...
au_test_harness/cros_au_test_harness.py:82: return cros_lib.RunCommand(command,
enter_chroot=True, print_cmd=False,
LGTM to for change alone. ;>

[sosa, 2011-04-18 23:16:26]

PTAL at patch set 3.  Switched to using /dev/null for first test harness run
(unneccessary to show 1 unit test passing AND fixes hang bug).  Also, made it
even easier to tell from which test msgs are coming from.

[dgarrett, 2011-04-18 23:32:52]

Looks good, with one question.

http://codereview.chromium.org/6857004/diff/11002/au_test_harness/vm_au_worke...
File au_test_harness/vm_au_worker.py (right):

http://codereview.chromium.org/6857004/diff/11002/au_test_harness/vm_au_worke...
au_test_harness/vm_au_worker.py:83: Info(self.GetUpdateMessage(image_path,
src_image_path, True, proxy_port))
Should this be self.TestInfo instead?