diff --git a/Changelog.md b/Changelog.md index a001dcc9b613..d9f0838a7a0a 100644 --- a/Changelog.md +++ b/Changelog.md @@ -3,6 +3,8 @@ Language Features: Compiler Features: +* Commandline Interface: Add logging options `--log-level`, `--log` and `--log-output` to set the global default level, specific logger level and the output. +* Logging: Introduce runtime switchable logging functionality to the compiler. Loggers are declared at call sites with `DEFINE_LOGGER` and used via the `solTrace`/`solDebug`/`solWarn` macros. Bugfixes: diff --git a/libsolutil/CMakeLists.txt b/libsolutil/CMakeLists.txt index 0e3098ea4942..16c11565e033 100644 --- a/libsolutil/CMakeLists.txt +++ b/libsolutil/CMakeLists.txt @@ -23,6 +23,8 @@ set(sources Keccak256.h LazyInit.h LEB128.h + Logger.cpp + Logger.h Numeric.cpp Numeric.h picosha2.h diff --git a/libsolutil/Logger.cpp b/libsolutil/Logger.cpp new file mode 100644 index 000000000000..f5dc01c19795 --- /dev/null +++ b/libsolutil/Logger.cpp @@ -0,0 +1,141 @@ +/* + This file is part of solidity. + + solidity 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, either version 3 of the License, or + (at your option) any later version. + + solidity 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 solidity. If not, see . +*/ +// SPDX-License-Identifier: GPL-3.0 + +#include + +#include + +using namespace solidity::log; + +namespace solidity::log +{ + +/// Cached logger handle owned by the registry. +/// Responsible for state changes (level) of the logger and its hierarchy. +struct LoggerHandle +{ + LoggerHandle(std::string _category, Level _level): + category(std::move(_category)), + effectiveLevel(_level), + logger(&effectiveLevel, category) + {} + + std::string category; + Level effectiveLevel; + Logger logger; +}; + +} + +std::string_view solidity::log::levelToString(Level _level) noexcept +{ + switch (_level) + { + case Level::trace: return "trace"; + case Level::debug: return "debug"; + case Level::warn: return "warn"; + case Level::off: return "off"; + } + return "off"; +} + +std::optional solidity::log::levelFromString(std::string_view _name) +{ + if (_name == "trace") return Level::trace; + if (_name == "debug") return Level::debug; + if (_name == "warn") return Level::warn; + if (_name == "off") return Level::off; + return std::nullopt; +} + +LoggerRegistry& LoggerRegistry::singleton() +{ + static LoggerRegistry registry; + return registry; +} + +LoggerRegistry::LoggerRegistry(): + m_stream(&std::cerr) +{ +} + +LoggerRegistry::~LoggerRegistry() = default; + +Logger const& LoggerRegistry::get(std::string_view _category) +{ + std::string category{_category}; + if (auto const loggerHandle = m_loggers.find(category); loggerHandle != m_loggers.end()) + return loggerHandle->second->logger; + + Level const effectiveLevel = computeEffectiveLevel(category); + auto [newLoggerHandle, _] = m_loggers.emplace(category, std::make_unique(category, effectiveLevel)); + return newLoggerHandle->second->logger; +} + +void LoggerRegistry::setLevel(std::string_view _prefix, Level _level) +{ + m_effectiveLevels[std::string(_prefix)] = _level; + + for (auto& [category, loggerHandle]: m_loggers) + loggerHandle->effectiveLevel = computeEffectiveLevel(loggerHandle->category); +} + +void LoggerRegistry::setOutput(std::ostream& _stream) +{ + m_stream = &_stream; +} + +void LoggerRegistry::reset() +{ + m_effectiveLevels.clear(); + for (auto& [category, loggerHandle]: m_loggers) + loggerHandle->effectiveLevel = Level::off; + m_stream = &std::cerr; +} + +Level LoggerRegistry::computeEffectiveLevel(std::string_view _category) const +{ + // Search for effective level, either defined for the category itself or for its closest ancestor + std::string key(_category); + while (true) + { + if (auto const it = m_effectiveLevels.find(key); it != m_effectiveLevels.end()) + return it->second; + + auto const dot = key.rfind('.'); + if (dot == std::string::npos) + break; + key.resize(dot); + } + + // Global level + if (auto const it = m_effectiveLevels.find(""); it != m_effectiveLevels.end()) + return it->second; + + return Level::off; +} + +void LoggerRegistry::write(Level _level, std::string_view _category, std::string const& _message) +{ + (*m_stream) << '[' << levelToString(_level) << ' ' << _category << "] " << _message << '\n'; +} + +void Logger::emitFormatted(Level _level, std::string _message) const +{ + LoggerRegistry::singleton().write(_level, m_category, _message); +} diff --git a/libsolutil/Logger.h b/libsolutil/Logger.h new file mode 100644 index 000000000000..9c85ab116ff4 --- /dev/null +++ b/libsolutil/Logger.h @@ -0,0 +1,151 @@ +/* + This file is part of solidity. + + solidity 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, either version 3 of the License, or + (at your option) any later version. + + solidity 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 solidity. If not, see . +*/ +// SPDX-License-Identifier: GPL-3.0 + +/** + * Runtime switchable, hierarchical logging for the compiler. + * Loggers are named hierarchically with '.' separators, e.g. "yul.ssa.stacklayout", and are obtained lazily from LoggerRegistry. + * Every logger starts at Level::off unless there is a parent logger of different severity. + * Use DEFINE_LOGGER once and the solTrace/solDebug/solWarn macros at the call sites. + */ +#pragma once + +#include + +#include +#include +#include +#include +#include +#include +#include +#include +#include + +namespace solidity::log +{ + +/// Severity levels ordered from highest to lowest verbosity. +enum class Level: std::uint8_t +{ + trace = 0, + debug = 1, + warn = 2, + off = 3 +}; + +std::string_view levelToString(Level _level) noexcept; + +std::optional levelFromString(std::string_view _name); + +struct LoggerHandle; + +class Logger +{ +public: + bool shouldLog(Level _requested) const noexcept { return *m_level <= _requested; } + + template + void trace(fmt::format_string _format, Args&&... _args) const + { + emit(Level::trace, _format, std::forward(_args)...); + } + + template + void debug(fmt::format_string _format, Args&&... _args) const + { + emit(Level::debug, _format, std::forward(_args)...); + } + + template + void warn(fmt::format_string _format, Args&&... _args) const + { + emit(Level::warn, _format, std::forward(_args)...); + } + +private: + friend struct LoggerHandle; + + Logger() noexcept = default; + Logger(Level const* _level, std::string_view _category) noexcept: m_level(_level), m_category(_category) {} + + template + void emit(Level _level, fmt::format_string _format, Args&&... _args) const + { + emitFormatted(_level, fmt::format(_format, std::forward(_args)...)); + } + + void emitFormatted(Level _level, std::string _message) const; + + /// Points to the effective level stored in the LoggerHandle cached by the registry + Level const* m_level = nullptr; + std::string_view m_category; +}; + + /// Process-wide singleton Registry of loggers +class LoggerRegistry +{ +public: + static LoggerRegistry& singleton(); + + /// Returns the logger if it exists already. + /// Otherwise, creates it before returning. + Logger const& get(std::string_view _category); + + /// Sets the level for all logs with _prefix. + void setLevel(std::string_view _prefix, Level _level); + + void setOutput(std::ostream& _stream); + + void reset(); + +private: + LoggerRegistry(); + ~LoggerRegistry(); + + /// Returns the level set for the category. + /// If there is no effective level set specifically for the category, searches for the closest + /// ancestor in the hierarchy which has a level set. + /// Returns Level::off in case nothing is found. + Level computeEffectiveLevel(std::string_view _category) const; + + /// Writes a line prefixed with "[ ]" + void write(Level _level, std::string_view _category, std::string const& _message); + + friend class Logger; + + std::map m_effectiveLevels; + std::unordered_map> m_loggers; + std::ostream* m_stream; +}; + +} + +/// Defines a file logger handle bound once to dottedCategory. +/// Subsequent uses are a single reference load. +#define DEFINE_LOGGER(variableName, dottedCategory) \ + static ::solidity::log::Logger const& variableName = \ + ::solidity::log::LoggerRegistry::singleton().get(dottedCategory) + +#define solLog(logger, lvl, ...) \ + do { if ((logger).shouldLog(::solidity::log::Level::lvl)) [[unlikely]] \ + (logger).lvl(__VA_ARGS__); \ + } while (0) + +#define solTrace(logger, ...) solLog((logger), trace, __VA_ARGS__) +#define solDebug(logger, ...) solLog((logger), debug, __VA_ARGS__) +#define solWarn(logger, ...) solLog((logger), warn, __VA_ARGS__) diff --git a/solc/CommandLineInterface.cpp b/solc/CommandLineInterface.cpp index fe28b287c6db..b07a7808371c 100644 --- a/solc/CommandLineInterface.cpp +++ b/solc/CommandLineInterface.cpp @@ -824,9 +824,27 @@ bool CommandLineInterface::parseArguments(int _argc, char const* const* _argv) } m_options = parser.options(); + applyLoggingOptions(); + return true; } +void CommandLineInterface::applyLoggingOptions() +{ + auto& registry = log::LoggerRegistry::singleton(); + + // Pass false so that merely configuring logging does not mark the CLI as having produced output. + registry.setOutput(m_options.logging.toStdout ? sout(false) : serr(false)); + + // Apply the global default first, then the per-category overrides in order, so that the + // overrides supersede --log-level and later occurrences win. + if (m_options.logging.globalLevel) + registry.setLevel("", *m_options.logging.globalLevel); + + for (auto const& [prefix, level]: m_options.logging.categoryLevels) + registry.setLevel(prefix, level); +} + void CommandLineInterface::processInput() { if (m_options.output.evmVersion < EVMVersion::constantinople()) diff --git a/solc/CommandLineInterface.h b/solc/CommandLineInterface.h index e61bf359f48a..1561a901a2a9 100644 --- a/solc/CommandLineInterface.h +++ b/solc/CommandLineInterface.h @@ -83,6 +83,9 @@ class CommandLineInterface std::optional const& standardJsonInput() const { return m_standardJsonInput; } private: + /// Applies the parsed logging options to the process-wide LoggerRegistry. Called once after + /// argument parsing, before any compilation work begins. + void applyLoggingOptions(); void printVersion(); void printLicense(); void compile(); diff --git a/solc/CommandLineParser.cpp b/solc/CommandLineParser.cpp index 7e5acc540c5f..8850e4f4ce10 100644 --- a/solc/CommandLineParser.cpp +++ b/solc/CommandLineParser.cpp @@ -64,6 +64,11 @@ static std::string const g_strLicense = "license"; static std::string const g_strLibraries = "libraries"; static std::string const g_strLink = "link"; static std::string const g_strLSP = "lsp"; +static std::string const g_strLogLevel = "log-level"; +static std::string const g_strLog = "log"; +static std::string const g_strLogOutput = "log-output"; +static std::string const g_strLogOutputStderr = "stderr"; +static std::string const g_strLogOutputStdout = "stdout"; static std::string const g_strMachine = "machine"; static std::string const g_strNoCBORMetadata = "no-cbor-metadata"; static std::string const g_strMetadataHash = "metadata-hash"; @@ -657,6 +662,28 @@ General Information)").c_str(), ; desc.add(outputOptions); + po::options_description loggingOptions("Logging Options"); + loggingOptions.add_options() + ( + g_strLogLevel.c_str(), + po::value()->value_name("trace|debug|warn|off"), + "Set the global default log level. Loggers default to 'off'." + ) + ( + g_strLog.c_str(), + po::value>()->value_name("=[,...]"), + ("Per-category log level overrides. The level applies to the given dot-separated category " + "prefix and all its descendants; the most specific prefix wins. Can be given multiple " + "times and supersedes --" + g_strLogLevel + ".").c_str() + ) + ( + g_strLogOutput.c_str(), + po::value()->value_name(g_strLogOutputStderr + "|" + g_strLogOutputStdout)->default_value(g_strLogOutputStderr), + "Where log output is written. Default: stderr." + ) + ; + desc.add(loggingOptions); + po::options_description alternativeInputModes("Alternative Input Modes"); alternativeInputModes.add_options() ( @@ -1184,6 +1211,55 @@ void CommandLineParser::processArgs() m_options.output.revertStrings = *revertStrings; } + if (m_args.count(g_strLogLevel)) + { + std::string const levelString = m_args[g_strLogLevel].as(); + std::optional const level = log::levelFromString(levelString); + if (!level) + solThrow(CommandLineValidationError, "Invalid option for --" + g_strLogLevel + ": " + levelString); + m_options.logging.globalLevel = *level; + } + + if (m_args.count(g_strLog)) + { + for (std::string const& specs: m_args[g_strLog].as>()) + { + std::vector splitSpecs; + for (std::string const& spec: boost::split(splitSpecs, specs, boost::is_any_of(","))) + { + if (spec.empty()) + continue; + + auto const separator = spec.find('='); + if (separator == std::string::npos) + solThrow( + CommandLineValidationError, + "Invalid log spec '" + spec + "' for --" + g_strLog + ". Expected =." + ); + + std::string const prefix = spec.substr(0, separator); + std::string const levelString = spec.substr(separator + 1); + std::optional const level = log::levelFromString(levelString); + if (!level) + solThrow( + CommandLineValidationError, + "Invalid log level '" + levelString + "' in --" + g_strLog + " spec '" + spec + "'." + ); + m_options.logging.categoryLevels.emplace_back(prefix, *level); + } + } + } + + { + std::string const logOutput = m_args[g_strLogOutput].as(); + if (logOutput == g_strLogOutputStdout) + m_options.logging.toStdout = true; + else if (logOutput == g_strLogOutputStderr) + m_options.logging.toStdout = false; + else + solThrow(CommandLineValidationError, "Invalid option for --" + g_strLogOutput + ": " + logOutput); + } + if (!m_args[g_strDebugInfo].defaulted()) { std::string optionValue = m_args[g_strDebugInfo].as(); diff --git a/solc/CommandLineParser.h b/solc/CommandLineParser.h index 99dc7c8dd1e5..4d1c7931f2c3 100644 --- a/solc/CommandLineParser.h +++ b/solc/CommandLineParser.h @@ -32,6 +32,7 @@ #include #include +#include #include #include @@ -42,6 +43,7 @@ #include #include #include +#include #include namespace solidity::frontend @@ -277,6 +279,16 @@ struct CommandLineOptions ModelCheckerSettings settings; } modelChecker; + struct Logging + { + bool operator==(Logging const&) const noexcept = default; + bool operator!=(Logging const&) const noexcept = default; + + std::optional globalLevel; + std::vector> categoryLevels; + bool toStdout = false; + } logging; + bool experimental = false; }; diff --git a/test/CMakeLists.txt b/test/CMakeLists.txt index 750673756210..722179730817 100644 --- a/test/CMakeLists.txt +++ b/test/CMakeLists.txt @@ -41,6 +41,7 @@ set(libsolutil_sources libsolutil/Keccak256.cpp libsolutil/LazyInit.cpp libsolutil/LEB128.cpp + libsolutil/Logger.cpp libsolutil/StringUtils.cpp libsolutil/SwarmHash.cpp libsolutil/TarjanSCC.cpp diff --git a/test/libsolutil/Logger.cpp b/test/libsolutil/Logger.cpp new file mode 100644 index 000000000000..44c232421f0a --- /dev/null +++ b/test/libsolutil/Logger.cpp @@ -0,0 +1,210 @@ +/* + This file is part of solidity. + + solidity 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, either version 3 of the License, or + (at your option) any later version. + + solidity 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 solidity. If not, see . +*/ +// SPDX-License-Identifier: GPL-3.0 +/** + * Unit tests for the logging registry. + */ + +#include + +#include + +#include + +using namespace solidity::log; + +namespace solidity::log::test +{ + +namespace +{ + +/// Resets the registry before and after each test so the process-wide singleton stays isolated. +struct LoggerFixture +{ + LoggerFixture() { LoggerRegistry::singleton().reset(); } + ~LoggerFixture() { LoggerRegistry::singleton().reset(); } +}; + +} + +BOOST_FIXTURE_TEST_SUITE(LoggerTest, LoggerFixture) + +BOOST_AUTO_TEST_CASE(loggers_default_to_off) +{ + Logger const& logger = LoggerRegistry::singleton().get("yul.ssa"); + BOOST_CHECK(!logger.shouldLog(Level::trace)); + BOOST_CHECK(!logger.shouldLog(Level::debug)); + BOOST_CHECK(!logger.shouldLog(Level::warn)); +} + +BOOST_AUTO_TEST_CASE(comparison_direction) +{ + auto& registry = LoggerRegistry::singleton(); + Logger const& logger = registry.get("a"); + + registry.setLevel("a", Level::trace); + BOOST_CHECK(logger.shouldLog(Level::trace)); + BOOST_CHECK(logger.shouldLog(Level::debug)); + BOOST_CHECK(logger.shouldLog(Level::warn)); + + registry.setLevel("a", Level::debug); + BOOST_CHECK(!logger.shouldLog(Level::trace)); + BOOST_CHECK(logger.shouldLog(Level::debug)); + BOOST_CHECK(logger.shouldLog(Level::warn)); + + registry.setLevel("a", Level::warn); + BOOST_CHECK(!logger.shouldLog(Level::trace)); + BOOST_CHECK(!logger.shouldLog(Level::debug)); + BOOST_CHECK(logger.shouldLog(Level::warn)); + + registry.setLevel("a", Level::off); + BOOST_CHECK(!logger.shouldLog(Level::trace)); + BOOST_CHECK(!logger.shouldLog(Level::debug)); + BOOST_CHECK(!logger.shouldLog(Level::warn)); +} + +BOOST_AUTO_TEST_CASE(hierarchy_most_specific_wins) +{ + auto& registry = LoggerRegistry::singleton(); + registry.setLevel("", Level::warn); + registry.setLevel("yul.ssa", Level::debug); + registry.setLevel("yul.ssa.codetransform.shuffler", Level::off); + + // Global default applies. + BOOST_CHECK(registry.get("yul").shouldLog(Level::warn)); + BOOST_CHECK(!registry.get("yul").shouldLog(Level::debug)); + + // "yul.ssa" rule applies to it and descendants. + BOOST_CHECK(registry.get("yul.ssa").shouldLog(Level::debug)); + BOOST_CHECK(registry.get("yul.ssa.codetransform").shouldLog(Level::debug)); + + // Most specific rule mutes the shuffler. + BOOST_CHECK(!registry.get("yul.ssa.codetransform.shuffler").shouldLog(Level::warn)); +} + +BOOST_AUTO_TEST_CASE(prefix_matching_is_segment_wise) +{ + auto& registry = LoggerRegistry::singleton(); + registry.setLevel("yul", Level::debug); + + // "yul" matches "yul.ssa" but must not match "yulish". + BOOST_CHECK(registry.get("yul.ssa").shouldLog(Level::debug)); + BOOST_CHECK(!registry.get("yulish").shouldLog(Level::debug)); +} + +BOOST_AUTO_TEST_CASE(level_change_propagates_to_existing_loggers) +{ + auto& registry = LoggerRegistry::singleton(); + Logger const& logger = registry.get("yul.ssa.stacklayout"); + BOOST_CHECK(!logger.shouldLog(Level::debug)); + + registry.setLevel("yul.ssa", Level::debug); + BOOST_CHECK(logger.shouldLog(Level::debug)); +} + +BOOST_AUTO_TEST_CASE(broader_rule_does_not_override_more_specific) +{ + auto& registry = LoggerRegistry::singleton(); + registry.setLevel("yul.ssa", Level::off); + Logger const& logger = registry.get("yul.ssa"); // exists before the broader rule is set + + registry.setLevel("yul", Level::debug); // broader prefix, arrives later + + // Most-specific match wins regardless of the order rules arrive in: "yul.ssa"=off still applies. + BOOST_CHECK(!logger.shouldLog(Level::debug)); +} + +BOOST_AUTO_TEST_CASE(sibling_inherits_parent_and_is_unaffected_by_other_subtrees) +{ + auto& registry = LoggerRegistry::singleton(); + registry.setLevel("yul", Level::warn); + registry.setLevel("yul.ssa", Level::debug); + + // "yul.ir" has no rule of its own, so it inherits its parent "yul"=warn. + Logger const& ir = registry.get("yul.ir"); + BOOST_CHECK(ir.shouldLog(Level::warn)); + BOOST_CHECK(!ir.shouldLog(Level::debug)); + + // Changing the sibling subtree "yul.ssa" must not affect "yul.ir". + registry.setLevel("yul.ssa", Level::trace); + BOOST_CHECK(ir.shouldLog(Level::warn)); + BOOST_CHECK(!ir.shouldLog(Level::debug)); +} + +BOOST_AUTO_TEST_CASE(output_has_prefix_and_formats_arguments) +{ + auto& registry = LoggerRegistry::singleton(); + std::ostringstream out; + registry.setOutput(out); + registry.setLevel("c", Level::debug); + + Logger const& logger = registry.get("c"); + solDebug(logger, "x={}", 1); + // Every line carries the standard "[ ] " prefix. + BOOST_CHECK_EQUAL(out.str(), "[debug c] x=1\n"); +} + +BOOST_AUTO_TEST_CASE(prefix_carries_message_level_not_logger_level) +{ + auto& registry = LoggerRegistry::singleton(); + std::ostringstream out; + registry.setOutput(out); + registry.setLevel("yul.ssa", Level::debug); + + Logger const& logger = registry.get("yul.ssa"); + solWarn(logger, "oops {}", 7); + // The prefix carries the level of the individual message, not the logger's configured level. + BOOST_CHECK_EQUAL(out.str(), "[warn yul.ssa] oops 7\n"); +} + +BOOST_AUTO_TEST_CASE(disabled_logger_does_not_evaluate_arguments) +{ + auto& registry = LoggerRegistry::singleton(); + std::ostringstream out; + registry.setOutput(out); + + Logger const& logger = registry.get("d"); // defaults to off + + int evaluations = 0; + auto sideEffect = [&]() { ++evaluations; return 42; }; + + solDebug(logger, "{}", sideEffect()); + BOOST_CHECK_EQUAL(evaluations, 0); + BOOST_CHECK(out.str().empty()); + + registry.setLevel("d", Level::debug); + solDebug(logger, "{}", sideEffect()); + BOOST_CHECK_EQUAL(evaluations, 1); + BOOST_CHECK_EQUAL(out.str(), "[debug d] 42\n"); +} + +BOOST_AUTO_TEST_CASE(level_string_round_trip) +{ + BOOST_CHECK(levelFromString("trace") == Level::trace); + BOOST_CHECK(levelFromString("debug") == Level::debug); + BOOST_CHECK(levelFromString("warn") == Level::warn); + BOOST_CHECK(levelFromString("off") == Level::off); + BOOST_CHECK(levelFromString("bogus") == std::nullopt); + + BOOST_CHECK_EQUAL(levelToString(Level::trace), "trace"); + BOOST_CHECK_EQUAL(levelToString(Level::off), "off"); +} + +BOOST_AUTO_TEST_SUITE_END() + +}