diff --git a/iocore/net/NetHandler.h b/iocore/net/NetHandler.h index 9103aeabd34..d218d8ccc6f 100644 --- a/iocore/net/NetHandler.h +++ b/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); diff --git a/iocore/net/P_Net.h b/iocore/net/P_Net.h index 09c2fa12512..7516b106cd5 100644 --- a/iocore/net/P_Net.h +++ b/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. diff --git a/iocore/net/P_NetAccept.h b/iocore/net/P_NetAccept.h index ddeeb8b5af7..f44c70b5171 100644 --- a/iocore/net/P_NetAccept.h +++ b/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"); + } }; // diff --git a/iocore/net/P_SNIActionPerformer.h b/iocore/net/P_SNIActionPerformer.h index 88790cab800..cdfb39de7ea 100644 --- a/iocore/net/P_SNIActionPerformer.h +++ b/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(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,7 +389,7 @@ 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(snis); ssl_vc->set_valid_tls_version_min(this->min_ver); ssl_vc->set_valid_tls_version_max(this->max_ver); @@ -396,7 +397,7 @@ class TLSValidProtocols : public ActionItem if (!unset) { auto ssl_vc = dynamic_cast(snis); const char *servername = snis->get_sni_server_name(); - Debug("ssl_sni", "TLSValidProtocol param 0%x, fqdn [%s]", static_cast(this->protocol_mask), servername); + Dbg(dbg_ctl_ssl_sni, "TLSValidProtocol param 0%x, fqdn [%s]", static_cast(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."); } diff --git a/iocore/net/P_UDPNet.h b/iocore/net/P_UDPNet.h index 190dad42921..ca97e5788db 100644 --- a/iocore/net/P_UDPNet.h +++ b/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; } diff --git a/iocore/net/P_UnixNet.h b/iocore/net/P_UnixNet.h index 36e8b78623f..6dce358cc2a 100644 --- a/iocore/net/P_UnixNet.h +++ b/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); diff --git a/iocore/net/P_UnixNetVConnection.h b/iocore/net/P_UnixNetVConnection.h index f978c9e2dc2..f453d014944 100644 --- a/iocore/net/P_UnixNetVConnection.h +++ b/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 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,7 +293,7 @@ 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; } @@ -298,7 +301,7 @@ UnixNetVConnection::set_active_timeout(ink_hrtime timeout_in) 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; } @@ -306,7 +309,7 @@ UnixNetVConnection::cancel_inactivity_timeout() 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; } diff --git a/iocore/net/PollCont.cc b/iocore/net/PollCont.cc index 66fab48b423..e08109c44d9 100644 --- a/iocore/net/PollCont.cc +++ b/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 &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 } diff --git a/iocore/net/QUICNetProcessor.cc b/iocore/net/QUICNetProcessor.cc index f13fe3c3b3b..5235b248bd7 100644 --- a/iocore/net/QUICNetProcessor.cc +++ b/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(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(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. diff --git a/iocore/net/QUICPacketHandler.cc b/iocore/net/QUICPacketHandler.cc index dcb491d0f0f..a0c1013a628 100644 --- a/iocore/net/QUICPacketHandler.cc +++ b/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_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(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"), diff --git a/iocore/net/SNIActionPerformer.cc b/iocore/net/SNIActionPerformer.cc index 46445cf5720..7d3f93ec880 100644 --- a/iocore/net/SNIActionPerformer.cc +++ b/iocore/net/SNIActionPerformer.cc @@ -46,9 +46,9 @@ ControlQUIC::SNIAction(TLSSNISupport *snis, const Context &ctx) const return SSL_TLSEXT_ERR_OK; } - if (is_debug_tag_set("ssl_sni")) { + if (dbg_ctl_ssl_sni.on()) { const char *servername = quic_vc->get_server_name(); - Debug("ssl_sni", "Rejecting handshake due to QUIC being disabled for fqdn [%s]", servername); + Dbg(dbg_ctl_ssl_sni, "Rejecting handshake due to QUIC being disabled for fqdn [%s]", servername); } return SSL_TLSEXT_ERR_ALERT_FATAL; @@ -84,11 +84,11 @@ SNI_IpAllow::load(swoc::TextView content, swoc::TextView server_name) while (!content.ltrim(delim).empty()) { swoc::TextView token{content.take_prefix_at(delim)}; if (swoc::IPRange r; r.load(token)) { - Debug("ssl_sni", "%.*s is not a valid format", static_cast(token.size()), token.data()); + Dbg(dbg_ctl_ssl_sni, "%.*s is not a valid format", static_cast(token.size()), token.data()); break; } else { - Debug("ssl_sni", "%.*s added to the ip_allow token %.*s", static_cast(token.size()), token.data(), - int(server_name.size()), server_name.data()); + Dbg(dbg_ctl_ssl_sni, "%.*s added to the ip_allow token %.*s", static_cast(token.size()), token.data(), + int(server_name.size()), server_name.data()); ip_addrs.fill(r); } } @@ -111,7 +111,7 @@ SNI_IpAllow::SNIAction(TLSSNISupport *snis, ActionItem::Context const &ctx) cons } else { swoc::LocalBufferWriter<256> w; w.print("{} is not allowed - denying connection\0", ip); - Debug("ssl_sni", "%s", w.data()); + Dbg(dbg_ctl_ssl_sni, "%s", w.data()); return SSL_TLSEXT_ERR_ALERT_FATAL; } } diff --git a/iocore/net/SNIActionPerformer.h b/iocore/net/SNIActionPerformer.h index ba40c73a26f..d06e40df5dd 100644 --- a/iocore/net/SNIActionPerformer.h +++ b/iocore/net/SNIActionPerformer.h @@ -34,6 +34,7 @@ #include #include "TLSSNISupport.h" #include "tscore/ink_inet.h" +#include "ts/DbgCtl.h" class ActionItem { @@ -66,4 +67,7 @@ class ActionItem return false; } virtual ~ActionItem(){}; + +protected: + inline static DbgCtl dbg_ctl_ssl_sni{"ssl_sni"}; }; diff --git a/iocore/net/SSLDiags.h b/iocore/net/SSLDiags.h index 0301e9bc413..3c7aadddb11 100644 --- a/iocore/net/SSLDiags.h +++ b/iocore/net/SSLDiags.h @@ -40,10 +40,10 @@ void SSLDiagnostic(const SourceLocation &loc, bool debug, SSLNetVConnection *vc, const char *SSLErrorName(int ssl_error); // Log a SSL network buffer. TAG must be a C-string literal debug tag. -#define SSLDebugBufferPrint(TAG, BUFFER, BUFFER_LEN, MESSAGE) \ - do { \ - if (is_debug_tag_set(TAG)) \ - SSLDebugBufferPrint_(BUFFER, BUFFER_LEN, MESSAGE); \ +#define SSLDebugBufferPrint(DBG_CTL, BUFFER, BUFFER_LEN, MESSAGE) \ + do { \ + if ((DBG_CTL).on()) \ + SSLDebugBufferPrint_(BUFFER, BUFFER_LEN, MESSAGE); \ } while (0) void SSLDebugBufferPrint_(const char *buffer, unsigned buflen, const char *message); diff --git a/iocore/net/SSLNetVConnection.cc b/iocore/net/SSLNetVConnection.cc index b43bd91a829..d16b3592fab 100644 --- a/iocore/net/SSLNetVConnection.cc +++ b/iocore/net/SSLNetVConnection.cc @@ -76,6 +76,20 @@ ClassAllocator sslNetVCAllocator("sslNetVCAllocator"); namespace { +DbgCtl dbg_ctl_ssl_early_data{"ssl_early_data"}; +DbgCtl dbg_ctl_ssl_early_data_show_received{"ssl_early_data_show_received"}; +DbgCtl dbg_ctl_ssl{"ssl"}; +DbgCtl dbg_ctl_v_ssl{"v_ssl"}; +DbgCtl dbg_ctl_ssl_error{"ssl.error"}; +DbgCtl dbg_ctl_ssl_error_accept{"ssl.error.accept"}; +DbgCtl dbg_ctl_ssl_error_connect{"ssl.error.connect"}; +DbgCtl dbg_ctl_ssl_error_write{"ssl.error.write"}; +DbgCtl dbg_ctl_ssl_error_read{"ssl.error.read"}; +DbgCtl dbg_ctl_ssl_shutdown{"ssl-shutdown"}; +DbgCtl dbg_ctl_ssl_alpn{"ssl_alpn"}; +DbgCtl dbg_ctl_ssl_origin_session_cache{"ssl.origin_session_cache"}; +DbgCtl dbg_ctl_proxyprotocol{"proxyprotocol"}; + /// Callback to get two locks. /// The lock for this continuation, and for the target continuation. class ContWrapper : public Continuation @@ -260,7 +274,7 @@ debug_certificate_name(const char *msg, X509_NAME *name) long len; char *ptr; len = BIO_get_mem_data(bio, &ptr); - Debug("ssl", "%s %.*s", msg, (int)len, ptr); + Dbg(dbg_ctl_ssl, "%s %.*s", msg, (int)len, ptr); } BIO_free(bio); @@ -291,18 +305,20 @@ SSLNetVConnection::_ssl_read_from_net(EThread *lthread, int64_t &ret) amount_to_read = block_write_avail; } - Debug("ssl", "amount_to_read=%" PRId64, amount_to_read); + Dbg(dbg_ctl_ssl, "amount_to_read=%" PRId64, amount_to_read); char *current_block = buf.writer()->end(); ink_release_assert(current_block != nullptr); sslErr = this->_ssl_read_buffer(current_block, amount_to_read, nread); - Debug("ssl", "nread=%" PRId64, nread); + Dbg(dbg_ctl_ssl, "nread=%" PRId64, nread); switch (sslErr) { case SSL_ERROR_NONE: - #if DEBUG - SSLDebugBufferPrint("ssl_buff", current_block, nread, "SSL Read"); + { + static DbgCtl dbg_ctl{"ssl_buff"}; + SSLDebugBufferPrint(dbg_ctl, current_block, nread, "SSL Read"); + } #endif ink_assert(nread); bytes_read += nread; @@ -313,21 +329,21 @@ SSLNetVConnection::_ssl_read_from_net(EThread *lthread, int64_t &ret) break; case SSL_ERROR_WANT_WRITE: event = SSL_WRITE_WOULD_BLOCK; - Debug("ssl.error", "SSL_ERROR_WOULD_BLOCK(write)"); + Dbg(dbg_ctl_ssl_error, "SSL_ERROR_WOULD_BLOCK(write)"); break; case SSL_ERROR_WANT_READ: event = SSL_READ_WOULD_BLOCK; - Debug("ssl.error", "SSL_ERROR_WOULD_BLOCK(read)"); + Dbg(dbg_ctl_ssl_error, "SSL_ERROR_WOULD_BLOCK(read)"); break; #ifdef SSL_ERROR_WANT_CLIENT_HELLO_CB case SSL_ERROR_WANT_CLIENT_HELLO_CB: event = SSL_READ_WOULD_BLOCK; - Debug("ssl.error", "SSL_ERROR_WOULD_BLOCK(read/client hello cb)"); + Dbg(dbg_ctl_ssl_error, "SSL_ERROR_WOULD_BLOCK(read/client hello cb)"); break; #endif case SSL_ERROR_WANT_X509_LOOKUP: event = SSL_READ_WOULD_BLOCK; - Debug("ssl.error", "SSL_ERROR_WOULD_BLOCK(read/x509 lookup)"); + Dbg(dbg_ctl_ssl_error, "SSL_ERROR_WOULD_BLOCK(read/x509 lookup)"); break; case SSL_ERROR_SYSCALL: if (nread != 0) { @@ -335,7 +351,7 @@ SSLNetVConnection::_ssl_read_from_net(EThread *lthread, int64_t &ret) SSL_INCREMENT_DYN_STAT(ssl_error_syscall); event = SSL_READ_ERROR; ret = errno; - Debug("ssl.error", "SSL_ERROR_SYSCALL, underlying IO error: %s", strerror(errno)); + Dbg(dbg_ctl_ssl_error, "SSL_ERROR_SYSCALL, underlying IO error: %s", strerror(errno)); } else { // then EOF observed, treat it as EOS event = SSL_READ_EOS; @@ -343,7 +359,7 @@ SSLNetVConnection::_ssl_read_from_net(EThread *lthread, int64_t &ret) break; case SSL_ERROR_ZERO_RETURN: event = SSL_READ_EOS; - Debug("ssl.error", "SSL_ERROR_ZERO_RETURN"); + Dbg(dbg_ctl_ssl_error, "SSL_ERROR_ZERO_RETURN"); break; case SSL_ERROR_SSL: default: { @@ -358,7 +374,7 @@ SSLNetVConnection::_ssl_read_from_net(EThread *lthread, int64_t &ret) } // while if (bytes_read > 0) { - Debug("ssl", "bytes_read=%" PRId64, bytes_read); + Dbg(dbg_ctl_ssl, "bytes_read=%" PRId64, bytes_read); s->vio.ndone += bytes_read; this->netActivity(lthread); @@ -374,7 +390,7 @@ SSLNetVConnection::_ssl_read_from_net(EThread *lthread, int64_t &ret) } else { // if( bytes_read > 0 ) #if defined(_DEBUG) if (bytes_read == 0) { - Debug("ssl", "bytes_read == 0"); + Dbg(dbg_ctl_ssl, "bytes_read == 0"); } #endif } @@ -406,8 +422,8 @@ SSLNetVConnection::read_raw_data() NET_INCREMENT_DYN_STAT(net_calls_to_read_stat); total_read += rattempted; - Debug("ssl", "read_raw_data r=%" PRId64 " rattempted=%" PRId64 " total_read=%" PRId64 " fd=%d", r, rattempted, total_read, - con.fd); + Dbg(dbg_ctl_ssl, "read_raw_data r=%" PRId64 " rattempted=%" PRId64 " total_read=%" PRId64 " fd=%d", r, rattempted, total_read, + con.fd); // last read failed or was incomplete if (r != rattempted || !b) { break; @@ -431,40 +447,40 @@ SSLNetVConnection::read_raw_data() pp_ipmap = SSLConfigParams::proxy_protocol_ip_addrs; if (this->get_is_proxy_protocol() && this->get_proxy_protocol_version() == ProxyProtocolVersion::UNDEFINED) { - Debug("proxyprotocol", "proxy protocol is enabled on this port"); + Dbg(dbg_ctl_proxyprotocol, "proxy protocol is enabled on this port"); if (pp_ipmap->count() > 0) { - Debug("proxyprotocol", "proxy protocol has a configured allowlist of trusted IPs - checking"); + Dbg(dbg_ctl_proxyprotocol, "proxy protocol has a configured allowlist of trusted IPs - checking"); // At this point, using get_remote_addr() will return the ip of the // proxy source IP, not the Proxy Protocol client ip. Since we are // checking the ip of the actual source of this connection, this is // what we want now. if (!pp_ipmap->contains(swoc::IPAddr(get_remote_addr()))) { - Debug("proxyprotocol", "Source IP is NOT in the configured allowlist of trusted IPs - closing connection"); + Dbg(dbg_ctl_proxyprotocol, "Source IP is NOT in the configured allowlist of trusted IPs - closing connection"); r = -ENOTCONN; // Need a quick close/exit here to refuse the connection!!!!!!!!! goto proxy_protocol_bypass; } else { char new_host[INET6_ADDRSTRLEN]; - Debug("proxyprotocol", "Source IP [%s] is in the trusted allowlist for proxy protocol", - ats_ip_ntop(this->get_remote_addr(), new_host, sizeof(new_host))); + Dbg(dbg_ctl_proxyprotocol, "Source IP [%s] is in the trusted allowlist for proxy protocol", + ats_ip_ntop(this->get_remote_addr(), new_host, sizeof(new_host))); } } else { - Debug("proxyprotocol", "proxy protocol DOES NOT have a configured allowlist of trusted IPs but " - "proxy protocol is enabled on this port - processing all connections"); + Dbg(dbg_ctl_proxyprotocol, "proxy protocol DOES NOT have a configured allowlist of trusted IPs but " + "proxy protocol is enabled on this port - processing all connections"); } auto const stored_r = r; if (this->has_proxy_protocol(buffer, &r)) { - Debug("proxyprotocol", "ssl has proxy protocol header"); - if (is_debug_tag_set("proxyprotocol")) { + Dbg(dbg_ctl_proxyprotocol, "ssl has proxy protocol header"); + if (dbg_ctl_proxyprotocol.on()) { IpEndpoint dst; dst.sa = *(this->get_proxy_protocol_dst_addr()); ip_port_text_buffer ipb1; ats_ip_nptop(&dst, ipb1, sizeof(ipb1)); - Debug("proxyprotocol", "ssl_has_proxy_v1, dest IP received [%s]", ipb1); + DbgPrint(dbg_ctl_proxyprotocol, "ssl_has_proxy_v1, dest IP received [%s]", ipb1); } } else { - Debug("proxyprotocol", "proxy protocol was enabled, but Proxy Protocol header was not present"); + Dbg(dbg_ctl_proxyprotocol, "proxy protocol was enabled, but Proxy Protocol header was not present"); // We are flexible with the Proxy Protocol designation. Maybe not all // connections include Proxy Protocol. Revert to the stored value of r so // we can process the bytes that are on the wire (likely a CLIENT_HELLO). @@ -490,7 +506,7 @@ SSLNetVConnection::read_raw_data() this->handShakeBioStored = 0; } - Debug("ssl", "%p read r=%" PRId64 " total=%" PRId64 " bio=%d\n", this, r, total_read, this->handShakeBioStored); + Dbg(dbg_ctl_ssl, "%p read r=%" PRId64 " total=%" PRId64 " bio=%d\n", this, r, total_read, this->handShakeBioStored); // check for errors if (r <= 0) { @@ -567,7 +583,7 @@ SSLNetVConnection::net_read_io(NetHandler *nh, EThread *lthread) if (sslClientRenegotiationAbort == true) { this->read.triggered = 0; readSignalError(nh, -ENET_SSL_FAILED); - Debug("ssl", "client renegotiation setting read signal error"); + Dbg(dbg_ctl_ssl, "client renegotiation setting read signal error"); return; } @@ -635,10 +651,10 @@ SSLNetVConnection::net_read_io(NetHandler *nh, EThread *lthread) } else if (ret == SSL_HANDSHAKE_WANT_READ || ret == SSL_HANDSHAKE_WANT_ACCEPT) { if (SSLConfigParams::ssl_handshake_timeout_in > 0) { double handshake_time = (static_cast(ink_get_hrtime() - this->get_tls_handshake_begin_time()) / 1000000000); - Debug("ssl", "ssl handshake for vc %p, took %.3f seconds, configured handshake_timer: %d", this, handshake_time, - SSLConfigParams::ssl_handshake_timeout_in); + Dbg(dbg_ctl_ssl, "ssl handshake for vc %p, took %.3f seconds, configured handshake_timer: %d", this, handshake_time, + SSLConfigParams::ssl_handshake_timeout_in); if (handshake_time > SSLConfigParams::ssl_handshake_timeout_in) { - Debug("ssl", "ssl handshake for vc %p, expired, release the connection", this); + Dbg(dbg_ctl_ssl, "ssl handshake for vc %p, expired, release the connection", this); read.triggered = 0; nh->read_ready_list.remove(this); readSignalError(nh, ETIMEDOUT); @@ -660,7 +676,7 @@ SSLNetVConnection::net_read_io(NetHandler *nh, EThread *lthread) nh->write_ready_list.remove(this); writeReschedule(nh); } else if (ret == EVENT_DONE) { - Debug("ssl", "ssl handshake EVENT_DONE ntodo=%" PRId64, ntodo); + Dbg(dbg_ctl_ssl, "ssl handshake EVENT_DONE ntodo=%" PRId64, ntodo); // If this was driven by a zero length read, signal complete when // the handshake is complete. Otherwise set up for continuing read // operations. @@ -703,7 +719,7 @@ SSLNetVConnection::net_read_io(NetHandler *nh, EThread *lthread) if (bytes > 0) { if (ret == SSL_READ_WOULD_BLOCK || ret == SSL_READ_READY) { if (readSignalAndUpdate(VC_EVENT_READ_READY) != EVENT_CONT) { - Debug("ssl", "readSignal != EVENT_CONT"); + Dbg(dbg_ctl_ssl, "readSignal != EVENT_CONT"); return; } } @@ -717,7 +733,7 @@ SSLNetVConnection::net_read_io(NetHandler *nh, EThread *lthread) case SSL_WRITE_WOULD_BLOCK: case SSL_READ_WOULD_BLOCK: if (lock.get_mutex() != s->vio.mutex.get()) { - Debug("ssl", "mutex switched"); + Dbg(dbg_ctl_ssl, "mutex switched"); if (ret == SSL_READ_WOULD_BLOCK) { readReschedule(nh); } else { @@ -729,7 +745,7 @@ SSLNetVConnection::net_read_io(NetHandler *nh, EThread *lthread) // we will need to be retriggered to read from this socket again read.triggered = 0; nh->read_ready_list.remove(this); - Debug("ssl", "read finished - would block"); + Dbg(dbg_ctl_ssl, "read finished - would block"); break; case SSL_READ_EOS: @@ -740,19 +756,19 @@ SSLNetVConnection::net_read_io(NetHandler *nh, EThread *lthread) readSignalDone(VC_EVENT_EOS, nh); if (bytes > 0) { - Debug("ssl", "read finished - EOS"); + Dbg(dbg_ctl_ssl, "read finished - EOS"); } else { - Debug("ssl", "read finished - 0 useful bytes read, bytes used by SSL layer"); + Dbg(dbg_ctl_ssl, "read finished - 0 useful bytes read, bytes used by SSL layer"); } break; case SSL_READ_COMPLETE: readSignalDone(VC_EVENT_READ_COMPLETE, nh); - Debug("ssl", "read finished - signal done"); + Dbg(dbg_ctl_ssl, "read finished - signal done"); break; case SSL_READ_ERROR: this->read.triggered = 0; readSignalError(nh, (ssl_read_errno) ? ssl_read_errno : -ENET_SSL_FAILED); - Debug("ssl", "read finished - read error"); + Dbg(dbg_ctl_ssl, "read finished - read error"); break; } } @@ -776,14 +792,15 @@ SSLNetVConnection::load_buffer_and_write(int64_t towrite, MIOBufferAccessor &buf // reset sslTotalBytesSent upon inactivity for SSL_DEF_TLS_RECORD_MSEC_THRESHOLD sslTotalBytesSent = 0; } - Debug("ssl", "now=%" PRId64 " lastwrite=%" PRId64 " msec_since_last_write=%d", now, sslLastWriteTime, msec_since_last_write); + Dbg(dbg_ctl_ssl, "now=%" PRId64 " lastwrite=%" PRId64 " msec_since_last_write=%d", now, sslLastWriteTime, + msec_since_last_write); } if (HttpProxyPort::TRANSPORT_BLIND_TUNNEL == this->attributes) { return this->super::load_buffer_and_write(towrite, buf, total_written, needs); } - Debug("ssl", "towrite=%" PRId64, towrite); + Dbg(dbg_ctl_ssl, "towrite=%" PRId64, towrite); do { // What is remaining left in the next block? @@ -829,7 +846,7 @@ SSLNetVConnection::load_buffer_and_write(int64_t towrite, MIOBufferAccessor &buf try_to_write = l; num_really_written = 0; - Debug("v_ssl", "b=%p l=%" PRId64, current_block, l); + Dbg(dbg_ctl_v_ssl, "b=%p l=%" PRId64, current_block, l); err = this->_ssl_write_buffer(current_block, l, num_really_written); // We wrote all that we thought we should @@ -838,8 +855,8 @@ SSLNetVConnection::load_buffer_and_write(int64_t towrite, MIOBufferAccessor &buf buf.reader()->consume(num_really_written); } - Debug("ssl", "try_to_write=%" PRId64 " written=%" PRId64 " total_written=%" PRId64, try_to_write, num_really_written, - total_written); + Dbg(dbg_ctl_ssl, "try_to_write=%" PRId64 " written=%" PRId64 " total_written=%" PRId64, try_to_write, num_really_written, + total_written); NET_INCREMENT_DYN_STAT(net_calls_to_write_stat); } while (num_really_written == try_to_write && total_written < towrite); @@ -853,12 +870,12 @@ SSLNetVConnection::load_buffer_and_write(int64_t towrite, MIOBufferAccessor &buf } else { switch (err) { case SSL_ERROR_NONE: - Debug("ssl", "SSL_write-SSL_ERROR_NONE"); + Dbg(dbg_ctl_ssl, "SSL_write-SSL_ERROR_NONE"); break; case SSL_ERROR_WANT_READ: needs |= EVENTIO_READ; num_really_written = -EAGAIN; - Debug("ssl.error", "SSL_write-SSL_ERROR_WANT_READ"); + Dbg(dbg_ctl_ssl_error, "SSL_write-SSL_ERROR_WANT_READ"); break; case SSL_ERROR_WANT_WRITE: #ifdef SSL_ERROR_WANT_CLIENT_HELLO_CB @@ -870,7 +887,7 @@ SSLNetVConnection::load_buffer_and_write(int64_t towrite, MIOBufferAccessor &buf } needs |= EVENTIO_WRITE; num_really_written = -EAGAIN; - Debug("ssl.error", "SSL_write-SSL_ERROR_WANT_WRITE"); + Dbg(dbg_ctl_ssl_error, "SSL_write-SSL_ERROR_WANT_WRITE"); break; } case SSL_ERROR_SYSCALL: @@ -878,12 +895,12 @@ SSLNetVConnection::load_buffer_and_write(int64_t towrite, MIOBufferAccessor &buf // we do with SSL_ERROR_SSL below, to indicate a connection error. num_really_written = -EPIPE; SSL_INCREMENT_DYN_STAT(ssl_error_syscall); - Debug("ssl.error", "SSL_write-SSL_ERROR_SYSCALL"); + Dbg(dbg_ctl_ssl_error, "SSL_write-SSL_ERROR_SYSCALL"); break; // end of stream case SSL_ERROR_ZERO_RETURN: num_really_written = -errno; - Debug("ssl.error", "SSL_write-SSL_ERROR_ZERO_RETURN"); + Dbg(dbg_ctl_ssl_error, "SSL_write-SSL_ERROR_ZERO_RETURN"); break; case SSL_ERROR_SSL: default: { @@ -919,13 +936,13 @@ SSLNetVConnection::do_io_close(int lerrno) if (getSSLHandShakeComplete()) { int shutdown_mode = SSL_get_shutdown(ssl); - Debug("ssl-shutdown", "previous shutdown state 0x%x", shutdown_mode); + Dbg(dbg_ctl_ssl_shutdown, "previous shutdown state 0x%x", shutdown_mode); int new_shutdown_mode = shutdown_mode | SSL_RECEIVED_SHUTDOWN; if (new_shutdown_mode != shutdown_mode) { // We do not need to sit around and wait for the client's close-notify if // they have not already sent it. We will still be standards compliant - Debug("ssl-shutdown", "new SSL_set_shutdown 0x%x", new_shutdown_mode); + Dbg(dbg_ctl_ssl_shutdown, "new SSL_set_shutdown 0x%x", new_shutdown_mode); SSL_set_shutdown(ssl, new_shutdown_mode); } @@ -944,12 +961,12 @@ SSLNetVConnection::do_io_close(int lerrno) if (do_shutdown) { // Send the close-notify int ret = SSL_shutdown(ssl); - Debug("ssl-shutdown", "SSL_shutdown %s", (ret) ? "success" : "failed"); + Dbg(dbg_ctl_ssl_shutdown, "SSL_shutdown %s", (ret) ? "success" : "failed"); } else { // Request a quiet shutdown to OpenSSL SSL_set_quiet_shutdown(ssl, 1); SSL_set_shutdown(ssl, SSL_RECEIVED_SHUTDOWN | SSL_SENT_SHUTDOWN); - Debug("ssl-shutdown", "Enable quiet shutdown"); + Dbg(dbg_ctl_ssl_shutdown, "Enable quiet shutdown"); } } } @@ -1038,7 +1055,7 @@ int SSLNetVConnection::sslStartHandShake(int event, int &err) { if (TSSystemState::is_ssl_handshaking_stopped()) { - Debug("ssl", "Stopping handshake due to server shutting down."); + Dbg(dbg_ctl_ssl, "Stopping handshake due to server shutting down."); return EVENT_ERROR; } if (this->get_tls_handshake_begin_time() == 0) { @@ -1054,22 +1071,22 @@ SSLNetVConnection::sslStartHandShake(int event, int &err) IpEndpoint dst; int namelen = sizeof(dst); if (0 != safe_getsockname(this->get_socket(), &dst.sa, &namelen)) { - Debug("ssl", "Failed to get dest ip, errno = [%d]", errno); + Dbg(dbg_ctl_ssl, "Failed to get dest ip, errno = [%d]", errno); return EVENT_ERROR; } SSLCertContext *cc = lookup->find(dst); - if (is_debug_tag_set("ssl")) { + if (dbg_ctl_ssl.on()) { IpEndpoint src; ip_port_text_buffer ipb1, ipb2; int ip_len = sizeof(src); if (0 != safe_getpeername(this->get_socket(), &src.sa, &ip_len)) { - Debug("ssl", "Failed to get src ip, errno = [%d]", errno); + DbgPrint(dbg_ctl_ssl, "Failed to get src ip, errno = [%d]", errno); return EVENT_ERROR; } ats_ip_nptop(&dst, ipb1, sizeof(ipb1)); ats_ip_nptop(&src, ipb2, sizeof(ipb2)); - Debug("ssl", "IP context is %p for [%s] -> [%s], default context %p", cc, ipb2, ipb1, lookup->defaultContext()); + DbgPrint(dbg_ctl_ssl, "IP context is %p for [%s] -> [%s], default context %p", cc, ipb2, ipb1, lookup->defaultContext()); } // Escape if this is marked to be a tunnel. @@ -1118,7 +1135,7 @@ SSLNetVConnection::sslStartHandShake(int event, int &err) SSL_CTX *clientCTX = nullptr; // First Look to see if there are override parameters - Debug("ssl", "Checking for outbound client cert override [%p]", options.ssl_client_cert_name.get()); + Dbg(dbg_ctl_ssl, "Checking for outbound client cert override [%p]", options.ssl_client_cert_name.get()); if (options.ssl_client_cert_name) { std::string certFilePath; std::string keyFilePath; @@ -1133,9 +1150,9 @@ SSLNetVConnection::sslStartHandShake(int event, int &err) if (options.ssl_client_ca_cert_name) { caCertFilePath = Layout::get()->relative_to(params->clientCACertPath, options.ssl_client_ca_cert_name); } - Debug("ssl", "Using outbound client cert `%s'", options.ssl_client_cert_name.get()); + Dbg(dbg_ctl_ssl, "Using outbound client cert `%s'", options.ssl_client_cert_name.get()); } else { - Debug("ssl", "Clearing outbound client cert"); + Dbg(dbg_ctl_ssl, "Clearing outbound client cert"); } sharedCTX = params->getCTX(certFilePath, keyFilePath, caCertFilePath.empty() ? params->clientCACertFilename : caCertFilePath.c_str(), @@ -1198,9 +1215,9 @@ SSLNetVConnection::sslStartHandShake(int event, int &err) ats_scoped_str &tlsext_host_name = this->options.sni_hostname ? this->options.sni_hostname : this->options.sni_servername; if (tlsext_host_name) { if (SSL_set_tlsext_host_name(this->ssl, tlsext_host_name)) { - Debug("ssl", "using SNI name '%s' for client handshake", tlsext_host_name.get()); + Dbg(dbg_ctl_ssl, "using SNI name '%s' for client handshake", tlsext_host_name.get()); } else { - Debug("ssl.error", "failed to set SNI name '%s' for client handshake", tlsext_host_name.get()); + Dbg(dbg_ctl_ssl_error, "failed to set SNI name '%s' for client handshake", tlsext_host_name.get()); SSL_INCREMENT_DYN_STAT(ssl_sni_name_set_failure); } } @@ -1210,8 +1227,8 @@ SSLNetVConnection::sslStartHandShake(int event, int &err) if (int res = SSL_set_alpn_protos(this->ssl, reinterpret_cast(this->options.alpn_protos.data()), this->options.alpn_protos.size()); res != 0) { - Debug("ssl.error", "failed to set ALPN '%.*s' for client handshake", static_cast(this->options.alpn_protos.size()), - this->options.alpn_protos.data()); + Dbg(dbg_ctl_ssl_error, "failed to set ALPN '%.*s' for client handshake", + static_cast(this->options.alpn_protos.size()), this->options.alpn_protos.data()); } } } @@ -1237,7 +1254,7 @@ SSLNetVConnection::sslServerHandShakeEvent(int &err) if (sslHandshakeHookState == HANDSHAKE_HOOKS_PRE) { SSL_INCREMENT_DYN_STAT(ssl_total_attempts_handshake_count_in_stat); if (!curHook) { - Debug("ssl", "Initialize preaccept curHook from NULL"); + Dbg(dbg_ctl_ssl, "Initialize preaccept curHook from NULL"); curHook = ssl_hooks->get(TSSslHookInternalID(TS_VCONN_START_HOOK)); } else { curHook = curHook->next(); @@ -1272,7 +1289,7 @@ SSLNetVConnection::sslServerHandShakeEvent(int &err) return EVENT_DONE; } - Debug("ssl", "Go on with the handshake state=%s", get_ssl_handshake_hook_state_name(sslHandshakeHookState)); + Dbg(dbg_ctl_ssl, "Go on with the handshake state=%s", get_ssl_handshake_hook_state_name(sslHandshakeHookState)); // All the pre-accept hooks have completed, proceed with the actual accept. if (this->handShakeReader) { @@ -1285,7 +1302,7 @@ SSLNetVConnection::sslServerHandShakeEvent(int &err) } #endif - Debug("ssl", "%p first read\n", this); + Dbg(dbg_ctl_ssl, "%p first read\n", this); // Read from socket to fill in the BIO buffer with the // raw handshake data before calling the ssl accept calls. int retval = this->read_raw_data(); @@ -1355,14 +1372,14 @@ SSLNetVConnection::sslServerHandShakeEvent(int &err) switch (ssl_error) { case SSL_ERROR_NONE: - if (is_debug_tag_set("ssl")) { + if (dbg_ctl_ssl.on()) { #ifdef OPENSSL_IS_OPENSSL3 X509 *cert = SSL_get1_peer_certificate(ssl); #else X509 *cert = SSL_get_peer_certificate(ssl); #endif - Debug("ssl", "SSL server handshake completed successfully"); + DbgPrint(dbg_ctl_ssl, "SSL server handshake completed successfully"); if (cert) { debug_certificate_name("client certificate subject CN is", X509_get_subject_name(cert)); debug_certificate_name("client certificate issuer CN is", X509_get_issuer_name(cert)); @@ -1406,9 +1423,9 @@ SSLNetVConnection::sslServerHandShakeEvent(int &err) } this->set_negotiated_protocol_id({reinterpret_cast(proto), static_cast(len)}); - Debug("ssl", "Origin selected next protocol '%.*s'", len, proto); + Dbg(dbg_ctl_ssl, "Origin selected next protocol '%.*s'", len, proto); } else { - Debug("ssl", "Origin did not select a next protocol"); + Dbg(dbg_ctl_ssl, "Origin did not select a next protocol"); } } @@ -1528,7 +1545,7 @@ SSLNetVConnection::sslClientHandShakeEvent(int &err) if (sslHandshakeHookState == HANDSHAKE_HOOKS_OUTBOUND_PRE) { SSL_INCREMENT_DYN_STAT(ssl_total_attempts_handshake_count_out_stat); if (!curHook) { - Debug("ssl", "Initialize outbound connect curHook from NULL"); + Dbg(dbg_ctl_ssl, "Initialize outbound connect curHook from NULL"); curHook = ssl_hooks->get(TSSslHookInternalID(TS_VCONN_OUTBOUND_START_HOOK)); } else { curHook = curHook->next(); @@ -1544,14 +1561,14 @@ SSLNetVConnection::sslClientHandShakeEvent(int &err) ssl_error = this->_ssl_connect(); switch (ssl_error) { case SSL_ERROR_NONE: - if (is_debug_tag_set("ssl")) { + if (dbg_ctl_ssl.on()) { #ifdef OPENSSL_IS_OPENSSL3 X509 *cert = SSL_get1_peer_certificate(ssl); #else X509 *cert = SSL_get_peer_certificate(ssl); #endif - Debug("ssl", "SSL client handshake completed successfully"); + DbgPrint(dbg_ctl_ssl, "SSL client handshake completed successfully"); if (cert) { debug_certificate_name("server certificate subject CN is", X509_get_subject_name(cert)); @@ -1567,7 +1584,7 @@ SSLNetVConnection::sslClientHandShakeEvent(int &err) if (len == 0) { SSL_get0_next_proto_negotiated(ssl, &proto, &len); } - Debug("ssl_alpn", "Negotiated ALPN: %.*s", len, proto); + Dbg(dbg_ctl_ssl_alpn, "Negotiated ALPN: %.*s", len, proto); this->set_negotiated_protocol_id({reinterpret_cast(proto), static_cast(len)}); } @@ -1582,19 +1599,19 @@ SSLNetVConnection::sslClientHandShakeEvent(int &err) return EVENT_DONE; case SSL_ERROR_WANT_WRITE: - Debug("ssl.error", "SSL_ERROR_WANT_WRITE"); + Dbg(dbg_ctl_ssl_error, "SSL_ERROR_WANT_WRITE"); return SSL_HANDSHAKE_WANT_WRITE; case SSL_ERROR_WANT_READ: - Debug("ssl.error", "SSL_ERROR_WANT_READ"); + Dbg(dbg_ctl_ssl_error, "SSL_ERROR_WANT_READ"); return SSL_HANDSHAKE_WANT_READ; #ifdef SSL_ERROR_WANT_CLIENT_HELLO_CB case SSL_ERROR_WANT_CLIENT_HELLO_CB: - Debug("ssl.error", "SSL_ERROR_WANT_CLIENT_HELLO_CB"); + Dbg(dbg_ctl_ssl_error, "SSL_ERROR_WANT_CLIENT_HELLO_CB"); break; #endif case SSL_ERROR_WANT_X509_LOOKUP: - Debug("ssl.error", "SSL_ERROR_WANT_X509_LOOKUP"); + Dbg(dbg_ctl_ssl_error, "SSL_ERROR_WANT_X509_LOOKUP"); break; case SSL_ERROR_WANT_ACCEPT: @@ -1604,13 +1621,13 @@ SSLNetVConnection::sslClientHandShakeEvent(int &err) break; case SSL_ERROR_ZERO_RETURN: - Debug("ssl.error", "EOS"); + Dbg(dbg_ctl_ssl_error, "EOS"); return EVENT_ERROR; case SSL_ERROR_SYSCALL: err = errno; SSL_INCREMENT_DYN_STAT(ssl_error_syscall); - Debug("ssl.error", "syscall"); + Dbg(dbg_ctl_ssl_error, "syscall"); return EVENT_ERROR; break; @@ -1622,14 +1639,14 @@ SSLNetVConnection::sslClientHandShakeEvent(int &err) ERR_error_string_n(e, buf, sizeof(buf)); // FIXME -- This triggers a retry on cases of cert validation errors.... SSL_CLR_ERR_INCR_DYN_STAT(this, ssl_error_ssl, "SSL_ERROR_SSL errno=%d", errno); - Debug("ssl.error", "SSL_ERROR_SSL"); + Dbg(dbg_ctl_ssl_error, "SSL_ERROR_SSL"); if (e) { if (this->options.sni_servername) { - Debug("ssl.error", "SSL connection failed for '%s': %s", this->options.sni_servername.get(), buf); + Dbg(dbg_ctl_ssl_error, "SSL connection failed for '%s': %s", this->options.sni_servername.get(), buf); } else { char buff[INET6_ADDRSTRLEN]; ats_ip_ntop(this->get_remote_addr(), buff, INET6_ADDRSTRLEN); - Debug("ssl.error", "SSL connection failed for '%s': %s", buff, buf); + Dbg(dbg_ctl_ssl_error, "SSL connection failed for '%s': %s", buff, buf); } } return EVENT_ERROR; @@ -1641,7 +1658,7 @@ SSLNetVConnection::sslClientHandShakeEvent(int &err) void SSLNetVConnection::reenable(NetHandler *nh, int event) { - Debug("ssl", "Handshake reenable from state=%s", get_ssl_handshake_hook_state_name(sslHandshakeHookState)); + Dbg(dbg_ctl_ssl, "Handshake reenable from state=%s", get_ssl_handshake_hook_state_name(sslHandshakeHookState)); // Mark as error to stop the Handshake if (event == TS_EVENT_ERROR) { @@ -1677,7 +1694,7 @@ SSLNetVConnection::reenable(NetHandler *nh, int event) // here in the reenable. if (curHook != nullptr) { curHook = curHook->next(); - Debug("ssl", "iterate from reenable curHook=%p", curHook); + Dbg(dbg_ctl_ssl, "iterate from reenable curHook=%p", curHook); } if (curHook != nullptr) { // Invoke the hook and return, wait for next reenable @@ -1693,11 +1710,11 @@ SSLNetVConnection::reenable(NetHandler *nh, int event) } else if (sslHandshakeHookState == HANDSHAKE_HOOKS_SNI) { curHook->invoke(TS_EVENT_SSL_SERVERNAME, this); } else if (sslHandshakeHookState == HANDSHAKE_HOOKS_PRE) { - Debug("ssl", "Reenable preaccept"); + Dbg(dbg_ctl_ssl, "Reenable preaccept"); sslHandshakeHookState = HANDSHAKE_HOOKS_PRE_INVOKE; ContWrapper::wrap(nh->mutex.get(), curHook->m_cont, TS_EVENT_VCONN_START, this); } else if (sslHandshakeHookState == HANDSHAKE_HOOKS_OUTBOUND_PRE) { - Debug("ssl", "Reenable outbound connect"); + Dbg(dbg_ctl_ssl, "Reenable outbound connect"); sslHandshakeHookState = HANDSHAKE_HOOKS_OUTBOUND_PRE_INVOKE; ContWrapper::wrap(nh->mutex.get(), curHook->m_cont, TS_EVENT_VCONN_OUTBOUND_START, this); } else if (sslHandshakeHookState == HANDSHAKE_HOOKS_DONE) { @@ -1707,7 +1724,7 @@ SSLNetVConnection::reenable(NetHandler *nh, int event) ContWrapper::wrap(nh->mutex.get(), curHook->m_cont, TS_EVENT_VCONN_CLOSE, this); } } else if (sslHandshakeHookState == HANDSHAKE_HOOKS_VERIFY_SERVER) { - Debug("ssl", "ServerVerify"); + Dbg(dbg_ctl_ssl, "ServerVerify"); ContWrapper::wrap(nh->mutex.get(), curHook->m_cont, TS_EVENT_SSL_VERIFY_SERVER, this); } return; @@ -1746,7 +1763,7 @@ SSLNetVConnection::reenable(NetHandler *nh, int event) default: break; } - Debug("ssl", "iterate from reenable curHook=%p %s", curHook, get_ssl_handshake_hook_state_name(sslHandshakeHookState)); + Dbg(dbg_ctl_ssl, "iterate from reenable curHook=%p %s", curHook, get_ssl_handshake_hook_state_name(sslHandshakeHookState)); } this->readReschedule(nh); @@ -1759,7 +1776,7 @@ SSLNetVConnection::callHooks(TSEvent eventId) ink_assert(eventId == TS_EVENT_SSL_CLIENT_HELLO || eventId == TS_EVENT_SSL_CERT || eventId == TS_EVENT_SSL_SERVERNAME || eventId == TS_EVENT_SSL_VERIFY_SERVER || eventId == TS_EVENT_SSL_VERIFY_CLIENT || eventId == TS_EVENT_VCONN_CLOSE || eventId == TS_EVENT_VCONN_OUTBOUND_CLOSE); - Debug("ssl", "sslHandshakeHookState=%s eventID=%d", get_ssl_handshake_hook_state_name(this->sslHandshakeHookState), eventId); + Dbg(dbg_ctl_ssl, "sslHandshakeHookState=%s eventID=%d", get_ssl_handshake_hook_state_name(this->sslHandshakeHookState), eventId); // Move state if it is appropriate if (eventId == TS_EVENT_VCONN_CLOSE) { @@ -1877,7 +1894,7 @@ SSLNetVConnection::callHooks(TSEvent eventId) return true; } - Debug("ssl", "iterated to curHook=%p", curHook); + Dbg(dbg_ctl_ssl, "iterated to curHook=%p", curHook); bool reenabled = true; @@ -1897,7 +1914,7 @@ SSLNetVConnection::callHooks(TSEvent eventId) reenabled = (this->sslHandshakeHookState != HANDSHAKE_HOOKS_CERT_INVOKE && this->sslHandshakeHookState != HANDSHAKE_HOOKS_PRE_INVOKE && this->sslHandshakeHookState != HANDSHAKE_HOOKS_CLIENT_HELLO_INVOKE); - Debug("ssl", "Called hook on state=%s reenabled=%d", get_ssl_handshake_hook_state_name(sslHandshakeHookState), reenabled); + Dbg(dbg_ctl_ssl, "Called hook on state=%s reenabled=%d", get_ssl_handshake_hook_state_name(sslHandshakeHookState), reenabled); } return reenabled; @@ -1941,7 +1958,7 @@ SSLNetVConnection::increment_ssl_version_metric(int version) const break; #endif default: - Debug("ssl", "Unrecognized SSL version %d", version); + Dbg(dbg_ctl_ssl, "Unrecognized SSL version %d", version); break; } } @@ -2067,17 +2084,18 @@ SSLNetVConnection::_lookupContextByIP() ip_port_text_buffer ipb1; ats_ip_nptop(&ip, ipb1, sizeof(ipb1)); cc = lookup->find(ip); - if (is_debug_tag_set("proxyprotocol")) { + if (dbg_ctl_proxyprotocol.on()) { IpEndpoint src; ip_port_text_buffer ipb2; int ip_len = sizeof(src); if (0 != safe_getpeername(this->get_socket(), &src.sa, &ip_len)) { - Debug("proxyprotocol", "Failed to get src ip, errno = [%d]", errno); + DbgPrint(dbg_ctl_proxyprotocol, "Failed to get src ip, errno = [%d]", errno); return nullptr; } ats_ip_nptop(&src, ipb2, sizeof(ipb2)); - Debug("proxyprotocol", "IP context is %p for [%s] -> [%s], default context %p", cc, ipb2, ipb1, lookup->defaultContext()); + DbgPrint(dbg_ctl_proxyprotocol, "IP context is %p for [%s] -> [%s], default context %p", cc, ipb2, ipb1, + lookup->defaultContext()); } } else if (0 == safe_getsockname(this->get_socket(), &ip.sa, &namelen)) { cc = lookup->find(ip); @@ -2199,7 +2217,7 @@ SSLNetVConnection::_ssl_accept() #endif if (had_error_on_reading_early_data) { - Debug("ssl_early_data", "Error on reading early data: %d", ret); + Dbg(dbg_ctl_ssl_early_data, "Error on reading early data: %d", ret); block->free(); break; } else { @@ -2212,9 +2230,9 @@ SSLNetVConnection::_ssl_accept() this->_early_data_buf->append_block(block); SSL_INCREMENT_DYN_STAT(ssl_early_data_received_count); - if (is_debug_tag_set("ssl_early_data_show_received")) { + if (dbg_ctl_ssl_early_data_show_received.on()) { std::string early_data_str(reinterpret_cast(block->buf()), nread); - Debug("ssl_early_data_show_received", "Early data buffer: \n%s", early_data_str.c_str()); + DbgPrint(dbg_ctl_ssl_early_data_show_received, "Early data buffer: \n%s", early_data_str.c_str()); } } else { block->free(); @@ -2222,16 +2240,16 @@ SSLNetVConnection::_ssl_accept() if (finished_reading_early_data) { this->_early_data_finish = true; - Debug("ssl_early_data", "SSL_READ_EARLY_DATA_FINISH: size = %lu", nread); + Dbg(dbg_ctl_ssl_early_data, "SSL_READ_EARLY_DATA_FINISH: size = %lu", nread); if (this->_early_data_reader == nullptr || this->_early_data_reader->read_avail() == 0) { - Debug("ssl_early_data", "no data in early data buffer"); + Dbg(dbg_ctl_ssl_early_data, "no data in early data buffer"); ERR_clear_error(); ret = SSL_accept(ssl); } break; } - Debug("ssl_early_data", "SSL_READ_EARLY_DATA_SUCCESS: size = %lu", nread); + Dbg(dbg_ctl_ssl_early_data, "SSL_READ_EARLY_DATA_SUCCESS: size = %lu", nread); } } } else { @@ -2245,11 +2263,11 @@ SSLNetVConnection::_ssl_accept() return SSL_ERROR_NONE; } ssl_error = SSL_get_error(ssl, ret); - if (ssl_error == SSL_ERROR_SSL && is_debug_tag_set("ssl.error.accept")) { + if (ssl_error == SSL_ERROR_SSL && dbg_ctl_ssl_error_accept.on()) { char buf[512]; unsigned long e = ERR_peek_last_error(); ERR_error_string_n(e, buf, sizeof(buf)); - Debug("ssl.error.accept", "SSL accept returned %d, ssl_error=%d, ERR_get_error=%ld (%s)", ret, ssl_error, e, buf); + DbgPrint(dbg_ctl_ssl_error_accept, "SSL accept returned %d, ssl_error=%d, ERR_get_error=%ld (%s)", ret, ssl_error, e, buf); } return ssl_error; @@ -2269,7 +2287,7 @@ SSLNetVConnection::_ssl_connect() std::string lookup_key; swoc::bwprint(lookup_key, "{}:{}:{}", sni_addr.c_str(), SSL_get_SSL_CTX(ssl), get_verify_str(ssl)); - Debug("ssl.origin_session_cache", "origin session cache lookup key = %s", lookup_key.c_str()); + Dbg(dbg_ctl_ssl_origin_session_cache, "origin session cache lookup key = %s", lookup_key.c_str()); std::shared_ptr shared_sess = this->getOriginSession(ssl, lookup_key); @@ -2286,22 +2304,18 @@ SSLNetVConnection::_ssl_connect() if (ret > 0) { if (SSL_session_reused(ssl)) { SSL_INCREMENT_DYN_STAT(ssl_origin_session_reused_count); - if (is_debug_tag_set("ssl.origin_session_cache")) { - Debug("ssl.origin_session_cache", "reused session to origin server"); - } + Dbg(dbg_ctl_ssl_origin_session_cache, "reused session to origin server"); } else { - if (is_debug_tag_set("ssl.origin_session_cache")) { - Debug("ssl.origin_session_cache", "new session to origin server"); - } + Dbg(dbg_ctl_ssl_origin_session_cache, "new session to origin server"); } return SSL_ERROR_NONE; } int ssl_error = SSL_get_error(ssl, ret); - if (ssl_error == SSL_ERROR_SSL && is_debug_tag_set("ssl.error.connect")) { + if (ssl_error == SSL_ERROR_SSL && dbg_ctl_ssl_error_connect.on()) { char buf[512]; unsigned long e = ERR_peek_last_error(); ERR_error_string_n(e, buf, sizeof(buf)); - Debug("ssl.error.connect", "SSL connect returned %d, ssl_error=%d, ERR_get_error=%ld (%s)", ret, ssl_error, e, buf); + DbgPrint(dbg_ctl_ssl_error_connect, "SSL connect returned %d, ssl_error=%d, ERR_get_error=%ld (%s)", ret, ssl_error, e, buf); } return ssl_error; @@ -2353,11 +2367,11 @@ SSLNetVConnection::_ssl_write_buffer(const void *buf, int64_t nbytes, int64_t &n return SSL_ERROR_NONE; } int ssl_error = SSL_get_error(ssl, ret); - if (ssl_error == SSL_ERROR_SSL && is_debug_tag_set("ssl.error.write")) { + if (ssl_error == SSL_ERROR_SSL && dbg_ctl_ssl_error_write.on()) { char tempbuf[512]; unsigned long e = ERR_peek_last_error(); ERR_error_string_n(e, tempbuf, sizeof(tempbuf)); - Debug("ssl.error.write", "SSL write returned %d, ssl_error=%d, ERR_get_error=%ld (%s)", ret, ssl_error, e, tempbuf); + DbgPrint(dbg_ctl_ssl_error_write, "SSL write returned %d, ssl_error=%d, ERR_get_error=%ld (%s)", ret, ssl_error, e, tempbuf); } return ssl_error; } @@ -2380,7 +2394,7 @@ SSLNetVConnection::_ssl_read_buffer(void *buf, int64_t nbytes, int64_t &nread) } if (early_data_len > 0) { - Debug("ssl_early_data", "Reading from early data buffer."); + Dbg(dbg_ctl_ssl_early_data, "Reading from early data buffer."); this->_increment_early_data_len(this->_early_data_reader->read(buf, nbytes < early_data_len ? nbytes : early_data_len)); if (nbytes < early_data_len) { @@ -2398,7 +2412,7 @@ SSLNetVConnection::_ssl_read_buffer(void *buf, int64_t nbytes, int64_t &nread) if (early_data_enabled && !this->_early_data_finish) { bool had_error_on_reading_early_data = false; bool finished_reading_early_data = false; - Debug("ssl_early_data", "More early data to read."); + Dbg(dbg_ctl_ssl_early_data, "More early data to read."); ssl_error_t ssl_error = SSL_ERROR_NONE; int ret; #if HAVE_SSL_READ_EARLY_DATA @@ -2437,22 +2451,22 @@ SSLNetVConnection::_ssl_read_buffer(void *buf, int64_t nbytes, int64_t &nread) #endif if (had_error_on_reading_early_data) { - Debug("ssl_early_data", "Error reading early data: %s", ERR_error_string(ERR_get_error(), nullptr)); + Dbg(dbg_ctl_ssl_early_data, "Error reading early data: %s", ERR_error_string(ERR_get_error(), nullptr)); } else { if ((nread = read_bytes) > 0) { this->_increment_early_data_len(read_bytes); SSL_INCREMENT_DYN_STAT(ssl_early_data_received_count); - if (is_debug_tag_set("ssl_early_data_show_received")) { + if (dbg_ctl_ssl_early_data_show_received.on()) { std::string early_data_str(reinterpret_cast(buf), nread); - Debug("ssl_early_data_show_received", "Early data buffer: \n%s", early_data_str.c_str()); + DbgPrint(dbg_ctl_ssl_early_data_show_received, "Early data buffer: \n%s", early_data_str.c_str()); } } if (finished_reading_early_data) { this->_early_data_finish = true; - Debug("ssl_early_data", "SSL_READ_EARLY_DATA_FINISH: size = %" PRId64, nread); + Dbg(dbg_ctl_ssl_early_data, "SSL_READ_EARLY_DATA_FINISH: size = %" PRId64, nread); } else { - Debug("ssl_early_data", "SSL_READ_EARLY_DATA_SUCCESS: size = %" PRId64, nread); + Dbg(dbg_ctl_ssl_early_data, "SSL_READ_EARLY_DATA_SUCCESS: size = %" PRId64, nread); } } return ssl_error; @@ -2466,11 +2480,11 @@ SSLNetVConnection::_ssl_read_buffer(void *buf, int64_t nbytes, int64_t &nread) return SSL_ERROR_NONE; } int ssl_error = SSL_get_error(ssl, ret); - if (ssl_error == SSL_ERROR_SSL && is_debug_tag_set("ssl.error.read")) { + if (ssl_error == SSL_ERROR_SSL && dbg_ctl_ssl_error_read.on()) { char tempbuf[512]; unsigned long e = ERR_peek_last_error(); ERR_error_string_n(e, tempbuf, sizeof(tempbuf)); - Debug("ssl.error.read", "SSL read returned %d, ssl_error=%d, ERR_get_error=%ld (%s)", ret, ssl_error, e, tempbuf); + DbgPrint(dbg_ctl_ssl_error_read, "SSL read returned %d, ssl_error=%d, ERR_get_error=%ld (%s)", ret, ssl_error, e, tempbuf); } return ssl_error; @@ -2525,19 +2539,19 @@ SSLNetVConnection::update_early_data_config(uint32_t max_early_data, uint32_t re bool ret1 = false; bool ret2 = false; if ((ret1 = SSL_set_max_early_data(ssl, max_early_data)) == 1) { - Debug("ssl_early_data", "SSL_set_max_early_data %u: success", max_early_data); + Dbg(dbg_ctl_ssl_early_data, "SSL_set_max_early_data %u: success", max_early_data); } else { - Debug("ssl_early_data", "SSL_set_max_early_data %u: failed", max_early_data); + Dbg(dbg_ctl_ssl_early_data, "SSL_set_max_early_data %u: failed", max_early_data); } if ((ret2 = SSL_set_recv_max_early_data(ssl, recv_max_early_data)) == 1) { - Debug("ssl_early_data", "SSL_set_recv_max_early_data %u: success", recv_max_early_data); + Dbg(dbg_ctl_ssl_early_data, "SSL_set_recv_max_early_data %u: success", recv_max_early_data); } else { - Debug("ssl_early_data", "SSL_set_recv_max_early_data %u: failed", recv_max_early_data); + Dbg(dbg_ctl_ssl_early_data, "SSL_set_recv_max_early_data %u: failed", recv_max_early_data); } if (ret1 && ret2) { - Debug("ssl_early_data", "Must disable anti-replay if 0-rtt is enabled."); + Dbg(dbg_ctl_ssl_early_data, "Must disable anti-replay if 0-rtt is enabled."); SSL_set_options(ssl, SSL_OP_NO_ANTI_REPLAY); } #else diff --git a/iocore/net/SSLSNIConfig.cc b/iocore/net/SSLSNIConfig.cc index 2cbe7c2dcfc..e3aada4dc60 100644 --- a/iocore/net/SSLSNIConfig.cc +++ b/iocore/net/SSLSNIConfig.cc @@ -50,6 +50,9 @@ static constexpr int OVECSIZE{30}; +static DbgCtl dbg_ctl_ssl{"ssl"}; +static DbgCtl dbg_ctl_ssl_sni{"ssl_sni"}; + //// // NamedElement // @@ -80,7 +83,7 @@ NamedElement::set_glob_name(std::string name) while ((pos = name.find('*', pos)) != std::string::npos) { name.replace(pos, 1, "(.{0,})"); } - Debug("ssl_sni", "Regexed fqdn=%s", name.c_str()); + Dbg(dbg_ctl_ssl_sni, "Regexed fqdn=%s", name.c_str()); set_regex_name(name); } @@ -118,7 +121,7 @@ SNIConfigParams::load_sni_config() auto &ai = sni_action_list.emplace_back(); ai.set_glob_name(item.fqdn); ai.inbound_port_ranges = item.inbound_port_ranges; - Debug("ssl", "name: %s", item.fqdn.data()); + Dbg(dbg_ctl_ssl, "name: %s", item.fqdn.data()); item.populate_sni_actions(ai.actions); if (!set_next_hop_properties(item)) { @@ -268,7 +271,7 @@ SNIConfig::startup() int SNIConfig::reconfigure() { - Debug("ssl", "Reload SNI file"); + Dbg(dbg_ctl_ssl, "Reload SNI file"); SNIConfigParams *params = new SNIConfigParams; bool retStatus = params->initialize(); diff --git a/iocore/net/TLSSNISupport.cc b/iocore/net/TLSSNISupport.cc index 88378a81418..36a5377791e 100644 --- a/iocore/net/TLSSNISupport.cc +++ b/iocore/net/TLSSNISupport.cc @@ -29,6 +29,13 @@ int TLSSNISupport::_ex_data_index = -1; +namespace +{ + +DbgCtl dbg_ctl_ssl_sni{"ssl_sni"}; + +} // end anonymous namespace + void TLSSNISupport::initialize() { @@ -61,14 +68,14 @@ TLSSNISupport::perform_sni_action() { const char *servername = this->get_sni_server_name(); if (!servername) { - Debug("ssl_sni", "No servername provided"); + Dbg(dbg_ctl_ssl_sni, "No servername provided"); return SSL_TLSEXT_ERR_OK; } SNIConfig::scoped_config params; auto const port{this->_get_local_port()}; if (auto const &actions = params->get({servername, std::strlen(servername)}, port); !actions.first) { - Debug("ssl_sni", "%s:%i not available in the map", servername, port); + Dbg(dbg_ctl_ssl_sni, "%s:%i not available in the map", servername, port); } else { for (auto &&item : *actions.first) { auto ret = item->SNIAction(this, actions.second); diff --git a/iocore/net/UnixNet.cc b/iocore/net/UnixNet.cc index 31bab7e230e..44e1f3676b5 100644 --- a/iocore/net/UnixNet.cc +++ b/iocore/net/UnixNet.cc @@ -41,6 +41,15 @@ NetHandler::Config NetHandler::global_config; std::bitset::digits> NetHandler::active_thread_types; const std::bitset NetHandler::config_value_affects_per_thread_value{0x3}; +namespace +{ + +DbgCtl dbg_ctl_inactivity_cop{"inactivity_cop"}; +DbgCtl dbg_ctl_inactivity_cop_check{"inactivity_cop_check"}; +DbgCtl dbg_ctl_inactivity_cop_verbose{"inactivity_cop_verbose"}; + +} // end anonymous namespace + NetHandler * get_NetHandler(EThread *t) { @@ -74,7 +83,7 @@ class InactivityCop : public Continuation ink_hrtime now = ink_get_hrtime(); NetHandler &nh = *get_NetHandler(this_ethread()); - Debug("inactivity_cop_check", "Checking inactivity on Thread-ID #%d", this_ethread()->id); + Dbg(dbg_ctl_inactivity_cop_check, "Checking inactivity on Thread-ID #%d", this_ethread()->id); // The rest NetEvents in cop_list which are not triggered between InactivityCop runs. // Use pop() to catch any closes caused by callbacks. while (NetEvent *ne = nh.cop_list.pop()) { @@ -93,8 +102,9 @@ class InactivityCop : public Continuation if (ne->default_inactivity_timeout_in == -1) { // If no context-specific default inactivity timeout has been set by an // override plugin, then use the global default. - Debug("inactivity_cop", "vc: %p setting the global default inactivity timeout of %d, next_inactivity_timeout_at: %" PRId64, - ne, nh.config.default_inactivity_timeout, ne->next_inactivity_timeout_at); + Dbg(dbg_ctl_inactivity_cop, + "vc: %p setting the global default inactivity timeout of %d, next_inactivity_timeout_at: %" PRId64, ne, + nh.config.default_inactivity_timeout, ne->next_inactivity_timeout_at); ne->set_default_inactivity_timeout(HRTIME_SECONDS(nh.config.default_inactivity_timeout)); } @@ -102,8 +112,8 @@ class InactivityCop : public Continuation // The event `EVENT_INACTIVITY_TIMEOUT` only be triggered if a read // or write I/O operation was set by `do_io_read()` or `do_io_write()`. if (ne->next_inactivity_timeout_at == 0 && ne->default_inactivity_timeout_in > 0 && (ne->read.enabled || ne->write.enabled)) { - Debug("inactivity_cop", "vc: %p inactivity timeout not set, setting a default of %d", ne, - nh.config.default_inactivity_timeout); + Dbg(dbg_ctl_inactivity_cop, "vc: %p inactivity timeout not set, setting a default of %d", ne, + nh.config.default_inactivity_timeout); ne->use_default_inactivity_timeout = true; ne->next_inactivity_timeout_at = ink_get_hrtime() + ne->default_inactivity_timeout_in; ne->inactivity_timeout_in = 0; @@ -113,7 +123,7 @@ class InactivityCop : public Continuation if (ne->next_inactivity_timeout_at && ne->next_inactivity_timeout_at < now) { if (ne->is_default_inactivity_timeout()) { // track the connections that timed out due to default inactivity - Debug("inactivity_cop", "vc: %p timed out due to default inactivity timeout", ne); + Dbg(dbg_ctl_inactivity_cop, "vc: %p timed out due to default inactivity timeout", ne); NET_INCREMENT_DYN_STAT(default_inactivity_timeout_count_stat); } if (nh.keep_alive_queue.in(ne)) { @@ -122,12 +132,12 @@ class InactivityCop : public Continuation NET_SUM_DYN_STAT(keep_alive_queue_timeout_total_stat, diff); NET_INCREMENT_DYN_STAT(keep_alive_queue_timeout_count_stat); } - Debug("inactivity_cop_verbose", "ne: %p now: %" PRId64 " timeout at: %" PRId64 " timeout in: %" PRId64, ne, - ink_hrtime_to_sec(now), ne->next_inactivity_timeout_at, ne->inactivity_timeout_in); + Dbg(dbg_ctl_inactivity_cop_verbose, "ne: %p now: %" PRId64 " timeout at: %" PRId64 " timeout in: %" PRId64, ne, + ink_hrtime_to_sec(now), ne->next_inactivity_timeout_at, ne->inactivity_timeout_in); ne->callback(VC_EVENT_INACTIVITY_TIMEOUT, e); } else if (ne->next_activity_timeout_at && ne->next_activity_timeout_at < now) { - Debug("inactivity_cop_verbose", "active ne: %p now: %" PRId64 " timeout at: %" PRId64 " timeout in: %" PRId64, ne, - ink_hrtime_to_sec(now), ne->next_activity_timeout_at, ne->active_timeout_in); + Dbg(dbg_ctl_inactivity_cop_verbose, "active ne: %p now: %" PRId64 " timeout at: %" PRId64 " timeout in: %" PRId64, ne, + ink_hrtime_to_sec(now), ne->next_activity_timeout_at, ne->active_timeout_in); ne->callback(VC_EVENT_ACTIVE_TIMEOUT, e); } } diff --git a/iocore/net/UnixNetAccept.cc b/iocore/net/UnixNetAccept.cc index dac10910981..138208b6e75 100644 --- a/iocore/net/UnixNetAccept.cc +++ b/iocore/net/UnixNetAccept.cc @@ -30,6 +30,14 @@ using NetAcceptHandler = int (NetAccept::*)(int, void *); int NetAccept::accept_till_done = 1; +namespace +{ + +DbgCtl dbg_ctl_iocore_net{"iocore_net"}; +DbgCtl dbg_ctl_iocore_net_accept_start{"iocore_net_accept_start"}; + +} // end anonymous namespace + static void safe_delay(int msec) { @@ -163,7 +171,8 @@ NetAccept::init_accept_loop() NetAccept *a = (i < n - 1) ? clone() : this; snprintf(thr_name, MAX_THREAD_NAME_LENGTH, "[ACCEPT %d:%d]", i, ats_ip_port_host_order(&server.accept_addr)); eventProcessor.spawn_thread(a, thr_name, stacksize); - Debug("iocore_net_accept_start", "Created accept thread #%d for port %d", i + 1, ats_ip_port_host_order(&server.accept_addr)); + Dbg(dbg_ctl_iocore_net_accept_start, "Created accept thread #%d for port %d", i + 1, + ats_ip_port_host_order(&server.accept_addr)); } } @@ -439,7 +448,7 @@ NetAccept::acceptFastEvent(int event, void *ep) NET_SUM_DYN_STAT(net_connections_throttled_in_stat, 1); continue; } - Debug("iocore_net", "accepted a new socket: %d", fd); + Dbg(dbg_ctl_iocore_net, "accepted a new socket: %d", fd); NET_SUM_GLOBAL_DYN_STAT(net_tcp_accept_stat, 1); if (opt.send_bufsize > 0) { if (unlikely(SocketManager::set_sndbuf_size(fd, opt.send_bufsize))) { @@ -468,7 +477,7 @@ NetAccept::acceptFastEvent(int event, void *ep) } // check return value from accept() if (res < 0) { - Debug("iocore_net", "received : %s", strerror(errno)); + Dbg(dbg_ctl_iocore_net, "received : %s", strerror(errno)); res = -errno; if (res == -EAGAIN || res == -ECONNABORTED #if defined(__linux__) diff --git a/iocore/net/UnixNetProcessor.cc b/iocore/net/UnixNetProcessor.cc index 90dbf5f18d8..87ed2035cb9 100644 --- a/iocore/net/UnixNetProcessor.cc +++ b/iocore/net/UnixNetProcessor.cc @@ -49,11 +49,21 @@ net_next_connection_number() NetProcessor::AcceptOptions const NetProcessor::DEFAULT_ACCEPT_OPTIONS; +namespace +{ + +DbgCtl dbg_ctl_iocore_net_processor{"iocore_net_processor"}; +DbgCtl dbg_ctl_iocore_net_accept{"iocore_net_accept"}; +DbgCtl dbg_ctl_http_tproxy{"http_tproxy"}; +DbgCtl dbg_ctl_Socks{"Socks"}; + +} // end anonymous namespace + Action * UnixNetProcessor::accept(Continuation *cont, AcceptOptions const &opt) { - Debug("iocore_net_processor", "NetProcessor::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::accept - port %d,recv_bufsize %d, send_bufsize %d, sockopt 0x%0x", + opt.local_port, opt.recv_bufsize, opt.send_bufsize, opt.sockopt_flags); return accept_internal(cont, NO_FD, opt); } @@ -61,8 +71,8 @@ UnixNetProcessor::accept(Continuation *cont, AcceptOptions const &opt) Action * UnixNetProcessor::main_accept(Continuation *cont, SOCKET fd, AcceptOptions const &opt) { - 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); return accept_internal(cont, fd, opt); } @@ -78,7 +88,7 @@ UnixNetProcessor::accept_internal(Continuation *cont, int fd, AcceptOptions cons NetAccept *na = createNetAccept(opt); na->id = ink_atomic_increment(&net_accept_number, 1); - Debug("iocore_net_accept", "creating new net accept number %d", na->id); + Dbg(dbg_ctl_iocore_net_accept, "creating new net accept number %d", na->id); // Fill in accept thread from configuration if necessary. if (opt.accept_threads < 0) { @@ -108,11 +118,11 @@ UnixNetProcessor::accept_internal(Continuation *cont, int fd, AcceptOptions cons ats_ip_copy(&na->server.accept_addr, &accept_ip); if (opt.f_inbound_transparent) { - Debug("http_tproxy", "Marked accept server %p on port %d as inbound transparent", na, opt.local_port); + Dbg(dbg_ctl_http_tproxy, "Marked accept server %p on port %d as inbound transparent", na, opt.local_port); } if (opt.f_proxy_protocol) { - Debug("http_tproxy", "Marked accept server %p on port %d for proxy protocol", na, opt.local_port); + Dbg(dbg_ctl_http_tproxy, "Marked accept server %p on port %d for proxy protocol", na, opt.local_port); } SessionAccept *sa = dynamic_cast(cont); @@ -194,7 +204,7 @@ UnixNetProcessor::connect_re(Continuation *cont, sockaddr const *target, NetVCOp if (using_socks) { char buff[INET6_ADDRPORTSTRLEN]; - Debug("Socks", "Using Socks ip: %s", ats_ip_nptop(target, buff, sizeof(buff))); + Dbg(dbg_ctl_Socks, "Using Socks ip: %s", ats_ip_nptop(target, buff, sizeof(buff))); socksEntry = socksAllocator.alloc(); // The socksEntry->init() will get the origin server addr by vc->get_remote_addr(), // and save it to socksEntry->req_data.dest_ip. @@ -212,7 +222,7 @@ UnixNetProcessor::connect_re(Continuation *cont, sockaddr const *target, NetVCOp result = &socksEntry->action_; vc->action_ = socksEntry; } else { - Debug("Socks", "Not Using Socks %d ", socks_conf_stuff->socks_needed); + Dbg(dbg_ctl_Socks, "Not Using Socks %d ", socks_conf_stuff->socks_needed); vc->action_ = cont; } diff --git a/iocore/net/UnixUDPConnection.cc b/iocore/net/UnixUDPConnection.cc index 92b9e602359..736b2ca6b12 100644 --- a/iocore/net/UnixUDPConnection.cc +++ b/iocore/net/UnixUDPConnection.cc @@ -32,6 +32,13 @@ #include "P_Net.h" #include "P_UDPNet.h" +namespace +{ + +DbgCtl dbg_ctl_udpnet{"udpnet"}; + +} // end anonymous namespace + UnixUDPConnection::~UnixUDPConnection() { UDPPacket *p = nullptr; @@ -49,7 +56,7 @@ UnixUDPConnection::~UnixUDPConnection() callbackAction->cancel(); callbackAction = nullptr; } - Debug("udpnet", "Destroying udp port = %d", getPortNum()); + Dbg(dbg_ctl_udpnet, "Destroying udp port = %d", getPortNum()); if (fd != NO_FD) { SocketManager::close(fd); } @@ -79,7 +86,7 @@ UnixUDPConnection::callbackHandler(int event, void *data) UDPPacket *p = nullptr; SList(UDPPacket, alink) aq(inQueue.popall()); - Debug("udpnet", "UDPConnection::callbackHandler"); + Dbg(dbg_ctl_udpnet, "UDPConnection::callbackHandler"); Queue result; while ((p = aq.pop())) { result.push(p); diff --git a/iocore/net/UnixUDPNet.cc b/iocore/net/UnixUDPNet.cc index 285e64d1e3c..c8df4212385 100644 --- a/iocore/net/UnixUDPNet.cc +++ b/iocore/net/UnixUDPNet.cc @@ -65,7 +65,13 @@ namespace #ifdef HAVE_RECVMMSG const uint32_t MAX_RECEIVE_MSG_PER_CALL{16}; //< VLEN parameter for the recvmmsg call. #endif -}; // namespace + +DbgCtl dbg_ctl_udpnet{"udpnet"}; +DbgCtl dbg_ctl_udp_read{"udp-read"}; +DbgCtl dbg_ctl_udp_send{"udp-send"}; +DbgCtl dbg_ctl_iocore_udp_main{"iocore_udp_main-send"}; + +} // end anonymous namespace UDPPacket * UDPPacket::new_UDPPacket() @@ -423,7 +429,7 @@ UDPNetProcessorInternal::read_single_message_from_net(UDPNetHandler *nh, UDPConn // truncated check if (msg.msg_flags & MSG_TRUNC) { - Debug("udp-read", "The UDP packet is truncated"); + Dbg(dbg_ctl_udp_read, "The UDP packet is truncated"); } safe_getsockname(xuc->getFd(), reinterpret_cast(&toaddr), &toaddr_len); @@ -442,8 +448,8 @@ UDPNetProcessorInternal::read_single_message_from_net(UDPNetHandler *nh, UDPConn } // If gro was used, then the kernel will tell us the size of each part that was spliced together. - Debug("udp-read", "Received %lld bytes. gso_size %lld (%s)", static_cast(r), static_cast(gso_size), - (gso_size > 0 ? "GRO" : "No GRO")); + Dbg(dbg_ctl_udp_read, "Received %lld bytes. gso_size %lld (%s)", static_cast(r), static_cast(gso_size), + (gso_size > 0 ? "GRO" : "No GRO")); IOBufferBlock *block; int64_t remaining{r}; @@ -464,7 +470,7 @@ UDPNetProcessorInternal::read_single_message_from_net(UDPNetHandler *nh, UDPConn block->next = nullptr; } } - Debug("udp-read", "Creating packet"); + Dbg(dbg_ctl_udp_read, "Creating packet"); // create packet UDPPacket *p = UDPPacket::new_incoming_UDPPacket(ats_ip_sa_cast(&fromaddr), ats_ip_sa_cast(&toaddr), chain); p->setConnection(uc); @@ -479,7 +485,7 @@ UDPNetProcessorInternal::read_single_message_from_net(UDPNetHandler *nh, UDPConn iters++; } while (r > 0); if (iters >= 1) { - Debug("udp-read", "read %d at a time", iters); + Dbg(dbg_ctl_udp_read, "read %d at a time", iters); } // if not already on to-be-called-back queue, then add it. if (!uc->onCallbackQueue) { @@ -553,25 +559,25 @@ UDPNetProcessorInternal::read_multiple_messages_from_net(UDPNetHandler *nh, UDPC const int return_val = SocketManager::recvmmsg(uc->getFd(), mmsg, MAX_RECEIVE_MSG_PER_CALL, MSG_WAITFORONE, nullptr); if (return_val <= 0) { - Debug("udp-read", "Done. recvmmsg() ret is %d, errno %s", return_val, strerror(errno)); + Dbg(dbg_ctl_udp_read, "Done. recvmmsg() ret is %d, errno %s", return_val, strerror(errno)); return; } - Debug("udp-read", "recvmmsg() read %d packets", return_val); + Dbg(dbg_ctl_udp_read, "recvmmsg() read %d packets", return_val); Ptr chain, next_chain; for (auto packet_num = 0; packet_num < return_val; packet_num++) { gso_size = 0; - Debug("udp-read", "Processing message %d from a total of %d", packet_num, return_val); + Dbg(dbg_ctl_udp_read, "Processing message %d from a total of %d", packet_num, return_val); struct msghdr &mhdr = mmsg[packet_num].msg_hdr; if (mhdr.msg_flags & MSG_TRUNC) { - Debug("udp-read", "The UDP packet is truncated"); + Dbg(dbg_ctl_udp_read, "The UDP packet is truncated"); break; } if (mhdr.msg_namelen <= 0) { - Debug("udp-read", "Unable to get remote address from recvmmsg() for fd: %d", uc->getFd()); + Dbg(dbg_ctl_udp_read, "Unable to get remote address from recvmmsg() for fd: %d", uc->getFd()); return; } @@ -596,8 +602,8 @@ UDPNetProcessorInternal::read_multiple_messages_from_net(UDPNetHandler *nh, UDPC total_bytes_read += received; // If gro was used, then the kernel will tell us the size of each part that was spliced together. - Debug("udp-read", "Received %lld bytes. gso_size %lld (%s)", static_cast(received), static_cast(gso_size), - (gso_size > 0 ? "GRO" : "No GRO")); + Dbg(dbg_ctl_udp_read, "Received %lld bytes. gso_size %lld (%s)", static_cast(received), + static_cast(gso_size), (gso_size > 0 ? "GRO" : "No GRO")); auto chain = buffer_chain[packet_num]; IOBufferBlock *block; @@ -619,7 +625,7 @@ UDPNetProcessorInternal::read_multiple_messages_from_net(UDPNetHandler *nh, UDPC block->next = nullptr; } } - Debug("udp-read", "Creating packet"); + Dbg(dbg_ctl_udp_read, "Creating packet"); // create packet UDPPacket *p = UDPPacket::new_incoming_UDPPacket(ats_ip_sa_cast(&fromaddr[packet_num]), ats_ip_sa_cast(&toaddr[packet_num]), chain); @@ -632,7 +638,7 @@ UDPNetProcessorInternal::read_multiple_messages_from_net(UDPNetHandler *nh, UDPC next_chain = nullptr; } } - Debug("udp-read", "Total bytes read %ld from %d packets.", total_bytes_read, return_val); + Dbg(dbg_ctl_udp_read, "Total bytes read %ld from %d packets.", total_bytes_read, return_val); // if not already on to-be-called-back queue, then add it. if (!uc->onCallbackQueue) { @@ -1049,12 +1055,12 @@ UDPNetProcessor::CreateUDPSocket(int *resfd, sockaddr const *remote_addr, Action if (opt.socket_recv_bufsize > 0) { if (unlikely(SocketManager::set_rcvbuf_size(fd, opt.socket_recv_bufsize))) { - Debug("udpnet", "set_dnsbuf_size(%d) failed", opt.socket_recv_bufsize); + Dbg(dbg_ctl_udpnet, "set_dnsbuf_size(%d) failed", opt.socket_recv_bufsize); } } if (opt.socket_send_bufsize > 0) { if (unlikely(SocketManager::set_sndbuf_size(fd, opt.socket_send_bufsize))) { - Debug("udpnet", "set_dnsbuf_size(%d) failed", opt.socket_send_bufsize); + Dbg(dbg_ctl_udpnet, "set_dnsbuf_size(%d) failed", opt.socket_send_bufsize); } } @@ -1071,7 +1077,7 @@ UDPNetProcessor::CreateUDPSocket(int *resfd, sockaddr const *remote_addr, Action } #endif if (!succeeded) { - Debug("udpnet", "setsockeopt for pktinfo failed"); + Dbg(dbg_ctl_udpnet, "setsockeopt for pktinfo failed"); goto HardError; } } else if (opt.ip_family == AF_INET6) { @@ -1087,7 +1093,7 @@ UDPNetProcessor::CreateUDPSocket(int *resfd, sockaddr const *remote_addr, Action } #endif if (!succeeded) { - Debug("udpnet", "setsockeopt for pktinfo failed"); + Dbg(dbg_ctl_udpnet, "setsockeopt for pktinfo failed"); goto HardError; } } @@ -1095,23 +1101,23 @@ UDPNetProcessor::CreateUDPSocket(int *resfd, sockaddr const *remote_addr, Action if (local_addr.network_order_port() || !is_any_address) { if (-1 == SocketManager::ink_bind(fd, &local_addr.sa, ats_ip_size(&local_addr.sa))) { char buff[INET6_ADDRPORTSTRLEN]; - Debug("udpnet", "ink bind failed on %s", ats_ip_nptop(local_addr, buff, sizeof(buff))); + Dbg(dbg_ctl_udpnet, "ink bind failed on %s", ats_ip_nptop(local_addr, buff, sizeof(buff))); goto SoftError; } if (safe_getsockname(fd, &local_addr.sa, &local_addr_len) < 0) { - Debug("udpnet", "CreateUdpsocket: getsockname didn't work"); + Dbg(dbg_ctl_udpnet, "CreateUdpsocket: getsockname didn't work"); goto HardError; } } *resfd = fd; *status = nullptr; - Debug("udpnet", "creating a udp socket port = %d, %d---success", ats_ip_port_host_order(remote_addr), - ats_ip_port_host_order(local_addr)); + Dbg(dbg_ctl_udpnet, "creating a udp socket port = %d, %d---success", ats_ip_port_host_order(remote_addr), + ats_ip_port_host_order(local_addr)); return true; SoftError: - Debug("udpnet", "creating a udp socket port = %d---soft failure", ats_ip_port_host_order(local_addr)); + Dbg(dbg_ctl_udpnet, "creating a udp socket port = %d---soft failure", ats_ip_port_host_order(local_addr)); if (fd != -1) { SocketManager::close(fd); } @@ -1119,7 +1125,7 @@ UDPNetProcessor::CreateUDPSocket(int *resfd, sockaddr const *remote_addr, Action *status = nullptr; return false; HardError: - Debug("udpnet", "creating a udp socket port = %d---hard failure", ats_ip_port_host_order(local_addr)); + Dbg(dbg_ctl_udpnet, "creating a udp socket port = %d---hard failure", ats_ip_port_host_order(local_addr)); if (fd != -1) { SocketManager::close(fd); } @@ -1164,7 +1170,7 @@ UDPNetProcessor::UDPBind(Continuation *cont, sockaddr const *addr, int fd, int s } #endif if (!succeeded) { - Debug("udpnet", "setsockeopt for pktinfo failed"); + Dbg(dbg_ctl_udpnet, "setsockeopt for pktinfo failed"); goto Lerror; } } else if (addr->sa_family == AF_INET6) { @@ -1180,7 +1186,7 @@ UDPNetProcessor::UDPBind(Continuation *cont, sockaddr const *addr, int fd, int s } #endif if (!succeeded) { - Debug("udpnet", "setsockeopt for pktinfo failed"); + Dbg(dbg_ctl_udpnet, "setsockeopt for pktinfo failed"); goto Lerror; } } @@ -1189,9 +1195,9 @@ UDPNetProcessor::UDPBind(Continuation *cont, sockaddr const *addr, int fd, int s if (G_udp_config.enable_gro) { int gro = 1; if (safe_setsockopt(fd, IPPROTO_UDP, UDP_GRO, (char *)&gro, sizeof(gro)) == 0) { - Debug("udpnet", "setsockopt UDP_GRO ok"); + Dbg(dbg_ctl_udpnet, "setsockopt UDP_GRO ok"); } else { - Debug("udpnet", "setsockopt UDP_GRO. errno=%d", errno); + Dbg(dbg_ctl_udpnet, "setsockopt UDP_GRO. errno=%d", errno); } } #endif @@ -1208,31 +1214,31 @@ UDPNetProcessor::UDPBind(Continuation *cont, sockaddr const *addr, int fd, int s } if (setsockopt_on(fd, SOL_SOCKET, SO_REUSEPORT) < 0) { - Debug("udpnet", "setsockopt for SO_REUSEPORT failed"); + Dbg(dbg_ctl_udpnet, "setsockopt for SO_REUSEPORT failed"); goto Lerror; } #ifdef SO_REUSEPORT_LB if (setsockopt_on(fd, SOL_SOCKET, SO_REUSEPORT_LB) < 0) { - Debug("udpnet", "setsockopt for SO_REUSEPORT_LB failed"); + Dbg(dbg_ctl_udpnet, "setsockopt for SO_REUSEPORT_LB failed"); goto Lerror; } #endif if (need_bind && (SocketManager::ink_bind(fd, addr, ats_ip_size(addr)) < 0)) { - Debug("udpnet", "ink_bind failed"); + Dbg(dbg_ctl_udpnet, "ink_bind failed"); goto Lerror; } // check this for GRO if (recv_bufsize) { if (unlikely(SocketManager::set_rcvbuf_size(fd, recv_bufsize))) { - Debug("udpnet", "set_dnsbuf_size(%d) failed", recv_bufsize); + Dbg(dbg_ctl_udpnet, "set_dnsbuf_size(%d) failed", recv_bufsize); } } if (send_bufsize) { if (unlikely(SocketManager::set_sndbuf_size(fd, send_bufsize))) { - Debug("udpnet", "set_dnsbuf_size(%d) failed", send_bufsize); + Dbg(dbg_ctl_udpnet, "set_dnsbuf_size(%d) failed", send_bufsize); } } if (safe_getsockname(fd, &myaddr.sa, &myaddr_len) < 0) { @@ -1240,7 +1246,7 @@ UDPNetProcessor::UDPBind(Continuation *cont, sockaddr const *addr, int fd, int s } n = new UnixUDPConnection(fd); - Debug("udpnet", "UDPNetProcessor::UDPBind: %p fd=%d", n, fd); + Dbg(dbg_ctl_udpnet, "UDPNetProcessor::UDPBind: %p fd=%d", n, fd); n->setBinding(&myaddr.sa); n->bindToThread(cont, cont->getThreadAffinity()); @@ -1255,7 +1261,7 @@ UDPNetProcessor::UDPBind(Continuation *cont, sockaddr const *addr, int fd, int s if (fd != NO_FD) { SocketManager::close(fd); } - Debug("udpnet", "Error: %s (%d)", strerror(errno), errno); + Dbg(dbg_ctl_udpnet, "Error: %s (%d)", strerror(errno), errno); cont->handleEvent(NET_EVENT_DATAGRAM_ERROR, nullptr); return ACTION_IO_ERROR; @@ -1299,7 +1305,7 @@ UDPQueue::service(UDPNetHandler *nh) ink_assert(p->link.prev == nullptr); ink_assert(p->link.next == nullptr); // insert into our queue. - Debug("udp-send", "Adding %p", p); + Dbg(dbg_ctl_udp_send, "Adding %p", p); if (p->p.conn->lastPktStartTime == 0) { pktSendStartTime = std::max(now, p->p.delivery_time); } else { @@ -1403,7 +1409,7 @@ UDPQueue::SendUDPPacket(UDPPacket *p) int n, count = 0; p->p.conn->lastSentPktStartTime = p->p.delivery_time; - Debug("udp-send", "Sending %p", p); + Dbg(dbg_ctl_udp_send, "Sending %p", p); msg.msg_control = nullptr; msg.msg_controllen = 0; @@ -1450,11 +1456,11 @@ UDPQueue::SendUDPPacket(UDPPacket *p) ++count; if ((g_udp_numSendRetries > 0) && (count >= g_udp_numSendRetries)) { // tried too many times; give up - Debug("udpnet", "Send failed: too many retries"); + Dbg(dbg_ctl_udpnet, "Send failed: too many retries"); return; } } else { - Debug("udp-send", "Error: %s (%d)", strerror(errno), errno); + Dbg(dbg_ctl_udp_send, "Error: %s (%d)", strerror(errno), errno); return; } } @@ -1478,11 +1484,11 @@ UDPQueue::SendUDPPacket(UDPPacket *p) ++count; if ((g_udp_numSendRetries > 0) && (count >= g_udp_numSendRetries)) { // tried too many times; give up - Debug("udpnet", "Send failed: too many retries"); + Dbg(dbg_ctl_udpnet, "Send failed: too many retries"); return; } } else { - Debug("udp-send", "Error: %s (%d)", strerror(errno), errno); + Dbg(dbg_ctl_udp_send, "Error: %s (%d)", strerror(errno), errno); return; } } @@ -1511,7 +1517,7 @@ UDPQueue::SendUDPPacket(UDPPacket *p) if ((n >= 0) || (errno != EAGAIN)) { // send succeeded or some random error happened. if (n < 0) { - Debug("udp-send", "Error: %s (%d)", strerror(errno), errno); + Dbg(dbg_ctl_udp_send, "Error: %s (%d)", strerror(errno), errno); } break; @@ -1520,7 +1526,7 @@ UDPQueue::SendUDPPacket(UDPPacket *p) ++count; if ((g_udp_numSendRetries > 0) && (count >= g_udp_numSendRetries)) { // tried too many times; give up - Debug("udpnet", "Send failed: too many retries"); + Dbg(dbg_ctl_udpnet, "Send failed: too many retries"); break; } } @@ -1656,15 +1662,15 @@ UDPQueue::SendMultipleUDPPackets(UDPPacket **p, uint16_t n) #ifdef SOL_UDP if (use_udp_gso && errno == EIO) { Warning("Disabling UDP GSO due to an error"); - Debug("udp-send", "Disabling UDP GSO due to an error"); + Dbg(dbg_ctl_udp_send, "Disabling UDP GSO due to an error"); use_udp_gso = false; return SendMultipleUDPPackets(p, n); } else { - Debug("udp-send", "udp_gso=%d res=%d errno=%d", use_udp_gso, res, errno); + Dbg(dbg_ctl_udp_send, "udp_gso=%d res=%d errno=%d", use_udp_gso, res, errno); return res; } #else - Debug("udp-send", "res=%d errno=%d", res, errno); + Dbg(dbg_ctl_udp_send, "res=%d errno=%d", res, errno); return res; #endif } @@ -1673,7 +1679,7 @@ UDPQueue::SendMultipleUDPPackets(UDPPacket **p, uint16_t n) #ifdef SOL_UDP if (use_udp_gso) { ink_assert(res <= n); - Debug("udp-send", "Sent %d messages by processing %d UDPPackets (GSO)", res, n); + Dbg(dbg_ctl_udp_send, "Sent %d messages by processing %d UDPPackets (GSO)", res, n); } else { #endif int i = 0; @@ -1685,7 +1691,7 @@ UDPQueue::SendMultipleUDPPackets(UDPPacket **p, uint16_t n) res -= (p[i]->p.chain.get()->size() / p[i]->p.segment_size) + ((p[i]->p.chain.get()->size() % p[i]->p.segment_size) != 0); } } - Debug("udp-send", "Sent %d messages by processing %d UDPPackets", nmsg, i); + Dbg(dbg_ctl_udp_send, "Sent %d messages by processing %d UDPPackets", nmsg, i); res = i; #ifdef SOL_UDP }