From 48e4c35fdce27ce2cb139f72374301f658276d0c Mon Sep 17 00:00:00 2001 From: Jonathan G Rennison Date: Tue, 16 Feb 2016 18:27:21 +0000 Subject: [PATCH 1/4] Add support for verbose asserts. Use for test/exec DoCommand mismatches. --- src/command.cpp | 37 ++++++++++++++++++++++++++++++++++++- src/command_type.h | 15 +++++++++++++++ src/openttd.cpp | 19 +++++++++++++++++++ src/stdafx.h | 4 ++++ 4 files changed, 74 insertions(+), 1 deletion(-) diff --git a/src/command.cpp b/src/command.cpp index 959610cd28..d72b55931d 100644 --- a/src/command.cpp +++ b/src/command.cpp @@ -26,6 +26,8 @@ #include "signal_func.h" #include "core/backup_type.hpp" #include "object_base.h" +#include "newgrf_text.h" +#include "string_func.h" #include "table/strings.h" @@ -735,7 +737,9 @@ CommandCost DoCommandPInternal(TileIndex tile, uint32 p1, uint32 p2, uint32 cmd, * test and execution have yielded the same result, * i.e. cost and error state are the same. */ if (!test_and_exec_can_differ) { - assert(res.GetCost() == res2.GetCost() && res.Failed() == res2.Failed()); // sanity check + assert_msg(res.GetCost() == res2.GetCost() && res.Failed() == res2.Failed(), + "Command: cmd: 0x%X (%s), Test: %s, Exec: %s", cmd, GetCommandName(cmd), + res.AllocSummaryMessage(GB(cmd, 16, 16)), res2.AllocSummaryMessage(GB(cmd, 16, 16))); // sanity check } else if (res2.Failed()) { return_dcpi(res2); } @@ -803,3 +807,34 @@ void CommandCost::UseTextRefStack(const GRFFile *grffile, uint num_registers) textref_stack[i] = _temp_store.GetValue(0x100 + i); } } + +char *CommandCost::AllocSummaryMessage(StringID cmd_msg) const +{ + char buf[DRAW_STRING_BUFFER]; + this->WriteSummaryMessage(buf, lastof(buf), cmd_msg); + return stredup(buf, lastof(buf)); +} + +int CommandCost::WriteSummaryMessage(char *buf, char *last, StringID cmd_msg) const +{ + if (this->Succeeded()) { + return seprintf(buf, last, "Success: cost: " OTTD_PRINTF64, (int64) this->GetCost()); + } else { + if (this->textref_stack_size > 0) StartTextRefStackUsage(this->textref_stack_grffile, this->textref_stack_size, textref_stack); + + char *b = buf; + b += seprintf(b, last, "Failed: cost: " OTTD_PRINTF64, (int64) this->GetCost()); + if (cmd_msg != 0) { + b += seprintf(b, last, " "); + b = GetString(b, cmd_msg, last); + } + if (this->message != INVALID_STRING_ID) { + b += seprintf(b, last, " "); + b = GetString(b, this->message, last); + } + + if (this->textref_stack_size > 0) StopTextRefStackUsage(); + + return b - buf; + } +} diff --git a/src/command_type.h b/src/command_type.h index f318216acc..1d39ee00a9 100644 --- a/src/command_type.h +++ b/src/command_type.h @@ -162,6 +162,21 @@ public: { return !this->success; } + + /** + * @param cmd_msg optional failure string as passed to DoCommand + * @return an allocated string summarising the command result + */ + char *AllocSummaryMessage(StringID cmd_msg = 0) const; + + /** + * Write a string summarising the command result + * @param buf buffer to write to + * @param last last byte in buffer + * @param cmd_msg optional failure string as passed to DoCommand + * @return the number of bytes written + */ + int WriteSummaryMessage(char *buf, char *last, StringID cmd_msg = 0) const; }; /** diff --git a/src/openttd.cpp b/src/openttd.cpp index c149ebbd4d..5e3d2a6c4c 100644 --- a/src/openttd.cpp +++ b/src/openttd.cpp @@ -123,6 +123,25 @@ void CDECL error(const char *s, ...) abort(); } +void CDECL assert_msg_error(int line, const char *file, const char *expr, const char *str, ...) +{ + va_list va; + char buf[2048]; + + char *b = buf; + b += seprintf(b, lastof(buf), "Assertion failed at line %i of %s: %s\n\t", line, file, expr); + + va_start(va, str); + vseprintf(b, lastof(buf), str, va); + va_end(va); + + ShowOSErrorBox(buf, true); + + /* Set the error message for the crash log and then invoke it. */ + CrashLog::SetErrorMessage(buf); + abort(); +} + /** * Shows some information on the console/a popup box depending on the OS. * @param str the text to show. diff --git a/src/stdafx.h b/src/stdafx.h index 4616212f18..78401402e5 100644 --- a/src/stdafx.h +++ b/src/stdafx.h @@ -446,6 +446,7 @@ assert_compile(SIZE_MAX >= UINT32_MAX); void NORETURN CDECL usererror(const char *str, ...) WARN_FORMAT(1, 2); void NORETURN CDECL error(const char *str, ...) WARN_FORMAT(1, 2); +void NORETURN CDECL assert_msg_error(int line, const char *file, const char *expr, const char *str, ...) WARN_FORMAT(4, 5); #define NOT_REACHED() error("NOT_REACHED triggered at line %i of %s", __LINE__, __FILE__) /* For non-debug builds with assertions enabled use the special assertion handler: @@ -460,6 +461,9 @@ void NORETURN CDECL error(const char *str, ...) WARN_FORMAT(1, 2); /* Asserts are enabled if NDEBUG isn't defined, or if we are using MSVC and WITH_ASSERT is defined. */ #if !defined(NDEBUG) || (defined(_MSC_VER) && defined(WITH_ASSERT)) #define OTTD_ASSERT + #define assert_msg(expression, ...) if (!(expression)) assert_msg_error(__LINE__, __FILE__, #expression, __VA_ARGS__); +#else + #define assert_msg(expression, ...) #endif #if defined(MORPHOS) || defined(__NDS__) || defined(__DJGPP__) From e89efa8581bd51e5e462074accfcebae5949a9ed Mon Sep 17 00:00:00 2001 From: Jonathan G Rennison Date: Tue, 16 Feb 2016 19:53:22 +0000 Subject: [PATCH 2/4] Add a function to test whether the current thread is the main thread. --- src/openttd.cpp | 2 ++ src/thread/thread.h | 10 ++++++++++ src/thread/thread_morphos.cpp | 4 ++++ src/thread/thread_none.cpp | 4 ++++ src/thread/thread_os2.cpp | 4 ++++ src/thread/thread_pthread.cpp | 12 ++++++++++++ src/thread/thread_win32.cpp | 12 ++++++++++++ 7 files changed, 48 insertions(+) diff --git a/src/openttd.cpp b/src/openttd.cpp index 5e3d2a6c4c..a6e6417243 100644 --- a/src/openttd.cpp +++ b/src/openttd.cpp @@ -63,6 +63,7 @@ #include "subsidy_func.h" #include "gfx_layout.h" #include "viewport_sprite_sorter.h" +#include "thread/thread.h" #include "linkgraph/linkgraphschedule.h" @@ -553,6 +554,7 @@ static const OptionData _options[] = { */ int openttd_main(int argc, char *argv[]) { + SetSelfAsMainThread(); char *musicdriver = NULL; char *sounddriver = NULL; char *videodriver = NULL; diff --git a/src/thread/thread.h b/src/thread/thread.h index b944a53b96..e660c1b2c7 100644 --- a/src/thread/thread.h +++ b/src/thread/thread.h @@ -122,4 +122,14 @@ private: */ uint GetCPUCoreCount(); +/** + * Set the current thread as the "main" thread + */ +void SetSelfAsMainThread(); + +/** + * @return true if the current thread definitely the "main" thread. If in doubt returns false. + */ +bool IsMainThread(); + #endif /* THREAD_H */ diff --git a/src/thread/thread_morphos.cpp b/src/thread/thread_morphos.cpp index cc6b2f9d3d..5fb45562ee 100644 --- a/src/thread/thread_morphos.cpp +++ b/src/thread/thread_morphos.cpp @@ -199,3 +199,7 @@ private: if (thread != NULL) *thread = to; return true; } + +void SetSelfAsMainThread() { } + +bool IsMainThread() { return false; } diff --git a/src/thread/thread_none.cpp b/src/thread/thread_none.cpp index afa799b239..6ba4b4f276 100644 --- a/src/thread/thread_none.cpp +++ b/src/thread/thread_none.cpp @@ -33,3 +33,7 @@ public: { return new ThreadMutex_None(); } + +void SetSelfAsMainThread() { } + +bool IsMainThread() { return true; } diff --git a/src/thread/thread_os2.cpp b/src/thread/thread_os2.cpp index 2dcb8288f4..8ec3104bf3 100644 --- a/src/thread/thread_os2.cpp +++ b/src/thread/thread_os2.cpp @@ -145,3 +145,7 @@ public: { return new ThreadMutex_OS2(); } + +void SetSelfAsMainThread() { } + +bool IsMainThread() { return false; } diff --git a/src/thread/thread_pthread.cpp b/src/thread/thread_pthread.cpp index ce407fd941..d98e26a341 100644 --- a/src/thread/thread_pthread.cpp +++ b/src/thread/thread_pthread.cpp @@ -172,3 +172,15 @@ public: { return new ThreadMutex_pthread(); } + +static pthread_t main_thread; + +void SetSelfAsMainThread() +{ + main_thread = pthread_self(); +} + +bool IsMainThread() +{ + return main_thread == pthread_self(); +} diff --git a/src/thread/thread_win32.cpp b/src/thread/thread_win32.cpp index c37baf7c36..ec0e45797f 100644 --- a/src/thread/thread_win32.cpp +++ b/src/thread/thread_win32.cpp @@ -158,3 +158,15 @@ public: { return new ThreadMutex_Win32(); } + +static uint main_thread_id; + +void SetSelfAsMainThread() +{ + main_thread_id = GetCurrentThreadId(); +} + +bool IsMainThread() +{ + return main_thread_id == GetCurrentThreadId(); +} From 5cf2b04f6a5973a6f556595ba07a004571fcd010 Mon Sep 17 00:00:00 2001 From: Jonathan G Rennison Date: Wed, 17 Feb 2016 19:45:07 +0000 Subject: [PATCH 3/4] Initial implementation of scope guard logging for including in crash logs. This adds a mechanism to create scope guards with an associated std::function which is called to output diagnostic info in the event of a crash. Add a macro to make it easy to efficiently capture variables on the stack and output a formatted message. Requires C++11, #ifdefed out for legacy compilers. --- source.list | 3 ++ src/crashlog.cpp | 9 ++++++ src/scope_info.cpp | 72 ++++++++++++++++++++++++++++++++++++++++++++++ src/scope_info.h | 58 +++++++++++++++++++++++++++++++++++++ src/stdafx.h | 6 ++++ 5 files changed, 148 insertions(+) create mode 100644 src/scope_info.cpp create mode 100644 src/scope_info.h diff --git a/source.list b/source.list index 2277a22139..456a71d374 100644 --- a/source.list +++ b/source.list @@ -1194,3 +1194,6 @@ thread/thread.h #else thread/thread_none.cpp #end + +scope_info.cpp +scope_info.h diff --git a/src/crashlog.cpp b/src/crashlog.cpp index 19a5898623..a0ec4d26fb 100644 --- a/src/crashlog.cpp +++ b/src/crashlog.cpp @@ -28,6 +28,8 @@ #include "network/network.h" #include "language.h" #include "fontcache.h" +#include "scope_info.h" +#include "thread/thread.h" #include "ai/ai_info.hpp" #include "game/game.hpp" @@ -327,6 +329,13 @@ char *CrashLog::FillCrashLog(char *buffer, const char *last) const buffer += seprintf(buffer, last, "In game date: %i-%02i-%02i (%i)\n\n", ymd.year, ymd.month + 1, ymd.day, _date_fract); buffer = this->LogError(buffer, last, CrashLog::message); + +#ifdef USE_SCOPE_INFO + if (IsMainThread()) { + buffer += WriteScopeLog(buffer, last); + } +#endif + buffer = this->LogOpenTTDVersion(buffer, last); buffer = this->LogRegisters(buffer, last); buffer = this->LogStacktrace(buffer, last); diff --git a/src/scope_info.cpp b/src/scope_info.cpp new file mode 100644 index 0000000000..7e5aa1cc23 --- /dev/null +++ b/src/scope_info.cpp @@ -0,0 +1,72 @@ +/* $Id$ */ + +/* + * This file is part of OpenTTD. + * OpenTTD is free software; you can redistribute it and/or modify it under the terms of the GNU General Public License as published by the Free Software Foundation, version 2. + * OpenTTD is distributed in the hope that it will be useful, but WITHOUT ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. + * See the GNU General Public License for more details. You should have received a copy of the GNU General Public License along with OpenTTD. If not, see . + */ + +/** @file scope_info.cpp Scope info debug functions. */ + +#include "stdafx.h" +#include "scope_info.h" +#include "string_func.h" +#include "strings_func.h" +#include "company_base.h" +#include "vehicle_base.h" +#include "table/strings.h" + +#include "safeguards.h" + +#ifdef USE_SCOPE_INFO + +std::vector> _scope_stack; + +int WriteScopeLog(char *buf, const char *last) +{ + char *b = buf; + if (!_scope_stack.empty()) { + b += seprintf(b, last, "Within context:"); + int depth = 0; + for (auto it = _scope_stack.rbegin(); it != _scope_stack.rend(); ++it, depth++) { + b += seprintf(b, last, "\n %2d: ", depth); + b += (*it)(b, last); + } + b += seprintf(b, last, "\n\n"); + } + return b - buf; +} + +// helper functions +char *DumpCompanyInfo(int company_id) +{ + char buf[256]; + char *b = buf + seprintf(buf, lastof(buf), "%d (", company_id); + SetDParam(0, company_id); + b = GetString(b, STR_COMPANY_NAME, lastof(buf)); + b += seprintf(b, lastof(buf), ")"); + return stredup(buf, lastof(buf)); +} + +char *DumpVehicleInfo(const Vehicle *v) +{ + char buf[256]; + char *b = buf; + if (v) { + b += seprintf(b, lastof(buf), "veh: %u: (", v->index); + SetDParam(0, v->index); + b = GetString(b, STR_VEHICLE_NAME, lastof(buf)); + if (v->First() && v->First() != v) { + b += seprintf(b, lastof(buf), "), front: %u: (", v->First()->index); + SetDParam(0, v->First()->index); + b = GetString(b, STR_VEHICLE_NAME, lastof(buf)); + } + b += seprintf(b, lastof(buf), ")"); + } else { + b += seprintf(b, lastof(buf), "veh: NULL"); + } + return stredup(buf, lastof(buf)); +} + +#endif diff --git a/src/scope_info.h b/src/scope_info.h new file mode 100644 index 0000000000..cb6cb18dd4 --- /dev/null +++ b/src/scope_info.h @@ -0,0 +1,58 @@ +/* $Id$ */ + +/* + * This file is part of OpenTTD. + * OpenTTD is free software; you can redistribute it and/or modify it under the terms of the GNU General Public License as published by the Free Software Foundation, version 2. + * OpenTTD is distributed in the hope that it will be useful, but WITHOUT ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. + * See the GNU General Public License for more details. You should have received a copy of the GNU General Public License along with OpenTTD. If not, see . + */ + +/** @file scope_info.h Scope info debug functions. */ + +#ifndef SCOPE_INFO_H +#define SCOPE_INFO_H + +#ifdef USE_SCOPE_INFO +#include +#include + +struct Vehicle; + +extern std::vector> _scope_stack; + +struct scope_info_func_obj { + scope_info_func_obj(std::function func) + { + _scope_stack.emplace_back(std::move(func)); + } + + scope_info_func_obj(const scope_info_func_obj ©src) = delete; + + ~scope_info_func_obj() + { + _scope_stack.pop_back(); + } +}; + +int WriteScopeLog(char *buf, const char *last); + +#define SCOPE_INFO_PASTE(a, b) a ## b + +/** + * This creates a lambda in the current scope with the specified capture which outputs the given args as a format string. + * This lambda is then captured by reference in a std::function which is pushed onto the scope stack + * The scope stack is popped at the end of the scope + */ +#define SCOPE_INFO_FMT(capture, ...) auto SCOPE_INFO_PASTE(_sc_lm_, __LINE__) = capture (char *buf, const char *last) { return seprintf(buf, last, __VA_ARGS__); }; scope_info_func_obj SCOPE_INFO_PASTE(_sc_obj_, __LINE__) ([&](char *buf, const char *last) -> int { return SCOPE_INFO_PASTE(_sc_lm_, __LINE__) (buf, last); }); + +// helper functions +char *DumpCompanyInfo(int company_id); +char *DumpVehicleInfo(const Vehicle *v); + +#else /* USE_SCOPE_INFO */ + +#define SCOPE_INFO_FMT(...) + +#endif /* USE_SCOPE_INFO */ + +#endif /* SCOPE_INFO_H */ diff --git a/src/stdafx.h b/src/stdafx.h index 78401402e5..cb99d244a8 100644 --- a/src/stdafx.h +++ b/src/stdafx.h @@ -520,4 +520,10 @@ static inline void free(const void *ptr) #define IGNORE_UNINITIALIZED_WARNING_STOP #endif +#if !defined(DISABLE_SCOPE_INFO) && (__cplusplus >= 201103L || defined(__STDCXX_VERSION__) || defined(__GXX_EXPERIMENTAL_CXX0X__) || defined(__GXX_EXPERIMENTAL_CPP0X__)) +#define USE_SCOPE_INFO +#endif + +#define SINGLE_ARG(...) __VA_ARGS__ + #endif /* STDAFX_H */ From ae6e43c5fade4ab4d0dbbfe86aa37750e3525d8c Mon Sep 17 00:00:00 2001 From: Jonathan G Rennison Date: Wed, 17 Feb 2016 19:45:24 +0000 Subject: [PATCH 4/4] Initial uses of scope guard logging. --- src/command.cpp | 5 +++++ src/vehicle.cpp | 10 ++++++++-- 2 files changed, 13 insertions(+), 2 deletions(-) diff --git a/src/command.cpp b/src/command.cpp index d72b55931d..b11306578d 100644 --- a/src/command.cpp +++ b/src/command.cpp @@ -28,6 +28,7 @@ #include "object_base.h" #include "newgrf_text.h" #include "string_func.h" +#include "scope_info.h" #include "table/strings.h" @@ -455,6 +456,8 @@ CommandCost DoCommand(const CommandContainer *container, DoCommandFlag flags) */ CommandCost DoCommand(TileIndex tile, uint32 p1, uint32 p2, DoCommandFlag flags, uint32 cmd, const char *text) { + SCOPE_INFO_FMT([=], "DoCommand: tile: %dx%d, p1: 0x%X, p2: 0x%X, flags: 0x%X, company: %s, cmd: 0x%X (%s)", TileX(tile), TileY(tile), p1, p2, flags, DumpCompanyInfo(_current_company), cmd, GetCommandName(cmd)); + CommandCost res; /* Do not even think about executing out-of-bounds tile-commands */ @@ -548,6 +551,8 @@ bool DoCommandP(const CommandContainer *container, bool my_cmd) */ bool DoCommandP(TileIndex tile, uint32 p1, uint32 p2, uint32 cmd, CommandCallback *callback, const char *text, bool my_cmd) { + SCOPE_INFO_FMT([=], "DoCommandP: tile: %dx%d, p1: 0x%X, p2: 0x%X, company: %s, cmd: 0x%X (%s), my_cmd: %d", TileX(tile), TileY(tile), p1, p2, DumpCompanyInfo(_current_company), cmd, GetCommandName(cmd), my_cmd); + /* Cost estimation is generally only done when the * local user presses shift while doing somthing. * However, in case of incoming network commands, diff --git a/src/vehicle.cpp b/src/vehicle.cpp index a482520f25..420761bb3d 100644 --- a/src/vehicle.cpp +++ b/src/vehicle.cpp @@ -52,6 +52,8 @@ #include "gamelog.h" #include "linkgraph/linkgraph.h" #include "linkgraph/refresh.h" +#include "string_func.h" +#include "scope_info.h" #include "table/strings.h" @@ -849,8 +851,10 @@ static void RunVehicleDayProc() if (_game_mode != GM_NORMAL) return; /* Run the day_proc for every DAY_TICKS vehicle starting at _date_fract. */ + Vehicle *v = NULL; + SCOPE_INFO_FMT([&v], "RunVehicleDayProc: %s", DumpVehicleInfo(v)); for (size_t i = _date_fract; i < Vehicle::GetPoolSize(); i += DAY_TICKS) { - Vehicle *v = Vehicle::Get(i); + v = Vehicle::Get(i); if (v == NULL) continue; /* Call the 32-day callback if needed */ @@ -883,7 +887,8 @@ void CallVehicleTicks() Station *st; FOR_ALL_STATIONS(st) LoadUnloadStation(st); - Vehicle *v; + Vehicle *v = NULL; + SCOPE_INFO_FMT([&v], "CallVehicleTicks: %s", DumpVehicleInfo(v)); FOR_ALL_VEHICLES(v) { /* Vehicle could be deleted in this tick */ if (!v->Tick()) { @@ -952,6 +957,7 @@ void CallVehicleTicks() } } } + v = NULL; Backup cur_company(_current_company, FILE_LINE); for (AutoreplaceMap::iterator it = _vehicles_to_autoreplace.Begin(); it != _vehicles_to_autoreplace.End(); it++) {