1 files changed, 28 insertions, 6 deletions

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;