813858 - Intermittent robocop shutdown failure with no summary, ending in Warning: cleaning up pidfile '/builds/tegra-060/test/../runtestsremote.pid' was unsuccessful from the test harness

Status: RESOLVED DUPLICATE of bug 814496

(Testing :: General, defect)

Description

[Phil Ringnalda (:philor)]

Don't really know whether this is a formerly-hidden shutdown crash now sort of hidden but managing to turn the run orange, or bustage from bug 812135/bug 808410, or something I'm not even noticing.

https://tbpl.mozilla.org/php/getParsedLog.php?id=17215767&tree=Mozilla-Inbound
Android no-ionmonkey Tegra 250 mozilla-inbound opt test robocop on 2012-11-20 10:38:54 PST for push 9195d74558f7
slave: tegra-060

10 INFO SimpleTest FINISHED
INFO | automation.py | Application ran for: 0:00:48.281564
INFO | automation.py | Reading PID log: /tmp/tmpRc36G6pidlog
getting files in '/mnt/sdcard/tests/profile/minidumps/'
WARNING | automationutils.processLeakLog() | refcount logging is off, so leaks can't be detected!

INFO | runtests.py | Running tests: end.
removing file: /mnt/sdcard/tests/logs/mochitest.log
Warning: cleaning up pidfile '/builds/tegra-060/test/../runtestsremote.pid' was unsuccessful from the test harness

Comment 1

[Phil Ringnalda (:philor)]

https://tbpl.mozilla.org/php/getParsedLog.php?id=17223192&tree=Mozilla-Inbound
https://tbpl.mozilla.org/php/getParsedLog.php?id=17224676&tree=Mozilla-Inbound

Comment 2

[Phil Ringnalda (:philor)]

https://tbpl.mozilla.org/php/getParsedLog.php?id=17231697&tree=Firefox

Comment 3

[Ed Morley [:emorley]]

https://tbpl.mozilla.org/php/getParsedLog.php?id=17235985&tree=Mozilla-Inbound

Comment 4

[Ed Morley [:emorley]]

(In reply to Phil Ringnalda (:philor) from comment #0)
> Don't really know whether this is a formerly-hidden shutdown crash now sort
> of hidden but managing to turn the run orange, or bustage from bug
> 812135/bug 808410, or something I'm not even noticing.

I believe this was an already-occurring issue that we'd previously been hiding, now brought to light by bug 808410 patch part 2, since we're not clobbering the return code after each run.

Geoff, I don't suppose you can see something in any of the logs that suggests why the return code from one of the individual test runs returned as non-zero?

I guess we could also print the return code after each iteration, to aid debugging this kind of thing.

Comment 5

[Geoff Brown [:gbrown]]

(In reply to Ed Morley [:edmorley UTC+0] from comment #4)
> Geoff, I don't suppose you can see something in any of the logs that
> suggests why the return code from one of the individual test runs returned
> as non-zero?

It takes some searching, but yes, there are errors visible. In at least 2 of the logs I found:

ERROR: Unable to parse process list (bug 805969)

Comment 6

[Ed Morley [:emorley]]

(In reply to Geoff Brown [:gbrown] from comment #5)
> It takes some searching, but yes, there are errors visible. In at least 2 of
> the logs I found:
> 
> ERROR: Unable to parse process list (bug 805969)

Ah thank you :-)

I wonder if Will would mind having those as "Automation Error", so TBPL's parser can see them...? Or else some other common prefix we can add to the TBPL regex list, that is less likely to get false positives than "ERROR:" (you laugh, but I'm sure we'll match against that during the desktop testsuites for a variety of things).

Comment 7

[Geoff Brown [:gbrown]]

I confirmed that all of the logs reported here have the bug 805969 message. Here's a sample:

pushing directory: /tmp/tmpWffKNd to /mnt/sdcard/tests/profile
INFO | runtests.py | Running tests: start.

FIRE PROC: '"MOZ_CRASHREPORTER=1,XPCOM_DEBUG_BREAK=stack,MOZ_CRASHREPORTER_NO_REPORT=1,NO_EM_RESTART=1,MOZ_PROCESS_LOG=/tmp/tmpWndNDHpidlog,XPCOM_MEM_BLOAT_LOG=/mnt/sdcard/tests/profile/runtests_leaks.log" am instrument -w -e deviceroot /mnt/sdcard/tests -e class org.mozilla.fennec.tests.testAboutPage org.mozilla.roboexample.test/org.mozilla.fennec.FennecInstrumentationTestRunner'
ERROR: Unable to parse process list (bug 805969)
Line: .
Full output of process list:
.
Test results for FennecInstrumentationTestRunner=.
Time: 39.59

OK (1 test)


10031	1513	com.mozilla.SUTAgentAndroid
10007	1215	com.android.inputmethod.latin
1001	1224	com.android.phone
1000	1020	system
10026	1614	com.svox.pico
10028	1601	com.android.defcontainer
10029	1344	com.android.deskclock
10034	1536	org.mozilla.ffxcp
10018	1231	com.android.launcher
10013	1486	com.cooliris.media
10004	1400	android.process.media
10009	1442	com.android.quicksearchbox
10002	1478	com.android.music
10032	1432	com.mozilla.watcher
10006	1413	com.android.mms
10010	1386	com.android.providers.calendar
10014	1370	com.android.email
10017	1359	com.android.bluetooth
1000	1243	com.android.settings
10015	1265	android.process.acore
INFO | runtests.py | Received unexpected exception while running application
Traceback (most recent call last):
  File "/builds/tegra-209/test/build/tests/mochitest/runtests.py", line 731, in runTests
    timeout = timeout)
  File "/builds/tegra-209/test/build/tests/mochitest/automation.py", line 1051, in runApp
    stderr = subprocess.STDOUT)
  File "/builds/tegra-209/test/build/tests/mochitest/remoteautomation.py", line 133, in Process
    return self.RProcess(self._devicemanager, cmd, stdout, stderr, env, cwd)
  File "/builds/tegra-209/test/build/tests/mochitest/remoteautomation.py", line 143, in __init__
    self.proc = dm.launchProcess(cmd, stdout, cwd, env, True)
  File "/builds/tegra-209/test/build/tests/mochitest/devicemanagerSUT.py", line 524, in launchProcess
    self.fireProcess(cmdline, failIfRunning)
  File "/builds/tegra-209/test/build/tests/mochitest/devicemanagerSUT.py", line 491, in fireProcess
    pid = self.processExist(appname)
  File "/builds/tegra-209/test/build/tests/mochitest/devicemanager.py", line 177, in processExist
    procList = self.getProcessList()
  File "/builds/tegra-209/test/build/tests/mochitest/devicemanagerSUT.py", line 465, in getProcessList
    raise DMError("Invalid process line: %s" % line)
DMError: Invalid process line: .
WARNING | automationutils.processLeakLog() | refcount logging is off, so leaks can't be detected!

INFO | runtests.py | Running tests: end.
removing file: /mnt/sdcard/tests/logs/mochitest.log
Warning: cleaning up pidfile '/builds/tegra-209/test/../runtestsremote.pid' was unsuccessful from the test harness
removing file: /mnt/sdcard/tests/robotium.config
INFO | runtests.py | Installing extension at /builds/tegra-209/test/build/tests/mochitest/extensions/[e-mail] to /tmp/tmpWffKNd.
INFO | runtests.py | Installing extension at /builds/tegra-209/test/build/tests/mochitest/extensions/specialpowers to /tmp/tmpWffKNd.
INFO | runtests.py | Installing extension at /builds/tegra-209/test/build/tests/mochitest/extensions/worker to /tmp/tmpWffKNd.
INFO | runtests.py | Installing extension at /builds/tegra-209/test/build/tests/mochitest/extensions/workerbootstrap to /tmp/tmpWffKNd.
pushing directory: /tmp/tmpWffKNd to /mnt/sdcard/tests/profile
args: ['/builds/tegra-209/test/build/hostutils/bin/xpcshell', '-g', '/builds/tegra-209/test/build/hostutils/xre', '-v', '170', '-f', './httpd.js', '-e', "const _PROFILE_PATH = '/tmp/tmpNrTftI';const _SERVER_PORT = '30209'; const _SERVER_ADDR = '10.250.48.220';\n                     const _TEST_PREFIX = undefined; const _DISPLAY_RESULTS = false;", '-f', './server.js']
INFO | runtests.py | Server pid: 5284
pushing directory: /tmp/tmpWffKNd to /mnt/sdcard/tests/profile
INFO | runtests.py | Running tests: start.

Comment 8

[Geoff Brown [:gbrown]]

Hypothesis: The text
------
.
Test results for FennecInstrumentationTestRunner=.
Time: 39.59

OK (1 test)


------
is being returned from sutAgent for another command (launching robocop?) and somehow getting mixed up with the response for the 'ps' command.

Comment 9

[Geoff Brown [:gbrown]]

I was able to reproduce this once, locally, with extra logging. The corrupt response to 'ps' was received after some timeouts on a long-running testBrowserProvider.

Comment 10

[Geoff Brown [:gbrown]]

Incidentally, I checked and testBrowserProvider normally takes under 200 s, and most rc tests take less than 50 s, so there may be another bug behind this one which is causing tests to occasionally take much longer than usual to execute.

Comment 11

[Geoff Brown [:gbrown]]

Haven't seen this or related problems since bug 814496 was resolved.