diff --git a/src/logging.h b/src/logging.h index 2906a1c157..2e2bf53e25 100644 --- a/src/logging.h +++ b/src/logging.h @@ -1,191 +1,168 @@ // Copyright (c) 2009-2010 Satoshi Nakamoto // Copyright (c) 2009-2016 The Bitcoin Core developers // Copyright (c) 2017-2018 The Bitcoin developers // Distributed under the MIT software license, see the accompanying // file COPYING or http://www.opensource.org/licenses/mit-license.php. #ifndef BITCOIN_LOGGING_H #define BITCOIN_LOGGING_H #include #include #include #include #include #include #include static const bool DEFAULT_LOGTIMEMICROS = false; static const bool DEFAULT_LOGIPS = false; static const bool DEFAULT_LOGTIMESTAMPS = true; extern bool fLogIPs; extern const char *const DEFAULT_DEBUGLOGFILE; struct CLogCategoryActive { std::string category; bool active; }; namespace BCLog { enum LogFlags : uint32_t { NONE = 0, NET = (1 << 0), TOR = (1 << 1), MEMPOOL = (1 << 2), HTTP = (1 << 3), BENCH = (1 << 4), ZMQ = (1 << 5), DB = (1 << 6), RPC = (1 << 7), ESTIMATEFEE = (1 << 8), ADDRMAN = (1 << 9), SELECTCOINS = (1 << 10), REINDEX = (1 << 11), CMPCTBLOCK = (1 << 12), RAND = (1 << 13), PRUNE = (1 << 14), PROXY = (1 << 15), MEMPOOLREJ = (1 << 16), LIBEVENT = (1 << 17), COINDB = (1 << 18), QT = (1 << 19), LEVELDB = (1 << 20), ALL = ~uint32_t(0), }; class Logger { private: FILE *m_fileout = nullptr; std::mutex m_file_mutex; std::list m_msgs_before_open; /** * m_started_new_line is a state variable that will suppress printing of the * timestamp when multiple calls are made that don't end in a newline. */ std::atomic_bool m_started_new_line{true}; /** * Log categories bitfield. */ std::atomic m_categories{0}; std::string LogTimestampStr(const std::string &str); public: bool m_print_to_console = false; bool m_print_to_file = false; bool m_log_timestamps = DEFAULT_LOGTIMESTAMPS; bool m_log_time_micros = DEFAULT_LOGTIMEMICROS; fs::path m_file_path; std::atomic m_reopen_file{false}; ~Logger(); /** Send a string to the log output */ void LogPrintStr(const std::string &str); /** Returns whether logs will be written to any output */ bool Enabled() const { return m_print_to_console || m_print_to_file; } bool OpenDebugLog(); void ShrinkDebugFile(); uint32_t GetCategoryMask() const { return m_categories.load(); } void EnableCategory(LogFlags category); bool EnableCategory(const std::string &str); void DisableCategory(LogFlags category); bool DisableCategory(const std::string &str); /** Return true if log accepts specified category */ bool WillLogCategory(LogFlags category) const; /** Default for whether ShrinkDebugFile should be run */ bool DefaultShrinkDebugFile() const; }; } // namespace BCLog BCLog::Logger &LogInstance(); /** Return true if log accepts specified category */ static inline bool LogAcceptCategory(BCLog::LogFlags category) { return LogInstance().WillLogCategory(category); } /** Returns a string with the log categories. */ std::string ListLogCategories(); /** Returns a vector of the active log categories. */ std::vector ListActiveLogCategories(); /** Return true if str parses as a log category and set the flag */ bool GetLogCategory(BCLog::LogFlags &flag, const std::string &str); // Be conservative when using LogPrintf/error or other things which // unconditionally log to debug.log! It should not be the case that an inbound // peer can fill up a user's disk with debug.log entries. - -static inline void MarkUsed() {} -template -static inline void MarkUsed(const T &t, const Args &... args) { - (void)t; - MarkUsed(args...); -} template -std::string FormatStringFromLogArgs(const char *fmt, const Args &... args) { - return fmt; +static inline void LogPrintf(const char *fmt, const Args &... args) { + if (LogInstance().Enabled()) { + std::string log_msg; + try { + log_msg = tfm::format(fmt, args...); + } catch (tinyformat::format_error &fmterr) { + /** + * Original format string will have newline so don't add one here + */ + log_msg = "Error \"" + std::string(fmterr.what()) + + "\" while formatting log message: " + fmt; + } + LogInstance().LogPrintStr(log_msg); + } } -#ifdef USE_COVERAGE -#define LogPrintf(...) \ - do { \ - MarkUsed(__VA_ARGS__); \ - } while (0) -#define LogPrint(category, ...) \ - do { \ - MarkUsed(__VA_ARGS__); \ - } while (0) -#else -#define LogPrintf(...) \ - do { \ - if (LogInstance().Enabled()) { \ - /* Unlikely name to avoid shadowing variables */ \ - std::string _log_msg_; \ - try { \ - _log_msg_ = tfm::format(__VA_ARGS__); \ - } catch (tinyformat::format_error & fmterr) { \ - /** \ - * Original format string will have newline so don't add one \ - * here \ - */ \ - _log_msg_ = "Error \"" + std::string(fmterr.what()) + \ - "\" while formatting log message: " + \ - FormatStringFromLogArgs(__VA_ARGS__); \ - } \ - LogInstance().LogPrintStr(_log_msg_); \ - } \ - } while (0) +// Use a macro instead of a function for conditional logging to prevent +// evaluating arguments when logging for the category is not enabled. #define LogPrint(category, ...) \ do { \ if (LogAcceptCategory((category))) { \ LogPrintf(__VA_ARGS__); \ } \ } while (0) -#endif /** * These are aliases used to explicitly state that the message should not end * with a newline character. It allows for detecting the missing newlines that * could make the logs hard to read. */ #define LogPrintfToBeContinued LogPrintf #define LogPrintToBeContinued LogPrint #endif // BITCOIN_LOGGING_H diff --git a/test/lint/lint-format-strings.py b/test/lint/lint-format-strings.py index 46ed32fa93..46fc8dfaff 100755 --- a/test/lint/lint-format-strings.py +++ b/test/lint/lint-format-strings.py @@ -1,291 +1,292 @@ #!/usr/bin/env python3 # # Copyright (c) 2018-2019 The Bitcoin Core developers # Distributed under the MIT software license, see the accompanying # file COPYING or http://www.opensource.org/licenses/mit-license.php. # # Lint format strings: This program checks that the number of arguments passed # to a variadic format string function matches the number of format specifiers # in the format string. import argparse import doctest import re import sys FALSE_POSITIVES = [ ("src/dbwrapper.cpp", "vsnprintf(p, limit - p, format, backup_ap)"), ("src/index/base.cpp", "FatalError(const char *fmt, const Args &... args)"), ("src/netbase.cpp", "LogConnectFailure(bool manual_connection, const char *fmt, const Args &... args)"), ("src/util/system.cpp", "strprintf(_(COPYRIGHT_HOLDERS), _(COPYRIGHT_HOLDERS_SUBSTITUTION))"), ("src/seeder/main.cpp", "fprintf(stderr, help, argv[0])"), ("src/tinyformat.h", "printf(const char *fmt, const Args &... args)"), ("src/tinyformat.h", "printf(const char *fmt, TINYFORMAT_VARARGS(n))"), ("src/wallet/wallet.h", "LogPrintf((\"%s \" + fmt).c_str(), GetDisplayName(), parameters...)"), + ("src/logging.h", "LogPrintf(const char *fmt, const Args &... args)"), ] FUNCTION_NAMES_AND_NUMBER_OF_LEADING_ARGUMENTS = [ ("FatalError", 0), ("fprintf", 1), ("LogConnectFailure", 1), ("LogPrint", 1), ("LogPrintf", 0), ("printf", 0), ("snprintf", 2), ("sprintf", 1), ("strprintf", 0), ("vfprintf", 1), ("vprintf", 1), ("vsnprintf", 1), ("vsprintf", 1), ] def parse_function_calls(function_name, source_code): """Return an array with all calls to function function_name in string source_code. Preprocessor directives and C++ style comments ("//") in source_code are removed. >>> len(parse_function_calls("foo", "foo();bar();foo();bar();")) 2 >>> parse_function_calls("foo", "foo(1);bar(1);foo(2);bar(2);")[0].startswith("foo(1);") True >>> parse_function_calls("foo", "foo(1);bar(1);foo(2);bar(2);")[1].startswith("foo(2);") True >>> len(parse_function_calls("foo", "foo();bar();// foo();bar();")) 1 >>> len(parse_function_calls("foo", "#define FOO foo();")) 0 """ assert type(function_name) is str and type( source_code) is str and function_name lines = [re.sub("// .*", " ", line).strip() for line in source_code.split("\n") if not line.strip().startswith("#")] return re.findall(r"[^a-zA-Z_](?=({}\(.*).*)".format(function_name), " " + " ".join(lines)) def normalize(s): """Return a normalized version of string s with newlines, tabs and C style comments ("/* ... */") replaced with spaces. Multiple spaces are replaced with a single space. >>> normalize(" /* nothing */ foo\tfoo /* bar */ foo ") 'foo foo foo' """ assert type(s) is str s = s.replace("\n", " ") s = s.replace("\t", " ") s = re.sub(r"/\*.*?\*/", " ", s) s = re.sub(" {2,}", " ", s) return s.strip() ESCAPE_MAP = { r"\n": "[escaped-newline]", r"\t": "[escaped-tab]", r'\"': "[escaped-quote]", } def escape(s): """Return the escaped version of string s with "\\\"", "\\n" and "\\t" escaped as "[escaped-backslash]", "[escaped-newline]" and "[escaped-tab]". >>> unescape(escape("foo")) == "foo" True >>> escape(r'foo \\t foo \\n foo \\\\ foo \\ foo \\"bar\\"') 'foo [escaped-tab] foo [escaped-newline] foo \\\\\\\\ foo \\\\ foo [escaped-quote]bar[escaped-quote]' """ assert type(s) is str for raw_value, escaped_value in ESCAPE_MAP.items(): s = s.replace(raw_value, escaped_value) return s def unescape(s): """Return the unescaped version of escaped string s. Reverses the replacements made in function escape(s). >>> unescape(escape("bar")) 'bar' >>> unescape("foo [escaped-tab] foo [escaped-newline] foo \\\\\\\\ foo \\\\ foo [escaped-quote]bar[escaped-quote]") 'foo \\\\t foo \\\\n foo \\\\\\\\ foo \\\\ foo \\\\"bar\\\\"' """ assert type(s) is str for raw_value, escaped_value in ESCAPE_MAP.items(): s = s.replace(escaped_value, raw_value) return s def parse_function_call_and_arguments(function_name, function_call): """Split string function_call into an array of strings consisting of: * the string function_call followed by "(" * the function call argument #1 * ... * the function call argument #n * a trailing ");" The strings returned are in escaped form. See escape(...). >>> parse_function_call_and_arguments("foo", 'foo("%s", "foo");') ['foo(', '"%s",', ' "foo"', ')'] >>> parse_function_call_and_arguments("foo", 'foo("%s", "foo");') ['foo(', '"%s",', ' "foo"', ')'] >>> parse_function_call_and_arguments("foo", 'foo("%s %s", "foo", "bar");') ['foo(', '"%s %s",', ' "foo",', ' "bar"', ')'] >>> parse_function_call_and_arguments("fooprintf", 'fooprintf("%050d", i);') ['fooprintf(', '"%050d",', ' i', ')'] >>> parse_function_call_and_arguments("foo", 'foo(bar(foobar(barfoo("foo"))), foobar); barfoo') ['foo(', 'bar(foobar(barfoo("foo"))),', ' foobar', ')'] >>> parse_function_call_and_arguments("foo", "foo()") ['foo(', '', ')'] >>> parse_function_call_and_arguments("foo", "foo(123)") ['foo(', '123', ')'] >>> parse_function_call_and_arguments("foo", 'foo("foo")') ['foo(', '"foo"', ')'] """ assert type(function_name) is str and type( function_call) is str and function_name remaining = normalize(escape(function_call)) expected_function_call = "{}(".format(function_name) assert remaining.startswith(expected_function_call) parts = [expected_function_call] remaining = remaining[len(expected_function_call):] open_parentheses = 1 in_string = False parts.append("") for char in remaining: parts.append(parts.pop() + char) if char == "\"": in_string = not in_string continue if in_string: continue if char == "(": open_parentheses += 1 continue if char == ")": open_parentheses -= 1 if open_parentheses > 1: continue if open_parentheses == 0: parts.append(parts.pop()[:-1]) parts.append(char) break if char == ",": parts.append("") return parts def parse_string_content(argument): """Return the text within quotes in string argument. >>> parse_string_content('1 "foo %d bar" 2') 'foo %d bar' >>> parse_string_content('1 foobar 2') '' >>> parse_string_content('1 "bar" 2') 'bar' >>> parse_string_content('1 "foo" 2 "bar" 3') 'foobar' >>> parse_string_content('1 "foo" 2 " " "bar" 3') 'foo bar' >>> parse_string_content('""') '' >>> parse_string_content('') '' >>> parse_string_content('1 2 3') '' """ assert type(argument) is str string_content = "" in_string = False for char in normalize(escape(argument)): if char == "\"": in_string = not in_string elif in_string: string_content += char return string_content def count_format_specifiers(format_string): """Return the number of format specifiers in string format_string. >>> count_format_specifiers("foo bar foo") 0 >>> count_format_specifiers("foo %d bar foo") 1 >>> count_format_specifiers("foo %d bar %i foo") 2 >>> count_format_specifiers("foo %d bar %i foo %% foo") 2 >>> count_format_specifiers("foo %d bar %i foo %% foo %d foo") 3 >>> count_format_specifiers("foo %d bar %i foo %% foo %*d foo") 4 """ assert type(format_string) is str n = 0 in_specifier = False for i, char in enumerate(format_string): if format_string[i - 1:i + 1] == "%%" or format_string[i:i + 2] == "%%": pass elif char == "%": in_specifier = True n += 1 elif char in "aAcdeEfFgGinopsuxX": in_specifier = False elif in_specifier and char == "*": n += 1 return n def main(args_in): """ Return a string output with information on string format errors >>> main(["test/lint/lint-format-strings-tests.txt"]) test/lint/lint-format-strings-tests.txt: Expected 1 argument(s) after format string but found 2 argument(s): printf("%d", 1, 2) test/lint/lint-format-strings-tests.txt: Expected 2 argument(s) after format string but found 3 argument(s): printf("%a %b", 1, 2, "anything") test/lint/lint-format-strings-tests.txt: Expected 1 argument(s) after format string but found 0 argument(s): printf("%d") test/lint/lint-format-strings-tests.txt: Expected 3 argument(s) after format string but found 2 argument(s): printf("%a%b%z", 1, "anything") >>> main(["test/lint/lint-format-strings-tests-skip-arguments.txt"]) test/lint/lint-format-strings-tests-skip-arguments.txt: Expected 1 argument(s) after format string but found 2 argument(s): fprintf(skipped, "%d", 1, 2) test/lint/lint-format-strings-tests-skip-arguments.txt: Expected 1 argument(s) after format string but found 0 argument(s): fprintf(skipped, "%d") test/lint/lint-format-strings-tests-skip-arguments.txt: Expected 1 argument(s) after format string but found 2 argument(s): snprintf(skip1, skip2, "%d", 1, 2) test/lint/lint-format-strings-tests-skip-arguments.txt: Expected 1 argument(s) after format string but found 0 argument(s): snprintf(skip1, skip2, "%d") test/lint/lint-format-strings-tests-skip-arguments.txt: Could not parse function call string "snprintf(...)": snprintf(skip1, "%d") """ parser = argparse.ArgumentParser(description="This program checks that the number of arguments passed " "to a variadic format string function matches the number of format " "specifiers in the format string.") parser.add_argument("file", type=argparse.FileType( "r", encoding="utf-8"), nargs="*", help="C++ source code file (e.g. foo.cpp)") args = parser.parse_args(args_in) for f in args.file: file_content = f.read() for (function_name, skip_arguments) in FUNCTION_NAMES_AND_NUMBER_OF_LEADING_ARGUMENTS: for function_call_str in parse_function_calls(function_name, file_content): parts = parse_function_call_and_arguments( function_name, function_call_str) relevant_function_call_str = unescape("".join(parts))[:512] if (f.name, relevant_function_call_str) in FALSE_POSITIVES: continue if len(parts) < 3 + skip_arguments: print("{}: Could not parse function call string \"{}(...)\": {}".format( f.name, function_name, relevant_function_call_str)) continue argument_count = len(parts) - 3 - skip_arguments format_str = parse_string_content(parts[1 + skip_arguments]) format_specifier_count = count_format_specifiers(format_str) if format_specifier_count != argument_count: print("{}: Expected {} argument(s) after format string but found {} argument(s): {}".format( f.name, format_specifier_count, argument_count, relevant_function_call_str)) continue if __name__ == "__main__": doctest.testmod() main(sys.argv[1:])