apache · shinrich · Apr 6, 2021 · Dec 16, 2020
diff --git a/proxy/http/HttpSM.cc b/proxy/http/HttpSM.cc
@@ -1222,10 +1222,12 @@ HttpSM::state_raw_http_server_open(int event, void *data)
 
     netvc->set_inactivity_timeout(get_server_inactivity_timeout());
     netvc->set_active_timeout(get_server_active_timeout());
+    t_state.current.server->clear_connect_fail();
     break;
 
   case VC_EVENT_ERROR:
   case NET_EVENT_OPEN_FAILED:
+    t_state.set_connect_fail(server_session->get_netvc()->lerrno);
     t_state.current.state = HttpTransact::OPEN_RAW_ERROR;
     // use this value just to get around other values
     t_state.hdr_info.response_error = HttpTransact::STATUS_CODE_SERVER_ERROR;
@@ -1867,8 +1869,11 @@ HttpSM::state_http_server_open(int event, void *data)
       }
 
       server_entry->write_vio = server_session->do_io_write(this, nbytes, server_session->get_reader());
-    } else {
-      // in the case of an intercept plugin don't to the connect timeout change
+
+      // Pre-emptively set a server connect failure that will be cleared once a WRITE_READY is received from origin or
+      // 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);
       handle_http_server_open();
     }
@@ -1884,6 +1889,7 @@ HttpSM::state_http_server_open(int event, void *data)
 
     // Reset the timeout to the non-connect timeout
     server_session->set_inactivity_timeout(get_server_inactivity_timeout());
+    t_state.current.server->clear_connect_fail();
     handle_http_server_open();
     return 0;
   case EVENT_INTERVAL: // Delayed call from another thread
@@ -1893,18 +1899,19 @@ HttpSM::state_http_server_open(int event, void *data)
     break;
   case VC_EVENT_INACTIVITY_TIMEOUT:
   case VC_EVENT_ACTIVE_TIMEOUT:
+    t_state.set_connect_fail(ETIMEDOUT);
+  /* fallthrough */
   case VC_EVENT_ERROR:
   case NET_EVENT_OPEN_FAILED: {
     if (server_session) {
       NetVConnection *vc = server_session->get_netvc();
       if (vc) {
+        t_state.set_connect_fail(vc->lerrno);
         server_connection_provided_cert = vc->provided_cert();
       }
     }
 
     t_state.current.state = HttpTransact::CONNECTION_ERROR;
-    // save the errno from the connect fail for future use (passed as negative value, flip back)
-    t_state.current.server->set_connect_fail(event == NET_EVENT_OPEN_FAILED ? -reinterpret_cast<intptr_t>(data) : ECONNABORTED);
     t_state.outbound_conn_track_state.clear();
 
     /* If we get this error in transparent mode, then we simply can't bind to the 4-tuple to make the connection.  There's no hope
@@ -3076,7 +3083,9 @@ HttpSM::tunnel_handler_server(int event, HttpTunnelProducer *p)
       t_state.current.server->abort      = HttpTransact::ABORTED;
       t_state.client_info.keep_alive     = HTTP_NO_KEEPALIVE;
       t_state.current.server->keep_alive = HTTP_NO_KEEPALIVE;
-      t_state.squid_codes.log_code       = SQUID_LOG_ERR_READ_ERROR;
+      if (event == VC_EVENT_EOS) {
+        t_state.squid_codes.log_code = SQUID_LOG_ERR_READ_ERROR;
+      }
     } else {
       SMDebug("http", "[%" PRId64 "] [HttpSM::tunnel_handler_server] finishing HTTP tunnel", sm_id);
       p->read_success               = true;
@@ -3672,6 +3681,28 @@ HttpSM::tunnel_handler_post_server(int event, HttpTunnelConsumer *c)
   case VC_EVENT_ERROR:
   case VC_EVENT_INACTIVITY_TIMEOUT:
   case VC_EVENT_ACTIVE_TIMEOUT:
+
+    switch (event) {
+    case VC_EVENT_INACTIVITY_TIMEOUT:
+      t_state.current.state = HttpTransact::INACTIVE_TIMEOUT;
+      t_state.set_connect_fail(ETIMEDOUT);
+      break;
+    case VC_EVENT_ACTIVE_TIMEOUT:
+      t_state.current.state = HttpTransact::ACTIVE_TIMEOUT;
+      t_state.set_connect_fail(ETIMEDOUT);
+      break;
+    case VC_EVENT_EOS:
+      t_state.current.state = HttpTransact::CONNECTION_CLOSED;
+      t_state.set_connect_fail(EPIPE);
+      break;
+    case VC_EVENT_ERROR:
+      t_state.current.state = HttpTransact::CONNECTION_CLOSED;
+      t_state.set_connect_fail(server_session->get_netvc()->lerrno);
+      break;
+    default:
+      break;
+    }
+
     //  Did not complete post tunneling
     //
     //    In the http case, we don't want to close
@@ -5379,7 +5410,7 @@ HttpSM::mark_host_failure(HostDBInfo *info, time_t time_down)
         char *url_str = t_state.hdr_info.client_request.url_string_get(&t_state.arena, nullptr);
         Log::error("%s", lbw()
                            .clip(1)
-                           .print("CONNECT Error: {} connecting to {} for '{}' (setting last failure time)",
+                           .print("CONNECT Error: {} connecting to {} for '{}' marking down",
                                   ts::bwf::Errno(t_state.current.server->connect_result), t_state.current.server->dst_addr,
                                   ts::bwf::FirstOf(url_str, "<none>"))
                            .extend(1)
@@ -5474,7 +5505,7 @@ HttpSM::mark_server_down_on_client_abort()
         wait = 0;
       }
       if (ink_hrtime_to_sec(wait) > t_state.txn_conf->client_abort_threshold) {
-        t_state.current.server->set_connect_fail(ETIMEDOUT);
+        t_state.set_connect_fail(ETIMEDOUT);
         do_hostdb_update_if_necessary();
       }
     }
@@ -5590,7 +5621,10 @@ HttpSM::handle_post_failure()
     tunnel.deallocate_buffers();
     tunnel.reset();
     // Server died
-    t_state.current.state = HttpTransact::CONNECTION_CLOSED;
+    if (t_state.current.state == HttpTransact::STATE_UNDEFINED || t_state.current.state == HttpTransact::CONNECTION_ALIVE) {
+      t_state.set_connect_fail(server_session->get_netvc()->lerrno);
+      t_state.current.state = HttpTransact::CONNECTION_CLOSED;
+    }
     call_transact_and_set_next_state(HttpTransact::HandleResponse);
   }
 }
@@ -5708,12 +5742,14 @@ HttpSM::handle_server_setup_error(int event, void *data)
   switch (event) {
   case VC_EVENT_EOS:
     t_state.current.state = HttpTransact::CONNECTION_CLOSED;
+    t_state.set_connect_fail(EPIPE);
     break;
   case VC_EVENT_ERROR:
-    t_state.current.state        = HttpTransact::CONNECTION_ERROR;
-    t_state.cause_of_death_errno = server_session->get_netvc()->lerrno;
+    t_state.current.state = HttpTransact::CONNECTION_ERROR;
+    t_state.set_connect_fail(server_session->get_netvc()->lerrno);
     break;
   case VC_EVENT_ACTIVE_TIMEOUT:
+    t_state.set_connect_fail(ETIMEDOUT);
     t_state.current.state = HttpTransact::ACTIVE_TIMEOUT;
     break;
 
@@ -5723,6 +5759,7 @@ HttpSM::handle_server_setup_error(int event, void *data)
     //   server failed
     // In case of TIMEOUT, the iocore sends back
     // server_entry->read_vio instead of the write_vio
+    t_state.set_connect_fail(ETIMEDOUT);
     if (server_entry->write_vio && server_entry->write_vio->nbytes > 0 && server_entry->write_vio->ndone == 0) {
       t_state.current.state = HttpTransact::CONNECTION_ERROR;
     } else {
@@ -7735,6 +7772,9 @@ HttpSM::set_next_state()
   }
 
   case HttpTransact::SM_ACTION_ORIGIN_SERVER_RAW_OPEN: {
+    // Pre-emptively set a server connect failure that will be cleared once a WRITE_READY is received from origin or
+    // bytes are received back
+    t_state.set_connect_fail(EIO);
     HTTP_SM_SET_DEFAULT_HANDLER(&HttpSM::state_raw_http_server_open);
 
     ink_assert(server_entry == nullptr);

diff --git a/proxy/http/HttpTransact.cc b/proxy/http/HttpTransact.cc
@@ -35,6 +35,7 @@
 #include <ctime>
 #include "tscore/ParseRules.h"
 #include "tscore/Filenames.h"
+#include "tscore/bwf_std_format.h"
 #include "HTTP.h"
 #include "HdrUtils.h"
 #include "logging/Log.h"
@@ -89,6 +90,9 @@ static char range_type[] = "multipart/byteranges; boundary=RANGE_SEPARATOR";
 
 extern HttpBodyFactory *body_factory;
 
+// Handy typedef for short (single line) message generation.
+using lbw = ts::LocalBufferWriter<256>;
+
 // wrapper to choose between a remap next hop strategy or use parent.config
 // remap next hop strategy is preferred
 inline static bool
@@ -1826,10 +1830,14 @@ HttpTransact::ReDNSRoundRobin(State *s)
     s->next_action = how_to_open_connection(s);
   } else {
     // Our ReDNS failed so output the DNS failure error message
-    build_error_response(s, HTTP_STATUS_BAD_GATEWAY, "Cannot find server.", "connect#dns_failed");
+    // Set to internal server error so later logging will pick up SQUID_LOG_ERR_DNS_FAIL
+    build_error_response(s, HTTP_STATUS_INTERNAL_SERVER_ERROR, "Cannot find server.", "connect#dns_failed");
     s->cache_info.action = CACHE_DO_NO_ACTION;
     s->next_action       = SM_ACTION_SEND_ERROR_CACHE_NOOP;
     //  s->next_action = PROXY_INTERNAL_CACHE_NOOP;
+    char *url_str = s->hdr_info.client_request.url_string_get(&s->arena, nullptr);
+    Log::error("%s",
+               lbw().clip(1).print("DNS Error: looking up {}", ts::bwf::FirstOf(url_str, "<none>")).extend(1).write('\0').data());
   }
 
   return;
@@ -1890,7 +1898,12 @@ HttpTransact::OSDNSLookup(State *s)
 
       // output the DNS failure error message
       SET_VIA_STRING(VIA_DETAIL_TUNNEL, VIA_DETAIL_TUNNEL_NO_FORWARD);
-      build_error_response(s, HTTP_STATUS_BAD_GATEWAY, "Cannot find server.", "connect#dns_failed");
+      // Set to internal server error so later logging will pick up SQUID_LOG_ERR_DNS_FAIL
+      build_error_response(s, HTTP_STATUS_INTERNAL_SERVER_ERROR, "Cannot find server.", "connect#dns_failed");
+      char *url_str = s->hdr_info.client_request.url_string_get(&s->arena, nullptr);
+      Log::error("%s",
+                 lbw().clip(1).print("DNS Error: looking up {}", ts::bwf::FirstOf(url_str, "<none>")).extend(1).write('\0').data());
+      // s->cache_info.action = CACHE_DO_NO_ACTION;
       TRANSACT_RETURN(SM_ACTION_SEND_ERROR_CACHE_NOOP, nullptr);
     }
     return;
@@ -3709,26 +3722,16 @@ HttpTransact::handle_response_from_server(State *s)
   case OUTBOUND_CONGESTION:
     TxnDebug("http_trans", "[handle_response_from_server] Error. congestion control -- congested.");
     SET_VIA_STRING(VIA_DETAIL_SERVER_CONNECT, VIA_DETAIL_SERVER_FAILURE);
-    s->current.server->set_connect_fail(EUSERS); // too many users
+    s->set_connect_fail(EUSERS); // too many users
     handle_server_connection_not_open(s);
     break;
   case OPEN_RAW_ERROR:
-  /* fall through */
   case CONNECTION_ERROR:
-  /* fall through */
   case STATE_UNDEFINED:
-  /* fall through */
   case INACTIVE_TIMEOUT:
-  /* fall through */
   case PARSE_ERROR:
-  /* fall through */
   case CONNECTION_CLOSED:
-  /* fall through */
   case BAD_INCOMING_RESPONSE:
-    // Set to generic I/O error if not already set specifically.
-    if (!s->current.server->had_connect_fail()) {
-      s->current.server->set_connect_fail(EIO);
-    }
 
     if (is_server_negative_cached(s)) {
       max_connect_retries = s->txn_conf->connect_attempts_max_retries_dead_server - 1;
@@ -3776,6 +3779,7 @@ HttpTransact::handle_response_from_server(State *s)
         return;
       }
     } else {
+      error_log_connection_failure(s, s->current.state);
       TxnDebug("http_trans", "[handle_response_from_server] Error. No more retries.");
       SET_VIA_STRING(VIA_DETAIL_SERVER_CONNECT, VIA_DETAIL_SERVER_FAILURE);
       handle_server_connection_not_open(s);
@@ -3784,7 +3788,7 @@ HttpTransact::handle_response_from_server(State *s)
   case ACTIVE_TIMEOUT:
     TxnDebug("http_trans", "[hrfs] connection not alive");
     SET_VIA_STRING(VIA_DETAIL_SERVER_CONNECT, VIA_DETAIL_SERVER_FAILURE);
-    s->current.server->set_connect_fail(ETIMEDOUT);
+    s->set_connect_fail(ETIMEDOUT);
     handle_server_connection_not_open(s);
     break;
   default:
@@ -3825,6 +3829,28 @@ HttpTransact::delete_server_rr_entry(State *s, int max_retries)
   TRANSACT_RETURN(SM_ACTION_ORIGIN_SERVER_RR_MARK_DOWN, ReDNSRoundRobin);
 }
 
+void
+HttpTransact::error_log_connection_failure(State *s, ServerState_t conn_state)
+{
+  char addrbuf[INET6_ADDRSTRLEN];
+
+  TxnDebug("http_trans", "[%d] failed to connect [%d] to %s", s->current.attempts, conn_state,
+           ats_ip_ntop(&s->current.server->dst_addr.sa, addrbuf, sizeof(addrbuf)));
+
+  //////////////////////////////////////////
+  // on the first connect attempt failure //
+  // record the failue                   //
+  //////////////////////////////////////////
+  if (0 == s->current.attempts) {
+    char *url_string = s->hdr_info.client_request.url_string_get(&s->arena);
+    Log::error("CONNECT: first attempt could not connect [%s] to %s for '%s' connect_result=%d src_port=%d cause_of_death_errno=%d",
+               HttpDebugNames::get_server_state_name(conn_state),
+               ats_ip_ntop(&s->current.server->dst_addr.sa, addrbuf, sizeof(addrbuf)), url_string ? url_string : "<none>",
+               s->current.server->connect_result, ntohs(s->current.server->src_addr.port()), s->cause_of_death_errno);
+    s->arena.str_free(url_string);
+  }
+}
+
 ///////////////////////////////////////////////////////////////////////////////
 // Name       : retry_server_connection_not_open
 // Description:
@@ -3843,28 +3869,10 @@ HttpTransact::retry_server_connection_not_open(State *s, ServerState_t conn_stat
   ink_assert(s->current.state != CONNECTION_ALIVE);
   ink_assert(s->current.state != ACTIVE_TIMEOUT);
   ink_assert(s->current.attempts <= max_retries);
-  ink_assert(s->current.server->had_connect_fail());
-  char addrbuf[INET6_ADDRSTRLEN];
+  ink_assert(s->cause_of_death_errno != -UNKNOWN_INTERNAL_ERROR);
 
-  char *url_string = s->hdr_info.client_request.url_string_get(&s->arena);
+  error_log_connection_failure(s, conn_state);
 
-  TxnDebug("http_trans", "[%d] failed to connect [%d] to %s", s->current.attempts, conn_state,
-           ats_ip_ntop(&s->current.server->dst_addr.sa, addrbuf, sizeof(addrbuf)));
-
-  //////////////////////////////////////////
-  // on the first connect attempt failure //
-  // record the failue                   //
-  //////////////////////////////////////////
-  if (0 == s->current.attempts) {
-    Log::error("CONNECT:[%d] could not connect [%s] to %s for '%s' connect_result=%d src_port=%d", s->current.attempts,
-               HttpDebugNames::get_server_state_name(conn_state),
-               ats_ip_ntop(&s->current.server->dst_addr.sa, addrbuf, sizeof(addrbuf)), url_string ? url_string : "<none>",
-               s->current.server->connect_result, ntohs(s->current.server->src_addr.port()));
-  }
-
-  if (url_string) {
-    s->arena.str_free(url_string);
-  }
   //////////////////////////////////////////////
   // disable keep-alive for request and retry //
   //////////////////////////////////////////////

diff --git a/proxy/http/HttpTransact.h b/proxy/http/HttpTransact.h
@@ -560,12 +560,6 @@ class HttpTransact
     {
       connect_result = 0;
     }
-    void
-    set_connect_fail(int e)
-    {
-      connect_result = e;
-    }
-
     ConnectionAttributes() { clear(); }
 
     void
@@ -583,7 +577,7 @@ class HttpTransact
     ConnectionAttributes *server               = nullptr;
     ink_time_t now                             = 0;
     ServerState_t state                        = STATE_UNDEFINED;
-    unsigned attempts                          = 1;
+    unsigned attempts                          = 0;
     unsigned simple_retry_attempts             = 0;
     unsigned unavailable_server_retry_attempts = 0;
     ParentRetry_t retry_type                   = PARENT_RETRY_NONE;
@@ -909,6 +903,17 @@ class HttpTransact
 
     ProxyProtocol pp_info;
 
+    void
+    set_connect_fail(int e)
+    {
+      if (e == EIO || this->current.server->connect_result == EIO) {
+        this->current.server->connect_result = e;
+      }
+      if (e != EIO) {
+        this->cause_of_death_errno = e;
+      }
+    }
+
   private:
     // Make this a raw byte array, so it will be accessed through the my_txn_conf() member function.
     alignas(OverridableHttpConfigParams) char _my_txn_conf[sizeof(OverridableHttpConfigParams)];
@@ -958,6 +963,7 @@ class HttpTransact
   static void handle_response_from_server(State *s);
   static void delete_server_rr_entry(State *s, int max_retries);
   static void retry_server_connection_not_open(State *s, ServerState_t conn_state, unsigned max_retries);
+  static void error_log_connection_failure(State *s, ServerState_t conn_state);
   static void handle_server_connection_not_open(State *s);
   static void handle_forward_server_connection_open(State *s);
   static void handle_cache_operation_on_forward_server_response(State *s);

diff --git a/proxy/http/HttpTunnel.cc b/proxy/http/HttpTunnel.cc
@@ -1314,6 +1314,10 @@ HttpTunnel::consumer_handler(int event, HttpTunnelConsumer *c)
   switch (event) {
   case VC_EVENT_WRITE_READY:
     this->consumer_reenable(c);
+    // Once we get a write ready from the origin, we can assume the connect to some degree succeeded
+    if (c->vc_type == HT_HTTP_SERVER) {
+      sm->t_state.current.server->clear_connect_fail();
+    }
     break;
 
   case VC_EVENT_WRITE_COMPLETE:

diff --git a/src/traffic_cache_tool/Makefile.inc b/src/traffic_cache_tool/Makefile.inc
@@ -42,6 +42,7 @@ traffic_cache_tool_traffic_cache_tool_LDADD = \
     $(top_builddir)/src/tscore/.libs/ink_mutex.o \
     $(top_builddir)/src/tscore/.libs/ink_string.o \
     $(top_builddir)/src/tscore/.libs/BufferWriterFormat.o \
+    $(top_builddir)/src/tscore/.libs/InkErrno.o \
     $(top_builddir)/src/tscore/.libs/ts_file.o \
     $(top_builddir)/src/tscore/.libs/Errata.o \
     $(top_builddir)/src/tscpp/util/.libs/TextView.o \