NetServices: Implement a logger for requests.

This logger can print to console or log to file.

Change-Id: I7eef847d42b360af1cb7cec0c897131b975a1f2f

src/tests/kits/net/netservices2/HttpDebugLogger.cpp

@@ -0,0 +1,144 @@
+/*
+ * Copyright 2022 Haiku Inc. All rights reserved.
+ * Distributed under the terms of the MIT License.
+ *
+ * Authors:
+ *		Niels Sascha Reedijk, [email protected]
+ */
+
+#include "HttpDebugLogger.h"
+
+#include <iostream>
+
+#include <ErrorsExt.h>
+#include <HttpSession.h>
+#include <NetServicesDefs.h>
+
+using namespace BPrivate::Network;
+
+
+HttpDebugLogger::HttpDebugLogger()
+	: BLooper("HttpDebugLogger")
+{
+
+}
+
+
+void
+HttpDebugLogger::SetConsoleLogging(bool enabled)
+{
+	fConsoleLogging = enabled;
+}
+
+
+void
+HttpDebugLogger::SetFileLogging(const char* path)
+{
+	if (auto status = fLogFile.SetTo(path, B_WRITE_ONLY | B_CREATE_FILE | B_OPEN_AT_END);
+		status != B_OK)
+		throw BSystemError("BFile::SetTo()", status);
+}
+
+void
+HttpDebugLogger::MessageReceived(BMessage* message)
+{
+	BString output;
+
+	if (!message->HasInt32(UrlEventData::Id))
+		return BLooper::MessageReceived(message);
+	int32 id = message->FindInt32(UrlEventData::Id);
+	output << "[" << id << "] ";
+
+	switch (message->what) {
+	case UrlEvent::HostNameResolved:
+	{
+		BString hostname;
+		message->FindString(UrlEventData::HostName, &hostname);
+		output << "<HostNameResolved> " << hostname;
+		break;
+	}
+	case UrlEvent::ConnectionOpened:
+		output << "<ConnectionOpened>";
+		break;
+	case UrlEvent::UploadProgress:
+	{
+		off_t numBytes = message->GetInt64(UrlEventData::NumBytes, -1);
+		off_t totalBytes = message->GetInt64(UrlEventData::TotalBytes, -1);
+		output << "<UploadProgress> bytes uploaded " << numBytes;
+		if (totalBytes == -1)
+			output << " (total unknown)";
+		else
+			output << " (" << totalBytes << " total)";
+		break;
+	}
+	case UrlEvent::ResponseStarted:
+	{
+		output << "<ResponseStarted>";
+		break;
+	}
+	case UrlEvent::HttpRedirect:
+	{
+		BString redirectUrl;
+		message->FindString(UrlEventData::HttpRedirectUrl, &redirectUrl);
+		output << "<HttpRedirect> to: " << redirectUrl;
+		break;
+	}
+	case UrlEvent::HttpStatus:
+	{
+		int16 status = message->FindInt16(UrlEventData::HttpStatusCode);
+		output << "<HttpStatus> code: " << status;
+		break;
+	}
+	case UrlEvent::HttpFields:
+	{
+		output << "<HttpFields> All fields parsed";
+		break;
+	}
+	case UrlEvent::DownloadProgress:
+	{
+		off_t numBytes = message->GetInt64(UrlEventData::NumBytes, -1);
+		off_t totalBytes = message->GetInt64(UrlEventData::TotalBytes, -1);
+		output << "<DownloadProgress> bytes downloaded " << numBytes;
+		if (totalBytes == -1)
+			output << " (total unknown)";
+		else
+			output << " (" << totalBytes << " total)";
+		break;
+	}
+	case UrlEvent::BytesWritten:
+	{
+		off_t numBytes = message->GetInt64(UrlEventData::NumBytes, -1);
+		output << "<BytesWritten> bytes written to output: " << numBytes;
+		break;
+	}
+	case UrlEvent::RequestCompleted:
+	{
+		bool success = false;
+		message->FindBool(UrlEventData::Success, &success);
+		output << "<RequestCompleted> success: ";
+		if (success)
+			output << "true";
+		else
+			output << "false";
+		break;
+	}
+	case UrlEvent::DebugMessage:
+	{
+		output << "UrlEvent::DebugMessage";
+		break;
+	}
+	default:
+		return BLooper::MessageReceived(message);
+	}
+
+	if (fConsoleLogging)
+		std::cout << output.String() << std::endl;
+
+	if (fLogFile.InitCheck() == B_OK) {
+		output += '\n';
+		if (auto status = fLogFile.WriteExactly(output.String(), output.Length()); status != B_OK)
+			throw BSystemError("BFile::WriteExactly()", status);
+		if (auto status = fLogFile.Flush(); status != B_OK)
+			throw BSystemError("BFile::Flush()", status);
+	}
+}

src/tests/kits/net/netservices2/HttpDebugLogger.h

@@ -0,0 +1,27 @@
+/*
+ * Copyright 2021 Haiku, inc.
+ * Distributed under the terms of the MIT License.
+ */
+#ifndef HTTP_DEBUG_LOGGER_H
+#define HTTP_DEBUG_LOGGER_H
+
+#include <File.h>
+#include <Looper.h>
+
+
+class HttpDebugLogger : public BLooper
+{
+public:
+					HttpDebugLogger();
+			void	SetConsoleLogging(bool enabled = true);
+			void	SetFileLogging(const char* path);
+
+protected:
+	virtual	void	MessageReceived(BMessage* message) override;
+
+private:
+			bool	fConsoleLogging = false;
+			BFile	fLogFile;
+};
+
+#endif // HTTP_DEBUG_LOGGER_H

src/tests/kits/net/netservices2/HttpProtocolTest.cpp

@@ -36,6 +36,10 @@ using BPrivate::Network::parse_http_time;
 
 using namespace std::literals;
 
+// Logger settings
+constexpr bool LOG_ENABLED = true;
+constexpr bool LOG_TO_CONSOLE = false;
+
 
 HttpProtocolTest::HttpProtocolTest()
 {
@@ -400,6 +404,17 @@ HttpIntegrationTest::HttpIntegrationTest(TestServerMode mode)
 {
 	// increase number of concurrent connections to 4 (from 2)
 	fSession.SetMaxConnectionsPerHost(4);
+
+	if constexpr (LOG_ENABLED) {
+		fLogger = new HttpDebugLogger();
+		fLogger->SetConsoleLogging(LOG_TO_CONSOLE);
+		if (mode == TestServerMode::Http)
+			fLogger->SetFileLogging("http-messages.log");
+		else
+			fLogger->SetFileLogging("https-messages.log");
+		fLogger->Run();
+		fLoggerMessenger.SetTo(fLogger);
+	}
 }
 
 
@@ -413,6 +428,16 @@ HttpIntegrationTest::setUp()
 }
 
 
+void
+HttpIntegrationTest::tearDown()
+{
+	if (fLogger) {
+		fLogger->Lock();
+		fLogger->Quit();
+	}
+}
+
+
 /* static */ void
 HttpIntegrationTest::AddTests(BTestSuite& parent)
 {
@@ -485,7 +510,7 @@ HttpIntegrationTest::HostAndNetworkFailTest()
 	{
 		// FIXME: find a better way to get an unused local port, instead of hardcoding one
 		auto request = BHttpRequest(BUrl("http://localhost:59445/"));
-		auto result = fSession.Execute(std::move(request));
+		auto result = fSession.Execute(std::move(request), nullptr, fLoggerMessenger);
 		try {
 			result.Status();
 			CPPUNIT_FAIL("Expecting exception when trying to connect to invalid hostname");
@@ -520,7 +545,7 @@ void
 HttpIntegrationTest::GetTest()
 {
 	auto request = BHttpRequest(BUrl(fTestServer.BaseUrl(), "/"));
-	auto result = fSession.Execute(std::move(request));
+	auto result = fSession.Execute(std::move(request), nullptr, fLoggerMessenger);
 	try {
 		auto receivedFields = result.Fields();
 
@@ -546,7 +571,7 @@ HttpIntegrationTest::HeadTest()
 {
 	auto request = BHttpRequest(BUrl(fTestServer.BaseUrl(), "/"));
 	request.SetMethod(BHttpMethod::Head);
-	auto result = fSession.Execute(std::move(request));
+	auto result = fSession.Execute(std::move(request),  nullptr, fLoggerMessenger);
 	try {
 		auto receivedFields = result.Fields();
 		CPPUNIT_ASSERT_EQUAL_MESSAGE("Mismatch in number of headers",
@@ -577,7 +602,7 @@ void
 HttpIntegrationTest::NoContentTest()
 {
 	auto request = BHttpRequest(BUrl(fTestServer.BaseUrl(), "/204"));
-	auto result = fSession.Execute(std::move(request));
+	auto result = fSession.Execute(std::move(request),  nullptr, fLoggerMessenger);
 	try {
 		auto receivedStatus = result.Status();
 		CPPUNIT_ASSERT_EQUAL(204, receivedStatus.code);
@@ -605,7 +630,7 @@ void
 HttpIntegrationTest::AutoRedirectTest()
 {
 	auto request = BHttpRequest(BUrl(fTestServer.BaseUrl(), "/302"));
-	auto result = fSession.Execute(std::move(request));
+	auto result = fSession.Execute(std::move(request),  nullptr, fLoggerMessenger);
 	try {
 		auto receivedFields = result.Fields();
 
@@ -632,14 +657,14 @@ HttpIntegrationTest::BasicAuthTest()
 	// Basic Authentication
 	auto request = BHttpRequest(BUrl(fTestServer.BaseUrl(), "/auth/basic/walter/secret"));
 	request.SetAuthentication({"walter", "secret"});
-	auto result = fSession.Execute(std::move(request));
+	auto result = fSession.Execute(std::move(request),  nullptr, fLoggerMessenger);
 	CPPUNIT_ASSERT(result.Status().code == 200);
 
 	// Basic Authentication with incorrect credentials
 	try {
 	request = BHttpRequest(BUrl(fTestServer.BaseUrl(), "/auth/basic/walter/secret"));
 	request.SetAuthentication({"invaliduser", "invalidpassword"});
-	result = fSession.Execute(std::move(request));
+	result = fSession.Execute(std::move(request),  nullptr, fLoggerMessenger);
 	CPPUNIT_ASSERT(result.Status().code == 401);
 	} catch (const BPrivate::Network::BError& e) {
 		CPPUNIT_FAIL(e.DebugMessage().String());
@@ -653,7 +678,7 @@ HttpIntegrationTest::StopOnErrorTest()
 	// Test the Stop on Error functionality
 	auto request = BHttpRequest(BUrl(fTestServer.BaseUrl(), "/400"));
 	request.SetStopOnError(true);
-	auto result = fSession.Execute(std::move(request));
+	auto result = fSession.Execute(std::move(request),  nullptr, fLoggerMessenger);
 	CPPUNIT_ASSERT(result.Status().code == 400);
 	CPPUNIT_ASSERT(result.Fields().CountFields() == 0);
 	CPPUNIT_ASSERT(result.Body().text.Length() == 0);
@@ -668,7 +693,7 @@ HttpIntegrationTest::RequestCancelTest()
 	//       processed. In practise, the cancellation always comes first. When the server
 	//       supports a wait parameter, then this test can be made more robust.
 	auto request = BHttpRequest(BUrl(fTestServer.BaseUrl(), "/"));
-	auto result = fSession.Execute(std::move(request));
+	auto result = fSession.Execute(std::move(request),  nullptr, fLoggerMessenger);
 	fSession.Cancel(result);
 	try {
 		result.Body();
@@ -745,6 +770,13 @@ HttpIntegrationTest::PostTest()
 	usleep(2000); // give some time to catch up on receiving all messages
 
 	observer->Lock();
+	while (observer->IsMessageWaiting())
+	{
+		observer->Unlock();
+		usleep(1000); // give some time to catch up on receiving all messages
+		observer->Lock();
+	}
+
 	// Assert that the messages have the right contents.
 	CPPUNIT_ASSERT_MESSAGE("Expected at least 8 observer messages for this request.",
 		observer->messages.size() >= 8);

src/tests/kits/net/netservices2/HttpProtocolTest.h

@@ -11,6 +11,7 @@
 #include <TestSuite.h>
 #include <tools/cppunit/ThreadedTestCase.h>
 
+#include "HttpDebugLogger.h"
 #include "TestServer.h"
 
 using BPrivate::Network::BHttpSession;
@@ -35,7 +36,7 @@ public:
 					HttpIntegrationTest(TestServerMode mode);
 
 	virtual	void		setUp() override;
-
+	virtual void		tearDown() override;
 
 			void	HostAndNetworkFailTest();
 			void	GetTest();
@@ -50,8 +51,10 @@ public:
 	static	void	AddTests(BTestSuite& suite);
 
 private:
-			TestServer		fTestServer;
-			BHttpSession	fSession;
+			TestServer			fTestServer;
+			BHttpSession		fSession;
+			HttpDebugLogger*	fLogger;
+			BMessenger			fLoggerMessenger;
 };
 
 #endif

src/tests/kits/net/netservices2/Jamfile

@@ -7,6 +7,7 @@ if $(TARGET_PACKAGING_ARCH) != x86_gcc2 {
 	UnitTestLib netservicekit2test.so :
 		ServicesKitTestAddon.cpp
 
+		HttpDebugLogger.cpp
 		HttpProtocolTest.cpp
 		TestServer.cpp