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 1 : 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 0 : 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 20 : bool debug_filter_allows(const char* text)
126 : {
127 : size_t i;
128 120 : for(i = 0; ; i++)
129 : {
130 : // no | found => no tag => should always be displayed
131 220 : if(text[i] == ' ' || text[i] == '\0')
132 0 : return true;
133 120 : if(text[i] == '|' && i != 0)
134 20 : break;
135 : }
136 :
137 20 : const u32 hash = fnv_hash(text, i*sizeof(text[0]));
138 :
139 : // check if entry allowing this tag is found
140 420 : for(i = 0; i < MAX_TAGS; i++)
141 400 : if(tags[i] == hash)
142 0 : return true;
143 :
144 20 : return false;
145 : }
146 :
147 : #undef debug_printf // allowing #defining it out
148 20 : void debug_printf(const char* fmt, ...)
149 : {
150 : char buf[16384];
151 :
152 : va_list ap;
153 20 : va_start(ap, fmt);
154 20 : const int numChars = vsprintf_s(buf, ARRAY_SIZE(buf), fmt, ap);
155 20 : if (numChars < 0)
156 0 : debug_break(); // poor man's assert - avoid infinite loop because ENSURE also uses debug_printf
157 20 : va_end(ap);
158 :
159 20 : debug_puts_filtered(buf);
160 20 : }
161 :
162 20 : void debug_puts_filtered(const char* text)
163 : {
164 20 : if(debug_filter_allows(text))
165 0 : debug_puts(text);
166 20 : }
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 : 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 : cassert(IDLE == 0);
185 : static volatile intptr_t state;
186 :
187 0 : if(!cpu_CAS(&state, IDLE, BUSY))
188 0 : 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 0 : PrintfWriter(wchar_t* buf, size_t maxChars)
223 0 : : m_pos(buf), m_charsLeft(maxChars)
224 : {
225 0 : }
226 :
227 0 : bool operator()(const wchar_t* fmt, ...) WPRINTF_ARGS(2)
228 : {
229 : 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 0 : 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 0 : 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 0 : goto fail;
327 :
328 0 : 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 0 : static bool ShouldSuppressError(atomic_bool* suppress)
355 : {
356 0 : if(isExiting)
357 0 : return true;
358 :
359 0 : if(!suppress)
360 0 : return false;
361 :
362 0 : if(*suppress == DEBUG_SUPPRESS)
363 0 : return true;
364 :
365 0 : 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 0 : case ERI_CONTINUE:
386 0 : 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 0 : 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 : 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 0 : 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 0 : 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 : CACHE_ALIGNED(u8) context[DEBUG_CONTEXT_SIZE];
527 29 : (void)debug_CaptureContext(context);
528 :
529 29 : if(ShouldSkipError(err))
530 29 : return ER_CONTINUE;
531 :
532 0 : const wchar_t* lastFuncToSkip = L"debug_OnError";
533 : 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 : CACHE_ALIGNED(u8) context[DEBUG_CONTEXT_SIZE];
542 0 : (void)debug_CaptureContext(context);
543 :
544 0 : const wchar_t* lastFuncToSkip = L"debug_OnAssertionFailure";
545 : 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 3 : }
|
