Log malformed HTTP/2 requests

Unlike HTTP/1 transactions, malformed HTTP/2 requests are rejected
before HttpSM creation, so they bypassed the normal transaction logging
path. That left malformed h2 traffic out of squid.log even when similar
h1 failures were visible.

This adds a pre-transaction LogAccess path for malformed h2 request
headers and emits a best-effort access log entry before resetting the
stream.

Author: bneradt

include/proxy/http2/Http2Stream.h

@@ -138,6 +138,12 @@ class Http2Stream : public ProxyTransaction
     return &_send_header;
   }
 
+  HTTPHdr const *
+  get_receive_header() const
+  {
+    return &_receive_header;
+  }
+
   void update_read_length(int count);
   void set_read_done();
 

include/proxy/logging/LogAccess.h

@@ -25,13 +25,16 @@
 #pragma once
 
 #include "tscore/ink_align.h"
+#include "proxy/Milestones.h"
+#include "proxy/hdrs/HTTP.h"
 #include "proxy/logging/LogField.h"
 
-class HTTPHdr;
 class HttpSM;
 class IpClass;
 union IpEndpoint;
 
+#include <string>
+
 /*-------------------------------------------------------------------------
   LogAccess
 
@@ -113,8 +116,56 @@ enum LogCacheWriteCodeType {
 class LogAccess
 {
 public:
+  /** Data used to access-log requests that fail before transaction creation.
+   *
+   * Malformed HTTP/2 request headers can be rejected while the connection is
+   * still decoding and validating the stream, before the request progresses
+   * far enough to create an @c HttpSM. This payload carries the copied request
+   * and session metadata needed to emit a best-effort transaction log entry
+   * for those failures.
+   */
+  struct PreTransactionLogData {
+    TransactionMilestones milestones;
+    HTTPHdr               client_request;
+
+    std::string method;
+    std::string scheme;
+    std::string authority;
+    std::string path;
+    std::string url;
+    std::string client_protocol = "http/2";
+
+    sockaddr_storage client_addr          = {};
+    sockaddr_storage local_addr           = {};
+    sockaddr_storage verified_client_addr = {};
+
+    int64_t            client_request_body_bytes = 0;
+    int64_t            server_transact_count     = 0;
+    SquidLogCode       log_code                  = SquidLogCode::ERR_INVALID_REQ;
+    SquidSubcode       subcode                   = SquidSubcode::EMPTY;
+    SquidHitMissCode   hit_miss_code             = SQUID_MISS_NONE;
+    SquidHierarchyCode hier_code                 = SquidHierarchyCode::NONE;
+
+    bool has_client_request       = false;
+    bool has_verified_client_addr = false;
+    bool client_tcp_reused        = false;
+    bool client_connection_is_ssl = false;
+    bool client_ssl_reused        = false;
+    bool is_internal              = false;
+
+    ~PreTransactionLogData()
+    {
+      if (client_request.valid()) {
+        client_request.destroy();
+      }
+    }
+  };
+
   LogAccess() = delete;
   explicit LogAccess(HttpSM *sm);
+  // The caller retains ownership of @a data, which must outlive init() and
+  // the synchronous Log::access() call that marshals this entry.
+  explicit LogAccess(PreTransactionLogData const &data);
 
   ~LogAccess() {}
   void init();
@@ -376,7 +427,29 @@ class LogAccess
   LogAccess &operator=(LogAccess &rhs) = delete; // or assignment
 
 private:
-  HttpSM *m_http_sm = nullptr;
+  /** Check whether this accessor is backed by a live @c HttpSM.
+   * @return @c true if normal transaction logging state is available.
+   */
+  bool has_http_sm() const;
+
+  /** Check whether this accessor is logging before @c HttpSM creation.
+   *
+   * This mode is used when a request did not progress far enough to create an
+   * @c HttpSM, but ATS still wants to emit a best-effort access log entry.
+   *
+   * @return @c true if this instance is backed by pre-transaction log data.
+   */
+  bool is_pre_transaction_logging() const;
+
+  PreTransactionLogData const *get_pre_transaction_log_data() const;
+  TransactionMilestones const &get_milestones() const;
+
+  // Invariant: after init(), exactly one of these members is non-nullptr.
+  // Normal transaction logging uses m_http_sm, while pre-transaction logging
+  // uses m_pre_transaction_log_data for requests rejected before HttpSM
+  // creation.
+  HttpSM                      *m_http_sm                  = nullptr;
+  PreTransactionLogData const *m_pre_transaction_log_data = nullptr;
 
   Arena m_arena;
 

src/proxy/http2/Http2ConnectionState.cc

@@ -33,6 +33,8 @@
 #include "proxy/http2/Http2DebugNames.h"
 #include "proxy/http/HttpDebugNames.h"
 #include "proxy/http/HttpSM.h"
+#include "proxy/logging/Log.h"
+#include "proxy/logging/LogAccess.h"
 
 #include "iocore/net/TLSSNISupport.h"
 
@@ -76,6 +78,132 @@ const int buffer_size_index[HTTP2_FRAME_TYPE_MAX] = {
   BUFFER_SIZE_INDEX_16K, // HTTP2_FRAME_TYPE_CONTINUATION
 };
 
+/** Fetch a header field value from a decoded HTTP/2 request.
+ *
+ * @param[in] hdr The decoded request header block to inspect.
+ * @param[in] name The field name to look up.
+ * @return The field value, or an empty view if the field is absent.
+ */
+std::string_view
+get_header_field_value(HTTPHdr const &hdr, std::string_view name)
+{
+  if (auto const *field = hdr.field_find(name); field != nullptr) {
+    return field->value_get();
+  }
+
+  return {};
+}
+
+/** Build a best-effort request target for access logging.
+ *
+ * @param[in] method The decoded request method or :method pseudo-header.
+ * @param[in] scheme The decoded :scheme pseudo-header, if present.
+ * @param[in] authority The decoded :authority pseudo-header, if present.
+ * @param[in] path The decoded :path pseudo-header, if present.
+ * @return A synthesized request target suitable for transaction logging.
+ */
+std::string
+synthesize_client_request_target(std::string_view method, std::string_view scheme, std::string_view authority,
+                                 std::string_view path)
+{
+  if (method == static_cast<std::string_view>(HTTP_METHOD_CONNECT)) {
+    if (!authority.empty()) {
+      return std::string(authority);
+    }
+    if (!path.empty()) {
+      return std::string(path);
+    }
+    return {};
+  }
+
+  if (!scheme.empty() && !authority.empty()) {
+    std::string url;
+    url.reserve(scheme.size() + authority.size() + path.size() + 4);
+    url.append(scheme);
+    url.append("://");
+    url.append(authority);
+    if (!path.empty()) {
+      url.append(path);
+    } else {
+      url.push_back('/');
+    }
+    return url;
+  }
+
+  if (!path.empty()) {
+    return std::string(path);
+  }
+
+  if (!authority.empty()) {
+    return std::string(authority);
+  }
+
+  return {};
+}
+
+/** Emit a best-effort access log entry for a malformed decoded request.
+ *
+ * This is used when the request is rejected before stream processing reaches
+ * the point of creating an @c HttpSM.
+ *
+ * @param[in] stream The stream whose decoded request headers were rejected.
+ * @return None.
+ */
+void
+log_malformed_request_access(Http2Stream *stream)
+{
+  if (stream == nullptr || stream->get_sm() != nullptr || stream->trailing_header_is_possible() ||
+      stream->is_outbound_connection()) {
+    return;
+  }
+
+  auto const *request = stream->get_receive_header();
+  if (request == nullptr || !request->valid() || request->type_get() != HTTPType::REQUEST) {
+    return;
+  }
+
+  auto *proxy_session = stream->get_proxy_ssn();
+  if (proxy_session == nullptr) {
+    return;
+  }
+
+  LogAccess::PreTransactionLogData data;
+  data.client_request.create(HTTPType::REQUEST, request->version_get());
+  data.client_request.copy(request);
+  data.has_client_request       = true;
+  data.client_connection_is_ssl = proxy_session->ssl() != nullptr;
+
+  auto const method    = get_header_field_value(*request, PSEUDO_HEADER_METHOD);
+  auto const scheme    = get_header_field_value(*request, PSEUDO_HEADER_SCHEME);
+  auto const authority = get_header_field_value(*request, PSEUDO_HEADER_AUTHORITY);
+  auto const path      = get_header_field_value(*request, PSEUDO_HEADER_PATH);
+
+  if (!method.empty()) {
+    data.method.assign(method.data(), method.size());
+  } else {
+    auto const method_value = const_cast<HTTPHdr *>(request)->method_get();
+    data.method.assign(method_value.data(), method_value.size());
+  }
+
+  data.scheme.assign(scheme.data(), scheme.size());
+  data.authority.assign(authority.data(), authority.size());
+  data.path.assign(path.data(), path.size());
+  data.url = synthesize_client_request_target(data.method, data.scheme, data.authority, data.path);
+
+  ats_ip_copy(reinterpret_cast<sockaddr *>(&data.client_addr), proxy_session->get_remote_addr());
+  ats_ip_copy(reinterpret_cast<sockaddr *>(&data.local_addr), proxy_session->get_local_addr());
+
+  ink_hrtime const now                              = ink_get_hrtime();
+  data.milestones[TS_MILESTONE_SM_START]            = now;
+  data.milestones[TS_MILESTONE_UA_BEGIN]            = now;
+  data.milestones[TS_MILESTONE_UA_FIRST_READ]       = now;
+  data.milestones[TS_MILESTONE_UA_READ_HEADER_DONE] = now;
+  data.milestones[TS_MILESTONE_SM_FINISH]           = now;
+
+  LogAccess access(data);
+  Log::access(&access);
+}
+
 inline unsigned
 read_rcv_buffer(char *buf, size_t bufsize, unsigned &nbytes, const Http2Frame &frame)
 {
@@ -496,6 +624,7 @@ Http2ConnectionState::rcv_headers_frame(const Http2Frame &frame)
         return Http2Error(Http2ErrorClass::HTTP2_ERROR_CLASS_CONNECTION, Http2ErrorCode::HTTP2_ERROR_ENHANCE_YOUR_CALM,
                           "recv headers enhance your calm");
       } else {
+        log_malformed_request_access(stream);
         return Http2Error(Http2ErrorClass::HTTP2_ERROR_CLASS_STREAM, Http2ErrorCode::HTTP2_ERROR_PROTOCOL_ERROR,
                           "recv headers malformed request");
       }
@@ -1108,6 +1237,7 @@ Http2ConnectionState::rcv_continuation_frame(const Http2Frame &frame)
         return Http2Error(Http2ErrorClass::HTTP2_ERROR_CLASS_CONNECTION, Http2ErrorCode::HTTP2_ERROR_ENHANCE_YOUR_CALM,
                           "continuation enhance your calm");
       } else {
+        log_malformed_request_access(stream);
         return Http2Error(Http2ErrorClass::HTTP2_ERROR_CLASS_CONNECTION, Http2ErrorCode::HTTP2_ERROR_PROTOCOL_ERROR,
                           "continuation malformed request");
       }

src/proxy/logging/CMakeLists.txt

@@ -48,6 +48,10 @@ if(BUILD_TESTING)
   target_compile_definitions(test_RolledLogDeleter PRIVATE TEST_LOG_UTILS)
   target_link_libraries(test_RolledLogDeleter tscore ts::inkevent records Catch2::Catch2WithMain)
   add_catch2_test(NAME test_RolledLogDeleter COMMAND test_RolledLogDeleter)
+
+  add_executable(test_LogAccess unit-tests/test_LogAccess.cc)
+  target_link_libraries(test_LogAccess ts::logging ts::http ts::inkevent records Catch2::Catch2WithMain)
+  add_catch2_test(NAME test_LogAccess COMMAND test_LogAccess)
 endif()
 
 clang_tidy_check(logging)