We recently upgraded to Packetfence 8.1. The upgrade went smoothly
except for our VOIP phones. They were returning a vlan of 1501 under
Packetfence 8.01 (as configured as voice role in the switch), but now
return a vlan 1 which is the management vlan (which seems to ignore
the switch role configuration).
Below is the radius debug.
(308) Wed Jul 25 09:03:44 2018: Debug: Received Access-Request Id 142
from 10.10.0.38:1645 to 10.0.1.44:1812 length 261
(308) Wed Jul 25 09:03:44 2018: Debug: User-Name = "0004f2963df1"
(308) Wed Jul 25 09:03:44 2018: Debug: User-Password = "0004f2963df1"
(308) Wed Jul 25 09:03:44 2018: Debug: Service-Type = Call-Check
(308) Wed Jul 25 09:03:44 2018: Debug: Cisco-AVPair =
"service-type=Call Check"
(308) Wed Jul 25 09:03:44 2018: Debug: Framed-MTU = 1500
(308) Wed Jul 25 09:03:44 2018: Debug: Called-Station-Id =
"50-08-AC-51-83-97"
(308) Wed Jul 25 09:03:44 2018: Debug: Calling-Station-Id =
"00-04-F2-96-3D-F1"
(308) Wed Jul 25 09:03:44 2018: Debug: Message-Authenticator =
0x33daf836866565e5329d562bac5b1eb8
(308) Wed Jul 25 09:03:44 2018: Debug: Cisco-AVPair =
"audit-session-id=0A0A0026000002D45C0C7682"
(308) Wed Jul 25 09:03:44 2018: Debug: Cisco-AVPair = "method=mab"
(308) Wed Jul 25 09:03:44 2018: Debug: NAS-IP-Address = 10.10.0.38
(308) Wed Jul 25 09:03:44 2018: Debug: NAS-Port = 60000
(308) Wed Jul 25 09:03:44 2018: Debug: NAS-Port-Id =
"GigabitEthernet1/0/23"
(308) Wed Jul 25 09:03:44 2018: Debug: NAS-Port-Type = Ethernet
(308) Wed Jul 25 09:03:44 2018: Debug: # Executing section authorize
from file /usr/local/pf/raddb/sites-enabled/packetfence
(308) Wed Jul 25 09:03:44 2018: Debug: authorize {
(308) Wed Jul 25 09:03:44 2018: Debug: update {
(308) Wed Jul 25 09:03:44 2018: Debug: EXPAND
%{Packet-Src-IP-Address}
(308) Wed Jul 25 09:03:44 2018: Debug: --> 10.10.0.38
(308) Wed Jul 25 09:03:44 2018: Debug: EXPAND %l
(308) Wed Jul 25 09:03:44 2018: Debug: --> 1532534624
(308) Wed Jul 25 09:03:44 2018: Debug: } # update = noop
(308) Wed Jul 25 09:03:44 2018: Debug: policy packetfence-set-tenant-id {
(308) Wed Jul 25 09:03:44 2018: Debug: if (
"%{%{control:PacketFence-Tenant-Id}:-0}" == "0") {
(308) Wed Jul 25 09:03:44 2018: Debug: EXPAND
%{%{control:PacketFence-Tenant-Id}:-0}
(308) Wed Jul 25 09:03:44 2018: Debug: --> 0
(308) Wed Jul 25 09:03:44 2018: Debug: if (
"%{%{control:PacketFence-Tenant-Id}:-0}" == "0") -> TRUE
(308) Wed Jul 25 09:03:44 2018: Debug: if (
"%{%{control:PacketFence-Tenant-Id}:-0}" == "0") {
(308) Wed Jul 25 09:03:44 2018: Debug: update control {
(308) Wed Jul 25 09:03:44 2018: Debug: EXPAND %{User-Name}
(308) Wed Jul 25 09:03:44 2018: Debug: --> 0004f2963df1
(308) Wed Jul 25 09:03:44 2018: Debug: SQL-User-Name set to
'0004f2963df1'
(308) Wed Jul 25 09:03:44 2018: Debug: Executing select
query: SELECT IFNULL((SELECT tenant_id FROM radius_nas WHERE nasname
= '10.10.0.38'), 0)
(308) Wed Jul 25 09:03:44 2018: Debug: EXPAND %{sql: SELECT
IFNULL((SELECT tenant_id FROM radius_nas WHERE nasname =
'%{Packet-Src-IP-Address}'), 0)}
(308) Wed Jul 25 09:03:44 2018: Debug: --> 1
(308) Wed Jul 25 09:03:44 2018: Debug: } # update control = noop
(308) Wed Jul 25 09:03:44 2018: Debug: } # if (
"%{%{control:PacketFence-Tenant-Id}:-0}" == "0") = noop
(308) Wed Jul 25 09:03:44 2018: Debug: if (
&control:PacketFence-Tenant-Id == 0 ) {
(308) Wed Jul 25 09:03:44 2018: Debug: if (
&control:PacketFence-Tenant-Id == 0 ) -> FALSE
(308) Wed Jul 25 09:03:44 2018: Debug: } # policy
packetfence-set-tenant-id = noop
(308) Wed Jul 25 09:03:44 2018: Debug: policy
rewrite_calling_station_id {
(308) Wed Jul 25 09:03:44 2018: Debug: if (&Calling-Station-Id
&& (&Calling-Station-Id =~
/^([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})$/i))
{
(308) Wed Jul 25 09:03:44 2018: Debug: if (&Calling-Station-Id
&& (&Calling-Station-Id =~
/^([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})$/i))
-> TRUE
(308) Wed Jul 25 09:03:44 2018: Debug: if (&Calling-Station-Id
&& (&Calling-Station-Id =~
/^([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})$/i))
{
(308) Wed Jul 25 09:03:44 2018: Debug: update request {
(308) Wed Jul 25 09:03:44 2018: Debug: EXPAND
%{tolower:%{1}:%{2}:%{3}:%{4}:%{5}:%{6}}
(308) Wed Jul 25 09:03:44 2018: Debug: --> 00:04:f2:96:3d:f1
(308) Wed Jul 25 09:03:44 2018: Debug: } # update request = noop
(308) Wed Jul 25 09:03:44 2018: Debug: [updated] = updated
(308) Wed Jul 25 09:03:44 2018: Debug: } # if
(&Calling-Station-Id && (&Calling-Station-Id =~
/^([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})$/i))
= up
dated
(308) Wed Jul 25 09:03:44 2018: Debug: ... skipping else:
Preceding "if" was taken
(308) Wed Jul 25 09:03:44 2018: Debug: } # policy
rewrite_calling_station_id = updated
(308) Wed Jul 25 09:03:44 2018: Debug: policy rewrite_called_station_id {
(308) Wed Jul 25 09:03:44 2018: Debug: if ((&Called-Station-Id)
&& (&Called-Station-Id =~
/^([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})(:(.+))?$/i))
{
(308) Wed Jul 25 09:03:44 2018: Debug: if ((&Called-Station-Id)
&& (&Called-Station-Id =~
/^([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})(:(.+))?$/i))
-> TRUE
(308) Wed Jul 25 09:03:44 2018: Debug: if ((&Called-Station-Id)
&& (&Called-Station-Id =~
/^([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})(:(.+))?$/i))
{
(308) Wed Jul 25 09:03:44 2018: Debug: update request {
(308) Wed Jul 25 09:03:44 2018: Debug: EXPAND
%{tolower:%{1}:%{2}:%{3}:%{4}:%{5}:%{6}}
(308) Wed Jul 25 09:03:44 2018: Debug: --> 50:08:ac:51:83:97
(308) Wed Jul 25 09:03:44 2018: Debug: } # update request = noop
(308) Wed Jul 25 09:03:44 2018: Debug: if ("%{8}") {
(308) Wed Jul 25 09:03:44 2018: Debug: EXPAND %{8}
(308) Wed Jul 25 09:03:44 2018: Debug: -->
(308) Wed Jul 25 09:03:44 2018: Debug: if ("%{8}") -> FALSE
(308) Wed Jul 25 09:03:44 2018: Debug: elsif (
(Colubris-AVPair) && "%{Colubris-AVPair}" =~ /^ssid=(.*)$/i) {
(308) Wed Jul 25 09:03:44 2018: Debug: elsif ( (Colubris-AVPair)
&& "%{Colubris-AVPair}" =~ /^ssid=(.*)$/i) -> FALSE
(308) Wed Jul 25 09:03:44 2018: Debug: elsif (Aruba-Essid-Name) {
(308) Wed Jul 25 09:03:44 2018: Debug: elsif
(Aruba-Essid-Name) -> FALSE
(308) Wed Jul 25 09:03:44 2018: Debug: elsif ( (Cisco-AVPair)
&& "%{Cisco-AVPair}" =~ /^ssid=(.*)$/i) {
(308) Wed Jul 25 09:03:44 2018: Debug: EXPAND %{Cisco-AVPair}
(308) Wed Jul 25 09:03:44 2018: Debug: -->
service-type=Call Check
(308) Wed Jul 25 09:03:44 2018: Debug: elsif ( (Cisco-AVPair)
&& "%{Cisco-AVPair}" =~ /^ssid=(.*)$/i) -> FALSE
(308) Wed Jul 25 09:03:44 2018: Debug: [updated] = updated
(308) Wed Jul 25 09:03:44 2018: Debug: } # if
((&Called-Station-Id) && (&Called-Station-Id =~
/^([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})(:(.+))?$/i
)) = updated
(308) Wed Jul 25 09:03:44 2018: Debug: ... skipping else:
Preceding "if" was taken
(308) Wed Jul 25 09:03:44 2018: Debug: } # policy
rewrite_called_station_id = updated
(308) Wed Jul 25 09:03:44 2018: Debug: policy filter_username {
(308) Wed Jul 25 09:03:44 2018: Debug: if (&User-Name) {
(308) Wed Jul 25 09:03:44 2018: Debug: if (&User-Name) -> TRUE
(308) Wed Jul 25 09:03:44 2018: Debug: if (&User-Name) {
(308) Wed Jul 25 09:03:44 2018: Debug: if (&User-Name =~ / /) {
(308) Wed Jul 25 09:03:44 2018: Debug: if (&User-Name =~ / /)
-> FALSE
(308) Wed Jul 25 09:03:44 2018: Debug: if (&User-Name =~
/@[^@]*@/ ) {
(308) Wed Jul 25 09:03:44 2018: Debug: if (&User-Name =~
/@[^@]*@/ ) -> FALSE
(308) Wed Jul 25 09:03:44 2018: Debug: if (&User-Name =~
/\.\./ ) {
(308) Wed Jul 25 09:03:44 2018: Debug: if (&User-Name =~
/\.\./ ) -> FALSE
(308) Wed Jul 25 09:03:44 2018: Debug: if ((&User-Name =~ /@/)
&& (&User-Name !~ /@(.+)\.(.+)$/)) {
(308) Wed Jul 25 09:03:44 2018: Debug: if ((&User-Name =~ /@/)
&& (&User-Name !~ /@(.+)\.(.+)$/)) -> FALSE
(308) Wed Jul 25 09:03:44 2018: Debug: if (&User-Name =~ /\.$/) {
(308) Wed Jul 25 09:03:44 2018: Debug: if (&User-Name =~
/\.$/) -> FALSE
(308) Wed Jul 25 09:03:44 2018: Debug: if (&User-Name =~ /@\./) {
(308) Wed Jul 25 09:03:44 2018: Debug: if (&User-Name =~
/@\./) -> FALSE
(308) Wed Jul 25 09:03:44 2018: Debug: } # if (&User-Name) =
updated
(308) Wed Jul 25 09:03:44 2018: Debug: } # policy filter_username =
updated
(308) Wed Jul 25 09:03:44 2018: Debug: policy filter_password {
(308) Wed Jul 25 09:03:44 2018: Debug: if (&User-Password &&
(&User-Password != "%{string:User-Password}")) {
(308) Wed Jul 25 09:03:44 2018: Debug: EXPAND
%{string:User-Password}
(308) Wed Jul 25 09:03:44 2018: Debug: --> 0004f2963df1
(308) Wed Jul 25 09:03:44 2018: Debug: if (&User-Password &&
(&User-Password != "%{string:User-Password}")) -> FALSE
(308) Wed Jul 25 09:03:44 2018: Debug: } # policy filter_password =
updated
(308) Wed Jul 25 09:03:44 2018: Debug: [preprocess] = ok
(308) Wed Jul 25 09:03:44 2018: Debug: suffix: Checking for suffix
after "@"
(308) Wed Jul 25 09:03:44 2018: Debug: suffix: No '@' in User-Name =
"0004f2963df1", skipping NULL due to config.
(308) Wed Jul 25 09:03:44 2018: Debug: [suffix] = noop
(308) Wed Jul 25 09:03:44 2018: Debug: ntdomain: Checking for prefix
before "\"
(308) Wed Jul 25 09:03:44 2018: Debug: ntdomain: No '\' in User-Name =
"0004f2963df1", looking up realm NULL
(308) Wed Jul 25 09:03:44 2018: Debug: ntdomain: Found realm "null"
(308) Wed Jul 25 09:03:44 2018: Debug: ntdomain: Adding
Stripped-User-Name = "0004f2963df1"
(308) Wed Jul 25 09:03:44 2018: Debug: ntdomain: Adding Realm = "null"
(308) Wed Jul 25 09:03:44 2018: Debug: ntdomain: Authentication realm
is LOCAL
(308) Wed Jul 25 09:03:44 2018: Debug: [ntdomain] = ok
(308) Wed Jul 25 09:03:44 2018: Debug: eap: No EAP-Message, not doing EAP
(308) Wed Jul 25 09:03:44 2018: Debug: [eap] = noop
(308) Wed Jul 25 09:03:44 2018: Debug: if ( !EAP-Message ) {
(308) Wed Jul 25 09:03:44 2018: Debug: if ( !EAP-Message ) -> TRUE
(308) Wed Jul 25 09:03:44 2018: Debug: if ( !EAP-Message ) {
(308) Wed Jul 25 09:03:44 2018: Debug: update {
(308) Wed Jul 25 09:03:44 2018: Debug: } # update = noop
(308) Wed Jul 25 09:03:44 2018: Debug: } # if ( !EAP-Message ) = noop
(308) Wed Jul 25 09:03:44 2018: Debug: policy
packetfence-eap-mac-policy {
(308) Wed Jul 25 09:03:44 2018: Debug: if ( &EAP-Type ) {
(308) Wed Jul 25 09:03:44 2018: Debug: if ( &EAP-Type ) -> FALSE
(308) Wed Jul 25 09:03:44 2018: Debug: [noop] = noop
(308) Wed Jul 25 09:03:44 2018: Debug: } # policy
packetfence-eap-mac-policy = noop
(308) Wed Jul 25 09:03:44 2018: WARNING: pap:
!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
(308) Wed Jul 25 09:03:44 2018: WARNING: pap: !!! Ignoring
control:User-Password. Update your !!!
(308) Wed Jul 25 09:03:44 2018: WARNING: pap: !!! configuration so
that the "known good" clear text !!!
(308) Wed Jul 25 09:03:44 2018: WARNING: pap: !!! password is in
Cleartext-Password and NOT in !!!
(308) Wed Jul 25 09:03:44 2018: WARNING: pap: !!! User-Password. !!!
(308) Wed Jul 25 09:03:44 2018: WARNING: pap:
!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
(308) Wed Jul 25 09:03:44 2018: WARNING: pap: Auth-Type already set.
Not setting to PAP
(308) Wed Jul 25 09:03:44 2018: Debug: [pap] = noop
(308) Wed Jul 25 09:03:44 2018: Debug: } # authorize = updated
(308) Wed Jul 25 09:03:44 2018: Debug: Found Auth-Type = Accept
(308) Wed Jul 25 09:03:44 2018: Debug: Auth-Type = Accept, accepting
the user
(308) Wed Jul 25 09:03:44 2018: Debug: # Executing section post-auth
from file /usr/local/pf/raddb/sites-enabled/packetfence
(308) Wed Jul 25 09:03:44 2018: Debug: post-auth {
(308) Wed Jul 25 09:03:44 2018: Debug: update {
(308) Wed Jul 25 09:03:44 2018: Debug: EXPAND
%{Packet-Src-IP-Address}
(308) Wed Jul 25 09:03:44 2018: Debug: --> 10.10.0.38
(308) Wed Jul 25 09:03:44 2018: Debug: } # update = noop
(308) Wed Jul 25 09:03:44 2018: Debug: policy packetfence-set-tenant-id {
(308) Wed Jul 25 09:03:44 2018: Debug: if (
"%{%{control:PacketFence-Tenant-Id}:-0}" == "0") {
(308) Wed Jul 25 09:03:44 2018: Debug: EXPAND
%{%{control:PacketFence-Tenant-Id}:-0}
(308) Wed Jul 25 09:03:44 2018: Debug: --> 1
(308) Wed Jul 25 09:03:44 2018: Debug: if (
"%{%{control:PacketFence-Tenant-Id}:-0}" == "0") -> FALSE
(308) Wed Jul 25 09:03:44 2018: Debug: if (
&control:PacketFence-Tenant-Id == 0 ) {
(308) Wed Jul 25 09:03:44 2018: Debug: if (
&control:PacketFence-Tenant-Id == 0 ) -> FALSE
(308) Wed Jul 25 09:03:44 2018: Debug: } # policy
packetfence-set-tenant-id = noop
(308) Wed Jul 25 09:03:44 2018: Debug: if (! EAP-Type || (EAP-Type !=
TTLS && EAP-Type != PEAP) ) {
(308) Wed Jul 25 09:03:44 2018: Debug: if (! EAP-Type || (EAP-Type !=
TTLS && EAP-Type != PEAP) ) -> TRUE
(308) Wed Jul 25 09:03:44 2018: Debug: if (! EAP-Type || (EAP-Type !=
TTLS && EAP-Type != PEAP) ) {
(308) Wed Jul 25 09:03:44 2018: Debug: rest: Expanding URI components
(308) Wed Jul 25 09:03:44 2018: Debug: rest: EXPAND http://127.0.0.1:7070
(308) Wed Jul 25 09:03:44 2018: Debug: rest: --> http://127.0.0.1:7070
(308) Wed Jul 25 09:03:44 2018: Debug: rest: EXPAND
//radius/rest/authorize
(308) Wed Jul 25 09:03:44 2018: Debug: rest: -->
//radius/rest/authorize
(308) Wed Jul 25 09:03:44 2018: Debug: rest: Sending HTTP POST to
"http://127.0.0.1:7070//radius/rest/authorize";
(308) Wed Jul 25 09:03:44 2018: Debug: rest: Encoding attribute
"User-Name"
(308) Wed Jul 25 09:03:44 2018: Debug: rest: Encoding attribute
"User-Password"
(308) Wed Jul 25 09:03:44 2018: Debug: rest: Encoding attribute
"NAS-IP-Address"
(308) Wed Jul 25 09:03:44 2018: Debug: rest: Encoding attribute
"NAS-Port"
(308) Wed Jul 25 09:03:44 2018: Debug: rest: Encoding attribute
"Service-Type"
(308) Wed Jul 25 09:03:44 2018: Debug: rest: Encoding attribute
"Framed-MTU"
(308) Wed Jul 25 09:03:44 2018: Debug: rest: Encoding attribute
"Called-Station-Id"
(308) Wed Jul 25 09:03:44 2018: Debug: rest: Encoding attribute
"Calling-Station-Id"
(308) Wed Jul 25 09:03:44 2018: Debug: rest: Encoding attribute
"NAS-Port-Type"
(308) Wed Jul 25 09:03:44 2018: Debug: rest: Encoding attribute
"Event-Timestamp"
(308) Wed Jul 25 09:03:44 2018: Debug: rest: Encoding attribute
"Message-Authenticator"
(308) Wed Jul 25 09:03:44 2018: Debug: rest: Encoding attribute
"NAS-Port-Id"
(308) Wed Jul 25 09:03:44 2018: Debug: rest: Encoding attribute
"Cisco-AVPair"
(308) Wed Jul 25 09:03:44 2018: Debug: rest: Encoding attribute
"Stripped-User-Name"
(308) Wed Jul 25 09:03:44 2018: Debug: rest: Encoding attribute "Realm"
(308) Wed Jul 25 09:03:44 2018: Debug: rest: Encoding attribute
"SQL-User-Name"
(308) Wed Jul 25 09:03:44 2018: Debug: rest: Encoding attribute
"FreeRADIUS-Client-IP-Address"
(308) Wed Jul 25 09:03:44 2018: Debug: rest: Returning 1018 bytes of
JSON data (buffer full or chunk exceeded)
(308) Wed Jul 25 09:03:44 2018: Debug: rest: Encoding attribute
"FreeRADIUS-Client-IP-Address"
(308) Wed Jul 25 09:03:44 2018: Debug: rest: Processing response header
(308) Wed Jul 25 09:03:44 2018: Debug: rest: Status : 100 (Continue)
(308) Wed Jul 25 09:03:44 2018: Debug: rest: Continuing...
(308) Wed Jul 25 09:03:44 2018: Debug: rest: Processing response header
(308) Wed Jul 25 09:03:44 2018: Debug: rest: Status : 200 (OK)
(308) Wed Jul 25 09:03:44 2018: Debug: rest: Type : json
(application/json)
(308) Wed Jul 25 09:03:44 2018: Debug: rest: Parsing attribute
"control:PacketFence-Role"
(308) Wed Jul 25 09:03:44 2018: Debug: rest: EXPAND voice
(308) Wed Jul 25 09:03:44 2018: Debug: rest: --> voice
(308) Wed Jul 25 09:03:44 2018: Debug: rest: PacketFence-Role := "voice"
(308) Wed Jul 25 09:03:44 2018: Debug: rest: Parsing attribute
"control:PacketFence-Eap-Type"
(308) Wed Jul 25 09:03:44 2018: Debug: rest: EXPAND 0
(308) Wed Jul 25 09:03:44 2018: Debug: rest: --> 0
(308) Wed Jul 25 09:03:44 2018: Debug: rest: PacketFence-Eap-Type := "0"
(308) Wed Jul 25 09:03:44 2018: Debug: rest: Parsing attribute
"control:PacketFence-AutoReg"
(308) Wed Jul 25 09:03:44 2018: Debug: rest: EXPAND 1
(308) Wed Jul 25 09:03:44 2018: Debug: rest: --> 1
(308) Wed Jul 25 09:03:44 2018: Debug: rest: PacketFence-AutoReg := "1"
(308) Wed Jul 25 09:03:44 2018: Debug: rest: Parsing attribute
"control:PacketFence-Authorization-Status"
(308) Wed Jul 25 09:03:44 2018: Debug: rest: EXPAND allow
(308) Wed Jul 25 09:03:44 2018: Debug: rest: --> allow
(308) Wed Jul 25 09:03:44 2018: Debug: rest:
PacketFence-Authorization-Status := "allow"
(308) Wed Jul 25 09:03:44 2018: Debug: rest: Parsing attribute
"control:PacketFence-Switch-Ip-Address"
(308) Wed Jul 25 09:03:44 2018: Debug: rest: EXPAND 10.10.0.38
(308) Wed Jul 25 09:03:44 2018: Debug: rest: --> 10.10.0.38
(308) Wed Jul 25 09:03:44 2018: Debug: rest:
PacketFence-Switch-Ip-Address := "10.10.0.38"
(308) Wed Jul 25 09:03:44 2018: Debug: rest: Parsing attribute
"control:PacketFence-Request-Time"
(308) Wed Jul 25 09:03:44 2018: Debug: rest: EXPAND 1532534624
(308) Wed Jul 25 09:03:44 2018: Debug: rest: --> 1532534624
(308) Wed Jul 25 09:03:44 2018: Debug: rest: PacketFence-Request-Time
:= 1532534624
(308) Wed Jul 25 09:03:44 2018: Debug: rest: Parsing attribute
"control:PacketFence-UserName"
(308) Wed Jul 25 09:03:44 2018: Debug: rest: EXPAND 0004f2963df1
(308) Wed Jul 25 09:03:44 2018: Debug: rest: --> 0004f2963df1
(308) Wed Jul 25 09:03:44 2018: Debug: rest: PacketFence-UserName :=
"0004f2963df1"
(308) Wed Jul 25 09:03:44 2018: Debug: rest: Parsing attribute
"control:PacketFence-IsPhone"
(308) Wed Jul 25 09:03:44 2018: Debug: rest: EXPAND 1
(308) Wed Jul 25 09:03:44 2018: Debug: rest: --> 1
(308) Wed Jul 25 09:03:44 2018: Debug: rest: PacketFence-IsPhone := "1"
(308) Wed Jul 25 09:03:44 2018: Debug: rest: Parsing attribute
"control:PacketFence-Switch-Id"
(308) Wed Jul 25 09:03:44 2018: Debug: rest: EXPAND 10.10.0.38
(308) Wed Jul 25 09:03:44 2018: Debug: rest: --> 10.10.0.38
(308) Wed Jul 25 09:03:44 2018: Debug: rest: PacketFence-Switch-Id :=
"10.10.0.38"
(308) Wed Jul 25 09:03:44 2018: Debug: rest: Parsing attribute
"control:PacketFence-Switch-Mac"
(308) Wed Jul 25 09:03:44 2018: Debug: rest: EXPAND 50:08:ac:51:83:97
(308) Wed Jul 25 09:03:44 2018: Debug: rest: --> 50:08:ac:51:83:97
(308) Wed Jul 25 09:03:44 2018: Debug: rest: PacketFence-Switch-Mac :=
"50:08:ac:51:83:97"
(308) Wed Jul 25 09:03:44 2018: Debug: rest: Parsing attribute
"control:PacketFence-Computer-Name"
(308) Wed Jul 25 09:03:44 2018: Debug: rest: PacketFence-Computer-Name
:= ""
(308) Wed Jul 25 09:03:44 2018: Debug: rest: Parsing attribute
"Cisco-AVPair"
(308) Wed Jul 25 09:03:44 2018: Debug: rest: EXPAND
device-traffic-class=voice
(308) Wed Jul 25 09:03:44 2018: Debug: rest: -->
device-traffic-class=voice
(308) Wed Jul 25 09:03:44 2018: Debug: rest: Cisco-AVPair :=
"device-traffic-class=voice"
(308) Wed Jul 25 09:03:44 2018: Debug: rest: Parsing attribute
"control:PacketFence-Mac"
(308) Wed Jul 25 09:03:44 2018: Debug: rest: EXPAND 00:04:f2:96:3d:f1
(308) Wed Jul 25 09:03:44 2018: Debug: rest: --> 00:04:f2:96:3d:f1
(308) Wed Jul 25 09:03:44 2018: Debug: rest: PacketFence-Mac :=
"00:04:f2:96:3d:f1"
(308) Wed Jul 25 09:03:44 2018: Debug: rest: Parsing attribute
"control:PacketFence-IfIndex"
(308) Wed Jul 25 09:03:44 2018: Debug: rest: EXPAND 10123
(308) Wed Jul 25 09:03:44 2018: Debug: rest: --> 10123
(308) Wed Jul 25 09:03:44 2018: Debug: rest: PacketFence-IfIndex :=
"10123"
(308) Wed Jul 25 09:03:44 2018: Debug: rest: Parsing attribute
"control:PacketFence-Connection-Type"
(308) Wed Jul 25 09:03:44 2018: Debug: rest: EXPAND WIRED_MAC_AUTH
(308) Wed Jul 25 09:03:44 2018: Debug: rest: --> WIRED_MAC_AUTH
(308) Wed Jul 25 09:03:44 2018: Debug: rest:
PacketFence-Connection-Type := "WIRED_MAC_AUTH"
(308) Wed Jul 25 09:03:44 2018: Debug: rest: Parsing attribute
"control:PacketFence-Status"
(308) Wed Jul 25 09:03:44 2018: Debug: rest: EXPAND reg
(308) Wed Jul 25 09:03:44 2018: Debug: rest: --> reg
(308) Wed Jul 25 09:03:44 2018: Debug: rest: PacketFence-Status := "reg"
(308) Wed Jul 25 09:03:44 2018: Debug: [rest] = updated
(308) Wed Jul 25 09:03:44 2018: Debug: update {
(308) Wed Jul 25 09:03:44 2018: Debug: } # update = noop
(308) Wed Jul 25 09:03:44 2018: Debug: if
(&control:PacketFence-Authorization-Status == "deny") {
(308) Wed Jul 25 09:03:44 2018: Debug: if
(&control:PacketFence-Authorization-Status == "deny") -> FALSE
(308) Wed Jul 25 09:03:44 2018: Debug: else {
(308) Wed Jul 25 09:03:44 2018: Debug: policy
packetfence-audit-log-accept {
(308) Wed Jul 25 09:03:44 2018: Debug: if (&User-Name &&
(&User-Name == "dummy")) {
(308) Wed Jul 25 09:03:44 2018: Debug: if (&User-Name &&
(&User-Name == "dummy")) -> FALSE
(308) Wed Jul 25 09:03:44 2018: Debug: else {
(308) Wed Jul 25 09:03:44 2018: Debug: policy
request-timing {
(308) Wed Jul 25 09:03:44 2018: Debug: if
(control:PacketFence-Request-Time != 0) {
(308) Wed Jul 25 09:03:44 2018: Debug: if
(control:PacketFence-Request-Time != 0) -> TRUE
(308) Wed Jul 25 09:03:44 2018: Debug: if
(control:PacketFence-Request-Time != 0) {
(308) Wed Jul 25 09:03:44 2018: Debug: update control {
(308) Wed Jul 25 09:03:44 2018: Debug: EXPAND
%{expr: %{control:PacketFence-Request-Time} - %{control:Tmp-Integer-0}}
(308) Wed Jul 25 09:03:44 2018: Debug: --> 0
(308) Wed Jul 25 09:03:44 2018: Debug: } # update
control = noop
(308) Wed Jul 25 09:03:44 2018: Debug: } # if
(control:PacketFence-Request-Time != 0) = noop
(308) Wed Jul 25 09:03:44 2018: Debug: } # policy
request-timing = noop
(308) Wed Jul 25 09:03:44 2018: Debug: sql: EXPAND type.accept.query
(308) Wed Jul 25 09:03:44 2018: Debug: sql: --> type.accept.query
(308) Wed Jul 25 09:03:44 2018: Debug: sql: Using query template 'query'
(308) Wed Jul 25 09:03:44 2018: Debug: sql: EXPAND %{User-Name}
(308) Wed Jul 25 09:03:44 2018: Debug: sql: --> 0004f2963df1
(308) Wed Jul 25 09:03:44 2018: Debug: sql: SQL-User-Name set to
'0004f2963df1'
(308) Wed Jul 25 09:03:44 2018: Debug: sql: EXPAND INSERT INTO
radius_audit_log ( mac, ip, computer_name,
user_name, stripped_user_name, realm,
event_type, switch_id, switch_mac, switch_ip_address
, radius_source_ip_address, called_station_id,
calling_station_id, nas_port_type, ssid, nas_port_id,
ifindex, nas_port, connection_type, nas_ip_address,
nas_identifier, auth_status,
reason, auth_type, eap_type, role,
node_status, profile, source, auto_reg,
is_phone, pf_domain, uuid,
radius_request, radius_reply, request_time, tenant_id)
VALUES ( '%{request:Calling-Station-Id}',
'%{request:Framed-IP-Address}',
'%{%{control:PacketFence-Computer-Name}:-N/A}',
'%{request:User-Name}', '%{request:Stripped-User-Name}',
'%{request:Realm}', 'Radius-
Access-Request', '%{%{control:PacketFence-Switch-Id}:-N/A}',
'%{%{control:PacketFence-Switch-Mac}:-N/A}',
'%{%{control:PacketFence-Switch-Ip-Address}:-N/A}',
'%{Packet-Src-IP-Address}', '%{request:Called-Station
-Id}', '%{request:Calling-Station-Id}', '%{request:NAS-Port-Type}',
'%{request:Called-Station-SSID}', '%{request:NAS-Port-Id}',
'%{%{control:PacketFence-IfIndex}:-N/A}', '%{request:NAS-Port}',
'%{%{control:Packe
tFence-Connection-Type}:-N/A}', '%{request:NAS-IP-Address}',
'%{request:NAS-Identifier}', 'Accept',
'%{request:Module-Failure-Message}', '%{control:Auth-Type}',
'%{request:EAP-Type}', '%{%{control
:PacketFence-Role}:-N/A}', '%{%{control:PacketFence-Status}:-N/A}',
'%{%{control:PacketFence-Profile}:-N/A}',
'%{%{control:PacketFence-Source}:-N/A}',
'%{%{control:PacketFence-AutoReg}:-0}',
'%{%{control:PacketFence-IsPhone}:-
0}', '%{request:PacketFence-Domain}', '',
'%{pairs:&request:[*]}','%{pairs:&reply:[*]}',
'%{control:PacketFence-Request-Time}',
'%{control:PacketFence-Tenant-Id}')
(308) Wed Jul 25 09:03:44 2018: Debug: sql: --> INSERT INTO
radius_audit_log ( mac, ip, computer_name, user_name,
stripped_user_name, realm, event_type, switch_id, switch_mac,
switch_ip_address
, radius_source_ip_address, called_station_id,
calling_station_id, nas_port_type, ssid, nas_port_id,
ifindex, nas_port, connection_type, nas_ip_address,
nas_identifier, auth_status,
reason, auth_type, eap_type, role,
node_status, profile, source, auto_reg,
is_phone, pf_domain, uuid,
radius_request, radius_reply, request_time, tenant_id)
VALUES ( '00:04:f2:96:3d:f1', '', 'N/A',
'0004f2963df1', '0004f2963df1', 'null',
'Radius-Access-Request', '10.10.0.38',
'50:08:ac:51:83:97', '10.10.0.38', '10.10.0.38', '50:08:a
c:51:83:97', '00:04:f2:96:3d:f1', 'Ethernet', '',
'GigabitEthernet1/0/23', '10123', '60000',
'WIRED_MAC_AUTH', '10.10.0.38', '',
'Accept', '', 'Accept', '', 'voice',
'reg', 'N/A', 'N/A', '1', '1', '', '',
'User-Name =3D =220004f2963df1=22=2C User-Password =3D
=22=2A=2A=2A=2A=2A=2A=22=2C NAS-IP-Address =3D 10.10.0.38=2C NAS-Port
=3D 60000=2C Service-Type =3D Call-Check=2C Fra
med-MTU =3D 1500=2C Called-Station-Id =3D =2250:08:ac:51:83:97=22=2C
Calling-Station-Id =3D =2200:04:f2:96:3d:f1=22=2C NAS-Port-Type =3D
Ethernet=2C Event-Timestamp =3D =22Jul 25 2018 09:03:44 PDT=22=2C
Message-Authenticator =3D 0x33daf83686
6565e5329d562bac5b1eb8=2C NAS-Port-Id =3D
=22GigabitEthernet1/0/23=22=2C Cisco-AVPair =3D =22service-type=3DCall
Check=22=2C Cisco-AVPair =3D
=22audit-session-id=3D0A0A0026000002D45C0C7682=22=2C Cisco-AVPair =3D
=22method=3Dmab=22=2C Strippe
d-User-Name =3D =220004f2963df1=22=2C Realm =3D =22null=22=2C
FreeRADIUS-Client-IP-Address =3D 10.10.0.38=2C SQL-User-Name =3D
=220004f2963df1=22','Cisco-AVPair =3D
=22device-traffic-class=3Dvoice=22', '0', '1')
(308) Wed Jul 25 09:03:44 2018: Debug: sql: Executing query: INSERT
INTO radius_audit_log ( mac, ip, computer_name,
user_name, stripped_user_name, realm, event_type, switch_id,
switch_mac, switch_
ip_address, radius_source_ip_address, called_station_id,
calling_station_id, nas_port_type, ssid,
nas_port_id, ifindex, nas_port,
connection_type, nas_ip_address, nas_identifier, au
th_status, reason, auth_type, eap_type,
role, node_status, profile, source, auto_reg,
is_phone, pf_domain, uuid,
radius_request, radius_reply, request_time, tenant_id
) VALUES ( '00:04:f2:96:3d:f1', '', 'N/A',
'0004f2963df1', '0004f2963df1', 'null',
'Radius-Access-Request', '10.10.0.38',
'50:08:ac:51:83:97', '10.10.0.38', '10.10.0.38'
, '50:08:ac:51:83:97', '00:04:f2:96:3d:f1', 'Ethernet',
'', 'GigabitEthernet1/0/23', '10123', '60000',
'WIRED_MAC_AUTH', '10.10.0.38', '',
'Accept', '', 'Accept', '',
'voice', 'reg', 'N/A', 'N/A', '1', '1', '', '',
'User-Name =3D =220004f2963df1=22=2C User-Password =3D
=22=2A=2A=2A=2A=2A=2A=22=2C NAS-IP-Address =3D 10.10.0.38=2C NAS-Port
=3D 60000=2C Service-Type =3D Call-Ch
eck=2C Framed-MTU =3D 1500=2C Called-Station-Id =3D
=2250:08:ac:51:83:97=22=2C Calling-Station-Id =3D
=2200:04:f2:96:3d:f1=22=2C NAS-Port-Type =3D Ethernet=2C
Event-Timestamp =3D =22Jul 25 2018 09:03:44 PDT=22=2C
Message-Authenticator =3D 0x
33daf836866565e5329d562bac5b1eb8=2C NAS-Port-Id =3D
=22GigabitEthernet1/0/23=22=2C Cisco-AVPair =3D =22service-type=3DCall
Check=22=2C Cisco-AVPair =3D
=22audit-session-id=3D0A0A0026000002D45C0C7682=22=2C Cisco-AVPair =3D
=22method=3Dmab=22=
2C Stripped-User-Name =3D =220004f2963df1=22=2C Realm =3D
=22null=22=2C FreeRADIUS-Client-IP-Address =3D 10.10.0.38=2C
SQL-User-Name =3D =220004f2963df1=22','Cisco-AVPair =3D
=22device-traffic-class=3Dvoice=22', '0', '1')
(308) Wed Jul 25 09:03:44 2018: Debug: sql: SQL query returned: success
(308) Wed Jul 25 09:03:44 2018: Debug: sql: 1 record(s) updated
(308) Wed Jul 25 09:03:44 2018: Debug: [sql] = ok
(308) Wed Jul 25 09:03:44 2018: Debug: } # else = ok
(308) Wed Jul 25 09:03:44 2018: Debug: } # policy
packetfence-audit-log-accept = ok
(308) Wed Jul 25 09:03:44 2018: Debug: } # else = ok
(308) Wed Jul 25 09:03:44 2018: Debug: } # if (! EAP-Type || (EAP-Type
!= TTLS && EAP-Type != PEAP) ) = updated
(308) Wed Jul 25 09:03:44 2018: Debug:
attr_filter.packetfence_post_auth: EXPAND %{User-Name}
(308) Wed Jul 25 09:03:44 2018: Debug:
attr_filter.packetfence_post_auth: --> 0004f2963df1
(308) Wed Jul 25 09:03:44 2018: Debug:
attr_filter.packetfence_post_auth: Matched entry DEFAULT at line 10
(308) Wed Jul 25 09:03:44 2018: Debug:
[attr_filter.packetfence_post_auth] = updated
(308) Wed Jul 25 09:03:44 2018: Debug: linelog: EXPAND
messages.%{%{reply:Packet-Type}:-default}
(308) Wed Jul 25 09:03:44 2018: Debug: linelog: -->
messages.Access-Accept
(308) Wed Jul 25 09:03:44 2018: Debug: linelog: EXPAND
[mac:%{Calling-Station-Id}] Accepted user: %{reply:User-Name} and
returned VLAN %{reply:Tunnel-Private-Group-ID}
(308) Wed Jul 25 09:03:44 2018: Debug: linelog: -->
[mac:00:04:f2:96:3d:f1] Accepted user: and returned VLAN
(308) Wed Jul 25 09:03:44 2018: Debug: [linelog] = ok
(308) Wed Jul 25 09:03:44 2018: Debug: } # post-auth = updated
(308) Wed Jul 25 09:03:44 2018: Debug: Sent Access-Accept Id 142 from
10.0.1.44:1812 to 10.10.0.38:1645 length 0
(308) Wed Jul 25 09:03:44 2018: Debug: Cisco-AVPair =
"device-traffic-class=voice"
(308) Wed Jul 25 09:03:44 2018: Debug: Finished request
Regards,
*Peter Truax*
*Network Administrator*
St. Martin’s University
------------------------------------------------------------------------------
Check out the vibrant tech community on one of the world's most
engaging tech sites, Slashdot.org! http://sdm.link/slashdot
_______________________________________________
PacketFence-users mailing list
PacketFence-users@lists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/packetfence-users
