Tasharen Entertainment Forum

Support => TNet 3 Support => Topic started by: gg67 on June 22, 2014, 09:58:40 PM

Title: TNet/RFC Debugging
Post by: gg67 on June 22, 2014, 09:58:40 PM
I'm running into some hard to reproduce networking bugs, mostly things like people getting booted from the channel (not timing out according to the server) that don't give me any debug output. My hunch is has things to do with people joining rooms, waiting for the room to load (we have some environments being downloaded from the web), RFC calls be fired and received, but then they leave and try again b/c the screen is frozen, etc.

What's the best way to watch all the RFC calls going around? Idk if anybody has experience debugging these issues that don't spit out errors and are hard to reproduce. Any advice would be appreciated!!
Title: Re: TNet/RFC Debugging
Post by: ArenMook on June 22, 2014, 10:27:01 PM
If it takes a while to load the level, then the player may get booted from the server due to inactivity. The server boots players after 10 seconds of no messages. You can change this by having players call TNManager.SetTimeout prior to loading the level.
Title: Re: TNet/RFC Debugging
Post by: gg67 on June 22, 2014, 11:55:57 PM
I've had our timeout at 60 seconds since our game is okay with inactivity. And if the player were to be booted bc of that, would the server log that as a "timeout"? Instead its just a disconnect. And it's one players are inside the room and everything is loaded.

Players join the channel, load the room, everything is fine. Then poof! They are disconnected from server.
Title: Re: TNet/RFC Debugging
Post by: ArenMook on June 23, 2014, 12:00:12 AM
Yeah that sounds unusual. I would suggest adding some extra debugging to the server side where it sends the Disconnect message. TNet never boots anyone without a cause, there is always a packet that gets sent first. It can happen if an error occurs.
Title: Re: TNet/RFC Debugging
Post by: gg67 on June 23, 2014, 08:21:33 AM
So like when the server receives the Disconnect packet, I print out what debug data? I haven't spend a ton of time playing and tweaking the server side of TNet so I'm not totally sure how to go about doing this.

Thanks!
Title: Re: TNet/RFC Debugging
Post by: gg67 on June 23, 2014, 09:54:30 PM
I'm seeing a lot of this error. I'm about to pull your new changes from github.

EndOfStreamException: Failed to read past end of stream.
  at System.IO.BinaryReader.ReadByte () [0x00000] in <filename unknown>:0
  at TNManager.CreateGameObject (UnityEngine.GameObject prefab, System.IO.BinaryReader reader) [0x00000] in <filename unknown>:0
  at TNManager.OnCreateObject (Int32 creator, Int32 index, UInt32 objectID, System.IO.BinaryReader reader) [0x00000] in <filename unknown>:0
  at TNet.GameClient.ProcessPacket (TNet.Buffer buffer, System.Net.IPEndPoint ip) [0x00000] in <filename unknown>:0
  at TNet.GameClient.ProcessPackets () [0x00000] in <filename unknown>:0
  at TNManager.Update () [0x00000] in <filename unknown>:0


Update 1 - Updating TNet on server and client seemed to fix things at the moment. In fact, restarting the executable on the server seems to fix things for a bit, then they get hectic again. The longer the server is up, the more channel open, closed, joined, left, things start getting bad. How are RFCs stored when they are saved? Do they go away when a channel is closed? Is there some way they could get crossed? And what's the best way to monitor what RFCs are saved?
Title: Re: TNet/RFC Debugging
Post by: ArenMook on June 24, 2014, 07:33:11 AM
RFCs disappear when the last player leaves the channel.

Judging by the stack trace, it received an object creation packet, but doesn't have a byte ID for what type of an object this is?

The structure of a Create packet is always rigid at the beginning:
- int: ID of the player that requested this object to be created.
- ushort: Index of the object being created (within a static list of prefabs on the client).
- uint32: Unique Identifier (aka Object ID) if requested, 0 otherwise. 0-16777215 range.
...followed by arbitrary amount of data.

This arbitrary data is expected to contain 1 byte for the type identifier, followed by function parameters. It looks like in your case you are getting a Create call with no identifier somehow. I'd love to know how that happens.

P.S. Delete the server.dat file.

P.P.S. Try to catch when this happens on the server. TNGameServer.cs, ProcessChannelPacket function around line 1258 is where the Packet.ResponseCreate gets sent. The "if (buffer.size > 0)" check below is what you're looking for. Debug break if it's zero.
Title: Re: TNet/RFC Debugging
Post by: gg67 on June 24, 2014, 08:00:02 AM
I've never deleted the server.dat file because I never wrote or read to it. Does TNet automatically do this behind the scenes?
Title: Re: TNet/RFC Debugging
Post by: ArenMook on June 24, 2014, 08:05:28 AM
Yup. All persistent data is saved there.
Title: Re: TNet/RFC Debugging
Post by: gg67 on June 24, 2014, 08:20:00 AM
Does persistent data include any data in a non persistent room? I don't create persistent rooms either.

Although deleting it may actually be helping. I noticed when I pulled you repo to the server last night everything seemed to work smoothly, even when restarting the server script didn't help.
Title: Re: TNet/RFC Debugging
Post by: ArenMook on June 24, 2014, 08:24:13 AM
It depends on when the save gets initiated. The server can be saved while it's running, for example -- which will just fully save its current state. It's very important to delete it every time the server/client code gets updated.
Title: Re: TNet/RFC Debugging
Post by: gg67 on June 24, 2014, 10:59:30 AM
1. Will deleting the server.dat while the server is running cause issues? Or will I need to restart it?

2. This is bizarre. I've had this issue since I first got TNet and have finally found out what's going on. Let's say I'm syncing player's positions 15 times a second via UDP.

What in the world is happening? It seems like the initial packets are over flowing from channel to channel.
Note: This only happens to the first player to join a channel and when other people join (usually only the second player to join).

UPDATE: After hours of debugging, I decided to include the channelID in the RFC call to update player position. Turns out, the very first packet in the new room is from the old channel. Do I need to call LeaveChannel before I call JoinChannel? I'm using the same packet ordering methods you use in your TNet Space Fighter Game kit.

Quick Fix: I kept the channelID in the RFC call and just ignored any packets where the packet's channel ID and TNMangaer.channelID didn't match.

3. Do saved RFCs from a player get removed when that player leaves the channel?
Title: Re: TNet/RFC Debugging
Post by: ArenMook on June 25, 2014, 08:01:47 AM
1. You need to restart it. Stop the server, delete the dat file, and start it back up.

2. That's a good work-around, and that's the downside of using UDP. Packets may arrive in the wrong order as they are not consecutive like with TCP.

3. That depends. Will the player's objects be removed? If it was created with a persistent flag, then no. RFCs are only removed if their TNObject is removed.
Title: Re: TNet/RFC Debugging
Post by: gg67 on June 25, 2014, 09:46:27 AM
2. I only need to worry about this when using UDP packets, yes? Will TCP be okay?

And thanks!
Title: Re: TNet/RFC Debugging
Post by: gg67 on June 25, 2014, 11:13:54 PM
Where would i want to look if everybody is disconnected from the server a few at a time and then a whole bunch of people get kicked? Does the server ever tell the client to disconnect? What about vice versa? When does this happen?

Ran into this issue again tonight w/ around 20 people in a channel. Happened after 30 minutes and then people couldn't even connect to server. Restarted server and all was well for about 30 minutes and then happened again. What could kick someone from server and then not let them reconnect?

And the worst part is I can't reproduce reliably...so i can't debug properly. So frustrating :(
Title: Re: TNet/RFC Debugging
Post by: ArenMook on June 26, 2014, 11:56:15 AM
The server won't tell the clients to disconnect, but it may disconnect them if they sent bad data.

Off the top of my head, nothing would kick someone off and not let them reconnect. TNet doesn't have a blacklist. I can only suggest running the server in debug (from visual studio) and logging the packets that arrive.
Title: Re: TNet/RFC Debugging
Post by: gg67 on July 09, 2014, 09:14:50 PM
Just experienced a mass disconnect of all players in a channel. I managed to snag a log from one of them and figured out where Close() is called on the client by putting Logs everywhere. Logs printed in this order:

  1. ProcessBuffer called close(true)
  2.  
  3. OnReceive called Close(true) 3
  4.  
  5. Close called w/ notify: True
  6.  
  7. Received Packet.Disconnect from Server.
  8.  



Here are where those were printed.

In TNTcpProtocol.cs ~line 588 UnityEngine.Debug.Log ("OnReceive called Close(true) 3");
In TNTcpProtocol.cs ~line 617 "UnityEngine.Debug.Log ("ProcessBuffer called close(true)")


  1.        
  2. void OnReceive (IAsyncResult result)
  3.         {
  4.                 if (stage == Stage.NotConnected) return;
  5.                 int bytes = 0;
  6.  
  7.                 try
  8.                 {
  9.                         bytes = mSocket.EndReceive(result);
  10.                 }
  11.                 catch (System.Exception ex)
  12.                 {
  13.                         Error(ex.Message);
  14.                         Disconnect();
  15.                         return;
  16.                 }
  17.                 lastReceivedTime = DateTime.Now.Ticks / 10000;
  18.  
  19.                 if (bytes == 0)
  20.                 {
  21.                         UnityEngine.Debug.Log ("OnReceive called Close(true) 1");
  22.                         Close(true);
  23.                 }
  24.                 else if (ProcessBuffer(bytes))
  25.                 {
  26.                         if (stage == Stage.NotConnected) return;
  27.  
  28.                         try
  29.                         {
  30.                                 // Queue up the next read operation
  31.                                 mSocket.BeginReceive(mTemp, 0, mTemp.Length, SocketFlags.None, OnReceive, null);
  32.                         }
  33.                         catch (System.Exception ex)
  34.                         {
  35.                                 Error(ex.Message);
  36.                                 UnityEngine.Debug.Log ("OnReceive called Close(false) 2");
  37.                                 Close(false);
  38.                         }
  39.                 }
  40.                 else
  41.                 {
  42.                         UnityEngine.Debug.Log ("OnReceive called Close(true) 3");
  43.                         Close(true);
  44.                 }
  45.         }
  46.  
  47.         /// <summary>
  48.         /// See if the received packet can be processed and split it up into different ones.
  49.         /// </summary>
  50.  
  51.         bool ProcessBuffer (int bytes)
  52.         {
  53.                 if (mReceiveBuffer == null)
  54.                 {
  55.                         // Create a new packet buffer
  56.                         mReceiveBuffer = Buffer.Create();
  57.                         mReceiveBuffer.BeginWriting(false).Write(mTemp, 0, bytes);
  58.                 }
  59.                 else
  60.                 {
  61.                         // Append this data to the end of the last used buffer
  62.                         mReceiveBuffer.BeginWriting(true).Write(mTemp, 0, bytes);
  63.                 }
  64.  
  65.                 for (int available = mReceiveBuffer.size - mOffset; available >= 4; )
  66.                 {
  67.                         // Figure out the expected size of the packet
  68.                         if (mExpected == 0)
  69.                         {
  70.                                 mExpected = mReceiveBuffer.PeekInt(mOffset);
  71.  
  72.                                 if (mExpected < 0 || mExpected > 16777216)
  73.                                 {
  74.                                         Close(true);
  75.                                         UnityEngine.Debug.Log ("ProcessBuffer called close(true)");
  76.                                         return false;
  77.                                 }
  78.                         }
  79.  


In TNGameClient.cs ProcessPacket() case Packet.Disconnect  is hit.

Any idea what's going on?
Title: Re: TNet/RFC Debugging
Post by: ArenMook on July 10, 2014, 07:44:13 PM
If "else Close(true);" is hit, then ProcessBuffer returned 'false', meaning the packet was not able to be processed. Looking at the function, that only happens in one place:
  1.                         // Figure out the expected size of the packet
  2.                         if (mExpected == 0)
  3.                         {
  4.                                 mExpected = mReceiveBuffer.PeekInt(mOffset);
  5.  
  6.                                 if (mExpected < 0 || mExpected > 16777216)
  7.                                 {
  8.                                         Close(true);
  9.                                         return false;
  10.                                 }
  11.                         }
So TNet checks the incoming buffer, and the expected number of bytes for the packet is invalid, indicating a malformed packet. Question is, how did it get to that? And why would everyone be disconnected? If anything, a single player's bad buffer should only disconect that player, not everyone.
Title: Re: TNet/RFC Debugging
Post by: gg67 on July 16, 2014, 10:37:17 PM
Ran into the same issue again tonight. We had 15 people all singing "Happy Birthday" and sending UDP voice every which way . Had a couple cases where the expected number of bytes is invalid, where we hit

  1. if (mExpected < 0 || mExpected > 16777216)
  2.  

and also ran into one where bytes == 0.

  1.         void OnReceive (IAsyncResult result)
  2.         {
  3.                 if (stage == Stage.NotConnected) return;
  4.                 int bytes = 0;
  5.  
  6.                 try
  7.                 {
  8.                         bytes = mSocket.EndReceive(result);
  9.                 }
  10.                 catch (System.Exception ex)
  11.                 {
  12.                         Error(ex.Message);
  13.                         Disconnect();
  14.                         return;
  15.                 }
  16.                 lastReceivedTime = DateTime.Now.Ticks / 10000;
  17.  
  18.                 if (bytes == 0)
  19.                 {
  20.                         UnityEngine.Debug.Log ("OnReceive called Close(true) 1");
  21.                         Close(true);
  22.                 }

It seems a malformed packet is being sent to all players, causing them to disconnect. Why do we call Close() in these cases of bad packets instead of just throwing the bad packet out?

Some other info, when everybody gets disconnected, the other player's do not leave the channel, I don't think. From my point of view in the game, everybody's avatar is frozen in the state they were in when everybody was disconnected (when the malformed packet is sent). When I exit the channel and rejoin the same channel (or even close the application and rejoin), everybody is still frozen in their last state. It's as if the player's were booted but never removed from the channel.
Title: Re: TNet/RFC Debugging
Post by: ArenMook on July 17, 2014, 03:15:23 AM
Because we don't know where the packet ends. Remember, TCP is a stream protocol. it has no end. This is why I record the packet size at the beginning (the "mExpected" value). If it's invalid, then there is no way to determine where the next packet begins and it's safer to just disconnect the player.

That said, why would everyone get disconnected in this case? Only the player who sent the malformed packet should get booted.

P.S. You mention sending UDP voice... UDP packets can arrive in a different order than they are sent, and according to the specs, UDP packets will either arrive fully, or not at all, so I question how they can get malformed. Have you tried using only TCP and seeing if that resolves the issue? If so maybe we need to have a closer look at what happens with UDP traffic.
Title: Re: TNet/RFC Debugging
Post by: gg67 on July 17, 2014, 08:19:54 AM
I totally didn't realize I was in the TNTcpProtocol file...so not being able to throw out the packet makes sense.

Quote
That said, why would everyone get disconnected in this case? Only the player who sent the malformed packet should get booted.

1. If Player A sends out a malformed TCP packet to everybody, wouldn't everybody have to close the connection? I don't understand why the sender would be booted from the way the code is written. The Close() calls are in OnReceive and OnProcessBuffer(). Is there a way on the client to debug and see who the sender is and possibly what RFC it was trying to send?

2. Also, can you explain why we Close if if (bytes == 0) in OnReceive()?

3. More possible symptoms, that I thought were unrelated but you never know...

  1. Failed to call RFC VRC_EventDispatcherRFC._TriggerAudioSource: failed to convert parameters
  2.   Expected args: System.Int32, System.String
  3.   Received args: System.Byte[], System.Int32
  4.  

I understand that it says the passed params and expected params aren't matching up, but it doesn't happen all the time. I've checked and double checked to make sure our function params and RFC caller params are in sync.

4. Quick shower thought, could something be happening to TCP packets when a ton of UDP is being sent at the same time? At the time of the crash, we a number of TCP packets being sent on repeat (maybe not a good idea?) as well as all the voice UDP. I've know I've heard about issues using both TCP and UDP at the same time...
Title: Re: TNet/RFC Debugging
Post by: ArenMook on July 18, 2014, 07:49:56 AM
1. Player packets go through the server, and it's the server that boots players who send malformed data. The server won't forward a malformed packet. You can see who the sender is by putting a log entry where the "mExpected" check fails -- line 599 of TNTcpProtocol.cs. Receiving happens on separate threads, then packets get added to the incoming buffer, and the Game Server processes them on line 334 of TNGameServer.cs.

2. Bytes 0 means a closed connection. It's what gets sent when you gracefully close the socket.

4. I know of no reason why TCP would be getting affected by UDP traffic. Heavy UDP usage may cause delays in TCP traffic I believe, but that's about it. Also not sure what you mean by "being sent on repeat"? In any case as I mentioned you can try disabling UDP (just run the server without the -udp option) and see if the issues disappear.
Title: Re: TNet/RFC Debugging
Post by: gg67 on July 18, 2014, 08:08:09 AM
I've been setting up my server only w/ the -tcp option. I thought udp packets were sent on a randomized udp port and the -udp option was for lobby server stuff?
Title: Re: TNet/RFC Debugging
Post by: ArenMook on July 19, 2014, 12:52:14 PM
If the server wasn't started with UDP, then UDP isn't going to be used at all. Only TCP will be used. When you try to use SendQuickly, it will go through TCP instead. If the server is started with -udp, then UDP will be used (provided the client is using it) when you use SendQuickly.
Title: Re: TNet/RFC Debugging
Post by: gg67 on July 21, 2014, 10:20:43 PM
1. I'm still a little confused on TNTcpProtocol. It's used on both the server and client, but what functions are used on which ends? ProcessBuffer, OnReceive, Close all seem to be Client side functions. It seems like the clients send a Disconnect request packet to the server in the Close function. Can you go into a little bit more detail on this script?

2. If I wanted to build a separate app to monitor the server, channels, players, player actions, would it be better to do it in Unity or create another c# script like the TNet server?

3. I'm noticing that OnNetworkDisconnect() isn't called when I have a client connected to the server and then I close the server. The Close() function is called in TNTcpProtocol, but the OnNetworkDisconnect() doesn't seemed to be fired. Is that by design? Or am I missing something.

4. Would having multiple clients running on the same machine cause issues? Since they are both sharing the same TCP port on the client?
Title: Re: TNet/RFC Debugging
Post by: ArenMook on July 22, 2014, 06:43:07 PM
1. TcpProtocol is used on both client and server side. Client only has one of it, while the server has as many of them as there are players. Each player is a TcpProtocol instance. ProcessBuffer is the function that's used to receive incoming data. It's called from OnReceive right above it, which is an asynchronous callback triggered by the system when new data arrives. The process of gracefully closing the connection involves notifying the server by sending a packet. Otherwise the connection would be terminated abruptly.

2. I'd say C#.

3. I assume you mean manually closing the app without going through the 'q' to exit it? You get an error in this case on the client side ("An existing connection was forcibly closed by the remote host"). Although thinking about it, having it send OnNetworkDisconnect would make sense. I'll make it happen.

4. Clients don't use the same port. They use different ports, they just connect to the same server port. So multiple clients are fine.
Title: Re: TNet/RFC Debugging
Post by: gg67 on July 22, 2014, 06:58:53 PM
For #3, I'm specifically talking about when the server tells the client to disconnect b/c the client sends a malformed packet. In this case I'd like to kick the user to my main menu screen. I assumed force closing the server gave me similar results on the client side. Is that gonna be the same thing?

Title: Re: TNet/RFC Debugging
Post by: ArenMook on July 22, 2014, 08:05:42 PM
Force closing the server just aborts the connection. It doesn't send anything, which is why there is no disconnect notification. I've modified the Pro repository to send out a notification. Will it affect your malformed packet case? Possibly, but it's just speculation on my part as I can't reproduce it on my end.
Title: Re: TNet/RFC Debugging
Post by: gg67 on July 22, 2014, 09:40:42 PM
Awesome! Thanks.

As for the c# standalone server monitoring app, do we want to connect to the server as a client/player? Or do we want to create a modified server that tells us more info than the default one does?

I'm looking into the "connect as another player" design right now. Is this possible to do without any of the files in TNet/Client? (since those are all Unity dependent). Looks possible, but didn't know if there are any "gotchas" I should know about. For example, I was able to connect to a server using just TNTcpProtocol, but failed the verification since I didn't actually create a player and increase the static player count, etc.

What's the best approach?
Title: Re: TNet/RFC Debugging
Post by: ArenMook on July 22, 2014, 11:48:49 PM
Connecting as a player option would be much more powerful, letting you to remotely connect to the server from any app -- even a Unity application easily. Would it be better in your case, or would it make more sense to go down the more secure route with a dedicated connection? That's for you to decide. I'd go with the easier route, personally -- so the same route you're taking right now.

You will connect as a normal player, you just won't be joining any channels -- so the whole verification thing isn't an issue as it will happen automatically. No one will see you anyway.
Title: Re: TNet/RFC Debugging
Post by: gg67 on July 23, 2014, 09:17:06 PM
I started working on this, but am having issues getting a basic connection going. It connects and then times out. Here's where I'm at:

  1. public class AdminMain
  2. {
  3.     static Thread mThread;
  4.     static GameClient mClient;
  5.  
  6.         /// <summary>
  7.         /// Application entry point -- parse the parameters.
  8.         /// </summary>
  9.  
  10.         static int Main (string[] args)
  11.         {
  12.         mClient = new GameClient();
  13.         TcpProtocol tcp = new TcpProtocol();
  14.         IPEndPoint endPoint = TNet.Tools.ResolveEndPoint("127.0.0.1", 5127);
  15.         tcp.Connect(endPoint);
  16.  
  17.  
  18.         mThread = new Thread(ThreadFunction);
  19.         mThread.Start();
  20.  
  21.         return 0;
  22.         }
  23.  
  24.     static void ThreadFunction()
  25.     {
  26.         for (; ; )
  27.         {
  28.             mClient.ProcessPackets();
  29.         }
  30.     }
  31. }
  32.  
  33.  
Title: Re: TNet/RFC Debugging
Post by: ArenMook on July 23, 2014, 09:47:04 PM
You should never have an endless loop like that. You need to add a Thread.Sleep in there or you will be completely eating up all your CPU cycles. Your Main function also exits right away, resulting in your application effectively shutting down. Have a look at the stand-alone server example that comes with TNet. It has a main function, and it enters an input loop there, thus preventing the application from terminating.