diff --git a/ci/check_symbols.sh b/ci/check_symbols.sh index 6185092d78..1b7dc4fb77 100755 --- a/ci/check_symbols.sh +++ b/ci/check_symbols.sh @@ -100,6 +100,28 @@ for sym in "${required_symbols[@]}"; do fi done +# The logger keeps one instance per component library only while its state stays hidden -- +# nothing fails to build or test if it becomes visible, since glibc silently merges it back +# into one via STB_GNU_UNIQUE. Assert it's absent from the dynamic symbol table. +logger_state_symbols=( + "cuopt::default_logger()" + "cuopt::global_log_buffer()" + "cuopt::reset_default_logger()" +) + +demangled_dyn_syms="$(readelf --dyn-syms --wide "${LIBRARY}" | awk '$7 != "UND" { print $8 }' | c++filt)" + +for sym in "${logger_state_symbols[@]}"; do + echo "Checking that logger state '${sym}' is NOT exported..." + if grep -qF "${sym}" <<< "${demangled_dyn_syms}"; then + echo "ERROR: Logger state '${sym}' is exported from ${LIBRARY}." + echo "ERROR: Per-component loggers silently collapse into one shared instance when this" + echo "ERROR: state is visible. Check that cpp/src/utilities/logger.hpp's namespace is not" + echo "ERROR: marked CUOPT_EXPORT and that hidden visibility is still set on the target." + failed=1 + fi +done + if [[ "${failed}" -ne 0 ]]; then exit 1 fi diff --git a/cpp/CMakeLists.txt b/cpp/CMakeLists.txt index b375cc4c56..56ae8b0938 100644 --- a/cpp/CMakeLists.txt +++ b/cpp/CMakeLists.txt @@ -648,6 +648,13 @@ target_compile_definitions(cuopt_objs PUBLIC CUSPARSE_ENABLE_EXPERIMENTAL_API ) +# Lets callers reach routing's logger through init_component_logger_t. Also set below on +# cuopt and cuopt_static: $ does not carry INTERFACE properties, and +# consumers such as cuopt_cli and the tests link those, not cuopt_objs. +if(NOT SKIP_ROUTING_BUILD) + target_compile_definitions(cuopt_objs PUBLIC CUOPT_HAS_ROUTING) +endif() + target_compile_options(cuopt_objs PRIVATE "$<$:${CUOPT_CXX_FLAGS}>" "$<$:${CUOPT_CUDA_FLAGS}>" @@ -811,6 +818,9 @@ if (BUILD_TESTS) "CUOPT_LOG_ACTIVE_LEVEL=RAPIDS_LOGGER_LOG_LEVEL_${LIBCUOPT_LOGGING_LEVEL}" CUSPARSE_ENABLE_EXPERIMENTAL_API ) + if(NOT SKIP_ROUTING_BUILD) + target_compile_definitions(cuopt_static PUBLIC CUOPT_HAS_ROUTING) + endif() target_link_libraries(cuopt_static PRIVATE $) add_dependencies(cuopt_static PSLP) target_link_libraries(cuopt_static PRIVATE $) @@ -869,6 +879,9 @@ target_compile_definitions(cuopt "CUOPT_LOG_ACTIVE_LEVEL=RAPIDS_LOGGER_LOG_LEVEL_${LIBCUOPT_LOGGING_LEVEL}" CUSPARSE_ENABLE_EXPERIMENTAL_API ) +if(NOT SKIP_ROUTING_BUILD) + target_compile_definitions(cuopt PUBLIC CUOPT_HAS_ROUTING) +endif() if (WRITE_FATBIN) file(WRITE "${CUOPT_BINARY_DIR}/fatbin.ld" diff --git a/cpp/cuopt_cli.cpp b/cpp/cuopt_cli.cpp index e070425eab..564e3d93a6 100644 --- a/cpp/cuopt_cli.cpp +++ b/cpp/cuopt_cli.cpp @@ -100,8 +100,14 @@ int run_single_file(const std::string& file_path, cuopt::mathematical_optimization::io::mps_reader_type_t mps_reader, cuopt::mathematical_optimization::solver_settings_t& settings) { - cuopt::init_logger_t log(settings.get_parameter(CUOPT_LOG_FILE), - settings.get_parameter(CUOPT_LOG_TO_CONSOLE)); + // The solver's logger lives in the solver library, reachable only through its exported + // entry point. The CLI's own logger appends rather than truncates, so it does not clear + // the file the solver has just opened. + const auto log_file = settings.get_parameter(CUOPT_LOG_FILE); + const auto log_console = settings.get_parameter(CUOPT_LOG_TO_CONSOLE); + + cuopt::init_component_logger_t solver_log(log_file, log_console); + cuopt::init_logger_t log(log_file, log_console, /*truncate=*/false); std::string base_filename = file_path.substr(file_path.find_last_of("/\\") + 1); diff --git a/cpp/src/CMakeLists.txt b/cpp/src/CMakeLists.txt index e8737cf6da..db71f8fa4d 100644 --- a/cpp/src/CMakeLists.txt +++ b/cpp/src/CMakeLists.txt @@ -4,7 +4,6 @@ # cmake-format: on set(UTIL_SRC_FILES ${CMAKE_CURRENT_SOURCE_DIR}/utilities/seed_generator.cu - ${CMAKE_CURRENT_SOURCE_DIR}/utilities/logger.cpp ${CMAKE_CURRENT_SOURCE_DIR}/utilities/version_info.cpp ${CMAKE_CURRENT_SOURCE_DIR}/utilities/timestamp_utils.cpp ${CMAKE_CURRENT_SOURCE_DIR}/utilities/work_unit_scheduler.cpp) diff --git a/cpp/src/math_optimization/CMakeLists.txt b/cpp/src/math_optimization/CMakeLists.txt index efa1600c54..25449bc929 100644 --- a/cpp/src/math_optimization/CMakeLists.txt +++ b/cpp/src/math_optimization/CMakeLists.txt @@ -9,6 +9,7 @@ list(PREPEND ${CMAKE_CURRENT_SOURCE_DIR}/solution_reader.cu ${CMAKE_CURRENT_SOURCE_DIR}/solution_writer.cu ${CMAKE_CURRENT_SOURCE_DIR}/tic_toc.cpp + ${CMAKE_CURRENT_SOURCE_DIR}/logger_entry.cpp ) set(CUOPT_SRC_FILES ${CUOPT_SRC_FILES} diff --git a/cpp/src/math_optimization/logger_entry.cpp b/cpp/src/math_optimization/logger_entry.cpp new file mode 100644 index 0000000000..dc8d024a50 --- /dev/null +++ b/cpp/src/math_optimization/logger_entry.cpp @@ -0,0 +1,20 @@ +/* clang-format off */ +/* + * SPDX-FileCopyrightText: Copyright (c) 2026, NVIDIA CORPORATION & AFFILIATES. All rights reserved. + * SPDX-License-Identifier: Apache-2.0 + */ +/* clang-format on */ + +#include + +// Compiled into cuopt_mathopt only, so this reaches mathopt's hidden logger instance. +namespace cuopt::mathematical_optimization { + +std::shared_ptr configure_logging(const std::string& log_file, + bool log_to_console, + bool truncate) +{ + return cuopt::make_logger_config(log_file, log_to_console, truncate); +} + +} // namespace cuopt::mathematical_optimization diff --git a/cpp/src/routing/CMakeLists.txt b/cpp/src/routing/CMakeLists.txt index 844eff833c..1dd2683f6d 100644 --- a/cpp/src/routing/CMakeLists.txt +++ b/cpp/src/routing/CMakeLists.txt @@ -4,6 +4,7 @@ # cmake-format: on set(ROUTING_SRC_FILES + ${CMAKE_CURRENT_SOURCE_DIR}/logger_entry.cpp ${CMAKE_CURRENT_SOURCE_DIR}/local_search/compute_insertions.cu ${CMAKE_CURRENT_SOURCE_DIR}/ges/squeeze.cu ${CMAKE_CURRENT_SOURCE_DIR}/local_search/sliding_window.cu diff --git a/cpp/src/routing/logger_entry.cpp b/cpp/src/routing/logger_entry.cpp new file mode 100644 index 0000000000..86c04c61b7 --- /dev/null +++ b/cpp/src/routing/logger_entry.cpp @@ -0,0 +1,20 @@ +/* clang-format off */ +/* + * SPDX-FileCopyrightText: Copyright (c) 2026, NVIDIA CORPORATION & AFFILIATES. All rights reserved. + * SPDX-License-Identifier: Apache-2.0 + */ +/* clang-format on */ + +#include + +// Compiled into cuopt_routing only, so this reaches routing's hidden logger instance. +namespace cuopt::routing { + +std::shared_ptr configure_logging(const std::string& log_file, + bool log_to_console, + bool truncate) +{ + return cuopt::make_logger_config(log_file, log_to_console, truncate); +} + +} // namespace cuopt::routing diff --git a/cpp/src/routing/solve.cu b/cpp/src/routing/solve.cu index a7caf88ad9..136d77a8b4 100644 --- a/cpp/src/routing/solve.cu +++ b/cpp/src/routing/solve.cu @@ -16,6 +16,9 @@ template assignment_t solve(data_model_view_t const& data_model, solver_settings_t const& settings) { + // Without this, CUOPT_LOG_ERROR below sinks into the buffer and is never emitted. + init_logger_t log("", settings.get_error_logging_mode()); + try { cuopt::routing::solver_t solver(data_model, settings); return solver.solve(); diff --git a/cpp/src/utilities/logger.cpp b/cpp/src/utilities/logger.cpp deleted file mode 100644 index 217f9c64cb..0000000000 --- a/cpp/src/utilities/logger.cpp +++ /dev/null @@ -1,191 +0,0 @@ -/* clang-format off */ -/* - * SPDX-FileCopyrightText: Copyright (c) 2025, NVIDIA CORPORATION & AFFILIATES. All rights reserved. - * SPDX-License-Identifier: Apache-2.0 - */ -/* clang-format on */ - -#include -#include - -namespace cuopt { - -struct buffered_entry { - rapids_logger::level_enum level; - std::string msg; -}; - -// Buffer to store log messages -class log_buffer { - public: - log_buffer() = default; - ~log_buffer() = default; - - void log(rapids_logger::level_enum lvl, const char* msg) - { - std::lock_guard lock(mutex); - if (!msg) return; - std::string str(msg); - - if (!str.empty() && str.back() == '\n') { str.pop_back(); } - messages.push_back({lvl, std::move(str)}); - } - - size_t size() const - { - std::lock_guard lock(mutex); - return messages.size(); - } - - std::vector drain_all() - { - std::lock_guard lock(mutex); - std::vector out; - out.swap(messages); - return out; - } - - std::vector messages; - mutable std::mutex mutex; -}; - -log_buffer& global_log_buffer() -{ - static log_buffer buffer; - return buffer; -} - -// Callback function for the buffer sink -static void buffer_log_callback(int lvl, const char* msg) -{ - // store level with message; actual filtering happens at logger time - global_log_buffer().log(static_cast(lvl), msg); -} - -/** - * @brief Returns the default sink for the global logger. - * - * If the environment variable `CUOPT_DEBUG_LOG_FILE` is defined, the default sink is a sink to that - * file. Otherwise, the default is to dump to stderr. - * - * @return sink_ptr The sink to use - */ -rapids_logger::sink_ptr default_sink() -{ - return std::make_shared(buffer_log_callback); -} - -/** - * @brief Returns the default log pattern for the global logger. - * - * @return std::string The default log pattern. - */ -inline std::string default_pattern() { return "[%Y-%m-%d %H:%M:%S:%f] [%n] [%-6l] %v"; } - -/** - * @brief Returns the default log level for the global logger. - * - * @return rapids_logger::level_enum The default log level. - */ -inline rapids_logger::level_enum default_level() -{ -#if CUOPT_LOG_ACTIVE_LEVEL == RAPIDS_LOGGER_LOG_LEVEL_TRACE - return rapids_logger::level_enum::trace; -#elif CUOPT_LOG_ACTIVE_LEVEL == RAPIDS_LOGGER_LOG_LEVEL_DEBUG - return rapids_logger::level_enum::debug; -#elif CUOPT_LOG_ACTIVE_LEVEL == RAPIDS_LOGGER_LOG_LEVEL_INFO - return rapids_logger::level_enum::info; -#elif CUOPT_LOG_ACTIVE_LEVEL == RAPIDS_LOGGER_LOG_LEVEL_WARN - return rapids_logger::level_enum::warn; -#elif CUOPT_LOG_ACTIVE_LEVEL == RAPIDS_LOGGER_LOG_LEVEL_ERROR - return rapids_logger::level_enum::error; -#elif CUOPT_LOG_ACTIVE_LEVEL == RAPIDS_LOGGER_LOG_LEVEL_CRITICAL - return rapids_logger::level_enum::critical; -#else - return rapids_logger::level_enum::info; -#endif -} - -rapids_logger::logger& default_logger() -{ - static rapids_logger::logger logger_ = [] { - rapids_logger::logger logger_{"CUOPT", {default_sink()}}; -#if CUOPT_LOG_ACTIVE_LEVEL >= RAPIDS_LOGGER_LOG_LEVEL_INFO - logger_.set_pattern("%v"); -#else - logger_.set_pattern(default_pattern()); -#endif - logger_.set_level(default_level()); - logger_.flush_on(rapids_logger::level_enum::debug); - - return logger_; - }(); - - return logger_; -} - -void reset_default_logger() -{ - default_logger().sinks().clear(); - default_logger().sinks().push_back(default_sink()); -#if CUOPT_LOG_ACTIVE_LEVEL >= RAPIDS_LOGGER_LOG_LEVEL_INFO - default_logger().set_pattern("%v"); -#else - default_logger().set_pattern(default_pattern()); -#endif - default_logger().set_level(default_level()); - default_logger().flush_on(rapids_logger::level_enum::debug); -} - -// Guard object whose destructor resets the logger -struct logger_config_guard { - ~logger_config_guard() { cuopt::reset_default_logger(); } -}; - -// Weak reference to detect if any init_logger_t instance is still alive -static std::weak_ptr g_active_guard; -static std::mutex g_guard_mutex; - -init_logger_t::init_logger_t(std::string log_file, bool log_to_console) -{ - std::lock_guard lock(g_guard_mutex); - - auto existing_guard = g_active_guard.lock(); - if (existing_guard) { - // Reuse existing configuration, just hold a reference to keep it alive - guard_ = existing_guard; - return; - } - - cuopt::default_logger().sinks().clear(); - - // re-initialize sinks - if (log_to_console) { - cuopt::default_logger().sinks().push_back( - std::make_shared(std::cout)); - } - if (!log_file.empty()) { - cuopt::default_logger().sinks().push_back( - std::make_shared(log_file, true)); - cuopt::default_logger().flush_on(rapids_logger::level_enum::debug); - } - -#if CUOPT_LOG_ACTIVE_LEVEL >= RAPIDS_LOGGER_LOG_LEVEL_INFO - cuopt::default_logger().set_pattern("%v"); -#else - cuopt::default_logger().set_pattern(cuopt::default_pattern()); -#endif - - // Extract messages from the global buffer and log to the default logger - auto buffered_messages = global_log_buffer().drain_all(); - for (const auto& entry : buffered_messages) { - cuopt::default_logger().log(entry.level, entry.msg.c_str()); - } - - // Create guard and store weak reference for future instances to find - auto guard = std::make_shared(); - g_active_guard = guard; - guard_ = guard; -} - -} // namespace cuopt diff --git a/cpp/src/utilities/logger.hpp b/cpp/src/utilities/logger.hpp index 2f9053b05f..cddd012fd4 100644 --- a/cpp/src/utilities/logger.hpp +++ b/cpp/src/utilities/logger.hpp @@ -15,39 +15,311 @@ #include #include +#include #include #include #include +#include #include #include #include -namespace CUOPT_EXPORT cuopt { - -/** - * @brief Get the default logger. +/* + * Defined inline with hidden visibility so each library that links this header owns its own + * logger instance. This is not optional: an inline function's static local is emitted as an + * STB_GNU_UNIQUE symbol, which glibc merges process-wide regardless of RTLD_LOCAL, so default + * visibility would collapse every library back into one shared logger. Do not mark this + * namespace CUOPT_EXPORT. * - * @return logger& The default logger + * Callers outside the libraries cannot reach a hidden logger, so each component exports a + * configure entry point instead -- see log_target_t and init_component_logger_t below. */ -rapids_logger::logger& default_logger(); +namespace cuopt { -/** - * @brief Reset the default logger to the default settings. - * This is needed when we are running multiple tests and each test has different logger settings - * and we need to reset the logger to the default settings before each test. - */ -void reset_default_logger(); +struct buffered_entry { + rapids_logger::level_enum level; + std::string msg; +}; + +// Buffer to store log messages +class log_buffer { + public: + log_buffer() = default; + ~log_buffer() = default; + + void log(rapids_logger::level_enum lvl, const char* msg) + { + std::lock_guard lock(mutex); + if (!msg) return; + std::string str(msg); + + if (!str.empty() && str.back() == '\n') { str.pop_back(); } + messages.push_back({lvl, std::move(str)}); + } + + size_t size() const + { + std::lock_guard lock(mutex); + return messages.size(); + } + + std::vector drain_all() + { + std::lock_guard lock(mutex); + std::vector out; + out.swap(messages); + return out; + } + + private: + std::vector messages; + mutable std::mutex mutex; +}; + +inline log_buffer& global_log_buffer() +{ + static log_buffer buffer; + return buffer; +} + +inline void buffer_log_callback(int lvl, const char* msg) +{ + global_log_buffer().log(static_cast(lvl), msg); +} + +// Buffers messages in memory until something configures the logger; anything logged before +// that, and never followed by a configure, is dropped. +inline rapids_logger::sink_ptr default_sink() +{ + return std::make_shared(buffer_log_callback); +} + +inline std::string default_pattern() { return "[%Y-%m-%d %H:%M:%S:%f] [%n] [%-6l] %v"; } + +inline rapids_logger::level_enum default_level() +{ +#if CUOPT_LOG_ACTIVE_LEVEL == RAPIDS_LOGGER_LOG_LEVEL_TRACE + return rapids_logger::level_enum::trace; +#elif CUOPT_LOG_ACTIVE_LEVEL == RAPIDS_LOGGER_LOG_LEVEL_DEBUG + return rapids_logger::level_enum::debug; +#elif CUOPT_LOG_ACTIVE_LEVEL == RAPIDS_LOGGER_LOG_LEVEL_INFO + return rapids_logger::level_enum::info; +#elif CUOPT_LOG_ACTIVE_LEVEL == RAPIDS_LOGGER_LOG_LEVEL_WARN + return rapids_logger::level_enum::warn; +#elif CUOPT_LOG_ACTIVE_LEVEL == RAPIDS_LOGGER_LOG_LEVEL_ERROR + return rapids_logger::level_enum::error; +#elif CUOPT_LOG_ACTIVE_LEVEL == RAPIDS_LOGGER_LOG_LEVEL_CRITICAL + return rapids_logger::level_enum::critical; +#else + return rapids_logger::level_enum::info; +#endif +} + +inline rapids_logger::logger& default_logger() +{ + static rapids_logger::logger logger_ = [] { + rapids_logger::logger logger_{"CUOPT", {default_sink()}}; +#if CUOPT_LOG_ACTIVE_LEVEL >= RAPIDS_LOGGER_LOG_LEVEL_INFO + logger_.set_pattern("%v"); +#else + logger_.set_pattern(default_pattern()); +#endif + logger_.set_level(default_level()); + logger_.flush_on(rapids_logger::level_enum::debug); + + return logger_; + }(); + + return logger_; +} + +inline void reset_default_logger() +{ + default_logger().sinks().clear(); + default_logger().sinks().push_back(default_sink()); +#if CUOPT_LOG_ACTIVE_LEVEL >= RAPIDS_LOGGER_LOG_LEVEL_INFO + default_logger().set_pattern("%v"); +#else + default_logger().set_pattern(default_pattern()); +#endif + default_logger().set_level(default_level()); + default_logger().flush_on(rapids_logger::level_enum::debug); +} + +// Points this image's logger at the given sinks and flushes anything buffered so far. +// `truncate` clears log_file up front instead of letting the sink truncate it: several +// loggers in one process can share a path, and a truncating sink writes from offset 0, +// silently overwriting whatever another one has already appended. Pass false when another +// image is already logging to the same path and has truncated it. +inline void apply_logger_config(const std::string& log_file, bool log_to_console, bool truncate) +{ + cuopt::default_logger().sinks().clear(); + + if (log_to_console) { + cuopt::default_logger().sinks().push_back( + std::make_shared(std::cout)); + } + if (!log_file.empty()) { + if (truncate) { std::ofstream(log_file, std::ios::trunc); } + cuopt::default_logger().sinks().push_back( + std::make_shared(log_file, /*truncate=*/false)); + cuopt::default_logger().flush_on(rapids_logger::level_enum::debug); + } + +#if CUOPT_LOG_ACTIVE_LEVEL >= RAPIDS_LOGGER_LOG_LEVEL_INFO + cuopt::default_logger().set_pattern("%v"); +#else + cuopt::default_logger().set_pattern(cuopt::default_pattern()); +#endif + + auto buffered_messages = global_log_buffer().drain_all(); + for (const auto& entry : buffered_messages) { + cuopt::default_logger().log(entry.level, entry.msg.c_str()); + } +} -// Ref-counted logger initializer +// Ref-counted initializer for the logger of the image that constructs it. Library code uses +// this directly (routing configures routing's logger, mathopt configures mathopt's); callers +// outside the libraries should use init_component_logger_t to reach a library's instead. class init_logger_t { - // Using shared_ptr for ref-counting std::shared_ptr guard_; public: - init_logger_t(std::string log_file, bool log_to_console); + init_logger_t(std::string log_file, bool log_to_console, bool truncate = true); +}; + +inline std::mutex g_guard_mutex; + +// Bumped for every configuration applied. A guard resets the logger only if its own +// configuration is still the current one. +inline uint64_t& active_config_generation() +{ + static uint64_t generation = 0; + return generation; +} + +// Guard whose destruction resets the logger, if its configuration is still current. The +// generation check matters: a guard's refcount reaching zero expires g_active_guard *before* +// this destructor runs, so another thread can install a new configuration in that window, and +// without the check this destructor would reset the logger out from under it. +struct logger_config_guard { + explicit logger_config_guard(uint64_t generation) : generation_(generation) {} + + ~logger_config_guard() + { + std::lock_guard lock(g_guard_mutex); + if (active_config_generation() != generation_) { return; } + cuopt::reset_default_logger(); + } + + private: + uint64_t generation_; +}; + +// Weak reference to detect if any init_logger_t instance is still alive +inline std::weak_ptr g_active_guard; + +// Applies a configuration and returns a handle that keeps it alive. Single lifetime mechanism +// for this image's logger: init_logger_t and the exported per-component configure_logging both +// go through it, so a caller inside the library and one outside share one refcount, and the +// logger resets only when the last handle drops -- which is what stops the solver +// reconfiguring mid-run and re-truncating a log file the caller had already written to. +inline std::shared_ptr make_logger_config(const std::string& log_file, + bool log_to_console, + bool truncate) +{ + std::lock_guard lock(g_guard_mutex); + + // Reuse the configuration already in place; reconfiguring here would re-truncate the file. + if (auto existing = g_active_guard.lock()) { return existing; } + + try { + apply_logger_config(log_file, log_to_console, truncate); + } catch (...) { + // Sinks are cleared before new ones install, so a throw here would otherwise leave the + // logger with none at all. + reset_default_logger(); + throw; + } + + auto guard = std::make_shared(++active_config_generation()); + g_active_guard = guard; + return guard; +} + +inline init_logger_t::init_logger_t(std::string log_file, bool log_to_console, bool truncate) + : guard_(make_logger_config(log_file, log_to_console, truncate)) +{ +} + +/** + * @brief Which component library's logger to configure. + */ +enum class log_target_t { + mathopt, ///< LP / MILP / QP, in cuopt_mathopt + routing ///< VRP, in cuopt_routing +}; + +} // namespace cuopt + +// Exported per-component entry points. Each is defined in exactly one component library, and +// configures that library's own hidden logger -- the only logging symbols crossing a boundary. +namespace cuopt::mathematical_optimization { +CUOPT_EXPORT std::shared_ptr configure_logging(const std::string& log_file, + bool log_to_console, + bool truncate); +} // namespace cuopt::mathematical_optimization + +#ifdef CUOPT_HAS_ROUTING +namespace cuopt::routing { +CUOPT_EXPORT std::shared_ptr configure_logging(const std::string& log_file, + bool log_to_console, + bool truncate); +} // namespace cuopt::routing +#endif + +namespace cuopt { + +// Configures a component library's logger from outside that library. The CLI, tests and +// Python bindings each hold their own logger and need to reach into the solver's; this +// dispatches to the component's exported entry point instead of init_logger_t. Defaults to +// mathopt because every external caller today is LP or MILP; routing is opted in explicitly. +class init_component_logger_t { + // Same refcount init_logger_t uses, so a caller here and library code inside the component + // cannot tear down each other's configuration. + std::shared_ptr handle_; + + public: + explicit init_component_logger_t(const std::string& log_file, + bool log_to_console, + log_target_t target = log_target_t::mathopt, + bool truncate = true) + { + switch (target) { + case log_target_t::routing: +#ifdef CUOPT_HAS_ROUTING + handle_ = cuopt::routing::configure_logging(log_file, log_to_console, truncate); +#else + // Silently doing nothing here would look like a working logger that drops every + // message, and the cause -- a SKIP_ROUTING_BUILD mismatch -- would be invisible. + throw std::runtime_error( + "cuOpt was built with SKIP_ROUTING_BUILD, so routing's logger does not exist and " + "log_target_t::routing cannot be configured."); +#endif + break; + case log_target_t::mathopt: + default: + handle_ = + cuopt::mathematical_optimization::configure_logging(log_file, log_to_console, truncate); + break; + } + } + + init_component_logger_t(const init_component_logger_t&) = delete; + init_component_logger_t& operator=(const init_component_logger_t&) = delete; }; -} // namespace CUOPT_EXPORT cuopt +} // namespace cuopt namespace cuopt::detail { diff --git a/cpp/tests/dual_simplex/unit_tests/solve.cpp b/cpp/tests/dual_simplex/unit_tests/solve.cpp index 2e44442599..d502ca9292 100644 --- a/cpp/tests/dual_simplex/unit_tests/solve.cpp +++ b/cpp/tests/dual_simplex/unit_tests/solve.cpp @@ -23,7 +23,7 @@ namespace cuopt::mathematical_optimization::simplex::test { TEST(dual_simplex, chess_set) { - cuopt::init_logger_t log("", true); + cuopt::init_component_logger_t log("", true); namespace simplex = cuopt::mathematical_optimization::simplex; raft::handle_t handle{}; simplex::user_problem_t user_problem(&handle); @@ -97,7 +97,7 @@ TEST(dual_simplex, chess_set) TEST(dual_simplex, burglar) { - cuopt::init_logger_t log("", true); + cuopt::init_component_logger_t log("", true); constexpr int num_items = 8; constexpr double max_weight = 102; @@ -173,7 +173,7 @@ TEST(dual_simplex, burglar) TEST(dual_simplex, empty_columns) { - cuopt::init_logger_t log("", true); + cuopt::init_component_logger_t log("", true); // Same as burglar problem above but with an empty column inserted constexpr int num_items = 9; constexpr double max_weight = 102; @@ -262,7 +262,7 @@ TEST(dual_simplex, empty_columns) TEST(dual_simplex, dual_variable_greater_than) { - cuopt::init_logger_t log("", true); + cuopt::init_component_logger_t log("", true); // minimize 3*x0 + 2 * x1 // subject to x0 + x1 >= 1 // x0 + 2x1 >= 3 diff --git a/cpp/tests/dual_simplex/unit_tests/solve_barrier.cu b/cpp/tests/dual_simplex/unit_tests/solve_barrier.cu index 16640c6c60..9f5963acec 100644 --- a/cpp/tests/dual_simplex/unit_tests/solve_barrier.cu +++ b/cpp/tests/dual_simplex/unit_tests/solve_barrier.cu @@ -41,7 +41,7 @@ static void init_handler(const raft::handle_t* handle_ptr) TEST(barrier, chess_set) { - cuopt::init_logger_t log("", true); + cuopt::init_component_logger_t log("", true); namespace simplex = cuopt::mathematical_optimization::simplex; raft::handle_t handle{}; init_handler(&handle); @@ -111,7 +111,7 @@ TEST(barrier, chess_set) TEST(barrier, dual_variable_greater_than) { - cuopt::init_logger_t log("", true); + cuopt::init_component_logger_t log("", true); // minimize 3*x0 + 2 * x1 // subject to x0 + x1 >= 1 // x0 + 2x1 >= 3 diff --git a/cpp/tests/utilities/CMakeLists.txt b/cpp/tests/utilities/CMakeLists.txt index 8747d47bd0..70979d7172 100644 --- a/cpp/tests/utilities/CMakeLists.txt +++ b/cpp/tests/utilities/CMakeLists.txt @@ -5,3 +5,6 @@ # Add CLI end-to-end test ConfigureTest(CLI_TEST test_cli.cpp LABELS numopt) + +# Logger boundary: per-library instances, shared log file, truncate semantics +ConfigureTest(LOGGER_TEST test_logger.cpp LABELS numopt) diff --git a/cpp/tests/utilities/test_logger.cpp b/cpp/tests/utilities/test_logger.cpp new file mode 100644 index 0000000000..44a871d58b --- /dev/null +++ b/cpp/tests/utilities/test_logger.cpp @@ -0,0 +1,290 @@ +/* clang-format off */ +/* + * SPDX-FileCopyrightText: Copyright (c) 2026, NVIDIA CORPORATION & AFFILIATES. All rights reserved. + * SPDX-License-Identifier: Apache-2.0 + */ +/* clang-format on */ + +#include + +#include + +#include +#include +#include +#include +#include +#include +#include +#include + +/* + * The logger is hidden, so this test binary has its own instance, separate from libcuopt's. + * CUOPT_LOG_* here reaches this image's logger: init_logger_t/make_logger_config are testable + * directly, while init_component_logger_t reaches into libcuopt's (its effect on a shared file + * is observable here, its messages are not). The hiding itself is checked by + * ci/check_symbols.sh, not here. + */ +namespace cuopt::test { + +namespace { + +int unique_id() +{ + static int counter = 0; + return counter++; +} + +std::string temp_log_path(const std::string& tag) +{ + return "cuopt_logger_test_" + tag + "_" + std::to_string(unique_id()) + ".log"; +} + +// Nesting under a regular file fails to open with ENOTDIR for any user, including CI's root -- +// unlike a missing directory, which the sink creates. +std::string unopenable_path_under(const std::string& blocker_file) +{ + std::ofstream blocker{blocker_file}; + blocker << "not a directory"; + return blocker_file + "/child.log"; +} + +std::string read_file(const std::string& path) +{ + std::ifstream in{path}; + std::ostringstream out; + out << in.rdbuf(); + return out.str(); +} + +// Holding the handle keeps the configuration alive; dropping it resets the logger. +struct scoped_config { + explicit scoped_config(const std::string& path, bool truncate = true) + : handle(cuopt::make_logger_config(path, false, truncate)) + { + } + std::shared_ptr handle; +}; + +} // namespace + +// A second configuration, after the first has been released, must actually take effect and +// not leave the logger reset to the buffer sink. +TEST(logger, reconfigure_does_not_reset_to_buffer) +{ + const auto first = temp_log_path("first"); + const auto second = temp_log_path("second"); + + { + scoped_config initial{first}; + CUOPT_LOG_ERROR("before_reconfigure"); + } + { + scoped_config replacement{second}; + CUOPT_LOG_ERROR("after_reconfigure"); + } + + EXPECT_NE(read_file(first).find("before_reconfigure"), std::string::npos); + EXPECT_NE(read_file(second).find("after_reconfigure"), std::string::npos) + << "the second configuration left the logger reset to the buffer sink"; + + std::remove(first.c_str()); + std::remove(second.c_str()); +} + +// Overlapping configurations behave like overlapping init_logger_t instances: the inner one +// reuses the outer configuration, and its exit must not tear that configuration down. +TEST(logger, nested_config_survives_inner_exit) +{ + const auto path = temp_log_path("nested"); + + { + scoped_config outer{path}; + { + scoped_config inner{path}; + } + CUOPT_LOG_ERROR("after_inner_exit"); + } + + EXPECT_NE(read_file(path).find("after_inner_exit"), std::string::npos) + << "inner exit tore down the outer configuration"; + + std::remove(path.c_str()); +} + +// truncate clears the file up front instead of letting the sink open in truncating mode, so +// a second logger appending to the same path is not overwritten from offset 0. +TEST(logger, truncate_clears_previous_contents) +{ + const auto path = temp_log_path("truncate"); + { + std::ofstream seed{path}; + seed << "STALE_CONTENT_FROM_PREVIOUS_RUN\n"; + } + + { + scoped_config cfg{path}; + CUOPT_LOG_ERROR("fresh"); + } + + const auto contents = read_file(path); + EXPECT_EQ(contents.find("STALE_CONTENT_FROM_PREVIOUS_RUN"), std::string::npos) + << "log file was not truncated"; + EXPECT_NE(contents.find("fresh"), std::string::npos); + + std::remove(path.c_str()); +} + +// truncate=false leaves what is already there, which is how a second logger on the same path +// avoids clobbering the first. +TEST(logger, append_preserves_existing_contents) +{ + const auto path = temp_log_path("append"); + { + std::ofstream seed{path}; + seed << "WRITTEN_BY_ANOTHER_LOGGER\n"; + } + + { + scoped_config cfg{path, /*truncate=*/false}; + CUOPT_LOG_ERROR("appended"); + } + + const auto contents = read_file(path); + EXPECT_NE(contents.find("WRITTEN_BY_ANOTHER_LOGGER"), std::string::npos) + << "appending logger overwrote the other logger's output"; + EXPECT_NE(contents.find("appended"), std::string::npos); + + std::remove(path.c_str()); +} + +// A configure that throws must not leave the logger wedged for later callers. +TEST(logger, failed_configure_does_not_wedge_later_ones) +{ + const auto blocker = temp_log_path("blocker"); + const auto unopenable = unopenable_path_under(blocker); + EXPECT_ANY_THROW(cuopt::make_logger_config(unopenable, false, true)); + + const auto path = temp_log_path("recovered"); + { + scoped_config cfg{path}; + CUOPT_LOG_ERROR("after_failed_configure"); + } + + EXPECT_NE(read_file(path).find("after_failed_configure"), std::string::npos) + << "a failed configure left the logger wedged"; + + std::remove(path.c_str()); + std::remove(blocker.c_str()); +} + +// Same failure for the image-local entry point: apply_logger_config clears the sinks before +// installing new ones, so a throw part way through must not leave the logger with none. +TEST(logger, failed_init_logger_restores_a_sink) +{ + const auto blocker = temp_log_path("blocker"); + const auto unopenable = unopenable_path_under(blocker); + EXPECT_ANY_THROW(cuopt::init_logger_t(unopenable, false, true)); + + const auto path = temp_log_path("init_recovered"); + { + scoped_config cfg{path}; + CUOPT_LOG_ERROR("after_failed_init"); + } + + EXPECT_NE(read_file(path).find("after_failed_init"), std::string::npos) + << "a failed init_logger_t left the logger without sinks"; + + std::remove(path.c_str()); + std::remove(blocker.c_str()); +} + +// Smoke test for concurrent configure/release/emit, not a regression test -- the race it +// relates to needs the refcount to hit zero at an exact moment that contention makes unlikely +// to hit here. Kept because it exercises the shared path and is where a sanitizer would catch +// unsynchronized sink mutation. +TEST(logger, concurrent_configure_and_emit) +{ + const auto path = temp_log_path("concurrent"); + + constexpr int kThreads = 8; + constexpr int kIterations = 400; + + std::vector threads; + threads.reserve(kThreads); + for (int t = 0; t < kThreads; ++t) { + threads.emplace_back([&path] { + for (int i = 0; i < kIterations; ++i) { + auto handle = cuopt::make_logger_config(path, false, /*truncate=*/false); + CUOPT_LOG_ERROR("concurrent_message"); + } + }); + } + for (auto& thread : threads) { + thread.join(); + } + + EXPECT_NE(read_file(path).find("concurrent_message"), std::string::npos); + + std::remove(path.c_str()); +} + +// The library's logger is reachable only through the exported entry point. Its messages are +// not observable here, but configuring it must clear the shared file exactly once. +TEST(logger, component_logger_truncates_shared_file) +{ + const auto path = temp_log_path("component"); + { + std::ofstream seed{path}; + seed << "STALE\n"; + } + + { + cuopt::init_component_logger_t solver_log{path, false}; + EXPECT_EQ(read_file(path).find("STALE"), std::string::npos) + << "component configure did not clear the file"; + } + + std::remove(path.c_str()); +} + +#ifdef CUOPT_HAS_ROUTING +// mathopt and routing are compiled into the same shared library (`cuopt` in +// cpp/CMakeLists.txt) until libcuopt splits into separate component libraries +// (#1622), so their "component" loggers are the same hidden instance today, not two +// independent ones. This pins down that current behavior: whichever component +// configures first wins the shared logger, and the second component's file is left +// alone rather than corrupted or silently truncated out from under a concurrent +// writer. If this starts failing, it means the split landed and mathopt/routing now +// have independent loggers -- update this test (and its neighbor above) to assert +// each file is truncated independently instead. +TEST(logger, mathopt_and_routing_share_one_instance_pre_split) +{ + const auto mathopt_path = temp_log_path("mathopt"); + const auto routing_path = temp_log_path("routing"); + { + std::ofstream seed{mathopt_path}; + seed << "STALE_MATHOPT\n"; + } + { + std::ofstream seed{routing_path}; + seed << "STALE_ROUTING\n"; + } + + { + cuopt::init_component_logger_t mathopt_log{mathopt_path, false, cuopt::log_target_t::mathopt}; + EXPECT_EQ(read_file(mathopt_path).find("STALE_MATHOPT"), std::string::npos) + << "mathopt configure did not clear its file"; + + cuopt::init_component_logger_t routing_log{routing_path, false, cuopt::log_target_t::routing}; + EXPECT_NE(read_file(routing_path).find("STALE_ROUTING"), std::string::npos) + << "routing's file was truncated -- mathopt and routing no longer share one " + "logger instance, see the comment above this test"; + } + + std::remove(mathopt_path.c_str()); + std::remove(routing_path.c_str()); +} +#endif + +} // namespace cuopt::test