Closed Bug 807230 Opened 13 years ago Closed 11 years ago

Intermittent DMError: Automation Error: Timeout in command {ls,ps,mkdr,rmdir,activity} | DMError: Automation Error: Timeout in command isdir /mnt/sdcard/tests/logs (or DMError: Automation Error: Timeout in command isdir /mnt/sdcard/tests/reftest)

Categories

(Release Engineering :: General, defect)

Product:
Release Engineering
Component:
General
Platform:
ARM
Android
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

(Not tracked)

Status:
RESOLVED WONTFIX

People

(Reporter: philor, Unassigned)

References

Details

https://tbpl.mozilla.org/php/getParsedLog.php?id=16608771&tree=Mozilla-Inbound Android Tegra 250 mozilla-inbound opt test mochitest-1 on 2012-10-30 20:10:49 PDT for push a2afde356192 slave: tegra-228 43453 INFO TEST-INFO | /tests/content/canvas/test/webgl/test_webgl_conformance_test_suite.html | [conformance/renderbuffers/framebuffer-object-attachment.html] (WebGL mochitest) Starting test page INFO | runtests.py | Received unexpected exception while running application Traceback (most recent call last): File "/builds/tegra-228/test/build/tests/mochitest/runtests.py", line 731, in runTests timeout = timeout) File "/builds/tegra-228/test/build/tests/mochitest/automation.py", line 1050, in runApp status = self.waitForFinish(proc, utilityPath, timeout, maxTime, startTime, debuggerInfo, symbolsPath) File "/builds/tegra-228/test/build/tests/mochitest/remoteautomation.py", line 66, in waitForFinish status = proc.wait(timeout = maxTime) File "/builds/tegra-228/test/build/tests/mochitest/remoteautomation.py", line 203, in wait t = self.stdout File "/builds/tegra-228/test/build/tests/mochitest/remoteautomation.py", line 180, in stdout if self.dm.fileExists(self.proc): File "/builds/tegra-228/test/build/tests/mochitest/devicemanagerSUT.py", line 407, in fileExists return s[-1] in self.listFiles(containingpath) File "/builds/tegra-228/test/build/tests/mochitest/devicemanagerSUT.py", line 418, in listFiles data = self._runCmds([{ 'cmd': 'cd ' + rootdir }, { 'cmd': 'ls' }]) File "/builds/tegra-228/test/build/tests/mochitest/devicemanagerSUT.py", line 140, in _runCmds self._sendCmds(cmdlist, outputfile, timeout) File "/builds/tegra-228/test/build/tests/mochitest/devicemanagerSUT.py", line 122, in _sendCmds raise err DMError: Automation Error: Timeout in command ls WARNING | automationutils.processLeakLog() | refcount logging is off, so leaks can't be detected! INFO | runtests.py | Running tests: end. TEST-UNEXPECTED-FAIL | Automation Error: Timeout in command isdir /mnt/sdcard/tests/logs | Exception caught while running tests. WARNING: Error getting device information at end of test program finished with exit code 1
Whiteboard: [orange]
Depends on: 816581
Summary: Intermittent DMError: Automation Error: Timeout in command ls, TEST-UNEXPECTED-FAIL | Automation Error: Timeout in command isdir /mnt/sdcard/tests/logs | Exception caught while running tests. → Intermittent DMError: Automation Error: Timeout in command {ls,ps}, TEST-UNEXPECTED-FAIL | Automation Error: Timeout in command isdir /mnt/sdcard/tests/logs | Exception caught while running tests.
this looks to be we are executing a command and the device becomes unreachable. Mostly evident by the fact that we get secondary errors about no route to host, connection refused, etc...
Summary: Intermittent DMError: Automation Error: Timeout in command {ls,ps}, TEST-UNEXPECTED-FAIL | Automation Error: Timeout in command isdir /mnt/sdcard/tests/logs | Exception caught while running tests. → Intermittent DMError: Automation Error: Timeout in command {ls,ps,isdir}, TEST-UNEXPECTED-FAIL | Automation Error: Timeout in command isdir /mnt/sdcard/tests/logs | Exception caught while running tests.
(In reply to Joel Maher (:jmaher) from comment #96) > this looks to be we are executing a command and the device becomes > unreachable. Mostly evident by the fact that we get secondary errors about > no route to host, connection refused, etc... Do we have any next steps? :-)
I suspect this is related to the libc.so fix we did where we would hang after doing shell commands in the sutagent. One thing to look into would be updating the sutagent and/or automation scripts to do as few shell commands as possible. We should only be doing it a few times per test run, so if we are executing commands to get status, stats, or logs which do this we should find other ways to get that data or find ways to not require that data so frequently.
Summary: Intermittent DMError: Automation Error: Timeout in command {ls,ps,isdir}, TEST-UNEXPECTED-FAIL | Automation Error: Timeout in command isdir /mnt/sdcard/tests/logs | Exception caught while running tests. → Intermittent DMError: Automation Error: Timeout in command {ls,ps,isdir,mkdr}, TEST-UNEXPECTED-FAIL | Automation Error: Timeout in command isdir /mnt/sdcard/tests/logs | Exception caught while running tests.
Joel - would you mind looking at this, or else finding an owner? :-)
Assignee: nobody → jmaher
Flags: needinfo?(jmaher)
this is caused by rebooting devices during tests, I am waiting until the mobile testing meeting before taking any action on this.
Flags: needinfo?(jmaher)
Information from etherpad regarding Android releng crashes * 350 failures in the last 2 months * majority is panda, but some tegras fail * tegra failures appear to be unexpected reboot of the device * panda failures seem to be unexpected reboot of the device * some logs fail on test and reboot with no logcat, device unavailable
Joel, I don't suppose you could given a quick status update for this bug? I'm struggling to work out where we're at with it from the comments. Cheers :-)
Flags: needinfo?(jmaher)
I haven't looked at this bug. Earlier on it was thought that fixing the power supplies would reduce/fix this bug. Looking over the history in orange factor we did reduce this bug by about 50% with that one fix. Other possible fixes would be in sutagent itself.
Flags: needinfo?(jmaher)
dminor: this issue might be reduced heavily by revisiting the sutagent and how we shell out for commands. If you have any thoughts on that, it would be greatly appreciated!
Assignee: jmaher → nobody
In bug 867360, I am looking at unexpected death of the Watcher; while investigating that, I am monitoring sutagent as well, and trying to add better diagnostics to both to determine when our test services are starting / stopping and why.
I suspect the timeouts here are the sutagent not accepting commands or returning when issued commands. This might be as easy as fixing how we shell out or do su commands. I have been wanting to spend some time and reduce our overall commands we issue for a given test. I believe we have too many commands and too much bandwidth (sucking the log file every few seconds) in each test.
(In reply to Geoff Brown [:gbrown] from comment #1309) > In bug 867360, I am looking at unexpected death of the Watcher; while > investigating that, I am monitoring sutagent as well, and trying to add > better diagnostics to both to determine when our test services are starting > / stopping and why. (In reply to Joel Maher (:jmaher) from comment #1310) > I suspect the timeouts here are the sutagent not accepting commands or > returning when issued commands. This might be as easy as fixing how we > shell out or do su commands. I have been wanting to spend some time and > reduce our overall commands we issue for a given test. I believe we have > too many commands and too much bandwidth (sucking the log file every few > seconds) in each test. Geoff/Joel, are either of you working on this? Would it be useful if I spoke to Clint and asked if he could find someone to help out here?
Flags: needinfo?(gbrown)
I think dminor was looking at this.
I am not actively working on this but am interested in investigating or helping out as soon as time allows. I hope that some of the sutagent changes from 867360 (not yet deployed) will help us understand the problem. :dminor -- anything to report?
Flags: needinfo?(gbrown) → needinfo?(dminor)
(In reply to Geoff Brown [:gbrown] from comment #1367) > I am not actively working on this but am interested in investigating or > helping out as soon as time allows. I hope that some of the sutagent changes > from 867360 (not yet deployed) will help us understand the problem. > > :dminor -- anything to report? I am looking at this, but at the moment I'm still trying to narrow down something reproducible in my local setup. I was able to get this problem or something similar to reproduce in the past, but haven't had luck in the past few days.
Flags: needinfo?(dminor)
After discussing this with jmaher, I ran a test setup which used to reproduce this problem on a local panda reliably. I set up mochitest-1 to run in a loop, and then polled the temperature using SUTAgent from a separate process every 2 seconds. I ran this over the weekend (60+ hours) and the issue did not reproduce for me. I normally run my panda on an isolated network; tonight I'll run it connected to the internet and see if that has any effect on getting this to reproduce.
Just a quick note that as expected, running my panda connected to the internet did not cause the issue to reproduce. The next thing I will try is an earlier version of SUTAgent on the chance that recent changes have caused this bug to act differently.
I have been able to repro this bug running the sut_tools smoketest. The main difference between what I was doing with my own script and the smoketests lies in package management and board reboots, so that looks like a good avenue to explore in trying to root cause this. The SUTAgent hang occurred when I did not have the temperature polling script running, so that does not appear to be a cause (although it may accelerate reproducing the issue.)
I enabled additional devicemanager logging in a try run here: https://tbpl.mozilla.org/?tree=Try&rev=bfec2e1c6714. This does not point to an explanation or solution in itself, but might contribute to our understanding.
Still unable to reproduce this locally. Discussed this further with jmaher, and we have some ideas that might help this happen less often, tracked in bug 881879 and bug 881897. Another possibiliy is to investigate forking behaviour in SUTAgent itself, particularly when using su.
Depends on: 881897
I think bug 883539 is a plausible explanation for this bug, on Panda -- just something to keep in mind.
Depends on: 883539