kicad-developers team mailing list archive

Thread
Date
Re: Occasional hang in Cvpcb when retrieving footprint libraries from github

To: Kristian Nielsen <knielsen@xxxxxxxxxxxxxxx>
From: Nick Østergaard <oe.nick@xxxxxxxxx>
Date: Wed, 2 Dec 2015 18:49:12 +0100
Cc: KiCad Developers <kicad-developers@xxxxxxxxxxxxxxxxxxx>
In-reply-to: <87y4dcbxmk.fsf@urd.knielsen-hq.org>
2015-12-02 17:53 GMT+01:00 Kristian Nielsen <knielsen@xxxxxxxxxxxxxxx>:
> Sometimes, but not everytime, Cvpcb hangs for me when started when it tries
> to read the footprints from Github. It looks like a race, maybe a bug in
> Boost. I suspect this might have been the causeof bugs like
> https://bugs.launchpad.net/kicad/+bug/1489128, just the random nature of the
> bug making debugging difficult.
>
> Does anyone else experience this? This is not the normal download delay, it
> seems stuck for good in recvmsg():
>
> $ strace -p 8161
> Process 8161 attached
> recvmsg(61,
>
> $ lsof -p 8145
> kicad   8145 knielsen   61u  IPv4              85080      0t0      TCP urd:37817->codeload.github.com:https (ESTABLISHED)
>
> $ sudo tcpdump -i any host codeload.github.com
> ... (other parallel connections omitted for brevity)
> 17:02:27.146802 IP urd.37817 > codeload.github.com.https: Flags [S], seq 3346029680, win 29200, options [mss 1460,sackOK,TS val 7315036 ecr 0,nop,wscale 7], length 0
> 17:02:27.277308 IP codeload.github.com.https > urd.37817: Flags [S.], seq 1746405727, ack 3346029681, win 14240, options [mss 1436,sackOK,TS val 1504320336 ecr 7315036,nop,wscale 10], length 0
> 17:02:27.277317 IP urd.37817 > codeload.github.com.https: Flags [.], ack 1, win 229, options [nop,nop,TS val 7315069 ecr 1504320336], length 0
> 17:02:27.277354 IP urd.37817 > codeload.github.com.https: Flags [P.], seq 1:296, ack 1, win 229, options [nop,nop,TS val 7315069 ecr 1504320336], length 295
> 17:02:27.417749 IP codeload.github.com.https > urd.37817: Flags [.], seq 1:1425, ack 296, win 15, options [nop,nop,TS val 1504320372 ecr 7315069], length 1424
> 17:02:27.417786 IP urd.37817 > codeload.github.com.https: Flags [.], ack 1425, win 251, options [nop,nop,TS val 7315104 ecr 1504320372], length 0
> 17:04:27.416054 IP codeload.github.com.https > urd.37817: Flags [F.], seq 3029, ack 296, win 15, options [nop,nop,TS val 1504350372 ecr 7315104], length 0
> 17:04:27.416079 IP urd.37817 > codeload.github.com.https: Flags [.], ack 1425, win 251, options [nop,nop,TS val 7345103 ecr 1504320372,nop,nop,sack 1 {3029:3030}], length 0
>
> See how the client sent 295 bytes and Github returned 1424 bytes - and then
> nothing, until Github times out and closes the connection, while the client
> is still stuck in recvmsg() on that connection. Clearly, Cvpcb should have
> continued the communication here, but got stuck somehow.
>
> GDB stacktraces of the stuck threads (full stacktrace at the end of the
> mail):
>
> Thread 2 (Thread 0x7f6458d1d700 (LWP 8161)):
> #0  0x00007f647e11de9d in recvmsg () at ../sysdeps/unix/syscall-template.S:81
> #1  0x00007f6470a6f96c in boost::asio::detail::socket_ops::sync_recv(int, unsigned char, iovec*, unsigned long, int, bool, boost::system::error_code&) ()
>    from /kvm/kicad/bin/_cvpcb.kiface
> #2  0x00007f6470a8189a in unsigned long boost::asio::ssl::detail::io<boost::asio::basic_stream_socket<boost::asio::ip::tcp, boost::asio::stream_socket_service<boost::asio::ip::tcp> >, boost::asio::ssl::detail::handshake_op>(boost::asio::basic_stream_socket<boost::asio::ip::tcp, boost::asio::stream_socket_service<boost::asio::ip::tcp> >&, boost::asio::ssl::detail::stream_core&, boost::asio::ssl::detail::handshake_op const&, boost::system::error_code&) () from /kvm/kicad/bin/_cvpcb.kiface
> #3  0x00007f6470a91c20 in avhttp::http_stream::open(avhttp::url const&, boost::system::error_code&) () from /kvm/kicad/bin/_cvpcb.kiface
> #4  0x00007f6470a69500 in GITHUB_PLUGIN::remote_get_zip(wxString const&) () from /kvm/kicad/bin/_cvpcb.kiface
>
> Thread 1 (Thread 0x7f6481164a80 (LWP 8145)):
> #0  pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
> #1  0x00007f6470a9bcbb in boost::condition_variable::wait(boost::unique_lock<boost::mutex>&) () from /kvm/kicad/bin/_cvpcb.kiface
> #2  0x00007f6470a9a3bc in boost::thread::join_noexcept() () from /kvm/kicad/bin/_cvpcb.kiface
> #3  0x00007f6470806ce0 in FOOTPRINT_LIST::ReadFootprintFiles(FP_LIB_TABLE*, wxString const*) () from /kvm/kicad/bin/_cvpcb.kiface
>
> It kind of looks like a bug in Boost here? I think boost opens a number of
> parallel HTTP sessions to github, and somehow there seems to be a race that
> causes it to get stuck occasionally. Unless it's a bug in the linux network
> stack (I am on version 4.1.3 of the Linux kernel).
>
> Any suggestions on what I could do to try to debug this further? I am using
> a self-compiled Kicad latest from Github as of today:
>
> commit f4cf050669955c7c75bb760166ffbd9b9c8f2e6b
> Author: jean-pierre charras <jp.charras@xxxxxxxxxx>
> Date:   Wed Dec 2 12:46:55 2015 +0100
>
>     Eagle plugin: fix typo errors. Use paired fab layers for layers 51 and 52. Not perfect, but better than the old choice (drawing layer)
>
> I am on Debian stable / Jessie. Boost version on the system is 1.55.0.2,
> while the one in .downloads-by-cmake/ is boost_1_54_0/ (sorry, not sure how
> to tell which of the two is used by the build).

Did you specifically use -DKICAD_SKIP_BOOST=YES ? If now then you are
using boost 1.54 that kicad downloaded.

You can see the version used in the help meny in any of the main apps,
help -> copy version info

> Hope this helps,
>
>  - Kristian.
>
> -----------------------------------------------------------------------
> Full GDB stack traces, for reference:
>
> Thread 4 (Thread 0x7f6472f23700 (LWP 8146)):
> #0  0x00007f647de4350d in poll () at ../sysdeps/unix/syscall-template.S:81
> #1  0x00007f647c4fdee4 in ?? () from /lib/x86_64-linux-gnu/libglib-2.0.so.0
> #2  0x00007f647c4fe272 in g_main_loop_run () from /lib/x86_64-linux-gnu/libglib-2.0.so.0
> #3  0x00007f6479f6bf76 in ?? () from /usr/lib/x86_64-linux-gnu/libgio-2.0.so.0
> #4  0x00007f647c524935 in ?? () from /lib/x86_64-linux-gnu/libglib-2.0.so.0
> #5  0x00007f647e1170a4 in start_thread (arg=0x7f6472f23700) at pthread_create.c:309
> #6  0x00007f647de4c04d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111
>
> Thread 3 (Thread 0x7f6472722700 (LWP 8147)):
> #0  0x00007f647de4350d in poll () at ../sysdeps/unix/syscall-template.S:81
> #1  0x00007f647c4fdee4 in ?? () from /lib/x86_64-linux-gnu/libglib-2.0.so.0
> #2  0x00007f647c4fdffc in g_main_context_iteration () from /lib/x86_64-linux-gnu/libglib-2.0.so.0
> #3  0x00007f647c4fe039 in ?? () from /lib/x86_64-linux-gnu/libglib-2.0.so.0
> #4  0x00007f647c524935 in ?? () from /lib/x86_64-linux-gnu/libglib-2.0.so.0
> #5  0x00007f647e1170a4 in start_thread (arg=0x7f6472722700) at pthread_create.c:309
> #6  0x00007f647de4c04d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111
>
> Thread 2 (Thread 0x7f6458d1d700 (LWP 8161)):
> #0  0x00007f647e11de9d in recvmsg () at ../sysdeps/unix/syscall-template.S:81
> #1  0x00007f6470a6f96c in boost::asio::detail::socket_ops::sync_recv(int, unsigned char, iovec*, unsigned long, int, bool, boost::system::error_code&) ()
>    from /kvm/kicad/bin/_cvpcb.kiface
> #2  0x00007f6470a8189a in unsigned long boost::asio::ssl::detail::io<boost::asio::basic_stream_socket<boost::asio::ip::tcp, boost::asio::stream_socket_service<boost::asio::ip::tcp> >, boost::asio::ssl::detail::handshake_op>(boost::asio::basic_stream_socket<boost::asio::ip::tcp, boost::asio::stream_socket_service<boost::asio::ip::tcp> >&, boost::asio::ssl::detail::stream_core&, boost::asio::ssl::detail::handshake_op const&, boost::system::error_code&) () from /kvm/kicad/bin/_cvpcb.kiface
> #3  0x00007f6470a91c20 in avhttp::http_stream::open(avhttp::url const&, boost::system::error_code&) () from /kvm/kicad/bin/_cvpcb.kiface
> #4  0x00007f6470a69500 in GITHUB_PLUGIN::remote_get_zip(wxString const&) () from /kvm/kicad/bin/_cvpcb.kiface
> #5  0x00007f6470a6a1c8 in GITHUB_PLUGIN::cacheLib(wxString const&, PROPERTIES const*) () from /kvm/kicad/bin/_cvpcb.kiface
> #6  0x00007f6470a6aa87 in GITHUB_PLUGIN::FootprintEnumerate(wxString const&, PROPERTIES const*) () from /kvm/kicad/bin/_cvpcb.kiface
> #7  0x00007f6470916d73 in FP_LIB_TABLE::FootprintEnumerate(wxString const&) () from /kvm/kicad/bin/_cvpcb.kiface
> #8  0x00007f6470806043 in FOOTPRINT_LIST::loader_job(wxString const*, int) () from /kvm/kicad/bin/_cvpcb.kiface
> #9  0x00007f6470a997d2 in thread_proxy () from /kvm/kicad/bin/_cvpcb.kiface
> #10 0x00007f647e1170a4 in start_thread (arg=0x7f6458d1d700) at pthread_create.c:309
> #11 0x00007f647de4c04d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111
>
> Thread 1 (Thread 0x7f6481164a80 (LWP 8145)):
> #0  pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
> #1  0x00007f6470a9bcbb in boost::condition_variable::wait(boost::unique_lock<boost::mutex>&) () from /kvm/kicad/bin/_cvpcb.kiface
> #2  0x00007f6470a9a3bc in boost::thread::join_noexcept() () from /kvm/kicad/bin/_cvpcb.kiface
> #3  0x00007f6470806ce0 in FOOTPRINT_LIST::ReadFootprintFiles(FP_LIB_TABLE*, wxString const*) () from /kvm/kicad/bin/_cvpcb.kiface
> #4  0x00007f647074d94f in CVPCB_MAINFRAME::LoadFootprintFiles() () from /kvm/kicad/bin/_cvpcb.kiface
> #5  0x00007f647075a7ae in CVPCB_MAINFRAME::ReadNetListAndLinkFiles(std::string const&) () from /kvm/kicad/bin/_cvpcb.kiface
> #6  0x00007f647f429d5e in wxAppConsoleBase::CallEventHandler(wxEvtHandler*, wxEventFunctor&, wxEvent&) const () from /usr/lib/x86_64-linux-gnu/libwx_baseu-3.0.so.0
> #7  0x00007f647f5c54c8 in wxEvtHandler::ProcessEventIfMatchesId(wxEventTableEntryBase const&, wxEvtHandler*, wxEvent&) () from /usr/lib/x86_64-linux-gnu/libwx_baseu-3.0.so.0
> #8  0x00007f647f5c55cb in wxEventHashTable::HandleEvent(wxEvent&, wxEvtHandler*) () from /usr/lib/x86_64-linux-gnu/libwx_baseu-3.0.so.0
> #9  0x00007f647f5c5978 in wxEvtHandler::TryHereOnly(wxEvent&) () from /usr/lib/x86_64-linux-gnu/libwx_baseu-3.0.so.0
> #10 0x00007f647f5c5a03 in wxEvtHandler::ProcessEventLocally(wxEvent&) () from /usr/lib/x86_64-linux-gnu/libwx_baseu-3.0.so.0
> #11 0x00007f647f5c5a65 in wxEvtHandler::ProcessEvent(wxEvent&) () from /usr/lib/x86_64-linux-gnu/libwx_baseu-3.0.so.0
> #12 0x00007f647095d559 in EDA_BASE_FRAME::ProcessEvent(wxEvent&) () from /kvm/kicad/bin/_cvpcb.kiface
> #13 0x0000000000497ac3 in ?? ()
> #14 0x00007f64710cee01 in SCH_EDIT_FRAME::sendNetlist() () from /kvm/kicad/bin/_eeschema.kiface
> #15 0x00007f6471140384 in SCH_EDIT_FRAME::OnOpenCvpcb(wxCommandEvent&) () from /kvm/kicad/bin/_eeschema.kiface
> #16 0x00007f647f429d5e in wxAppConsoleBase::CallEventHandler(wxEvtHandler*, wxEventFunctor&, wxEvent&) const () from /usr/lib/x86_64-linux-gnu/libwx_baseu-3.0.so.0
> #17 0x00007f647f5c54c8 in wxEvtHandler::ProcessEventIfMatchesId(wxEventTableEntryBase const&, wxEvtHandler*, wxEvent&) () from /usr/lib/x86_64-linux-gnu/libwx_baseu-3.0.so.0
> #18 0x00007f647f5c55cb in wxEventHashTable::HandleEvent(wxEvent&, wxEvtHandler*) () from /usr/lib/x86_64-linux-gnu/libwx_baseu-3.0.so.0
> #19 0x00007f647f5c5978 in wxEvtHandler::TryHereOnly(wxEvent&) () from /usr/lib/x86_64-linux-gnu/libwx_baseu-3.0.so.0
> #20 0x00007f64711d31a9 in EDA_BASE_FRAME::ProcessEvent(wxEvent&) () from /kvm/kicad/bin/_eeschema.kiface
> #21 0x00007f647f5c5783 in wxEvtHandler::DoTryChain(wxEvent&) () from /usr/lib/x86_64-linux-gnu/libwx_baseu-3.0.so.0
> #22 0x00007f647f5c5a65 in wxEvtHandler::ProcessEvent(wxEvent&) () from /usr/lib/x86_64-linux-gnu/libwx_baseu-3.0.so.0
> #23 0x00007f647ffa7608 in wxWindowBase::TryAfter(wxEvent&) () from /usr/lib/x86_64-linux-gnu/libwx_gtk2u_core-3.0.so.0
> #24 0x00007f6480b46498 in wxAuiToolBar::OnLeftUp(wxMouseEvent&) () from /usr/lib/x86_64-linux-gnu/libwx_gtk2u_aui-3.0.so.0
> #25 0x00007f647f429d5e in wxAppConsoleBase::CallEventHandler(wxEvtHandler*, wxEventFunctor&, wxEvent&) const () from /usr/lib/x86_64-linux-gnu/libwx_baseu-3.0.so.0
> #26 0x00007f647f5c54c8 in wxEvtHandler::ProcessEventIfMatchesId(wxEventTableEntryBase const&, wxEvtHandler*, wxEvent&) () from /usr/lib/x86_64-linux-gnu/libwx_baseu-3.0.so.0
> #27 0x00007f647f5c55cb in wxEventHashTable::HandleEvent(wxEvent&, wxEvtHandler*) () from /usr/lib/x86_64-linux-gnu/libwx_baseu-3.0.so.0
> #28 0x00007f647f5c5978 in wxEvtHandler::TryHereOnly(wxEvent&) () from /usr/lib/x86_64-linux-gnu/libwx_baseu-3.0.so.0
> #29 0x00007f647f5c5a03 in wxEvtHandler::ProcessEventLocally(wxEvent&) () from /usr/lib/x86_64-linux-gnu/libwx_baseu-3.0.so.0
> #30 0x00007f647f5c5a65 in wxEvtHandler::ProcessEvent(wxEvent&) () from /usr/lib/x86_64-linux-gnu/libwx_baseu-3.0.so.0
> #31 0x00007f647f5c57d7 in wxEvtHandler::SafelyProcessEvent(wxEvent&) () from /usr/lib/x86_64-linux-gnu/libwx_baseu-3.0.so.0
> #32 0x00007f647fd956cb in ?? () from /usr/lib/x86_64-linux-gnu/libwx_gtk2u_core-3.0.so.0
> #33 0x00007f647d84aa3f in ?? () from /usr/lib/x86_64-linux-gnu/libgtk-x11-2.0.so.0
> #34 0x00007f647d220245 in g_closure_invoke () from /usr/lib/x86_64-linux-gnu/libgobject-2.0.so.0
> #35 0x00007f647d231f6c in ?? () from /usr/lib/x86_64-linux-gnu/libgobject-2.0.so.0
> #36 0x00007f647d23a285 in g_signal_emit_valist () from /usr/lib/x86_64-linux-gnu/libgobject-2.0.so.0
> #37 0x00007f647d23a9df in g_signal_emit () from /usr/lib/x86_64-linux-gnu/libgobject-2.0.so.0
> #38 0x00007f647d961d6c in ?? () from /usr/lib/x86_64-linux-gnu/libgtk-x11-2.0.so.0
> #39 0x00007f647d849184 in gtk_propagate_event () from /usr/lib/x86_64-linux-gnu/libgtk-x11-2.0.so.0
> #40 0x00007f647d84961b in gtk_main_do_event () from /usr/lib/x86_64-linux-gnu/libgtk-x11-2.0.so.0
> #41 0x00007f647d4bcb5c in ?? () from /usr/lib/x86_64-linux-gnu/libgdk-x11-2.0.so.0
> #42 0x00007f647c4fdc5d in g_main_context_dispatch () from /lib/x86_64-linux-gnu/libglib-2.0.so.0
> #43 0x00007f647c4fdf48 in ?? () from /lib/x86_64-linux-gnu/libglib-2.0.so.0
> #44 0x00007f647c4fe272 in g_main_loop_run () from /lib/x86_64-linux-gnu/libglib-2.0.so.0
> #45 0x00007f647d848597 in gtk_main () from /usr/lib/x86_64-linux-gnu/libgtk-x11-2.0.so.0
> #46 0x00007f647fd688a5 in wxGUIEventLoop::DoRun() () from /usr/lib/x86_64-linux-gnu/libwx_gtk2u_core-3.0.so.0
> #47 0x00007f647f46fd50 in wxEventLoopBase::Run() () from /usr/lib/x86_64-linux-gnu/libwx_baseu-3.0.so.0
> #48 0x00007f647f42c086 in wxAppConsoleBase::MainLoop() () from /usr/lib/x86_64-linux-gnu/libwx_baseu-3.0.so.0
> #49 0x0000000000442196 in ?? ()
> #50 0x00007f647f4c6c20 in wxEntry(int&, wchar_t**) () from /usr/lib/x86_64-linux-gnu/libwx_baseu-3.0.so.0
> #51 0x0000000000421a5e in ?? ()
> #52 0x00007f647dd87b45 in __libc_start_main (main=0x421a30, argc=2, argv=0x7fff279fa1c8, init=<optimized out>, fini=<optimized out>, rtld_fini=<optimized out>,
>     stack_end=0x7fff279fa1b8) at libc-start.c:287
>
> _______________________________________________
> Mailing list: https://launchpad.net/~kicad-developers
> Post to     : kicad-developers@xxxxxxxxxxxxxxxxxxx
> Unsubscribe : https://launchpad.net/~kicad-developers
> More help   : https://help.launchpad.net/ListHelp
Follow ups

Re: Occasional hang in Cvpcb when retrieving footprint libraries from github
From: Kristian Nielsen, 2015-12-02
References

Occasional hang in Cvpcb when retrieving footprint libraries from github
From: Kristian Nielsen, 2015-12-02