Menu
▾
▴
Re: [PacketFence-users] Can't link PacketFence with AD Server.
|
From: Adrian D. <adr...@no...> - 2019-02-06 10:17:39
|
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-AES256-GCM-SHA384"
(37) Wed Feb 6 11:08:00 2019: Debug: eap_peap: TLS-Session-Version = "TLS 1.2"
(37) Wed Feb 6 11:08:00 2019: Debug: eap_peap: TLS - got 51 bytes of data
(37) Wed Feb 6 11:08:00 2019: Debug: eap_peap: [eaptls process] = handled
(37) Wed Feb 6 11:08:00 2019: Debug: eap: Sending EAP Request (code 1) ID 5 length 57
(37) Wed Feb 6 11:08:00 2019: Debug: eap: EAP session adding &reply:State = 0x6107f6c76502efb3
(37) Wed Feb 6 11:08:00 2019: Debug: [eap] = handled
(37) Wed Feb 6 11:08:00 2019: Debug: } # authenticate = handled
(37) Wed Feb 6 11:08:00 2019: Debug: Using Post-Auth-Type Challenge
(37) Wed Feb 6 11:08:00 2019: Debug: Post-Auth-Type sub-section not found. Ignoring.
(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: session-state: Saving cached attributes
(37) Wed Feb 6 11:08:00 2019: Debug: TLS-Session-Cipher-Suite = "ECDHE-RSA-AES256-GCM-SHA384"
(37) Wed Feb 6 11:08:00 2019: Debug: TLS-Session-Version = "TLS 1.2"
(37) Wed Feb 6 11:08:00 2019: Debug: Sent Access-Challenge Id 15 from 192.168.1.112:1812 to 192.168.1.201:1812 length 0
(37) Wed Feb 6 11:08:00 2019: Debug: EAP-Message = 0x0105003919001403030001011603030028f55fa6b762e31eb0ea4406f262057280968ba5ccda8559d50b65b62f5cebe75c700ef930a4e3913a
(37) Wed Feb 6 11:08:00 2019: Debug: Message-Authenticator = 0x00000000000000000000000000000000
(37) Wed Feb 6 11:08:00 2019: Debug: State = 0x6107f6c76502efb330f8eb3fa2cd242e
(37) Wed Feb 6 11:08:00 2019: Debug: Finished request
(38) Wed Feb 6 11:08:00 2019: Debug: Received Access-Request Id 16 from 192.168.1.201:1812 to 192.168.1.112:1812 length 148
(38) Wed Feb 6 11:08:00 2019: Debug: NAS-IP-Address = 192.168.1.201
(38) Wed Feb 6 11:08:00 2019: Debug: Cisco-NAS-Port = "FastEthernet0/17"
(38) Wed Feb 6 11:08:00 2019: Debug: NAS-Port-Type = Async
(38) Wed Feb 6 11:08:00 2019: Debug: User-Name = "PFAdmin"
(38) Wed Feb 6 11:08:...
[truncated message content] |
