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

ErethanErethan ✭
in Photon Server
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?

Comments

  • chvetsovchvetsov mod
    hi, @Erethan

    could you try to use join for second player?

    from what server do you get this error from Master or from GameServer?

    best,
    ilya
  • ErethanErethan ✭
    I am not sure, but from the Logs, I would guess that clients are still on the master server when they get this error.

    GameFull.png

    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

  • ErethanErethan ✭
    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 occurs
  • ErethanErethan ✭
    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
  • chvetsovchvetsov mod
    Activate debug logging on GS.
    It sounds like bug.
    Please collect the logs and send them to me. Are you using ExpectedUsers?

    best,
    ilya
  • ErethanErethan ✭
    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
  • chvetsovchvetsov mod
    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
  • JohnTubeJohnTube mod
    Hi @Erethan,

    Thank you for choosing Photon!

    I wanted to suggest using Photon Server v5 instead of v4 and the issue might already be solved there.
  • ErethanErethan ✭
    Once I get the chance, I will upgrade my Server then report back (and get the logs if the bug persists)

    Thanks @chvetsov & @JohnTube!
  • ErethanErethan ✭
    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.
  • chvetsovchvetsov mod
    HI, @Erethan
    from log I see that second player managed to join. What happened on your end?

    best,
    ilya
  • ErethanErethan ✭
    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.
Sign In or Register to comment.