From 4faa2c1c9ed054c141088744821f3a4900d9e92d Mon Sep 17 00:00:00 2001 From: 0blu Date: Fri, 18 Oct 2024 18:47:59 +0200 Subject: [PATCH] Improve network log output --- src/game/Protocol/WorldSocket.cpp | 15 ++++++++----- src/game/Protocol/WorldSocketMgr.cpp | 4 ++-- src/realmd/AuthSocket.cpp | 17 ++++++++------ src/realmd/Main.cpp | 4 ++-- src/shared/IO/Networking/AsyncSocket.cpp | 2 +- src/shared/IO/Networking/AsyncSocket.h | 3 ++- .../IO/Networking/AsyncSocket_posix.cpp | 22 +++++++++---------- .../IO/Networking/AsyncSocket_windows.cpp | 10 ++++----- src/shared/IO/Networking/SocketDescriptor.cpp | 9 ++++---- 9 files changed, 46 insertions(+), 40 deletions(-) diff --git a/src/game/Protocol/WorldSocket.cpp b/src/game/Protocol/WorldSocket.cpp index cfdb91acdc4..46d467bad8b 100644 --- a/src/game/Protocol/WorldSocket.cpp +++ b/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()); + } } diff --git a/src/game/Protocol/WorldSocketMgr.cpp b/src/game/Protocol/WorldSocketMgr.cpp index 9fceee5d99b..5a193de088e 100644 --- a/src/game/Protocol/WorldSocketMgr.cpp +++ b/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(); } } diff --git a/src/realmd/AuthSocket.cpp b/src/realmd/AuthSocket.cpp index 54ef8cb8dbe..903ccee6411 100644 --- a/src/realmd/AuthSocket.cpp +++ b/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 cmd = std::make_shared(); - 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()); + } } diff --git a/src/realmd/Main.cpp b/src/realmd/Main.cpp index 610641b581f..b51e9ee644e 100644 --- a/src/realmd/Main.cpp +++ b/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(); } }); diff --git a/src/shared/IO/Networking/AsyncSocket.cpp b/src/shared/IO/Networking/AsyncSocket.cpp index 0f6cb9ffd85..90224b33e99 100644 --- a/src/shared/IO/Networking/AsyncSocket.cpp +++ b/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 diff --git a/src/shared/IO/Networking/AsyncSocket.h b/src/shared/IO/Networking/AsyncSocket.h index ec3f06b0e6e..800cd1ea42c 100644 --- a/src/shared/IO/Networking/AsyncSocket.h +++ b/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 const& callback); - void CloseSocket(); + /// Will return false if the connection was already closed + bool CloseSocket(); bool IsClosing() const; IO::Networking::IpEndpoint const& GetRemoteEndpoint() const diff --git a/src/shared/IO/Networking/AsyncSocket_posix.cpp b/src/shared/IO/Networking/AsyncSocket_posix.cpp index 229e1f45410..49dfb941597 100644 --- a/src/shared/IO/Networking/AsyncSocket_posix.cpp +++ b/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; diff --git a/src/shared/IO/Networking/AsyncSocket_windows.cpp b/src/shared/IO/Networking/AsyncSocket_windows.cpp index 875206e7f49..98219c129e6 100644 --- a/src/shared/IO/Networking/AsyncSocket_windows.cpp +++ b/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 diff --git a/src/shared/IO/Networking/SocketDescriptor.cpp b/src/shared/IO/Networking/SocketDescriptor.cpp index e7a90760ffd..8c6501b00b5 100644 --- a/src/shared/IO/Networking/SocketDescriptor.cpp +++ b/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); }