Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Reliable Messages Arriving Out of Order #36

Open
jknight-nc opened this issue Apr 18, 2016 · 2 comments
Open

Reliable Messages Arriving Out of Order #36

jknight-nc opened this issue Apr 18, 2016 · 2 comments

Comments

@jknight-nc
Copy link

jknight-nc commented Apr 18, 2016

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: jknight-nc@b3c62c8

@jknight-nc
Copy link
Author

@claywilkinson Does google acknowledge this issue?

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

@claywilkinson
Copy link
Contributor

claywilkinson commented Dec 21, 2016

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.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants