Menu
▾
▴
Re: [PacketFence-users] Can't link PacketFence with AD Server.
|
From: Durand f. <fd...@in...> - 2019-02-06 23:26:36
|
Hello Adrian,
your issue looks to be because you have 2 Calling-Station-Id attributes
in the request.
(33) Wed Feb 6 11:08:00 2019: Debug: Calling-Station-Id =
"4\227\366\024I\344"
(33) Wed Feb 6 11:08:00 2019: Debug: Service-Type = Framed-User
(33) Wed Feb 6 11:08:00 2019: Debug: Framed-MTU = 1500
(33) Wed Feb 6 11:08:00 2019: Debug: Calling-Station-Id =
"34-97-f6-14-49-e4"
Check the switch config to see if there a configuration parameter that
add it.
Also you will be able to remove it with the freeradius configuration
(raddb/sites-enable/packetfence)
Regards
Fabrice
Le 19-02-06 à 05 h 16, Adrian Dessaigne via PacketFence-users a écrit :
> Hello Fabrice,
>
> Yes, it's only for 802.1x.
>
> Below is the result of the radius debug. But in case, here a pastbin of the debug : pastebin com/LXHCHVwt
>
> (31) Wed Feb 6 11:07:45 2019: Debug: Received Status-Server Id 47 from 127.0.0.1:47397 to 127.0.0.1:18121 length 50
> (31) Wed Feb 6 11:07:45 2019: Debug: Message-Authenticator = 0xee2fd3b5c0c61bbfe07b64710674a8b4
> (31) Wed Feb 6 11:07:45 2019: Debug: FreeRADIUS-Statistics-Type = 15
> (31) Wed Feb 6 11:07:45 2019: Debug: # Executing group from file /usr/local/pf/raddb/sites-enabled/status
> (31) Wed Feb 6 11:07:45 2019: Debug: Autz-Type Status-Server {
> (31) Wed Feb 6 11:07:45 2019: Debug: [ok] = ok
> (31) Wed Feb 6 11:07:45 2019: Debug: } # Autz-Type Status-Server = ok
> (31) Wed Feb 6 11:07:45 2019: Debug: Sent Access-Accept Id 47 from 127.0.0.1:18121 to 127.0.0.1:47397 length 0
> (31) Wed Feb 6 11:07:45 2019: Debug: FreeRADIUS-Total-Access-Requests = 32
> (31) Wed Feb 6 11:07:45 2019: Debug: FreeRADIUS-Total-Access-Accepts = 0
> (31) Wed Feb 6 11:07:45 2019: Debug: FreeRADIUS-Total-Access-Rejects = 1
> (31) Wed Feb 6 11:07:45 2019: Debug: FreeRADIUS-Total-Access-Challenges = 9
> (31) Wed Feb 6 11:07:45 2019: Debug: FreeRADIUS-Total-Auth-Responses = 10
> (31) Wed Feb 6 11:07:45 2019: Debug: FreeRADIUS-Total-Auth-Duplicate-Requests = 0
> (31) Wed Feb 6 11:07:45 2019: Debug: FreeRADIUS-Total-Auth-Malformed-Requests = 0
> (31) Wed Feb 6 11:07:45 2019: Debug: FreeRADIUS-Total-Auth-Invalid-Requests = 0
> (31) Wed Feb 6 11:07:45 2019: Debug: FreeRADIUS-Total-Auth-Dropped-Requests = 0
> (31) Wed Feb 6 11:07:45 2019: Debug: FreeRADIUS-Total-Auth-Unknown-Types = 0
> (31) Wed Feb 6 11:07:45 2019: Debug: FreeRADIUS-Total-Accounting-Requests = 0
> (31) Wed Feb 6 11:07:45 2019: Debug: FreeRADIUS-Total-Accounting-Responses = 0
> (31) Wed Feb 6 11:07:45 2019: Debug: FreeRADIUS-Total-Acct-Duplicate-Requests = 0
> (31) Wed Feb 6 11:07:45 2019: Debug: FreeRADIUS-Total-Acct-Malformed-Requests = 0
> (31) Wed Feb 6 11:07:45 2019: Debug: FreeRADIUS-Total-Acct-Invalid-Requests = 0
> (31) Wed Feb 6 11:07:45 2019: Debug: FreeRADIUS-Total-Acct-Dropped-Requests = 0
> (31) Wed Feb 6 11:07:45 2019: Debug: FreeRADIUS-Total-Acct-Unknown-Types = 0
> (31) Wed Feb 6 11:07:45 2019: Debug: FreeRADIUS-Total-Proxy-Access-Requests = 0
> (31) Wed Feb 6 11:07:45 2019: Debug: FreeRADIUS-Total-Proxy-Access-Accepts = 0
> (31) Wed Feb 6 11:07:45 2019: Debug: FreeRADIUS-Total-Proxy-Access-Rejects = 0
> (31) Wed Feb 6 11:07:45 2019: Debug: FreeRADIUS-Total-Proxy-Access-Challenges = 0
> (31) Wed Feb 6 11:07:45 2019: Debug: FreeRADIUS-Total-Proxy-Auth-Responses = 0
> (31) Wed Feb 6 11:07:45 2019: Debug: FreeRADIUS-Total-Proxy-Auth-Duplicate-Requests = 0
> (31) Wed Feb 6 11:07:45 2019: Debug: FreeRADIUS-Total-Proxy-Auth-Malformed-Requests = 0
> (31) Wed Feb 6 11:07:45 2019: Debug: FreeRADIUS-Total-Proxy-Auth-Invalid-Requests = 0
> (31) Wed Feb 6 11:07:45 2019: Debug: FreeRADIUS-Total-Proxy-Auth-Dropped-Requests = 0
> (31) Wed Feb 6 11:07:45 2019: Debug: FreeRADIUS-Total-Proxy-Auth-Unknown-Types = 0
> (31) Wed Feb 6 11:07:45 2019: Debug: FreeRADIUS-Total-Proxy-Accounting-Requests = 0
> (31) Wed Feb 6 11:07:45 2019: Debug: FreeRADIUS-Total-Proxy-Accounting-Responses = 0
> (31) Wed Feb 6 11:07:45 2019: Debug: FreeRADIUS-Total-Proxy-Acct-Duplicate-Requests = 0
> (31) Wed Feb 6 11:07:45 2019: Debug: FreeRADIUS-Total-Proxy-Acct-Malformed-Requests = 0
> (31) Wed Feb 6 11:07:45 2019: Debug: FreeRADIUS-Total-Proxy-Acct-Invalid-Requests = 0
> (31) Wed Feb 6 11:07:45 2019: Debug: FreeRADIUS-Total-Proxy-Acct-Dropped-Requests = 0
> (31) Wed Feb 6 11:07:45 2019: Debug: FreeRADIUS-Total-Proxy-Acct-Unknown-Types = 0
> (31) Wed Feb 6 11:07:45 2019: Debug: Finished request
> (31) Wed Feb 6 11:07:50 2019: Debug: Cleaning up request packet ID 47 with timestamp +316
> (32) Wed Feb 6 11:08:00 2019: Debug: Received Status-Server Id 108 from 127.0.0.1:59381 to 127.0.0.1:18121 length 50
> (32) Wed Feb 6 11:08:00 2019: Debug: Message-Authenticator = 0xdfa3d9e1387b29953ed61b9e8299eec9
> (32) Wed Feb 6 11:08:00 2019: Debug: FreeRADIUS-Statistics-Type = 15
> (32) Wed Feb 6 11:08:00 2019: Debug: # Executing group from file /usr/local/pf/raddb/sites-enabled/status
> (32) Wed Feb 6 11:08:00 2019: Debug: Autz-Type Status-Server {
> (32) Wed Feb 6 11:08:00 2019: Debug: [ok] = ok
> (32) Wed Feb 6 11:08:00 2019: Debug: } # Autz-Type Status-Server = ok
> (32) Wed Feb 6 11:08:00 2019: Debug: Sent Access-Accept Id 108 from 127.0.0.1:18121 to 127.0.0.1:59381 length 0
> (32) Wed Feb 6 11:08:00 2019: Debug: FreeRADIUS-Total-Access-Requests = 33
> (32) Wed Feb 6 11:08:00 2019: Debug: FreeRADIUS-Total-Access-Accepts = 0
> (32) Wed Feb 6 11:08:00 2019: Debug: FreeRADIUS-Total-Access-Rejects = 1
> (32) Wed Feb 6 11:08:00 2019: Debug: FreeRADIUS-Total-Access-Challenges = 9
> (32) Wed Feb 6 11:08:00 2019: Debug: FreeRADIUS-Total-Auth-Responses = 10
> (32) Wed Feb 6 11:08:00 2019: Debug: FreeRADIUS-Total-Auth-Duplicate-Requests = 0
> (32) Wed Feb 6 11:08:00 2019: Debug: FreeRADIUS-Total-Auth-Malformed-Requests = 0
> (32) Wed Feb 6 11:08:00 2019: Debug: FreeRADIUS-Total-Auth-Invalid-Requests = 0
> (32) Wed Feb 6 11:08:00 2019: Debug: FreeRADIUS-Total-Auth-Dropped-Requests = 0
> (32) Wed Feb 6 11:08:00 2019: Debug: FreeRADIUS-Total-Auth-Unknown-Types = 0
> (32) Wed Feb 6 11:08:00 2019: Debug: FreeRADIUS-Total-Accounting-Requests = 0
> (32) Wed Feb 6 11:08:00 2019: Debug: FreeRADIUS-Total-Accounting-Responses = 0
> (32) Wed Feb 6 11:08:00 2019: Debug: FreeRADIUS-Total-Acct-Duplicate-Requests = 0
> (32) Wed Feb 6 11:08:00 2019: Debug: FreeRADIUS-Total-Acct-Malformed-Requests = 0
> (32) Wed Feb 6 11:08:00 2019: Debug: FreeRADIUS-Total-Acct-Invalid-Requests = 0
> (32) Wed Feb 6 11:08:00 2019: Debug: FreeRADIUS-Total-Acct-Dropped-Requests = 0
> (32) Wed Feb 6 11:08:00 2019: Debug: FreeRADIUS-Total-Acct-Unknown-Types = 0
> (32) Wed Feb 6 11:08:00 2019: Debug: FreeRADIUS-Total-Proxy-Access-Requests = 0
> (32) Wed Feb 6 11:08:00 2019: Debug: FreeRADIUS-Total-Proxy-Access-Accepts = 0
> (32) Wed Feb 6 11:08:00 2019: Debug: FreeRADIUS-Total-Proxy-Access-Rejects = 0
> (32) Wed Feb 6 11:08:00 2019: Debug: FreeRADIUS-Total-Proxy-Access-Challenges = 0
> (32) Wed Feb 6 11:08:00 2019: Debug: FreeRADIUS-Total-Proxy-Auth-Responses = 0
> (32) Wed Feb 6 11:08:00 2019: Debug: FreeRADIUS-Total-Proxy-Auth-Duplicate-Requests = 0
> (32) Wed Feb 6 11:08:00 2019: Debug: FreeRADIUS-Total-Proxy-Auth-Malformed-Requests = 0
> (32) Wed Feb 6 11:08:00 2019: Debug: FreeRADIUS-Total-Proxy-Auth-Invalid-Requests = 0
> (32) Wed Feb 6 11:08:00 2019: Debug: FreeRADIUS-Total-Proxy-Auth-Dropped-Requests = 0
> (32) Wed Feb 6 11:08:00 2019: Debug: FreeRADIUS-Total-Proxy-Auth-Unknown-Types = 0
> (32) Wed Feb 6 11:08:00 2019: Debug: FreeRADIUS-Total-Proxy-Accounting-Requests = 0
> (32) Wed Feb 6 11:08:00 2019: Debug: FreeRADIUS-Total-Proxy-Accounting-Responses = 0
> (32) Wed Feb 6 11:08:00 2019: Debug: FreeRADIUS-Total-Proxy-Acct-Duplicate-Requests = 0
> (32) Wed Feb 6 11:08:00 2019: Debug: FreeRADIUS-Total-Proxy-Acct-Malformed-Requests = 0
> (32) Wed Feb 6 11:08:00 2019: Debug: FreeRADIUS-Total-Proxy-Acct-Invalid-Requests = 0
> (32) Wed Feb 6 11:08:00 2019: Debug: FreeRADIUS-Total-Proxy-Acct-Dropped-Requests = 0
> (32) Wed Feb 6 11:08:00 2019: Debug: FreeRADIUS-Total-Proxy-Acct-Unknown-Types = 0
> (32) Wed Feb 6 11:08:00 2019: Debug: Finished request
> (33) Wed Feb 6 11:08:00 2019: Debug: Received Access-Request Id 11 from 192.168.1.201:1812 to 192.168.1.112:1812 length 136
> (33) Wed Feb 6 11:08:00 2019: Debug: NAS-IP-Address = 192.168.1.201
> (33) Wed Feb 6 11:08:00 2019: Debug: Cisco-NAS-Port = "FastEthernet0/17"
> (33) Wed Feb 6 11:08:00 2019: Debug: NAS-Port-Type = Async
> (33) Wed Feb 6 11:08:00 2019: Debug: User-Name = "PFAdmin"
> (33) Wed Feb 6 11:08:00 2019: Debug: Calling-Station-Id = "4\227\366\024I\344"
> (33) Wed Feb 6 11:08:00 2019: Debug: Service-Type = Framed-User
> (33) Wed Feb 6 11:08:00 2019: Debug: Framed-MTU = 1500
> (33) Wed Feb 6 11:08:00 2019: Debug: Calling-Station-Id = "34-97-f6-14-49-e4"
> (33) Wed Feb 6 11:08:00 2019: Debug: EAP-Message = 0x0200000c01504641646d696e
> (33) Wed Feb 6 11:08:00 2019: Debug: Message-Authenticator = 0xa1556616da106053da08d3ef6084a98f
> (33) Wed Feb 6 11:08:00 2019: Debug: # Executing section authorize from file /usr/local/pf/raddb/sites-enabled/packetfence
> (33) Wed Feb 6 11:08:00 2019: Debug: authorize {
> (33) Wed Feb 6 11:08:00 2019: Debug: update {
> (33) Wed Feb 6 11:08:00 2019: Debug: EXPAND %{Packet-Src-IP-Address}
> (33) Wed Feb 6 11:08:00 2019: Debug: --> 192.168.1.201
> (33) Wed Feb 6 11:08:00 2019: Debug: EXPAND %l
> (33) Wed Feb 6 11:08:00 2019: Debug: --> 1549447680
> (33) Wed Feb 6 11:08:00 2019: Debug: EXPAND %{Calling-Station-ID} %{User-Name}
> (33) Wed Feb 6 11:08:00 2019: Debug: --> 4\227\366\024I\344 PFAdmin
> (33) Wed Feb 6 11:08:00 2019: Debug: } # update = noop
> (33) Wed Feb 6 11:08:00 2019: Debug: policy packetfence-set-tenant-id {
> (33) Wed Feb 6 11:08:00 2019: Debug: if ( "%{%{control:PacketFence-Tenant-Id}:-0}" == "0") {
> (33) Wed Feb 6 11:08:00 2019: Debug: EXPAND %{%{control:PacketFence-Tenant-Id}:-0}
> (33) Wed Feb 6 11:08:00 2019: Debug: --> 0
> (33) Wed Feb 6 11:08:00 2019: Debug: if ( "%{%{control:PacketFence-Tenant-Id}:-0}" == "0") -> TRUE
> (33) Wed Feb 6 11:08:00 2019: Debug: if ( "%{%{control:PacketFence-Tenant-Id}:-0}" == "0") {
> (33) Wed Feb 6 11:08:00 2019: Debug: update control {
> (33) Wed Feb 6 11:08:00 2019: Debug: EXPAND %{User-Name}
> (33) Wed Feb 6 11:08:00 2019: Debug: --> PFAdmin
> (33) Wed Feb 6 11:08:00 2019: Debug: SQL-User-Name set to 'PFAdmin'
> (33) Wed Feb 6 11:08:00 2019: Debug: Executing select query: SELECT IFNULL((SELECT tenant_id FROM radius_nas WHERE nasname = '192.168.1.201'), 0)
> (33) Wed Feb 6 11:08:00 2019: Debug: EXPAND %{sql: SELECT IFNULL((SELECT tenant_id FROM radius_nas WHERE nasname = '%{Packet-Src-IP-Address}'), 0)}
> (33) Wed Feb 6 11:08:00 2019: Debug: --> 1
> (33) Wed Feb 6 11:08:00 2019: Debug: } # update control = noop
> (33) Wed Feb 6 11:08:00 2019: Debug: } # if ( "%{%{control:PacketFence-Tenant-Id}:-0}" == "0") = noop
> (33) Wed Feb 6 11:08:00 2019: Debug: if ( &control:PacketFence-Tenant-Id == 0 ) {
> (33) Wed Feb 6 11:08:00 2019: Debug: if ( &control:PacketFence-Tenant-Id == 0 ) -> FALSE
> (33) Wed Feb 6 11:08:00 2019: Debug: } # policy packetfence-set-tenant-id = noop
> (33) Wed Feb 6 11:08:00 2019: Debug: policy rewrite_calling_station_id {
> (33) Wed Feb 6 11:08:00 2019: 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)) {
> (33) Wed Feb 6 11:08:00 2019: 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)) -> FALSE
> (33) Wed Feb 6 11:08:00 2019: Debug: else {
> (33) Wed Feb 6 11:08:00 2019: Debug: [noop] = noop
> (33) Wed Feb 6 11:08:00 2019: Debug: } # else = noop
> (33) Wed Feb 6 11:08:00 2019: Debug: } # policy rewrite_calling_station_id = noop
> (33) Wed Feb 6 11:08:00 2019: Debug: policy rewrite_called_station_id {
> (33) Wed Feb 6 11:08:00 2019: 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)) {
> (33) Wed Feb 6 11:08:00 2019: 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)) -> FALSE
> (33) Wed Feb 6 11:08:00 2019: Debug: else {
> (33) Wed Feb 6 11:08:00 2019: Debug: [noop] = noop
> (33) Wed Feb 6 11:08:00 2019: Debug: } # else = noop
> (33) Wed Feb 6 11:08:00 2019: Debug: } # policy rewrite_called_station_id = noop
> (33) Wed Feb 6 11:08:00 2019: Debug: policy filter_username {
> (33) Wed Feb 6 11:08:00 2019: Debug: if (&User-Name) {
> (33) Wed Feb 6 11:08:00 2019: Debug: if (&User-Name) -> TRUE
> (33) Wed Feb 6 11:08:00 2019: Debug: if (&User-Name) {
> (33) Wed Feb 6 11:08:00 2019: Debug: if (&User-Name =~ / /) {
> (33) Wed Feb 6 11:08:00 2019: Debug: if (&User-Name =~ / /) -> FALSE
> (33) Wed Feb 6 11:08:00 2019: Debug: if (&User-Name =~ /@[^@]*@/ ) {
> (33) Wed Feb 6 11:08:00 2019: Debug: if (&User-Name =~ /@[^@]*@/ ) -> FALSE
> (33) Wed Feb 6 11:08:00 2019: Debug: if (&User-Name =~ /\.\./ ) {
> (33) Wed Feb 6 11:08:00 2019: Debug: if (&User-Name =~ /\.\./ ) -> FALSE
> (33) Wed Feb 6 11:08:00 2019: Debug: if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) {
> (33) Wed Feb 6 11:08:00 2019: Debug: if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) -> FALSE
> (33) Wed Feb 6 11:08:00 2019: Debug: if (&User-Name =~ /\.$/) {
> (33) Wed Feb 6 11:08:00 2019: Debug: if (&User-Name =~ /\.$/) -> FALSE
> (33) Wed Feb 6 11:08:00 2019: Debug: if (&User-Name =~ /@\./) {
> (33) Wed Feb 6 11:08:00 2019: Debug: if (&User-Name =~ /@\./) -> FALSE
> (33) Wed Feb 6 11:08:00 2019: Debug: } # if (&User-Name) = noop
> (33) Wed Feb 6 11:08:00 2019: Debug: } # policy filter_username = noop
> (33) Wed Feb 6 11:08:00 2019: Debug: policy filter_password {
> (33) Wed Feb 6 11:08:00 2019: Debug: if (&User-Password && (&User-Password != "%{string:User-Password}")) {
> (33) Wed Feb 6 11:08:00 2019: Debug: if (&User-Password && (&User-Password != "%{string:User-Password}")) -> FALSE
> (33) Wed Feb 6 11:08:00 2019: Debug: } # policy filter_password = noop
> (33) Wed Feb 6 11:08:00 2019: Debug: [preprocess] = ok
> (33) Wed Feb 6 11:08:00 2019: Debug: suffix: Checking for suffix after "@"
> (33) Wed Feb 6 11:08:00 2019: Debug: suffix: No '@' in User-Name = "PFAdmin", skipping NULL due to config.
> (33) Wed Feb 6 11:08:00 2019: Debug: [suffix] = noop
> (33) Wed Feb 6 11:08:00 2019: Debug: ntdomain: Checking for prefix before "\"
> (33) Wed Feb 6 11:08:00 2019: Debug: ntdomain: No '\' in User-Name = "PFAdmin", looking up realm NULL
> (33) Wed Feb 6 11:08:00 2019: Debug: ntdomain: Found realm "null"
> (33) Wed Feb 6 11:08:00 2019: Debug: ntdomain: Adding Stripped-User-Name = "PFAdmin"
> (33) Wed Feb 6 11:08:00 2019: Debug: ntdomain: Adding Realm = "null"
> (33) Wed Feb 6 11:08:00 2019: Debug: ntdomain: Authentication realm is LOCAL
> (33) Wed Feb 6 11:08:00 2019: Debug: [ntdomain] = ok
> (33) Wed Feb 6 11:08:00 2019: Debug: eap: Peer sent EAP Response (code 2) ID 0 length 12
> (33) Wed Feb 6 11:08:00 2019: Debug: eap: EAP-Identity reply, returning 'ok' so we can short-circuit the rest of authorize
> (33) Wed Feb 6 11:08:00 2019: Debug: [eap] = ok
> (33) Wed Feb 6 11:08:00 2019: Debug: } # authorize = ok
> (33) Wed Feb 6 11:08:00 2019: Debug: Found Auth-Type = eap
> (33) Wed Feb 6 11:08:00 2019: Debug: # Executing group from file /usr/local/pf/raddb/sites-enabled/packetfence
> (33) Wed Feb 6 11:08:00 2019: Debug: authenticate {
> (33) Wed Feb 6 11:08:00 2019: Debug: eap: Peer sent packet with method EAP Identity (1)
> (33) Wed Feb 6 11:08:00 2019: Debug: eap: Calling submodule eap_peap to process data
> (33) Wed Feb 6 11:08:00 2019: Debug: eap_peap: Initiating new TLS session
> (33) Wed Feb 6 11:08:00 2019: Debug: eap_peap: [eaptls start] = request
> (33) Wed Feb 6 11:08:00 2019: Debug: eap: Sending EAP Request (code 1) ID 1 length 6
> (33) Wed Feb 6 11:08:00 2019: Debug: eap: EAP session adding &reply:State = 0x6107f6c76106efb3
> (33) Wed Feb 6 11:08:00 2019: Debug: [eap] = handled
> (33) Wed Feb 6 11:08:00 2019: Debug: } # authenticate = handled
> (33) Wed Feb 6 11:08:00 2019: Debug: Using Post-Auth-Type Challenge
> (33) Wed Feb 6 11:08:00 2019: Debug: Post-Auth-Type sub-section not found. Ignoring.
> (33) Wed Feb 6 11:08:00 2019: Debug: # Executing group from file /usr/local/pf/raddb/sites-enabled/packetfence
> (33) Wed Feb 6 11:08:00 2019: Debug: Sent Access-Challenge Id 11 from 192.168.1.112:1812 to 192.168.1.201:1812 length 0
> (33) Wed Feb 6 11:08:00 2019: Debug: EAP-Message = 0x010100061920
> (33) Wed Feb 6 11:08:00 2019: Debug: Message-Authenticator = 0x00000000000000000000000000000000
> (33) Wed Feb 6 11:08:00 2019: Debug: State = 0x6107f6c76106efb330f8eb3fa2cd242e
> (33) Wed Feb 6 11:08:00 2019: Debug: Finished request
> (34) Wed Feb 6 11:08:00 2019: Debug: Received Access-Request Id 12 from 192.168.1.201:1812 to 192.168.1.112:1812 length 308
> (34) Wed Feb 6 11:08:00 2019: Debug: NAS-IP-Address = 192.168.1.201
> (34) Wed Feb 6 11:08:00 2019: Debug: Cisco-NAS-Port = "FastEthernet0/17"
> (34) Wed Feb 6 11:08:00 2019: Debug: NAS-Port-Type = Async
> (34) Wed Feb 6 11:08:00 2019: Debug: User-Name = "PFAdmin"
> (34) Wed Feb 6 11:08:00 2019: Debug: Calling-Station-Id = "4\227\366\024I\344"
> (34) Wed Feb 6 11:08:00 2019: Debug: Service-Type = Framed-User
> (34) Wed Feb 6 11:08:00 2019: Debug: Framed-MTU = 1500
> (34) Wed Feb 6 11:08:00 2019: Debug: Calling-Station-Id = "34-97-f6-14-49-e4"
> (34) Wed Feb 6 11:08:00 2019: Debug: State = 0x6107f6c76106efb330f8eb3fa2cd242e
> (34) Wed Feb 6 11:08:00 2019: Debug: EAP-Message = 0x020100a619800000009c16030300970100009303035c5ab201048e7e41774a58339bdab85702a7956033f4064b552a20d7212854ff00002ac02cc02bc030c02f009f009ec024c023c028c027c00ac009c014c013009d009c003d003c0035002f000a01000040000500050100000000000a00080006001d
> (34) Wed Feb 6 11:08:00 2019: Debug: Message-Authenticator = 0x4a124e8f4da7001c2938623f4cc2eb1a
> (34) Wed Feb 6 11:08:00 2019: Debug: session-state: No cached attributes
> (34) Wed Feb 6 11:08:00 2019: Debug: # Executing section authorize from file /usr/local/pf/raddb/sites-enabled/packetfence
> (34) Wed Feb 6 11:08:00 2019: Debug: authorize {
> (34) Wed Feb 6 11:08:00 2019: Debug: update {
> (34) Wed Feb 6 11:08:00 2019: Debug: EXPAND %{Packet-Src-IP-Address}
> (34) Wed Feb 6 11:08:00 2019: Debug: --> 192.168.1.201
> (34) Wed Feb 6 11:08:00 2019: Debug: EXPAND %l
> (34) Wed Feb 6 11:08:00 2019: Debug: --> 1549447680
> (34) Wed Feb 6 11:08:00 2019: Debug: EXPAND %{Calling-Station-ID} %{User-Name}
> (34) Wed Feb 6 11:08:00 2019: Debug: --> 4\227\366\024I\344 PFAdmin
> (34) Wed Feb 6 11:08:00 2019: Debug: } # update = noop
> (34) Wed Feb 6 11:08:00 2019: Debug: policy packetfence-set-tenant-id {
> (34) Wed Feb 6 11:08:00 2019: Debug: if ( "%{%{control:PacketFence-Tenant-Id}:-0}" == "0") {
> (34) Wed Feb 6 11:08:00 2019: Debug: EXPAND %{%{control:PacketFence-Tenant-Id}:-0}
> (34) Wed Feb 6 11:08:00 2019: Debug: --> 0
> (34) Wed Feb 6 11:08:00 2019: Debug: if ( "%{%{control:PacketFence-Tenant-Id}:-0}" == "0") -> TRUE
> (34) Wed Feb 6 11:08:00 2019: Debug: if ( "%{%{control:PacketFence-Tenant-Id}:-0}" == "0") {
> (34) Wed Feb 6 11:08:00 2019: Debug: update control {
> (34) Wed Feb 6 11:08:00 2019: Debug: EXPAND %{User-Name}
> (34) Wed Feb 6 11:08:00 2019: Debug: --> PFAdmin
> (34) Wed Feb 6 11:08:00 2019: Debug: SQL-User-Name set to 'PFAdmin'
> (34) Wed Feb 6 11:08:00 2019: Debug: Executing select query: SELECT IFNULL((SELECT tenant_id FROM radius_nas WHERE nasname = '192.168.1.201'), 0)
> (34) Wed Feb 6 11:08:00 2019: Debug: EXPAND %{sql: SELECT IFNULL((SELECT tenant_id FROM radius_nas WHERE nasname = '%{Packet-Src-IP-Address}'), 0)}
> (34) Wed Feb 6 11:08:00 2019: Debug: --> 1
> (34) Wed Feb 6 11:08:00 2019: Debug: } # update control = noop
> (34) Wed Feb 6 11:08:00 2019: Debug: } # if ( "%{%{control:PacketFence-Tenant-Id}:-0}" == "0") = noop
> (34) Wed Feb 6 11:08:00 2019: Debug: if ( &control:PacketFence-Tenant-Id == 0 ) {
> (34) Wed Feb 6 11:08:00 2019: Debug: if ( &control:PacketFence-Tenant-Id == 0 ) -> FALSE
> (34) Wed Feb 6 11:08:00 2019: Debug: } # policy packetfence-set-tenant-id = noop
> (34) Wed Feb 6 11:08:00 2019: Debug: policy rewrite_calling_station_id {
> (34) Wed Feb 6 11:08:00 2019: 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)) {
> (34) Wed Feb 6 11:08:00 2019: 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)) -> FALSE
> (34) Wed Feb 6 11:08:00 2019: Debug: else {
> (34) Wed Feb 6 11:08:00 2019: Debug: [noop] = noop
> (34) Wed Feb 6 11:08:00 2019: Debug: } # else = noop
> (34) Wed Feb 6 11:08:00 2019: Debug: } # policy rewrite_calling_station_id = noop
> (34) Wed Feb 6 11:08:00 2019: Debug: policy rewrite_called_station_id {
> (34) Wed Feb 6 11:08:00 2019: 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)) {
> (34) Wed Feb 6 11:08:00 2019: 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)) -> FALSE
> (34) Wed Feb 6 11:08:00 2019: Debug: else {
> (34) Wed Feb 6 11:08:00 2019: Debug: [noop] = noop
> (34) Wed Feb 6 11:08:00 2019: Debug: } # else = noop
> (34) Wed Feb 6 11:08:00 2019: Debug: } # policy rewrite_called_station_id = noop
> (34) Wed Feb 6 11:08:00 2019: Debug: policy filter_username {
> (34) Wed Feb 6 11:08:00 2019: Debug: if (&User-Name) {
> (34) Wed Feb 6 11:08:00 2019: Debug: if (&User-Name) -> TRUE
> (34) Wed Feb 6 11:08:00 2019: Debug: if (&User-Name) {
> (34) Wed Feb 6 11:08:00 2019: Debug: if (&User-Name =~ / /) {
> (34) Wed Feb 6 11:08:00 2019: Debug: if (&User-Name =~ / /) -> FALSE
> (34) Wed Feb 6 11:08:00 2019: Debug: if (&User-Name =~ /@[^@]*@/ ) {
> (34) Wed Feb 6 11:08:00 2019: Debug: if (&User-Name =~ /@[^@]*@/ ) -> FALSE
> (34) Wed Feb 6 11:08:00 2019: Debug: if (&User-Name =~ /\.\./ ) {
> (34) Wed Feb 6 11:08:00 2019: Debug: if (&User-Name =~ /\.\./ ) -> FALSE
> (34) Wed Feb 6 11:08:00 2019: Debug: if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) {
> (34) Wed Feb 6 11:08:00 2019: Debug: if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) -> FALSE
> (34) Wed Feb 6 11:08:00 2019: Debug: if (&User-Name =~ /\.$/) {
> (34) Wed Feb 6 11:08:00 2019: Debug: if (&User-Name =~ /\.$/) -> FALSE
> (34) Wed Feb 6 11:08:00 2019: Debug: if (&User-Name =~ /@\./) {
> (34) Wed Feb 6 11:08:00 2019: Debug: if (&User-Name =~ /@\./) -> FALSE
> (34) Wed Feb 6 11:08:00 2019: Debug: } # if (&User-Name) = noop
> (34) Wed Feb 6 11:08:00 2019: Debug: } # policy filter_username = noop
> (34) Wed Feb 6 11:08:00 2019: Debug: policy filter_password {
> (34) Wed Feb 6 11:08:00 2019: Debug: if (&User-Password && (&User-Password != "%{string:User-Password}")) {
> (34) Wed Feb 6 11:08:00 2019: Debug: if (&User-Password && (&User-Password != "%{string:User-Password}")) -> FALSE
> (34) Wed Feb 6 11:08:00 2019: Debug: } # policy filter_password = noop
> (34) Wed Feb 6 11:08:00 2019: Debug: [preprocess] = ok
> (34) Wed Feb 6 11:08:00 2019: Debug: suffix: Checking for suffix after "@"
> (34) Wed Feb 6 11:08:00 2019: Debug: suffix: No '@' in User-Name = "PFAdmin", skipping NULL due to config.
> (34) Wed Feb 6 11:08:00 2019: Debug: [suffix] = noop
> (34) Wed Feb 6 11:08:00 2019: Debug: ntdomain: Checking for prefix before "\"
> (34) Wed Feb 6 11:08:00 2019: Debug: ntdomain: No '\' in User-Name = "PFAdmin", looking up realm NULL
> (34) Wed Feb 6 11:08:00 2019: Debug: ntdomain: Found realm "null"
> (34) Wed Feb 6 11:08:00 2019: Debug: ntdomain: Adding Stripped-User-Name = "PFAdmin"
> (34) Wed Feb 6 11:08:00 2019: Debug: ntdomain: Adding Realm = "null"
> (34) Wed Feb 6 11:08:00 2019: Debug: ntdomain: Authentication realm is LOCAL
> (34) Wed Feb 6 11:08:00 2019: Debug: [ntdomain] = ok
> (34) Wed Feb 6 11:08:00 2019: Debug: eap: Peer sent EAP Response (code 2) ID 1 length 166
> (34) Wed Feb 6 11:08:00 2019: Debug: eap: Continuing tunnel setup
> (34) Wed Feb 6 11:08:00 2019: Debug: [eap] = ok
> (34) Wed Feb 6 11:08:00 2019: Debug: } # authorize = ok
> (34) Wed Feb 6 11:08:00 2019: Debug: Found Auth-Type = eap
> (34) Wed Feb 6 11:08:00 2019: Debug: # Executing group from file /usr/local/pf/raddb/sites-enabled/packetfence
> (34) Wed Feb 6 11:08:00 2019: Debug: authenticate {
> (34) Wed Feb 6 11:08:00 2019: Debug: eap: Expiring EAP session with state 0x6107f6c76106efb3
> (34) Wed Feb 6 11:08:00 2019: Debug: eap: Finished EAP session with state 0x6107f6c76106efb3
> (34) Wed Feb 6 11:08:00 2019: Debug: eap: Previous EAP request found for state 0x6107f6c76106efb3, released from the list
> (34) Wed Feb 6 11:08:00 2019: Debug: eap: Peer sent packet with method EAP PEAP (25)
> (34) Wed Feb 6 11:08:00 2019: Debug: eap: Calling submodule eap_peap to process data
> (34) Wed Feb 6 11:08:00 2019: Debug: eap_peap: Continuing EAP-TLS
> (34) Wed Feb 6 11:08:00 2019: Debug: eap_peap: Peer indicated complete TLS record size will be 156 bytes
> (34) Wed Feb 6 11:08:00 2019: Debug: eap_peap: Got complete TLS record (156 bytes)
> (34) Wed Feb 6 11:08:00 2019: Debug: eap_peap: [eaptls verify] = length included
> (34) Wed Feb 6 11:08:00 2019: Debug: eap_peap: (other): before/accept initialization
> (34) Wed Feb 6 11:08:00 2019: Debug: eap_peap: TLS_accept: before/accept initialization
> (34) Wed Feb 6 11:08:00 2019: Debug: eap_peap: TLS_accept: SSLv3 read client hello A
> (34) Wed Feb 6 11:08:00 2019: Debug: eap_peap: TLS_accept: SSLv3 write server hello A
> (34) Wed Feb 6 11:08:00 2019: Debug: eap_peap: TLS_accept: SSLv3 write certificate A
> (34) Wed Feb 6 11:08:00 2019: Debug: eap_peap: TLS_accept: SSLv3 write key exchange A
> (34) Wed Feb 6 11:08:00 2019: Debug: eap_peap: TLS_accept: SSLv3 write server done A
> (34) Wed Feb 6 11:08:00 2019: Debug: eap_peap: TLS_accept: SSLv3 flush data
> (34) Wed Feb 6 11:08:00 2019: Debug: eap_peap: TLS_accept: SSLv3 read client certificate A
> (34) Wed Feb 6 11:08:00 2019: Debug: eap_peap: TLS_accept: Need to read more data: SSLv3 read client key exchange A
> (34) Wed Feb 6 11:08:00 2019: Debug: eap_peap: TLS_accept: Need to read more data: SSLv3 read client key exchange A
> (34) Wed Feb 6 11:08:00 2019: Debug: eap_peap: TLS - In Handshake Phase
> (34) Wed Feb 6 11:08:00 2019: Debug: eap_peap: TLS - got 2673 bytes of data
> (34) Wed Feb 6 11:08:00 2019: Debug: eap_peap: [eaptls process] = handled
> (34) Wed Feb 6 11:08:00 2019: Debug: eap: Sending EAP Request (code 1) ID 2 length 1004
> (34) Wed Feb 6 11:08:00 2019: Debug: eap: EAP session adding &reply:State = 0x6107f6c76005efb3
> (34) Wed Feb 6 11:08:00 2019: Debug: [eap] = handled
> (34) Wed Feb 6 11:08:00 2019: Debug: } # authenticate = handled
> (34) Wed Feb 6 11:08:00 2019: Debug: Using Post-Auth-Type Challenge
> (34) Wed Feb 6 11:08:00 2019: Debug: Post-Auth-Type sub-section not found. Ignoring.
> (34) Wed Feb 6 11:08:00 2019: Debug: # Executing group from file /usr/local/pf/raddb/sites-enabled/packetfence
> (34) Wed Feb 6 11:08:00 2019: Debug: Sent Access-Challenge Id 12 from 192.168.1.112:1812 to 192.168.1.201:1812 length 0
> (34) Wed Feb 6 11:08:00 2019: Debug: EAP-Message = 0x010203ec19c000000a711603030039020000350303d25c37e9658498fba99ced0abe3cd7b8b359a5fc81c1f0c4cebd430ede088c1700c03000000dff01000100000b00040300010216030308d30b0008cf0008cc0003de308203da308202c2a003020102020101300d06092a864886f70d01010b050030
> (34) Wed Feb 6 11:08:00 2019: Debug: Message-Authenticator = 0x00000000000000000000000000000000
> (34) Wed Feb 6 11:08:00 2019: Debug: State = 0x6107f6c76005efb330f8eb3fa2cd242e
> (34) Wed Feb 6 11:08:00 2019: Debug: Finished request
> (35) Wed Feb 6 11:08:00 2019: Debug: Received Access-Request Id 13 from 192.168.1.201:1812 to 192.168.1.112:1812 length 148
> (35) Wed Feb 6 11:08:00 2019: Debug: NAS-IP-Address = 192.168.1.201
> (35) Wed Feb 6 11:08:00 2019: Debug: Cisco-NAS-Port = "FastEthernet0/17"
> (35) Wed Feb 6 11:08:00 2019: Debug: NAS-Port-Type = Async
> (35) Wed Feb 6 11:08:00 2019: Debug: User-Name = "PFAdmin"
> (35) Wed Feb 6 11:08:00 2019: Debug: Calling-Station-Id = "4\227\366\024I\344"
> (35) Wed Feb 6 11:08:00 2019: Debug: Service-Type = Framed-User
> (35) Wed Feb 6 11:08:00 2019: Debug: Framed-MTU = 1500
> (35) Wed Feb 6 11:08:00 2019: Debug: Calling-Station-Id = "34-97-f6-14-49-e4"
> (35) Wed Feb 6 11:08:00 2019: Debug: State = 0x6107f6c76005efb330f8eb3fa2cd242e
> (35) Wed Feb 6 11:08:00 2019: Debug: EAP-Message = 0x020200061900
> (35) Wed Feb 6 11:08:00 2019: Debug: Message-Authenticator = 0x55bbacc7e58f0383be508eb31b014a3d
> (35) Wed Feb 6 11:08:00 2019: Debug: session-state: No cached attributes
> (35) Wed Feb 6 11:08:00 2019: Debug: # Executing section authorize from file /usr/local/pf/raddb/sites-enabled/packetfence
> (35) Wed Feb 6 11:08:00 2019: Debug: authorize {
> (35) Wed Feb 6 11:08:00 2019: Debug: update {
> (35) Wed Feb 6 11:08:00 2019: Debug: EXPAND %{Packet-Src-IP-Address}
> (35) Wed Feb 6 11:08:00 2019: Debug: --> 192.168.1.201
> (35) Wed Feb 6 11:08:00 2019: Debug: EXPAND %l
> (35) Wed Feb 6 11:08:00 2019: Debug: --> 1549447680
> (35) Wed Feb 6 11:08:00 2019: Debug: EXPAND %{Calling-Station-ID} %{User-Name}
> (35) Wed Feb 6 11:08:00 2019: Debug: --> 4\227\366\024I\344 PFAdmin
> (35) Wed Feb 6 11:08:00 2019: Debug: } # update = noop
> (35) Wed Feb 6 11:08:00 2019: Debug: policy packetfence-set-tenant-id {
> (35) Wed Feb 6 11:08:00 2019: Debug: if ( "%{%{control:PacketFence-Tenant-Id}:-0}" == "0") {
> (35) Wed Feb 6 11:08:00 2019: Debug: EXPAND %{%{control:PacketFence-Tenant-Id}:-0}
> (35) Wed Feb 6 11:08:00 2019: Debug: --> 0
> (35) Wed Feb 6 11:08:00 2019: Debug: if ( "%{%{control:PacketFence-Tenant-Id}:-0}" == "0") -> TRUE
> (35) Wed Feb 6 11:08:00 2019: Debug: if ( "%{%{control:PacketFence-Tenant-Id}:-0}" == "0") {
> (35) Wed Feb 6 11:08:00 2019: Debug: update control {
> (35) Wed Feb 6 11:08:00 2019: Debug: EXPAND %{User-Name}
> (35) Wed Feb 6 11:08:00 2019: Debug: --> PFAdmin
> (35) Wed Feb 6 11:08:00 2019: Debug: SQL-User-Name set to 'PFAdmin'
> (35) Wed Feb 6 11:08:00 2019: Debug: Executing select query: SELECT IFNULL((SELECT tenant_id FROM radius_nas WHERE nasname = '192.168.1.201'), 0)
> (35) Wed Feb 6 11:08:00 2019: Debug: EXPAND %{sql: SELECT IFNULL((SELECT tenant_id FROM radius_nas WHERE nasname = '%{Packet-Src-IP-Address}'), 0)}
> (35) Wed Feb 6 11:08:00 2019: Debug: --> 1
> (35) Wed Feb 6 11:08:00 2019: Debug: } # update control = noop
> (35) Wed Feb 6 11:08:00 2019: Debug: } # if ( "%{%{control:PacketFence-Tenant-Id}:-0}" == "0") = noop
> (35) Wed Feb 6 11:08:00 2019: Debug: if ( &control:PacketFence-Tenant-Id == 0 ) {
> (35) Wed Feb 6 11:08:00 2019: Debug: if ( &control:PacketFence-Tenant-Id == 0 ) -> FALSE
> (35) Wed Feb 6 11:08:00 2019: Debug: } # policy packetfence-set-tenant-id = noop
> (35) Wed Feb 6 11:08:00 2019: Debug: policy rewrite_calling_station_id {
> (35) Wed Feb 6 11:08:00 2019: 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)) {
> (35) Wed Feb 6 11:08:00 2019: 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)) -> FALSE
> (35) Wed Feb 6 11:08:00 2019: Debug: else {
> (35) Wed Feb 6 11:08:00 2019: Debug: [noop] = noop
> (35) Wed Feb 6 11:08:00 2019: Debug: } # else = noop
> (35) Wed Feb 6 11:08:00 2019: Debug: } # policy rewrite_calling_station_id = noop
> (35) Wed Feb 6 11:08:00 2019: Debug: policy rewrite_called_station_id {
> (35) Wed Feb 6 11:08:00 2019: 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)) {
> (35) Wed Feb 6 11:08:00 2019: 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)) -> FALSE
> (35) Wed Feb 6 11:08:00 2019: Debug: else {
> (35) Wed Feb 6 11:08:00 2019: Debug: [noop] = noop
> (35) Wed Feb 6 11:08:00 2019: Debug: } # else = noop
> (35) Wed Feb 6 11:08:00 2019: Debug: } # policy rewrite_called_station_id = noop
> (35) Wed Feb 6 11:08:00 2019: Debug: policy filter_username {
> (35) Wed Feb 6 11:08:00 2019: Debug: if (&User-Name) {
> (35) Wed Feb 6 11:08:00 2019: Debug: if (&User-Name) -> TRUE
> (35) Wed Feb 6 11:08:00 2019: Debug: if (&User-Name) {
> (35) Wed Feb 6 11:08:00 2019: Debug: if (&User-Name =~ / /) {
> (35) Wed Feb 6 11:08:00 2019: Debug: if (&User-Name =~ / /) -> FALSE
> (35) Wed Feb 6 11:08:00 2019: Debug: if (&User-Name =~ /@[^@]*@/ ) {
> (35) Wed Feb 6 11:08:00 2019: Debug: if (&User-Name =~ /@[^@]*@/ ) -> FALSE
> (35) Wed Feb 6 11:08:00 2019: Debug: if (&User-Name =~ /\.\./ ) {
> (35) Wed Feb 6 11:08:00 2019: Debug: if (&User-Name =~ /\.\./ ) -> FALSE
> (35) Wed Feb 6 11:08:00 2019: Debug: if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) {
> (35) Wed Feb 6 11:08:00 2019: Debug: if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) -> FALSE
> (35) Wed Feb 6 11:08:00 2019: Debug: if (&User-Name =~ /\.$/) {
> (35) Wed Feb 6 11:08:00 2019: Debug: if (&User-Name =~ /\.$/) -> FALSE
> (35) Wed Feb 6 11:08:00 2019: Debug: if (&User-Name =~ /@\./) {
> (35) Wed Feb 6 11:08:00 2019: Debug: if (&User-Name =~ /@\./) -> FALSE
> (35) Wed Feb 6 11:08:00 2019: Debug: } # if (&User-Name) = noop
> (35) Wed Feb 6 11:08:00 2019: Debug: } # policy filter_username = noop
> (35) Wed Feb 6 11:08:00 2019: Debug: policy filter_password {
> (35) Wed Feb 6 11:08:00 2019: Debug: if (&User-Password && (&User-Password != "%{string:User-Password}")) {
> (35) Wed Feb 6 11:08:00 2019: Debug: if (&User-Password && (&User-Password != "%{string:User-Password}")) -> FALSE
> (35) Wed Feb 6 11:08:00 2019: Debug: } # policy filter_password = noop
> (35) Wed Feb 6 11:08:00 2019: Debug: [preprocess] = ok
> (35) Wed Feb 6 11:08:00 2019: Debug: suffix: Checking for suffix after "@"
> (35) Wed Feb 6 11:08:00 2019: Debug: suffix: No '@' in User-Name = "PFAdmin", skipping NULL due to config.
> (35) Wed Feb 6 11:08:00 2019: Debug: [suffix] = noop
> (35) Wed Feb 6 11:08:00 2019: Debug: ntdomain: Checking for prefix before "\"
> (35) Wed Feb 6 11:08:00 2019: Debug: ntdomain: No '\' in User-Name = "PFAdmin", looking up realm NULL
> (35) Wed Feb 6 11:08:00 2019: Debug: ntdomain: Found realm "null"
> (35) Wed Feb 6 11:08:00 2019: Debug: ntdomain: Adding Stripped-User-Name = "PFAdmin"
> (35) Wed Feb 6 11:08:00 2019: Debug: ntdomain: Adding Realm = "null"
> (35) Wed Feb 6 11:08:00 2019: Debug: ntdomain: Authentication realm is LOCAL
> (35) Wed Feb 6 11:08:00 2019: Debug: [ntdomain] = ok
> (35) Wed Feb 6 11:08:00 2019: Debug: eap: Peer sent EAP Response (code 2) ID 2 length 6
> (35) Wed Feb 6 11:08:00 2019: Debug: eap: Continuing tunnel setup
> (35) Wed Feb 6 11:08:00 2019: Debug: [eap] = ok
> (35) Wed Feb 6 11:08:00 2019: Debug: } # authorize = ok
> (35) Wed Feb 6 11:08:00 2019: Debug: Found Auth-Type = eap
> (35) Wed Feb 6 11:08:00 2019: Debug: # Executing group from file /usr/local/pf/raddb/sites-enabled/packetfence
> (35) Wed Feb 6 11:08:00 2019: Debug: authenticate {
> (35) Wed Feb 6 11:08:00 2019: Debug: eap: Expiring EAP session with state 0x6107f6c76005efb3
> (35) Wed Feb 6 11:08:00 2019: Debug: eap: Finished EAP session with state 0x6107f6c76005efb3
> (35) Wed Feb 6 11:08:00 2019: Debug: eap: Previous EAP request found for state 0x6107f6c76005efb3, released from the list
> (35) Wed Feb 6 11:08:00 2019: Debug: eap: Peer sent packet with method EAP PEAP (25)
> (35) Wed Feb 6 11:08:00 2019: Debug: eap: Calling submodule eap_peap to process data
> (35) Wed Feb 6 11:08:00 2019: Debug: eap_peap: Continuing EAP-TLS
> (35) Wed Feb 6 11:08:00 2019: Debug: eap_peap: Peer ACKed our handshake fragment
> (35) Wed Feb 6 11:08:00 2019: Debug: eap_peap: [eaptls verify] = request
> (35) Wed Feb 6 11:08:00 2019: Debug: eap_peap: [eaptls process] = handled
> (35) Wed Feb 6 11:08:00 2019: Debug: eap: Sending EAP Request (code 1) ID 3 length 1000
> (35) Wed Feb 6 11:08:00 2019: Debug: eap: EAP session adding &reply:State = 0x6107f6c76304efb3
> (35) Wed Feb 6 11:08:00 2019: Debug: [eap] = handled
> (35) Wed Feb 6 11:08:00 2019: Debug: } # authenticate = handled
> (35) Wed Feb 6 11:08:00 2019: Debug: Using Post-Auth-Type Challenge
> (35) Wed Feb 6 11:08:00 2019: Debug: Post-Auth-Type sub-section not found. Ignoring.
> (35) Wed Feb 6 11:08:00 2019: Debug: # Executing group from file /usr/local/pf/raddb/sites-enabled/packetfence
> (35) Wed Feb 6 11:08:00 2019: Debug: Sent Access-Challenge Id 13 from 192.168.1.112:1812 to 192.168.1.201:1812 length 0
> (35) Wed Feb 6 11:08:00 2019: Debug: EAP-Message = 0x010303e819409b4a6e4b07d7ced2ebfce7125b653994b713630a9d74769e4cbbdfaf52cf8015dabac71d60caab48b5e232ea44fafcaed36d6f771e194cacf3c84fa418d11e0e3f335ba6591c89ada50004e8308204e4308203cca003020102020900f758cc2d39024963300d06092a864886f70d01010b
> (35) Wed Feb 6 11:08:00 2019: Debug: Message-Authenticator = 0x00000000000000000000000000000000
> (35) Wed Feb 6 11:08:00 2019: Debug: State = 0x6107f6c76304efb330f8eb3fa2cd242e
> (35) Wed Feb 6 11:08:00 2019: Debug: Finished request
> (36) Wed Feb 6 11:08:00 2019: Debug: Received Access-Request Id 14 from 192.168.1.201:1812 to 192.168.1.112:1812 length 148
> (36) Wed Feb 6 11:08:00 2019: Debug: NAS-IP-Address = 192.168.1.201
> (36) Wed Feb 6 11:08:00 2019: Debug: Cisco-NAS-Port = "FastEthernet0/17"
> (36) Wed Feb 6 11:08:00 2019: Debug: NAS-Port-Type = Async
> (36) Wed Feb 6 11:08:00 2019: Debug: User-Name = "PFAdmin"
> (36) Wed Feb 6 11:08:00 2019: Debug: Calling-Station-Id = "4\227\366\024I\344"
> (36) Wed Feb 6 11:08:00 2019: Debug: Service-Type = Framed-User
> (36) Wed Feb 6 11:08:00 2019: Debug: Framed-MTU = 1500
> (36) Wed Feb 6 11:08:00 2019: Debug: Calling-Station-Id = "34-97-f6-14-49-e4"
> (36) Wed Feb 6 11:08:00 2019: Debug: State = 0x6107f6c76304efb330f8eb3fa2cd242e
> (36) Wed Feb 6 11:08:00 2019: Debug: EAP-Message = 0x020300061900
> (36) Wed Feb 6 11:08:00 2019: Debug: Message-Authenticator = 0x377888437c1806b049e1821d1c603796
> (36) Wed Feb 6 11:08:00 2019: Debug: session-state: No cached attributes
> (36) Wed Feb 6 11:08:00 2019: Debug: # Executing section authorize from file /usr/local/pf/raddb/sites-enabled/packetfence
> (36) Wed Feb 6 11:08:00 2019: Debug: authorize {
> (36) Wed Feb 6 11:08:00 2019: Debug: update {
> (36) Wed Feb 6 11:08:00 2019: Debug: EXPAND %{Packet-Src-IP-Address}
> (36) Wed Feb 6 11:08:00 2019: Debug: --> 192.168.1.201
> (36) Wed Feb 6 11:08:00 2019: Debug: EXPAND %l
> (36) Wed Feb 6 11:08:00 2019: Debug: --> 1549447680
> (36) Wed Feb 6 11:08:00 2019: Debug: EXPAND %{Calling-Station-ID} %{User-Name}
> (36) Wed Feb 6 11:08:00 2019: Debug: --> 4\227\366\024I\344 PFAdmin
> (36) Wed Feb 6 11:08:00 2019: Debug: } # update = noop
> (36) Wed Feb 6 11:08:00 2019: Debug: policy packetfence-set-tenant-id {
> (36) Wed Feb 6 11:08:00 2019: Debug: if ( "%{%{control:PacketFence-Tenant-Id}:-0}" == "0") {
> (36) Wed Feb 6 11:08:00 2019: Debug: EXPAND %{%{control:PacketFence-Tenant-Id}:-0}
> (36) Wed Feb 6 11:08:00 2019: Debug: --> 0
> (36) Wed Feb 6 11:08:00 2019: Debug: if ( "%{%{control:PacketFence-Tenant-Id}:-0}" == "0") -> TRUE
> (36) Wed Feb 6 11:08:00 2019: Debug: if ( "%{%{control:PacketFence-Tenant-Id}:-0}" == "0") {
> (36) Wed Feb 6 11:08:00 2019: Debug: update control {
> (36) Wed Feb 6 11:08:00 2019: Debug: EXPAND %{User-Name}
> (36) Wed Feb 6 11:08:00 2019: Debug: --> PFAdmin
> (36) Wed Feb 6 11:08:00 2019: Debug: SQL-User-Name set to 'PFAdmin'
> (36) Wed Feb 6 11:08:00 2019: Debug: Executing select query: SELECT IFNULL((SELECT tenant_id FROM radius_nas WHERE nasname = '192.168.1.201'), 0)
> (36) Wed Feb 6 11:08:00 2019: Debug: EXPAND %{sql: SELECT IFNULL((SELECT tenant_id FROM radius_nas WHERE nasname = '%{Packet-Src-IP-Address}'), 0)}
> (36) Wed Feb 6 11:08:00 2019: Debug: --> 1
> (36) Wed Feb 6 11:08:00 2019: Debug: } # update control = noop
> (36) Wed Feb 6 11:08:00 2019: Debug: } # if ( "%{%{control:PacketFence-Tenant-Id}:-0}" == "0") = noop
> (36) Wed Feb 6 11:08:00 2019: Debug: if ( &control:PacketFence-Tenant-Id == 0 ) {
> (36) Wed Feb 6 11:08:00 2019: Debug: if ( &control:PacketFence-Tenant-Id == 0 ) -> FALSE
> (36) Wed Feb 6 11:08:00 2019: Debug: } # policy packetfence-set-tenant-id = noop
> (36) Wed Feb 6 11:08:00 2019: Debug: policy rewrite_calling_station_id {
> (36) Wed Feb 6 11:08:00 2019: 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)) {
> (36) Wed Feb 6 11:08:00 2019: 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)) -> FALSE
> (36) Wed Feb 6 11:08:00 2019: Debug: else {
> (36) Wed Feb 6 11:08:00 2019: Debug: [noop] = noop
> (36) Wed Feb 6 11:08:00 2019: Debug: } # else = noop
> (36) Wed Feb 6 11:08:00 2019: Debug: } # policy rewrite_calling_station_id = noop
> (36) Wed Feb 6 11:08:00 2019: Debug: policy rewrite_called_station_id {
> (36) Wed Feb 6 11:08:00 2019: 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)) {
> (36) Wed Feb 6 11:08:00 2019: 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)) -> FALSE
> (36) Wed Feb 6 11:08:00 2019: Debug: else {
> (36) Wed Feb 6 11:08:00 2019: Debug: [noop] = noop
> (36) Wed Feb 6 11:08:00 2019: Debug: } # else = noop
> (36) Wed Feb 6 11:08:00 2019: Debug: } # policy rewrite_called_station_id = noop
> (36) Wed Feb 6 11:08:00 2019: Debug: policy filter_username {
> (36) Wed Feb 6 11:08:00 2019: Debug: if (&User-Name) {
> (36) Wed Feb 6 11:08:00 2019: Debug: if (&User-Name) -> TRUE
> (36) Wed Feb 6 11:08:00 2019: Debug: if (&User-Name) {
> (36) Wed Feb 6 11:08:00 2019: Debug: if (&User-Name =~ / /) {
> (36) Wed Feb 6 11:08:00 2019: Debug: if (&User-Name =~ / /) -> FALSE
> (36) Wed Feb 6 11:08:00 2019: Debug: if (&User-Name =~ /@[^@]*@/ ) {
> (36) Wed Feb 6 11:08:00 2019: Debug: if (&User-Name =~ /@[^@]*@/ ) -> FALSE
> (36) Wed Feb 6 11:08:00 2019: Debug: if (&User-Name =~ /\.\./ ) {
> (36) Wed Feb 6 11:08:00 2019: Debug: if (&User-Name =~ /\.\./ ) -> FALSE
> (36) Wed Feb 6 11:08:00 2019: Debug: if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) {
> (36) Wed Feb 6 11:08:00 2019: Debug: if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) -> FALSE
> (36) Wed Feb 6 11:08:00 2019: Debug: if (&User-Name =~ /\.$/) {
> (36) Wed Feb 6 11:08:00 2019: Debug: if (&User-Name =~ /\.$/) -> FALSE
> (36) Wed Feb 6 11:08:00 2019: Debug: if (&User-Name =~ /@\./) {
> (36) Wed Feb 6 11:08:00 2019: Debug: if (&User-Name =~ /@\./) -> FALSE
> (36) Wed Feb 6 11:08:00 2019: Debug: } # if (&User-Name) = noop
> (36) Wed Feb 6 11:08:00 2019: Debug: } # policy filter_username = noop
> (36) Wed Feb 6 11:08:00 2019: Debug: policy filter_password {
> (36) Wed Feb 6 11:08:00 2019: Debug: if (&User-Password && (&User-Password != "%{string:User-Password}")) {
> (36) Wed Feb 6 11:08:00 2019: Debug: if (&User-Password && (&User-Password != "%{string:User-Password}")) -> FALSE
> (36) Wed Feb 6 11:08:00 2019: Debug: } # policy filter_password = noop
> (36) Wed Feb 6 11:08:00 2019: Debug: [preprocess] = ok
> (36) Wed Feb 6 11:08:00 2019: Debug: suffix: Checking for suffix after "@"
> (36) Wed Feb 6 11:08:00 2019: Debug: suffix: No '@' in User-Name = "PFAdmin", skipping NULL due to config.
> (36) Wed Feb 6 11:08:00 2019: Debug: [suffix] = noop
> (36) Wed Feb 6 11:08:00 2019: Debug: ntdomain: Checking for prefix before "\"
> (36) Wed Feb 6 11:08:00 2019: Debug: ntdomain: No '\' in User-Name = "PFAdmin", looking up realm NULL
> (36) Wed Feb 6 11:08:00 2019: Debug: ntdomain: Found realm "null"
> (36) Wed Feb 6 11:08:00 2019: Debug: ntdomain: Adding Stripped-User-Name = "PFAdmin"
> (36) Wed Feb 6 11:08:00 2019: Debug: ntdomain: Adding Realm = "null"
> (36) Wed Feb 6 11:08:00 2019: Debug: ntdomain: Authentication realm is LOCAL
> (36) Wed Feb 6 11:08:00 2019: Debug: [ntdomain] = ok
> (36) Wed Feb 6 11:08:00 2019: Debug: eap: Peer sent EAP Response (code 2) ID 3 length 6
> (36) Wed Feb 6 11:08:00 2019: Debug: eap: Continuing tunnel setup
> (36) Wed Feb 6 11:08:00 2019: Debug: [eap] = ok
> (36) Wed Feb 6 11:08:00 2019: Debug: } # authorize = ok
> (36) Wed Feb 6 11:08:00 2019: Debug: Found Auth-Type = eap
> (36) Wed Feb 6 11:08:00 2019: Debug: # Executing group from file /usr/local/pf/raddb/sites-enabled/packetfence
> (36) Wed Feb 6 11:08:00 2019: Debug: authenticate {
> (36) Wed Feb 6 11:08:00 2019: Debug: eap: Expiring EAP session with state 0x6107f6c76304efb3
> (36) Wed Feb 6 11:08:00 2019: Debug: eap: Finished EAP session with state 0x6107f6c76304efb3
> (36) Wed Feb 6 11:08:00 2019: Debug: eap: Previous EAP request found for state 0x6107f6c76304efb3, released from the list
> (36) Wed Feb 6 11:08:00 2019: Debug: eap: Peer sent packet with method EAP PEAP (25)
> (36) Wed Feb 6 11:08:00 2019: Debug: eap: Calling submodule eap_peap to process data
> (36) Wed Feb 6 11:08:00 2019: Debug: eap_peap: Continuing EAP-TLS
> (36) Wed Feb 6 11:08:00 2019: Debug: eap_peap: Peer ACKed our handshake fragment
> (36) Wed Feb 6 11:08:00 2019: Debug: eap_peap: [eaptls verify] = request
> (36) Wed Feb 6 11:08:00 2019: Debug: eap_peap: [eaptls process] = handled
> (36) Wed Feb 6 11:08:00 2019: Debug: eap: Sending EAP Request (code 1) ID 4 length 691
> (36) Wed Feb 6 11:08:00 2019: Debug: eap: EAP session adding &reply:State = 0x6107f6c76203efb3
> (36) Wed Feb 6 11:08:00 2019: Debug: [eap] = handled
> (36) Wed Feb 6 11:08:00 2019: Debug: } # authenticate = handled
> (36) Wed Feb 6 11:08:00 2019: Debug: Using Post-Auth-Type Challenge
> (36) Wed Feb 6 11:08:00 2019: Debug: Post-Auth-Type sub-section not found. Ignoring.
> (36) Wed Feb 6 11:08:00 2019: Debug: # Executing group from file /usr/local/pf/raddb/sites-enabled/packetfence
> (36) Wed Feb 6 11:08:00 2019: Debug: Sent Access-Challenge Id 14 from 192.168.1.112:1812 to 192.168.1.201:1812 length 0
> (36) Wed Feb 6 11:08:00 2019: Debug: EAP-Message = 0x010402b319000530030101ff30360603551d1f042f302d302ba029a0278625687474703a2f2f7777772e6578616d706c652e6f72672f6578616d706c655f63612e63726c300d06092a864886f70d01010b0500038201010064722cd312cea220b7d9018c31b170ff2c0ba56c5263f823245633cd7c713b
> (36) Wed Feb 6 11:08:00 2019: Debug: Message-Authenticator = 0x00000000000000000000000000000000
> (36) Wed Feb 6 11:08:00 2019: Debug: State = 0x6107f6c76203efb330f8eb3fa2cd242e
> (36) Wed Feb 6 11:08:00 2019: Debug: Finished request
> (37) Wed Feb 6 11:08:00 2019: Debug: Received Access-Request Id 15 from 192.168.1.201:1812 to 192.168.1.112:1812 length 278
> (37) Wed Feb 6 11:08:00 2019: Debug: NAS-IP-Address = 192.168.1.201
> (37) Wed Feb 6 11:08:00 2019: Debug: Cisco-NAS-Port = "FastEthernet0/17"
> (37) Wed Feb 6 11:08:00 2019: Debug: NAS-Port-Type = Async
> (37) Wed Feb 6 11:08:00 2019: Debug: User-Name = "PFAdmin"
> (37) Wed Feb 6 11:08:00 2019: Debug: Calling-Station-Id = "4\227\366\024I\344"
> (37) Wed Feb 6 11:08:00 2019: Debug: Service-Type = Framed-User
> (37) Wed Feb 6 11:08:00 2019: Debug: Framed-MTU = 1500
> (37) Wed Feb 6 11:08:00 2019: Debug: Calling-Station-Id = "34-97-f6-14-49-e4"
> (37) Wed Feb 6 11:08:00 2019: Debug: State = 0x6107f6c76203efb330f8eb3fa2cd242e
> (37) Wed Feb 6 11:08:00 2019: Debug: EAP-Message = 0x0204008819800000007e160303004610000042410448b8eaa90f269621ecae6fb6d301f0b1ee68583ba7bfdff0a080bb4b1c5e5c49ba92cbf1865d82b69ef6da467511fa7277fbd766a67e5978145759dbef95bda414030300010116030300280000000000000000cbe317a4d907ca6e930249864962b9
> (37) Wed Feb 6 11:08:00 2019: Debug: Message-Authenticator = 0x40dea7837e53015bef991a9a9b659190
> (37) Wed Feb 6 11:08:00 2019: Debug: session-state: No cached attributes
> (37) Wed Feb 6 11:08:00 2019: Debug: # Executing section authorize from file /usr/local/pf/raddb/sites-enabled/packetfence
> (37) Wed Feb 6 11:08:00 2019: Debug: authorize {
> (37) Wed Feb 6 11:08:00 2019: Debug: update {
> (37) Wed Feb 6 11:08:00 2019: Debug: EXPAND %{Packet-Src-IP-Address}
> (37) Wed Feb 6 11:08:00 2019: Debug: --> 192.168.1.201
> (37) Wed Feb 6 11:08:00 2019: Debug: EXPAND %l
> (37) Wed Feb 6 11:08:00 2019: Debug: --> 1549447680
> (37) Wed Feb 6 11:08:00 2019: Debug: EXPAND %{Calling-Station-ID} %{User-Name}
> (37) Wed Feb 6 11:08:00 2019: Debug: --> 4\227\366\024I\344 PFAdmin
> (37) Wed Feb 6 11:08:00 2019: Debug: } # update = noop
> (37) Wed Feb 6 11:08:00 2019: Debug: policy packetfence-set-tenant-id {
> (37) Wed Feb 6 11:08:00 2019: Debug: if ( "%{%{control:PacketFence-Tenant-Id}:-0}" == "0") {
> (37) Wed Feb 6 11:08:00 2019: Debug: EXPAND %{%{control:PacketFence-Tenant-Id}:-0}
> (37) Wed Feb 6 11:08:00 2019: Debug: --> 0
> (37) Wed Feb 6 11:08:00 2019: Debug: if ( "%{%{control:PacketFence-Tenant-Id}:-0}" == "0") -> TRUE
> (37) Wed Feb 6 11:08:00 2019: Debug: if ( "%{%{control:PacketFence-Tenant-Id}:-0}" == "0") {
> (37) Wed Feb 6 11:08:00 2019: Debug: update control {
> (37) Wed Feb 6 11:08:00 2019: Debug: EXPAND %{User-Name}
> (37) Wed Feb 6 11:08:00 2019: Debug: --> PFAdmin
> (37) Wed Feb 6 11:08:00 2019: Debug: SQL-User-Name set to 'PFAdmin'
> (37) Wed Feb 6 11:08:00 2019: Debug: Executing select query: SELECT IFNULL((SELECT tenant_id FROM radius_nas WHERE nasname = '192.168.1.201'), 0)
> (37) Wed Feb 6 11:08:00 2019: Debug: EXPAND %{sql: SELECT IFNULL((SELECT tenant_id FROM radius_nas WHERE nasname = '%{Packet-Src-IP-Address}'), 0)}
> (37) Wed Feb 6 11:08:00 2019: Debug: --> 1
> (37) Wed Feb 6 11:08:00 2019: Debug: } # update control = noop
> (37) Wed Feb 6 11:08:00 2019: Debug: } # if ( "%{%{control:PacketFence-Tenant-Id}:-0}" == "0") = noop
> (37) Wed Feb 6 11:08:00 2019: Debug: if ( &control:PacketFence-Tenant-Id == 0 ) {
> (37) Wed Feb 6 11:08:00 2019: Debug: if ( &control:PacketFence-Tenant-Id == 0 ) -> FALSE
> (37) Wed Feb 6 11:08:00 2019: Debug: } # policy packetfence-set-tenant-id = noop
> (37) Wed Feb 6 11:08:00 2019: Debug: policy rewrite_calling_station_id {
> (37) Wed Feb 6 11:08:00 2019: 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)) {
> (37) Wed Feb 6 11:08:00 2019: 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)) -> FALSE
> (37) Wed Feb 6 11:08:00 2019: Debug: else {
> (37) Wed Feb 6 11:08:00 2019: Debug: [noop] = noop
> (37) Wed Feb 6 11:08:00 2019: Debug: } # else = noop
> (37) Wed Feb 6 11:08:00 2019: Debug: } # policy rewrite_calling_station_id = noop
> (37) Wed Feb 6 11:08:00 2019: Debug: policy rewrite_called_station_id {
> (37) Wed Feb 6 11:08:00 2019: 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)) {
> (37) Wed Feb 6 11:08:00 2019: 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)) -> FALSE
> (37) Wed Feb 6 11:08:00 2019: Debug: else {
> (37) Wed Feb 6 11:08:00 2019: Debug: [noop] = noop
> (37) Wed Feb 6 11:08:00 2019: Debug: } # else = noop
> (37) Wed Feb 6 11:08:00 2019: Debug: } # policy rewrite_called_station_id = noop
> (37) Wed Feb 6 11:08:00 2019: Debug: policy filter_username {
> (37) Wed Feb 6 11:08:00 2019: Debug: if (&User-Name) {
> (37) Wed Feb 6 11:08:00 2019: Debug: if (&User-Name) -> TRUE
> (37) Wed Feb 6 11:08:00 2019: Debug: if (&User-Name) {
> (37) Wed Feb 6 11:08:00 2019: Debug: if (&User-Name =~ / /) {
> (37) Wed Feb 6 11:08:00 2019: Debug: if (&User-Name =~ / /) -> FALSE
> (37) Wed Feb 6 11:08:00 2019: Debug: if (&User-Name =~ /@[^@]*@/ ) {
> (37) Wed Feb 6 11:08:00 2019: Debug: if (&User-Name =~ /@[^@]*@/ ) -> FALSE
> (37) Wed Feb 6 11:08:00 2019: Debug: if (&User-Name =~ /\.\./ ) {
> (37) Wed Feb 6 11:08:00 2019: Debug: if (&User-Name =~ /\.\./ ) -> FALSE
> (37) Wed Feb 6 11:08:00 2019: Debug: if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) {
> (37) Wed Feb 6 11:08:00 2019: Debug: if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) -> FALSE
> (37) Wed Feb 6 11:08:00 2019: Debug: if (&User-Name =~ /\.$/) {
> (37) Wed Feb 6 11:08:00 2019: Debug: if (&User-Name =~ /\.$/) -> FALSE
> (37) Wed Feb 6 11:08:00 2019: Debug: if (&User-Name =~ /@\./) {
> (37) Wed Feb 6 11:08:00 2019: Debug: if (&User-Name =~ /@\./) -> FALSE
> (37) Wed Feb 6 11:08:00 2019: Debug: } # if (&User-Name) = noop
> (37) Wed Feb 6 11:08:00 2019: Debug: } # policy filter_username = noop
> (37) Wed Feb 6 11:08:00 2019: Debug: policy filter_password {
> (37) Wed Feb 6 11:08:00 2019: Debug: if (&User-Password && (&User-Password != "%{string:User-Password}")) {
> (37) Wed Feb 6 11:08:00 2019: Debug: if (&User-Password && (&User-Password != "%{string:User-Password}")) -> FALSE
> (37) Wed Feb 6 11:08:00 2019: Debug: } # policy filter_password = noop
> (37) Wed Feb 6 11:08:00 2019: Debug: [preprocess] = ok
> (37) Wed Feb 6 11:08:00 2019: Debug: suffix: Checking for suffix after "@"
> (37) Wed Feb 6 11:08:00 2019: Debug: suffix: No '@' in User-Name = "PFAdmin", skipping NULL due to config.
> (37) Wed Feb 6 11:08:00 2019: Debug: [suffix] = noop
> (37) Wed Feb 6 11:08:00 2019: Debug: ntdomain: Checking for prefix before "\"
> (37) Wed Feb 6 11:08:00 2019: Debug: ntdomain: No '\' in User-Name = "PFAdmin", looking up realm NULL
> (37) Wed Feb 6 11:08:00 2019: Debug: ntdomain: Found realm "null"
> (37) Wed Feb 6 11:08:00 2019: Debug: ntdomain: Adding Stripped-User-Name = "PFAdmin"
> (37) Wed Feb 6 11:08:00 2019: Debug: ntdomain: Adding Realm = "null"
> (37) Wed Feb 6 11:08:00 2019: Debug: ntdomain: Authentication realm is LOCAL
> (37) Wed Feb 6 11:08:00 2019: Debug: [ntdomain] = ok
> (37) Wed Feb 6 11:08:00 2019: Debug: eap: Peer sent EAP Response (code 2) ID 4 length 136
> (37) Wed Feb 6 11:08:00 2019: Debug: eap: Continuing tunnel setup
> (37) Wed Feb 6 11:08:00 2019: Debug: [eap] = ok
> (37) Wed Feb 6 11:08:00 2019: Debug: } # authorize = ok
> (37) Wed Feb 6 11:08:00 2019: Debug: Found Auth-Type = eap
> (37) Wed Feb 6 11:08:00 2019: Debug: # Executing group from file /usr/local/pf/raddb/sites-enabled/packetfence
> (37) Wed Feb 6 11:08:00 2019: Debug: authenticate {
> (37) Wed Feb 6 11:08:00 2019: Debug: eap: Expiring EAP session with state 0x6107f6c76203efb3
> (37) Wed Feb 6 11:08:00 2019: Debug: eap: Finished EAP session with state 0x6107f6c76203efb3
> (37) Wed Feb 6 11:08:00 2019: Debug: eap: Previous EAP request found for state 0x6107f6c76203efb3, released from the list
> (37) Wed Feb 6 11:08:00 2019: Debug: eap: Peer sent packet with method EAP PEAP (25)
> (37) Wed Feb 6 11:08:00 2019: Debug: eap: Calling submodule eap_peap to process data
> (37) Wed Feb 6 11:08:00 2019: Debug: eap_peap: Continuing EAP-TLS
> (37) Wed Feb 6 11:08:00 2019: Debug: eap_peap: Peer indicated complete TLS record size will be 126 bytes
> (37) Wed Feb 6 11:08:00 2019: Debug: eap_peap: Got complete TLS record (126 bytes)
> (37) Wed Feb 6 11:08:00 2019: Debug: eap_peap: [eaptls verify] = length included
> (37) Wed Feb 6 11:08:00 2019: Debug: eap_peap: TLS_accept: SSLv3 read client key exchange A
> (37) Wed Feb 6 11:08:00 2019: Debug: eap_peap: TLS_accept: SSLv3 read certificate verify A
> (37) Wed Feb 6 11:08:00 2019: Debug: eap_peap: TLS_accept: SSLv3 read finished A
> (37) Wed Feb 6 11:08:00 2019: Debug: eap_peap: TLS_accept: SSLv3 write change cipher spec A
> (37) Wed Feb 6 11:08:00 2019: Debug: eap_peap: TLS_accept: SSLv3 write finished A
> (37) Wed Feb 6 11:08:00 2019: Debug: eap_peap: TLS_accept: SSLv3 flush data
> (37) Wed Feb 6 11:08:00 2019: Debug: eap_peap: (other): SSL negotiation finished successfully
> (37) Wed Feb 6 11:08:00 2019: Debug: eap_peap: TLS - Connection Established
> (37) Wed Feb 6 11:08:00 2019: Debug: eap_peap: TLS-Session-Cipher-Suite = "ECDHE-RSA-AE...
[truncated message content] |
