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()