Adding packet logging + fixing lost packets (that are now kept for 2 seconds while waiting protocols that should receive them to be started).

git-svn-id: svn+ssh://svn.code.sf.net/p/supertuxkart/code/main/branches/hilnius@13652 178a84e3-b1eb-0310-8ba1-8eac791a3b58

src/config/user_config.hpp

@@ -563,6 +563,10 @@ namespace UserConfigParams
                             "stun.voxgratia.org",
                             "stun.xten.com") );
 
+    PARAM_PREFIX StringUserConfigParam m_packets_log_filename
+            PARAM_DEFAULT( StringUserConfigParam("packets_log.txt", "packets_log_filename",
+                                                 "Where to log received and sent packets.") );
+
     // ---- Graphic Quality
     PARAM_PREFIX GroupUserConfigParam        m_graphics_quality
             PARAM_DEFAULT( GroupUserConfigParam("GFX",

src/network/protocol_manager.cpp

@@ -142,6 +142,7 @@ void ProtocolManager::notifyEvent(Event* event)
     if (protocols_ids.size() != 0)
     {
         EventProcessingInfo epi;
+        epi.arrival_time = Time::getTimeSinceEpoch();
         epi.event = event2;
         epi.protocols_ids = protocols_ids;
         m_events_to_process.push_back(epi); // add the event to the queue
@@ -334,7 +335,7 @@ bool ProtocolManager::propagateEvent(EventProcessingInfo* event, bool synchronou
                 index++;
         }
     }
-    if (event->protocols_ids.size() == 0)
+    if (event->protocols_ids.size() == 0 || (Time::getTimeSinceEpoch()-event->arrival_time) >= TIME_TO_KEEP_EVENTS)
     {
         // because we made a copy of the event
         delete event->event->peer; // no more need of that

src/network/protocol_manager.hpp

@@ -31,6 +31,8 @@
 
 #include <vector>
 
+#define TIME_TO_KEEP_EVENTS 1.0
+
 /*!
  * \enum PROTOCOL_STATE
  * \brief Defines the three states that a protocol can have.
@@ -84,6 +86,7 @@ typedef struct ProtocolRequest
 typedef struct EventProcessingInfo
 {
     Event* event;
+    double arrival_time;
     std::vector<int> protocols_ids;
 } EventProcessingInfo;
 

src/network/protocols/connect_to_peer.cpp

@@ -117,6 +117,7 @@ void ConnectToPeer::asynchronousUpdate()
             }
             break;
         case CONNECTING: // waiting the peer to connect
+            break;
         case CONNECTED:
         {
             // the ping protocol is there for NAT traversal (disabled when connecting to LAN peer)

src/network/stk_host.cpp

@@ -18,6 +18,7 @@
 
 #include "network/stk_host.hpp"
 
+#include "config/user_config.hpp"
 #include "network/network_manager.hpp"
 #include "utils/log.hpp"
 #include "utils/time.hpp"
@@ -33,6 +34,26 @@
 #include <pthread.h>
 #include <signal.h>
 
+FILE* STKHost::m_log_file = NULL;
+pthread_mutex_t STKHost::m_log_mutex;
+
+void STKHost::logPacket(const NetworkString ns, bool incoming)
+{
+    if (m_log_file == NULL)
+        return;
+    pthread_mutex_lock(&m_log_mutex);
+    if (incoming)
+        fprintf(m_log_file, "[%d\t]  <--  ", (int)(Time::getRealTime()));
+    else
+        fprintf(m_log_file, "[%d\t]  -->  ", (int)(Time::getRealTime()));
+    for (int i = 0; i < ns.size(); i++)
+    {
+        fprintf(m_log_file, "%d.", ns[i]);
+    }
+    fprintf(m_log_file, "\n");
+    pthread_mutex_unlock(&m_log_mutex);
+}
+
 // ----------------------------------------------------------------------------
 
 void* STKHost::receive_data(void* self)
@@ -44,6 +65,8 @@ void* STKHost::receive_data(void* self)
     {
         while (enet_host_service(host, &event, 20) != 0) {
             Event* evt = new Event(&event);
+            if (evt->type == EVENT_TYPE_MESSAGE)
+                logPacket(evt->data(), true);
             if (event.type != ENET_EVENT_TYPE_NONE)
                 NetworkManager::getInstance()->notifyEvent(evt);
             delete evt;
@@ -62,7 +85,13 @@ STKHost::STKHost()
 {
     m_host = NULL;
     m_listening_thread = NULL;
+    m_log_file = NULL;
     pthread_mutex_init(&m_exit_mutex, NULL);
+    pthread_mutex_init(&m_log_mutex, NULL);
+    if (UserConfigParams::m_packets_log_filename.toString() != "")
+        m_log_file = fopen(UserConfigParams::m_packets_log_filename.c_str(), "w");
+    if (!m_log_file)
+        Log::warn("STKHost", "Network packets won't be logged: no file.");
 }
 
 // ----------------------------------------------------------------------------
@@ -70,6 +99,8 @@ STKHost::STKHost()
 STKHost::~STKHost()
 {
     stopListening();
+    if (m_log_file)
+        fclose(m_log_file);
     if (m_host)
     {
         enet_host_destroy(m_host);
@@ -158,6 +189,7 @@ void STKHost::sendRawPacket(uint8_t* data, int length, TransportAddress dst)
     sendto(m_host->socket, (char*)data, length, 0,(sockaddr*)&to, to_len);
     Log::verbose("STKHost", "Raw packet sent to %i.%i.%i.%i:%u", ((dst.ip>>24)&0xff)
     , ((dst.ip>>16)&0xff), ((dst.ip>>8)&0xff), ((dst.ip>>0)&0xff), dst.port);
+    STKHost::logPacket(NetworkString(std::string((char*)(data), length)), false);
 }
 
 // ----------------------------------------------------------------------------
@@ -177,6 +209,7 @@ uint8_t* STKHost::receiveRawPacket()
         len = recv(m_host->socket,(char*)buffer,2048, 0);
         Time::sleep(1);
     }
+    STKHost::logPacket(NetworkString(std::string((char*)(buffer), len)), true);
     return buffer;
 }
 
@@ -216,6 +249,7 @@ uint8_t* STKHost::receiveRawPacket(TransportAddress* sender)
         inet_ntop(AF_INET, &(addr.sin_addr), s, 20);
         Log::info("STKHost", "IPv4 Address of the sender was %s", s);
     }
+    STKHost::logPacket(NetworkString(std::string((char*)(buffer), len)), true);
     return buffer;
 }
 
@@ -264,6 +298,7 @@ uint8_t* STKHost::receiveRawPacket(TransportAddress sender, int max_tries)
         inet_ntop(AF_INET, &(addr.sin_addr), s, 20);
         Log::info("STKHost", "IPv4 Address of the sender was %s", s);
     }
+    STKHost::logPacket(NetworkString(std::string((char*)(buffer), len)), true);
     return buffer;
 }
 
@@ -274,6 +309,7 @@ void STKHost::broadcastPacket(const NetworkString& data, bool reliable)
     ENetPacket* packet = enet_packet_create(data.c_str(), data.size()+1,
                (reliable ? ENET_PACKET_FLAG_RELIABLE : ENET_PACKET_FLAG_UNSEQUENCED));
     enet_host_broadcast(m_host, 0, packet);
+    STKHost::logPacket(data, false);
 }
 
 // ----------------------------------------------------------------------------

src/network/stk_host.hpp

@@ -58,6 +58,13 @@ class STKHost
         STKHost();
         /*! \brief Destructor                                               */
         virtual ~STKHost();
+        
+        /*! \brief Log packets into a file
+         *  \param ns : The data in the packet
+         *  \param incoming : True if the packet comes from a peer.
+         *  False if it's sent to a peer.
+         */
+        static void logPacket(const NetworkString ns, bool incoming);
 
         /*! \brief Thread function checking if data is received.
          *  This function tries to get data from network low-level functions as
@@ -153,6 +160,8 @@ class STKHost
         pthread_t*  m_listening_thread; //!< Thread listening network events.
         pthread_mutex_t m_exit_mutex;   //!< Mutex to kill properly the thread
         bool        m_listening;
+        static FILE*       m_log_file;         //!< Where to log packets
+        static pthread_mutex_t m_log_mutex;    //!< To write in the log only once at a time
 
 };