Temporarily 'Game full' while room still has space. Double counting joins?
Options
Erethan
✭✭
I am hosting a photon server on my machine and using PUN 2 to connect clients to the server.
However, it seems that clients are double counting for a while (~10s) when they join a room.
Max players -> Max can join
2 -> 1
3 -> 2
4 -> 2
5 -> 3
I call 'JoinOrCreateRoom("Room", roomOptions, TypedLobby.Default)' to create/join the room, and from the client logs, I am sure that I only call this once.
What else could be happening?
However, it seems that clients are double counting for a while (~10s) when they join a room.
Max players -> Max can join
2 -> 1
3 -> 2
4 -> 2
5 -> 3
I call 'JoinOrCreateRoom("Room", roomOptions, TypedLobby.Default)' to create/join the room, and from the client logs, I am sure that I only call this once.
What else could be happening?
0
Comments
-
I am not sure, but from the Logs, I would guess that clients are still on the master server when they get this error.
I joined the room with up to 3 clients (counting with the Master client who created the room)
Max players -> MasterClient -> Second client-> Third client
2 -> OK -> 'Game full' -> x
3 -> OK -> OK -> 'Game full'
4 -> OK -> OK -> 'Game full'
5 -> OK -> OK -> OK
0 -
I just realized you might have meant call JoinRoom instead of JoinOrCreateRoom for the other clients. I'm sorry.
I checked that, and I the same issue occurs0 -
When a room is created, 'OnRoomListUpdate' does say that there are 2 players inside that room. When another player joints, it increases to 4.
If I wait for a while, this number halfes back to what it's supposed to be. However, if another client joins the room, this client will still count as 2 for a while
0 -
Activate debug logging on GS.
It sounds like bug.
Please collect the logs and send them to me. Are you using ExpectedUsers?
best,
ilya0 -
I am not sure where exactly I am supposed to change to enable debugging on the GS.
I've changed this config file:
'...\deploy\Loadbalancing\GameServer\bin\log4net.config'
at
'<log4net debug="false">'
to
'<log4net debug="true">'
But I saw no effect on 'deploy\log\GSGame.log'. However I am not sure if I changed the right file and if I am looking at the correct logs.
Below gives some more info about logging but I could not figure it out on how to enable logging on the GS
https://doc.photonengine.com/en-US/server/current/app-framework/logging#the_unmanaged_photon_socket_server_log
Also, I am not using ExpectedUsers
0 -
yes, you found correct log4net.config
it has this:
<root>
<level value="INFO" />
<appender-ref ref="LogFileAppender" />
<appender-ref ref="ConsoleAppender" />
</root>
INFO should be changed to DEBUG
best,
ilya
0 -
As I have not managed to get the Photon Server v5 working, I recorded the GameServer logs. In the below version, I've cut many consecutive 'DEBUG Photon.Hive.Plugin.RaiseEventCallInfo - Continue.'.
GSGame.log:
2020-08-06 15:06:53,565 [17] DEBUG Photon.LoadBalancing.GameServer.GameApplication - CreatePeer for NetworkedVR
2020-08-06 15:06:53,572 [17] DEBUG Photon.LoadBalancing.GameServer.GameApplication - incoming game peer at 192.168.0.102:5056 from 192.168.0.102:64398
2020-08-06 15:06:53,732 [9] DEBUG Photon.LoadBalancing.GameServer.GameClientPeer - OnOperationRequest: conId=5, opCode=230
2020-08-06 15:06:53,740 [9] DEBUG Photon.LoadBalancing.GameServer.GameClientPeer - HandleTokenlessAuthenticateRequest - Token Authentication done. UserId: 0e4323b6-eea0-40a9-91bc-b0f26c8dbf8b
2020-08-06 15:06:53,767 [13] DEBUG Photon.LoadBalancing.GameServer.GameClientPeer - OnOperationRequest: conId=5, opCode=227
2020-08-06 15:06:53,779 [13] DEBUG Photon.Hive.HivePeer - RemovePeerFromCurrentRoom: Room Reference is null for p:GameClientPeer: PID 5, IsConnected: True, IsDisposed: False, Last Activity: Operation 227 at UTC 06/08/2020 18:06:53 in Room , IP 192.168.0.102:64398,
2020-08-06 15:06:53,791 [13] DEBUG Photon.Hive.Caching.RoomCacheBase - Created room instance reference: roomName=Room, referenceCount=1
2020-08-06 15:06:53,800 [19] DEBUG Photon.Hive.Plugin.CreateGameCallInfo - Continue.
2020-08-06 15:06:53,808 [19] DEBUG Photon.Hive.HiveGame - Processing Join from IP: 192.168.0.102 to port: 5056
2020-08-06 15:06:53,818 [19] DEBUG Photon.Hive.Collections.ActorsManager - Actor added: 1 0e4323b6-eea0-40a9-91bc-b0f26c8dbf8b to game: Room -- peer:GameClientPeer: PID 5, IsConnected: True, IsDisposed: False, Last Activity: Operation 227 at UTC 06/08/2020 18:06:53 in Room Room, IP 192.168.0.102:64398,
2020-08-06 15:06:53,827 [19] DEBUG Photon.Hive.HiveGame - JoinApplyGameStateChanges: Actor 1 is added. MasterClientId is 1
2020-08-06 15:06:53,836 [19] DEBUG Photon.Hive.HiveGame - Created Game - name=Room, lobyName=, lobbyType=Default, maxPlayers=16, IsOpen=True, IsVisible=True, EmptyRoomLiveTime=0, PlayerTTL=0, CheckUserOnJoin=True, PublishUserId=False, ExpectedUsers=
2020-08-06 15:06:53,844 [19] DEBUG Photon.LoadBalancing.GameServer.Game - UpdateGameStateOnMasterOnCreate: game - 'Room'
2020-08-06 15:06:53,962 [18] DEBUG Photon.Hive.Plugin.RaiseEventCallInfo - Continue.
2020-08-06 15:06:56,682 [9] DEBUG Photon.LoadBalancing.GameServer.GameApplication - CreatePeer for NetworkedVR
2020-08-06 15:06:56,690 [9] DEBUG Photon.LoadBalancing.GameServer.GameApplication - incoming game peer at 192.168.0.102:5056 from 192.168.0.102:64403
2020-08-06 15:06:56,782 [15] DEBUG Photon.LoadBalancing.GameServer.GameClientPeer - OnOperationRequest: conId=7, opCode=230
2020-08-06 15:06:56,791 [15] DEBUG Photon.LoadBalancing.GameServer.GameClientPeer - HandleTokenlessAuthenticateRequest - Token Authentication done. UserId: c4b08bde-2613-433a-ae6a-0b61ca08f39e
2020-08-06 15:06:56,883 [18] DEBUG Photon.LoadBalancing.GameServer.GameClientPeer - OnOperationRequest: conId=7, opCode=226
2020-08-06 15:06:56,892 [18] DEBUG Photon.Hive.HivePeer - RemovePeerFromCurrentRoom: Room Reference is null for p:GameClientPeer: PID 7, IsConnected: True, IsDisposed: False, Last Activity: Operation 226 at UTC 06/08/2020 18:06:56 in Room , IP 192.168.0.102:64403,
2020-08-06 15:06:56,930 [18] DEBUG Photon.Hive.Caching.RoomCacheBase - Created room instance reference: roomName=Room, referenceCount=2
2020-08-06 15:06:56,940 [24] DEBUG Photon.Hive.Plugin.BeforeJoinGameCallInfo - Continue.
2020-08-06 15:06:56,949 [24] DEBUG Photon.Hive.Collections.ActorsManager - Actor added: 2 c4b08bde-2613-433a-ae6a-0b61ca08f39e to game: Room -- peer:GameClientPeer: PID 7, IsConnected: True, IsDisposed: False, Last Activity: Operation 226 at UTC 06/08/2020 18:06:56 in Room Room, IP 192.168.0.102:64403,
2020-08-06 15:06:56,958 [24] DEBUG Photon.Hive.HiveGame - JoinApplyGameStateChanges: Actor 2 is added. MasterClientId is 1
2020-08-06 15:06:56,969 [24] DEBUG Photon.Hive.Plugin.JoinGameCallInfo - Continue.
2020-08-06 15:06:57,155 [9] DEBUG Photon.Hive.Plugin.RaiseEventCallInfo - Continue.
2020-08-06 15:06:57,169 [9] DEBUG Photon.Hive.Plugin.RaiseEventCallInfo - Continue.
2020-08-06 15:06:57,179 [9] DEBUG Photon.Hive.Plugin.RaiseEventCallInfo - Continue.
2020-08-06 15:06:57,223 [18] DEBUG Photon.Hive.Plugin.RaiseEventCallInfo - Continue.
2020-08-06 15:06:57,238 [18] DEBUG Photon.Hive.Plugin.RaiseEventCallInfo - Continue.
2020-08-06 15:06:57,252 [18] DEBUG Photon.Hive.Plugin.RaiseEventCallInfo - Continue.
.
.
.
2020-08-06 15:07:27,967 [24] DEBUG Photon.Hive.Plugin.RaiseEventCallInfo - Continue.
2020-08-06 15:07:28,167 [18] DEBUG Photon.Hive.Plugin.RaiseEventCallInfo - Continue.
2020-08-06 15:07:28,267 [17] DEBUG Photon.Hive.Plugin.RaiseEventCallInfo - Continue.
2020-08-06 15:07:28,368 [18] DEBUG Photon.Hive.Plugin.RaiseEventCallInfo - Continue.
2020-08-06 15:07:28,468 [15] DEBUG Photon.Hive.Plugin.RaiseEventCallInfo - Continue.
2020-08-06 15:07:28,668 [18] DEBUG Photon.Hive.Plugin.RaiseEventCallInfo - Continue.
2020-08-06 15:07:28,804 [19] DEBUG Photon.Hive.HivePeer - OnDisconnect: conId=7, reason=ClientDisconnect, reasonDetail=
2020-08-06 15:07:28,813 [19] DEBUG Photon.Hive.HivePeer - RemovePeerFromCurrentRoom: Removing peer from room. p:GameClientPeer: PID 7, IsConnected: False, IsDisposed: False, Last Activity: Operation 253 at UTC 06/08/2020 18:07:28 in Room Room, IP 192.168.0.102:0,
2020-08-06 15:07:28,822 [19] DEBUG Photon.Hive.HiveGame - ProcessMessage 1
2020-08-06 15:07:28,822 [15] DEBUG Photon.Hive.Caching.RoomCacheBase - Removed room instance reference: roomName=Room, referenceCount=1
2020-08-06 15:07:28,830 [19] DEBUG Photon.Hive.Plugin.LeaveGameCallInfo - Continue.
2020-08-06 15:07:28,852 [19] DEBUG Photon.Hive.HiveGame - Clean up actor Actor: 2; Peer:'GameClientPeer: PID 7, IsConnected: False, IsDisposed: True, Last Activity: Operation 253 at UTC 06/08/2020 18:07:28 in Room , IP 192.168.0.102:0, ', DeactivationTime:'', UserId:'c4b08bde-2613-433a-ae6a-0b61ca08f39e',nick:'8030aea4-7839-4f5d-bfba-16814bbe7ce8' - DeleteCacheOnLeave:
2020-08-06 15:07:28,860 [19] DEBUG Photon.Hive.Collections.ActorsManager - Actor removed: 2 c4b08bde-2613-433a-ae6a-0b61ca08f39e to game: Room -- peer:GameClientPeer: PID 7, IsConnected: False, IsDisposed: True, Last Activity: Operation 253 at UTC 06/08/2020 18:07:28 in Room , IP 192.168.0.102:0,
2020-08-06 15:07:30,636 [17] DEBUG Photon.Hive.HivePeer - OnDisconnect: conId=5, reason=ClientDisconnect, reasonDetail=
2020-08-06 15:07:30,644 [17] DEBUG Photon.Hive.HivePeer - RemovePeerFromCurrentRoom: Removing peer from room. p:GameClientPeer: PID 5, IsConnected: False, IsDisposed: False, Last Activity: Operation 253 at UTC 06/08/2020 18:06:57 in Room Room, IP 192.168.0.102:0,
2020-08-06 15:07:30,653 [17] DEBUG Photon.Hive.HiveGame - ProcessMessage 1
2020-08-06 15:07:30,653 [15] DEBUG Photon.Hive.Caching.RoomCacheBase - Removed room instance reference: roomName=Room, referenceCount=0
2020-08-06 15:07:30,661 [17] DEBUG Photon.Hive.Plugin.LeaveGameCallInfo - Continue.
2020-08-06 15:07:30,673 [15] DEBUG Photon.Hive.Caching.RoomCacheBase - Room has no references. Tring to remove it. room:Room
2020-08-06 15:07:30,681 [17] DEBUG Photon.Hive.HiveGame - Clean up actor Actor: 1; Peer:'GameClientPeer: PID 5, IsConnected: False, IsDisposed: True, Last Activity: Operation 253 at UTC 06/08/2020 18:06:57 in Room Room, IP 192.168.0.102:0, ', DeactivationTime:'', UserId:'0e4323b6-eea0-40a9-91bc-b0f26c8dbf8b',nick:'b5682b17-2931-415a-beb7-d5673b0977a9' - DeleteCacheOnLeave:
2020-08-06 15:07:30,689 [15] DEBUG Photon.Hive.Caching.RoomCacheBase - Room BeforeRemoveFromCache returned 'false'. Removing stopped. room:Room
2020-08-06 15:07:30,707 [17] DEBUG Photon.Hive.HiveGame - Actor 1 left. MasterClientId is 0
2020-08-06 15:07:30,738 [17] DEBUG Photon.Hive.Collections.ActorsManager - Actor removed: 1 0e4323b6-eea0-40a9-91bc-b0f26c8dbf8b to game: Room -- peer:GameClientPeer: PID 5, IsConnected: False, IsDisposed: True, Last Activity: Operation 253 at UTC 06/08/2020 18:06:57 in Room , IP 192.168.0.102:0,
2020-08-06 15:07:30,747 [19] DEBUG Photon.Hive.Plugin.BeforeCloseGameCallInfo - Continue.
2020-08-06 15:07:30,758 [19] DEBUG Photon.Hive.Plugin.CloseGameCallInfo - Continue.
2020-08-06 15:07:30,768 [19] DEBUG Photon.Hive.Caching.RoomCacheBase - Removed room instance: roomId=Room
2020-08-06 15:07:30,778 [19] DEBUG Photon.Hive.Room - Tried to remove room: roomName=Room, removed=True
2020-08-06 15:07:30,789 [19] DEBUG Photon.Hive.HiveHostGame - we are actually beeing released - not sure this should be called.
0 -
Just to follow up on this issue:
In the logs above, I've set maxPlayers to 16 so the problem wouldn't be noticeable by using only two clients. I guess I assumed it would show the players double counting somewhere in the logs. I'm sorry,
When I re run the tests latter, this issue has disappeared. Meanwhile, I've been watching roomcount (and logging) as I develop my app to see if I notice anything weird.0