Re: [squid-users] external_acl_type script crash always after 1mn

From: David Touzeau <david_at_touzeau.eu>
Date: Sat, 29 Sep 2012 18:53:18 +0200

After many tests, i have found the right code that did not crash the script.
Issue was in php code not in squid.

while (!feof(STDIN)) {
$url = trim(fgets(STDIN));
if($url<>null){
     WLOG($url." str:".strlen($url));
      fwrite(STDOUT, "OK\n");
}

}

Thanks

-----Original Message-----
From: David Touzeau
Sent: Saturday, September 29, 2012 4:46 PM
To: squid-users_at_squid-cache.org
Subject: [squid-users] external_acl_type script crash always after 1mn

Dear i'm trying to build my own external_helper using php.
I have some troubles and i did not see why...
It seems that after 1mn squid claim that helper are crashed.

I did not know why in my code.
i did not see where and how it crash...
You will see that the php code is very simple and do nothing.

So, each minutes or sometimes each 2mn, squid claim :
2012/09/29 16:21:19 kid1| WARNING: MyExternACL #3 exited
2012/09/29 16:21:19 kid1| Too few MyExternACL processes are running (need
1/5)
2012/09/29 16:21:19 kid1| Starting new helpers
2012/09/29 16:21:19 kid1| helperOpenServers: Starting 1/5
'external_acl_squid.php' processes
2012/09/29 16:21:19 kid1| WARNING: MyExternACL #5 exited
2012/09/29 16:21:19 kid1| Too few MyExternACL processes are running (need
1/5)
2012/09/29 16:21:19 kid1| Closing HTTP port 0.0.0.0:3128
2012/09/29 16:21:19 kid1| Closing HTTP port [::]:3129
2012/09/29 16:21:19 kid1| Closing HTTP port [::]:3140
2012/09/29 16:21:19 kid1| Closing HTTPS port 0.0.0.0:3133
2012/09/29 16:21:19 kid1| storeDirWriteCleanLogs: Starting...
2012/09/29 16:21:19 kid1| Finished. Wrote 13514 entries.
2012/09/29 16:21:19 kid1| Took 0.01 seconds (1580399.95 entries/sec).
FATAL: The MyExternACL helpers are crashing too rapidly, need help!

Squid Cache (Version 3.2.1-20120928-r11668): Terminated abnormally.

in squid.conf, i have set this acl:
external_acl_type MyExternACL %SRC %{X-Forwarded-For}>h %SRCEUI48 %URI %DST
%PATH /var/lib/squid3/external_acl_squid.php

My code write the start/stop and process TTL.
You can see that each 60s Squid stop the process or something wrong....

2012-09-29 16:28:42 [32628]: v1.0: die after (60s/about 1mn)
2012-09-29 16:28:42 [32627]: v1.0: die after (60s/about 1mn)
2012-09-29 16:28:42 [32629]: v1.0: die after (60s/about 1mn)
2012-09-29 16:28:42 [32630]: v1.0: die after (60s/about 1mn)
2012-09-29 16:28:42 [1487]: starting...
2012-09-29 16:28:42 [32626]: v1.0: die after (60s/about 1mn)
2012-09-29 16:28:42 [1487]: v1.0: die after (0s/about 0mn)
2012-09-29 16:28:45 [1680]: starting...
2012-09-29 16:28:45 [1683]: starting...
2012-09-29 16:28:45 [1687]: starting...
2012-09-29 16:28:45 [1684]: starting...
2012-09-29 16:28:45 [1686]: starting...
2012-09-29 16:28:46 [1680]: 192.168.1.158 - 64:27:37:02:53:3d
http://live.lemde.fr/mux.json live.lemde.fr /mux.json str:87
2012-09-29 16:29:45 [1683]: v1.0: die after (60s/about 1mn)
2012-09-29 16:29:45 [1687]: v1.0: die after (60s/about 1mn)
2012-09-29 16:29:45 [1684]: v1.0: die after (60s/about 1mn)
2012-09-29 16:29:45 [1686]: v1.0: die after (60s/about 1mn)
2012-09-29 16:29:45 [1680]: v1.0: die after (60s/about 1mn)
2012-09-29 16:29:45 [5855]: starting...
2012-09-29 16:29:45 [5855]: v1.0: die after (0s/about 0mn)
2012-09-29 16:29:48 [5875]: starting...
2012-09-29 16:29:48 [5874]: starting...
2012-09-29 16:29:48 [5876]: starting...
2012-09-29 16:29:48 [5879]: starting...
2012-09-29 16:29:48 [5877]: starting...
2012-09-29 16:29:51 [5874]: 192.168.1.158 - 64:27:37:02:53:3d
http://live.lemde.fr/mux.json live.lemde.fr /mux.json str:87
2012-09-29 16:30:48 [5875]: v1.0: die after (60s/about 1mn)
2012-09-29 16:30:48 [5876]: v1.0: die after (60s/about 1mn)
2012-09-29 16:30:48 [5879]: v1.0: die after (60s/about 1mn)
2012-09-29 16:30:48 [5877]: v1.0: die after (60s/about 1mn)
2012-09-29 16:30:48 [10734]: starting...
2012-09-29 16:30:48 [5874]: v1.0: die after (60s/about 1mn)
2012-09-29 16:30:48 [10734]: v1.0: die after (0s/about 0mn)
2012-09-29 16:30:51 [10759]: starting...
2012-09-29 16:30:51 [10762]: starting...
2012-09-29 16:30:51 [10761]: starting...
2012-09-29 16:30:51 [10758]: starting...
2012-09-29 16:30:51 [10760]: starting...

Perhaps my code is wrong ???
here it is the php code

---------------------------------------------------------------------------------------------------------
#!/usr/bin/php -q
<?php

  $GLOBALS["F"] = @fopen("/var/log/squid/external-acl.log", 'a');
  $GLOBALS["PID"]=getmypid();
  $GLOBALS["STARTIME"]=time();
  WLOG("starting...");
  set_time_limit(0);

  while ( $input = @fgets(STDIN) ) {
    $Source = trim($input);
    if($Source==null){continue;}
    if (feof(STDIN)) {
        WLOG("break loop");
        break;
    }
    $Source=trim($input);
    if($Source==null){continue;}
    WLOG($Source." str:".strlen($Source));
    echo "OK\n";

}
$distanceInSeconds = round(abs(time() - $GLOBALS["STARTIME"]));
$distanceInMinutes = round($distanceInSeconds / 60);
WLOG("v1.0: die after ({$distanceInSeconds}s/about
{$distanceInMinutes}mn)");
@fclose($GLOBALS["F"]);

function WLOG($text=null){

    $date=@date("Y-m-d H:i:s");
       if (is_file("/var/log/squid/external-acl.log")) {
           $size=@filesize("/var/log/squid/external-acl.log");
           if($size>1000000){
               @fclose($GLOBALS["F"]);
               unlink("/var/log/squid/external-acl.log");
              $GLOBALS["F"] = @fopen("/var/log/squid/external-acl.log",
'a');
           }
     }

    @fwrite($GLOBALS["F"], "$date [{$GLOBALS["PID"]}]: $text\n");
}
?>
---------------------------------------------------------------------------------------------------------
Received on Sat Sep 29 2012 - 16:53:46 MDT

This archive was generated by hypermail 2.2.0 : Sun Sep 30 2012 - 12:00:15 MDT