Remove deprecated debug output functions from 21 source files. (#9683)

Author: ywkaras

iocore/net/NetHandler.h

@@ -223,6 +223,9 @@ class NetHandler : public Continuation, public EThread::LoopTailHandler
 
   NetHandler();
 
+  inline static DbgCtl dbg_ctl_socket{"socket"};
+  inline static DbgCtl dbg_ctl_iocore_net{"iocore_net"};
+
 private:
   void _close_ne(NetEvent *ne, ink_hrtime now, int &handle_event, int &closed, int &total_idle_time, int &total_idle_count);
 

iocore/net/P_Net.h

@@ -108,9 +108,9 @@ static constexpr ts::ModuleVersion NET_SYSTEM_MODULE_INTERNAL_VERSION(NET_SYSTEM
 
 // For very verbose iocore debugging.
 #ifndef DEBUG
-#define NetDebug(tag, fmt, ...)
+#define NetDbg(dbg_ctl, fmt, ...)
 #else
-#define NetDebug(tag, fmt, ...) Debug(tag, fmt, ##__VA_ARGS__)
+#define NetDbg(dbg_ctl, fmt, ...) Dbg(dbg_ctl, fmt, ##__VA_ARGS__)
 #endif
 
 /// Default amount of buffer space to use for the initial read on an incoming connection.

iocore/net/P_NetAccept.h

@@ -76,7 +76,11 @@ struct NetAcceptAction : public Action, public RefCountObj {
     return Action::operator=(acont);
   }
 
-  ~NetAcceptAction() override { Debug("net_accept", "NetAcceptAction dying"); }
+  ~NetAcceptAction() override
+  {
+    static DbgCtl dbg_ctl{"net_accept"};
+    Dbg(dbg_ctl, "NetAcceptAction dying");
+  }
 };
 
 //

iocore/net/P_SNIActionPerformer.h

@@ -75,10 +75,10 @@ class ControlH2 : public ActionItem
     if (ssl_vc) {
       if (!enable_h2) {
         ssl_vc->disableProtocol(TS_ALPN_PROTOCOL_INDEX_HTTP_2_0);
-        Debug("ssl_sni", "H2 disabled, fqdn [%s]", servername);
+        Dbg(dbg_ctl_ssl_sni, "H2 disabled, fqdn [%s]", servername);
       } else {
         ssl_vc->enableProtocol(TS_ALPN_PROTOCOL_INDEX_HTTP_2_0);
-        Debug("ssl_sni", "H2 enabled, fqdn [%s]", servername);
+        Dbg(dbg_ctl_ssl_sni, "H2 enabled, fqdn [%s]", servername);
       }
     }
     return SSL_TLSEXT_ERR_OK;
@@ -179,7 +179,7 @@ class TunnelDestination : public ActionItem
     if (ssl_netvc) {
       if (fnArrIndexes.empty()) {
         ssl_netvc->set_tunnel_destination(destination, type, !TLSTunnelSupport::PORT_IS_DYNAMIC, tunnel_prewarm);
-        Debug("ssl_sni", "Destination now is [%s], fqdn [%s]", destination.c_str(), servername);
+        Dbg(dbg_ctl_ssl_sni, "Destination now is [%s], fqdn [%s]", destination.c_str(), servername);
       } else {
         bool port_is_dynamic = false;
         auto fixed_dst{destination};
@@ -189,7 +189,8 @@ class TunnelDestination : public ActionItem
           fixed_dst = fix_destination[fnArrIndex](fixed_dst, var_start_pos, ctx, ssl_netvc, port_is_dynamic);
         }
         ssl_netvc->set_tunnel_destination(fixed_dst, type, port_is_dynamic, tunnel_prewarm);
-        Debug("ssl_sni", "Destination now is [%s], configured [%s], fqdn [%s]", fixed_dst.c_str(), destination.c_str(), servername);
+        Dbg(dbg_ctl_ssl_sni, "Destination now is [%s], configured [%s], fqdn [%s]", fixed_dst.c_str(), destination.c_str(),
+            servername);
       }
 
       if (type == SNIRoutingType::BLIND) {
@@ -320,7 +321,7 @@ class VerifyClient : public ActionItem
   {
     auto ssl_vc            = dynamic_cast<SSLNetVConnection *>(snis);
     const char *servername = snis->get_sni_server_name();
-    Debug("ssl_sni", "action verify param %d, fqdn [%s]", this->mode, servername);
+    Dbg(dbg_ctl_ssl_sni, "action verify param %d, fqdn [%s]", this->mode, servername);
     setClientCertLevel(ssl_vc->ssl, this->mode);
     ssl_vc->set_ca_cert_file(ca_file, ca_dir);
     setClientCertCACerts(ssl_vc->ssl, ssl_vc->get_ca_cert_file(), ssl_vc->get_ca_cert_dir());
@@ -388,15 +389,15 @@ class TLSValidProtocols : public ActionItem
   {
     if (this->min_ver >= 0 || this->max_ver >= 0) {
       const char *servername = snis->get_sni_server_name();
-      Debug("ssl_sni", "TLSValidProtocol min=%d, max=%d, fqdn [%s]", this->min_ver, this->max_ver, servername);
+      Dbg(dbg_ctl_ssl_sni, "TLSValidProtocol min=%d, max=%d, fqdn [%s]", this->min_ver, this->max_ver, servername);
       auto ssl_vc = dynamic_cast<SSLNetVConnection *>(snis);
       ssl_vc->set_valid_tls_version_min(this->min_ver);
       ssl_vc->set_valid_tls_version_max(this->max_ver);
     } else {
       if (!unset) {
         auto ssl_vc            = dynamic_cast<SSLNetVConnection *>(snis);
         const char *servername = snis->get_sni_server_name();
-        Debug("ssl_sni", "TLSValidProtocol param 0%x, fqdn [%s]", static_cast<unsigned int>(this->protocol_mask), servername);
+        Dbg(dbg_ctl_ssl_sni, "TLSValidProtocol param 0%x, fqdn [%s]", static_cast<unsigned int>(this->protocol_mask), servername);
         ssl_vc->set_valid_tls_protocols(protocol_mask, TLSValidProtocols::max_mask);
         Warning("valid_tls_versions_in is deprecated. Use valid_tls_version_min_in and ivalid_tls_version_max_in instead.");
       }

iocore/net/P_UDPNet.h

@@ -231,9 +231,12 @@ class PacketQueue
       }
     }
 
-    if (s != now_slot)
-      Debug("v_udpnet-service", "Advancing by (%d slots): behind by %" PRId64 " ms", s - now_slot,
-            ink_hrtime_to_msec(t - delivery_time[now_slot]));
+    if (s != now_slot) {
+      static DbgCtl dbg_ctl{"v_udpnet-service"};
+      Dbg(dbg_ctl, "Advancing by (%d slots): behind by %" PRId64 " ms", s - now_slot,
+          ink_hrtime_to_msec(t - delivery_time[now_slot]));
+    }
+
     now_slot = s;
   }
 

iocore/net/P_UnixNet.h

@@ -232,7 +232,8 @@ read_disable(NetHandler *nh, NetEvent *ne)
     // Clear the next scheduled inactivity time, but don't clear inactivity_timeout_in,
     // so the current timeout is used when the NetEvent is reenabled and not the default inactivity timeout
     ne->next_inactivity_timeout_at = 0;
-    Debug("socket", "read_disable updating inactivity_at %" PRId64 ", NetEvent=%p", ne->next_inactivity_timeout_at, ne);
+    Dbg(NetHandler::dbg_ctl_socket, "read_disable updating inactivity_at %" PRId64 ", NetEvent=%p", ne->next_inactivity_timeout_at,
+        ne);
   }
   ne->read.enabled = 0;
   nh->read_ready_list.remove(ne);
@@ -255,7 +256,8 @@ write_disable(NetHandler *nh, NetEvent *ne)
     // Clear the next scheduled inactivity time, but don't clear inactivity_timeout_in,
     // so the current timeout is used when the NetEvent is reenabled and not the default inactivity timeout
     ne->next_inactivity_timeout_at = 0;
-    Debug("socket", "write_disable updating inactivity_at %" PRId64 ", NetEvent=%p", ne->next_inactivity_timeout_at, ne);
+    Dbg(NetHandler::dbg_ctl_socket, "write_disable updating inactivity_at %" PRId64 ", NetEvent=%p", ne->next_inactivity_timeout_at,
+        ne);
   }
   ne->write.enabled = 0;
   nh->write_ready_list.remove(ne);

iocore/net/P_UnixNetVConnection.h

@@ -228,6 +228,9 @@ class UnixNetVConnection : public NetVConnection, public NetEvent
 private:
   virtual void *_prepareForMigration();
   virtual NetProcessor *_getNetProcessor();
+
+  inline static DbgCtl _dbg_ctl_socket{"socket"};
+  inline static DbgCtl _dbg_ctl_socket_mptcp{"socket_mptcp"};
 };
 
 extern ClassAllocator<UnixNetVConnection> netVCAllocator;
@@ -268,10 +271,10 @@ UnixNetVConnection::set_mptcp_state()
   int mptcp_enabled_size = sizeof(mptcp_enabled);
 
   if (0 == safe_getsockopt(con.fd, IPPROTO_TCP, MPTCP_ENABLED, (char *)&mptcp_enabled, &mptcp_enabled_size)) {
-    Debug("socket_mptcp", "MPTCP socket state: %d", mptcp_enabled);
+    Dbg(_dbg_ctl_socket_mptcp, "MPTCP socket state: %d", mptcp_enabled);
     mptcp_state = mptcp_enabled > 0 ? true : false;
   } else {
-    Debug("socket_mptcp", "MPTCP failed getsockopt(): %s", strerror(errno));
+    Dbg(_dbg_ctl_socket_mptcp, "MPTCP failed getsockopt(): %s", strerror(errno));
   }
 }
 
@@ -290,23 +293,23 @@ UnixNetVConnection::get_inactivity_timeout()
 inline void
 UnixNetVConnection::set_active_timeout(ink_hrtime timeout_in)
 {
-  Debug("socket", "Set active timeout=%" PRId64 ", NetVC=%p", timeout_in, this);
+  Dbg(_dbg_ctl_socket, "Set active timeout=%" PRId64 ", NetVC=%p", timeout_in, this);
   active_timeout_in        = timeout_in;
   next_activity_timeout_at = (active_timeout_in > 0) ? ink_get_hrtime() + timeout_in : 0;
 }
 
 inline void
 UnixNetVConnection::cancel_inactivity_timeout()
 {
-  Debug("socket", "Cancel inactive timeout for NetVC=%p", this);
+  Dbg(_dbg_ctl_socket, "Cancel inactive timeout for NetVC=%p", this);
   inactivity_timeout_in      = 0;
   next_inactivity_timeout_at = 0;
 }
 
 inline void
 UnixNetVConnection::cancel_active_timeout()
 {
-  Debug("socket", "Cancel active timeout for NetVC=%p", this);
+  Dbg(_dbg_ctl_socket, "Cancel active timeout for NetVC=%p", this);
   active_timeout_in        = 0;
   next_activity_timeout_at = 0;
 }

iocore/net/PollCont.cc

@@ -25,6 +25,16 @@
 #include "PollCont.h"
 #include "P_Net.h"
 
+namespace
+{
+#ifdef DEBUG
+
+DbgCtl dbg_ctl_iocore_net_poll{"iocore_net_poll"};
+DbgCtl dbg_ctl_v_iocore_net_poll{"v_iocore_net_poll"};
+
+#endif
+} // end anonymous namespace
+
 PollCont::PollCont(Ptr<ProxyMutex> &m, int pt)
   : Continuation(m.get()), net_handler(nullptr), nextPollDescriptor(nullptr), poll_timeout(pt)
 {
@@ -66,9 +76,8 @@ PollCont::do_poll(ink_hrtime timeout)
      * read or write) that need processing [ebalsa] */
     if (likely(!net_handler->read_ready_list.empty() || !net_handler->write_ready_list.empty() ||
                !net_handler->read_enable_list.empty() || !net_handler->write_enable_list.empty())) {
-      NetDebug("iocore_net_poll", "rrq: %d, wrq: %d, rel: %d, wel: %d", net_handler->read_ready_list.empty(),
-               net_handler->write_ready_list.empty(), net_handler->read_enable_list.empty(),
-               net_handler->write_enable_list.empty());
+      NetDbg(dbg_ctl_iocore_net_poll, "rrq: %d, wrq: %d, rel: %d, wel: %d", net_handler->read_ready_list.empty(),
+             net_handler->write_ready_list.empty(), net_handler->read_enable_list.empty(), net_handler->write_enable_list.empty());
       poll_timeout = 0; // poll immediately returns -- we have triggered stuff
                         // to process right now
     } else if (timeout >= 0) {
@@ -81,15 +90,15 @@ PollCont::do_poll(ink_hrtime timeout)
 #if TS_USE_EPOLL
   pollDescriptor->result =
     epoll_wait(pollDescriptor->epoll_fd, pollDescriptor->ePoll_Triggered_Events, POLL_DESCRIPTOR_SIZE, poll_timeout);
-  NetDebug("v_iocore_net_poll", "[PollCont::pollEvent] epoll_fd: %d, timeout: %d, results: %d", pollDescriptor->epoll_fd,
-           poll_timeout, pollDescriptor->result);
+  NetDbg(dbg_ctl_v_iocore_net_poll, "[PollCont::pollEvent] epoll_fd: %d, timeout: %d, results: %d", pollDescriptor->epoll_fd,
+         poll_timeout, pollDescriptor->result);
 #elif TS_USE_KQUEUE
   struct timespec tv;
   tv.tv_sec  = poll_timeout / 1000;
   tv.tv_nsec = 1000000 * (poll_timeout % 1000);
   pollDescriptor->result =
     kevent(pollDescriptor->kqueue_fd, nullptr, 0, pollDescriptor->kq_Triggered_Events, POLL_DESCRIPTOR_SIZE, &tv);
-  NetDebug("v_iocore_net_poll", "[PollCont::pollEvent] kqueue_fd: %d, timeout: %d, results: %d", pollDescriptor->kqueue_fd,
-           poll_timeout, pollDescriptor->result);
+  NetDbg(dbg_ctl_v_iocore_net_poll, "[PollCont::pollEvent] kqueue_fd: %d, timeout: %d, results: %d", pollDescriptor->kqueue_fd,
+         poll_timeout, pollDescriptor->result);
 #endif
 }

iocore/net/QUICNetProcessor.cc

@@ -39,6 +39,15 @@
 
 QUICNetProcessor quic_NetProcessor;
 
+namespace
+{
+
+DbgCtl dbg_ctl_quic_ps{"quic_ps"};
+DbgCtl dbg_ctl_udpnet{"udpnet"};
+DbgCtl dbg_ctl_iocore_net_processor{"iocore_net_processor"};
+
+} // end anonymous namespace
+
 QUICNetProcessor::QUICNetProcessor() {}
 
 QUICNetProcessor::~QUICNetProcessor()
@@ -68,7 +77,7 @@ QUICNetProcessor::start(int, size_t stacksize)
 
 #ifdef TLS1_3_VERSION_DRAFT_TXT
   // FIXME: remove this when TLS1_3_VERSION_DRAFT_TXT is removed
-  Debug("quic_ps", "%s", TLS1_3_VERSION_DRAFT_TXT);
+  Dbg(dbg_ctl_quick_ps, "%s", TLS1_3_VERSION_DRAFT_TXT);
 #endif
 
   return 0;
@@ -107,7 +116,7 @@ QUICNetProcessor::allocate_vc(EThread *t)
 Action *
 QUICNetProcessor::connect_re(Continuation *cont, sockaddr const *remote_addr, NetVCOptions const &opt)
 {
-  Debug("quic_ps", "connect to server");
+  Dbg(dbg_ctl_quick_ps, "connect to server");
   EThread *t = cont->mutex->thread_holding;
   ink_assert(t);
   QUICNetVConnection *vc = static_cast<QUICNetVConnection *>(this->allocate_vc(t));
@@ -124,7 +133,7 @@ QUICNetProcessor::connect_re(Continuation *cont, sockaddr const *remote_addr, Ne
 
   // Setup UDPConnection
   UnixUDPConnection *con = new UnixUDPConnection(fd);
-  Debug("quic_ps", "con=%p fd=%d", con, fd);
+  Dbg(dbg_ctl_quick_ps, "con=%p fd=%d", con, fd);
 
   this->_rtable                        = new QUICResetTokenTable();
   QUICPacketHandlerOut *packet_handler = new QUICPacketHandlerOut(*this->_rtable);
@@ -139,7 +148,7 @@ QUICNetProcessor::connect_re(Continuation *cont, sockaddr const *remote_addr, Ne
   errno   = 0;
   int res = con->ep.start(pd, con, EVENTIO_READ);
   if (res < 0) {
-    Debug("udpnet", "Error: %s (%d)", strerror(errno), errno);
+    Dbg(dbg_ctl_udpnet, "Error: %s (%d)", strerror(errno), errno);
   }
 
   // Setup QUICNetVConnection
@@ -182,8 +191,8 @@ Action *
 QUICNetProcessor::main_accept(Continuation *cont, SOCKET fd, AcceptOptions const &opt)
 {
   // UnixNetProcessor *this_unp = static_cast<UnixNetProcessor *>(this);
-  Debug("iocore_net_processor", "NetProcessor::main_accept - port %d,recv_bufsize %d, send_bufsize %d, sockopt 0x%0x",
-        opt.local_port, opt.recv_bufsize, opt.send_bufsize, opt.sockopt_flags);
+  Dbg(dbg_ctl_iocore_net_processor, "NetProcessor::main_accept - port %d,recv_bufsize %d, send_bufsize %d, sockopt 0x%0x",
+      opt.local_port, opt.recv_bufsize, opt.send_bufsize, opt.sockopt_flags);
 
   ProxyMutex *mutex  = this_ethread()->mutex.get();
   int accept_threads = opt.accept_threads; // might be changed.

iocore/net/QUICPacketHandler.cc

@@ -37,17 +37,22 @@
 #include "QUICMultiCertConfigLoader.h"
 #include "QUICTLS.h"
 
-static constexpr char debug_tag[]   = "quic_sec";
-static constexpr char v_debug_tag[] = "v_quic_sec";
+namespace
+{
+
+DbgCtl dbg_ctl{"quic_sec"};
+DbgCtl dbg_ctl_v{"v_quic_sec"};
+DbgCtl dbg_ctl_quick_ph{"quic_ph"};
+
+} // end anonymous namespace
 
-#define QUICDebug(fmt, ...)       Debug(debug_tag, fmt, ##__VA_ARGS__)
-#define QUICQCDebug(qc, fmt, ...) Debug(debug_tag, "[%s] " fmt, qc->cids().data(), ##__VA_ARGS__)
+#define QUICDebug(fmt, ...)       Dbg(dbg_ctl, fmt, ##__VA_ARGS__)
+#define QUICQCDebug(qc, fmt, ...) Dbg(dbg_ctl, "[%s] " fmt, qc->cids().data(), ##__VA_ARGS__)
 
 // ["local dcid" - "local scid"]
-#define QUICPHDebug(dcid, scid, fmt, ...) \
-  Debug(debug_tag, "[%08" PRIx32 "-%08" PRIx32 "] " fmt, dcid.h32(), scid.h32(), ##__VA_ARGS__)
+#define QUICPHDebug(dcid, scid, fmt, ...) Dbg(dbg_ctl, "[%08" PRIx32 "-%08" PRIx32 "] " fmt, dcid.h32(), scid.h32(), ##__VA_ARGS__)
 #define QUICVPHDebug(dcid, scid, fmt, ...) \
-  Debug(v_debug_tag, "[%08" PRIx32 "-%08" PRIx32 "] " fmt, dcid.h32(), scid.h32(), ##__VA_ARGS__)
+  Dbg(dbg_ctl_v, "[%08" PRIx32 "-%08" PRIx32 "] " fmt, dcid.h32(), scid.h32(), ##__VA_ARGS__)
 
 //
 // QUICPacketHandler
@@ -102,7 +107,7 @@ QUICPacketHandler::_send_packet(UDPConnection *udp_con, IpEndpoint &addr, Ptr<IO
 {
   UDPPacket *udp_packet = UDPPacket::new_UDPPacket(addr, 0, udp_payload);
 
-  if (is_debug_tag_set(v_debug_tag)) {
+  if (dbg_ctl_v.on()) {
     ip_port_text_buffer ipb;
     QUICConnectionId dcid = QUICConnectionId::ZERO();
     QUICConnectionId scid = QUICConnectionId::ZERO();
@@ -257,7 +262,7 @@ QUICPacketHandlerIn::_recv_packet(int event, UDPPacket *udp_packet)
       return;
     }
 
-    if (is_debug_tag_set(v_debug_tag)) {
+    if (dbg_ctl_v.on()) {
       ip_port_text_buffer ipb_from;
       ip_port_text_buffer ipb_to;
       QUICVPHDebug(scid, dcid, "recv LH packet from %s to %s size=%" PRId64,
@@ -299,7 +304,7 @@ QUICPacketHandlerIn::_recv_packet(int event, UDPPacket *udp_packet)
     }
   } else {
     // TODO: lookup DCID by 5-tuple when ATS omits SCID
-    if (is_debug_tag_set(v_debug_tag)) {
+    if (dbg_ctl_v.on()) {
       ip_port_text_buffer ipb_from;
       ip_port_text_buffer ipb_to;
       QUICVPHDebug(scid, dcid, "recv SH packet from %s to %s size=%" PRId64,
@@ -339,7 +344,7 @@ QUICPacketHandlerIn::_recv_packet(int event, UDPPacket *udp_packet)
       this->_send_stateless_reset(dcid, params->instance_id(), udp_packet->getConnection(), udp_packet->from, buf_len - 1);
     udp_packet->free();
 
-    if (is_debug_tag_set(debug_tag) && sent) {
+    if (dbg_ctl.on() && sent) {
       QUICPHDebug(scid, dcid, "sent Stateless Reset : connection not found, dcid=%s", dcid.hex().c_str());
     }
 
@@ -350,7 +355,7 @@ QUICPacketHandlerIn::_recv_packet(int event, UDPPacket *udp_packet)
       this->_send_stateless_reset(dcid, params->instance_id(), udp_packet->getConnection(), udp_packet->from, buf_len - 1);
     udp_packet->free();
 
-    if (is_debug_tag_set(debug_tag) && sent) {
+    if (dbg_ctl.on() && sent) {
       QUICPHDebug(scid, dcid, "sent Stateless Reset : connection is already closed, dcid=%s", dcid.hex().c_str());
     }
 
@@ -367,7 +372,7 @@ QUICPacketHandlerIn::_recv_packet(int event, UDPPacket *udp_packet)
     QUICConnectionId original_cid = dcid;
     QUICConnectionId peer_cid     = scid;
 
-    if (is_debug_tag_set("quic_sec")) {
+    if (dbg_ctl.on()) {
       QUICPHDebug(peer_cid, original_cid, "client initial dcid=%s", original_cid.hex().c_str());
     }
 
@@ -555,7 +560,7 @@ QUICPacketHandlerOut::event_handler(int event, Event *data)
     return EVENT_CONT;
   }
   default:
-    Debug("quic_ph", "Unknown Event (%d)", event);
+    Dbg(dbg_ctl_quic_ph, "Unknown Event (%d)", event);
 
     break;
   }
@@ -576,7 +581,7 @@ QUICPacketHandlerOut::_recv_packet(int event, UDPPacket *udp_packet)
   const uint8_t *buf   = reinterpret_cast<uint8_t *>(block->buf());
   uint64_t buf_len     = block->size();
 
-  if (is_debug_tag_set(debug_tag)) {
+  if (dbg_ctl.on()) {
     ip_port_text_buffer ipb_from;
     ip_port_text_buffer ipb_to;
     QUICQCDebug(this->_vc, "recv %s packet from %s to %s size=%" PRId64, (QUICInvariants::is_long_header(buf) ? "LH" : "SH"),