Debug.cpp

Go to the documentation of this file.

//~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
// Project: uLib - User mode library.
// Module: Debug and error handling support.
// Author: Copyright (c) Love Nystrom
// License: NNOSL (BSD descendant, see NNOSL.txt in the base directory).
//~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~

#include <uLib/Debug.h>
#include <uLib/StrFunc.h>
#include <uLib/UtilFunc.h>

#undef USE_ULIB_DBGOUTPUT // Temp dbg squelch...
#define USE_ULIB_DBGOUTPUT  0  // DbgOutput fails to emit in rare corner cases ??

#ifndef USE_ULIB_DBGOUTPUT // Use custom DbgOutput instead of OutputDebugString?
  #ifdef HAVE_STRUCTURED_EH
    #define USE_ULIB_DBGOUTPUT  1
  #else
    #define USE_ULIB_DBGOUTPUT  0  // __try/__except is required.
  #endif
#endif

#if !defined(HAVE_STRUCTURED_EH) || defined(_UNICODE)
  // The custom DbgOutput function requires __try/__except.
  // Unicode must use OutputDebugStringW. DbgOutput doesn't do WCHAR translation.
  #undef USE_ULIB_DBGOUTPUT
  #define USE_ULIB_DBGOUTPUT  0
#endif

//==---------------------------------------------------------------------------
// SysErrorMsg gets the system defined error message for an Err code.
// If Err zero is passed in, Err is fetched with GetLastError().
// If a Buf is passed in, it is used to return the error string.
// If no Buf is given and Size is non-zero, Buf is allocated with new[]
// (so it can be disposed with deleteStr), and if Size is zero
// an internal static buffer is used.
//==---------------------------------------------------------------------------

CSTR SysErrorMsg( DWORD Err, TSTR Buf, UINT Length )
{
    static __thread_local TCHAR sBuf[ MAX_PATH ];

    if (!Err) Err = GetLastError();
    if (!Buf)
    {
        if (Length) Buf = newStrBuf( Length );
        else
        {
            Buf = sBuf;
            Length = dimof(sBuf);
        }
    }
    DWORD flags = FORMAT_MESSAGE_FROM_SYSTEM | FORMAT_MESSAGE_IGNORE_INSERTS;
    DWORD len = FormatMessage( flags, 0, Err, 0, Buf, Length, 0 );
    if (!len)
        _stprintf_s( Buf, Length, _T("Error %lu (0x%08lX)"), HRESULT_CODE(Err), Err );
    else
    {
        TSTR end = Buf+len-1; // Strip off trailing CRLF.
        while( *end == CR || *end == LF ) *end-- = 0;
    }
    return Buf;
}

// NtErrorMsg is experimental - Will the error translations make sense?

CSTR NtErrorMsg( NTSTATUS Status, TSTR Buf, UINT Size )
{
    return SysErrorMsg( LsaNtStatusToWinError( Status ), Buf, Size );
}

// Provide a wrap for "RtlSetLastWin32ErrorAndNtStatusFromNtStatus" (urrk).

bool SetLastErrorFromNtStatus( NTSTATUS Status )
{
    static VOID (NTAPI *RtlSetLastErrorFromNtStatus)( NTSTATUS Status );
    if (!RtlSetLastErrorFromNtStatus) // My abbreviated name..
    {
        HMODULE hMod = GetModuleHandleA( "NTDLL" );

        // IMNSHO the exported API name is "a sandwich short of a picnic". :/
        // Please learn decent API naming, and write the details as header comments!

        static CCASTR S_Api = "RtlSetLastWin32ErrorAndNtStatusFromNtStatus"; // OMG
        (FARPROC&) RtlSetLastErrorFromNtStatus = GetProcAddress( hMod, S_Api );
    }
    bool ok = (RtlSetLastErrorFromNtStatus != NULL);
    if (ok) RtlSetLastErrorFromNtStatus( Status );
    else SetLastError( LsaNtStatusToWinError( Status ));
    return ok;
}


//==---------------------------------------------------------------------------
// DPrint outputs a debugger string if Level <= global trace level.
// Level zero messages are meant to always be emitted.
// To squelch *all* output, set dbg_Level = -1
//==---------------------------------------------------------------------------

CHAR rt_Tag[] = "dbg_Lvl"; // 8 byte tag to locate dbg_Level in RAM at runtime.
// rt_Tag is an experiment to facilitate changing debug level at runtime.
// To do this, a debug "manager" would need to locate the tag in the loaded
// debugee, and modify the 4 byte integer (dbg_Level) just beyound it..

int dbg_Level = DP_DEBUG;

int SetDebugLevel( int Level )
{
    int prevLevel = dbg_Level;
    dbg_Level = Level;
    return prevLevel;
}

CSTR   dbg_Name = _T("[uLib]");
HANDLE dbg_LogFile = NULL;
bool   dbg_Flush = false;

//==---------------------------------------------------------------------------

#define _DP_MAXLEN_ 512  // DPrint buffer size (512 = kernel debugger's buffer)

#if USE_ULIB_DBGOUTPUT
    extern "C" bool DbgOutput( CSTR Str ); // Implemented below. Currently only ANSI text.
#else
    #define DbgOutput(s)  OutputDebugString(s)
#endif

static volatile bool __inDPrint = false; // Reentrancy lock.
volatile ULONG nDPrintSkipped = 0; // Nr of skipped (due to re-entry) DPrint calls.

// PONDER: Make DPrint immutable ANSI..? No reason to waste power on internal
// wide string translates since callers can dump wide strings anyway (with %S or %wZ).

void __cdecl DPrint( int Level, CSTR Fmt, ... )
{
    static TCHAR buf[_DP_MAXLEN_]; // Plain static, since we have reentrancy lock.

    TCHAR   *pch;
    DWORD   cbWr, xCode;
    va_list va;

    if (__inDPrint) // Prevent re-entry
        InterlockedIncrement( (LONG*)&nDPrintSkipped ); // Absolute zero so far.
    else
    {
        __inDPrint = true; //InterlockedIncrement( &__inDPrint );
        if (Level <= dbg_Level)
        {
            pch = _tcsecpy( buf, dbg_Name );
            switch( Level )
            {
                case DP_ALWAYS: *pch++ = SPACE; *pch = 0; break;
                case DP_FATAL:   pch = _tcsecpy( pch, _T(" FATAL: ") ); break;
                case DP_SEVERE:  pch = _tcsecpy( pch, _T(" SEVERE: ") ); break;
                case DP_ERROR:   pch = _tcsecpy( pch, _T(" ERROR: ") ); break;
                case DP_WARNING: pch = _tcsecpy( pch, _T(" WARNING: ") ); break;
                case DP_INFO:    pch = _tcsecpy( pch, _T(" INFO: ") ); break;
                case DP_DEBUG:   pch = _tcsecpy( pch, _T(" DEBUG: ") ); break;
                case DP_VERBOSE: pch = _tcsecpy( pch, _T(" VERBOSE: ") ); break;
                case DP_EXTREME: pch = _tcsecpy( pch, _T(" EXTREME: ") ); break;
                BEGIN_STRSAFE_OVERRIDE //#pragma warning( disable: 4996 )
                default: pch += _stprintf( pch, _T(" LEVEL%i: "), Level );
                END_STRSAFE_OVERRIDE //#pragma warning( default: 4996 )
                //default: *pch++ = _T(' ');
            }
            int len = int( pch - buf );
            int remain = dimof(buf) - len; // Circumvented in gcc (gcc has no vsprintf_s)

            va_start( va, Fmt );
            #ifndef HAVE_STRUCTURED_EH // No SEH in GCC. ("Libify" ReactOS's SEH2/3 and use that?)
                len += _vstprintf_s( pch, remain, Fmt, va );
                #ifdef __GNUC__
                UNUSED( remain );
                #endif
            #else
                BEGIN_STRSAFE_OVERRIDE
                __try {
                    len += _vsntprintf( pch, remain, Fmt, va );
                    // Why is vsnprintf() deemed unsafe when it already has a runlength limit?
                }
                __except_execute {
                    // Agh.. An exception in the debug printer is not a fun thing :/
                    // Show/tell and try to recover.
                    //*pch = 0; // Superfluous.. we're reusing buf...
                    xCode = GetExceptionCode();
                    _stprintf( buf,
                        _T("[uLib] SEVERE: [DPrint] Exception 0x%08X in _vsntprintf.")
                        _T(" Check your code!\n"), xCode
                        );
                }
                __end_except; // gcc kludge
                END_STRSAFE_OVERRIDE
            #endif
            va_end( va );

            DbgOutput( buf );

            if (dbg_LogFile)
            {
                PCHAR text;
              #ifdef _UNICODE
                static CHAR ansi[_DP_MAXLEN_];
                WideCharToMultiByte( CP_ACP, 0, buf,-1, ansi,dimof(ansi), NULL, NULL );
                text = ansi;
              #else
                text = buf;
              #endif
                WriteFile( dbg_LogFile, text, len, &cbWr, NULL );
                if (dbg_Flush) FlushFileBuffers( dbg_LogFile );
            }
        }
        __inDPrint = false; //InterlockedDecrement( &__inDPrint );
    }
    #ifdef __GNUC__
    //UNUSED( nums );
    UNUSED( xCode );
    #endif
}

HANDLE OpenLogFile( CSTR Name, bool Append )
{
    if (!Name) Name = DefaultLogFileName( NULL );

    DWORD dispo = Append ? OPEN_ALWAYS : CREATE_ALWAYS;
    DWORD flags = FILE_FLAG_SEQUENTIAL_SCAN;
    DWORD share = FILE_SHARE_READ;

    HANDLE hFile = CheckHandle( CreateFile( Name, GENERIC_WRITE, share, NULL, dispo, flags, NULL ));
    if (hFile)
    {
        FILETIME now = uLib::Now();
        if (Append) SetFilePointer( hFile, 0,0, FILE_END );
        WriteStr( hFile, _T("\n%s Logfile opened %s\n"), dbg_Name, FileTimeStr( &now ));
    }

    return hFile;
}

CSTR DefaultLogFileName( HMODULE hModule )
{
    static TCHAR LogName[ MAX_PATH ];
    int len = GetModuleFileName( hModule, LogName, dimof(LogName) );
    UNUSED( len );

    TSTR pzDot = _tcsrchr( LogName, DOT );
    if (!pzDot) pzDot = LogName + _tcslen( LogName ); // Set for append

    BEGIN_STRSAFE_OVERRIDE
    _tcscpy( pzDot, _T(".log") );
    END_STRSAFE_OVERRIDE

    return LogName;
}

#if USE_ULIB_DBGOUTPUT
//~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
// MEMO: Excerpt from very old Microsoft sample program (DBMON).
//
// Synopsis: DBMON notes 10/7/94
// Kent Forschmiedt (kentf), Microsoft Corporation
//
// The first DWORD of the shared memory buffer contains the process ID of the
// client that sent the debug string.  DBMON will print the process ID if the
// previous line printed was from another process, or if the previous line was
// from the same process and ended in a newline.
//
// The shared memory buffer must be 4096 bytes. If it is larger, it won't do any
// good. If it is smaller, nothing terrible will happen, but strings larger than
// the buffer will not be delivered, and a complaining message will be sent to
// the kernel debugger by the client. Why is it this size?  Because shared memory
// comes in page-sized chunks, so we might as well ask for as much as will be used
// on the machines with the smallest pages.  On machines with larger pages, the
// remainder of the page will be wasted anyway.
//
// Event DBWIN_BUFFER_READY must be an auto-reset event, so that only one client
// thread will use the buffer at a time. Using a manual reset event with
// PulseEvent will not work.
//
// Event DBWIN_DATA_READY need not be auto-reset, but it is simpler that way.
//
// Allowing multiple copies of DBMON to run might be amusing, put not particularly
// useful. As I originally wrote it, the messages were distributed randomly among
// the DBMON instances or were garbled. I added a check for ERROR_ALREADY_EXISTS so
// it won't run twice. The worst you can do to the client is cause it to print a
// message on the kernel debugger, as above.
//
// If DBMON is broken and never calls SetEvent(AckEvent), it will cause a 10
// second delay in the client every time OutputDebugString is called, then the
// message will be printed on the kernel debugger.
//
// OutputDebugString will force synchronization of client threads when DBMON is
// running. Letting the kernel debugger catch the strings will also synchronize
// threads, but the timing effects may be different.  Caveat emptor. / Kent F
//~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~

#include <uLib/UtilFunc.h>

#define BUFFER_READY_EVT_NAME   _T("DBWIN_BUFFER_READY")
#define DATA_READY_EVT_NAME     _T("DBWIN_DATA_READY")
#define DBMUTEX_NAME            _T("DBWinMutex")
#define SHARED_BUFFER_NAME      _T("DBWIN_BUFFER")
#define SHARED_BUFFER_SIZE      4096

#ifndef DBG_PRINTEXCEPTION_C
#define DBG_PRINTEXCEPTION_C    0x40010006L
#endif

// PONDER: Restrict DbgOut to ANSI, and adapt callers

static int __stdcall dbo_ExecFilter( DWORD xCode )
{
    static const int Execute = EXCEPTION_EXECUTE_HANDLER;
    static const int Search = EXCEPTION_CONTINUE_SEARCH;
    return (xCode == DBG_PRINTEXCEPTION_C) ? Execute : Search;
}

extern "C" bool DbgOutput( CSTR Str )
{
    static const UINT  MAX_BUFAVAIL = SHARED_BUFFER_SIZE - sizeof(DWORD) - 1;
    static const UINT  DBWIN_TIMEOUT = 10000;

    // Statics are implicitly initialized to zero by the compiler.

    static HANDLE  hSharedFile; // = NULL;
    static PBYTE   pSharedMem;  // = NULL;
    static HANDLE  hAckEvent;   // = NULL;
    static HANDLE  hReadyEvent; // = NULL;
    static HANDLE  hDbgMutex;   // = NULL;

    bool Sent = false;

    if ( !Str ) // Special IPC uninitialize command: Str == NULL.
    {
        hAckEvent = CloseHandleEx( hAckEvent );
        if (pSharedMem) { UnmapViewOfFile( pSharedMem ); pSharedMem = NULL; }
        hSharedFile = CloseHandleEx( hSharedFile );
        hReadyEvent = CloseHandleEx( hReadyEvent );
        goto dbgout_Exit;
    }

    ULONG_PTR xArg[ 2 ];

    __try
    {
        // Raise a debugger exception that a usermode debugger can catch.
        // If it doesn't, the kernel debugger (if active) will catch it...

        xArg[0] = 1 + _tcslen( Str );
        xArg[1] = (ULONG_PTR) Str;
        Sent = true; // Assume a debugger is present
        RaiseException( DBG_PRINTEXCEPTION_C, 0, 2, xArg );
    }
    __except( dbo_ExecFilter( GetExceptionCode() ))
    {
        Sent = false; // Ugh: No debugger caught the exception...
    }
    __end_except;

    if (!Sent)
    {
        // No debugger caught the exception, so try sending it to a
        // standard debug monitor, e.g Kent F's DBMON or Mark R's DbgView.
        //
        // Clean room analysis (using detours) of OutputDebugString revealed
        // that it creates or opens, and destroys, at least two events each call,
        // which seems inefficient, if not ill considered.
        // This DbgOutput function was implemented such that it avoids
        // that waste of time, doing the IPC setup only once in a process.
        //
        // If, for some reason, an app needs to reinitialize the IPC, it can call
        // DbgOutput( NULL ), and the next call will redo the IPC setup.

        UINT nRemain;
        CSTR pzOutput;

        // Look for DBMON or similar...

        if (!hDbgMutex)
        {
            if (!DefSec.lpSecurityDescriptor) // If caller never initialized a SDesc
            {
                // NOTE: This side effect has not been documented..
                InitializeSecDesc( &DefSecDesc, NULL ); // Full access
                DefSec.lpSecurityDescriptor = &DefSecDesc;
            }
            hDbgMutex = CreateMutex( &DefSec, FALSE, DBMUTEX_NAME );
        }

        if (hDbgMutex)
        {
            if (!WaitFor( hDbgMutex, DBWIN_TIMEOUT ))
                goto dbgout_Exit; // No DBMON, so bail out.

            if (!hSharedFile) // First call ?
            {
                // Setup interprocess communication.
                // Note that it's the _debugger_ that must create the IPC objects.

                hSharedFile = OpenFileMapping( FILE_MAP_WRITE, FALSE, SHARED_BUFFER_NAME );
                pSharedMem = hSharedFile
                    ? (PBYTE) MapViewOfFile( hSharedFile, FILE_MAP_WRITE, 0,0,0 )
                    : NULL;
                hAckEvent = pSharedMem
                    ? OpenEvent( SYNCHRONIZE, FALSE, BUFFER_READY_EVT_NAME )
                    : NULL;
                hReadyEvent = hAckEvent
                    ? OpenEvent( EVENT_MODIFY_STATE, FALSE, DATA_READY_EVT_NAME )
                    : NULL;
            }
            ReleaseMutex( hDbgMutex );
        }

        if (!hReadyEvent) goto dbgout_Exit; // IPC not initialized

        pzOutput = Str;
        nRemain = (UINT)_tcslen( pzOutput );
        DWORD procId = GetCurrentProcessId();

        while( nRemain ) // Loop it out (in case we got us a whopper)...
        {
            if (WaitFor( hAckEvent, DBWIN_TIMEOUT ))
            {
                *PDWORD( pSharedMem ) = procId;

                UINT Used = (nRemain < MAX_BUFAVAIL) ? nRemain : MAX_BUFAVAIL;
                PBYTE pzShared = (pSharedMem + sizeof(DWORD));
                memcpy( pzShared, pzOutput, Used );
                pzShared[ Used ] = 0;

                Sent = bool_cast( SetEvent( hReadyEvent ));
                if (Sent)
                {
                    pzOutput += Used;
                    nRemain  -= Used;
                }
            }
        }
    }
dbgout_Exit:
    return Sent;
}
#endif//USE_ULIB_DBGOUTPUT
// EOF