search

playgameservices / android-basic-samples

Google Play game services - Android samples
Apache License 2.0
972 stars 970 forks source link

Some multi-player sessions see zero received messages (reliable/unreliable) #155

Closed stolk closed 8 years ago

stolk commented 9 years ago

When I test a 1 vs 1 real time game, pretty much half of the sessions, there is no data received after the room is connected and kicks off.

I captured a device log of a session where the communication was not successful, despite a successful ShowRoomUI.

It looks like the earliest sign of problems is in 'UDP bind failed with error 22' Any idea what could be the cause of this, and what is the meaning of error 22?

It looks like the earliest sign of trouble is that RoomServiceStateMachine attempts a reconnection.

I/RoomServiceStateMachine( 7398): Attempting to reconnect to: p_CJiO4I6oysDA5wEQAQ

thanks,

bram

I/libjingle( 7398): Attempting to create a session, with data only.
I/libjingle( 7398): CompleteInitiateCall_w:remoteJid=1vcyx4ttcd3151f9fvooegjs68@public.talk.google.com/games_andr3812DFE4
I/libjingle( 7398): void gtalk::LibjingleClient::OnCallCreate(cricket::Call*): Connecting to OnAddSession
E/libjingle( 7398): Error(mediasession.cc:529): cricket::SessionDescription* cricket::MediaSessionDescriptionFactory::CreateOffer(const cricket::MediaSessionOptions&, const cricket::SessionDescription*): Creating Data offer.
I/libjingle( 7398): AddSession() called. has_data = 1
I/libjingle( 7398): Creating data channel.
I/libjingle( 7398): Is worker current:0
I/libjingle( 7398): Current thread:0x7a5f22d8
I/libjingle( 7398): worker_thread:0x7a6795a0 initialized=1
I/libjingle( 7398): Created channel for data
I/libjingle( 7398): DataChannel::Init() called
I/libjingle( 7398): result = 1
D/dalvikvm(13146): DexOpt: unable to opt direct call 0x0083 at 0x86 in Lcom/google/android/gms/games/ui/client/ClientFragmentActivity;.instantiateGoogleApiClient
I/libjingle( 7398): void gtalk::LibjingleClient::OnAddSession(cricket::Call*, cricket::Session*): OnAddSession called.
I/swaag   (13059): Participant Status Changed. Valid=1
I/swaag   (13059): Participant id p_CJiO4I6oysDA5wEQAQ, name Player 7806
I/libjingle( 7398): Setting local data description
I/libjingle( 7398): Added data send stream '' with ssrc=542955133
I/libjingle( 7398): Add send ssrc: 542955133
I/libjingle( 7398): Changing data state, recv=0 send=0
I/libjingle( 7398): Channel enabled
I/libjingle( 7398): Changing data state, recv=1 send=0
I/libjingle( 7398): Network Information: All networks
I/libjingle( 7398): Name, Description, Prefix, Prefix Length, IP, ignored
I/libjingle( 7398): ipv4-default default IPV4 network 0.0.0.0 32 10.0.1.27 0
I/libjingle( 7398): wlan0 wlan0 10.0.1.0 24 10.0.1.27 0
I/libjingle( 7398): p2p0 p2p0 fe80:: 64 fe80::485a:3fff:fe5d:dd44 0
I/libjingle( 7398): wlan0 wlan0 fe80:: 64 fe80::4a5a:3fff:fe5d:dd44 0
I/libjingle( 7398): 
I/swaag   (13059): Room Status Changed to 2.
I/libjingle( 7398): HttpRequest start: relay.google.com/create_session?username=F5YYr1CDXdEsjPSn&password=Ks4ng024KHDGjFHer%2fWN%2bhML&sn=3
I/libjingle( 7398): SSL Cleanup
E/libjingle( 7398): Error(basicpacketsocketfactory.cc:67): UDP bind failed with error 22
E/libjingle( 7398): Error(basicpacketsocketfactory.cc:67): UDP bind failed with error 22
E/libjingle( 7398): Error(basicpacketsocketfactory.cc:67): UDP bind failed with error 22
E/libjingle( 7398): Error(basicpacketsocketfactory.cc:67): UDP bind failed with error 22
I/libjingle( 7398): OpenSSLAdapter::OnConnectEvent
I/libjingle( 7398): BeginSSL: relay.google.com
I/libjingle( 7398): Parsing Jingle data content
I/libjingle( 7398): Setting remote data description
I/libjingle( 7398): Added data recv stream '' with ssrc=2192033831
I/libjingle( 7398): Add remote ssrc: 2192033831
I/libjingle( 7398): SRTP reset to init state
I/libjingle( 7398): DataMediaChannel::SetSendBandwidth to 10485000bps.
I/libjingle( 7398): Changing data state, recv=1 send=0
D/dalvikvm(13146): Note: class Lcom/google/android/gms/games/internal/IGamesService$Stub; has 202 unimplemented (abstract) methods
I/WaitingRoom(13146): Room status after registering listener: 2
I/libjingle( 7398): HttpRequest completed successfully
I/libjingle( 7398): SSL Cleanup
I/libjingle( 7398): Channel socket writable (data_rtp) for the first time
I/libjingle( 7398): Changing data state, recv=1 send=1
I/swaag   (13059): P2P Connected.
I/swaag   (13059): Connected Set Changed. Currently connected: 2
I/swaag   (13059): Connected Set Changed. Currently connected: 2
I/WaitingRoom(13146): CALLBACK: onRoomConnected()...
I/WaitingRoom(13146): onRoomConnected: statusCode = 0 for room ID: ChoKCQj1jOXnmhsQAhABGAAg____________ARCeuIisweyEgU0
I/swaag   (13059): CMD_GAINED_FOCUS handled
D/BuggyActivity(13059): onActivityResult(4673607,-1,Intent { (has extras) }
V/GamesNativeSDK(13059): Received OnActivityResult with result_code: -1
V/GamesNativeSDK(13059): Received Activity Resume Event.
I/swaag   (13059): Succesfully showed room (created by Bram Stolk): (null)
I/swaag   (13059): Participant 0: Player 7806 (p_CJiO4I6oysDA5wEQAQ)
I/swaag   (13059): Participant 1: Bram Stolk (p_CJ64iKzB7ISBTRAB)
E/GamesNativeSDK(13059): Sending reliable message
E/GamesNativeSDK(13059): Sending reliable message SUCCEEDED
I/swaag   (13059): Starting round 0 with map 0
I/swaag   (13059): geomdb cleared of 0 entries (0 evicted from cache).
I/swaag   (13059): world created for level -1
I/swaag   (13059): objectOfInterest at 0x7c375dc8 named 'player'
I/swaag   (13059): CMD_RESUME handled
D/ChimeraCfgMgr( 1856): Loading module com.google.android.gms.games from APK com.google.android.play.games
D/ChimeraModuleLdr( 1856): Module APK com.google.android.play.games already loaded
I/libjingle( 7398): worker_thread:0x7a6795a0 initialized=1
I/RoomServiceStateMachine( 7398): Attempting to reconnect to: p_CJiO4I6oysDA5wEQAQ
I/libjingle( 7398): Channel disabled
I/libjingle( 7398): Changing data state, recv=0 send=0
I/libjingle( 7398): Destroyed channel
I/libjingle( 7398): Attempting to create a session, with data only.
I/libjingle( 7398): CompleteInitiateCall_w:remoteJid=1vcyx4ttcd3151f9fvooegjs68@public.talk.google.com/games_andr3812DFE4
I/libjingle( 7398): void gtalk::LibjingleClient::OnCallCreate(cricket::Call*): Connecting to OnAddSession
E/libjingle( 7398): Error(mediasession.cc:529): cricket::SessionDescription* cricket::MediaSessionDescriptionFactory::CreateOffer(const cricket::MediaSessionOptions&, const cricket::SessionDescription*): Creating Data offer.
I/libjingle( 7398): AddSession() called. has_data = 1
I/libjingle( 7398): Creating data channel.
I/libjingle( 7398): Is worker current:0
I/libjingle( 7398): Current thread:0x7a5f22d8
I/libjingle( 7398): worker_thread:0x7a6795a0 initialized=1
I/libjingle( 7398): Created channel for data
I/libjingle( 7398): DataChannel::Init() called
I/libjingle( 7398): result = 1
I/libjingle( 7398): void gtalk::LibjingleClient::OnAddSession(cricket::Call*, cricket::Session*): OnAddSession called.
I/libjingle( 7398): Setting local data description
I/libjingle( 7398): Added data send stream '' with ssrc=1513025174
I/libjingle( 7398): Add send ssrc: 1513025174
I/libjingle( 7398): Changing data state, recv=0 send=0
E/libjingle( 7398): Error(latencyprober.cpp:83): Peer already added for reliable latency metrics.
I/libjingle( 7398): Channel enabled
I/libjingle( 7398): Changing data state, recv=1 send=0
I/libjingle( 7398): Network Information: All networks
I/libjingle( 7398): Name, Description, Prefix, Prefix Length, IP, ignored
I/libjingle( 7398): ipv4-default default IPV4 network 0.0.0.0 32 10.0.1.27 0
I/libjingle( 7398): wlan0 wlan0 10.0.1.0 24 10.0.1.27 0
I/libjingle( 7398): p2p0 p2p0 fe80:: 64 fe80::485a:3fff:fe5d:dd44 0
I/libjingle( 7398): wlan0 wlan0 fe80:: 64 fe80::4a5a:3fff:fe5d:dd44 0
I/libjingle( 7398): 
I/libjingle( 7398): HttpRequest start: relay.google.com/create_session?username=2SnHIommK1POhvUN&password=ZfKDjnxO4ER1auGWLUuMb%2fy%2b&sn=3
I/libjingle( 7398): SSL Cleanup
E/libjingle( 7398): Error(basicpacketsocketfactory.cc:67): UDP bind failed with error 22
E/libjingle( 7398): Error(basicpacketsocketfactory.cc:67): UDP bind failed with error 22
E/libjingle( 7398): Error(basicpacketsocketfactory.cc:67): UDP bind failed with error 22
E/libjingle( 7398): Error(basicpacketsocketfactory.cc:67): UDP bind failed with error 22
I/libjingle( 7398): OpenSSLAdapter::OnConnectEvent
I/libjingle( 7398): BeginSSL: relay.google.com
I/libjingle( 7398): IbbDataTask::ProcessStart() called:
I/libjingle( 7398): Got Xmpp data back: <ibb:data ibb:seq="0" ibb:sid="1" xmlns:ibb="http://jabber.org/protocol/ibb"/>
I/libjingle( 7398): static void gtalk::LibjingleJniHelper::DispatchIbbSendResult(jobject, const string&, const string&, bool): Dispatch ID:1
I/libjingle( 7398): IbbDataTask::ProcessStart() called:
I/libjingle( 7398): Parsing Jingle data content
I/libjingle( 7398): Setting remote data description
I/libjingle( 7398): Added data recv stream '' with ssrc=1992942837
I/libjingle( 7398): Add remote ssrc: 1992942837
I/libjingle( 7398): SRTP reset to init state
I/libjingle( 7398): DataMediaChannel::SetSendBandwidth to 10485000bps.
I/libjingle( 7398): Changing data state, recv=1 send=0
I/swaag   (13059): Connected Set Changed. Currently connected: 0
I/swaag   (13059): Participant Status Changed. Valid=1
I/swaag   (13059): Participant id p_CJiO4I6oysDA5wEQAQ, name Player 7806
I/swaag   (13059): Connected Set Changed. Currently connected: 0
E/RoomServiceStateMachine( 7398): Attempting to send an unreliable message to participants when not in connected set.
E/RoomServiceStateMachine( 7398): Attempting to send an unreliable message to participants when not in connected set.
I/libjingle( 7398): HttpRequest completed successfully
I/libjingle( 7398): SSL Cleanup
E/RoomServiceStateMachine( 7398): Attempting to send an unreliable message to participants when not in connected set.
E/RoomServiceStateMachine( 7398): Attempting to send an unreliable message to participants when not in connected set.
E/RoomServiceStateMachine( 7398): Attempting to send an unreliable message to participants when not in connected set.
E/RoomServiceStateMachine( 7398): Attempting to send an unreliable message to participants when not in connected set.
E/RoomServiceStateMachine( 7398): Attempting to send an unreliable message to participants when not in connected set.
E/RoomServiceStateMachine( 7398): Attempting to send an unreliable message to participants when not in connected set.
E/RoomServiceStateMachine( 7398): Attempting to send an unreliable message to participants when not in connected set.
E/RoomServiceStateMachine( 7398): Attempting to send an unreliable message to participants when not in connected set.
E/libjingle( 7398): Error(basicpacketsocketfactory.cc:67): UDP bind failed with error 22
E/libjingle( 7398): Error(basicpacketsocketfactory.cc:67): UDP bind failed with error 22
E/RoomServiceStateMachine( 7398): Attempting to send an unreliable message to participants when not in connected set.
E/RoomServiceStateMachine( 7398): Attempting to send an unreliable message to participants when not in connected set.
E/RoomServiceStateMachine( 7398): Attempting to send an unreliable message to participants when not in connected set.
E/RoomServiceStateMachine( 7398): Attempting to send an unreliable message to participants when not in connected set.
E/libjingle( 7398): Error(basicpacketsocketfactory.cc:85): TCP bind failed with error 22
E/libjingle( 7398): Error(basicpacketsocketfactory.cc:85): TCP bind failed with error 22
E/RoomServiceStateMachine( 7398): Attempting to send an unreliable message to participants when not in connected set.
E/RoomServiceStateMachine( 7398): Attempting to send an unreliable message to participants when not in connected set.
E/RoomServiceStateMachine( 7398): Attempting to send an unreliable message to participants when not in connected set.
E/RoomServiceStateMachine( 7398): Attempting to send an unreliable message to participants when not in connected set.
E/RoomServiceStateMachine( 7398): Attempting to send an unreliable message to participants when not in connected set.
E/RoomServiceStateMachine( 7398): Attempting to send an unreliable message to participants when not in connected set.
E/RoomServiceStateMachine( 7398): Attempting to send an unreliable message to participants when not in connected set.
E/RoomServiceStateMachine( 7398): Attempting to send an unreliable message to participants when not in connected set.
stolk commented 9 years ago

So the bind error may actually be benign. As I captured a log of a session that did work well. And in a working session, these bind errors show up as well.

The difference between the non working run, and working run, seem to be the following lines in non-working case:

I/RoomServiceStateMachine( 7398): Attempting to reconnect to: p_CJiO4I6oysDA5wEQAQ
I/libjingle( 7398): Channel disabled

And here is the complete log of a working run:

V/GamesNativeSDK(13638): Detaching from JVM on thread main_dispatch
I/libjingle(13302): Parsing Jingle data content
I/libjingle(13302): void gtalk::LibjingleClient::OnCallCreate(cricket::Call*): Connecting to OnAddSession
I/libjingle(13302): Calling Call::IncomingSession()
I/libjingle(13302): AddSession() called. has_data = 1
I/libjingle(13302): Creating data channel.
I/libjingle(13302): Is worker current:0
I/libjingle(13302): Current thread:0x7bb81328
I/libjingle(13302): worker_thread:0x7bb816a0 initialized=1
I/libjingle(13302): Created channel for data
I/libjingle(13302): DataChannel::Init() called
I/libjingle(13302): Setting remote data description
I/libjingle(13302): Added data recv stream '' with ssrc=3174303273
I/libjingle(13302): Add remote ssrc: 3174303273
I/libjingle(13302): DataMediaChannel::SetSendBandwidth to 10485000bps.
I/libjingle(13302): Changing data state, recv=0 send=0
I/libjingle(13302): result = 1
I/libjingle(13302): void gtalk::LibjingleClient::OnAddSession(cricket::Call*, cricket::Session*): OnAddSession called.
I/libjingle(13302): Setting local data description
I/libjingle(13302): Added data send stream '' with ssrc=1305734841
I/libjingle(13302): Add send ssrc: 1305734841
I/libjingle(13302): SRTP reset to init state
I/libjingle(13302): Changing data state, recv=0 send=0
I/libjingle(13302): Channel enabled
I/libjingle(13302): Changing data state, recv=1 send=0
I/swaag   (13638): Participant Status Changed. Valid=1
I/swaag   (13638): Participant id p_CKbLkbu9yN7cgwEQAQ, name Player 4285
I/libjingle(13302): Network Information: All networks
I/libjingle(13302): Name, Description, Prefix, Prefix Length, IP, ignored
I/libjingle(13302): ipv4-default default IPV4 network 0.0.0.0 32 10.0.1.27 0
I/libjingle(13302): wlan0 wlan0 10.0.1.0 24 10.0.1.27 0
I/libjingle(13302): p2p0 p2p0 fe80:: 64 fe80::485a:3fff:fe5d:dd44 0
I/libjingle(13302): wlan0 wlan0 fe80:: 64 fe80::4a5a:3fff:fe5d:dd44 0
I/libjingle(13302): 
I/libjingle(13302): HttpRequest start: relay.google.com/create_session?username=tIK2wp4biF5iq1fk&password=1AnWRlfzmQo0Z7JOp2M0l9qv&sn=3
I/libjingle(13302): SSL Cleanup
E/libjingle(13302): Error(basicpacketsocketfactory.cc:67): UDP bind failed with error 22
E/libjingle(13302): Error(basicpacketsocketfactory.cc:67): UDP bind failed with error 22
E/libjingle(13302): Error(basicpacketsocketfactory.cc:67): UDP bind failed with error 22
E/libjingle(13302): Error(basicpacketsocketfactory.cc:67): UDP bind failed with error 22
I/swaag   (13638): Room Status Changed to 2.
I/libjingle(13302): OpenSSLAdapter::OnConnectEvent
I/libjingle(13302): BeginSSL: relay.google.com
I/libjingle(13302): Channel socket writable (data_rtp) for the first time
I/libjingle(13302): Changing data state, recv=1 send=1
I/swaag   (13638): P2P Connected.
D/ChimeraCfgMgr( 1856): Loading module com.google.android.gms.games from APK com.google.android.play.games
D/ChimeraModuleLdr( 1856): Module APK com.google.android.play.games already loaded
I/libjingle(13302): HttpRequest completed successfully
I/libjingle(13302): SSL Cleanup
I/swaag   (13638): Connected Set Changed. Currently connected: 2
I/swaag   (13638): Connected Set Changed. Currently connected: 2
I/WaitingRoom(13146): CALLBACK: onRoomConnected()...
I/WaitingRoom(13146): onRoomConnected: statusCode = 0 for room ID: ChoKCQj1jOXnmhsQAhABGAAg____________ARDfqOb_h6Whs8sB
I/swaag   (13638): CMD_GAINED_FOCUS handled
D/BuggyActivity(13638): onActivityResult(4673607,-1,Intent { (has extras) }
V/GamesNativeSDK(13638): Received OnActivityResult with result_code: -1
I/swaag   (13638): Succesfully showed room (created by Bram Stolk): (null)
V/GamesNativeSDK(13638): Received Activity Resume Event.
I/swaag   (13638): Participant 0: Bram Stolk (p_CN-o5v-HpaGzywEQAQ)
I/swaag   (13638): Participant 1: Player 4285 (p_CKbLkbu9yN7cgwEQAQ)
E/GamesNativeSDK(13638): Sending reliable message
E/GamesNativeSDK(13638): Sending reliable message SUCCEEDED
I/swaag   (13638): Starting round 0 with map 0
I/swaag   (13638): geomdb cleared of 5 entries (0 evicted from cache).
I/swaag   (13638): world created for level -1
I/swaag   (13638): objectOfInterest at 0x7847a7f8 named 'player'
I/swaag   (13638): CMD_RESUME handled
D/ChimeraCfgMgr( 1856): Loading module com.google.android.gms.games from APK com.google.android.play.games
D/ChimeraModuleLdr( 1856): Module APK com.google.android.play.games already loaded
I/libjingle(13302): IbbDataTask::ProcessStart() called:
I/libjingle(13302): Got Xmpp DATA: <ibb:data ibb:seq="0" ibb:sid="1" xmlns:ibb="http://jabber.org/protocol/ibb">SUROIGlkPTExNTQ0MzU5NDE4MTc4ODQyNzM0MQA=</ibb:data>
I/libjingle(13302): IbbDataTask::ProcessStart() called:
I/swaag   (13638): Our opponent has Id 115443594181788427341
I/swaag   (13638): player has Id 115443594181788427341 and avatar http://lh4.googleusercontent.com/-ODkLDV2kc4Q/AAAAAAAAAAI/AAAAAAAAACE/aSg52Gvf1K0/s96-ns/
I/libjingle(13302): IbbDataTask::ProcessStart() called:
I/libjingle(13302): Got Xmpp data back: <ibb:data ibb:seq="0" ibb:sid="1" xmlns:ibb="http://jabber.org/protocol/ibb"/>
I/libjingle(13302): static void gtalk::LibjingleJniHelper::DispatchIbbSendResult(jobject, const string&, const string&, bool): Dispatch ID:1
I/libjingle(13302): IbbDataTask::ProcessStart() called:
claywilkinson commented 9 years ago

A couple questions:

  1. How are you sending the data that is not being received? Does the message that is not being received correspond to:
E/GamesNativeSDK(13638): Sending reliable message
E/GamesNativeSDK(13638): Sending reliable message SUCCEEDED

Which version of play game services and the play games app are you running?

stolk commented 9 years ago

Thanks Clayton,

In the non-working case, none of the communication makes it through. I send first a reliable message, followed by an unreliable message 10 times per sec or so. None arrive.

Play Games App: On Galaxy S device it is:

3.2.21 (2197783-038)

On Galaxy Note it is:

3.2.21 (2197783-030)

So it is almost the same, but not quite? What does the -038 and -030 suffixes mean?

The sdk: cpp gpg 1.4.1

The library project: API23, 

android-sdk-linux/extras/google/google_play_services/libproject/google-play-services_lib/

I am not using proguard, btw.

Bram

claywilkinson commented 9 years ago

thanks - would you mind renaming the thread to something like "multiplayer messages not received"?

I'll pass the info along and see what we can find out.

stolk commented 9 years ago

So, in my game I was sending the first message very quickly, in the actual lambda func that handled the WaitingRoomUIResponse. (So the lambda that is passed into gameservices->RealTimeMultiplayer().ShowWaitingRoomUI() func.)

I decided to see if maybe I could delay that first message a bit by sending it in my own thread, not in thread that runs the lambda callbacks.

And I must say that since doing that, the communication seems a lot more stable. I still have to test a little bit more to make sure that the problem is actually gone, but so far, it is looking better.

What is the guidance on what can be done in the lambdas? What kind of calls are allowed in there? Are all lambdas called on one single thread? Does it have a name? I know that nesting lambda's is OK, as the example project does this liberally.

Bram

claywilkinson commented 9 years ago

Interesting sounds like a race condition somewhere. Lambdas work fine. I have not dug into the thread management within the SDK too much. https://developers.google.com/games/services/cpp/GettingStartedNativeClient has some information.

It is plausible that the callbacks for room state changes or players joining are called before some internal data structures are updated, (which sounds like a bug), which is making the sending of messages not work correctly. I'll keep looking into it.

claywilkinson commented 8 years ago

Passed along to the dev. team for the SDK to be addressed sometime in the future.

stolk commented 7 years ago

Ok, I'm finally beginning to get a handle on this. In my code, I was initiating a game_services_->Players().Fetch( id, fetchcallback );

However, I did so in the callback

void OnDataReceived
    (
        gpg::RealTimeRoom const& room, 
        gpg::MultiplayerParticipant const& from_participant, 
        std::vector< uint8_t > data, 
        bool is_reliable
    );

Apparently initiating a fetch while handling a message causes a race condition or something.

After removing that Fetch, I have a very hard time reproducing the issue. I hope it is gone for good now.