[squid-users] Squid BUG: assurance failed: tok.skip(WellKnownUrlPathPrefix())

Tue Sep 12 19:50:42 UTC 2023

Well there seems to be some recurring pattern of behaviour:

grep tok.skip cache.log

2023/09/12 19:12:03 kid4| ERROR: Squid BUG: assurance failed: tok.skip(WellKnownUrlPathPrefix())
2023/09/12 19:12:03 kid3| ERROR: Squid BUG: assurance failed: tok.skip(WellKnownUrlPathPrefix())
2023/09/12 19:12:03 kid4| ERROR: Squid BUG: assurance failed: tok.skip(WellKnownUrlPathPrefix())
2023/09/12 19:12:03 kid4| ERROR: Squid BUG: assurance failed: tok.skip(WellKnownUrlPathPrefix())
2023/09/12 19:12:04 kid4| ERROR: Squid BUG: assurance failed: tok.skip(WellKnownUrlPathPrefix())

2023/09/12 19:17:03 kid4| ERROR: Squid BUG: assurance failed: tok.skip(WellKnownUrlPathPrefix())
2023/09/12 19:17:03 kid4| ERROR: Squid BUG: assurance failed: tok.skip(WellKnownUrlPathPrefix())
2023/09/12 19:17:04 kid4| ERROR: Squid BUG: assurance failed: tok.skip(WellKnownUrlPathPrefix())
2023/09/12 19:17:04 kid3| ERROR: Squid BUG: assurance failed: tok.skip(WellKnownUrlPathPrefix())
2023/09/12 19:17:04 kid4| ERROR: Squid BUG: assurance failed: tok.skip(WellKnownUrlPathPrefix())

2023/09/12 19:22:04 kid3| ERROR: Squid BUG: assurance failed: tok.skip(WellKnownUrlPathPrefix())
2023/09/12 19:22:04 kid2| ERROR: Squid BUG: assurance failed: tok.skip(WellKnownUrlPathPrefix())
2023/09/12 19:22:04 kid3| ERROR: Squid BUG: assurance failed: tok.skip(WellKnownUrlPathPrefix())
2023/09/12 19:22:04 kid3| ERROR: Squid BUG: assurance failed: tok.skip(WellKnownUrlPathPrefix())
2023/09/12 19:22:04 kid4| ERROR: Squid BUG: assurance failed: tok.skip(WellKnownUrlPathPrefix())

2023/09/12 19:27:04 kid4| ERROR: Squid BUG: assurance failed: tok.skip(WellKnownUrlPathPrefix())
2023/09/12 19:27:04 kid4| ERROR: Squid BUG: assurance failed: tok.skip(WellKnownUrlPathPrefix())
2023/09/12 19:27:04 kid4| ERROR: Squid BUG: assurance failed: tok.skip(WellKnownUrlPathPrefix())
2023/09/12 19:27:04 kid3| ERROR: Squid BUG: assurance failed: tok.skip(WellKnownUrlPathPrefix())
2023/09/12 19:27:04 kid3| ERROR: Squid BUG: assurance failed: tok.skip(WellKnownUrlPathPrefix())

2023/09/12 19:32:04 kid2| ERROR: Squid BUG: assurance failed: tok.skip(WellKnownUrlPathPrefix())
2023/09/12 19:32:04 kid3| ERROR: Squid BUG: assurance failed: tok.skip(WellKnownUrlPathPrefix())
2023/09/12 19:32:04 kid4| ERROR: Squid BUG: assurance failed: tok.skip(WellKnownUrlPathPrefix())
2023/09/12 19:32:04 kid2| ERROR: Squid BUG: assurance failed: tok.skip(WellKnownUrlPathPrefix())
2023/09/12 19:32:04 kid3| ERROR: Squid BUG: assurance failed: tok.skip(WellKnownUrlPathPrefix())

2023/09/12 19:37:03 kid2| ERROR: Squid BUG: assurance failed: tok.skip(WellKnownUrlPathPrefix())
2023/09/12 19:37:03 kid4| ERROR: Squid BUG: assurance failed: tok.skip(WellKnownUrlPathPrefix())
2023/09/12 19:37:03 kid4| ERROR: Squid BUG: assurance failed: tok.skip(WellKnownUrlPathPrefix())
2023/09/12 19:37:03 kid4| ERROR: Squid BUG: assurance failed: tok.skip(WellKnownUrlPathPrefix())
2023/09/12 19:37:03 kid3| ERROR: Squid BUG: assurance failed: tok.skip(WellKnownUrlPathPrefix())

2023/09/12 19:42:03 kid4| ERROR: Squid BUG: assurance failed: tok.skip(WellKnownUrlPathPrefix())
2023/09/12 19:42:03 kid4| ERROR: Squid BUG: assurance failed: tok.skip(WellKnownUrlPathPrefix())
2023/09/12 19:42:03 kid4| ERROR: Squid BUG: assurance failed: tok.skip(WellKnownUrlPathPrefix())
2023/09/12 19:42:03 kid4| ERROR: Squid BUG: assurance failed: tok.skip(WellKnownUrlPathPrefix())
2023/09/12 19:42:03 kid2| ERROR: Squid BUG: assurance failed: tok.skip(WellKnownUrlPathPrefix())

2023/09/12 19:47:04 kid3| ERROR: Squid BUG: assurance failed: tok.skip(WellKnownUrlPathPrefix())
2023/09/12 19:47:04 kid3| ERROR: Squid BUG: assurance failed: tok.skip(WellKnownUrlPathPrefix())
2023/09/12 19:47:04 kid3| ERROR: Squid BUG: assurance failed: tok.skip(WellKnownUrlPathPrefix())
2023/09/12 19:47:04 kid2| ERROR: Squid BUG: assurance failed: tok.skip(WellKnownUrlPathPrefix())
2023/09/12 19:47:04 kid3| ERROR: Squid BUG: assurance failed: tok.skip(WellKnownUrlPathPrefix())

2023/09/12 19:52:04 kid3| ERROR: Squid BUG: assurance failed: tok.skip(WellKnownUrlPathPrefix())
2023/09/12 19:52:04 kid3| ERROR: Squid BUG: assurance failed: tok.skip(WellKnownUrlPathPrefix())
2023/09/12 19:52:04 kid4| ERROR: Squid BUG: assurance failed: tok.skip(WellKnownUrlPathPrefix())
2023/09/12 19:52:04 kid4| ERROR: Squid BUG: assurance failed: tok.skip(WellKnownUrlPathPrefix())
2023/09/12 19:52:04 kid4| ERROR: Squid BUG: assurance failed: tok.skip(WellKnownUrlPathPrefix())

and the same 5 lines at these times:
2023/09/12 19:57:03 kid3| ERROR: Squid BUG: assurance failed: tok.skip(WellKnownUrlPathPrefix())
2023/09/12 20:02:03 kid4| ERROR: Squid BUG: assurance failed: tok.skip(WellKnownUrlPathPrefix())
2023/09/12 20:07:03 kid4| ERROR: Squid BUG: assurance failed: tok.skip(WellKnownUrlPathPrefix())
2023/09/12 20:12:03 kid2| ERROR: Squid BUG: assurance failed: tok.skip(WellKnownUrlPathPrefix())
2023/09/12 20:17:03 kid2| ERROR: Squid BUG: assurance failed: tok.skip(WellKnownUrlPathPrefix())
2023/09/12 20:22:03 kid1| ERROR: Squid BUG: assurance failed: tok.skip(WellKnownUrlPathPrefix())
2023/09/12 20:27:04 kid4| ERROR: Squid BUG: assurance failed: tok.skip(WellKnownUrlPathPrefix())
2023/09/12 20:32:03 kid3| ERROR: Squid BUG: assurance failed: tok.skip(WellKnownUrlPathPrefix())
2023/09/12 20:37:04 kid3| ERROR: Squid BUG: assurance failed: tok.skip(WellKnownUrlPathPrefix())
2023/09/12 20:42:03 kid2| ERROR: Squid BUG: assurance failed: tok.skip(WellKnownUrlPathPrefix())
2023/09/12 20:47:03 kid3| ERROR: Squid BUG: assurance failed: tok.skip(WellKnownUrlPathPrefix())
2023/09/12 20:52:04 kid4| ERROR: Squid BUG: assurance failed: tok.skip(WellKnownUrlPathPrefix())
2023/09/12 20:57:03 kid3| ERROR: Squid BUG: assurance failed: tok.skip(WellKnownUrlPathPrefix())

So we can see it's occurring every 5mins at the same time, every time 5 occurrences. I suppose this is caused by my mrtg script calling squidclient exactly 5 times (to get number of used fd, max currently use fd, mean object size and number of store entries + store entries in memory). 

So, put this aside as the script (running on another computer) uses older squidclient.  I call it like this:
squidclient -h squid_ip -p squid_port -vv mgr:info

Request:
GET cache_object://squid_ip/info HTTP/1.0
Host: squid_ip
User-Agent: squidclient/4.6
Accept: */*
Connection: close

Sending HTTP request ...
done.
HTTP/1.1 404 Not Found
Server: squid
Mime-Version: 1.0
Date: Tue, 12 Sep 2023 19:09:41 GMT
Content-Type: text/html;charset=utf-8
Content-Length: 13057
X-Squid-Error: ERR_INVALID_URL 0
Cache-Status: proxy;detail=no-cache
Via: 1.1 proxy (squid)
Connection: close

This is obviously calling for url cache_object://squid_ip/info which I think is obsolete. Now I went with the new squidclient:

./squidclient -h squid_ip -p squid_port -vv mgr:info

Request:
GET http://squid_ip:squid_port/squid-internal-mgr/info HTTP/1.0
Host: 10.50.1.5:3127
User-Agent: squidclient/6.3
Accept: */*
Connection: close

But it seems squid is then trying to open it's visible_hostname:squid_port/squid-internal-mgr/ and due my DNS setting it is its WAN IP - so it's connecting to its outside IP with its outside IP which is not in the http_access manager allow list (now it is and the newer squidclient works). So maybe I should just start with my DNS and then I will take a look how to implement the new cachemgr.cgi into my old setup...

L

LL

-----Původní zpráva-----
Od: squid-users za uživatele Alex Rousskov
Odesláno: út 12.9.2023 19:28
Komu: squid-users at lists.squid-cache.org
Předmět: Re: [squid-users] Squid BUG: assurance failed: tok.skip(WellKnownUrlPathPrefix())

On 2023-09-12 13:06, Loučanský Lukáš wrote:
> Is this anyhow interesting?

Not really, IMO -- the problem happens earlier. I can confirm that you 
are running v6.3-based code. Let's call that progress :-).

Can you share the a _pointer_ to a compressed ALL,9 cache.log file while 
reproducing the problem using a single transaction?

https://wiki.squid-cache.org/SquidFaq/BugReporting#debugging-a-single-transaction

Alex.

> 
> 2023/09/12 18:47:04.267 kid4| 24,8| SBuf.cc(30) SBuf: SBuf15514952 created
> 2023/09/12 18:47:04.267 kid4| 24,8| SBuf.cc(30) SBuf: SBuf15514953 created
> 2023/09/12 18:47:04.267 kid4| 24,8| SBuf.cc(30) SBuf: SBuf15514954 created
> 2023/09/12 18:47:04.267 kid4| 24,7| SBuf.cc(85) assign: assigning 
> SBuf15514952 from SBuf15514912
> 2023/09/12 18:47:04.267 kid4| 24,8| SBuf.cc(38) SBuf: SBuf15514955 
> created from id SBuf15514915
> 2023/09/12 18:47:04.267 kid4| 24,8| SBuf.cc(445) startsWith: 
> SBuf15514955 startsWith SBuf125812, caseSensitive: 0
> 2023/09/12 18:47:04.267 kid4| 24,8| SBuf.cc(447) startsWith: no, too short
> 2023/09/12 18:47:04.267 kid4| 24,8| Tokenizer.cc(185) skip: no match, 
> not skipping '/squid-internal-mgr/'
> 2023/09/12 18:47:04 kid4| ERROR: Squid BUG: assurance failed: 
> tok.skip(WellKnownUrlPathPrefix())
> 2023/09/12 18:47:04.268 kid4| 24,8| SBuf.cc(70) ~SBuf: SBuf15514955 
> destructed
> 
> 
> BTW debug 24,9 makes pretty big log files... :-)
> 
> L
> 
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.squid-cache.org/pipermail/squid-users/attachments/20230912/1d1dc2a9/attachment-0001.htm>