Strange error: There were error(s) loading the rules: pfctl: pfctl_rules

artooro · Aug 9, 2022, 4:11 PM

I've been seeing this problem on quite a few firewalls after upgrading to pfSense 22.05
Normally a reboot resolves the issue for awhile until something triggers it again.
And I have not been able to figure out what triggers it.

A router that had the problem, after a reboot the truss command ends with

exit(0x0)					
process exit, rval = 0

But when the issue has been triggered prior to reboot it ends with

ioctl(3,DIOCOSFPADD,0xbfbfe5c8)			= 0 (0x0)
ioctl(3,DIOCOSFPADD,0xbfbfe5c8)			= 0 (0x0)
ioctl(3,DIOCOSFPADD,0xbfbfe5c8)			= 0 (0x0)
ioctl(3,DIOCOSFPADD,0xbfbfe5c8)			= 0 (0x0)
ioctl(3,DIOCOSFPADD,0xbfbfe5c8)			= 0 (0x0)
read(4,0x20401c80,32768)			= 0 (0x0)
close(4)					= 0 (0x0)
mmap(0x0,12288,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_ANON,-1,0x20600008) = 541171712 (0x2041a000)
mmap(0x0,12288,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_ANON,-1,0x20600008) = 541184000 (0x2041d000)
mmap(0x0,20480,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_ANON,-1,0x20600008) = 541196288 (0x20420000)
mmap(0x0,86016,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_ANON,-1,0x20600008) = 541216768 (0x20425000)
ioctl(3,DIOCXBEGIN,0xbfbfd9d0)			ERR#16 'Device busy'
pfctl: write(2,"pfctl: ",7)				= 7 (0x7)
pfctl_ruleswrite(2,"pfctl_rules",11)			= 11 (0xb)

write(2,"\n",1)					= 1 (0x1)
ioctl(3,DIOCXROLLBACK,0xbfbfd9f0)		= 0 (0x0)
sigprocmask(SIG_BLOCK,{ SIGHUP|SIGINT|SIGQUIT|SIGKILL|SIGPIPE|SIGALRM|SIGTERM|SIGURG|SIGSTOP|SIGTSTP|SIGCONT|SIGCHLD|SIGTTIN|SIGTTOU|SIGIO|SIGXCPU|SIGXFSZ|SIGVTALRM|SIGPROF|SIGWINCH|SIGINFO|SIGUSR1|SIGUSR2 },{ }) = 0 (0x0)
sigprocmask(SIG_SETMASK,{ },0x0)		= 0 (0x0)
sigprocmask(SIG_BLOCK,{ SIGHUP|SIGINT|SIGQUIT|SIGKILL|SIGPIPE|SIGALRM|SIGTERM|SIGURG|SIGSTOP|SIGTSTP|SIGCONT|SIGCHLD|SIGTTIN|SIGTTOU|SIGIO|SIGXCPU|SIGXFSZ|SIGVTALRM|SIGPROF|SIGWINCH|SIGINFO|SIGUSR1|SIGUSR2 },{ }) = 0 (0x0)
sigprocmask(SIG_SETMASK,{ },0x0)		= 0 (0x0)
sigprocmask(SIG_BLOCK,{ SIGHUP|SIGINT|SIGQUIT|SIGKILL|SIGPIPE|SIGALRM|SIGTERM|SIGURG|SIGSTOP|SIGTSTP|SIGCONT|SIGCHLD|SIGTTIN|SIGTTOU|SIGIO|SIGXCPU|SIGXFSZ|SIGVTALRM|SIGPROF|SIGWINCH|SIGINFO|SIGUSR1|SIGUSR2 },{ }) = 0 (0x0)
sigprocmask(SIG_SETMASK,{ },0x0)		= 0 (0x0)
sigprocmask(SIG_BLOCK,{ SIGHUP|SIGINT|SIGQUIT|SIGKILL|SIGPIPE|SIGALRM|SIGTERM|SIGURG|SIGSTOP|SIGTSTP|SIGCONT|SIGCHLD|SIGTTIN|SIGTTOU|SIGIO|SIGXCPU|SIGXFSZ|SIGVTALRM|SIGPROF|SIGWINCH|SIGINFO|SIGUSR1|SIGUSR2 },{ }) = 0 (0x0)
sigprocmask(SIG_SETMASK,{ },0x0)		= 0 (0x0)
sigprocmask(SIG_BLOCK,{ SIGHUP|SIGINT|SIGQUIT|SIGKILL|SIGPIPE|SIGALRM|SIGTERM|SIGURG|SIGSTOP|SIGTSTP|SIGCONT|SIGCHLD|SIGTTIN|SIGTTOU|SIGIO|SIGXCPU|SIGXFSZ|SIGVTALRM|SIGPROF|SIGWINCH|SIGINFO|SIGUSR1|SIGUSR2 },{ }) = 0 (0x0)
sigprocmask(SIG_SETMASK,{ },0x0)		= 0 (0x0)
sigprocmask(SIG_BLOCK,{ SIGHUP|SIGINT|SIGQUIT|SIGKILL|SIGPIPE|SIGALRM|SIGTERM|SIGURG|SIGSTOP|SIGTSTP|SIGCONT|SIGCHLD|SIGTTIN|SIGTTOU|SIGIO|SIGXCPU|SIGXFSZ|SIGVTALRM|SIGPROF|SIGWINCH|SIGINFO|SIGUSR1|SIGUSR2 },{ }) = 0 (0x0)
sigprocmask(SIG_SETMASK,{ },0x0)		= 0 (0x0)
sigprocmask(SIG_BLOCK,{ SIGHUP|SIGINT|SIGQUIT|SIGKILL|SIGPIPE|SIGALRM|SIGTERM|SIGURG|SIGSTOP|SIGTSTP|SIGCONT|SIGCHLD|SIGTTIN|SIGTTOU|SIGIO|SIGXCPU|SIGXFSZ|SIGVTALRM|SIGPROF|SIGWINCH|SIGINFO|SIGUSR1|SIGUSR2 },{ }) = 0 (0x0)
sigprocmask(SIG_SETMASK,{ },0x0)		= 0 (0x0)
sigprocmask(SIG_BLOCK,{ SIGHUP|SIGINT|SIGQUIT|SIGKILL|SIGPIPE|SIGALRM|SIGTERM|SIGURG|SIGSTOP|SIGTSTP|SIGCONT|SIGCHLD|SIGTTIN|SIGTTOU|SIGIO|SIGXCPU|SIGXFSZ|SIGVTALRM|SIGPROF|SIGWINCH|SIGINFO|SIGUSR1|SIGUSR2 },{ }) = 0 (0x0)
sigprocmask(SIG_SETMASK,{ },0x0)		= 0 (0x0)
exit(0x1)					
process exit, rval = 1

I've verified that there are no duplicate firewall rules and NAT reflection is disabled.
The only reason it might be triggered with our installs more than others is because we use a lot of tables to filter traffic and these tables are constantly being updated.

Flole · Aug 9, 2022, 4:14 PM

@artooro Looks like exactly the same thing I'm seeing, except for me it happens instantly. I'm trying to spin up a VM now so I can test without rebooting, let's hope that the VM also shows this issue.

artooro · Aug 9, 2022, 4:35 PM

Depends on if available CPU has anything to do with it. I've not switched to pfSense Plus on any VMs and I don't think I've seen this on any v2.6.0 CE installs yet.

Even disabling and re-enabling pf does not help, a full system reboot seems to be required.

Flole · Aug 9, 2022, 4:38 PM

@artooro There was a new feature introduced in the latest plus for filtering based on MAC-Addresses. If that implementation broke something it won't be visible on previous versions.

Flole · Aug 9, 2022, 7:01 PM

I tried to replicate the issue on a VM but no luck there. I was obviously not able to replicate all Interfaces there so it might have something to do with that aswell. I tried to do simultaneous rule loading by firing multiple pfctl commands at the same time just to see if they maybe tangle with each other, but that was also unsuccessful.

artooro · Aug 9, 2022, 7:06 PM

@flole I have noticed that editing interfaces can trigger it as well, but not consistently.

Flole · Aug 11, 2022, 9:38 PM

Have you heard anything back from the developers yet? Just imagine the consequences if this bug hits in a critical environment, it should be fixed ASAP.

jacko · Aug 11, 2022, 10:01 PM

I also just had this error on my SG-1100, nothing seemed to trigger it. I rebooted it, it worked for about 2 mins and then no network connection again. I could not ping anything including the router, 2nd reboot and so far it's still running.
Was running PFBlockerNg 3.1.0_4, but I've now disabled it.

Theses are the errors:

There were error(s) loading the rules: pfctl: pfctl_rules - The line in question reads [0]: @ 2022-08-11 22:26:17
There were error(s) loading the rules: pfctl: pfctl_rules - The line in question reads [0]: @ 2022-08-11 22:26:20
There were error(s) loading the rules: pfctl: pfctl_rules - The line in question reads [0]: @ 2022-08-11 22:26:29
There were error(s) loading the rules: pfctl: pfctl_rules - The line in question reads [0]: @ 2022-08-11 22:37:02

Flole · Aug 11, 2022, 10:12 PM

@jacko Just be glad that it failed in a "block-all" state for you. An "allow-all" state is much worse, especially if it's unnoticed....

stephenw10 · Aug 11, 2022, 11:31 PM

Mmm, unfortunately this is unhelpful:
ioctl(3,DIOCXBEGIN,0xbfbfd9d0) ERR#16 'Device busy'

The issue has already happened and pf is no longer responding to pfctl. What we'd need there is to see the truss output from the first invocation of pfctl after boot. But that's not easy.
We are looking at it but we've not been able to replicate it locally. Yet.

I opened a bug to track it. Add any new info you have there:
https://redmine.pfsense.org/issues/13408

Steve

Flole · Aug 11, 2022, 11:42 PM

@stephenw10 Maybe it would help to add additional debug output in pf's code? Is it clear where the wrong branch is taken/where the error is actually thrown? If that's unclear it's probably a good idea to figure that out first. One possible way is probably the one I described above, but is there another one? If it's clear what state the firewall ends up in then it's easier to figure out potential ways how it could end up in that state.

artooro · Aug 12, 2022, 3:08 AM

@stephenw10 thanks, what I'll attempt tomorrow is to edit https://github.com/pfsense/pfsense/blob/60a2fa6b6f1a59f3f86933265fbb48e25f652bfc/src/etc/inc/filter.inc#L527 to use truss and output to a log file, and see if we can get something helpful there.
As I have a couple of systems where it's pretty easy to reproduce.

Flole · Aug 13, 2022, 7:36 AM

@artooro I'd make a copy of every rules-file that's loaded there aswell. Just to see if loading those files in the same order causes the issue.

Flole · Aug 16, 2022, 5:20 PM

After some reboots it started working again for me aswell. I noticed that my GIF tunnels did not come up this time. Maybe it is related? Are others affected by this also using (multiple) GIF tunnels?

ChrisJenk · Aug 16, 2022, 5:23 PM

@flole said in Strange error: There were error(s) loading the rules: pfctl: pfctl_rules:

After some reboots it started working again for me aswell. I noticed that my GIF tunnels did not come up this time. Maybe it is related? Are others affected by this also using (multiple) GIF tunnels?

I have a single GIF tunnel (a 6in4 for HE Tunnelbroker).

stephenw10 · Aug 16, 2022, 7:42 PM

Hmm, that could be a clue. Though I haven't seen it on any test box I have that has GIF tunnels.So maybe something else required on that specifically.

artooro · Aug 16, 2022, 8:00 PM

I've been able to capture the initial pfctl that fails via truss which I've attached here:
1-truss_pfctl_1660664796.txt

I don't have any GIF tunnels, but do use WireGuard interfaces.

And if anyone is interested in capturing this themselves, what I did is edit /etc/src/filter.inc and commented out line 527 and added the following quick and dirty code:

		$_grbg = exec("/usr/bin/truss /sbin/pfctl -o basic -f {$g['tmp_path']}/rules.debug 2>&1", $rules_error, $rules_loading);
		$rval = 0;
		if ($rules_error[count($rules_error)-1] == "process exit, rval = 1") {
			$rval = 1;
			file_notice("filter_load", sprintf("pfctl process exit, rval = 1"), "Filter Reload", "");
		}
		$date = new DateTime();
		$truss_filename = "/root/" . $rval . "-truss_pfctl_" . $date->getTimestamp() . ".txt";
		file_put_contents($truss_filename, implode("\n", $rules_error));

Flole · Aug 16, 2022, 8:44 PM

@artooro Maybe you should post the one that ran right before it aswell, just in case something there was already messed up. But it looks promising to me, I believe @kprovost is the pfctl and Kernel expert, maybe he can spot a potential bug based on that truss-output?

Keep in mind that if you're using the captive portal pfctl is invoked at (at least) one other location aswell.

stephenw10 · Aug 16, 2022, 8:49 PM

Yup I pinged him. Late where he is though, I hope he's enjoying a beer by now.

artooro · Aug 16, 2022, 8:59 PM

@flole I checked and the previous run is the same as all the successful invocations.