Open Bug 1615608 Opened 5 years ago Updated 1 year ago

Intermittent linux-tsan ThreadSanitizer: nested bug in the same thread, aborting.

Categories

(Testing :: General, defect, P5)

Version 3
defect

Tracking

(Not tracked)

People

(Reporter: intermittent-bug-filer, Unassigned)

References

(Blocks 1 open bug, )

Details

(Keywords: intermittent-failure, Whiteboard: [stockwell unknown])

Attachments

(1 obsolete file)

Filed by: aciure [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=288928788&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/RjudD43bRGaUq44tnDrgOw/runs/0/artifacts/public/logs/live_backing.log


[task 2020-02-14T13:38:43.955Z] 13:38:43 INFO - GECKO(3115) | Console message: [JavaScript Error: "The character encoding of the HTML document was not declared. The document will render with garbled text in some browser configurations if the document contains characters from outside the US-ASCII range. The character encoding of the page must be declared in the document or in the transfer protocol." {file: "http://mochi.test:8888/tests/toolkit/components/extensions/test/mochitest/file_WebNavigation_page1.html" line: 0}]
[task 2020-02-14T13:38:44.863Z] 13:38:44 INFO - GECKO(3115) | Console message: [JavaScript Warning: "The character encoding of a framed document was not declared. The document may appear different if viewed without the document framing it." {file: "http://mochi.test:8888/tests/toolkit/components/extensions/test/mochitest/file_WebNavigation_page2.html" line: 0}]
[task 2020-02-14T13:38:45.753Z] 13:38:45 INFO - GECKO(3115) | ==3406==WARNING: Symbolizer buffer too small
[task 2020-02-14T13:38:45.753Z] 13:38:45 INFO - GECKO(3115) | ==3406==WARNING: Symbolizer buffer too small
[task 2020-02-14T13:38:45.753Z] 13:38:45 INFO - GECKO(3115) | ThreadSanitizer:DEADLYSIGNAL
[task 2020-02-14T13:38:45.753Z] 13:38:45 INFO - GECKO(3115) | ThreadSanitizer: nested bug in the same thread, aborting.
[task 2020-02-14T13:38:45.816Z] 13:38:45 INFO - GECKO(3115) | ###!!! [Parent][MessageChannel] Error: (msgtype=0x1E0079,name=PBrowser::Msg_ParentActivated) Channel error: cannot send/recv
[task 2020-02-14T13:38:45.816Z] 13:38:45 INFO - GECKO(3115) | ###!!! [Parent][MessageChannel] Error: (msgtype=0x1E0079,name=PBrowser::Msg_ParentActivated) Channel error: cannot send/recv
[task 2020-02-14T13:38:45.844Z] 13:38:45 INFO - GECKO(3115) | ###!!! [Parent][MessageChannel] Error: (msgtype=0x1E0051,name=PBrowser::Msg_FlushTabState) Channel error: cannot send/recv
[task 2020-02-14T13:38:45.844Z] 13:38:45 INFO - GECKO(3115) | ###!!! [Parent][MessageChannel] Error: (msgtype=0x1E0096,name=PBrowser::Msg_Destroy) Channel error: cannot send/recv
[task 2020-02-14T13:38:45.844Z] 13:38:45 INFO - GECKO(3115) | ###!!! [Parent][MessageChannel] Error: (msgtype=0x370135,name=PContent::Msg_DetachBrowsingContext) Channel error: cannot send/recv
[task 2020-02-14T13:38:45.940Z] 13:38:45 INFO - GECKO(3115) | ###!!! [Parent][MessageChannel] Error: (msgtype=0x1E0057,name=PBrowser::Msg_UpdateEffects) Channel error: cannot send/recv
[task 2020-02-14T13:38:45.941Z] 13:38:45 INFO - GECKO(3115) | ###!!! [Parent][MessageChannel] Error: (msgtype=0x1E0051,name=PBrowser::Msg_FlushTabState) Channel error: cannot send/recv
[task 2020-02-14T13:38:45.941Z] 13:38:45 INFO - GECKO(3115) | ###!!! [Parent][MessageChannel] Error: (msgtype=0x1E007B,name=PBrowser::Msg_StopIMEStateManagement) Channel error: cannot send/recv
[task 2020-02-14T13:38:45.941Z] 13:38:45 INFO - GECKO(3115) | ###!!! [Parent][MessageChannel] Error: (msgtype=0x1E0096,name=PBrowser::Msg_Destroy) Channel error: cannot send/recv
[task 2020-02-14T13:38:45.941Z] 13:38:45 INFO - GECKO(3115) | ###!!! [Parent][MessageChannel] Error: (msgtype=0x370135,name=PContent::Msg_DetachBrowsingContext) Channel error: cannot send/recv
[task 2020-02-14T13:38:46.037Z] 13:38:46 ERROR - GECKO(3115) | A content process crashed and MOZ_CRASHREPORTER_SHUTDOWN is set, shutting down
[task 2020-02-14T13:39:01.640Z] 13:39:01 INFO - GECKO(3115) | Console message: [JavaScript Error: "SessionStore: exception whilst flushing all windows: [Exception... "Component returned failure code: 0x80070057 (NS_ERROR_ILLEGAL_VALUE) [nsIObserverService.removeObserver]" nsresult: "0x80070057 (NS_ERROR_ILLEGAL_VALUE)" location: "JS frame :: resource:///modules/sessionstore/SessionStore.jsm :: cleanup :: line 1835" data: no]" {file: "resource:///modules/sessionstore/SessionStore.jsm" line: 1837}]
[task 2020-02-14T13:39:01.641Z] 13:39:01 INFO - GECKO(3115) | cleanup@resource:///modules/sessionstore/SessionStore.jsm:1837:20
[task 2020-02-14T13:39:01.642Z] 13:39:01 INFO - GECKO(3115) | observe@resource://gre/modules/AsyncShutdown.jsm:551:16
[task 2020-02-14T13:39:01.643Z] 13:39:01 INFO - GECKO(3115) | observe@resource:///modules/ContentCrashHandlers.jsm:177:28
[task 2020-02-14T13:39:01.644Z] 13:39:01 INFO - GECKO(3115) | Console message: [JavaScript Error: "SessionStore: exception whilst flushing all windows: [Exception... "Component returned failure code: 0x80070057 (NS_ERROR_ILLEGAL_VALUE) [nsIObserverService.removeObserver]" nsresult: "0x80070057 (NS_ERROR_ILLEGAL_VALUE)" location: "JS frame :: resource:///modules/sessionstore/SessionStore.jsm :: cleanup :: line 1835" data: no]" {file: "resource:///modules/sessionstore/SessionStore.jsm" line: 1837}]
[task 2020-02-14T13:39:01.644Z] 13:39:01 INFO - GECKO(3115) | cleanup@resource:///modules/sessionstore/SessionStore.jsm:1837:20
[task 2020-02-14T13:39:01.645Z] 13:39:01 INFO - GECKO(3115) | observe@resource://gre/modules/AsyncShutdown.jsm:551:16
[task 2020-02-14T13:39:01.646Z] 13:39:01 INFO - GECKO(3115) | observe@resource:///modules/ContentCrashHandlers.jsm:177:28
[task 2020-02-14T13:39:03.673Z] 13:39:03 INFO - GECKO(3115) | Console message: 1581687543320 Toolkit.Telemetry WARN TelemetryEnvironment::registerChangeListener - already shutdown
[task 2020-02-14T13:39:03.814Z] 13:39:03 INFO - GECKO(3115) | 1581687543807 Marionette TRACE Received observer notification xpcom-will-shutdown
[task 2020-02-14T13:39:03.815Z] 13:39:03 INFO - GECKO(3115) | 1581687543808 Marionette INFO Stopped listening on port 2828
[task 2020-02-14T13:39:03.815Z] 13:39:03 INFO - GECKO(3115) | 1581687543808 Marionette DEBUG Marionette stopped listening
[task 2020-02-14T13:39:03.831Z] 13:39:03 INFO - GECKO(3115) | *** WIFI GEO: shutdown called
[task 2020-02-14T13:39:03.892Z] 13:39:03 INFO - GECKO(3115) | Console message: *** WIFI GEO: shutdown called
[task 2020-02-14T13:39:05.382Z] 13:39:05 INFO - TEST-INFO | Main app process: exit 0
[task 2020-02-14T13:39:05.383Z] 13:39:05 INFO - runtests.py | Application ran for: 0:05:02.608471
[task 2020-02-14T13:39:05.383Z] 13:39:05 INFO - zombiecheck | Reading PID log: /tmp/tmpGs05M6pidlog

The PR at https://github.com/mozilla/treeherder/pull/6016 should make this more visible on Treeherder. TSan does not emit a SUMMARY when it hits this nested bug situation, which makes this particular intermittent hard to recognize right now.

Blocks: tsan
Depends on: 1624857

There are 20 failures associated to this bug in the last 7 days. These are occurring on linux1804-64-tsan, opt.

log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=299928498&repo=autoland&lineNumber=1703
[task 2020-04-29T03:46:38.394Z] 03:46:38 INFO - GECKO(1552) | 1588131998385 Marionette TRACE Received observer notification marionette-startup-requested
[task 2020-04-29T03:46:38.396Z] 03:46:38 INFO - GECKO(1552) | 1588131998388 Marionette TRACE Waiting until startup recorder finished recording startup scripts...
[task 2020-04-29T03:46:40.252Z] 03:46:40 INFO - GECKO(1552) | 1588132000243 Marionette TRACE All scripts recorded.
[task 2020-04-29T03:46:41.260Z] 03:46:41 INFO - GECKO(1552) | 1588132001247 Marionette INFO Listening on port 2828
[task 2020-04-29T03:46:41.262Z] 03:46:41 INFO - GECKO(1552) | 1588132001249 Marionette DEBUG Marionette is listening
[task 2020-04-29T03:46:41.498Z] 03:46:41 INFO - GECKO(1552) | 1588132001488 Marionette DEBUG Accepted connection 0 from 127.0.0.1:59700
[task 2020-04-29T03:46:41.514Z] 03:46:41 INFO - GECKO(1552) | 1588132001506 Marionette DEBUG Closed connection 0
[task 2020-04-29T03:46:41.516Z] 03:46:41 INFO - GECKO(1552) | 1588132001513 Marionette DEBUG Accepted connection 1 from 127.0.0.1:59702
[task 2020-04-29T03:46:41.565Z] 03:46:41 INFO - GECKO(1552) | 1588132001560 Marionette DEBUG 1 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
[task 2020-04-29T03:46:42.012Z] 03:46:42 INFO - GECKO(1552) | 1588132001999 Marionette TRACE [5] Frame script loaded
[task 2020-04-29T03:46:42.316Z] 03:46:42 INFO - GECKO(1552) | 1588132002309 Marionette TRACE [5] Frame script registered
[task 2020-04-29T03:46:42.476Z] 03:46:42 INFO - GECKO(1552) | 1588132002469 Marionette DEBUG 1 <- [1,1,null,{"sessionId":"7a3874a9-5850-4013-a61d-362d549302a0","capabilities":{"browserName":"firefox","browserVersion":"77.0a ... p/tmplYNUB4.mozrunner","moz:shutdownTimeout":360000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true}}]
[task 2020-04-29T03:46:42.640Z] 03:46:42 INFO - GECKO(1552) | 1588132002623 Marionette DEBUG 1 -> [0,2,"Addon:Install",{"path":"/tmp/tmp2jxYcv.zip","temporary":false}]
[task 2020-04-29T03:46:43.762Z] 03:46:43 INFO - GECKO(1552) | ==1663==WARNING: Symbolizer buffer too small
[task 2020-04-29T03:46:43.763Z] 03:46:43 INFO - GECKO(1552) | ==1663==WARNING: Symbolizer buffer too small
[task 2020-04-29T03:46:43.763Z] 03:46:43 INFO - GECKO(1552) | ThreadSanitizer:DEADLYSIGNAL
[task 2020-04-29T03:46:43.763Z] 03:46:43 INFO - GECKO(1552) | ThreadSanitizer: nested bug in the same thread, aborting.
[task 2020-04-29T03:46:43.880Z] 03:46:43 INFO - GECKO(1552) | ###!!! [Parent][MessageChannel] Error: (msgtype=0x380131,name=PContent::Msg_AsyncMessage) Channel error: cannot send/recv
[task 2020-04-29T03:46:43.924Z] 03:46:43 ERROR - GECKO(1552) | A content process crashed and MOZ_CRASHREPORTER_SHUTDOWN is set, shutting down
[task 2020-04-29T03:46:45.888Z] 03:46:45 INFO - runtests.py | Waiting for browser...
[task 2020-04-29T03:46:45.929Z] 03:46:45 INFO - GECKO(1552) | 1588132005919 Marionette DEBUG Closed connection 1
[task 2020-04-29T03:46:46.484Z] 03:46:46 INFO - GECKO(1552) | 1588132006473 Marionette TRACE [22] Frame script loaded
[task 2020-04-29T03:46:46.484Z] 03:46:46 INFO - GECKO(1552) | 1588132006480 Marionette ERROR [22] No reply from Marionette:Register
[task 2020-04-29T03:46:47.586Z] 03:46:47 INFO - GECKO(1552) | 1588132007573 Marionette DEBUG 1 <- [1,2,{"error":"unknown error","message":"Could not install add-on: /tmp/tmp2jxYcv.zip: AddonManager is not initialized","stac ... t@chrome://marionette/content/server.js:249:9\n_onJSONObjectReady/<@chrome://marionette/content/transport.js:501:20\n"},null]
[task 2020-04-29T03:46:49.080Z] 03:46:49 INFO - GECKO(1552) | 1588132009073 Marionette TRACE Received observer notification xpcom-will-shutdown
[task 2020-04-29T03:46:49.081Z] 03:46:49 INFO - GECKO(1552) | 1588132009074 Marionette INFO Stopped listening on port 2828
[task 2020-04-29T03:46:49.081Z] 03:46:49 INFO - GECKO(1552) | 1588132009074 Marionette DEBUG Marionette stopped listening

:gbrown can you take a look?

Flags: needinfo?(gbrown)
Whiteboard: [stockwell needswork]

Hopefully :decoder understands what is happening here...

Flags: needinfo?(gbrown) → needinfo?(choller)

(In reply to Geoff Brown [:gbrown] from comment #17)

Hopefully :decoder understands what is happening here...

No, in fact I don't. We have had this problem since the beginning, but intermittently and at an acceptable rate. This is a TSan internal problem of some sort. I will try to raise it again with the Google/TSan developers (leaving needinfo for this)

In the last 7 days there have been 30 occurrences on linux1804-64-tsan opt.

Recent failure: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=302607390&repo=autoland&lineNumber=1772

...
[task 2020-05-16T22:18:02.658Z] 22:18:02     INFO - TEST-OK | dom/encoding/test/test_utf16_files.html | took 916ms
[task 2020-05-16T22:18:02.807Z] 22:18:02     INFO - TEST-START | Shutdown
[task 2020-05-16T22:18:02.811Z] 22:18:02     INFO - Passed:  57
[task 2020-05-16T22:18:02.814Z] 22:18:02     INFO - Failed:  0
[task 2020-05-16T22:18:02.815Z] 22:18:02     INFO - Todo:    0
[task 2020-05-16T22:18:02.816Z] 22:18:02     INFO - Mode:    e10s
[task 2020-05-16T22:18:02.818Z] 22:18:02     INFO - Slowest: 8579ms - /tests/dom/encoding/test/test_stringencoding.html
[task 2020-05-16T22:18:02.818Z] 22:18:02     INFO - SimpleTest FINISHED
[task 2020-05-16T22:18:02.822Z] 22:18:02     INFO - TEST-INFO | Ran 1 Loops
[task 2020-05-16T22:18:02.823Z] 22:18:02     INFO - SimpleTest FINISHED
[task 2020-05-16T22:18:06.082Z] 22:18:06     INFO - GECKO(1568) | 1589667486073	Marionette	TRACE	Received observer notification xpcom-will-shutdown
[task 2020-05-16T22:18:06.083Z] 22:18:06     INFO - GECKO(1568) | 1589667486075	Marionette	INFO	Stopped listening on port 2828
[task 2020-05-16T22:18:06.084Z] 22:18:06     INFO - GECKO(1568) | 1589667486076	Marionette	DEBUG	Marionette stopped listening
[task 2020-05-16T22:18:11.890Z] 22:18:11     INFO - TEST-INFO | Main app process: exit 0
[task 2020-05-16T22:18:11.890Z] 22:18:11     INFO - runtests.py | Application ran for: 0:01:06.919046
[task 2020-05-16T22:18:11.891Z] 22:18:11     INFO - zombiecheck | Reading PID log: /tmp/tmpqjLl7fpidlog
[task 2020-05-16T22:18:11.892Z] 22:18:11     INFO - ==> process 1568 launched child process 1583
[task 2020-05-16T22:18:11.892Z] 22:18:11     INFO - ==> process 1568 launched child process 1663
[task 2020-05-16T22:18:11.893Z] 22:18:11     INFO - ==> process 1568 launched child process 1679
[task 2020-05-16T22:18:11.893Z] 22:18:11     INFO - ==> process 1568 launched child process 1750
[task 2020-05-16T22:18:11.893Z] 22:18:11     INFO - ==> process 1568 launched child process 1775
[task 2020-05-16T22:18:11.894Z] 22:18:11     INFO - zombiecheck | Checking for orphan process with PID: 1663
[task 2020-05-16T22:18:11.895Z] 22:18:11     INFO - zombiecheck | Checking for orphan process with PID: 1679
[task 2020-05-16T22:18:11.895Z] 22:18:11     INFO - zombiecheck | Checking for orphan process with PID: 1775
[task 2020-05-16T22:18:11.896Z] 22:18:11     INFO - zombiecheck | Checking for orphan process with PID: 1750
[task 2020-05-16T22:18:11.897Z] 22:18:11     INFO - zombiecheck | Checking for orphan process with PID: 1583
[task 2020-05-16T22:18:11.897Z] 22:18:11     INFO - Stopping web server
[task 2020-05-16T22:18:11.913Z] 22:18:11     INFO - Stopping web socket server
[task 2020-05-16T22:18:11.937Z] 22:18:11     INFO - Stopping ssltunnel
[task 2020-05-16T22:18:11.957Z] 22:18:11  WARNING - leakcheck | refcount logging is off, so leaks can't be detected!
[task 2020-05-16T22:18:11.958Z] 22:18:11     INFO - runtests.py | Running tests: end.
[task 2020-05-16T22:18:11.978Z] 22:18:11     INFO - Buffered messages finished
[task 2020-05-16T22:18:11.978Z] 22:18:11     INFO - Running manifest: dom/html/test/mochitest.ini
[task 2020-05-16T22:18:11.979Z] 22:18:11     INFO - The following extra prefs will be set:
[task 2020-05-16T22:18:11.979Z] 22:18:11     INFO -   plugin.load_flash_only=false
[task 2020-05-16T22:18:11.999Z] 22:18:11     INFO -  Setting pipeline to PAUSED ...
[task 2020-05-16T22:18:11.999Z] 22:18:11     INFO -  Pipeline is PREROLLING ...
[task 2020-05-16T22:18:12.003Z] 22:18:12     INFO -  Pipeline is PREROLLED ...
[task 2020-05-16T22:18:12.003Z] 22:18:12     INFO -  Setting pipeline to PLAYING ...
[task 2020-05-16T22:18:12.003Z] 22:18:12     INFO -  New clock: GstSystemClock
[task 2020-05-16T22:18:12.039Z] 22:18:12     INFO -  Got EOS from element "pipeline0".
[task 2020-05-16T22:18:12.039Z] 22:18:12     INFO -  Execution ended after 0:00:00.033449850
[task 2020-05-16T22:18:12.039Z] 22:18:12     INFO -  Setting pipeline to PAUSED ...
[task 2020-05-16T22:18:12.040Z] 22:18:12     INFO -  Setting pipeline to READY ...
[task 2020-05-16T22:18:12.040Z] 22:18:12     INFO -  (gst-launch-1.0:1841): GStreamer-CRITICAL **: 22:18:12.034: gst_object_unref: assertion '((GObject *) object)->ref_count > 0' failed
[task 2020-05-16T22:18:12.040Z] 22:18:12     INFO -  Setting pipeline to NULL ...
[task 2020-05-16T22:18:12.040Z] 22:18:12     INFO -  Freeing pipeline ...
[task 2020-05-16T22:18:12.064Z] 22:18:12     INFO - INFO | runtests.py | TSan using symbolizer at /builds/worker/workspace/build/application/firefox/llvm-symbolizer
[task 2020-05-16T22:18:12.390Z] 22:18:12     INFO -  pk12util: PKCS12 IMPORT SUCCESSFUL
[task 2020-05-16T22:18:12.822Z] 22:18:12     INFO - INFO | runtests.py | TSan using symbolizer at /builds/worker/workspace/build/application/firefox/llvm-symbolizer
[task 2020-05-16T22:18:12.822Z] 22:18:12     INFO - INFO | runtests.py | TSan using symbolizer at /builds/worker/workspace/build/application/firefox/llvm-symbolizer
[task 2020-05-16T22:18:12.826Z] 22:18:12     INFO - MochitestServer : launching [u'/builds/worker/workspace/build/tests/bin/xpcshell', '-g', '/builds/worker/workspace/build/application/firefox', '-f', '/builds/worker/workspace/build/tests/bin/components/httpd.js', '-e', "const _PROFILE_PATH = '/tmp/tmpfpsDhI.mozrunner'; const _SERVER_PORT = '8888'; const _SERVER_ADDR = '127.0.0.1'; const _TEST_PREFIX = undefined; const _DISPLAY_RESULTS = false;", '-f', '/builds/worker/workspace/build/tests/mochitest/server.js']
[task 2020-05-16T22:18:12.826Z] 22:18:12     INFO - runtests.py | Server pid: 1860
[task 2020-05-16T22:18:12.830Z] 22:18:12     INFO - runtests.py | Websocket server pid: 1863
[task 2020-05-16T22:18:12.833Z] 22:18:12     INFO - INFO | runtests.py | TSan using symbolizer at /builds/worker/workspace/build/application/firefox/llvm-symbolizer
[task 2020-05-16T22:18:12.849Z] 22:18:12     INFO - runtests.py | SSL tunnel pid: 1866
[task 2020-05-16T22:18:13.598Z] 22:18:13     INFO - runtests.py | Running with scheme: http
[task 2020-05-16T22:18:13.598Z] 22:18:13     INFO - runtests.py | Running with e10s: True
[task 2020-05-16T22:18:13.599Z] 22:18:13     INFO - runtests.py | Running with fission: False
[task 2020-05-16T22:18:13.599Z] 22:18:13     INFO - runtests.py | Running with serviceworker_e10s: True
[task 2020-05-16T22:18:13.599Z] 22:18:13     INFO - runtests.py | Running with socketprocess_e10s: False
[task 2020-05-16T22:18:13.600Z] 22:18:13     INFO - runtests.py | Running tests: start.
[task 2020-05-16T22:18:13.600Z] 22:18:13     INFO - 
[task 2020-05-16T22:18:13.620Z] 22:18:13     INFO - Application command: /builds/worker/workspace/build/application/firefox/firefox -marionette -foreground -profile /tmp/tmpfpsDhI.mozrunner
[task 2020-05-16T22:18:13.637Z] 22:18:13     INFO - runtests.py | Application pid: 1885
[task 2020-05-16T22:18:13.637Z] 22:18:13     INFO - TEST-INFO | started process GECKO(1885)
[task 2020-05-16T22:18:19.966Z] 22:18:19     INFO - GECKO(1885) | 1589667499958	Marionette	TRACE	Marionette enabled
[task 2020-05-16T22:18:21.055Z] 22:18:21     INFO - GECKO(1885) | 1589667501051	Marionette	TRACE	Received observer notification toplevel-window-ready
[task 2020-05-16T22:18:32.735Z] 22:18:32     INFO - GECKO(1885) | ==2010==WARNING: Symbolizer buffer too small
[task 2020-05-16T22:18:32.735Z] 22:18:32     INFO - GECKO(1885) | ==2010==WARNING: Symbolizer buffer too small
[task 2020-05-16T22:18:33.479Z] 22:18:33     INFO - GECKO(1885) | ==2010==WARNING: Symbolizer buffer too small
[task 2020-05-16T22:18:33.479Z] 22:18:33     INFO - GECKO(1885) | ==2010==WARNING: Symbolizer buffer too small
[task 2020-05-16T22:18:33.481Z] 22:18:33     INFO - GECKO(1885) | ==2010==WARNING: Symbolizer buffer too small
[task 2020-05-16T22:18:33.481Z] 22:18:33     INFO - GECKO(1885) | ==2010==WARNING: Symbolizer buffer too small
[task 2020-05-16T22:18:33.485Z] 22:18:33     INFO - GECKO(1885) | ==2010==WARNING: Symbolizer buffer too small
[task 2020-05-16T22:18:33.485Z] 22:18:33     INFO - GECKO(1885) | ==2010==WARNING: Symbolizer buffer too small
[task 2020-05-16T22:18:33.488Z] 22:18:33     INFO - GECKO(1885) | ==2010==WARNING: Symbolizer buffer too small
[task 2020-05-16T22:18:33.489Z] 22:18:33     INFO - GECKO(1885) | ==2010==WARNING: Symbolizer buffer too small
[task 2020-05-16T22:18:33.491Z] 22:18:33     INFO - GECKO(1885) | ThreadSanitizer:DEADLYSIGNAL
[task 2020-05-16T22:18:33.491Z] 22:18:33     INFO - GECKO(1885) | ThreadSanitizer: nested bug in the same thread, aborting.
[task 2020-05-16T22:18:33.540Z] 22:18:33     INFO - GECKO(1885) | ###!!! [Parent][MessageChannel] Error: (msgtype=0x390023,name=PContent::Msg_PreferenceUpdate) Channel error: cannot send/recv
...
...
[task 2020-05-16T22:18:33.693Z] 22:18:33     INFO - GECKO(1885) | ###!!! [Parent][MessageChannel] Error: (msgtype=0x390023,name=PContent::Msg_PreferenceUpdate) Channel error: cannot send/recv
[task 2020-05-16T22:18:33.751Z] 22:18:33    ERROR - GECKO(1885) | A content process crashed and MOZ_CRASHREPORTER_SHUTDOWN is set, shutting down
[task 2020-05-16T22:18:33.992Z] 22:18:33     INFO - GECKO(1885) | JavaScript error: resource://activity-stream/lib/ActivityStreamPrefs.jsm, line 27: NS_ERROR_ILLEGAL_VALUE: Component returned failure code: 0x80070057 (NS_ERROR_ILLEGAL_VALUE) [nsIPrefBranch.removeObserver]
[task 2020-05-16T22:18:40.413Z] 22:18:40     INFO - GECKO(1885) | JavaScript error: , line 0: uncaught exception: 2147500036
[task 2020-05-16T22:18:40.413Z] 22:18:40     INFO - GECKO(1885) | JavaScript error: resource://activity-stream/lib/TopSitesFeed.jsm, line 447: uncaught exception: 2147500036
[task 2020-05-16T22:18:40.413Z] 22:18:40     INFO - GECKO(1885) | JavaScript error: resource://activity-stream/lib/TopSitesFeed.jsm, line 473: uncaught exception: 2147500036
[task 2020-05-16T22:21:13.694Z] 22:21:13     INFO - runtests.py | Waiting for browser...
[task 2020-05-16T22:21:13.695Z] 22:21:13     INFO - TEST-INFO | Main app process: exit 0

This bug failed 32 times in the last 7 days. Occurs on linux1804-64-tsan on opt build types.

Recent log:
https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=304326413&repo=mozilla-central&lineNumber=2879

In the past week there were 34 failures on linux1804-64-tsan opt.

Recent failure log:
https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=306204415&repo=autoland&lineNumber=3541

[task 2020-06-13T08:08:26.989Z] 08:08:26 INFO - TEST-INFO | started process GECKO(3270)
[task 2020-06-13T08:08:31.669Z] 08:08:31 INFO - GECKO(3270) | 1592035711664 Marionette TRACE Marionette enabled
[task 2020-06-13T08:08:32.447Z] 08:08:32 INFO - GECKO(3270) | 1592035712441 Marionette TRACE Received observer notification toplevel-window-ready
[task 2020-06-13T08:08:40.787Z] 08:08:40 INFO - GECKO(3270) | console.error: SearchService: "_readCacheFile: Error reading cache file:" (new Error("", "(unknown module)"))
[task 2020-06-13T08:08:40.883Z] 08:08:40 INFO - GECKO(3270) | ==3381==WARNING: Symbolizer buffer too small
[task 2020-06-13T08:08:40.884Z] 08:08:40 INFO - GECKO(3270) | ==3381==WARNING: Symbolizer buffer too small
[task 2020-06-13T08:08:41.341Z] 08:08:41 INFO - GECKO(3270) | ==3381==WARNING: Symbolizer buffer too small
[task 2020-06-13T08:08:41.342Z] 08:08:41 INFO - GECKO(3270) | ==3381==WARNING: Symbolizer buffer too small
[task 2020-06-13T08:08:41.342Z] 08:08:41 INFO - GECKO(3270) | ==3381==WARNING: Symbolizer buffer too small
[task 2020-06-13T08:08:41.342Z] 08:08:41 INFO - GECKO(3270) | ==3381==WARNING: Symbolizer buffer too small
[task 2020-06-13T08:08:41.342Z] 08:08:41 INFO - GECKO(3270) | ==3381==WARNING: Symbolizer buffer too small
[task 2020-06-13T08:08:41.342Z] 08:08:41 INFO - GECKO(3270) | ==3381==WARNING: Symbolizer buffer too small
[task 2020-06-13T08:08:41.342Z] 08:08:41 INFO - GECKO(3270) | ==3381==WARNING: Symbolizer buffer too small
[task 2020-06-13T08:08:41.343Z] 08:08:41 INFO - GECKO(3270) | ==3381==WARNING: Symbolizer buffer too small
[task 2020-06-13T08:08:41.344Z] 08:08:41 INFO - GECKO(3270) | ==3381==WARNING: Symbolizer buffer too small
[task 2020-06-13T08:08:41.345Z] 08:08:41 INFO - GECKO(3270) | ==3381==WARNING: Symbolizer buffer too small
[task 2020-06-13T08:08:41.347Z] 08:08:41 INFO - GECKO(3270) | ==3381==WARNING: Symbolizer buffer too small
[task 2020-06-13T08:08:41.347Z] 08:08:41 INFO - GECKO(3270) | ==3381==WARNING: Symbolizer buffer too small
[task 2020-06-13T08:08:41.347Z] 08:08:41 INFO - GECKO(3270) | ==3381==WARNING: Symbolizer buffer too small
[task 2020-06-13T08:08:41.347Z] 08:08:41 INFO - GECKO(3270) | ==3381==WARNING: Symbolizer buffer too small
[task 2020-06-13T08:08:41.355Z] 08:08:41 INFO - GECKO(3270) | ==3381==WARNING: Symbolizer buffer too small
[task 2020-06-13T08:08:41.355Z] 08:08:41 INFO - GECKO(3270) | ==3381==WARNING: Symbolizer buffer too small
[task 2020-06-13T08:08:41.355Z] 08:08:41 INFO - GECKO(3270) | ThreadSanitizer:DEADLYSIGNAL
[task 2020-06-13T08:08:41.355Z] 08:08:41 INFO - GECKO(3270) | ThreadSanitizer: nested bug in the same thread, aborting.

This bug failed 35 times in the last 7 days. Occurs on linux1804-64-tsan on opt build types.

Recent log:
https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=308527626&repo=autoland&lineNumber=2783

There are 34 failures in last 7 days. This happens on linux1804-64-tsan on opt.

Recent failure log:
https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=309425861&repo=autoland&lineNumber=2109

TSan developers suggested that we add some debug output to our Clang and see if that sheds some light on what is happening. I will try to take a stab at it this week.

In the last 7 days there have been 22 occurrences on linux1804-64-tsan opt.

Recent failure: https://treeherder.mozilla.org/logviewer.html#?job_id=311057963&repo=mozilla-central

This bug failed failed 33 times in the last 7 days. This happens on linux1804-64-tsan opt.

Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=312459194&repo=autoland&lineNumber=2858

Christian, circling back at comment 35, any chance this is still on your radar? The bug is now in disable recommended queue with:

Flags: needinfo?(choller)
Flags: needinfo?(choller)

(In reply to Cosmin Sabou [:CosminS] from comment #46)

Christian, circling back at comment 35, any chance this is still on your radar?

This is still on my radar, but previous attempts to debug this failed so far. It might well be that this bug will stick around a bit longer.

Given the amount of bugs we have found so far, I still think that the rate here is acceptable (although annoying, I agree), and would not justify to disable TSan as a whole. If this was a single test or a small group of tests, then I would disable it immediately but this issue can happen across all of CI unfortunately :/

I'm leaving the needinfo to make sure I take another stab at this soon.

Whiteboard: [stockwell disable-recommended] → [stockwell needswork:owner]

Hi Christian, are there any updates here?

There are 41 total failures in the last 7 days on linux1804-64-tsan opt.

Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=314220068&repo=mozilla-central&lineNumber=2526

[task 2020-08-27T22:09:46.893Z] 22:09:46 INFO - TEST-START | dom/security/test/referrer-policy/test_img_referrer.html
[task 2020-08-27T22:09:49.341Z] 22:09:49 INFO - GECKO(2489) | ==2629==WARNING: Symbolizer buffer too small
[task 2020-08-27T22:09:49.341Z] 22:09:49 INFO - GECKO(2489) | ==2629==WARNING: Symbolizer buffer too small
[task 2020-08-27T22:09:49.342Z] 22:09:49 INFO - GECKO(2489) | ThreadSanitizer:DEADLYSIGNAL
[task 2020-08-27T22:09:49.343Z] 22:09:49 INFO - GECKO(2489) | ThreadSanitizer: nested bug in the same thread, aborting.
[task 2020-08-27T22:09:49.399Z] 22:09:49 INFO - GECKO(2489) | ###!!! [Parent][MessageChannel] Error: (msgtype=0x390149,name=PContent::Msg_AsyncMessage) Channel error: cannot send/recv
[task 2020-08-27T22:09:49.435Z] 22:09:49 ERROR - GECKO(2489) | A content process crashed and MOZ_CRASHREPORTER_SHUTDOWN is set, shutting down
[task 2020-08-27T22:09:51.697Z] 22:09:51 INFO - GECKO(2489) | 1598566191696 Marionette TRACE Received observer notification xpcom-will-shutdown
[task 2020-08-27T22:09:51.701Z] 22:09:51 INFO - GECKO(2489) | 1598566191697 Marionette INFO Stopped listening on port 2828
[task 2020-08-27T22:09:51.702Z] 22:09:51 INFO - GECKO(2489) | 1598566191697 Marionette DEBUG Marionette stopped listening
[task 2020-08-27T22:10:02.697Z] 22:10:02 INFO - TEST-INFO | Main app process: exit 0

Whiteboard: [stockwell disable-recommended] → [stockwell needswork:owner]
Whiteboard: [stockwell disable-recommended] → [stockwell needswork:owner]

It looks like this bug went completely away with the upgrade to Clang 11. I guess that's great news \o/

Flags: needinfo?(choller)
Severity: normal → S3
Attachment #9387264 - Attachment is obsolete: true
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: