This is an automated email from the ASF dual-hosted git repository. cmcfarlen pushed a commit to branch 10.0.x in repository https://gitbox.apache.org/repos/asf/trafficserver.git
commit 2f4544a0a453c1f50e307524472f4166e4f9ea1d Author: Walt Karas <[email protected]> AuthorDate: Tue May 14 16:34:38 2024 -0400 Remove obsolete debug output calls in 23 source files. (#11298) In the src/proxy tree. (cherry picked from commit c537ce6c2c954334549a835b3f0d20552dcd0fc6) --- src/proxy/ControlBase.cc | 6 +- src/proxy/hdrs/HTTP.cc | 28 ++++--- src/proxy/hdrs/HdrHeap.cc | 12 ++- src/proxy/hdrs/HdrToken.cc | 14 +++- src/proxy/hdrs/MIME.cc | 67 +++++++++------- src/proxy/hdrs/URL.cc | 55 ++++++++----- src/proxy/hdrs/XPACK.cc | 30 ++++--- src/proxy/http2/HPACK.cc | 21 ++--- src/proxy/http2/Http2ClientSession.cc | 10 ++- src/proxy/http2/Http2CommonSession.cc | 19 +++-- src/proxy/http2/Http2ConnectionState.cc | 25 +++--- src/proxy/http2/Http2SessionAccept.cc | 12 ++- src/proxy/logging/Log.cc | 63 +++++++++------ src/proxy/logging/LogAccess.cc | 27 ++++--- src/proxy/logging/LogBuffer.cc | 27 ++++--- src/proxy/logging/LogConfig.cc | 50 +++++++----- src/proxy/logging/LogField.cc | 22 +++-- src/proxy/logging/LogFile.cc | 41 ++++++---- src/proxy/logging/LogFilter.cc | 19 +++-- src/proxy/logging/LogFormat.cc | 59 ++++++++------ src/proxy/logging/LogObject.cc | 93 ++++++++++++---------- src/proxy/logging/YamlLogConfig.cc | 11 ++- .../logging/unit-tests/benchmark_LogObject.cc | 2 +- 23 files changed, 432 insertions(+), 281 deletions(-) diff --git a/src/proxy/ControlBase.cc b/src/proxy/ControlBase.cc index e96ddd3765..69c9c757aa 100644 --- a/src/proxy/ControlBase.cc +++ b/src/proxy/ControlBase.cc @@ -525,9 +525,9 @@ PrefixMod::check(HttpRequestData *req) const const char *path = req->hdr->url_get()->path_get(&path_len); bool zret = path_len >= static_cast<int>(text.size()) && 0 == memcmp(path, text.data(), text.size()); /* - Debug("cache_control", "Prefix check: URL=%0.*s Mod=%0.*s Z=%s", - path_len, path, text.size(), text.data(), - zret ? "Match" : "Fail" + Dbg(dbg_ctl_cache_control, "Prefix check: URL=%0.*s Mod=%0.*s Z=%s", + path_len, path, text.size(), text.data(), + zret ? "Match" : "Fail" ); */ return zret; diff --git a/src/proxy/hdrs/HTTP.cc b/src/proxy/hdrs/HTTP.cc index fd3a2d3f36..166d896599 100644 --- a/src/proxy/hdrs/HTTP.cc +++ b/src/proxy/hdrs/HTTP.cc @@ -143,6 +143,12 @@ int HTTP_LEN_100_CONTINUE; Arena *const HTTPHdr::USE_HDR_HEAP_MAGIC = reinterpret_cast<Arena *>(1); +namespace +{ +DbgCtl dbg_ctl_http{"http"}; + +} // end anonymous namespace + /*********************************************************************** * * * M A I N C O D E * @@ -571,9 +577,9 @@ http_hdr_describe(HdrHeapObjImpl *raw, bool recurse) HTTPHdrImpl *obj = (HTTPHdrImpl *)raw; if (obj->m_polarity == HTTP_TYPE_REQUEST) { - Debug("http", "[TYPE: REQ, V: %04X, URL: %p, METHOD: \"%.*s\", METHOD_LEN: %d, FIELDS: %p]", obj->m_version.get_flat_version(), - obj->u.req.m_url_impl, obj->u.req.m_len_method, (obj->u.req.m_ptr_method ? obj->u.req.m_ptr_method : "NULL"), - obj->u.req.m_len_method, obj->m_fields_impl); + Dbg(dbg_ctl_http, "[TYPE: REQ, V: %04X, URL: %p, METHOD: \"%.*s\", METHOD_LEN: %d, FIELDS: %p]", + obj->m_version.get_flat_version(), obj->u.req.m_url_impl, obj->u.req.m_len_method, + (obj->u.req.m_ptr_method ? obj->u.req.m_ptr_method : "NULL"), obj->u.req.m_len_method, obj->m_fields_impl); if (recurse) { if (obj->u.req.m_url_impl) { obj_describe(obj->u.req.m_url_impl, recurse); @@ -583,9 +589,9 @@ http_hdr_describe(HdrHeapObjImpl *raw, bool recurse) } } } else { - Debug("http", "[TYPE: RSP, V: %04X, STATUS: %d, REASON: \"%.*s\", REASON_LEN: %d, FIELDS: %p]", - obj->m_version.get_flat_version(), obj->u.resp.m_status, obj->u.resp.m_len_reason, - (obj->u.resp.m_ptr_reason ? obj->u.resp.m_ptr_reason : "NULL"), obj->u.resp.m_len_reason, obj->m_fields_impl); + Dbg(dbg_ctl_http, "[TYPE: RSP, V: %04X, STATUS: %d, REASON: \"%.*s\", REASON_LEN: %d, FIELDS: %p]", + obj->m_version.get_flat_version(), obj->u.resp.m_status, obj->u.resp.m_len_reason, + (obj->u.resp.m_ptr_reason ? obj->u.resp.m_ptr_reason : "NULL"), obj->u.resp.m_len_reason, obj->m_fields_impl); if (recurse) { if (obj->m_fields_impl) { obj_describe(obj->m_fields_impl, recurse); @@ -1249,7 +1255,7 @@ validate_hdr_content_length(HdrHeap *heap, HTTPHdrImpl *hh) // the Content-Length if (mime_hdr_field_find(hh->m_fields_impl, MIME_FIELD_TRANSFER_ENCODING, MIME_LEN_TRANSFER_ENCODING) != nullptr) { // Delete all Content-Length headers - Debug("http", "Transfer-Encoding header and Content-Length headers the request, removing all Content-Length headers"); + Dbg(dbg_ctl_http, "Transfer-Encoding header and Content-Length headers the request, removing all Content-Length headers"); mime_hdr_field_delete(heap, hh->m_fields_impl, content_length_field, true); return PARSE_RESULT_DONE; } @@ -1268,14 +1274,14 @@ validate_hdr_content_length(HdrHeap *heap, HTTPHdrImpl *hh) // Content-Length = 1*DIGIT // if (value.empty()) { - Debug("http", "Content-Length headers don't match the ABNF, returning parse error"); + Dbg(dbg_ctl_http, "Content-Length headers don't match the ABNF, returning parse error"); return PARSE_RESULT_ERROR; } // If the content-length value contains a non-numeric value, the header is invalid if (std::find_if(value.cbegin(), value.cend(), [](std::string_view::value_type c) { return !std::isdigit(c); }) != value.cend()) { - Debug("http", "Content-Length value contains non-digit, returning parse error"); + Dbg(dbg_ctl_http, "Content-Length value contains non-digit, returning parse error"); return PARSE_RESULT_ERROR; } @@ -1284,11 +1290,11 @@ validate_hdr_content_length(HdrHeap *heap, HTTPHdrImpl *hh) if ((value.length() != value_dup.length()) || value.compare(value_dup) != 0) { // Values are different, parse error - Debug("http", "Content-Length headers don't match, returning parse error"); + Dbg(dbg_ctl_http, "Content-Length headers don't match, returning parse error"); return PARSE_RESULT_ERROR; } else { // Delete the duplicate since it has the same value - Debug("http", "Deleting duplicate Content-Length header"); + Dbg(dbg_ctl_http, "Deleting duplicate Content-Length header"); mime_hdr_field_delete(heap, hh->m_fields_impl, content_length_field->m_next_dup, false); } } diff --git a/src/proxy/hdrs/HdrHeap.cc b/src/proxy/hdrs/HdrHeap.cc index a8013f13fb..03ad762728 100644 --- a/src/proxy/hdrs/HdrHeap.cc +++ b/src/proxy/hdrs/HdrHeap.cc @@ -45,6 +45,12 @@ static constexpr uint32_t MAX_HDR_HEAP_OBJ_LENGTH = (1 << 20) - 1; ///< m_length Allocator hdrHeapAllocator("hdrHeap", HdrHeap::DEFAULT_SIZE); Allocator strHeapAllocator("hdrStrHeap", HdrStrHeap::DEFAULT_SIZE); +namespace +{ +DbgCtl dbg_ctl_http{"http"}; + +} // end anonymous namespace + /*------------------------------------------------------------------------- -------------------------------------------------------------------------*/ @@ -53,8 +59,8 @@ obj_describe(HdrHeapObjImpl *obj, bool recurse) { static const char *obj_names[] = {"EMPTY", "RAW", "URL", "HTTP_HEADER", "MIME_HEADER", "FIELD_BLOCK"}; - Debug("http", "%s %p: [T: %d, L: %4d, OBJFLAGS: %X] ", obj_names[obj->m_type], obj, obj->m_type, obj->m_length, - obj->m_obj_flags); + Dbg(dbg_ctl_http, "%s %p: [T: %d, L: %4d, OBJFLAGS: %X] ", obj_names[obj->m_type], obj, obj->m_type, obj->m_length, + obj->m_obj_flags); switch (obj->m_type) { case HDR_HEAP_OBJ_EMPTY: @@ -337,7 +343,7 @@ HdrHeap::demote_rw_str_heap() i.m_heap_start = reinterpret_cast<char *>(m_read_write_heap.get()); i.m_heap_len = m_read_write_heap->total_size() - m_read_write_heap->space_avail(); - // Debug("hdrs", "Demoted rw heap of %d size", m_read_write_heap->total_size()); + // Dbg(dbg_ctl_hdrs, "Demoted rw heap of %d size", m_read_write_heap->total_size()); m_read_write_heap = nullptr; return 0; } diff --git a/src/proxy/hdrs/HdrToken.cc b/src/proxy/hdrs/HdrToken.cc index 5262b39537..253d0d90a5 100644 --- a/src/proxy/hdrs/HdrToken.cc +++ b/src/proxy/hdrs/HdrToken.cc @@ -33,6 +33,10 @@ #include "tsutil/Regex.h" #include "proxy/hdrs/URL.h" +namespace +{ +DbgCtl dbg_ctl_hdr_token{"hdr_token"}; + /* You SHOULD add to _hdrtoken_commonly_tokenized_strs, with the same ordering ** important, ordering matters ** @@ -47,7 +51,7 @@ /ericb */ -static const char *_hdrtoken_strs[] = { +const char *_hdrtoken_strs[] = { // MIME Field names "Accept-Charset", "Accept-Encoding", "Accept-Language", "Accept-Ranges", "Accept", "Age", "Allow", "Approved", // NNTP @@ -118,7 +122,7 @@ static const char *_hdrtoken_strs[] = { // RFC-7932 "br"}; -static HdrTokenTypeBinding _hdrtoken_strs_type_initializers[] = { +HdrTokenTypeBinding _hdrtoken_strs_type_initializers[] = { {"file", HDRTOKEN_TYPE_SCHEME }, {"ftp", HDRTOKEN_TYPE_SCHEME }, {"gopher", HDRTOKEN_TYPE_SCHEME }, @@ -168,7 +172,7 @@ static HdrTokenTypeBinding _hdrtoken_strs_type_initializers[] = { {(char *)nullptr, static_cast<HdrTokenType>(0)}, }; -static HdrTokenFieldInfo _hdrtoken_strs_field_initializers[] = { +HdrTokenFieldInfo _hdrtoken_strs_field_initializers[] = { {"Accept", MIME_SLOTID_ACCEPT, MIME_PRESENCE_ACCEPT, (HTIF_COMMAS | HTIF_MULTVALS) }, {"Accept-Charset", MIME_SLOTID_ACCEPT_CHARSET, MIME_PRESENCE_ACCEPT_CHARSET, (HTIF_COMMAS | HTIF_MULTVALS) }, {"Accept-Encoding", MIME_SLOTID_ACCEPT_ENCODING, MIME_PRESENCE_ACCEPT_ENCODING, (HTIF_COMMAS | HTIF_MULTVALS) }, @@ -248,6 +252,8 @@ static HdrTokenFieldInfo _hdrtoken_strs_field_initializers[] = { {nullptr, 0, 0, 0 }, }; +} // end anonymous namespace + const char *_hdrtoken_strs_heap_f = nullptr; // storage first byte const char *_hdrtoken_strs_heap_l = nullptr; // storage last byte @@ -609,7 +615,7 @@ hdrtoken_tokenize(const char *string, int string_len, const char **wks_string_ou return wks_idx; } - Debug("hdr_token", "Did not find a WKS for '%.*s'", string_len, string); + Dbg(dbg_ctl_hdr_token, "Did not find a WKS for '%.*s'", string_len, string); return -1; } diff --git a/src/proxy/hdrs/MIME.cc b/src/proxy/hdrs/MIME.cc index ad88c19f45..5dbcb349c0 100644 --- a/src/proxy/hdrs/MIME.cc +++ b/src/proxy/hdrs/MIME.cc @@ -355,6 +355,12 @@ int MIME_WKSIDX_SEC_WEBSOCKET_VERSION; int MIME_WKSIDX_HTTP2_SETTINGS; int MIME_WKSIDX_EARLY_DATA; +namespace +{ +DbgCtl dbg_ctl_http{"http"}; + +} // end anonymous namespace + /*********************************************************************** * * * U T I L I T Y R O U T I N E S * @@ -1325,14 +1331,15 @@ mime_hdr_field_find(MIMEHdrImpl *mh, const char *field_name_str, int field_name_ //////////////////////////////////////////// #if TRACK_FIELD_FIND_CALLS - Debug("http", "mime_hdr_field_find(hdr 0x%X, field %.*s): is_wks = %d", mh, field_name_len, field_name_str, is_wks); + Dbg(dbg_ctl_http, "mime_hdr_field_find(hdr 0x%X, field %.*s): is_wks = %d", mh, field_name_len, field_name_str, is_wks); #endif if (is_wks) { token_info = hdrtoken_wks_to_prefix(field_name_str); if ((token_info->wks_info.mask) && ((mh->m_presence_bits & token_info->wks_info.mask) == 0)) { #if TRACK_FIELD_FIND_CALLS - Debug("http", "mime_hdr_field_find(hdr 0x%X, field %.*s): MISS (due to presence bits)", mh, field_name_len, field_name_str); + Dbg(dbg_ctl_http, "mime_hdr_field_find(hdr 0x%X, field %.*s): MISS (due to presence bits)", mh, field_name_len, + field_name_str); #endif return nullptr; } @@ -1346,13 +1353,13 @@ mime_hdr_field_find(MIMEHdrImpl *mh, const char *field_name_str, int field_name_ MIMEField *f = _mime_hdr_field_list_search_by_slotnum(mh, slotnum); ink_assert((f == nullptr) || f->is_live()); #if TRACK_FIELD_FIND_CALLS - Debug("http", "mime_hdr_field_find(hdr 0x%X, field %.*s): %s (due to slot accelerators)", mh, field_name_len, - field_name_str, (f ? "HIT" : "MISS")); + Dbg(dbg_ctl_http, "mime_hdr_field_find(hdr 0x%X, field %.*s): %s (due to slot accelerators)", mh, field_name_len, + field_name_str, (f ? "HIT" : "MISS")); #endif return f; } else { #if TRACK_FIELD_FIND_CALLS - Debug("http", "mime_hdr_field_find(hdr 0x%X, field %.*s): UNKNOWN (slot too big)", mh, field_name_len, field_name_str); + Dbg(dbg_ctl_http, "mime_hdr_field_find(hdr 0x%X, field %.*s): UNKNOWN (slot too big)", mh, field_name_len, field_name_str); #endif } } @@ -1364,8 +1371,8 @@ mime_hdr_field_find(MIMEHdrImpl *mh, const char *field_name_str, int field_name_ MIMEField *f = _mime_hdr_field_list_search_by_wks(mh, token_info->wks_idx); ink_assert((f == nullptr) || f->is_live()); #if TRACK_FIELD_FIND_CALLS - Debug("http", "mime_hdr_field_find(hdr 0x%X, field %.*s): %s (due to WKS list walk)", mh, field_name_len, field_name_str, - (f ? "HIT" : "MISS")); + Dbg(dbg_ctl_http, "mime_hdr_field_find(hdr 0x%X, field %.*s): %s (due to WKS list walk)", mh, field_name_len, field_name_str, + (f ? "HIT" : "MISS")); #endif return f; } else { @@ -1373,8 +1380,8 @@ mime_hdr_field_find(MIMEHdrImpl *mh, const char *field_name_str, int field_name_ ink_assert((f == nullptr) || f->is_live()); #if TRACK_FIELD_FIND_CALLS - Debug("http", "mime_hdr_field_find(hdr 0x%X, field %.*s): %s (due to strcmp list walk)", mh, field_name_len, field_name_str, - (f ? "HIT" : "MISS")); + Dbg(dbg_ctl_http, "mime_hdr_field_find(hdr 0x%X, field %.*s): %s (due to strcmp list walk)", mh, field_name_len, field_name_str, + (f ? "HIT" : "MISS")); #endif return f; } @@ -2654,16 +2661,16 @@ mime_hdr_describe(HdrHeapObjImpl *raw, bool recurse) MIMEFieldBlockImpl *fblock; MIMEHdrImpl *obj = (MIMEHdrImpl *)raw; - Debug("http", "\t[PBITS: 0x%08X%08X, SLACC: 0x%04X%04X%04X%04X, HEADBLK: %p, TAILBLK: %p]", - (uint32_t)((obj->m_presence_bits >> 32) & (TOK_64_CONST(0xFFFFFFFF))), - (uint32_t)((obj->m_presence_bits >> 0) & (TOK_64_CONST(0xFFFFFFFF))), obj->m_slot_accelerators[0], - obj->m_slot_accelerators[1], obj->m_slot_accelerators[2], obj->m_slot_accelerators[3], &(obj->m_first_fblock), - obj->m_fblock_list_tail); + Dbg(dbg_ctl_http, "\t[PBITS: 0x%08X%08X, SLACC: 0x%04X%04X%04X%04X, HEADBLK: %p, TAILBLK: %p]", + (uint32_t)((obj->m_presence_bits >> 32) & (TOK_64_CONST(0xFFFFFFFF))), + (uint32_t)((obj->m_presence_bits >> 0) & (TOK_64_CONST(0xFFFFFFFF))), obj->m_slot_accelerators[0], + obj->m_slot_accelerators[1], obj->m_slot_accelerators[2], obj->m_slot_accelerators[3], &(obj->m_first_fblock), + obj->m_fblock_list_tail); - Debug("http", "\t[CBITS: 0x%08X, T_MAXAGE: %d, T_SMAXAGE: %d, T_MAXSTALE: %d, T_MINFRESH: %d, PNO$: %d]", - obj->m_cooked_stuff.m_cache_control.m_mask, obj->m_cooked_stuff.m_cache_control.m_secs_max_age, - obj->m_cooked_stuff.m_cache_control.m_secs_s_maxage, obj->m_cooked_stuff.m_cache_control.m_secs_max_stale, - obj->m_cooked_stuff.m_cache_control.m_secs_min_fresh, obj->m_cooked_stuff.m_pragma.m_no_cache); + Dbg(dbg_ctl_http, "\t[CBITS: 0x%08X, T_MAXAGE: %d, T_SMAXAGE: %d, T_MAXSTALE: %d, T_MINFRESH: %d, PNO$: %d]", + obj->m_cooked_stuff.m_cache_control.m_mask, obj->m_cooked_stuff.m_cache_control.m_secs_max_age, + obj->m_cooked_stuff.m_cache_control.m_secs_s_maxage, obj->m_cooked_stuff.m_cache_control.m_secs_max_stale, + obj->m_cooked_stuff.m_cache_control.m_secs_min_fresh, obj->m_cooked_stuff.m_pragma.m_no_cache); for (fblock = &(obj->m_first_fblock); fblock != nullptr; fblock = fblock->m_next) { if (recurse || (fblock == &(obj->m_first_fblock))) { obj_describe((HdrHeapObjImpl *)fblock, recurse); @@ -2679,11 +2686,11 @@ mime_field_block_describe(HdrHeapObjImpl *raw, bool /* recurse ATS_UNUSED */) MIMEFieldBlockImpl *obj = (MIMEFieldBlockImpl *)raw; - Debug("http", "[FREETOP: %d, NEXTBLK: %p]", obj->m_freetop, obj->m_next); + Dbg(dbg_ctl_http, "[FREETOP: %d, NEXTBLK: %p]", obj->m_freetop, obj->m_next); for (i = 0; i < obj->m_freetop; i++) { MIMEField *f = &(obj->m_field_slots[i]); - Debug("http", "\tSLOT #%2d (%p), %-8s", i, f, readiness_names[f->m_readiness]); + Dbg(dbg_ctl_http, "\tSLOT #%2d (%p), %-8s", i, f, readiness_names[f->m_readiness]); switch (f->m_readiness) { case MIME_FIELD_SLOT_READINESS_EMPTY: @@ -2691,14 +2698,14 @@ mime_field_block_describe(HdrHeapObjImpl *raw, bool /* recurse ATS_UNUSED */) case MIME_FIELD_SLOT_READINESS_DETACHED: case MIME_FIELD_SLOT_READINESS_LIVE: case MIME_FIELD_SLOT_READINESS_DELETED: - Debug("http", "[N: \"%.*s\", N_LEN: %d, N_IDX: %d, ", f->m_len_name, (f->m_ptr_name ? f->m_ptr_name : "NULL"), f->m_len_name, - f->m_wks_idx); - Debug("http", "V: \"%.*s\", V_LEN: %d, ", f->m_len_value, (f->m_ptr_value ? f->m_ptr_value : "NULL"), f->m_len_value); - Debug("http", "NEXTDUP: %p, RAW: %d, RAWLEN: %d, F: %d]", f->m_next_dup, f->m_n_v_raw_printable, - f->m_len_name + f->m_len_value + f->m_n_v_raw_printable_pad, f->m_flags); + Dbg(dbg_ctl_http, "[N: \"%.*s\", N_LEN: %d, N_IDX: %d, ", f->m_len_name, (f->m_ptr_name ? f->m_ptr_name : "NULL"), + f->m_len_name, f->m_wks_idx); + Dbg(dbg_ctl_http, "V: \"%.*s\", V_LEN: %d, ", f->m_len_value, (f->m_ptr_value ? f->m_ptr_value : "NULL"), f->m_len_value); + Dbg(dbg_ctl_http, "NEXTDUP: %p, RAW: %d, RAWLEN: %d, F: %d]", f->m_next_dup, f->m_n_v_raw_printable, + f->m_len_name + f->m_len_value + f->m_n_v_raw_printable_pad, f->m_flags); break; } - Debug("http", "\n"); + Dbg(dbg_ctl_http, "\n"); } } @@ -3890,7 +3897,7 @@ MIMEHdrImpl::recompute_cooked_stuff(MIMEField *changing_field_or_null) // If >= 0 then this is a well known token if (hdrtoken_tokenize(s, tlen, &token_wks) >= 0) { #if TRACK_COOKING - Debug("http", "recompute_cooked_stuff: got field '%s'", token_wks); + Dbg(dbg_ctl_http, "recompute_cooked_stuff: got field '%s'", token_wks); #endif HdrTokenHeapPrefix *p = hdrtoken_wks_to_prefix(token_wks); @@ -3898,7 +3905,7 @@ MIMEHdrImpl::recompute_cooked_stuff(MIMEField *changing_field_or_null) m_cooked_stuff.m_cache_control.m_mask |= mask; #if TRACK_COOKING - Debug("http", " set mask 0x%0X", mask); + Dbg(dbg_ctl_http, " set mask 0x%0X", mask); #endif if (mask & (MIME_COOKED_MASK_CC_MAX_AGE | MIME_COOKED_MASK_CC_S_MAXAGE | MIME_COOKED_MASK_CC_MAX_STALE | @@ -3907,7 +3914,7 @@ MIMEHdrImpl::recompute_cooked_stuff(MIMEField *changing_field_or_null) if (mime_parse_integer(c, e, &value)) { #if TRACK_COOKING - Debug("http", " set integer value %d", value); + Dbg(dbg_ctl_http, " set integer value %d", value); #endif if (token_wks == MIME_VALUE_MAX_AGE) { m_cooked_stuff.m_cache_control.m_secs_max_age = value; @@ -3920,7 +3927,7 @@ MIMEHdrImpl::recompute_cooked_stuff(MIMEField *changing_field_or_null) } } else { #if TRACK_COOKING - Debug("http", " set integer value %d", INT_MAX); + Dbg(dbg_ctl_http, " set integer value %d", INT_MAX); #endif if (token_wks == MIME_VALUE_MAX_STALE) { m_cooked_stuff.m_cache_control.m_secs_max_stale = INT_MAX; diff --git a/src/proxy/hdrs/URL.cc b/src/proxy/hdrs/URL.cc index 7bfe3cf3ee..191e644876 100644 --- a/src/proxy/hdrs/URL.cc +++ b/src/proxy/hdrs/URL.cc @@ -93,9 +93,16 @@ int URL_LEN_MMS; int URL_LEN_MMSU; int URL_LEN_MMST; +namespace +{ // Whether we should implement url_CryptoHash_get() using url_CryptoHash_get_fast(). Note that // url_CryptoHash_get_fast() does NOT produce the same result as url_CryptoHash_get_general(). -static int url_hash_method = 0; +int url_hash_method = 0; + +DbgCtl dbg_ctl_http{"http"}; +DbgCtl dbg_ctl_url_cachekey{"url_cachekey"}; + +} // end anonymous namespace // test to see if a character is a valid character for a host in a URI according to // RFC 3986 and RFC 1034 @@ -1210,7 +1217,7 @@ url_is_strictly_compliant(const char *start, const char *end) { for (const char *i = start; i < end; ++i) { if (!ParseRules::is_uri(*i)) { - Debug("http", "Non-RFC compliant character [0x%.2X] found in URL", (unsigned char)*i); + Dbg(dbg_ctl_http, "Non-RFC compliant character [0x%.2X] found in URL", (unsigned char)*i); return false; } } @@ -1227,11 +1234,11 @@ url_is_mostly_compliant(const char *start, const char *end) { for (const char *i = start; i < end; ++i) { if (isspace(*i)) { - Debug("http", "Whitespace character [0x%.2X] found in URL", (unsigned char)*i); + Dbg(dbg_ctl_http, "Whitespace character [0x%.2X] found in URL", (unsigned char)*i); return false; } if (!isprint(*i)) { - Debug("http", "Non-printable character [0x%.2X] found in URL", (unsigned char)*i); + Dbg(dbg_ctl_http, "Non-printable character [0x%.2X] found in URL", (unsigned char)*i); return false; } } @@ -1733,22 +1740,25 @@ url_describe(HdrHeapObjImpl *raw, bool /* recurse ATS_UNUSED */) { URLImpl *obj = (URLImpl *)raw; - Debug("http", "[URLTYPE: %d, SWKSIDX: %d,", obj->m_url_type, obj->m_scheme_wks_idx); - Debug("http", "\tSCHEME: \"%.*s\", SCHEME_LEN: %d,", obj->m_len_scheme, (obj->m_ptr_scheme ? obj->m_ptr_scheme : "NULL"), - obj->m_len_scheme); - Debug("http", "\tUSER: \"%.*s\", USER_LEN: %d,", obj->m_len_user, (obj->m_ptr_user ? obj->m_ptr_user : "NULL"), obj->m_len_user); - Debug("http", "\tPASSWORD: \"%.*s\", PASSWORD_LEN: %d,", obj->m_len_password, - (obj->m_ptr_password ? obj->m_ptr_password : "NULL"), obj->m_len_password); - Debug("http", "\tHOST: \"%.*s\", HOST_LEN: %d,", obj->m_len_host, (obj->m_ptr_host ? obj->m_ptr_host : "NULL"), obj->m_len_host); - Debug("http", "\tPORT: \"%.*s\", PORT_LEN: %d, PORT_NUM: %d", obj->m_len_port, (obj->m_ptr_port ? obj->m_ptr_port : "NULL"), - obj->m_len_port, obj->m_port); - Debug("http", "\tPATH: \"%.*s\", PATH_LEN: %d,", obj->m_len_path, (obj->m_ptr_path ? obj->m_ptr_path : "NULL"), obj->m_len_path); - Debug("http", "\tPARAMS: \"%.*s\", PARAMS_LEN: %d,", obj->m_len_params, (obj->m_ptr_params ? obj->m_ptr_params : "NULL"), - obj->m_len_params); - Debug("http", "\tQUERY: \"%.*s\", QUERY_LEN: %d,", obj->m_len_query, (obj->m_ptr_query ? obj->m_ptr_query : "NULL"), - obj->m_len_query); - Debug("http", "\tFRAGMENT: \"%.*s\", FRAGMENT_LEN: %d]", obj->m_len_fragment, - (obj->m_ptr_fragment ? obj->m_ptr_fragment : "NULL"), obj->m_len_fragment); + Dbg(dbg_ctl_http, "[URLTYPE: %d, SWKSIDX: %d,", obj->m_url_type, obj->m_scheme_wks_idx); + Dbg(dbg_ctl_http, "\tSCHEME: \"%.*s\", SCHEME_LEN: %d,", obj->m_len_scheme, (obj->m_ptr_scheme ? obj->m_ptr_scheme : "NULL"), + obj->m_len_scheme); + Dbg(dbg_ctl_http, "\tUSER: \"%.*s\", USER_LEN: %d,", obj->m_len_user, (obj->m_ptr_user ? obj->m_ptr_user : "NULL"), + obj->m_len_user); + Dbg(dbg_ctl_http, "\tPASSWORD: \"%.*s\", PASSWORD_LEN: %d,", obj->m_len_password, + (obj->m_ptr_password ? obj->m_ptr_password : "NULL"), obj->m_len_password); + Dbg(dbg_ctl_http, "\tHOST: \"%.*s\", HOST_LEN: %d,", obj->m_len_host, (obj->m_ptr_host ? obj->m_ptr_host : "NULL"), + obj->m_len_host); + Dbg(dbg_ctl_http, "\tPORT: \"%.*s\", PORT_LEN: %d, PORT_NUM: %d", obj->m_len_port, (obj->m_ptr_port ? obj->m_ptr_port : "NULL"), + obj->m_len_port, obj->m_port); + Dbg(dbg_ctl_http, "\tPATH: \"%.*s\", PATH_LEN: %d,", obj->m_len_path, (obj->m_ptr_path ? obj->m_ptr_path : "NULL"), + obj->m_len_path); + Dbg(dbg_ctl_http, "\tPARAMS: \"%.*s\", PARAMS_LEN: %d,", obj->m_len_params, (obj->m_ptr_params ? obj->m_ptr_params : "NULL"), + obj->m_len_params); + Dbg(dbg_ctl_http, "\tQUERY: \"%.*s\", QUERY_LEN: %d,", obj->m_len_query, (obj->m_ptr_query ? obj->m_ptr_query : "NULL"), + obj->m_len_query); + Dbg(dbg_ctl_http, "\tFRAGMENT: \"%.*s\", FRAGMENT_LEN: %d]", obj->m_len_fragment, + (obj->m_ptr_fragment ? obj->m_ptr_fragment : "NULL"), obj->m_len_fragment); } /*------------------------------------------------------------------------- @@ -1904,9 +1914,10 @@ url_CryptoHash_get_general(const URLImpl *url, CryptoContext &ctx, CryptoHash &h ctx.update(&port, sizeof(port)); if (generation != -1) { ctx.update(&generation, sizeof(generation)); - Debug("url_cachekey", "Final url string for cache hash key %.*s%d%d", buffer_len, buffer, port, static_cast<int>(generation)); + Dbg(dbg_ctl_url_cachekey, "Final url string for cache hash key %.*s%d%d", buffer_len, buffer, port, + static_cast<int>(generation)); } else { - Debug("url_cachekey", "Final url string for cache hash key %.*s%d", buffer_len, buffer, port); + Dbg(dbg_ctl_url_cachekey, "Final url string for cache hash key %.*s%d", buffer_len, buffer, port); } ctx.finalize(hash); } diff --git a/src/proxy/hdrs/XPACK.cc b/src/proxy/hdrs/XPACK.cc index 7ed7bb359d..a218e9f79f 100644 --- a/src/proxy/hdrs/XPACK.cc +++ b/src/proxy/hdrs/XPACK.cc @@ -30,9 +30,13 @@ #include "tscore/ink_memory.h" #include "tsutil/LocalBuffer.h" -#define XPACKDebug(fmt, ...) Debug("xpack", fmt, ##__VA_ARGS__) +namespace +{ +DbgCtl dbg_ctl_xpack{"xpack"}; + +#define XPACKDbg(fmt, ...) Dbg(dbg_ctl_xpack, fmt, ##__VA_ARGS__) -static inline bool +inline bool match(const char *s1, int s1_len, const char *s2, int s2_len) { if (s1_len != s2_len) { @@ -50,6 +54,8 @@ match(const char *s1, int s1_len, const char *s2, int s2_len) return true; } +} // end anonymous namespace + // // [RFC 7541] 5.1. Integer representation // @@ -216,7 +222,7 @@ xpack_encode_string(uint8_t *buf_start, const uint8_t *buf_end, const char *valu // XpackDynamicTable::XpackDynamicTable(uint32_t size) : _maximum_size(size), _available(size), _max_entries(size), _storage(size) { - XPACKDebug("Dynamic table size: %u", size); + XPACKDbg("Dynamic table size: %u", size); this->_entries = static_cast<struct XpackDynamicTableEntry *>(ats_malloc(sizeof(struct XpackDynamicTableEntry) * size)); this->_entries_head = size - 1; this->_entries_tail = size - 1; @@ -233,7 +239,7 @@ XpackDynamicTable::~XpackDynamicTable() const XpackLookupResult XpackDynamicTable::lookup(uint32_t index, const char **name, size_t *name_len, const char **value, size_t *value_len) const { - XPACKDebug("Lookup entry: abs_index=%u", index); + XPACKDbg("Lookup entry: abs_index=%u", index); if (this->is_empty()) { // There's no entry @@ -263,7 +269,7 @@ XpackDynamicTable::lookup(uint32_t index, const char **name, size_t *name_len, c const XpackLookupResult XpackDynamicTable::lookup(const char *name, size_t name_len, const char *value, size_t value_len) const { - XPACKDebug("Lookup entry: name=%.*s, value=%.*s", static_cast<int>(name_len), name, static_cast<int>(value_len), value); + XPACKDbg("Lookup entry: name=%.*s, value=%.*s", static_cast<int>(name_len), name, static_cast<int>(value_len), value); XpackLookupResult::MatchType match_type = XpackLookupResult::MatchType::NONE; uint32_t i = this->_calc_index(this->_entries_tail, 1); uint32_t end = this->_calc_index(this->_entries_head, 1); @@ -293,7 +299,7 @@ XpackDynamicTable::lookup(const char *name, size_t name_len, const char *value, } } - XPACKDebug("Lookup entry: candidate_index=%u, match_type=%u", candidate_index, match_type); + XPACKDbg("Lookup entry: candidate_index=%u, match_type=%u", candidate_index, match_type); return {candidate_index, match_type}; } @@ -307,7 +313,7 @@ const XpackLookupResult XpackDynamicTable::lookup_relative(uint32_t relative_index, const char **name, size_t *name_len, const char **value, size_t *value_len) const { - XPACKDebug("Lookup entry: rel_index=%u", relative_index); + XPACKDbg("Lookup entry: rel_index=%u", relative_index); return this->lookup(this->_entries[this->_entries_head].index - relative_index, name, name_len, value, value_len); } @@ -355,8 +361,8 @@ XpackDynamicTable::insert_entry(const char *name, size_t name_len, const char *v wks}; this->_available -= required_size; - XPACKDebug("Insert Entry: entry=%u, index=%u, size=%zu", this->_entries_head, this->_entries_inserted - 1, name_len + value_len); - XPACKDebug("Available size: %u", this->_available); + XPACKDbg("Insert Entry: entry=%u, index=%u, size=%zu", this->_entries_head, this->_entries_inserted - 1, name_len + value_len); + XPACKDbg("Available size: %u", this->_available); return {this->_entries_inserted, value_len ? XpackLookupResult::MatchType::EXACT : XpackLookupResult::MatchType::NAME}; } @@ -493,11 +499,11 @@ XpackDynamicTable::_make_space(uint64_t required_size) // Evict if (freed > 0) { - XPACKDebug("Evict entries: from %u to %u", this->_entries[this->_calc_index(this->_entries_tail, 1)].index, - this->_entries[tail - 1].index); + XPACKDbg("Evict entries: from %u to %u", this->_entries[this->_calc_index(this->_entries_tail, 1)].index, + this->_entries[tail - 1].index); this->_available += freed; this->_entries_tail = tail - 1; - XPACKDebug("Available size: %u", this->_available); + XPACKDbg("Available size: %u", this->_available); } return required_size <= this->_available; diff --git a/src/proxy/http2/HPACK.cc b/src/proxy/http2/HPACK.cc index 53e71ec2db..d2dd14be6c 100644 --- a/src/proxy/http2/HPACK.cc +++ b/src/proxy/http2/HPACK.cc @@ -196,6 +196,9 @@ constexpr HpackHeaderField STATIC_TABLE[] = { constexpr std::string_view HPACK_HDR_FIELD_COOKIE = STATIC_TABLE[TS_HPACK_STATIC_TABLE_COOKIE].name; constexpr std::string_view HPACK_HDR_FIELD_AUTHORIZATION = STATIC_TABLE[TS_HPACK_STATIC_TABLE_AUTHORIZATION].name; +DbgCtl dbg_ctl_hpack_encode{"hpack_encode"}; +DbgCtl dbg_ctl_hpack_decode{"hpack_decode"}; + // // Local functions // @@ -208,7 +211,7 @@ hpack_field_is_literal(HpackField ftype) // Try not to use memcmp(sv, sv) and strncasecmp(sv, sv) because we don't care which value comes first on a dictionary. // Return immediately if the lengths of given strings don't match. // Also, we noticed with profiling that taking char* and int was more performant than taking std::string_view. -static inline bool +inline bool match(const char *s1, int s1_len, const char *s2, int s2_len) { if (s1_len != s2_len) { @@ -411,7 +414,7 @@ encode_indexed_header_field(uint8_t *buf_start, const uint8_t *buf_end, uint32_t *p |= 0x80; p += len; - Debug("hpack_encode", "Encoded field: %d", index); + Dbg(dbg_ctl_hpack_encode, "Encoded field: %d", index); return p - buf_start; } @@ -464,7 +467,7 @@ encode_literal_header_field_with_indexed_name(uint8_t *buf_start, const uint8_t } p += len; - Debug("hpack_encode", "Encoded field: %d: %.*s", index, static_cast<int>(header.value.size()), header.value.data()); + Dbg(dbg_ctl_hpack_encode, "Encoded field: %d: %.*s", index, static_cast<int>(header.value.size()), header.value.data()); return p - buf_start; } @@ -512,8 +515,8 @@ encode_literal_header_field_with_new_name(uint8_t *buf_start, const uint8_t *buf p += len; - Debug("hpack_encode", "Encoded field: %.*s: %.*s", static_cast<int>(header.name.size()), header.name.data(), - static_cast<int>(header.value.size()), header.value.data()); + Dbg(dbg_ctl_hpack_encode, "Encoded field: %.*s: %.*s", static_cast<int>(header.name.size()), header.name.data(), + static_cast<int>(header.value.size()), header.value.data()); return p - buf_start; } @@ -549,13 +552,13 @@ decode_indexed_header_field(MIMEFieldWrapper &header, const uint8_t *buf_start, return HPACK_ERROR_COMPRESSION_ERROR; } - if (is_debug_tag_set("hpack_decode")) { + if (dbg_ctl_hpack_decode.on()) { int decoded_name_len; const char *decoded_name = header.name_get(&decoded_name_len); int decoded_value_len; const char *decoded_value = header.value_get(&decoded_value_len); - Debug("hpack_decode", "Decoded field: %.*s: %.*s", decoded_name_len, decoded_name, decoded_value_len, decoded_value); + Dbg(dbg_ctl_hpack_decode, "Decoded field: %.*s: %.*s", decoded_name_len, decoded_name, decoded_value_len, decoded_value); } return len; @@ -640,13 +643,13 @@ decode_literal_header_field(MIMEFieldWrapper &header, const uint8_t *buf_start, } // Print decoded header field - if (is_debug_tag_set("hpack_decode")) { + if (dbg_ctl_hpack_decode.on()) { int decoded_name_len; const char *decoded_name = header.name_get(&decoded_name_len); int decoded_value_len; const char *decoded_value = header.value_get(&decoded_value_len); - Debug("hpack_decode", "Decoded field: %.*s: %.*s", decoded_name_len, decoded_name, decoded_value_len, decoded_value); + Dbg(dbg_ctl_hpack_decode, "Decoded field: %.*s: %.*s", decoded_name_len, decoded_name, decoded_value_len, decoded_value); } if (has_http2_violation) { diff --git a/src/proxy/http2/Http2ClientSession.cc b/src/proxy/http2/Http2ClientSession.cc index 5cd713e527..2839e37ade 100644 --- a/src/proxy/http2/Http2ClientSession.cc +++ b/src/proxy/http2/Http2ClientSession.cc @@ -30,13 +30,19 @@ ClassAllocator<Http2ClientSession, true> http2ClientSessionAllocator("http2ClientSessionAllocator"); -static int +namespace +{ +DbgCtl dbg_ctl_ssl_early_data{"ssl_early_data"}; + +int send_connection_event(Continuation *cont, int event, void *edata) { SCOPED_MUTEX_LOCK(lock, cont->mutex, this_ethread()); return cont->handleEvent(event, edata); } +} // end anonymous namespace + Http2ClientSession::Http2ClientSession() : super() {} void @@ -103,7 +109,7 @@ Http2ClientSession::new_connection(NetVConnection *new_vc, MIOBuffer *iobuf, IOB if (auto eds = new_vc->get_service<TLSEarlyDataSupport>(); eds) { this->read_from_early_data = eds->get_early_data_len(); - Debug("ssl_early_data", "read_from_early_data = %" PRId64, this->read_from_early_data); + Dbg(dbg_ctl_ssl_early_data, "read_from_early_data = %" PRId64, this->read_from_early_data); } Http2SsnDebug("session born, netvc %p", this->_vc); diff --git a/src/proxy/http2/Http2CommonSession.cc b/src/proxy/http2/Http2CommonSession.cc index abc3c41aaf..7a46d37712 100644 --- a/src/proxy/http2/Http2CommonSession.cc +++ b/src/proxy/http2/Http2CommonSession.cc @@ -24,18 +24,23 @@ #include "proxy/http2/Http2CommonSession.h" #include "proxy/http/HttpDebugNames.h" +namespace +{ +DbgCtl dbg_ctl_http2_cs{"http2_cs"}; + #define REMEMBER(e, r) \ { \ this->remember(MakeSourceLocation(), e, r); \ } -#define STATE_ENTER(state_name, event) \ - do { \ - REMEMBER(event, this->recursion) \ - Debug("http2_cs", "[%" PRId64 "] [%s, %s]", this->get_connection_id(), #state_name, HttpDebugNames::get_event_name(event)); \ +#define STATE_ENTER(state_name, event) \ + do { \ + REMEMBER(event, this->recursion) \ + Dbg(dbg_ctl_http2_cs, "[%" PRId64 "] [%s, %s]", this->get_connection_id(), #state_name, \ + HttpDebugNames::get_event_name(event)); \ } while (0) -#define Http2SsnDebug(fmt, ...) Debug("http2_cs", "[%" PRId64 "] " fmt, this->get_connection_id(), ##__VA_ARGS__) +#define Http2SsnDebug(fmt, ...) Dbg(dbg_ctl_http2_cs, "[%" PRId64 "] " fmt, this->get_connection_id(), ##__VA_ARGS__) #define HTTP2_SET_SESSION_HANDLER(handler) \ do { \ @@ -45,7 +50,7 @@ // memcpy the requested bytes from the IOBufferReader, returning how many were // actually copied. -static inline unsigned +inline unsigned copy_from_buffer_reader(void *dst, IOBufferReader *reader, unsigned nbytes) { char *end; @@ -54,6 +59,8 @@ copy_from_buffer_reader(void *dst, IOBufferReader *reader, unsigned nbytes) return end - static_cast<char *>(dst); } +} // end anonymous namespace + void Http2CommonSession::remember(const SourceLocation &location, int event, int reentrant) { diff --git a/src/proxy/http2/Http2ConnectionState.cc b/src/proxy/http2/Http2ConnectionState.cc index 62645b758a..4baaa52b52 100644 --- a/src/proxy/http2/Http2ConnectionState.cc +++ b/src/proxy/http2/Http2ConnectionState.cc @@ -44,6 +44,11 @@ #include <sstream> #include <numeric> +namespace +{ +DbgCtl dbg_ctl_http2_con{"http2_con"}; +DbgCtl dbg_ctl_http2_priority{"http2_priority"}; + #define REMEMBER(e, r) \ { \ if (this->session) { \ @@ -51,12 +56,12 @@ } \ } -#define Http2ConDebug(session, fmt, ...) Debug("http2_con", "[%" PRId64 "] " fmt, session->get_connection_id(), ##__VA_ARGS__); +#define Http2ConDebug(session, fmt, ...) Dbg(dbg_ctl_http2_con, "[%" PRId64 "] " fmt, session->get_connection_id(), ##__VA_ARGS__); #define Http2StreamDebug(session, stream_id, fmt, ...) \ - Debug("http2_con", "[%" PRId64 "] [%u] " fmt, session->get_connection_id(), stream_id, ##__VA_ARGS__); + Dbg(dbg_ctl_http2_con, "[%" PRId64 "] [%u] " fmt, session->get_connection_id(), stream_id, ##__VA_ARGS__); -static const int buffer_size_index[HTTP2_FRAME_TYPE_MAX] = { +const int buffer_size_index[HTTP2_FRAME_TYPE_MAX] = { BUFFER_SIZE_INDEX_16K, // HTTP2_FRAME_TYPE_DATA BUFFER_SIZE_INDEX_16K, // HTTP2_FRAME_TYPE_HEADERS -1, // HTTP2_FRAME_TYPE_PRIORITY @@ -69,7 +74,7 @@ static const int buffer_size_index[HTTP2_FRAME_TYPE_MAX] = { BUFFER_SIZE_INDEX_16K, // HTTP2_FRAME_TYPE_CONTINUATION }; -inline static unsigned +inline unsigned read_rcv_buffer(char *buf, size_t bufsize, unsigned &nbytes, const Http2Frame &frame) { char *end; @@ -84,6 +89,8 @@ read_rcv_buffer(char *buf, size_t bufsize, unsigned &nbytes, const Http2Frame &f return end - buf; } +} // end anonymous namespace + Http2Error Http2ConnectionState::rcv_data_frame(const Http2Frame &frame) { @@ -195,7 +202,7 @@ Http2ConnectionState::rcv_data_frame(const Http2Frame &frame) // Update stream window size stream->decrement_local_rwnd(payload_length); - if (is_debug_tag_set("http2_con")) { + if (dbg_ctl_http2_con.on()) { uint32_t const stream_window = this->acknowledged_local_settings.get(HTTP2_SETTINGS_INITIAL_WINDOW_SIZE); uint32_t const session_window = this->_get_configured_receive_session_window_size(); Http2StreamDebug(this->session, id, @@ -582,10 +589,10 @@ Http2ConnectionState::rcv_priority_frame(const Http2Frame &frame) // [RFC 7540] 5.3.3 Reprioritization Http2StreamDebug(this->session, stream_id, "Reprioritize"); this->dependency_tree->reprioritize(node, priority.stream_dependency, priority.exclusive_flag); - if (is_debug_tag_set("http2_priority")) { + if (dbg_ctl_http2_priority.on()) { std::stringstream output; this->dependency_tree->dump_tree(output); - Debug("http2_priority", "[%" PRId64 "] reprioritize %s", this->session->get_connection_id(), output.str().c_str()); + Dbg(dbg_ctl_http2_priority, "[%" PRId64 "] reprioritize %s", this->session->get_connection_id(), output.str().c_str()); } } else { // PRIORITY frame is received before HEADERS frame. @@ -1966,10 +1973,10 @@ Http2ConnectionState::delete_stream(Http2Stream *stream) if (node->active) { dependency_tree->deactivate(node, 0); } - if (is_debug_tag_set("http2_priority")) { + if (dbg_ctl_http2_priority.on()) { std::stringstream output; dependency_tree->dump_tree(output); - Debug("http2_priority", "[%" PRId64 "] %s", session->get_connection_id(), output.str().c_str()); + Dbg(dbg_ctl_http2_priority, "[%" PRId64 "] %s", session->get_connection_id(), output.str().c_str()); } dependency_tree->remove(node); // ink_release_assert(dependency_tree->find(stream->get_id()) == nullptr); diff --git a/src/proxy/http2/Http2SessionAccept.cc b/src/proxy/http2/Http2SessionAccept.cc index 53e84fe64e..8d9449a37d 100644 --- a/src/proxy/http2/Http2SessionAccept.cc +++ b/src/proxy/http2/Http2SessionAccept.cc @@ -26,6 +26,12 @@ #include "iocore/utils/Machine.h" #include "proxy/IPAllow.h" +namespace +{ +DbgCtl dbg_ctl_http2_seq{"http2_seq"}; + +} // end anonymous namespace + Http2SessionAccept::Http2SessionAccept(const HttpSessionAccept::Options &_o) : SessionAccept(nullptr), options(_o) { SET_HANDLER(&Http2SessionAccept::mainEvent); @@ -46,11 +52,11 @@ Http2SessionAccept::accept(NetVConnection *netvc, MIOBuffer *iobuf, IOBufferRead netvc->attributes = this->options.transport_type; - if (is_debug_tag_set("http2_seq")) { + if (dbg_ctl_http2_seq.on()) { ip_port_text_buffer ipb; - Debug("http2_seq", "[HttpSessionAccept2:mainEvent %p] accepted connection from %s transport type = %d", netvc, - ats_ip_nptop(client_ip, ipb, sizeof(ipb)), netvc->attributes); + DbgPrint(dbg_ctl_http2_seq, "[HttpSessionAccept2:mainEvent %p] accepted connection from %s transport type = %d", netvc, + ats_ip_nptop(client_ip, ipb, sizeof(ipb)), netvc->attributes); } Http2ClientSession *new_session = THREAD_ALLOC_INIT(http2ClientSessionAllocator, this_ethread()); diff --git a/src/proxy/logging/Log.cc b/src/proxy/logging/Log.cc index 795421e967..2b884393ec 100644 --- a/src/proxy/logging/Log.cc +++ b/src/proxy/logging/Log.cc @@ -87,8 +87,17 @@ LogsStatsBlock log_rsb; to be changed (as the result of a manager callback). -------------------------------------------------------------------------*/ -LogConfig *Log::config = nullptr; -static unsigned log_configid = 0; +LogConfig *Log::config = nullptr; + +namespace +{ +DbgCtl dbg_ctl_log_config{"log-config"}; +DbgCtl dbg_ctl_log_api_mutex{"log-api-mutex"}; +DbgCtl dbg_ctl_log_periodic{"log-periodic"}; +DbgCtl dbg_ctl_log{"log"}; +DbgCtl dbg_ctl_log_preproc{"log-preproc"}; + +unsigned log_configid = 0; // Downcast from a Ptr<LogFieldAliasTable> to a Ptr<LogFieldAliasMap>. static Ptr<LogFieldAliasMap> @@ -97,13 +106,15 @@ make_alias_map(Ptr<LogFieldAliasTable> &table) return make_ptr(static_cast<LogFieldAliasMap *>(table.get())); } +} // end anonymous namespace + void Log::change_configuration() { LogConfig *prev_config = Log::config; LogConfig *new_config = nullptr; - Debug("log-config", "Changing configuration ..."); + Dbg(dbg_ctl_log_config, "Changing configuration ..."); new_config = new LogConfig; ink_assert(new_config != nullptr); @@ -113,7 +124,7 @@ Log::change_configuration() // the new config // ink_mutex_acquire(prev_config->log_object_manager._APImutex); - Debug("log-api-mutex", "Log::change_configuration acquired api mutex"); + Dbg(dbg_ctl_log_api_mutex, "Log::change_configuration acquired api mutex"); new_config->init(prev_config); @@ -127,7 +138,7 @@ Log::change_configuration() // Server would crash the next time the plugin referenced the freed object. ink_mutex_release(prev_config->log_object_manager._APImutex); - Debug("log-api-mutex", "Log::change_configuration released api mutex"); + Dbg(dbg_ctl_log_api_mutex, "Log::change_configuration released api mutex"); // Register the new config in the config processor; the old one will now be scheduled for a // future deletion. We don't need to do anything magical with refcounts, since the @@ -138,7 +149,7 @@ Log::change_configuration() // objects that weren't transferred to the new config ... prev_config->log_object_manager.flush_all_objects(); - Debug("log-config", "... new configuration in place"); + Dbg(dbg_ctl_log_config, "... new configuration in place"); } /*------------------------------------------------------------------------- @@ -198,10 +209,10 @@ struct PeriodicWakeup : Continuation { void Log::periodic_tasks(long time_now) { - Debug("log-api-mutex", "entering Log::periodic_tasks"); + Dbg(dbg_ctl_log_api_mutex, "entering Log::periodic_tasks"); if (logging_mode_changed || Log::config->reconfiguration_needed) { - Debug("log-config", "Performing reconfiguration, init status = %d", init_status); + Dbg(dbg_ctl_log_config, "Performing reconfiguration, init status = %d", init_status); if (logging_mode_changed) { int val = static_cast<int>(REC_ConfigReadInteger("proxy.config.log.logging_enabled")); @@ -221,8 +232,8 @@ Log::periodic_tasks(long time_now) // change_configuration(); } else if (logging_mode > LOG_MODE_NONE || config->has_api_objects()) { - Debug("log-periodic", "Performing periodic tasks"); - Debug("log-periodic", "Periodic task interval = %d", periodic_tasks_interval); + Dbg(dbg_ctl_log_periodic, "Performing periodic tasks"); + Dbg(dbg_ctl_log_periodic, "Periodic task interval = %d", periodic_tasks_interval); // Check if space is ok and update the space used // @@ -993,7 +1004,7 @@ int Log::handle_logging_mode_change(const char * /* name ATS_UNUSED */, RecDataT /* data_type ATS_UNUSED */, RecData /* data ATS_UNUSED */, void * /* cookie ATS_UNUSED */) { - Debug("log-config", "Enabled status changed"); + Dbg(dbg_ctl_log_config, "Enabled status changed"); logging_mode_changed = true; return 0; } @@ -1002,14 +1013,14 @@ int Log::handle_periodic_tasks_int_change(const char * /* name ATS_UNUSED */, RecDataT /* data_type ATS_UNUSED */, RecData data, void * /* cookie ATS_UNSED */) { - Debug("log-periodic", "periodic task interval changed"); + Dbg(dbg_ctl_log_periodic, "periodic task interval changed"); if (data.rec_int <= 0) { periodic_tasks_interval = PERIODIC_TASKS_INTERVAL_FALLBACK; Error("new periodic tasks interval = %d is invalid, falling back to default = %d", (int)data.rec_int, PERIODIC_TASKS_INTERVAL_FALLBACK); } else { periodic_tasks_interval = static_cast<uint32_t>(data.rec_int); - Debug("log-periodic", "periodic task interval changed to %u", periodic_tasks_interval); + Dbg(dbg_ctl_log_periodic, "periodic task interval changed to %u", periodic_tasks_interval); } return REC_ERR_OKAY; } @@ -1017,7 +1028,7 @@ Log::handle_periodic_tasks_int_change(const char * /* name ATS_UNUSED */, RecDat int Log::handle_log_rotation_request() { - Debug("log", "Request to reopen rotated log files."); + Dbg(dbg_ctl_log, "Request to reopen rotated log files."); log_rotate_signal_received = true; return 0; } @@ -1078,7 +1089,7 @@ Log::init(int flags) init_fields(); if (!(config_flags & LOGCAT)) { - Debug("log-config", "Log::init(): logging_mode = %d init status = %d", logging_mode, init_status); + Dbg(dbg_ctl_log_config, "Log::init(): logging_mode = %d init status = %d", logging_mode, init_status); config->init(); init_when_enabled(); } @@ -1105,7 +1116,7 @@ Log::init_when_enabled() } Note("logging initialized[%d], logging_mode = %d", init_status, logging_mode); - if (is_debug_tag_set("log-config")) { + if (dbg_ctl_log_config.on()) { config->display(); } } @@ -1169,18 +1180,18 @@ Log::access(LogAccess *lad) if (Log::config->sampling_frequency > 1) { this_sample = sample++; if (this_sample && this_sample % Log::config->sampling_frequency) { - Debug("log", "sampling, skipping this entry ..."); + Dbg(dbg_ctl_log, "sampling, skipping this entry ..."); Metrics::Counter::increment(log_rsb.event_log_access_skip); ret = Log::SKIP; goto done; } else { - Debug("log", "sampling, LOGGING this entry ..."); + Dbg(dbg_ctl_log, "sampling, LOGGING this entry ..."); sample = 1; } } if (Log::config->log_object_manager.get_num_objects() == 0) { - Debug("log", "no log objects, skipping this entry ..."); + Dbg(dbg_ctl_log, "no log objects, skipping this entry ..."); Metrics::Counter::increment(log_rsb.event_log_access_skip); ret = Log::SKIP; goto done; @@ -1264,7 +1275,7 @@ Log::preproc_thread_main(void *args) { int idx = *static_cast<int *>(args); - Debug("log-preproc", "log preproc thread is alive ..."); + Dbg(dbg_ctl_log_preproc, "log preproc thread is alive ..."); Log::preproc_notify[idx].lock(); @@ -1280,8 +1291,8 @@ Log::preproc_thread_main(void *args) // config->increment_space_used(bytes_to_disk); // TODO: the bytes_to_disk should be set to Log - Debug("log-preproc", "%zu buffers preprocessed from LogConfig %p (refcount=%d) this round", buffers_preproced, current, - current->refcount()); + Dbg(dbg_ctl_log_preproc, "%zu buffers preprocessed from LogConfig %p (refcount=%d) this round", buffers_preproced, current, + current->refcount()); configProcessor.release(log_configid, current); } @@ -1362,8 +1373,8 @@ Log::flush_thread_main(void * /* args ATS_UNUSED */) // while (total_bytes - bytes_written) { if (Log::config->logging_space_exhausted) { - Debug("log", "logging space exhausted, failed to write file:%s, have dropped (%d) bytes.", logfile->get_name(), - (total_bytes - bytes_written)); + Dbg(dbg_ctl_log, "logging space exhausted, failed to write file:%s, have dropped (%d) bytes.", logfile->get_name(), + (total_bytes - bytes_written)); Metrics::Counter::increment(log_rsb.bytes_lost_before_written_to_disk, total_bytes - bytes_written); break; @@ -1378,7 +1389,7 @@ Log::flush_thread_main(void * /* args ATS_UNUSED */) Metrics::Counter::increment(log_rsb.bytes_lost_before_written_to_disk, total_bytes - bytes_written); break; } - Debug("log", "Successfully wrote some stuff to %s", logfile->get_name()); + Dbg(dbg_ctl_log, "Successfully wrote some stuff to %s", logfile->get_name()); bytes_written += len; } @@ -1395,7 +1406,7 @@ Log::flush_thread_main(void * /* args ATS_UNUSED */) // now = ink_get_hrtime() / HRTIME_SECOND; if (now >= last_time + periodic_tasks_interval) { - Debug("log-preproc", "periodic tasks for %" PRId64, (int64_t)now); + Dbg(dbg_ctl_log_preproc, "periodic tasks for %" PRId64, (int64_t)now); periodic_tasks(now); last_time = ink_get_hrtime() / HRTIME_SECOND; } diff --git a/src/proxy/logging/LogAccess.cc b/src/proxy/logging/LogAccess.cc index d8ced3a9cd..b14126a0fb 100644 --- a/src/proxy/logging/LogAccess.cc +++ b/src/proxy/logging/LogAccess.cc @@ -44,6 +44,13 @@ char INVALID_STR[] = "!INVALID_STR!"; // #define MARSHAL_RECORD_LENGTH 32 +namespace +{ +DbgCtl dbg_ctl_log_escape{"log-escape"}; +DbgCtl dbg_ctl_log_resolve{"log-resolve"}; + +} // end anonymous namespace + /*------------------------------------------------------------------------- LogAccess @@ -710,7 +717,7 @@ escape_json(char *dest, const char *buf, int len) int unmarshal_str_json(char **buf, char *dest, int len, LogSlice *slice) { - Debug("log-escape", "unmarshal_str_json start, len=%d, slice=%p", len, slice); + Dbg(dbg_ctl_log_escape, "unmarshal_str_json start, len=%d, slice=%p", len, slice); char *val_buf = *buf; int val_len = static_cast<int>(::strlen(val_buf)); @@ -722,7 +729,7 @@ unmarshal_str_json(char **buf, char *dest, int len, LogSlice *slice) int offset, n; n = slice->toStrOffset(escaped_len, &offset); - Debug("log-escape", "unmarshal_str_json start, n=%d, offset=%d", n, offset); + Dbg(dbg_ctl_log_escape, "unmarshal_str_json start, n=%d, offset=%d", n, offset); if (n <= 0) { return 0; } @@ -1181,16 +1188,16 @@ char * resolve_logfield_string(LogAccess *context, const char *format_str) { if (!context) { - Debug("log-resolve", "No context to resolve?"); + Dbg(dbg_ctl_log_resolve, "No context to resolve?"); return nullptr; } if (!format_str) { - Debug("log-resolve", "No format to resolve?"); + Dbg(dbg_ctl_log_resolve, "No format to resolve?"); return nullptr; } - Debug("log-resolve", "Resolving: %s", format_str); + Dbg(dbg_ctl_log_resolve, "Resolving: %s", format_str); // // Divide the format string into two parts: one for the printf-style @@ -1205,14 +1212,14 @@ resolve_logfield_string(LogAccess *context, const char *format_str) // format_str. Nothing to free here either. // if (!n_fields) { - Debug("log-resolve", "No fields found; returning copy of format_str"); + Dbg(dbg_ctl_log_resolve, "No fields found; returning copy of format_str"); ats_free(printf_str); ats_free(fields_str); return ats_strdup(format_str); } - Debug("log-resolve", "%d fields: %s", n_fields, fields_str); - Debug("log-resolve", "printf string: %s", printf_str); + Dbg(dbg_ctl_log_resolve, "%d fields: %s", n_fields, fields_str); + Dbg(dbg_ctl_log_resolve, "printf string: %s", printf_str); LogFieldList fields; bool contains_aggregates; @@ -1229,14 +1236,14 @@ resolve_logfield_string(LogAccess *context, const char *format_str) // temporary storage buffer. Make sure the LogAccess context is // initialized first. // - Debug("log-resolve", "Marshaling data from LogAccess into buffer ..."); + Dbg(dbg_ctl_log_resolve, "Marshaling data from LogAccess into buffer ..."); context->init(); unsigned bytes_needed = fields.marshal_len(context); char *buf = static_cast<char *>(ats_malloc(bytes_needed)); unsigned bytes_used = fields.marshal(context, buf); ink_assert(bytes_needed == bytes_used); - Debug("log-resolve", " %u bytes marshalled", bytes_used); + Dbg(dbg_ctl_log_resolve, " %u bytes marshalled", bytes_used); // // Now we can "unmarshal" the data from the buffer into a string, diff --git a/src/proxy/logging/LogBuffer.cc b/src/proxy/logging/LogBuffer.cc index 8b6d03f31b..600f389f2f 100644 --- a/src/proxy/logging/LogBuffer.cc +++ b/src/proxy/logging/LogBuffer.cc @@ -57,6 +57,13 @@ FieldListCacheElement fieldlist_cache[FIELDLIST_CACHE_SIZE]; int fieldlist_cache_entries = 0; int32_t LogBuffer::M_ID; +namespace +{ +DbgCtl dbg_ctl_log_logbuffer{"log-logbuffer"}; +DbgCtl dbg_ctl_log_fieldlist{"log-fieldlist"}; + +} // end anonymous namespace + /*------------------------------------------------------------------------- The following LogBufferHeader routines are used to grab strings out from the data section using the offsets held in the buffer header. @@ -131,8 +138,8 @@ LogBuffer::LogBuffer(const LogConfig *cfg, LogObject *owner, size_t size, size_t m_expiration_time = LogUtils::timestamp() + cfg->max_secs_per_buffer; - Debug("log-logbuffer", "[%p] Created buffer %u for %s at address %p, size %d", this_ethread(), m_id, m_owner->get_base_filename(), - m_buffer, (int)size); + Dbg(dbg_ctl_log_logbuffer, "[%p] Created buffer %u for %s at address %p, size %d", this_ethread(), m_id, + m_owner->get_base_filename(), m_buffer, (int)size); } LogBuffer::LogBuffer(LogObject *owner, LogBufferHeader *header) @@ -156,8 +163,8 @@ LogBuffer::LogBuffer(LogObject *owner, LogBufferHeader *header) // m_id = static_cast<uint32_t>(ink_atomic_increment(&M_ID, 1)); - Debug("log-logbuffer", "[%p] Created repurposed buffer %u for %s at address %p", this_ethread(), m_id, - m_owner->get_base_filename(), m_buffer); + Dbg(dbg_ctl_log_logbuffer, "[%p] Created repurposed buffer %u for %s at address %p", this_ethread(), m_id, + m_owner->get_base_filename(), m_buffer); } void @@ -171,7 +178,7 @@ LogBuffer::freeLogBuffer() log_buffer = m_buffer; } if (log_buffer) { - Debug("log-logbuffer", "[%p] Deleting buffer %u at address %p", this_ethread(), m_id, log_buffer); + Dbg(dbg_ctl_log_logbuffer, "[%p] Deleting buffer %u at address %p", this_ethread(), m_id, log_buffer); if (m_buffer_fast_allocator_size >= 0) { ioBufAllocator[m_buffer_fast_allocator_size].free_void(log_buffer); } else { @@ -319,7 +326,7 @@ LogBuffer::checkout_write(size_t *write_offset, size_t write_size) *write_offset = offset + sizeof(LogEntryHeader); } - // Debug("log-logbuffer","[%p] %s for buffer %u (%s) returning %d", + // Dbg(dbg_ctl_log_logbuffer,"[%p] %s for buffer %u (%s) returning %d", // this_ethread(), // (write_offset ? "checkout_write" : "force_new_buffer"), // m_id, m_owner->get_base_filename(), ret_val); @@ -356,7 +363,7 @@ LogBuffer::checkin_write(size_t write_offset) } } while (!switch_state(old_s, new_s)); - // Debug("log-logbuffer","[%p] checkin_write for buffer %u (%s) " + // Dbg(dbg_ctl_log_logbuffer,"[%p] checkin_write for buffer %u (%s) " // "returning %d (%u writers left)", this_ethread(), // m_id, m_owner->get_base_filename(), ret_val, writers_left); @@ -617,21 +624,21 @@ LogBuffer::to_ascii(LogEntryHeader *entry, LogFormatType type, char *buf, int bu for (i = 0; i < fieldlist_cache_entries; i++) { if (strcmp(symbol_str, fieldlist_cache[i].symbol_str) == 0) { - Debug("log-fieldlist", "Fieldlist for %s found in cache, #%d", symbol_str, i); + Dbg(dbg_ctl_log_fieldlist, "Fieldlist for %s found in cache, #%d", symbol_str, i); fieldlist = fieldlist_cache[i].fieldlist; break; } } if (!fieldlist) { - Debug("log-fieldlist", "Fieldlist for %s not found; creating ...", symbol_str); + Dbg(dbg_ctl_log_fieldlist, "Fieldlist for %s not found; creating ...", symbol_str); fieldlist = new LogFieldList; ink_assert(fieldlist != nullptr); bool contains_aggregates = false; LogFormat::parse_symbol_string(symbol_str, fieldlist, &contains_aggregates); if (fieldlist_cache_entries < FIELDLIST_CACHE_SIZE) { - Debug("log-fieldlist", "Fieldlist cached as entry %d", fieldlist_cache_entries); + Dbg(dbg_ctl_log_fieldlist, "Fieldlist cached as entry %d", fieldlist_cache_entries); fieldlist_cache[fieldlist_cache_entries].fieldlist = fieldlist; fieldlist_cache[fieldlist_cache_entries].symbol_str = ats_strdup(symbol_str); fieldlist_cache_entries++; diff --git a/src/proxy/logging/LogConfig.cc b/src/proxy/logging/LogConfig.cc index 0ef4db6ff7..1c542e494b 100644 --- a/src/proxy/logging/LogConfig.cc +++ b/src/proxy/logging/LogConfig.cc @@ -62,6 +62,14 @@ #define DIAGS_LOG_FILENAME "diags.log" #define MANAGER_LOG_FILENAME "manager.log" +namespace +{ +DbgCtl dbg_ctl_logspace{"logspace"}; +DbgCtl dbg_ctl_log{"log"}; +DbgCtl dbg_ctl_log_config{"log-config"}; + +} // end anonymous namespace + void LogConfig::reconfigure_mgmt_variables(swoc::MemSpan<void>) { @@ -77,8 +85,8 @@ LogConfig::register_rolled_log_auto_delete(std::string_view logname, int rolling return; } - Debug("logspace", "Registering rotated log deletion for %s with min roll count %d", std::string(logname).c_str(), - rolling_min_count); + Dbg(dbg_ctl_logspace, "Registering rotated log deletion for %s with min roll count %d", std::string(logname).c_str(), + rolling_min_count); rolledLogDeleter.register_log_type_for_deletion(logname, rolling_min_count); } @@ -298,7 +306,7 @@ LogConfig::init(LogConfig *prev_config) if (Log::error_logging_enabled()) { std::unique_ptr<LogFormat> fmt(MakeTextLogFormat("error")); - Debug("log", "creating predefined error log object"); + Dbg(dbg_ctl_log, "creating predefined error log object"); errlog = new LogObject(this, fmt.get(), logfile_dir, error_log_filename, LOG_FILE_ASCII, nullptr, rolling_enabled, preproc_threads, rolling_interval_sec, rolling_offset_hr, rolling_size_mb, /* auto_created */ false, @@ -385,7 +393,7 @@ LogConfig::display(FILE *fd) void LogConfig::setup_log_objects() { - Debug("log", "creating objects..."); + Dbg(dbg_ctl_log, "creating objects..."); filter_list.clear(); @@ -395,7 +403,7 @@ LogConfig::setup_log_objects() // Open local pipes so readers can see them. log_object_manager.open_local_pipes(); - if (is_debug_tag_set("log")) { + if (dbg_ctl_log.on()) { log_object_manager.display(); } } @@ -414,7 +422,7 @@ int LogConfig::reconfigure(const char * /* name ATS_UNUSED */, RecDataT /* data_type ATS_UNUSED */, RecData /* data ATS_UNUSED */, void * /* cookie ATS_UNUSED */) { - Debug("log-config", "Reconfiguration request accepted"); + Dbg(dbg_ctl_log_config, "Reconfiguration request accepted"); Log::config->reconfiguration_needed = true; return 0; } @@ -521,10 +529,10 @@ LogConfig::space_to_write(int64_t bytes_to_write) const space = ((logical_space_used < config_space) && (physical_space_left > partition_headroom)); - Debug("logspace", - "logical space used %" PRId64 ", configured space %" PRId64 ", physical space left %" PRId64 ", partition headroom %" PRId64 - ", space %s available", - logical_space_used, config_space, physical_space_left, partition_headroom, space ? "is" : "is not"); + Dbg(dbg_ctl_logspace, + "logical space used %" PRId64 ", configured space %" PRId64 ", physical space left %" PRId64 ", partition headroom %" PRId64 + ", space %s available", + logical_space_used, config_space, physical_space_left, partition_headroom, space ? "is" : "is not"); return space; } @@ -624,8 +632,8 @@ LogConfig::update_space_used() m_partition_space_left = partition_space_left; Metrics::Gauge::store(log_rsb.log_files_space_used, m_space_used); - Debug("logspace", "%" PRId64 " bytes being used for logs", m_space_used); - Debug("logspace", "%" PRId64 " bytes left on partition", m_partition_space_left); + Dbg(dbg_ctl_logspace, "%" PRId64 " bytes being used for logs", m_space_used); + Dbg(dbg_ctl_logspace, "%" PRId64 " bytes left on partition", m_partition_space_left); // // Now that we have an accurate picture of the amount of space being @@ -642,16 +650,16 @@ LogConfig::update_space_used() int64_t headroom = static_cast<int64_t>(max_space_mb_headroom) * LOG_MEGABYTE; if (!space_to_write(headroom)) { - Debug("logspace", "headroom reached, trying to clear space ..."); + Dbg(dbg_ctl_logspace, "headroom reached, trying to clear space ..."); if (!rolledLogDeleter.has_candidates()) { Note("Cannot clear space because there are no recognized Traffic Server rolled logs for auto deletion."); } else { - Debug("logspace", "Considering %zu delete candidates ...", rolledLogDeleter.get_candidate_count()); + Dbg(dbg_ctl_logspace, "Considering %zu delete candidates ...", rolledLogDeleter.get_candidate_count()); } while (rolledLogDeleter.has_candidates()) { if (space_to_write(headroom + log_buffer_size)) { - Debug("logspace", "low water mark reached; stop deleting"); + Dbg(dbg_ctl_logspace, "low water mark reached; stop deleting"); break; } @@ -659,19 +667,19 @@ LogConfig::update_space_used() // Check if any candidate exists if (!victim) { // This shouldn't be triggered unless min_count are configured wrong or extra non-log files occupy the directory - Debug("logspace", "No more victims. Check your rolling_min_count settings and logging directory."); + Dbg(dbg_ctl_logspace, "No more victims. Check your rolling_min_count settings and logging directory."); } else { - Debug("logspace", "auto-deleting %s", victim->rolled_log_path.c_str()); + Dbg(dbg_ctl_logspace, "auto-deleting %s", victim->rolled_log_path.c_str()); if (unlink(victim->rolled_log_path.c_str()) < 0) { Note("Traffic Server was unable to auto-delete rolled " "logfile %s: %s.", victim->rolled_log_path.c_str(), strerror(errno)); } else { - Debug("logspace", - "The rolled logfile, %s, was auto-deleted; " - "%" PRId64 " bytes were reclaimed.", - victim->rolled_log_path.c_str(), victim->size); + Dbg(dbg_ctl_logspace, + "The rolled logfile, %s, was auto-deleted; " + "%" PRId64 " bytes were reclaimed.", + victim->rolled_log_path.c_str(), victim->size); // Update after successful unlink; m_space_used -= victim->size; diff --git a/src/proxy/logging/LogField.cc b/src/proxy/logging/LogField.cc index 1bdbf71625..9e02c4c721 100644 --- a/src/proxy/logging/LogField.cc +++ b/src/proxy/logging/LogField.cc @@ -39,9 +39,12 @@ #include "proxy/logging/LogAccess.h" #include "proxy/logging/Log.h" +namespace +{ + // clang-format off // -static const char *container_names[] = { +const char *container_names[] = { "not-a-container", "cqh", "psh", @@ -60,7 +63,7 @@ static const char *container_names[] = { "msdms", }; -static const char *aggregate_names[] = { +const char *aggregate_names[] = { "not-an-agg-op", "COUNT", "SUM", @@ -69,6 +72,11 @@ static const char *aggregate_names[] = { "LAST", }; +DbgCtl dbg_ctl_log_agg{"log-agg"}; +DbgCtl dbg_ctl_log_field_hash{"log-field-hash"}; + +} // end anonymous namespace + // clang-format on LogSlice::LogSlice(char *str) @@ -678,10 +686,10 @@ LogField::update_aggregate(int64_t val) return; } - Debug("log-agg", - "Aggregate field %s updated with val %" PRId64 ", " - "new val = %" PRId64 ", cnt = %" PRId64 "", - m_symbol, val, m_agg_val, m_agg_cnt); + Dbg(dbg_ctl_log_agg, + "Aggregate field %s updated with val %" PRId64 ", " + "new val = %" PRId64 ", cnt = %" PRId64 "", + m_symbol, val, m_agg_val, m_agg_cnt); } LogField::Container @@ -790,7 +798,7 @@ LogFieldList::find_by_symbol(const char *symbol) const if (auto it = Log::field_symbol_hash.find(symbol); it != Log::field_symbol_hash.end() && it->second) { field = it->second; - Debug("log-field-hash", "Field %s found", field->symbol()); + Dbg(dbg_ctl_log_field_hash, "Field %s found", field->symbol()); return field; } // trusty old method diff --git a/src/proxy/logging/LogFile.cc b/src/proxy/logging/LogFile.cc index 1f3caea3ca..b235045c76 100644 --- a/src/proxy/logging/LogFile.cc +++ b/src/proxy/logging/LogFile.cc @@ -55,6 +55,13 @@ #include "proxy/logging/LogConfig.h" #include "proxy/logging/Log.h" +namespace +{ +DbgCtl dbg_ctl_log_file{"log-file"}; +DbgCtl dbg_ctl_log{"log"}; + +} // end anonymous namespace + /*------------------------------------------------------------------------- LogFile::LogFile @@ -84,7 +91,7 @@ LogFile::LogFile(const char *name, const char *header, LogFileFormat format, uin m_fd = -1; m_ascii_buffer_size = (ascii_buffer_size < max_line_size ? max_line_size : ascii_buffer_size); - Debug("log-file", "exiting LogFile constructor, m_name=%s, this=%p, escape_type=%d", m_name, this, escape_type); + Dbg(dbg_ctl_log_file, "exiting LogFile constructor, m_name=%s, this=%p, escape_type=%d", m_name, this, escape_type); } /*------------------------------------------------------------------------- @@ -99,7 +106,7 @@ LogFile::LogFile(const char *name, const char *header, LogFileFormat format, uin LogFile::~LogFile() { - Debug("log-file", "entering LogFile destructor, this=%p", this); + Dbg(dbg_ctl_log_file, "entering LogFile destructor, this=%p", this); // close_file() checks whether a file is open before attempting to close, so // this is safe to call even if a file had not been opened. Further, calling @@ -109,7 +116,7 @@ LogFile::~LogFile() delete m_log; ats_free(m_header); ats_free(m_name); - Debug("log-file", "exiting LogFile destructor, this=%p", this); + Dbg(dbg_ctl_log_file, "exiting LogFile destructor, this=%p", this); } /*------------------------------------------------------------------------- @@ -165,14 +172,14 @@ LogFile::open_file() return LOG_FILE_COULD_NOT_CREATE_PIPE; } } else { - Debug("log-file", "Created named pipe %s for logging", m_name); + Dbg(dbg_ctl_log_file, "Created named pipe %s for logging", m_name); } // now open the pipe - Debug("log-file", "attempting to open pipe %s", m_name); + Dbg(dbg_ctl_log_file, "attempting to open pipe %s", m_name); m_fd = ::open(m_name, O_WRONLY | O_NDELAY, 0); if (m_fd < 0) { - Debug("log-file", "no readers for pipe %s", m_name); + Dbg(dbg_ctl_log_file, "no readers for pipe %s", m_name); return LOG_FILE_NO_PIPE_READERS; } @@ -183,7 +190,7 @@ LogFile::open_file() if (pipe_size == -1) { Error("Get pipe size failed for pipe %s: %s", m_name, strerror(errno)); } else { - Debug("log-file", "Previous buffer size for pipe %s: %ld", m_name, pipe_size); + Dbg(dbg_ctl_log_file, "Previous buffer size for pipe %s: %ld", m_name, pipe_size); } int ret = fcntl(m_fd, F_SETPIPE_SZ, m_pipe_buffer_size); @@ -195,7 +202,7 @@ LogFile::open_file() if (pipe_size == -1) { Error("Get pipe size after setting it failed for pipe %s: %s", m_name, strerror(errno)); } else { - Debug("log-file", "New buffer size for pipe %s: %ld", m_name, pipe_size); + Dbg(dbg_ctl_log_file, "New buffer size for pipe %s: %ld", m_name, pipe_size); } } #endif // F_GETPIPE_SZ @@ -218,14 +225,14 @@ LogFile::open_file() // if (!file_exists) { if (m_file_format != LOG_FILE_BINARY && m_header && m_log) { - Debug("log-file", "writing header to LogFile %s", m_name); + Dbg(dbg_ctl_log_file, "writing header to LogFile %s", m_name); writeln(m_header, strlen(m_header), fileno(m_log->m_fp), m_name); } } Metrics::Gauge::increment(log_rsb.log_files_open); - Debug("log", "exiting LogFile::open_file(), file=%s presumably open", m_name); + Dbg(dbg_ctl_log, "exiting LogFile::open_file(), file=%s presumably open", m_name); return LOG_FILE_NO_ERROR; } @@ -243,7 +250,7 @@ LogFile::close_file() if (::close(m_fd)) { Error("Error closing LogFile %s: %s.", m_name, strerror(errno)); } else { - Debug("log-file", "LogFile %s (fd=%d) is closed", m_name, m_fd); + Dbg(dbg_ctl_log_file, "LogFile %s (fd=%d) is closed", m_name, m_fd); Metrics::Gauge::decrement(log_rsb.log_files_open); } m_fd = -1; @@ -251,7 +258,7 @@ LogFile::close_file() if (m_log->close_file()) { Error("Error closing LogFile %s: %s.", m_log->get_name(), strerror(errno)); } else { - Debug("log-file", "LogFile %s is closed", m_log->get_name()); + Dbg(dbg_ctl_log_file, "LogFile %s is closed", m_log->get_name()); Metrics::Gauge::decrement(log_rsb.log_files_open); } } else { @@ -335,7 +342,7 @@ LogFile::trim_rolled(size_t rolling_max_count) Error("unable to auto-delete rolled logfile %s: %s", file._name.c_str(), strerror(errno)); result = false; } else { - Debug("log-file", "rolled logfile, %s, was auto-deleted", file._name.c_str()); + Dbg(dbg_ctl_log_file, "rolled logfile, %s, was auto-deleted", file._name.c_str()); } } } @@ -562,10 +569,10 @@ LogFile::write_ascii_logbuffer(LogBufferHeader *buffer_header, int fd, const cha int LogFile::write_ascii_logbuffer3(LogBufferHeader *buffer_header, const char *alt_format) { - Debug("log-file", - "entering LogFile::write_ascii_logbuffer3 for %s " - "(this=%p)", - m_name, this); + Dbg(dbg_ctl_log_file, + "entering LogFile::write_ascii_logbuffer3 for %s " + "(this=%p)", + m_name, this); ink_assert(buffer_header != nullptr); LogBufferIterator iter(buffer_header); diff --git a/src/proxy/logging/LogFilter.cc b/src/proxy/logging/LogFilter.cc index a3c97a87d5..8be0b3ae03 100644 --- a/src/proxy/logging/LogFilter.cc +++ b/src/proxy/logging/LogFilter.cc @@ -49,6 +49,13 @@ const char *LogFilter::OPERATOR_NAME[] = {"MATCH", "CASE_INSENSITIVE_MATCH", "CONTAIN", "CASE_INSENSITIVE_CONTAIN"}; const char *LogFilter::ACTION_NAME[] = {"REJECT", "ACCEPT", "WIPE_FIELD_VALUE"}; +namespace +{ +DbgCtl dbg_ctl_log{"log"}; +DbgCtl dbg_ctl_log_filter_compare{"log-filter-compare"}; + +} // end anonymous namespace + /*------------------------------------------------------------------------- LogFilter::LogFilter @@ -91,14 +98,14 @@ LogFilter::parse(const char *name, Action action, const char *condition) // validate field symbol if (strlen(field_str) > 2 && field_str[0] == '%' && field_str[1] == '<') { - Debug("log", "Field symbol has <> form: %s", field_str); + Dbg(dbg_ctl_log, "Field symbol has <> form: %s", field_str); char *end = field_str; while (*end && *end != '>') { end++; } *end = '\0'; field_str += 2; - Debug("log", "... now field symbol is %s", field_str); + Dbg(dbg_ctl_log, "... now field symbol is %s", field_str); } if (LogField *f = Log::global_field_list.find_by_symbol(field_str)) { @@ -108,7 +115,7 @@ LogFilter::parse(const char *name, Action action, const char *condition) if (!logfield) { // check for container fields if (*field_str == '{') { - Debug("log", "%s appears to be a container field", field_str); + Dbg(dbg_ctl_log, "%s appears to be a container field", field_str); char *fname; char *cname; @@ -126,7 +133,7 @@ LogFilter::parse(const char *name, Action action, const char *condition) // start of container symbol cname = fname_end + 1; - Debug("log", "found container field: Name = %s, symbol = %s", fname, cname); + Dbg(dbg_ctl_log, "found container field: Name = %s, symbol = %s", fname, cname); LogField::Container container = LogField::valid_container_name(cname); if (container == LogField::NO_CONTAINER) { @@ -883,7 +890,7 @@ filters_are_equal(LogFilter *filt1, LogFilter *filt2) // TODO: we should check name here if (filt1->type() == filt2->type()) { if (filt1->type() == LogFilter::INT_FILTER) { - Debug("log-filter-compare", "int compare"); + Dbg(dbg_ctl_log_filter_compare, "int compare"); ret = (*((LogFilterInt *)filt1) == *((LogFilterInt *)filt2)); } else if (filt1->type() == LogFilter::IP_FILTER) { ret = (*((LogFilterIP *)filt1) == *((LogFilterIP *)filt2)); @@ -893,7 +900,7 @@ filters_are_equal(LogFilter *filt1, LogFilter *filt2) ink_assert(!"invalid filter type"); } } else { - Debug("log-filter-compare", "type diff"); + Dbg(dbg_ctl_log_filter_compare, "type diff"); } return ret; } diff --git a/src/proxy/logging/LogFormat.cc b/src/proxy/logging/LogFormat.cc index c20e85f81a..5684bbc174 100644 --- a/src/proxy/logging/LogFormat.cc +++ b/src/proxy/logging/LogFormat.cc @@ -49,6 +49,13 @@ // bool LogFormat::m_tagging_on = false; +namespace +{ +DbgCtl dbg_ctl_log_format{"log-format"}; +DbgCtl dbg_ctl_log_agg{"log-agg"}; +DbgCtl dbg_ctl_log_slice{"log-slice"}; + +} // end anonymous namespace /*------------------------------------------------------------------------- LogFormat::setup -------------------------------------------------------------------------*/ @@ -282,13 +289,13 @@ LogFormat::format_from_specification(char *spec, char **file_name, char **file_h // token = tok.getNext(); if (token == nullptr) { - Debug("log-format", "token expected"); + Dbg(dbg_ctl_log_format, "token expected"); return nullptr; } if (strcasecmp(token, "format") == 0) { - Debug("log-format", "this is a format"); + Dbg(dbg_ctl_log_format, "this is a format"); } else { - Debug("log-format", "should be 'format'"); + Dbg(dbg_ctl_log_format, "should be 'format'"); return nullptr; } @@ -298,16 +305,16 @@ LogFormat::format_from_specification(char *spec, char **file_name, char **file_h // token = tok.getNext(); if (token == nullptr) { - Debug("log-format", "token expected"); + Dbg(dbg_ctl_log_format, "token expected"); return nullptr; } if (!strcasecmp(token, "disabled")) { - Debug("log-format", "format not enabled, skipping ..."); + Dbg(dbg_ctl_log_format, "format not enabled, skipping ..."); return nullptr; } else if (!strcasecmp(token, "enabled")) { - Debug("log-format", "enabled format"); + Dbg(dbg_ctl_log_format, "enabled format"); } else { - Debug("log-format", "should be 'enabled' or 'disabled', not %s", token); + Dbg(dbg_ctl_log_format, "should be 'enabled' or 'disabled', not %s", token); return nullptr; } @@ -316,7 +323,7 @@ LogFormat::format_from_specification(char *spec, char **file_name, char **file_h // token = tok.getNext(); if (token == nullptr) { - Debug("log-format", "token expected"); + Dbg(dbg_ctl_log_format, "token expected"); return nullptr; } format_id = atoi(token); @@ -327,7 +334,7 @@ LogFormat::format_from_specification(char *spec, char **file_name, char **file_h // token = tok.getNext(); if (token == nullptr) { - Debug("log-format", "token expected"); + Dbg(dbg_ctl_log_format, "token expected"); return nullptr; } format_name = token; @@ -337,7 +344,7 @@ LogFormat::format_from_specification(char *spec, char **file_name, char **file_h // token = tok.getNext(); if (token == nullptr) { - Debug("log-format", "token expected"); + Dbg(dbg_ctl_log_format, "token expected"); return nullptr; } format_str = token; @@ -347,7 +354,7 @@ LogFormat::format_from_specification(char *spec, char **file_name, char **file_h // token = tok.getNext(); if (token == nullptr) { - Debug("log-format", "token expected"); + Dbg(dbg_ctl_log_format, "token expected"); return nullptr; } *file_name = ats_strdup(token); @@ -357,7 +364,7 @@ LogFormat::format_from_specification(char *spec, char **file_name, char **file_h // token = tok.getNext(); if (token == nullptr) { - Debug("log-format", "token expected"); + Dbg(dbg_ctl_log_format, "token expected"); return nullptr; } if (!strcasecmp(token, "ASCII")) { @@ -365,7 +372,7 @@ LogFormat::format_from_specification(char *spec, char **file_name, char **file_h } else if (!strcasecmp(token, "BINARY")) { *file_type = LOG_FILE_BINARY; } else { - Debug("log-format", "%s is not a valid file format (ASCII or BINARY)", token); + Dbg(dbg_ctl_log_format, "%s is not a valid file format (ASCII or BINARY)", token); return nullptr; } @@ -374,7 +381,7 @@ LogFormat::format_from_specification(char *spec, char **file_name, char **file_h // token = tok.getRest(); if (token == nullptr) { - Debug("log-format", "token expected"); + Dbg(dbg_ctl_log_format, "token expected"); return nullptr; } // set header to NULL if "none" was specified (a NULL header means @@ -382,7 +389,7 @@ LogFormat::format_from_specification(char *spec, char **file_name, char **file_h // *file_header = strcmp(token, "none") == 0 ? nullptr : ats_strdup(token); - Debug("log-format", "custom:%d:%s:%s:%s:%d:%s", format_id, format_name, format_str, *file_name, *file_type, token); + Dbg(dbg_ctl_log_format, "custom:%d:%s:%s:%s:%d:%s", format_id, format_name, format_str, *file_name, *file_type, token); format = new LogFormat(format_name, format_str); ink_assert(format != nullptr); @@ -434,12 +441,12 @@ LogFormat::parse_symbol_string(const char *symbol_string, LogFieldList *field_li if (begin_paren) { char *end_paren = strchr(symbol, ')'); if (end_paren) { - Debug("log-agg", "Aggregate symbol: %s", symbol); + Dbg(dbg_ctl_log_agg, "Aggregate symbol: %s", symbol); *begin_paren = '\0'; *end_paren = '\0'; name = begin_paren + 1; sym = symbol; - Debug("log-agg", "Aggregate = %s, field = %s", sym, name); + Dbg(dbg_ctl_log_agg, "Aggregate = %s, field = %s", sym, name); aggregate = LogField::valid_aggregate_name(sym); if (aggregate == LogField::NO_AGGREGATE) { Note("Invalid aggregate specification: %s", sym); @@ -461,7 +468,7 @@ LogFormat::parse_symbol_string(const char *symbol_string, LogFieldList *field_li field_list->add(new_f, false); field_count++; *contains_aggregates = true; - Debug("log-agg", "Aggregate field %s(%s) added", sym, name); + Dbg(dbg_ctl_log_agg, "Aggregate field %s(%s) added", sym, name); } } } else { @@ -474,7 +481,7 @@ LogFormat::parse_symbol_string(const char *symbol_string, LogFieldList *field_li // Now check for a container field, which starts with '{' // else if (*symbol == '{') { - Debug("log-format", "Container symbol: %s", symbol); + Dbg(dbg_ctl_log_format, "Container symbol: %s", symbol); f = nullptr; char *name_end = strchr(symbol, '}'); if (name_end != nullptr) { @@ -482,7 +489,7 @@ LogFormat::parse_symbol_string(const char *symbol_string, LogFieldList *field_li *name_end = 0; // changes '}' to '\0' sym = name_end + 1; // start of container symbol LogSlice slice(sym); - Debug("log-format", "Name = %s, symbol = %s", name, sym); + Dbg(dbg_ctl_log_format, "Name = %s, symbol = %s", name, sym); container = LogField::valid_container_name(sym); if (container == LogField::NO_CONTAINER) { Note("Invalid container specification: %s", sym); @@ -491,11 +498,11 @@ LogFormat::parse_symbol_string(const char *symbol_string, LogFieldList *field_li ink_assert(f != nullptr); if (slice.m_enable) { f->m_slice = slice; - Debug("log-slice", "symbol = %s, [%d:%d]", sym, f->m_slice.m_start, f->m_slice.m_end); + Dbg(dbg_ctl_log_slice, "symbol = %s, [%d:%d]", sym, f->m_slice.m_start, f->m_slice.m_end); } field_list->add(f, false); field_count++; - Debug("log-format", "Container field {%s}%s added", name, sym); + Dbg(dbg_ctl_log_format, "Container field {%s}%s added", name, sym); } } else { Note("Invalid container field specification: no trailing " @@ -508,17 +515,17 @@ LogFormat::parse_symbol_string(const char *symbol_string, LogFieldList *field_li // else { LogSlice slice(symbol); - Debug("log-format", "Regular field symbol: %s", symbol); + Dbg(dbg_ctl_log_format, "Regular field symbol: %s", symbol); f = Log::global_field_list.find_by_symbol(symbol); if (f != nullptr) { LogField *cpy = new LogField(*f); if (slice.m_enable) { cpy->m_slice = slice; - Debug("log-slice", "symbol = %s, [%d:%d]", symbol, cpy->m_slice.m_start, cpy->m_slice.m_end); + 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_count++; - Debug("log-format", "Regular field %s added", symbol); + 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.", @@ -727,7 +734,7 @@ LogFormat::parse_format_string(const char *format_str, char **printf_str, char * (*fields_str)[fields_pos] = '\0'; (*printf_str)[printf_pos] = '\0'; - Debug("log-format", "LogFormat::parse_format_string: field_count=%d, \"%s\", \"%s\"", field_count, *fields_str, *printf_str); + Dbg(dbg_ctl_log_format, "LogFormat::parse_format_string: field_count=%d, \"%s\", \"%s\"", field_count, *fields_str, *printf_str); return field_count; } diff --git a/src/proxy/logging/LogObject.cc b/src/proxy/logging/LogObject.cc index a21bb7b4d5..33df54dc13 100644 --- a/src/proxy/logging/LogObject.cc +++ b/src/proxy/logging/LogObject.cc @@ -42,18 +42,29 @@ #include <thread> #include <map> -static bool +namespace +{ +DbgCtl dbg_ctl_log_logbuffer{"log-logbuffer"}; +DbgCtl dbg_ctl_log_config{"log-config"}; +DbgCtl dbg_ctl_log{"log"}; +DbgCtl dbg_ctl_log_agg{"log-agg"}; +DbgCtl dbg_ctl_log_buffer{"log-buffer"}; +DbgCtl dbg_ctl_log_config_transfer{"log-config-transfer"}; + +bool should_roll_on_time(Log::RollingEnabledValues roll) { return roll == Log::ROLL_ON_TIME_ONLY || roll == Log::ROLL_ON_TIME_OR_SIZE; } -static bool +bool should_roll_on_size(Log::RollingEnabledValues roll) { return roll == Log::ROLL_ON_SIZE_ONLY || roll == Log::ROLL_ON_TIME_OR_SIZE; } +} // end anonymous namespace + size_t LogBufferManager::preproc_buffers(LogBufferSink *sink) { @@ -81,7 +92,7 @@ LogBufferManager::preproc_buffers(LogBufferSink *sink) prepared++; } - Debug("log-logbuffer", "prepared %d buffers", prepared); + Dbg(dbg_ctl_log_logbuffer, "prepared %d buffers", prepared); return prepared; } @@ -137,12 +148,12 @@ LogObject::LogObject(LogConfig *cfg, const LogFormat *format, const char *log_di } _setup_rolling(cfg, rolling_enabled, rolling_interval_sec, rolling_offset_hr, rolling_size_mb); - Debug("log-config", "exiting LogObject constructor, filename=%s this=%p fast=%d", m_filename, this, m_fast); + Dbg(dbg_ctl_log_config, "exiting LogObject constructor, filename=%s this=%p fast=%d", m_filename, this, m_fast); } LogObject::~LogObject() { - Debug("log-config", "entering LogObject destructor, this=%p", this); + Dbg(dbg_ctl_log_config, "entering LogObject destructor, this=%p", this); preproc_buffers(); ats_free(m_basename); @@ -383,7 +394,7 @@ LogObject::_checkout_write(size_t *write_offset, size_t bytes_needed) ink_atomic_increment(&buffer->m_references, FREELIST_VERSION(old_h) - 1); int idx = m_buffer_manager_idx++ % m_flush_threads; - Debug("log-logbuffer", "adding buffer %d to flush list after checkout", buffer->get_id()); + Dbg(dbg_ctl_log_logbuffer, "adding buffer %d to flush list after checkout", buffer->get_id()); m_buffer_manager[idx].add_to_flush_queue(buffer); Log::preproc_notify[idx].signal(); buffer = nullptr; @@ -496,12 +507,12 @@ private: period = 1; } eventProcessor.schedule_every(this, period * HRTIME_SECOND, ET_CALL); - Debug("log-config", "thread local buffer manager init: %d wakeup period", period); + Dbg(dbg_ctl_log_config, "thread local buffer manager init: %d wakeup period", period); } ~ThreadLocalLogBufferManager() override { - Debug("log-config", "thread local buffer manager destructor"); + Dbg(dbg_ctl_log_config, "thread local buffer manager destructor"); // only the LogBuffer objects are owned by this for (auto [o, b] : current_buffers) { // ideally we flush these here but there are shutdown order issues so if the @@ -562,7 +573,7 @@ void LogObject::flush_buffer(LogBuffer *buffer) { int idx = m_buffer_manager_idx++ % m_flush_threads; - Debug("log-logbuffer", "adding buffer %d to flush list after checkout", buffer->get_id()); + Dbg(dbg_ctl_log_logbuffer, "adding buffer %d to flush list after checkout", buffer->get_id()); m_buffer_manager[idx].add_to_flush_queue(buffer); Log::preproc_notify[idx].signal(); } @@ -578,7 +589,7 @@ LogObject::log(LogAccess *lad, std::string_view text_entry) // likewise, send data to a remote client even if local space is exhausted // (if there is a remote client, m_logFile will be NULL if (Log::config->logging_space_exhausted && !writes_to_pipe() && m_logFile) { - Debug("log", "logging space exhausted, can't write to:%s, drop this entry", m_logFile->get_name()); + Dbg(dbg_ctl_log, "logging space exhausted, can't write to:%s, drop this entry", m_logFile->get_name()); return Log::FULL; } // this verification must be done here in order to avoid 'dead' LogBuffers @@ -589,12 +600,12 @@ LogObject::log(LogAccess *lad, std::string_view text_entry) } if (lad && m_filter_list.toss_this_entry(lad)) { - Debug("log", "entry filtered, skipping ..."); + Dbg(dbg_ctl_log, "entry filtered, skipping ..."); return Log::SKIP; } if (lad && m_filter_list.wipe_this_entry(lad)) { - Debug("log", "entry wiped, ..."); + Dbg(dbg_ctl_log, "entry wiped, ..."); } if (lad && m_format->is_aggregate()) { @@ -622,10 +633,10 @@ LogObject::log(LogAccess *lad, std::string_view text_entry) } if (time_now < m_format->m_interval_next) { - Debug("log-agg", - "Time now = %ld, next agg = %ld; not time " - "for aggregate entry", - time_now, m_format->m_interval_next); + Dbg(dbg_ctl_log_agg, + "Time now = %ld, next agg = %ld; not time " + "for aggregate entry", + time_now, m_format->m_interval_next); return Log::AGGR; } // can easily compute bytes_needed because all fields are INTs @@ -638,7 +649,7 @@ LogObject::log(LogAccess *lad, std::string_view text_entry) } if (bytes_needed == 0) { - Debug("log-buffer", "Nothing to log, bytes_needed = 0"); + Dbg(dbg_ctl_log_buffer, "Nothing to log, bytes_needed = 0"); return Log::SKIP; } @@ -668,7 +679,7 @@ LogObject::log(LogAccess *lad, std::string_view text_entry) bytes_used = m_format->m_field_list.marshal_agg(&(*buffer)[offset]); ink_assert(bytes_needed >= bytes_used); m_format->m_interval_next += m_format->m_interval_sec; - Debug("log-agg", "Aggregate entry created; next time is %ld", m_format->m_interval_next); + Dbg(dbg_ctl_log_agg, "Aggregate entry created; next time is %ld", m_format->m_interval_next); } else if (lad) { bytes_used = m_format->m_field_list.marshal(lad, &(*buffer)[offset]); ink_assert(bytes_needed >= bytes_used); @@ -949,10 +960,10 @@ LogObjectManager::_manage_object(LogObject *log_object, bool is_api_object, int ink_release_assert(retVal == NO_FILENAME_CONFLICTS); - Debug("log", - "LogObjectManager managing object %s (%s) " - "[signature = %" PRIu64 ", address = %p]", - log_object->get_base_filename(), log_object->get_full_filename(), log_object->get_signature(), log_object); + Dbg(dbg_ctl_log, + "LogObjectManager managing object %s (%s) " + "[signature = %" PRIu64 ", address = %p]", + log_object->get_base_filename(), log_object->get_full_filename(), log_object->get_signature(), log_object); if (log_object->has_alternate_name()) { Warning("The full path for the (%s) LogObject " @@ -1002,13 +1013,13 @@ LogObjectManager::_solve_filename_conflicts(LogObject *log_object, int maxConfli if (got_sig && signature == obj_sig) { conflicts = false; } - Debug("log", - "LogObjectManager::_solve_filename_conflicts\n" - "\tfilename = %s\n" - "\tmeta file signature = %" PRIu64 "\n" - "\tlog object signature = %" PRIu64 "\n" - "\tconflicts = %d", - filename, signature, obj_sig, conflicts); + Dbg(dbg_ctl_log, + "LogObjectManager::_solve_filename_conflicts\n" + "\tfilename = %s\n" + "\tmeta file signature = %" PRIu64 "\n" + "\tlog object signature = %" PRIu64 "\n" + "\tconflicts = %d", + filename, signature, obj_sig, conflicts); } if (conflicts) { @@ -1220,17 +1231,17 @@ LogObjectManager::open_local_pipes() void LogObjectManager::transfer_objects(LogObjectManager &old_mgr) { - Debug("log-config-transfer", "transferring objects from LogObjectManager %p, to %p", &old_mgr, this); + Dbg(dbg_ctl_log_config_transfer, "transferring objects from LogObjectManager %p, to %p", &old_mgr, this); - if (is_debug_tag_set("log-config-transfer")) { - Debug("log-config-transfer", "TRANSFER OBJECTS: list of old objects"); + if (dbg_ctl_log_config_transfer.on()) { + Dbg(dbg_ctl_log_config_transfer, "TRANSFER OBJECTS: list of old objects"); for (auto &_object : old_mgr._objects) { - Debug("log-config-transfer", "%s", _object->get_original_filename()); + Dbg(dbg_ctl_log_config_transfer, "%s", _object->get_original_filename()); } - Debug("log-config-transfer", "TRANSFER OBJECTS : list of new objects"); + Dbg(dbg_ctl_log_config_transfer, "TRANSFER OBJECTS : list of new objects"); for (unsigned i = 0; i < this->_objects.size(); i++) { - Debug("log-config-transfer", "%s", _objects[i]->get_original_filename()); + Dbg(dbg_ctl_log_config_transfer, "%s", _objects[i]->get_original_filename()); } } @@ -1242,7 +1253,7 @@ LogObjectManager::transfer_objects(LogObjectManager &old_mgr) for (auto old_obj : old_mgr._objects) { LogObject *new_obj; - Debug("log-config-transfer", "examining existing object %s", old_obj->get_base_filename()); + Dbg(dbg_ctl_log_config_transfer, "examining existing object %s", old_obj->get_base_filename()); // See if any of the new objects is just a copy of an old one. If so, transfer the // old one to the new manager and delete the new one. We don't use Vec::in here because @@ -1250,11 +1261,11 @@ LogObjectManager::transfer_objects(LogObjectManager &old_mgr) for (unsigned j = 0; j < _objects.size(); j++) { new_obj = _objects[j]; - Debug("log-config-transfer", "comparing existing object %s to new object %s", old_obj->get_base_filename(), - new_obj->get_base_filename()); + Dbg(dbg_ctl_log_config_transfer, "comparing existing object %s to new object %s", old_obj->get_base_filename(), + new_obj->get_base_filename()); if (*new_obj == *old_obj) { - Debug("log-config-transfer", "keeping existing object %s", old_obj->get_base_filename()); + Dbg(dbg_ctl_log_config_transfer, "keeping existing object %s", old_obj->get_base_filename()); old_obj->refcount_inc(); this->_objects[j] = old_obj; @@ -1267,8 +1278,8 @@ LogObjectManager::transfer_objects(LogObjectManager &old_mgr) } } - if (is_debug_tag_set("log-config-transfer")) { - Debug("log-config-transfer", "Log Object List after transfer:"); + if (dbg_ctl_log_config_transfer.on()) { + Dbg(dbg_ctl_log_config_transfer, "Log Object List after transfer:"); display(); } } diff --git a/src/proxy/logging/YamlLogConfig.cc b/src/proxy/logging/YamlLogConfig.cc index f673a9e40e..e554e8f966 100644 --- a/src/proxy/logging/YamlLogConfig.cc +++ b/src/proxy/logging/YamlLogConfig.cc @@ -31,6 +31,13 @@ #include <algorithm> #include <memory> +namespace +{ +DbgCtl dbg_ctl_log{"log"}; +DbgCtl dbg_ctl_xml{"xml"}; + +} // end anonymous namespace + bool YamlLogConfig::parse(const char *cfgFilename) { @@ -71,7 +78,7 @@ YamlLogConfig::loadLogConfig(const char *cfgFilename) if (fmt->valid()) { cfg->format_list.add(fmt, false); - if (is_debug_tag_set("log")) { + if (dbg_ctl_log.on()) { printf("The following format was added to the global format list\n"); fmt->display(stdout); } @@ -88,7 +95,7 @@ YamlLogConfig::loadLogConfig(const char *cfgFilename) if (filter) { cfg->filter_list.add(filter, false); - if (is_debug_tag_set("xml")) { + if (dbg_ctl_xml.on()) { printf("The following filter was added to the global filter list\n"); filter->display(stdout); } diff --git a/src/proxy/logging/unit-tests/benchmark_LogObject.cc b/src/proxy/logging/unit-tests/benchmark_LogObject.cc index 3762d75fe2..e42f583907 100644 --- a/src/proxy/logging/unit-tests/benchmark_LogObject.cc +++ b/src/proxy/logging/unit-tests/benchmark_LogObject.cc @@ -99,7 +99,7 @@ TEST_CASE("LogObject", "[proxy/logging]") diags()->set_std_output(StdStream::STDOUT, bind_stdout); diags()->set_std_output(StdStream::STDERR, bind_stderr); - if (is_debug_tag_set("diags")) { + if (DbgCtl dc{"diags"}; dc.on()) { diags()->dump(); } Layout::create("/opt/ats");
