From 9a767574ff874456a0499a2829ddfae8cb5b9935 Mon Sep 17 00:00:00 2001 From: Vadim Zeitlin Date: Thu, 8 Jan 2026 12:55:03 +0100 Subject: [PATCH] Add wxWebRequestDebugLogger for details logging of HTTP transfers Allow getting detailed information about the operations performed by wxWebRequest, at least when using libcurl-based backend, which provides good built-in support for this, and partially when using WinHTTP. Note that the debug logger is set at the session level and not for each request: this is less flexible, but more convenient and is probably how it will always be used in practice. See #26086. --- include/wx/msw/private/webrequest_winhttp.h | 4 + include/wx/private/webrequest.h | 11 ++ include/wx/webrequest.h | 33 +++++ interface/wx/webrequest.h | 127 ++++++++++++++++++ src/common/webrequest.cpp | 8 ++ src/common/webrequest_curl.cpp | 92 +++++++++++++ src/msw/webrequest_winhttp.cpp | 139 +++++++++++++++++++- tests/net/webrequest.cpp | 50 +++++++ 8 files changed, 459 insertions(+), 5 deletions(-) diff --git a/include/wx/msw/private/webrequest_winhttp.h b/include/wx/msw/private/webrequest_winhttp.h index 35231eec5a..ad6bdee829 100644 --- a/include/wx/msw/private/webrequest_winhttp.h +++ b/include/wx/msw/private/webrequest_winhttp.h @@ -170,6 +170,10 @@ private: return Fail(operation, ::GetLastError()); } + // Log all the headers of the response if debug logging is enabled. + void LogResponseHeadersIfNecessary(); + + // These functions can only be used for asynchronous requests. void SetFailed(const wxString& operation, DWORD errorCode) { diff --git a/include/wx/private/webrequest.h b/include/wx/private/webrequest.h index 9ae251a5bb..e7ada0051f 100644 --- a/include/wx/private/webrequest.h +++ b/include/wx/private/webrequest.h @@ -362,11 +362,22 @@ public: virtual bool EnablePersistentStorage(bool WXUNUSED(enable)) { return false; } + void SetDebugLogger(std::unique_ptr logger) + { m_debugLogger = std::move(logger); } + + // Return raw, non owning pointer to the debug logger (may be null). + wxWebRequestDebugLogger* GetDebugLogger() const + { return m_debugLogger.get(); } + protected: explicit wxWebSessionImpl(Mode mode); bool IsAsync() const { return m_mode == Mode::Async; } + + // If non-null, use it to log debug information. + std::unique_ptr m_debugLogger; + private: // Make it a friend to allow accessing our m_headers. friend class wxWebRequest; diff --git a/include/wx/webrequest.h b/include/wx/webrequest.h index 620b67d2a0..4a3967c139 100644 --- a/include/wx/webrequest.h +++ b/include/wx/webrequest.h @@ -135,6 +135,37 @@ protected: wxWebResponseImplPtr m_impl; }; +// Base class for logging debug information from web requests. +class wxWebRequestDebugLogger +{ +public: + wxWebRequestDebugLogger() = default; + virtual ~wxWebRequestDebugLogger() = default; + + // Informational message not directly corresponding to any data sent or + // received. + virtual void OnInfo(const wxString& info) = 0; + + // Request sent to the server, e.g. "GET /index.html HTTP/1.1". + virtual void OnRequestSent(const wxString& line) = 0; + + // Response received from the server, e.g. "HTTP/1.1 200 OK". + virtual void OnResponseReceived(const wxString& line) = 0; + + // Header sent to the server. + virtual void OnHeaderSent(const wxString& name, const wxString& value) = 0; + + // Header received from the server. + virtual void OnHeaderReceived(const wxString& name, const wxString& value) = 0; + + // Data sent to the server. This data may be binary and encrypted when + // using HTTPS, so it is typically not human-readable. + virtual void OnDataSent(const void* data, size_t size) = 0; + + // Data received from the server. Same remarks as for OnDataSent() apply. + virtual void OnDataReceived(const void* data, size_t size) = 0; +}; + class WXDLLIMPEXP_NET wxWebRequestBase { public: @@ -395,6 +426,8 @@ public: bool EnablePersistentStorage(bool enable = true); + void SetDebugLogger(std::unique_ptr logger); + wxWebSessionHandle GetNativeHandle() const; private: diff --git a/interface/wx/webrequest.h b/interface/wx/webrequest.h index e692b94dd3..a4bfb1c6f0 100644 --- a/interface/wx/webrequest.h +++ b/interface/wx/webrequest.h @@ -1312,6 +1312,103 @@ public: static wxWebProxy Default(); }; +/** + Base class for logging debug information from web requests. + + An object of a class derived from this one may be associated with a + wxWebSession or wxWebSessionSync using wxWebSession::SetDebugLogger() in + order to receive detailed information about the data exchanged with the + HTTP server. + + Once this object is associated with a session, its member functions will be + called to report various events happening during the request processing. + + libcurl-based backend provides the most full-featured logging, with WinHTTP + backend providing only limited information and NSURLSession-based backend + currently not providing any logging at all. + + @since 3.3.2 + + @library{wxnet} + @category{net} +*/ +class wxWebRequestDebugLogger +{ +public: + /// Default constructor. + wxWebRequestDebugLogger() = default; + + /** + Called to notify about an informational message. + + For example, the libcurl-based backend provides details about the + protocol used (including TLS version when applicable) and the + connection state using this function. + + @param info A single line informational message. + */ + virtual void OnInfo(const wxString& info) = 0; + + /** + Called with the request line sent to the server. + + A typical example of such a line would be `GET /index.html HTTP/1.1`. + */ + virtual void OnRequestSent(const wxString& line) = 0; + + /** + Called with the status line received from the server. + + A typical example of such a line would be `HTTP/1.1 200 OK`. + */ + virtual void OnResponseReceived(const wxString& line) = 0; + + /** + Called for each header sent to the server. + + This is currently only called when libcurl-based backend is used. + + @param name Name of the header + @param value String value of the header + */ + virtual void OnHeaderSent(const wxString& name, const wxString& value) = 0; + + /** + Called for each header received from the server. + + @param name Name of the header + @param value String value of the header + */ + virtual void OnHeaderReceived(const wxString& name, const wxString& value) = 0; + + /** + Called when other data is sent to the server. + + This data may be binary and encrypted when using HTTPS, so it is + typically not human-readable, although it may be in some cases (e.g. + when using a text body with HTTP POST). + + This is currently only called when libcurl-based backend is used or + when WinHTTP backend is used with synchronous requests. + + @param data Pointer to the received data buffer. + @param size Size of the received data buffer in bytes. + */ + virtual void OnDataSent(const void* data, size_t size) = 0; + + /** + Called when other data is received from the server. + + This data may be binary and encrypted when using HTTPS, so it is + typically not human-readable, although it may be in some cases (e.g. + when receiving a text response body). + + @param data Pointer to the received data buffer. + @param size Size of the received data buffer in bytes. + */ + virtual void OnDataReceived(const void* data, size_t size) = 0; +}; + /** @class wxWebSession @@ -1530,6 +1627,21 @@ public: @since 3.3.0 */ bool EnablePersistentStorage(bool enable); + + /** + Enable debug logging for all requests created by this session. + + If @a logger is non-null, it will be used to log detailed debug + information about the data exchanged with the HTTP server for all + requests created by this session after this function is called. + + @note Calling this function destroys any previously set logger, make + sure there are no active requests using it any more before doing + so to avoid crashes. + + @since 3.3.2 + */ + void SetDebugLogger(std::unique_ptr logger); }; /** @@ -1721,6 +1833,21 @@ public: @note This is only implemented in the macOS backend. */ bool EnablePersistentStorage(bool enable); + + /** + Enable debug logging for all requests created by this session. + + If @a logger is non-null, it will be used to log detailed debug + information about the data exchanged with the HTTP server for all + requests created by this session after this function is called. + + @note Calling this function destroys any previously set logger, make + sure there are no active requests using it any more before doing + so to avoid crashes. + + @since 3.3.2 + */ + void SetDebugLogger(std::unique_ptr logger); }; diff --git a/src/common/webrequest.cpp b/src/common/webrequest.cpp index 726a94c9f4..3606e4d479 100644 --- a/src/common/webrequest.cpp +++ b/src/common/webrequest.cpp @@ -1236,6 +1236,14 @@ bool wxWebSessionBase::EnablePersistentStorage(bool enable) return m_impl->EnablePersistentStorage(enable); } +void +wxWebSessionBase::SetDebugLogger(std::unique_ptr logger) +{ + wxCHECK_IMPL_VOID(); + + m_impl->SetDebugLogger(std::move(logger)); +} + // ---------------------------------------------------------------------------- // Module ensuring all global/singleton objects are destroyed on shutdown. // ---------------------------------------------------------------------------- diff --git a/src/common/webrequest_curl.cpp b/src/common/webrequest_curl.cpp index c43a12cc21..1d26665efa 100644 --- a/src/common/webrequest_curl.cpp +++ b/src/common/webrequest_curl.cpp @@ -346,6 +346,89 @@ static int wxCURLSeek(void* userdata, curl_off_t offset, int origin) return static_cast(userdata)->CURLOnSeek(offset, origin); } +static int +wxCURLDebugFunction(CURL* WXUNUSED(handle), + curl_infotype type, + char* data, + size_t size, + void* userdata) +{ + wxCHECK_MSG( userdata, 0, "invalid curl debug function data" ); + + auto* const logger = static_cast(userdata); + wxString text; + switch ( type ) + { + case CURLINFO_TEXT: + case CURLINFO_HEADER_IN: + case CURLINFO_HEADER_OUT: + text = wxString::FromUTF8(data, size); + break; + + case CURLINFO_DATA_IN: + case CURLINFO_SSL_DATA_IN: + logger->OnDataReceived(data, size); + break; + + case CURLINFO_DATA_OUT: + case CURLINFO_SSL_DATA_OUT: + logger->OnDataSent(data, size); + break; + + case CURLINFO_END: + wxFAIL_MSG("Unexpected CURLINFO_END info type in debug function"); + break; + } + + if ( !text.empty() ) + { + // Remove trailing newline added by libcurl. + text.Trim(); + + if ( type == CURLINFO_TEXT ) + { + // Informational messages are always on single line, so we don't + // need to do anything else with them. + logger->OnInfo(text); + } + else // Header or similar. + { + // We may have multiple lines and each of them may be either a + // header or a request/status line as libcurl reports both of them + // in the same way. + for ( auto const& line: wxSplit(text, '\n') ) + { + wxString value; + auto const name = line.BeforeFirst(':', &value); + + // A correct "start line" (from RFC 7230) can't include a colon + // before a space, so this is a simple way to distinguish it + // from a header field. + if ( value.empty() || name.find(' ') != wxString::npos ) + { + if ( type == CURLINFO_HEADER_IN ) + logger->OnResponseReceived(line); + else // CURLINFO_HEADER_OUT + logger->OnRequestSent(line); + } + else + { + // Remove leading space, if any. + value.Trim(false); + + if ( type == CURLINFO_HEADER_IN ) + logger->OnHeaderReceived(name, value); + else // CURLINFO_HEADER_OUT + logger->OnHeaderSent(name, value); + } + } + } + } + + // We must always return 0 according to libcurl documentation. + return 0; +} + wxWebRequestCURL::wxWebRequestCURL(wxWebSession & session, wxWebSessionCURL& sessionImpl, wxEvtHandler* handler, @@ -529,6 +612,15 @@ wxWebRequest::Result wxWebRequestCURL::DoFinishPrepare() if ( securityFlags & wxWebRequest::Ignore_Host ) wxCURLSetOpt(m_handle, CURLOPT_SSL_VERIFYHOST, 0); + + // Enable debug logging if requested. + if ( auto const* logger = GetSessionImpl().GetDebugLogger() ) + { + wxCURLSetOpt(m_handle, CURLOPT_DEBUGDATA, logger); + wxCURLSetOpt(m_handle, CURLOPT_DEBUGFUNCTION, wxCURLDebugFunction); + wxCURLSetOpt(m_handle, CURLOPT_VERBOSE, 1L); + } + return Result::Ok(); } diff --git a/src/msw/webrequest_winhttp.cpp b/src/msw/webrequest_winhttp.cpp index 2b53fe2b9c..9f27040171 100644 --- a/src/msw/webrequest_winhttp.cpp +++ b/src/msw/webrequest_winhttp.cpp @@ -134,6 +134,9 @@ wxWinHTTP::WinHttpSetTimeouts_t wxWinHTTP::WinHttpSetTimeouts; #ifndef WINHTTP_PROTOCOL_FLAG_HTTP2 #define WINHTTP_PROTOCOL_FLAG_HTTP2 0x1 #endif +#ifndef WINHTTP_PROTOCOL_FLAG_HTTP3 +#define WINHTTP_PROTOCOL_FLAG_HTTP3 0x2 +#endif #ifndef WINHTTP_OPTION_ENABLE_HTTP_PROTOCOL #define WINHTTP_OPTION_ENABLE_HTTP_PROTOCOL 133 #endif @@ -347,12 +350,18 @@ wxWebRequestWinHTTP::HandleCallback(DWORD dwInternetStatus, case WINHTTP_CALLBACK_STATUS_READ_COMPLETE: if ( dwStatusInformationLength > 0 ) { + if ( auto* const logger = GetSessionImpl().GetDebugLogger() ) + logger->OnDataReceived(lpvStatusInformation, dwStatusInformationLength); + m_response->ReportDataReceived(dwStatusInformationLength); if ( !m_response->ReadData() && !WasCancelled() ) SetFailedWithLastError("Reading data"); } else { + if ( auto* const logger = GetSessionImpl().GetDebugLogger() ) + logger->OnInfo("Request completed"); + SetFinalStateFromStatus(); } break; @@ -445,6 +454,8 @@ void wxWebRequestWinHTTP::WriteData() break; } + LogResponseHeadersIfNecessary(); + // Start reading the response, even in unauthorized case. if ( !m_response->ReadData() ) SetFailedWithLastError("Reading data"); @@ -452,6 +463,8 @@ void wxWebRequestWinHTTP::WriteData() return; } + LogResponseHeadersIfNecessary(); + CheckResult(DoWriteData()); } @@ -481,6 +494,12 @@ wxWebRequest::Result wxWebRequestWinHTTP::DoWriteData(DWORD* numWritten) return FailWithLastError("Writing data"); } + if ( numWritten && *numWritten ) + { + if ( auto* const logger = GetSessionImpl().GetDebugLogger() ) + logger->OnDataSent(buffer, *numWritten); + } + return Result::Ok(); } @@ -642,6 +661,8 @@ wxWebRequest::Result wxWebRequestWinHTTP::Execute() continue; } + LogResponseHeadersIfNecessary(); + // Read the response data. for ( ;; ) { @@ -656,6 +677,9 @@ wxWebRequest::Result wxWebRequestWinHTTP::Execute() } // We're done. + if ( auto* const logger = GetSessionImpl().GetDebugLogger() ) + logger->OnInfo("Request completed"); + return GetResultFromHTTPStatus(m_response); } @@ -684,12 +708,19 @@ wxWebRequest::Result wxWebRequestWinHTTP::DoPrepareRequest() m_tryCredentialsFromURL = true; } + const wxString host(urlComps.lpszHostName, urlComps.dwHostNameLength); + const INTERNET_PORT port = urlComps.nPort; + + auto* const logger = GetSessionImpl().GetDebugLogger(); + if ( logger ) + logger->OnInfo(wxString::Format("Connecting to %s:%u", host, port)); + // Open a connection m_connect = wxWinHTTP::WinHttpConnect ( m_sessionImpl.GetHandle(), - wxString(urlComps.lpszHostName, urlComps.dwHostNameLength).wc_str(), - urlComps.nPort, + host.wc_str(), + port, wxRESERVED_PARAM ); if ( m_connect == nullptr ) @@ -719,6 +750,50 @@ wxWebRequest::Result wxWebRequestWinHTTP::DoPrepareRequest() return FailWithLastError("Opening request"); } + if ( logger ) + { + // Synthesize the request line for logging purposes only: for this, we + // need to get the HTTP version used by WinHTTP. + DWORD httpVersion = 0; + DWORD size = sizeof(httpVersion); + if ( wxWinHTTP::WinHttpQueryOption + ( + m_request, + WINHTTP_OPTION_HTTP_PROTOCOL_USED, + &httpVersion, + &size + ) ) + { + wxString httpStr; + switch ( httpVersion ) + { + case 0: + // Default value meaning HTTP/1.1. + httpStr = "1.1"; + break; + + case WINHTTP_PROTOCOL_FLAG_HTTP2: + httpStr = "2"; + break; + + case WINHTTP_PROTOCOL_FLAG_HTTP3: + httpStr = "3"; + break; + + default: + httpStr = wxString::Format("unknown (%u)", httpVersion); + break; + } + + if ( objectName.empty() ) + objectName = "/"; + + logger->OnRequestSent( + wxString::Format("%s %s HTTP/%s", method, objectName, httpStr) + ); + } + } + if ( int flags = GetSecurityFlags() ) { DWORD optValue = 0; @@ -834,6 +909,9 @@ wxWebRequest::Result wxWebRequestWinHTTP::SendRequest() return FailWithLastError("Sending request"); } + if ( auto* const logger = GetSessionImpl().GetDebugLogger() ) + logger->OnInfo("Headers sent"); + return Result::Ok(); } @@ -843,6 +921,47 @@ void wxWebRequestWinHTTP::DoCancel() m_request = nullptr; } +void wxWebRequestWinHTTP::LogResponseHeadersIfNecessary() +{ + auto* const logger = GetSessionImpl().GetDebugLogger(); + if ( !logger ) + return; + + auto const + headers = wxWinHTTPQueryHeaderString(m_request, WINHTTP_QUERY_RAW_HEADERS_CRLF); + + bool seenStatus = false; + for ( size_t pos = 0;; ) + { + const size_t end = headers.find("\r\n", pos); + + if ( end == wxString::npos ) + break; + + const wxString line = headers.substr(pos, end - pos); + if ( line.empty() ) + break; + + pos = end + 2; + + if ( !seenStatus ) + { + logger->OnResponseReceived(line); + + seenStatus = true; + continue; + } + + wxString value; + auto const name = line.BeforeFirst(':', &value); + + // Remove leading space, if any. + value.Trim(false); + + logger->OnHeaderReceived(name, value); + } +} + // // wxWebResponseWinHTTP // @@ -916,13 +1035,23 @@ bool wxWebResponseWinHTTP::ReadData(DWORD* bytesRead) { wxLogTrace(wxTRACE_WEBREQUEST, "Request %p: reading data", &m_request); - return wxWinHTTP::WinHttpReadData + void* const data = GetDataBuffer(wxWEBREQUEST_BUFFER_SIZE); + if ( !wxWinHTTP::WinHttpReadData ( m_requestHandle, - GetDataBuffer(wxWEBREQUEST_BUFFER_SIZE), + data, wxWEBREQUEST_BUFFER_SIZE, bytesRead // [out] bytes read, must be null in async mode - ) == TRUE; + ) ) + return false; + + if ( bytesRead && *bytesRead ) + { + if ( auto* const logger = m_request.GetSessionImpl().GetDebugLogger() ) + logger->OnDataReceived(data, *bytesRead); + } + + return true; } // diff --git a/tests/net/webrequest.cpp b/tests/net/webrequest.cpp index 1784d95649..9ac827ba2a 100644 --- a/tests/net/webrequest.cpp +++ b/tests/net/webrequest.cpp @@ -24,6 +24,8 @@ #include "wx/uri.h" #include "wx/wfstream.h" +#include "wx/private/make_unique.h" + #include #include @@ -222,6 +224,54 @@ protected: GetRequest().MakeInsecure(flags); } + + wxString debug; + if ( wxGetEnv("WX_TEST_WEBREQUEST_DEBUG", &debug ) ) + { + class DebugLogger : public wxWebRequestDebugLogger + { + public: + virtual void OnInfo(const wxString& info) override + { + wxFprintf(stderr, "// %s\n", info); + } + + virtual void OnRequestSent(const wxString& line) override + { + wxFprintf(stderr, "=> %s\n", line); + } + + virtual void OnResponseReceived(const wxString& line) override + { + wxFprintf(stderr, "<= %s\n", line); + } + + virtual void OnHeaderSent(const wxString& name, const wxString& value) override + { + wxFprintf(stderr, "-> %s: %s\n", name, value); + } + + virtual void OnHeaderReceived(const wxString& name, const wxString& value) override + { + wxFprintf(stderr, "<- %s: %s\n", name, value); + } + + virtual void OnDataSent(const void* WXUNUSED(data), size_t size) override + { + wxFprintf(stderr, "-> data (%zu bytes)\n", size); + } + + virtual void OnDataReceived(const void* WXUNUSED(data), size_t size) override + { + wxFprintf(stderr, "<- data (%zu bytes)\n", size); + } + }; + + if ( debug == "1" ) + GetSession().SetDebugLogger(std::make_unique()); + else + WARN("Unknown WX_TEST_WEBREQUEST_DEBUG value: " << debug); + } } private: