This is an automated email from the ASF dual-hosted git repository.

eze pushed a commit to branch master
in repository https://gitbox.apache.org/repos/asf/trafficserver.git


The following commit(s) were added to refs/heads/master by this push:
     new 671e639  Add more information to diags.log error message for block 
stitching errors.
671e639 is described below

commit 671e63994bffc2da6c0b2a89612707f9baf03c1d
Author: Brian Olsen <[email protected]>
AuthorDate: Wed Apr 10 17:58:35 2019 +0000

    Add more information to diags.log error message for block stitching errors.
---
 plugins/experimental/slice/HttpHeader.cc           |  36 ++-
 plugins/experimental/slice/HttpHeader.h            |  12 +-
 plugins/experimental/slice/Range.cc                |   8 +-
 plugins/experimental/slice/client.cc               |   6 +-
 plugins/experimental/slice/response.cc             |   9 +-
 plugins/experimental/slice/server.cc               | 139 +++++++--
 .../pluginTest/slice/gold_error/crr.stderr.gold    |   1 +
 .../pluginTest/slice/gold_error/crr.stdout.gold    |   9 +
 .../pluginTest/slice/gold_error/etag.stderr.gold   |   1 +
 .../pluginTest/slice/gold_error/etag.stdout.gold   |   9 +
 .../pluginTest/slice/gold_error/lm.stderr.gold     |   1 +
 .../pluginTest/slice/gold_error/lm.stdout.gold     |   9 +
 .../pluginTest/slice/gold_error/non206.stderr.gold |   1 +
 .../pluginTest/slice/gold_error/non206.stdout.gold |  10 +
 .../pluginTest/slice/slice_error.test.py           | 326 +++++++++++++++++++++
 15 files changed, 532 insertions(+), 45 deletions(-)

diff --git a/plugins/experimental/slice/HttpHeader.cc 
b/plugins/experimental/slice/HttpHeader.cc
index 0f1a78f..bcf649b 100644
--- a/plugins/experimental/slice/HttpHeader.cc
+++ b/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");
     }
diff --git a/plugins/experimental/slice/HttpHeader.h 
b/plugins/experimental/slice/HttpHeader.h
index 3572761..bfd9c4d 100644
--- a/plugins/experimental/slice/HttpHeader.h
+++ b/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;
 
   /**
diff --git a/plugins/experimental/slice/Range.cc 
b/plugins/experimental/slice/Range.cc
index 1a7e968..c9a9d4d 100644
--- a/plugins/experimental/slice/Range.cc
+++ b/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;
     }
diff --git a/plugins/experimental/slice/client.cc 
b/plugins/experimental/slice/client.cc
index d52887e..75bbe8e 100644
--- a/plugins/experimental/slice/client.cc
+++ b/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;
diff --git a/plugins/experimental/slice/response.cc 
b/plugins/experimental/slice/response.cc
index 4b9f101..410b150 100644
--- a/plugins/experimental/slice/response.cc
+++ b/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";
diff --git a/plugins/experimental/slice/server.cc 
b/plugins/experimental/slice/server.cc
index f2f4dee..9371469 100644
--- a/plugins/experimental/slice/server.cc
+++ b/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);
       }
     }
   }
diff --git a/tests/gold_tests/pluginTest/slice/gold_error/crr.stderr.gold 
b/tests/gold_tests/pluginTest/slice/gold_error/crr.stderr.gold
new file mode 100644
index 0000000..fad0575
--- /dev/null
+++ b/tests/gold_tests/pluginTest/slice/gold_error/crr.stderr.gold
@@ -0,0 +1 @@
+the quick``
diff --git a/tests/gold_tests/pluginTest/slice/gold_error/crr.stdout.gold 
b/tests/gold_tests/pluginTest/slice/gold_error/crr.stdout.gold
new file mode 100644
index 0000000..955a424
--- /dev/null
+++ b/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: ``
diff --git a/tests/gold_tests/pluginTest/slice/gold_error/etag.stderr.gold 
b/tests/gold_tests/pluginTest/slice/gold_error/etag.stderr.gold
new file mode 100644
index 0000000..fad0575
--- /dev/null
+++ b/tests/gold_tests/pluginTest/slice/gold_error/etag.stderr.gold
@@ -0,0 +1 @@
+the quick``
diff --git a/tests/gold_tests/pluginTest/slice/gold_error/etag.stdout.gold 
b/tests/gold_tests/pluginTest/slice/gold_error/etag.stdout.gold
new file mode 100644
index 0000000..955a424
--- /dev/null
+++ b/tests/gold_tests/pluginTest/slice/gold_error/etag.stdout.gold
@@ -0,0 +1,9 @@
+``
+Cache-Control: ``
+Connection: ``
+Content-Length: 19
+Date: ``
+Etag: ``
+HTTP/1.1 200 OK
+Server: ``
+Via: ``
diff --git a/tests/gold_tests/pluginTest/slice/gold_error/lm.stderr.gold 
b/tests/gold_tests/pluginTest/slice/gold_error/lm.stderr.gold
new file mode 100644
index 0000000..fad0575
--- /dev/null
+++ b/tests/gold_tests/pluginTest/slice/gold_error/lm.stderr.gold
@@ -0,0 +1 @@
+the quick``
diff --git a/tests/gold_tests/pluginTest/slice/gold_error/lm.stdout.gold 
b/tests/gold_tests/pluginTest/slice/gold_error/lm.stdout.gold
new file mode 100644
index 0000000..2d83f7e
--- /dev/null
+++ b/tests/gold_tests/pluginTest/slice/gold_error/lm.stdout.gold
@@ -0,0 +1,9 @@
+``
+Cache-Control: ``
+Connection: ``
+Content-Length: 19
+Date: ``
+HTTP/1.1 200 OK
+Last-Modified: ``
+Server: ``
+Via: ``
diff --git a/tests/gold_tests/pluginTest/slice/gold_error/non206.stderr.gold 
b/tests/gold_tests/pluginTest/slice/gold_error/non206.stderr.gold
new file mode 100644
index 0000000..fad0575
--- /dev/null
+++ b/tests/gold_tests/pluginTest/slice/gold_error/non206.stderr.gold
@@ -0,0 +1 @@
+the quick``
diff --git a/tests/gold_tests/pluginTest/slice/gold_error/non206.stdout.gold 
b/tests/gold_tests/pluginTest/slice/gold_error/non206.stdout.gold
new file mode 100644
index 0000000..86ee5dd
--- /dev/null
+++ b/tests/gold_tests/pluginTest/slice/gold_error/non206.stdout.gold
@@ -0,0 +1,10 @@
+``
+Cache-Control: ``
+Connection: ``
+Content-Length: 19
+Date: ``
+Etag: ``
+HTTP/1.1 200 OK
+Last-Modified: ``
+Server: ``
+Via: ``
diff --git a/tests/gold_tests/pluginTest/slice/slice_error.test.py 
b/tests/gold_tests/pluginTest/slice/slice_error.test.py
new file mode 100644
index 0000000..f6fd4d5
--- /dev/null
+++ b/tests/gold_tests/pluginTest/slice/slice_error.test.py
@@ -0,0 +1,326 @@
+'''
+'''
+#  Licensed to the Apache Software Foundation (ASF) under one
+#  or more contributor license agreements.  See the NOTICE file
+#  distributed with this work for additional information
+#  regarding copyright ownership.  The ASF licenses this file
+#  to you under the Apache License, Version 2.0 (the
+#  "License"); you may not use this file except in compliance
+#  with the License.  You may obtain a copy of the License at
+#
+#      http://www.apache.org/licenses/LICENSE-2.0
+#
+#  Unless required by applicable law or agreed to in writing, software
+#  distributed under the License is distributed on an "AS IS" BASIS,
+#  WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+#  See the License for the specific language governing permissions and
+#  limitations under the License.
+
+import os
+import time
+Test.Summary = '''
+Slice plugin error.log test
+'''
+
+## Test description:
+# Preload the cache with the entire asset to be range requested.
+# Reload remap rule with slice plugin
+# Request content through the slice plugin
+
+Test.SkipUnless(
+    Condition.HasProgram("curl", "Curl needs to be installed on system for 
this test to work"),
+    Condition.PluginExists('slice.so'),
+)
+Test.ContinueOnFail = False
+
+# configure origin server
+server = Test.MakeOriginServer("server", lookup_key="{%Range}{PATH}")
+
+# Define ATS and configure
+ts = Test.MakeATSProcess("ts", command="traffic_manager")
+
+body = "the quick brown fox" # len 19
+
+# default root
+request_header_chk = {"headers":
+  "GET / HTTP/1.1\r\n" +
+  "Host: www.example.com\r\n" +
+  "Range: bytes=0-\r\n" +
+  "\r\n",
+  "timestamp": "1469733493.993",
+  "body": "",
+}
+
+response_header_chk = {"headers":
+  "HTTP/1.1 206 Partial Content\r\n" +
+  "Connection: close\r\n" +
+  "\r\n",
+  "timestamp": "1469733493.993",
+  "body": body,
+}
+
+server.addResponse("sessionlog.json", request_header_chk, response_header_chk)
+
+blockbytes = 9
+
+range0 = "{}-{}".format(0, blockbytes - 1)
+range1 = "{}-{}".format(blockbytes, (2 * blockbytes) - 1)
+
+body0 = body[0:blockbytes]
+body1 = body[blockbytes:2 * blockbytes]
+
+# Mismatch etag
+
+request_header_etag0 = {"headers":
+  "GET /etag HTTP/1.1\r\n" +
+  "Host: www.example.com\r\n" +
+  "Range: bytes={}\r\n".format(range0) +
+  "X-Slicer-Info: full content request\r\n" +
+  "\r\n",
+  "timestamp": "1469733493.993",
+  "body": "",
+}
+
+response_header_etag0 = {"headers":
+  "HTTP/1.1 206 Partial Content\r\n" +
+  "Connection: close\r\n" +
+  'Etag: "etag0"\r\n' +
+  "Content-Range: bytes {}/{}\r\n".format(range0, len(body)) +
+  "Cache-Control: max-age=500\r\n" +
+  "\r\n",
+  "timestamp": "1469733493.993",
+  "body": body0,
+}
+
+server.addResponse("sessionlog.json", request_header_etag0, 
response_header_etag0)
+
+request_header_etag1 = {"headers":
+  "GET /etag HTTP/1.1\r\n" +
+  "Host: www.example.com\r\n" +
+  "Range: bytes={}\r\n".format(range1) +
+  "X-Slicer-Info: full content request\r\n" +
+  "\r\n",
+  "timestamp": "1469733493.993",
+  "body": "",
+}
+
+response_header_etag1 = {"headers":
+  "HTTP/1.1 206 Partial Content\r\n" +
+  "Connection: close\r\n" +
+  'Etag: "etag1"\r\n' +
+  "Content-Range: bytes {}/{}\r\n".format(range1, len(body)) +
+  "Cache-Control: max-age=500\r\n" +
+  "\r\n",
+  "timestamp": "1469733493.993",
+  "body": body1,
+}
+
+server.addResponse("sessionlog.json", request_header_etag1, 
response_header_etag1)
+
+# mismatch Last-Modified
+
+request_header_lm0 = {"headers":
+  "GET /lastmodified HTTP/1.1\r\n" +
+  "Host: www.example.com\r\n" +
+  "Range: bytes={}\r\n".format(range0) +
+  "X-Slicer-Info: full content request\r\n" +
+  "\r\n",
+  "timestamp": "1469733493.993",
+  "body": "",
+}
+
+response_header_lm0 = {"headers":
+  "HTTP/1.1 206 Partial Content\r\n" +
+  "Connection: close\r\n" +
+  "Last-Modified: Tue, 08 May 2018 15:49:41 GMT\r\n" +
+  "Content-Range: bytes {}/{}\r\n".format(range0, len(body)) +
+  "Cache-Control: max-age=500\r\n" +
+  "\r\n",
+  "timestamp": "1469733493.993",
+  "body": body0,
+}
+
+server.addResponse("sessionlog.json", request_header_lm0, response_header_lm0)
+
+request_header_lm1 = {"headers":
+  "GET /lastmodified HTTP/1.1\r\n" +
+  "Host: www.example.com\r\n" +
+  "Range: bytes={}\r\n".format(range1) +
+  "X-Slicer-Info: full content request\r\n" +
+  "\r\n",
+  "timestamp": "1469733493.993",
+  "body": "",
+}
+
+response_header_lm1 = {"headers":
+  "HTTP/1.1 206 Partial Content\r\n" +
+  "Connection: close\r\n" +
+  "Last-Modified: Tue, 08 Apr 2019 18:00:00 GMT\r\n" +
+  "Content-Range: bytes {}/{}\r\n".format(range1, len(body)) +
+  "Cache-Control: max-age=500\r\n" +
+  "\r\n",
+  "timestamp": "1469733493.993",
+  "body": body1,
+}
+
+server.addResponse("sessionlog.json", request_header_lm1, response_header_lm1)
+
+# non 206 slice block
+
+request_header_n206_0 = {"headers":
+  "GET /non206 HTTP/1.1\r\n" +
+  "Host: www.example.com\r\n" +
+  "Range: bytes={}\r\n".format(range0) +
+  "X-Slicer-Info: full content request\r\n" +
+  "\r\n",
+  "timestamp": "1469733493.993",
+  "body": "",
+}
+
+response_header_n206_0 = {"headers":
+  "HTTP/1.1 206 Partial Content\r\n" +
+  "Connection: close\r\n" +
+  'Etag: "etag"\r\n' +
+  "Last-Modified: Tue, 08 May 2018 15:49:41 GMT\r\n" +
+  "Content-Range: bytes {}/{}\r\n".format(range0, len(body)) +
+  "Cache-Control: max-age=500\r\n" +
+  "\r\n",
+  "timestamp": "1469733493.993",
+  "body": body0,
+}
+
+server.addResponse("sessionlog.json", request_header_n206_0, 
response_header_n206_0)
+
+# mismatch content-range
+
+request_header_crr0 = {"headers":
+  "GET /crr HTTP/1.1\r\n" +
+  "Host: www.example.com\r\n" +
+  "Range: bytes={}\r\n".format(range0) +
+  "X-Slicer-Info: full content request\r\n" +
+  "\r\n",
+  "timestamp": "1469733493.993",
+  "body": "",
+}
+
+response_header_crr0 = {"headers":
+  "HTTP/1.1 206 Partial Content\r\n" +
+  "Connection: close\r\n" +
+  "Etag: crr\r\n" +
+  "Content-Range: bytes {}/{}\r\n".format(range0, len(body)) +
+  "Cache-Control: max-age=500\r\n" +
+  "\r\n",
+  "timestamp": "1469733493.993",
+  "body": body0,
+}
+
+server.addResponse("sessionlog.json", request_header_crr0, 
response_header_crr0)
+
+request_header_crr1 = {"headers":
+  "GET /crr HTTP/1.1\r\n" +
+  "Host: www.example.com\r\n" +
+  "Range: bytes={}\r\n".format(range1) +
+  "X-Slicer-Info: full content request\r\n" +
+  "\r\n",
+  "timestamp": "1469733493.993",
+  "body": "",
+}
+
+response_header_crr1 = {"headers":
+  "HTTP/1.1 206 Partial Content\r\n" +
+  "Connection: close\r\n" +
+  "Etag: crr\r\n" +
+  "Content-Range: bytes {}/{}\r\n".format(range1, len(body) - 1) +
+  "Cache-Control: max-age=500\r\n" +
+  "\r\n",
+  "timestamp": "1469733493.993",
+  "body": body1,
+}
+
+server.addResponse("sessionlog.json", request_header_crr1, 
response_header_crr1)
+
+ts.Setup.CopyAs('curlsort.sh', Test.RunDirectory)
+curl_and_args = 'sh curlsort.sh -H "Host: www.example.com"'
+
+# set up whole asset fetch into cache
+ts.Disk.remap_config.AddLine(
+  'map / http://127.0.0.1:{}'.format(server.Variables.Port) +
+    ' @plugin=slice.so @pparam=bytesover:{}'.format(blockbytes)
+)
+
+# minimal configuration
+ts.Disk.records_config.update({
+  'proxy.config.diags.debug.enabled': 1,
+  'proxy.config.diags.debug.tags': 'slice',
+  'proxy.config.http.cache.http': 0,
+  'proxy.config.http.wait_for_cache': 0,
+  'proxy.config.http.insert_age_in_response': 0,
+  'proxy.config.http.insert_request_via_str': 0,
+  'proxy.config.http.insert_response_via_str': 3,
+  'proxy.config.http.server_ports': '{}'.format(ts.Variables.port),
+})
+
+# Override builtin error check as these cases will fail
+# taken from the slice plug code
+ts.Disk.diags_log.Content = Testers.ContainsExpression('reason="Mismatch block 
Etag"', "Mismatch block etag")
+ts.Disk.diags_log.Content += Testers.ContainsExpression('reason="Mismatch 
block Last-Modified"', "Mismatch block Last-Modified")
+ts.Disk.diags_log.Content += Testers.ContainsExpression('reason="Non 206 
internal block response"', "Non 206 internal block response")
+ts.Disk.diags_log.Content += Testers.ContainsExpression('reason="Mismatch/Bad 
block Content-Range"', "Mismatch/Bad block Content-Range")
+
+# 0 Test - Etag mismatch test
+tr = Test.AddTestRun("Etag test")
+tr.Processes.Default.StartBefore(server)
+tr.Processes.Default.StartBefore(Test.Processes.ts, ready=1)
+tr.Processes.Default.Command = curl_and_args + ' 
http://127.0.0.1:{}/etag'.format(ts.Variables.port)
+tr.Processes.Default.ReturnCode = 0
+tr.Processes.Default.Streams.stdout = "gold_error/etag.stdout.gold"
+tr.Processes.Default.Streams.stderr = "gold_error/etag.stderr.gold"
+tr.StillRunningAfter = ts
+
+# 1 Check - diags.log message
+tr = Test.AddTestRun("Etag error check")
+tr.Processes.Default.Command = "grep 'Mismatch block Etag' 
{}".format(ts.Disk.diags_log.Name)
+tr.Processes.Default.ReturnCode = 0
+tr.StillRunningAfter = ts
+
+# 2 Test - Last Modified mismatch test
+tr = Test.AddTestRun("Last-Modified test")
+tr.Processes.Default.Command = curl_and_args + ' 
http://127.0.0.1:{}/lastmodified'.format(ts.Variables.port)
+tr.Processes.Default.ReturnCode = 0
+tr.Processes.Default.Streams.stdout = "gold_error/lm.stdout.gold"
+tr.Processes.Default.Streams.stderr = "gold_error/lm.stderr.gold"
+tr.StillRunningAfter = ts
+
+# 3 Check - diags.log message
+tr = Test.AddTestRun("Last-Modified error check")
+tr.Processes.Default.Command = "grep 'Mismatch block Last-Modified' 
{}".format(ts.Disk.diags_log.Name)
+tr.Processes.Default.ReturnCode = 0
+tr.StillRunningAfter = ts
+
+# 4 Test - Non 206 mismatch test
+tr = Test.AddTestRun("Non 206 test")
+tr.Processes.Default.Command = curl_and_args + ' 
http://127.0.0.1:{}/non206'.format(ts.Variables.port)
+tr.Processes.Default.ReturnCode = 0
+tr.Processes.Default.Streams.stdout = "gold_error/non206.stdout.gold"
+tr.Processes.Default.Streams.stderr = "gold_error/non206.stderr.gold"
+tr.StillRunningAfter = ts
+
+# 3 Check - diags.log message
+tr = Test.AddTestRun("Non 206 error check")
+tr.Processes.Default.Command = "grep 'Non 206 internal block response' 
{}".format(ts.Disk.diags_log.Name)
+tr.Processes.Default.ReturnCode = 0
+tr.StillRunningAfter = ts
+
+# 4 Test - Block content-range
+tr = Test.AddTestRun("Content-Range test")
+tr.Processes.Default.Command = curl_and_args + ' 
http://127.0.0.1:{}/crr'.format(ts.Variables.port)
+tr.Processes.Default.ReturnCode = 0
+tr.Processes.Default.Streams.stdout = "gold_error/crr.stdout.gold"
+tr.Processes.Default.Streams.stderr = "gold_error/crr.stderr.gold"
+tr.StillRunningAfter = ts
+
+# 3 Check - diags.log message
+tr = Test.AddTestRun("Content-Range error check")
+tr.Processes.Default.Command = "grep 'Mismatch/Bad block Content-Range' 
{}".format(ts.Disk.diags_log.Name)
+tr.Processes.Default.ReturnCode = 0
+tr.StillRunningAfter = ts

Reply via email to