Closed Bug 1471222 Opened 6 years ago Closed 5 years ago

Intermittent Linux asan Last test finished | application timed out after 370 seconds with no output after tests ran

Categories

(Testing :: Mochitest, defect, P5)

Product:
Testing
Component:
Mochitest
Type:
defect

Tracking

(Not tracked)

Status:
RESOLVED INCOMPLETE

People

(Reporter: intermittent-bug-filer, Unassigned)

References

Details

(Keywords: intermittent-failure) 

Filed by: cbrindusan [at] mozilla.com

https://treeherder.mozilla.org/logviewer.html#?job_id=184901506&repo=autoland

https://queue.taskcluster.net/v1/task/C_9ZLLbiRvGoJ-BNiJsdHw/runs/0/artifacts/public/logs/live_backing.log

https://hg.mozilla.org/mozilla-central/raw-file/tip/layout/tools/reftest/reftest-analyzer.xhtml#logurl=https://queue.taskcluster.net/v1/task/C_9ZLLbiRvGoJ-BNiJsdHw/runs/0/artifacts/public/logs/live_backing.log&only_show_unexpected=1

[task 2018-06-26T11:49:45.505Z] 11:49:45     INFO - REFTEST TEST-START | file:///builds/worker/workspace/build/tests/reftest/tests/layout/reftests/table-anonymous-boxes/white-space-pre-1.html == file:///builds/worker/workspace/build/tests/reftest/tests/layout/reftests/table-anonymous-boxes/white-space-pre-ref.html
[task 2018-06-26T11:49:45.506Z] 11:49:45     INFO - REFTEST TEST-LOAD | file:///builds/worker/workspace/build/tests/reftest/tests/layout/reftests/table-anonymous-boxes/white-space-pre-1.html | 114 / 115 (99%)
[task 2018-06-26T11:49:45.600Z] 11:49:45     INFO - REFTEST TEST-LOAD | file:///builds/worker/workspace/build/tests/reftest/tests/layout/reftests/table-anonymous-boxes/white-space-pre-ref.html | 114 / 115 (99%)
[task 2018-06-26T11:49:45.679Z] 11:49:45     INFO - REFTEST TEST-PASS | file:///builds/worker/workspace/build/tests/reftest/tests/layout/reftests/table-anonymous-boxes/white-space-pre-1.html == file:///builds/worker/workspace/build/tests/reftest/tests/layout/reftests/table-anonymous-boxes/white-space-pre-ref.html | image comparison, max difference: 0, number of differing pixels: 0
[task 2018-06-26T11:49:45.680Z] 11:49:45     INFO - REFTEST TEST-END | file:///builds/worker/workspace/build/tests/reftest/tests/layout/reftests/table-anonymous-boxes/white-space-pre-1.html == file:///builds/worker/workspace/build/tests/reftest/tests/layout/reftests/table-anonymous-boxes/white-space-pre-ref.html
[task 2018-06-26T11:49:45.697Z] 11:49:45     INFO - REFTEST INFO | Slowest test took 655ms (file:///builds/worker/workspace/build/tests/reftest/tests/layout/reftests/table-anonymous-boxes/162063-1.xhtml)
[task 2018-06-26T11:49:45.699Z] 11:49:45     INFO - REFTEST INFO | Total canvas count = 5
[task 2018-06-26T11:49:45.964Z] 11:49:45     INFO - JavaScript error: chrome://reftest/content/reftest.jsm, line 1547: NS_ERROR_NOT_AVAILABLE: Component returned failure code: 0x80040111 (NS_ERROR_NOT_AVAILABLE) [nsIPropertyBag2.getPropertyAsAString]
[task 2018-06-26T11:49:46.022Z] 11:49:46     INFO - JavaScript error: chrome://reftest/content/reftest.jsm, line 1547: NS_ERROR_NOT_AVAILABLE: Component returned failure code: 0x80040111 (NS_ERROR_NOT_AVAILABLE) [nsIPropertyBag2.getPropertyAsAString]
[task 2018-06-26T11:49:46.579Z] 11:49:46     INFO - 1530013786573	Marionette	DEBUG	Received observer notification xpcom-will-shutdown
[task 2018-06-26T11:49:46.579Z] 11:49:46     INFO - 1530013786574	Marionette	INFO	Stopped listening on port 2828
[task 2018-06-26T11:49:46.581Z] 11:49:46     INFO - 1530013786574	Marionette	DEBUG	Remote service is inactive
[task 2018-06-26T11:49:47.189Z] 11:49:47     INFO - REFTEST INFO | Process mode: e10s
[task 2018-06-26T11:49:47.189Z] 11:49:47  WARNING - leakcheck | refcount logging is off, so leaks can't be detected!
[task 2018-06-26T11:49:47.189Z] 11:49:47     INFO - REFTEST INFO | Running tests in file:///builds/worker/workspace/build/tests/reftest/tests/layout/reftests/svg/smil/reftest.list
[task 2018-06-26T11:49:47.213Z] 11:49:47     INFO - REFTEST INFO | INFO | runtests.py | ASan using symbolizer at /builds/worker/workspace/build/application/firefox/llvm-symbolizer
[task 2018-06-26T11:49:47.229Z] 11:49:47     INFO - REFTEST INFO | INFO | runtests.py | ASan running in default memory configuration
[task 2018-06-26T11:49:47.230Z] 11:49:47     INFO - REFTEST INFO | Running with e10s: True
[task 2018-06-26T11:49:47.231Z] 11:49:47     INFO - REFTEST INFO | Application command: /builds/worker/workspace/build/application/firefox/firefox -marionette -profile /tmp/tmpwwTaGq.mozrunner
[task 2018-06-26T11:49:49.061Z] 11:49:49     INFO - 1530013789058	Marionette	DEBUG	Received observer notification profile-after-change
[task 2018-06-26T11:49:49.163Z] 11:49:49     INFO - ATTENTION: default value of option force_s3tc_enable overridden by environment.
[task 2018-06-26T11:49:49.234Z] 11:49:49     INFO - 1530013789229	Marionette	DEBUG	Received observer notification command-line-startup
[task 2018-06-26T11:49:49.234Z] 11:49:49     INFO - 1530013789230	Marionette	DEBUG	Received observer notification nsPref:changed
[task 2018-06-26T11:49:49.234Z] 11:49:49     INFO - 1530013789230	Marionette	DEBUG	Init aborted (running=false, enabled=true, finalUIStartup=false)
[task 2018-06-26T11:49:52.466Z] 11:49:52     INFO - 1530013792456	Marionette	DEBUG	Received observer notification sessionstore-windows-restored
[task 2018-06-26T11:49:52.467Z] 11:49:52     INFO - 1530013792457	Marionette	DEBUG	Waiting for delayed startup...
[task 2018-06-26T11:49:54.554Z] 11:49:54     INFO - 1530013794546	Marionette	DEBUG	Waiting for startup tests...
[task 2018-06-26T11:49:54.845Z] 11:49:54     INFO - 1530013794838	Marionette	INFO	Listening on port 2828
[task 2018-06-26T11:49:54.845Z] 11:49:54     INFO - 1530013794839	Marionette	DEBUG	Remote service is active
[task 2018-06-26T11:49:54.928Z] 11:49:54     INFO - 1530013794924	Marionette	DEBUG	Accepted connection 0 from 127.0.0.1:33564
[task 2018-06-26T11:49:54.945Z] 11:49:54     INFO - 1530013794936	Marionette	DEBUG	Closed connection 0
[task 2018-06-26T11:49:54.945Z] 11:49:54     INFO - 1530013794940	Marionette	DEBUG	Accepted connection 1 from 127.0.0.1:33566
[task 2018-06-26T11:49:54.967Z] 11:49:54     INFO - 1530013794960	Marionette	TRACE	1 -> [0,1,"WebDriver:NewSession",{}]
[task 2018-06-26T11:49:55.472Z] 11:49:55     INFO - 1530013795469	Marionette	DEBUG	[2147483649] Frame script loaded
[task 2018-06-26T11:49:55.477Z] 11:49:55     INFO - 1530013795474	Marionette	DEBUG	[2147483649] Frame script registered
[task 2018-06-26T11:49:55.514Z] 11:49:55     INFO - 1530013795510	Marionette	TRACE	1 <- [1,1,null,{"sessionId":"2b08f0be-9832-4cc5-9fd7-f981ad57a5c4","capabilities":{"browserName":"firefox","browserVersion":"63.0a ... ssID":8730,"moz:profile":"/tmp/tmpwwTaGq.mozrunner","moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true}}]
[task 2018-06-26T11:49:55.550Z] 11:49:55     INFO - 1530013795542	Marionette	TRACE	1 -> [0,2,"Addon:Install",{"path":"/builds/worker/workspace/build/tests/reftest/reftest","temporary":true}]
[task 2018-06-26T11:49:55.687Z] 11:49:55     INFO - 1530013795681	Marionette	TRACE	1 <- [1,2,null,{"value":"reftest@mozilla.org"}]
[task 2018-06-26T11:49:56.402Z] 11:49:56     INFO - 1530013796398	Marionette	TRACE	1 -> [0,3,"WebDriver:DeleteSession",{}]
[task 2018-06-26T11:49:56.406Z] 11:49:56     INFO - 1530013796402	Marionette	TRACE	1 <- [1,3,null,{"value":null}]
[task 2018-06-26T11:49:56.423Z] 11:49:56     INFO - 1530013796418	Marionette	DEBUG	Closed connection 1
[task 2018-06-26T11:49:58.442Z] 11:49:58     INFO - ###!!! [Child][MessageChannel] Error: (msgtype=0x2D00FB,name=PContent::Msg_AccumulateChildKeyedHistograms) Channel closing: too late to send/recv, messages will be lost
[task 2018-06-26T11:49:58.443Z] 11:49:58     INFO - ###!!! [Child][MessageChannel] Error: (msgtype=0x2D00FF,name=PContent::Msg_RecordDiscardedData) Channel closing: too late to send/recv, messages will be lost
[task 2018-06-26T11:50:02.431Z] 11:50:02     INFO - ###!!! [Child][MessageChannel] Error: (msgtype=0x2D00FA,name=PContent::Msg_AccumulateChildHistograms) Channel closing: too late to send/recv, messages will be lost
[task 2018-06-26T11:50:02.432Z] 11:50:02     INFO - ###!!! [Child][MessageChannel] Error: (msgtype=0x2D00FF,name=PContent::Msg_RecordDiscardedData) Channel closing: too late to send/recv, messages will be lost
[task 2018-06-26T11:50:06.773Z] 11:50:06     INFO - ###!!! [Child][MessageChannel] Error: (msgtype=0x2D00FA,name=PContent::Msg_AccumulateChildHistograms) Channel closing: too late to send/recv, messages will be lost
[task 2018-06-26T11:50:06.775Z] 11:50:06     INFO - ###!!! [Child][MessageChannel] Error: (msgtype=0x2D00FF,name=PContent::Msg_RecordDiscardedData) Channel closing: too late to send/recv, messages will be lost
[task 2018-06-26T11:50:08.775Z] 11:50:08     INFO - ###!!! [Child][MessageChannel] Error: (msgtype=0x2D00FA,name=PContent::Msg_AccumulateChildHistograms) Channel closing: too late to send/recv, messages will be lost
[task 2018-06-26T11:50:08.776Z] 11:50:08     INFO - ###!!! [Child][MessageChannel] Error: (msgtype=0x2D00FB,name=PContent::Msg_AccumulateChildKeyedHistograms) Channel closing: too late to send/recv, messages will be lost
[task 2018-06-26T11:50:08.777Z] 11:50:08     INFO - ###!!! [Child][MessageChannel] Error: (msgtype=0x2D00FF,name=PContent::Msg_RecordDiscardedData) Channel closing: too late to send/recv, messages will be lost
[task 2018-06-26T11:50:12.233Z] 11:50:12     INFO - ###!!! [Child][MessageChannel] Error: (msgtype=0x550027,name=PNecko::Msg_RemoveRequestContext) Channel closing: too late to send/recv, messages will be lost
[task 2018-06-26T11:50:13.101Z] 11:50:13     INFO - ###!!! [Child][MessageChannel] Error: (msgtype=0x2D00FA,name=PContent::Msg_AccumulateChildHistograms) Channel closing: too late to send/recv, messages will be lost
[task 2018-06-26T11:50:13.106Z] 11:50:13     INFO - ###!!! [Child][MessageChannel] Error: (msgtype=0x2D00FF,name=PContent::Msg_RecordDiscardedData) Channel closing: too late to send/recv, messages will be lost
[task 2018-06-26T11:50:15.095Z] 11:50:15     INFO - ###!!! [Child][MessageChannel] Error: (msgtype=0x2D00FA,name=PContent::Msg_AccumulateChildHistograms) Channel closing: too late to send/recv, messages will be lost
[task 2018-06-26T11:50:15.096Z] 11:50:15     INFO - ###!!! [Child][MessageChannel] Error: (msgtype=0x2D00FB,name=PContent::Msg_AccumulateChildKeyedHistograms) Channel closing: too late to send/recv, messages will be lost
[task 2018-06-26T11:50:15.098Z] 11:50:15     INFO - ###!!! [Child][MessageChannel] Error: (msgtype=0x2D00FF,name=PContent::Msg_RecordDiscardedData) Channel closing: too late to send/recv, messages will be lost
[task 2018-06-26T11:50:38.394Z] 11:50:38     INFO - ###!!! [Child][MessageChannel] Error: (msgtype=0x2D00FC,name=PContent::Msg_UpdateChildScalars) Channel closing: too late to send/recv, messages will be lost
[task 2018-06-26T11:50:38.397Z] 11:50:38     INFO - ###!!! [Child][MessageChannel] Error: (msgtype=0x2D00FF,name=PContent::Msg_RecordDiscardedData) Channel closing: too late to send/recv, messages will be lost
[task 2018-06-26T11:50:53.247Z] 11:50:53     INFO - ###!!! [Child][MessageChannel] Error: (msgtype=0x2D00FA,name=PContent::Msg_AccumulateChildHistograms) Channel closing: too late to send/recv, messages will be lost
[task 2018-06-26T11:50:53.251Z] 11:50:53     INFO - ###!!! [Child][MessageChannel] Error: (msgtype=0x2D00FF,name=PContent::Msg_RecordDiscardedData) Channel closing: too late to send/recv, messages will be lost
[task 2018-06-26T11:57:03.252Z] 11:57:03    ERROR - REFTEST ERROR | file:///builds/worker/workspace/build/tests/reftest/tests/layout/reftests/table-anonymous-boxes/white-space-pre-1.html | application timed out after 370 seconds with no output
Mochitest timeouts ("application timed out after 370 seconds with no output") during shutdown on Linux asan have increased significantly in the last 2 weeks. Andrea, do you have an idea what's going on or can redirect the needinfo, please?
Component: Layout: Tables → Mochitest
Flags: needinfo?(amarchesini)
Product: Core → Testing
Summary: Intermittent table-anonymous-boxes/white-space-pre-1.html | application timed out after 370 seconds with no output → Intermittent Linux asan <random test> | application timed out after 370 seconds with no output after tests ran
gbrown: Hi, there have been 3 new reftest asan timeouts yesterday:
https://bugzilla.mozilla.org/show_bug.cgi?id=1471762
https://bugzilla.mozilla.org/show_bug.cgi?id=1471776
https://bugzilla.mozilla.org/show_bug.cgi?id=1471801
Could you please take a look? Thank you.
Flags: needinfo?(gbrown)
I think :kmag is looking into it.
Depends on: 1471724
Flags: needinfo?(gbrown) → needinfo?(kmaglione+bmo)
It looks like this hasn't recurred since the last landing of bug 1442737, so it probably isn't an issue for the moment. We really need to fix the <random test> part of it, though, so I'm going to continue with bug 1471724.

I'm also going to see if I can find which changeset made this problem go away, but that will unfortunately not be easy...
Flags: needinfo?(kmaglione+bmo)
Kris is taking care of this bug. Clearing the NI request.
Flags: needinfo?(amarchesini)
Summary: Intermittent Linux asan <random test> | application timed out after 370 seconds with no output after tests ran → Intermittent Linux asan Last test finished | application timed out after 370 seconds with no output after tests ran
Depends on: 1475141
Unfortunately, most of the remaining failures are reftests at this point, so landing this patch won't help until bug 1475141 is fixed.
Based on Comment 62 we're currently waiting for Bug 1475141 to be fixed. 

Removing [stockwell disable-recommended] 

Failure rate has decreased since August 5th. There are currently 3 failures in the last 7 days.
Whiteboard: [stockwell disable-recommended]

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup

Status: NEW → RESOLVED
Closed: 5 years ago
Resolution: --- → INCOMPLETE

New occurrence: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=252207455&repo=autoland&lineNumber=6851

Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Depends on: 1565286

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup

Status: REOPENED → RESOLVED
Closed: 5 years ago → 5 years ago
Resolution: --- → INCOMPLETE
You need to log in before you can comment on or make changes to this bug.