pcbnew segfaults on footprint search

[evils]

when searching for a footprint in pcbnew's "add footprint", it segfaults

i encountered this issue on NixOS on kicad 5.1.4, i've since built kicad from git revision 3be1862

triggering the crash via valgrind is somewhat tricky, most of the time the search lists results but the footprint preview says "footprint not found" in which case this it does not segfault.
i've succeeded at this several times and i am under the impression the address accessed is not always 0x0
here are a few more segfaults caught via just gdb
https://paste.ee/p/tVFgB

included as comments are the gdb bt full and valgrind output for pcbnew from 3be1862 with the most recent footprints etc for that commit
the .pcbnew-wrapped and all the /nix/store/[hash] stuff is due to this running on NixOS
i'm fairly sure this issue isn't due to NixOS, due to an anecdotal report on the freenode #kicad IRC channel of someone experiencing this issue on debian10 when using xfwm (i'm using i3wm)
further information is available here, https://github.com/NixOS/nixpkgs/issues/72248
most relevant to my build setup may be this, https://github.com/Evils-Devils/nixpkgs/tree/kicad-unstable

Application: KiCad
Version: 5.99.0-2019-11-20, debug build
Libraries:
    wxWidgets 3.1.2
    libcurl/7.66.0 OpenSSL/1.1.1d zlib/1.2.11 libssh2/1.9.0 nghttp2/1.39.2
Platform: Linux 4.19.80 x86_64, 64 bit, Little endian, wxGTK
Build Info:
    Build date: Jan 1 1970 00:00:01
    wxWidgets: 3.1.2 (wchar_t,wx containers) GTK+ 3.24
    Boost: 1.67.0
    OpenCASCADE Community Edition: 6.9.1
    Curl: 7.66.0
    Compiler: GCC 8.3.0 with C++ ABI 1013

Build settings:
    KICAD_SCRIPTING=ON
    KICAD_SCRIPTING_MODULES=ON
    KICAD_SCRIPTING_PYTHON3=ON
    KICAD_SCRIPTING_WXPYTHON=ON
    KICAD_SCRIPTING_WXPYTHON_PHOENIX=ON
    KICAD_SCRIPTING_ACTION_MENU=ON
    BUILD_GITHUB_PLUGIN=ON
    KICAD_USE_OCE=ON
    KICAD_USE_OCC=OFF
    KICAD_SPICE=ON
    KICAD_STDLIB_DEBUG=ON
    KICAD_SANITIZE=OFF

[Seth Hillbrand (sethh)]

Please add your full version information from Help->About KiCad->Copy Version Information.

Also add all data relevant to the bug report as attachments or text in this report. Please do not link to external sites.

[evils (evils)]

output of valgrind

==2880== Memcheck, a memory error detector
==2880== Copyright (C) 2002-2017, and GNU GPL'd, by Julian Seward et al.
==2880== Using Valgrind-3.15.0 and LibVEX; rerun with -h for copyright info
==2880== Command: /nix/store/mw4xn7dachzm859gch2wkbl1ikq05grn-kicad-unstable-2019-11-20/bin/.pcbnew-wrapped
==2880==
==2880== Invalid read of size 4
==2880== at 0x12495F2C: pymalloc_free.isra.0 (in /nix/store/gpnm7i19lpj8p43mjrdw03d0hjalmskl-python3-3.7.5/lib/libpython3.7m.so.1.0)
==2880== by 0x124987F8: _PyObject_Free (in /nix/store/gpnm7i19lpj8p43mjrdw03d0hjalmskl-python3-3.7.5/lib/libpython3.7m.so.1.0)
==2880== by 0x124818A7: dictresize (in /nix/store/gpnm7i19lpj8p43mjrdw03d0hjalmskl-python3-3.7.5/lib/libpython3.7m.so.1.0)
==2880== by 0x1248696F: PyDict_SetDefault (in /nix/store/gpnm7i19lpj8p43mjrdw03d0hjalmskl-python3-3.7.5/lib/libpython3.7m.so.1.0)
==2880== by 0x124EBBD0: PyUnicode_InternInPlace (in /nix/store/gpnm7i19lpj8p43mjrdw03d0hjalmskl-python3-3.7.5/lib/libpython3.7m.so.1.0)
==2880== by 0x124EBED9: PyUnicode_InternFromString (in /nix/store/gpnm7i19lpj8p43mjrdw03d0hjalmskl-python3-3.7.5/lib/libpython3.7m.so.1.0)
==2880== by 0x124A8794: PyType_Ready (in /nix/store/gpnm7i19lpj8p43mjrdw03d0hjalmskl-python3-3.7.5/lib/libpython3.7m.so.1.0)
==2880== by 0x12494B8F: _Py_ReadyTypes (in /nix/store/gpnm7i19lpj8p43mjrdw03d0hjalmskl-python3-3.7.5/lib/libpython3.7m.so.1.0)
==2880== by 0x1254FB94: _Py_InitializeCore_impl (in /nix/store/gpnm7i19lpj8p43mjrdw03d0hjalmskl-python3-3.7.5/lib/libpython3.7m.so.1.0)
==2880== by 0x125500AD: _Py_InitializeCore (in /nix/store/gpnm7i19lpj8p43mjrdw03d0hjalmskl-python3-3.7.5/lib/libpython3.7m.so.1.0)
==2880== by 0x12550E1F: _Py_InitializeFromConfig (in /nix/store/gpnm7i19lpj8p43mjrdw03d0hjalmskl-python3-3.7.5/lib/libpython3.7m.so.1.0)
==2880== by 0x12550FED: Py_InitializeEx (in /nix/store/gpnm7i19lpj8p43mjrdw03d0hjalmskl-python3-3.7.5/lib/libpython3.7m.so.1.0)
==2880== Address 0x18476020 is 80 bytes inside a block of size 576 free'd
==2880== at 0x4835900: free (in /nix/store/pgbq8wyhlhjawqcmh2cg7di8fjsf0l8f-valgrind-3.15.0/lib/valgrind/vgpreload_memcheck-amd64-linux.so)
==2880== by 0x124818A7: dictresize (in /nix/store/gpnm7i19lpj8p43mjrdw03d0hjalmskl-python3-3.7.5/lib/libpython3.7m.so.1.0)
==2880== by 0x1248696F: PyDict_SetDefault (in /nix/store/gpnm7i19lpj8p43mjrdw03d0hjalmskl-python3-3.7.5/lib/libpython3.7m.so.1.0)
==2880== by 0x124EBBD0: PyUnicode_InternInPlace (in /nix/store/gpnm7i19lpj8p43mjrdw03d0hjalmskl-python3-3.7.5/lib/libpython3.7m.so.1.0)
==2880== by 0x124EBED9: PyUnicode_InternFromString (in /nix/store/gpnm7i19lpj8p43mjrdw03d0hjalmskl-python3-3.7.5/lib/libpython3.7m.so.1.0)
==2880== by 0x124A8794: PyType_Ready (in /nix/store/gpnm7i19lpj8p43mjrdw03d0hjalmskl-python3-3.7.5/lib/libpython3.7m.so.1.0)
==2880== by 0x12494B8F: _Py_ReadyTypes (in /nix/store/gpnm7i19lpj8p43mjrdw03d0hjalmskl-python3-3.7.5/lib/libpython3.7m.so.1.0)
==2880== by 0x1254FB94: _Py_InitializeCore_impl (in /nix/store/gpnm7i19lpj8p43mjrdw03d0hjalmskl-python3-3.7.5/lib/libpython3.7m.so.1.0)
==2880== by 0x125500AD: _Py_InitializeCore (in /nix/store/gpnm7i19lpj8p4...

[evils (evils)]

output of gdb bt full for the same execution's coredump

(gdb) bt full
#0 0x0000000006584ffd in __GI__IO_file_underflow () from /nix/store/qb6k4hp7gk331x9fydw0w7qj4dv09bwz-glibc-2.27/lib/libc.so.6
No symbol table info available.
#1 0x00000000065860f2 in _IO_default_uflow () from /nix/store/qb6k4hp7gk331x9fydw0w7qj4dv09bwz-glibc-2.27/lib/libc.so.6
No symbol table info available.
#2 0x00000000116b1aea in getc_unlocked (__fp=<optimized out>)
    at /nix/store/4a8wp97g0ddhjwx573k30x4fqzvkfn67-glibc-2.27-dev/include/bits/stdio.h:65
No locals.
#3 FILE_LINE_READER::ReadLine (this=0x3a5390a0) at /build/source/common/richio.cpp:207
        cc = <optimized out>
        __FUNCTION__ = "ReadLine"
#4 0x0000000011624d26 in DSNLEXER::readLine (this=0x1c6098c0) at /build/source/include/dsnlexer.h:121
        len = <optimized out>
#5 DSNLEXER::NextTok (this=this@entry=0x1c6098c0) at /build/source/common/dsnlexer.cpp:555
        len = <optimized out>
        cur = <optimized out>
        head = 0x4494d050 "(drill 1) (layers *.Cu *.Mask))\n"
        __FUNCTION__ = "NextTok"
#6 0x0000000011429c56 in PCB_LEXER::NextTok (this=0x1c6098c0) at /build/source/build/common/pcb_lexer.h:348
No locals.
#7 PCB_PARSER::parseBoardItemLayersAsMask (this=0x1c6098c0) at /build/source/pcbnew/pcb_parser.cpp:1398
        token = <optimized out>
        __FUNCTION__ = "parseBoardItemLayersAsMask"
        layerMask = {<std::__debug::bitset<51>> = {<std::__cxx1998::bitset<51>> = {<std::__cxx1998::_Base_bitset<1>> = {
                _M_w = 4294967295}, <No data fields>}, <No data fields>}, <No data fields>}
#8 0x000000001142b7b8 in PCB_PARSER::parseD_PAD (this=0x1c6098c0, aParent=<optimized out>) at /build/source/pcbnew/pcb_parser.cpp:3010
        layerMask = <optimized out>
        __FUNCTION__ = "parseD_PAD"
        sz = <optimized out>
        pt = <optimized out>
        pad = {_M_t = {
            _M_t = {<std::_Tuple_impl<0, D_PAD*, std::default_delete<D_PAD> >> = {<std::_Tuple_impl<1, std::default_delete<D_PAD> >> = {<std::_Head_base<1, std::default_delete<D_PAD>, true>> = {<std::default_delete<D_PAD>> = {<No data fields>}, <No data fields>}, <No data fields>}, <std::_Head_base<0, D_PAD*, false>> = {_M_head_impl = 0x3d1a0c60}, <No data fields>}, <No data fields>}}}
        token = <optimized out>
#9 0x000000001142ee93 in PCB_PARSER::parseMODULE_unchecked (this=0x1c6098c0, aInitialComments=<optimized out>)
    at /build/source/pcbnew/pcb_parser.cpp:2522
        pad = <optimized out>
        __FUNCTION__ = "parseMODULE_unchecked"
        name = {static npos = 18446744073709551615, m_impl = {static npos = 18446744073709551615,
            _M_dataplus = {<std::allocator<wchar_t>> = {<__gnu_cxx::new_allocator<wchar_t>> = {<No data fields>}, <No data fields>},
              _M_p = 0x170d7ff0 L"DIN41612_B2_2x8_Horizontal"}, _M_string_length = 26, {_M_local_buf = L"\032\000\x6073994",
              _M_allocated_capacity = 26}}, m_convertedToChar = {m_str = 0x26d48540 "DIN41612_B2_2x8_Horizontal", m_len = 26}}
        pt = {x = 7620000, y = 0}
        token = <optimized out>
        fpid = {nickname = {static npos = 18446744073709551615, m_s = {static npos = 184467440737095...

[John Beard (john-j-beard)]

I feel like this bit might be related:

==2880== Invalid read of size 8
==2880== at 0x113DE690: FP_CACHE::Load() (kicad_plugin.cpp:287)
==2880== by 0x113DF203: PCB_IO::validateCache(wxString const&, bool) (kicad_plugin.cpp:2046)
==2880== by 0x113DFD4F: PCB_IO::getFootprint(wxString const&, wxString const&, PROPERTIES const*, bool) (kicad_plugin.cpp:2091)
==2880== by 0x113E0030: PCB_IO::FootprintLoad(wxString const&, wxString const&, PROPERTIES const*) (kicad_plugin.cpp:2136)
==2880== by 0x11311786: FP_LIB_TABLE::FootprintLoad(wxString const&, wxString const&) (fp_lib_table.cpp:363)
==2880== by 0x10DE1472: FOOTPRINT_INFO_GENERATOR::GenerateHtml() (generate_footprint_info.cpp:74)
==2880== by 0x10DE1319: GenerateFootprintInfo(FP_LIB_TABLE*, LIB_ID const&) (generate_footprint_info.cpp:139)
==2880== by 0x10DDA783: FP_TREE_MODEL_ADAPTER::GenerateInfo(LIB_ID const&, int) (fp_tree_model_adapter.cpp:77)
==2880== by 0x115AFB28: LIB_TREE::onPreselect(wxCommandEvent&) (lib_tree.cpp:392)
==2880== by 0x549356D: wxEvtHandler::ProcessEventIfMatchesId(wxEventTableEntryBase const&, wxEvtHandler*, wxEvent&) (in /nix/store/kkckslvs98x8fjr61wzmjlvy246i137w-wxwidgets-3.1.2/lib/libwx_baseu-3.1.so.2.0.0)
==2880== by 0x54939A4: wxEvtHandler::SearchDynamicEventTable(wxEvent&) (in /nix/store/kkckslvs98x8fjr61wzmjlvy246i137w-wxwidgets-3.1.2/lib/libwx_baseu-3.1.so.2.0.0)
==2880== by 0x5493D5F: wxEvtHandler::TryHereOnly(wxEvent&) (in /nix/store/kkckslvs98x8fjr61wzmjlvy246i137w-wxwidgets-3.1.2/lib/libwx_baseu-3.1.so.2.0.0)
==2880== Address 0x3d1c4840 is 0 bytes inside a block of size 336 free'd
==2880== at 0x4835F9E: operator delete(void*, unsigned long) (in /nix/store/pgbq8wyhlhjawqcmh2cg7di8fjsf0l8f-valgrind-3.15.0/lib/valgrind/vgpreload_memcheck-amd64-linux.so)
==2880== by 0x113DF460: PCB_IO::validateCache(wxString const&, bool) (kicad_plugin.cpp:2044)
==2880== by 0x113DFD4F: PCB_IO::getFootprint(wxString const&, wxString const&, PROPERTIES const*, bool) (kicad_plugin.cpp:2091)
==2880== by 0x113E0030: PCB_IO::FootprintLoad(wxString const&, wxString const&, PROPERTIES const*) (kicad_plugin.cpp:2136)
==2880== by 0x11311786: FP_LIB_TABLE::FootprintLoad(wxString const&, wxString const&) (fp_lib_table.cpp:363)
==2880== by 0x113119D0: FP_LIB_TABLE::FootprintLoadWithOptionalNickname(LIB_ID const&) (fp_lib_table.cpp:438)
==2880== by 0x10F54DB0: ProcessEntry (footprint_preview_panel.cpp:205)
==2880== by 0x10F54DB0: FP_LOADER_THREAD::Entry() (footprint_preview_panel.cpp:236)
==2880== by 0x54649D1: wxThread::CallEntry() (in /nix/store/kkckslvs98x8fjr61wzmjlvy246i137w-wxwidgets-3.1.2/lib/libwx_baseu-3.1.so.2.0.0)
==2880== by 0x54676BC: wxThreadInternal::PthreadStart(wxThread*) (in /nix/store/kkckslvs98x8fjr61wzmjlvy246i137w-wxwidgets-3.1.2/lib/libwx_baseu-3.1.so.2.0.0)
==2880== by 0x64F1EF6: start_thread (in /nix/store/qb6k4hp7gk331x9fydw0w7qj4dv09bwz-glibc-2.27/lib/libpthread-2.27.so)
==2880== by 0x65FE22E: clone (in /nix/store/qb6k4hp7gk331x9fydw0w7qj4dv09bwz-glibc-2.27/lib/libc-2.27.so)
==2880== Block was alloc'd at
==2880== at 0x4834DB2: operator new(unsigned long) (in /nix/store/pgbq8wyhlhjawqcmh2cg7d...

[John Beard (john-j-beard)]

Setting to confirmed because multiple users have seen this.

[Seth Hillbrand (sethh)]

@evils- Would you be able to test John's patch?

[evils (evils)]

doh
yea, the patch works, with a minor freeze when searching

[John Beard (john-j-beard)]

This patch is not a complete solution.

I have rigged up a test fixture that concurrently loads from the PCB_IO plugin from multiple threads. This still crashes with the fix.

From the comments of PCB_IO: "@note This class is not thread safe, but it is re-entrant multiple times in sequence."

So I think either the plugin needs to be thread safe (and so do all plugins, probably, in that case, which is a little bit of an ask), or the accesses need to be mediated through a single thread.

If it's only the cache that's not thread safe (I'm not sure about that), the some kind of store of std::shared_ptr<FP_CACHE> might be enough, so we don't destruct the caches from under other threads. Plus a little bit of mutex-ed access to the store.

[Seth Hillbrand (sethh)]

@John-

Would you like to take this bug?

[John Beard (john-j-beard)]

@Seth, I would take it, but not sure I can commit to a complete solution on a "Critical bug" basis.

If anyone else can see a quick-and-easy way to reliably fix this now, I an more than happy to look at a more robust concurrent footprint cache in the medium term.

[John Beard (john-j-beard)]

I think I've got a handle of what's going on here, I'm working on a fix.

[KiCad Janitor (kicad-janitor)]

KiCad bug tracker has moved to Gitlab. This report is now available here: https://gitlab.com/kicad/code/kicad/-/issues/1755