Slice errorlog

plugins/experimental/slice/HttpHeader.cc

@@ -53,6 +53,24 @@ HttpHeader::setStatus(TSHttpStatus const newstatus)
   return TS_SUCCESS == TSHttpHdrStatusSet(m_buffer, m_lochdr, newstatus);
 }
 
+char *
+HttpHeader ::urlString(int *const urllen) const
+{
+  char *urlstr = nullptr;
+  TSAssert(nullptr != urllen);
+
+  TSMLoc locurl            = nullptr;
+  TSReturnCode const rcode = TSHttpHdrUrlGet(m_buffer, m_lochdr, &locurl);
+  if (TS_SUCCESS == rcode && nullptr != locurl) {
+    urlstr = TSUrlStringGet(m_buffer, locurl, urllen);
+    TSHandleMLocRelease(m_buffer, m_lochdr, locurl);
+  } else {
+    *urllen = 0;
+  }
+
+  return urlstr;
+}
+
 bool
 HttpHeader::setUrl(TSMBuffer const bufurl, TSMLoc const locurl)
 {
@@ -102,6 +120,10 @@ HttpHeader::getCharPtr(CharPtrGetFunc func, int *const len) const
     }
   }
 
+  if (nullptr == res && nullptr != len) {
+    *len = 0;
+  }
+
   return res;
 }
 
@@ -144,6 +166,7 @@ bool
 HttpHeader::valueForKey(char const *const keystr, int const keylen, char *const valstr, int *const vallen, int const index) const
 {
   if (!isValid()) {
+    *vallen = 0;
     return false;
   }
 
@@ -171,9 +194,6 @@ HttpHeader::valueForKey(char const *const keystr, int const keylen, char *const
     *vallen = 0;
   }
 
-  if (!status) {
-  }
-
   return status;
 }
 
@@ -224,16 +244,12 @@ HttpHeader::toString() const
   case TS_HTTP_TYPE_REQUEST: {
     res.append(method());
 
-    TSMLoc locurl            = nullptr;
-    TSReturnCode const rcode = TSHttpHdrUrlGet(m_buffer, m_lochdr, &locurl);
-    if (TS_SUCCESS == rcode && nullptr != locurl) {
-      int urllen         = 0;
-      char *const urlstr = TSUrlStringGet(m_buffer, locurl, &urllen);
+    int urllen         = 0;
+    char *const urlstr = urlString(&urllen);
+    if (nullptr != urlstr) {
       res.append(" ");
       res.append(urlstr, urllen);
       TSfree(urlstr);
-
-      TSHandleMLocRelease(m_buffer, m_lochdr, locurl);
     } else {
       res.append(" UnknownURL");
     }

plugins/experimental/slice/HttpHeader.h

@@ -71,6 +71,16 @@ struct HttpHeader {
     return getCharPtr(TSHttpHdrMethodGet, len);
   }
 
+  // request method version
+  int
+  version() const
+  {
+    return TSHttpHdrVersionGet(m_buffer, m_lochdr);
+  }
+
+  // Returns string representation of the url. Caller gets ownership!
+  char *urlString(int *const urllen) const;
+
   // host
   char const *
   hostname(int *const len) const
@@ -95,7 +105,7 @@ struct HttpHeader {
   bool valueForKey(char const *const keystr, int const keylen,
                    char *const valstr,  // <-- return string value
                    int *const vallen,   // <-- pass in capacity, returns len of string
-                   int const index = -1 // sets all values
+                   int const index = -1 // retrieves all values
                    ) const;
 
   /**

plugins/experimental/slice/Range.cc

@@ -57,10 +57,10 @@ Range::fromStringClosed(char const *const rangestr)
   }
 
   // rip out any whitespace
-  static int const RLEN = 1024;
-  char rangebuf[RLEN];
-  char *pbuf = rangebuf;
-  while ('\0' != *pstr && (pbuf - rangebuf) < RLEN) {
+  char rangebuf[1024];
+  int const rangelen = sizeof(rangebuf);
+  char *pbuf         = rangebuf;
+  while ('\0' != *pstr && (pbuf - rangebuf) < rangelen) {
     if (!isblank(*pstr)) {
       *pbuf++ = *pstr;
     }

plugins/experimental/slice/client.cc

@@ -38,7 +38,7 @@ requestBlock(TSCont contp, Data *const data)
   Range blockbe(blockbeg, blockbeg + data->m_blockbytes_config);
 
   char rangestr[1024];
-  int rangelen      = 1023;
+  int rangelen      = sizeof(rangestr);
   bool const rpstat = blockbe.toStringClosed(rangestr, &rangelen);
   TSAssert(rpstat);
 
@@ -114,7 +114,7 @@ handle_client_req(TSCont contp, TSEvent event, Data *const data)
     Range rangebe;
 
     char rangestr[1024];
-    int rangelen        = 1024;
+    int rangelen        = sizeof(rangestr);
     bool const hasRange = header.valueForKey(TS_MIME_FIELD_RANGE, TS_MIME_LEN_RANGE, rangestr, &rangelen,
                                              0); // <-- first range only
     if (hasRange) {
@@ -135,7 +135,7 @@ handle_client_req(TSCont contp, TSEvent event, Data *const data)
       }
     } else {
       DEBUG_LOG("Full content request");
-      static char const *const valstr = "full content request";
+      static char const *const valstr = "-";
       static size_t const vallen      = strlen(valstr);
       header.setKeyVal(SLICER_MIME_FIELD_INFO, strlen(SLICER_MIME_FIELD_INFO), valstr, vallen);
       data->m_statustype = TS_HTTP_STATUS_OK;

plugins/experimental/slice/response.cc

@@ -68,9 +68,8 @@ string502()
     bodystr.append("</body>\n");
     bodystr.append("</html>\n");
 
-    static int const CLEN = 1024;
-    char clenstr[CLEN];
-    int const clen = snprintf(clenstr, CLEN, "%lu", bodystr.size());
+    char clenstr[1024];
+    int const clen = snprintf(clenstr, sizeof(clenstr), "%lu", bodystr.size());
 
     msg.append("HTTP/1.1 502 Bad Gateway\r\n");
     msg.append("Content-Length: ");
@@ -96,9 +95,7 @@ form416HeaderAndBody(HttpHeader &header, int64_t const contentlen, std::string c
   header.setReason(reason, strlen(reason));
 
   char bufstr[256];
-  int buflen = snprintf
-    //    (bufstr, 255, "%" PRId64, bodystr.size());
-    (bufstr, 255, "%lu", bodystr.size());
+  int buflen = snprintf(bufstr, sizeof(bufstr), "%lu", bodystr.size());
   header.setKeyVal(TS_MIME_FIELD_CONTENT_LENGTH, TS_MIME_LEN_CONTENT_LENGTH, bufstr, buflen);
 
   static char const *const ctypestr = "text/html";

plugins/experimental/slice/server.cc

@@ -22,6 +22,8 @@
 #include "response.h"
 #include "transfer.h"
 
+#include "ts/experimental.h"
+
 #include <cinttypes>
 
 namespace
@@ -42,9 +44,8 @@ contentRangeFrom(HttpHeader const &header)
   /* Pull content length off the response header
     and manipulate it into a client response header
    */
-  static int const RLEN = 1024;
-  char rangestr[RLEN];
-  int rangelen = RLEN - 1;
+  char rangestr[1024];
+  int rangelen = sizeof(rangestr);
 
   // look for expected Content-Range field
   bool const hasContentRange(header.valueForKey(TS_MIME_FIELD_CONTENT_RANGE, TS_MIME_LEN_CONTENT_RANGE, rangestr, &rangelen));
@@ -63,11 +64,13 @@ handleFirstServerHeader(Data *const data, TSCont const contp)
 {
   HttpHeader header(data->m_resp_hdrmgr.m_buffer, data->m_resp_hdrmgr.m_lochdr);
 
+  //  DEBUG_LOG("First header\n%s", header.toString().c_str());
+
   data->m_dnstream.setupVioWrite(contp);
 
   // only process a 206, everything else gets a pass through
   if (TS_HTTP_STATUS_PARTIAL_CONTENT != header.status()) {
-    DEBUG_LOG("Non 206 response from parent: %d", header.status());
+    DEBUG_LOG("Initial reponse other than 206: %d", header.status());
     data->m_bail = true;
 
     TSHttpHdrPrint(header.m_buffer, header.m_lochdr, data->m_dnstream.m_write.m_iobuf);
@@ -138,7 +141,7 @@ handleFirstServerHeader(Data *const data, TSCont const contp)
     respcr.m_length = data->m_contentlen;
 
     char rangestr[1024];
-    int rangelen      = 1023;
+    int rangelen      = sizeof(rangestr);
     bool const crstat = respcr.toStringClosed(rangestr, &rangelen);
 
     // corner case, return 500 ??
@@ -163,7 +166,7 @@ handleFirstServerHeader(Data *const data, TSCont const contp)
   }
 
   char bufstr[1024];
-  int const buflen = snprintf(bufstr, 1023, "%" PRId64, bodybytes);
+  int const buflen = snprintf(bufstr, sizeof(bufstr), "%" PRId64, bodybytes);
   header.setKeyVal(TS_MIME_FIELD_CONTENT_LENGTH, TS_MIME_LEN_CONTENT_LENGTH, bufstr, buflen);
 
   // add the response header length to the total bytes to send
@@ -180,29 +183,124 @@ handleFirstServerHeader(Data *const data, TSCont const contp)
   return true;
 }
 
+void
+logSliceError(char const *const message, Data const *const data, HttpHeader const &header_resp)
+{
+  HttpHeader const header_req(data->m_req_hdrmgr.m_buffer, data->m_req_hdrmgr.m_lochdr);
+
+  TSHRTime const timenowus = TShrtime();
+  int64_t const msecs      = timenowus / 1000000;
+  int64_t const secs       = msecs / 1000;
+  int64_t const ms         = msecs % 1000;
+
+  // Gather information on the request, must delete urlstr
+  int urllen         = 0;
+  char *const urlstr = header_req.urlString(&urllen);
+
+  char urlpstr[16384];
+  size_t urlplen = sizeof(urlpstr);
+  TSStringPercentEncode(urlstr, urllen, urlpstr, urlplen, &urlplen, nullptr);
+
+  if (nullptr != urlstr) {
+    TSfree(urlstr);
+  }
+
+  // uas
+  char uasstr[8192];
+  int uaslen = sizeof(uasstr);
+  header_req.valueForKey(TS_MIME_FIELD_USER_AGENT, TS_MIME_LEN_USER_AGENT, uasstr, &uaslen);
+
+  // raw range request
+  char rangestr[1024];
+  int rangelen = sizeof(rangestr);
+  header_req.valueForKey(SLICER_MIME_FIELD_INFO, strlen(SLICER_MIME_FIELD_INFO), rangestr, &rangelen);
+
+  // Normalized range request
+  ContentRange const crange(data->m_req_range.m_beg, data->m_req_range.m_end, data->m_contentlen);
+  char normstr[1024];
+  int normlen = sizeof(normstr);
+  crange.toStringClosed(normstr, &normlen);
+
+  // block range request
+  int64_t const blockbeg = data->m_blocknum * data->m_blockbytes_config;
+  int64_t const blockend = std::min(blockbeg + data->m_blockbytes_config, data->m_contentlen);
+
+  // Block response data
+  TSHttpStatus const statusgot = header_resp.status();
+
+  // content range
+  char crstr[1024];
+  int crlen = sizeof(crstr);
+  header_resp.valueForKey(TS_MIME_FIELD_CONTENT_RANGE, TS_MIME_LEN_CONTENT_RANGE, crstr, &crlen);
+
+  // etag
+  char etagstr[1024];
+  int etaglen = sizeof(etagstr);
+  header_resp.valueForKey(TS_MIME_FIELD_ETAG, TS_MIME_LEN_ETAG, etagstr, &etaglen);
+
+  // last modified
+  char lmstr[1024];
+  int lmlen = sizeof(lmstr);
+  header_resp.valueForKey(TS_MIME_FIELD_LAST_MODIFIED, TS_MIME_LEN_LAST_MODIFIED, lmstr, &lmlen);
+
+  // cc
+  char ccstr[2048];
+  int cclen = sizeof(ccstr);
+  header_resp.valueForKey(TS_MIME_FIELD_CACHE_CONTROL, TS_MIME_LEN_CACHE_CONTROL, ccstr, &cclen);
+
+  // via tag
+  char viastr[8192];
+  int vialen = sizeof(viastr);
+  header_resp.valueForKey(TS_MIME_FIELD_VIA, TS_MIME_LEN_VIA, viastr, &vialen);
+
+  char etagexpstr[1024];
+  size_t etagexplen = sizeof(etagexpstr);
+  TSStringPercentEncode(data->m_etag, data->m_etaglen, etagexpstr, etagexplen, &etagexplen, nullptr);
+
+  char etaggotstr[1024];
+  size_t etaggotlen = sizeof(etaggotstr);
+  TSStringPercentEncode(etagstr, etaglen, etaggotstr, etaggotlen, &etaggotlen, nullptr);
+
+  TSError("[%s] %" PRId64 ".%" PRId64 " reason=\"%s\""
+          " uri=\"%.*s\""
+          " uas=\"%.*s\""
+          " req_range=\"%.*s\""
+          " norm_range=\"%.*s\""
+
+          " etag_exp=\"%.*s\""
+          " lm_exp=\"%.*s\""
+
+          " blk_range=\"%" PRId64 "-%" PRId64 "\""
+
+          " status_got=\"%d\""
+          " cr_got=\"%.*s\""
+          " etag_got=\"%.*s\""
+          " lm_got=\"%.*s\""
+          " cc=\"%.*s\""
+          " via=\"%.*s\"",
+          PLUGIN_NAME, secs, ms, message, (int)urlplen, urlpstr, uaslen, uasstr, rangelen, rangestr, normlen, normstr,
+          (int)etagexplen, etagexpstr, data->m_lastmodifiedlen, data->m_lastmodified, blockbeg, blockend - 1, statusgot, crlen,
+          crstr, (int)etaggotlen, etaggotstr, lmlen, lmstr, cclen, ccstr, vialen, viastr);
+}
+
 bool
 handleNextServerHeader(Data *const data, TSCont const contp)
 {
+  // block response header
   HttpHeader header(data->m_resp_hdrmgr.m_buffer, data->m_resp_hdrmgr.m_lochdr);
+  //  DEBUG_LOG("Next Header:\n%s", header.toString().c_str());
 
   // only process a 206, everything else just aborts
   if (TS_HTTP_STATUS_PARTIAL_CONTENT != header.status()) {
-    ERROR_LOG("Non 206 internal block response from parent: %d", header.status());
+    logSliceError("Non 206 internal block response", data, header);
     data->m_bail = true;
     return false;
   }
 
   // can't parse the content range header, abort -- might be too strict
   ContentRange const blockcr = contentRangeFrom(header);
-  if (!blockcr.isValid()) {
-    ERROR_LOG("Unable to parse internal block Content-Range header");
-    data->m_bail = true;
-    return false;
-  }
-
-  // make sure the block comes from the same asset as the first block
-  if (data->m_contentlen != blockcr.m_length) {
-    ERROR_LOG("Mismatch in slice block Content-Range Len %" PRId64 " and %" PRId64, data->m_contentlen, blockcr.m_length);
+  if (!blockcr.isValid() || blockcr.m_length != data->m_contentlen) {
+    logSliceError("Mismatch/Bad block Content-Range", data, header);
     data->m_bail = true;
     return false;
   }
@@ -211,23 +309,22 @@ handleNextServerHeader(Data *const data, TSCont const contp)
 
   // prefer the etag but use Last-Modified if we must.
   char etag[8192];
-  int etaglen = sizeof(etag) - 1;
+  int etaglen = sizeof(etag);
   header.valueForKey(TS_MIME_FIELD_ETAG, TS_MIME_LEN_ETAG, etag, &etaglen);
 
   if (0 < data->m_etaglen || 0 < etaglen) {
     same = data->m_etaglen == etaglen && 0 == strncmp(etag, data->m_etag, etaglen);
     if (!same) {
-      ERROR_LOG("Mismatch in slice block ETAG '%.*s' and '%.*s'", data->m_etaglen, data->m_etag, etaglen, etag);
+      logSliceError("Mismatch block Etag", data, header);
     }
   } else {
     char lastmodified[8192];
-    int lastmodifiedlen = sizeof(lastmodified) - 1;
+    int lastmodifiedlen = sizeof(lastmodified);
     header.valueForKey(TS_MIME_FIELD_LAST_MODIFIED, TS_MIME_LEN_LAST_MODIFIED, lastmodified, &lastmodifiedlen);
     if (0 < data->m_lastmodifiedlen || 0 != lastmodifiedlen) {
       same = data->m_lastmodifiedlen == lastmodifiedlen && 0 == strncmp(lastmodified, data->m_lastmodified, lastmodifiedlen);
       if (!same) {
-        ERROR_LOG("Mismatch in slice block Last-Modified '%.*s' and '%.*s'", data->m_lastmodifiedlen, data->m_lastmodified,
-                  lastmodifiedlen, lastmodified);
+        logSliceError("Mismatch block Last-Modified", data, header);
       }
     }
   }

tests/gold_tests/pluginTest/slice/gold_error/crr.stderr.gold

@@ -0,0 +1 @@
+the quick``

tests/gold_tests/pluginTest/slice/gold_error/crr.stdout.gold

@@ -0,0 +1,9 @@
+``
+Cache-Control: ``
+Connection: ``
+Content-Length: 19
+Date: ``
+Etag: ``
+HTTP/1.1 200 OK
+Server: ``
+Via: ``

tests/gold_tests/pluginTest/slice/gold_error/etag.stderr.gold

@@ -0,0 +1 @@
+the quick``