Refactor logging to use unique id per request and take logging level …

…from user (microsoft#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

@@ -10,26 +10,34 @@
 namespace onnxruntime {
 namespace hosting {
 
-HostingEnvironment::HostingEnvironment() : logger_id_("HostingLog"),
-                                           default_logging_manager_(
-                                               std::unique_ptr<onnxruntime::logging::ISink>{&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<onnxruntime::logging::ISink>{&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<onnxruntime::InferenceSession>(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<onnxruntime::logging::Logger> 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<onnxruntime::InferenceSession> HostingEnvironment::GetSession() const {
   return this->session_;
 }
 
 }  // namespace hosting
-}  // namespace onnxruntime
+}  // namespace onnxruntime

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<onnxruntime::logging::Logger> GetLogger(const std::string& id);
   std::shared_ptr<onnxruntime::InferenceSession> GetSession() const;
 
  private:
   std::string logger_id_;
   onnxruntime::hosting::LogSink sink_;
-  std::unique_ptr<onnxruntime::Environment> runtime_environment_;
   onnxruntime::logging::LoggingManager default_logging_manager_;
+
+  std::unique_ptr<onnxruntime::Environment> runtime_environment_;
   onnxruntime::SessionOptions options_;
   std::shared_ptr<onnxruntime::InferenceSession> session_;
 };

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 <boost/integer/integer_log2.hpp>
+
+#include <string>
 
 #include <boost/beast/http.hpp>
+#include <boost/uuid/uuid.hpp>
+#include <boost/uuid/uuid_io.hpp>
+#include <boost/uuid/uuid_generators.hpp>
 
 namespace onnxruntime {
 namespace hosting {
@@ -19,15 +29,19 @@ class HttpContext {
   http::request<http::string_body, http::basic_fields<std::allocator<char>>> request{};
   http::response<http::string_body> 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;
 };
 
 }  // namespace hosting
 }  // namespace onnxruntime
 
-#endif  // ONNXRUNTIME_HOSTING_HTTP_HTTP_CONTEXT_H
+#endif  // ONNXRUNTIME_HOSTING_HTTP_CONTEXT_H

onnxruntime/hosting/http/predict_request_handler.cc

@@ -15,11 +15,9 @@ void Predict(const std::string& name,
              HttpContext& context,
              std::shared_ptr<HostingEnvironment> 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);

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);
                                        }));
 }

onnxruntime/hosting/main.cc

@@ -20,8 +20,8 @@ int main(int argc, char* argv[]) {
     exit(EXIT_FAILURE);
   }
 
-  auto env = std::make_shared<hosting::HostingEnvironment>();
-  auto logger = env->GetLogger();
+  auto env = std::make_shared<hosting::HostingEnvironment>(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)

onnxruntime/hosting/server_configuration.h

@@ -9,21 +9,31 @@
 
 #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;
 
 // Wrapper around Boost program_options and should provide all the functionality for options parsing
 // 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

onnxruntime/test/hosting/server_configuration_test.cc

@@ -16,15 +16,17 @@ TEST(PositiveTests, ConfigParsingFullArgs) {
       const_cast<char*>("--model_path"), const_cast<char*>("testdata/mul_1.pb"),
       const_cast<char*>("--address"), const_cast<char*>("4.4.4.4"),
       const_cast<char*>("--http_port"), const_cast<char*>("80"),
-      const_cast<char*>("--num_http_threads"), const_cast<char*>("1")};
+      const_cast<char*>("--num_http_threads"), const_cast<char*>("1"),
+      const_cast<char*>("--logging_level"), const_cast<char*>("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<char*>("/path/to/binary"),
       const_cast<char*>("--model_path"), const_cast<char*>("does/not/exist"),
@@ -92,6 +96,20 @@ TEST(PositiveTests, ConfigParsingModelNotFound) {
   EXPECT_EQ(res, Result::ExitFailure);
 }
 
+TEST(NegativeTests, ConfigParsingWrongLoggingLevel) {
+  char* test_argv[] = {
+      const_cast<char*>("/path/to/binary"),
+      const_cast<char*>("--logging_level"), const_cast<char*>("not a logging level"),
+      const_cast<char*>("--model_path"), const_cast<char*>("testdata/mul_1.pb"),
+      const_cast<char*>("--address"), const_cast<char*>("4.4.4.4"),
+      const_cast<char*>("--http_port"), const_cast<char*>("80"),
+      const_cast<char*>("--num_http_threads"), const_cast<char*>("1")};
+
+  onnxruntime::hosting::ServerConfiguration config{};
+  Result res = config.ParseInput(11, test_argv);
+  EXPECT_EQ(res, Result::ExitFailure);
+}
+
 }  // namespace test
 }  // namespace hosting
 }  // namespace onnxruntime

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):