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

Flole · Aug 8, 2022, 1:24 PM

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

It does if there's an error in the ruleset, yes. It doesn't if the rules file is empty though:

You are getting exit code 0 there though, I am getting exit code 1 there.

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

We have seen devices load a kernel from another storage device but I've never been able to replicate that here. Obviously that only applies if you have more than one drive in the system.

It's a single drive only. I always wanted to migrate to ZFS though and use mirroring on this system, so maybe it's a good time now to backup the config and reinstall using ZFS on 2 drives.

I just saw in the system log this message from snort being logged:

s2c_pf_block() => ioctl() DIOCRADDADDRS: No such process

So maybe this gives more information on what's going on? I assume the same ioctl call is being made by pfctl aswell and most likely the same error is returned there? Just that pfctl isn't displaying that error.

In the boot log I am only seeing this error, but it seems unrelated:

dummynet: bad switch 21!

stephenw10 · Aug 8, 2022, 1:32 PM

Yeah those errors all point to a mismatch in something but I'm unsure what if the kernel and pfctl are correct.

The quickest way back up is going to be a re-install though.

Steve

Flole · Aug 8, 2022, 1:37 PM

Maybe it's the library thats not matching? Snort doesn't call pfctl I think, if it uses the library which pfctl also uses and that one is corrupted/wrong that could explain it.

sha256sum ./usr/lib/libpfctl*
bd164a6f18720e395fae0b30ae552afb04b5a86919e9ab8e0ba433678ef5b75b  ./usr/lib/libpfctl.a
aa7aa511a5d26c453dbbae04568ae5cecd39407d2b53be1fc66d51669af796c4  ./usr/lib/libpfctl.so
aa7aa511a5d26c453dbbae04568ae5cecd39407d2b53be1fc66d51669af796c4  ./usr/lib/libpfctl.so.5

bmeeks · Aug 8, 2022, 1:40 PM

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

Maybe it's the library thats not matching? Snort doesn't call pfctl I think, if it uses the library which pfctl also uses and that one is corrupted/wrong that could explain it.
sha256sum ./usr/lib/libpfctl*
bd164a6f18720e395fae0b30ae552afb04b5a86919e9ab8e0ba433678ef5b75b  ./usr/lib/libpfctl.a
aa7aa511a5d26c453dbbae04568ae5cecd39407d2b53be1fc66d51669af796c4  ./usr/lib/libpfctl.so
aa7aa511a5d26c453dbbae04568ae5cecd39407d2b53be1fc66d51669af796c4  ./usr/lib/libpfctl.so.5

As the author of the custom Snort plugin I can tell you how it works. It is making direct ioctl() system calls for all of its operations with the packet filter firewall. Those system calls will wind up using the library. You have a corrupted installation with mismatching versions of core system libraries.

stephenw10 · Aug 8, 2022, 1:41 PM

Looks like the expected values:

[22.05-RELEASE][admin@4100-2.stevew.lan]/root: sha256 /usr/lib/libpfctl*
SHA256 (/usr/lib/libpfctl.a) = bd164a6f18720e395fae0b30ae552afb04b5a86919e9ab8e0ba433678ef5b75b
SHA256 (/usr/lib/libpfctl.so) = aa7aa511a5d26c453dbbae04568ae5cecd39407d2b53be1fc66d51669af796c4
SHA256 (/usr/lib/libpfctl.so.5) = aa7aa511a5d26c453dbbae04568ae5cecd39407d2b53be1fc66d51669af796c4

bmeeks · Aug 8, 2022, 1:44 PM

Did you by chance, at any point in the recent past, install some third-party package or otherwise switch the pkg repo pointer? The symptoms sound like some libraries on the system do not now match up with others.

Flole · Aug 8, 2022, 1:45 PM

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

You have a corrupted installation with mismatching versions of core system libraries.

Not entirely sure how that could happen by simply rebooting and why the initial loading of the rules when booting works (aswell as querying the rules/tables and so on) though. To me that sounds like something after the initial loading is causing those errors, otherwise no rules would be loaded?

Others solved the same behaviour by rebooting, that obviously doesn't fix a mismatched version.

stephenw10 · Aug 8, 2022, 1:48 PM

I suspect in the cases that fixed this by simply rebooting it had somehow loaded an old kernel from a different device.

I assume you are running Snort?

Flole · Aug 8, 2022, 1:49 PM

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

Did you by chance, at any point in the recent past, install some third-party package or otherwise switch the pkg repo pointer? The symptoms sound like some libraries on the system do not now match up with others.

No I didn't, I did a normal reboot and since then things started acting in this weird way. I don't think I updated any packages since I upgraded to 2.6.0 (and that was already a few weeks ago). A messed up library would be used immediately without rebooting though.

bmeeks · Aug 8, 2022, 1:50 PM

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

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

You have a corrupted installation with mismatching versions of core system libraries.

Not entirely sure how that could happen by simply rebooting and why the initial loading of the rules when booting works (aswell as querying the rules/tables and so on) though. To me that sounds like something after the initial loading is causing those errors, otherwise no rules would be loaded?

Others solved the same behaviour by rebooting, that obviously doesn't fix a mismatched version.

The Snort error you posted is coming directly from the custom blocking plug-in code. When the Snort binary is implementing a "block", it does so by making a pf call using the ioctl() primitive within FreeBSD. It passes an Op-Code along with the system call letting the OS know what it wants. In the case of your error, it is asking pf to add an IP address to the snort2c table. That is what the DIOCRADDADDRS op-code means.

The fact that call is failing tells me that the code for that operation is not present in the OS. But it should always be there.

bmeeks · Aug 8, 2022, 1:52 PM

The shortest road back to normal operation may be a reinstall.

Flole · Aug 8, 2022, 1:57 PM

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

I assume you are running Snort?

Correct, I am running Snort.

It doesn't seem completely broken though:

[22.05-RELEASE][root@XXXXXXX]/: pfctl -d
pf disabled
[22.05-RELEASE][root@XXXXXXX]/: pfctl -e
pf enabled

So it works to some extend apparently. And even running pfctl -a shows that rules are loaded. It seems to me like somehow it's not possible to add new rules to the filter.

However, clearing rules also does not work:

[22.05-RELEASE][root@XXXXXX]/: pfctl -Fa
pfctl: pfctl_clear_eth_rules: Device busy

Is that really the behaviour if there's a mismatch of some libraries? How do the rules end up there initially and why can I query them properly?

stephenw10 · Aug 8, 2022, 2:23 PM

Try running:

truss pfctl -g -f /tmp/rules.debug

Flole · Aug 8, 2022, 2:29 PM

Looks like it does "prepare" them to some extend and then tries to apply(?), which fails and then rolls back:

....
ioctl(3,DIOCOSFPADD,0x7fffffffe450)              = 0 (0x0)
ioctl(3,DIOCOSFPADD,0x7fffffffe450)              = 0 (0x0)
read(4,0x8007174c0,32768)                        = 0 (0x0)
close(4)                                         = 0 (0x0)
mmap(0x0,28672,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_ANON,-1,0x0) = 34367270912 (0x80072f000)
mmap(0x0,20480,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_ANON,-1,0x0) = 34367299584 (0x800736000)
mmap(0x0,86016,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_ANON,-1,0x0) = 34367320064 (0x80073b000)
ioctl(3,DIOCXBEGIN,0x7fffffffd568)               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,0x7fffffffd5a8)            = 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

stephenw10 · Aug 8, 2022, 3:10 PM

Hmm, not really anything very insightful there unfortunately.

I would reinstall that if that's an option for you.

Flole · Aug 8, 2022, 3:28 PM

Isn't the "Device busy" error when it comes to applying those rules showing that something causes some kind of lockup? The first rule loading works apparently, otherwise after a reboot I would end up with an empty ruleset, but something later on causes issue. For examble pf_begin_eth would return EBUSY if it's still waiting for NET_EPOCH_CALL(pf_rollback_eth_cb) to finish (according to the comments in there). As the ethernet-based filtering is new in 2.6.0 afaik it could be that it introduced a bug, especially since I am not the only one having such an issue and such a lockup would also be fixed with a reboot (assuming after the reboot it isn't simply caused again), so that's consistent with what others are seeing aswell, except for me apparently the issue is automatically re-triggered after a reboot for some reason.

I will try a reinstall though so I finally migrate to ZFS and have redundant disks aswell, the second HDD is in the appliance now for a few years but is completely unused so far :D

stephenw10 · Aug 8, 2022, 4:37 PM

Yeah, it could well be a bug. I have alerted out developers.

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.