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 }