Closed Bug 1621269 Opened 5 years ago Closed 4 years ago

High frequency Linux ccov reftest pid: None | application crashed <[@ Allocator<MozJemallocBase>::free(void*)][@ gcov_do_dump][@ RunWatchdog][@ fseek]> after application terminated with exit code 11

Categories

(Testing :: Code Coverage, defect, P3)

defect

Tracking

(Not tracked)

RESOLVED WORKSFORME

People

(Reporter: intermittent-bug-filer, Unassigned)

References

(Regression)

Details

(Keywords: crash, intermittent-failure, Whiteboard: [retriggered][stockwell disabled][stockwell needswork:owner])

Crash Data

Attachments

(1 file)

Filed by: malexandru [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=292440916&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/SG2dfNk_QaOu6WCZLd6foA/runs/0/artifacts/public/logs/live_backing.log
Reftest URL: https://hg.mozilla.org/mozilla-central/raw-file/tip/layout/tools/reftest/reftest-analyzer.xhtml#logurl=https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/SG2dfNk_QaOu6WCZLd6foA/runs/0/artifacts/public/logs/live_backing.log&only_show_unexpected=1


[task 2020-03-10T12:23:41.236Z] 12:23:41     INFO - Calling ['/builds/worker/workspace/build/venv/bin/python', '-u', '/builds/worker/workspace/build/tests/reftest/runreftest.py', '--total-chunks', '8', '--this-chunk', '2', '--setpref=media.peerconnection.mtransport_process=false', '--setpref=network.process.enabled=false', '--appname=/builds/worker/workspace/build/application/firefox/firefox', '--utility-path=tests/bin', '--extra-profile-file=tests/bin/plugins', u'--symbols-path=https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/Bcu8Xlr3QyqF1GZpgj5UEQ/artifacts/public/build/target.crashreporter-symbols.zip', '--log-raw=/builds/worker/workspace/build/blobber_upload_dir/reftest-no-accel_raw.log', '--log-errorsummary=/builds/worker/workspace/build/blobber_upload_dir/reftest-no-accel_errorsummary.log', '--cleanup-crashes', '--marionette-startup-timeout=180', '--sandbox-read-whitelist=/builds/worker/workspace/build', '--log-raw=-', '--suite=reftest', '--setpref=layers.acceleration.disabled=true', '--topsrcdir=tests/reftest/tests', '--', 'tests/reftest/tests/layout/reftests/reftest.list'] with output_timeout 1000
[task 2020-03-10T12:23:41.582Z] 12:23:41     INFO - REFTEST INFO | Running with e10s: True
[task 2020-03-10T12:23:41.582Z] 12:23:41     INFO - REFTEST INFO | Application command: /builds/worker/workspace/build/application/firefox/firefox -marionette -profile /tmp/tmpFATJJc.mozrunner
[task 2020-03-10T12:23:41.663Z] 12:23:41     INFO - [CodeCoverage] Setting handlers for process 1148.
[task 2020-03-10T12:23:43.776Z] 12:23:43     INFO - 1583843023768	addons.webextension.doh-rollout@mozilla.org	WARN	Loading extension 'doh-rollout@mozilla.org': Reading manifest: Invalid extension permission: networkStatus
[task 2020-03-10T12:23:43.894Z] 12:23:43     INFO - 1583843023885	addons.webextension.screenshots@mozilla.org	WARN	Loading extension 'screenshots@mozilla.org': Reading manifest: Invalid extension permission: mozillaAddons
[task 2020-03-10T12:23:43.894Z] 12:23:43     INFO - 1583843023885	addons.webextension.screenshots@mozilla.org	WARN	Loading extension 'screenshots@mozilla.org': Reading manifest: Invalid extension permission: telemetry
[task 2020-03-10T12:23:43.894Z] 12:23:43     INFO - 1583843023886	addons.webextension.screenshots@mozilla.org	WARN	Loading extension 'screenshots@mozilla.org': Reading manifest: Invalid extension permission: resource://pdf.js/
[task 2020-03-10T12:23:43.895Z] 12:23:43     INFO - 1583843023886	addons.webextension.screenshots@mozilla.org	WARN	Loading extension 'screenshots@mozilla.org': Reading manifest: Invalid extension permission: about:reader*
[task 2020-03-10T12:23:44.097Z] 12:23:44     INFO - 1583843024093	Marionette	TRACE	Received observer notification profile-after-change
[task 2020-03-10T12:23:44.314Z] 12:23:44     INFO - 1583843024307	Marionette	TRACE	Received observer notification command-line-startup
[task 2020-03-10T12:23:44.315Z] 12:23:44     INFO - 1583843024308	Marionette	DEBUG	Init aborted (running=false, enabled=true, finalUIStartup=false)
[task 2020-03-10T12:23:44.598Z] 12:23:44     INFO - 1583843024595	Marionette	TRACE	Received observer notification toplevel-window-ready
[task 2020-03-10T12:23:47.015Z] 12:23:47     INFO - [CodeCoverage] Setting handlers for process 1222.
[task 2020-03-10T12:23:47.939Z] 12:23:47     INFO - [CodeCoverage] Setting handlers for process 1364.
[task 2020-03-10T12:23:52.542Z] 12:23:52     INFO - 1583843032538	Marionette	TRACE	Received observer notification marionette-startup-requested
[task 2020-03-10T12:23:52.544Z] 12:23:52     INFO - 1583843032540	Marionette	TRACE	Waiting until startup recorder finished recording startup scripts...
[task 2020-03-10T12:23:52.689Z] 12:23:52     INFO - 1583843032687	Marionette	TRACE	All scripts recorded.
[task 2020-03-10T12:23:52.992Z] 12:23:52     INFO - 1583843032984	Marionette	INFO	Listening on port 2828
[task 2020-03-10T12:23:52.993Z] 12:23:52     INFO - 1583843032985	Marionette	DEBUG	Marionette is listening
[task 2020-03-10T12:23:53.055Z] 12:23:53     INFO - 1583843033051	Marionette	DEBUG	Accepted connection 0 from 127.0.0.1:45918
[task 2020-03-10T12:23:53.075Z] 12:23:53     INFO - 1583843033066	Marionette	DEBUG	Closed connection 0
[task 2020-03-10T12:23:53.077Z] 12:23:53     INFO - 1583843033069	Marionette	DEBUG	Accepted connection 1 from 127.0.0.1:45920
[task 2020-03-10T12:23:53.080Z] 12:23:53     INFO - 1583843033073	Marionette	DEBUG	1 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
[task 2020-03-10T12:23:53.278Z] 12:23:53     INFO - [CodeCoverage] Setting handlers for process 1433.
[task 2020-03-10T12:23:53.403Z] 12:23:53     INFO - 1583843033399	Marionette	TRACE	[16] Frame script loaded
[task 2020-03-10T12:23:53.541Z] 12:23:53     INFO - 1583843033530	Marionette	TRACE	[16] Frame script registered
[task 2020-03-10T12:23:53.577Z] 12:23:53     INFO - 1583843033563	Marionette	DEBUG	1 <- [1,1,null,{"sessionId":"83b8ff3d-50ec-4476-bd04-15fe61d91cd2","capabilities":{"browserName":"firefox","browserVersion":"75.0a ... mp/tmpFATJJc.mozrunner","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true}}]
[task 2020-03-10T12:23:53.599Z] 12:23:53     INFO - 1583843033592	Marionette	DEBUG	1 -> [0,2,"Addon:Install",{"path":"/builds/worker/workspace/build/tests/reftest/reftest","temporary":true}]
[task 2020-03-10T12:23:53.696Z] 12:23:53     INFO - 1583843033692	Marionette	TRACE	Received observer notification toplevel-window-ready
[task 2020-03-10T12:23:53.704Z] 12:23:53     INFO - 1583843033701	Marionette	DEBUG	1 <- [1,2,null,{"value":"reftest@mozilla.org"}]
[task 2020-03-10T12:23:53.765Z] 12:23:53     INFO - 1583843033762	Marionette	TRACE	Received observer notification toplevel-window-ready
[task 2020-03-10T12:23:53.842Z] 12:23:53     INFO - 1583843033838	Marionette	DEBUG	1 -> [0,3,"WebDriver:DeleteSession",{}]
[task 2020-03-10T12:23:53.850Z] 12:23:53     INFO - 1583843033843	Marionette	DEBUG	1 <- [1,3,null,{"value":null}]
[task 2020-03-10T12:23:53.972Z] 12:23:53     INFO - 1583843033963	Marionette	DEBUG	Closed connection 1
[task 2020-03-10T12:23:54.377Z] 12:23:54     INFO - REFTEST INFO | Reading manifest file:///builds/worker/workspace/build/tests/reftest/tests/layout/reftests/reftest.list
[task 2020-03-10T12:23:54.419Z] 12:23:54     INFO - [CodeCoverage] Setting handlers for process 1453.
[task 2020-03-10T12:23:54.442Z] 12:23:54     INFO - REFTEST INFO | Dumping JSON representation of sandbox
[task 2020-03-10T12:23:54.442Z] 12:23:54     INFO - REFTEST INFO | {"isDebugBuild":false,"xulRuntime":{"widgetToolkit":"gtk","OS":"Linux","XPCOMABI":"x86_64-gcc3"},"smallScreen":false,"d2d":false,"dwrite":false,"gpuProcess":false,"azureCairo":false,"azureSkia":true,"skiaContent":true,"azureSkiaGL":false,"contentSameGfxBackendAsCanvas":true,"remoteCanvas":false,"layersGPUAccelerated":false,"d3d11":false,"d3d9":false,"layersOpenGL":false,"webrender":false,"layersOMTC":true,"advancedLayers":false,"layerChecksEnabled":true,"retainedDisplayList":true,"usesOverlayScrollbars":false,"Android":false,"cocoaWidget":false,"gtkWidget":true,"qtWidget":false,"winWidget":false,"is64Bit":true,"geckoview":false,"transparentScrollbars":true,"AddressSanitizer":false,"webrtc":true,"retainedDisplayLists":true,"compareRetainedDisplayLists":false,"skiaPdf":false,"release_or_beta":false,"http":{"userAgent":"Mozilla/5.0 (X11; Linux x86_64; rv:75.0) Gecko/20100101 Firefox/75.0","appName":"Mozilla","appVersion":"5.0","platform":"X11","oscpu":"Linux x86_64","misc":"rv:75.0"},"haveTestPlugin":true,"windowsDefaultTheme":false,"nativeThemePref":true,"gpuProcessForceEnabled":false,"prefs":{},"browserIsRemote":true,"browserIsFission":false,"asyncPan":true,"usesRepeatResampling":false,"verify":false,"fission":false,"serviceWorkerE10s":true}
[task 2020-03-10T12:23:55.089Z] 12:23:55     INFO - 1583843035084	Marionette	TRACE	[22] Frame script loaded
included manifest at file:///builds/worker/workspace/build/tests/reftest/tests/layout/reftests/reftest.list line 286 due to matching skip condition
[task 2020-03-10T12:24:02.802Z] 12:24:02     INFO - REFTEST INFO | Skipping included manifest at file:///builds/worker/workspace/build/tests/reftest/tests/layout/reftests/reftest.list line 289 due to matching skip condition
[task 2020-03-10T12:24:02.804Z] 12:24:02     INFO - REFTEST INFO | Skipping included manifest at file:///builds/worker/workspace/build/tests/reftest/tests/layout/reftests/reftest.list line 292 due to matching skip condition
[task 2020-03-10T12:24:03.432Z] 12:24:03     INFO - REFTEST INFO | Skipping included manifest at file:///builds/worker/workspace/build/tests/reftest/tests/layout/reftests/reftest.list line 311 due to matching skip condition
[task 2020-03-10T12:24:08.648Z] 12:24:08     INFO - 1583843048642	Marionette	ERROR	[22] No reply from Marionette:Register
[task 2020-03-10T12:24:08.763Z] 12:24:08     INFO - REFTEST INFO | Slowest test took 0ms (undefined)
[task 2020-03-10T12:24:08.763Z] 12:24:08     INFO - REFTEST INFO | Total canvas count = 0
[task 2020-03-10T12:24:10.377Z] 12:24:10     INFO - ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2020-03-10T12:24:10.394Z] 12:24:10     INFO - ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2020-03-10T12:24:10.696Z] 12:24:10     INFO - ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2020-03-10T12:24:10.696Z] 12:24:10     INFO - ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2020-03-10T12:24:10.717Z] 12:24:10     INFO - profiling:/tmp/tmppEzfTI/lib/ckfw/ckfw_nssckfw/wrap.gcda:Not a gcov data file
[task 2020-03-10T12:24:10.717Z] 12:24:10     INFO - profiling:/tmp/tmppEzfTI/src/gzlib.gcda:Merge mismatch for function 0
[task 2020-03-10T12:24:10.717Z] 12:24:10     INFO - profiling:/tmp/tmppEzfTI/lib/ckfw/ckfw_nssckfw/slot.gcda:Not a gcov data file
[task 2020-03-10T12:24:10.733Z] 12:24:10     INFO - ExceptionHandler::GenerateDump cloned child 1501
[task 2020-03-10T12:24:10.734Z] 12:24:10     INFO - ExceptionHandler::SendContinueSignalToChild sent continue signal to child
[task 2020-03-10T12:24:10.734Z] 12:24:10     INFO - ExceptionHandler::WaitForContinueSignal waiting for continue signal...
[task 2020-03-10T12:24:13.221Z] 12:24:13     INFO - profiling:/tmp/tmppEzfTI/libyuv/libyuv_libyuv/Unified_cpp_media_libyuv_libyuv0.gcda:Merge mismatch for function 88
[task 2020-03-10T12:24:13.257Z] 12:24:13     INFO - profiling:/tmp/tmppEzfTI/libyuv/libyuv_libyuv/Unified_cpp_media_libyuv_libyuv0.gcda:Merge mismatch for function 88
[task 2020-03-10T12:24:13.260Z] 12:24:13     INFO - profiling:/tmp/tmppEzfTI/libyuv/libyuv_libyuv/Unified_cpp_media_libyuv_libyuv0.gcda:Merge mismatch for function 88
[task 2020-03-10T12:24:13.519Z] 12:24:13    ERROR - TEST-UNEXPECTED-FAIL | None | application terminated with exit code 11
[task 2020-03-10T12:24:13.519Z] 12:24:13     INFO - REFTEST INFO | Downloading symbols from: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/Bcu8Xlr3QyqF1GZpgj5UEQ/artifacts/public/build/target.crashreporter-symbols.zip
[task 2020-03-10T12:24:17.277Z] 12:24:17     INFO - REFTEST INFO | Copy/paste: /builds/worker/fetches/minidump_stackwalk/minidump_stackwalk /tmp/tmpFATJJc.mozrunner/minidumps/3348f3ce-99dd-4e71-7dd6-c3589a878856.dmp /tmp/tmpfMUDZm
[task 2020-03-10T12:24:22.334Z] 12:24:22     INFO - REFTEST INFO | Saved minidump as /builds/worker/workspace/build/blobber_upload_dir/3348f3ce-99dd-4e71-7dd6-c3589a878856.dmp
[task 2020-03-10T12:24:22.334Z] 12:24:22     INFO - REFTEST INFO | Saved app info as /builds/worker/workspace/build/blobber_upload_dir/3348f3ce-99dd-4e71-7dd6-c3589a878856.extra
[task 2020-03-10T12:24:22.544Z] 12:24:22     INFO - REFTEST PROCESS-CRASH | pid: None | application crashed [@ Allocator<MozJemallocBase>::free(void*)]
[task 2020-03-10T12:24:22.544Z] 12:24:22     INFO - Crash dump filename: /tmp/tmpFATJJc.mozrunner/minidumps/3348f3ce-99dd-4e71-7dd6-c3589a878856.dmp
[task 2020-03-10T12:24:22.544Z] 12:24:22     INFO - Operating system: Linux
[task 2020-03-10T12:24:22.545Z] 12:24:22     INFO -                   0.0.0 Linux 4.4.0-1014-aws #14taskcluster1-Ubuntu SMP Tue Apr 3 10:27:00 UTC 2018 x86_64
[task 2020-03-10T12:24:22.545Z] 12:24:22     INFO - CPU: amd64
[task 2020-03-10T12:24:22.545Z] 12:24:22     INFO -      family 6 model 62 stepping 4
[task 2020-03-10T12:24:22.545Z] 12:24:22     INFO -      4 CPUs
[task 2020-03-10T12:24:22.546Z] 12:24:22     INFO - 
[task 2020-03-10T12:24:22.546Z] 12:24:22     INFO - GPU: UNKNOWN
[task 2020-03-10T12:24:22.547Z] 12:24:22     INFO - 
[task 2020-03-10T12:24:22.547Z] 12:24:22     INFO - Crash reason:  SIGSEGV /0x00000080
[task 2020-03-10T12:24:22.547Z] 12:24:22     INFO - Crash address: 0x0
[task 2020-03-10T12:24:22.548Z] 12:24:22     INFO - Process uptime: not available
[task 2020-03-10T12:24:22.548Z] 12:24:22     INFO - 
[task 2020-03-10T12:24:22.548Z] 12:24:22     INFO - Thread 32 (crashed)
[task 2020-03-10T12:24:22.549Z] 12:24:22     INFO -  0  firefox-bin!Allocator<MozJemallocBase>::free(void*) [malloc_decls.h:718652138136a4e4903197925698b752a5c793b6 : 54 + 0x9d]
[task 2020-03-10T12:24:22.549Z] 12:24:22     INFO -     rax = 0x0000000000000001   rdx = 0x00007fb9f6402040
[task 2020-03-10T12:24:22.549Z] 12:24:22     INFO -     rcx = 0x00007fb9f67a46d9   rbx = 0xe5e5e5e5e5e5e5e5
[task 2020-03-10T12:24:22.550Z] 12:24:22     INFO -     rsi = 0x0000000000000000   rdi = 0xe5e5e5e5e5e5e5e5
[task 2020-03-10T12:24:22.550Z] 12:24:22     INFO -     rbp = 0x00007fb9c8944a30   rsp = 0x00007fb9c8944a00
[task 2020-03-10T12:24:22.551Z] 12:24:22     INFO -      r8 = 0x0000000000001000    r9 = 0x000000000000000c
[task 2020-03-10T12:24:22.551Z] 12:24:22     INFO -     r10 = 0x00007fb9c894a700   r11 = 0x0000000000000206
[task 2020-03-10T12:24:22.551Z] 12:24:22     INFO -     r12 = 0x000000000005e5e5   r13 = 0xe5e5e5e5e5e5e5e5
[task 2020-03-10T12:24:22.552Z] 12:24:22     INFO -     r14 = 0xe5e5e5e5e5e00000   r15 = 0x00007fb9eb588d68
[task 2020-03-10T12:24:22.552Z] 12:24:22     INFO -     rip = 0x0000562f50ec4f7d
[task 2020-03-10T12:24:22.554Z] 12:24:22     INFO -     Found by: given as instruction pointer in context
[task 2020-03-10T12:24:22.554Z] 12:24:22     INFO -  1  firefox-bin!replace_free [PHC.cpp:718652138136a4e4903197925698b752a5c793b6 : 1155 + 0x50]
[task 2020-03-10T12:24:22.556Z] 12:24:22     INFO -     rbx = 0x00007fb9bf09f800   rbp = 0x00007fb9c8944b10
[task 2020-03-10T12:24:22.556Z] 12:24:22     INFO -     rsp = 0x00007fb9c8944a40   r12 = 0x0000000000000000
[task 2020-03-10T12:24:22.556Z] 12:24:22     INFO -     r13 = 0xe5e5e5e5e5e5e5e5   r14 = 0x00007fb9e971c148
[task 2020-03-10T12:24:22.556Z] 12:24:22     INFO -     r15 = 0x00007fb9eb588d68   rip = 0x0000562f50ecb9e0
[task 2020-03-10T12:24:22.556Z] 12:24:22     INFO -     Found by: call frame info
[task 2020-03-10T12:24:22.557Z] 12:24:22     INFO -  2  firefox-bin!free [malloc_decls.h:718652138136a4e4903197925698b752a5c793b6 : 54 + 0x30]
[task 2020-03-10T12:24:22.557Z] 12:24:22     INFO -     rbx = 0x00007fb9bf09f800   rbp = 0x00007fb9c8944b30
[task 2020-03-10T12:24:22.557Z] 12:24:22     INFO -     rsp = 0x00007fb9c8944b20   r12 = 0x0000000000000000
[task 2020-03-10T12:24:22.558Z] 12:24:22     INFO -     r13 = 0x00007fb9e971c0e0   r14 = 0x00007fb9e971c148
[task 2020-03-10T12:24:22.558Z] 12:24:22     INFO -     r15 = 0x00007fb9eb588d68   rip = 0x0000562f50eb4c10
[task 2020-03-10T12:24:22.558Z] 12:24:22     INFO -     Found by: call frame info
[task 2020-03-10T12:24:22.559Z] 12:24:22     INFO -  3  libc-2.27.so!_IO_unsave_markers [genops.c : 1039 + 0x13]
[task 2020-03-10T12:24:22.559Z] 12:24:22     INFO -     rbx = 0x00007fb9bf09f800   rbp = 0x0000000000000000
[task 2020-03-10T12:24:22.559Z] 12:24:22     INFO -     rsp = 0x00007fb9c8944b40   r12 = 0x0000000000000000
[task 2020-03-10T12:24:22.559Z] 12:24:22     INFO -     r13 = 0x00007fb9e971c0e0   r14 = 0x00007fb9e971c148
[task 2020-03-10T12:24:22.560Z] 12:24:22     INFO -     r15 = 0x00007fb9eb588d68   rip = 0x00007fb9f6703c0c
[task 2020-03-10T12:24:22.560Z] 12:24:22     INFO -     Found by: call frame info
[task 2020-03-10T12:24:22.561Z] 12:24:22     INFO -  4  libc-2.27.so!_IO_new_file_close_it [fileops.c : 140 + 0x5]
[task 2020-03-10T12:24:22.561Z] 12:24:22     INFO -     rbx = 0x00007fb9bf09f800   rbp = 0x0000000000000000
[task 2020-03-10T12:24:22.561Z] 12:24:22     INFO -     rsp = 0x00007fb9c8944b50   r12 = 0x0000000000000000
[task 2020-03-10T12:24:22.562Z] 12:24:22     INFO -     r13 = 0x00007fb9e971c0e0   r14 = 0x00007fb9e971c148
[task 2020-03-10T12:24:22.562Z] 12:24:22     INFO -     r15 = 0x00007fb9eb588d68   rip = 0x00007fb9f67001c2
[task 2020-03-10T12:24:22.563Z] 12:24:22     INFO -     Found by: call frame info
[task 2020-03-10T12:24:22.563Z] 12:24:22     INFO -  5  libc-2.27.so!_IO_new_fclose [iofclose.c : 53 + 0x8]
[task 2020-03-10T12:24:22.564Z] 12:24:22     INFO -     rbx = 0x00007fb9bf09f800   rbp = 0x0000000001b30000
[task 2020-03-10T12:24:22.564Z] 12:24:22     INFO -     rsp = 0x00007fb9c8944b70   r12 = 0x0000000000000000
[task 2020-03-10T12:24:22.564Z] 12:24:22     INFO -     r13 = 0x00007fb9e971c0e0   r14 = 0x00007fb9e971c148
[task 2020-03-10T12:24:22.564Z] 12:24:22     INFO -     r15 = 0x00007fb9eb588d68   rip = 0x00007fb9f66f2387
[task 2020-03-10T12:24:22.564Z] 12:24:22     INFO -     Found by: call frame info
[task 2020-03-10T12:24:22.565Z] 12:24:22     INFO -  6  libxul.so!__gcov_close [gcov-io.c : 212 + 0x5]
[task 2020-03-10T12:24:22.565Z] 12:24:22     INFO -     rbx = 0x0000562f50fb9d40   rbp = 0x0000000001b30000
[task 2020-03-10T12:24:22.565Z] 12:24:22     INFO -     rsp = 0x00007fb9c8944b90   r12 = 0x0000000000000000
[task 2020-03-10T12:24:22.565Z] 12:24:22     INFO -     r13 = 0x00007fb9e971c0e0   r14 = 0x00007fb9e971c148
[task 2020-03-10T12:24:22.565Z] 12:24:22     INFO -     r15 = 0x00007fb9eb588d68   rip = 0x00007fb9e2ec729c
[task 2020-03-10T12:24:22.565Z] 12:24:22     INFO -     Found by: call frame info
[task 2020-03-10T12:24:22.566Z] 12:24:22     INFO -  7  libxul.so!gcov_do_dump [libgcov-driver.c : 850 + 0x14f]
[task 2020-03-10T12:24:22.566Z] 12:24:22     INFO -     rbx = 0x00007fb9e971c0e0   rbp = 0x0000000001b30000
[task 2020-03-10T12:24:22.567Z] 12:24:22     INFO -     rsp = 0x00007fb9c8944ba0   r12 = 0x0000000000000000
[task 2020-03-10T12:24:22.567Z] 12:24:22     INFO -     r13 = 0x00007fb9e971c0e0   r14 = 0x00007fb9e971c148
[task 2020-03-10T12:24:22.568Z] 12:24:22     INFO -     r15 = 0x00007fb9eb588d68   rip = 0x00007fb9e2ec7e11
[task 2020-03-10T12:24:22.568Z] 12:24:22     INFO -     Found by: call frame info
[task 2020-03-10T12:24:22.569Z] 12:24:22     INFO -  8  libxul.so!__gcov_dump_one [libgcov-driver.c : 871 + 0xe]
[task 2020-03-10T12:24:22.569Z] 12:24:22     INFO -     rbx = 0x00007fb9ecafdf00   rbp = 0x00007fb9c89494d0
[task 2020-03-10T12:24:22.569Z] 12:24:22     INFO -     rsp = 0x00007fb9c89493b0   r12 = 0x00007fb9c4c1f140
[task 2020-03-10T12:24:22.569Z] 12:24:22     INFO -     r13 = 0x00007fb9bf06b280   r14 = 0x0000000000000001
[task 2020-03-10T12:24:22.570Z] 12:24:22     INFO -     r15 = 0x00007fb9c8949470   rip = 0x00007fb9e2ec8ca2
[task 2020-03-10T12:24:22.570Z] 12:24:22     INFO -     Found by: call frame info
[task 2020-03-10T12:24:22.571Z] 12:24:22     INFO -  9  libxul.so!__gcov_dump_int [libgcov-interface.c : 164 + 0x8]
[task 2020-03-10T12:24:22.571Z] 12:24:22     INFO -     rbx = 0x00007fb9ecafdf00   rbp = 0x00007fb9c89494d0
[task 2020-03-10T12:24:22.572Z] 12:24:22     INFO -     rsp = 0x00007fb9c89493c0   r12 = 0x00007fb9c4c1f140
[task 2020-03-10T12:24:22.572Z] 12:24:22     INFO -     r13 = 0x00007fb9bf06b280   r14 = 0x0000000000000001
[task 2020-03-10T12:24:22.573Z] 12:24:22     INFO -     r15 = 0x00007fb9c8949470   rip = 0x00007fb9e2ec8e38
[task 2020-03-10T12:24:22.573Z] 12:24:22     INFO -     Found by: call frame info
[task 2020-03-10T12:24:22.574Z] 12:24:22     INFO - 10  libxul.so!__gcov_flush [libgcov-interface.c : 88 + 0x5]
[task 2020-03-10T12:24:22.574Z] 12:24:22     INFO -     rbx = 0x00007fb9c8949460   rbp = 0x00007fb9c89494d0
[task 2020-03-10T12:24:22.575Z] 12:24:22     INFO -     rsp = 0x00007fb9c89493d0   r12 = 0x00007fb9c4c1f140
[task 2020-03-10T12:24:22.575Z] 12:24:22     INFO -     r13 = 0x00007fb9bf06b280   r14 = 0x0000000000000001
[task 2020-03-10T12:24:22.576Z] 12:24:22     INFO -     r15 = 0x00007fb9c8949470   rip = 0x00007fb9e2ec6aff
[task 2020-03-10T12:24:22.576Z] 12:24:22     INFO -     Found by: call frame info
[task 2020-03-10T12:24:22.577Z] 12:24:22     INFO - 11  libxul.so!__gcov_fork [libgcov-interface.c : 179 + 0x5]
[task 2020-03-10T12:24:22.577Z] 12:24:22     INFO -     rbx = 0x00007fb9c8949460   rbp = 0x00007fb9c89494d0
[task 2020-03-10T12:24:22.578Z] 12:24:22     INFO -     rsp = 0x00007fb9c89493e0   r12 = 0x00007fb9c4c1f140
[task 2020-03-10T12:24:22.578Z] 12:24:22     INFO -     r13 = 0x00007fb9bf06b280   r14 = 0x0000000000000001
[task 2020-03-10T12:24:22.579Z] 12:24:22     INFO -     r15 = 0x00007fb9c8949470   rip = 0x00007fb9e2ec6b36
[task 2020-03-10T12:24:22.579Z] 12:24:22     INFO -     Found by: call frame info
[task 2020-03-10T12:24:22.579Z] 12:24:22     INFO - 12  libxul.so!base::LaunchApp(std::vector<std::string, std::allocator<std::string> > const&, base::LaunchOptions const&, int*) [process_util_linux.cc:718652138136a4e4903197925698b752a5c793b6 : 232 + 0x5]
[task 2020-03-10T12:24:22.580Z] 12:24:22     INFO -     rbx = 0x00007fb9c8949460   rbp = 0x00007fb9c89494d0
[task 2020-03-10T12:24:22.580Z] 12:24:22     INFO -     rsp = 0x00007fb9c89493f0   r12 = 0x00007fb9c4c1f140
[task 2020-03-10T12:24:22.581Z] 12:24:22     INFO -     r13 = 0x00007fb9bf06b280   r14 = 0x0000000000000001
[task 2020-03-10T12:24:22.581Z] 12:24:22     INFO -     r15 = 0x00007fb9c8949470   rip = 0x00007fb9dbf458ee
[task 2020-03-10T12:24:22.581Z] 12:24:22     INFO -     Found by: call frame info
[task 2020-03-10T12:24:22.582Z] 12:24:22     INFO - 13  libxul.so!mozilla::ipc::PosixProcessLauncher::DoLaunch() [GeckoChildProcessHost.cpp:718652138136a4e4903197925698b752a5c793b6 : 1198 + 0x5]
[task 2020-03-10T12:24:22.582Z] 12:24:22     INFO -     rbx = 0x00007fb9c4c1f098   rbp = 0x00007fb9c8949520
[task 2020-03-10T12:24:22.583Z] 12:24:22     INFO -     rsp = 0x00007fb9c89494e0   r12 = 0x00007fb9c8949530
[task 2020-03-10T12:24:22.583Z] 12:24:22     INFO -     r13 = 0x00007fb9bf5872c0   r14 = 0x00007fb9c8949580
[task 2020-03-10T12:24:22.584Z] 12:24:22     INFO -     r15 = 0x00007fb9bf9c99b0   rip = 0x00007fb9dbf90656
[task 2020-03-10T12:24:22.584Z] 12:24:22     INFO -     Found by: call frame info
[task 2020-03-10T12:24:22.584Z] 12:24:22     INFO - 14  libxul.so!mozilla::ipc::BaseProcessLauncher::PerformAsyncLaunch() [GeckoChildProcessHost.cpp:718652138136a4e4903197925698b752a5c793b6 : 956 + 0xe]
[task 2020-03-10T12:24:22.585Z] 12:24:22     INFO -     rbx = 0x00007fb9c4c1f098   rbp = 0x00007fb9c8949570
[task 2020-03-10T12:24:22.585Z] 12:24:22     INFO -     rsp = 0x00007fb9c8949530   r12 = 0x00007fb9c4c1f090
[task 2020-03-10T12:24:22.586Z] 12:24:22     INFO -     r13 = 0x00007fb9bf5872c0   r14 = 0x00007fb9c8949580
[task 2020-03-10T12:24:22.586Z] 12:24:22     INFO -     r15 = 0x00007fb9bf9c99b0   rip = 0x00007fb9dbf933f1
[task 2020-03-10T12:24:22.586Z] 12:24:22     INFO -     Found by: call frame info
[task 2020-03-10T12:24:22.587Z] 12:24:22     INFO - 15  libxul.so!mozilla::detail::ProxyRunnable<mozilla::MozPromise<mozilla::ipc::LaunchResults, mozilla::ipc::LaunchError, false>, RefPtr<mozilla::MozPromise<mozilla::ipc::LaunchResults, mozilla::ipc::LaunchError, false> > (mozilla::ipc::BaseProcessLauncher::*)(), mozilla::ipc::BaseProcessLauncher>::Run() [MozPromise.h:718652138136a4e4903197925698b752a5c793b6 : 1349 + 0x2b]
[task 2020-03-10T12:24:22.587Z] 12:24:22     INFO -     rbx = 0x00007fb9bf5872c0   rbp = 0x00007fb9c89495a0
[task 2020-03-10T12:24:22.588Z] 12:24:22     INFO -     rsp = 0x00007fb9c8949580   r12 = 0x00007fb9c89495c0
[task 2020-03-10T12:24:22.588Z] 12:24:22     INFO -     r13 = 0x00007fb9bf5872c0   r14 = 0x00007fb9d5905298
[task 2020-03-10T12:24:22.589Z] 12:24:22     INFO -     r15 = 0x00007fb9bf9c99b0   rip = 0x00007fb9dbf9427f
[task 2020-03-10T12:24:22.589Z] 12:24:22     INFO -     Found by: call frame info
[task 2020-03-10T12:24:22.590Z] 12:24:22     INFO - 16  libxul.so!mozilla::TaskQueue::Runner::Run() [TaskQueue.cpp:718652138136a4e4903197925698b752a5c793b6 : 207 + 0xa]
[task 2020-03-10T12:24:22.590Z] 12:24:22     INFO -     rbx = 0x00007fb9bc8bb760   rbp = 0x00007fb9c8949680
[task 2020-03-10T12:24:22.590Z] 12:24:22     INFO -     rsp = 0x00007fb9c89495b0   r12 = 0x00007fb9c89495c0
[task 2020-03-10T12:24:22.590Z] 12:24:22     INFO -     r13 = 0x00007fb9bf5872c0   r14 = 0x00007fb9d5905298
[task 2020-03-10T12:24:22.591Z] 12:24:22     INFO -     r15 = 0x00007fb9bf9c99b0   rip = 0x00007fb9db7c48bb
[task 2020-03-10T12:24:22.591Z] 12:24:22     INFO -     Found by: call frame info
[task 2020-03-10T12:24:22.592Z] 12:24:22     INFO - 17  libxul.so!nsThread::ProcessNextEvent(bool, bool*) [nsThread.cpp:718652138136a4e4903197925698b752a5c793b6 : 1220 + 0x6]
[task 2020-03-10T12:24:22.592Z] 12:24:22     INFO -     rbx = 0x00007fb9c91a6de0   rbp = 0x00007fb9c8949bc0
[task 2020-03-10T12:24:22.593Z] 12:24:22     INFO -     rsp = 0x00007fb9c8949690   r12 = 0x00007fb9c91a6ea8
[task 2020-03-10T12:24:22.593Z] 12:24:22     INFO -     r13 = 0x0000000000000000   r14 = 0x00007fb9bc8bb760
[task 2020-03-10T12:24:22.593Z] 12:24:22     INFO -     r15 = 0x00007fb9c8949be7   rip = 0x00007fb9db7c8efd
[task 2020-03-10T12:24:22.594Z] 12:24:22     INFO -     Found by: call frame info
[task 2020-03-10T12:24:22.594Z] 12:24:22     INFO - 18  libxul.so!NS_ProcessNextEvent(nsIThread*, bool) [nsThreadUtils.cpp:718652138136a4e4903197925698b752a5c793b6 : 481 + 0xe]
[task 2020-03-10T12:24:22.595Z] 12:24:22     INFO -     rbx = 0x00007fb9c8949c90   rbp = 0x00007fb9c8949bf0
[task 2020-03-10T12:24:22.595Z] 12:24:22     INFO -     rsp = 0x00007fb9c8949bd0   r12 = 0x00007fb9cbd65300
[task 2020-03-10T12:24:22.596Z] 12:24:22     INFO -     r13 = 0x00007fb9c91a6de0   r14 = 0x00007fb9cbd65320
[task 2020-03-10T12:24:22.596Z] 12:24:22     INFO -     r15 = 0x0000000000000000   rip = 0x00007fb9db7b1bd3
[task 2020-03-10T12:24:22.597Z] 12:24:22     INFO -     Found by: call frame info
[task 2020-03-10T12:24:22.597Z] 12:24:22     INFO - 19  libxul.so!mozilla::ipc::MessagePumpForNonMainThreads::Run(base::MessagePump::Delegate*) [MessagePump.cpp:718652138136a4e4903197925698b752a5c793b6 : 332 + 0xd]
[task 2020-03-10T12:24:22.598Z] 12:24:22     INFO -     rbx = 0x00007fb9c8949c90   rbp = 0x00007fb9c8949c30
[task 2020-03-10T12:24:22.598Z] 12:24:22     INFO -     rsp = 0x00007fb9c8949c00   r12 = 0x00007fb9cbd65300
[task 2020-03-10T12:24:22.599Z] 12:24:22     INFO -     r13 = 0x00007fb9c91a6de0   r14 = 0x00007fb9cbd65320
[task 2020-03-10T12:24:22.599Z] 12:24:22     INFO -     r15 = 0x0000000000000000   rip = 0x00007fb9dbf9e0d1
[task 2020-03-10T12:24:22.600Z] 12:24:22     INFO -     Found by: call frame info
[task 2020-03-10T12:24:22.600Z] 12:24:22     INFO - 20  libxul.so!MessageLoop::Run() [message_loop.cc:718652138136a4e4903197925698b752a5c793b6 : 290 + 0x5]
[task 2020-03-10T12:24:22.600Z] 12:24:22     INFO -     rbx = 0x00007fb9c91a6de0   rbp = 0x00007fb9c8949c60
[task 2020-03-10T12:24:22.601Z] 12:24:22     INFO -     rsp = 0x00007fb9c8949c40   r12 = 0x00007fb9c8949c80
[task 2020-03-10T12:24:22.601Z] 12:24:22     INFO -     r13 = 0x00007fb9e9bc93e0   r14 = 0x00007fb9c8949c90
[task 2020-03-10T12:24:22.602Z] 12:24:22     INFO -     r15 = 0x00007fb9c894a640   rip = 0x00007fb9dbf4891a
[task 2020-03-10T12:24:22.602Z] 12:24:22     INFO -     Found by: call frame info
[task 2020-03-10T12:24:22.602Z] 12:24:22     INFO - 21  libxul.so!nsThread::ThreadFunc(void*) [nsThread.cpp:718652138136a4e4903197925698b752a5c793b6 : 464 + 0x8]
[task 2020-03-10T12:24:22.603Z] 12:24:22     INFO -     rbx = 0x00007fb9c91a6de0   rbp = 0x00007fb9c8949e60
[task 2020-03-10T12:24:22.603Z] 12:24:22     INFO -     rsp = 0x00007fb9c8949c70   r12 = 0x00007fb9c8949c80
[task 2020-03-10T12:24:22.604Z] 12:24:22     INFO -     r13 = 0x00007fb9e9bc93e0   r14 = 0x00007fb9c8949c90
[task 2020-03-10T12:24:22.604Z] 12:24:22     INFO -     r15 = 0x00007fb9c894a640   rip = 0x00007fb9db7c872f
[task 2020-03-10T12:24:22.604Z] 12:24:22     INFO -     Found by: call frame info
[task 2020-03-10T12:24:22.605Z] 12:24:22     INFO - 22  libnspr4.so!_pt_root [ptthread.c:718652138136a4e4903197925698b752a5c793b6 : 201 + 0x7]
[task 2020-03-10T12:24:22.605Z] 12:24:22     INFO -     rbx = 0x00007fb9c8d28ca0   rbp = 0x00007fb9c8949eb0
[task 2020-03-10T12:24:22.605Z] 12:24:22     INFO -     rsp = 0x00007fb9c8949e70   r12 = 0x0000000000000000
[task 2020-03-10T12:24:22.605Z] 12:24:22     INFO -     r13 = 0x00000000000004c5   r14 = 0x00007fb9c894a700
[task 2020-03-10T12:24:22.606Z] 12:24:22     INFO -     r15 = 0x00007fb9c894a640   rip = 0x00007fb9f7b619be
[task 2020-03-10T12:24:22.606Z] 12:24:22     INFO -     Found by: call frame info
[task 2020-03-10T12:24:22.606Z] 12:24:22     INFO - 23  libpthread-2.27.so!start_thread [pthread_create.c : 463 + 0xd]
[task 2020-03-10T12:24:22.607Z] 12:24:22     INFO -     rbx = 0x0000000000000000   rbp = 0x0000000000000000
[task 2020-03-10T12:24:22.607Z] 12:24:22     INFO -     rsp = 0x00007fb9c8949ec0   r12 = 0x00007fb9c8949f80
[task 2020-03-10T12:24:22.607Z] 12:24:22     INFO -     r13 = 0x0000000000000000   r14 = 0x00007fb9c8d28ca0
[task 2020-03-10T12:24:22.607Z] 12:24:22     INFO -     r15 = 0x00007fffa74cc2c0   rip = 0x00007fb9f77b76db
[task 2020-03-10T12:24:22.608Z] 12:24:22     INFO -     Found by: call frame info
[task 2020-03-10T12:24:22.608Z] 12:24:22     INFO - 24  libc-2.27.so!__GI___clone + 0x3f
[task 2020-03-10T12:24:22.608Z] 12:24:22     INFO -     rbx = 0x00007fb9c894a700   rbp = 0x0000000000000000
[task 2020-03-10T12:24:22.608Z] 12:24:22     INFO -     rsp = 0x00007fb9c8949f80   r12 = 0x00007fb9c8949f80
[task 2020-03-10T12:24:22.609Z] 12:24:22     INFO -     r13 = 0x0000000000000000   r14 = 0x00007fb9c8d28ca0
[task 2020-03-10T12:24:22.609Z] 12:24:22     INFO -     r15 = 0x00007fffa74cc2c0   rip = 0x00007fb9f679588f
[task 2020-03-10T12:24:22.609Z] 12:24:22     INFO -     Found by: call frame info
[task 2020-03-10T12:24:22.609Z] 12:24:22     INFO - 
[task 2020-03-10T12:24:22.610Z] 12:24:22     INFO - Thread 0
[task 2020-03-10T12:24:22.610Z] 12:24:22     INFO -  0  libxul.so!XPCWrappedNative::CallMethod(XPCCallContext&, XPCWrappedNative::CallMode) [XPCWrappedNative.cpp:718652138136a4e4903197925698b752a5c793b6 : 1141 + 0x5a0]
[task 2020-03-10T12:24:22.610Z] 12:24:22     INFO -     rax = 0x00007fb9e2f58458   rdx = 0x0000000000000008
[task 2020-03-10T12:24:22.610Z] 12:24:22     INFO -     rcx = 0x00007fffa74cee18   rbx = 0x0000000000000001
[task 2020-03-10T12:24:22.611Z] 12:24:22     INFO -     rsi = 0xfffffffffffffff8   rdi = 0x0000000000000000
[task 2020-03-10T12:24:22.611Z] 12:24:22     INFO -     rbp = 0x00007fffa74cef20   rsp = 0x00007fffa74cecf0
[task 2020-03-10T12:24:22.611Z] 12:24:22     INFO -      r8 = 0x0000000000000001    r9 = 0x0000000000000000
[task 2020-03-10T12:24:22.611Z] 12:24:22     INFO -     r10 = 0x0000000000000001   r11 = 0xfffc800000000000
[task 2020-03-10T12:24:22.612Z] 12:24:22     INFO -     r12 = 0x0000000000000001   r13 = 0x0000000000000000
[task 2020-03-10T12:24:22.612Z] 12:24:22     INFO -     r14 = 0x00000000000005e8   r15 = 0x00007fffa74cee10
[task 2020-03-10T12:24:22.612Z] 12:24:22     INFO -     rip = 0x00007fb9dc62c7d0
[task 2020-03-10T12:24:22.612Z] 12:24:22     INFO -     Found by: given as instruction pointer in context
[task 2020-03-10T12:24:22.613Z] 12:24:22     INFO -  1  libxul.so!XPC_WN_GetterSetter(JSContext*, unsigned int, JS::Value*) [XPCWrappedNativeJSOps.cpp:718652138136a4e4903197925698b752a5c793b6 : 987 + 0xd]
[task 2020-03-10T12:24:22.613Z] 12:24:22     INFO -     rbx = 0x00007fb9d032a000   rbp = 0x00007fffa74cf060
[task 2020-03-10T12:24:22.613Z] 12:24:22     INFO -     rsp = 0x00007fffa74cef30   r12 = 0x00007fffa74cf1e0
[task 2020-03-10T12:24:22.613Z] 12:24:22     INFO -     r13 = 0x0000000000000000   r14 = 0x0000000000000001
[task 2020-03-10T12:24:22.614Z] 12:24:22     INFO -     r15 = 0x00007fffa74cef90   rip = 0x00007fb9dc63655c
[task 2020-03-10T12:24:22.614Z] 12:24:22     INFO -     Found by: call frame info
[task 2020-03-10T12:24:22.614Z] 12:24:22     INFO -  2  libxul.so!js::InternalCallOrConstruct(JSContext*, JS::CallArgs const&, js::MaybeConstruct, js::CallReason) [Interpreter.cpp:718652138136a4e4903197925698b752a5c793b6 : 569 + 0x10a]
[task 2020-03-10T12:24:22.615Z] 12:24:22     INFO -     rbx = 0x00007fb9d032a000   rbp = 0x00007fffa74cf130
[task 2020-03-10T12:24:22.615Z] 12:24:22     INFO -     rsp = 0x00007fffa74cf070   r12 = 0x00007fffa74cf1b0
[task 2020-03-10T12:24:22.615Z] 12:24:22     INFO -     r13 = 0x00007fffa74cf090   r14 = 0x00007fb9dc636330
[task 2020-03-10T12:24:22.616Z] 12:24:22     INFO -     r15 = 0x00007fffa74cf0c0   rip = 0x00007fb9e0a6825a
[task 2020-03-10T12:24:22.616Z] 12:24:22     INFO -     Found by: call frame info
[task 2020-03-10T12:24:22.616Z] 12:24:22     INFO -  3  libxul.so!InternalCall [Interpreter.cpp:718652138136a4e4903197925698b752a5c793b6 : 632 + 0xd]
Crash Signature: [@ Allocator<MozJemallocBase>::free(void*)] → [@ Allocator<MozJemallocBase>::free(void*)], [@ RunWatchdog], [@ gcov_do_dump], [@ fseek]
Flags: needinfo?(mconley)
Regressed by: 1617983

Looking...

The stack shows that we're crashing in a call to PHC's replace_free inside of the thread in the parent process that does async process launch...

njn, is this a problem in PHC? Or is PHC just being asked to free a nullptr?

Or, jld, is this more likely a problem in the way we're async-launching the process / forking on the Linux server?

Flags: needinfo?(n.nethercote)
Flags: needinfo?(jld)

There's a bunch of 0xe5e5e5e5e5e5e5e5 in those registers, so it smells like a use after free.

See also bug 1603574 comment #5; there seems to be a bug in the gcov runtime. I wondered if the thing we're doing that's provoking the bug might be forking on multiple threads concurrently, which is unlikely but possible, but that's just a guess. Also I notice bug 1607004 comment #0, where the crash is under dlclose rather than fork.

Flags: needinfo?(jld)
See Also: → 1603574, 1607004

I think PHC's presence in the stack is a red herring. PHC wraps the allocator, but lets the vast majority of requests through to the allocator. The presence of the Allocator<MozJemallocBase>::free(void*) frame above PHC's replace_free is consistent with a free() call that is being passed through to the allocator.

Flags: needinfo?(n.nethercote)

Thre are 45 total failures in the last 2 days on linux1804-64-ccov

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

[task 2020-03-11T06:17:33.180Z] 06:17:33 INFO - TEST-START | xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_browserSettings.js
[task 2020-03-11T06:17:40.090Z] 06:17:40 WARNING - TEST-UNEXPECTED-FAIL | xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_browserSettings.js | xpcshell return code: -11
[task 2020-03-11T06:17:40.090Z] 06:17:40 INFO - TEST-INFO took 6911ms
[task 2020-03-11T06:17:40.090Z] 06:17:40 INFO - >>>>>>>
[task 2020-03-11T06:17:40.090Z] 06:17:40 INFO - PID 16714 | [CodeCoverage] Setting handlers for process 16714.
[task 2020-03-11T06:17:40.091Z] 06:17:40 INFO - (xpcshell/head.js) | test MAIN run_test pending (1)
[task 2020-03-11T06:17:40.091Z] 06:17:40 INFO - (xpcshell/head.js) | test run_next_test 0 pending (2)
[task 2020-03-11T06:17:40.091Z] 06:17:40 INFO - (xpcshell/head.js) | test MAIN run_test finished (2)
[task 2020-03-11T06:17:40.092Z] 06:17:40 INFO - running event loop
[task 2020-03-11T06:17:40.093Z] 06:17:40 INFO - xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_browserSettings.js | Starting check_remote
[task 2020-03-11T06:17:40.095Z] 06:17:40 INFO - (xpcshell/head.js) | test check_remote pending (2)
[task 2020-03-11T06:17:40.096Z] 06:17:40 INFO - TEST-PASS | xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_browserSettings.js | check_remote - [check_remote : 1] useRemoteWebExtensions matches - true == true
[task 2020-03-11T06:17:40.097Z] 06:17:40 INFO - TEST-PASS | xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_browserSettings.js | check_remote - [check_remote : 1] testing from extension process - false == false
[task 2020-03-11T06:17:40.097Z] 06:17:40 INFO - (xpcshell/head.js) | test run_next_test 0 finished (2)
[task 2020-03-11T06:17:40.097Z] 06:17:40 INFO - (xpcshell/head.js) | test run_next_test 1 pending (2)
[task 2020-03-11T06:17:40.097Z] 06:17:40 INFO - (xpcshell/head.js) | test check_remote finished (2)
[task 2020-03-11T06:17:40.097Z] 06:17:40 INFO - xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_browserSettings.js | Starting test_browser_settings
[task 2020-03-11T06:17:40.097Z] 06:17:40 INFO - (xpcshell/head.js) | test test_browser_settings pending (2)
[task 2020-03-11T06:17:40.097Z] 06:17:40 INFO - PID 16714 | 1583907454127 addons.manager DEBUG Application has been upgraded
[task 2020-03-11T06:17:40.097Z] 06:17:40 INFO - PID 16714 | 1583907454128 addons.manager DEBUG Loaded provider scope for resource://gre/modules/addons/XPIProvider.jsm: ["XPIProvider", "XPIInternal"]
[task 2020-03-11T06:17:40.097Z] 06:17:40 INFO - PID 16714 | 1583907454150 addons.manager DEBUG Loaded provider scope for resource://gre/modules/addons/GMPProvider.jsm
[task 2020-03-11T06:17:40.097Z] 06:17:40 INFO - PID 16714 | 1583907454159 addons.manager DEBUG Loaded provider scope for resource://gre/modules/addons/PluginProvider.jsm
[task 2020-03-11T06:17:40.099Z] 06:17:40 INFO - PID 16714 | 1583907454159 addons.manager DEBUG Starting provider: XPIProvider
[task 2020-03-11T06:17:40.103Z] 06:17:40 INFO - PID 16714 | 1583907454160 addons.xpi DEBUG startup
[task 2020-03-11T06:17:40.103Z] 06:17:40 INFO - PID 16714 | 1583907454161 addons.xpi DEBUG List of valid built-in add-ons could not be parsed.: [Exception... "Component returned failure code: 0xc1f30001 (NS_ERROR_NOT_INITIALIZED) [nsIXPCComponents_Utils.readUTF8URI]" nsresult: "0xc1f30001 (NS_ERROR_NOT_INITIALIZED)" location: "JS frame :: resource://gre/modules/addons/XPIProvider.jsm :: startup :: line 2374" data: no] Stack trace: startup()@resource://gre/modules/addons/XPIProvider.jsm:2374
[task 2020-03-11T06:17:40.103Z] 06:17:40 INFO - PID 16714 | callProvider()@resource://gre/modules/AddonManager.jsm:215
[task 2020-03-11T06:17:40.103Z] 06:17:40 INFO - PID 16714 | _startProvider()@resource://gre/modules/AddonManager.jsm:587
[task 2020-03-11T06:17:40.103Z] 06:17:40 INFO - PID 16714 | startup()@resource://gre/modules/AddonManager.jsm:811
[task 2020-03-11T06:17:40.103Z] 06:17:40 INFO - PID 16714 | startup()@resource://gre/modules/AddonManager.jsm:3482
[task 2020-03-11T06:17:40.103Z] 06:17:40 INFO - PID 16714 | observe()@resource://gre/modules/addonManager.js:87
[task 2020-03-11T06:17:40.103Z] 06:17:40 INFO - PID 16714 | promiseStartupManager()@resource://testing-common/AddonTestUtils.jsm:975
[task 2020-03-11T06:17:40.103Z] 06:17:40 INFO - PID 16714 | test_browser_settings()@/builds/worker/workspace/build/tests/xpcshell/tests/toolkit/components/extensions/test/xpcshell/test_ext_browserSettings.js:90
[task 2020-03-11T06:17:40.103Z] 06:17:40 INFO - PID 16714 | run_next_test/_run_next_test/<()@/builds/worker/workspace/build/tests/xpcshell/head.js:1567
[task 2020-03-11T06:17:40.103Z] 06:17:40 INFO - PID 16714 | _run_next_test()@/builds/worker/workspace/build/tests/xpcshell/head.js:1567
[task 2020-03-11T06:17:40.103Z] 06:17:40 INFO - PID 16714 | run()@/builds/worker/workspace/build/tests/xpcshell/head.js:735
[task 2020-03-11T06:17:40.103Z] 06:17:40 INFO - PID 16714 | _do_main()@/builds/worker/workspace/build/tests/xpcshell/head.js:246
[task 2020-03-11T06:17:40.103Z] 06:17:40 INFO - PID 16714 | _execute_test()@/builds/worker/workspace/build/tests/xpcshell/head.js:573
[task 2020-03-11T06:17:40.104Z] 06:17:40 INFO - PID 16714 | -e:1

Whiteboard: [retriggered][stockwell needswork:owner]

ni?ing marco to see how I can run ccov on debug builds on try to upload to pernosco.

Flags: needinfo?(mconley) → needinfo?(mcastelluccio)

Finally managed to get some linux1804-64 debug ccov builds going on try: https://treeherder.mozilla.org/#/jobs?repo=try&revision=b2a80e74ccf2296bb5847ff6a191b7a2966c03eb

Flags: needinfo?(mcastelluccio) → needinfo?(mconley)
Crash Signature: [@ Allocator<MozJemallocBase>::free(void*)], [@ RunWatchdog], [@ gcov_do_dump], [@ fseek] → [@ Allocator<MozJemallocBase>::free(void*)], [@ RunWatchdog], [@ gcov_do_dump], [@ fseek], [@ _IO_new_fclose]
Crash Signature: [@ Allocator<MozJemallocBase>::free(void*)], [@ RunWatchdog], [@ gcov_do_dump], [@ fseek], [@ _IO_new_fclose] → [@ Allocator<MozJemallocBase>::free(void*)], [@ RunWatchdog], [@ gcov_do_dump], [@ fseek], [@ _IO_new_fclose], [@ raise]

Mike, the failure occurs on Linux 18.04 x64 CCov opt, which was not triggered in your try push. i added the jobs and the failure still shows up. Please check try results.

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

(In reply to Andreea Pavel [:apavel] from comment #16)

Mike, the failure occurs on Linux 18.04 x64 CCov opt, which was not triggered in your try push. i added the jobs and the failure still shows up. Please check try results.

Thanks, apavel. The reason I wasn't running Linux 18.04 x64 CCov opt is because Pernosco / rr doesn't work with opt builds, and we must use debug builds. That's why my try push has debug builds.

Here's a more recent push where I think I've got the failure reproducing... I've aske Pernosco for a trace and am waiting to hear back: https://treeherder.mozilla.org/#/jobs?repo=try&revision=817bbe219fe8b845770512e66aaabae1c00882aa

Thank you!

Based on comment 5, I suspect what we should probably do is disable the privileged about content process on ccov builds. This is unfortunate, since we're going to be missing out on coverage measurement for more and more of the browser as we start taking advantage of the privileged about content process. I don't know how else to deal with this though. :/

I have had 0 luck getting Pernosco traces for this, which is doubly unfortunate.

marco, is it alright if I just go ahead and disable the separate privileged about content process for ccov builds?

Flags: needinfo?(mconley) → needinfo?(mcastelluccio)

Mike, would this be better classified under DOM::Content Processes? It looks more related to ipc than to layout to me.

Flags: needinfo?(mconley)

It's hard to say. This is maybe a bug in our process launching code, or maybe a bug in our IPC layer, or maybe a bug in our ccov code. I really don't know. :(

Flags: needinfo?(mconley)

(In reply to Mike Conley (:mconley) (:⚙️) from comment #19)

Based on comment 5, I suspect what we should probably do is disable the privileged about content process on ccov builds. This is unfortunate, since we're going to be missing out on coverage measurement for more and more of the browser as we start taking advantage of the privileged about content process. I don't know how else to deal with this though. :/

I have had 0 luck getting Pernosco traces for this, which is doubly unfortunate.

marco, is it alright if I just go ahead and disable the separate privileged about content process for ccov builds?

Yeah, it's unfortunate but it sounds like it's the best option for now.

Flags: needinfo?(mcastelluccio)

We should retry after we switch the coverage build to use Clang instead of GCC, maybe the bug is in ccov code and it will be fixed, or the bug is timing-dependent and it will disappear with a different compiler.

Since this is Linux-only, can we disable the privileged about content process for Linux only?

Assignee: nobody → mconley
Status: NEW → ASSIGNED
Attachment #9134257 - Attachment description: Bug 1621269 - Disable the privileged about content process on ccov builds. r?emalysz! → Bug 1621269 - Disable the privileged about content process on Linux64 ccov builds. r?emalysz!
Pushed by mconley@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/6089cf9fb442 Disable the privileged about content process on Linux64 ccov builds. r=emalysz
Whiteboard: [retriggered][stockwell disable-recommended] → [retriggered][stockwell disabled]
Summary: High frequency Linux ccov reftest pid: None | application crashed <[@ Allocator<MozJemallocBase>::free(void*)][@ gcov_do_dump][@ RunWatchdog][@ fseek]> after application terminated with exit code 11 → Perma Linux ccov reftest pid: None | application crashed <[@ Allocator<MozJemallocBase>::free(void*)][@ gcov_do_dump][@ RunWatchdog][@ fseek]> after application terminated with exit code 11
Summary: Perma Linux ccov reftest pid: None | application crashed <[@ Allocator<MozJemallocBase>::free(void*)][@ gcov_do_dump][@ RunWatchdog][@ fseek]> after application terminated with exit code 11 → High frequency Linux ccov reftest pid: None | application crashed <[@ Allocator<MozJemallocBase>::free(void*)][@ gcov_do_dump][@ RunWatchdog][@ fseek]> after application terminated with exit code 11

The priority flag is not set for this bug.
:dbaron, could you have a look please?

For more information, please visit auto_nag documentation.

Flags: needinfo?(dbaron)

Triaging this as a bug in gcov based on comment 5. That's not particularly high-confidence, but I'm reasonably confident that Layout is not the right place (just because the crash happened in a reftest).

Component: Layout → Code Coverage
Flags: needinfo?(dbaron)
Product: Core → Testing

The priority flag is not set for this bug.
:ekyle, could you have a look please?

For more information, please visit auto_nag documentation.

Flags: needinfo?(klahnakoski)

Pretty sure this is the same issue we're seeing in bug 1565352, and should go away when we switch to Clang.

Priority: -- → P3
See Also: → 1565352

Because this bug's Severity has not been changed from the default since it was filed, and it's Priority is P3 (Backlog,) indicating it has been triaged, the bug's Severity is being updated to S3 (normal.)

Assignee: mconley → nobody
Severity: normal → S3
Status: ASSIGNED → NEW
Flags: needinfo?(klahnakoski)
See Also: → 1642426

There were 52 failures in the last 7 days.

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

[task 2020-06-05T23:59:02.469Z] 23:59:02 INFO - TEST-START | browser/extensions/formautofill/test/unit/heuristics/third_party/test_Sears.js
[task 2020-06-05T23:59:18.343Z] 23:59:18 WARNING - TEST-UNEXPECTED-FAIL | browser/extensions/formautofill/test/unit/heuristics/third_party/test_Sears.js | xpcshell return code: -11
[task 2020-06-05T23:59:18.343Z] 23:59:18 INFO - TEST-INFO took 15879ms
[task 2020-06-05T23:59:18.344Z] 23:59:18 INFO - >>>>>>>
[task 2020-06-05T23:59:18.344Z] 23:59:18 INFO - PID 4926 | [CodeCoverage] Setting handlers for process 4926.
[task 2020-06-05T23:59:18.344Z] 23:59:18 INFO - (xpcshell/head.js) | test MAIN run_test pending (1)

[task 2020-06-05T23:59:18.386Z] 23:59:18 INFO - PID 4926 | profiling:/tmp/tmpdfAP0i/config/external/icu/common/ucasemap.gcda:Merge mismatch for function 18
[task 2020-06-05T23:59:18.386Z] 23:59:18 INFO - PID 4926 | profiling:/tmp/tmpdfAP0i/xpcom/threads/Unified_cpp_xpcom_threads1.gcda:Merge mismatch for function 544
[task 2020-06-05T23:59:18.387Z] 23:59:18 INFO - <<<<<<<
[task 2020-06-05T23:59:18.387Z] 23:59:18 INFO - mozcrash Downloading symbols from: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/aiI5HnKOToqVdPF0oaCblQ/artifacts/public/build/target.crashreporter-symbols.zip
[task 2020-06-05T23:59:21.676Z] 23:59:21 INFO - mozcrash Copy/paste: /builds/worker/fetches/minidump_stackwalk/minidump_stackwalk /tmp/xpc-other-qsScND/46dc8a76-6a10-d4e2-5727-b37eb9152234.dmp /tmp/tmpckI1Lt
[task 2020-06-05T23:59:26.040Z] 23:59:26 INFO - mozcrash Saved minidump as /builds/worker/workspace/build/blobber_upload_dir/46dc8a76-6a10-d4e2-5727-b37eb9152234.dmp
[task 2020-06-05T23:59:26.040Z] 23:59:26 INFO - mozcrash Saved app info as /builds/worker/workspace/build/blobber_upload_dir/46dc8a76-6a10-d4e2-5727-b37eb9152234.extra
[task 2020-06-05T23:59:26.040Z] 23:59:26 WARNING - PROCESS-CRASH | browser/extensions/formautofill/test/unit/heuristics/third_party/test_Sears.js | application crashed [@ gcov_do_dump]

Kyle, could you take a look, please?

Flags: needinfo?(klahnakoski)
Whiteboard: [retriggered][stockwell disabled] → [retriggered][stockwell disabled][stockwell needswork:owner]

calixte, and here is another.

Flags: needinfo?(cdenizet)
Status: NEW → RESOLVED
Closed: 4 years ago
Resolution: --- → WORKSFORME

The last report is unrelated to this bug which is Linux specific and in looking at logs it seems that there is nothing related to ccov.
:aryx, could you check why this failure has been reported here ?

Flags: needinfo?(cdenizet) → needinfo?(aryx.bugmail)

Annotator picked up wrong bug for crash signature [@ RunWatchdog].

Crash Signature: [@ Allocator<MozJemallocBase>::free(void*)], [@ RunWatchdog], [@ gcov_do_dump], [@ fseek], [@ _IO_new_fclose], [@ raise] → [@ Allocator<MozJemallocBase>::free(void*)], [@ RunWatchdog], [@ gcov_do_dump] [@ fseek] [@ _IO_new_fclose] [@ raise]
Flags: needinfo?(klahnakoski)
Flags: needinfo?(aryx.bugmail)
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: