OnDisconnect() not called?

Sergiy

Hi

Can it be that calling Disconnect() on server-side will not raise OnDisconnect() event?

For example:

Please consider following situation:

There is a BackGammonPeer class that is inheriting PeerBase class:
[code2=csharp]public abstract class BackGammonPeer : PeerBase
{
....................
protected override void OnDisconnect(DisconnectReason reasonCode, string reasonDetail)
{
RequestFiber.Enqueue(() =>
{
DoLogDebug(string.Format("BackGammonPeer Disconnect. Reason: {0}, ReasonDetail: {1}", reasonCode, reasonDetail),
Enums.DebugTypes.Info);
_eventsFiber.Stop();
_eventsFiber.Dispose();
RequestFiber.Dispose();
Dispose();
});
}
}[/code2]

PlayerPeer class inheriting BackGammonPeer:
[code2=csharp]public class PlayerPeer : BackGammonPeer
{
...................................................
protected override void OnDisconnect(DisconnectReason reasonCode, string reasonDetail)
{
RequestFiber.Enqueue(() =>
{
try
{
DoLogDebug(string.Format("PlayerPeer OnDisconnect started. PlayerName: {0}, PlayerKey: {1}", PlayerName, PlayerKey), Enums.DebugTypes.Info);
if (PeerState != Enums.PeerStates.Disconnecting)
{
CleanUp();
}
else
{
DoLogDebug(
string.Format(
"PlayerPeer OnDisconnect - PeerState is Disconnecting, skipping cleanup. PlayerName: {0}, PlayerKey: {1}",
PlayerName, PlayerKey), Enums.DebugTypes.Info);
}
DoLogDebug(string.Format("PlayerPeer OnDisconnected finished. PlayerName: {0}, PlayerKey: {1}", PlayerName, PlayerKey), Enums.DebugTypes.Info);
base.OnDisconnect(reasonCode, reasonDetail);
}
catch (Exception exception)
{
DoLogException(string.Format("PlayerPeer OnDisconnect EXCEPTION!"), exception);
}
});
}
}[/code2]

Now on server I'm calling
[code2=csharp]PlayerPeer playerPeer = GetPlayerPeer();
playerPeer.Disconnect();[/code2]

PlayerPeer.IsConnected becomes false, but OnDisconnect() is not calling. This happens sometimes, not always. I wrote a routine that tracks such peers and calls CleanUp() on them, but it's a bad option.

Maybe I'm missing something? Please help.

chvetsov

Why do you put body of OnDisconnect to RequestFiber?
i belive, this is wrong way, because OnDisconnect are called from RequestFiber.

and second, i think, that if you will remove
RequestFiber.Dispose();
Dispose();
from BackGammonPeer.OnDisconnect it will work better because this is done by framework

Sergiy

Hi chvetsov

Thanks for reply

1. Because I have to do some cleanup - remove peer from peers list, notify his and opponent's team that he has left, etc. This is done is Cleanup() method. But, if I understand you correctly, OnDisconnect() is executing if RequestFiber anyway. Is it correct?

2. I didn't know that. Thanks for clarification

Do you think that any of mentioned above can prevent OnDisconnect() from raising when i call Disconnect() ?

chvetsov

Sergiy wrote:

1. But, if I understand you correctly, OnDisconnect() is executing if RequestFiber anyway. Is it correct?

Yes, this is correct. All notifications from peer come from same fiber, namely RequestFiber.

Sergiy wrote:

2. I didn't know that. Thanks for clarification

Do you think that any of mentioned above can prevent OnDisconnect() from raising when i call Disconnect() ?

Well, I'm sure it is called everytime. I think that you do not get call to your cleanup task. And this is defenetly because you put your tasks to RequestFiber. Because right after OnDisconnect call RequestFiber is disposed and this prevents execution of task in it

Sergiy

Thanks. I'll try and report results here.

Just one more question:

All notifications from peer come from same fiber, namely RequestFiber.

Does it mean that OnOperationRequest() is executing in RequestFiber anyway? So here:
[code2=csharp]protected override void OnOperationRequest(OperationRequest operationRequest, SendParameters sendParameters)
{
RequestFiber.Enqueue(() =>
{
try
{
switch ((OperationCodes) operationRequest.OperationCode)
{
case OperationCodes.AuthenticatePlayer:
ProcessAuthenticatePlayerRequest(operationRequest);
break;

........................................................................
}
}
catch (Exception exception)
{
DoLogException(
string.Format("PlayerPeer OnOperationRequest EXCEPTION! OperationCode: {0}",
(OperationCodes) operationRequest.OperationCode), exception);
}
});
}[/code2]
RequestFiber.Enqueue can be safely removed? And ProcessAuthenticatePlayerRequest() will be called in RequestFiber anyway?

chvetsov

Yes, that is right

Sergiy

Hi

Still strange thing - Peer's IsConnected property is false but OnDisconnect() was not called How can it be?

chvetsov

let us to see your code

Sergiy

I'm not sure which part of code to post.... can you please specify?

IsConnected is false, I'm logging OnDisconnect(), but it was not called.

Sergiy

Here is the code. Sorry, it's quite long:


GamblerPeer.cs:
[code2=csharp]private void CleanUp()
{
try
{
DoLogDebug(string.Format("GamblerPeer CleanUp started. UserName: {0}, GamblerKey: {1}", UserName, GamblerKey), Enums.DebugTypes.Info);
if (PeerState == Enums.PeerStates.Disconnecting)
return;
if (PeerState != Enums.PeerStates.Connected)
{
Lobby.RemoveGambler(AccountID);
Debuggers.SendEvent(new DbgGamblerLeftLobbyEvent(AccountID));
}
PeerState = Enums.PeerStates.Disconnecting;
DoLogDebug(string.Format("GamblerPeer Cleanup finished, UserName: {0}, GamblerKey: {1}", UserName, GamblerKey),
Enums.DebugTypes.Info);
GamblerKey = Guid.Empty;
if (_matchInfoSubscriber != null)
_matchInfoSubscriber.Dispose();
_gamblerBalances.Clear();
DoLogDebug("GamblerPeer Gambler Disconnected", Enums.DebugTypes.Info);
}
catch (Exception exception)
{
DoLogException(string.Format("GamblerPeer CleanUp EXCEPTION! UserName: {0}, GamblerKey: {1}", UserName, GamblerKey), exception);
}
//});
}

protected override void OnDisconnect(DisconnectReason reasonCode, string reasonDetail)
{
DoLogDebug(string.Format("GamblerPeer OnDisconnect. UserName: {0}, GamblerKey: {1}", UserName, GamblerKey), Enums.DebugTypes.Info);
if (PeerState != Enums.PeerStates.Disconnecting)
CleanUp();
else
{
DoLogDebug(
string.Format(
"GamblerPeer OnDisconnect - PeerState is Disconnecting, skipping cleanup. UserName: {0}, GamblerKey: {1}",
UserName, GamblerKey), Enums.DebugTypes.Info);
}
base.OnDisconnect(reasonCode, reasonDetail);
}[/code2]

PlayerPeer.cs:
[code2=csharp]private void CleanUp()
{
try
{
DoLogDebug(string.Format("PlayerPeer CleanUp started."), Enums.DebugTypes.Info);
if (PeerState == Enums.PeerStates.Disconnecting)
return;
if (PeerState != Enums.PeerStates.Connected)
{
Lobby.RemovePlayer(PlayerKey);
Debuggers.SendEvent(new DbgPlayerLeftEvent(PlayerKey, AccountID));
}
PeerState = Enums.PeerStates.Disconnecting;
DoLogDebug(string.Format("PlayerPeer Cleanup finished"), Enums.DebugTypes.Info);
}
catch (Exception exception)
{
DoLogException(string.Format("PlayerPeer CleanUp EXCEPTION!"), exception);
}
}[

protected override void OnDisconnect(DisconnectReason reasonCode, string reasonDetail)
{
try
{
DoLogDebug(string.Format("PlayerPeer OnDisconnect started"), Enums.DebugTypes.Info);
if (PeerState != Enums.PeerStates.Disconnecting)
{
CleanUp();
}
else
{
DoLogDebug(
string.Format(
"PlayerPeer OnDisconnect - PeerState is Disconnecting, skipping cleanup"), Enums.DebugTypes.Info);
}
DoLogDebug(string.Format("PlayerPeer OnDisconnected finished"), Enums.DebugTypes.Info);
base.OnDisconnect(reasonCode, reasonDetail);
}
catch (Exception exception)
{
DoLogException(string.Format("PlayerPeer OnDisconnect EXCEPTION!"), exception);
}[/code2]

and, finally, Lobby.cs
[code2=csharp]public static void RemoveGambler(long accountID)
{
_executionFiber.Enqueue(() =>
{
try
{
if (!_gamblerPeers.ContainsKey(accountID))
{
DoLogDebug(string.Format("Lobby RemoveGambler - AccountID: {0} not found", accountID), Enums.DebugTypes.Error);
return;
}
GamblerPeer gamblerPeer;
if (_gamblerPeers.TryRemove(accountID, out gamblerPeer))
{
DoLogDebug(string.Format("Lobby RemoveGambler - GamblerName: {0}, AccountID: {1} removed", gamblerPeer.UserName, accountID), Enums.DebugTypes.Info);
foreach (PlayerPeer playerPeer in _playerPeers.ToArray().Where(t => t.Value.AccountID == gamblerPeer.AccountID).Select(t => t.Value))
{
DoLogDebug(
string.Format("Lobby RemoveGambler - GamblerName: {0}. Removing PlayerKey: {1}",
gamblerPeer.UserName, playerPeer.PlayerKey), Enums.DebugTypes.Info);
//playerPeer.CleanUp();
playerPeer.Disconnect();
}
}
else
{
DoLogDebug(
string.Format("Lobby RemoveGambler - GamblerName: {0}, AccountID: {1} cannot be removed", gamblerPeer.UserName, accountID),
Enums.DebugTypes.Error);
}
}
catch (Exception exception)
{
DoLogException(string.Format("Lobby RemoveGambler EXCEPTION!! AccountID: {0}", accountID), exception);
}
});
}

public static void RemovePlayer(Guid playerKey)
{
_executionFiber.Enqueue(() =>
{
try
{
DoLogDebug(string.Format("Lobby RemovePlayer - PlayerKey: {0}", playerKey), Enums.DebugTypes.Info);
if (!_playerPeers.ContainsKey(playerKey))
{
DoLogDebug(string.Format("Lobby RemovePlayer - PlayerKey: {0} not found", playerKey), Enums.DebugTypes.Error);
foreach (KeyValuePair<long, GameBase> keyValuePair in Matches.ToArray().
Where(
t =>
t.Value.Info.WhitePlayerKey == playerKey ||
t.Value.Info.BlackPlayerKey == playerKey)
)
{
keyValuePair.Value.RemovePlayerPeer(playerKey);
DoLogDebug(
string.Format(
"PlayerPeer was not in Players dictionary, but it was found in the match. PlayerKey: {0}, MatchID: {1}",
playerKey, keyValuePair.Key), Enums.DebugTypes.Error);
}
return;
}
PlayerPeer playerPeer;
if (!_playerPeers.TryRemove(playerKey, out playerPeer))
{
DoLogDebug(string.Format("Lobby RemovePlayer - PlayerName: {0}, PlayerKey: {1} cannot be removed", playerPeer.PlayerName, playerKey), Enums.DebugTypes.Error);
return;
}
DoLogDebug(string.Format("Lobby RemovePlayer - PlayerName: {0}, PlayerKey: {1} removed", playerPeer.PlayerName, playerKey), Enums.DebugTypes.Info);
if (playerPeer.MatchID == 0)
return;
if (Matches.ContainsKey(playerPeer.MatchID))
{
Matches[playerPeer.MatchID].RemovePlayerPeer(playerPeer.PlayerKey);
DoLogDebug(
string.Format("Lobby RemovePlayer - removed Player: {0}, PlayerKey: {1} from MatchID: {2}", playerPeer.PlayerName,
playerPeer.PlayerKey, playerPeer.MatchID), Enums.DebugTypes.Info);
}
GamblerPeer gamblerPeer = GetGamblerPeer(playerPeer.AccountID);
if (gamblerPeer != null)
gamblerPeer.SendEvent(new PopupClosedEvent(playerPeer.MatchID));
}
catch (Exception exception)
{
DoLogException(string.Format("Lobby RemovePlayer EXCEPTION!! PlayerKey: {0}", playerKey), exception);
}
});
}

private static void ClearDisconnectedPeers()
{
_executionFiber.Enqueue(() =>
{
try
{
foreach (PlayerPeer disconnectedPeer in _playerPeers.ToArray().Where(t => !t.Value.Connected).Select(t => t.Value))
{
PlayerPeer playerPeer;
_playerPeers.TryRemove(disconnectedPeer.PlayerKey, out playerPeer);
if (playerPeer != null)
{
DoLogDebug(
string.Format("Lobby ClearDisconnectedPeers - removing disconnected PlayerPeer: {0}, PlayerKey: {1}",
playerPeer.PlayerName, playerPeer.PlayerKey), Enums.DebugTypes.Info);
//playerPeer.CleanUp();
playerPeer.Disconnect();
}
}
foreach (GamblerPeer disconnectedPeer in _gamblerPeers.ToArray().Where(t => !t.Value.Connected).Select(t => t.Value))
{
GamblerPeer gamblerPeer;
_gamblerPeers.TryRemove(disconnectedPeer.AccountID, out gamblerPeer);
if (gamblerPeer != null)
{
DoLogDebug(
string.Format("Lobby ClearDisconnectedPeers - removing disconnected GamblerPeer: {0}, AccountID: {1}, GamblerKey: {2}",
gamblerPeer.UserName, gamblerPeer.AccountID, gamblerPeer.GamblerKey), Enums.DebugTypes.Info);
//gamblerPeer.CleanUp();
gamblerPeer.Disconnect();
//gamblerPeer.Dispose();
}
}
}
catch (Exception exception)
{
DoLogException(string.Format("ClearDisconnectedGamblers EXCEPTION!!"), exception);
}
});
}[/code2]

ClearDisconnectedPeers() in called every 3 seconds to make sure that all disconnected peers are actually removed. I had to do it because, as i wrote, OnDisconnect() is not always calling.

finally, the log file:

[code2=plain]2/26/2013 5:16:08 PM: GamblerPeer OnDisconnect. UserName: levan2212, GamblerKey: ace87a48-b275-45a7-b373-0380d1196392, ConnectionID: 1566, IP: 94.43.180.93, JoinDate: 2/26/2013 4:53:08 PM, PeerState: JoinedToLobby, Type: GBSSoft.BackGammon.Server.Peers.GamblerPeer, ClientType: Web, ClientVersion: 1.1.0.6
2/26/2013 5:16:08 PM: GamblerPeer CleanUp started. UserName: levan2212, GamblerKey: ace87a48-b275-45a7-b373-0380d1196392, ConnectionID: 1566, IP: 94.43.180.93, JoinDate: 2/26/2013 4:53:08 PM, PeerState: JoinedToLobby, Type: GBSSoft.BackGammon.Server.Peers.GamblerPeer, ClientType: Web, ClientVersion: 1.1.0.6
2/26/2013 5:16:08 PM: GamblerPeer Cleanup finished, UserName: levan2212, GamblerKey: ace87a48-b275-45a7-b373-0380d1196392, ConnectionID: 1566, IP: 94.43.180.93, JoinDate: 2/26/2013 4:53:08 PM, PeerState: Disconnecting, Type: GBSSoft.BackGammon.Server.Peers.GamblerPeer, ClientType: Web, ClientVersion: 1.1.0.6
2/26/2013 5:16:08 PM: Lobby RemoveGambler - GamblerName: levan2212, AccountID: 20658 removed
2/26/2013 5:16:08 PM: Lobby RemoveGambler - GamblerName: levan2212. Removing PlayerKey: c520e97e-7ad3-45fc-8d77-d2db0cbb7aa5
2/26/2013 5:16:08 PM: GamblerPeer Gambler Disconnected, ConnectionID: 1566, IP: 94.43.180.93, JoinDate: 2/26/2013 4:53:08 PM, PeerState: Disconnecting, Type: GBSSoft.BackGammon.Server.Peers.GamblerPeer, ClientType: Web, ClientVersion: 1.1.0.6
2/26/2013 5:16:08 PM: BackGammonPeer Disconnect. Reason: TimeoutDisconnect, ReasonDetail: , ConnectionID: 1566, IP: 94.43.180.93, JoinDate: 2/26/2013 4:53:08 PM, PeerState: Disconnecting, Type: GBSSoft.BackGammon.Server.Peers.GamblerPeer, ClientType: Web, ClientVersion: 1.1.0.6
2/26/2013 5:16:11 PM: Lobby ClearDisconnectedPeers - removing disconnected PlayerPeer: levan2212, PlayerKey: c520e97e-7ad3-45fc-8d77-d2db0cbb7aa5[/code2]

Please note "Removing Player Key" line. After that:

1. Disconnect() was called on PlayerPeer
2. The PlayerPeer's OnDisconnect() method should have been raised, but it didn't.
3. After 3 secs ClearDisconnectedPeers() has processed that PlayerPeer and called Disconnect() on it
4. Second time OnDisconnect() didn't raise...

i really don't understand this.....

chvetsov

hmm, I do not see any problems right now
But there is something what i do not udnerstnad
I do not understand why GamblerPeer and BackGammonPeer have same ConnectionID.

And yet two question:
What protocol do you use?
and please check, whether peer in ClearDisconeectedPeers disposed or not

Sergiy

My bad - I should have provided more info.

BackGammonPeer is the ancestor of GamblerPeer and PlayerPeer as well. That's why they have same ConnectionID.

[code2=csharp]public class GamblerPeer : BackGammonPeer[/code2]
[code2=csharp]public class PlayerPeer : BackGammonPeer[/code2]
[code2=csharp]public abstract class BackGammonPeer : PeerBase
{
protected BackGammonPeer(IRpcProtocol rpcProtocol, IPhotonPeer photonPeer) : base(rpcProtocol, photonPeer)
{
_eventsFiber = new PoolFiber();
_eventsFiber.Start();
PeerState = Enums.PeerStates.Connected;
JoinDate = DateTime.Now;
}
....................................................................

protected override void OnDisconnect(DisconnectReason reasonCode, string reasonDetail)
{
DoLogDebug(string.Format("BackGammonPeer Disconnect. Reason: {0}, ReasonDetail: {1}", reasonCode, reasonDetail),
Enums.DebugTypes.Info);
_eventsFiber.Stop();
_eventsFiber.Dispose();
}
}[/code2]

BTW, I have noticed that tho different peers can have same ConnectionID, not sure whether they were both connected or not. Is it normal behavior?

Protocol is TCP. Flash (AS3) client, using Photon-Flash_v3-0-1-0_SDK.

I will track whether the peer's IsDisposed property is true and let you know

UPD: IsConnected property is false and IsDisposed property is false too
Again: this happens not always, but often. I have imagination (maybe wrong, though) that it happens only on ManagedDisconnect

chvetsov

We will take a look

chvetsov

could you say what version of photon SDK do you have?

Sergiy

Latest - ExitGames-Photon-Server-SDK_v3-2-10-4248

chvetsov

Well, right now i can advise next thing.

1. Please ensure that you setuped correctly logger factory. Sample you can see in Lite project. LiteApplication.cs:52.

2. You need to set log level for 'root' logger to DEBUG

You will get log in which we will see does SDK call OnDisconnect or not

Sergiy

I've tracked down 3 occurrences. In all these cases server has called Disconnect() but OnDisconnect() didn't fire. IsConnected and IsDisposed properties are both false

[code2=plain]2013-02-28 14:32:19,847 [16] DEBUG OperationData [(null)] - OnReceive - ConnID=322, data=(106 bytes) F4-02-10-00-01-04-23-06-81-41-30-66-55-77-74-53-4B-41-58-49-56-31-42-31-32-57-71-7A-4D-53-77-69-72-2F-43-48-66-31-41-4C-6D-55-58-50-6A-58-4C-2B-73-4F-52-42-71-2F-71-7A-39-65-6C-74-74-70-5A-4D-31-77-78-47-35-2B-73-42-6E-42-75-32-74-76-70-7A-4D-76-53-69-76-34-51-49-61-73-37-43-4D-36-65-6B-46-61-6A-50-75-39-69-62-69-75
2013-02-28 14:32:19,848 [31] INFO GBSSoft.BackGammon.Server.BackGammonPeer [(null)] - PlayerPeer ProcessCancelJoinRequest, PlayerName: alika5555, PlayerKey: 9723aaef-904f-4f74-b42e-085d5c06a377, MatchID: 123559, ConnectionID: 322, IP: 94.43.216.211, JoinDate: 2/28/2013 2:31:55 PM, PeerState: AuthenticatedAsPlayer, Type: GBSSoft.BackGammon.Server.Peers.PlayerPeer
2013-02-28 14:32:19,848 [31] DEBUG OperationData [(null)] - SentOpResponse: ConnID=322, opCode=37, return=0, ChannelId=1, result=Ok, data=(141 bytes) F4-03-25-00-00-2A-00-01-04-4F-06-82-01-68-6B-30-6C-43-43-36-48-54-41-4D-38-35-73-6A-4F-7A-64-34-70-31-55-77-32-6A-59-38-52-55-42-7A-34-30-4A-4F-2F-62-37-49-53-73-32-32-67-6B-67-37-58-43-4E-73-6D-57-47-74-41-61-39-6E-34-6E-2B-42-62-44-45-43-75-69-4C-67-37-6A-48-68-4E-4C-38-59-47-75-49-4B-75-39-33-50-49-73-6E-6C-38-58-59-2B-6F-70-4B-6C-4F-54-39-47-5A-39-4C-55-2B-4D-48-6F-48-78-43-43-47-79-35-45-58-4C-34-52-59-6E-46-6A-2B
2013-02-28 14:32:19,849 [31] INFO GBSSoft.BackGammon.Server.BackGammonPeer [(null)] - PlayerPeer ProcessCancelJoinRequest ErrorCode: NoError, PlayerName: alika5555, PlayerKey: 9723aaef-904f-4f74-b42e-085d5c06a377, MatchID: 123559, ConnectionID: 322, IP: 94.43.216.211, JoinDate: 2/28/2013 2:31:55 PM, PeerState: AuthenticatedAsPlayer, Type: GBSSoft.BackGammon.Server.Peers.PlayerPeer
2013-02-28 14:32:19,849 [31] INFO GBSSoft.BackGammon.Server.BackGammonPeer [(null)] - PlayerPeer ProcessCancelJoinRequest calling Disconnect, PlayerName: alika5555, PlayerKey: 9723aaef-904f-4f74-b42e-085d5c06a377, MatchID: 123559, ConnectionID: 322, IP: 94.43.216.211, JoinDate: 2/28/2013 2:31:55 PM, PeerState: AuthenticatedAsPlayer, Type: GBSSoft.BackGammon.Server.Peers.PlayerPeer
2013-02-28 14:32:19,849 [31] DEBUG Photon.SocketServer.PeerBase [(null)] - Peer 322 changed state from Connected to Disconnecting
2013-02-28 14:32:19,849 [31] DEBUG Photon.SocketServer.PeerBase [(null)] - Disconnect client called

2013-02-28 14:32:55,864 [14] DEBUG OperationData [(null)] - OnReceive - ConnID=338, data=(170 bytes) F4-02-05-00-01-04-5F-06-82-41-71-41-4D-76-78-47-34-39-76-33-7A-69-2F-7A-51-72-72-36-35-42-36-6B-67-63-56-55-4C-5A-72-77-55-67-70-62-77-36-79-41-52-47-55-7A-51-74-52-73-51-55-4D-74-4D-30-6D-4F-56-6D-67-4E-76-33-6B-4A-50-48-2F-46-75-59-73-6B-75-37-58-79-79-36-33-48-4F-6B-44-70-58-70-6A-32-4A-74-75-58-59-4F-48-69-66-59-71-2B-37-2B-43-6F-38-73-53-64-58-34-69-48-51-67-4E-71-67-58-6D-2B-4F-31-50-33-6C-32-58-6F-35-43-78-73-6B-38-34-30-36-44-6C-30-6F-4C-7A-2F-77-6C-4D-31-65-34-53-46-78-4D-57-2B-44-71-49-49-34-61
2013-02-28 14:32:55,864 [73] ERROR GBSSoft.BackGammon.Server.BackGammonPeer [(null)] - PlayerPeer ProcessJoinMatchAsPlayerRequest Invalid MatchID, PlayerName: alika5555, PlayerKey: c705c208-9677-42bd-b8df-9df641fc2632, MatchID: 123583, ConnectionID: 338, IP: 94.43.216.211, JoinDate: 2/28/2013 2:32:53 PM, PeerState: AuthenticatedAsPlayer, Type: GBSSoft.BackGammon.Server.Peers.PlayerPeer
2013-02-28 14:32:55,865 [73] DEBUG OperationData [(null)] - SentOpResponse: ConnID=338, opCode=71, return=0, ChannelId=1, result=Ok, data=(141 bytes) F4-03-47-00-00-2A-00-01-04-1B-06-82-01-68-6B-30-6C-43-43-36-48-54-41-4D-38-35-73-6A-4F-7A-64-34-70-31-55-77-32-6A-59-38-52-55-42-7A-34-30-4A-4F-2F-62-37-49-53-73-32-32-67-6B-67-37-58-43-4E-73-6D-57-47-74-41-61-39-6E-34-6E-2B-42-62-39-6E-43-6B-6F-52-30-43-4E-4D-30-32-32-61-4D-4A-5A-51-42-70-67-46-69-33-72-73-4F-76-42-54-70-44-49-38-54-53-4B-70-45-79-57-35-6F-69-57-74-51-78-44-6C-49-4B-64-69-52-74-44-6A-49-46-37-6B-37-59
2013-02-28 14:32:55,865 [73] DEBUG Photon.SocketServer.PeerBase [(null)] - Peer 338 changed state from Connected to Disconnecting
2013-02-28 14:32:55,865 [73] DEBUG Photon.SocketServer.PeerBase [(null)] - Disconnect client called

2013-02-28 15:21:27,255 [14] DEBUG OperationData [(null)] - OnReceive - ConnID=807, data=(106 bytes) F4-02-10-00-01-04-3A-06-81-41-48-41-73-6D-35-6A-77-72-30-39-6D-67-6B-67-37-58-43-4E-73-6D-57-45-44-61-6A-48-49-46-58-30-74-52-6D-7A-6A-6C-32-68-66-4D-6B-48-63-58-63-75-41-31-32-36-7A-67-53-55-77-33-2F-4A-4A-4E-74-49-6B-42-31-48-41-48-6E-73-70-59-6E-47-2B-71-36-4B-59-2F-39-62-58-67-78-45-53-69-47-43-46-6F-41-45-68-6F
2013-02-28 15:21:27,255 [19] INFO GBSSoft.BackGammon.Server.BackGammonPeer [(null)] - PlayerPeer ProcessCancelJoinRequest, PlayerName: gena1967, PlayerKey: 0ee04687-6093-4db9-9f52-618f4f8ac415, MatchID: 123641, ConnectionID: 807, IP: 178.134.248.72, JoinDate: 2/28/2013 3:21:06 PM, PeerState: AuthenticatedAsPlayer, Type: GBSSoft.BackGammon.Server.Peers.PlayerPeer
2013-02-28 15:21:27,256 [23] DEBUG OperationData [(null)] - SentEvent: ConnID=444, evCode=25, ChannelId=1, result=Ok, data=(150 bytes) F4-04-19-00-01-04-20-06-82-19-4A-33-49-7A-34-61-2F-67-35-2F-67-77-58-44-63-4D-4F-6A-2B-41-46-34-31-7A-7A-37-69-68-41-30-35-61-77-53-5A-6E-6B-52-62-5A-65-75-71-48-2F-63-4F-38-49-63-58-71-78-69-44-69-31-44-47-6E-35-74-33-59-4D-51-5A-57-4F-4D-52-7A-6B-37-57-50-38-71-38-71-6F-33-30-56-42-37-62-63-42-48-36-45-45-32-4D-61-63-39-64-42-45-78-61-41-77-2F-4C-36-42-4E-4E-36-39-33-5A-37-63-35-77-6A-76-54-6C-66-4C-51-43-76-66-4F-5A-4C-37-4F-4A-54-38-5A-45-3D
2013-02-28 15:21:27,257 [19] DEBUG OperationData [(null)] - SentOpResponse: ConnID=807, opCode=24, return=0, ChannelId=1, result=Ok, data=(141 bytes) F4-03-18-00-00-2A-00-01-04-4A-06-82-01-68-6B-30-6C-43-43-36-48-54-41-4D-38-35-73-6A-4F-7A-64-34-70-31-55-77-32-6A-59-38-52-55-42-7A-34-30-4A-4F-2F-62-37-49-53-73-32-32-67-6B-67-37-58-43-4E-73-6D-57-47-74-41-61-39-6E-34-6E-2B-42-62-44-45-43-75-69-4C-67-37-6A-48-68-4E-4C-38-59-47-75-49-4B-75-39-33-50-49-73-6E-6C-38-58-59-2B-6F-70-4B-6C-4F-54-39-47-5A-39-4C-55-2B-4D-48-6F-48-78-43-43-47-79-35-45-58-4C-34-52-59-6E-46-6A-2B
2013-02-28 15:21:27,257 [19] INFO GBSSoft.BackGammon.Server.BackGammonPeer [(null)] - PlayerPeer ProcessCancelJoinRequest ErrorCode: NoError, PlayerName: gena1967, PlayerKey: 0ee04687-6093-4db9-9f52-618f4f8ac415, MatchID: 123641, ConnectionID: 807, IP: 178.134.248.72, JoinDate: 2/28/2013 3:21:06 PM, PeerState: AuthenticatedAsPlayer, Type: GBSSoft.BackGammon.Server.Peers.PlayerPeer
2013-02-28 15:21:27,257 [19] INFO GBSSoft.BackGammon.Server.BackGammonPeer [(null)] - PlayerPeer ProcessCancelJoinRequest calling Disconnect, PlayerName: gena1967, PlayerKey: 0ee04687-6093-4db9-9f52-618f4f8ac415, MatchID: 123641, ConnectionID: 807, IP: 178.134.248.72, JoinDate: 2/28/2013 3:21:06 PM, PeerState: AuthenticatedAsPlayer, Type: GBSSoft.BackGammon.Server.Peers.PlayerPeer
2013-02-28 15:21:27,257 [19] DEBUG Photon.SocketServer.PeerBase [(null)] - Peer 807 changed state from Connected to Disconnecting
2013-02-28 15:21:27,258 [19] DEBUG Photon.SocketServer.PeerBase [(null)] - Disconnect client called[/code2]

chvetsov

We need full log. could you upload it to somewhere and share link here?

chvetsov

Well, possible the solution for you is next
according to documentation for TCPListener

---

Parameter DisconnectTimeout
Default: 120000
A time, in ms, which is allowed for the client to close the connection once the connection has been disconnected by the application.

---

Because you work with flash it is not possible to predict when it will close connection. We use this timeout.
You can set it to 2000. I belive you will see OnDisconnect call in 2000 ms

Please, try

Sergiy

First of all - here's part of my PhotonServer.config:
[code2=xml]<BackGammonServer
MaxMessageSize="512000"
MaxQueuedDataPerPeer="512000"
PerPeerMaxReliableDataInTransit="51200"
PerPeerTransmitRateLimitKBSec="256"
PerPeerTransmitRatePeriodMilliseconds="200"
MinimumTimeout="5000"
MaximumTimeout="30000">
<TCPListeners>
<!-- Gambler -->
<TCPListener
IPAddress="0.0.0.0"
Port="21311"
PolicyApplication="Policy">
</TCPListener>
<!-- Player -->
<TCPListener
IPAddress="0.0.0.0"
Port="21312"
PolicyApplication="Policy">
</TCPListener>
<!-- Debugger -->
<TCPListener
IPAddress="0.0.0.0"
Port="21319"
PolicyApplication="Policy">
</TCPListener>
</TCPListeners>[/code2]

Do I need to change it?

Second - why should we wait for flash client to close connection? Actually, server is calling Disconnect() and I thought it should terminate connection instantly, regardless of client timeout. Do you mean that after calling Disconnect() on peer, server still waits that peer's disconnect timeout? :shock:

Philip

> Do I need to change it?
If you don't wan't to wait - yes.

> Second - why should we wait for flash client to close connection?
that is not specific to flash ...

> Actually, server is calling Disconnect() and I thought it should terminate connection instantly,
> regardless of client timeout. Do you mean that after calling Disconnect() on peer,
> server still waits that peer's disconnect timeout?
Yes - that is the default. Because that is the "clean" way to close a tcp connection.
And you can configure the behavior of Photon reducing the timeout.
We might allow to PeerBase.Abort() in a future release, which is what you seem to be expecting ...

Sergiy

I have uploaded log file to WikiSend.
GBSSoft.BackGammon.Server.Log.zip

Please look at following PlayePeers:
1. Name: fridon40, PlayerKey: ff2d2fbd-514d-429d-a5a0-3398dda5c3f1
2. Name: chere70, PlayerKey: ace39a69-e0a1-4020-98b9-393a22dd6753

Sergiy

OK, so I set MinimumTimeout to 3000, MaximumTimeout to 3000 and will add DisconnectTimeout to TCPListener section and set it to 500. BTW, what will happen if I set it to 0?

I'm not sure that it will help, because even after 5 minutes peers were alive, but with IsConnected and IsDisposed set to false

chvetsov

So, what result of your tests?

Sergiy

I noticed that setting InactivityTimeout to less then 1000 leads to disconnects even when client runs on same computer as server. Client is .NET. So I'll set MinimumTimeout and MaximumTimeout to 5000, InactivityTimeout to 10000, DisconnectTimeout to 500 and report results on Monday.

How about my logs - any news?

chvetsov

No, news about log yet. Just because we wait results for you. Becase it is not so easy to parse 17 Mb of logs

Sergiy

Hi

I restarted server with new PhotonServer.config file. Same behavior - after a while appeared connections with both IsConnected and IsDisposed properties set to false. I'm positive that this situation happens when server calls Disconnect() on peer.

Below is PhotonServer.config file:
[code2=xml]<BackGammonServer
MaxMessageSize="512000"
MaxQueuedDataPerPeer="512000"
PerPeerMaxReliableDataInTransit="51200"
PerPeerTransmitRateLimitKBSec="256"
PerPeerTransmitRatePeriodMilliseconds="200"
MinimumTimeout="10000"
MaximumTimeout="10000">

<IOPool
NumThreads = "6"
Priority = "Normal">
</IOPool>
<ThreadPool
InitialThreads = "8"
MinThreads = "8"
MaxThreads = "8"
Priority = "Normal">
</ThreadPool>
<ENetThreadPool
InitialThreads = "2"
MinThreads = "2"
MaxThreads = "4"
Priority = "Normal">
</ENetThreadPool>

<TCPListeners>
<!-- Gambler -->
<TCPListener
IPAddress="0.0.0.0"
Port="21311"
InactivityTimeout = "10000"
DisconnectTimeout = "1000"
PolicyApplication="Policy">
</TCPListener>
<!-- Player -->
<TCPListener
IPAddress="0.0.0.0"
Port="21312"
InactivityTimeout = "10000"
DisconnectTimeout = "1000"
PolicyApplication="Policy">
</TCPListener>
</TCPListeners>

<!-- Policy request listener for Unity and Flash (port 843) and Silverlight (port 943) -->
<TCPPolicyListeners>
<!-- multiple Listeners allowed for different ports -->
<TCPPolicyListener
IPAddress="0.0.0.0"
Port="843"
InactivityTimeout = "5000"
Application="Policy">
</TCPPolicyListener>
<TCPPolicyListener
IPAddress="0.0.0.0"
Port="943"
Application="Policy">
</TCPPolicyListener>
</TCPPolicyListeners>[/code2]

As for log file that I've uploaded - IMHO, no need to parse whole 17 megs. You only need check 20-25 lines where peers with specific PlayerKeys appeared.

[Deleted User]

Another question - can you please have a look at PhotonCLR.log in /bin_Win64/log/ (or the appropriate bin_XXX folder, from where you run Photon), and see if there is an exception?

Unhandled exceptions are logged there, not in your specific applications log file, and uncaught exceptions might prevent that OnDisconnect is called.

Sergiy

Thanks for joining in, Nicole

I've checked PhotonCLR.log (actually, i'm constantly checking it to make sure that all exceptions are handled). No exceptions there.

Sergiy

Any news...??

chvetsov

Nicole, will make a tests to reporoduce a problem