You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@trafficserver.apache.org by GitBox <gi...@apache.org> on 2022/01/31 21:01:40 UTC
[GitHub] [trafficserver] fdiary opened a new issue #8539: CACHE_LOOKUP_HIT_FRESH status for POST request is not good
fdiary opened a new issue #8539:
URL: https://github.com/apache/trafficserver/issues/8539
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
```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
https://github.com/apache/trafficserver/blob/d0a44f86345c9125946978efbbf837a720fc9537/plugins/compress/compress.cc#L884-L891
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
--
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: issues-unsubscribe@trafficserver.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [trafficserver] bneradt commented on issue #8539: CACHE_LOOKUP_HIT_FRESH status for POST request is not good
Posted by GitBox <gi...@apache.org>.
bneradt commented on issue #8539:
URL: https://github.com/apache/trafficserver/issues/8539#issuecomment-984081715
Thank you @fdiary for these details. This is helpful. I'll start by working on a test for this.
--
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: issues-unsubscribe@trafficserver.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [trafficserver] SolidWallOfCode commented on issue #8539: CACHE_LOOKUP_HIT_FRESH status for POST request is not good
Posted by GitBox <gi...@apache.org>.
SolidWallOfCode commented on issue #8539:
URL: https://github.com/apache/trafficserver/issues/8539#issuecomment-982161141
Does this happen in only `POST` is used for the URL? Or does it require having done a `GET` previously that was cached?
--
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: issues-unsubscribe@trafficserver.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [trafficserver] bneradt closed issue #8539: CACHE_LOOKUP_HIT_FRESH status for POST request is not good
Posted by GitBox <gi...@apache.org>.
bneradt closed issue #8539:
URL: https://github.com/apache/trafficserver/issues/8539
--
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: issues-unsubscribe@trafficserver.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [trafficserver] bneradt commented on issue #8539: CACHE_LOOKUP_HIT_FRESH status for POST request is not good
Posted by GitBox <gi...@apache.org>.
bneradt commented on issue #8539:
URL: https://github.com/apache/trafficserver/issues/8539#issuecomment-1026208322
It has proven tricky to both reliably fix this issue without introducing other issues. My first patch, while stable, got broken by a change in the way things are ordered in the HttpSM, while my second patch, while presumably more reliable wrt this issue, introduced crashes in some situations. I'll try to swing back around to this issue later. For now I backed out both patches to ensure stability in 9.2.x and master.
--
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: issues-unsubscribe@trafficserver.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [trafficserver] fdiary commented on issue #8539: CACHE_LOOKUP_HIT_FRESH status for POST request is not good
Posted by GitBox <gi...@apache.org>.
fdiary commented on issue #8539:
URL: https://github.com/apache/trafficserver/issues/8539#issuecomment-985104853
@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.
--
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: issues-unsubscribe@trafficserver.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [trafficserver] bneradt edited a comment on issue #8539: CACHE_LOOKUP_HIT_FRESH status for POST request is not good
Posted by GitBox <gi...@apache.org>.
bneradt edited a comment 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 = "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.
--
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: issues-unsubscribe@trafficserver.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [trafficserver] SolidWallOfCode edited a comment on issue #8539: CACHE_LOOKUP_HIT_FRESH status for POST request is not good
Posted by GitBox <gi...@apache.org>.
SolidWallOfCode edited a comment on issue #8539:
URL: https://github.com/apache/trafficserver/issues/8539#issuecomment-982161141
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?
--
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: issues-unsubscribe@trafficserver.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [trafficserver] bneradt commented on issue #8539: CACHE_LOOKUP_HIT_FRESH status for POST request is not good
Posted by GitBox <gi...@apache.org>.
bneradt commented on issue #8539:
URL: https://github.com/apache/trafficserver/issues/8539#issuecomment-982161546
@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.
--
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: issues-unsubscribe@trafficserver.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [trafficserver] fdiary commented on issue #8539: CACHE_LOOKUP_HIT_FRESH status for POST request is not good
Posted by GitBox <gi...@apache.org>.
fdiary commented on issue #8539:
URL: https://github.com/apache/trafficserver/issues/8539#issuecomment-982658571
@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.
--
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: issues-unsubscribe@trafficserver.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [trafficserver] bneradt edited a comment on issue #8539: CACHE_LOOKUP_HIT_FRESH status for POST request is not good
Posted by GitBox <gi...@apache.org>.
bneradt edited a comment 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 = "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.
--
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: issues-unsubscribe@trafficserver.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [trafficserver] bneradt commented on issue #8539: CACHE_LOOKUP_HIT_FRESH status for POST request is not good
Posted by GitBox <gi...@apache.org>.
bneradt commented on issue #8539:
URL: https://github.com/apache/trafficserver/issues/8539#issuecomment-985042493
@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?
--
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: issues-unsubscribe@trafficserver.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [trafficserver] fdiary commented on issue #8539: CACHE_LOOKUP_HIT_FRESH status for POST request is not good
Posted by GitBox <gi...@apache.org>.
fdiary commented on issue #8539:
URL: https://github.com/apache/trafficserver/issues/8539#issuecomment-982680697
@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
```python
#!/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` ?
https://github.com/apache/trafficserver/blob/420935b7d7c61ab94a8addaaa43b6affb1fa9ab7/proxy/http/HttpTransact.cc#L727-L733
* we should introduce another hook like `READ_CACHE_RESPONSE_HOOK` when we are really sending a cache response ?
--
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: issues-unsubscribe@trafficserver.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [trafficserver] bneradt commented on issue #8539: CACHE_LOOKUP_HIT_FRESH status for POST request is not good
Posted by GitBox <gi...@apache.org>.
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 = "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 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: issues-unsubscribe@trafficserver.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [trafficserver] bneradt commented on issue #8539: CACHE_LOOKUP_HIT_FRESH status for POST request is not good
Posted by GitBox <gi...@apache.org>.
bneradt commented on issue #8539:
URL: https://github.com/apache/trafficserver/issues/8539#issuecomment-984977809
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.
--
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: issues-unsubscribe@trafficserver.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org