feat: sar_trace_compare, trace logging system

Co-authored by: mlugg <mlugg@mlugg.co.uk>

Author: Krzyhau

docs/cvars.md

@@ -617,6 +617,7 @@
 |sar_trace_bbox_use_hover|0|Move trace bbox to hovered trace point tick on given trace.|
 |sar_trace_clear|cmd|sar_trace_clear \<name> - Clear player trace with a given name|
 |sar_trace_clear_all|cmd|sar_trace_clear_all - Clear all the traces|
+|sar_trace_compare|cmd|sar_trace_compare \<trace 1> \<trace 2> - compares two given recorded traces and shows where differences occurred.|
 |sar_trace_draw|0|Display the recorded player trace. Requires cheats|
 |sar_trace_draw_hover|1|Display information about the trace at the hovered tick.|
 |sar_trace_draw_speed_deltas|0|Display the speed deltas. Requires sar_trace_draw|

src/Features/PlayerTrace.cpp

@@ -164,6 +164,9 @@ void PlayerTrace::AddPoint(std::string trace_name, void *player, int slot, bool
 		camera->GetEyePos<true>(slot, eyepos, angles);
 	}
 
+	this->EmitLog(Utils::ssprintf("ProcessMovement(%d)", session->GetTick()).c_str());
+	this->EmitLog(Utils::ssprintf("player @ (%.6f,%.6f,%.6f)", pos.x, pos.y, pos.z).c_str());
+
 	HitboxList hitboxes = ConstructHitboxList(pos);
 
 	trace.positions[slot].push_back(pos);
@@ -178,6 +181,9 @@ void PlayerTrace::AddPoint(std::string trace_name, void *player, int slot, bool
 	if (slot == 0) {
 		PortalLocations portals = ConstructPortalLocations();
 		trace.portals.push_back(portals);
+
+		VphysLocationList vphysLocations = ConstructVphysLocationList();
+		trace.vphysLocations.push_back(vphysLocations);
 	}
 }
 Trace *PlayerTrace::GetTrace(std::string trace_name) {
@@ -649,6 +655,49 @@ HitboxList PlayerTrace::ConstructHitboxList(Vector center) const {
 	return list;
 }
 
+VphysLocationList PlayerTrace::ConstructVphysLocationList() const {
+	VphysLocationList locationList;
+
+	for (int i = 0; i < Offsets::NUM_ENT_ENTRIES; ++i) {
+		void *ent = server->m_EntPtrArray[i].m_pEntity;
+		if (!ent) continue;
+		auto className = server->GetEntityClassName(ent);
+
+		const char *allowedClassNames[] = {
+			"player",
+			"prop_physics",
+			"func_physbox",
+			"prop_weighted_cube",
+			"prop_monster_box",
+			"npc_security_camera",
+			"npc_portal_turret_floor",
+			"func_brush",
+			"prop_dynamic",
+		};
+
+		int size = sizeof(allowedClassNames) / sizeof(allowedClassNames[0]);
+		bool isAllowedEntity = false;
+
+		for (int i = 0; i < size; i++) {
+			if (strcmp(className, allowedClassNames[i]) == 0) {
+				isAllowedEntity = true;
+				break;
+			}
+		}
+		if (!isAllowedEntity) continue;
+
+		ICollideable *coll = &SE(ent)->collision();
+
+		locationList.locations[i] = {
+			std::string(className),
+			coll->GetCollisionOrigin(),
+			coll->GetCollisionAngles()
+		};
+	}
+
+	return locationList;
+}
+
 PortalLocations PlayerTrace::ConstructPortalLocations() const {
 	if (!sar_trace_portal_record.GetBool()) return PortalLocations{};
 
@@ -1020,3 +1069,161 @@ CON_COMMAND(sar_trace_export, "sar_trace_export <filename> [trace name] - Export
 
 	console->Print("Trace successfully exported to '%s'!\n", filename.c_str());
 }
+
+CON_COMMAND(sar_trace_compare, "sar_trace_compare <trace 1> <trace 2> - compares two given recorded traces and shows where differences occurred.\n") {
+	if (args.ArgC() != 3)
+		return console->Print(sar_trace_compare.ThisPtr()->m_pszHelpString);
+
+	auto trace1Name = args[1];
+	auto trace2Name = args[2];
+
+	auto trace1 = playerTrace->GetTrace(trace1Name);
+	auto trace2 = playerTrace->GetTrace(trace2Name);
+	if (trace1 == nullptr || trace2 == nullptr) {
+		return console->Print("Trace with name \"%s\" does not exist.\n", trace1 == nullptr ? trace1Name : trace2Name);
+	}
+
+	console->Print("Comparing traces \"%s\" and \"%s\":\n", trace1Name, trace2Name);
+
+	const auto goodColor = Color(110, 247, 76);
+	const auto badColor = Color(255, 100, 100);
+
+	auto startTick1 = tickInternalToUser(0, *trace1);
+	auto startTick2 = tickInternalToUser(0, *trace2);
+	if (startTick1 != startTick2) {
+		console->ColorMsg(badColor, "Mismatch in starting tick: %d <-> %d\n", startTick1, startTick2);
+		console->ColorMsg(badColor, "Comparison cancelled.\n");
+		return;
+	}
+
+	auto vphysList1 = trace1->vphysLocations;
+	auto vphysList2 = trace2->vphysLocations;
+	if (vphysList1.size() != vphysList2.size()) {
+		console->ColorMsg(badColor, "Mismatch in trace length: %d <-> %d\n", vphysList1.size(), vphysList2.size());
+		return;
+	}
+
+	int mismatchCount = 0;
+
+	auto maxLength = std::min(vphysList1.size(), vphysList2.size());
+	for (size_t i = 0; i < maxLength; ++i) {
+
+		auto userTick = tickInternalToUser(i, *trace1);
+
+		auto locationsList1 = vphysList1[i].locations;
+		auto locationsList2 = vphysList2[i].locations;
+
+		for (int ent_index = 0; ent_index < Offsets::NUM_ENT_ENTRIES; ++ent_index) {
+			auto location1Entry = locationsList1.find(ent_index);
+			auto location2Entry = locationsList2.find(ent_index);
+
+			auto location1Valid = (location1Entry != locationsList1.end());
+			auto location2Valid = (location2Entry != locationsList2.end());
+
+			if (!location1Valid && !location2Valid) {
+				continue;
+			} else if (!location1Valid || !location2Valid) {
+				auto entityName = location1Valid ? (*location1Entry).second.className.c_str() : (*location2Entry).second.className.c_str();
+				console->ColorMsg(badColor, "Tick %d Slot %d: entity %s exists in trace \"%s\", but not in trace \"%s\"\n",
+					userTick, ent_index, entityName, location1Valid ? trace1Name : trace2Name, location2Valid ? trace1Name : trace2Name);
+				mismatchCount++;
+				continue;
+			} 
+
+			bool mismatch = false;
+
+			auto location1 = (*location1Entry).second;
+			auto location2 = (*location2Entry).second;
+
+			if (location1.className != location2.className) {
+				console->ColorMsg(badColor, "Tick %d Slot %d: mismatch in entity types:\n  %s <-> %s\n",
+					userTick, ent_index, location1.className.c_str(), location2.className.c_str());
+				mismatch = true;
+			}
+
+			if (location1.pos != location2.pos) {
+				console->ColorMsg(badColor, "Tick %d Slot %d: mismatch in position of entity %s:\n  (%.9f %.9f %.9f) <-> (%.9f %.9f %.9f)\n",
+					userTick, ent_index, location1.className.c_str(), 
+					location1.pos.x, location1.pos.y, location1.pos.z, 
+					location2.pos.x, location2.pos.y, location2.pos.z
+				);
+				mismatch = true;
+			}
+
+			if (QAngleToVector(location1.ang) != QAngleToVector(location2.ang)) {
+				console->ColorMsg(badColor, "Tick %d Slot %d: mismatch in rotation of entity %s:\n  (%.9f %.9f %.9f) <-> (%.9f %.9f %.9f)\n",
+					userTick, ent_index, location1.className.c_str(), 
+					location1.ang.x, location1.ang.y, location1.ang.z, 
+					location2.ang.x, location2.ang.y, location2.ang.z
+				);
+				mismatch = true;
+			}
+
+			if (mismatch) {
+				mismatchCount++;
+			}
+		}
+	}
+	console->Print("Checked %d ticks, found mismatches: %d.\n", maxLength, mismatchCount);
+
+	if (mismatchCount > 0) {
+		console->Print("Mismatch detected: dumping trace logs.\n");
+		std::string dump_1_name = Utils::ssprintf("%s_dump.txt", trace1Name);
+		FILE *f1 = fopen(dump_1_name.c_str(), "w");
+		if (f1) {
+			for (auto line : trace1->log_lines) {
+				fprintf(f1, "%s\n", line.c_str());
+			}
+			fclose(f1);
+			console->Print("Trace '%s' log dumped to '%s'\n", trace1Name, dump_1_name.c_str());
+		}
+		std::string dump_2_name = Utils::ssprintf("%s_dump.txt", trace2Name);
+		FILE *f2 = fopen(dump_2_name.c_str(), "w");
+		if (f2) {
+			for (auto line : trace2->log_lines) {
+				fprintf(f2, "%s\n", line.c_str());
+			}
+			fclose(f2);
+			console->Print("Trace '%s' log dumped to '%s'\n", trace2Name, dump_2_name.c_str());
+		}
+	}
+}
+
+void PlayerTrace::EnterLogScope(const char *name) {
+	if (!playerTrace->ShouldRecord()) return;
+	auto trace = this->GetTrace(sar_trace_record.GetString());
+	if (!trace) return;
+	std::string line = "";
+	for (unsigned i = 0; i < trace->log_scope_stack.size(); ++i) {
+		line += "  ";
+	}
+	line += Utils::ssprintf("[ENTER %s]", name);
+	trace->log_lines.push_back(line);
+	trace->log_scope_stack.push_back({name});
+}
+
+void PlayerTrace::ExitLogScope() {
+	if (!playerTrace->ShouldRecord()) return;
+	auto trace = this->GetTrace(sar_trace_record.GetString());
+	if (!trace) return;
+	std::string line = "";
+	if (trace->log_scope_stack.size() == 0) return; // trace probably stopped/started halfway through a log scope
+	for (unsigned i = 0; i < trace->log_scope_stack.size() - 1; ++i) {
+		line += "  ";
+	}
+	line += Utils::ssprintf("[EXIT %s]", trace->log_scope_stack.back().c_str());
+	trace->log_lines.push_back(line);
+	trace->log_scope_stack.pop_back();
+}
+
+void PlayerTrace::EmitLog(const char *msg) {
+	if (!playerTrace->ShouldRecord()) return;
+	auto trace = this->GetTrace(sar_trace_record.GetString());
+	if (!trace) return;
+	std::string line = "";
+	for (unsigned i = 0; i < trace->log_scope_stack.size(); ++i) {
+		line += "  ";
+	}
+	line += msg;
+	trace->log_lines.push_back(line);
+}

src/Features/PlayerTrace.hpp

@@ -22,6 +22,15 @@ struct HitboxList {
 	std::vector<ObbBox> obb;
 };
 
+struct VphysLocationList {
+	struct Location {
+		std::string className;
+		Vector pos;
+		QAngle ang;
+	};
+	std::map<int, Location> locations;
+};
+
 struct PortalLocations {
 	struct PortalLocation {
 		Vector pos;
@@ -49,6 +58,10 @@ struct Trace {
 	// Only have one of those, store all the portals in the map
 	// indiscriminately of player (also ones placed by pedestals etc)
 	std::vector<PortalLocations> portals;
+	std::vector<VphysLocationList> vphysLocations;
+
+	std::vector<std::string> log_scope_stack;
+	std::vector<std::string> log_lines;
 	bool draw = true;
 };
 
@@ -87,6 +100,8 @@ class PlayerTrace : public Feature {
 	void TeleportAt(std::string trace_name, int slot, int tick, bool eye);
 	// Construct a list of the hitboxes of all entities near a point
 	HitboxList ConstructHitboxList(Vector center) const;
+	// Construct a list of locations of all dynamic entities for verification purposes
+	VphysLocationList ConstructVphysLocationList() const;
 	// Construct a list of all portals in the map
 	PortalLocations ConstructPortalLocations() const;
 	// Draw info about all traces to a HUD context
@@ -97,6 +112,11 @@ class PlayerTrace : public Feature {
 	void CheckTraceChanged();
 	// Get the current trace bbox tick for TAS stuff, or -1 if there isn't one
 	int GetTasTraceTick();
+
+	// Returns an identifier for the scope which should be passed to ExitLogScope
+	void EnterLogScope(const char *name);
+	void ExitLogScope();
+	void EmitLog(const char *msg);
 };
 
 extern PlayerTrace *playerTrace;