TimeoutDisconnect error

Options
artefacto
edited May 2011 in DotNet
Hi.
Based on the unity realtime demo, I am developing a multiplayer game. It is working nicely and players can connect, move and edit their avatar colors perfectly. Also, each client sees the different changes for the other remote clients. So far, so good.
Unfortunately, for some still unknown reason, at some point, clients start being disconnected, game freezes until the window is closed. I looked at some logs and here is what I get :
Direct3D:
    Version:  Direct3D 9.0c [nvd3dum.dll 8.17.12.6658]
    Renderer: NVIDIA GeForce 8800 GTX
    Vendor:   NVIDIA
    VRAM:     768 MB
    Caps:     Shader=30 DepthRT=1 NativeDepth=1 NativeShadow=1 DF16=0 DF24=0 INTZ=1 RAWZ=0 NULL=1 RESZ=0 SlowINTZ=0
desktop: 1280x1024 60Hz; virtual: 1280x1024 at 0,0
<I> Initializing (RawInput).

<RI> Input initialized.

Non platform assembly: data-02E96428 (this message is harmless)
Non platform assembly: data-07470048 (this message is harmless)
Non platform assembly: data-02EFBF68 (this message is harmless)

Unloading 0 unused Assets to reduce memory usage. Loaded Objects now: 5762.
Unloading 5 Unused Serialized files (Serialized files now loaded: 0 / Dirty serialized files: 0)
Platform assembly: D:\MyProject_2.1\MyProject_Win_Data\Managed\System.dll (this message is harmless)
ExitGames.RealtimeDemo.LitePeer()
UnityEngine.Debug:Internal_Log(Int32, String, Object)
UnityEngine.Debug:Log(Object)
UsePhoton:DebugReturn(String)
ExitGames.RealtimeDemo.Game:DebugReturn(DebugLevel, String)
ExitGames.RealtimeDemo.LitePeer:.ctor(IPhotonPeerListener, Boolean)
ExitGames.RealtimeDemo.Game:Connect()
UsePhoton:Start()
 
(Filename: C:/BuildAgent/work/6bc5f79e0a4296d6/Runtime/ExportGenerated/StandalonePlayer/BaseClass.cpp Line: 2505)

nPeerReturn():Connect
UnityEngine.Debug:Internal_Log(Int32, String, Object)
UnityEngine.Debug:Log(Object)
UsePhoton:DebugReturn(String)
ExitGames.RealtimeDemo.Game:DebugReturn(String)
ExitGames.RealtimeDemo.Game:PeerStatusCallback(StatusCode)
ExitGames.Client.Photon.PeerBase:InitCallback()
ExitGames.Client.Photon.NConnect:deserializeNeutron(Byte[])
ExitGames.Client.Photon.EnetPeer:DispatchIncomingCommands()
ExitGames.Client.Photon.PhotonPeer:DispatchIncomingCommands()
ExitGames.RealtimeDemo.Game:DispatchAll()
ExitGames.RealtimeDemo.Game:Update()
UsePhoton:Update()
 
(Filename: C:/BuildAgent/work/6bc5f79e0a4296d6/Runtime/ExportGenerated/StandalonePlayer/BaseClass.cpp Line: 2505)

Connect(ed)
UnityEngine.Debug:Internal_Log(Int32, String, Object)
UnityEngine.Debug:Log(Object)
UsePhoton:DebugReturn(String)
ExitGames.RealtimeDemo.Game:DebugReturn(String)
ExitGames.RealtimeDemo.Game:PeerStatusCallback(StatusCode)
ExitGames.Client.Photon.PeerBase:InitCallback()
ExitGames.Client.Photon.NConnect:deserializeNeutron(Byte[])
ExitGames.Client.Photon.EnetPeer:DispatchIncomingCommands()
ExitGames.Client.Photon.PhotonPeer:DispatchIncomingCommands()
ExitGames.RealtimeDemo.Game:DispatchAll()
ExitGames.RealtimeDemo.Game:Update()
UsePhoton:Update()
 
(Filename: C:/BuildAgent/work/6bc5f79e0a4296d6/Runtime/ExportGenerated/StandalonePlayer/BaseClass.cpp Line: 2505)

nPeerReturn() 90/0
UnityEngine.Debug:Internal_Log(Int32, String, Object)
UnityEngine.Debug:Log(Object)
UsePhoton:DebugReturn(String)
ExitGames.RealtimeDemo.Game:DebugReturn(String)
ExitGames.RealtimeDemo.Game:OperationResult(Byte, Int32, Hashtable, Int16)
ExitGames.Client.Photon.NConnect:deserializeNeutron(Byte[])
ExitGames.Client.Photon.EnetPeer:DispatchIncomingCommands()
ExitGames.Client.Photon.PhotonPeer:DispatchIncomingCommands()
ExitGames.RealtimeDemo.Game:DispatchAll()
ExitGames.RealtimeDemo.Game:Update()
UsePhoton:Update()
 
(Filename: C:/BuildAgent/work/6bc5f79e0a4296d6/Runtime/ExportGenerated/StandalonePlayer/BaseClass.cpp Line: 2505)

LocalPlayer: 4 'toto' : 0 : 8 @ [0;0;0] & [0;0;0;0], 0
UnityEngine.Debug:Internal_Log(Int32, String, Object)
UnityEngine.Debug:Log(Object)
UsePhoton:DebugReturn(String)
ExitGames.RealtimeDemo.Game:DebugReturn(String)
ExitGames.RealtimeDemo.Game:OperationResult(Byte, Int32, Hashtable, Int16)
ExitGames.Client.Photon.NConnect:deserializeNeutron(Byte[])
ExitGames.Client.Photon.EnetPeer:DispatchIncomingCommands()
ExitGames.Client.Photon.PhotonPeer:DispatchIncomingCommands()
ExitGames.RealtimeDemo.Game:DispatchAll()
ExitGames.RealtimeDemo.Game:Update()
UsePhoton:Update()
 
(Filename: C:/BuildAgent/work/6bc5f79e0a4296d6/Runtime/ExportGenerated/StandalonePlayer/BaseClass.cpp Line: 2505)

EventAction() 90
UnityEngine.Debug:Internal_Log(Int32, String, Object)
UnityEngine.Debug:Log(Object)
UsePhoton:DebugReturn(String)
ExitGames.RealtimeDemo.Game:DebugReturn(String)
ExitGames.RealtimeDemo.Game:EventAction(Byte, Hashtable)
ExitGames.Client.Photon.NConnect:deserializeNeutron(Byte[])
ExitGames.Client.Photon.EnetPeer:DispatchIncomingCommands()
ExitGames.Client.Photon.PhotonPeer:DispatchIncomingCommands()
ExitGames.RealtimeDemo.Game:DispatchAll()
ExitGames.RealtimeDemo.Game:Update()
UsePhoton:Update()
So connection is successful when I reach here.
Then, I see incoming messages from remote players such as :
Players: 4 'toto' : 0 : 8 @ [371.7217;-13.3777;149.2537] & [0;-0.9887562;0;0.1495363], 0, 1 'titi' : 0 : 7 @ [324.0034;-15.17655;376.1432] & [0;-0.95956;0;0.2815043], 0, 2 'tata' : 0 : 6 @ [18.96566;82.33677;178.1496] & [0;0.003491681;0;0.9999939], 0, 3 'tutu' : 0 : 7 @ [329.8362;-15.09564;374.7629] & [0;-0.09758303;0;0.9952275], 0, 5 'Player 5' : 0 : 6 @ [0;0;0] & [0;0;0;0], 0, 
UnityEngine.Debug:Internal_Log(Int32, String, Object)
UnityEngine.Debug:Log(Object)
UsePhoton:DebugReturn(String)
ExitGames.RealtimeDemo.Game:DebugReturn(String)
ExitGames.RealtimeDemo.Game:PrintPlayers()
ExitGames.RealtimeDemo.Game:EventAction(Byte, Hashtable)
ExitGames.Client.Photon.NConnect:deserializeNeutron(Byte[])
ExitGames.Client.Photon.EnetPeer:DispatchIncomingCommands()
ExitGames.Client.Photon.PhotonPeer:DispatchIncomingCommands()
ExitGames.RealtimeDemo.Game:DispatchAll()
ExitGames.RealtimeDemo.Game:Update()
UsePhoton:Update()
 
(Filename: C:/BuildAgent/work/6bc5f79e0a4296d6/Runtime/ExportGenerated/StandalonePlayer/BaseClass.cpp Line: 2505)

EventAction() 107
UnityEngine.Debug:Internal_Log(Int32, String, Object)
UnityEngine.Debug:Log(Object)
UsePhoton:DebugReturn(String)
ExitGames.RealtimeDemo.Game:DebugReturn(String)
ExitGames.RealtimeDemo.Game:EventAction(Byte, Hashtable)
ExitGames.Client.Photon.NConnect:deserializeNeutron(Byte[])
ExitGames.Client.Photon.EnetPeer:DispatchIncomingCommands()
ExitGames.Client.Photon.PhotonPeer:DispatchIncomingCommands()
ExitGames.RealtimeDemo.Game:DispatchAll()
ExitGames.RealtimeDemo.Game:Update()
UsePhoton:Update()
 
(Filename: C:/BuildAgent/work/6bc5f79e0a4296d6/Runtime/ExportGenerated/StandalonePlayer/BaseClass.cpp Line: 2505)

EventAction() 104
UnityEngine.Debug:Internal_Log(Int32, String, Object)
UnityEngine.Debug:Log(Object)
UsePhoton:DebugReturn(String)
ExitGames.RealtimeDemo.Game:DebugReturn(String)
ExitGames.RealtimeDemo.Game:EventAction(Byte, Hashtable)
ExitGames.Client.Photon.NConnect:deserializeNeutron(Byte[])
ExitGames.Client.Photon.EnetPeer:DispatchIncomingCommands()
ExitGames.Client.Photon.PhotonPeer:DispatchIncomingCommands()
ExitGames.RealtimeDemo.Game:DispatchAll()
ExitGames.RealtimeDemo.Game:Update()
UsePhoton:Update()
 
(Filename: C:/BuildAgent/work/6bc5f79e0a4296d6/Runtime/ExportGenerated/StandalonePlayer/BaseClass.cpp Line: 2505)

Players: 4 'toto' : 0 : 8 @ [372.2949;-13.3777;149.0763] & [0;-0.9887562;0;0.1495363], 0, 1 'titi' : 0 : 7 @ [324.0034;-15.17655;376.1432] & [0;-0.95956;0;0.2815043], 0, 2 'tata' : 0 : 6 @ [18.96566;82.33677;178.1496] & [0;0.003491681;0;0.9999939], 0, 3 'tutu' : 0 : 7 @ [329.8362;-15.09564;374.7629] & [0;-0.09758303;0;0.9952275], 0, 5 'toutou' : 0 : 5 @ [0;0;0] & [0;0;0;0], 0, 
UnityEngine.Debug:Internal_Log(Int32, String, Object)
UnityEngine.Debug:Log(Object)
UsePhoton:DebugReturn(String)
ExitGames.RealtimeDemo.Game:DebugReturn(String)
ExitGames.RealtimeDemo.Game:PrintPlayers()
ExitGames.RealtimeDemo.Game:EventAction(Byte, Hashtable)
ExitGames.Client.Photon.NConnect:deserializeNeutron(Byte[])
ExitGames.Client.Photon.EnetPeer:DispatchIncomingCommands()
ExitGames.Client.Photon.PhotonPeer:DispatchIncomingCommands()
ExitGames.RealtimeDemo.Game:DispatchAll()
ExitGames.RealtimeDemo.Game:Update()
UsePhoton:Update()
 
(Filename: C:/BuildAgent/work/6bc5f79e0a4296d6/Runtime/ExportGenerated/StandalonePlayer/BaseClass.cpp Line: 2505)

EventAction() 107
UnityEngine.Debug:Internal_Log(Int32, String, Object)
UnityEngine.Debug:Log(Object)
UsePhoton:DebugReturn(String)
ExitGames.RealtimeDemo.Game:DebugReturn(String)
ExitGames.RealtimeDemo.Game:EventAction(Byte, Hashtable)
ExitGames.Client.Photon.NConnect:deserializeNeutron(Byte[])
ExitGames.Client.Photon.EnetPeer:DispatchIncomingCommands()
ExitGames.Client.Photon.PhotonPeer:DispatchIncomingCommands()
ExitGames.RealtimeDemo.Game:DispatchAll()
ExitGames.RealtimeDemo.Game:Update()
UsePhoton:Update()
 
(Filename: C:/BuildAgent/work/6bc5f79e0a4296d6/Runtime/ExportGenerated/StandalonePlayer/BaseClass.cpp Line: 2505)

Instantiate player #5
UnityEngine.Debug:Internal_Log(Int32, String, Object)
UnityEngine.Debug:Log(Object)
UsePhoton:DebugReturn(String)
UsePhoton:UpdatePlayers()
UsePhoton:Update()
 
(Filename: C:/BuildAgent/work/6bc5f79e0a4296d6/Runtime/ExportGenerated/StandalonePlayer/BaseClass.cpp Line: 2505)

EventAction() 104
UnityEngine.Debug:Internal_Log(Int32, String, Object)
UnityEngine.Debug:Log(Object)
UsePhoton:DebugReturn(String)
ExitGames.RealtimeDemo.Game:DebugReturn(String)
ExitGames.RealtimeDemo.Game:EventAction(Byte, Hashtable)
ExitGames.Client.Photon.NConnect:deserializeNeutron(Byte[])
ExitGames.Client.Photon.EnetPeer:DispatchIncomingCommands()
ExitGames.Client.Photon.PhotonPeer:DispatchIncomingCommands()
ExitGames.RealtimeDemo.Game:DispatchAll()
ExitGames.RealtimeDemo.Game:Update()
UsePhoton:Update()
By the way, Event 107 is when a player changes its colors. And then at some point, I guess this :
EventAction() 107
UnityEngine.Debug:Internal_Log(Int32, String, Object)
UnityEngine.Debug:Log(Object)
UsePhoton:DebugReturn(String)
ExitGames.RealtimeDemo.Game:DebugReturn(String)
ExitGames.RealtimeDemo.Game:EventAction(Byte, Hashtable)
ExitGames.Client.Photon.NConnect:deserializeNeutron(Byte[])
ExitGames.Client.Photon.EnetPeer:DispatchIncomingCommands()
ExitGames.Client.Photon.PhotonPeer:DispatchIncomingCommands()
ExitGames.RealtimeDemo.Game:DispatchAll()
ExitGames.RealtimeDemo.Game:Update()
UsePhoton:Update()
 
(Filename: C:/BuildAgent/work/6bc5f79e0a4296d6/Runtime/ExportGenerated/StandalonePlayer/BaseClass.cpp Line: 2505)

nPeerReturn():TimeoutDisconnect
UnityEngine.Debug:Internal_Log(Int32, String, Object)
UnityEngine.Debug:Log(Object)
UsePhoton:DebugReturn(String)
ExitGames.RealtimeDemo.Game:DebugReturn(String)
ExitGames.RealtimeDemo.Game:PeerStatusCallback(StatusCode)
ExitGames.Client.Photon.EnetPeer:SendOutgoingCommands()
ExitGames.Client.Photon.PhotonPeer:SendOutgoingCommands()
ExitGames.RealtimeDemo.Game:SendOutgoingCommands()
ExitGames.RealtimeDemo.Game:Update()
UsePhoton:Update()
 
(Filename: C:/BuildAgent/work/6bc5f79e0a4296d6/Runtime/ExportGenerated/StandalonePlayer/BaseClass.cpp Line: 2505)

PeerStatusCallback: TimeoutDisconnect
UnityEngine.Debug:Internal_Log(Int32, String, Object)
UnityEngine.Debug:Log(Object)
UsePhoton:DebugReturn(String)
ExitGames.RealtimeDemo.Game:DebugReturn(String)
ExitGames.RealtimeDemo.Game:PeerStatusCallback(StatusCode)
ExitGames.Client.Photon.EnetPeer:SendOutgoingCommands()
ExitGames.Client.Photon.PhotonPeer:SendOutgoingCommands()
ExitGames.RealtimeDemo.Game:SendOutgoingCommands()
ExitGames.RealtimeDemo.Game:Update()
UsePhoton:Update()
 
(Filename: C:/BuildAgent/work/6bc5f79e0a4296d6/Runtime/ExportGenerated/StandalonePlayer/BaseClass.cpp Line: 2505)

nPeerReturn():Disconnect
UnityEngine.Debug:Internal_Log(Int32, String, Object)
UnityEngine.Debug:Log(Object)
UsePhoton:DebugReturn(String)
ExitGames.RealtimeDemo.Game:DebugReturn(String)
ExitGames.RealtimeDemo.Game:PeerStatusCallback(StatusCode)
ExitGames.Client.Photon.EnetPeer:Disconnected()
ExitGames.Client.Photon.EnetPeer:SendOutgoingCommands()
ExitGames.Client.Photon.PhotonPeer:SendOutgoingCommands()
ExitGames.RealtimeDemo.Game:SendOutgoingCommands()
ExitGames.RealtimeDemo.Game:Update()
UsePhoton:Update()
 
(Filename: C:/BuildAgent/work/6bc5f79e0a4296d6/Runtime/ExportGenerated/StandalonePlayer/BaseClass.cpp Line: 2505)

Disconnect(ed) peer.state: 0
UnityEngine.Debug:Internal_Log(Int32, String, Object)
UnityEngine.Debug:Log(Object)
UsePhoton:DebugReturn(String)
ExitGames.RealtimeDemo.Game:DebugReturn(String)
ExitGames.RealtimeDemo.Game:PeerStatusCallback(StatusCode)
ExitGames.Client.Photon.EnetPeer:Disconnected()
ExitGames.Client.Photon.EnetPeer:SendOutgoingCommands()
ExitGames.Client.Photon.PhotonPeer:SendOutgoingCommands()
ExitGames.RealtimeDemo.Game:SendOutgoingCommands()
ExitGames.RealtimeDemo.Game:Update()
UsePhoton:Update()
 
(Filename: C:/BuildAgent/work/6bc5f79e0a4296d6/Runtime/ExportGenerated/StandalonePlayer/BaseClass.cpp Line: 2505)

removing 4 = Player (UnityEngine.GameObject)
UnityEngine.Debug:Internal_Log(Int32, String, Object)
UnityEngine.Debug:Log(Object)
UsePhoton:DebugReturn(String)
UsePhoton:UpdatePlayers()
UsePhoton:Update()
 
(Filename: C:/BuildAgent/work/6bc5f79e0a4296d6/Runtime/ExportGenerated/StandalonePlayer/BaseClass.cpp Line: 2505)

removing 1 = remote_1 (UnityEngine.GameObject)
UnityEngine.Debug:Internal_Log(Int32, String, Object)
UnityEngine.Debug:Log(Object)
UsePhoton:DebugReturn(String)
UsePhoton:UpdatePlayers()
UsePhoton:Update()
 
(Filename: C:/BuildAgent/work/6bc5f79e0a4296d6/Runtime/ExportGenerated/StandalonePlayer/BaseClass.cpp Line: 2505)

removing 2 = remote_2 (UnityEngine.GameObject)
UnityEngine.Debug:Internal_Log(Int32, String, Object)
UnityEngine.Debug:Log(Object)
UsePhoton:DebugReturn(String)
UsePhoton:UpdatePlayers()
UsePhoton:Update()
 
(Filename: C:/BuildAgent/work/6bc5f79e0a4296d6/Runtime/ExportGenerated/StandalonePlayer/BaseClass.cpp Line: 2505)

removing 3 = remote_3 (UnityEngine.GameObject)
UnityEngine.Debug:Internal_Log(Int32, String, Object)
UnityEngine.Debug:Log(Object)
UsePhoton:DebugReturn(String)
UsePhoton:UpdatePlayers()
UsePhoton:Update()
 
(Filename: C:/BuildAgent/work/6bc5f79e0a4296d6/Runtime/ExportGenerated/StandalonePlayer/BaseClass.cpp Line: 2505)

removing 5 = remote_5 (UnityEngine.GameObject)
UnityEngine.Debug:Internal_Log(Int32, String, Object)
UnityEngine.Debug:Log(Object)
UsePhoton:DebugReturn(String)
UsePhoton:UpdatePlayers()
UsePhoton:Update()
 
(Filename: C:/BuildAgent/work/6bc5f79e0a4296d6/Runtime/ExportGenerated/StandalonePlayer/BaseClass.cpp Line: 2505)
I tried running the realtime-demo, and it works fine. Do you know what can cause this crash ?

I already check the firewall ports and I also checked messages aren't sent too often (position updates are done at the same rate as the demo, chat and colors edition are only sent once when required.
Thanks a lot for the help.

Comments

  • Tobias
    Options
    The "TimeoutDisconnect" log entry tells me that the client timed out first, as it didn't get an acknowledgement in time for something sent.
    In recent client SDKs, the reception of ACKs is independent from your Service() calls, so you can't do anything wrong there. If you're up to date.
    Those logs include no hint why the disconnect happens. Maybe in the server logs?
    You could add a time value to all logs. Without it, it's hard to get the sequence of things out of three logs.

    Which version of the SDKs (server + client) are you using?
    Did you modify the server application or are you running what's in the SDK?
    Do you run the server locally? What is the Roundtrip Time to the server?
    I think you can rule out the firewall. If your server runs on some hosting service, you might ask them if their firewall might shut down a connection to avoid Denial of Service attacks. This is what AirVm does by default. They can turn it off for you.

    Aside from this, I would look into the server logs.
  • Boris
    Options
    If the game freezes or has a VERY low frame rate it cannot call service as much as needed and the connection will then drop.
  • Thanks for the help. Here is some info regarding to your questions.

    - First thing about the server logs, where are they exactly ? :oops: I right-clicked on the Photon icon, selected Open logs, but the most recent log is about 1 month ago... Are they supposed to be somewhere else ?
    - The Photon versions I'm using are 2.4.7 for the server (XP, 32 bits) and 6.2.0 for the client (tested on Vista 32 bits and 64 bits).
    - I didn't changed the server app... just running the default one.
    - The server is not set up locally any more. It used to be earlier, but we moved it to check connection speed and delays. The roundtrip time was around 150. Server time is around -500 millions :? not sure what it means exactly...

    About Boris' question, the framerate is between 10-15 and 60 (depending on the client pc). When I said the game froze, it was just before crashing. No real slow down before that.

    Hope this help.
  • Boris
    Options
    the server logs are on the machine that your client connects to.
    two folders:
    1) log in the photon bin folder: contains photon logs
    2) log right next to the bin folder: contains application logs (lite etc)
  • Kaiserludi
    Options
    artefacto wrote:
    - The server is not set up locally any more. It used to be earlier, but we moved it to check connection speed and delays. The roundtrip time was around 150. Server time is around -500 millions :? not sure what it means exactly...
    Nothing more, than that your server machine is running for about 25 days (+ 0-endless times about 49 days) without a restart. The servertime is a 32bit signed integer in milliseconds since the server hardware has started. After a bii more than 24,5 days it crosses MAX_INT and gets a negative value, every abit mroe than 49 days it crosses 0 and begins, where it has started.
  • gnoblin
    Options
    is it recommended to restart the server every 25 days? :)
  • Kaiserludi
    Options
    gnoblin wrote:
    is it recommended to restart the server every 25 days? :)
    No, its not. The servertime will overflow every 49 days, but this only means: a) you should not compare absolute servertimes, but only differences between two servertimes and b) you should not rely on servertimes, which could be from weeks ago, but only use it for short intervals.

    Of course we could send 64bit servertimes instead, but for the intended usage the overflow every 49days doesn't matter and the 4bytes more would sum up to a small, but unneeded traffic-increase, as the servertime has to be updated very often, to be of any use.