kicad-developers team mailing list archive

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

To: KiCad Developers <kicad-developers@xxxxxxxxxxxxxxxxxxx>
From: Kristian Nielsen <knielsen@xxxxxxxxxxxxxxx>
Date: Wed, 02 Dec 2015 17:53:23 +0100
User-agent: Gnus/5.13 (Gnus v5.13) Emacs/24.4 (gnu/linux)
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).

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
Follow ups

Re: Occasional hang in Cvpcb when retrieving footprint libraries from github
From: Nick Østergaard, 2015-12-02
Re: Occasional hang in Cvpcb when retrieving footprint libraries from github
From: Mark Roszko, 2015-12-02