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 to 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 to 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 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 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 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]
https://lists.sourceforge.net/lists/listinfo/packetfence-users
