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 f3fdef648c5d9f6f03e3969c808286074025dc99 Author: Walt Karas <[email protected]> AuthorDate: Sun May 5 20:20:44 2024 -0400 Remove obsolete debug output calls in 44 source files. (#11321) In the src/iocore tree. (cherry picked from commit 1548746e78680b71790538bd9cdaa0bcc9f17c7c) --- include/iocore/net/ConnectionTracker.h | 6 +- src/iocore/cache/Cache.cc | 2 +- src/iocore/cache/HttpTransactCache.cc | 120 +++++++++++++------------ src/iocore/hostdb/HostDB.cc | 2 +- src/iocore/io_uring/io_uring.cc | 10 ++- src/iocore/net/ALPNSupport.cc | 8 +- src/iocore/net/Connection.cc | 21 +++-- src/iocore/net/ConnectionTracker.cc | 14 +-- src/iocore/net/NetHandler.cc | 88 +++++++++--------- src/iocore/net/NetVCTest.cc | 16 ++-- src/iocore/net/NetVConnection.cc | 8 +- src/iocore/net/OCSPStapling.cc | 68 +++++++------- src/iocore/net/P_NetVCTest.h | 2 +- src/iocore/net/ProxyProtocol.cc | 40 +++++---- src/iocore/net/QUICMultiCertConfigLoader.cc | 3 - src/iocore/net/QUICNetProcessor.cc | 23 +++-- src/iocore/net/QUICNetVConnection.cc | 13 ++- src/iocore/net/QUICNextProtocolAccept.cc | 10 ++- src/iocore/net/QUICPacketHandler.cc | 23 +++-- src/iocore/net/ReadWriteEventIO.cc | 8 +- src/iocore/net/SNIActionPerformer.cc | 14 ++- src/iocore/net/SSLCertLookup.cc | 24 +++-- src/iocore/net/SSLClientUtils.cc | 21 +++-- src/iocore/net/SSLConfig.cc | 37 +++++--- src/iocore/net/SSLDynlock.cc | 15 +++- src/iocore/net/SSLNetVConnection.cc | 6 +- src/iocore/net/SSLNextProtocolAccept.cc | 12 ++- src/iocore/net/SSLNextProtocolSet.cc | 8 +- src/iocore/net/SSLSNIConfig.cc | 15 ++-- src/iocore/net/SSLSessionCache.cc | 82 ++++++++--------- src/iocore/net/SSLStats.cc | 10 ++- src/iocore/net/TLSBasicSupport.cc | 8 +- src/iocore/net/TLSCertSwitchSupport.cc | 15 +++- src/iocore/net/TLSEarlyDataSupport.cc | 15 ++-- src/iocore/net/TLSKeyLogger.cc | 12 ++- src/iocore/net/TLSSessionResumptionSupport.cc | 16 ++-- src/iocore/net/UDPEventIO.cc | 8 +- src/iocore/net/UnixConnection.cc | 20 +++-- src/iocore/net/UnixNetAccept.cc | 8 +- src/iocore/net/UnixNetVConnection.cc | 44 +++++---- src/iocore/net/quic/QUICGlobals.cc | 8 +- src/iocore/net/quic/QUICTransportParameters.cc | 23 ++--- src/iocore/utils/OneWayTunnel.cc | 8 +- src/proxy/http/HttpSM.cc | 2 +- 44 files changed, 558 insertions(+), 358 deletions(-) diff --git a/include/iocore/net/ConnectionTracker.h b/include/iocore/net/ConnectionTracker.h index 5d0f07b631..d272b78f8d 100644 --- a/include/iocore/net/ConnectionTracker.h +++ b/include/iocore/net/ConnectionTracker.h @@ -195,7 +195,7 @@ public: * @param addr IP address of the upstream. * @param debug_tag Tag to use for the debug message. If no debug message should be generated set this to @c nullptr. */ - void Warn_Blocked(int max_connections, int64_t id, int count, const sockaddr *addr, const char *debug_tag = nullptr); + void Warn_Blocked(int max_connections, int64_t id, int count, const sockaddr *addr, DbgCtl *debug_tag = nullptr); }; /** Get or create the @c Group for the specified inbound session properties. @@ -238,8 +238,8 @@ public: */ static void config_init(GlobalConfig *global, TxnConfig *txn, RecConfigUpdateCb const &config_cb); - /// Tag used for debugging output. - static constexpr char const *const DEBUG_TAG{"conn_track"}; + /// Debug control used for debugging output. + static inline DbgCtl dbg_ctl{"conn_track"}; /** Convert a string to a match type. * diff --git a/src/iocore/cache/Cache.cc b/src/iocore/cache/Cache.cc index e17e34a75b..22fc3a7e7b 100644 --- a/src/iocore/cache/Cache.cc +++ b/src/iocore/cache/Cache.cc @@ -1938,7 +1938,7 @@ ink_cache_init(ts::ModuleVersion v) REC_ReadConfigInteger(cacheProcessor.wait_for_cache, "proxy.config.http.wait_for_cache"); REC_EstablishStaticConfigInt32(cache_config_persist_bad_disks, "proxy.config.cache.persist_bad_disks"); - Debug("cache_init", "proxy.config.cache.persist_bad_disks = %d", cache_config_persist_bad_disks); + Dbg(dbg_ctl_cache_init, "proxy.config.cache.persist_bad_disks = %d", cache_config_persist_bad_disks); if (cache_config_persist_bad_disks) { std::filesystem::path localstatedir{Layout::get()->localstatedir}; std::filesystem::path bad_disks_path{localstatedir / ts::filename::BAD_DISKS}; diff --git a/src/iocore/cache/HttpTransactCache.cc b/src/iocore/cache/HttpTransactCache.cc index 02190a2c22..d6246e76f4 100644 --- a/src/iocore/cache/HttpTransactCache.cc +++ b/src/iocore/cache/HttpTransactCache.cc @@ -36,12 +36,20 @@ #include "tscore/InkErrno.h" #include "tscore/ink_time.h" +namespace +{ +DbgCtl dbg_ctl_http_match{"http_match"}; +DbgCtl dbg_ctl_http_seq{"http_seq"}; +DbgCtl dbg_ctl_http_alts{"http_alts"}; +DbgCtl dbg_ctl_http_alternate{"http_alternate"}; +DbgCtl dbg_ctl_http_age{"http_age"}; + /** Find the pointer and length of an etag, after stripping off any leading "W/" prefix, and surrounding double quotes. */ -inline static const char * +inline const char * find_etag(const char *raw_tag_field, int raw_tag_field_len, int *length) { const char *quote; @@ -72,7 +80,7 @@ find_etag(const char *raw_tag_field, int raw_tag_field_len, int *length) string field_to_match, using strong rules. */ -inline static bool +inline bool do_strings_match_strongly(const char *raw_tag_field, int raw_tag_field_len, const char *comma_sep_tag_list, int comma_sep_tag_list_len) { @@ -112,7 +120,7 @@ do_strings_match_strongly(const char *raw_tag_field, int raw_tag_field_len, cons string field_to_match, using weak rules. */ -inline static bool +inline bool do_strings_match_weakly(const char *raw_tag_field, int raw_tag_field_len, const char *comma_sep_tag_list, int comma_sep_tag_list_len) { @@ -143,18 +151,20 @@ do_strings_match_weakly(const char *raw_tag_field, int raw_tag_field_len, const return false; } -inline static bool +inline bool is_asterisk(char *s) { return ((s[0] == '*') && (s[1] == NUL)); } -inline static bool +inline bool is_empty(char *s) { return (s[0] == NUL); } +} // end anonymous namespace + /** Given a set of alternates, select the best match. @@ -182,9 +192,9 @@ HttpTransactCache::SelectFromAlternates(CacheHTTPInfoVector *cache_vector, HTTPH return -1; } - Debug("http_match", "[SelectFromAlternates] # alternates = %d", alt_count); - Debug("http_seq", "[SelectFromAlternates] %d alternates for this cached doc", alt_count); - if (is_debug_tag_set("http_alts")) { + Dbg(dbg_ctl_http_match, "[SelectFromAlternates] # alternates = %d", alt_count); + Dbg(dbg_ctl_http_seq, "[SelectFromAlternates] %d alternates for this cached doc", alt_count); + if (dbg_ctl_http_alts.on()) { fprintf(stderr, "[alts] There are %d alternates for this request header.\n", alt_count); } @@ -220,7 +230,7 @@ HttpTransactCache::SelectFromAlternates(CacheHTTPInfoVector *cache_vector, HTTPH current_age = static_cast<time_t>(0); } - if (is_debug_tag_set("http_alts")) { + if (dbg_ctl_http_alts.on()) { fprintf(stderr, "[alts] ---- alternate #%d (Q = %g) has these request/response hdrs:\n", i + 1, Q); char b[4096]; int used, tmp, offset; @@ -254,8 +264,8 @@ HttpTransactCache::SelectFromAlternates(CacheHTTPInfoVector *cache_vector, HTTPH } } } - Debug("http_seq", "[SelectFromAlternates] Chosen alternate # %d", best_index); - if (is_debug_tag_set("http_alts")) { + Dbg(dbg_ctl_http_seq, "[SelectFromAlternates] Chosen alternate # %d", best_index); + if (dbg_ctl_http_alts.on()) { fprintf(stderr, "[alts] and the winner is alternate number %d\n", best_index); } @@ -347,7 +357,7 @@ HttpTransactCache::calculate_quality_of_match(const HttpConfigAccessor *http_con // absence in both requests counts as exact match if (accept_field == nullptr && cached_accept_field == nullptr) { - Debug("http_alternate", "Exact match for ACCEPT CHARSET (not in request nor cache)"); + Dbg(dbg_ctl_http_alternate, "Exact match for ACCEPT CHARSET (not in request nor cache)"); q[1] = 1.001; // slightly higher weight to this guy } else { q[1] = calculate_quality_of_accept_charset_match(accept_field, content_field, cached_accept_field); @@ -366,7 +376,7 @@ HttpTransactCache::calculate_quality_of_match(const HttpConfigAccessor *http_con // absence in both requests counts as exact match if (accept_field == nullptr && cached_accept_field == nullptr) { - Debug("http_alternate", "Exact match for ACCEPT ENCODING (not in request nor cache)"); + Dbg(dbg_ctl_http_alternate, "Exact match for ACCEPT ENCODING (not in request nor cache)"); q[2] = 1.001; // slightly higher weight to this guy } else { q[2] = calculate_quality_of_accept_encoding_match(accept_field, content_field, cached_accept_field); @@ -385,7 +395,7 @@ HttpTransactCache::calculate_quality_of_match(const HttpConfigAccessor *http_con // absence in both requests counts as exact match if (accept_field == nullptr && cached_accept_field == nullptr) { - Debug("http_alternate", "Exact match for ACCEPT LANGUAGE (not in request nor cache)"); + Dbg(dbg_ctl_http_alternate, "Exact match for ACCEPT LANGUAGE (not in request nor cache)"); q[3] = 1.001; // slightly higher weight to this guy } else { q[3] = calculate_quality_of_accept_language_match(accept_field, content_field, cached_accept_field); @@ -398,24 +408,24 @@ HttpTransactCache::calculate_quality_of_match(const HttpConfigAccessor *http_con // final quality is minimum Q, or -1, if some match failed // Q = ((q[0] < 0) || (q[1] < 0) || (q[2] < 0) || (q[3] < 0)) ? -1.0 : q[0] * q[1] * q[2] * q[3]; - Debug("http_match", " CalcQualityOfMatch: Accept match = %g", q[0]); - Debug("http_seq", " CalcQualityOfMatch: Accept match = %g", q[0]); - Debug("http_alternate", "Content-Type and Accept %f", q[0]); + Dbg(dbg_ctl_http_match, " CalcQualityOfMatch: Accept match = %g", q[0]); + Dbg(dbg_ctl_http_seq, " CalcQualityOfMatch: Accept match = %g", q[0]); + Dbg(dbg_ctl_http_alternate, "Content-Type and Accept %f", q[0]); - Debug("http_match", " CalcQualityOfMatch: AcceptCharset match = %g", q[1]); - Debug("http_seq", " CalcQualityOfMatch: AcceptCharset match = %g", q[1]); - Debug("http_alternate", "Content-Type and Accept-Charset %f", q[1]); + Dbg(dbg_ctl_http_match, " CalcQualityOfMatch: AcceptCharset match = %g", q[1]); + Dbg(dbg_ctl_http_seq, " CalcQualityOfMatch: AcceptCharset match = %g", q[1]); + Dbg(dbg_ctl_http_alternate, "Content-Type and Accept-Charset %f", q[1]); - Debug("http_match", " CalcQualityOfMatch: AcceptEncoding match = %g", q[2]); - Debug("http_seq", " CalcQualityOfMatch: AcceptEncoding match = %g", q[2]); - Debug("http_alternate", "Content-Encoding and Accept-Encoding %f", q[2]); + Dbg(dbg_ctl_http_match, " CalcQualityOfMatch: AcceptEncoding match = %g", q[2]); + Dbg(dbg_ctl_http_seq, " CalcQualityOfMatch: AcceptEncoding match = %g", q[2]); + Dbg(dbg_ctl_http_alternate, "Content-Encoding and Accept-Encoding %f", q[2]); - Debug("http_match", " CalcQualityOfMatch: AcceptLanguage match = %g", q[3]); - Debug("http_seq", " CalcQualityOfMatch: AcceptLanguage match = %g", q[3]); - Debug("http_alternate", "Content-Language and Accept-Language %f", q[3]); + Dbg(dbg_ctl_http_match, " CalcQualityOfMatch: AcceptLanguage match = %g", q[3]); + Dbg(dbg_ctl_http_seq, " CalcQualityOfMatch: AcceptLanguage match = %g", q[3]); + Dbg(dbg_ctl_http_alternate, "Content-Language and Accept-Language %f", q[3]); - Debug("http_alternate", "Mult's Quality Factor: %f", Q); - Debug("http_alternate", "----------End of Alternate----------"); + Dbg(dbg_ctl_http_alternate, "Mult's Quality Factor: %f", Q); + Dbg(dbg_ctl_http_alternate, "----------End of Alternate----------"); int force_alt = 0; @@ -463,10 +473,10 @@ HttpTransactCache::calculate_quality_of_match(const HttpConfigAccessor *http_con Q = -1.0; } - Debug("http_match", " CalcQualityOfMatch: CalcVariability says variability = %d", (variability != VARIABILITY_NONE)); - Debug("http_seq", " CalcQualityOfMatch: CalcVariability says variability = %d", (variability != VARIABILITY_NONE)); - Debug("http_match", " CalcQualityOfMatch: Returning final Q = %g", Q); - Debug("http_seq", " CalcQualityOfMatch: Returning final Q = %g", Q); + Dbg(dbg_ctl_http_match, " CalcQualityOfMatch: CalcVariability says variability = %d", (variability != VARIABILITY_NONE)); + Dbg(dbg_ctl_http_seq, " CalcQualityOfMatch: CalcVariability says variability = %d", (variability != VARIABILITY_NONE)); + Dbg(dbg_ctl_http_match, " CalcQualityOfMatch: Returning final Q = %g", Q); + Dbg(dbg_ctl_http_seq, " CalcQualityOfMatch: Returning final Q = %g", Q); } return Q; @@ -550,7 +560,7 @@ HttpTransactCache::calculate_quality_of_accept_match(MIMEField *accept_field, MI char a_type[32], a_subtype[32]; HttpCompat::parse_mime_type(a_param->str, a_type, a_subtype, sizeof(a_type), sizeof(a_subtype)); - Debug("http_match", "matching Content-type; '%s/%s' with Accept value '%s/%s'\n", c_type, c_subtype, a_type, a_subtype); + Dbg(dbg_ctl_http_match, "matching Content-type; '%s/%s' with Accept value '%s/%s'\n", c_type, c_subtype, a_type, a_subtype); bool wildcard_found = true; // Only do wildcard checks if the content type is not image/webp @@ -646,17 +656,17 @@ HttpTransactCache::calculate_document_age(ink_time_t request_time, ink_time_t re current_age = corrected_initial_age + resident_time; } - Debug("http_age", "[calculate_document_age] age_value: %" PRId64, (int64_t)age_value); - Debug("http_age", "[calculate_document_age] date_value: %" PRId64, (int64_t)date_value); - Debug("http_age", "[calculate_document_age] response_time: %" PRId64, (int64_t)response_time); - Debug("http_age", "[calculate_document_age] now: %" PRId64, (int64_t)now); - Debug("http_age", "[calculate_document_age] now (fixed): %" PRId64, (int64_t)now_value); - Debug("http_age", "[calculate_document_age] apparent_age: %" PRId64, (int64_t)apparent_age); - Debug("http_age", "[calculate_document_age] corrected_received_age: %" PRId64, (int64_t)corrected_received_age); - Debug("http_age", "[calculate_document_age] response_delay: %" PRId64, (int64_t)response_delay); - Debug("http_age", "[calculate_document_age] corrected_initial_age: %" PRId64, (int64_t)corrected_initial_age); - Debug("http_age", "[calculate_document_age] resident_time: %" PRId64, (int64_t)resident_time); - Debug("http_age", "[calculate_document_age] current_age: %" PRId64, (int64_t)current_age); + Dbg(dbg_ctl_http_age, "[calculate_document_age] age_value: %" PRId64, (int64_t)age_value); + Dbg(dbg_ctl_http_age, "[calculate_document_age] date_value: %" PRId64, (int64_t)date_value); + Dbg(dbg_ctl_http_age, "[calculate_document_age] response_time: %" PRId64, (int64_t)response_time); + Dbg(dbg_ctl_http_age, "[calculate_document_age] now: %" PRId64, (int64_t)now); + Dbg(dbg_ctl_http_age, "[calculate_document_age] now (fixed): %" PRId64, (int64_t)now_value); + Dbg(dbg_ctl_http_age, "[calculate_document_age] apparent_age: %" PRId64, (int64_t)apparent_age); + Dbg(dbg_ctl_http_age, "[calculate_document_age] corrected_received_age: %" PRId64, (int64_t)corrected_received_age); + Dbg(dbg_ctl_http_age, "[calculate_document_age] response_delay: %" PRId64, (int64_t)response_delay); + Dbg(dbg_ctl_http_age, "[calculate_document_age] corrected_initial_age: %" PRId64, (int64_t)corrected_initial_age); + Dbg(dbg_ctl_http_age, "[calculate_document_age] resident_time: %" PRId64, (int64_t)resident_time); + Dbg(dbg_ctl_http_age, "[calculate_document_age] current_age: %" PRId64, (int64_t)current_age); return current_age; } @@ -705,7 +715,7 @@ HttpTransactCache::calculate_quality_of_accept_charset_match(MIMEField *accept_f a_raw = accept_field->value_get(&a_raw_len); ca_raw = cached_accept_field->value_get(&ca_raw_len); if (a_raw && ca_raw && a_raw_len == ca_raw_len && !strncmp(a_raw, ca_raw, a_raw_len)) { - Debug("http_alternate", "Exact match for ACCEPT CHARSET"); + Dbg(dbg_ctl_http_alternate, "Exact match for ACCEPT CHARSET"); return static_cast<float>(1.001); // slightly higher weight to this guy } } @@ -917,7 +927,7 @@ HttpTransactCache::calculate_quality_of_accept_encoding_match(MIMEField *accept_ a_raw = accept_field->value_get(&a_raw_len); ca_raw = cached_accept_field->value_get(&ca_raw_len); if (a_raw && ca_raw && a_raw_len == ca_raw_len && !strncmp(a_raw, ca_raw, a_raw_len)) { - Debug("http_alternate", "Exact match for ACCEPT ENCODING"); + Dbg(dbg_ctl_http_alternate, "Exact match for ACCEPT ENCODING"); return static_cast<float>(1.001); // slightly higher weight to this guy } } @@ -928,8 +938,8 @@ HttpTransactCache::calculate_quality_of_accept_encoding_match(MIMEField *accept_ } // if no Content-Encoding, treat as "identity" // if (!content_field) { - Debug("http_match", "[calculate_quality_accept_encoding_match]: " - "response hdr does not have content-encoding."); + Dbg(dbg_ctl_http_match, "[calculate_quality_accept_encoding_match]: " + "response hdr does not have content-encoding."); is_identity_encoding = true; } else { // TODO: Should we check the return value (count) here? @@ -1143,7 +1153,7 @@ HttpTransactCache::calculate_quality_of_accept_language_match(MIMEField *accept_ a_raw = accept_field->value_get(&a_raw_len); ca_raw = cached_accept_field->value_get(&ca_raw_len); if (a_raw && ca_raw && a_raw_len == ca_raw_len && !strncmp(a_raw, ca_raw, a_raw_len)) { - Debug("http_alternate", "Exact match for ACCEPT LANGUAGE"); + Dbg(dbg_ctl_http_alternate, "Exact match for ACCEPT LANGUAGE"); return static_cast<float>(1.001); // slightly higher weight to this guy } } @@ -1159,8 +1169,8 @@ HttpTransactCache::calculate_quality_of_accept_language_match(MIMEField *accept_ if (match_accept_content_language("identity", accept_field, &wildcard_present, &wildcard_q, &q, &a_range_length)) { goto language_wildcard; } - Debug("http_match", "[calculate_quality_accept_language_match]: " - "response hdr does not have content-language."); + Dbg(dbg_ctl_http_match, "[calculate_quality_accept_language_match]: " + "response hdr does not have content-language."); return (1.0); } @@ -1213,8 +1223,8 @@ HttpTransactCache::CalcVariability(const HttpConfigAccessor *http_config_params, StrList vary_list; if (obj_origin_server_response->value_get_comma_list(MIME_FIELD_VARY, MIME_LEN_VARY, &vary_list) > 0) { - if (is_debug_tag_set("http_match") && vary_list.head) { - Debug("http_match", "Vary list of %d elements", vary_list.count); + if (dbg_ctl_http_match.on() && vary_list.head) { + DbgPrint(dbg_ctl_http_match, "Vary list of %d elements", vary_list.count); vary_list.dump(stderr); } @@ -1230,9 +1240,9 @@ HttpTransactCache::CalcVariability(const HttpConfigAccessor *http_config_params, // but currently we just treat it equivalent to a '*'. // ///////////////////////////////////////////////////////////// - Debug("http_match", "Vary: %s", field->str); + Dbg(dbg_ctl_http_match, "Vary: %s", field->str); if (((field->str[0] == '*') && (field->str[1] == NUL))) { - Debug("http_match", "Wildcard variability --- object not served from cache"); + Dbg(dbg_ctl_http_match, "Wildcard variability --- object not served from cache"); variability = VARIABILITY_ALL; break; } diff --git a/src/iocore/hostdb/HostDB.cc b/src/iocore/hostdb/HostDB.cc index e081961736..91d93671fb 100644 --- a/src/iocore/hostdb/HostDB.cc +++ b/src/iocore/hostdb/HostDB.cc @@ -1418,7 +1418,7 @@ HostDBRecord::select_best_http(ts_time now, ts_seconds fail_window, sockaddr con // Check and update RR if it's time - this always yields a valid target if there is one. if (now > ntime && rr_ctime.compare_exchange_strong(ctime, ntime)) { best_alive = best_any = this->select_next_rr(now, fail_window); - Debug("hostdb", "Round robin timed interval expired - index %d", this->index_of(best_alive)); + Dbg(dbg_ctl_hostdb, "Round robin timed interval expired - index %d", this->index_of(best_alive)); } else { // pick the current index, which may be down. best_any = &info[this->rr_idx()]; } diff --git a/src/iocore/io_uring/io_uring.cc b/src/iocore/io_uring/io_uring.cc index 326a46fd66..2815f494bb 100644 --- a/src/iocore/io_uring/io_uring.cc +++ b/src/iocore/io_uring/io_uring.cc @@ -37,6 +37,12 @@ using ts::Metrics; std::atomic<int> main_wq_fd; +namespace +{ +DbgCtl dbg_ctl_io_uring{"io_uring"}; + +} // end anonymous namespace + IOUringConfig IOUringContext::config; struct IOUringStatsBlock { @@ -78,12 +84,12 @@ IOUringContext::IOUringContext() int ret = io_uring_queue_init_params(config.queue_entries, &ring, &p); if (ret < 0) { char *err = strerror(-ret); - Debug("io_uring", "io_uring_queue_init_params failed: (%d) %s", -ret, err); + Dbg(dbg_ctl_io_uring, "io_uring_queue_init_params failed: (%d) %s", -ret, err); ring.ring_fd = -1; } else { /* no sharing for non-fixed either */ if (config.sq_poll_ms && !(p.features & IORING_FEAT_SQPOLL_NONFIXED)) { - Debug("io_uring", "No SQPOLL sharing with nonfixed"); + Dbg(dbg_ctl_io_uring, "No SQPOLL sharing with nonfixed"); } } diff --git a/src/iocore/net/ALPNSupport.cc b/src/iocore/net/ALPNSupport.cc index ea37cb4706..3ac2d5d836 100644 --- a/src/iocore/net/ALPNSupport.cc +++ b/src/iocore/net/ALPNSupport.cc @@ -27,6 +27,12 @@ int ALPNSupport::_ex_data_index = -1; +namespace +{ +DbgCtl dbg_ctl_ssl{"ssl"}; + +} // end anonymous namespace + void ALPNSupport::initialize() { @@ -103,7 +109,7 @@ ALPNSupport::select_next_protocol(SSL *ssl, const unsigned char **out, unsigned // SSL_select_next_proto chooses the first server-offered protocol that appears in the clients protocol set, ie. the // server selects the protocol. This is a n^2 search, so it's preferable to keep the protocol set short. if (SSL_select_next_proto(const_cast<unsigned char **>(out), outlen, npnptr, npnsize, in, inlen) == OPENSSL_NPN_NEGOTIATED) { - Debug("ssl", "selected ALPN protocol %.*s", (int)(*outlen), *out); + Dbg(dbg_ctl_ssl, "selected ALPN protocol %.*s", (int)(*outlen), *out); retval = SSL_TLSEXT_ERR_OK; } else { *out = nullptr; diff --git a/src/iocore/net/Connection.cc b/src/iocore/net/Connection.cc index ae3a70799b..2b77dfd169 100644 --- a/src/iocore/net/Connection.cc +++ b/src/iocore/net/Connection.cc @@ -43,6 +43,15 @@ #define FIRST_RANDOM_PORT 16000 #define LAST_RANDOM_PORT 32000 +namespace +{ +DbgCtl dbg_ctl_http_tproxy{"http_tproxy"}; +DbgCtl dbg_ctl_proxyprotocol{"proxyprotocol"}; +DbgCtl dbg_ctl_iocore_net_server{"iocore_net_server"}; +DbgCtl dbg_ctl_connection{"connection"}; + +} // end anonymous namespace + int get_listen_backlog() { @@ -82,10 +91,10 @@ Server::accept(Connection *c) return res; } c->fd = res; - if (is_debug_tag_set("iocore_net_server")) { + if (dbg_ctl_iocore_net_server.on()) { ip_port_text_buffer ipb1, ipb2; - Debug("iocore_net_server", "Connection accepted [Server]. %s -> %s", ats_ip_nptop(&c->addr, ipb2, sizeof(ipb2)), - ats_ip_nptop(&addr, ipb1, sizeof(ipb1))); + DbgPrint(dbg_ctl_iocore_net_server, "Connection accepted [Server]. %s -> %s", ats_ip_nptop(&c->addr, ipb2, sizeof(ipb2)), + ats_ip_nptop(&addr, ipb1, sizeof(ipb1))); } #ifdef SEND_BUF_SIZE @@ -250,7 +259,7 @@ Server::setup_fd_for_listen(bool non_blocking, const NetProcessor::AcceptOptions if (opt.f_inbound_transparent) { #if TS_USE_TPROXY - Debug("http_tproxy", "Listen port inbound transparency enabled."); + Dbg(dbg_ctl_http_tproxy, "Listen port inbound transparency enabled."); if (setsockopt_on(fd, SOL_IP, TS_IP_TRANSPARENT) < 0) { Fatal("[Server::listen] Unable to set transparent socket option [%d] %s\n", errno, strerror(errno)); } @@ -260,7 +269,7 @@ Server::setup_fd_for_listen(bool non_blocking, const NetProcessor::AcceptOptions } if (opt.f_proxy_protocol) { - Debug("proxyprotocol", "Proxy Protocol enabled."); + Dbg(dbg_ctl_proxyprotocol, "Proxy Protocol enabled."); } #if defined(TCP_MAXSEG) @@ -347,7 +356,7 @@ Server::listen(bool non_blocking, const NetProcessor::AcceptOptions &opt) } if (opt.f_mptcp) { - Debug("connection", "Define socket with MPTCP"); + Dbg(dbg_ctl_connection, "Define socket with MPTCP"); prot = IPPROTO_MPTCP; } diff --git a/src/iocore/net/ConnectionTracker.cc b/src/iocore/net/ConnectionTracker.cc index 137247f58a..9a018ce71b 100644 --- a/src/iocore/net/ConnectionTracker.cc +++ b/src/iocore/net/ConnectionTracker.cc @@ -256,10 +256,10 @@ ConnectionTracker::Group::equal(const Key &lhs, const Key &rhs) } } - if (is_debug_tag_set(DEBUG_TAG)) { + if (dbg_ctl.on()) { swoc::LocalBufferWriter<256> w; w.print("Comparing {} to {} -> {}\0", lhs, rhs, zret ? "match" : "fail"); - Debug(DEBUG_TAG, "%s", w.data()); + DbgPrint(dbg_ctl, "%s", w.data()); } return zret; @@ -423,26 +423,26 @@ ConnectionTracker::TxnState::Note_Unblocked(const TxnConfig *config, int count, swoc::LocalBufferWriter<256> w; w.print("Peer unblocked: [{}] count={} limit={} group=({}) blocked={} peer={}\0", swoc::bwf::Date(lat, "%b %d %H:%M:%S"sv), count, config->server_max, *_g, blocked, addr); - Debug(DEBUG_TAG, "%s", w.data()); + Dbg(dbg_ctl, "%s", w.data()); Note("%s", w.data()); } } void -ConnectionTracker::TxnState::Warn_Blocked(int max_connections, int64_t id, int count, sockaddr const *addr, char const *debug_tag) +ConnectionTracker::TxnState::Warn_Blocked(int max_connections, int64_t id, int count, sockaddr const *addr, DbgCtl *dbg_ctl_p) { bool alert_p = _g->should_alert(); auto blocked = alert_p ? _g->_blocked.exchange(0) : _g->_blocked.load(); - if (alert_p || debug_tag) { + if (alert_p || dbg_ctl_p) { swoc::LocalBufferWriter<256> w; if (id > 1) { w.print("[{}] ", id); } w.print("too many connections: count={} limit={} group=({}) blocked={} peer={}\0", count, max_connections, *_g, blocked, addr); - if (debug_tag) { - Debug(debug_tag, "%s", w.data()); + if (dbg_ctl_p) { + Dbg(*dbg_ctl_p, "%s", w.data()); } if (alert_p) { Warning("%s", w.data()); diff --git a/src/iocore/net/NetHandler.cc b/src/iocore/net/NetHandler.cc index e2384eb96b..f83f09ad48 100644 --- a/src/iocore/net/NetHandler.cc +++ b/src/iocore/net/NetHandler.cc @@ -35,6 +35,13 @@ using namespace std::literals; +namespace +{ +DbgCtl dbg_ctl_net_queue{"net_queue"}; +DbgCtl dbg_ctl_v_net_queue{"v_net_queue"}; + +} // end anonymous namespace + std::atomic<uint32_t> NetHandler::additional_accepts{0}; std::atomic<uint32_t> NetHandler::per_client_max_connections_in{0}; @@ -57,7 +64,7 @@ NetHandler::startIO(NetEvent *ne) res = errno; // EEXIST should be ok, though it should have been cleared before we got back here if (errno != EEXIST) { - Debug("iocore_net", "NetHandler::startIO : failed on EventIO::start, errno = [%d](%s)", errno, strerror(errno)); + Dbg(dbg_ctl_iocore_net, "NetHandler::startIO : failed on EventIO::start, errno = [%d](%s)", errno, strerror(errno)); return -res; } } @@ -119,28 +126,28 @@ NetHandler::update_nethandler_config(const char *str, RecDataT, RecData data, vo if (name == "proxy.config.net.max_connections_in"sv) { updated_member = &NetHandler::global_config.max_connections_in; - Debug("net_queue", "proxy.config.net.max_connections_in updated to %" PRId64, data.rec_int); + Dbg(dbg_ctl_net_queue, "proxy.config.net.max_connections_in updated to %" PRId64, data.rec_int); } else if (name == "proxy.config.net.max_requests_in"sv) { updated_member = &NetHandler::global_config.max_requests_in; - Debug("net_queue", "proxy.config.net.max_requests_in updated to %" PRId64, data.rec_int); + Dbg(dbg_ctl_net_queue, "proxy.config.net.max_requests_in updated to %" PRId64, data.rec_int); } else if (name == "proxy.config.net.inactive_threshold_in"sv) { updated_member = &NetHandler::global_config.inactive_threshold_in; - Debug("net_queue", "proxy.config.net.inactive_threshold_in updated to %" PRId64, data.rec_int); + Dbg(dbg_ctl_net_queue, "proxy.config.net.inactive_threshold_in updated to %" PRId64, data.rec_int); } else if (name == "proxy.config.net.transaction_no_activity_timeout_in"sv) { updated_member = &NetHandler::global_config.transaction_no_activity_timeout_in; - Debug("net_queue", "proxy.config.net.transaction_no_activity_timeout_in updated to %" PRId64, data.rec_int); + Dbg(dbg_ctl_net_queue, "proxy.config.net.transaction_no_activity_timeout_in updated to %" PRId64, data.rec_int); } else if (name == "proxy.config.net.keep_alive_no_activity_timeout_in"sv) { updated_member = &NetHandler::global_config.keep_alive_no_activity_timeout_in; - Debug("net_queue", "proxy.config.net.keep_alive_no_activity_timeout_in updated to %" PRId64, data.rec_int); + Dbg(dbg_ctl_net_queue, "proxy.config.net.keep_alive_no_activity_timeout_in updated to %" PRId64, data.rec_int); } else if (name == "proxy.config.net.default_inactivity_timeout"sv) { updated_member = &NetHandler::global_config.default_inactivity_timeout; - Debug("net_queue", "proxy.config.net.default_inactivity_timeout updated to %" PRId64, data.rec_int); + Dbg(dbg_ctl_net_queue, "proxy.config.net.default_inactivity_timeout updated to %" PRId64, data.rec_int); } else if (name == "proxy.config.net.additional_accepts"sv) { NetHandler::additional_accepts.store(data.rec_int, std::memory_order_relaxed); - Debug("net_queue", "proxy.config.net.additional_accepts updated to %" PRId64, data.rec_int); + Dbg(dbg_ctl_net_queue, "proxy.config.net.additional_accepts updated to %" PRId64, data.rec_int); } else if (name == "proxy.config.net.per_client.max_connections_in"sv) { NetHandler::per_client_max_connections_in.store(data.rec_int, std::memory_order_relaxed); - Debug("net_queue", "proxy.config.net.per_client.max_connections_in updated to %" PRId64, data.rec_int); + Dbg(dbg_ctl_net_queue, "proxy.config.net.per_client.max_connections_in updated to %" PRId64, data.rec_int); } if (updated_member) { @@ -195,17 +202,17 @@ NetHandler::init_for_process() RecRegisterConfigUpdateCb("proxy.config.net.additional_accepts", update_nethandler_config, nullptr); RecRegisterConfigUpdateCb("proxy.config.net.per_client.max_connections_in", update_nethandler_config, nullptr); - Debug("net_queue", "proxy.config.net.max_connections_in updated to %d", global_config.max_connections_in); - Debug("net_queue", "proxy.config.net.max_requests_in updated to %d", global_config.max_requests_in); - Debug("net_queue", "proxy.config.net.inactive_threshold_in updated to %d", global_config.inactive_threshold_in); - Debug("net_queue", "proxy.config.net.transaction_no_activity_timeout_in updated to %d", - global_config.transaction_no_activity_timeout_in); - Debug("net_queue", "proxy.config.net.keep_alive_no_activity_timeout_in updated to %d", - global_config.keep_alive_no_activity_timeout_in); - Debug("net_queue", "proxy.config.net.default_inactivity_timeout updated to %d", global_config.default_inactivity_timeout); - Debug("net_queue", "proxy.config.net.additional_accepts updated to %d", additional_accepts.load(std::memory_order_relaxed)); - Debug("net_queue", "proxy.config.net.per_client.max_connections_in updated to %d", - per_client_max_connections_in.load(std::memory_order_relaxed)); + Dbg(dbg_ctl_net_queue, "proxy.config.net.max_connections_in updated to %d", global_config.max_connections_in); + Dbg(dbg_ctl_net_queue, "proxy.config.net.max_requests_in updated to %d", global_config.max_requests_in); + Dbg(dbg_ctl_net_queue, "proxy.config.net.inactive_threshold_in updated to %d", global_config.inactive_threshold_in); + Dbg(dbg_ctl_net_queue, "proxy.config.net.transaction_no_activity_timeout_in updated to %d", + global_config.transaction_no_activity_timeout_in); + Dbg(dbg_ctl_net_queue, "proxy.config.net.keep_alive_no_activity_timeout_in updated to %d", + global_config.keep_alive_no_activity_timeout_in); + Dbg(dbg_ctl_net_queue, "proxy.config.net.default_inactivity_timeout updated to %d", global_config.default_inactivity_timeout); + Dbg(dbg_ctl_net_queue, "proxy.config.net.additional_accepts updated to %d", additional_accepts.load(std::memory_order_relaxed)); + Dbg(dbg_ctl_net_queue, "proxy.config.net.per_client.max_connections_in updated to %d", + per_client_max_connections_in.load(std::memory_order_relaxed)); } // @@ -385,10 +392,10 @@ bool NetHandler::manage_active_queue(NetEvent *enabling_ne, bool ignore_queue_size = false) { const int total_connections_in = active_queue_size + keep_alive_queue_size; - Debug("v_net_queue", - "max_connections_per_thread_in: %d max_requests_per_thread_in: %d total_connections_in: %d " - "active_queue_size: %d keep_alive_queue_size: %d", - max_connections_per_thread_in, max_requests_per_thread_in, total_connections_in, active_queue_size, keep_alive_queue_size); + Dbg(dbg_ctl_v_net_queue, + "max_connections_per_thread_in: %d max_requests_per_thread_in: %d total_connections_in: %d " + "active_queue_size: %d keep_alive_queue_size: %d", + max_connections_per_thread_in, max_requests_per_thread_in, total_connections_in, active_queue_size, keep_alive_queue_size); if (!max_requests_per_thread_in) { // active queue has no max @@ -438,8 +445,8 @@ NetHandler::configure_per_thread_values() int threads = eventProcessor.thread_group[ET_NET]._count; max_connections_per_thread_in = config.max_connections_in / threads; max_requests_per_thread_in = config.max_requests_in / threads; - Debug("net_queue", "max_connections_per_thread_in updated to %d threads: %d", max_connections_per_thread_in, threads); - Debug("net_queue", "max_requests_per_thread_in updated to %d threads: %d", max_requests_per_thread_in, threads); + Dbg(dbg_ctl_net_queue, "max_connections_per_thread_in updated to %d threads: %d", max_connections_per_thread_in, threads); + Dbg(dbg_ctl_net_queue, "max_requests_per_thread_in updated to %d threads: %d", max_requests_per_thread_in, threads); } void @@ -448,8 +455,9 @@ NetHandler::manage_keep_alive_queue() uint32_t total_connections_in = active_queue_size + keep_alive_queue_size; ink_hrtime now = ink_get_hrtime(); - Debug("v_net_queue", "max_connections_per_thread_in: %d total_connections_in: %d active_queue_size: %d keep_alive_queue_size: %d", - max_connections_per_thread_in, total_connections_in, active_queue_size, keep_alive_queue_size); + Dbg(dbg_ctl_v_net_queue, + "max_connections_per_thread_in: %d total_connections_in: %d active_queue_size: %d keep_alive_queue_size: %d", + max_connections_per_thread_in, total_connections_in, active_queue_size, keep_alive_queue_size); if (!max_connections_per_thread_in || total_connections_in <= max_connections_per_thread_in) { return; @@ -472,9 +480,9 @@ NetHandler::manage_keep_alive_queue() } if (total_idle_count > 0) { - Debug("net_queue", "max cons: %d active: %d idle: %d already closed: %d, close event: %d mean idle: %d", - max_connections_per_thread_in, total_connections_in, keep_alive_queue_size, closed, handle_event, - total_idle_time / total_idle_count); + Dbg(dbg_ctl_net_queue, "max cons: %d active: %d idle: %d already closed: %d, close event: %d mean idle: %d", + max_connections_per_thread_in, total_connections_in, keep_alive_queue_size, closed, handle_event, + total_idle_time / total_idle_count); } } @@ -495,9 +503,9 @@ NetHandler::_close_ne(NetEvent *ne, ink_hrtime now, int &handle_event, int &clos Metrics::Counter::increment(net_rsb.keep_alive_queue_timeout_total, diff); Metrics::Counter::increment(net_rsb.keep_alive_queue_timeout_count); } - Debug("net_queue", "closing connection NetEvent=%p idle: %u now: %" PRId64 " at: %" PRId64 " in: %" PRId64 " diff: %" PRId64, ne, - keep_alive_queue_size, ink_hrtime_to_sec(now), ink_hrtime_to_sec(ne->next_inactivity_timeout_at), - ink_hrtime_to_sec(ne->inactivity_timeout_in), diff); + Dbg(dbg_ctl_net_queue, "closing connection NetEvent=%p idle: %u now: %" PRId64 " at: %" PRId64 " in: %" PRId64 " diff: %" PRId64, + ne, keep_alive_queue_size, ink_hrtime_to_sec(now), ink_hrtime_to_sec(ne->next_inactivity_timeout_at), + ink_hrtime_to_sec(ne->inactivity_timeout_in), diff); if (ne->closed) { free_netevent(ne); ++closed; @@ -521,7 +529,7 @@ NetHandler::_close_ne(NetEvent *ne, ink_hrtime now, int &handle_event, int &clos void NetHandler::add_to_keep_alive_queue(NetEvent *ne) { - Debug("net_queue", "NetEvent: %p", ne); + Dbg(dbg_ctl_net_queue, "NetEvent: %p", ne); ink_assert(mutex->thread_holding == this_ethread()); if (keep_alive_queue.in(ne)) { @@ -541,7 +549,7 @@ NetHandler::add_to_keep_alive_queue(NetEvent *ne) void NetHandler::remove_from_keep_alive_queue(NetEvent *ne) { - Debug("net_queue", "NetEvent: %p", ne); + Dbg(dbg_ctl_net_queue, "NetEvent: %p", ne); ink_assert(mutex->thread_holding == this_ethread()); if (keep_alive_queue.in(ne)) { @@ -553,9 +561,9 @@ NetHandler::remove_from_keep_alive_queue(NetEvent *ne) bool NetHandler::add_to_active_queue(NetEvent *ne) { - Debug("net_queue", "NetEvent: %p", ne); - Debug("net_queue", "max_connections_per_thread_in: %d active_queue_size: %d keep_alive_queue_size: %d", - max_connections_per_thread_in, active_queue_size, keep_alive_queue_size); + Dbg(dbg_ctl_net_queue, "NetEvent: %p", ne); + Dbg(dbg_ctl_net_queue, "max_connections_per_thread_in: %d active_queue_size: %d keep_alive_queue_size: %d", + max_connections_per_thread_in, active_queue_size, keep_alive_queue_size); ink_assert(mutex->thread_holding == this_ethread()); bool active_queue_full = false; @@ -586,7 +594,7 @@ NetHandler::add_to_active_queue(NetEvent *ne) void NetHandler::remove_from_active_queue(NetEvent *ne) { - Debug("net_queue", "NetEvent: %p", ne); + Dbg(dbg_ctl_net_queue, "NetEvent: %p", ne); ink_assert(mutex->thread_holding == this_ethread()); if (active_queue.in(ne)) { diff --git a/src/iocore/net/NetVCTest.cc b/src/iocore/net/NetVCTest.cc index f999671246..fd848763c9 100644 --- a/src/iocore/net/NetVCTest.cc +++ b/src/iocore/net/NetVCTest.cc @@ -86,15 +86,15 @@ NetVCTest::~NetVCTest() mutex = nullptr; if (read_buffer) { - Debug(debug_tag, "Freeing read MIOBuffer with %d blocks on %s", read_buffer->max_block_count(), - (test_cont_type == NET_VC_TEST_ACTIVE) ? "Active" : "Passive"); + Dbg(dbg_ctl, "Freeing read MIOBuffer with %d blocks on %s", read_buffer->max_block_count(), + (test_cont_type == NET_VC_TEST_ACTIVE) ? "Active" : "Passive"); free_MIOBuffer(read_buffer); read_buffer = nullptr; } if (write_buffer) { - Debug(debug_tag, "Freeing write MIOBuffer with %d blocks on %s", write_buffer->max_block_count(), - (test_cont_type == NET_VC_TEST_ACTIVE) ? "Active" : "Passive"); + Dbg(dbg_ctl, "Freeing write MIOBuffer with %d blocks on %s", write_buffer->max_block_count(), + (test_cont_type == NET_VC_TEST_ACTIVE) ? "Active" : "Passive"); free_MIOBuffer(write_buffer); write_buffer = nullptr; } @@ -109,7 +109,7 @@ NetVCTest::init_test(NetVcTestType_t c_type, NetTestDriver *driver_arg, NetVConn test_vc = nvc; regress = robj; module_name = module_name_arg; - debug_tag = debug_tag_arg; + dbg_ctl = DbgCtl{debug_tag_arg}; bytes_to_send = my_def->bytes_to_send; bytes_to_read = my_def->bytes_to_read; @@ -206,7 +206,7 @@ NetVCTest::consume_and_check_bytes(IOBufferReader *r, uint8_t *seed) } } - Debug(debug_tag, "consume_&_check: read %d, to_read %d", actual_bytes_read, bytes_to_read); + Dbg(dbg_ctl, "consume_&_check: read %d, to_read %d", actual_bytes_read, bytes_to_read); r->consume(b_consumed); } @@ -270,7 +270,7 @@ NetVCTest::finished() void NetVCTest::write_handler(int event) { - Debug(debug_tag, "write_handler received event %d on %s", event, (test_cont_type == NET_VC_TEST_ACTIVE) ? "Active" : "Passive"); + Dbg(dbg_ctl, "write_handler received event %d on %s", event, (test_cont_type == NET_VC_TEST_ACTIVE) ? "Active" : "Passive"); switch (event) { case VC_EVENT_WRITE_READY: @@ -303,7 +303,7 @@ NetVCTest::write_handler(int event) void NetVCTest::read_handler(int event) { - Debug(debug_tag, "read_handler received event %d on %s", event, (test_cont_type == NET_VC_TEST_ACTIVE) ? "Active" : "Passive"); + Dbg(dbg_ctl, "read_handler received event %d on %s", event, (test_cont_type == NET_VC_TEST_ACTIVE) ? "Active" : "Passive"); switch (event) { case VC_EVENT_READ_READY: diff --git a/src/iocore/net/NetVConnection.cc b/src/iocore/net/NetVConnection.cc index 5bc9fe39a8..d07902c65f 100644 --- a/src/iocore/net/NetVConnection.cc +++ b/src/iocore/net/NetVConnection.cc @@ -35,6 +35,12 @@ #include "P_Net.h" #include "ts/apidefs.h" +namespace +{ +DbgCtl dbg_ctl_ssl{"ssl"}; + +} // end anonymous namespace + //// // NetVConnection // @@ -83,7 +89,7 @@ NetVConnection::has_proxy_protocol(char *buffer, int64_t *bytes_r) if (*bytes_r <= 0) { *bytes_r = -EAGAIN; } else { - Debug("ssl", "Moving %" PRId64 " characters remaining in the buffer from %p to %p", *bytes_r, buffer + len, buffer); + Dbg(dbg_ctl_ssl, "Moving %" PRId64 " characters remaining in the buffer from %p to %p", *bytes_r, buffer + len, buffer); memmove(buffer, buffer + len, *bytes_r); } diff --git a/src/iocore/net/OCSPStapling.cc b/src/iocore/net/OCSPStapling.cc index beb67cc5e5..957fb5cce1 100644 --- a/src/iocore/net/OCSPStapling.cc +++ b/src/iocore/net/OCSPStapling.cc @@ -260,6 +260,12 @@ constexpr int TS_OCSP_CERTSTATUS_UNKNOWN = 2; // End of definitions from RFC 6960 +namespace +{ + DbgCtl dbg_ctl_ssl_ocsp{"ssl_ocsp"}; + +} // end anonymous namespace + // Cached info stored in SSL_CTX ex_info struct certinfo { unsigned char idx[20]; // Index in session cache SHA1 hash of certificate @@ -431,7 +437,7 @@ TS_OCSP_cert_id_new(const EVP_MD *dgst, const X509_NAME *issuerName, const ASN1_ alg = cid->hashAlgorithm; ASN1_OBJECT_free(alg->algorithm); if ((nid = EVP_MD_type(dgst)) == NID_undef) { - Debug("ssl_ocsp", "Unknown NID"); + Dbg(dbg_ctl_ssl_ocsp, "Unknown NID"); goto err; } if ((alg->algorithm = OBJ_nid2obj(nid)) == nullptr) @@ -458,7 +464,7 @@ TS_OCSP_cert_id_new(const EVP_MD *dgst, const X509_NAME *issuerName, const ASN1_ } return cid; digerr: - Debug("ssl_ocsp", "Digest error"); + Dbg(dbg_ctl_ssl_ocsp, "Digest error"); err: TS_OCSP_CERTID_free(cid); return nullptr; @@ -493,12 +499,12 @@ TS_OCSP_check_validity(ASN1_GENERALIZEDTIME *thisupd, ASN1_GENERALIZEDTIME *next time(&t_now); /* Check thisUpdate is valid and not more than nsec in the future */ if (!ASN1_GENERALIZEDTIME_check(thisupd)) { - Debug("ssl_ocsp", "Error in thisUpdate field"); + Dbg(dbg_ctl_ssl_ocsp, "Error in thisUpdate field"); ret = 0; } else { t_tmp = t_now + nsec; if (X509_cmp_time(thisupd, &t_tmp) > 0) { - Debug("ssl_ocsp", "Status not yet valid"); + Dbg(dbg_ctl_ssl_ocsp, "Status not yet valid"); ret = 0; } @@ -509,7 +515,7 @@ TS_OCSP_check_validity(ASN1_GENERALIZEDTIME *thisupd, ASN1_GENERALIZEDTIME *next if (maxsec >= 0) { t_tmp = t_now - maxsec; if (X509_cmp_time(thisupd, &t_tmp) < 0) { - Debug("ssl_ocsp", "Status too old"); + Dbg(dbg_ctl_ssl_ocsp, "Status too old"); ret = 0; } } @@ -520,19 +526,19 @@ TS_OCSP_check_validity(ASN1_GENERALIZEDTIME *thisupd, ASN1_GENERALIZEDTIME *next /* Check nextUpdate is valid and not more than nsec in the past */ if (!ASN1_GENERALIZEDTIME_check(nextupd)) { - Debug("ssl_ocsp", "Error in nextUpdate field"); + Dbg(dbg_ctl_ssl_ocsp, "Error in nextUpdate field"); ret = 0; } else { t_tmp = t_now - nsec; if (X509_cmp_time(nextupd, &t_tmp) < 0) { - Debug("ssl_ocsp", "Status expired"); + Dbg(dbg_ctl_ssl_ocsp, "Status expired"); ret = 0; } } /* Also don't allow nextUpdate to precede thisUpdate */ if (ASN1_STRING_cmp(nextupd, thisupd) < 0) { - Debug("ssl_ocsp", "nextUpdate precedes thisUpdate"); + Dbg(dbg_ctl_ssl_ocsp, "nextUpdate precedes thisUpdate"); ret = 0; } @@ -562,11 +568,11 @@ TS_OCSP_response_get1_basic(TS_OCSP_RESPONSE *resp) TS_OCSP_RESPBYTES *rb = resp->responseBytes; if (rb == nullptr) { - Debug("ssl_ocsp", "No response data"); + Dbg(dbg_ctl_ssl_ocsp, "No response data"); return nullptr; } if (OBJ_obj2nid(rb->responseType) != NID_id_pkix_OCSP_basic) { - Debug("ssl_ocsp", "Not basic response"); + Dbg(dbg_ctl_ssl_ocsp, "Not basic response"); return nullptr; } @@ -796,7 +802,7 @@ stapling_cache_response(TS_OCSP_RESPONSE *rsp, certinfo *cinf) cinf->expire_time = time(nullptr) + SSLConfigParams::ssl_ocsp_cache_timeout; ink_mutex_release(&cinf->stapling_mutex); - Debug("ssl_ocsp", "stapling_cache_response: success to cache response"); + Dbg(dbg_ctl_ssl_ocsp, "stapling_cache_response: success to cache response"); return true; } @@ -842,7 +848,7 @@ ssl_stapling_init_cert(SSL_CTX *ctx, X509 *cert, const char *certname, const cha cinf->expire_time = 0; if (cinf->is_prefetched) { - Debug("ssl_ocsp", "using OCSP prefetched response file %s", rsp_file); + Dbg(dbg_ctl_ssl_ocsp, "using OCSP prefetched response file %s", rsp_file); FILE *fp = fopen(rsp_file, "r"); if (fp) { fseek(fp, 0, SEEK_END); @@ -873,7 +879,7 @@ ssl_stapling_init_cert(SSL_CTX *ctx, X509 *cert, const char *certname, const cha Error("stapling_refresh_response: can not cache response"); goto err; } else { - Debug("ssl_ocsp", "stapling_refresh_response: successful refresh OCSP response"); + Dbg(dbg_ctl_ssl_ocsp, "stapling_refresh_response: successful refresh OCSP response"); TS_OCSP_RESPONSE_free(rsp); rsp = nullptr; } @@ -1043,7 +1049,7 @@ query_responder(const char *uri, const char *user_agent, TS_OCSP_REQUEST *req, i if (!httpreq.is_done()) { Error("OCSP request was timed out; uri=%s", uri); if (!httpreq.is_initiated()) { - Debug("ssl_ocsp", "Request is not initiated yet. Cancelling the event."); + Dbg(dbg_ctl_ssl_ocsp, "Request is not initiated yet. Cancelling the event."); e->cancel(&httpreq); } } @@ -1117,7 +1123,7 @@ make_url_for_get(TS_OCSP_REQUEST *req, const char *base_url) Error("stapling_refresh_response: unable to convert OCSP request to DER; falling back to POST; url=%s", base_url); return nullptr; } - Debug("ssl_ocsp", "converted OCSP request to DER; length=%d", ocsp_der_len); + Dbg(dbg_ctl_ssl_ocsp, "converted OCSP request to DER; length=%d", ocsp_der_len); if (ats_base64_encode(ocsp_der, ocsp_der_len, ocsp_encoded_der, MAX_OCSP_GET_ENCODED_LENGTH, &ocsp_encoded_der_len) == false || ocsp_encoded_der_len == 0) { @@ -1126,14 +1132,14 @@ make_url_for_get(TS_OCSP_REQUEST *req, const char *base_url) return nullptr; } OPENSSL_free(ocsp_der); - Debug("ssl_ocsp", "encoded DER with base64: %s", ocsp_encoded_der); + Dbg(dbg_ctl_ssl_ocsp, "encoded DER with base64: %s", ocsp_encoded_der); if (nullptr == Encoding::pure_escapify_url(nullptr, ocsp_encoded_der, ocsp_encoded_der_len, &ocsp_escaped_len, ocsp_escaped, MAX_OCSP_GET_ENCODED_LENGTH, encoding_map)) { Error("stapling_refresh_response: unable to escapify encoded url; falling back to POST; url=%s", base_url); return nullptr; } - Debug("ssl_ocsp", "escaped encoded path; %d bytes, %s", ocsp_escaped_len, ocsp_escaped); + Dbg(dbg_ctl_ssl_ocsp, "escaped encoded path; %d bytes, %s", ocsp_escaped_len, ocsp_escaped); size_t total_url_len = sizeof(char) * (strlen(base_url) + 1 + ocsp_escaped_len + 1); // <base URL> + / + <encoded OCSP request> + \0 @@ -1143,7 +1149,7 @@ make_url_for_get(TS_OCSP_REQUEST *req, const char *base_url) // increase buffer index as necessary to fit the largest observed encoded_path_len while (buffer_size < total_url_len && buffer_idx < MAX_BUFFER_SIZE_INDEX) { buffer_size = BUFFER_SIZE_FOR_INDEX(++buffer_idx); - Debug("ssl_ocsp", "increased buffer index to %d", buffer_idx); + Dbg(dbg_ctl_ssl_ocsp, "increased buffer index to %d", buffer_idx); } if (buffer_size < total_url_len) { @@ -1153,8 +1159,8 @@ make_url_for_get(TS_OCSP_REQUEST *req, const char *base_url) return nullptr; } - Debug("ssl_ocsp", "creating new buffer block with index %d, size %d, to store %zu encoded bytes", buffer_idx, buffer_size, - total_url_len); + Dbg(dbg_ctl_ssl_ocsp, "creating new buffer block with index %d, size %d, to store %zu encoded bytes", buffer_idx, buffer_size, + total_url_len); url = new_IOBufferBlock(); url->alloc(buffer_idx); @@ -1169,7 +1175,7 @@ make_url_for_get(TS_OCSP_REQUEST *req, const char *base_url) written = ink_strlcat(url->end(), ocsp_escaped, url->write_avail()); url->fill(written); - Debug("ssl_ocsp", "appended encoded data to path: %s", url->buf()); + Dbg(dbg_ctl_ssl_ocsp, "appended encoded data to path: %s", url->buf()); return url; } @@ -1211,7 +1217,7 @@ stapling_refresh_response(certinfo *cinf, TS_OCSP_RESPONSE **prsp) url = cinf->uri; } - Debug("ssl_ocsp", "stapling_refresh_response: querying responder; method=%s uri=%s", use_get ? "GET" : "POST", cinf->uri); + Dbg(dbg_ctl_ssl_ocsp, "stapling_refresh_response: querying responder; method=%s uri=%s", use_get ? "GET" : "POST", cinf->uri); *prsp = query_responder(url, cinf->user_agent, req, SSLConfigParams::ssl_ocsp_request_timeout, use_get); if (*prsp == nullptr) { @@ -1220,7 +1226,7 @@ stapling_refresh_response(certinfo *cinf, TS_OCSP_RESPONSE **prsp) response_status = ASN1_ENUMERATED_get((*prsp)->responseStatus); if (response_status == TS_OCSP_RESPONSE_STATUS_SUCCESSFUL) { - Debug("ssl_ocsp", "stapling_refresh_response: query response received"); + Dbg(dbg_ctl_ssl_ocsp, "stapling_refresh_response: query response received"); stapling_check_response(cinf, *prsp); } else { Error("stapling_refresh_response: responder response error; uri=%s method=%s response_status=%d", cinf->uri, @@ -1230,7 +1236,7 @@ stapling_refresh_response(certinfo *cinf, TS_OCSP_RESPONSE **prsp) if (!stapling_cache_response(*prsp, cinf)) { Error("stapling_refresh_response: can not cache response"); } else { - Debug("ssl_ocsp", "stapling_refresh_response: successfully refreshed OCSP response"); + Dbg(dbg_ctl_ssl_ocsp, "stapling_refresh_response: successfully refreshed OCSP response"); } goto done; @@ -1260,7 +1266,7 @@ ocsp_update() SSLCertificateConfig::scoped_config certLookup; - Debug("ssl_ocsp", "updating OCSP data"); + Dbg(dbg_ctl_ssl_ocsp, "updating OCSP data"); #ifndef OPENSSL_IS_BORINGSSL const SSLCertContextType ctxTypes[] = {SSLCertContextType::GENERIC}; #else @@ -1284,7 +1290,7 @@ ocsp_update() if (cinf->resp_derlen == 0 || cinf->is_expire || cinf->expire_time < current_time) { ink_mutex_release(&cinf->stapling_mutex); if (stapling_refresh_response(cinf, &resp)) { - Debug("ssl_ocsp", "Successfully refreshed OCSP for %s certificate. url=%s", cinf->certname, cinf->uri); + Dbg(dbg_ctl_ssl_ocsp, "Successfully refreshed OCSP for %s certificate. url=%s", cinf->certname, cinf->uri); Metrics::Counter::increment(ssl_rsb.ocsp_refreshed_cert); } else { Error("Failed to refresh OCSP for %s certificate. url=%s", cinf->certname, cinf->uri); @@ -1314,12 +1320,12 @@ ssl_callback_ocsp_stapling(SSL *ssl, void *) // originally was, cinf = stapling_get_cert_info(ssl->ctx); certinfo_map *map = stapling_get_cert_info(SSL_get_SSL_CTX(ssl)); if (map == nullptr) { - Debug("ssl_ocsp", "ssl_callback_ocsp_stapling: failed to get certificate map"); + Dbg(dbg_ctl_ssl_ocsp, "ssl_callback_ocsp_stapling: failed to get certificate map"); return SSL_TLSEXT_ERR_NOACK; } if (map->empty()) { - Debug("ssl_ocsp", "ssl_callback_ocsp_stapling: certificate map empty"); + Dbg(dbg_ctl_ssl_ocsp, "ssl_callback_ocsp_stapling: certificate map empty"); return SSL_TLSEXT_ERR_NOACK; } @@ -1359,15 +1365,15 @@ ssl_callback_ocsp_stapling(SSL *ssl, void *) time_t current_time = time(nullptr); if ((cinf->resp_derlen == 0 || cinf->is_expire) || (cinf->expire_time < current_time && !cinf->is_prefetched)) { ink_mutex_release(&cinf->stapling_mutex); - Debug("ssl_ocsp", "ssl_callback_ocsp_stapling: failed to get certificate status for %s", cinf->certname); + Dbg(dbg_ctl_ssl_ocsp, "ssl_callback_ocsp_stapling: failed to get certificate status for %s", cinf->certname); return SSL_TLSEXT_ERR_NOACK; } else { unsigned char *p = static_cast<unsigned char *>(OPENSSL_malloc(cinf->resp_derlen)); memcpy(p, cinf->resp_der, cinf->resp_derlen); ink_mutex_release(&cinf->stapling_mutex); SSL_set_tlsext_status_ocsp_resp(ssl, p, cinf->resp_derlen); - Debug("ssl_ocsp", "ssl_callback_ocsp_stapling: successfully got certificate status for %s", cinf->certname); - Debug("ssl_ocsp", "is_prefetched:%d uri:%s", cinf->is_prefetched, cinf->uri); + Dbg(dbg_ctl_ssl_ocsp, "ssl_callback_ocsp_stapling: successfully got certificate status for %s", cinf->certname); + Dbg(dbg_ctl_ssl_ocsp, "is_prefetched:%d uri:%s", cinf->is_prefetched, cinf->uri); return SSL_TLSEXT_ERR_OK; } } diff --git a/src/iocore/net/P_NetVCTest.h b/src/iocore/net/P_NetVCTest.h index 1e1269f0fb..f82e59febb 100644 --- a/src/iocore/net/P_NetVCTest.h +++ b/src/iocore/net/P_NetVCTest.h @@ -139,5 +139,5 @@ public: const char *test_name = nullptr; const char *module_name = nullptr; - const char *debug_tag = nullptr; + DbgCtl dbg_ctl; }; diff --git a/src/iocore/net/ProxyProtocol.cc b/src/iocore/net/ProxyProtocol.cc index 7bbf80ed00..821e90187e 100644 --- a/src/iocore/net/ProxyProtocol.cc +++ b/src/iocore/net/ProxyProtocol.cc @@ -62,6 +62,10 @@ constexpr uint16_t PPv2_ADDR_LEN_UNIX = 108 + 108; const swoc::bwf::Spec ADDR_ONLY_FMT{"::a"}; +DbgCtl dbg_ctl_proxyprotocol_v1{"proxyprotocol_v1"}; +DbgCtl dbg_ctl_proxyprotocol_v2{"proxyprotocol_v2"}; +DbgCtl dbg_ctl_proxyprotocol{"proxyprotocol"}; + struct PPv2Hdr { uint8_t sig[12]; ///< preface uint8_t ver_cmd; ///< protocol version and command @@ -103,12 +107,12 @@ proxy_protocol_v1_parse(ProxyProtocol *pp_info, swoc::TextView hdr) // Find the terminating newline swoc::TextView::size_type pos = hdr.find('\n'); if (pos == hdr.npos) { - Debug("proxyprotocol_v1", "ssl_has_proxy_v1: LF not found"); + Dbg(dbg_ctl_proxyprotocol_v1, "ssl_has_proxy_v1: LF not found"); return 0; } if (hdr[pos - 1] != '\r') { - Debug("proxyprotocol_v1", "ssl_has_proxy_v1: CR not found"); + Dbg(dbg_ctl_proxyprotocol_v1, "ssl_has_proxy_v1: CR not found"); return 0; } @@ -119,15 +123,15 @@ proxy_protocol_v1_parse(ProxyProtocol *pp_info, swoc::TextView hdr) // The header should begin with the PROXY preface token = hdr.split_prefix_at(' '); if (0 == token.size() || token != PPv1_CONNECTION_PREFACE) { - Debug("proxyprotocol_v1", "proxy_protov1_parse: header [%.*s] does not start with preface [%.*s]", static_cast<int>(hdr.size()), - hdr.data(), static_cast<int>(PPv1_CONNECTION_PREFACE.size()), PPv1_CONNECTION_PREFACE.data()); + Dbg(dbg_ctl_proxyprotocol_v1, "proxy_protov1_parse: header [%.*s] does not start with preface [%.*s]", + static_cast<int>(hdr.size()), hdr.data(), static_cast<int>(PPv1_CONNECTION_PREFACE.size()), PPv1_CONNECTION_PREFACE.data()); return 0; } - Debug("proxyprotocol_v1", "proxy_protov1_parse: [%.*s] = PREFACE", static_cast<int>(token.size()), token.data()); + Dbg(dbg_ctl_proxyprotocol_v1, "proxy_protov1_parse: [%.*s] = PREFACE", static_cast<int>(token.size()), token.data()); // The INET protocol family - TCP4, TCP6 or UNKNOWN if (hdr.starts_with(PPv1_PROTO_UNKNOWN)) { - Debug("proxyprotocol_v1", "proxy_protov1_parse: [UNKNOWN] = INET Family"); + Dbg(dbg_ctl_proxyprotocol_v1, "proxy_protov1_parse: [UNKNOWN] = INET Family"); // Ignore anything presented before the CRLF pp_info->version = ProxyProtocolVersion::V1; @@ -150,7 +154,7 @@ proxy_protocol_v1_parse(ProxyProtocol *pp_info, swoc::TextView hdr) } else { return 0; } - Debug("proxyprotocol_v1", "proxy_protov1_parse: [%.*s] = INET Family", static_cast<int>(token.size()), token.data()); + Dbg(dbg_ctl_proxyprotocol_v1, "proxy_protov1_parse: [%.*s] = INET Family", static_cast<int>(token.size()), token.data()); // Next up is the layer 3 source address // - 255.255.255.255 or ffff:f...f:ffff ffff:f...f:fff @@ -158,7 +162,7 @@ proxy_protocol_v1_parse(ProxyProtocol *pp_info, swoc::TextView hdr) if (0 == token.size()) { return 0; } - Debug("proxyprotocol_v1", "proxy_protov1_parse: [%.*s] = Source Address", static_cast<int>(token.size()), token.data()); + Dbg(dbg_ctl_proxyprotocol_v1, "proxy_protov1_parse: [%.*s] = Source Address", static_cast<int>(token.size()), token.data()); if (0 != ats_ip_pton(token, &pp_info->src_addr)) { return 0; } @@ -169,7 +173,7 @@ proxy_protocol_v1_parse(ProxyProtocol *pp_info, swoc::TextView hdr) if (0 == token.size()) { return 0; } - Debug("proxyprotocol_v1", "proxy_protov1_parse: [%.*s] = Destination Address", static_cast<int>(token.size()), token.data()); + Dbg(dbg_ctl_proxyprotocol_v1, "proxy_protov1_parse: [%.*s] = Destination Address", static_cast<int>(token.size()), token.data()); if (0 != ats_ip_pton(token, &pp_info->dst_addr)) { return 0; } @@ -179,12 +183,12 @@ proxy_protocol_v1_parse(ProxyProtocol *pp_info, swoc::TextView hdr) if (0 == token.size()) { return 0; } - Debug("proxyprotocol_v1", "proxy_protov1_parse: [%.*s] = Source Port", static_cast<int>(token.size()), token.data()); + Dbg(dbg_ctl_proxyprotocol_v1, "proxy_protov1_parse: [%.*s] = Source Port", static_cast<int>(token.size()), token.data()); in_port_t src_port = swoc::svtoi(token); if (src_port == 0) { - Debug("proxyprotocol_v1", "proxy_protov1_parse: src port [%d] token [%.*s] failed to parse", src_port, - static_cast<int>(token.size()), token.data()); + Dbg(dbg_ctl_proxyprotocol_v1, "proxy_protov1_parse: src port [%d] token [%.*s] failed to parse", src_port, + static_cast<int>(token.size()), token.data()); return 0; } pp_info->src_addr.network_order_port() = htons(src_port); @@ -195,12 +199,12 @@ proxy_protocol_v1_parse(ProxyProtocol *pp_info, swoc::TextView hdr) if (0 == token.size() || token.find(0x20) != token.npos) { return 0; } - Debug("proxyprotocol_v1", "proxy_protov1_parse: [%.*s] = Destination Port", static_cast<int>(token.size()), token.data()); + Dbg(dbg_ctl_proxyprotocol_v1, "proxy_protov1_parse: [%.*s] = Destination Port", static_cast<int>(token.size()), token.data()); in_port_t dst_port = swoc::svtoi(token); if (dst_port == 0) { - Debug("proxyprotocol_v1", "proxy_protov1_parse: dst port [%d] token [%.*s] failed to parse", dst_port, - static_cast<int>(token.size()), token.data()); + Dbg(dbg_ctl_proxyprotocol_v1, "proxy_protov1_parse: dst port [%d] token [%.*s] failed to parse", dst_port, + static_cast<int>(token.size()), token.data()); return 0; } pp_info->dst_addr.network_order_port() = htons(dst_port); @@ -354,7 +358,7 @@ proxy_protocol_v1_build(uint8_t *buf, size_t max_buf_len, const ProxyProtocol &p bw.commit(len); } - Debug("proxyprotocol_v1", "Proxy Protocol v1: %.*s", static_cast<int>(bw.size()), bw.data()); + Dbg(dbg_ctl_proxyprotocol_v1, "Proxy Protocol v1: %.*s", static_cast<int>(bw.size()), bw.data()); bw.write("\r\n"); return bw.size(); @@ -440,7 +444,7 @@ proxy_protocol_v2_build(uint8_t *buf, size_t max_buf_len, const ProxyProtocol &p // Set len field (number of following bytes part of the header) in the hdr uint16_t len = htons(bw.size() - PPv2_CONNECTION_HEADER_LEN); memcpy(buf + len_field_offset, &len, sizeof(uint16_t)); - Debug("proxyprotocol_v2", "Proxy Protocol v2 of %zu bytes", bw.size()); + Dbg(dbg_ctl_proxyprotocol_v2, "Proxy Protocol v2 of %zu bytes", bw.size()); return bw.size(); } @@ -463,7 +467,7 @@ proxy_protocol_parse(ProxyProtocol *pp_info, swoc::TextView tv) } else { // if we don't have the PROXY preface, we don't have a ProxyProtocol header // TODO: print hexdump of buffer safely - Debug("proxyprotocol", "failed to find ProxyProtocol preface in the first %zu bytes", tv.size()); + Dbg(dbg_ctl_proxyprotocol, "failed to find ProxyProtocol preface in the first %zu bytes", tv.size()); } return len; diff --git a/src/iocore/net/QUICMultiCertConfigLoader.cc b/src/iocore/net/QUICMultiCertConfigLoader.cc index cd899e70cd..a6cbc4ca6e 100644 --- a/src/iocore/net/QUICMultiCertConfigLoader.cc +++ b/src/iocore/net/QUICMultiCertConfigLoader.cc @@ -32,9 +32,6 @@ #include "tscore/Filenames.h" // #include "iocore/net/quic/QUICGlobals.h" -#define QUICConfDebug(fmt, ...) Debug("quic_conf", fmt, ##__VA_ARGS__) -#define QUICGlobalQCDebug(qc, fmt, ...) Debug("quic_global", "[%s] " fmt, qc->cids().data(), ##__VA_ARGS__) - int QUICCertConfig::_config_id = 0; // diff --git a/src/iocore/net/QUICNetProcessor.cc b/src/iocore/net/QUICNetProcessor.cc index b9c32cb028..97d1435c11 100644 --- a/src/iocore/net/QUICNetProcessor.cc +++ b/src/iocore/net/QUICNetProcessor.cc @@ -40,10 +40,19 @@ QUICNetProcessor quic_NetProcessor; +namespace +{ +DbgCtl dbg_ctl_vv_quiche{"vv_quiche"}; +DbgCtl dbg_ctl_quic_ps{"quic_ps"}; +DbgCtl dbg_ctl_udpnet{"udpnet"}; +DbgCtl dbg_ctl_iocore_net_processor{"iocore_net_processor"}; + +} // end anonymous namespace + static void debug_log(const char *line, void *argp) { - Debug("vv_quiche", "%s\n", line); + Dbg(dbg_ctl_vv_quiche, "%s\n", line); } QUICNetProcessor::QUICNetProcessor() {} @@ -101,7 +110,7 @@ QUICNetProcessor::start(int, size_t stacksize) #ifdef TLS1_3_VERSION_DRAFT_TXT // FIXME: remove this when TLS1_3_VERSION_DRAFT_TXT is removed - Debug("quic_ps", "%s", TLS1_3_VERSION_DRAFT_TXT); + Dbg(dbg_ctl_quic_ps, "%s", TLS1_3_VERSION_DRAFT_TXT); #endif return 0; @@ -138,7 +147,7 @@ QUICNetProcessor::allocate_vc(EThread *t) Action * QUICNetProcessor::connect_re(Continuation *cont, sockaddr const *remote_addr, NetVCOptions const &opt) { - Debug("quic_ps", "connect to server"); + Dbg(dbg_ctl_quic_ps, "connect to server"); EThread *t = cont->mutex->thread_holding; ink_assert(t); @@ -156,7 +165,7 @@ QUICNetProcessor::connect_re(Continuation *cont, sockaddr const *remote_addr, Ne // Setup UDPConnection UnixUDPConnection *con = new UnixUDPConnection(fd); - Debug("quic_ps", "con=%p fd=%d", con, fd); + Dbg(dbg_ctl_quic_ps, "con=%p fd=%d", con, fd); QUICPacketHandlerOut *packet_handler = new QUICPacketHandlerOut(); if (opt.local_ip.isValid()) { @@ -170,7 +179,7 @@ QUICNetProcessor::connect_re(Continuation *cont, sockaddr const *remote_addr, Ne errno = 0; int res = con->ep.start(pd, con, get_UDPNetHandler(cont->getThreadAffinity()), EVENTIO_READ); if (res < 0) { - Debug("udpnet", "Error: %s (%d)", strerror(errno), errno); + Dbg(dbg_ctl_udpnet, "Error: %s (%d)", strerror(errno), errno); } // Setup QUICNetVConnection @@ -213,8 +222,8 @@ Action * QUICNetProcessor::main_accept(Continuation *cont, SOCKET fd, AcceptOptions const &opt) { // UnixNetProcessor *this_unp = static_cast<UnixNetProcessor *>(this); - Debug("iocore_net_processor", "NetProcessor::main_accept - port %d,recv_bufsize %d, send_bufsize %d, sockopt 0x%0x", - opt.local_port, opt.recv_bufsize, opt.send_bufsize, opt.sockopt_flags); + Dbg(dbg_ctl_iocore_net_processor, "NetProcessor::main_accept - port %d,recv_bufsize %d, send_bufsize %d, sockopt 0x%0x", + opt.local_port, opt.recv_bufsize, opt.send_bufsize, opt.sockopt_flags); int accept_threads = opt.accept_threads; // might be changed. IpEndpoint accept_ip; // local binding address. diff --git a/src/iocore/net/QUICNetVConnection.cc b/src/iocore/net/QUICNetVConnection.cc index c406799a68..2348cb36b2 100644 --- a/src/iocore/net/QUICNetVConnection.cc +++ b/src/iocore/net/QUICNetVConnection.cc @@ -30,10 +30,17 @@ #include <netinet/in.h> #include <quiche.h> -static constexpr ink_hrtime WRITE_READY_INTERVAL = HRTIME_MSECONDS(2); +namespace +{ +constexpr ink_hrtime WRITE_READY_INTERVAL = HRTIME_MSECONDS(2); + +DbgCtl dbg_ctl_quic_net{"quic_net"}; +DbgCtl dbg_ctl_v_quic_net{"v_quic_net"}; + +} // end anonymous namespace -#define QUICConDebug(fmt, ...) Debug("quic_net", "[%s] " fmt, this->cids().data(), ##__VA_ARGS__) -#define QUICConVDebug(fmt, ...) Debug("v_quic_net", "[%s] " fmt, this->cids().data(), ##__VA_ARGS__) +#define QUICConDebug(fmt, ...) Dbg(dbg_ctl_quic_net, "[%s] " fmt, this->cids().data(), ##__VA_ARGS__) +#define QUICConVDebug(fmt, ...) Dbg(dbg_ctl_v_quic_net, "[%s] " fmt, this->cids().data(), ##__VA_ARGS__) ClassAllocator<QUICNetVConnection> quicNetVCAllocator("quicNetVCAllocator"); diff --git a/src/iocore/net/QUICNextProtocolAccept.cc b/src/iocore/net/QUICNextProtocolAccept.cc index 1ece9d017c..99c09a282c 100644 --- a/src/iocore/net/QUICNextProtocolAccept.cc +++ b/src/iocore/net/QUICNextProtocolAccept.cc @@ -23,7 +23,11 @@ #include "P_QUICNextProtocolAccept.h" -static QUICNetVConnection * +namespace +{ +DbgCtl dbg_ctl_v_quic{"v_quic"}; + +QUICNetVConnection * quic_netvc_cast(int event, void *edata) { union { @@ -46,12 +50,14 @@ quic_netvc_cast(int event, void *edata) } } +} // namespace + int QUICNextProtocolAccept::mainEvent(int event, void *edata) { QUICNetVConnection *netvc = quic_netvc_cast(event, edata); - Debug("v_quic", "[%s] event %d netvc %p", netvc->cids().data(), event, netvc); + Dbg(dbg_ctl_v_quic, "[%s] event %d netvc %p", netvc->cids().data(), event, netvc); switch (event) { case NET_EVENT_ACCEPT: ink_release_assert(netvc != nullptr); diff --git a/src/iocore/net/QUICPacketHandler.cc b/src/iocore/net/QUICPacketHandler.cc index 7ca3af1929..26d3883d99 100644 --- a/src/iocore/net/QUICPacketHandler.cc +++ b/src/iocore/net/QUICPacketHandler.cc @@ -34,14 +34,21 @@ #include "swoc/BufferWriter.h" -static constexpr char debug_tag[] = "quic_sec"; -static constexpr char v_debug_tag[] = "v_quic_sec"; +namespace +{ +constexpr char debug_tag[] = "quic_sec"; +constexpr char v_debug_tag[] = "v_quic_sec"; + +DbgCtl dbg_ctl{debug_tag}; +DbgCtl dbg_ctl_v{v_debug_tag}; +DbgCtl dbg_ctl_quic_sec{"quic_sec"}; + +} // end anonymous namespace -#define QUICDebug(fmt, ...) Debug(debug_tag, fmt, ##__VA_ARGS__) -#define QUICPHDebug(dcid, scid, fmt, ...) \ - Debug(debug_tag, "[%08" PRIx32 "-%08" PRIx32 "] " fmt, dcid.h32(), scid.h32(), ##__VA_ARGS__) +#define QUICDebug(fmt, ...) Dbg(dbg_ctl, fmt, ##__VA_ARGS__) +#define QUICPHDebug(dcid, scid, fmt, ...) Dbg(dbg_ctl, "[%08" PRIx32 "-%08" PRIx32 "] " fmt, dcid.h32(), scid.h32(), ##__VA_ARGS__) #define QUICVPHDebug(dcid, scid, fmt, ...) \ - Debug(v_debug_tag, "[%08" PRIx32 "-%08" PRIx32 "] " fmt, dcid.h32(), scid.h32(), ##__VA_ARGS__) + Dbg(dbg_ctl_v, "[%08" PRIx32 "-%08" PRIx32 "] " fmt, dcid.h32(), scid.h32(), ##__VA_ARGS__) QUICPacketHandler::QUICPacketHandler() { @@ -77,7 +84,7 @@ QUICPacketHandler::send_packet(UDPConnection *udp_con, IpEndpoint &addr, Ptr<IOB { UDPPacket *udp_packet = UDPPacket::new_UDPPacket(addr, 0, udp_payload, segment_size, send_at_hint); - if (is_debug_tag_set(v_debug_tag)) { + if (dbg_ctl_v.on()) { ip_port_text_buffer ipb; QUICConnectionId dcid = QUICConnectionId::ZERO(); QUICConnectionId scid = QUICConnectionId::ZERO(); @@ -263,7 +270,7 @@ QUICPacketHandlerIn::_recv_packet(int event, UDPPacket *udp_packet) QUICConnectionId original_cid = {dcid, static_cast<uint8_t>(dcid_len)}; QUICConnectionId peer_cid = {scid, static_cast<uint8_t>(scid_len)}; - if (is_debug_tag_set("quic_sec")) { + if (dbg_ctl_quic_sec.on()) { QUICPHDebug(peer_cid, original_cid, "client initial dcid=%s", original_cid.hex().c_str()); } diff --git a/src/iocore/net/ReadWriteEventIO.cc b/src/iocore/net/ReadWriteEventIO.cc index f74c37beb4..e4346d9923 100644 --- a/src/iocore/net/ReadWriteEventIO.cc +++ b/src/iocore/net/ReadWriteEventIO.cc @@ -25,6 +25,12 @@ #include "iocore/net/ReadWriteEventIO.h" #include "iocore/net/NetHandler.h" +namespace +{ +DbgCtl dbg_ctl_iocore_net_main{"iocore_net_main"}; + +} // end anonymous namespace + int ReadWriteEventIO::start(EventLoop l, NetEvent *ne, NetHandler *nh, int events) { @@ -64,7 +70,7 @@ ReadWriteEventIO::process_event(int flags) _nh->write_ready_list.enqueue(_ne); } } else if (!(flags & (EVENTIO_READ))) { - Debug("iocore_net_main", "Unhandled epoll event: 0x%04x", flags); + Dbg(dbg_ctl_iocore_net_main, "Unhandled epoll event: 0x%04x", flags); // In practice we sometimes see EPOLLERR and EPOLLHUP through there // Anything else would be surprising ink_assert((flags & ~(EVENTIO_ERROR)) == 0); diff --git a/src/iocore/net/SNIActionPerformer.cc b/src/iocore/net/SNIActionPerformer.cc index 81b8bf7807..2d71a2644a 100644 --- a/src/iocore/net/SNIActionPerformer.cc +++ b/src/iocore/net/SNIActionPerformer.cc @@ -33,6 +33,14 @@ #include "P_QUICNetVConnection.h" #endif +namespace +{ +#if TS_USE_QUIC == 1 +DbgCtl dbg_ctl_ssl_sni{"ssl_sni"}; +#endif + +} // end anonymous namespace + int ControlQUIC::SNIAction(SSL &ssl, const Context &ctx) const { @@ -49,7 +57,7 @@ ControlQUIC::SNIAction(SSL &ssl, const Context &ctx) const if (dbg_ctl_ssl_sni.on()) { if (auto snis = TLSSNISupport::getInstance(&ssl)) { const char *servername = snis->get_sni_server_name(); - Dbg(dbg_ctl_ssl_sni, "Rejecting handshake due to QUIC being disabled for fqdn [%s]", servername); + DbgPrint(dbg_ctl_ssl_sni, "Rejecting handshake due to QUIC being disabled for fqdn [%s]", servername); } } @@ -185,7 +193,7 @@ TunnelDestination::SNIAction(SSL &ssl, const Context &ctx) const const char *servername = snis->get_sni_server_name(); if (fnArrIndexes.empty()) { tuns->set_tunnel_destination(destination, type, !TLSTunnelSupport::PORT_IS_DYNAMIC, tunnel_prewarm); - Debug("ssl_sni", "Destination now is [%s], fqdn [%s]", destination.c_str(), servername); + Dbg(dbg_ctl_ssl_sni, "Destination now is [%s], fqdn [%s]", destination.c_str(), servername); } else { bool port_is_dynamic = false; auto fixed_dst{destination}; @@ -195,7 +203,7 @@ TunnelDestination::SNIAction(SSL &ssl, const Context &ctx) const fixed_dst = fix_destination[fnArrIndex](fixed_dst, var_start_pos, ctx, ssl_netvc, port_is_dynamic); } tuns->set_tunnel_destination(fixed_dst, type, port_is_dynamic, tunnel_prewarm); - Debug("ssl_sni", "Destination now is [%s], configured [%s], fqdn [%s]", fixed_dst.c_str(), destination.c_str(), servername); + Dbg(dbg_ctl_ssl_sni, "Destination now is [%s], configured [%s], fqdn [%s]", fixed_dst.c_str(), destination.c_str(), servername); } if (type == SNIRoutingType::BLIND) { diff --git a/src/iocore/net/SSLCertLookup.cc b/src/iocore/net/SSLCertLookup.cc index 0f9be8675a..12edd1afe6 100644 --- a/src/iocore/net/SSLCertLookup.cc +++ b/src/iocore/net/SSLCertLookup.cc @@ -40,6 +40,12 @@ #include <vector> #include <openssl/rand.h> +namespace +{ +DbgCtl dbg_ctl_ssl{"ssl"}; + +} // end anonymous namespace + struct SSLAddressLookupKey { explicit SSLAddressLookupKey(const IpEndpoint &ip) { @@ -117,7 +123,7 @@ private: void Print() const { - Debug("ssl", "Item=%p SSL_CTX=#%d", this, idx); + Dbg(dbg_ctl_ssl, "Item=%p SSL_CTX=#%d", this, idx); } int idx = -1; ///< Index in the context store. LINK(ContextRef, link); ///< Require by @c Trie @@ -171,7 +177,7 @@ ticket_block_create(char *ticket_key_data, int ticket_key_len) Error("SSL session ticket key is too short (>= 48 bytes are required)"); goto fail; } - Debug("ssl", "Create %d ticket key blocks", num_ticket_keys); + Dbg(dbg_ctl_ssl, "Create %d ticket key blocks", num_ticket_keys); keyblock = ticket_block_alloc(num_ticket_keys); @@ -466,22 +472,22 @@ SSLContextStorage::insert(const char *name, int idx) } if (subdomain) { if (auto it = this->wilddomains.find(subdomain); it != this->wilddomains.end()) { - Debug("ssl", "previously indexed '%s' with SSL_CTX #%d, cannot index it with SSL_CTX #%d now", lower_case_name, it->second, - idx); + Dbg(dbg_ctl_ssl, "previously indexed '%s' with SSL_CTX #%d, cannot index it with SSL_CTX #%d now", lower_case_name, + it->second, idx); idx = -1; } else { this->wilddomains.emplace(subdomain, idx); - Debug("ssl", "indexed '%s' with SSL_CTX %p [%d]", lower_case_name, ctx.get(), idx); + Dbg(dbg_ctl_ssl, "indexed '%s' with SSL_CTX %p [%d]", lower_case_name, ctx.get(), idx); } } } else { if (auto it = this->hostnames.find(lower_case_name); it != this->hostnames.end() && idx != it->second) { - Debug("ssl", "previously indexed '%s' with SSL_CTX %d, cannot index it with SSL_CTX #%d now", lower_case_name, it->second, - idx); + Dbg(dbg_ctl_ssl, "previously indexed '%s' with SSL_CTX %d, cannot index it with SSL_CTX #%d now", lower_case_name, it->second, + idx); idx = -1; } else { this->hostnames.emplace(lower_case_name, idx); - Debug("ssl", "indexed '%s' with SSL_CTX %p [%d]", lower_case_name, ctx.get(), idx); + Dbg(dbg_ctl_ssl, "indexed '%s' with SSL_CTX %p [%d]", lower_case_name, ctx.get(), idx); } } return idx; @@ -491,7 +497,7 @@ void SSLContextStorage::printWildDomains() const { for (auto &&it : this->wilddomains) { - Debug("ssl", "Stored wilddomain %s", it.first.c_str()); + Dbg(dbg_ctl_ssl, "Stored wilddomain %s", it.first.c_str()); } } diff --git a/src/iocore/net/SSLClientUtils.cc b/src/iocore/net/SSLClientUtils.cc index 3d0880ada5..51b6d4a897 100644 --- a/src/iocore/net/SSLClientUtils.cc +++ b/src/iocore/net/SSLClientUtils.cc @@ -39,6 +39,13 @@ SSLOriginSessionCache *origin_sess_cache; +namespace +{ +DbgCtl dbg_ctl_ssl_verify{"ssl_verify"}; +DbgCtl dbg_ctl_ssl_origin_session_cache{"ssl.origin_session_cache"}; + +} // end anonymous namespace + int verify_callback(int signature_ok, X509_STORE_CTX *ctx) { @@ -47,7 +54,7 @@ verify_callback(int signature_ok, X509_STORE_CTX *ctx) int err; SSL *ssl; - Debug("ssl_verify", "Entered cert verify callback"); + Dbg(dbg_ctl_ssl_verify, "Entered cert verify callback"); /* * Retrieve the pointer to the SSL of the connection currently treated @@ -59,7 +66,7 @@ verify_callback(int signature_ok, X509_STORE_CTX *ctx) // No enforcing, go away if (netvc == nullptr) { // No netvc, very bad. Go away. Things are not good. - Debug("ssl_verify", "WARNING, NetVC is NULL in cert verify callback"); + Dbg(dbg_ctl_ssl_verify, "WARNING, NetVC is NULL in cert verify callback"); return false; } else if (netvc->options.verifyServerPolicy == YamlSNIConfig::Policy::DISABLED) { return true; // Tell them that all is well @@ -75,7 +82,7 @@ verify_callback(int signature_ok, X509_STORE_CTX *ctx) if (check_sig) { if (!signature_ok) { - Debug("ssl_verify", "verification error:num=%d:%s:depth=%d", err, X509_verify_cert_error_string(err), depth); + Dbg(dbg_ctl_ssl_verify, "verification error:num=%d:%s:depth=%d", err, X509_verify_cert_error_string(err), depth); const char *sni_name; char buff[INET6_ADDRSTRLEN]; ats_ip_ntop(netvc->get_remote_addr(), buff, INET6_ADDRSTRLEN); @@ -110,7 +117,7 @@ verify_callback(int signature_ok, X509_STORE_CTX *ctx) ats_ip_ntop(netvc->get_remote_addr(), buff, INET6_ADDRSTRLEN); } if (validate_hostname(cert, sni_name, false, &matched_name)) { - Debug("ssl_verify", "Hostname %s verified OK, matched %s", sni_name, matched_name); + Dbg(dbg_ctl_ssl_verify, "Hostname %s verified OK, matched %s", sni_name, matched_name); ats_free(matched_name); } else { // Name validation failed // Get the server address if we did't already compute it @@ -156,7 +163,7 @@ ssl_client_cert_callback(SSL *ssl, void * /*arg*/) // both are internal pointers X509 *cert = SSL_CTX_get0_certificate(ctx); netvc->set_sent_cert(cert != nullptr ? 2 : 1); - Debug("ssl_verify", "sent cert: %d", cert != nullptr ? 2 : 1); + Dbg(dbg_ctl_ssl_verify, "sent cert: %d", cert != nullptr ? 2 : 1); } return 1; } @@ -170,9 +177,7 @@ ssl_new_session_callback(SSL *ssl, SSL_SESSION *sess) swoc::bwprint(lookup_key, "{}:{}:{}", sni_addr.c_str(), SSL_get_SSL_CTX(ssl), get_verify_str(ssl)); origin_sess_cache->insert_session(lookup_key, sess, ssl); } else { - if (is_debug_tag_set("ssl.origin_session_cache")) { - Debug("ssl.origin_session_cache", "Failed to fetch SNI/IP."); - } + Dbg(dbg_ctl_ssl_origin_session_cache, "Failed to fetch SNI/IP."); } // return 0 here since we're converting the sessions using i2d_SSL_SESSION, diff --git a/src/iocore/net/SSLConfig.cc b/src/iocore/net/SSLConfig.cc index 846dc24613..45d8e93aca 100644 --- a/src/iocore/net/SSLConfig.cc +++ b/src/iocore/net/SSLConfig.cc @@ -84,7 +84,15 @@ bool SSLConfigParams::server_allow_early_data_params = false; int SSLConfigParams::async_handshake_enabled = 0; char *SSLConfigParams::engine_conf_file = nullptr; -static std::unique_ptr<ConfigUpdateHandler<SSLTicketKeyConfig>> sslTicketKey; +namespace +{ +std::unique_ptr<ConfigUpdateHandler<SSLTicketKeyConfig>> sslTicketKey; + +DbgCtl dbg_ctl_ssl_load{"ssl_load"}; +DbgCtl dbg_ctl_ssl_config_updateCTX{"ssl_config_updateCTX"}; +DbgCtl dbg_ctl_ssl_client_ctx{"ssl_client_ctx"}; + +} // end anonymous namespace SSLConfigParams::SSLConfigParams() { @@ -194,10 +202,10 @@ UpdateServerPolicy(const char * /* name ATS_UNUSED */, RecDataT /* data_type ATS SSLConfigParams *params = SSLConfig::acquire(); char *verify_server = data.rec_string; if (params != nullptr && verify_server != nullptr) { - Debug("ssl_load", "New Server Policy %s", verify_server); + Dbg(dbg_ctl_ssl_load, "New Server Policy %s", verify_server); params->SetServerPolicy(verify_server); } else { - Debug("ssl_load", "Failed to load new Server Policy %p %p", verify_server, params); + Dbg(dbg_ctl_ssl_load, "Failed to load new Server Policy %p %p", verify_server, params); } return 0; } @@ -587,7 +595,7 @@ SSLConfig::startup() void SSLConfig::reconfigure() { - Debug("ssl_load", "Reload SSLConfig"); + Dbg(dbg_ctl_ssl_load, "Reload SSLConfig"); SSLConfigParams *params; params = new SSLConfigParams; // start loading the next config @@ -646,7 +654,7 @@ SSLCertificateConfig::reconfigure() // twice the healthcheck period to simulate a loading a large certificate set. if (is_action_tag_set("test.multicert.delay")) { const int secs = 60; - Debug("ssl_load", "delaying certificate reload by %d secs", secs); + Dbg(dbg_ctl_ssl_load, "delaying certificate reload by %d secs", secs); ink_hrtime_sleep(HRTIME_SECONDS(secs)); } @@ -726,7 +734,7 @@ SSLTicketParams::LoadTicket(bool &nochange) struct stat sdata; if (last_load_time && (stat(ticket_key_filename, &sdata) >= 0)) { if (sdata.st_mtime && sdata.st_mtime <= last_load_time) { - Debug("ssl_load", "ticket key %s has not changed", ticket_key_filename); + Dbg(dbg_ctl_ssl_load, "ticket key %s has not changed", ticket_key_filename); // No updates since last load return true; } @@ -748,7 +756,7 @@ SSLTicketParams::LoadTicket(bool &nochange) default_global_keyblock = keyblock; load_time = time(nullptr); - Debug("ssl_load", "ticket key reloaded from %s", ticket_key_filename); + Dbg(dbg_ctl_ssl_load, "ticket key reloaded from %s", ticket_key_filename); #endif return true; } @@ -840,25 +848,26 @@ cleanup_bio(BIO *&biop) void SSLConfigParams::updateCTX(const std::string &cert_secret_name) const { - Debug("ssl_config_updateCTX", "Update cert %s, %p", cert_secret_name.c_str(), this); + Dbg(dbg_ctl_ssl_config_updateCTX, "Update cert %s, %p", cert_secret_name.c_str(), this); // Instances of SSLConfigParams should access by one thread at a time only. secret_for_updateCTX is accessed // atomically as a fail-safe. // char const *expected = nullptr; if (!secret_for_updateCTX.compare_exchange_strong(expected, cert_secret_name.c_str())) { - if (is_debug_tag_set("ssl_config_updateCTX")) { + if (dbg_ctl_ssl_config_updateCTX.on()) { // As a fail-safe, handle it if secret_for_updateCTX doesn't or no longer points to a null-terminated string. // char const *s{expected}; for (; *s && (std::size_t(s - expected) < cert_secret_name.size()); ++s) {} - Debug("ssl_config_updateCTX", "Update cert, indirect recusive call caused by call for %.*s", int(s - expected), expected); + DbgPrint(dbg_ctl_ssl_config_updateCTX, "Update cert, indirect recusive call caused by call for %.*s", int(s - expected), + expected); } return; } // Clear the corresponding client CTXs. They will be lazy loaded later - Debug("ssl_load", "Update cert %s", cert_secret_name.c_str()); + Dbg(dbg_ctl_ssl_load, "Update cert %s", cert_secret_name.c_str()); this->clearCTX(cert_secret_name); // Update the server cert @@ -876,7 +885,7 @@ SSLConfigParams::clearCTX(const std::string &client_cert) const auto ctx_iter = ctx_map_iter->second.find(client_cert); if (ctx_iter != ctx_map_iter->second.end()) { ctx_iter->second = nullptr; - Debug("ssl_load", "Clear client cert %s %s", ctx_map_iter->first.c_str(), ctx_iter->first.c_str()); + Dbg(dbg_ctl_ssl_load, "Clear client cert %s %s", ctx_map_iter->first.c_str(), ctx_iter->first.c_str()); } } ink_mutex_release(&ctxMapLock); @@ -898,7 +907,7 @@ SSLConfigParams::getCTX(const std::string &client_cert, const std::string &key_f ctx_key = client_cert; swoc::bwprint(top_level_key, "{}:{}", ca_bundle_file, ca_bundle_path); - Debug("ssl_client_ctx", "Look for client cert \"%s\" \"%s\"", top_level_key.c_str(), ctx_key.c_str()); + Dbg(dbg_ctl_ssl_client_ctx, "Look for client cert \"%s\" \"%s\"", top_level_key.c_str(), ctx_key.c_str()); ink_mutex_acquire(&ctxMapLock); auto ctx_map_iter = top_level_ctx_map.find(top_level_key); @@ -915,7 +924,7 @@ SSLConfigParams::getCTX(const std::string &client_cert, const std::string &key_f EVP_PKEY *key = nullptr; // Create context if doesn't exists if (!client_ctx) { - Debug("ssl_client_ctx", "Load new cert for %s %s", top_level_key.c_str(), ctx_key.c_str()); + Dbg(dbg_ctl_ssl_client_ctx, "Load new cert for %s %s", top_level_key.c_str(), ctx_key.c_str()); client_ctx = shared_SSL_CTX(SSLInitClientContext(this), SSLReleaseContext); // Upon configuration, elevate file access to be able to read root-only diff --git a/src/iocore/net/SSLDynlock.cc b/src/iocore/net/SSLDynlock.cc index a3162804e9..c7a790f666 100644 --- a/src/iocore/net/SSLDynlock.cc +++ b/src/iocore/net/SSLDynlock.cc @@ -34,10 +34,17 @@ struct CRYPTO_dynlock_value { ink_mutex mutex; }; +namespace +{ +DbgCtl dbg_ctl_v_ssl_lock{"v_ssl_lock"}; +DbgCtl dbg_ctl_ssl{"ssl"}; + +} // end anonymous namespace + struct CRYPTO_dynlock_value * ssl_dyn_create_callback(const char *file, int line) { - Debug("v_ssl_lock", "file: %s line: %d", file, line); + Dbg(dbg_ctl_v_ssl_lock, "file: %s line: %d", file, line); CRYPTO_dynlock_value *value = new CRYPTO_dynlock_value(file, line); return value; @@ -48,14 +55,14 @@ ssl_dyn_create_callback(const char *file, int line) void ssl_dyn_lock_callback(int mode, struct CRYPTO_dynlock_value *value, const char *file, int line) { - Debug("v_ssl_lock", "file: %s line: %d", file, line); + Dbg(dbg_ctl_v_ssl_lock, "file: %s line: %d", file, line); if (mode & CRYPTO_LOCK) { ink_mutex_acquire(&value->mutex); } else if (mode & CRYPTO_UNLOCK) { ink_mutex_release(&value->mutex); } else { - Debug("ssl", "invalid SSL locking mode 0x%x", mode); + Dbg(dbg_ctl_ssl, "invalid SSL locking mode 0x%x", mode); ink_release_assert(0); } } @@ -64,6 +71,6 @@ ssl_dyn_lock_callback(int mode, struct CRYPTO_dynlock_value *value, const char * void ssl_dyn_destroy_callback(struct CRYPTO_dynlock_value *value, const char *file, int line) { - Debug("v_ssl_lock", "file: %s line: %d", file, line); + Dbg(dbg_ctl_v_ssl_lock, "file: %s line: %d", file, line); delete value; } diff --git a/src/iocore/net/SSLNetVConnection.cc b/src/iocore/net/SSLNetVConnection.cc index 3cad1ba2eb..4d0e2d9a24 100644 --- a/src/iocore/net/SSLNetVConnection.cc +++ b/src/iocore/net/SSLNetVConnection.cc @@ -2237,7 +2237,7 @@ SSLNetVConnection::_getNetProcessor() void SSLNetVConnection::_propagateHandShakeBuffer(UnixNetVConnection *target, EThread *t) { - Debug("ssl", "allow-plain, handshake buffer ready to read=%" PRId64, this->handShakeHolder->read_avail()); + Dbg(dbg_ctl_ssl, "allow-plain, handshake buffer ready to read=%" PRId64, this->handShakeHolder->read_avail()); // Take ownership of the handShake buffer this->sslHandshakeStatus = SSLHandshakeStatus::SSL_HANDSHAKE_DONE; NetState *s = &target->read; @@ -2287,7 +2287,7 @@ SSLNetVConnection::_migrateFromSSL() ink_assert(newvc != nullptr); if (newvc != nullptr && newvc->populate(hold_con, this->read.vio.cont, nullptr) != EVENT_DONE) { newvc->do_io_close(); - Debug("ssl", "Failed to populate unixvc for allow-plain"); + Dbg(dbg_ctl_ssl, "Failed to populate unixvc for allow-plain"); newvc = nullptr; } if (newvc != nullptr) { @@ -2295,7 +2295,7 @@ SSLNetVConnection::_migrateFromSSL() newvc->set_is_transparent(this->is_transparent); newvc->set_context(get_context()); newvc->options = this->options; - Debug("ssl", "Move to unixvc for allow-plain"); + Dbg(dbg_ctl_ssl, "Move to unixvc for allow-plain"); this->_propagateHandShakeBuffer(newvc, t); } diff --git a/src/iocore/net/SSLNextProtocolAccept.cc b/src/iocore/net/SSLNextProtocolAccept.cc index 2f73efbdcc..b66b60dcd6 100644 --- a/src/iocore/net/SSLNextProtocolAccept.cc +++ b/src/iocore/net/SSLNextProtocolAccept.cc @@ -24,7 +24,11 @@ #include "P_SSLNextProtocolAccept.h" #include "P_SSLNetVConnection.h" -static void +namespace +{ +DbgCtl dbg_ctl_ssl{"ssl"}; + +void send_plugin_event(Continuation *plugin, int event, void *edata) { if (plugin->mutex) { @@ -35,7 +39,7 @@ send_plugin_event(Continuation *plugin, int event, void *edata) } } -static SSLNetVConnection * +SSLNetVConnection * ssl_netvc_cast(int event, void *edata) { union { @@ -58,6 +62,8 @@ ssl_netvc_cast(int event, void *edata) } } +} // end anonymous namespace + // SSLNextProtocolTrampoline is the receiver of the I/O event generated when we perform a 0-length read on the new SSL // connection. The 0-length read forces the SSL handshake, which allows us to bind an endpoint that is selected by the // NPN extension. The Continuation that receives the read event *must* have a mutex, but we don't want to take a global @@ -134,7 +140,7 @@ SSLNextProtocolAccept::mainEvent(int event, void *edata) { SSLNetVConnection *netvc = ssl_netvc_cast(event, edata); - Debug("ssl", "[SSLNextProtocolAccept:mainEvent] event %d netvc %p", event, netvc); + Dbg(dbg_ctl_ssl, "[SSLNextProtocolAccept:mainEvent] event %d netvc %p", event, netvc); switch (event) { case NET_EVENT_ACCEPT: ink_release_assert(netvc != nullptr); diff --git a/src/iocore/net/SSLNextProtocolSet.cc b/src/iocore/net/SSLNextProtocolSet.cc index 7fe825104c..db8ccdd934 100644 --- a/src/iocore/net/SSLNextProtocolSet.cc +++ b/src/iocore/net/SSLNextProtocolSet.cc @@ -27,6 +27,12 @@ #include "P_SSLNextProtocolSet.h" #include "swoc/TextView.h" +namespace +{ +DbgCtl dbg_ctl_ssl{"ssl"}; + +} // end anonymous namespace + // For currently defined protocol strings, see // http://technotes.googlecode.com/git/nextprotoneg.html. The OpenSSL // documentation tells us to return a string in "wire format". The @@ -67,7 +73,7 @@ SSLNextProtocolSet::create_npn_advertisement(const SessionProtocolSet &enabled, for (ep = endpoints.head; ep != nullptr; ep = endpoints.next(ep)) { if (enabled.contains(globalSessionProtocolNameRegistry.toIndex(swoc::TextView{ep->protocol, strlen(ep->protocol)}))) { - Debug("ssl", "advertising protocol %s, %p", ep->protocol, ep->endpoint); + Dbg(dbg_ctl_ssl, "advertising protocol %s, %p", ep->protocol, ep->endpoint); advertised = append_protocol(ep->protocol, advertised); } } diff --git a/src/iocore/net/SSLSNIConfig.cc b/src/iocore/net/SSLSNIConfig.cc index e3c32650ff..43e4d76e26 100644 --- a/src/iocore/net/SSLSNIConfig.cc +++ b/src/iocore/net/SSLSNIConfig.cc @@ -53,13 +53,14 @@ #include <algorithm> #include <functional> -static constexpr int OVECSIZE{30}; - -static DbgCtl dbg_ctl_ssl{"ssl"}; -static DbgCtl dbg_ctl_ssl_sni{"ssl_sni"}; - namespace { +constexpr int OVECSIZE{30}; + +DbgCtl dbg_ctl_ssl{"ssl"}; +DbgCtl dbg_ctl_ssl_sni{"ssl_sni"}; +DbgCtl dbg_ctl_sni{"sni"}; + bool is_port_in_the_ranges(const std::vector<ts::port_range_t> &port_ranges, in_port_t port) { @@ -217,11 +218,11 @@ SNIConfigParams::get(std::string_view servername, in_port_t dest_incoming_port) char lower_case_name[TS_MAX_HOST_NAME_LEN + 1]; ts::transform_lower(servername, lower_case_name); - Debug("sni", "lower_case_name=%s", lower_case_name); + Dbg(dbg_ctl_sni, "lower_case_name=%s", lower_case_name); auto range = sni_action_map.equal_range(lower_case_name); for (auto it = range.first; it != range.second; ++it) { - Debug("sni", "match with %s", it->first.c_str()); + Dbg(dbg_ctl_sni, "match with %s", it->first.c_str()); if (!is_port_in_the_ranges(it->second.inbound_port_ranges, dest_incoming_port)) { continue; diff --git a/src/iocore/net/SSLSessionCache.cc b/src/iocore/net/SSLSessionCache.cc index fa9394c54d..90eaceec23 100644 --- a/src/iocore/net/SSLSessionCache.cc +++ b/src/iocore/net/SSLSessionCache.cc @@ -37,11 +37,22 @@ #define PRINT_BUCKET(x) #endif +namespace +{ +DbgCtl dbg_ctl_ssl_origin_session_cache{"ssl.origin_session_cache"}; +DbgCtl dbg_ctl_ssl_session_cache{"ssl.session_cache"}; +DbgCtl dbg_ctl_ssl_session_cache_bucket{"ssl.session_cache.bucket"}; +DbgCtl dbg_ctl_ssl_session_cache_get{"ssl.session_cache.get"}; +DbgCtl dbg_ctl_ssl_session_cache_insert{"ssl.session_cache.insert"}; +DbgCtl dbg_ctl_ssl_session_cache_remove{"ssl.session_cache.remove"}; + +} // end anonymous namespace + /* Session Cache */ SSLSessionCache::SSLSessionCache() : nbuckets(SSLConfigParams::session_cache_number_buckets) { - Debug("ssl.session_cache", "Created new ssl session cache %p with %zu buckets each with size max size %zu", this, nbuckets, - SSLConfigParams::session_cache_max_bucket_size); + Dbg(dbg_ctl_ssl_session_cache, "Created new ssl session cache %p with %zu buckets each with size max size %zu", this, nbuckets, + SSLConfigParams::session_cache_max_bucket_size); session_bucket = new SSLSessionBucket[nbuckets]; } @@ -68,11 +79,11 @@ SSLSessionCache::getSession(const SSLSessionID &sid, SSL_SESSION **sess, ssl_ses uint64_t target_bucket = hash % nbuckets; SSLSessionBucket *bucket = &session_bucket[target_bucket]; - if (is_debug_tag_set("ssl.session_cache")) { + if (dbg_ctl_ssl_session_cache.on()) { char buf[sid.len * 2 + 1]; sid.toString(buf, sizeof(buf)); - Debug("ssl.session_cache.get", "SessionCache looking in bucket %" PRId64 " (%p) for session '%s' (hash: %" PRIX64 ").", - target_bucket, bucket, buf, hash); + DbgPrint(dbg_ctl_ssl_session_cache_get, "SessionCache looking in bucket %" PRId64 " (%p) for session '%s' (hash: %" PRIX64 ").", + target_bucket, bucket, buf, hash); } return bucket->getSession(sid, sess, data); @@ -85,11 +96,12 @@ SSLSessionCache::removeSession(const SSLSessionID &sid) uint64_t target_bucket = hash % nbuckets; SSLSessionBucket *bucket = &session_bucket[target_bucket]; - if (is_debug_tag_set("ssl.session_cache")) { + if (dbg_ctl_ssl_session_cache_remove.on()) { char buf[sid.len * 2 + 1]; sid.toString(buf, sizeof(buf)); - Debug("ssl.session_cache.remove", "SessionCache using bucket %" PRId64 " (%p): Removing session '%s' (hash: %" PRIX64 ").", - target_bucket, bucket, buf, hash); + DbgPrint(dbg_ctl_ssl_session_cache_remove, + "SessionCache using bucket %" PRId64 " (%p): Removing session '%s' (hash: %" PRIX64 ").", target_bucket, bucket, buf, + hash); } Metrics::Counter::increment(ssl_rsb.session_cache_eviction); @@ -103,11 +115,12 @@ SSLSessionCache::insertSession(const SSLSessionID &sid, SSL_SESSION *sess, SSL * uint64_t target_bucket = hash % nbuckets; SSLSessionBucket *bucket = &session_bucket[target_bucket]; - if (is_debug_tag_set("ssl.session_cache")) { + if (dbg_ctl_ssl_session_cache_insert.on()) { char buf[sid.len * 2 + 1]; sid.toString(buf, sizeof(buf)); - Debug("ssl.session_cache.insert", "SessionCache using bucket %" PRId64 " (%p): Inserting session '%s' (hash: %" PRIX64 ").", - target_bucket, bucket, buf, hash); + DbgPrint(dbg_ctl_ssl_session_cache_insert, + "SessionCache using bucket %" PRId64 " (%p): Inserting session '%s' (hash: %" PRIX64 ").", target_bucket, bucket, buf, + hash); } bucket->insertSession(sid, sess, ssl); @@ -135,14 +148,15 @@ SSLSessionBucket::insertSession(const SSLSessionID &id, SSL_SESSION *sess, SSL * size_t len = i2d_SSL_SESSION(sess, nullptr); // make sure we're not going to need more than SSL_MAX_SESSION_SIZE bytes /* do not cache a session that's too big. */ if (len > static_cast<size_t>(SSL_MAX_SESSION_SIZE)) { - Debug("ssl.session_cache", "Unable to save SSL session because size of %zd exceeds the max of %d", len, SSL_MAX_SESSION_SIZE); + Dbg(dbg_ctl_ssl_session_cache, "Unable to save SSL session because size of %zd exceeds the max of %d", len, + SSL_MAX_SESSION_SIZE); return; } - if (is_debug_tag_set("ssl.session_cache")) { + if (dbg_ctl_ssl_session_cache.on()) { char buf[id.len * 2 + 1]; id.toString(buf, sizeof(buf)); - Debug("ssl.session_cache", "Inserting session '%s' to bucket %p.", buf, this); + DbgPrint(dbg_ctl_ssl_session_cache, "Inserting session '%s' to bucket %p.", buf, this); } Ptr<IOBufferData> buf; @@ -214,11 +228,11 @@ SSLSessionBucket::getSession(const SSLSessionID &id, SSL_SESSION **sess, ssl_ses { char buf[id.len * 2 + 1]; buf[0] = '\0'; // just to be safe. - if (is_debug_tag_set("ssl.session_cache")) { + if (dbg_ctl_ssl_session_cache.on()) { id.toString(buf, sizeof(buf)); } - Debug("ssl.session_cache", "Looking for session with id '%s' in bucket %p", buf, this); + Dbg(dbg_ctl_ssl_session_cache, "Looking for session with id '%s' in bucket %p", buf, this); std::shared_lock lock(mutex, std::try_to_lock); if (!lock.owns_lock()) { @@ -233,7 +247,7 @@ SSLSessionBucket::getSession(const SSLSessionID &id, SSL_SESSION **sess, ssl_ses auto entry = bucket_map.find(id); if (entry == bucket_map.end()) { - Debug("ssl.session_cache", "Session with id '%s' not found in bucket %p.", buf, this); + Dbg(dbg_ctl_ssl_session_cache, "Session with id '%s' not found in bucket %p.", buf, this); return false; } const unsigned char *loc = reinterpret_cast<const unsigned char *>(entry->second->asn1_data->data()); @@ -248,7 +262,7 @@ SSLSessionBucket::getSession(const SSLSessionID &id, SSL_SESSION **sess, ssl_ses void inline SSLSessionBucket::print(const char *ref_str) const { /* NOTE: This method assumes you're already holding the bucket lock */ - if (!is_debug_tag_set("ssl.session_cache.bucket")) { + if (!dbg_ctl_ssl_session_cache_bucket.on()) { return; } @@ -323,20 +337,18 @@ SSLOriginSessionCache::insert_session(const std::string &lookup_key, SSL_SESSION /* do not cache a session that's too big. */ if (len > static_cast<size_t>(SSL_MAX_ORIG_SESSION_SIZE)) { - Debug("ssl.origin_session_cache", "Unable to save SSL session because size of %zd exceeds the max of %d", len, - SSL_MAX_ORIG_SESSION_SIZE); + Dbg(dbg_ctl_ssl_origin_session_cache, "Unable to save SSL session because size of %zd exceeds the max of %d", len, + SSL_MAX_ORIG_SESSION_SIZE); return; } else if (len == 0) { - Debug("ssl.origin_session_cache", "Unable to save SSL session because size is 0"); + Dbg(dbg_ctl_ssl_origin_session_cache, "Unable to save SSL session because size is 0"); return; } // Duplicate the session from the connection, we'll be keeping track the ref-count with a shared pointer ourself SSL_SESSION *sess_ptr = SSLSessionDup(sess); - if (is_debug_tag_set("ssl.origin_session_cache")) { - Debug("ssl.origin_session_cache", "insert session: %s = %p", lookup_key.c_str(), sess_ptr); - } + Dbg(dbg_ctl_ssl_origin_session_cache, "insert session: %s = %p", lookup_key.c_str(), sess_ptr); // Create the shared pointer to the session, with the custom deleter std::shared_ptr<SSL_SESSION> shared_sess(sess_ptr, SSLSessDeleter); @@ -348,17 +360,13 @@ SSLOriginSessionCache::insert_session(const std::string &lookup_key, SSL_SESSION auto entry = orig_sess_map.find(lookup_key); if (entry != orig_sess_map.end()) { auto node = entry->second; - if (is_debug_tag_set("ssl.origin_session_cache")) { - Debug("ssl.origin_session_cache", "found duplicate key: %s, replacing %p with %p", lookup_key.c_str(), - node->shared_sess.get(), sess_ptr); - } + Dbg(dbg_ctl_ssl_origin_session_cache, "found duplicate key: %s, replacing %p with %p", lookup_key.c_str(), + node->shared_sess.get(), sess_ptr); orig_sess_que.remove(node); orig_sess_map.erase(entry); delete node; } else if (orig_sess_map.size() >= SSLConfigParams::origin_session_cache_size) { - if (is_debug_tag_set("ssl.origin_session_cache")) { - Debug("ssl.origin_session_cache", "origin session cache full, removing oldest session"); - } + Dbg(dbg_ctl_ssl_origin_session_cache, "origin session cache full, removing oldest session"); remove_oldest_session(lock); } @@ -369,9 +377,7 @@ SSLOriginSessionCache::insert_session(const std::string &lookup_key, SSL_SESSION std::shared_ptr<SSL_SESSION> SSLOriginSessionCache::get_session(const std::string &lookup_key, ssl_curve_id *curve) { - if (is_debug_tag_set("ssl.origin_session_cache")) { - Debug("ssl.origin_session_cache", "get session: %s", lookup_key.c_str()); - } + Dbg(dbg_ctl_ssl_origin_session_cache, "get session: %s", lookup_key.c_str()); std::shared_lock lock(mutex); auto entry = orig_sess_map.find(lookup_key); @@ -394,9 +400,7 @@ SSLOriginSessionCache::remove_oldest_session(const std::unique_lock<ts::shared_m while (orig_sess_que.head && orig_sess_que.size >= static_cast<int>(SSLConfigParams::origin_session_cache_size)) { auto node = orig_sess_que.pop(); - if (is_debug_tag_set("ssl.origin_session_cache")) { - Debug("ssl.origin_session_cache", "remove oldest session: %s, session ptr: %p", node->key.c_str(), node->shared_sess.get()); - } + Dbg(dbg_ctl_ssl_origin_session_cache, "remove oldest session: %s, session ptr: %p", node->key.c_str(), node->shared_sess.get()); orig_sess_map.erase(node->key); delete node; } @@ -410,9 +414,7 @@ SSLOriginSessionCache::remove_session(const std::string &lookup_key) auto entry = orig_sess_map.find(lookup_key); if (entry != orig_sess_map.end()) { auto node = entry->second; - if (is_debug_tag_set("ssl.origin_session_cache")) { - Debug("ssl.origin_session_cache", "remove session: %s, session ptr: %p", lookup_key.c_str(), node->shared_sess.get()); - } + Dbg(dbg_ctl_ssl_origin_session_cache, "remove session: %s, session ptr: %p", lookup_key.c_str(), node->shared_sess.get()); orig_sess_que.remove(node); orig_sess_map.erase(entry); delete node; diff --git a/src/iocore/net/SSLStats.cc b/src/iocore/net/SSLStats.cc index e2833da0ab..e259020de3 100644 --- a/src/iocore/net/SSLStats.cc +++ b/src/iocore/net/SSLStats.cc @@ -32,6 +32,12 @@ SSLStatsBlock ssl_rsb; std::unordered_map<std::string, Metrics::Counter::AtomicType *> cipher_map; +namespace +{ +DbgCtl dbg_ctl_ssl{"ssl"}; + +} // end anonymous namespace + // ToDo: This gets called once per global sync, for now at least. void SSLPeriodicMetricsUpdate() @@ -43,7 +49,7 @@ SSLPeriodicMetricsUpdate() int64_t misses = 0; int64_t timeouts = 0; - Debug("ssl", "Starting to update the new session metrics"); + Dbg(dbg_ctl_ssl, "Starting to update the new session metrics"); if (certLookup) { const unsigned ctxCount = certLookup->count(); for (size_t i = 0; i < ctxCount; i++) { @@ -74,7 +80,7 @@ add_cipher_stat(const char *cipherName, const std::string &statName) Metrics::Counter::AtomicType *metric = Metrics::Counter::createPtr(statName); cipher_map.emplace(cipherName, metric); - Debug("ssl", "registering SSL cipher metric '%s'", statName.c_str()); + Dbg(dbg_ctl_ssl, "registering SSL cipher metric '%s'", statName.c_str()); } } diff --git a/src/iocore/net/TLSBasicSupport.cc b/src/iocore/net/TLSBasicSupport.cc index d3fdcca619..3a7779fc4d 100644 --- a/src/iocore/net/TLSBasicSupport.cc +++ b/src/iocore/net/TLSBasicSupport.cc @@ -27,6 +27,12 @@ int TLSBasicSupport::_ex_data_index = -1; +namespace +{ +DbgCtl dbg_ctl_ssl{"ssl"}; + +} // end anonymous namespace + void TLSBasicSupport::initialize() { @@ -166,6 +172,6 @@ TLSBasicSupport::_record_tls_handshake_end_time() this->_tls_handshake_end_time = ink_get_hrtime(); const ink_hrtime ssl_handshake_time = this->_tls_handshake_end_time - this->_tls_handshake_begin_time; - Debug("ssl", "ssl handshake time:%" PRId64, ssl_handshake_time); + Dbg(dbg_ctl_ssl, "ssl handshake time:%" PRId64, ssl_handshake_time); Metrics::Counter::increment(ssl_rsb.total_handshake_time, ssl_handshake_time); } diff --git a/src/iocore/net/TLSCertSwitchSupport.cc b/src/iocore/net/TLSCertSwitchSupport.cc index f5bd680030..afe604b877 100644 --- a/src/iocore/net/TLSCertSwitchSupport.cc +++ b/src/iocore/net/TLSCertSwitchSupport.cc @@ -22,6 +22,13 @@ #include "iocore/net/TLSCertSwitchSupport.h" #include "P_SSLCertLookup.h" +namespace +{ +DbgCtl dbg_ctl_ssl{"ssl"}; +DbgCtl dbg_ctl_ssl_load{"ssl_load"}; + +} // end anonymous namespace + int TLSCertSwitchSupport::_ex_data_index = -1; void @@ -64,11 +71,11 @@ TLSCertSwitchSupport::selectCertificate(SSL *ssl, SSLCertContextType ctxType) const char *servername = SSL_get_servername(ssl, TLSEXT_NAMETYPE_host_name); bool found = true; - Debug("ssl", "set_context_cert ssl=%p server=%s", ssl, servername); + Dbg(dbg_ctl_ssl, "set_context_cert ssl=%p server=%s", ssl, servername); // catch the client renegotiation early on if (this->_isTryingRenegotiation()) { - Debug("ssl_load", "set_context_cert trying to renegotiate from the client"); + Dbg(dbg_ctl_ssl_load, "set_context_cert trying to renegotiate from the client"); return 0; } @@ -92,8 +99,8 @@ TLSCertSwitchSupport::selectCertificate(SSL *ssl, SSLCertContextType ctxType) SSL_CTX *verify_ctx = SSL_get_SSL_CTX(ssl); // set_context_cert found SSL context for ... - Debug("ssl_load", "ssl_cert_callback %s SSL context %p for requested name '%s'", found ? "found" : "using", verify_ctx, - servername); + Dbg(dbg_ctl_ssl_load, "ssl_cert_callback %s SSL context %p for requested name '%s'", found ? "found" : "using", verify_ctx, + servername); if (verify_ctx == nullptr) { return 0; diff --git a/src/iocore/net/TLSEarlyDataSupport.cc b/src/iocore/net/TLSEarlyDataSupport.cc index adfa30a202..a29cd0c1c5 100644 --- a/src/iocore/net/TLSEarlyDataSupport.cc +++ b/src/iocore/net/TLSEarlyDataSupport.cc @@ -82,22 +82,23 @@ TLSEarlyDataSupport::update_early_data_config(SSL *ssl, uint32_t max_early_data, // are calling "ssl_accept" non-blocking, it seems to be confusing the anti-replay // mechanism and causing session resumption to fail. #ifdef HAVE_SSL_SET_MAX_EARLY_DATA - bool ret1 = false; - bool ret2 = false; + static DbgCtl dbg_ctl_ssl_early_data{"ssl_early_data"}; + bool ret1 = false; + bool ret2 = false; if ((ret1 = SSL_set_max_early_data(ssl, max_early_data)) == 1) { - Debug("ssl_early_data", "SSL_set_max_early_data %u: success", max_early_data); + Dbg(dbg_ctl_ssl_early_data, "SSL_set_max_early_data %u: success", max_early_data); } else { - Debug("ssl_early_data", "SSL_set_max_early_data %u: failed", max_early_data); + Dbg(dbg_ctl_ssl_early_data, "SSL_set_max_early_data %u: failed", max_early_data); } if ((ret2 = SSL_set_recv_max_early_data(ssl, recv_max_early_data)) == 1) { - Debug("ssl_early_data", "SSL_set_recv_max_early_data %u: success", recv_max_early_data); + Dbg(dbg_ctl_ssl_early_data, "SSL_set_recv_max_early_data %u: success", recv_max_early_data); } else { - Debug("ssl_early_data", "SSL_set_recv_max_early_data %u: failed", recv_max_early_data); + Dbg(dbg_ctl_ssl_early_data, "SSL_set_recv_max_early_data %u: failed", recv_max_early_data); } if (ret1 && ret2) { - Debug("ssl_early_data", "Must disable anti-replay if 0-rtt is enabled."); + Dbg(dbg_ctl_ssl_early_data, "Must disable anti-replay if 0-rtt is enabled."); SSL_set_options(ssl, SSL_OP_NO_ANTI_REPLAY); } #else diff --git a/src/iocore/net/TLSKeyLogger.cc b/src/iocore/net/TLSKeyLogger.cc index 5873902064..d8f1e15c6e 100644 --- a/src/iocore/net/TLSKeyLogger.cc +++ b/src/iocore/net/TLSKeyLogger.cc @@ -30,6 +30,12 @@ #include <sys/uio.h> #include <unistd.h> +namespace +{ +DbgCtl dbg_ctl_ssl_keylog{"ssl_keylog"}; + +} // end anonymous namespace + // The caller of this function is responsible to acquire a unique_lock for // _mutex. void @@ -48,11 +54,11 @@ void TLSKeyLogger::enable_keylogging_internal(const char *keylog_file) { #if TS_HAS_TLS_KEYLOGGING - Debug("ssl_keylog", "Enabling TLS key logging to: %s.", keylog_file); + Dbg(dbg_ctl_ssl_keylog, "Enabling TLS key logging to: %s.", keylog_file); std::unique_lock lock{_mutex}; if (keylog_file == nullptr) { close_keylog_file(); - Debug("ssl_keylog", "Received a nullptr for keylog_file: disabling keylogging."); + Dbg(dbg_ctl_ssl_keylog, "Received a nullptr for keylog_file: disabling keylogging."); return; } @@ -76,7 +82,7 @@ TLSKeyLogger::disable_keylogging_internal() Note("Disabling TLS key logging."); } close_keylog_file(); - Debug("ssl_keylog", "TLS keylogging is disabled."); + Dbg(dbg_ctl_ssl_keylog, "TLS keylogging is disabled."); } void diff --git a/src/iocore/net/TLSSessionResumptionSupport.cc b/src/iocore/net/TLSSessionResumptionSupport.cc index 91ac0e7fd3..02cf2d6845 100644 --- a/src/iocore/net/TLSSessionResumptionSupport.cc +++ b/src/iocore/net/TLSSessionResumptionSupport.cc @@ -50,12 +50,18 @@ char mac_param_digest[] = "sha256"; int TLSSessionResumptionSupport::_ex_data_index = -1; -static bool +namespace +{ +DbgCtl dbg_ctl_ssl_session_ticket{"ssl_session_ticket"}; + +bool is_ssl_session_timed_out(SSL_SESSION *session) { return SSL_SESSION_get_timeout(session) < (time(nullptr) - SSL_SESSION_get_time(session)); } +} // end anonymous namespace + void TLSSessionResumptionSupport::initialize() { @@ -247,7 +253,7 @@ TLSSessionResumptionSupport::_setSessionInformation(ssl_ticket_key_block *keyblo } #endif - Debug("ssl_session_ticket", "create ticket for a new session."); + Dbg(dbg_ctl_ssl_session_ticket, "create ticket for a new session."); Metrics::Counter::increment(ssl_rsb.total_tickets_created); return 1; } @@ -282,7 +288,7 @@ TLSSessionResumptionSupport::_getSessionInformation(ssl_ticket_key_block *keyblo } #endif - Debug("ssl_session_ticket", "verify the ticket for an existing session."); + Dbg(dbg_ctl_ssl_session_ticket, "verify the ticket for an existing session."); // Increase the total number of decrypted tickets. Metrics::Counter::increment(ssl_rsb.total_tickets_verified); @@ -294,7 +300,7 @@ TLSSessionResumptionSupport::_getSessionInformation(ssl_ticket_key_block *keyblo #ifdef TLS1_3_VERSION if (SSL_version(ssl) >= TLS1_3_VERSION) { - Debug("ssl_session_ticket", "make sure tickets are only used once."); + Dbg(dbg_ctl_ssl_session_ticket, "make sure tickets are only used once."); return 2; } #endif @@ -304,7 +310,7 @@ TLSSessionResumptionSupport::_getSessionInformation(ssl_ticket_key_block *keyblo } } - Debug("ssl_session_ticket", "keyname is not consistent."); + Dbg(dbg_ctl_ssl_session_ticket, "keyname is not consistent."); Metrics::Counter::increment(ssl_rsb.total_tickets_not_found); return 0; } diff --git a/src/iocore/net/UDPEventIO.cc b/src/iocore/net/UDPEventIO.cc index 7d599acf87..0823df64ed 100644 --- a/src/iocore/net/UDPEventIO.cc +++ b/src/iocore/net/UDPEventIO.cc @@ -24,6 +24,12 @@ #include "iocore/net/UDPEventIO.h" #include "P_UDPNet.h" +namespace +{ +DbgCtl dbg_ctl_iocore_udp_main{"iocore_udp_main"}; + +} // end anonymous namespace + int UDPEventIO::start(EventLoop l, UnixUDPConnection *uc, UDPNetHandler *uh, int events) { @@ -47,6 +53,6 @@ UDPEventIO::process_event(int flags) udpNetInternal.udp_read_from_net(_uh, _uc); } } else { - Debug("iocore_udp_main", "Unhandled epoll event: 0x%04x", flags); + Dbg(dbg_ctl_iocore_udp_main, "Unhandled epoll event: 0x%04x", flags); } } diff --git a/src/iocore/net/UnixConnection.cc b/src/iocore/net/UnixConnection.cc index c5e1af8e7f..de1afcbb6d 100644 --- a/src/iocore/net/UnixConnection.cc +++ b/src/iocore/net/UnixConnection.cc @@ -44,6 +44,8 @@ unsigned int const IP_TRANSPARENT = 19; namespace { +DbgCtl dbg_ctl_socket{"socket"}; + /** Struct to make cleaning up resources easier. By default, the @a method is invoked on the @a object when @@ -158,13 +160,13 @@ Connection::open(NetVCOptions const &opt) static char const *const DEBUG_TEXT = "::open setsockopt() IP_TRANSPARENT"; #if TS_USE_TPROXY if (-1 == setsockopt_on(fd, SOL_IP, TS_IP_TRANSPARENT)) { - Debug("socket", "%s - fail %d:%s", DEBUG_TEXT, errno, strerror(errno)); + Dbg(dbg_ctl_socket, "%s - fail %d:%s", DEBUG_TEXT, errno, strerror(errno)); return -errno; } else { - Debug("socket", "%s set", DEBUG_TEXT); + Dbg(dbg_ctl_socket, "%s set", DEBUG_TEXT); } #else - Debug("socket", "%s - requested but TPROXY not configured", DEBUG_TEXT); + Dbg(dbg_ctl_socket, "%s - requested but TPROXY not configured", DEBUG_TEXT); #endif } @@ -179,7 +181,7 @@ Connection::open(NetVCOptions const &opt) while (rbufsz && !SocketManager::set_rcvbuf_size(fd, rbufsz)) { rbufsz -= 1024; } - Debug("socket", "::open: recv_bufsize = %d of %d", rbufsz, opt.socket_recv_bufsize); + Dbg(dbg_ctl_socket, "::open: recv_bufsize = %d of %d", rbufsz, opt.socket_recv_bufsize); } } if (opt.socket_send_bufsize > 0) { @@ -189,7 +191,7 @@ Connection::open(NetVCOptions const &opt) while (sbufsz && !SocketManager::set_sndbuf_size(fd, sbufsz)) { sbufsz -= 1024; } - Debug("socket", "::open: send_bufsize = %d of %d", sbufsz, opt.socket_send_bufsize); + Dbg(dbg_ctl_socket, "::open: send_bufsize = %d of %d", sbufsz, opt.socket_send_bufsize); } } @@ -273,24 +275,24 @@ Connection::apply_options(NetVCOptions const &opt) if (SOCK_STREAM == sock_type) { if (opt.sockopt_flags & NetVCOptions::SOCK_OPT_NO_DELAY) { setsockopt_on(fd, IPPROTO_TCP, TCP_NODELAY); - Debug("socket", "::open: setsockopt() TCP_NODELAY on socket"); + Dbg(dbg_ctl_socket, "::open: setsockopt() TCP_NODELAY on socket"); } if (opt.sockopt_flags & NetVCOptions::SOCK_OPT_KEEP_ALIVE) { setsockopt_on(fd, SOL_SOCKET, SO_KEEPALIVE); - Debug("socket", "::open: setsockopt() SO_KEEPALIVE on socket"); + Dbg(dbg_ctl_socket, "::open: setsockopt() SO_KEEPALIVE on socket"); } if (opt.sockopt_flags & NetVCOptions::SOCK_OPT_LINGER_ON) { struct linger l; l.l_onoff = 1; l.l_linger = 0; safe_setsockopt(fd, SOL_SOCKET, SO_LINGER, reinterpret_cast<char *>(&l), sizeof(l)); - Debug("socket", "::open:: setsockopt() turn on SO_LINGER on socket"); + Dbg(dbg_ctl_socket, "::open:: setsockopt() turn on SO_LINGER on socket"); } #ifdef TCP_NOTSENT_LOWAT if (opt.sockopt_flags & NetVCOptions::SOCK_OPT_TCP_NOTSENT_LOWAT) { uint32_t lowat = opt.packet_notsent_lowat; safe_setsockopt(fd, IPPROTO_TCP, TCP_NOTSENT_LOWAT, reinterpret_cast<char *>(&lowat), sizeof(lowat)); - Debug("socket", "::open:: setsockopt() set TCP_NOTSENT_LOWAT to %d", lowat); + Dbg(dbg_ctl_socket, "::open:: setsockopt() set TCP_NOTSENT_LOWAT to %d", lowat); } #endif } diff --git a/src/iocore/net/UnixNetAccept.cc b/src/iocore/net/UnixNetAccept.cc index 914e610de6..61a178b992 100644 --- a/src/iocore/net/UnixNetAccept.cc +++ b/src/iocore/net/UnixNetAccept.cc @@ -35,6 +35,8 @@ namespace DbgCtl dbg_ctl_iocore_net{"iocore_net"}; DbgCtl dbg_ctl_iocore_net_accept_start{"iocore_net_accept_start"}; +DbgCtl dbg_ctl_iocore_net_accepts{"iocore_net_accepts"}; +DbgCtl dbg_ctl_iocore_net_accept{"iocore_net_accept"}; /** Check and handle if the number of client connections exceeds the configured max. * @@ -56,7 +58,7 @@ handle_max_client_connections(IpEndpoint const &addr, std::shared_ptr<Connection inbound_tracker.release(); inbound_tracker.blocked(); inbound_tracker.Warn_Blocked(client_max, 0, tracked_count - 1, addr, - is_debug_tag_set("iocore_net_accept") ? "iocore_net_accept" : nullptr); + dbg_ctl_iocore_net_accept.on() ? &dbg_ctl_iocore_net_accept : nullptr); Metrics::Counter::increment(net_rsb.per_client_connections_throttled_in); return false; } @@ -176,7 +178,7 @@ Ldone: // if we stop looping as a result of hitting the accept limit, // resechedule accepting to the end of the thread event queue // for the goal of fairness between accepting and other work - Debug("iocore_net_accepts", "exited accept loop - count: %d, limit: %d", count, additional_accepts); + Dbg(dbg_ctl_iocore_net_accepts, "exited accept loop - count: %d, limit: %d", count, additional_accepts); if (count >= additional_accepts) { this_ethread()->schedule_imm_local(na); } @@ -601,7 +603,7 @@ Ldone: // if we stop looping as a result of hitting the accept limit, // resechedule accepting to the end of the thread event queue // for the goal of fairness between accepting and other work - Debug("iocore_net_accepts", "exited accept loop - count: %d, limit: %d", count, additional_accepts); + Dbg(dbg_ctl_iocore_net_accepts, "exited accept loop - count: %d, limit: %d", count, additional_accepts); if (count >= additional_accepts) { this_ethread()->schedule_imm_local(this); } diff --git a/src/iocore/net/UnixNetVConnection.cc b/src/iocore/net/UnixNetVConnection.cc index 11fa21237e..320323e4e5 100644 --- a/src/iocore/net/UnixNetVConnection.cc +++ b/src/iocore/net/UnixNetVConnection.cc @@ -38,6 +38,14 @@ // Global ClassAllocator<UnixNetVConnection> netVCAllocator("netVCAllocator"); +namespace +{ +DbgCtl dbg_ctl_socket{"socket"}; +DbgCtl dbg_ctl_inactivity_cop{"inactivity_cop"}; +DbgCtl dbg_ctl_iocore_net{"iocore_net"}; + +} // end anonymous namespace + // // Reschedule a UnixNetVConnection by moving it // onto or off of the ready_list @@ -67,7 +75,7 @@ write_reschedule(NetHandler *nh, UnixNetVConnection *vc) void net_activity(UnixNetVConnection *vc, EThread *thread) { - Debug("socket", "net_activity updating inactivity %" PRId64 ", NetVC=%p", vc->inactivity_timeout_in, vc); + Dbg(dbg_ctl_socket, "net_activity updating inactivity %" PRId64 ", NetVC=%p", vc->inactivity_timeout_in, vc); (void)thread; if (vc->inactivity_timeout_in) { vc->next_inactivity_timeout_at = ink_get_hrtime() + vc->inactivity_timeout_in; @@ -94,7 +102,7 @@ read_signal_and_update(int event, UnixNetVConnection *vc) case VC_EVENT_ERROR: case VC_EVENT_ACTIVE_TIMEOUT: case VC_EVENT_INACTIVITY_TIMEOUT: - Debug("inactivity_cop", "event %d: null read.vio cont, closing vc %p", event, vc); + Dbg(dbg_ctl_inactivity_cop, "event %d: null read.vio cont, closing vc %p", event, vc); vc->closed = 1; break; default: @@ -128,7 +136,7 @@ write_signal_and_update(int event, UnixNetVConnection *vc) case VC_EVENT_ERROR: case VC_EVENT_ACTIVE_TIMEOUT: case VC_EVENT_INACTIVITY_TIMEOUT: - Debug("inactivity_cop", "event %d: null write.vio cont, closing vc %p", event, vc); + Dbg(dbg_ctl_inactivity_cop, "event %d: null write.vio cont, closing vc %p", event, vc); vc->closed = 1; break; default: @@ -306,7 +314,7 @@ read_from_net(NetHandler *nh, UnixNetVConnection *vc, EThread *thread) buf.writer()->fill(r); #ifdef DEBUG if (buf.writer()->write_avail() <= 0) { - Debug("iocore_net", "read_from_net, read buffer full"); + Dbg(dbg_ctl_iocore_net, "read_from_net, read buffer full"); } #endif s->vio.ndone += r; @@ -321,7 +329,7 @@ read_from_net(NetHandler *nh, UnixNetVConnection *vc, EThread *thread) ink_assert(ntodo >= 0); if (s->vio.ntodo() <= 0) { read_signal_done(VC_EVENT_READ_COMPLETE, nh, vc); - Debug("iocore_net", "read_from_net, read finished - signal done"); + Dbg(dbg_ctl_iocore_net, "read_from_net, read finished - signal done"); return; } else { if (read_signal_and_update(VC_EVENT_READ_READY, vc) != EVENT_CONT) { @@ -652,7 +660,7 @@ UnixNetVConnection::do_io_close(int alerrno /* = -1 */) if (netvc_context == NET_VCONNECTION_OUT) { // do not clear the iobufs yet to guard // against race condition with session pool closing - Debug("iocore_net", "delay vio buffer clear to protect against race for vc %p", this); + Dbg(dbg_ctl_iocore_net, "delay vio buffer clear to protect against race for vc %p", this); } else { // may be okay to delay for all VCs? read.vio.buffer.clear(); @@ -1143,7 +1151,7 @@ UnixNetVConnection::populate(Connection &con_in, Continuation *c, void *arg) } if (h->startIO(this) < 0) { - Debug("iocore_net", "populate : Failed to add to epoll list"); + Dbg(dbg_ctl_iocore_net, "populate : Failed to add to epoll list"); return EVENT_ERROR; } @@ -1174,11 +1182,11 @@ UnixNetVConnection::connectUp(EThread *t, int fd) // // Initialize this UnixNetVConnection // - if (is_debug_tag_set("iocore_net")) { + if (dbg_ctl_iocore_net.on()) { char addrbuf[INET6_ADDRSTRLEN]; - Debug("iocore_net", "connectUp:: local_addr=%s:%d [%s]", - options.local_ip.isValid() ? options.local_ip.toString(addrbuf, sizeof(addrbuf)) : "*", options.local_port, - NetVCOptions::toString(options.addr_binding)); + DbgPrint(dbg_ctl_iocore_net, "connectUp:: local_addr=%s:%d [%s]", + options.local_ip.isValid() ? options.local_ip.toString(addrbuf, sizeof(addrbuf)) : "*", options.local_port, + NetVCOptions::toString(options.addr_binding)); } // If this is getting called from the TS API, then we are wiring up a file descriptor @@ -1289,7 +1297,7 @@ UnixNetVConnection::clear() void UnixNetVConnection::free_thread(EThread *t) { - Debug("iocore_net", "Entering UnixNetVConnection::free()"); + Dbg(dbg_ctl_iocore_net, "Entering UnixNetVConnection::free()"); ink_release_assert(t == this_ethread()); @@ -1301,7 +1309,7 @@ UnixNetVConnection::free_thread(EThread *t) con.close(); if (is_tunnel_endpoint()) { - Debug("iocore_net", "Freeing UnixNetVConnection that is tunnel endpoint"); + Dbg(dbg_ctl_iocore_net, "Freeing UnixNetVConnection that is tunnel endpoint"); Metrics::Gauge::decrement(([&]() -> Metrics::Gauge::AtomicType * { switch (get_context()) { @@ -1336,7 +1344,7 @@ UnixNetVConnection::apply_options() TS_INLINE void UnixNetVConnection::set_inactivity_timeout(ink_hrtime timeout_in) { - Debug("socket", "Set inactive timeout=%" PRId64 ", for NetVC=%p", timeout_in, this); + Dbg(dbg_ctl_socket, "Set inactive timeout=%" PRId64 ", for NetVC=%p", timeout_in, this); inactivity_timeout_in = timeout_in; next_inactivity_timeout_at = (timeout_in > 0) ? ink_get_hrtime() + inactivity_timeout_in : 0; } @@ -1344,7 +1352,7 @@ UnixNetVConnection::set_inactivity_timeout(ink_hrtime timeout_in) TS_INLINE void UnixNetVConnection::set_default_inactivity_timeout(ink_hrtime timeout_in) { - Debug("socket", "Set default inactive timeout=%" PRId64 ", for NetVC=%p", timeout_in, this); + Dbg(dbg_ctl_socket, "Set default inactive timeout=%" PRId64 ", for NetVC=%p", timeout_in, this); default_inactivity_timeout_in = timeout_in; } @@ -1521,13 +1529,13 @@ UnixNetVConnection::set_tcp_congestion_control(int side) Error("Unable to set TCP congestion control on socket %d to \"%s\", errno=%d (%s)", con.fd, ccp.data(), errno, strerror(errno)); } else { - Debug("socket", "Setting TCP congestion control on socket [%d] to \"%s\" -> %d", con.fd, ccp.data(), rv); + Dbg(dbg_ctl_socket, "Setting TCP congestion control on socket [%d] to \"%s\" -> %d", con.fd, ccp.data(), rv); } return 0; } return -1; #else - Debug("socket", "Setting TCP congestion control is not supported on this platform."); + Dbg(dbg_ctl_socket, "Setting TCP congestion control is not supported on this platform."); return -1; #endif } @@ -1535,7 +1543,7 @@ UnixNetVConnection::set_tcp_congestion_control(int side) void UnixNetVConnection::mark_as_tunnel_endpoint() { - Debug("iocore_net", "Entering UnixNetVConnection::mark_as_tunnel_endpoint()"); + Dbg(dbg_ctl_iocore_net, "Entering UnixNetVConnection::mark_as_tunnel_endpoint()"); ink_assert(!_is_tunnel_endpoint); diff --git a/src/iocore/net/quic/QUICGlobals.cc b/src/iocore/net/quic/QUICGlobals.cc index 0756fc9f47..2f3e31f1be 100644 --- a/src/iocore/net/quic/QUICGlobals.cc +++ b/src/iocore/net/quic/QUICGlobals.cc @@ -34,10 +34,16 @@ #include <openssl/ssl.h> -#define QUICGlobalDebug(fmt, ...) Debug("quic_global", fmt, ##__VA_ARGS__) +#define QUICGlobalDebug(fmt, ...) Dbg(dbg_ctl_quic_global, fmt, ##__VA_ARGS__) QuicStatsBlock quic_rsb; +namespace +{ +DbgCtl dbg_ctl_quic_global{"quic_global"}; + +} // end anonymous namespace + int QUIC::ssl_quic_qc_index = -1; int QUIC::ssl_quic_tls_index = -1; diff --git a/src/iocore/net/quic/QUICTransportParameters.cc b/src/iocore/net/quic/QUICTransportParameters.cc index d6bf96c674..0825279953 100644 --- a/src/iocore/net/quic/QUICTransportParameters.cc +++ b/src/iocore/net/quic/QUICTransportParameters.cc @@ -73,7 +73,7 @@ QUICTransportParameters::Value::len() const QUICTransportParameters::QUICTransportParameters(const uint8_t *buf, size_t len, QUICVersion version) { this->_load(buf, len, version); - if (is_debug_tag_set(tag)) { + if (dbg_ctl_tag.on()) { this->_print(); } } @@ -140,7 +140,7 @@ QUICTransportParameters::_load(const uint8_t *buf, size_t len, QUICVersion versi // Validate parameters int res = this->_validate_parameters(version); if (res < 0) { - Debug(tag, "Transport parameter is not valid (err=%d)", res); + Dbg(dbg_ctl, "Transport parameter is not valid (err=%d)", res); this->_valid = false; } else { this->_valid = true; @@ -262,7 +262,7 @@ QUICTransportParameters::store(uint8_t *buf, uint16_t *len) const *len = (p - buf); - if (is_debug_tag_set(tag)) { + if (dbg_ctl_tag.on()) { this->_print(); } } @@ -272,17 +272,18 @@ QUICTransportParameters::_print() const { for (auto &p : this->_parameters) { if (p.second->len() == 0) { - Debug(tag, "%s: (no value)", QUICDebugNames::transport_parameter_id(p.first)); + Dbg(dbg_ctl, "%s: (no value)", QUICDebugNames::transport_parameter_id(p.first)); } else if (p.second->len() <= 8) { uint64_t int_value; size_t int_value_len; QUICVariableInt::decode(int_value, int_value_len, p.second->data(), p.second->len()); - Debug(tag, "%s (%" PRIu32 "): 0x%" PRIx64 " (%" PRIu64 ")", QUICDebugNames::transport_parameter_id(p.first), - static_cast<uint16_t>(p.first), int_value, int_value); + Dbg(dbg_ctl, "%s (%" PRIu32 "): 0x%" PRIx64 " (%" PRIu64 ")", QUICDebugNames::transport_parameter_id(p.first), + static_cast<uint16_t>(p.first), int_value, int_value); } else if (p.second->len() <= 24) { char hex_str[65]; to_hex_str(hex_str, sizeof(hex_str), p.second->data(), p.second->len()); - Debug(tag, "%s (%" PRIu32 "): %s", QUICDebugNames::transport_parameter_id(p.first), static_cast<uint16_t>(p.first), hex_str); + Dbg(dbg_ctl, "%s (%" PRIu32 "): %s", QUICDebugNames::transport_parameter_id(p.first), static_cast<uint16_t>(p.first), + hex_str); } else if (QUICTransportParameterId::PREFERRED_ADDRESS == p.first) { QUICPreferredAddress pref_addr(p.second->data(), p.second->len()); char token_hex_str[QUICStatelessResetToken::LEN * 2 + 1]; @@ -291,11 +292,11 @@ QUICTransportParameters::_print() const to_hex_str(token_hex_str, sizeof(token_hex_str), pref_addr.token().buf(), QUICStatelessResetToken::LEN); ats_ip_nptop(pref_addr.endpoint_ipv4(), ep_ipv4_hex_str, sizeof(ep_ipv4_hex_str)); ats_ip_nptop(pref_addr.endpoint_ipv6(), ep_ipv6_hex_str, sizeof(ep_ipv6_hex_str)); - Debug(tag, "%s: Endpoint(IPv4)=%s, Endpoint(IPv6)=%s, CID=%s, Token=%s", QUICDebugNames::transport_parameter_id(p.first), - ep_ipv4_hex_str, ep_ipv6_hex_str, pref_addr.cid().hex().c_str(), token_hex_str); + Dbg(dbg_ctl, "%s: Endpoint(IPv4)=%s, Endpoint(IPv6)=%s, CID=%s, Token=%s", QUICDebugNames::transport_parameter_id(p.first), + ep_ipv4_hex_str, ep_ipv6_hex_str, pref_addr.cid().hex().c_str(), token_hex_str); } else { - Debug(tag, "%s (%" PRIu32 "): (%u byte data)", QUICDebugNames::transport_parameter_id(p.first), - static_cast<uint16_t>(p.first), p.second->len()); + Dbg(dbg_ctl, "%s (%" PRIu32 "): (%u byte data)", QUICDebugNames::transport_parameter_id(p.first), + static_cast<uint16_t>(p.first), p.second->len()); } } } diff --git a/src/iocore/utils/OneWayTunnel.cc b/src/iocore/utils/OneWayTunnel.cc index 92fcc069a9..bad074d4ac 100644 --- a/src/iocore/utils/OneWayTunnel.cc +++ b/src/iocore/utils/OneWayTunnel.cc @@ -45,6 +45,12 @@ ClassAllocator<OneWayTunnel> OneWayTunnelAllocator("OneWayTunnelAllocator"); +namespace +{ +DbgCtl dbg_ctl_one_way_tunnel{"one_way_tunnel"}; + +} // end anonymous namespace + inline void transfer_data(MIOBufferAccessor &in_buf, MIOBufferAccessor &out_buf) { @@ -131,7 +137,7 @@ OneWayTunnel::init(VConnection *vcSource, VConnection *vcTarget, Continuation *a size_index = BUFFER_SIZE_INDEX_32K; } - Debug("one_way_tunnel", "buffer size index [%" PRId64 "] [%d]", size_index, size_estimate); + Dbg(dbg_ctl_one_way_tunnel, "buffer size index [%" PRId64 "] [%d]", size_index, size_estimate); // enqueue read request on vcSource. MIOBuffer *buf1 = new_MIOBuffer(size_index); diff --git a/src/proxy/http/HttpSM.cc b/src/proxy/http/HttpSM.cc index cb7f880d2d..b6bf68c3a6 100644 --- a/src/proxy/http/HttpSM.cc +++ b/src/proxy/http/HttpSM.cc @@ -5483,7 +5483,7 @@ HttpSM::do_http_server_open(bool raw, bool only_direct) ct_state.blocked(); Metrics::Counter::increment(http_rsb.origin_connections_throttled); ct_state.Warn_Blocked(server_max, sm_id, ccount - 1, &t_state.current.server->dst_addr.sa, - debug_on && dbg_ctl_http.on() ? "http" : nullptr); + debug_on && dbg_ctl_http.on() ? &dbg_ctl_http : nullptr); send_origin_throttled_response(); return; } else {
