search

playgameservices / cpp-android-basic-samples

Sample games using the Google Play Games C++ SDK
303 stars 131 forks source link

Reliable Messages Arriving Out of Order #36

Open jknight-nc opened 8 years ago

jknight-nc commented 8 years ago

We are seeing messages arriving out of order when using the SendReliableMessage API.

Device A (Server) is sending messages with the following identifiers: 21, 22, 16, 17, 17.

Device B (Client) is receiving messages with the following identifiers: 21, 16, 17, 22, 17.

These are the logs from device A:

Server:
Sends messages with order: 21, 22, 16, 17, 17
=====
D/ssg3    (20503): 2016-04-19 04:27:03.800 ssg3[20503:2874] [NCRTMatchGoogle] sendDataToAllPlayers reliable:(YES) msgType: 21 msglength 13
I/libjingle(28263): IbbDataTask::ProcessStart() called:
I/libjingle(28263): Got Xmpp DATA: <ibb:data ibb:seq="0" ibb:sid="1" xmlns:ibb="http://jabber.org/protocol/ibb">ARUIABABGAElAAAAAA==</ibb:data>
I/libjingle(28263): IbbDataTask::ProcessStart() called:
D/ssg3    (20503): 2016-04-19 04:27:03.975 ssg3[20503:2874] [NCRTMatchGoogle] OnDataReceived reliable:(YES) msgType: 21
D/ssg3    (20503): 2016-04-19 04:27:03.977 ssg3[20503:2874] [NCRTMatchGoogle] sendDataToAllPlayers reliable:(YES) msgType: 22 msglength 2
D/ssg3    (20503): 2016-04-19 04:27:03.977 ssg3[20503:2874] [NCRTMatchGoogle] sendDataToAllPlayers reliable:(YES) msgType: 16 msglength 2
D/ssg3    (20503): 2016-04-19 04:27:03.978 ssg3[20503:2874] [NCRTMatchGoogle] sendDataToAllPlayers reliable:(YES) msgType: 17 msglength 42
D/ssg3    (20503): 2016-04-19 04:27:04.012 ssg3[20503:2874] [NCRTMatchGoogle] sendDataToAllPlayers reliable:(YES) msgType: 17 msglength 122
I/libjingle(28263): IbbDataTask::ProcessStart() called:
I/libjingle(28263): Got Xmpp data back: <ibb:data ibb:seq="0" ibb:sid="1" xmlns:ibb="http://jabber.org/protocol/ibb"/>
I/libjingle(28263): static void gtalk::LibjingleJniHelper::DispatchIbbSendResult(jobject, const string&, const string&, bool): Dispatch ID:1
I/libjingle(28263): IbbDataTask::ProcessStart() called:
I/libjingle(28263): IbbDataTask::ProcessStart() called:
I/libjingle(28263): Got Xmpp data back: <ibb:data ibb:seq="0" ibb:sid="3" xmlns:ibb="http://jabber.org/protocol/ibb"/>
I/libjingle(28263): static void gtalk::LibjingleJniHelper::DispatchIbbSendResult(jobject, const string&, const string&, bool): Dispatch ID:3
I/libjingle(28263): IbbDataTask::ProcessStart() called:
I/libjingle(28263): IbbDataTask::ProcessStart() called:
I/libjingle(28263): Got Xmpp data back: <ibb:data ibb:seq="0" ibb:sid="5" xmlns:ibb="http://jabber.org/protocol/ibb"/>
I/libjingle(28263): static void gtalk::LibjingleJniHelper::DispatchIbbSendResult(jobject, const string&, const string&, bool): Dispatch ID:5
I/libjingle(28263): IbbDataTask::ProcessStart() called:
I/libjingle(28263): Got Xmpp data back: <ibb:data ibb:seq="0" ibb:sid="4" xmlns:ibb="http://jabber.org/protocol/ibb"/>
I/libjingle(28263): static void gtalk::LibjingleJniHelper::DispatchIbbSendResult(jobject, const string&, const string&, bool): Dispatch ID:4
I/libjingle(28263): IbbDataTask::ProcessStart() called:
I/libjingle(28263): Got Xmpp data back: <ibb:data ibb:seq="0" ibb:sid="2" xmlns:ibb="http://jabber.org/protocol/ibb"/>
I/libjingle(28263): static void gtalk::LibjingleJniHelper::DispatchIbbSendResult(jobject, const string&, const string&, bool): Dispatch ID:2
I/libjingle(28263): IbbDataTask::ProcessStart() called:

These are the logs from Device B

Client:
Receives messages with order: 21, 16, 17, 22, 17
=====
I/libjingle(10546): IbbDataTask::ProcessStart() called:
I/libjingle(10546): Got Xmpp DATA: <ibb:data ibb:seq="0" ibb:sid="1" xmlns:ibb="http://jabber.org/protocol/ibb">ARUIABABGAElAAAAAA==</ibb:data>
I/libjingle(10546): IbbDataTask::ProcessStart() called:
D/ssg3    (24194): 2016-04-18 15:27:05.379 ssg3[24194:292d] [NCRTMatchGoogle] OnDataReceived reliable:(YES) msgType: 21
W/GamesServiceBroker( 1584): Client connected with SDK 8487000, Services 8703238, and Games 37200038
W/GamesServiceBroker( 1584): Client connected with SDK 8487000, Services 8703238, and Games 37200038    
I/libjingle(10546): IbbDataTask::ProcessStart() called:
I/libjingle(10546): Got Xmpp data back: <ibb:data ibb:seq="0" ibb:sid="1" xmlns:ibb="http://jabber.org/protocol/ibb"/>
I/libjingle(10546): static void gtalk::LibjingleJniHelper::DispatchIbbSendResult(jobject, const string&, const string&, bool): Dispatch ID:1
I/libjingle(10546): Got Xmpp DATA: <ibb:data ibb:seq="0" ibb:sid="3" xmlns:ibb="http://jabber.org/protocol/ibb">ARA=</ibb:data>
I/libjingle(10546): IbbDataTask::ProcessStart() called:
I/libjingle(10546): IbbDataTask::ProcessStart() called:
I/libjingle(10546): Got Xmpp DATA: <ibb:data ibb:seq="0" ibb:sid="5" xmlns:ibb="http://jabber.org/protocol/ibb">AREKJEQwMTQ5N0VFLUFDNEQtNEFCQS1BRTZFLTgwQTc5MUY4OEZCMhAAGiQ4MEQwRjc1MS05NkM2LTQyNUYtODUwNS05QTg4REUyNTE1MjIgASokOEI1MEExOEYtRDVERC00MDVCLTk0M0QtQ0FGRkUzMjFFQzBGMAU=</ibb:data>
I/libjingle(10546): IbbDataTask::ProcessStart() called:
D/ssg3    (24194): 2016-04-18 15:27:05.581 ssg3[24194:292d] [NCRTMatchGoogle] OnDataReceived reliable:(YES) msgType: 16
I/libjingle(10546): Got Xmpp DATA: <ibb:data ibb:seq="0" ibb:sid="2" xmlns:ibb="http://jabber.org/protocol/ibb">ARY=</ibb:data>
I/libjingle(10546): IbbDataTask::ProcessStart() called:
D/ssg3    (24194): 2016-04-18 15:27:05.583 ssg3[24194:292d] [NCRTMatchGoogle] OnDataReceived reliable:(YES) msgType: 17
D/ssg3    (24194): 2016-04-18 15:27:05.583 ssg3[24194:292d] [NCRTMatchGoogle] OnDataReceived reliable:(YES) msgType: 22
D/ssg3    (24194): 2016-04-18 15:27:05.591 ssg3[24194:292d] SSGEventHandler received MSG_SERVER_CLIENT_GOTO_PREGAME
I/libjingle(10546): IbbDataTask::ProcessStart() called:
I/libjingle(10546): Got Xmpp DATA: <ibb:data ibb:seq="0" ibb:sid="4" xmlns:ibb="http://jabber.org/protocol/ibb">AREKJDkwNjNCM0E4LUNBMjAtNEI5MC04RDk4LUQ5QzlGMDJENUNBMBAA</ibb:data>
I/libjingle(10546): IbbDataTask::ProcessStart() called:
D/ssg3    (24194): 2016-04-18 15:27:05.595 ssg3[24194:292d] [NCRTMatchGoogle] OnDataReceived reliable:(YES) msgType: 17
D/ssg3    (24194): 2016-04-18 15:27:05.810 ssg3[24194:292d] SSGEventHandler received MSG_SERVER_CLIENT_PUSH_WORLDNAME
D/ssg3    (24194): 2016-04-18 15:27:05.811 ssg3[24194:292d] SSGEventHandler received MSG_BROADCAST_CLAIM_HOST
D/ssg3    (24194): 2016-04-18 15:27:05.812 ssg3[24194:292d] Broadcast msg claiming host in wrong state. state: 0

Another user has reported this problem: http://stackoverflow.com/questions/27199974/sendreliable-message-sometimes-not-received-by-opposite-peer

Iit seems like the SendReliable pathway does not meet the in-order gaurentee outlined here: https://developers.google.com/games/services/common/concepts/realtimeMultiplayer#sending_game_data

Any information or confirmation on this bug is greatly appreciated.

EDIT:

I've modified the ButtonClicker sample on a fork of this project to demonstrate that the reliable messaging system delivers messages out of order:

https://github.com/jknight-nc/cpp-android-basic-samples/tree/outoforder

The commit is located here: https://github.com/jknight-nc/cpp-android-basic-samples/commit/b3c62c87bf947595942c0fb40de7704a715218c2

jknight-nc commented 7 years ago

@claywilkinson Does google acknowledge this issue?

I think I've definitively proved a relatively major issue with this sdk.

claywilkinson commented 7 years ago

There has been some work on this earlier in the year. There still can be a problem in some situations that can cause out of order delivery, so we recommend adding some ordering bits to your message so you can sort them accordingly.