Merge pull request #255 from Hoikas/keyleaks

Key Leaks/Debug Logging

Sources/Plasma/Apps/plClient/winmain.cpp

@@ -305,11 +305,6 @@ LRESULT CALLBACK WndProc(HWND hWnd, UINT message, WPARAM wParam, LPARAM lParam)
                 bool active = (LOWORD(wParam) == WA_ACTIVE || LOWORD(wParam) == WA_CLICKACTIVE);
                 bool minimized = (HIWORD(wParam) != 0);
 
-                DebugMsgF("Got WM_ACTIVATE, active=%s, minimized=%s, clicked=%s",
-                    active ? "true" : "false",
-                    minimized ? "true" : "false",
-                    (LOWORD(wParam) == WA_CLICKACTIVE) ? "true" : "false");
-
                 if (gClient && !minimized && !gClient->GetDone())
                 {
                     gClient->WindowActivate(active);
@@ -324,7 +319,6 @@ LRESULT CALLBACK WndProc(HWND hWnd, UINT message, WPARAM wParam, LPARAM lParam)
 
         // Let go of the mouse if the window is being moved.
         case WM_ENTERSIZEMOVE:
-            DebugMsgF("Got WM_ENTERSIZEMOVE%s", gClient ? "" : ", no client, ignoring");
             gDragging = true;
             if( gClient )
                 gClient->WindowActivate(false);
@@ -332,7 +326,6 @@ LRESULT CALLBACK WndProc(HWND hWnd, UINT message, WPARAM wParam, LPARAM lParam)
 
         // Redo the mouse capture if the window gets moved
         case WM_EXITSIZEMOVE:
-            DebugMsgF("Got WM_EXITSIZEMOVE%s", gClient ? "" : ", no client, ignoring");
             gDragging = false;
             if( gClient )
                 gClient->WindowActivate(true);
@@ -342,12 +335,7 @@ LRESULT CALLBACK WndProc(HWND hWnd, UINT message, WPARAM wParam, LPARAM lParam)
         // and his cool program that bumps windows out from under the taskbar)
         case WM_MOVE:
             if (!gDragging && gClient && gClient->GetInputManager())
-            {
                 gClient->GetInputManager()->Activate(true);
-                DebugMsgF("Got WM_MOVE");
-            }
-            else
-                DebugMsgF("Got WM_MOVE, but ignoring");
             break;
 
         /// Resize the window
@@ -358,7 +346,6 @@ LRESULT CALLBACK WndProc(HWND hWnd, UINT message, WPARAM wParam, LPARAM lParam)
         //  size, not when the window is minimized or restored)
         case WM_SIZING:
             {
-                DebugMsgF("Got WM_SIZING");
                 RECT r;
                 ::GetClientRect(hWnd, &r);
                 gClient->GetPipeline()->Resize(r.right - r.left, r.bottom - r.top);
@@ -369,14 +356,12 @@ LRESULT CALLBACK WndProc(HWND hWnd, UINT message, WPARAM wParam, LPARAM lParam)
             // Let go of the mouse if the window is being minimized
             if (wParam == SIZE_MINIMIZED)
             {
-                DebugMsgF("Got WM_SIZE, SIZE_MINIMIZED%s", gClient ? "" : ", but no client, ignoring");
                 if (gClient)
                     gClient->WindowActivate(false);
             }
             // Redo the mouse capture if the window gets restored
             else if (wParam == SIZE_RESTORED)
             {
-                DebugMsgF("Got WM_SIZE, SIZE_RESTORED%s", gClient ?  "" : ", but no client, ignoring");
                 if (gClient)
                     gClient->WindowActivate(true);
             }
@@ -653,32 +638,40 @@ BOOL WinInit(HINSTANCE hInst, int nCmdShow)
 //
 // For error logging
 //
-static FILE* gDebugFile=NULL;
-void DebugMessageProc(const char* msg)
+static plStatusLog* s_DebugLog = nullptr;
+static void _DebugMessageProc(const char* msg)
 {
-    OutputDebugString(msg);
-    OutputDebugString("\n");
-    if (gDebugFile != NULL)
-    {
-        fprintf(gDebugFile, "%s\n", msg);
-        fflush(gDebugFile);
-    }
+#if defined(HS_DEBUGGING) || !defined(PLASMA_EXTERNAL_RELEASE)
+    s_DebugLog->AddLine(msg, plStatusLog::kRed);
+#endif // defined(HS_DEBUGGING) || !defined(PLASMA_EXTERNAL_RELEASE)
 }
 
-void DebugMsgF(const char* format, ...)
+static void _StatusMessageProc(const char* msg)
 {
-#ifndef PLASMA_EXTERNAL_RELEASE
+#if defined(HS_DEBUGGING) || !defined(PLASMA_EXTERNAL_RELEASE)
+    s_DebugLog->AddLine(msg);
+#endif // defined(HS_DEBUGGING) || !defined(PLASMA_EXTERNAL_RELEASE)
+}
+
+static void DebugMsgF(const char* format, ...)
+{
+#if defined(HS_DEBUGGING) || !defined(PLASMA_EXTERNAL_RELEASE)
     va_list args;
     va_start(args, format);
-
-    char buf[256];
-    int numWritten = _vsnprintf(buf, sizeof(buf), format, args);
-    hsAssert(numWritten > 0, "Buffer too small");
-
+    s_DebugLog->AddLineV(plStatusLog::kYellow, format, args);
     va_end(args);
+#endif // defined(HS_DEBUGGING) || !defined(PLASMA_EXTERNAL_RELEASE)
+}
 
-    DebugMessageProc(buf);
-#endif
+static void DebugInit()
+{
+#if defined(HS_DEBUGGING) || !defined(PLASMA_EXTERNAL_RELEASE)
+    plStatusLogMgr& mgr = plStatusLogMgr::GetInstance();
+    s_DebugLog = mgr.CreateStatusLog(30, "plasmadbg.log", plStatusLog::kFilledBackground |
+                 plStatusLog::kDeleteForMe | plStatusLog::kAlignToTop | plStatusLog::kTimestamp);
+    hsSetDebugMessageProc(_DebugMessageProc);
+    hsSetStatusMessageProc(_StatusMessageProc);
+#endif // defined(HS_DEBUGGING) || !defined(PLASMA_EXTERNAL_RELEASE)
 }
 
 static void AuthFailedStrings (ENetError authError,
@@ -1203,6 +1196,7 @@ LONG WINAPI plCustomUnhandledExceptionFilter( struct _EXCEPTION_POINTERS *Except
 #include "pfConsoleCore/pfConsoleEngine.h"
 PF_CONSOLE_LINK_ALL()
 
+#include "plResMgr/plVersion.h"
 int WINAPI WinMain(HINSTANCE hInst, HINSTANCE hPrevInst, LPSTR lpCmdLine, int nCmdShow)
 {
     PF_CONSOLE_INIT_ALL()
@@ -1398,22 +1392,8 @@ int WINAPI WinMain(HINSTANCE hInst, HINSTANCE hPrevInst, LPSTR lpCmdLine, int nC
     //
     // Set up to log errors by using hsDebugMessage
     //
-    gDebugFile = NULL;
-    if ( !plStatusLog::fLoggingOff )
-    {
-        wchar_t fileAndPath[MAX_PATH];
-        PathGetLogDirectory(fileAndPath, arrsize(fileAndPath));
-        PathAddFilename(fileAndPath, fileAndPath, L"plasmalog.txt", arrsize(fileAndPath));
-        gDebugFile = _wfopen(fileAndPath, L"wt");
-        hsAssert(gDebugFile != NULL, "Error creating debug file plasmalog.txt");
-        hsSetDebugMessageProc(DebugMessageProc);
-        if (gDebugFile != NULL)
-        {
-            fputs(plProduct::ProductString().c_str(), gDebugFile);
-            fputs("\n", gDebugFile);
-            fflush(gDebugFile);
-        }
-    }
+    DebugInit();
+    DebugMsgF("Plasma 2.0.%i.%i - %s", PLASMA2_MAJOR_VERSION, PLASMA2_MINOR_VERSION, plProduct::ProductString().c_str());
 
     for (;;) {
         // Create Window
@@ -1485,10 +1465,6 @@ int WINAPI WinMain(HINSTANCE hInst, HINSTANCE hPrevInst, LPSTR lpCmdLine, int nC
         break;
     }
 
-#ifndef _DEBUG
-    try
-    {
-#endif
     //
     // Cleanup
     //
@@ -1500,17 +1476,6 @@ int WINAPI WinMain(HINSTANCE hInst, HINSTANCE hPrevInst, LPSTR lpCmdLine, int nC
     hsAssert(hsgResMgr::ResMgr()->RefCnt()==1, "resMgr has too many refs, expect mem leaks");
     hsgResMgr::Shutdown();  // deletes fResMgr
     DeInitNetClientComm();
-#ifndef _DEBUG
-    } catch (...)
-    {
-        // just catch all the crashes on exit... just to keep GameTap from complaining
-        if (gDebugFile)
-            fprintf(gDebugFile, "Crashed on shutdown.\n");
-    }
-#endif
-
-    if (gDebugFile)
-        fclose(gDebugFile);
 
     // Uninstall our unhandled exception filter, if we installed one
 #ifndef HS_DEBUGGING

Sources/Plasma/CoreLib/hsStream.cpp

@@ -714,17 +714,13 @@ uint32_t hsUNIXStream::Read(uint32_t bytes,  void* buffer)
 {
     if (!fRef || !bytes)
         return 0;
-    int numItems = ::fread(buffer, 1 /*size*/, bytes /*count*/, fRef);
+    size_t numItems = ::fread(buffer, 1 /*size*/, bytes /*count*/, fRef);
     fBytesRead += numItems;
     fPosition += numItems;
-    if ((unsigned)numItems < bytes) {
-        if (feof(fRef)) {
-            // EOF ocurred
-            char str[128];
-            sprintf(str, "Hit EOF on UNIX Read, only read %d out of requested %d bytes\n", numItems, bytes);
-            hsDebugMessage(str, 0);
-        }
-        else {
+    if (numItems < bytes)
+    {
+        if (!feof(fRef))
+        {
             hsDebugMessage("Error on UNIX Read", ferror(fRef));
         }
     }

Sources/Plasma/NucleusLib/inc/plgDispatch.h

@@ -68,6 +68,8 @@ public:
     virtual void    MsgQueueOnOff(bool) = 0;      // Turn on or off Queued Messages, if off, uses MsgSend Immediately (for plugins)
 
     virtual bool    SetMsgBuffering(bool on) = 0; // On starts deferring msg delivery until buffering is set to off again.
+
+    virtual void    BeginShutdown() = 0;
 };
 
 class plgDispatch

Sources/Plasma/NucleusLib/pnDispatch/plDispatch.cpp

@@ -103,12 +103,16 @@ plDispatch::plDispatch()
 
 plDispatch::~plDispatch()
 {
-    int i;
-    for( i = 0; i < fRegisteredExactTypes.GetCount(); i++ )
-        delete fRegisteredExactTypes[i];
-
+    hsAssert(fRegisteredExactTypes.GetCount() == 0, "registered type after Dispatch shutdown");
     ITrashUndelivered();
+}
 
+void plDispatch::BeginShutdown()
+{
+    for (int i = 0; i < fRegisteredExactTypes.Count(); ++i)
+        delete fRegisteredExactTypes[i];
+    fRegisteredExactTypes.Reset();
+    ITrashUndelivered();
 }
 
 void plDispatch::ITrashUndelivered()

Sources/Plasma/NucleusLib/pnDispatch/plDispatch.h

@@ -131,6 +131,8 @@ public:
 
     virtual bool    SetMsgBuffering(bool on); // On starts deferring msg delivery until buffering is set to off again.
 
+    virtual void    BeginShutdown();
+
     static void SetMsgRecieveCallback(MsgRecieveCallback callback) { fMsgRecieveCallback = callback; }
 };
 
@@ -149,6 +151,8 @@ public:
     virtual void MsgQueue(plMessage* msg) {}
     virtual void MsgQueueProcess() {}
 
+    virtual void BeginShutdown() {}
+
 };
 
 #endif // plDispatch_inc

Sources/Plasma/PubUtilLib/plResMgr/plResManager.cpp

@@ -96,7 +96,6 @@ static void ILog(uint8_t level, const char* format, ...)
 
 plResManager::plResManager():
     fInited(false),
-    fPageOutHint(0),
     fDispatch(nil),
     fReadingObject( false ),
     fCurCloneID(0),
@@ -205,10 +204,11 @@ void plResManager::IShutdown()
     // TimerCallbackMgr is a fixed-keyed object, so needs to shut down before the registry
     plgTimerCallbackMgr::Shutdown(); 
 
-    // Destroy the dispatch. Note that we do this before the registry so that any lingering messages
-    // can free up keys properly
-    hsRefCnt_SafeUnRef(fDispatch);
-    fDispatch = nil;
+    // Formerly, we destroyed the Dispatcher here to clean up keys for leak reporting.
+    // However, if there are *real* leaked keys, then they will want to unload after this step.
+    // To unload, plKeyImp needs to dispatcher. SO, we're going to pitch everything currently in the
+    // Dispatcher and kill it later
+    fDispatch->BeginShutdown();
 
     // Just before we shut down the registry, page out any keys that still exist.
     // (They shouldn't... they're baaaaaad.)
@@ -224,9 +224,12 @@ void plResManager::IShutdown()
     fLoadedPages.clear();
 
     IUnlockPages();
-
     fLastFoundPage = nil;
 
+    // Now, kill off the Dispatcher
+    hsRefCnt_SafeUnRef(fDispatch);
+    fDispatch = nullptr;
+
     kResMgrLog(1, ILog(1, "   ...Shutdown successful!"));
 
     fInited = false;
@@ -488,47 +491,21 @@ public:
     }
 };
 
-#if HS_BUILD_FOR_UNIX
-static void sLeakReportRedirectFn( const char message[] )
-{
-    hsUNIXStream stream;
-    stream.Open( "resMgrMemLeaks.txt", "at" );
-    stream.WriteString( message );
-    stream.Close();
-}
-static bool sFirstTime = true;
-#endif
-
 // Just the scene nodes (and objects referenced by the node... and so on)
 void plResManager::IPageOutSceneNodes(bool forceAll)
 {
     plSynchEnabler ps(false);   // disable dirty tracking while paging out
 
-#if HS_BUILD_FOR_UNIX
-    if (sFirstTime)
-    {
-        hsUNIXStream stream;
-        stream.Open("resMgrMemLeaks.txt", "wt");
-        stream.Close();
-        sFirstTime = false;
-    }
-    hsDebugMessageProc oldProc = hsSetStatusMessageProc(sLeakReportRedirectFn);
-#endif
-
     if (forceAll)
     {
         hsStatusMessage( "--- plResManager Object Leak Report (BEGIN) ---" );
-        plPageOutIterator iter(this, uint16_t(-1));
+        plPageOutIterator iter(this, static_cast<uint16_t>(-1));
         hsStatusMessage( "--- plResManager Object Leak Report (END) ---" );
     }
     else
     {
-        plPageOutIterator iter(this, fPageOutHint);
+        plPageOutIterator iter(this, 0);
     }
-
-#if HS_BUILD_FOR_UNIX
-    hsSetStatusMessageProc( oldProc );
-#endif
 }
 
 //// FindKey /////////////////////////////////////////////////////////////////
@@ -1578,7 +1555,7 @@ static void sIReportLeak(plKeyImp* key, plRegistryPageNode* page)
     if (!alreadyDone)
     {
         // Print out page header
-        hsStatusMessageF("  Leaks in page %s>%s[%08x]:\n", lastPage->GetPageInfo().GetAge().c_str(), lastPage->GetPageInfo().GetPage().c_str(), lastPage->GetPageInfo().GetLocation().GetSequenceNumber());
+        hsStatusMessageF("\tLeaks in page %s>%s[%08x]:\n", lastPage->GetPageInfo().GetAge().c_str(), lastPage->GetPageInfo().GetPage().c_str(), lastPage->GetPageInfo().GetLocation().GetSequenceNumber());
         alreadyDone = true;
     }
 
@@ -1586,14 +1563,14 @@ static void sIReportLeak(plKeyImp* key, plRegistryPageNode* page)
     if (refsLeft == 0)
         return;
 
-    char tempStr2[128];
-    if (key->ObjectIsLoaded() == nil)
-        sprintf(tempStr2, "(key only, %d refs left)", refsLeft);
+    plStringStream ss;
+    ss << "\t\t" << plFactory::GetNameOfClass(key->GetUoid().GetClassType()) << ": ";
+    ss << key->GetUoid().StringIze() << " ";
+    if (key->ObjectIsLoaded())
+        ss << "- " << key->GetDataLen() << " bytes - " << refsLeft << " refs left";
     else
-        sprintf(tempStr2, "- %d bytes - %d refs left", key->GetDataLen(), refsLeft);
-
-    hsStatusMessageF("    %s: %s %s\n", plFactory::GetNameOfClass(key->GetUoid().GetClassType()), 
-                                                key->GetUoid().StringIze().c_str(), tempStr2);
+        ss << "(key only, " << refsLeft << " refs left)";
+    hsStatusMessage(ss.GetString().c_str());
 }
 
 //// UnloadPageObjects ///////////////////////////////////////////////////////
@@ -1624,7 +1601,7 @@ void plResManager::UnloadPageObjects(plRegistryPageNode* pageNode, uint16_t clas
 
     plUnloadObjectsIterator iterator;
 
-    if (classIndexHint != uint16_t(-1))
+    if (classIndexHint != static_cast<uint16_t>(-1))
         pageNode->IterateKeys(&iterator, classIndexHint);
     else
         pageNode->IterateKeys(&iterator);

Sources/Plasma/PubUtilLib/plResMgr/plResManager.h

@@ -209,7 +209,6 @@ protected:
     plRegistryPageNode* CreatePage(const plLocation& location, const char* age, const char* page);
 
     bool          fInited;
-    uint16_t      fPageOutHint;
 
     // True if we're reading in an object. We only read one object at a time
     bool               fReadingObject;

Sources/Tools/MaxMain/plPluginResManager.cpp

@@ -60,9 +60,6 @@ You can contact Cyan Worlds, Inc. by email legal@cyan.com
 
 plKey plPluginResManager::NameToLoc(const plString& age, const plString& page, int32_t sequenceNumber, bool itinerant)
 {
-    // Hack for now--always prefer paging out sceneNodes first
-    fPageOutHint = plSceneNode::Index();
-
     // Get or create our page
     plRegistryPageNode* pageNode = INameToPage(age, page, sequenceNumber, itinerant);
     hsAssert(pageNode != nil, "No page returned from INameToPage(), shouldn't be possible");