From fa9178bda702daadfd40c32fa896512599a628ce Mon Sep 17 00:00:00 2001 From: bneradt Date: Fri, 3 Apr 2026 14:55:56 -0500 Subject: [PATCH] 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. --- include/proxy/http2/Http2Stream.h | 6 + include/proxy/logging/LogAccess.h | 77 ++- src/proxy/http2/Http2ConnectionState.cc | 130 +++++ src/proxy/logging/CMakeLists.txt | 4 + src/proxy/logging/LogAccess.cc | 504 +++++++++++++----- .../logging/unit-tests/test_LogAccess.cc | 209 ++++++++ .../h2_malformed_request_logging.test.py | 207 +++++++ .../connect/malformed_h2_request_client.py | 172 ++++++ .../h2_malformed_request_logging.replay.yaml | 90 ++++ 9 files changed, 1259 insertions(+), 140 deletions(-) create mode 100644 src/proxy/logging/unit-tests/test_LogAccess.cc create mode 100644 tests/gold_tests/connect/h2_malformed_request_logging.test.py create mode 100644 tests/gold_tests/connect/malformed_h2_request_client.py create mode 100644 tests/gold_tests/connect/replays/h2_malformed_request_logging.replay.yaml diff --git a/include/proxy/http2/Http2Stream.h b/include/proxy/http2/Http2Stream.h index 5d9beac647e..bc4b0743c51 100644 --- a/include/proxy/http2/Http2Stream.h +++ b/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(); diff --git a/include/proxy/logging/LogAccess.h b/include/proxy/logging/LogAccess.h index d24a5eb6827..8a17404230e 100644 --- a/include/proxy/logging/LogAccess.h +++ b/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 + /*------------------------------------------------------------------------- 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; diff --git a/src/proxy/http2/Http2ConnectionState.cc b/src/proxy/http2/Http2ConnectionState.cc index 4b38579574c..e5356ab0812 100644 --- a/src/proxy/http2/Http2ConnectionState.cc +++ b/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(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(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(&data.client_addr), proxy_session->get_remote_addr()); + ats_ip_copy(reinterpret_cast(&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"); } diff --git a/src/proxy/logging/CMakeLists.txt b/src/proxy/logging/CMakeLists.txt index 27da4f05d85..60a3372b43e 100644 --- a/src/proxy/logging/CMakeLists.txt +++ b/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) diff --git a/src/proxy/logging/LogAccess.cc b/src/proxy/logging/LogAccess.cc index fd4add5c02d..ce7c2e261f7 100644 --- a/src/proxy/logging/LogAccess.cc +++ b/src/proxy/logging/LogAccess.cc @@ -67,16 +67,74 @@ DbgCtl dbg_ctl_log_unmarshal_data{"log-unmarshal-data"}; // Error in txn data wh LogAccess::LogAccess(HttpSM *sm) : m_http_sm(sm) { - ink_assert(m_http_sm != nullptr); + ink_assert(has_http_sm()); } -/*------------------------------------------------------------------------- - LogAccess::init - -------------------------------------------------------------------------*/ +LogAccess::LogAccess(PreTransactionLogData const &data) : m_pre_transaction_log_data(&data) {} + +bool +LogAccess::has_http_sm() const +{ + return m_http_sm != nullptr; +} + +bool +LogAccess::is_pre_transaction_logging() const +{ + return m_pre_transaction_log_data != nullptr; +} + +LogAccess::PreTransactionLogData const * +LogAccess::get_pre_transaction_log_data() const +{ + return m_pre_transaction_log_data; +} + +TransactionMilestones const & +LogAccess::get_milestones() const +{ + if (has_http_sm()) { + return m_http_sm->milestones; + } + + ink_assert(is_pre_transaction_logging()); + return m_pre_transaction_log_data->milestones; +} void LogAccess::init() { + if (is_pre_transaction_logging()) { + auto const *pre = this->get_pre_transaction_log_data(); + ink_assert(pre != nullptr); + + if (pre->has_client_request && pre->client_request.valid()) { + m_client_request = const_cast(&m_pre_transaction_log_data->client_request); + } + + if (!pre->url.empty()) { + m_client_req_url_len = pre->url.size(); + m_client_req_url_str = m_arena.str_alloc(m_client_req_url_len + 1); + memcpy(m_client_req_url_str, pre->url.data(), m_client_req_url_len); + m_client_req_url_str[m_client_req_url_len] = '\0'; + + m_client_req_url_canon_str = + Encoding::escapify_url(&m_arena, m_client_req_url_str, m_client_req_url_len, &m_client_req_url_canon_len); + } + + if (!pre->path.empty()) { + m_client_req_url_path_len = pre->path.size(); + char *path_copy = m_arena.str_alloc(m_client_req_url_path_len + 1); + memcpy(path_copy, pre->path.data(), m_client_req_url_path_len); + path_copy[m_client_req_url_path_len] = '\0'; + m_client_req_url_path_str = path_copy; + } + + return; + } + + ink_assert(has_http_sm()); + HttpTransact::HeaderInfo *hdr = &(m_http_sm->t_state.hdr_info); if (hdr->client_request.valid()) { @@ -1460,7 +1518,7 @@ int LogAccess::marshal_plugin_identity_id(char *buf) { if (buf) { - marshal_int(buf, m_http_sm->plugin_id); + marshal_int(buf, has_http_sm() ? m_http_sm->plugin_id : 0); } return INK_MIN_ALIGN; } @@ -1469,7 +1527,7 @@ int LogAccess::marshal_plugin_identity_tag(char *buf) { int len = INK_MIN_ALIGN; - const char *tag = m_http_sm->plugin_tag; + const char *tag = has_http_sm() ? m_http_sm->plugin_tag : nullptr; if (!tag) { tag = "*"; @@ -1487,25 +1545,40 @@ LogAccess::marshal_plugin_identity_tag(char *buf) int LogAccess::marshal_client_host_ip(char *buf) { - return marshal_ip(buf, &m_http_sm->t_state.effective_client_addr.sa); + if (has_http_sm()) { + return marshal_ip(buf, &m_http_sm->t_state.effective_client_addr.sa); + } + + auto const *pre = this->get_pre_transaction_log_data(); + return marshal_ip(buf, pre != nullptr ? reinterpret_cast(&pre->client_addr) : nullptr); } int LogAccess::marshal_remote_host_ip(char *buf) { - return marshal_ip(buf, &m_http_sm->t_state.client_info.src_addr.sa); + if (has_http_sm()) { + return marshal_ip(buf, &m_http_sm->t_state.client_info.src_addr.sa); + } + + auto const *pre = this->get_pre_transaction_log_data(); + return marshal_ip(buf, pre != nullptr ? reinterpret_cast(&pre->client_addr) : nullptr); } int LogAccess::marshal_host_interface_ip(char *buf) { - return marshal_ip(buf, &m_http_sm->t_state.client_info.dst_addr.sa); + if (has_http_sm()) { + return marshal_ip(buf, &m_http_sm->t_state.client_info.dst_addr.sa); + } + + auto const *pre = this->get_pre_transaction_log_data(); + return marshal_ip(buf, pre != nullptr ? reinterpret_cast(&pre->local_addr) : nullptr); } int LogAccess::marshal_client_host_ip_verified(char *buf) { - if (m_http_sm) { + if (has_http_sm()) { auto txn = m_http_sm->get_ua_txn(); if (txn) { sockaddr const *addr = txn->get_verified_client_addr(); @@ -1514,6 +1587,11 @@ LogAccess::marshal_client_host_ip_verified(char *buf) } } } + + if (auto const *pre = this->get_pre_transaction_log_data(); pre != nullptr && pre->has_verified_client_addr) { + return marshal_ip(buf, reinterpret_cast(&pre->verified_client_addr)); + } + return marshal_client_host_ip(buf); } @@ -1548,7 +1626,7 @@ LogAccess::marshal_client_sni_server_name(char *buf) // std::string_view server_name = ""; - if (m_http_sm) { + if (has_http_sm()) { auto txn = m_http_sm->get_ua_txn(); if (txn) { auto ssn = txn->get_proxy_ssn(); @@ -1576,7 +1654,7 @@ int LogAccess::marshal_client_provided_cert(char *buf) { int provided_cert = 0; - if (m_http_sm) { + if (has_http_sm()) { auto txn = m_http_sm->get_ua_txn(); if (txn) { auto ssn = txn->get_proxy_ssn(); @@ -1600,7 +1678,7 @@ int LogAccess::marshal_proxy_provided_cert(char *buf) { int provided_cert = 0; - if (m_http_sm) { + if (has_http_sm()) { provided_cert = m_http_sm->server_connection_provided_cert; } if (buf) { @@ -1645,7 +1723,7 @@ LogAccess::marshal_proxy_protocol_version(char *buf) const char *version_str = nullptr; int len = INK_MIN_ALIGN; - if (m_http_sm) { + if (has_http_sm()) { ProxyProtocolVersion ver = m_http_sm->t_state.pp_info.version; switch (ver) { case ProxyProtocolVersion::V1: @@ -1674,7 +1752,7 @@ int LogAccess::marshal_proxy_protocol_src_ip(char *buf) { sockaddr const *ip = nullptr; - if (m_http_sm && m_http_sm->t_state.pp_info.version != ProxyProtocolVersion::UNDEFINED) { + if (has_http_sm() && m_http_sm->t_state.pp_info.version != ProxyProtocolVersion::UNDEFINED) { ip = &m_http_sm->t_state.pp_info.src_addr.sa; } return marshal_ip(buf, ip); @@ -1686,7 +1764,7 @@ int LogAccess::marshal_proxy_protocol_dst_ip(char *buf) { sockaddr const *ip = nullptr; - if (m_http_sm && m_http_sm->t_state.pp_info.version != ProxyProtocolVersion::UNDEFINED) { + if (has_http_sm() && m_http_sm->t_state.pp_info.version != ProxyProtocolVersion::UNDEFINED) { ip = &m_http_sm->t_state.pp_info.dst_addr.sa; } return marshal_ip(buf, ip); @@ -1697,7 +1775,7 @@ LogAccess::marshal_proxy_protocol_authority(char *buf) { int len = INK_MIN_ALIGN; - if (m_http_sm) { + if (has_http_sm()) { if (auto authority = m_http_sm->t_state.pp_info.get_tlv(PP2_TYPE_AUTHORITY)) { len = padded_length(authority->size() + 1); if (buf) { @@ -1714,7 +1792,7 @@ LogAccess::marshal_proxy_protocol_tls_cipher(char *buf) { int len = INK_MIN_ALIGN; - if (m_http_sm) { + if (has_http_sm()) { if (auto cipher = m_http_sm->t_state.pp_info.get_tlv_ssl_cipher(); cipher) { len = padded_length(cipher->size() + 1); if (buf) { @@ -1735,7 +1813,7 @@ LogAccess::marshal_proxy_protocol_tls_version(char *buf) { int len = INK_MIN_ALIGN; - if (m_http_sm) { + if (has_http_sm()) { if (auto version = m_http_sm->t_state.pp_info.get_tlv_ssl_version(); version) { len = padded_length(version->size() + 1); if (buf) { @@ -1756,7 +1834,7 @@ LogAccess::marshal_proxy_protocol_tls_group(char *buf) { int len = INK_MIN_ALIGN; - if (m_http_sm) { + if (has_http_sm()) { if (auto group = m_http_sm->t_state.pp_info.get_tlv_ssl_group(); group) { len = padded_length(group->size() + 1); if (buf) { @@ -1777,12 +1855,19 @@ LogAccess::marshal_proxy_protocol_tls_group(char *buf) int LogAccess::marshal_client_host_port(char *buf) { - if (m_http_sm) { - auto txn = m_http_sm->get_ua_txn(); - if (txn) { - uint16_t port = txn->get_client_port(); - marshal_int(buf, port); + if (buf) { + uint16_t port = 0; + + if (has_http_sm()) { + auto txn = m_http_sm->get_ua_txn(); + if (txn) { + port = txn->get_client_port(); + } + } else if (auto const *pre = this->get_pre_transaction_log_data(); pre != nullptr) { + port = ats_ip_port_host_order(reinterpret_cast(&pre->client_addr)); } + + marshal_int(buf, port); } return INK_MIN_ALIGN; } @@ -1791,7 +1876,12 @@ int LogAccess::marshal_remote_host_port(char *buf) { if (buf) { - uint16_t port = m_http_sm->t_state.client_info.src_addr.host_order_port(); + uint16_t port = 0; + if (has_http_sm()) { + port = m_http_sm->t_state.client_info.src_addr.host_order_port(); + } else if (auto const *pre = this->get_pre_transaction_log_data(); pre != nullptr) { + port = ats_ip_port_host_order(reinterpret_cast(&pre->client_addr)); + } marshal_int(buf, port); } return INK_MIN_ALIGN; @@ -1828,6 +1918,11 @@ LogAccess::marshal_client_auth_user_name(char *buf) void LogAccess::validate_unmapped_url() { + if (!has_http_sm()) { + m_client_req_unmapped_url_canon_str = INVALID_STR; + return; + } + if (m_client_req_unmapped_url_canon_str == nullptr) { // prevent multiple validations m_client_req_unmapped_url_canon_str = INVALID_STR; @@ -1890,6 +1985,11 @@ LogAccess::validate_unmapped_url_path() void LogAccess::validate_lookup_url() { + if (!has_http_sm()) { + m_cache_lookup_url_canon_str = INVALID_STR; + return; + } + if (m_cache_lookup_url_canon_str == nullptr) { // prevent multiple validations m_cache_lookup_url_canon_str = INVALID_STR; @@ -1954,17 +2054,23 @@ LogAccess::marshal_client_req_http_method(char *buf) if (m_client_request) { str = m_client_request->method_get(); + } - // calculate the padded length only if the actual length - // is not zero. We don't want the padded length to be zero - // because marshal_mem should write the DEFAULT_STR to the - // buffer if str is nil, and we need room for this. - // - if (!str.empty()) { - plen = padded_length(static_cast(str.length()) + 1); // +1 for trailing 0 + if (str.empty()) { + if (auto const *pre = m_pre_transaction_log_data; pre != nullptr) { + str = pre->method; } } + // calculate the padded length only if the actual length + // is not zero. We don't want the padded length to be zero + // because marshal_mem should write the DEFAULT_STR to the + // buffer if str is nil, and we need room for this. + // + if (!str.empty()) { + plen = padded_length(static_cast(str.length()) + 1); // +1 for trailing 0 + } + if (buf) { marshal_mem(buf, str.data(), static_cast(str.length()), plen); } @@ -2075,10 +2181,29 @@ LogAccess::marshal_client_req_url_path(char *buf) int LogAccess::marshal_client_req_url_scheme(char *buf) { - int scheme = m_http_sm->t_state.orig_scheme; + int scheme = -1; const char *str = nullptr; - int alen; - int plen = INK_MIN_ALIGN; + int alen = 0; + int plen = INK_MIN_ALIGN; + + if (!has_http_sm()) { + if (auto const *pre = this->get_pre_transaction_log_data(); pre != nullptr && !pre->scheme.empty()) { + str = pre->scheme.c_str(); + alen = pre->scheme.size(); + } else { + str = DEFAULT_STR; + alen = DEFAULT_STR_LEN; + } + plen = padded_length(alen + 1); + + if (buf) { + marshal_mem(buf, str, alen, plen); + } + + return plen; + } + + scheme = m_http_sm->t_state.orig_scheme; // If the transaction aborts very early, the scheme may not be set, or so ASAN reports. if (scheme >= 0) { @@ -2124,8 +2249,15 @@ LogAccess::marshal_client_req_http_version(char *buf) int LogAccess::marshal_client_req_protocol_version(char *buf) { - const char *protocol_str = m_http_sm->get_user_agent().get_client_protocol(); - int len = LogAccess::padded_strlen(protocol_str); + const char *protocol_str = DEFAULT_STR; + + if (has_http_sm()) { + protocol_str = m_http_sm->get_user_agent().get_client_protocol(); + } else if (auto const *pre = this->get_pre_transaction_log_data(); pre != nullptr && !pre->client_protocol.empty()) { + protocol_str = pre->client_protocol.c_str(); + } + + int len = LogAccess::padded_strlen(protocol_str); // Set major & minor versions when protocol_str is not "http/2". if (::strlen(protocol_str) == 4 && strncmp("http", protocol_str, 4) == 0) { @@ -2156,7 +2288,7 @@ LogAccess::marshal_client_req_protocol_version(char *buf) int LogAccess::marshal_server_req_protocol_version(char *buf) { - const char *protocol_str = m_http_sm->server_protocol; + const char *protocol_str = has_http_sm() ? m_http_sm->server_protocol : DEFAULT_STR; int len = LogAccess::padded_strlen(protocol_str); // Set major & minor versions when protocol_str is not "http/2". @@ -2207,7 +2339,11 @@ LogAccess::marshal_client_req_content_len(char *buf) if (buf) { int64_t len = 0; if (m_client_request) { - len = m_http_sm->client_request_body_bytes; + if (has_http_sm()) { + len = m_http_sm->client_request_body_bytes; + } else if (auto const *pre = this->get_pre_transaction_log_data(); pre != nullptr) { + len = pre->client_request_body_bytes; + } } marshal_int(buf, len); } @@ -2220,7 +2356,12 @@ LogAccess::marshal_client_req_squid_len(char *buf) if (buf) { int64_t val = 0; if (m_client_request) { - val = m_client_request->length_get() + m_http_sm->client_request_body_bytes; + val = m_client_request->length_get(); + if (has_http_sm()) { + val += m_http_sm->client_request_body_bytes; + } else if (auto const *pre = this->get_pre_transaction_log_data(); pre != nullptr) { + val += pre->client_request_body_bytes; + } } marshal_int(buf, val); } @@ -2234,7 +2375,13 @@ int LogAccess::marshal_client_req_tcp_reused(char *buf) { if (buf) { - marshal_int(buf, m_http_sm->get_user_agent().get_client_tcp_reused() ? 1 : 0); + int64_t val = 0; + if (has_http_sm()) { + val = m_http_sm->get_user_agent().get_client_tcp_reused() ? 1 : 0; + } else if (auto const *pre = this->get_pre_transaction_log_data(); pre != nullptr) { + val = pre->client_tcp_reused ? 1 : 0; + } + marshal_int(buf, val); } return INK_MIN_ALIGN; } @@ -2243,7 +2390,13 @@ int LogAccess::marshal_client_req_is_ssl(char *buf) { if (buf) { - marshal_int(buf, m_http_sm->get_user_agent().get_client_connection_is_ssl() ? 1 : 0); + int64_t val = 0; + if (has_http_sm()) { + val = m_http_sm->get_user_agent().get_client_connection_is_ssl() ? 1 : 0; + } else if (auto const *pre = this->get_pre_transaction_log_data(); pre != nullptr) { + val = pre->client_connection_is_ssl ? 1 : 0; + } + marshal_int(buf, val); } return INK_MIN_ALIGN; } @@ -2252,7 +2405,13 @@ int LogAccess::marshal_client_req_ssl_reused(char *buf) { if (buf) { - marshal_int(buf, m_http_sm->get_user_agent().get_client_ssl_reused() ? 1 : 0); + int64_t val = 0; + if (has_http_sm()) { + val = m_http_sm->get_user_agent().get_client_ssl_reused() ? 1 : 0; + } else if (auto const *pre = this->get_pre_transaction_log_data(); pre != nullptr) { + val = pre->client_ssl_reused ? 1 : 0; + } + marshal_int(buf, val); } return INK_MIN_ALIGN; } @@ -2261,7 +2420,13 @@ int LogAccess::marshal_client_req_is_internal(char *buf) { if (buf) { - marshal_int(buf, m_http_sm->is_internal ? 1 : 0); + int64_t val = 0; + if (has_http_sm()) { + val = m_http_sm->is_internal ? 1 : 0; + } else if (auto const *pre = this->get_pre_transaction_log_data(); pre != nullptr) { + val = pre->is_internal ? 1 : 0; + } + marshal_int(buf, val); } return INK_MIN_ALIGN; } @@ -2272,9 +2437,8 @@ LogAccess::marshal_client_req_mptcp_state(char *buf) if (buf) { int val = -1; - if (m_http_sm->mptcp_state.has_value()) { + if (has_http_sm() && m_http_sm->mptcp_state.has_value()) { val = m_http_sm->mptcp_state.value() ? 1 : 0; - } else { } marshal_int(buf, val); } @@ -2288,15 +2452,17 @@ int LogAccess::marshal_client_finish_status_code(char *buf) { if (buf) { - int code = LOG_FINISH_FIN; - HttpTransact::AbortState_t cl_abort_state = m_http_sm->t_state.client_info.abort; - if (cl_abort_state == HttpTransact::ABORTED) { - // Check to see if the abort is due to a timeout - if (m_http_sm->t_state.client_info.state == HttpTransact::ACTIVE_TIMEOUT || - m_http_sm->t_state.client_info.state == HttpTransact::INACTIVE_TIMEOUT) { - code = LOG_FINISH_TIMEOUT; - } else { - code = LOG_FINISH_INTR; + int code = LOG_FINISH_FIN; + if (has_http_sm()) { + HttpTransact::AbortState_t cl_abort_state = m_http_sm->t_state.client_info.abort; + if (cl_abort_state == HttpTransact::ABORTED) { + // Check to see if the abort is due to a timeout + if (m_http_sm->t_state.client_info.state == HttpTransact::ACTIVE_TIMEOUT || + m_http_sm->t_state.client_info.state == HttpTransact::INACTIVE_TIMEOUT) { + code = LOG_FINISH_TIMEOUT; + } else { + code = LOG_FINISH_INTR; + } } } marshal_int(buf, code); @@ -2311,7 +2477,7 @@ int LogAccess::marshal_client_req_id(char *buf) { if (buf) { - marshal_int(buf, m_http_sm->sm_id); + marshal_int(buf, has_http_sm() ? m_http_sm->sm_id : 0); } return INK_MIN_ALIGN; } @@ -2323,8 +2489,9 @@ int LogAccess::marshal_client_req_uuid(char *buf) { char str[TS_CRUUID_STRING_LEN + 1]; - const char *uuid = Machine::instance()->process_uuid.getString(); - int len = snprintf(str, sizeof(str), "%s-%" PRId64 "", uuid, m_http_sm->sm_id); + const char *uuid = Machine::instance()->process_uuid.getString(); + int64_t req_id = has_http_sm() ? m_http_sm->sm_id : 0; + int len = snprintf(str, sizeof(str), "%s-%" PRId64 "", uuid, req_id); ink_assert(len <= TS_CRUUID_STRING_LEN); len = padded_length(len + 1); @@ -2346,7 +2513,11 @@ int LogAccess::marshal_client_rx_error_code(char *buf) { char error_code[MAX_PROXY_ERROR_CODE_SIZE] = {0}; - m_http_sm->t_state.client_info.rx_error_code.str(error_code, sizeof(error_code)); + if (has_http_sm()) { + m_http_sm->t_state.client_info.rx_error_code.str(error_code, sizeof(error_code)); + } else { + error_code[0] = '-'; + } int round_len = LogAccess::padded_strlen(error_code); if (buf) { @@ -2360,7 +2531,11 @@ int LogAccess::marshal_client_tx_error_code(char *buf) { char error_code[MAX_PROXY_ERROR_CODE_SIZE] = {0}; - m_http_sm->t_state.client_info.tx_error_code.str(error_code, sizeof(error_code)); + if (has_http_sm()) { + m_http_sm->t_state.client_info.tx_error_code.str(error_code, sizeof(error_code)); + } else { + error_code[0] = '-'; + } int round_len = LogAccess::padded_strlen(error_code); if (buf) { @@ -2375,7 +2550,7 @@ LogAccess::marshal_client_tx_error_code(char *buf) int LogAccess::marshal_client_security_protocol(char *buf) { - const char *proto = m_http_sm->get_user_agent().get_client_sec_protocol(); + const char *proto = has_http_sm() ? m_http_sm->get_user_agent().get_client_sec_protocol() : DEFAULT_STR; int round_len = LogAccess::padded_strlen(proto); if (buf) { @@ -2388,7 +2563,7 @@ LogAccess::marshal_client_security_protocol(char *buf) int LogAccess::marshal_client_security_cipher_suite(char *buf) { - const char *cipher = m_http_sm->get_user_agent().get_client_cipher_suite(); + const char *cipher = has_http_sm() ? m_http_sm->get_user_agent().get_client_cipher_suite() : DEFAULT_STR; int round_len = LogAccess::padded_strlen(cipher); if (buf) { @@ -2401,7 +2576,7 @@ LogAccess::marshal_client_security_cipher_suite(char *buf) int LogAccess::marshal_client_security_curve(char *buf) { - const char *curve = m_http_sm->get_user_agent().get_client_curve(); + const char *curve = has_http_sm() ? m_http_sm->get_user_agent().get_client_curve() : DEFAULT_STR; int round_len = LogAccess::padded_strlen(curve); if (buf) { @@ -2414,7 +2589,7 @@ LogAccess::marshal_client_security_curve(char *buf) int LogAccess::marshal_client_security_group(char *buf) { - const char *group = m_http_sm->get_user_agent().get_client_security_group(); + const char *group = has_http_sm() ? m_http_sm->get_user_agent().get_client_security_group() : DEFAULT_STR; int round_len = LogAccess::padded_strlen(group); if (buf) { @@ -2428,7 +2603,8 @@ int LogAccess::marshal_client_security_alpn(char *buf) { const char *alpn = "-"; - if (const int alpn_id = m_http_sm->get_user_agent().get_client_alpn_id(); alpn_id != SessionProtocolNameRegistry::INVALID) { + if (has_http_sm() && m_http_sm->get_user_agent().get_client_alpn_id() != SessionProtocolNameRegistry::INVALID) { + const int alpn_id = m_http_sm->get_user_agent().get_client_alpn_id(); swoc::TextView client_sec_alpn = globalSessionProtocolNameRegistry.nameFor(alpn_id); alpn = client_sec_alpn.data(); } @@ -2476,7 +2652,10 @@ int LogAccess::marshal_proxy_resp_squid_len(char *buf) { if (buf) { - int64_t val = m_http_sm->client_response_hdr_bytes + m_http_sm->client_response_body_bytes; + int64_t val = 0; + if (has_http_sm()) { + val = m_http_sm->client_response_hdr_bytes + m_http_sm->client_response_body_bytes; + } marshal_int(buf, val); } return INK_MIN_ALIGN; @@ -2489,7 +2668,7 @@ int LogAccess::marshal_proxy_resp_content_len(char *buf) { if (buf) { - int64_t val = m_http_sm->client_response_body_bytes; + int64_t val = has_http_sm() ? m_http_sm->client_response_body_bytes : 0; marshal_int(buf, val); } return INK_MIN_ALIGN; @@ -2532,7 +2711,7 @@ LogAccess::marshal_status_plugin_entry(char *buf) char const *str = nullptr; int len = INK_MIN_ALIGN; - if (m_http_sm) { + if (has_http_sm()) { std::string const &tag = m_http_sm->t_state.http_return_code_setter_name; if (!tag.empty()) { str = tag.c_str(); @@ -2553,7 +2732,7 @@ int LogAccess::marshal_proxy_resp_header_len(char *buf) { if (buf) { - int64_t val = m_http_sm->client_response_hdr_bytes; + int64_t val = has_http_sm() ? m_http_sm->client_response_hdr_bytes : 0; marshal_int(buf, val); } return INK_MIN_ALIGN; @@ -2567,7 +2746,7 @@ LogAccess::marshal_proxy_finish_status_code(char *buf) to FIN */ if (buf) { int code = LOG_FINISH_FIN; - if (m_http_sm->t_state.current.server) { + if (has_http_sm() && m_http_sm->t_state.current.server) { switch (m_http_sm->t_state.current.server->state) { case HttpTransact::ACTIVE_TIMEOUT: case HttpTransact::INACTIVE_TIMEOUT: @@ -2596,7 +2775,10 @@ int LogAccess::marshal_proxy_host_port(char *buf) { if (buf) { - uint16_t port = m_http_sm->t_state.request_data.incoming_port; + uint16_t port = 0; + if (has_http_sm()) { + port = m_http_sm->t_state.request_data.incoming_port; + } marshal_int(buf, port); } return INK_MIN_ALIGN; @@ -2609,7 +2791,12 @@ int LogAccess::marshal_cache_result_code(char *buf) { if (buf) { - SquidLogCode code = m_http_sm->t_state.squid_codes.log_code; + SquidLogCode code = SquidLogCode::EMPTY; + if (has_http_sm()) { + code = m_http_sm->t_state.squid_codes.log_code; + } else if (auto const *pre = this->get_pre_transaction_log_data(); pre != nullptr) { + code = pre->log_code; + } marshal_int(buf, static_cast(code)); } return INK_MIN_ALIGN; @@ -2622,7 +2809,12 @@ int LogAccess::marshal_cache_result_subcode(char *buf) { if (buf) { - SquidSubcode code = m_http_sm->t_state.squid_codes.subcode; + SquidSubcode code = SquidSubcode::EMPTY; + if (has_http_sm()) { + code = m_http_sm->t_state.squid_codes.subcode; + } else if (auto const *pre = this->get_pre_transaction_log_data(); pre != nullptr) { + code = pre->subcode; + } marshal_int(buf, static_cast(code)); } return INK_MIN_ALIGN; @@ -2635,7 +2827,12 @@ int LogAccess::marshal_cache_hit_miss(char *buf) { if (buf) { - SquidHitMissCode code = m_http_sm->t_state.squid_codes.hit_miss_code; + SquidHitMissCode code = SQUID_MISS_NONE; + if (has_http_sm()) { + code = m_http_sm->t_state.squid_codes.hit_miss_code; + } else if (auto const *pre = this->get_pre_transaction_log_data(); pre != nullptr) { + code = pre->hit_miss_code; + } marshal_int(buf, static_cast(code)); } return INK_MIN_ALIGN; @@ -2665,7 +2862,7 @@ LogAccess::marshal_proxy_req_content_len(char *buf) { if (buf) { int64_t val = 0; - if (m_proxy_request) { + if (m_proxy_request && has_http_sm()) { val = m_http_sm->server_request_body_bytes; } marshal_int(buf, val); @@ -2678,7 +2875,7 @@ LogAccess::marshal_proxy_req_squid_len(char *buf) { if (buf) { int64_t val = 0; - if (m_proxy_request) { + if (m_proxy_request && has_http_sm()) { val = m_proxy_request->length_get() + m_http_sm->server_request_body_bytes; } marshal_int(buf, val); @@ -2690,6 +2887,9 @@ LogAccess::marshal_proxy_req_squid_len(char *buf) int LogAccess::marshal_proxy_req_server_ip(char *buf) { + if (!has_http_sm()) { + return marshal_ip(buf, nullptr); + } return marshal_ip(buf, m_http_sm->t_state.current.server != nullptr ? &m_http_sm->t_state.current.server->src_addr.sa : nullptr); } @@ -2697,8 +2897,10 @@ int LogAccess::marshal_proxy_req_server_port(char *buf) { if (buf) { - uint16_t port = - m_http_sm->t_state.current.server != nullptr ? m_http_sm->t_state.current.server->src_addr.host_order_port() : 0; + uint16_t port = 0; + if (has_http_sm()) { + port = m_http_sm->t_state.current.server != nullptr ? m_http_sm->t_state.current.server->src_addr.host_order_port() : 0; + } marshal_int(buf, port); } return INK_MIN_ALIGN; @@ -2707,6 +2909,9 @@ LogAccess::marshal_proxy_req_server_port(char *buf) int LogAccess::marshal_next_hop_ip(char *buf) { + if (!has_http_sm()) { + return marshal_ip(buf, nullptr); + } return marshal_ip(buf, m_http_sm->t_state.current.server != nullptr ? &m_http_sm->t_state.current.server->dst_addr.sa : nullptr); } @@ -2714,8 +2919,10 @@ int LogAccess::marshal_next_hop_port(char *buf) { if (buf) { - uint16_t port = - m_http_sm->t_state.current.server != nullptr ? m_http_sm->t_state.current.server->dst_addr.host_order_port() : 0; + uint16_t port = 0; + if (has_http_sm()) { + port = m_http_sm->t_state.current.server != nullptr ? m_http_sm->t_state.current.server->dst_addr.host_order_port() : 0; + } marshal_int(buf, port); } return INK_MIN_ALIGN; @@ -2728,8 +2935,7 @@ int LogAccess::marshal_proxy_req_is_ssl(char *buf) { if (buf) { - int64_t is_ssl; - is_ssl = m_http_sm->server_connection_is_ssl; + int64_t is_ssl = has_http_sm() ? m_http_sm->server_connection_is_ssl : 0; marshal_int(buf, is_ssl); } return INK_MIN_ALIGN; @@ -2739,7 +2945,7 @@ int LogAccess::marshal_proxy_req_ssl_reused(char *buf) { if (buf) { - marshal_int(buf, m_http_sm->server_ssl_reused ? 1 : 0); + marshal_int(buf, has_http_sm() && m_http_sm->server_ssl_reused ? 1 : 0); } return INK_MIN_ALIGN; } @@ -2751,7 +2957,12 @@ int LogAccess::marshal_proxy_hierarchy_route(char *buf) { if (buf) { - SquidHierarchyCode code = m_http_sm->t_state.squid_codes.hier_code; + SquidHierarchyCode code = SquidHierarchyCode::EMPTY; + if (has_http_sm()) { + code = m_http_sm->t_state.squid_codes.hier_code; + } else if (auto const *pre = this->get_pre_transaction_log_data(); pre != nullptr) { + code = pre->hier_code; + } marshal_int(buf, static_cast(code)); } return INK_MIN_ALIGN; @@ -2764,6 +2975,10 @@ LogAccess::marshal_proxy_hierarchy_route(char *buf) int LogAccess::marshal_server_host_ip(char *buf) { + if (!has_http_sm()) { + return marshal_ip(buf, nullptr); + } + sockaddr const *ip = nullptr; ip = &m_http_sm->t_state.server_info.dst_addr.sa; if (!ats_is_ip(ip)) { @@ -2788,7 +3003,7 @@ LogAccess::marshal_server_host_name(char *buf) char *str = nullptr; int len = INK_MIN_ALIGN; - if (m_http_sm->t_state.current.server) { + if (has_http_sm() && m_http_sm->t_state.current.server) { str = m_http_sm->t_state.current.server->name; len = LogAccess::padded_strlen(str); } @@ -2825,7 +3040,7 @@ LogAccess::marshal_server_resp_content_len(char *buf) { if (buf) { int64_t val = 0; - if (m_server_response) { + if (m_server_response && has_http_sm()) { val = m_http_sm->server_response_body_bytes; } marshal_int(buf, val); @@ -2854,7 +3069,7 @@ LogAccess::marshal_server_resp_squid_len(char *buf) { if (buf) { int64_t val = 0; - if (m_server_response) { + if (m_server_response && has_http_sm()) { val = m_server_response->length_get() + m_http_sm->server_response_body_bytes; } marshal_int(buf, val); @@ -2884,7 +3099,11 @@ int LogAccess::marshal_server_resp_time_ms(char *buf) { if (buf) { - marshal_int(buf, m_http_sm->milestones.difference_msec(TS_MILESTONE_SERVER_CONNECT, TS_MILESTONE_SERVER_CLOSE)); + int64_t val = -1; + if (has_http_sm()) { + val = m_http_sm->milestones.difference_msec(TS_MILESTONE_SERVER_CONNECT, TS_MILESTONE_SERVER_CLOSE); + } + marshal_int(buf, val); } return INK_MIN_ALIGN; } @@ -2893,8 +3112,11 @@ int LogAccess::marshal_server_resp_time_s(char *buf) { if (buf) { - marshal_int(buf, - static_cast(m_http_sm->milestones.difference_sec(TS_MILESTONE_SERVER_CONNECT, TS_MILESTONE_SERVER_CLOSE))); + int64_t val = -1; + if (has_http_sm()) { + val = static_cast(m_http_sm->milestones.difference_sec(TS_MILESTONE_SERVER_CONNECT, TS_MILESTONE_SERVER_CLOSE)); + } + marshal_int(buf, val); } return INK_MIN_ALIGN; } @@ -2906,8 +3128,12 @@ int LogAccess::marshal_server_transact_count(char *buf) { if (buf) { - int64_t count; - count = m_http_sm->server_transact_count; + int64_t count = 0; + if (has_http_sm()) { + count = m_http_sm->server_transact_count; + } else if (auto const *pre = this->get_pre_transaction_log_data(); pre != nullptr) { + count = pre->server_transact_count; + } marshal_int(buf, count); } return INK_MIN_ALIGN; @@ -2920,7 +3146,7 @@ int LogAccess::marshal_server_simple_retry_count(char *buf) { if (buf) { - const int64_t attempts = m_http_sm->t_state.current.simple_retry_attempts; + const int64_t attempts = has_http_sm() ? m_http_sm->t_state.current.simple_retry_attempts : 0; marshal_int(buf, attempts); } return INK_MIN_ALIGN; @@ -2933,7 +3159,7 @@ int LogAccess::marshal_server_unavailable_retry_count(char *buf) { if (buf) { - const int64_t attempts = m_http_sm->t_state.current.unavailable_server_retry_attempts; + const int64_t attempts = has_http_sm() ? m_http_sm->t_state.current.unavailable_server_retry_attempts : 0; marshal_int(buf, attempts); } return INK_MIN_ALIGN; @@ -2946,7 +3172,7 @@ int LogAccess::marshal_server_connect_attempts(char *buf) { if (buf) { - int64_t attempts = m_http_sm->t_state.current.retry_attempts.saved(); + int64_t attempts = has_http_sm() ? m_http_sm->t_state.current.retry_attempts.saved() : 0; marshal_int(buf, attempts); } return INK_MIN_ALIGN; @@ -2978,7 +3204,7 @@ LogAccess::marshal_cache_resp_content_len(char *buf) { if (buf) { int64_t val = 0; - if (m_cache_response) { + if (m_cache_response && has_http_sm()) { val = m_http_sm->cache_response_body_bytes; } marshal_int(buf, val); @@ -2991,7 +3217,7 @@ LogAccess::marshal_cache_resp_squid_len(char *buf) { if (buf) { int64_t val = 0; - if (m_cache_response) { + if (m_cache_response && has_http_sm()) { val = m_cache_response->length_get() + m_http_sm->cache_response_body_bytes; } marshal_int(buf, val); @@ -3007,7 +3233,7 @@ LogAccess::marshal_cache_resp_header_len(char *buf) { if (buf) { int64_t val = 0; - if (m_cache_response) { + if (m_cache_response && has_http_sm()) { val = m_http_sm->cache_response_hdr_bytes; } marshal_int(buf, val); @@ -3035,7 +3261,7 @@ int LogAccess::marshal_client_retry_after_time(char *buf) { if (buf) { - int64_t crat = m_http_sm->t_state.congestion_control_crat; + int64_t crat = has_http_sm() ? m_http_sm->t_state.congestion_control_crat : 0; marshal_int(buf, crat); } return INK_MIN_ALIGN; @@ -3078,7 +3304,7 @@ int LogAccess::marshal_cache_write_code(char *buf) { if (buf) { - int code = convert_cache_write_code(m_http_sm->t_state.cache_info.write_status); + int code = has_http_sm() ? convert_cache_write_code(m_http_sm->t_state.cache_info.write_status) : LOG_CACHE_WRITE_NONE; marshal_int(buf, code); } @@ -3089,7 +3315,8 @@ int LogAccess::marshal_cache_write_transform_code(char *buf) { if (buf) { - int code = convert_cache_write_code(m_http_sm->t_state.cache_info.transform_write_status); + int code = + has_http_sm() ? convert_cache_write_code(m_http_sm->t_state.cache_info.transform_write_status) : LOG_CACHE_WRITE_NONE; marshal_int(buf, code); } @@ -3103,7 +3330,7 @@ int LogAccess::marshal_transfer_time_ms(char *buf) { if (buf) { - marshal_int(buf, m_http_sm->milestones.difference_msec(TS_MILESTONE_SM_START, TS_MILESTONE_SM_FINISH)); + marshal_int(buf, this->get_milestones().difference_msec(TS_MILESTONE_SM_START, TS_MILESTONE_SM_FINISH)); } return INK_MIN_ALIGN; } @@ -3112,7 +3339,7 @@ int LogAccess::marshal_transfer_time_s(char *buf) { if (buf) { - marshal_int(buf, static_cast(m_http_sm->milestones.difference_sec(TS_MILESTONE_SM_START, TS_MILESTONE_SM_FINISH))); + marshal_int(buf, static_cast(this->get_milestones().difference_sec(TS_MILESTONE_SM_START, TS_MILESTONE_SM_FINISH))); } return INK_MIN_ALIGN; } @@ -3140,9 +3367,9 @@ LogAccess::marshal_file_size(char *buf) } } else { // This is semi-broken when we serveq zero length objects. See TS-2213 - if (m_http_sm->server_response_body_bytes > 0) { + if (has_http_sm() && m_http_sm->server_response_body_bytes > 0) { marshal_int(buf, m_http_sm->server_response_body_bytes); - } else if (m_http_sm->cache_response_body_bytes > 0) { + } else if (has_http_sm() && m_http_sm->cache_response_body_bytes > 0) { marshal_int(buf, m_http_sm->cache_response_body_bytes); } } @@ -3160,7 +3387,7 @@ LogAccess::marshal_client_http_connection_id(char *buf) { if (buf) { int64_t id = 0; - if (m_http_sm) { + if (has_http_sm()) { id = m_http_sm->client_connection_id(); } marshal_int(buf, id); @@ -3176,7 +3403,7 @@ LogAccess::marshal_client_http_transaction_id(char *buf) { if (buf) { int64_t id = 0; - if (m_http_sm) { + if (has_http_sm()) { id = m_http_sm->client_transaction_id(); } marshal_int(buf, id); @@ -3192,7 +3419,7 @@ LogAccess::marshal_client_http_transaction_priority_weight(char *buf) { if (buf) { int64_t id = 0; - if (m_http_sm) { + if (has_http_sm()) { id = m_http_sm->client_transaction_priority_weight(); } marshal_int(buf, id); @@ -3208,7 +3435,7 @@ LogAccess::marshal_client_http_transaction_priority_dependence(char *buf) { if (buf) { int64_t id = 0; - if (m_http_sm) { + if (has_http_sm()) { id = m_http_sm->client_transaction_priority_dependence(); } marshal_int(buf, id); @@ -3224,7 +3451,7 @@ LogAccess::marshal_cache_read_retries(char *buf) { if (buf) { int64_t id = 0; - if (m_http_sm) { + if (has_http_sm()) { id = m_http_sm->get_cache_sm().get_open_read_tries(); } marshal_int(buf, id); @@ -3240,7 +3467,7 @@ LogAccess::marshal_cache_write_retries(char *buf) { if (buf) { int64_t id = 0; - if (m_http_sm) { + if (has_http_sm()) { id = m_http_sm->get_cache_sm().get_open_write_tries(); } marshal_int(buf, id); @@ -3253,7 +3480,7 @@ LogAccess::marshal_cache_collapsed_connection_success(char *buf) { if (buf) { int64_t id = 0; // default - no collapse attempt - if (m_http_sm) { + if (has_http_sm()) { SquidLogCode code = m_http_sm->t_state.squid_codes.log_code; // We attempted an open write, but ended up with some sort of HIT which means we must have gone back to the read state @@ -3370,7 +3597,7 @@ LogAccess::marshal_http_header_field(LogField::Container container, char *field, // The Transfer-Encoding:chunked value may have been removed from the header // during processing, but we store it for logging purposes. - if (valid_field == false && container == LogField::SSH && strcmp(field, "Transfer-Encoding") == 0) { + if (valid_field == false && has_http_sm() && container == LogField::SSH && strcmp(field, "Transfer-Encoding") == 0) { const std::string &stored_te = m_http_sm->t_state.hdr_info.server_response_transfer_encoding; if (!stored_te.empty()) { valid_field = true; @@ -3515,7 +3742,7 @@ int LogAccess::marshal_milestone(TSMilestonesType ms, char *buf) { if (buf) { - int64_t val = ink_hrtime_to_msec(m_http_sm->milestones[ms]); + int64_t val = ink_hrtime_to_msec(this->get_milestones()[ms]); marshal_int(buf, val); } return INK_MIN_ALIGN; @@ -3525,7 +3752,7 @@ int LogAccess::marshal_milestone_fmt_sec(TSMilestonesType type, char *buf) { if (buf) { - ink_hrtime tsec = ink_hrtime_to_sec(m_http_sm->milestones[type]); + ink_hrtime tsec = ink_hrtime_to_sec(this->get_milestones()[type]); marshal_int(buf, tsec); } return INK_MIN_ALIGN; @@ -3535,7 +3762,7 @@ int LogAccess::marshal_milestone_fmt_ms(TSMilestonesType type, char *buf) { if (buf) { - ink_hrtime tmsec = ink_hrtime_to_msec(m_http_sm->milestones[type]); + ink_hrtime tmsec = ink_hrtime_to_msec(this->get_milestones()[type]); marshal_int(buf, tmsec); } return INK_MIN_ALIGN; @@ -3545,7 +3772,7 @@ int LogAccess::marshal_milestone_diff(TSMilestonesType ms1, TSMilestonesType ms2, char *buf) { if (buf) { - int64_t val = m_http_sm->milestones.difference_msec(ms2, ms1); + int64_t val = this->get_milestones().difference_msec(ms2, ms1); marshal_int(buf, val); } return INK_MIN_ALIGN; @@ -3556,28 +3783,29 @@ LogAccess::marshal_milestones_csv(char *buf) { Dbg(dbg_ctl_log_unmarshal_data, "marshal_milestones_csv"); + auto const &milestones = this->get_milestones(); swoc::LocalBufferWriter<256> bw; - bw.print("{}", m_http_sm->milestones.difference_msec(TS_MILESTONE_TLS_HANDSHAKE_START, TS_MILESTONE_TLS_HANDSHAKE_END)); - bw.print(",{}", m_http_sm->milestones.difference_msec(TS_MILESTONE_SM_START, TS_MILESTONE_UA_BEGIN)); - bw.print(",{}", m_http_sm->milestones.difference_msec(TS_MILESTONE_SM_START, TS_MILESTONE_UA_FIRST_READ)); - bw.print(",{}", m_http_sm->milestones.difference_msec(TS_MILESTONE_SM_START, TS_MILESTONE_UA_READ_HEADER_DONE)); - bw.print(",{}", m_http_sm->milestones.difference_msec(TS_MILESTONE_SM_START, TS_MILESTONE_CACHE_OPEN_READ_BEGIN)); - bw.print(",{}", m_http_sm->milestones.difference_msec(TS_MILESTONE_SM_START, TS_MILESTONE_CACHE_OPEN_READ_END)); - bw.print(",{}", m_http_sm->milestones.difference_msec(TS_MILESTONE_SM_START, TS_MILESTONE_CACHE_OPEN_WRITE_BEGIN)); - bw.print(",{}", m_http_sm->milestones.difference_msec(TS_MILESTONE_SM_START, TS_MILESTONE_CACHE_OPEN_WRITE_END)); - bw.print(",{}", m_http_sm->milestones.difference_msec(TS_MILESTONE_SM_START, TS_MILESTONE_DNS_LOOKUP_BEGIN)); - bw.print(",{}", m_http_sm->milestones.difference_msec(TS_MILESTONE_SM_START, TS_MILESTONE_DNS_LOOKUP_END)); - bw.print(",{}", m_http_sm->milestones.difference_msec(TS_MILESTONE_SM_START, TS_MILESTONE_SERVER_CONNECT)); - bw.print(",{}", m_http_sm->milestones.difference_msec(TS_MILESTONE_SM_START, TS_MILESTONE_SERVER_CONNECT_END)); - bw.print(",{}", m_http_sm->milestones.difference_msec(TS_MILESTONE_SM_START, TS_MILESTONE_SERVER_FIRST_READ)); - bw.print(",{}", m_http_sm->milestones.difference_msec(TS_MILESTONE_SM_START, TS_MILESTONE_SERVER_READ_HEADER_DONE)); - bw.print(",{}", m_http_sm->milestones.difference_msec(TS_MILESTONE_SM_START, TS_MILESTONE_SERVER_CLOSE)); - bw.print(",{}", m_http_sm->milestones.difference_msec(TS_MILESTONE_SM_START, TS_MILESTONE_UA_BEGIN_WRITE)); - bw.print(",{}", m_http_sm->milestones.difference_msec(TS_MILESTONE_SM_START, TS_MILESTONE_UA_CLOSE)); - bw.print(",{}", m_http_sm->milestones.difference_msec(TS_MILESTONE_SM_START, TS_MILESTONE_SM_FINISH)); - bw.print(",{}", m_http_sm->milestones.difference_msec(TS_MILESTONE_SM_START, TS_MILESTONE_PLUGIN_ACTIVE)); - bw.print(",{}", m_http_sm->milestones.difference_msec(TS_MILESTONE_SM_START, TS_MILESTONE_PLUGIN_TOTAL)); + bw.print("{}", milestones.difference_msec(TS_MILESTONE_TLS_HANDSHAKE_START, TS_MILESTONE_TLS_HANDSHAKE_END)); + bw.print(",{}", milestones.difference_msec(TS_MILESTONE_SM_START, TS_MILESTONE_UA_BEGIN)); + bw.print(",{}", milestones.difference_msec(TS_MILESTONE_SM_START, TS_MILESTONE_UA_FIRST_READ)); + bw.print(",{}", milestones.difference_msec(TS_MILESTONE_SM_START, TS_MILESTONE_UA_READ_HEADER_DONE)); + bw.print(",{}", milestones.difference_msec(TS_MILESTONE_SM_START, TS_MILESTONE_CACHE_OPEN_READ_BEGIN)); + bw.print(",{}", milestones.difference_msec(TS_MILESTONE_SM_START, TS_MILESTONE_CACHE_OPEN_READ_END)); + bw.print(",{}", milestones.difference_msec(TS_MILESTONE_SM_START, TS_MILESTONE_CACHE_OPEN_WRITE_BEGIN)); + bw.print(",{}", milestones.difference_msec(TS_MILESTONE_SM_START, TS_MILESTONE_CACHE_OPEN_WRITE_END)); + bw.print(",{}", milestones.difference_msec(TS_MILESTONE_SM_START, TS_MILESTONE_DNS_LOOKUP_BEGIN)); + bw.print(",{}", milestones.difference_msec(TS_MILESTONE_SM_START, TS_MILESTONE_DNS_LOOKUP_END)); + bw.print(",{}", milestones.difference_msec(TS_MILESTONE_SM_START, TS_MILESTONE_SERVER_CONNECT)); + bw.print(",{}", milestones.difference_msec(TS_MILESTONE_SM_START, TS_MILESTONE_SERVER_CONNECT_END)); + bw.print(",{}", milestones.difference_msec(TS_MILESTONE_SM_START, TS_MILESTONE_SERVER_FIRST_READ)); + bw.print(",{}", milestones.difference_msec(TS_MILESTONE_SM_START, TS_MILESTONE_SERVER_READ_HEADER_DONE)); + bw.print(",{}", milestones.difference_msec(TS_MILESTONE_SM_START, TS_MILESTONE_SERVER_CLOSE)); + bw.print(",{}", milestones.difference_msec(TS_MILESTONE_SM_START, TS_MILESTONE_UA_BEGIN_WRITE)); + bw.print(",{}", milestones.difference_msec(TS_MILESTONE_SM_START, TS_MILESTONE_UA_CLOSE)); + bw.print(",{}", milestones.difference_msec(TS_MILESTONE_SM_START, TS_MILESTONE_SM_FINISH)); + bw.print(",{}", milestones.difference_msec(TS_MILESTONE_SM_START, TS_MILESTONE_PLUGIN_ACTIVE)); + bw.print(",{}", milestones.difference_msec(TS_MILESTONE_SM_START, TS_MILESTONE_PLUGIN_TOTAL)); bw.print("\0"); auto const view = bw.view(); diff --git a/src/proxy/logging/unit-tests/test_LogAccess.cc b/src/proxy/logging/unit-tests/test_LogAccess.cc new file mode 100644 index 00000000000..38e79aa5b97 --- /dev/null +++ b/src/proxy/logging/unit-tests/test_LogAccess.cc @@ -0,0 +1,209 @@ +/** @file + + Unit tests for LogAccess. + + @section license License + + Licensed to the Apache Software Foundation (ASF) under one + or more contributor license agreements. See the NOTICE file + distributed with this work for additional information + regarding copyright ownership. The ASF licenses this file + to you under the Apache License, Version 2.0 (the + "License"); you may not use this file except in compliance + with the License. You may obtain a copy of the License at + + http://www.apache.org/licenses/LICENSE-2.0 + + Unless required by applicable law or agreed to in writing, software + distributed under the License is distributed on an "AS IS" BASIS, + WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + See the License for the specific language governing permissions and + limitations under the License. + */ + +#include + +#include "proxy/logging/LogAccess.h" +#include "tscore/ink_inet.h" + +#include +#include + +using namespace std::literals; + +extern int cmd_disable_pfreelist; + +namespace +{ +void +initialize_headers_once() +{ + static bool initialized = false; + + if (!initialized) { + cmd_disable_pfreelist = true; + url_init(); + mime_init(); + http_init(); + initialized = true; + } +} + +void +add_header_field(HTTPHdr &hdr, std::string_view name, std::string_view value) +{ + MIMEField *field = hdr.field_create(name); + REQUIRE(field != nullptr); + field->value_set(hdr.m_heap, hdr.m_mime, value); + hdr.field_attach(field); +} + +std::string +synthesize_target(std::string_view method, std::string_view scheme, std::string_view authority, std::string_view path) +{ + if (method == static_cast(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); + } + + return authority.empty() ? std::string{} : std::string(authority); +} + +void +set_socket_address(sockaddr_storage &addr, std::string_view text) +{ + REQUIRE(0 == ats_ip_pton(text, reinterpret_cast(&addr))); +} + +void +populate_pre_transaction_data(LogAccess::PreTransactionLogData &data, std::string_view method, std::string_view scheme, + std::string_view authority, std::string_view path) +{ + initialize_headers_once(); + + auto *heap = new_HdrHeap(HdrHeap::DEFAULT_SIZE + 64); + data.client_request.create(HTTPType::REQUEST, HTTP_2_0, heap); + data.client_request.method_set(method); + data.has_client_request = true; + data.client_connection_is_ssl = true; + data.log_code = SquidLogCode::ERR_INVALID_REQ; + data.hit_miss_code = SQUID_MISS_NONE; + data.hier_code = SquidHierarchyCode::NONE; + data.server_transact_count = 0; + data.client_protocol = "http/2"; + data.method.assign(method.data(), method.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_target(method, scheme, authority, path); + set_socket_address(data.client_addr, "192.0.2.10:4321"sv); + + add_header_field(data.client_request, PSEUDO_HEADER_METHOD, method); + if (!scheme.empty()) { + add_header_field(data.client_request, PSEUDO_HEADER_SCHEME, scheme); + } + if (!authority.empty()) { + add_header_field(data.client_request, PSEUDO_HEADER_AUTHORITY, authority); + } + if (!path.empty()) { + add_header_field(data.client_request, PSEUDO_HEADER_PATH, path); + } + add_header_field(data.client_request, static_cast(MIME_FIELD_USER_AGENT), "TikTok/1.0"); + + data.milestones[TS_MILESTONE_SM_START] = ink_hrtime_from_msec(10); + data.milestones[TS_MILESTONE_UA_BEGIN] = ink_hrtime_from_msec(10); + data.milestones[TS_MILESTONE_UA_FIRST_READ] = ink_hrtime_from_msec(12); + data.milestones[TS_MILESTONE_UA_READ_HEADER_DONE] = ink_hrtime_from_msec(14); + data.milestones[TS_MILESTONE_SM_FINISH] = ink_hrtime_from_msec(15); +} + +template +std::string +marshal_string(Marshal marshal) +{ + const int len = marshal(nullptr); + std::vector buffer(len); + marshal(buffer.data()); + return std::string(buffer.data()); +} + +template +int64_t +marshal_int_value(Marshal marshal) +{ + std::vector buffer(INK_MIN_ALIGN * 2); + marshal(buffer.data()); + char *ptr = buffer.data(); + return LogAccess::unmarshal_int(&ptr); +} +} // namespace + +TEST_CASE("LogAccess pre-transaction CONNECT fields", "[LogAccess]") +{ + LogAccess::PreTransactionLogData data; + populate_pre_transaction_data(data, "CONNECT", ""sv, "example.com:443", ""sv); + LogAccess access(data); + + access.init(); + + CHECK(marshal_string([&](char *buf) { return access.marshal_client_req_http_method(buf); }) == "CONNECT"); + CHECK(marshal_string([&](char *buf) { return access.marshal_client_req_protocol_version(buf); }) == "http/2"); + CHECK(marshal_string([&](char *buf) { return access.marshal_client_req_url(buf); }) == "example.com:443"); + CHECK(marshal_int_value([&](char *buf) { return access.marshal_cache_result_code(buf); }) == + static_cast(SquidLogCode::ERR_INVALID_REQ)); + CHECK(marshal_int_value([&](char *buf) { return access.marshal_server_transact_count(buf); }) == 0); + + char user_agent[] = "User-Agent"; + CHECK(marshal_string([&](char *buf) { return access.marshal_http_header_field(LogField::CQH, user_agent, buf); }) == + "TikTok/1.0"); +} + +TEST_CASE("LogAccess malformed CONNECT without authority falls back to path", "[LogAccess]") +{ + LogAccess::PreTransactionLogData data; + populate_pre_transaction_data(data, "CONNECT", "https"sv, ""sv, "/"sv); + LogAccess access(data); + + access.init(); + + CHECK(marshal_string([&](char *buf) { return access.marshal_client_req_url(buf); }) == "/"); + CHECK(marshal_string([&](char *buf) { return access.marshal_client_req_url_canon(buf); }) == "/"); + CHECK(marshal_string([&](char *buf) { return access.marshal_client_req_url_path(buf); }) == "/"); + CHECK(marshal_string([&](char *buf) { return access.marshal_client_req_url_scheme(buf); }) == "https"); + CHECK(marshal_int_value([&](char *buf) { return access.marshal_transfer_time_ms(buf); }) == 5); +} + +TEST_CASE("LogAccess pre-transaction client host port is null-safe", "[LogAccess]") +{ + LogAccess::PreTransactionLogData data; + populate_pre_transaction_data(data, "GET", "https"sv, "example.com", "/client-port"sv); + LogAccess access(data); + + access.init(); + + CHECK(access.marshal_client_host_port(nullptr) == INK_MIN_ALIGN); + CHECK(marshal_int_value([&](char *buf) { return access.marshal_client_host_port(buf); }) == 4321); +} diff --git a/tests/gold_tests/connect/h2_malformed_request_logging.test.py b/tests/gold_tests/connect/h2_malformed_request_logging.test.py new file mode 100644 index 00000000000..16ba7df48a1 --- /dev/null +++ b/tests/gold_tests/connect/h2_malformed_request_logging.test.py @@ -0,0 +1,207 @@ +''' +Verify malformed HTTP/2 requests are access logged. +''' +# Licensed to the Apache Software Foundation (ASF) under one +# or more contributor license agreements. See the NOTICE file +# distributed with this work for additional information +# regarding copyright ownership. The ASF licenses this file +# to you under the Apache License, Version 2.0 (the +# "License"); you may not use this file except in compliance +# with the License. You may obtain a copy of the License at +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +# See the License for the specific language governing permissions and +# limitations under the License. + +import os +import re +import sys + +Test.Summary = 'Malformed HTTP/2 requests are logged before transaction creation' + + +class MalformedH2RequestLoggingTest: + """ + Exercise malformed and valid HTTP/2 request logging paths. + """ + + REPLAY_FILE = 'replays/h2_malformed_request_logging.replay.yaml' + MALFORMED_CLIENT = 'malformed_h2_request_client.py' + MALFORMED_CASES = ( + { + 'scenario': 'connect-missing-authority', + 'uuid': 'malformed-connect', + 'method': 'CONNECT', + 'pqu': '/', + 'description': 'Send malformed HTTP/2 CONNECT request', + }, + { + 'scenario': 'get-missing-path', + 'uuid': 'malformed-get-missing-path', + 'method': 'GET', + 'pqu': 'https://missing-path.example/', + 'description': 'Send malformed HTTP/2 GET request without :path', + }, + { + 'scenario': 'get-connection-header', + 'uuid': 'malformed-get-connection', + 'method': 'GET', + 'pqu': 'https://bad-connection.example/bad-connection', + 'description': 'Send malformed HTTP/2 GET request with Connection header', + }, + ) + + def __init__(self): + self._setup_server() + self._setup_ts() + self._processes_started = False + Test.Setup.CopyAs(self.MALFORMED_CLIENT, Test.RunDirectory) + + @property + def _squid_log_path(self) -> str: + return os.path.join(self._ts.Variables.LOGDIR, 'squid.log') + + def _setup_server(self): + self._server = Test.MakeVerifierServerProcess('malformed-request-server', self.REPLAY_FILE) + for case in self.MALFORMED_CASES: + self._server.Streams.stdout += Testers.ExcludesExpression( + f'uuid: {case["uuid"]}', + f'{case["description"]} must not reach the origin server.', + ) + self._server.Streams.stdout += Testers.ContainsExpression( + 'GET /get HTTP/1.1\nuuid: valid-connect', + reflags=re.MULTILINE, + description='A valid CONNECT tunnel should still reach the origin.', + ) + self._server.Streams.stdout += Testers.ContainsExpression( + r'GET /valid-get HTTP/1\.1\n(?:.*\n)*uuid: valid-get', + reflags=re.MULTILINE, + description='A valid non-CONNECT request should still reach the origin.', + ) + + def _setup_ts(self): + self._ts = Test.MakeATSProcess('ts', enable_tls=True, enable_cache=False) + self._ts.addDefaultSSLFiles() + self._ts.Disk.File( + os.path.join(self._ts.Variables.CONFIGDIR, 'storage.config'), + id='storage_config', + typename='ats:config', + ) + self._ts.Disk.storage_config.AddLine('') + self._ts.Disk.ssl_multicert_yaml.AddLines( + """ +ssl_multicert: + - dest_ip: "*" + ssl_cert_name: server.pem + ssl_key_name: server.key +""".split('\n')) + self._ts.Disk.File( + os.path.join(self._ts.Variables.CONFIGDIR, 'ssl_multicert.config'), + id='ssl_multicert_config', + typename='ats:config', + ) + self._ts.Disk.ssl_multicert_config.AddLine('ssl_cert_name=server.pem ssl_key_name=server.key dest_ip=*') + + self._ts.Disk.records_config.update( + { + 'proxy.config.diags.debug.enabled': 1, + 'proxy.config.diags.debug.tags': 'http|hpack|http2', + 'proxy.config.ssl.server.cert.path': self._ts.Variables.SSLDir, + 'proxy.config.ssl.server.private_key.path': self._ts.Variables.SSLDir, + 'proxy.config.http.server_ports': f'{self._ts.Variables.ssl_port}:ssl', + 'proxy.config.http.connect_ports': self._server.Variables.http_port, + }) + self._ts.Disk.remap_config.AddLine(f'map / http://127.0.0.1:{self._server.Variables.http_port}/') + self._ts.Disk.logging_yaml.AddLines( + """ +logging: + formats: + - name: malformed_h2_request + format: 'uuid=%<{uuid}cqh> cqpv=% cqhm=% crc=% sstc=% pqu=%' + logs: + - filename: squid + format: malformed_h2_request + mode: ascii +""".split('\n')) + self._ts.Disk.diags_log.Content = Testers.ContainsExpression( + 'recv headers malformed request', + 'ATS should reject malformed requests at the HTTP/2 layer.', + ) + for index, case in enumerate(self.MALFORMED_CASES): + expected = ( + rf'uuid={case["uuid"]} cqpv=http/2 cqhm={case["method"]} ' + rf'crc=ERR_INVALID_REQ sstc=0 pqu={re.escape(case["pqu"])}') + tester = Testers.ContainsExpression( + expected, + f'{case["description"]} should be logged with ERR_INVALID_REQ.', + ) + if index == 0: + self._ts.Disk.squid_log.Content = tester + else: + self._ts.Disk.squid_log.Content += tester + self._ts.Disk.squid_log.Content += Testers.ContainsExpression( + r'uuid=valid-connect cqpv=http/2 cqhm=CONNECT ', + 'A valid HTTP/2 CONNECT should still use the normal transaction log path.', + ) + self._ts.Disk.squid_log.Content += Testers.ContainsExpression( + r'uuid=valid-get cqpv=http/2 cqhm=GET ', + 'A valid HTTP/2 GET should still use the normal transaction log path.', + ) + self._ts.Disk.squid_log.Content += Testers.ExcludesExpression( + r'uuid=valid-connect .*crc=ERR_INVALID_REQ', + 'Valid HTTP/2 CONNECT logging must not be marked as malformed.', + ) + self._ts.Disk.squid_log.Content += Testers.ExcludesExpression( + r'uuid=valid-get .*crc=ERR_INVALID_REQ', + 'Valid HTTP/2 GET logging must not be marked as malformed.', + ) + + def _add_malformed_request_runs(self): + for case in self.MALFORMED_CASES: + tr = Test.AddTestRun(case['description']) + tr.Processes.Default.Command = ( + f'{sys.executable} {self.MALFORMED_CLIENT} {self._ts.Variables.ssl_port} {case["scenario"]}') + tr.Processes.Default.ReturnCode = 0 + self._keep_support_processes_running(tr) + tr.Processes.Default.Streams.stdout += Testers.ContainsExpression( + r'Received (RST_STREAM on stream 1 with error code 1|GOAWAY with error code [01])', + 'ATS should reject the malformed request at the HTTP/2 layer.', + ) + + def _add_valid_request_run(self): + tr = Test.AddTestRun('Send valid HTTP/2 requests') + tr.AddVerifierClientProcess('valid-request-client', self.REPLAY_FILE, https_ports=[self._ts.Variables.ssl_port]) + self._keep_support_processes_running(tr) + + def _await_malformed_log_entries(self): + tr = Test.AddAwaitFileContainsTestRun( + 'Await malformed request squid log entries', + self._squid_log_path, + 'crc=ERR_INVALID_REQ', + desired_count=len(self.MALFORMED_CASES), + ) + self._keep_support_processes_running(tr) + + def _keep_support_processes_running(self, tr): + if self._processes_started: + tr.StillRunningAfter = self._server + tr.StillRunningAfter = self._ts + return + + tr.Processes.Default.StartBefore(self._server) + tr.Processes.Default.StartBefore(self._ts) + tr.StillRunningAfter = self._server + tr.StillRunningAfter = self._ts + self._processes_started = True + + def run(self): + self._add_malformed_request_runs() + self._add_valid_request_run() + self._await_malformed_log_entries() + + +MalformedH2RequestLoggingTest().run() diff --git a/tests/gold_tests/connect/malformed_h2_request_client.py b/tests/gold_tests/connect/malformed_h2_request_client.py new file mode 100644 index 00000000000..c60178287c0 --- /dev/null +++ b/tests/gold_tests/connect/malformed_h2_request_client.py @@ -0,0 +1,172 @@ +#!/usr/bin/env python3 + +# Licensed to the Apache Software Foundation (ASF) under one +# or more contributor license agreements. See the NOTICE file +# distributed with this work for additional information +# regarding copyright ownership. The ASF licenses this file +# to you under the Apache License, Version 2.0 (the +# "License"); you may not use this file except in compliance +# with the License. You may obtain a copy of the License at +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +# See the License for the specific language governing permissions and +# limitations under the License. +""" +Send malformed HTTP/2 requests directly on the wire. +""" + +import argparse +import socket +import ssl +import sys + +import hpack + +H2_PREFACE = b"PRI * HTTP/2.0\r\n\r\nSM\r\n\r\n" + +TYPE_HEADERS = 0x01 +TYPE_RST_STREAM = 0x03 +TYPE_SETTINGS = 0x04 +TYPE_GOAWAY = 0x07 + +FLAG_ACK = 0x01 +FLAG_END_STREAM = 0x01 +FLAG_END_HEADERS = 0x04 + +PROTOCOL_ERROR = 0x01 + + +def make_frame(frame_type: int, flags: int, stream_id: int, payload: bytes = b"") -> bytes: + return (len(payload).to_bytes(3, "big") + bytes([frame_type, flags]) + (stream_id & 0x7FFFFFFF).to_bytes(4, "big") + payload) + + +def recv_exact(sock: socket.socket, size: int) -> bytes: + data = bytearray() + while len(data) < size: + chunk = sock.recv(size - len(data)) + if not chunk: + break + data.extend(chunk) + return bytes(data) + + +def read_frame(sock: socket.socket): + header = recv_exact(sock, 9) + if len(header) == 0: + return None + if len(header) != 9: + raise RuntimeError(f"incomplete frame header: got {len(header)} bytes") + + length = int.from_bytes(header[0:3], "big") + payload = recv_exact(sock, length) + if len(payload) != length: + raise RuntimeError(f"incomplete frame payload: expected {length}, got {len(payload)}") + + return { + "length": length, + "type": header[3], + "flags": header[4], + "stream_id": int.from_bytes(header[5:9], "big") & 0x7FFFFFFF, + "payload": payload, + } + + +def connect_socket(port: int) -> socket.socket: + socket.setdefaulttimeout(5) + + ctx = ssl.create_default_context() + ctx.check_hostname = False + ctx.verify_mode = ssl.CERT_NONE + ctx.set_alpn_protocols(["h2"]) + + tls_socket = socket.create_connection(("127.0.0.1", port)) + tls_socket = ctx.wrap_socket(tls_socket, server_hostname="localhost") + if tls_socket.selected_alpn_protocol() != "h2": + raise RuntimeError(f"failed to negotiate h2, got {tls_socket.selected_alpn_protocol()!r}") + return tls_socket + + +def make_malformed_headers(scenario: str) -> bytes: + encoder = hpack.Encoder() + if scenario == "connect-missing-authority": + headers = [ + (":method", "CONNECT"), + (":scheme", "https"), + (":path", "/"), + ("user-agent", "TikTok/1.0"), + ("uuid", "malformed-connect"), + ] + elif scenario == "get-missing-path": + headers = [ + (":method", "GET"), + (":scheme", "https"), + (":authority", "missing-path.example"), + ("user-agent", "Malformed/1.0"), + ("uuid", "malformed-get-missing-path"), + ] + elif scenario == "get-connection-header": + headers = [ + (":method", "GET"), + (":scheme", "https"), + (":authority", "bad-connection.example"), + (":path", "/bad-connection"), + ("connection", "close"), + ("user-agent", "Malformed/1.0"), + ("uuid", "malformed-get-connection"), + ] + else: + raise ValueError(f"unknown scenario: {scenario}") + + return encoder.encode(headers) + + +def main() -> int: + parser = argparse.ArgumentParser() + parser.add_argument("port", type=int, help="TLS port to connect to") + parser.add_argument( + "scenario", + choices=("connect-missing-authority", "get-missing-path", "get-connection-header"), + help="Malformed request shape to send", + ) + args = parser.parse_args() + + tls_socket = connect_socket(args.port) + try: + payload = make_malformed_headers(args.scenario) + tls_socket.sendall(H2_PREFACE) + tls_socket.sendall(make_frame(TYPE_SETTINGS, 0, 0)) + tls_socket.sendall(make_frame(TYPE_HEADERS, FLAG_END_STREAM | FLAG_END_HEADERS, 1, payload)) + + while True: + frame = read_frame(tls_socket) + if frame is None: + print(f"Connection closed after malformed request scenario {args.scenario}") + return 0 + + frame_type = frame["type"] + if frame_type == TYPE_SETTINGS and not (frame["flags"] & FLAG_ACK): + tls_socket.sendall(make_frame(TYPE_SETTINGS, FLAG_ACK, 0)) + continue + + if frame_type == TYPE_RST_STREAM and frame["stream_id"] == 1: + error_code = int.from_bytes(frame["payload"][0:4], "big") + print(f"Received RST_STREAM on stream 1 with error code {error_code}") + return 0 if error_code == PROTOCOL_ERROR else 1 + + if frame_type == TYPE_GOAWAY: + error_code = int.from_bytes(frame["payload"][4:8], "big") + print(f"Received GOAWAY with error code {error_code}") + return 0 if error_code in (0, PROTOCOL_ERROR) else 1 + except socket.timeout: + print(f"Timed out waiting for ATS to reject malformed request scenario {args.scenario}", file=sys.stderr) + return 1 + finally: + tls_socket.close() + + +if __name__ == "__main__": + raise SystemExit(main()) diff --git a/tests/gold_tests/connect/replays/h2_malformed_request_logging.replay.yaml b/tests/gold_tests/connect/replays/h2_malformed_request_logging.replay.yaml new file mode 100644 index 00000000000..fdb1169153a --- /dev/null +++ b/tests/gold_tests/connect/replays/h2_malformed_request_logging.replay.yaml @@ -0,0 +1,90 @@ +# Licensed to the Apache Software Foundation (ASF) under one +# or more contributor license agreements. See the NOTICE file +# distributed with this work for additional information +# regarding copyright ownership. The ASF licenses this file +# to you under the Apache License, Version 2.0 (the +# "License"); you may not use this file except in compliance +# with the License. You may obtain a copy of the License at +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +# See the License for the specific language governing permissions and +# limitations under the License. + +# This replays healthy HTTP/2 requests to verify their logging. + +meta: + version: "1.0" + +sessions: + - protocol: + stack: http2 + tls: + sni: www.example.com + transactions: + - client-request: + headers: + encoding: esc_json + fields: + - [ :method, GET ] + - [ :scheme, https ] + - [ :authority, www.example.com ] + - [ :path, /valid-get ] + - [ uuid, valid-get ] + content: + encoding: plain + size: 0 + + proxy-request: + method: GET + + server-response: + status: 200 + reason: OK + content: + encoding: plain + data: response_to_valid_get + size: 21 + + proxy-response: + status: 200 + content: + verify: { value: "response_to_valid_get", as: contains } + - protocol: + stack: http2 + tls: + sni: www.example.com + transactions: + - client-request: + frames: + - HEADERS: + headers: + fields: + - [:method, CONNECT] + - [:authority, www.example.com:80] + - [uuid, valid-connect] + - [test, connect-request] + - DATA: + content: + encoding: plain + data: "GET /get HTTP/1.1\r\nuuid: valid-connect\r\ntest: real-request\r\n\r\n" + + # Note: the server will receive the tunneled GET request. + proxy-request: + method: GET + + server-response: + status: 200 + reason: OK + content: + encoding: plain + data: response_to_tunnelled_request + size: 29 + + proxy-response: + status: 200 + content: + verify: { value: "response_to_tunnelled_request", as: contains }