HTTP plugin request debug logging (#587)

* added log level control/query to LoggerRef
* added debug logging to http plugin implementation
* added GetDebugName() to transport plugin interfaces
* added debug name to log output

1 files changed, 142 insertions, 27 deletions

diff --git a/src/zenhttp/servers/httpplugin.cpp b/src/zenhttp/servers/httpplugin.cpp
index 4ae7cd87a..8795fbcaa 100644
--- a/src/zenhttp/servers/httpplugin.cpp
+++ b/src/zenhttp/servers/httpplugin.cpp
@@ -7,7 +7,11 @@
 #	include "httpparser.h"
 
 #	include <zencore/except.h>
+#	include <zencore/filesystem.h>
+#	include <zencore/fmtutils.h>
 #	include <zencore/logging.h>
+#	include <zencore/scopeguard.h>
+#	include <zencore/session.h>
 #	include <zencore/thread.h>
 #	include <zencore/trace.h>
 #	include <zenhttp/httpserver.h>
@@ -15,6 +19,8 @@
 #	include <memory>
 #	include <string_view>
 
+#	include <fmt/format.h>
+
 #	if ZEN_PLATFORM_WINDOWS
 #		include <conio.h>
 #	endif
@@ -38,17 +44,21 @@ using namespace std::literals;
 
 struct HttpPluginConnectionHandler : public TransportServerConnection, public HttpRequestParserCallbacks, RefCounted
 {
+	HttpPluginConnectionHandler();
+	~HttpPluginConnectionHandler();
+
+	// TransportServerConnection
+
 	virtual uint32_t AddRef() const override;
 	virtual uint32_t Release() const override;
-
-	virtual void OnBytesRead(const void* Buffer, size_t DataSize) override;
+	virtual void	 OnBytesRead(const void* Buffer, size_t DataSize) override;
 
 	// HttpRequestParserCallbacks
 
 	virtual void HandleRequest() override;
 	virtual void TerminateConnection() override;
 
-	void Initialize(TransportConnection* Transport, HttpPluginServerImpl& Server);
+	void Initialize(TransportConnection* Transport, HttpPluginServerImpl& Server, uint32_t ConnectionId);
 
 private:
 	enum class RequestState
@@ -65,7 +75,8 @@ private:
 	RequestState	  m_RequestState = RequestState::kInitialState;
 	HttpRequestParser m_RequestParser{*this};
 
-	uint32_t				 m_ConnectionId = 0;
+	uint32_t				 m_ConnectionId	  = 0;
+	std::atomic_uint32_t	 m_RequestCounter = 0;
 	Ref<IHttpPackageHandler> m_PackageHandler;
 
 	TransportConnection*  m_TransportConnection = nullptr;
@@ -82,7 +93,7 @@ struct HttpPluginServerImpl : public HttpPluginServer, TransportServer
 	// HttpPluginServer
 
 	virtual void RegisterService(HttpService& Service) override;
-	virtual int	 Initialize(int BasePort) override;
+	virtual int	 Initialize(int BasePort, std::filesystem::path DataDir) override;
 	virtual void Run(bool IsInteractiveSession) override;
 	virtual void RequestExit() override;
 	virtual void Close() override;
@@ -92,6 +103,8 @@ struct HttpPluginServerImpl : public HttpPluginServer, TransportServer
 
 	HttpService* RouteRequest(std::string_view Url);
 
+	void WriteDebugPayload(std::string_view Filename, const std::span<const IoBuffer> Payload);
+
 	struct ServiceEntry
 	{
 		std::string	 ServiceUrlPath;
@@ -103,6 +116,11 @@ struct HttpPluginServerImpl : public HttpPluginServer, TransportServer
 	std::vector<ServiceEntry>		  m_UriHandlers;
 	std::vector<Ref<TransportPlugin>> m_Plugins;
 	Event							  m_ShutdownEvent;
+	bool							  m_IsRequestLoggingEnabled = false;
+	LoggerRef						  m_RequestLog;
+	std::atomic_uint32_t			  m_ConnectionIdCounter{0};
+	std::filesystem::path			  m_DataDir;	 // Application data directory
+	std::filesystem::path			  m_PayloadDir;	 // Request debugging payload directory
 
 	// TransportServer
 
@@ -147,14 +165,20 @@ public:
 	HttpPluginResponse() = default;
 	explicit HttpPluginResponse(HttpContentType ContentType) : m_ContentType(ContentType) {}
 
+	HttpPluginResponse(const HttpPluginResponse&) = delete;
+	HttpPluginResponse& operator=(const HttpPluginResponse&) = delete;
+
 	void InitializeForPayload(uint16_t ResponseCode, std::span<IoBuffer> BlobList);
 
-	inline uint16_t ResponseCode() const { return m_ResponseCode; }
-	inline uint64_t ContentLength() const { return m_ContentLength; }
+	inline uint16_t		   ResponseCode() const { return m_ResponseCode; }
+	inline uint64_t		   ContentLength() const { return m_ContentLength; }
+	inline HttpContentType ContentType() const { return m_ContentType; }
 
 	const std::vector<IoBuffer>& ResponseBuffers() const { return m_ResponseBuffers; }
 	void						 SuppressPayload() { m_ResponseBuffers.resize(1); }
 
+	std::string_view GetHeaders();
+
 private:
 	uint16_t					 m_ResponseCode	 = 0;
 	bool						 m_IsKeepAlive	 = true;
@@ -162,8 +186,6 @@ private:
 	uint64_t					 m_ContentLength = 0;
 	std::vector<IoBuffer>		 m_ResponseBuffers;
 	ExtendableStringBuilder<160> m_Headers;
-
-	std::string_view GetHeaders();
 };
 
 void
@@ -210,27 +232,55 @@ HttpPluginResponse::InitializeForPayload(uint16_t ResponseCode, std::span<IoBuff
 std::string_view
 HttpPluginResponse::GetHeaders()
 {
-	m_Headers << "HTTP/1.1 " << ResponseCode() << " " << ReasonStringForHttpResultCode(ResponseCode()) << "\r\n"
-			  << "Content-Type: " << MapContentTypeToString(m_ContentType) << "\r\n"
-			  << "Content-Length: " << ContentLength() << "\r\n"sv;
-
-	if (!m_IsKeepAlive)
+	if (m_Headers.Size() == 0)
 	{
-		m_Headers << "Connection: close\r\n"sv;
-	}
+		m_Headers << "HTTP/1.1 " << ResponseCode() << " " << ReasonStringForHttpResultCode(ResponseCode()) << "\r\n"
+				  << "Content-Type: " << MapContentTypeToString(m_ContentType) << "\r\n"
+				  << "Content-Length: " << ContentLength() << "\r\n"sv;
+
+		if (!m_IsKeepAlive)
+		{
+			m_Headers << "Connection: close\r\n"sv;
+		}
 
-	m_Headers << "\r\n"sv;
+		m_Headers << "\r\n"sv;
+	}
 
 	return m_Headers;
 }
 
 //////////////////////////////////////////////////////////////////////////
 
+HttpPluginConnectionHandler::HttpPluginConnectionHandler()
+{
+}
+
+HttpPluginConnectionHandler::~HttpPluginConnectionHandler()
+{
+	if (m_Server)
+	{
+		ZEN_LOG_TRACE(m_Server->m_RequestLog, "END connection #{}", m_ConnectionId);
+	}
+}
+
 void
-HttpPluginConnectionHandler::Initialize(TransportConnection* Transport, HttpPluginServerImpl& Server)
+HttpPluginConnectionHandler::Initialize(TransportConnection* Transport, HttpPluginServerImpl& Server, uint32_t ConnectionId)
 {
 	m_TransportConnection = Transport;
 	m_Server			  = &Server;
+	m_ConnectionId		  = ConnectionId;
+
+	std::string_view ConnectionName;
+	if (const char* Name = Transport->GetDebugName())
+	{
+		ConnectionName = Name;
+	}
+	else
+	{
+		ConnectionName = "anonymous";
+	}
+
+	ZEN_LOG_TRACE(m_Server->m_RequestLog, "NEW connection #{} ('')", m_ConnectionId, ConnectionName);
 }
 
 uint32_t
@@ -248,13 +298,19 @@ HttpPluginConnectionHandler::Release() const
 void
 HttpPluginConnectionHandler::OnBytesRead(const void* Buffer, size_t AvailableBytes)
 {
+	ZEN_ASSERT(m_Server);
+
+	ZEN_LOG_TRACE(m_Server->m_RequestLog, "connection #{} OnBytesRead: {}", m_ConnectionId, AvailableBytes);
+
 	while (AvailableBytes)
 	{
 		const size_t ConsumedBytes = m_RequestParser.ConsumeData((const char*)Buffer, AvailableBytes);
 
 		if (ConsumedBytes == ~0ull)
 		{
-			// terminate connection
+			// request parser error -- terminate connection
+
+			ZEN_LOG_TRACE(m_Server->m_RequestLog, "connection #{} terminating due to request parsing error", m_ConnectionId);
 
 			return TerminateConnection();
 		}
@@ -269,15 +325,21 @@ HttpPluginConnectionHandler::OnBytesRead(const void* Buffer, size_t AvailableByt
 void
 HttpPluginConnectionHandler::HandleRequest()
 {
+	ZEN_ASSERT(m_Server);
+
+	const uint32_t RequestNumber = m_RequestCounter.fetch_add(1);
+
+	ZEN_LOG_TRACE(m_Server->m_RequestLog, "connection #{} ENTER HandleRequest #{}", m_ConnectionId, RequestNumber);
+	auto $Exit =
+		MakeGuard([&] { ZEN_LOG_TRACE(m_Server->m_RequestLog, "connection #{} EXIT HandleRequest #{}", m_ConnectionId, RequestNumber); });
+
 	if (!m_RequestParser.IsKeepAlive())
 	{
 		// Once response has been written, connection is done
 		m_RequestState = RequestState::kWritingFinal;
 
-		// We're not going to read any more data from this socket
-
-		const bool Receive	= true;
-		const bool Transmit = false;
+		const bool Receive	= true;	  // We're not going to read any more data from this socket
+		const bool Transmit = false;  // We will write more data however
 		m_TransportConnection->Shutdown(Receive, Transmit);
 	}
 	else
@@ -300,6 +362,23 @@ HttpPluginConnectionHandler::HandleRequest()
 
 		HttpPluginServerRequest Request(m_RequestParser, *Service, m_RequestParser.Body());
 
+		const HttpVerb		   RequestVerb = Request.RequestVerb();
+		const std::string_view Uri		   = Request.RelativeUri();
+
+		{
+			ZEN_LOG_TRACE(m_Server->m_RequestLog,
+						  "connection #{} Handling Request: {} {} ({} bytes ({}), accept: {})",
+						  m_ConnectionId,
+						  ToString(RequestVerb),
+						  Uri,
+						  Request.ContentLength(),
+						  ToString(Request.RequestContentType()),
+						  ToString(Request.AcceptContentType()));
+
+			m_Server->WriteDebugPayload(fmt::format("request_{}_{}.bin", m_ConnectionId, RequestNumber),
+										std::vector<IoBuffer>{Request.ReadPayload()});
+		}
+
 		if (!HandlePackageOffers(*Service, Request, m_PackageHandler))
 		{
 			try
@@ -340,6 +419,17 @@ HttpPluginConnectionHandler::HandleRequest()
 
 		if (std::unique_ptr<HttpPluginResponse> Response = std::move(Request.m_Response))
 		{
+			{
+				const uint16_t ResponseCode = Response->ResponseCode();
+				ZEN_LOG_TRACE(m_Server->m_RequestLog,
+							  "connection #{} Response: {} {} ({} bytes, {})",
+							  m_ConnectionId,
+							  ResponseCode,
+							  ToString(HttpResponseCode(ResponseCode)),
+							  Response->ContentLength(),
+							  ToString(Response->ContentType()));
+			}
+
 			// Transmit the response
 
 			if (m_RequestParser.RequestVerb() == HttpVerb::kHead)
@@ -349,10 +439,16 @@ HttpPluginConnectionHandler::HandleRequest()
 
 			const std::vector<IoBuffer>& ResponseBuffers = Response->ResponseBuffers();
 
-			//// TODO: should cork/uncork for Linux?
+			m_Server->WriteDebugPayload(fmt::format("response_{}_{}.bin", m_ConnectionId, RequestNumber), ResponseBuffers);
 
 			for (const IoBuffer& Buffer : ResponseBuffers)
 			{
+				ZEN_LOG_TRACE(m_Server->m_RequestLog,
+							  "connection #{} SEND: {} bytes, {}",
+							  m_ConnectionId,
+							  Buffer.GetSize(),
+							  ToString(Buffer.GetContentType()));
+
 				int64_t SentBytes = SendBuffer(Buffer);
 
 				if (SentBytes < 0)
@@ -558,8 +654,9 @@ HttpPluginServerRequest::TryGetRanges(HttpRanges& Ranges)
 
 //////////////////////////////////////////////////////////////////////////
 
-HttpPluginServerImpl::HttpPluginServerImpl()
+HttpPluginServerImpl::HttpPluginServerImpl() : m_RequestLog(logging::Get("http_requests"))
 {
+	m_RequestLog.SetLogLevel(logging::level::Trace);
 }
 
 HttpPluginServerImpl::~HttpPluginServerImpl()
@@ -570,13 +667,19 @@ TransportServerConnection*
 HttpPluginServerImpl::CreateConnectionHandler(TransportConnection* Connection)
 {
 	HttpPluginConnectionHandler* Handler{new HttpPluginConnectionHandler()};
-	Handler->Initialize(Connection, *this);
+	const uint32_t				 ConnectionId = m_ConnectionIdCounter.fetch_add(1);
+	Handler->Initialize(Connection, *this, ConnectionId);
 	return Handler;
 }
 
 int
-HttpPluginServerImpl::Initialize(int BasePort)
+HttpPluginServerImpl::Initialize(int BasePort, std::filesystem::path DataDir)
 {
+	m_DataDir	 = DataDir;
+	m_PayloadDir = DataDir / "debug" / GetSessionIdString();
+
+	ZEN_INFO("any debug payloads will be written to '{}'", m_PayloadDir);
+
 	try
 	{
 		RwLock::ExclusiveLockScope _(m_Lock);
@@ -742,6 +845,18 @@ HttpPluginServerImpl::RouteRequest(std::string_view Url)
 	return CandidateService;
 }
 
+void
+HttpPluginServerImpl::WriteDebugPayload(std::string_view Filename, const std::span<const IoBuffer> Payload)
+{
+	std::vector<const IoBuffer*> Buffers;
+	for (auto& Io : Payload)
+	{
+		Buffers.push_back(&Io);
+	}
+
+	WriteFile(m_PayloadDir / Filename, Buffers.data(), Buffers.size());
+}
+
 //////////////////////////////////////////////////////////////////////////
 
 struct HttpPluginServerImpl;