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.

Sign up for GitHub

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

Jump to bottom

Crash during DB download on MacOS #448

Closed
velolala opened this issue Apr 23, 2024 · 17 comments
Closed

Crash during DB download on MacOS #448

velolala opened this issue Apr 23, 2024 · 17 comments
Assignees
@Bouni
Labels
bug Something isn't working MacOS MacOS issue

Comments

@velolala
Copy link

Hi there, this plugin looks awesome, unfortunately I could not try it out yet, because of the following issue:

Bug/Reproduction
Every single time I open the plugin, it starts to download the zip parts of the parts DB, but then KiCAD crashes before completion. I monitored the $plugin/jlcpcb folder, and the furthest the download ever got was parts 001-007 complete (80000000 bytes), but part 008 still at 0 bytes. Unfortunately I could not get a readable exception, but if you can help me to run the download step manually, I'm happy to debug further!

Version information

OS: MacOS 13.6.6 (22G630)

Plugin: 2024.04.03

Application: KiCad arm64 on arm64
Version: 8.0.1, release build
Libraries:
    wxWidgets 3.2.4
    FreeType 2.13.2
    HarfBuzz 8.3.0
    FontConfig 2.15.0
    libcurl/8.4.0 (SecureTransport) LibreSSL/3.3.6 zlib/1.2.11 nghttp2/1.51.0
Platform: macOS Ventura Version 13.6.6 (Build 22G630), 64 bit, Little endian, wxMac
Build Info:
    Date: Mar 14 2024 13:30:33
    wxWidgets: 3.2.4 (wchar_t,wx containers)
    Boost: 1.84.0
    OCC: 7.7.2
    Curl: 7.87.0
    ngspice: 42
    Compiler: Clang 14.0.3 with C++ ABI 1002
Build settings:
@ahalekelly
Copy link

ahalekelly commented Apr 24, 2024 •
edited

I updated to the latest version using the KiCAD plugin manager and I also started having this issue. Downgrading from 2024.04.03 to 2024.04.01 seems to have fixed it.

@velolala
Copy link
Author

Great to hear from you! I actually found some more info: it seems there is some (b)locking issue, that triggers an OS watchdog. I started kicad from commandline and got this:

% /Applications/KiCad/KiCad.app/Contents/MacOS/kicad
Fontconfig error: Cannot load default config file: No such file: (null)
2024.04.24 10:05:20 - DEBUG - download -  Parts db is split into 8 parts. Proceeding to download...
2024.04.24 10:05:20 - DEBUG - download -  Removing any spurios old zip part files...
2024.04.24 10:05:20 - DEBUG - download -  Removing /Users/myuser/Documents/KiCad/8.0/3rdparty/plugins/com_github_bouni_kicad-jlcpcb-tools/jlcpcb/parts-fts5.db.zip.001.
2024.04.24 10:05:20 - DEBUG - download -  Removing /Users/myuser/Documents/KiCad/8.0/3rdparty/plugins/com_github_bouni_kicad-jlcpcb-tools/jlcpcb/parts-fts5.db.zip.002.
2024.04.24 10:05:20 - DEBUG - download -  Removing /Users/myuser/Documents/KiCad/8.0/3rdparty/plugins/com_github_bouni_kicad-jlcpcb-tools/jlcpcb/parts-fts5.db.zip.003.
2024.04.24 10:05:20 - DEBUG - download -  Download parts db chunk 1 with a size of 76.29MB
2024.04.24 10:06:09 - DEBUG - download -  Download parts db chunk 2 with a size of 76.29MB
2024.04.24 10:06:46 - DEBUG - download -  Download parts db chunk 3 with a size of 76.29MB
2024.04.24 10:07:22 - DEBUG - download -  Download parts db chunk 4 with a size of 76.29MB
2024-04-24 10:07:27.845 kicad[81575:1652519] IMKClient Stall detected, *please Report* your user scenario attaching a spindump (or sysdiagnose) that captures the problem - (invocationInterruptXPCReply) block performed very slowly (5.00 secs).
zsh: trace trap  /Applications/KiCad/KiCad.app/Contents/MacOS/kicad

@velolala
Copy link
Author

And the same Stall exception can be triggered when running the plugin in Standalone Mode:

2024.04.24 11:05:58 - DEBUG - download -  Download parts db chunk 2 with a size of 76.29MB
2024-04-24 11:06:03.641 Python[82574:1673876] IMKClient Stall detected, *please Report* your user scenario attaching a spindump (or sysdiagnose) that captures the problem - (invocationInterruptXPCReply) block performed very slowly (5.00 secs).
zsh: trace trap   -m com_github_bouni_kicad-jlcpcb-tools

@Bouni
Copy link
Owner

Bouni commented Apr 24, 2024

I guess this is a MacOs only issue. Does not happen on Windows ...

@chmorgan I think you're on MacOS, right? Do you see this kind off issues?

@Bouni Bouni added bug Something isn't working MacOS MacOS issue labels Apr 24, 2024
@whmountains
Copy link
Collaborator

This just happened to me while trying to check out the latest commits. (I'm on MacOS as well.) I tried to do a git bisect, but unfortunately I can no longer reproduce the issue. I even tried deleting the entire contents of the jlcpcb folder and re-opening the plugin, but still no crash.

I suspect this issue is a timeout which only happens on slower systems or networks. My system is generally fast enough, but if I have enough background tasks it pushes it over the edge.

I thought it might be blocking tasks on the main thread, but I double checked and the download task already happens on a worker thread.

Not sure what to say.

@chmorgan
Copy link
Collaborator

@Bouni and others, I can try to reproduce it here. I've seen it happen prior to the fts5 changes but it's sporadic. Crash, then restart and download finishes. If I can catch it on the debugger that should help, and I'll look at the issue text above.

@whmountains
Copy link
Collaborator

Happened to me again today. I'd say I get the error in about 5% of db download attempts.

@whmountains whmountains mentioned this issue Apr 25, 2024
Closed
@chmorgan
Copy link
Collaborator

Proposed fix in #455 but could use more testing to confirm it resolves the issue.

@velolala
Copy link
Author

Hey @chmorgan (and everyone else helping out with this),
I ran the standalone from your PR and it did crash on me on the first download attempt:

2024.04.27 20:51:16 - DEBUG - download -  Download parts db chunk 1 with a size of 76.29MB
2024.04.27 20:51:19 - DEBUG - download -  Download parts db chunk 2 with a size of 76.29MB
2024.04.27 20:51:25 - DEBUG - download -  Download parts db chunk 3 with a size of 76.29MB
zsh: trace trap   -m kicad-jlcpcb-tools

This is however without the IMKClient Stall message.

On consecutive attempts it worked though – much more reliable than what I saw before. I will shake it some more though, to see if it will eventually spit out the old issue still. I'll let you know what I find.

@velolala
Copy link
Author

velolala commented Apr 27, 2024 •
edited

Well, that was quick (or I was too quick to send the previous):
I found a way to pretty reliably cause the crash (on #455 and 2024.04.03):

  1. run the standalone /Applications/KiCad/KiCad.app/Contents/Frameworks/Python.framework/Versions/3.9/bin/python3 -m kicad-jlcpcb-tools
  2. click on Download
  3. during the download, click and mark in the log message area.

Regarding 3) some explanation: the log messages sometimes seem to appear late or hidden(?). "Spam clicking"/marking & scrolling inside the log message area, is what I intuitively did, to make them visible. I believe it did also crash without this. However, with 3) I can force the crash pretty quickly.

Edit:
This is always with IMKClient Stall

@velolala
Copy link
Author

It seems to be enough, to mark any text inside the log area.

See e.g. this terminal log, where I had two successful downloads, then before the third attempt, I had marked a few characters on the last log message (in the UI): 
/Applications/KiCad/KiCad.app/Contents/Frameworks/Python.framework/Versions/3.9/bin/python3 -m kicad-jlcpcb-tools
/Users/kicad/remoteroot/workspace/build-macos-kicad-release/kicad-mac-builder/build/kicad/src/kicad/pcbnew/action_plugin.cpp(163): assert "PgmOrNull()" failed in register_action().
starting jlcpcbtools standalone mode...
2024.04.27 21:16:03 - DEBUG - download -  Parts db is split into 8 parts. Proceeding to download...
2024.04.27 21:16:03 - DEBUG - download -  Removing any spurios old zip part files...
2024.04.27 21:16:03 - DEBUG - download -  Removing /Users/myuser/Projects/kicad-jlcpcb-tools/jlcpcb/parts-fts5.db.zip.001.
2024.04.27 21:16:03 - DEBUG - download -  Removing /Users/myuser/Projects/kicad-jlcpcb-tools/jlcpcb/parts-fts5.db.zip.006.
2024.04.27 21:16:03 - DEBUG - download -  Removing /Users/myuser/Projects/kicad-jlcpcb-tools/jlcpcb/parts-fts5.db.zip.008.
2024.04.27 21:16:03 - DEBUG - download -  Removing /Users/myuser/Projects/kicad-jlcpcb-tools/jlcpcb/parts-fts5.db.zip.007.
2024.04.27 21:16:03 - DEBUG - download -  Removing /Users/myuser/Projects/kicad-jlcpcb-tools/jlcpcb/parts-fts5.db.zip.005.
2024.04.27 21:16:03 - DEBUG - download -  Removing /Users/myuser/Projects/kicad-jlcpcb-tools/jlcpcb/parts-fts5.db.zip.002.
2024.04.27 21:16:03 - DEBUG - download -  Removing /Users/myuser/Projects/kicad-jlcpcb-tools/jlcpcb/parts-fts5.db.zip.003.
2024.04.27 21:16:03 - DEBUG - download -  Removing /Users/myuser/Projects/kicad-jlcpcb-tools/jlcpcb/parts-fts5.db.zip.004.
2024.04.27 21:16:06 - DEBUG - download -  Download parts db chunk 1 with a size of 76.29MB
2024.04.27 21:16:12 - DEBUG - download -  Download parts db chunk 2 with a size of 76.29MB
2024.04.27 21:16:16 - DEBUG - download -  Download parts db chunk 3 with a size of 76.29MB
2024.04.27 21:16:19 - DEBUG - download -  Download parts db chunk 4 with a size of 76.29MB
2024.04.27 21:16:21 - DEBUG - download -  Download parts db chunk 5 with a size of 76.29MB
2024.04.27 21:16:24 - DEBUG - download -  Download parts db chunk 6 with a size of 76.29MB
2024.04.27 21:16:27 - DEBUG - download -  Download parts db chunk 7 with a size of 76.29MB
2024.04.27 21:16:29 - DEBUG - download -  Download parts db chunk 8 with a size of 18.00MB
2024.04.27 21:16:30 - DEBUG - download -  Combining and extracting zip part files...
2024.04.27 21:16:43 - DEBUG - download -  Parts db is split into 8 parts. Proceeding to download...
2024.04.27 21:16:43 - DEBUG - download -  Removing any spurios old zip part files...
2024.04.27 21:16:49 - DEBUG - download -  Download parts db chunk 1 with a size of 76.29MB
2024.04.27 21:16:53 - DEBUG - download -  Download parts db chunk 2 with a size of 76.29MB
2024.04.27 21:16:56 - DEBUG - download -  Download parts db chunk 3 with a size of 76.29MB
2024.04.27 21:17:00 - DEBUG - download -  Download parts db chunk 4 with a size of 76.29MB
2024.04.27 21:17:04 - DEBUG - download -  Download parts db chunk 5 with a size of 76.29MB
2024.04.27 21:17:07 - DEBUG - download -  Download parts db chunk 6 with a size of 76.29MB
2024.04.27 21:17:09 - DEBUG - download -  Download parts db chunk 7 with a size of 76.29MB
2024.04.27 21:17:13 - DEBUG - download -  Download parts db chunk 8 with a size of 18.00MB
2024.04.27 21:17:14 - DEBUG - download -  Combining and extracting zip part files...
2024.04.27 21:17:42 - DEBUG - download -  Parts db is split into 8 parts. Proceeding to download...
2024-04-27 21:17:47.676 Python[789:2092234] IMKClient Stall detected, *please Report* your user scenario attaching a spindump (or sysdiagnose) that captures the problem - (invocationInterruptXPCReply) block performed very slowly (5.00 secs).
zsh: trace trap   -m kicad-jlcpcb-tools

@chmorgan
Copy link
Collaborator

chmorgan commented Apr 27, 2024 via email

@chmorgan
Copy link
Collaborator

chmorgan commented Apr 27, 2024 •
edited

@Bouni @velolala, again this is a bit of a shot in the dark. The download happens in a background thread (good), but logging appears to modify the widgets directly. Looking at the other issue with the trace, the ns index exception one, it appears there was some textctrl related function in the crash log.

Latest change on #455 takes the logging events and marshals them over to the main thread. I'm assuming, although I can't find it anywhere, that it isn't safe or valid to interact with widgets from threads other than the UI thread. If downloading is using logging (and it is), and its the only case of a background thread in typical use, then perhaps this background use of logging is resulting in a crash due to widget interactions from a non-UI thread.

Thoughts? @velolala can you give the latest change a try to see if it resolves the issue?

@velolala
Copy link
Author

@chmorgan This definitely spoiled the fun of crashing it for me (read: download works without crashes).

Only thing is cosmetics: the log area does not show the complete log anymore, but only a few lines (if I mark and scroll).

Great, thank you!!!

@chmorgan
Copy link
Collaborator

@whmountains can you give this one a spin too?

@Bouni does my logic make sense for the fix here? I can drop the read change although it should be pretty similar in terms of performance and have much less peak memory usage which is likely a good thing.

@whmountains
Copy link
Collaborator

Well that was fast! Here I was thinking this bug would take an eternity to track down and it's already patched. Incredible work @chmorgan and excellent repro case @velolala.

I tested on the cmm_fts5_like branch and could reliably cause a crash using the method from @velolala. I tested on the cmm_download download branch and it's solid as a rock. I think we can consider this a fix. 🎉

@whmountains whmountains mentioned this issue Apr 30, 2024
Merged
@chmorgan
Copy link
Collaborator

Closing as issue appears resolved.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@Bouni Bouni

Labels
bug Something isn't working MacOS MacOS issue
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
5 participants
@Bouni @velolala @chmorgan @ahalekelly @whmountains