Duplicate/Inconsistent state received on Unity client

[pedroplaykids]

Hello,

We're using SFS2X as the network solution for one of our projects and I find a strange problem. I'll try to explain as simply and as detailed as possible.

Consider state the set of user variables describing the game state (it contains a packet number to help packet identification) and packet a TCP packet.

I'm using the following configuration to reproduce the problem:
Server (s)- local machine
client 1(c1) - client on Unity editor
client 2(c2) - client on iOS device

Sometimes, not always, when c2 performs an action (like jumping) the state describing the position received at c1 are duplicate or somewhat invalid.

This is a Unity trace that shows in which frame a certain numbered state is received:

console_trace.png

(118.12 KiB) Not downloaded yet

We can see from this trace that state 71 is dropped and 72 is received twice at the frame 4560.

To evaluate at which communication layer the problem was occurring I toke a trace from the packets exchanged between c1,c2 and s (packets are ordered by oldest to newest):

packet_information.png

(130.34 KiB) Not downloaded yet

Packet number

1825

contains both states 71 and 72 as you can see from the packet data:

Code: Select all

0000   6c 96 cf df 8c 15 d0 c5 f3 55 30 4c 08 00 45 00   l.Ïß..ÐÅóU0L..E.
0010   02 58 00 00 40 00 40 06 05 49 c0 a8 d8 d1 c0 a8   .X..@.@..IÀ¨ØÑÀ¨
0020   d9 34 d1 7c 26 cd ad 16 cf 28 ed 7c 86 ce 80 18   Ù4Ñ|&Í..Ï(í|.Î..
0030   08 00 06 21 00 00 01 01 08 0a 2b 30 ec 18 52 90   ...!......+0ì.R.
0040   10 d2 80 01 0f 12 00 03 00 01 63 02 00 00 01 61   .Ò........c....a
0050   03 00 0c 00 01 70 12 00 01 00 02 76 6c 11 00 0d   .....p.....vl...
0060   11 00 04 08 00 01 78 02 03 07 3f fb 3e 06 60 00   ......x...?û>.`.
0070   00 00 01 00 11 00 04 08 00 01 79 02 03 07 3f f6   ..........y...?ö
0080   78 60 a0 00 00 00 01 00 11 00 04 08 00 01 7a 02   x` ...........z.
0090   03 07 40 31 89 c5 00 00 00 00 01 00 11 00 04 08   ..@1.Å..........
00a0   00 03 72 6f 74 02 03 07 40 50 09 ef a0 00 00 00   ..rot...@P.ï ...
00b0   01 00 11 00 04 08 00 02 61 73 02 02 04 7c 16 1a   ........as...|..
00c0   2b 01 00 11 00 04 08 00 02 61 70 02 03 07 40 33   +........ap...@3
00d0   52 b3 c0 00 00 00 01 00 11 00 04 08 00 02 72 65   R³À...........re
00e0   02 02 04 00 00 00 00 01 00 11 00 04 08 00 01 74   ...............t
00f0   02 01 01 00 01 00 11 00 04 08 00 02 78 73 02 03   ............xs..
0100   07 00 00 00 00 00 00 00 00 01 00 11 00 04 08 00   ................
0110   02 79 73 02 03 07 40 16 c7 2e 80 00 00 00 01 00   .ys...@.Ç.......
0120   11 00 04 08 00 02 7a 73 02 03 07 00 00 00 00 00   ......zs........
0130   00 00 00 01 00 11 00 04 08 00 02 74 73 02 02 04   ...........ts...
0140   00 00 00 [b]47[/b] 01 00 11 00 04 08 00 02 71 61 02 01   ...G........qa..
0150   01 00 01 00 80 01 0f 12 00 03 00 01 63 02 00 00   ............c...
0160   01 61 03 00 0c 00 01 70 12 00 01 00 02 76 6c 11   .a.....p.....vl.
0170   00 0d 11 00 04 08 00 01 78 02 03 07 3f fb 3e 06   ........x...?û>.
0180   60 00 00 00 01 00 11 00 04 08 00 01 79 02 03 07   `...........y...
0190   3f fb cf 80 a0 00 00 00 01 00 11 00 04 08 00 01   ?ûÏ. ...........
01a0   7a 02 03 07 40 31 89 c5 00 00 00 00 01 00 11 00   z...@1.Å........
01b0   04 08 00 03 72 6f 74 02 03 07 40 50 09 ef a0 00   ....rot...@P.ï .
01c0   00 00 01 00 11 00 04 08 00 02 61 73 02 02 04 7c   ..........as...|
01d0   16 1a 2b 01 00 11 00 04 08 00 02 61 70 02 03 07   ..+........ap...
01e0   40 33 54 c1 40 00 00 00 01 00 11 00 04 08 00 02   @3TÁ@...........
01f0   72 65 02 02 04 00 00 00 00 01 00 11 00 04 08 00   re..............
0200   01 74 02 01 01 00 01 00 11 00 04 08 00 02 78 73   .t............xs
0210   02 03 07 00 00 00 00 00 00 00 00 01 00 11 00 04   ................
0220   08 00 02 79 73 02 03 07 40 0a 16 cf 00 00 00 00   ...ys...@..Ï....
0230   01 00 11 00 04 08 00 02 7a 73 02 03 07 00 00 00   ........zs......
0240   00 00 00 00 00 01 00 11 00 04 08 00 02 74 73 02   .............ts.
0250   02 04 00 00 00 [b]48[/b] 01 00 11 00 04 08 00 02 71 61   .....H........qa
0260   02 01 01 00 01 00       

......

This packet was sent from c2->s. Next, we can see that SFS2X server immediately sent two packets to c1 (

1759

and

1761

), containing states 71 and 72:

1759

Code: Select all

0000   02 00 00 00 45 00 01 4e 00 00 40 00 40 06 00 00   ....E..N..@.@...
0010   7f 00 00 01 7f 00 00 01 26 cd e9 1b f3 a3 46 16   ........&Íé.ó£F.
0020   ad fd 5d 08 80 18 31 2d ff 42 00 00 01 01 08 0a   .ý]...1-ÿB......
0030   52 90 11 3c 52 90 10 d3 80 01 17 12 00 03 00 01   R..<R..Ó........
0040   70 12 00 02 00 01 75 04 00 00 00 63 00 02 76 6c   p.....u....c..vl
0050   11 00 0d 11 00 04 08 00 01 78 02 03 07 3f fb 3e   .........x...?û>
0060   06 60 00 00 00 01 00 11 00 04 08 00 01 79 02 03   .`...........y..
0070   07 3f f6 78 60 a0 00 00 00 01 00 11 00 04 08 00   .?öx` ..........
0080   01 7a 02 03 07 40 31 89 c5 00 00 00 00 01 00 11   .z...@1.Å.......
0090   00 04 08 00 03 72 6f 74 02 03 07 40 50 09 ef a0   .....rot...@P.ï 
00a0   00 00 00 01 00 11 00 04 08 00 02 61 73 02 02 04   ...........as...
00b0   7c 16 1a 2b 01 00 11 00 04 08 00 02 61 70 02 03   |..+........ap..
00c0   07 40 33 52 b3 c0 00 00 00 01 00 11 00 04 08 00   .@3R³À..........
00d0   02 72 65 02 02 04 00 00 00 00 01 00 11 00 04 08   .re.............
00e0   00 01 74 02 01 01 00 01 00 11 00 04 08 00 02 78   ..t............x
00f0   73 02 03 07 00 00 00 00 00 00 00 00 01 00 11 00   s...............
0100   04 08 00 02 79 73 02 03 07 40 16 c7 2e 80 00 00   ....ys...@.Ç....
0110   00 01 00 11 00 04 08 00 02 7a 73 02 03 07 00 00   .........zs.....
0120   00 00 00 00 00 00 01 00 11 00 04 08 00 02 74 73   ..............ts
0130   02 02 04 00 00 00 [b]47[/b] 01 00 11 00 04 08 00 02 71   ......G........q
0140   61 02 01 01 00 01 00 00 01 61 03 00 0c 00 01 63   a........a.....c
0150   02 00                                             ..

1761

Code: Select all

0000   02 00 00 00 45 00 01 4e 00 00 40 00 40 06 00 00   ....E..N..@.@...
0010   7f 00 00 01 7f 00 00 01 26 cd e9 1b f3 a3 47 30   ........&Íé.ó£G0
0020   ad fd 5d 08 80 18 31 2d ff 42 00 00 01 01 08 0a   .ý]...1-ÿB......
0030   52 90 11 3f 52 90 11 3c 80 01 17 12 00 03 00 01   R..?R..<........
0040   70 12 00 02 00 01 75 04 00 00 00 63 00 02 76 6c   p.....u....c..vl
0050   11 00 0d 11 00 04 08 00 01 78 02 03 07 3f fb 3e   .........x...?û>
0060   06 60 00 00 00 01 00 11 00 04 08 00 01 79 02 03   .`...........y..
0070   07 3f fb cf 80 a0 00 00 00 01 00 11 00 04 08 00   .?ûÏ. ..........
0080   01 7a 02 03 07 40 31 89 c5 00 00 00 00 01 00 11   .z...@1.Å.......
0090   00 04 08 00 03 72 6f 74 02 03 07 40 50 09 ef a0   .....rot...@P.ï 
00a0   00 00 00 01 00 11 00 04 08 00 02 61 73 02 02 04   ...........as...
00b0   7c 16 1a 2b 01 00 11 00 04 08 00 02 61 70 02 03   |..+........ap..
00c0   07 40 33 54 c1 40 00 00 00 01 00 11 00 04 08 00   .@3TÁ@..........
00d0   02 72 65 02 02 04 00 00 00 00 01 00 11 00 04 08   .re.............
00e0   00 01 74 02 01 01 00 01 00 11 00 04 08 00 02 78   ..t............x
00f0   73 02 03 07 00 00 00 00 00 00 00 00 01 00 11 00   s...............
0100   04 08 00 02 79 73 02 03 07 40 0a 16 cf 00 00 00   ....ys...@..Ï...
0110   00 01 00 11 00 04 08 00 02 7a 73 02 03 07 00 00   .........zs.....
0120   00 00 00 00 00 00 01 00 11 00 04 08 00 02 74 73   ..............ts
0130   02 02 04 00 00 00 [b]48[/b] 01 00 11 00 04 08 00 02 71   ......H........q
0140   61 02 01 01 00 01 00 00 01 61 03 00 0c 00 01 63   a........a.....c
0150   02 00                                             ..

So, the server sent the packets right to the client, but as shown on the image above c1 dropped state 71 and duplicated state 72. It appears that both packets were received before the next update and 72 overwrote the last state.

I've explained this case since it was simpler, but we found even cases were 3 packets were intertwined, resulting in even more duplicated packets. All tests were conducted using a LAN.

Our game is a real-time third person and this client behavior is confusing our interpolation/dead reckoning, and also showing some ghosting.

Can someone please help me with this issue?

Best regards,

[Lapo]

Hello,
can you tell us which server version and C# API version are you using?

Also, have you found a way to reproduce the issue?
What is the average packet rate of your game approximately?
To exclude platform specific issues have you tried running one client in the editor and one .exe client?

I ask because in the past we've seen a couple of odd behaviors when the Unity project was built for mobile devices, so I'd like to see if we can exclude this sort of issues.

Thanks

[pedroplaykids]

Hello Lapo,

thanks for the quick reply.

can you tell us which server version and C# API version are you using?

We're using Linux server Community Edition v2.13, Unity with Script Runtime Version .NET 4.x Equivalent and Compatibility Level .NET 4.x. C# client version is 1.7.9.0.

Also, have you found a way to reproduce the issue?

Yes. I run the server on my local machine and a mobile device and Unity Editor as clients. Modifying the user variables by moving/jumping my character causes these issues with the packets.

What is the average packet rate of your game approximately?

Both clients are configured to send their position (if it has changed) at approximately 1/15 s (each 66ms). The send position code is inside a mono behavior FixedUpdate script that runs with a 20ms period.

To exclude platform specific issues have you tried running one client in the editor and one .exe client?

Yes. When changing client c2 (iOS) with a native MacOs client I couldn't reproduce the issue.

I ask because in the past we've seen a couple of odd behaviors when the Unity project was built for mobile devices, so I'd like to see if we can exclude this sort of issues.

The problem seems to occur when the Editor client (I've only used the client editor to receive the packets, it's easier to debug) receives more than one state (in one or more TCP packets) on the same frame. It never gives us out of order packets, but it drops some packets which is causing some ghosts/jitter in our game.

Best regards,

[Lapo]

Hi,
if I understand this correctly you're saying that the problem manifests with the client running in the Editor when playing with a second client as iOS build. Correct?
And it doesn't happen when you use the 2nd player built for native OSX.

I need a few clarifications:
you're referring to "packet states" in your post with specific numbers but I am not sure how you're determining those values? Analyzing the raw packets you posted the User Variables updates don't contain any counter/identifier so I am not sure how you're assigning those specific counters to each packet. Can you clarify?

Since you're not using the latest API, it would be best if you downloaded the latest C# API 1.7.11 and tried the same scenario. I don't think it will make much difference, but just in case. This also help us investigating as we'll use the latest code base.

If the problem persists could you provide a proof-of-concept that reproduces the issue?

Thanks

[Bax]

My opinion is that sometimes (maybe due to the framerate?) two variables update events related to the same client are received before the processEvents method is called. As event objects (added to the queue processed by that method) keep a reference to the variables (and not a copy), when the two events are actually processed, they point the same value.
Unfortunately we had to choose the "processEvents" approach due to the limitations of Unity with threads, and we can't change it (copy objects instead of referencing them), as we might incur in memory issues.

I think you have to options:
1) work around this issue making your code resilient in case an update is missing;
2) do not rely on user variables; instead send those updates using Extension messages; in fact all params objects attached to the ExtensionResponse events are unique (as they are not stored inside the API) and the issue above won't occur.

Hope this helps.

[pedroplaykids]

Hello Lapo and Bax,

again, thanks for the quick reply. You'll quote both answers with my responses:

Lapo Quote:

Hi,
if I understand this correctly you're saying that the problem manifests with the client running in the Editor when playing with a second client as iOS build. Correct?
And it doesn't happen when you use the 2nd player built for native OSX.

Yes, that's correct. The problem relates to what Bax reported, I'll get in details in his quote.

I need a few clarifications:
you're referring to "packet states" in your post with specific numbers but I am not sure how you're determining those values? Analyzing the raw packets you posted the User Variables updates don't contain any counter/identifier so I am not sure how you're assigning those specific counters to each packet. Can you clarify?

These packet states are ids I'm assigning at the sender side. Analyzing the raw packets I can find the number inspecting the bits, look at this example:

0240 00 00 00 00 00 01 00 11 00 04 08 00 02 74 73 02 .............ts.
0250 02 04 00 00 00 48 01 00 11 00 04 08 00 02 71 61 .....H........qa

variable ts represents the packet state, so 0x48=72, so I can see in the Unity editor which received state this packet relates to.


Since you're not using the latest API, it would be best if you downloaded the latest C# API 1.7.11 and tried the same scenario. I don't think it will make much difference, but just in case. This also helps us investigating as we'll use the latest code base.
Ok, I'll update but since Bax brought more information I believe this problem will still occur.

If the problem persists could you provide a proof-of-concept that reproduces the issue?
Bax already got to the point, I'll get in more details

Thanks[/quote]

Bax Quote:

My opinion is that sometimes (maybe due to the framerate?) two variables update events related to the same client are received before the processEvents method is called. As event objects (added to the queue processed by that method) keep a reference to the variables (and not a copy), when the two events are actually processed, they point the same value.
Unfortunately, we had to choose the "processEvents" approach due to the limitations of Unity with threads, and we can't change it (copy objects instead of referencing them), as we might incur in memory issues.

Yes, that is exactly the issue. If it was only one frame that would be fine. The problem is that even with a send rate of about 66ms when using a high-end iOS device (iPhone 7+ or above) we find cases where this problem extends up to five packets. If we, at least, received the states our prediction movement would not cause so much jitter/ghosting.

I've looked at your implementation and I couldn't find any delays in the sending methods, so I didn't expect so much variation on the time the packets are sent when using the iPhone. I'll try to debug with more attention the variance of the delay between sending packets on the iOS device.

While I humbly disagree about the Unity threading model limitations, since your implementation purely mono based, I understand that you are treating user variables as a state snapshot, so it makes sense to me that you don't go creating a list of user variables state copies that you've received on the same frame.

When looking at the TCPSocketLayer class I've found the following code on line 142 (v1.7.9.0):

Code: Select all

   
    private static void Sleep(int ms)
    {
      Thread.Sleep(10);
    }


Probably you meant to use the ms parameter in this method.

I think you have to options:
1) work around this issue making your code resilient in case an update is missing;
2) do not rely on user variables; instead send those updates using Extension messages; in fact all params objects attached to the ExtensionResponse events are unique (as they are not stored inside the API) and the issue above won't occur.

Ok, I'll try to use extension messages and let you know if it worked fine!

Hope this helps.

Again, thanks very much for the quick reply Lapo and Bax!

Best regards,

[Lapo]

Hi,

While I humbly disagree about the Unity threading model limitations, since your implementation purely mono based, I understand that you are treating user variables as a state snapshot, so it makes sense to me that you don't go creating a list of user variables state copies that you've received on the same frame.

The API are meant to work both in Unity with it's own threading limitations, as well as in a pure .Net/Mono environment with multi-threading. (therefore without manual event polling)

I've looked at your implementation and I couldn't find any delays in the sending methods, so I didn't expect so much variation on the time the packets are sent when using the iPhone. I'll try to debug with more attention the variance of the delay between sending packets on the iOS device.

I also don't think this is due to delays on the sending side. It's more likely connected to packet aggregation (i.e. Nagle Algorithm). If two UserVar updates are sent in the same TCP packet, on the other end the SystemController (class responsible to handle the calls) will process two updates and generate two events, but it's possible that both happen within 1 cycle of the event polling thread (the Unity main thread calling processEvent). In this scenario you will get two events showing the same data twice, because the 2nd update overwrote the 1st one.

Maybe packets are not aggregated (or less likely to) when running the native OSX client?

Ok, I'll try to use extension messages and let you know if it worked fine!

Yes in this case, it's the better solution.

Cheers

[pedroplaykids]

Hi Lapo,

I also don't think this is due to delays on the sending side. It's more likely connected to packet aggregation (i.e. Nagle Algorithm). If two UserVar updates are sent in the same TCP packet, on the other end the SystemController (class responsible to handle the calls) will process two updates and generate two events, but it's possible that both happen within 1 cycle of the event polling thread (the Unity main thread calling processEvent). In this scenario you will get two events showing the same data twice, because the 2nd update overwrote the 1st one.

Maybe packets are not aggregated (or less likely to) when running the native OSX client?

It may be, but sometimes the states are being sent as different packets, so not all problems relate to packet aggregation.
Probably iOsxMacOs have different TCP implementations, hence the disparity between the two behaviors.
You described the problem perfectly, I'm receiving the same data twice. The problem is that sometimes I end up missing up to 5 packets, you see?

Thanks very much you and Bax for the support.

Best regards,