Frequest disconnections with error 1040
Options
Hi,
We're using Photon-AndroidNDK_v3-2-2-0_Could_SDK - not the most recent android SDK.
We're using the free plan (20 CCU) for development.
We're getting frequent disconnections while doing QA on our game, with error code 1040. I'm trying to investigate why.
Here's a log from a weird case:
[code2=text]-- Leaving a game room
02-03 15:58:23.955: I/demo-loadBalancing(13603): player 1 587879931 has joined the game
02-03 15:58:28.525: I/demo-loadBalancing(13603): leaving game room
02-03 15:58:28.920: I/demo-loadBalancing(13603): 2014-02-03 15:58:28,929404 INFO LoadBalancing-cpp\LoadBalancingClient.cpp onOperationResponse() line: 306 - OperationResponse - operationCode: 254, returnCode: 0 {}
02-03 15:58:30.380: I/demo-loadBalancing(13603): 2014-02-03 15:58:30,386824 INFO LoadBalancing-cpp\LoadBalancingClient.cpp onStatusChanged() line: 510 - connected to masterserver
02-03 15:58:30.945: I/demo-loadBalancing(13603): 2014-02-03 15:58:30,949986 INFO EnetPeer.cpp dispatchIncomingCommands() line: 327 - skipped dispatching of old command
02-03 15:58:31.175: I/demo-loadBalancing(13603): 2014-02-03 15:58:31,184127 INFO AuthenticatingClient.cpp opAuthenticate() line: 66 - OperationRequest - operationCode: 230 {224="286b7ed2-0bd6-4edf-a2cd-70cdf741692a", 220="1.0", 225="587879931"}
02-03 15:58:31.705: I/demo-loadBalancing(13603): 2014-02-03 15:58:31,713734 INFO LoadBalancing-cpp\LoadBalancingClient.cpp onOperationResponse() line: 306 - OperationResponse - operationCode: 230, returnCode: 0 {}
02-03 15:58:32.270: I/demo-loadBalancing(13603): 2014-02-03 15:58:32,275402 INFO LoadBalancing-cpp\LoadBalancingClient.cpp onOperationResponse() line: 306 - OperationResponse - operationCode: 229, returnCode: 0 {}
02-03 15:58:32.270: I/demo-loadBalancing(13603): 2014-02-03 15:58:32,275795 INFO NetworkLogic.cpp leaveRoomReturn() line: 476 -
02-03 15:58:32.270: I/demo-loadBalancing(13603): game room has been successfully left
-- Joining another game room (5 seconds later)
02-03 15:58:37.700: I/demo-loadBalancing(13603): 2014-02-03 15:58:37,708541 INFO EnetPeer.cpp sendOutgoingCommands() line: 187 - going to resend pCommand: time: 8381 = 8371 sentCount: 1, original sentTime: 7586
02-03 15:58:39.555: I/demo-loadBalancing(13603): 2014-02-03 15:58:39,562271 INFO EnetPeer.cpp removeSentReliableCommand() line: 976 - ACK w/o command! ackReceivedReliableSequenceNumber=5 ackReceivedChannel=255
02-03 15:58:53.225: I/demo-loadBalancing(13603): creating game "GameRoom_534974_234376"
02-03 15:58:53.950: I/demo-loadBalancing(13603): 2014-02-03 15:58:53,958688 INFO LoadBalancing-cpp\LoadBalancingClient.cpp onOperationResponse() line: 306 - OperationResponse - operationCode: 227, returnCode: 0 {230="180.131.139.238:5056", 255="GameRoom_534974_234376"}
02-03 15:58:55.705: I/demo-loadBalancing(13603): 2014-02-03 15:58:55,712662 INFO LoadBalancing-cpp\LoadBalancingClient.cpp onStatusChanged() line: 505 - connected to gameserver
02-03 15:58:56.210: I/demo-loadBalancing(13603): 2014-02-03 15:58:56,216171 INFO AuthenticatingClient.cpp opAuthenticate() line: 66 - OperationRequest - operationCode: 230 {224="286b7ed2-0bd6-4edf-a2cd-70cdf741692a", 220="1.0", 225="587879931"}
02-03 15:58:56.995: I/demo-loadBalancing(13603): 2014-02-03 15:58:57,004068 INFO EnetPeer.cpp dispatchIncomingCommands() line: 327 - skipped dispatching of old command
02-03 15:58:57.195: I/demo-loadBalancing(13603): 2014-02-03 15:58:57,203012 INFO EnetPeer.cpp sendOutgoingCommands() line: 187 - going to resend pCommand: time: 2715 = 2707 sentCount: 1, original sentTime: 1742
02-03 15:58:57.230: I/demo-loadBalancing(13603): 2014-02-03 15:58:57,235946 INFO EnetPeer.cpp sendOutgoingCommands() line: 187 - going to resend pCommand: time: 2748 = 2707 sentCount: 1, original sentTime: 1742
02-03 15:58:57.595: I/demo-loadBalancing(13603): 2014-02-03 15:58:57,602072 INFO LoadBalancing-cpp\LoadBalancingClient.cpp onOperationResponse() line: 306 - OperationResponse - operationCode: 230, returnCode: 0 {}
02-03 15:58:57.695: I/demo-loadBalancing(13603): 2014-02-03 15:58:57,700043 INFO EnetPeer.cpp removeSentReliableCommand() line: 976 - ACK w/o command! ackReceivedReliableSequenceNumber=3 ackReceivedChannel=20
02-03 15:58:57.760: I/demo-loadBalancing(13603): 2014-02-03 15:58:57,765694 INFO EnetPeer.cpp removeSentReliableCommand() line: 976 - ACK w/o command! ackReceivedReliableSequenceNumber=3 ackReceivedChannel=0
02-03 15:58:58.555: I/demo-loadBalancing(13603): 2014-02-03 15:58:58,563093 INFO EnetPeer.cpp sendOutgoingCommands() line: 187 - going to resend pCommand: time: 4075 = 4045 sentCount: 1, original sentTime: 3080
02-03 15:58:58.985: I/demo-loadBalancing(13603): 2014-02-03 15:58:58,992661 INFO LoadBalancing-cpp\LoadBalancingClient.cpp onOperationResponse() line: 306 - OperationResponse - operationCode: 227, returnCode: 0 {254=1, 248={"rsih"=69612190, 250=["rsih", "rsil", "game_type_yan"], "game_type_yan"=2013, 255=4, 254=false, "rsil"=2010985213}}
02-03 15:58:58.985: I/demo-loadBalancing(13603): 2014-02-03 15:58:58,993101 INFO NetworkLogic.cpp createRoomReturn() line: 392 -
02-03 15:58:58.985: I/demo-loadBalancing(13603): 2014-02-03 15:58:58,993237 INFO NetworkLogic.cpp createRoomReturn() line: 400 - localPlayerNr: 1
02-03 15:58:58.985: I/demo-loadBalancing(13603): game room "GameRoom_534974_234376" has been created
02-03 15:58:58.985: I/demo-loadBalancing(13603): 2014-02-03 15:58:58,994600 INFO NetworkLogic.cpp joinRoomEventAction() line: 341 - 587879931 joined the game
02-03 15:58:58.990: I/demo-loadBalancing(13603): player 1 587879931 has joined the game
02-03 15:58:59.205: I/demo-loadBalancing(13603): 2014-02-03 15:58:59,211633 INFO EnetPeer.cpp removeSentReliableCommand() line: 976 - ACK w/o command! ackReceivedReliableSequenceNumber=4 ackReceivedChannel=20
02-03 15:59:07.025: I/demo-loadBalancing(13603): 2014-02-03 15:59:07,034597 INFO EnetPeer.cpp sendOutgoingCommands() line: 187 - going to resend pCommand: time: 12547 = 12527 sentCount: 1, original sentTime: 10095
02-03 15:59:09.975: I/demo-loadBalancing(13603): 2014-02-03 15:59:09,982305 INFO EnetPeer.cpp removeSentReliableCommand() line: 976 - ACK w/o command! ackReceivedReliableSequenceNumber=7 ackReceivedChannel=255
02-03 15:59:13.585: I/demo-loadBalancing(13603): 2014-02-03 15:59:13,594402 INFO EnetPeer.cpp sendOutgoingCommands() line: 187 - going to resend pCommand: time: 19107 = 19103 sentCount: 1, original sentTime: 14998
02-03 15:59:17.460: I/demo-loadBalancing(13603): 2014-02-03 15:59:17,468609 INFO EnetPeer.cpp removeSentReliableCommand() line: 976 - ACK w/o command! ackReceivedReliableSequenceNumber=8 ackReceivedChannel=255
02-03 15:59:25.455: I/demo-loadBalancing(13603): 2014-02-03 15:59:25,460257 INFO EnetPeer.cpp sendOutgoingCommands() line: 153 - disconnect due to retry timeout (max retry time) time: 30973 originalSentTime: 25969
02-03 15:59:25.455: I/demo-loadBalancing(13603): 2014-02-03 15:59:25,460501 ERROR NetworkLogic.cpp connectionErrorReturn() line: 313 - code: 1040
02-03 15:59:25.455: I/demo-loadBalancing(13603): connection failed with error 1040
02-03 15:59:25.455: I/demo-loadBalancing(13603): 2014-02-03 15:59:25,461834 INFO NetworkLogic.cpp disconnectReturn() line: 385 -
02-03 15:59:25.455: I/demo-loadBalancing(13603): disconnected[/code2]
Note the "going to resend pComand" and then "ACK w/o command!", and the many "skipped dispatching of old command".
The "ACK w/o command!" messages started appearing only after joining the second room.
Device had internet connection (original log contains successful HTTP requests app has made at that time).
Are we doing something wrong?
Can you point me at reasons why we're getting disconnections with error 1040? (not all cases are like the one above).
Thanks!
We're using Photon-AndroidNDK_v3-2-2-0_Could_SDK - not the most recent android SDK.
We're using the free plan (20 CCU) for development.
We're getting frequent disconnections while doing QA on our game, with error code 1040. I'm trying to investigate why.
Here's a log from a weird case:
[code2=text]-- Leaving a game room
02-03 15:58:23.955: I/demo-loadBalancing(13603): player 1 587879931 has joined the game
02-03 15:58:28.525: I/demo-loadBalancing(13603): leaving game room
02-03 15:58:28.920: I/demo-loadBalancing(13603): 2014-02-03 15:58:28,929404 INFO LoadBalancing-cpp\LoadBalancingClient.cpp onOperationResponse() line: 306 - OperationResponse - operationCode: 254, returnCode: 0 {}
02-03 15:58:30.380: I/demo-loadBalancing(13603): 2014-02-03 15:58:30,386824 INFO LoadBalancing-cpp\LoadBalancingClient.cpp onStatusChanged() line: 510 - connected to masterserver
02-03 15:58:30.945: I/demo-loadBalancing(13603): 2014-02-03 15:58:30,949986 INFO EnetPeer.cpp dispatchIncomingCommands() line: 327 - skipped dispatching of old command
02-03 15:58:31.175: I/demo-loadBalancing(13603): 2014-02-03 15:58:31,184127 INFO AuthenticatingClient.cpp opAuthenticate() line: 66 - OperationRequest - operationCode: 230 {224="286b7ed2-0bd6-4edf-a2cd-70cdf741692a", 220="1.0", 225="587879931"}
02-03 15:58:31.705: I/demo-loadBalancing(13603): 2014-02-03 15:58:31,713734 INFO LoadBalancing-cpp\LoadBalancingClient.cpp onOperationResponse() line: 306 - OperationResponse - operationCode: 230, returnCode: 0 {}
02-03 15:58:32.270: I/demo-loadBalancing(13603): 2014-02-03 15:58:32,275402 INFO LoadBalancing-cpp\LoadBalancingClient.cpp onOperationResponse() line: 306 - OperationResponse - operationCode: 229, returnCode: 0 {}
02-03 15:58:32.270: I/demo-loadBalancing(13603): 2014-02-03 15:58:32,275795 INFO NetworkLogic.cpp leaveRoomReturn() line: 476 -
02-03 15:58:32.270: I/demo-loadBalancing(13603): game room has been successfully left
-- Joining another game room (5 seconds later)
02-03 15:58:37.700: I/demo-loadBalancing(13603): 2014-02-03 15:58:37,708541 INFO EnetPeer.cpp sendOutgoingCommands() line: 187 - going to resend pCommand: time: 8381 = 8371 sentCount: 1, original sentTime: 7586
02-03 15:58:39.555: I/demo-loadBalancing(13603): 2014-02-03 15:58:39,562271 INFO EnetPeer.cpp removeSentReliableCommand() line: 976 - ACK w/o command! ackReceivedReliableSequenceNumber=5 ackReceivedChannel=255
02-03 15:58:53.225: I/demo-loadBalancing(13603): creating game "GameRoom_534974_234376"
02-03 15:58:53.950: I/demo-loadBalancing(13603): 2014-02-03 15:58:53,958688 INFO LoadBalancing-cpp\LoadBalancingClient.cpp onOperationResponse() line: 306 - OperationResponse - operationCode: 227, returnCode: 0 {230="180.131.139.238:5056", 255="GameRoom_534974_234376"}
02-03 15:58:55.705: I/demo-loadBalancing(13603): 2014-02-03 15:58:55,712662 INFO LoadBalancing-cpp\LoadBalancingClient.cpp onStatusChanged() line: 505 - connected to gameserver
02-03 15:58:56.210: I/demo-loadBalancing(13603): 2014-02-03 15:58:56,216171 INFO AuthenticatingClient.cpp opAuthenticate() line: 66 - OperationRequest - operationCode: 230 {224="286b7ed2-0bd6-4edf-a2cd-70cdf741692a", 220="1.0", 225="587879931"}
02-03 15:58:56.995: I/demo-loadBalancing(13603): 2014-02-03 15:58:57,004068 INFO EnetPeer.cpp dispatchIncomingCommands() line: 327 - skipped dispatching of old command
02-03 15:58:57.195: I/demo-loadBalancing(13603): 2014-02-03 15:58:57,203012 INFO EnetPeer.cpp sendOutgoingCommands() line: 187 - going to resend pCommand: time: 2715 = 2707 sentCount: 1, original sentTime: 1742
02-03 15:58:57.230: I/demo-loadBalancing(13603): 2014-02-03 15:58:57,235946 INFO EnetPeer.cpp sendOutgoingCommands() line: 187 - going to resend pCommand: time: 2748 = 2707 sentCount: 1, original sentTime: 1742
02-03 15:58:57.595: I/demo-loadBalancing(13603): 2014-02-03 15:58:57,602072 INFO LoadBalancing-cpp\LoadBalancingClient.cpp onOperationResponse() line: 306 - OperationResponse - operationCode: 230, returnCode: 0 {}
02-03 15:58:57.695: I/demo-loadBalancing(13603): 2014-02-03 15:58:57,700043 INFO EnetPeer.cpp removeSentReliableCommand() line: 976 - ACK w/o command! ackReceivedReliableSequenceNumber=3 ackReceivedChannel=20
02-03 15:58:57.760: I/demo-loadBalancing(13603): 2014-02-03 15:58:57,765694 INFO EnetPeer.cpp removeSentReliableCommand() line: 976 - ACK w/o command! ackReceivedReliableSequenceNumber=3 ackReceivedChannel=0
02-03 15:58:58.555: I/demo-loadBalancing(13603): 2014-02-03 15:58:58,563093 INFO EnetPeer.cpp sendOutgoingCommands() line: 187 - going to resend pCommand: time: 4075 = 4045 sentCount: 1, original sentTime: 3080
02-03 15:58:58.985: I/demo-loadBalancing(13603): 2014-02-03 15:58:58,992661 INFO LoadBalancing-cpp\LoadBalancingClient.cpp onOperationResponse() line: 306 - OperationResponse - operationCode: 227, returnCode: 0 {254=1, 248={"rsih"=69612190, 250=["rsih", "rsil", "game_type_yan"], "game_type_yan"=2013, 255=4, 254=false, "rsil"=2010985213}}
02-03 15:58:58.985: I/demo-loadBalancing(13603): 2014-02-03 15:58:58,993101 INFO NetworkLogic.cpp createRoomReturn() line: 392 -
02-03 15:58:58.985: I/demo-loadBalancing(13603): 2014-02-03 15:58:58,993237 INFO NetworkLogic.cpp createRoomReturn() line: 400 - localPlayerNr: 1
02-03 15:58:58.985: I/demo-loadBalancing(13603): game room "GameRoom_534974_234376" has been created
02-03 15:58:58.985: I/demo-loadBalancing(13603): 2014-02-03 15:58:58,994600 INFO NetworkLogic.cpp joinRoomEventAction() line: 341 - 587879931 joined the game
02-03 15:58:58.990: I/demo-loadBalancing(13603): player 1 587879931 has joined the game
02-03 15:58:59.205: I/demo-loadBalancing(13603): 2014-02-03 15:58:59,211633 INFO EnetPeer.cpp removeSentReliableCommand() line: 976 - ACK w/o command! ackReceivedReliableSequenceNumber=4 ackReceivedChannel=20
02-03 15:59:07.025: I/demo-loadBalancing(13603): 2014-02-03 15:59:07,034597 INFO EnetPeer.cpp sendOutgoingCommands() line: 187 - going to resend pCommand: time: 12547 = 12527 sentCount: 1, original sentTime: 10095
02-03 15:59:09.975: I/demo-loadBalancing(13603): 2014-02-03 15:59:09,982305 INFO EnetPeer.cpp removeSentReliableCommand() line: 976 - ACK w/o command! ackReceivedReliableSequenceNumber=7 ackReceivedChannel=255
02-03 15:59:13.585: I/demo-loadBalancing(13603): 2014-02-03 15:59:13,594402 INFO EnetPeer.cpp sendOutgoingCommands() line: 187 - going to resend pCommand: time: 19107 = 19103 sentCount: 1, original sentTime: 14998
02-03 15:59:17.460: I/demo-loadBalancing(13603): 2014-02-03 15:59:17,468609 INFO EnetPeer.cpp removeSentReliableCommand() line: 976 - ACK w/o command! ackReceivedReliableSequenceNumber=8 ackReceivedChannel=255
02-03 15:59:25.455: I/demo-loadBalancing(13603): 2014-02-03 15:59:25,460257 INFO EnetPeer.cpp sendOutgoingCommands() line: 153 - disconnect due to retry timeout (max retry time) time: 30973 originalSentTime: 25969
02-03 15:59:25.455: I/demo-loadBalancing(13603): 2014-02-03 15:59:25,460501 ERROR NetworkLogic.cpp connectionErrorReturn() line: 313 - code: 1040
02-03 15:59:25.455: I/demo-loadBalancing(13603): connection failed with error 1040
02-03 15:59:25.455: I/demo-loadBalancing(13603): 2014-02-03 15:59:25,461834 INFO NetworkLogic.cpp disconnectReturn() line: 385 -
02-03 15:59:25.455: I/demo-loadBalancing(13603): disconnected[/code2]
Note the "going to resend pComand" and then "ACK w/o command!", and the many "skipped dispatching of old command".
The "ACK w/o command!" messages started appearing only after joining the second room.
Device had internet connection (original log contains successful HTTP requests app has made at that time).
Are we doing something wrong?
Can you point me at reasons why we're getting disconnections with error 1040? (not all cases are like the one above).
Thanks!
0
Comments
-
Hi natasky.
This looks like you have a bad connection with a high jitter and a high latency between you clients and the used cloud region.
Have you tried to use a different cloud region?
Have you tried if connecting to a local Photon server instance instead of the Photon cloud makes a difference?
Could you please log the values, that get returned by PhotonPeer::getRoundTripTime() and PhotonPeer::getRoundTripTimeVariance(), once every service() call?
Please download and run winmtr: http://winmtr.net/ to check the connection quality between your clients and the cloud region and to find out which part of the route is the cause of the problem.0
