From d0da5d392f64c63fefde352a2a0b569317ca59cc Mon Sep 17 00:00:00 2001 From: madmaxoft Date: Fri, 24 Jan 2014 23:03:48 +0100 Subject: Added per-connection comm logging in debug mode. It is meant for debugging only, so it is compiled only into debug mode. It is activated by starting the server with "/logcomm" parameter. --- src/Protocol/Protocol17x.cpp | 64 ++++++++++++++++++++++++++++++++++++++++++++ src/Protocol/Protocol17x.h | 5 ++++ 2 files changed, 69 insertions(+) (limited to 'src/Protocol') diff --git a/src/Protocol/Protocol17x.cpp b/src/Protocol/Protocol17x.cpp index 9506332dc..d2d0df7f7 100644 --- a/src/Protocol/Protocol17x.cpp +++ b/src/Protocol/Protocol17x.cpp @@ -53,6 +53,18 @@ Implements the 1.7.x protocol classes: +#ifdef _DEBUG +// fwd: main.cpp: +extern bool g_ShouldLogComm; +#endif + + + + + +/////////////////////////////////////////////////////////////////////////////////////////////////////////////////////// +// cProtocol172: + cProtocol172::cProtocol172(cClientHandle * a_Client, const AString & a_ServerAddress, UInt16 a_ServerPort, UInt32 a_State) : super(a_Client), m_ServerAddress(a_ServerAddress), @@ -63,6 +75,15 @@ cProtocol172::cProtocol172(cClientHandle * a_Client, const AString & a_ServerAdd m_OutPacketLenBuffer(20), // 20 bytes is more than enough for one VarInt m_IsEncrypted(false) { + // Create the comm log file, if so requested: + #ifdef _DEBUG + if (g_ShouldLogComm) + { + cFile::CreateFolder("CommLogs"); + AString FileName = Printf("CommLogs/%x__%s.log", (unsigned)time(NULL), a_Client->GetIPString().c_str()); + m_CommLogFile.Open(FileName, cFile::fmWrite); + } + #endif // _DEBUG } @@ -1065,6 +1086,18 @@ void cProtocol172::SendWindowProperty(const cWindow & a_Window, short a_Property void cProtocol172::AddReceivedData(const char * a_Data, int a_Size) { + // Write the incoming data into the comm log file: + #ifdef _DEBUG + if (g_ShouldLogComm) + { + AString Hex; + CreateHexDump(Hex, a_Data, a_Size, 16); + m_CommLogFile.Printf("Incoming data: %d bytes. %d bytes unparsed already present in buffer.\n%s\n", + a_Size, m_ReceivedData.GetReadableSpace(), Hex.c_str() + ); + } + #endif + if (!m_ReceivedData.Write(a_Data, a_Size)) { // Too much data in the incoming queue, report to caller: @@ -1100,6 +1133,24 @@ void cProtocol172::AddReceivedData(const char * a_Data, int a_Size) return; } + // Log the packet info into the comm log file: + #ifdef _DEBUG + if (g_ShouldLogComm) + { + AString PacketData; + bb.ReadAll(PacketData); + bb.ResetRead(); + bb.ReadVarInt(PacketType); + ASSERT(PacketData.size() > 0); + PacketData.resize(PacketData.size() - 1); + AString PacketDataHex; + CreateHexDump(PacketDataHex, PacketData.data(), PacketData.size(), 16); + m_CommLogFile.Printf("Next incoming packet is type %u (0x%x), length %u (0x%x) at state %d. Payload:\n%s\n", + PacketType, PacketType, PacketLen, PacketLen, m_State, PacketDataHex.c_str() + ); + } + #endif // _DEBUG + if (!HandlePacket(bb, PacketType)) { // Unknown packet, already been reported, but without the length. Log the length here: @@ -1807,6 +1858,19 @@ cProtocol172::cPacketizer::~cPacketizer() m_Out.ReadAll(DataToSend); m_Protocol.SendData(DataToSend.data(), DataToSend.size()); m_Out.CommitRead(); + + // Log the comm into logfile: + #ifdef _DEBUG + if (g_ShouldLogComm) + { + AString Hex; + ASSERT(DataToSend.size() > 0); + CreateHexDump(Hex, DataToSend.data() + 1, DataToSend.size() - 1, 16); + m_Protocol.m_CommLogFile.Printf("Outgoing packet: type %d (0x%x), length %u (0x%x), state %d. Payload:\n%s\n", + DataToSend[0], DataToSend[0], PacketLen, PacketLen, m_Protocol.m_State, Hex.c_str() + ); + } + #endif // _DEBUG } diff --git a/src/Protocol/Protocol17x.h b/src/Protocol/Protocol17x.h index 3f440f313..b04a1f019 100644 --- a/src/Protocol/Protocol17x.h +++ b/src/Protocol/Protocol17x.h @@ -223,6 +223,11 @@ protected: CryptoPP::CFB_Mode::Decryption m_Decryptor; CryptoPP::CFB_Mode::Encryption m_Encryptor; + #ifdef _DEBUG + /** The logfile where the comm is logged, when g_ShouldLogComm is true */ + cFile m_CommLogFile; + #endif + /// Adds the received (unencrypted) data to m_ReceivedData, parses complete packets void AddReceivedData(const char * a_Data, int a_Size); -- cgit v1.2.3 From 96b4af15963ac70b25ab243d84d48221a3d41369 Mon Sep 17 00:00:00 2001 From: madmaxoft Date: Sat, 25 Jan 2014 15:06:21 +0100 Subject: Protocol17: Comm logging shows the data left over from previous parse. --- src/Protocol/Protocol17x.cpp | 17 +++++++++++++++-- 1 file changed, 15 insertions(+), 2 deletions(-) (limited to 'src/Protocol') diff --git a/src/Protocol/Protocol17x.cpp b/src/Protocol/Protocol17x.cpp index d2d0df7f7..8abe4f259 100644 --- a/src/Protocol/Protocol17x.cpp +++ b/src/Protocol/Protocol17x.cpp @@ -1090,10 +1090,23 @@ void cProtocol172::AddReceivedData(const char * a_Data, int a_Size) #ifdef _DEBUG if (g_ShouldLogComm) { + if (m_ReceivedData.GetReadableSpace() > 0) + { + AString AllData; + int OldReadableSpace = m_ReceivedData.GetReadableSpace(); + m_ReceivedData.ReadAll(AllData); + m_ReceivedData.ResetRead(); + m_ReceivedData.SkipRead(m_ReceivedData.GetReadableSpace() - OldReadableSpace); + AString Hex; + CreateHexDump(Hex, AllData.data(), AllData.size(), 16); + m_CommLogFile.Printf("Incoming data, %d (0x%x) bytes unparsed already present in buffer:\n%s\n", + AllData.size(), AllData.size(), Hex.c_str() + ); + } AString Hex; CreateHexDump(Hex, a_Data, a_Size, 16); - m_CommLogFile.Printf("Incoming data: %d bytes. %d bytes unparsed already present in buffer.\n%s\n", - a_Size, m_ReceivedData.GetReadableSpace(), Hex.c_str() + m_CommLogFile.Printf("Incoming data: %d (0x%x) bytes: \n%s\n", + a_Size, a_Size, Hex.c_str() ); } #endif -- cgit v1.2.3 From ff066453b805748d6e665b3ad219a62c777e4453 Mon Sep 17 00:00:00 2001 From: madmaxoft Date: Sat, 25 Jan 2014 15:28:16 +0100 Subject: Comm logging is available in both Debug and Release modes. --- src/Protocol/Protocol17x.cpp | 26 ++++++++++++++++---------- src/Protocol/Protocol17x.h | 2 -- 2 files changed, 16 insertions(+), 12 deletions(-) (limited to 'src/Protocol') diff --git a/src/Protocol/Protocol17x.cpp b/src/Protocol/Protocol17x.cpp index 8abe4f259..504dd99c3 100644 --- a/src/Protocol/Protocol17x.cpp +++ b/src/Protocol/Protocol17x.cpp @@ -53,10 +53,8 @@ Implements the 1.7.x protocol classes: -#ifdef _DEBUG // fwd: main.cpp: extern bool g_ShouldLogComm; -#endif @@ -76,14 +74,12 @@ cProtocol172::cProtocol172(cClientHandle * a_Client, const AString & a_ServerAdd m_IsEncrypted(false) { // Create the comm log file, if so requested: - #ifdef _DEBUG if (g_ShouldLogComm) { cFile::CreateFolder("CommLogs"); AString FileName = Printf("CommLogs/%x__%s.log", (unsigned)time(NULL), a_Client->GetIPString().c_str()); m_CommLogFile.Open(FileName, cFile::fmWrite); } - #endif // _DEBUG } @@ -1087,7 +1083,6 @@ void cProtocol172::SendWindowProperty(const cWindow & a_Window, short a_Property void cProtocol172::AddReceivedData(const char * a_Data, int a_Size) { // Write the incoming data into the comm log file: - #ifdef _DEBUG if (g_ShouldLogComm) { if (m_ReceivedData.GetReadableSpace() > 0) @@ -1109,7 +1104,6 @@ void cProtocol172::AddReceivedData(const char * a_Data, int a_Size) a_Size, a_Size, Hex.c_str() ); } - #endif if (!m_ReceivedData.Write(a_Data, a_Size)) { @@ -1147,7 +1141,6 @@ void cProtocol172::AddReceivedData(const char * a_Data, int a_Size) } // Log the packet info into the comm log file: - #ifdef _DEBUG if (g_ShouldLogComm) { AString PacketData; @@ -1162,7 +1155,6 @@ void cProtocol172::AddReceivedData(const char * a_Data, int a_Size) PacketType, PacketType, PacketLen, PacketLen, m_State, PacketDataHex.c_str() ); } - #endif // _DEBUG if (!HandlePacket(bb, PacketType)) { @@ -1180,6 +1172,12 @@ void cProtocol172::AddReceivedData(const char * a_Data, int a_Size) LOGD("Packet contents:\n%s", Out.c_str()); #endif // _DEBUG + // Put a message in the comm log: + if (g_ShouldLogComm) + { + m_CommLogFile.Printf("^^^^^^ Unhandled packet ^^^^^^\n\n\n"); + } + return; } @@ -1189,6 +1187,16 @@ void cProtocol172::AddReceivedData(const char * a_Data, int a_Size) LOGWARNING("Protocol 1.7: Wrong number of bytes read for packet 0x%x, state %d. Read %u bytes, packet contained %u bytes", PacketType, m_State, bb.GetUsedSpace() - bb.GetReadableSpace(), PacketLen ); + + // Put a message in the comm log: + if (g_ShouldLogComm) + { + m_CommLogFile.Printf("^^^^^^ Wrong number of bytes read for this packet (exp %d left, got %d left) ^^^^^^\n\n\n", + 1, bb.GetReadableSpace() + ); + m_CommLogFile.Flush(); + } + ASSERT(!"Read wrong number of bytes!"); m_Client->PacketError(PacketType); } @@ -1873,7 +1881,6 @@ cProtocol172::cPacketizer::~cPacketizer() m_Out.CommitRead(); // Log the comm into logfile: - #ifdef _DEBUG if (g_ShouldLogComm) { AString Hex; @@ -1883,7 +1890,6 @@ cProtocol172::cPacketizer::~cPacketizer() DataToSend[0], DataToSend[0], PacketLen, PacketLen, m_Protocol.m_State, Hex.c_str() ); } - #endif // _DEBUG } diff --git a/src/Protocol/Protocol17x.h b/src/Protocol/Protocol17x.h index b04a1f019..cac7f0d29 100644 --- a/src/Protocol/Protocol17x.h +++ b/src/Protocol/Protocol17x.h @@ -223,10 +223,8 @@ protected: CryptoPP::CFB_Mode::Decryption m_Decryptor; CryptoPP::CFB_Mode::Encryption m_Encryptor; - #ifdef _DEBUG /** The logfile where the comm is logged, when g_ShouldLogComm is true */ cFile m_CommLogFile; - #endif /// Adds the received (unencrypted) data to m_ReceivedData, parses complete packets -- cgit v1.2.3