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 e2e6c6ca13e3f060975401f90f54f86aa4572a38 Author: Walt Karas <[email protected]> AuthorDate: Mon Apr 8 18:49:29 2024 -0400 Remove deprecated debug output functions from proxy/http source files. (#11217) (cherry picked from commit dab2eb1c3ff1135138f776eb84a1aae7ccf7a3eb) --- include/proxy/ProxySession.h | 3 + include/proxy/http/remap/PluginDso.h | 11 +- include/proxy/http/remap/PluginFactory.h | 9 ++ src/proxy/http/ConnectingEntry.cc | 22 ++-- src/proxy/http/Http1ClientSession.cc | 33 +++--- src/proxy/http/Http1ServerSession.cc | 16 ++- src/proxy/http/HttpBodyFactory.cc | 105 ++++++++++--------- src/proxy/http/HttpCacheSM.cc | 58 ++++++----- src/proxy/http/HttpConfig.cc | 10 +- src/proxy/http/HttpSessionAccept.cc | 12 ++- src/proxy/http/HttpSessionManager.cc | 84 ++++++++------- src/proxy/http/HttpTransactHeaders.cc | 66 ++++++------ src/proxy/http/HttpTunnel.cc | 89 +++++++++------- src/proxy/http/PreWarmManager.cc | 64 +++++++----- src/proxy/http/remap/PluginDso.cc | 34 +++--- src/proxy/http/remap/PluginFactory.cc | 30 +++--- src/proxy/http/remap/RemapConfig.cc | 115 +++++++++++---------- src/proxy/http/remap/RemapPluginInfo.cc | 18 ++-- src/proxy/http/remap/RemapPlugins.cc | 24 +++-- src/proxy/http/remap/RemapProcessor.cc | 36 ++++--- src/proxy/http/remap/UrlMapping.cc | 8 +- src/proxy/http/remap/UrlMappingPathIndex.cc | 15 ++- src/proxy/http/remap/UrlRewrite.cc | 82 ++++++++------- .../http/remap/unit-tests/plugin_testing_common.h | 4 +- 24 files changed, 544 insertions(+), 404 deletions(-) diff --git a/include/proxy/ProxySession.h b/include/proxy/ProxySession.h index a9f3e4a289..4965428564 100644 --- a/include/proxy/ProxySession.h +++ b/include/proxy/ProxySession.h @@ -36,6 +36,9 @@ // Emit a debug message conditional on whether this particular client session // has debugging enabled. This should only be called from within a client session // member function. +#define SsnDbg(ssn, dbg_ctl, ...) SpecificDbg((ssn)->debug(), dbg_ctl, __VA_ARGS__) + +// deprecated #define SsnDebug(ssn, tag, ...) SpecificDebug((ssn)->debug(), tag, __VA_ARGS__) class ProxyTransaction; diff --git a/include/proxy/http/remap/PluginDso.h b/include/proxy/http/remap/PluginDso.h index 8207c3da05..41f18b943d 100644 --- a/include/proxy/http/remap/PluginDso.h +++ b/include/proxy/http/remap/PluginDso.h @@ -166,7 +166,8 @@ protected: void *_dlh = nullptr; /** @brief dlopen handler used internally in this class, used as flag for loaded vs unloaded (nullptr) */ - static constexpr const char *const _tag = "plugin_dso"; /** @brief log tag used by this class */ + static constexpr const char *const _tag = "plugin_dso"; /** @brief log tag used by this class */ + static const DbgCtl &_dbg_ctl(); swoc::file::file_time_type _mtime{fs::file_time_type::min()}; /* @brief modification time of the DSO's file, used for checking */ bool _preventiveCleaning = true; @@ -174,3 +175,11 @@ protected: _plugins; /** @brief a global list of plugins, usually maintained by a plugin factory or plugin instance itself */ RefCountObj _instanceCount; /** @brief used for properly calling "done" and "indicate config reload" methods by the factory */ }; + +inline const DbgCtl & +PluginDso::_dbg_ctl() +{ + static DbgCtl dc{_tag}; + + return dc; +} diff --git a/include/proxy/http/remap/PluginFactory.h b/include/proxy/http/remap/PluginFactory.h index 7234d4141e..5a63a13f41 100644 --- a/include/proxy/http/remap/PluginFactory.h +++ b/include/proxy/http/remap/PluginFactory.h @@ -120,4 +120,13 @@ protected: bool _preventiveCleaning = true; static constexpr const char *const _tag = "plugin_factory"; /** @brief log tag used by this class */ + static const DbgCtl &_dbg_ctl(); }; + +inline const DbgCtl & +PluginFactory::_dbg_ctl() +{ + static DbgCtl dc{_tag}; + + return dc; +} diff --git a/src/proxy/http/ConnectingEntry.cc b/src/proxy/http/ConnectingEntry.cc index 9655478145..081079640f 100644 --- a/src/proxy/http/ConnectingEntry.cc +++ b/src/proxy/http/ConnectingEntry.cc @@ -22,9 +22,17 @@ */ +#include "tsutil/DbgCtl.h" #include "proxy/http/ConnectingEntry.h" #include "proxy/http/HttpSM.h" +namespace +{ + +DbgCtl dbg_ctl_http_connect{"http_connect"}; + +} // end anonymous namespace + ConnectingEntry::~ConnectingEntry() { if (_netvc_read_buffer != nullptr) { @@ -36,7 +44,7 @@ ConnectingEntry::~ConnectingEntry() int ConnectingEntry::state_http_server_open(int event, void *data) { - Debug("http_connect", "entered inside ConnectingEntry::state_http_server_open"); + Dbg(dbg_ctl_http_connect, "entered inside ConnectingEntry::state_http_server_open"); switch (event) { case NET_EVENT_OPEN: { @@ -44,7 +52,7 @@ ConnectingEntry::state_http_server_open(int event, void *data) UnixNetVConnection *vc = static_cast<UnixNetVConnection *>(netvc); ink_release_assert(_pending_action == nullptr || _pending_action->continuation == vc->get_action()->continuation); _pending_action = nullptr; - Debug("http_connect", "ConnectingEntrysetting handler for connection handshake"); + Dbg(dbg_ctl_http_connect, "ConnectingEntrysetting handler for connection handshake"); // Just want to get a write-ready event so we know that the connection handshake is complete. // The buffer we create will be handed over to the eventually created server session _netvc_read_buffer = new_MIOBuffer(HTTP_SERVER_RESP_HDR_BUFFER_INDEX); @@ -68,7 +76,7 @@ ConnectingEntry::state_http_server_open(int event, void *data) case VC_EVENT_READ_COMPLETE: case VC_EVENT_WRITE_READY: case VC_EVENT_WRITE_COMPLETE: { - Debug("http_connect", "Kick off %zd state machines waiting for origin", connect_sms.size()); + Dbg(dbg_ctl_http_connect, "Kick off %zd state machines waiting for origin", connect_sms.size()); this->remove_entry(); netvc->do_io_write(nullptr, 0, nullptr); if (!connect_sms.empty()) { @@ -83,7 +91,7 @@ ConnectingEntry::state_http_server_open(int event, void *data) if (new_session->is_multiplexing()) { // Hand off to all queued up ConnectSM's. while (!connect_sms.empty()) { - Debug("http_connect", "ConnectingEntry Pass along CONNECT_EVENT_TXN %d", count++); + Dbg(dbg_ctl_http_connect, "ConnectingEntry Pass along CONNECT_EVENT_TXN %d", count++); auto entry = connect_sms.begin(); SCOPED_MUTEX_LOCK(lock, (*entry)->mutex, this_ethread()); @@ -92,7 +100,7 @@ ConnectingEntry::state_http_server_open(int event, void *data) } } else { // Hand off to one and tell all of the others to connect directly - Debug("http_connect", "ConnectingEntry send CONNECT_EVENT_TXN to first %d", count++); + Dbg(dbg_ctl_http_connect, "ConnectingEntry send CONNECT_EVENT_TXN to first %d", count++); { SCOPED_MUTEX_LOCK(lock, (*prime_iter)->mutex, this_ethread()); (*prime_iter)->handleEvent(CONNECT_EVENT_TXN, new_session); @@ -100,7 +108,7 @@ ConnectingEntry::state_http_server_open(int event, void *data) } while (!connect_sms.empty()) { auto entry = connect_sms.begin(); - Debug("http_connect", "ConnectingEntry Pass along CONNECT_EVENT_DIRECT %d", count++); + Dbg(dbg_ctl_http_connect, "ConnectingEntry Pass along CONNECT_EVENT_DIRECT %d", count++); SCOPED_MUTEX_LOCK(lock, (*entry)->mutex, this_ethread()); (*entry)->handleEvent(CONNECT_EVENT_DIRECT, nullptr); connect_sms.erase(entry); @@ -118,7 +126,7 @@ ConnectingEntry::state_http_server_open(int event, void *data) case VC_EVENT_ACTIVE_TIMEOUT: case VC_EVENT_ERROR: case NET_EVENT_OPEN_FAILED: { - Debug("http_connect", "Stop %zd state machines waiting for failed origin", connect_sms.size()); + Dbg(dbg_ctl_http_connect, "Stop %zd state machines waiting for failed origin", connect_sms.size()); this->remove_entry(); int vc_provided_cert = 0; int lerrno = EIO; diff --git a/src/proxy/http/Http1ClientSession.cc b/src/proxy/http/Http1ClientSession.cc index 91ac594419..56778cb244 100644 --- a/src/proxy/http/Http1ClientSession.cc +++ b/src/proxy/http/Http1ClientSession.cc @@ -41,12 +41,12 @@ #include "iocore/net/TLSBasicSupport.h" #include "iocore/net/TLSEarlyDataSupport.h" -#define HttpSsnDebug(fmt, ...) SsnDebug(this, "http_cs", fmt, __VA_ARGS__) +#define HttpSsnDbg(fmt, ...) SsnDbg(this, dbg_ctl_http_cs, fmt, __VA_ARGS__) -#define STATE_ENTER(state_name, event, vio) \ - do { \ - /*ink_assert (magic == HTTP_SM_MAGIC_ALIVE); REMEMBER (event, NULL, reentrancy_count); */ \ - HttpSsnDebug("[%" PRId64 "] [%s, %s]", con_id, #state_name, HttpDebugNames::get_event_name(event)); \ +#define STATE_ENTER(state_name, event, vio) \ + do { \ + /*ink_assert (magic == HTTP_SM_MAGIC_ALIVE); REMEMBER (event, NULL, reentrancy_count); */ \ + HttpSsnDbg("[%" PRId64 "] [%s, %s]", con_id, #state_name, HttpDebugNames::get_event_name(event)); \ } while (0) #ifdef USE_HTTP_DEBUG_LISTS @@ -60,6 +60,13 @@ ink_mutex debug_cs_list_mutex; ClassAllocator<Http1ClientSession, true> http1ClientSessionAllocator("http1ClientSessionAllocator"); +namespace +{ +DbgCtl dbg_ctl_http_cs{"http_cs"}; +DbgCtl dbg_ctl_ssl_early_data{"ssl_early_data"}; + +} // end anonymous namespace + Http1ClientSession::Http1ClientSession() : super(), trans(this) {} // @@ -73,7 +80,7 @@ Http1ClientSession::destroy() if (!in_destroy) { in_destroy = true; - HttpSsnDebug("[%" PRId64 "] session destroy", con_id); + HttpSsnDbg("[%" PRId64 "] session destroy", con_id); ink_assert(read_buffer); ink_release_assert(transact_count == released_transactions); do_api_callout(TS_HTTP_SSN_CLOSE_HOOK); @@ -143,7 +150,7 @@ Http1ClientSession::new_connection(NetVConnection *new_vc, MIOBuffer *iobuf, IOB if (TLSEarlyDataSupport *eds = new_vc->get_service<TLSEarlyDataSupport>()) { read_from_early_data = eds->get_early_data_len(); - Debug("ssl_early_data", "read_from_early_data = %" PRId64, read_from_early_data); + Dbg(dbg_ctl_ssl_early_data, "read_from_early_data = %" PRId64, read_from_early_data); } MUTEX_TRY_LOCK(lock, mutex, this_ethread()); @@ -188,7 +195,7 @@ Http1ClientSession::new_connection(NetVConnection *new_vc, MIOBuffer *iobuf, IOB ink_mutex_release(&debug_cs_list_mutex); #endif - HttpSsnDebug("[%" PRId64 "] session born, netvc %p", con_id, new_vc); + HttpSsnDbg("[%" PRId64 "] session born, netvc %p", con_id, new_vc); _vc->set_tcp_congestion_control(CLIENT_SIDE); @@ -243,7 +250,7 @@ Http1ClientSession::do_io_close(int alerrno) if (half_close && this->trans.get_sm()) { read_state = HCS_HALF_CLOSED; SET_HANDLER(&Http1ClientSession::state_wait_for_close); - HttpSsnDebug("[%" PRId64 "] session half close", con_id); + HttpSsnDbg("[%" PRId64 "] session half close", con_id); if (_vc) { _vc->do_io_shutdown(IO_SHUTDOWN_WRITE); @@ -262,7 +269,7 @@ Http1ClientSession::do_io_close(int alerrno) // READ_READY event. _reader->consume(_reader->read_avail()); } else { - HttpSsnDebug("[%" PRId64 "] session closed", con_id); + HttpSsnDbg("[%" PRId64 "] session closed", con_id); read_state = HCS_CLOSED; if (_vc) { @@ -426,10 +433,10 @@ Http1ClientSession::release(ProxyTransaction *trans) /* Start the new transaction once we finish completely the current transaction and unroll the stack */ bool more_to_read = this->_reader->is_read_avail_more_than(0); if (more_to_read) { - HttpSsnDebug("[%" PRId64 "] data already in buffer, starting new transaction", con_id); + HttpSsnDbg("[%" PRId64 "] data already in buffer, starting new transaction", con_id); new_transaction(); } else { - HttpSsnDebug("[%" PRId64 "] initiating io for next header", con_id); + HttpSsnDbg("[%" PRId64 "] initiating io for next header", con_id); read_state = HCS_KEEP_ALIVE; SET_HANDLER(&Http1ClientSession::state_keep_alive); ka_vio = this->do_io_read(this, INT64_MAX, read_buffer); @@ -478,7 +485,7 @@ Http1ClientSession::attach_server_session(PoolableSession *ssession, bool transa ink_assert(bound_ss == nullptr); ssession->state = PoolableSession::KA_RESERVED; bound_ss = ssession; - HttpSsnDebug("[%" PRId64 "] attaching server session [%" PRId64 "] as slave", con_id, ssession->connection_id()); + HttpSsnDbg("[%" PRId64 "] attaching server session [%" PRId64 "] as slave", con_id, ssession->connection_id()); ink_assert(ssession->get_netvc() != this->get_netvc()); // handling potential keep-alive here diff --git a/src/proxy/http/Http1ServerSession.cc b/src/proxy/http/Http1ServerSession.cc index ce86245a0e..c3ca053357 100644 --- a/src/proxy/http/Http1ServerSession.cc +++ b/src/proxy/http/Http1ServerSession.cc @@ -37,6 +37,12 @@ ClassAllocator<Http1ServerSession, true> httpServerSessionAllocator("httpServerSessionAllocator"); +namespace +{ +DbgCtl dbg_ctl_http_ss{"http_ss"}; + +} // end anonymous namespace + Http1ServerSession::Http1ServerSession() : super_type(), trans(this) {} void @@ -90,7 +96,7 @@ Http1ServerSession::new_connection(NetVConnection *new_vc, MIOBuffer *iobuf, IOB read_buffer = iobuf; _reader = reader; } - Debug("http_ss", "[%" PRId64 "] session born, netvc %p", con_id, new_vc); + Dbg(dbg_ctl_http_ss, "[%" PRId64 "] session born, netvc %p", con_id, new_vc); state = INIT; new_vc->set_tcp_congestion_control(SERVER_SIDE); @@ -102,7 +108,7 @@ Http1ServerSession::do_io_close(int alerrno) // Only do the close bookkeeping 1 time if (state != SSN_CLOSED) { swoc::LocalBufferWriter<256> w; - bool debug_p = is_debug_tag_set("http_ss"); + bool debug_p = dbg_ctl_http_ss.on(); state = SSN_CLOSED; @@ -116,7 +122,7 @@ Http1ServerSession::do_io_close(int alerrno) this->release_outbound_connection_tracking(); if (debug_p) { - Debug("http_ss", "%.*s", static_cast<int>(w.size()), w.data()); + Dbg(dbg_ctl_http_ss, "%.*s", static_cast<int>(w.size()), w.data()); } if (_vc) { @@ -141,8 +147,8 @@ Http1ServerSession::do_io_close(int alerrno) void Http1ServerSession::release(ProxyTransaction *trans) { - Debug("http_ss", "[%" PRId64 "] Releasing session, private_session=%d, sharing_match=%d", con_id, this->is_private(), - sharing_match); + Dbg(dbg_ctl_http_ss, "[%" PRId64 "] Releasing session, private_session=%d, sharing_match=%d", con_id, this->is_private(), + sharing_match); if (state == SSN_IN_USE) { // The caller should have already set the inactive timeout to the keep alive timeout // Unfortunately, we do not have access to that value from here. diff --git a/src/proxy/http/HttpBodyFactory.cc b/src/proxy/http/HttpBodyFactory.cc index 1b9589fc5c..995c0a36a5 100644 --- a/src/proxy/http/HttpBodyFactory.cc +++ b/src/proxy/http/HttpBodyFactory.cc @@ -59,6 +59,15 @@ // //////////////////////////////////////////////////////////////////////// +namespace +{ + +DbgCtl dbg_ctl_body_factory{"body_factory"}; +DbgCtl dbg_ctl_body_factory_determine_set{"body_factory_determine_set"}; +DbgCtl dbg_ctl_body_factory_instantiation{"body_factory_instantiation"}; + +} // end anonymous namespace + char * HttpBodyFactory::fabricate_with_old_api(const char *type, HttpTransact::State *context, int64_t max_buffer_length, int64_t *resulting_buffer_length, char *content_language_out_buf, @@ -258,7 +267,7 @@ HttpBodyFactory::reconfigure() // extract relevant records.yaml values // //////////////////////////////////////////// - Debug("body_factory", "config variables changed, reconfiguring..."); + Dbg(dbg_ctl_body_factory, "config variables changed, reconfiguring..."); all_found = true; @@ -266,12 +275,12 @@ HttpBodyFactory::reconfigure() rec_err = RecGetRecordInt("proxy.config.body_factory.enable_customizations", &e); enable_customizations = ((rec_err == REC_ERR_OKAY) ? e : 0); all_found = all_found && (rec_err == REC_ERR_OKAY); - Debug("body_factory", "enable_customizations = %d (found = %" PRId64 ")", enable_customizations, e); + Dbg(dbg_ctl_body_factory, "enable_customizations = %d (found = %" PRId64 ")", enable_customizations, e); rec_err = RecGetRecordInt("proxy.config.body_factory.enable_logging", &e); enable_logging = ((rec_err == REC_ERR_OKAY) ? (e ? true : false) : false); all_found = all_found && (rec_err == REC_ERR_OKAY); - Debug("body_factory", "enable_logging = %d (found = %" PRId64 ")", enable_logging, e); + Dbg(dbg_ctl_body_factory, "enable_logging = %d (found = %" PRId64 ")", enable_logging, e); ats_scoped_str directory_of_template_sets; @@ -289,7 +298,7 @@ HttpBodyFactory::reconfigure() } } - Debug("body_factory", "directory_of_template_sets = '%s' ", (const char *)directory_of_template_sets); + Dbg(dbg_ctl_body_factory, "directory_of_template_sets = '%s' ", (const char *)directory_of_template_sets); ats_free(s); @@ -351,7 +360,7 @@ HttpBodyFactory::HttpBodyFactory() if (no_registrations_failed == false) { Warning("couldn't setup all body_factory callbacks, disabling body_factory"); } else { - Debug("body_factory", "all callbacks established successfully"); + Dbg(dbg_ctl_body_factory, "all callbacks established successfully"); callbacks_established = true; reconfigure(); } @@ -380,17 +389,17 @@ HttpBodyFactory::fabricate(StrList *acpt_language_list, StrList *acpt_charset_li *content_language_return = nullptr; *content_charset_return = nullptr; - Debug("body_factory", "calling fabricate(type '%s')", type); + Dbg(dbg_ctl_body_factory, "calling fabricate(type '%s')", type); *buffer_length_return = 0; // if error body suppressed, return NULL if (is_response_suppressed(context)) { - Debug("body_factory", " error suppression enabled, returning NULL template"); + Dbg(dbg_ctl_body_factory, " error suppression enabled, returning NULL template"); return nullptr; } // if custom error pages are disabled, return NULL if (!enable_customizations) { - Debug("body_factory", " customization disabled, returning NULL template"); + Dbg(dbg_ctl_body_factory, " customization disabled, returning NULL template"); return nullptr; } @@ -429,7 +438,7 @@ HttpBodyFactory::fabricate(StrList *acpt_language_list, StrList *acpt_charset_li } if (t == nullptr) { - Debug("body_factory", " can't find template, returning NULL template"); + Dbg(dbg_ctl_body_factory, " can't find template, returning NULL template"); return nullptr; } @@ -475,8 +484,8 @@ HttpBodyFactory::determine_set_by_language(std::unique_ptr<BodySetTable> &table_ Lc_best = INT_MAX; I_best = INT_MAX; - Debug("body_factory_determine_set", " INITIAL: [ set_best='%s', Q=%g, La=%d, Lc=%d, I=%d ]", set_best, Q_best, La_best, Lc_best, - I_best); + Dbg(dbg_ctl_body_factory_determine_set, " INITIAL: [ set_best='%s', Q=%g, La=%d, Lc=%d, I=%d ]", set_best, Q_best, La_best, + Lc_best, I_best); // FIX: eliminate this special case (which doesn't work anyway), by properly // handling empty lists and empty pieces in match_accept_XXX @@ -484,7 +493,7 @@ HttpBodyFactory::determine_set_by_language(std::unique_ptr<BodySetTable> &table_ // if no Accept-Language or Accept-Charset, just return default if ((acpt_language_list->count == 0) && (acpt_charset_list->count == 0)) { Q_best = 1; - Debug("body_factory_determine_set", " no constraints => returning '%s'", set_best); + Dbg(dbg_ctl_body_factory_determine_set, " no constraints => returning '%s'", set_best); goto done; } @@ -516,8 +525,8 @@ HttpBodyFactory::determine_set_by_language(std::unique_ptr<BodySetTable> &table_ is_the_default_set = (strcmp(set_name, "default") == 0); - Debug("body_factory_determine_set", " --- SET: %-8s (Content-Language '%s', Content-Charset '%s')", set_name, - body_set->content_language, body_set->content_charset); + Dbg(dbg_ctl_body_factory_determine_set, " --- SET: %-8s (Content-Language '%s', Content-Charset '%s')", set_name, + body_set->content_language, body_set->content_charset); // if no Accept-Language hdr at all, treat as a wildcard that // slightly prefers "default". @@ -526,13 +535,13 @@ HttpBodyFactory::determine_set_by_language(std::unique_ptr<BodySetTable> &table_ La = 0; Lc = INT_MAX; I = 1; - Debug("body_factory_determine_set", " SET: [%-8s] A-L not present => [ Ql=%g, La=%d, Lc=%d, I=%d ]", set_name, Ql, La, - Lc, I); + Dbg(dbg_ctl_body_factory_determine_set, " SET: [%-8s] A-L not present => [ Ql=%g, La=%d, Lc=%d, I=%d ]", set_name, Ql, + La, Lc, I); } else { Lc = strlen(body_set->content_language); Ql = HttpCompat::match_accept_language(body_set->content_language, Lc, acpt_language_list, &La, &I, true); - Debug("body_factory_determine_set", " SET: [%-8s] A-L match value => [ Ql=%g, La=%d, Lc=%d, I=%d ]", set_name, Ql, La, - Lc, I); + Dbg(dbg_ctl_body_factory_determine_set, " SET: [%-8s] A-L match value => [ Ql=%g, La=%d, Lc=%d, I=%d ]", set_name, Ql, + La, Lc, I); } ///////////////////////////////////////////////////////////// @@ -554,11 +563,11 @@ HttpBodyFactory::determine_set_by_language(std::unique_ptr<BodySetTable> &table_ if (acpt_charset_list->count == 0) { Qc = (is_the_default_set ? 1.0001 : 1.000); Idummy = 1; - Debug("body_factory_determine_set", " SET: [%-8s] A-C not present => [ Qc=%g ]", set_name, Qc); + Dbg(dbg_ctl_body_factory_determine_set, " SET: [%-8s] A-C not present => [ Qc=%g ]", set_name, Qc); } else { Qc = HttpCompat::match_accept_charset(body_set->content_charset, strlen(body_set->content_charset), acpt_charset_list, &Idummy, true); - Debug("body_factory_determine_set", " SET: [%-8s] A-C match value => [ Qc=%g ]", set_name, Qc); + Dbg(dbg_ctl_body_factory_determine_set, " SET: [%-8s] A-C match value => [ Qc=%g ]", set_name, Qc); } ///////////////////////////////////////////////////////////////// @@ -585,9 +594,9 @@ HttpBodyFactory::determine_set_by_language(std::unique_ptr<BodySetTable> &table_ } } - Debug("body_factory_determine_set", " NEW: [ set='%s', Q=%g, La=%d, Lc=%d, I=%d ]", set_name, Q, La, Lc, I); - Debug("body_factory_determine_set", " OLD: [ set='%s', Q=%g, La=%d, Lc=%d, I=%d ]", set_best, Q_best, La_best, Lc_best, - I_best); + Dbg(dbg_ctl_body_factory_determine_set, " NEW: [ set='%s', Q=%g, La=%d, Lc=%d, I=%d ]", set_name, Q, La, Lc, I); + Dbg(dbg_ctl_body_factory_determine_set, " OLD: [ set='%s', Q=%g, La=%d, Lc=%d, I=%d ]", set_best, Q_best, La_best, + Lc_best, I_best); if (((Q > Q_best)) || ((Q == Q_best) && (La > La_best)) || ((Q == Q_best) && (La == La_best) && (Lc < Lc_best)) || ((Q == Q_best) && (La == La_best) && (Lc == Lc_best) && (I < I_best))) { @@ -597,11 +606,11 @@ HttpBodyFactory::determine_set_by_language(std::unique_ptr<BodySetTable> &table_ I_best = I; set_best = set_name; - Debug("body_factory_determine_set", " WINNER: [ set_best='%s', Q=%g, La=%d, Lc=%d, I=%d ]", set_best, Q_best, La_best, - Lc_best, I_best); + Dbg(dbg_ctl_body_factory_determine_set, " WINNER: [ set_best='%s', Q=%g, La=%d, Lc=%d, I=%d ]", set_best, Q_best, La_best, + Lc_best, I_best); } else { - Debug("body_factory_determine_set", " LOSER: [ set_best='%s', Q=%g, La=%d, Lc=%d, I=%d ]", set_best, Q_best, La_best, - Lc_best, I_best); + Dbg(dbg_ctl_body_factory_determine_set, " LOSER: [ set_best='%s', Q=%g, La=%d, Lc=%d, I=%d ]", set_best, Q_best, La_best, + Lc_best, I_best); } } } @@ -632,7 +641,7 @@ HttpBodyFactory::determine_set_by_language(StrList *acpt_language_list, StrList HttpBodyTemplate * HttpBodyFactory::find_template(const char *set, const char *type, HttpBodySet **body_set_return) { - Debug("body_factory", "calling find_template(%s,%s)", set, type); + Dbg(dbg_ctl_body_factory, "calling find_template(%s,%s)", set, type); *body_set_return = nullptr; @@ -652,13 +661,13 @@ HttpBodyFactory::find_template(const char *set, const char *type, HttpBodySet ** } *body_set_return = body_set; - Debug("body_factory", "find_template(%s,%s) -> (file %s, length %" PRId64 ", lang '%s', charset '%s')", set, type, - t->template_pathname, t->byte_count, body_set->content_language, body_set->content_charset); + Dbg(dbg_ctl_body_factory, "find_template(%s,%s) -> (file %s, length %" PRId64 ", lang '%s', charset '%s')", set, type, + t->template_pathname, t->byte_count, body_set->content_language, body_set->content_charset); return t; } } - Debug("body_factory", "find_template(%s,%s) -> NULL", set, type); + Dbg(dbg_ctl_body_factory, "find_template(%s,%s) -> NULL", set, type); return nullptr; } @@ -693,9 +702,9 @@ void HttpBodyFactory::nuke_template_tables() { if (table_of_sets) { - Debug("body_factory", "deleting pre-existing template tables"); + Dbg(dbg_ctl_body_factory, "deleting pre-existing template tables"); } else { - Debug("body_factory", "no pre-existing template tables"); + Dbg(dbg_ctl_body_factory, "no pre-existing template tables"); } if (table_of_sets) { /////////////////////////////////////////// @@ -731,7 +740,7 @@ HttpBodyFactory::load_sets_from_directory(char *set_dir) return nullptr; } - Debug("body_factory", "load_sets_from_directory(%s)", set_dir); + Dbg(dbg_ctl_body_factory, "load_sets_from_directory(%s)", set_dir); ////////////////////////////////////////////////// // try to open the requested template directory // @@ -779,7 +788,7 @@ HttpBodyFactory::load_sets_from_directory(char *set_dir) HttpBodySet *body_set = load_body_set_from_directory(dirEntry->d_name, subdir); if (body_set != nullptr) { - Debug("body_factory", " %s -> %p", dirEntry->d_name, body_set); + Dbg(dbg_ctl_body_factory, " %s -> %p", dirEntry->d_name, body_set); new_table_of_sets->emplace(dirEntry->d_name, body_set); } } @@ -804,7 +813,7 @@ HttpBodyFactory::load_body_set_from_directory(char *set_name, char *tmpl_dir) // ensure we can open tmpl_dir as a directory // //////////////////////////////////////////////// - Debug("body_factory", " load_body_set_from_directory(%s)", tmpl_dir); + Dbg(dbg_ctl_body_factory, " load_body_set_from_directory(%s)", tmpl_dir); dir = opendir(tmpl_dir); if (dir == nullptr) { return nullptr; @@ -821,7 +830,7 @@ HttpBodyFactory::load_body_set_from_directory(char *set_name, char *tmpl_dir) closedir(dir); return nullptr; } - Debug("body_factory", " found '%s'", path); + Dbg(dbg_ctl_body_factory, " found '%s'", path); ///////////////////////////////////////////////////////////////// // create body set, and loop over template files, loading them // @@ -830,8 +839,8 @@ HttpBodyFactory::load_body_set_from_directory(char *set_name, char *tmpl_dir) HttpBodySet *body_set = new HttpBodySet; body_set->init(set_name, tmpl_dir); - Debug("body_factory", " body_set = %p (set_name '%s', lang '%s', charset '%s')", body_set, body_set->set_name, - body_set->content_language, body_set->content_charset); + Dbg(dbg_ctl_body_factory, " body_set = %p (set_name '%s', lang '%s', charset '%s')", body_set, body_set->set_name, + body_set->content_language, body_set->content_charset); while ((dirEntry = readdir(dir))) { HttpBodyTemplate *tmpl; @@ -868,7 +877,7 @@ HttpBodyFactory::load_body_set_from_directory(char *set_name, char *tmpl_dir) if (!tmpl->load_from_file(tmpl_dir, dirEntry->d_name)) { delete tmpl; } else { - Debug("body_factory", " %s -> %p", dirEntry->d_name, tmpl); + Dbg(dbg_ctl_body_factory, " %s -> %p", dirEntry->d_name, tmpl); body_set->set_template_by_name(dirEntry->d_name, tmpl); } } @@ -1022,7 +1031,7 @@ HttpBodySet::init(char *set, char *dir) HttpBodyTemplate * HttpBodySet::get_template_by_name(const char *name) { - Debug("body_factory", " calling get_template_by_name(%s)", name); + Dbg(dbg_ctl_body_factory, " calling get_template_by_name(%s)", name); if (table_of_pages == nullptr) { return nullptr; @@ -1033,11 +1042,11 @@ HttpBodySet::get_template_by_name(const char *name) if ((t == nullptr) || (!t->is_sane())) { return nullptr; } - Debug("body_factory", " get_template_by_name(%s) -> (file %s, length %" PRId64 ")", name, t->template_pathname, - t->byte_count); + Dbg(dbg_ctl_body_factory, " get_template_by_name(%s) -> (file %s, length %" PRId64 ")", name, t->template_pathname, + t->byte_count); return t; } - Debug("body_factory", " get_template_by_name(%s) -> NULL", name); + Dbg(dbg_ctl_body_factory, " get_template_by_name(%s) -> NULL", name); return nullptr; } @@ -1132,7 +1141,7 @@ HttpBodyTemplate::load_from_file(char *dir, char *file) return 0; } - Debug("body_factory", " read %" PRId64 " bytes from '%s'", new_byte_count, path); + Dbg(dbg_ctl_body_factory, " read %" PRId64 " bytes from '%s'", new_byte_count, path); ///////////////////////////////// // actually commit the changes // @@ -1151,15 +1160,15 @@ HttpBodyTemplate::build_instantiated_buffer(HttpTransact::State *context, int64_ { char *buffer = nullptr; - Debug("body_factory_instantiation", " before instantiation: [%s]", template_buffer); + Dbg(dbg_ctl_body_factory_instantiation, " before instantiation: [%s]", template_buffer); LogAccess la(context->state_machine); buffer = resolve_logfield_string(&la, template_buffer); *buflen_return = ((buffer == nullptr) ? 0 : strlen(buffer)); - Debug("body_factory_instantiation", " after instantiation: [%s]", buffer); - Debug("body_factory", " returning %" PRId64 " byte instantiated buffer", *buflen_return); + Dbg(dbg_ctl_body_factory_instantiation, " after instantiation: [%s]", buffer); + Dbg(dbg_ctl_body_factory, " returning %" PRId64 " byte instantiated buffer", *buflen_return); return buffer; } diff --git a/src/proxy/http/HttpCacheSM.cc b/src/proxy/http/HttpCacheSM.cc index 9661dec19e..cccb1eb034 100644 --- a/src/proxy/http/HttpCacheSM.cc +++ b/src/proxy/http/HttpCacheSM.cc @@ -39,12 +39,18 @@ sm->history.push_back(MakeSourceLocation(), e, r); \ } -#define STATE_ENTER(state_name, event) \ - { \ - SM_REMEMBER(master_sm, event, NO_REENTRANT); \ - Debug("http_cache", "[%" PRId64 "] [%s, %s]", master_sm->sm_id, #state_name, HttpDebugNames::get_event_name(event)); \ +#define STATE_ENTER(state_name, event) \ + { \ + SM_REMEMBER(master_sm, event, NO_REENTRANT); \ + Dbg(dbg_ctl_http_cache, "[%" PRId64 "] [%s, %s]", master_sm->sm_id, #state_name, HttpDebugNames::get_event_name(event)); \ } +namespace +{ +DbgCtl dbg_ctl_http_cache{"http_cache"}; + +} // end anonymous namespace + HttpCacheAction::HttpCacheAction() {} void @@ -148,10 +154,10 @@ HttpCacheSM::state_cache_open_read(int event, void *data) // than or equal to the max number of open read retries, // else treat as a cache miss. ink_assert(open_read_tries <= master_sm->t_state.txn_conf->max_cache_open_read_retries || write_locked); - Debug("http_cache", - "[%" PRId64 "] [state_cache_open_read] cache open read failure %d. " - "retrying cache open read...", - master_sm->sm_id, open_read_tries); + Dbg(dbg_ctl_http_cache, + "[%" PRId64 "] [state_cache_open_read] cache open read failure %d. " + "retrying cache open read...", + master_sm->sm_id, open_read_tries); do_cache_open_read(cache_key); break; @@ -206,13 +212,13 @@ HttpCacheSM::state_cache_open_write(int event, void *data) // without write retries in both a cache miss or a cache refresh scenario. if (write_retry_done()) { - Debug("http_cache", "[%" PRId64 "] [state_cache_open_write] cache open write failure %d. read retry triggered", - master_sm->sm_id, open_write_tries); + Dbg(dbg_ctl_http_cache, "[%" PRId64 "] [state_cache_open_write] cache open write failure %d. read retry triggered", + master_sm->sm_id, open_write_tries); if (master_sm->t_state.txn_conf->max_cache_open_read_retries <= 0) { - Debug("http_cache", - "[%" PRId64 "] [state_cache_open_write] invalid config, cache write fail set to" - " read retry, but, max_cache_open_read_retries is not enabled", - master_sm->sm_id); + Dbg(dbg_ctl_http_cache, + "[%" PRId64 "] [state_cache_open_write] invalid config, cache write fail set to" + " read retry, but, max_cache_open_read_retries is not enabled", + master_sm->sm_id); } open_read_tries = 0; @@ -233,10 +239,10 @@ HttpCacheSM::state_cache_open_write(int event, void *data) } else { // The cache is hosed or full or something. // Forward the failure to the main sm - Debug("http_cache", - "[%" PRId64 "] [state_cache_open_write] cache open write failure %d. " - "done retrying...", - master_sm->sm_id, open_write_tries); + Dbg(dbg_ctl_http_cache, + "[%" PRId64 "] [state_cache_open_write] cache open write failure %d. " + "done retrying...", + master_sm->sm_id, open_write_tries); open_write_cb = true; err_code = reinterpret_cast<intptr_t>(data); master_sm->handleEvent(event, &captive_action); @@ -245,17 +251,17 @@ HttpCacheSM::state_cache_open_write(int event, void *data) case EVENT_INTERVAL: if (master_sm->t_state.txn_conf->cache_open_write_fail_action == CACHE_WL_FAIL_ACTION_READ_RETRY) { - Debug("http_cache", - "[%" PRId64 "] [state_cache_open_write] cache open write failure %d. " - "falling back to read retry...", - master_sm->sm_id, open_write_tries); + Dbg(dbg_ctl_http_cache, + "[%" PRId64 "] [state_cache_open_write] cache open write failure %d. " + "falling back to read retry...", + master_sm->sm_id, open_write_tries); open_read_cb = false; master_sm->handleEvent(CACHE_EVENT_OPEN_READ, &captive_action); } else { - Debug("http_cache", - "[%" PRId64 "] [state_cache_open_write] cache open write failure %d. " - "retrying cache open write...", - master_sm->sm_id, open_write_tries); + Dbg(dbg_ctl_http_cache, + "[%" PRId64 "] [state_cache_open_write] cache open write failure %d. " + "retrying cache open write...", + master_sm->sm_id, open_write_tries); // Retry the cache open write if the number retries is less // than or equal to the max number of open write retries diff --git a/src/proxy/http/HttpConfig.cc b/src/proxy/http/HttpConfig.cc index 1cfde695b2..91b9470228 100644 --- a/src/proxy/http/HttpConfig.cc +++ b/src/proxy/http/HttpConfig.cc @@ -53,6 +53,12 @@ REC_EstablishStaticConfigByte(_ix, _n); \ REC_RegisterConfigUpdateFunc(_n, http_config_cb, NULL) +namespace +{ +DbgCtl dbg_ctl_http_config{"http_config"}; + +} // end anonymous namespace + class HttpConfigCont : public Continuation { public: @@ -74,7 +80,7 @@ template <typename T, unsigned N> static bool http_config_enum_search(std::string_view key, const ConfigEnumPair<T> (&list)[N], MgmtByte &value) { - Debug("http_config", "enum element %.*s", static_cast<int>(key.size()), key.data()); + Dbg(dbg_ctl_http_config, "enum element %.*s", static_cast<int>(key.size()), key.data()); // We don't expect any of these lists to be more than 10 long, so a linear search is the best choice. for (unsigned i = 0; i < N; ++i) { if (key.compare(list[i]._key) == 0) { @@ -126,7 +132,7 @@ HttpConfig::load_server_session_sharing_match(const char *key, MgmtByte &mask) std::string_view key_list(key); size_t start = 0; size_t offset = 0; - Debug("http_config", "enum mask value %s", key); + Dbg(dbg_ctl_http_config, "enum mask value %s", key); do { offset = key_list.find(',', start); if (offset == std::string_view::npos) { diff --git a/src/proxy/http/HttpSessionAccept.cc b/src/proxy/http/HttpSessionAccept.cc index 7351cacb2e..fcbf43e877 100644 --- a/src/proxy/http/HttpSessionAccept.cc +++ b/src/proxy/http/HttpSessionAccept.cc @@ -26,6 +26,12 @@ #include "proxy/http/Http1ClientSession.h" #include "iocore/utils/Machine.h" +namespace +{ +DbgCtl dbg_ctl_http_seq{"http_seq"}; + +} // end anonymous namespace + bool HttpSessionAccept::accept(NetVConnection *netvc, MIOBuffer *iobuf, IOBufferReader *reader) { @@ -44,9 +50,9 @@ HttpSessionAccept::accept(NetVConnection *netvc, MIOBuffer *iobuf, IOBufferReade netvc->attributes = transport_type; } - if (is_debug_tag_set("http_seq")) { - Debug("http_seq", "[HttpSessionAccept:mainEvent %p] accepted connection from %s transport type = %d", netvc, - ats_ip_nptop(client_ip, ipb, sizeof(ipb)), netvc->attributes); + if (dbg_ctl_http_seq.on()) { + Dbg(dbg_ctl_http_seq, "[HttpSessionAccept:mainEvent %p] accepted connection from %s transport type = %d", netvc, + ats_ip_nptop(client_ip, ipb, sizeof(ipb)), netvc->attributes); } Http1ClientSession *new_session = THREAD_ALLOC_INIT(http1ClientSessionAllocator, this_ethread()); diff --git a/src/proxy/http/HttpSessionManager.cc b/src/proxy/http/HttpSessionManager.cc index b64ba0ce70..e38996aee6 100644 --- a/src/proxy/http/HttpSessionManager.cc +++ b/src/proxy/http/HttpSessionManager.cc @@ -36,6 +36,12 @@ #include "proxy/http/HttpDebugNames.h" #include <iterator> +namespace +{ +DbgCtl dbg_ctl_http_ss{"http_ss"}; + +} // end anonymous namespace + // Initialize a thread to handle HTTP session management void initialize_thread_for_http_sessions(EThread *thread) @@ -92,7 +98,7 @@ ServerSessionPool::validate_host_sni(HttpSM *sm, NetVConnection *netvc) int len = 0; const char *req_host = sm->t_state.hdr_info.server_request.host_get(&len); retval = strncasecmp(session_sni, req_host, len) == 0; - Debug("http_ss", "validate_host_sni host=%*.s, sni=%s", len, req_host, session_sni); + Dbg(dbg_ctl_http_ss, "validate_host_sni host=%*.s, sni=%s", len, req_host, session_sni); } } return retval; @@ -108,8 +114,8 @@ ServerSessionPool::validate_sni(HttpSM *sm, NetVConnection *netvc) if (sm->t_state.scheme == URL_WKSIDX_HTTPS) { const char *session_sni = netvc->get_sni_servername(); std::string_view proposed_sni = sm->get_outbound_sni(); - Debug("http_ss", "validate_sni proposed_sni=%.*s, sni=%s", static_cast<int>(proposed_sni.length()), proposed_sni.data(), - session_sni); + Dbg(dbg_ctl_http_ss, "validate_sni proposed_sni=%.*s, sni=%s", static_cast<int>(proposed_sni.length()), proposed_sni.data(), + session_sni); if (!session_sni || proposed_sni.length() == 0) { retval = session_sni == nullptr && proposed_sni.length() == 0; } else { @@ -129,8 +135,8 @@ ServerSessionPool::validate_cert(HttpSM *sm, NetVConnection *netvc) if (sm->t_state.scheme == URL_WKSIDX_HTTPS) { const char *session_cert = netvc->options.ssl_client_cert_name; std::string_view proposed_cert = sm->get_outbound_cert(); - Debug("http_ss", "validate_cert proposed_cert=%.*s, cert=%s", static_cast<int>(proposed_cert.size()), proposed_cert.data(), - session_cert); + Dbg(dbg_ctl_http_ss, "validate_cert proposed_cert=%.*s, cert=%s", static_cast<int>(proposed_cert.size()), proposed_cert.data(), + session_cert); if (!session_cert || proposed_cert.length() == 0) { retval = session_cert == nullptr && proposed_cert.length() == 0; } else { @@ -148,7 +154,7 @@ ServerSessionPool::acquireSession(sockaddr const *addr, CryptoHash const &hostna to_return = nullptr; if ((TS_SERVER_SESSION_SHARING_MATCH_MASK_HOSTONLY & match_style) && !(TS_SERVER_SESSION_SHARING_MATCH_MASK_IP & match_style)) { - Debug("http_ss", "Search for host name only not IP. Pool size %zu", m_fqdn_pool.count()); + Dbg(dbg_ctl_http_ss, "Search for host name only not IP. Pool size %zu", m_fqdn_pool.count()); // This is broken out because only in this case do we check the host hash first. The range must be checked // to verify an upstream that matches port and SNI name is selected. Walk backwards to select oldest. in_port_t port = ats_ip_port_cast(addr); @@ -156,7 +162,7 @@ ServerSessionPool::acquireSession(sockaddr const *addr, CryptoHash const &hostna auto iter = std::make_reverse_iterator(range.end()); auto const end = std::make_reverse_iterator(range.begin()); while (iter != end) { - Debug("http_ss", "Compare port 0x%x against 0x%x", port, ats_ip_port_cast(iter->get_remote_addr())); + Dbg(dbg_ctl_http_ss, "Compare port 0x%x against 0x%x", port, ats_ip_port_cast(iter->get_remote_addr())); if (port == ats_ip_port_cast(iter->get_remote_addr()) && (!(match_style & TS_SERVER_SESSION_SHARING_MATCH_MASK_SNI) || validate_sni(sm, iter->get_netvc())) && (!(match_style & TS_SERVER_SESSION_SHARING_MATCH_MASK_HOSTSNISYNC) || validate_host_sni(sm, iter->get_netvc())) && @@ -172,7 +178,7 @@ ServerSessionPool::acquireSession(sockaddr const *addr, CryptoHash const &hostna this->removeSession(to_return); } } else if (iter != end) { - Debug("http_ss", "Failed find entry due to name mismatch %s", sm->t_state.current.server->name); + Dbg(dbg_ctl_http_ss, "Failed find entry due to name mismatch %s", sm->t_state.current.server->name); } } else if (TS_SERVER_SESSION_SHARING_MATCH_MASK_IP & match_style) { // matching is not disabled. auto range = m_ip_pool.equal_range(addr); @@ -227,10 +233,10 @@ ServerSessionPool::releaseSession(PoolableSession *ss) // put it in the pools. this->addSession(ss); - Debug("http_ss", - "[%" PRId64 "] [release session] " - "session placed into shared pool", - ss->connection_id()); + Dbg(dbg_ctl_http_ss, + "[%" PRId64 "] [release session] " + "session placed into shared pool", + ss->connection_id()); } // Called from the NetProcessor to let us know that a @@ -270,14 +276,14 @@ ServerSessionPool::eventHandler(int event, void *data) // origin, then reset the timeouts on our end and do not close the connection if ((event == VC_EVENT_INACTIVITY_TIMEOUT || event == VC_EVENT_ACTIVE_TIMEOUT) && s->state == PoolableSession::KA_POOLED && s->conn_track_group) { - Debug("http_ss", "s->conn_track_group->min_keep_alive_conns : %d", s->conn_track_group->_min_keep_alive_conns); + Dbg(dbg_ctl_http_ss, "s->conn_track_group->min_keep_alive_conns : %d", s->conn_track_group->_min_keep_alive_conns); bool connection_count_below_min = s->conn_track_group->_count <= s->conn_track_group->_min_keep_alive_conns; if (connection_count_below_min) { - Debug("http_ss", - "[%" PRId64 "] [session_bucket] session received io notice [%s], " - "resetting timeout to maintain minimum number of connections", - s->connection_id(), HttpDebugNames::get_event_name(event)); + Dbg(dbg_ctl_http_ss, + "[%" PRId64 "] [session_bucket] session received io notice [%s], " + "resetting timeout to maintain minimum number of connections", + s->connection_id(), HttpDebugNames::get_event_name(event)); s->get_netvc()->set_inactivity_timeout(s->get_netvc()->get_inactivity_timeout()); found = true; break; @@ -286,8 +292,8 @@ ServerSessionPool::eventHandler(int event, void *data) // We've found our server session. Remove it from // our lists and close it down - Debug("http_ss", "[%" PRId64 "] [session_pool] session %p received io notice [%s]", s->connection_id(), s, - HttpDebugNames::get_event_name(event)); + Dbg(dbg_ctl_http_ss, "[%" PRId64 "] [session_pool] session %p received io notice [%s]", s->connection_id(), s, + HttpDebugNames::get_event_name(event)); ink_assert(s->state == PoolableSession::KA_POOLED); // Out of the pool! Now! this->removeSession(s); @@ -362,17 +368,17 @@ HttpSessionManager::acquire_session(HttpSM *sm, sockaddr const *ip, const char * ServerSessionPool::validate_host_sni(sm, to_return->get_netvc())) && (!(match_style & TS_SERVER_SESSION_SHARING_MATCH_MASK_CERT) || ServerSessionPool::validate_cert(sm, to_return->get_netvc()))) { - Debug("http_ss", "[%" PRId64 "] [acquire session] returning attached session ", to_return->connection_id()); + Dbg(dbg_ctl_http_ss, "[%" PRId64 "] [acquire session] returning attached session ", to_return->connection_id()); to_return->state = PoolableSession::SSN_IN_USE; sm->create_server_txn(to_return); return HSM_DONE; } // Release this session back to the main session pool and // then continue looking for one from the shared pool - Debug("http_ss", - "[%" PRId64 "] [acquire session] " - "session not a match, returning to shared pool", - to_return->connection_id()); + Dbg(dbg_ctl_http_ss, + "[%" PRId64 "] [acquire session] " + "session not a match, returning to shared pool", + to_return->connection_id()); to_return->release(nullptr); to_return = nullptr; } @@ -444,11 +450,11 @@ HttpSessionManager::_acquire_session(sockaddr const *ip, CryptoHash const &hostn if (TS_SERVER_SESSION_SHARING_POOL_THREAD == pool_type) { retval = ethread->server_session_pool->acquireSession(ip, hostname_hash, match_style, sm, to_return); acquired = (HSM_DONE == retval); - Debug("http_ss", "[acquire session] thread pool search %s", to_return ? "successful" : "failed"); + Dbg(dbg_ctl_http_ss, "[acquire session] thread pool search %s", to_return ? "successful" : "failed"); } else { retval = m_g_pool->acquireSession(ip, hostname_hash, match_style, sm, to_return); acquired = (HSM_DONE == retval); - Debug("http_ss", "[acquire session] global pool search %s", to_return ? "successful" : "failed"); + Dbg(dbg_ctl_http_ss, "[acquire session] global pool search %s", to_return ? "successful" : "failed"); // At this point to_return has been removed from the pool. Do we need to move it // to the same thread? if (to_return) { @@ -486,12 +492,12 @@ HttpSessionManager::_acquire_session(sockaddr const *ip, CryptoHash const &hostn if (to_return) { if (sm->create_server_txn(to_return)) { - Debug("http_ss", "[%" PRId64 "] [acquire session] return session from shared pool", to_return->connection_id()); + Dbg(dbg_ctl_http_ss, "[%" PRId64 "] [acquire session] return session from shared pool", to_return->connection_id()); to_return->state = PoolableSession::SSN_IN_USE; retval = HSM_DONE; } else { - Debug("http_ss", "[%" PRId64 "] [acquire session] failed to get transaction on session from shared pool", - to_return->connection_id()); + Dbg(dbg_ctl_http_ss, "[%" PRId64 "] [acquire session] failed to get transaction on session from shared pool", + to_return->connection_id()); // Don't close the H2 origin. Otherwise you get use-after free with the activity timeout cop if (!to_return->is_multiplexing()) { to_return->do_io_close(); @@ -530,8 +536,8 @@ HttpSessionManager::release_session(PoolableSession *to_release) to_release->sharing_pool = TS_SERVER_SESSION_SHARING_POOL_THREAD; return release_session(to_release); } else { - Debug("http_ss", "[%" PRId64 "] [release session] could not release session due to lock contention", - to_release->connection_id()); + Dbg(dbg_ctl_http_ss, "[%" PRId64 "] [release session] could not release session due to lock contention", + to_release->connection_id()); released_p = false; } } @@ -549,16 +555,16 @@ ServerSessionPool::removeSession(PoolableSession *to_remove) EThread *ethread = this_ethread(); SCOPED_MUTEX_LOCK(lock, mutex, ethread); char peer_ip[INET6_ADDRPORTSTRLEN]; - if (is_debug_tag_set("http_ss")) { + if (dbg_ctl_http_ss.on()) { ats_ip_nptop(to_remove->get_remote_addr(), peer_ip, sizeof(peer_ip)); - Debug("http_ss", "Remove session %p %s m_fqdn_pool size=%zu m_ip_pool_size=%zu", to_remove, peer_ip, m_fqdn_pool.count(), - m_ip_pool.count()); + Dbg(dbg_ctl_http_ss, "Remove session %p %s m_fqdn_pool size=%zu m_ip_pool_size=%zu", to_remove, peer_ip, m_fqdn_pool.count(), + m_ip_pool.count()); } m_fqdn_pool.erase(to_remove); m_ip_pool.erase(to_remove); - if (is_debug_tag_set("http_ss")) { - Debug("http_ss", "After Remove session %p m_fqdn_pool size=%zu m_ip_pool_size=%zu", to_remove, m_fqdn_pool.count(), - m_ip_pool.count()); + if (dbg_ctl_http_ss.on()) { + Dbg(dbg_ctl_http_ss, "After Remove session %p m_fqdn_pool size=%zu m_ip_pool_size=%zu", to_remove, m_fqdn_pool.count(), + m_ip_pool.count()); } } @@ -571,9 +577,9 @@ ServerSessionPool::addSession(PoolableSession *ss) m_ip_pool.insert(ss); m_fqdn_pool.insert(ss); - if (is_debug_tag_set("http_ss")) { + if (dbg_ctl_http_ss.on()) { char peer_ip[INET6_ADDRPORTSTRLEN]; ats_ip_nptop(ss->get_remote_addr(), peer_ip, sizeof(peer_ip)); - Debug("http_ss", "[%" PRId64 "] [add session] session placed into shared pool under ip %s", ss->connection_id(), peer_ip); + Dbg(dbg_ctl_http_ss, "[%" PRId64 "] [add session] session placed into shared pool under ip %s", ss->connection_id(), peer_ip); } } diff --git a/src/proxy/http/HttpTransactHeaders.cc b/src/proxy/http/HttpTransactHeaders.cc index 9080263001..37b463e691 100644 --- a/src/proxy/http/HttpTransactHeaders.cc +++ b/src/proxy/http/HttpTransactHeaders.cc @@ -41,6 +41,14 @@ using namespace std::literals; +namespace +{ +DbgCtl dbg_ctl_http_trans{"http_trans"}; +DbgCtl dbg_ctl_http_transact_headers{"http_transact_headers"}; +DbgCtl dbg_ctl_anon{"anon"}; + +} // end anonymous namespace + bool HttpTransactHeaders::is_method_cacheable(const HttpConfigParams *http_config_param, const int method) { @@ -272,8 +280,8 @@ HttpTransactHeaders::convert_request(HTTPVersion outgoing_ver, HTTPHdr *outgoing } else if (outgoing_ver == HTTPVersion(1, 0)) { convert_to_1_0_request_header(outgoing_request); } else { - Debug("http_trans", "[HttpTransactHeaders::convert_request]" - "Unsupported Version - passing through"); + Dbg(dbg_ctl_http_trans, "[HttpTransactHeaders::convert_request]" + "Unsupported Version - passing through"); } } @@ -287,8 +295,8 @@ HttpTransactHeaders::convert_response(HTTPVersion outgoing_ver, HTTPHdr *outgoin } else if (outgoing_ver == HTTPVersion(1, 0)) { convert_to_1_0_response_header(outgoing_response, reason_phrase); } else { - Debug("http_trans", "[HttpTransactHeaders::convert_response]" - "Unsupported Version - passing through"); + Dbg(dbg_ctl_http_trans, "[HttpTransactHeaders::convert_response]" + "Unsupported Version - passing through"); } } @@ -347,7 +355,7 @@ HttpTransactHeaders::convert_to_1_0_response_header(HTTPHdr *outgoing_response, // Set reason phrase if passed in. if (reason_phrase != nullptr) { - Debug("http_transact_headers", "Setting HTTP/1.0 reason phrase to '%s'", reason_phrase); + Dbg(dbg_ctl_http_transact_headers, "Setting HTTP/1.0 reason phrase to '%s'", reason_phrase); outgoing_response->reason_set(reason_phrase, strlen(reason_phrase)); } @@ -369,7 +377,7 @@ HttpTransactHeaders::convert_to_1_1_response_header(HTTPHdr *outgoing_response, // Set reason phrase if passed in. if (reason_phrase != nullptr) { - Debug("http_transact_headers", "Setting HTTP/1.1 reason phrase to '%s'", reason_phrase); + Dbg(dbg_ctl_http_transact_headers, "Setting HTTP/1.1 reason phrase to '%s'", reason_phrase); outgoing_response->reason_set(reason_phrase, strlen(reason_phrase)); } } @@ -898,8 +906,8 @@ HttpTransactHeaders::add_global_user_agent_header_to_request(const OverridableHt if (http_txn_conf->global_user_agent_header) { MIMEField *ua_field; - Debug("http_trans", "Adding User-Agent: %.*s", static_cast<int>(http_txn_conf->global_user_agent_header_size), - http_txn_conf->global_user_agent_header); + Dbg(dbg_ctl_http_trans, "Adding User-Agent: %.*s", static_cast<int>(http_txn_conf->global_user_agent_header_size), + http_txn_conf->global_user_agent_header); if ((ua_field = header->field_find(MIME_FIELD_USER_AGENT, MIME_LEN_USER_AGENT)) == nullptr) { if (likely((ua_field = header->field_create(MIME_FIELD_USER_AGENT, MIME_LEN_USER_AGENT)) != nullptr)) { header->field_attach(ua_field); @@ -942,7 +950,7 @@ HttpTransactHeaders::add_forwarded_field_to_request(HttpTransact::State *s, HTTP } if (ats_ip_ntop(&src_addr.sa, hdr.aux_data(), hdr.remaining()) == nullptr) { - Debug("http_trans", "[add_forwarded_field_to_outgoing_request] ats_ip_ntop() call failed"); + Dbg(dbg_ctl_http_trans, "[add_forwarded_field_to_outgoing_request] ats_ip_ntop() call failed"); return; } @@ -996,7 +1004,7 @@ HttpTransactHeaders::add_forwarded_field_to_request(HttpTransact::State *s, HTTP } if (ats_ip_ntop(&s->client_info.dst_addr.sa, hdr.aux_data(), hdr.remaining()) == nullptr) { - Debug("http_trans", "[add_forwarded_field_to_outgoing_request] ats_ip_ntop() call failed"); + Dbg(dbg_ctl_http_trans, "[add_forwarded_field_to_outgoing_request] ats_ip_ntop() call failed"); return; } @@ -1093,8 +1101,8 @@ HttpTransactHeaders::add_forwarded_field_to_request(HttpTransact::State *s, HTTP request->value_append(MIME_FIELD_FORWARDED, MIME_LEN_FORWARDED, sV.data(), sV.size(), true, ','); // true => separator must // be inserted - Debug("http_trans", "[add_forwarded_field_to_outgoing_request] Forwarded header (%.*s) added", static_cast<int>(hdr.size()), - hdr.data()); + Dbg(dbg_ctl_http_trans, "[add_forwarded_field_to_outgoing_request] Forwarded header (%.*s) added", + static_cast<int>(hdr.size()), hdr.data()); } } @@ -1118,7 +1126,7 @@ HttpTransactHeaders::add_server_header_to_response(const OverridableHttpConfigPa // This will remove any old string (free it), and set our Server header. if (do_add && likely(ua_field)) { - Debug("http_trans", "Adding Server: %s", http_txn_conf->proxy_response_server_string); + Dbg(dbg_ctl_http_trans, "Adding Server: %s", http_txn_conf->proxy_response_server_string); header->field_value_set(ua_field, http_txn_conf->proxy_response_server_string, http_txn_conf->proxy_response_server_string_len); } @@ -1135,27 +1143,27 @@ HttpTransactHeaders::remove_privacy_headers_from_request(HttpConfigParams *http_ // From if (http_txn_conf->anonymize_remove_from) { - Debug("anon", "removing 'From' headers"); + Dbg(dbg_ctl_anon, "removing 'From' headers"); header->field_delete(MIME_FIELD_FROM, MIME_LEN_FROM); } // Referer if (http_txn_conf->anonymize_remove_referer) { - Debug("anon", "removing 'Referer' headers"); + Dbg(dbg_ctl_anon, "removing 'Referer' headers"); header->field_delete(MIME_FIELD_REFERER, MIME_LEN_REFERER); } // User-Agent if (http_txn_conf->anonymize_remove_user_agent) { - Debug("anon", "removing 'User-agent' headers"); + Dbg(dbg_ctl_anon, "removing 'User-agent' headers"); header->field_delete(MIME_FIELD_USER_AGENT, MIME_LEN_USER_AGENT); } // Cookie if (http_txn_conf->anonymize_remove_cookie) { - Debug("anon", "removing 'Cookie' headers"); + Dbg(dbg_ctl_anon, "removing 'Cookie' headers"); header->field_delete(MIME_FIELD_COOKIE, MIME_LEN_COOKIE); } // Client-ip if (http_txn_conf->anonymize_remove_client_ip) { - Debug("anon", "removing 'Client-ip' headers"); + Dbg(dbg_ctl_anon, "removing 'Client-ip' headers"); header->field_delete(MIME_FIELD_CLIENT_IP, MIME_LEN_CLIENT_IP); } ///////////////////////////////////////////// @@ -1170,10 +1178,10 @@ HttpTransactHeaders::remove_privacy_headers_from_request(HttpConfigParams *http_ const char *anon_string; anon_string = http_config_param->anonymize_other_header_list; - Debug("anon", "removing other headers (%s)", anon_string); + Dbg(dbg_ctl_anon, "removing other headers (%s)", anon_string); HttpCompat::parse_comma_list(&anon_list, anon_string); for (field = anon_list.head; field != nullptr; field = field->next) { - Debug("anon", "removing '%s' headers", field->str); + Dbg(dbg_ctl_anon, "removing '%s' headers", field->str); header->field_delete(field->str, field->len); } } @@ -1192,38 +1200,38 @@ HttpTransactHeaders::normalize_accept_encoding(const OverridableHttpConfigParams // Force Accept-Encoding header to gzip or no header. if (HttpTransactCache::match_content_encoding(ae_field, "gzip")) { header->field_value_set(ae_field, "gzip", 4); - Debug("http_trans", "[Headers::normalize_accept_encoding] normalized Accept-Encoding to gzip"); + Dbg(dbg_ctl_http_trans, "[Headers::normalize_accept_encoding] normalized Accept-Encoding to gzip"); } else { header->field_delete(ae_field); - Debug("http_trans", "[Headers::normalize_accept_encoding] removed non-gzip Accept-Encoding"); + Dbg(dbg_ctl_http_trans, "[Headers::normalize_accept_encoding] removed non-gzip Accept-Encoding"); } } else if (normalize_ae == 2) { // Force Accept-Encoding header to br (Brotli) or no header. if (HttpTransactCache::match_content_encoding(ae_field, "br")) { header->field_value_set(ae_field, "br", 2); - Debug("http_trans", "[Headers::normalize_accept_encoding] normalized Accept-Encoding to br"); + Dbg(dbg_ctl_http_trans, "[Headers::normalize_accept_encoding] normalized Accept-Encoding to br"); } else if (HttpTransactCache::match_content_encoding(ae_field, "gzip")) { header->field_value_set(ae_field, "gzip", 4); - Debug("http_trans", "[Headers::normalize_accept_encoding] normalized Accept-Encoding to gzip"); + Dbg(dbg_ctl_http_trans, "[Headers::normalize_accept_encoding] normalized Accept-Encoding to gzip"); } else { header->field_delete(ae_field); - Debug("http_trans", "[Headers::normalize_accept_encoding] removed non-br Accept-Encoding"); + Dbg(dbg_ctl_http_trans, "[Headers::normalize_accept_encoding] removed non-br Accept-Encoding"); } } else if (normalize_ae == 3) { // Force Accept-Encoding header to br,gzip, or br, or gzip, or no header. if (HttpTransactCache::match_content_encoding(ae_field, "br") && HttpTransactCache::match_content_encoding(ae_field, "gzip")) { header->field_value_set(ae_field, "br, gzip", 8); - Debug("http_trans", "[Headers::normalize_accept_encoding] normalized Accept-Encoding to br, gzip"); + Dbg(dbg_ctl_http_trans, "[Headers::normalize_accept_encoding] normalized Accept-Encoding to br, gzip"); } else if (HttpTransactCache::match_content_encoding(ae_field, "br")) { header->field_value_set(ae_field, "br", 2); - Debug("http_trans", "[Headers::normalize_accept_encoding] normalized Accept-Encoding to br"); + Dbg(dbg_ctl_http_trans, "[Headers::normalize_accept_encoding] normalized Accept-Encoding to br"); } else if (HttpTransactCache::match_content_encoding(ae_field, "gzip")) { header->field_value_set(ae_field, "gzip", 4); - Debug("http_trans", "[Headers::normalize_accept_encoding] normalized Accept-Encoding to gzip"); + Dbg(dbg_ctl_http_trans, "[Headers::normalize_accept_encoding] normalized Accept-Encoding to gzip"); } else { header->field_delete(ae_field); - Debug("http_trans", "[Headers::normalize_accept_encoding] removed non-br non-gzip Accept-Encoding"); + Dbg(dbg_ctl_http_trans, "[Headers::normalize_accept_encoding] removed non-br non-gzip Accept-Encoding"); } } else { static bool logged = false; diff --git a/src/proxy/http/HttpTunnel.cc b/src/proxy/http/HttpTunnel.cc index 16d4eca89d..4c9a00fe8b 100644 --- a/src/proxy/http/HttpTunnel.cc +++ b/src/proxy/http/HttpTunnel.cc @@ -42,12 +42,20 @@ #include "tscore/ParseRules.h" #include "tscore/ink_memory.h" -static const int min_block_transfer_bytes = 256; -static const char *const CHUNK_HEADER_FMT = "%" PRIx64 "\r\n"; +namespace +{ +DbgCtl dbg_ctl_http_chunk{"http_chunk"}; +DbgCtl dbg_ctl_http_redirect{"http_redirect"}; +DbgCtl dbg_ctl_http_tunnel{"http_tunnel"}; + +const int min_block_transfer_bytes = 256; +const char *const CHUNK_HEADER_FMT = "%" PRIx64 "\r\n"; // This should be as small as possible because it will only hold the // header and trailer per chunk - the chunk body will be a reference to // a block in the input stream. -static int const CHUNK_IOBUFFER_SIZE_INDEX = MIN_IOBUFFER_SIZE; +int const CHUNK_IOBUFFER_SIZE_INDEX = MIN_IOBUFFER_SIZE; + +} // end anonymous namespace ChunkedHandler::ChunkedHandler() : max_chunk_size(DEFAULT_MAX_CHUNK_SIZE) {} @@ -169,7 +177,7 @@ ChunkedHandler::read_size() } } else if (state == CHUNK_READ_SIZE_CRLF) { // Scan for a linefeed if (ParseRules::is_lf(*tmp)) { - Debug("http_chunk", "read chunk size of %d bytes", running_sum); + Dbg(dbg_ctl_http_chunk, "read chunk size of %d bytes", running_sum); bytes_left = (cur_chunk_size = running_sum); state = (running_sum == 0) ? CHUNK_READ_TRAILER_BLANK : CHUNK_READ_CHUNK; done = true; @@ -251,11 +259,11 @@ ChunkedHandler::read_chunk() ink_assert(bytes_left >= 0); if (bytes_left == 0) { - Debug("http_chunk", "completed read of chunk of %" PRId64 " bytes", cur_chunk_size); + Dbg(dbg_ctl_http_chunk, "completed read of chunk of %" PRId64 " bytes", cur_chunk_size); state = CHUNK_READ_SIZE_START; } else if (bytes_left > 0) { - Debug("http_chunk", "read %" PRId64 " bytes of an %" PRId64 " chunk", b, cur_chunk_size); + Dbg(dbg_ctl_http_chunk, "read %" PRId64 " bytes of an %" PRId64 " chunk", b, cur_chunk_size); } } @@ -284,7 +292,7 @@ ChunkedHandler::read_trailer() // or must have only had a CR on it if (state == CHUNK_READ_TRAILER_CR || state == CHUNK_READ_TRAILER_BLANK) { state = CHUNK_READ_DONE; - Debug("http_chunk", "completed read of trailers"); + Dbg(dbg_ctl_http_chunk, "completed read of trailers"); done = true; break; } else { @@ -352,7 +360,7 @@ ChunkedHandler::generate_chunked_content() int64_t write_val = std::min(max_chunk_size, r_avail); state = CHUNK_WRITE_CHUNK; - Debug("http_chunk", "creating a chunk of size %" PRId64 " bytes", write_val); + Dbg(dbg_ctl_http_chunk, "creating a chunk of size %" PRId64 " bytes", write_val); // Output the chunk size. if (write_val != max_chunk_size) { @@ -634,7 +642,7 @@ HttpTunnel::add_producer(VConnection *vc, int64_t nbytes_arg, IOBufferReader *re { HttpTunnelProducer *p; - Debug("http_tunnel", "[%" PRId64 "] adding producer '%s'", sm->sm_id, name_arg); + Dbg(dbg_ctl_http_tunnel, "[%" PRId64 "] adding producer '%s'", sm->sm_id, name_arg); ink_assert(reader_start->mbuf); if ((p = alloc_producer()) != nullptr) { @@ -689,7 +697,7 @@ HttpTunnelConsumer * HttpTunnel::add_consumer(VConnection *vc, VConnection *producer, HttpConsumerHandler sm_handler, HttpTunnelType_t vc_type, const char *name_arg, int64_t skip_bytes) { - Debug("http_tunnel", "[%" PRId64 "] adding consumer '%s'", sm->sm_id, name_arg); + Dbg(dbg_ctl_http_tunnel, "[%" PRId64 "] adding consumer '%s'", sm->sm_id, name_arg); // Find the producer entry HttpTunnelProducer *p = get_producer(producer); @@ -698,7 +706,7 @@ HttpTunnel::add_consumer(VConnection *vc, VConnection *producer, HttpConsumerHan // Check to see if the producer terminated // without sending all of its data if (p->alive == false && p->read_success == false) { - Debug("http_tunnel", "[%" PRId64 "] consumer '%s' not added due to producer failure", sm->sm_id, name_arg); + Dbg(dbg_ctl_http_tunnel, "[%" PRId64 "] consumer '%s' not added due to producer failure", sm->sm_id, name_arg); return nullptr; } // Initialize the consumer structure @@ -737,7 +745,7 @@ void HttpTunnel::tunnel_run(HttpTunnelProducer *p_arg) { ++reentrancy_count; - Debug("http_tunnel", "tunnel_run started, p_arg is %s", p_arg ? "provided" : "NULL"); + Dbg(dbg_ctl_http_tunnel, "tunnel_run started, p_arg is %s", p_arg ? "provided" : "NULL"); if (p_arg) { producer_run(p_arg); } else { @@ -826,8 +834,8 @@ HttpTunnel::producer_run(HttpTunnelProducer *p) } if (p->do_dechunking) { // bz57413 - Debug("http_tunnel", "[producer_run] do_dechunking p->chunked_handler.chunked_reader->read_avail() = %" PRId64 "", - p->chunked_handler.chunked_reader->read_avail()); + Dbg(dbg_ctl_http_tunnel, "[producer_run] do_dechunking p->chunked_handler.chunked_reader->read_avail() = %" PRId64 "", + p->chunked_handler.chunked_reader->read_avail()); // initialize a reader to dechunked buffer start before writing to keep ref count dechunked_buffer_start = p->chunked_handler.dechunked_buffer->alloc_reader(); @@ -837,7 +845,7 @@ HttpTunnel::producer_run(HttpTunnelProducer *p) if (!transform_consumer) { p->chunked_handler.dechunked_buffer->write(p->buffer_start, p->chunked_handler.skip_bytes); - Debug("http_tunnel", "[producer_run] do_dechunking::Copied header of size %" PRId64 "", p->chunked_handler.skip_bytes); + Dbg(dbg_ctl_http_tunnel, "[producer_run] do_dechunking::Copied header of size %" PRId64 "", p->chunked_handler.skip_bytes); } } } @@ -895,8 +903,8 @@ HttpTunnel::producer_run(HttpTunnelProducer *p) // including the maximum configured post data size if ((p->vc_type == HT_BUFFER_READ && sm->is_postbuf_valid()) || (p->alive && sm->t_state.method == HTTP_WKSIDX_POST && sm->enable_redirection && p->vc_type == HT_HTTP_CLIENT)) { - Debug("http_redirect", "[HttpTunnel::producer_run] client post: %" PRId64 " max size: %" PRId64 "", - p->buffer_start->read_avail(), HttpConfig::m_master.post_copy_size); + Dbg(dbg_ctl_http_redirect, "[HttpTunnel::producer_run] client post: %" PRId64 " max size: %" PRId64 "", + p->buffer_start->read_avail(), HttpConfig::m_master.post_copy_size); // (note that since we are not dechunking POST, this is the chunked size if chunked) if (p->buffer_start->read_avail() > HttpConfig::m_master.post_copy_size) { @@ -927,12 +935,12 @@ HttpTunnel::producer_run(HttpTunnelProducer *p) // bz57413 // If there is no transformation plugin, then we didn't add the header, hence no need to consume it - Debug("http_tunnel", "[producer_run] do_dechunking p->chunked_handler.chunked_reader->read_avail() = %" PRId64 "", - p->chunked_handler.chunked_reader->read_avail()); + Dbg(dbg_ctl_http_tunnel, "[producer_run] do_dechunking p->chunked_handler.chunked_reader->read_avail() = %" PRId64 "", + p->chunked_handler.chunked_reader->read_avail()); if (!transform_consumer && (p->chunked_handler.chunked_reader->read_avail() >= p->chunked_handler.skip_bytes)) { p->chunked_handler.chunked_reader->consume(p->chunked_handler.skip_bytes); - Debug("http_tunnel", "[producer_run] do_dechunking p->chunked_handler.skip_bytes = %" PRId64 "", - p->chunked_handler.skip_bytes); + Dbg(dbg_ctl_http_tunnel, "[producer_run] do_dechunking p->chunked_handler.skip_bytes = %" PRId64 "", + p->chunked_handler.skip_bytes); } // if(p->chunked_handler.chunked_reader->read_avail() > 0) // p->chunked_handler.chunked_reader->consume( @@ -997,7 +1005,7 @@ HttpTunnel::producer_run(HttpTunnelProducer *p) p->handler_state = HTTP_SM_POST_SUCCESS; } } - Debug("http_tunnel", "Start write vio %" PRId64 " bytes", c_write); + Dbg(dbg_ctl_http_tunnel, "Start write vio %" PRId64 " bytes", c_write); // Start the writes now that we know we will consume all the initial data c->write_vio = c->vc->do_io_write(this, c_write, c->buffer_reader); ink_assert(c_write > 0); @@ -1018,13 +1026,13 @@ HttpTunnel::producer_run(HttpTunnelProducer *p) p->alive = false; p->read_success = true; p->handler_state = HTTP_SM_POST_SUCCESS; - Debug("http_tunnel", "[%" PRId64 "] [tunnel_run] producer already done", sm->sm_id); + Dbg(dbg_ctl_http_tunnel, "[%" PRId64 "] [tunnel_run] producer already done", sm->sm_id); producer_handler(HTTP_TUNNEL_EVENT_PRECOMPLETE, p); } else { if (read_start_pos > 0) { p->read_vio = ((CacheVC *)p->vc)->do_io_pread(this, producer_n, p->read_buffer, read_start_pos); } else { - Debug("http_tunnel", "Start read vio %" PRId64 " bytes", producer_n); + Dbg(dbg_ctl_http_tunnel, "Start read vio %" PRId64 " bytes", producer_n); p->read_vio = p->vc->do_io_read(this, producer_n, p->read_buffer); p->read_vio->reenable(); } @@ -1051,8 +1059,8 @@ HttpTunnel::producer_handler_dechunked(int event, HttpTunnelProducer *p) { ink_assert(p->do_chunking); - Debug("http_tunnel", "[%" PRId64 "] producer_handler_dechunked [%s %s]", sm->sm_id, p->name, - HttpDebugNames::get_event_name(event)); + Dbg(dbg_ctl_http_tunnel, "[%" PRId64 "] producer_handler_dechunked [%s %s]", sm->sm_id, p->name, + HttpDebugNames::get_event_name(event)); // We only interested in translating certain events switch (event) { @@ -1091,7 +1099,8 @@ HttpTunnel::producer_handler_chunked(int event, HttpTunnelProducer *p) { ink_assert(p->do_dechunking || p->do_chunked_passthru); - Debug("http_tunnel", "[%" PRId64 "] producer_handler_chunked [%s %s]", sm->sm_id, p->name, HttpDebugNames::get_event_name(event)); + Dbg(dbg_ctl_http_tunnel, "[%" PRId64 "] producer_handler_chunked [%s %s]", sm->sm_id, p->name, + HttpDebugNames::get_event_name(event)); // We only interested in translating certain events switch (event) { @@ -1111,7 +1120,7 @@ HttpTunnel::producer_handler_chunked(int event, HttpTunnelProducer *p) // If we couldn't understand the encoding, return // an error if (p->chunked_handler.state == ChunkedHandler::CHUNK_READ_ERROR) { - Debug("http_tunnel", "[%" PRId64 "] producer_handler_chunked [%s chunk decoding error]", sm->sm_id, p->name); + Dbg(dbg_ctl_http_tunnel, "[%" PRId64 "] producer_handler_chunked [%s chunk decoding error]", sm->sm_id, p->name); p->chunked_handler.truncation = true; // FIX ME: we return EOS here since it will cause the // the client to be reenabled. ERROR makes more @@ -1156,7 +1165,7 @@ HttpTunnel::producer_handler(int event, HttpTunnelProducer *p) HttpProducerHandler jump_point; bool sm_callback = false; - Debug("http_tunnel", "[%" PRId64 "] producer_handler [%s %s]", sm->sm_id, p->name, HttpDebugNames::get_event_name(event)); + Dbg(dbg_ctl_http_tunnel, "[%" PRId64 "] producer_handler [%s %s]", sm->sm_id, p->name, HttpDebugNames::get_event_name(event)); // Handle chunking/dechunking/chunked-passthrough if necessary. if (p->do_chunking) { @@ -1173,7 +1182,7 @@ HttpTunnel::producer_handler(int event, HttpTunnelProducer *p) if ((p->vc_type == HT_BUFFER_READ && sm->is_postbuf_valid()) || (sm->t_state.method == HTTP_WKSIDX_POST && sm->enable_redirection && (event == VC_EVENT_READ_READY || event == VC_EVENT_READ_COMPLETE) && p->vc_type == HT_HTTP_CLIENT)) { - Debug("http_redirect", "[HttpTunnel::producer_handler] [%s %s]", p->name, HttpDebugNames::get_event_name(event)); + Dbg(dbg_ctl_http_redirect, "[HttpTunnel::producer_handler] [%s %s]", p->name, HttpDebugNames::get_event_name(event)); if ((sm->postbuf_buffer_avail() + sm->postbuf_reader_avail()) > HttpConfig::m_master.post_copy_size) { Warning("http_redirect, [HttpTunnel::producer_handler] post exceeds buffer limit, buffer_avail=%" PRId64 @@ -1191,8 +1200,8 @@ HttpTunnel::producer_handler(int event, HttpTunnelProducer *p) } } // end of added logic for partial copy of POST - Debug("http_redirect", "[%" PRId64 "] enable_redirection: [%d %d %d] event: %d, state: %d", sm->sm_id, p->alive == true, - sm->enable_redirection, (p->self_consumer && p->self_consumer->alive == true), event, p->chunked_handler.state); + Dbg(dbg_ctl_http_redirect, "[%" PRId64 "] enable_redirection: [%d %d %d] event: %d, state: %d", sm->sm_id, p->alive == true, + sm->enable_redirection, (p->self_consumer && p->self_consumer->alive == true), event, p->chunked_handler.state); switch (event) { case VC_EVENT_READ_READY: @@ -1203,7 +1212,7 @@ HttpTunnel::producer_handler(int event, HttpTunnelProducer *p) // Data read from producer, reenable consumers for (c = p->consumer_list.head; c; c = c->link.next) { if (c->alive && c->write_vio) { - Debug("http_redirect", "Read ready alive"); + Dbg(dbg_ctl_http_redirect, "Read ready alive"); c->write_vio->reenable(); } } @@ -1302,8 +1311,8 @@ HttpTunnel::consumer_reenable(HttpTunnelConsumer *c) HttpTunnelProducer *srcp = p->flow_control_source; if (backlog >= flow_state.high_water) { - if (is_debug_tag_set("http_tunnel")) { - Debug("http_tunnel", "[%" PRId64 "] Throttle %p %" PRId64 " / %" PRId64, sm->sm_id, p, backlog, p->backlog()); + if (dbg_ctl_http_tunnel.on()) { + Dbg(dbg_ctl_http_tunnel, "[%" PRId64 "] Throttle %p %" PRId64 " / %" PRId64, sm->sm_id, p, backlog, p->backlog()); } p->throttle(); // p becomes srcp for future calls to this method } else { @@ -1317,8 +1326,8 @@ HttpTunnel::consumer_reenable(HttpTunnelConsumer *c) backlog = srcp->backlog(flow_state.low_water); } if (backlog < flow_state.low_water) { - if (is_debug_tag_set("http_tunnel")) { - Debug("http_tunnel", "[%" PRId64 "] Unthrottle %p %" PRId64 " / %" PRId64, sm->sm_id, p, backlog, p->backlog()); + if (dbg_ctl_http_tunnel.on()) { + Dbg(dbg_ctl_http_tunnel, "[%" PRId64 "] Unthrottle %p %" PRId64 " / %" PRId64, sm->sm_id, p, backlog, p->backlog()); } srcp->unthrottle(); if (srcp->read_vio) { @@ -1363,7 +1372,7 @@ HttpTunnel::consumer_handler(int event, HttpTunnelConsumer *c) HttpConsumerHandler jump_point; HttpTunnelProducer *p = c->producer; - Debug("http_tunnel", "[%" PRId64 "] consumer_handler [%s %s]", sm->sm_id, c->name, HttpDebugNames::get_event_name(event)); + Dbg(dbg_ctl_http_tunnel, "[%" PRId64 "] consumer_handler [%s %s]", sm->sm_id, c->name, HttpDebugNames::get_event_name(event)); ink_assert(c->alive == true); @@ -1436,7 +1445,7 @@ HttpTunnel::consumer_handler(int event, HttpTunnelConsumer *c) // [amc] I don't think this happens but we'll leave a debug trap // here just in case. if (p->is_throttled()) { - Debug("http_tunnel", "Special event %s on %p with flow control on", HttpDebugNames::get_event_name(event), p); + Dbg(dbg_ctl_http_tunnel, "Special event %s on %p with flow control on", HttpDebugNames::get_event_name(event), p); } break; @@ -1793,7 +1802,7 @@ HttpTunnel::_is_tls_tunnel_active() const ink_hrtime now = ink_get_hrtime(); - Debug("http_tunnel", "now=%" PRId64 " last_update=%" PRId64, now, _tls_tunnel_last_update); + Dbg(dbg_ctl_http_tunnel, "now=%" PRId64 " last_update=%" PRId64, now, _tls_tunnel_last_update); // In some cases, m_tls_tunnel_last_update could be larger than now, because it's using cached current time. // - e.g. comparing Thread::cur_time of different threads. diff --git a/src/proxy/http/PreWarmManager.cc b/src/proxy/http/PreWarmManager.cc index 6c11049132..86e0e92fe9 100644 --- a/src/proxy/http/PreWarmManager.cc +++ b/src/proxy/http/PreWarmManager.cc @@ -36,14 +36,22 @@ #include <algorithm> -#define PreWarmSMDebug(fmt, ...) Debug("prewarm_sm", "[%p] " fmt, this, ##__VA_ARGS__); -#define PreWarmSMVDebug(fmt, ...) Debug("v_prewarm_sm", "[%p] " fmt, this, ##__VA_ARGS__); +#define PreWarmSMDbg(fmt, ...) Dbg(dbg_ctl_prewarm_sm, "[%p] " fmt, this, ##__VA_ARGS__); +#define PreWarmSMVDbg(fmt, ...) Dbg(dbg_ctl_v_prewarm_sm, "[%p] " fmt, this, ##__VA_ARGS__); ClassAllocator<PreWarmSM> preWarmSMAllocator("preWarmSMAllocator"); PreWarmManager prewarmManager; namespace { +DbgCtl dbg_ctl_prewarm_sm{"prewarm_sm"}; +DbgCtl dbg_ctl_v_prewarm_conf{"v_prewarm_conf"}; +DbgCtl dbg_ctl_v_prewarm_q{"v_prewarm_q"}; +DbgCtl dbg_ctl_prewarm{"prewarm"}; +DbgCtl dbg_ctl_prewarm_m{"prewarm_m"}; +DbgCtl dbg_ctl_v_prewarm_sm{"v_prewarm_sm"}; +DbgCtl dbg_ctl_v_prewarm_init{"v_prewarm_init"}; + using namespace std::literals; constexpr ts_seconds DOWN_SERVER_TIMEOUT = 300s; @@ -112,8 +120,8 @@ PreWarmSM::PreWarmSM(const PreWarm::SPtrConstDst &dst, const PreWarm::SPtrConstC { SET_HANDLER(&PreWarmSM::state_init); - Debug("v_prewarm_conf", "host=%p _dst=%ld _conf=%ld _stats_ids=%ld", dst->host.data(), _dst.use_count(), _conf.use_count(), - _stats_ids.use_count()); + Dbg(dbg_ctl_v_prewarm_conf, "host=%p _dst=%ld _conf=%ld _stats_ids=%ld", dst->host.data(), _dst.use_count(), _conf.use_count(), + _stats_ids.use_count()); } PreWarmSM::~PreWarmSM() {} @@ -228,8 +236,8 @@ PreWarmSM::state_init(int event, void *data) _timeout.set_active_timeout(_conf->connect_timeout); _milestones.mark(Milestone::INIT); - PreWarmSMDebug("pre-warming a netvc dst=%.*s:%d type=%d alpn=%d retry=%" PRIu32, (int)_dst->host.size(), _dst->host.data(), - _dst->port, (int)_dst->type, _dst->alpn_index, _retry_counter); + PreWarmSMDbg("pre-warming a netvc dst=%.*s:%d type=%d alpn=%d retry=%" PRIu32, (int)_dst->host.size(), _dst->host.data(), + _dst->port, (int)_dst->type, _dst->alpn_index, _retry_counter); if (_conf->srv_enabled) { char target[MAXDNAME]; @@ -241,7 +249,7 @@ PreWarmSM::state_init(int event, void *data) memcpy(target + target_len, _dst->host.data(), _dst->host.size()); target_len += _dst->host.size(); - PreWarmSMVDebug("lookup SRV by %.*s", (int)target_len, target); + PreWarmSMVDbg("lookup SRV by %.*s", (int)target_len, target); Action *srv_lookup_action_handle = hostDBProcessor.getSRVbyname_imm( this, static_cast<cb_process_result_pfn>(&PreWarmSM::process_srv_info), target, target_len); @@ -249,7 +257,7 @@ PreWarmSM::state_init(int event, void *data) _pending_action = srv_lookup_action_handle; } } else { - PreWarmSMVDebug("lookup A/AAAA by %.*s", (int)_dst->host.size(), _dst->host.data()); + PreWarmSMVDbg("lookup A/AAAA by %.*s", (int)_dst->host.size(), _dst->host.data()); Action *dns_lookup_action_handle = hostDBProcessor.getbyname_imm( this, static_cast<cb_process_result_pfn>(&PreWarmSM::process_hostdb_info), _dst->host.data(), _dst->host.size()); @@ -278,7 +286,7 @@ PreWarmSM::state_dns_lookup(int event, void *data) _pending_action = nullptr; if (record == nullptr || record->is_failed()) { - PreWarmSMVDebug("hostdb lookup is failed"); + PreWarmSMVDbg("hostdb lookup is failed"); retry(); return EVENT_DONE; @@ -287,7 +295,7 @@ PreWarmSM::state_dns_lookup(int event, void *data) HostDBInfo *info = record->select_next_rr(ts_clock::now(), DOWN_SERVER_TIMEOUT); if (info == nullptr) { - PreWarmSMVDebug("hostdb lookup found no entry"); + PreWarmSMVDbg("hostdb lookup found no entry"); retry(); return EVENT_DONE; } @@ -296,9 +304,9 @@ PreWarmSM::state_dns_lookup(int event, void *data) addr.network_order_port() = htons(_dst->port); - if (is_debug_tag_set("v_prewarm_sm")) { + if (dbg_ctl_v_prewarm_sm.on()) { char addrbuf[INET6_ADDRPORTSTRLEN]; - PreWarmSMVDebug("hostdb lookup is done %s", ats_ip_nptop(addr, addrbuf, sizeof(addrbuf))); + PreWarmSMVDbg("hostdb lookup is done %s", ats_ip_nptop(addr, addrbuf, sizeof(addrbuf))); } SET_HANDLER(&PreWarmSM::state_net_open); @@ -376,7 +384,7 @@ PreWarmSM::state_net_open(int event, void *data) NetVConnection *netvc = static_cast<NetVConnection *>(vio->vc_server); ink_release_assert(netvc == _netvc); - PreWarmSMVDebug("%s Handshake is done netvc=%p", (_dst->type == SNIRoutingType::FORWARD) ? "TCP" : "TLS", _netvc); + PreWarmSMVDbg("%s Handshake is done netvc=%p", (_dst->type == SNIRoutingType::FORWARD) ? "TCP" : "TLS", _netvc); SET_HANDLER(&PreWarmSM::state_open); _timeout.cancel_active_timeout(); @@ -433,12 +441,12 @@ PreWarmSM::state_open(int event, void *data) ink_release_assert(netvc == _netvc); - if (is_debug_tag_set("prewarm_sm")) { + if (dbg_ctl_prewarm_sm.on()) { if (_read_buf_reader->is_read_avail_more_than(0)) { uint64_t read_len = _read_buf_reader->read_avail(); - PreWarmSMDebug("buffering data from origin server len=%" PRIu64, read_len); + PreWarmSMDbg("buffering data from origin server len=%" PRIu64, read_len); - if (is_debug_tag_set("v_prewarm_sm")) { + if (dbg_ctl_v_prewarm_sm.on()) { uint8_t buf[1024]; read_len = std::min(static_cast<uint64_t>(sizeof(buf)), read_len); _read_buf_reader->memcpy(buf, read_len); @@ -446,7 +454,7 @@ PreWarmSM::state_open(int event, void *data) swoc::LocalBufferWriter<2048> bw; bw.print("{:x}", swoc::MemSpan<void const>(buf, read_len)); - PreWarmSMVDebug("\n%.*s\n", int(bw.extent()), bw.data()); + PreWarmSMVDbg("\n%.*s\n", int(bw.extent()), bw.data()); } } } @@ -457,7 +465,7 @@ PreWarmSM::state_open(int event, void *data) // possibly inactive timeout at origin server [[fallthrough]]; case VC_EVENT_INACTIVITY_TIMEOUT: { - PreWarmSMDebug("%s (%d)", get_vc_event_name(event), event); + PreWarmSMDbg("%s (%d)", get_vc_event_name(event), event); stop(); break; } @@ -704,9 +712,9 @@ PreWarmQueue::state_running(int event, void *data) _prewarm_on_event_interval(dst, info); // set prewarmManager.stats - Debug("v_prewarm_q", "dst=%.*s:%d type=%d alpn=%d miss=%d hit=%d init=%d open=%d", (int)dst->host.size(), dst->host.data(), - dst->port, (int)dst->type, dst->alpn_index, info.stat.miss, info.stat.hit, (int)info.init_list->size(), - (int)info.open_list->size()); + Dbg(dbg_ctl_v_prewarm_q, "dst=%.*s:%d type=%d alpn=%d miss=%d hit=%d init=%d open=%d", (int)dst->host.size(), + dst->host.data(), dst->port, (int)dst->type, dst->alpn_index, info.stat.miss, info.stat.hit, (int)info.init_list->size(), + (int)info.open_list->size()); auto &[counters, gauges] = *info.stats_ids; @@ -857,7 +865,7 @@ PreWarmQueue::_prewarm_on_event_interval(const PreWarm::SPtrConstDst &dst, const break; } - Debug("v_prewarm_q", "prewarm_size=%" PRId32, n); + Dbg(dbg_ctl_v_prewarm_q, "prewarm_size=%" PRId32, n); for (uint32_t i = 0; i < n; ++i) { _new_prewarm_sm(dst, info.conf, info.stats_ids); @@ -993,7 +1001,7 @@ PreWarmManager::reconfigure_prewarming_on_threads() EventProcessor::ThreadGroupDescriptor *tg = &(eventProcessor.thread_group[0]); ink_release_assert(memcmp(tg->_name.data(), "ET_NET", 6) == 0); - Debug("prewarm", "reconfigure prewarming"); + Dbg(dbg_ctl_prewarm, "reconfigure prewarming"); for (int i = 0; i < tg->_count; ++i) { EThread *ethread = tg->_thread[i]; @@ -1091,9 +1099,9 @@ PreWarmManager::_parse_sni_conf(PreWarm::ParsedSNIConf &parsed_conf, const SNICo } for (int id : alpn_ids) { - Debug("prewarm_m", "sni=%s dst=%s type=%d alpn=%d min=%d max=%d c_timeout=%d i_timeout=%d srv=%d", item.fqdn.c_str(), - item.tunnel_destination.c_str(), (int)item.tunnel_type, id, (int)item.tunnel_prewarm_min, (int)item.tunnel_prewarm_max, - (int)item.tunnel_prewarm_connect_timeout, (int)item.tunnel_prewarm_inactive_timeout, item.tunnel_prewarm_srv); + Dbg(dbg_ctl_prewarm_m, "sni=%s dst=%s type=%d alpn=%d min=%d max=%d c_timeout=%d i_timeout=%d srv=%d", item.fqdn.c_str(), + item.tunnel_destination.c_str(), (int)item.tunnel_type, id, (int)item.tunnel_prewarm_min, (int)item.tunnel_prewarm_max, + (int)item.tunnel_prewarm_connect_timeout, (int)item.tunnel_prewarm_inactive_timeout, item.tunnel_prewarm_srv); std::string dst_fqdn; int32_t port; @@ -1171,7 +1179,7 @@ PreWarmManager::_register_stats(const PreWarm::ParsedSNIConf &parsed_conf) } else { ++stats_counter; counters[j] = metric; - Debug("v_prewarm_init", "conter stat id=%d name=%s", Metrics::Counter::lookup(name), name); + Dbg(dbg_ctl_v_prewarm_init, "conter stat id=%d name=%s", Metrics::Counter::lookup(name), name); } } @@ -1188,7 +1196,7 @@ PreWarmManager::_register_stats(const PreWarm::ParsedSNIConf &parsed_conf) } else { ++stats_counter; gauges[j] = metric; - Debug("v_prewarm_init", "gauge stat id=%d name=%s", Metrics::Gauge::lookup(name), name); + Dbg(dbg_ctl_v_prewarm_init, "gauge stat id=%d name=%s", Metrics::Gauge::lookup(name), name); } } diff --git a/src/proxy/http/remap/PluginDso.cc b/src/proxy/http/remap/PluginDso.cc index 1139ddcb65..9da092a790 100644 --- a/src/proxy/http/remap/PluginDso.cc +++ b/src/proxy/http/remap/PluginDso.cc @@ -34,7 +34,7 @@ #include "unit-tests/plugin_testing_common.h" #else #include "tscore/Diags.h" -#define PluginDebug Debug +#define PluginDbg Dbg #define PluginError Error #endif @@ -58,8 +58,8 @@ concat_error(std::string &error, const std::string &msg) PluginDso::PluginDso(const fs::path &configPath, const fs::path &effectivePath, const fs::path &runtimePath) : _configPath(configPath), _effectivePath(effectivePath), _runtimePath(runtimePath) { - PluginDebug(_tag, "PluginDso (%p) created _configPath: [%s] _effectivePath: [%s] _runtimePath: [%s]", this, _configPath.c_str(), - _effectivePath.c_str(), _runtimePath.c_str()); + PluginDbg(_dbg_ctl(), "PluginDso (%p) created _configPath: [%s] _effectivePath: [%s] _runtimePath: [%s]", this, + _configPath.c_str(), _effectivePath.c_str(), _runtimePath.c_str()); } PluginDso::~PluginDso() @@ -80,14 +80,14 @@ PluginDso::load(std::string &error) return false; } - PluginDebug(_tag, "plugin '%s' started loading DSO", _configPath.c_str()); + PluginDbg(_dbg_ctl(), "plugin '%s' started loading DSO", _configPath.c_str()); /* Find plugin DSO looking through the search dirs */ if (_effectivePath.empty()) { concat_error(error, "empty effective path"); result = false; } else { - PluginDebug(_tag, "plugin '%s' effective path: %s", _configPath.c_str(), _effectivePath.c_str()); + PluginDbg(_dbg_ctl(), "plugin '%s' effective path: %s", _configPath.c_str(), _effectivePath.c_str()); /* Copy the installed plugin DSO to a runtime directory if dynamic reload enabled */ std::error_code ec; @@ -96,12 +96,12 @@ PluginDso::load(std::string &error) concat_error(error, ec.message()); result = false; } else { - PluginDebug(_tag, "plugin '%s' runtime path: %s", _configPath.c_str(), _runtimePath.c_str()); + PluginDbg(_dbg_ctl(), "plugin '%s' runtime path: %s", _configPath.c_str(), _runtimePath.c_str()); /* Save the time for later checking if DSO got modified in consecutive DSO reloads */ std::error_code ec; _mtime = fs::last_write_time(_effectivePath, ec); - PluginDebug(_tag, "plugin '%s' modification time %ld", _configPath.c_str(), ts_clock::to_time_t(_mtime)); + PluginDbg(_dbg_ctl(), "plugin '%s' modification time %ld", _configPath.c_str(), ts_clock::to_time_t(_mtime)); /* Now attempt to load the plugin DSO */ #if defined(darwin) @@ -125,7 +125,7 @@ PluginDso::load(std::string &error) clean(error); } } - PluginDebug(_tag, "plugin '%s' finished loading DSO", _configPath.c_str()); + PluginDbg(_dbg_ctl(), "plugin '%s' finished loading DSO", _configPath.c_str()); return result; } @@ -267,15 +267,15 @@ void PluginDso::acquire() { this->refcount_inc(); - PluginDebug(_tag, "plugin DSO acquire (ref-count:%d, dso-addr:%p)", this->refcount(), this); + PluginDbg(_dbg_ctl(), "plugin DSO acquire (ref-count:%d, dso-addr:%p)", this->refcount(), this); } void PluginDso::release() { - PluginDebug(_tag, "plugin DSO release (ref-count:%d, dso-addr:%p)", this->refcount() - 1, this); + PluginDbg(_dbg_ctl(), "plugin DSO release (ref-count:%d, dso-addr:%p)", this->refcount() - 1, this); if (0 == this->refcount_dec()) { - PluginDebug(_tag, "unloading plugin DSO '%s' (dso-addr:%p)", _configPath.c_str(), this); + PluginDbg(_dbg_ctl(), "unloading plugin DSO '%s' (dso-addr:%p)", _configPath.c_str(), this); _plugins->remove(this); } } @@ -284,14 +284,14 @@ void PluginDso::incInstanceCount() { _instanceCount.refcount_inc(); - PluginDebug(_tag, "instance count (inst-count:%d, dso-addr:%p)", _instanceCount.refcount(), this); + PluginDbg(_dbg_ctl(), "instance count (inst-count:%d, dso-addr:%p)", _instanceCount.refcount(), this); } void PluginDso::decInstanceCount() { _instanceCount.refcount_dec(); - PluginDebug(_tag, "instance count (inst-count:%d, dso-addr:%p)", _instanceCount.refcount(), this); + PluginDbg(_dbg_ctl(), "instance count (inst-count:%d, dso-addr:%p)", _instanceCount.refcount(), this); } int @@ -352,8 +352,8 @@ PluginDso::LoadedPlugins::indicatePreReload(const char *factoryId) { SCOPED_MUTEX_LOCK(lock, _mutex, this_ethread()); - PluginDebug(_tag, "indicated config is going to be reloaded by factory '%s' to %zu plugin%s", factoryId, _list.count(), - _list.count() != 1 ? "s" : ""); + PluginDbg(_dbg_ctl(), "indicated config is going to be reloaded by factory '%s' to %zu plugin%s", factoryId, _list.count(), + _list.count() != 1 ? "s" : ""); _list.apply([](PluginDso &plugin) -> void { plugin.indicatePreReload(); }); } @@ -364,8 +364,8 @@ PluginDso::LoadedPlugins::indicatePostReload(bool reloadSuccessful, const std::u { SCOPED_MUTEX_LOCK(lock, _mutex, this_ethread()); - PluginDebug(_tag, "indicated config is done reloading by factory '%s' to %zu plugin%s", factoryId, _list.count(), - _list.count() != 1 ? "s" : ""); + PluginDbg(_dbg_ctl(), "indicated config is done reloading by factory '%s' to %zu plugin%s", factoryId, _list.count(), + _list.count() != 1 ? "s" : ""); for (auto &plugin : _list) { TSRemapReloadStatus status = TSREMAP_CONFIG_RELOAD_FAILURE; diff --git a/src/proxy/http/remap/PluginFactory.cc b/src/proxy/http/remap/PluginFactory.cc index aa259bd39e..399da3c042 100644 --- a/src/proxy/http/remap/PluginFactory.cc +++ b/src/proxy/http/remap/PluginFactory.cc @@ -30,7 +30,7 @@ #include "unit-tests/plugin_testing_common.h" #else #include "tscore/Diags.h" -#define PluginDebug Debug +#define PluginDbg Dbg #define PluginError Error #endif #include "../../../iocore/eventsystem/P_EventSystem.h" @@ -94,7 +94,7 @@ PluginFactory::PluginFactory() } } - PluginDebug(_tag, "created plugin factory %s", getUuid()); + PluginDbg(_dbg_ctl(), "created plugin factory %s", getUuid()); } PluginFactory::~PluginFactory() @@ -104,7 +104,7 @@ PluginFactory::~PluginFactory() fs::remove_all(_runtimeDir, _ec); - PluginDebug(_tag, "destroyed plugin factory %s", getUuid()); + PluginDbg(_dbg_ctl(), "destroyed plugin factory %s", getUuid()); delete _uuid; } @@ -112,7 +112,7 @@ PluginFactory & PluginFactory::addSearchDir(const fs::path &searchDir) { _searchDirs.push_back(searchDir); - PluginDebug(_tag, "added plugin search dir %s", searchDir.c_str()); + PluginDbg(_dbg_ctl(), "added plugin search dir %s", searchDir.c_str()); return *this; } @@ -120,7 +120,7 @@ PluginFactory & PluginFactory::setRuntimeDir(const fs::path &runtimeDir) { _runtimeDir = runtimeDir / fs::path(getUuid()); - PluginDebug(_tag, "set plugin runtime dir %s", runtimeDir.c_str()); + PluginDbg(_dbg_ctl(), "set plugin runtime dir %s", runtimeDir.c_str()); return *this; } @@ -148,14 +148,14 @@ PluginFactory::getRemapPlugin(const fs::path &configPath, int argc, char **argv, if (effectivePath.empty()) { error.assign("failed to find plugin '").append(configPath.string()).append("'"); // The error will be reported by the caller but add debug log entry with this tag for convenience. - PluginDebug(_tag, "%s", error.c_str()); + PluginDbg(_dbg_ctl(), "%s", error.c_str()); return nullptr; } // The plugin may have opt out by `TSPluginDSOReloadEnable`, let's check and overwrite if (dynamicReloadEnabled && PluginDso::loadedPlugins()->isPluginInDsoOptOutTable(effectivePath)) { // plugin not interested to be reload. - PluginDebug(_tag, "Plugin %s not interested in taking part of the reload.", effectivePath.c_str()); + PluginDbg(_dbg_ctl(), "Plugin %s not interested in taking part of the reload.", effectivePath.c_str()); dynamicReloadEnabled = false; } @@ -165,7 +165,7 @@ PluginFactory::getRemapPlugin(const fs::path &configPath, int argc, char **argv, if (nullptr == plugin) { /* The plugin requested have not been loaded yet. */ - PluginDebug(_tag, "plugin '%s' has not been loaded yet, loading as remap plugin", configPath.c_str()); + PluginDbg(_dbg_ctl(), "plugin '%s' has not been loaded yet, loading as remap plugin", configPath.c_str()); fs::path runtimePath; @@ -176,15 +176,15 @@ PluginFactory::getRemapPlugin(const fs::path &configPath, int argc, char **argv, runtimePath /= effectivePath.relative_path(); fs::path parent = runtimePath.parent_path(); - PluginDebug(_tag, "Using effectivePath: [%s] runtimePath: [%s] parent: [%s]", effectivePath.c_str(), runtimePath.c_str(), - parent.c_str()); + PluginDbg(_dbg_ctl(), "Using effectivePath: [%s] runtimePath: [%s] parent: [%s]", effectivePath.c_str(), runtimePath.c_str(), + parent.c_str()); if (!fs::create_directories(parent, _ec)) { error.assign("failed to create plugin runtime dir"); return nullptr; } } else { runtimePath = effectivePath; - PluginDebug(_tag, "Using effectivePath: [%s] runtimePath: [%s]", effectivePath.c_str(), runtimePath.c_str()); + PluginDbg(_dbg_ctl(), "Using effectivePath: [%s] runtimePath: [%s]", effectivePath.c_str(), runtimePath.c_str()); } plugin = new RemapPluginInfo(configPath, effectivePath, runtimePath); @@ -199,7 +199,7 @@ PluginFactory::getRemapPlugin(const fs::path &configPath, int argc, char **argv, } } else { /* Plugin DSO load succeeded but instance init failed. */ - PluginDebug(_tag, "plugin '%s' instance init failed", configPath.c_str()); + PluginDbg(_dbg_ctl(), "plugin '%s' instance init failed", configPath.c_str()); plugin->unload(error); delete plugin; } @@ -209,12 +209,12 @@ PluginFactory::getRemapPlugin(const fs::path &configPath, int argc, char **argv, } } else { /* Plugin DSO load failed. */ - PluginDebug(_tag, "plugin '%s' DSO load failed", configPath.c_str()); + PluginDbg(_dbg_ctl(), "plugin '%s' DSO load failed", configPath.c_str()); delete plugin; } } } else { - PluginDebug(_tag, "plugin '%s' has already been loaded", configPath.c_str()); + PluginDbg(_dbg_ctl(), "plugin '%s' has already been loaded", configPath.c_str()); inst = RemapPluginInst::init(plugin, argc, argv, error); if (nullptr != inst) { _instList.append(inst); @@ -276,7 +276,7 @@ PluginFactory::findByEffectivePath(const fs::path &path, bool dynamicReloadEnabl void PluginFactory::deactivate() { - PluginDebug(_tag, "deactivate configuration used by factory '%s'", getUuid()); + PluginDbg(_dbg_ctl(), "deactivate configuration used by factory '%s'", getUuid()); _instList.apply([](RemapPluginInst &pluginInst) -> void { pluginInst.done(); }); } diff --git a/src/proxy/http/remap/RemapConfig.cc b/src/proxy/http/remap/RemapConfig.cc index 2bbc630060..29bca49fa6 100644 --- a/src/proxy/http/remap/RemapConfig.cc +++ b/src/proxy/http/remap/RemapConfig.cc @@ -39,10 +39,18 @@ #define modulePrefix "[ReverseProxy]" -static bool remap_parse_config_bti(const char *path, BUILD_TABLE_INFO *bti); - load_remap_file_func load_remap_file_cb = nullptr; +namespace +{ +DbgCtl dbg_ctl_url_rewrite{"url_rewrite"}; +DbgCtl dbg_ctl_remap_plugin{"remap_plugin"}; +DbgCtl dbg_ctl_url_rewrite_regex{"url_rewrite_regex"}; + +bool remap_parse_config_bti(const char *path, BUILD_TABLE_INFO *bti); + +} // end anonymous namespace + /** Returns the length of the URL. @@ -109,7 +117,7 @@ process_filter_opt(url_mapping *mp, const BUILD_TABLE_INFO *bti, char *errStrBuf const char *errStr = nullptr; if (unlikely(!mp || !bti || !errStrBuf || errStrBufSize <= 0)) { - Debug("url_rewrite", "[process_filter_opt] Invalid argument(s)"); + Dbg(dbg_ctl_url_rewrite, "[process_filter_opt] Invalid argument(s)"); return (const char *)"[process_filter_opt] Invalid argument(s)"; } // ACLs are processed in this order: @@ -117,7 +125,7 @@ process_filter_opt(url_mapping *mp, const BUILD_TABLE_INFO *bti, char *errStrBuf // 2. All named ACLs in remap.config. // 3. Rules as specified in ip_allow.yaml. if (!errStr && (bti->remap_optflg & REMAP_OPTFLG_ALL_FILTERS) != 0) { - Debug("url_rewrite", "[process_filter_opt] Add per remap filter"); + Dbg(dbg_ctl_url_rewrite, "[process_filter_opt] Add per remap filter"); for (rpp = &mp->filter; *rpp; rpp = &((*rpp)->next)) { ; } @@ -127,8 +135,8 @@ process_filter_opt(url_mapping *mp, const BUILD_TABLE_INFO *bti, char *errStrBuf ; } if (rp->active_queue_flag) { - Debug("url_rewrite", "[process_filter_opt] Add active main filter \"%s\" (argc=%d)", - rp->filter_name ? rp->filter_name : "<nullptr>", rp->argc); + Dbg(dbg_ctl_url_rewrite, "[process_filter_opt] Add active main filter \"%s\" (argc=%d)", + rp->filter_name ? rp->filter_name : "<nullptr>", rp->argc); for (rpp = &mp->filter; *rpp; rpp = &((*rpp)->next)) { ; } @@ -178,12 +186,12 @@ parse_define_directive(const char *directive, BUILD_TABLE_INFO *bti, char *errbu if (bti->paramc < 2) { snprintf(errbuf, errbufsize, "Directive \"%s\" must have name argument", directive); - Debug("url_rewrite", "[parse_directive] %s", errbuf); + Dbg(dbg_ctl_url_rewrite, "[parse_directive] %s", errbuf); return (const char *)errbuf; } if (bti->argc < 1) { snprintf(errbuf, errbufsize, "Directive \"%s\" must have filter parameter(s)", directive); - Debug("url_rewrite", "[parse_directive] %s", errbuf); + Dbg(dbg_ctl_url_rewrite, "[parse_directive] %s", errbuf); return (const char *)errbuf; } @@ -192,13 +200,13 @@ parse_define_directive(const char *directive, BUILD_TABLE_INFO *bti, char *errbu if ((cstr = remap_validate_filter_args(&rp, (const char **)bti->argv, bti->argc, errbuf, errbufsize)) == nullptr && rp) { if (flg) { // new filter - add to list acl_filter_rule **rpp = nullptr; - Debug("url_rewrite", "[parse_directive] new rule \"%s\" was created", bti->paramv[1]); + Dbg(dbg_ctl_url_rewrite, "[parse_directive] new rule \"%s\" was created", bti->paramv[1]); for (rpp = &bti->rules_list; *rpp; rpp = &((*rpp)->next)) { ; } (*rpp = rp)->name(bti->paramv[1]); } - Debug("url_rewrite", "[parse_directive] %d argument(s) were added to rule \"%s\"", bti->argc, bti->paramv[1]); + Dbg(dbg_ctl_url_rewrite, "[parse_directive] %d argument(s) were added to rule \"%s\"", bti->argc, bti->paramv[1]); rp->add_argv(bti->argc, bti->argv); // store string arguments for future processing } @@ -210,7 +218,7 @@ parse_delete_directive(const char *directive, BUILD_TABLE_INFO *bti, char *errbu { if (bti->paramc < 2) { snprintf(errbuf, errbufsize, "Directive \"%s\" must have name argument", directive); - Debug("url_rewrite", "[parse_directive] %s", errbuf); + Dbg(dbg_ctl_url_rewrite, "[parse_directive] %s", errbuf); return (const char *)errbuf; } @@ -225,7 +233,7 @@ parse_activate_directive(const char *directive, BUILD_TABLE_INFO *bti, char *err if (bti->paramc < 2) { snprintf(errbuf, errbufsize, "Directive \"%s\" must have name argument", directive); - Debug("url_rewrite", "[parse_directive] %s", errbuf); + Dbg(dbg_ctl_url_rewrite, "[parse_directive] %s", errbuf); return (const char *)errbuf; } @@ -237,7 +245,7 @@ parse_activate_directive(const char *directive, BUILD_TABLE_INFO *bti, char *err if ((rp = acl_filter_rule::find_byname(bti->rules_list, (const char *)bti->paramv[1])) == nullptr) { snprintf(errbuf, errbufsize, R"(Undefined filter "%s" in directive "%s")", bti->paramv[1], directive); - Debug("url_rewrite", "[parse_directive] %s", errbuf); + Dbg(dbg_ctl_url_rewrite, "[parse_directive] %s", errbuf); return (const char *)errbuf; } @@ -252,7 +260,7 @@ parse_deactivate_directive(const char *directive, BUILD_TABLE_INFO *bti, char *e if (bti->paramc < 2) { snprintf(errbuf, errbufsize, "Directive \"%s\" must have name argument", directive); - Debug("url_rewrite", "[parse_directive] %s", errbuf); + Dbg(dbg_ctl_url_rewrite, "[parse_directive] %s", errbuf); return (const char *)errbuf; } @@ -264,7 +272,7 @@ parse_deactivate_directive(const char *directive, BUILD_TABLE_INFO *bti, char *e if ((rp = acl_filter_rule::find_byname(bti->rules_list, (const char *)bti->paramv[1])) == nullptr) { snprintf(errbuf, errbufsize, R"(Undefined filter "%s" in directive "%s")", bti->paramv[1], directive); - Debug("url_rewrite", "[parse_directive] %s", errbuf); + Dbg(dbg_ctl_url_rewrite, "[parse_directive] %s", errbuf); return (const char *)errbuf; } @@ -299,7 +307,7 @@ parse_remap_fragment(const char *path, BUILD_TABLE_INFO *bti, char *errbuf, size nbti.rules_list = bti->rules_list; nbti.rewrite = bti->rewrite; - Debug("url_rewrite", "[%s] including remap configuration from %s", __func__, (const char *)path); + Dbg(dbg_ctl_url_rewrite, "[%s] including remap configuration from %s", __func__, (const char *)path); success = remap_parse_config_bti(path, &nbti); // The sub-parse might have updated the rules list, so push it up to the parent parse. @@ -322,7 +330,7 @@ parse_include_directive(const char *directive, BUILD_TABLE_INFO *bti, char *errb { if (bti->paramc < 2) { snprintf(errbuf, errbufsize, "Directive \"%s\" must have a path argument", directive); - Debug("url_rewrite", "[%s] %s", __func__, errbuf); + Dbg(dbg_ctl_url_rewrite, "[%s] %s", __func__, errbuf); return (const char *)errbuf; } @@ -412,7 +420,7 @@ remap_parse_directive(BUILD_TABLE_INFO *bti, char *errbuf, size_t errbufsize) // Check arguments if (unlikely(!bti || !errbuf || errbufsize == 0 || !bti->paramc || (directive = bti->paramv[0]) == nullptr)) { - Debug("url_rewrite", "[parse_directive] Invalid argument(s)"); + Dbg(dbg_ctl_url_rewrite, "[parse_directive] Invalid argument(s)"); return "Invalid argument(s)"; } @@ -423,7 +431,7 @@ remap_parse_directive(BUILD_TABLE_INFO *bti, char *errbuf, size_t errbufsize) } snprintf(errbuf, errbufsize, "Unknown directive \"%s\"", directive); - Debug("url_rewrite", "[parse_directive] %s", errbuf); + Dbg(dbg_ctl_url_rewrite, "[parse_directive] %s", errbuf); return (const char *)errbuf; } @@ -435,11 +443,11 @@ remap_validate_filter_args(acl_filter_rule **rule_pp, const char **argv, int arg bool new_rule_flg = false; if (!rule_pp) { - Debug("url_rewrite", "[validate_filter_args] Invalid argument(s)"); + Dbg(dbg_ctl_url_rewrite, "[validate_filter_args] Invalid argument(s)"); return (const char *)"Invalid argument(s)"; } - if (is_debug_tag_set("url_rewrite")) { + if (dbg_ctl_url_rewrite.on()) { printf("validate_filter_args: "); for (i = 0; i < argc; i++) { printf("\"%s\" ", argv[i]); @@ -450,11 +458,11 @@ remap_validate_filter_args(acl_filter_rule **rule_pp, const char **argv, int arg if ((rule = *rule_pp) == nullptr) { rule = new acl_filter_rule(); if (unlikely((*rule_pp = rule) == nullptr)) { - Debug("url_rewrite", "[validate_filter_args] Memory allocation error"); + Dbg(dbg_ctl_url_rewrite, "[validate_filter_args] Memory allocation error"); return (const char *)"Memory allocation Error"; } new_rule_flg = true; - Debug("url_rewrite", "[validate_filter_args] new acl_filter_rule class was created during remap rule processing"); + Dbg(dbg_ctl_url_rewrite, "[validate_filter_args] new acl_filter_rule class was created during remap rule processing"); } bool ip_is_listed = false; @@ -464,7 +472,7 @@ remap_validate_filter_args(acl_filter_rule **rule_pp, const char **argv, int arg const char *argptr; if ((ul = remap_check_option(&argv[i], 1, 0, nullptr, &argptr)) == 0) { - Debug("url_rewrite", "[validate_filter_args] Unknown remap option - %s", argv[i]); + Dbg(dbg_ctl_url_rewrite, "[validate_filter_args] Unknown remap option - %s", argv[i]); snprintf(errStrBuf, errStrBufSize, "Unknown option - \"%s\"", argv[i]); errStrBuf[errStrBufSize - 1] = 0; if (new_rule_flg) { @@ -478,7 +486,7 @@ remap_validate_filter_args(acl_filter_rule **rule_pp, const char **argv, int arg hasarg = !(ul & REMAP_OPTFLG_INTERNAL); if (hasarg && (!argptr || !argptr[0])) { - Debug("url_rewrite", "[validate_filter_args] Empty argument in %s", argv[i]); + Dbg(dbg_ctl_url_rewrite, "[validate_filter_args] Empty argument in %s", argv[i]); snprintf(errStrBuf, errStrBufSize, "Empty argument in \"%s\"", argv[i]); errStrBuf[errStrBufSize - 1] = 0; if (new_rule_flg) { @@ -496,7 +504,7 @@ remap_validate_filter_args(acl_filter_rule **rule_pp, const char **argv, int arg if (m >= 0 && m < HTTP_WKSIDX_METHODS_CNT) { rule->standard_method_lookup[m] = true; } else { - Debug("url_rewrite", "[validate_filter_args] Using nonstandard method [%s]", argptr); + Dbg(dbg_ctl_url_rewrite, "[validate_filter_args] Using nonstandard method [%s]", argptr); rule->nonstandard_methods.insert(argptr); } rule->method_restriction_enabled = true; @@ -504,7 +512,7 @@ remap_validate_filter_args(acl_filter_rule **rule_pp, const char **argv, int arg if (ul & REMAP_OPTFLG_SRC_IP) { /* "src_ip=" option */ if (rule->src_ip_cnt >= ACL_FILTER_MAX_SRC_IP) { - Debug("url_rewrite", "[validate_filter_args] Too many \"src_ip=\" filters"); + Dbg(dbg_ctl_url_rewrite, "[validate_filter_args] Too many \"src_ip=\" filters"); snprintf(errStrBuf, errStrBufSize, "Defined more than %d \"src_ip=\" filters!", ACL_FILTER_MAX_SRC_IP); errStrBuf[errStrBufSize - 1] = 0; if (new_rule_flg) { @@ -521,7 +529,7 @@ remap_validate_filter_args(acl_filter_rule **rule_pp, const char **argv, int arg if (arg == "all") { ipi->match_all_addresses = true; } else if (ats_ip_range_parse(arg, ipi->start, ipi->end) != 0) { - Debug("url_rewrite", "[validate_filter_args] Unable to parse IP value in %s", argv[i]); + Dbg(dbg_ctl_url_rewrite, "[validate_filter_args] Unable to parse IP value in %s", argv[i]); snprintf(errStrBuf, errStrBufSize, "Unable to parse IP value in %s", argv[i]); errStrBuf[errStrBufSize - 1] = 0; if (new_rule_flg) { @@ -546,7 +554,7 @@ remap_validate_filter_args(acl_filter_rule **rule_pp, const char **argv, int arg if (ul & REMAP_OPTFLG_SRC_IP_CATEGORY) { /* "src_ip_category=" option */ if (rule->src_ip_category_cnt >= ACL_FILTER_MAX_SRC_IP) { - Debug("url_rewrite", "[validate_filter_args] Too many \"src_ip_category=\" filters"); + Dbg(dbg_ctl_url_rewrite, "[validate_filter_args] Too many \"src_ip_category=\" filters"); snprintf(errStrBuf, errStrBufSize, "Defined more than %d \"src_ip_category=\" filters!", ACL_FILTER_MAX_SRC_IP); errStrBuf[errStrBufSize - 1] = 0; if (new_rule_flg) { @@ -576,7 +584,7 @@ remap_validate_filter_args(acl_filter_rule **rule_pp, const char **argv, int arg if (ul & REMAP_OPTFLG_IN_IP) { /* "in_ip=" option */ if (rule->in_ip_cnt >= ACL_FILTER_MAX_IN_IP) { - Debug("url_rewrite", "[validate_filter_args] Too many \"in_ip=\" filters"); + Dbg(dbg_ctl_url_rewrite, "[validate_filter_args] Too many \"in_ip=\" filters"); snprintf(errStrBuf, errStrBufSize, "Defined more than %d \"in_ip=\" filters!", ACL_FILTER_MAX_IN_IP); errStrBuf[errStrBufSize - 1] = 0; if (new_rule_flg) { @@ -594,7 +602,7 @@ remap_validate_filter_args(acl_filter_rule **rule_pp, const char **argv, int arg if (arg == "all") { ipi->match_all_addresses = true; } else if (ats_ip_range_parse(arg, ipi->start, ipi->end) != 0) { - Debug("url_rewrite", "[validate_filter_args] Unable to parse IP value in %s", argv[i]); + Dbg(dbg_ctl_url_rewrite, "[validate_filter_args] Unable to parse IP value in %s", argv[i]); snprintf(errStrBuf, errStrBufSize, "Unable to parse IP value in %s", argv[i]); errStrBuf[errStrBufSize - 1] = 0; if (new_rule_flg) { @@ -623,7 +631,7 @@ remap_validate_filter_args(acl_filter_rule **rule_pp, const char **argv, int arg } else if (is_inkeylist(argptr, "1", "on", "allow", "enable", nullptr)) { rule->allow_flag = 1; } else { - Debug("url_rewrite", "[validate_filter_args] Unknown argument \"%s\"", argv[i]); + Dbg(dbg_ctl_url_rewrite, "[validate_filter_args] Unknown argument \"%s\"", argv[i]); snprintf(errStrBuf, errStrBufSize, "Unknown argument \"%s\"", argv[i]); errStrBuf[errStrBufSize - 1] = 0; if (new_rule_flg) { @@ -648,7 +656,7 @@ remap_validate_filter_args(acl_filter_rule **rule_pp, const char **argv, int arg rule->src_ip_valid = 1; } - if (is_debug_tag_set("url_rewrite")) { + if (dbg_ctl_url_rewrite.on()) { rule->print(); } @@ -839,7 +847,7 @@ remap_load_plugin(const char **argv, int argc, url_mapping *mp, char *errbuf, in return false; /* incorrect input data */ } - Debug("remap_plugin", "using path %s for plugin", c); + Dbg(dbg_ctl_remap_plugin, "using path %s for plugin", c); /* Prepare remap plugin parameters from the config */ if ((err = mp->fromURL.string_get(nullptr)) == nullptr) { @@ -873,14 +881,14 @@ remap_load_plugin(const char **argv, int argc, url_mapping *mp, char *errbuf, in } } - Debug("url_rewrite", "Viewing all parameters for config line"); + Dbg(dbg_ctl_url_rewrite, "Viewing all parameters for config line"); for (int k = 0; k < argc; k++) { - Debug("url_rewrite", "Argument %d: %s", k, argv[k]); + Dbg(dbg_ctl_url_rewrite, "Argument %d: %s", k, argv[k]); } - Debug("url_rewrite", "Viewing parsed plugin parameters for %s: [%d]", c, *plugin_found_at); + Dbg(dbg_ctl_url_rewrite, "Viewing parsed plugin parameters for %s: [%d]", c, *plugin_found_at); for (int k = 0; k < parc; k++) { - Debug("url_rewrite", "Argument %d: %s", k, pargv[k]); + Dbg(dbg_ctl_url_rewrite, "Argument %d: %s", k, pargv[k]); } RemapPluginInst *pi = nullptr; @@ -977,7 +985,9 @@ lFail: return false; } -static bool +namespace +{ +bool remap_parse_config_bti(const char *path, BUILD_TABLE_INFO *bti) { char errBuf[1024]; @@ -1022,7 +1032,7 @@ remap_parse_config_bti(const char *path, BUILD_TABLE_INFO *bti) return false; } - Debug("url_rewrite", "[BuildTable] UrlRewrite::BuildTable()"); + Dbg(dbg_ctl_url_rewrite, "[BuildTable] UrlRewrite::BuildTable()"); for (cur_line = tokLine(content.data(), &tok_state, '\\'); cur_line != nullptr;) { reg_map = nullptr; @@ -1054,7 +1064,7 @@ remap_parse_config_bti(const char *path, BUILD_TABLE_INFO *bti) continue; } - Debug("url_rewrite", "[BuildTable] Parsing: \"%s\"", cur_line); + Dbg(dbg_ctl_url_rewrite, "[BuildTable] Parsing: \"%s\"", cur_line); tok_count = whiteTok.Initialize(cur_line, (SHARE_TOKS | ALLOW_SPACES)); @@ -1095,23 +1105,23 @@ remap_parse_config_bti(const char *path, BUILD_TABLE_INFO *bti) // Check to see whether is a reverse or forward mapping if (!strcasecmp("reverse_map", type_id_str)) { - Debug("url_rewrite", "[BuildTable] - REVERSE_MAP"); + Dbg(dbg_ctl_url_rewrite, "[BuildTable] - REVERSE_MAP"); maptype = REVERSE_MAP; } else if (!strcasecmp("map", type_id_str)) { - Debug("url_rewrite", "[BuildTable] - %s", - ((bti->remap_optflg & REMAP_OPTFLG_MAP_WITH_REFERER) == 0) ? "FORWARD_MAP" : "FORWARD_MAP_REFERER"); + Dbg(dbg_ctl_url_rewrite, "[BuildTable] - %s", + ((bti->remap_optflg & REMAP_OPTFLG_MAP_WITH_REFERER) == 0) ? "FORWARD_MAP" : "FORWARD_MAP_REFERER"); maptype = ((bti->remap_optflg & REMAP_OPTFLG_MAP_WITH_REFERER) == 0) ? FORWARD_MAP : FORWARD_MAP_REFERER; } else if (!strcasecmp("redirect", type_id_str)) { - Debug("url_rewrite", "[BuildTable] - PERMANENT_REDIRECT"); + Dbg(dbg_ctl_url_rewrite, "[BuildTable] - PERMANENT_REDIRECT"); maptype = PERMANENT_REDIRECT; } else if (!strcasecmp("redirect_temporary", type_id_str)) { - Debug("url_rewrite", "[BuildTable] - TEMPORARY_REDIRECT"); + Dbg(dbg_ctl_url_rewrite, "[BuildTable] - TEMPORARY_REDIRECT"); maptype = TEMPORARY_REDIRECT; } else if (!strcasecmp("map_with_referer", type_id_str)) { - Debug("url_rewrite", "[BuildTable] - FORWARD_MAP_REFERER"); + Dbg(dbg_ctl_url_rewrite, "[BuildTable] - FORWARD_MAP_REFERER"); maptype = FORWARD_MAP_REFERER; } else if (!strcasecmp("map_with_recv_port", type_id_str)) { - Debug("url_rewrite", "[BuildTable] - FORWARD_MAP_WITH_RECV_PORT"); + Dbg(dbg_ctl_url_rewrite, "[BuildTable] - FORWARD_MAP_WITH_RECV_PORT"); maptype = FORWARD_MAP_WITH_RECV_PORT; } else { snprintf(errStrBuf, sizeof(errStrBuf), "unknown mapping type at line %d", cln + 1); @@ -1299,7 +1309,7 @@ remap_parse_config_bti(const char *path, BUILD_TABLE_INFO *bti) errStr = "could not process regex mapping config line"; goto MAP_ERROR; } - Debug("url_rewrite_regex", "Configured regex rule for host [%s]", fromHost_lower); + Dbg(dbg_ctl_url_rewrite_regex, "Configured regex rule for host [%s]", fromHost_lower); } // If a TS receives a request on a port which is set to tunnel mode @@ -1358,7 +1368,7 @@ remap_parse_config_bti(const char *path, BUILD_TABLE_INFO *bti) errStr = errStrBuf; goto MAP_ERROR; } - Debug("url_rewrite_regex", "mapped the 'strategy' named %s", strategy); + Dbg(dbg_ctl_url_rewrite_regex, "mapped the 'strategy' named %s", strategy); } } @@ -1372,7 +1382,7 @@ remap_parse_config_bti(const char *path, BUILD_TABLE_INFO *bti) // this loads the first plugin if (!remap_load_plugin((const char **)bti->argv, bti->argc, new_mapping, errStrBuf, sizeof(errStrBuf), 0, &plugin_found_at, bti->rewrite)) { - Debug("remap_plugin", "Remap plugin load error - %s", errStrBuf[0] ? errStrBuf : "Unknown error"); + Dbg(dbg_ctl_remap_plugin, "Remap plugin load error - %s", errStrBuf[0] ? errStrBuf : "Unknown error"); errStr = errStrBuf; goto MAP_ERROR; } @@ -1381,7 +1391,7 @@ remap_parse_config_bti(const char *path, BUILD_TABLE_INFO *bti) jump_to_argc += plugin_found_at; if (!remap_load_plugin((const char **)bti->argv, bti->argc, new_mapping, errStrBuf, sizeof(errStrBuf), jump_to_argc, &plugin_found_at, bti->rewrite)) { - Debug("remap_plugin", "Remap plugin load error - %s", errStrBuf[0] ? errStrBuf : "Unknown error"); + Dbg(dbg_ctl_remap_plugin, "Remap plugin load error - %s", errStrBuf[0] ? errStrBuf : "Unknown error"); errStr = errStrBuf; goto MAP_ERROR; } @@ -1415,6 +1425,7 @@ remap_parse_config_bti(const char *path, BUILD_TABLE_INFO *bti) IpAllow::enableAcceptCheck(bti->accept_check_p); return true; } +} // end anonymous namespace bool remap_parse_config(const char *path, UrlRewrite *rewrite) diff --git a/src/proxy/http/remap/RemapPluginInfo.cc b/src/proxy/http/remap/RemapPluginInfo.cc index 91fe92c8bc..001fad8a86 100644 --- a/src/proxy/http/remap/RemapPluginInfo.cc +++ b/src/proxy/http/remap/RemapPluginInfo.cc @@ -34,7 +34,7 @@ #include "unit-tests/plugin_testing_common.h" #else #include "tscore/Diags.h" -#define PluginDebug Debug +#define PluginDbg Dbg #define PluginError Error #endif @@ -55,7 +55,7 @@ RemapPluginInfo::getFunctionSymbol(const char *symbol) std::string error; /* ignore the error, return nullptr if symbol not defined */ void *address = nullptr; if (getSymbol(symbol, address, error)) { - PluginDebug(_tag, "plugin '%s' found symbol '%s'", _configPath.c_str(), symbol); + PluginDbg(_dbg_ctl(), "plugin '%s' found symbol '%s'", _configPath.c_str(), symbol); } return reinterpret_cast<T *>(address); } @@ -111,7 +111,7 @@ RemapPluginInfo::load(std::string &error) } if (valid) { - PluginDebug(_tag, "plugin '%s' callbacks validated", _configPath.c_str()); + PluginDbg(_dbg_ctl(), "plugin '%s' callbacks validated", _configPath.c_str()); } else { PluginError("plugin '%s' callbacks validation failed: %s", _configPath.c_str(), error.c_str()); } @@ -125,7 +125,7 @@ RemapPluginInfo::init(std::string &error) TSRemapInterface ri; bool result = true; - PluginDebug(_tag, "started initializing plugin '%s'", _configPath.c_str()); + PluginDbg(_dbg_ctl(), "started initializing plugin '%s'", _configPath.c_str()); /* A buffer to get the error from the plugin instance init function, be defensive here. */ char tmpbuf[2048]; @@ -148,7 +148,7 @@ RemapPluginInfo::init(std::string &error) resetPluginContext(); - PluginDebug(_tag, "finished initializing plugin '%s'", _configPath.c_str()); + PluginDbg(_dbg_ctl(), "finished initializing plugin '%s'", _configPath.c_str()); return result; } @@ -168,7 +168,7 @@ RemapPluginInfo::initInstance(int argc, char **argv, void **ih, std::string &err TSReturnCode res = TS_SUCCESS; bool result = true; - PluginDebug(_tag, "started initializing instance of plugin '%s'", _configPath.c_str()); + PluginDbg(_dbg_ctl(), "started initializing instance of plugin '%s'", _configPath.c_str()); /* A buffer to get the error from the plugin instance init function, be defensive here. */ char tmpbuf[2048]; @@ -201,7 +201,7 @@ RemapPluginInfo::initInstance(int argc, char **argv, void **ih, std::string &err } } - PluginDebug(_tag, "finished initializing instance of plugin '%s'", _configPath.c_str()); + PluginDbg(_dbg_ctl(), "finished initializing instance of plugin '%s'", _configPath.c_str()); return result; } @@ -277,12 +277,12 @@ RemapPluginInfo::setPluginContext() { _tempContext = pluginThreadContext; pluginThreadContext = this; - PluginDebug(_tag, "change plugin context from dso-addr:%p to dso-addr:%p", pluginThreadContext, _tempContext); + PluginDbg(_dbg_ctl(), "change plugin context from dso-addr:%p to dso-addr:%p", pluginThreadContext, _tempContext); } inline void RemapPluginInfo::resetPluginContext() { - PluginDebug(_tag, "change plugin context from dso-addr:%p to dso-addr:%p (restore)", this, pluginThreadContext); + PluginDbg(_dbg_ctl(), "change plugin context from dso-addr:%p to dso-addr:%p (restore)", this, pluginThreadContext); pluginThreadContext = _tempContext; } diff --git a/src/proxy/http/remap/RemapPlugins.cc b/src/proxy/http/remap/RemapPlugins.cc index 159a09ea36..7dedef9b2e 100644 --- a/src/proxy/http/remap/RemapPlugins.cc +++ b/src/proxy/http/remap/RemapPlugins.cc @@ -24,8 +24,14 @@ #include "proxy/http/remap/RemapPlugins.h" +namespace +{ ClassAllocator<RemapPlugins> pluginAllocator("RemapPluginsAlloc"); +DbgCtl dbg_ctl_url_rewrite{"url_rewrite"}; + +} // end anonymous namespace + TSRemapStatus RemapPlugins::run_plugin(RemapPluginInst *plugin) { @@ -86,14 +92,14 @@ RemapPlugins::run_single_remap() RemapPluginInst *plugin = map->get_plugin_instance(_cur); // get the nth plugin in our list of plugins TSRemapStatus plugin_retcode = TSREMAP_NO_REMAP; bool zret = true; // default - last iteration. - Debug("url_rewrite", "running single remap rule id %d for the %d%s time", map->map_id, _cur, - _cur == 1 ? "st" : - _cur == 2 ? "nd" : - _cur == 3 ? "rd" : - "th"); + Dbg(dbg_ctl_url_rewrite, "running single remap rule id %d for the %d%s time", map->map_id, _cur, + _cur == 1 ? "st" : + _cur == 2 ? "nd" : + _cur == 3 ? "rd" : + "th"); if (0 == _cur) { - Debug("url_rewrite", "setting the remapped url by copying from mapping rule"); + Dbg(dbg_ctl_url_rewrite, "setting the remapped url by copying from mapping rule"); url_rewrite_remap_request(_s->url_map, _request_url, _s->hdr_info.client_request.method_get_wksidx()); } @@ -112,11 +118,11 @@ RemapPlugins::run_single_remap() } if (TSREMAP_NO_REMAP_STOP == plugin_retcode || TSREMAP_DID_REMAP_STOP == plugin_retcode) { - Debug("url_rewrite", "breaking remap plugin chain since last plugin said we should stop after %d rewrites", _rewritten); + Dbg(dbg_ctl_url_rewrite, "breaking remap plugin chain since last plugin said we should stop after %d rewrites", _rewritten); } else if (_cur >= map->plugin_instance_count()) { - Debug("url_rewrite", "completed all remap plugins for rule id %d, changed by %d plugins", map->map_id, _rewritten); + Dbg(dbg_ctl_url_rewrite, "completed all remap plugins for rule id %d, changed by %d plugins", map->map_id, _rewritten); } else { - Debug("url_rewrite", "completed single remap, attempting another via immediate callback"); + Dbg(dbg_ctl_url_rewrite, "completed single remap, attempting another via immediate callback"); zret = false; // not done yet. } } diff --git a/src/proxy/http/remap/RemapProcessor.cc b/src/proxy/http/remap/RemapProcessor.cc index 7406d47839..fd905b80d7 100644 --- a/src/proxy/http/remap/RemapProcessor.cc +++ b/src/proxy/http/remap/RemapProcessor.cc @@ -24,8 +24,12 @@ #include "proxy/http/remap/RemapProcessor.h" RemapProcessor remapProcessor; -extern ClassAllocator<RemapPlugins> pluginAllocator; +namespace +{ +DbgCtl dbg_ctl_url_rewrite{"url_rewrite"}; + +} // end anonymous namespace /** Most of this comes from UrlRewrite::Remap(). Generally, all this does is set "map" to the appropriate entry from the HttpSM's leased m_remap @@ -36,7 +40,7 @@ extern ClassAllocator<RemapPlugins> pluginAllocator; bool RemapProcessor::setup_for_remap(HttpTransact::State *s, UrlRewrite *table) { - Debug("url_rewrite", "setting up for remap: %p", s); + Dbg(dbg_ctl_url_rewrite, "setting up for remap: %p", s); URL *request_url = nullptr; bool mapping_found = false; HTTPHdr *request_header = &s->hdr_info.client_request; @@ -53,7 +57,7 @@ RemapProcessor::setup_for_remap(HttpTransact::State *s, UrlRewrite *table) if (unlikely((table->num_rules_forward == 0) && (table->num_rules_forward_with_recv_port == 0))) { ink_assert(table->forward_mappings.empty() && table->forward_mappings_with_recv_port.empty()); - Debug("url_rewrite", "[lookup] No forward mappings found; Skipping..."); + Dbg(dbg_ctl_url_rewrite, "[lookup] No forward mappings found; Skipping..."); return false; } @@ -74,18 +78,18 @@ RemapProcessor::setup_for_remap(HttpTransact::State *s, UrlRewrite *table) request_host_len = 0; } - Debug("url_rewrite", "[lookup] attempting %s lookup", proxy_request ? "proxy" : "normal"); + Dbg(dbg_ctl_url_rewrite, "[lookup] attempting %s lookup", proxy_request ? "proxy" : "normal"); if (table->num_rules_forward_with_recv_port) { - Debug("url_rewrite", "[lookup] forward mappings with recv port found; Using recv port %d", - s->client_info.dst_addr.host_order_port()); + Dbg(dbg_ctl_url_rewrite, "[lookup] forward mappings with recv port found; Using recv port %d", + s->client_info.dst_addr.host_order_port()); if (table->forwardMappingWithRecvPortLookup(request_url, s->client_info.dst_addr.host_order_port(), request_host, request_host_len, s->url_map)) { - Debug("url_rewrite", "Found forward mapping with recv port"); + Dbg(dbg_ctl_url_rewrite, "Found forward mapping with recv port"); mapping_found = true; } else if (table->num_rules_forward == 0) { ink_assert(table->forward_mappings.empty()); - Debug("url_rewrite", "No forward mappings left"); + Dbg(dbg_ctl_url_rewrite, "No forward mappings left"); return false; } } @@ -98,7 +102,7 @@ RemapProcessor::setup_for_remap(HttpTransact::State *s, UrlRewrite *table) // they function as default rules for server requests. // If there's no host, we've already done this. if (!mapping_found && table->nohost_rules && request_host_len) { - Debug("url_rewrite", "[lookup] nothing matched"); + Dbg(dbg_ctl_url_rewrite, "[lookup] nothing matched"); mapping_found = table->forwardMappingLookup(request_url, 0, "", 0, s->url_map); } @@ -122,7 +126,7 @@ RemapProcessor::setup_for_remap(HttpTransact::State *s, UrlRewrite *table) if (mapping_found) { request_header->mark_target_dirty(); } else { - Debug("url_rewrite", "RemapProcessor::setup_for_remap did not find a mapping"); + Dbg(dbg_ctl_url_rewrite, "RemapProcessor::setup_for_remap did not find a mapping"); } return mapping_found; @@ -235,11 +239,11 @@ RemapProcessor::finish_remap(HttpTransact::State *s, UrlRewrite *table) const char *host_hdr = request_header->value_get(MIME_FIELD_HOST, MIME_LEN_HOST, &host_len); if (request_url && host_hdr != nullptr && s->txn_conf->maintain_pristine_host_hdr == 0) { - if (is_debug_tag_set("url_rewrite")) { + if (dbg_ctl_url_rewrite.on()) { int old_host_hdr_len; char *old_host_hdr = const_cast<char *>(request_header->value_get(MIME_FIELD_HOST, MIME_LEN_HOST, &old_host_hdr_len)); if (old_host_hdr) { - Debug("url_rewrite", "Host: Header before rewrite %.*s", old_host_hdr_len, old_host_hdr); + Dbg(dbg_ctl_url_rewrite, "Host: Header before rewrite %.*s", old_host_hdr_len, old_host_hdr); } } // @@ -267,9 +271,9 @@ RemapProcessor::finish_remap(HttpTransact::State *s, UrlRewrite *table) // through if (tmp >= TS_MAX_HOST_NAME_LEN) { request_header->field_delete(MIME_FIELD_HOST, MIME_LEN_HOST); - Debug("url_rewrite", "Host: Header too long after rewrite"); + Dbg(dbg_ctl_url_rewrite, "Host: Header too long after rewrite"); } else { - Debug("url_rewrite", "Host: Header after rewrite %.*s", tmp, host_hdr_buf); + Dbg(dbg_ctl_url_rewrite, "Host: Header after rewrite %.*s", tmp, host_hdr_buf); request_header->value_set(MIME_FIELD_HOST, MIME_LEN_HOST, host_hdr_buf, tmp); } } @@ -282,7 +286,7 @@ RemapProcessor::finish_remap(HttpTransact::State *s, UrlRewrite *table) Action * RemapProcessor::perform_remap(Continuation *cont, HttpTransact::State *s) { - Debug("url_rewrite", "Beginning RemapProcessor::perform_remap"); + Dbg(dbg_ctl_url_rewrite, "Beginning RemapProcessor::perform_remap"); HTTPHdr *request_header = &s->hdr_info.client_request; URL *request_url = request_header->url_get(); url_mapping *map = s->url_map.getMapping(); @@ -290,7 +294,7 @@ RemapProcessor::perform_remap(Continuation *cont, HttpTransact::State *s) if (!map) { Error("Could not find corresponding url_mapping for this transaction %p", s); - Debug("url_rewrite", "Could not find corresponding url_mapping for this transaction"); + Dbg(dbg_ctl_url_rewrite, "Could not find corresponding url_mapping for this transaction"); ink_assert(!"this should never happen -- call setup_for_remap first"); cont->handleEvent(EVENT_REMAP_ERROR, nullptr); return ACTION_RESULT_DONE; diff --git a/src/proxy/http/remap/UrlMapping.cc b/src/proxy/http/remap/UrlMapping.cc index 280d792040..bb2bd6db63 100644 --- a/src/proxy/http/remap/UrlMapping.cc +++ b/src/proxy/http/remap/UrlMapping.cc @@ -27,6 +27,12 @@ #include "records/RecCore.h" #include "tscore/ink_cap.h" +namespace +{ +DbgCtl dbg_ctl_url_rewrite{"url_rewrite"}; + +} // end anonymous namespace + /** * **/ @@ -43,7 +49,7 @@ url_mapping::add_plugin_instance(RemapPluginInst *i) RemapPluginInst * url_mapping::get_plugin_instance(std::size_t index) const { - Debug("url_rewrite", "get_plugin says we have %zu plugins and asking for plugin %zu", _plugin_inst_list.size(), index); + Dbg(dbg_ctl_url_rewrite, "get_plugin says we have %zu plugins and asking for plugin %zu", _plugin_inst_list.size(), index); if (index < _plugin_inst_list.size()) { return _plugin_inst_list[index]; } diff --git a/src/proxy/http/remap/UrlMappingPathIndex.cc b/src/proxy/http/remap/UrlMappingPathIndex.cc index 560ad6690a..9730ba3f83 100644 --- a/src/proxy/http/remap/UrlMappingPathIndex.cc +++ b/src/proxy/http/remap/UrlMappingPathIndex.cc @@ -23,6 +23,13 @@ #include "proxy/http/remap/UrlMappingPathIndex.h" +namespace +{ +DbgCtl dbg_ctl_UrlMappingPathIndex_Insert{"UrlMappingPathIndex::Insert"}; +DbgCtl dbg_ctl_UrlMappingPathIndex_Search{"UrlMappingPathIndex::Search"}; + +} // end anonymous namespace + UrlMappingPathIndex::~UrlMappingPathIndex() { for (auto &m_trie : m_tries) { @@ -45,7 +52,7 @@ UrlMappingPathIndex::Insert(url_mapping *mapping) if (!trie) { trie = new UrlMappingTrie(); m_tries.insert(UrlMappingGroup::value_type(UrlMappingTrieKey(scheme_idx, port), trie)); - Debug("UrlMappingPathIndex::Insert", "Created new trie for scheme index, port combo <%d, %d>", scheme_idx, port); + Dbg(dbg_ctl_UrlMappingPathIndex_Insert, "Created new trie for scheme index, port combo <%d, %d>", scheme_idx, port); } from_path = mapping->fromURL.path_get(&from_path_len); @@ -53,7 +60,7 @@ UrlMappingPathIndex::Insert(url_mapping *mapping) Error("Couldn't insert into trie!"); return false; } - Debug("UrlMappingPathIndex::Insert", "Inserted new element!"); + Dbg(dbg_ctl_UrlMappingPathIndex_Insert, "Inserted new element!"); return true; } @@ -69,13 +76,13 @@ UrlMappingPathIndex::Search(URL *request_url, int request_port, bool normal_sear trie = _GetTrie(request_url, scheme_idx, request_port, normal_search); if (!trie) { - Debug("UrlMappingPathIndex::Search", "No mappings exist for scheme index, port combo <%d, %d>", scheme_idx, request_port); + Dbg(dbg_ctl_UrlMappingPathIndex_Search, "No mappings exist for scheme index, port combo <%d, %d>", scheme_idx, request_port); goto lFail; } path = request_url->path_get(&path_len); if (!(retval = trie->Search(path, path_len))) { - Debug("UrlMappingPathIndex::Search", "Couldn't find entry for url with path [%.*s]", path_len, path); + Dbg(dbg_ctl_UrlMappingPathIndex_Search, "Couldn't find entry for url with path [%.*s]", path_len, path); goto lFail; } return retval; diff --git a/src/proxy/http/remap/UrlRewrite.cc b/src/proxy/http/remap/UrlRewrite.cc index e377451921..80b1460749 100644 --- a/src/proxy/http/remap/UrlRewrite.cc +++ b/src/proxy/http/remap/UrlRewrite.cc @@ -32,6 +32,11 @@ #define modulePrefix "[ReverseProxy]" +namespace +{ +DbgCtl dbg_ctl_url_rewrite_regex{"url_rewrite_regex"}; +DbgCtl dbg_ctl_url_rewrite{"url_rewrite"}; + /** Determines where we are in a situation where a virtual path is being mapped to a server home page. If it is, we set a special flag @@ -41,7 +46,7 @@ real accessing a directory (albeit a virtual one). */ -static void +void SetHomePageRedirectFlag(url_mapping *new_mapping, URL &new_to_url) { int fromLen, toLen; @@ -50,6 +55,7 @@ SetHomePageRedirectFlag(url_mapping *new_mapping, URL &new_to_url) new_mapping->homePageRedirect = (from_path && !to_path) ? true : false; } +} // end anonymous namespace bool UrlRewrite::load() @@ -83,7 +89,7 @@ UrlRewrite::load() /* Initialize the next hop strategy factory */ std::string sf = RecConfigReadConfigPath("proxy.config.url_remap.strategies.filename", "strategies.yaml"); - Debug("url_rewrite_regex", "strategyFactory file: %s", sf.c_str()); + Dbg(dbg_ctl_url_rewrite_regex, "strategyFactory file: %s", sf.c_str()); strategyFactory = new NextHopStrategyFactory(sf.c_str()); if (TS_SUCCESS == this->BuildTable(config_file_path)) { @@ -92,7 +98,7 @@ UrlRewrite::load() REC_ReadConfigInteger(required_rules, "proxy.config.url_remap.min_rules_required"); if (n_rules >= required_rules) { _valid = true; - if (is_debug_tag_set("url_rewrite")) { + if (dbg_ctl_url_rewrite.on()) { Print(); } } else { @@ -126,7 +132,7 @@ void UrlRewrite::SetReverseFlag(int flag) { reverse_proxy = flag; - if (is_debug_tag_set("url_rewrite")) { + if (dbg_ctl_url_rewrite.on()) { Print(); } } @@ -270,7 +276,7 @@ url_rewrite_remap_request(const UrlMappingContainer &mapping_container, URL *req toHost = map_to->host_get(&toHostLen); - Debug("url_rewrite", "%s: Remapping rule id: %d matched", __func__, mapping_container.getMapping()->map_id); + Dbg(dbg_ctl_url_rewrite, "%s: Remapping rule id: %d matched", __func__, mapping_container.getMapping()->map_id); request_url->host_set(toHost, toHostLen); request_url->port_set(map_to->port_get_raw()); @@ -448,7 +454,7 @@ UrlRewrite::PerformACLFiltering(HttpTransact::State *s, url_mapping *map) } } } - Debug("url_rewrite", "Checked the specified src_ip, result: %s", src_ip_matches ? "true" : "false"); + Dbg(dbg_ctl_url_rewrite, "Checked the specified src_ip, result: %s", src_ip_matches ? "true" : "false"); ip_matches &= src_ip_matches; } @@ -467,7 +473,7 @@ UrlRewrite::PerformACLFiltering(HttpTransact::State *s, url_mapping *map) } } } - Debug("url_rewrite", "Checked the specified src_ip_category, result: %s", category_ip_matches ? "true" : "false"); + Dbg(dbg_ctl_url_rewrite, "Checked the specified src_ip_category, result: %s", category_ip_matches ? "true" : "false"); ip_matches &= category_ip_matches; } @@ -477,12 +483,12 @@ UrlRewrite::PerformACLFiltering(HttpTransact::State *s, url_mapping *map) for (int j = 0; j < rp->in_ip_cnt && !in_ip_matches; j++) { IpEndpoint incoming_addr; incoming_addr.assign(s->state_machine->get_ua_txn()->get_netvc()->get_local_addr()); - if (is_debug_tag_set("url_rewrite")) { + if (dbg_ctl_url_rewrite.on()) { char buf1[128], buf2[128], buf3[128]; ats_ip_ntop(incoming_addr, buf1, sizeof(buf1)); rp->in_ip_array[j].start.toString(buf2, sizeof(buf2)); rp->in_ip_array[j].end.toString(buf3, sizeof(buf3)); - Debug("url_rewrite", "Trying to match incoming address %s in range %s - %s.", buf1, buf2, buf3); + Dbg(dbg_ctl_url_rewrite, "Trying to match incoming address %s in range %s - %s.", buf1, buf2, buf3); } bool in_range = rp->in_ip_array[j].contains(incoming_addr); if (rp->in_ip_array[j].invert) { @@ -495,27 +501,27 @@ UrlRewrite::PerformACLFiltering(HttpTransact::State *s, url_mapping *map) } } } - Debug("url_rewrite", "Checked the specified in_ip, result: %s", in_ip_matches ? "true" : "false"); + Dbg(dbg_ctl_url_rewrite, "Checked the specified in_ip, result: %s", in_ip_matches ? "true" : "false"); ip_matches &= in_ip_matches; } if (rp->internal) { ip_matches = s->state_machine->get_ua_txn()->get_netvc()->get_is_internal_request(); - Debug("url_rewrite", "%s an internal request", ip_matches ? "matched" : "didn't match"); + Dbg(dbg_ctl_url_rewrite, "%s an internal request", ip_matches ? "matched" : "didn't match"); } - Debug("url_rewrite", "%d: ACL filter %s rule matches by ip: %s, by method: %s", rule_index, - (rp->allow_flag ? "allow" : "deny"), (ip_matches ? "true" : "false"), (method_matches ? "true" : "false")); + Dbg(dbg_ctl_url_rewrite, "%d: ACL filter %s rule matches by ip: %s, by method: %s", rule_index, + (rp->allow_flag ? "allow" : "deny"), (ip_matches ? "true" : "false"), (method_matches ? "true" : "false")); if (ip_matches) { // The rule matches. Handle the method according to the rule. if (method_matches) { // Did they specify allowing the listed methods, or denying them? - Debug("url_rewrite", "matched ACL filter rule, %s request", rp->allow_flag ? "allowing" : "denying"); + Dbg(dbg_ctl_url_rewrite, "matched ACL filter rule, %s request", rp->allow_flag ? "allowing" : "denying"); s->client_connection_allowed = rp->allow_flag; } else { - Debug("url_rewrite", "ACL rule matched on IP but not on method, action: %s, %s the request", - (rp->allow_flag ? "allow" : "deny"), (rp->allow_flag ? "denying" : "allowing")); + Dbg(dbg_ctl_url_rewrite, "ACL rule matched on IP but not on method, action: %s, %s the request", + (rp->allow_flag ? "allow" : "deny"), (rp->allow_flag ? "denying" : "allowing")); s->client_connection_allowed = !rp->allow_flag; } // Since we have a matching ACL, no need to process ip_allow.yaml rules. @@ -552,12 +558,12 @@ UrlRewrite::Remap_redirect(HTTPHdr *request_header, URL *redirect_url) // header and a valid URL // if (request_header == nullptr) { - Debug("url_rewrite", "request_header was invalid. UrlRewrite::Remap_redirect bailing out."); + Dbg(dbg_ctl_url_rewrite, "request_header was invalid. UrlRewrite::Remap_redirect bailing out."); return NONE; } request_url = request_header->url_get(); if (!request_url->valid()) { - Debug("url_rewrite", "request_url was invalid. UrlRewrite::Remap_redirect bailing out."); + Dbg(dbg_ctl_url_rewrite, "request_url was invalid. UrlRewrite::Remap_redirect bailing out."); return NONE; } @@ -825,7 +831,7 @@ UrlRewrite::_mappingLookup(MappingsStore &mappings, URL *request_url, int reques char request_host_lower[TS_MAX_HOST_NAME_LEN]; if (!request_host || !request_url || (request_host_len < 0) || (request_host_len >= TS_MAX_HOST_NAME_LEN)) { - Debug("url_rewrite", "Invalid arguments!"); + Dbg(dbg_ctl_url_rewrite, "Invalid arguments!"); return false; } @@ -840,13 +846,13 @@ UrlRewrite::_mappingLookup(MappingsStore &mappings, URL *request_url, int reques url_mapping *mapping = _tableLookup(mappings.hash_lookup, request_url, request_port, request_host_lower, request_host_len); if (mapping != nullptr) { rank_ceiling = mapping->getRank(); - Debug("url_rewrite", "Found 'simple' mapping with rank %d", rank_ceiling); + Dbg(dbg_ctl_url_rewrite, "Found 'simple' mapping with rank %d", rank_ceiling); mapping_container.set(mapping); retval = true; } if (_regexMappingLookup(mappings.regex_list, request_url, request_port, request_host_lower, request_host_len, rank_ceiling, mapping_container)) { - Debug("url_rewrite", "Using regex mapping with rank %d", (mapping_container.getMapping())->getRank()); + Dbg(dbg_ctl_url_rewrite, "Using regex mapping with rank %d", (mapping_container.getMapping())->getRank()); retval = true; } if (retval) { @@ -894,8 +900,8 @@ UrlRewrite::_expandSubstitutions(size_t *matches_info, const RegexMapping *reg_m memcpy(dest_buf + cur_buf_size, reg_map->to_url_host_template + token_start, n_bytes_needed); cur_buf_size += n_bytes_needed; } - Debug("url_rewrite_regex", "Expanded substitutions and returning string [%.*s] with length %d", cur_buf_size, dest_buf, - cur_buf_size); + Dbg(dbg_ctl_url_rewrite_regex, "Expanded substitutions and returning string [%.*s] with length %d", cur_buf_size, dest_buf, + cur_buf_size); return cur_buf_size; lOverFlow: @@ -912,9 +918,9 @@ UrlRewrite::_regexMappingLookup(RegexMappingList ®ex_mappings, URL *request_u if (rank_ceiling == -1) { // we will now look at all regex mappings rank_ceiling = INT_MAX; - Debug("url_rewrite_regex", "Going to match all regexes"); + Dbg(dbg_ctl_url_rewrite_regex, "Going to match all regexes"); } else { - Debug("url_rewrite_regex", "Going to match regexes with rank <= %d", rank_ceiling); + Dbg(dbg_ctl_url_rewrite_regex, "Going to match regexes with rank <= %d", rank_ceiling); } int request_scheme_len, reg_map_scheme_len; @@ -941,32 +947,32 @@ UrlRewrite::_regexMappingLookup(RegexMappingList ®ex_mappings, URL *request_u reg_map_scheme = list_iter->url_map->fromURL.scheme_get(®_map_scheme_len); if ((request_scheme_len != reg_map_scheme_len) || strncmp(request_scheme, reg_map_scheme, request_scheme_len)) { - Debug("url_rewrite_regex", "Skipping regex with rank %d as scheme does not match request scheme", reg_map_rank); + Dbg(dbg_ctl_url_rewrite_regex, "Skipping regex with rank %d as scheme does not match request scheme", reg_map_rank); continue; } if (list_iter->url_map->fromURL.port_get() != request_port) { - Debug("url_rewrite_regex", - "Skipping regex with rank %d as regex map port does not match request port. " - "regex map port: %d, request port %d", - reg_map_rank, list_iter->url_map->fromURL.port_get(), request_port); + Dbg(dbg_ctl_url_rewrite_regex, + "Skipping regex with rank %d as regex map port does not match request port. " + "regex map port: %d, request port %d", + reg_map_rank, list_iter->url_map->fromURL.port_get(), request_port); continue; } reg_map_path = list_iter->url_map->fromURL.path_get(®_map_path_len); if ((request_path_len < reg_map_path_len) || strncmp(reg_map_path, request_path, reg_map_path_len)) { // use the shorter path length here - Debug("url_rewrite_regex", "Skipping regex with rank %d as path does not cover request path", reg_map_rank); + Dbg(dbg_ctl_url_rewrite_regex, "Skipping regex with rank %d as path does not cover request path", reg_map_rank); continue; } int match_result = list_iter->regular_expression.exec(std::string_view(request_host, request_host_len), matches); if (match_result > 0) { - Debug("url_rewrite_regex", - "Request URL host [%.*s] matched regex in mapping of rank %d " - "with %d possible substitutions", - request_host_len, request_host, reg_map_rank, match_result); + Dbg(dbg_ctl_url_rewrite_regex, + "Request URL host [%.*s] matched regex in mapping of rank %d " + "with %d possible substitutions", + request_host_len, request_host, reg_map_rank, match_result); mapping_container.set(list_iter->url_map); @@ -980,12 +986,12 @@ UrlRewrite::_regexMappingLookup(RegexMappingList ®ex_mappings, URL *request_u expanded_url->copy(&((list_iter->url_map)->toURL)); expanded_url->host_set(buf, buf_len); - Debug("url_rewrite_regex", "Expanded toURL to [%.*s]", expanded_url->length_get(), expanded_url->string_get_ref()); + Dbg(dbg_ctl_url_rewrite_regex, "Expanded toURL to [%.*s]", expanded_url->length_get(), expanded_url->string_get_ref()); retval = true; break; } else { - Debug("url_rewrite_regex", "Request URL host [%.*s] did NOT match regex in mapping of rank %d", request_host_len, - request_host, reg_map_rank); + Dbg(dbg_ctl_url_rewrite_regex, "Request URL host [%.*s] did NOT match regex in mapping of rank %d", request_host_len, + request_host, reg_map_rank); } } diff --git a/src/proxy/http/remap/unit-tests/plugin_testing_common.h b/src/proxy/http/remap/unit-tests/plugin_testing_common.h index b45e5f215b..5652626628 100644 --- a/src/proxy/http/remap/unit-tests/plugin_testing_common.h +++ b/src/proxy/http/remap/unit-tests/plugin_testing_common.h @@ -89,8 +89,8 @@ public: using GetPluginDebugObjectFunction = void *(); extern "C" GetPluginDebugObjectFunction getPluginDebugObjectTest; -#define PluginDebug(category, fmt, ...) \ - PrintToStdErr("(%s) %s:%d:%s() " fmt "\n", category, __FILE__, __LINE__, __func__, ##__VA_ARGS__) +#define PluginDbg(dbg_ctl, fmt, ...) \ + PrintToStdErr("(%s) %s:%d:%s() " fmt "\n", (dbg_ctl).tag(), __FILE__, __LINE__, __func__, ##__VA_ARGS__) #define PluginError(fmt, ...) PrintToStdErr("%s:%d:%s() " fmt "\n", __FILE__, __LINE__, __func__, ##__VA_ARGS__) void PrintToStdErr(const char *fmt, ...);
