Squid and SquidGuard does not start after reboot
-
I have Squid and SquidGuard on pfsense 1.2.3 RC3. Content Filtering and Logging works perfect until reboot. After reboot , although the services seem running, users bypass squid in transparent proxy mode and squidguard, so there is no log. When I start the services manually, system works normally. How can I solve this issue?
-
I have Squid and SquidGuard on pfsense 1.2.3 RC3. Content Filtering and Logging works perfect until reboot. After reboot , although the services seem running, users bypass squid in transparent proxy mode and squidguard, so there is no log. When I start the services manually, system works normally. How can I solve this issue?
I'm facing the same problem here. Is there a way to force these service to reload?
-
to force a reload/restart of a service go under status -> services then click the pause/play button, that service is then restarted. Its the button to the left of stop.
-
I've never been able to reliably reproduce this in order to work on a fix.
It seems to be some combination of installed packages, I think the last time someone mentioned it, it was snort. That package has changed quite a lot since the last time someone brought this up, though.
Try reinstalling all of your packages and then testing it again.
-
Hello All,
anyone come up with a solution to this?
I have two machines that are configured identically. One is a VM appliance and the other is an alix board based system. The vmware appliance works perfectly. Squid starts on boot and the proxy works right of the bat. On my alix system, however, this is not the case. I have to manually restart squid to make things work.
ps aux | grep squid
show that squid is running. The cache.log file shows that squid is starting up and reading the configuration files correctly. yet… tail -f on /var/squid/log/access.log shows that it is not caching... when the squid service is restarted then everything starts working correctly.The boot process for both machines look identical. The synching packages line looks like
squid squidcache squidnac squid squidtraffic squidupstream squidauth squidusers squidcache squidGuard
squid and squidGuard are the only packages installed. I have uninstalled and reinstalled a million times without success on the alix box. The problem also occurs if squid is the only package installed.
Right now I am thinking that there is some race condition on the slower alix box. Some process that is on the boot order list ahead of squid, which squid needs to work, hasn't completed starting up before squid runs. But... i am not sure what that would be.
This is all very frustrating.
running the latest version of 1.2.3 downloaded form pfsense.org about 2 weeks ago.
--luis
-
Here is some more info…
As stated in my previous post my 2 pfsense machines are configured identically. One requires manual restart of squid the other does not.
Here are the system logs at boot for the system that requires the manual restart of squid.
Jun 22 08:25:36 kernel: ppc0: parallel port not found.
Jun 22 08:25:36 kernel: sio0 at port 0x3f8-0x3ff irq 4 flags 0x10 on isa0
Jun 22 08:25:36 kernel: sio0: type 16550A, console
Jun 22 08:25:36 kernel: sio0: [FILTER]
Jun 22 08:25:36 kernel: sio1 at port 0x2f8-0x2ff irq 3 on isa0
Jun 22 08:25:36 kernel: sio1: type 16550A
Jun 22 08:25:36 kernel: sio1: [FILTER]
Jun 22 08:25:36 kernel: Timecounter "TSC" frequency 498054562 Hz quality 800
Jun 22 08:25:36 kernel: Timecounters tick every 10.000 msec
Jun 22 08:25:36 kernel: IPsec: Initialized Security Association Processing.
Jun 22 08:25:36 kernel: ad0: 152627MB <samsung hm160hc="" lq100-10="">at ata0-master PIO4
Jun 22 08:25:36 kernel: Trying to mount root from ufs:/dev/ad0s1a
Jun 22 08:25:36 kernel: glxsb0: <amd geode="" lx="" security="" block="" (aes-128-cbc,="" rng)="">mem 0xefff4000-0xefff7fff irq 9 at
device 1.2 on pci0
Jun 22 08:25:37 kernel: pflog0: promiscuous mode enabled
Jun 22 08:25:46 php: : SQUID is installed but not started. Not installing redirect rules.
Jun 22 08:25:46 php: : SQUID is installed but not started. Not installing redirect rules.
Jun 22 08:25:47 pftpx[481]: listening on 127.0.0.1 port 8021
Jun 22 08:25:47 pftpx[481]: listening on 127.0.0.1 port 8021
Jun 22 08:25:50 dhcpd: Internet Systems Consortium DHCP Server V3.0.7
Jun 22 08:25:50 dhcpd: Copyright 2004-2008 Internet Systems Consortium.
Jun 22 08:25:50 dhcpd: All rights reserved.
Jun 22 08:25:50 dhcpd: For info, please visit http://www.isc.org/sw/dhcp/
Jun 22 08:25:50 dnsmasq[580]: started, version 2.45 cachesize 150
Jun 22 08:25:50 dnsmasq[580]: compile time options: IPv6 GNU-getopt BSD-bridge ISC-leasefile no-DBus no-I18N TFTP
Jun 22 08:25:50 dnsmasq[580]: reading /etc/resolv.conf
Jun 22 08:25:50 dnsmasq[580]: using nameserver 192.168.0.1#53
Jun 22 08:25:50 dnsmasq[580]: read /etc/hosts - 2 addresses
Jun 22 08:25:50 kernel: ipfw2 (+ipv6) initialized, divert loadable, nat loadable, rule-based forwarding enabled,
default to accept, logging disabled
Jun 22 08:25:55 php: : SQUID is installed but not started. Not installing redirect rules.
Jun 22 08:25:55 php: : SQUID is installed but not started. Not installing redirect rules.
Jun 22 08:25:57 php: : Creating rrd update script
Jun 22 08:25:57 dhcpd: Internet Systems Consortium DHCP Server V3.0.7
Jun 22 08:25:57 dhcpd: Copyright 2004-2008 Internet Systems Consortium.
Jun 22 08:25:57 dhcpd: All rights reserved.
Jun 22 08:25:57 dhcpd: For info, please visit http://www.isc.org/sw/dhcp/
Jun 22 08:26:00 php: : Resyncing configuration for all packages.
Jun 22 08:26:02 php: : Reloading Squid for configuration sync
Jun 22 08:26:05 last message repeated 2 times
Jun 22 08:26:06 php: : Starting Squid
Jun 22 08:26:06 squid[1034]: Squid Parent: child process 1037 started
Jun 22 08:26:08 php: : Reloading Squid for configuration sync
Jun 22 08:26:10 last message repeated 2 times
Jun 22 08:26:11 check_reload_status: check_reload_status is starting
Jun 22 08:26:11 check_reload_status: rc.newwanip starting
Jun 22 08:26:14 login: login on console as root
Jun 22 08:26:18 php: : Informational: rc.newwanip is starting vr1.
Jun 22 08:26:18 php: : rc.newwanip working with (IP address: 192.168.0.4) (interface: wan) (interface real: vr1).
Jun 22 08:29:32 sshd[1633]: Accepted keyboard-interactive/pam for admin from 192.168.10.199 port 59703 ssh2
Jun 22 08:30:31 php[530]: /pkg_edit.php: Reloading Squid for configuration sync
Jun 22 08:30:34 check_reload_status: reloading filterHere are the logs for the system that works automatically…
Jun 22 08:02:50 kernel: acpi_throttle0: <acpi cpu="" throttling="">on cpu0
Jun 22 08:02:50 kernel: pmtimer0 on isa0
Jun 22 08:02:50 kernel: orm0: <isa option="" roms="">at iomem 0xc0000-0xc7fff,0xc8000-0xc8fff,0xc9000-0xc9fff,0xdc000-0xdffff,0xe0000-0xe3fff pnpid ORM0000 on isa0
Jun 22 08:02:50 kernel: sc0: <system console="">at flags 0x100 on isa0
Jun 22 08:02:50 kernel: sc0: VGA <16 virtual consoles, flags=0x300>
Jun 22 08:02:50 kernel: vga0: <generic isa="" vga="">at port 0x3c0-0x3df iomem 0xa0000-0xbffff on isa0
Jun 22 08:02:50 kernel: Timecounter "TSC" frequency 2659711266 Hz quality 800
Jun 22 08:02:50 kernel: Timecounters tick every 10.000 msec
Jun 22 08:02:50 kernel: IPsec: Initialized Security Association Processing.
Jun 22 08:02:50 kernel: ad0: 8192MB <vmware virtual="" ide="" hard="" drive="" 00000001="">at ata0-master UDMA33
Jun 22 08:02:50 kernel: acd0: CDROM <vmware virtual="" ide="" cdrom="" drive="" 00000001="">at ata1-master UDMA33
Jun 22 08:02:50 kernel: Waiting 5 seconds for SCSI devices to settle
Jun 22 08:02:50 kernel: Trying to mount root from ufs:/dev/ad0s1a
Jun 22 08:02:50 kernel: pflog0: promiscuous mode enabled
Jun 22 08:02:50 php: : SQUID is installed but not started. Not installing redirect rules.
Jun 22 08:02:50 php: : SQUID is installed but not started. Not installing redirect rules.
Jun 22 08:02:50 pftpx[478]: listening on 127.0.0.1 port 8021
Jun 22 08:02:50 pftpx[478]: listening on 127.0.0.1 port 8021
Jun 22 08:02:52 dhcpd: Internet Systems Consortium DHCP Server V3.0.7
Jun 22 08:02:52 dhcpd: Copyright 2004-2008 Internet Systems Consortium.
Jun 22 08:02:52 dhcpd: All rights reserved.
Jun 22 08:02:52 dhcpd: For info, please visit http://www.isc.org/sw/dhcp/
Jun 22 08:02:52 dnsmasq[573]: started, version 2.45 cachesize 150
Jun 22 08:02:52 dnsmasq[573]: compile time options: IPv6 GNU-getopt BSD-bridge ISC-leasefile no-DBus no-I18N TFTP
Jun 22 08:02:52 dnsmasq[573]: reading /etc/resolv.conf
Jun 22 08:02:52 dnsmasq[573]: using nameserver 192.168.0.1#53
Jun 22 08:02:52 dnsmasq[573]: read /etc/hosts - 2 addresses
Jun 22 08:02:52 kernel: ipfw2 (+ipv6) initialized, divert loadable, nat loadable, rule-based forwarding enabled, default to accept, logging disabled
Jun 22 08:02:54 php: : SQUID is installed but not started. Not installing redirect rules.
Jun 22 08:02:54 php: : SQUID is installed but not started. Not installing redirect rules.
Jun 22 08:02:55 php: : Creating rrd update script
Jun 22 08:02:55 dhcpd: Internet Systems Consortium DHCP Server V3.0.7
Jun 22 08:02:55 dhcpd: Copyright 2004-2008 Internet Systems Consortium.
Jun 22 08:02:55 dhcpd: All rights reserved.
Jun 22 08:02:55 dhcpd: For info, please visit http://www.isc.org/sw/dhcp/
Jun 22 08:02:55 php: : Resyncing configuration for all packages.
Jun 22 08:02:56 php: : Reloading Squid for configuration sync
Jun 22 08:02:57 last message repeated 6 times
Jun 22 08:02:57 check_reload_status: check_reload_status is starting
Jun 22 08:02:57 squid[968]: Squid Parent: child process 971 started
Jun 22 08:02:57 check_reload_status: rc.newwanip starting
Jun 22 08:02:58 login: login on ttyv0 as root
Jun 22 08:02:58 php: : Informational: rc.newwanip is starting em0.
Jun 22 08:02:59 php: : rc.newwanip working with (IP address: 192.168.0.9) (interface: wan) (interface real: em0).
Jun 22 08:03:02 Squid_Alarm[1101]: Squid has exited. Reconfiguring filter.
Jun 22 08:03:02 Squid_Alarm[1103]: Attempting restart…
Jun 22 08:03:02 squid[1110]: Squid Parent: child process 1113 started
Jun 22 08:03:05 Squid_Alarm[1117]: Reconfiguring filter…
Jun 22 08:03:06 Squid_Alarm[1194]: Squid has resumed. Reconfiguring filter.
Jun 22 08:04:48 sshd[1383]: Accepted keyboard-interactive/pam for admin from 192.168.0.101 port 60639 ssh2so notice the following… in the system that works late in the boot process we see that when rc.newwanip runs Squid has an alarm which causes it to restart...
Jun 22 08:02:59 php: : rc.newwanip working with (IP address: 192.168.0.9) (interface: wan) (interface real: em0).
Jun 22 08:03:02 Squid_Alarm[1101]: Squid has exited. Reconfiguring filter.
Jun 22 08:03:02 Squid_Alarm[1103]: Attempting restart…the system that requires the manual restart does not exhibit this behavior.
Jun 22 08:26:18 php: : rc.newwanip working with (IP address: 192.168.0.4) (interface: wan) (interface real: vr1).
Jun 22 08:29:32 sshd[1633]: Accepted keyboard-interactive/pam for admin from 192.168.10.199 port 59703 ssh2
Jun 22 08:30:31 php[530]: /pkg_edit.php: Reloading Squid for configuration sync
Jun 22 08:30:34 check_reload_status: reloading filterSo maybe what should happen after rc.newwanip runs is that squid should be restarted and ** NOT ** reload from a configuration sync that was done prior to assignment of the wan IP ???!??!?
I don't currently know enough about squid and its startup sequence to know if the above observation is related or not to the problem. I will see if I can figure out how to restart squid after rc.newwanip to see if that makes any difference.
comments anyone?
–luis</vmware></vmware></generic></system></isa></acpi></amd></samsung>
-
It may be a timing issue somehow. I setup squid on my ALIX on 1.2.3 and it works - but I am using a wireless WAN, which is slower to get an IP than DHCP or PPPoE would be.
During boot, I also get:
Jun 22 17:23:49 pfSense php: : SQUID is installed but not started. Not installing redirect rules. Jun 22 17:23:49 pfSense php: : SQUID is installed but not started. Not installing redirect rules.but a few moments after rc.newwanip is run, the redirect rule is present and the proxy works.
I do not see squid restart anywhere near rc.newwanip, either.
It would be interesting to know one more thing: You said squid was running, but I'd like to know if the NAT redirect rule is actually there.
Just after a reboot, drop to a shell prompt and then run the following:
# pfctl -sn | grep httpIf squid's redirect rule is present, you should get a line like this:
rdr on vr0 inet proto tcp from any to ! (vr0) port = http -> 127.0.0.1 port 80If that line is not there, it would explain why the proxy appears to be non-functional.
-
Probably this is a HAVP package message. If squid not running - HAVP giu not use redirect rules (rdr to squid).
Jun 22 17:23:49 pfSense php: : SQUID is installed but not started. Not installing redirect rules. -
Probably this is a HAVP package message. If squid not running - HAVP giu not use redirect rules (rdr to squid).
Jun 22 17:23:49 pfSense php: : SQUID is installed but not started. Not installing redirect rules.No, it's from squid, it's just that the filter.inc reload tries to grab the rules before squid is running on ALIX. It's ok, it happens a few seconds later and it's fine. Nothing to worry about in most cases. HAVP is not involved.
-
Putting squidguard into this mix on ALIX definitely isn't quite right at boot time though. I've got some fixes I just committed to squidguard which makes that combination work OK for me on reboot.
Try to reinstall squid and squidguard, double check your settings, and then try again.
If you are running on CF in that ALIX, under squid's cache management, be sure to choose the null type for the cache, that way it won't fill up your /var memory disk with cache data and bomb out, too.
-
It may be a timing issue somehow. I setup squid on my ALIX on 1.2.3 and it works - but I am using a wireless WAN, which is slower to get an IP than DHCP or PPPoE would be.
Just after a reboot, drop to a shell prompt and then run the following:
# pfctl -sn | grep httpIf squid's redirect rule is present, you should get a line like this:
rdr on vr0 inet proto tcp from any to ! (vr0) port = http -> 127.0.0.1 port 80If that line is not there, it would explain why the proxy appears to be non-functional.
OK. so here is a clean sequence.
1. uninstalled squid (and all squid packages)
2. installed squid and configured it. (it is currently the only package installed. squidGuard is not installed.)
3. made sure squid worked correctly.
4. rebooted the system and go the following in syslogJun 22 20:11:29 webxaccelerator php: : SQUID is installed but not started. Not installing redirect rules.
Jun 22 20:11:29 webxaccelerator php: : SQUID is installed but not started. Not installing redirect rules.Jun 22 20:11:34 webxaccelerator kernel: ipfw2 (+ipv6) initialized, divert loadable, nat loadable, rule-based forwarding enabled, default to accept, logging disabled
Jun 22 20:11:38 webxaccelerator php: : SQUID is installed but not started. Not installing redirect rules.
Jun 22 20:11:38 webxaccelerator php: : SQUID is installed but not started. Not installing redirect rules.Jun 22 20:11:43 webxaccelerator php: : Resyncing configuration for all packages.
Jun 22 20:11:45 webxaccelerator php: : Reloading Squid for configuration sync
Jun 22 20:11:48 webxaccelerator last message repeated 2 times
Jun 22 20:11:49 webxaccelerator php: : Starting Squid
Jun 22 20:11:49 webxaccelerator squid[1017]: Squid Parent: child process 1019 started
Jun 22 20:11:50 webxaccelerator php: : Reloading Squid for configuration sync
Jun 22 20:11:52 webxaccelerator last message repeated 2 times
Jun 22 20:12:00 webxaccelerator php: : Informational: rc.newwanip is starting vr1.
Jun 22 20:12:00 webxaccelerator php: : rc.newwanip working with (IP address: 192.168.0.4) (interface: wan) (interface real: vr1).the rc.newwanip is the last thing in the log file…
5. here is the output for
pfctl -sn | grep http
i.e. nada.. zip... no rule!
6. then i do a
killall -TERM squid
ps aux | grep squid
7. we now wait for proxy_monitor.sh to span a new squid... and here it is
ps aux | grep squid
root 1687 0.0 1.5 7196 3700 ?? Ss 8:16PM 0:00.00 /usr/local/sbin/squid -D
proxy 1690 0.0 3.9 15388 9772 ?? S 8:16PM 0:00.17 (squid) -D (squid)
root 1847 0.0 0.1 376 256 p0 R+ 8:16PM 0:00.00 grep squid8. the output of pfctl now shows...
pfctl -sn | grep http
rdr on vr0 inet proto tcp from any to ! (vr0) port = http -> 127.0.0.1 port 80
9. we confirm that indeed the proxy service is now working as it should be looking at /var/squid/log/access
so the pf rule is not getting installed which is why the proxy service is not working.
I currently have WAN IP set to DHCP so it takes a bit of time to get the IP address of the WAN.
does anyone know how to control the order of execution of the startup scripts? i have been looking but no luck.
so the $64,000 question is.... why is the rule not getting created?
I look forward to your response.
-
In your boot log, it did try to add the NAT rule – twice.
Jun 22 20:11:29 webxaccelerator php: : SQUID is installed but not started. Not installing redirect rules. Jun 22 20:11:29 webxaccelerator php: : SQUID is installed but not started. Not installing redirect rules. [...] Jun 22 20:11:38 webxaccelerator php: : SQUID is installed but not started. Not installing redirect rules. Jun 22 20:11:38 webxaccelerator php: : SQUID is installed but not started. Not installing redirect rules.There is one each for the NAT and firewall rules. So it tried twice but since at the time that was run, the squid process was not running, it didn't add the rule. I looked at my boot log again and I also see the same two sets of two lines. For me, it shows up shortly after the rc.newwanip run finishes. Not sure why that might be different in your case, except that my WAN is wireless which would be even slower than DHCP alone.
However, the missing NAT rule is the real problem, and should be easier to fix or patch around.
-
OK. so what I think you are telling me is that squid is starting up too late. In other words there is no squid process running when the NAT rules was going to be installed… However, squid is spawned later on but for some reason the redirect rule was not installed then.
Later on when squid is manually killed with "killall -TERM squid" followed by a /usr/local/etc/rc.d/squid.sh start (executed by the proxy_monitor) then rule is reinstalled. the rule is probably installed by /etc/rc.filter_configure_sync executed from within the body of the proxy_monitor.
if [ $NUM_PROCS -lt 1 ]; then
# squid is down
echo "Squid has exited. Reconfiguring filter." |
logger -p daemon.info -i -t Squid_Alarm
echo "Attempting restart…" | logger -p daemon.info -i -t Squid_Alarm
/usr/local/etc/rc.d/squid.sh start
sleep 3
echo "Reconfiguring filter..." | logger -p daemon.info -i -t Squid_Alarm
/etc/rc.filter_configure_sync
touch /var/run/squid_alarm
fiso maybe the solution is as simple as running /etc/rc.filter_configure_sync after boot? let me reboot and try that manually.
so... that works!
pfctl -sn| grep http
/etc/rc.filter_configure_sync
!p
pfctl -sn | grep http
rdr on vr0 inet proto tcp from any to ! (vr0) port = http -> 127.0.0.1 port 80how would I arrange to have /etc/rc.filter_configure_sync executed as the last thing in the boot sequence?
--luis
-
That's the thing – it should be run there already, and again in rc.newwanip. But I may need to make the equivalent PHP code run at the end of the squid package sync routine.
I'm working on getting that updated.It's already run there. Maybe it just needs to sleep a little first.Can you open /usr/local/pkg/squid.inc, go to line 1128 or so, and find this line:
filter_configure();And make it this:
// Sleep for a couple seconds to give squid a chance to fire up fully. sleep(5); filter_configure(); -
OK. I will give that a try right away…
in the mean time I have fixed the issue by adding following ugly hack to /etc/rc.newwanip
line 65: exec("/etc/rc.filter_configure_sync");
so the code now looks like
log_error("rc.newwanip working with (IP address: {$curwanip}) (interface: {$interface}) (interface real: {$interface_real}).");
if($curwanip == "0.0.0.0") {
log_error("Failed to update WAN IP, restarting dhclient.");
exec("dhclient $interface_real");
exit;
}exec("/etc/rc.filter_configure_sync");
and the nat rule is in place after reboot
pfctl -sn | grep http
rdr on vr0 inet proto tcp from any to ! (vr0) port = http -> 127.0.0.1 port 80
Your solution is ** MUCH NICER **... let me try it....
Nope... that did not work.
pfctl -sn | grep http
here is the full system log
Jun 22 21:12:05 webxaccelerator kernel: cpu0 on motherboard
Jun 22 21:12:05 webxaccelerator kernel: orm0: <isa option="" rom="">at iomem 0xe0000-0xea7ff pnpid ORM0000 on isa0
Jun 22 21:12:05 webxaccelerator kernel: ppc0: parallel port not found.
Jun 22 21:12:05 webxaccelerator kernel: sio0 at port 0x3f8-0x3ff irq 4 flags 0x10 on isa0
Jun 22 21:12:05 webxaccelerator kernel: sio0: type 16550A, console
Jun 22 21:12:05 webxaccelerator kernel: sio0: [FILTER]
Jun 22 21:12:05 webxaccelerator kernel: sio1 at port 0x2f8-0x2ff irq 3 on isa0
Jun 22 21:12:05 webxaccelerator kernel: sio1: type 16550A
Jun 22 21:12:05 webxaccelerator kernel: sio1: [FILTER]
Jun 22 21:12:05 webxaccelerator kernel: Timecounter "TSC" frequency 498054727 Hz quality 800
Jun 22 21:12:05 webxaccelerator kernel: Timecounters tick every 10.000 msec
Jun 22 21:12:05 webxaccelerator kernel: IPsec: Initialized Security Association Processing.
Jun 22 21:12:05 webxaccelerator kernel: ad0: 152627MB <samsung hm160hc="" lq100-10="">at ata0-master PIO4
Jun 22 21:12:05 webxaccelerator kernel: Trying to mount root from ufs:/dev/ad0s1a
Jun 22 21:12:05 webxaccelerator kernel: glxsb0: <amd geode="" lx="" security="" block="" (aes-128-cbc,="" rng)="">mem 0xefff4000-0xefff7fff irq 9 at device 1.2 on pci0
Jun 22 21:12:06 webxaccelerator kernel: pflog0: promiscuous mode enabled
Jun 22 21:12:15 webxaccelerator php: : SQUID is installed but not started. Not installing redirect rules.
Jun 22 21:12:15 webxaccelerator php: : SQUID is installed but not started. Not installing redirect rules.
Jun 22 21:12:16 webxaccelerator pftpx[481]: listening on 127.0.0.1 port 8021
Jun 22 21:12:16 webxaccelerator pftpx[481]: listening on 127.0.0.1 port 8021
Jun 22 21:12:19 webxaccelerator dhcpd: Internet Systems Consortium DHCP Server V3.0.7
Jun 22 21:12:19 webxaccelerator dhcpd: Copyright 2004-2008 Internet Systems Consortium.
Jun 22 21:12:19 webxaccelerator dhcpd: All rights reserved.
Jun 22 21:12:19 webxaccelerator dhcpd: For info, please visit http://www.isc.org/sw/dhcp/
Jun 22 21:12:19 webxaccelerator dnsmasq[580]: started, version 2.45 cachesize 150
Jun 22 21:12:19 webxaccelerator dnsmasq[580]: compile time options: IPv6 GNU-getopt BSD-bridge ISC-leasefile no-DBus no-I18N TFTP
Jun 22 21:12:19 webxaccelerator dnsmasq[580]: reading /etc/resolv.conf
Jun 22 21:12:19 webxaccelerator dnsmasq[580]: using nameserver 192.168.0.1#53
Jun 22 21:12:19 webxaccelerator dnsmasq[580]: read /etc/hosts - 2 addresses
Jun 22 21:12:19 webxaccelerator kernel: ipfw2 (+ipv6) initialized, divert loadable, nat loadable, rule-based forwarding enabled, default to accept, logging disabled
Jun 22 21:12:24 webxaccelerator php: : SQUID is installed but not started. Not installing redirect rules.
Jun 22 21:12:24 webxaccelerator php: : SQUID is installed but not started. Not installing redirect rules.
Jun 22 21:12:25 webxaccelerator php: : Creating rrd update script
Jun 22 21:12:26 webxaccelerator dhcpd: Internet Systems Consortium DHCP Server V3.0.7
Jun 22 21:12:26 webxaccelerator dhcpd: Copyright 2004-2008 Internet Systems Consortium.
Jun 22 21:12:26 webxaccelerator dhcpd: All rights reserved.
Jun 22 21:12:26 webxaccelerator dhcpd: For info, please visit http://www.isc.org/sw/dhcp/
Jun 22 21:12:28 webxaccelerator php: : Resyncing configuration for all packages.
Jun 22 21:12:31 webxaccelerator php: : Reloading Squid for configuration sync
Jun 22 21:12:38 webxaccelerator php: : Starting Squid
Jun 22 21:12:38 webxaccelerator squid[958]: Squid Parent: child process 960 started
Jun 22 21:12:44 webxaccelerator php: : Reloading Squid for configuration sync
Jun 22 21:13:09 webxaccelerator last message repeated 4 times
Jun 22 21:13:15 webxaccelerator check_reload_status: check_reload_status is starting
Jun 22 21:13:15 webxaccelerator check_reload_status: rc.newwanip starting
Jun 22 21:13:18 webxaccelerator login: login on console as root
Jun 22 21:13:24 webxaccelerator php: : Informational: rc.newwanip is starting vr1.
Jun 22 21:13:25 webxaccelerator php: : rc.newwanip working with (IP address: 192.168.0.4) (interface: wan) (interface real: vr1).and here is the mod to squid.inc
sleep(5);
filter_configure();What else could be happening?
–luis</amd></samsung></isa>
-
I'll have to run some more tests tomorrow to see if I can figure out what is going wrong. You could experiment with different sleep values, maybe up to 30 seconds or so, as a test. I went ahead and committed the 5 second sleep to the package just in case it worked.
-
hm… shouldn't line 1128 of /usr/local/pkg/squid.inc be calling
filter_configure_sync() instead of filter_configure()?
i just looked at the code or filter_configure in /etc/inc/filter.inc and it doesn't look like does much... It basically touches /tmp/filter_dirty and then exits...
when does filter_configure_sync() get called?
I just replaced the call to filter_configure() with filter_configure_sync() in squid.inc and guess what... that seems to work.
pfctl -sn | grep http
rdr on vr0 inet proto tcp from any to ! (vr0) port = http -> 127.0.0.1 port 80
Does this work for you?
--luis
-
Not sure offhand, but if it works, I'll commit it.I was informed that is a Very Bad Thing
to do, since it can get you stuck in a loop.I'll investigate it further tomorrow, but at least there is a lead.
-
well it works for me… i assume it will work for you as well since it seems to be a fairly innocuous function. I just cant see how filter_configure() ever worked since the all the work is done in filter_configure_sync(). It seems that filter_configure() just flags the fact that changes to the filter rules need to be synced and then expects some other process to detect this and then do the job.
Anyway, am not familiar with the code enough to know if there are other repercussions to making the change. You would be a better judge of this. On the surface, however, it looks like the right thing to do.
Thanks for all your help. Unless I hear from you I assume that this issue is now closed.
take care.
--luis
-
That is the difference. filter_configure_sync() is synchronous - it does it right then and there and you wait on it. The other method waits on a periodic process to pick up the flag file and run with it.
-
Not sure offhand, but if it works, I'll commit it.I was informed that is a Very Bad Thing to do, since it can get you stuck in a loop.I'll investigate it further tomorrow, but at least there is a lead.
OK. let me know if you need help. I certainly have a system here that can reproduce the problem very reliably.
Is the "VERY BAD THING" caused by the possibility of having two filter_configure_syn() happening at the same time?
–luis
-
That seemed to be the case, but I don't know the specifics in detail.
I'll work on it more tomorrow and see what I can come up with.
-
Now to make things even more strange, I cannot reproduce the problem at all.
I uninstalled and reinstalled both squid and squidguard last night, and now when I reboot the rule is there, and I'm not using any locally modified code. I even switched slices and tried it again, and it came up with the rule intact.
Does it still happen for you if you uninstall and reinstall squid now?
I made a couple changes to the pkg last night but nothing that should have affected this.
Jim
-
Now to make things even more strange, I cannot reproduce the problem at all.
I uninstalled and reinstalled both squid and squidguard last night, and now when I reboot the rule is there, and I'm not using any locally modified code. I even switched slices and tried it again, and it came up with the rule intact.
Does it still happen for you if you uninstall and reinstall squid now?
I made a couple changes to the pkg last night but nothing that should have affected this.
Jim
i booted my system with the manually modified /usr/local/pkg/squid.inc with the change where filter_configure() was replaced with filter_configure_sync() and confirmed that the http redirect rule was in place.
then i uninstalled squid (So there are 0 packages on the system now) and rebooted.
then i checked for the rule… its not there.
pfctl -sn | grep http
the system logs look clean and the boot console shows no errors.
next I installed squid and started the service and noticed that the rule was in place.
pfctl -sn | grep http
rdr on vr0 inet proto tcp from any to ! (vr0) port = http -> 127.0.0.1 port 80
after reboot i get
pfctl -sn | grep http
rdr on vr0 inet proto tcp from any to ! (vr0) port = http -> 127.0.0.1 port 80
so... the rule is in place.
i did notice that the boot sequence now takes a lot longer than it did before. During the Syncing packages line each squid module takes a long time... Here is what I have
Syncing packges: squid squidcache squidmac squid squidtraffic squidupstream squidauth squidusers
So is the delay caused by a full filter_configure_sync for each one? ah... i see that you have the sleep(5) in there. let me take that out to see what happens...
so... when the sleep(5) is removed the boot up sequence is much faster.. as expected.
** BUT **
pfctl -sn | grep http
the rule is gone.
I really don't like the sleep solution.... there is obviously some race condition happening here which is being addressed by slowing down the config process. Having a random sleep is just asking for problems down the road.
anyway, replacing filter_configure() with filter_configure_sync()works for me. Are you sure this is not the answer? the book sequence is fast (maybe a little slower than using filter_configure() but not noticeably so) and it works...
pfctl -sn | grep http
rdr on vr0 inet proto tcp from any to ! (vr0) port = http -> 127.0.0.1 port 80
I look forward to your thoughts.
--luis
-
Given the warnings I was given about not using filter_configure_sync() in that way, the sleep() solution is better. The reason the rule isn't present was because they were trying to add the rules too quickly after squid was told to start up.
If you look in the code, the squid launch process is done using mwexec_bg() which will fork a background process, which will cause a race with whatever code is next, the sleep induces a delay before reconfiguring the filter, which seems to make it work.
Though I swear I tried it yesterday with that sleep() and it didn't make a difference.
I have a couple more ideas, though:
- Remove the sleep, and change mwexec_bg() for squid to mwexec() on line 1123 which may avoid the race.
- Loop a couple times and only sleep for a second or two if squid is not running. That way it doesn't proceed until the process is found, or breaks out if it's not running after a few seconds (5, 10, whatever).
-
I just committed both of those, give it a try.
It works for me. By the time I get to the shell prompt and check, the rule is there.
-
I just committed both of those, give it a try.
It works for me. By the time I get to the shell prompt and check, the rule is there.
sigh… just tried it and....
pfctl -sn | grep http
no rule.
I see the code changes you have made
if (!is_service_running('squid')) {
log_error("Starting Squid");
mwexec("/usr/local/sbin/squid -D");
} else {
log_error("Reloading Squid for configuration sync");
mwexec("/usr/local/sbin/squid -k reconfigure");
}// Sleep for a couple seconds to give squid a chance to fire up fully.
for ($i=0; $i < 10; $i++) {
if (!is_service_running('squid'))
sleep(1);
}The log files show the following
Jun 23 20:42:16 php: : SQUID is installed but not started. Not installing "nat" rules.
Jun 23 20:42:16 php: : SQUID is installed but not started. Not installing "filter" rules.
...
Jun 23 20:42:21 php: : Resyncing configuration for all packages.
Jun 23 20:42:23 php: : Reloading Squid for configuration sync
Jun 23 20:42:25 php: : Reloading Squid for configuration sync
Jun 23 20:42:29 php: : Starting Squid
Jun 23 20:42:29 squid[1080]: Squid Parent: child process 1083 started
Jun 23 20:42:31 php: : Reloading Squid for configuration sync
Jun 23 20:42:35 last message repeated 3 times
Jun 23 20:42:36 check_reload_status: check_reload_status is starting
Jun 23 20:42:36 check_reload_status: rc.newwanip starting
Jun 23 20:42:44 php: : Informational: rc.newwanip is starting vr1.
Jun 23 20:42:44 php: : rc.newwanip working with (IP address: 192.168.0.4) (interface: wan) (interface real: vr1).modifying the code so that it looks like
// Sleep for a couple seconds to give squid a chance to fire up fully.
for ($i=0; $i < 10; $i++) {
if (!is_service_running('squid'))
sleep(1);
}
sleep(5);
filter_configure();makes things work again.
so… either is_service_running() is not working correctly or squid needs a little time after it is spawned before the filters_can be configured.
modifying the code like // Sleep for a couple seconds to give squid a chance to fire up fully.
for ($i=0; $i < 10; $i++) {
sleep(1);
if (is_service_running('squid')) {
break;
}
}shows that the first squid takes a while to spawn when observing the "Synching services line" on the console which means that is_service_running() is working.
what is scary here is that some amount of time between 1 - 5 seconds (on my system, who knows on others) is required after squid is spawned before the async version of filter_configure() is effective.
maybe mwexec("/usr/local/sbin/squid -k reconfigure");
is messing things up.
anyway... i am still confused by
/* reload filter async */
function filter_configure() {
if(isset($config['system']['developerspew'])) {
$mt = microtime();
echo "filter_configure() being called $mt\n";
}
global $g;touch($g['tmp_path'] . "/filter_dirty");
}some external event has to be triggered to cause /filter_dirty to be tested and filter_configure_sync() to be run. So… why would a delay of X seconds matter? once you touch a file the timestamp does not get modified... so even if squid were not running when the file was touched this should not matter.... Something must be removing /filter_dirty before the async process has had a chance to sync up the rules. What would that be? Obviously this process happens soon after squid is spawned... this is why the sleep(5) works. because the thing that deletes /filter_dirty has done its job and filter_configure then creates a file which then gets picked up on the next sync....
the logs show that squid is running
Jun 23 20:42:31 php: : Reloading Squid for configuration sync
Jun 23 20:42:35 last message repeated 3 timesso.. the problem is not "trying to update the rule when squid is not running". This is an issue with the way the filter rules are synced. the Async methods is failing here.
right now i am clueless how to effectively solve this race condition. Placing a sleep(5) is really not a solution IMHO.
--luis
-
question
the following is an excerpt from /etc/rc
–----
....
echo -n "Starting CRON... "
cd /tmp && /usr/sbin/cron -s 2>/dev/null
echo "done."Start packages
/etc/rc.start_packages
rm -rf /usr/local/pkg/pf/CVS
Remove stale files that have already been processed by bootup
scripts
rm -f /tmp/filter_dirty
rm -f /tmp/rc.linkup
nohup /usr/bin/nice -n20 /usr/local/sbin/check_reload_status &
....
is there any chance that rm -f /tmp/filter_dirty
might happen before the syncing of the rules when spawning squid? This would cause filter_config() in squid.inc to be ignored. It would explain why sleep(5) works. the sleep would cause the rm in rc to happen before filter_config() is called.let me test that by commenting out the rm in rc....
hey guess what
pfctl -sn | grep http
rdr on vr0 inet proto tcp from any to ! (vr0) port = http -> 127.0.0.1 port 80
the problem has ** NOTHING TO DO WITH THE SQUID PACKAGE ***
its a race condition cause in /etc/rc.
this is a a serious bug that could have repercussions for any package that rules that get created right about the time rc
removes /tmp/filter_dirty.comment out
rm -f /tmp/filter_dirtyand everything works like expected. no sleeps required in before filter_config() to make things work.
this no longer needed.
// Sleep for a couple seconds to give squid a chance to fire up fully.
/*
for ($i=0; $i < 10; $i++) {
sleep(1);
if (is_service_running('squid')) {
break;
}
}
*/i bet you a $1 that if you put back the mwexec_bg things would still work since the creation of the rules happens asynchronously.
HOWEVER... i still think its a good idea to leave the synchronous spawn and the loop in there just to make DARN sure that squid is up before you try to update the filters.
--luis
-
Good find there. I'm not sure why that rm is there. I asked around and at most that would mean another filter reload, which is harmless, and in this case necessary. It must still be working for me again on this test ALIX now because my WAN is wireless and rc.newwanip doesn't run as quickly.
So removing that rm is safe, but I'm not sure how best to handle that long-term. I'm not sure it should be patched out for everyone.
-
The way I see it the rm in rc is bad… the reason for this is that there are many programs that set /tmp/filter_dirty expecting to have some process later on detect it and then sync up the filters. The issue is that the rm in rc can happen at any time while subsystems are booting up. This is bad... The rc script should 'wait' until the system is fully booted before removing this file. But it doesn't. It just removes it willy-nilly at some random time without considering the effect on the boot process.
This is your classic multi-processing synchronization problem. You have one process removing a resource that another program needs without checking first.
From everything I have looked at it seems that having rc remove the file is unnecessary. Think about it... reloading process set /tmp/filter_dirty and remove it after the synchronization is complete. So... why should removing it once in rc matter? On my system, for example, currently the file does not exist even though the rm in rc is commented out. This is because the file is unlinked after the filter synchronization was completed. The house keeping in rc is unnecessary.
IMHO 1 of two things needs to be done.
1. rm needs to be removed from rc
or
2. some synchronization mechanism needs to be added to rc so that rc does not attempt to remove this file until after all processes have been started up.Please check again with the powers that be... I believe that removing the rm in rc will not negatively impact the operation of the system for anyone and therefore should be done since there are now documented examples where in some instances it breaks the boot process. No telling what other users are having weird unexplained behavior because of this. In our case it was squid. but for some other user it might be.... Also, keep in mind that this thread has been open since Oct 2009... so this is a long standing problem. Not something that just cropped up.
summing up... having rm -f /tmp/filter_dirty in rc causes inconsistent behavior in pfSense and it is therefore detrimental to the project.
--luis
PS... here is another thread where boot up problems are probably caused by removal of /tmp/filter_dirty in /etc/rc
http://forum.pfsense.org/index.php?topic=19381.0#lastPost
this one was reported in Sept 2009. -
Taking the rm out is the solution, but since that is a system file and not a package file, I'm hesitant to remove that as part of the package installation - that's what I was referring to.
/tmp/filter_dirty is removed automatically by check_reload_status after it reloads the filter – nothing needs to remove that file manually.
-
Taking the rm out is the solution, but since that is a system file and not a package file, I'm hesitant to remove that as part of the package installation - that's what I was referring to.
/tmp/filter_dirty is removed automatically by check_reload_status after it reloads the filter – nothing needs to remove that file manually.
Yes… i agree with you 100% this should not be removed by the package....
This needs to be patched in the distribution.
Who takes care of that?
--luis
-
Well 1.2.3 won't see any more updates to the base system. I can remove that line on 2.0, though (it's still there), after running it by a few others.
-
OK. thanks…
Its a pity that there are no more updates to 1.2.3...
I will add this to our list of things to do when building a new distribution...
I will let the folks at the applianceshop know as well.
Take care and thanks for your help.
--luis
-
It might be possible to get it committed into the 1.2.3 tree so a rebranded release for a customer could pick it up, failing that, an overlay for the rc file could be setup for a custom build.
Or I could just make a little patch package that removes it, too, but not bundle it with squid (since it doesn't affect everyone)
-
certainly getting the fix into the tree seems like a reasonable thing to do…
Squid users having problems hopefully will find this form thread and will then know that to fix the problem the need to edit /etc/rc
go to line 322 and delete it.i.e.
make this
Remove stale files that have already been processed by bootup
scripts
rm -f /tmp/filter_dirty
rm -f /tmp/rc.linkuplook like this
Remove stale files that have already been processed by bootup
scripts
rm -f /tmp/rc.linkup
--luis
-
I just added a package to apply a simple patch that removes the line in question.
Give it a spin and see if it helps. It's called "Patch rc to leave filter_dirty" (for lack of a better name :-)
-
it failed!
Remove stale files that have already been processed by bootup
scripts
rm -f /tmp/filter_dirty
rm -f /tmp/rc.linkup
nohup /usr/bin/nice -n20 /usr/local/sbin/check_reload_status &Here is the list of installed packages on my system
Patch rc to leave filter_dirty System No info, check the forum 0.1 Patch to stop /etc/rc from removing /tmp/filter_dirty on boot. Fixes boot issues with some packages on certain platforms.
squid Network No info, check the forum Current: 2.7.9
Installed: 2.7.8_1 High performance web proxy cache.squidGuard Network Management No info, check the forum 1.3-2 High perfomance web proxy URL filter. Required proxy Squid package.
Let me know when you want me to try it again.
–luis
-
Apparently I messed up the path in the patch. I fixed it, should be OK now.
-
