From 12ff56507f1f66d7c936ae38fb92241ec7146316 Mon Sep 17 00:00:00 2001 From: bneradt Date: Fri, 26 Mar 2021 16:12:17 +0000 Subject: [PATCH] Add proxy.config.cache.log.alternate.eviction This commit adds the ability to toggle the logging of cache eviction of alternates. This can be helpful for tuning proxy.config.cache.limits.http.max_alts and detecting problematic Vary: behavior with origins. --- configs/records.config.default.in | 2 + .../configuration/cache-basics.en.rst | 3 + doc/admin-guide/files/records.config.en.rst | 16 + iocore/cache/Cache.cc | 4 + iocore/cache/CacheWrite.cc | 24 ++ iocore/cache/P_CacheInternal.h | 1 + lib/perl/lib/Apache/TS/AdminClient.pm | 1 + mgmt/RecordsConfig.cc | 2 + .../cache/gold/two_alternates_evicted.gold | 3 + .../replay/varied_transactions.replay.yaml | 357 ++++++++++++++++++ tests/gold_tests/cache/vary-handling.test.py | 44 +++ 11 files changed, 457 insertions(+) create mode 100644 tests/gold_tests/cache/gold/two_alternates_evicted.gold create mode 100644 tests/gold_tests/cache/replay/varied_transactions.replay.yaml create mode 100644 tests/gold_tests/cache/vary-handling.test.py diff --git a/configs/records.config.default.in b/configs/records.config.default.in index 278139f5ffb..733d42d6eb2 100644 --- a/configs/records.config.default.in +++ b/configs/records.config.default.in @@ -129,6 +129,8 @@ CONFIG proxy.config.cache.ram_cache.size INT -1 CONFIG proxy.config.cache.ram_cache_cutoff INT 4194304 # https://docs.trafficserver.apache.org/records.config#proxy-config-cache-limits-http-max-alts CONFIG proxy.config.cache.limits.http.max_alts INT 5 + # https://docs.trafficserver.apache.org/records.config#proxy-config-cache-log-alternate-eviction +CONFIG proxy.config.cache.log.alternate.eviction INT 0 # https://docs.trafficserver.apache.org/records.config#proxy-config-cache-max-doc-size CONFIG proxy.config.cache.max_doc_size INT 0 CONFIG proxy.config.cache.min_average_object_size INT 8000 diff --git a/doc/admin-guide/configuration/cache-basics.en.rst b/doc/admin-guide/configuration/cache-basics.en.rst index f42c282993c..ffdace636e4 100644 --- a/doc/admin-guide/configuration/cache-basics.en.rst +++ b/doc/admin-guide/configuration/cache-basics.en.rst @@ -583,6 +583,9 @@ To force document caching: #. Run the command :option:`traffic_ctl config reload` to apply the configuration changes. + +.. _CachingHttpAlternates: + Caching HTTP Alternates ======================= diff --git a/doc/admin-guide/files/records.config.en.rst b/doc/admin-guide/files/records.config.en.rst index 4750364ef08..6c043d88407 100644 --- a/doc/admin-guide/files/records.config.en.rst +++ b/doc/admin-guide/files/records.config.en.rst @@ -2242,6 +2242,22 @@ Cache Control The maximum number of alternates that are allowed for any given URL. Disable by setting to 0. +.. ts:cv:: CONFIG proxy.config.cache.log.alternate.eviction INT 0 + + When enabled (``1``), |TS| will emit a Status level log entry every time an + alternate for an object is evicted due to the number of its alternates + exceeding the value of :ts:cv:`proxy.config.cache.limits.http.max_alts`. The + URI for the evicted alternate is included in the log. This logging may be + useful to determine whether :ts:cv:`proxy.config.cache.limits.http.max_alts` + is tuned correctly for a given environment. It also provides visibility into + alternate eviction for individual objects, which can be helpful for + diagnosing unexpected `Vary:` header behavior from particular origins. + + For further details concerning the caching of alternates, see :ref:`Caching + HTTP Alternates `. + + By default, alternate eviction logging is disabled (set to ``0``). + .. ts:cv:: CONFIG proxy.config.cache.target_fragment_size INT 1048576 Sets the target size of a contiguous fragment of a file in the disk cache. diff --git a/iocore/cache/Cache.cc b/iocore/cache/Cache.cc index d8bd30cc8f6..3604908b242 100644 --- a/iocore/cache/Cache.cc +++ b/iocore/cache/Cache.cc @@ -64,6 +64,7 @@ int cache_config_ram_cache_compress = 0; int cache_config_ram_cache_compress_percent = 90; int cache_config_ram_cache_use_seen_filter = 1; int cache_config_http_max_alts = 3; +int cache_config_log_alternate_eviction = 0; int cache_config_dir_sync_frequency = 60; int cache_config_permit_pinning = 0; int cache_config_select_alternate = 1; @@ -3165,6 +3166,9 @@ ink_cache_init(ts::ModuleVersion v) REC_EstablishStaticConfigInt32(cache_config_http_max_alts, "proxy.config.cache.limits.http.max_alts"); Debug("cache_init", "proxy.config.cache.limits.http.max_alts = %d", cache_config_http_max_alts); + REC_EstablishStaticConfigInt32(cache_config_log_alternate_eviction, "proxy.config.cache.log.alternate.eviction"); + Debug("cache_init", "proxy.config.cache.log.alternate.eviction = %d", cache_config_log_alternate_eviction); + REC_EstablishStaticConfigInteger(cache_config_ram_cache_cutoff, "proxy.config.cache.ram_cache_cutoff"); Debug("cache_init", "cache_config_ram_cache_cutoff = %" PRId64 " = %" PRId64 "Mb", cache_config_ram_cache_cutoff, cache_config_ram_cache_cutoff / (1024 * 1024)); diff --git a/iocore/cache/CacheWrite.cc b/iocore/cache/CacheWrite.cc index 56446cb8f73..95e069f5fda 100644 --- a/iocore/cache/CacheWrite.cc +++ b/iocore/cache/CacheWrite.cc @@ -98,6 +98,30 @@ CacheVC::updateVector(int /* event ATS_UNUSED */, Event * /* e ATS_UNUSED */) if (od->move_resident_alt && get_alternate_index(write_vector, od->single_doc_key) == 0) { od->move_resident_alt = false; } + if (cache_config_log_alternate_eviction) { + CacheHTTPInfo *info = write_vector->get(0); + HTTPHdr *request = info->request_get(); + if (request->valid()) { + // In contrast to url_string_get, this url_print interface doesn't + // use HTTPHdr's m_heap which is not valid at this point because the + // HttpSM is most likely gone. + int url_length = request->url_printed_length(); + ats_scoped_mem url_text; + url_text = static_cast(ats_malloc(url_length + 1)); + int index = 0; + int offset = 0; + // url_print does not NULL terminate, so url_length instead of url_length + 1. + int ret = request->url_print(url_text.get(), url_length, &index, &offset); + url_text.get()[url_length] = '\0'; + if (ret == 0) { + Note("Could not print URL of evicted alternate."); + } else { + Status("The maximum number of alternates was exceeded for a resource. " + "An alternate was evicted for URL: %.*s", + url_length, url_text.get()); + } + } + } write_vector->remove(0, true); } if (vec) { diff --git a/iocore/cache/P_CacheInternal.h b/iocore/cache/P_CacheInternal.h index 70f670537d8..69d26a9461a 100644 --- a/iocore/cache/P_CacheInternal.h +++ b/iocore/cache/P_CacheInternal.h @@ -207,6 +207,7 @@ extern RecRawStatBlock *cache_rsb; // Configuration extern int cache_config_dir_sync_frequency; extern int cache_config_http_max_alts; +extern int cache_config_log_alternate_eviction; extern int cache_config_permit_pinning; extern int cache_config_select_alternate; extern int cache_config_max_doc_size; diff --git a/lib/perl/lib/Apache/TS/AdminClient.pm b/lib/perl/lib/Apache/TS/AdminClient.pm index 3767cce07ac..899350f54fb 100644 --- a/lib/perl/lib/Apache/TS/AdminClient.pm +++ b/lib/perl/lib/Apache/TS/AdminClient.pm @@ -341,6 +341,7 @@ The Apache Traffic Server Administration Manual will explain what these strings proxy.config.cache.hosting_filename proxy.config.cache.ip_allow.filename proxy.config.cache.limits.http.max_alts + proxy.config.cache.log.alternate.eviction proxy.config.cache.max_disk_errors proxy.config.cache.max_doc_size proxy.config.cache.min_average_object_size diff --git a/mgmt/RecordsConfig.cc b/mgmt/RecordsConfig.cc index 99d024be3b3..317b6c0b10e 100644 --- a/mgmt/RecordsConfig.cc +++ b/mgmt/RecordsConfig.cc @@ -838,6 +838,8 @@ static const RecordElement RecordsConfig[] = // # (0 disables the maximum number of alts check) {RECT_CONFIG, "proxy.config.cache.limits.http.max_alts", RECD_INT, "5", RECU_DYNAMIC, RR_NULL, RECC_STR, "^[0-9]+$", RECA_NULL} , + {RECT_CONFIG, "proxy.config.cache.log.alternate.eviction", RECD_INT, "0", RECU_DYNAMIC, RR_NULL, RECC_INT, "[0-1]", RECA_NULL} + , {RECT_CONFIG, "proxy.config.cache.force_sector_size", RECD_INT, "0", RECU_DYNAMIC, RR_NULL, RECC_NULL, nullptr, RECA_NULL} , {RECT_CONFIG, "proxy.config.cache.target_fragment_size", RECD_INT, "1048576", RECU_DYNAMIC, RR_NULL, RECC_NULL, nullptr, RECA_NULL} diff --git a/tests/gold_tests/cache/gold/two_alternates_evicted.gold b/tests/gold_tests/cache/gold/two_alternates_evicted.gold new file mode 100644 index 00000000000..3b10b2c9b2d --- /dev/null +++ b/tests/gold_tests/cache/gold/two_alternates_evicted.gold @@ -0,0 +1,3 @@ +`` +``STATUS: The maximum number of alternates was exceeded for a resource. An alternate was evicted for URL: http://127.0.0.1:``/same/path/for/all/requests +``STATUS: The maximum number of alternates was exceeded for a resource. An alternate was evicted for URL: http://127.0.0.1:``/same/path/for/all/requests diff --git a/tests/gold_tests/cache/replay/varied_transactions.replay.yaml b/tests/gold_tests/cache/replay/varied_transactions.replay.yaml new file mode 100644 index 00000000000..ccb35e7210e --- /dev/null +++ b/tests/gold_tests/cache/replay/varied_transactions.replay.yaml @@ -0,0 +1,357 @@ +# 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. + +# +# ------------- +# Replay Notes: +# ------------- +# This replay file assumes a proxy.config.cache.limits.http.max_alts of 4. +# + +meta: + version: "1.0" + + blocks: + + - 404_response: &404_response + status: 404 + reason: "Not Found" + headers: + fields: + - [ Content-Length, 0 ] + + +sessions: +- transactions: + + # Populate the cache with the first alternate. + - client-request: + method: "GET" + version: "1.1" + url: /same/path/for/all/requests + headers: + fields: + - [ Host, example.com ] + - [ uuid, 1 ] + - [ X-Vary-On-This, first ] + + proxy-request: + headers: + fields: + - [ X-Vary-On-This, { value: first, as: equal } ] + + server-response: + status: 200 + reason: OK + headers: + fields: + - [ Transfer-Encoding, chunked ] + - [ Cache-Control, max-age=300 ] + - [ Vary, X-Vary-On-This ] + - [ Connection, keep-alive ] + - [ X-Response-Identifier, first ] + content: + encoding: plain + data: "first" + + proxy-response: + status: 200 + headers: + fields: + - [ X-Response-Identifier, { value: first, as: equal } ] + + # Populate the cache with a second alternate. + - client-request: + method: "GET" + version: "1.1" + url: /same/path/for/all/requests + headers: + fields: + - [ Host, example.com ] + - [ uuid, 2 ] + - [ X-Vary-On-This, second ] + + # Add a delay so ATS has time to finish any caching IO for the previous + # transaction. + delay: 100ms + + proxy-request: + headers: + fields: + - [ X-Vary-On-This, { value: second, as: equal } ] + + server-response: + status: 200 + reason: OK + headers: + fields: + - [ Transfer-Encoding, chunked ] + - [ Cache-Control, max-age=300 ] + - [ Vary, X-Vary-On-This ] + - [ Connection, keep-alive ] + - [ X-Response-Identifier, second ] + content: + encoding: plain + data: "second" + + proxy-response: + status: 200 + headers: + fields: + - [ X-Response-Identifier, { value: second, as: equal } ] + + # There are two alternates in the cache now. Make sure we reply with the + # correct one based upon the specified Vary: target. + - client-request: + method: "GET" + version: "1.1" + url: /same/path/for/all/requests + headers: + fields: + - [ Host, example.com ] + - [ uuid, 3 ] + - [ X-Vary-On-This, first ] + + # Add a delay so ATS has time to finish any caching IO for the previous + # transaction. + delay: 100ms + + server-response: + <<: *404_response + + # The response should be served out of the cache, not from the server. + proxy-response: + status: 200 + headers: + fields: + - [ X-Response-Identifier, { value: first, as: equal } ] + + # Populate the cache with a third alternate. + - client-request: + method: "GET" + version: "1.1" + url: /same/path/for/all/requests + headers: + fields: + - [ Host, example.com ] + - [ uuid, 4 ] + - [ X-Vary-On-This, third ] + + # Add a delay so ATS has time to finish any caching IO for the previous + # transaction. + delay: 100ms + + proxy-request: + headers: + fields: + - [ X-Vary-On-This, { value: third, as: equal } ] + + server-response: + status: 200 + reason: OK + headers: + fields: + - [ Transfer-Encoding, chunked ] + - [ Cache-Control, max-age=300 ] + - [ Vary, X-Vary-On-This ] + - [ Connection, keep-alive ] + - [ X-Response-Identifier, third ] + content: + encoding: plain + data: "third" + + proxy-response: + status: 200 + headers: + fields: + - [ X-Response-Identifier, { value: third, as: equal } ] + + # Populate the cache with a fourth alternate. + - client-request: + method: "GET" + version: "1.1" + url: /same/path/for/all/requests + headers: + fields: + - [ Host, example.com ] + - [ uuid, 5 ] + - [ X-Vary-On-This, fourth ] + + # Add a delay so ATS has time to finish any caching IO for the previous + # transaction. + delay: 100ms + + proxy-request: + headers: + fields: + - [ X-Vary-On-This, { value: fourth, as: equal } ] + + server-response: + status: 200 + reason: OK + headers: + fields: + - [ Transfer-Encoding, chunked ] + - [ Cache-Control, max-age=300 ] + - [ Vary, X-Vary-On-This ] + - [ Connection, keep-alive ] + - [ X-Response-Identifier, fourth ] + content: + encoding: plain + data: "fourth" + + proxy-response: + status: 200 + headers: + fields: + - [ X-Response-Identifier, { value: fourth, as: equal } ] + + # This is the fifth alternate for the resource and should result in alternate + # eviction since max_alts is set to 4. + - client-request: + method: "GET" + version: "1.1" + url: /same/path/for/all/requests + headers: + fields: + - [ Host, example.com ] + - [ uuid, 6 ] + - [ X-Vary-On-This, fifth ] + + # Add a delay so ATS has time to finish any caching IO for the previous + # transaction. + delay: 100ms + + proxy-request: + headers: + fields: + - [ X-Vary-On-This, { value: fifth, as: equal } ] + + server-response: + status: 200 + reason: OK + headers: + fields: + - [ Transfer-Encoding, chunked ] + - [ Cache-Control, max-age=300 ] + - [ Vary, X-Vary-On-This ] + - [ Connection, keep-alive ] + - [ X-Response-Identifier, fifth ] + content: + encoding: plain + data: "fifth" + + proxy-response: + status: 200 + headers: + fields: + - [ X-Response-Identifier, { value: fifth, as: equal } ] + + # The fifth alternate should be in the cache. Verify we can reply with it. + - client-request: + method: "GET" + version: "1.1" + url: /same/path/for/all/requests + headers: + fields: + - [ Host, example.com ] + - [ uuid, 7 ] + - [ X-Vary-On-This, fifth ] + + # Add a delay so ATS has time to finish any caching IO for the previous + # transaction. + delay: 100ms + + server-response: + <<: *404_response + + # The fifth alternate should be served out of cache. + proxy-response: + status: 200 + headers: + fields: + - [ X-Response-Identifier, { value: fifth, as: equal } ] + + # There are currently 4 alternates cached. The addition of this one should, + # again, result in alternate eviction. + - client-request: + method: "GET" + version: "1.1" + url: /same/path/for/all/requests + headers: + fields: + - [ Host, example.com ] + - [ uuid, 8 ] + - [ X-Vary-On-This, sixth ] + + # Add a delay so ATS has time to finish any caching IO for the previous + # transaction. + delay: 100ms + + proxy-request: + headers: + fields: + - [ X-Vary-On-This, { value: sixth, as: equal } ] + + server-response: + status: 200 + reason: OK + headers: + fields: + - [ Transfer-Encoding, chunked ] + - [ Cache-Control, max-age=300 ] + - [ Vary, X-Vary-On-This ] + - [ Connection, keep-alive ] + - [ X-Response-Identifier, sixth ] + content: + encoding: plain + data: "sixth" + + proxy-response: + status: 200 + headers: + fields: + - [ X-Response-Identifier, { value: sixth, as: equal } ] + + # Verify that we can reply to a request for that lastly added alternate. + - client-request: + method: "GET" + version: "1.1" + url: /same/path/for/all/requests + headers: + fields: + - [ Host, example.com ] + - [ uuid, 9 ] + - [ X-Vary-On-This, sixth ] + + # Add a delay so ATS has time to finish any caching IO for the previous + # transaction. + delay: 100ms + + proxy-request: + headers: + fields: + - [ X-Vary-On-This, { value: sixth, as: equal } ] + + # This should be served out of the cache and not reach the origin. + server-response: + <<: *404_response + + proxy-response: + status: 200 + headers: + fields: + - [ X-Response-Identifier, { value: sixth, as: equal } ] diff --git a/tests/gold_tests/cache/vary-handling.test.py b/tests/gold_tests/cache/vary-handling.test.py new file mode 100644 index 00000000000..5467f0672fa --- /dev/null +++ b/tests/gold_tests/cache/vary-handling.test.py @@ -0,0 +1,44 @@ +''' +Test correct handling of altenates via the Vary header. +''' +# 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. + +Test.Summary = ''' +Test correct handling of altenates via the Vary header. +''' + +ts = Test.MakeATSProcess("ts") +replay_file = "replay/varied_transactions.replay.yaml" +server = Test.MakeVerifierServerProcess("server", replay_file) +ts.Disk.records_config.update({ + 'proxy.config.diags.debug.enabled': 1, + 'proxy.config.diags.debug.tags': 'http', + 'proxy.config.http.insert_age_in_response': 0, + 'proxy.config.cache.limits.http.max_alts': 4, + 'proxy.config.cache.log.alternate.eviction': 1, +}) + +ts.Disk.remap_config.AddLine( + 'map / http://127.0.0.1:{0}'.format(server.Variables.http_port) +) + +tr = Test.AddTestRun("Run traffic with max_alts behavior when set to 4") +tr.Processes.Default.StartBefore(server) +tr.Processes.Default.StartBefore(ts) +tr.AddVerifierClientProcess("client", replay_file, http_ports=[ts.Variables.port]) + +ts.Disk.diags_log.Content += "gold/two_alternates_evicted.gold"