You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@trafficserver.apache.org by zw...@apache.org on 2022/04/20 21:54:37 UTC
[trafficserver] branch 9.2.x updated: HttpSM, HttpTunnel, and Http2Stream debug logging updates (#8788)
This is an automated email from the ASF dual-hosted git repository.
zwoop pushed a commit to branch 9.2.x
in repository https://gitbox.apache.org/repos/asf/trafficserver.git
The following commit(s) were added to refs/heads/9.2.x by this push:
new 17e301601 HttpSM, HttpTunnel, and Http2Stream debug logging updates (#8788)
17e301601 is described below
commit 17e301601b85696f6651845ac1f61575b844a2ad
Author: Brian Neradt <br...@gmail.com>
AuthorDate: Mon Apr 18 18:15:55 2022 -0500
HttpSM, HttpTunnel, and Http2Stream debug logging updates (#8788)
When enabling debug logging with the http tag, it is often helpful to be
able to identify logs based on the corresponding state machine ID. This
is especially the case when there is a significant amount of concurrent
traffic such that many logs from different state machines are being
emitted at the same time. This patch updates logging calls to more
consistently add the associated state machine ID for such logs.
Also: debug messages already contain the function names, so it's
redundant to specify them in the debug log line. Removing places where
this redundancy existed.
(cherry picked from commit 360aafbc11edc4c578187a25cadfa7e07c023262)
---
proxy/http/HttpSM.cc | 206 ++++++++++-----------
proxy/http/HttpTransact.cc | 433 +++++++++++++++++++--------------------------
proxy/http/HttpTunnel.cc | 6 +-
proxy/http2/Http2Stream.cc | 6 +-
4 files changed, 284 insertions(+), 367 deletions(-)
diff --git a/proxy/http/HttpSM.cc b/proxy/http/HttpSM.cc
index 6ee36814b..76d7d0105 100644
--- a/proxy/http/HttpSM.cc
+++ b/proxy/http/HttpSM.cc
@@ -295,7 +295,7 @@ HttpVCTable::cleanup_all()
}
}
-#define SMDebug(tag, ...) SpecificDebug(debug_on, tag, __VA_ARGS__)
+#define SMDebug(tag, fmt, ...) SpecificDebug(debug_on, tag, "[%" PRId64 "] " fmt, sm_id, ##__VA_ARGS__)
#define REMEMBER(e, r) \
{ \
@@ -305,10 +305,10 @@ HttpVCTable::cleanup_all()
#ifdef STATE_ENTER
#undef STATE_ENTER
#endif
-#define STATE_ENTER(state_name, event) \
- { \
- /*ink_assert (magic == HTTP_SM_MAGIC_ALIVE); */ REMEMBER(event, reentrancy_count); \
- SMDebug("http", "[%" PRId64 "] [%s, %s]", sm_id, #state_name, HttpDebugNames::get_event_name(event)); \
+#define STATE_ENTER(state_name, event) \
+ { \
+ /*ink_assert (magic == HTTP_SM_MAGIC_ALIVE); */ REMEMBER(event, reentrancy_count); \
+ SMDebug("http", "[%s, %s]", #state_name, HttpDebugNames::get_event_name(event)); \
}
#define HTTP_SM_SET_DEFAULT_HANDLER(_h) \
@@ -795,7 +795,7 @@ HttpSM::state_read_client_request_header(int event, void *data)
do_blind_tunnel = true;
}
if (do_blind_tunnel) {
- SMDebug("http", "[%" PRId64 "] first request on connection failed parsing, switching to passthrough.", sm_id);
+ SMDebug("http", "first request on connection failed parsing, switching to passthrough.");
t_state.transparent_passthrough = true;
http_parser_clear(&http_parser);
@@ -832,7 +832,7 @@ HttpSM::state_read_client_request_header(int event, void *data)
switch (state) {
case PARSE_RESULT_ERROR:
- SMDebug("http", "[%" PRId64 "] error parsing client request header", sm_id);
+ SMDebug("http", "error parsing client request header");
// Disable further I/O on the client
ua_entry->read_vio->nbytes = ua_entry->read_vio->ndone;
@@ -850,7 +850,7 @@ HttpSM::state_read_client_request_header(int event, void *data)
case PARSE_RESULT_CONT:
if (ua_entry->eos) {
- SMDebug("http_seq", "[%" PRId64 "] EOS before client request parsing finished", sm_id);
+ SMDebug("http_seq", "EOS before client request parsing finished");
set_ua_abort(HttpTransact::ABORTED, event);
// Disable further I/O on the client
@@ -859,7 +859,7 @@ HttpSM::state_read_client_request_header(int event, void *data)
call_transact_and_set_next_state(HttpTransact::BadRequest);
break;
} else if (event == VC_EVENT_READ_COMPLETE) {
- SMDebug("http_parse", "[%" PRId64 "] VC_EVENT_READ_COMPLETE and PARSE CONT state", sm_id);
+ SMDebug("http_parse", "VC_EVENT_READ_COMPLETE and PARSE CONT state");
break;
} else {
if (is_transparent_passthrough_allowed() && ua_raw_buffer_reader != nullptr &&
@@ -873,7 +873,7 @@ HttpSM::state_read_client_request_header(int event, void *data)
return VC_EVENT_CONT;
}
case PARSE_RESULT_DONE:
- SMDebug("http", "[%" PRId64 "] done parsing client request header", sm_id);
+ SMDebug("http", "done parsing client request header");
if (!t_state.hdr_info.client_request.check_hdr_implements()) {
t_state.http_return_code = HTTP_STATUS_NOT_IMPLEMENTED;
@@ -1040,10 +1040,7 @@ HttpSM::state_watch_for_client_abort(int event, void *data)
// where the tunnel is not active
HttpTunnelConsumer *c = tunnel.get_consumer(ua_txn);
if (c && c->alive) {
- SMDebug("http",
- "[%" PRId64 "] [watch_for_client_abort] "
- "forwarding event %s to tunnel",
- sm_id, HttpDebugNames::get_event_name(event));
+ SMDebug("http", "forwarding event %s to tunnel", HttpDebugNames::get_event_name(event));
tunnel.handleEvent(event, c->write_vio);
return 0;
} else {
@@ -1207,7 +1204,7 @@ HttpSM::state_read_push_response_header(int event, void *data)
switch (state) {
case PARSE_RESULT_ERROR:
- SMDebug("http", "[%" PRId64 "] error parsing push response header", sm_id);
+ SMDebug("http", "error parsing push response header");
call_transact_and_set_next_state(HttpTransact::HandleBadPushRespHdr);
break;
@@ -1216,7 +1213,7 @@ HttpSM::state_read_push_response_header(int event, void *data)
return VC_EVENT_CONT;
case PARSE_RESULT_DONE:
- SMDebug("http", "[%" PRId64 "] done parsing push response header", sm_id);
+ SMDebug("http", "done parsing push response header");
call_transact_and_set_next_state(HttpTransact::HandlePushResponseHdr);
break;
default:
@@ -1572,8 +1569,7 @@ plugins required to work with sni_routing.
return -1;
}
- SMDebug("http", "[%" PRId64 "] calling plugin on hook %s at hook %p", sm_id, HttpDebugNames::get_api_hook_name(cur_hook_id),
- cur_hook);
+ SMDebug("http", "calling plugin on hook %s at hook %p", HttpDebugNames::get_api_hook_name(cur_hook_id), cur_hook);
APIHook const *hook = cur_hook;
// Need to delay the next hook update until after this hook is called to handle dynamic
@@ -1861,7 +1857,7 @@ HttpSM::create_server_session(NetVConnection *netvc)
// the max and or min number of connections per host. Transfer responsibility for this to the
// session object.
if (s.outbound_conn_track_state.is_active()) {
- Debug("http_connect", "[%" PRId64 "] max number of outbound connections: %d", this->sm_id, s.txn_conf->outbound_conntrack.max);
+ SMDebug("http_connect", "max number of outbound connections: %d", s.txn_conf->outbound_conntrack.max);
retval->enable_outbound_connection_tracking(s.outbound_conn_track_state.drop());
}
return retval;
@@ -1889,7 +1885,7 @@ HttpSM::create_server_txn(PoolableSession *new_session)
int
HttpSM::state_http_server_open(int event, void *data)
{
- SMDebug("http_track", "entered inside state_http_server_open");
+ SMDebug("http_track", "entered inside state_http_server_open: %s", HttpDebugNames::get_event_name(event));
STATE_ENTER(&HttpSM::state_http_server_open, event);
ink_release_assert(event == EVENT_INTERVAL || event == NET_EVENT_OPEN || event == NET_EVENT_OPEN_FAILED ||
pending_action.is_empty());
@@ -1919,7 +1915,7 @@ HttpSM::state_http_server_open(int event, void *data)
pending_action = nullptr;
if (this->plugin_tunnel_type == HTTP_NO_PLUGIN_TUNNEL) {
- SMDebug("http", "[%" PRId64 "] setting handler for TCP handshake", sm_id);
+ SMDebug("http", "setting handler for TCP handshake");
// Just want to get a write-ready event so we know that the TCP handshake is complete.
server_entry->vc_write_handler = &HttpSM::state_http_server_open;
server_entry->vc_read_handler = &HttpSM::state_http_server_open;
@@ -1936,7 +1932,7 @@ HttpSM::state_http_server_open(int event, void *data)
// bytes are received back
t_state.set_connect_fail(EIO);
} else { // in the case of an intercept plugin don't to the connect timeout change
- SMDebug("http", "[%" PRId64 "] not setting handler for TCP handshake", sm_id);
+ SMDebug("http", "not setting handler for TCP handshake");
handle_http_server_open();
}
@@ -1946,7 +1942,7 @@ HttpSM::state_http_server_open(int event, void *data)
case VC_EVENT_WRITE_READY:
case VC_EVENT_WRITE_COMPLETE:
// Update the time out to the regular connection timeout.
- SMDebug("http_ss", "[%" PRId64 "] TCP Handshake complete", sm_id);
+ SMDebug("http_ss", "TCP Handshake complete");
server_entry->vc_write_handler = &HttpSM::state_send_server_request_header;
// Reset the timeout to the non-connect timeout
@@ -1986,9 +1982,9 @@ HttpSM::state_http_server_open(int event, void *data)
if (EADDRNOTAVAIL == t_state.current.server->connect_result && t_state.client_info.is_transparent) {
if (is_debug_tag_set("http_tproxy")) {
ip_port_text_buffer ip_c, ip_s;
- Debug("http_tproxy", "Force close of client connect (%s->%s) due to EADDRNOTAVAIL [%" PRId64 "]",
- ats_ip_nptop(&t_state.client_info.src_addr.sa, ip_c, sizeof ip_c),
- ats_ip_nptop(&t_state.server_info.dst_addr.sa, ip_s, sizeof ip_s), sm_id);
+ SMDebug("http_tproxy", "Force close of client connect (%s->%s) due to EADDRNOTAVAIL",
+ ats_ip_nptop(&t_state.client_info.src_addr.sa, ip_c, sizeof ip_c),
+ ats_ip_nptop(&t_state.server_info.dst_addr.sa, ip_s, sizeof ip_s));
}
t_state.client_info.keep_alive = HTTP_NO_KEEPALIVE; // part of the problem, clear it.
terminate_sm = true;
@@ -2375,7 +2371,7 @@ HttpSM::process_hostdb_info(HostDBInfo *r)
ink_release_assert(ats_is_ip(t_state.host_db_info.ip()));
}
} else {
- SMDebug("http", "[%" PRId64 "] DNS lookup failed for '%s'", sm_id, t_state.dns_info.lookup_name);
+ SMDebug("http", "DNS lookup failed for '%s'", t_state.dns_info.lookup_name);
if (!use_client_addr) {
t_state.dns_info.lookup_success = false;
@@ -2459,7 +2455,7 @@ HttpSM::state_hostdb_reverse_lookup(int event, void *data)
if (data) {
t_state.request_data.hostname_str = (static_cast<HostDBInfo *>(data))->hostname();
} else {
- SMDebug("http", "[%" PRId64 "] reverse DNS lookup failed for '%s'", sm_id, t_state.dns_info.lookup_name);
+ SMDebug("http", "reverse DNS lookup failed for '%s'", t_state.dns_info.lookup_name);
}
call_transact_and_set_next_state(nullptr);
break;
@@ -2589,7 +2585,7 @@ HttpSM::state_cache_open_write(int event, void *data)
// Failed on the write lock and retrying the vector
// for reading
if (t_state.redirect_info.redirect_in_process) {
- SMDebug("http_redirect", "[%" PRId64 "] CACHE_EVENT_OPEN_WRITE_FAILED during redirect follow", sm_id);
+ SMDebug("http_redirect", "CACHE_EVENT_OPEN_WRITE_FAILED during redirect follow");
t_state.cache_open_write_fail_action = CACHE_WL_FAIL_ACTION_DEFAULT;
t_state.cache_info.write_lock_state = HttpTransact::CACHE_WL_FAIL;
break;
@@ -2602,7 +2598,7 @@ HttpSM::state_cache_open_write(int event, void *data)
if (!t_state.cache_info.object_read ||
(t_state.cache_open_write_fail_action == CACHE_WL_FAIL_ACTION_ERROR_ON_MISS_OR_REVALIDATE)) {
// cache miss, set wl_state to fail
- SMDebug("http", "[%" PRId64 "] cache object read %p, cache_wl_fail_action %d", sm_id, t_state.cache_info.object_read,
+ SMDebug("http", "cache object read %p, cache_wl_fail_action %d", t_state.cache_info.object_read,
t_state.cache_open_write_fail_action);
t_state.cache_info.write_lock_state = HttpTransact::CACHE_WL_FAIL;
break;
@@ -2691,7 +2687,7 @@ HttpSM::state_cache_open_read(int event, void *data)
case CACHE_EVENT_OPEN_READ: {
pending_action = nullptr;
- SMDebug("http", "[%" PRId64 "] cache_open_read - CACHE_EVENT_OPEN_READ", sm_id);
+ SMDebug("http", "cache_open_read - CACHE_EVENT_OPEN_READ");
/////////////////////////////////
// lookup/open is successful. //
@@ -2714,10 +2710,10 @@ HttpSM::state_cache_open_read(int event, void *data)
case CACHE_EVENT_OPEN_READ_FAILED:
pending_action = nullptr;
- SMDebug("http", "[%" PRId64 "] cache_open_read - CACHE_EVENT_OPEN_READ_FAILED with %s (%d)", sm_id,
- InkStrerror(-cache_sm.get_last_error()), -cache_sm.get_last_error());
+ SMDebug("http", "cache_open_read - CACHE_EVENT_OPEN_READ_FAILED with %s (%d)", InkStrerror(-cache_sm.get_last_error()),
+ -cache_sm.get_last_error());
- SMDebug("http", "[state_cache_open_read] open read failed.");
+ SMDebug("http", "open read failed.");
// Inform HttpTransact somebody else is updating the document
// HttpCacheSM already waited so transact should go ahead.
if (cache_sm.get_last_error() == -ECACHE_DOC_BUSY) {
@@ -2752,7 +2748,7 @@ HttpSM::main_handler(int event, void *data)
// Don't use the state enter macro since it uses history
// space that we don't care about
- SMDebug("http", "[%" PRId64 "] [HttpSM::main_handler, %s]", sm_id, HttpDebugNames::get_event_name(event));
+ SMDebug("http", "%s, %d", HttpDebugNames::get_event_name(event), event);
HttpVCTableEntry *vc_entry = nullptr;
@@ -2990,10 +2986,7 @@ HttpSM::tunnel_handler_100_continue(int event, void *data)
// if the server closed while sending the
// 100 continue header, handle it here so we
// don't assert later
- SMDebug("http",
- "[%" PRId64 "] tunnel_handler_100_continue - server already "
- "closed, terminating connection",
- sm_id);
+ SMDebug("http", "server already closed, terminating connection");
// Since 100 isn't a final (loggable) response header
// kill the 100 continue header and create an empty one
@@ -3091,7 +3084,7 @@ HttpSM::is_http_server_eos_truncation(HttpTunnelProducer *p)
int64_t cl = t_state.hdr_info.server_response.get_content_length();
if (cl != UNDEFINED_COUNT && cl > server_response_body_bytes) {
- SMDebug("http", "[%" PRId64 "] server EOS after %" PRId64 " bytes, expected %" PRId64, sm_id, server_response_body_bytes, cl);
+ SMDebug("http", "server EOS after %" PRId64 " bytes, expected %" PRId64, server_response_body_bytes, cl);
return true;
} else {
return false;
@@ -3158,7 +3151,7 @@ HttpSM::tunnel_handler_server(int event, HttpTunnelProducer *p)
ink_assert(p->vc_type == HT_HTTP_SERVER);
if (is_http_server_eos_truncation(p)) {
- SMDebug("http", "[%" PRId64 "] [HttpSM::tunnel_handler_server] aborting HTTP tunnel due to server truncation", sm_id);
+ SMDebug("http", "aborting HTTP tunnel due to server truncation");
tunnel.chain_abort_all(p);
// UA session may not be in the tunnel yet, don't NULL out the pointer in that case.
// Note: This is a hack. The correct solution is for the UA session to signal back to the SM
@@ -3174,7 +3167,7 @@ HttpSM::tunnel_handler_server(int event, HttpTunnelProducer *p)
t_state.squid_codes.log_code = SQUID_LOG_ERR_READ_ERROR;
}
} else {
- SMDebug("http", "[%" PRId64 "] [HttpSM::tunnel_handler_server] finishing HTTP tunnel", sm_id);
+ SMDebug("http", "finishing HTTP tunnel");
p->read_success = true;
t_state.current.server->abort = HttpTransact::DIDNOT_ABORT;
// Appending reason to a response without Content-Length will result in
@@ -3275,7 +3268,7 @@ HttpSM::tunnel_handler_server(int event, HttpTunnelProducer *p)
// origin server
bool release_origin_connection = true;
if (t_state.txn_conf->attach_server_session_to_client == 1 && ua_txn && t_state.client_info.keep_alive == HTTP_KEEPALIVE) {
- Debug("http", "attaching server session to the client");
+ SMDebug("http", "attaching server session to the client");
if (ua_txn->attach_server_session(static_cast<PoolableSession *>(server_txn->get_proxy_ssn()))) {
release_origin_connection = false;
}
@@ -3364,7 +3357,7 @@ HttpSM::is_bg_fill_necessary(HttpTunnelConsumer *c)
if (pDone <= 1.0 && pDone > t_state.txn_conf->background_fill_threshold) {
return true;
} else {
- SMDebug("http", "[%" PRId64 "] no background. Only %%%f of %%%f done [%" PRId64 " / %" PRId64 " ]", sm_id, pDone,
+ SMDebug("http", "no background. Only %%%f of %%%f done [%" PRId64 " / %" PRId64 " ]", pDone,
t_state.txn_conf->background_fill_threshold, ua_body_done, ua_cl);
}
}
@@ -3399,7 +3392,7 @@ HttpSM::tunnel_handler_ua(int event, HttpTunnelConsumer *c)
if (is_bg_fill_necessary(c)) {
p = c->producer->self_consumer ? c->producer->self_consumer->producer : c->producer;
- SMDebug("http", "[%" PRId64 "] Initiating background fill", sm_id);
+ SMDebug("http", "Initiating background fill");
// check whether to finish the reading.
background_fill = p->read_success ? BACKGROUND_FILL_COMPLETED : BACKGROUND_FILL_STARTED;
@@ -3591,6 +3584,7 @@ int
HttpSM::tunnel_handler_cache_write(int event, HttpTunnelConsumer *c)
{
STATE_ENTER(&HttpSM::tunnel_handler_cache_write, event);
+ SMDebug("http", "handling cache event: %s", HttpDebugNames::get_event_name(event));
HttpTransact::CacheWriteStatus_t *status_ptr =
(c->producer->vc_type == HT_TRANSFORM) ? &t_state.cache_info.transform_write_status : &t_state.cache_info.write_status;
@@ -3604,7 +3598,7 @@ HttpSM::tunnel_handler_cache_write(int event, HttpTunnelConsumer *c)
c->vc->do_io_close(EHTTP_ERROR);
HTTP_INCREMENT_DYN_STAT(http_cache_write_errors);
- SMDebug("http", "[%" PRId64 "] aborting cache write due %s event from cache", sm_id, HttpDebugNames::get_event_name(event));
+ SMDebug("http", "aborting cache write due %s event from cache", HttpDebugNames::get_event_name(event));
// abort the producer if the cache_writevc is the only consumer.
if (c->producer->alive && c->producer->num_consumers == 1) {
tunnel.chain_abort_all(c->producer);
@@ -4165,7 +4159,7 @@ HttpSM::state_remap_request(int event, void * /* data ATS_UNUSED */)
case EVENT_REMAP_COMPLETE: {
pending_action = nullptr;
- SMDebug("url_rewrite", "completed processor-based remapping request for [%" PRId64 "]", sm_id);
+ SMDebug("url_rewrite", "completed processor-based remapping request");
t_state.url_remap_success = remapProcessor.finish_remap(&t_state, m_remap);
call_transact_and_set_next_state(nullptr);
break;
@@ -4207,8 +4201,7 @@ HttpSM::check_sni_host()
const char *action_value = host_sni_policy == 2 ? "terminate" : "continue";
if (!sni_value || sni_value[0] == '\0') { // No SNI
Warning("No SNI for TLS request with hostname %.*s action=%s", host_len, host_name, action_value);
- SMDebug("ssl_sni", "[HttpSM::check_sni_host] No SNI for TLS request with hostname %.*s action=%s", host_len, host_name,
- action_value);
+ SMDebug("ssl_sni", "No SNI for TLS request with hostname %.*s action=%s", host_len, host_name, action_value);
if (host_sni_policy == 2) {
Log::error("%s", lbw()
.clip(1)
@@ -4221,8 +4214,7 @@ HttpSM::check_sni_host()
}
} else if (strncasecmp(host_name, sni_value, host_len) != 0) { // Name mismatch
Warning("SNI/hostname mismatch sni=%s host=%.*s action=%s", sni_value, host_len, host_name, action_value);
- SMDebug("ssl_sni", "[HttpSM::check_sni_host] SNI/hostname mismatch sni=%s host=%.*s action=%s", sni_value, host_len,
- host_name, action_value);
+ SMDebug("ssl_sni", "SNI/hostname mismatch sni=%s host=%.*s action=%s", sni_value, host_len, host_name, action_value);
if (host_sni_policy == 2) {
Log::error("%s", lbw()
.clip(1)
@@ -4235,11 +4227,10 @@ HttpSM::check_sni_host()
this->t_state.client_connection_enabled = false;
}
} else {
- SMDebug("ssl_sni", "[HttpSM::check_sni_host] SNI/hostname sucessfully match sni=%s host=%.*s", sni_value, host_len,
- host_name);
+ SMDebug("ssl_sni", "SNI/hostname sucessfully match sni=%s host=%.*s", sni_value, host_len, host_name);
}
} else {
- SMDebug("ssl_sni", "[HttpSM::check_sni_host] No SNI/hostname check configured for host=%.*s", host_len, host_name);
+ SMDebug("ssl_sni", "No SNI/hostname check configured for host=%.*s", host_len, host_name);
}
}
}
@@ -4249,8 +4240,8 @@ HttpSM::check_sni_host()
void
HttpSM::do_remap_request(bool run_inline)
{
- SMDebug("http_seq", "[HttpSM::do_remap_request] Remapping request");
- SMDebug("url_rewrite", "Starting a possible remapping for request [%" PRId64 "]", sm_id);
+ SMDebug("http_seq", "Remapping request");
+ SMDebug("url_rewrite", "Starting a possible remapping for request");
bool ret = remapProcessor.setup_for_remap(&t_state, m_remap);
check_sni_host();
@@ -4274,14 +4265,14 @@ HttpSM::do_remap_request(bool run_inline)
}
if (!ret) {
- SMDebug("url_rewrite", "Could not find a valid remapping entry for this request [%" PRId64 "]", sm_id);
+ SMDebug("url_rewrite", "Could not find a valid remapping entry for this request");
if (!run_inline) {
handleEvent(EVENT_REMAP_COMPLETE, nullptr);
}
return;
}
- SMDebug("url_rewrite", "Found a remap map entry for [%" PRId64 "], attempting to remap request and call any plugins", sm_id);
+ SMDebug("url_rewrite", "Found a remap map entry, attempting to remap request and call any plugins");
pending_action = remapProcessor.perform_remap(this, &t_state);
return;
@@ -4328,7 +4319,7 @@ HttpSM::do_hostdb_lookup()
}
return;
} else { /* we aren't using SRV stuff... */
- SMDebug("http_seq", "[HttpSM::do_hostdb_lookup] Doing DNS Lookup");
+ SMDebug("http_seq", "Doing DNS Lookup");
// If there is not a current server, we must be looking up the origin
// server at the beginning of the transaction
@@ -4370,7 +4361,7 @@ HttpSM::do_hostdb_reverse_lookup()
ink_assert(t_state.dns_info.lookup_name != nullptr);
ink_assert(pending_action.is_empty());
- SMDebug("http_seq", "[HttpSM::do_hostdb_reverse_lookup] Doing reverse DNS Lookup");
+ SMDebug("http_seq", "Doing reverse DNS Lookup");
IpEndpoint addr;
ats_ip_pton(t_state.dns_info.lookup_name, &addr.sa);
@@ -4406,7 +4397,7 @@ HttpSM::do_hostdb_update_if_necessary()
// If we failed back over to the origin server, we don't have our
// hostdb information anymore which means we shouldn't update the hostdb
if (!ats_ip_addr_eq(&t_state.current.server->dst_addr.sa, t_state.host_db_info.ip())) {
- SMDebug("http", "[%" PRId64 "] skipping hostdb update due to server failover", sm_id);
+ SMDebug("http", "skipping hostdb update due to server failover");
return;
}
@@ -4435,14 +4426,14 @@ HttpSM::do_hostdb_update_if_necessary()
t_state.host_db_info.app.http_data.fail_count = 0;
issue_update |= 1;
char addrbuf[INET6_ADDRPORTSTRLEN];
- SMDebug("http", "[%" PRId64 "] hostdb update marking IP: %s as up", sm_id,
+ SMDebug("http", "hostdb update marking IP: %s as up",
ats_ip_nptop(&t_state.current.server->dst_addr.sa, addrbuf, sizeof(addrbuf)));
}
if (t_state.dns_info.srv_lookup_success && t_state.dns_info.srv_app.http_data.last_failure != 0) {
t_state.dns_info.srv_app.http_data.last_failure = 0;
hostDBProcessor.setby_srv(t_state.dns_info.lookup_name, 0, t_state.dns_info.srv_hostname, &t_state.dns_info.srv_app);
- SMDebug("http", "[%" PRId64 "] hostdb update marking SRV: %s as up", sm_id, t_state.dns_info.srv_hostname);
+ SMDebug("http", "hostdb update marking SRV: %s as up", t_state.dns_info.srv_hostname);
}
}
@@ -4494,7 +4485,7 @@ HttpSM::parse_range_and_compare(MIMEField *field, int64_t content_length)
}
if (parse_range_done) {
- Debug("http_range", "parse_range already done, t_state.range_setup %d", t_state.range_setup);
+ SMDebug("http_range", "parse_range already done, t_state.range_setup %d", t_state.range_setup);
return;
}
parse_range_done = true;
@@ -4636,7 +4627,7 @@ HttpSM::parse_range_and_compare(MIMEField *field, int64_t content_length)
int frag_offset_cnt = t_state.cache_info.object_read->get_frag_offset_count();
if (!frag_offset_tbl || !frag_offset_cnt || (frag_offset_tbl[frag_offset_cnt - 1] < static_cast<uint64_t>(end))) {
- Debug("http_range", "request range in cache, end %" PRId64 ", frg_offset_cnt %d" PRId64, end, frag_offset_cnt);
+ SMDebug("http_range", "request range in cache, end %" PRId64 ", frg_offset_cnt %d" PRId64, end, frag_offset_cnt);
t_state.range_in_cache = false;
}
}
@@ -4689,7 +4680,7 @@ HttpSM::calculate_output_cl(int64_t num_chars_for_ct, int64_t num_chars_for_cl)
t_state.range_output_cl += boundary_size + 2;
}
- Debug("http_range", "Pre-calculated Content-Length for Range response is %" PRId64, t_state.range_output_cl);
+ SMDebug("http_range", "Pre-calculated Content-Length for Range response is %" PRId64, t_state.range_output_cl);
}
void
@@ -4731,7 +4722,7 @@ HttpSM::do_range_setup_if_necessary()
bool do_transform = false;
if (!t_state.range_in_cache && t_state.cache_info.object_read) {
- Debug("http_range", "range can't be satisfied from cache, force origin request");
+ SMDebug("http_range", "range can't be satisfied from cache, force origin request");
t_state.cache_lookup_result = HttpTransact::CACHE_LOOKUP_MISS;
return;
}
@@ -4787,7 +4778,7 @@ HttpSM::do_range_setup_if_necessary()
content_length = t_state.hdr_info.server_response.get_content_length();
}
- Debug("http_trans", "Unable to accelerate range request, fallback to transform");
+ SMDebug("http_trans", "Unable to accelerate range request, fallback to transform");
// create a Range: transform processor for requests of type Range: bytes=1-2,4-5,10-100 (eg. multiple ranges)
INKVConnInternal *range_trans = transformProcessor.range_transform(mutex.get(), t_state.ranges, t_state.num_range_fields,
@@ -4828,8 +4819,7 @@ HttpSM::do_cache_lookup_and_read()
c_url = t_state.cache_info.lookup_url;
}
- SMDebug("http_seq", "[HttpSM::do_cache_lookup_and_read] [%" PRId64 "] Issuing cache lookup for URL %s", sm_id,
- c_url->string_get(&t_state.arena));
+ SMDebug("http_seq", "Issuing cache lookup for URL %s", c_url->string_get(&t_state.arena));
HttpCacheKey key;
Cache::generate_key(&key, c_url, t_state.txn_conf->cache_generation_number);
@@ -4854,8 +4844,7 @@ HttpSM::do_cache_delete_all_alts(Continuation *cont)
// Do not delete a non-existent object.
ink_assert(t_state.cache_info.object_read);
- SMDebug("http_seq", "[HttpSM::do_cache_delete_all_alts] Issuing cache delete for %s",
- t_state.cache_info.lookup_url->string_get_ref());
+ SMDebug("http_seq", "Issuing cache delete for %s", t_state.cache_info.lookup_url->string_get_ref());
HttpCacheKey key;
Cache::generate_key(&key, t_state.cache_info.lookup_url, t_state.txn_conf->cache_generation_number);
@@ -4933,7 +4922,7 @@ HttpSM::do_cache_prepare_action(HttpCacheSM *c_sm, CacheHTTPInfo *object_read_in
}
ink_assert(s_url != nullptr && s_url->valid());
- SMDebug("http_cache_write", "[%" PRId64 "] writing to cache with URL %s", sm_id, s_url->string_get(&t_state.arena));
+ SMDebug("http_cache_write", "writing to cache with URL %s", s_url->string_get(&t_state.arena));
HttpCacheKey key;
Cache::generate_key(&key, s_url, t_state.txn_conf->cache_generation_number);
@@ -5073,10 +5062,10 @@ HttpSM::do_http_server_open(bool raw)
ink_assert(t_state.current.server->dst_addr.network_order_port() != 0);
char addrbuf[INET6_ADDRPORTSTRLEN];
- SMDebug("http", "[%" PRId64 "] open connection to %s: %s", sm_id, t_state.current.server->name,
+ SMDebug("http", "open connection to %s: %s", t_state.current.server->name,
ats_ip_nptop(&t_state.current.server->dst_addr.sa, addrbuf, sizeof(addrbuf)));
- SMDebug("http_seq", "[HttpSM::do_http_server_open] Sending request to server");
+ SMDebug("http_seq", "Sending request to server");
// set the server first connect milestone here in case we return in the plugin_tunnel case that follows
milestones[TS_MILESTONE_SERVER_CONNECT] = Thread::get_hrtime();
@@ -5129,8 +5118,8 @@ HttpSM::do_http_server_open(bool raw)
}
Warning("server '%s' prohibited by ip-allow policy at line %d", ats_ip_ntop(server_ip, ipb, sizeof(ipb)),
acl.source_line());
- Debug("ip-allow", "Line %d denial for '%.*s' from %s", acl.source_line(), method_str_len, method_str,
- ats_ip_ntop(server_ip, ipb, sizeof(ipb)));
+ SMDebug("ip-allow", "Line %d denial for '%.*s' from %s", acl.source_line(), method_str_len, method_str,
+ ats_ip_ntop(server_ip, ipb, sizeof(ipb)));
}
t_state.current.attempts = t_state.txn_conf->connect_attempts_max_retries; // prevent any more retries with this IP
call_transact_and_set_next_state(HttpTransact::Forbidden);
@@ -5313,7 +5302,7 @@ HttpSM::do_http_server_open(bool raw)
auto wcount = ct_state.enqueue();
if (wcount < t_state.http_config_param->global_outbound_conntrack.queue_size) {
ct_state.rescheduled();
- SMDebug("http", "%s", lbw().print("[{}] queued for {}\0", sm_id, t_state.current.server->dst_addr).data());
+ SMDebug("http", "%s", lbw().print("queued for {}\0", t_state.current.server->dst_addr).data());
pending_action = eventProcessor.schedule_in(
this, HRTIME_MSECONDS(t_state.http_config_param->global_outbound_conntrack.queue_delay.count()));
} else { // the queue is full
@@ -5614,10 +5603,10 @@ HttpSM::mark_host_failure(HostDBInfo *info, time_t time_down)
}
}
info->app.http_data.last_failure = time_down;
- SMDebug("http", "[%" PRId64 "] hostdb update marking IP: %s as down", sm_id,
+ SMDebug("http", "hostdb update marking IP: %s as down",
ats_ip_nptop(&t_state.current.server->dst_addr.sa, addrbuf, sizeof(addrbuf)));
} else {
- SMDebug("http", "[%" PRId64 "] hostdb increment IP failcount %s to %d", sm_id,
+ SMDebug("http", "hostdb increment IP failcount %s to %d",
ats_ip_nptop(&t_state.current.server->dst_addr.sa, addrbuf, sizeof(addrbuf)), info->app.http_data.fail_count);
}
} else { // Clear the failure
@@ -5847,10 +5836,7 @@ HttpSM::handle_server_setup_error(int event, void *data)
if (tunnel.is_tunnel_active()) {
ink_assert(server_entry->read_vio == data || server_entry->write_vio == data);
- SMDebug("http",
- "[%" PRId64 "] [handle_server_setup_error] "
- "forwarding event %s to post tunnel",
- sm_id, HttpDebugNames::get_event_name(event));
+ SMDebug("http", "forwarding event %s to post tunnel", HttpDebugNames::get_event_name(event));
HttpTunnelConsumer *c = tunnel.get_consumer(server_entry->vc);
// it is possible only user agent post->post transform is set up
// this happened for Linux iocore where NET_EVENT_OPEN was returned
@@ -6140,11 +6126,10 @@ HttpSM::do_setup_post_tunnel(HttpVC_t to_vc_type)
void
HttpSM::perform_transform_cache_write_action()
{
- SMDebug("http", "[%" PRId64 "] perform_transform_cache_write_action %s", sm_id,
- HttpDebugNames::get_cache_action_name(t_state.cache_info.action));
+ SMDebug("http", "%s", HttpDebugNames::get_cache_action_name(t_state.cache_info.action));
if (t_state.range_setup) {
- SMDebug("http", "[%" PRId64 "] perform_transform_cache_write_action %s (with range setup)", sm_id,
+ SMDebug("http", "perform_transform_cache_write_action %s (with range setup)",
HttpDebugNames::get_cache_action_name(t_state.cache_info.action));
}
@@ -6180,8 +6165,7 @@ HttpSM::perform_transform_cache_write_action()
void
HttpSM::perform_cache_write_action()
{
- SMDebug("http", "[%" PRId64 "] perform_cache_write_action %s", sm_id,
- HttpDebugNames::get_cache_action_name(t_state.cache_info.action));
+ SMDebug("http", "%s", HttpDebugNames::get_cache_action_name(t_state.cache_info.action));
switch (t_state.cache_info.action) {
case HttpTransact::CACHE_DO_NO_ACTION:
@@ -6301,9 +6285,9 @@ HttpSM::attach_server_session()
addr.assign(server_txn->get_remote_addr());
if (!ats_ip_addr_eq(&t_state.current.server->dst_addr, &addr)) {
ip_port_text_buffer ipb1, ipb2;
- Debug("http_ss", "updating ip when attaching server session from %s to %s",
- ats_ip_ntop(&t_state.current.server->dst_addr.sa, ipb1, sizeof(ipb1)),
- ats_ip_ntop(server_txn->get_remote_addr(), ipb2, sizeof(ipb2)));
+ SMDebug("http_ss", "updating ip when attaching server session from %s to %s",
+ ats_ip_ntop(&t_state.current.server->dst_addr.sa, ipb1, sizeof(ipb1)),
+ ats_ip_ntop(server_txn->get_remote_addr(), ipb2, sizeof(ipb2)));
ats_ip_copy(&t_state.current.server->dst_addr, server_txn->get_remote_addr());
}
@@ -6419,7 +6403,7 @@ HttpSM::setup_server_send_request()
// the plugin decided to append a message to the request
if (t_state.api_server_request_body_set) {
- SMDebug("http", "[%" PRId64 "] appending msg of %" PRId64 " bytes to request %s", sm_id, msg_len, t_state.internal_msg_buffer);
+ SMDebug("http", "appending msg of %" PRId64 " bytes to request %s", msg_len, t_state.internal_msg_buffer);
hdr_length += server_entry->write_buffer->write(t_state.internal_msg_buffer, msg_len);
server_request_body_bytes = msg_len;
}
@@ -6445,7 +6429,7 @@ HttpSM::setup_server_read_response_header()
ink_assert(server_txn != nullptr && server_txn->get_remote_reader() != nullptr);
- SMDebug("http", "[setup_server_read_response_header] Setting up the header read");
+ SMDebug("http", "Setting up the header read");
// Now that we've got the ability to read from the
// server, setup to read the response header
@@ -6638,7 +6622,7 @@ HttpSM::setup_error_transfer()
t_state.api_next_action = HttpTransact::SM_ACTION_API_SEND_RESPONSE_HDR;
do_api_callout();
} else {
- SMDebug("http", "[setup_error_transfer] Now closing connection ...");
+ SMDebug("http", "Now closing connection ...");
vc_table.cleanup_entry(ua_entry);
ua_entry = nullptr;
// ua_txn = NULL;
@@ -7280,14 +7264,14 @@ HttpSM::kill_this()
//////////////
// Log Data //
//////////////
- SMDebug("http_seq", "[HttpSM::update_stats] Logging transaction");
+ SMDebug("http_seq", "Logging transaction");
if (Log::transaction_logging_enabled() && t_state.api_info.logging_enabled) {
LogAccess accessor(this);
int ret = Log::access(&accessor);
if (ret & Log::FULL) {
- SMDebug("http", "[update_stats] Logging system indicates FULL.");
+ SMDebug("http", "Logging system indicates FULL.");
}
if (ret & Log::FAIL) {
Log::error("failed to log transaction for at least one log object");
@@ -7326,7 +7310,7 @@ HttpSM::kill_this()
ink_mutex_release(&debug_sm_list_mutex);
#endif
- SMDebug("http", "[%" PRId64 "] deallocating sm", sm_id);
+ SMDebug("http", "deallocating sm");
destroy();
}
}
@@ -7580,7 +7564,7 @@ HttpSM::call_transact_and_set_next_state(TransactEntryFunc_t f)
f(&t_state);
}
- SMDebug("http", "[%" PRId64 "] State Transition: %s -> %s", sm_id, HttpDebugNames::get_action_name(last_action),
+ SMDebug("http", "State Transition: %s -> %s", HttpDebugNames::get_action_name(last_action),
HttpDebugNames::get_action_name(t_state.next_action));
set_next_state();
@@ -7628,7 +7612,7 @@ HttpSM::set_next_state()
case HttpTransact::SM_ACTION_REMAP_REQUEST: {
do_remap_request(true); /* run inline */
- SMDebug("url_rewrite", "completed inline remapping request for [%" PRId64 "]", sm_id);
+ SMDebug("url_rewrite", "completed inline remapping request");
t_state.url_remap_success = remapProcessor.finish_remap(&t_state, m_remap);
if (t_state.next_action == HttpTransact::SM_ACTION_SEND_ERROR_CACHE_NOOP && t_state.transact_return_point == nullptr) {
// It appears that we can now set the next_action to error and transact_return_point to nullptr when
@@ -7649,7 +7633,7 @@ HttpSM::set_next_state()
* then we can skip the lookup
*/
ip_text_buffer ipb;
- SMDebug("dns", "[HttpTransact::HandleRequest] Skipping DNS lookup for API supplied target %s.",
+ SMDebug("dns", "Skipping DNS lookup for API supplied target %s.",
ats_ip_ntop(&t_state.server_info.dst_addr, ipb, sizeof(ipb)));
// this seems wasteful as we will just copy it right back
ats_ip_copy(t_state.host_db_info.ip(), &t_state.server_info.dst_addr);
@@ -7659,8 +7643,7 @@ HttpSM::set_next_state()
} else if (0 == ats_ip_pton(t_state.dns_info.lookup_name, t_state.host_db_info.ip()) &&
ats_is_ip_loopback(t_state.host_db_info.ip())) {
// If it's 127.0.0.1 or ::1 don't bother with hostdb
- SMDebug("dns", "[HttpTransact::HandleRequest] Skipping DNS lookup for %s because it's loopback",
- t_state.dns_info.lookup_name);
+ SMDebug("dns", "Skipping DNS lookup for %s because it's loopback", t_state.dns_info.lookup_name);
t_state.dns_info.lookup_success = true;
call_transact_and_set_next_state(nullptr);
break;
@@ -7676,8 +7659,7 @@ HttpSM::set_next_state()
*/
if (is_debug_tag_set("dns")) {
ip_text_buffer ipb;
- SMDebug("dns", "[HttpTransact::HandleRequest] Skipping DNS lookup for client supplied target %s.",
- ats_ip_ntop(addr, ipb, sizeof(ipb)));
+ SMDebug("dns", "Skipping DNS lookup for client supplied target %s.", ats_ip_ntop(addr, ipb, sizeof(ipb)));
}
ats_ip_copy(t_state.host_db_info.ip(), addr);
t_state.host_db_info.app.http_data.http_version = t_state.hdr_info.client_request.version_get();
@@ -7691,7 +7673,7 @@ HttpSM::set_next_state()
} else if (t_state.parent_result.result == PARENT_UNDEFINED && t_state.dns_info.lookup_success) {
// Already set, and we don't have a parent proxy to lookup
ink_assert(ats_is_ip(t_state.host_db_info.ip()));
- SMDebug("dns", "[HttpTransact::HandleRequest] Skipping DNS lookup, provided by plugin");
+ SMDebug("dns", "Skipping DNS lookup, provided by plugin");
call_transact_and_set_next_state(nullptr);
break;
} else if (t_state.dns_info.looking_up == HttpTransact::ORIGIN_SERVER && t_state.http_config_param->no_dns_forward_to_parent &&
@@ -8012,7 +7994,7 @@ HttpSM::set_next_state()
void
HttpSM::do_redirect()
{
- SMDebug("http_redirect", "[HttpSM::do_redirect] enable_redirection %u", enable_redirection);
+ SMDebug("http_redirect", "enable_redirection %u", enable_redirection);
if (!enable_redirection || redirection_tries >= t_state.txn_conf->number_of_redirections) {
this->postbuf_clear();
@@ -8045,7 +8027,7 @@ HttpSM::do_redirect()
int ret = Log::access(&accessor);
if (ret & Log::FULL) {
- SMDebug("http", "[update_stats] Logging system indicates FULL.");
+ SMDebug("http", "Logging system indicates FULL.");
}
if (ret & Log::FAIL) {
Log::error("failed to log transaction for at least one log object");
@@ -8078,7 +8060,7 @@ HttpSM::do_redirect()
void
HttpSM::redirect_request(const char *arg_redirect_url, const int arg_redirect_len)
{
- SMDebug("http_redirect", "[HttpSM::redirect_request]");
+ SMDebug("http_redirect", "redirect url: %.*s", arg_redirect_len, arg_redirect_url);
// get a reference to the client request header and client url and check to see if the url is valid
HTTPHdr &clientRequestHeader = t_state.hdr_info.client_request;
URL &clientUrl = *clientRequestHeader.url_get();
@@ -8212,7 +8194,7 @@ HttpSM::redirect_request(const char *arg_redirect_url, const int arg_redirect_le
if (redirectScheme == nullptr) {
clientUrl.scheme_set(scheme_str, scheme_len);
- SMDebug("http_redirect", "[HttpSM::redirect_request] URL without scheme");
+ SMDebug("http_redirect", "URL without scheme");
}
if (noPortInHost) {
@@ -8241,7 +8223,7 @@ HttpSM::redirect_request(const char *arg_redirect_url, const int arg_redirect_le
char *saveptr = nullptr;
// the client request didn't have a host, so use the current origin host
- SMDebug("http_redirect", "[HttpSM::redirect_request] keeping client request host %s://%s", next_hop_scheme, origHost);
+ SMDebug("http_redirect", "keeping client request host %s://%s", next_hop_scheme, origHost);
char *origHostNoPort = strtok_r(origHost, ":", &saveptr);
if (origHostNoPort == nullptr) {
@@ -8357,7 +8339,7 @@ HttpSM::is_redirect_required()
bool redirect_required = (enable_redirection && (redirection_tries < t_state.txn_conf->number_of_redirections) &&
!HttpTransact::is_fresh_cache_hit(t_state.cache_lookup_result));
- SMDebug("http_redirect", "is_redirect_required %u", redirect_required);
+ SMDebug("http_redirect", "redirect_required: %u", redirect_required);
if (redirect_required == true) {
HTTPStatus status = t_state.hdr_info.client_response.status_get();
diff --git a/proxy/http/HttpTransact.cc b/proxy/http/HttpTransact.cc
index 0244a9f7c..4fd26abd8 100644
--- a/proxy/http/HttpTransact.cc
+++ b/proxy/http/HttpTransact.cc
@@ -214,8 +214,8 @@ markParentDown(HttpTransact::State *s)
HTTP_INCREMENT_DYN_STAT(http_total_parent_marked_down_count);
url_mapping *mp = s->url_map.getMapping();
- TxnDebug("http_trans", "sm_id[%" PRId64 "] enable_parent_timeout_markdowns: %d, disable_parent_markdowns: %d",
- s->state_machine->sm_id, s->txn_conf->enable_parent_timeout_markdowns, s->txn_conf->disable_parent_markdowns);
+ TxnDebug("http_trans", "enable_parent_timeout_markdowns: %d, disable_parent_markdowns: %d",
+ s->txn_conf->enable_parent_timeout_markdowns, s->txn_conf->disable_parent_markdowns);
if (s->txn_conf->disable_parent_markdowns == 1) {
TxnDebug("http_trans", "parent markdowns are disabled for this request");
@@ -274,9 +274,8 @@ parentExists(HttpTransact::State *s)
inline static void
nextParent(HttpTransact::State *s)
{
- TxnDebug("parent_down", "sm_id[%" PRId64 "] connection to parent %s failed, conn_state: %s, request to origin: %s",
- s->state_machine->sm_id, s->parent_result.hostname, HttpDebugNames::get_server_state_name(s->current.state),
- s->request_data.get_host());
+ TxnDebug("parent_down", "connection to parent %s failed, conn_state: %s, request to origin: %s", s->parent_result.hostname,
+ HttpDebugNames::get_server_state_name(s->current.state), s->request_data.get_host());
url_mapping *mp = s->url_map.getMapping();
if (s->response_action.handled) {
s->parent_result.hostname = s->response_action.action.hostname;
@@ -348,39 +347,39 @@ HttpTransact::is_response_valid(State *s, HTTPHdr *incoming_response)
return true;
#endif
case NO_RESPONSE_HEADER_ERROR:
- TxnDebug("http_trans", "[is_response_valid] No errors in response");
+ TxnDebug("http_trans", "No errors in response");
return true;
case MISSING_REASON_PHRASE:
- TxnDebug("http_trans", "[is_response_valid] Response Error: Missing reason phrase - allowing");
+ TxnDebug("http_trans", "Response Error: Missing reason phrase - allowing");
return true;
case STATUS_CODE_SERVER_ERROR:
- TxnDebug("http_trans", "[is_response_valid] Response Error: Origin Server returned 500 - allowing");
+ TxnDebug("http_trans", "Response Error: Origin Server returned 500 - allowing");
return true;
case CONNECTION_OPEN_FAILED:
- TxnDebug("http_trans", "[is_response_valid] Response Error: connection open failed");
+ TxnDebug("http_trans", "Response Error: connection open failed");
s->current.state = CONNECTION_ERROR;
return false;
case NON_EXISTANT_RESPONSE_HEADER:
- TxnDebug("http_trans", "[is_response_valid] Response Error: No response header");
+ TxnDebug("http_trans", "Response Error: No response header");
s->current.state = BAD_INCOMING_RESPONSE;
return false;
case NOT_A_RESPONSE_HEADER:
- TxnDebug("http_trans", "[is_response_valid] Response Error: Not a response header");
+ TxnDebug("http_trans", "Response Error: Not a response header");
s->current.state = BAD_INCOMING_RESPONSE;
return false;
case MISSING_STATUS_CODE:
- TxnDebug("http_trans", "[is_response_valid] Response Error: Missing status code");
+ TxnDebug("http_trans", "Response Error: Missing status code");
s->current.state = BAD_INCOMING_RESPONSE;
return false;
default:
- TxnDebug("http_trans", "[is_response_valid] Errors in response");
+ TxnDebug("http_trans", "Errors in response");
s->current.state = BAD_INCOMING_RESPONSE;
return false;
}
@@ -839,8 +838,7 @@ how_to_open_connection(HttpTransact::State *s)
void
HttpTransact::BadRequest(State *s)
{
- TxnDebug("http_trans", "[BadRequest]"
- "parser marked request bad");
+ TxnDebug("http_trans", "parser marked request bad");
bootstrap_state_variables_from_request(s, &s->hdr_info.client_request);
const char *body_factory_template = "request#syntax_error";
@@ -873,8 +871,7 @@ HttpTransact::BadRequest(State *s)
void
HttpTransact::PostActiveTimeoutResponse(State *s)
{
- TxnDebug("http_trans", "[PostActiveTimeoutResponse]"
- "post active timeout");
+ TxnDebug("http_trans", "post active timeout");
bootstrap_state_variables_from_request(s, &s->hdr_info.client_request);
build_error_response(s, HTTP_STATUS_REQUEST_TIMEOUT, "Active Timeout", "timeout#activity");
TRANSACT_RETURN(SM_ACTION_SEND_ERROR_CACHE_NOOP, nullptr);
@@ -883,8 +880,7 @@ HttpTransact::PostActiveTimeoutResponse(State *s)
void
HttpTransact::PostInactiveTimeoutResponse(State *s)
{
- TxnDebug("http_trans", "[PostInactiveTimeoutResponse]"
- "post inactive timeout");
+ TxnDebug("http_trans", "post inactive timeout");
bootstrap_state_variables_from_request(s, &s->hdr_info.client_request);
build_error_response(s, HTTP_STATUS_REQUEST_TIMEOUT, "Inactive Timeout", "timeout#inactivity");
TRANSACT_RETURN(SM_ACTION_SEND_ERROR_CACHE_NOOP, nullptr);
@@ -893,8 +889,7 @@ HttpTransact::PostInactiveTimeoutResponse(State *s)
void
HttpTransact::Forbidden(State *s)
{
- TxnDebug("http_trans", "[Forbidden]"
- "IpAllow marked request forbidden");
+ TxnDebug("http_trans", "IpAllow marked request forbidden");
bootstrap_state_variables_from_request(s, &s->hdr_info.client_request);
build_error_response(s, HTTP_STATUS_FORBIDDEN, "Access Denied", "access#denied");
TRANSACT_RETURN(SM_ACTION_SEND_ERROR_CACHE_NOOP, nullptr);
@@ -903,8 +898,7 @@ HttpTransact::Forbidden(State *s)
void
HttpTransact::SelfLoop(State *s)
{
- TxnDebug("http_trans", "[Loop]"
- "Request will selfloop.");
+ TxnDebug("http_trans", "Request will selfloop.");
bootstrap_state_variables_from_request(s, &s->hdr_info.client_request);
build_error_response(s, HTTP_STATUS_BAD_REQUEST, "Direct self loop detected", "request#cycle_detected");
TRANSACT_RETURN(SM_ACTION_SEND_ERROR_CACHE_NOOP, nullptr);
@@ -913,8 +907,7 @@ HttpTransact::SelfLoop(State *s)
void
HttpTransact::TooEarly(State *s)
{
- TxnDebug("http_trans", "[TooEarly]"
- "Early Data method is not safe");
+ TxnDebug("http_trans", "Early Data method is not safe");
bootstrap_state_variables_from_request(s, &s->hdr_info.client_request);
build_error_response(s, HTTP_STATUS_TOO_EARLY, "Too Early", "too#early");
TRANSACT_RETURN(SM_ACTION_SEND_ERROR_CACHE_NOOP, nullptr);
@@ -950,7 +943,7 @@ HttpTransact::HandleBlindTunnel(State *s)
// IpEndpoint dest_addr;
// ip_text_buffer new_host;
- TxnDebug("http_trans", "[HttpTransact::HandleBlindTunnel]");
+ TxnDebug("http_trans", "Entering HttpTransact::HandleBlindTunnel");
// We set the version to 0.9 because once we know where we are going
// this blind ssl tunnel is indistinguishable from a "CONNECT 0.9"
@@ -964,8 +957,7 @@ HttpTransact::HandleBlindTunnel(State *s)
if (is_debug_tag_set("http_trans")) {
int host_len;
const char *host = s->hdr_info.client_request.url_get()->host_get(&host_len);
- TxnDebug("http_trans", "[HandleBlindTunnel] destination set to %.*s:%d", host_len, host,
- s->hdr_info.client_request.url_get()->port_get());
+ TxnDebug("http_trans", "destination set to %.*s:%d", host_len, host, s->hdr_info.client_request.url_get()->port_get());
}
// Set the mode to tunnel so that we don't lookup the cache
@@ -1515,12 +1507,12 @@ HttpTransact::HandleRequest(State *s)
if (!(is_request_valid(s, &s->hdr_info.client_request))) {
HTTP_INCREMENT_DYN_STAT(http_invalid_client_requests_stat);
- TxnDebug("http_seq", "[HttpTransact::HandleRequest] request invalid.");
+ TxnDebug("http_seq", "request invalid.");
s->next_action = SM_ACTION_SEND_ERROR_CACHE_NOOP;
// s->next_action = HttpTransact::PROXY_INTERNAL_CACHE_NOOP;
return;
}
- TxnDebug("http_seq", "[HttpTransact::HandleRequest] request valid.");
+ TxnDebug("http_seq", "request valid.");
if (is_debug_tag_set("http_chdr_describe")) {
obj_describe(s->hdr_info.client_request.m_http, true);
@@ -1732,7 +1724,7 @@ HttpTransact::setup_plugin_request_intercept(State *s)
void
HttpTransact::HandleApiErrorJump(State *s)
{
- TxnDebug("http_trans", "[HttpTransact::HandleApiErrorJump]");
+ TxnDebug("http_trans", "Entering HttpTransact::HandleApiErrorJump");
// since the READ_REQUEST_HDR_HOOK is processed before
// we examine the request, returning TS_EVENT_ERROR will cause
@@ -1778,7 +1770,7 @@ HttpTransact::HandleApiErrorJump(State *s)
void
HttpTransact::PPDNSLookupAPICall(State *s)
{
- TxnDebug("http_trans", "[HttpTransact::PPDNSLookupAPICall] response_action.handled %d", s->response_action.handled);
+ TxnDebug("http_trans", "response_action.handled %d", s->response_action.handled);
if (!s->response_action.handled) {
TRANSACT_RETURN(SM_ACTION_DNS_LOOKUP, PPDNSLookup);
} else {
@@ -1809,7 +1801,7 @@ HttpTransact::PPDNSLookupAPICall(State *s)
void
HttpTransact::PPDNSLookup(State *s)
{
- TxnDebug("http_trans", "[HttpTransact::PPDNSLookup]");
+ TxnDebug("http_trans", "Entering HttpTransact::PPDNSLookup");
ink_assert(s->dns_info.looking_up == PARENT_PROXY);
if (!s->dns_info.lookup_success) {
@@ -1843,8 +1835,7 @@ HttpTransact::PPDNSLookup(State *s)
get_ka_info_from_host_db(s, &s->parent_info, &s->client_info, &s->host_db_info);
char addrbuf[INET6_ADDRSTRLEN];
- TxnDebug("http_trans", "[PPDNSLookup] DNS lookup for sm_id[%" PRId64 "] successful IP: %s", s->state_machine->sm_id,
- ats_ip_ntop(&s->parent_info.dst_addr.sa, addrbuf, sizeof(addrbuf)));
+ TxnDebug("http_trans", "DNS lookup for successful IP: %s", ats_ip_ntop(&s->parent_info.dst_addr.sa, addrbuf, sizeof(addrbuf)));
}
// Since this function can be called several times while retrying
@@ -1904,7 +1895,7 @@ HttpTransact::ReDNSRoundRobin(State *s)
get_ka_info_from_host_db(s, &s->server_info, &s->client_info, &s->host_db_info);
char addrbuf[INET6_ADDRSTRLEN];
- TxnDebug("http_trans", "[ReDNSRoundRobin] DNS lookup for O.S. successful IP: %s",
+ TxnDebug("http_trans", "DNS lookup for O.S. successful IP: %s",
ats_ip_ntop(&s->server_info.dst_addr.sa, addrbuf, sizeof(addrbuf)));
s->next_action = how_to_open_connection(s);
@@ -1954,11 +1945,11 @@ HttpTransact::OSDNSLookup(State *s)
{
ink_assert(s->dns_info.looking_up == ORIGIN_SERVER);
- TxnDebug("http_trans", "[HttpTransact::OSDNSLookup]");
+ TxnDebug("http_trans", "Entering HttpTransact::OSDNSLookup");
// It's never valid to connect *to* INADDR_ANY, so let's reject the request now.
if (ats_is_ip_any(s->host_db_info.ip())) {
- TxnDebug("http_trans", "[OSDNSLookup] Invalid request IP: INADDR_ANY");
+ TxnDebug("http_trans", "Invalid request IP: INADDR_ANY");
build_error_response(s, HTTP_STATUS_BAD_REQUEST, "Bad Destination Address", "request#syntax_error");
SET_VIA_STRING(VIA_DETAIL_TUNNEL, VIA_DETAIL_TUNNEL_NO_FORWARD);
TRANSACT_RETURN(SM_ACTION_SEND_ERROR_CACHE_NOOP, nullptr);
@@ -1972,9 +1963,9 @@ HttpTransact::OSDNSLookup(State *s)
*/
s->dns_info.lookup_success = true;
s->dns_info.os_addr_style = DNSLookupInfo::OS_Addr::OS_ADDR_USE_CLIENT;
- TxnDebug("http_seq", "[HttpTransact::OSDNSLookup] DNS lookup unsuccessful, using client target address");
+ TxnDebug("http_seq", "DNS lookup unsuccessful, using client target address");
} else {
- TxnDebug("http_seq", "[HttpTransact::OSDNSLookup] DNS Lookup unsuccessful");
+ TxnDebug("http_seq", "DNS Lookup unsuccessful");
// Even with unsuccessful DNS lookup, return stale object from cache if applicable
if (is_cache_hit(s->cache_lookup_result) && is_stale_cache_response_returnable(s)) {
@@ -1998,7 +1989,7 @@ HttpTransact::OSDNSLookup(State *s)
// The dns lookup succeeded
ink_assert(s->dns_info.lookup_success);
- TxnDebug("http_seq", "[HttpTransact::OSDNSLookup] DNS Lookup successful");
+ TxnDebug("http_seq", "DNS Lookup successful");
// For the transparent case, nail down the kind of address we are really using
if (DNSLookupInfo::OS_Addr::OS_ADDR_TRY_HOSTDB == s->dns_info.os_addr_style) {
@@ -2036,9 +2027,7 @@ HttpTransact::OSDNSLookup(State *s)
get_ka_info_from_host_db(s, &s->server_info, &s->client_info, &s->host_db_info);
char addrbuf[INET6_ADDRSTRLEN];
- TxnDebug("http_trans",
- "[OSDNSLookup] DNS lookup for O.S. successful "
- "IP: %s",
+ TxnDebug("http_trans", "DNS lookup for O.S. successful IP: %s",
ats_ip_ntop(&s->server_info.dst_addr.sa, addrbuf, sizeof(addrbuf)));
if (s->redirect_info.redirect_in_process) {
@@ -2055,13 +2044,13 @@ HttpTransact::OSDNSLookup(State *s)
}
if (action == RedirectEnabled::Action::FOLLOW) {
- TxnDebug("http_trans", "[OSDNSLookup] Invalid redirect address. Following");
+ TxnDebug("http_trans", "Invalid redirect address. Following");
} else if (action == RedirectEnabled::Action::REJECT || s->hdr_info.server_response.valid() == false) {
if (action == RedirectEnabled::Action::REJECT) {
- TxnDebug("http_trans", "[OSDNSLookup] Invalid redirect address. Rejecting.");
+ TxnDebug("http_trans", "Invalid redirect address. Rejecting.");
} else {
// Invalid server response, since we can't copy it we are going to reject
- TxnDebug("http_trans", "[OSDNSLookup] Invalid server response. Rejecting.");
+ TxnDebug("http_trans", "Invalid server response. Rejecting.");
Error("Invalid server response. Rejecting. IP: %s", ats_ip_ntop(&s->server_info.dst_addr.sa, addrbuf, sizeof(addrbuf)));
}
build_error_response(s, HTTP_STATUS_FORBIDDEN, nullptr, "request#syntax_error");
@@ -2070,9 +2059,9 @@ HttpTransact::OSDNSLookup(State *s)
} else {
// Return this 3xx to the client as-is
if (action == RedirectEnabled::Action::RETURN) {
- TxnDebug("http_trans", "[OSDNSLookup] Configured to return on invalid redirect address.");
+ TxnDebug("http_trans", "Configured to return on invalid redirect address.");
} else {
- TxnDebug("http_trans", "[OSDNSLookup] Invalid redirect address. Returning.");
+ TxnDebug("http_trans", "Invalid redirect address. Returning.");
}
build_response_copy(s, &s->hdr_info.server_response, &s->hdr_info.client_response, s->client_info.http_version);
TRANSACT_RETURN(SM_ACTION_INTERNAL_CACHE_NOOP, nullptr);
@@ -2173,8 +2162,8 @@ HttpTransact::DecideCacheLookup(State *s)
// now decide whether the cache can even be looked up.
if (s->cache_info.action == CACHE_DO_LOOKUP) {
- TxnDebug("http_trans", "[DecideCacheLookup] Will do cache lookup.");
- TxnDebug("http_seq", "[DecideCacheLookup] Will do cache lookup");
+ TxnDebug("http_trans", "Will do cache lookup.");
+ TxnDebug("http_seq", "Will do cache lookup");
ink_assert(s->current.mode != TUNNELLING_PROXY);
if (s->cache_info.lookup_url == nullptr) {
@@ -2221,8 +2210,8 @@ HttpTransact::DecideCacheLookup(State *s)
} else {
ink_assert(s->cache_info.action != CACHE_DO_LOOKUP && s->cache_info.action != CACHE_DO_SERVE);
- TxnDebug("http_trans", "[DecideCacheLookup] Will NOT do cache lookup.");
- TxnDebug("http_seq", "[DecideCacheLookup] Will NOT do cache lookup");
+ TxnDebug("http_trans", "Will NOT do cache lookup.");
+ TxnDebug("http_seq", "Will NOT do cache lookup");
// If this is a push request, we need send an error because
// since what ever was sent is not cacheable
if (s->method == HTTP_WKSIDX_PUSH) {
@@ -2521,10 +2510,10 @@ HttpTransact::issue_revalidate(State *s)
// action should be when the response is received.
if (does_method_require_cache_copy_deletion(s->http_config_param, s->method)) {
s->cache_info.action = CACHE_PREPARE_TO_DELETE;
- TxnDebug("http_seq", "[HttpTransact::issue_revalidate] cache action: DELETE");
+ TxnDebug("http_seq", "cache action: DELETE");
} else {
s->cache_info.action = CACHE_PREPARE_TO_UPDATE;
- TxnDebug("http_seq", "[HttpTransact::issue_revalidate] cache action: UPDATE");
+ TxnDebug("http_seq", "cache action: UPDATE");
}
} else {
// We've looped back around due to missing the write lock
@@ -2548,15 +2537,14 @@ HttpTransact::issue_revalidate(State *s)
bool no_cache_in_request = false;
if (s->hdr_info.client_request.is_pragma_no_cache_set() || s->hdr_info.client_request.is_cache_control_set(HTTP_VALUE_NO_CACHE)) {
- TxnDebug("http_trans", "[issue_revalidate] no-cache header directive in request, folks");
+ TxnDebug("http_trans", "no-cache header directive in request, folks");
no_cache_in_request = true;
}
if ((!(s->hdr_info.client_request.presence(MIME_PRESENCE_IF_MODIFIED_SINCE))) &&
(!(s->hdr_info.client_request.presence(MIME_PRESENCE_IF_NONE_MATCH))) && (no_cache_in_request == true) &&
(!s->txn_conf->cache_ims_on_client_no_cache) && (s->www_auth_content == CACHE_AUTH_NONE)) {
- TxnDebug("http_trans",
- "[issue_revalidate] Can not make this a conditional request. This is the force update of the cached copy case");
+ TxnDebug("http_trans", "Can not make this a conditional request. This is the force update of the cached copy case");
// set cache action to update. response will be a 200 or error,
// causing cached copy to be replaced (if 200).
s->cache_info.action = CACHE_PREPARE_TO_UPDATE;
@@ -2609,8 +2597,7 @@ HttpTransact::issue_revalidate(State *s)
case HTTP_STATUS_GONE: // 410
/* fall through */
default:
- TxnDebug("http_trans", "[issue_revalidate] cached response is"
- "not a 200 response so no conditionalization.");
+ TxnDebug("http_trans", "cached response is not a 200 response so no conditionalization.");
s->cache_info.action = CACHE_PREPARE_TO_UPDATE;
break;
case HTTP_STATUS_PARTIAL_CONTENT:
@@ -2625,10 +2612,10 @@ HttpTransact::HandleCacheOpenReadHitFreshness(State *s)
CacheHTTPInfo *&obj = s->cache_info.object_read;
ink_release_assert((s->request_sent_time == UNDEFINED_TIME) && (s->response_received_time == UNDEFINED_TIME));
- TxnDebug("http_seq", "[HttpTransact::HandleCacheOpenReadHitFreshness] Hit in cache");
+ TxnDebug("http_seq", "Hit in cache");
if (delete_all_document_alternates_and_return(s, true)) {
- TxnDebug("http_trans", "[HandleCacheOpenReadHitFreshness] Delete and return");
+ TxnDebug("http_trans", "Delete and return");
s->cache_info.action = CACHE_DO_DELETE;
s->next_action = HttpTransact::SM_ACTION_INTERNAL_CACHE_DELETE;
return;
@@ -2647,8 +2634,8 @@ HttpTransact::HandleCacheOpenReadHitFreshness(State *s)
ink_assert(s->request_sent_time <= s->response_received_time);
- TxnDebug("http_trans", "[HandleCacheOpenReadHitFreshness] request_sent_time : %" PRId64, (int64_t)s->request_sent_time);
- TxnDebug("http_trans", "[HandleCacheOpenReadHitFreshness] response_received_time : %" PRId64, (int64_t)s->response_received_time);
+ TxnDebug("http_trans", "request_sent_time : %" PRId64, (int64_t)s->request_sent_time);
+ TxnDebug("http_trans", "response_received_time : %" PRId64, (int64_t)s->response_received_time);
// if the plugin has already decided the freshness, we don't need to
// do it again
if (s->cache_lookup_result == HttpTransact::CACHE_LOOKUP_NONE) {
@@ -2657,18 +2644,15 @@ HttpTransact::HandleCacheOpenReadHitFreshness(State *s)
Freshness_t freshness = what_is_document_freshness(s, &s->hdr_info.client_request, obj->response_get());
switch (freshness) {
case FRESHNESS_FRESH:
- TxnDebug("http_seq", "[HttpTransact::HandleCacheOpenReadHitFreshness] "
- "Fresh copy");
+ TxnDebug("http_seq", "Fresh copy");
s->cache_lookup_result = HttpTransact::CACHE_LOOKUP_HIT_FRESH;
break;
case FRESHNESS_WARNING:
- TxnDebug("http_seq", "[HttpTransact::HandleCacheOpenReadHitFreshness] "
- "Heuristic-based Fresh copy");
+ TxnDebug("http_seq", "Heuristic-based Fresh copy");
s->cache_lookup_result = HttpTransact::CACHE_LOOKUP_HIT_WARNING;
break;
case FRESHNESS_STALE:
- TxnDebug("http_seq", "[HttpTransact::HandleCacheOpenReadHitFreshness] "
- "Stale in cache");
+ TxnDebug("http_seq", "Stale in cache");
s->cache_lookup_result = HttpTransact::CACHE_LOOKUP_HIT_STALE;
break;
default:
@@ -2695,11 +2679,11 @@ HttpTransact::HandleCacheOpenReadHitFreshness(State *s)
void
HttpTransact::CallOSDNSLookup(State *s)
{
- TxnDebug("http", "[HttpTransact::callos] %s ", s->server_info.name);
+ TxnDebug("http", "%s ", s->server_info.name);
HostStatus &pstatus = HostStatus::instance();
HostStatRec *hst = pstatus.getHostStatus(s->server_info.name);
if (hst && hst->status == TSHostStatus::TS_HOST_STATUS_DOWN) {
- TxnDebug("http", "[HttpTransact::callos] %d ", s->cache_lookup_result);
+ TxnDebug("http", "%d ", s->cache_lookup_result);
s->current.state = OUTBOUND_CONGESTION;
if (s->cache_lookup_result == CACHE_LOOKUP_HIT_STALE || s->cache_lookup_result == CACHE_LOOKUP_HIT_WARNING ||
s->cache_lookup_result == CACHE_LOOKUP_HIT_FRESH) {
@@ -2743,24 +2727,20 @@ HttpTransact::need_to_revalidate(State *s)
switch (authentication_needed) {
case AUTHENTICATION_SUCCESS:
- TxnDebug("http_seq", "[HttpTransact::HandleCacheOpenReadHit] "
- "Authentication not needed");
+ TxnDebug("http_seq", "Authentication not needed");
needs_authenticate = false;
break;
case AUTHENTICATION_MUST_REVALIDATE:
SET_VIA_STRING(VIA_DETAIL_CACHE_LOOKUP, VIA_DETAIL_MISS_METHOD);
- TxnDebug("http_seq", "[HttpTransact::HandleCacheOpenReadHit] "
- "Authentication needed");
+ TxnDebug("http_seq", "Authentication needed");
needs_authenticate = true;
break;
case AUTHENTICATION_MUST_PROXY:
- TxnDebug("http_seq", "[HttpTransact::HandleCacheOpenReadHit] "
- "Authentication needed");
+ TxnDebug("http_seq", "Authentication needed");
needs_authenticate = true;
break;
case AUTHENTICATION_CACHE_AUTH:
- TxnDebug("http_seq", "[HttpTransact::HandleCacheOpenReadHit] "
- "Authentication needed for cache_auth_content");
+ TxnDebug("http_seq", "Authentication needed for cache_auth_content");
needs_authenticate = false;
needs_cache_auth = true;
break;
@@ -2840,24 +2820,20 @@ HttpTransact::HandleCacheOpenReadHit(State *s)
switch (authentication_needed) {
case AUTHENTICATION_SUCCESS:
- TxnDebug("http_seq", "[HttpTransact::HandleCacheOpenReadHit] "
- "Authentication not needed");
+ TxnDebug("http_seq", "Authentication not needed");
needs_authenticate = false;
break;
case AUTHENTICATION_MUST_REVALIDATE:
SET_VIA_STRING(VIA_DETAIL_CACHE_LOOKUP, VIA_DETAIL_MISS_METHOD);
- TxnDebug("http_seq", "[HttpTransact::HandleCacheOpenReadHit] "
- "Authentication needed");
+ TxnDebug("http_seq", "Authentication needed");
needs_authenticate = true;
break;
case AUTHENTICATION_MUST_PROXY:
- TxnDebug("http_seq", "[HttpTransact::HandleCacheOpenReadHit] "
- "Authentication needed");
+ TxnDebug("http_seq", "Authentication needed");
HandleCacheOpenReadMiss(s);
return;
case AUTHENTICATION_CACHE_AUTH:
- TxnDebug("http_seq", "[HttpTransact::HandleCacheOpenReadHit] "
- "Authentication needed for cache_auth_content");
+ TxnDebug("http_seq", "Authentication needed for cache_auth_content");
needs_authenticate = false;
needs_cache_auth = true;
break;
@@ -2919,8 +2895,7 @@ HttpTransact::HandleCacheOpenReadHit(State *s)
if (send_revalidate) {
TxnDebug("http_trans", "CacheOpenRead --- HIT-STALE");
- TxnDebug("http_seq", "[HttpTransact::HandleCacheOpenReadHit] "
- "Revalidate document with server");
+ TxnDebug("http_seq", "Revalidate document with server");
find_server_and_update_current_info(s);
@@ -3095,7 +3070,7 @@ HttpTransact::build_response_from_cache(State *s, HTTPWarningCode warning_code)
case HTTP_STATUS_NOT_MODIFIED:
// A IMS or INM GET client request with conditions being met
// by the cached response. Send back a NOT MODIFIED response.
- TxnDebug("http_trans", "[build_response_from_cache] Not modified");
+ TxnDebug("http_trans", "Not modified");
SET_VIA_STRING(VIA_DETAIL_CACHE_LOOKUP, VIA_DETAIL_HIT_CONDITIONAL);
build_response(s, cached_response, &s->hdr_info.client_response, s->client_info.http_version, client_response_code);
@@ -3106,7 +3081,7 @@ HttpTransact::build_response_from_cache(State *s, HTTPWarningCode warning_code)
case HTTP_STATUS_PRECONDITION_FAILED:
// A conditional request with conditions not being met by the cached
// response. Send back a PRECONDITION FAILED response.
- TxnDebug("http_trans", "[build_response_from_cache] Precondition Failed");
+ TxnDebug("http_trans", "Precondition Failed");
SET_VIA_STRING(VIA_DETAIL_CACHE_LOOKUP, VIA_DETAIL_MISS_CONDITIONAL);
build_response(s, &s->hdr_info.client_response, s->client_info.http_version, client_response_code);
@@ -3125,7 +3100,7 @@ HttpTransact::build_response_from_cache(State *s, HTTPWarningCode warning_code)
if (s->method == HTTP_WKSIDX_GET || (s->http_config_param->cache_post_method == 1 && s->method == HTTP_WKSIDX_POST) ||
s->api_resp_cacheable == true) {
// send back the full document to the client.
- TxnDebug("http_trans", "[build_response_from_cache] Match! Serving full document.");
+ TxnDebug("http_trans", "Match! Serving full document.");
s->cache_info.action = CACHE_DO_SERVE;
// Check if cached response supports Range. If it does, append
@@ -3143,7 +3118,7 @@ HttpTransact::build_response_from_cache(State *s, HTTPWarningCode warning_code)
// or if the range can't be satisfied from the cache
// In that case we fetch the entire source so it's OK to switch
// this late.
- TxnDebug("http_seq", "[HttpTransact::HandleCacheOpenReadHit] Out-of-order Range request - tunneling");
+ TxnDebug("http_seq", "Out-of-order Range request - tunneling");
s->cache_info.action = CACHE_DO_NO_ACTION;
if (s->force_dns) {
HandleCacheOpenReadMiss(s); // DNS is already completed no need of doing DNS
@@ -3164,7 +3139,7 @@ HttpTransact::build_response_from_cache(State *s, HTTPWarningCode warning_code)
}
// If the client request is a HEAD, then serve the header from cache.
else if (s->method == HTTP_WKSIDX_HEAD) {
- TxnDebug("http_trans", "[build_response_from_cache] Match! Serving header only.");
+ TxnDebug("http_trans", "Match! Serving header only.");
build_response(s, cached_response, &s->hdr_info.client_response, s->client_info.http_version);
s->cache_info.action = CACHE_DO_NO_ACTION;
@@ -3173,7 +3148,7 @@ HttpTransact::build_response_from_cache(State *s, HTTPWarningCode warning_code)
// We handled the request but it's not GET or HEAD (eg. DELETE),
// and server is not reachable: 502
//
- TxnDebug("http_trans", "[build_response_from_cache] No match! Connection failed.");
+ TxnDebug("http_trans", "No match! Connection failed.");
build_error_response(s, HTTP_STATUS_BAD_GATEWAY, "Connection Failed", "connect#failed_connect");
s->cache_info.action = CACHE_DO_NO_ACTION;
s->next_action = SM_ACTION_INTERNAL_CACHE_NOOP;
@@ -3335,12 +3310,11 @@ HttpTransact::handle_cache_write_lock(State *s)
void
HttpTransact::HandleCacheOpenReadMiss(State *s)
{
- TxnDebug("http_trans", "[HandleCacheOpenReadMiss] --- MISS");
- TxnDebug("http_seq", "[HttpTransact::HandleCacheOpenReadMiss] "
- "Miss in cache");
+ TxnDebug("http_trans", "--- MISS");
+ TxnDebug("http_seq", "Miss in cache");
if (delete_all_document_alternates_and_return(s, false)) {
- TxnDebug("http_trans", "[HandleCacheOpenReadMiss] Delete and return");
+ TxnDebug("http_trans", "Delete and return");
s->cache_info.action = CACHE_DO_NO_ACTION;
s->next_action = SM_ACTION_INTERNAL_CACHE_NOOP;
return;
@@ -3438,7 +3412,7 @@ HttpTransact::HandleCacheOpenReadMiss(State *s)
void
HttpTransact::OriginServerRawOpen(State *s)
{
- TxnDebug("http_trans", "[HttpTransact::OriginServerRawOpen]");
+ TxnDebug("http_trans", "Entering HttpTransact::OriginServerRawOpen");
switch (s->current.state) {
case STATE_UNDEFINED:
@@ -3459,7 +3433,7 @@ HttpTransact::OriginServerRawOpen(State *s)
case CONNECTION_ALIVE:
build_response(s, &s->hdr_info.client_response, s->client_info.http_version, HTTP_STATUS_OK);
- TxnDebug("http_trans", "[OriginServerRawOpen] connection alive. next action is ssl_tunnel");
+ TxnDebug("http_trans", "connection alive. next action is ssl_tunnel");
s->next_action = SM_ACTION_SSL_TUNNEL;
break;
default:
@@ -3494,15 +3468,15 @@ HttpTransact::OriginServerRawOpen(State *s)
void
HttpTransact::HandleResponse(State *s)
{
- TxnDebug("http_trans", "[HttpTransact::HandleResponse]");
- TxnDebug("http_seq", "[HttpTransact::HandleResponse] Response received");
+ TxnDebug("http_trans", "Entering HttpTransact::HandleResponse");
+ TxnDebug("http_seq", "Response received");
s->source = SOURCE_HTTP_ORIGIN_SERVER;
s->response_received_time = ink_local_time();
ink_assert(s->response_received_time >= s->request_sent_time);
s->current.now = s->response_received_time;
- TxnDebug("http_trans", "[HandleResponse] response_received_time: %" PRId64, (int64_t)s->response_received_time);
+ TxnDebug("http_trans", "response_received_time: %" PRId64, (int64_t)s->response_received_time);
DUMP_HEADER("http_hdrs", &s->hdr_info.server_response, s->state_machine_id, "Incoming O.S. Response");
HTTP_INCREMENT_DYN_STAT(http_incoming_responses_stat);
@@ -3517,9 +3491,9 @@ HttpTransact::HandleResponse(State *s)
}
if (!HttpTransact::is_response_valid(s, &s->hdr_info.server_response)) {
- TxnDebug("http_seq", "[HttpTransact::HandleResponse] Response not valid");
+ TxnDebug("http_seq", "Response not valid");
} else {
- TxnDebug("http_seq", "[HttpTransact::HandleResponse] Response valid");
+ TxnDebug("http_seq", "Response valid");
initialize_state_variables_from_response(s, &s->hdr_info.server_response);
}
@@ -3652,7 +3626,7 @@ void
HttpTransact::handle_response_from_parent(State *s)
{
LookingUp_t next_lookup = UNDEFINED_LOOKUP;
- TxnDebug("http_trans", "[handle_response_from_parent] (hrfp)");
+ TxnDebug("http_trans", "(hrfp)");
HTTP_RELEASE_ASSERT(s->current.server == &s->parent_info);
// if this parent was retried from a markdown, then
@@ -3753,7 +3727,7 @@ HttpTransact::handle_response_from_parent(State *s)
// Done trying parents... fail over to origin server if that is
// appropriate
HTTP_INCREMENT_DYN_STAT(http_total_parent_retries_exhausted_stat);
- TxnDebug("http_trans", "[handle_response_from_parent] Error. No more retries.");
+ TxnDebug("http_trans", "Error. No more retries.");
if (s->current.state == CONNECTION_ERROR || s->current.state == INACTIVE_TIMEOUT) {
markParentDown(s);
}
@@ -3807,7 +3781,7 @@ HttpTransact::handle_response_from_parent(State *s)
void
HttpTransact::handle_response_from_server(State *s)
{
- TxnDebug("http_trans", "[handle_response_from_server] (hrfs)");
+ TxnDebug("http_trans", "(hrfs)");
HTTP_RELEASE_ASSERT(s->current.server == &s->server_info);
unsigned max_connect_retries = 0;
@@ -3825,7 +3799,7 @@ HttpTransact::handle_response_from_server(State *s)
handle_forward_server_connection_open(s);
break;
case OUTBOUND_CONGESTION:
- TxnDebug("http_trans", "[handle_response_from_server] Error. congestion control -- congested.");
+ TxnDebug("http_trans", "Error. congestion control -- congested.");
SET_VIA_STRING(VIA_DETAIL_SERVER_CONNECT, VIA_DETAIL_SERVER_FAILURE);
s->set_connect_fail(EUSERS); // too many users
handle_server_connection_not_open(s);
@@ -3869,7 +3843,7 @@ HttpTransact::handle_response_from_server(State *s)
return;
} else {
retry_server_connection_not_open(s, s->current.state, max_connect_retries);
- TxnDebug("http_trans", "[handle_response_from_server] Error. Retrying...");
+ TxnDebug("http_trans", "Error. Retrying...");
s->next_action = how_to_open_connection(s);
if (s->api_server_addr_set) {
@@ -3885,7 +3859,7 @@ HttpTransact::handle_response_from_server(State *s)
}
} else {
error_log_connection_failure(s, s->current.state);
- TxnDebug("http_trans", "[handle_response_from_server] Error. No more retries.");
+ TxnDebug("http_trans", "Error. No more retries.");
SET_VIA_STRING(VIA_DETAIL_SERVER_CONNECT, VIA_DETAIL_SERVER_FAILURE);
handle_server_connection_not_open(s);
}
@@ -3923,14 +3897,13 @@ HttpTransact::delete_server_rr_entry(State *s, int max_retries)
TxnDebug("http_trans", "[%d] failed to connect to %s", s->current.attempts,
ats_ip_ntop(&s->current.server->dst_addr.sa, addrbuf, sizeof(addrbuf)));
- TxnDebug("http_trans", "[delete_server_rr_entry] marking rr entry "
- "down and finding next one");
+ TxnDebug("http_trans", "marking rr entry down and finding next one");
ink_assert(s->current.server->had_connect_fail());
ink_assert(s->current.request_to == ORIGIN_SERVER);
ink_assert(s->current.server == &s->server_info);
update_dns_info(&s->dns_info, &s->current);
s->current.attempts++;
- TxnDebug("http_trans", "[delete_server_rr_entry] attempts now: %d, max: %d", s->current.attempts, max_retries);
+ TxnDebug("http_trans", "attempts now: %d, max: %d", s->current.attempts, max_retries);
TRANSACT_RETURN(SM_ACTION_ORIGIN_SERVER_RR_MARK_DOWN, ReDNSRoundRobin);
}
@@ -3992,7 +3965,7 @@ HttpTransact::retry_server_connection_not_open(State *s, ServerState_t conn_stat
s->current.server->keep_alive = HTTP_NO_KEEPALIVE;
s->current.attempts++;
- TxnDebug("http_trans", "[retry_server_connection_not_open] attempts now: %d, max: %d", s->current.attempts, max_retries);
+ TxnDebug("http_trans", "attempts now: %d, max: %d", s->current.attempts, max_retries);
return;
}
@@ -4012,8 +3985,8 @@ HttpTransact::handle_server_connection_not_open(State *s)
{
bool serve_from_cache = false;
- TxnDebug("http_trans", "[handle_server_connection_not_open] (hscno)");
- TxnDebug("http_seq", "[HttpTransact::handle_server_connection_not_open] ");
+ TxnDebug("http_trans", "(hscno)");
+ TxnDebug("http_seq", "Entering HttpTransact::handle_server_connection_not_open");
ink_assert(s->current.state != CONNECTION_ALIVE);
SET_VIA_STRING(VIA_SERVER_RESULT, VIA_SERVER_ERROR);
@@ -4101,8 +4074,8 @@ HttpTransact::handle_server_connection_not_open(State *s)
void
HttpTransact::handle_forward_server_connection_open(State *s)
{
- TxnDebug("http_trans", "[handle_forward_server_connection_open] (hfsco)");
- TxnDebug("http_seq", "[HttpTransact::handle_server_connection_open] ");
+ TxnDebug("http_trans", "(hfsco)");
+ TxnDebug("http_seq", "Entering HttpTransact::handle_server_connection_open");
ink_release_assert(s->current.state == CONNECTION_ALIVE);
HTTPVersion real_version = s->state_machine->get_server_version(s->hdr_info.server_response);
@@ -4292,8 +4265,8 @@ HttpTransact::build_response_copy(State *s, HTTPHdr *base_response, HTTPHdr *out
void
HttpTransact::handle_cache_operation_on_forward_server_response(State *s)
{
- TxnDebug("http_trans", "[handle_cache_operation_on_forward_server_response] (hcoofsr)");
- TxnDebug("http_seq", "[handle_cache_operation_on_forward_server_response]");
+ TxnDebug("http_trans", "(hcoofsr)");
+ TxnDebug("http_seq", "Entering handle_cache_operation_on_forward_server_response");
HTTPHdr *base_response = nullptr;
HTTPStatus server_response_code = HTTP_STATUS_NONE;
@@ -4789,8 +4762,8 @@ HttpTransact::handle_cache_operation_on_forward_server_response(State *s)
void
HttpTransact::handle_no_cache_operation_on_forward_server_response(State *s)
{
- TxnDebug("http_trans", "[handle_no_cache_operation_on_forward_server_response] (hncoofsr)");
- TxnDebug("http_seq", "[handle_no_cache_operation_on_forward_server_response]");
+ TxnDebug("http_trans", "(hncoofsr)");
+ TxnDebug("http_seq", "Entering handle_no_cache_operation_on_forward_server_response");
bool keep_alive = s->current.server->keep_alive == HTTP_KEEPALIVE;
const char *warn_text = nullptr;
@@ -5266,8 +5239,8 @@ HttpTransact::get_ka_info_from_config(State *s, ConnectionAttributes *server_inf
bool check_hostdb = false;
if (server_info->http_version > HTTP_0_9) {
- TxnDebug("http_trans", "get_ka_info_from_config, version already set server_info->http_version %d.%d",
- server_info->http_version.get_major(), server_info->http_version.get_minor());
+ TxnDebug("http_trans", "version already set server_info->http_version %d.%d", server_info->http_version.get_major(),
+ server_info->http_version.get_minor());
return false;
}
switch (s->txn_conf->send_http11_requests) {
@@ -5293,8 +5266,8 @@ HttpTransact::get_ka_info_from_config(State *s, ConnectionAttributes *server_inf
server_info->http_version = HTTP_1_1;
break;
}
- TxnDebug("http_trans", "get_ka_info_from_config, server_info->http_version %d.%d, check_hostdb %d",
- server_info->http_version.get_major(), server_info->http_version.get_minor(), check_hostdb);
+ TxnDebug("http_trans", "server_info->http_version %d.%d, check_hostdb %d", server_info->http_version.get_major(),
+ server_info->http_version.get_minor(), check_hostdb);
// Set keep_alive info based on the records.config setting
server_info->keep_alive = s->txn_conf->keep_alive_enabled_out ? HTTP_KEEPALIVE : HTTP_NO_KEEPALIVE;
@@ -5415,10 +5388,7 @@ HttpTransact::add_client_ip_to_outgoing_request(State *s, HTTPHdr *request)
// Add or append to the X-Forwarded-For header
if (s->txn_conf->insert_squid_x_forwarded_for) {
request->value_append_or_set(MIME_FIELD_X_FORWARDED_FOR, MIME_LEN_X_FORWARDED_FOR, ip_string, ip_string_size);
- TxnDebug("http_trans",
- "[add_client_ip_to_outgoing_request] Appended connecting client's "
- "(%s) to the X-Forwards header",
- ip_string);
+ TxnDebug("http_trans", "Appended connecting client's (%s) to the X-Forwards header", ip_string);
}
}
@@ -5589,7 +5559,7 @@ HttpTransact::set_client_request_state(State *s, HTTPHdr *incoming_hdr)
s->hdr_info.request_content_length = HTTP_UNDEFINED_CL; // content length less than zero is invalid
}
- TxnDebug("http_trans", "[set_client_request_state] set req cont length to %" PRId64, s->hdr_info.request_content_length);
+ TxnDebug("http_trans", "set req cont length to %" PRId64, s->hdr_info.request_content_length);
}
HttpTransact::ResponseError_t
@@ -5624,11 +5594,11 @@ HttpTransact::check_response_validity(State *s, HTTPHdr *incoming_hdr)
if (incoming_hdr->presence(MIME_PRESENCE_DATE)) {
time_t date_value = incoming_hdr->get_date();
if (date_value <= 0) {
- TxnDebug("http_trans", "[check_response_validity] Bogus date in response");
+ TxnDebug("http_trans", "Bogus date in response");
return BOGUS_OR_NO_DATE_IN_RESPONSE;
}
} else {
- TxnDebug("http_trans", "[check_response_validity] No date in response");
+ TxnDebug("http_trans", "No date in response");
return BOGUS_OR_NO_DATE_IN_RESPONSE;
}
#endif
@@ -5926,8 +5896,7 @@ HttpTransact::initialize_state_variables_from_response(State *s, HTTPHdr *incomi
}
if (s->current.server->keep_alive == HTTP_KEEPALIVE) {
- TxnDebug("http_hdrs", "[initialize_state_variables_from_response]"
- "Server is keep-alive.");
+ TxnDebug("http_hdrs", "Server is keep-alive.");
} else if (s->state_machine->ua_txn && s->state_machine->ua_txn->is_outbound_transparent() &&
s->state_machine->t_state.http_config_param->use_client_source_port) {
/* If we are reusing the client<->ATS 4-tuple for ATS<->server then if the server side is closed, we can't
@@ -5966,7 +5935,7 @@ HttpTransact::initialize_state_variables_from_response(State *s, HTTPHdr *incomi
const char *wks_value = hdrtoken_string_to_wks(enc_value, enc_val_len);
if (wks_value == HTTP_VALUE_CHUNKED && !is_response_body_precluded(status_code, s->method)) {
- TxnDebug("http_hdrs", "[init_state_vars_from_resp] transfer encoding: chunked!");
+ TxnDebug("http_hdrs", "transfer encoding: chunked!");
s->current.server->transfer_encoding = CHUNKED_ENCODING;
s->hdr_info.response_content_length = HTTP_UNDEFINED_CL;
@@ -6089,8 +6058,7 @@ HttpTransact::is_stale_cache_response_returnable(State *s)
cc_mask = (MIME_COOKED_MASK_CC_MUST_REVALIDATE | MIME_COOKED_MASK_CC_PROXY_REVALIDATE | MIME_COOKED_MASK_CC_NEED_REVALIDATE_ONCE |
MIME_COOKED_MASK_CC_NO_CACHE | MIME_COOKED_MASK_CC_NO_STORE | MIME_COOKED_MASK_CC_S_MAXAGE);
if ((cached_response->get_cooked_cc_mask() & cc_mask) || cached_response->is_pragma_no_cache_set()) {
- TxnDebug("http_trans", "[is_stale_cache_response_returnable] "
- "document headers prevent serving stale");
+ TxnDebug("http_trans", "document headers prevent serving stale");
return false;
}
// See how old the document really is. We don't want create a
@@ -6100,22 +6068,18 @@ HttpTransact::is_stale_cache_response_returnable(State *s)
cached_response, cached_response->get_date(), s->current.now);
// Negative age is overflow
if ((current_age < 0) || (current_age > s->txn_conf->cache_max_stale_age)) {
- TxnDebug("http_trans",
- "[is_stale_cache_response_returnable] "
- "document age is too large %" PRId64,
- (int64_t)current_age);
+ TxnDebug("http_trans", "document age is too large %" PRId64, (int64_t)current_age);
return false;
}
// If the stale document requires authorization, we can't return it either.
Authentication_t auth_needed = AuthenticationNeeded(s->txn_conf, &s->hdr_info.client_request, cached_response);
if (auth_needed != AUTHENTICATION_SUCCESS) {
- TxnDebug("http_trans", "[is_stale_cache_response_returnable] "
- "authorization prevent serving stale");
+ TxnDebug("http_trans", "authorization prevent serving stale");
return false;
}
- TxnDebug("http_trans", "[is_stale_cache_response_returnable] can serve stale");
+ TxnDebug("http_trans", "can serve stale");
return true;
}
@@ -6304,8 +6268,7 @@ HttpTransact::is_response_cacheable(State *s, HTTPHdr *request, HTTPHdr *respons
// of other trafficserver clients. The flag is set in the
// process_host_db_info method
if (!s->dns_info.lookup_validated && s->client_info.is_transparent) {
- TxnDebug("http_trans", "[is_response_cacheable] "
- "Lookup not validated. Possible DNS cache poison. Don't cache");
+ TxnDebug("http_trans", "Lookup not validated. Possible DNS cache poison. Don't cache");
return false;
}
@@ -6320,8 +6283,7 @@ HttpTransact::is_response_cacheable(State *s, HTTPHdr *request, HTTPHdr *respons
// be served to a GET url1 request, but we just match URL not method.
int req_method = request->method_get_wksidx();
if (!(HttpTransactHeaders::is_method_cacheable(s->http_config_param, req_method)) && s->api_req_cacheable == false) {
- TxnDebug("http_trans", "[is_response_cacheable] "
- "only GET, and some HEAD and POST are cacheable");
+ TxnDebug("http_trans", "only GET, and some HEAD and POST are cacheable");
return false;
}
// TxnDebug("http_trans", "[is_response_cacheable] method is cacheable");
@@ -6329,8 +6291,7 @@ HttpTransact::is_response_cacheable(State *s, HTTPHdr *request, HTTPHdr *respons
// should not be cached (same subsequent requests will not be
// looked up, either, so why cache this).
if (!(is_request_cache_lookupable(s))) {
- TxnDebug("http_trans", "[is_response_cacheable] "
- "request is not cache lookupable, response is not cacheable");
+ TxnDebug("http_trans", "request is not cache lookupable, response is not cacheable");
return false;
}
// already has a fresh copy in the cache
@@ -6342,20 +6303,18 @@ HttpTransact::is_response_cacheable(State *s, HTTPHdr *request, HTTPHdr *respons
// If there are cookies in response but a ttl is set, allow caching
if ((s->cache_control.ttl_in_cache <= 0) &&
do_cookies_prevent_caching(static_cast<int>(s->txn_conf->cache_responses_to_cookies), request, response)) {
- TxnDebug("http_trans", "[is_response_cacheable] "
- "response has uncachable cookies, response is not cacheable");
+ TxnDebug("http_trans", "response has uncachable cookies, response is not cacheable");
return false;
}
// if server spits back a WWW-Authenticate
if ((s->txn_conf->cache_ignore_auth) == 0 && response->presence(MIME_PRESENCE_WWW_AUTHENTICATE)) {
- TxnDebug("http_trans", "[is_response_cacheable] "
- "response has WWW-Authenticate, response is not cacheable");
+ TxnDebug("http_trans", "response has WWW-Authenticate, response is not cacheable");
return false;
}
// does server explicitly forbid storing?
// If OS forbids storing but a ttl is set, allow caching
if (!s->cache_info.directives.does_server_permit_storing && (s->cache_control.ttl_in_cache <= 0)) {
- TxnDebug("http_trans", "[is_response_cacheable] server does not permit storing and config file does not "
+ TxnDebug("http_trans", "server does not permit storing and config file does not "
"indicate that server directive should be ignored");
return false;
}
@@ -6365,7 +6324,7 @@ HttpTransact::is_response_cacheable(State *s, HTTPHdr *request, HTTPHdr *respons
// ttl overrides other config parameters
if ((!s->cache_info.directives.does_config_permit_storing && (s->cache_control.ttl_in_cache <= 0)) ||
(s->cache_control.never_cache)) {
- TxnDebug("http_trans", "[is_response_cacheable] config doesn't allow storing, and cache control does not "
+ TxnDebug("http_trans", "config doesn't allow storing, and cache control does not "
"say to ignore no-cache and does not specify never-cache or a ttl");
return false;
}
@@ -6373,11 +6332,11 @@ HttpTransact::is_response_cacheable(State *s, HTTPHdr *request, HTTPHdr *respons
// does client explicitly forbid storing?
if (!s->cache_info.directives.does_client_permit_storing && !s->cache_control.ignore_client_no_cache) {
- TxnDebug("http_trans", "[is_response_cacheable] client does not permit storing, "
+ TxnDebug("http_trans", "client does not permit storing, "
"and cache control does not say to ignore client no-cache");
return false;
}
- TxnDebug("http_trans", "[is_response_cacheable] client permits storing");
+ TxnDebug("http_trans", "client permits storing");
HTTPStatus response_code = response->status_get();
@@ -6393,15 +6352,13 @@ HttpTransact::is_response_cacheable(State *s, HTTPHdr *request, HTTPHdr *respons
// and we are configured to not cache without them.
switch (s->txn_conf->cache_required_headers) {
case HttpConfigParams::CACHE_REQUIRED_HEADERS_NONE:
- TxnDebug("http_trans", "[is_response_cacheable] "
- "no response headers required");
+ TxnDebug("http_trans", "no response headers required");
break;
case HttpConfigParams::CACHE_REQUIRED_HEADERS_AT_LEAST_LAST_MODIFIED:
if (!response->presence(MIME_PRESENCE_EXPIRES) && !(response->get_cooked_cc_mask() & cc_mask) &&
!response->get_last_modified()) {
- TxnDebug("http_trans", "[is_response_cacheable] "
- "last_modified, expires, or max-age is required");
+ TxnDebug("http_trans", "last_modified, expires, or max-age is required");
s->squid_codes.hit_miss_code = ((response->get_date() == 0) ? (SQUID_MISS_HTTP_NO_DLE) : (SQUID_MISS_HTTP_NO_LE));
return false;
@@ -6410,8 +6367,7 @@ HttpTransact::is_response_cacheable(State *s, HTTPHdr *request, HTTPHdr *respons
case HttpConfigParams::CACHE_REQUIRED_HEADERS_CACHE_CONTROL:
if (!response->presence(MIME_PRESENCE_EXPIRES) && !(response->get_cooked_cc_mask() & cc_mask)) {
- TxnDebug("http_trans", "[is_response_cacheable] "
- "expires header or max-age is required");
+ TxnDebug("http_trans", "expires header or max-age is required");
return false;
}
break;
@@ -6423,10 +6379,7 @@ HttpTransact::is_response_cacheable(State *s, HTTPHdr *request, HTTPHdr *respons
}
// do not cache partial content - Range response
if (response_code == HTTP_STATUS_PARTIAL_CONTENT || response_code == HTTP_STATUS_RANGE_NOT_SATISFIABLE) {
- TxnDebug("http_trans",
- "[is_response_cacheable] "
- "response code %d - don't cache",
- response_code);
+ TxnDebug("http_trans", "response code %d - don't cache", response_code);
return false;
}
@@ -6434,7 +6387,7 @@ HttpTransact::is_response_cacheable(State *s, HTTPHdr *request, HTTPHdr *respons
int indicator;
indicator = response_cacheable_indicated_by_cc(response);
if (indicator > 0) { // cacheable indicated by cache control header
- TxnDebug("http_trans", "[is_response_cacheable] YES by response cache control");
+ TxnDebug("http_trans", "YES by response cache control");
// even if it is authenticated, this is cacheable based on regular rules
s->www_auth_content = CACHE_AUTH_NONE;
return true;
@@ -6443,10 +6396,9 @@ HttpTransact::is_response_cacheable(State *s, HTTPHdr *request, HTTPHdr *respons
// If a ttl is set, allow caching even if response contains
// Cache-Control headers to prevent caching
if (s->cache_control.ttl_in_cache > 0) {
- TxnDebug("http_trans", "[is_response_cacheable] Cache-control header directives in response overridden by ttl in %s",
- ts::filename::CACHE);
+ TxnDebug("http_trans", "Cache-control header directives in response overridden by ttl in %s", ts::filename::CACHE);
} else {
- TxnDebug("http_trans", "[is_response_cacheable] NO by response cache control");
+ TxnDebug("http_trans", "NO by response cache control");
return false;
}
}
@@ -6454,21 +6406,21 @@ HttpTransact::is_response_cacheable(State *s, HTTPHdr *request, HTTPHdr *respons
// continue to determine cacheability
if (response->presence(MIME_PRESENCE_EXPIRES)) {
- TxnDebug("http_trans", "[is_response_cacheable] YES response w/ Expires");
+ TxnDebug("http_trans", "YES response w/ Expires");
return true;
}
// if it's a 302 or 307 and no positive indicator from cache-control, reject
if (response_code == HTTP_STATUS_MOVED_TEMPORARILY || response_code == HTTP_STATUS_TEMPORARY_REDIRECT) {
- TxnDebug("http_trans", "[is_response_cacheable] cache-control or expires header is required for 302");
+ TxnDebug("http_trans", "cache-control or expires header is required for 302");
return false;
}
// if it's a POST request and no positive indicator from cache-control
if (req_method == HTTP_WKSIDX_POST) {
// allow caching for a POST requests w/o Expires but with a ttl
if (s->cache_control.ttl_in_cache > 0) {
- TxnDebug("http_trans", "[is_response_cacheable] POST method with a TTL");
+ TxnDebug("http_trans", "POST method with a TTL");
} else {
- TxnDebug("http_trans", "[is_response_cacheable] NO POST w/o Expires or CC");
+ TxnDebug("http_trans", "NO POST w/o Expires or CC");
return false;
}
}
@@ -6476,7 +6428,7 @@ HttpTransact::is_response_cacheable(State *s, HTTPHdr *request, HTTPHdr *respons
if ((response_code == HTTP_STATUS_OK) || (response_code == HTTP_STATUS_NOT_MODIFIED) ||
(response_code == HTTP_STATUS_NON_AUTHORITATIVE_INFORMATION) || (response_code == HTTP_STATUS_MOVED_PERMANENTLY) ||
(response_code == HTTP_STATUS_MULTIPLE_CHOICES) || (response_code == HTTP_STATUS_GONE)) {
- TxnDebug("http_trans", "[is_response_cacheable] YES response code seems fine");
+ TxnDebug("http_trans", "YES response code seems fine");
return true;
}
// Notice that the following are not overridable by negative caching.
@@ -6512,10 +6464,10 @@ HttpTransact::is_request_valid(State *s, HTTPHdr *incoming_request)
incoming_error = check_request_validity(s, incoming_request);
switch (incoming_error) {
case NO_REQUEST_HEADER_ERROR:
- TxnDebug("http_trans", "[is_request_valid] no request header errors");
+ TxnDebug("http_trans", "no request header errors");
break;
case FAILED_PROXY_AUTHORIZATION:
- TxnDebug("http_trans", "[is_request_valid] failed proxy authorization");
+ TxnDebug("http_trans", "failed proxy authorization");
SET_VIA_STRING(VIA_DETAIL_TUNNEL, VIA_DETAIL_TUNNEL_NO_FORWARD);
build_error_response(s, HTTP_STATUS_PROXY_AUTHENTICATION_REQUIRED, "Proxy Authentication Required",
"access#proxy_auth_required");
@@ -6523,7 +6475,7 @@ HttpTransact::is_request_valid(State *s, HTTPHdr *incoming_request)
case NON_EXISTANT_REQUEST_HEADER:
/* fall through */
case BAD_HTTP_HEADER_SYNTAX: {
- TxnDebug("http_trans", "[is_request_valid] non-existent/bad header");
+ TxnDebug("http_trans", "non-existent/bad header");
SET_VIA_STRING(VIA_DETAIL_TUNNEL, VIA_DETAIL_TUNNEL_NO_FORWARD);
build_error_response(s, HTTP_STATUS_BAD_REQUEST, "Invalid HTTP Request", "request#syntax_error");
return false;
@@ -6546,7 +6498,7 @@ HttpTransact::is_request_valid(State *s, HTTPHdr *incoming_request)
// determine the cases should be hidden behind the method. //
////////////////////////////////////////////////////////////////////
- TxnDebug("http_trans", "[is_request_valid] missing host field");
+ TxnDebug("http_trans", "missing host field");
SET_VIA_STRING(VIA_DETAIL_TUNNEL, VIA_DETAIL_TUNNEL_NO_FORWARD);
if (s->http_config_param->reverse_proxy_enabled) { // host header missing and reverse proxy on
build_error_response(s, HTTP_STATUS_BAD_REQUEST, "Host Header Required", "request#no_host");
@@ -6558,37 +6510,37 @@ HttpTransact::is_request_valid(State *s, HTTPHdr *incoming_request)
return false;
case SCHEME_NOT_SUPPORTED:
case NO_REQUEST_SCHEME: {
- TxnDebug("http_trans", "[is_request_valid] unsupported or missing request scheme");
+ TxnDebug("http_trans", "unsupported or missing request scheme");
SET_VIA_STRING(VIA_DETAIL_TUNNEL, VIA_DETAIL_TUNNEL_NO_FORWARD);
build_error_response(s, HTTP_STATUS_BAD_REQUEST, "Unsupported URL Scheme", "request#scheme_unsupported");
return false;
}
/* fall through */
case METHOD_NOT_SUPPORTED:
- TxnDebug("http_trans", "[is_request_valid] unsupported method");
+ TxnDebug("http_trans", "unsupported method");
s->current.mode = TUNNELLING_PROXY;
return true;
case BAD_CONNECT_PORT:
int port;
port = url ? url->port_get() : 0;
- TxnDebug("http_trans", "[is_request_valid] %d is an invalid connect port", port);
+ TxnDebug("http_trans", "%d is an invalid connect port", port);
SET_VIA_STRING(VIA_DETAIL_TUNNEL, VIA_DETAIL_TUNNEL_NO_FORWARD);
build_error_response(s, HTTP_STATUS_FORBIDDEN, "Tunnel Forbidden", "access#connect_forbidden");
return false;
case NO_POST_CONTENT_LENGTH: {
- TxnDebug("http_trans", "[is_request_valid] post request without content length");
+ TxnDebug("http_trans", "post request without content length");
SET_VIA_STRING(VIA_DETAIL_TUNNEL, VIA_DETAIL_TUNNEL_NO_FORWARD);
build_error_response(s, HTTP_STATUS_LENGTH_REQUIRED, "Content Length Required", "request#no_content_length");
return false;
}
case UNACCEPTABLE_TE_REQUIRED: {
- TxnDebug("http_trans", "[is_request_valid] TE required is unacceptable.");
+ TxnDebug("http_trans", "TE required is unacceptable.");
SET_VIA_STRING(VIA_DETAIL_TUNNEL, VIA_DETAIL_TUNNEL_NO_FORWARD);
build_error_response(s, HTTP_STATUS_NOT_ACCEPTABLE, "Transcoding Not Available", "transcoding#unsupported");
return false;
}
case INVALID_POST_CONTENT_LENGTH: {
- TxnDebug("http_trans", "[is_request_valid] post request with negative content length value");
+ TxnDebug("http_trans", "post request with negative content length value");
SET_VIA_STRING(VIA_DETAIL_TUNNEL, VIA_DETAIL_TUNNEL_NO_FORWARD);
build_error_response(s, HTTP_STATUS_BAD_REQUEST, "Invalid Content Length", "request#invalid_content_length");
return false;
@@ -6837,7 +6789,7 @@ HttpTransact::handle_content_length_header(State *s, HTTPHdr *header, HTTPHdr *b
header->field_delete(MIME_FIELD_CONTENT_LENGTH, MIME_LEN_CONTENT_LENGTH);
s->hdr_info.trust_response_cl = false;
}
- TxnDebug("http_trans", "[handle_content_length_header] RESPONSE cont len in hdr is %" PRId64, header->get_content_length());
+ TxnDebug("http_trans", "RESPONSE cont len in hdr is %" PRId64, header->get_content_length());
} else {
// No content length header.
// If the source is cache or server returned 304 response,
@@ -7173,10 +7125,7 @@ HttpTransact::delete_all_document_alternates_and_return(State *s, bool cache_hit
}
if (s->method == HTTP_WKSIDX_PURGE || (valid_max_forwards && max_forwards <= 0)) {
- TxnDebug("http_trans",
- "[delete_all_document_alternates_and_return] "
- "DELETE with Max-Forwards: %d",
- max_forwards);
+ TxnDebug("http_trans", "DELETE with Max-Forwards: %d", max_forwards);
SET_VIA_STRING(VIA_DETAIL_TUNNEL, VIA_DETAIL_TUNNEL_NO_FORWARD);
@@ -7192,10 +7141,7 @@ HttpTransact::delete_all_document_alternates_and_return(State *s, bool cache_hit
} else {
if (valid_max_forwards) {
--max_forwards;
- TxnDebug("http_trans",
- "[delete_all_document_alternates_and_return] "
- "Decrementing max_forwards to %d",
- max_forwards);
+ TxnDebug("http_trans", "Decrementing max_forwards to %d", max_forwards);
s->hdr_info.client_request.value_set_int(MIME_FIELD_MAX_FORWARDS, MIME_LEN_MAX_FORWARDS, max_forwards);
}
}
@@ -7302,7 +7248,7 @@ HttpTransact::calculate_document_freshness_limit(State *s, HTTPHdr *response, ti
if (max_age >= 0) {
freshness_limit = std::min(std::max(0, max_age), static_cast<int>(s->txn_conf->cache_guaranteed_max_lifetime));
- TxnDebug("http_match", "calculate_document_freshness_limit --- freshness_limit = %d", freshness_limit);
+ TxnDebug("http_match", "freshness_limit = %d", freshness_limit);
} else {
date_set = last_modified_set = false;
@@ -7319,9 +7265,8 @@ HttpTransact::calculate_document_freshness_limit(State *s, HTTPHdr *response, ti
date_set = true;
} else {
date_value = s->request_sent_time;
- TxnDebug("http_match",
- "calculate_document_freshness_limit --- Expires header = %" PRId64 " no date, using sent time %" PRId64,
- (int64_t)expires_value, (int64_t)date_value);
+ TxnDebug("http_match", "Expires header = %" PRId64 " no date, using sent time %" PRId64, (int64_t)expires_value,
+ (int64_t)date_value);
}
ink_assert(date_value > 0);
@@ -7332,12 +7277,12 @@ HttpTransact::calculate_document_freshness_limit(State *s, HTTPHdr *response, ti
if (expires_set && !cache_sm.is_readwhilewrite_inprogress()) {
if (expires_value == UNDEFINED_TIME || expires_value <= date_value) {
expires_value = date_value;
- TxnDebug("http_match", "calculate_document_freshness_limit --- no expires, using date %" PRId64, (int64_t)expires_value);
+ TxnDebug("http_match", "no expires, using date %" PRId64, (int64_t)expires_value);
}
freshness_limit = static_cast<int>(expires_value - date_value);
- TxnDebug("http_match", "calculate_document_freshness_limit --- Expires: %" PRId64 ", Date: %" PRId64 ", freshness_limit = %d",
- (int64_t)expires_value, (int64_t)date_value, freshness_limit);
+ TxnDebug("http_match", "Expires: %" PRId64 ", Date: %" PRId64 ", freshness_limit = %d", (int64_t)expires_value,
+ (int64_t)date_value, freshness_limit);
freshness_limit = std::min(std::max(0, freshness_limit), static_cast<int>(s->txn_conf->cache_guaranteed_max_lifetime));
} else {
@@ -7345,15 +7290,13 @@ HttpTransact::calculate_document_freshness_limit(State *s, HTTPHdr *response, ti
if (response->presence(MIME_PRESENCE_LAST_MODIFIED)) {
last_modified_set = true;
last_modified_value = response->get_last_modified();
- TxnDebug("http_match", "calculate_document_freshness_limit --- Last Modified header = %" PRId64,
- (int64_t)last_modified_value);
+ TxnDebug("http_match", "Last Modified header = %" PRId64, (int64_t)last_modified_value);
if (last_modified_value == UNDEFINED_TIME) {
last_modified_set = false;
} else if (last_modified_value > date_value) {
last_modified_value = date_value;
- TxnDebug("http_match", "calculate_document_freshness_limit --- no last-modified, using sent time %" PRId64,
- (int64_t)last_modified_value);
+ TxnDebug("http_match", "no last-modified, using sent time %" PRId64, (int64_t)last_modified_value);
}
}
@@ -7365,12 +7308,11 @@ HttpTransact::calculate_document_freshness_limit(State *s, HTTPHdr *response, ti
int h_freshness = static_cast<int>(time_since_last_modify * f);
freshness_limit = std::max(h_freshness, 0);
TxnDebug("http_match",
- "calculate_document_freshness_limit --- heuristic: date=%" PRId64 ", lm=%" PRId64
- ", time_since_last_modify=%" PRId64 ", f=%g, freshness_limit = %d",
+ "heuristic: date=%" PRId64 ", lm=%" PRId64 ", time_since_last_modify=%" PRId64 ", f=%g, freshness_limit = %d",
(int64_t)date_value, (int64_t)last_modified_value, (int64_t)time_since_last_modify, f, freshness_limit);
} else {
freshness_limit = s->txn_conf->cache_heuristic_min_lifetime;
- TxnDebug("http_match", "calculate_document_freshness_limit --- heuristic: freshness_limit = %d", freshness_limit);
+ TxnDebug("http_match", "heuristic: freshness_limit = %d", freshness_limit);
}
}
}
@@ -7392,7 +7334,7 @@ HttpTransact::calculate_document_freshness_limit(State *s, HTTPHdr *response, ti
freshness_limit = min_freshness_bounds;
}
- TxnDebug("http_match", "calculate_document_freshness_limit --- final freshness_limit = %d", freshness_limit);
+ TxnDebug("http_match", "final freshness_limit = %d", freshness_limit);
return (freshness_limit);
}
@@ -7422,7 +7364,7 @@ HttpTransact::what_is_document_freshness(State *s, HTTPHdr *client_request, HTTP
if (s->cache_open_write_fail_action & CACHE_WL_FAIL_ACTION_STALE_ON_REVALIDATE) {
if (is_stale_cache_response_returnable(s)) {
- TxnDebug("http_match", "[what_is_document_freshness] cache_serve_stale_on_write_lock_fail, return FRESH");
+ TxnDebug("http_match", "cache_serve_stale_on_write_lock_fail, return FRESH");
return (FRESHNESS_FRESH);
}
}
@@ -7437,8 +7379,7 @@ HttpTransact::what_is_document_freshness(State *s, HTTPHdr *client_request, HTTP
// but for how long it has been stored in the cache (resident time)
int resident_time = s->current.now - s->response_received_time;
- TxnDebug("http_match", "[..._document_freshness] ttl-in-cache = %d, resident time = %d", s->cache_control.ttl_in_cache,
- resident_time);
+ TxnDebug("http_match", "ttl-in-cache = %d, resident time = %d", s->cache_control.ttl_in_cache, resident_time);
if (resident_time > s->cache_control.ttl_in_cache) {
return (FRESHNESS_STALE);
} else {
@@ -7453,8 +7394,7 @@ HttpTransact::what_is_document_freshness(State *s, HTTPHdr *client_request, HTTP
// Check to see if the server forces revalidation
if ((cooked_cc_mask & cc_mask) && s->cache_control.revalidate_after <= 0) {
- TxnDebug("http_match", "[what_is_document_freshness] document stale due to "
- "server must-revalidate");
+ TxnDebug("http_match", "document stale due to server must-revalidate");
return FRESHNESS_STALE;
}
@@ -7477,7 +7417,7 @@ HttpTransact::what_is_document_freshness(State *s, HTTPHdr *client_request, HTTP
current_age = std::max(static_cast<time_t>(s->txn_conf->cache_guaranteed_max_lifetime), current_age);
}
- TxnDebug("http_match", "[what_is_document_freshness] fresh_limit: %d current_age: %" PRId64, fresh_limit, (int64_t)current_age);
+ TxnDebug("http_match", "fresh_limit: %d current_age: %" PRId64, fresh_limit, (int64_t)current_age);
ink_assert(client_request == &s->hdr_info.client_request);
@@ -7488,22 +7428,19 @@ HttpTransact::what_is_document_freshness(State *s, HTTPHdr *client_request, HTTP
break;
case 1: // Stale if heuristic
if (heuristic) {
- TxnDebug("http_match", "[what_is_document_freshness] config requires FRESHNESS_STALE because heuristic calculation");
+ TxnDebug("http_match", "config requires FRESHNESS_STALE because heuristic calculation");
return (FRESHNESS_STALE);
}
break;
case 2: // Always stale
- TxnDebug("http_match", "[what_is_document_freshness] config "
- "specifies always FRESHNESS_STALE");
+ TxnDebug("http_match", "config specifies always FRESHNESS_STALE");
return (FRESHNESS_STALE);
case 3: // Never stale
- TxnDebug("http_match", "[what_is_document_freshness] config "
- "specifies always FRESHNESS_FRESH");
+ TxnDebug("http_match", "config specifies always FRESHNESS_FRESH");
return (FRESHNESS_FRESH);
case 4: // Stale if IMS
if (client_request->presence(MIME_PRESENCE_IF_MODIFIED_SINCE)) {
- TxnDebug("http_match", "[what_is_document_freshness] config "
- "specifies FRESHNESS_STALE if IMS present");
+ TxnDebug("http_match", "config specifies FRESHNESS_STALE if IMS present");
return (FRESHNESS_STALE);
}
default: // Bad config, ignore
@@ -7520,7 +7457,7 @@ HttpTransact::what_is_document_freshness(State *s, HTTPHdr *client_request, HTTP
// max-stale: (current_age <= fresh_limit + max_stale) //
//////////////////////////////////////////////////////////////////////
age_limit = fresh_limit; // basic constraint
- TxnDebug("http_match", "[..._document_freshness] initial age limit: %d", age_limit);
+ TxnDebug("http_match", "initial age limit: %d", age_limit);
cooked_cc_mask = client_request->get_cooked_cc_mask();
cc_mask = (MIME_COOKED_MASK_CC_MAX_STALE | MIME_COOKED_MASK_CC_MIN_FRESH | MIME_COOKED_MASK_CC_MAX_AGE);
@@ -7530,8 +7467,7 @@ HttpTransact::what_is_document_freshness(State *s, HTTPHdr *client_request, HTTP
/////////////////////////////////////////////////
if (cooked_cc_mask & MIME_COOKED_MASK_CC_MAX_STALE) {
if (os_specifies_revalidate) {
- TxnDebug("http_match", "[...document_freshness] OS specifies revalidation; "
- "ignoring client's max-stale request...");
+ TxnDebug("http_match", "OS specifies revalidation; ignoring client's max-stale request...");
} else {
int max_stale_val = client_request->get_cooked_cc_max_stale();
@@ -7540,7 +7476,7 @@ HttpTransact::what_is_document_freshness(State *s, HTTPHdr *client_request, HTTP
} else {
age_limit = max_stale_val;
}
- TxnDebug("http_match", "[..._document_freshness] max-stale set, age limit: %d", age_limit);
+ TxnDebug("http_match", "max-stale set, age limit: %d", age_limit);
}
}
/////////////////////////////////////////////////////
@@ -7548,7 +7484,7 @@ HttpTransact::what_is_document_freshness(State *s, HTTPHdr *client_request, HTTP
/////////////////////////////////////////////////////
if (cooked_cc_mask & MIME_COOKED_MASK_CC_MIN_FRESH) {
age_limit = std::min(age_limit, fresh_limit - client_request->get_cooked_cc_min_fresh());
- TxnDebug("http_match", "[..._document_freshness] min_fresh set, age limit: %d", age_limit);
+ TxnDebug("http_match", "min_fresh set, age limit: %d", age_limit);
}
///////////////////////////////////////////////////
// if max-age set, constrain the freshness limit //
@@ -7559,7 +7495,7 @@ HttpTransact::what_is_document_freshness(State *s, HTTPHdr *client_request, HTTP
do_revalidate = true;
}
age_limit = std::min(age_limit, age_val);
- TxnDebug("http_match", "[..._document_freshness] min_fresh set, age limit: %d", age_limit);
+ TxnDebug("http_match", "min_fresh set, age limit: %d", age_limit);
}
}
/////////////////////////////////////////////////////////
@@ -7573,7 +7509,7 @@ HttpTransact::what_is_document_freshness(State *s, HTTPHdr *client_request, HTTP
// if instead the revalidate_after overrides all other variables
age_limit = s->cache_control.revalidate_after;
- TxnDebug("http_match", "[..._document_freshness] revalidate_after set, age limit: %d", age_limit);
+ TxnDebug("http_match", "revalidate_after set, age limit: %d", age_limit);
}
TxnDebug("http_match", "document_freshness --- current_age = %" PRId64, (int64_t)current_age);
@@ -7587,20 +7523,20 @@ HttpTransact::what_is_document_freshness(State *s, HTTPHdr *client_request, HTTP
///////////////////////////////////////////
if (do_revalidate || !age_limit || current_age > age_limit) { // client-modified limit
- TxnDebug("http_match", "[..._document_freshness] document needs revalidate/too old; "
+ TxnDebug("http_match", "document needs revalidate/too old; "
"returning FRESHNESS_STALE");
return (FRESHNESS_STALE);
} else if (current_age > fresh_limit) { // original limit
if (os_specifies_revalidate) {
- TxnDebug("http_match", "[..._document_freshness] document is stale and OS specifies revalidation; "
+ TxnDebug("http_match", "document is stale and OS specifies revalidation; "
"returning FRESHNESS_STALE");
return (FRESHNESS_STALE);
}
- TxnDebug("http_match", "[..._document_freshness] document is stale but no revalidation explicitly required; "
+ TxnDebug("http_match", "document is stale but no revalidation explicitly required; "
"returning FRESHNESS_WARNING");
return (FRESHNESS_WARNING);
} else {
- TxnDebug("http_match", "[..._document_freshness] document is fresh; returning FRESHNESS_FRESH");
+ TxnDebug("http_match", "document is fresh; returning FRESHNESS_FRESH");
return (FRESHNESS_FRESH);
}
}
@@ -7895,14 +7831,14 @@ HttpTransact::build_request(State *s, HTTPHdr *base_request, HTTPHdr *outgoing_r
} else if (s->current.request_to == PARENT_PROXY && parent_is_proxy(s)) {
// If we have a parent proxy set the URL target field.
if (!outgoing_request->is_target_in_url()) {
- TxnDebug("http_trans", "[build_request] adding target to URL for parent proxy");
+ TxnDebug("http_trans", "adding target to URL for parent proxy");
outgoing_request->set_url_target_from_host_field();
}
} else if (s->next_hop_scheme == URL_WKSIDX_HTTP || s->next_hop_scheme == URL_WKSIDX_HTTPS ||
s->next_hop_scheme == URL_WKSIDX_WS || s->next_hop_scheme == URL_WKSIDX_WSS) {
// Otherwise, remove the URL target from HTTP and Websocket URLs since certain origins
// cannot deal with absolute URLs.
- TxnDebug("http_trans", "[build_request] removing host name from url");
+ TxnDebug("http_trans", "removing host name from url");
HttpTransactHeaders::remove_host_name_from_url(outgoing_request);
}
@@ -7914,24 +7850,21 @@ HttpTransact::build_request(State *s, HTTPHdr *base_request, HTTPHdr *outgoing_r
if (s->current.mode == GENERIC_PROXY) {
if (is_request_likely_cacheable(s, base_request)) {
if (s->txn_conf->cache_when_to_revalidate != 4) {
- TxnDebug("http_trans", "[build_request] "
- "request like cacheable and conditional headers removed");
+ TxnDebug("http_trans", "request like cacheable and conditional headers removed");
HttpTransactHeaders::remove_conditional_headers(outgoing_request);
} else {
- TxnDebug("http_trans", "[build_request] "
- "request like cacheable but keep conditional headers");
+ TxnDebug("http_trans", "request like cacheable but keep conditional headers");
}
} else {
// In this case, we send a conditional request
// instead of the normal non-conditional request.
- TxnDebug("http_trans", "[build_request] "
- "request not like cacheable and conditional headers not removed");
+ TxnDebug("http_trans", "request not like cacheable and conditional headers not removed");
}
}
if (s->http_config_param->send_100_continue_response) {
HttpTransactHeaders::remove_100_continue_headers(s, outgoing_request);
- TxnDebug("http_trans", "[build_request] request expect 100-continue headers removed");
+ TxnDebug("http_trans", "request expect 100-continue headers removed");
}
if (base_request->is_early_data()) {
@@ -7944,7 +7877,7 @@ HttpTransact::build_request(State *s, HTTPHdr *base_request, HTTPHdr *outgoing_r
// The assert is backwards in this case because request is being (re)sent.
ink_assert(s->request_sent_time >= s->response_received_time);
- TxnDebug("http_trans", "[build_request] request_sent_time: %" PRId64, (int64_t)s->request_sent_time);
+ TxnDebug("http_trans", "request_sent_time: %" PRId64, (int64_t)s->request_sent_time);
DUMP_HEADER("http_hdrs", outgoing_request, s->state_machine_id, "Proxy's Request");
HTTP_INCREMENT_DYN_STAT(http_outgoing_requests_stat);
@@ -8299,7 +8232,7 @@ HttpTransact::build_error_response(State *s, HTTPStatus status_code, const char
void
HttpTransact::build_redirect_response(State *s)
{
- TxnDebug("http_redirect", "[HttpTransact::build_redirect_response]");
+ TxnDebug("http_redirect", "Entering HttpTransact::build_redirect_response");
URL *u;
const char *old_host;
int old_host_len;
diff --git a/proxy/http/HttpTunnel.cc b/proxy/http/HttpTunnel.cc
index 564adc23b..abe085727 100644
--- a/proxy/http/HttpTunnel.cc
+++ b/proxy/http/HttpTunnel.cc
@@ -1174,7 +1174,7 @@ HttpTunnel::producer_handler(int event, HttpTunnelProducer *p)
}
} // end of added logic for partial copy of POST
- Debug("http_redirect", "[HttpTunnel::producer_handler] enable_redirection: [%d %d %d] event: %d, state: %d", p->alive == true,
+ Debug("http_redirect", "[%" PRId64 "] enable_redirection: [%d %d %d] event: %d, state: %d", sm->sm_id, p->alive == true,
sm->enable_redirection, (p->self_consumer && p->self_consumer->alive == true), event, p->chunked_handler.state);
switch (event) {
@@ -1281,7 +1281,7 @@ HttpTunnel::consumer_reenable(HttpTunnelConsumer *c)
if (backlog >= flow_state.high_water) {
if (is_debug_tag_set("http_tunnel")) {
- Debug("http_tunnel", "Throttle %p %" PRId64 " / %" PRId64, p, backlog, p->backlog());
+ Debug("http_tunnel", "[%" PRId64 "] Throttle %p %" PRId64 " / %" PRId64, sm->sm_id, p, backlog, p->backlog());
}
p->throttle(); // p becomes srcp for future calls to this method
} else {
@@ -1296,7 +1296,7 @@ HttpTunnel::consumer_reenable(HttpTunnelConsumer *c)
}
if (backlog < flow_state.low_water) {
if (is_debug_tag_set("http_tunnel")) {
- Debug("http_tunnel", "Unthrottle %p %" PRId64 " / %" PRId64, p, backlog, p->backlog());
+ Debug("http_tunnel", "[%" PRId64 "] Unthrottle %p %" PRId64 " / %" PRId64, sm->sm_id, p, backlog, p->backlog());
}
srcp->unthrottle();
if (srcp->read_vio) {
diff --git a/proxy/http2/Http2Stream.cc b/proxy/http2/Http2Stream.cc
index a2bb06f32..a3e37819d 100644
--- a/proxy/http2/Http2Stream.cc
+++ b/proxy/http2/Http2Stream.cc
@@ -25,7 +25,8 @@
#include "HTTP2.h"
#include "Http2ClientSession.h"
-#include "../http/HttpSM.h"
+#include "HttpDebugNames.h"
+#include "HttpSM.h"
#include <numeric>
@@ -279,6 +280,7 @@ Http2Stream::send_request(Http2ConnectionState &cstate)
bool
Http2Stream::change_state(uint8_t type, uint8_t flags)
{
+ auto const initial_state = _state;
switch (_state) {
case Http2StreamState::HTTP2_STREAM_STATE_IDLE:
if (type == HTTP2_FRAME_TYPE_HEADERS) {
@@ -373,7 +375,7 @@ Http2Stream::change_state(uint8_t type, uint8_t flags)
return false;
}
- Http2StreamDebug("%s", Http2DebugNames::get_state_name(_state));
+ Http2StreamDebug("%s -> %s", Http2DebugNames::get_state_name(initial_state), Http2DebugNames::get_state_name(_state));
return true;
}