Add crash detection to test report generation.

Add crash detection to test report generation.

As titled, similarly to http://codereview.chromium.org/6508003/, crashes are now detected in Autotest runs and will result in an error being thrown when detected.

The error thrown during crash detection will cause smoke failures and close the tree.

Change-Id: I403833c99c6c37f971bdbe962655ead10a1014c5

BUG=chromium-os:12100
TEST=Ran bvt, smoke with good and bad builds through run_remote_tests.

Committed: http://chrome-svn/viewvc/chromeos?view=rev&revision=1838b64

[sosa, 2011-02-16 00:39:32]

+petkov

[petkov, 2011-02-16 00:53:56]

http://codereview.chromium.org/6526031/diff/2002/generate_test_report.py
File generate_test_report.py (right):

http://codereview.chromium.org/6526031/diff/2002/generate_test_report.py#newc...
generate_test_report.py:119: crashes.append(match.group(1).split('\t')[0])
what does this do? group(1) is the whole string, right? then split by \t, and
[0] would be "Received crash notification..."?

http://codereview.chromium.org/6526031/diff/2002/generate_test_report.py#newc...
generate_test_report.py:226: print ''
Isn't it better to interleave the crash results into the main results table?
Then you see the data for each test in one place (PASS/FAIL, perf, crashes...)

[DaleCurtis, 2011-02-16 00:59:00]

http://codereview.chromium.org/6526031/diff/2002/generate_test_report.py
File generate_test_report.py (right):

http://codereview.chromium.org/6526031/diff/2002/generate_test_report.py#newc...
generate_test_report.py:119: crashes.append(match.group(1).split('\t')[0])
Autotest attaches the timetamp and a couple other things on the end of the
string.

On 2011/02/16 00:53:56, petkov wrote:
> what does this do? group(1) is the whole string, right? then split by \t, and
> [0] would be "Received crash notification..."?

http://codereview.chromium.org/6526031/diff/2002/generate_test_report.py#newc...
generate_test_report.py:226: print ''
I thought about this, but cmasone indicated he'd like a strong separation
between the test results and the crash results. I'm okay with interleaving them
if he has no objections.

On 2011/02/16 00:53:56, petkov wrote:
> Isn't it better to interleave the crash results into the main results table?
> Then you see the data for each test in one place (PASS/FAIL, perf, crashes...)

[Chris Masone, 2011-02-16 01:00:55]

If the crash results are associated with the tests, sheriffs will ping test
"owners" and not the owners of the crashing processes.  We see this now,
when the login tests report that they failed because Chrome crashed, or
because flimflam wouldn't respond to DBus calls...people still nag me about
it.

On Tue, Feb 15, 2011 at 4:59 PM, <dalecurtis@chromium.org> wrote:

>
> http://codereview.chromium.org/6526031/diff/2002/generate_test_report.py
> File generate_test_report.py (right):
>
>
>
http://codereview.chromium.org/6526031/diff/2002/generate_test_report.py#newc...
> generate_test_report.py:119:
> crashes.append(match.group(1).split('\t')[0])
> Autotest attaches the timetamp and a couple other things on the end of
> the string.
>
>
> On 2011/02/16 00:53:56, petkov wrote:
>
>> what does this do? group(1) is the whole string, right? then split by
>>
> \t, and
>
>> [0] would be "Received crash notification..."?
>>
>
>
>
http://codereview.chromium.org/6526031/diff/2002/generate_test_report.py#newc...
> generate_test_report.py:226: print ''
> I thought about this, but cmasone indicated he'd like a strong
> separation between the test results and the crash results. I'm okay with
> interleaving them if he has no objections.
>
>
> On 2011/02/16 00:53:56, petkov wrote:
>
>> Isn't it better to interleave the crash results into the main results
>>
> table?
>
>> Then you see the data for each test in one place (PASS/FAIL, perf,
>>
> crashes...)
>
> http://codereview.chromium.org/6526031/
>

[petkov, 2011-02-16 01:01:16]

http://codereview.chromium.org/6526031/diff/2002/generate_test_report.py
File generate_test_report.py (right):

http://codereview.chromium.org/6526031/diff/2002/generate_test_report.py#newc...
generate_test_report.py:119: crashes.append(match.group(1).split('\t')[0])
On 2011/02/16 00:59:00, dalec wrote:
> Autotest attaches the timetamp and a couple other things on the end of the
> string.

Sorry, I still don't get what this does... Can you copy/paste some sample
expected input and output? Thanks.

> 
> On 2011/02/16 00:53:56, petkov wrote:
> > what does this do? group(1) is the whole string, right? then split by \t,
and
> > [0] would be "Received crash notification..."?
>

[DaleCurtis, 2011-02-16 01:03:54]

http://codereview.chromium.org/6526031/diff/2002/generate_test_report.py
File generate_test_report.py (right):

http://codereview.chromium.org/6526031/diff/2002/generate_test_report.py#newc...
generate_test_report.py:119: crashes.append(match.group(1).split('\t')[0])
Line in status.log is this:
"INFO    desktopui_ChromeFirstRender     Received crash notification for
Xorg[9945] sig 11 (ignoring - no consent)       timestamp=1297813740   
localtime=Feb 15 15:49:00"

Regex returns:
"Received crash notification for Xorg[9945] sig 11 (ignoring - no consent)      
timestamp=1297813740    localtime=Feb 15 15:49:00"

We want:
"Received crash notification for Xorg[9945] sig 11 (ignoring - no consent)"

On 2011/02/16 01:01:17, petkov wrote:
> On 2011/02/16 00:59:00, dalec wrote:
> > Autotest attaches the timetamp and a couple other things on the end of the
> > string.
> 
> Sorry, I still don't get what this does... Can you copy/paste some sample
> expected input and output? Thanks.
> 
> > 
> > On 2011/02/16 00:53:56, petkov wrote:
> > > what does this do? group(1) is the whole string, right? then split by \t,
> and
> > > [0] would be "Received crash notification..."?
> > 
>

[petkov, 2011-02-16 01:04:02]

On 2011/02/16 01:00:55, Chris Masone wrote:
> If the crash results are associated with the tests, sheriffs will ping test
> "owners" and not the owners of the crashing processes.  We see this now,
> when the login tests report that they failed because Chrome crashed, or
> because flimflam wouldn't respond to DBus calls...people still nag me about
> it.

But isn't it still useful to find out during which test the crash occurred? It
seems the current report hides this info. Anything wrong with:

TestName-1           PASS
  perf-key-1         123
  perf-key-2         111
  crash-1
  crash-2
TestName-2           PASS
  ...

> 
> On Tue, Feb 15, 2011 at 4:59 PM, <mailto:dalecurtis@chromium.org> wrote:
> 
> >
> > http://codereview.chromium.org/6526031/diff/2002/generate_test_report.py
> > File generate_test_report.py (right):
> >
> >
> >
>
http://codereview.chromium.org/6526031/diff/2002/generate_test_report.py#newc...
> > generate_test_report.py:119:
> > crashes.append(match.group(1).split('\t')[0])
> > Autotest attaches the timetamp and a couple other things on the end of
> > the string.
> >
> >
> > On 2011/02/16 00:53:56, petkov wrote:
> >
> >> what does this do? group(1) is the whole string, right? then split by
> >>
> > \t, and
> >
> >> [0] would be "Received crash notification..."?
> >>
> >
> >
> >
>
http://codereview.chromium.org/6526031/diff/2002/generate_test_report.py#newc...
> > generate_test_report.py:226: print ''
> > I thought about this, but cmasone indicated he'd like a strong
> > separation between the test results and the crash results. I'm okay with
> > interleaving them if he has no objections.
> >
> >
> > On 2011/02/16 00:53:56, petkov wrote:
> >
> >> Isn't it better to interleave the crash results into the main results
> >>
> > table?
> >
> >> Then you see the data for each test in one place (PASS/FAIL, perf,
> >>
> > crashes...)
> >
> > http://codereview.chromium.org/6526031/
> >

[petkov, 2011-02-16 01:06:03]

http://codereview.chromium.org/6526031/diff/2002/generate_test_report.py
File generate_test_report.py (right):

http://codereview.chromium.org/6526031/diff/2002/generate_test_report.py#newc...
generate_test_report.py:119: crashes.append(match.group(1).split('\t')[0])
On 2011/02/16 01:03:54, dalec wrote:
> Line in status.log is this:
> "INFO    desktopui_ChromeFirstRender     Received crash notification for
> Xorg[9945] sig 11 (ignoring - no consent)       timestamp=1297813740   
> localtime=Feb 15 15:49:00"
> 
> Regex returns:
> "Received crash notification for Xorg[9945] sig 11 (ignoring - no consent)    
 
> timestamp=1297813740    localtime=Feb 15 15:49:00"
> 
> We want:
> "Received crash notification for Xorg[9945] sig 11 (ignoring - no consent)"
> 
> On 2011/02/16 01:01:17, petkov wrote:
> > On 2011/02/16 00:59:00, dalec wrote:
> > > Autotest attaches the timetamp and a couple other things on the end of the
> > > string.
> > 
> > Sorry, I still don't get what this does... Can you copy/paste some sample
> > expected input and output? Thanks.
> > 
> > > 
> > > On 2011/02/16 00:53:56, petkov wrote:
> > > > what does this do? group(1) is the whole string, right? then split by
\t,
> > and
> > > > [0] would be "Received crash notification..."?
> > > 
> > 
> 

Thanks. It seems "Received crash notification for " is verbose and redundant.
Maybe replace with just "crash".
Also, (ignoring - no consent) is redundant.

[DaleCurtis, 2011-02-16 01:09:34]

I can trim the message, but I was trying to keep the text as close to what's in
/var/log/messages for recognizability. If you think it's clearer trimmed, I'll
do so.

On 2011/02/16 01:06:03, petkov wrote:
> http://codereview.chromium.org/6526031/diff/2002/generate_test_report.py
> File generate_test_report.py (right):
> 
>
http://codereview.chromium.org/6526031/diff/2002/generate_test_report.py#newc...
> generate_test_report.py:119: crashes.append(match.group(1).split('\t')[0])
> On 2011/02/16 01:03:54, dalec wrote:
> > Line in status.log is this:
> > "INFO    desktopui_ChromeFirstRender     Received crash notification for
> > Xorg[9945] sig 11 (ignoring - no consent)       timestamp=1297813740   
> > localtime=Feb 15 15:49:00"
> > 
> > Regex returns:
> > "Received crash notification for Xorg[9945] sig 11 (ignoring - no consent)  
 
>  
> > timestamp=1297813740    localtime=Feb 15 15:49:00"
> > 
> > We want:
> > "Received crash notification for Xorg[9945] sig 11 (ignoring - no consent)"
> > 
> > On 2011/02/16 01:01:17, petkov wrote:
> > > On 2011/02/16 00:59:00, dalec wrote:
> > > > Autotest attaches the timetamp and a couple other things on the end of
the
> > > > string.
> > > 
> > > Sorry, I still don't get what this does... Can you copy/paste some sample
> > > expected input and output? Thanks.
> > > 
> > > > 
> > > > On 2011/02/16 00:53:56, petkov wrote:
> > > > > what does this do? group(1) is the whole string, right? then split by
> \t,
> > > and
> > > > > [0] would be "Received crash notification..."?
> > > > 
> > > 
> > 
> 
> Thanks. It seems "Received crash notification for " is verbose and redundant.
> Maybe replace with just "crash".
> Also, (ignoring - no consent) is redundant.

[petkov, 2011-02-16 01:11:53]

On 2011/02/16 01:09:34, dalec wrote:
> I can trim the message, but I was trying to keep the text as close to what's
in
> /var/log/messages for recognizability. If you think it's clearer trimmed, I'll
> do so.

I don't see any benefit in the extra redundant verbosity. The point of this
report is to provide a concise and clear summary of what happened during the
test run. The shorter the better.

> 
> On 2011/02/16 01:06:03, petkov wrote:
> > http://codereview.chromium.org/6526031/diff/2002/generate_test_report.py
> > File generate_test_report.py (right):
> > 
> >
>
http://codereview.chromium.org/6526031/diff/2002/generate_test_report.py#newc...
> > generate_test_report.py:119: crashes.append(match.group(1).split('\t')[0])
> > On 2011/02/16 01:03:54, dalec wrote:
> > > Line in status.log is this:
> > > "INFO    desktopui_ChromeFirstRender     Received crash notification for
> > > Xorg[9945] sig 11 (ignoring - no consent)       timestamp=1297813740   
> > > localtime=Feb 15 15:49:00"
> > > 
> > > Regex returns:
> > > "Received crash notification for Xorg[9945] sig 11 (ignoring - no consent)
 
>  
> >  
> > > timestamp=1297813740    localtime=Feb 15 15:49:00"
> > > 
> > > We want:
> > > "Received crash notification for Xorg[9945] sig 11 (ignoring - no
consent)"
> > > 
> > > On 2011/02/16 01:01:17, petkov wrote:
> > > > On 2011/02/16 00:59:00, dalec wrote:
> > > > > Autotest attaches the timetamp and a couple other things on the end of
> the
> > > > > string.
> > > > 
> > > > Sorry, I still don't get what this does... Can you copy/paste some
sample
> > > > expected input and output? Thanks.
> > > > 
> > > > > 
> > > > > On 2011/02/16 00:53:56, petkov wrote:
> > > > > > what does this do? group(1) is the whole string, right? then split
by
> > \t,
> > > > and
> > > > > > [0] would be "Received crash notification..."?
> > > > > 
> > > > 
> > > 
> > 
> > Thanks. It seems "Received crash notification for " is verbose and
redundant.
> > Maybe replace with just "crash".
> > Also, (ignoring - no consent) is redundant.

[DaleCurtis, 2011-02-16 01:18:49]

Changed, new log message is:

Crashes detected during testing:
-------------------------------------------------------------
desktopui_ChromeFirstRender/desktopui_ChromeFirstRender
  Crash: Xorg[7400] sig 11
  Crash: Xorg[9945] sig 11
-------------------------------------------------------------
Total crashes: 2

http://codereview.chromium.org/6526031/diff/2002/generate_test_report.py
File generate_test_report.py (right):

http://codereview.chromium.org/6526031/diff/2002/generate_test_report.py#newc...
generate_test_report.py:119: crashes.append(match.group(1).split('\t')[0])
On 2011/02/16 01:06:03, petkov wrote:
> On 2011/02/16 01:03:54, dalec wrote:
> > Line in status.log is this:
> > "INFO    desktopui_ChromeFirstRender     Received crash notification for
> > Xorg[9945] sig 11 (ignoring - no consent)       timestamp=1297813740   
> > localtime=Feb 15 15:49:00"
> > 
> > Regex returns:
> > "Received crash notification for Xorg[9945] sig 11 (ignoring - no consent)  
 
>  
> > timestamp=1297813740    localtime=Feb 15 15:49:00"
> > 
> > We want:
> > "Received crash notification for Xorg[9945] sig 11 (ignoring - no consent)"
> > 
> > On 2011/02/16 01:01:17, petkov wrote:
> > > On 2011/02/16 00:59:00, dalec wrote:
> > > > Autotest attaches the timetamp and a couple other things on the end of
the
> > > > string.
> > > 
> > > Sorry, I still don't get what this does... Can you copy/paste some sample
> > > expected input and output? Thanks.
> > > 
> > > > 
> > > > On 2011/02/16 00:53:56, petkov wrote:
> > > > > what does this do? group(1) is the whole string, right? then split by
> \t,
> > > and
> > > > > [0] would be "Received crash notification..."?
> > > > 
> > > 
> > 
> 
> Thanks. It seems "Received crash notification for " is verbose and redundant.
> Maybe replace with just "crash".
> Also, (ignoring - no consent) is redundant.

Done.

[petkov, 2011-02-16 01:20:41]

Thanks much. I would still like to see the crashes interleaved into the main
report unless cmasone feels strongly against it.

[Chris Masone, 2011-02-16 01:22:48]

I feel strongly against it :-)

The output Dale showed me seemed to gather all the crashes at the end, and
still call out which test caused them.

On Tue, Feb 15, 2011 at 5:20 PM, <petkov@chromium.org> wrote:

> Thanks much. I would still like to see the crashes interleaved into the
> main
> report unless cmasone feels strongly against it.
>
>
> http://codereview.chromium.org/6526031/
>

[petkov, 2011-02-16 01:26:36]

On 2011/02/16 01:22:48, Chris Masone wrote:
> I feel strongly against it :-)

I don't think this will achieve what you want -- test owners not being bothered.
And it just increases the verbosity.

An alternative is to group the crash report by crashing process -- and then list
the tests that expose the crash. This may be closer to what you want -- it
focuses on the crashing process rather than the test.

> 
> The output Dale showed me seemed to gather all the crashes at the end, and
> still call out which test caused them.
> 
> On Tue, Feb 15, 2011 at 5:20 PM, <mailto:petkov@chromium.org> wrote:
> 
> > Thanks much. I would still like to see the crashes interleaved into the
> > main
> > report unless cmasone feels strongly against it.
> >
> >
> > http://codereview.chromium.org/6526031/
> >

[Chris Masone, 2011-02-16 02:09:41]

On 2011/02/16 01:26:36, petkov wrote:
> On 2011/02/16 01:22:48, Chris Masone wrote:
> > I feel strongly against it :-)
> 
> I don't think this will achieve what you want -- test owners not being
bothered.
> And it just increases the verbosity.
> 
> An alternative is to group the crash report by crashing process -- and then
list
> the tests that expose the crash. This may be closer to what you want -- it
> focuses on the crashing process rather than the test.

Oh, I'd support that :-)  Can we do that?

> 
> > 
> > The output Dale showed me seemed to gather all the crashes at the end, and
> > still call out which test caused them.
> > 
> > On Tue, Feb 15, 2011 at 5:20 PM, <mailto:petkov@chromium.org> wrote:
> > 
> > > Thanks much. I would still like to see the crashes interleaved into the
> > > main
> > > report unless cmasone feels strongly against it.
> > >
> > >
> > > http://codereview.chromium.org/6526031/
> > >

[petkov, 2011-02-16 03:46:54]

LGTM

Thanks!

http://codereview.chromium.org/6526031/diff/3006/generate_test_report.py
File generate_test_report.py (right):

http://codereview.chromium.org/6526031/diff/3006/generate_test_report.py#newc...
generate_test_report.py:217: if result['crashes'] and not test == tests[0]:
isn't this test != tests[0]?

this filter is a bit hacky but i don't have any better suggestions...

[Chris Masone, 2011-02-16 04:23:11]

Thanks for sticking to this, Dale :-)

Lgtm too
On Feb 15, 2011 7:46 PM, <petkov@chromium.org> wrote:
> LGTM
>
> Thanks!
>
>
> http://codereview.chromium.org/6526031/diff/3006/generate_test_report.py
> File generate_test_report.py (right):
>
>
http://codereview.chromium.org/6526031/diff/3006/generate_test_report.py#newc...
> generate_test_report.py:217: if result['crashes'] and not test ==
> tests[0]:
> isn't this test != tests[0]?
>
> this filter is a bit hacky but i don't have any better suggestions...
>
> http://codereview.chromium.org/6526031/

[petkov, 2011-02-16 08:17:40]

http://codereview.chromium.org/6526031/diff/3006/generate_test_report.py
File generate_test_report.py (right):

http://codereview.chromium.org/6526031/diff/3006/generate_test_report.py#newc...
generate_test_report.py:117: regex = re.compile('Received crash notification for
(\w+).+ (sig \d+)')
btw, for the process name, you probably want to cover '-' too.
maybe \S+ instead of \w+?

[DaleCurtis, 2011-02-16 19:59:16]

Thanks for the reviews guys. I soaked it through another 10 smokes on real
hardware. Pushing now. I'll keep an eye on PFQ.

http://codereview.chromium.org/6526031/diff/3006/generate_test_report.py
File generate_test_report.py (right):

http://codereview.chromium.org/6526031/diff/3006/generate_test_report.py#newc...
generate_test_report.py:117: regex = re.compile('Received crash notification for
(\w+).+ (sig \d+)')
\S+ would grab the process id and such too. Switched to [-\w]+

On 2011/02/16 08:17:40, petkov wrote:
> btw, for the process name, you probably want to cover '-' too.
> maybe \S+ instead of \w+?

http://codereview.chromium.org/6526031/diff/3006/generate_test_report.py#newc...
generate_test_report.py:217: if result['crashes'] and not test == tests[0]:
Yup, changed. Python has me losing sense of basic operators.

On 2011/02/16 03:46:54, petkov wrote:
> isn't this test != tests[0]?
> 
> this filter is a bit hacky but i don't have any better suggestions...