et seg faults on network disconnect about eternalterminal

[MisterTea]

The logs don't show any issues. Can you try running in verbose mode? Pass the -v option to et.

[NikolasOliveira]

Here are the results with -v

Same process:

Successful connection:

niko@mexico:~$ et -v niko@cartagena
preexec - timestamp: Tue Mar 14 20:23:14 PDT 2017 - et -v niko@cartagena - 2167
I0314 20:23:20.978246 17672 TerminalServer.cpp:184] Closing server in fork
I0314 20:23:20.978361 17672 UnixSocketHandler.cpp:291] Closing connection: 4
I0314 20:23:20.978373 17672 UnixSocketHandler.cpp:291] Closing connection: 5
I0314 20:23:20.978381 17672 UnixSocketHandler.cpp:291] Closing connection: 6
I0314 20:23:20.978387 17672 Connection.cpp:109] Closed socket
I0314 20:23:20.978397 17672 TerminalServer.cpp:189] Child process /bin/bash
postexec - exit code: 0, elapsed time: s -  - 17672

Disconnect the network:

niko@mexico:~$ nmcli dev status | grep 'wlan0\|DEVICE' 
preexec - timestamp: Tue Mar 14 20:23:29 PDT 2017 - nmcli dev status | grep 'wlan0\|DEVICE' - 13930
DEVICE   TYPE      STATE        CONNECTION 
wlan0    wifi      connected    sainte     
postexec - exit code: 0, elapsed time: .112s - nmcli dev status | grep 'wlan0|DEVICE' - 13930
niko@mexico:~$ nmcli dev disconnect wlan0
preexec - timestamp: Tue Mar 14 20:23:34 PDT 2017 - nmcli dev disconnect wlan0 - 13930
Device 'wlan0' successfully disconnected.
postexec - exit code: 0, elapsed time: .218s - nmcli dev disconnect wlan0 - 13930
niko@mexico:~$ nmcli dev status | grep 'wlan0\|DEVICE' 
preexec - timestamp: Tue Mar 14 20:23:35 PDT 2017 - nmcli dev status | grep 'wlan0\|DEVICE' - 13930
DEVICE   TYPE      STATE         CONNECTION 
wlan0    wifi      disconnected  --         
postexec - exit code: 0, elapsed time: .092s - nmcli dev status | grep 'wlan0|DEVICE' - 13930

Seg fault on the et session:

niko@cartagena:~$ /usr/local/bin/et: line 116: 17383 Segmentation fault      (core dumped) $CLIENT_BINARY --passkeyfile="$TMPFILE" $VERBOSITY --host="$HOSTNAME" --port="$PORT" --log_dir="$LOG_DIR" 2> /tmp/et_err
             postexec - exit code: 139, elapsed time: 26.478s - et -v niko@cartagena - 2167
                                                                                           niko@mexico:~$ 

Log attached.
etclientLogs.tar.gz
etserverLogs.tar.gz

I can upload the core if that'll help, but I don't see anything in /var/crash or /var/core

Cheers,
Niko

[MisterTea]

Hmm, there's nothing in the logs. Can you get a stack trace from the seg fault?

Run like this to get a stack trace (use the 'bt' command to print the whole stack trace):

gdb --args et ....

[NikolasOliveira]

Same process as before so I'll skip outlining the steps and just paste the backtrace:

NOTE: I had to edit the et shell script and prepend the call to the etclient binary with the gdb call, since gdb was not happy running on et directly (complaining that it wasn't an executable binary).

niko@mexico:~$ et niko@cartagena
preexec - timestamp: Thu Mar 16 13:03:36 PDT 2017 - et niko@cartagena - 6380
GNU gdb (Ubuntu 7.11.1-0ubuntu1~16.04) 7.11.1
Copyright (C) 2016 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.  Type "show copying"
and "show warranty" for details.
This GDB was configured as "x86_64-linux-gnu".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>.
Find the GDB manual and other documentation resources online at:
<http://www.gnu.org/software/gdb/documentation/>.
For help, type "help".
Type "apropos word" to search for commands related to "word"...
Reading symbols from etclient...(no debugging symbols found)...done.
(gdb) run
Starting program: /usr/local/bin/etclient --passkeyfile=/tmp/et.YNhbmz --host=cartagena --port=2022 --log_dir=/tmp
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
postexec - exit code: 0, elapsed time: s -  - 21913
niko@cartagena:~$ [New Thread 0x7ffff50a6700 (LWP 25699)]

                                                         Thread 2 "etclient" received signal SIGSEGV, Segmentation fault.
  [Switching to Thread 0x7ffff50a6700 (LWP 25699)]
strlen () at ../sysdeps/x86_64/strlen.S:106
(gdb) bt
#0  strlen () at ../sysdeps/x86_64/strlen.S:106
#1  0x00007ffff6b30229 in std::basic_ostream<char, std::char_traits<char> >& std::operator<< <std::char_traits<char> >(std::basic_ostream<char, std::char_traits<char> >&, char const*) () from /usr/lib/x86_64-linux-gnu/libstdc++.so.6
#2  0x00000000004494ed in et::UnixSocketHandler::connect(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, int) ()
#3  0x0000000000442996 in et::ClientConnection::pollReconnect() ()
#4  0x0000000000445937 in void std::_Mem_fn_base<void (et::ClientConnection::*)(), true>::operator()<, void>(et::ClientConnection*) const ()
#5  0x00000000004458cb in void std::_Bind_simple<std::_Mem_fn<void (et::ClientConnection::*)()> (et::ClientConnection*)>::_M_invoke<0ul>(std::_Index_tuple<0ul>) ()
#6  0x00000000004457d2 in std::_Bind_simple<std::_Mem_fn<void (et::ClientConnection::*)()> (et::ClientConnection*)>::operator()() ()
#7  0x0000000000445762 in std::thread::_Impl<std::_Bind_simple<std::_Mem_fn<void (et::ClientConnection::*)()> (et::ClientConnection*)> >::_M_run() ()
#8  0x00007ffff6ad9c80 in ?? () from /usr/lib/x86_64-linux-gnu/libstdc++.so.6
#9  0x00007ffff77766ba in start_thread (arg=0x7ffff50a6700) at pthread_create.c:333
#10 0x00007ffff654882d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:109
(gdb) 

[MisterTea]

Hmm, the stack trace doesn't have the line numbers in it. Are you using the binary from the repo or did you build your own?

[MisterTea]

I found one case where it's possible to get strlen(NULL), but it means the socket creation failed, which is very strange. Either way, try the latest master and let me know if the problem goes away.

[NikolasOliveira]

@MisterTea This is a build of master from 2 days ago. Is there anything new since then?
Also, how often do you archive master (https://github.com/MisterTea/EternalTCP/archive/master.zip)?

[MisterTea]

I just pushed a change 13 minutes ago. Master gets archived automatically by github

[MisterTea]

Since you are building it yourself, can you build a debug binary so I can see the line numbers? You can do this by using ccmake and changing the build type to debug

[NikolasOliveira]

Ah, didn't know that zip was built automatically. I'll try fresh code tonight.

[MisterTea]

Cool, you can also set debug mode like this:

cmake -DCMAKE_BUILD_TYPE=Debug ./

[NikolasOliveira]

Cool, you can also set debug mode like this:

Yupp, will do

[NikolasOliveira]

Repro with latest code and debug symbols:

niko@mexico:/tmp/et/EternalTCP-master/build$ et niko@cartagena
preexec - timestamp: Thu Mar 16 20:13:16 PDT 2017 - et niko@cartagena - 30385
GNU gdb (Ubuntu 7.11.1-0ubuntu1~16.04) 7.11.1
Copyright (C) 2016 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.  Type "show copying"
and "show warranty" for details.
This GDB was configured as "x86_64-linux-gnu".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>.
Find the GDB manual and other documentation resources online at:
<http://www.gnu.org/software/gdb/documentation/>.
For help, type "help".
Type "apropos word" to search for commands related to "word"...
Reading symbols from etclient...done.
(gdb) run
Starting program: /tmp/et/EternalTCP-master/build/etclient --passkeyfile=/tmp/et.imlnMJ --host=cartagena --port=2022 --log_dir=/tmp
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
postexec - exit code: 0, elapsed time: s -  - 27782
niko@cartagena:~$ [New Thread 0x7ffff50a6700 (LWP 15213)]

                                                         Thread 2 "etclient" received signal SIGSEGV, Segmentation fault.
                      [Switching to Thread 0x7ffff50a6700 (LWP 15213)]
0x0000000000449452 in et::UnixSocketHandler::connect (this=0x67c520, hostname="cartagena", 
    port=2022) at /tmp/et/EternalTCP-master/src/UnixSocketHandler.cpp:79
79	    if ((sockfd = socket(p->ai_family, p->ai_socktype, p->ai_protocol)) == -1) {
(gdb) bt
#0  0x0000000000449452 in et::UnixSocketHandler::connect (this=0x67c520, hostname="cartagena", port=2022) at /tmp/et/EternalTCP-master/src/UnixSocketHandler.cpp:79
#1  0x0000000000442996 in et::ClientConnection::pollReconnect (this=0x67ecf0) at /tmp/et/EternalTCP-master/src/ClientConnection.cpp:95
#2  0x0000000000445937 in std::_Mem_fn_base<void (et::ClientConnection::*)(), true>::operator()<, void>(et::ClientConnection*) const (this=0x67ec50, __object=0x67ecf0)
    at /usr/include/c++/5/functional:600
#3  0x00000000004458cb in std::_Bind_simple<std::_Mem_fn<void (et::ClientConnection::*)()> (et::ClientConnection*)>::_M_invoke<0ul>(std::_Index_tuple<0ul>) (this=0x67ec48)
    at /usr/include/c++/5/functional:1531
#4  0x00000000004457d2 in std::_Bind_simple<std::_Mem_fn<void (et::ClientConnection::*)()> (et::ClientConnection*)>::operator()() (this=0x67ec48) at /usr/include/c++/5/functional:1520
#5  0x0000000000445762 in std::thread::_Impl<std::_Bind_simple<std::_Mem_fn<void (et::ClientConnection::*)()> (et::ClientConnection*)> >::_M_run() (this=0x67ec30) at /usr/include/c++/5/thread:115
#6  0x00007ffff6ad9c80 in ?? () from /usr/lib/x86_64-linux-gnu/libstdc++.so.6
#7  0x00007ffff77766ba in start_thread (arg=0x7ffff50a6700) at pthread_create.c:333
#8  0x00007ffff654882d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:109
(gdb)

[MisterTea]

Wow this is really strange. Just before the line that's crashing, can you add this:

cout << "CREATING SOCKET: " << p << " " << p->ai_family << " " << p->ai_socktype << " " << p->ai_protocol;

and let me know what it says.

[MisterTea]

Also what OS are you running?

[NikolasOliveira]

Wow this is really strange. Just before the line that's crashing, can you add this:

Sure I can take a look at that. But it might be easier for me to just checkout a dev branch with all the debug logging you want in it and build that and test with it?

Also what OS are you running?

Ubuntu 16.04 on both ends:

niko@mexico:~$ lsb_release -a
preexec - timestamp: Fri Mar 17 09:43:50 PDT 2017 - lsb_release -a - 18412
No LSB modules are available.
Distributor ID:	Ubuntu
Description:	Ubuntu 16.04.1 LTS
Release:	16.04
Codename:	xenial
postexec - exit code: 0, elapsed time: .075s - lsb_release -a - 18412

niko@cartagena:~$ lsb_release -a
preexec - timestamp: Fri Mar 17 09:43:34 PDT 2017 - lsb_release -a - 30778
No LSB modules are available.
Distributor ID: Ubuntu
Description:    Ubuntu 16.04.1 LTS
Release:        16.04
Codename:       xenial
postexec - exit code: 0, elapsed time: .052s - lsb_release -a - 30778

[MisterTea]

A debug branch is a good idea. If we don't get to the bottom of it with that print then I'll do that.

[NikolasOliveira]

Here are the results. I directed the logging to stderr so that it'd show up in the /tmp/et_err log:

niko@mexico:/tmp/et/EternalTCP-master/build$ et niko@cartagena
preexec - timestamp: Sat Mar 18 18:50:05 PDT 2017 - et niko@cartagena - 12680
GNU gdb (Ubuntu 7.11.1-0ubuntu1~16.04) 7.11.1
Copyright (C) 2016 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.  Type "show copying"
and "show warranty" for details.
This GDB was configured as "x86_64-linux-gnu".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>.
Find the GDB manual and other documentation resources online at:
<http://www.gnu.org/software/gdb/documentation/>.
For help, type "help".
Type "apropos word" to search for commands related to "word"...
Reading symbols from etclient...done.
(gdb) run
Starting program: /tmp/et/EternalTCP-master/build/etclient --passkeyfile=/tmp/et.E7uwwi --host=cartagena --port=2022 --log_dir=/tmp
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
postexec - exit code: 0, elapsed time: s -  - 9913
niko@cartagena:~$ [New Thread 0x7ffff50a6700 (LWP 28918)]

                                                         Thread 2 "etclient" received signal SIGSEGV, Segmentation fault.
                                                                                                                         [Switching to Thread 0x7ffff50a6700 (LWP 28918)]
0x00000000004494a2 in et::UnixSocketHandler::connect (this=0x67c520, hostname="cartagena", port=2022)
    at /tmp/et/EternalTCP-master/src/UnixSocketHandler.cpp:79
79	    cerr << "CREATING SOCKET: " << p << " " << p->ai_family << " " << p->ai_socktype << " " << p->ai_protocol << "\n";
(gdb) bt
#0  0x00000000004494a2 in et::UnixSocketHandler::connect (this=0x67c520, hostname="cartagena", port=2022)
    at /tmp/et/EternalTCP-master/src/UnixSocketHandler.cpp:79
#1  0x00000000004429e6 in et::ClientConnection::pollReconnect (this=0x67ecf0)
    at /tmp/et/EternalTCP-master/src/ClientConnection.cpp:95
#2  0x0000000000445987 in std::_Mem_fn_base<void (et::ClientConnection::*)(), true>::operator()<, void>(et::ClientConnection*) const (this=0x67fea0, __object=0x67ecf0) at /usr/include/c++/5/functional:600
#3  0x000000000044591b in std::_Bind_simple<std::_Mem_fn<void (et::ClientConnection::*)()> (et::ClientConnection*)>::_M_invoke<0ul>(std::_Index_tuple<0ul>) (this=0x67fe98) at /usr/include/c++/5/functional:1531
#4  0x0000000000445822 in std::_Bind_simple<std::_Mem_fn<void (et::ClientConnection::*)()> (et::ClientConnection*)>::operator()() (this=0x67fe98) at /usr/include/c++/5/functional:1520
#5  0x00000000004457b2 in std::thread::_Impl<std::_Bind_simple<std::_Mem_fn<void (et::ClientConnection::*)()> (et::ClientConnection*)> >::_M_run() (this=0x67fe80) at /usr/include/c++/5/thread:115
#6  0x00007ffff6ad9c80 in ?? () from /usr/lib/x86_64-linux-gnu/libstdc++.so.6
#7  0x00007ffff77766ba in start_thread (arg=0x7ffff50a6700) at pthread_create.c:333
#8  0x00007ffff654882d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:109
(gdb) 

And the logging:

niko@mexico:/tmp$ cat et_err 
preexec - timestamp: Sat Mar 18 18:52:43 PDT 2017 - cat et_err - 25113
CREATING SOCKET: 0x67ca70 2 1 6
E0318 18:50:27.013267 28737 UnixSocketHandler.cpp:274] Tried to close a connection that doesn't exist: 4
CREATING SOCKET: 0x45494e 1866691694 1667591790 1852795252
postexec - exit code: 0, elapsed time: .006s - cat et_err - 25113

[MisterTea]

Ok I found the problem. getaddrinfo(), unlike most of the unix functions, returns the error code directly instead of returning -1 and expecting you to check the errno variable. I should have a fix for this soon, but I want to make sure I handle the errors correctly.

[MisterTea]

Out of curiosity, can you print the return value from getaddrinfo?

I want to know what rc is after this line:

  int rc = getaddrinfo(hostname.c_str(), portname.c_str(), &hints, &results);

[MisterTea]

It's probably EAI_NODATA since you are manually killing your network interface.

[MisterTea]

Whatever the error is, 3018cc3 will keep retrying instead of crashing the client, so latest master should work for you. Please close if this fixes the issue.

[NikolasOliveira]

Hit another seg fault :(

niko@mexico:/tmp/et/EternalTCP-master/build$ et niko@cartagena
preexec - timestamp: Tue Mar 21 09:54:56 PDT 2017 - et niko@cartagena - 22293
GNU gdb (Ubuntu 7.11.1-0ubuntu1~16.04) 7.11.1
Copyright (C) 2016 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.  Type "show copying"
and "show warranty" for details.
This GDB was configured as "x86_64-linux-gnu".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>.
Find the GDB manual and other documentation resources online at:
<http://www.gnu.org/software/gdb/documentation/>.
For help, type "help".
Type "apropos word" to search for commands related to "word"...
Reading symbols from etclient...done.

(gdb) run
Starting program: /tmp/et/EternalTCP-master/build/etclient --passkeyfile=/tmp/et.ivlcyC --host=cartagena --port=2022 --log_dir=/tmp
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
postexec - exit code: 0, elapsed time: s -  - 26279

niko@cartagena:~$ hostname
preexec - timestamp: Tue Mar 21 09:55:31 PDT 2017 - hostname - 26279
cartagena
postexec - exit code: 0, elapsed time: .003s - hostname - 26279

<<<disconnect network now>>>

niko@cartagena:~$ [New Thread 0x7ffff50a6700 (LWP 3562)]

                                                        Thread 2 "etclient" received signal SIGSEGV, Segmentation fault.
 [Switching to Thread 0x7ffff50a6700 (LWP 3562)]
__GI___libc_free (mem=0x6f6e20646c756f43) at malloc.c:2949
(gdb) bt'
#0  __GI___libc_free (mem=0x6f6e20646c756f43) at malloc.c:2949
#1  0x00007ffff6530d2d in __GI_freeaddrinfo (ai=0x63656e6e6f632074) at ../sysdeps/posix/getaddrinfo.c:2692
#2  0x0000000000449350 in et::UnixSocketHandler::connect (this=0x67c520, hostname="cartagena", port=2022)
    at /tmp/et/EternalTCP-master/src/UnixSocketHandler.cpp:71
#3  0x0000000000442996 in et::ClientConnection::pollReconnect (this=0x67ecf0)
    at /tmp/et/EternalTCP-master/src/ClientConnection.cpp:95
#4  0x0000000000445937 in std::_Mem_fn_base<void (et::ClientConnection::*)(), true>::operator()<, void>(et::ClientConnection*) const (this=0x68b1f0, __object=0x67ecf0) at /usr/include/c++/5/functional:600
#5  0x00000000004458cb in std::_Bind_simple<std::_Mem_fn<void (et::ClientConnection::*)()> (et::ClientConnection*)>::_M_invoke<0ul>(std::_Index_tuple<0ul>) (this=0x68b1e8) at /usr/include/c++/5/functional:1531
#6  0x00000000004457d2 in std::_Bind_simple<std::_Mem_fn<void (et::ClientConnection::*)()> (et::ClientConnection*)>::operator()() (this=0x68b1e8) at /usr/include/c++/5/functional:1520
#7  0x0000000000445762 in std::thread::_Impl<std::_Bind_simple<std::_Mem_fn<void (et::ClientConnection::*)()> (et::ClientConnection*)> >::_M_run() (this=0x68b1d0) at /usr/include/c++/5/thread:115
#8  0x00007ffff6ad9c80 in ?? () from /usr/lib/x86_64-linux-gnu/libstdc++.so.6
#9  0x00007ffff77766ba in start_thread (arg=0x7ffff50a6700) at pthread_create.c:333
#10 0x00007ffff654882d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:109

Client logfile contents:

niko@mexico:~$ cat /tmp/etclient.INFO 
preexec - timestamp: Tue Mar 21 10:02:47 PDT 2017 - cat /tmp/etclient.INFO - 22108
Log file created at: 2017/03/21 09:55:03
Running on machine: mexico
Log line format: [IWEF]mmdd hh:mm:ss.uuuuuu threadid file:line] msg
I0321 09:55:03.357337  2817 TerminalClient.cpp:87] Sending command to set terminal to xterm-256color
I0321 09:55:03.370230  2817 UnixSocketHandler.cpp:117] Connected to server: cartagena.int.convergent.io using fd 4
I0321 09:55:51.015184  2817 TerminalClient.cpp:248] Missed a keepalive, killing connection.
I0321 09:55:51.015219  2817 ClientConnection.cpp:63] Closing socket
I0321 09:55:51.015224  2817 ClientConnection.cpp:72] Locked reconnect mutex
E0321 09:55:51.015236  2817 UnixSocketHandler.cpp:273] Tried to close a connection that doesn't exist: 4
I0321 09:55:51.015382  2817 ClientConnection.cpp:75] Socket closed.  Starting new reconnect thread
I0321 09:55:51.015630  3562 ClientConnection.cpp:94] Trying to reconnect to cartagena:2022
postexec - exit code: 0, elapsed time: .009s - cat /tmp/etclient.INFO - 22108
niko@mexico:~$ cat /tmp/et_err 
preexec - timestamp: Tue Mar 21 10:02:53 PDT 2017 - cat /tmp/et_err - 22108
E0321 09:55:51.015236  2817 UnixSocketHandler.cpp:273] Tried to close a connection that doesn't exist: 4
2949	malloc.c: No such file or directory.
postexec - exit code: 0, elapsed time: .005s - cat /tmp/et_err - 22108

[MisterTea]

Whoops, that's my fault. Fixing...

[MisterTea]

Ok try now. Sorry for all the iterations: it's hard to fix something I can't reproduce.

[NikolasOliveira]

I'll try that patch later this afternoon.
It is curious that you can't repro it with your testing. Any idea what's unique about my setup?

[MisterTea]

Not sure, I would need to know the error code you are getting to find out.

[NikolasOliveira]

We have a winner!

Thanks for chasing this down @MisterTea, I'm excited to get some real usage out of et now.

Cheers,
Niko