PacketFence
Bug Tracking System
Main | My View | View Issues | Change Log | Roadmap
  

View Issue Details [ Jump to Notes ] [ Issue History ] [ Print ]
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 
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,
TagsNo tags attached.
fixed in git revision4e7e8a8123
fixed in mtn revision
Attached Filespatch file icon pfdhcplistener-process-mgmt-3.5.1-regression.patch [^] (1,179 bytes) 2012-09-11 14:43 [Show Content]

- Relationships

-  Notes
(0003049)
obilodeau (reporter)
2012-09-11 11:58

 We've got similar reports of problems w/ CentOS 6 that I'm investigating right now.
(0003050)
obilodeau (reporter)
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 (reporter)
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 (reporter)
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 (reporter)
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 (reporter)
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.

- Issue History
Date Modified Username Field Change
2012-09-11 10:18 obilodeau New Issue
2012-09-11 10:18 obilodeau Status new => assigned
2012-09-11 10:18 obilodeau Assigned To => obilodeau
2012-09-11 11:58 obilodeau Note Added: 0003049
2012-09-11 12:16 obilodeau Note Added: 0003050
2012-09-11 12:17 obilodeau Note Edited: 0003050
2012-09-11 13:45 obilodeau Note Added: 0003051
2012-09-11 13:55 obilodeau Note Added: 0003052
2012-09-11 13:55 obilodeau Summary pfdhcplistener management regression => pfdhcplistener management regressions
2012-09-11 13:55 obilodeau Note Added: 0003053
2012-09-11 14:40 obilodeau File Added: pfdhcplistener-process-mgmt-3.5.1-regression.patch
2012-09-11 14:42 obilodeau git revision => 4e7e8a8123
2012-09-11 14:42 obilodeau Note Added: 0003054
2012-09-11 14:42 obilodeau Status assigned => resolved
2012-09-11 14:42 obilodeau Fixed in Version => +1
2012-09-11 14:42 obilodeau Resolution open => fixed
2012-09-11 14:43 obilodeau File Deleted: pfdhcplistener-process-mgmt-3.5.1-regression.patch
2012-09-11 14:43 obilodeau File Added: pfdhcplistener-process-mgmt-3.5.1-regression.patch
2012-10-19 10:15 fgaudreault Assigned To obilodeau =>
2012-10-19 10:15 fgaudreault Fixed in Version +1 => devel
2012-10-19 10:15 fgaudreault Target Version +1 => 3.6.0

Copyright © 2000 - 2012 MantisBT Group
Powered by Mantis Bugtracker