cpp-android-basic-samples icon indicating copy to clipboard operation
cpp-android-basic-samples copied to clipboard
verified publisher icon playgameservices

Reliable Messages Arriving Out of Order

Open jknight-nc opened this issue 9 years ago • 2 comments

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 avatar Apr 18 '16 22:04 jknight-nc

@claywilkinson Does google acknowledge this issue?

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

jknight-nc avatar Nov 17 '16 17:11 jknight-nc

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.

claywilkinson avatar Dec 21 '16 21:12 claywilkinson