[Debgging] Add read/write logger

- You can use the two comparison files (iw4_reads.log & zb_writes.log) to compare the two for differences
- Move the hook in QuickPatches around to change the asset that you're logging

src/Components/Modules/AssetInterfaces/IGfxWorld.cpp

@@ -115,6 +115,7 @@ namespace Assets
 		AssertSize(Game::GfxWorldDpvsPlanes, 16);
 
 		Utils::Stream* buffer = builder->getBuffer();
+        SAVE_LOG_ENTER("GfxWorldDpvsPlanes");
 
 		if (asset->planes)
 		{
@@ -151,11 +152,13 @@ namespace Assets
 		}
 
 		buffer->popBlock();
+        SAVE_LOG_EXIT();
 	}
 
 	void IGfxWorld::saveGfxWorldDraw(Game::GfxWorldDraw* asset, Game::GfxWorldDraw* dest, Components::ZoneBuilder::Zone* builder)
 	{
 		AssertSize(Game::GfxWorldDraw, 72);
+        SAVE_LOG_ENTER("GfxWorldDraw");
 
 		Utils::Stream* buffer = builder->getBuffer();
 
@@ -284,6 +287,8 @@ namespace Assets
 			buffer->saveArray(asset->indices, asset->indexCount);
 			Utils::Stream::ClearPointer(&dest->indices);
 		}
+
+        SAVE_LOG_EXIT();
 	}
 
 	void IGfxWorld::saveGfxLightGrid(Game::GfxLightGrid* asset, Game::GfxLightGrid* dest, Components::ZoneBuilder::Zone* builder)
@@ -291,6 +296,7 @@ namespace Assets
 		AssertSize(Game::GfxLightGrid, 56);
 
 		Utils::Stream* buffer = builder->getBuffer();
+        SAVE_LOG_ENTER("GfxLightGrid");
 
 		if (asset->rowDataStart)
 		{
@@ -323,12 +329,15 @@ namespace Assets
 			buffer->saveArray(asset->colors, asset->colorCount);
 			Utils::Stream::ClearPointer(&dest->colors);
 		}
+        SAVE_LOG_EXIT();
 	}
 
 	void IGfxWorld::savesunflare_t(Game::sunflare_t* asset, Game::sunflare_t* dest, Components::ZoneBuilder::Zone* builder)
 	{
 		AssertSize(Game::sunflare_t, 96);
 
+        SAVE_LOG_ENTER("sunflare_t");
+
 		if (asset->spriteMaterial)
 		{
 			dest->spriteMaterial = builder->requireAsset(Game::XAssetType::ASSET_TYPE_MATERIAL, asset->spriteMaterial->name).material;
@@ -338,6 +347,8 @@ namespace Assets
 		{
 			dest->flareMaterial = builder->requireAsset(Game::XAssetType::ASSET_TYPE_MATERIAL, asset->flareMaterial->name).material;
 		}
+        
+        SAVE_LOG_EXIT();
 	}
 
 	void IGfxWorld::saveGfxWorldDpvsStatic(Game::GfxWorld* world, Game::GfxWorldDpvsStatic* asset, Game::GfxWorldDpvsStatic* dest, int /*planeCount*/, Components::ZoneBuilder::Zone* builder)
@@ -345,6 +356,7 @@ namespace Assets
 		AssertSize(Game::GfxWorldDpvsStatic, 108);
 
 		Utils::Stream* buffer = builder->getBuffer();
+        SAVE_LOG_ENTER("GfxWorldDpvsStatic");
 
 		buffer->pushBlock(Game::XFILE_BLOCK_RUNTIME);
 
@@ -458,6 +470,7 @@ namespace Assets
 		}
 
 		buffer->popBlock();
+        SAVE_LOG_EXIT();
 	}
 
 	void IGfxWorld::saveGfxWorldDpvsDynamic(Game::GfxWorldDpvsDynamic* asset, Game::GfxWorldDpvsDynamic* dest, Components::ZoneBuilder::Zone* builder)
@@ -465,6 +478,7 @@ namespace Assets
 		AssertSize(Game::GfxWorldDpvsDynamic, 48);
 
 		Utils::Stream* buffer = builder->getBuffer();
+        SAVE_LOG_ENTER("GfxWorldDpvsDynamic");
 
 		buffer->pushBlock(Game::XFILE_BLOCK_RUNTIME);
 
@@ -497,6 +511,7 @@ namespace Assets
 		}
 
 		buffer->popBlock();
+        SAVE_LOG_EXIT();
 	}
 
 	void IGfxWorld::save(Game::XAssetHeader header, Components::ZoneBuilder::Zone* builder)
@@ -504,6 +519,7 @@ namespace Assets
 		AssertSize(Game::GfxWorld, 0x274);
 
 		Utils::Stream* buffer = builder->getBuffer();
+        SAVE_LOG_ENTER("GfxWorld");
 		Game::GfxWorld* asset = header.gfxWorld;
 		Game::GfxWorld* dest = buffer->dest<Game::GfxWorld>();
 		buffer->save(asset);
@@ -860,5 +876,6 @@ namespace Assets
 		}
 
 		buffer->popBlock();
+        SAVE_LOG_EXIT();
 	}
 }

src/Components/Modules/QuickPatch.cpp

@@ -141,6 +141,54 @@ namespace Components
 		Game::CL_SelectStringTableEntryInDvar_f();
 	}
 
+#ifdef DEBUG
+
+    FILE* QuickPatch::readLog = nullptr;
+    Utils::Hook QuickPatch::beginLoggingHook;
+    int* QuickPatch::g_streamPos = (int*)0x16E5554;
+
+    void QuickPatch::logReads(bool /*flush*/)
+    {
+        fopen_s(&readLog, "userraw/logs/iw4_reads.log", "w");
+
+        // call the original load func
+        __asm
+        {
+            push 1
+            call beginLoggingHook.original
+            add esp, 4
+        }
+
+        if(readLog)
+        {
+            fclose(readLog);
+            readLog = nullptr;
+        }
+    }
+
+    void QuickPatch::logXAssetRead(int len)
+    {
+        *g_streamPos = *g_streamPos + len;
+        if(!readLog) return;
+        fprintf(readLog, "%d\n", len);
+        fflush(readLog);
+        // manually flush file because otherwie when ZB crashes it wont get flushed
+    }
+
+    void QuickPatch::logXAssetVirtualRead(int len)
+    {
+        *g_streamPos = *g_streamPos + len;
+        if(!readLog) return;
+        fprintf(readLog, "(%d)\n", len);
+        fflush(readLog);
+        // manually flush file because otherwie when ZB crashes it wont get flushed
+    }
+
+
+#endif
+
+
+
 	QuickPatch::QuickPatch()
 	{
 		// protocol version (workaround for hacks)
@@ -433,6 +481,12 @@ namespace Components
 				Game::Con_DrawMiniConsole(0, 2, 4, (Game::CL_IsCgameInitialized() ? 1.0f : 0.4f));
 			}
 		});
+
+        beginLoggingHook.initialize(0x4BCB62, QuickPatch::logReads, HOOK_CALL); // currently set to Load_GfxWorld
+        beginLoggingHook.install()->quick();
+        Utils::Hook(0x470E75, QuickPatch::logXAssetRead, HOOK_CALL).install()->quick();
+        Utils::Hook(0x4E0E0B, QuickPatch::logXAssetRead, HOOK_CALL).install()->quick();
+        Utils::Hook(0x470E5A, QuickPatch::logXAssetVirtualRead, HOOK_CALL).install()->quick();
 #endif
 	}
 

src/Components/Modules/QuickPatch.hpp

@@ -31,5 +31,14 @@ namespace Components
 		static int MsgReadBitsCompressCheckSV(const char *from, char *to, int size);
 		static int MsgReadBitsCompressCheckCL(const char *from, char *to, int size);
 		static void CL_HandleRelayPacketCheck(Game::msg_t* msg, int client);
+
+#ifdef DEBUG
+        static FILE* readLog;
+        static Utils::Hook beginLoggingHook;
+        static int* g_streamPos;
+        static void logReads(bool flush);
+        static void logXAssetRead(int len);
+        static void logXAssetVirtualRead(int len);
+#endif
 	};
 }

src/STDInclude.hpp

@@ -148,6 +148,17 @@ using namespace std::literals;
 #define AssertSize(x, size) static_assert(sizeof(x) == size, STRINGIZE(x) " structure has an invalid size.")
 #define AssertOffset(x, y, offset) static_assert(offsetof(x, y) == offset, STRINGIZE(x) "::" STRINGIZE(y) " is not at the right offset.")
 
+// write logs for ZoneBuilder
+#ifndef DEBUG
+    #define SAVE_LOG_ENTER(x)
+    #define SAVE_LOG_EXIT()
+    #define SAVE_LOG_WRITE(size)
+#else
+    #define SAVE_LOG_ENTER(x) builder->getBuffer()->enterStruct(x)
+    #define SAVE_LOG_EXIT() builder->getBuffer()->leaveStruct()
+    #define SAVE_LOG_WRITE(size) this->logWrite(size)
+#endif
+
 // Resource stuff
 #ifdef APSTUDIO_INVOKED
 #ifndef APSTUDIO_READONLY_SYMBOLS

src/Utils/Stream.cpp

@@ -62,6 +62,14 @@ namespace Utils
 	Stream::Stream() : criticalSectionState(0)
 	{
 		memset(this->blockSize, 0, sizeof(this->blockSize));
+#ifdef DEBUG
+
+        if(this->writeLog) return;
+        if(fopen_s(&this->writeLog, "userraw/logs/zb_writes.log", "w"))
+        {
+            Components::Logger::Print("WARNING: Couldn't open write log. Writes from ZoneBuilder will not be logged.\n");
+        }
+#endif
 	}
 
 	Stream::Stream(size_t size) : Stream()
@@ -77,6 +85,13 @@ namespace Utils
 		{
 			MessageBoxA(0, Utils::String::VA("Invalid critical section state '%i' for stream destruction!", this->criticalSectionState), "WARNING", MB_ICONEXCLAMATION);
 		}
+
+#ifdef DEBUG
+        if(this->writeLog)
+        {
+            fclose(this->writeLog);
+        }
+#endif
 	};
 
 	size_t Stream::length()
@@ -109,6 +124,9 @@ namespace Utils
 
 		this->buffer.append(static_cast<const char*>(_str), size * count);
 
+        // log the write for zonebuilder debugging
+        SAVE_LOG_WRITE(size * count);
+
 		if (this->data() != data && this->isCriticalSection())
 		{
 			MessageBoxA(0, "Stream reallocation during critical operations not permitted!\nPlease increase the initial memory size or reallocate memory during non-critical sections!", "ERROR", MB_ICONERROR);
@@ -303,4 +321,38 @@ namespace Utils
 
 		return (this->criticalSectionState != 0);
 	}
+
+#ifdef DEBUG
+
+    FILE* Stream::writeLog = nullptr;
+    int Stream::structLevel = 0;
+
+    void Stream::enterStruct(const char* structName)
+    {
+        if(!this->writeLog) return;
+        fprintf(this->writeLog, "%*s%s\n", this->structLevel++, "", structName);
+    }
+
+    void Stream::leaveStruct()
+    {
+        if(!this->writeLog) return;
+        this->structLevel--;
+
+        if(this->structLevel < 0) {
+            Components::Logger::Print("Stream::exitStruct underflow! All following writes will not be logged!\n");
+            fclose(this->writeLog);
+            this->writeLog = nullptr;
+            return;
+        }
+
+        fprintf(this->writeLog, "%*s-----\n", this->structLevel, "");
+    }
+
+    void Stream::logWrite(int writeLen)
+    {
+        if(!this->writeLog) return;
+        fprintf(this->writeLog, "%*s%d\n", this->structLevel, "", writeLen);
+    }
+
+#endif
 }

src/Utils/Stream.hpp

@@ -121,6 +121,14 @@ namespace Utils
 		void leaveCriticalSection();
 		bool isCriticalSection();
 
+        // for recording zb writes
+#ifdef DEBUG
+        static FILE* writeLog;
+        static int structLevel;
+        void enterStruct(const char* structName);
+        void leaveStruct();
+        void logWrite(int writeLen);
+#endif
 
 		// This represents packed offset in streams:
 		// - lowest 28 bits store the value/offset