TSHttpTxnCacheLookupStatusGet: handle cannot respond cases

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] "

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

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;

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

tests/gold_tests/cache/cache-request-method.test.py

@@ -17,18 +17,24 @@
 #  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.
 '''
 
 # 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

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

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

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

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 <ts/ts.h>   // for debug
+#include <cstdlib>   // for abort
+#include <cinttypes> // for PRId64
+#include <string_view>
+#include <unordered_map>
+
+namespace
+{
+constexpr char const *PLUGIN_NAME = "print_cache_status";
+static TSTextLogObject pluginlog;
+
+std::unordered_map<int, std::string_view> 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<TSHttpTxn>(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);
+  }
+}