More tracing stuff

6 files changed, 101 insertions, 58 deletions

diff --git a/server/src/api.cpp b/server/src/api.cpp
index 41c49c8..f1ca24e 100644
--- a/server/src/api.cpp
+++ b/server/src/api.cpp
@@ -144,9 +144,11 @@ handler::handler(log::logger const& l, datex2::situation_publication pub)
   l_.info("Point index size: {}", bpe_index_.size());
 }
 
-auto handler::process_gpx(gpx::file&& gpx_file)
+auto handler::process_gpx(trace::id trace_id, gpx::file&& gpx_file)
     -> std::optional<process_gpx_result>
 {
+  auto l = l_.with("trace_id", trace_id.as_string());
+
   auto const now = chrono::utc_clock::now();
   auto const relevant = std::initializer_list<time::period>{
     time::period{now - chrono::days(7), now + chrono::days(7)}
@@ -162,7 +164,7 @@ auto handler::process_gpx(gpx::file&& gpx_file)
 
   auto vincenty_strategy = geo::wgs84::vincenty_strategy{};
 
-  l_.debug("Querying for relevant situations");
+  l.debug("Querying for relevant situations");
   auto relevant_road_closures =
       std::unordered_set<std::shared_ptr<datex2::road_closure>>{};
   auto ls_checked = 0uz;
@@ -170,7 +172,7 @@ auto handler::process_gpx(gpx::file&& gpx_file)
   auto i = 0;
   for (auto const& part : segments)
   {
-    l_.debug("Checking part [{}/{}]", ++i, segments.size());
+    l.debug("Checking part [{}/{}]", ++i, segments.size());
 
     auto part_zone_lss =
         geo::utm::multizonal::split_linestring_across_zones(part);
@@ -206,7 +208,7 @@ auto handler::process_gpx(gpx::file&& gpx_file)
   }
 
   auto const after_query = chrono::steady_clock::now();
-  l_.debug(
+  l.debug(
       "Done (checked {} line string(s) and {} point(s)) in {}", ls_checked,
       p_checked,
       chrono::duration_cast<chrono::milliseconds>(after_query - before_query));
@@ -216,12 +218,12 @@ auto handler::process_gpx(gpx::file&& gpx_file)
   for (auto const& rc : relevant_road_closures)
     relevant_situations.emplace(rc->parent);
 
-  l_.debug(
+  l.debug(
       "Identified {} relevant road closure(s), part of {} unique "
       "situation(s)",
       relevant_road_closures.size(), relevant_situations.size());
   for (auto const& sit : relevant_situations)
-    l_.debug("Relevant situation: {}", sit->id);
+    l.debug("Relevant situation: {}", sit->id);
 
   return process_gpx_result{
     .tracks = gpx_file.tracks
diff --git a/server/src/api.cppm b/server/src/api.cppm
index 7166ad0..b2744cb 100644
--- a/server/src/api.cppm
+++ b/server/src/api.cppm
@@ -93,7 +93,8 @@ class handler
 public:
   explicit handler(log::logger const& l, datex2::situation_publication pub);
 
-  auto process_gpx(gpx::file&& gpx_file) -> std::optional<process_gpx_result>;
+  auto process_gpx(trace::id trace_id, gpx::file&& gpx_file)
+      -> std::optional<process_gpx_result>;
   auto sysinfo() -> sysinfo;
 };
 
diff --git a/server/src/http_server.cpp b/server/src/http_server.cpp
index da8e6f0..c3a9ed7 100644
--- a/server/src/http_server.cpp
+++ b/server/src/http_server.cpp
@@ -13,6 +13,9 @@ module;
 module routemon:http.server$impl;
 
 import :http.server;
+import :trace;
+
+namespace chrono = std::chrono;
 
 namespace routemon::http {
 
@@ -86,10 +89,10 @@ auto global_options_handler(base_ctx const& ctx, readable_request r)
   co_return std::move(rsp);
 }
 
-auto router::handle_request(readable_request r) const
+auto router::handle_request(trace::id trace_id, readable_request r) const
     -> net::awaitable<presponse>
 {
-  return impl_->handle_request(r);
+  return impl_->handle_request(trace_id, r);
 }
 
 server::server(log::logger const& l, router&& r)
@@ -112,16 +115,35 @@ auto server::do_session(beast::tcp_stream strm) -> net::awaitable<void>
     else if (ec)
       throw boost::system::system_error{ec};
 
+    auto trace_id = trace::id{};
+    auto l = l_.sub("do_session").with("trace_id", trace_id.as_string());
+    l.debug("Read header, invoking request handler");
+    auto const before_hdl = chrono::steady_clock::now();
+
     auto http_version = p0.get().version();
     auto&& rsp = co_await r_.handle_request(
-        readable_request{
-          .p = util::not_null{&p0},
-          .strm = util::not_null{&strm},
-          .buf = util::not_null{&buf},
+        trace_id, readable_request{
+                    .p = util::not_null{&p0},
+                    .strm = util::not_null{&strm},
+                    .buf = util::not_null{&buf},
+                  });
+
+    l.debug(
+        "Request handler returned after {}, writing response",
+        chrono::duration<double, std::milli>{
+          chrono::steady_clock::now() - before_hdl
         });
+    auto before_write_rsp = chrono::steady_clock::now();
+
     rsp.header().version(http_version);
     bool keep_alive = rsp.keep_alive();
     co_await beast::async_write(strm, std::move(rsp));
+
+    l.debug(
+        "Wrote response in {}", chrono::duration<double, std::milli>{
+                                  chrono::steady_clock::now() - before_write_rsp
+                                });
+
     if (!keep_alive)
     {
       break;
diff --git a/server/src/http_server.cppm b/server/src/http_server.cppm
index b16f3a8..12c83db 100644
--- a/server/src/http_server.cppm
+++ b/server/src/http_server.cppm
@@ -164,6 +164,19 @@ auto id_middleware(
   co_return co_await next(std::move(ctx));
 }
 
+struct base_ctx
+{
+  std::locale locale;
+  trace::id trace_id;
+};
+
+template <class Ctx>
+using basic_route_handler_fn_t =
+    std::function<auto(
+                      Ctx, readable_request,
+                      std::vector<std::string> const& matches)
+                      ->net::awaitable<presponse>>;
+
 template <class Ctx>
 auto cors_middleware(std::vector<std::string> const& allow_origins)
     -> middleware_t<Ctx, Ctx>
@@ -186,39 +199,21 @@ auto cors_middleware(std::vector<std::string> const& allow_origins)
   };
 }
 
-template <class InnerCtx>
-struct trace_id_ctx : InnerCtx
-{
-  trace::id trace_id = {};
-};
-
-template <class OuterCtx>
+template <class Ctx>
 auto trace_id_middleware(
-    OuterCtx ctx0, bhttp::request_header<bhttp::fields>& req_hdr,
-    next_handler_t<trace_id_ctx<OuterCtx>> next) -> net::awaitable<presponse>
+    Ctx ctx, bhttp::request_header<bhttp::fields>& req_hdr,
+    next_handler_t<Ctx> next) -> net::awaitable<presponse>
 {
   std::ignore = req_hdr;
-  auto ctx = trace_id_ctx{std::move(ctx0)};
   auto prersp = co_await next(std::move(ctx));
   prersp.header().set(
-      "X-Routemon-Trace-Id", std::string_view{ctx.trace_id.as_string()});
+      "X-Routemon-Trace-Id",
+      std::string_view{static_cast<base_ctx const&>(ctx).trace_id.as_string()});
   prersp.header().insert(
       bhttp::field::access_control_expose_headers, "X-Routemon-Trace-Id");
   co_return std::move(prersp);
 }
 
-struct base_ctx
-{
-  std::locale locale;
-};
-
-template <class Ctx>
-using basic_route_handler_fn_t =
-    std::function<auto(
-                      Ctx, readable_request,
-                      std::vector<std::string> const& matches)
-                      ->net::awaitable<presponse>>;
-
 struct keep_alive
 {
   bool value;
@@ -555,7 +550,7 @@ class router
   struct impl_base
   {
     virtual ~impl_base() = default;
-    virtual auto handle_request(readable_request r) const
+    virtual auto handle_request(trace::id trace_id, readable_request r) const
         -> net::awaitable<presponse> = 0;
   };
 
@@ -564,16 +559,17 @@ class router
   template <std::derived_from<base_ctx> PreRouteCtx>
   class impl : public impl_base
   {
+    log::logger l_;
     locale::selector lsel_;
     middleware_t<base_ctx, PreRouteCtx> global_middleware_;
     route_tree<routed_ctx<PreRouteCtx>> routes_;
 
   public:
     explicit impl(
-        locale::selector&& lsel,
+        log::logger const& l, locale::selector&& lsel,
         middleware_t<base_ctx, PreRouteCtx> global_middleware,
         route_tree<routed_ctx<PreRouteCtx>> routes)
-      : lsel_{std::move(lsel)},
+      : l_{l.sub("router")}, lsel_{std::move(lsel)},
         global_middleware_{std::move(global_middleware)},
         routes_{std::move(routes)}
     {
@@ -674,6 +670,13 @@ class router
           co_return problem_rsp(ctx, problem, keep_alive{false});
         }
 
+        l_.with(
+              "trace_id",
+              static_cast<base_ctx const&>(ctx).trace_id.as_string())
+            .debug(
+                "Request targets {} {}", req_base.method_string(),
+                req_url.path());
+
         auto mres = match(req_url.segments());
         if (!mres)
         {
@@ -732,13 +735,13 @@ class router
       }
     }
 
-    auto handle_request(readable_request r) const
+    auto handle_request(trace::id trace_id, readable_request r) const
         -> net::awaitable<presponse> override
     {
       auto header = r.p->get().base();
       auto locale = lsel_.select(header[bhttp::field::accept_language]);
       co_return co_await global_middleware_(
-          base_ctx{.locale = locale}, header,
+          base_ctx{.locale = locale, .trace_id = trace_id}, header,
           [&](PreRouteCtx ctx) -> net::awaitable<presponse>
           { co_return co_await route_request(std::move(ctx), std::move(r)); });
     }
@@ -747,15 +750,16 @@ class router
 public:
   template <std::derived_from<base_ctx> PreRouteCtx>
   explicit router(
-      locale::selector&& lsel,
+      log::logger const& l, locale::selector&& lsel,
       middleware_t<base_ctx, PreRouteCtx> global_middleware,
       route_tree<routed_ctx<PreRouteCtx>> routes)
     : impl_{std::make_unique<impl<PreRouteCtx>>(
-          std::move(lsel), std::move(global_middleware), std::move(routes))}
+          l, std::move(lsel), std::move(global_middleware), std::move(routes))}
   {
   }
 
-  auto handle_request(readable_request r) const -> net::awaitable<presponse>;
+  auto handle_request(trace::id trace_id, readable_request r) const
+      -> net::awaitable<presponse>;
 };
 
 class server
diff --git a/server/src/srv.cpp b/server/src/srv.cpp
index b70f05c..f79da33 100644
--- a/server/src/srv.cpp
+++ b/server/src/srv.cpp
@@ -19,6 +19,7 @@ import :gpx;
 import :srv;
 
 namespace beast = boost::beast;
+namespace chrono = std::chrono;
 namespace json = boost::json;
 namespace net = boost::asio;
 using tcp = boost::asio::ip::tcp;
@@ -157,12 +158,22 @@ static_assert(bhttp::concepts::body_reader<readable_gpx_body>);
 auto handler::handle_process_gpx(l0_ctx ctx, http::readable_request r)
     -> net::awaitable<http::presponse>
 {
+  auto l =
+      l_.sub("handle_process_gpx").with("trace_id", ctx.trace_id.as_string());
+
   auto gpx_file = gpx::file{};
   try
   {
+    l.debug("Reading GPX request body");
+    auto const before_read_gpx = chrono::steady_clock::now();
     auto req =
         co_await http::read_request<readable_gpx_body>(ctx, std::move(r));
     gpx_file = std::move(req->body().unwrap());
+    l.debug(
+        "Read GPX request body in {}",
+        chrono::duration<double, std::milli>{
+          chrono::steady_clock::now() - before_read_gpx
+        });
   }
   catch (std::exception& ex)
   {
@@ -178,7 +189,7 @@ auto handler::handle_process_gpx(l0_ctx ctx, http::readable_request r)
 
   // TODO: catch handler exceptions and return 500 when raised?
   // (keep-alive depends on whether whole request was read)
-  auto mres = inner_.process_gpx(std::move(gpx_file));
+  auto mres = inner_.process_gpx(ctx.trace_id, std::move(gpx_file));
   if (!mres)
   {
     auto tpl = problem::tpl{
@@ -212,7 +223,10 @@ auto handler::handle_sysinfo(l0_ctx ctx, http::readable_request r)
   co_return rsp;
 }
 
-handler::handler(api::handler&& inner) : inner_{std::move(inner)} {}
+handler::handler(log::logger const& l, api::handler&& inner)
+  : l_{l.sub("handler")}, inner_{std::move(inner)}
+{
+}
 
 auto handler::make_routes() -> http::route_tree<http::routed_ctx<outer_ctx>>
 {
@@ -235,22 +249,21 @@ auto handler::make_routes() -> http::route_tree<http::routed_ctx<outer_ctx>>
 auto server::make_global_middleware(config::http_server const& cfg)
     -> http::middleware_t<http::base_ctx, handler::outer_ctx>
 {
-  return http::middleware_compose<
-      http::base_ctx, http::trace_id_ctx<http::base_ctx>,
-      http::trace_id_ctx<http::base_ctx>
-  >(http::trace_id_middleware<http::base_ctx>,
-    http::cors_middleware<http::trace_id_ctx<http::base_ctx>>(
-        cfg.allow_origins));
+  return http::
+      middleware_compose<http::base_ctx, http::base_ctx, http::base_ctx>(
+          http::trace_id_middleware<http::base_ctx>,
+          http::cors_middleware<http::base_ctx>(cfg.allow_origins));
 }
 
 server::server(
     log::logger const& l, config::http_server const& cfg,
     locale::selector&& lsel, api::handler&& inner)
-  : handler_{std::move(inner)},
+  : handler_{l, std::move(inner)},
     srv_{
-      l, http::router{
-           std::move(lsel), make_global_middleware(cfg), handler_.make_routes()
-         }
+      l,
+      http::router{
+        l, std::move(lsel), make_global_middleware(cfg), handler_.make_routes()
+      }
     }
 {
 }
diff --git a/server/src/srv.cppm b/server/src/srv.cppm
index 063617e..b06dc3b 100644
--- a/server/src/srv.cppm
+++ b/server/src/srv.cppm
@@ -11,10 +11,11 @@ namespace routemon::srv {
 
 class handler
 {
+  log::logger l_;
   api::handler inner_;
 
 public:
-  using outer_ctx = http::trace_id_ctx<http::base_ctx>;
+  using outer_ctx = http::base_ctx;
   using l0_ctx = http::routed_ctx<outer_ctx>;
 
 private:
@@ -25,7 +26,7 @@ private:
       -> net::awaitable<http::presponse>;
 
 public:
-  handler(api::handler&& inner);
+  handler(log::logger const& l, api::handler&& inner);
 
   auto make_routes() -> http::route_tree<http::routed_ctx<outer_ctx>>;
 };