From fd0d2304a79b1accd7abb65ef6607f366214c8cf Mon Sep 17 00:00:00 2001 From: Brian Neradt Date: Thu, 2 Dec 2021 00:43:57 +0000 Subject: [PATCH] TSHttpTxnCacheLookupStatusGet: handle cannot respond cases ATS initially experiences cache lookups as a HIT for resources that we ultimately cannot use due to a need for authentication or if the methods for the incoming request and that of the request for the cached response don't match. Our TSHttpTxnCacheLookupStatusGet plugin interface returned the initial HIT status instead of marking these as MISSES. This patch changes the status to return a MISS in these circumstances. Closes #8539 --- proxy/http/HttpTransact.cc | 22 ++--- proxy/http/HttpTransact.h | 7 ++ src/traffic_server/InkAPI.cc | 6 +- tests/Makefile.am | 1 + .../cache/cache-request-method.test.py | 30 ++++++- ...rint_cache_status_cache_post_disabled.gold | 7 ++ ...print_cache_status_cache_post_enabled.gold | 10 +++ tests/gold_tests/cache/plugins/Makefile.inc | 18 ++++ .../cache/plugins/print_cache_status.cc | 89 +++++++++++++++++++ 9 files changed, 177 insertions(+), 13 deletions(-) create mode 100644 tests/gold_tests/cache/gold/print_cache_status_cache_post_disabled.gold create mode 100644 tests/gold_tests/cache/gold/print_cache_status_cache_post_enabled.gold create mode 100644 tests/gold_tests/cache/plugins/Makefile.inc create mode 100644 tests/gold_tests/cache/plugins/print_cache_status.cc diff --git a/proxy/http/HttpTransact.cc b/proxy/http/HttpTransact.cc index ac8a1df1406..7a46aa4f40f 100644 --- a/proxy/http/HttpTransact.cc +++ b/proxy/http/HttpTransact.cc @@ -2757,12 +2757,13 @@ HttpTransact::need_to_revalidate(State *s) needs_revalidate = false; } - bool send_revalidate = ((needs_authenticate == true) || (needs_revalidate == true) || (is_cache_response_returnable(s) == false)); + s->cache_hit_but_revalidate = + ((needs_authenticate == true) || (needs_revalidate == true) || (is_cache_response_returnable(s) == false)); if (needs_cache_auth == true) { - s->www_auth_content = send_revalidate ? CACHE_AUTH_STALE : CACHE_AUTH_FRESH; - send_revalidate = true; + s->www_auth_content = s->cache_hit_but_revalidate ? CACHE_AUTH_STALE : CACHE_AUTH_FRESH; + s->cache_hit_but_revalidate = true; } - return send_revalidate; + return s->cache_hit_but_revalidate; } /////////////////////////////////////////////////////////////////////////////// @@ -2881,21 +2882,21 @@ HttpTransact::HandleCacheOpenReadHit(State *s) // do we need to revalidate. in other words if the response // has to be authorized, is stale or can not be returned, do // a revalidate. - bool send_revalidate = (needs_authenticate || needs_revalidate || !response_returnable); + s->cache_hit_but_revalidate = (needs_authenticate || needs_revalidate || !response_returnable); if (needs_cache_auth == true) { SET_VIA_STRING(VIA_DETAIL_CACHE_LOOKUP, VIA_DETAIL_MISS_EXPIRED); - s->www_auth_content = send_revalidate ? CACHE_AUTH_STALE : CACHE_AUTH_FRESH; - send_revalidate = true; + s->www_auth_content = s->cache_hit_but_revalidate ? CACHE_AUTH_STALE : CACHE_AUTH_FRESH; + s->cache_hit_but_revalidate = true; } TxnDebug("http_trans", "CacheOpenRead --- needs_auth = %d", needs_authenticate); TxnDebug("http_trans", "CacheOpenRead --- needs_revalidate = %d", needs_revalidate); TxnDebug("http_trans", "CacheOpenRead --- response_returnable = %d", response_returnable); TxnDebug("http_trans", "CacheOpenRead --- needs_cache_auth = %d", needs_cache_auth); - TxnDebug("http_trans", "CacheOpenRead --- send_revalidate = %d", send_revalidate); + TxnDebug("http_trans", "CacheOpenRead --- send_revalidate = %d", s->cache_hit_but_revalidate); - if (send_revalidate) { + if (s->cache_hit_but_revalidate) { TxnDebug("http_trans", "CacheOpenRead --- HIT-STALE"); TxnDebug("http_seq", "[HttpTransact::HandleCacheOpenReadHit] " @@ -2997,7 +2998,8 @@ HttpTransact::HandleCacheOpenReadHit(State *s) // realistically, if we can not make this claim, then there // is no reason to cache anything. // - ink_assert((send_revalidate == true && server_up == false) || (send_revalidate == false && server_up == true)); + ink_assert((s->cache_hit_but_revalidate == true && server_up == false) || + (s->cache_hit_but_revalidate == false && server_up == true)); TxnDebug("http_trans", "CacheOpenRead --- HIT-FRESH"); TxnDebug("http_seq", "[HttpTransact::HandleCacheOpenReadHit] " diff --git a/proxy/http/HttpTransact.h b/proxy/http/HttpTransact.h index 2ec1e45af6a..ec4a9d78685 100644 --- a/proxy/http/HttpTransact.h +++ b/proxy/http/HttpTransact.h @@ -700,6 +700,13 @@ class HttpTransact ParentResult parent_result; CacheControlResult cache_control; CacheLookupResult_t cache_lookup_result = CACHE_LOOKUP_NONE; + /** There was a cache hit, but the cached resource cannot be used. + * + * This may happen because it is stale, it needs authentication, or the + * request method of the incoming request doesn't match that of the request + * corresponding to the cached resource. + */ + bool cache_hit_but_revalidate = false; StateMachineAction_t next_action = SM_ACTION_UNDEFINED; // out StateMachineAction_t api_next_action = SM_ACTION_UNDEFINED; // out diff --git a/src/traffic_server/InkAPI.cc b/src/traffic_server/InkAPI.cc index f43796cad4f..c9500972bf5 100644 --- a/src/traffic_server/InkAPI.cc +++ b/src/traffic_server/InkAPI.cc @@ -5429,7 +5429,11 @@ TSHttpTxnCacheLookupStatusGet(TSHttpTxn txnp, int *lookup_status) break; case HttpTransact::CACHE_LOOKUP_HIT_WARNING: case HttpTransact::CACHE_LOOKUP_HIT_FRESH: - *lookup_status = TS_CACHE_LOOKUP_HIT_FRESH; + if (sm->t_state.cache_hit_but_revalidate) { + *lookup_status = TS_CACHE_LOOKUP_MISS; + } else { + *lookup_status = TS_CACHE_LOOKUP_HIT_FRESH; + } break; case HttpTransact::CACHE_LOOKUP_SKIPPED: *lookup_status = TS_CACHE_LOOKUP_SKIPPED; diff --git a/tests/Makefile.am b/tests/Makefile.am index 391078815e5..81e7a1505e7 100644 --- a/tests/Makefile.am +++ b/tests/Makefile.am @@ -31,6 +31,7 @@ AM_LDFLAGS += $(TS_PLUGIN_LD_FLAGS) AM_LDFLAGS += -rpath $(abs_builddir) include gold_tests/bigobj/Makefile.inc +include gold_tests/cache/plugins/Makefile.inc include gold_tests/continuations/plugins/Makefile.inc include gold_tests/chunked_encoding/Makefile.inc include gold_tests/pluginTest/tsapi/Makefile.inc diff --git a/tests/gold_tests/cache/cache-request-method.test.py b/tests/gold_tests/cache/cache-request-method.test.py index 5715e812a14..2db75f82f6c 100644 --- a/tests/gold_tests/cache/cache-request-method.test.py +++ b/tests/gold_tests/cache/cache-request-method.test.py @@ -17,6 +17,8 @@ # See the License for the specific language governing permissions and # limitations under the License. +import os + Test.Summary = ''' Verify correct caching behavior with respect to request method. ''' @@ -24,11 +26,15 @@ # Test 0: Verify correct POST response handling when caching POST responses is # disabled. ts = Test.MakeATSProcess("ts") +Test.PrepareTestPlugin(os.path.join(Test.Variables.AtsBuildGoldTestsDir, + 'cache', 'plugins', '.libs', 'print_cache_status.so'), ts) +Test.Disk.File(os.path.join(ts.Variables.LOGDIR, 'print_cache_status.log'), + exists=True, content='gold/print_cache_status_cache_post_disabled.gold') replay_file = "replay/post_with_post_caching_disabled.replay.yaml" server = Test.MakeVerifierServerProcess("server0", replay_file) ts.Disk.records_config.update({ 'proxy.config.diags.debug.enabled': 1, - 'proxy.config.diags.debug.tags': 'http.*|cache.*', + 'proxy.config.diags.debug.tags': 'http|cache|print_cache_status', 'proxy.config.http.insert_age_in_response': 0, # Caching of POST responses is disabled by default. Verify default behavior @@ -43,14 +49,26 @@ tr.Processes.Default.StartBefore(ts) tr.AddVerifierClientProcess("client0", replay_file, http_ports=[ts.Variables.port]) +# Wait for log file to appear, then wait one extra second to make sure TS is done writing it. +test_run = Test.AddTestRun() +test_run.Processes.Default.Command = ( + os.path.join(Test.Variables.AtsTestToolsDir, 'condwait') + ' 60 1 -f ' + + os.path.join(ts.Variables.LOGDIR, 'print_cache_status.log') +) +test_run.Processes.Default.ReturnCode = 0 + # Test 1: Verify correct POST response handling when caching POST responses is # enabled. ts = Test.MakeATSProcess("ts-cache-post") +Test.PrepareTestPlugin(os.path.join(Test.Variables.AtsBuildGoldTestsDir, + 'cache', 'plugins', '.libs', 'print_cache_status.so'), ts) +Test.Disk.File(os.path.join(ts.Variables.LOGDIR, 'print_cache_status.log'), + exists=True, content='gold/print_cache_status_cache_post_enabled.gold') replay_file = "replay/post_with_post_caching_enabled.replay.yaml" server = Test.MakeVerifierServerProcess("server1", replay_file) ts.Disk.records_config.update({ 'proxy.config.diags.debug.enabled': 1, - 'proxy.config.diags.debug.tags': 'http.*|cache.*', + 'proxy.config.diags.debug.tags': 'http|cache|print_cache_status', 'proxy.config.http.insert_age_in_response': 0, 'proxy.config.http.cache.post_method': 1, }) @@ -61,3 +79,11 @@ tr.Processes.Default.StartBefore(server) tr.Processes.Default.StartBefore(ts) tr.AddVerifierClientProcess("client1", replay_file, http_ports=[ts.Variables.port]) + +# Wait for log file to appear, then wait one extra second to make sure TS is done writing it. +test_run = Test.AddTestRun() +test_run.Processes.Default.Command = ( + os.path.join(Test.Variables.AtsTestToolsDir, 'condwait') + ' 60 1 -f ' + + os.path.join(ts.Variables.LOGDIR, 'print_cache_status.log') +) +test_run.Processes.Default.ReturnCode = 0 diff --git a/tests/gold_tests/cache/gold/print_cache_status_cache_post_disabled.gold b/tests/gold_tests/cache/gold/print_cache_status_cache_post_disabled.gold new file mode 100644 index 00000000000..90e2e8d7d0f --- /dev/null +++ b/tests/gold_tests/cache/gold/print_cache_status_cache_post_disabled.gold @@ -0,0 +1,7 @@ +`` Cache lookup status: TS_CACHE_LOOKUP_MISS +`` Cache lookup status: TS_CACHE_LOOKUP_HIT_FRESH +`` Cache lookup status: TS_CACHE_LOOKUP_MISS +`` Cache lookup status: TS_CACHE_LOOKUP_MISS +`` Cache lookup status: TS_CACHE_LOOKUP_HIT_FRESH +`` Cache lookup status: TS_CACHE_LOOKUP_MISS +`` Cache lookup status: TS_CACHE_LOOKUP_HIT_FRESH diff --git a/tests/gold_tests/cache/gold/print_cache_status_cache_post_enabled.gold b/tests/gold_tests/cache/gold/print_cache_status_cache_post_enabled.gold new file mode 100644 index 00000000000..f795b2951c6 --- /dev/null +++ b/tests/gold_tests/cache/gold/print_cache_status_cache_post_enabled.gold @@ -0,0 +1,10 @@ +`` Cache lookup status: TS_CACHE_LOOKUP_MISS +`` Cache lookup status: TS_CACHE_LOOKUP_HIT_FRESH +`` Cache lookup status: TS_CACHE_LOOKUP_MISS +`` Cache lookup status: TS_CACHE_LOOKUP_HIT_FRESH +`` Cache lookup status: TS_CACHE_LOOKUP_MISS +`` Cache lookup status: TS_CACHE_LOOKUP_HIT_FRESH +`` Cache lookup status: TS_CACHE_LOOKUP_MISS +`` Cache lookup status: TS_CACHE_LOOKUP_MISS +`` Cache lookup status: TS_CACHE_LOOKUP_MISS +`` Cache lookup status: TS_CACHE_LOOKUP_HIT_FRESH diff --git a/tests/gold_tests/cache/plugins/Makefile.inc b/tests/gold_tests/cache/plugins/Makefile.inc new file mode 100644 index 00000000000..1b0b7baf920 --- /dev/null +++ b/tests/gold_tests/cache/plugins/Makefile.inc @@ -0,0 +1,18 @@ +# 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. + +noinst_LTLIBRARIES += gold_tests/cache/plugins/print_cache_status.la +gold_tests_cache_plugins_print_cache_status_la_SOURCES = gold_tests/cache/plugins/print_cache_status.cc diff --git a/tests/gold_tests/cache/plugins/print_cache_status.cc b/tests/gold_tests/cache/plugins/print_cache_status.cc new file mode 100644 index 00000000000..531b6aa4c6c --- /dev/null +++ b/tests/gold_tests/cache/plugins/print_cache_status.cc @@ -0,0 +1,89 @@ +/** + @file + @brief A plugin that prints the cache lookup status. + + @section license License + + Licensed to the Apache Software Foundation (ASF) under one + or more contributor license agreements. See the NOTICE file + distributed with this work for additional information + regarding copyright ownership. The ASF licenses this file + to you under the Apache License, Version 2.0 (the + "License"); you may not use this file except in compliance + with the License. You may obtain a copy of the License at + + http://www.apache.org/licenses/LICENSE-2.0 + + Unless required by applicable law or agreed to in writing, software + distributed under the License is distributed on an "AS IS" BASIS, + WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + See the License for the specific language governing permissions and + limitations under the License. +*/ +#include // for debug +#include // for abort +#include // for PRId64 +#include +#include + +namespace +{ +constexpr char const *PLUGIN_NAME = "print_cache_status"; +static TSTextLogObject pluginlog; + +std::unordered_map lookup_status_to_string = { + {TS_CACHE_LOOKUP_MISS, "TS_CACHE_LOOKUP_MISS"}, + {TS_CACHE_LOOKUP_HIT_STALE, "TS_CACHE_LOOKUP_HIT_STALE"}, + {TS_CACHE_LOOKUP_HIT_FRESH, "TS_CACHE_LOOKUP_HIT_FRESH"}, + {TS_CACHE_LOOKUP_SKIPPED, "TS_CACHE_LOOKUP_SKIPPED"}, +}; + +int +global_handler(TSCont continuation, TSEvent event, void *data) +{ + TSHttpTxn txnp = static_cast(data); + + switch (event) { + case TS_EVENT_HTTP_CACHE_LOOKUP_COMPLETE: { + int obj_status = 0; + if (TS_ERROR == TSHttpTxnCacheLookupStatusGet(txnp, &obj_status)) { + TSError("[%s] TSHttpTxnCacheLookupStatusGet failed", PLUGIN_NAME); + } + TSTextLogObjectWrite(pluginlog, "Cache lookup status: %s", lookup_status_to_string[obj_status].data()); + } break; + + default: + TSError("[%s] Unexpected event: %d", PLUGIN_NAME, event); + return 0; + } + + TSHttpTxnReenable(txnp, TS_EVENT_HTTP_CONTINUE); + + return 0; +} +} // anonymous namespace + +void +TSPluginInit(int argc, const char *argv[]) +{ + TSDebug(PLUGIN_NAME, "initializing plugin"); + + TSPluginRegistrationInfo info; + + info.plugin_name = PLUGIN_NAME; + info.vendor_name = "Apache"; + info.support_email = "bneradt@apache.org"; + + if (TSPluginRegister(&info) != TS_SUCCESS) { + TSError("[%s] Plugin registration failed.", PLUGIN_NAME); + } + TSAssert(TS_SUCCESS == TSTextLogObjectCreate(PLUGIN_NAME, TS_LOG_MODE_ADD_TIMESTAMP, &pluginlog)); + + TSCont contp = TSContCreate(global_handler, TSMutexCreate()); + if (contp == nullptr) { + TSError("[%s] could not create continuation.", PLUGIN_NAME); + std::abort(); + } else { + TSHttpHookAdd(TS_HTTP_CACHE_LOOKUP_COMPLETE_HOOK, contp); + } +}