From 8a16ecbce90582c7ffdeade78644e93948563e37 Mon Sep 17 00:00:00 2001 From: Niels Sascha Reedijk Date: Sun, 14 Aug 2022 14:53:48 +0100 Subject: [PATCH] NetServices: Add debugging constants and messages These allow for additional messages about the progress/status of the request. For now, the messages are sent unconditionally, though it may be reasonable to in the future switch to sending them only when enabled. Change-Id: Ic45a0055037af02c689494fa5ce0acd03592ad7e --- docs/user/book.dox | 4 +- docs/user/netservices/NetServicesDefs.dox | 30 ++++++- .../private/netservices2/NetServicesDefs.h | 6 ++ .../network/libnetservices2/HttpSession.cpp | 83 ++++++++----------- .../kits/net/netservices2/HttpDebugLogger.cpp | 23 ++++- .../net/netservices2/HttpProtocolTest.cpp | 5 ++ 6 files changed, 97 insertions(+), 54 deletions(-) diff --git a/docs/user/book.dox b/docs/user/book.dox index bf1ef097e5..09e191eb57 100644 --- a/docs/user/book.dox +++ b/docs/user/book.dox @@ -678,7 +678,7 @@ snooze_until(time - Latency(), B_SYSTEM_TIMEBASE); - \ref BPrivate::Network::UrlEvent::HttpRedirect "UrlEvent::HttpRedirect + \ref BPrivate::Network::UrlEvent::HttpRedirect "UrlEvent::HttpRedirect" The network services kit is handling a HTTP redirect. The request will be repeated for a new URL. @@ -768,7 +768,7 @@ snooze_until(time - Latency(), B_SYSTEM_TIMEBASE); \ref BPrivate::Network::UrlEventData::Id "UrlEventData::Id" \c int32
\ref BPrivate::Network::UrlEventData::DebugType "UrlEventData::DebugType" - \c int32
+ \c uint32
\ref BPrivate::Network::UrlEventData::DebugMessage "UrlEventData::DebugMessage" \ref BString diff --git a/docs/user/netservices/NetServicesDefs.dox b/docs/user/netservices/NetServicesDefs.dox index 767822ba59..58a4aa51c9 100644 --- a/docs/user/netservices/NetServicesDefs.dox +++ b/docs/user/netservices/NetServicesDefs.dox @@ -410,7 +410,10 @@ namespace Network { /*! \var const char* UrlEventData::DebugType - \brief An \c int32 representing a debug type constant. + \brief An \c uint32 representing a debug type constant. + + The value is one of \ref UrlEventData::DebugError, \ref UrlEventData::DebugWarning or + \ref UrlEventData::DebugInfo. \since Haiku R1 */ @@ -424,6 +427,31 @@ namespace Network { */ +/*! + \var UrlEventData::DebugInfo + \brief Value for \ref UrlEventData::DebugType indicating that the message is an info messsage. + + \since Haiku R1 +*/ + + +/*! + \var UrlEventData::DebugWarning + \brief Value for \ref UrlEventData::DebugType indicating that the message is a warning + messsage. + + \since Haiku R1 +*/ + + +/*! + \var UrlEventData::DebugError + \brief Value for \ref UrlEventData::DebugType indicating that the message is an error messsage. + + \since Haiku R1 +*/ + + } // namespace Network } // namespace BPrivate diff --git a/headers/private/netservices2/NetServicesDefs.h b/headers/private/netservices2/NetServicesDefs.h index 8e3f2f4854..6fae2382ff 100644 --- a/headers/private/netservices2/NetServicesDefs.h +++ b/headers/private/netservices2/NetServicesDefs.h @@ -105,6 +105,12 @@ namespace UrlEventData { extern const char* Success; extern const char* DebugType; extern const char* DebugMessage; + + enum { + DebugInfo = '_DBI', + DebugWarning = '_DBW', + DebugError = '_DBE' + }; } } diff --git a/src/kits/network/libnetservices2/HttpSession.cpp b/src/kits/network/libnetservices2/HttpSession.cpp index 0a94285a34..b24ce745eb 100644 --- a/src/kits/network/libnetservices2/HttpSession.cpp +++ b/src/kits/network/libnetservices2/HttpSession.cpp @@ -244,11 +244,10 @@ BHttpSession::Impl::Execute(BHttpRequest&& request, std::unique_ptr tar return retval; } -#include + void BHttpSession::Impl::Cancel(int32 identifier) { - std::cout << "BHttpSession::Impl::Cancel for " << identifier << std::endl; auto lock = AutoLocker(fLock); // Check if the item is on the control queue fControlQueue.remove_if([&identifier](auto& request){ @@ -313,14 +312,11 @@ BHttpSession::Impl::ControlThreadFunc(void* arg) continue; for (auto& request: requests) { - std::cout << "ControlThreadFunc(): processing request " << request.Id() << std::endl; - bool hasError = false; try { request.ResolveHostName(); request.OpenConnection(); } catch (...) { - std::cout << "ControlThreadFunc()[" << request.Id() << "] error resolving/connecting" << std::endl; request.SetError(std::current_exception()); hasError = true; } @@ -347,7 +343,6 @@ BHttpSession::Impl::ControlThreadFunc(void* arg) wait_for_thread(impl->fDataThread, &threadResult); // Cancel all requests for (auto& request: impl->fControlQueue) { - std::cout << "ControlThreadFunc()[" << request.Id() << "] canceling request because the session is quitting" << std::endl; try { throw BNetworkRequestError(__PRETTY_FUNCTION__, BNetworkRequestError::Canceled); } catch (...) { @@ -382,7 +377,6 @@ BHttpSession::Impl::DataThreadFunc(void* arg) continue; else if (status < 0) { // Something went inexplicably wrong - std::cout << "BSystemError wait_for_objects() " << status << std::endl; throw BSystemError("wait_for_objects()", status); } @@ -422,7 +416,6 @@ BHttpSession::Impl::DataThreadFunc(void* arg) for (auto it = data->connectionMap.cbegin(); it != data->connectionMap.cend(); it++) { offset++; if (it->second.Id() == id) { - std::cout << "DataThreadFunc() [" << id << "] cancelling request" << std::endl; data->objectList[offset].events = EVENT_CANCELLED; break; } @@ -442,12 +435,10 @@ BHttpSession::Impl::DataThreadFunc(void* arg) continue; if ((item.events & B_EVENT_WRITE) == B_EVENT_WRITE) { auto& request = data->connectionMap.find(item.object)->second; - std::cout << "DataThreadFunc() [" << request.Id() << "] ready for sending the request" << std::endl; auto error = false; try { request.TransferRequest(); } catch (...) { - std::cout << "DataThreadFunc() [" << request.Id() << "] error sending the request" << std::endl; request.SetError(std::current_exception()); error = true; } @@ -462,7 +453,6 @@ BHttpSession::Impl::DataThreadFunc(void* arg) } } else if ((item.events & B_EVENT_READ) == B_EVENT_READ) { auto& request = data->connectionMap.find(item.object)->second; - std::cout << "DataThreadFunc() [" << request.Id() << "] ready for receiving the response" << std::endl; auto finished = false; try { if (request.CanCancel()) @@ -471,8 +461,6 @@ BHttpSession::Impl::DataThreadFunc(void* arg) finished = request.ReceiveResult(); } catch (const Redirect& r) { // Request is redirected, send back to the controlThread - std::cout << "DataThreadFunc() [" << request.Id() << "] will be redirected to " << r.url.UrlString().String() << std::endl; - // Move existing request into a new request and hand over to the control queue auto lock = AutoLocker(data->fLock); data->fControlQueue.emplace_back(request, r); @@ -519,31 +507,29 @@ BHttpSession::Impl::DataThreadFunc(void* arg) } else { // Likely to be B_EVENT_INVALID. This should not happen auto& request = data->connectionMap.find(item.object)->second; - std::cout << "DataThreadFunc() [" << request.Id() << "] other event " << item.events << std::endl; - throw BRuntimeError(__PRETTY_FUNCTION__, "Socket was deleted at an unexpected time"); + request.SendMessage(UrlEvent::DebugMessage, [](BMessage& msg){ + msg.AddUInt32(UrlEventData::DebugType, UrlEventData::DebugError); + msg.AddString(UrlEventData::DebugMessage, "Unexpected event; socket deleted?"); + }); + throw BRuntimeError(__PRETTY_FUNCTION__, + "Socket was deleted at an unexpected time"); } } // Reset objectList data->objectList[0].events = B_EVENT_ACQUIRE_SEMAPHORE; - if (resizeObjectList) { - std::cout << "DataThreadFunc() resizing objectlist to " << data->connectionMap.size() + 1 << std::endl; + if (resizeObjectList) data->objectList.resize(data->connectionMap.size() + 1); - } + auto i = 1; for (auto it = data->connectionMap.cbegin(); it != data->connectionMap.cend(); it++) { data->objectList[i].object = it->first; - if (it->second.State() == Request::InitialState) { - std::cout << "DataThreadFunc() [" << it->second.Id() << "] in Request::InitialState" << std::endl; + if (it->second.State() == Request::InitialState) throw BRuntimeError(__PRETTY_FUNCTION__, "Invalid state of request"); - } - else if (it->second.State() == Request::Connected) { + else if (it->second.State() == Request::Connected) data->objectList[i].events = B_EVENT_WRITE | B_EVENT_DISCONNECTED; - std::cout << "DataThreadFunc() [ " << it->second.Id() << "] wait for B_EVENT_WRITE" << std::endl; - } else { - std::cout << "DataThreadFunc() [ " << it->second.Id() << "] wait for B_EVENT_READ" << std::endl; + else data->objectList[i].events = B_EVENT_READ | B_EVENT_DISCONNECTED; - } i++; } } @@ -552,14 +538,12 @@ BHttpSession::Impl::DataThreadFunc(void* arg) // Cancel all requests for (auto it = data->connectionMap.begin(); it != data->connectionMap.end(); it++) { try { - std::cout << "DataThreadFunc() [ " << it->second.Id() << "] canceling request because we are quitting" << std::endl; throw BNetworkRequestError(__PRETTY_FUNCTION__, BNetworkRequestError::Canceled); } catch (...) { it->second.SetError(std::current_exception()); } } } else { - std::cout << "DataThreadFunc(): Unknown reason that the dataQueueSem is deleted" << std::endl; throw BRuntimeError(__PRETTY_FUNCTION__, "Unknown reason that the dataQueueSem is deleted"); } @@ -578,7 +562,6 @@ std::vector BHttpSession::Impl::GetRequestsForControlThread() { std::vector requests; - std::cout << __PRETTY_FUNCTION__ << ": number of items in fConnectionCount: " << fConnectionCount.size() << std::endl; // Clean up connection list if it is at the max number of hosts if (fConnectionCount.size() >= fMaxHosts.load()) { @@ -597,10 +580,13 @@ BHttpSession::Impl::GetRequestsForControlThread() auto host = request.GetHost(); auto it = fConnectionCount.find(host); if (it != fConnectionCount.end()) { - std::cout << __PRETTY_FUNCTION__ << ": found connnections for host, count: " << it->second << std::endl; if (static_cast(atomic_get(std::addressof(it->second))) >= fMaxConnectionsPerHost.load(std::memory_order_relaxed)) { - std::cout << "\tskip loading this request as max connections per host is reached" << std::endl; + request.SendMessage(UrlEvent::DebugMessage, [](BMessage& msg){ + msg.AddUInt32(UrlEventData::DebugType, UrlEventData::DebugWarning); + msg.AddString(UrlEventData::DebugMessage, + "Request is queued: too many active connections for host"); + }); return false; } else { atomic_add(std::addressof(it->second), 1); @@ -608,7 +594,11 @@ BHttpSession::Impl::GetRequestsForControlThread() } } else { if (fConnectionCount.size() == fMaxHosts.load()) { - std::cout << "\tskip loading this request as max hosts is reached" << std::endl; + request.SendMessage(UrlEvent::DebugMessage, [](BMessage& msg){ + msg.AddUInt32(UrlEventData::DebugType, UrlEventData::DebugWarning); + msg.AddString(UrlEventData::DebugMessage, + "Request is queued: maximum number of concurrent hosts"); + }); return false; } auto[newIt, success] = fConnectionCount.insert({host, 1}); @@ -728,6 +718,18 @@ void BHttpSession::Request::SetError(std::exception_ptr e) { fResult->SetError(e); + SendMessage(UrlEvent::DebugMessage, [&e](BMessage& msg){ + msg.AddUInt32(UrlEventData::DebugType, UrlEventData::DebugError); + try { + std::rethrow_exception(e); + } catch (BError& error) { + msg.AddString(UrlEventData::DebugMessage, error.DebugMessage()); + } catch (std::exception& error) { + msg.AddString(UrlEventData::DebugMessage, error.what()); + } catch (...) { + msg.AddString(UrlEventData::DebugMessage, "Unknown exception"); + } + }); SendMessage(UrlEvent::RequestCompleted, [](BMessage& msg){ msg.AddBool(UrlEventData::Success, false); }); @@ -819,8 +821,6 @@ BHttpSession::Request::OpenConnection() void BHttpSession::Request::TransferRequest() { - std::cout << "TransferRequest() [" << Id() << "] Starting sending of request" << std::endl; - // Assert that we are in the right state if (fRequestStatus != Connected) throw BRuntimeError(__PRETTY_FUNCTION__, @@ -841,10 +841,6 @@ BHttpSession::Request::TransferRequest() if (fSerializer.Complete()) fRequestStatus = RequestSent; - - std::cout << "TransferRequest() [" << Id() << "] currentBytesWritten: " << currentBytesWritten << " totalBytesWritten: " << - fSerializer.BodyBytesTransferred() << " totalSize: " << fSerializer.BodyBytesTotal().value_or(0) << " complete: " - << fSerializer.Complete() << std::endl; } @@ -859,11 +855,8 @@ BHttpSession::Request::ReceiveResult() // First: stream data from the socket auto bytesRead = fBuffer.ReadFrom(fSocket.get()); - if (bytesRead == B_WOULD_BLOCK || bytesRead == B_INTERRUPTED) { + if (bytesRead == B_WOULD_BLOCK || bytesRead == B_INTERRUPTED) return false; - } - - std::cout << "ReceiveResult() [" << Id() << "] read " << bytesRead << " from socket" << std::endl; // Parse the content in the buffer switch (fRequestStatus) { @@ -954,7 +947,6 @@ BHttpSession::Request::ReceiveResult() case BHttpStatusCode::TemporaryRedirect: case BHttpStatusCode::PermanentRedirect: { - std::cout << "ReceiveResult() [" << Id() << "] Handle redirect with status: " << fStatus.code << std::endl; auto locationField = fFields.FindField("Location"); if (locationField == fFields.end()) { throw BNetworkRequestError(__PRETTY_FUNCTION__, @@ -996,7 +988,6 @@ BHttpSession::Request::ReceiveResult() if (!fParser.HasContent()) { // Any requests with not content are finished - std::cout << "ReceiveResult() [" << Id() << "] Request is completing without content" << std::endl; fResult->SetBody(); SendMessage(UrlEvent::RequestCompleted, [](BMessage& msg) { msg.AddBool(UrlEventData::Success, true); @@ -1016,9 +1007,6 @@ BHttpSession::Request::ReceiveResult() return bytesWrittenToBody; }); - std::cout << "ReceiveResult() [" << Id() << "] body bytes current read/total received/total expected: " << - bytesRead << "/" << fParser.BodyBytesTransferred() << "/" << fParser.BodyBytesTotal().value_or(0) << std::endl; - SendMessage(UrlEvent::DownloadProgress, [this, bytesRead](BMessage& msg) { msg.AddInt64(UrlEventData::NumBytes, bytesRead); if (fParser.BodyBytesTotal()) @@ -1032,7 +1020,6 @@ BHttpSession::Request::ReceiveResult() } if (fParser.Complete()) { - std::cout << "ReceiveResult() [" << Id() << "] received all body bytes: " << fParser.BodyBytesTransferred() << std::endl; fResult->SetBody(); SendMessage(UrlEvent::RequestCompleted, [](BMessage& msg) { msg.AddBool(UrlEventData::Success, true); diff --git a/src/tests/kits/net/netservices2/HttpDebugLogger.cpp b/src/tests/kits/net/netservices2/HttpDebugLogger.cpp index 5ffa1d4813..9b3934e417 100644 --- a/src/tests/kits/net/netservices2/HttpDebugLogger.cpp +++ b/src/tests/kits/net/netservices2/HttpDebugLogger.cpp @@ -113,8 +113,7 @@ HttpDebugLogger::MessageReceived(BMessage* message) } case UrlEvent::RequestCompleted: { - bool success = false; - message->FindBool(UrlEventData::Success, &success); + bool success = message->GetBool(UrlEventData::Success, false); output << " success: "; if (success) output << "true"; @@ -124,7 +123,25 @@ HttpDebugLogger::MessageReceived(BMessage* message) } case UrlEvent::DebugMessage: { - output << "UrlEvent::DebugMessage"; + uint32 debugType = message->GetUInt32(UrlEventData::DebugType, 0); + BString debugMessage; + message->FindString(UrlEventData::DebugMessage, &debugMessage); + output << " "; + switch (debugType) { + case UrlEventData::DebugInfo: + output << "INFO: "; + break; + case UrlEventData::DebugWarning: + output << "WARNING: "; + break; + case UrlEventData::DebugError: + output << "ERROR: "; + break; + default: + output << "UNKNOWN: "; + break; + } + output << debugMessage; break; } default: diff --git a/src/tests/kits/net/netservices2/HttpProtocolTest.cpp b/src/tests/kits/net/netservices2/HttpProtocolTest.cpp index 405fe13b0c..83b984100e 100644 --- a/src/tests/kits/net/netservices2/HttpProtocolTest.cpp +++ b/src/tests/kits/net/netservices2/HttpProtocolTest.cpp @@ -786,6 +786,11 @@ HttpIntegrationTest::PostTest() auto id = observer->messages[0].GetInt32(BPrivate::Network::UrlEventData::Id, -1); CPPUNIT_ASSERT_EQUAL_MESSAGE("message Id does not match", result.Identity(), id); + if (message.what == BPrivate::Network::UrlEvent::DebugMessage) { + // ignore debug messages + continue; + } + switch(previousMessage) { case 0: CPPUNIT_ASSERT_MESSAGE("message should be HostNameResolved",