From a5f97db47d315aad638305b97341c8d6d15a3fa6 Mon Sep 17 00:00:00 2001 From: tmccrmck Date: Mon, 1 Apr 2019 12:13:43 -0700 Subject: [PATCH] Refactor logging to use unique id per request and take logging level from user (#21) * Removes capturing env by reference in main * Uses uuid for logging ids * Take logging_level as a program argument * Pass logging_level to default_logging_manager * Change name of logger to HostingApp * Log if request id is null --- onnxruntime/hosting/environment.cc | 26 +++++++---- onnxruntime/hosting/environment.h | 10 +++-- onnxruntime/hosting/http/context.h | 26 ++++++++--- .../hosting/http/predict_request_handler.cc | 6 +-- onnxruntime/hosting/http/session.cc | 2 +- onnxruntime/hosting/main.cc | 25 ++++++----- onnxruntime/hosting/server_configuration.h | 45 +++++++++++++------ .../test/hosting/server_configuration_test.cc | 24 ++++++++-- tools/ci_build/build.py | 2 +- 9 files changed, 114 insertions(+), 52 deletions(-) diff --git a/onnxruntime/hosting/environment.cc b/onnxruntime/hosting/environment.cc index f7323217f11ff..1bcde3da2246d 100644 --- a/onnxruntime/hosting/environment.cc +++ b/onnxruntime/hosting/environment.cc @@ -10,26 +10,34 @@ namespace onnxruntime { namespace hosting { -HostingEnvironment::HostingEnvironment() : logger_id_("HostingLog"), - default_logging_manager_( - std::unique_ptr{&sink_}, - onnxruntime::logging::Severity::kVERBOSE, - /* default_filter_user_data */ false, - onnxruntime::logging::LoggingManager::InstanceType::Default, - &logger_id_) { +HostingEnvironment::HostingEnvironment(onnxruntime::logging::Severity severity) : logger_id_("HostingApp"), + default_logging_manager_( + std::unique_ptr{&sink_}, + severity, + /* default_filter_user_data */ false, + onnxruntime::logging::LoggingManager::InstanceType::Default, + &logger_id_) { auto status = onnxruntime::Environment::Create(this->runtime_environment_); // The session initialization MUST BE AFTER environment creation session_ = std::make_shared(options_, &default_logging_manager_); } -const onnxruntime::logging::Logger& HostingEnvironment::GetLogger() { +const onnxruntime::logging::Logger& HostingEnvironment::GetAppLogger() { return this->default_logging_manager_.DefaultLogger(); } +std::shared_ptr HostingEnvironment::GetLogger(const std::string& id) { + if (id.empty()) { + LOGS(GetAppLogger(), WARNING) << "Request id is null or empty string"; + } + + return this->default_logging_manager_.CreateLogger(id); +} + std::shared_ptr HostingEnvironment::GetSession() const { return this->session_; } } // namespace hosting -} // namespace onnxruntime \ No newline at end of file +} // namespace onnxruntime diff --git a/onnxruntime/hosting/environment.h b/onnxruntime/hosting/environment.h index 9e4af9a8bf844..485fced686b79 100644 --- a/onnxruntime/hosting/environment.h +++ b/onnxruntime/hosting/environment.h @@ -16,17 +16,21 @@ namespace hosting { class HostingEnvironment { public: - HostingEnvironment(); + explicit HostingEnvironment(onnxruntime::logging::Severity severity); + // TODO: cleanly dispose session + ~HostingEnvironment() = default; HostingEnvironment(const HostingEnvironment&) = delete; - const onnxruntime::logging::Logger& GetLogger(); + const onnxruntime::logging::Logger& GetAppLogger(); + std::shared_ptr GetLogger(const std::string& id); std::shared_ptr GetSession() const; private: std::string logger_id_; onnxruntime::hosting::LogSink sink_; - std::unique_ptr runtime_environment_; onnxruntime::logging::LoggingManager default_logging_manager_; + + std::unique_ptr runtime_environment_; onnxruntime::SessionOptions options_; std::shared_ptr session_; }; diff --git a/onnxruntime/hosting/http/context.h b/onnxruntime/hosting/http/context.h index 23a6b59769934..1da6117cd1a2b 100644 --- a/onnxruntime/hosting/http/context.h +++ b/onnxruntime/hosting/http/context.h @@ -1,10 +1,20 @@ // Copyright (c) Microsoft Corporation. All rights reserved. // Licensed under the MIT License. -#ifndef ONNXRUNTIME_HOSTING_HTTP_HTTP_CONTEXT_H -#define ONNXRUNTIME_HOSTING_HTTP_HTTP_CONTEXT_H +#ifndef ONNXRUNTIME_HOSTING_HTTP_CONTEXT_H +#define ONNXRUNTIME_HOSTING_HTTP_CONTEXT_H + +// boost random is using a deprecated header in 1.69 +// See: https://github.com/boostorg/random/issues/49 +#define BOOST_PENDING_INTEGER_LOG2_HPP +#include + +#include #include +#include +#include +#include namespace onnxruntime { namespace hosting { @@ -19,10 +29,14 @@ class HttpContext { http::request>> request{}; http::response response{}; - std::string error_message = "An unknown server error has occurred"; - http::status error_code = http::status::internal_server_error; + std::string uuid; + http::status error_code; + std::string error_message; + + HttpContext() : uuid(boost::uuids::to_string(boost::uuids::random_generator()())), + error_code(http::status::internal_server_error), + error_message("An unknown server error has occurred") {} - HttpContext() = default; ~HttpContext() = default; HttpContext(const HttpContext&) = delete; }; @@ -30,4 +44,4 @@ class HttpContext { } // namespace hosting } // namespace onnxruntime -#endif // ONNXRUNTIME_HOSTING_HTTP_HTTP_CONTEXT_H +#endif // ONNXRUNTIME_HOSTING_HTTP_CONTEXT_H diff --git a/onnxruntime/hosting/http/predict_request_handler.cc b/onnxruntime/hosting/http/predict_request_handler.cc index 11efc3f7701dd..9ab4aa42074ba 100644 --- a/onnxruntime/hosting/http/predict_request_handler.cc +++ b/onnxruntime/hosting/http/predict_request_handler.cc @@ -15,11 +15,9 @@ void Predict(const std::string& name, HttpContext& context, std::shared_ptr env) { PredictRequest predictRequest{}; - auto logger = env->GetLogger(); + auto logger = env->GetLogger(context.uuid); - LOGS(logger, VERBOSE) << "Name: " << name; - LOGS(logger, VERBOSE) << "Version: " << version; - LOGS(logger, VERBOSE) << "Action: " << action; + LOGS(*logger, VERBOSE) << "Name: " << name << " Version: " << version << " Action: " << action; auto body = context.request.body(); auto status = GetRequestFromJson(body, predictRequest); diff --git a/onnxruntime/hosting/http/session.cc b/onnxruntime/hosting/http/session.cc index b2366dce5f53e..7eb06942f7f79 100644 --- a/onnxruntime/hosting/http/session.cc +++ b/onnxruntime/hosting/http/session.cc @@ -85,7 +85,7 @@ void HttpSession::Send(Msg&& msg) { http::async_write(self_->socket_, *ptr, net::bind_executor(strand_, - [self_, close = ptr->need_eof()](beast::error_code ec, std::size_t bytes) { + [ self_, close = ptr->need_eof() ](beast::error_code ec, std::size_t bytes) { self_->OnWrite(ec, bytes, close); })); } diff --git a/onnxruntime/hosting/main.cc b/onnxruntime/hosting/main.cc index 0218a06530987..a0b4390f50b9b 100644 --- a/onnxruntime/hosting/main.cc +++ b/onnxruntime/hosting/main.cc @@ -20,8 +20,8 @@ int main(int argc, char* argv[]) { exit(EXIT_FAILURE); } - auto env = std::make_shared(); - auto logger = env->GetLogger(); + auto env = std::make_shared(config.logging_level); + auto logger = env->GetAppLogger(); LOGS(logger, VERBOSE) << "Logging manager initialized."; LOGS(logger, VERBOSE) << "Model path: " << config.model_path; auto status = env->GetSession()->Load(config.model_path); @@ -32,26 +32,27 @@ int main(int argc, char* argv[]) { hosting::App app{}; app.RegisterStartup( - [&env](const auto& details) -> void { - auto logger = env->GetLogger(); + [env](const auto& details) -> void { + auto logger = env->GetAppLogger(); LOGS(logger, VERBOSE) << "Listening at: " << "http://" << details.address << ":" << details.port; }); app.RegisterError( - [&env](auto& context) -> void { - auto logger = env->GetLogger(); - LOGS(logger, VERBOSE) << "Error code: " << context.error_code; - LOGS(logger, VERBOSE) << "Error message: " << context.error_message; + [env](auto& context) -> void { + auto logger = env->GetLogger(context.uuid); + LOGS(*logger, VERBOSE) << "Error code: " << context.error_code; + LOGS(*logger, VERBOSE) << "Error message: " << context.error_message; context.response.result(context.error_code); context.response.body() = hosting::CreateJsonError(context.error_code, context.error_message); }); - app.RegisterPost(R"(/v1/models/([^/:]+)(?:/versions/(\d+))?:(classify|regress|predict))", - [env](const auto& name, const auto& version, const auto& action, auto& context) -> void { - hosting::Predict(name, version, action, context, env); - }); + app.RegisterPost( + R"(/v1/models/([^/:]+)(?:/versions/(\d+))?:(classify|regress|predict))", + [env](const auto& name, const auto& version, const auto& action, auto& context) -> void { + hosting::Predict(name, version, action, context, env); + }); app.Bind(boost_address, config.http_port) .NumThreads(config.num_http_threads) diff --git a/onnxruntime/hosting/server_configuration.h b/onnxruntime/hosting/server_configuration.h index 9ab742e2f7102..cd0cc892560fd 100644 --- a/onnxruntime/hosting/server_configuration.h +++ b/onnxruntime/hosting/server_configuration.h @@ -9,12 +9,14 @@ #include "boost/program_options.hpp" +#include "core/common/logging/logging.h" + namespace onnxruntime { namespace hosting { -enum Result { ExitSuccess = 1, - ExitFailure, - ContinueSuccess }; +enum class Result { ExitSuccess = 1, + ExitFailure, + ContinueSuccess }; namespace po = boost::program_options; @@ -22,8 +24,16 @@ namespace po = boost::program_options; // Provides sane default values class ServerConfiguration { public: + const std::string full_desc = "ONNX Hosting: host an ONNX model for inferencing with ONNXRuntime"; + std::string model_path; + std::string address = "0.0.0.0"; + int http_port = 8001; + int num_http_threads = std::thread::hardware_concurrency(); + onnxruntime::logging::Severity logging_level{}; + ServerConfiguration() { desc.add_options()("help,h", "Shows a help message and exits"); + desc.add_options()("logging_level", po::value(&logging_level_str)->default_value(logging_level_str), "Logging level. Allowed options (case sensitive): verbose, info, warning, error, fatal"); desc.add_options()("model_path,m", po::value(&model_path)->required(), "Path to ONNX model"); desc.add_options()("address,a", po::value(&address)->default_value(address), "The base HTTP address"); desc.add_options()("http_port", po::value(&http_port)->default_value(http_port), "HTTP port to listen to requests"); @@ -51,19 +61,22 @@ class ServerConfiguration { return Result::ExitFailure; } + logging_level = GetSeverity(logging_level_str); return ValidateOptions(); } - const std::string full_desc = "ONNX Hosting: host an ONNX model for inferencing with ONNXRuntime"; - std::string model_path; - std::string address = "0.0.0.0"; - int http_port = 8001; - int num_http_threads = std::thread::hardware_concurrency(); - private: + po::options_description desc{"Allowed options"}; + po::variables_map vm{}; + std::string logging_level_str = "verbose"; + // Print help and return if there is a bad value Result ValidateOptions() { - if (num_http_threads <= 0) { + if (vm.count("logging_level") && + (!(logging_level_str == "verbose" || logging_level_str == "info") || logging_level_str == "warning" || logging_level_str == "error" || logging_level_str == "fatal")) { + PrintHelp(std::cerr, "logging_level must be one of verbose, info, warning, error, or fatal"); + return Result::ExitFailure; + } else if (num_http_threads <= 0) { PrintHelp(std::cerr, "num_http_threads must be greater than 0"); return Result::ExitFailure; } else if (http_port < 0 || http_port > 65535) { @@ -82,6 +95,15 @@ class ServerConfiguration { return vm.count("help") || vm.count("h"); } + onnxruntime::logging::Severity GetSeverity(const std::string& level) const { + if (level == "verbose") return onnxruntime::logging::Severity::kVERBOSE; + if (level == "info") return onnxruntime::logging::Severity::kINFO; + if (level == "warning") return onnxruntime::logging::Severity::kWARNING; + if (level == "error") return onnxruntime::logging::Severity::kERROR; + if (level == "fatal") return onnxruntime::logging::Severity::kFATAL; + return onnxruntime::logging::Severity::kVERBOSE; + } + // Prints a helpful message (param: what) to the user and then the program options // Example: config.PrintHelp(std::cout, "Non-negative values not allowed") // Which will print that message and then all publicly available options @@ -94,9 +116,6 @@ class ServerConfiguration { std::ifstream infile(fileName.c_str()); return infile.good(); } - - po::options_description desc{"Allowed options"}; - po::variables_map vm{}; }; } // namespace hosting diff --git a/onnxruntime/test/hosting/server_configuration_test.cc b/onnxruntime/test/hosting/server_configuration_test.cc index 7b4b18b0f3306..f7a21e686df5c 100644 --- a/onnxruntime/test/hosting/server_configuration_test.cc +++ b/onnxruntime/test/hosting/server_configuration_test.cc @@ -16,15 +16,17 @@ TEST(PositiveTests, ConfigParsingFullArgs) { const_cast("--model_path"), const_cast("testdata/mul_1.pb"), const_cast("--address"), const_cast("4.4.4.4"), const_cast("--http_port"), const_cast("80"), - const_cast("--num_http_threads"), const_cast("1")}; + const_cast("--num_http_threads"), const_cast("1"), + const_cast("--logging_level"), const_cast("info")}; onnxruntime::hosting::ServerConfiguration config{}; - Result res = config.ParseInput(9, test_argv); + Result res = config.ParseInput(11, test_argv); EXPECT_EQ(res, Result::ContinueSuccess); EXPECT_EQ(config.model_path, "testdata/mul_1.pb"); EXPECT_EQ(config.address, "4.4.4.4"); EXPECT_EQ(config.http_port, 80); EXPECT_EQ(config.num_http_threads, 1); + EXPECT_EQ(config.logging_level, onnxruntime::logging::Severity::kINFO); } TEST(PositiveTests, ConfigParsingShortArgs) { @@ -42,6 +44,7 @@ TEST(PositiveTests, ConfigParsingShortArgs) { EXPECT_EQ(config.address, "4.4.4.4"); EXPECT_EQ(config.http_port, 5001); EXPECT_EQ(config.num_http_threads, 2); + EXPECT_EQ(config.logging_level, onnxruntime::logging::Severity::kVERBOSE); } TEST(PositiveTests, ConfigParsingDefaults) { @@ -57,6 +60,7 @@ TEST(PositiveTests, ConfigParsingDefaults) { EXPECT_EQ(config.address, "0.0.0.0"); EXPECT_EQ(config.http_port, 8001); EXPECT_EQ(config.num_http_threads, 3); + EXPECT_EQ(config.logging_level, onnxruntime::logging::Severity::kVERBOSE); } TEST(PositiveTests, ConfigParsingHelp) { @@ -79,7 +83,7 @@ TEST(NegativeTests, ConfigParsingNoModelArg) { EXPECT_EQ(res, Result::ExitFailure); } -TEST(PositiveTests, ConfigParsingModelNotFound) { +TEST(NegativeTests, ConfigParsingModelNotFound) { char* test_argv[] = { const_cast("/path/to/binary"), const_cast("--model_path"), const_cast("does/not/exist"), @@ -92,6 +96,20 @@ TEST(PositiveTests, ConfigParsingModelNotFound) { EXPECT_EQ(res, Result::ExitFailure); } +TEST(NegativeTests, ConfigParsingWrongLoggingLevel) { + char* test_argv[] = { + const_cast("/path/to/binary"), + const_cast("--logging_level"), const_cast("not a logging level"), + const_cast("--model_path"), const_cast("testdata/mul_1.pb"), + const_cast("--address"), const_cast("4.4.4.4"), + const_cast("--http_port"), const_cast("80"), + const_cast("--num_http_threads"), const_cast("1")}; + + onnxruntime::hosting::ServerConfiguration config{}; + Result res = config.ParseInput(11, test_argv); + EXPECT_EQ(res, Result::ExitFailure); +} + } // namespace test } // namespace hosting } // namespace onnxruntime \ No newline at end of file diff --git a/tools/ci_build/build.py b/tools/ci_build/build.py index 8ab6a3b6b230b..4eb381eec4f70 100755 --- a/tools/ci_build/build.py +++ b/tools/ci_build/build.py @@ -227,7 +227,7 @@ def install_hosting_deps(source_dir): boostrap_path = os.path.join(vcpkg_folder_path, 'bootstrap-vcpkg' + file_ending) run_subprocess([boostrap_path]) - run_subprocess([vcpkg_executable, 'install', 'boost-beast', 'boost-program-options', 'rapidjson']) + run_subprocess([vcpkg_executable, 'install', 'boost-beast', 'boost-program-options', 'boost-uuid']) def check_md5(filename, expected_md5): if not os.path.exists(filename):