PacketFence - BTS - PacketFence
View Issue Details
IDProjectCategoryView StatusDate SubmittedLast Update
0001195PacketFencecorepublic2011-03-09 09:082011-10-25 09:01
Reporterryacketta 
Assigned Toobilodeau 
PrioritynormalSeveritymajorReproducibilityalways
StatusclosedResolutionfixed 
PlatformOSOS Version
Product Version2.1.0 
Target Version2.2.0Fixed in Version2.2.0 
fixed in git revision
fixed in mtn revision9383cc837db8b1949158d40cafad4c0dcbd26f2e
Summary0001195: BayStack 470 48-T VoIP autoreg
DescriptionLooks like PF tries to determine if the connected device is a VoIP
before the devices is added to the PF DB

...
Mar 04 09:34:22 pfsetvlan(5) INFO: creating new
pf::SNMP::Nortel::BayStack470 object (pf::SwitchFactory::instantiate)
Mar 04 09:34:22 pfsetvlan(5) INFO: $VAR1 = {
           'type' => 'Nortel::BayStack470',
           'mode' => 'production',
           'uplink' => '1',
           'voiceVlan' => '5',
           'VoIPEnabled' => 'yes'
         };
  (pf::SwitchFactory::instantiate)
Mar 04 09:34:22 pfsetvlan(5) INFO: secureMacAddrViolation trap received
on <IP> ifIndex 18 for 00:0e:08:d8:96:1a (main::handleTrap)
Mar 04 09:34:22 pfsetvlan(5) INFO: isVoipEnabled = 1
(pf::SNMP::Nortel::isVoIPEnabled)
Mar 04 09:34:22 pfsetvlan(5) INFO: determining DHCP fingerprint info for
00:0e:08:d8:96:1a (pf::SNMP::isPhoneAtIfIndex)
Mar 04 09:34:22 pfsetvlan(5) INFO: isVoipEnabled = 1
(pf::SNMP::Nortel::isVoIPEnabled)
Mar 04 09:34:22 pfsetvlan(5) INFO: isVoipEnabled = 1
(pf::SNMP::Nortel::isVoIPEnabled)
Mar 04 09:34:22 pfsetvlan(5) INFO: node 00:0e:08:d8:96:1a does not yet
exist in PF database. Adding it now (main::node_update_PF)
...
Mar 04 09:25:21 pfdhcplistener(29846) DEBUG: violation not added, no
trigger found for os::3 or violation is disabled
(pf::violation::violation_trigger)
Mar 04 09:25:21 pfdhcplistener(29846) INFO: 00:0e:08:d8:96:1a requested
an IP. DHCP Fingerprint: OS::308 (Sipura VoIP Adaptor). Modifying node
with last_dhcp = 2011-03-04 09:25:21,computername =
SipuraSPA,dhcp_fingerprint = 1,3,42,6,7,15,58,59,44,66 (main::listen_dhcp)
...
Mar 04 09:34:30 pfsetvlan(7) INFO: determining through discovery
protocols if <IP> ifIndex 18 has VoIP phone connected
(pf::SNMP::hasPhoneAtIfIndex)
Mar 04 09:34:30 pfsetvlan(7) INFO: isVoipEnabled = 1
(pf::SNMP::Nortel::isVoIPEnabled)
Mar 04 09:34:30 pfsetvlan(7) INFO: isVoipEnabled = 1
(pf::SNMP::Nortel::isVoIPEnabled)
Mar 04 09:34:30 pfsetvlan(7) INFO: MAC: 00:0e:08:d8:96:1a, PID: 1,
Status: reg. Returned VLAN: 11 (pf::vlan::fetchVlanForNode)
Mar 04 09:34:31 pfsetvlan(7) INFO: setting VLAN at <IP> ifIndex 18 from
102 to 11 (pf::SNMP::setVlan)

Running a watered down node_view_with_fingerprint_sql reveals that this
is a VoIP Phone:

mysql> SELECT node.mac, node.pid, node.voip, node.bypass_vlan,
node.status, IFNULL(os_class.description, ' ') as dhcp_fingerprint
FROM node LEFT JOIN dhcp_fingerprint ON
node.dhcp_fingerprint=dhcp_fingerprint.fingerprint JOIN os_mapping ON
dhcp_fingerprint.os_id=os_mapping.os_type LEFT JOIN os_class
ON os_mapping.os_class=os_class.class_id GROUP BY node.mac
HAVING node.mac='00:0e:08:d8:96:1a';
+-------------------+-----+------+-------------+--------+----------------------+
| mac | pid | voip | bypass_vlan | status |
dhcp_fingerprint |
+-------------------+-----+------+-------------+--------+----------------------+
| 00:0e:08:d8:96:1a | 1 | no | | reg | VoIP
Phones/Adapters |
+-------------------+-----+------+-------------+--------+----------------------+
1 row in set (0.00 sec)

Steps To Reproduce
Additional Informationmodified violations.conf

[1200003]
desc=Auto-registered Device
priority=1
trigger=OS::308
actions=log,autoreg,email
disable=N

switches.conf:
[default]
vlans = 1,5,11,102
normalVlan = 11
registrationVlan = 102
isolationVlan =
macDetectionVlan = 102
guestVlan =
customVlan1 = 5
customVlan2 =
customVlan3 =
customVlan4 =
customVlan5 =
VoIPEnabled = yes
voiceVlan = 5

...

[IP]
type = Nortel::BayStack470
mode = production
uplink = 1
voiceVlan = 5
VoIPEnabled = yes

TagsNo tags attached.
Relationships
Attached Files
Issue History
Date ModifiedUsernameFieldChange
2011-03-09 09:08ryackettaNew Issue
2011-03-09 09:32ryackettaNote Added: 0001906
2011-03-09 09:32ryackettaNote Edited: 0001906
2011-03-14 17:32obilodeauStatusnew => assigned
2011-03-14 17:32obilodeauAssigned To => obilodeau
2011-03-14 17:38obilodeauNote Added: 0001923
2011-03-14 17:38obilodeauStatusassigned => feedback
2011-03-14 17:46obilodeauTarget Version => +1
2011-03-15 08:22ryackettaNote Added: 0001924
2011-03-18 09:33obilodeauRelationship addedduplicate of 0001183
2011-03-18 11:10obilodeauNote Added: 0001950
2011-03-18 11:32ryackettaNote Added: 0001952
2011-03-18 11:38obilodeauRelationship deleted0001183
2011-03-18 11:42obilodeauNote Added: 0001955
2011-03-18 11:51obilodeauNote Added: 0001956
2011-03-18 13:16ryackettaNote Added: 0001960
2011-03-18 14:32obilodeauNote Added: 0001962
2011-03-18 14:34obilodeaumtn revision => 9383cc837db8b1949158d40cafad4c0dcbd26f2e
2011-03-18 14:34obilodeauNote Added: 0001963
2011-03-18 14:34obilodeauStatusfeedback => resolved
2011-03-18 14:34obilodeauFixed in Version => +1
2011-03-18 14:34obilodeauResolutionopen => fixed
2011-05-04 11:32obilodeauFixed in Version+1 => 2.2.0
2011-05-04 11:40obilodeauStatusresolved => closed
2011-10-25 09:01obilodeauTarget Version+1 => 2.2.0

Notes
(0001906)
ryacketta   
2011-03-09 09:32   
A complete log from this morning
Mar 09 09:27:47 pfsetvlan(23) INFO: creating new pf::SNMP::Nortel::BayStack470 object (pf::SwitchFactory::instantiate)
Mar 09 09:27:47 pfsetvlan(23) INFO: $VAR1 = {
          'type' => 'Nortel::BayStack470',
          'mode' => 'production',
          'uplink' => '1',
          'voiceVlan' => '5',
          'VoIPEnabled' => 'yes'
        };
 (pf::SwitchFactory::instantiate)
Mar 09 09:27:47 pfsetvlan(22) INFO: creating new pf::SNMP::Nortel::BayStack470 object (pf::SwitchFactory::instantiate)
Mar 09 09:27:47 pfsetvlan(22) INFO: $VAR1 = {
          'type' => 'Nortel::BayStack470',
          'mode' => 'production',
          'uplink' => '1',
          'voiceVlan' => '5',
          'VoIPEnabled' => 'yes'
        };
 (pf::SwitchFactory::instantiate)
Mar 09 09:27:47 pfsetvlan(23) INFO: creating new pf::SNMP::Nortel::BayStack470 object (pf::SwitchFactory::instantiate)
Mar 09 09:27:47 pfsetvlan(23) INFO: $VAR1 = {
          'type' => 'Nortel::BayStack470',
          'mode' => 'production',
          'uplink' => '1',
          'voiceVlan' => '5',
          'VoIPEnabled' => 'yes'
        };
 (pf::SwitchFactory::instantiate)
Mar 09 09:27:47 pfsetvlan(22) WARN: unable to fetch first board index. Will assume it's 1 (pf::SNMP::Nortel::getFirstBoardIndex)
Mar 09 09:27:47 pfsetvlan(22) INFO: creating new pf::SNMP::Nortel::BayStack470 object (pf::SwitchFactory::instantiate)
Mar 09 09:27:47 pfsetvlan(22) INFO: $VAR1 = {
          'type' => 'Nortel::BayStack470',
          'mode' => 'production',
          'uplink' => '1',
          'voiceVlan' => '5',
          'VoIPEnabled' => 'yes'
        };
 (pf::SwitchFactory::instantiate)
Mar 09 09:27:47 pfsetvlan(22) WARN: unable to fetch first board index. Will assume it's 1 (pf::SNMP::Nortel::getFirstBoardIndex)
Mar 09 09:27:47 pfsetvlan(3) INFO: nb of items in queue: 2; nb of threads running: 0 (main::startTrapHandlers)
Mar 09 09:27:47 pfsetvlan(3) INFO: creating new pf::SNMP::Nortel::BayStack470 object (pf::SwitchFactory::instantiate)
Mar 09 09:27:47 pfsetvlan(3) INFO: $VAR1 = {
          'type' => 'Nortel::BayStack470',
          'mode' => 'production',
          'uplink' => '1',
          'voiceVlan' => '5',
          'VoIPEnabled' => 'yes'
        };
 (pf::SwitchFactory::instantiate)
Mar 09 09:27:47 pfsetvlan(4) INFO: nb of items in queue: 1; nb of threads running: 1 (main::startTrapHandlers)
Mar 09 09:27:47 pfsetvlan(3) INFO: up trap received on [IP] ifIndex 8 (main::handleTrap)
Mar 09 09:27:47 pfsetvlan(3) WARN: unable to fetch first board index. Will assume it's 1 (pf::SNMP::Nortel::getFirstBoardIndex)
Mar 09 09:27:47 pfsetvlan(3) INFO: security traps are configured on this switch port. Stopping UP trap handling here (main::handleTrap)
Mar 09 09:27:47 pfsetvlan(3) INFO: finished (main::cleanupAfterThread)
Mar 09 09:27:47 pfsetvlan(5) INFO: nb of items in queue: 1; nb of threads running: 0 (main::startTrapHandlers)
Mar 09 09:27:47 pfsetvlan(5) INFO: creating new pf::SNMP::Nortel::BayStack470 object (pf::SwitchFactory::instantiate)
Mar 09 09:27:47 pfsetvlan(5) INFO: $VAR1 = {
          'type' => 'Nortel::BayStack470',
          'mode' => 'production',
          'uplink' => '1',
          'voiceVlan' => '5',
          'VoIPEnabled' => 'yes'
        };
 (pf::SwitchFactory::instantiate)
Mar 09 09:27:47 pfsetvlan(5) INFO: secureMacAddrViolation trap received on [IP] ifIndex 8 for 00:0e:08:d8:96:1a (main::handleTrap)
Mar 09 09:27:47 pfsetvlan(5) INFO: isVoipEnabled = 1 (pf::SNMP::Nortel::isVoIPEnabled)
Mar 09 09:27:47 pfsetvlan(5) INFO: determining DHCP fingerprint info for 00:0e:08:d8:96:1a (pf::SNMP::isPhoneAtIfIndex)
Mar 09 09:27:47 pfsetvlan(5) INFO: $VAR1 = undef;
 (pf::node::node_view_with_fingerprint)
Mar 09 09:27:47 pfsetvlan(5) INFO: isVoipEnabled = 1 (pf::SNMP::Nortel::isVoIPEnabled)
Mar 09 09:27:47 pfsetvlan(5) INFO: isVoipEnabled = 1 (pf::SNMP::Nortel::isVoIPEnabled)
Mar 09 09:27:47 pfsetvlan(5) INFO: node 00:0e:08:d8:96:1a does not yet exist in PF database. Adding it now (main::node_update_PF)
Mar 09 09:27:48 pfsetvlan(5) WARN: unable to fetch first board index. Will assume it's 1 (pf::SNMP::Nortel::getFirstBoardIndex)
Mar 09 09:27:48 pfsetvlan(5) WARN: unable to fetch first board index. Will assume it's 1 (pf::SNMP::Nortel::getFirstBoardIndex)
Mar 09 09:27:48 pfsetvlan(5) INFO: MAC: 00:0e:08:d8:96:1a is of status unreg; belongs into registration VLAN (pf::vlan::getRegistrationVlan)
Mar 09 09:27:48 pfsetvlan(5) INFO: authorizing 00:0e:08:d8:96:1a at new location [IP] ifIndex 8 (main::handleTrap)
Mar 09 09:27:48 pfsetvlan(5) WARN: unable to fetch first board index. Will assume it's 1 (pf::SNMP::Nortel::getFirstBoardIndex)
Mar 09 09:27:49 pfsetvlan(25) INFO: creating new pf::SNMP::Nortel::BayStack470 object (pf::SwitchFactory::instantiate)
Mar 09 09:27:49 pfsetvlan(25) INFO: $VAR1 = {
          'type' => 'Nortel::BayStack470',
          'mode' => 'production',
          'uplink' => '1',
          'voiceVlan' => '5',
          'VoIPEnabled' => 'yes'
        };
 (pf::SwitchFactory::instantiate)
Mar 09 09:27:49 pfsetvlan(25) INFO: creating new pf::SNMP::Nortel::BayStack470 object (pf::SwitchFactory::instantiate)
Mar 09 09:27:49 pfsetvlan(25) INFO: $VAR1 = {
          'type' => 'Nortel::BayStack470',
          'mode' => 'production',
          'uplink' => '1',
          'voiceVlan' => '5',
          'VoIPEnabled' => 'yes'
        };
 (pf::SwitchFactory::instantiate)
Mar 09 09:27:49 pfsetvlan(6) INFO: nb of items in queue: 1; nb of threads running: 1 (main::startTrapHandlers)
Mar 09 09:27:52 pfsetvlan(5) INFO: setting VLAN at [IP] ifIndex 8 from 11 to 102 (pf::SNMP::setVlan)
Mar 09 09:27:52 pfsetvlan(5) INFO: finished (main::cleanupAfterThread)
Mar 09 09:27:52 pfsetvlan(7) INFO: nb of items in queue: 1; nb of threads running: 0 (main::startTrapHandlers)
Mar 09 09:27:52 pfsetvlan(7) INFO: creating new pf::SNMP::Nortel::BayStack470 object (pf::SwitchFactory::instantiate)
Mar 09 09:27:52 pfsetvlan(7) INFO: $VAR1 = {
          'type' => 'Nortel::BayStack470',
          'mode' => 'production',
          'uplink' => '1',
          'voiceVlan' => '5',
          'VoIPEnabled' => 'yes'
        };
 (pf::SwitchFactory::instantiate)
Mar 09 09:27:52 pfsetvlan(7) INFO: down trap received on [IP] ifIndex 8 (main::handleTrap)
Mar 09 09:27:52 pfsetvlan(7) WARN: unable to fetch first board index. Will assume it's 1 (pf::SNMP::Nortel::getFirstBoardIndex)
Mar 09 09:27:52 pfsetvlan(7) INFO: security traps are configured on this switch port. Stopping DOWN trap handling here (main::handleTrap)
Mar 09 09:27:52 pfsetvlan(7) INFO: finished (main::cleanupAfterThread)
Mar 09 09:27:53 pfsetvlan(24) INFO: creating new pf::SNMP::Nortel::BayStack470 object (pf::SwitchFactory::instantiate)
Mar 09 09:27:53 pfsetvlan(24) INFO: $VAR1 = {
          'type' => 'Nortel::BayStack470',
          'mode' => 'production',
          'uplink' => '1',
          'voiceVlan' => '5',
          'VoIPEnabled' => 'yes'
        };
 (pf::SwitchFactory::instantiate)
Mar 09 09:27:53 pfsetvlan(24) INFO: ignoring unknown trap: 2011-03-09|14:27:51|UDP: [[IP]]:1024|[IP]|BEGIN TYPE 6 END TYPE BEGIN SUBTYPE .1 END SUBTYPE BEGIN VARIABLEBINDINGS END VARIABLEBINDINGS (main::parseTrap)
Mar 09 09:27:55 pfsetvlan(21) INFO: creating new pf::SNMP::Nortel::BayStack470 object (pf::SwitchFactory::instantiate)
Mar 09 09:27:55 pfsetvlan(21) INFO: $VAR1 = {
          'type' => 'Nortel::BayStack470',
          'mode' => 'production',
          'uplink' => '1',
          'voiceVlan' => '5',
          'VoIPEnabled' => 'yes'
        };
 (pf::SwitchFactory::instantiate)
Mar 09 09:27:55 pfsetvlan(21) INFO: creating new pf::SNMP::Nortel::BayStack470 object (pf::SwitchFactory::instantiate)
Mar 09 09:27:55 pfsetvlan(21) INFO: $VAR1 = {
          'type' => 'Nortel::BayStack470',
          'mode' => 'production',
          'uplink' => '1',
          'voiceVlan' => '5',
          'VoIPEnabled' => 'yes'
        };
 (pf::SwitchFactory::instantiate)
Mar 09 09:27:55 pfsetvlan(8) INFO: nb of items in queue: 1; nb of threads running: 0 (main::startTrapHandlers)
Mar 09 09:27:55 pfsetvlan(8) INFO: creating new pf::SNMP::Nortel::BayStack470 object (pf::SwitchFactory::instantiate)
Mar 09 09:27:55 pfsetvlan(8) INFO: $VAR1 = {
          'type' => 'Nortel::BayStack470',
          'mode' => 'production',
          'uplink' => '1',
          'voiceVlan' => '5',
          'VoIPEnabled' => 'yes'
        };
 (pf::SwitchFactory::instantiate)
Mar 09 09:27:55 pfsetvlan(8) INFO: up trap received on [IP] ifIndex 8 (main::handleTrap)
Mar 09 09:27:55 pfsetvlan(8) WARN: unable to fetch first board index. Will assume it's 1 (pf::SNMP::Nortel::getFirstBoardIndex)
Mar 09 09:27:55 pfsetvlan(8) INFO: security traps are configured on this switch port. Stopping UP trap handling here (main::handleTrap)
Mar 09 09:27:55 pfsetvlan(8) INFO: finished (main::cleanupAfterThread)
Mar 09 09:27:59 pfdhcplistener(17278) INFO: calling '/usr/local/pf/bin/pfcmd violation add vid=1200003,mac=00:0e:08:d8:96:1a' (trigger os::308) (pf::violation::violation_trigger)
Mar 09 09:28:00 pfcmd(0) INFO: pfcmd calling violation_add for 00:0e:08:d8:96:1a (main::command_param)
Mar 09 09:28:00 pfcmd(0) INFO: grace expired on violation 1200003 for node 00:0e:08:d8:96:1a (pf::violation::violation_add)
Mar 09 09:28:00 pfcmd(0) INFO: violation 1200003 added for 00:0e:08:d8:96:1a (pf::violation::violation_add)
Mar 09 09:28:00 pfcmd(0) INFO: executing action 'autoreg' on class 1200003 (pf::action::action_execute)
Mar 09 09:28:00 pfcmd(0) INFO: executing action 'email' on class 1200003 (pf::action::action_execute)
Mar 09 09:28:01 pfcmd(0) INFO: email regarding 'PF Alert: Auto-registered Device detection on 00:0e:08:d8:96:1a' sent to yacketrj@potsdam.edu (pf::util::pfmailer)
Mar 09 09:28:01 pfcmd(0) INFO: executing action 'log' on class 1200003 (pf::action::action_execute)
Mar 09 09:28:01 pfcmd(0) WARN: unable to resolve 00:0e:08:d8:96:1a to ip (pf::iplog::mac2ip)
Mar 09 09:28:01 pfcmd(0) INFO: /usr/local/pf/logs/violation.log 2011-03-09 09:28:01: Auto-registered Device (1200003) detected on node 00:0e:08:d8:96:1a (0) (pf::action::action_log)
Mar 09 09:28:01 pfcmd(0) INFO: this is a non-trap violation, closing violation entry now (pf::action::action_execute)
Mar 09 09:28:01 pfcmd(0) INFO: violation 1200003 force-closed for 00:0e:08:d8:96:1a (pf::violation::violation_force_close)
Mar 09 09:28:01 pfcmd(0) INFO: VLAN isolation is enabled and violation_add is part of adjustswitchportvlanreasons (main::vlan_reevaluation)
Mar 09 09:28:01 pfcmd(0) INFO: 00:0e:08:d8:96:1a is currentlog connected at [IP] ifIndex 8 in VLAN 102 (main::vlan_reevaluation)
Mar 09 09:28:01 pfcmd(0) INFO: creating new pf::SNMP::Nortel::BayStack470 object (pf::SwitchFactory::instantiate)
Mar 09 09:28:01 pfcmd(0) INFO: $VAR1 = {
          'type' => 'Nortel::BayStack470',
          'mode' => 'production',
          'uplink' => '1',
          'voiceVlan' => '5',
          'VoIPEnabled' => 'yes'
        };
 (pf::SwitchFactory::instantiate)
Mar 09 09:28:01 pfcmd(0) INFO: MAC: 00:0e:08:d8:96:1a, PID: 1, Status: reg. Returned VLAN: 11 (pf::vlan::fetchVlanForNode)
Mar 09 09:28:01 pfcmd(0) INFO: calling /usr/local/pf/bin/flip.pl for node 00:0e:08:d8:96:1a (current VLAN = 102 but should be in VLAN 11) (main::vlan_reevaluation)
Mar 09 09:28:01 flip.pl(0) INFO: flip.pl called with 00:0e:08:d8:96:1a (main::)
Mar 09 09:28:01 flip.pl(0) INFO: switch port for 00:0e:08:d8:96:1a is [IP] ifIndex 8 connection type: Wired SNMP (main::)
Mar 09 09:28:01 flip.pl(0) INFO: creating new pf::SNMP::PacketFence object (pf::SwitchFactory::instantiate)
Mar 09 09:28:01 flip.pl(0) INFO: $VAR1 = {
          'type' => 'PacketFence',
          'mode' => 'production',
          'uplink' => 'dynamic'
        };
 (pf::SwitchFactory::instantiate)
Mar 09 09:28:01 pfdhcplistener(17278) INFO: 00:0e:08:d8:96:1a requested an IP. DHCP Fingerprint: OS::308 (Sipura VoIP Adaptor). Modifying node with last_dhcp = 2011-03-09 09:28:01,computername = SipuraSPA,dhcp_fingerprint = 1,3,42,6,7,15,58,59,44,66 (main::listen_dhcp)
Mar 09 09:28:01 pfdhcplistener(17278) INFO: DHCPOFFER from 10.102.1.254 (52:54:00:cf:9a:c2) to host 00:0e:08:d8:96:1a (10.102.1.199) (main::listen_dhcp)
Mar 09 09:28:01 pfdhcplistener(17278) INFO: DHCPREQUEST from 00:0e:08:d8:96:1a (10.102.1.199) (main::listen_dhcp)
Mar 09 09:28:01 pfdhcplistener(17278) INFO: resolved 10.102.1.199 to mac (00:0e:08:d8:96:1a) in ARP table (pf::iplog::ip2macinarp)
Mar 09 09:28:02 pfdhcplistener(17278) INFO: 118 grace remaining on violation 1200003 (trigger os::308) for node 00:0e:08:d8:96:1a. Not adding violation. (pf::violation::violation_trigger)
Mar 09 09:28:02 pfdhcplistener(17278) INFO: 00:0e:08:d8:96:1a requested an IP. DHCP Fingerprint: OS::308 (Sipura VoIP Adaptor). Modifying node with last_dhcp = 2011-03-09 09:28:02,computername = SipuraSPA,dhcp_fingerprint = 1,3,42,6,7,15,58,59,44,66 (main::listen_dhcp)
Mar 09 09:28:02 pfdhcplistener(17278) INFO: DHCPACK from 10.102.1.254 (52:54:00:cf:9a:c2) to host 00:0e:08:d8:96:1a (10.102.1.199) (main::listen_dhcp)
Mar 09 09:28:03 pfsetvlan(22) INFO: local (127.0.0.1) trap for switch [IP] (main::parseTrap)
Mar 09 09:28:03 pfsetvlan(22) INFO: creating new pf::SNMP::Nortel::BayStack470 object (pf::SwitchFactory::instantiate)
Mar 09 09:28:03 pfsetvlan(22) INFO: $VAR1 = {
          'type' => 'Nortel::BayStack470',
          'mode' => 'production',
          'uplink' => '1',
          'voiceVlan' => '5',
          'VoIPEnabled' => 'yes'
        };
 (pf::SwitchFactory::instantiate)
Mar 09 09:28:03 pfsetvlan(22) INFO: creating new pf::SNMP::Nortel::BayStack470 object (pf::SwitchFactory::instantiate)
Mar 09 09:28:03 pfsetvlan(22) INFO: $VAR1 = {
          'type' => 'Nortel::BayStack470',
          'mode' => 'production',
          'uplink' => '1',
          'voiceVlan' => '5',
          'VoIPEnabled' => 'yes'
        };
 (pf::SwitchFactory::instantiate)
Mar 09 09:28:03 pfsetvlan(10) INFO: nb of items in queue: 1; nb of threads running: 0 (main::startTrapHandlers)
Mar 09 09:28:03 pfsetvlan(10) INFO: creating new pf::SNMP::Nortel::BayStack470 object (pf::SwitchFactory::instantiate)
Mar 09 09:28:03 pfsetvlan(10) INFO: $VAR1 = {
          'type' => 'Nortel::BayStack470',
          'mode' => 'production',
          'uplink' => '1',
          'voiceVlan' => '5',
          'VoIPEnabled' => 'yes'
        };
 (pf::SwitchFactory::instantiate)
Mar 09 09:28:03 pfsetvlan(10) INFO: reAssignVlan trap received on [IP] ifIndex 8 (main::handleTrap)
Mar 09 09:28:03 pfsetvlan(10) WARN: unable to fetch first board index. Will assume it's 1 (pf::SNMP::Nortel::getFirstBoardIndex)
Mar 09 09:28:03 pfsetvlan(10) INFO: security traps are configured on [IP] ifIndex 8. Re-assigning VLAN for 00:0e:08:d8:96:1a (main::handleTrap)
Mar 09 09:28:03 pfsetvlan(10) INFO: isVoipEnabled = 1 (pf::SNMP::Nortel::isVoIPEnabled)
Mar 09 09:28:04 pfsetvlan(10) WARN: couldn't get MAC at ifIndex 8. This is a problem. (pf::SNMP::_getMacAtIfIndex)
Mar 09 09:28:04 pfsetvlan(10) INFO: determining through discovery protocols if [IP] ifIndex 8 has VoIP phone connected (pf::SNMP::hasPhoneAtIfIndex)
Mar 09 09:28:04 pfsetvlan(10) INFO: isVoipEnabled = 1 (pf::SNMP::Nortel::isVoIPEnabled)
Mar 09 09:28:04 pfsetvlan(10) INFO: isVoipEnabled = 1 (pf::SNMP::Nortel::isVoIPEnabled)
Mar 09 09:28:04 pfsetvlan(10) INFO: MAC: 00:0e:08:d8:96:1a, PID: 1, Status: reg. Returned VLAN: 11 (pf::vlan::fetchVlanForNode)
Mar 09 09:28:04 pfsetvlan(10) INFO: setting VLAN at [IP] ifIndex 8 from 102 to 11 (pf::SNMP::setVlan)
Mar 09 09:28:05 pfsetvlan(10) INFO: no VoIP phone is currently connected at [IP] ifIndex 8. Flipping port admin status (main::handleTrap)
(0001923)
obilodeau   
2011-03-14 17:38   
I fear that the issue is more important than only VoIP support. Can you do the following snmpwalk on the switch:

snmpwalk -v <version> -c <community> <switch-ip> 1.3.6.1.4.1.45.1.6.5.3.10.1.1

Thanks
(0001924)
ryacketta   
2011-03-15 08:22   
snmpwalk -v 2c -c RO IP 1.3.6.1.4.1.45.1.6.5.3.10.1.1
SNMPv2-SMI::enterprises.45.1.6.5.3.10.1.1 = No Such Instance currently exists at this OID
(0001950)
obilodeau   
2011-03-18 11:10   
With the fixed module provided in 0001183. Once you'll have confirmed that port-security works, can you try to reproduce your VoIP issues please?

Thanks
(0001952)
ryacketta   
2011-03-18 11:32   
still seen as a non VoIP device, complete log when i connect the VoIP device:

Mar 18 11:27:31 pfsetvlan(7) INFO: nb of items in queue: 1; nb of threads running: 0 (main::startTrapHandlers)
Mar 18 11:27:31 pfsetvlan(7) INFO: up trap received on 137.143.212.20 ifIndex 10 (main::handleTrap)
Mar 18 11:27:31 pfsetvlan(7) INFO: security traps are configured on this switch port. Stopping UP trap handling here (main::handleTrap)
Mar 18 11:27:31 pfsetvlan(7) INFO: finished (main::cleanupAfterThread)
Mar 18 11:27:33 pfsetvlan(9) INFO: nb of items in queue: 1; nb of threads running: 0 (main::startTrapHandlers)
Mar 18 11:27:33 pfsetvlan(9) INFO: secureMacAddrViolation trap received on 137.143.212.20 ifIndex 10 for 00:0e:08:d8:96:1a (main::handleTrap)
Mar 18 11:27:33 pfsetvlan(9) INFO: node 00:0e:08:d8:96:1a does not yet exist in PF database. Adding it now (main::node_update_PF)
Mar 18 11:27:34 pfsetvlan(9) INFO: MAC: 00:0e:08:d8:96:1a is of status unreg; belongs into registration VLAN (pf::vlan::getRegistrationVlan)
Mar 18 11:27:34 pfsetvlan(9) INFO: authorizing 00:0e:08:d8:96:1a at new location 137.143.212.20 ifIndex 10 (main::handleTrap)
Mar 18 11:27:34 pfsetvlan(9) INFO: setting VLAN at 137.143.212.20 ifIndex 10 from 1 to 102 (pf::SNMP::setVlan)
Mar 18 11:27:35 pfsetvlan(9) INFO: finished (main::cleanupAfterThread)
Mar 18 11:27:40 pfdhcplistener(5902) INFO: calling '/usr/local/pf/bin/pfcmd violation add vid=1200003,mac=00:0e:08:d8:96:1a' (trigger os::308) (pf::violation::violation_trigger)
Mar 18 11:27:41 pfcmd(0) INFO: pfcmd calling violation_add for 00:0e:08:d8:96:1a (main::command_param)
Mar 18 11:27:41 pfcmd(0) INFO: grace expired on violation 1200003 for node 00:0e:08:d8:96:1a (pf::violation::violation_add)
Mar 18 11:27:41 pfcmd(0) INFO: violation 1200003 added for 00:0e:08:d8:96:1a (pf::violation::violation_add)
Mar 18 11:27:41 pfcmd(0) INFO: executing action 'autoreg' on class 1200003 (pf::action::action_execute)
Mar 18 11:27:41 pfcmd(0) INFO: executing action 'email' on class 1200003 (pf::action::action_execute)
Mar 18 11:27:42 pfcmd(0) INFO: email regarding 'PF Alert: Auto-registered Device detection on 00:0e:08:d8:96:1a' sent to yacketrj@potsdam.edu (pf::util::pfmailer)
Mar 18 11:27:42 pfcmd(0) INFO: executing action 'log' on class 1200003 (pf::action::action_execute)
Mar 18 11:27:42 pfcmd(0) WARN: unable to resolve 00:0e:08:d8:96:1a to ip (pf::iplog::mac2ip)
Mar 18 11:27:42 pfcmd(0) INFO: /usr/local/pf/logs/violation.log 2011-03-18 11:27:42: Auto-registered Device (1200003) detected on node 00:0e:08:d8:96:1a (0) (pf::action::action_log)
Mar 18 11:27:42 pfcmd(0) INFO: this is a non-trap violation, closing violation entry now (pf::action::action_execute)
Mar 18 11:27:42 pfcmd(0) INFO: violation 1200003 force-closed for 00:0e:08:d8:96:1a (pf::violation::violation_force_close)
Mar 18 11:27:42 pfcmd(0) INFO: VLAN isolation is enabled and violation_add is part of adjustswitchportvlanreasons (main::vlan_reevaluation)
Mar 18 11:27:42 pfcmd(0) INFO: 00:0e:08:d8:96:1a is currentlog connected at 137.143.212.20 ifIndex 10 in VLAN 102 (main::vlan_reevaluation)
Mar 18 11:27:42 pfcmd(0) INFO: MAC: 00:0e:08:d8:96:1a, PID: 1, Status: reg. Returned VLAN: 11 (pf::vlan::fetchVlanForNode)
Mar 18 11:27:42 pfcmd(0) INFO: calling /usr/local/pf/bin/flip.pl for node 00:0e:08:d8:96:1a (current VLAN = 102 but should be in VLAN 11) (main::vlan_reevaluation)
Mar 18 11:27:42 flip.pl(0) INFO: flip.pl called with 00:0e:08:d8:96:1a (main::)
Mar 18 11:27:42 flip.pl(0) INFO: switch port for 00:0e:08:d8:96:1a is 137.143.212.20 ifIndex 10 connection type: Wired SNMP (main::)
Mar 18 11:27:43 pfdhcplistener(5902) INFO: 00:0e:08:d8:96:1a requested an IP. DHCP Fingerprint: OS::308 (Sipura VoIP Adaptor). Modifying node with last_dhcp = 2011-03-18 11:27:43,computername = SipuraSPA,dhcp_fingerprint = 1,3,42,6,7,15,58,59,44,66 (main::listen_dhcp)
Mar 18 11:27:43 pfdhcplistener(5902) INFO: DHCPOFFER from 10.102.1.254 (52:54:00:cf:9a:c2) to host 00:0e:08:d8:96:1a (10.102.1.199) (main::listen_dhcp)
Mar 18 11:27:43 pfdhcplistener(5902) INFO: DHCPREQUEST from 00:0e:08:d8:96:1a (10.102.1.199) (main::listen_dhcp)
Mar 18 11:27:43 pfdhcplistener(5902) INFO: resolved 10.102.1.199 to mac (00:0e:08:d8:96:1a) in ARP table (pf::iplog::ip2macinarp)
Mar 18 11:27:43 pfdhcplistener(5902) INFO: 117 grace remaining on violation 1200003 (trigger os::308) for node 00:0e:08:d8:96:1a. Not adding violation. (pf::violation::violation_trigger)
Mar 18 11:27:43 pfdhcplistener(5902) INFO: 00:0e:08:d8:96:1a requested an IP. DHCP Fingerprint: OS::308 (Sipura VoIP Adaptor). Modifying node with last_dhcp = 2011-03-18 11:27:43,computername = SipuraSPA,dhcp_fingerprint = 1,3,42,6,7,15,58,59,44,66 (main::listen_dhcp)
Mar 18 11:27:43 pfdhcplistener(5902) INFO: DHCPACK from 10.102.1.254 (52:54:00:cf:9a:c2) to host 00:0e:08:d8:96:1a (10.102.1.199) (main::listen_dhcp)
Mar 18 11:27:45 pfsetvlan(21) INFO: local (127.0.0.1) trap for switch 137.143.212.20 (main::parseTrap)
Mar 18 11:27:45 pfsetvlan(11) INFO: nb of items in queue: 1; nb of threads running: 0 (main::startTrapHandlers)
Mar 18 11:27:45 pfsetvlan(11) INFO: reAssignVlan trap received on 137.143.212.20 ifIndex 10 (main::handleTrap)
Mar 18 11:27:45 pfsetvlan(11) INFO: security traps are configured on 137.143.212.20 ifIndex 10. Re-assigning VLAN for 00:0e:08:d8:96:1a (main::handleTrap)
Mar 18 11:27:46 pfsetvlan(11) WARN: couldn't get MAC at ifIndex 10. This is a problem. (pf::SNMP::_getMacAtIfIndex)
Mar 18 11:27:46 pfsetvlan(11) INFO: determining through discovery protocols if 137.143.212.20 ifIndex 10 has VoIP phone connected (pf::SNMP::hasPhoneAtIfIndex)
Mar 18 11:27:46 pfsetvlan(11) INFO: MAC: 00:0e:08:d8:96:1a, PID: 1, Status: reg. Returned VLAN: 11 (pf::vlan::fetchVlanForNode)
Mar 18 11:27:46 pfsetvlan(11) INFO: setting VLAN at 137.143.212.20 ifIndex 10 from 102 to 11 (pf::SNMP::setVlan)
Mar 18 11:27:47 pfsetvlan(11) INFO: no VoIP phone is currently connected at 137.143.212.20 ifIndex 10. Flipping port admin status (main::handleTrap)
(0001955)
obilodeau   
2011-03-18 11:42   
The first time a phone comes up (when it has no node entry) it will always be treated like a PC. Then it'll do DHCP in the registration VLAN and then we will pick up the fact that it's a phone.

So, now, the next time it'll be plugged in, it should be treated as a phone.
(0001956)
obilodeau   
2011-03-18 11:51   
oh and PacketFence won't add an allowed tagged voice vlan. Your port should already by pre-configured to allow your tagged voice VLAN. All PacketFence does is managed the untagged VLAN and the security MAC address authorizations.
(0001960)
ryacketta   
2011-03-18 13:16   
Seems to be an issue somewhere, Here is the log after a re-connection:

Mar 18 13:12:28 pfsetvlan(3) INFO: nb of items in queue: 1; nb of threads running: 0 (main::startTrapHandlers)
Mar 18 13:12:28 pfsetvlan(3) INFO: up trap received on 137.143.212.20 ifIndex 10 (main::handleTrap)
Mar 18 13:12:28 pfsetvlan(3) INFO: security traps are configured on this switch port. Stopping UP trap handling here (main::handleTrap)
Mar 18 13:12:28 pfsetvlan(3) INFO: finished (main::cleanupAfterThread)

The switch still has port 10 configured for our DATA vlan (11), which was set during the first connection / autoreg attempt
(0001962)
obilodeau   
2011-03-18 14:32   
PacketFence only authorizes VoIP MAC but doesn't perform VLAN changes since they work using tagged VLAN. That's a design decision taken a long time ago probably because the tagged VLAN configuration by SNMP is not standard and very fragmented.

That said, for your environment your port configuration should allow your voice vlan tagged by default. Then whenever you plug an IP Phone, PacketFence will authorize it's MAC and your phone will communicate using its preconfigured voice vlan tag.
(0001963)
obilodeau   
2011-03-18 14:34   
autoreg works as it should. Was probably broken because of 0001183 but is now fixed.

For VoIP configuration question, we should probably go back to the mailing list.

Thanks!