[fixed] 3.5.1: Game freezes (sigkill req'd) when network disconnects

[tomreyn]

When my ISP enforces the 24-hourly disconnect of my Internet connection, the game just freezes and I can not switch back to windowed mode, switch to a terminal  or similar. All I can do then is SSH in and kill -9 `pidof megaglest` (magic sysrq + k may work too).

[softcoder]

If possible next time get a backtrace of the program while its frozen from a terminal prompt see we can see what code is hung.

Code: [Select]

sudo gdb -q -n -ex bt -batch megaglest `pidof megaglest` | tee /tmp/test
Thanks

[tomreyn]

Sorry, that's the second time I didn't think of this myself...

Ok, here it is:

Code: [Select]

0x00007fb4f24b5143 in select () from /lib/x86_64-linux-gnu/libc.so.6
#0  0x00007fb4f24b5143 in select () from /lib/x86_64-linux-gnu/libc.so.6
#1  0x00000000007d716e in Shared::Platform::Socket::isReadable (this=0x325b450) at /home/tomreyn/SCM/megaglest-trunk/source/shared_lib/sources/platform/posix/socket.cpp:1401
#2  0x00000000007d931d in Shared::Platform::Socket::isConnected (this=0x325b450) at /home/tomreyn/SCM/megaglest-trunk/source/shared_lib/sources/platform/posix/socket.cpp:1468
#3  0x0000000000666758 in Glest::Game::ClientInterface::waitForMessage (this=0x7fb4dc0680e0) at /home/tomreyn/SCM/megaglest-trunk/source/glest_game/network/client_interface.cpp:1028
#4  0x000000000066ac31 in Glest::Game::ClientInterface::updateKeyframe (this=0x7fb4dc0680e0, frameCount=1480) at /home/tomreyn/SCM/megaglest-trunk/source/glest_game/network/client_interface.cpp:533
#5  0x00000000004e8a33 in Glest::Game::Commander::updateNetwork (this=0x7fb4dc07a270, game=<value optimized out>) at /home/tomreyn/SCM/megaglest-trunk/source/glest_game/game/commander.cpp:507
#6  0x000000000050ad27 in Glest::Game::Game::update (this=0x7fb4dc079030) at /home/tomreyn/SCM/megaglest-trunk/source/glest_game/game/game.cpp:872
#7  0x000000000057f4b8 in Glest::Game::Program::loopWorker (this=0x27b66f0) at /home/tomreyn/SCM/megaglest-trunk/source/glest_game/main/program.cpp:301
#8  0x00000000005713a6 in Glest::Game::glestMain (argc=<value optimized out>, argv=<value optimized out>) at /home/tomreyn/SCM/megaglest-trunk/source/glest_game/main/main.cpp:2932
#9  0x00000000005721d0 in glestMainWrapper (argc=1, argv=0x7fff4e63f128) at /home/tomreyn/SCM/megaglest-trunk/source/glest_game/main/main.cpp:3016
#10 main (argc=1, argv=0x7fff4e63f128) at /home/tomreyn/SCM/megaglest-trunk/source/glest_game/main/main.cpp:3038

This is what happens on the client (Client: v3.5.1-GNUC: 40502 [64bit]-Rev: 2256 player [tomreyn]): the game just freezes, consuming all available CPU resources indefinitely. User input is ignored, only kill -9 works to recover.  On the server, everything is as expected: the client is displayed as having timed out after a while.

[softcoder]

This doesn't make sense as this backtrace would not cause a hang (unless for some reason the socket was not reporting it is disconnected). IS this something that happens during normal operation or did you do something special to get this result? I cannot reproduce these results no matter how hard i try.

[tomreyn]

This happens reproducibly when I disconnect my router off the Internet (by means of clicking on 'disconnect on its web interface) or reboot it.
I did this test setup because the same thing happens when I play online and my ISP triggers a disconnection (as they do every 24 hours) during a game.

To clarify: this happens in-game, while you are already playing, not while you are in the lobby (have not tested there).

[tomreyn]

Some more backtraces taken in the same situation:

Code: [Select]

0x00007fac4076f143 in select () from /lib/x86_64-linux-gnu/libc.so.6
#0  0x00007fac4076f143 in select () from /lib/x86_64-linux-gnu/libc.so.6
#1  0x00000000007c7237 in Shared::Platform::Socket::isWritable (this=0x7fac3013fdb0) at /home/tomreyn/SCM/megaglest-trunk/source/shared_lib/sources/platform/posix/socket.cpp:1438
#2  0x00000000007c7645 in Shared::Platform::Socket::isConnected (this=0x7fac3013fdb0) at /home/tomreyn/SCM/megaglest-trunk/source/shared_lib/sources/platform/posix/socket.cpp:1463
#3  0x0000000000688928 in Glest::Game::ClientInterface::waitForMessage (this=0x7fac3016bf10) at /home/tomreyn/SCM/megaglest-trunk/source/glest_game/network/client_interface.cpp:1028
#4  0x000000000068ce01 in Glest::Game::ClientInterface::updateKeyframe (this=0x7fac3016bf10, frameCount=900) at /home/tomreyn/SCM/megaglest-trunk/source/glest_game/network/client_interface.cpp:533
#5  0x0000000000505d03 in Glest::Game::Commander::updateNetwork (this=0x7fac30238700, game=<value optimized out>) at /home/tomreyn/SCM/megaglest-trunk/source/glest_game/game/commander.cpp:507
#6  0x00000000004f2087 in Glest::Game::Game::update (this=0x7fac302374c0) at /home/tomreyn/SCM/megaglest-trunk/source/glest_game/game/game.cpp:872
#7  0x00000000005808b8 in Glest::Game::Program::loopWorker (this=0xc64d90) at /home/tomreyn/SCM/megaglest-trunk/source/glest_game/main/program.cpp:301
#8  0x0000000000579546 in Glest::Game::glestMain (argc=<value optimized out>, argv=<value optimized out>) at /home/tomreyn/SCM/megaglest-trunk/source/glest_game/main/main.cpp:2932
#9  0x000000000057a370 in glestMainWrapper (argc=1, argv=0x7fff96cb86f8) at /home/tomreyn/SCM/megaglest-trunk/source/glest_game/main/main.cpp:3016
#10 main (argc=1, argv=0x7fff96cb86f8) at /home/tomreyn/SCM/megaglest-trunk/source/glest_game/main/main.cpp:3038

0x00007fac4076f143 in select () from /lib/x86_64-linux-gnu/libc.so.6
#0  0x00007fac4076f143 in select () from /lib/x86_64-linux-gnu/libc.so.6
#1  0x00000000007c507a in hasDataToRead (this=<value optimized out>) at /home/tomreyn/SCM/megaglest-trunk/source/shared_lib/sources/platform/posix/socket.cpp:973
#2  Shared::Platform::Socket::hasDataToRead (this=<value optimized out>) at /home/tomreyn/SCM/megaglest-trunk/source/shared_lib/sources/platform/posix/socket.cpp:950
#3  0x000000000068401d in Glest::Game::NetworkInterface::getNextMessageType (this=0x7fac3016bf10, checkHasDataFirst=true) at /home/tomreyn/SCM/megaglest-trunk/source/glest_game/network/network_interface.cpp:55
#4  0x000000000068889d in Glest::Game::ClientInterface::waitForMessage (this=0x7fac3016bf10) at /home/tomreyn/SCM/megaglest-trunk/source/glest_game/network/client_interface.cpp:1026
#5  0x000000000068ce01 in Glest::Game::ClientInterface::updateKeyframe (this=0x7fac3016bf10, frameCount=900) at /home/tomreyn/SCM/megaglest-trunk/source/glest_game/network/client_interface.cpp:533
#6  0x0000000000505d03 in Glest::Game::Commander::updateNetwork (this=0x7fac30238700, game=<value optimized out>) at /home/tomreyn/SCM/megaglest-trunk/source/glest_game/game/commander.cpp:507
#7  0x00000000004f2087 in Glest::Game::Game::update (this=0x7fac302374c0) at /home/tomreyn/SCM/megaglest-trunk/source/glest_game/game/game.cpp:872
#8  0x00000000005808b8 in Glest::Game::Program::loopWorker (this=0xc64d90) at /home/tomreyn/SCM/megaglest-trunk/source/glest_game/main/program.cpp:301
#9  0x0000000000579546 in Glest::Game::glestMain (argc=<value optimized out>, argv=<value optimized out>) at /home/tomreyn/SCM/megaglest-trunk/source/glest_game/main/main.cpp:2932
#10 0x000000000057a370 in glestMainWrapper (argc=1, argv=0x7fff96cb86f8) at /home/tomreyn/SCM/megaglest-trunk/source/glest_game/main/main.cpp:3016
#11 main (argc=1, argv=0x7fff96cb86f8) at /home/tomreyn/SCM/megaglest-trunk/source/glest_game/main/main.cpp:3038

0x00007fac4076f143 in select () from /lib/x86_64-linux-gnu/libc.so.6
#0  0x00007fac4076f143 in select () from /lib/x86_64-linux-gnu/libc.so.6
#1  0x00000000007c507a in hasDataToRead (this=<value optimized out>) at /home/tomreyn/SCM/megaglest-trunk/source/shared_lib/sources/platform/posix/socket.cpp:973
#2  Shared::Platform::Socket::hasDataToRead (this=<value optimized out>) at /home/tomreyn/SCM/megaglest-trunk/source/shared_lib/sources/platform/posix/socket.cpp:950
#3  0x000000000068401d in Glest::Game::NetworkInterface::getNextMessageType (this=0x7fac3016bf10, checkHasDataFirst=true) at /home/tomreyn/SCM/megaglest-trunk/source/glest_game/network/network_interface.cpp:55
#4  0x000000000068889d in Glest::Game::ClientInterface::waitForMessage (this=0x7fac3016bf10) at /home/tomreyn/SCM/megaglest-trunk/source/glest_game/network/client_interface.cpp:1026
#5  0x000000000068ce01 in Glest::Game::ClientInterface::updateKeyframe (this=0x7fac3016bf10, frameCount=900) at /home/tomreyn/SCM/megaglest-trunk/source/glest_game/network/client_interface.cpp:533
#6  0x0000000000505d03 in Glest::Game::Commander::updateNetwork (this=0x7fac30238700, game=<value optimized out>) at /home/tomreyn/SCM/megaglest-trunk/source/glest_game/game/commander.cpp:507
#7  0x00000000004f2087 in Glest::Game::Game::update (this=0x7fac302374c0) at /home/tomreyn/SCM/megaglest-trunk/source/glest_game/game/game.cpp:872
#8  0x00000000005808b8 in Glest::Game::Program::loopWorker (this=0xc64d90) at /home/tomreyn/SCM/megaglest-trunk/source/glest_game/main/program.cpp:301
#9  0x0000000000579546 in Glest::Game::glestMain (argc=<value optimized out>, argv=<value optimized out>) at /home/tomreyn/SCM/megaglest-trunk/source/glest_game/main/main.cpp:2932
#10 0x000000000057a370 in glestMainWrapper (argc=1, argv=0x7fff96cb86f8) at /home/tomreyn/SCM/megaglest-trunk/source/glest_game/main/main.cpp:3016
#11 main (argc=1, argv=0x7fff96cb86f8) at /home/tomreyn/SCM/megaglest-trunk/source/glest_game/main/main.cpp:3038

0x00007fac4076f143 in select () from /lib/x86_64-linux-gnu/libc.so.6
#0  0x00007fac4076f143 in select () from /lib/x86_64-linux-gnu/libc.so.6
#1  0x00000000007c7237 in Shared::Platform::Socket::isWritable (this=0x7fac3013fdb0) at /home/tomreyn/SCM/megaglest-trunk/source/shared_lib/sources/platform/posix/socket.cpp:1438
#2  0x00000000007c7645 in Shared::Platform::Socket::isConnected (this=0x7fac3013fdb0) at /home/tomreyn/SCM/megaglest-trunk/source/shared_lib/sources/platform/posix/socket.cpp:1463
#3  0x0000000000688928 in Glest::Game::ClientInterface::waitForMessage (this=0x7fac3016bf10) at /home/tomreyn/SCM/megaglest-trunk/source/glest_game/network/client_interface.cpp:1028
#4  0x000000000068ce01 in Glest::Game::ClientInterface::updateKeyframe (this=0x7fac3016bf10, frameCount=900) at /home/tomreyn/SCM/megaglest-trunk/source/glest_game/network/client_interface.cpp:533
#5  0x0000000000505d03 in Glest::Game::Commander::updateNetwork (this=0x7fac30238700, game=<value optimized out>) at /home/tomreyn/SCM/megaglest-trunk/source/glest_game/game/commander.cpp:507
#6  0x00000000004f2087 in Glest::Game::Game::update (this=0x7fac302374c0) at /home/tomreyn/SCM/megaglest-trunk/source/glest_game/game/game.cpp:872
#7  0x00000000005808b8 in Glest::Game::Program::loopWorker (this=0xc64d90) at /home/tomreyn/SCM/megaglest-trunk/source/glest_game/main/program.cpp:301
#8  0x0000000000579546 in Glest::Game::glestMain (argc=<value optimized out>, argv=<value optimized out>) at /home/tomreyn/SCM/megaglest-trunk/source/glest_game/main/main.cpp:2932
#9  0x000000000057a370 in glestMainWrapper (argc=1, argv=0x7fff96cb86f8) at /home/tomreyn/SCM/megaglest-trunk/source/glest_game/main/main.cpp:3016
#10 main (argc=1, argv=0x7fff96cb86f8) at /home/tomreyn/SCM/megaglest-trunk/source/glest_game/main/main.cpp:3038

#0  0x00007fac4076f143 in select () from /lib/x86_64-linux-gnu/libc.so.6
#1  0x00000000007c7237 in Shared::Platform::Socket::isWritable (this=0x7fac3013fdb0) at /home/tomreyn/SCM/megaglest-trunk/source/shared_lib/sources/platform/posix/socket.cpp:1438
#2  0x00000000007c7645 in Shared::Platform::Socket::isConnected (this=0x7fac3013fdb0) at /home/tomreyn/SCM/megaglest-trunk/source/shared_lib/sources/platform/posix/socket.cpp:1463
#3  0x0000000000688928 in Glest::Game::ClientInterface::waitForMessage (this=0x7fac3016bf10) at /home/tomreyn/SCM/megaglest-trunk/source/glest_game/network/client_interface.cpp:1028
#4  0x000000000068ce01 in Glest::Game::ClientInterface::updateKeyframe (this=0x7fac3016bf10, frameCount=900) at /home/tomreyn/SCM/megaglest-trunk/source/glest_game/network/client_interface.cpp:533
#5  0x0000000000505d03 in Glest::Game::Commander::updateNetwork (this=0x7fac30238700, game=<value optimized out>) at /home/tomreyn/SCM/megaglest-trunk/source/glest_game/game/commander.cpp:507
#6  0x00000000004f2087 in Glest::Game::Game::update (this=0x7fac302374c0) at /home/tomreyn/SCM/megaglest-trunk/source/glest_game/game/game.cpp:872
#7  0x00000000005808b8 in Glest::Game::Program::loopWorker (this=0xc64d90) at /home/tomreyn/SCM/megaglest-trunk/source/glest_game/main/program.cpp:301
#8  0x0000000000579546 in Glest::Game::glestMain (argc=<value optimized out>, argv=<value optimized out>) at /home/tomreyn/SCM/megaglest-trunk/source/glest_game/main/main.cpp:2932
#9  0x000000000057a370 in glestMainWrapper (argc=1, argv=0x7fff96cb86f8) at /home/tomreyn/SCM/megaglest-trunk/source/glest_game/main/main.cpp:3016
#10 main (argc=1, argv=0x7fff96cb86f8) at /home/tomreyn/SCM/megaglest-trunk/source/glest_game/main/main.cpp:3038

0x00007fac4330b412 in pthread_mutex_lock () from /lib/x86_64-linux-gnu/libpthread.so.0
#0  0x00007fac4330b412 in pthread_mutex_lock () from /lib/x86_64-linux-gnu/libpthread.so.0
#1  0x00007fac4357248e in SDL_mutexP () from /usr/lib/libSDL-1.2.so.0
#2  0x00000000007bd47e in Shared::Platform::Mutex::p (this=0x7fac3013fe58) at /home/tomreyn/SCM/megaglest-trunk/source/shared_lib/sources/platform/sdl/thread.cpp:117
#3  0x00000000007c6ffc in Lock (this=0x7fac3013fdb0) at /home/tomreyn/SCM/megaglest-trunk/source/shared_lib/include/platform/sdl/thread.h:124
#4  MutexSafeWrapper (this=0x7fac3013fdb0) at /home/tomreyn/SCM/megaglest-trunk/source/shared_lib/include/platform/sdl/thread.h:97
#5  Shared::Platform::Socket::isWritable (this=0x7fac3013fdb0) at /home/tomreyn/SCM/megaglest-trunk/source/shared_lib/sources/platform/posix/socket.cpp:1429
#6  0x00000000007c7645 in Shared::Platform::Socket::isConnected (this=0x7fac3013fdb0) at /home/tomreyn/SCM/megaglest-trunk/source/shared_lib/sources/platform/posix/socket.cpp:1463
#7  0x0000000000688928 in Glest::Game::ClientInterface::waitForMessage (this=0x7fac3016bf10) at /home/tomreyn/SCM/megaglest-trunk/source/glest_game/network/client_interface.cpp:1028
#8  0x000000000068ce01 in Glest::Game::ClientInterface::updateKeyframe (this=0x7fac3016bf10, frameCount=900) at /home/tomreyn/SCM/megaglest-trunk/source/glest_game/network/client_interface.cpp:533
#9  0x0000000000505d03 in Glest::Game::Commander::updateNetwork (this=0x7fac30238700, game=<value optimized out>) at /home/tomreyn/SCM/megaglest-trunk/source/glest_game/game/commander.cpp:507
#10 0x00000000004f2087 in Glest::Game::Game::update (this=0x7fac302374c0) at /home/tomreyn/SCM/megaglest-trunk/source/glest_game/game/game.cpp:872
#11 0x00000000005808b8 in Glest::Game::Program::loopWorker (this=0xc64d90) at /home/tomreyn/SCM/megaglest-trunk/source/glest_game/main/program.cpp:301
#12 0x0000000000579546 in Glest::Game::glestMain (argc=<value optimized out>, argv=<value optimized out>) at /home/tomreyn/SCM/megaglest-trunk/source/glest_game/main/main.cpp:2932
#13 0x000000000057a370 in glestMainWrapper (argc=1, argv=0x7fff96cb86f8) at /home/tomreyn/SCM/megaglest-trunk/source/glest_game/main/main.cpp:3016
#14 main (argc=1, argv=0x7fff96cb86f8) at /home/tomreyn/SCM/megaglest-trunk/source/glest_game/main/main.cpp:3038

0x00007fac407092ca in ?? () from /lib/x86_64-linux-gnu/libc.so.6
#0  0x00007fac407092ca in ?? () from /lib/x86_64-linux-gnu/libc.so.6
#1  0x00007fac4070d8e3 in free () from /lib/x86_64-linux-gnu/libc.so.6
#2  0x00007fac40f5d019 in std::basic_string<char, std::char_traits<char>, std::allocator<char> >::~basic_string() () from /usr/lib/x86_64-linux-gnu/libstdc++.so.6
#3  0x00000000007c7210 in Shared::Platform::Socket::isWritable (this=0x7fac3013fdb0) at /home/tomreyn/SCM/megaglest-trunk/source/shared_lib/sources/platform/posix/socket.cpp:1437
#4  0x00000000007c7645 in Shared::Platform::Socket::isConnected (this=0x7fac3013fdb0) at /home/tomreyn/SCM/megaglest-trunk/source/shared_lib/sources/platform/posix/socket.cpp:1463
#5  0x0000000000688928 in Glest::Game::ClientInterface::waitForMessage (this=0x7fac3016bf10) at /home/tomreyn/SCM/megaglest-trunk/source/glest_game/network/client_interface.cpp:1028
#6  0x000000000068ce01 in Glest::Game::ClientInterface::updateKeyframe (this=0x7fac3016bf10, frameCount=900) at /home/tomreyn/SCM/megaglest-trunk/source/glest_game/network/client_interface.cpp:533
#7  0x0000000000505d03 in Glest::Game::Commander::updateNetwork (this=0x7fac30238700, game=<value optimized out>) at /home/tomreyn/SCM/megaglest-trunk/source/glest_game/game/commander.cpp:507
#8  0x00000000004f2087 in Glest::Game::Game::update (this=0x7fac302374c0) at /home/tomreyn/SCM/megaglest-trunk/source/glest_game/game/game.cpp:872
#9  0x00000000005808b8 in Glest::Game::Program::loopWorker (this=0xc64d90) at /home/tomreyn/SCM/megaglest-trunk/source/glest_game/main/program.cpp:301
#10 0x0000000000579546 in Glest::Game::glestMain (argc=<value optimized out>, argv=<value optimized out>) at /home/tomreyn/SCM/megaglest-trunk/source/glest_game/main/main.cpp:2932
#11 0x000000000057a370 in glestMainWrapper (argc=1, argv=0x7fff96cb86f8) at /home/tomreyn/SCM/megaglest-trunk/source/glest_game/main/main.cpp:3016
#12 main (argc=1, argv=0x7fff96cb86f8) at /home/tomreyn/SCM/megaglest-trunk/source/glest_game/main/main.cpp:3038

This time I was playing on my LAN with my desktop hosting (connected to router via wired network) and my laptop being the client (connected via wireless).

[softcoder]

Please turn on network debugging and reproduce this and paste the logs (I'll also try to reproduce based on this info in the meantime)

*UPDATE: Fixed in svn rev #2260

[tomreyn]

This is great! The client nicely detects the disconnected state now (and no longer freezes).

Of course, being a good QA guy, I'm never satisfied:

While this is now fixed, the server (which never froze and still doesn't) does not seem to realise that the client has disconnected and is not going to return anytime soon. :/
The server keeps thinking that the client is just lagging even after the network view (hotkey 'n') lists this client as: 0 [601.00]  (which I think is > 10 minutes). What I do to cause this situation is to disconnect the client (my laptop) of the wireless (its only upstream).

If, however, I reconnect the client to the wireless LAN later, run the game and search for LAN servers, then the server which so far thought the client was still connected realises the client is actually no longer connected and formally disconnects it. But apparently until it receives such notification it will just happily count the lag to values higher than "0 [601.00]", which seems to be too much...

[softcoder]

Because the socket layer did not receive a proper disconnect (a very controversial subject all over the net) we kept on going. To help deal more practically with this i added a max time ever lag value of 45 seconds (that 601 was seconds behind the client is). Now at 45 or more seconds behind the server, the server will disconnect those clients using svn rev #2261

[tomreyn]

I just tried this after updating both client and server to #2262 but after I deactivate the clients' network interface and after the client detects that it was disconnected, the server keeps counting and does not detect that the client has serious connectivity issues. I cancelled when it was at "1 [121]", i.e. after 121 seconds.

I'll redo this with clean builds on server + client and with network + debug logs enabled shortly.

[tomreyn]

OK, the rebuilt is done, and this issue still occurs. The servers' and the clients' logs are now ready.

[tomreyn]

For what it's worth, r2263 is still affected by this.

[will]

In the scenario described - its equiv to the cable being cut and all tcp connections will just buffer until timeout (default 270 minutes iirc) - will cause select to just hang.

All io should be nonblocking, or in thread with short timeout.

Are we really doing io synchronosuly in the game thread?

[softcoder]

Should be fixed (yes the networking is threaded, however the client will 'freeze' for up to 10 seconds to wait for packets from the server before it drops).

[tomreyn]

It's fixed for me. Thanks!