796219 - Marionette issue not turning builds orange on autolog

Status: RESOLVED FIXED

(Remote Protocol :: Marionette, defect)

Description

[cmtalbert]

We have a issue on autolog where the tests appear to be green, but when you click on them you find out that marionette is throwing an exception.

There are two problems here:
1. Marionette is throwing an exception. This might be the issue that jgriffin was tracking down earlier today that just hasn't propagated up to the code that autolog is running.
2. The test shouldn't be green if no tests actually ran. :(

See the following log snippet from this log: http://brasstacks.mozilla.com/autologserver/showlog?file=bdbd4796-0bd0-11e2-ae82-12313d2924ca.txt.gz
INFO | runtests.py | Installing extension at /data/jenkins/workspace/mochitest/objdir-gecko/_tests/testing/mochitest/extensions/workerbootstrap to /tmp/tmpbdVReG.
INFO | runtests.py | Installing extension at /data/jenkins/workspace/mochitest/objdir-gecko/_tests/testing/mochitest/extensions/worker to /tmp/tmpbdVReG.
args: ['/data/jenkins/workspace/mochitest/xulrunner/xpcshell', '-g', '/data/jenkins/workspace/mochitest/xulrunner', '-v', '170', '-f', './httpd.js', '-e', "const _PROFILE_PATH = '/tmp/tmpKVQbPC';const _SERVER_PORT = '8888'; const _SERVER_ADDR = '10.0.2.2';\n                     const _TEST_PREFIX = undefined; const _DISPLAY_RESULTS = false;", '-f', './server.js']
INFO | runtests.py | Server pid: 9116
rm failed for /data/local/tests/profile, No such file or directory
2 KB/s (114 bytes in 0.047s)
239 KB/s (14727 bytes in 0.059s)
4 KB/s (253 bytes in 0.053s)
79 KB/s (7168 bytes in 0.088s)
38 KB/s (1726 bytes in 0.043s)
8 KB/s (413 bytes in 0.047s)
7 KB/s (373 bytes in 0.047s)
8 KB/s (413 bytes in 0.047s)
8 KB/s (413 bytes in 0.047s)
8 KB/s (369 bytes in 0.043s)
6 KB/s (393 bytes in 0.055s)
9 KB/s (417 bytes in 0.043s)
12 KB/s (679 bytes in 0.051s)
1 KB/s (51 bytes in 0.042s)
758 KB/s (276410 bytes in 0.355s)
72 KB/s (3850 bytes in 0.051s)
2 KB/s (172 bytes in 0.056s)
15 KB/s (748 bytes in 0.047s)
2 KB/s (172 bytes in 0.081s)
10 KB/s (692 bytes in 0.063s)
1 KB/s (80 bytes in 0.063s)
4 KB/s (214 bytes in 0.044s)
0 KB/s (26 bytes in 0.078s)
57 KB/s (3174 bytes in 0.053s)
5 KB/s (302 bytes in 0.055s)
/data/local/user.js: cannot open for read: No such file or directory
129 KB/s (14727 bytes in 0.110s)
2 KB/s (103 bytes in 0.046s)
1 KB/s (94 bytes in 0.051s)
INFO | runtests.py | Running tests: start.

MOZPROCESS WARNING: ProcessHandler.waitForFinish() is deprecated, use ProcessHandler.wait() instead
INFO | runtests.py | Received unexpected exception while running application
Traceback (most recent call last):
  File "/data/jenkins/workspace/mochitest/objdir-gecko/_tests/testing/mochitest/runtests.py", line 731, in runTests
    timeout = timeout)
  File "/data/jenkins/workspace/mochitest/objdir-gecko/_tests/testing/mochitest/automation.py", line 1012, in runApp
    stderr = subprocess.STDOUT)
  File "/data/jenkins/workspace/mochitest/objdir-gecko/_tests/testing/mochitest/b2gautomation.py", line 245, in Process
    session = self.marionette.start_session()
  File "/data/jenkins/workspace/mochitest/venv/src/marionette/marionette/marionette.py", line 237, in start_session
    self.session = self._send_message('newSession', 'value')
  File "/data/jenkins/workspace/mochitest/venv/src/marionette/marionette/marionette.py", line 169, in _send_message
    self._handle_error(response)
  File "/data/jenkins/workspace/mochitest/venv/src/marionette/marionette/marionette.py", line 227, in _handle_error
    raise MarionetteException(message=response, status=500)
MarionetteException: {u'ok': True, u'from': u'conn1.marionette1'}
WARNING | automationutils.processLeakLog() | refcount logging is off, so leaks can't be detected!

INFO | runtests.py | Running tests: end.

Comment 1

[Jonathan Griffin (:jgriffin)]

We use https://github.com/jonallengriffin/b2gautomation/blob/master/b2gautomation/mochilog.py to parse the Jenkins mochitest log before posting to autolog, which in turn uses the logparser (http://hg.mozilla.org/automation/logparser/).

The mochitest logparser doesn't know anything about Python exceptions (it only understands TEST-UNEXPECTED-FAIL and the like), so when a test run suffers an infrastructure exception like this, it just sees that 0 tests ran.

We could fix this either by updating the logparser to understand Python exceptions (http://hg.mozilla.org/automation/logparser/file/025da2685aeb/logparser/testsuiteparser.py), or by updating mochilog.py in a similar fashion.

Comment 2

[Gregory Szorc [:gps]]

Attachment: Detect runtests.py exceptions, v1

I have no clue if this is good enough. The output of parselogs.py with the example log in the bug is:

{
  "failures": [
    {
      "test": "Shutdown", 
      "failures": [
        {
          "status": "PROCESS-CRASH", 
          "text": "INFO | runtests.py | Received unexpected exception while running application"
        }
      ]
    }
  ], 
  "filename": "mochitest-python-exception.log.gz", 
  "id": "73046b16248a4c9a78f5c55af5a1bac39f64e732", 
  "testfailure_count": 1
}

I suppose I could add in more parsing of tracebacks, etc. Is that really needed? Or, will things magically link to the right location in the full log? I have no clue how all this stuff works.

Comment 3

[Jonathan Griffin (:jgriffin)]

Comment on attachment 670057 [details] [diff] [review]
Detect runtests.py exceptions, v1

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

Thanks!  Yes, this is enough to cause these runs to show as failed in autolog.

Comment 4

[Gregory Szorc [:gps]]

https://hg.mozilla.org/automation/logparser/rev/4d455c780ddc

I'm not sure what the deploy and bug closing procedure is. Over to jgriffin for further action.

Comment 5

[Jonathan Griffin (:jgriffin)]

(In reply to Gregory Szorc [:gps] from comment #4)
> https://hg.mozilla.org/automation/logparser/rev/4d455c780ddc
> 
> I'm not sure what the deploy and bug closing procedure is. Over to jgriffin
> for further action.

I need to do the equivalent of a clobber on the Jenkins slaves running the automation, which I'll do now.