Closed Bug 924972 Opened 11 years ago Closed 10 years ago

Intermittent B2G test_reftests_with_caret.html | application timed out after 330 seconds with no output

Categories

(Firefox OS Graveyard :: General, defect)

Product:
Firefox OS Graveyard
Component:
General
Platform:
ARM
Gonk (Firefox OS)
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

(firefox27 wontfix, firefox28 wontfix, firefox29 fixed, firefox-esr24 wontfix, b2g-v1.2 wontfix)

Status:
RESOLVED WORKSFORME
Milestone:
1.3 Sprint 6 - 12/6
Tracking Flags:
Tracking Status
firefox27 --- wontfix
firefox28 --- wontfix
firefox29 --- fixed
firefox-esr24 --- wontfix
b2g-v1.2 --- wontfix

People

(Reporter: emorley, Assigned: ehsan.akhgari)

References

Details

(Keywords: intermittent-failure)

Attachments

(1 file, 1 obsolete file)

Patch (v1)
1.47 KB, patch
enndeakin
: review+
Details | Diff | Splinter Review 
Broken out from bug 820739 comment 845...

b2g_emulator_vm mozilla-inbound opt test mochitest-9 on 2013-10-01 16:43:47 PDT for push 7eca799dbebc

slave: tst-linux64-ec2-441

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

{
16:56:03     INFO -  591 INFO TEST-START | /tests/layout/base/tests/test_reftests_with_caret.html
16:56:03     INFO -  592 INFO TEST-PASS | /tests/layout/base/tests/test_reftests_with_caret.html | Spellcheck should be turned off for this platrom or this if..else check removed
16:56:03     INFO -  593 INFO TEST-PASS | /tests/layout/base/tests/test_reftests_with_caret.html | Reftest http://mochi.test:8888/tests/layout/base/tests/bug389321-2.html
16:56:03     INFO -  594 INFO TEST-PASS | /tests/layout/base/tests/test_reftests_with_caret.html | Reftest http://mochi.test:8888/tests/layout/base/tests/bug389321-3.html
16:56:03     INFO -  595 INFO TEST-PASS | /tests/layout/base/tests/test_reftests_with_caret.html | Reftest http://mochi.test:8888/tests/layout/base/tests/bug585922.html
16:56:03     INFO -  596 INFO TEST-PASS | /tests/layout/base/tests/test_reftests_with_caret.html | Reftest http://mochi.test:8888/tests/layout/base/tests/bug632215-1.html
16:56:03     INFO -  597 INFO TEST-PASS | /tests/layout/base/tests/test_reftests_with_caret.html | Reftest http://mochi.test:8888/tests/layout/base/tests/bug632215-2.html
16:56:03     INFO -  598 INFO TEST-PASS | /tests/layout/base/tests/test_reftests_with_caret.html | Reftest http://mochi.test:8888/tests/layout/base/tests/bug633044-1.html
16:56:03     INFO -  599 INFO TEST-PASS | /tests/layout/base/tests/test_reftests_with_caret.html | Reftest http://mochi.test:8888/tests/layout/base/tests/bug240933-1.html
16:56:03     INFO -  600 INFO TEST-PASS | /tests/layout/base/tests/test_reftests_with_caret.html | Reftest http://mochi.test:8888/tests/layout/base/tests/bug240933-2.html
16:56:03     INFO -  Failed to get window.getSelection()
16:56:03     INFO -  Failed to get window.getSelection()
16:56:03     INFO -  Failed to get window.getSelection()
16:56:03     INFO -  Failed to get window.getSelection()
16:56:03     INFO -  Failed to get window.getSelection()
16:56:03     INFO -  Failed to get window.getSelection()
16:56:03     INFO -  601 INFO TEST-PASS | /tests/layout/base/tests/test_reftests_with_caret.html | Reftest http://mochi.test:8888/tests/layout/base/tests/bug389321-1.html
16:56:03     INFO -  602 INFO TEST-PASS | /tests/layout/base/tests/test_reftests_with_caret.html | Reftest http://mochi.test:8888/tests/layout/base/tests/bug482484.html
16:56:03     INFO -  603 INFO TEST-PASS | /tests/layout/base/tests/test_reftests_with_caret.html | Reftest http://mochi.test:8888/tests/layout/base/tests/bug597519-1.html
16:56:03     INFO -  604 INFO TEST-PASS | /tests/layout/base/tests/test_reftests_with_caret.html | Reftest http://mochi.test:8888/tests/layout/base/tests/bug602141-1.html
16:56:03     INFO -  605 INFO TEST-PASS | /tests/layout/base/tests/test_reftests_with_caret.html | Reftest http://mochi.test:8888/tests/layout/base/tests/bug602141-2.html
16:56:03     INFO -  606 INFO TEST-PASS | /tests/layout/base/tests/test_reftests_with_caret.html | Reftest http://mochi.test:8888/tests/layout/base/tests/bug602141-3.html
16:56:03     INFO -  607 INFO TEST-PASS | /tests/layout/base/tests/test_reftests_with_caret.html | Reftest http://mochi.test:8888/tests/layout/base/tests/bug602141-4.html
16:56:03     INFO -  608 INFO TEST-PASS | /tests/layout/base/tests/test_reftests_with_caret.html | Reftest http://mochi.test:8888/tests/layout/base/tests/bug612271-1.html
16:56:03     INFO -  609 INFO TEST-PASS | /tests/layout/base/tests/test_reftests_with_caret.html | Reftest http://mochi.test:8888/tests/layout/base/tests/bug612271-2.html
16:56:03     INFO -  610 INFO TEST-PASS | /tests/layout/base/tests/test_reftests_with_caret.html | Reftest http://mochi.test:8888/tests/layout/base/tests/bug612271-3.html
16:56:03     INFO -  611 INFO TEST-PASS | /tests/layout/base/tests/test_reftests_with_caret.html | Reftest http://mochi.test:8888/tests/layout/base/tests/bug613433-1.html
16:56:03     INFO -  612 INFO TEST-PASS | /tests/layout/base/tests/test_reftests_with_caret.html | Reftest http://mochi.test:8888/tests/layout/base/tests/bug613433-2.html
16:56:03     INFO -  613 INFO TEST-PASS | /tests/layout/base/tests/test_reftests_with_caret.html | Reftest http://mochi.test:8888/tests/layout/base/tests/bug613433-3.html
16:56:03     INFO -  JavaScript error: , line 0: Permission denied to access property 'toString'
16:56:03     INFO -  JavaScript error: , line 0: Permission denied to access property 'message'

command timed out: 1200 seconds without output, attempting to kill
process killed by signal 9
program finished with exit code -1
elapsedTime=1929.535770
========= Finished '/tools/buildbot/bin/python scripts/scripts/b2g_emulator_unittest.py ...' failed (results: 2, elapsed: 32 mins, 9 secs) (at 2013-10-01 17:16:03.339117) =========
}
Flags: needinfo?(ehsan)
I think this bug is basically about us running out of time when running this test.  Let's try to increase the timeout first.

https://hg.mozilla.org/integration/mozilla-inbound/rev/1e7ec87921a5
Assignee: nobody → ehsan
Flags: needinfo?(ehsan)
https://hg.mozilla.org/mozilla-central/rev/1e7ec87921a5
Status: NEW → RESOLVED
Closed: 11 years ago
Resolution: --- → FIXED
Target Milestone: --- → 1.3 Sprint 6 - 12/6
Summary: Intermittent B2G test_reftests_with_caret.html "command timed out: 1200 seconds without output, attempting to kill" → Intermittent B2G test_reftests_with_caret.html "command timed out: 1200 seconds without output, attempting to kill" or "application timed out after 330 seconds with no output"
seems not to be fixed :(
Status: RESOLVED → REOPENED
Resolution: FIXED → ---
Yeah... it actually hasn't made any difference at all.

Does anybody know what these "INFO -  System JS : ERROR (null):0 - uncaught exception: 2147746065" messages are?
No, but you can see them in plenty of non-B2G mochitest runs as well.
(In reply to comment #29)
> No, but you can see them in plenty of non-B2G mochitest runs as well.

Hmm, I see.  Are we seeing similar hard to explain timeouts in other tests on these runs?
Updating summary to reflect that the harness now handles these properly, so we don't get "command timed out: 1200 seconds without output, attempting to kill" failures modes for this any more :-)
Summary: Intermittent B2G test_reftests_with_caret.html "command timed out: 1200 seconds without output, attempting to kill" or "application timed out after 330 seconds with no output" → Intermittent B2G test_reftests_with_caret.html | application timed out after 330 seconds with no output
I tried to see if I can reproduce this today but ran into bug 961236.
Depends on: 961236
OK, I can reproduce this locally 100% of the time.  This is the test which fails to load completely: <http://mxr.mozilla.org/mozilla-central/source/layout/base/tests/bug613433-ref.html>.  I tried to grab a focus manager log by #defining PR_LOGGING in nsFocusManager.cpp and modifying b2g.sh like this:

$ git diff
diff --git a/b2g.sh b/b2g.sh
index ca7694a..5c33d75 100755
--- a/b2g.sh
+++ b/b2g.sh
@@ -38,6 +38,9 @@ if [ -f "$B2G_DIR/libdmd.so" ]; then
 fi
 export LD_PRELOAD
 
+export NSPR_LOG_MODULES=Focus:5,FocusNavigation:5
+export NSPR_LOG_FILE=/data/local/tmp/focus.log
+
 export LD_LIBRARY_PATH=/vendor/lib:/system/lib:"$B2G_DIR"
 export GRE_HOME="$B2G_DIR"
 exec $COMMAND_PREFIX "$B2G_DIR/b2g"

But the focus.log file on the emulator is empty after I run these tests.  Neil, can you please see if you can figure out what I'm not doing right here?

Thanks!
Flags: needinfo?(enndeakin)
Attached file focus.log (obsolete) — 
I managed to fix my NSPR logging problem by using forced logging, and this is the resulting log file.  I am not sure if this is what I would expect here at all.  Neil, can you decipher this file?  Why are there so few entries inside it?  What's going wrong with the focus here?

FWIW here is how to run this test on a local emulator build:

./mach mochitest-remote layout/base/tests/test_reftests_with_caret.html
Attachment #8362639 - Attachment mime type: text/x-log → text/plain
The log says that a blank page is being loaded but not any test page. The window is not being raised. I can't say why the the url isn't loading but the widget layer should be calling nsWebShellWindow::WindowActivated.
Flags: needinfo?(enndeakin)
I suspected this weirdness is caused by the NSPR logging macros so I just changed them to use __android_log_print.  With that, I get better focus logs:

I/GeckoDump(  331): TEST-PASS | unknown test url | Reftest http://mochi.test:8888/tests/layout/base/tests/bug612271-3.html
I/Gecko   (  331): Window 0x43248960 Hidden [Currently: 0x0 0x0]
I/Gecko   (  331):   Hide Window: http://mochi.test:8888/tests/layout/base/tests/bug612271-3.html
I/Gecko   (  331): Window 0x432485c0 Hidden [Currently: 0x0 0x0]
I/Gecko   (  331):   Hide Window: http://mochi.test:8888/tests/layout/base/tests/bug612271-ref.html
I/Gecko   (  331): <<SetFocus begin>>
I/Gecko   (  331): Cannot focus iframe because content not in document
I/Gecko   (  331): <<SetFocus end>>
I/Gecko   (  331): <<SetFocus begin>>
I/Gecko   (  331): Shift Focus: div
I/Gecko   (  331):  Flags: 0 Current Window: 0x0 New Window: 0x43248790 Current Element: 0x0
I/Gecko   (  331):  In Active Window: 0 In Focused Window: 0 SendFocus: 0
I/Gecko   (  331): <<SetFocus end>>
E/GeckoConsole(  331): [JavaScript Error: "The Components object is deprecated. It will soon be removed." {file: "http://mochi.test:8888/tests/SimpleTest/EventUtils.js" line: 27}]
I/Gecko   (  331): Window 0x43248790 Shown [Currently: 0x0 0x0]
I/Gecko   (  331): Shown Window: http://mochi.test:8888/tests/layout/base/tests/bug613433-1.html
I/Gecko   (  331): [SharedSurface_Gralloc 0x430fdca0] destroyed
I/Gecko   (  331): SharedSurface_Gralloc::Create -------
I/Gecko   (  331): SharedSurface_Gralloc::Create: success -- surface 0x430fdca0, GraphicBuffer 0x43bcc680.
I/Gecko   (  331): <<SetFocus begin>>
I/Gecko   (  331): Cannot focus iframe because content not in document
I/Gecko   (  331): <<SetFocus end>>
I/Gecko   (  331): <<SetFocus begin>>
I/Gecko   (  331): Shift Focus: div
I/Gecko   (  331):  Flags: 0 Current Window: 0x0 New Window: 0x43248ed0 Current Element: 0x0
I/Gecko   (  331):  In Active Window: 0 In Focused Window: 0 SendFocus: 0
I/Gecko   (  331): <<SetFocus end>>
I/Gecko   (  331): Window 0x43248ed0 Shown [Currently: 0x0 0x0]
I/Gecko   (  331): Shown Window: http://mochi.test:8888/tests/layout/base/tests/bug613433-ref.html
I/Gecko   (  331): [SharedSurface_Gralloc 0x43261f40] destroyed
I/GeckoDump(  331): TEST-UNEXPECTED-FAIL | unknown test url | iframe load for bug613433-ref.html timed out
Flags: needinfo?(enndeakin)
That log is better but still shows that the window isn't being raised. If it were, then the bits that say [Currently: 0x0 0x0] should be outputting non-zeroes.

I'm assuming you are running just this test on its own?

Maybe the test needs to use waitForFocus instead of using onload, assuming it is available.
Flags: needinfo?(enndeakin)
Attached patch Patch (v1) — — Splinter Review 
Indeed there are two problems here:

1. This test should have used waitForFocus()
2. The call to iframe.focus() must happen after the iframe is added to the document.  The focus manager debug logs made this clear.

With this patch, the failure doesn't happen locally any more.
Attachment #8362639 - Attachment is obsolete: true
Attachment #8362667 - Flags: review?(enndeakin)
Attachment #8362667 - Flags: review?(enndeakin) → review+
This will hopefully fix this orange and also many other problems we've had with this test!

https://hg.mozilla.org/integration/mozilla-inbound/rev/fa16b32c7ada
I also backed out the debugging patch I pushed earlier in this bug: https://hg.mozilla.org/integration/mozilla-inbound/rev/4d5f60e6521e
Thank you for digging into this! :-)
Blocks: 961919
https://hg.mozilla.org/mozilla-central/rev/fa16b32c7ada
Status: REOPENED → RESOLVED
Closed: 11 years ago → 10 years ago
Resolution: --- → FIXED
Comment 116 is on a push with this patch, but let's try to enforce the focus before loading every subtest, like this:

https://hg.mozilla.org/integration/mozilla-inbound/rev/746018b05d67
Status: RESOLVED → REOPENED
Resolution: FIXED → ---
Backed it out because it broke stuff :(

https://hg.mozilla.org/integration/mozilla-inbound/rev/ac50946eb2ea
https://hg.mozilla.org/mozilla-central/rev/1eb2405c8c18
Status: REOPENED → RESOLVED
Closed: 10 years ago → 10 years ago
Resolution: --- → FIXED
Unless you have a strong objection, I'm not going to bother backporting this to the branches.
status-b2g-v1.2: --- → wontfix
status-firefox27: --- → wontfix
status-firefox28: --- → wontfix
status-firefox29: --- → fixed
status-firefox-esr24: --- → wontfix
(In reply to Ryan VanderMeulen [:RyanVM UTC-5] from comment #121)
> Unless you have a strong objection, I'm not going to bother backporting this
> to the branches.

No objections from me!
Status: RESOLVED → REOPENED
Resolution: FIXED → ---
Neil, are there known cases where waitForFocus would not be able to set the focus on b2g?  I think that's currently the only theory which can explain the test failures in comment 124 and 125...
Flags: needinfo?(enndeakin)
Sorry, I don't know.
Flags: needinfo?(enndeakin)
But if you can reproduce locally, you should be able to trace through where this is failing if waitForFocus is indeed failing. It should at least be getting to nsWindow::SetFocus, which in turn should be raising the window by calling nsIWidgetListener::WindowActivated. On other platforms, there is an OS layer step in-between those two steps where something sometimes goes wrong, especially on Linux. I'm not about the situation here.
I haven't been able to reproduce locally, but I'll try again next week.
Closing bugs where TBPLbot has previously commented, but have now not been modified for >3 months & do not contain the whiteboard strings for disabled/annotated tests or use the keyword leave-open. Filter on: mass-intermittent-bug-closure-2014-07
Status: REOPENED → RESOLVED
Closed: 10 years ago → 10 years ago
Resolution: --- → WORKSFORME
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: