bneradt commented on issue #8539: URL: https://github.com/apache/trafficserver/issues/8539#issuecomment-984973130
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 = "[email protected]";
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 a:
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.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: [email protected]
For queries about this service, please contact Infrastructure at:
[email protected]
