Unknown softlock, possibly related to unresolved #40

[ghost]

Issue type: problem

Description:

During a Draft Pick game between Pwntagonist (host) and Krabble Krauser, their game experienced a softlock after both players finished drafting and outfitting their teams. They thought the game froze and was completely unresponsive. I suggested Pwntagonist use FEServer's Kick All to see if it indeed was a freeze (unresponsiveness), or instead a softlock (inability to progress). Using Kick All proved the application was still responsive to both players as they were successfully kicked.

Pwntagonist managed to procure the following logs and thinks it might be due to his suspect internet connection.

I believe the first log may give us a major insight as to what's causing the softlocks (observed in still unresolved #40 which most likely needs a new title) that players with poor internet connections such as my GF Sarah experience regularly.

---

Examples:

java.net.SocketTimeoutException: Read timed out
    at java.net.SocketInputStream.socketRead0(Native Method)
    at java.net.SocketInputStream.socketRead(Unknown Source)
    at java.net.SocketInputStream.read(Unknown Source)
    at java.net.SocketInputStream.read(Unknown Source)
    at java.net.SocketInputStream.read(Unknown Source)
    at java.io.ObjectInputStream$PeekInputStream.peek(Unknown Source)
    at java.io.ObjectInputStream$BlockDataInputStream.peek(Unknown Source)
    at java.io.ObjectInputStream$BlockDataInputStream.peekByte(Unknown Source)
    at java.io.ObjectInputStream.readObject0(Unknown Source)
    at java.io.ObjectInputStream.readObject(Unknown Source)
    at net.fe.network.ServerListener.run(ServerListener.java:87)

AND

java.io.EOFException
    at java.io.ObjectInputStream$BlockDataInputStream.peekByte(Unknown Source)
    at java.io.ObjectInputStream.readObject0(Unknown Source)
    at java.io.ObjectInputStream.readObject(Unknown Source)
    at net.fe.network.ServerListener.run(ServerListener.java:87)

[HamaIndustries]

It looks like they reached a timeout, which in turn truncated the file sent and led to an EOF. I wonder if it's the filesize that causes the timeout, or the length of time they spend drafting. How many times has this happened?

@rayrobdod Since you've modified the network, do you think this is plausible, and would a larger timeout help?

[ghost]

It's only sending text though, correct? I doubt the filesize can be an issue, otherwise I can only imagine games on a much larger scale, like MMOs being technologically impossible.

Honestly, I can't think of anything causing a timeout aside from a poor connection, temperamental firewall, or dropped packet. Is the timeout duration manually defined? Perhaps we should increase the time allowed before the application gives up?

This is only the second time I've heard of this particular error in the logs, the second one being on the sub earlier today. So I'm not sure how often this occurs in the wild. Sarah's internet has been so abominable that I haven't even attempted a game with her recently, though probably I should to see if the result is a similar log now that logs are more verbose.

I'm tagging @rayrobdod and @Purplemandown so we have all hands on deck for additional insight on this. These softlocks need to stop, ideally before the next tourney - I don't want a repeat of our 2nd tournament.

[HamaIndustries]

Keep in mind, we've only seen this after the 1.5 patch, so it would be a good idea to look into those changes first.

[ghost]

1.5 is also the first public release with verbose logging. Awareness doesn't equal suspect. The softlocks have been a thing for some time now though. The only time I've personally experienced softlocks were with Sarah (other games with other players prior to 1.5 have helped me uncover crashes exclusively. The few 1.5 games I've played / spectated went fine), but it's a known fact that her wi-fi is the poster child for instability. These softlocks have been a thing since I joined the project, which is why #40 exists and was such an early bug.

I should do some tests with her to see if I can produce a log with similar output, just not sure when I'll get to it since I'm running on burnout as always.

[Purplemandown]

Looking at this again, I don't think that the softlock problem is an issue of tcp vs. udp. I think Java's sockets might just be on a timeout/the JVM is closing connections (even though it isn't supposed to). Could we fix this by putting all the command sends in trys, and opening a new connection if it catches a EOFException or SocketTimeoutException? (I didn't look at much of the netcode, so this is assuming that it's not doing this now)

[ghost]

@rayrobdod would be most familiar with the netcode, I think, given the overhaul to it during 1.5. @rayrobdod can you confirm @Purplemandown 's theory? If not, is there any particular test I can perform to confirm it?

Meanwhile, can anyone tell me if there's a way for us to handle intermittent wi-fi connections so that the game state doesn't softlock or otherwise become irrepairable in the event someone's wi-fi cuts out momentarily?

[ghost]

@rayrobdod @eliatlarge @Purplemandown I'm also beginning to wonder if there's a difference between LAN games via localhost and WAN games via entering a public IP address.

When using my public IP instead of localhost to playtest something, I triggered a softlock where the game state went out of sync.

Logs show no signs of errors, nothing like the logs supplied here. Using the "Kick All" button only kicked one of the clients. The other client remained responsive to user input but unresponsive to FEServer.

GameState-Desync-Softlock.zip

You'll notice in client_log_2016-06-22@19-43-49.887.log that it did not receive the kick signal, nor the battle between Dart and Oswin. It should be noted that this was while testing PR #117 , however I can't see that being the cause.

Speaking of these logs, can someone explain to me what the difference between FINE and FINER are in the server logs? Also seems a bit confusing to read lately.

[rayrobdod]

The code doesn't do what @Purplemandown suggests; it could help, but I've yet to see anything specific that indicates that it would help.

There is barely any difference between "FINER" and "FINE" (or even between those and "INFO" or "WARNING"). It's a part of the framework that allows a subset of messages to be turned off, but there's no need to take advantage of that and I thought I was only using one of them.