Re: [squid-users] external_acl problem with cache

On 25/01/11 17:19, Luis Enrique Sanchez Arce wrote:
>
> hello,
>
> I put the variable grace = 0 but the problem persist.
>
> This is my program
>
> -----------------------------
>
> #!/usr/bin/env perl
>
> use UUID::Random;
>
> $| = 1;
>
> while ($in_squid =<STDIN>) {
>
> $uuid = UUID::Random::generate;
>
> print("ERR message=hello log=$uuid\n");
> }
>
> -----------------------------------------------------------
>
> And this is my conf in squid
>
> .......
> ...
> ..
>
> logformat test %ts.%03tu %6tr %>a %Ss/%03Hs %<st %rm %ru %un %Sh/%<A %mt %ea
> access_log /var/log/squid3/access.log test
>
> external_acl_type example children=30 negative_ttl=0 ttl=0 cache=0 grace=0 %URI /path/to/myprogram.pl
> acl test_example external example
> http_access allow test_example
>
> ....
> ..
> ..
>
> ----------------------------------------------------------
>
> when i test my config obtain this in access.log:
>
> 1295928233.847 0 10.8.54.79 TCP_DENIED/403 2372 GET http://intranet2.uci.cu/ - NONE/- text/html e10b2e75-a354-c0d1-4998-2e5abb4bdd96
> 1295928234.312 0 10.8.54.79 TCP_DENIED/403 2372 GET http://intranet2.uci.cu/ - NONE/- text/html 20190de1-6e57-6c69-3493-ff90b21005ca
> 1295928234.502 0 10.8.54.79 TCP_DENIED/403 2372 GET http://intranet2.uci.cu/ - NONE/- text/html 20190de1-6e57-6c69-3493-ff90b21005ca
> 1295928235.520 0 10.8.54.79 TCP_DENIED/403 2372 GET http://intranet2.uci.cu/ - NONE/- text/html bda52df3-c351-7444-6df3-90088c527ea6
> 1295928235.703 0 10.8.54.79 TCP_DENIED/403 2372 GET http://intranet2.uci.cu/ - NONE/- text/html bda52df3-c351-7444-6df3-90088c527ea6
> 1295928235.972 0 10.8.54.79 TCP_DENIED/403 2372 GET http://intranet2.uci.cu/ - NONE/- text/html bda52df3-c351-7444-6df3-90088c527ea6
> 1295928236.168 0 10.8.54.79 TCP_DENIED/403 2372 GET http://intranet2.uci.cu/ - NONE/- text/html 679769f2-8272-0021-198b-63c74ed940ae
> 1295928236.270 0 10.8.54.79 TCP_DENIED/403 2372 GET http://intranet2.uci.cu/ - NONE/- text/html 679769f2-8272-0021-198b-63c74ed940ae
> 1295928236.467 0 10.8.54.79 TCP_DENIED/403 2372 GET http://intranet2.uci.cu/ - NONE/- text/html 679769f2-8272-0021-198b-63c74ed940ae
> 1295928236.564 0 10.8.54.79 TCP_DENIED/403 2372 GET http://intranet2.uci.cu/ - NONE/- text/html 679769f2-8272-0021-198b-63c74ed940ae
> 1295928236.761 0 10.8.54.79 TCP_DENIED/403 2372 GET http://intranet2.uci.cu/ - NONE/- text/html 679769f2-8272-0021-198b-63c74ed940ae
> 1295928236.910 0 10.8.54.79 TCP_DENIED/403 2372 GET http://intranet2.uci.cu/ - NONE/- text/html 679769f2-8272-0021-198b-63c74ed940ae
> 1295928237.157 0 10.8.54.79 TCP_DENIED/403 2372 GET http://intranet2.uci.cu/ - NONE/- text/html 21cd7fb2-eff6-42b7-e907-010e6d7531d1
>
>
> In some cases, the uuid is repeated. This is a problem for me.
>

I think I see the pattern. All requests within one second are sharing
that UUID.

This looks like hitting a second bug inside the grace calculation now.
It seems to be expiring the when (now+grace < now) instead of (now+grace
<= now).

Thank you for the simple test case. I've replicated the above and proven
that by fixing just that grace bug I can reduce the duplicates down to a
much shorter overlap equal to the response time of the helper. But not
remove them completely. That fix is now in Squid-3.

The patch I proposed earlier overlooked a few important things, so is
not usable as-is. Working on a better version now.

Amos

-- 
Please be using
   Current Stable Squid 2.7.STABLE9 or 3.1.10
   Beta testers wanted for 3.2.0.4