Hi All,
I have an unsupported switch that I want to test with packetfence.
Earlier I was successful with authenticating dot1x linux clients
with this switch and vlan enforcement worked just fine. The
switch is added to packetfence as generic type and production mode.
Now I want to try MAC AUTH to enable some printers or other such
devices that lack the suplicant. But i'm getting some strange
results.
It is a simple case where the switch sends an auth request to
packetfence with MAC address of the client as username and
password. I added the MAC as a user in the Pf db (create user)
and configured it to return vlan 5 (Voice vlan).
On the web UI of packetfence, I can see the device as registered
but strangely the Username which is the MAC address of the device
do not have any node registered against it. It does not return
the proper vlan id. Also, even if a change the client MAC address
that is not even added to packetfence the result in the same
access-accept with undefined role and vlan.
Please check the logs below and advise, i'm sure i'm missing some
configuration, thank you.
Ali
raddebug
(11) Wed Aug 22 09:35:55 2018: Debug: Received Access-Request Id
1 from 10.10.51.169:1812 <http://10.10.51.169:1812> to
10.10.50.204:1812 <http://10.10.50.204:1812> length 153
(11) Wed Aug 22 09:35:55 2018: Debug: User-Name =
"00:02:09:00:01:00"
(11) Wed Aug 22 09:35:55 2018: Debug: User-Password =
"00:02:09:00:01:00"
(11) Wed Aug 22 09:35:55 2018: Debug: Framed-MTU = 1500
(11) Wed Aug 22 09:35:55 2018: Debug: Called-Station-Id =
"CC-37-AB-4F-B1-C1"
(11) Wed Aug 22 09:35:55 2018: Debug: Calling-Station-Id =
"00-02-09-00-01-00"
(11) Wed Aug 22 09:35:55 2018: Debug: NAS-IP-Address = 0.0.0.0
(11) Wed Aug 22 09:35:55 2018: Debug: NAS-Port-Type = Ethernet
(11) Wed Aug 22 09:35:55 2018: Debug: NAS-Port = 25
(11) Wed Aug 22 09:35:55 2018: Debug: Message-Authenticator =
0x175584cbbaa167dc3be140dc927b2079
(11) Wed Aug 22 09:35:55 2018: Debug: # Executing section
authorize from file /usr/local/pf/raddb/sites-enabled/packetfence
(11) Wed Aug 22 09:35:55 2018: Debug: authorize {
(11) Wed Aug 22 09:35:55 2018: Debug: update {
(11) Wed Aug 22 09:35:55 2018: Debug: EXPAND
%{Packet-Src-IP-Address}
(11) Wed Aug 22 09:35:55 2018: Debug: --> 10.10.51.169
(11) Wed Aug 22 09:35:55 2018: Debug: EXPAND %l
(11) Wed Aug 22 09:35:55 2018: Debug: --> 1534901755
(11) Wed Aug 22 09:35:55 2018: Debug: } # update = noop
(11) Wed Aug 22 09:35:55 2018: Debug: policy
packetfence-set-tenant-id {
(11) Wed Aug 22 09:35:55 2018: Debug: if (
"%{%{control:PacketFence-Tenant-Id}:-0}" == "0") {
(11) Wed Aug 22 09:35:55 2018: Debug: EXPAND
%{%{control:PacketFence-Tenant-Id}:-0}
(11) Wed Aug 22 09:35:55 2018: Debug: --> 0
(11) Wed Aug 22 09:35:55 2018: Debug: if (
"%{%{control:PacketFence-Tenant-Id}:-0}" == "0") -> TRUE
(11) Wed Aug 22 09:35:55 2018: Debug: if (
"%{%{control:PacketFence-Tenant-Id}:-0}" == "0") {
(11) Wed Aug 22 09:35:55 2018: Debug: update control {
(11) Wed Aug 22 09:35:55 2018: Debug: EXPAND %{User-Name}
(11) Wed Aug 22 09:35:55 2018: Debug: --> 00:02:09:00:01:00
(11) Wed Aug 22 09:35:55 2018: Debug: SQL-User-Name set to
'00:02:09:00:01:00'
(11) Wed Aug 22 09:35:55 2018: Debug: Executing select query:
SELECT IFNULL((SELECT tenant_id FROM radius_nas WHERE nasname =
'10.10.51.169'), 0)
(11) Wed Aug 22 09:35:55 2018: Debug: EXPAND %{sql: SELECT
IFNULL((SELECT tenant_id FROM radius_nas WHERE nasname =
'%{Packet-Src-IP-Address}'), 0)}
(11) Wed Aug 22 09:35:55 2018: Debug: --> 0
(11) Wed Aug 22 09:35:55 2018: Debug: } # update control
= noop
(11) Wed Aug 22 09:35:55 2018: Debug: } # if (
"%{%{control:PacketFence-Tenant-Id}:-0}" == "0") = noop
(11) Wed Aug 22 09:35:55 2018: Debug: if (
&control:PacketFence-Tenant-Id == 0 ) {
(11) Wed Aug 22 09:35:55 2018: Debug: if (
&control:PacketFence-Tenant-Id == 0 ) -> TRUE
(11) Wed Aug 22 09:35:55 2018: Debug: if (
&control:PacketFence-Tenant-Id == 0 ) {
(11) Wed Aug 22 09:35:55 2018: Debug: update control {
(11) Wed Aug 22 09:35:55 2018: Debug: EXPAND %{User-Name}
(11) Wed Aug 22 09:35:55 2018: Debug: --> 00:02:09:00:01:00
(11) Wed Aug 22 09:35:55 2018: Debug: SQL-User-Name set to
'00:02:09:00:01:00'
(11) Wed Aug 22 09:35:55 2018: Debug: Executing select query:
SELECT IFNULL((SELECT tenant_id from radius_nas WHERE start_ip <=
INET_ATON('10.10.51.169') and INET_ATON('10.10.51.169') <= end_ip
order by range_length limit 1), 1)
(11) Wed Aug 22 09:35:55 2018: Debug: EXPAND %{sql: SELECT
IFNULL((SELECT tenant_id from radius_nas WHERE start_ip <=
INET_ATON('%{Packet-Src-IP-Address}') and
INET_ATON('%{Packet-Src-IP-Address}') <= end_ip order by
range_length limit 1), 1)}
(11) Wed Aug 22 09:35:55 2018: Debug: --> 1
(11) Wed Aug 22 09:35:55 2018: Debug: } # update control
= noop
(11) Wed Aug 22 09:35:55 2018: Debug: } # if (
&control:PacketFence-Tenant-Id == 0 ) = noop
(11) Wed Aug 22 09:35:55 2018: Debug: } # policy
packetfence-set-tenant-id = noop
(11) Wed Aug 22 09:35:55 2018: Debug: policy
rewrite_calling_station_id {
(11) Wed Aug 22 09:35:55 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))
{
(11) Wed Aug 22 09:35:55 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
(11) Wed Aug 22 09:35:55 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))
{
(11) Wed Aug 22 09:35:55 2018: Debug: update request {
(11) Wed Aug 22 09:35:55 2018: Debug: EXPAND
%{tolower:%{1}:%{2}:%{3}:%{4}:%{5}:%{6}}
(11) Wed Aug 22 09:35:55 2018: Debug: --> 00:02:09:00:01:00
(11) Wed Aug 22 09:35:55 2018: Debug: } # update request
= noop
(11) Wed Aug 22 09:35:55 2018: Debug: [updated] = updated
(11) Wed Aug 22 09:35:55 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))
= updated
(11) Wed Aug 22 09:35:55 2018: Debug: ... skipping else:
Preceding "if" was taken
(11) Wed Aug 22 09:35:55 2018: Debug: } # policy
rewrite_calling_station_id = updated
(11) Wed Aug 22 09:35:55 2018: Debug: policy
rewrite_called_station_id {
(11) Wed Aug 22 09:35:55 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))
{
(11) Wed Aug 22 09:35:55 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
(11) Wed Aug 22 09:35:55 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))
{
(11) Wed Aug 22 09:35:55 2018: Debug: update request {
(11) Wed Aug 22 09:35:55 2018: Debug: EXPAND
%{tolower:%{1}:%{2}:%{3}:%{4}:%{5}:%{6}}
(11) Wed Aug 22 09:35:55 2018: Debug: --> cc:37:ab:4f:b1:c1
(11) Wed Aug 22 09:35:55 2018: Debug: } # update request
= noop
(11) Wed Aug 22 09:35:55 2018: Debug: if ("%{8}") {
(11) Wed Aug 22 09:35:55 2018: Debug: EXPAND %{8}
(11) Wed Aug 22 09:35:55 2018: Debug: -->
(11) Wed Aug 22 09:35:55 2018: Debug: if ("%{8}") -> FALSE
(11) Wed Aug 22 09:35:55 2018: Debug: elsif ( (Colubris-AVPair)
&& "%{Colubris-AVPair}" =~ /^ssid=(.*)$/i) {
(11) Wed Aug 22 09:35:55 2018: Debug: elsif ( (Colubris-AVPair)
&& "%{Colubris-AVPair}" =~ /^ssid=(.*)$/i) -> FALSE
(11) Wed Aug 22 09:35:55 2018: Debug: elsif (Aruba-Essid-Name) {
(11) Wed Aug 22 09:35:55 2018: Debug: elsif (Aruba-Essid-Name)
-> FALSE
(11) Wed Aug 22 09:35:55 2018: Debug: elsif ( (Cisco-AVPair) &&
"%{Cisco-AVPair}" =~ /^ssid=(.*)$/i) {
(11) Wed Aug 22 09:35:55 2018: Debug: elsif ( (Cisco-AVPair) &&
"%{Cisco-AVPair}" =~ /^ssid=(.*)$/i) -> FALSE
(11) Wed Aug 22 09:35:55 2018: Debug: [updated] = updated
(11) Wed Aug 22 09:35:55 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
(11) Wed Aug 22 09:35:55 2018: Debug: ... skipping else:
Preceding "if" was taken
(11) Wed Aug 22 09:35:55 2018: Debug: } # policy
rewrite_called_station_id = updated
(11) Wed Aug 22 09:35:55 2018: Debug: policy filter_username {
(11) Wed Aug 22 09:35:55 2018: Debug: if (&User-Name) {
(11) Wed Aug 22 09:35:55 2018: Debug: if (&User-Name) -> TRUE
(11) Wed Aug 22 09:35:55 2018: Debug: if (&User-Name) {
(11) Wed Aug 22 09:35:55 2018: Debug: if (&User-Name =~ /
/) {
(11) Wed Aug 22 09:35:55 2018: Debug: if (&User-Name =~ /
/) -> FALSE
(11) Wed Aug 22 09:35:55 2018: Debug: if (&User-Name =~
/@[^@]*@/ ) {
(11) Wed Aug 22 09:35:55 2018: Debug: if (&User-Name =~
/@[^@]*@/ ) -> FALSE
(11) Wed Aug 22 09:35:55 2018: Debug: if (&User-Name =~
/\.\./ ) {
(11) Wed Aug 22 09:35:55 2018: Debug: if (&User-Name =~
/\.\./ ) -> FALSE
(11) Wed Aug 22 09:35:55 2018: Debug: if ((&User-Name =~
/@/) && (&User-Name !~ /@(.+)\.(.+)$/)) {
(11) Wed Aug 22 09:35:55 2018: Debug: if ((&User-Name =~
/@/) && (&User-Name !~ /@(.+)\.(.+)$/)) -> FALSE
(11) Wed Aug 22 09:35:55 2018: Debug: if (&User-Name =~
/\.$/) {
(11) Wed Aug 22 09:35:55 2018: Debug: if (&User-Name =~
/\.$/) -> FALSE
(11) Wed Aug 22 09:35:55 2018: Debug: if (&User-Name =~
/@\./) {
(11) Wed Aug 22 09:35:55 2018: Debug: if (&User-Name =~
/@\./) -> FALSE
(11) Wed Aug 22 09:35:55 2018: Debug: } # if (&User-Name)
= updated
(11) Wed Aug 22 09:35:55 2018: Debug: } # policy
filter_username = updated
(11) Wed Aug 22 09:35:55 2018: Debug: policy filter_password {
(11) Wed Aug 22 09:35:55 2018: Debug: if (&User-Password &&
(&User-Password != "%{string:User-Password}")) {
(11) Wed Aug 22 09:35:55 2018: Debug: EXPAND %{string:User-Password}
(11) Wed Aug 22 09:35:55 2018: Debug: --> 00:02:09:00:01:00
(11) Wed Aug 22 09:35:55 2018: Debug: if (&User-Password &&
(&User-Password != "%{string:User-Password}")) -> FALSE
(11) Wed Aug 22 09:35:55 2018: Debug: } # policy
filter_password = updated
(11) Wed Aug 22 09:35:55 2018: Debug: [preprocess] = ok
(11) Wed Aug 22 09:35:55 2018: Debug: suffix: Checking for suffix
after "@"
(11) Wed Aug 22 09:35:55 2018: Debug: suffix: No '@' in User-Name
= "00:02:09:00:01:00", skipping NULL due to config.
(11) Wed Aug 22 09:35:55 2018: Debug: [suffix] = noop
(11) Wed Aug 22 09:35:55 2018: Debug: ntdomain: Checking for
prefix before "\"
(11) Wed Aug 22 09:35:55 2018: Debug: ntdomain: No '\' in
User-Name = "00:02:09:00:01:00", looking up realm NULL
(11) Wed Aug 22 09:35:55 2018: Debug: ntdomain: Found realm "null"
(11) Wed Aug 22 09:35:55 2018: Debug: ntdomain: Adding
Stripped-User-Name = "00:02:09:00:01:00"
(11) Wed Aug 22 09:35:55 2018: Debug: ntdomain: Adding Realm = "null"
(11) Wed Aug 22 09:35:55 2018: Debug: ntdomain: Authentication
realm is LOCAL
(11) Wed Aug 22 09:35:55 2018: Debug: [ntdomain] = ok
(11) Wed Aug 22 09:35:55 2018: Debug: eap: No EAP-Message, not
doing EAP
(11) Wed Aug 22 09:35:55 2018: Debug: [eap] = noop
(11) Wed Aug 22 09:35:55 2018: Debug: if ( !EAP-Message ) {
(11) Wed Aug 22 09:35:55 2018: Debug: if ( !EAP-Message ) ->
TRUE
(11) Wed Aug 22 09:35:55 2018: Debug: if ( !EAP-Message ) {
(11) Wed Aug 22 09:35:55 2018: Debug: update {
(11) Wed Aug 22 09:35:55 2018: Debug: } # update = noop
(11) Wed Aug 22 09:35:55 2018: Debug: } # if ( !EAP-Message
) = noop
(11) Wed Aug 22 09:35:55 2018: Debug: policy
packetfence-eap-mac-policy {
(11) Wed Aug 22 09:35:55 2018: Debug: if ( &EAP-Type ) {
(11) Wed Aug 22 09:35:55 2018: Debug: if ( &EAP-Type ) ->
FALSE
(11) Wed Aug 22 09:35:55 2018: Debug: [noop] = noop
(11) Wed Aug 22 09:35:55 2018: Debug: } # policy
packetfence-eap-mac-policy = noop
(11) Wed Aug 22 09:35:55 2018: WARNING: pap:
!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
(11) Wed Aug 22 09:35:55 2018: WARNING: pap: !!! Ignoring
control:User-Password. Update your !!!
(11) Wed Aug 22 09:35:55 2018: WARNING: pap: !!! configuration so
that the "known good" clear text !!!
(11) Wed Aug 22 09:35:55 2018: WARNING: pap: !!! password is in
Cleartext-Password and NOT in !!!
(11) Wed Aug 22 09:35:55 2018: WARNING: pap: !!! User-Password. !!!
(11) Wed Aug 22 09:35:55 2018: WARNING: pap:
!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
(11) Wed Aug 22 09:35:55 2018: WARNING: pap: Auth-Type already
set. Not setting to PAP
(11) Wed Aug 22 09:35:55 2018: Debug: [pap] = noop
(11) Wed Aug 22 09:35:55 2018: Debug: } # authorize = updated
(11) Wed Aug 22 09:35:55 2018: Debug: Found Auth-Type = Accept
(11) Wed Aug 22 09:35:55 2018: Debug: Auth-Type = Accept,
accepting the user
(11) Wed Aug 22 09:35:55 2018: Debug: # Executing section
post-auth from file /usr/local/pf/raddb/sites-enabled/packetfence
(11) Wed Aug 22 09:35:55 2018: Debug: post-auth {
(11) Wed Aug 22 09:35:55 2018: Debug: update {
(11) Wed Aug 22 09:35:55 2018: Debug: EXPAND
%{Packet-Src-IP-Address}
(11) Wed Aug 22 09:35:55 2018: Debug: --> 10.10.51.169
(11) Wed Aug 22 09:35:55 2018: Debug: } # update = noop
(11) Wed Aug 22 09:35:55 2018: Debug: policy
packetfence-set-tenant-id {
(11) Wed Aug 22 09:35:55 2018: Debug: if (
"%{%{control:PacketFence-Tenant-Id}:-0}" == "0") {
(11) Wed Aug 22 09:35:55 2018: Debug: EXPAND
%{%{control:PacketFence-Tenant-Id}:-0}
(11) Wed Aug 22 09:35:55 2018: Debug: --> 1
(11) Wed Aug 22 09:35:55 2018: Debug: if (
"%{%{control:PacketFence-Tenant-Id}:-0}" == "0") -> FALSE
(11) Wed Aug 22 09:35:55 2018: Debug: if (
&control:PacketFence-Tenant-Id == 0 ) {
(11) Wed Aug 22 09:35:55 2018: Debug: if (
&control:PacketFence-Tenant-Id == 0 ) -> FALSE
(11) Wed Aug 22 09:35:55 2018: Debug: } # policy
packetfence-set-tenant-id = noop
(11) Wed Aug 22 09:35:55 2018: Debug: if (! EAP-Type ||
(EAP-Type != TTLS && EAP-Type != PEAP) ) {
(11) Wed Aug 22 09:35:55 2018: Debug: if (! EAP-Type ||
(EAP-Type != TTLS && EAP-Type != PEAP) ) -> TRUE
(11) Wed Aug 22 09:35:55 2018: Debug: if (! EAP-Type ||
(EAP-Type != TTLS && EAP-Type != PEAP) ) {
(11) Wed Aug 22 09:35:55 2018: Debug: rest: Expanding URI components
(11) Wed Aug 22 09:35:55 2018: Debug: rest: EXPAND
http://127.0.0.1:7070
(11) Wed Aug 22 09:35:55 2018: Debug: rest: --> http://127.0.0.1:7070
(11) Wed Aug 22 09:35:55 2018: Debug: rest: EXPAND
//radius/rest/authorize
(11) Wed Aug 22 09:35:55 2018: Debug: rest: -->
//radius/rest/authorize
(11) Wed Aug 22 09:35:55 2018: Debug: rest: Sending HTTP POST to
"http://127.0.0.1:7070//radius/rest/authorize";
(11) Wed Aug 22 09:35:55 2018: Debug: rest: Encoding attribute
"User-Name"
(11) Wed Aug 22 09:35:55 2018: Debug: rest: Encoding attribute
"User-Password"
(11) Wed Aug 22 09:35:55 2018: Debug: rest: Encoding attribute
"NAS-IP-Address"
(11) Wed Aug 22 09:35:55 2018: Debug: rest: Encoding attribute
"NAS-Port"
(11) Wed Aug 22 09:35:55 2018: Debug: rest: Encoding attribute
"Framed-MTU"
(11) Wed Aug 22 09:35:55 2018: Debug: rest: Encoding attribute
"Called-Station-Id"
(11) Wed Aug 22 09:35:55 2018: Debug: rest: Encoding attribute
"Calling-Station-Id"
(11) Wed Aug 22 09:35:55 2018: Debug: rest: Encoding attribute
"NAS-Port-Type"
(11) Wed Aug 22 09:35:55 2018: Debug: rest: Encoding attribute
"Event-Timestamp"
(11) Wed Aug 22 09:35:55 2018: Debug: rest: Encoding attribute
"Message-Authenticator"
(11) Wed Aug 22 09:35:55 2018: Debug: rest: Encoding attribute
"Stripped-User-Name"
(11) Wed Aug 22 09:35:55 2018: Debug: rest: Encoding attribute
"Realm"
(11) Wed Aug 22 09:35:55 2018: Debug: rest: Encoding attribute
"SQL-User-Name"
(11) Wed Aug 22 09:35:55 2018: Debug: rest: Encoding attribute
"FreeRADIUS-Client-IP-Address"
(11) Wed Aug 22 09:35:55 2018: Debug: rest: Processing response
header
(11) Wed Aug 22 09:35:55 2018: Debug: rest: Status : 200 (OK)
(11) Wed Aug 22 09:35:55 2018: Debug: rest: Type : json
(application/json)
(11) Wed Aug 22 09:35:55 2018: Debug: rest: Parsing attribute
"control:PacketFence-Status"
(11) Wed Aug 22 09:35:55 2018: Debug: rest: EXPAND reg
(11) Wed Aug 22 09:35:55 2018: Debug: rest: --> reg
(11) Wed Aug 22 09:35:55 2018: Debug: rest: PacketFence-Status :=
"reg"
(11) Wed Aug 22 09:35:55 2018: Debug: rest: Parsing attribute
"control:PacketFence-Switch-Ip-Address"
(11) Wed Aug 22 09:35:55 2018: Debug: rest: EXPAND 0.0.0.0
(11) Wed Aug 22 09:35:55 2018: Debug: rest: --> 0.0.0.0
(11) Wed Aug 22 09:35:55 2018: Debug: rest:
PacketFence-Switch-Ip-Address := "0.0.0.0"
(11) Wed Aug 22 09:35:55 2018: Debug: rest: Parsing attribute
"control:PacketFence-Mac"
(11) Wed Aug 22 09:35:55 2018: Debug: rest: EXPAND 00:02:09:00:01:00
(11) Wed Aug 22 09:35:55 2018: Debug: rest: --> 00:02:09:00:01:00
(11) Wed Aug 22 09:35:55 2018: Debug: rest: PacketFence-Mac :=
"00:02:09:00:01:00"
(11) Wed Aug 22 09:35:55 2018: Debug: rest: Parsing attribute
"control:PacketFence-Switch-Mac"
(11) Wed Aug 22 09:35:55 2018: Debug: rest: EXPAND cc:37:ab:4f:b1:c1
(11) Wed Aug 22 09:35:55 2018: Debug: rest: --> cc:37:ab:4f:b1:c1
(11) Wed Aug 22 09:35:55 2018: Debug: rest:
PacketFence-Switch-Mac := "cc:37:ab:4f:b1:c1"
(11) Wed Aug 22 09:35:55 2018: Debug: rest: Parsing attribute
"control:PacketFence-IfIndex"
(11) Wed Aug 22 09:35:55 2018: Debug: rest: EXPAND 25
(11) Wed Aug 22 09:35:55 2018: Debug: rest: --> 25
(11) Wed Aug 22 09:35:55 2018: Debug: rest: PacketFence-IfIndex
:= "25"
(11) Wed Aug 22 09:35:55 2018: Debug: rest: Parsing attribute
"control:PacketFence-Request-Time"
(11) Wed Aug 22 09:35:55 2018: Debug: rest: EXPAND 1534901755
(11) Wed Aug 22 09:35:55 2018: Debug: rest: --> 1534901755
(11) Wed Aug 22 09:35:55 2018: Debug: rest:
PacketFence-Request-Time := 1534901755
(11) Wed Aug 22 09:35:55 2018: Debug: rest: Parsing attribute
"control:PacketFence-Authorization-Status"
(11) Wed Aug 22 09:35:55 2018: Debug: rest: EXPAND allow
(11) Wed Aug 22 09:35:55 2018: Debug: rest: --> allow
(11) Wed Aug 22 09:35:55 2018: Debug: rest:
PacketFence-Authorization-Status := "allow"
(11) Wed Aug 22 09:35:55 2018: Debug: rest: Parsing attribute
"control:PacketFence-AutoReg"
(11) Wed Aug 22 09:35:55 2018: Debug: rest: EXPAND 0
(11) Wed Aug 22 09:35:55 2018: Debug: rest: --> 0
(11) Wed Aug 22 09:35:55 2018: Debug: rest: PacketFence-AutoReg
:= "0"
(11) Wed Aug 22 09:35:55 2018: Debug: rest: Parsing attribute
"control:PacketFence-Connection-Type"
(11) Wed Aug 22 09:35:55 2018: Debug: rest: EXPAND WIRED_MAC_AUTH
(11) Wed Aug 22 09:35:55 2018: Debug: rest: --> WIRED_MAC_AUTH
(11) Wed Aug 22 09:35:55 2018: Debug: rest:
PacketFence-Connection-Type := "WIRED_MAC_AUTH"
(11) Wed Aug 22 09:35:55 2018: Debug: rest: Parsing attribute
"control:PacketFence-UserName"
(11) Wed Aug 22 09:35:55 2018: Debug: rest: EXPAND 00:02:09:00:01:00
(11) Wed Aug 22 09:35:55 2018: Debug: rest: --> 00:02:09:00:01:00
(11) Wed Aug 22 09:35:55 2018: Debug: rest: PacketFence-UserName
:= "00:02:09:00:01:00"
(11) Wed Aug 22 09:35:55 2018: Debug: rest: Parsing attribute
"control:PacketFence-Eap-Type"
(11) Wed Aug 22 09:35:55 2018: Debug: rest: EXPAND 0
(11) Wed Aug 22 09:35:55 2018: Debug: rest: --> 0
(11) Wed Aug 22 09:35:55 2018: Debug: rest: PacketFence-Eap-Type
:= "0"
(11) Wed Aug 22 09:35:55 2018: Debug: rest: Parsing attribute
"control:PacketFence-Switch-Id"
(11) Wed Aug 22 09:35:55 2018: Debug: rest: EXPAND cc:37:ab:4f:b1:c1
(11) Wed Aug 22 09:35:55 2018: Debug: rest: --> cc:37:ab:4f:b1:c1
(11) Wed Aug 22 09:35:55 2018: Debug: rest: PacketFence-Switch-Id
:= "cc:37:ab:4f:b1:c1"
(11) Wed Aug 22 09:35:55 2018: Debug: rest: Parsing attribute
"control:PacketFence-IsPhone"
(11) Wed Aug 22 09:35:55 2018: Debug: rest: PacketFence-IsPhone := ""
(11) Wed Aug 22 09:35:55 2018: Debug: [rest] = updated
(11) Wed Aug 22 09:35:55 2018: Debug: update {
(11) Wed Aug 22 09:35:55 2018: Debug: } # update = noop
(11) Wed Aug 22 09:35:55 2018: Debug: if
(&control:PacketFence-Authorization-Status == "deny") {
(11) Wed Aug 22 09:35:55 2018: Debug: if
(&control:PacketFence-Authorization-Status == "deny") -> FALSE
(11) Wed Aug 22 09:35:55 2018: Debug: else {
(11) Wed Aug 22 09:35:55 2018: Debug: policy
packetfence-audit-log-accept {
(11) Wed Aug 22 09:35:55 2018: Debug: if (&User-Name != "dummy") {
(11) Wed Aug 22 09:35:55 2018: Debug: if (&User-Name !=
"dummy") -> TRUE
(11) Wed Aug 22 09:35:55 2018: Debug: if (&User-Name != "dummy") {
(11) Wed Aug 22 09:35:55 2018: Debug: policy request-timing {
(11) Wed Aug 22 09:35:55 2018: Debug: if
(control:PacketFence-Request-Time != 0) {
(11) Wed Aug 22 09:35:55 2018: Debug: if
(control:PacketFence-Request-Time != 0) -> TRUE
(11) Wed Aug 22 09:35:55 2018: Debug: if
(control:PacketFence-Request-Time != 0) {
(11) Wed Aug 22 09:35:55 2018: Debug: update control {
(11) Wed Aug 22 09:35:55 2018: Debug: EXPAND %{expr:
%{control:PacketFence-Request-Time} - %{control:Tmp-Integer-0}}
(11) Wed Aug 22 09:35:55 2018: Debug: --> 0
(11) Wed Aug 22 09:35:55 2018: Debug: } # update control = noop
(11) Wed Aug 22 09:35:55 2018: Debug: } # if
(control:PacketFence-Request-Time != 0) = noop
(11) Wed Aug 22 09:35:55 2018: Debug: } # policy request-timing
= noop
(11) Wed Aug 22 09:35:55 2018: Debug: sql: EXPAND type.accept.query
(11) Wed Aug 22 09:35:55 2018: Debug: sql: --> type.accept.query
(11) Wed Aug 22 09:35:55 2018: Debug: sql: Using query template
'query'
(11) Wed Aug 22 09:35:55 2018: Debug: sql: EXPAND %{User-Name}
(11) Wed Aug 22 09:35:55 2018: Debug: sql: --> 00:02:09:00:01:00
(11) Wed Aug 22 09:35:55 2018: Debug: sql: SQL-User-Name set to
'00:02:09:00:01:00'
(11) Wed Aug 22 09:35:55 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:PacketFence-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}')
(11) Wed Aug 22 09:35:55 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:02:09:00:01:00', '',
'N/A', '00:02:09:00:01:00', '00:02:09:00:01:00', 'null',
'Radius-Access-Request', 'cc:37:ab:4f:b1:c1',
'cc:37:ab:4f:b1:c1', '0.0.0.0', '10.10.51.169',
'cc:37:ab:4f:b1:c1', '00:02:09:00:01:00', 'Ethernet', '',
'', '25', '25', 'WIRED_MAC_AUTH',
'0.0.0.0', '', 'Accept', '', 'Accept', '',
'N/A', 'reg', 'N/A', 'N/A', '0', '0',
'', '', 'User-Name =3D =2200:02:09:00:01:00=22=2C User-Password
=3D =22=2A=2A=2A=2A=2A=2A=22=2C NAS-IP-Address =3D 0.0.0.0=2C
NAS-Port =3D 25=2C Framed-MTU =3D 1500=2C Called-Station-Id =3D
=22cc:37:ab:4f:b1:c1=22=2C Calling-Station-Id =3D
=2200:02:09:00:01:00=22=2C NAS-Port-Type =3D Ethernet=2C
Event-Timestamp =3D =22Aug 22 2018 09:35:55 HKT=22=2C
Message-Authenticator =3D 0x175584cbbaa167dc3be140dc927b2079=2C
Stripped-User-Name =3D =2200:02:09:00:01:00=22=2C Realm =3D
=22null=22=2C FreeRADIUS-Client-IP-Address =3D 10.10.51.169=2C
SQL-User-Name =3D =2200:02:09:00:01:00=22','', '0', '1')
(11) Wed Aug 22 09:35:55 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, 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:02:09:00:01:00', '',
'N/A', '00:02:09:00:01:00', '00:02:09:00:01:00', 'null',
'Radius-Access-Request', 'cc:37:ab:4f:b1:c1',
'cc:37:ab:4f:b1:c1', '0.0.0.0', '10.10.51.169',
'cc:37:ab:4f:b1:c1', '00:02:09:00:01:00', 'Ethernet', '',
'', '25', '25', 'WIRED_MAC_AUTH',
'0.0.0.0', '', 'Accept', '', 'Accept', '',
'N/A', 'reg', 'N/A', 'N/A', '0', '0',
'', '', 'User-Name =3D =2200:02:09:00:01:00=22=2C User-Password
=3D =22=2A=2A=2A=2A=2A=2A=22=2C NAS-IP-Address =3D 0.0.0.0=2C
NAS-Port =3D 25=2C Framed-MTU =3D 1500=2C Called-Station-Id =3D
=22cc:37:ab:4f:b1:c1=22=2C Calling-Station-Id =3D
=2200:02:09:00:01:00=22=2C NAS-Port-Type =3D Ethernet=2C
Event-Timestamp =3D =22Aug 22 2018 09:35:55 HKT=22=2C
Message-Authenticator =3D 0x175584cbbaa167dc3be140dc927b2079=2C
Stripped-User-Name =3D =2200:02:09:00:01:00=22=2C Realm =3D
=22null=22=2C FreeRADIUS-Client-IP-Address =3D 10.10.51.169=2C
SQL-User-Name =3D =2200:02:09:00:01:00=22','', '0', '1')
(11) Wed Aug 22 09:35:55 2018: Debug: sql: SQL query returned:
success
(11) Wed Aug 22 09:35:55 2018: Debug: sql: 1 record(s) updated
(11) Wed Aug 22 09:35:55 2018: Debug: [sql] = ok
(11) Wed Aug 22 09:35:55 2018: Debug: } # if
(&User-Name != "dummy") = ok
(11) Wed Aug 22 09:35:55 2018: Debug: } # policy
packetfence-audit-log-accept = ok
(11) Wed Aug 22 09:35:55 2018: Debug: } # else = ok
(11) Wed Aug 22 09:35:55 2018: Debug: } # if (! EAP-Type ||
(EAP-Type != TTLS && EAP-Type != PEAP) ) = updated
(11) Wed Aug 22 09:35:55 2018: Debug:
attr_filter.packetfence_post_auth: EXPAND %{User-Name}
(11) Wed Aug 22 09:35:55 2018: Debug:
attr_filter.packetfence_post_auth: --> 00:02:09:00:01:00
(11) Wed Aug 22 09:35:55 2018: Debug:
attr_filter.packetfence_post_auth: Matched entry DEFAULT at line 10
(11) Wed Aug 22 09:35:55 2018: Debug:
[attr_filter.packetfence_post_auth] = updated
(11) Wed Aug 22 09:35:55 2018: Debug: linelog: EXPAND
messages.%{%{reply:Packet-Type}:-default}
(11) Wed Aug 22 09:35:55 2018: Debug: linelog: -->
messages.Access-Accept
(11) Wed Aug 22 09:35:55 2018: Debug: linelog: EXPAND
[mac:%{Calling-Station-Id}] Accepted user: %{reply:User-Name} and
returned VLAN %{reply:Tunnel-Private-Group-ID}
(11) Wed Aug 22 09:35:55 2018: Debug: linelog: -->
[mac:00:02:09:00:01:00] Accepted user: and returned VLAN
(11) Wed Aug 22 09:35:55 2018: Debug: [linelog] = ok
(11) Wed Aug 22 09:35:55 2018: Debug: } # post-auth = updated
(11) Wed Aug 22 09:35:55 2018: Debug: Sent Access-Accept Id 1
from 10.10.50.204:1812 <http://10.10.50.204:1812> to
10.10.51.169:1812 <http://10.10.51.169:1812> length 0
(11) Wed Aug 22 09:35:55 2018: Debug: Finished request
packetfence.log
Aug 22 09:35:55 packetfence auth[13550]: [mac:00:02:09:00:01:00]
Accepted user: and returned VLAN
Aug 22 09:35:55 packetfence auth[13550]: (11) Login OK:
[00:02:09:00:01:00] (from client cc:37:ab:4f:b1:c1 port 25 cli
00:02:09:00:01:00)
radius.log
Aug 22 09:35:55 packetfence packetfence_httpd.aaa:
httpd.aaa(12659) INFO: [mac:00:02:09:00:01:00] handling radius
autz request: from switch_ip => (0.0.0.0), connection_type =>
WIRED_MAC_AUTH,switch_mac => (cc:37:ab:4f:b1:c1), mac =>
[00:02:09:00:01:00], port => 25, username => "00:02:09:00:01:00"
(pf::radius::authorize)
Aug 22 09:35:55 packetfence packetfence_httpd.aaa:
httpd.aaa(12659) INFO: [mac:00:02:09:00:01:00] Instantiate
profile MAC-AUTH (pf::Connection::ProfileFactory::_from_profile)
Aug 22 09:35:55 packetfence packetfence_httpd.aaa:
httpd.aaa(12659) WARN: [mac:00:02:09:00:01:00] Use of
uninitialized value in string eq at /usr/local/pf/lib/pf/role.pm
<http://role.pm> line 731.
(pf::role::_check_bypass)
Aug 22 09:35:55 packetfence packetfence_httpd.aaa:
httpd.aaa(12659) INFO: [mac:00:02:09:00:01:00] Connection type is
WIRED_MAC_AUTH. Getting role from node_info
(pf::role::getRegisteredRole)
Aug 22 09:35:55 packetfence packetfence_httpd.aaa:
httpd.aaa(12659) WARN: [mac:00:02:09:00:01:00] Use of
uninitialized value $role in concatenation (.) or string at
/usr/local/pf/lib/pf/role.pm <http://role.pm> line 478.
(pf::role::getRegisteredRole)
Aug 22 09:35:55 packetfence packetfence_httpd.aaa:
httpd.aaa(12659) INFO: [mac:00:02:09:00:01:00] Username was NOT
defined or unable to match a role - returning node based role ''
(pf::role::getRegisteredRole)
Aug 22 09:35:55 packetfence packetfence_httpd.aaa:
httpd.aaa(12659) INFO: [mac:00:02:09:00:01:00] PID: "default",
Status: reg Returned VLAN: (undefined), Role: (undefined)
(pf::role::fetchRoleForNode)
Aug 22 09:35:55 packetfence packetfence_httpd.aaa:
httpd.aaa(12659) WARN: [mac:00:02:09:00:01:00] Use of
uninitialized value $vlanName in hash element at
/usr/local/pf/lib/pf/Switch.pm line 768.
(pf::Switch::getVlanByName)
Aug 22 09:35:55 packetfence packetfence_httpd.aaa:
httpd.aaa(12659) WARN: [mac:00:02:09:00:01:00] Use of
uninitialized value $vlanName in concatenation (.) or string at
/usr/local/pf/lib/pf/Switch.pm line 771.
(pf::Switch::getVlanByName)
Aug 22 09:35:55 packetfence packetfence_httpd.aaa:
httpd.aaa(12659) WARN: [mac:00:02:09:00:01:00] No parameter Vlan
found in conf/switches.conf for the switch cc:37:ab:4f:b1:c1
(pf::Switch::getVlanByName)
Aug 22 09:35:57 packetfence packetfence_httpd.aaa:
httpd.aaa(12659) INFO: [mac:00:02:09:00:01:00] handling radius
autz request: from switch_ip => (0.0.0.0), connection_type =>
WIRED_MAC_AUTH,switch_mac => (cc:37:ab:4f:b1:c1), mac =>
[00:02:09:00:01:00], port => 25, username => "00:02:09:00:01:00"
(pf::radius::authorize)
Aug 22 09:35:57 packetfence packetfence_httpd.aaa:
httpd.aaa(12659) INFO: [mac:00:02:09:00:01:00] handling radius
autz request: from switch_ip => (0.0.0.0), connection_type =>
WIRED_MAC_AUTH,switch_mac => (cc:37:ab:4f:b1:c1), mac =>
[00:02:09:00:01:00], port => 25, username => "00:02:09:00:01:00"
(pf::radius::authorize)
Aug 22 09:35:57 packetfence packetfence_httpd.aaa:
httpd.aaa(12659) INFO: [mac:00:02:09:00:01:00] Instantiate
profile MAC-AUTH (pf::Connection::ProfileFactory::_from_profile)
Aug 22 09:35:57 packetfence packetfence_httpd.aaa:
httpd.aaa(12659) INFO: [mac:00:02:09:00:01:00] Instantiate
profile MAC-AUTH (pf::Connection::ProfileFactory::_from_profile)
Aug 22 09:35:57 packetfence packetfence_httpd.aaa:
httpd.aaa(12659) WARN: [mac:00:02:09:00:01:00] Use of
uninitialized value in string eq at /usr/local/pf/lib/pf/role.pm
<http://role.pm> line 731.
(pf::role::_check_bypass)
--
Amjad Ali
------------------------------------------------------------------------------
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
[email protected]
<mailto:[email protected]>
https://lists.sourceforge.net/lists/listinfo/packetfence-users
