From 6e963968f9a1a0790daedaa1cba94b53c1654d6e Mon Sep 17 00:00:00 2001 From: bneradt Date: Mon, 23 Mar 2026 16:55:39 -0500 Subject: [PATCH] Add log field header fallbacks Allow custom log formats to fall back between header fields with `?:` so configs can log a secondary header when the primary one is absent. This keeps the feature in the existing `%<...>` syntax and preserves the current distinction between missing and empty values. Store fallback chains as a single log field so the selected header still uses normal escaping and its own slice settings. Update the logging admin guide and extend the logging AuTest coverage for primary, secondary, and missing header cases. --- doc/admin-guide/logging/formatting.en.rst | 23 ++- include/proxy/logging/LogAccess.h | 6 +- include/proxy/logging/LogField.h | 49 +++--- src/proxy/logging/LogAccess.cc | 104 ++++++------- src/proxy/logging/LogField.cc | 146 +++++++++++++++++- src/proxy/logging/LogFormat.cc | 105 ++++++++++++- tests/gold_tests/logging/gold/field-test.gold | 6 +- tests/gold_tests/logging/log-field.test.py | 12 +- 8 files changed, 367 insertions(+), 84 deletions(-) diff --git a/doc/admin-guide/logging/formatting.en.rst b/doc/admin-guide/logging/formatting.en.rst index 9031ead20b8..8d4b0db2c66 100644 --- a/doc/admin-guide/logging/formatting.en.rst +++ b/doc/admin-guide/logging/formatting.en.rst @@ -314,8 +314,27 @@ 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. For example:: + + Format = '%<{x-primary-id}cqh?:{x-secondary-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 ``-``. 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. + +Note that this fallback chain feature is only supported for header field +expressions. + +Slices apply to each candidate in the fallback chain individually:: + + Format = '%<{x-primary-id}cqh[0:8]?:{x-secondary-id}cqh[0:16]>' ===== ====================== ================================================== 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..f2c767ac4dd 100644 --- a/include/proxy/logging/LogField.h +++ b/include/proxy/logging/LogField.h @@ -27,6 +27,7 @@ #include #include #include +#include #include "tscore/ink_inet.h" #include "tscore/ink_platform.h" @@ -129,6 +130,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 +145,7 @@ 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); LogField(const LogField &rhs); ~LogField(); @@ -193,27 +201,32 @@ 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_header_fields; + bool is_header_field_fallback() const; + int select_header_field(LogAccess *lad) const; + unsigned marshal_header_field(LogAccess *lad, const HeaderField &field, char *buf) const; public: LINK(LogField, link); 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..cc29d706f67 100644 --- a/src/proxy/logging/LogField.cc +++ b/src/proxy/logging/LogField.cc @@ -28,6 +28,7 @@ representation of a logging field. ***************************************************************************/ #include "tscore/ink_platform.h" +#include #include "swoc/swoc_meta.h" #include "swoc/TextView.h" #include "swoc/string_view_util.h" @@ -431,6 +432,29 @@ LogField::LogField(const char *field, Container container) } } +LogField::LogField(const char *symbol, std::vector header_fields) + : 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_header_fields(std::move(header_fields)) +{ + ink_assert(m_name != nullptr); + ink_assert(m_symbol != nullptr); + ink_assert(m_type >= 0 && m_type < N_TYPES); + ink_assert(!m_header_fields.empty()); +} + // Copy ctor LogField::LogField(const LogField &rhs) : m_name(ats_strdup(rhs.m_name)), @@ -448,7 +472,8 @@ 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_header_fields(rhs.m_header_fields) { ink_assert(m_name != nullptr); ink_assert(m_symbol != nullptr); @@ -475,6 +500,17 @@ LogField::~LogField() unsigned LogField::marshal_len(LogAccess *lad) { + if (is_header_field_fallback()) { + int selected = select_header_field(lad); + int bytes = INK_MIN_ALIGN; + if (selected >= 0) { + bytes += marshal_header_field(lad, m_header_fields[selected], nullptr); + } else { + bytes += LogAccess::padded_strlen(nullptr); + } + return bytes; + } + if (m_container == NO_CONTAINER) { if (m_custom_marshal_func == nullptr) { return (lad->*m_marshal_func)(nullptr); @@ -542,6 +578,10 @@ LogField::isContainerUpdateFieldSupported(Container container) void LogField::updateField(LogAccess *lad, char *buf, int len) { + if (is_header_field_fallback()) { + return; + } + if (m_container == NO_CONTAINER) { return (lad->*m_set_func)(buf, len); } else { @@ -561,6 +601,27 @@ LogField::updateField(LogAccess *lad, char *buf, int len) unsigned LogField::marshal(LogAccess *lad, char *buf) { + if (is_header_field_fallback()) { + int selected = select_header_field(lad); + int bytes = INK_MIN_ALIGN; + char *value_buf = buf ? buf + INK_MIN_ALIGN : nullptr; + + if (buf) { + LogAccess::marshal_int(buf, selected); + } + + if (selected >= 0) { + bytes += marshal_header_field(lad, m_header_fields[selected], value_buf); + } else { + int padded_len = LogAccess::padded_strlen(nullptr); + if (value_buf) { + LogAccess::marshal_str(value_buf, nullptr, padded_len); + } + bytes += padded_len; + } + return bytes; + } + if (m_container == NO_CONTAINER) { if (m_custom_marshal_func == nullptr) { return (lad->*m_marshal_func)(buf); @@ -653,6 +714,17 @@ LogField::marshal_agg(char *buf) unsigned LogField::unmarshal(char **buf, char *dest, int len, LogEscapeType escape_type) { + if (is_header_field_fallback()) { + int64_t selected = LogAccess::unmarshal_int(buf); + LogSlice *slice = nullptr; + + if (selected >= 0 && selected < static_cast(m_header_fields.size()) && m_header_fields[selected].slice.m_enable) { + slice = &m_header_fields[selected].slice; + } + + return LogAccess::unmarshal_str(buf, dest, len, slice, 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 +749,11 @@ LogField::display(FILE *fd) { static const char *names[LogField::N_TYPES] = {"sINT", "dINT", "STR", "IP"}; + if (is_header_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 +861,79 @@ 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_header_field_fallback() const +{ + return !m_header_fields.empty(); +} + +int +LogField::select_header_field(LogAccess *lad) const +{ + for (unsigned i = 0; i < m_header_fields.size(); ++i) { + if (lad->has_http_header_field(m_header_fields[i].container, m_header_fields[i].name.c_str())) { + return i; + } + } + + return -1; +} + +unsigned +LogField::marshal_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 header 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); + } +} + /*------------------------------------------------------------------------- LogFieldList diff --git a/src/proxy/logging/LogFormat.cc b/src/proxy/logging/LogFormat.cc index 52f07eba7bc..a6f727a5dcf 100644 --- a/src/proxy/logging/LogFormat.cc +++ b/src/proxy/logging/LogFormat.cc @@ -28,9 +28,12 @@ ***************************************************************************/ #include "tscore/ink_config.h" +#include #include #include #include +#include +#include #include "tscore/SimpleTokenizer.h" #include "tscore/CryptoHash.h" @@ -55,6 +58,94 @@ DbgCtl dbg_ctl_log_format{"log-format"}; DbgCtl dbg_ctl_log_agg{"log-agg"}; DbgCtl dbg_ctl_log_slice{"log-slice"}; +char * +trim_log_field_token(char *token) +{ + while (*token != '\0' && std::isspace(static_cast(*token))) { + ++token; + } + + size_t len = std::strlen(token); + while (len > 0 && std::isspace(static_cast(token[len - 1]))) { + token[--len] = '\0'; + } + + return token; +} + +bool +parse_header_fallback_candidate(char *candidate, LogField::HeaderField &field, const std::string &original_symbol) +{ + candidate = trim_log_field_token(candidate); + if (*candidate == '\0') { + Note("Invalid header fallback field specification: empty candidate in %s", original_symbol.c_str()); + return false; + } + + if (*candidate != '{') { + Note("Invalid header fallback field specification: %s is not a header field candidate in %s", candidate, + original_symbol.c_str()); + return false; + } + + char *name_end = std::strchr(candidate, '}'); + if (name_end == nullptr) { + Note("Invalid header fallback field specification: no trailing '}' in %s", original_symbol.c_str()); + return false; + } + + *name_end = '\0'; + char *name = candidate + 1; + char *symbol = trim_log_field_token(name_end + 1); + LogSlice slice(symbol); + + if (*name == '\0') { + Note("Invalid header fallback field specification: empty header name in %s", original_symbol.c_str()); + return false; + } + + auto container = LogField::valid_container_name(symbol); + if (!LogField::isHeaderContainer(container)) { + Note("Invalid header fallback field specification: %s is not a supported header container in %s", symbol, + original_symbol.c_str()); + return false; + } + + field.name = name; + field.container = container; + field.slice = slice; + return true; +} + +LogField * +parse_header_fallback_field(char *symbol) +{ + std::string original_symbol(symbol); + std::vector header_fields; + char *candidate = symbol; + + while (candidate != nullptr) { + char *separator = std::strstr(candidate, "?:"); + if (separator != nullptr) { + *separator = '\0'; + } + + LogField::HeaderField field; + if (!parse_header_fallback_candidate(candidate, field, original_symbol)) { + return nullptr; + } + header_fields.push_back(std::move(field)); + + if (separator == nullptr) { + break; + } + + candidate = separator + 2; + } + + return new LogField(original_symbol.c_str(), std::move(header_fields)); +} + } // end anonymous namespace /*------------------------------------------------------------------------- LogFormat::setup @@ -433,6 +524,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 +568,16 @@ LogFormat::parse_symbol_string(const char *symbol_string, LogFieldList *field_li "')' in %s", symbol); } + } else if (std::strstr(symbol, "?:") != nullptr) { + Dbg(dbg_ctl_log_format, "Header fallback symbol: %s", symbol); + f = parse_header_fallback_field(symbol); + if (f != nullptr) { + field_list->add(f, false); + field_count++; + Dbg(dbg_ctl_log_format, "Header fallback field %s added", original_symbol.c_str()); + } else { + field_list->addBadSymbol(original_symbol); + } } // // Now check for a container field, which starts with '{' @@ -529,7 +632,7 @@ LogFormat::parse_symbol_string(const char *symbol_string, LogFieldList *field_li 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/tests/gold_tests/logging/gold/field-test.gold b/tests/gold_tests/logging/gold/field-test.gold index c33b71f4bac..c0ff8b10a67 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 +Transfer-Encoding:- Content-Type:application/jason,%20application/json Request-ID:secondary-2 +Transfer-Encoding:- Content-Type:application/json Request-ID:- diff --git a/tests/gold_tests/logging/log-field.test.py b/tests/gold_tests/logging/log-field.test.py index e7534850c30..421b50be991 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>' logs: - filename: field-test format: custom @@ -95,11 +95,17 @@ # 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 --header "Host: test-1" --header "X-Primary-Id: primary-1" --header "X-Secondary-Id: secondary-1" http://localhost:{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 --header "Host: test-2" --header "X-Secondary-Id: secondary-2" http://localhost:{0}/test-2'.format( + ts.Variables.port), + ts=ts) tr.Processes.Default.ReturnCode = 0 tr = Test.AddTestRun()