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();
 }
 

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: