Improve network log output

src/game/Protocol/WorldSocket.cpp

@@ -76,7 +76,7 @@ WorldSocket::WorldSocket(IO::Networking::AsyncSocket socket)
 
 WorldSocket::~WorldSocket()
 {
-    m_socket.CloseSocket();
+    CloseSocket();
 }
 
 void WorldSocket::DoRecvIncomingData()
@@ -89,7 +89,7 @@ void WorldSocket::DoRecvIncomingData()
         {
             if (error.GetErrorType() != IO::NetworkError::ErrorType::SocketClosed || !self->IsClosing())
             {
-                sLog.Out(LOG_BASIC, LOG_LVL_BASIC, "WorldSocket::DoRecvIncomingData: IoError: %s", error.ToString().c_str());
+                sLog.Out(LOG_NETWORK, LOG_LVL_BASIC, "[%s] WorldSocket::DoRecvIncomingData: IoError: %s", self->m_socket.GetRemoteIpString().c_str(), error.ToString().c_str());
                 self->CloseSocket(); // This call to CloseSocket is actually necessary for once, so that others can see that this socket is not usable anymore
             }
             return;
@@ -103,7 +103,7 @@ void WorldSocket::DoRecvIncomingData()
 
         if ((header->size < 4) || (header->size > 0x2800) || (header->cmd >= NUM_MSG_TYPES))
         {
-            sLog.Out(LOG_BASIC, LOG_LVL_BASIC, "WorldSocket::DoRecvIncomingData: client sent malformed packet size = %u , cmd = %u", header->size, header->cmd);
+            sLog.Out(LOG_NETWORK, LOG_LVL_BASIC, "[%s] WorldSocket::DoRecvIncomingData: client sent malformed packet size = %u, cmd = %u", self->m_socket.GetRemoteIpString().c_str(), header->size, header->cmd);
             return;
         }
 
@@ -520,7 +520,7 @@ void WorldSocket::SendPacket(WorldPacket packet)
     if (m_sendQueue.size() > 1024) // There should never be so many packets queued up. The socket is probably not responding.
     {
         m_sendQueueLock.unlock();
-        sLog.Out(LOG_NETWORK, LOG_LVL_ERROR, "Send queue is full. Disconnect IP: ", GetRemoteIpString().c_str());
+        sLog.Out(LOG_NETWORK, LOG_LVL_ERROR, "[%s] Send queue is full. Disconnecting.", GetRemoteIpString().c_str());
         CloseSocket();
         return;
     }
@@ -541,7 +541,7 @@ void WorldSocket::HandleResultOfAsyncWrite(IO::NetworkError const& error, std::s
 {
     if (error)
     {
-        sLog.Out(LOG_NETWORK, LOG_LVL_ERROR, "Failed to send packet %s", error.ToString().c_str());
+        sLog.Out(LOG_NETWORK, LOG_LVL_ERROR, "[%s] Failed to send packet %s", GetRemoteIpString().c_str(), error.ToString().c_str());
         m_sendQueueIsRunning.clear();
         return;
     }
@@ -594,5 +594,8 @@ void WorldSocket::Start()
 
 void WorldSocket::CloseSocket()
 {
-    m_socket.CloseSocket();
+    if (m_socket.CloseSocket())
+    {
+        sLog.Out(LOG_NETWORK, LOG_LVL_BASIC, "[%s] Connection closed", GetRemoteIpString().c_str());
+    }
 }

src/game/Protocol/WorldSocketMgr.cpp

@@ -102,14 +102,14 @@ void WorldSocketMgr::OnNewClientConnected(IO::Networking::SocketDescriptor socke
                 return; // implicit close()
             }
             worldSocket->m_remoteIpAddressStringAfterProxy = maybeIp.value().ToString();
-            sLog.Out(LOG_BASIC, LOG_LVL_BASIC, "Accepting connection from %s (proxy ip: %s)", worldSocket->GetRemoteIpString().c_str(), worldSocket->m_socket.GetRemoteIpString().c_str());
+            sLog.Out(LOG_NETWORK, LOG_LVL_BASIC, "[%s] Connection accepted (proxy ip: %s)", worldSocket->GetRemoteIpString().c_str(), worldSocket->m_socket.GetRemoteIpString().c_str());
             worldSocket->Start();
         });
     }
     else
     {
         // no proxy, we can start directly
-        sLog.Out(LOG_BASIC, LOG_LVL_BASIC, "Accepting connection from %s", worldSocket->GetRemoteIpString().c_str());
+        sLog.Out(LOG_NETWORK, LOG_LVL_BASIC, "[%s] Connection accepted", worldSocket->GetRemoteIpString().c_str());
         worldSocket->Start();
     }
 }

src/realmd/AuthSocket.cpp

@@ -92,7 +92,7 @@ void AuthSocket::Start()
 
 AuthSocket::~AuthSocket()
 {
-    m_socket.CloseSocket();
+    CloseSocket();
 
     if (m_sessionDurationTimeout)
         m_sessionDurationTimeout->Cancel();
@@ -111,13 +111,13 @@ void AuthSocket::DoRecvIncomingData()
 {
     std::shared_ptr<eAuthCmd> cmd = std::make_shared<eAuthCmd>();
 
-    sLog.Out(LOG_BASIC, LOG_LVL_DEBUG, "DoRecvIncomingData() Reading... Ready for next opcode");
+    sLog.Out(LOG_BASIC, LOG_LVL_DEBUG, "[%s] DoRecvIncomingData() Reading... Ready for next opcode", GetRemoteIpString().c_str());
     m_socket.Read((char*)cmd.get(), sizeof(eAuthCmd), [self = shared_from_this(), cmd](IO::NetworkError const& error, size_t) -> void
     {
         if (error)
         {
             if (error.GetErrorType() != IO::NetworkError::ErrorType::SocketClosed)
-                sLog.Out(LOG_BASIC, LOG_LVL_ERROR, "[Auth] DoRecvIncomingData Read(cmd) error: %s", error.ToString().c_str());
+                sLog.Out(LOG_BASIC, LOG_LVL_ERROR, "[%s] DoRecvIncomingData Read(cmd) error: %s", self->GetRemoteIpString().c_str(), error.ToString().c_str());
             return;
         }
 
@@ -143,15 +143,15 @@ void AuthSocket::DoRecvIncomingData()
             if (table[i].cmd != *cmd)
                 continue;
 
-            sLog.Out(LOG_BASIC, LOG_LVL_DEBUG, "[Auth] CMD: %u requires status %u, user has %u", *cmd, table[i].status, self->m_status);
+            sLog.Out(LOG_BASIC, LOG_LVL_DEBUG, "[%s] CMD: %u requires status %u, user has %u", self->GetRemoteIpString().c_str(), *cmd, table[i].status, self->m_status);
 
             if (table[i].status != self->m_status)
             { // unauthorized
-                sLog.Out(LOG_BASIC, LOG_LVL_ERROR, "[Auth] Received unauthorized command %u", *cmd);
+                sLog.Out(LOG_BASIC, LOG_LVL_ERROR, "[%s] Received unauthorized command %u", self->GetRemoteIpString().c_str(), *cmd);
                 return;
             }
 
-            sLog.Out(LOG_BASIC, LOG_LVL_DEBUG, "[Auth] Got data for cmd %u", *cmd);
+            sLog.Out(LOG_BASIC, LOG_LVL_DEBUG, "[%s] Got data for cmd %u", self->GetRemoteIpString().c_str(), *cmd);
 
             // this handler will async call Read and Write, and hopefully will call DoRecvIncomingData or CloseSocket when done.
             ((*self).*table[i].asyncHandler)();
@@ -1478,5 +1478,8 @@ bool AuthSocket::VerifyVersion(uint8 const* a, int32 aLength, uint8 const* versi
 
 void AuthSocket::CloseSocket()
 {
-    m_socket.CloseSocket();
+    if (m_socket.CloseSocket())
+    {
+        sLog.Out(LOG_NETWORK, LOG_LVL_BASIC, "[%s] Connection closed", GetRemoteIpString().c_str());
+    }
 }

src/realmd/Main.cpp

@@ -262,14 +262,14 @@ extern int main(int argc, char** argv)
                     return; // implicit close()
                 }
                 authSocket->m_remoteIpAddressStringAfterProxy = maybeIp.value().ToString();
-                sLog.Out(LOG_BASIC, LOG_LVL_BASIC, "Accepting connection from %s (proxy ip: %s)", authSocket->GetRemoteIpString().c_str(), authSocket->m_socket.GetRemoteIpString().c_str());
+                sLog.Out(LOG_NETWORK, LOG_LVL_BASIC, "[%s] Connection accepted (proxy ip: %s)", authSocket->GetRemoteIpString().c_str(), authSocket->m_socket.GetRemoteIpString().c_str());
                 authSocket->Start();
             });
         }
         else
         {
             // no proxy, we can start directly
-            sLog.Out(LOG_BASIC, LOG_LVL_BASIC, "Accepting connection from %s", authSocket->GetRemoteIpString().c_str());
+            sLog.Out(LOG_NETWORK, LOG_LVL_BASIC, "[%s] Connection accepted", authSocket->GetRemoteIpString().c_str());
             authSocket->Start();
         }
     });

src/shared/IO/Networking/AsyncSocket.cpp

@@ -33,7 +33,7 @@ IO::Networking::AsyncSocket::~AsyncSocket()
     if (state & SocketStateFlags::WAS_MOVED_NO_DTOR)
         return; // Ignore destructor
 
-    sLog.Out(LOG_NETWORK, LOG_LVL_DEBUG, "Destructor called ~AsyncSocket: No references left");
+    sLog.Out(LOG_NETWORK, LOG_LVL_DEBUG, "[%s] Destructor called ~AsyncSocket: No references left", GetRemoteIpString().c_str());
     CloseSocket();
 
 //#ifdef DEBUG

src/shared/IO/Networking/AsyncSocket.h

@@ -61,7 +61,8 @@ namespace IO { namespace Networking {
             /// Useful for computational expensive operations (e.g. packing and encryption), that should be avoided in the main loop
             void EnterIoContext(std::function<void(IO::NetworkError)> const& callback);
 
-            void CloseSocket();
+            /// Will return false if the connection was already closed
+            bool CloseSocket();
             bool IsClosing() const;
 
             IO::Networking::IpEndpoint const& GetRemoteEndpoint() const

src/shared/IO/Networking/AsyncSocket_posix.cpp

@@ -90,7 +90,7 @@ void IO::Networking::AsyncSocket::Read(char* target, std::size_t size, std::func
     if (alreadyRead == 0)
     {
         m_atomicState.fetch_and(~SocketStateFlags::READ_PENDING_SET);
-        sLog.Out(LOG_NETWORK, LOG_LVL_DEBUG, "Read(...) -> ::recv() returned 0, which means the socket is half-closed.");
+        sLog.Out(LOG_NETWORK, LOG_LVL_DEBUG, "[%s] Read(...) -> ::recv() returned 0, which means the socket is half-closed.", GetRemoteIpString().c_str());
         callback(IO::NetworkError(IO::NetworkError::ErrorType::SocketClosed), 0);
         StopPendingTransactionsAndForceClose();
         return;
@@ -158,7 +158,7 @@ void IO::Networking::AsyncSocket::ReadSome(char* target, std::size_t size, std::
     if (alreadyRead == 0)
     {
         m_atomicState.fetch_and(~SocketStateFlags::READ_PENDING_SET);
-        sLog.Out(LOG_NETWORK, LOG_LVL_DEBUG, "Read(...) -> ::recv() returned 0, which means the socket is half-closed.");
+        sLog.Out(LOG_NETWORK, LOG_LVL_DEBUG, "[%s] Read(...) -> ::recv() returned 0, which means the socket is half-closed.", GetRemoteIpString().c_str());
         callback(IO::NetworkError(IO::NetworkError::ErrorType::SocketClosed), 0);
         StopPendingTransactionsAndForceClose();
         return;
@@ -255,7 +255,7 @@ void IO::Networking::AsyncSocket::CloseSocket()
     if (m_atomicState.fetch_or(SocketStateFlags::SHUTDOWN_PENDING) & SocketStateFlags::SHUTDOWN_PENDING)
         return; // there was already a ::close()
 
-    sLog.Out(LOG_NETWORK, LOG_LVL_DEBUG, "CloseSocket(): Disconnect request");
+    sLog.Out(LOG_NETWORK, LOG_LVL_DEBUG, "[%s] CloseSocket(): Disconnect request", GetRemoteIpString().c_str());
     m_descriptor.CloseSocket(); // will silently remove from this socket from the epoll/kqueue set
 }
 
@@ -292,13 +292,13 @@ void IO::Networking::AsyncSocket::PerformNonBlockingRead()
     if (newWrittenBytes == 0)
     {
         m_atomicState.fetch_and(~SocketStateFlags::READ_PENDING_LOAD);
-        sLog.Out(LOG_NETWORK, LOG_LVL_DEBUG, "::recv() returned 0, which means the socket is half-closed.");
+        sLog.Out(LOG_NETWORK, LOG_LVL_DEBUG, "[%s] ::recv() returned 0, which means the socket is half-closed.", GetRemoteIpString().c_str());
         StopPendingTransactionsAndForceClose();
         return;
     }
     if (newWrittenBytes < 0)
     {
-        sLog.Out(LOG_NETWORK, LOG_LVL_ERROR, "::recv on client failed: %s", SystemErrorToString(errno).c_str());
+        sLog.Out(LOG_NETWORK, LOG_LVL_ERROR, "[%s] ::recv on client failed: %s", GetRemoteIpString().c_str(), SystemErrorToString(errno).c_str());
         m_atomicState.fetch_and(~SocketStateFlags::READ_PENDING_LOAD);
         return;
     }
@@ -365,7 +365,7 @@ void IO::Networking::AsyncSocket::PerformNonBlockingWrite()
     {
         if (errno != EWOULDBLOCK)
         {
-            sLog.Out(LOG_NETWORK, LOG_LVL_ERROR, "::send on client failed: %s", SystemErrorToString(errno).c_str());
+            sLog.Out(LOG_NETWORK, LOG_LVL_ERROR, "[%s] ::send on client failed: %s", GetRemoteIpString().c_str(), SystemErrorToString(errno).c_str());
         }
         m_atomicState.fetch_and(~SocketStateFlags::WRITE_PENDING_LOAD);
         return;
@@ -509,17 +509,17 @@ void IO::Networking::AsyncSocket::OnIoEvent(uint32_t event)
         socklen_t errLen = sizeof(error);
         if (::getsockopt(m_descriptor.GetNativeSocket(), SOL_SOCKET, SO_ERROR, (void*)&error, &errLen) == 0)
         {
-            sLog.Out(LOG_NETWORK, LOG_LVL_ERROR, "epoll reported socket error: %s", SystemErrorToString(error).c_str());
+            sLog.Out(LOG_NETWORK, LOG_LVL_ERROR, "[%s] epoll reported socket error: %s", GetRemoteIpString().c_str(), SystemErrorToString(error).c_str());
         }
         else
         {
-            sLog.Out(LOG_NETWORK, LOG_LVL_ERROR, "epoll reported socket error: Internal error");
+            sLog.Out(LOG_NETWORK, LOG_LVL_ERROR, "[%s] epoll reported socket error: Internal error", GetRemoteIpString().c_str());
         }
         StopPendingTransactionsAndForceClose();
     }
     else if (event & EPOLLRDHUP)
     {
-        sLog.Out(LOG_NETWORK, LOG_LVL_DEBUG, "EPOLLRDHUP -> Going to disconnect.");
+        sLog.Out(LOG_NETWORK, LOG_LVL_DEBUG, "[%s] EPOLLRDHUP -> Going to disconnect.", GetRemoteIpString().c_str());
         StopPendingTransactionsAndForceClose();
     }
     else
@@ -539,14 +539,14 @@ void IO::Networking::AsyncSocket::OnIoEvent(uint32_t event)
             socklen_t errLen = sizeof(error);
             if (::getsockopt(m_descriptor.GetNativeSocket(), SOL_SOCKET, SO_ERROR, (void*)&error, &errLen) == 0)
             {
-                sLog.Out(LOG_NETWORK, LOG_LVL_ERROR, "kqueue reported socket exception: Error: %s", SystemErrorToString(error).c_str());
+                sLog.Out(LOG_NETWORK, LOG_LVL_ERROR, "[%s] kqueue reported socket exception: Error: %s", GetRemoteIpString().c_str(), SystemErrorToString(error).c_str());
 
                 if (error == 0)
                     break;
             }
             else
             {
-                sLog.Out(LOG_NETWORK, LOG_LVL_ERROR, "kqueue reported socket exception: Internal error");
+                sLog.Out(LOG_NETWORK, LOG_LVL_ERROR, "[%s] kqueue reported socket exception: Internal error", GetRemoteIpString().c_str());
             }
             StopPendingTransactionsAndForceClose();
             break;

src/shared/IO/Networking/AsyncSocket_windows.cpp

@@ -78,7 +78,7 @@ void IO::Networking::AsyncSocket::Read(char* target, std::size_t size, std::func
         uint64_t bytesProcessed = m_currentReadTask.InternalHigh;
         if (bytesProcessed == 0)
         { // 0 means the socket is already closed on the other side
-            sLog.Out(LOG_NETWORK, LOG_LVL_DEBUG, "Empty response -> Going to disconnect.");
+            sLog.Out(LOG_NETWORK, LOG_LVL_DEBUG, "[%s] Empty response -> Going to disconnect.", GetRemoteIpString().c_str());
             CloseSocket();
             auto tmpCallback = std::move(m_readCallback);
             m_currentReadTask.Reset();
@@ -185,7 +185,7 @@ void IO::Networking::AsyncSocket::ReadSome(char* target, std::size_t size, std::
         uint64_t bytesProcessed = m_currentReadTask.InternalHigh;
         if (bytesProcessed == 0)
         { // 0 means the socket is already closed on the other side
-            sLog.Out(LOG_NETWORK, LOG_LVL_DEBUG, "Empty response -> Going to disconnect.");
+            sLog.Out(LOG_NETWORK, LOG_LVL_DEBUG, "[%s] Empty response -> Going to disconnect.", GetRemoteIpString().c_str());
             CloseSocket();
             auto tmpCallback = std::move(m_readCallback);
             m_currentReadTask.Reset();
@@ -315,14 +315,14 @@ void IO::Networking::AsyncSocket::Write(IO::ReadableBuffer const& source, std::f
     }
 }
 
-void IO::Networking::AsyncSocket::CloseSocket()
+bool IO::Networking::AsyncSocket::CloseSocket()
 {
     // set SHUTDOWN_PENDING flag, and check if there was already a previous one
     if (m_atomicState.fetch_or(SocketStateFlags::SHUTDOWN_PENDING) & SocketStateFlags::SHUTDOWN_PENDING)
-        return; // there was already a ::close()
+        return false; // there was already a ::close()
 
-    sLog.Out(LOG_NETWORK, LOG_LVL_DEBUG, "CloseSocket(): Disconnect request");
     m_descriptor.CloseSocket(); // will interrupt and fail all pending IOCP events and post them to the queue
+    return true;
 }
 
 /// The callback is invoked in the IO thread

src/shared/IO/Networking/SocketDescriptor.cpp

@@ -15,9 +15,8 @@ IO::Networking::SocketDescriptor::~SocketDescriptor()
 
 void IO::Networking::SocketDescriptor::CloseSocket()
 {
-    if (!m_isClosed)
-    {
-        IO::Networking::Internal::CloseSocket(m_nativeSocket);
-        m_isClosed = true;
-    }
+    if (m_isClosed)
+        return;
+    m_isClosed = true;
+    IO::Networking::Internal::CloseSocket(m_nativeSocket);
 }