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 2014/04/17 18:44:42 UTC

[43/50] git commit: TS-2708: refactor and modernize the tcp_info plugin

TS-2708: refactor and modernize the tcp_info plugin

Always build the tcp_info plugin, even if it doesn't end up doing
anything useful on the build platform. This is convenient for
development.

Only sample and log TCP metrics after it passes the sample threshold
to reduce unnecessary work.

Add IPv6 support. Use TS*Assert instead of assert. Remove the Config
global variable. Add a txn_close hook.

Use the text logging API rather than writing custom logs.


Project: http://git-wip-us.apache.org/repos/asf/trafficserver/repo
Commit: http://git-wip-us.apache.org/repos/asf/trafficserver/commit/d461c33e
Tree: http://git-wip-us.apache.org/repos/asf/trafficserver/tree/d461c33e
Diff: http://git-wip-us.apache.org/repos/asf/trafficserver/diff/d461c33e

Branch: refs/heads/5.0.x
Commit: d461c33e2050905bce86dc1eba59665ee879754b
Parents: bf16745
Author: James Peach <jp...@apache.org>
Authored: Fri Apr 11 13:33:46 2014 -0700
Committer: James Peach <jp...@apache.org>
Committed: Wed Apr 16 10:29:03 2014 -0700

----------------------------------------------------------------------
 CHANGES                                   |   2 +
 configure.ac                              |  10 +-
 plugins/experimental/tcp_info/Makefile.am |   4 -
 plugins/experimental/tcp_info/tcp_info.cc | 268 +++++++++++++++----------
 proxy/api/ts/ts.h                         |   7 +-
 5 files changed, 180 insertions(+), 111 deletions(-)
----------------------------------------------------------------------


http://git-wip-us.apache.org/repos/asf/trafficserver/blob/d461c33e/CHANGES
----------------------------------------------------------------------
diff --git a/CHANGES b/CHANGES
index f578673..932f614 100644
--- a/CHANGES
+++ b/CHANGES
@@ -1,6 +1,8 @@
                                                          -*- coding: utf-8 -*-
 Changes with Apache Traffic Server 5.0.0
 
+  *) [TS-2708] Refactor and modernize the tcp_info plugin.
+
   *) [TS-2555] Adding global plugin support to ts_lua plugin.
 
   *) [TS-2717] header-rewrite set-redirect not working.

http://git-wip-us.apache.org/repos/asf/trafficserver/blob/d461c33e/configure.ac
----------------------------------------------------------------------
diff --git a/configure.ac b/configure.ac
index ad8c054..2a19d01 100644
--- a/configure.ac
+++ b/configure.ac
@@ -1801,11 +1801,13 @@ TS_CHECK_GETHOSTBYNAME_R_STYLE
 TS_CHECK_MACRO_IN6_IS_ADDR_UNSPECIFIED
 
 AC_CHECK_TYPE([struct tcp_info],
-  [enable_tcpinfo_plugin=yes],
-  [enable_tcpinfo_plugin=no],
-  [[#include <netinet/tcp.h>]]
+  [AC_DEFINE(HAVE_STRUCT_TCP_INFO, 1, [whether struct tcp_info is available])],
+  [],
+  [[
+   #include <netinet/in.h>
+   #include <netinet/tcp.h>
+  ]]
 )
-AM_CONDITIONAL([BUILD_TCPINFO_PLUGIN], [ test "x${enable_tcpinfo_plugin}" != "xno" ])
 
 # See if we can build the remap_stats plugin
 AS_IF([test "x$enable_experimental_plugins" = xyes],

http://git-wip-us.apache.org/repos/asf/trafficserver/blob/d461c33e/plugins/experimental/tcp_info/Makefile.am
----------------------------------------------------------------------
diff --git a/plugins/experimental/tcp_info/Makefile.am b/plugins/experimental/tcp_info/Makefile.am
index 7e6e5f1..daabefd 100644
--- a/plugins/experimental/tcp_info/Makefile.am
+++ b/plugins/experimental/tcp_info/Makefile.am
@@ -16,11 +16,7 @@
 
 include $(top_srcdir)/build/plugins.mk
 
-if BUILD_TCPINFO_PLUGIN
-
 pkglib_LTLIBRARIES = tcp_info.la
 tcp_info_la_SOURCES = tcp_info.cc
 tcp_info_la_LDFLAGS = $(TS_PLUGIN_LDFLAGS)
 
-endif
-

http://git-wip-us.apache.org/repos/asf/trafficserver/blob/d461c33e/plugins/experimental/tcp_info/tcp_info.cc
----------------------------------------------------------------------
diff --git a/plugins/experimental/tcp_info/tcp_info.cc b/plugins/experimental/tcp_info/tcp_info.cc
index 7835039..e828ded 100644
--- a/plugins/experimental/tcp_info/tcp_info.cc
+++ b/plugins/experimental/tcp_info/tcp_info.cc
@@ -27,102 +27,176 @@
 #include <unistd.h>
 #include <netinet/in.h>
 #include <netinet/tcp.h>
-#include <assert.h>
 #include <sys/types.h>
 #include <sys/stat.h>
 #include <getopt.h>
 #include <fcntl.h>
 #include <limits.h>
 #include <string.h>
+#include <errno.h>
 #include <sys/time.h>
 #include <arpa/inet.h>
 
+#include "ink_defs.h"
+
+#if defined(TCP_INFO) && defined(HAVE_STRUCT_TCP_INFO)
+#define TCPI_PLUGIN_SUPPORTED 1
+#endif
+
 #define TCPI_HOOK_SSN_START     0x01u
 #define TCPI_HOOK_TXN_START     0x02u
 #define TCPI_HOOK_SEND_RESPONSE 0x04u
 #define TCPI_HOOK_SSN_CLOSE     0x08u
+#define TCPI_HOOK_TXN_CLOSE     0x10u
+
+// Log format headers. These are emitted once at the start of a log file. Note that we
+// carefully order the fields so the field ordering is compatible. This lets you change
+// the verbosity without breaking a perser that is moderately robust.
+static const char * tcpi_headers[] = {
+  "timestamp event client server rtt",
+  "timestamp event client server rtt rttvar last_sent last_recv "
+    "snd_ssthresh rcv_ssthresh unacked sacked lost retrans fackets",
+};
 
 struct Config {
   int sample;
-  const char* log_file;
-  int log_fd;
-  int log_level;
+  unsigned log_level;
+  TSTextLogObject log;
+
+  Config() : sample(1000), log_level(1), log(NULL) {
+  }
+
+  ~Config() {
+    if (log) {
+      TSTextLogObjectDestroy(log);
+    }
+  }
 };
 
-static Config config;
+union const_sockaddr_ptr {
+  const struct sockaddr * sa;
+  const struct sockaddr_in * in;
+  const struct sockaddr_in6 * in6;
+
+  const void * addr() const {
+    switch (sa->sa_family) {
+    case AF_INET: return &(in->sin_addr);
+    case AF_INET6: return &(in6->sin6_addr);
+    default: return NULL;
+    }
+  }
+
+};
+
+#if TCPI_PLUGIN_SUPPORTED
 
 static void
-log_tcp_info(const char* event_name, const char* client_ip, const char* server_ip, struct tcp_info &info) {
-  char buffer[256];
+log_tcp_info(Config * config, const char * event_name, TSHttpSsn ssnp)
+{
+  char                client_str[INET6_ADDRSTRLEN];
+  char                server_str[INET6_ADDRSTRLEN];
+  const_sockaddr_ptr  client_addr;
+  const_sockaddr_ptr  server_addr;
+
+  struct tcp_info     info;
+  socklen_t           tcp_info_len = sizeof(info);
+  int                 fd;
 
-  // get the current time
-  struct timeval now;
-  gettimeofday(&now, NULL);
+  TSReleaseAssert(config->log != NULL);
 
-  int bytes = 0;
-  if (config.log_level == 2) {
+  if (TSHttpSsnClientFdGet(ssnp, &fd) != TS_SUCCESS) {
+    TSDebug("tcp_info", "error getting the client socket fd");
+    return;
+  }
+
+  if (getsockopt(fd, IPPROTO_TCP, TCP_INFO, &info, &tcp_info_len) != 0) {
+    TSDebug("tcp_info", "getsockopt(%d, TCP_INFO) failed: %s", fd, strerror(errno));
+    return;
+  }
+
+  client_addr.sa = TSHttpSsnClientAddrGet(ssnp);
+  server_addr.sa = TSHttpSsnIncomingAddrGet(ssnp);
+
+  if (client_addr.sa == NULL || server_addr.sa == NULL) {
+    return;
+  }
+
+  // convert ip to string
+  inet_ntop(client_addr.sa->sa_family, client_addr.addr(), client_str, sizeof(client_str));
+  inet_ntop(server_addr.sa->sa_family, server_addr.addr(), server_str, sizeof(server_str));
+
+  TSReturnCode ret;
+
+  if (config->log_level == 2) {
 #if !defined(freebsd) || defined(__GLIBC__)
-    bytes = snprintf(buffer, sizeof(buffer), "%s %u %u %s %s %u %u %u %u %u %u %u %u %u %u %u %u\n",
+    ret = TSTextLogObjectWrite(config->log, "%s %s %s %u %u %u %u %u %u %u %u %u %u %u %u",
                      event_name,
-                     (uint32_t)now.tv_sec,
-                     (uint32_t)now.tv_usec,
-                     client_ip,
-                     server_ip,
+                     client_str,
+                     server_str,
+                     info.tcpi_rtt,
+                     info.tcpi_rttvar,
                      info.tcpi_last_data_sent,
                      info.tcpi_last_data_recv,
                      info.tcpi_snd_cwnd,
                      info.tcpi_snd_ssthresh,
                      info.tcpi_rcv_ssthresh,
-                     info.tcpi_rtt,
-                     info.tcpi_rttvar,
                      info.tcpi_unacked,
                      info.tcpi_sacked,
                      info.tcpi_lost,
                      info.tcpi_retrans,
-                     info.tcpi_fackets
-      );
+                     info.tcpi_fackets);
 #else
-        bytes = snprintf(buffer, sizeof(buffer), "%s %u %u %s %s %u %u %u %u %u %u %u %u %u %u %u %u\n",
+    ret = TSTextLogObjectWrite(config->log, "%s %s %s %u %u %u %u %u %u %u %u %u %u %u %u",
                      event_name,
-                     (uint32_t)now.tv_sec,
-                     (uint32_t)now.tv_usec,
-                     client_ip,
-                     server_ip,
+                     client_str,
+                     server_str,
+                     info.tcpi_rtt,
+                     info.tcpi_rttvar,
                      info.__tcpi_last_data_sent,
                      info.tcpi_last_data_recv,
                      info.tcpi_snd_cwnd,
                      info.tcpi_snd_ssthresh,
                      info.__tcpi_rcv_ssthresh,
-                     info.tcpi_rtt,
-                     info.tcpi_rttvar,
                      info.__tcpi_unacked,
                      info.__tcpi_sacked,
                      info.__tcpi_lost,
                      info.__tcpi_retrans,
-                     info.__tcpi_fackets
-      );
+                     info.__tcpi_fackets);
 #endif
   } else {
-    bytes = snprintf(buffer, sizeof(buffer), "%s %u %s %s %u\n",
+    ret = TSTextLogObjectWrite(config->log, "%s %s %s %u",
                      event_name,
-                     (uint32_t)now.tv_sec,
-                     client_ip,
-                     server_ip,
-                     info.tcpi_rtt
-    );
+                     client_str,
+                     server_str,
+                     info.tcpi_rtt);
+  }
+
+  // It's really not clear how we should handle logging failures. It a failure transient
+  // or persistent? Should we try to re-open the logs? How frequently should we do that?
+  if (ret != TS_SUCCESS) {
+    TSError("[tcp_info] log write failed, disabling logging");
+    TSTextLogObjectDestroy(config->log);
+    config->log = NULL;
   }
+}
 
-  ssize_t wrote = write(config.log_fd, buffer, bytes);
-  assert(wrote == bytes);
-  TSDebug("tcp_info", "wrote: %d bytes to file: %s", bytes, config.log_file);
-  TSDebug("tcp_info", "logging: %s", buffer);
+#else /* TCPI_PLUGIN_SUPPORTED */
+
+static void
+log_tcp_info(Config * /* config */, const char * /* event_name */, TSHttpSsn /* ssnp */)
+{
+  return; // TCP metrics not supported.
 }
 
+#endif /* TCPI_PLUGIN_SUPPORTED */
+
 static int
-tcp_info_hook(TSCont /* contp ATS_UNUSED */, TSEvent event, void *edata)
+tcp_info_hook(TSCont contp, TSEvent event, void *edata)
 {
   TSHttpSsn ssnp = NULL;
   TSHttpTxn txnp = NULL;
+  int       random = 0;
+  Config *  config = (Config *)TSContDataGet(contp);
 
   const char *event_name;
   switch (event) {
@@ -147,52 +221,22 @@ tcp_info_hook(TSCont /* contp ATS_UNUSED */, TSEvent event, void *edata)
     return 0;
   }
 
-  TSDebug("tcp_info", "tcp_info_hook called, event: %s", event_name);
+  TSDebug("tcp_info", "logging hook called for %s (%s) with log object %p",
+      TSHttpEventNameLookup(event), event_name, config->log);
 
-  struct tcp_info tcp_info;
-  int tcp_info_len = sizeof(tcp_info);
-  int fd;
-
-  if (TSHttpSsnClientFdGet(ssnp, &fd) != TS_SUCCESS) {
-    TSDebug("tcp_info", "error getting the client socket fd");
+  if (config->log == NULL) {
     goto done;
   }
 
-  // get the tcp info structure
-  if (getsockopt(fd, IPPROTO_TCP, TCP_INFO, (void *)&tcp_info, (socklen_t *)&tcp_info_len) == 0) {
-    // the structure is the correct size
-    if (tcp_info_len == sizeof(tcp_info)) {
-      // no need to run rand if we are always going log (100%)
-      int random = 0;
-      if (config.sample < 1000) {
-        random = rand() % 1000;
-        TSDebug("tcp_info", "random: %d, config.sample: %d", random, config.sample);
-      }
-
-      if (random < config.sample) {
-        TSDebug("tcp_info", "got the tcp_info struture and now logging");
-
-        // get the client address
-        const struct sockaddr *client_addr = TSHttpSsnClientAddrGet(ssnp);
-        const struct sockaddr *server_addr = TSHttpSsnIncomingAddrGet(ssnp);
-        if (client_addr == NULL || server_addr == NULL)
-          goto done;
-        struct sockaddr_in *client_in_addr = (struct sockaddr_in *)client_addr;
-        struct sockaddr_in *server_in_addr = (struct sockaddr_in *)server_addr;
-        char client_str[INET_ADDRSTRLEN];
-        char server_str[INET_ADDRSTRLEN];
-
-        // convert ip to string
-        inet_ntop(client_addr->sa_family, &(client_in_addr->sin_addr), client_str, INET_ADDRSTRLEN);
-        inet_ntop(server_addr->sa_family, &(server_in_addr->sin_addr), server_str, INET_ADDRSTRLEN);
+  // no need to run rand if we are always going log (100%)
+  if (config->sample < 1000) {
+    random = rand() % 1000;
+    TSDebug("tcp_info", "random: %d, config->sample: %d", random, config->sample);
+  }
 
-        log_tcp_info(event_name, client_str, server_str, tcp_info);
-      }
-    } else {
-      TSDebug("tcp_info", "tcp_info length is the wrong size");
-    }
-  } else {
-    TSDebug("tcp_info", "error calling getsockopt()");
+  if (random < config->sample) {
+    TSDebug("tcp_info", "sampling TCP metrics for %s event", event_name);
+    log_tcp_info(config, event_name, ssnp);
   }
 
 done:
@@ -201,7 +245,8 @@ done:
   } else if (ssnp != NULL) {
     TSHttpSsnReenable(ssnp, TS_EVENT_HTTP_CONTINUE);
   }
-  return 0;
+
+  return TS_EVENT_NONE;
 }
 
 static bool
@@ -241,6 +286,7 @@ parse_hook_list(const char * hook_list)
     { "txn_start", TCPI_HOOK_TXN_START },
     { "send_resp_hdr", TCPI_HOOK_SEND_RESPONSE },
     { "ssn_close", TCPI_HOOK_SSN_CLOSE },
+    { "txn_close", TCPI_HOOK_TXN_CLOSE },
     { NULL, 0u }
   };
 
@@ -279,7 +325,10 @@ TSPluginInit(int argc, const char * argv[])
   };
 
   TSPluginRegistrationInfo info;
-  unsigned hooks = 0;
+  Config *  config = new Config();
+  const char *  filename = "tcp_info";
+  TSCont    cont;
+  unsigned  hooks = 0;
 
   info.plugin_name = (char*)"tcp_info";
   info.vendor_name = (char*)"Apache Software Foundation";
@@ -289,10 +338,6 @@ TSPluginInit(int argc, const char * argv[])
     TSError("tcp_info: plugin registration failed");
   }
 
-  config.sample = 1000;
-  config.log_level = 1;
-  config.log_file = NULL;
-
   optind = 0;
   for (;;) {
     unsigned long lval;
@@ -300,17 +345,17 @@ TSPluginInit(int argc, const char * argv[])
     switch (getopt_long(argc, (char * const *)argv, "r:f:l:h:", longopts, NULL)) {
     case 'r':
       if (parse_unsigned(optarg, lval)) {
-        config.sample = atoi(optarg);
+        config->sample = atoi(optarg);
       } else {
         TSError("[tcp_info] invalid sample rate '%s'", optarg);
       }
       break;
     case 'f':
-      config.log_file = optarg;
+      filename = optarg;
       break;
     case 'l':
-      if (parse_unsigned(optarg, lval) && (lval == 1 || lval == 2)) {
-        config.log_level = atoi(optarg);
+      if (parse_unsigned(optarg, lval) && (lval <= countof(tcpi_headers))) {
+        config->log_level = lval;
       } else {
         TSError("[tcp_info] invalid log level '%s'", optarg);
       }
@@ -327,32 +372,53 @@ TSPluginInit(int argc, const char * argv[])
 
 init:
 
-  TSDebug("tcp_info", "sample: %d", config.sample);
-  TSDebug("tcp_info", "log filename: %s", config.log_file);
-  TSDebug("tcp_info", "log_level: %d", config.log_level);
+#if !TCPI_PLUGIN_SUPPORTED
+  TSError("[tcp_info] TCP metrics are not supported on this platform");
+#endif
+
+  TSDebug("tcp_info", "sample: %d", config->sample);
+  TSDebug("tcp_info", "log filename: %s", filename);
+  TSDebug("tcp_info", "log_level: %u", config->log_level);
   TSDebug("tcp_info", "hook mask: 0x%x", hooks);
 
-  config.log_fd = open(config.log_file, O_APPEND | O_CREAT | O_RDWR, 0666);
-  assert(config.log_fd > 0);
+  if (TSTextLogObjectCreate(filename, TS_LOG_MODE_ADD_TIMESTAMP, &config->log) != TS_SUCCESS) {
+    TSError("[tcp_info] failed to create log file '%s'", filename);
+    delete config;
+    return;
+  }
+
+  TSTextLogObjectHeaderSet(config->log, tcpi_headers[config->log_level - 1]);
+
+  // Enable log rolling. Unless we specify an explicit rolling period, the log will
+  // be rolled based on the size specified in proxy.config.log.rolling_size_mb.
+  TSTextLogObjectRollingEnabledSet(config->log, 1 /* rolling_enabled */);
+
+  cont = TSContCreate(tcp_info_hook, NULL);
+  TSContDataSet(cont, config);
 
   if (hooks & TCPI_HOOK_SSN_START) {
-    TSHttpHookAdd(TS_HTTP_SSN_START_HOOK, TSContCreate(tcp_info_hook, NULL));
+    TSHttpHookAdd(TS_HTTP_SSN_START_HOOK, cont);
     TSDebug("tcp_info", "added hook to the start of the TCP connection");
   }
 
   if (hooks & TCPI_HOOK_TXN_START) {
-    TSHttpHookAdd(TS_HTTP_TXN_START_HOOK, TSContCreate(tcp_info_hook, NULL));
+    TSHttpHookAdd(TS_HTTP_TXN_START_HOOK, cont);
     TSDebug("tcp_info", "added hook to the close of the transaction");
   }
 
   if (hooks & TCPI_HOOK_SEND_RESPONSE) {
-    TSHttpHookAdd(TS_HTTP_SEND_RESPONSE_HDR_HOOK, TSContCreate(tcp_info_hook, NULL));
+    TSHttpHookAdd(TS_HTTP_SEND_RESPONSE_HDR_HOOK, cont);
     TSDebug("tcp_info", "added hook to the sending of the headers");
   }
 
   if (hooks & TCPI_HOOK_SSN_CLOSE) {
-    TSHttpHookAdd(TS_HTTP_SSN_CLOSE_HOOK, TSContCreate(tcp_info_hook, NULL));
+    TSHttpHookAdd(TS_HTTP_SSN_CLOSE_HOOK, cont);
     TSDebug("tcp_info", "added hook to the close of the TCP connection");
   }
 
+  if (hooks & TCPI_HOOK_TXN_CLOSE) {
+    TSHttpHookAdd(TS_HTTP_TXN_CLOSE_HOOK, cont);
+    TSDebug("tcp_info", "added hook to the close of the transaction");
+  }
+
 }

http://git-wip-us.apache.org/repos/asf/trafficserver/blob/d461c33e/proxy/api/ts/ts.h
----------------------------------------------------------------------
diff --git a/proxy/api/ts/ts.h b/proxy/api/ts/ts.h
index 3dce82f..8e0edb4 100644
--- a/proxy/api/ts/ts.h
+++ b/proxy/api/ts/ts.h
@@ -1381,7 +1381,8 @@ extern "C"
   
   /** Change packet TOS for the server side connection
    *
-      @note The change takes effect immediately, if no OS connection has been
+      
+   note The change takes effect immediately, if no OS connection has been
       made, then this sets the mark that will be used IF an OS connection
       is established
       
@@ -1401,6 +1402,7 @@ extern "C"
      string would prevent setting a content type header (but that is not adviced).
 
      @param txnp HTTP transaction whose parent proxy to get.
+     TSError("[tcp_info] TCP metrics are not supported on this platform");
      @param buf The body message (must be heap allocated).
      @param buflength Length of the body message.
      @param mimetype The MIME type to set the response to (can be NULL, but must
@@ -2115,7 +2117,8 @@ extern "C"
   tsapi void TSTextLogObjectRollingIntervalSecSet(TSTextLogObject the_object, int rolling_interval_sec);
 
   /**
-      Set the rolling offset.
+      Set the rolling offset. rolling_offset_hr specifies the hour (between 0 and 23) when log rolling
+      shuld take place.
 
    */
   tsapi void TSTextLogObjectRollingOffsetHrSet(TSTextLogObject the_object, int rolling_offset_hr);