Temporarily 'Game full' while room still has space. Double counting joins?

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
could you try to use join for second player?
from what server do you get this error from Master or from GameServer?
best,
ilya
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
I checked that, and I the same issue occurs
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
It sounds like bug.
Please collect the logs and send them to me. Are you using ExpectedUsers?
best,
ilya
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
it has this:
<root>
<level value="INFO" />
<appender-ref ref="LogFileAppender" />
<appender-ref ref="ConsoleAppender" />
</root>
INFO should be changed to DEBUG
best,
ilya
Thank you for choosing Photon!
I wanted to suggest using Photon Server v5 instead of v4 and the issue might already be solved there.
Thanks @chvetsov & @JohnTube!
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.
from log I see that second player managed to join. What happened on your end?
best,
ilya
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.