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

@@ -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)
     {

include/wx/private/webrequest.h

@@ -362,11 +362,22 @@ public:
 
     virtual bool EnablePersistentStorage(bool WXUNUSED(enable)) { return false; }
 
+    void SetDebugLogger(std::unique_ptr<wxWebRequestDebugLogger> 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<wxWebRequestDebugLogger> m_debugLogger;
+
 private:
     // Make it a friend to allow accessing our m_headers.
     friend class wxWebRequest;

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<wxWebRequestDebugLogger> logger);
+
     wxWebSessionHandle GetNativeHandle() const;
 
 private:

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<wxWebRequestDebugLogger> 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<wxWebRequestDebugLogger> logger);
 };
 
 

src/common/webrequest.cpp

@@ -1236,6 +1236,14 @@ bool wxWebSessionBase::EnablePersistentStorage(bool enable)
     return m_impl->EnablePersistentStorage(enable);
 }
 
+void
+wxWebSessionBase::SetDebugLogger(std::unique_ptr<wxWebRequestDebugLogger> logger)
+{
+    wxCHECK_IMPL_VOID();
+
+    m_impl->SetDebugLogger(std::move(logger));
+}
+
 // ----------------------------------------------------------------------------
 // Module ensuring all global/singleton objects are destroyed on shutdown.
 // ----------------------------------------------------------------------------

src/common/webrequest_curl.cpp

@@ -346,6 +346,89 @@ static int wxCURLSeek(void* userdata, curl_off_t offset, int origin)
     return static_cast<wxWebRequestCURL*>(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<wxWebRequestDebugLogger*>(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();
 }
 

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;
 }
 
 //

tests/net/webrequest.cpp

@@ -24,6 +24,8 @@
 #include "wx/uri.h"
 #include "wx/wfstream.h"
 
+#include "wx/private/make_unique.h"
+
 #include <memory>
 #include <unordered_map>
 
@@ -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<DebugLogger>());
+            else
+                WARN("Unknown WX_TEST_WEBREQUEST_DEBUG value: " << debug);
+        }
     }
 
 private: