Closed Bug 1269813 Opened 8 years ago Closed 8 years ago

Permanent WinXP/Win8 "test_bug226361.xhtml | application timed out after 330 seconds with no output" or "test_bug1264380.html | Test timed out" on Ash

Categories

(Core :: DOM: Core & HTML, defect)

Product:
Core
Component:
DOM: Core & HTML
Platform:
Unspecified
Windows
Type:
defect
Priority:
Not set
Severity:
critical

Tracking

()

Status:
RESOLVED FIXED
Milestone:
mozilla49
Tracking Flags:
Tracking Status
e10s + ---
firefox47 --- unaffected
firefox48 --- unaffected
firefox49 --- fixed

People

(Reporter: RyanVM, Assigned: bevis)

References

(Blocks 1 open bug)

Details

(Keywords: intermittent-failure, Whiteboard: [e10s-orangeblockers])

Attachments

(2 files)

test screenshot
318.53 KB, image/png
Details
Skip The Test on Windows Platform.
1.32 KB, patch
wchen
: review+
Details | Diff | Splinter Review
Attached image test screenshot — 
I'm kind of amazed that Win7 passes and both WinXP and Win8 have issues, but here we are anyway. Ash is the branch we're using to run e10s tests across all platforms, including those where we're restrained from running in production due to limited capacity. It's standard mozilla-central otherwise and should be treated with similar levels of priority.

Maybe related, maybe not, but I'll note that we also have bug 1268756 on file for an nsBaseDragService permaleak that only affects Win8 in the browser/base/content/test/general tests for some reason.

If you need help reproducing on Try, the patch below will force e10s on for non-e10s test suites (in other words, you'd schedule regular Windows debug mochitest-2 and it will be e10s-enabled anyway).
https://hg.mozilla.org/try/rev/42d59882f94d23328fd4006e2e04870680094339

https://treeherder.mozilla.org/logviewer.html#?job_id=173356&repo=ash#L3253

10:03:19     INFO -  620 INFO TEST-START | dom/events/test/test_bug1264380.html
10:03:19     INFO -  MEMORY STAT | vsize 273MB | vsizeMaxContiguous 473MB | residentFast 111MB | heapAllocated 18MB
10:03:19     INFO -  621 INFO TEST-OK | dom/events/test/test_bug1264380.html | took 66ms
10:03:19     INFO -  622 INFO TEST-START | dom/events/test/test_bug226361.xhtml
10:08:49  WARNING -  TEST-UNEXPECTED-TIMEOUT | dom/events/test/test_bug226361.xhtml | application timed out after 330 seconds with no output
10:08:49     INFO -  Determining child pids from psutil
10:08:49     INFO -  Found child pids: [3380]
10:08:49     INFO -  Killing process: 3380
10:08:49     INFO -  TEST-INFO | started process screenshot
10:08:49     INFO -  TEST-INFO | screenshot: exit 0
10:08:50     INFO -  psutil found pid 3380 dead
10:08:50     INFO -  Killing process: 2724
10:08:50     INFO -  Not taking screenshot here: see the one that was previously logged
10:08:50     INFO -  TEST-INFO | Main app process: exit 1
10:08:50  WARNING -  TEST-UNEXPECTED-FAIL | dom/events/test/test_bug226361.xhtml | application terminated with exit code 1
10:08:50     INFO -  runtests.py | Application ran for: 0:05:41.832000
10:08:50     INFO -  zombiecheck | Reading PID log: c:\docume~1\cltbld~1.t-x\locals~1\temp\tmpcib5rlpidlog
10:08:50     INFO -  ==> process 2724 launched child process 3704 ("C:\slave\test\build\application\firefox\plugin-container.exe" --channel="2724.0.841652355\1622476625" -greomni "C:\slave\test\build\application\firefox\omni.ja" -appomni "C:\slave\test\build\application\firefox\browser\omni.ja" -sandbox -appdir "C:\slave\test\build\application\firefox\browser"  2724 "\\.\pipe\gecko-crash-server-pipe.2724" tab)
10:08:50     INFO -  ==> process 2724 launched child process 3380 ("C:\slave\test\build\application\firefox\plugin-container.exe" --channel="2724.5.227581857\1723671327" -greomni "C:\slave\test\build\application\firefox\omni.ja" -appomni "C:\slave\test\build\application\firefox\browser\omni.ja" -sandbox -appdir "C:\slave\test\build\application\firefox\browser"  2724 "\\.\pipe\gecko-crash-server-pipe.2724" tab)
10:08:50     INFO -  zombiecheck | Checking for orphan process with PID: 3704
10:08:50     INFO -  zombiecheck | Checking for orphan process with PID: 3380
10:08:50     INFO -  mozcrash Downloading symbols from: https://queue.taskcluster.net/v1/task/DrlRuxR1Rke-oPE3RIauhw/artifacts/public/build/firefox-49.0a1.en-US.win32.crashreporter-symbols.zip
10:08:56     INFO -  mozcrash Copy/paste: C:\slave\test\build\win32-minidump_stackwalk.exe c:\docume~1\cltbld~1.t-x\locals~1\temp\tmp2rizuu.mozrunner\minidumps\764dc005-abda-42ff-9fd6-77be16d24861.dmp c:\docume~1\cltbld~1.t-x\locals~1\temp\tmpxpzuqc
10:09:04     INFO -  mozcrash Saved minidump as C:\slave\test\build\blobber_upload_dir\764dc005-abda-42ff-9fd6-77be16d24861.dmp
10:09:04  WARNING -  PROCESS-CRASH | dom/events/test/test_bug226361.xhtml | application crashed [None]
10:09:04     INFO -  Crash dump filename: c:\docume~1\cltbld~1.t-x\locals~1\temp\tmp2rizuu.mozrunner\minidumps\764dc005-abda-42ff-9fd6-77be16d24861.dmp
10:09:04     INFO -  Operating system: Windows NT
10:09:04     INFO -                    5.1.2600 Service Pack 3
10:09:04     INFO -  CPU: x86
10:09:04     INFO -       GenuineIntel family 6 model 30 stepping 5
10:09:04     INFO -       8 CPUs
10:09:04     INFO -  No crash
10:09:04     INFO -  Process uptime: 342 seconds
10:09:04     INFO -  Thread 0
10:09:04     INFO -   0  xul.dll!NowCalibrate [Time.cpp:0a25833062a8 : 103 + 0xc]
10:09:04     INFO -      eip = 0x04d05c02   esp = 0x0012c42c   ebp = 0x0012c450   ebx = 0x0243a200
10:09:04     INFO -      esi = 0x7c8017e9   edi = 0x7c9010e0   eax = 0x7680e6fe   ecx = 0x0012c438
10:09:04     INFO -      edx = 0x0012c448   efl = 0x00000246
10:09:04     INFO -      Found by: given as instruction pointer in context
10:09:04     INFO -   1  xul.dll!PRMJ_Now() [Time.cpp:0a25833062a8 : 176 + 0x5]
10:09:04     INFO -      eip = 0x04d05ec4   esp = 0x0012c458   ebp = 0x0012c49c
10:09:04     INFO -      Found by: call frame info
10:09:04     INFO -   2  xul.dll!js::gc::GCRuntime::maybePeriodicFullGC() [jsgc.cpp:0a25833062a8 : 3407 + 0x5]
10:09:04     INFO -      eip = 0x04b94420   esp = 0x0012c4a4   ebp = 0x0012c4d0
10:09:04     INFO -      Found by: call frame info
10:09:04     INFO -   3  xul.dll!mozilla::dom::AutoEntryScript::~AutoEntryScript() [ScriptSettings.cpp:0a25833062a8 : 680 + 0x8]
10:09:04     INFO -      eip = 0x039b95ff   esp = 0x0012c4d8   ebp = 0x0012c5f4
10:09:04     INFO -      Found by: call frame info
10:09:04     INFO -   4  xul.dll!nsXPCWrappedJSClass::DelegatedQueryInterface(nsXPCWrappedJS *,nsID const &,void * *) [XPCWrappedJSClass.cpp:0a25833062a8 : 596 + 0x36]
10:09:04     INFO -      eip = 0x036c5d52   esp = 0x0012c4e4   ebp = 0x0012c5f4
10:09:04     INFO -      Found by: call frame info
10:09:04     INFO -   5  xul.dll!nsXPCWrappedJS::QueryInterface(nsID const &,void * *) [XPCWrappedJS.cpp:0a25833062a8 : 221 + 0x9]
10:09:04     INFO -      eip = 0x036cd296   esp = 0x0012c5fc   ebp = 0x0012c618
10:09:04     INFO -      Found by: call frame info
10:09:04     INFO -   6  xul.dll!XPCConvert::JSObject2NativeInterface(void * *,JS::Handle<JSObject *>,nsID const *,nsISupports *,nsresult *) [XPCConvert.cpp:0a25833062a8 : 991 + 0x19]
10:09:04     INFO -      eip = 0x036b2817   esp = 0x0012c620   ebp = 0x0012c6a4
10:09:04     INFO -      Found by: call frame info
10:09:04     INFO -   7  xul.dll!XPCConvert::JSData2Native(void *,JS::Handle<JS::Value>,nsXPTType const &,nsID const *,nsresult *) [XPCConvert.cpp:0a25833062a8 : 715 + 0x1a]
10:09:04     INFO -      eip = 0x036b2287   esp = 0x0012c6ac   ebp = 0x0012c7cc
10:09:04     INFO -      Found by: call frame info
10:09:04     INFO -   8  xul.dll!XPCWrappedNative::CallMethod(XPCCallContext &,XPCWrappedNative::CallMode) [XPCWrappedNative.cpp:0a25833062a8 : 1367 + 0x5cf]
10:09:04     INFO -      eip = 0x036c2984   esp = 0x0012c7d4   ebp = 0x0012c968
10:09:04     INFO -      Found by: call frame info
10:09:04     INFO -   9  xul.dll!nsDOMClassInfo::Resolve(nsIXPConnectWrappedNative *,JSContext *,JSObject *,jsid,bool *,bool *) [nsDOMClassInfo.cpp:0a25833062a8 : 850 + 0x10]
10:09:04     INFO -      eip = 0x03a00687   esp = 0x0012c818   ebp = 0x0012c98c
10:09:04     INFO -      Found by: stack scanning
10:09:04     INFO -  10  xul.dll + 0x1ae0490
10:09:04     INFO -      eip = 0x04c30490   esp = 0x0012c8e4   ebp = 0x0012cf3c
10:09:04     INFO -      Found by: call frame info with scanning
10:09:04     INFO -  11  0x12d2e4
10:09:04     INFO -      eip = 0x0012d2e4   esp = 0x0012cf44   ebp = 0x00924830
10:09:04     INFO -      Found by: previous frame's frame pointer

https://treeherder.mozilla.org/logviewer.html#?job_id=173063&repo=ash#L3172

09:47:30     INFO -  620 INFO TEST-START | dom/events/test/test_bug1264380.html
09:47:30     INFO -  MEMORY STAT | vsize 458MB | vsizeMaxContiguous 4467511MB | residentFast 122MB | heapAllocated 24MB
09:47:30     INFO -  621 INFO TEST-OK | dom/events/test/test_bug1264380.html | took 59ms
09:52:53     INFO -  TEST-INFO | started process screenshot
09:52:54     INFO -  TEST-INFO | screenshot: exit 0
09:52:54     INFO -  622 INFO TEST-UNEXPECTED-FAIL | dom/events/test/test_bug1264380.html | Test timed out.

09:59:54  WARNING -  TEST-UNEXPECTED-TIMEOUT | dom/events/test/test_bug1264380.html | application timed out after 330 seconds with no output
09:59:54     INFO -  Determining child pids from psutil
09:59:54     INFO -  Found child pids: [3524]
09:59:54     INFO -  Killing process: 3524
09:59:54     INFO -  Not taking screenshot here: see the one that was previously logged
09:59:54     INFO -  mozcrash Using C:\slave\test\build\tests\bin\minidumpwriter.exe to write a dump to c:\users\cltbld~1.t-w\appdata\local\temp\tmpanbdyu.mozrunner\minidumps\1f948949-fdf4-4fa7-8ec5-fead8b157b36.dmp for [3524]
09:59:56     INFO -  psutil found pid 3524 dead
09:59:56     INFO -  Killing process: 3808
09:59:56     INFO -  Not taking screenshot here: see the one that was previously logged
09:59:56     INFO -  mozcrash Using C:\slave\test\build\tests\bin\minidumpwriter.exe to write a dump to c:\users\cltbld~1.t-w\appdata\local\temp\tmpanbdyu.mozrunner\minidumps\427f96b1-86d2-4565-b755-d902f7b4362e.dmp for [3808]
09:59:56     INFO -  TEST-INFO | Main app process: exit 1
09:59:56  WARNING -  TEST-UNEXPECTED-FAIL | dom/events/test/test_bug1264380.html | application terminated with exit code 1
09:59:56     INFO -  runtests.py | Application ran for: 0:12:39.787000
09:59:56     INFO -  zombiecheck | Reading PID log: c:\users\cltbld~1.t-w\appdata\local\temp\tmpupasuhpidlog
09:59:56     INFO -  ==> process 3808 launched child process 3580 ("C:\slave\test\build\application\firefox\plugin-container.exe" --channel="3808.0.1036052459\635447369" -greomni "C:\slave\test\build\application\firefox\omni.ja" -appomni "C:\slave\test\build\application\firefox\browser\omni.ja" -sandbox -appdir "C:\slave\test\build\application\firefox\browser"  3808 "\\.\pipe\gecko-crash-server-pipe.3808" tab)
09:59:56     INFO -  ==> process 3808 launched child process 3524 ("C:\slave\test\build\application\firefox\plugin-container.exe" --channel="3808.5.1381015924\805752296" -greomni "C:\slave\test\build\application\firefox\omni.ja" -appomni "C:\slave\test\build\application\firefox\browser\omni.ja" -sandbox -appdir "C:\slave\test\build\application\firefox\browser"  3808 "\\.\pipe\gecko-crash-server-pipe.3808" tab)
09:59:56     INFO -  zombiecheck | Checking for orphan process with PID: 3580
09:59:56     INFO -  zombiecheck | Checking for orphan process with PID: 3524
09:59:56     INFO -  mozcrash Downloading symbols from: https://queue.taskcluster.net/v1/task/Eme4Lu3vQn2qyLiLlTZgGQ/artifacts/public/build/firefox-49.0a1.en-US.win64.crashreporter-symbols.zip
10:00:06     INFO -  mozcrash Copy/paste: C:\slave\test\build\win32-minidump_stackwalk.exe c:\users\cltbld~1.t-w\appdata\local\temp\tmpanbdyu.mozrunner\minidumps\1f948949-fdf4-4fa7-8ec5-fead8b157b36.dmp c:\users\cltbld~1.t-w\appdata\local\temp\tmpoydbpm
10:00:10     INFO -  mozcrash Saved minidump as C:\slave\test\build\blobber_upload_dir\1f948949-fdf4-4fa7-8ec5-fead8b157b36.dmp
10:00:10  WARNING -  PROCESS-CRASH | dom/events/test/test_bug1264380.html | application crashed [None]
10:00:10     INFO -  Crash dump filename: c:\users\cltbld~1.t-w\appdata\local\temp\tmpanbdyu.mozrunner\minidumps\1f948949-fdf4-4fa7-8ec5-fead8b157b36.dmp
10:00:10     INFO -  Operating system: Windows NT
10:00:10     INFO -                    6.2.9200
10:00:10     INFO -  CPU: amd64
10:00:10     INFO -       family 6 model 30 stepping 5
10:00:10     INFO -       8 CPUs
10:00:10     INFO -  No crash
10:00:10     INFO -  Process uptime: 753 seconds
10:00:10     INFO -  Thread 0
10:00:10     INFO -   0  ntdll.dll!ZwWaitForMultipleObjects + 0xa
10:00:10     INFO -      rax = 0x0000000000000001   rdx = 0x0000007ece000a40
10:00:10     INFO -      rcx = 0x00000000ffffffff   rbx = 0x0000000000000001
10:00:10     INFO -      rsi = 0x0000000000000000   rdi = 0x0000000000000001
10:00:10     INFO -      rbp = 0x0000000000000000   rsp = 0x0000007ec3e1e848
10:00:10     INFO -       r8 = 0x0000007ed6101778    r9 = 0x0000007ec5800778
10:00:10     INFO -      r10 = 0x0000000000000000   r11 = 0x0000007ece06ff00
10:00:10     INFO -      r12 = 0x0000000000000000   r13 = 0x0000007ec3e1eb60
10:00:10     INFO -      r14 = 0x0000000000000000   r15 = 0x0000000000000000
10:00:10     INFO -      rip = 0x000007ff4e14315b
10:00:10     INFO -      Found by: given as instruction pointer in context
10:00:10     INFO -   1  KERNELBASE.dll!memset + 0x42
10:00:10     INFO -      rsp = 0x0000007ec3e1e850   rip = 0x000007ff4b1c12c6
10:00:10     INFO -      Found by: stack scanning
10:00:10     INFO -   2  xul.dll!mozilla::layers::PCompositorBridgeChild::OnMessageReceived(IPC::Message const &) [PCompositorBridgeChild.cpp:0a25833062a8 : 1260 + 0xf]
10:00:10     INFO -      rsp = 0x0000007ec3e1e860   rip = 0x000007ff30e2adb7
10:00:10     INFO -      Found by: stack scanning
10:00:10     INFO -   3  KERNELBASE.dll!ReleaseSemaphore + 0xa
10:00:10     INFO -      rsp = 0x0000007ec3e1ea50   rip = 0x000007ff4b1c1a22
10:00:10     INFO -      Found by: call frame info
10:00:10     INFO -   4  nss3.dll!md_UnlockAndPostNotifies [w95cv.c:0a25833062a8 : 161 + 0x10]
10:00:10     INFO -      rsp = 0x0000007ec3e1ea60   rip = 0x000007ff40c813f0
10:00:10     INFO -      Found by: stack scanning
10:00:10     INFO -   5  nss3.dll!PR_Unlock [prulock.c:0a25833062a8 : 328 + 0x9]
10:00:10     INFO -      rsp = 0x0000007ec3e1eb60   rip = 0x000007ff40c8e847
10:00:10     INFO -      Found by: call frame info
10:00:10     INFO -   6  nss3.dll!PR_Interrupt [prcthr.c:0a25833062a8 : 166 + 0xc]
10:00:10     INFO -      rsp = 0x0000007ec3e1eb90   rip = 0x000007ff40c9066c
10:00:10     INFO -      Found by: call frame info
Flags: needinfo?(btseng)
See Also: → 1270043
Unfortunately, we are not able to have a stable drag session test on windows platform yet. (Tests on Windows XP & Windows 8 in treeherder were not enabled by default as explained at comment 0. That's why we didn't catch this while fixing bug 1264380.)

After the comparison on treeherder listed below, the fix of bug 1264380 in DataTransfer.cpp is fine.
However, the usage of dragService.endDragSession() in test_bug1264380.html is not stable and might not be proper in windows platform which causes either test_bug1264380.html failed or affect the test result of another test case in test_bug226361.xhtml.

To have a quick fix of this problem, I'd like to narrow down the test scope in (e10s && os != "win") and file a follow-up in bug 1270043 to address this in the future.

--
Failed on Windows 8 and cause another test case(test_bug226361.xhtml) failed in Windows XP:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=647e95219f55&filter-searchStr=Mochitest%20Mochitest%20M%20%282%29
https://treeherder.mozilla.org/#/jobs?repo=try&revision=7371511387f9&filter-searchStr=Mochitest%20Mochitest%20M%20%282%29

Passed if test_bug1264380.html is skipped:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=7a1e1770602e&filter-searchStr=Mochitest%20Mochitest%20M%20%282%29
https://treeherder.mozilla.org/#/jobs?repo=try&revision=4f7508bd693c&filter-searchStr=Mochitest%20Mochitest%20M%20%282%29
Assignee: nobody → btseng
Status: NEW → ASSIGNED
Flags: needinfo?(btseng)
Attachment #8748559 - Flags: review?(wchen)
Attachment #8748559 - Flags: review?(wchen) → review+
https://hg.mozilla.org/mozilla-central/rev/b2cc990b4246
Status: ASSIGNED → RESOLVED
Closed: 8 years ago
status-firefox49: affected → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla49
Component: DOM → DOM: Core & HTML
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: