From 6dd31ebedaa30c2a8d971bb79dd0331d107a09c7 Mon Sep 17 00:00:00 2001 From: Brian Olsen Date: Wed, 1 Apr 2020 19:12:37 +0000 Subject: [PATCH] Slice plugin: recover out of sync slices, better handling of non 206s The very first slice is used as the reference slice to make recovery easiest. Recover asset where slices differ in content-length, etag, last-modified. autests included to cover basic functionality. Includes additions to include/ts/experimental.h: tsapi time_t TSMimeParseDate(char const *const value_str, int const value_len); tsapi TSReturnCode TSMimeFormatDate(time_t const value_time, char *const value_str, int *const value_len); These are derived from TSMimeHdrFieldValueDateSet/TSMimeHdrFieldValueDateGet. --- .../plugins/cache_range_requests.en.rst | 8 +- doc/admin-guide/plugins/slice.en.rst | 103 +++-- include/ts/experimental.h | 10 + .../cache_range_requests.cc | 5 +- plugins/experimental/slice/Config.cc | 7 +- plugins/experimental/slice/Config.h | 2 + plugins/experimental/slice/ContentRange.h | 8 +- plugins/experimental/slice/Data.cc | 65 --- plugins/experimental/slice/Data.h | 76 ++-- plugins/experimental/slice/HttpHeader.cc | 54 +++ plugins/experimental/slice/HttpHeader.h | 8 + plugins/experimental/slice/Range.h | 4 +- plugins/experimental/slice/client.cc | 44 +- plugins/experimental/slice/server.cc | 344 ++++++++++++--- plugins/experimental/slice/slice.cc | 46 ++- plugins/experimental/slice/slice.h | 31 +- plugins/experimental/slice/util.cc | 36 +- src/traffic_server/InkAPI.cc | 25 ++ tests/gold_tests/pluginTest/slice/curlsort.sh | 33 -- .../gold_tests/pluginTest/slice/gold/aa.gold | 1 + .../gold_tests/pluginTest/slice/gold/aaa.gold | 1 + .../gold_tests/pluginTest/slice/gold/bb.gold | 1 + .../gold_tests/pluginTest/slice/gold/bbb.gold | 1 + .../slice/gold/slice_200.stderr.gold | 2 +- .../slice/gold/slice_200.stdout.gold | 8 - .../slice/gold/slice_206.stderr.gold | 2 +- .../slice/gold/slice_206.stdout.gold | 9 - .../slice/gold/slice_first.stderr.gold | 2 +- .../slice/gold/slice_first.stdout.gold | 9 - .../slice/gold/slice_last.stderr.gold | 2 +- .../slice/gold/slice_last.stdout.gold | 9 - .../slice/gold/slice_mid.stderr.gold | 2 +- .../slice/gold/slice_mid.stdout.gold | 9 - .../slice/gold_error/contents.stderr.gold | 1 + .../slice/gold_error/crr.stderr.gold | 1 - .../slice/gold_error/crr.stdout.gold | 9 - .../slice/gold_error/etag.stderr.gold | 1 - .../slice/gold_error/etag.stdout.gold | 9 - .../slice/gold_error/lm.stderr.gold | 1 - .../slice/gold_error/lm.stdout.gold | 9 - .../slice/gold_error/non206.stderr.gold | 1 - .../slice/gold_error/non206.stdout.gold | 10 - .../gold_tests/pluginTest/slice/slice.test.py | 141 +++---- .../pluginTest/slice/slice_error.test.py | 158 ++++--- .../pluginTest/slice/slice_regex.test.py | 6 +- .../slice/slice_selfhealing.test.py | 391 ++++++++++++++++++ 46 files changed, 1227 insertions(+), 478 deletions(-) delete mode 100644 plugins/experimental/slice/Data.cc delete mode 100755 tests/gold_tests/pluginTest/slice/curlsort.sh create mode 100644 tests/gold_tests/pluginTest/slice/gold/aa.gold create mode 100644 tests/gold_tests/pluginTest/slice/gold/aaa.gold create mode 100644 tests/gold_tests/pluginTest/slice/gold/bb.gold create mode 100644 tests/gold_tests/pluginTest/slice/gold/bbb.gold delete mode 100644 tests/gold_tests/pluginTest/slice/gold/slice_200.stdout.gold delete mode 100644 tests/gold_tests/pluginTest/slice/gold/slice_206.stdout.gold delete mode 100644 tests/gold_tests/pluginTest/slice/gold/slice_first.stdout.gold delete mode 100644 tests/gold_tests/pluginTest/slice/gold/slice_last.stdout.gold delete mode 100644 tests/gold_tests/pluginTest/slice/gold/slice_mid.stdout.gold create mode 100644 tests/gold_tests/pluginTest/slice/gold_error/contents.stderr.gold delete mode 100644 tests/gold_tests/pluginTest/slice/gold_error/crr.stderr.gold delete mode 100644 tests/gold_tests/pluginTest/slice/gold_error/crr.stdout.gold delete mode 100644 tests/gold_tests/pluginTest/slice/gold_error/etag.stderr.gold delete mode 100644 tests/gold_tests/pluginTest/slice/gold_error/etag.stdout.gold delete mode 100644 tests/gold_tests/pluginTest/slice/gold_error/lm.stderr.gold delete mode 100644 tests/gold_tests/pluginTest/slice/gold_error/lm.stdout.gold delete mode 100644 tests/gold_tests/pluginTest/slice/gold_error/non206.stderr.gold delete mode 100644 tests/gold_tests/pluginTest/slice/gold_error/non206.stdout.gold create mode 100644 tests/gold_tests/pluginTest/slice/slice_selfhealing.test.py diff --git a/doc/admin-guide/plugins/cache_range_requests.en.rst b/doc/admin-guide/plugins/cache_range_requests.en.rst index 6d11d21121a..0189122f36a 100644 --- a/doc/admin-guide/plugins/cache_range_requests.en.rst +++ b/doc/admin-guide/plugins/cache_range_requests.en.rst @@ -113,7 +113,7 @@ all requests (include partial content) will use consistent hashing method for parent selection. -X-CRR-IMS header support +X-Crr-Ims header support ------------------------ .. option:: --consider-ims @@ -125,13 +125,13 @@ special header: .. code:: - X-CRR-IMS: Tue, 19 Nov 2019 13:26:45 GMT + X-Crr-Ims: Tue, 19 Nov 2019 13:26:45 GMT -When this header is provided and a `cache hit fresh` is encoutered the +When this header is provided and a `cache hit fresh` is encountered the ``Date`` header of the object in cache is compared to this header date value. If the cache date is *less* than this IMS date then the object is marked as STALE and an appropriate If-Modified-Since or If-Match -request along with this X-CRR-IMS header is passed up to the parent. +request along with this X-Crr-Ims header is passed up to the parent. In order for this to properly work in a CDN each cache in the chain *SHOULD* also contain a remap rule with the diff --git a/doc/admin-guide/plugins/slice.en.rst b/doc/admin-guide/plugins/slice.en.rst index 8c7063d826f..e04668952d5 100644 --- a/doc/admin-guide/plugins/slice.en.rst +++ b/doc/admin-guide/plugins/slice.en.rst @@ -75,15 +75,6 @@ The slice plugin supports the following options:: Limited to any positive number. Ignored if --blockbytes provided. - --remap-host= (optional) - Uses effective url with given hostname for remapping. - Requires setting up an intermediate loopback remap rule. - -r for short - - --pace-errorlog= (optional) - Limit stitching error logs to every 'n' second(s) - -p for short - --disable-errorlog (optional) Disable writing block stitch errors to the error log. -d for short @@ -100,6 +91,37 @@ The slice plugin supports the following options:: Cannot be used with --exclude-regex -i for short + --pace-errorlog= (optional) + Limit stitching error logs to every 'n' second(s) + -p for short + + --ref-relative (optional) + Self healing mode typically uses slice 0 as the reference slice + for every request. This is very safe but also increases plugin + time and latency as the first slice is always fully processed + whether or not the original requests needs any data from slice 0. + This option uses the first slice in the request as reference + which has better performance. A downside of this mode is that + self healing won't happen if blocks in a request agree. + Normally leave this off. + -l for short + + --remap-host= (optional) + Uses effective url with given hostname for remapping. + Requires setting up an intermediate loopback remap rule. + -r for short + + --throttle (optional) + Under certain circumstances where many contiguous slices are in + RAM cache ATS will aggressively try to push these through the + slice plugin. The downside of this is that all these contiguous + slices end up being marked as fresh even if the downstream + client aborts. This option keeps track of how much data the + client has already passed down and slows down issuing new + slice requests. + Normally leave this off. + -o for short + Examples:: @plugin=slice.so @pparam=--blockbytes=1000000 @plugin=cache_range_requests.so @@ -194,21 +216,50 @@ adding in range request headers ("Range: bytes="). A special header X-Slicer-Info header is added and the pristine URL is restored. -For each of these blocks separate sequential TSHttpConnect(s) are made -back into the front end of ATS and all of the remap plugins are rerun. -Slice skips the remap due to presence of the X-Slicer-Info header and -allows cache_range_requests.so to serve the slice block back to Slice -either via cache OR parent request. - -Slice assembles a header based on the first slice block response and -sends it to the client. If necessary it then skips over bytes in -the first block and starts sending byte content, examining each -block header and sends its bytes to the client until the client -request is satisfied. - -Any extra bytes at the end of the last block are consumed by -the Slice plugin to allow cache_range_requests to finish -the block fetch to ensure the block is cached. +For each of these blocks separate sequential TSHttpConnect(s) are +made back into the front end of ATS. By default of the remap plugins +are rerun. Slice skips the remap due to presence of the X-Slicer-Info +header and allows cache_range_requests.so to serve the slice block back +to Slice either via cache OR parent request. + +Slice assembles a header based on the very first slice block response +and sends it to the client. If necessary it then skips over bytes in the +first block and starts sending byte content, examining each block header +and sends its bytes to the client until the client request is satisfied. + +Any extra bytes at the end of the last block are consumed by the the +Slice plugin to allow cache_range_requests to finish the block fetch to +ensure the block is cached. + +Self Healing +------------ + +The slice plugin uses the very first slice as a reference slice which +uses content-length and last-modified and/or etags to ensure assembled +blocks come from the same asset. In the case where a slice from a parent +is fetched which indicates that the asset has changed, the slice plugin +will attempt to self heal the asset. The `cache_range_requests` plugin +must be configured with the `--consider-ims` parameter in order for +this to work. + +Example `remap.config` configuration:: + + map http://slice/ http://parent/ @plugin=slice.so @pparam=--remap-host=cache_range_requests + map http://cache_range_requests/ http://parent/ @plugin=cache_range_requests.so @pparam=--consider-ims + +When a request is served, the slice plugin uses reference slice 0 to +build a response to the client. When subsequent slices are fetched they +are checked against this reference slice. If a mismatch occurs an IMS +request for the offending slice is made through the `cache_range_requests` +plugin using an X-Crr-Ims header. If the refetched slice still mismatches +then the client connection is aborted a crr IMS request is made for +the reference slice in an attempt to refetch it. + +Optionally (but not recommended) the plugin may be configured to use +the first slice in the request as the reference slice. This option +is faster since it does not visit any slices outside those needed to +fulfill a request. However this may still cause problems if the +requested range was calculated from a newer version of the asset. Important Notes =============== @@ -216,8 +267,8 @@ Important Notes This plugin assumes that the content requested is cacheable. Any first block server response that is not a 206 is passed directly -down to the client. If that response is a '200' only the first -portion of the response is passed back and the transaction is closed. +down to the client. Any 200 responses are passed back through to +the client. Only the first server response block is used to evaluate any "If-" conditional headers. Subsequent server slice block requests diff --git a/include/ts/experimental.h b/include/ts/experimental.h index d2ebfd0211a..52118f7d3d4 100644 --- a/include/ts/experimental.h +++ b/include/ts/experimental.h @@ -452,6 +452,16 @@ tsapi TSMBuffer TSFetchRespHdrMBufGet(TSFetchSM fetch_sm); */ tsapi TSMLoc TSFetchRespHdrMLocGet(TSFetchSM fetch_sm); +/* + * Parse a MIME header date string. + */ +tsapi time_t TSMimeParseDate(char const *const value_str, int const value_len); + +/* + * Print as a MIME header date string. + */ +tsapi TSReturnCode TSMimeFormatDate(time_t const value_time, char *const value_str, int *const value_len); + #ifdef __cplusplus } #endif /* __cplusplus */ diff --git a/plugins/cache_range_requests/cache_range_requests.cc b/plugins/cache_range_requests/cache_range_requests.cc index 41a770221ba..0ca59d9765e 100644 --- a/plugins/cache_range_requests/cache_range_requests.cc +++ b/plugins/cache_range_requests/cache_range_requests.cc @@ -29,6 +29,7 @@ #include "ts/ts.h" #include "ts/remap.h" +#include #include #include #include @@ -58,7 +59,7 @@ struct txndata { }; // Header for optional revalidation -constexpr std::string_view X_IMS_HEADER = {"X-CRR-IMS"}; +constexpr std::string_view X_IMS_HEADER = {"X-Crr-Ims"}; // pluginconfig struct (global plugin only) pluginconfig *gPluginConfig = {nullptr}; @@ -240,6 +241,7 @@ range_header_check(TSHttpTxn txnp, pluginconfig *const pc) TSMLoc const imsloc = TSMimeHdrFieldFind(hdr_buf, hdr_loc, X_IMS_HEADER.data(), X_IMS_HEADER.size()); if (TS_NULL_MLOC != imsloc) { time_t const itime = TSMimeHdrFieldValueDateGet(hdr_buf, hdr_loc, imsloc); + DEBUG_LOG("Servicing the '%.*s' header", (int)X_IMS_HEADER.size(), X_IMS_HEADER.data()); TSHandleMLocRelease(hdr_buf, hdr_loc, imsloc); if (0 < itime) { txn_state->ims_time = itime; @@ -477,6 +479,7 @@ handle_cache_lookup_complete(TSHttpTxn txnp, txndata *const txn_state) if (TS_SUCCESS == TSHttpTxnCacheLookupStatusGet(txnp, &cachestat)) { if (TS_CACHE_LOOKUP_HIT_FRESH == cachestat) { time_t const ch_time = get_date_from_cached_hdr(txnp); + DEBUG_LOG("IMS Cached header time %" PRId64 " vs IMS %" PRId64, ch_time, txn_state->ims_time); if (ch_time < txn_state->ims_time) { TSHttpTxnCacheLookupStatusSet(txnp, TS_CACHE_LOOKUP_HIT_STALE); if (TSIsDebugTagSet(PLUGIN_NAME)) { diff --git a/plugins/experimental/slice/Config.cc b/plugins/experimental/slice/Config.cc index 17b7329c656..2ff68662d6e 100644 --- a/plugins/experimental/slice/Config.cc +++ b/plugins/experimental/slice/Config.cc @@ -111,6 +111,7 @@ Config::fromArgs(int const argc, char const *const argv[]) {const_cast("disable-errorlog"), no_argument, nullptr, 'd'}, {const_cast("exclude-regex"), required_argument, nullptr, 'e'}, {const_cast("include-regex"), required_argument, nullptr, 'i'}, + {const_cast("ref-relative"), no_argument, nullptr, 'l'}, {const_cast("throttle"), no_argument, nullptr, 'o'}, {const_cast("pace-errorlog"), required_argument, nullptr, 'p'}, {const_cast("remap-host"), required_argument, nullptr, 'r'}, @@ -121,7 +122,7 @@ Config::fromArgs(int const argc, char const *const argv[]) // getopt assumes args start at '1' so this hack is needed char *const *argvp = (const_cast(argv) - 1); for (;;) { - int const opt = getopt_long(argc + 1, argvp, "b:de:i:op:r:t:", longopts, nullptr); + int const opt = getopt_long(argc + 1, argvp, "b:de:i:lop:r:t:", longopts, nullptr); if (-1 == opt) { break; } @@ -177,6 +178,10 @@ Config::fromArgs(int const argc, char const *const argv[]) DEBUG_LOG("Using regex for url include: '%s'", m_regexstr.c_str()); } } break; + case 'l': { + m_reftype = RefType::Relative; + DEBUG_LOG("Reference slice relative to request (not slice block 0)"); + } break; case 'o': { m_throttle = true; DEBUG_LOG("Enabling internal block throttling"); diff --git a/plugins/experimental/slice/Config.h b/plugins/experimental/slice/Config.h index 5edf4638f07..1f59511e8c0 100644 --- a/plugins/experimental/slice/Config.h +++ b/plugins/experimental/slice/Config.h @@ -43,6 +43,8 @@ struct Config { pcre_extra *m_regex_extra{nullptr}; bool m_throttle{false}; // internal block throttling int m_paceerrsecs{0}; // -1 disable logging, 0 no pacing, max 60s + enum RefType { First, Relative }; + RefType m_reftype{First}; // reference slice is relative to request // Convert optarg to bytes static int64_t bytesFrom(char const *const valstr); diff --git a/plugins/experimental/slice/ContentRange.h b/plugins/experimental/slice/ContentRange.h index 2412e668433..3755a96e80f 100644 --- a/plugins/experimental/slice/ContentRange.h +++ b/plugins/experimental/slice/ContentRange.h @@ -25,12 +25,13 @@ Range is converted from closed range into a half open range for. */ struct ContentRange { - int64_t m_beg = -1; - int64_t m_end = -1; // half open - int64_t m_length = -1; // full content length + int64_t m_beg{-1}; + int64_t m_end{-1}; // half open + int64_t m_length{-1}; // full content length ContentRange() {} explicit ContentRange(int64_t const begin, int64_t const end, int64_t const len) : m_beg(begin), m_end(end), m_length(len) {} + bool isValid() const { @@ -38,6 +39,7 @@ struct ContentRange { } /** parsed from a Content-Range field + * Must be null terminated. */ bool fromStringClosed(char const *const valstr); diff --git a/plugins/experimental/slice/Data.cc b/plugins/experimental/slice/Data.cc deleted file mode 100644 index aac6943d47b..00000000000 --- a/plugins/experimental/slice/Data.cc +++ /dev/null @@ -1,65 +0,0 @@ -/** @file - 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. - */ - -#include "Data.h" - -#include -#include -#include -#include -#include - -namespace -{ -std::mutex mutex; -int64_t inplay = 0; -std::unique_ptr thread; -} // namespace - -void -monitor() -{ - std::lock_guard guard(mutex); - // while (0 < inplay) - while (true) { - mutex.unlock(); - std::this_thread::sleep_for(std::chrono::seconds(10)); - std::cerr << "Inplay: " << inplay << std::endl; - mutex.lock(); - } - // thread.release(); -} - -void -incrData() -{ - std::lock_guard const guard(mutex); - if (!thread) { - thread.reset(new std::thread(monitor)); - } - - ++inplay; -} - -void -decrData() -{ - std::lock_guard const guard(mutex); - --inplay; - assert(0 <= inplay); -} diff --git a/plugins/experimental/slice/Data.h b/plugins/experimental/slice/Data.h index 3150bd299b8..e29ad8420ea 100644 --- a/plugins/experimental/slice/Data.h +++ b/plugins/experimental/slice/Data.h @@ -28,6 +28,18 @@ struct Config; +enum BlockState { + Pending, + PendingInt, // Pending internal refectch + PendingRef, // Pending reference refetch + Active, + ActiveInt, // Active internal refetch + ActiveRef, // Active reference refetch + Done, + Passthru, // non 206 response passthru + Fail, +}; + struct Data { Data(Data const &) = delete; Data &operator=(Data const &) = delete; @@ -41,32 +53,34 @@ struct Data { TSMLoc m_urlloc{nullptr}; char m_hostname[8192]; - int m_hostlen; + int m_hostlen{0}; + + // read from slice block 0 + char m_date[33]; + int m_datelen{0}; char m_etag[8192]; - int m_etaglen; - char m_lastmodified[8192]; - int m_lastmodifiedlen; + int m_etaglen{0}; + char m_lastmodified[33]; + int m_lastmodifiedlen{0}; - TSHttpStatus m_statustype; // 200 or 206 + int64_t m_contentlen{-1}; - bool m_bail; // non 206/200 response + TSHttpStatus m_statustype{TS_HTTP_STATUS_NONE}; // 200 or 206 Range m_req_range; // converted to half open interval - int64_t m_contentlen; - int64_t m_blocknum; // block number to work on, -1 bad/stop - int64_t m_blockexpected; // body bytes expected - int64_t m_blockskip; // number of bytes to skip in this block - int64_t m_blockconsumed; // body bytes consumed + int64_t m_blocknum{-1}; // block number to work on, -1 bad/stop + int64_t m_blockexpected{0}; // body bytes expected + int64_t m_blockskip{0}; // number of bytes to skip in this block + int64_t m_blockconsumed{0}; // body bytes consumed - enum BlockState { Pending, Active, Done, Fail }; - BlockState m_blockstate; // is there an active slice block + BlockState m_blockstate{Pending}; // is there an active slice block - int64_t m_bytestosend; // header + content bytes to send - int64_t m_bytessent; // number of bytes written to the client + int64_t m_bytestosend{0}; // header + content bytes to send + int64_t m_bytessent{0}; // number of bytes written to the client - bool m_server_block_header_parsed; - bool m_server_first_header_parsed; + bool m_server_block_header_parsed{false}; + bool m_server_first_header_parsed{false}; Stage m_upstream; Stage m_dnstream; @@ -76,31 +90,12 @@ struct Data { TSHttpParser m_http_parser{nullptr}; //!< cached for reuse - explicit Data(Config *const config) - : m_config(config), - m_client_ip(), - m_urlbuf(nullptr), - m_urlloc(nullptr), - m_hostlen(0), - m_etaglen(0), - m_lastmodifiedlen(0), - m_statustype(TS_HTTP_STATUS_NONE), - m_req_range(-1, -1), - m_contentlen(-1), - m_blocknum(-1), - m_blockexpected(0), - m_blockskip(0), - m_blockconsumed(0), - m_blockstate(Pending), - m_bytestosend(0), - m_bytessent(0), - m_server_block_header_parsed(false), - m_server_first_header_parsed(false), - m_http_parser(nullptr) + explicit Data(Config *const config) : m_config(config) { + m_date[0] = '\0'; m_hostname[0] = '\0'; - m_lastmodified[0] = '\0'; m_etag[0] = '\0'; + m_lastmodified[0] = '\0'; #if defined(COLLECT_STATS) TSStatIntIncrement(stats::DataCreate, 1); #endif @@ -114,11 +109,14 @@ struct Data { if (nullptr != m_urlbuf) { if (nullptr != m_urlloc) { TSHandleMLocRelease(m_urlbuf, TS_NULL_MLOC, m_urlloc); + m_urlloc = nullptr; } TSMBufferDestroy(m_urlbuf); + m_urlbuf = nullptr; } if (nullptr != m_http_parser) { TSHttpParserDestroy(m_http_parser); + m_http_parser = nullptr; } } }; diff --git a/plugins/experimental/slice/HttpHeader.cc b/plugins/experimental/slice/HttpHeader.cc index f70c42e264c..2a66e5a20d3 100644 --- a/plugins/experimental/slice/HttpHeader.cc +++ b/plugins/experimental/slice/HttpHeader.cc @@ -20,6 +20,7 @@ #include "slice.h" +#include #include #include @@ -231,6 +232,59 @@ HttpHeader::setKeyVal(char const *const keystr, int const keylen, char const *co return status; } +bool +HttpHeader::timeForKey(char const *const keystr, int const keylen, time_t *const timeval) const +{ + TSAssert(nullptr != timeval); + + if (!isValid()) { + *timeval = 0; + return false; + } + + bool status = false; + + TSMLoc const locfield = TSMimeHdrFieldFind(m_buffer, m_lochdr, keystr, keylen); + + if (nullptr != locfield) { + *timeval = TSMimeHdrFieldValueDateGet(m_buffer, m_lochdr, locfield); + TSHandleMLocRelease(m_buffer, m_lochdr, locfield); + } else { + *timeval = 0; + } + + return status; +} + +bool +HttpHeader::setKeyTime(char const *const keystr, int const keylen, time_t const timeval) +{ + if (!isValid()) { + return false; + } + + bool status(false); + + TSMLoc locfield(TSMimeHdrFieldFind(m_buffer, m_lochdr, keystr, keylen)); + + if (nullptr == locfield) { + DEBUG_LOG("Creating header %.*s", keylen, keystr); + TSMimeHdrFieldCreateNamed(m_buffer, m_lochdr, keystr, keylen, &locfield); + } + + if (nullptr != locfield) { + if (TS_SUCCESS == TSMimeHdrFieldValueDateSet(m_buffer, m_lochdr, locfield, timeval)) { + if (TS_SUCCESS == TSMimeHdrFieldAppend(m_buffer, m_lochdr, locfield)) { + status = true; + DEBUG_LOG("Set header %.*s to %" PRId64, keylen, keystr, timeval); + } + } + TSHandleMLocRelease(m_buffer, m_lochdr, locfield); + } + + return status; +} + std::string HttpHeader::toString() const { diff --git a/plugins/experimental/slice/HttpHeader.h b/plugins/experimental/slice/HttpHeader.h index 001e5f6480a..e22b83d4bf6 100644 --- a/plugins/experimental/slice/HttpHeader.h +++ b/plugins/experimental/slice/HttpHeader.h @@ -47,6 +47,7 @@ struct HttpHeader { TSMLoc const m_lochdr; explicit HttpHeader(TSMBuffer buffer, TSMLoc lochdr) : m_buffer(buffer), m_lochdr(lochdr) {} + bool isValid() const { @@ -112,6 +113,7 @@ struct HttpHeader { // returns false if header invalid or something went wrong with removal. bool removeKey(char const *const key, int const keylen); + // retrieves header value as a char* 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 @@ -125,6 +127,12 @@ struct HttpHeader { int const index = -1 // sets all values ); + // retrieves header value as a time_t + bool timeForKey(char const *const keystr, int const keylen, time_t *const timeval) const; + + // sets header value as a time_t + bool setKeyTime(char const *const key, int const keylen, time_t const timeval); + /** dump header into provided char buffer */ std::string toString() const; diff --git a/plugins/experimental/slice/Range.h b/plugins/experimental/slice/Range.h index 8c8826d2091..ba581c6a37a 100644 --- a/plugins/experimental/slice/Range.h +++ b/plugins/experimental/slice/Range.h @@ -31,8 +31,8 @@ struct Range { public: static int64_t constexpr maxval = (std::numeric_limits::max() >> 2); - int64_t m_beg = -1; - int64_t m_end = -1; // half open + int64_t m_beg{-1}; + int64_t m_end{-1}; // half open Range() {} explicit Range(int64_t const begin, int64_t const end) : m_beg(begin), m_end(end) {} diff --git a/plugins/experimental/slice/client.cc b/plugins/experimental/slice/client.cc index 5d4bde5e690..1ad1b74f2f1 100644 --- a/plugins/experimental/slice/client.cc +++ b/plugins/experimental/slice/client.cc @@ -27,6 +27,9 @@ bool handle_client_req(TSCont contp, TSEvent event, Data *const data) { +#if defined(COLLECT_STATS) + stats::StatsRAI const rai(stats::ClientTime); +#endif switch (event) { case TS_EVENT_VCONN_READ_READY: case TS_EVENT_VCONN_READ_COMPLETE: { @@ -85,15 +88,19 @@ handle_client_req(TSCont contp, TSEvent event, Data *const data) rangebe = Range(0, Range::maxval); } - // set to the first block in range - data->m_blocknum = rangebe.firstBlockFor(data->m_config->m_blockbytes); + if (Config::RefType::First == data->m_config->m_reftype) { + data->m_blocknum = 0; + } else { + data->m_blocknum = rangebe.firstBlockFor(data->m_config->m_blockbytes); + } + data->m_req_range = rangebe; // remove ATS keys to avoid 404 loop header.removeKey(TS_MIME_FIELD_VIA, TS_MIME_LEN_VIA); header.removeKey(TS_MIME_FIELD_X_FORWARDED_FOR, TS_MIME_LEN_X_FORWARDED_FOR); - // send the first block request to server + // send block request to server if (!request_block(contp, data)) { abort(contp, data); return false; @@ -119,15 +126,28 @@ handle_client_req(TSCont contp, TSEvent event, Data *const data) void handle_client_resp(TSCont contp, TSEvent event, Data *const data) { - DEBUG_LOG("%p handle_client_resp %s", data, TSHttpEventNameLookup(event)); - #if defined(COLLECT_STATS) TSStatIntIncrement(stats::Client, 1); + stats::StatsRAI const rai(stats::ClientTime); #endif switch (event) { case TS_EVENT_VCONN_WRITE_READY: { - if (Data::BlockState::Pending == data->m_blockstate) { + switch (data->m_blockstate) { + case BlockState::Fail: + case BlockState::PendingRef: + case BlockState::ActiveRef: { + TSVIO const output_vio = data->m_dnstream.m_write.m_vio; + int64_t const output_done = TSVIONDoneGet(output_vio); + int64_t const output_sent = data->m_bytessent; + + if (output_sent == output_done) { + DEBUG_LOG("Downstream output is done, shutting down"); + shutdown(contp, data); + } + } break; + + case BlockState::Pending: { bool start_next_block = true; if (data->m_config->m_throttle) { @@ -140,11 +160,17 @@ handle_client_resp(TSCont contp, TSEvent event, Data *const data) start_next_block = false; DEBUG_LOG("%p handle_client_resp: throttling %" PRId64, data, (output_done - output_sent)); } - } - if (start_next_block) { - request_block(contp, data); + if (start_next_block) { + DEBUG_LOG("Starting next block request"); + request_block(contp, data); + } } + } break; + case BlockState::Passthru: { + } break; + default: + break; } } break; case TS_EVENT_VCONN_WRITE_COMPLETE: { diff --git a/plugins/experimental/slice/server.cc b/plugins/experimental/slice/server.cc index 5356806a52f..54b7ce19f9d 100644 --- a/plugins/experimental/slice/server.cc +++ b/plugins/experimental/slice/server.cc @@ -46,19 +46,62 @@ contentRangeFrom(HttpHeader const &header) if (!hasContentRange) { DEBUG_LOG("invalid response header, no Content-Range"); - } else if (!bcr.fromStringClosed(rangestr)) { - DEBUG_LOG("invalid response header, malformed Content-Range, %s", rangestr); + } else { + // ensure null termination + rangestr[rangelen] = '\0'; + if (!bcr.fromStringClosed(rangestr)) { + DEBUG_LOG("invalid response header, malformed Content-Range, %s", rangestr); + } } return bcr; } -bool +int64_t +contentLengthFrom(HttpHeader const &header) +{ + int64_t bytes = 0; + + char constr[1024]; + int conlen = sizeof(constr); + + // look for expected Content-Length field + bool const hasContentLength(header.valueForKey(TS_MIME_FIELD_CONTENT_LENGTH, TS_MIME_LEN_CONTENT_LENGTH, constr, &conlen)); + + if (!hasContentLength) { + DEBUG_LOG("invalid response header, no Content-Length"); + bytes = INT64_MAX; + } else { + // ensure null termination + constr[conlen] = '\0'; + char *endptr = nullptr; + bytes = std::max((int64_t)0, (int64_t)strtoll(constr, &endptr, 10)); + } + + return bytes; +} + +// Also reference server header +enum HeaderState { + Good, + Fail, + Passthru, +}; + +HeaderState handleFirstServerHeader(Data *const data, TSCont const contp) { +#if defined(COLLECT_STATS) + stats::StatsRAI const rai(stats::FirstHeaderTime); +#endif + + HeaderState state = HeaderState::Good; + HttpHeader header(data->m_resp_hdrmgr.m_buffer, data->m_resp_hdrmgr.m_lochdr); - // DEBUG_LOG("First header\n%s", header.toString().c_str()); + if (TSIsDebugTagSet(PLUGIN_NAME)) { + DEBUG_LOG("First header\n%s", header.toString().c_str()); + } data->m_dnstream.setupVioWrite(contp, INT64_MAX); @@ -71,22 +114,29 @@ handleFirstServerHeader(Data *const data, TSCont const contp) DEBUG_LOG("Initial response other than 206: %d", header.status()); // Should run TSVIONSetBytes(output_io, hlen + bodybytes); - // int const hlen = TSHttpHdrLengthGet(header.m_buffer, header.m_lochdr); - // TSVIONBytesSet(output_vio, hlen); + int64_t const hlen = TSHttpHdrLengthGet(header.m_buffer, header.m_lochdr); + int64_t const clen = contentLengthFrom(header); + DEBUG_LOG("Passthru: header: %" PRId64 " body: %" PRId64, hlen, clen); + if (clen != INT64_MAX) { + TSVIONBytesSet(output_vio, hlen + clen); + } else { + TSVIONBytesSet(output_vio, clen); + } TSHttpHdrPrint(header.m_buffer, header.m_lochdr, output_buf); - transfer_all_bytes(data); - - return false; + state = HeaderState::Passthru; + return state; } ContentRange const blockcr = contentRangeFrom(header); + // 206 with bad content range? if (!blockcr.isValid()) { static std::string const &msg502 = string502(); TSVIONBytesSet(output_vio, msg502.size()); TSIOBufferWrite(output_buf, msg502.data(), msg502.size()); TSVIOReenable(output_vio); - return false; + state = HeaderState::Fail; + return state; } // set the resource content length from block response @@ -120,13 +170,17 @@ handleFirstServerHeader(Data *const data, TSCont const contp) data->m_upstream.m_read.close(); - return false; + state = HeaderState::Fail; } + // save data header string + data->m_datelen = sizeof(data->m_date); + header.valueForKey(TS_MIME_FIELD_DATE, TS_MIME_LEN_DATE, data->m_date, &data->m_datelen); + // save weak cache header identifiers (rfc7232 section 2) - data->m_etaglen = sizeof(data->m_etag) - 1; + data->m_etaglen = sizeof(data->m_etag); header.valueForKey(TS_MIME_FIELD_ETAG, TS_MIME_LEN_ETAG, data->m_etag, &data->m_etaglen); - data->m_lastmodifiedlen = sizeof(data->m_lastmodified) - 1; + data->m_lastmodifiedlen = sizeof(data->m_lastmodified); header.valueForKey(TS_MIME_FIELD_LAST_MODIFIED, TS_MIME_LEN_LAST_MODIFIED, data->m_lastmodified, &data->m_lastmodifiedlen); // size of the first block payload @@ -149,7 +203,7 @@ handleFirstServerHeader(Data *const data, TSCont const contp) data->m_dnstream.close(); ERROR_LOG("Bad/invalid response content range"); - return false; + state = HeaderState::Fail; } header.setKeyVal(TS_MIME_FIELD_CONTENT_RANGE, TS_MIME_LEN_CONTENT_RANGE, rangestr, rangelen); @@ -173,7 +227,7 @@ handleFirstServerHeader(Data *const data, TSCont const contp) data->m_bytessent = hbytes; TSVIOReenable(output_vio); - return true; + return state; } void @@ -241,9 +295,8 @@ logSliceError(char const *const message, Data const *const data, HttpHeader cons 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); + time_t lmgot = 0; + header_resp.timeForKey(TS_MIME_FIELD_LAST_MODIFIED, TS_MIME_LEN_LAST_MODIFIED, &lmgot); // cc char ccstr[2048]; @@ -279,61 +332,151 @@ logSliceError(char const *const message, Data const *const data, HttpHeader cons " status_got=\"%d\"" " cr_got=\"%.*s\"" " etag_got=\"%.*s\"" - " lm_got=\"%.*s\"" + " lm_got=\"%" PRId64 "\"" " cc=\"%.*s\"" - " via=\"%.*s\"", + " via=\"%.*s\" - attempting to recover", 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); + (int)etaggotlen, etaggotstr, lmgot, cclen, ccstr, vialen, viastr); } bool handleNextServerHeader(Data *const data, TSCont const contp) { +#if defined(COLLECT_STATS) + stats::StatsRAI const rai(stats::NextHeaderTime); +#endif + // 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()); + if (TSIsDebugTagSet(PLUGIN_NAME)) { + 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()) { - logSliceError("Non 206 internal block response", data, header); + bool same = true; + + switch (header.status()) { + case TS_HTTP_STATUS_NOT_FOUND: + // need to reissue reference slice + logSliceError("404 internal block response (asset gone)", data, header); + same = false; + break; + case TS_HTTP_STATUS_PARTIAL_CONTENT: + break; + default: + DEBUG_LOG("Non 206/404 internal block response encountered"); return false; + break; } // can't parse the content range header, abort -- might be too strict - ContentRange const blockcr = contentRangeFrom(header); - if (!blockcr.isValid() || blockcr.m_length != data->m_contentlen) { - logSliceError("Mismatch/Bad block Content-Range", data, header); - return false; - } + ContentRange blockcr; - bool same = true; + if (same) { + blockcr = contentRangeFrom(header); + if (!blockcr.isValid() || blockcr.m_length != data->m_contentlen) { + logSliceError("Mismatch/Bad block Content-Range", data, header); + same = false; + } + } - // prefer the etag but use Last-Modified if we must. - char etag[8192]; - int etaglen = sizeof(etag); - header.valueForKey(TS_MIME_FIELD_ETAG, TS_MIME_LEN_ETAG, etag, &etaglen); + if (same) { + // prefer the etag but use Last-Modified if we must. + char etag[8192]; + 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) { - logSliceError("Mismatch block Etag", data, header); - } - } else { - char lastmodified[8192]; - 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 (0 < data->m_etaglen || 0 < etaglen) { + same = data->m_etaglen == etaglen && 0 == strncmp(etag, data->m_etag, etaglen); if (!same) { - logSliceError("Mismatch block Last-Modified", data, header); + logSliceError("Mismatch block Etag", data, header); + } + } else { + char lastmodified[33]; + 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) { + logSliceError("Mismatch block Last-Modified", data, header); + } } } } - if (!same) { - data->m_upstream.close(); - return false; + // Header mismatch + if (same) { + // If we were in reference block refetch mode and the headers + // still match there is a problem + if (BlockState::ActiveRef == data->m_blockstate) { + ERROR_LOG("Reference block refetched, got the same block back again"); + return false; + } + } else { + switch (data->m_blockstate) { + case BlockState::Active: { + data->m_upstream.abort(); + + // Refetch the current interior slice + data->m_blockstate = BlockState::PendingInt; + + time_t date = 0; + header.timeForKey(TS_MIME_FIELD_DATE, TS_MIME_LEN_DATE, &date); + + // Ask for any slice newer than the cached one + time_t const dateims = date + 1; + + DEBUG_LOG("Attempting to reissue interior slice block request with IMS header time: %" PRId64, dateims); + + // add special CRR IMS header to the request + HttpHeader headerreq(data->m_req_hdrmgr.m_buffer, data->m_req_hdrmgr.m_lochdr); + if (!headerreq.setKeyTime(X_CRR_IMS_HEADER.data(), X_CRR_IMS_HEADER.size(), dateims)) { + ERROR_LOG("Failed setting '%.*s'", (int)X_CRR_IMS_HEADER.size(), X_CRR_IMS_HEADER.data()); + return false; + } + + } break; + case BlockState::ActiveInt: { + data->m_upstream.abort(); + + // New interior slice still mismatches, refetch the reference slice + data->m_blockstate = BlockState::PendingRef; + + // convert reference date header to time_t + time_t const date = TSMimeParseDate(data->m_date, data->m_datelen); + + // Ask for any slice newer than the cached one + time_t const dateims = date + 1; + + DEBUG_LOG("Attempting to reissue reference slice block request with IMS header time: %" PRId64, dateims); + + // add special CRR IMS header to the request + HttpHeader headerreq(data->m_req_hdrmgr.m_buffer, data->m_req_hdrmgr.m_lochdr); + if (!headerreq.setKeyTime(X_CRR_IMS_HEADER.data(), X_CRR_IMS_HEADER.size(), dateims)) { + ERROR_LOG("Failed setting '%.*s'", (int)X_CRR_IMS_HEADER.size(), X_CRR_IMS_HEADER.data()); + return false; + } + + // Reset for first block + if (Config::RefType::First == data->m_config->m_reftype) { + data->m_blocknum = 0; + } else { + data->m_blocknum = data->m_req_range.firstBlockFor(data->m_config->m_blockbytes); + } + + return true; + + } break; + // Refetch the reference slice + case BlockState::ActiveRef: { + // In this state the reference changed otherwise the asset is toast + // reset the content length (if content length drove the mismatch) + data->m_contentlen = blockcr.m_length; + return true; + } break; + default: + break; + } } data->m_blockexpected = blockcr.rangeSize(); @@ -347,14 +490,18 @@ handleNextServerHeader(Data *const data, TSCont const contp) void handle_server_resp(TSCont contp, TSEvent event, Data *const data) { - DEBUG_LOG("%p handle_server_resp: %s", data, TSHttpEventNameLookup(event)); - #if defined(COLLECT_STATS) TSStatIntIncrement(stats::Server, 1); + stats::StatsRAI const rai(stats::ServerTime); #endif switch (event) { case TS_EVENT_VCONN_READ_READY: { + if (data->m_blockstate == BlockState::Passthru) { + transfer_all_bytes(data); + return; + } + // has block response header been parsed?? if (!data->m_server_block_header_parsed) { int64_t consumed = 0; @@ -374,19 +521,38 @@ handle_server_resp(TSCont contp, TSEvent event, Data *const data) if (TS_PARSE_DONE == res) { if (!data->m_server_first_header_parsed) { - headerStat = handleFirstServerHeader(data, contp); + HeaderState const state = handleFirstServerHeader(data, contp); + data->m_server_first_header_parsed = true; + switch (state) { + case HeaderState::Fail: + data->m_blockstate = BlockState::Fail; + headerStat = false; + break; + case HeaderState::Passthru: { + data->m_blockstate = BlockState::Passthru; + transfer_all_bytes(data); + DEBUG_LOG("Going into a passthru state"); + return; + } break; + case HeaderState::Good: + default: + headerStat = true; + break; + } } else { headerStat = handleNextServerHeader(data, contp); } data->m_server_block_header_parsed = true; + } else if (TS_PARSE_CONT == res) { + return; } // kill the upstream and allow dnstream to clean up if (!headerStat) { data->m_upstream.abort(); - data->m_blockstate = Data::BlockState::Fail; + data->m_blockstate = BlockState::Fail; if (data->m_dnstream.m_write.isOpen()) { TSVIOReenable(data->m_dnstream.m_write.m_vio); } else { @@ -395,8 +561,41 @@ handle_server_resp(TSCont contp, TSEvent event, Data *const data) return; } - // how much to fast forward into this data block - data->m_blockskip = data->m_req_range.skipBytesForBlock(data->m_config->m_blockbytes, data->m_blocknum); + // header may have been successfully parsed but with caveats + switch (data->m_blockstate) { + // request new version of current internal slice + case BlockState::PendingInt: { + request_block(contp, data); + return; + } break; + // request new version of reference slice + case BlockState::PendingRef: { + request_block(contp, data); + return; + } break; + case BlockState::ActiveRef: { + // Mark the reference block for "skip". + int64_t const blockbytes = data->m_config->m_blockbytes; + int64_t const firstblock = data->m_req_range.firstBlockFor(blockbytes); + int64_t const blockpos = firstblock * blockbytes; + int64_t const firstblockbytes = std::min(blockbytes, data->m_contentlen - blockpos); + data->m_blockskip = firstblockbytes; + + // Check if we should abort the client + if (data->m_dnstream.isOpen()) { + TSVIO const output_vio = data->m_dnstream.m_write.m_vio; + int64_t const output_done = TSVIONDoneGet(output_vio); + int64_t const output_sent = data->m_bytessent; + if (output_done == output_sent) { + data->m_dnstream.abort(); + } + } + } break; + default: { + // how much to normally fast forward into this data block + data->m_blockskip = data->m_req_range.skipBytesForBlock(data->m_config->m_blockbytes, data->m_blocknum); + } break; + } } transfer_content_bytes(data); @@ -405,13 +604,40 @@ handle_server_resp(TSCont contp, TSEvent event, Data *const data) // fprintf(stderr, "%p: TS_EVENT_VCONN_READ_COMPLETE\n", data); } break; case TS_EVENT_VCONN_EOS: { - data->m_blockstate = Data::BlockState::Pending; + switch (data->m_blockstate) { + case BlockState::ActiveRef: + case BlockState::Passthru: { + transfer_all_bytes(data); + data->m_upstream.close(); + TSVIO const output_vio = data->m_dnstream.m_write.m_vio; + if (nullptr != output_vio) { + TSVIOReenable(output_vio); + } else { + shutdown(contp, data); + } + return; + } break; + default: + break; + } + + // corner condition, good source header + 0 length aborted content + // results in no header being read, just an EOS. + // trying to delete the upstream will crash ATS (??) + if (0 == data->m_blockexpected) { + shutdown(contp, data); // this will crash if first block + return; + } + + transfer_content_bytes(data); + data->m_upstream.close(); + data->m_blockstate = BlockState::Pending; // check for block truncation if (data->m_blockconsumed < data->m_blockexpected) { DEBUG_LOG("%p handle_server_resp truncation: %" PRId64 "\n", data, data->m_blockexpected - data->m_blockconsumed); - data->m_blockstate = Data::BlockState::Fail; + data->m_blockstate = BlockState::Fail; // shutdown(contp, data); return; } @@ -454,7 +680,7 @@ handle_server_resp(TSCont contp, TSEvent event, Data *const data) } else { data->m_upstream.close(); - data->m_blockstate = Data::BlockState::Done; + data->m_blockstate = BlockState::Done; if (!data->m_dnstream.m_read.isOpen()) { shutdown(contp, data); } diff --git a/plugins/experimental/slice/slice.cc b/plugins/experimental/slice/slice.cc index f53fdd3d248..60542fa7451 100644 --- a/plugins/experimental/slice/slice.cc +++ b/plugins/experimental/slice/slice.cc @@ -33,11 +33,16 @@ #if defined(COLLECT_STATS) namespace stats { -int DataCreate = -1; -int DataDestroy = -1; -int Reader = -1; -int Server = -1; -int Client = -1; +int DataCreate = -1; +int DataDestroy = -1; +int Reader = -1; +int Server = -1; +int Client = -1; +int RequestTime = -1; +int FirstHeaderTime = -1; +int NextHeaderTime = -1; +int ServerTime = -1; +int ClientTime = -1; } // namespace stats #endif // COLLECT_STATS @@ -48,6 +53,10 @@ Config globalConfig; bool read_request(TSHttpTxn txnp, Config *const config) { +#if defined(COLLECT_STATS) + stats::StatsRAI const rai(stats::RequestTime); +#endif + DEBUG_LOG("slice read_request"); TxnHdrMgr hdrmgr; hdrmgr.populateFrom(txnp, TSHttpTxnClientReqGet); @@ -180,7 +189,7 @@ read_request(TSHttpTxn txnp, Config *const config) // we'll intercept this GET and do it ourselves TSMutex const mutex = TSContMutexGet(reinterpret_cast(txnp)); - // TSMutex const mutex = TSMutexCreate(); + // TSMutex const mutex = TSMutexCreate(); TSCont const icontp(TSContCreate(intercept_hook, mutex)); TSContDataSet(icontp, (void *)data); TSHttpTxnIntercept(icontp, txnp); @@ -291,6 +300,31 @@ TSRemapInit(TSRemapInterface *api_info, char *errbug, int errbuf_size) stats::Client = TSStatCreate(nameclient.c_str(), TS_RECORDDATATYPE_INT, TS_STAT_NON_PERSISTENT, TS_STAT_SYNC_SUM); assert(0 <= stats::Client); + + std::string const namerequest = std::string(PLUGIN_NAME) + ".RequestTime"; + stats::RequestTime = TSStatCreate(namerequest.c_str(), TS_RECORDDATATYPE_INT, TS_STAT_NON_PERSISTENT, TS_STAT_SYNC_SUM); + + assert(0 <= stats::RequestTime); + + std::string const namefirst = std::string(PLUGIN_NAME) + ".FirstHeaderTime"; + stats::FirstHeaderTime = TSStatCreate(namefirst.c_str(), TS_RECORDDATATYPE_INT, TS_STAT_NON_PERSISTENT, TS_STAT_SYNC_SUM); + + assert(0 <= stats::FirstHeaderTime); + + std::string const namenext = std::string(PLUGIN_NAME) + ".NextHeaderTime"; + stats::NextHeaderTime = TSStatCreate(namenext.c_str(), TS_RECORDDATATYPE_INT, TS_STAT_NON_PERSISTENT, TS_STAT_SYNC_SUM); + + assert(0 <= stats::NextHeaderTime); + + std::string const nameservertime = std::string(PLUGIN_NAME) + ".ServerTime"; + stats::ServerTime = TSStatCreate(nameservertime.c_str(), TS_RECORDDATATYPE_INT, TS_STAT_NON_PERSISTENT, TS_STAT_SYNC_SUM); + + assert(0 <= stats::ServerTime); + + std::string const nameclienttime = std::string(PLUGIN_NAME) + ".ClientTime"; + stats::ClientTime = TSStatCreate(nameclienttime.c_str(), TS_RECORDDATATYPE_INT, TS_STAT_NON_PERSISTENT, TS_STAT_SYNC_SUM); + + assert(0 <= stats::ClientTime); } #endif // COLLECT_STATS diff --git a/plugins/experimental/slice/slice.h b/plugins/experimental/slice/slice.h index d4e040b32f2..fe3dba239bb 100644 --- a/plugins/experimental/slice/slice.h +++ b/plugins/experimental/slice/slice.h @@ -19,8 +19,10 @@ #pragma once #include "ts/ts.h" +#include "ts/experimental.h" #include +#include #ifndef SLICE_EXPORT #define SLICE_EXPORT extern "C" tsapi @@ -30,11 +32,17 @@ #define PLUGIN_NAME "slice" #endif +#ifndef COLLECT_STATS +#define COLLECT_STATS +#endif + +constexpr std::string_view X_CRR_IMS_HEADER = {"X-Crr-Ims"}; + #if !defined(UNITTEST) #define __FILENAME__ (strrchr(__FILE__, '/') ? strrchr(__FILE__, '/') + 1 : __FILE__) #define DEBUG_LOG(fmt, ...) \ - TSDebug(PLUGIN_NAME, "[%s:%04d] %s(): " fmt, __FILENAME__, __LINE__, __func__, \ + TSDebug(PLUGIN_NAME, "[%s:% 4d] %s(): " fmt, __FILENAME__, __LINE__, __func__, \ ##__VA_ARGS__) /* \ ; fprintf(stderr, "[%s:%04d]: " fmt "\n" \ , __FILENAME__ \ @@ -43,7 +51,7 @@ */ #define ERROR_LOG(fmt, ...) \ - TSError("[%s:%04d] %s(): " fmt, __FILENAME__, __LINE__, __func__, ##__VA_ARGS__); \ + TSError("[%s:% 4d] %s(): " fmt, __FILENAME__, __LINE__, __func__, ##__VA_ARGS__); \ TSDebug(PLUGIN_NAME, "[%s:%04d] %s(): " fmt, __FILENAME__, __LINE__, __func__, ##__VA_ARGS__) #else @@ -61,5 +69,24 @@ extern int DataDestroy; extern int Reader; extern int Server; extern int Client; +extern int RequestTime; +extern int FirstHeaderTime; +extern int NextHeaderTime; +extern int ServerTime; +extern int ClientTime; + +struct StatsRAI { + int m_statid; + TSHRTime m_timebeg; + + StatsRAI(int statid) : m_statid(statid), m_timebeg(TShrtime()) {} + + ~StatsRAI() + { + TSHRTime const timeend = TShrtime(); + TSStatIntIncrement(m_statid, timeend - m_timebeg); + } +}; + } // namespace stats #endif // COLLECT_STATS diff --git a/plugins/experimental/slice/util.cc b/plugins/experimental/slice/util.cc index f3ae7d2bcf1..cc78c2bbc19 100644 --- a/plugins/experimental/slice/util.cc +++ b/plugins/experimental/slice/util.cc @@ -51,9 +51,15 @@ request_block(TSCont contp, Data *const data) return false; } - if (Data::BlockState::Pending != data->m_blockstate) { - ERROR_LOG("request_block called with non Pending state!"); + switch (data->m_blockstate) { + case BlockState::Pending: + case BlockState::PendingInt: + case BlockState::PendingRef: + break; + default: + ERROR_LOG("request_block called with non Pending* state!"); return false; + break; } int64_t const blockbeg = (data->m_config->m_blockbytes * data->m_blocknum); @@ -90,10 +96,10 @@ request_block(TSCont contp, Data *const data) TSHttpHdrPrint(header.m_buffer, header.m_lochdr, data->m_upstream.m_write.m_iobuf); TSVIOReenable(data->m_upstream.m_write.m_vio); - /* - std::string const headerstr(header.toString()); - DEBUG_LOG("Headers\n%s", headerstr.c_str()); - */ + if (TSIsDebugTagSet(PLUGIN_NAME)) { + std::string const headerstr(header.toString()); + DEBUG_LOG("Headers\n%s", headerstr.c_str()); + } // get ready for data back from the server data->m_upstream.setupVioRead(contp, INT64_MAX); @@ -104,9 +110,25 @@ request_block(TSCont contp, Data *const data) data->m_blockexpected = 0; data->m_blockconsumed = 0; - data->m_blockstate = Data::BlockState::Active; data->m_server_block_header_parsed = false; + switch (data->m_blockstate) { + case BlockState::Pending: + data->m_blockstate = BlockState::Active; + break; + case BlockState::PendingInt: + data->m_blockstate = BlockState::ActiveInt; + header.removeKey(X_CRR_IMS_HEADER.data(), X_CRR_IMS_HEADER.size()); + break; + case BlockState::PendingRef: + data->m_blockstate = BlockState::ActiveRef; + header.removeKey(X_CRR_IMS_HEADER.data(), X_CRR_IMS_HEADER.size()); + break; + default: + ERROR_LOG("Invalid blockstate"); + break; + } + return true; } diff --git a/src/traffic_server/InkAPI.cc b/src/traffic_server/InkAPI.cc index 1efa887d9b0..4c96cc24320 100644 --- a/src/traffic_server/InkAPI.cc +++ b/src/traffic_server/InkAPI.cc @@ -3346,6 +3346,16 @@ TSMimeHdrFieldValueDateGet(TSMBuffer bufp, TSMLoc hdr, TSMLoc field) return mime_parse_date(value_str, value_str + value_len); } +time_t +TSMimeParseDate(char const *const value_str, int const value_len) +{ + if (value_str == nullptr) { + return (time_t)0; + } + + return mime_parse_date(value_str, value_str + value_len); +} + int TSMimeHdrFieldValueIntGet(TSMBuffer bufp, TSMLoc hdr, TSMLoc field, int idx) { @@ -3445,6 +3455,21 @@ TSMimeHdrFieldValueDateSet(TSMBuffer bufp, TSMLoc hdr, TSMLoc field, time_t valu return TS_SUCCESS; } +TSReturnCode +TSMimeFormatDate(time_t const value_time, char *const value_str, int *const value_length) +{ + if (value_length == nullptr) { + return TS_ERROR; + } + + if (*value_length < 33) { + return TS_ERROR; + } + + *value_length = mime_format_date(value_str, value_time); + return TS_SUCCESS; +} + TSReturnCode TSMimeHdrFieldValueIntSet(TSMBuffer bufp, TSMLoc hdr, TSMLoc field, int idx, int value) { diff --git a/tests/gold_tests/pluginTest/slice/curlsort.sh b/tests/gold_tests/pluginTest/slice/curlsort.sh deleted file mode 100755 index eabf5618ff2..00000000000 --- a/tests/gold_tests/pluginTest/slice/curlsort.sh +++ /dev/null @@ -1,33 +0,0 @@ -#!/bin/sh - -# 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. - -cmd='curl' -for arg in "$@"; do - case "$arg" in - *\'*) -# arg=`printf '%s' "$arg" | sed s/'/'\"'\"'/g"` - arg=`printf '%s' "$arg"` - ;; - *) : ;; - esac - cmd="$cmd '$arg'" -done - -cmd="$cmd -s -D /dev/stdout -o /dev/stderr" - -eval " $cmd" | sort diff --git a/tests/gold_tests/pluginTest/slice/gold/aa.gold b/tests/gold_tests/pluginTest/slice/gold/aa.gold new file mode 100644 index 00000000000..7ec9a4b774e --- /dev/null +++ b/tests/gold_tests/pluginTest/slice/gold/aa.gold @@ -0,0 +1 @@ +aa \ No newline at end of file diff --git a/tests/gold_tests/pluginTest/slice/gold/aaa.gold b/tests/gold_tests/pluginTest/slice/gold/aaa.gold new file mode 100644 index 00000000000..7c4a013e52c --- /dev/null +++ b/tests/gold_tests/pluginTest/slice/gold/aaa.gold @@ -0,0 +1 @@ +aaa \ No newline at end of file diff --git a/tests/gold_tests/pluginTest/slice/gold/bb.gold b/tests/gold_tests/pluginTest/slice/gold/bb.gold new file mode 100644 index 00000000000..b5b5773c405 --- /dev/null +++ b/tests/gold_tests/pluginTest/slice/gold/bb.gold @@ -0,0 +1 @@ +bb \ No newline at end of file diff --git a/tests/gold_tests/pluginTest/slice/gold/bbb.gold b/tests/gold_tests/pluginTest/slice/gold/bbb.gold new file mode 100644 index 00000000000..01f02e32ce8 --- /dev/null +++ b/tests/gold_tests/pluginTest/slice/gold/bbb.gold @@ -0,0 +1 @@ +bbb \ No newline at end of file diff --git a/tests/gold_tests/pluginTest/slice/gold/slice_200.stderr.gold b/tests/gold_tests/pluginTest/slice/gold/slice_200.stderr.gold index 24ad29c1a82..c2475221112 100644 --- a/tests/gold_tests/pluginTest/slice/gold/slice_200.stderr.gold +++ b/tests/gold_tests/pluginTest/slice/gold/slice_200.stderr.gold @@ -1 +1 @@ -lets go surfin now`` +lets go surfin now \ No newline at end of file diff --git a/tests/gold_tests/pluginTest/slice/gold/slice_200.stdout.gold b/tests/gold_tests/pluginTest/slice/gold/slice_200.stdout.gold deleted file mode 100644 index 50eeb38afb7..00000000000 --- a/tests/gold_tests/pluginTest/slice/gold/slice_200.stdout.gold +++ /dev/null @@ -1,8 +0,0 @@ -`` -Cache-Control: `` -Connection: `` -Content-Length: 18 -Date: `` -Etag: "path" -HTTP/1.1 200 OK -Server: `` diff --git a/tests/gold_tests/pluginTest/slice/gold/slice_206.stderr.gold b/tests/gold_tests/pluginTest/slice/gold/slice_206.stderr.gold index 24ad29c1a82..c2475221112 100644 --- a/tests/gold_tests/pluginTest/slice/gold/slice_206.stderr.gold +++ b/tests/gold_tests/pluginTest/slice/gold/slice_206.stderr.gold @@ -1 +1 @@ -lets go surfin now`` +lets go surfin now \ No newline at end of file diff --git a/tests/gold_tests/pluginTest/slice/gold/slice_206.stdout.gold b/tests/gold_tests/pluginTest/slice/gold/slice_206.stdout.gold deleted file mode 100644 index 0ff73438579..00000000000 --- a/tests/gold_tests/pluginTest/slice/gold/slice_206.stdout.gold +++ /dev/null @@ -1,9 +0,0 @@ -`` -Cache-Control: `` -Connection: `` -Content-Length: 18 -Content-Range: bytes 0-17/18 -Date: `` -Etag: "path" -HTTP/1.1 206 Partial Content -Server: `` diff --git a/tests/gold_tests/pluginTest/slice/gold/slice_first.stderr.gold b/tests/gold_tests/pluginTest/slice/gold/slice_first.stderr.gold index 10893bb0688..956bab9d26b 100644 --- a/tests/gold_tests/pluginTest/slice/gold/slice_first.stderr.gold +++ b/tests/gold_tests/pluginTest/slice/gold/slice_first.stderr.gold @@ -1 +1 @@ -lets go`` +lets go \ No newline at end of file diff --git a/tests/gold_tests/pluginTest/slice/gold/slice_first.stdout.gold b/tests/gold_tests/pluginTest/slice/gold/slice_first.stdout.gold deleted file mode 100644 index c12d4c194da..00000000000 --- a/tests/gold_tests/pluginTest/slice/gold/slice_first.stdout.gold +++ /dev/null @@ -1,9 +0,0 @@ -`` -Cache-Control: max-age=`` -Connection: `` -Content-Length: 7 -Content-Range: bytes 0-6/18 -Date: `` -Etag: `` -HTTP/1.1 206 Partial Content -Server: `` diff --git a/tests/gold_tests/pluginTest/slice/gold/slice_last.stderr.gold b/tests/gold_tests/pluginTest/slice/gold/slice_last.stderr.gold index 30d9d270514..a5f7a5d421b 100644 --- a/tests/gold_tests/pluginTest/slice/gold/slice_last.stderr.gold +++ b/tests/gold_tests/pluginTest/slice/gold/slice_last.stderr.gold @@ -1 +1 @@ - now`` + now \ No newline at end of file diff --git a/tests/gold_tests/pluginTest/slice/gold/slice_last.stdout.gold b/tests/gold_tests/pluginTest/slice/gold/slice_last.stdout.gold deleted file mode 100644 index 8457c952f01..00000000000 --- a/tests/gold_tests/pluginTest/slice/gold/slice_last.stdout.gold +++ /dev/null @@ -1,9 +0,0 @@ -`` -Cache-Control: max-age=`` -Connection: `` -Content-Length: 4 -Content-Range: bytes 14-17/18 -Date: `` -Etag: `` -HTTP/1.1 206 Partial Content -Server: `` diff --git a/tests/gold_tests/pluginTest/slice/gold/slice_mid.stderr.gold b/tests/gold_tests/pluginTest/slice/gold/slice_mid.stderr.gold index ef40e3253f5..9f2bb071ba2 100644 --- a/tests/gold_tests/pluginTest/slice/gold/slice_mid.stderr.gold +++ b/tests/gold_tests/pluginTest/slice/gold/slice_mid.stderr.gold @@ -1 +1 @@ -go surfin no`` +go surfin no \ No newline at end of file diff --git a/tests/gold_tests/pluginTest/slice/gold/slice_mid.stdout.gold b/tests/gold_tests/pluginTest/slice/gold/slice_mid.stdout.gold deleted file mode 100644 index e078833d768..00000000000 --- a/tests/gold_tests/pluginTest/slice/gold/slice_mid.stdout.gold +++ /dev/null @@ -1,9 +0,0 @@ -`` -Cache-Control: max-age=`` -Connection: `` -Content-Length: 12 -Content-Range: bytes 5-16/18 -Date: `` -Etag: `` -HTTP/1.1 206 Partial Content -Server: `` diff --git a/tests/gold_tests/pluginTest/slice/gold_error/contents.stderr.gold b/tests/gold_tests/pluginTest/slice/gold_error/contents.stderr.gold new file mode 100644 index 00000000000..321dd5d09d6 --- /dev/null +++ b/tests/gold_tests/pluginTest/slice/gold_error/contents.stderr.gold @@ -0,0 +1 @@ +the quick \ No newline at end of file diff --git a/tests/gold_tests/pluginTest/slice/gold_error/crr.stderr.gold b/tests/gold_tests/pluginTest/slice/gold_error/crr.stderr.gold deleted file mode 100644 index fad05754105..00000000000 --- a/tests/gold_tests/pluginTest/slice/gold_error/crr.stderr.gold +++ /dev/null @@ -1 +0,0 @@ -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 deleted file mode 100644 index 7109c04a13f..00000000000 --- a/tests/gold_tests/pluginTest/slice/gold_error/crr.stdout.gold +++ /dev/null @@ -1,9 +0,0 @@ -`` -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 deleted file mode 100644 index fad05754105..00000000000 --- a/tests/gold_tests/pluginTest/slice/gold_error/etag.stderr.gold +++ /dev/null @@ -1 +0,0 @@ -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 deleted file mode 100644 index 7109c04a13f..00000000000 --- a/tests/gold_tests/pluginTest/slice/gold_error/etag.stdout.gold +++ /dev/null @@ -1,9 +0,0 @@ -`` -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 deleted file mode 100644 index fad05754105..00000000000 --- a/tests/gold_tests/pluginTest/slice/gold_error/lm.stderr.gold +++ /dev/null @@ -1 +0,0 @@ -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 deleted file mode 100644 index 20bd1a54127..00000000000 --- a/tests/gold_tests/pluginTest/slice/gold_error/lm.stdout.gold +++ /dev/null @@ -1,9 +0,0 @@ -`` -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 deleted file mode 100644 index fad05754105..00000000000 --- a/tests/gold_tests/pluginTest/slice/gold_error/non206.stderr.gold +++ /dev/null @@ -1 +0,0 @@ -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 deleted file mode 100644 index f381661d6a6..00000000000 --- a/tests/gold_tests/pluginTest/slice/gold_error/non206.stdout.gold +++ /dev/null @@ -1,10 +0,0 @@ -`` -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.test.py b/tests/gold_tests/pluginTest/slice/slice.test.py index 81e1f563f5b..fa4c2031bd8 100644 --- a/tests/gold_tests/pluginTest/slice/slice.test.py +++ b/tests/gold_tests/pluginTest/slice/slice.test.py @@ -34,12 +34,12 @@ server = Test.MakeOriginServer("server") # Define ATS and configure -ts = Test.MakeATSProcess("ts", command="traffic_manager", select_ports=True) +ts = Test.MakeATSProcess("ts", command="traffic_server") # default root request_header_chk = {"headers": "GET / HTTP/1.1\r\n" + - "Host: www.example.com\r\n" + + "Host: ats\r\n" + "\r\n", "timestamp": "1469733493.993", "body": "", @@ -55,12 +55,12 @@ server.addResponse("sessionlog.json", request_header_chk, response_header_chk) -#block_bytes = 7 +block_bytes = 7 body = "lets go surfin now" request_header = {"headers": "GET /path HTTP/1.1\r\n" + - "Host: www.example.com\r\n" + + "Host: origin\r\n" + "\r\n", "timestamp": "1469733493.993", "body": "", @@ -78,106 +78,99 @@ server.addResponse("sessionlog.json", request_header, response_header) -ts.Setup.CopyAs('curlsort.sh', Test.RunDirectory) -curl_and_args = 'sh curlsort.sh -H "Host: www.example.com"' +curl_and_args = 'curl -s -D /dev/stdout -o /dev/stderr -x http://127.0.0.1:{}'.format(ts.Variables.port) # set up whole asset fetch into cache -ts.Disk.remap_config.AddLine( - 'map / http://127.0.0.1:{}'.format(server.Variables.Port) -) +ts.Disk.remap_config.AddLines([ + 'map http://preload/ http://127.0.0.1:{}'.format(server.Variables.Port), + 'map http://slice/ http://127.0.0.1:{}'.format(server.Variables.Port) + + ' @plugin=slice.so @pparam=--blockbytes-test={}'.format(block_bytes) +]) # minimal configuration ts.Disk.records_config.update({ - 'proxy.config.diags.debug.enabled': 1, - 'proxy.config.diags.debug.tags': 'slice', +# 'proxy.config.diags.debug.enabled': 1, +# 'proxy.config.diags.debug.tags': 'slice', 'proxy.config.http.cache.http': 1, 'proxy.config.http.wait_for_cache': 1, - 'proxy.config.http.insert_age_in_response': 0, - 'proxy.config.http.response_via_str': 3, }) # 0 Test - Prefetch entire asset into cache tr = Test.AddTestRun("Fetch first slice range") -tr.Processes.Default.StartBefore(server) -tr.Processes.Default.StartBefore(Test.Processes.ts) -tr.Processes.Default.Command = curl_and_args + ' http://127.0.0.1:{}/path'.format(ts.Variables.port) -tr.Processes.Default.ReturnCode = 0 -tr.Processes.Default.Streams.stdout = "gold/slice_200.stdout.gold" -tr.Processes.Default.Streams.stderr = "gold/slice_200.stderr.gold" +ps = tr.Processes.Default +ps.StartBefore(server, ready=When.PortOpen(server.Variables.Port)) +ps.StartBefore(Test.Processes.ts, ready=When.PortOpen(ts.Variables.port)) +ps.Command = curl_and_args + ' http://preload/path' +ps.ReturnCode = 0 +ps.Streams.stderr = "gold/slice_200.stderr.gold" +ps.Streams.stdout.Content = Testers.ContainsExpression("200 OK", "expected 200 OK response") tr.StillRunningAfter = ts -block_bytes = 7 - -# 1 - Reconfigure remap.config with slice plugin -tr = Test.AddTestRun("Load Slice plugin") -remap_config_path = ts.Disk.remap_config.Name -tr.Disk.File(remap_config_path, typename="ats:config").AddLines([ - 'map / http://127.0.0.1:{}'.format(server.Variables.Port) + - ' @plugin=slice.so @pparam=--blockbytes-test={}'.format(block_bytes) -]) - -tr.StillRunningAfter = ts -tr.StillRunningAfter = server -tr.Processes.Default.Command = 'traffic_ctl config reload' -# Need to copy over the environment so traffic_ctl knows where to find the unix domain socket -tr.Processes.Default.Env = ts.Env -tr.Processes.Default.ReturnCode = 0 -tr.Processes.Default.TimeOut = 5 -tr.TimeOut = 5 - -# 2 Test - First complete slice +# 1 Test - First complete slice tr = Test.AddTestRun("Fetch first slice range") -tr.DelayStart = 5 -tr.Processes.Default.Command = curl_and_args + ' http://127.0.0.1:{}/path'.format(ts.Variables.port) + ' -r 0-6' -tr.Processes.Default.ReturnCode = 0 -tr.Processes.Default.Streams.stdout = "gold/slice_first.stdout.gold" -tr.Processes.Default.Streams.stderr = "gold/slice_first.stderr.gold" +ps = tr.Processes.Default +ps.Command = curl_and_args + ' http://slice/path' + ' -r 0-6' +ps.ReturnCode = 0 +ps.Streams.stderr = "gold/slice_first.stderr.gold" +ps.Streams.stdout.Content = Testers.ContainsExpression("206 Partial Content", "expected 206 response") +ps.Streams.stdout.Content += Testers.ContainsExpression("Content-Range: bytes 0-6/18", "mismatch byte content response") tr.StillRunningAfter = ts -# 3 Test - Last slice auto +# 2 Test - Last slice auto tr = Test.AddTestRun("Last slice -- 14-") -tr.Processes.Default.Command = curl_and_args + ' http://127.0.0.1:{}/path'.format(ts.Variables.port) + ' -r 14-' -tr.Processes.Default.ReturnCode = 0 -tr.Processes.Default.Streams.stdout = "gold/slice_last.stdout.gold" -tr.Processes.Default.Streams.stderr = "gold/slice_last.stderr.gold" +ps = tr.Processes.Default +ps.Command = curl_and_args + ' http://slice/path' + ' -r 14-' +ps.ReturnCode = 0 +ps.Streams.stderr = "gold/slice_last.stderr.gold" +ps.Streams.stdout.Content = Testers.ContainsExpression("206 Partial Content", "expected 206 response") +ps.Streams.stdout.Content += Testers.ContainsExpression("Content-Range: bytes 14-17/18", "mismatch byte content response") tr.StillRunningAfter = ts -# 4 Test - Last slice exact +# 3 Test - Last slice exact tr = Test.AddTestRun("Last slice 14-17") -tr.Processes.Default.Command = curl_and_args + ' http://127.0.0.1:{}/path'.format(ts.Variables.port) + ' -r 14-17' -tr.Processes.Default.ReturnCode = 0 -tr.Processes.Default.Streams.stdout = "gold/slice_last.stdout.gold" -tr.Processes.Default.Streams.stderr = "gold/slice_last.stderr.gold" +ps = tr.Processes.Default +ps.Command = curl_and_args + ' http://slice/path' + ' -r 14-17' +ps.ReturnCode = 0 +ps.Streams.stderr = "gold/slice_last.stderr.gold" +ps.Streams.stdout.Content = Testers.ContainsExpression("206 Partial Content", "expected 206 response") +ps.Streams.stdout.Content += Testers.ContainsExpression("Content-Range: bytes 14-17/18", "mismatch byte content response") tr.StillRunningAfter = ts -# 5 Test - Last slice truncated +# 4 Test - Last slice truncated tr = Test.AddTestRun("Last truncated slice 14-20") -tr.Processes.Default.Command = curl_and_args + ' http://127.0.0.1:{}/path'.format(ts.Variables.port) + ' -r 14-20' -tr.Processes.Default.ReturnCode = 0 -tr.Processes.Default.Streams.stdout = "gold/slice_last.stdout.gold" -tr.Processes.Default.Streams.stderr = "gold/slice_last.stderr.gold" +ps = tr.Processes.Default +ps.Command = curl_and_args + ' http://slice/path' + ' -r 14-20' +ps.ReturnCode = 0 +ps.Streams.stderr = "gold/slice_last.stderr.gold" +ps.Streams.stdout.Content = Testers.ContainsExpression("206 Partial Content", "expected 206 response") +ps.Streams.stdout.Content += Testers.ContainsExpression("Content-Range: bytes 14-17/18", "mismatch byte content response") tr.StillRunningAfter = ts -# 6 Test - Whole asset via slices +# 5 Test - Whole asset via slices tr = Test.AddTestRun("Whole asset via slices") -tr.Processes.Default.Command = curl_and_args + ' http://127.0.0.1:{}/path'.format(ts.Variables.port) -tr.Processes.Default.ReturnCode = 0 -tr.Processes.Default.Streams.stdout = "gold/slice_200.stdout.gold" -tr.Processes.Default.Streams.stderr = "gold/slice_200.stderr.gold" +ps = tr.Processes.Default +ps.Command = curl_and_args + ' http://slice/path' +ps.ReturnCode = 0 +ps.Streams.stderr = "gold/slice_200.stderr.gold" +ps.Streams.stdout.Content = Testers.ContainsExpression("200 OK", "expected 200 OK response") tr.StillRunningAfter = ts -# 7 Test - Whole asset via range +# 6 Test - Whole asset via range tr = Test.AddTestRun("Whole asset via range") -tr.Processes.Default.Command = curl_and_args + ' http://127.0.0.1:{}/path'.format(ts.Variables.port) + ' -r 0-' -tr.Processes.Default.ReturnCode = 0 -tr.Processes.Default.Streams.stdout = "gold/slice_206.stdout.gold" -tr.Processes.Default.Streams.stderr = "gold/slice_206.stderr.gold" +ps = tr.Processes.Default +ps.Command = curl_and_args + ' http://slice/path' + ' -r 0-' +ps.ReturnCode = 0 +ps.Streams.stderr = "gold/slice_206.stderr.gold" +ps.Streams.stdout.Content = Testers.ContainsExpression("206 Partial Content", "expected 206 response") +ps.Streams.stdout.Content += Testers.ContainsExpression("Content-Range: bytes 0-17/18", "mismatch byte content response") tr.StillRunningAfter = ts -# 8 Test - Non aligned slice request +# 7 Test - Non aligned slice request tr = Test.AddTestRun("Non aligned slice request") -tr.Processes.Default.Command = curl_and_args + ' http://127.0.0.1:{}/path'.format(ts.Variables.port) + ' -r 5-16' -tr.Processes.Default.ReturnCode = 0 -tr.Processes.Default.Streams.stdout = "gold/slice_mid.stdout.gold" -tr.Processes.Default.Streams.stderr = "gold/slice_mid.stderr.gold" +ps = tr.Processes.Default +ps.Command = curl_and_args + ' http://slice/path' + ' -r 5-16' +ps.ReturnCode = 0 +ps.Streams.stderr = "gold/slice_mid.stderr.gold" +ps.Streams.stdout.Content = Testers.ContainsExpression("206 Partial Content", "expected 206 response") +ps.Streams.stdout.Content += Testers.ContainsExpression("Content-Range: bytes 5-16/18", "mismatch byte content response") tr.StillRunningAfter = ts diff --git a/tests/gold_tests/pluginTest/slice/slice_error.test.py b/tests/gold_tests/pluginTest/slice/slice_error.test.py index 0ae06f1f23c..8b0f841fa57 100644 --- a/tests/gold_tests/pluginTest/slice/slice_error.test.py +++ b/tests/gold_tests/pluginTest/slice/slice_error.test.py @@ -34,14 +34,14 @@ server = Test.MakeOriginServer("server", lookup_key="{%Range}{PATH}") # Define ATS and configure -ts = Test.MakeATSProcess("ts", command="traffic_manager", select_ports=True) +ts = Test.MakeATSProcess("ts", command="traffic_server") 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" + + "Host: ats\r\n" + "Range: bytes=0-\r\n" + "\r\n", "timestamp": "1469733493.993", @@ -70,7 +70,7 @@ request_header_etag0 = {"headers": "GET /etag HTTP/1.1\r\n" + - "Host: www.example.com\r\n" + + "Host: ats\r\n" + "Range: bytes={}\r\n".format(range0) + "X-Slicer-Info: full content request\r\n" + "\r\n", @@ -93,7 +93,7 @@ request_header_etag1 = {"headers": "GET /etag HTTP/1.1\r\n" + - "Host: www.example.com\r\n" + + "Host: ats\r\n" + "Range: bytes={}\r\n".format(range1) + "X-Slicer-Info: full content request\r\n" + "\r\n", @@ -118,7 +118,7 @@ request_header_lm0 = {"headers": "GET /lastmodified HTTP/1.1\r\n" + - "Host: www.example.com\r\n" + + "Host: ats\r\n" + "Range: bytes={}\r\n".format(range0) + "X-Slicer-Info: full content request\r\n" + "\r\n", @@ -141,7 +141,7 @@ request_header_lm1 = {"headers": "GET /lastmodified HTTP/1.1\r\n" + - "Host: www.example.com\r\n" + + "Host: ats\r\n" + "Range: bytes={}\r\n".format(range1) + "X-Slicer-Info: full content request\r\n" + "\r\n", @@ -166,7 +166,7 @@ request_header_n206_0 = {"headers": "GET /non206 HTTP/1.1\r\n" + - "Host: www.example.com\r\n" + + "Host: ats\r\n" + "Range: bytes={}\r\n".format(range0) + "X-Slicer-Info: full content request\r\n" + "\r\n", @@ -188,11 +188,31 @@ server.addResponse("sessionlog.json", request_header_n206_0, response_header_n206_0) +request_header_n206_1 = {"headers": + "GET /non206 HTTP/1.1\r\n" + + "Host: ats\r\n" + + "Range: bytes={}\r\n".format(range1) + + "X-Slicer-Info: full content request\r\n" + + "\r\n", + "timestamp": "1469733493.993", + "body": "", +} + +response_header_n206_1 = {"headers": + "HTTP/1.1 502 Bad Gateway\r\n" + + "Connection: close\r\n" + + "\r\n", + "timestamp": "1469733493.993", + "body": body1, +} + +server.addResponse("sessionlog.json", request_header_n206_1, response_header_n206_1) + # mismatch content-range request_header_crr0 = {"headers": "GET /crr HTTP/1.1\r\n" + - "Host: www.example.com\r\n" + + "Host: ats\r\n" + "Range: bytes={}\r\n".format(range0) + "X-Slicer-Info: full content request\r\n" + "\r\n", @@ -215,7 +235,7 @@ request_header_crr1 = {"headers": "GET /crr HTTP/1.1\r\n" + - "Host: www.example.com\r\n" + + "Host: ats\r\n" + "Range: bytes={}\r\n".format(range1) + "X-Slicer-Info: full content request\r\n" + "\r\n", @@ -236,8 +256,33 @@ 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"' +# 404 internal block + +request_header_internal404_0 = {"headers": + "GET /internal404 HTTP/1.1\r\n" + + "Host: ats\r\n" + + "Range: bytes={}\r\n".format(range0) + + "X-Slicer-Info: full content request\r\n" + + "\r\n", + "timestamp": "1469733493.993", + "body": "", +} + +response_header_internal404_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_internal404_0, response_header_internal404_0) + +curl_and_args = 'curl -s -D /dev/stdout -o /dev/stderr -x http://127.0.0.1:{}'.format(ts.Variables.port) # set up whole asset fetch into cache ts.Disk.remap_config.AddLine( @@ -247,76 +292,81 @@ # minimal configuration ts.Disk.records_config.update({ - 'proxy.config.diags.debug.enabled': 0, - 'proxy.config.diags.debug.tags': 'slice', +# '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, }) # 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") +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="Mismatch/Bad block Content-Range', "Mismatch/Bad block Content-Range") +ts.Disk.diags_log.Content += Testers.ContainsExpression('reason="404 internal block response', "404 internal block response") # 0 Test - Etag mismatch test tr = Test.AddTestRun("Etag test") -tr.Processes.Default.StartBefore(server) -tr.Processes.Default.StartBefore(Test.Processes.ts) -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" +ps = tr.Processes.Default +ps.StartBefore(server, ready=When.PortOpen(server.Variables.Port)) +ps.StartBefore(Test.Processes.ts, ready=When.PortOpen(ts.Variables.port)) +ps.Command = curl_and_args + ' http://ats/etag' +#ps.ReturnCode = 0 # curl will return fail status +ps.Streams.stdout.Content = Testers.ContainsExpression("200 OK", "expected 200 OK response") +ps.Streams.stderr = "gold_error/contents.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 +ps = tr.Processes.Default +ps.Command = "grep 'Mismatch block Etag' {}".format(ts.Disk.diags_log.Name) +ps.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" +ps = tr.Processes.Default +ps.Command = curl_and_args + ' http://ats/lastmodified' +#ps.ReturnCode = 0 # curl will return fail status +ps.Streams.stderr = "gold_error/contents.stderr.gold" +ps.Streams.stdout.Content = Testers.ContainsExpression("200 OK", "expected 200 OK response") 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 +ps = tr.Processes.Default +ps.Command = "grep 'Mismatch block Last-Modified' {}".format(ts.Disk.diags_log.Name) +ps.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" +# 4 Test - Block content-range +tr = Test.AddTestRun("Content-Range test") +ps = tr.Processes.Default +ps.Command = curl_and_args + ' http://ats/crr' +#ps.ReturnCode = 0 # curl will return fail status +ps.Streams.stderr = "gold_error/contents.stderr.gold" +ps.Streams.stdout.Content = Testers.ContainsExpression("200 OK", "expected 200 OK response") 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 +# 5 Check - diags.log message +tr = Test.AddTestRun("Content-Range error check") +ps = tr.Processes.Default +ps.Command = "grep 'Mismatch/Bad block Content-Range' {}".format(ts.Disk.diags_log.Name) +ps.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" +# 6 Test - 404 internal test +tr = Test.AddTestRun("Internal 404 test") +ps = tr.Processes.Default +ps.Command = curl_and_args + ' http://ats/internal404' +#ps.ReturnCode = 0 # curl will return fail status +ps.Streams.stderr = "gold_error/contents.stderr.gold" +ps.Streams.stdout.Content = Testers.ContainsExpression("200 OK", "expected 200 OK response") 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 +# 7 Check - diags.log message +tr = Test.AddTestRun("Internal 404 check") +ps = tr.Processes.Default +ps.Command = "grep '404 internal block response' {}".format(ts.Disk.diags_log.Name) +ps.ReturnCode = 0 tr.StillRunningAfter = ts diff --git a/tests/gold_tests/pluginTest/slice/slice_regex.test.py b/tests/gold_tests/pluginTest/slice/slice_regex.test.py index f1a14b52952..6ca86a8196f 100644 --- a/tests/gold_tests/pluginTest/slice/slice_regex.test.py +++ b/tests/gold_tests/pluginTest/slice/slice_regex.test.py @@ -34,7 +34,7 @@ server = Test.MakeOriginServer("server") # Define ATS and configure -ts = Test.MakeATSProcess("ts", command="traffic_manager", select_ports=True) +ts = Test.MakeATSProcess("ts", command="traffic_server") # default root request_header_chk = {"headers": @@ -124,8 +124,8 @@ # minimal configuration ts.Disk.records_config.update({ - 'proxy.config.diags.debug.enabled': 1, - 'proxy.config.diags.debug.tags': 'slice', +# '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, diff --git a/tests/gold_tests/pluginTest/slice/slice_selfhealing.test.py b/tests/gold_tests/pluginTest/slice/slice_selfhealing.test.py new file mode 100644 index 00000000000..c4583ef28f9 --- /dev/null +++ b/tests/gold_tests/pluginTest/slice/slice_selfhealing.test.py @@ -0,0 +1,391 @@ +''' +''' +# 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. + +Test.Summary = ''' +Slice selfhealing 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.PluginExists('slice.so'), + Condition.PluginExists('cache_range_requests.so'), + Condition.PluginExists('xdebug.so'), +) +Test.ContinueOnFail = False + +# configure origin server +server = Test.MakeOriginServer("server", lookup_key="{%uuid}") + +# Define ATS and configure +ts = Test.MakeATSProcess("ts", command="traffic_server") + +# default root +req_header_chk = {"headers": + "GET / HTTP/1.1\r\n" + + "Host: www.example.com\r\n" + + "uuid: none\r\n" + + "\r\n", + "timestamp": "1469733493.993", + "body": "", +} + +res_header_chk = {"headers": + "HTTP/1.1 200 OK\r\n" + + "Connection: close\r\n" + + "\r\n", + "timestamp": "1469733493.993", + "body": "", +} + +server.addResponse("sessionlog.json", req_header_chk, res_header_chk) + +# set up slice plugin with remap host into cache_range_requests +ts.Disk.remap_config.AddLines([ + 'map http://slice/ http://127.0.0.1:{}/'.format(server.Variables.Port) + + ' @plugin=slice.so @pparam=--blockbytes-test=3 @pparam=--remap-host=cache_range_requests', + 'map http://cache_range_requests/ http://127.0.0.1:{}/'.format(server.Variables.Port) + + ' @plugin=cache_range_requests.so @pparam=--consider-ims', +]) + +ts.Disk.plugin_config.AddLine('xdebug.so') + +# minimal configuration +ts.Disk.records_config.update({ + 'proxy.config.http.cache.http': 1, + 'proxy.config.http.wait_for_cache': 1, +# 'proxy.config.diags.debug.enabled': 1, +# 'proxy.config.diags.debug.tags': 'cache_range_requests|slice', +}) + +curl_and_args = 'curl -s -D /dev/stdout -o /dev/stderr -x localhost:{}'.format(ts.Variables.port) + ' -H "x-debug: x-cache"' + +# Test case: 2nd slice out of date (refetch and continue) + +req_header_2ndold1 = {"headers": + "GET /second HTTP/1.1\r\n" + + "Host: www.example.com\r\n" + + "uuid: etagold-1\r\n" + + "Range: bytes=3-5\r\n" + "\r\n", + "timestamp": "1469733493.993", + "body": "", +} + +res_header_2ndold1 = {"headers": + "HTTP/1.1 206 Partial Content\r\n" + + "Accept-Ranges: bytes\r\n" + + "Cache-Control: max-age=5000\r\n" + + "Connection: close\r\n" + + "Content-Range: bytes 3-4/5\r\n" + + 'Etag: "etagold"\r\n' + + "\r\n", + "timestamp": "1469733493.993", + "body": "aa" +} + +server.addResponse("sessionlog.json", req_header_2ndold1, res_header_2ndold1) + +req_header_2ndnew0 = {"headers": + "GET /second HTTP/1.1\r\n" + + "Host: www.example.com\r\n" + + "uuid: etagnew-0\r\n" + + "Range: bytes=0-2\r\n" + "\r\n", + "timestamp": "1469733493.993", + "body": "", +} + +res_header_2ndnew0 = {"headers": + "HTTP/1.1 206 Partial Content\r\n" + + "Accept-Ranges: bytes\r\n" + + "Cache-Control: max-age=5000\r\n" + + "Connection: close\r\n" + + "Content-Range: bytes 0-2/5\r\n" + + 'Etag: "etagnew"\r\n' + + "\r\n", + "timestamp": "1469733493.993", + "body": "bbb" +} + +server.addResponse("sessionlog.json", req_header_2ndnew0, res_header_2ndnew0) + +req_header_2ndnew1 = {"headers": + "GET /second HTTP/1.1\r\n" + + "Host: www.example.com\r\n" + + "uuid: etagnew-1\r\n" + + "Range: bytes=3-5\r\n" + "\r\n", + "timestamp": "1469733493.993", + "body": "", +} + +res_header_2ndnew1 = {"headers": + "HTTP/1.1 206 Partial Content\r\n" + + "Accept-Ranges: bytes\r\n" + + "Cache-Control: max-age=5000\r\n" + + "Connection: close\r\n" + + "Content-Range: bytes 3-4/5\r\n" + + 'Etag: "etagnew"\r\n' + + "\r\n", + "timestamp": "1469733493.993", + "body": "bb" +} + +server.addResponse("sessionlog.json", req_header_2ndnew1, res_header_2ndnew1) + +# 0 Test - Preload reference etagnew-0 +tr = Test.AddTestRun("Preload reference etagnew-0") +ps = tr.Processes.Default +ps.StartBefore(server, ready=When.PortOpen(server.Variables.Port)) +ps.StartBefore(Test.Processes.ts, ready=When.PortOpen(ts.Variables.port)) +ps.Command = curl_and_args + ' http://cache_range_requests/second -r 0-2 -H "uuid: etagnew-0"' +ps.ReturnCode = 0 +ps.Streams.stderr = "gold/bbb.gold" +ps.Streams.stdout.Content = Testers.ContainsExpression("etagnew", "expected etagnew") +tr.StillRunningAfter = ts + +# 1 Test - Preload reference etagold-1 +tr = Test.AddTestRun("Preload slice etagold-1") +ps = tr.Processes.Default +ps.Command = curl_and_args + ' http://cache_range_requests/second -r 3-5 -H "uuid: etagold-1"' +ps.ReturnCode = 0 +ps.Streams.stderr = "gold/aa.gold" +ps.Streams.stdout.Content = Testers.ContainsExpression("etagold", "expected etagold") +tr.StillRunningAfter = ts + +# 2 Test - Request second slice via slice plugin, with instructions to fetch new 2nd slice +tr = Test.AddTestRun("Request 2nd slice (expect refetch)") +ps = tr.Processes.Default +ps.Command = curl_and_args + ' http://slice/second -r 3- -H "uuid: etagnew-1"' +ps.ReturnCode = 0 +ps.Streams.stderr = "gold/bb.gold" +ps.Streams.stdout.Content = Testers.ContainsExpression("etagnew", "expected etagnew") +tr.StillRunningAfter = ts + +# 3 Test - Request fullly healed asset via slice plugin +tr = Test.AddTestRun("Request full healed slice") +ps = tr.Processes.Default +ps.Command = curl_and_args + ' http://slice/second' +ps.ReturnCode = 0 +ps.Streams.stderr.Content = Testers.ContainsExpression("bbbbb", "expected bbbbb content") +ps.Streams.stdout.Content = Testers.ContainsExpression("etagnew", "expected etagnew") +tr.StillRunningAfter = ts + +# Test case: reference slice out of date (abort connection, heal reference) + +req_header_refold0 = {"headers": + "GET /reference HTTP/1.1\r\n" + + "Host: www.example.com\r\n" + + "uuid: etagold-0\r\n" + + "Range: bytes=0-2\r\n" + "\r\n", + "timestamp": "1469733493.993", + "body": "", +} + +res_header_refold0 = {"headers": + "HTTP/1.1 206 Partial Content\r\n" + + "Accept-Ranges: bytes\r\n" + + "Cache-Control: max-age=5000\r\n" + + "Connection: close\r\n" + + "Content-Range: bytes 0-2/5\r\n" + + 'Etag: "etagold"\r\n' + + "\r\n", + "timestamp": "1469733493.993", + "body": "aaa" +} + +server.addResponse("sessionlog.json", req_header_refold0, res_header_refold0) + +req_header_refnew0 = {"headers": + "GET /reference HTTP/1.1\r\n" + + "Host: www.example.com\r\n" + + "uuid: etagnew-0\r\n" + + "Range: bytes=0-2\r\n" + "\r\n", + "timestamp": "1469733493.993", + "body": "", +} + +res_header_refnew0 = {"headers": + "HTTP/1.1 206 Partial Content\r\n" + + "Accept-Ranges: bytes\r\n" + + "Cache-Control: max-age=5000\r\n" + + "Connection: close\r\n" + + "Content-Range: bytes 0-2/5\r\n" + + 'Etag: "etagnew"\r\n' + + "\r\n", + "timestamp": "1469733493.993", + "body": "bbb" +} + +server.addResponse("sessionlog.json", req_header_refnew0, res_header_refnew0) + +req_header_refnew1 = {"headers": + "GET /reference HTTP/1.1\r\n" + + "Host: www.example.com\r\n" + + "uuid: etagnew-1\r\n" + + "Range: bytes=3-5\r\n" + "\r\n", + "timestamp": "1469733493.993", + "body": "", +} + +res_header_refnew1 = {"headers": + "HTTP/1.1 206 Partial Content\r\n" + + "Accept-Ranges: bytes\r\n" + + "Cache-Control: max-age=5000\r\n" + + "Connection: close\r\n" + + "Content-Range: bytes 3-4/5\r\n" + + 'Etag: "etagnew"\r\n' + + "\r\n", + "timestamp": "1469733493.993", + "body": "bb" +} + +server.addResponse("sessionlog.json", req_header_refnew1, res_header_refnew1) + +# 4 Test - Preload reference etagold-0 +tr = Test.AddTestRun("Preload reference etagold-0") +ps = tr.Processes.Default +ps.Command = curl_and_args + ' http://cache_range_requests/reference -r 0-2 -H "uuid: etagold-0"' +ps.ReturnCode = 0 +ps.Streams.stderr = "gold/aaa.gold" +ps.Streams.stdout.Content = Testers.ContainsExpression("etagold", "expected etagold") +tr.StillRunningAfter = ts + +# 5 Test - Preload reference etagnew-1 +tr = Test.AddTestRun("Preload slice etagnew-1") +ps = tr.Processes.Default +ps.Command = curl_and_args + ' http://cache_range_requests/reference -r 3-5 -H "uuid: etagnew-1"' +ps.ReturnCode = 0 +ps.Streams.stderr = "gold/bb.gold" +ps.Streams.stdout.Content = Testers.ContainsExpression("etagnew", "expected etagnew") +tr.StillRunningAfter = ts + +# 6 Test - Request reference slice via slice plugin, with instructions to fetch new 2nd slice -- this will send the old header, but abort and refetch it +tr = Test.AddTestRun("Request 2nd slice (expect abort)") +ps = tr.Processes.Default +ps.Command = curl_and_args + ' http://slice/reference -r 3- -H "uuid: etagnew-0" -w "SENT: \'%{size_download}\'"' +# ps.ReturnCode = 0 # curl will fail here +ps.Streams.stdout.Content = Testers.ContainsExpression("etagold", "expected etagold") +ps.Streams.stdout.Content += Testers.ContainsExpression("SENT: '0'", "expected empty payload") +tr.StillRunningAfter = ts + +# 7 Test - Request full healed asset via slice plugin +tr = Test.AddTestRun("Request full healed slice") +ps = tr.Processes.Default +ps.Command = curl_and_args + ' http://slice/reference' +ps.ReturnCode = 0 +ps.Streams.stderr.Content = Testers.ContainsExpression("bbbbb", "expected bbbbb content") +ps.Streams.stdout.Content = Testers.ContainsExpression("etagnew", "expected etagnew") +tr.StillRunningAfter = ts + +# Request results in 200, not 206 (server not support range requests) + +req_header_200 = {"headers": + "GET /code200 HTTP/1.1\r\n" + + "Host: www.example.com\r\n" + + "uuid: code200\r\n" + + "Range: bytes=3-5\r\n" + "\r\n", + "timestamp": "1469733493.993", + "body": "", +} + +res_header_200 = {"headers": + "HTTP/1.1 200 OK\r\n" + + "Cache-Control: max-age=5000\r\n" + + "Connection: close\r\n" + + 'Etag: "etag"\r\n' + + "\r\n", + "timestamp": "1469733493.993", + "body": "ccccc" +} + +server.addResponse("sessionlog.json", req_header_200, res_header_200) + +# 8 test - Request through slice but get a 200 back +tr = Test.AddTestRun("Request gets a 200") +ps = tr.Processes.Default +ps.Command = curl_and_args + ' http://slice/code200 -r 3-5 -H "uuid: code200"' +ps.ReturnCode = 0 +ps.Streams.stderr.Content = Testers.ContainsExpression("ccccc", "expected full ccccc content") +ps.Streams.stdout.Content = Testers.ContainsExpression("200 OK", "expected 200") +tr.StillRunningAfter = ts + +# Test for asset gone + +# Preload +req_header_assetgone0 = {"headers": + "GET /assetgone HTTP/1.1\r\n" + + "Host: www.example.com\r\n" + + "uuid: assetgone-0\r\n" + + "Range: bytes=0-2\r\n" + "\r\n", + "timestamp": "1469733493.993", + "body": "", +} + +res_header_assetgone0 = {"headers": + "HTTP/1.1 206 Partial Content\r\n" + + "Accept-Ranges: bytes\r\n" + + "Cache-Control: max-age=5000\r\n" + + "Connection: close\r\n" + + "Content-Range: bytes 0-2/5\r\n" + + 'Etag: "etag"\r\n' + + "\r\n", + "timestamp": "1469733493.993", + "body": "aaa" +} + +server.addResponse("sessionlog.json", req_header_assetgone0, res_header_assetgone0) + +# 9 test - Preload reference slice +tr = Test.AddTestRun("Preload reference assetgone-0") +ps = tr.Processes.Default +ps.Command = curl_and_args + ' http://slice/assetgone -r 0-2 -H "uuid: assetgone-0"' +ps.ReturnCode = 0 +ps.Streams.stderr = "gold/aaa.gold" +ps.Streams.stdout.Content = Testers.ContainsExpression("etag", "expected etag") +tr.StillRunningAfter = ts + +# 10 test - Fetch full asset, 2nd slice should trigger 404 response +tr = Test.AddTestRun("Fetch full asset") +ps = tr.Processes.Default +ps.Command = curl_and_args + ' http://slice/assetgone' +#ps.ReturnCode = 0 # curl will return non zero +ps.Streams.stderr = "gold/aaa.gold" +ps.Streams.stdout.Content = Testers.ContainsExpression("etag", "expected etag") +ps.Streams.stdout.Content += Testers.ContainsExpression("Content-Length: 5", "expected header of content-length 5") +tr.StillRunningAfter = ts + +# 11 test - Fetch full asset again, full blown 404 +tr = Test.AddTestRun("Fetch full asset, 404") +ps = tr.Processes.Default +ps.Command = curl_and_args + ' http://slice/assetgone' +#ps.ReturnCode = 0 # curl will return non zero +ps.Streams.stdout.Content = Testers.ContainsExpression("404 Not Found", "Expected 404") +tr.StillRunningAfter = ts + +# Over riding the built in ERROR check since we expect to see logSliceErrors +ts.Disk.diags_log.Content = Testers.ContainsExpression("logSliceError", "logSliceErrors generated")