[Logging] Netcode Logging Unify (#2443)

* [Logging] Unify netcode logging

* More tweaks, generator

* Exclude OP_SpecialMesg at callback level

* Consolidate packet loggers

* Log at EQStream level instead of proxy

* Fix C->S

* Server to server logging

* C-S for Loginserver

* Hook UCS for C->S

* Update eqemu_logsys.h

* World C->S logging

* Translate opcodes through patch system for client to server

* Additional logging requests

* Add detailed opcode translation logging

* vStringFormat resiliency

* Translate loginserver C->S

* Simplify out message string (reduce copies) and ignore legacy formats

* Update eqemu_logsys.cpp

* Log file format

* Handle deprecated categories

common/net/daybreak_connection.cpp

@@ -3,6 +3,7 @@
 #include "../event/task.h"
 #include "../data_verification.h"
 #include "crc32.h"
+#include "../eqemu_logsys.h"
 #include <zlib.h>
 #include <fmt/format.h>
 #include <sstream>
@@ -308,6 +309,8 @@ EQ::Net::DaybreakConnection::DaybreakConnection(DaybreakConnectionManager *owner
 	m_combined[1] = OP_Combined;
 	m_last_session_stats = Clock::now();
 	m_outgoing_budget = owner->m_options.outgoing_data_rate;
+
+	LogNetcode("New session [{}] with encode key [{}]", m_connect_code, HostToNetwork(m_encode_key));
 }
 
 //new connection made as client
@@ -466,7 +469,7 @@ void EQ::Net::DaybreakConnection::ProcessPacket(Packet &p)
 			for (int i = 1; i >= 0; --i) {
 				switch (m_encode_passes[i]) {
 					case EncodeXOR:
-						if (temp.GetInt8(0) == 0) 
+						if (temp.GetInt8(0) == 0)
 							Decode(temp, DaybreakHeader::size(), temp.Length() - DaybreakHeader::size());
 						else
 							Decode(temp, 1, temp.Length() - 1);
@@ -630,6 +633,8 @@ void EQ::Net::DaybreakConnection::ProcessDecodedPacket(const Packet &p)
 					DynamicPacket p;
 					p.PutSerialize(0, reply);
 					InternalSend(p);
+
+					LogNetcode("[OP_SessionRequest] Session [{}] started with encode key [{}]", m_connect_code, HostToNetwork(m_encode_key));
 				}
 
 				break;
@@ -647,6 +652,12 @@ void EQ::Net::DaybreakConnection::ProcessDecodedPacket(const Packet &p)
 						m_encode_passes[1] = (DaybreakEncodeType)reply.encode_pass2;
 						m_max_packet_size = reply.max_packet_size;
 						ChangeStatus(StatusConnected);
+
+						LogNetcode(
+							"[OP_SessionResponse] Session [{}] refresh with encode key [{}]",
+							m_connect_code,
+							HostToNetwork(m_encode_key)
+						);
 					}
 				}
 				break;
@@ -771,6 +782,12 @@ void EQ::Net::DaybreakConnection::ProcessDecodedPacket(const Packet &p)
 					SendDisconnect();
 				}
 
+				LogNetcode(
+					"[OP_SessionDisconnect] Session [{}] disconnect with encode key [{}]",
+					m_connect_code,
+					HostToNetwork(m_encode_key)
+				);
+
 				ChangeStatus(StatusDisconnecting);
 				break;
 			}
@@ -835,6 +852,7 @@ bool EQ::Net::DaybreakConnection::ValidateCRC(Packet &p)
 	}
 
 	if (p.Length() < (size_t)m_crc_bytes) {
+		LogNetcode("Session [{}] ignored packet (crc bytes invalid on session)", m_connect_code);
 		return false;
 	}
 
@@ -1078,7 +1096,7 @@ void EQ::Net::DaybreakConnection::ProcessResend(int stream)
 	if (m_status == DbProtocolStatus::StatusDisconnected) {
 		return;
 	}
-	
+
 	auto resends = 0;
 	auto now = Clock::now();
 	auto s = &m_streams[stream];
@@ -1113,7 +1131,7 @@ void EQ::Net::DaybreakConnection::ProcessResend(int stream)
 				Close();
 				return;
 			}
-	
+
 			if ((size_t)time_since_last_send.count() > entry.second.resend_delay) {
 				auto &p = entry.second.packet;
 				if (p.Length() >= DaybreakHeader::size()) {
@@ -1406,8 +1424,8 @@ void EQ::Net::DaybreakConnection::InternalQueuePacket(Packet &p, int stream_id,
 		sent.first_sent = Clock::now();
 		sent.times_resent = 0;
 		sent.resend_delay = EQ::Clamp(
-			static_cast<size_t>((m_rolling_ping * m_owner->m_options.resend_delay_factor) + m_owner->m_options.resend_delay_ms), 
-			m_owner->m_options.resend_delay_min, 
+			static_cast<size_t>((m_rolling_ping * m_owner->m_options.resend_delay_factor) + m_owner->m_options.resend_delay_ms),
+			m_owner->m_options.resend_delay_min,
 			m_owner->m_options.resend_delay_max);
 		stream->sent_packets.insert(std::make_pair(stream->sequence_out, sent));
 		stream->sequence_out++;

common/net/eqstream.cpp

@@ -65,6 +65,15 @@ EQ::Net::EQStream::~EQStream()
 }
 
 void EQ::Net::EQStream::QueuePacket(const EQApplicationPacket *p, bool ack_req) {
+
+	LogPacketServerClient(
+		"[{}] [{:#06x}] Size [{}] {}",
+		OpcodeManager::EmuToName(p->GetOpcode()),
+		(*m_opcode_manager)->EmuToEQ(p->GetOpcode()),
+		p->Size(),
+		(LogSys.IsLogEnabled(Logs::Detail, Logs::PacketServerClient) ? DumpPacketToString(p) : "")
+	);
+
 	if (m_opcode_manager && *m_opcode_manager) {
 		uint16 opcode = 0;
 		if (p->GetOpcodeBypass() != 0) {

common/net/eqstream.h

@@ -57,6 +57,10 @@ namespace EQ
 			virtual void SetOpcodeManager(OpcodeManager **opm) {
 				m_opcode_manager = opm;
 			}
+			virtual OpcodeManager * GetOpcodeManager() const
+			{
+				return (*m_opcode_manager);
+			};
 
 			virtual Stats GetStats() const;
 			virtual void ResetStats();

common/net/servertalk_server_connection.cpp

@@ -135,7 +135,7 @@ void EQ::Net::ServertalkServerConnection::ProcessReadBuffer()
 		auto leg_opcode = *(uint16_t*)&m_buffer[current];
 		auto leg_size = *(uint16_t*)&m_buffer[current + 2] - 4;
 
-		//this creates a small edge case where the exact size of a 
+		//this creates a small edge case where the exact size of a
 		//packet from the modern protocol can't be "43061256"
 		//so in send we pad it one byte if that's the case
 		if (leg_opcode == ServerOP_NewLSInfo && leg_size == sizeof(ServerNewLSInfo_Struct)) {
@@ -319,6 +319,16 @@ void EQ::Net::ServertalkServerConnection::ProcessMessage(EQ::Net::Packet &p)
 			size_t message_len = length;
 			EQ::Net::StaticPacket packet(&data[0], message_len);
 
+			const auto is_detail_enabled = LogSys.IsLogEnabled(Logs::Detail, Logs::PacketServerToServer);
+			if (opcode != ServerOP_KeepAlive || is_detail_enabled) {
+				LogPacketServerToServer(
+					"[{:#06x}] Size [{}] {}",
+					opcode,
+					packet.Length(),
+					(is_detail_enabled ? "\n" + packet.ToString() : "")
+				);
+			}
+
 			auto cb = m_message_callbacks.find(opcode);
 			if (cb != m_message_callbacks.end()) {
 				cb->second(opcode, packet);