PacketFence - BTS - PacketFence
View Issue Details
IDProjectCategoryView StatusDate SubmittedLast Update
0001545PacketFencedhcppublic2012-09-11 10:182012-10-19 10:15
Reporterobilodeau 
Assigned To 
PrioritynormalSeverityminorReproducibilityhave not tried
StatusresolvedResolutionfixed 
PlatformLinuxOSDebianOS Version
Product Version3.5.1 
Target Version3.6.0Fixed in Versiondevel 
fixed in git revision4e7e8a8123
fixed in mtn revision
Summary0001545: pfdhcplistener management regressions
DescriptionAs reported on the mailing list:

I've just carried out a new installation of PacketFence 3.5.1 on Debian and everything seems to be working 
properly, apart from pfdhcplistener. It isn't being started by the PacketFence init script, apparently 
because it's already running:

$ sudo /usr/local/pf/bin/pfcmd service pfdhcplistener status
service|shouldBeStarted|pid
pfdhcplistener|1|1954 1956 1958
$

$ sudo /usr/local/pf/bin/pfcmd service pfdhcplistener start
Checking configuration sanity...
service|command
config files|start
iptables|start
pfdhcplistener|already running
$

$ sudo /usr/local/pf/bin/pfcmd service pfdhcplistener stop
service|command
pfdhcplistener|stop
$

$ sudo /usr/local/pf/bin/pfcmd service pfdhcplistener status
service|shouldBeStarted|pid
pfdhcplistener|1|2067 2069 2071
$

The packetfence.log file contains the following for the period during which the above command were run:


Sep 07 15:25:16 pfcmd(1953) INFO: Executing pfcmd service pfdhcplistener status (main::service)
Sep 07 15:25:16 pfcmd(1953) INFO: /usr/local/pf/sbin/pfdhcplistener status (pf::services::service_ctl)

Sep 07 15:25:16 pfcmd(1953) INFO: pfdhcplistener pids eth0.3299 => 1954, eth0.3199 => 1956, eth0 
=> 1958 (pf::services::service_ctl)
Sep 07 15:25:20 pfcmd(1961) INFO: Executing pfcmd service pfdhcplistener start (main::service)
Sep 07 15:25:22 pfcmd(1961) INFO: /usr/sbin/named status (pf::services::service_ctl)
Sep 07 15:25:22 pfcmd(1961) INFO: pidof -x named returned 0 (pf::services::service_ctl)
Sep 07 15:25:22 pfcmd(1961) INFO: /usr/sbin/dhcpd status (pf::services::service_ctl)
Sep 07 15:25:22 pfcmd(1961) INFO: pidof -x dhcpd returned 0 (pf::services::service_ctl)
Sep 07 15:25:22 pfcmd(1961) INFO: /usr/sbin/snort status (pf::services::service_ctl)
Sep 07 15:25:22 pfcmd(1961) INFO: pidof -x snort returned 0 (pf::services::service_ctl)
Sep 07 15:25:22 pfcmd(1961) INFO: /usr/bin/suricata status (pf::services::service_ctl)
Sep 07 15:25:22 pfcmd(1961) INFO: pidof -x suricata returned 0 (pf::services::service_ctl)
Sep 07 15:25:22 pfcmd(1961) INFO: /usr/sbin/freeradius status (pf::services::service_ctl)
Sep 07 15:25:22 pfcmd(1961) INFO: pidof -x freeradius returned 1642 (pf::services::service_ctl)
Sep 07 15:25:22 pfcmd(1961) INFO: /usr/sbin/apache2 status (pf::services::service_ctl)
Sep 07 15:25:22 pfcmd(1961) INFO: pidof -x apache2 returned 1703 1702 1701 1700 1699 1686 (pf::services::service_ctl)

Sep 07 15:25:22 pfcmd(1961) INFO: /usr/sbin/snmptrapd status (pf::services::service_ctl)
Sep 07 15:25:22 pfcmd(1961) INFO: pidof -x snmptrapd returned 1688 (pf::services::service_ctl)
Sep 07 15:25:22 pfcmd(1961) INFO: /usr/local/pf/sbin/pfdetect status (pf::services::service_ctl)
Sep 07 15:25:22 pfcmd(1961) INFO: pidof -x pfdetect returned 0 (pf::services::service_ctl)
Sep 07 15:25:22 pfcmd(1961) INFO: /usr/local/pf/sbin/pfredirect status (pf::services::service_ctl)
Sep 07 15:25:22 pfcmd(1961) INFO: pidof -x pfredirect returned 0 (pf::services::service_ctl)
Sep 07 15:25:22 pfcmd(1961) INFO: /usr/local/pf/sbin/pfsetvlan status (pf::services::service_ctl)
Sep 07 15:25:22 pfcmd(1961) INFO: pidof -x pfsetvlan returned 1696 (pf::services::service_ctl)
Sep 07 15:25:22 pfcmd(1961) INFO: /usr/local/pf/sbin/pfdhcplistener status (pf::services::service_ctl)

Sep 07 15:25:22 pfcmd(1961) INFO: pfdhcplistener pids eth0.3299 => 1975, eth0.3199 => 1977, eth0 
=> 1979 (pf::services::service_ctl)
Sep 07 15:25:22 pfcmd(1961) INFO: /usr/local/pf/sbin/pfmon status (pf::services::service_ctl)
Sep 07 15:25:22 pfcmd(1961) INFO: pidof -x pfmon returned 1695 (pf::services::service_ctl)
Sep 07 15:25:23 pfcmd(1961) INFO: restoring iptables from /usr/local/pf/var/conf/iptables.conf (pf::iptables::iptables_restore)

Sep 07 15:26:05 pfcmd(1986) INFO: Executing pfcmd service pfdhcplistener stop (main::service)
Sep 07 15:26:05 pfcmd(1986) INFO: /usr/local/pf/sbin/pfdhcplistener stop (pf::services::service_ctl)

Sep 07 15:26:05 pfcmd(1986) INFO: Stopping pfdhcplistener with '/usr/bin/pkill pfdhcplistener' (pf::services::service_ctl)

Sep 07 15:26:05 pfcmd(1986) INFO: /usr/local/pf/sbin/pfdhcplistener status (pf::services::service_ctl)

Sep 07 15:26:05 pfcmd(1986) INFO: pfdhcplistener pids eth0.3299 => 1988, eth0.3199 => 1990, eth0 
=> 1992 (pf::services::service_ctl)
Sep 07 15:26:05 pfcmd(1986) INFO: Waiting for pfdhcplistener to stop (pf::services::service_ctl)
Sep 07 15:26:07 pfcmd(1986) INFO: /usr/local/pf/sbin/pfdhcplistener status (pf::services::service_ctl)

Sep 07 15:26:08 pfcmd(1986) INFO: pfdhcplistener pids eth0.3299 => 1994, eth0.3199 => 1996, eth0 
=> 1998 (pf::services::service_ctl)
Sep 07 15:26:08 pfcmd(1986) INFO: Waiting for pfdhcplistener to stop (pf::services::service_ctl)
Sep 07 15:26:10 pfcmd(1986) INFO: /usr/local/pf/sbin/pfdhcplistener status (pf::services::service_ctl)

Sep 07 15:26:10 pfcmd(1986) INFO: pfdhcplistener pids eth0.3299 => 2000, eth0.3199 => 2002, eth0 
=> 2004 (pf::services::service_ctl)
Sep 07 15:26:10 pfcmd(1986) INFO: Waiting for pfdhcplistener to stop (pf::services::service_ctl)
Sep 07 15:26:12 pfcmd(1986) INFO: /usr/local/pf/sbin/pfdhcplistener status (pf::services::service_ctl)

Sep 07 15:26:12 pfcmd(1986) INFO: pfdhcplistener pids eth0.3299 => 2006, eth0.3199 => 2008, eth0 
=> 2010 (pf::services::service_ctl)
Sep 07 15:26:12 pfcmd(1986) INFO: Waiting for pfdhcplistener to stop (pf::services::service_ctl)
Sep 07 15:26:14 pfcmd(1986) INFO: /usr/local/pf/sbin/pfdhcplistener status (pf::services::service_ctl)

Sep 07 15:26:14 pfcmd(1986) INFO: pfdhcplistener pids eth0.3299 => 2012, eth0.3199 => 2014, eth0 
=> 2016 (pf::services::service_ctl)
Sep 07 15:26:14 pfcmd(1986) INFO: Waiting for pfdhcplistener to stop (pf::services::service_ctl)
Sep 07 15:26:16 pfcmd(1986) INFO: /usr/local/pf/sbin/pfdhcplistener status (pf::services::service_ctl)

Sep 07 15:26:16 pfcmd(1986) INFO: pfdhcplistener pids eth0.3299 => 2018, eth0.3199 => 2020, eth0 
=> 2022 (pf::services::service_ctl)
Sep 07 15:26:16 pfcmd(1986) INFO: Waiting for pfdhcplistener to stop (pf::services::service_ctl)
Sep 07 15:26:18 pfcmd(1986) INFO: /usr/local/pf/sbin/pfdhcplistener status (pf::services::service_ctl)

Sep 07 15:26:18 pfcmd(1986) INFO: pfdhcplistener pids eth0.3299 => 2024, eth0.3199 => 2026, eth0 
=> 2028 (pf::services::service_ctl)
Sep 07 15:26:18 pfcmd(1986) INFO: Waiting for pfdhcplistener to stop (pf::services::service_ctl)
Sep 07 15:26:20 pfcmd(1986) INFO: /usr/local/pf/sbin/pfdhcplistener status (pf::services::service_ctl)

Sep 07 15:26:20 pfcmd(1986) INFO: pfdhcplistener pids eth0.3299 => 2030, eth0.3199 => 2032, eth0 
=> 2034 (pf::services::service_ctl)
Sep 07 15:26:20 pfcmd(1986) INFO: Waiting for pfdhcplistener to stop (pf::services::service_ctl)
Sep 07 15:26:22 pfcmd(1986) INFO: /usr/local/pf/sbin/pfdhcplistener status (pf::services::service_ctl)

Sep 07 15:26:22 pfcmd(1986) INFO: pfdhcplistener pids eth0.3299 => 2036, eth0.3199 => 2038, eth0 
=> 2040 (pf::services::service_ctl)
Sep 07 15:26:22 pfcmd(1986) INFO: Waiting for pfdhcplistener to stop (pf::services::service_ctl)
Sep 07 15:26:24 pfcmd(1986) INFO: /usr/local/pf/sbin/pfdhcplistener status (pf::services::service_ctl)

Sep 07 15:26:24 pfcmd(1986) INFO: pfdhcplistener pids eth0.3299 => 2042, eth0.3199 => 2044, eth0 
=> 2046 (pf::services::service_ctl)
Sep 07 15:26:24 pfcmd(1986) INFO: Waiting for pfdhcplistener to stop (pf::services::service_ctl)
Sep 07 15:26:26 pfcmd(1986) INFO: /usr/sbin/named status (pf::services::service_ctl)
Sep 07 15:26:26 pfcmd(1986) INFO: pidof -x named returned 0 (pf::services::service_ctl)
Sep 07 15:26:26 pfcmd(1986) INFO: /usr/sbin/dhcpd status (pf::services::service_ctl)
Sep 07 15:26:26 pfcmd(1986) INFO: pidof -x dhcpd returned 0 (pf::services::service_ctl)
Sep 07 15:26:26 pfcmd(1986) INFO: /usr/sbin/snort status (pf::services::service_ctl)
Sep 07 15:26:26 pfcmd(1986) INFO: pidof -x snort returned 0 (pf::services::service_ctl)
Sep 07 15:26:26 pfcmd(1986) INFO: /usr/bin/suricata status (pf::services::service_ctl)
Sep 07 15:26:26 pfcmd(1986) INFO: pidof -x suricata returned 0 (pf::services::service_ctl)
Sep 07 15:26:26 pfcmd(1986) INFO: /usr/sbin/freeradius status (pf::services::service_ctl)
Sep 07 15:26:26 pfcmd(1986) INFO: pidof -x freeradius returned 1642 (pf::services::service_ctl)
Sep 07 15:26:26 pfcmd(1986) INFO: /usr/sbin/apache2 status (pf::services::service_ctl)
Sep 07 15:26:26 pfcmd(1986) INFO: pidof -x apache2 returned 1703 1702 1701 1700 1699 1686 (pf::services::service_ctl)

Sep 07 15:26:26 pfcmd(1986) INFO: /usr/sbin/snmptrapd status (pf::services::service_ctl)
Sep 07 15:26:26 pfcmd(1986) INFO: pidof -x snmptrapd returned 1688 (pf::services::service_ctl)
Sep 07 15:26:26 pfcmd(1986) INFO: /usr/local/pf/sbin/pfdetect status (pf::services::service_ctl)
Sep 07 15:26:26 pfcmd(1986) INFO: pidof -x pfdetect returned 0 (pf::services::service_ctl)
Sep 07 15:26:26 pfcmd(1986) INFO: /usr/local/pf/sbin/pfredirect status (pf::services::service_ctl)
Sep 07 15:26:26 pfcmd(1986) INFO: pidof -x pfredirect returned 0 (pf::services::service_ctl)
Sep 07 15:26:26 pfcmd(1986) INFO: /usr/local/pf/sbin/pfsetvlan status (pf::services::service_ctl)
Sep 07 15:26:26 pfcmd(1986) INFO: pidof -x pfsetvlan returned 1696 (pf::services::service_ctl)
Sep 07 15:26:26 pfcmd(1986) INFO: /usr/local/pf/sbin/pfdhcplistener status (pf::services::service_ctl)

Sep 07 15:26:26 pfcmd(1986) INFO: pfdhcplistener pids eth0.3299 => 2058, eth0.3199 => 2060, eth0 
=> 2062 (pf::services::service_ctl)
Sep 07 15:26:26 pfcmd(1986) INFO: /usr/local/pf/sbin/pfmon status (pf::services::service_ctl)
Sep 07 15:26:26 pfcmd(1986) INFO: pidof -x pfmon returned 1695 (pf::services::service_ctl)
Sep 07 15:26:33 pfcmd(2066) INFO: Executing pfcmd service pfdhcplistener status (main::service)
Sep 07 15:26:33 pfcmd(2066) INFO: /usr/local/pf/sbin/pfdhcplistener status (pf::services::service_ctl)

Sep 07 15:26:33 pfcmd(2066) INFO: pfdhcplistener pids eth0.3299 => 2067, eth0.3199 => 2069, eth0 
=> 2071 (pf::services::service_ctl)

The PIDs for pfdhcplistener seem to increase each time the status command is executed, but there's no 
evidence of the processes actually being started. If I execute pfdhcplistener manually, it starts normally 
and I get DHCP fingerprint information in the log. Another server running PacketFence 3.5.0 and an almost 
identical configuration does not exhibit this problem.

Hoping somebody else can reproduce this problem or suggest a fix.

Regards,
Steps To Reproduce
Additional Information
TagsNo tags attached.
Relationships
Attached Filespatch pfdhcplistener-process-mgmt-3.5.1-regression.patch (1,179) 2012-09-11 14:43
https://www.packetfence.org/bugs/file_download.php?file_id=162&type=bug
Issue History
Date ModifiedUsernameFieldChange
2012-09-11 10:18obilodeauNew Issue
2012-09-11 10:18obilodeauStatusnew => assigned
2012-09-11 10:18obilodeauAssigned To => obilodeau
2012-09-11 11:58obilodeauNote Added: 0003049
2012-09-11 12:16obilodeauNote Added: 0003050
2012-09-11 12:17obilodeauNote Edited: 0003050
2012-09-11 13:45obilodeauNote Added: 0003051
2012-09-11 13:55obilodeauNote Added: 0003052
2012-09-11 13:55obilodeauSummarypfdhcplistener management regression => pfdhcplistener management regressions
2012-09-11 13:55obilodeauNote Added: 0003053
2012-09-11 14:40obilodeauFile Added: pfdhcplistener-process-mgmt-3.5.1-regression.patch
2012-09-11 14:42obilodeaugit revision => 4e7e8a8123
2012-09-11 14:42obilodeauNote Added: 0003054
2012-09-11 14:42obilodeauStatusassigned => resolved
2012-09-11 14:42obilodeauFixed in Version => +1
2012-09-11 14:42obilodeauResolutionopen => fixed
2012-09-11 14:43obilodeauFile Deleted: pfdhcplistener-process-mgmt-3.5.1-regression.patch
2012-09-11 14:43obilodeauFile Added: pfdhcplistener-process-mgmt-3.5.1-regression.patch
2012-10-19 10:15fgaudreaultAssigned Toobilodeau =>
2012-10-19 10:15fgaudreaultFixed in Version+1 => devel
2012-10-19 10:15fgaudreaultTarget Version+1 => 3.6.0

Notes
(0003049)
obilodeau   
2012-09-11 11:58   
We've got similar reports of problems w/ CentOS 6 that I'm investigating right now.
(0003050)
obilodeau   
2012-09-11 12:16   
(edited on: 2012-09-11 12:17)
Unable to reproduce on CentOS 6. Asked my colleague more information.

Investigating on debian live cd now.
(0003051)
obilodeau   
2012-09-11 13:45   
Debian:

I added the -l flag to the pgrep call to see what was matching as a false pfdhcplistener and here it is:

# bin/pfcmd service pfdhcplistener status
service|shouldBeStarted|pid
pfdhcplistener|1|1391 sh -c pgrep -l -f "pfdhcplistener: listening on eth0.100" 1393 sh -c 
pgrep -l -f "pfdhcplistener: listening on eth0"


So it's pgrep catching itself and since it's a valid pid, no need to start another pfdhcplistener or complain further.
(0003052)
obilodeau   
2012-09-11 13:55   
CentOS:

With a setup with eth0, eth0.<vlan>, etc. I was able to reproduce. This is caused by pgrep not being strict about the pattern.

After all looking for a process called 'pfdhcplistener: listening on eth0' will match 'pfdhcplistener: listening on eth0.100'.
(0003053)
obilodeau   
2012-09-11 13:55   
The fix in both cases is to be strict about the match by adding -x to the pgrep call. A patch is on it's way.
(0003054)
obilodeau   
2012-09-11 14:42   
Attached patch to ticket. Everyone affected should apply it with:

cd /usr/local/pf/
patch -p1 < <patchfile>


Fix committed in stable. Will be part of our next release.