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
Is this blocked on bug 883539?
I still suspect that bug 883539 may also cause the failures in this bug, on Panda -- but I am not sure. I have no explanation for the failures on Tegra.
Geoff, any new ideas here? This and bug 877939 are pretty high up the OrangeFactor list on all branches.
Flags: needinfo?(gbrown)
(In reply to Ryan VanderMeulen [:RyanVM UTC-4] from comment #2082) > Geoff, any new ideas here? Not really. I have partial theories like: - we run low on memory (but why only sometimes?) and android kills sutagent, and maybe watcher too - on Panda only, the system deadlock described in bug 883539 causes android to kill off sutagent, and maybe watcher too - there's an unknown bug in sutagent that causes it to crash - networking problems, or a crash/bug in a device network component? I would like to see this reproduced with better logging. If we could get a logcat up to the moment we lose connectivity, maybe that would tell us what's happening. I started on a patch to do that, but it got complicated and other priorities pushed that aside. I would like to get back to that work, but cannot find the time right now. The new sutagent (1.19) *may* help -- it sounds like rel-eng will be deploying that in the next week or so. The new watcher (1.16) might help too. That's being scheduled too. But this may just be wishful thinking. Would it help to re-classify this error as a retry (turn the oranges into blues)?
Flags: needinfo?(gbrown)
(In reply to Geoff Brown [:gbrown] from comment #2083) > Would it help to re-classify this error as a retry (turn the oranges into > blues)? Very much so... :-)
(In reply to Ed Morley [:edmorley UTC+1] from comment #2099) > (In reply to Geoff Brown [:gbrown] from comment #2083) > > Would it help to re-classify this error as a retry (turn the oranges into > > blues)? > > Very much so... :-) I'm guessing we can either change the failure string to include "Remote Device Error:" so we match: https://hg.mozilla.org/build/buildbotcustom/file/e09ee7610d5b/status/errors.py#l6 ...or we can add another entry to errors.py specifically for this failure.
https://tbpl.mozilla.org/php/getParsedLog.php?id=28932797&tree=Mozilla-Inbound
Summary: 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. → Intermittent DMError: Automation Error: Timeout in command {ls,ps,isdir,mkdr,activity}, TEST-UNEXPECTED-FAIL | Automation Error: Timeout in command isdir /mnt/sdcard/tests/logs | Exception caught while running tests.
(In reply to TBPL Robot from comment #2406) > philor > https://tbpl.mozilla.org/php/getParsedLog.php?id=31573943&tree=Mozilla- > Inbound > Android 2.2 Armv6 Tegra mozilla-inbound opt test jsreftest-1 on 2013-12-06 > 09:12:37 This is a fairly rare case, in that the harness managed to report a logcat. Might this be significant: 12-06 09:20:16.686 E/GeckoConsole( 1772): [JavaScript Error: "this.browser.stop is not a function" {file: "chrome://browser/content/browser.js" line: 2656}] 12-06 09:20:16.686 E/GeckoConsole( 1772): Sending snapshot message. 12-06 09:20:16.696 E/GeckoConsole( 1772): [JavaScript Error: "aTab is null" {file: "chrome://browser/content/browser.js" line: 926}] 12-06 09:20:16.786 E/GeckoConsole( 1772): [JavaScript Error: "this.selectedTab is null" {file: "chrome://browser/content/browser.js" line: 1497}] ?
Most of the recent armv6/Robocop-2 failures are in testMozPay -- reported in bug 945675.
(In reply to TBPL Robot from comment #2417) > philor > https://tbpl.mozilla.org/php/getParsedLog.php?id=31714226&tree=Mozilla- > Inbound We got lucky here and collected a logcat: 7:44:50 INFO - 17:44:50 INFO - 12-09 17:00:43.703 I/GeckoDump( 2223): 27700 INFO TEST-INFO | MEMORY STAT vsize after test: 843284480 17:44:50 INFO - 17:44:50 INFO - 12-09 17:00:43.710 I/GeckoDump( 2223): 27701 INFO TEST-INFO | MEMORY STAT residentFast after test: 220073984 17:44:50 INFO - 17:44:50 INFO - 12-09 17:00:43.710 I/GeckoDump( 2223): 27702 INFO TEST-INFO | MEMORY STAT heapAllocated after test: 49433304 17:44:50 INFO - 17:44:50 INFO - 12-09 17:00:43.804 I/GeckoDump( 2223): 27703 INFO TEST-END | /tests/content/html/content/test/test_applet_attributes_reflection.html | finished in 642ms 17:44:50 INFO - 17:44:50 INFO - 12-09 17:00:43.835 D/GeckoTabs( 2223): handleMessage: SessionHistory:New 17:44:50 INFO - 17:44:50 INFO - 12-09 17:00:43.843 D/GeckoTabs( 2223): handleMessage: SessionHistory:Purge 17:44:50 INFO - 17:44:50 INFO - 12-09 17:00:43.882 I/GeckoDump( 2223): 27704 INFO TEST-START | /tests/content/html/content/test/test_audio_wakelock.html 17:44:50 INFO - 17:44:50 INFO - 12-09 17:00:44.187 I/GeckoDump( 2223): 27705 INFO TEST-PASS | /tests/content/html/content/test/test_audio_wakelock.html | Audio element locked the target == cpu 17:44:50 INFO - 17:44:50 INFO - 12-09 17:00:44.187 I/GeckoDump( 2223): 27706 INFO TEST-PASS | /tests/content/html/content/test/test_audio_wakelock.html | Audio element locked the cpu - no paused 17:44:50 INFO - 17:44:50 INFO - 12-09 17:00:44.242 E/libOpenSLES( 2223): pAudioSrc: samplesPerSec=11127000 17:44:50 INFO - 17:44:50 INFO - 12-09 17:00:44.242 W/libOpenSLES( 2223): Leaving Engine::CreateAudioPlayer (SL_RESULT_CONTENT_UNSUPPORTED) 17:44:50 INFO - 17:44:50 INFO - 12-09 17:00:54.492 I/dalvikvm( 2223): Jit: resizing JitTable from 4096 to 8192 17:44:50 INFO - 17:44:50 INFO - 12-09 17:01:01.882 I/SUTAgentAndroid( 1902): 10.12.131.19 : activity 17:44:50 INFO - 17:44:50 INFO - 12-09 17:01:21.906 I/SUTAgentAndroid( 1902): 10.12.131.19 : activity 17:44:50 INFO - 17:44:50 INFO - 12-09 17:01:21.921 I/SUTAgentAndroid( 1902): 10.12.131.19 : isdir /mnt/sdcard/tests/logs 17:44:50 INFO - 17:44:50 INFO - 12-09 17:01:21.937 I/SUTAgentAndroid( 1902): 10.12.131.19 : cd /mnt/sdcard/tests/logs 17:44:50 INFO - 17:44:50 INFO - 12-09 17:01:21.953 I/SUTAgentAndroid( 1902): 10.12.131.19 : ls 17:44:50 INFO - 17:44:50 INFO - 12-09 17:01:21.968 I/SUTAgentAndroid( 1902): 10.12.131.19 : pull /mnt/sdcard/tests/logs/mochitest.log 2521177 17:44:50 INFO - 17:44:50 INFO - 12-09 17:03:08.296 W/ThrottleService( 1401): unable to find stats for iface rmnet0 17:44:50 INFO - 17:44:50 INFO - 12-09 17:06:16.195 F/NetworkStats( 1401): problem reading network stats 17:44:50 INFO - 17:44:50 INFO - 12-09 17:06:16.195 F/NetworkStats( 1401): java.lang.IllegalStateException: problem parsing idx 1 17:44:50 INFO - 17:44:50 INFO - 12-09 17:06:16.195 F/NetworkStats( 1401): at com.android.internal.net.NetworkStatsFactory.readNetworkStatsDetail(NetworkStatsFactory.java:300) 17:44:50 INFO - 17:44:50 INFO - 12-09 17:06:16.195 F/NetworkStats( 1401): at com.android.server.NetworkManagementService.getNetworkStatsUidDetail(NetworkManagementService.java:1282) 17:44:50 INFO - 17:44:50 INFO - 12-09 17:06:16.195 F/NetworkStats( 1401): at com.android.server.net.NetworkStatsService.performPollLocked(NetworkStatsService.java:831) 17:44:50 INFO - 17:44:50 INFO - 12-09 17:06:16.195 F/NetworkStats( 1401): at com.android.server.net.NetworkStatsService.performPoll(NetworkStatsService.java:799) 17:44:50 INFO - 17:44:50 INFO - 12-09 17:06:16.195 F/NetworkStats( 1401): at com.android.server.net.NetworkStatsService.access$100(NetworkStatsService.java:128) 17:44:50 INFO - 17:44:50 INFO - 12-09 17:06:16.195 F/NetworkStats( 1401): at com.android.server.net.NetworkStatsService$3.onReceive(NetworkStatsService.java:633) 17:44:50 INFO - 17:44:50 INFO - 12-09 17:06:16.195 F/NetworkStats( 1401): at android.app.LoadedApk$ReceiverDispatcher$Args.run(LoadedApk.java:728) 17:44:50 INFO - 17:44:50 INFO - 12-09 17:06:16.195 F/NetworkStats( 1401): at android.os.Handler.handleCallback(Handler.java:605) 17:44:50 INFO - 17:44:50 INFO - 12-09 17:06:16.195 F/NetworkStats( 1401): at android.os.Handler.dispatchMessage(Handler.java:92) 17:44:50 INFO - 17:44:50 INFO - 12-09 17:06:16.195 F/NetworkStats( 1401): at android.os.Looper.loop(Looper.java:137) 17:44:50 INFO - 17:44:50 INFO - 12-09 17:06:16.195 F/NetworkStats( 1401): at android.os.HandlerThread.run(HandlerThread.java:60) 17:44:50 INFO - 17:44:50 INFO - 12-09 17:06:16.195 F/NetworkStats( 1401): Caused by: java.io.FileNotFoundException: /proc/net/xt_qtaguid/stats: open failed: ENOENT (No such file or directory) 17:44:50 INFO - 17:44:50 INFO - 12-09 17:06:16.195 F/NetworkStats( 1401): at libcore.io.IoBridge.open(IoBridge.java:406) 17:44:50 INFO - 17:44:50 INFO - 12-09 17:06:16.195 F/NetworkStats( 1401): at java.io.FileInputStream.<init>(FileInputStream.java:78) 17:44:50 INFO - 17:44:50 INFO - 12-09 17:06:16.195 F/NetworkStats( 1401): at com.android.internal.net.NetworkStatsFactory.readNetworkStatsDetail(NetworkStatsFactory.java:269) 17:44:50 INFO - 17:44:50 INFO - 12-09 17:06:16.195 F/NetworkStats( 1401): ... 10 more 17:44:50 INFO - 17:44:50 INFO - 12-09 17:06:16.195 F/NetworkStats( 1401): Caused by: libcore.io.ErrnoException: open failed: ENOENT (No such file or directory) 17:44:50 INFO - 17:44:50 INFO - 12-09 17:06:16.195 F/NetworkStats( 1401): at libcore.io.Posix.open(Native Method) 17:44:50 INFO - 17:44:50 INFO - 12-09 17:06:16.195 F/NetworkStats( 1401): at libcore.io.BlockGuardOs.open(BlockGuardOs.java:110) 17:44:50 INFO - 17:44:50 INFO - 12-09 17:06:16.195 F/NetworkStats( 1401): at libcore.io.IoBridge.open(IoBridge.java:390) 17:44:50 INFO - 17:44:50 INFO - 12-09 17:06:16.195 F/NetworkStats( 1401): ... 12 more 17:44:50 INFO - 17:44:50 INFO - 12-09 17:06:26.187 W/ActivityManager( 1401): Timeout of broadcast BroadcastRecord{4153cea0 com.android.server.action.NETWORK_STATS_POLL} - receiver=android.app.LoadedApk$ReceiverDispatcher$InnerReceiver@41339700, started 10000ms ago 17:44:50 INFO - 17:44:50 INFO - 12-09 17:06:26.187 W/ActivityManager( 1401): Receiver during timeout: BroadcastFilter{4139c1b0 ReceiverList{4139c138 1401 system/1000 local:41339700}} 17:44:50 INFO - 17:44:50 INFO - 12-09 17:06:42.242 I/SUTAgentAndroid( 1902): CmdWorkerThread starts: 149 17:44:50 INFO - 17:44:50 INFO - 12-09 17:06:42.242 I/SUTAgentAndroid( 1902): 10.12.131.19 : activity 17:44:50 INFO - 17:44:50 INFO - 12-09 17:07:02.257 I/SUTAgentAndroid( 1902): 10.12.131.19 : activity 17:44:50 INFO - 17:44:50 INFO - 12-09 17:07:22.281 I/SUTAgentAndroid( 1902): 10.12.131.19 : activity 17:44:50 INFO - 17:44:50 INFO - 12-09 17:07:22.296 I/SUTAgentAndroid( 1902): 10.12.131.19 : isdir /mnt/sdcard/tests/logs 17:44:50 INFO - 17:44:50 INFO - 12-09 17:07:22.304 I/SUTAgentAndroid( 1902): 10.12.131.19 : cd /mnt/sdcard/tests/logs 17:44:50 INFO - 17:44:50 INFO - 12-09 17:07:22.320 I/SUTAgentAndroid( 1902): 10.12.131.19 : ls 17:44:50 INFO - 17:44:50 INFO - 12-09 17:07:22.335 I/SUTAgentAndroid( 1902): 10.12.131.19 : pull /mnt/sdcard/tests/logs/mochitest.log 2521177 17:44:50 INFO - 17:44:50 INFO - 12-09 17:12:42.562 I/SUTAgentAndroid( 1902): CmdWorkerThread starts: 150 17:44:50 INFO - 17:44:50 INFO - 12-09 17:12:42.562 I/SUTAgentAndroid( 1902): 10.12.131.19 : activity 17:44:50 INFO - 17:44:50 INFO - 12-09 17:13:02.585 I/SUTAgentAndroid( 1902): 10.12.131.19 : activity 17:44:50 INFO - 17:44:50 INFO - 12-09 17:13:22.609 I/SUTAgentAndroid( 1902): 10.12.131.19 : activity 17:44:50 INFO - 17:44:50 INFO - 12-09 17:13:22.625 I/SUTAgentAndroid( 1902): 10.12.131.19 : isdir /mnt/sdcard/tests/logs 17:44:50 INFO - 17:44:50 INFO - 12-09 17:13:22.640 I/SUTAgentAndroid( 1902): 10.12.131.19 : cd /mnt/sdcard/tests/logs 17:44:50 INFO - 17:44:50 INFO - 12-09 17:13:22.656 I/SUTAgentAndroid( 1902): 10.12.131.19 : ls 17:44:50 INFO - 17:44:50 INFO - 12-09 17:13:22.664 I/SUTAgentAndroid( 1902): 10.12.131.19 : pull /mnt/sdcard/tests/logs/mochitest.log 2521177 17:44:50 INFO - 17:44:50 INFO - 12-09 17:18:42.898 I/SUTAgentAndroid( 1902): CmdWorkerThread starts: 151 17:44:50 INFO - 17:44:50 INFO - 12-09 17:18:42.898 I/SUTAgentAndroid( 1902): 10.12.131.19 : activity 17:44:50 INFO - 17:44:50 INFO - 12-09 17:19:02.921 I/SUTAgentAndroid( 1902): 10.12.131.19 : activity 17:44:50 INFO - 17:44:50 INFO - 12-09 17:19:22.937 I/SUTAgentAndroid( 1902): 10.12.131.19 : activity 17:44:50 INFO - 17:44:50 INFO - 12-09 17:19:22.953 I/SUTAgentAndroid( 1902): 10.12.131.19 : isdir /mnt/sdcard/tests/logs 17:44:50 INFO - 17:44:50 INFO - 12-09 17:19:22.968 I/SUTAgentAndroid( 1902): 10.12.131.19 : cd /mnt/sdcard/tests/logs 17:44:50 INFO - 17:44:50 INFO - 12-09 17:19:22.984 I/SUTAgentAndroid( 1902): 10.12.131.19 : ls 17:44:50 INFO - 17:44:50 INFO - 12-09 17:19:23.000 I/SUTAgentAndroid( 1902): 10.12.131.19 : pull /mnt/sdcard/tests/logs/mochitest.log 2521177 17:44:50 INFO - 17:44:50 INFO - 12-09 17:19:38.617 I/SUTAgentAndroid( 1902): CmdWorkerThread starts: 152 17:44:50 INFO - 17:44:50 INFO - 12-09 17:19:38.617 I/SUTAgentAndroid( 1902): 10.12.131.33 : testroot 17:44:50 INFO - 17:44:50 INFO - 12-09 17:19:38.632 I/SUTAgentAndroid( 1902): 10.12.131.33 : isdir /mnt/sdcard/tests 17:44:50 INFO - 17:44:50 INFO - 12-09 17:19:38.656 I/SUTAgentAndroid( 1902): 10.12.131.33 : ver 17:44:50 INFO - 17:44:50 INFO - 12-09 17:19:38.671 I/SUTAgentAndroid( 1902): CmdWorkerThread ends: 152 17:44:50 INFO - 17:44:50 INFO - 12-09 17:21:16.218 F/BatteryStatsImpl( 1401): problem reading network stats 17:44:50 INFO - 17:44:50 INFO - 12-09 17:21:16.218 F/BatteryStatsImpl( 1401): java.lang.IllegalStateException: problem parsing idx 1 17:44:50 INFO - 17:44:50 INFO - 12-09 17:21:16.218 F/BatteryStatsImpl( 1401): at com.android.internal.net.NetworkStatsFactory.readNetworkStatsDetail(NetworkStatsFactory.java:300) 17:44:50 INFO - 17:44:50 INFO - 12-09 17:21:16.218 F/BatteryStatsImpl( 1401): at com.android.internal.net.NetworkStatsFactory.readNetworkStatsDetail(NetworkStatsFactory.java:250) 17:44:50 INFO - 17:44:50 INFO - 12-09 17:21:16.218 F/BatteryStatsImpl( 1401): at com.android.internal.os.BatteryStatsImpl.getNetworkStatsDetailGroupedByUid(BatteryStatsImpl.java:5734) 17:44:50 INFO - 17:44:50 INFO - 12-09 17:21:16.218 F/BatteryStatsImpl( 1401): at com.android.internal.os.BatteryStatsImpl.access$100(BatteryStatsImpl.java:76) 17:44:50 INFO - 17:44:50 INFO - 12-09 17:21:16.218 F/BatteryStatsImpl( 1401): at com.android.internal.os.BatteryStatsImpl$Uid.computeCurrentTcpBytesReceived(BatteryStatsImpl.java:2457) 17:44:50 INFO - 17:44:50 INFO - 12-09 17:21:16.218 F/BatteryStatsImpl( 1401): at com.android.internal.os.BatteryStatsImpl$Uid.getTcpBytesReceived(BatteryStatsImpl.java:2446) 17:44:50 INFO - 17:44:50 INFO - 12-09 17:21:16.218 F/BatteryStatsImpl( 1401): at com.android.internal.os.BatteryStatsImpl.writeSummaryToParcel(BatteryStatsImpl.java:5437) 17:44:50 INFO - 17:44:50 INFO - 12-09 17:21:16.218 F/BatteryStatsImpl( 1401): at com.android.internal.os.BatteryStatsImpl.writeLocked(BatteryStatsImpl.java:4836) 17:44:50 INFO - 17:44:50 INFO - 12-09 17:21:16.218 F/BatteryStatsImpl( 1401): at com.android.internal.os.BatteryStatsImpl.writeAsyncLocked(BatteryStatsImpl.java:4818) 17:44:50 INFO - 17:44:50 INFO - 12-09 17:21:16.218 F/BatteryStatsImpl( 1401): at com.android.server.am.ActivityManagerService.updateCpuStatsNow(ActivityManagerService.java:1652) 17:44:50 INFO - 17:44:50 INFO - 12-09 17:21:16.218 F/BatteryStatsImpl( 1401): at com.android.server.am.ActivityManagerService$3.run(ActivityManagerService.java:1534) 17:44:50 INFO - 17:44:50 INFO - 12-09 17:21:16.218 F/BatteryStatsImpl( 1401): Caused by: java.io.FileNotFoundException: /proc/net/xt_qtaguid/stats: open failed: ENOENT (No such file or directory) 17:44:50 INFO - 17:44:50 INFO - 12-09 17:21:16.218 F/BatteryStatsImpl( 1401): at libcore.io.IoBridge.open(IoBridge.java:406) 17:44:50 INFO - 17:44:50 INFO - 12-09 17:21:16.218 F/BatteryStatsImpl( 1401): at java.io.FileInputStream.<init>(FileInputStream.java:78) 17:44:50 INFO - 17:44:50 INFO - 12-09 17:21:16.218 F/BatteryStatsImpl( 1401): at com.android.internal.net.NetworkStatsFactory.readNetworkStatsDetail(NetworkStatsFactory.java:269) 17:44:50 INFO - 17:44:50 INFO - 12-09 17:21:16.218 F/BatteryStatsImpl( 1401): ... 10 more 17:44:50 INFO - 17:44:50 INFO - 12-09 17:21:16.218 F/BatteryStatsImpl( 1401): Caused by: libcore.io.ErrnoException: open failed: ENOENT (No such file or directory) 17:44:50 INFO - 17:44:50 INFO - 12-09 17:21:16.218 F/BatteryStatsImpl( 1401): at libcore.io.Posix.open(Native Method) 17:44:50 INFO - 17:44:50 INFO - 12-09 17:21:16.218 F/BatteryStatsImpl( 1401): at libcore.io.BlockGuardOs.open(BlockGuardOs.java:110) 17:44:50 INFO - 17:44:50 INFO - 12-09 17:21:16.218 F/BatteryStatsImpl( 1401): at libcore.io.IoBridge.open(IoBridge.java:390) 17:44:50 INFO - 17:44:50 INFO - 12-09 17:21:16.218 F/BatteryStatsImpl( 1401): ... 12 more 17:44:50 INFO - 17:44:50 INFO - 12-09 17:24:43.226 I/SUTAgentAndroid( 1902): CmdWorkerThread starts: 153 17:44:50 INFO - 17:44:50 INFO - 12-09 17:24:43.226 I/SUTAgentAndroid( 1902): 10.12.131.19 : activity 17:44:50 INFO - 17:44:50 INFO - 12-09 17:29:39.187 I/SUTAgentAndroid( 1902): CmdWorkerThread starts: 154 17:44:50 INFO - 17:44:50 INFO - 12-09 17:29:39.187 I/SUTAgentAndroid( 1902): 10.12.131.33 : testroot 17:44:50 INFO - 17:44:50 INFO - 12-09 17:29:39.203 I/SUTAgentAndroid( 1902): 10.12.131.33 : isdir /mnt/sdcard/tests 17:44:50 INFO - 17:44:50 INFO - 12-09 17:29:39.226 I/SUTAgentAndroid( 1902): 10.12.131.33 : ver 17:44:50 INFO - 17:44:50 INFO - 12-09 17:29:39.242 I/SUTAgentAndroid( 1902): CmdWorkerThread ends: 154 17:44:50 INFO - 17:44:50 INFO - 12-09 17:39:49.882 I/SUTAgentAndroid( 1902): CmdWorkerThread starts: 155 17:44:50 INFO - 17:44:50 INFO - 12-09 17:39:49.882 I/SUTAgentAndroid( 1902): 10.12.131.33 : testroot 17:44:50 INFO - 17:44:50 INFO - 12-09 17:39:49.898 I/SUTAgentAndroid( 1902): 10.12.131.33 : isdir /mnt/sdcard/tests 17:44:50 INFO - 17:44:50 INFO - 12-09 17:39:49.914 I/SUTAgentAndroid( 1902): 10.12.131.33 : ver 17:44:50 INFO - 17:44:50 INFO - 12-09 17:39:49.921 I/SUTAgentAndroid( 1902): CmdWorkerThread ends: 155 17:44:50 INFO - 17:44:50 INFO - 12-09 17:44:48.835 I/SUTAgentAndroid( 1902): CmdWorkerThread starts: 156 17:44:50 INFO - 17:44:50 INFO - 12-09 17:44:48.835 I/SUTAgentAndroid( 1902): 10.12.131.19 : testroot 17:44:50 INFO - 17:44:50 INFO - 12-09 17:44:48.851 I/SUTAgentAndroid( 1902): 10.12.131.19 : isdir /mnt/sdcard/tests 17:44:50 INFO - 17:44:50 INFO - 12-09 17:44:48.859 I/SUTAgentAndroid( 1902): 10.12.131.19 : ver 17:44:50 INFO - 17:44:50 INFO - 12-09 17:44:48.875 I/SUTAgentAndroid( 1902): 10.12.131.19 : execsu /system/bin/logcat -v time -d dalvikvm:I ConnectivityService:S WifiMonitor:S WifiStateTracker:S wpa_supplicant:S NetworkStateTracker:S 17:44:50 INFO - 17:44:50 INFO - 12-09 17:44:49.195 I/dalvikvm-heap( 1902): Grow heap (frag case) to 7.132MB for 183634-byte allocation 17:44:50 INFO - *** END LOGCAT *** Note that a new CmdWorkerThread is spawned (and the old one seems to never end) after each pull command -- I think that is troubling.
Summary: Intermittent DMError: Automation Error: Timeout in command {ls,ps,isdir,mkdr,activity}, 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,rmdir,activity}, TEST-UNEXPECTED-FAIL | Automation Error: Timeout in command isdir /mnt/sdcard/tests/logs | Exception caught while running tests.
Tweaking summary to avoid false positives.
Summary: Intermittent DMError: Automation Error: Timeout in command {ls,ps,isdir,mkdr,rmdir,activity}, 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,mkdr,rmdir,activity} (followed by DMError: Automation Error: Timeout in command isdir /mnt/sdcard/tests/logs)
Summary: Intermittent DMError: Automation Error: Timeout in command {ls,ps,mkdr,rmdir,activity} (followed by DMError: Automation Error: Timeout in command isdir /mnt/sdcard/tests/logs) → 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)
Component: General → General Automation
Product: Testing → Release Engineering
QA Contact: catlee
Version: Trunk → unspecified
It's faster and easier to just star this as "a", and it's not like that will increase the risk of our starring actual new failure, since we star so many hundreds of other failures that nobody cares to fix that way already.
Status: NEW → RESOLVED
Closed: 11 years ago
Keywords: intermittent-failure
Resolution: --- → WONTFIX
Component: General Automation → General
You need to log in before you can comment on or make changes to this bug.