search

inverse-inc / packetfence

PacketFence is a fully supported, trusted, Free and Open Source network access control (NAC) solution. Boasting an impressive feature set including a captive-portal for registration and remediation, centralized wired and wireless management, powerful BYOD management options, 802.1X support, layer-2 isolation of problematic devices; PacketFence can be used to effectively secure networks small to very large heterogeneous networks.
https://packetfence.org
GNU General Public License v2.0
1.31k stars 276 forks source link

pfsetvlan doesn't process traps #655

Closed caralo closed 9 years ago

caralo commented 9 years ago

We have enabled pfsetvlan and snmptrapd in PF 5.1 Debian 7 because we are still using port-security in a Cisco 2950. In the logs we can see this when we start pfsetvlan:

pfsetvlan(6) ERROR: Thread 6 terminated abnormally: Deep recursion on subroutine "CHI::Driver::FileWITHCHI::Driver::Role::UniversalANDpf::Role::CHI::Driver::FileUmaskANDpf::Role::CHI::Driver::UntaintANDCHI::Driver::Role::HasSubcaches::new" at (eval 2139) line 47. (main::)

and the same with Thread 7 and 8

The security traps from the switch are reaching packetfence but nothing happens. pfsetvlan does nothing.

We had to go back to PF4.7 and everything is working now with the same configuration in the switch and packetfence, so there is something wrong in PF5.1 and pfsetvlan.

jrouzierinverse commented 9 years ago

Caralo thank you for reporting this.

Could you post if possible the previous 20 lines before the error occurred. This will help in the debugging effort.

caralo commented 9 years ago

OK, this is what I found:

Jun 03 11:01:01 pfcmd.pl(18096) INFO: Memory configuration is not valid anymore for key config::Pf in local cached_hash (pfconfig::cached::is_valid) Jun 03 11:01:01 pfcmd.pl(18096) INFO: Daemon memcached took 0.006 seconds to start. (pf::services::manager::launchService) Jun 03 11:01:01 pfcmd.pl(18096) INFO: Memory configuration is not valid anymore for key interfaces::internal_nets in local cached_hash (pfconfig::cached::is_valid) Jun 03 11:01:01 pfcmd.pl(18096) INFO: generating /usr/local/pf/var/conf/ssl-certificates.conf (pf::services::manager::httpd::generateConfig) Jun 03 11:01:01 pfcmd.pl(18096) INFO: generating /usr/local/pf/var/conf/captive-portal-common.conf (pf::services::manager::httpd::generateConfig) Jun 03 11:01:11 pfcmd.pl(18096) INFO: Daemon httpd.admin took 9.702 seconds to start. (pf::services::manager::launchService) Jun 03 11:01:20 pfcmd.pl(18096) INFO: Memory configuration is not valid anymore for key interfaces::monitor_int in local cached_hash (pfconfig::cached::is_valid) Jun 03 11:01:20 pfcmd.pl(18096) INFO: Memory configuration is not valid anymore for key interfaces::management_network in local cached_hash (pfconfig::cached::is_valid) Jun 03 11:01:25 pfcmd.pl(18096) INFO: Daemon carbon-cache took 0.118 seconds to start. (pf::services::manager::launchService) Jun 03 11:01:25 pfcmd.pl(18096) INFO: Daemon carbon-relay took 0.118 seconds to start. (pf::services::manager::launchService) Jun 03 11:01:25 pfcmd.pl(18096) INFO: Daemon collectd took 0.014 seconds to start. (pf::services::manager::launchService) Jun 03 11:01:25 pfcmd.pl(18096) INFO: pf::services::manager, /usr/local/pf/lib/pf/services/manager.pm, 178 (pf::services::manager::dhcpd::generateConfig) Jun 03 11:01:25 pfcmd.pl(18096) INFO: Memory configuration is not valid anymore for key interfaces::listen_ints in local cached_hash (pfconfig::cached::is_valid) Jun 03 11:01:25 pfcmd.pl(18096) ERROR: requesting member ips for an undefined interface... (pf::cluster::members_ips) Jun 03 11:01:25 pfcmd.pl(18096) ERROR: requesting member ips for an undefined interface... (pf::cluster::members_ips) Jun 03 11:01:25 pfcmd.pl(18096) ERROR: requesting member ips for an undefined interface... (pf::cluster::members_ips) Jun 03 11:01:25 pfcmd.pl(18096) ERROR: requesting member ips for an undefined interface... (pf::cluster::members_ips) Jun 03 11:01:25 pfcmd.pl(18096) ERROR: requesting member ips for an undefined interface... (pf::cluster::members_ips) Jun 03 11:01:25 pfcmd.pl(18096) ERROR: requesting member ips for an undefined interface... (pf::cluster::members_ips) Jun 03 11:01:25 pfcmd.pl(18096) ERROR: requesting member ips for an undefined interface... (pf::cluster::members_ips) Jun 03 11:01:25 pfcmd.pl(18096) ERROR: requesting member ips for an undefined interface... (pf::cluster::members_ips) Jun 03 11:01:25 pfcmd.pl(18096) ERROR: requesting member ips for an undefined interface... (pf::cluster::members_ips) Jun 03 11:01:25 pfcmd.pl(18096) INFO: Daemon dhcpd took 0.034 seconds to start. (pf::services::manager::launchService) Jun 03 11:01:27 pfcmd.pl(18096) INFO: Daemon httpd.aaa took 2.242 seconds to start. (pf::services::manager::launchService) Jun 03 11:01:30 pfcmd.pl(18096) INFO: Daemon httpd.graphite took 0.771 seconds to start. (pf::services::manager::launchService) Jun 03 11:01:34 pfcmd.pl(18096) INFO: Daemon httpd.portal took 3.580 seconds to start. (pf::services::manager::launchService) Jun 03 11:01:40 pfcmd.pl(18096) INFO: Daemon httpd.proxy took 2.217 seconds to start. (pf::services::manager::launchService) Jun 03 11:01:44 pfcmd.pl(18096) INFO: Daemon httpd.webservices took 2.360 seconds to start. (pf::services::manager::launchService) Jun 03 11:01:46 pfcmd.pl(18096) INFO: Instantiate a new iptables modification method. pf::ipset (pf::inline::get_technique) Jun 03 11:01:46 pfcmd.pl(18096) INFO: saving existing iptables to /usr/local/pf/var/iptables.bak (pf::iptables::iptables_save) Jun 03 11:01:46 pfcmd.pl(18096) WARN: We are using IPSET (pf::ipset::iptables_generate) Jun 03 11:01:46 pfcmd.pl(18096) INFO: flushing iptables (pf::ipset::iptables_flush_mangle) Jun 03 11:01:46 pfcmd.pl(18096) INFO: Adding DNS DNAT rules for unregistered and isolated inline clients. (pf::iptables::generate_inline_rules) Jun 03 11:01:46 pfcmd.pl(18096) INFO: Adding Proxy interception rules (pf::iptables::generate_inline_rules) Jun 03 11:01:46 pfcmd.pl(18096) INFO: Adding Proxy interception rules (pf::iptables::generate_inline_rules) Jun 03 11:01:46 pfcmd.pl(18096) INFO: Adding NAT Masquarade statement (PAT) (pf::iptables::generate_inline_rules) Jun 03 11:01:46 pfcmd.pl(18096) INFO: Addind ROUTED statement (pf::iptables::generate_inline_rules) Jun 03 11:01:46 pfcmd.pl(18096) INFO: building firewall to accept registered users through inline interface (pf::iptables::generate_inline_rules) Jun 03 11:01:48 pfcmd.pl(18096) INFO: restoring iptables from /usr/local/pf/var/conf/iptables.conf (pf::iptables::iptables_restore) Jun 03 11:01:50 pfcmd.pl(18096) INFO: Daemon pfbandwidthd took 1.954 seconds to start. (pf::services::manager::launchService) Jun 03 11:01:50 pfcmd.pl(18096) INFO: Daemon pfdetect took 0.005 seconds to start. (pf::services::manager::launchService) Jun 03 11:01:52 pfcmd.pl(18096) INFO: Daemon pfdhcplistener_eth0.818 took 0.013 seconds to start. (pf::services::manager::launchService) Jun 03 11:01:54 pfcmd.pl(18096) INFO: Daemon pfdhcplistener_eth0.819 took 0.007 seconds to start. (pf::services::manager::launchService) Jun 03 11:01:56 pfcmd.pl(18096) INFO: Daemon pfdhcplistener_eth0.820 took 0.007 seconds to start. (pf::services::manager::launchService) Jun 03 11:01:58 pfcmd.pl(18096) INFO: Daemon pfdhcplistener_eth0.802 took 0.006 seconds to start. (pf::services::manager::launchService) Jun 03 11:02:00 pfcmd.pl(18096) INFO: Daemon pfdns took 0.007 seconds to start. (pf::services::manager::launchService) Jun 03 11:02:04 pfcmd.pl(18096) INFO: Daemon pfmon took 2.112 seconds to start. (pf::services::manager::launchService) Jun 03 11:02:04 pfcmd.pl(18096) INFO: generating /usr/local/pf/var/conf/snmptrapd.conf (pf::services::manager::snmptrapd::generateConfig) Jun 03 11:02:04 pfcmd.pl(18096) INFO: Daemon snmptrapd took 0.029 seconds to start. (pf::services::manager::launchService) Jun 03 11:02:06 pfsetvlan(18326) INFO: pfsetvlan starting and writing 18329 to /usr/local/pf/var/run/pfsetvlan.pid (pf::services::util::createpid) Jun 03 11:02:06 pfsetvlan(18326) INFO: Process started (main::) Jun 03 11:02:06 pfcmd.pl(18096) INFO: Daemon pfsetvlan took 2.021 seconds to start. (pf::services::manager::launchService) Jun 03 11:02:08 pfcmd.pl(18096) INFO: Daemon radiusd took 1.105 seconds to start. (pf::services::manager::launchService) Jun 03 11:02:08 pfcmd.pl(18096) INFO: Daemon radsniff3 took 0.102 seconds to start. (pf::services::manager::launchService) Jun 03 11:02:08 pfcmd.pl(18096) INFO: generating /usr/local/pf/conf/snort.conf (pf::services::manager::snort::generateConfig) Jun 03 11:02:10 pfsetvlan(6) ERROR: Thread 6 terminated abnormally: Deep recursion on subroutine "CHI::Driver::FileWITHCHI::Driver::Role::UniversalANDpf::Role::CHI::Driver::FileUmaskANDpf::Role::CHI::Driver::UntaintANDCHI::Driver::Role::HasSubcaches::new" at (eval 2139) line 47. (main::) Jun 03 11:02:11 pfsetvlan(7) ERROR: Thread 7 terminated abnormally: Deep recursion on subroutine "CHI::Driver::FileWITHCHI::Driver::Role::UniversalANDpf::Role::CHI::Driver::FileUmaskANDpf::Role::CHI::Driver::UntaintANDCHI::Driver::Role::HasSubcaches::new" at (eval 2139) line 47. (main::) Jun 03 11:02:11 pfsetvlan(8) ERROR: Thread 8 terminated abnormally: Deep recursion on subroutine "CHI::Driver::FileWITHCHI::Driver::Role::UniversalANDpf::Role::CHI::Driver::FileUmaskANDpf::Role::CHI::Driver::UntaintANDCHI::Driver::Role::HasSubcaches::new" at (eval 2139) line 47. (main::) Jun 03 11:02:11 pfcmd.pl(18096) INFO: Daemon snort took 3.780 seconds to start. (pf::services::manager::launchService) Jun 03 11:02:11 pfcmd.pl(18096) INFO: Daemon statsd took 0.005 seconds to start. (pf::services::manager::launchService)

hrodenburg commented 9 years ago

I would like to post a "+1" as I am facing this same problem. I also posted on the mailing list, but just found out there was an bug filed for this issue. In my case I am using HP procurve 26xx switches. See this thread: http://www.mail-archive.com/packetfence-users%40lists.sourceforge.net/msg08582.html If more information is needed, please let me know.

erSitzt commented 9 years ago

Same here. The errors when starting pfsetvlan are gone (after applying the changes suggested for @hrodenburg in the mailing list ), but when a trap is received i get the same errors.

Jul 09 12:31:02 pfsetvlan(6) ERROR: Thread 6 terminated abnormally: Deep recursion on subroutine "CHI::Driver::File__WITH__CHI::Driver::Role::Universal__AND__pf::Role::CHI::Driver::FileUmask__AND__pf::Role::CHI::Driver::Untaint__AND__CHI::Driver::Role::HasSubcaches::new" at (eval 2086) line 47.
 (main::)
Jul 09 12:31:04 pfsetvlan(7) ERROR: Thread 7 terminated abnormally: Deep recursion on subroutine "CHI::Driver::File__WITH__CHI::Driver::Role::Universal__AND__pf::Role::CHI::Driver::FileUmask__AND__pf::Role::CHI::Driver::Untaint__AND__CHI::Driver::Role::HasSubcaches::new" at (eval 2086) line 47.
 (main::)
Jul 09 12:31:05 pfsetvlan(8) ERROR: Thread 8 terminated abnormally: Deep recursion on subroutine "CHI::Driver::File__WITH__CHI::Driver::Role::Universal__AND__pf::Role::CHI::Driver::FileUmask__AND__pf::Role::CHI::Driver::Untaint__AND__CHI::Driver::Role::HasSubcaches::new" at (eval 2086) line 47.
 (main::)

I'm using ProCurve 2920 with PF5.1

jrouzierinverse commented 9 years ago

Are you running centos or debian or ubuntu?

hrodenburg commented 9 years ago

In my case I am running ubuntu 12.04

erSitzt commented 9 years ago

Same here.

jrouzierinverse commented 9 years ago

We found the problem it is a bug in the combination of the Moo module and threads. We will update the package for the next release. (Which will be out very soon)

hrodenburg commented 9 years ago

That sounds great! Thanks!

catatonicChimp commented 9 years ago

awesome good to hear

erSitzt commented 9 years ago

Nice

catatonicChimp commented 9 years ago

Just wondering if the fix has been made to the latest dev snapshot of 5.3.0? I just installed it this afternoon and I still get same error from pfsetvlan.

Running Ubuntu 12.04, switch: D-link DGS-3210-24T

ul 16 15:40:27 httpd.webservices(2973) WARN: Unable to perform a Fingerbank lookup for device with MAC address '00:23:cc:4c:07:13' (pf::fingerbank::process) Jul 16 15:40:38 pfcmd.pl(4029) INFO: pidof -x pfsetvlan returned 3026 (pf::services::manager::pidFromFile) Jul 16 15:40:38 pfcmd.pl(4029) INFO: verifying process 3026 (pf::services::manager::removeStalePid) Jul 16 15:40:38 pfcmd.pl(4029) INFO: pidof -x pfsetvlan returned 3026 (pf::services::manager::pidFromFile) Jul 16 15:40:38 pfcmd.pl(4029) INFO: pidof -x pfsetvlan returned 3026 (pf::services::manager::pidFromFile) Jul 16 15:40:38 pfcmd.pl(4029) INFO: pidof -x pfsetvlan returned 3026 (pf::services::manager::pidFromFile) Jul 16 15:40:38 pfcmd.pl(4029) INFO: Sending TERM signal to pfsetvlan with pid 3026 (pf::services::manager::stopService) Jul 16 15:40:38 pfcmd.pl(4029) INFO: pidof -x pfsetvlan returned 3026 (pf::services::manager::pidFromFile) Jul 16 15:40:38 pfcmd.pl(4029) INFO: verifying process 3026 (pf::services::manager::removeStalePid) Jul 16 15:40:38 pfcmd.pl(4029) INFO: pidof -x pfsetvlan returned 3026 (pf::services::manager::pidFromFile) Jul 16 15:40:38 pfsetvlan(0) FATAL: pfsetvlan: caught SIGTERM - terminating at /usr/share/perl5/File/Tail.pm line 554. (main::normal_sighandler) Jul 16 15:40:38 pfsetvlan(0) FATAL: pfsetvlan: caught SIGTERM - terminating at /usr/share/perl5/File/Tail.pm line 554. (File::Tail::read) Jul 16 15:40:38 pfsetvlan(0) ERROR: pfsetvlan: caught SIGTERM - terminating at /usr/share/perl5/File/Tail.pm line 554. (File::Tail::read) Jul 16 15:40:38 pfsetvlan(0) INFO: stopping pfsetvlan (main::) Jul 16 15:40:38 pfsetvlan(0) FATAL: pfsetvlan: caught SIGTERM - terminating at /usr/share/perl5/File/Tail.pm line 554. (main::END) Jul 16 15:40:38 pfsetvlan(0) FATAL: pfsetvlan: caught SIGTERM - terminating at /usr/share/perl5/File/Tail.pm line 554. END failed--call queue aborted at /usr/local/pf/sbin/pfsetvlan line 554. (main::) Jul 16 15:40:38 pfsetvlan(0) ERROR: pfsetvlan: caught SIGTERM - terminating at /usr/share/perl5/File/Tail.pm line 554. END failed--call queue aborted at /usr/local/pf/sbin/pfsetvlan line 554. (main::) Jul 16 15:40:45 pfcmd.pl(4029) INFO: pidof -x snmptrapd returned 3023 (pf::services::manager::pidFromFile) Jul 16 15:40:45 pfcmd.pl(4029) INFO: verifying process 3023 (pf::services::manager::removeStalePid) Jul 16 15:40:45 pfcmd.pl(4029) INFO: pidof -x snmptrapd returned 3023 (pf::services::manager::pidFromFile) Jul 16 15:40:45 pfcmd.pl(4029) INFO: pidof -x snmptrapd returned 3023 (pf::services::manager::pidFromFile) Jul 16 15:40:48 pfsetvlan(4034) INFO: pfsetvlan starting and writing 4035 to /usr/local/pf/var/run/pfsetvlan.pid (pf::services::util::createpid) Jul 16 15:40:48 pfsetvlan(4034) INFO: Process started (main::) Jul 16 15:40:48 pfcmd.pl(4029) INFO: Daemon pfsetvlan took 2.855 seconds to start. (pf::services::manager::launchService) Jul 16 15:41:03 pfsetvlan(6) ERROR: Thread 6 terminated abnormally: Deep recursion on subroutine "CHI::Driver::FileWITHCHI::Driver::Role::UniversalANDpf::Role::CHI::Driver::FileUmaskANDpf::Role::CHI::Driver::UntaintANDCHI::Driver::Role::HasSubcaches::new" at (eval 2114) line 47. (main::) Jul 16 15:41:03 pfsetvlan(7) ERROR: Thread 7 terminated abnormally: Deep recursion on subroutine "CHI::Driver::FileWITHCHI::Driver::Role::UniversalANDpf::Role::CHI::Driver::FileUmaskANDpf::Role::CHI::Driver::UntaintANDCHI::Driver::Role::HasSubcaches::new" at (eval 2114) line 47. (main::)

==> radius.log <== Thu Jul 16 15:41:11 2015 : Auth: Login incorrect: [E4115B342EC3](from client 192.168.1.15 port 13 cli E4-11-5B-34-2E-C3)

==> packetfence.log <== Jul 16 15:41:13 pfsetvlan(8) ERROR: Thread 8 terminated abnormally: Deep recursion on subroutine "CHI::Driver::FileWITHCHI::Driver::Role::UniversalANDpf::Role::CHI::Driver::FileUmaskANDpf::Role::CHI::Driver::UntaintANDCHI::Driver::Role::HasSubcaches::new" at (eval 2114) line 47. (main::)

louismunro commented 9 years ago

It should be fixed. Can you post the output of this command please?

# dpkg -l | grep libmoo-perl

julsemaan commented 9 years ago

Louis, the markdown expert

louismunro commented 9 years ago

Y U NO WORK MARKDOWN?

louismunro commented 9 years ago

We have released a new devel build that is supposed to contain the fix. Try it at your convenience.

catatonicChimp commented 9 years ago

Seems it didn't like my original install... it was reporting 1.003000-1.... but I've reinstalled again and its now pointing to 1.004002-1 dpkg -l | grep libmoo-perl ii libmoo-perl 1.003000-1 Minimalist Object Orientation library (with Moose compatiblity)

ii libmoo-perl 1.004002-1 Minimalist Object Orientation (with Moose compatibility)

erSitzt commented 9 years ago

I've updated to the newer libmoo-perl and its working now. Thanks

jrouzierinverse commented 9 years ago

I am closing this issue as it seemed it was fixed.