search

worldofbalance / wob-server

4 stars 6 forks source link

RNO server is creating two threads for one client #14

Closed jan-burianek closed 8 years ago

jan-burianek commented 8 years ago

As soon as a client is connected to a socket, 2 threads are created ID 12, 13 (my case) every request is processed by thread ID 12 but RequestRRGetMap (thread ID 13) which terminates everything because thread ID 13 is "empty".

niculistana commented 8 years ago

Hi @jan-burianek!

Could you please tell us the steps to reproduce this issue?

ilmiyoon commented 8 years ago

Yes, also please print out all the protocols received on the server. Print statement in Request.doParse()

jan-burianek commented 8 years ago

The issue may be reproduced like this:

  1. Start the game (everything is alright) - Thread 12 - player does not exist - no request
  2. Log In (everything is alright) - Thread 12 - player constructed + assigned - RequestLogin
    • parsing:
        version = DataReader.readString(dataInput).trim();
        user_id = DataReader.readString(dataInput).trim();
        password = DataReader.readString(dataInput).trim();
  1. Join race (everything is alright) - Thread 12 - player as expected - RequestRaceInit
    • parsing:
        player_id = DataReader.readInt(dataInput);
        room_id = DataReader.readInt(dataInput);
  1. Get ready - fail - Thread 13 - player does not exist (different thread) - RequestRRGetMap
    • parsing:
        // Nothing to parse;

Error statement:

Request [115] Error:
null
---
java.lang.NullPointerException
    at networking.request.RequestRRGetMap.doBusiness(RequestRRGetMap.java:32)
    at core.GameClient.run(GameClient.java:122)
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    at java.lang.Thread.run(Thread.java:745)
niculistana commented 8 years ago

@jkrubin @laisture Could you guys take a look at this as well? The more eyes the better. Thanks!

jkrubin commented 8 years ago

Sorry I haven't had time to read any code this weekend. I'll try to figure it out by Monday night

Sent from my iPhone

On Apr 9, 2016, at 2:39 PM, Nicu Listana notifications@github.com wrote:

@jkrubin @laisture Could you guys take a look at this as well? The more eyes the better. Thanks!

— You are receiving this because you were mentioned. Reply to this email directly or view it on GitHub

ilmiyoon commented 8 years ago

@rujoota @anuagg Hi server team members, can you look at this issue? Do you have any experience like this? Any clue?

anuagg commented 8 years ago

@jan-burianek Are you sure, you running the latest server and client code on your local machine? These test results are when you tried running unity code connected to server running at your local machine or remote server ( 520.something / thecity server )? See when I tried the same by running server code locally and then connecting to a client, it works fine for me. So, in my opinion issue might be that you are not getting connected with the running rhino server. Reasons might be:

  1. If you run server code on your local machine (Netbeans or intelliJ), then in client code (unity) you have to change credentials in config file (set remote-host to localhost) and in Constants file (set remote port to 20039). If any of this is not set, you'll get runtime errors.
  2. Might be some connection problems with remote server, if you are connected with a remote server

And having two threads for a single client might be a part of running rhino's code design. I think this has nothing to do with the errors you are getting.

rujoota commented 8 years ago

Hi @jan-burianek, I am also facing similar issue. I keep on getting null exception on various objects on my server. Not sure if these are because of threading issue. I tried running jar separately on different port. My config files are properly set. Tried to debug this issue, but it seems not replicating at exact same line.

ilmiyoon commented 8 years ago

@worldofbalance/server Let's have a debugging session together at class.

rujoota commented 8 years ago

Strangely enough, when I created our server in different netbeans solution and ran in parallel with wob-server, this doesn't happen.

jan-burianek commented 8 years ago

@anuagg I am 120% sure that I'm running a current server instance on my local machine and also that my client does communicate with it. If you are using some POSIX friendly OS, netstat -luntp may say a few things about your client / server interaction. I am also sure that login credentials have no impact on this issue since they are not validated by the server at all. According to me, this issue is clearly "thread based" and a solution may come to the surface only by figuring out why two threads are created instead of one. Unfortunately, it might be rooted at a very low level...

@rujoota Wow... maybe it's platform specific or it's even some another thing, I'm running the server on JDK 1.8, OS X, but I think we should not rely on the correct "random" running environment and figure out what causes this issue... I'll try some other JVM debugging tools

rujoota commented 8 years ago

@jan-burianek I am using same environment. I have a feeling that because we are using many shared classes from wob-server, it might be creating race conditions.

ilmiyoon commented 8 years ago

@jan-burianek Jan, I want to know if this happened at the old last semester code or the problem started once we restructured the server code. Then finding solution would be easier. Can you run the same tracking using the code from last year (that Jens posted) and see if it creates two thread at the same point?

jensvdh commented 8 years ago

Good idea. If you check out master you would be able to run last year's code.

jan-burianek commented 8 years ago

OK, I can make it

jan-burianek commented 8 years ago

I have something.

At first, I let the each server thread print its call stack right after the thread came to life, the result is:

RunnerItems list successfully loaded.
Server has started on port: 20039
Waiting for clients...
127.0.0.1 is connecting...
Thread ID: 14 Session ID: ae7e9807-c0f6-4f93-8d9b-006b7557b400 Thread has been just created
Stack Trace:
Timer-0:
    java.lang.Object.wait(Native Method)
    java.util.TimerThread.mainLoop(Timer.java:552)
    java.util.TimerThread.run(Timer.java:505)
main:
    java.net.PlainSocketImpl.socketAccept(Native Method)
    java.net.AbstractPlainSocketImpl.accept(AbstractPlainSocketImpl.java:404)
    java.net.ServerSocket.implAccept(ServerSocket.java:545)
    java.net.ServerSocket.accept(ServerSocket.java:513)
    core.GameServer.run(GameServer.java:226)
    core.GameServer.main(GameServer.java:367)
Abandoned connection cleanup thread:
    java.lang.Object.wait(Native Method)
    java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:142)
    java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:158)
    com.mysql.jdbc.NonRegisteringDriver$1.run(NonRegisteringDriver.java:93)
Finalizer:
    java.lang.Object.wait(Native Method)
    java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:142)
    java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:158)
    java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:209)
Reference Handler:
    java.lang.Object.wait(Native Method)
    java.lang.Object.wait(Object.java:502)
    java.lang.ref.Reference$ReferenceHandler.run(Reference.java:157)
pool-1-thread-1:
    java.lang.Thread.dumpThreads(Native Method)
    java.lang.Thread.getAllStackTraces(Thread.java:1603)
    core.GameClient.run(GameClient.java:90)
    java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
    java.util.concurrent.FutureTask.run(FutureTask.java:266)
    java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
    java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    java.lang.Thread.run(Thread.java:745)
Signal Dispatcher:
127.0.0.1 is connecting...
Thread ID: 15 Session ID: 48097013-4b4a-4c73-afcf-cbec364e6f37 Thread has been just created
Stack Trace:
pool-1-thread-2:
    java.lang.Thread.dumpThreads(Native Method)
    java.lang.Thread.getAllStackTraces(Thread.java:1603)
    core.GameClient.run(GameClient.java:90)
    java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
    java.util.concurrent.FutureTask.run(FutureTask.java:266)
    java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
    java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    java.lang.Thread.run(Thread.java:745)
Timer-0:
    java.lang.Object.wait(Native Method)
    java.util.TimerThread.mainLoop(Timer.java:552)
    java.util.TimerThread.run(Timer.java:505)
main:
    java.net.PlainSocketImpl.socketAccept(Native Method)
    java.net.AbstractPlainSocketImpl.accept(AbstractPlainSocketImpl.java:404)
    java.net.ServerSocket.implAccept(ServerSocket.java:545)
    java.net.ServerSocket.accept(ServerSocket.java:513)
    core.GameServer.run(GameServer.java:226)
    core.GameServer.main(GameServer.java:367)
Abandoned connection cleanup thread:
    java.lang.Object.wait(Native Method)
    java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:142)
    java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:158)
    com.mysql.jdbc.NonRegisteringDriver$1.run(NonRegisteringDriver.java:93)
Finalizer:
    java.lang.Object.wait(Native Method)
    java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:142)
    java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:158)
    java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:209)
Reference Handler:
    java.lang.Object.wait(Native Method)
    java.lang.Object.wait(Object.java:502)
    java.lang.ref.Reference$ReferenceHandler.run(Reference.java:157)
pool-1-thread-1:
    java.lang.System.currentTimeMillis(Native Method)
    core.GameClient.run(GameClient.java:150)
    java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
    java.util.concurrent.FutureTask.run(FutureTask.java:266)
    java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
    java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    java.lang.Thread.run(Thread.java:745)
Signal Dispatcher:
Thread ID: 14 Session ID: ae7e9807-c0f6-4f93-8d9b-006b7557b400 User ID: player does not exists
Thread ID: 14 Session ID: ae7e9807-c0f6-4f93-8d9b-006b7557b400 User ID: player does not exists
Thread ID: 14 Session ID: ae7e9807-c0f6-4f93-8d9b-006b7557b400 User ID: player does not exists
Thread ID: 14 Session ID: ae7e9807-c0f6-4f93-8d9b-006b7557b400 User ID: player does not exists
Thread ID: 14 Session ID: ae7e9807-c0f6-4f93-8d9b-006b7557b400 User ID: player does not exists
Thread ID: 14 Session ID: ae7e9807-c0f6-4f93-8d9b-006b7557b400 User ID: player does not exists
Thread ID: 14 Session ID: ae7e9807-c0f6-4f93-8d9b-006b7557b400 User ID: player does not exists
Thread ID: 14 Session ID: ae7e9807-c0f6-4f93-8d9b-006b7557b400 User ID: player does not exists
Thread ID: 14 Session ID: ae7e9807-c0f6-4f93-8d9b-006b7557b400 User ID: player does not exists
Thread ID: 14 Session ID: ae7e9807-c0f6-4f93-8d9b-006b7557b400 User ID: player does not exists
Thread ID: 14 Session ID: ae7e9807-c0f6-4f93-8d9b-006b7557b400 User ID: player does not exists
Thread ID: 14 Session ID: ae7e9807-c0f6-4f93-8d9b-006b7557b400 User ID: player does not exists
Thread ID: 14 Session ID: ae7e9807-c0f6-4f93-8d9b-006b7557b400 User ID: player does not exists
Disconnected from the target VM, address: '127.0.0.1:64946', transport: 'socket'

Process finished with exit code 130

So both threads appear to be created regularly at the same place. So I tried to track the traffic between client and server and this is a sample of the result:

      1 0.000000       127.0.0.1             127.0.0.1             TCP      56     58983 → 20039
[FIN, ACK] Seq=1 Ack=1 Win=12759 Len=0 TSval=378781082 TSecr=378564753
Frame 1: 56 bytes on wire (448 bits), 56 bytes captured (448 bits) on interface 0
Null/Loopback
Internet Protocol Version 4, Src: 127.0.0.1, Dst: 127.0.0.1
Transmission Control Protocol, Src Port: 58983 (58983), Dst Port: 20039 (20039), Seq: 1, Ack: 1,
Len: 0
      2 0.000073       127.0.0.1             127.0.0.1             TCP      56
[ACK] Seq=1 Ack=2 Win=12759 Len=0 TSval=378781082 TSecr=378781082
Frame 2: 56 bytes on wire (448 bits), 56 bytes captured (448 bits) on interface 0
Null/Loopback
Internet Protocol Version 4, Src: 127.0.0.1, Dst: 127.0.0.1
Transmission Control Protocol, Src Port: 20039 (20039), Dst Port: 58983 (58983), Seq: 1, Ack: 2,
Len: 0
      3 1.374882       127.0.0.1             127.0.0.1             TCP      68     57512 → 20039
[SYN] Seq=0 Win=65535 Len=0 MSS=16344 WS=32 TSval=378782448 TSecr=0 SACK_PERM=1
Frame 3: 68 bytes on wire (544 bits), 68 bytes captured (544 bits) on interface 0
Null/Loopback
Internet Protocol Version 4, Src: 127.0.0.1, Dst: 127.0.0.1
Transmission Control Protocol, Src Port: 57512 (57512), Dst Port: 20039 (20039), Seq: 0, Len: 0
      4 1.374980       127.0.0.1             127.0.0.1             TCP      68     20039 → 57512
[SYN, ACK] Seq=0 Ack=1 Win=65535 Len=0 MSS=16344 WS=32 TSval=378782448 TSecr=378782448
SACK_PERM=1
Frame 4: 68 bytes on wire (544 bits), 68 bytes captured (544 bits) on interface 0
Null/Loopback
Internet Protocol Version 4, Src: 127.0.0.1, Dst: 127.0.0.1
Transmission Control Protocol, Src Port: 20039 (20039), Dst Port: 57512 (57512), Seq: 0, Ack: 1,
Len: 0
      5 1.374992       127.0.0.1             127.0.0.1             TCP      56
[ACK] Seq=1 Ack=1 Win=408288 Len=0 TSval=378782448 TSecr=378782448
Frame 5: 56 bytes on wire (448 bits), 56 bytes captured (448 bits) on interface 0
Null/Loopback
Internet Protocol Version 4, Src: 127.0.0.1, Dst: 127.0.0.1
Transmission Control Protocol, Src Port: 57512 (57512), Dst Port: 20039 (20039), Seq: 1, Ack: 1,
Len: 0
      6 1.375004       127.0.0.1             127.0.0.1             TCP      56     [TCP Window
Update] 20039 → 57512 [ACK] Seq=1 Ack=1 Win=408288 Len=0 TSval=378782448 TSecr=378782448
Frame 6: 56 bytes on wire (448 bits), 56 bytes captured (448 bits) on interface 0
Null/Loopback
Internet Protocol Version 4, Src: 127.0.0.1, Dst: 127.0.0.1
Transmission Control Protocol, Src Port: 20039 (20039), Dst Port: 57512 (57512), Seq: 1, Ack: 1,
Len: 0
      7 1.459383       127.0.0.1             127.0.0.1             TCP      68     57514 → 20039
[SYN] Seq=0 Win=65535 Len=0 MSS=16344 WS=32 TSval=378782533 TSecr=0 SACK_PERM=1
Frame 7: 68 bytes on wire (544 bits), 68 bytes captured (544 bits) on interface 0
Null/Loopback
Internet Protocol Version 4, Src: 127.0.0.1, Dst: 127.0.0.1
Transmission Control Protocol, Src Port: 57514 (57514), Dst Port: 20039 (20039), Seq: 0, Len: 0
      8 1.459451       127.0.0.1             127.0.0.1             TCP      68     20039 → 57514
[SYN, ACK] Seq=0 Ack=1 Win=65535 Len=0 MSS=16344 WS=32 TSval=378782533 TSecr=378782533
SACK_PERM=1
Frame 8: 68 bytes on wire (544 bits), 68 bytes captured (544 bits) on interface 0
Null/Loopback
Internet Protocol Version 4, Src: 127.0.0.1, Dst: 127.0.0.1
Transmission Control Protocol, Src Port: 20039 (20039), Dst Port: 57514 (57514), Seq: 0, Ack: 1,
Len: 0
      9 1.459468       127.0.0.1             127.0.0.1             TCP      56
[ACK] Seq=1 Ack=1 Win=408288 Len=0 TSval=378782533 TSecr=378782533
Frame 9: 56 bytes on wire (448 bits), 56 bytes captured (448 bits) on interface 0
Null/Loopback
Internet Protocol Version 4, Src: 127.0.0.1, Dst: 127.0.0.1
Transmission Control Protocol, Src Port: 57514 (57514), Dst Port: 20039 (20039), Seq: 1, Ack: 1,
Len: 0
     10 1.459483       127.0.0.1             127.0.0.1             TCP      56     [TCP Window
Update] 20039 → 57514 [ACK] Seq=1 Ack=1 Win=408288 Len=0 TSval=378782533 TSecr=378782533
Frame 10: 56 bytes on wire (448 bits), 56 bytes captured (448 bits) on interface 0
Null/LoopbackInternet Protocol Version 4, Src: 127.0.0.1, Dst: 127.0.0.1
Transmission Control Protocol, Src Port: 20039 (20039), Dst Port: 57514 (57514), Seq: 1, Ack: 1,
Len: 0
     11 2.923715       127.0.0.1             127.0.0.1             TCP      60
[PSH, ACK] Seq=1 Ack=1 Win=408288 Len=4 TSval=378783974 TSecr=378782448
Frame 11: 60 bytes on wire (480 bits), 60 bytes captured (480 bits) on interface 0
Null/Loopback
Internet Protocol Version 4, Src: 127.0.0.1, Dst: 127.0.0.1
Transmission Control Protocol, Src Port: 57512 (57512), Dst Port: 20039 (20039), Seq: 1, Ack: 1,
Len: 4
Data (4 bytes)
0000  02 00 66 00                                       ..f.
     12 2.923743       127.0.0.1             127.0.0.1             TCP      56
[ACK] Seq=1 Ack=5 Win=408288 Len=0 TSval=378783974 TSecr=378783974
Frame 12: 56 bytes on wire (448 bits), 56 bytes captured (448 bits) on interface 0
Null/Loopback
Internet Protocol Version 4, Src: 127.0.0.1, Dst: 127.0.0.1
Transmission Control Protocol, Src Port: 20039 (20039), Dst Port: 57512 (57512), Seq: 1, Ack: 5,
Len: 0
     13 3.926834       127.0.0.1             127.0.0.1             TCP      60
[PSH, ACK] Seq=5 Ack=1 Win=408288 Len=4 TSval=378784972 TSecr=378783974
Frame 13: 60 bytes on wire (480 bits), 60 bytes captured (480 bits) on interface 0
Null/Loopback
Internet Protocol Version 4, Src: 127.0.0.1, Dst: 127.0.0.1
Transmission Control Protocol, Src Port: 57512 (57512), Dst Port: 20039 (20039), Seq: 5, Ack: 1,
Len: 4
Data (4 bytes)
0000  02 00 66 00                                       ..f.
     14 3.926858       127.0.0.1             127.0.0.1             TCP      56
[ACK] Seq=1 Ack=9 Win=408288 Len=0 TSval=378784972 TSecr=378784972
Frame 14: 56 bytes on wire (448 bits), 56 bytes captured (448 bits) on interface 0
Null/Loopback
Internet Protocol Version 4, Src: 127.0.0.1, Dst: 127.0.0.1
Transmission Control Protocol, Src Port: 20039 (20039), Dst Port: 57512 (57512), Seq: 1, Ack: 9,
Len: 0
     15 4.936892       127.0.0.1             127.0.0.1             TCP      60
[PSH, ACK] Seq=9 Ack=1 Win=408288 Len=4 TSval=378785977 TSecr=378784972
Frame 15: 60 bytes on wire (480 bits), 60 bytes captured (480 bits) on interface 0
Null/Loopback
Internet Protocol Version 4, Src: 127.0.0.1, Dst: 127.0.0.1
Transmission Control Protocol, Src Port: 57512 (57512), Dst Port: 20039 (20039), Seq: 9, Ack: 1,
Len: 4
Data (4 bytes)
0000  02 00 66 00                                       ..f.
     16 4.936928       127.0.0.1             127.0.0.1
[ACK] Seq=1 Ack=13 Win=408288 Len=0 TSval=378785977 TSecr=378785977
Frame 16: 56 bytes on wire (448 bits), 56 bytes captured (448 bits) on interface 0
Null/Loopback
Internet Protocol Version 4, Src: 127.0.0.1, Dst: 127.0.0.1
Transmission Control Protocol, Src Port: 20039 (20039), Dst Port: 57512 (57512), Seq: 1, Ack:
13, Len: 0
     17 5.939177       127.0.0.1             127.0.0.1             TCP      60
[PSH, ACK] Seq=13 Ack=1 Win=408288 Len=4 TSval=378786976 TSecr=378785977
Frame 17: 60 bytes on wire (480 bits), 60 bytes captured (480 bits) on interface 0
Null/Loopback
Internet Protocol Version 4, Src: 127.0.0.1, Dst: 127.0.0.1
Transmission Control Protocol, Src Port: 57512 (57512), Dst Port: 20039 (20039), Seq: 13, Ack:
1, Len: 4
Data (4 bytes)
0000  02 00 66 00                                       ..f.
     18 5.939199       127.0.0.1             127.0.0.1
[ACK] Seq=1 Ack=17 Win=408256 Len=0 TSval=378786976 TSecr=378786976
Frame 18: 56 bytes on wire (448 bits), 56 bytes captured (448 bits) on interface 0
Null/Loopback
Internet Protocol Version 4, Src: 127.0.0.1, Dst: 127.0.0.1
Transmission Control Protocol, Src Port: 20039 (20039), Dst Port: 57512 (57512), Seq: 1, Ack:
17, Len: 0, etc...

What is weird about this output is that (because of timing) it looks like the client is communicating with the server trough two sockets at the same time. You can see the direction at e.g. Src Port: 20039 (20039), Dst Port: 57512 and the other way Src Port: 57512 (57512), Dst Port: 20039 (20039) So it is quite likely that this is not a server issue but client may be sending two requests, for some reason I'm not familiar with so far.

jan-burianek commented 8 years ago

So there comes another mysterious issue: why and where the client is doing this and why it is sending RequestLogin and RequestRaceInit requests over another socket than the RequestRRGetMap request.

laisture commented 8 years ago

@jan-burianek I believe that it's because the RR server used to be a separate server before, and it's stil acting like it is, so my guess would be that when you send a new RequestLogin, it will notice that you are already logged in and will log you out and then try to log you in again. Please look at line 59 to 62 in RequestLogin at: https://github.com/worldofbalance/wob-server/blob/development/src/rr/net/request/RequestLogin.java

  1. if (thread != null) {
  2. responseLogin.setStatus((short) 2); // Account is in use
  3. thread.removePlayerData();
  4. thread.newSession();

This is just my guess. @ilmiyoon @niculistana @jkrubin

jan-burianek commented 8 years ago

Ultimate solution from @jan-burianek @Fito just to make it public and consistent across all the games: The thing is that if you are retrieving ConnectionManager from Unity like

RRConnectionManager cManager = gameObject.GetComponent<RRConnectionManager>();

it may return completely new instance every time (and that's bad). To avoid this issue, connection manager has to be created on one place as a Unity component:

gameObject.AddComponent<RRConnectionManager>();

and every time you need to use the ConnectionManager, it may be retrieved as a singleton instance:

RRConnectionManager cManager = RRConnectionManager.getInstance();
niculistana commented 8 years ago

@jan-burianek Good idea to making it a singleton instance. Thank you for the solution. Please update and make a pull request.