STR: Starting to test mtbf run on v2.1 branch, after more than 20 minutes execution test cases began to fail when disabling ftu. Device: flame Revision info Gaia 95e9b099aa89ded133e44014dd40b19dc0193c01 Gecko https://hg.mozilla.org/releases/mozilla-aurora/rev/92a6bbdfd945 BuildID 20140905000202 Version 34.0a2 ro.build.date Fri Jun 27 15:57:58 CST 2014 ro.bootloader L1TC00011230 ro.build.version.incremental 110 EXPECT: Test run will not stop in 100 hours ACTUAL: Test ended in 30~60 minutes

Paul, any stacktraces/logs/memdumps we can get here to get started here ? We need to bisect if this is atest bug or a gecko/gaia issue. This test works on 2.0 as expected?

re-run on 2.0 didn't see this issue. keep ni?

Add last 2 logcat before test run stopped.

Look like bug 1061742

Remove disabling keyboard ftu, log repeated E/GeckoConsole( 314): Content JS LOG at dummy file:645 in GaiaDataLayer.disableWiFi/<: wifi enabled status: true Detail in logcat3 Malini, can you give comments from marionette? It looks pretty similar to bug 1061742, a waitfor condition can't be matched, when the client raises timeout exception, previously executing script kept running in server side.

(In reply to Paul Yang [: pyang] from comment #7) > Remove disabling keyboard ftu, log repeated > E/GeckoConsole( 314): Content JS LOG at dummy file:645 in > GaiaDataLayer.disableWiFi/<: wifi enabled status: true > > Detail in logcat3 > > Malini, can you give comments from marionette? Sure, only logcat12 has marionette output, and it looks healthy. > It looks pretty similar to bug 1061742, a waitfor condition can't be > matched, when the client raises timeout exception, previously executing > script kept running in server side. In Bug 1061742's logcat, it looks like E/GeckoConsole( 4168): [JavaScript Error: "ReadOnlyError: A mutation operation was attempted in a READ_ONLY transaction." {file: "resource://gre/modules/SettingsRequestManager.jsm" line: 509}] is the error that's causing the problems. Logcat3, logcat12 and logcat13 don't contain this error, nor any other suspicious error

Thanks Malini. I just re-run the test and it gave the same log as you mentioned (in logcat4, line 32027)

Re-run on today's pvt build and it failed. Add attachment of periodically gathering logcat/b2g-ps/top Cervantes, can you help to see this case?

From the top output it's not clear whether there is a CPU spin like the one you showed me yesterday, but one recurring log entry concerns me: 09-16 14:45:01.979 310 310 E GeckoConsole: Content JS LOG at dummy file:352 in GaiaApps.getDisplayedApp: app with origin 'app://verticalhome.gaiamobile.org' is displayed 09-16 14:45:01.979 310 310 E GeckoConsole: Content JS LOG at dummy file:644 in GaiaDataLayer.disableWiFi/<: wifi enabled status: true Does it keep popping up even after you take the device offline? If yes I think we have a performance problem because it will consume CPU clocks and suck up the battery. We need to figure out whether this is caused by the test harness, or will it potentially happen on end user's device.

Yes, it kept popping on devices even test ended. What else do we need to go deeper? You can setup mtbf and run locally, should be 100% percent to reproduce.

We checked one device that finished the test and shows CPU spin (42% on flame). This keeps popping up in adb logcat: E/GeckoConsole( 321): Content JS LOG at dummy file:644 in GaiaDataLayer.disableWiFi/<: wifi enabled status: true There is definitely one infinite loop.

The dummy files in log are gaia/tests/atoms/gaia_app.js and gaia/tests/atoms/gaia_data_layer.js Attachment is stdout from one of the test run. Malini, can you help to do more investigation for current logs?

You should also consider this being an actual bug on the phone. During an event this weekend we had several phones that started to be super slow after using for an hour or so. Scrolling in the setting app looked like performing with 2fps.

I think this is bug on the phone but still need advice from framework to confirm. After tracing marionette server, waitFor function in contact simply loop until timeout. The phones didn't run slowly, so might not be the same issue. Keep trying to narrow down.

(In reply to Paul Yang [: pyang] from comment #14) > Created attachment 8490615 [details] > marionette_stdout.log > > The dummy files in log are gaia/tests/atoms/gaia_app.js and > gaia/tests/atoms/gaia_data_layer.js > Attachment is stdout from one of the test run. Malini, can you help to do > more investigation for current logs? The framework looks like it's doing the right thing here. If there was a marionette bug, you'd see some IOError/"connection lost" errors. Seems more like a wifi problem, especially since you get those wifi messages in the logcat after the tests end from comment #12. Maybe a memory dump would be useful here? I've seen an issue where we'd have tons of wifi workers being spun up and it was causing failures, and that was detected using the memory dump.

Given the above comments - should we consider putting this on the blocking 2.1? queue & have someone from the wifi team take a look at this bug?

It might not be a wifi issue, because sometimes it loops in getDisplayedApp() so I will think the queue is full or busy waiting for something.

We saw a phone that never run automatic test and could reproduce script timeout issue. However, it didn't print any log except E/QCALOG ( 415): [MessageQ] ProcessNewMessage: [XTWWAN-PE] unknown deliver target [OS-Agent] E/QCALOG ( 415): [MessageQ] ProcessNewMessage: [XTWiFi-PE] unknown deliver target [OS-Agent] and look so much like suspended.

What is the phone showing when the test gets hung (e.g. a screenshot)?

Actually it didn't get hung. I can still operate apps like homescreen or settings. One thing strange is developer menu in settings disabled and can't be enabled anymore. I'll try to bisect for a regression window next week.

Can't reproduce by today's build Trigger more test runs and see if it becomes WFM Build info: Gaia-Rev b3f9b97d16a1ab55f80239d63c1a85c3da3d39ad Gecko-Rev https://hg.mozilla.org/releases/mozilla-aurora/rev/2c6e3261c47b Build ID 20140921160204 Version 34.0a2 Device Name flame FW-Release 4.3 FW-Incremental 110 FW-Date Fri Jun 27 15:57:58 CST 2014 Bootloader L1TC00011230

memory report by latest pvt build

(In reply to Malini Das [:mdas] from comment #17) > (In reply to Paul Yang [: pyang] from comment #14) > > Created attachment 8490615 [details] > > marionette_stdout.log > > > > The dummy files in log are gaia/tests/atoms/gaia_app.js and > > gaia/tests/atoms/gaia_data_layer.js > > Attachment is stdout from one of the test run. Malini, can you help to do > > more investigation for current logs? > > The framework looks like it's doing the right thing here. If there was a > marionette bug, you'd see some IOError/"connection lost" errors. Seems more > like a wifi problem, especially since you get those wifi messages in the > logcat after the tests end from comment #12. > > Maybe a memory dump would be useful here? I've seen an issue where we'd have > tons of wifi workers being spun up and it was causing failures, and that was > detected using the memory dump. malini, can you please help investigate the memory reports/logs paul attached recently to see if its the wifi workers causing failures that you suspected?

I don't know how to read memory log/crash log data. CC'ing khuey since he's knowledgeable about memory reports. Does anything here looks suspicious?

I see ~5400 SettingsLocks in that log. That's the only thing that jumps out at me.

Update zip for debug info every 5 tests

Memory report from get_about memory

Update latest cc log

Update gc log

Kyle, Just update memory report and cc & gc log by our latest build, logcat and b2g-ps, top are included in output_debug_87.zip. The device has memory pressure even suspended. Please help to investigate and comment, thanks.

That log has about 8000 SettingsLocks in it. It also has a ton of iframes leaked via bug 1051995.

(In reply to Kyle Huey [:khuey] (khuey@mozilla.com) from comment #35) > That log has about 8000 SettingsLocks in it. > > It also has a ton of iframes leaked via bug 1051995. Nice, that would match what I saw the other morning.

qdot, We triggered test yesterday with revision Gaia 93a99bea0b40d81bd063f7d8b1964dc1ba35ba7b Gecko https://hg.mozilla.org/releases/mozilla-aurora/rev/d7e31ecd48af BuildID 20140924000243 Version 34.0a2 ro.build.date Thu Sep 4 14:59:02 CST 2014 ro.bootloader L1TC10011800 ro.build.version.incremental 27 From greping cc-log and gc-log, SettingsLock reduce to 388 lines. However it didn't solve the issue. I'll try it today and see if it's improved.

Update latest test run status: based on flame-kk v2.1 12 devices brief metrics https://docs.google.com/a/mozilla.com/spreadsheets/d/1RT1yMbXFnMiJSNRzaCddFfW55NX9vNdjaL3ChouCH54/edit#gid=1020998015 MTBF: 8.23 hours cpu usage is up to 50% even suspended. Update output(b2g-ps, top, dmesg, logcat) as well

On a device which b2g process consumes cpu ~50%, perf shows ~70% in the for loop matching regexp of mozilla::hal_impl::OomVictimLogger::Observe. I'd like to run gdb on the device directly to check, but found there're no symbols in PVT build. Just made a local build, will ask Paul to take another run and use gdb to check when test finish.

BTW, I am not sure whether cpu usage high relates to marionete timeout, will also check that.

From logcat there're a lot of: E/GeckoConsole( 210): Content JS LOG at dummy file:352 in GaiaApps.getDisplayedApp: app with origin 'app://verticalhome.gaiamobile.org' is displayed and there's a bug 1036631 which has been resolved (?).

There's also a repeated died/reborn process from logcat: D/QSEECOMAPI: (22157): QSEECom_get_handle sb_length = 0x2000 D/QSEECOMAPI: (22157): App is not loaded in QSEE E/QSEECOMAPI: (22157): Error::Cannot open the file /vendor/firmware/keymaster/keymaster.mdt E/QSEECOMAPI: (22157): Error::Loading image failed with ret = -1 D/QSEECOMAPI: (22157): QSEECom_get_handle sb_length = 0x2000 D/QSEECOMAPI: (22157): App is not loaded in QSEE E/QSEECOMAPI: (22157): Error::Cannot open the file /firmware/image/keymaste.mdt E/QSEECOMAPI: (22157): Error::Loading image failed with ret = -1 I/cat ( 303): <4>[57586.589981] QSEECOM: qseecom_release: data: released = false, type = 1, data = 0xd030e300 I/cat ( 303): <4>[57586.598860] QSEECOM: qseecom_release: data: released = false, type = 1, data = 0xd030e300 E/QCOMKeyMaster(22157): Loading keymaster app failied E/keystore(22157): could not open keymaster device in keystore (Operation not permitted) E/keystore(22157): keystore keymaster could not be initialized; exiting

(In reply to Ting-Yu Chou [:ting] from comment #42) > From logcat there're a lot of: > > E/GeckoConsole( 210): Content JS LOG at dummy file:352 in > GaiaApps.getDisplayedApp: app with origin > 'app://verticalhome.gaiamobile.org' is displayed > > and there's a bug 1036631 which has been resolved (?). I'll dig into this, the patch of bug 1036631 does not fix it.

I'm not sure if they are the same. Gary, do you think this bug and bug 1036631 are the same?

So GaiaApps.getDisplayedApp is called from here http://mxr.mozilla.org/gaia/source/tests/python/gaia-ui-tests/gaiatest/gaia_test.py#80, but the breakpoint in xpc::EvalInSandbox is not hit nor JS::Evaluate when the script keeps executing repeatedly, any ideas?

(In reply to Paul Yang [: pyang] from comment #45) > Gary, do you think this bug and bug 1036631 are the same? Probably, mine was just a continuous burst of that Content JS LOG message, but I never really got around to verifying that it went away properly after the fix landed. So there is a chance that patch didn't fix the issue.

Ting and I reviewed the patch - it turn off 2 line of log which seems not related. The symptom of this bug is, when it started to burst of message, you need to check following 1. execute javascript from marionette raise timeout all the time 2. cpu high load even suspended 3. unusual memory usage Can you try to reproduce it by latest build?

MTBF runs still encountered this bug multiple times as last run of 10 devices. Some of them even turn themselves off, and there is no log in jenkins about their shutdown of themselves.

(In reply to Ting-Yu Chou [:ting] from comment #46) > So GaiaApps.getDisplayedApp is called from here > http://mxr.mozilla.org/gaia/source/tests/python/gaia-ui-tests/gaiatest/ > gaia_test.py#80, but the breakpoint in xpc::EvalInSandbox is not hit nor > JS::Evaluate > when the script keeps executing repeatedly, any ideas? Not sure if it is related, but from attachment 8493599 [details] there're Sandbox with 1 unknown edge.

I found also GaiaApps.launch() uses waitFor() to wait for the application get launched but does not have a timeout, which will check the condition every 100ms. The checking http://dxr.mozilla.org/mozilla-central/source/testing/marionette/marionette-simpletest.js#178 is not true when timeout is undefined.

Scratch comment 51, correction: When waitFor is called without timeout, and the corresponding Marionette instance has timeout undefined, the waitFor will check the condition every 100ms indefinitely until the test function returns true.

What I found in comment 52 seems duplicate bug 997909, but I haven't figured out is it the reason marionette keeps script timeout. Added more logs for next run as I couldn't repro it locally with the codebase 20140905 in 20 minutes like the subject described.

Paul just reminded me that why waitFor does not timeout, after double checking, its logic is a bit odd: waitFor: function test_waitFor(callback, test, timeout) { ... var now = Date.now(); var deadline = now + (typeof(timeout) == "undefined" ? this.timeout : timeout); if (deadline <= now) { // timeout... } ... this.window.setTimeout(this.waitFor.bind(this), 100, callback, test, deadline - now); }, The 3rd argument to next waitFor call |deadline - now| is exactly the same as timeout or this.timeout, and it does not decrease in following invocations. So if the test function always returns false, the waitFor will never end. Did I misunderstand anything?

You're right, there's a bug in this code. Thanks for pointing it out.

Gary spoke with me about this. I'll take a stab at this tomorrow. ni?ing myself as a reminder

try: https://treeherder.mozilla.org/ui/#/jobs?repo=try&revision=88ca30f0d803

Good job, Ting. We'll trigger another run as soon as patch landed.

When MTBF keeps script timeout, the traceback shows: Traceback (most recent call last): File "/home/ting/w/fx/os/mtbf/venv/local/lib/python2.7/site-packages/marionette_client-0.8.4-py2.7.egg/marionette/marionette_test.py", line 246, in run self.setUp() File "/home/ting/w/fx/os/mtbf/venv/local/lib/python2.7/site-packages/gaiatest-0.28-py2.7.egg/gaiatest/gaia_test.py", line 788, in setUp self.cleanup_gaia(full_reset=True) File "/home/ting/w/fx/os/mtbf/MTBF-Driver/mtbf_driver/MtbfTestCase.py", line 76, in cleanup_gaia self.data_layer.set_setting('lockscreen.passcode-lock.code', '1111') File "/home/ting/w/fx/os/mtbf/venv/local/lib/python2.7/site-packages/gaiatest-0.28-py2.7.egg/gaiatest/gaia_test.py", line 221, in set_setting result = self.marionette.execute_async_script('return GaiaDataLayer.setSetting("%s", %s)' % (name, value), special_powers=True) File "/home/ting/w/fx/os/mtbf/venv/local/lib/python2.7/site-packages/marionette_client-0.8.4-py2.7.egg/marionette/marionette.py", line 1252, in execute_async_script filename=os.path.basename(frame[0])) File "/home/ting/w/fx/os/mtbf/venv/local/lib/python2.7/site-packages/marionette_client-0.8.4-py2.7.egg/marionette/decorators.py", line 35, in _ return func(*args, **kwargs) File "/home/ting/w/fx/os/mtbf/venv/local/lib/python2.7/site-packages/marionette_client-0.8.4-py2.7.egg/marionette/marionette.py", line 638, in _send_message self._handle_error(response) File "/home/ting/w/fx/os/mtbf/venv/local/lib/python2.7/site-packages/marionette_client-0.8.4-py2.7.egg/marionette/marionette.py", line 700, in _handle_error raise errors.ScriptTimeoutException(message=message, status=status, stacktrace=stacktrace) This seems not related to waitFor.

Hi Jonathan, According to #60, The symptom of this bug was gecko rejected marionette to execute script. We triggered several run yesterday, and in some of them, we saw loop log but the test was not stopped; that means blocking execution issue and infinite waitFor should be independent. Therefore the patch is for bug 997909 , not sure whether we should leave the patch there otherwise even if it is landed, we can't mark this bug as resolved fixed.(In reply to Ting-Yu Chou [:ting] from comment #60)

SettingsLock.set is called, but the logs in onsettingstransactionsuccess and onsettingstransactionfailure both not seen from adb logcat: http://mxr.mozilla.org/gaia/source/tests/atoms/gaia_data_layer.js#216

The onsettingstransaction* callbacks are not happened since the set task is queued for waiting another lock. The pending lock actually runs to broadcastMessage() for sending settings change, but is interrupted by a child-process-shutdown because of OOM.

(In reply to Jonathan Griffin (:jgriffin) from comment #58) > try: https://treeherder.mozilla.org/ui/#/jobs?repo=try&revision=88ca30f0d803 A gip run on Try with this patch could be valuable because it uses Settings a lot.

(In reply to Ting-Yu Chou [:ting] from comment #63) > Created attachment 8498099 [details] [diff] [review] > patch v1: Prevent interrupting broadcastMessage() Try: https://treeherder.mozilla.org/ui/#/jobs?repo=try&revision=25e0a6eb30f4

Comment on attachment 8497733 [details] [diff] [review] Make waitFor actually terminate if condition is never true, Review of attachment 8497733 [details] [diff] [review]: ----------------------------------------------------------------- Thanks for the quick fix!

Comment on attachment 8497733 [details] [diff] [review] Make waitFor actually terminate if condition is never true, Moving patch to bug 997909 per pyang.

Comment on attachment 8498099 [details] [diff] [review] patch v1: Prevent interrupting broadcastMessage() Review of attachment 8498099 [details] [diff] [review]: ----------------------------------------------------------------- bent is on vacation.

Added r=khuey to commit message. Kyle, thanks for your help.

Comment on attachment 8498595 [details] [diff] [review] patch v2 Approval Request Comment [Feature/regressing bug #]: n/a [User impact if declined]: settings change will be queued but not executed once the issue occur [Describe test coverage new/current, TBPL]: n/a [Risks and why]: low, simply add a catch [String/UUID change made/needed]: n/a

Paul, Walter, can you verify this is fixed on trunk and 2.1?

Unfortunately, as I saw in last two runs. It still happens for almost 100%...

Correction: It's bug 997909 that didn't get fixed. However, I haven't seem this bug reproduced yet. I think it should be safe.

Verified by latest pvt build.