LCOV - code coverage report
Current view: top level - source/lib - debug.cpp (source / functions) Hit Total Coverage
Test: 0 A.D. test coverage report Lines: 44 185 23.8 %
Date: 2022-03-08 13:03:03 Functions: 7 21 33.3 %

          Line data    Source code
       1             : /* Copyright (C) 2021 Wildfire Games.
       2             :  *
       3             :  * Permission is hereby granted, free of charge, to any person obtaining
       4             :  * a copy of this software and associated documentation files (the
       5             :  * "Software"), to deal in the Software without restriction, including
       6             :  * without limitation the rights to use, copy, modify, merge, publish,
       7             :  * distribute, sublicense, and/or sell copies of the Software, and to
       8             :  * permit persons to whom the Software is furnished to do so, subject to
       9             :  * the following conditions:
      10             :  *
      11             :  * The above copyright notice and this permission notice shall be included
      12             :  * in all copies or substantial portions of the Software.
      13             :  *
      14             :  * THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND,
      15             :  * EXPRESS OR IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF
      16             :  * MERCHANTABILITY, FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT.
      17             :  * IN NO EVENT SHALL THE AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY
      18             :  * CLAIM, DAMAGES OR OTHER LIABILITY, WHETHER IN AN ACTION OF CONTRACT,
      19             :  * TORT OR OTHERWISE, ARISING FROM, OUT OF OR IN CONNECTION WITH THE
      20             :  * SOFTWARE OR THE USE OR OTHER DEALINGS IN THE SOFTWARE.
      21             :  */
      22             : 
      23             : #include "precompiled.h"
      24             : #include "lib/debug.h"
      25             : 
      26             : #include "lib/alignment.h"
      27             : #include "lib/app_hooks.h"
      28             : #include "lib/fnv_hash.h"
      29             : #include "lib/sysdep/cpu.h"   // cpu_CAS
      30             : #include "lib/sysdep/sysdep.h"
      31             : #include "lib/sysdep/vm.h"
      32             : 
      33             : #if OS_WIN
      34             : # include "lib/sysdep/os/win/wdbg_heap.h"
      35             : #endif
      36             : 
      37             : #include <cstdarg>
      38             : #include <cstring>
      39             : #include <cstdio>
      40             : 
      41             : namespace
      42             : {
      43             : 
      44             : // (NB: this may appear obscene, but deep stack traces have been
      45             : // observed to take up > 256 KiB)
      46             : constexpr std::size_t MESSAGE_SIZE = 512 * KiB / sizeof(wchar_t);
      47             : wchar_t g_MessageBuffer[MESSAGE_SIZE];
      48             : 
      49             : } // anonymous namespace
      50             : 
      51             : static const StatusDefinition debugStatusDefinitions[] = {
      52             :     { ERR::SYM_NO_STACK_FRAMES_FOUND, L"No stack frames found" },
      53             :     { ERR::SYM_UNRETRIEVABLE_STATIC, L"Value unretrievable (stored in external module)" },
      54             :     { ERR::SYM_UNRETRIEVABLE, L"Value unretrievable" },
      55             :     { ERR::SYM_TYPE_INFO_UNAVAILABLE, L"Error getting type_info" },
      56             :     { ERR::SYM_INTERNAL_ERROR, L"Exception raised while processing a symbol" },
      57             :     { ERR::SYM_UNSUPPORTED, L"Symbol type not (fully) supported" },
      58             :     { ERR::SYM_CHILD_NOT_FOUND, L"Symbol does not have the given child" },
      59             :     { ERR::SYM_NESTING_LIMIT, L"Symbol nesting too deep or infinite recursion" },
      60             :     { ERR::SYM_SINGLE_SYMBOL_LIMIT, L"Symbol has produced too much output" },
      61             :     { INFO::SYM_SUPPRESS_OUTPUT, L"Symbol was suppressed" }
      62             : };
      63             : STATUS_ADD_DEFINITIONS(debugStatusDefinitions);
      64             : 
      65             : 
      66             : // need to shoehorn printf-style variable params into
      67             : // the OutputDebugString call.
      68             : // - don't want to split into multiple calls - would add newlines to output.
      69             : // - fixing Win32 _vsnprintf to return # characters that would be written,
      70             : //   as required by C99, looks difficult and unnecessary. if any other code
      71             : //   needs that, implement GNU vasprintf.
      72             : // - fixed size buffers aren't nice, but much simpler than vasprintf-style
      73             : //   allocate+expand_until_it_fits. these calls are for quick debug output,
      74             : //   not loads of data, anyway.
      75             : 
      76             : // rationale: static data instead of std::set to allow setting at any time.
      77             : // we store FNV hash of tag strings for fast comparison; collisions are
      78             : // extremely unlikely and can only result in displaying more/less text.
      79             : static const size_t MAX_TAGS = 20;
      80             : static u32 tags[MAX_TAGS];
      81             : static size_t num_tags;
      82             : 
      83           0 : void debug_filter_add(const char* tag)
      84             : {
      85           0 :     const u32 hash = fnv_hash(tag, strlen(tag)*sizeof(tag[0]));
      86             : 
      87             :     // make sure it isn't already in the list
      88           0 :     for(size_t i = 0; i < MAX_TAGS; i++)
      89           0 :         if(tags[i] == hash)
      90             :             return;
      91             : 
      92             :     // too many already?
      93           0 :     if(num_tags == MAX_TAGS)
      94             :     {
      95           0 :         DEBUG_WARN_ERR(ERR::LOGIC); // increase MAX_TAGS
      96           0 :         return;
      97             :     }
      98             : 
      99           0 :     tags[num_tags++] = hash;
     100             : }
     101             : 
     102           0 : void debug_filter_remove(const char* tag)
     103             : {
     104           0 :     const u32 hash = fnv_hash(tag, strlen(tag)*sizeof(tag[0]));
     105             : 
     106           0 :     for(size_t i = 0; i < MAX_TAGS; i++)
     107             :     {
     108           0 :         if(tags[i] == hash) // found it
     109             :         {
     110             :             // replace with last element (avoid holes)
     111           0 :             tags[i] = tags[MAX_TAGS-1];
     112           0 :             num_tags--;
     113             : 
     114             :             // can only happen once, so we're done.
     115           0 :             return;
     116             :         }
     117             :     }
     118             : }
     119             : 
     120           0 : void debug_filter_clear()
     121             : {
     122           0 :     std::fill(tags, tags+MAX_TAGS, 0);
     123           0 : }
     124             : 
     125          14 : bool debug_filter_allows(const char* text)
     126             : {
     127          14 :     size_t i;
     128          14 :     for(i = 0; ; i++)
     129             :     {
     130             :         // no | found => no tag => should always be displayed
     131          84 :         if(text[i] == ' ' || text[i] == '\0')
     132             :             return true;
     133          84 :         if(text[i] == '|' && i != 0)
     134             :             break;
     135             :     }
     136             : 
     137          14 :     const u32 hash = fnv_hash(text, i*sizeof(text[0]));
     138             : 
     139             :     // check if entry allowing this tag is found
     140         294 :     for(i = 0; i < MAX_TAGS; i++)
     141         280 :         if(tags[i] == hash)
     142             :             return true;
     143             : 
     144             :     return false;
     145             : }
     146             : 
     147             : #undef debug_printf // allowing #defining it out
     148          14 : void debug_printf(const char* fmt, ...)
     149             : {
     150          14 :     char buf[16384];
     151             : 
     152          14 :     va_list ap;
     153          14 :     va_start(ap, fmt);
     154          14 :     const int numChars = vsprintf_s(buf, ARRAY_SIZE(buf), fmt, ap);
     155          14 :     if (numChars < 0)
     156           0 :         debug_break();  // poor man's assert - avoid infinite loop because ENSURE also uses debug_printf
     157          14 :     va_end(ap);
     158             : 
     159          14 :     debug_puts_filtered(buf);
     160          14 : }
     161             : 
     162          14 : void debug_puts_filtered(const char* text)
     163             : {
     164          14 :     if(debug_filter_allows(text))
     165           0 :         debug_puts(text);
     166          14 : }
     167             : 
     168             : 
     169             : //-----------------------------------------------------------------------------
     170             : 
     171           0 : Status debug_WriteCrashlog(const wchar_t* text)
     172             : {
     173             :     // (avoid infinite recursion and/or reentering this function if it
     174             :     // fails/reports an error)
     175           0 :     enum State
     176             :     {
     177             :         IDLE,
     178             :         BUSY,
     179             :         FAILED
     180             :     };
     181             :     // note: the initial state is IDLE. we rely on zero-init because
     182             :     // initializing local static objects from constants may happen when
     183             :     // this is first called, which isn't thread-safe. (see C++ 6.7.4)
     184           0 :     cassert(IDLE == 0);
     185           0 :     static volatile intptr_t state;
     186             : 
     187           0 :     if(!cpu_CAS(&state, IDLE, BUSY))
     188             :         return ERR::REENTERED;  // NOWARN
     189             : 
     190           0 :     OsPath pathname = ah_get_log_dir()/"crashlog.txt";
     191           0 :     FILE* f = sys_OpenFile(pathname, "w");
     192           0 :     if(!f)
     193             :     {
     194           0 :         state = FAILED; // must come before DEBUG_DISPLAY_ERROR
     195           0 :         DEBUG_DISPLAY_ERROR(L"Unable to open crashlog.txt for writing (please ensure the log directory is writable)");
     196           0 :         return ERR::FAIL;   // NOWARN (the above text is more helpful than a generic error code)
     197             :     }
     198             : 
     199           0 :     fputwc(0xFEFF, f);  // BOM
     200           0 :     fwprintf(f, L"%ls\n", text);
     201           0 :     fwprintf(f, L"\n\n====================================\n\n");
     202             : 
     203             :     // allow user to bundle whatever information they want
     204           0 :     ah_bundle_logs(f);
     205             : 
     206           0 :     fclose(f);
     207           0 :     state = IDLE;
     208           0 :     return INFO::OK;
     209             : }
     210             : 
     211             : 
     212             : //-----------------------------------------------------------------------------
     213             : // error message
     214             : //-----------------------------------------------------------------------------
     215             : 
     216             : 
     217             : // a stream with printf-style varargs and the possibility of
     218             : // writing directly to the output buffer.
     219             : class PrintfWriter
     220             : {
     221             : public:
     222             :     PrintfWriter(wchar_t* buf, size_t maxChars)
     223           0 :         : m_pos(buf), m_charsLeft(maxChars)
     224             :     {
     225             :     }
     226             : 
     227           0 :     bool operator()(const wchar_t* fmt, ...) WPRINTF_ARGS(2)
     228             :     {
     229           0 :         va_list ap;
     230           0 :         va_start(ap, fmt);
     231           0 :         const int len = vswprintf(m_pos, m_charsLeft, fmt, ap);
     232           0 :         va_end(ap);
     233           0 :         if(len < 0)
     234             :             return false;
     235           0 :         m_pos += len;
     236           0 :         m_charsLeft -= len;
     237           0 :         return true;
     238             :     }
     239             : 
     240           0 :     wchar_t* Position() const
     241             :     {
     242           0 :         return m_pos;
     243             :     }
     244             : 
     245           0 :     size_t CharsLeft() const
     246             :     {
     247           0 :         return m_charsLeft;
     248             :     }
     249             : 
     250           0 :     void CountAddedChars()
     251             :     {
     252           0 :         const size_t len = wcslen(m_pos);
     253           0 :         m_pos += len;
     254           0 :         m_charsLeft -= len;
     255           0 :     }
     256             : 
     257             : private:
     258             :     wchar_t* m_pos;
     259             :     size_t m_charsLeft;
     260             : };
     261             : 
     262             : 
     263             : // split out of debug_DisplayError because it's used by the self-test.
     264           0 : const wchar_t* debug_BuildErrorMessage(
     265             :     const wchar_t* description,
     266             :     const wchar_t* filename, int line, const char* func,
     267             :     void* context, const wchar_t* lastFuncToSkip)
     268             : {
     269             :     // retrieve errno (might be relevant) before doing anything else
     270             :     // that might overwrite it.
     271           0 :     wchar_t description_buf[100] = L"?";
     272           0 :     wchar_t os_error[100] = L"?";
     273           0 :     Status errno_equiv = StatusFromErrno(); // NOWARN
     274           0 :     if(errno_equiv != ERR::FAIL)    // meaningful translation
     275           0 :         StatusDescription(errno_equiv, description_buf, ARRAY_SIZE(description_buf));
     276           0 :     sys_StatusDescription(0, os_error, ARRAY_SIZE(os_error));
     277             : 
     278           0 :     PrintfWriter writer(g_MessageBuffer, MESSAGE_SIZE);
     279             : 
     280             :     // header
     281           0 :     if(!writer(
     282             :         L"%ls\r\n"
     283             :         L"Location: %ls:%d (%hs)\r\n"
     284             :         L"\r\n"
     285             :         L"Call stack:\r\n"
     286             :         L"\r\n",
     287             :         description, filename, line, func
     288             :     ))
     289             :     {
     290           0 : fail:
     291           0 :         return L"(error while formatting error message)";
     292             :     }
     293             : 
     294             :     // append stack trace
     295           0 :     Status ret = debug_DumpStack(writer.Position(), writer.CharsLeft(), context, lastFuncToSkip);
     296           0 :     if(ret == ERR::REENTERED)
     297             :     {
     298           0 :         if(!writer(
     299             :             L"While generating an error report, we encountered a second "
     300             :             L"problem. Please be sure to report both this and the subsequent "
     301             :             L"error messages."
     302             :         ))
     303             :             goto fail;
     304             :     }
     305           0 :     else if(ret != INFO::OK)
     306             :     {
     307           0 :         wchar_t error_buf[100] = {'?'};
     308           0 :         if(!writer(
     309             :             L"(error while dumping stack: %ls)",
     310             :             StatusDescription(ret, error_buf, ARRAY_SIZE(error_buf))
     311             :         ))
     312           0 :             goto fail;
     313             :     }
     314             :     else    // success
     315             :     {
     316           0 :         writer.CountAddedChars();
     317             :     }
     318             : 
     319             :     // append errno
     320           0 :     if(!writer(
     321             :         L"\r\n"
     322             :         L"errno = %d (%ls)\r\n"
     323             :         L"OS error = %ls\r\n",
     324           0 :         errno, description_buf, os_error
     325             :     ))
     326             :         goto fail;
     327             : 
     328             :     return g_MessageBuffer;
     329             : }
     330             : 
     331             : 
     332             : //-----------------------------------------------------------------------------
     333             : // display error messages
     334             : //-----------------------------------------------------------------------------
     335             : 
     336             : // translates and displays the given strings in a dialog.
     337             : // this is typically only used when debug_DisplayError has failed or
     338             : // is unavailable because that function is much more capable.
     339             : // implemented via sys_display_msg; see documentation there.
     340           0 : void debug_DisplayMessage(const wchar_t* caption, const wchar_t* msg)
     341             : {
     342           0 :     sys_display_msg(caption, msg);
     343           0 : }
     344             : 
     345             : 
     346             : // when an error has come up and user clicks Exit, we don't want any further
     347             : // errors (e.g. caused by atexit handlers) to come up, possibly causing an
     348             : // infinite loop. hiding errors isn't good, but we assume that whoever clicked
     349             : // exit really doesn't want to see any more messages.
     350             : static atomic_bool isExiting;
     351             : 
     352             : // this logic is applicable to any type of error. special cases such as
     353             : // suppressing certain expected WARN_ERRs are done there.
     354             : static bool ShouldSuppressError(atomic_bool* suppress)
     355             : {
     356           0 :     if(isExiting)
     357             :         return true;
     358             : 
     359           0 :     if(!suppress)
     360             :         return false;
     361             : 
     362           0 :     if(*suppress == DEBUG_SUPPRESS)
     363             :         return true;
     364             : 
     365             :     return false;
     366             : }
     367             : 
     368           0 : static ErrorReactionInternal CallDisplayError(const wchar_t* text, size_t flags)
     369             : {
     370             :     // first try app hook implementation
     371           0 :     ErrorReactionInternal er = ah_display_error(text, flags);
     372             :     // .. it's only a stub: default to normal implementation
     373           0 :     if(er == ERI_NOT_IMPLEMENTED)
     374           0 :         er = sys_display_error(text, flags);
     375             : 
     376           0 :     return er;
     377             : }
     378             : 
     379           0 : static ErrorReaction PerformErrorReaction(ErrorReactionInternal er, size_t flags, atomic_bool* suppress)
     380             : {
     381           0 :     const bool shouldHandleBreak = (flags & DE_MANUAL_BREAK) == 0;
     382             : 
     383           0 :     switch(er)
     384             :     {
     385             :     case ERI_CONTINUE:
     386             :         return ER_CONTINUE;
     387             : 
     388           0 :     case ERI_BREAK:
     389             :         // handle "break" request unless the caller wants to (doing so here
     390             :         // instead of within the dlgproc yields a correct call stack)
     391           0 :         if(shouldHandleBreak)
     392             :         {
     393           0 :             debug_break();
     394           0 :             return ER_CONTINUE;
     395             :         }
     396             :         else
     397             :             return ER_BREAK;
     398             : 
     399           0 :     case ERI_SUPPRESS:
     400           0 :         (void)cpu_CAS(suppress, 0, DEBUG_SUPPRESS);
     401           0 :         return ER_CONTINUE;
     402             : 
     403           0 :     case ERI_EXIT:
     404           0 :         isExiting = 1;  // see declaration
     405           0 :         COMPILER_FENCE;
     406             : 
     407             : #if OS_WIN
     408             :         // prevent (slow) heap reporting since we're exiting abnormally and
     409             :         // thus probably leaking like a sieve.
     410             :         wdbg_heap_Enable(false);
     411             : #endif
     412             : 
     413           0 :         exit(EXIT_FAILURE);
     414             : 
     415           0 :     case ERI_NOT_IMPLEMENTED:
     416           0 :     default:
     417           0 :         debug_break();  // not expected to be reached
     418           0 :         return ER_CONTINUE;
     419             :     }
     420             : }
     421             : 
     422           0 : ErrorReaction debug_DisplayError(const wchar_t* description,
     423             :     size_t flags, void* context, const wchar_t* lastFuncToSkip,
     424             :     const wchar_t* pathname, int line, const char* func,
     425             :     atomic_bool* suppress)
     426             : {
     427             :     // "suppressing" this error means doing nothing and returning ER_CONTINUE.
     428           0 :     if(ShouldSuppressError(suppress))
     429             :         return ER_CONTINUE;
     430             : 
     431             :     // fix up params
     432             :     // .. caller supports a suppress flag; set the corresponding flag so that
     433             :     //    the error display implementation enables the Suppress option.
     434           0 :     if(suppress)
     435           0 :         flags |= DE_ALLOW_SUPPRESS;
     436             : 
     437           0 :     if(flags & DE_NO_DEBUG_INFO)
     438             :     {
     439             :         // in non-debug-info mode, simply display the given description
     440             :         // and then return immediately
     441           0 :         ErrorReactionInternal er = CallDisplayError(description, flags);
     442           0 :         return PerformErrorReaction(er, flags, suppress);
     443             :     }
     444             : 
     445             :     // .. deal with incomplete file/line info
     446           0 :     if(!pathname || pathname[0] == '\0')
     447           0 :         pathname = L"unknown";
     448           0 :     if(line <= 0)
     449           0 :         line = 0;
     450           0 :     if(!func || func[0] == '\0')
     451           0 :         func = "?";
     452             :     // .. _FILE__ evaluates to the full path (albeit without drive letter)
     453             :     //    which is rather long. we only display the base name for clarity.
     454           0 :     const wchar_t* filename = path_name_only(pathname);
     455             : 
     456             :     // display in output window; double-click will navigate to error location.
     457           0 :     const wchar_t* text = debug_BuildErrorMessage(description, filename, line, func, context, lastFuncToSkip);
     458             : 
     459           0 :     (void)debug_WriteCrashlog(text);
     460           0 :     ErrorReactionInternal er = CallDisplayError(text, flags);
     461             : 
     462             :     // TODO: use utf8 conversion without internal allocations.
     463           0 :     debug_printf("%s(%d): %s\n", utf8_from_wstring(filename).c_str(), line, utf8_from_wstring(description).c_str());
     464             : 
     465             :     // note: debug_break-ing here to make sure the app doesn't continue
     466             :     // running is no longer necessary. debug_DisplayError now determines our
     467             :     // window handle and is modal.
     468             : 
     469           0 :     return PerformErrorReaction(er, flags, suppress);
     470             : }
     471             : 
     472             : 
     473             : // is errorToSkip valid? (also guarantees mutual exclusion)
     474             : enum SkipStatus
     475             : {
     476             :     INVALID, VALID, BUSY
     477             : };
     478             : static intptr_t skipStatus = INVALID;
     479             : static Status errorToSkip;
     480             : static size_t numSkipped;
     481             : 
     482           9 : void debug_SkipErrors(Status err)
     483             : {
     484           9 :     if(cpu_CAS(&skipStatus, INVALID, BUSY))
     485             :     {
     486           9 :         errorToSkip = err;
     487           9 :         numSkipped = 0;
     488           9 :         COMPILER_FENCE;
     489           9 :         skipStatus = VALID; // linearization point
     490             :     }
     491             :     else
     492           0 :         DEBUG_WARN_ERR(ERR::REENTERED);
     493           9 : }
     494             : 
     495           9 : size_t debug_StopSkippingErrors()
     496             : {
     497           9 :     if(cpu_CAS(&skipStatus, VALID, BUSY))
     498             :     {
     499           9 :         const size_t ret = numSkipped;
     500           9 :         COMPILER_FENCE;
     501           9 :         skipStatus = INVALID;   // linearization point
     502           9 :         return ret;
     503             :     }
     504             :     else
     505             :     {
     506           0 :         DEBUG_WARN_ERR(ERR::REENTERED);
     507           0 :         return 0;
     508             :     }
     509             : }
     510             : 
     511          29 : static bool ShouldSkipError(Status err)
     512             : {
     513          29 :     if(cpu_CAS(&skipStatus, VALID, BUSY))
     514             :     {
     515          29 :         numSkipped++;
     516          29 :         const bool ret = (err == errorToSkip);
     517          29 :         COMPILER_FENCE;
     518          29 :         skipStatus = VALID;
     519          29 :         return ret;
     520             :     }
     521             :     return false;
     522             : }
     523             : 
     524          29 : ErrorReaction debug_OnError(Status err, atomic_bool* suppress, const wchar_t* file, int line, const char* func)
     525             : {
     526          29 :     CACHE_ALIGNED(u8) context[DEBUG_CONTEXT_SIZE];
     527          29 :     (void)debug_CaptureContext(context);
     528             : 
     529          29 :     if(ShouldSkipError(err))
     530             :         return ER_CONTINUE;
     531             : 
     532           0 :     const wchar_t* lastFuncToSkip = L"debug_OnError";
     533           0 :     wchar_t buf[400];
     534           0 :     wchar_t err_buf[200]; StatusDescription(err, err_buf, ARRAY_SIZE(err_buf));
     535           0 :     swprintf_s(buf, ARRAY_SIZE(buf), L"Function call failed: return value was %lld (%ls)", (long long)err, err_buf);
     536           0 :     return debug_DisplayError(buf, DE_MANUAL_BREAK, context, lastFuncToSkip, file,line,func, suppress);
     537             : }
     538             : 
     539           0 : ErrorReaction debug_OnAssertionFailure(const wchar_t* expr, atomic_bool* suppress, const wchar_t* file, int line, const char* func)
     540             : {
     541           0 :     CACHE_ALIGNED(u8) context[DEBUG_CONTEXT_SIZE];
     542           0 :     (void)debug_CaptureContext(context);
     543             : 
     544           0 :     const wchar_t* lastFuncToSkip = L"debug_OnAssertionFailure";
     545           0 :     wchar_t buf[400];
     546           0 :     swprintf_s(buf, ARRAY_SIZE(buf), L"Assertion failed: \"%ls\"", expr);
     547           0 :     return debug_DisplayError(buf, DE_MANUAL_BREAK, context, lastFuncToSkip, file,line,func, suppress);
     548             : }

Generated by: LCOV version 1.13