Fix Cache Result Code of negative revalidation cases (#12824) (#12831)

* Add %<crc> logging verification to the negative revalidating AuTest

* Fix crc for stale-if-error

* Fix for conditional request
Conflicts:
	src/proxy/http/HttpTransactHeaders.cc
	tests/gold_tests/autest-site/ats_replay.test.ext
	tests/gold_tests/cache/replay/negative-revalidating-enabled.replay.yaml

Author: masaori335

src/proxy/http/HttpTransact.cc

@@ -4342,6 +4342,9 @@ HttpTransact::handle_cache_operation_on_forward_server_response(State *s)
         base_response->set_expires(exp_time);
 
         SET_VIA_STRING(VIA_CACHE_FILL_ACTION, VIA_CACHE_UPDATED);
+        SET_VIA_STRING(VIA_CACHE_RESULT, VIA_IN_CACHE_STALE);
+        // change VIA_SERVER_RESULT to ERROR because this status hit the negative_revalidating_list
+        SET_VIA_STRING(VIA_SERVER_RESULT, VIA_SERVER_ERROR);
         Metrics::Counter::increment(http_rsb.cache_updates);
 
         // unset Cache-control: "need-revalidate-once" (if it's set)

src/proxy/http/HttpTransactHeaders.cc

@@ -38,6 +38,7 @@
 #include "proxy/PoolableSession.h"
 
 #include "iocore/utils/Machine.h"
+#include "tsutil/DbgCtl.h"
 
 using namespace std::literals;
 
@@ -420,6 +421,8 @@ HttpTransactHeaders::downgrade_request(bool *origin_server_keep_alive, HTTPHdr *
 void
 HttpTransactHeaders::generate_and_set_squid_codes(HTTPHdr *header, char *via_string, HttpTransact::SquidLogInfo *squid_codes)
 {
+  Dbg(dbg_ctl_http_transact_headers, "via_string=%s", via_string);
+
   SquidLogCode       log_code      = SQUID_LOG_EMPTY;
   SquidHierarchyCode hier_code     = SQUID_HIER_EMPTY;
   SquidHitMissCode   hit_miss_code = SQUID_HIT_RESERVED;
@@ -477,6 +480,8 @@ HttpTransactHeaders::generate_and_set_squid_codes(HTTPHdr *header, char *via_str
       } else {
         if (via_string[VIA_CACHE_RESULT] == VIA_IN_CACHE_STALE && via_string[VIA_SERVER_RESULT] == VIA_SERVER_NOT_MODIFIED) {
           log_code = SQUID_LOG_TCP_REFRESH_HIT;
+        } else if (via_string[VIA_CACHE_RESULT] == VIA_IN_CACHE_STALE && via_string[VIA_SERVER_RESULT] == VIA_SERVER_ERROR) {
+          log_code = SQUID_LOG_TCP_REF_FAIL_HIT;
         } else {
           log_code = SQUID_LOG_TCP_IMS_MISS;
         }

tests/gold_tests/cache/gold/negative-revalidating-enabled-access.gold

@@ -0,0 +1,10 @@
+11 TCP_MISS 200 200
+12 TCP_``HIT 200 000
+42 TCP_IMS_HIT 304 000
+13 TCP_REFRESH_FAIL_HIT 200 503
+43 TCP_REFRESH_FAIL_HIT 304 503
+14 TCP_``MISS 503 503
+21 TCP_MISS 200 200
+22 TCP_``HIT 200 000
+23 TCP_REFRESH_FAIL_HIT 200 503
+``

tests/gold_tests/cache/negative-revalidating.test.py

@@ -17,6 +17,8 @@
 #  See the License for the specific language governing permissions and
 #  limitations under the License.
 
+import os
+
 Test.Summary = '''
 Test the negative revalidating feature.
 '''
@@ -25,14 +27,17 @@
 class NegativeRevalidatingTest:
     _test_num: int = 0
 
-    def __init__(self, name: str, records_config: dict, replay_file: str):
+    def __init__(self, name: str, records_config: dict, replay_file: str, gold_access_log=""):
         self._tr = Test.AddTestRun(name)
         self._replay_file = replay_file
 
         self.__setupOriginServer()
         self.__setupTS(records_config)
         self.__setupClient()
 
+        if gold_access_log:
+            self.__testAccessLog(gold_access_log)
+
         NegativeRevalidatingTest._test_num += 1
 
     def __setupClient(self):
@@ -46,6 +51,20 @@ def __setupTS(self, records_config):
         self._ts = Test.MakeATSProcess(f"ts-{NegativeRevalidatingTest._test_num}")
         self._ts.Disk.records_config.update(records_config)
         self._ts.Disk.remap_config.AddLine('map / http://127.0.0.1:{0}'.format(self._server.Variables.http_port))
+        self._ts.Disk.logging_yaml.AddLines(
+            '''
+logging:
+    formats:
+        - name: access
+          format: '%<{uuid}cqh> %<crc> %<pssc> %<sssc>'
+    logs:
+        - filename: access
+          format: access
+          mode: ascii
+'''.split("\n"))
+
+    def __testAccessLog(self, gold_access_log):
+        Test.Disk.File(os.path.join(self._ts.Variables.LOGDIR, 'access.log'), exists=True, content=gold_access_log)
 
     def run(self):
         self._tr.Processes.Default.StartBefore(self._ts)
@@ -81,7 +100,8 @@ def run(self):
         # 'proxy.config.http.negative_revalidating_enabled': 1,
         'proxy.config.http.cache.max_stale_age': 6
     },
-    "replay/negative-revalidating-enabled.replay.yaml").run()
+    "replay/negative-revalidating-enabled.replay.yaml",
+    "gold/negative-revalidating-enabled-access.gold").run()
 
 #
 # Verify negative_revalidating list behavior.

tests/gold_tests/cache/replay/negative-revalidating-enabled.replay.yaml

@@ -47,6 +47,7 @@ sessions:
         fields:
         - [ Content-Length, 32 ]
         - [ Cache-Control, max-age=2 ]
+        - [ ETag, C0FFEE ]
 
     proxy-response:
       status: 200
@@ -77,6 +78,30 @@ sessions:
     proxy-response:
       status: 200
 
+  # Verify we serve the 304 Not Modified out of the cache with INM request
+  - client-request:
+      method: "GET"
+      version: "1.1"
+      scheme: "http"
+      url: /path/reques_item
+      headers:
+        fields:
+        - [ Host, example.com ]
+        - [ uuid, 42 ]
+        - [ If-None-Match, C0FFEE ]
+
+    # This should not reach the origin server.
+    server-response:
+      status: 503
+      reason: "Service Unavailable"
+      headers:
+        fields:
+        - [ Content-Length, 32 ]
+
+    # Again, we should serve this out of the cache.
+    proxy-response:
+      status: 304
+
   # Verify that with negative_revalidating enabled, we serve the 200 OK out of
   # the cache even though it is stale (but younger than max-age + max_stale_age).
   - client-request:
@@ -104,6 +129,30 @@ sessions:
     proxy-response:
       status: 200
 
+  # Verify that we serve the 304 Not Modified out of the cache with INM request
+  - client-request:
+      method: "GET"
+      version: "1.1"
+      scheme: "http"
+      url: /path/reques_item
+      headers:
+        fields:
+        - [ Host, example.com ]
+        - [ uuid, 43 ]
+        - [ If-None-Match, C0FFEE ]
+
+    # This should not reach the origin server.
+    server-response:
+      status: 503
+      reason: "Service Unavailable"
+      headers:
+        fields:
+        - [ Content-Length, 32 ]
+
+    # Again, we should serve this out of the cache.
+    proxy-response:
+      status: 304
+
   # Verify that max_stale_age is respected.
   - client-request:
       method: "GET"