search

playgameservices / play-games-plugin-for-unity

Google Play Games plugin for Unity
Other
3.46k stars 966 forks source link

RTMP client corrupting room ID? #553

Closed cluckeyetea closed 8 years ago

cluckeyetea commented 9 years ago

I have my real-time multiplayer game for the most part working with GPGS and the plugin. However it is pretty easy to get the system into a state where you can't ever connect again. The only solution is to restart everything.

I spent a long time thinking this issue was on my side. And tonight I looked through most of the plug-in code and didn't notice anything that looked at fault. Perhaps this is an issue with the GPGS lib itself?

I will give you an example debug log below. Note how the invitation ID I use in my accept call first of all. The "#" char is part of my debug logging only, so this is a straight forward ASCII only UUID. Yet you see in the response from Volley the first part of the ID has been HTTP encoded--unnecessarily from what I can tell. The %08 is a backspace--surely that can't be right!

Then when the real-time agent responds, the chars have gone from being ASCII to Unicode. Anyone familiar with the GPGS Unity Plugin know if this could possibly be something happening on the plugin-side before it gets passed off to the native SDK? I've been fighting with this all week and am at my wits end.

06-03 22:50:55.649: I/Unity(11584): lobby open with current invite #ChEKCQjuhsqv2wYQAhABGAEgARDK7Lv9gseAqaUB 06-03 22:50:55.888: E/Volley(12650): [60186] BasicNetwork.performRequest: Unexpected response code 400 for https://www.googleapis.com/games/v1/rooms/%08%25%0B%E9%94%81%E5%B6%A8sqv2wYQAhABGAEgARDK7Lv9gseAqaUB/join?language=en_US 06-03 22:50:55.889: E/RealTimeAgent(12650): Failed to accept invitation 06-03 22:50:55.892: W/RealTimeAgent(12650): {"errors":[{"domain":"global","reason":"invalid","message":"Invalid id with value \b% 锁嶨sqv2wYQAhABGAEgARDK7Lv9gseAqaUB."}],"code":400} 06-03 22:50:55.902: I/Unity(11584): [Play Games Plugin DLL] 06/03/15 22:50:55 -05:00 DEBUG: Entering internal callback for RealtimeManager#InternalRealTimeRoomCallback 06-03 22:50:55.902: I/Unity(11584):
06-03 22:50:55.902: I/Unity(11584): (Filename: ./artifacts/AndroidManagedGenerated/UnityEngineDebug.cpp Line: 56) 06-03 22:50:55.902: I/Unity(11584): [Play Games Plugin DLL] 06/03/15 22:50:55 -05:00 DEBUG: Entering state: ShutdownState

claywilkinson commented 9 years ago

Thanks for the question - We'll take a look. Can you post more of the log such as when the invitation is received?

cluckeyetea commented 9 years ago

Absolutely. I ran it again tonight and captured more of the trace so hopefully its helpful.

06-06 00:10:25.024: E/SQLiteLog(11781): (284) automatic index on invitations(external_inviter_id)
06-06 00:10:25.032: E/SQLiteLog(11781): (284) automatic index on invitations(external_inviter_id)
06-06 00:10:25.040: I/Unity(29623):  [Play Games Plugin DLL] 06/06/15 0:10:25 -05:00 DEBUG: At this point the invite ID is ChEKCQjuhsqv2wYQAhABGAEgARCClLK2qsnB6_kB
06-06 00:10:25.040: I/Unity(29623):  
06-06 00:10:25.040: I/Unity(29623): (Filename: ./artifacts/AndroidManagedGenerated/UnityEngineDebug.cpp Line: 56)
06-06 00:10:25.059: I/Unity(29623): lobby Game Services invite received--ask player if they want to play.
06-06 00:10:25.059: I/Unity(29623):  
06-06 00:10:25.059: I/Unity(29623): (Filename: ./artifacts/AndroidManagedGenerated/UnityEngineDebug.cpp Line: 56)
06-06 00:10:25.059: I/Unity(29623): User is still considering the invite from Klaud Balls
06-06 00:10:25.059: I/Unity(29623):  
06-06 00:10:25.059: I/Unity(29623): (Filename: ./artifacts/AndroidManagedGenerated/UnityEngineDebug.cpp Line: 56)
06-06 00:10:25.546: I/Unity(29623): lobby on toast show callback
06-06 00:10:25.546: I/Unity(29623):  
06-06 00:10:25.546: I/Unity(29623): (Filename: ./artifacts/AndroidManagedGenerated/UnityEngineDebug.cpp Line: 56)
06-06 00:10:26.960: I/Unity(29623): lobby on toast dismiss callback
06-06 00:10:26.960: I/Unity(29623):  
06-06 00:10:26.960: I/Unity(29623): (Filename: ./artifacts/AndroidManagedGenerated/UnityEngineDebug.cpp Line: 56)
06-06 00:10:26.960: I/Unity(29623):  [Play Games Plugin DLL] 06/06/15 0:10:26 -05:00 DEBUG: Entering state: BeforeRoomCreateStartedState
06-06 00:10:26.960: I/Unity(29623):  
06-06 00:10:26.960: I/Unity(29623): (Filename: ./artifacts/AndroidManagedGenerated/UnityEngineDebug.cpp Line: 56)
06-06 00:10:26.960: I/Unity(29623):  [Play Games Plugin DLL] 06/06/15 0:10:26 -05:00 DEBUG: BeforeRoomCreateStartedState.OnStateEntered: Defaulting to no-op.
06-06 00:10:26.960: I/Unity(29623):  
06-06 00:10:26.960: I/Unity(29623): (Filename: ./artifacts/AndroidManagedGenerated/UnityEngineDebug.cpp Line: 56)
06-06 00:10:26.961: I/Unity(29623): lobby Game Services invite accepted in our app.
06-06 00:10:26.961: I/Unity(29623):  
06-06 00:10:26.961: I/Unity(29623): (Filename: ./artifacts/AndroidManagedGenerated/UnityEngineDebug.cpp Line: 56)
06-06 00:10:26.961: I/Unity(29623): lobby kick off animations
06-06 00:10:26.961: I/Unity(29623):  
06-06 00:10:26.961: I/Unity(29623): (Filename: ./artifacts/AndroidManagedGenerated/UnityEngineDebug.cpp Line: 56)
06-06 00:10:26.961: I/Unity(29623): lobby kick off waiting for friends animations
06-06 00:10:26.961: I/Unity(29623):  
06-06 00:10:26.961: I/Unity(29623): (Filename: ./artifacts/AndroidManagedGenerated/UnityEngineDebug.cpp Line: 56)
06-06 00:10:26.977: D/ChimeraSrvcProxy(11781): Creating service proxy ComponentInfo{com.google.android.gms/com.google.android.gms.games.chimera.GamesAsyncServiceProxy}
06-06 00:10:26.977: D/ChimeraSrvcProxy(11781): Proxying container service ComponentInfo{com.google.android.gms/com.google.android.gms.games.chimera.GamesAsyncServiceProxy} to Chimera service impl com.google.android.gms.games.service.PlayGamesAsyncService
06-06 00:10:26.977: D/ChimeraCfgMgr(11781): Loading module com.google.android.gms.games from APK com.google.android.play.games
06-06 00:10:26.977: D/ChimeraModuleLdr(11781): Module APK com.google.android.play.games already loaded
06-06 00:10:26.987: I/MultiplayerAgent(11781): Returning cached entities
06-06 00:10:26.992: E/SQLiteLog(11781): (284) automatic index on invitations(external_inviter_id)
06-06 00:10:26.993: I/Unity(29623):  [Play Games Plugin DLL] 06/06/15 0:10:26 -05:00 DEBUG: BeforeRoomCreateStartedState.IsRoomConnected: Returning room not connected.
06-06 00:10:26.993: I/Unity(29623):  
06-06 00:10:26.993: I/Unity(29623): (Filename: ./artifacts/AndroidManagedGenerated/UnityEngineDebug.cpp Line: 56)
06-06 00:10:26.994: I/Unity(29623):  [Play Games Plugin DLL] 06/06/15 0:10:26 -05:00 DEBUG: BeforeRoomCreateStartedState.IsRoomConnected: Returning room not connected.
06-06 00:10:26.994: I/Unity(29623):  
06-06 00:10:26.994: I/Unity(29623): (Filename: ./artifacts/AndroidManagedGenerated/UnityEngineDebug.cpp Line: 56)
06-06 00:10:27.000: I/Unity(29623):  [Play Games Plugin DLL] 06/06/15 0:10:27 -05:00 DEBUG: Entering internal callback for RealtimeManager#InternalFetchInvitationsCallback
06-06 00:10:27.000: I/Unity(29623):  
06-06 00:10:27.000: I/Unity(29623): (Filename: ./artifacts/AndroidManagedGenerated/UnityEngineDebug.cpp Line: 56)
06-06 00:10:27.001: I/Unity(29623):  [Play Games Plugin DLL] 06/06/15 0:10:27 -05:00 DEBUG: At this point the invite ID is ChEKCQjuhsqv2wYQAhABGAEgARCClLK2qsnB6_kB
06-06 00:10:27.001: I/Unity(29623):  
06-06 00:10:27.001: I/Unity(29623): (Filename: ./artifacts/AndroidManagedGenerated/UnityEngineDebug.cpp Line: 56)
06-06 00:10:27.001: I/Unity(29623):  [Play Games Plugin DLL] 06/06/15 0:10:27 -05:00 DEBUG: OnData Callback has addr: 4100
06-06 00:10:27.001: I/Unity(29623):  
06-06 00:10:27.001: I/Unity(29623): (Filename: ./artifacts/AndroidManagedGenerated/UnityEngineDebug.cpp Line: 56)
06-06 00:10:27.001: I/Unity(29623):  [Play Games Plugin DLL] 06/06/15 0:10:27 -05:00 DEBUG: BeforeRoomCreateStartedState.IsNonPreemptable: Is preemptable by default.
06-06 00:10:27.001: I/Unity(29623):  
06-06 00:10:27.001: I/Unity(29623): (Filename: ./artifacts/AndroidManagedGenerated/UnityEngineDebug.cpp Line: 56)
06-06 00:10:27.001: I/Unity(29623):  [Play Games Plugin DLL] 06/06/15 0:10:27 -05:00 DEBUG: Entering state: RoomCreationPendingState
06-06 00:10:27.001: I/Unity(29623):  
06-06 00:10:27.001: I/Unity(29623): (Filename: ./artifacts/AndroidManagedGenerated/UnityEngineDebug.cpp Line: 56)
06-06 00:10:27.002: I/Unity(29623):  [Play Games Plugin DLL] 06/06/15 0:10:27 -05:00 DEBUG: RoomCreationPendingState.OnStateEntered: Defaulting to no-op.
06-06 00:10:27.002: I/Unity(29623):  
06-06 00:10:27.002: I/Unity(29623): (Filename: ./artifacts/AndroidManagedGenerated/UnityEngineDebug.cpp Line: 56)
06-06 00:10:27.030: I/GLSUser(1873): [GLSUser] getTokenFromCache: [account: <ELLIDED:-25291>, callingPkg: com.marzoa.ruletafree, service: oauth2:https://www.googleapis.com/auth/games https://www.googleapis.com/auth/appstate https://www.googleapis.com/auth/drive.appdata]
06-06 00:10:27.079: I/GLSUser(1873): [GLSUser] getTokenFromCache: [account: <ELLIDED:-25291>, callingPkg: com.marzoa.ruletafree, service: oauth2:https://www.googleapis.com/auth/games https://www.googleapis.com/auth/appstate https://www.googleapis.com/auth/drive.appdata]
06-06 00:10:27.087: I/GLSUser(1873): [GLSUser] getTokenFromGoogle [account: <ELLIDED:-25291>, callingPkg: com.marzoa.ruletafree, service: oauth2:https://www.googleapis.com/auth/games https://www.googleapis.com/auth/appstate https://www.googleapis.com/auth/drive.appdata
06-06 00:10:27.153: I/SBar.MotoNetworkCtrlr(1306): PhoneStateListener[0].onSignalStrengthsChanged:SignalStrength: 99 0 -120 -160 -120 -1 -1 16 -111 -14 -8 2147483647 2147483647 gsm|lte 14 -81 0 true 4 4 0 0 2 99 99 99 5 0 level=2
06-06 00:10:27.216: I/GLSUser(1873): [GLSUser] getAuthtoken(<ELLIDED:-25291>, oauth2:https://www.googleapis.com/auth/games https://www.googleapis.com/auth/appstate https://www.googleapis.com/auth/drive.appdata) -> status: null)
06-06 00:10:27.216: I/GLSUser(1873): [GLSUser] Extracting token using key: Auth
06-06 00:10:27.258: W/GLSUser(1873): [GLSUser] Permission for com.marzoa.ruletafree to access oauth2:https://www.googleapis.com/auth/games https://www.googleapis.com/auth/appstate https://www.googleapis.com/auth/drive.appdata will be managed remotely.
06-06 00:10:27.279: I/libjingle(29910): Token type:OAuth2
06-06 00:10:27.279: I/libjingle(29910): Final XMPP server hostname talk.google.com port to 5222
06-06 00:10:27.327: I/libjingle(29910): OpenSSLAdapter::OnConnectEvent
06-06 00:10:27.396: I/SBar.MotoNetworkCtrlr(1306): onReceive: WifiManager.RSSI_CHANGED_ACTION Received
06-06 00:10:27.415: I/libjingle(29910): BeginSSL: talk.google.com
06-06 00:10:27.782: I/libjingle(29910): Starting Jingle info task.
06-06 00:10:27.783: I/libjingle(29910): IbbDataTask::ProcessStart() called:
06-06 00:10:27.784: I/libjingle(29910): ProcessStart()::Sending Jingle info stanza.
06-06 00:10:27.785: I/libjingle(29910): BuzzSubscriptionsTask::SubscribeTask::ProcessStart() called:
06-06 00:10:27.786: I/libjingle(29910): void games_rtmp::BuzzSubscription::CheckOverride(): Channel GAMES_NOTIFICATION_CHANNEL default: games.google.com
06-06 00:10:27.787: I/libjingle(29910): void games_rtmp::BuzzSubscription::CheckOverride(): Notifier GAMES_NOTIFICATION_JID default: games@google.com
06-06 00:10:27.789: I/libjingle(29910): void games_rtmp::BuzzSubscription::CheckOverride(): Channel GAMES_BUZZBOT_CHANNEL default: games.google.com/buzzbot
06-06 00:10:27.790: I/libjingle(29910): void games_rtmp::BuzzSubscription::CheckOverride(): Notifier GAMES_BUZZBOT_JID default: play-presence@games.bot.talk.google.com
06-06 00:10:27.791: I/libjingle(29910): SUBSCRIBE STANZA: <cli:iq type="set" to="games@ob.talk.google.com" id="9" xmlns:cli="jabber:client"><subscribe xmlns="google:push"><item channel="games.google.com" from="games@google.com"/><item channel="games.google.com/buzzbot" from="play-presence@games.bot.talk.google.com"/></subscribe></cli:iq>
06-06 00:10:27.792: I/libjingle(29910): Send Stanza return ok:
06-06 00:10:27.831: I/libjingle(29910): OnJingleInfo called. Setting relay/stun hosts.
06-06 00:10:27.875: I/libjingle(29910): SubscribeTask HandleStanza : <cli:iq to="games@ob.talk.google.com/games_andrE6E5C179" from="games@ob.talk.google.com" id="9" type="result" xmlns:cli="jabber:client"/>
06-06 00:10:27.878: I/libjingle(29910): void games_rtmp::BuzzSubscriptionsTask::SubscriptionSuccess(): Subscription Successful.
06-06 00:10:27.889: D/ChimeraSrvcProxy(11781): Creating service proxy ComponentInfo{com.google.android.gms/com.google.android.gms.games.chimera.GamesAsyncServiceProxy}
06-06 00:10:27.889: D/ChimeraSrvcProxy(11781): Proxying container service ComponentInfo{com.google.android.gms/com.google.android.gms.games.chimera.GamesAsyncServiceProxy} to Chimera service impl com.google.android.gms.games.service.PlayGamesAsyncService
06-06 00:10:27.889: D/ChimeraCfgMgr(11781): Loading module com.google.android.gms.games from APK com.google.android.play.games
06-06 00:10:27.889: D/ChimeraModuleLdr(11781): Module APK com.google.android.play.games already loaded
06-06 00:10:27.928: I/GLSUser(1873): [GLSUser] getTokenFromCache: [account: <ELLIDED:-25291>, callingPkg: com.marzoa.ruletafree, service: oauth2:https://www.googleapis.com/auth/games https://www.googleapis.com/auth/appstate https://www.googleapis.com/auth/drive.appdata]
06-06 00:10:28.074: E/Volley(11781): [80327] BasicNetwork.performRequest: Unexpected response code 400 for https://www.googleapis.com/games/v1/rooms/(%2C%D1%B9T%01%E5%B6%A8sqv2wYQAhABGAEgARCClLK2qsnB6_kB/join?language=en_US
06-06 00:10:28.076: E/RealTimeAgent(11781): Failed to accept invitation
06-06 00:10:28.095: W/RealTimeAgent(11781): {"errors":[{"domain":"global","reason":"invalid","message":"Invalid id with value (,ѹT嶨sqv2wYQAhABGAEgARCClLK2qsnB6_kB."}],"code":400}
06-06 00:10:28.102: I/Unity(29623):  [Play Games Plugin DLL] 06/06/15 0:10:28 -05:00 DEBUG: Entering internal callback for RealtimeManager#InternalRealTimeRoomCallback
06-06 00:10:28.102: I/Unity(29623):  
06-06 00:10:28.102: I/Unity(29623): (Filename: ./artifacts/AndroidManagedGenerated/UnityEngineDebug.cpp Line: 56)
06-06 00:10:28.102: I/Unity(29623):  [Play Games Plugin DLL] 06/06/15 0:10:28 -05:00 DEBUG: Entering state: ShutdownState
06-06 00:10:28.102: I/Unity(29623):  
06-06 00:10:28.102: I/Unity(29623): (Filename: ./artifacts/AndroidManagedGenerated/UnityEngineDebug.cpp Line: 56)
06-06 00:10:28.102: I/Unity(29623):  [Play Games Plugin DLL] 06/06/15 0:10:28 -05:00 DEBUG: ShutdownState.OnStateEntered: Defaulting to no-op.
06-06 00:10:28.102: I/Unity(29623):  
06-06 00:10:28.102: I/Unity(29623): (Filename: ./artifacts/AndroidManagedGenerated/UnityEngineDebug.cpp Line: 56)
06-06 00:10:28.112: I/Unity(29623): OnRoomConnected
06-06 00:10:28.112: I/Unity(29623):  
06-06 00:10:28.112: I/Unity(29623): (Filename: ./artifacts/AndroidManagedGenerated/UnityEngineDebug.cpp Line: 56)
06-06 00:10:28.112: I/Unity(29623): LOBBY: lobby game setup complete
06-06 00:10:28.112: I/Unity(29623): LOBBY: game setup is OK = false
cluckeyetea commented 9 years ago

Just FYI it appears I can avoid this error by always making my user accept from the GPGS inbox. So perhaps somehow the room id is getting corrupting marshaling the string between managed and unmanaged code in the plugin. Though I don't see that in my logging. Anyway for me I don't have a hard and fast requirement to do my game accepts in game so for the time being I'm just going to send the user to his/her inbox.

claywilkinson commented 8 years ago

I'm closing this one. We can't seem to reproduce the problem. It is possible that in the various updates since June that it was fixed. Please re-open if you can reproduce it and share the versions of play-services, play games app and the version of the Unity plugin.