Add MxTrace function (#1054)

CMakeLists.txt

@@ -220,6 +220,7 @@ add_library(omni STATIC
   LEGO1/omni/src/common/mxatom.cpp
   LEGO1/omni/src/common/mxcompositepresenter.cpp
   LEGO1/omni/src/common/mxcore.cpp
+  LEGO1/omni/src/common/mxdebug.cpp
   LEGO1/omni/src/common/mxmediamanager.cpp
   LEGO1/omni/src/common/mxmediapresenter.cpp
   LEGO1/omni/src/common/mxmisc.cpp

LEGO1/lego/legoomni/src/input/legoinputmanager.cpp

@@ -8,6 +8,7 @@
 #include "legoworld.h"
 #include "misc.h"
 #include "mxautolock.h"
+#include "mxdebug.h"
 #include "roi/legoroi.h"
 
 DECOMP_SIZE_ASSERT(LegoInputManager, 0x338)
@@ -111,17 +112,19 @@ void LegoInputManager::Destroy()
 }
 
 // FUNCTION: LEGO1 0x1005c030
+// FUNCTION: BETA10 0x10088f6e
 void LegoInputManager::CreateAndAcquireKeyboard(HWND p_hwnd)
 {
 	HINSTANCE hinstance = (HINSTANCE) GetWindowLong(p_hwnd, GWL_HINSTANCE);
-	HRESULT hresult = DirectInputCreate(hinstance, 0x500, &m_directInput, NULL); // 0x500 for DX5
 
-	if (hresult == DI_OK) {
+	// 0x500 for DX5
-		HRESULT createdeviceresult = m_directInput->CreateDevice(GUID_SysKeyboard, &m_directInputDevice, NULL);
+	if (DirectInputCreate(hinstance, 0x500, &m_directInput, NULL) == DI_OK) {
-		if (createdeviceresult == DI_OK) {
+		if (m_directInput->CreateDevice(GUID_SysKeyboard, &m_directInputDevice, NULL) == DI_OK) {
 			m_directInputDevice->SetCooperativeLevel(p_hwnd, DISCL_NONEXCLUSIVE | DISCL_FOREGROUND);
 			m_directInputDevice->SetDataFormat(&c_dfDIKeyboard);
-			m_directInputDevice->Acquire();
+			if (m_directInputDevice->Acquire()) {
+				MxTrace("Can't acquire the keyboard!\n");
+			}
 		}
 	}
 }

LEGO1/omni/include/mxdebug.h

@@ -0,0 +1,32 @@
+#ifndef MXDEBUG_H
+#define MXDEBUG_H
+
+#include "compat.h"
+
+#ifdef _DEBUG
+
+// In debug mode, replace the macro with the function call.
+#define MxTrace _MxTrace
+
+void _MxTrace(const char* format, ...);
+int DebugHeapState();
+
+#else
+
+// If not debug, MxTrace is a no-op.
+
+#ifdef COMPAT_MODE
+
+// Use variadic args for macro (C99)
+#define MxTrace(...)
+
+#else
+
+// MSVC 4.20 does not have variadic args for macros
+#define MxTrace(args)
+
+#endif // COMPAT_MODE
+
+#endif // _DEBUG
+
+#endif // MXDEBUG_H

LEGO1/omni/include/mxdssubscriber.h

@@ -34,7 +34,10 @@ public:
 	MxStreamChunk* PeekData();
 	void FreeDataChunk(MxStreamChunk* p_chunk);
 
+	// FUNCTION: BETA10 0x101354f0
 	inline MxU32 GetObjectId() { return m_objectId; }
+
+	// FUNCTION: BETA10 0x10135510
 	inline MxS16 GetUnknown48() { return m_unk0x48; }
 
 private:

LEGO1/omni/include/mxmemorypool.h

@@ -3,6 +3,7 @@
 
 #include "decomp.h"
 #include "mxbitset.h"
+#include "mxdebug.h"
 #include "mxtypes.h"
 
 #include <assert.h>
@@ -49,11 +50,7 @@ MxU8* MxMemoryPool<BS, NB>::Get()
 		if (!m_blockRef[i]) {
 			m_blockRef[i].Flip();
 
-#ifdef _DEBUG
+			MxTrace("Get> %d pool: busy %d blocks\n", m_blockSize, m_blockRef.Count());
-			// TODO: This is actually some debug print function, but
-			// we just need any func with variatic args to eliminate diff noise.
-			printf("Get> %d pool: busy %d blocks\n", m_blockSize, m_blockRef.Count());
-#endif
 
 			return &m_pool[i * m_blockSize * 1024];
 		}
@@ -78,9 +75,7 @@ void MxMemoryPool<BS, NB>::Release(MxU8* p_buf)
 		m_blockRef[i].Flip();
 	}
 
-#ifdef _DEBUG
+	MxTrace("Release> %d pool: busy %d blocks\n", m_blockSize, m_blockRef.Count());
-	printf("Release> %d pool: busy %d blocks\n", m_blockSize, m_blockRef.Count());
-#endif
 }
 
 #endif // MXMEMORYPOOL_H

LEGO1/omni/include/mxstreamcontroller.h

@@ -47,7 +47,7 @@ public:
 	MxResult FUN_100c1a00(MxDSAction* p_action, MxU32 p_offset);
 	MxPresenter* FUN_100c1e70(MxDSAction& p_action);
 	MxResult FUN_100c1f00(MxDSAction* p_action);
-	MxBool FUN_100c20d0(MxDSObject& p_obj);
+	MxBool IsStoped(MxDSObject* p_obj);
 	MxResult InsertActionToList54(MxDSAction* p_action);
 	MxNextActionDataStart* FindNextActionDataStartFromStreamingAction(MxDSStreamingAction* p_action);
 

LEGO1/omni/include/mxstreamer.h

@@ -35,6 +35,7 @@ private:
 };
 
 // VTABLE: LEGO1 0x100dc710
+// VTABLE: BETA10 0x101c2378
 // SIZE 0x2c
 class MxStreamer : public MxCore {
 public:
@@ -115,6 +116,7 @@ private:
 
 // clang-format off
 // TEMPLATE: LEGO1 0x100b9090
+// TEMPLATE: BETA10 0x10146720
 // list<MxStreamController *,allocator<MxStreamController *> >::~list<MxStreamController *,allocator<MxStreamController *> >
 // clang-format on
 

LEGO1/omni/src/action/mxdsmediaaction.cpp

@@ -1,5 +1,6 @@
 #include "mxdsmediaaction.h"
 
+#include "mxdebug.h"
 #include "mxutilities.h"
 
 DECOMP_SIZE_ASSERT(MxDSMediaAction, 0xb8)
@@ -86,6 +87,8 @@ void MxDSMediaAction::CopyMediaSrcPath(const char* p_mediaSrcPath)
 		if (m_mediaSrcPath) {
 			strcpy(m_mediaSrcPath, p_mediaSrcPath);
 		}
+
+		MxTrace("MxDSMediaAction: name allocation failed: %s.\n", p_mediaSrcPath);
 	}
 	else {
 		m_mediaSrcPath = NULL;

LEGO1/omni/src/common/mxdebug.cpp

@@ -0,0 +1,30 @@
+#include "mxdebug.h"
+
+#ifdef _DEBUG
+
+// Debug-only wrapper for OutputDebugString to support variadic arguments.
+// Identical functions at BETA10 0x100ec9fe and 0x101741b5 are more limited in scope.
+// This is the most widely used version.
+
+#include <stdio.h>
+#include <windows.h>
+
+// FUNCTION: BETA10 0x10124cb9
+int DebugHeapState()
+{
+	return 0;
+}
+
+// FUNCTION: BETA10 0x10124cdd
+void _MxTrace(const char* format, ...)
+{
+	va_list args;
+	char buffer[256];
+
+	va_start(args, format);
+	_vsnprintf(buffer, 256, format, args);
+	OutputDebugString(buffer);
+	va_end(args);
+}
+
+#endif

LEGO1/omni/src/stream/mxstreamcontroller.cpp

@@ -1,6 +1,7 @@
 #include "mxstreamcontroller.h"
 
 #include "mxautolock.h"
+#include "mxdebug.h"
 #include "mxdsmultiaction.h"
 #include "mxdsstreamingaction.h"
 #include "mxmisc.h"
@@ -41,8 +42,10 @@ MxStreamController::MxStreamController()
 }
 
 // FUNCTION: LEGO1 0x100c1290
+// FUNCTION: BETA10 0x1014e354
 MxStreamController::~MxStreamController()
 {
+	MxTrace("Destroy %s controller.\n", m_atom.GetInternal());
 	AUTOLOCK(m_criticalSection);
 
 	MxDSSubscriber* subscriber;
@@ -313,19 +316,27 @@ MxNextActionDataStart* MxStreamController::FindNextActionDataStartFromStreamingA
 }
 
 // FUNCTION: LEGO1 0x100c20d0
-MxBool MxStreamController::FUN_100c20d0(MxDSObject& p_obj)
+// FUNCTION: BETA10 0x1014f3b5
+MxBool MxStreamController::IsStoped(MxDSObject* p_obj)
 {
-	if (m_subscriberList.Find(&p_obj)) {
+	MxDSSubscriber* subscriber = m_subscriberList.Find(p_obj);
+
+	if (subscriber) {
+		MxTrace(
+			"Subscriber for action (stream %d, instance %d) from %s is still here.\n",
+			subscriber->GetObjectId(),
+			subscriber->GetUnknown48(),
+			GetAtom().GetInternal()
+		);
 		return FALSE;
 	}
 
-	if (p_obj.IsA("MxDSMultiAction")) {
+	if (p_obj->IsA("MxDSMultiAction")) {
-		MxDSActionList* actions = ((MxDSMultiAction&) p_obj).GetActionList();
+		MxDSActionListCursor cursor(((MxDSMultiAction*) p_obj)->GetActionList());
-		MxDSActionListCursor cursor(actions);
 		MxDSAction* action;
 
 		while (cursor.Next(action)) {
-			if (!FUN_100c20d0(*action)) {
+			if (!IsStoped(action)) {
 				return FALSE;
 			}
 		}

LEGO1/omni/src/stream/mxstreamer.cpp

@@ -1,11 +1,13 @@
 #include "mxstreamer.h"
 
+#include "mxdebug.h"
 #include "mxdiskstreamcontroller.h"
 #include "mxmisc.h"
 #include "mxnotificationmanager.h"
 #include "mxramstreamcontroller.h"
 
 #include <algorithm>
+#include <assert.h>
 
 DECOMP_SIZE_ASSERT(MxStreamer, 0x2c);
 DECOMP_SIZE_ASSERT(MxMemoryPool64, 0x0c);
@@ -14,12 +16,14 @@ DECOMP_SIZE_ASSERT(MxBitset<22>, 0x04);
 DECOMP_SIZE_ASSERT(MxBitset<2>, 0x04);
 
 // FUNCTION: LEGO1 0x100b8f00
+// FUNCTION: BETA10 0x10145150
 MxStreamer::MxStreamer()
 {
 	NotificationManager()->Register(this);
 }
 
 // FUNCTION: LEGO1 0x100b9190
+// FUNCTION: BETA10 0x10145220
 MxResult MxStreamer::Create()
 {
 	if (m_pool64.Allocate() || m_pool128.Allocate()) {
@@ -30,42 +34,66 @@ MxResult MxStreamer::Create()
 }
 
 // FUNCTION: LEGO1 0x100b91d0
+// FUNCTION: BETA10 0x10145268
 MxStreamer::~MxStreamer()
 {
 	while (!m_openStreams.empty()) {
-		MxStreamController* c = m_openStreams.front();
+		MxStreamController* controller = m_openStreams.front();
+
+#ifdef COMPAT_MODE
+		{
+			MxDSAction action;
+			assert(controller->IsStoped(&action));
+		}
+#else
+		assert(controller->IsStoped(&MxDSAction()));
+#endif
+
 		m_openStreams.pop_front();
-		delete c;
+		delete controller;
 	}
 
 	NotificationManager()->Unregister(this);
 }
 
 // FUNCTION: LEGO1 0x100b92c0
+// FUNCTION: BETA10 0x1014542d
 MxStreamController* MxStreamer::Open(const char* p_name, MxU16 p_lookupType)
 {
+	MxTrace("Open %s as %s controller\n", p_name, !p_lookupType ? "disk" : "RAM");
+	MxTrace("Heap before: %d\n", DebugHeapState());
+
 	MxStreamController* stream = NULL;
 
-	if (!GetOpenStream(p_name)) {
+	if (GetOpenStream(p_name)) {
-		switch (p_lookupType) {
+		goto done;
-		case e_diskStream:
-			stream = new MxDiskStreamController();
-			break;
-		case e_RAMStream:
-			stream = new MxRAMStreamController();
-			break;
-		}
-
-		if (stream && (stream->Open(p_name) != SUCCESS || AddStreamControllerToOpenList(stream) != SUCCESS)) {
-			delete stream;
-			stream = NULL;
-		}
 	}
 
+	switch (p_lookupType) {
+	case e_diskStream:
+		stream = new MxDiskStreamController();
+		break;
+	case e_RAMStream:
+		stream = new MxRAMStreamController();
+		break;
+	}
+
+	if (stream == NULL) {
+		goto done;
+	}
+
+	if (stream->Open(p_name) != SUCCESS || AddStreamControllerToOpenList(stream) != SUCCESS) {
+		delete stream;
+		stream = NULL;
+	}
+
+done:
+	MxTrace("Heap after: %d\n", DebugHeapState());
 	return stream;
 }
 
 // FUNCTION: LEGO1 0x100b9570
+// FUNCTION: BETA10 0x10145638
 MxLong MxStreamer::Close(const char* p_name)
 {
 	MxDSAction ds;
@@ -77,7 +105,7 @@ MxLong MxStreamer::Close(const char* p_name)
 		if (!p_name || !strcmp(p_name, c->GetAtom().GetInternal())) {
 			m_openStreams.erase(it);
 
-			if (c->FUN_100c20d0(ds)) {
+			if (c->IsStoped(&ds)) {
 				delete c;
 			}
 			else {
@@ -98,6 +126,7 @@ MxNotificationParam* MxStreamerNotification::Clone() const
 }
 
 // FUNCTION: LEGO1 0x100b9870
+// FUNCTION: BETA10 0x1014584b
 MxStreamController* MxStreamer::GetOpenStream(const char* p_name)
 {
 	for (list<MxStreamController*>::iterator it = m_openStreams.begin(); it != m_openStreams.end(); it++) {
@@ -178,7 +207,7 @@ MxBool MxStreamer::FUN_100b9b30(MxDSObject& p_dsObject)
 {
 	MxStreamController* controller = GetOpenStream(p_dsObject.GetAtomId().GetInternal());
 	if (controller) {
-		return controller->FUN_100c20d0(p_dsObject);
+		return controller->IsStoped(&p_dsObject);
 	}
 	return TRUE;
 }
@@ -193,7 +222,7 @@ MxLong MxStreamer::Notify(MxParam& p_param)
 
 		MxStreamController* c = static_cast<MxStreamerNotification&>(p_param).GetController();
 
-		if (c->FUN_100c20d0(ds)) {
+		if (c->IsStoped(&ds)) {
 			delete c;
 		}
 		else {