From 5123fa361fff3eb194e3556a18cd80f1ec47c155 Mon Sep 17 00:00:00 2001 From: Brian Neradt Date: Thu, 6 Aug 2026 10:38:05 -0500 Subject: [PATCH 01/10] Preserve the cache action while dispatching cache write events (#13487) A transaction that loses the cache write lock and schedules a retry hands HttpSM a reusable captive action owned by HttpCacheSM. When the retry fires, HttpSM::state_cache_open_write() assigns the result of adjust_thread() to pending_action before releasing that delivered action. The callback is normally already on the correct thread, so adjust_thread() returns nullptr, and assigning nullptr to a PendingAction cancels whatever it was holding. The transaction thereby cancels its own captive action, and the cache read that the retry immediately issues comes back on an action already marked cancelled. Debug builds abort on the resulting assertion in HttpCacheSM, which is how this was found in production; release builds instead take the cancelled early return, drop a valid cache callback, and stall the transaction until it times out. This patch clears the delivered action before the thread adjustment rather than after it. Clearing first is safe because the cache action has already called back, and it means a genuine reschedule installs its event as the new pending action instead of canceling a captive action that is still in use. This also adds an autest in which two transactions contend for the cache write lock with read-while-writer disabled, so the loser's write retry delivers a synchronous cache read callback. That test aborts reliably on an unpatched debug build. (cherry picked from commit 6a96d5056debcb5499496fb8ede73fcf901398d0) --- src/proxy/http/HttpSM.cc | 8 +- .../cache/cache-write-retry-callback.test.py | 25 ++++ .../cache-write-retry-callback.replay.yaml | 134 ++++++++++++++++++ 3 files changed, 165 insertions(+), 2 deletions(-) create mode 100644 tests/gold_tests/cache/cache-write-retry-callback.test.py create mode 100644 tests/gold_tests/cache/replay/cache-write-retry-callback.replay.yaml diff --git a/src/proxy/http/HttpSM.cc b/src/proxy/http/HttpSM.cc index bc0a7c95384..49b351d29ab 100644 --- a/src/proxy/http/HttpSM.cc +++ b/src/proxy/http/HttpSM.cc @@ -2535,6 +2535,12 @@ HttpSM::state_cache_open_write(int event, void *data) { STATE_ENTER(state_cache_open_write, event); + // The cache action has already delivered this callback, so drop it before any + // thread adjustment below can assign over it. Assigning to pending_action + // cancels whatever it holds, and canceling the cache SM's reusable captive + // action here would break every cache operation this transaction makes later. + pending_action.clear_if_action_is(reinterpret_cast(data)); + // Make sure we are on the "right" thread if (_ua.get_txn()) { pending_action = _ua.get_txn()->adjust_thread(this, event, data); @@ -2546,8 +2552,6 @@ HttpSM::state_cache_open_write(int event, void *data) ink_release_assert(vc && vc->thread == this_ethread()); } - pending_action.clear_if_action_is(reinterpret_cast(data)); - ATS_PROBE1(milestone_cache_open_write_end, sm_id); milestones[TS_MILESTONE_CACHE_OPEN_WRITE_END] = ink_get_hrtime(); pending_action = nullptr; diff --git a/tests/gold_tests/cache/cache-write-retry-callback.test.py b/tests/gold_tests/cache/cache-write-retry-callback.test.py new file mode 100644 index 00000000000..28e3e2ec64b --- /dev/null +++ b/tests/gold_tests/cache/cache-write-retry-callback.test.py @@ -0,0 +1,25 @@ +''' +Verify a cache write retry does not cancel the cache read that follows it. +''' +# 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 = ''' +Verify a transaction that loses the cache write lock and retries can still +receive the cache read callback that its retry triggers. +''' + +Test.ATSReplayTest(replay_file="replay/cache-write-retry-callback.replay.yaml") diff --git a/tests/gold_tests/cache/replay/cache-write-retry-callback.replay.yaml b/tests/gold_tests/cache/replay/cache-write-retry-callback.replay.yaml new file mode 100644 index 00000000000..9e3627803b7 --- /dev/null +++ b/tests/gold_tests/cache/replay/cache-write-retry-callback.replay.yaml @@ -0,0 +1,134 @@ +# 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. +# +# Two transactions request the same uncached object. The first takes the cache +# write lock and holds it while its origin response is outstanding. The second +# loses the write lock, and its scheduled retry hands a cache read event back to +# HttpSM. HttpSM used to cancel its own cache action while dispatching that +# event, which aborted debug builds on the canceled action assertion in +# HttpCacheSM and dropped the callback in release builds. +# +# Read-while-writer is disabled so that the contending cache read fails +# immediately rather than waiting for the writer, which is what makes the +# callback arrive synchronously from within the write retry. + +meta: + version: "1.0" + +autest: + description: 'Verify a cache write retry preserves the cache read callback that follows it' + dns: + name: 'dns-write-retry-callback' + + server: + name: 'origin-write-retry-callback' + + client: + name: 'client-write-retry-callback' + process_config: + # The two sessions below have to overlap in time, so the client must not + # serialize them onto a single thread. + other_args: '--thread-limit 4' + + ats: + name: 'ts-write-retry-callback' + process_config: + enable_cache: true + + records_config: + proxy.config.diags.debug.enabled: 1 + proxy.config.diags.debug.tags: 'http_cache|http_trans' + # READ_RETRY: retry the cache read when the write lock is lost. + proxy.config.http.cache.open_write_fail_action: 5 + proxy.config.http.cache.max_open_write_retries: 1 + proxy.config.http.cache.max_open_write_retry_timeout: 0 + proxy.config.http.cache.max_open_read_retries: 2 + proxy.config.http.cache.open_read_retry_time: 250 + proxy.config.cache.enable_read_while_writer: 0 + + remap_config: + - from: "http://example.com/" + to: "http://backend.example.com:{SERVER_HTTP_PORT}/" + + log_validation: + traffic_out: + excludes: + - expression: "[Ff]atal|failed assertion" + description: "Verify ATS does not abort while retrying the cache write" + contains: + - expression: "falling back to read retry" + description: "Verify the contending transaction retried its cache read after losing the write lock" + - expression: "READ_RETRY cache read failed, bypassing cache" + description: "Verify the retried cache read was delivered and handled" + +sessions: + # Take the cache write lock and hold it for the duration of this slow origin + # response. + - transactions: + - client-request: + method: GET + version: '1.1' + url: /contended-object + headers: + fields: + - [uuid, cache-writer] + - [Host, example.com] + + server-response: + delay: 3s + status: 200 + reason: OK + headers: + fields: + - [Content-Length, 16] + - [Cache-Control, "max-age=300"] + - [X-Response, writer] + + proxy-response: + status: 200 + headers: + fields: + - [X-Response, {value: writer, as: equal}] + + # Lose the cache write lock to the session above. Both write attempts fail + # while that writer owns the lock, so the scheduled write retry delivers a + # cache read event to HttpSM, which issues another cache read. That read also + # fails, and the transaction proxies to the origin without caching. + - transactions: + - client-request: + delay: 200ms + method: GET + version: '1.1' + url: /contended-object + headers: + fields: + - [uuid, cache-contender] + - [Host, example.com] + + server-response: + status: 200 + reason: OK + headers: + fields: + - [Content-Length, 16] + - [Cache-Control, "max-age=300"] + - [X-Response, contender] + + proxy-response: + status: 200 + headers: + fields: + - [X-Response, {value: contender, as: equal}] From 5e0c7e91c2e3b063c7f89cb5e614db12d4bfc61f Mon Sep 17 00:00:00 2001 From: Brian Neradt Date: Thu, 6 Aug 2026 11:27:00 -0500 Subject: [PATCH 02/10] Initialize logging queues before workers (#13509) Pre-initialization plugin log buffers can be waiting when the logging workers start. A preprocessing thread can consume one before the flush queue exists and crash traffic_server while pushing the buffer to a null queue. This patch addresses the initialization race by constructing every logging notification and queue before spawning either worker. No logging thread can observe partially initialized shared queue state. This completes the startup ordering protection from #13472, which prevents plugins from waking a preprocessor before its notification exists but does not protect the flush queue after that worker starts. (cherry picked from commit 317799743707bf85fdd32f058afc489fad5c5db2) --- src/proxy/logging/Log.cc | 10 +++++----- 1 file changed, 5 insertions(+), 5 deletions(-) diff --git a/src/proxy/logging/Log.cc b/src/proxy/logging/Log.cc index 2bcaba9815b..6e72ac408b2 100644 --- a/src/proxy/logging/Log.cc +++ b/src/proxy/logging/Log.cc @@ -1242,7 +1242,11 @@ void Log::create_threads() { char desc[64]; - preproc_notify = new EventNotify[preproc_threads]; + preproc_notify = new EventNotify[preproc_threads]; + flush_notify = new EventNotify; + flush_data_list = new InkAtomicList; + + ink_atomiclist_init(flush_data_list, "Logging flush buffer list", 0); size_t stacksize; stacksize = RecGetRecordInt("proxy.config.thread.default.stacksize").value_or(0); @@ -1261,10 +1265,6 @@ Log::create_threads() // TODO: Enable multiple flush threads, such as // one flush thread per file. // - flush_notify = new EventNotify; - flush_data_list = new InkAtomicList; - - ink_atomiclist_init(flush_data_list, "Logging flush buffer list", 0); Continuation *flush_cont = new LoggingFlushContinuation(0); eventProcessor.spawn_thread(flush_cont, "[LOG_FLUSH]", stacksize); } From c5ea556ab6c392574bd6e2cb8cc282664e9f718d Mon Sep 17 00:00:00 2001 From: Masaori Koshiba Date: Fri, 7 Aug 2026 09:54:42 +0900 Subject: [PATCH 03/10] Bound the ring walk of ParentConsistentHash::selectParent (#13368) * Bound the ring walk of ParentConsistentHash::selectParent When every parent in a consistent_hash pool is down, selectParent walked the whole hash ring taking the global host_status_rwlock on every hop. The ring holds 1024 replica nodes per parent (num_parents * 1024 nodes) and the chash_lookup() gate withholds wrap_around until the ring is traversed twice, so one all-down selection cost ~2 * num_parents * 1024 HostStatus::getHostStatus() calls (~49k for 24 parents) -- inline ET_NET CPU that starved the loopback health probe and drove the VIP flap in inc-p1s2-260703. Track the distinct parents examined on each ring: skip the locked getHostStatus read for a parent already seen, and force wrap_around once every distinct parent has been rejected. The expensive locked read is now paid at most once per parent (O(num_parents)); the ring still advances ~O(N*logN) cheap, lock-free hops to reach every distinct parent. Selection order and the retry-window logic are unchanged. The seen-parent tracking is sized to num_parents (std::vector), not MAX_PARENTS: the parent.config parser does not cap num_parents at MAX_PARENTS, so a fixed [MAX_PARENTS] array would overflow the stack for pools larger than 64. Add consistent_hash_ring_walk.test.py: an all-down 100-parent pool (marked down via HostStatus, >MAX_PARENTS on purpose) must report "getHostStatus calls: 100", proving the walk reads each parent once instead of walking the full ring. * Keep the parent seen-flags out of the heap in selectParent selectParent() runs inline on ET_NET for every transaction, so the two std::vector allocations per call are pure overhead for what is a 64-flag bitmap in the ordinary case. ts::LocalBuffer keeps both rings' flags on the stack (80 bytes each) and falls back to the heap only for a pool larger than MAX_PARENTS, which stays necessary because the parent.config parser does not cap num_parents. (cherry picked from commit 38076cc46040d88e10c7b7a3a95bde3b4f4e996e) --- src/proxy/ParentConsistentHash.cc | 45 +++++- .../consistent_hash_ring_walk.test.py | 143 ++++++++++++++++++ 2 files changed, 184 insertions(+), 4 deletions(-) create mode 100644 tests/gold_tests/parent_proxy/consistent_hash_ring_walk.test.py diff --git a/src/proxy/ParentConsistentHash.cc b/src/proxy/ParentConsistentHash.cc index fad0d94e6f0..29be36b511d 100644 --- a/src/proxy/ParentConsistentHash.cc +++ b/src/proxy/ParentConsistentHash.cc @@ -20,10 +20,12 @@ See the License for the specific language governing permissions and limitations under the License. */ +#include #include #include "proxy/HostStatus.h" #include "proxy/ParentConsistentHash.h" #include "tscore/HashSip.h" +#include "tsutil/LocalBuffer.h" namespace { @@ -151,6 +153,19 @@ ParentConsistentHash::selectParent(bool first_call, ParentResult *result, Reques HostStatus &pStatus = HostStatus::instance(); TSHostStatus host_stat = TSHostStatus::TS_HOST_STATUS_INIT; + // Bound the all-down ring walk: read each distinct parent's status at most once. + // Stack resident up to MAX_PARENTS -- the parent.config parser does not cap num_parents, so a bigger + // pool falls back to the heap rather than overflowing the stack. + int const num_parents_in_ring[2] = {result->rec->num_parents, result->rec->num_secondary_parents}; + ts::LocalBuffer primary_seen(num_parents_in_ring[PRIMARY]); + ts::LocalBuffer secondary_seen(num_parents_in_ring[SECONDARY]); + bool *const seen_parent[2] = {primary_seen.data(), secondary_seen.data()}; + int seen_count[2] = {0, 0}; + int host_status_calls = 0; // getHostStatus() calls this selection (== distinct parents examined) + + std::fill_n(seen_parent[PRIMARY], num_parents_in_ring[PRIMARY], false); + std::fill_n(seen_parent[SECONDARY], num_parents_in_ring[SECONDARY], false); + Dbg(dbg_ctl_parent_select, "ParentConsistentHash::%s(): Using a consistent hash parent selection strategy.", __func__); ink_assert(numParents(result) > 0 || result->rec->go_direct == true); @@ -220,8 +235,14 @@ ParentConsistentHash::selectParent(bool first_call, ParentResult *result, Reques // ---------------------------------------------------------------------------------------------------- // didn't find a parent or the parent is marked unavailable or the parent is marked down - HostStatRec *hst = (pRec) ? pStatus.getHostStatus(pRec->hostname) : nullptr; - host_stat = (hst) ? hst->status : TSHostStatus::TS_HOST_STATUS_UP; + HostStatRec *hst = nullptr; + if (pRec) { + hst = pStatus.getHostStatus(pRec->hostname); + host_status_calls++; + seen_parent[last_lookup][pRec->idx] = true; + seen_count[last_lookup]++; + } + host_stat = (hst) ? hst->status : TSHostStatus::TS_HOST_STATUS_UP; if (firstCall) { result->first_choice_status = host_stat; } @@ -234,6 +255,8 @@ ParentConsistentHash::selectParent(bool first_call, ParentResult *result, Reques } } if (!pRec || (pRec && !pRec->available.load()) || host_stat == TS_HOST_STATUS_DOWN) { + // All-down walk: ~O(N*logN) lock-free ring hops to reach every distinct parent, but <= N (num_parents) getHostStatus reads (see + // seen_parent below). do { // check if the host is retryable. It's retryable if the retry window has elapsed // and the global host status is HOST_STATUS_UP @@ -312,7 +335,21 @@ ParentConsistentHash::selectParent(bool first_call, ParentResult *result, Reques Dbg(dbg_ctl_parent_select, "No available parents."); break; } - hst = (pRec) ? pStatus.getHostStatus(pRec->hostname) : nullptr; + // Read each distinct parent's status at most once; force wrap when all are rejected. + if (pRec && seen_parent[last_lookup][pRec->idx]) { + if (seen_count[last_lookup] >= num_parents_in_ring[last_lookup]) { + wrap_around[last_lookup] = true; + } + host_stat = TS_HOST_STATUS_DOWN; + continue; + } + hst = nullptr; + if (pRec) { + hst = pStatus.getHostStatus(pRec->hostname); + host_status_calls++; + seen_parent[last_lookup][pRec->idx] = true; + seen_count[last_lookup]++; + } host_stat = (hst) ? hst->status : TSHostStatus::TS_HOST_STATUS_UP; // if the config ignore_self_detect is set to true and the host is down due to SELF_DETECT reason // ignore the down status and mark it as available @@ -324,7 +361,7 @@ ParentConsistentHash::selectParent(bool first_call, ParentResult *result, Reques } while (!pRec || !pRec->available.load() || host_stat == TS_HOST_STATUS_DOWN); } - Dbg(dbg_ctl_parent_select, "Additional parent lookups: %d", lookups); + Dbg(dbg_ctl_parent_select, "Additional parent lookups: %d, getHostStatus calls: %d", lookups, host_status_calls); // ---------------------------------------------------------------------------------------------------- // Validate and return the final result. diff --git a/tests/gold_tests/parent_proxy/consistent_hash_ring_walk.test.py b/tests/gold_tests/parent_proxy/consistent_hash_ring_walk.test.py new file mode 100644 index 00000000000..a279c2c7c7a --- /dev/null +++ b/tests/gold_tests/parent_proxy/consistent_hash_ring_walk.test.py @@ -0,0 +1,143 @@ +""" +Verify ParentConsistentHash::selectParent() does not waste work walking an +all-down consistent_hash pool. + +A consistent-hash ring has 1024 replica nodes per parent (default +ATSConsistentHash replicas, DEFAULT_PARENT_WEIGHT=1.0), so num_parents*1024 ring +nodes total. When every parent is down, selectParent must walk the ring to +conclude so -- but it must read each parent's HostStatus (the global +host_status_rwlock) at most ONCE, not once per replica node. selectParent tracks +the distinct parents examined and stops as soon as all are rejected, so an +all-down selection over N parents costs exactly N getHostStatus calls -- not the +~2*N*1024 (two ring passes) the naive walk cost, which put ~8-13 ms of inline +ET_NET CPU per request and wedged the vipd health probe in inc-p1s2-260703. + +Proven by the per-selection "getHostStatus calls: " debug line +(ParentConsistentHash.cc): it must equal the parent count, not a five-figure ring +walk. + +Pool size > MAX_PARENTS (64) on purpose: num_parents is NOT capped at +MAX_PARENTS by the config parser, so the per-selection "seen parent" tracking +must be sized to the actual pool (a fixed [MAX_PARENTS] array would overflow). +Running a >64-parent pool to completion (no crash, correct 502, bounded count) +guards that sizing. + +no_dns_just_forward_to_parent=1 lets ATS skip origin resolution and go straight +to parent selection, so this test needs no DNS server and no origin -- every +parent is HostStatus-DOWN => PARENT_FAIL => 502 before any connect. +""" +# Licensed to the Apache Software Foundation (ASF) under one +# or more contributor license agreements. See the NOTICE file +# distributed with this work for additional information +# regarding copyright ownership. The ASF licenses this file +# to you under the Apache License, Version 2.0 (the +# "License"); you may not use this file except in compliance +# with the License. You may obtain a copy of the License at +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +# See the License for the specific language governing permissions and +# limitations under the License. + +import os + +from ports import get_port + +Test.Summary = ''' +An all-down consistent_hash parent pool (marked down via HostStatus) drives +selectParent to read each distinct parent's HostStatus exactly once +(O(num_parents)), not once per ring replica node (~2 * num_parents * 1024). +''' +Test.ContinueOnFail = True + +# > MAX_PARENTS (64): exercises the pool-sized "seen parent" tracking and would +# overflow a fixed [MAX_PARENTS] array. Distinct names matter -- consistent_hash +# keys the ring on hostname, so identical names would collapse to one ring node. +NUM_PARENTS = 100 + + +class ParentDownRingWalkTest: + """All parents HostStatus-DOWN => selectParent reads each parent once => 502.""" + + parent_hostnames = [f'deadparent{i:03d}' for i in range(1, NUM_PARENTS + 1)] + + def __init__(self): + self._setupTS() + + def _setupTS(self): + self.ts = Test.MakeATSProcess('ts', enable_cache=False) + + # A dead (reserved-but-unbound) port per parent. They are never actually + # connected -- every parent is HostStatus-DOWN so selectParent returns + # PARENT_FAIL before any connect -- but parent.config needs a port. + self._parent_ports = [] + for i in range(len(self.parent_hostnames)): + name = f'dead_parent_port_{i}' + get_port(self.ts, name) + self._parent_ports.append(getattr(self.ts.Variables, name)) + + self.ts.Disk.records_config.update( + { + # Enable only the parent_select debug ctl so the per-selection + # "getHostStatus calls: " line is emitted. + 'proxy.config.diags.debug.enabled': 1, + 'proxy.config.diags.debug.tags': 'parent_select', + # Skip origin DNS: forward straight to parent selection. No DNS + # server / origin needed for this isolation. + 'proxy.config.http.no_dns_just_forward_to_parent': 1, + # self_detect off: this test populates the HostStatus map via + # `traffic_ctl host down` below, not via self_detect (the + # deadparents never resolve to this box anyway). + 'proxy.config.http.parent_proxy.fail_threshold': 10, + 'proxy.config.http.parent_proxy.retry_time': 300, + 'proxy.config.http.parent_proxy.self_detect': 0, + 'proxy.config.url_remap.remap_required': 0, + }) + + # Consistent-hash pool of distinct parent hostnames, go_direct=false so an + # all-down pool yields 502 (not a direct-to-origin fallback). + self._parents = list(zip(self.parent_hostnames, self._parent_ports)) + parent_list = ', '.join(f'{host}:{port}|1' for host, port in self._parents) + self.ts.Disk.parent_config.AddLine( + f'dest_domain=. parent="{parent_list}" round_robin=consistent_hash ' + 'go_direct=false parent_is_proxy=true') + + # The all-down selection is a single findParent call. selectParent reads + # each distinct parent's HostStatus at most once and stops once all are + # rejected, so the per-selection "getHostStatus calls" count equals the + # parent count -- not the ~2*N*1024 five-figure ring walk it cost before. + self.ts.Disk.traffic_out.Content += Testers.ContainsExpression( + r'getHostStatus calls: %d\b' % NUM_PARENTS, + 'selectParent read each distinct parent once (O(num_parents)), not the full ring.') + # It must NOT take the HostStatus lock once per ring replica node (the old + # bug reported a five-figure count). + self.ts.Disk.traffic_out.Content += Testers.ExcludesExpression( + r'getHostStatus calls: [0-9]{5}', 'selectParent must not read HostStatus once per ring replica node.') + + def run(self): + traffic_ctl = os.path.join(self.ts.Variables.BINDIR, 'traffic_ctl') + + # 1. Bring the whole parent pool DOWN via HostStatus (one RPC call). + # Populates hosts_statuses (=> every getHostStatus takes the rwlock) + # and forces host_stat==DOWN (=> the full ring walk, no early exit). + down = Test.AddTestRun('Mark the entire parent pool down via HostStatus') + down.Processes.Default.StartBefore(self.ts) + down.Processes.Default.Command = f'{traffic_ctl} host down ' + ' '.join(self.parent_hostnames) + down.Processes.Default.Env = self.ts.Env + down.Processes.Default.ReturnCode = 0 + + # 2. One request through the all-down pool -> bounded walk -> 502. A crash + # here (e.g. seen-parent tracking overflowing on a >64 pool) fails the test. + load = Test.AddTestRun('Request through the all-down pool -> bounded selection -> 502') + load.MakeCurlCommand( + f'-s -o /dev/null -w "%{{http_code}}" --proxy 127.0.0.1:{self.ts.Variables.port} http://example.com/ring-walk-probe', + ts=self.ts) + load.Processes.Default.Streams.stdout = Testers.ContainsExpression('502', 'All parents down => 502.') + load.Processes.Default.ReturnCode = 0 + load.StillRunningAfter = self.ts + + +ParentDownRingWalkTest().run() From 430ba4b8b35864c38ccab31f394f280218f6548b Mon Sep 17 00:00:00 2001 From: Masaori Koshiba Date: Fri, 7 Aug 2026 11:41:14 +0900 Subject: [PATCH 04/10] slice: purge every block of an object, not just those before a gap (#13475) * slice: purge every block of an object, not just those before a gap A PURGE is meant to discard the object, but the block walk stopped at the first block that was not in cache, so any object whose cached blocks were not a contiguous run from block 0 was only partially purged, and the client still got a 200. A gap in the middle left every block behind it cached; an uncached first block purged nothing and relayed that block's 404; and a "bytes=-N" purge deleted the head while leaving the tail it had named. The stop was load-bearing. The walk's only other terminator needs the object length, which slice only ever learned from a 206's Content-Range, and a PURGE response has none. So the core now reports the removed object's extent as X-Purged-Content-Range on a PURGE cache hit, and the walk learns where the object ends from the blocks it is already deleting. It is not Content-Range itself, since that header on a 200 is meaningless under RFC 9110 and cache_range_requests reads the pair as a stored 206 and rewrites the status. PURGE gets its own state machine in the plugin, so it no longer routes through handleFirstServerHeader, whose double duty as "form and emit the client response" is what leaked the 404. A 404 for a block is stepped over, nothing is written downstream until the walk finishes, and the response is then synthesized: 200 if any block was removed, 404 if none was. The extent is taken as a maximum rather than the first value seen, since blocks of one object disagree when the origin object was replaced in place. Until some block reports an extent the walk has no end but a miss bound, so add --purge-probe-blocks, default 8, capping consecutive uncached blocks. It never limits how many blocks a purge removes. A per-request override named by --purge-probe-header, default X-Slice-Purge-Probe, lets an operator who knows the object size widen it. A suffix range names its blocks by distance from an end slice does not know yet, so such a purge is widened to the whole object, a superset of what was asked. A PURGE whose Range cannot be parsed is refused with a 400 rather than guessing which blocks were meant. Tests cover the traversal over gaps, an uncached first block, both open-ended range forms, blocks that disagree about the object length, the miss bound and its override, and the refusal. They measure on the origin rather than the response body, since a purged block and a surviving block are indistinguishable to the client. Two further tests reproduce the client-visible failures of an origin object replaced in place under a child/parent hierarchy, which is how this problem was found. * Doc: Fix example of HTTP/1.1 messages * slice: pace the two PURGE request-validation error logs Both values are client supplied, so a bad one repeats as fast as requests arrive. Route them through Config::canLogError() like the other slice error paths. * slice: let a PURGE range bound the walk before any extent is known The requested range end comes from the client's Range header, but the walk only consulted it once some block had reported the object's extent, which only a block that was actually removed can do. A closed-range PURGE whose leading blocks were uncached therefore ran past its range end and removed blocks the client never named. * slice: do not report a partial PURGE as a success A block PURGE answering neither 200 nor 404 was read as "already absent", so a 403 from ip_allow or a 502 counted as a miss and the walk carried on to answer 200 on the strength of blocks it had removed earlier, telling the client the object was gone while part of it was still cached. Such a status says nothing about the blocks behind it either, so the walk now stops there and reports it. (cherry picked from commit 48fc8429140dc9da2bc237c7fb890fb4a0bbd54d) --- doc/admin-guide/plugins/slice.en.rst | 99 +- doc/admin-guide/storage/index.en.rst | 17 +- plugins/slice/Config.cc | 26 +- plugins/slice/Config.h | 6 + plugins/slice/Data.h | 23 +- plugins/slice/HttpHeader.cc | 26 + plugins/slice/HttpHeader.h | 11 + plugins/slice/client.cc | 70 ++ plugins/slice/response.cc | 15 + plugins/slice/response.h | 6 + plugins/slice/server.cc | 213 ++++- plugins/slice/server.h | 11 + plugins/slice/util.cc | 8 +- src/proxy/http/HttpTransact.cc | 19 + .../slice_purge_gaps_client.replay.yaml | 895 ++++++++++++++++++ .../slice_purge_gaps_server.replay.yaml | 586 ++++++++++++ .../slice_stale_generation_client.replay.yaml | 206 ++++ .../slice_stale_generation_server.replay.yaml | 286 ++++++ .../slice/rules/purge_block_failure.conf | 41 + .../pluginTest/slice/slice_purge_gaps.test.py | 346 +++++++ .../slice/slice_stale_generation.test.py | 327 +++++++ 21 files changed, 3206 insertions(+), 31 deletions(-) create mode 100644 tests/gold_tests/pluginTest/slice/replay/slice_purge_gaps_client.replay.yaml create mode 100644 tests/gold_tests/pluginTest/slice/replay/slice_purge_gaps_server.replay.yaml create mode 100644 tests/gold_tests/pluginTest/slice/replay/slice_stale_generation_client.replay.yaml create mode 100644 tests/gold_tests/pluginTest/slice/replay/slice_stale_generation_server.replay.yaml create mode 100644 tests/gold_tests/pluginTest/slice/rules/purge_block_failure.conf create mode 100644 tests/gold_tests/pluginTest/slice/slice_purge_gaps.test.py create mode 100644 tests/gold_tests/pluginTest/slice/slice_stale_generation.test.py diff --git a/doc/admin-guide/plugins/slice.en.rst b/doc/admin-guide/plugins/slice.en.rst index 40d606129c5..21edd7eb203 100644 --- a/doc/admin-guide/plugins/slice.en.rst +++ b/doc/admin-guide/plugins/slice.en.rst @@ -186,7 +186,21 @@ The slice plugin supports the following options:: that causes `cache_range_requests` to be bypassed in such requests, and allow ATS to handle those range requests internally. - + --purge-probe-blocks= (optional) + Default is 8 + How many consecutive uncached slice blocks a PURGE walks, before any block + has reported the object's extent, until it concludes that nothing about the + object is cached. May be overridden per request with the header named by + ``--purge-probe-header``. See `Purge Requests`_. + -q for short + + --purge-probe-header= (optional) + Default is X-Slice-Purge-Probe + Name of the request header a PURGE may use to override + ``--purge-probe-blocks`` for that request. A malformed value is ignored + in favour of the configured default. Slice strips this header from the + block requests it issues. + -H for short Examples:: @@ -338,17 +352,78 @@ requests may end up being served from temporally different assets. Purge Requests -------------- -The slice plugin supports PURGE requests, discarding the requested object from cache. -If a range is given in the client request, only the slice blocks from the -requested range will be purged (if in cache). If not, all of the blocks will be discarded -from the cache. - -If a block receives a 404, indicating the requested block to be purged is not in the cache, -slice will not continue to purge the following blocks. - -The functionality works with `--ref-relative` both enabled and disabled. If `--ref-relative` is -disabled (using slice 0 as the reference block), requesting to PURGE a block that does not have -slice 0 in its range will still PURGE the slice 0 block, as the reference block is always processed. +The slice plugin supports PURGE requests, discarding the requested object from +cache. Without a range every block is discarded; with a range, the blocks that +range covers are. Two cases below purge more than the range names: a suffix range, +and block 0 when ``--ref-relative`` is disabled. + +Slice issues one PURGE per block and walks every block it was asked for, whether +or not each one is currently cached. A block that is already absent answers 404 +internally; that is simply noted and the walk continues, so a gap left by +per-block eviction cannot leave the blocks behind it in cache. + +Slice learns where the object ends from the blocks it removes. PURGE is a Traffic +Server extension, so a successful block purge reports the removed object's extent +in a ``X-Purged-Content-Range`` header, and the walk continues to the last block that +extent implies. Blocks of one object can disagree about its length when the origin +object has been replaced in place; slice takes the largest extent any block +reports, so the longer generation's tail is not left behind. + +Until some block has reported an extent, a walk over an open-ended range has no +end but the miss bound: it stops after ``--purge-probe-blocks`` consecutive +uncached blocks and reports that nothing was found. That is what bounds a PURGE +for a URL which is not cached at all. + +An operator often knows more about the object than the plugin does, since the +block count is just the object's size divided by the block size. That count can be +supplied per request with the header named by ``--purge-probe-header``, default +``X-Slice-Purge-Probe``:: + + PURGE /obj HTTP/1.1 + X-Slice-Purge-Probe: 64 + +This only changes how long the walk keeps going without having found anything; it +never limits how many blocks are purged once an extent is known. + +The bound has to be able to span a whole object, because in the worst case only +the object's last block is still cached, so the value an operator wants is the +object's size divided by the block size: a 10 GB object in 1 MB blocks needs +10240. There is no ceiling on it beyond that, since reaching the bound costs one +internal cache lookup per block and PURGE is already restricted by +:file:`ip_allow.yaml`. A malformed value is ignored in favour of the configured +default, and slice strips the header from the block requests it issues. + +If the bound is reached, slice logs that it gave up and reports ``404`` even though +later blocks may still be cached. Raise ``--purge-probe-blocks``, or send the +override, for objects whose leading blocks are routinely absent. + +A client range that is already closed, such as ``bytes=0-6399999999``, bounds the +walk directly, and is clamped against the object's extent as soon as some block +reports one. An over-estimate therefore costs no extra block PURGEs beyond the end +of the object, and if no block is cached at all the miss bound stops the walk. + +A suffix range, ``bytes=-``, names its blocks by their distance from an end +slice does not know yet, and purging is the only way it could find out. Rather +than guess at the start, such a purge is widened to the whole object: a superset of +what was asked for, so the named blocks certainly go. A ``GET`` with the same header +is unaffected and still returns exactly the last *n* bytes. + +The response is sent once the walk is complete: ``200`` if at least one block was +removed, ``404`` if none was found. This matches what Traffic Server reports for a +PURGE of an object that is not sliced. + +A block whose PURGE returns neither ``200`` nor ``404`` — a ``403`` from +:file:`ip_allow.yaml`, for instance, or a ``502`` — says nothing about whether that +block was cached, and nothing about the blocks behind it. The walk stops there and that +status is reported in place of ``200``, so the two success statuses keep meaning what +they say: ``200`` that the object is gone and ``404`` that it was not there, never that +this proxy could not tell. Blocks the walk had already removed stay removed, and blocks +behind the failing one are left cached, so such a PURGE is worth repeating once +whatever refused it has been dealt with. + +The functionality works with ``--ref-relative`` both enabled and disabled. With it +disabled, block 0 is always the first block walked, so a PURGE whose range does not +cover block 0 still purges it. Conditional Slicing ------------------- diff --git a/doc/admin-guide/storage/index.en.rst b/doc/admin-guide/storage/index.en.rst index 22788eeaa4d..d10d9e5e82b 100644 --- a/doc/admin-guide/storage/index.en.rst +++ b/doc/admin-guide/storage/index.en.rst @@ -304,7 +304,7 @@ from any other IP, we connect to the daemon via localhost: :: > Host: example.com > Accept: */* > - < HTTP/1.1 200 Ok + < HTTP/1.1 200 OK < Date: Thu, 08 Jan 2010 20:32:07 GMT < Connection: keep-alive @@ -312,6 +312,21 @@ The next time Traffic Server receives a request for the removed object, it will contact the origin server to retrieve a new copy, which will replace the previously cached version in Traffic Server. +If the removed object was stored as a partial response, that is if it carried a +``Content-Range``, then the ``200 OK`` also reports that range back in a +``X-Purged-Content-Range`` header:: + + < HTTP/1.1 200 OK + < X-Purged-Content-Range: bytes 0-1048575/9437184 + +This lets a caller that holds one piece of a larger resource learn the whole +resource's extent without a second lookup. It is what allows the +:ref:`admin-plugins-slice` plugin to purge an object block by block and know which +block is the last one. The range is reported under its own header name rather than +as ``Content-Range``, because ``Content-Range`` on a ``200`` response has no +meaning under :rfc:`9110` and is read by other components as a sign that a stored +partial response is being served. + This procedure only removes the index to the object from a specific Traffic Server cache. While the object remains on disk, Traffic Server will no longer able to find the object. The next request for that object will result in a fresh copy of the diff --git a/plugins/slice/Config.cc b/plugins/slice/Config.cc index b95ace3bab0..b5e19f71891 100644 --- a/plugins/slice/Config.cc +++ b/plugins/slice/Config.cc @@ -27,8 +27,9 @@ namespace { -constexpr std::string_view DefaultSliceSkipHeader = {"X-Slicer-Info"}; -constexpr std::string_view DefaultCrrIdentHeader = {"X-Crr-Ident"}; +constexpr std::string_view DefaultSliceSkipHeader = {"X-Slicer-Info"}; +constexpr std::string_view DefaultCrrIdentHeader = {"X-Crr-Ident"}; +constexpr std::string_view DefaultPurgeProbeHeader = {"X-Slice-Purge-Probe"}; } // namespace Config::~Config() @@ -121,13 +122,15 @@ Config::fromArgs(int const argc, char const *const argv[]) {const_cast("minimum-size"), required_argument, nullptr, 'm'}, {const_cast("metadata-cache-size"), required_argument, nullptr, 'z'}, {const_cast("stats-prefix"), required_argument, nullptr, 'x'}, + {const_cast("purge-probe-blocks"), required_argument, nullptr, 'q'}, + {const_cast("purge-probe-header"), required_argument, nullptr, 'H'}, {nullptr, 0, nullptr, 0 }, }; // 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:g:i:lm:p:r:s:t:x:z:", longopts, nullptr); + int const opt = getopt_long(argc + 1, argvp, "b:de:g:H:i:lm:p:q:r:s:t:x:z:", longopts, nullptr); if (-1 == opt) { break; } @@ -248,6 +251,19 @@ Config::fromArgs(int const argc, char const *const argv[]) stat_prefix = optarg; DEBUG_LOG("Stat prefix: %s", stat_prefix.c_str()); } break; + case 'q': { + int const blocksread = atoi(optarg); + if (0 < blocksread) { + m_purge_probe_blocks = blocksread; + DEBUG_LOG("Using purge probe blocks %d", m_purge_probe_blocks); + } else { + ERROR_LOG("Invalid purge-probe-blocks: %s", optarg); + } + } break; + case 'H': { + m_purge_probe_header.assign(optarg); + DEBUG_LOG("Using purge probe header %s", optarg); + } break; default: break; } @@ -275,6 +291,10 @@ Config::fromArgs(int const argc, char const *const argv[]) m_skip_header = DefaultSliceSkipHeader; DEBUG_LOG("Using default slice skip header %s", m_skip_header.c_str()); } + if (m_purge_probe_header.empty()) { + m_purge_probe_header = DefaultPurgeProbeHeader; + DEBUG_LOG("Using default purge probe header %s", m_purge_probe_header.c_str()); + } if (m_min_size_to_slice > 0) { if (m_oscache.has_value()) { diff --git a/plugins/slice/Config.h b/plugins/slice/Config.h index 4fd15a2506b..f9888e66404 100644 --- a/plugins/slice/Config.h +++ b/plugins/slice/Config.h @@ -36,6 +36,8 @@ struct Config { static constexpr int64_t const blockbytesmax = 1024 * 1024 * 128; // 128MB static constexpr int64_t const blockbytesdefault = 1024 * 1024; // 1MB + static constexpr int const purgeprobeblocksdefault = 8; + int64_t m_blockbytes{blockbytesdefault}; std::string m_remaphost; // remap host to use for loopback slice GET std::string m_regexstr; // regex string for things to slice (default all) @@ -49,8 +51,12 @@ struct Config { bool m_head_strip_range{false}; // strip range header for head requests uint64_t m_min_size_to_slice{0}; // Only strip objects larger than this + // consecutive uncached blocks a purge tolerates before giving up on the object + int m_purge_probe_blocks{purgeprobeblocksdefault}; + std::string m_skip_header; std::string m_crr_ident_header; + std::string m_purge_probe_header; // request header overriding m_purge_probe_blocks // Convert optarg to bytes static int64_t bytesFrom(char const *const valstr); diff --git a/plugins/slice/Data.h b/plugins/slice/Data.h index 0c19dfaafa5..a3fd8e1cf45 100644 --- a/plugins/slice/Data.h +++ b/plugins/slice/Data.h @@ -77,6 +77,11 @@ struct Data { int64_t m_blockskip{0}; // number of bytes to skip in this block int64_t m_blockconsumed{0}; // body bytes consumed + int64_t m_purge_hits{0}; // blocks a purge actually removed + int m_purge_misses{0}; // consecutive uncached blocks the walk has seen + int m_purge_miss_bound{0}; // from the config or the request header + TSHttpStatus m_purge_error{TS_HTTP_STATUS_NONE}; // block failure that ended the walk + BlockState m_blockstate{Pending}; // is there an active slice block int64_t m_bytestosend{0}; // header + content bytes to send @@ -109,11 +114,25 @@ struct Data { memset(&m_client_ip, 0, sizeof(m_client_ip)); } - // Check if response only expects header + // HEAD only; a purge sends just a header too but never reaches the transfer path bool onlyHeader() const { - return (m_method_type == TS_HTTP_METHOD_HEAD || m_method_type == TS_HTTP_METHOD_PURGE); + return m_method_type == TS_HTTP_METHOD_HEAD; + } + + bool + is_purge() const + { + return m_method_type == TS_HTTP_METHOD_PURGE; + } + + // The purge range, closed against the object length once known. m_req_range + // stays as sent so a longer extent can widen the walk; a clamp could only shrink. + Range + purge_range() const + { + return (m_contentlen < 0) ? m_req_range : m_req_range.intersectedWith(Range(0, m_contentlen)); } ~Data() diff --git a/plugins/slice/HttpHeader.cc b/plugins/slice/HttpHeader.cc index d08e76db7a9..e075036a240 100644 --- a/plugins/slice/HttpHeader.cc +++ b/plugins/slice/HttpHeader.cc @@ -326,6 +326,32 @@ HttpHeader::toString() const /////// HdrMgr +bool +HdrMgr::create_response(TSHttpStatus const status) +{ + resetHeader(); + + if (nullptr == m_buffer) { + m_buffer = TSMBufferCreate(); + } + + m_lochdr = TSHttpHdrCreate(m_buffer); + if (nullptr == m_lochdr) { + return false; + } + + TSHttpHdrTypeSet(m_buffer, m_lochdr, TS_HTTP_TYPE_RESPONSE); + TSHttpHdrVersionSet(m_buffer, m_lochdr, TS_HTTP_VERSION(1, 1)); + TSHttpHdrStatusSet(m_buffer, m_lochdr, status); + + char const *const reason = TSHttpHdrReasonLookup(status); + if (nullptr != reason) { + TSHttpHdrReasonSet(m_buffer, m_lochdr, reason, strlen(reason)); + } + + return true; +} + TSParseResult HdrMgr::populateFrom(TSHttpParser const http_parser, TSIOBufferReader const reader, HeaderParseFunc const parsefunc, int64_t *const bytes) diff --git a/plugins/slice/HttpHeader.h b/plugins/slice/HttpHeader.h index c52738e5d18..0fd50c779a9 100644 --- a/plugins/slice/HttpHeader.h +++ b/plugins/slice/HttpHeader.h @@ -39,6 +39,10 @@ constexpr std::string_view SLICE_CRR_HEADER = {"Slice-Crr-Status"}; constexpr std::string_view SLICE_CRR_VAL = "1"; +// extent of the object a PURGE removed, reported by ATS on a successful purge. +// Emitted by HttpTransact::delete_all_document_alternates_and_return. +constexpr std::string_view PURGED_CONTENT_RANGE = {"X-Purged-Content-Range"}; + /** Designed to be a cheap throwaway struct which allows a consumer to make various calls to manipulate headers. @@ -207,6 +211,13 @@ struct HdrMgr { } } + /** Create an owned HTTP/1.1 response header with the given status. + * + * For a response slice forms itself, with no server response to relay. An + * intercept is an HTTP/1.x channel, so the version is not negotiable. + */ + bool create_response(TSHttpStatus const status); + void resetHeader() { diff --git a/plugins/slice/client.cc b/plugins/slice/client.cc index 1494ffa38a5..5c5933cd101 100644 --- a/plugins/slice/client.cc +++ b/plugins/slice/client.cc @@ -19,9 +19,49 @@ #include "client.h" #include "Config.h" +#include "server.h" #include "util.h" +#include "swoc/TextView.h" + +#include #include +#include + +namespace +{ +// Miss bound for this purge: the request header when usable, else the config value. +int +purge_miss_bound(HttpHeader const &header, Config *const conf) +{ + char probestr[64]; + int probelen = sizeof(probestr); + + if (!header.valueForKey(conf->m_purge_probe_header.data(), conf->m_purge_probe_header.size(), probestr, &probelen)) { + return conf->m_purge_probe_blocks; + } + + swoc::TextView value{probestr, static_cast(probelen)}; + // isspace is only defined for values representable as unsigned char + value.trim_if([](char c) { return 0 != isspace(static_cast(c)); }); + + swoc::TextView parsed; + intmax_t const blocks = swoc::svtoi(value, &parsed, 10); + + // parsed must cover the whole value: "8abc" is a mistake, not eight blocks + if (parsed.size() != value.size() || blocks <= 0 || std::numeric_limits::max() < blocks) { + // paced: the value is client supplied, so a bad one repeats as fast as requests arrive + if (conf->canLogError()) { + ERROR_LOG("Ignoring invalid %.*s value '%.*s'", static_cast(conf->m_purge_probe_header.size()), + conf->m_purge_probe_header.data(), probelen, probestr); + } + return conf->m_purge_probe_blocks; + } + + return static_cast(blocks); +} + +} // namespace // this is called once per transaction when the client sends a req header bool @@ -94,6 +134,31 @@ handle_client_req(TSCont contp, TSEvent event, Data *const data) data->m_req_range = rangebe; + if (data->is_purge()) { + // The substituted range covers block 0, so walking it would delete the head + if (TS_HTTP_STATUS_REQUESTED_RANGE_NOT_SATISFIABLE == data->m_statustype) { + // paced: the range is client supplied, so a bad one repeats as fast as requests arrive + if (data->m_config->canLogError()) { + ERROR_LOG("Refusing PURGE with an unparseable range"); + } + finish_purge(contp, data, TS_HTTP_STATUS_BAD_REQUEST); + return true; + } + + data->m_purge_miss_bound = purge_miss_bound(header, data->m_config); + DEBUG_LOG("%p Purge miss bound %d block(s)", data, data->m_purge_miss_bound); + + // A suffix range cannot know its start block, so purge a superset: everything + if (data->m_req_range.isEndBytes()) { + data->m_req_range = Range(0, Range::maxval); + data->m_blocknum = 0; + DEBUG_LOG("%p Purge suffix range widened to the whole object", data); + } + + // The miss bound is for this proxy to act on, not to propagate + header.removeKey(conf->m_purge_probe_header.data(), conf->m_purge_probe_header.size()); + } + // 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); @@ -126,6 +191,11 @@ handle_client_resp(TSCont contp, TSEvent event, Data *const data) { switch (event) { case TS_EVENT_VCONN_WRITE_READY: { + // finish_purge writes the whole response at once; nothing to throttle or pull + if (data->is_purge()) { + break; + } + switch (data->m_blockstate) { case BlockState::Fail: case BlockState::PendingRef: diff --git a/plugins/slice/response.cc b/plugins/slice/response.cc index 94081cf7b20..a34ef3a6cb0 100644 --- a/plugins/slice/response.cc +++ b/plugins/slice/response.cc @@ -86,6 +86,21 @@ string502(int const httpver) return msg; } +// Form the response to a sliced PURGE, once every block has been walked +bool +form_purge_response(HdrMgr &hdrmgr, TSHttpStatus const status) +{ + if (!hdrmgr.create_response(status)) { + return false; + } + + // The core adds Date, Age, Server and Connection to an intercept's response + HttpHeader header(hdrmgr.m_buffer, hdrmgr.m_lochdr); + header.setKeyVal(TS_MIME_FIELD_CONTENT_LENGTH, TS_MIME_LEN_CONTENT_LENGTH, "0", 1); + + return true; +} + void form416HeaderAndBody(HttpHeader &header, int64_t const contentlen, std::string const &bodystr) { diff --git a/plugins/slice/response.h b/plugins/slice/response.h index c116d22e21c..569af1120bc 100644 --- a/plugins/slice/response.h +++ b/plugins/slice/response.h @@ -25,4 +25,10 @@ std::string string502(int const httpver); std::string const &bodyString416(); +/** Fill hdrmgr with the response to a sliced PURGE, for the caller to print. + * + * The header is owned by hdrmgr and destroyed with it. + */ +bool form_purge_response(HdrMgr &hdrmgr, TSHttpStatus const status); + void form416HeaderAndBody(HttpHeader &header, int64_t const contentlen, std::string const &bodystr); diff --git a/plugins/slice/server.cc b/plugins/slice/server.cc index 7105d5157bd..2b25f22c01a 100644 --- a/plugins/slice/server.cc +++ b/plugins/slice/server.cc @@ -32,7 +32,7 @@ namespace { ContentRange -contentRangeFrom(HttpHeader const &header) +content_range_for_key(HttpHeader const &header, char const *const key, int const keylen) { ContentRange bcr; @@ -42,22 +42,25 @@ contentRangeFrom(HttpHeader const &header) char rangestr[1024]; int rangelen = sizeof(rangestr); - // look for expected Content-Range field - bool const hasContentRange(header.valueForKey(TS_MIME_FIELD_CONTENT_RANGE, TS_MIME_LEN_CONTENT_RANGE, rangestr, &rangelen)); - - if (!hasContentRange) { - DEBUG_LOG("invalid response header, no Content-Range"); + if (!header.valueForKey(key, keylen, rangestr, &rangelen)) { + DEBUG_LOG("invalid response header, no %.*s", keylen, key); } else { // ensure null termination rangestr[rangelen] = '\0'; if (!bcr.fromStringClosed(rangestr)) { - DEBUG_LOG("invalid response header, malformed Content-Range, %s", rangestr); + DEBUG_LOG("invalid response header, malformed %.*s, %s", keylen, key, rangestr); } } return bcr; } +ContentRange +contentRangeFrom(HttpHeader const &header) +{ + return content_range_for_key(header, TS_MIME_FIELD_CONTENT_RANGE, TS_MIME_LEN_CONTENT_RANGE); +} + int64_t contentLengthFrom(HttpHeader const &header) { @@ -136,7 +139,7 @@ handleFirstServerHeader(Data *const data, TSCont const contp) int64_t const hlen = TSHttpHdrLengthGet(header.m_buffer, header.m_lochdr); int64_t const clen = contentLengthFrom(header); if (TS_HTTP_STATUS_OK == header.status() && data->onlyHeader()) { - DEBUG_LOG("HEAD/PURGE request stripped Range header: expects 200"); + DEBUG_LOG("HEAD request stripped Range header: expects 200"); data->m_bytestosend = hlen; data->m_blockexpected = 0; TSVIONBytesSet(output_vio, hlen); @@ -499,12 +502,201 @@ handleNextServerHeader(Data *const data) return true; } +// Take the largest extent any block reports: blocks disagree when the origin +// object was replaced in place, and the shorter one would leave a tail cached. +void +note_purge_extent(Data *const data, int64_t const length) +{ + if (length <= data->m_contentlen) { + return; + } + + data->m_contentlen = length; + DEBUG_LOG("purge extent now %" PRId64 ", walking through block %" PRId64, length, + data->purge_range().lastBlockFor(data->m_config->m_blockbytes)); +} + +// A block that could not be purged is not a block that was absent, so the client must +// not be told the object is gone. The walk stops here: the rest of the object is +// unknown, and a 5xx often means the cache is in no state to be asked again. +void +note_purge_failure(Data *const data, TSHttpStatus const status) +{ + data->m_purge_error = status; + + // paced: a config refusing PURGE would otherwise log once per purge request + if (data->m_config->canLogError()) { + ERROR_LOG("Purge of block %" PRId64 " failed (%d), the object may be left partly cached", data->m_blocknum, status); + } +} + +// Record what the block response said, without answering the client. +void +note_purge_block_result(Data *const data) +{ + HttpHeader const header(data->m_resp_hdrmgr.m_buffer, data->m_resp_hdrmgr.m_lochdr); + DEBUG_LOG("Purge block header\n%s", header.toString().c_str()); + + TSHttpStatus const status = header.status(); + + if (TS_HTTP_STATUS_OK == status) { + ++data->m_purge_hits; + data->m_purge_misses = 0; + + // Not Content-Range: cache_range_requests reads that on a 200 as a stored 206 + // and rewrites the status + ContentRange const purgedcr = content_range_for_key(header, PURGED_CONTENT_RANGE.data(), PURGED_CONTENT_RANGE.size()); + if (purgedcr.isValid() && 0 < purgedcr.m_length) { + note_purge_extent(data, purgedcr.m_length); + } else { + DEBUG_LOG("Purged block %" PRId64 " reported no usable extent", data->m_blocknum); + } + } else if (TS_HTTP_STATUS_NOT_FOUND == status) { + // Already absent. The walk used to stop here, leaving every later block cached. + ++data->m_purge_misses; + DEBUG_LOG("Purge block %" PRId64 " was not cached", data->m_blocknum); + } else { + // Anything else is a refusal or a failure, which says nothing about the block + note_purge_failure(data, status); + } +} + +// Issue the next purge, or answer the client if the walk is over. +void +advance_purge(TSCont const contp, Data *const data) +{ + // A block that could not be purged says nothing about the ones behind it + if (TS_HTTP_STATUS_NONE != data->m_purge_error) { + finish_purge(contp, data); + return; + } + + int64_t const blockbytes = data->m_config->m_blockbytes; + Range const range = data->purge_range(); + + ++data->m_blocknum; + int64_t const firstblock = range.firstBlockFor(blockbytes); + if (data->m_blocknum < firstblock) { + data->m_blocknum = firstblock; + } + + // The requested range bounds the walk whether or not the extent is known yet + if (!range.blockIsInside(blockbytes, data->m_blocknum)) { + finish_purge(contp, data); + return; + } + + // An open ended range has no such bound until some block reports an extent + if (data->m_contentlen < 0 && data->m_purge_miss_bound <= data->m_purge_misses) { + DEBUG_LOG("purge gave up after %d consecutive uncached block(s)", data->m_purge_misses); + finish_purge(contp, data); + return; + } + + data->m_blockstate = BlockState::Pending; + if (!request_block(contp, data)) { + note_purge_failure(data, TS_HTTP_STATUS_INTERNAL_SERVER_ERROR); + finish_purge(contp, data); + } +} + } // namespace +// Answer the client once every block has been walked. Nothing is written +// downstream before this, so one uncached block cannot leak a 404 to the client. +// A non-NONE status overrides the outcome of the walk. +void +finish_purge(TSCont const contp, Data *const data, TSHttpStatus const status) +{ + data->m_upstream.close(); + data->m_blockstate = BlockState::Done; + + // A block that could not be purged outranks the hits: 200 has to keep meaning that + // the object is gone, and 404 that it was never there + TSHttpStatus const reply = (TS_HTTP_STATUS_NONE != status) ? status : + (TS_HTTP_STATUS_NONE != data->m_purge_error) ? data->m_purge_error : + (0 < data->m_purge_hits) ? TS_HTTP_STATUS_OK : + TS_HTTP_STATUS_NOT_FOUND; + + DEBUG_LOG("purge removed %" PRId64 " block(s), answering %d", data->m_purge_hits, reply); + + if (!data->m_dnstream.isOpen()) { + shutdown(contp, data); + return; + } + + HdrMgr synthmgr; + if (!form_purge_response(synthmgr, reply)) { + ERROR_LOG("Failed forming the purge response"); + shutdown(contp, data); + return; + } + + HttpHeader const synth(synthmgr.m_buffer, synthmgr.m_lochdr); + int const hlen = synth.byteSize(); + + data->m_dnstream.setupVioWrite(contp, hlen); + TSHttpHdrPrint(synthmgr.m_buffer, synthmgr.m_lochdr, data->m_dnstream.m_write.m_iobuf); + data->m_bytessent = hlen; + TSVIOReenable(data->m_dnstream.m_write.m_vio); +} + +// A purge walks blocks instead of transferring them, so it runs its own machine +void +handle_purge_resp(TSCont const contp, TSEvent const event, Data *const data) +{ + switch (event) { + case TS_EVENT_VCONN_READ_READY: + case TS_EVENT_VCONN_READ_COMPLETE: { + if (!data->m_server_block_header_parsed) { + int64_t consumed = 0; + TSIOBufferReader const reader = data->m_upstream.m_read.m_reader; + TSVIO const input_vio = data->m_upstream.m_read.m_vio; + TSParseResult const res = data->m_resp_hdrmgr.populateFrom(data->m_http_parser, reader, TSHttpHdrParseResp, &consumed); + + TSVIONDoneSet(input_vio, TSVIONDoneGet(input_vio) + consumed); + + if (TS_PARSE_CONT == res) { + return; + } + + data->m_server_block_header_parsed = true; + note_purge_block_result(data); + } + + // No block PURGE response has a body worth reading, but drop whatever arrives + // so the upstream read cannot stall on a full buffer + data->m_upstream.m_read.drainReader(); + } break; + + case TS_EVENT_VCONN_EOS: { + if (!data->m_server_block_header_parsed) { + // No response at all is not evidence the block was absent + note_purge_failure(data, TS_HTTP_STATUS_BAD_GATEWAY); + DEBUG_LOG("Purge block %" PRId64 " ended with no response header", data->m_blocknum); + } + + // The next block cannot be requested while this one holds the upstream + data->m_upstream.close(); + advance_purge(contp, data); + } break; + + default: { + DEBUG_LOG("%p handle_purge_resp unhandled event: %s", data, TSHttpEventNameLookup(event)); + } break; + } +} + // this is called every time the server has data for us void handle_server_resp(TSCont contp, TSEvent event, Data *const data) { + // A purge never transfers content, so it gets its own state machine + if (data->is_purge()) { + handle_purge_resp(contp, event, data); + return; + } + switch (event) { case TS_EVENT_VCONN_READ_READY: { if (data->m_blockstate == BlockState::Passthru) { @@ -691,10 +883,7 @@ handle_server_resp(TSCont contp, TSEvent event, Data *const data) // isn't keeping up bool start_next_block = false; - if (data->m_method_type == TS_HTTP_METHOD_PURGE) { - // for PURGE requests, clients won't request more data (no body content) - start_next_block = true; - } else if (data->m_dnstream.m_write.isOpen()) { + if (data->m_dnstream.m_write.isOpen()) { // check throttle condition TSVIO const output_vio = data->m_dnstream.m_write.m_vio; int64_t const output_done = TSVIONDoneGet(output_vio); diff --git a/plugins/slice/server.h b/plugins/slice/server.h index c0d77e48032..667b854875e 100644 --- a/plugins/slice/server.h +++ b/plugins/slice/server.h @@ -35,3 +35,14 @@ */ void handle_server_resp(TSCont contp, TSEvent event, Data *const data); + +/** Walk the object's slice blocks issuing a PURGE for each. + * + * A purge transfers no content, so it runs a separate state machine: it walks + * every block whether or not each is cached, taking the object's extent from the + * ones it removes, and answers the client only once the walk is done. + */ +void handle_purge_resp(TSCont contp, TSEvent event, Data *const data); + +// Answer a purge: 200 if any block was removed, 404 if none was, or status if given +void finish_purge(TSCont contp, Data *const data, TSHttpStatus const status = TS_HTTP_STATUS_NONE); diff --git a/plugins/slice/util.cc b/plugins/slice/util.cc index 2f3a578629d..96b6060f8b2 100644 --- a/plugins/slice/util.cc +++ b/plugins/slice/util.cc @@ -138,7 +138,7 @@ request_block(TSCont contp, Data *const data) } header.removeKey(SLICE_CRR_HEADER.data(), SLICE_CRR_HEADER.size()); - if (data->m_config->m_prefetchcount > 0 && data->m_req_range.m_beg >= 0 && + if (!data->is_purge() && data->m_config->m_prefetchcount > 0 && data->m_req_range.m_beg >= 0 && data->m_blocknum == data->m_req_range.firstBlockFor(data->m_config->m_blockbytes)) { header.setKeyVal(SLICE_CRR_HEADER.data(), SLICE_CRR_HEADER.size(), SLICE_CRR_VAL.data(), SLICE_CRR_VAL.size()); } @@ -232,6 +232,12 @@ request_block(TSCont contp, Data *const data) bool reader_avail_more_than(TSIOBufferReader const reader, int64_t bytes) { + // A purge refused before opening an upstream has no reader, and TSIOBufferReaderStart + // does not tolerate a null one + if (nullptr == reader) { + return false; + } + TSIOBufferBlock block = TSIOBufferReaderStart(reader); if (nullptr == block) { diff --git a/src/proxy/http/HttpTransact.cc b/src/proxy/http/HttpTransact.cc index c6d1b274ca0..e4226ccf704 100644 --- a/src/proxy/http/HttpTransact.cc +++ b/src/proxy/http/HttpTransact.cc @@ -7472,6 +7472,25 @@ HttpTransact::delete_all_document_alternates_and_return(State *s, bool cache_hit build_response(s, &s->hdr_info.client_response, s->client_info.http_version, (cache_hit == true) ? HTTPStatus::OK : HTTPStatus::NOT_FOUND); + // Report what was removed, so a caller holding one piece of a larger resource + // can learn its extent without a second lookup. Not Content-Range itself: on + // a 200 that is meaningless per RFC 9110, and cache_range_requests reads the + // pair as a stored 206 being served as 200 and rewrites the status. + if (cache_hit == true && s->method == HTTP_WKSIDX_PURGE && s->cache_info.object_read != nullptr) { + // read by the slice plugin as PURGED_CONTENT_RANGE in plugins/slice/HttpHeader.h + static constexpr std::string_view PURGED_CONTENT_RANGE{"X-Purged-Content-Range"}; + HTTPHdr *const cached_response = s->cache_info.object_read->response_get(); + + if (cached_response != nullptr) { + auto value{cached_response->value_get(static_cast(MIME_FIELD_CONTENT_RANGE))}; + if (!value.empty()) { + s->hdr_info.client_response.value_set(PURGED_CONTENT_RANGE, value); + TxnDbg(dbg_ctl_http_trans, "PURGE reporting X-Purged-Content-Range: %.*s", static_cast(value.length()), + value.data()); + } + } + } + return true; } else { if (valid_max_forwards) { diff --git a/tests/gold_tests/pluginTest/slice/replay/slice_purge_gaps_client.replay.yaml b/tests/gold_tests/pluginTest/slice/replay/slice_purge_gaps_client.replay.yaml new file mode 100644 index 00000000000..18b768f37af --- /dev/null +++ b/tests/gold_tests/pluginTest/slice/replay/slice_purge_gaps_client.replay.yaml @@ -0,0 +1,895 @@ +# 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. + +# +# Client side of slice_purge_gaps.test.py. Each transaction is one phase, selected +# by uuid with the verifier-client --keys option; several phases share a run where +# they are independent. The uuid also picks which origin transaction the block +# requests slice derives from will match. +# +# Blocks are 10 bytes: block 0 is "a", 1 is "b", 2 is "c", 4 is "e". Every proxy +# runs --ref-relative, so a ranged GET touches only the blocks its range covers +# and a fill phase can leave a chosen block uncached. +# + +meta: + version: "1.0" + +sessions: +- transactions: + + - client-request: + method: GET + version: "1.1" + url: /hole + headers: + fields: + - [Host, slice] + - [Range, bytes=0-9] + - [uuid, hole-fill-0] + proxy-response: + status: 206 + headers: + fields: + - [Content-Range, {value: bytes 0-9/30, as: equal}] + content: + encoding: plain + data: 'aaaaaaaaaa' + verify: {as: equal} + + - client-request: + method: GET + version: "1.1" + url: /hole + headers: + fields: + - [Host, slice] + - [Range, bytes=20-29] + - [uuid, hole-fill-2] + proxy-response: + status: 206 + headers: + fields: + - [Content-Range, {value: bytes 20-29/30, as: equal}] + content: + encoding: plain + data: 'cccccccccc' + verify: {as: equal} + + - client-request: + method: PURGE + version: "1.1" + url: /hole + headers: + fields: + - [Host, slice] + - [uuid, hole-purge] + proxy-response: + status: 200 + headers: + fields: + - [Content-Length, {value: '0', as: equal}] + + - client-request: + method: GET + version: "1.1" + url: /hole + headers: + fields: + - [Host, slice] + - [Range, bytes=0-9] + - [uuid, hole-check-0] + proxy-response: + status: 206 + headers: + fields: + - [Content-Range, {value: bytes 0-9/30, as: equal}] + content: + encoding: plain + data: 'aaaaaaaaaa' + verify: {as: equal} + + - client-request: + method: GET + version: "1.1" + url: /hole + headers: + fields: + - [Host, slice] + - [Range, bytes=20-29] + - [uuid, hole-check-2] + proxy-response: + status: 206 + headers: + fields: + - [Content-Range, {value: bytes 20-29/30, as: equal}] + content: + encoding: plain + data: 'cccccccccc' + verify: {as: equal} + + - client-request: + method: GET + version: "1.1" + url: /nofirst + headers: + fields: + - [Host, slice] + - [Range, bytes=10-19] + - [uuid, nofirst-fill-1] + proxy-response: + status: 206 + headers: + fields: + - [Content-Range, {value: bytes 10-19/30, as: equal}] + content: + encoding: plain + data: 'bbbbbbbbbb' + verify: {as: equal} + + - client-request: + method: PURGE + version: "1.1" + url: /nofirst + headers: + fields: + - [Host, slice] + - [uuid, nofirst-purge] + proxy-response: + status: 200 + headers: + fields: + - [Content-Length, {value: '0', as: equal}] + + - client-request: + method: GET + version: "1.1" + url: /nofirst + headers: + fields: + - [Host, slice] + - [Range, bytes=10-19] + - [uuid, nofirst-check-1] + proxy-response: + status: 206 + headers: + fields: + - [Content-Range, {value: bytes 10-19/30, as: equal}] + content: + encoding: plain + data: 'bbbbbbbbbb' + verify: {as: equal} + + - client-request: + method: GET + version: "1.1" + url: /mixed + headers: + fields: + - [Host, slice] + - [Range, bytes=0-9] + - [uuid, mixed-fill-0] + proxy-response: + status: 206 + headers: + fields: + - [Content-Range, {value: bytes 0-9/30, as: equal}] + content: + encoding: plain + data: 'aaaaaaaaaa' + verify: {as: equal} + + - client-request: + method: GET + version: "1.1" + url: /mixed + headers: + fields: + - [Host, slice] + - [Range, bytes=10-19] + - [uuid, mixed-fill-1] + proxy-response: + status: 206 + headers: + fields: + - [Content-Range, {value: bytes 10-19/50, as: equal}] + content: + encoding: plain + data: 'bbbbbbbbbb' + verify: {as: equal} + + - client-request: + method: GET + version: "1.1" + url: /mixed + headers: + fields: + - [Host, slice] + - [Range, bytes=40-49] + - [uuid, mixed-fill-4] + proxy-response: + status: 206 + headers: + fields: + - [Content-Range, {value: bytes 40-49/50, as: equal}] + content: + encoding: plain + data: 'eeeeeeeeee' + verify: {as: equal} + + - client-request: + method: PURGE + version: "1.1" + url: /mixed + headers: + fields: + - [Host, slice] + - [uuid, mixed-purge] + proxy-response: + status: 200 + headers: + fields: + - [Content-Length, {value: '0', as: equal}] + + - client-request: + method: GET + version: "1.1" + url: /mixed + headers: + fields: + - [Host, slice] + - [Range, bytes=40-49] + - [uuid, mixed-check-4] + proxy-response: + status: 206 + headers: + fields: + - [Content-Range, {value: bytes 40-49/50, as: equal}] + content: + encoding: plain + data: 'eeeeeeeeee' + verify: {as: equal} + + - client-request: + method: GET + version: "1.1" + url: /mixed + headers: + fields: + - [Host, slice] + - [Range, bytes=0-9] + - [uuid, mixed-check-0] + proxy-response: + status: 206 + headers: + fields: + - [Content-Range, {value: bytes 0-9/30, as: equal}] + content: + encoding: plain + data: 'aaaaaaaaaa' + verify: {as: equal} + + - client-request: + method: GET + version: "1.1" + url: /mixed + headers: + fields: + - [Host, slice] + - [Range, bytes=10-19] + - [uuid, mixed-check-1] + proxy-response: + status: 206 + headers: + fields: + - [Content-Range, {value: bytes 10-19/50, as: equal}] + content: + encoding: plain + data: 'bbbbbbbbbb' + verify: {as: equal} + + - client-request: + method: GET + version: "1.1" + url: /ranged + headers: + fields: + - [Host, slice] + - [Range, bytes=0-9] + - [uuid, ranged-fill-0] + proxy-response: + status: 206 + headers: + fields: + - [Content-Range, {value: bytes 0-9/30, as: equal}] + content: + encoding: plain + data: 'aaaaaaaaaa' + verify: {as: equal} + + - client-request: + method: GET + version: "1.1" + url: /ranged + headers: + fields: + - [Host, slice] + - [Range, bytes=20-29] + - [uuid, ranged-fill-2] + proxy-response: + status: 206 + headers: + fields: + - [Content-Range, {value: bytes 20-29/30, as: equal}] + content: + encoding: plain + data: 'cccccccccc' + verify: {as: equal} + + - client-request: + method: PURGE + version: "1.1" + url: /ranged + headers: + fields: + - [Host, slice] + - [Range, bytes=0-29] + - [uuid, ranged-purge] + proxy-response: + status: 200 + headers: + fields: + - [Content-Length, {value: '0', as: equal}] + + - client-request: + method: GET + version: "1.1" + url: /ranged + headers: + fields: + - [Host, slice] + - [Range, bytes=0-9] + - [uuid, ranged-check-0] + proxy-response: + status: 206 + headers: + fields: + - [Content-Range, {value: bytes 0-9/30, as: equal}] + content: + encoding: plain + data: 'aaaaaaaaaa' + verify: {as: equal} + + - client-request: + method: GET + version: "1.1" + url: /ranged + headers: + fields: + - [Host, slice] + - [Range, bytes=20-29] + - [uuid, ranged-check-2] + proxy-response: + status: 206 + headers: + fields: + - [Content-Range, {value: bytes 20-29/30, as: equal}] + content: + encoding: plain + data: 'cccccccccc' + verify: {as: equal} + + - client-request: + method: GET + version: "1.1" + url: /openend + headers: + fields: + - [Host, slice] + - [Range, bytes=0-9] + - [uuid, openend-fill-0] + proxy-response: + status: 206 + headers: + fields: + - [Content-Range, {value: bytes 0-9/30, as: equal}] + content: + encoding: plain + data: 'aaaaaaaaaa' + verify: {as: equal} + + - client-request: + method: GET + version: "1.1" + url: /openend + headers: + fields: + - [Host, slice] + - [Range, bytes=20-29] + - [uuid, openend-fill-2] + proxy-response: + status: 206 + headers: + fields: + - [Content-Range, {value: bytes 20-29/30, as: equal}] + content: + encoding: plain + data: 'cccccccccc' + verify: {as: equal} + + - client-request: + method: PURGE + version: "1.1" + url: /openend + headers: + fields: + - [Host, slice] + - [Range, bytes=20-] + - [uuid, openend-purge] + proxy-response: + status: 200 + headers: + fields: + - [Content-Length, {value: '0', as: equal}] + + - client-request: + method: GET + version: "1.1" + url: /openend + headers: + fields: + - [Host, slice] + - [Range, bytes=20-29] + - [uuid, openend-check-2] + proxy-response: + status: 206 + headers: + fields: + - [Content-Range, {value: bytes 20-29/30, as: equal}] + content: + encoding: plain + data: 'cccccccccc' + verify: {as: equal} + + - client-request: + method: GET + version: "1.1" + url: /openend + headers: + fields: + - [Host, slice] + - [Range, bytes=0-9] + - [uuid, openend-check-0] + proxy-response: + status: 206 + headers: + fields: + - [Content-Range, {value: bytes 0-9/30, as: equal}] + content: + encoding: plain + data: 'aaaaaaaaaa' + verify: {as: equal} + + - client-request: + method: GET + version: "1.1" + url: /outside + headers: + fields: + - [Host, slice] + - [Range, bytes=10-19] + - [uuid, outside-fill-1] + proxy-response: + status: 206 + headers: + fields: + - [Content-Range, {value: bytes 10-19/30, as: equal}] + content: + encoding: plain + data: 'bbbbbbbbbb' + verify: {as: equal} + + - client-request: + method: PURGE + version: "1.1" + url: /outside + headers: + fields: + - [Host, slice] + - [Range, bytes=0-9] + - [uuid, outside-purge] + proxy-response: + status: 404 + + - client-request: + method: GET + version: "1.1" + url: /outside + headers: + fields: + - [Host, slice] + - [Range, bytes=10-19] + - [uuid, outside-check-1] + proxy-response: + status: 206 + headers: + fields: + - [Content-Range, {value: bytes 10-19/30, as: equal}] + content: + encoding: plain + data: 'bbbbbbbbbb' + verify: {as: equal} + + - client-request: + method: GET + version: "1.1" + url: /endbytes + headers: + fields: + - [Host, slice] + - [Range, bytes=0-9] + - [uuid, endbytes-fill-0] + proxy-response: + status: 206 + headers: + fields: + - [Content-Range, {value: bytes 0-9/30, as: equal}] + content: + encoding: plain + data: 'aaaaaaaaaa' + verify: {as: equal} + + - client-request: + method: GET + version: "1.1" + url: /endbytes + headers: + fields: + - [Host, slice] + - [Range, bytes=20-29] + - [uuid, endbytes-fill-2] + proxy-response: + status: 206 + headers: + fields: + - [Content-Range, {value: bytes 20-29/30, as: equal}] + content: + encoding: plain + data: 'cccccccccc' + verify: {as: equal} + + - client-request: + method: PURGE + version: "1.1" + url: /endbytes + headers: + fields: + - [Host, slice] + - [Range, bytes=-10] + - [uuid, endbytes-purge] + proxy-response: + status: 200 + headers: + fields: + - [Content-Length, {value: '0', as: equal}] + + - client-request: + method: GET + version: "1.1" + url: /endbytes + headers: + fields: + - [Host, slice] + - [Range, bytes=0-9] + - [uuid, endbytes-check-0] + proxy-response: + status: 206 + headers: + fields: + - [Content-Range, {value: bytes 0-9/30, as: equal}] + content: + encoding: plain + data: 'aaaaaaaaaa' + verify: {as: equal} + + - client-request: + method: GET + version: "1.1" + url: /endbytes + headers: + fields: + - [Host, slice] + - [Range, bytes=20-29] + - [uuid, endbytes-check-2] + proxy-response: + status: 206 + headers: + fields: + - [Content-Range, {value: bytes 20-29/30, as: equal}] + content: + encoding: plain + data: 'cccccccccc' + verify: {as: equal} + + - client-request: + method: GET + version: "1.1" + url: /sparse + headers: + fields: + - [Host, slice] + - [Range, bytes=40-49] + - [uuid, sparse-fill-4] + proxy-response: + status: 206 + headers: + fields: + - [Content-Range, {value: bytes 40-49/50, as: equal}] + content: + encoding: plain + data: 'eeeeeeeeee' + verify: {as: equal} + + - client-request: + method: PURGE + version: "1.1" + url: /sparse + headers: + fields: + - [Host, slice] + - [X-Slice-Purge-Probe, not-a-number] + - [uuid, sparse-purge-narrow] + proxy-response: + status: 404 + + - client-request: + method: GET + version: "1.1" + url: /sparse + headers: + fields: + - [Host, slice] + - [Range, bytes=40-49] + - [uuid, sparse-check-alive] + proxy-response: + status: 206 + headers: + fields: + - [Content-Range, {value: bytes 40-49/50, as: equal}] + content: + encoding: plain + data: 'eeeeeeeeee' + verify: {as: equal} + + - client-request: + method: PURGE + version: "1.1" + url: /sparse + headers: + fields: + - [Host, slice] + - [X-Slice-Purge-Probe, '8'] + - [uuid, sparse-purge-wide] + proxy-response: + status: 200 + headers: + fields: + - [Content-Length, {value: '0', as: equal}] + + - client-request: + method: GET + version: "1.1" + url: /sparse + headers: + fields: + - [Host, slice] + - [Range, bytes=40-49] + - [uuid, sparse-check-gone] + proxy-response: + status: 206 + headers: + fields: + - [Content-Range, {value: bytes 40-49/50, as: equal}] + content: + encoding: plain + data: 'eeeeeeeeee' + verify: {as: equal} + + - client-request: + method: GET + version: "1.1" + url: /badrange + headers: + fields: + - [Host, slice] + - [Range, bytes=0-9] + - [uuid, badrange-fill-0] + proxy-response: + status: 206 + headers: + fields: + - [Content-Range, {value: bytes 0-9/30, as: equal}] + content: + encoding: plain + data: 'aaaaaaaaaa' + verify: {as: equal} + + - client-request: + method: PURGE + version: "1.1" + url: /badrange + headers: + fields: + - [Host, slice] + - [Range, bytes=not-a-range] + - [uuid, badrange-purge] + proxy-response: + status: 400 + + - client-request: + method: GET + version: "1.1" + url: /badrange + headers: + fields: + - [Host, slice] + - [Range, bytes=0-9] + - [uuid, badrange-check-0] + proxy-response: + status: 206 + headers: + fields: + - [Content-Range, {value: bytes 0-9/30, as: equal}] + content: + encoding: plain + data: 'aaaaaaaaaa' + verify: {as: equal} + + - client-request: + method: GET + version: "1.1" + url: /failblock + headers: + fields: + - [Host, slice] + - [Range, bytes=0-9] + - [uuid, failblock-fill-0] + proxy-response: + status: 206 + headers: + fields: + - [Content-Range, {value: bytes 0-9/40, as: equal}] + content: + encoding: plain + data: 'aaaaaaaaaa' + verify: {as: equal} + + - client-request: + method: GET + version: "1.1" + url: /failblock + headers: + fields: + - [Host, slice] + - [Range, bytes=30-39] + - [uuid, failblock-fill-3] + proxy-response: + status: 206 + headers: + fields: + - [Content-Range, {value: bytes 30-39/40, as: equal}] + content: + encoding: plain + data: 'dddddddddd' + verify: {as: equal} + + - client-request: + method: PURGE + version: "1.1" + url: /failblock + headers: + fields: + - [Host, slice] + - [uuid, failblock-purge] + proxy-response: + status: 500 + + - client-request: + method: GET + version: "1.1" + url: /failblock + headers: + fields: + - [Host, slice] + - [Range, bytes=0-9] + - [uuid, failblock-check-0] + proxy-response: + status: 206 + headers: + fields: + - [Content-Range, {value: bytes 0-9/40, as: equal}] + content: + encoding: plain + data: 'aaaaaaaaaa' + verify: {as: equal} + + - client-request: + method: GET + version: "1.1" + url: /failblock + headers: + fields: + - [Host, slice] + - [Range, bytes=30-39] + - [uuid, failblock-check-3] + proxy-response: + status: 206 + headers: + fields: + - [Content-Range, {value: bytes 30-39/40, as: equal}] + content: + encoding: plain + data: 'dddddddddd' + verify: {as: equal} + + - client-request: + method: GET + version: "1.1" + url: /denied + headers: + fields: + - [Host, slice] + - [Range, bytes=0-9] + - [uuid, denied-fill-0] + proxy-response: + status: 206 + headers: + fields: + - [Content-Range, {value: bytes 0-9/30, as: equal}] + content: + encoding: plain + data: 'aaaaaaaaaa' + verify: {as: equal} + + - client-request: + method: PURGE + version: "1.1" + url: /denied + headers: + fields: + - [Host, slice] + - [uuid, denied-purge] + proxy-response: + status: 403 + + - client-request: + method: GET + version: "1.1" + url: /denied + headers: + fields: + - [Host, slice] + - [Range, bytes=0-9] + - [uuid, denied-check-0] + proxy-response: + status: 206 + headers: + fields: + - [Content-Range, {value: bytes 0-9/30, as: equal}] + content: + encoding: plain + data: 'aaaaaaaaaa' + verify: {as: equal} diff --git a/tests/gold_tests/pluginTest/slice/replay/slice_purge_gaps_server.replay.yaml b/tests/gold_tests/pluginTest/slice/replay/slice_purge_gaps_server.replay.yaml new file mode 100644 index 00000000000..b60525e8f85 --- /dev/null +++ b/tests/gold_tests/pluginTest/slice/replay/slice_purge_gaps_server.replay.yaml @@ -0,0 +1,586 @@ +# 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. + +# +# Origin side of slice_purge_gaps.test.py. +# +# Keyed on "{url}{field.range}{field.uuid}", so one transaction answers one block +# of one phase. Blocks are 10 bytes: block 0 is "a", 1 is "b", 2 is "c", 4 is "e". +# +# PURGE is answered by ATS and the plugin issues no other request kind, so neither +# appears here. +# +# A check phase for a block expected to SURVIVE its purge is deliberately absent: +# if such a block were wrongly purged, ATS would ask for an unregistered key and +# the client's own expectation would fail too. +# + +meta: + version: "1.0" + +sessions: +- transactions: + + - client-request: + method: GET + version: "1.1" + url: /hole + headers: + fields: + - [Host, slice] + - [Range, bytes=0-9] + - [uuid, hole-fill-0] + server-response: + status: 206 + reason: Partial Content + headers: + fields: + - [Content-Range, bytes 0-9/30] + - [Content-Length, '10'] + - [Cache-Control, 'public, max-age=86400'] + content: {encoding: plain, data: 'aaaaaaaaaa', size: 10} + + - client-request: + method: GET + version: "1.1" + url: /hole + headers: + fields: + - [Host, slice] + - [Range, bytes=20-29] + - [uuid, hole-fill-2] + server-response: + status: 206 + reason: Partial Content + headers: + fields: + - [Content-Range, bytes 20-29/30] + - [Content-Length, '10'] + - [Cache-Control, 'public, max-age=86400'] + content: {encoding: plain, data: 'cccccccccc', size: 10} + + - client-request: + method: GET + version: "1.1" + url: /hole + headers: + fields: + - [Host, slice] + - [Range, bytes=0-9] + - [uuid, hole-check-0] + server-response: + status: 206 + reason: Partial Content + headers: + fields: + - [Content-Range, bytes 0-9/30] + - [Content-Length, '10'] + - [Cache-Control, 'public, max-age=86400'] + content: {encoding: plain, data: 'aaaaaaaaaa', size: 10} + + - client-request: + method: GET + version: "1.1" + url: /hole + headers: + fields: + - [Host, slice] + - [Range, bytes=20-29] + - [uuid, hole-check-2] + server-response: + status: 206 + reason: Partial Content + headers: + fields: + - [Content-Range, bytes 20-29/30] + - [Content-Length, '10'] + - [Cache-Control, 'public, max-age=86400'] + content: {encoding: plain, data: 'cccccccccc', size: 10} + + - client-request: + method: GET + version: "1.1" + url: /nofirst + headers: + fields: + - [Host, slice] + - [Range, bytes=10-19] + - [uuid, nofirst-fill-1] + server-response: + status: 206 + reason: Partial Content + headers: + fields: + - [Content-Range, bytes 10-19/30] + - [Content-Length, '10'] + - [Cache-Control, 'public, max-age=86400'] + content: {encoding: plain, data: 'bbbbbbbbbb', size: 10} + + - client-request: + method: GET + version: "1.1" + url: /nofirst + headers: + fields: + - [Host, slice] + - [Range, bytes=10-19] + - [uuid, nofirst-check-1] + server-response: + status: 206 + reason: Partial Content + headers: + fields: + - [Content-Range, bytes 10-19/30] + - [Content-Length, '10'] + - [Cache-Control, 'public, max-age=86400'] + content: {encoding: plain, data: 'bbbbbbbbbb', size: 10} + + - client-request: + method: GET + version: "1.1" + url: /mixed + headers: + fields: + - [Host, slice] + - [Range, bytes=0-9] + - [uuid, mixed-fill-0] + server-response: + status: 206 + reason: Partial Content + headers: + fields: + - [Content-Range, bytes 0-9/30] + - [Content-Length, '10'] + - [Cache-Control, 'public, max-age=86400'] + content: {encoding: plain, data: 'aaaaaaaaaa', size: 10} + + - client-request: + method: GET + version: "1.1" + url: /mixed + headers: + fields: + - [Host, slice] + - [Range, bytes=10-19] + - [uuid, mixed-fill-1] + server-response: + status: 206 + reason: Partial Content + headers: + fields: + - [Content-Range, bytes 10-19/50] + - [Content-Length, '10'] + - [Cache-Control, 'public, max-age=86400'] + content: {encoding: plain, data: 'bbbbbbbbbb', size: 10} + + - client-request: + method: GET + version: "1.1" + url: /mixed + headers: + fields: + - [Host, slice] + - [Range, bytes=40-49] + - [uuid, mixed-fill-4] + server-response: + status: 206 + reason: Partial Content + headers: + fields: + - [Content-Range, bytes 40-49/50] + - [Content-Length, '10'] + - [Cache-Control, 'public, max-age=86400'] + content: {encoding: plain, data: 'eeeeeeeeee', size: 10} + + - client-request: + method: GET + version: "1.1" + url: /mixed + headers: + fields: + - [Host, slice] + - [Range, bytes=40-49] + - [uuid, mixed-check-4] + server-response: + status: 206 + reason: Partial Content + headers: + fields: + - [Content-Range, bytes 40-49/50] + - [Content-Length, '10'] + - [Cache-Control, 'public, max-age=86400'] + content: {encoding: plain, data: 'eeeeeeeeee', size: 10} + + - client-request: + method: GET + version: "1.1" + url: /ranged + headers: + fields: + - [Host, slice] + - [Range, bytes=0-9] + - [uuid, ranged-fill-0] + server-response: + status: 206 + reason: Partial Content + headers: + fields: + - [Content-Range, bytes 0-9/30] + - [Content-Length, '10'] + - [Cache-Control, 'public, max-age=86400'] + content: {encoding: plain, data: 'aaaaaaaaaa', size: 10} + + - client-request: + method: GET + version: "1.1" + url: /ranged + headers: + fields: + - [Host, slice] + - [Range, bytes=20-29] + - [uuid, ranged-fill-2] + server-response: + status: 206 + reason: Partial Content + headers: + fields: + - [Content-Range, bytes 20-29/30] + - [Content-Length, '10'] + - [Cache-Control, 'public, max-age=86400'] + content: {encoding: plain, data: 'cccccccccc', size: 10} + + - client-request: + method: GET + version: "1.1" + url: /ranged + headers: + fields: + - [Host, slice] + - [Range, bytes=0-9] + - [uuid, ranged-check-0] + server-response: + status: 206 + reason: Partial Content + headers: + fields: + - [Content-Range, bytes 0-9/30] + - [Content-Length, '10'] + - [Cache-Control, 'public, max-age=86400'] + content: {encoding: plain, data: 'aaaaaaaaaa', size: 10} + + - client-request: + method: GET + version: "1.1" + url: /ranged + headers: + fields: + - [Host, slice] + - [Range, bytes=20-29] + - [uuid, ranged-check-2] + server-response: + status: 206 + reason: Partial Content + headers: + fields: + - [Content-Range, bytes 20-29/30] + - [Content-Length, '10'] + - [Cache-Control, 'public, max-age=86400'] + content: {encoding: plain, data: 'cccccccccc', size: 10} + + - client-request: + method: GET + version: "1.1" + url: /openend + headers: + fields: + - [Host, slice] + - [Range, bytes=0-9] + - [uuid, openend-fill-0] + server-response: + status: 206 + reason: Partial Content + headers: + fields: + - [Content-Range, bytes 0-9/30] + - [Content-Length, '10'] + - [Cache-Control, 'public, max-age=86400'] + content: {encoding: plain, data: 'aaaaaaaaaa', size: 10} + + - client-request: + method: GET + version: "1.1" + url: /openend + headers: + fields: + - [Host, slice] + - [Range, bytes=20-29] + - [uuid, openend-fill-2] + server-response: + status: 206 + reason: Partial Content + headers: + fields: + - [Content-Range, bytes 20-29/30] + - [Content-Length, '10'] + - [Cache-Control, 'public, max-age=86400'] + content: {encoding: plain, data: 'cccccccccc', size: 10} + + - client-request: + method: GET + version: "1.1" + url: /openend + headers: + fields: + - [Host, slice] + - [Range, bytes=20-29] + - [uuid, openend-check-2] + server-response: + status: 206 + reason: Partial Content + headers: + fields: + - [Content-Range, bytes 20-29/30] + - [Content-Length, '10'] + - [Cache-Control, 'public, max-age=86400'] + content: {encoding: plain, data: 'cccccccccc', size: 10} + + - client-request: + method: GET + version: "1.1" + url: /outside + headers: + fields: + - [Host, slice] + - [Range, bytes=10-19] + - [uuid, outside-fill-1] + server-response: + status: 206 + reason: Partial Content + headers: + fields: + - [Content-Range, bytes 10-19/30] + - [Content-Length, '10'] + - [Cache-Control, 'public, max-age=86400'] + content: {encoding: plain, data: 'bbbbbbbbbb', size: 10} + + - client-request: + method: GET + version: "1.1" + url: /endbytes + headers: + fields: + - [Host, slice] + - [Range, bytes=0-9] + - [uuid, endbytes-fill-0] + server-response: + status: 206 + reason: Partial Content + headers: + fields: + - [Content-Range, bytes 0-9/30] + - [Content-Length, '10'] + - [Cache-Control, 'public, max-age=86400'] + content: {encoding: plain, data: 'aaaaaaaaaa', size: 10} + + - client-request: + method: GET + version: "1.1" + url: /endbytes + headers: + fields: + - [Host, slice] + - [Range, bytes=20-29] + - [uuid, endbytes-fill-2] + server-response: + status: 206 + reason: Partial Content + headers: + fields: + - [Content-Range, bytes 20-29/30] + - [Content-Length, '10'] + - [Cache-Control, 'public, max-age=86400'] + content: {encoding: plain, data: 'cccccccccc', size: 10} + + - client-request: + method: GET + version: "1.1" + url: /endbytes + headers: + fields: + - [Host, slice] + - [Range, bytes=0-9] + - [uuid, endbytes-check-0] + server-response: + status: 206 + reason: Partial Content + headers: + fields: + - [Content-Range, bytes 0-9/30] + - [Content-Length, '10'] + - [Cache-Control, 'public, max-age=86400'] + content: {encoding: plain, data: 'aaaaaaaaaa', size: 10} + + - client-request: + method: GET + version: "1.1" + url: /endbytes + headers: + fields: + - [Host, slice] + - [Range, bytes=20-29] + - [uuid, endbytes-check-2] + server-response: + status: 206 + reason: Partial Content + headers: + fields: + - [Content-Range, bytes 20-29/30] + - [Content-Length, '10'] + - [Cache-Control, 'public, max-age=86400'] + content: {encoding: plain, data: 'cccccccccc', size: 10} + + - client-request: + method: GET + version: "1.1" + url: /sparse + headers: + fields: + - [Host, slice] + - [Range, bytes=40-49] + - [uuid, sparse-fill-4] + server-response: + status: 206 + reason: Partial Content + headers: + fields: + - [Content-Range, bytes 40-49/50] + - [Content-Length, '10'] + - [Cache-Control, 'public, max-age=86400'] + content: {encoding: plain, data: 'eeeeeeeeee', size: 10} + + - client-request: + method: GET + version: "1.1" + url: /sparse + headers: + fields: + - [Host, slice] + - [Range, bytes=40-49] + - [uuid, sparse-check-gone] + server-response: + status: 206 + reason: Partial Content + headers: + fields: + - [Content-Range, bytes 40-49/50] + - [Content-Length, '10'] + - [Cache-Control, 'public, max-age=86400'] + content: {encoding: plain, data: 'eeeeeeeeee', size: 10} + + - client-request: + method: GET + version: "1.1" + url: /badrange + headers: + fields: + - [Host, slice] + - [Range, bytes=0-9] + - [uuid, badrange-fill-0] + server-response: + status: 206 + reason: Partial Content + headers: + fields: + - [Content-Range, bytes 0-9/30] + - [Content-Length, '10'] + - [Cache-Control, 'public, max-age=86400'] + content: {encoding: plain, data: 'aaaaaaaaaa', size: 10} + + - client-request: + method: GET + version: "1.1" + url: /failblock + headers: + fields: + - [Host, slice] + - [Range, bytes=0-9] + - [uuid, failblock-fill-0] + server-response: + status: 206 + reason: Partial Content + headers: + fields: + - [Content-Range, bytes 0-9/40] + - [Content-Length, '10'] + - [Cache-Control, 'public, max-age=86400'] + content: {encoding: plain, data: 'aaaaaaaaaa', size: 10} + + - client-request: + method: GET + version: "1.1" + url: /failblock + headers: + fields: + - [Host, slice] + - [Range, bytes=30-39] + - [uuid, failblock-fill-3] + server-response: + status: 206 + reason: Partial Content + headers: + fields: + - [Content-Range, bytes 30-39/40] + - [Content-Length, '10'] + - [Cache-Control, 'public, max-age=86400'] + content: {encoding: plain, data: 'dddddddddd', size: 10} + + - client-request: + method: GET + version: "1.1" + url: /failblock + headers: + fields: + - [Host, slice] + - [Range, bytes=0-9] + - [uuid, failblock-check-0] + server-response: + status: 206 + reason: Partial Content + headers: + fields: + - [Content-Range, bytes 0-9/40] + - [Content-Length, '10'] + - [Cache-Control, 'public, max-age=86400'] + content: {encoding: plain, data: 'aaaaaaaaaa', size: 10} + + - client-request: + method: GET + version: "1.1" + url: /denied + headers: + fields: + - [Host, slice] + - [Range, bytes=0-9] + - [uuid, denied-fill-0] + server-response: + status: 206 + reason: Partial Content + headers: + fields: + - [Content-Range, bytes 0-9/30] + - [Content-Length, '10'] + - [Cache-Control, 'public, max-age=86400'] + content: {encoding: plain, data: 'aaaaaaaaaa', size: 10} diff --git a/tests/gold_tests/pluginTest/slice/replay/slice_stale_generation_client.replay.yaml b/tests/gold_tests/pluginTest/slice/replay/slice_stale_generation_client.replay.yaml new file mode 100644 index 00000000000..b000ceda3b7 --- /dev/null +++ b/tests/gold_tests/pluginTest/slice/replay/slice_stale_generation_client.replay.yaml @@ -0,0 +1,206 @@ +# 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. + +# +# Client side of slice_stale_generation.test.py. Each transaction is one phase, +# selected with the verifier-client --keys option, and its uuid also selects +# which generation the origin serves for the block requests that slice derives +# from it. +# +# Generation 1 is 32 bytes of "a" with ETag "v1". Generation 2, which replaces +# it under the same URL once the cache is filled, is 64 bytes of "b" with ETag +# "v2". +# + +meta: + version: "1.0" + +sessions: +- transactions: + + # + # Fill the cache while the origin holds generation 1. + # + - client-request: + method: GET + version: "1.1" + url: /obj + headers: + fields: + - [Host, slice] + - [uuid, fill] + proxy-response: + status: 200 + headers: + fields: + - [Content-Length, {value: '32', as: equal}] + - [ETag, {value: '"v1"', as: equal}] + content: + encoding: plain + data: 'aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa' + verify: {as: equal} + + # + # The bug. Bytes 16-47 are entirely present in the current 64 byte object, but + # the cached reference block still reports the old 32 byte length, so the range + # is clipped to the stale object's end and served with the stale ETag as a + # fresh hit. Correct would be: 206, bytes 16-47/64, ETag "v2", 32 bytes of "b". + # + - client-request: + method: GET + version: "1.1" + url: /obj + headers: + fields: + - [Host, slice] + - [Range, bytes=16-47] + - [x-debug, x-cache] + - [uuid, clipped] + proxy-response: + status: 206 + headers: + fields: + - [Content-Range, {value: bytes 16-31/32, as: equal}] + - [Content-Length, {value: '16', as: equal}] + - [ETag, {value: '"v1"', as: equal}] + - [X-Cache, {value: hit-fresh, as: prefix}] + content: + encoding: plain + data: 'aaaaaaaaaaaaaaaa' + verify: {as: equal} + + # + # Worse: a range that starts past the stale length is refused outright, even + # though those bytes exist in the current object. Correct would be: 206, + # bytes 32-63/64. + # + - client-request: + method: GET + version: "1.1" + url: /obj + headers: + fields: + - [Host, slice] + - [Range, bytes=32-63] + - [uuid, unsatisfiable] + proxy-response: + status: 416 + headers: + fields: + - [Content-Range, {value: '*/32', as: equal}] + - [ETag, {as: absent}] + + # + # Control: a path first fetched after the object was replaced is served + # correctly, so the two phases above are measuring the stale cached generation + # and not a broken plugin or harness. + # + - client-request: + method: GET + version: "1.1" + url: /fresh + headers: + fields: + - [Host, slice] + - [Range, bytes=16-47] + - [x-debug, x-cache] + - [uuid, control] + proxy-response: + status: 206 + headers: + fields: + - [Content-Range, {value: bytes 16-47/64, as: equal}] + - [Content-Length, {value: '32', as: equal}] + - [ETag, {value: '"v2"', as: equal}] + content: + encoding: plain + data: 'bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb' + verify: {as: equal} + + # + # Cache an interior block of /mixed at generation 1, for + # SliceMixedGenerationTest. The reference block is cached with a one second + # lifetime and the interior block with a day, so only the reference block + # revalidates later. + # + - client-request: + method: GET + version: "1.1" + url: /mixed + headers: + fields: + - [Host, slice] + - [Range, bytes=16-31] + - [uuid, fill-interior] + proxy-response: + status: 206 + headers: + fields: + - [Content-Range, {value: bytes 16-31/32, as: equal}] + - [Content-Length, {value: '16', as: equal}] + - [ETag, {value: '"v1"', as: equal}] + content: + encoding: plain + data: 'aaaaaaaaaaaaaaaa' + verify: {as: equal} + + # + # The mixed generation failure. The reference block revalidates to generation + # 2 while the cached interior block is still generation 1, so slice advertises + # the current object correctly and then cannot deliver it: the interior block's + # Content-Range disagrees, the self heal refetches the interior and then the + # reference and gets the same blocks back, and the transaction is aborted with + # the response header already on the wire. The client is left holding a well + # formed 206 that promises 16 bytes and delivers none. + # + # This is the production symptom behind the block walk's "curl exit 18": + # a correct looking Content-Range of .../7031250004 followed by a body that + # stops early. + # + # The client is left with nothing parsable: slice aborts the transaction, and + # the response header it had already formed from the reference block never + # reaches the wire. There is deliberately no proxy-response node here, because + # no response arrives to verify. The test asserts the failure on the + # verifier-client's own output and in diags.log instead. + # + - client-request: + method: GET + version: "1.1" + url: /mixed + headers: + fields: + - [Host, slice] + - [Range, bytes=16-31] + - [x-debug, x-cache] + - [uuid, mixed] + + # A second child with a completely cold cache, pointed at the same parent. It + # never saw the previous generation, yet it fails identically, because the two + # blocks it fetches come from the parent and the parent is holding one of each. + # This is the incident's shape: the mixed set existed in exactly one place, the + # parent, and every child node inherited it. It also shows slice cannot evict: + # the earlier abort left the mixed pair on the parent untouched. + # + - client-request: + method: GET + version: "1.1" + url: /mixed + headers: + fields: + - [Host, slice] + - [Range, bytes=16-31] + - [x-debug, x-cache] + - [uuid, cold-child] diff --git a/tests/gold_tests/pluginTest/slice/replay/slice_stale_generation_server.replay.yaml b/tests/gold_tests/pluginTest/slice/replay/slice_stale_generation_server.replay.yaml new file mode 100644 index 00000000000..21d778a1f95 --- /dev/null +++ b/tests/gold_tests/pluginTest/slice/replay/slice_stale_generation_server.replay.yaml @@ -0,0 +1,286 @@ +# 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. + +# +# Origin side of slice_stale_generation.test.py. +# +# The server is keyed on "{url}{field.range}{field.uuid}", so each slice block +# request selects a transaction by the block's byte range and by the phase uuid +# that the client propagated through the plugin. The phase uuid is what replaces +# the origin object: the fill phase is answered with generation 1 (32 bytes, +# ETag "v1"), every later phase with generation 2 (64 bytes, ETag "v2"). +# +# For the two phases that read the already cached object there is deliberately +# only one transaction each, the reference block. Those exist so the origin +# really does hold the new object, but the test asserts the server never +# receives them: the cached blocks are fresh for a day, so nothing revalidates. +# If slice did go upstream it would either pick up generation 2, failing the +# client side assertions, or ask for an unregistered block and get a 404, +# failing the diags.log assertion. +# + +meta: + version: "1.0" + +sessions: +- transactions: + + # + # Phase fill: the origin holds generation 1, cached in 16 byte blocks with a + # day of freshness. + # + - client-request: + method: GET + version: "1.1" + url: /obj + headers: + fields: + - [Host, slice] + - [Range, bytes=0-15] + - [uuid, fill] + server-response: + status: 206 + reason: Partial Content + headers: + fields: + - [Content-Range, bytes 0-15/32] + - [Content-Length, '16'] + - [ETag, '"v1"'] + - [Last-Modified, 'Mon, 01 Jun 2026 00:00:00 GMT'] + - [Cache-Control, 'public, max-age=86400'] + - [Accept-Ranges, bytes] + content: {encoding: plain, data: 'aaaaaaaaaaaaaaaa', size: 16} + + - client-request: + method: GET + version: "1.1" + url: /obj + headers: + fields: + - [Host, slice] + - [Range, bytes=16-31] + - [uuid, fill] + server-response: + status: 206 + reason: Partial Content + headers: + fields: + - [Content-Range, bytes 16-31/32] + - [Content-Length, '16'] + - [ETag, '"v1"'] + - [Last-Modified, 'Mon, 01 Jun 2026 00:00:00 GMT'] + - [Cache-Control, 'public, max-age=86400'] + - [Accept-Ranges, bytes] + content: {encoding: plain, data: 'aaaaaaaaaaaaaaaa', size: 16} + + # + # The object is replaced here. Generation 2 is longer, with a new ETag and + # Last-Modified, under the same URL. The reference block is registered for + # each phase that reads the cached object, so the origin genuinely holds the + # new object, but the test asserts these keys are never requested. + # + - client-request: + method: GET + version: "1.1" + url: /obj + headers: + fields: + - [Host, slice] + - [Range, bytes=0-15] + - [uuid, clipped] + server-response: + status: 206 + reason: Partial Content + headers: + fields: + - [Content-Range, bytes 0-15/64] + - [Content-Length, '16'] + - [ETag, '"v2"'] + - [Last-Modified, 'Wed, 08 Jul 2026 23:54:41 GMT'] + - [Cache-Control, 'public, max-age=86400'] + - [Accept-Ranges, bytes] + content: {encoding: plain, data: 'bbbbbbbbbbbbbbbb', size: 16} + + - client-request: + method: GET + version: "1.1" + url: /obj + headers: + fields: + - [Host, slice] + - [Range, bytes=0-15] + - [uuid, unsatisfiable] + server-response: + status: 206 + reason: Partial Content + headers: + fields: + - [Content-Range, bytes 0-15/64] + - [Content-Length, '16'] + - [ETag, '"v2"'] + - [Last-Modified, 'Wed, 08 Jul 2026 23:54:41 GMT'] + - [Cache-Control, 'public, max-age=86400'] + - [Accept-Ranges, bytes] + content: {encoding: plain, data: 'bbbbbbbbbbbbbbbb', size: 16} + + # + # Phase control: a path first requested after the object was replaced, so + # nothing about it is cached and the client must see generation 2. + # + - client-request: + method: GET + version: "1.1" + url: /fresh + headers: + fields: + - [Host, slice] + - [Range, bytes=0-15] + - [uuid, control] + server-response: + status: 206 + reason: Partial Content + headers: + fields: + - [Content-Range, bytes 0-15/64] + - [Content-Length, '16'] + - [ETag, '"v2"'] + - [Last-Modified, 'Wed, 08 Jul 2026 23:54:41 GMT'] + - [Cache-Control, 'public, max-age=86400'] + - [Accept-Ranges, bytes] + content: {encoding: plain, data: 'bbbbbbbbbbbbbbbb', size: 16} + + - client-request: + method: GET + version: "1.1" + url: /fresh + headers: + fields: + - [Host, slice] + - [Range, bytes=16-31] + - [uuid, control] + server-response: + status: 206 + reason: Partial Content + headers: + fields: + - [Content-Range, bytes 16-31/64] + - [Content-Length, '16'] + - [ETag, '"v2"'] + - [Last-Modified, 'Wed, 08 Jul 2026 23:54:41 GMT'] + - [Cache-Control, 'public, max-age=86400'] + - [Accept-Ranges, bytes] + content: {encoding: plain, data: 'bbbbbbbbbbbbbbbb', size: 16} + + - client-request: + method: GET + version: "1.1" + url: /fresh + headers: + fields: + - [Host, slice] + - [Range, bytes=32-47] + - [uuid, control] + server-response: + status: 206 + reason: Partial Content + headers: + fields: + - [Content-Range, bytes 32-47/64] + - [Content-Length, '16'] + - [ETag, '"v2"'] + - [Last-Modified, 'Wed, 08 Jul 2026 23:54:41 GMT'] + - [Cache-Control, 'public, max-age=86400'] + - [Accept-Ranges, bytes] + content: {encoding: plain, data: 'bbbbbbbbbbbbbbbb', size: 16} + + # + # Phase fill-interior, used by SliceMixedGenerationTest: /mixed at generation + # 1. The reference block is given a one second freshness lifetime so that + # later only it revalidates. In production the reference block was evicted and + # refetched after the replacement while the interior blocks survived; a short + # lifetime reaches the same end state without depending on eviction. + # + - client-request: + method: GET + version: "1.1" + url: /mixed + headers: + fields: + - [Host, slice] + - [Range, bytes=0-15] + - [uuid, fill-interior] + server-response: + status: 206 + reason: Partial Content + headers: + fields: + - [Content-Range, bytes 0-15/32] + - [Content-Length, '16'] + - [ETag, '"v1"'] + - [Last-Modified, 'Mon, 01 Jun 2026 00:00:00 GMT'] + - [Cache-Control, 'public, max-age=1'] + - [Accept-Ranges, bytes] + content: {encoding: plain, data: 'aaaaaaaaaaaaaaaa', size: 16} + + - client-request: + method: GET + version: "1.1" + url: /mixed + headers: + fields: + - [Host, slice] + - [Range, bytes=16-31] + - [uuid, fill-interior] + server-response: + status: 206 + reason: Partial Content + headers: + fields: + - [Content-Range, bytes 16-31/32] + - [Content-Length, '16'] + - [ETag, '"v1"'] + - [Last-Modified, 'Mon, 01 Jun 2026 00:00:00 GMT'] + - [Cache-Control, 'public, max-age=86400'] + - [Accept-Ranges, bytes] + content: {encoding: plain, data: 'aaaaaaaaaaaaaaaa', size: 16} + + # + # Phase mixed: the object has been replaced. Only the reference block is + # stale, so only it revalidates, and it comes back as generation 2 while the + # cached interior block is still generation 1. That is the disagreement slice + # cannot heal. + # + - client-request: + method: GET + version: "1.1" + url: /mixed + headers: + fields: + - [Host, slice] + - [Range, bytes=0-15] + - [uuid, mixed] + server-response: + status: 206 + reason: Partial Content + headers: + fields: + - [Content-Range, bytes 0-15/64] + - [Content-Length, '16'] + - [ETag, '"v2"'] + - [Last-Modified, 'Wed, 08 Jul 2026 23:54:41 GMT'] + - [Cache-Control, 'public, max-age=86400'] + - [Accept-Ranges, bytes] + content: {encoding: plain, data: 'bbbbbbbbbbbbbbbb', size: 16} diff --git a/tests/gold_tests/pluginTest/slice/rules/purge_block_failure.conf b/tests/gold_tests/pluginTest/slice/rules/purge_block_failure.conf new file mode 100644 index 00000000000..1737d1dede4 --- /dev/null +++ b/tests/gold_tests/pluginTest/slice/rules/purge_block_failure.conf @@ -0,0 +1,41 @@ +# +# 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. +# + +# Make a block PURGE fail, which the core will not do on its own. +# +# slice re-issues every block as its own PURGE through this same remap rule, adding +# Range and its skip header on the way, so a rule can single out one block or all of +# them without ever matching the client's own PURGE. set-status fires at the remap +# pseudo-hook, before any cache lookup, so it applies whether or not the block is +# cached and leaves a cached one where it was. + +# One block mid-walk, behind a block that will be removed and in front of one that must +# not be. Gated on the method: this object's fill and check GETs are ranged too. +cond %{REMAP_PSEUDO_HOOK} [AND] +cond %{METHOD} =PURGE [AND] +cond %{CLIENT-URL:PATH} /failblock/ [AND] +cond %{CLIENT-HEADER:Range} ="bytes=10-19" + set-status 500 + +# Every block, as ip_allow.yaml refusing PURGE would. The walk stops at the first, so +# only block 0 is ever asked for, and nothing is removed at all. +cond %{REMAP_PSEUDO_HOOK} [AND] +cond %{METHOD} =PURGE [AND] +cond %{CLIENT-URL:PATH} /denied/ [AND] +cond %{CLIENT-HEADER:X-Slicer-Info} ="" [NOT] + set-status 403 diff --git a/tests/gold_tests/pluginTest/slice/slice_purge_gaps.test.py b/tests/gold_tests/pluginTest/slice/slice_purge_gaps.test.py new file mode 100644 index 00000000000..a8ff70c0461 --- /dev/null +++ b/tests/gold_tests/pluginTest/slice/slice_purge_gaps.test.py @@ -0,0 +1,346 @@ +"""Verify a PURGE traverses every slice block, not just the ones before a gap.""" + +# 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 = __doc__ + +Test.SkipUnless( + Condition.PluginExists('slice.so'), + Condition.PluginExists('cache_range_requests.so'), + Condition.PluginExists('header_rewrite.so'), +) +Test.ContinueOnFail = True + + +class SlicePurgeGapsTest: + """Verify a PURGE removes every block it was asked for. + + Slice turns one client PURGE into one PURGE per block. The walk used to stop + at the first block that was not cached, because it had no other end + condition: m_contentlen was only ever set from a 206's Content-Range, a PURGE + response carried none, and so m_req_range.blockIsInside() was true for every + block number. The 404 stood in for a length the plugin never learned. + + ATS now reports the removed object's extent as X-Purged-Content-Range, so the + walk learns where the object ends from the blocks it is already deleting, and + a 404 is merely noted and stepped over. The requested range bounds the walk + throughout; until some block reports an extent, an open ended one is bounded + only by a limit on consecutive misses. A block response that is neither 200 nor + 404 is a failure rather than an absence, and says nothing about the blocks + behind it, so the walk stops there and reports that status. + + Each object below exercises one thing, and each is purged exactly once, + because a purge consumes the state it is measured against. + + /hole blocks 0 and 2 cached, block 1 absent. A 404 mid-walk must not end + it, so block 2 goes too. + /nofirst only block 1 cached. The walk steps over block 0's 404, picks the + extent up from block 1, and the client must not be handed that 404. + /mixed blocks reporting a 30 byte and a 50 byte object, as happens when + the origin object is replaced in place. The walk must follow the + largest extent reported, not the first. + /ranged same gap as /hole, purged with a closed range. Already bounded, so + this isolates the 404 handling from the extent discovery. + /openend purged with "bytes=20-". The start is stated, so only block 2 may + go and block 0 must survive. + /outside only block 1 cached, purged for block 0 alone. No block is removed, + so no extent is ever reported and only the range can end the walk + before it reaches a block the client did not name. + /endbytes purged with "bytes=-10". A suffix range cannot know which block it + starts at, so it is widened to the whole object and every block + goes. + /sparse only block 4 cached, on a proxy whose miss bound is 2, so the + default walk cannot reach it. Covers the bound, its per-request + override, and the fallback when the override is malformed. + /badrange purged with an unparseable range, which must be refused rather + than silently applied to block 0. + /failblock blocks 0 and 3 cached, with a 500 injected for block 1's PURGE. Block + 0 is removed, the walk stops at block 1, block 3 is left alone, and + the client hears the 500 rather than the 200 block 0 earned. + /denied block 0 cached, with a 403 injected for every block PURGE, as + ip_allow refusing PURGE would. The walk stops at its first block, so + nothing is removed and the client must not be told 404. + + Whether a block was purged is measured on the origin, not on the response + body: the origin serves each check phase exactly what the matching fill phase + served, so a purged block and a surviving block are indistinguishable to the + client, and the only difference is whether the origin was asked again. + """ + + _client_replay: str = 'replay/slice_purge_gaps_client.replay.yaml' + _server_replay: str = 'replay/slice_purge_gaps_server.replay.yaml' + + # The core answers a block PURGE with nothing but 200 or 404, so a failure has to + # be injected to be tested at all. + _fail_rules: str = 'purge_block_failure.conf' + + _block_bytes: int = 10 + + # Low enough that the default walk cannot reach /sparse's block 4, which is + # what makes the per-request override observable. + _low_miss_bound: int = 2 + + # Keyed on the block range as well as the phase uuid, so one origin + # transaction answers one block of one phase. + _origin_key_format: str = '--format "{url}{field.range}{field.uuid}"' + + def __init__(self) -> None: + """Declare the origin and the two proxies.""" + self._started = False + self._configure_origin() + self._ts = self._make_ts('ts', fail_rules=True) + self._ts_bound = self._make_ts('ts-bound', miss_bound=self._low_miss_bound) + + self._ts.Disk.traffic_out.Content = Testers.ContainsExpression( + 'Purge suffix range widened to the whole object', + 'A suffix range purge should be widened rather than guessing at its start.') + + self._ts_bound.Disk.traffic_out.Content = Testers.ContainsExpression( + f'gave up after {self._low_miss_bound} consecutive uncached block', + 'The walk should stop at its configured miss bound rather than scanning the whole range.') + self._ts_bound.Disk.diags_log.Content = Testers.ContainsExpression( + 'Ignoring invalid X-Slice-Purge-Probe', 'A malformed override should be rejected, not acted on.') + + # A purge issues nothing but block PURGEs. request_block logs every request + # header it builds at debug, so an only-if-cached here would mean a + # read-only length probe had been reintroduced. + for ts in (self._ts, self._ts_bound): + ts.Disk.traffic_out.Content += Testers.ExcludesExpression( + 'only-if-cached', 'A purge should not issue a read-only length probe.') + + def _configure_origin(self) -> None: + """Configure the origin.""" + self._origin = Test.MakeVerifierServerProcess('origin', self._server_replay, other_args=self._origin_key_format) + + # ATS answers PURGE itself and the plugin issues no other request kind, so + # neither may ever be seen upstream. + self._origin.Streams.stdout += Testers.ExcludesExpression( + 'PURGE', 'A PURGE should be answered by ATS and never forwarded to the origin.') + self._origin.Streams.stdout += Testers.ExcludesExpression('HEAD /', 'A purge should never issue a HEAD upstream.') + + def _make_ts(self, label: str, miss_bound: int = None, fail_rules: bool = False) -> 'Process': + """Create a proxy that slices in front of cache_range_requests. + + --ref-relative keeps a ranged GET from dragging block 0 in as a reference + block, which is what lets a fill phase leave a chosen block uncached. + + :param label: process name suffix. + :param miss_bound: --purge-probe-blocks value, or None for the default. + :param fail_rules: load the header_rewrite rules that fail a block PURGE. + """ + ts = Test.MakeATSProcess(label, enable_cache=True) + + rules = '' + if fail_rules: + ts.Setup.CopyAs(f'rules/{self._fail_rules}', Test.RunDirectory) + rules = f' @plugin=header_rewrite.so @pparam={Test.RunDirectory}/{self._fail_rules}' + + bound = '' if miss_bound is None else f' @pparam=--purge-probe-blocks={miss_bound}' + ts.Disk.remap_config.AddLine( + f'map http://slice/ http://127.0.0.1:{self._origin.Variables.http_port}/' + f'{rules} @plugin=slice.so @pparam=--blockbytes-test={self._block_bytes} @pparam=--ref-relative{bound}' + ' @plugin=cache_range_requests.so') + ts.Disk.records_config.update( + { + 'proxy.config.diags.debug.enabled': 1, + 'proxy.config.diags.debug.tags': 'slice|cache_range_requests', + }) + return ts + + def _run(self, summary: str, phases: str, ts: 'Process' = None) -> None: + """Add a TestRun replaying one or more phases, in replay file order. + + :param summary: TestRun description. + :param phases: space separated verifier-client keys. + :param ts: proxy to replay against, defaulting to the ordinary one. + """ + ts = self._ts if ts is None else ts + tr = Test.AddTestRun(summary) + if not self._started: + tr.Processes.Default.StartBefore(self._origin) + tr.Processes.Default.StartBefore(self._ts) + tr.Processes.Default.StartBefore(self._ts_bound) + self._started = True + tr.AddVerifierClientProcess( + f"client-{phases.replace(' ', '-')}", self._client_replay, http_ports=[ts.Variables.port], keys=phases) + tr.StillRunningAfter = ts + + def _origin_saw(self, phase: str, block: str, why: str) -> None: + """Assert the origin was asked for a block under a given phase.""" + self._origin.Streams.stdout += Testers.ContainsExpression(f'request with key /{block}{phase}', why) + + def _fill(self, summary: str, url: str, blocks: list, ts: 'Process' = None) -> None: + """Cache the given blocks of an object, and prove each fill happened. + + The fill assertions carry weight: a check phase only observes that the + origin was asked, which is equally true of a block that was purged and one + that was never cached at all. Asserting the fill reached the origin is what + makes the later check mean "removed" rather than merely "absent". + """ + self._run(summary, ' '.join(f'{url}-fill-{block}' for block in blocks), ts) + for block in blocks: + self._origin_saw( + f'{url}-fill-{block}', f'{url}bytes={block * 10}-{block * 10 + 9}', + f'Block {block} of /{url} should have been fetched and cached.') + + def _purged(self, phase: str, block: str, why: str) -> None: + """Assert a phase's block request reached the origin, so it was purged.""" + self._origin_saw(phase, block, why) + + def _survived(self, phase: str, block: str, why: str) -> None: + """Assert a phase's block request never reached the origin, so it survived. + + The origin has no transaction registered for such a phase either, so a + wrongly purged block fails the client's own expectation as well. + """ + self._origin.Streams.stdout += Testers.ExcludesExpression(f'request with key /{block}{phase}', why) + + def _gap_mid_walk(self) -> None: + """A 404 in the middle of the walk must not end it.""" + self._fill('Cache blocks 0 and 2 of /hole, leaving block 1 uncached', 'hole', [0, 2]) + self._run('PURGE the whole /hole object', 'hole-purge') + self._run('Both cached blocks of /hole were purged', 'hole-check-0 hole-check-2') + self._purged('hole-check-0', 'holebytes=0-9', 'Block 0 is in front of the gap, so it should be purged.') + self._purged('hole-check-2', 'holebytes=20-29', 'A PURGE should traverse blocks behind an uncached one.') + + def _uncached_first_block(self) -> None: + """A miss on the first block must not stop the purge before it starts.""" + self._fill('Cache only block 1 of /nofirst', 'nofirst', [1]) + self._run('PURGE /nofirst, whose block 0 is not cached', 'nofirst-purge') + self._run('Block 1 of /nofirst was purged', 'nofirst-check-1') + self._purged('nofirst-check-1', 'nofirstbytes=10-19', 'An uncached first block should not stop the purge.') + + def _largest_extent_wins(self) -> None: + """A block reporting a longer object widens the walk.""" + self._fill('Cache blocks 0, 1 and 4 of /mixed, disagreeing about its length', 'mixed', [0, 1, 4]) + self._run('PURGE /mixed', 'mixed-purge') + self._run('Block 4 of /mixed was purged, so the walk took the longer extent', 'mixed-check-4') + self._purged('mixed-check-4', 'mixedbytes=40-49', 'The walk should follow the largest extent any block reports.') + + def _closed_range(self) -> None: + """A closed range bounds the walk itself, isolating the 404 step-over.""" + self._fill('Cache blocks 0 and 2 of /ranged, leaving block 1 uncached', 'ranged', [0, 2]) + self._run('PURGE /ranged with a closed range spanning the whole object', 'ranged-purge') + self._run('Both cached blocks of /ranged were purged', 'ranged-check-0 ranged-check-2') + self._purged('ranged-check-0', 'rangedbytes=0-9', 'A closed range purge should remove the blocks it covers.') + self._purged('ranged-check-2', 'rangedbytes=20-29', 'A 404 should not end a closed range purge either.') + + def _open_ended_range(self) -> None: + """A "bytes=N-" purge states its start, so it purges only what it names.""" + self._fill('Cache blocks 0 and 2 of /openend', 'openend', [0, 2]) + self._run('PURGE /openend from byte 20 on', 'openend-purge') + self._run('Block 2 of /openend went and block 0 stayed', 'openend-check-2 openend-check-0') + self._purged('openend-check-2', 'openendbytes=20-29', 'The block covering the range should be purged.') + self._survived('openend-check-0', 'openendbytes=0-9', 'A purge should not remove blocks before its stated start.') + + def _range_bounds_the_walk(self) -> None: + """A range ends the walk even before any block has reported an extent. + + /outside has only block 1 cached and is purged for block 0 alone. Nothing + is ever removed, so no block reports an extent, and the miss bound would + otherwise carry the walk past the end of the named range and into a block + the client never asked to remove. + """ + self._fill('Cache only block 1 of /outside', 'outside', [1]) + self._run('PURGE /outside for block 0 only, which is not cached', 'outside-purge') + self._run('Block 1 of /outside survived a purge that did not name it', 'outside-check-1') + self._survived( + 'outside-check-1', 'outsidebytes=10-19', 'A purge should stop at the end of its range, not at the miss bound.') + + def _suffix_range(self) -> None: + """A "bytes=-N" purge is widened to the whole object.""" + self._fill('Cache blocks 0 and 2 of /endbytes', 'endbytes', [0, 2]) + self._run('PURGE the last 10 bytes of /endbytes', 'endbytes-purge') + self._run('Every cached block of /endbytes went, not just the named tail', 'endbytes-check-0 endbytes-check-2') + self._purged('endbytes-check-2', 'endbytesbytes=20-29', 'The block covering the suffix range must be purged.') + self._purged( + 'endbytes-check-0', 'endbytesbytes=0-9', + 'A widened suffix purge removes the whole object, which is a superset of what was named.') + + def _miss_bound_and_override(self) -> None: + """The miss bound stops a walk that has found nothing, and is overridable. + + /sparse has only block 4 of five cached, out of reach of this proxy's + configured bound of two. Nothing about the remap changes between the two + purges below; only the request header does. + """ + ts = self._ts_bound + self._fill('Cache only block 4 of /sparse, out of reach of the configured bound', 'sparse', [4], ts) + + self._run('A purge with a malformed override falls back to the configured bound', 'sparse-purge-narrow', ts) + self._run('Block 4 of /sparse survived the too-narrow purge', 'sparse-check-alive', ts) + self._survived('sparse-check-alive', 'sparsebytes=40-49', 'A walk that gave up before block 4 should not have purged it.') + + self._run('PURGE /sparse with an override wide enough to reach block 4', 'sparse-purge-wide', ts) + self._run('Block 4 of /sparse was purged once the bound reached it', 'sparse-check-gone', ts) + self._purged('sparse-check-gone', 'sparsebytes=40-49', 'A request supplied bound should let the walk reach block 4.') + + def _unparseable_range(self) -> None: + """A purge whose range cannot be parsed is refused, not guessed at. + + An unparseable range leaves the plugin's range covering block 0 only, so + walking it would delete the head of the object and report success. A purge + is destructive, so it is rejected instead. + """ + self._fill('Cache block 0 of /badrange', 'badrange', [0]) + self._run('A PURGE with an unparseable range is refused', 'badrange-purge') + self._run('Block 0 of /badrange survived the refused purge', 'badrange-check-0') + self._survived('badrange-check-0', 'badrangebytes=0-9', 'A refused purge must not have removed anything.') + self._ts.Disk.diags_log.Content = Testers.ContainsExpression( + 'Refusing PURGE with an unparseable range', 'The refusal should be visible in the error log.') + + def _block_failure(self) -> None: + """A block that could not be purged is not a block that was absent. + + Only a 404 says the block was not cached. Any other status says the walk could + not tell, and says nothing about the blocks behind it either, so it stops there + and the client hears that status rather than the 200 the earlier blocks earned. + Both failures are injected with header_rewrite, since the core answers a block + PURGE with nothing but 200 or 404 on its own. + """ + self._fill('Cache blocks 0 and 3 of /failblock', 'failblock', [0, 3]) + self._run('PURGE /failblock, whose block 1 answers 500', 'failblock-purge') + self._run('/failblock was purged up to the failing block only', 'failblock-check-0 failblock-check-3') + self._purged('failblock-check-0', 'failblockbytes=0-9', 'A block removed before the failure should stay removed.') + self._survived( + 'failblock-check-3', 'failblockbytes=30-39', + 'The walk should stop at the failing block, leaving what is behind it cached.') + self._ts.Disk.diags_log.Content += Testers.ContainsExpression( + 'Purge of block 1 failed', 'The block that ended the walk should be logged.') + + self._fill('Cache block 0 of /denied', 'denied', [0]) + self._run('PURGE /denied, whose every block answers 403', 'denied-purge') + self._run('Block 0 of /denied survived the refused purge', 'denied-check-0') + self._survived('denied-check-0', 'deniedbytes=0-9', 'A purge refused at its first block must not remove anything.') + self._ts.Disk.diags_log.Content += Testers.ContainsExpression( + 'Purge of block 0 failed', 'A purge refused outright should be logged rather than reported as a 404.') + + def run(self) -> None: + """Configure the test runs.""" + self._gap_mid_walk() + self._uncached_first_block() + self._largest_extent_wins() + self._closed_range() + self._open_ended_range() + self._range_bounds_the_walk() + self._suffix_range() + self._unparseable_range() + self._miss_bound_and_override() + self._block_failure() + + +SlicePurgeGapsTest().run() diff --git a/tests/gold_tests/pluginTest/slice/slice_stale_generation.test.py b/tests/gold_tests/pluginTest/slice/slice_stale_generation.test.py new file mode 100644 index 00000000000..05381279391 --- /dev/null +++ b/tests/gold_tests/pluginTest/slice/slice_stale_generation.test.py @@ -0,0 +1,327 @@ +"""Verify slice serves a stale object identity after the origin object changes.""" + +# 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 = __doc__ + +Test.SkipUnless( + Condition.PluginExists('slice.so'), + Condition.PluginExists('cache_range_requests.so'), + Condition.PluginExists('xdebug.so'), +) +Test.ContinueOnFail = False + + +class SliceHierarchyTest: + """Build the child/parent hierarchy the incident ran on. + + Both tiers load slice with the same block size, and both put + cache_range_requests behind it, as the affected property does. + + The parent only behaves as a slicing proxy for requests that arrive without + slice's skip header. The child stamps that header onto every block request it + issues (client.cc:66), so slice returns immediately on the parent + (slice.cc:48) and a child block request is handled there by + cache_range_requests alone: look up this exact Range, forward it on a miss, + store whatever 206 comes back. The parent therefore holds N independent + per-Range objects with no shared identity, and cannot notice, refuse or + reconcile a version mix. That is where the mixed set lived in the incident. + + A client hitting the parent directly is a different path: the parent does + slice that request, forms its own reference block and clamps against it. + """ + + _server_replay: str = 'replay/slice_stale_generation_server.replay.yaml' + _client_replay: str = 'replay/slice_stale_generation_client.replay.yaml' + + _block_bytes: int = 16 + + _origin_key_format: str = '--format "{url}{field.range}{field.uuid}"' + + def __init__(self, name: str) -> None: + """Declare the origin, the parent and the child. + + :param name: suffix distinguishing this hierarchy's processes. + """ + self._name = name + self._configure_dns() + self._configure_origin() + self._configure_parent() + self._configure_child() + + def _configure_dns(self) -> None: + """Configure a DNS server so neither tier consults resolv.conf.""" + self._dns = Test.MakeDNServer(f'dns-{self._name}', default='127.0.0.1') + + def _configure_origin(self) -> None: + """Configure the origin. + + The server is keyed on the block's byte range and on the phase uuid that + slice propagates from the client request, so one replay file answers + every block request of every phase and can replace the object between + phases without holding any state. + """ + self._origin = Test.MakeVerifierServerProcess( + f'origin-{self._name}', self._server_replay, other_args=self._origin_key_format) + + def _slice_remap(self, source: str, upstream: str) -> str: + """Build a remap rule carrying slice in front of cache_range_requests.""" + return ( + f'map {source} {upstream}' + f' @plugin=slice.so @pparam=--blockbytes-test={self._block_bytes}' + ' @plugin=cache_range_requests.so') + + def _records(self, ts: 'Process', debug: int) -> None: + """Apply the records.yaml settings common to both tiers.""" + ts.Disk.records_config.update( + { + 'proxy.config.diags.debug.enabled': debug, + 'proxy.config.diags.debug.tags': 'slice|cache_range_requests', + 'proxy.config.dns.nameservers': f'127.0.0.1:{self._dns.Variables.Port}', + 'proxy.config.dns.resolv_conf': 'NULL', + 'proxy.config.http.parent_proxy.self_detect': 0, + }) + + def _configure_parent(self) -> None: + """Configure the parent, which the child's block requests reach.""" + self._parent = Test.MakeATSProcess(f'ts-parent-{self._name}') + self._parent.Disk.remap_config.AddLine( + self._slice_remap('http://origin.test/', f'http://127.0.0.1:{self._origin.Variables.http_port}/')) + self._parent.Disk.plugin_config.AddLine('xdebug.so --enable=x-cache') + self._records(self._parent, debug=1) + + # slice is loaded on the parent, but every block request the child sends + # carries the skip header, so slice returns immediately and the request + # is handled by cache_range_requests alone. Plugin debug output lands in + # traffic.out, not diags.log. + self._parent.Disk.traffic_out.Content = Testers.ContainsExpression( + 'slice passing GET or HEAD request through to next plugin', + "The child's block requests should bypass the parent's slice.") + self._parent.Disk.traffic_out.Content += Testers.ExcludesExpression( + 'slice accepting and slicing', 'The parent should never slice a child block request.') + + def _make_child(self, label: str) -> 'Process': + """Create a child tier that slices and forwards to the parent.""" + ts = Test.MakeATSProcess(f'ts-{label}-{self._name}') + ts.Disk.remap_config.AddLine(self._slice_remap('http://slice/', 'http://origin.test/')) + ts.Disk.parent_config.AddLine( + f'dest_domain=. parent=127.0.0.1:{self._parent.Variables.port}' + ' round_robin=consistent_hash go_direct=false') + ts.Disk.plugin_config.AddLine('xdebug.so --enable=x-cache') + self._records(ts, debug=1) + return ts + + def _configure_child(self) -> None: + """Configure the child, which slices and forwards to the parent.""" + self._child = self._make_child('child') + + def _start_hierarchy(self, tr: 'TestRun') -> None: + """Bring up origin, parent and child for the first TestRun.""" + tr.Processes.Default.StartBefore(self._dns) + tr.Processes.Default.StartBefore(self._origin) + tr.Processes.Default.StartBefore(self._parent) + tr.Processes.Default.StartBefore(self._child) + + def _replay_phase(self, tr: 'TestRun', phase: str, ts: 'Process' = None) -> 'Process': + """Replay the client transaction for one phase against a child.""" + ts = self._child if ts is None else ts + return tr.AddVerifierClientProcess( + f'client-{phase}-{self._name}', self._client_replay, http_ports=[ts.Variables.port], keys=phase) + + def _still_running(self, tr: 'TestRun') -> None: + """Assert both tiers survive the TestRun.""" + tr.StillRunningAfter = self._child + tr.StillRunningAfter = self._parent + + +class SliceStaleGenerationTest(SliceHierarchyTest): + """Verify a cached reference block pins a stale object identity. + + The plugin takes the whole object length from the reference block's + Content-Range and clips the client range to it, so the cached reference + block, not the origin, defines the object's identity for every request:: + + server.cc handleFirstServerHeader: + data->m_contentlen = blockcr.m_length; + data->m_req_range.m_end = std::min(data->m_contentlen, data->m_req_range.m_end); + + Replacing the object under the same URL therefore forks every cache into one + that filled before the replacement and one that filled after, for as long as + the reference block stays fresh. On the stale side, ranges that exist in the + current object are answered against the stale length with the stale ETag: + clipped short, or refused with a 416. Neither path logs a block stitch error, + because handleNextServerHeader only complains when blocks disagree with each + other and here they are uniformly stale. + + Modelled on an incident where a versioned, year-cacheable object was replaced + in place. Two edges seven hours apart on either side of the replacement served + object lengths 4043309056 and 7031250004 for the same URL, the stale one + clipping a 64 MiB range request down to 16 MiB. + """ + + # The reference block the origin holds at the new generation for each phase + # that reads the cached object. The test asserts the origin never gets these. + _unreachable_keys = ('/objbytes=0-15clipped', '/objbytes=0-15unsatisfiable') + + def __init__(self) -> None: + """Declare the hierarchy and its assertions.""" + super().__init__('stale') + + for key in self._unreachable_keys: + self._origin.Streams.stdout += Testers.ExcludesExpression( + f'request with key {key}', 'The stale object should never be refetched after the origin object changed.') + + # Debug is enabled on the child, so Config::canLogError cannot suppress a + # block stitch error by pacing. The stale response is served with none. + self._child.Disk.diags_log.Content = Testers.ExcludesExpression( + 'logSliceError', 'The stale response should be served with no block stitch error.') + self._child.Disk.diags_log.Content += Testers.ExcludesExpression( + 'Mismatch/Bad block Content-Range', 'The stale blocks agree with each other, so nothing should mismatch.') + + def _fill_cache(self) -> None: + """Cache the whole object while the origin holds the first generation.""" + tr = Test.AddTestRun('Cache the object while the origin holds the first generation') + self._start_hierarchy(tr) + self._replay_phase(tr, 'fill') + self._still_running(tr) + + def _verify_clipped_range(self) -> None: + """A range inside the current object is clipped to the stale length.""" + tr = Test.AddTestRun('A range inside the current object is clipped to the stale length') + self._replay_phase(tr, 'clipped') + self._still_running(tr) + + def _verify_unsatisfiable_range(self) -> None: + """A range past the stale length is refused with a 416.""" + tr = Test.AddTestRun('A range past the stale length is refused with a 416') + self._replay_phase(tr, 'unsatisfiable') + self._still_running(tr) + + def _verify_uncached_object(self) -> None: + """An object first fetched after the replacement is served correctly.""" + tr = Test.AddTestRun('An object first fetched after the replacement is served correctly') + self._replay_phase(tr, 'control') + self._still_running(tr) + + def run(self) -> None: + """Configure the test runs.""" + self._fill_cache() + self._verify_clipped_range() + self._verify_unsatisfiable_range() + self._verify_uncached_object() + + +class SliceMixedGenerationTest(SliceHierarchyTest): + """Verify the parent stores a version mix and the child cannot recover. + + The other failure mode from the same origin object replacement, and the one + the parent's per-Range cache makes possible. Only the reference block is + refetched after the replacement, so the parent ends up holding two blocks of + one object at two different generations, both fresh, with nothing to relate + them. It serves each on request without complaint. + + The child is the only tier that compares blocks, and only against its own + reference block. It forms the client response header from the reference block, + which is correct for the current object, and only then discovers that the + interior block belongs to the previous one:: + + server.cc handleNextServerHeader: + if (!blockcr.isValid() || blockcr.m_length != data->m_contentlen) { + logSliceError("Mismatch/Bad block Content-Range", data, header); + + The self heal refetches the reference block, which is already the newest one + the parent holds, so the same block comes back and the interior block still + disagrees with it. The second mismatch is where slice gives up. + + The upstream is aborted. Slice can abort but cannot evict, so the mixed pair + on the parent survives. The final TestRun proves where the damage actually + lives: a second child with a completely cold cache, pointed at the same + parent, fails identically. It never saw the previous generation; it simply + inherits the mix from the one place that holds it. That is the incident's + shape, where all 105 blocks hashed to a single parent and every one of the 32 + child nodes served the same broken object. + """ + + # The reference block is cached with a one second lifetime, so let it expire. + _expiry_wait: int = 2 + + def __init__(self) -> None: + """Declare the hierarchy and its assertions.""" + super().__init__('mixed') + self._cold_child = self._make_child('cold-child') + + # Unlike the stale case, the child does report this one: first the interior + # block against the reference block, then the refetch against the interior. + self._child.Disk.diags_log.Content = Testers.ContainsExpression( + 'Mismatch/Bad block Content-Range.*blk_range="16-31".*etag_got="%22v1%22"', + 'The interior block should disagree with the reference block.') + self._child.Disk.diags_log.Content += Testers.ContainsExpression( + 'Mismatch/Bad block Content-Range.*blk_range="0-15".*etag_got="%22v2%22"', + 'The refetched reference block should disagree in turn, leaving no way out.') + + # The parent never compares blocks, so it never complains about the mix + # it is storing and serving to the child. + self._parent.Disk.diags_log.Content += Testers.ExcludesExpression( + 'logSliceError', 'The parent should not notice the version mix it holds.') + self._parent.Disk.diags_log.Content += Testers.ExcludesExpression( + 'Mismatch/Bad block Content-Range', 'The parent should not compare blocks at all.') + + def _fill_interior_block(self) -> None: + """Cache an interior block at the first generation, on both tiers.""" + tr = Test.AddTestRun('Cache an interior block at the first generation') + self._start_hierarchy(tr) + self._replay_phase(tr, 'fill-interior') + self._still_running(tr) + + def _verify_aborted_response(self) -> None: + """The reference block moves on and the transaction cannot be completed.""" + tr = Test.AddTestRun('A mixed generation object cannot be delivered and the request fails') + client = self._replay_phase(tr, 'mixed') + # Let the reference block go stale so that only it is revalidated. + tr.Processes.Default.Command = f'sleep {self._expiry_wait}; ' + tr.Processes.Default.Command + # Slice aborts the transaction, so the client never reads a response at + # all: not a short body, no response header. verifier-client exits 1. + client.ReturnCode = 1 + client.Streams.stdout += Testers.ContainsExpression( + 'Failed to find a well-formed, completed HTTP response: PARSE_INCOMPLETE', + 'The client should not receive a parsable response.') + client.Streams.stdout += Testers.ContainsExpression( + 'Failed HTTP/1 transaction with key: mixed', 'The transaction should fail.') + self._still_running(tr) + + def _verify_mix_is_on_the_parent(self) -> None: + """A cold child fails identically, because the mix lives on the parent.""" + tr = Test.AddTestRun('A second child with a cold cache inherits the mix from the parent') + tr.Processes.Default.StartBefore(self._cold_child) + client = self._replay_phase(tr, 'cold-child', ts=self._cold_child) + client.ReturnCode = 1 + client.Streams.stdout += Testers.ContainsExpression( + 'Failed HTTP/1 transaction with key: cold-child', 'A node that never saw the old generation should fail the same way.') + self._cold_child.Disk.diags_log.Content = Testers.ContainsExpression( + 'Mismatch/Bad block Content-Range', 'The cold child should hit the same mismatch.') + tr.StillRunningAfter = self._cold_child + self._still_running(tr) + + def run(self) -> None: + """Configure the test runs.""" + self._fill_interior_block() + self._verify_aborted_response() + self._verify_mix_is_on_the_parent() + + +SliceStaleGenerationTest().run() +SliceMixedGenerationTest().run() From a378ccafd300a95616df9f1872e10f015bf1befc Mon Sep 17 00:00:00 2001 From: Mo Chen Date: Fri, 7 Aug 2026 09:48:52 -0500 Subject: [PATCH 05/10] Return an empty view for a non-participating capture group (#13441) RegexMatches::operator[] only checked the index against the ovector count. A group that does not participate in the match has unset offsets, and an optional group that precedes a participating one is still within that count, so the check passes and the subject pointer is advanced by PCRE2_UNSET. The resulting view has length zero, so callers see an empty string today, but the pointer is invalid. (cherry picked from commit e3bd6892026e9356076dfa84b0aecfa558cccacb) --- src/tsutil/Regex.cc | 7 +++++++ src/tsutil/unit_tests/test_Regex.cc | 17 +++++++++++++++++ 2 files changed, 24 insertions(+) diff --git a/src/tsutil/Regex.cc b/src/tsutil/Regex.cc index 34bfc5447d6..2c84b3fa08e 100644 --- a/src/tsutil/Regex.cc +++ b/src/tsutil/Regex.cc @@ -228,6 +228,13 @@ RegexMatches::operator[](size_t index) const } PCRE2_SIZE *ovector = pcre2_get_ovector_pointer(_MatchData::get(_match_data)); + + // A group that did not participate in the match has an unset offset. This happens for an optional + // group that precedes a participating one, so a valid index is not enough to guarantee an offset. + if (PCRE2_UNSET == ovector[2 * index]) { + return std::string_view(); + } + return std::string_view(_subject.data() + ovector[2 * index], ovector[2 * index + 1] - ovector[2 * index]); } diff --git a/src/tsutil/unit_tests/test_Regex.cc b/src/tsutil/unit_tests/test_Regex.cc index f5cddd47a00..76273e23226 100644 --- a/src/tsutil/unit_tests/test_Regex.cc +++ b/src/tsutil/unit_tests/test_Regex.cc @@ -460,6 +460,23 @@ TEST_CASE("RegexMatches edge cases", "[libts][Regex][RegexMatches]") CHECK(count >= 2); // At least whole match + first group CHECK(matches[1] == "foo"); } + + SECTION("RegexMatches with a non-participating group before a participating one") + { + // pcre2_match() returns one past the highest participating group, so an earlier optional group + // that did not participate is still within that count. Its offsets are unset. + Regex r; + REQUIRE(r.compile("(a)?(b)") == true); + + RegexMatches matches; + int count = r.exec("b", matches); + + CHECK(count == 3); + CHECK(matches[0] == "b"); + CHECK(matches[1] == ""); + CHECK(matches[2] == "b"); + CHECK(matches[1].data() == nullptr); + } } TEST_CASE("Regex with special characters", "[libts][Regex][special]") From 745b2e7e1ff81241521549298097c2b42061e460 Mon Sep 17 00:00:00 2001 From: Mo Chen Date: Fri, 7 Aug 2026 09:55:56 -0500 Subject: [PATCH 06/10] Destroy replaced configs on ET_TASK (#13491) * Destroy replaced configs on ET_TASK ConfigProcessor::set() scheduled the deferred destruction of the replaced config with schedule_in(), which defaults to ET_CALL, so a network thread ran the destructor 60 seconds later inside the drain phase of its event loop. The destructor blocks that thread for as long as the config takes to release, which is bounded only by the size of the config. ConfigProcessor::release() is the only place a config is destroyed, and two callers reach it: the releaser at 60 seconds, which destroys the config whenever nothing else still holds a reference, and a transaction that outlived the releaser and drops the last reference itself. Schedule the releaser on ET_TASK, and hand the destructor from the transaction path to ET_TASK as well, so neither can block a network thread. The 60 second wait is unchanged. Shortening it would narrow the window that makes the load-then-increment in get() safe. The config debug tag now reports the duration of each destruction and the thread that ran it. (cherry picked from commit 46be2f5008dd9026d2bdd6b3f02c5066031605e9) --- src/iocore/eventsystem/ConfigProcessor.cc | 76 +++++++++++++++++- .../config_destroy_thread.test.py | 77 +++++++++++++++++++ 2 files changed, 151 insertions(+), 2 deletions(-) create mode 100644 tests/gold_tests/config_processor/config_destroy_thread.test.py diff --git a/src/iocore/eventsystem/ConfigProcessor.cc b/src/iocore/eventsystem/ConfigProcessor.cc index a49335154ac..adf3cbc69f8 100644 --- a/src/iocore/eventsystem/ConfigProcessor.cc +++ b/src/iocore/eventsystem/ConfigProcessor.cc @@ -22,7 +22,10 @@ */ #include "iocore/eventsystem/ConfigProcessor.h" +#include "iocore/eventsystem/EThread.h" +#include "iocore/eventsystem/Tasks.h" #include "tscore/ink_atomic.h" +#include "tscore/ink_thread.h" #if TS_HAS_TESTS #include "tscore/TestBox.h" #endif @@ -34,8 +37,69 @@ namespace DbgCtl dbg_ctl_config{"config"}; +void +destroy_config(unsigned int id, ConfigInfo *info) +{ + ink_hrtime start = ink_get_hrtime(); + + delete info; + + if (dbg_ctl_config.on()) { + char thread_name[MAX_THREAD_NAME_LENGTH] = {}; + + ink_get_thread_name(thread_name, sizeof(thread_name)); + DbgPrint(dbg_ctl_config, "Destroyed config %u in %" PRId64 " ns on thread %s", id, ink_get_hrtime() - start, thread_name); + } +} + +/// Runs the destructor of a detached ConfigInfo on ET_TASK. +class ConfigInfoDestroyer : public Continuation +{ +public: + ConfigInfoDestroyer(unsigned int id, ConfigInfo *info) : Continuation(nullptr), m_id(id), m_info(info) + { + SET_HANDLER(&ConfigInfoDestroyer::handle_event); + } + + int + handle_event(int /* event ATS_UNUSED */, void * /* edata ATS_UNUSED */) + { + destroy_config(m_id, m_info); + delete this; + return EVENT_DONE; + } + +private: + unsigned int m_id; + ConfigInfo *m_info; +}; + +/// Hand a detached ConfigInfo to ET_TASK for destruction. Returns false when the caller has to +/// destroy it itself. +bool +destroy_config_on_task_thread(unsigned int id, ConfigInfo *info) +{ + EThread *ethread = this_ethread(); + + // ET_TASK is ET_CALL until the task threads are registered, so before that point an ET_NET caller + // destroys the config on its own thread. + if (ethread == nullptr || ethread->is_event_type(ET_TASK)) { + return false; + } + + ConfigInfoDestroyer *destroyer = new ConfigInfoDestroyer(id, info); + + if (eventProcessor.schedule_imm(destroyer, ET_TASK) == nullptr) { + // The event system is shutting down and will never run the destroyer. + delete destroyer; + return false; + } + + return true; } +} // namespace + class ConfigInfoReleaser : public Continuation { public: @@ -94,7 +158,10 @@ ConfigProcessor::set(unsigned int id, ConfigInfo *info, unsigned timeout_secs) // The ConfigInfoReleaser now takes our refcount, but // some other thread might also have one ... ink_assert(old_info->refcount() > 0); - eventProcessor.schedule_in(new ConfigInfoReleaser(id, old_info), HRTIME_SECONDS(timeout_secs)); + // Destroying a config releases everything it owns - a replaced certificate table takes its whole + // certificate set with the chains, keys and staples. Run it on ET_TASK, which already carries the + // config load, so the cost cannot land on a network event loop. + eventProcessor.schedule_in(new ConfigInfoReleaser(id, old_info), HRTIME_SECONDS(timeout_secs), ET_TASK); } return id; @@ -140,7 +207,12 @@ ConfigProcessor::release(unsigned int id, ConfigInfo *info) // When we release, we should already have replaced this object in the index. Dbg(dbg_ctl_config, "Release config %d %p", id, info); ink_release_assert(info != this->infos[idx]); - delete info; + + // The releaser runs on ET_TASK, but a transaction that outlived it drops the last reference on + // its own thread, which serves network connections. + if (!destroy_config_on_task_thread(id, info)) { + destroy_config(id, info); + } } } diff --git a/tests/gold_tests/config_processor/config_destroy_thread.test.py b/tests/gold_tests/config_processor/config_destroy_thread.test.py new file mode 100644 index 00000000000..0909c0f3bd3 --- /dev/null +++ b/tests/gold_tests/config_processor/config_destroy_thread.test.py @@ -0,0 +1,77 @@ +''' +Verify that a replaced config is destroyed on an ET_TASK thread. +''' +# Licensed to the Apache Software Foundation (ASF) under one +# or more contributor license agreements. See the NOTICE file +# distributed with this work for additional information +# regarding copyright ownership. The ASF licenses this file +# to you under the Apache License, Version 2.0 (the +# "License"); you may not use this file except in compliance +# with the License. You may obtain a copy of the License at +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +# See the License for the specific language governing permissions and +# limitations under the License. + +import os + +Test.Summary = ''' +Verify that a replaced config is destroyed on an ET_TASK thread. +''' + +# ConfigProcessor::set() waits CONFIG_PROCESSOR_RELEASE_SECS before it releases the config that it +# replaced. That timeout is a compile time constant of 60 seconds, so this test needs more than a +# minute of wall clock and does not run in CI. Comment out the next line to run it. +Test.SkipIf(Condition.true("Test takes over 60 seconds to run.")) + +Test.ContinueOnFail = True + +ts = Test.MakeATSProcess("ts") + +ts.Disk.records_config.update({ + 'proxy.config.diags.debug.enabled': 1, + 'proxy.config.diags.debug.tags': 'config', +}) + +ts.Disk.remap_config.AddLine('map / http://127.0.0.1:8080') + +config_dir = ts.Variables.CONFIGDIR + +# Two replacements, reached two different ways. Touching parent.config replaces ParentConfigParams +# through the reload framework, which runs on ET_TASK. Changing an HTTP record replaces +# HttpConfigParams from a network thread, which is the case this test is really about. Neither old +# config is referenced once the test stops sending traffic, so both reach a zero reference count and +# are destroyed when the release timeout expires. +tr = Test.AddTestRun("Mark parent.config for reload") +tr.Processes.Default.StartBefore(ts) +tr.Processes.Default.Command = f"sleep 3 && touch {os.path.join(config_dir, 'parent.config')} && sleep 1" +tr.Processes.Default.ReturnCode = 0 +tr.StillRunningAfter = ts + +Test.AddConfigReload(ts, expect="any", token="config_destroy_thread") + +tr = Test.AddTestRun("Replace the HTTP config from a network thread") +tr.DelayStart = 3 +tr.Processes.Default.Env = ts.Env +tr.Processes.Default.Command = "traffic_ctl config set proxy.config.http.response_server_str probe && sleep 3" +tr.Processes.Default.ReturnCode = 0 +tr.StillRunningAfter = ts + +tr = Test.AddTestRun("Wait for the release timeout to expire") +tr.DelayStart = 3 +tr.Processes.Default.Command = "sleep 80" +tr.Processes.Default.ReturnCode = 0 +tr.TimeOut = 150 +tr.StillRunningAfter = ts + +# The releaser runs on ET_TASK, so it destroys the replaced config there. +ts.Disk.traffic_out.Content = Testers.ContainsExpression( + r"Destroyed config \d+ in \d+ ns on thread \[ET_TASK", "a replaced config should be destroyed on a task thread") + +# Destroying a config on a network thread is the regression this test guards against. +ts.Disk.traffic_out.Content += Testers.ExcludesExpression( + r"Destroyed config \d+ in \d+ ns on thread \[ET_NET", "no config should be destroyed on a network thread") From de92d6075358ae8a0efe5e2afa0a01c995c0b901 Mon Sep 17 00:00:00 2001 From: Brian Neradt Date: Fri, 7 Aug 2026 11:07:06 -0500 Subject: [PATCH 07/10] Harden timing-sensitive AuTests (#13508) Several AuTests fail nondeterministically in parallel CI. The gRPC server can stop before its final response reaches the client, and the port allocator both ignores bound UDP ports and assumes every datagram address has a numeric port. The heavyweight strategy tests also rely on filename ordering that the parallel runner does not preserve. These failures appear as 502s, bind errors, setup exceptions, or port collisions. This patch addresses the races by counting completed RPCs, reserving bound IPv4 and IPv6 UDP ports while ignoring Unix sockets, and running both ordering-sensitive strategy tests after the parallel workers. Ports bound when the queue is initialized stay excluded for the full run, safely reducing the pool available on busy hosts. (cherry picked from commit 816420efcf42ad76c70e422e8ad9ed6e26a183aa) --- tests/gold_tests/autest-site/ports.py | 49 ++++++++++++------- tests/gold_tests/h2/grpc/grpc_server.py | 6 +-- .../zzz_strategies_peer.test.py | 4 +- .../zzz_strategies_peer2.test.py | 4 +- tests/serial_tests.txt | 4 ++ 5 files changed, 41 insertions(+), 26 deletions(-) diff --git a/tests/gold_tests/autest-site/ports.py b/tests/gold_tests/autest-site/ports.py index cfc56f4a305..3674601aab2 100644 --- a/tests/gold_tests/autest-site/ports.py +++ b/tests/gold_tests/autest-site/ports.py @@ -39,7 +39,7 @@ class PortQueueSelectionError(Exception): pass -def PortOpen(port: int, address: str = None, listening_ports: Set[int] = None) -> bool: +def PortOpen(port: int, address: str = None, bound_ports: Set[int] = None) -> bool: """ Detect whether the port is open, that is a socket is currently using that port. @@ -49,19 +49,19 @@ def PortOpen(port: int, address: str = None, listening_ports: Set[int] = None) - Args: port: The port to check. address: The address to check. Defaults to localhost. - listening_ports: A set of ports that are currently listening. If a port - is in this set, it is considered open. + bound_ports: A set of ports that are currently bound. If a port is in + this set, it is considered open. Returns: - True if there is a connection currently listening on the port, False if - there is no server listening on the port currently. + True if a socket is currently bound to the port or accepts a TCP + connection, False otherwise. """ ret = False if address is None: address = "localhost" - if port in listening_ports: - host.WriteDebug('PortOpen', f"{port} is open because it is in the listening sockets set.") + if port in bound_ports: + host.WriteDebug('PortOpen', f"{port} is open because it is in the bound sockets set.") return True address = (address, port) @@ -108,9 +108,9 @@ def _get_available_port(queue): host.WriteWarning("Port queue is empty.") raise PortQueueSelectionError("Could not get a valid port because the queue is empty") - listening_ports = _get_listening_ports() + bound_ports = _get_bound_ports() port = queue.get() - while PortOpen(port, listening_ports=listening_ports): + while PortOpen(port, bound_ports=bound_ports): host.WriteDebug('_get_available_port', f"Port was closed but now is used: {port}") if queue.qsize() == 0: host.WriteWarning("Port queue is empty.") @@ -119,16 +119,27 @@ def _get_available_port(queue): return port -def _get_listening_ports() -> Set[int]: - """Use psutil to get the set of ports that are currently listening. +def _is_bound(conn) -> bool: + """Return whether an internet socket connection occupies its local port.""" + return bool( + conn.family in (socket.AF_INET, socket.AF_INET6) and conn.laddr and + (conn.status == psutil.CONN_LISTEN or conn.type == socket.SOCK_DGRAM)) - :return: The set of ports that are currently listening. + +def _get_bound_ports() -> Set[int]: + """Use psutil to get the set of ports that are currently bound. + + TCP sockets report a listening status, but UDP sockets have no comparable + status. Any UDP socket with a local address is bound and therefore makes + its port unavailable to AuTest processes. + + :return: The set of ports that are currently bound. """ ports: Set[int] = set() try: connections = psutil.net_connections(kind='all') for conn in connections: - if conn.status == psutil.CONN_LISTEN: + if _is_bound(conn): ports.add(conn.laddr.port) except psutil.AccessDenied: # Mac OS X doesn't allow net_connections() to be called without root. @@ -138,7 +149,7 @@ def _get_listening_ports() -> Set[int]: except (psutil.AccessDenied, psutil.NoSuchProcess): continue for conn in connections: - if conn.status == psutil.CONN_LISTEN: + if _is_bound(conn): ports.add(conn.laddr.port) return ports @@ -192,14 +203,14 @@ def _setup_port_queue(amount=1000): rmin = dmin - 2000 rmax = 65536 - dmax - listening_ports = _get_listening_ports() + bound_ports = _get_bound_ports() if rmax > amount: # Fill in ports, starting above the upper OS-usable port range. # Add port_offset to support parallel test execution. port = dmax + 1 + port_offset while port < 65536 and g_ports.qsize() < amount: - if PortOpen(port, listening_ports=listening_ports): - host.WriteDebug('_setup_port_queue', f"Rejecting an already open port: {port}") + if PortOpen(port, bound_ports=bound_ports): + host.WriteDebug('_setup_port_queue', f"Rejecting an already bound port: {port}") else: host.WriteDebug('_setup_port_queue', f"Adding a possible port to connect to: {port}") g_ports.put(port) @@ -210,8 +221,8 @@ def _setup_port_queue(amount=1000): # Add port_offset to support parallel test execution (same as high range). port = 2001 + port_offset while port < dmin and g_ports.qsize() < amount: - if PortOpen(port, listening_ports=listening_ports): - host.WriteDebug('_setup_port_queue', f"Rejecting an already open port: {port}") + if PortOpen(port, bound_ports=bound_ports): + host.WriteDebug('_setup_port_queue', f"Rejecting an already bound port: {port}") else: host.WriteDebug('_setup_port_queue', f"Adding a possible port to connect to: {port}") g_ports.put(port) diff --git a/tests/gold_tests/h2/grpc/grpc_server.py b/tests/gold_tests/h2/grpc/grpc_server.py index 2a435db65f2..22faee92d37 100644 --- a/tests/gold_tests/h2/grpc/grpc_server.py +++ b/tests/gold_tests/h2/grpc/grpc_server.py @@ -37,7 +37,7 @@ def __init__(self, num_expected_messages: int, done_event: asyncio.Event): self._num_expected_messages = num_expected_messages self._done_event = done_event - def _record_message(self) -> None: + def _record_message(self, _context: grpc.aio.ServicerContext) -> None: global global_message_counter global_message_counter += 1 @@ -46,14 +46,14 @@ def _record_message(self) -> None: async def MakeRequest(self, request: simple_pb2.SimpleRequest, context: grpc.aio.ServicerContext): """An example gRPC method.""" - self._record_message() + context.add_done_callback(self._record_message) print(f'Received request: {request.message}') response = simple_pb2.SimpleResponse(message=f"Echo: {request.message}") return response async def MakeAnotherRequest(self, request: simple_pb2.SimpleRequest, context: grpc.aio.ServicerContext): """An example gRPC method.""" - self._record_message() + context.add_done_callback(self._record_message) print(f'Received another request: {request.message}') response = simple_pb2.SimpleResponse(message=f"Another echo: {request.message}") return response diff --git a/tests/gold_tests/next_hop/zzz_strategies_peer/zzz_strategies_peer.test.py b/tests/gold_tests/next_hop/zzz_strategies_peer/zzz_strategies_peer.test.py index 8e58908857c..69384861c1b 100644 --- a/tests/gold_tests/next_hop/zzz_strategies_peer/zzz_strategies_peer.test.py +++ b/tests/gold_tests/next_hop/zzz_strategies_peer/zzz_strategies_peer.test.py @@ -20,8 +20,8 @@ Test next hop selection using strategies.yaml with consistent hashing, with peering. ''' -# The tls_conn_timeout test will fail if it runs before this test in CI. Therefore, this test has a zzz -# prefix so it will run last in CI. +# This test must run after tls_conn_timeout and is listed in tests/serial_tests.txt +# to preserve that ordering. # Define and populate MicroServer. # diff --git a/tests/gold_tests/next_hop/zzz_strategies_peer2/zzz_strategies_peer2.test.py b/tests/gold_tests/next_hop/zzz_strategies_peer2/zzz_strategies_peer2.test.py index 8aad4e61027..82fa93e9b85 100644 --- a/tests/gold_tests/next_hop/zzz_strategies_peer2/zzz_strategies_peer2.test.py +++ b/tests/gold_tests/next_hop/zzz_strategies_peer2/zzz_strategies_peer2.test.py @@ -20,8 +20,8 @@ Test next hop using strategies.yaml with consistent hashing, with peering, and no upstream group" ''' -# The tls_conn_timeout test will fail if it runs before this test in CI. Therefore, this test has a zzz -# prefix so it will run last in CI. +# This test must run after tls_conn_timeout and is listed in tests/serial_tests.txt +# to preserve that ordering. # Define and populate MicroServer. # diff --git a/tests/serial_tests.txt b/tests/serial_tests.txt index d6eff1d2949..6fa665bf61d 100644 --- a/tests/serial_tests.txt +++ b/tests/serial_tests.txt @@ -6,3 +6,7 @@ # Spins up 12 ATS instances with varying thread configs; fails under parallel load thread_config/thread_config.test.py + +# Each must run after tls_conn_timeout and starts 14 ATS instances at once. +next_hop/zzz_strategies_peer/zzz_strategies_peer.test.py +next_hop/zzz_strategies_peer2/zzz_strategies_peer2.test.py From 7bf5d4b63d674bf2f1d9d5691c4e2238a85d7117 Mon Sep 17 00:00:00 2001 From: Brian Neradt Date: Fri, 7 Aug 2026 12:14:09 -0500 Subject: [PATCH 08/10] Avoid stale H2 writes after 100 Continue (#13504) HttpSM owns the write buffer attached to an HTTP/2 stream. After WRITE_COMPLETE it may release the buffer while a connection-level write-ready event can restart the stream through the non-owning _send_reader alias. This leaves restart_sending vulnerable to a use-after-free. Clear _send_reader before delivering WRITE_COMPLETE to HttpSM, and check completed write VIOs before inspecting the reader during connection restarts. This preserves zero-byte completion processing, including END_STREAM. Co-authored-by: bneradt (cherry picked from commit c0351de28011cbbb54597cd5ce564344e7ac6642) --- src/proxy/http2/Http2Stream.cc | 11 ++++++++--- 1 file changed, 8 insertions(+), 3 deletions(-) diff --git a/src/proxy/http2/Http2Stream.cc b/src/proxy/http2/Http2Stream.cc index 6be67db03b9..611e8b6a4eb 100644 --- a/src/proxy/http2/Http2Stream.cc +++ b/src/proxy/http2/Http2Stream.cc @@ -807,12 +807,12 @@ Http2Stream::restart_sending() } } - IOBufferReader *reader = this->get_data_reader_for_send(); - if (reader && !reader->is_read_avail_more_than(0)) { + if (this->write_vio.mutex && this->write_vio.ntodo() <= 0) { return; } - if (this->write_vio.mutex && this->write_vio.ntodo() == 0) { + IOBufferReader *reader = this->get_data_reader_for_send(); + if (reader && !reader->is_read_avail_more_than(0)) { return; } @@ -970,6 +970,11 @@ Http2Stream::signal_write_event(int event, bool call_update) write_event = nullptr; } _timeout.update_inactivity(); + if (event == VC_EVENT_WRITE_COMPLETE) { + // HttpSM owns the write buffer and may release it while handling this + // event. Drop the unowned alias before transferring control. + _send_reader = nullptr; + } this->write_vio.cont->handleEvent(event, &this->write_vio); } else { if (this->_write_vio_event) { From 601871fa9576332f309caaf4ac64f3a506c3702d Mon Sep 17 00:00:00 2001 From: Brian Neradt Date: Fri, 7 Aug 2026 13:21:47 -0500 Subject: [PATCH 09/10] Fix cache read VC replacement after a lost write lock (#13515) A transaction that revalidates a stale cached object and cannot take the cache write lock is sent back through a second cache lookup while it still holds the cache read connection its first lookup opened. The read that completes for that second lookup replaces the connection the transaction is using: debug builds abort on the read connection assertion in HttpCacheSM::state_cache_open_read(), and release builds close that connection out from under the stale object saved as the retry fallback, leaving the fallback pointing into freed memory. The re-lookup runs for every cache_open_write_fail_action rather than only for the two that configure a read retry, so fail action 2, which is documented to serve the stale object instead of retrying anything, aborts a debug build several times a day under production traffic. This patch limits the re-lookup to the fail actions that configure a read retry. A transaction that loses the write lock with a cached object and no retry configured now hands that object straight to the freshness handling that serves stale content, with no second lookup. The retry actions do want that lookup, so this also makes replacing the read connection explicit and drops the saved stale object along with the connection that owns it, since neither can outlive the other. This adds an autest covering both configurations that does not depend on contention between transactions: denying the write lock through max_open_write_retries makes the failure synchronous, and each configuration aborts an unpatched debug build on the production assertion. The re-lookup arrived with the fail action 6 work in #12852, which applied it to every non-default fail action; that commit's own test notes the stale path is timing sensitive and does not exercise it. The resulting aborts resemble the ones #13487 fixed, because both land in HttpCacheSM while a cache write retry dispatches events, but they are a distinct failure. #13487 stopped HttpSM from canceling its own captive action, which aborts on the cancellation assertion in HttpCacheSM.cc:138; this is the read connection assertion ten lines later, reached with that action perfectly valid. Both fixes are needed, and neither subsumes the other. Co-authored-by: Claude Opus 5 (cherry picked from commit f5c1b092f6e96f8127cd1fd05fc10f605eb32300) --- include/proxy/http/HttpConfig.h | 12 ++ src/proxy/http/HttpCacheSM.cc | 20 +-- src/proxy/http/HttpTransact.cc | 13 ++ .../cache/cache-write-lock-fail-write.conf | 24 +++ .../cache-write-lock-stale-revalidate.test.py | 32 ++++ .../cache-write-lock-stale-retry.replay.yaml | 145 ++++++++++++++++++ .../cache-write-lock-stale-serve.replay.yaml | 139 +++++++++++++++++ 7 files changed, 373 insertions(+), 12 deletions(-) create mode 100644 tests/gold_tests/cache/cache-write-lock-fail-write.conf create mode 100644 tests/gold_tests/cache/cache-write-lock-stale-revalidate.test.py create mode 100644 tests/gold_tests/cache/replay/cache-write-lock-stale-retry.replay.yaml create mode 100644 tests/gold_tests/cache/replay/cache-write-lock-stale-serve.replay.yaml diff --git a/include/proxy/http/HttpConfig.h b/include/proxy/http/HttpConfig.h index c09bdddba80..5bf58f7d7d0 100644 --- a/include/proxy/http/HttpConfig.h +++ b/include/proxy/http/HttpConfig.h @@ -420,6 +420,18 @@ enum class CacheOpenWriteFailAction_t { TOTAL_TYPES }; +/** Whether a cache_open_write_fail_action retries the cache read. + * + * @param[in] action A proxy.config.http.cache.open_write_fail_action value. + * @return Whether losing the cache write lock should retry the cache read. + */ +inline bool +is_read_retry_write_fail_action(MgmtByte action) +{ + return action == static_cast(CacheOpenWriteFailAction_t::READ_RETRY) || + action == static_cast(CacheOpenWriteFailAction_t::READ_RETRY_STALE_ON_REVALIDATE); +} + extern HttpStatsBlock http_rsb; ///////////////////////////////////////////////////////////// diff --git a/src/proxy/http/HttpCacheSM.cc b/src/proxy/http/HttpCacheSM.cc index cc8dcded3d0..4ddcc27ddcc 100644 --- a/src/proxy/http/HttpCacheSM.cc +++ b/src/proxy/http/HttpCacheSM.cc @@ -43,14 +43,6 @@ namespace { DbgCtl dbg_ctl_http_cache{"http_cache"}; - -// Helper to check if cache_open_write_fail_action has READ_RETRY behavior -inline bool -is_read_retry_action(MgmtByte action) -{ - return action == static_cast(CacheOpenWriteFailAction_t::READ_RETRY) || - action == static_cast(CacheOpenWriteFailAction_t::READ_RETRY_STALE_ON_REVALIDATE); -} } // end anonymous namespace //// @@ -145,9 +137,13 @@ HttpCacheSM::state_cache_open_read(int event, void *data) switch (event) { case CACHE_EVENT_OPEN_READ: Metrics::Gauge::increment(http_rsb.current_cache_connections); - ink_assert((cache_read_vc == nullptr) || master_sm->t_state.redirect_info.redirect_in_process); + ink_assert((cache_read_vc == nullptr) || master_sm->t_state.redirect_info.redirect_in_process || + master_sm->t_state.cache_info.write_lock_state == HttpTransact::CacheWriteLock_t::READ_RETRY); if (cache_read_vc) { - // redirect follow in progress, close the previous cache_read_vc + // A redirect follow or a read retry after losing the cache write lock + // replaces the read VC. The stale object that a read retry saved as its + // fallback lives in the VC being closed, so it cannot outlive it. + master_sm->t_state.cache_info.stale_fallback = nullptr; close_read(); } cache_read_vc = static_cast(data); @@ -234,7 +230,7 @@ HttpCacheSM::state_cache_open_write(int event, void *data) break; case CACHE_EVENT_OPEN_WRITE_FAILED: { - if (is_read_retry_action(master_sm->t_state.txn_conf->cache_open_write_fail_action)) { + if (is_read_retry_write_fail_action(master_sm->t_state.txn_conf->cache_open_write_fail_action)) { // fall back to open_read_tries // Note that when READ_RETRY actions are configured, max_cache_open_write_retries // is automatically ignored. Make sure to not disable max_cache_open_read_retries @@ -282,7 +278,7 @@ HttpCacheSM::state_cache_open_write(int event, void *data) _read_retry_event = nullptr; } - if (is_read_retry_action(master_sm->t_state.txn_conf->cache_open_write_fail_action)) { + if (is_read_retry_write_fail_action(master_sm->t_state.txn_conf->cache_open_write_fail_action)) { Dbg(dbg_ctl_http_cache, "[%" PRId64 "] [state_cache_open_write] cache open write failure %d. " "falling back to read retry...", diff --git a/src/proxy/http/HttpTransact.cc b/src/proxy/http/HttpTransact.cc index e4226ccf704..2908a1446d0 100644 --- a/src/proxy/http/HttpTransact.cc +++ b/src/proxy/http/HttpTransact.cc @@ -3365,6 +3365,19 @@ HttpTransact::handle_cache_write_lock(State *s) // HIT_STALE (revalidation case), the hook already fired and deferred is false. CacheHTTPInfo *obj = s->cache_info.object_read; if (obj != nullptr) { + if (!is_read_retry_write_fail_action(s->cache_open_write_fail_action)) { + // Fail actions 2 and 3 do not retry the cache read: they serve the + // object this transaction already looked up. Deciding otherwise here + // would issue a second cache lookup while the transaction still holds + // the cache read connection from the first one, and the read that + // completes on that second lookup replaces the connection out from + // under it. + TxnDbg(dbg_ctl_http_trans, "write lock lost with a cached object and no read retry configured"); + s->hdr_info.server_request.destroy(); + HandleCacheOpenReadHitFreshness(s); + return; + } + // Restore request/response times from cached object for freshness calculations and Age header. // Similar to HandleCacheOpenReadHitFreshness, handle clock skew by capping times. s->request_sent_time = obj->request_sent_time_get(); diff --git a/tests/gold_tests/cache/cache-write-lock-fail-write.conf b/tests/gold_tests/cache/cache-write-lock-fail-write.conf new file mode 100644 index 00000000000..94afd2ccac6 --- /dev/null +++ b/tests/gold_tests/cache/cache-write-lock-fail-write.conf @@ -0,0 +1,24 @@ +# +# 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. + +# Deny the cache write lock to any request carrying X-Fail-Cache-Write. With no +# write retries left, HttpCacheSM::open_write() reports the write failure +# without going to the cache at all, which makes the write lock loss +# deterministic instead of dependent upon a race between two transactions. +cond %{REMAP_PSEUDO_HOOK} +cond %{CLIENT-HEADER:X-Fail-Cache-Write} =1 +set-config proxy.config.http.cache.max_open_write_retries 0 [L] diff --git a/tests/gold_tests/cache/cache-write-lock-stale-revalidate.test.py b/tests/gold_tests/cache/cache-write-lock-stale-revalidate.test.py new file mode 100644 index 00000000000..1ff37247c84 --- /dev/null +++ b/tests/gold_tests/cache/cache-write-lock-stale-revalidate.test.py @@ -0,0 +1,32 @@ +''' +Verify losing the cache write lock while revalidating a stale object is handled. +''' +# 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 = ''' +Verify that a transaction which loses the cache write lock while revalidating a +stale object serves that object instead of tripping over the cache read +connection it still holds. +''' + +Test.ContinueOnFail = True + +# STALE_ON_REVALIDATE (action 2) serves the stale object directly. +Test.ATSReplayTest(replay_file="replay/cache-write-lock-stale-serve.replay.yaml") + +# READ_RETRY_STALE_ON_REVALIDATE (action 6) retries the cache read first. +Test.ATSReplayTest(replay_file="replay/cache-write-lock-stale-retry.replay.yaml") diff --git a/tests/gold_tests/cache/replay/cache-write-lock-stale-retry.replay.yaml b/tests/gold_tests/cache/replay/cache-write-lock-stale-retry.replay.yaml new file mode 100644 index 00000000000..6fe5975b61d --- /dev/null +++ b/tests/gold_tests/cache/replay/cache-write-lock-stale-retry.replay.yaml @@ -0,0 +1,145 @@ +# 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. +# +# proxy.config.http.cache.open_write_fail_action 6 +# (READ_RETRY_STALE_ON_REVALIDATE) retries the cache read when the write lock +# for a revalidation cannot be taken, hoping that whoever holds the lock has +# written a newer object. The retry has to replace the cache read connection the +# transaction opened for its first lookup, and the stale object saved as the +# fallback for that retry lives inside that connection, so neither may outlive +# the other. Debug builds used to abort in +# HttpCacheSM::state_cache_open_read() when the retry read completed. + +meta: + version: "1.0" + + blocks: + # The retried read finds the same stale object, which action 6 serves, so this + # response should never be seen. Negative revalidating is disabled below so + # that a 500 from the origin is passed through to the client rather than + # masked by the cached object, making an unexpected origin request visible in + # the proxy response. + - origin_not_expected: &origin_not_expected + server-response: + status: 500 + reason: "Internal Server Error" + headers: + fields: + - [ Content-Length, 16 ] + - [ X-Response, origin ] + +autest: + description: 'Verify a lost write lock on revalidation can retry the cache read' + + dns: + name: 'dns-stale-retry' + + server: + name: 'origin-stale-retry' + + client: + name: 'client-stale-retry' + + ats: + name: 'ts-stale-retry' + process_config: + enable_cache: true + + copy_to_config_dir: + - 'cache-write-lock-fail-write.conf' + + records_config: + proxy.config.diags.debug.enabled: 1 + proxy.config.diags.debug.tags: 'http_cache|http_trans|http_match' + # READ_RETRY_STALE_ON_REVALIDATE: retry the cache read when the write lock + # is lost, and fall back to the stale object if the retry finds nothing + # fresher. + proxy.config.http.cache.open_write_fail_action: 6 + proxy.config.http.cache.max_open_write_retry_timeout: 0 + proxy.config.http.cache.max_open_read_retries: 2 + proxy.config.http.cache.open_read_retry_time: 100 + # Pass an origin error through instead of covering it with the cached + # object, so that the proxy response below detects an origin request. + proxy.config.http.negative_revalidating_enabled: 0 + + remap_config: + - from: "http://example.com/" + to: "http://backend.example.com:{SERVER_HTTP_PORT}/" + plugins: + - name: header_rewrite.so + args: ['cache-write-lock-fail-write.conf'] + + log_validation: + traffic_out: + excludes: + - expression: "[Ff]atal|failed assertion" + description: 'Verify ATS does not abort when the retried cache read completes' + contains: + - expression: "READ_RETRY: object stale, triggering actual cache retry" + description: 'Verify the lost write lock triggered a cache read retry' + - expression: "cache_serve_stale_on_write_lock_fail" + description: 'Verify the stale object was served after the retry found nothing fresher' + +sessions: +- transactions: + + # Populate the cache with an object that is stale one second later. + - client-request: + method: GET + version: '1.1' + url: /stale-object + headers: + fields: + - [ Host, example.com ] + - [ uuid, prime-cache ] + + server-response: + status: 200 + reason: OK + headers: + fields: + - [ Content-Length, 16 ] + - [ Cache-Control, "max-age=1" ] + - [ X-Response, cached ] + + proxy-response: + status: 200 + headers: + fields: + - [ X-Response, { value: cached, as: equal } ] + + # The cached object is stale now, so ATS prepares to revalidate it and asks + # the cache for the write lock. The header below denies that lock, so the + # transaction retries its cache read and then serves the stale object. + - client-request: + delay: 2s + + method: GET + version: '1.1' + url: /stale-object + headers: + fields: + - [ Host, example.com ] + - [ uuid, revalidate-without-write-lock ] + - [ X-Fail-Cache-Write, '1' ] + + <<: *origin_not_expected + + proxy-response: + status: 200 + headers: + fields: + - [ X-Response, { value: cached, as: equal } ] diff --git a/tests/gold_tests/cache/replay/cache-write-lock-stale-serve.replay.yaml b/tests/gold_tests/cache/replay/cache-write-lock-stale-serve.replay.yaml new file mode 100644 index 00000000000..1b4924e0a09 --- /dev/null +++ b/tests/gold_tests/cache/replay/cache-write-lock-stale-serve.replay.yaml @@ -0,0 +1,139 @@ +# 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. +# +# proxy.config.http.cache.open_write_fail_action 2 (STALE_ON_REVALIDATE) asks +# ATS to serve the stale cached object when it cannot take the write lock to +# revalidate it. That transaction still holds the cache read connection from +# its own lookup, so the write lock failure must not send it back through +# another cache lookup: the second lookup replaces the read connection the +# transaction is using, which aborts debug builds on the canceled read +# connection assertion in HttpCacheSM::state_cache_open_read(). + +meta: + version: "1.0" + + blocks: + # The stale object has to be served out of the cache, so this response should + # never be seen. Negative revalidating is disabled below so that a 500 from + # the origin is passed through to the client rather than masked by the cached + # object, making an unexpected origin request visible in the proxy response. + - origin_not_expected: &origin_not_expected + server-response: + status: 500 + reason: "Internal Server Error" + headers: + fields: + - [ Content-Length, 16 ] + - [ X-Response, origin ] + +autest: + description: 'Verify a lost write lock on revalidation serves the stale object' + + dns: + name: 'dns-stale-serve' + + server: + name: 'origin-stale-serve' + + client: + name: 'client-stale-serve' + + ats: + name: 'ts-stale-serve' + process_config: + enable_cache: true + + copy_to_config_dir: + - 'cache-write-lock-fail-write.conf' + + records_config: + proxy.config.diags.debug.enabled: 1 + proxy.config.diags.debug.tags: 'http_cache|http_trans|http_match' + # STALE_ON_REVALIDATE: serve stale when the write lock is lost. + proxy.config.http.cache.open_write_fail_action: 2 + proxy.config.http.cache.max_open_write_retry_timeout: 0 + # Pass an origin error through instead of covering it with the cached + # object, so that the proxy response below detects an origin request. + proxy.config.http.negative_revalidating_enabled: 0 + + remap_config: + - from: "http://example.com/" + to: "http://backend.example.com:{SERVER_HTTP_PORT}/" + plugins: + - name: header_rewrite.so + args: ['cache-write-lock-fail-write.conf'] + + log_validation: + traffic_out: + excludes: + - expression: "[Ff]atal|failed assertion" + description: 'Verify ATS does not abort when the write lock is lost' + - expression: "READ_RETRY: object stale" + description: 'Verify no cache read retry is issued for a fail action that does not configure one' + contains: + - expression: "cache_serve_stale_on_write_lock_fail" + description: 'Verify the stale object was served because the write lock was lost' + +sessions: +- transactions: + + # Populate the cache with an object that is stale one second later. + - client-request: + method: GET + version: '1.1' + url: /stale-object + headers: + fields: + - [ Host, example.com ] + - [ uuid, prime-cache ] + + server-response: + status: 200 + reason: OK + headers: + fields: + - [ Content-Length, 16 ] + - [ Cache-Control, "max-age=1" ] + - [ X-Response, cached ] + + proxy-response: + status: 200 + headers: + fields: + - [ X-Response, { value: cached, as: equal } ] + + # The cached object is stale now, so ATS prepares to revalidate it and asks + # the cache for the write lock. The header below denies that lock, which used + # to drive the transaction into a second cache lookup. + - client-request: + delay: 2s + + method: GET + version: '1.1' + url: /stale-object + headers: + fields: + - [ Host, example.com ] + - [ uuid, revalidate-without-write-lock ] + - [ X-Fail-Cache-Write, '1' ] + + <<: *origin_not_expected + + proxy-response: + status: 200 + headers: + fields: + - [ X-Response, { value: cached, as: equal } ] From 6b006336ca87bf51deb93bc1bbf146f326c374c9 Mon Sep 17 00:00:00 2001 From: Mo Chen Date: Fri, 7 Aug 2026 13:51:28 -0500 Subject: [PATCH 10/10] Deliver VCONN_CLOSE for parked TLS hooks; fix SNI queue accounting (#13406) * rate_limit: balance the SNI active-slot counter for queued connections A queued SNI connection never reserves a slot, but its VCONN_CLOSE released one unconditionally. A queued connection that closed therefore decremented the active-slot counter without a matching increment; it wrapped below zero and the next reserve() aborted the server on TSReleaseAssert(_active <= _limit). Balance the accounting: resume queued connections with reserve-then-pop so a resumed connection owns a real slot; release a slot on close only when the connection is no longer queued (a still-queued one never held one) and drop it from the queue; detach an expired connection the same way the reject path does. Removing a closing connection from the queue also fixes a stale-pointer dereference when a parked queued connection is reset. Add deterministic regressions for the resume and max_age paths. * rate_limit: add an SNI reject-teardown autest Exercise the sync-reject path against a TLS listener: a holder reserves the one slot and a burst of concurrent handshakes is rejected mid-handshake (TS_EVENT_ERROR) with the allocator freelists disabled. Asserts the reject path is reached and every rejected handshake VC is freed without a memory-safety fault. * rate_limit tests: annotate helpers and create the FIFO atomically Annotate the TestRun parameters like the surrounding class-based gold tests, and create the holder FIFO inside a fresh mktemp -d directory instead of on an unlinked mktemp -u path, whose creation is not atomic. * Deliver VCONN_CLOSE for connections parked in a TLS handshake hook callHooks() moves the hook state to DONE when a connection closes, but it kept curHook pointing into whichever handshake hook list the connection was parked in. Each hook id owns a separate list, so advancing curHook walked the handshake list rather than the close list: the close event was dropped once that list ran out, and delivered to the next handshake plugin when it did not. A plugin that parks a connection therefore never learns that it died. In the rate_limit SNI queue that leaves a freed TSVConn on the queue and leaks the selector lease, and the next sweep reenables freed memory. Restart from the head of the close hook list unless we are already iterating it. Take the same path for TS_EVENT_VCONN_OUTBOUND_CLOSE, which previously invoked nothing at all for a connection parked in the outbound pre-handshake hook. * rate_limit: address review feedback Drop the dependency on coreutils "timeout", which is absent on macOS and made the gold tests fail rather than skip there, and which was relied on for fractional deadlines. A small sleep-and-kill helper replaces it. Also drop -verify_quiet, which is redundant with -quiet and is not accepted by every s_client implementation. Take the element by const reference in RateLimiter::remove(), and record what bounds the scan: the configured queue size, or connections_throttle when a "queue" is given without a "size". Correct the queue test's narration. It described the counter wrapping and the probe aborting the server, which is what happened before 508c1bea26 fixed the sweep's resume condition; the test now pins that fix rather than reproducing it. (cherry picked from commit b9b9109864c3402ac61885728cffde1d32e2154f) --- plugins/experimental/rate_limit/limiter.h | 24 +++++ .../experimental/rate_limit/sni_limiter.cc | 7 +- .../experimental/rate_limit/sni_selector.cc | 21 ++++- src/iocore/net/TLSEventSupport.cc | 12 ++- .../rate_limit/rate_limit_sni_expiry.test.py | 86 ++++++++++++++++++ .../rate_limit_sni_expiry_client.sh | 77 ++++++++++++++++ .../rate_limit/rate_limit_sni_queue.test.py | 88 +++++++++++++++++++ .../rate_limit/rate_limit_sni_queue_client.sh | 78 ++++++++++++++++ .../rate_limit/rate_limit_sni_reject.test.py | 82 +++++++++++++++++ .../rate_limit_sni_reject_client.sh | 60 +++++++++++++ .../tls_hooks_close_while_parked.test.py | 82 +++++++++++++++++ 11 files changed, 612 insertions(+), 5 deletions(-) create mode 100644 tests/gold_tests/pluginTest/rate_limit/rate_limit_sni_expiry.test.py create mode 100644 tests/gold_tests/pluginTest/rate_limit/rate_limit_sni_expiry_client.sh create mode 100644 tests/gold_tests/pluginTest/rate_limit/rate_limit_sni_queue.test.py create mode 100644 tests/gold_tests/pluginTest/rate_limit/rate_limit_sni_queue_client.sh create mode 100644 tests/gold_tests/pluginTest/rate_limit/rate_limit_sni_reject.test.py create mode 100644 tests/gold_tests/pluginTest/rate_limit/rate_limit_sni_reject_client.sh create mode 100644 tests/gold_tests/tls_hooks/tls_hooks_close_while_parked.test.py diff --git a/plugins/experimental/rate_limit/limiter.h b/plugins/experimental/rate_limit/limiter.h index 6696274fafc..038c295faf1 100644 --- a/plugins/experimental/rate_limit/limiter.h +++ b/plugins/experimental/rate_limit/limiter.h @@ -327,6 +327,30 @@ template class RateLimiter return item; } + // Remove a still-queued element (e.g. a connection that closed before it was resumed). + // Returns true if it was found in the queue, so the caller can tell a queued element + // (which never reserved a slot) from one that was already resumed. + // + // Linear in the queue depth, and only reached when an element closes while queued, which + // requires the limiter to be at its limit. The depth is bounded by the configured queue size; + // note that a "queue" without a "size" leaves _max_queue at UINT32_MAX, in which case the only + // bound is proxy.config.net.connections_throttle. + bool + remove(const T &elem) + { + std::lock_guard lock(_queue_lock); + + for (auto it = _queue.begin(); it != _queue.end(); ++it) { + if (std::get<0>(*it) == elem) { + _queue.erase(it); + --_size; + return true; + } + } + + return false; + } + void incrementMetric(uint metric) { diff --git a/plugins/experimental/rate_limit/sni_limiter.cc b/plugins/experimental/rate_limit/sni_limiter.cc index 67241ad1784..36bca010045 100644 --- a/plugins/experimental/rate_limit/sni_limiter.cc +++ b/plugins/experimental/rate_limit/sni_limiter.cc @@ -171,7 +171,12 @@ sni_limit_cont(TSCont contp, TSEvent event, void *edata) if (limiter) { TSUserArgSet(vc, gVCIdx, nullptr); - limiter->free(); + // A connection that is still queued never reserved a slot, so only release one if it + // is not in the queue (either it reserved at CLIENT_HELLO or the sweep resumed it into + // a reserved slot). Dropping it from the queue also avoids a stale entry. + if (!limiter->remove(vc)) { + limiter->free(); + } limiter->selector()->release(); // Release the selector, such that it can be deleted later } TSVConnReenable(vc); diff --git a/plugins/experimental/rate_limit/sni_selector.cc b/plugins/experimental/rate_limit/sni_selector.cc index c1c2eec7ea7..5d992687aa0 100644 --- a/plugins/experimental/rate_limit/sni_selector.cc +++ b/plugins/experimental/rate_limit/sni_selector.cc @@ -219,9 +219,17 @@ sni_queue_cont(TSCont cont, TSEvent /* event ATS_UNUSED */, void * /* edata ATS_ QueueTime now = std::chrono::system_clock::now(); // Only do this once per limiter if (owner) { // Don't operate on the aliases - // Try to enable some queued VCs (if any) if there are slots available + // Try to enable some queued VCs (if any) if there are slots available. Reserving before + // dequeuing means a resumed VC owns the slot it was granted, so its VCONN_CLOSE releases + // exactly that slot. while (limiter->size() > 0 && limiter->reserve() == ReserveStatus::RESERVED) { - auto [vc, contp, start_time] = limiter->pop(); + auto [vc, contp, start_time] = limiter->pop(); + + if (nullptr == vc) { // A concurrent close emptied the queue; give the slot back + limiter->free(); + break; + } + std::chrono::milliseconds delay = std::chrono::duration_cast(now - start_time); (void)contp; // Ugly, but silences some compilers. @@ -236,11 +244,18 @@ sni_queue_cont(TSCont cont, TSEvent /* event ATS_UNUSED */, void * /* edata ATS_ while (limiter->size() > 0 && limiter->hasOldEntity(now)) { // The oldest object on the queue is too old on the queue, so "kill" it. - auto [vc, contp, start_time] = limiter->pop(); + auto [vc, contp, start_time] = limiter->pop(); + + if (nullptr == vc) { // A concurrent close emptied the queue + break; + } + std::chrono::milliseconds age = std::chrono::duration_cast(now - start_time); (void)contp; Dbg(dbg_ctl, "Queued VC is too old (%ldms), erroring out", static_cast(age.count())); + // This VC never reserved a slot; detach it (clear the arg and release the selector + // lease) so its VCONN_CLOSE does not release a slot it never held. TSUserArgSet(vc, gVCIdx, nullptr); limiter->selector()->release(); TSVConnReenableEx(vc, TS_EVENT_ERROR); diff --git a/src/iocore/net/TLSEventSupport.cc b/src/iocore/net/TLSEventSupport.cc index c1009d8c6ca..a44d5c71b6c 100644 --- a/src/iocore/net/TLSEventSupport.cc +++ b/src/iocore/net/TLSEventSupport.cc @@ -153,10 +153,20 @@ TLSEventSupport::callHooks(TSEvent eventId) Dbg(dbg_ctl_ssl, "sslHandshakeHookState=%s eventID=%d", get_ssl_handshake_hook_state_name(this->sslHandshakeHookState), eventId); // Move state if it is appropriate - if (eventId == TS_EVENT_VCONN_CLOSE) { + if (eventId == TS_EVENT_VCONN_CLOSE || eventId == TS_EVENT_VCONN_OUTBOUND_CLOSE) { // Regardless of state, if the connection is closing, then transition to // the DONE state. This will trigger us to call the appropriate cleanup // routines. + // + // A connection can close while it is parked in a handshake hook, waiting for a plugin to + // reenable it. curHook then still points into that handshake hook's list. Each hook id owns + // a separate list, so advancing curHook below would walk the handshake list rather than the + // close list: the close event is dropped when the handshake list is exhausted, or delivered + // to the wrong plugin when it is not. Restart from the head of the close list unless we are + // already iterating it. + if (this->sslHandshakeHookState != SSLHandshakeHookState::HANDSHAKE_HOOKS_DONE) { + this->curHook = nullptr; + } this->sslHandshakeHookState = SSLHandshakeHookState::HANDSHAKE_HOOKS_DONE; } else { switch (this->sslHandshakeHookState) { diff --git a/tests/gold_tests/pluginTest/rate_limit/rate_limit_sni_expiry.test.py b/tests/gold_tests/pluginTest/rate_limit/rate_limit_sni_expiry.test.py new file mode 100644 index 00000000000..af90d7fac63 --- /dev/null +++ b/tests/gold_tests/pluginTest/rate_limit/rate_limit_sni_expiry.test.py @@ -0,0 +1,86 @@ +''' +Regression test for the max_age expiry branch of the rate_limit SNI queue accounting. A +queued connection never reserves a slot, so when the sweep expires it the plugin must +detach it rather than release a slot it never held; otherwise the expiry underflows the +active-slot counter and the next reserve() trips a release assertion, aborting the server. +ATS must survive the expiry. +''' +# Licensed to the Apache Software Foundation (ASF) under one +# or more contributor license agreements. See the NOTICE file +# distributed with this work for additional information +# regarding copyright ownership. The ASF licenses this file +# to you under the Apache License, Version 2.0 (the +# "License"); you may not use this file except in compliance +# with the License. You may obtain a copy of the License at +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +# See the License for the specific language governing permissions and +# limitations under the License. + +import os + +Test.Summary = __doc__ + +Test.SkipUnless(Condition.PluginExists('rate_limit.so')) + + +class RateLimitSniExpiryTest: + """Age a queued connection out via max_age and assert the active-slot counter stays balanced.""" + + def __init__(self) -> None: + tr = Test.AddTestRun('rate_limit SNI queue max_age expiry') + self._configure_trafficserver() + self._configure_client(tr) + + def _configure_trafficserver(self) -> None: + ts = Test.MakeATSProcess('ts', enable_tls=True, enable_cache=False) + self._ts = ts + ts.addDefaultSSLFiles() + ts.Disk.ssl_multicert_config.AddLine('dest_ip=* ssl_cert_name=server.pem ssl_key_name=server.key') + + # One concurrent handshake for this SNI, a one-deep queue, and a 1s max age so the + # sweep expires the queued connection. Named .config (not .yaml) so autest treats it + # as a plain config file; the plugin parses it as YAML regardless. + ts.Disk.MakeConfigFile('rate_limit.config').AddLines( + [ + 'selector:', + ' - sni: rate.limited.com', + ' limit: 1', + ' queue:', + ' size: 1', + ' max_age: 1', + ]) + ts.Disk.plugin_config.AddLine(f'rate_limit.so {ts.Variables.CONFIGDIR}/rate_limit.config') + + # Disable the freelist / ProxyAllocator so allocation behavior is not a confound; the + # abort under test is a release-assertion, and this keeps the run representative of CI. + ts.Command += ' -f -F' + + ts.Disk.records_config.update( + { + 'proxy.config.ssl.server.cert.path': ts.Variables.SSLDir, + 'proxy.config.ssl.server.private_key.path': ts.Variables.SSLDir, + 'proxy.config.diags.debug.enabled': 1, + 'proxy.config.diags.debug.tags': 'rate_limit', + }) + + # The expiry branch is actually reached... + ts.Disk.traffic_out.Content = Testers.ContainsExpression('too old', 'a queued connection was expired') + # ...and expiring it does not underflow the active-slot counter into the release assertion. + ts.Disk.traffic_out.Content += Testers.ExcludesExpression( + '_active <= _limit|received signal', 'expiring a queued connection must not underflow and abort ATS') + + def _configure_client(self, tr: 'TestRun') -> None: + ts = self._ts + client = os.path.join(Test.TestDirectory, 'rate_limit_sni_expiry_client.sh') + tr.Processes.Default.Command = f'bash {client} 127.0.0.1 {ts.Variables.ssl_port} rate.limited.com' + tr.Processes.Default.ReturnCode = 0 + tr.Processes.Default.StartBefore(ts) + tr.Processes.Default.Streams.stdout = Testers.ContainsExpression('rate_limit-expiry-done', 'the client ran to completion') + + +RateLimitSniExpiryTest() diff --git a/tests/gold_tests/pluginTest/rate_limit/rate_limit_sni_expiry_client.sh b/tests/gold_tests/pluginTest/rate_limit/rate_limit_sni_expiry_client.sh new file mode 100644 index 00000000000..10742f2c8c7 --- /dev/null +++ b/tests/gold_tests/pluginTest/rate_limit/rate_limit_sni_expiry_client.sh @@ -0,0 +1,77 @@ +#!/usr/bin/env bash +# +# 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. +# +# Exercise the max_age EXPIRY branch of the rate_limit SNI queue accounting. A queued +# connection never reserves a slot; when the sweep expires it (max_age), it must be +# detached so its close does not release a slot it never held. Otherwise the expiry is an +# unmatched decrement of the active-slot counter, and -- combined with the holder's own +# close -- the counter wraps below zero and the limiter's release assertion aborts ATS. +# +# 1. holder completes its handshake and holds the single slot (counter = 1); +# 2. one connection enqueues (slot full) and stays parked -- it is NOT disconnected, so +# only the sweep's max_age expiry removes it; +# 3. after max_age the sweep errors it out -> (unfixed) unmatched decrement -> counter 1->0; +# 4. the holder is closed; its matched decrement lands on the understated counter -> wrap; +# 5. a probe connection's reserve() observes the wrapped counter and the assertion aborts. +# +# args: host port sni +set -u +host="$1" +port="$2" +sni="$3" + +OSSL="openssl s_client -connect ${host}:${port} -servername ${sni} -quiet -no_ign_eof" + +# Run a command in the background and terminate it after a deadline. coreutils "timeout" is not +# available everywhere (notably macOS), so do it with sleep and kill. +run_for() { + deadline="$1" + shift + "$@" & + target=$! + ( + sleep "${deadline}" + kill -TERM "${target}" 2>/dev/null + ) & +} + +# 1. Holder: hold the single slot. Its stdin is a FIFO on fd 3 so we end it in step 4. +fifo_dir="$(mktemp -d "${TMPDIR:-/tmp}/rl_holder.XXXXXX")" +fifo="${fifo_dir}/fifo" +mkfifo "$fifo" +${OSSL} <"$fifo" >/dev/null 2>&1 & +exec 3<>"$fifo" +rm -rf "$fifo_dir" +sleep 3 # let the holder reserve the one slot + +# 2. One queued connection: enqueues and stays parked at the ClientHello hook (not killed), +# so the sweep's max_age expiry -- not a disconnect or a resume -- is what removes it. +${OSSL} /dev/null 2>&1 & +queued=$! +sleep 3 # > max_age (1s) + sweeps: the expiry path errors the queued connection out + +# 4. End the holder: its matched decrement lands on the (unfixed) understated counter. +exec 3>&- +sleep 2 + +# 5. Probe: its reserve() reads the counter; if it wrapped, the release assertion aborts. +run_for 2 sh -c "${OSSL} /dev/null 2>&1" +kill "${queued}" 2>/dev/null || true +sleep 1 + +echo "rate_limit-expiry-done" diff --git a/tests/gold_tests/pluginTest/rate_limit/rate_limit_sni_queue.test.py b/tests/gold_tests/pluginTest/rate_limit/rate_limit_sni_queue.test.py new file mode 100644 index 00000000000..9573cbf2435 --- /dev/null +++ b/tests/gold_tests/pluginTest/rate_limit/rate_limit_sni_queue.test.py @@ -0,0 +1,88 @@ +''' +Regression test for a queue-accounting balance bug in the rate_limit SNI limiter: a +queued connection never reserves a slot, but its VCONN_CLOSE unconditionally releases +one, so a queued connection that closes underflows the active-slot counter and the next +reserve() trips a release assertion, aborting the server. ATS must survive the queue +churn. +''' +# Licensed to the Apache Software Foundation (ASF) under one +# or more contributor license agreements. See the NOTICE file +# distributed with this work for additional information +# regarding copyright ownership. The ASF licenses this file +# to you under the Apache License, Version 2.0 (the +# "License"); you may not use this file except in compliance +# with the License. You may obtain a copy of the License at +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +# See the License for the specific language governing permissions and +# limitations under the License. + +import os + +Test.Summary = __doc__ + +Test.SkipUnless(Condition.PluginExists('rate_limit.so')) + + +class RateLimitSniQueueTest: + """Churn the rate_limit SNI queue and assert the active-slot counter never underflows.""" + + def __init__(self) -> None: + tr = Test.AddTestRun('rate_limit SNI queue accounting') + self._configure_trafficserver() + self._configure_client(tr) + + def _configure_trafficserver(self) -> None: + ts = Test.MakeATSProcess('ts', enable_tls=True, enable_cache=False) + self._ts = ts + ts.addDefaultSSLFiles() + ts.Disk.ssl_multicert_config.AddLine('dest_ip=* ssl_cert_name=server.pem ssl_key_name=server.key') + + # One concurrent handshake for this SNI and a queue that admits exactly one more. + # No rate and no max_age -- the sweep's resume path alone drives the scenario, with + # no rate-bucket or expiry timing to confound it. Named .config (not .yaml) so autest + # treats it as a plain config file; the plugin parses it as YAML regardless. + ts.Disk.MakeConfigFile('rate_limit.config').AddLines( + [ + 'selector:', + ' - sni: rate.limited.com', + ' limit: 1', + ' queue:', + ' size: 1', + ]) + ts.Disk.plugin_config.AddLine(f'rate_limit.so {ts.Variables.CONFIGDIR}/rate_limit.config') + + # Disable the freelist / ProxyAllocator so freed objects are really released rather + # than recycled, keeping allocation reuse from masking a stale access. + ts.Command += ' -f -F' + + ts.Disk.records_config.update( + { + 'proxy.config.ssl.server.cert.path': ts.Variables.SSLDir, + 'proxy.config.ssl.server.private_key.path': ts.Variables.SSLDir, + 'proxy.config.diags.debug.enabled': 1, + 'proxy.config.diags.debug.tags': 'rate_limit', + }) + + # The queue path is reached... + ts.Disk.traffic_out.Content = Testers.ContainsExpression('Queueing the VC', 'a connection was queued') + # ...and the active-slot counter never underflows into the release assertion. Match + # both the specific assertion (pins the failure to this bug) and the generic abort. + ts.Disk.traffic_out.Content += Testers.ExcludesExpression( + '_active <= _limit|received signal', 'the active-slot counter must not underflow and abort ATS') + + def _configure_client(self, tr: 'TestRun') -> None: + ts = self._ts + client = os.path.join(Test.TestDirectory, 'rate_limit_sni_queue_client.sh') + tr.Processes.Default.Command = f'bash {client} 127.0.0.1 {ts.Variables.ssl_port} rate.limited.com' + tr.Processes.Default.ReturnCode = 0 + tr.Processes.Default.StartBefore(ts) + tr.Processes.Default.Streams.stdout = Testers.ContainsExpression( + 'rate_limit-queue-crash-done', 'the client ran to completion') + + +RateLimitSniQueueTest() diff --git a/tests/gold_tests/pluginTest/rate_limit/rate_limit_sni_queue_client.sh b/tests/gold_tests/pluginTest/rate_limit/rate_limit_sni_queue_client.sh new file mode 100644 index 00000000000..0ce7e56f3b1 --- /dev/null +++ b/tests/gold_tests/pluginTest/rate_limit/rate_limit_sni_queue_client.sh @@ -0,0 +1,78 @@ +#!/usr/bin/env bash +# +# 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. +# +# Drive the rate_limit SNI limiter's queue-then-resume path with exactly one queued connection, +# and check that the active-slot counter stays balanced and the server survives. +# +# 1. holder completes its handshake and holds the single slot (counter = 1); +# 2. one connection enqueues because the slot is full, then closes while parked; +# 3. the sweep reserves a slot and resumes a queued connection; +# 4. the holder is closed and releases its slot; +# 5. a probe connection reserves the freed slot. +# +# Against the plugin before 508c1bea26 this aborts the server: the sweep resumed a queued +# connection without a reservation, whose close then decremented the counter unmatched until it +# wrapped and reserve() tripped TSReleaseAssert(_active <= _limit). The test asserts the counter +# never wraps and no signal is logged, so it pins that fix as well as this change. +# +# args: host port sni +set -u +host="$1" +port="$2" +sni="$3" + +OSSL="openssl s_client -connect ${host}:${port} -servername ${sni} -quiet -no_ign_eof" + +# Run a command in the background and terminate it after a deadline. coreutils "timeout" is not +# available everywhere (notably macOS), so do it with sleep and kill. +run_for() { + deadline="$1" + shift + "$@" & + target=$! + ( + sleep "${deadline}" + kill -TERM "${target}" 2>/dev/null + ) & +} + +# 1. Holder: hold the single slot. Its stdin is a FIFO kept open on fd 3, so we end the +# holder deterministically in step 4 (closing fd 3 -> EOF -> clean TLS close -> FIN). +fifo_dir="$(mktemp -d "${TMPDIR:-/tmp}/rl_holder.XXXXXX")" +fifo="${fifo_dir}/fifo" +mkfifo "$fifo" +${OSSL} <"$fifo" >/dev/null 2>&1 & +exec 3<>"$fifo" +rm -rf "$fifo_dir" +sleep 3 # let the holder reserve the one slot + +# 2. One queued connection: enqueues because the slot is full, then closes while still parked +# at the ClientHello hook. +run_for 0.3 sh -c "${OSSL} /dev/null 2>&1" +sleep 2 # >= 2 sweep periods (300ms each), so the sweep runs while the connection is queued + +# 4. End the holder, releasing its slot. +exec 3>&- # close the FIFO write end -> holder sees EOF -> clean TLS close (FIN) +sleep 2 + +# 5. Probe: reserve() must succeed against a balanced counter rather than tripping the +# TSReleaseAssert(_active <= _limit) that a wrapped counter causes. +run_for 2 sh -c "${OSSL} /dev/null 2>&1" +sleep 3 + +echo "rate_limit-queue-crash-done" diff --git a/tests/gold_tests/pluginTest/rate_limit/rate_limit_sni_reject.test.py b/tests/gold_tests/pluginTest/rate_limit/rate_limit_sni_reject.test.py new file mode 100644 index 00000000000..4e279dd9f90 --- /dev/null +++ b/tests/gold_tests/pluginTest/rate_limit/rate_limit_sni_reject.test.py @@ -0,0 +1,82 @@ +''' +Exercise the rate_limit SNI limiter's reject path against a TLS listener, so the +consumer-driven SSLNetVConnection teardown frees every rejected handshake VC +cleanly (no use-after-free or crash). +''' +# Licensed to the Apache Software Foundation (ASF) under one +# or more contributor license agreements. See the NOTICE file +# distributed with this work for additional information +# regarding copyright ownership. The ASF licenses this file +# to you under the Apache License, Version 2.0 (the +# "License"); you may not use this file except in compliance +# with the License. You may obtain a copy of the License at +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +# See the License for the specific language governing permissions and +# limitations under the License. + +import os + +Test.Summary = __doc__ + +Test.SkipUnless(Condition.PluginExists('rate_limit.so')) + + +class RateLimitSniRejectTest: + """Drive rate_limit's SNI reject path and assert ATS frees the VCs without a fault.""" + + def __init__(self) -> None: + tr = Test.AddTestRun('rate_limit SNI reject teardown') + self._configure_trafficserver() + self._configure_client(tr) + + def _configure_trafficserver(self) -> None: + ts = Test.MakeATSProcess('ts', enable_tls=True, enable_cache=False) + self._ts = ts + ts.addDefaultSSLFiles() + ts.Disk.ssl_multicert_config.AddLine('dest_ip=* ssl_cert_name=server.pem ssl_key_name=server.key') + + # One concurrent handshake for this SNI and no queue, so every further concurrent + # handshake is rejected outright (TS_EVENT_ERROR) rather than queued. Named .config + # (not .yaml) so autest treats it as a plain config file; the plugin parses it as + # YAML regardless (YAML::LoadFile). + ts.Disk.MakeConfigFile('rate_limit.config').AddLines([ + 'selector:', + ' - sni: rate.limited.com', + ' limit: 1', + ]) + ts.Disk.plugin_config.AddLine(f'rate_limit.so {ts.Variables.CONFIGDIR}/rate_limit.config') + + # Disable the freelist / ProxyAllocator so a freed SSLNetVConnection is really + # free()'d rather than recycled; a stale-VC access then hits freed memory + # instead of a still-valid recycled object. + ts.Command += ' -f -F' + + ts.Disk.records_config.update( + { + 'proxy.config.ssl.server.cert.path': ts.Variables.SSLDir, + 'proxy.config.ssl.server.private_key.path': ts.Variables.SSLDir, + 'proxy.config.diags.debug.enabled': 1, + 'proxy.config.diags.debug.tags': 'rate_limit', + }) + + # The reject disposition is reached... + ts.Disk.traffic_out.Content = Testers.ContainsExpression('Rejecting connection', 'over-limit handshakes were rejected') + # ...and ATS tears every rejected handshake VC down without a memory-safety fault. + ts.Disk.traffic_out.Content += Testers.ExcludesExpression( + 'use-after-free|attempting free|SEGV|received signal', 'ATS must survive the reject churn') + + def _configure_client(self, tr: 'TestRun') -> None: + ts = self._ts + client = os.path.join(Test.TestDirectory, 'rate_limit_sni_reject_client.sh') + tr.Processes.Default.Command = f'bash {client} 127.0.0.1 {ts.Variables.ssl_port} rate.limited.com' + tr.Processes.Default.ReturnCode = 0 + tr.Processes.Default.StartBefore(ts) + tr.Processes.Default.Streams.stdout = Testers.ContainsExpression('rate_limit-reject-done', 'the client ran to completion') + + +RateLimitSniRejectTest() diff --git a/tests/gold_tests/pluginTest/rate_limit/rate_limit_sni_reject_client.sh b/tests/gold_tests/pluginTest/rate_limit/rate_limit_sni_reject_client.sh new file mode 100644 index 00000000000..8d44b314bcd --- /dev/null +++ b/tests/gold_tests/pluginTest/rate_limit/rate_limit_sni_reject_client.sh @@ -0,0 +1,60 @@ +#!/usr/bin/env bash +# +# 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. +# +# Drive the rate_limit SNI limiter (limit 1, no queue) through its reject path so the +# consumer-driven SSLNetVConnection teardown is exercised for a rejected handshake: +# holder completes the handshake and HOLDS the one slot open; +# a burst of near-simultaneous handshakes then arrives while the slot is taken and, +# with no queue configured, each is REJECTED with TS_EVENT_ERROR mid-handshake. +# ATS must free every one of these rejected handshake VCs cleanly. +# +# args: host port sni +set -u +host="$1" +port="$2" +sni="$3" + +OSSL="openssl s_client -connect ${host}:${port} -servername ${sni} -quiet -no_ign_eof" + +# Run a command in the background and terminate it after a deadline. coreutils "timeout" is not +# available everywhere (notably macOS), so do it with sleep and kill. +run_for() { + deadline="$1" + shift + "$@" & + target=$! + ( + sleep "${deadline}" + kill -TERM "${target}" 2>/dev/null + ) & +} + +# holder: complete the handshake and hold the single slot for ~5s (slow stdin keeps it open). +(sleep 5) | ${OSSL} >/dev/null 2>&1 & +sleep 2 # let the holder reserve the slot + +# Burst of near-simultaneous handshakes against the full limiter; with no queue every one +# is rejected with TS_EVENT_ERROR, so its handshake VC is torn down consumer-driven. +for _ in $(seq 5); do + run_for 2 sh -c "${OSSL} /dev/null 2>&1" +done + +# Let the burst finish and the holder release its slot cleanly. +sleep 4 + +echo "rate_limit-reject-done" diff --git a/tests/gold_tests/tls_hooks/tls_hooks_close_while_parked.test.py b/tests/gold_tests/tls_hooks/tls_hooks_close_while_parked.test.py new file mode 100644 index 00000000000..1bf00bc329b --- /dev/null +++ b/tests/gold_tests/tls_hooks/tls_hooks_close_while_parked.test.py @@ -0,0 +1,82 @@ +''' +Verify that a plugin's VCONN_CLOSE hook runs when the connection closes while it is +parked in a TLS handshake hook. +''' +# Licensed to the Apache Software Foundation (ASF) under one +# or more contributor license agreements. See the NOTICE file +# distributed with this work for additional information +# regarding copyright ownership. The ASF licenses this file +# to you under the Apache License, Version 2.0 (the +# "License"); you may not use this file except in compliance +# with the License. You may obtain a copy of the License at +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +# See the License for the specific language governing permissions and +# limitations under the License. + +import os + +Test.Summary = ''' +A connection that closes while parked in a TLS handshake hook must still deliver +TS_VCONN_CLOSE_HOOK to the plugin. +''' + +Test.SkipUnless(Condition.HasOpenSSLVersion("1.1.1"),) + +ts = Test.MakeATSProcess("ts", enable_tls=True) +server = Test.MakeOriginServer("server") +server.addResponse( + "sessionlog.json", { + "headers": "GET / HTTP/1.1\r\nHost: www.example.com\r\n\r\n", + "timestamp": "1469733493.993", + "body": "" + }, { + "headers": "HTTP/1.1 200 OK\r\nConnection: close\r\n\r\n", + "timestamp": "1469733493.993", + "body": "" + }) + +ts.addDefaultSSLFiles() + +ts.Disk.records_config.update( + { + 'proxy.config.diags.debug.enabled': 1, + 'proxy.config.diags.show_location': 0, + 'proxy.config.diags.debug.tags': 'ssl_hook_test', + # Fire the handshake timeout while the plugin still has the handshake parked (2s park). + 'proxy.config.ssl.handshake_timeout_in': 1, + 'proxy.config.ssl.server.cert.path': '{0}'.format(ts.Variables.SSLDir), + 'proxy.config.ssl.server.private_key.path': '{0}'.format(ts.Variables.SSLDir), + }) + +ts.Disk.ssl_multicert_config.AddLine('dest_ip=* ssl_cert_name=server.pem ssl_key_name=server.key') + +ts.Disk.remap_config.AddLine( + 'map https://example.com:{1} http://127.0.0.1:{0}'.format(server.Variables.Port, ts.Variables.ssl_port)) + +# The delayed client hello callback parks the handshake for 2 seconds before it reenables. +Test.PrepareTestPlugin(os.path.join(Test.Variables.AtsTestPluginsDir, 'ssl_hook_test.so'), ts, '-client_hello=1 -close=1') + +# Give up after 1 second, which is inside the 2 second park, so the connection closes while it +# is still suspended in the client hello hook. curl reports operation timed out (exit 28). +tr = Test.AddTestRun("Client disconnects while parked in the client hello hook") +tr.Processes.Default.StartBefore(server) +tr.Processes.Default.StartBefore(Test.Processes.ts) +tr.StillRunningAfter = ts +tr.StillRunningAfter = server +tr.MakeCurlCommand('-k --max-time 1 -H \'host:example.com:{0}\' https://127.0.0.1:{0}'.format(ts.Variables.ssl_port), ts=ts) +tr.Processes.Default.ReturnCode = 28 +tr.Processes.Default.TimeOut = 15 +tr.TimeOut = 15 + +# The handshake really was parked. +ts.Disk.traffic_out.Content = Testers.ContainsExpression("Client Hello callback 0", "the handshake parked in the client hello hook") + +# The close hook must still fire, with the correct event. Before the fix, callHooks() advanced +# curHook within the client hello hook list instead of the close hook list, so this never ran. +ts.Disk.traffic_out.Content += Testers.ContainsExpression( + "Close callback 0 .* - event is good", "the close hook ran for the parked connection")