"check_reload_status: syncing firewall" every 5 minutes in log

Pontiac_CZ · Jun 1, 2011, 5:48 AM

Hi all pfSense experts :),
I have 2.0-RC1 (i386) built on Sat Feb 26 15:30:26 EST 2011 and %subj% alert I get every 5 minutes in my System log so it looks like this:


May 27 05:17:34 	check_reload_status: syncing firewall
May 27 05:12:33 	check_reload_status: syncing firewall
May 27 05:07:33 	check_reload_status: syncing firewall
May 27 05:02:33 	check_reload_status: syncing firewall
May 27 04:57:32 	check_reload_status: syncing firewall
May 27 04:52:32 	check_reload_status: syncing firewall
May 27 04:47:32 	check_reload_status: syncing firewall
May 27 04:42:31 	check_reload_status: syncing firewall
May 27 04:37:31 	check_reload_status: syncing firewall
May 27 04:32:31 	check_reload_status: syncing firewall
May 27 04:27:30 	check_reload_status: syncing firewall
May 27 04:22:30 	check_reload_status: syncing firewall
May 27 04:17:30 	check_reload_status: syncing firewall

and it's much longer - like I say, every five minutes during a few recent days.

What is it the firewall sychronizes with? I surely didn't set up any sort of synchronization. It even happens in the deep night when noone could change firewall configuration. These messages mess up my log and push others down out of view.

I run Captive portal on this machine, home use - usually only one voucher active at a time, but none was active during these night hours that I pasted in.

On my another pfSense box I nearly cannot see them.

jimp · May 31, 2011, 4:19 PM

That just means that it reloaded the firewall rules. That can happen for a lot of different reasons.

Pontiac_CZ · Jun 1, 2011, 5:47 AM

This looks like a Microsoft support answer ;) - but no offense, I understand it is quite complicated inside. It seems to me like there is some sort of a scheduled task reloading the firewall rules every five minutes that I accidentally set up and now don't know how.
OK, I'll have to accept this behaviour or reinstall. Maybe I can put an article into Redmine…

wk · Jun 1, 2011, 7:47 AM

I have turned packet filtering off, but my log also shows this every 5 minutes.

jimp · Jun 1, 2011, 1:51 PM

It's the most accurate answer anyone can give with the minimal information provided. GIGO. :-)

If you have captive portal enabled, it may be related to something there.

Pontiac_CZ · Jun 2, 2011, 5:44 AM

Yes, I have the Captive portal enabled - this and DHCP server are the only services I work with. No VPNs, no packages.

What about you, wk? Do you use CP as well?

wk · Jun 3, 2011, 8:21 AM

Yes.
I only use CP. No other services, no other packages.

jimp · Jun 3, 2011, 11:45 AM

Vouchers or no vouchers?

Pontiac_CZ · Jun 3, 2011, 11:53 AM

I do use vouchers. The rules still keep reloading every 5 minutes, days and nights, no matter if a voucher is active or not. (actually I mentioned this in my first post, but let's have it confirmed)
wk?

jimp · Jun 3, 2011, 11:58 AM

Check the output of these two commands:

$ ps uxawww | grep minicron
$ cat /etc/crontab

See what entries you have that might be executing every 5 minutes. (Though it could easily not be a cron job…)

Pontiac_CZ · Jun 3, 2011, 12:06 PM

The first one:


$ ps uxawww | grep minicron
root   27262  0.0  0.2  3316  1036  ??  Is   19May11   0:00.97 /usr/local/bin/minicron 240 /var/run/ping_hosts.pid /usr/local/bin/ping_hosts.sh
root   27584  0.0  0.2  3316  1036  ??  Is   19May11   0:00.07 /usr/local/bin/minicron 3600 /var/run/expire_accounts.pid /etc/rc.expireaccounts
root   27746  0.0  0.2  3316  1036  ??  Is   19May11   0:00.00 /usr/local/bin/minicron 86400 /var/run/update_alias_url_data.pid /etc/rc.update_alias_url_data
root   37975  0.0  0.3  3656  1476  ??  S     2:04PM   0:00.00 sh -c ps uxawww | grep minicron
root   38435  0.0  0.3  3524  1268  ??  S     2:04PM   0:00.00 grep minicron
root   58830  0.0  0.2  3316  1040  ??  Is   19May11   0:04.06 /usr/local/bin/minicron 60 /var/run/cp_prunedb.pid /etc/rc.prunecaptiveportal
root   59217  0.0  0.2  3316  1040  ??  Is   19May11   0:00.82 /usr/local/bin/minicron 300 /var/run/vouchercron.pid /etc/rc.savevoucher

and the other:


$ cat /etc/crontab
SHELL=/bin/sh
PATH=/etc:/bin:/sbin:/usr/bin:/usr/sbin
HOME=/var/log
#minute hour    mday    month   wday    who      command
#
#
# pfSense specific crontab entries
# Created: May 19, 2011, 7:50 am
#

0	*	*	*	*	root	/usr/bin/nice -n20 newsyslog
1,31	0-5	*	*	*	root	/usr/bin/nice -n20 adjkerntz -a
1	3	1	*	*	root	/usr/bin/nice -n20 /etc/rc.update_bogons.sh
*/60	*	*	*	*	root	/usr/bin/nice -n20 /usr/local/sbin/expiretable -v -t 3600 sshlockout
1	1	*	*	*	root	/usr/bin/nice -n20 /etc/rc.dyndns.update
*/60	*	*	*	*	root	/usr/bin/nice -n20 /usr/local/sbin/expiretable -v -t 3600 virusprot
30	12	*	*	*	root	/usr/bin/nice -n20 /etc/rc.update_urltables
#
# If possible do not add items to this file manually.
# If you do so, this file must be terminated with a blank line (e.g. new line)
#

jimp · Jun 3, 2011, 12:16 PM

If you run /etc/rc.savevoucher by hand, does it make that message appear in the logs? That appears to be the only thing running every five minutes.

Pontiac_CZ · Jun 3, 2011, 12:54 PM

Ok, I sent the "/etc/rc.savevoucher" command to the pfSense box through "Execute Shell Command" field - but since then the system's been unresponsive (five minutes). Are you sure that was a good idea? :)
I am awaiting a desperate call from my employer any minute…

wk · Jun 3, 2011, 1:00 PM

I'm using vouchers too.

I executed the command via ssh and it worked as jimp said.
The message appeares in the log.

wallabybob · Jun 3, 2011, 1:10 PM

I'm running captive portal and vouchers and I see those messages in the system log:

clog /var/log/system.log | grep syncing | more

May 28 18:38:38 pfsense2 check_reload_status: syncing firewall
May 28 18:43:42 pfsense2 check_reload_status: syncing firewall
May 28 18:48:45 pfsense2 check_reload_status: syncing firewall
May 28 18:53:48 pfsense2 check_reload_status: syncing firewall
May 28 18:58:51 pfsense2 check_reload_status: syncing firewall
May 28 19:03:55 pfsense2 check_reload_status: syncing firewall
May 28 19:08:59 pfsense2 check_reload_status: syncing firewall
May 28 19:14:02 pfsense2 check_reload_status: syncing firewall
May 28 19:19:06 pfsense2 check_reload_status: syncing firewall
May 28 19:24:09 pfsense2 check_reload_status: syncing firewall
May 28 19:29:13 pfsense2 check_reload_status: syncing firewall
May 28 19:34:15 pfsense2 check_reload_status: syncing firewall
May 28 19:39:19 pfsense2 check_reload_status: syncing firewall
May 28 19:44:22 pfsense2 check_reload_status: syncing firewall
May 28 19:49:25 pfsense2 check_reload_status: syncing firewall
May 28 19:54:28 pfsense2 check_reload_status: syncing firewall
May 28 19:59:32 pfsense2 check_reload_status: syncing firewall
May 28 20:04:35 pfsense2 check_reload_status: syncing firewall
May 28 20:09:38 pfsense2 check_reload_status: syncing firewall
May 28 20:14:42 pfsense2 check_reload_status: syncing firewall
May 28 20:19:46 pfsense2 check_reload_status: syncing firewall
May 28 20:24:49 pfsense2 check_reload_status: syncing firewall
May 28 20:29:52 pfsense2 check_reload_status: syncing firewall
May 28 20:34:55 pfsense2 check_reload_status: syncing firewall
May 28 20:39:58 pfsense2 check_reload_status: syncing firewall
May 28 20:45:01 pfsense2 check_reload_status: syncing firewall
May 28 20:50:04 pfsense2 check_reload_status: syncing firewall
May 28 20:55:08 pfsense2 check_reload_status: syncing firewall
May 28 21:00:11 pfsense2 check_reload_status: syncing firewall
. . .

On my other pfSense system where I'm not running captive portal:

clog /var/log/system.log | grep syncing | more

uname -a

FreeBSD pfsense.example.org 8.1-RELEASE-p3 FreeBSD 8.1-RELEASE-p3 #1: Sat May 21 21:30:20 EDT 2011 sullrich@FreeBSD_8.0_pfSense_2.0-snaps.pfsense.org:/usr/obj.pfSense/usr/pfSensesrc/src/sys/pfSense.8 i386

uptime

11:09PM up 8 days, 14:54, 2 users, load averages: 0.15, 0.10, 0.07

I'm running the same pfSense build on both systems.

jimp · Jun 3, 2011, 1:11 PM

So mystery solved. It's the voucher saving process every five minutes causing the log message.

It's also writing out the config every five minutes in that case, too, so I imagine that your backup history under Diagnostics > Backup/Restore is quite useless.

wk · Jun 3, 2011, 1:38 PM

Jimp,

you are right. The Config History also tells every 5 minutes: (system): made unknown change

Thanks for helping.

Pontiac_CZ · Jun 3, 2011, 1:48 PM

Well, does that mean something for devs? Do you consider that bug? May we look forward to this to be fixed in the post-RC version? :)

jimp · Jun 3, 2011, 1:55 PM

If you enable the voucher save feature, it will always happen. You can change how often this happens in the voucher config options.

Without saving the vouchers periodically, a sudden reboot would lose voucher usage data.

wk · Jun 3, 2011, 2:01 PM

jimp,

the text in the gui tells: 'No save is done if no new vouchers have been activated.'

There are no new vouchers or active vouchers.