759988 - Log order is confused

Status: RESOLVED INCOMPLETE

(Testing Graveyard :: Peptest, defect)

Description

[Mark Côté [:mcote]]

On Windows XP, at least, I often see the following, and similar errors, 

PEP TEST-END | test_openWindow.js | finished in: 237 ms
Exception in thread Thread-3:
Traceback (most recent call last):
  File "c:\mozilla-build\python\Lib\threading.py", line 552, in __bootstrap_inner
    self.run()
  File "c:\Documents and Settings\mcote\peptest\lib\site-packages\mozrunner-5.5-py2.7.egg\mozrunner\runner.py", line 270, in run
    self.ph.waitForFinish()
  File "c:\Documents and Settings\mcote\peptest\lib\site-packages\mozprocess-0.1b2-py2.7.egg\mozprocess\processhandler.py", line 600, in waitForFinish
    self.processOutputLine(line.rstrip())
  File "c:\documents and settings\mcote\peptest\src\peptest\peptest\pepprocess.py", line 103, in processOutputLine
    ' | unresponsive time: ' + tokens[3].rstrip() + ' ms')
TypeError: unsupported operand type(s) for +: 'NoneType' and 'str'

It seems that currentAction, or sometimes currentTest, is not defined because we are in between tests. There are a few varieties of this error, and strangely sometimes there is no stack trace printed, just the TypeError.

Comment 1

[Mark Côté [:mcote]]

Okay seems that the problem is that, at least on my WinXP VM, the log order is strange:

MOZ_EVENT_TRACE start 1338437917132
MOZ_EVENT_TRACE sample 1338437917304 646
MOZ_EVENT_TRACE sample 1338437917491 654
MOZ_EVENT_TRACE sample 1338437917679 662
MOZ_EVENT_TRACE sample 1338437917741 243
PEP ACTION-START test_openWindow.js open_window
PEP TEST-START test_openWindow.js

PEP DEBUG MOZMILL pass {"function":"MozMillElement.keypress()"}
MOZ_EVENT_TRACE sample 1338437917991 400
PEP ACTION-END test_openWindow.js open_window
PEP TEST-END test_openWindow.js 251
MOZ_EVENT_TRACE sample 1338437918101 421
MOZ_EVENT_TRACE sample 1338437918694 186
PEP ACTION-START test_resizeWindow.js resize_by
PEP TEST-START test_resizeWindow.js
PEP ACTION-START test_resizeWindow.js resize_to
PEP ACTION-END test_resizeWindow.js resize_by
PEP TEST-END test_resizeWindow.js 409
PEP ACTION-END test_resizeWindow.js resize_to

Here we see that the ACTION-START for the "resize_by" action of the test "test_resizeWindow.js" actually occurs before the TEST-START. Also, the "resize_to" and "resize_by" actions are interleaved, which PepProcess is not expecting.