search

cztomczak / cefpython

Python bindings for the Chromium Embedded Framework (CEF)
Other
3.06k stars 472 forks source link

[Windows] Crash on exit with multi_threaded_message_loop=True #380

Open cztomczak opened 7 years ago

cztomczak commented 7 years ago

Patch available in PR #412.

Do not call CefDoMessageLoopWork in cef.Shutdown() when multi_threaded_message_loop=True. This is probably the cause of a crash in pywin32.py example (PR #374) when using multi threaded message loop.

To fix this, modifications in cefpython.pyx are required, so that message loop work calls are not executed during shutdown when multi threaded message loop is set to true. PRs are welcome.

cztomczak commented 6 years ago

Related PR: https://github.com/cztomczak/cefpython/pull/412

MikeChurvis commented 4 years ago

Is a workaround available? Even after following the correct browser close-and-dereference procedures, cef.Shutdown() still crashes the application, but yields neither an exception nor a stack trace.

A minimal example of the problem code:

import sys
import time
from cefpython3 import cefpython as cef

test_browser = None

def main():
    sys.excepthook = cef.ExceptHook
    cef.Initialize(
        settings={'multi_threaded_message_loop': True},
        switches={'enable-logging': '',
                  'v': '1'}
    )

    cef.PostTask(cef.TID_UI, create_test_browser)
    time.sleep(5.0)
    cef.PostTask(cef.TID_UI, close_test_browser)

    try:
        print('Trying cef.Shutdown()')
        cef.Shutdown()
    finally:
        print("Post-Shutdown code")  # Execution never reaches this point.

def create_test_browser():
    assert cef.IsThread(cef.TID_UI)

    global test_browser
    test_browser = cef.CreateBrowserSync(
        cef.WindowInfo(), 
        {},
        'data:text/html,<!DOCTYPE html><html><body>Hello World!</body></html>'
    )

def close_test_browser():
    assert cef.IsThread(cef.TID_UI)

    global test_browser
    test_browser.CloseBrowser()
    test_browser = None

    print('Test browser closed')

if __name__ == '__main__':
    main()

And the resulting log (verbose level 1):

[0819/221427.942:VERBOSE1:webrtc_internals.cc(125)] Could not get the download directory.
[0819/221427.940:INFO:cefpython_app.cpp(199)] [Browser process] OnBeforeChildProcessLaunch() command line: "C:\Users\MikeChurvis\.virtualenvs\ClockButton_V2-bOJ0vsI8\lib\site-packages\cefpython3\subprocess" --type=gpu-process --enable-logging --no-sandbox --v=1 --locales-dir-path="C:\Users\MikeChurvis\.virtualenvs\ClockButton_V2-bOJ0vsI8\lib\site-packages\cefpython3\locales" --log-file="C:\Users\MikeChurvis\.virtualenvs\ClockButton_V2-bOJ0vsI8\Scripts\debug.log" --log-severity=error --resources-dir-path="C:\Users\MikeChurvis\.virtualenvs\ClockButton_V2-bOJ0vsI8\lib\site-packages\cefpython3" --lang=en-US --disable-gpu-shader-disk-cache /prefetch:2

[0819/221427.947:INFO:cefpython_app.cpp(199)] [Browser process] OnBeforeChildProcessLaunch() command line: "C:\Users\MikeChurvis\.virtualenvs\ClockButton_V2-bOJ0vsI8\lib\site-packages\cefpython3\subprocess" --type=gpu-process --enable-logging --no-sandbox --v=1 --locales-dir-path="C:\Users\MikeChurvis\.virtualenvs\ClockButton_V2-bOJ0vsI8\lib\site-packages\cefpython3\locales" --log-file="C:\Users\MikeChurvis\.virtualenvs\ClockButton_V2-bOJ0vsI8\Scripts\debug.log" --log-severity=error --resources-dir-path="C:\Users\MikeChurvis\.virtualenvs\ClockButton_V2-bOJ0vsI8\lib\site-packages\cefpython3" --lang=en-US --disable-gpu-shader-disk-cache --gpu-preferences=KAAAAAAAAACAA4CAAQAAAAAAAAAAAGAAEAAAAAAAAAAAAAAAAAAAACgAAAAEAAAAIAAAAAAAAAAoAAAAAAAAADAAAAAAAAAAOAAAAAAAAAAQAAAAAAAAAAAAAAAKAAAAEAAAAAAAAAAAAAAACwAAABAAAAAAAAAAAQAAAAoAAAAQAAAAAAAAAAEAAAALAAAA --locales-dir-path="C:\Users\MikeChurvis\.virtualenvs\ClockButton_V2-bOJ0vsI8\lib\site-packages\cefpython3\locales" --log-file="C:\Users\MikeChurvis\.virtualenvs\ClockButton_V2-bOJ0vsI8\Scripts\debug.log" --log-severity=error --resources-dir-path="C:\Users\MikeChurvis\.virtualenvs\ClockButton_V2-bOJ0vsI8\lib\site-packages\cefpython3" --lang=en-US /prefetch:2

[0819/221428.106:VERBOSE1:pref_proxy_config_tracker_impl.cc(155)] 00000264FE5A8570: set chrome proxy config service to 0000026481A02F50

DevTools listening on ws://127.0.0.1:54482/devtools/browser/2585a64a-2a08-4a6f-b1d9-59a46d66aa99
[0819/221428.117:VERBOSE1:multi_log_ct_verifier.cc(75)] Adding CT log: Google 'Argon2018' log
[0819/221428.117:VERBOSE1:multi_log_ct_verifier.cc(75)] Adding CT log: Google 'Argon2019' log
[0819/221428.117:VERBOSE1:multi_log_ct_verifier.cc(75)] Adding CT log: Google 'Argon2020' log
[0819/221428.117:VERBOSE1:multi_log_ct_verifier.cc(75)] Adding CT log: Google 'Argon2021' log
[0819/221428.118:VERBOSE1:multi_log_ct_verifier.cc(75)] Adding CT log: Google 'Aviator' log
[0819/221428.118:VERBOSE1:multi_log_ct_verifier.cc(75)] Adding CT log: Google 'Icarus' log
[0819/221428.118:VERBOSE1:multi_log_ct_verifier.cc(75)] Adding CT log: Google 'Pilot' log
[0819/221428.118:VERBOSE1:multi_log_ct_verifier.cc(75)] Adding CT log: Google 'Rocketeer' log
[0819/221428.118:VERBOSE1:multi_log_ct_verifier.cc(75)] Adding CT log: Google 'Skydiver' log
[0819/221428.118:VERBOSE1:multi_log_ct_verifier.cc(75)] Adding CT log: Cloudflare 'Nimbus2018' Log
[0819/221428.118:VERBOSE1:multi_log_ct_verifier.cc(75)] Adding CT log: Cloudflare 'Nimbus2019' Log
[0819/221428.118:VERBOSE1:multi_log_ct_verifier.cc(75)] Adding CT log: Cloudflare 'Nimbus2020' Log
[0819/221428.118:VERBOSE1:multi_log_ct_verifier.cc(75)] Adding CT log: Cloudflare 'Nimbus2021' Log
[0819/221428.118:VERBOSE1:multi_log_ct_verifier.cc(75)] Adding CT log: DigiCert Log Server
[0819/221428.118:VERBOSE1:multi_log_ct_verifier.cc(75)] Adding CT log: DigiCert Log Server 2
[0819/221428.118:VERBOSE1:multi_log_ct_verifier.cc(75)] Adding CT log: Symantec log
[0819/221428.118:VERBOSE1:multi_log_ct_verifier.cc(75)] Adding CT log: Symantec 'Vega' log
[0819/221428.118:VERBOSE1:multi_log_ct_verifier.cc(75)] Adding CT log: Symantec 'Sirius' log
[0819/221428.118:VERBOSE1:multi_log_ct_verifier.cc(75)] Adding CT log: Venafi Gen2 CT log
[0819/221428.118:VERBOSE1:multi_log_ct_verifier.cc(75)] Adding CT log: CNNIC CT log
[0819/221428.118:VERBOSE1:multi_log_ct_verifier.cc(75)] Adding CT log: Comodo 'Sabre' CT log
[0819/221428.118:VERBOSE1:multi_log_ct_verifier.cc(75)] Adding CT log: Comodo 'Mammoth' CT log
[0819/221428.118:VERBOSE1:multi_log_ct_verifier.cc(75)] Adding CT log: StartCom log
[0819/221428.118:VERBOSE1:multi_log_ct_verifier.cc(75)] Adding CT log: WoSign log
[0819/221428.118:VERBOSE1:multi_log_ct_verifier.cc(75)] Adding CT log: Izenpe log
[0819/221428.119:VERBOSE1:multi_log_ct_verifier.cc(75)] Adding CT log: Venafi log
[0819/221428.119:VERBOSE1:multi_log_ct_verifier.cc(75)] Adding CT log: Certly.IO log
[0819/221428.120:INFO:cef_log.cpp(8)] [Browser process] PyTaskRunnable: taskId=1, func=create_test_browser

[0819/221428.121:INFO:cef_log.cpp(8)] [Browser process] CreateBrowserSync() called

[0819/221428.122:INFO:cef_log.cpp(8)] [Browser process] navigateUrl: data:text/html,<!DOCTYPE html><html><body>Hello World!</body></html>

[0819/221428.122:INFO:cef_log.cpp(8)] [Browser process] CefBrowser::CreateBrowserSync()

[0819/221428.202:INFO:cef_log.cpp(8)] [Browser process] GetPyBrowser(): create new PyBrowser, browserId=1

[0819/221428.293:INFO:cef_log.cpp(8)] [Browser process] Switch already set, ignoring: enable-logging

[0819/221428.293:INFO:cef_log.cpp(8)] [Browser process] Switch already set, ignoring: v

[0819/221428.293:INFO:cefpython_app.cpp(199)] [Browser process] OnBeforeChildProcessLaunch() command line: "C:\Users\MikeChurvis\.virtualenvs\ClockButton_V2-bOJ0vsI8\lib\site-packages\cefpython3\subprocess" --type=renderer --enable-logging --no-sandbox --v=1 --service-pipe-token=8A99C6C31CA3F68820A2404F8F3D783A --lang=en-US --locales-dir-path="C:\Users\MikeChurvis\.virtualenvs\ClockButton_V2-bOJ0vsI8\lib\site-packages\cefpython3\locales" --log-file="C:\Users\MikeChurvis\.virtualenvs\ClockButton_V2-bOJ0vsI8\Scripts\debug.log" --log-severity=error --resources-dir-path="C:\Users\MikeChurvis\.virtualenvs\ClockButton_V2-bOJ0vsI8\lib\site-packages\cefpython3" --disable-gpu-shader-disk-cache /prefetch:1

[0819/221428.368:INFO:cef_log.cpp(8)] [Browser process] GetPyFrame(): underlying frame does not yet exist: browserId = 1, frameId = -4

[0819/221428.372:INFO:cef_log.cpp(8)] [Browser process] CefBrowser::CreateBrowserSync() succeeded

[0819/221428.372:INFO:cef_log.cpp(8)] [Browser process] CefBrowser window handle = 1443448

[0819/221428.374:VERBOSE1:network_delegate.cc(30)] NetworkDelegate::NotifyBeforeURLRequest: data:text/html,<!DOCTYPE html><html><body>Hello World!</body></html>
[0819/221428.377:INFO:cef_log.cpp(8)] [Browser process] GetPyFrame(): underlying frame does not yet exist: browserId = 1, frameId = -4

[0819/221428.378:INFO:cef_log.cpp(8)] [Browser process] GetPyFrame(): underlying frame does not yet exist: browserId = 1, frameId = -4

[0819/221429.271:INFO:cef_log.cpp(8)] [Browser process] GetPyFrame(): create new PyFrame, frameId=2

[0819/221433.114:INFO:cef_log.cpp(8)] [Browser process] Shutdown()

[0819/221433.114:INFO:cef_log.cpp(8)] [Browser process] PyTaskRunnable: taskId=2, func=close_test_browser

[0819/221433.114:INFO:cef_log.cpp(8)] [Browser process] CefBrowser::CloseBrowser(False)

Trying cef.Shutdown()
Test browser closed
[0819/221433.185:INFO:cef_log.cpp(8)] [Browser process] LifespanHandler_OnBeforeClose

[0819/221433.185:INFO:cef_log.cpp(8)] [Browser process] del g_pyFrames[1#2]

[0819/221433.186:INFO:cef_log.cpp(8)] [Browser process] del g_pyBrowsers[1]

Process finished with exit code -2147483645

The exit code corresponds to Exception code: 0x80000003. This issue has been discussed on the CEF Forum. However, the workaround proposed (equivalent to adding {'disable-features': 'NetworkService'} to the switches param of cef.Initialize) yielded no success.

My specs:

CEF Python 66.0 Chromium 66.0.3359.181 CEF 3.3359.1774.gd49d25f Python 3.7.4 64bit PyCharm Professional 2019.3 Windows 10 Microsoft Surface Pro 3

Let me know if I can answer any further questions. Thank you for your time.

cztomczak commented 4 years ago

LifespanHandler::OnBeforeClose should be called before Shutdown otherwise errors will occur. You could call Shutdown from OnBeforeClose.

@MikeChurvis Your logs don't make sense, Shutdown is being called before "Trying cef.Shutdown" is printed.

MikeChurvis commented 4 years ago

@cztomczak New discovery: The error still occurs when no browser is created.

New minimal example:

import sys

from cefpython3 import cefpython as cef

def main():
    sys.excepthook = cef.ExceptHook

    cef.Initialize(
        settings={
            'multi_threaded_message_loop': True},
        switches={
            'enable-logging': '',
            'v': '1'
    })
    print('Initialize complete.')

    cef.Shutdown()
    print('Shutdown complete.')

if __name__ == '__main__':
    main()

The log:

[0820/191635.669:VERBOSE1:webrtc_internals.cc(125)] Could not get the download directory.
[0820/191635.667:INFO:cefpython_app.cpp(199)] [Browser process] OnBeforeChildProcessLaunch() command line: "C:\Users\MikeChurvis\.virtualenvs\ClockButton_V2-bOJ0vsI8\lib\site-packages\cefpython3\subprocess" --type=gpu-process --enable-logging --no-sandbox --v=1 --locales-dir-path="C:\Users\MikeChurvis\.virtualenvs\ClockButton_V2-bOJ0vsI8\lib\site-packages\cefpython3\locales" --log-file="C:\Users\MikeChurvis\.virtualenvs\ClockButton_V2-bOJ0vsI8\Scripts\debug.log" --log-severity=error --resources-dir-path="C:\Users\MikeChurvis\.virtualenvs\ClockButton_V2-bOJ0vsI8\lib\site-packages\cefpython3" --lang=en-US --disable-gpu-shader-disk-cache /prefetch:2

[0820/191635.671:INFO:cefpython_app.cpp(199)] [Browser process] OnBeforeChildProcessLaunch() command line: "C:\Users\MikeChurvis\.virtualenvs\ClockButton_V2-bOJ0vsI8\lib\site-packages\cefpython3\subprocess" --type=gpu-process --enable-logging --no-sandbox --v=1 --locales-dir-path="C:\Users\MikeChurvis\.virtualenvs\ClockButton_V2-bOJ0vsI8\lib\site-packages\cefpython3\locales" --log-file="C:\Users\MikeChurvis\.virtualenvs\ClockButton_V2-bOJ0vsI8\Scripts\debug.log" --log-severity=error --resources-dir-path="C:\Users\MikeChurvis\.virtualenvs\ClockButton_V2-bOJ0vsI8\lib\site-packages\cefpython3" --lang=en-US --disable-gpu-shader-disk-cache --gpu-preferences=KAAAAAAAAACAA4CAAQAAAAAAAAAAAGAAEAAAAAAAAAAAAAAAAAAAACgAAAAEAAAAIAAAAAAAAAAoAAAAAAAAADAAAAAAAAAAOAAAAAAAAAAQAAAAAAAAAAAAAAAKAAAAEAAAAAAAAAAAAAAACwAAABAAAAAAAAAAAQAAAAoAAAAQAAAAAAAAAAEAAAALAAAA --locales-dir-path="C:\Users\MikeChurvis\.virtualenvs\ClockButton_V2-bOJ0vsI8\lib\site-packages\cefpython3\locales" --log-file="C:\Users\MikeChurvis\.virtualenvs\ClockButton_V2-bOJ0vsI8\Scripts\debug.log" --log-severity=error --resources-dir-path="C:\Users\MikeChurvis\.virtualenvs\ClockButton_V2-bOJ0vsI8\lib\site-packages\cefpython3" --lang=en-US /prefetch:2

[0820/191635.696:VERBOSE1:pref_proxy_config_tracker_impl.cc(155)] 000001EC88644570: set chrome proxy config service to 000001EC88711970
[0820/191635.707:VERBOSE1:multi_log_ct_verifier.cc(75)] Adding CT log: Google 'Argon2018' log
[0820/191635.707:VERBOSE1:multi_log_ct_verifier.cc(75)] Adding CT log: Google 'Argon2019' log
[0820/191635.707:VERBOSE1:multi_log_ct_verifier.cc(75)] Adding CT log: Google 'Argon2020' log
[0820/191635.707:VERBOSE1:multi_log_ct_verifier.cc(75)] Adding CT log: Google 'Argon2021' log
[0820/191635.707:VERBOSE1:multi_log_ct_verifier.cc(75)] Adding CT log: Google 'Aviator' log
[0820/191635.707:VERBOSE1:multi_log_ct_verifier.cc(75)] Adding CT log: Google 'Icarus' log
[0820/191635.707:VERBOSE1:multi_log_ct_verifier.cc(75)] Adding CT log: Google 'Pilot' log
[0820/191635.707:VERBOSE1:multi_log_ct_verifier.cc(75)] Adding CT log: Google 'Rocketeer' log
[0820/191635.707:VERBOSE1:multi_log_ct_verifier.cc(75)] Adding CT log: Google 'Skydiver' log
[0820/191635.708:VERBOSE1:multi_log_ct_verifier.cc(75)] Adding CT log: Cloudflare 'Nimbus2018' Log
[0820/191635.708:VERBOSE1:multi_log_ct_verifier.cc(75)] Adding CT log: Cloudflare 'Nimbus2019' Log
[0820/191635.708:VERBOSE1:multi_log_ct_verifier.cc(75)] Adding CT log: Cloudflare 'Nimbus2020' Log
[0820/191635.708:VERBOSE1:multi_log_ct_verifier.cc(75)] Adding CT log: Cloudflare 'Nimbus2021' Log
[0820/191635.708:VERBOSE1:multi_log_ct_verifier.cc(75)] Adding CT log: DigiCert Log Server
[0820/191635.708:VERBOSE1:multi_log_ct_verifier.cc(75)] Adding CT log: DigiCert Log Server 2
[0820/191635.708:VERBOSE1:multi_log_ct_verifier.cc(75)] Adding CT log: Symantec log
[0820/191635.708:VERBOSE1:multi_log_ct_verifier.cc(75)] Adding CT log: Symantec 'Vega' log
[0820/191635.708:VERBOSE1:multi_log_ct_verifier.cc(75)] Adding CT log: Symantec 'Sirius' log
[0820/191635.708:VERBOSE1:multi_log_ct_verifier.cc(75)] Adding CT log: Venafi Gen2 CT log
[0820/191635.708:VERBOSE1:multi_log_ct_verifier.cc(75)] Adding CT log: CNNIC CT log
[0820/191635.708:VERBOSE1:multi_log_ct_verifier.cc(75)] Adding CT log: Comodo 'Sabre' CT log
[0820/191635.708:VERBOSE1:multi_log_ct_verifier.cc(75)] Adding CT log: Comodo 'Mammoth' CT log
[0820/191635.709:VERBOSE1:multi_log_ct_verifier.cc(75)] Adding CT log: StartCom log
[0820/191635.709:VERBOSE1:multi_log_ct_verifier.cc(75)] Adding CT log: WoSign log
[0820/191635.709:VERBOSE1:multi_log_ct_verifier.cc(75)] Adding CT log: Izenpe log
[0820/191635.709:VERBOSE1:multi_log_ct_verifier.cc(75)] Adding CT log: Venafi log
[0820/191635.709:VERBOSE1:multi_log_ct_verifier.cc(75)] Adding CT log: Certly.IO log

DevTools listening on ws://127.0.0.1:55509/devtools/browser/6a9f9033-ca72-45d7-a4d6-1e9e0dfad185
[0820/191635.714:INFO:cef_log.cpp(8)] [Browser process] Shutdown()

Initialize complete.

Process finished with exit code -2147483645

Now I'm truly stumped. What are your thoughts?

cztomczak commented 4 years ago

Shutdown seems to be called too early. Your logs are again out of order.

MikeChurvis commented 4 years ago

@cztomczak I added a 10 second sleep between Initialize and Shutdown. This fixed the order of the log, but the same error occurs:

. . .
[0820/234839.898:VERBOSE1:multi_log_ct_verifier.cc(75)] Adding CT log: StartCom log
[0820/234839.898:VERBOSE1:multi_log_ct_verifier.cc(75)] Adding CT log: WoSign log
[0820/234839.898:VERBOSE1:multi_log_ct_verifier.cc(75)] Adding CT log: Izenpe log
[0820/234839.898:VERBOSE1:multi_log_ct_verifier.cc(75)] Adding CT log: Venafi log
[0820/234839.898:VERBOSE1:multi_log_ct_verifier.cc(75)] Adding CT log: Certly.IO log
Initialize complete.
Sleeping 10 seconds...
[0820/234849.890:INFO:cef_log.cpp(8)] [Browser process] Shutdown()

Process finished with exit code -2147483645
cztomczak commented 4 years ago

Looks like a breakpoint. See https://stackoverflow.com/questions/11583957/program-has-exited-with-code-2147483645

You would need to debug using Visual Studio. You can download CEF debug symbols from Spotify automated builds site. Looks like a breakpoint in Chromium/CEF code.

cztomczak commented 4 years ago

The script runs fine for me without any errors. Are you using a custom built Python or cefpython?

My logs:

Microsoft Windows [Version 10.0.18363.1016]

C:\Users\Czarek\Downloads>python breakpoint.py
[0821/104605.421:INFO:cefpython_app.cpp(199)] [Browser process] OnBeforeChildProcessLaunch() command line: "C:\Users\Czarek\AppData\Local\Programs\Python\Python36-32\lib\site-packages\cefpython3\subprocess" --type=gpu-process --enable-logging --no-sandbox --v=1 --locales-dir-path="C:\Users\Czarek\AppData\Local\Programs\Python\Python36-32\lib\site-packages\cefpython3\locales" --log-file="C:\Users\Czarek\AppData\Local\Programs\Python\Python36-32\debug.log" --log-severity=error --resources-dir-path="C:\Users\Czarek\AppData\Local\Programs\Python\Python36-32\lib\site-packages\cefpython3" --lang=en-US --disable-gpu-shader-disk-cache /prefetch:2

[0821/104605.421:INFO:cefpython_app.cpp(199)] [Browser process] OnBeforeChildProcessLaunch() command line: "C:\Users\Czarek\AppData\Local\Programs\Python\Python36-32\lib\site-packages\cefpython3\subprocess" --type=gpu-process --enable-logging --no-sandbox --v=1 --locales-dir-path="C:\Users\Czarek\AppData\Local\Programs\Python\Python36-32\lib\site-packages\cefpython3\locales" --log-file="C:\Users\Czarek\AppData\Local\Programs\Python\Python36-32\debug.log" --log-severity=error --resources-dir-path="C:\Users\Czarek\AppData\Local\Programs\Python\Python36-32\lib\site-packages\cefpython3" --lang=en-US --disable-gpu-shader-disk-cache --gpu-preferences=KAAAAAAAAACAA4CAAQAAAAAAAAAAAGAAEAAAAAAAAAAAAAAAAAAAACgAAAAEAAAAIAAAAAAAAAAoAAAAAAAAADAAAAAAAAAAOAAAAAAAAAAQAAAAAAAAAAAAAAAKAAAAEAAAAAAAAAAAAAAACwAAABAAAAAAAAAAAQAAAAoAAAAQAAAAAAAAAAEAAAALAAAA --locales-dir-path="C:\Users\Czarek\AppData\Local\Programs\Python\Python36-32\lib\site-packages\cefpython3\locales" --log-file="C:\Users\Czarek\AppData\Local\Programs\Python\Python36-32\debug.log" --log-severity=error --resources-dir-path="C:\Users\Czarek\AppData\Local\Programs\Python\Python36-32\lib\site-packages\cefpython3" --lang=en-US /prefetch:2

[0821/104605.436:VERBOSE1:webrtc_internals.cc(125)] Could not get the download directory.
[0821/104605.468:VERBOSE1:pref_proxy_config_tracker_impl.cc(155)] 08E42488: set chrome proxy config service to 03F1DC68
[0821/104605.468:VERBOSE1:multi_log_ct_verifier.cc(75)] Adding CT log: Google 'Argon2018' log
Initialize complete.
[0821/104605.468:INFO:cef_log.cpp(8)] [Browser process] Shutdown()

[0821/104605.468:VERBOSE1:multi_log_ct_verifier.cc(75)] Adding CT log: Google 'Argon2019' log
[0821/104605.468:VERBOSE1:multi_log_ct_verifier.cc(75)] Adding CT log: Google 'Argon2020' log

DevTools listening on ws://127.0.0.1:59870/devtools/browser/558af83d-d78f-4467-bd5d-210956fb544a
[0821/104605.468:VERBOSE1:multi_log_ct_verifier.cc(75)] Adding CT log: Google 'Argon2021' log
[0821/104605.468:VERBOSE1:multi_log_ct_verifier.cc(75)] Adding CT log: Google 'Aviator' log
[0821/104605.468:VERBOSE1:multi_log_ct_verifier.cc(75)] Adding CT log: Google 'Icarus' log
[0821/104605.468:VERBOSE1:multi_log_ct_verifier.cc(75)] Adding CT log: Google 'Pilot' log
[0821/104605.468:VERBOSE1:multi_log_ct_verifier.cc(75)] Adding CT log: Google 'Rocketeer' log
[0821/104605.468:VERBOSE1:multi_log_ct_verifier.cc(75)] Adding CT log: Google 'Skydiver' log
[0821/104605.468:VERBOSE1:multi_log_ct_verifier.cc(75)] Adding CT log: Cloudflare 'Nimbus2018' Log
[0821/104605.468:VERBOSE1:multi_log_ct_verifier.cc(75)] Adding CT log: Cloudflare 'Nimbus2019' Log
[0821/104605.468:VERBOSE1:multi_log_ct_verifier.cc(75)] Adding CT log: Cloudflare 'Nimbus2020' Log
[0821/104605.468:VERBOSE1:multi_log_ct_verifier.cc(75)] Adding CT log: Cloudflare 'Nimbus2021' Log
[0821/104605.468:VERBOSE1:multi_log_ct_verifier.cc(75)] Adding CT log: DigiCert Log Server
[0821/104605.483:VERBOSE1:multi_log_ct_verifier.cc(75)] Adding CT log: DigiCert Log Server 2
[0821/104605.483:VERBOSE1:multi_log_ct_verifier.cc(75)] Adding CT log: Symantec log
[0821/104605.483:VERBOSE1:multi_log_ct_verifier.cc(75)] Adding CT log: Symantec 'Vega' log
[0821/104605.483:VERBOSE1:multi_log_ct_verifier.cc(75)] Adding CT log: Symantec 'Sirius' log
[0821/104605.483:VERBOSE1:multi_log_ct_verifier.cc(75)] Adding CT log: Venafi Gen2 CT log
[0821/104605.483:VERBOSE1:multi_log_ct_verifier.cc(75)] Adding CT log: CNNIC CT log
[0821/104605.483:VERBOSE1:multi_log_ct_verifier.cc(75)] Adding CT log: Comodo 'Sabre' CT log
[0821/104605.483:VERBOSE1:multi_log_ct_verifier.cc(75)] Adding CT log: Comodo 'Mammoth' CT log
[0821/104605.483:VERBOSE1:multi_log_ct_verifier.cc(75)] Adding CT log: StartCom log
[0821/104605.483:VERBOSE1:multi_log_ct_verifier.cc(75)] Adding CT log: WoSign log
[0821/104605.483:VERBOSE1:multi_log_ct_verifier.cc(75)] Adding CT log: Izenpe log
[0821/104605.483:VERBOSE1:multi_log_ct_verifier.cc(75)] Adding CT log: Venafi log
[0821/104605.483:VERBOSE1:multi_log_ct_verifier.cc(75)] Adding CT log: Certly.IO log
[0821/104607.257:VERBOSE1:statistics_recorder.cc(410)] Collections of all histograms
Histogram: GPU.ANGLE.D3D11CreateDeviceMS recorded 1 samples, mean = 12.0 (flags = 0x1)
0   ...
12  ------------------------------------------------------------------------O (1 = 100.0%) {0.0%}
14  ...

Histogram: GPU.ANGLE.D3D11FeatureLevel recorded 1 samples, mean = 5.0 (flags = 0x1)
0  ...
5  ------------------------------------------------------------------------O (1 = 100.0%) {0.0%}
6  O                                                                         (0 = 0.0%) {100.0%}

Histogram: GPU.ANGLE.D3D11InitializeResult recorded 1 samples, mean = 0.0 (flags = 0x1)
0  ------------------------------------------------------------------------O (1 = 100.0%)
1  ...

Histogram: GPU.ANGLE.DisplayInitializeMS recorded 1 samples, mean = 16.0 (flags = 0x1)
0   ...
14  ------------------------------------------------------------------------O (1 = 100.0%) {0.0%}
17  ...

Histogram: GPU.ANGLE.Renderer11InitializeDLLsMS recorded 1 samples, mean = 0.0 (flags = 0x1)
0  ------------------------------------------------------------------------O (1 = 100.0%)
1  ...

Histogram: GPU.ANGLE.Renderer11InitializeDeviceMS recorded 1 samples, mean = 1.0 (flags = 0x1)
0  O                                                                         (0 = 0.0%)
1  ------------------------------------------------------------------------O (1 = 100.0%) {0.0%}
2  ...

Histogram: GPU.ANGLE.SupportsDXGI1_2 recorded 1 samples, mean = 1.0 (flags = 0x1)
0  O                                                                         (0 = 0.0%)
1  ------------------------------------------------------------------------O (1 = 100.0%) {0.0%}
2  O                                                                         (0 = 0.0%) {100.0%}

Histogram: GPU.CollectContextGraphicsInfo recorded 1 samples, mean = 1.0 (flags = 0x1)
0  O                                                                         (0 = 0.0%)
1  ------------------------------------------------------------------------O (1 = 100.0%) {0.0%}
2  ...

Histogram: GPU.D3DShaderModel recorded 1 samples, mean = 5.0 (flags = 0x1)
0  ...
5  ------------------------------------------------------------------------O (1 = 100.0%) {0.0%}
6  O                                                                         (0 = 0.0%) {100.0%}

Histogram: GPU.DirectComposition.OverlaysSupported recorded 1 samples, mean = 0.0 (flags = 0x1)
0  ------------------------------------------------------------------------O (1 = 100.0%)
1  ...

Histogram: GPU.EGLDisplayType recorded 1 samples, mean = 4.0 (flags = 0x1)
0  ...
4  ------------------------------------------------------------------------O (1 = 100.0%) {0.0%}
5  ...

Histogram: GPU.InitializeOneOffMediumTime recorded 1 samples, mean = 23.0 (flags = 0x1)
0   ...
22  ------------------------------------------------------------------------O (1 = 100.0%) {0.0%}
27  ...

Histogram: GPU.MaxMSAASampleCount recorded 1 samples (flags = 0x1)
8  ------------------------------------------------------------------------O (1 = 100.0%)

Histogram: GPU.Sandbox.InitializedSuccessfully recorded 1 samples, mean = 0.0 (flags = 0x1)
0  ------------------------------------------------------------------------O (1 = 100.0%)
1  ...

Histogram: LibraryLoader.LoadNativeLibraryWindows recorded 3 samples, mean = 0.3 (flags = 0x1)
0  ------------------------------------------------------------------------O (2 = 66.7%)
1  ------------------------------------O                                     (1 = 33.3%) {66.7%}
2  ...

Histogram: TaskScheduler.DetachDuration.ContentChild.BackgroundBlockingPool recorded 0 samples (flags = 0x1)
0 ...

Histogram: TaskScheduler.DetachDuration.ContentChild.BackgroundPool recorded 0 samples (flags = 0x1)
0 ...

Histogram: TaskScheduler.DetachDuration.ContentChild.ForegroundBlockingPool recorded 0 samples (flags = 0x1)
0 ...

Histogram: TaskScheduler.DetachDuration.ContentChild.ForegroundPool recorded 0 samples (flags = 0x1)
0 ...

Histogram: TaskScheduler.NumTasksBeforeDetach.ContentChild.BackgroundBlockingPool recorded 0 samples (flags = 0x1)
0 ...

Histogram: TaskScheduler.NumTasksBeforeDetach.ContentChild.BackgroundPool recorded 0 samples (flags = 0x1)
0 ...

Histogram: TaskScheduler.NumTasksBeforeDetach.ContentChild.ForegroundBlockingPool recorded 0 samples (flags = 0x1)
0 ...

Histogram: TaskScheduler.NumTasksBeforeDetach.ContentChild.ForegroundPool recorded 0 samples (flags = 0x1)
0 ...

Histogram: TaskScheduler.NumTasksBetweenWaits.ContentChild.BackgroundBlockingPool recorded 0 samples (flags = 0x1)
0 ...

Histogram: TaskScheduler.NumTasksBetweenWaits.ContentChild.BackgroundPool recorded 0 samples (flags = 0x1)
0 ...

Histogram: TaskScheduler.NumTasksBetweenWaits.ContentChild.ForegroundBlockingPool recorded 0 samples (flags = 0x1)
0 ...

Histogram: TaskScheduler.NumTasksBetweenWaits.ContentChild.ForegroundPool recorded 0 samples (flags = 0x1)
0 ...

Histogram: TaskScheduler.TaskLatencyMicroseconds.ContentChild.BackgroundTaskPriority recorded 0 samples (flags = 0x1)
0 ...

Histogram: TaskScheduler.TaskLatencyMicroseconds.ContentChild.BackgroundTaskPriority_MayBlock recorded 0 samples (flags = 0x1)
0 ...

Histogram: TaskScheduler.TaskLatencyMicroseconds.ContentChild.UserBlockingTaskPriority recorded 0 samples (flags = 0x1)
0 ...

Histogram: TaskScheduler.TaskLatencyMicroseconds.ContentChild.UserBlockingTaskPriority_MayBlock recorded 0 samples (flags = 0x1)
0 ...

Histogram: TaskScheduler.TaskLatencyMicroseconds.ContentChild.UserVisibleTaskPriority recorded 0 samples (flags = 0x1)
0 ...

Histogram: TaskScheduler.TaskLatencyMicroseconds.ContentChild.UserVisibleTaskPriority_MayBlock recorded 0 samples (flags = 0x1)
0 ...

Histogram: Windows.CreateThreadTime recorded 7 samples, mean = 0.0 (flags = 0x1)
0  ------------------------------------------------------------------------O (7 = 100.0%)
1  ...
cztomczak commented 4 years ago

Tested with Python 3.6.8.

MikeChurvis commented 4 years ago

Are you using a custom built Python or cefpython?

No. I'm using Anaconda's Python 3.7.4 interpreter, and for cefpython, it was just pip install cefpython3==66.0 as per the Readme.

I will try the example with a fresh venv & clean Python 3.6.8 install.

MikeChurvis commented 4 years ago

@cztomczak No luck.

Fresh Python 3.6.8 install, new pipenv. Same exact error & log as before.

I'm running low on time for this deliverable, so I'm gonna have to bite the bullet & restructure the app to be able to use cef.MessageLoop() on the main thread. This wasn't possible with pystray, so I'll have to find an alternative.

That said, if I have some time afterwards, I'd love to learn how to debug these kinds of deep errors! You mentioned using VS and Spotify's debug symbols; is there a good resource for learning how to setup something like that?

cztomczak commented 4 years ago

What if you call os._exit(0) after cef.Shutdown? Look how we've fixed some other exit code issue on Mac: https://github.com/cztomczak/cefpython/blob/5c15c72db9dc2199df54bea04f121ba16afadd88/examples/wxpython.py#L219

MikeChurvis commented 4 years ago

call os._exit(0) after cef.Shutdown

No statement after cef.Shutdown will execute under any circumstances, it seems. Also, my application needs to release an inter-process lock before any final exit is invoked.

cztomczak commented 4 years ago

You should be able to debug with any Visual Studio. Last time I've debuged cefpython with VS2017. First download libcef.dll.pdb with release symbols (win, 64bit):

http://opensource.spotify.com/cefbuilds/cef_binary_3.3359.1774.gd49d25f_windows64_release_symbols.tar.bz2

Place it next to libcef.dll in the cefpython3 package directory.

Launch python script, then click the Attach to process button in top bar and select options as seen on the screenshot (Native code, Python code).

image

To debug cefpython code you would need to modify cefpython build scripts to add debug flags so that debug symbols are included and then build it from sources.

cztomczak commented 4 years ago

In the attach to process window select python.exe process and also subprocess.exe - there are multiple of them, these are Chromium subprocesses.

MikeChurvis commented 4 years ago

@cztomczak Wonderful! Thank you so much for your help and guidance on this. I'll let you know what I find!