Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

fix: work around a null scoped_ptr dereference #19366

Merged
merged 1 commit into from Aug 27, 2019

Conversation

richard-townsend-arm
Copy link
Contributor

Description of Change

For the last week or so, we've been running each Electron 6 commit through the unit tests multiple times. Sometimes, the unit test suite dies halfway through for no discernible reason. Executing under the debugger indicates that the callback passed to base::BindRepeating during atom's certificate verification process sometimes has a null bind_state, which causes the crash (this happens on x86 and on Windows on Arm). To workaround, this PR changes the callback to one which logs the result if this occurs. Since applying this fix, we haven't seen the issue in subsequent runs.

The certificate verification logic has been rewritten in master (therefore this patch will not apply). The new code may suffer from the same problem, but we haven't spotted it yet because we don't have enough capacity to test master and 6-0-x to the same level.

CC @jkleinsc @MarshallOfSound

Checklist

Release Notes

Notes: no-notes

@electron-cation electron-cation bot added the new-pr 🌱 PR opened in the last 24 hours label Jul 22, 2019
@richard-townsend-arm
Copy link
Contributor Author

CI seems to have flaked due the Github downtime.

@nornagon
Copy link
Member

Have you observed the log message being printed at all? I'm not sure what would cause the callback to become nulled out...

@richard-townsend-arm
Copy link
Contributor Author

So I just realised that I forgot to add --enable-logging=stderr to my test script. I'll add it now and we'll see how it gets on.

@electron-cation electron-cation bot removed the new-pr 🌱 PR opened in the last 24 hours label Jul 23, 2019
@richard-townsend-arm
Copy link
Contributor Author

OK, so a quick update on this one: I haven't been able to find an acceptable way of adding --enable-logging=stderr to my test scripts - electron.exe seems to be opening a ton of spurious console windows (which affects the results of window-focusing tests), and the tests seem to take a lot longer (with Powershell burning a lot of CPU cycles for some reason). I'll continue to try and figure out the best way to capture the stderr without this problem. In the meantime: I can reassure you that it happens quite rarely (5% of the runs that I examined), so it's kind of a "fix if time" issue.

@richard-townsend-arm
Copy link
Contributor Author

OK, so still trying to track down the problem. Everything seems to be behaving a bit weirdly, and my fix is not actually effective (?) Here's my x64 system demonstrating it:
image

So 1) The callback's bind_state_ should not be NULL, 2) even if it was null, cb.is_null() should have noticed it.

@jkleinsc
Copy link
Contributor

@richard-townsend-arm to see the logging set the ELECTRON_ENABLE_LOGGING environment variable to 1.

@nornagon
Copy link
Member

nornagon commented Jul 24, 2019

@jkleinsc --enable-logging=stderr should have done the trick, no need for the env var as well.

EDIT: oh, i see, the earlier message was saying that passing the flag wasn't easy to do. carry on.

@richard-townsend-arm
Copy link
Contributor Author

richard-townsend-arm commented Jul 24, 2019

So interestingly (trying with and without --ci), seems that it may be happening in the webview section:
image

stderr is not very helpful still:

 D:\electron\6\src\out\x64.dchecks\resources\electron.asar\renderer\init.js", source: D:\electron\6\src\out\x64.dchecks\resources\electron.asar\renderer\init.js (167)
[86952:0724/191625.432:INFO:CONSOLE(2885)] "Unable to load preload script: D:\electron\6\src\electron\spec\fixtures\module\preload-error-exception.js", source: electron/js2c/sandbox_bundle.js (2885)
[86952:0724/191625.433:INFO:CONSOLE(2886)] "Error: Hello World!", source: electron/js2c/sandbox_bundle.js (2886)
[86952:0724/191625.883:INFO:CONSOLE(2885)] "Unable to load preload script: D:\electron\6\src\electron\spec\fixtures\module\preload-error-syntax.js", source: electron/js2c/sandbox_bundle.js (2885)
[86952:0724/191625.883:INFO:CONSOLE(2886)] "ReferenceError: foobar is not defined", source: electron/js2c/sandbox_bundle.js (2886)
[86952:0724/191626.370:INFO:CONSOLE(2885)] "Unable to load preload script: D:\electron\6\src\electron\spec\fixtures\module\preload-invalid.js", source: electron/js2c/sandbox_bundle.js (2885)
[86952:0724/191626.371:INFO:CONSOLE(2886)] "Error: ENOENT: no such file or directory, open 'D:\electron\6\src\electron\spec\fixtures\module\preload-invalid.js'", source: electron/js2c/sandbox_bundle.js (2886)
[86952:0724/191626.446:ERROR:process_win.cc(168)] Unable to terminate process: Access is denied. (0x5)
[86952:0724/191627.710:ERROR:process_win.cc(168)] Unable to terminate process: Access is denied. (0x5)
[86952:0724/191628.170:ERROR:process_win.cc(168)] Unable to terminate process: Access is denied. (0x5)
[86952:0724/191629.252:ERROR:process_win.cc(168)] Unable to terminate process: Access is denied. (0x5)
[86952:0724/191629.705:WARNING:ipc_message_attachment_set.cc(49)] MessageAttachmentSet destroyed with unconsumed attachments: 0/1
[86952:0724/191629.932:ERROR:process_win.cc(168)] Unable to terminate process: Access is denied. (0x5)
[86952:0724/191630.339:WARNING:ipc_message_attachment_set.cc(49)] MessageAttachmentSet destroyed with unconsumed attachments: 0/1
'D:\electron\6\src\electron\spec\does-not-exist.txt' is not recognized as an internal or external command,
operable program or batch file.
[86952:0724/191646.059:INFO:CONSOLE(10)] "{"background":{"persistent":false,"scripts":["background.js"]},"content_scripts":[{"js":["main.js"],"matches":["<all_urls>"],"run_at":"document_start"}],"extensionId":"chrome-api","manifest_version":2,"name":"chrome-api","srcDirectory":"D:\\electron\\6\\src\\electron\\spec\\fixtures\\extensions\\chrome-api","startPage":"chrome-extension://chrome-api","version":"1.0"}", source: chrome-extension://chrome-api/main.js (10)
[86952:0724/191646.631:INFO:CONSOLE(14)] "{"message":"Hello World!","tabId":780}", source: chrome-extension://chrome-api/main.js (14)
[86952:0724/191647.139:INFO:CONSOLE(19)] "3", source: chrome-extension://chrome-api/main.js (19)
[86952:0724/191652.904:ERROR:process_win.cc(168)] Unable to terminate process: Access is denied. (0x5)
[86952:0724/191653.758:WARNING:quota_manager.cc(1737)] No storage quota provided in QuotaSettings.
[86952:0724/191654.744:WARNING:quota_manager.cc(1737)] No storage quota provided in QuotaSettings.
[86952:0724/191656.779:ERROR:process_win.cc(168)] Unable to terminate process: Access is denied. (0x5)
[86952:0724/191657.398:ERROR:process_win.cc(168)] Unable to terminate process: Access is denied. (0x5)
[86952:0724/191700.674:ERROR:process_win.cc(168)] Unable to terminate process: Access is denied. (0x5)
Blocked other://D:\electron\6\src\electron\spec\fixtures/pages/window-opener-location.html from calling getURL on its opener.
[86952:0724/191705.004:INFO:CONSOLE(90)] "LocationProxy: failed to parse string", source: D:\electron\6\src\out\x64.dchecks\resources\electron.asar\renderer\window-setup.js (90)
[86952:0724/191705.559:ERROR:process_win.cc(168)] Unable to terminate process: Access is denied. (0x5)
[86952:0724/191706.008:ERROR:process_win.cc(168)] Unable to terminate process: Access is denied. (0x5)
Blocked file:///D:/electron/6/src/electron/spec/fixtures/pages/window-opener-location.html from calling getURL on its opener.
[86952:0724/191706.910:INFO:CONSOLE(90)] "LocationProxy: failed to parse string", source: D:\electron\6\src\out\x64.dchecks\resources\electron.asar\renderer\window-setup.js (90)
[86952:0724/191706.924:INFO:CONSOLE(12)] "", source: other:///D:\electron\6\src\electron\spec\fixtures/pages/webview-opener-postMessage.html?p=file%3A%2F%2FD%3A%5Celectron%5C6%5Csrc%5Celectron%5Cspec%5Cfixtures%2Fpages%2Fwindow-opener-location.html (12)
[86952:0724/191707.859:INFO:CONSOLE(12)] "file:///D:/electron/6/src/electron/spec/fixtures/pages/webview-opener-postMessage.html?p=file%3A%2F%2FD%3A%5Celectron%5C6%5Csrc%5Celectron%5Cspec%5Cfixtures%2Fpages%2Fwindow-opener-location.html", source: file:///D:/electron/6/src/electron/spec/fixtures/pages/webview-opener-postMessage.html?p=file%3A%2F%2FD%3A%5Celectron%5C6%5Csrc%5Celectron%5Cspec%5Cfixtures%2Fpages%2Fwindow-opener-location.html (12)
[86952:0724/191708.796:INFO:CONSOLE(12)] "other:///D:\electron\6\src\electron\spec\fixtures/pages/webview-opener-postMessage.html?p=file%3A%2F%2FD%3A%5Celectron%5C6%5Csrc%5Celectron%5Cspec%5Cfixtures%2Fpages%2Fwindow-opener-location.html", source: other:///D:\electron\6\src\electron\spec\fixtures/pages/webview-opener-postMessage.html?p=file%3A%2F%2FD%3A%5Celectron%5C6%5Csrc%5Celectron%5Cspec%5Cfixtures%2Fpages%2Fwindow-opener-location.html (12)
[86952:0724/191708.808:ERROR:process_win.cc(168)] Unable to terminate process: Access is denied. (0x5)
[86952:0724/191708.821:ERROR:process_win.cc(168)] Unable to terminate process: Access is denied. (0x5)
[86952:0724/191709.954:ERROR:process_win.cc(168)] Unable to terminate process: Access is denied. (0x5)
[86952:0724/191710.834:INFO:CONSOLE(12)] "message", source: file:///D:/electron/6/src/electron/spec/fixtures/pages/webview-opener-postMessage.html?p=D%3A%5Celectron%5C6%5Csrc%5Celectron%5Cspec%5Cfixtures%2Fpages%2Fwindow-opener-postMessage.html (12)
[86952:0724/191710.845:ERROR:process_win.cc(168)] Unable to terminate process: Access is denied. (0x5)
[86952:0724/191710.857:ERROR:process_win.cc(168)] Unable to terminate process: Access is denied. (0x5)
[86952:0724/191711.657:ERROR:process_win.cc(168)] Unable to terminate process: Access is denied. (0x5)
[86952:0724/191711.671:ERROR:process_win.cc(168)] Unable to terminate process: Access is denied. (0x5)
[86952:0724/191713.759:ERROR:process_win.cc(168)] Unable to terminate process: Access is denied. (0x5)
[86952:0724/191728.846:ERROR:process_win.cc(168)] Unable to terminate process: Access is denied. (0x5)
[86952:0724/191729.496:ERROR:process_win.cc(168)] Unable to terminate process: Access is denied. (0x5)
[86952:0724/191729.665:INFO:CONSOLE(1146)] "document.registerElement is deprecated and will be removed in M80, around February 2020. Please use window.customElements.define instead. See https://www.chromestatus.com/features/4642138092470272 and https://developers.google.com/web/updates/2019/07/web-components-time-to-upgrade for more details.", source: D:\electron\6\src\electron\spec\chromium-spec.js (1146)
[86952:0724/191741.337:ERROR:process_win.cc(168)] Unable to terminate process: Access is denied. (0x5)
[86952:0724/191741.357:ERROR:process_win.cc(168)] Unable to terminate process: Access is denied. (0x5)
[86952:0724/191742.473:ERROR:process_win.cc(168)] Unable to terminate process: Access is denied. (0x5)
[86952:0724/191742.494:ERROR:process_win.cc(168)] Unable to terminate process: Access is denied. (0x5)
[86952:0724/191744.522:ERROR:process_win.cc(168)] Unable to terminate process: Access is denied. (0x5)
[86952:0724/191746.921:ERROR:process_win.cc(168)] Unable to terminate process: Access is denied. (0x5)
test[86952:0724/191807.009:INFO:CONSOLE(110)] "%cElectron Security Warning (Node.js Integration with Remote Content)", source: D:\electron\6\src\out\x64.dchecks\resources\electron.asar\renderer\security-warnings.js (110)
[86952:0724/191807.588:INFO:CONSOLE(128)] "%cElectron Security Warning (Disabled webSecurity)", source: D:\electron\6\src\out\x64.dchecks\resources\electron.asar\renderer\security-warnings.js (128)
[86952:0724/191807.589:INFO:CONSOLE(159)] "%cElectron Security Warning (allowRunningInsecureContent)", source: D:\electron\6\src\out\x64.dchecks\resources\electron.asar\renderer\security-warnings.js (159)
[86952:0724/191808.176:INFO:CONSOLE(145)] "%cElectron Security Warning (Insecure Content-Security-Policy)", source: D:\electron\6\src\out\x64.dchecks\resources\electron.asar\renderer\security-warnings.js (145)
[86952:0724/191808.703:INFO:CONSOLE(159)] "%cElectron Security Warning (allowRunningInsecureContent)", source: D:\electron\6\src\out\x64.dchecks\resources\electron.asar\renderer\security-warnings.js (159)
[86952:0724/191809.223:INFO:CONSOLE(173)] "%cElectron Security Warning (experimentalFeatures)", source: D:\electron\6\src\out\x64.dchecks\resources\electron.asar\renderer\security-warnings.js (173)
[86952:0724/191809.841:INFO:CONSOLE(189)] "%cElectron Security Warning (enableBlinkFeatures)", source: D:\electron\6\src\out\x64.dchecks\resources\electron.asar\renderer\security-warnings.js (189)
[86952:0724/191810.430:INFO:CONSOLE(206)] "%cElectron Security Warning (allowpopups)", source: D:\electron\6\src\out\x64.dchecks\resources\electron.asar\renderer\security-warnings.js (206)
[86952:0724/191811.026:INFO:CONSOLE(95)] "%cElectron Security Warning (Insecure Resources)", source: D:\electron\6\src\out\x64.dchecks\resources\electron.asar\renderer\security-warnings.js (95)
[86952:0724/191811.137:ERROR:process_win.cc(168)] Unable to terminate process: Access is denied. (0x5)
[86952:0724/191811.551:INFO:CONSOLE(1819)] "%cElectron Security Warning (Disabled webSecurity)", source: electron/js2c/sandbox_bundle.js (1819)
[86952:0724/191811.552:INFO:CONSOLE(1850)] "%cElectron Security Warning (allowRunningInsecureContent)", source: electron/js2c/sandbox_bundle.js (1850)
[86952:0724/191812.062:INFO:CONSOLE(1836)] "%cElectron Security Warning (Insecure Content-Security-Policy)", source: electron/js2c/sandbox_bundle.js (1836)
[86952:0724/191812.575:INFO:CONSOLE(1850)] "%cElectron Security Warning (allowRunningInsecureContent)", source: electron/js2c/sandbox_bundle.js (1850)
[86952:0724/191813.056:INFO:CONSOLE(1864)] "%cElectron Security Warning (experimentalFeatures)", source: electron/js2c/sandbox_bundle.js (1864)
[86952:0724/191813.493:INFO:CONSOLE(1880)] "%cElectron Security Warning (enableBlinkFeatures)", source: electron/js2c/sandbox_bundle.js (1880)
[86952:0724/191813.907:INFO:CONSOLE(1897)] "%cElectron Security Warning (allowpopups)", source: electron/js2c/sandbox_bundle.js (1897)
[86952:0724/191814.428:INFO:CONSOLE(1786)] "%cElectron Security Warning (Insecure Resources)", source: electron/js2c/sandbox_bundle.js (1786)
[86952:0724/191815.005:INFO:CONSOLE(128)] "%cElectron Security Warning (Disabled webSecurity)", source: D:\electron\6\src\out\x64.dchecks\resources\electron.asar\renderer\security-warnings.js (128)
[86952:0724/191815.005:INFO:CONSOLE(159)] "%cElectron Security Warning (allowRunningInsecureContent)", source: D:\electron\6\src\out\x64.dchecks\resources\electron.asar\renderer\security-warnings.js (159)
[86952:0724/191815.576:INFO:CONSOLE(145)] "%cElectron Security Warning (Insecure Content-Security-Policy)", source: D:\electron\6\src\out\x64.dchecks\resources\electron.asar\renderer\security-warnings.js (145)
[86952:0724/191816.180:INFO:CONSOLE(159)] "%cElectron Security Warning (allowRunningInsecureContent)", source: D:\electron\6\src\out\x64.dchecks\resources\electron.asar\renderer\security-warnings.js (159)
[86952:0724/191816.748:INFO:CONSOLE(173)] "%cElectron Security Warning (experimentalFeatures)", source: D:\electron\6\src\out\x64.dchecks\resources\electron.asar\renderer\security-warnings.js (173)
[86952:0724/191817.278:INFO:CONSOLE(189)] "%cElectron Security Warning (enableBlinkFeatures)", source: D:\electron\6\src\out\x64.dchecks\resources\electron.asar\renderer\security-warnings.js (189)
[86952:0724/191817.885:INFO:CONSOLE(206)] "%cElectron Security Warning (allowpopups)", source: D:\electron\6\src\out\x64.dchecks\resources\electron.asar\renderer\security-warnings.js (206)
[86952:0724/191818.403:INFO:CONSOLE(95)] "%cElectron Security Warning (Insecure Resources)", source: D:\electron\6\src\out\x64.dchecks\resources\electron.asar\renderer\security-warnings.js (95)
[86952:0724/191821.375:ERROR:process_win.cc(168)] Unable to terminate process: Access is denied. (0x5)
[86952:0724/191821.385:ERROR:process_win.cc(168)] Unable to terminate process: Access is denied. (0x5)
[86952:0724/191822.423:ERROR:process_win.cc(168)] Unable to terminate process: Access is denied. (0x5)
[86952:0724/191822.442:ERROR:process_win.cc(168)] Unable to terminate process: Access is denied. (0x5)
[86952:0724/191823.201:ERROR:process_win.cc(168)] Unable to terminate process: Access is denied. (0x5)
[86952:0724/191823.212:ERROR:process_win.cc(168)] Unable to terminate process: Access is denied. (0x5)
[86952:0724/191824.718:INFO:CONSOLE(7)] "a", source: file:///D:/electron/6/src/electron/spec/fixtures/pages/a.html (7)
[86952:0724/191825.234:VERBOSE1:CONSOLE(8094)] "Main._createAppUI: 67.549072265625ms", source: devtools://devtools/bundled/shell.js (8094)
[86952:0724/191825.313:VERBOSE1:CONSOLE(8094)] "Main._showAppUI: 28.896240234375ms", source: devtools://devtools/bundled/shell.js (8094)
[86952:0724/191825.357:VERBOSE1:CONSOLE(8094)] "Main._initializeTarget: 30.44189453125ms", source: devtools://devtools/bundled/shell.js (8094)
[86952:0724/191825.525:VERBOSE1:CONSOLE(8094)] "Main._lateInitialization: 7.768798828125ms", source: devtools://devtools/bundled/shell.js (8094)
[86952:0724/191825.719:ERROR:CONSOLE(24)] "Empty response arrived for script 'devtools://devtools/remote/serve_file/@b0d7645bbb7099871083a253a26eaf4e0c5f3975/product_registry_impl/product_registry_impl_module.js'", source: devtools://devtools/bundled/shell.js (24)
[86952:0724/191825.720:ERROR:CONSOLE(109)] "Uncaught (in promise) Error: Could not instantiate: ProductRegistryImpl.Registry", source: devtools://devtools/bundled/shell.js (109)
[86952:0724/191825.721:ERROR:CONSOLE(109)] "Uncaught (in promise) Error: Could not instantiate: ProductRegistryImpl.Registry", source: devtools://devtools/bundled/shell.js (109)
[86952:0724/191825.722:ERROR:CONSOLE(109)] "Uncaught (in promise) Error: Could not instantiate: ProductRegistryImpl.Registry", source: devtools://devtools/bundled/shell.js (109)
[86952:0724/191826.717:INFO:CONSOLE(7)] "a", source: file:///D:/electron/6/src/electron/spec/fixtures/pages/a.html (7)
[86952:0724/191827.266:INFO:CONSOLE(7)] "a", source: file:///D:/electron/6/src/electron/spec/fixtures/pages/a.html (7)
[86952:0724/191827.592:INFO:CONSOLE(5)] "b", source: file:///D:/electron/6/src/electron/spec/fixtures/pages/b.html (5)
[86952:0724/191827.609:ERROR:process_win.cc(168)] Unable to terminate process: Access is denied. (0x5)
[86952:0724/191828.141:INFO:CONSOLE(4)] "Window script is loaded before preload script", source: file:///D:/electron/6/src/electron/spec/fixtures/pages/e.html (4)
[86952:0724/191828.881:FATAL:scoped_refptr.h(220)] Check failed: ptr_.

@richard-townsend-arm
Copy link
Contributor Author

I'll try to replicate it on Linux (that way I can do reverse debug).

@richard-townsend-arm
Copy link
Contributor Author

So I think the missing piece of the puzzle is that proc's bind_state can also be null. Hopefully get a new patch out tomorrow.

@richard-townsend-arm
Copy link
Contributor Author

richard-townsend-arm commented Aug 13, 2019

Cool, so the current patch should take care of the problem.

@jkleinsc
Copy link
Contributor

@richard-townsend-arm can you rebase this with the latest from 6-0-x? I just merged in the changes so that we can properly build WOA.

This happens occasionally when running the test suite and indicates
that the callback's been reset or the underlying reference has been
released. To workaround, print a warning.
@jkleinsc
Copy link
Contributor

@nornagon
Copy link
Member

I still don't understand how proc.bind_state gets to be null here..?

@jkleinsc jkleinsc merged commit 0491abf into electron:6-0-x Aug 27, 2019
@release-clerk
Copy link

release-clerk bot commented Aug 27, 2019

No Release Notes

@richard-townsend-arm richard-townsend-arm deleted the null-cb-deref branch August 27, 2019 15:39
@richard-townsend-arm
Copy link
Contributor Author

(Although it's just been merged, a quick explanation of what I think was going wrong for posterity): I think it's related to #18065: when AtomCertVerifier::OnDefaultVerificationDone gets called, it doesn't check whether AtomCertVerifier::verify_proc() is null or not. It's supposed to be set to something non-null by SetCertVerifyProcInIO, but this is is (for some reason) queued up to run asynchronously on the IO thread. I think this means that when the IO thread's congested, there's a small window of opportunity where requests can complete and verify_proc() is null. It's proving tough to prove beyond all doubt that this is what's actually happening though due to the heavy asynchronous...ness going on.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

Successfully merging this pull request may close these issues.

None yet

4 participants