828324 - mozcrash output is not TBPL-starrable & the PROCESS-CRASH/stackwalk lines can end up interleaved

Status: RESOLVED FIXED

(Testing :: Mozbase, defect)

Description

[Ed Morley [:emorley]]

With bug 813132 in production, I've just seen:

{
FIRE PROC: ' "MOZ_CRASHREPORTER_SHUTDOWN=1,MOZ_CRASHREPORTER_NO_REPORT=1,NO_EM_RESTART=1" org.mozilla.fennec  -profile /mnt/sdcard/tests/profile -tp file:/mnt/sdcard/tests/svg.manifest -tpnoisy -tpcycles 3 -tppagecycles 1 -tpdelay 1000'
getting files in '/mnt/sdcard/tests/profile/minidumps/'
Crash dump filename: /tmp/tmpfd1iC9/4d377dbf-7a54-d335-3649b455-23409abd.dmp
Operating system: Android
                  0.0.0 Linux 3.2.0+ #2 SMP PREEMPT Thu Nov 29 08:06:57 EST 2012 armv7l pandaboard/pandaboard/pandaboard:4.0.4/IMM76I/5:eng/test-keys
CPU: arm
     0 CPUs

Crash reason:  SIGSEGV
Crash address: 0xbec937a0

Thread 11 (crashed)
 0  libnss3.so!nssCertificate_Destroy [certificate.c : 102 + 0x0]
     r4 = 0xbec9374c    r5 = 0x629fb680    r6 = 0x00000000    r7 = 0x5d6ff90c
     r8 = 0x604aa6d9    r9 = 0x64860400   r10 = 0x00000008    fp = 0x00000010

...
...
...

32  dalvik-heap (deleted) + 0x7d665e
     sp = 0x5d6ffcbc    pc = 0x4135f660
    Found by: stack scanning
33  libdvm.so + 0x8fb77
     sp = 0x5d6ffcc8    pc = 0x409a6b79
    Found by: stack scanning
34  dalvik-heap (deleted) + 0x7e2efe
     sp = 0x5d6ffccc    pc = 0x4136bf00
    Found by: stack scanning
35  data@app@orgmozcrash ERROR | PROCESS-CRASH | ttest.py | application crashed [@ nssCertificate_Destroy]
[e-mail] + 0x178244
     sp = 0x5d6ffcd0    pc = 0x5ba77246
    Found by: stack scanning
}

This is presumably due to mixing print and log.error, and logging being bufferd.

  148 	log.error("PROCESS-CRASH | %s | application crashed [%s]", test_name, top_frame)
  149 	print '\n'.join(stackwalk_output)

at https://github.com/mozilla/mozbase/blob/492a08a51e2c2f6b9911cca45094e4291ee162c4/mozcrash/mozcrash/mozcrash.py#L148

We should just make this both print, and then we'd also avoid the "ERROR | " breaking TBPL parsing (yeah I can adjust the TBPL regexes for these, but it still bloats the annotated summary output to the point where it is more likely to wrap onto another line).

Comment 1

[Ed Morley [:emorley]]

Log in question where this occurred was:
https://tbpl.mozilla.org/php/getParsedLog.php?id=18629740&full=1&branch=mozilla-inbound#error0

Comment 2

[Ed Morley [:emorley]]

Attachment: Patch v1

Comment 3

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

Comment on attachment 699982 [details] [diff] [review]
Patch v1

Review of attachment 699982 [details] [diff] [review]:
-----------------------------------------------------------------

should we remove the rest of the log.*() calls in mozcrash.py?

Comment 4

[Ed Morley [:emorley]]

(In reply to Joel Maher (:jmaher) from comment #3)
> should we remove the rest of the log.*() calls in mozcrash.py?

Maybe...

Ted?

Comment 5

[(not currently active) Ted Mielczarek]

Is this only an issue with log.error? (Is log.error going to stderr and the rest to stdout?)

This is the first time I've seen something like that on non-Windows. I thought everything else was line-buffered?

Comment 6

[Ed Morley [:emorley]]

It might be, yeah.

Either way, I think print is the correct decision here for now.

I've landed bug 829092 in the meantime so TBPL matches against these lines, even with the "mozcrash ERROR |" prefix - but that still doesn't fully fix things, since TBPL expects (since every other suite uses this format):
"failure-type | test-name | message"
...so the extra pipe breaks it.

If we decide in the future that (a) we've happy to remove the prefix from mozlog, and (b) we're going to debug the interleaving here - then we can always switch this back to log.error

Comment 7

[Ed Morley [:emorley]]

https://github.com/mozilla/mozbase/commit/80752fd0f0d3887f2c563a27c03e9a2624cccf70

Comment 8

[Ed Morley [:emorley]]

philor/Ryan, once the dependencies are fixed, will mean the talos crashes (hopefully) get a starable crash signature :-)

Comment 10

[Ed Morley [:emorley]]

Working fine on inbound :-)

Comment 11

[Jeff Hammel]

This can (and should) be fixed from logging.  I'm not entirely sure how, but see http://docs.python.org/2/library/logging.handlers.html .

Comment 12

[Ed Morley [:emorley]]

(In reply to Jeff Hammel [:jhammel] from comment #11)
> This can (and should) be fixed from logging.  I'm not entirely sure how, but
> see http://docs.python.org/2/library/logging.handlers.html .

Broken out to bug 926407.