CACHE_LOOKUP_HIT_FRESH status for POST request is not good

[fdiary]

Hi !

If ATS receives a POST request to 'fresh cache existing' URL, we have CACHE_LOOKUP_HIT_FRESH status. But ATS will never return such fresh cache unless proxy.config.http.cache.post_method is 1, regardless if POST request (that should be always sent to the backend) succeeds or not. I believe the status should be something else for such 'fresh cache exists but it will not be served' case, by the following reason.

[background]

I am writing a Lua plugin script, that modifies response body. To do that, I want uncompressed response from the backend, thus I use compress plugin, later than lua plugin in plugin.config, to 'remove Accept-Encoding sent to the backend' and 'compress response from ATS'.

• plugin.config

tslua.so modify_body.lua
compress.so compress.config

• modify_body.lua

function do_global_read_response()
    ts.hook(TS_LUA_HOOK_SEND_RESPONSE_HDR, modify_body)
end

function do_global_cache_lookup_complete()
    if ts.http.get_cache_lookup_status() == TS_LUA_CACHE_LOOKUP_HIT_FRESH then
        ts.hook(TS_LUA_HOOK_SEND_RESPONSE_HDR, modify_body)
    end
end

function modify_body(data, end_of_stream)
    ...
end

• compress.config

cache false
remove-accept-encoding true
compressible-content-type text/*

In case of GET request having fresh cache,

1. (lua) cache_lookup_complete; register transform hook to modify body, because of CACHE_LOOKUP_HIT_FRESH status
2. (compress) cache_lookup_complete: register transform hook to compress response, because of CACHE_LOOKUP_HIT_FRESH status

trafficserver/plugins/compress/compress.cc

Lines 884 to 891 in d0a44f8

	case TS_EVENT_HTTP_CACHE_LOOKUP_COMPLETE: {
	int obj_status;
	if (TS_ERROR != TSHttpTxnCacheLookupStatusGet(txnp, &obj_status) && (TS_CACHE_LOOKUP_HIT_FRESH == obj_status)) {
	if (hc != nullptr) {
	info("handling compression of cached object");
	if (transformable(txnp, false, hc, &compress_type, &algorithms)) {
	compress_transform_add(txnp, hc, compress_type, algorithms);

So transform is invoked 1. -> 2. order, that is good.

In case of GET/POST request without fresh cache,

1. (lua) cache_lookup_complete; do nothing, because of non-CACHE_LOOKUP_HIT_FRESH status
2. (compress) cache_lookup_complete: do nothing, because of non-CACHE_LOOKUP_HIT_FRESH status
3. (lua) read_response; register transform hook to modify body
4. (compress) read_response: register transform hook to compress response

So transform is invoked 3. -> 4. order, that is good.

in case of POST request having fresh cache, the following will happen,

1. (lua) cache_lookup_complete; register transform hook to modify body, because of CACHE_LOOKUP_HIT_FRESH status, but it is not used as we will anyway have another response from the backend
2. (compress) cache_lookup_complete: register transform hook to compress response, because of CACHE_LOOKUP_HIT_FRESH status
3. (lua) read_response; register transform hook to modify body
4. (compress) read_response: compress plugin does NOT register transform hook, if it is done in cache_lookup_complete stage.

So transform is invoked 2. -> 3. order for the final response, that is NOT good, i.e. for the 'response from the backend to this POST request', compress plugin's compress transform is invoked first, thus Lua script's modify_body function gets compressed result.

(also compress plugin does nothing in send_request timing if transform is registered in cache_lookup_complete timing, remove-access-encoding true is not effective for this case)

To avoid this issue, I patched compress plugin so that it does NOT register transform hook in cache_lookup_complete timing, in case of POST request. But similar issue can happen for any plugin and it breaks expected hook timing order by plugin order in plugin.config.

This is why I would like to propose another status than CACHE_LOOKUP_HIT_FRESH for 'fresh cache exists but it will not be served' case.

Thanks in advance !
Kazuhiko

[SolidWallOfCode]

Does this happen in only POST is used for the URL? Or does it require having done a GET previously that was cached? The question is, how does a POST yield a hit fresh if POST requests aren't cached?

[bneradt]

@fdiary : can you please write an autest for this? If not, can you provide a set of curl commands that would reproduce this so that someone else can write the autest for it.

[fdiary]

@SolidWallOfCode

does it require having done a GET previously that was cached?

Yes.

Imagine we have the following chronological requests in the same URL :

1. GET : CACHE_LOOKUP_HIT_MISS -> fetch from the origin server, then respond it and store in cache
2. GET : CACHE_LOOKUP_HIT_FRESH -> fetch from the cache, then respond it
3. POST : CACHE_LOOKUP_HIT_FRESH -> but fetch from the origin server, then respond it and invalidate the existing cache
4. POST : CACHE_LOOKUP_MISS -> fetch from the origin server, then respond and do NOT store in cache

And the issue here is in 3. case above, i.e. compress plugin implementation does not assume "CACHE_LOOKUP_HIT_FRESH but fetch from the origin server" case.

[fdiary]

@bneradt Let me first show the minimal example of the following issue :

(also compress plugin does nothing in send_request timing if transform is registered in cache_lookup_complete timing, remove-access-encoding true is not effective for this case)

• dump_accept_encoding.py

#!/usr/bin/env python3
import http.server as SimpleHTTPServer
import socketserver as SocketServer

PORT = 8888

class TestHandler(SimpleHTTPServer.SimpleHTTPRequestHandler):

  def do_GET(self):
    self.send_response(200)
    self.send_header('Content-Type', 'text/plain')
    self.send_header('Cache-Control', 'max-age=60')
    result = bytes(str(self.headers.get('Accept-Encoding')) + '\n', 'utf-8')
    self.send_header('Content-Length', len(result))
    self.end_headers()
    self.wfile.write(result)

  do_POST = do_GET

httpd = SocketServer.TCPServer(("", PORT), TestHandler)

httpd.serve_forever()

• plugin.config

compress.so compress.config

• compress.config

cache false
remove-accept-encoding true
compressible-content-type text/*

Now let's show the result of the 4 requests as written in the previous comment :

$ curl -X GET -H 'Accept-Encoding: gzip' http://localhost:8080/
None <- Accept-Encoding is stripped in the request to the origin server
$ curl -X GET -H 'Accept-Encoding: gzip' http://localhost:8080/
None <- cached result, same as above
$ curl -X POST -H 'Accept-Encoding: gzip' -H 'Content-Length: 0' http://localhost:8080/
gzip <- Accept-Encoding is NOT stripped in the request to the origin server
$ curl -X POST -H 'Accept-Encoding: gzip' -H 'Content-Length: 0' http://localhost:8080/
None <- Accept-Encoding is stripped in the request to the origin server

As you can see, CACHE_LOOKUP_HIT_FRESH is not a proper enough condition to know 'ATS will return a cached response'. But I'm wondering what should be the way to go.

• we should have another state than CACHE_LOOKUP_HIT_FRESH ?

• each plugin should implement the same logic as does_method_require_cache_copy_deletion ?
  

  trafficserver/proxy/http/HttpTransact.cc

  Lines 727 to 733 in 420935b

  	inline static bool
  	does_method_require_cache_copy_deletion(const HttpConfigParams *http_config_param, const int method)
  	{
  	return ((method != HTTP_WKSIDX_GET) &&
  	(method == HTTP_WKSIDX_DELETE || method == HTTP_WKSIDX_PURGE || method == HTTP_WKSIDX_PUT ||
  	(http_config_param->cache_post_method != 1 && method == HTTP_WKSIDX_POST)));
  	}

• we should introduce another hook like READ_CACHE_RESPONSE_HOOK when we are really sending a cache response ?

[bneradt]

Thank you @fdiary for these details. This is helpful. I'll start by working on a test for this.

[bneradt]

I've created and added the following plugin to the cache-request-method.test.py test. It reproduces the issue by printing the cache status which it sees:

  @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";

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);
    }
    TSDebug(PLUGIN_NAME, "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);
  }

  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);
  }
}

The test is updated with:

$ git diff master -- tests/gold_tests/cache/cache-request-method.test.py
diff --git a/tests/gold_tests/cache/cache-request-method.test.py b/tests/gold_tests/cache/cache-request-method.test.py
index 5715e812a..d21dec035 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 @@ Verify correct caching behavior with respect to request method.
 #  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,13 @@ 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)
 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
@@ -46,11 +50,13 @@ tr.AddVerifierClientProcess("client0", replay_file, http_ports=[ts.Variables.por
 # 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)
 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,
 })

Running the test gives this output:

$ grep print_cache_status /tmp/sbcr/cache-request-method/_output/cache-request-method-ts/stream.all.txt                                                                                                                                                                                            
[Dec  2 19:55:46.134] traffic_server DIAG: (print_cache_status) initializing plugin
[Dec  2 19:55:46.173] [ET_NET 3] DIAG: (print_cache_status) Cache lookup status: TS_CACHE_LOOKUP_MISS
[Dec  2 19:55:46.287] [ET_NET 3] DIAG: (print_cache_status) Cache lookup status: TS_CACHE_LOOKUP_HIT_FRESH
[Dec  2 19:55:46.296] [ET_NET 3] DIAG: (print_cache_status) Cache lookup status: TS_CACHE_LOOKUP_HIT_FRESH
[Dec  2 19:55:46.410] [ET_NET 3] DIAG: (print_cache_status) Cache lookup status: TS_CACHE_LOOKUP_MISS
[Dec  2 19:55:46.526] [ET_NET 3] DIAG: (print_cache_status) Cache lookup status: TS_CACHE_LOOKUP_HIT_FRESH
[Dec  2 19:55:46.534] [ET_NET 3] DIAG: (print_cache_status) Cache lookup status: TS_CACHE_LOOKUP_HIT_FRESH
[Dec  2 19:55:46.646] [ET_NET 3] DIAG: (print_cache_status) Cache lookup status: TS_CACHE_LOOKUP_HIT_FRESH

The test does the following:

1. GET for a resource. Should be a miss and it is (good).
2. Repeats the GET. Should be a hit and it is (good).
3. Does a POST for the resource. This results in a hit, which this ticket records as confusing to the plugin because the resource is actually rejected because the methods don't line up. This, therefore, is reproducing the behavior this ticket records.
4. The 200 OK to the previous POST invalidates the resource. The GET is therefore a miss, which is good.
5. A GET is repeated, which replies out of cache. This should be a hit and it is (good).
6. A POST is repeated, which again replies with a HIT. This also reproduces what is described in this ticket.
7. Unlike before, the server replies to the POST with an error response. Thus the original resource is not invalidated. A GET is made for the resource which receives a hit, which is good.

Thus requests 3 and 6 reproduce this problem described in this ticket.

[bneradt]

Now that we've reproduced this with a test, we'll have to consider how to handle this. I'm a little leery about changing this cache_lookup_result variable because both the HttpSM.cc and HttpTransact.cc make use of the cache_lookup_result in a way that looks potentially sensitive. I don't want to break things in a non-obvious way. I'll tinker around a bit and see what our options are.

[bneradt]

@fdiary : I created #8545 for this. For these situations where there is a cached resource but the request methods don't line up, the patch will cause TSHttpTxnCacheLookupStatusGet to now return a TS_CACHE_LOOKUP_MISS instead of a TS_CACHE_LOOKUP_HIT_FRESH. I think this will address your situation, but can you please confirm this?

[fdiary]

@bneradt Thanks for your great effort !

Yes, exactly. The change in #8545 will solve this issue, without any change on existing plugins. If there isn't any bad side effect with it, it should be the best solution, in my opinion.