<div dir="ltr">Hi,<div><br></div><div>I have just started my enhanced logging journey and have a small snippet below that might illuminate the issue ...</div><div><br></div><div><i>2024/02/07 17:06:39.212 kid1| 88,3| client_side_reply.cc(507) handleIMSReply: origin replied with error 502, forwarding to client due to fail_on_validation_err</i><br></div><div><br></div><div>A few lines below in the log it looks like squid sent :-</div><div><br></div><div><i>2024/02/07 17:06:39.212 kid1| 11,2| Stream.cc(280) sendStartOfMessage: HTTP Client REPLY:<br>---------<br>HTTP/1.1 502 Bad Gateway<br>Server: squid/5.7<br>Mime-Version: 1.0<br>Date: Wed, 07 Feb 2024 17:06:39 GMT<br>Content-Type: text/html;charset=utf-8<br>Content-Length: 3853<br>X-Squid-Error: ERR_READ_ERROR 0<br>Vary: Accept-Language<br>Content-Language: en<br>X-Cache: MISS from labs-maul-st-15<br>X-Cache-Lookup: HIT from labs-maul-st-15:3129<br>Via: 1.1 labs-maul-st-15 (squid/5.7)<br>Connection: close</i><br></div><div><br></div><div><br></div><div>The rest of the logs are quite large and contain URLs I cannot put here.   The logs were generated with debug_options to ALL,3.   </div><div><br></div><div>Any ideas?   Or should I generate more detailed logs and send them privately?</div><div><br></div><div>Thanks again,</div><div><br></div><div>Robin</div><div><br></div><div><br></div><div><br></div></div><br><div class="gmail_quote"><div dir="ltr" class="gmail_attr">On Fri, 2 Feb 2024 at 11:20, Robin Carlisle <<a href="mailto:robin.carlisle@framestore.com" target="_blank">robin.carlisle@framestore.com</a>> wrote:<br></div><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex"><div dir="ltr"><div>Hi, thanks for your reply.   </div><div><br></div><div>I have been looking at : <a href="https://developer.mozilla.org/en-US/docs/Web/HTTP/Headers/Cache-Control" target="_blank">https://developer.mozilla.org/en-US/docs/Web/HTTP/Headers/Cache-Control</a><br></div><div><br></div><i>The stale-if-error response directive indicates that the cache can reuse a stale response when an upstream server generates an error, or when the error is generated locally. Here, an error is considered any response with a status code of 500, 502, 503, or 504.<br><br>Cache-Control: max-age=604800, stale-if-error=86400<br>In the example above, the response is fresh for 7 days (604800s). Afterwards, it becomes stale, but can be used for an extra 1 day (86400s) when an error is encountered.<br><br>After the stale-if-error period passes, the client will receive any error generated</i><div><br></div><div>Given what you have said and what the above docs say - I am still confused as it looks like (in my test cases) the cached response can be used for 3600 secs (this works), after which the cached response can still be used for an additional 31536000 seconds on an error (this doesnt work).</div><div><br></div><div>I am going to dig into the error logging you suggested to see if I can make sense of that - and will send on if I can't.</div><div><br></div><div>Thanks v much for your help again,</div><div><br></div><div>Robin</div><div><br></div><div><br></div><div><br></div><div><br></div></div><br><div class="gmail_quote"><div dir="ltr" class="gmail_attr">On Thu, 1 Feb 2024 at 18:27, Alex Rousskov <<a href="mailto:rousskov@measurement-factory.com" target="_blank">rousskov@measurement-factory.com</a>> wrote:<br></div><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex">On 2024-02-01 12:03, Robin Carlisle wrote:<br>
> Hi, I am having trouble with stale-if-error response.<br>
<br>
If I am interpreting Squid code correctly, in primary use cases:<br>
<br>
* without a Cache-Control:stale-if-error=X in the original response, <br>
Squid sends a stale object if revalidation results in a 5xx error;<br>
<br>
* with a Cache-Control:stale-if-error=X and object age at most X, Squid <br>
sends a stale object if revalidation results in a 5xx error;<br>
<br>
* with a Cache-Control:stale-if-error=X and object age exceeding X, <br>
Squid forwards the 5xx error response if revalidation results in a 5xx <br>
error;<br>
<br>
In other words, stale-if-error=X turns on a "fail on validation errors" <br>
behavior for stale objects older than X. It has no other effects.<br>
<br>
In your test case, the stale objects are much younger than <br>
stale-if-error value (e.g., Age~=3601 vs. stale-if-error=31536000). <br>
Thus, stale-if-error should have no relevant effect.<br>
<br>
Something else is probably preventing your Squid from serving the stale <br>
response when facing a 5xx error. I do not know what that something is.<br>
<br>
I recommend sharing (privately if you need to protect sensitive info) a <br>
pointer to a compressed ALL,9 cache.log collected while reproducing the <br>
problem (using two transactions similar to the ones you have shared <br>
below -- a successful stale hit and a problematic one): <br>
<a href="https://wiki.squid-cache.org/SquidFaq/BugReporting#debugging-a-single-transaction" rel="noreferrer" target="_blank">https://wiki.squid-cache.org/SquidFaq/BugReporting#debugging-a-single-transaction</a><br>
<br>
Alternatively, you can try to study cache.log yourself after setting <br>
debug_options to ALL,3. Searching for "refresh" and "handleIMSReply" may <br>
yield enough clues.<br>
<br>
<br>
HTH,<br>
<br>
Alex.<br>
<br>
<br>
<br>
<br>
> # /etc/squid/squid.conf :<br>
> <br>
> acl to_aws dstdomain .<a href="http://amazonaws.com" rel="noreferrer" target="_blank">amazonaws.com</a> <<a href="http://amazonaws.com" rel="noreferrer" target="_blank">http://amazonaws.com</a>><br>
> <br>
> acl from_local src localhost<br>
> <br>
> http_access allow to_aws<br>
> <br>
> http_access allow from_local<br>
> <br>
> cache allow all<br>
> <br>
> cache_dir ufs /var/cache/squid 1024 16 256<br>
> <br>
> http_port 3129 ssl-bump cert=/etc/squid/maul.pem <br>
> generate-host-certificates=on dynamic_cert_mem_cache_size=4MB<br>
> <br>
> sslcrtd_program /usr/lib/squid/security_file_certgen -s <br>
> /var/lib/squid/ssl_db -M 4MB<br>
> <br>
> acl step1 at_step SslBump1<br>
> <br>
> ssl_bump bump step1<br>
> <br>
> ssl_bump bump all<br>
> <br>
> sslproxy_cert_error deny all<br>
> <br>
> cache_store_log stdio:/var/log/squid/store.log<br>
> <br>
> logfile_rotate 0<br>
> <br>
> shutdown_lifetime 3 seconds<br>
> <br>
> <br>
> # /usr/bin/proxy-test :<br>
> <br>
> #!/bin/bash<br>
> <br>
> curl --proxy <a href="http://localhost:3129" rel="noreferrer" target="_blank">http://localhost:3129</a> <<a href="http://localhost:3129" rel="noreferrer" target="_blank">http://localhost:3129</a>> \<br>
> <br>
>    --cacert /etc/squid/stuff.pem \<br>
> <br>
>    -v "<a href="https://stuff.amazonaws.com/api/v1/stuff/stuff.json" rel="noreferrer" target="_blank">https://stuff.amazonaws.com/api/v1/stuff/stuff.json</a> <br>
> <<a href="https://stuff.amazonaws.com/api/v1/stuff/stuff.json" rel="noreferrer" target="_blank">https://stuff.amazonaws.com/api/v1/stuff/stuff.json</a>>" \<br>
> <br>
>    -H "Authorization: token MYTOKEN" \<br>
> <br>
>    -H "Content-Type: application/json" \<br>
> <br>
>    --output "/tmp/stuff.json"<br>
> <br>
> <br>
> <br>
> Tests  ..........<br>
> <br>
> <br>
> At this point in time the network cable is unattached.  Squid returns <br>
> the cached object it got when the network was online earlier. The Age of <br>
> this object is just still under the max_age of 3600.     Previously I <br>
> was using offline_mode but I found that it did not try to revalidate <br>
> from the origin after the object expired (defined via max-age response). <br>
>    My understanding is that stale-if-error should work under my <br>
> circumstances.<br>
> <br>
> <br>
> # /var/log/squid/access.log<br>
> <br>
> 1706799404.440      6 127.0.0.1 NONE_NONE/200 0 CONNECT <br>
> <a href="http://stuff.amazonaws.com:443" rel="noreferrer" target="_blank">stuff.amazonaws.com:443</a> <<a href="http://stuff.amazonaws.com:443" rel="noreferrer" target="_blank">http://stuff.amazonaws.com:443</a>> - HIER_NONE/- -<br>
> <br>
> 1706799404.440      0 127.0.0.1 TCP_MEM_HIT/200 20726 GET <br>
> <a href="https://stuff.amazonaws.com/stuff.json" rel="noreferrer" target="_blank">https://stuff.amazonaws.com/stuff.json</a> <br>
> <<a href="https://stuff.amazonaws.com/stuff.json" rel="noreferrer" target="_blank">https://stuff.amazonaws.com/stuff.json</a>> - HIER_NONE/- application/json<br>
> <br>
> <br>
> # extract from /usr/bin/proxy-test<br>
> <br>
> < HTTP/1.1 200 OK<br>
> <br>
> < Date: Thu, 01 Feb 2024 13:57:11 GMT<br>
> <br>
> < Content-Type: application/json<br>
> <br>
> < Content-Length: 20134<br>
> <br>
> < x-amzn-RequestId: 3a2d3b26-df73-4b30-88cb-1a9268fa0df2<br>
> <br>
> < Last-Modified: 2024-02-01T13:00:45.000Z<br>
> <br>
> < Access-Control-Allow-Origin: *<br>
> <br>
> < x-amz-apigw-id: SdZwpG7qiYcERUQ=<br>
> <br>
> < Cache-Control: public, max-age=3600, stale-if-error=31536000<br>
> <br>
> < ETag: "cec102b43372840737ab773c2e77858b"<br>
> <br>
> < X-Amzn-Trace-Id: Root=1-65bba337-292be751134161b03555cdd6<br>
> <br>
> < Age: 3573<br>
> <br>
> < X-Cache: HIT from labs-maul-st-31<br>
> <br>
> < X-Cache-Lookup: HIT from labs-maul-st-31:3129<br>
> <br>
> < Via: 1.1 labs-maul-st-31 (squid/5.7)<br>
> <br>
> < Connection: keep-alive<br>
> <br>
> <br>
> <br>
> <br>
> Below .. the curl script executes again.  The Age has gone over the <br>
> max-age so squid attempted to refresh from the origin.  The machine is <br>
> still offline so the refresh failed.   I expected that the <br>
> stale-if-error response would instruct squid to return the cached object <br>
> as a 200.<br>
> <br>
> <br>
> # /var/log/squid/access.log<br>
> <br>
> 1706799434.464      5 127.0.0.1 NONE_NONE/200 0 CONNECT <br>
> <a href="http://stuff.amazonaws.com:443" rel="noreferrer" target="_blank">stuff.amazonaws.com:443</a> <<a href="http://stuff.amazonaws.com:443" rel="noreferrer" target="_blank">http://stuff.amazonaws.com:443</a>> - HIER_NONE/- -<br>
> <br>
> 1706799434.464      0 127.0.0.1 TCP_REFRESH_FAIL_ERR/502 4235 GET <br>
> <a href="https://stuff.amazonaws.com/stuff.json" rel="noreferrer" target="_blank">https://stuff.amazonaws.com/stuff.json</a> <br>
> <<a href="https://stuff.amazonaws.com/stuff.json" rel="noreferrer" target="_blank">https://stuff.amazonaws.com/stuff.json</a>> - HIER_NONE/- text/html<br>
> <br>
> <br>
> # extract from /usr/bin/proxy-test<br>
> <br>
> < HTTP/1.1 502 Bad Gateway<br>
> <br>
> < Server: squid/5.7<br>
> <br>
> < Mime-Version: 1.0<br>
> <br>
> < Date: Thu, 01 Feb 2024 14:57:14 GMT<br>
> <br>
> < Content-Type: text/html;charset=utf-8<br>
> <br>
> < Content-Length: 3853<br>
> <br>
> < X-Squid-Error: ERR_READ_ERROR 0<br>
> <br>
> < Vary: Accept-Language<br>
> <br>
> < Content-Language: en<br>
> <br>
> < X-Cache: MISS from labs-maul-st-31<br>
> <br>
> < X-Cache-Lookup: HIT from labs-maul-st-31:3129<br>
> <br>
> < Via: 1.1 labs-maul-st-31 (squid/5.7)<br>
> <br>
> < Connection: close<br>
> <br>
> <br>
> <br>
> Hope someone can help me with this.  All the best,<br>
> <br>
> <br>
> Robin Carlisle<br>
> <br>
> <br>
> <br>
> _______________________________________________<br>
> squid-users mailing list<br>
> <a href="mailto:squid-users@lists.squid-cache.org" target="_blank">squid-users@lists.squid-cache.org</a><br>
> <a href="https://lists.squid-cache.org/listinfo/squid-users" rel="noreferrer" target="_blank">https://lists.squid-cache.org/listinfo/squid-users</a><br>
<br>
_______________________________________________<br>
squid-users mailing list<br>
<a href="mailto:squid-users@lists.squid-cache.org" target="_blank">squid-users@lists.squid-cache.org</a><br>
<a href="https://lists.squid-cache.org/listinfo/squid-users" rel="noreferrer" target="_blank">https://lists.squid-cache.org/listinfo/squid-users</a><br>
</blockquote></div>
</blockquote></div>