DEADSOFTWARE

net: oops; reconnection to failed master was totally broken
[d2df-sdl.git] / src / game / g_netmaster.pas
index c0ef87270eb8dc06d1bab1a91c2d945bddcc1732..1703da27cdcbe44c21bf4f0b6bbc9875c97af211 100644 (file)
@@ -30,6 +30,14 @@ const
   NET_MMSG_DEL = 201;
   NET_MMSG_GET = 202;
 
+const
+  // all timeouts in seconds
+  NMASTER_TIMEOUT_CONNECT = 3; // 3 seconds
+  NMASTER_TIMEOUT_RECONNECT = 5*60; // 5 minutes
+  //NMASTER_TIMEOUT_RECONNECT = 30; // 5 minutes
+  //NMASTER_FORCE_UPDATE_TIMEOUT = 20;
+  //NMASTER_FORCE_UPDATE_TIMEOUT = 0;
+
 type
   TNetServer = record
     Number: Byte;
@@ -67,8 +75,8 @@ type
     NetHostConnected: Boolean;
     NetHostConReqTime: Int64; // to timeout `connect`; -1 means "waiting for shutdown"
     NetUpdatePending: Boolean; // should we send an update after connection completes?
-    lastConnectTime: Int64;
-    updateSent: Boolean;
+    lastDisconnectTime: Int64; // last real disconnect time; <0: do not reconnect
+    updateSent: Boolean; // was at least one update sent? (used to decide if we should call `remove()`)
     lastUpdateTime: Int64;
     // server list request working flags
     srvAnswered: Integer;
@@ -121,6 +129,8 @@ var
   slMOTD: AnsiString = '';
   slUrgent: AnsiString = '';
 
+  NMASTER_FORCE_UPDATE_TIMEOUT: Integer = 0; // fuck you, fpc, and your idiotic "diagnostics"
+
 
 procedure g_Net_Slist_Set (IP: AnsiString; Port: Word; list: AnsiString='');
 function g_Net_Slist_Fetch (var SL: TNetServerList): Boolean;
@@ -146,6 +156,7 @@ procedure g_Net_Slist_ServerMapStarted ();
 // this server renamed (or password mode changed, or other params changed)
 procedure g_Net_Slist_ServerRenamed ();
 
+// non-zero timeout ignores current status (used to fetch server list)
 procedure g_Net_Slist_Pulse (timeout: Integer=0);
 
 procedure g_Net_Slist_ShutdownAll ();
@@ -223,7 +234,7 @@ begin
       Inc(activeCount);
       if (mlist[f].isConnected() and mlist[f].updateSent) then
       begin
-        writeln('unregistering from ', f);
+        writeln('unregistering from [', mlist[f].hostName, ']');
         mlist[f].remove();
       end;
       //mlist[f].disconnect(false);
@@ -237,9 +248,12 @@ begin
     ct := GetTimerMS();
     if (ct < stt) or (ct-stt >= 1500) then break;
 
+    // fuck! https://www.mail-archive.com/enet-discuss@cubik.org/msg00852.html
+    // tl;dr: on shitdows, we can get -1 sometimes, and it is *NOT* a failure.
+    //        thank you, enet. let's ignore failures altogether then.
     sres := enet_host_service(NetMHost, @NetMEvent, 100);
-    if (sres < 0) then break;
-    if (sres = 0) then continue;
+    // if (sres < 0) then break;
+    if (sres <= 0) then continue;
 
     idx := findByPeer(NetMEvent.peer);
     if (idx < 0) then
@@ -275,13 +289,13 @@ end;
 //  DisconnectAll
 //
 //==========================================================================
-procedure DisconnectAll ();
+procedure DisconnectAll (forced: Boolean=false);
 var
   f: Integer;
 begin
   for f := 0 to High(mlist) do
   begin
-    if (mlist[f].isAlive()) then mlist[f].disconnect(false);
+    if (mlist[f].isAlive()) then mlist[f].disconnect(forced);
   end;
 end;
 
@@ -295,11 +309,11 @@ procedure ConnectAll (sendUpdate: Boolean);
 var
   f: Integer;
 begin
+  // set flags; pulse will take care of the rest
   for f := 0 to High(mlist) do
   begin
     // force reconnect
-    mlist[f].lastConnectTime := 0;
-    //if (not mlist[f].isAlive()) then continue;
+    mlist[f].lastDisconnectTime := 0;
     // force updating
     if (sendUpdate) then
     begin
@@ -319,6 +333,7 @@ procedure UpdateAll (force: Boolean);
 var
   f: Integer;
 begin
+  // set flags; pulse will take care of the rest
   for f := 0 to High(mlist) do
   begin
     if (not mlist[f].isAlive()) then continue;
@@ -482,7 +497,7 @@ begin
   NetHostConnected := false;
   NetHostConReqTime := 0;
   NetUpdatePending := false;
-  lastConnectTime := 0;
+  lastDisconnectTime := 0;
   updateSent := false;
   lastUpdateTime := 0;
   hostName := '';
@@ -603,7 +618,9 @@ begin
   if not isAlive() then exit;
   if NetHostConnected then exit;
   NetHostConnected := true;
+  NetHostConReqTime := 0; // just in case
   e_LogWritefln('connected to master at [%s]', [hostName], TMsgType.Notify);
+  //g_Console_Add(Format(_lc[I_NET_MSG]+_lc[I_NET_SLIST_CONN], [mlist[f].hostName]));
 end;
 
 
@@ -617,7 +634,7 @@ begin
   if not isAlive() then exit;
   e_LogWritefln('disconnected from master at [%s]', [hostName], TMsgType.Notify);
   disconnect(true);
-  //if (spamConsole) then g_Console_Add(_lc[I_NET_MSG] + _lc[I_NET_SLIST_DISC]);
+  //if (spamConsole) then g_Console_Add(Format(_lc[I_NET_MSG]+_lc[I_NET_SLIST_DISC], [hostName]));
 end;
 
 
@@ -649,7 +666,8 @@ begin
   slReadUrgent := true;
   // number of items
   Cnt := msg.ReadByte();
-  g_Console_Add(_lc[I_NET_MSG]+Format(_lc[I_NET_SLIST_RETRIEVED], [Cnt]), True);
+  //g_Console_Add(_lc[I_NET_MSG]+Format(_lc[I_NET_SLIST_RETRIEVED], [Cnt, hostName]), True);
+  e_LogWritefln('got %u server(s) from master at [%s]', [Cnt, hostName], TMsgType.Notify);
   if (Cnt > 0) then
   begin
     SetLength(srvAnswer, Cnt);
@@ -684,10 +702,12 @@ begin
     if (msg.ReadCount < msg.CurSize) then
     begin
       slMOTD := b_Text_Format(msg.ReadString());
+      if (slMOTD <> '') then e_LogWritefln('got MOTD from master at [%s]: %s', [hostName, slMOTD], TMsgType.Notify);
       s := b_Text_Format(msg.ReadString());
       // check if the message has updated and the user has to read it again
       if (slUrgent <> s) then slReadUrgent := false;
       slUrgent := s;
+      if (s <> '') then e_LogWritefln('got urgent from master at [%s]: %s', [hostName, s], TMsgType.Notify);
     end;
   end;
 end;
@@ -695,75 +715,39 @@ end;
 
 //==========================================================================
 //
-//  TMasterHost.pulse
-//
-//  this performs various scheduled tasks, if necessary
+//  TMasterHost.disconnect
 //
 //==========================================================================
-procedure TMasterHost.pulse ();
-var
-  ct: Int64;
-  mrate: Cardinal;
+procedure TMasterHost.disconnect (forced: Boolean);
 begin
-  if not isAlive() then exit;
-  if (NetHostConReqTime = -1) then exit; // waiting for shutdown (disconnect in progress)
-  ct := GetTimerMS();
-  // process pending connection timeout
-  if (not NetHostConnected) then
+  if isAlive() then
   begin
-    if (ct < NetHostConReqTime) or (ct-NetHostConReqTime >= 3000) then
+    lastDisconnectTime := GetTimerMS();
+    if forced or (not NetHostConnected) or (NetHostConReqTime = -1) then
     begin
-      e_LogWritefln('failed to connect to master at [%s]', [hostName], TMsgType.Notify);
-      // do not spam with error messages, it looks like the master is down
-      //g_Console_Add(_lc[I_NET_MSG_ERROR] + _lc[I_NET_SLIST_ERROR], True);
-      enet_peer_disconnect(peer, 0);
-      // main pulse will take care of the rest
-    end;
-    exit;
-  end;
-  // send update, if necessary
-  if (NetUpdatePending) then
-  begin
-    mrate := NetMasterRate;
-         if (mrate < 10000) then mrate := 10000
-    else if (mrate > 1000*60*10) then mrate := 1000*60*10;
-    if (lastUpdateTime = 0) or (ct < lastUpdateTime) or (ct-lastUpdateTime >= mrate) then
+      enet_peer_reset(peer);
+      peer := nil;
+      NetHostConReqTime := 0;
+      updateSent := false;
+    end
+    else
     begin
-      lastUpdateTime := ct;
-      update();
+      enet_peer_disconnect_later(peer, 0);
+      // main pulse will take care of the rest
+      NetHostConReqTime := -1;
     end;
-  end;
-end;
-
-
-//==========================================================================
-//
-//  TMasterHost.disconnect
-//
-//==========================================================================
-procedure TMasterHost.disconnect (forced: Boolean);
-begin
-  if not isAlive() then exit;
-
-  if (forced) then
-  begin
-    enet_peer_reset(peer);
-    peer := nil;
-    NetHostConReqTime := 0;
   end
   else
   begin
-    enet_peer_disconnect_later(peer, 0);
-    // main pulse will take care of the rest
-    NetHostConReqTime := -1;
+    // just in case
+    NetHostConReqTime := 0;
+    updateSent := false;
   end;
 
   NetHostConnected := false;
   NetUpdatePending := false;
-  //updateSent := false;
   lastUpdateTime := 0;
-  //lastConnectTime := 0;
-  //if (spamConsole) then g_Console_Add(_lc[I_NET_MSG] + _lc[I_NET_SLIST_DISC]);
+  //if (spamConsole) then g_Console_Add(Format(_lc[I_NET_MSG]+_lc[I_NET_SLIST_DISC], [hostName]));
 end;
 
 
@@ -779,13 +763,15 @@ begin
   if (NetHostConReqTime = -1) then
   begin
     disconnect(true);
+    if (NetHostConReqTime = -1) then e_LogWritefln('ketmar broke master [%s] logic! (000)', [hostName], TMsgType.Notify);
+    if (isAlive()) then e_LogWritefln('ketmar broke master [%s] logic! (001)', [hostName], TMsgType.Notify);
   end
   else
   begin
     if isAlive() then begin result := true; exit; end;
   end;
 
-  lastConnectTime := GetTimerMS();
+  lastDisconnectTime := GetTimerMS(); // why not?
   SetLength(srvAnswer, 0);
   srvAnswered := 0;
   NetHostConnected := false;
@@ -801,7 +787,7 @@ begin
     exit;
   end;
 
-  NetHostConReqTime := lastConnectTime;
+  NetHostConReqTime := lastDisconnectTime;
   e_LogWritefln('connecting to master at [%s]', [hostName], TMsgType.Notify);
 end;
 
@@ -855,6 +841,7 @@ begin
     try
       netmsg.Write(Byte(NET_MMSG_UPD));
       netmsg.Write(NetAddr.port);
+      //writeln(formatstrf('%08x', [NetAddr.host]), ' : ', NetAddr.host);
 
       writeInfo(netmsg);
 
@@ -910,6 +897,50 @@ begin
 end;
 
 
+//==========================================================================
+//
+//  TMasterHost.pulse
+//
+//  this performs various scheduled tasks, if necessary
+//
+//==========================================================================
+procedure TMasterHost.pulse ();
+var
+  ct: Int64;
+  mrate: Cardinal;
+begin
+  if not isAlive() then exit;
+  if (NetHostConReqTime = -1) then exit; // waiting for shutdown (disconnect in progress)
+  ct := GetTimerMS();
+  // process pending connection timeout
+  if (not NetHostConnected) then
+  begin
+    if (ct < NetHostConReqTime) or (ct-NetHostConReqTime >= 1000*NMASTER_TIMEOUT_CONNECT) then
+    begin
+      e_LogWritefln('failed to connect to master at [%s]', [hostName], TMsgType.Notify);
+      // do not spam with error messages, it looks like the master is down
+      //g_Console_Add(_lc[I_NET_MSG_ERROR] + _lc[I_NET_SLIST_ERROR], True);
+      disconnect(true);
+    end;
+    exit;
+  end;
+  // send update, if necessary
+  if (NetUpdatePending) then
+  begin
+    mrate := NetMasterRate;
+         if (mrate < 10000) then mrate := 10000
+    else if (mrate > 1000*60*10) then mrate := 1000*60*10;
+    if (NMASTER_FORCE_UPDATE_TIMEOUT > 0) then mrate := NMASTER_FORCE_UPDATE_TIMEOUT*1000;
+    if (lastUpdateTime = 0) or (ct < lastUpdateTime) or (ct-lastUpdateTime >= mrate) then
+    begin
+      //e_LogWritefln('update timeout: %d', [Integer(mrate)], TMsgType.Notify);
+      lastUpdateTime := ct;
+      update();
+    end;
+  end;
+end;
+
+
 //**************************************************************************
 //
 // other functions
@@ -1069,10 +1100,23 @@ end;
 //
 //**************************************************************************
 
+//==========================================================================
+//
+//  isMasterReportsEnabled
+//
+//==========================================================================
+function isMasterReportsEnabled (): Boolean;
+begin
+  result := (reportsEnabled and g_Game_IsServer() and g_Game_IsNet() and NetUseMaster);
+end;
+
+
 //==========================================================================
 //
 //  g_Net_Slist_Pulse
 //
+//  non-zero timeout ignores current status (used to fetch server list)
+//
 //==========================================================================
 procedure g_Net_Slist_Pulse (timeout: Integer=0);
 var
@@ -1080,6 +1124,8 @@ var
   sres: Integer;
   idx: Integer;
   ct: Int64;
+  isListQuery: Boolean;
+  count: Integer;
 begin
   if (not g_Net_IsNetworkAvailable()) then exit;
 
@@ -1098,73 +1144,97 @@ begin
     NetMHost := enet_host_create(nil, 64, NET_MCHANS, 1024*1024, 1024*1024);
     if (NetMHost = nil) then
     begin
-      g_Console_Add(_lc[I_NET_MSG_ERROR]+_lc[I_NET_ERR_CLIENT], True);
+      e_LogWriteln(_lc[I_NET_MSG_ERROR] + _lc[I_NET_ERR_CLIENT] + ' (host_create)', TMsgType.Notify);
       for f := 0 to High(mlist) do mlist[f].clear();
       SetLength(mlist, 0);
       Exit;
     end;
   end;
 
+  isListQuery := (timeout > 0);
   ct := GetTimerMS();
+  // reconnect/disconnect/pulse for each master
   for f := 0 to High(mlist) do
   begin
     if (not mlist[f].isValid()) then continue;
     if (not mlist[f].isAlive()) then
     begin
-      if reportsEnabled and g_Game_IsServer() and g_Game_IsNet() and NetUseMaster then
+      // not connected; try to reconnect if we're asking for a host list, or we are in netgame, and we are the host
+      if isListQuery or isMasterReportsEnabled() then
       begin
-        if (mlist[f].lastConnectTime = 0) or (ct < mlist[f].lastConnectTime) or (ct-mlist[f].lastConnectTime >= 1000*60*5) then
+        if (mlist[f].lastDisconnectTime = 0) or (ct < mlist[f].lastDisconnectTime) or (ct-mlist[f].lastDisconnectTime >= 1000*NMASTER_TIMEOUT_RECONNECT) then
         begin
+          e_LogWritefln('reconnecting to master [%s]', [mlist[f].hostName], TMsgType.Notify);
           mlist[f].connect();
+        end
+        else
+        begin
+          //e_LogWritefln('DEAD master [%s]: ct=%d; ldt=%d; diff=%d', [mlist[f].hostName, Integer(ct), Integer(mlist[f].lastDisconnectTime), Integer(ct-mlist[f].lastDisconnectTime)], TMsgType.Notify);
         end;
       end;
     end
     else
     begin
-      if not reportsEnabled or not g_Game_IsServer() or not g_Game_IsNet() or not NetUseMaster then
+      // if we're not in slist query, and not in netgame (or not a host), disconnect
+      if (not isListQuery) and (not isMasterReportsEnabled()) then
       begin
-        if (mlist[f].isConnected()) and (mlist[f].updateSent) then mlist[f].remove();
+        if (mlist[f].isConnected()) and (mlist[f].updateSent) then
+        begin
+          e_LogWritefln('removing from master [%s]', [mlist[f].hostName], TMsgType.Notify);
+          mlist[f].remove();
+        end;
+        e_LogWritefln('disconnecting from master [%s]', [mlist[f].hostName], TMsgType.Notify);
         mlist[f].disconnect(false);
       end;
     end;
     mlist[f].pulse();
   end;
 
-  while true do
+  // fuck! https://www.mail-archive.com/enet-discuss@cubik.org/msg00852.html
+  // tl;dr: on shitdows, we can get -1 sometimes, and it is *NOT* a failure.
+  //        thank you, enet. let's ignore failures altogether then.
+  count := 10; // no more than ten events in a row
+  sres := enet_host_service(NetMHost, @NetMEvent, timeout);
+  while (sres > 0) do
   begin
-    sres := enet_host_service(NetMHost, @NetMEvent, timeout);
+    {
     if (sres < 0) then
     begin
-      g_Console_Add(_lc[I_NET_MSG_ERROR]+_lc[I_NET_ERR_CLIENT], True);
+      e_LogWriteln(_lc[I_NET_MSG_ERROR] + _lc[I_NET_ERR_CLIENT] + ' (host_service)', TMsgType.Notify);
       for f := 0 to High(mlist) do mlist[f].clear();
       SetLength(mlist, 0);
       enet_host_destroy(NetMHost);
       NetMHost := nil;
       exit;
     end;
+    }
 
-    if (sres = 0) then break;
     idx := findByPeer(NetMEvent.peer);
     if (idx < 0) then
     begin
       e_LogWriteln('network event from unknown master host. ignored.', TMsgType.Warning);
       if (NetMEvent.kind = ENET_EVENT_TYPE_RECEIVE) then enet_packet_destroy(NetMEvent.packet);
-      continue;
-    end;
-
-    if (NetMEvent.kind = ENET_EVENT_TYPE_CONNECT) then
-    begin
-      mlist[idx].connectedEvent();
-    end
-    else if (NetMEvent.kind = ENET_EVENT_TYPE_DISCONNECT) then
-    begin
-      mlist[idx].disconnectedEvent();
     end
-    else if (NetMEvent.kind = ENET_EVENT_TYPE_RECEIVE) then
+    else
     begin
-      mlist[idx].receivedEvent(NetMEvent.packet);
-      enet_packet_destroy(NetMEvent.packet);
+      if (NetMEvent.kind = ENET_EVENT_TYPE_CONNECT) then
+      begin
+        mlist[idx].connectedEvent();
+      end
+      else if (NetMEvent.kind = ENET_EVENT_TYPE_DISCONNECT) then
+      begin
+        mlist[idx].disconnectedEvent();
+      end
+      else if (NetMEvent.kind = ENET_EVENT_TYPE_RECEIVE) then
+      begin
+        mlist[idx].receivedEvent(NetMEvent.packet);
+        enet_packet_destroy(NetMEvent.packet);
+      end;
     end;
+
+    Dec(count);
+    if (count = 0) then break;
+    sres := enet_host_service(NetMHost, @NetMEvent, 0);
   end;
 end;
 
@@ -1311,6 +1381,8 @@ begin
 
   g_Net_Slist_Pulse(); // this will create mhost
 
+  DisconnectAll(true); // forced disconnect
+
   NetOut.Clear();
   NetOut.Write(Byte(NET_MMSG_GET));
 
@@ -1320,13 +1392,12 @@ begin
 
   try
     e_WriteLog('Fetching serverlist...', TMsgType.Notify);
-    g_Console_Add(_lc[I_NET_MSG] + _lc[I_NET_SLIST_FETCH]);
+    g_Console_Add(_lc[I_NET_MSG]+_lc[I_NET_SLIST_FETCH]);
 
     // wait until all servers connected and answered
     stt := GetTimerMS();
     while true do
     begin
-      g_Net_Slist_Pulse(300);
       aliveCount := 0;
       hasUnanswered := false;
       for f := 0 to High(mlist) do
@@ -1342,12 +1413,14 @@ begin
           mlist[f].connect();
           if (mlist[f].isAlive()) then
           begin
+            //g_Console_Add(Format(_lc[I_NET_MSG]+_lc[I_NET_SLIST_WCONN], [mlist[f].hostName]));
             hasUnanswered := true;
             stt := GetTimerMS();
           end;
         end
         else if (mlist[f].isConnected()) then
         begin
+          //g_Console_Add(Format(_lc[I_NET_MSG]+_lc[I_NET_SLIST_CONN], [mlist[f].hostName]));
           if (mlist[f].srvAnswered = 0) then
           begin
             pkt := enet_packet_create(NetOut.Data, NetOut.CurSize, Cardinal(ENET_PACKET_FLAG_RELIABLE));
@@ -1379,6 +1452,7 @@ begin
       // check for timeout
       ct := GetTimerMS();
       if (ct < stt) or (ct-stt > 4000) then break;
+      g_Net_Slist_Pulse(300);
     end;
 
     if (aliveCount = 0) then