Dqn/dqn_debug.cpp

// NOTE: [$ASAN] Dqn_Asan ========================================================================== ===
void Dqn_ASAN_PoisonMemoryRegion(void const volatile *ptr, Dqn_usize size)
{
    #if __has_feature(address_sanitizer) || defined(__SANITIZE_ADDRESS__)
    __asan_poison_memory_region(ptr, size);
    if (DQN_ASAN_VET_POISON) {
        DQN_HARD_ASSERT(__asan_address_is_poisoned(ptr));
        DQN_HARD_ASSERT(__asan_address_is_poisoned((char *)ptr + (size - 1)));
    }
    #else
    (void)ptr; (void)size;
    #endif
}

void Dqn_ASAN_UnpoisonMemoryRegion(void const volatile *ptr, Dqn_usize size)
{
    #if __has_feature(address_sanitizer) || defined(__SANITIZE_ADDRESS__)
    __asan_unpoison_memory_region(ptr, size);
    if (DQN_ASAN_VET_POISON) {
        DQN_HARD_ASSERT(__asan_region_is_poisoned((void *)ptr, size) == 0);
    }
    #else
    (void)ptr; (void)size;
    #endif
}

// NOTE: [$DEBG] Dqn_Debug =========================================================================
DQN_API Dqn_String8 Dqn_Debug_CleanStackTrace(Dqn_String8 stack_trace)
{
    // NOTE: Remove the stacktrace's library invocations from the stack trace
    // which just adds noise to the actual trace we want to look at, e.g:
    //
    // dqn\b_stacktrace.h(198): b_stacktrace_get
    // dqn\b_stacktrace.h(156): b_stacktrace_get_string

    Dqn_String8BinarySplitResult split_line0 = Dqn_String8_BinarySplit(stack_trace, DQN_STRING8("\n"));
    Dqn_String8BinarySplitResult split_line1 = Dqn_String8_BinarySplit(split_line0.rhs, DQN_STRING8("\n"));

    Dqn_String8 result = split_line1.rhs;
    return result;
}

#if defined(DQN_LEAK_TRACING)
DQN_API void Dqn_Debug_TrackAlloc_(Dqn_String8 stack_trace, void *ptr, Dqn_usize size, bool leak_permitted)
{
    if (!ptr)
        return;

    if (g_dqn_library->alloc_tracking_disabled)
        return;

    // NOTE: In this function we can create alloc records and hence it's
    // possible for the alloc table to resize. This can cause a nested call
    // into the tracking alloc function and dead-lock. We don't
    // care about tracking these alloc records for the alloc table itself so we 
    // disable alloc tracking for the duration of this function.
    // TODO(doyle): @robust This is not thread safe.
    Dqn_TicketMutex_Begin(&g_dqn_library->alloc_table_mutex);
    g_dqn_library->alloc_tracking_disabled = true;

    DQN_DEFER {
        g_dqn_library->alloc_tracking_disabled = false;
        Dqn_TicketMutex_End(&g_dqn_library->alloc_table_mutex);
    };

    // NOTE: If the entry was not added, we are reusing a pointer that has been freed.
    // TODO: Add API for always making the item but exposing a var to indicate if the item was newly created or it already existed.
    Dqn_DSMap<Dqn_AllocRecord> *alloc_table = &g_dqn_library->alloc_table;
    Dqn_DSMapKey key                        = Dqn_DSMap_KeyU64(alloc_table, DQN_CAST(uintptr_t)ptr);
    Dqn_AllocRecord *alloc                  = Dqn_DSMap_Find(alloc_table, key);
    if (alloc) {
        if ((alloc->flags & Dqn_AllocRecordFlag_Freed) == 0) {
            Dqn_String8 alloc_stack_trace       = Dqn_String8_Init(alloc->stack_trace, alloc->stack_trace_size);
            Dqn_String8 alloc_clean_stack_trace = Dqn_String8_Slice(alloc_stack_trace, g_dqn_library->stack_trace_offset_to_our_call_stack, alloc_stack_trace.size);
            Dqn_String8 clean_stack_trace       = Dqn_String8_Slice(stack_trace,       g_dqn_library->stack_trace_offset_to_our_call_stack, stack_trace.size);
            DQN_HARD_ASSERTF(
                alloc->flags & Dqn_AllocRecordFlag_Freed,
                "\n\nThis pointer is already in the leak tracker, however it has not "
                "been freed yet. This same pointer is being ask to be tracked "
                "twice in the allocation table, e.g. one if its previous free "
                "calls has not being marked freed with an equivalent call to "
                "Dqn_Debug_TrackDealloc()\n"
                "\n"
                "The pointer (0x%p) originally allocated %_$$zu at:\n"
                "\n"
                "%.*s"
                "\n"
                "The pointer is being allocated again at:\n"
                "%.*s"
                ,
                ptr, alloc->size,
                DQN_STRING_FMT(alloc_clean_stack_trace),
                DQN_STRING_FMT(clean_stack_trace));
        }

        // NOTE: Pointer was reused, clean up the prior entry
        free(alloc->stack_trace);
        free(alloc->freed_stack_trace);
        *alloc = {};
    } else {
        alloc = Dqn_DSMap_Make(alloc_table, key, /*found*/ nullptr);
    }

    alloc->ptr              = ptr;
    alloc->size             = size;
    alloc->stack_trace      = stack_trace.data;
    alloc->stack_trace_size = DQN_CAST(uint16_t)stack_trace.size;

    // TODO(doyle): @robust The global flag is not multi-thread safe
    if (leak_permitted || g_dqn_library->alloc_is_allowed_to_leak)
        alloc->flags |= Dqn_AllocRecordFlag_LeakPermitted;
}

DQN_API void Dqn_Debug_TrackDealloc_(Dqn_String8 stack_trace, void *ptr)
{
    if (!ptr || g_dqn_library->alloc_tracking_disabled)
        return;

    Dqn_TicketMutex_Begin(&g_dqn_library->alloc_table_mutex);
    DQN_DEFER { Dqn_TicketMutex_End(&g_dqn_library->alloc_table_mutex); };

    Dqn_DSMap<Dqn_AllocRecord> *alloc_table = &g_dqn_library->alloc_table;
    Dqn_DSMapKey key                        = Dqn_DSMap_KeyU64(alloc_table, DQN_CAST(uintptr_t)ptr);
    Dqn_AllocRecord *alloc                  = Dqn_DSMap_Find(alloc_table, key);

    DQN_HARD_ASSERTF(alloc, "Allocated pointer can not be removed as it does not exist in the "
                            "allocation table. When this memory was allocated, the pointer was "
                            "not added to the allocation table [ptr=%p]",
                            ptr);

    if (alloc->flags & Dqn_AllocRecordFlag_Freed) {
        Dqn_String8 alloc_stack_trace       = Dqn_String8_Init(alloc->stack_trace, alloc->stack_trace_size);
        Dqn_String8 alloc_clean_stack_trace = Dqn_String8_Slice(alloc_stack_trace, g_dqn_library->stack_trace_offset_to_our_call_stack, alloc_stack_trace.size);

        Dqn_String8 alloc_freed_stack_trace       = Dqn_String8_Init(alloc->freed_stack_trace, alloc->freed_stack_trace_size);
        Dqn_String8 alloc_freed_clean_stack_trace = Dqn_String8_Slice(alloc_freed_stack_trace, g_dqn_library->stack_trace_offset_to_our_call_stack, alloc_freed_stack_trace.size);

        Dqn_String8 dealloc_stack_trace           = Dqn_String8_Slice(stack_trace, g_dqn_library->stack_trace_offset_to_our_call_stack, stack_trace.size);

        DQN_HARD_ASSERTF((alloc->flags & Dqn_AllocRecordFlag_Freed) == 0,
                         "\n\nDouble free detected, pointer to free was already marked "
                         " as freed. Either the pointer was reallocated but not"
                         " traced, or, the pointer was freed twice.\n"
                         "\n"
                         "The pointer (0x%p) originally allocated %_$$zu at:\n"
                         "\n"
                         "%.*s"
                         "\n"
                         "The pointer was freed at:\n"
                         "\n"
                         "%.*s"
                         "\n"
                         "The pointer is being freed again at:\n"
                         "%.*s"
                         ,
                         ptr, alloc->freed_size,
                         DQN_STRING_FMT(alloc_clean_stack_trace),
                         DQN_STRING_FMT(alloc_freed_clean_stack_trace),
                         DQN_STRING_FMT(dealloc_stack_trace));
    }

    alloc->flags                  |= Dqn_AllocRecordFlag_Freed;
    alloc->freed_size              = alloc->size;
    alloc->freed_stack_trace       = stack_trace.data;
    alloc->freed_stack_trace_size  = DQN_CAST(uint16_t)stack_trace.size;
}

DQN_API void Dqn_Debug_DumpLeaks()
{
    uint64_t leak_count   = 0;
    uint64_t leaked_bytes = 0;
    for (Dqn_usize index = 1; index < g_dqn_library->alloc_table.occupied; index++) {
        Dqn_DSMapSlot<Dqn_AllocRecord> *slot = g_dqn_library->alloc_table.slots + index;
        Dqn_AllocRecord *alloc               = &slot->value;
        bool alloc_leaked                    = (alloc->flags & Dqn_AllocRecordFlag_Freed) == 0;
        bool leak_permitted                  = (alloc->flags & Dqn_AllocRecordFlag_LeakPermitted);
        if (alloc_leaked && !leak_permitted) {
            leaked_bytes += alloc->size;
            leak_count++;

            Dqn_String8 stack_trace = Dqn_String8_Init(alloc->stack_trace, alloc->stack_trace_size);
            Dqn_String8 clean_stack_trace = Dqn_String8_Slice(stack_trace, g_dqn_library->stack_trace_offset_to_our_call_stack, stack_trace.size);
            Dqn_Log_WarningF("Pointer (0x%p) leaked %_$$zu at:\n"
                             "%.*s",
                             alloc->ptr, alloc->size,
                             DQN_STRING_FMT(clean_stack_trace));
        }
    }

    if (leak_count) {
        Dqn_Log_WarningF("There were %I64u leaked allocations totalling %_$$I64u", leak_count, leaked_bytes);
    }
}
#endif // defined(DQN_LEAK_TRACING)

// NOTE: [$LLOG] Dqn_Log  ==========================================================================
DQN_API Dqn_String8 Dqn_Log_MakeString(Dqn_Allocator allocator,
                                       bool colour,
                                       Dqn_String8 type,
                                       int log_type,
                                       Dqn_CallSite call_site,
                                       char const *fmt,
                                       va_list args)
{
    Dqn_usize     header_size_no_ansi_codes = 0;
    Dqn_String8   header                    = {};
    {
        DQN_LOCAL_PERSIST Dqn_usize max_type_length = 0;
        max_type_length                             = DQN_MAX(max_type_length, type.size);
        int type_padding                            = DQN_CAST(int)(max_type_length - type.size);

        Dqn_String8 colour_esc = {};
        Dqn_String8 bold_esc   = {};
        Dqn_String8 reset_esc  = {};
        if (colour) {
            bold_esc  = Dqn_Print_ESCBoldString;
            reset_esc = Dqn_Print_ESCResetString;
            switch (log_type) {
                case Dqn_LogType_Debug:                                                                          break;
                case Dqn_LogType_Info:    colour_esc = Dqn_Print_ESCColourFgU32String(Dqn_LogTypeColourU32_Info);    break;
                case Dqn_LogType_Warning: colour_esc = Dqn_Print_ESCColourFgU32String(Dqn_LogTypeColourU32_Warning); break;
                case Dqn_LogType_Error:   colour_esc = Dqn_Print_ESCColourFgU32String(Dqn_LogTypeColourU32_Error);   break;
            }
        }

        Dqn_String8 file_name            = Dqn_String8_FileNameFromPath(call_site.file);
        Dqn_DateHMSTimeString const time = Dqn_Date_HMSLocalTimeStringNow();
        header                           = Dqn_String8_InitF(allocator,
                                                             "%.*s "   // date
                                                             "%.*s "   // hms
                                                             "%.*s"    // colour
                                                             "%.*s"    // bold
                                                             "%.*s"    // type
                                                             "%*s"     // type padding
                                                             "%.*s"    // reset
                                                             " %.*s"   // file name
                                                             ":%05u ", // line number
                                                             DQN_CAST(uint32_t)time.date_size - 2, time.date + 2,   // date
                                                             DQN_CAST(uint32_t)time.hms_size,      time.hms,        // hms
                                                             DQN_CAST(uint32_t)colour_esc.size,    colour_esc.data, // colour
                                                             DQN_CAST(uint32_t)bold_esc.size,      bold_esc.data,   // bold
                                                             DQN_CAST(uint32_t)type.size,          type.data,       // type
                                                             DQN_CAST(uint32_t)type_padding,       "",              // type padding
                                                             DQN_CAST(uint32_t)reset_esc.size,     reset_esc.data,  // reset
                                                             DQN_CAST(uint32_t)file_name.size,     file_name.data,  // file name
                                                             call_site.line);                                       // line number
        header_size_no_ansi_codes = header.size - colour_esc.size - Dqn_Print_ESCResetString.size;
    }

    // NOTE: Header padding ========================================================================
    Dqn_usize header_padding = 0;
    {
        DQN_LOCAL_PERSIST Dqn_usize max_header_length = 0;
        max_header_length                             = DQN_MAX(max_header_length, header_size_no_ansi_codes);
        header_padding                                = max_header_length - header_size_no_ansi_codes;
    }

    // NOTE: Construct final log ===================================================================
    Dqn_String8 user_msg = Dqn_String8_InitFV(allocator, fmt, args);
    Dqn_String8 result   = Dqn_String8_Allocate(allocator, header.size + header_padding + user_msg.size, Dqn_ZeroMem_No);
    DQN_MEMCPY(result.data,                                header.data, header.size);
    DQN_MEMSET(result.data + header.size,                  ' ',         header_padding);
    DQN_MEMCPY(result.data + header.size + header_padding, user_msg.data, user_msg.size);
    return result;
}

DQN_FILE_SCOPE void Dqn_Log_FVDefault_(Dqn_String8 type, int log_type, void *user_data, Dqn_CallSite call_site, char const *fmt, va_list args)
{
    Dqn_Library *lib = g_dqn_library;
    (void)log_type;
    (void)user_data;

    // NOTE: Open log file for appending if requested ==========================
    Dqn_TicketMutex_Begin(&lib->log_file_mutex);
    if (lib->log_to_file && !lib->log_file.handle && lib->log_file.error_size == 0) {
        Dqn_ThreadScratch scratch  = Dqn_Thread_GetScratch(nullptr);
        Dqn_String8       log_path = Dqn_FsPath_ConvertF(scratch.arena, "%.*s/dqn.log", DQN_STRING_FMT(lib->exe_dir));
        lib->log_file              = Dqn_Fs_OpenFile(log_path, Dqn_FsFileOpen_CreateAlways, Dqn_FsFileAccess_AppendOnly);
    }
    Dqn_TicketMutex_End(&lib->log_file_mutex);

    // NOTE: Generate the log header ===========================================
    Dqn_ThreadScratch scratch = Dqn_Thread_GetScratch(nullptr);
    Dqn_String8 log_line      = Dqn_Log_MakeString(scratch.allocator,
                                                   !lib->log_no_colour,
                                                   type,
                                                   log_type,
                                                   call_site,
                                                   fmt,
                                                   args);

    // NOTE: Print log =========================================================
    Dqn_Print_StdLn(Dqn_PrintStd_Out, log_line);

    Dqn_TicketMutex_Begin(&lib->log_file_mutex);
    Dqn_Fs_WriteFile(&lib->log_file, log_line);
    Dqn_Fs_WriteFile(&lib->log_file, DQN_STRING8("\n"));
    Dqn_TicketMutex_End(&lib->log_file_mutex);
}

DQN_API void Dqn_Log_FVCallSite(Dqn_String8 type, Dqn_CallSite call_site, char const *fmt, va_list args)
{
    Dqn_LogProc *logging_function = g_dqn_library->log_callback ? g_dqn_library->log_callback : Dqn_Log_FVDefault_;
    logging_function(type, -1 /*log_type*/, g_dqn_library->log_user_data, call_site, fmt, args);
}

DQN_API void Dqn_Log_FCallSite(Dqn_String8 type, Dqn_CallSite call_site, char const  *fmt, ...)
{
    va_list args;
    va_start(args, fmt);
    Dqn_Log_FVCallSite(type, call_site, fmt, args);
    va_end(args);
}

DQN_API void Dqn_Log_TypeFVCallSite(Dqn_LogType type, Dqn_CallSite call_site, char const *fmt, va_list args)
{
    Dqn_String8 type_string = DQN_STRING8("DQN-BAD-LOG-TYPE");
    switch (type) {
        case Dqn_LogType_Error:   type_string = DQN_STRING8("ERROR"); break;
        case Dqn_LogType_Info:    type_string = DQN_STRING8("INFO"); break;
        case Dqn_LogType_Warning: type_string = DQN_STRING8("WARN"); break;
        case Dqn_LogType_Debug:   type_string = DQN_STRING8("DEBUG"); break;
        case Dqn_LogType_Count:   type_string = DQN_STRING8("BADXX"); break;
    }

    Dqn_LogProc *logging_function = g_dqn_library->log_callback ? g_dqn_library->log_callback : Dqn_Log_FVDefault_;
    logging_function(type_string, type /*log_type*/, g_dqn_library->log_user_data, call_site, fmt, args);
}

DQN_API void Dqn_Log_TypeFCallSite(Dqn_LogType type, Dqn_CallSite call_site, char const  *fmt, ...)
{
    va_list args;
    va_start(args, fmt);
    Dqn_Log_TypeFVCallSite(type, call_site, fmt, args);
    va_end(args);
}