diff --git a/doc/admin-guide/logging/formatting.en.rst b/doc/admin-guide/logging/formatting.en.rst index 9031ead20b8..48ce9402a87 100644 --- a/doc/admin-guide/logging/formatting.en.rst +++ b/doc/admin-guide/logging/formatting.en.rst @@ -314,8 +314,54 @@ prior to the log field's name, as so:: Format = '%<{User-agent}cqh>' The above would insert the User Agent string from the client request headers -into your log entry (or a blank string if no such header was present, or it did -not contain a value). +into your log entry (or ``-`` if no such header was present). + +Header fields can also be chained with a fallback operator, ``??``, when you want +the log to use the first header that exists among n headers. For example:: + + Format = '%<{x-primary-id}cqh??{x-secondary-id}cqh??{x-tertiary-id}cqh>' + +|TS| evaluates the candidates from left to right and logs the first header that +exists. If none of the headers exist, |TS| logs ``-`` by default. A header that +exists but has an empty value is considered present, so |TS| logs the empty +value instead of falling back. So in the example above, the value of +x-primary-id of the client request is logged if it exists, otherwise the value +of x-secondary-id is logged if it exists, otherwise ``-`` is logged if neither +of the headers is present. + +The final log field in the chain can be a non-header log field whose value +specifies the final fallback in the chain. This symbol is used only after all +the previous header candidates in the chain are missing. For example:: + + Format = '%<{x-remote-ip}cqh??chi>' + +In this case, the value of the x-remote-ip HTTP header field is logged if that +client request header exists. Otherwise, |TS| logs the value of ``chi``, the IP +address of the client host. + +The final non-HTTP header log field must be the last term in the chain, so +forms like ``%`` are invalid. + +Alternatively, you can provide an explicit quoted default literal as the final +term in the chain to use instead of the default ``-`` literal:: + + Format = '%<{x-primary-id}cqh??{x-secondary-id}cqh??"missing-id">' + +If none of the headers exist, |TS| logs the default literal instead, +``missing-id`` in this case. The default literal must be quoted and must be the +last term in the chain. Also, final non-header log fields and final default +string literals cannot be used together. Thus forms like +'%<{x-remote-ip}cqh??chi??"missing-id">' are invalid. + + +Slices apply to each candidate in the fallback chain individually:: + + Format = '%<{x-primary-id}cqh[0:8]??{x-secondary-id}cqh[0:16]>' + +This is also true of non-header log fields. That is, if the final log field +supports slicing, its own slice is preserved as usual:: + + Format = '%<{x-remote-ip}cqh??pqup[0:8]>' ===== ====================== ================================================== Field Source Description diff --git a/include/proxy/logging/LogAccess.h b/include/proxy/logging/LogAccess.h index d24a5eb6827..6b64aa973e2 100644 --- a/include/proxy/logging/LogAccess.h +++ b/include/proxy/logging/LogAccess.h @@ -306,6 +306,7 @@ class LogAccess int marshal_milestone_diff(TSMilestonesType ms1, TSMilestonesType ms2, char *buf); int marshal_milestones_csv(char *buf); + bool has_http_header_field(LogField::Container container, const char *field) const; void set_http_header_field(LogField::Container container, char *field, char *buf, int len); // Plugin @@ -405,8 +406,9 @@ class LogAccess char *m_cache_lookup_url_canon_str = nullptr; int m_cache_lookup_url_canon_len = 0; - void validate_unmapped_url(); - void validate_unmapped_url_path(); + HTTPHdr *header_for_container(LogField::Container container) const; + void validate_unmapped_url(); + void validate_unmapped_url_path(); void validate_lookup_url(); }; diff --git a/include/proxy/logging/LogField.h b/include/proxy/logging/LogField.h index b883b7c558c..700b609eb0e 100644 --- a/include/proxy/logging/LogField.h +++ b/include/proxy/logging/LogField.h @@ -23,10 +23,13 @@ #pragma once +#include +#include #include #include #include #include +#include #include "tscore/ink_inet.h" #include "tscore/ink_platform.h" @@ -129,6 +132,12 @@ class LogField N_AGGREGATES, }; + struct HeaderField { + std::string name; + Container container = NO_CONTAINER; + LogSlice slice; + }; + LogField(const char *name, const char *symbol, Type type, MarshalFunc marshal, VarUnmarshalFuncSliceOnly unmarshal, SetFunc _setFunc = nullptr); @@ -138,6 +147,8 @@ class LogField LogField(const char *name, const char *symbol, Type type, CustomMarshalFunc custom_marshal, CustomUnmarshalFunc custom_unmarshal); LogField(const char *field, Container container); + LogField(const char *symbol, std::vector header_fields, std::unique_ptr fallback_field = nullptr, + std::optional fallback_default = std::nullopt); LogField(const LogField &rhs); ~LogField(); @@ -193,27 +204,38 @@ class LogField static Container valid_container_name(char *name); static Aggregate valid_aggregate_name(char *name); static bool fieldlist_contains_aggregates(const char *fieldlist); + static bool isHeaderContainer(Container container); static bool isContainerUpdateFieldSupported(Container container); private: - char *m_name; - char *m_symbol; - Type m_type; - Container m_container; - MarshalFunc m_marshal_func; // place data into buffer - VarUnmarshalFunc m_unmarshal_func; // create a string of the data - Aggregate m_agg_op; - int64_t m_agg_cnt; - int64_t m_agg_val; - TSMilestonesType m_milestone1; ///< Used for MS and MSDMS as the first (or only) milestone. - TSMilestonesType m_milestone2; ///< Second milestone for MSDMS - bool m_time_field; - Ptr m_alias_map; // map sINT <--> string - SetFunc m_set_func; - TSMilestonesType milestone_from_m_name(); - int milestones_from_m_name(TSMilestonesType *m1, TSMilestonesType *m2); - CustomMarshalFunc m_custom_marshal_func = nullptr; - CustomUnmarshalFunc m_custom_unmarshal_func = nullptr; + char *m_name; + char *m_symbol; + Type m_type; + Container m_container; + MarshalFunc m_marshal_func; // place data into buffer + VarUnmarshalFunc m_unmarshal_func; // create a string of the data + Aggregate m_agg_op; + int64_t m_agg_cnt; + int64_t m_agg_val; + TSMilestonesType m_milestone1; ///< Used for MS and MSDMS as the first (or only) milestone. + TSMilestonesType m_milestone2; ///< Second milestone for MSDMS + bool m_time_field; + Ptr m_alias_map; // map sINT <--> string + SetFunc m_set_func; + TSMilestonesType milestone_from_m_name(); + int milestones_from_m_name(TSMilestonesType *m1, TSMilestonesType *m2); + CustomMarshalFunc m_custom_marshal_func = nullptr; + CustomUnmarshalFunc m_custom_unmarshal_func = nullptr; + std::vector m_fallback_header_fields; + std::unique_ptr m_fallback_field; + std::optional m_fallback_default; + bool is_field_fallback() const; + int select_fallback_selector(LogAccess *lad) const; + unsigned marshal_fallback_header_field(LogAccess *lad, const HeaderField &field, char *buf) const; + unsigned marshal_fallback_default(char *buf) const; + + static constexpr int FALLBACK_DEFAULT_SELECTOR = -1; + static constexpr int FALLBACK_FIELD_SELECTOR = -2; public: LINK(LogField, link); diff --git a/src/proxy/logging/CMakeLists.txt b/src/proxy/logging/CMakeLists.txt index 27da4f05d85..29139f69d5d 100644 --- a/src/proxy/logging/CMakeLists.txt +++ b/src/proxy/logging/CMakeLists.txt @@ -26,6 +26,7 @@ add_library( LogFile.cc LogFilter.cc LogFormat.cc + LogFieldFallback.cc LogObject.cc LogUtils.cc RolledLogDeleter.cc @@ -39,6 +40,11 @@ target_include_directories(logging PRIVATE ${SWOC_INCLUDE_DIR}) target_link_libraries(logging PUBLIC ts::inkevent ts::inkutils ts::http ts::hdrs ts::tscore yaml-cpp::yaml-cpp) if(BUILD_TESTING) + add_executable(test_LogFieldFallback unit-tests/test_LogFieldFallback.cc) + target_include_directories(test_LogFieldFallback PRIVATE ${CMAKE_CURRENT_SOURCE_DIR}) + target_link_libraries(test_LogFieldFallback PRIVATE ts::logging Catch2::Catch2WithMain) + add_catch2_test(NAME test_LogFieldFallback COMMAND test_LogFieldFallback) + add_executable(test_LogUtils LogUtils.cc unit-tests/test_LogUtils.cc) target_compile_definitions(test_LogUtils PRIVATE TEST_LOG_UTILS) target_link_libraries(test_LogUtils tscore ts::inkevent records Catch2::Catch2WithMain) diff --git a/src/proxy/logging/LogAccess.cc b/src/proxy/logging/LogAccess.cc index fd4add5c02d..9c2ffb79d62 100644 --- a/src/proxy/logging/LogAccess.cc +++ b/src/proxy/logging/LogAccess.cc @@ -481,6 +481,54 @@ LogAccess::marshal_custom_field(char *buf, LogField::CustomMarshalFunc plugin_ma return LogAccess::padded_length(len); } +HTTPHdr * +LogAccess::header_for_container(LogField::Container container) const +{ + switch (container) { + case LogField::CQH: + case LogField::ECQH: + return m_client_request; + + case LogField::PSH: + case LogField::EPSH: + return m_proxy_response; + + case LogField::PQH: + case LogField::EPQH: + return m_proxy_request; + + case LogField::SSH: + case LogField::ESSH: + return m_server_response; + + case LogField::CSSH: + case LogField::ECSSH: + return m_cache_response; + + default: + return nullptr; + } +} + +bool +LogAccess::has_http_header_field(LogField::Container container, const char *field) const +{ + if (HTTPHdr const *header = header_for_container(container); header != nullptr) { + if (header->field_find(std::string_view{field}) != nullptr) { + return true; + } + } + + if (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()) { + return true; + } + } + + return false; +} + inline int LogAccess::unmarshal_with_map(int64_t code, char *dest, int len, const Ptr &map, const char *msg) { @@ -3282,33 +3330,7 @@ LogAccess::marshal_http_header_field(LogField::Container container, char *field, int padded_len = INK_MIN_ALIGN; int actual_len = 0; bool valid_field = false; - HTTPHdr *header; - - switch (container) { - case LogField::CQH: - header = m_client_request; - break; - - case LogField::PSH: - header = m_proxy_response; - break; - - case LogField::PQH: - header = m_proxy_request; - break; - - case LogField::SSH: - header = m_server_response; - break; - - case LogField::CSSH: - header = m_cache_response; - break; - - default: - header = nullptr; - break; - } + HTTPHdr *header = header_for_container(container); if (header) { MIMEField *fld = header->field_find(std::string_view{field}); @@ -3413,33 +3435,7 @@ LogAccess::marshal_http_header_field_escapify(LogField::Container container, cha int padded_len = INK_MIN_ALIGN; int actual_len = 0, new_len = 0; bool valid_field = false; - HTTPHdr *header; - - switch (container) { - case LogField::ECQH: - header = m_client_request; - break; - - case LogField::EPSH: - header = m_proxy_response; - break; - - case LogField::EPQH: - header = m_proxy_request; - break; - - case LogField::ESSH: - header = m_server_response; - break; - - case LogField::ECSSH: - header = m_cache_response; - break; - - default: - header = nullptr; - break; - } + HTTPHdr *header = header_for_container(container); if (header) { MIMEField *fld = header->field_find(std::string_view{field}); diff --git a/src/proxy/logging/LogField.cc b/src/proxy/logging/LogField.cc index 58529490790..2c8378ef489 100644 --- a/src/proxy/logging/LogField.cc +++ b/src/proxy/logging/LogField.cc @@ -28,6 +28,8 @@ representation of a logging field. ***************************************************************************/ #include "tscore/ink_platform.h" +#include +#include #include "swoc/swoc_meta.h" #include "swoc/TextView.h" #include "swoc/string_view_util.h" @@ -431,6 +433,33 @@ LogField::LogField(const char *field, Container container) } } +LogField::LogField(const char *symbol, std::vector header_fields, std::unique_ptr fallback_field, + std::optional fallback_default) + : m_name(ats_strdup(symbol)), + m_symbol(ats_strdup(symbol)), + m_type(LogField::STRING), + m_container(NO_CONTAINER), + m_marshal_func(nullptr), + m_unmarshal_func(&(LogAccess::unmarshal_str)), + m_agg_op(NO_AGGREGATE), + m_agg_cnt(0), + m_agg_val(0), + m_milestone1(TS_MILESTONE_LAST_ENTRY), + m_milestone2(TS_MILESTONE_LAST_ENTRY), + m_time_field(false), + m_alias_map(nullptr), + m_set_func(nullptr), + m_fallback_header_fields(std::move(header_fields)), + m_fallback_field(std::move(fallback_field)), + m_fallback_default(std::move(fallback_default)) +{ + ink_assert(m_name != nullptr); + ink_assert(m_symbol != nullptr); + ink_assert(m_type >= 0 && m_type < N_TYPES); + ink_assert(!m_fallback_header_fields.empty()); + ink_assert(!(m_fallback_field && m_fallback_default.has_value())); +} + // Copy ctor LogField::LogField(const LogField &rhs) : m_name(ats_strdup(rhs.m_name)), @@ -448,7 +477,10 @@ LogField::LogField(const LogField &rhs) m_alias_map(rhs.m_alias_map), m_set_func(rhs.m_set_func), m_custom_marshal_func(rhs.m_custom_marshal_func), - m_custom_unmarshal_func(rhs.m_custom_unmarshal_func) + m_custom_unmarshal_func(rhs.m_custom_unmarshal_func), + m_fallback_header_fields(rhs.m_fallback_header_fields), + m_fallback_field(rhs.m_fallback_field ? std::make_unique(*rhs.m_fallback_field) : nullptr), + m_fallback_default(rhs.m_fallback_default) { ink_assert(m_name != nullptr); ink_assert(m_symbol != nullptr); @@ -475,6 +507,19 @@ LogField::~LogField() unsigned LogField::marshal_len(LogAccess *lad) { + if (is_field_fallback()) { + int selector = select_fallback_selector(lad); + int bytes = INK_MIN_ALIGN; + if (selector >= 0) { + bytes += marshal_fallback_header_field(lad, m_fallback_header_fields[selector], nullptr); + } else if (selector == FALLBACK_FIELD_SELECTOR) { + bytes += m_fallback_field->marshal_len(lad); + } else { + bytes += marshal_fallback_default(nullptr); + } + return bytes; + } + if (m_container == NO_CONTAINER) { if (m_custom_marshal_func == nullptr) { return (lad->*m_marshal_func)(nullptr); @@ -542,6 +587,10 @@ LogField::isContainerUpdateFieldSupported(Container container) void LogField::updateField(LogAccess *lad, char *buf, int len) { + if (is_field_fallback()) { + return; + } + if (m_container == NO_CONTAINER) { return (lad->*m_set_func)(buf, len); } else { @@ -561,6 +610,25 @@ LogField::updateField(LogAccess *lad, char *buf, int len) unsigned LogField::marshal(LogAccess *lad, char *buf) { + if (is_field_fallback()) { + int selector = select_fallback_selector(lad); + int bytes = INK_MIN_ALIGN; + char *value_buf = buf ? buf + INK_MIN_ALIGN : nullptr; + + if (buf) { + LogAccess::marshal_int(buf, selector); + } + + if (selector >= 0) { + bytes += marshal_fallback_header_field(lad, m_fallback_header_fields[selector], value_buf); + } else if (selector == FALLBACK_FIELD_SELECTOR) { + bytes += m_fallback_field->marshal(lad, value_buf); + } else { + bytes += marshal_fallback_default(value_buf); + } + return bytes; + } + if (m_container == NO_CONTAINER) { if (m_custom_marshal_func == nullptr) { return (lad->*m_marshal_func)(buf); @@ -653,6 +721,26 @@ LogField::marshal_agg(char *buf) unsigned LogField::unmarshal(char **buf, char *dest, int len, LogEscapeType escape_type) { + if (is_field_fallback()) { + int64_t selector = LogAccess::unmarshal_int(buf); + LogSlice *slice = nullptr; + + if (selector >= 0 && selector < static_cast(m_fallback_header_fields.size()) && + m_fallback_header_fields[selector].slice.m_enable) { + slice = &m_fallback_header_fields[selector].slice; + } + + if (selector >= 0 && selector < static_cast(m_fallback_header_fields.size())) { + return LogAccess::unmarshal_str(buf, dest, len, slice, escape_type); + } + + if (selector == FALLBACK_FIELD_SELECTOR && m_fallback_field) { + return m_fallback_field->unmarshal(buf, dest, len, escape_type); + } + + return LogAccess::unmarshal_str(buf, dest, len, nullptr, escape_type); + } + return std::visit( swoc::meta::vary{[&](UnmarshalFuncWithSlice f) -> unsigned { return (*f)(buf, dest, len, &m_slice, escape_type); }, [&](UnmarshalFuncWithMap f) -> unsigned { return (*f)(buf, dest, len, m_alias_map); }, @@ -677,6 +765,11 @@ LogField::display(FILE *fd) { static const char *names[LogField::N_TYPES] = {"sINT", "dINT", "STR", "IP"}; + if (is_field_fallback()) { + fprintf(fd, " %30s %10s %5s\n", m_name, "fallback", names[m_type]); + return; + } + fprintf(fd, " %30s %10s %5s\n", m_name, m_symbol, names[m_type]); } @@ -784,12 +877,112 @@ LogField::fieldlist_contains_aggregates(const char *fieldlist) return false; } +bool +LogField::isHeaderContainer(Container container) +{ + switch (container) { + case CQH: + case PSH: + case PQH: + case SSH: + case CSSH: + case ECQH: + case EPSH: + case EPQH: + case ESSH: + case ECSSH: + return true; + default: + return false; + } +} + void LogField::set_http_header_field(LogAccess *lad, LogField::Container container, char *field, char *buf, int len) { return lad->set_http_header_field(container, field, buf, len); } +bool +LogField::is_field_fallback() const +{ + return !m_fallback_header_fields.empty(); +} + +int +LogField::select_fallback_selector(LogAccess *lad) const +{ + for (unsigned i = 0; i < m_fallback_header_fields.size(); ++i) { + if (lad->has_http_header_field(m_fallback_header_fields[i].container, m_fallback_header_fields[i].name.c_str())) { + return i; + } + } + + if (m_fallback_field) { + return FALLBACK_FIELD_SELECTOR; + } + + return FALLBACK_DEFAULT_SELECTOR; +} + +unsigned +LogField::marshal_fallback_header_field(LogAccess *lad, const HeaderField &field, char *buf) const +{ + switch (field.container) { + case CQH: + case PSH: + case PQH: + case SSH: + case CSSH: + return lad->marshal_http_header_field(field.container, const_cast(field.name.c_str()), buf); + + case ECQH: + case EPSH: + case EPQH: + case ESSH: + case ECSSH: + return lad->marshal_http_header_field_escapify(field.container, const_cast(field.name.c_str()), buf); + + default: + Note("Invalid container type in fallback field: %d", field.container); + if (buf) { + int padded_len = LogAccess::padded_strlen(nullptr); + LogAccess::marshal_str(buf, nullptr, padded_len); + return padded_len; + } + return LogAccess::padded_strlen(nullptr); + } +} + +unsigned +LogField::marshal_fallback_default(char *buf) const +{ + if (!m_fallback_default.has_value()) { + int padded_len = LogAccess::padded_strlen(nullptr); + if (buf) { + LogAccess::marshal_str(buf, nullptr, padded_len); + } + return padded_len; + } + + std::string const &fallback_default = *m_fallback_default; + int running_len = static_cast(fallback_default.size()) + 1; + int padded_len = LogAccess::padded_length(running_len); + if (buf) { + std::memcpy(buf, fallback_default.data(), fallback_default.size()); + buf[fallback_default.size()] = '\0'; + +#ifdef DEBUG + while (running_len < padded_len) { + buf[running_len] = '$'; + ++running_len; + } +#endif + } + + return padded_len; +} + /*------------------------------------------------------------------------- LogFieldList diff --git a/src/proxy/logging/LogFieldFallback.cc b/src/proxy/logging/LogFieldFallback.cc new file mode 100644 index 00000000000..876ac722060 --- /dev/null +++ b/src/proxy/logging/LogFieldFallback.cc @@ -0,0 +1,315 @@ +/** @file + + Helpers for parsing log field fallback expressions. + + @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 "LogFieldFallback.h" + +#include +#include +#include +#include + +#include "swoc/TextView.h" + +namespace +{ +constexpr std::string_view FIELD_FALLBACK_SEPARATOR{"??"}; + +/** Find the next fallback separator outside of quoted default literals. + * + * This keeps the chain tokenizer from splitting on separator text that is + * part of a quoted default value. + * + * @param[in] text Candidate fallback expression text. + * @return Pointer to the first separator occurrence, or @c nullptr if none. + */ +constexpr char const * +find_field_fallback_separator(std::string_view text) +{ + char quote = '\0'; + bool escape = false; + + // The following logic assumes a 2 character separator. If that changes, + // adjust the logic accordingly. + static_assert(FIELD_FALLBACK_SEPARATOR.size() == 2, "FIELD_FALLBACK_SEPARATOR must be exactly two characters long"); + + for (auto const *spot = text.data(), *limit = text.data() + text.size(); spot < limit; ++spot) { + char c = *spot; + + if (quote != '\0') { + if (escape) { + escape = false; + } else if (c == '\\') { + escape = true; + } else if (c == quote) { + quote = '\0'; + } + continue; + } + + if (c == '\'' || c == '"') { + quote = c; + continue; + } + + if (*spot == FIELD_FALLBACK_SEPARATOR[0] && (spot + 1) < limit && *(spot + 1) == FIELD_FALLBACK_SEPARATOR[1]) { + return spot; + } + } + + return nullptr; +} + +constexpr bool +test_find_field_fallback_separator() +{ + static_assert(find_field_fallback_separator("") == nullptr); + constexpr char const *text1 = "{field}??default"; + static_assert(find_field_fallback_separator(text1) == text1 + 7); + constexpr char const *text2 = "??default"; + static_assert(find_field_fallback_separator(text2) == text2); + constexpr char const *text3 = "{field}??def??ault"; + static_assert(find_field_fallback_separator(text3) == text3 + 7); + constexpr char const *text4 = "{field}??\"def??ault\""; + static_assert(find_field_fallback_separator(text4) == text4 + 7); + return true; +} + +static_assert(test_find_field_fallback_separator(), "find_field_fallback_separator failed its tests"); + +void +set_parse_error(std::string &error, std::string_view symbol, std::string_view detail) +{ + error.assign("Invalid log field fallback specification: "); + error.append(detail.data(), detail.size()); + error.append(" in "); + error.append(symbol.data(), symbol.size()); +} + +bool +parse_header_fallback_candidate(swoc::TextView term, LogField::HeaderField &field, std::string_view original_symbol, + std::string &error) +{ + term.trim_if(isspace); + std::string term_text{term}; + + if (term_text.empty()) { + set_parse_error(error, original_symbol, "empty candidate"); + return false; + } + + if (term_text.front() != '{') { + set_parse_error(error, original_symbol, term_text + " is not a header field candidate"); + return false; + } + + term.remove_prefix(1); + size_t name_end = term.find('}'); + if (name_end == swoc::TextView::npos) { + set_parse_error(error, original_symbol, "no trailing '}'"); + return false; + } + + swoc::TextView field_name = term.substr(0, name_end); + if (field_name.empty()) { + set_parse_error(error, original_symbol, "empty header name"); + return false; + } + + swoc::TextView container_text = term.substr(name_end + 1); + container_text.trim_if(isspace); + std::string container_spec{container_text}; + LogSlice slice(container_spec.data()); + auto container = LogField::valid_container_name(container_spec.data()); + + if (!LogField::isHeaderContainer(container)) { + set_parse_error(error, original_symbol, container_spec + " is not a supported header container"); + return false; + } + + field.name.assign(field_name.data(), field_name.size()); + field.container = container; + field.slice = slice; + + return true; +} + +bool +parse_field_fallback_symbol(swoc::TextView term, std::string &field_symbol, std::string_view original_symbol, std::string &error) +{ + term.trim_if(isspace); + if (term.empty()) { + set_parse_error(error, original_symbol, "empty candidate"); + return false; + } + + if (term.find('(') != swoc::TextView::npos || term.find(')') != swoc::TextView::npos) { + set_parse_error(error, original_symbol, "aggregate expressions are not supported in fallback chains"); + return false; + } + + if (term.find('{') != swoc::TextView::npos || term.find('}') != swoc::TextView::npos) { + set_parse_error(error, original_symbol, std::string{term} + " is not a supported fallback term"); + return false; + } + + field_symbol.assign(term.data(), term.size()); + return true; +} + +bool +parse_field_fallback_default(swoc::TextView term, std::string &default_value, std::string_view original_symbol, std::string &error) +{ + term.trim_if(isspace); + if (term.empty()) { + set_parse_error(error, original_symbol, "empty default"); + return false; + } + + char quote = term.front(); + if (quote != '\'' && quote != '"') { + set_parse_error(error, original_symbol, std::string{term} + " is not a quoted default literal"); + return false; + } + + default_value.clear(); + bool escaped = false; + + for (auto const *spot = term.data() + 1, *limit = term.data_end(); spot < limit; ++spot) { + char c = *spot; + + if (escaped) { + if (c == quote || c == '\\') { + default_value.push_back(c); + } else { + default_value.push_back('\\'); + default_value.push_back(c); + } + escaped = false; + continue; + } + + if (c == '\\') { + escaped = true; + continue; + } + + if (c == quote) { + if (spot + 1 != limit) { + set_parse_error(error, original_symbol, "trailing characters after default literal"); + return false; + } + return true; + } + + default_value.push_back(c); + } + + set_parse_error(error, original_symbol, "unterminated default literal"); + return false; +} +} // namespace + +namespace LogFieldFallback +{ +bool +has_fallback(std::string_view symbol) +{ + return find_field_fallback_separator(symbol) != nullptr; +} + +std::optional +parse(std::string_view symbol, std::string &error) +{ + error.clear(); + + ParseResult result; + swoc::TextView remaining{symbol}; + + while (true) { + swoc::TextView term; + bool has_more_terms = false; + + if (auto const *separator = find_field_fallback_separator(remaining); separator != nullptr) { + term = swoc::TextView{remaining.data(), static_cast(separator - remaining.data())}; + remaining.remove_prefix((separator - remaining.data()) + FIELD_FALLBACK_SEPARATOR.size()); + has_more_terms = true; + } else { + term = remaining; + remaining = swoc::TextView{}; + } + + term.trim_if(isspace); + if (term.empty()) { + set_parse_error(error, symbol, "empty candidate"); + return std::nullopt; + } + + if (term.starts_with('"') || term.starts_with('\'')) { + if (has_more_terms) { + set_parse_error(error, symbol, "default literal must be the final term"); + return std::nullopt; + } + + std::string fallback_default; + if (!parse_field_fallback_default(term, fallback_default, symbol, error)) { + return std::nullopt; + } + result.fallback_default = std::move(fallback_default); + break; + } + + if (term.starts_with('{')) { + LogField::HeaderField field; + if (!parse_header_fallback_candidate(term, field, symbol, error)) { + return std::nullopt; + } + + result.header_fields.push_back(std::move(field)); + + if (!has_more_terms) { + break; + } + } else { + if (has_more_terms) { + set_parse_error(error, symbol, "plain field symbols must be the final term"); + return std::nullopt; + } + + std::string fallback_symbol; + if (!parse_field_fallback_symbol(term, fallback_symbol, symbol, error)) { + return std::nullopt; + } + + result.fallback_symbol = std::move(fallback_symbol); + break; + } + } + + if (result.header_fields.empty()) { + set_parse_error(error, symbol, "must start with a header field candidate"); + return std::nullopt; + } + + return result; +} +} // namespace LogFieldFallback diff --git a/src/proxy/logging/LogFieldFallback.h b/src/proxy/logging/LogFieldFallback.h new file mode 100644 index 00000000000..0827d06654e --- /dev/null +++ b/src/proxy/logging/LogFieldFallback.h @@ -0,0 +1,60 @@ +/** @file + + Private helper declarations for parsing log field fallback expressions. + + @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. + */ + +#pragma once + +#include +#include +#include +#include + +#include "proxy/logging/LogField.h" + +namespace LogFieldFallback +{ +/** Parsed representation of a log field fallback chain. */ +struct ParseResult { + /// Header candidates evaluated from left to right. + std::vector header_fields; + /// Optional final plain field symbol used when no header candidate is present. + std::optional fallback_symbol; + /// Optional quoted default literal used when no header candidate is present. + std::optional fallback_default; +}; + +/** Determine whether a symbol uses log field fallback syntax. + * + * @param[in] symbol Log field symbol text from a custom format. + * @return @c true if @a symbol contains an unquoted fallback separator. + */ +bool has_fallback(std::string_view symbol); + +/** Parse a log field fallback symbol into header candidates and an optional + * final plain symbol or default literal. + * + * @param[in] symbol Log field symbol text from a custom format. + * @param[out] error Receives a human-readable parse error on failure. + * @return Parsed fallback state on success, @c std::nullopt on failure. + */ +std::optional parse(std::string_view symbol, std::string &error); +} // namespace LogFieldFallback diff --git a/src/proxy/logging/LogFormat.cc b/src/proxy/logging/LogFormat.cc index 52f07eba7bc..feee9696e49 100644 --- a/src/proxy/logging/LogFormat.cc +++ b/src/proxy/logging/LogFormat.cc @@ -28,13 +28,18 @@ ***************************************************************************/ #include "tscore/ink_config.h" +#include #include #include #include +#include +#include +#include #include "tscore/SimpleTokenizer.h" #include "tscore/CryptoHash.h" +#include "LogFieldFallback.h" #include "proxy/logging/LogUtils.h" #include "proxy/logging/LogFile.h" #include "proxy/logging/LogField.h" @@ -55,6 +60,25 @@ DbgCtl dbg_ctl_log_format{"log-format"}; DbgCtl dbg_ctl_log_agg{"log-agg"}; DbgCtl dbg_ctl_log_slice{"log-slice"}; +LogField * +make_regular_field_from_symbol(char *symbol) +{ + LogSlice slice(symbol); + LogField *field = Log::global_field_list.find_by_symbol(symbol); + + if (field == nullptr) { + return nullptr; + } + + auto *copy = new LogField(*field); + if (slice.m_enable) { + copy->m_slice = slice; + Dbg(dbg_ctl_log_slice, "symbol = %s, [%d:%d]", symbol, copy->m_slice.m_start, copy->m_slice.m_end); + } + + return copy; +} + } // end anonymous namespace /*------------------------------------------------------------------------- LogFormat::setup @@ -433,6 +457,8 @@ LogFormat::parse_symbol_string(const char *symbol_string, LogFieldList *field_li symbol = strtok_r(sym_str, ",", &saveptr); while (symbol != nullptr) { + std::string original_symbol(symbol); + // // See if there is an aggregate operator, which will contain "()" // @@ -475,6 +501,40 @@ LogFormat::parse_symbol_string(const char *symbol_string, LogFieldList *field_li "')' in %s", symbol); } + } else if (LogFieldFallback::has_fallback(symbol)) { + Dbg(dbg_ctl_log_format, "Field fallback symbol: %s", symbol); + std::string parse_error; + auto parsed = LogFieldFallback::parse(symbol, parse_error); + if (parsed.has_value()) { + std::unique_ptr fallback_field; + bool valid_fallback = true; + + if (parsed->fallback_symbol.has_value()) { + std::string fallback_symbol = *parsed->fallback_symbol; + LogField *resolved_field = make_regular_field_from_symbol(fallback_symbol.data()); + + if (resolved_field == nullptr) { + Note("The fallback field symbol %s was not found in the " + "list of known symbols.", + fallback_symbol.c_str()); + field_list->addBadSymbol(original_symbol); + valid_fallback = false; + } else { + fallback_field.reset(resolved_field); + } + } + + if (valid_fallback) { + f = new LogField(original_symbol.c_str(), std::move(parsed->header_fields), std::move(fallback_field), + std::move(parsed->fallback_default)); + field_list->add(f, false); + field_count++; + Dbg(dbg_ctl_log_format, "Field fallback field %s added", original_symbol.c_str()); + } + } else { + Note("%s", parse_error.c_str()); + field_list->addBadSymbol(original_symbol); + } } // // Now check for a container field, which starts with '{' @@ -513,23 +573,17 @@ LogFormat::parse_symbol_string(const char *symbol_string, LogFieldList *field_li // treat this like a regular field symbol // else { - LogSlice slice(symbol); Dbg(dbg_ctl_log_format, "Regular field symbol: %s", symbol); - f = Log::global_field_list.find_by_symbol(symbol); + f = make_regular_field_from_symbol(symbol); if (f != nullptr) { - LogField *cpy = new LogField(*f); - if (slice.m_enable) { - cpy->m_slice = slice; - Dbg(dbg_ctl_log_slice, "symbol = %s, [%d:%d]", symbol, cpy->m_slice.m_start, cpy->m_slice.m_end); - } - field_list->add(cpy, false); + field_list->add(f, false); field_count++; Dbg(dbg_ctl_log_format, "Regular field %s added", symbol); } else { Note("The log format symbol %s was not found in the " "list of known symbols.", symbol); - field_list->addBadSymbol(symbol); + field_list->addBadSymbol(original_symbol); } } diff --git a/src/proxy/logging/unit-tests/test_LogFieldFallback.cc b/src/proxy/logging/unit-tests/test_LogFieldFallback.cc new file mode 100644 index 00000000000..74ec47e2aab --- /dev/null +++ b/src/proxy/logging/unit-tests/test_LogFieldFallback.cc @@ -0,0 +1,120 @@ +/** @file + + Catch-based tests for LogFieldFallback parsing helpers. + + @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 + +#include "LogFieldFallback.h" + +using LogFieldFallback::ParseResult; + +namespace +{ +ParseResult +require_parse(std::string_view symbol) +{ + std::string error; + auto parsed = LogFieldFallback::parse(symbol, error); + + INFO(error); + REQUIRE(parsed.has_value()); + + return std::move(*parsed); +} +} // namespace + +TEST_CASE("Field fallback detection ignores quoted separators", "[LogFieldFallback]") +{ + REQUIRE_FALSE(LogFieldFallback::has_fallback("{field}cqh")); + REQUIRE(LogFieldFallback::has_fallback("{field}cqh??{other}pqh")); + REQUIRE(LogFieldFallback::has_fallback("{field}cqh??chi")); + REQUIRE(LogFieldFallback::has_fallback("{field}cqh??\"default??value\"")); + REQUIRE_FALSE(LogFieldFallback::has_fallback("\"default??value\"")); +} + +TEST_CASE("Field fallback parsing preserves containers and slices", "[LogFieldFallback]") +{ + auto parsed = require_parse(" {x-primary-id}cqh[0:8] ?? {x-secondary-id}epqh[0:16] "); + + REQUIRE(parsed.header_fields.size() == 2); + REQUIRE_FALSE(parsed.fallback_symbol.has_value()); + REQUIRE_FALSE(parsed.fallback_default.has_value()); + + CHECK(parsed.header_fields[0].name == "x-primary-id"); + CHECK(parsed.header_fields[0].container == LogField::CQH); + CHECK(parsed.header_fields[0].slice.m_enable); + CHECK(parsed.header_fields[0].slice.m_start == 0); + CHECK(parsed.header_fields[0].slice.m_end == 8); + + CHECK(parsed.header_fields[1].name == "x-secondary-id"); + CHECK(parsed.header_fields[1].container == LogField::EPQH); + CHECK(parsed.header_fields[1].slice.m_enable); + CHECK(parsed.header_fields[1].slice.m_start == 0); + CHECK(parsed.header_fields[1].slice.m_end == 16); +} + +TEST_CASE("Field fallback parsing supports final plain symbols", "[LogFieldFallback]") +{ + auto parsed = require_parse("{x-primary-id}cqh??{x-secondary-id}cqh??cqup[0:7]"); + + REQUIRE(parsed.header_fields.size() == 2); + REQUIRE(parsed.fallback_symbol.has_value()); + CHECK(parsed.fallback_symbol == std::optional{"cqup[0:7]"}); + REQUIRE_FALSE(parsed.fallback_default.has_value()); +} + +TEST_CASE("Field fallback parsing supports quoted defaults", "[LogFieldFallback]") +{ + auto parsed = require_parse("{x-primary-id}cqh??{x-secondary-id}cqh??\"missing\\\"id\\\\tail\""); + + REQUIRE(parsed.header_fields.size() == 2); + REQUIRE_FALSE(parsed.fallback_symbol.has_value()); + REQUIRE(parsed.fallback_default.has_value()); + CHECK(parsed.fallback_default == std::optional{"missing\"id\\tail"}); +} + +TEST_CASE("Field fallback parsing rejects malformed chains", "[LogFieldFallback]") +{ + std::string error; + + auto parsed = LogFieldFallback::parse("{x-primary-id}cqh??\"missing\"??{x-secondary-id}cqh", error); + REQUIRE_FALSE(parsed.has_value()); + CHECK(error.find("default literal must be the final term") != std::string::npos); + + parsed = LogFieldFallback::parse("{x-primary-id}record??{x-secondary-id}cqh", error); + REQUIRE_FALSE(parsed.has_value()); + CHECK(error.find("record is not a supported header container") != std::string::npos); + + parsed = LogFieldFallback::parse("{x-primary-id}cqh????{x-secondary-id}cqh", error); + REQUIRE_FALSE(parsed.has_value()); + CHECK(error.find("empty candidate") != std::string::npos); + + parsed = LogFieldFallback::parse("{x-primary-id}cqh??chi??\"missing\"", error); + REQUIRE_FALSE(parsed.has_value()); + CHECK(error.find("plain field symbols must be the final term") != std::string::npos); + + parsed = LogFieldFallback::parse("{x-primary-id}cqh??SUM(psql)", error); + REQUIRE_FALSE(parsed.has_value()); + CHECK(error.find("aggregate expressions are not supported in fallback chains") != std::string::npos); +} diff --git a/tests/gold_tests/logging/gold/field-test.gold b/tests/gold_tests/logging/gold/field-test.gold index c33b71f4bac..8f1e4c7375d 100644 --- a/tests/gold_tests/logging/gold/field-test.gold +++ b/tests/gold_tests/logging/gold/field-test.gold @@ -1,3 +1,3 @@ -Transfer-Encoding:Chunked Content-Type:application/json,%20application/json -Transfer-Encoding:- Content-Type:application/jason,%20application/json -Transfer-Encoding:- Content-Type:application/json +Transfer-Encoding:Chunked Content-Type:application/json,%20application/json Request-ID:primary-1 Request-ID-Default:primary-1 Request-ID-Or-IP:primary-1 Remote-IP:203.0.113.10 Path-Fallback:test-1 +Transfer-Encoding:- Content-Type:application/jason,%20application/json Request-ID:secondary-2 Request-ID-Default:secondary-2 Request-ID-Or-IP:secondary-2 Remote-IP:127.0.0.1 Path-Fallback:test-2 +Transfer-Encoding:- Content-Type:application/json Request-ID:- Request-ID-Default:missing-id Request-ID-Or-IP:127.0.0.1 Remote-IP:127.0.0.1 Path-Fallback:test-3 diff --git a/tests/gold_tests/logging/log-field.test.py b/tests/gold_tests/logging/log-field.test.py index 6cbcd4991a5..4268ec5cc73 100644 --- a/tests/gold_tests/logging/log-field.test.py +++ b/tests/gold_tests/logging/log-field.test.py @@ -73,7 +73,7 @@ logging: formats: - name: custom - format: 'Transfer-Encoding:%<{Transfer-Encoding}ssh> Content-Type:%<{Content-Type}essh>' + format: 'Transfer-Encoding:%<{Transfer-Encoding}ssh> Content-Type:%<{Content-Type}essh> Request-ID:%<{X-Primary-Id}cqh??{X-Secondary-Id}cqh> Request-ID-Default:%<{X-Primary-Id}cqh??{X-Secondary-Id}cqh??"missing-id"> Request-ID-Or-IP:%<{X-Primary-Id}cqh??{X-Secondary-Id}cqh??chi> Remote-IP:%<{X-Remote-Ip}cqh??chi> Path-Fallback:%<{X-Path-Fallback}cqh??cqup[0:7]>' logs: - filename: field-test format: custom @@ -95,15 +95,21 @@ # Delay on readiness of our ssl ports tr.Processes.Default.StartBefore(Test.Processes.ts) -tr.MakeCurlCommand('--verbose --header "Host: test-1" http://localhost:{0}/test-1'.format(ts.Variables.port), ts=ts) +tr.MakeCurlCommand( + '--verbose --ipv4 --header "Host: test-1" --header "X-Primary-Id: primary-1" --header "X-Secondary-Id: secondary-1" --header "X-Remote-Ip: 203.0.113.10" http://127.0.0.1:{0}/test-1' + .format(ts.Variables.port), + ts=ts) tr.Processes.Default.ReturnCode = 0 tr = Test.AddTestRun() -tr.MakeCurlCommand('--verbose --header "Host: test-2" http://localhost:{0}/test-2'.format(ts.Variables.port), ts=ts) +tr.MakeCurlCommand( + '--verbose --ipv4 --header "Host: test-2" --header "X-Secondary-Id: secondary-2" http://127.0.0.1:{0}/test-2'.format( + ts.Variables.port), + ts=ts) tr.Processes.Default.ReturnCode = 0 tr = Test.AddTestRun() -tr.MakeCurlCommand('--verbose --header "Host: test-3" http://localhost:{0}/test-3'.format(ts.Variables.port), ts=ts) +tr.MakeCurlCommand('--verbose --ipv4 --header "Host: test-3" http://127.0.0.1:{0}/test-3'.format(ts.Variables.port), ts=ts) tr.Processes.Default.ReturnCode = 0 # Wait for all expected log lines to be written.