diff --git a/doc/admin-guide/plugins/slice.en.rst b/doc/admin-guide/plugins/slice.en.rst index 5a22bf1d3ee..f9f26bdf3fe 100644 --- a/doc/admin-guide/plugins/slice.en.rst +++ b/doc/admin-guide/plugins/slice.en.rst @@ -129,8 +129,9 @@ The slice plugin supports the following options:: --prefetch-count= (optional) Default is 0 Prefetches successive 'n' slice block requests in the background - and cached. Especially for large objects, prefetching can improve - cache miss latency. + and caches (with `cache_range_requests` plugin). Prefetching is only + enabled when first block is a cacheable object with miss or hit-stale status. + Especially for large objects, prefetching can improve cache miss latency. -f for short Examples:: diff --git a/plugins/cache_range_requests/cache_range_requests.cc b/plugins/cache_range_requests/cache_range_requests.cc index 7c3b708b869..46539f370ad 100644 --- a/plugins/cache_range_requests/cache_range_requests.cc +++ b/plugins/cache_range_requests/cache_range_requests.cc @@ -48,6 +48,8 @@ using parent_select_mode_t = enum parent_select_mode { }; constexpr std::string_view DefaultImsHeader = {"X-Crr-Ims"}; +constexpr std::string_view SLICE_CRR_HEADER = {"Slice-Crr-Status"}; +constexpr std::string_view SLICE_CRR_VAL = "1"; struct pluginconfig { parent_select_mode_t ps_mode{PS_DEFAULT}; @@ -64,6 +66,8 @@ struct txndata { time_t ims_time{0}; bool verify_cacheability{false}; bool cache_complete_responses{false}; + bool slice_response{false}; + bool slice_request{false}; }; // pluginconfig struct (global plugin only) @@ -296,6 +300,13 @@ range_header_check(TSHttpTxn txnp, pluginconfig *const pc) TSHttpTxnHookAdd(txnp, TS_HTTP_CACHE_LOOKUP_COMPLETE_HOOK, txn_contp); DEBUG_LOG("Also Added TS_HTTP_CACHE_LOOKUP_COMPLETE_HOOK"); } + + // check if slice requests for cache lookup status + TSMLoc const locfield(TSMimeHdrFieldFind(hdr_buf, hdr_loc, SLICE_CRR_HEADER.data(), SLICE_CRR_HEADER.size())); + if (nullptr != locfield) { + TSHandleMLocRelease(hdr_buf, hdr_loc, locfield); + txn_state->slice_request = true; + } } TSHandleMLocRelease(hdr_buf, hdr_loc, range_loc); } else { @@ -370,6 +381,12 @@ handle_client_send_response(TSHttpTxn txnp, txndata *const txn_state) DEBUG_LOG("Restoring response header to TS_HTTP_STATUS_PARTIAL_CONTENT."); TSHttpHdrStatusSet(resp_buf, resp_loc, TS_HTTP_STATUS_PARTIAL_CONTENT); } + + remove_header(resp_buf, resp_loc, SLICE_CRR_HEADER.data(), SLICE_CRR_HEADER.size()); + if (txn_state->slice_response) { + set_header(resp_buf, resp_loc, SLICE_CRR_HEADER.data(), SLICE_CRR_HEADER.size(), SLICE_CRR_VAL.data(), + SLICE_CRR_VAL.size()); + } } else { DEBUG_LOG("Ignoring status code %d; txn_state->origin_status=%d", status, txn_state->origin_status); } @@ -404,6 +421,7 @@ handle_server_read_response(TSHttpTxn txnp, txndata *const txn_state) { TSMBuffer resp_buf = nullptr; TSMLoc resp_loc = TS_NULL_MLOC; + int cache_lookup; if (TS_SUCCESS == TSHttpTxnServerRespGet(txnp, &resp_buf, &resp_loc)) { TSHttpStatus const status = TSHttpHdrStatusGet(resp_buf, resp_loc); @@ -433,6 +451,15 @@ handle_server_read_response(TSHttpTxn txnp, txndata *const txn_state) DEBUG_LOG("Allowing object to be cached."); } } + + // slice requesting cache lookup status and cacheability (only on miss or validation) + if ((txn_state->origin_status == TS_HTTP_STATUS_PARTIAL_CONTENT || txn_state->origin_status == TS_HTTP_STATUS_NOT_MODIFIED) && + txn_state->slice_request && TSHttpTxnIsCacheable(txnp, nullptr, resp_buf) && + TSHttpTxnCacheLookupStatusGet(txnp, &cache_lookup) == TS_SUCCESS && + (cache_lookup == TS_CACHE_LOOKUP_MISS || cache_lookup == TS_CACHE_LOOKUP_HIT_STALE)) { + txn_state->slice_response = true; + } + TSHandleMLocRelease(resp_buf, TS_NULL_MLOC, resp_loc); } } diff --git a/plugins/experimental/slice/Data.h b/plugins/experimental/slice/Data.h index 9cfbb2f7ead..8e654a69bc4 100644 --- a/plugins/experimental/slice/Data.h +++ b/plugins/experimental/slice/Data.h @@ -93,7 +93,7 @@ struct Data { Stage m_upstream; Stage m_dnstream; - std::unordered_map m_fetchstates; + bool m_prefetchable{false}; HdrMgr m_req_hdrmgr; // manager for server request HdrMgr m_resp_hdrmgr; // manager for client response diff --git a/plugins/experimental/slice/HttpHeader.h b/plugins/experimental/slice/HttpHeader.h index 15a1b158ef1..81f1817fb73 100644 --- a/plugins/experimental/slice/HttpHeader.h +++ b/plugins/experimental/slice/HttpHeader.h @@ -36,6 +36,9 @@ #include +constexpr std::string_view SLICE_CRR_HEADER = {"Slice-Crr-Status"}; +constexpr std::string_view SLICE_CRR_VAL = "1"; + /** Designed to be a cheap throwaway struct which allows a consumer to make various calls to manipulate headers. diff --git a/plugins/experimental/slice/prefetch.cc b/plugins/experimental/slice/prefetch.cc index 2325db77f4b..a83d25a6310 100644 --- a/plugins/experimental/slice/prefetch.cc +++ b/plugins/experimental/slice/prefetch.cc @@ -43,13 +43,13 @@ BgBlockFetch::schedule(Data *const data, int blocknum) bool BgBlockFetch::fetch(Data *const data) { - if (_bg_stream.m_read.isOpen()) { + if (m_stream.m_read.isOpen()) { // should never happen since the connection was just initialized ERROR_LOG("Background block request already in flight!"); return false; } - int64_t const blockbeg = (data->m_config->m_blockbytes * _blocknum); + int64_t const blockbeg = (data->m_config->m_blockbytes * m_blocknum); Range blockbe(blockbeg, blockbeg + data->m_config->m_blockbytes); char rangestr[1024]; @@ -69,11 +69,11 @@ BgBlockFetch::fetch(Data *const data) ERROR_LOG("Error trying to set range request header %s", rangestr); return false; } - TSAssert(nullptr == _cont); + TSAssert(nullptr == m_cont); // Setup the continuation - _cont = TSContCreate(handler, TSMutexCreate()); - TSContDataSet(_cont, static_cast(this)); + m_cont = TSContCreate(handler, TSMutexCreate()); + TSContDataSet(m_cont, static_cast(this)); // create virtual connection back into ATS TSHttpConnectOptions options = TSHttpConnectOptionsGet(TS_CONNECT_PLUGIN); @@ -88,16 +88,17 @@ BgBlockFetch::fetch(Data *const data) int const hlen = TSHttpHdrLengthGet(header.m_buffer, header.m_lochdr); // set up connection with the HttpConnect server - _bg_stream.setupConnection(upvc); - _bg_stream.setupVioWrite(_cont, hlen); - TSHttpHdrPrint(header.m_buffer, header.m_lochdr, _bg_stream.m_write.m_iobuf); + m_stream.setupConnection(upvc); + m_stream.setupVioWrite(m_cont, hlen); + TSHttpHdrPrint(header.m_buffer, header.m_lochdr, m_stream.m_write.m_iobuf); if (TSIsDebugTagSet(PLUGIN_NAME)) { std::string const headerstr(header.toString()); DEBUG_LOG("Headers\n%s", headerstr.c_str()); } + // ensure blocks are pulled through to cache + m_stream.setupVioRead(m_cont, INT64_MAX); - data->m_fetchstates[_blocknum] = true; return true; } @@ -113,22 +114,37 @@ BgBlockFetch::handler(TSCont contp, TSEvent event, void * /* edata ATS_UNUSED */ switch (event) { case TS_EVENT_VCONN_WRITE_COMPLETE: - TSVConnShutdown(bg->_bg_stream.m_vc, 0, 1); - bg->_bg_stream.close(); - delete bg; + TSVConnShutdown(bg->m_stream.m_vc, 0, 1); break; - default: - if (event == TS_EVENT_VCONN_INACTIVITY_TIMEOUT) { - DEBUG_LOG("encountered Inactivity Timeout"); - TSVConnAbort(bg->_bg_stream.m_vc, TS_VC_CLOSE_ABORT); - } else { - TSVConnClose(bg->_bg_stream.m_vc); + case TS_EVENT_VCONN_READ_READY: { + TSIOBufferReader const reader = bg->m_stream.m_read.m_reader; + if (nullptr != reader) { + int64_t const avail = TSIOBufferReaderAvail(reader); + TSIOBufferReaderConsume(reader, avail); + TSVIO const rvio = bg->m_stream.m_read.m_vio; + TSVIONDoneSet(rvio, TSVIONDoneGet(rvio) + avail); + TSVIOReenable(rvio); } - bg->_bg_stream.abort(); + } break; + case TS_EVENT_NET_ACCEPT_FAILED: + case TS_EVENT_VCONN_INACTIVITY_TIMEOUT: + case TS_EVENT_VCONN_ACTIVE_TIMEOUT: + case TS_EVENT_ERROR: + bg->m_stream.abort(); + TSContDataSet(contp, nullptr); + delete bg; + TSContDestroy(contp); + break; + case TS_EVENT_VCONN_READ_COMPLETE: + case TS_EVENT_VCONN_EOS: + bg->m_stream.close(); TSContDataSet(contp, nullptr); delete bg; TSContDestroy(contp); break; + default: + DEBUG_LOG("Unhandled bg fetch event:%s (%d)", TSHttpEventNameLookup(event), event); + break; } return 0; } diff --git a/plugins/experimental/slice/prefetch.h b/plugins/experimental/slice/prefetch.h index e04376bacf6..e5d1edfc247 100644 --- a/plugins/experimental/slice/prefetch.h +++ b/plugins/experimental/slice/prefetch.h @@ -35,22 +35,13 @@ struct BgBlockFetch { static bool schedule(Data *const data, int blocknum); - explicit BgBlockFetch(int blocknum) : _blocknum(blocknum) {} + explicit BgBlockFetch(int blocknum) : m_blocknum(blocknum) {} bool fetch(Data *const data); static int handler(TSCont contp, TSEvent event, void * /* edata ATS_UNUSED */); /* This is for the actual background fetch / NetVC */ - Stage _bg_stream; - - int _blocknum; - TSCont _cont = nullptr; - - ~BgBlockFetch() - { - if (nullptr != _cont) { - TSContDestroy(_cont); - _cont = nullptr; - } - } + Stage m_stream; + int m_blocknum; + TSCont m_cont = nullptr; }; \ No newline at end of file diff --git a/plugins/experimental/slice/server.cc b/plugins/experimental/slice/server.cc index ddf0cc9ad2f..a25376bc920 100644 --- a/plugins/experimental/slice/server.cc +++ b/plugins/experimental/slice/server.cc @@ -20,6 +20,7 @@ #include "Config.h" #include "ContentRange.h" +#include "HttpHeader.h" #include "response.h" #include "transfer.h" #include "util.h" @@ -217,6 +218,10 @@ handleFirstServerHeader(Data *const data, TSCont const contp) data->m_bytessent = hbytes; TSVIOReenable(output_vio); + if (data->m_config->m_prefetchcount > 0 && header.hasKey(SLICE_CRR_HEADER.data(), SLICE_CRR_HEADER.size())) { + data->m_prefetchable = true; + } + return HeaderState::Good; } diff --git a/plugins/experimental/slice/util.cc b/plugins/experimental/slice/util.cc index 7e4bc1148ec..f9c74ed1aea 100644 --- a/plugins/experimental/slice/util.cc +++ b/plugins/experimental/slice/util.cc @@ -18,6 +18,7 @@ #include "util.h" #include "prefetch.h" +#include "HttpHeader.h" #include "Config.h" #include "Data.h" @@ -86,6 +87,11 @@ request_block(TSCont contp, Data *const data) return false; } + header.removeKey(SLICE_CRR_HEADER.data(), SLICE_CRR_HEADER.size()); + if (data->m_blocknum == 0 && data->m_config->m_prefetchcount > 0) { + header.setKeyVal(SLICE_CRR_HEADER.data(), SLICE_CRR_HEADER.size(), SLICE_CRR_VAL.data(), SLICE_CRR_VAL.size()); + } + // create virtual connection back into ATS TSHttpConnectOptions options = TSHttpConnectOptionsGet(TS_CONNECT_PLUGIN); options.addr = reinterpret_cast(&data->m_client_ip); @@ -112,16 +118,19 @@ request_block(TSCont contp, Data *const data) } // if prefetch config set, schedule next block requests in background - for (int i = 0; i < data->m_config->m_prefetchcount; i++) { - int nextblocknum = data->m_blocknum + i + 1; - if (data->m_req_range.blockIsInside(data->m_config->m_blockbytes, nextblocknum) && !data->m_fetchstates[nextblocknum]) { - if (BgBlockFetch::schedule(data, nextblocknum)) { - DEBUG_LOG("Background fetch requested"); - } else { - DEBUG_LOG("Background fetch not requested"); + if (data->m_prefetchable && data->m_config->m_prefetchcount > 0) { + int nextblocknum = 2; + if (data->m_blocknum > 1) { + nextblocknum = data->m_blocknum + data->m_config->m_prefetchcount; + } + for (int i = nextblocknum; i <= data->m_blocknum + data->m_config->m_prefetchcount; i++) { + if (data->m_req_range.blockIsInside(data->m_config->m_blockbytes, i)) { + if (BgBlockFetch::schedule(data, i)) { + DEBUG_LOG("Background fetch requested"); + } else { + DEBUG_LOG("Background fetch not requested"); + } } - } else { - break; } } // get ready for data back from the server diff --git a/tests/gold_tests/pluginTest/slice/gold/slice_prefetch.gold b/tests/gold_tests/pluginTest/slice/gold/slice_prefetch.gold new file mode 100644 index 00000000000..1a82ca139a3 --- /dev/null +++ b/tests/gold_tests/pluginTest/slice/gold/slice_prefetch.gold @@ -0,0 +1,27 @@ +bytes 0-6/18 miss +bytes ``/18 miss +bytes ``/18 miss +bytes 14-17/18 hit-fresh +- miss, none +bytes 0-6/18 hit-fresh +bytes 7-13/18 hit-fresh +bytes 14-17/18 hit-fresh +- hit-fresh, none +bytes 0-6/18 hit-stale +bytes ``/18 hit-stale +bytes ``/18 hit-stale +bytes 14-17/18 hit-fresh +- hit-stale, none +bytes 0-4/18 miss +bytes ``/18 `` +bytes ``/18 `` +bytes ``/18 `` +bytes ``/18 `` +bytes 15-17/18 hit-fresh +bytes 0-17/18 miss, none +bytes 0-6/18 hit-fresh +bytes 7-13/18 hit-fresh +bytes 14-17/18 hit-fresh +bytes 5-16/18 hit-fresh, none +bytes 0-6/18 hit-fresh +*/18 hit-fresh, none diff --git a/tests/gold_tests/pluginTest/slice/slice_prefetch.test.py b/tests/gold_tests/pluginTest/slice/slice_prefetch.test.py index 5dc6aed134c..4201d6873ff 100644 --- a/tests/gold_tests/pluginTest/slice/slice_prefetch.test.py +++ b/tests/gold_tests/pluginTest/slice/slice_prefetch.test.py @@ -15,6 +15,7 @@ # WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. # See the License for the specific language governing permissions and # limitations under the License. +import os Test.Summary = ''' slice plugin prefetch feature test @@ -27,6 +28,7 @@ Test.SkipUnless( Condition.PluginExists('slice.so'), Condition.PluginExists('cache_range_requests.so'), + Condition.PluginExists('xdebug.so'), ) Test.ContinueOnFail = False @@ -52,7 +54,7 @@ response_header = {"headers": "HTTP/1.1 200 OK\r\n" + "Connection: close\r\n" + - "Cache-Control: public, max-age=500\r\n" + + "Cache-Control: public, max-age=5\r\n" + "\r\n", "timestamp": "1469733493.993", "body": body, @@ -79,7 +81,7 @@ resp_header = {"headers": "HTTP/1.1 206 Partial Content\r\n" + "Accept-Ranges: bytes\r\n" + - "Cache-Control: public, max-age=500\r\n" + + "Cache-Control: public, max-age=5\r\n" + f"Content-Range: bytes {b0}-{b1}/{bodylen}\r\n" + "Connection: close\r\n" + "\r\n", @@ -88,91 +90,103 @@ } server.addResponse("sessionlog.json", req_header, resp_header) -curl_and_args = 'curl -s -D /dev/stdout -o /dev/stderr -x http://127.0.0.1:{}'.format(ts.Variables.port) +curl_and_args = 'curl -s -D /dev/stdout -o /dev/stderr -x http://127.0.0.1:{} -H "x-debug: x-cache"'.format(ts.Variables.port) ts.Disk.remap_config.AddLines([ - f'map http://sliceprefetch1bytes1/ http://127.0.0.1:{server.Variables.Port}' + - f' @plugin=slice.so @pparam=--blockbytes-test={block_bytes_1} @pparam=--prefetch-count=1' + + f'map http://sliceprefetchbytes1/ http://127.0.0.1:{server.Variables.Port}' + + f' @plugin=slice.so @pparam=--blockbytes-test={block_bytes_1} @pparam=--prefetch-count=1 \\' + ' @plugin=cache_range_requests.so', - f'map http://sliceprefetch2bytes1/ http://127.0.0.1:{server.Variables.Port}' + - f' @plugin=slice.so @pparam=--blockbytes-test={block_bytes_1} @pparam=--prefetch-count=2' + - ' @plugin=cache_range_requests.so', - f'map http://sliceprefetch1bytes2/ http://127.0.0.1:{server.Variables.Port}' + - f' @plugin=slice.so @pparam=--blockbytes-test={block_bytes_2} @pparam=--prefetch-count=1' + - ' @plugin=cache_range_requests.so', - f'map http://sliceprefetch2bytes2/ http://127.0.0.1:{server.Variables.Port}' + - f' @plugin=slice.so @pparam=--blockbytes-test={block_bytes_2} @pparam=--prefetch-count=2' + + f'map http://sliceprefetchbytes2/ http://127.0.0.1:{server.Variables.Port}' + + f' @plugin=slice.so @pparam=--blockbytes-test={block_bytes_2} @pparam=--prefetch-count=3 \\' + ' @plugin=cache_range_requests.so', ]) +ts.Disk.plugin_config.AddLine('xdebug.so') +ts.Disk.logging_yaml.AddLines([ + 'logging:', + ' formats:', + ' - name: cache', + ' format: "%<{Content-Range}psh> %<{X-Cache}psh>"', + ' logs:', + ' - filename: cache', + ' format: cache', + ' mode: ascii', +]) + ts.Disk.records_config.update({ 'proxy.config.diags.debug.enabled': 1, - 'proxy.config.diags.debug.tags': 'slice|cache_range_requests|pvc', + 'proxy.config.diags.debug.tags': 'slice|cache_range_requests|xdebug', }) -# 0 Test - Full object slice with only next block prefetched in background, block bytes= 7 -tr = Test.AddTestRun("Full object slice with only next block prefetched in background, block bytes= 7") +# 0 Test - Full object slice (miss) with only block 14-20 prefetched in background, block bytes= 7 +tr = Test.AddTestRun("Full object slice: first block is miss, only block 14-20 prefetched") ps = tr.Processes.Default ps.StartBefore(server, ready=When.PortOpen(server.Variables.Port)) ps.StartBefore(Test.Processes.ts) -ps.Command = curl_and_args + ' http://sliceprefetch1bytes1/path' +ps.Command = curl_and_args + ' http://sliceprefetchbytes1/path' ps.ReturnCode = 0 ps.Streams.stderr = "gold/slice_200.stderr.gold" ps.Streams.stdout.Content = Testers.ContainsExpression("200 OK", "expected 200 OK response") +ps.Streams.stdout.Content += Testers.ContainsExpression("X-Cache: miss", "expected cache miss") tr.StillRunningAfter = ts -# 1 Test - Full object slice with nest 2 blocks prefetched in background, block bytes= 7 -tr = Test.AddTestRun("Test - Full object slice with nest 2 blocks prefetched in background, block bytes= 7") +# 1 Test - Full object slice (hit-fresh) with no prefetched blocks, block bytes= 7 +tr = Test.AddTestRun("Full object slice: first block is hit-fresh, no blocks prefetched") ps = tr.Processes.Default -ps.Command = curl_and_args + ' http://sliceprefetch2bytes1/path' +ps.Command = 'sleep 1; ' + curl_and_args + ' http://sliceprefetchbytes1/path' ps.ReturnCode = 0 ps.Streams.stderr = "gold/slice_200.stderr.gold" ps.Streams.stdout.Content = Testers.ContainsExpression("200 OK", "expected 200 OK response") +ps.Streams.stdout.Content += Testers.ContainsExpression("X-Cache: hit-fresh", "expected cache fresh") tr.StillRunningAfter = ts -# 2 Test - Full object slice with only next block prefetched in background, block bytes= 5 -tr = Test.AddTestRun("Full object slice with only next block prefetched in background, block bytes= 5") +# 2 Test - Full object slice with only next block prefetched in background, block bytes= 7 +tr = Test.AddTestRun("Full object slice: first block is hit-stale, only block 14-20 prefetched") ps = tr.Processes.Default -ps.Command = curl_and_args + ' http://sliceprefetch1bytes2/path' +ps.Command = 'sleep 5; ' + curl_and_args + ' http://sliceprefetchbytes1/path' ps.ReturnCode = 0 ps.Streams.stderr = "gold/slice_200.stderr.gold" ps.Streams.stdout.Content = Testers.ContainsExpression("200 OK", "expected 200 OK response") +ps.Streams.stdout.Content += Testers.ContainsExpression("X-Cache: hit-stale", "expected cache hit-stale") tr.StillRunningAfter = ts -# 3 Test - Full object slice with nest 2 blocks prefetched in background, block bytes= 5 -tr = Test.AddTestRun("Full object slice with nest 2 blocks prefetched in background, block bytes= 5") +# 3 Test - Full object slice (miss) with only blocks 10-14, 15-19 prefetched in background, block bytes= 5 +tr = Test.AddTestRun("Full object slice: first block is miss, only blocks 10-14, 15-19 prefetched") ps = tr.Processes.Default -ps.Command = curl_and_args + ' http://sliceprefetch2bytes2/path' +ps.Command = curl_and_args + ' http://sliceprefetchbytes2/path' + ' -r 0-' 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 - -# 4 Test - Whole asset via range -tr = Test.AddTestRun("Whole asset via range") -ps = tr.Processes.Default -ps.Command = curl_and_args + ' http://sliceprefetch1bytes1/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") +ps.Streams.stdout.Content += Testers.ContainsExpression("X-Cache: miss", "expected cache miss") tr.StillRunningAfter = ts -# 5 Test - Non aligned slice request +# 4 Test - Non aligned slice request tr = Test.AddTestRun("Non aligned slice request") ps = tr.Processes.Default -ps.Command = curl_and_args + ' http://sliceprefetch1bytes1/path' + ' -r 5-16' +ps.Command = curl_and_args + ' http://sliceprefetchbytes1/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 -# 6 Test - special case, begin inside last slice block but outside asset len +# 5 Test - special case, begin inside last slice block but outside asset len tr = Test.AddTestRun("Invalid end range request, 416") beg = len(body) + 1 end = beg + block_bytes ps = tr.Processes.Default -ps.Command = curl_and_args + f' http://sliceprefetch1bytes1/path -r {beg}-{end}' +ps.Command = curl_and_args + f' http://sliceprefetchbytes1/path -r {beg}-{end}' ps.Streams.stdout.Content = Testers.ContainsExpression("416 Requested Range Not Satisfiable", "expected 416 response") tr.StillRunningAfter = ts + +# 6 Test - All requests (client & slice internal) logs to see background fetches +cache_file = os.path.join(ts.Variables.LOGDIR, 'cache.log') +# Wait for log file to appear, then wait one extra second to make sure TS is done writing it. +test_run = Test.AddTestRun("Checking debug logs for background fetches") +test_run.Processes.Default.Command = ( + os.path.join(Test.Variables.AtsTestToolsDir, 'condwait') + ' 60 1 -f ' + + cache_file +) +ts.Disk.File(cache_file).Content = "gold/slice_prefetch.gold" +test_run.Processes.Default.ReturnCode = 0