Hi, I am trying to use packetfence for mikrotik device cli access. I want to access with my MS Active Directory users. Mikrotik devices use mschap for cli connections. In my Packetfence->Radius Configuration, mschapv2 feature is enabled but i have some problems when i access to devices. First i will use default radius config for cli access, packetfence try to bind to active directory server. I tested my Active Directory connection with other devices(without mschap). In normally these connections it work but when i try mikrotik devices,it give this issue on packetfence.log:
*Mar 16 14:52:23 debian packetfence_httpd.aaa: httpd.aaa(3306) WARN: [mac:30:23:03:8e:50:c2] [AD-source] User CN=evren,CN=Users,DC=evrenkorkmaz,DC=xyz cannot bind from CN=Users,DC=evrenkorkmaz,DC=xyz on 192.168.56.102:389 <http://192.168.56.102:389> (pf::Authentication::Source::LDAPSource::authenticate)Mar 16 14:52:23 debian packetfence_httpd.aaa: httpd.aaa(3306) INFO: [mac:30:23:03:8e:50:c2] User evren tried to login in 192.168.30.6 but authentication failed (pf::radius::switch_access)* When i analyze the raddebug outputs, user is rejected in the rest module: *(22) Mon Mar 16 14:53:21 2020: Debug: rest: Encoding attribute "FreeRADIUS-Client-IP-Address"(22) Mon Mar 16 14:53:21 2020: Debug: rest: Encoding attribute "PacketFence-KeyBalanced"(22) Mon Mar 16 14:53:21 2020: Debug: rest: Encoding attribute "PacketFence-Radius-Ip"(22) Mon Mar 16 14:53:21 2020: Debug: rest: Processing response header(22) Mon Mar 16 14:53:21 2020: Debug: rest: Status : 401 (Unauthorized)(22) Mon Mar 16 14:53:21 2020: Debug: rest: Type : json (application/json)(22) Mon Mar 16 14:53:21 2020: ERROR: rest: Server returned:(22) Mon Mar 16 14:53:21 2020: ERROR: rest: {"Reply-Message":"Authentication failed on PacketFence","control:PacketFence-Authorization-Status":"allow"}(22) Mon Mar 16 14:53:21 2020: Debug: [rest] = invalid(22) Mon Mar 16 14:53:21 2020: Debug: } # if (! EAP-Type || (EAP-Type != TTLS && EAP-Type != PEAP) ) = invalid(22) Mon Mar 16 14:53:21 2020: Debug: } # post-auth = invalid(22) Mon Mar 16 14:53:21 2020: Debug: Using Post-Auth-Type Reject* As i understand, packetfence must to use packetfence-tunnel for mschap authentication. So i enabled *this feature on "Packetfence->System Config.->Radius Config" but nothing change. * *Lastly, i enabled packetfence auhorize feature on "Packetfence->System Config.->Radius Config" . Now packetfence give "Mac is empty" error and i cant resolve this problem.* *radius.log:* *Mar 16 15:05:59 debian auth[25164]: Need 7 more connections to reach 10 sparesMar 16 15:05:59 debian auth[25164]: rlm_sql (sql): Opening additional connection (5), 1 of 61 pending slots usedMar 16 15:05:59 debian auth[25164]: Need 1 more connections to reach min connections (3)Mar 16 15:05:59 debian auth[25164]: rlm_rest (rest): Opening additional connection (2), 1 of 62 pending slots usedMar 16 15:05:59 debian auth[25164]: (13) Invalid user: [evren] (from client 192.168.30.6/32 <http://192.168.30.6/32> port 0 cli 192.168.30.1)Mar 16 15:05:59 debian auth[25164]: [mac:192.168.30.1] Rejected user: evrenMar 16 15:05:59 debian auth[25164]: (13) Login incorrect: [evren] (from client 192.168.30.6/32 <http://192.168.30.6/32> port 0 cli 192.168.30.1)* *packetfence.log is empty.* *raddebug: * *(24) Mon Mar 16 15:07:23 2020: Debug: rest: Encoding attribute "MS-CHAP2-Response"(24) Mon Mar 16 15:07:23 2020: Debug: rest: Encoding attribute "SQL-User-Name"(24) Mon Mar 16 15:07:23 2020: Debug: rest: Encoding attribute "FreeRADIUS-Client-IP-Address"(24) Mon Mar 16 15:07:23 2020: Debug: rest: Encoding attribute "PacketFence-KeyBalanced"(24) Mon Mar 16 15:07:23 2020: Debug: rest: Processing response header(24) Mon Mar 16 15:07:23 2020: Debug: rest: Status : 401 (Unauthorized)(24) Mon Mar 16 15:07:23 2020: Debug: rest: Type : json (application/json)(24) Mon Mar 16 15:07:23 2020: Debug: rest: Parsing attribute "control:PacketFence-Authorization-Status"(24) Mon Mar 16 15:07:23 2020: Debug: rest: EXPAND allow(24) Mon Mar 16 15:07:23 2020: Debug: rest: --> allow(24) Mon Mar 16 15:07:23 2020: Debug: rest: PacketFence-Authorization-Status := "allow"(24) Mon Mar 16 15:07:23 2020: Debug: rest: Parsing attribute "Reply-Message"(24) Mon Mar 16 15:07:23 2020: Debug: rest: EXPAND Mac is empty(24) Mon Mar 16 15:07:23 2020: Debug: rest: --> Mac is empty(24) Mon Mar 16 15:07:23 2020: Debug: rest: Reply-Message := "Mac is empty"(24) Mon Mar 16 15:07:23 2020: Debug: [rest] = reject(24) Mon Mar 16 15:07:23 2020: Debug: } # if ( !EAP-Message ) = reject(24) Mon Mar 16 15:07:23 2020: Debug: } # authorize = reject(24) Mon Mar 16 15:07:23 2020: Debug: Using Post-Auth-Type Reject* Later i realized that issue. User is rejected before the password section. I couldn't solve these problems. Please help me. All logs: (24) Mon Mar 16 15:07:23 2020: Debug: Received Access-Request Id 94 from 192.168.30.6:35889 to 192.168.30.2:1812 length 145 (24) Mon Mar 16 15:07:23 2020: Debug: Service-Type = Login-User (24) Mon Mar 16 15:07:23 2020: Debug: User-Name = "evren" (24) Mon Mar 16 15:07:23 2020: Debug: MS-CHAP-Challenge = 0x018b60198941ed5dc6de1774ba21b1c2 (24) Mon Mar 16 15:07:23 2020: Debug: MS-CHAP2-Response = 0x0000cd84cd595ad3e76cbb6e412f5914905a00000000000000000bb6f34220fbf40b8ad8874a1d5bf508728465ebaf6de37e (24) Mon Mar 16 15:07:23 2020: Debug: Calling-Station-Id = "192.168.30.1" (24) Mon Mar 16 15:07:23 2020: Debug: NAS-Identifier = "MikroTik" (24) Mon Mar 16 15:07:23 2020: Debug: NAS-IP-Address = 192.168.30.6 (24) Mon Mar 16 15:07:23 2020: Debug: # Executing section authorize from file /usr/local/pf/raddb/sites-enabled/packetfence (24) Mon Mar 16 15:07:23 2020: Debug: authorize { (24) Mon Mar 16 15:07:23 2020: Debug: update { (24) Mon Mar 16 15:07:23 2020: Debug: EXPAND %{Packet-Src-IP-Address} (24) Mon Mar 16 15:07:23 2020: Debug: --> 192.168.30.6 (24) Mon Mar 16 15:07:23 2020: Debug: EXPAND %l (24) Mon Mar 16 15:07:23 2020: Debug: --> 1584360443 (24) Mon Mar 16 15:07:23 2020: Debug: } # update = noop (24) Mon Mar 16 15:07:23 2020: Debug: policy packetfence-set-realm-if-machine { (24) Mon Mar 16 15:07:23 2020: Debug: if (User-Name =~ /host\/([a-z0-9_-]*)[\.](.*)/i) { (24) Mon Mar 16 15:07:23 2020: Debug: if (User-Name =~ /host\/([a-z0-9_-]*)[\.](.*)/i) -> FALSE (24) Mon Mar 16 15:07:23 2020: Debug: } # policy packetfence-set-realm-if-machine = noop (24) Mon Mar 16 15:07:23 2020: Debug: policy packetfence-balanced-key-policy { (24) Mon Mar 16 15:07:23 2020: Debug: if (&PacketFence-KeyBalanced && (&PacketFence-KeyBalanced =~ /^(.*)(.)$/i)) { (24) Mon Mar 16 15:07:23 2020: Debug: if (&PacketFence-KeyBalanced && (&PacketFence-KeyBalanced =~ /^(.*)(.)$/i)) -> FALSE (24) Mon Mar 16 15:07:23 2020: Debug: else { (24) Mon Mar 16 15:07:23 2020: Debug: update { (24) Mon Mar 16 15:07:23 2020: Debug: EXPAND %{md5:%{Calling-Station-Id}%{User-Name}} (24) Mon Mar 16 15:07:23 2020: Debug: --> 85bde241d7f98ac7a0bab114b852c753 (24) Mon Mar 16 15:07:23 2020: Debug: EXPAND %{md5:%{Calling-Station-Id}%{User-Name}} (24) Mon Mar 16 15:07:23 2020: Debug: --> 85bde241d7f98ac7a0bab114b852c753 (24) Mon Mar 16 15:07:23 2020: Debug: } # update = noop (24) Mon Mar 16 15:07:23 2020: Debug: } # else = noop (24) Mon Mar 16 15:07:23 2020: Debug: } # policy packetfence-balanced-key-policy = noop (24) Mon Mar 16 15:07:23 2020: Debug: policy packetfence-set-tenant-id { (24) Mon Mar 16 15:07:23 2020: Debug: if (!NAS-IP-Address || NAS-IP-Address == "0.0.0.0"){ (24) Mon Mar 16 15:07:23 2020: Debug: if (!NAS-IP-Address || NAS-IP-Address == "0.0.0.0") -> FALSE (24) Mon Mar 16 15:07:23 2020: Debug: if ( "%{%{control:PacketFence-Tenant-Id}:-0}" == "0") { (24) Mon Mar 16 15:07:23 2020: Debug: EXPAND %{%{control:PacketFence-Tenant-Id}:-0} (24) Mon Mar 16 15:07:23 2020: Debug: --> 0 (24) Mon Mar 16 15:07:23 2020: Debug: if ( "%{%{control:PacketFence-Tenant-Id}:-0}" == "0") -> TRUE (24) Mon Mar 16 15:07:23 2020: Debug: if ( "%{%{control:PacketFence-Tenant-Id}:-0}" == "0") { (24) Mon Mar 16 15:07:23 2020: Debug: update control { (24) Mon Mar 16 15:07:23 2020: Debug: EXPAND %{User-Name} (24) Mon Mar 16 15:07:23 2020: Debug: --> evren (24) Mon Mar 16 15:07:23 2020: Debug: SQL-User-Name set to 'evren' (24) Mon Mar 16 15:07:23 2020: Debug: Executing select query: SELECT IFNULL((SELECT tenant_id FROM radius_nas WHERE nasname = '192.168.30.6'), 0) (24) Mon Mar 16 15:07:23 2020: Debug: EXPAND %{sql: SELECT IFNULL((SELECT tenant_id FROM radius_nas WHERE nasname = '%{NAS-IP-Address}'), 0)} (24) Mon Mar 16 15:07:23 2020: Debug: --> 1 (24) Mon Mar 16 15:07:23 2020: Debug: } # update control = noop (24) Mon Mar 16 15:07:23 2020: Debug: } # if ( "%{%{control:PacketFence-Tenant-Id}:-0}" == "0") = noop (24) Mon Mar 16 15:07:23 2020: Debug: if ( &control:PacketFence-Tenant-Id == 0 ) { (24) Mon Mar 16 15:07:23 2020: Debug: if ( &control:PacketFence-Tenant-Id == 0 ) -> FALSE (24) Mon Mar 16 15:07:23 2020: Debug: } # policy packetfence-set-tenant-id = noop (24) Mon Mar 16 15:07:23 2020: Debug: policy rewrite_calling_station_id { (24) Mon Mar 16 15:07:23 2020: 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)) { (24) Mon Mar 16 15:07:23 2020: 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 (24) Mon Mar 16 15:07:23 2020: Debug: else { (24) Mon Mar 16 15:07:23 2020: Debug: [noop] = noop (24) Mon Mar 16 15:07:23 2020: Debug: } # else = noop (24) Mon Mar 16 15:07:23 2020: Debug: } # policy rewrite_calling_station_id = noop (24) Mon Mar 16 15:07:23 2020: Debug: policy rewrite_called_station_id { (24) Mon Mar 16 15:07:23 2020: 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)) { (24) Mon Mar 16 15:07:23 2020: 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 (24) Mon Mar 16 15:07:23 2020: Debug: else { (24) Mon Mar 16 15:07:23 2020: Debug: [noop] = noop (24) Mon Mar 16 15:07:23 2020: Debug: } # else = noop (24) Mon Mar 16 15:07:23 2020: Debug: } # policy rewrite_called_station_id = noop (24) Mon Mar 16 15:07:23 2020: Debug: policy filter_username { (24) Mon Mar 16 15:07:23 2020: Debug: if (&User-Name) { (24) Mon Mar 16 15:07:23 2020: Debug: if (&User-Name) -> TRUE (24) Mon Mar 16 15:07:23 2020: Debug: if (&User-Name) { (24) Mon Mar 16 15:07:23 2020: Debug: if (&User-Name =~ / /) { (24) Mon Mar 16 15:07:23 2020: Debug: if (&User-Name =~ / /) -> FALSE (24) Mon Mar 16 15:07:23 2020: Debug: if (&User-Name =~ /@[^@]*@/ ) { (24) Mon Mar 16 15:07:23 2020: Debug: if (&User-Name =~ /@[^@]*@/ ) -> FALSE (24) Mon Mar 16 15:07:23 2020: Debug: if (&User-Name =~ /\.\./ ) { (24) Mon Mar 16 15:07:23 2020: Debug: if (&User-Name =~ /\.\./ ) -> FALSE (24) Mon Mar 16 15:07:23 2020: Debug: if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) { (24) Mon Mar 16 15:07:23 2020: Debug: if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) -> FALSE (24) Mon Mar 16 15:07:23 2020: Debug: if (&User-Name =~ /\.$/) { (24) Mon Mar 16 15:07:23 2020: Debug: if (&User-Name =~ /\.$/) -> FALSE (24) Mon Mar 16 15:07:23 2020: Debug: if (&User-Name =~ /@\./) { (24) Mon Mar 16 15:07:23 2020: Debug: if (&User-Name =~ /@\./) -> FALSE (24) Mon Mar 16 15:07:23 2020: Debug: } # if (&User-Name) = noop (24) Mon Mar 16 15:07:23 2020: Debug: } # policy filter_username = noop (24) Mon Mar 16 15:07:23 2020: Debug: policy filter_password { (24) Mon Mar 16 15:07:23 2020: Debug: if (&User-Password && (&User-Password != "%{string:User-Password}")) { (24) Mon Mar 16 15:07:23 2020: Debug: if (&User-Password && (&User-Password != "%{string:User-Password}")) -> FALSE (24) Mon Mar 16 15:07:23 2020: Debug: } # policy filter_password = noop (24) Mon Mar 16 15:07:23 2020: Debug: [preprocess] = ok (24) Mon Mar 16 15:07:23 2020: Debug: suffix: Checking for suffix after "@" (24) Mon Mar 16 15:07:23 2020: Debug: suffix: No '@' in User-Name = "evren", skipping NULL due to config. (24) Mon Mar 16 15:07:23 2020: Debug: [suffix] = noop (24) Mon Mar 16 15:07:23 2020: Debug: if ( !EAP-Message ) { (24) Mon Mar 16 15:07:23 2020: Debug: if ( !EAP-Message ) -> TRUE (24) Mon Mar 16 15:07:23 2020: Debug: if ( !EAP-Message ) { (24) Mon Mar 16 15:07:23 2020: Debug: rest: Expanding URI components (24) Mon Mar 16 15:07:23 2020: Debug: rest: EXPAND http://127.0.0.1:7070 (24) Mon Mar 16 15:07:23 2020: Debug: rest: --> http://127.0.0.1:7070 (24) Mon Mar 16 15:07:23 2020: Debug: rest: EXPAND //radius/rest/filter (24) Mon Mar 16 15:07:23 2020: Debug: rest: --> //radius/rest/filter (24) Mon Mar 16 15:07:23 2020: Debug: rest: Sending HTTP POST to " http://127.0.0.1:7070//radius/rest/filter"; (24) Mon Mar 16 15:07:23 2020: Debug: rest: Encoding attribute "User-Name" (24) Mon Mar 16 15:07:23 2020: Debug: rest: Encoding attribute "NAS-IP-Address" (24) Mon Mar 16 15:07:23 2020: Debug: rest: Encoding attribute "Service-Type" (24) Mon Mar 16 15:07:23 2020: Debug: rest: Encoding attribute "Calling-Station-Id" (24) Mon Mar 16 15:07:23 2020: Debug: rest: Encoding attribute "NAS-Identifier" (24) Mon Mar 16 15:07:23 2020: Debug: rest: Encoding attribute "Event-Timestamp" (24) Mon Mar 16 15:07:23 2020: Debug: rest: Encoding attribute "MS-CHAP-Challenge" (24) Mon Mar 16 15:07:23 2020: Debug: rest: Encoding attribute "MS-CHAP2-Response" (24) Mon Mar 16 15:07:23 2020: Debug: rest: Encoding attribute "SQL-User-Name" (24) Mon Mar 16 15:07:23 2020: Debug: rest: Encoding attribute "FreeRADIUS-Client-IP-Address" (24) Mon Mar 16 15:07:23 2020: Debug: rest: Encoding attribute "PacketFence-KeyBalanced" (24) Mon Mar 16 15:07:23 2020: Debug: rest: Processing response header (24) Mon Mar 16 15:07:23 2020: Debug: rest: Status : 401 (Unauthorized) (24) Mon Mar 16 15:07:23 2020: Debug: rest: Type : json (application/json) (24) Mon Mar 16 15:07:23 2020: Debug: rest: Parsing attribute "control:PacketFence-Authorization-Status" (24) Mon Mar 16 15:07:23 2020: Debug: rest: EXPAND allow (24) Mon Mar 16 15:07:23 2020: Debug: rest: --> allow (24) Mon Mar 16 15:07:23 2020: Debug: rest: PacketFence-Authorization-Status := "allow" (24) Mon Mar 16 15:07:23 2020: Debug: rest: Parsing attribute "Reply-Message" (24) Mon Mar 16 15:07:23 2020: Debug: rest: EXPAND Mac is empty (24) Mon Mar 16 15:07:23 2020: Debug: rest: --> Mac is empty (24) Mon Mar 16 15:07:23 2020: Debug: rest: Reply-Message := "Mac is empty" (24) Mon Mar 16 15:07:23 2020: Debug: [rest] = reject (24) Mon Mar 16 15:07:23 2020: Debug: } # if ( !EAP-Message ) = reject (24) Mon Mar 16 15:07:23 2020: Debug: } # authorize = reject (24) Mon Mar 16 15:07:23 2020: Debug: Using Post-Auth-Type Reject (24) Mon Mar 16 15:07:23 2020: Debug: # Executing group from file /usr/local/pf/raddb/sites-enabled/packetfence (24) Mon Mar 16 15:07:23 2020: Debug: Post-Auth-Type REJECT { (24) Mon Mar 16 15:07:23 2020: Debug: policy packetfence-set-tenant-id { (24) Mon Mar 16 15:07:23 2020: Debug: if (!NAS-IP-Address || NAS-IP-Address == "0.0.0.0"){ (24) Mon Mar 16 15:07:23 2020: Debug: if (!NAS-IP-Address || NAS-IP-Address == "0.0.0.0") -> FALSE (24) Mon Mar 16 15:07:23 2020: Debug: if ( "%{%{control:PacketFence-Tenant-Id}:-0}" == "0") { (24) Mon Mar 16 15:07:23 2020: Debug: EXPAND %{%{control:PacketFence-Tenant-Id}:-0} (24) Mon Mar 16 15:07:23 2020: Debug: --> 1 (24) Mon Mar 16 15:07:23 2020: Debug: if ( "%{%{control:PacketFence-Tenant-Id}:-0}" == "0") -> FALSE (24) Mon Mar 16 15:07:23 2020: Debug: if ( &control:PacketFence-Tenant-Id == 0 ) { (24) Mon Mar 16 15:07:23 2020: Debug: if ( &control:PacketFence-Tenant-Id == 0 ) -> FALSE (24) Mon Mar 16 15:07:23 2020: Debug: } # policy packetfence-set-tenant-id = noop (24) Mon Mar 16 15:07:23 2020: Debug: update { (24) Mon Mar 16 15:07:23 2020: Debug: } # update = noop (24) Mon Mar 16 15:07:23 2020: Debug: if (! EAP-Type || (EAP-Type != TTLS && EAP-Type != PEAP) ) { (24) Mon Mar 16 15:07:23 2020: Debug: if (! EAP-Type || (EAP-Type != TTLS && EAP-Type != PEAP) ) -> TRUE (24) Mon Mar 16 15:07:23 2020: Debug: if (! EAP-Type || (EAP-Type != TTLS && EAP-Type != PEAP) ) { (24) Mon Mar 16 15:07:23 2020: Debug: policy packetfence-audit-log-reject { (24) Mon Mar 16 15:07:23 2020: Debug: if (&User-Name && (&User-Name == "dummy")) { (24) Mon Mar 16 15:07:23 2020: Debug: if (&User-Name && (&User-Name == "dummy")) -> FALSE (24) Mon Mar 16 15:07:23 2020: Debug: else { (24) Mon Mar 16 15:07:23 2020: Debug: policy request-timing { (24) Mon Mar 16 15:07:23 2020: Debug: if ("%{%{control:PacketFence-Request-Time}:-0}" != 0) { (24) Mon Mar 16 15:07:23 2020: Debug: EXPAND %{%{control:PacketFence-Request-Time}:-0} (24) Mon Mar 16 15:07:23 2020: Debug: --> 0 (24) Mon Mar 16 15:07:23 2020: Debug: if ("%{%{control:PacketFence-Request-Time}:-0}" != 0) -> FALSE (24) Mon Mar 16 15:07:23 2020: Debug: } # policy request-timing = noop (24) Mon Mar 16 15:07:23 2020: Debug: sql_reject: EXPAND type.reject.query (24) Mon Mar 16 15:07:23 2020: Debug: sql_reject: --> type.reject.query (24) Mon Mar 16 15:07:23 2020: Debug: sql_reject: Using query template 'query' (24) Mon Mar 16 15:07:23 2020: Debug: sql_reject: EXPAND %{User-Name} (24) Mon Mar 16 15:07:23 2020: Debug: sql_reject: --> evren (24) Mon Mar 16 15:07:23 2020: Debug: sql_reject: SQL-User-Name set to 'evren' (24) Mon Mar 16 15:07:23 2020: Debug: sql_reject: EXPAND INSERT INTO radius_audit_log ( mac, ip, computer_name, user_name, stripped_user_name, realm, event_type, switch_id, switch_mac, switch_ip_address, radius_source_ip_address, called_station_id, calling_station_id, nas_port_type, ssid, nas_port_id, ifindex, nas_port, connection_type, nas_ip_address, nas_identifier, auth_status, reason, auth_type, eap_type, role, node_status, profile, source, auto_reg, is_phone, pf_domain, uuid, radius_request, radius_reply, request_time, tenant_id, radius_ip) VALUES ( '%{request:Calling-Station-Id}', '%{request:Framed-IP-Address}', '%{%{control:PacketFence-Computer-Name}:-N/A}', '%{request:User-Name}', '%{request:Stripped-User-Name}', '%{request:Realm}', 'Radius-Access-Request', '%{%{control:PacketFence-Switch-Id}:-N/A}', '%{%{control:PacketFence-Switch-Mac}:-N/A}', '%{%{control:PacketFence-Switch-Ip-Address}:-N/A}', '%{Packet-Src-IP-Address}', '%{request:Called-Station-Id}', '%{request:Calling-Station-Id}', '%{request:NAS-Port-Type}', '%{request:Called-Station-SSID}', '%{request:NAS-Port-Id}', '%{%{control:PacketFence-IfIndex}:-N/A}', '%{request:NAS-Port}', '%{%{control:PacketFence-Connection-Type}:-N/A}', '%{request:NAS-IP-Address}', '%{request:NAS-Identifier}', 'Reject', '%{request:Module-Failure-Message}', '%{control:Auth-Type}', '%{request:EAP-Type}', '%{%{control:PacketFence-Role}:-N/A}', '%{%{control:PacketFence-Status}:-N/A}', '%{%{control:PacketFence-Profile}:-N/A}', '%{%{control:PacketFence-Source}:-N/A}', '%{%{control:PacketFence-AutoReg}:-0}', '%{%{control:PacketFence-IsPhone}:-0}', '%{request:PacketFence-Domain}', '', '%{pairs:&request:[*]}','%{pairs:&reply:[*]}', '%{%{control:PacketFence-Request-Time}:-N/A}', '%{control:PacketFence-Tenant-Id}', '%{request:PacketFence-Radius-Ip}') (24) Mon Mar 16 15:07:23 2020: Debug: sql_reject: --> INSERT INTO radius_audit_log ( mac, ip, computer_name, user_name, stripped_user_name, realm, event_type, switch_id, switch_mac, switch_ip_address, radius_source_ip_address, called_station_id, calling_station_id, nas_port_type, ssid, nas_port_id, ifindex, nas_port, connection_type, nas_ip_address, nas_identifier, auth_status, reason, auth_type, eap_type, role, node_status, profile, source, auto_reg, is_phone, pf_domain, uuid, radius_request, radius_reply, request_time, tenant_id, radius_ip) VALUES ( '192.168.30.1', '', 'N/A', 'evren', '', '', 'Radius-Access-Request', 'N/A', 'N/A', 'N/A', '192.168.30.6', '', '192.168.30.1', '', '', '', 'N/A', '', 'N/A', '192.168.30.6', 'MikroTik', 'Reject', '', '', '', 'N/A', 'N/A', 'N/A', 'N/A', '0', '0', '', '', 'User-Name =3D =22evren=22=2C NAS-IP-Address =3D 192.168.30.6=2C Service-Type =3D Login-User=2C Calling-Station-Id =3D =22192.168.30.1=22=2C NAS-Identifier =3D =22MikroTik=22=2C Event-Timestamp =3D =22Mar 16 2020 15:07:23 =2B03=22=2C MS-CHAP-Challenge =3D 0x018b60198941ed5dc6de1774ba21b1c2=2C MS-CHAP2-Response =3D 0x0000cd84cd595ad3e76cbb6e412f5914905a00000000000000000bb6f34220fbf40b8ad8874a1d5bf508728465ebaf6de37e=2C FreeRADIUS-Client-IP-Address =3D 192.168.30.6=2C PacketFence-KeyBalanced =3D =2285bde241d7f98ac7a0bab114b852c753=22=2C User-Password =3D =22=2A=2A=2A=2A=2A=2A=22=2C SQL-User-Name =3D =22evren=22','Reply-Message =3D =22Mac is empty=22', '0', '1', '') (24) Mon Mar 16 15:07:23 2020: Debug: sql_reject: Executing query: INSERT INTO radius_audit_log ( mac, ip, computer_name, user_name, stripped_user_name, realm, event_type, switch_id, switch_mac, switch_ip_address, radius_source_ip_address, called_station_id, calling_station_id, nas_port_type, ssid, nas_port_id, ifindex, nas_port, connection_type, nas_ip_address, nas_identifier, auth_status, reason, auth_type, eap_type, role, node_status, profile, source, auto_reg, is_phone, pf_domain, uuid, radius_request, radius_reply, request_time, tenant_id, radius_ip) VALUES ( '192.168.30.1', '', 'N/A', 'evren', '', '', 'Radius-Access-Request', 'N/A', 'N/A', 'N/A', '192.168.30.6', '', '192.168.30.1', '', '', '', 'N/A', '', 'N/A', '192.168.30.6', 'MikroTik', 'Reject', '', '', '', 'N/A', 'N/A', 'N/A', 'N/A', '0', '0', '', '', 'User-Name =3D =22evren=22=2C NAS-IP-Address =3D 192.168.30.6=2C Service-Type =3D Login-User=2C Calling-Station-Id =3D =22192.168.30.1=22=2C NAS-Identifier =3D =22MikroTik=22=2C Event-Timestamp =3D =22Mar 16 2020 15:07:23 =2B03=22=2C MS-CHAP-Challenge =3D 0x018b60198941ed5dc6de1774ba21b1c2=2C MS-CHAP2-Response =3D 0x0000cd84cd595ad3e76cbb6e412f5914905a00000000000000000bb6f34220fbf40b8ad8874a1d5bf508728465ebaf6de37e=2C FreeRADIUS-Client-IP-Address =3D 192.168.30.6=2C PacketFence-KeyBalanced =3D =2285bde241d7f98ac7a0bab114b852c753=22=2C User-Password =3D =22=2A=2A=2A=2A=2A=2A=22=2C SQL-User-Name =3D =22evren=22','Reply-Message =3D =22Mac is empty=22', '0', '1', '') (23) Mon Mar 16 15:07:23 2020: Debug: Cleaning up request packet ID 210 with timestamp +251 (24) Mon Mar 16 15:07:23 2020: Debug: sql_reject: SQL query returned: success (24) Mon Mar 16 15:07:23 2020: Debug: sql_reject: 1 record(s) updated (24) Mon Mar 16 15:07:23 2020: Debug: [sql_reject] = ok (24) Mon Mar 16 15:07:23 2020: Debug: } # else = ok (24) Mon Mar 16 15:07:23 2020: Debug: } # policy packetfence-audit-log-reject = ok (24) Mon Mar 16 15:07:23 2020: Debug: } # if (! EAP-Type || (EAP-Type != TTLS && EAP-Type != PEAP) ) = ok (24) Mon Mar 16 15:07:23 2020: Debug: if ("%{%{control:PacketFence-Proxied-From}:-False}" == "True") { (24) Mon Mar 16 15:07:23 2020: Debug: EXPAND %{%{control:PacketFence-Proxied-From}:-False} (24) Mon Mar 16 15:07:23 2020: Debug: --> False (24) Mon Mar 16 15:07:23 2020: Debug: if ("%{%{control:PacketFence-Proxied-From}:-False}" == "True") -> FALSE (24) Mon Mar 16 15:07:23 2020: Debug: attr_filter.access_reject: EXPAND %{User-Name} (24) Mon Mar 16 15:07:23 2020: Debug: attr_filter.access_reject: --> evren (24) Mon Mar 16 15:07:23 2020: Debug: attr_filter.access_reject: Matched entry DEFAULT at line 11 (24) Mon Mar 16 15:07:23 2020: Debug: [attr_filter.access_reject] = updated (24) Mon Mar 16 15:07:23 2020: Debug: attr_filter.packetfence_post_auth: EXPAND %{User-Name} (24) Mon Mar 16 15:07:23 2020: Debug: attr_filter.packetfence_post_auth: --> evren (24) Mon Mar 16 15:07:23 2020: Debug: attr_filter.packetfence_post_auth: Matched entry DEFAULT at line 10 (24) Mon Mar 16 15:07:23 2020: Debug: [attr_filter.packetfence_post_auth] = updated (24) Mon Mar 16 15:07:23 2020: Debug: [eap] = noop (24) Mon Mar 16 15:07:23 2020: Debug: policy remove_reply_message_if_eap { (24) Mon Mar 16 15:07:23 2020: Debug: if (&reply:EAP-Message && &reply:Reply-Message) { (24) Mon Mar 16 15:07:23 2020: Debug: if (&reply:EAP-Message && &reply:Reply-Message) -> FALSE (24) Mon Mar 16 15:07:23 2020: Debug: else { (24) Mon Mar 16 15:07:23 2020: Debug: [noop] = noop (24) Mon Mar 16 15:07:23 2020: Debug: } # else = noop (24) Mon Mar 16 15:07:23 2020: Debug: } # policy remove_reply_message_if_eap = noop (24) Mon Mar 16 15:07:23 2020: Debug: linelog: EXPAND messages.%{%{reply:Packet-Type}:-default} (24) Mon Mar 16 15:07:23 2020: Debug: linelog: --> messages.Access-Reject (24) Mon Mar 16 15:07:23 2020: Debug: linelog: EXPAND [mac:%{Calling-Station-Id}] Rejected user: %{User-Name} (24) Mon Mar 16 15:07:23 2020: Debug: linelog: --> [mac:192.168.30.1] Rejected user: evren (24) Mon Mar 16 15:07:23 2020: Debug: [linelog] = ok (24) Mon Mar 16 15:07:23 2020: Debug: } # Post-Auth-Type REJECT = updated (24) Mon Mar 16 15:07:23 2020: Debug: Delaying response for 1.000000 seconds (24) Mon Mar 16 15:07:23 2020: Debug: (24) Discarding duplicate request from client 192.168.30.6/32 port 35889 - ID: 94 due to delayed response (24) Mon Mar 16 15:07:24 2020: Debug: (24) Discarding duplicate request from client 192.168.30.6/32 port 35889 - ID: 94 due to delayed response (24) Mon Mar 16 15:07:24 2020: Debug: Sending delayed response (24) Mon Mar 16 15:07:24 2020: Debug: Sent Access-Reject Id 94 from 192.168.30.2:1812 to 192.168.30.6:35889 length 34 (24) Mon Mar 16 15:07:24 2020: Debug: Reply-Message = "Mac is empty" (25) Mon Mar 16 15:07:27 2020: Debug: Received Access-Request Id 95 from 192.168.30.6:35675 to 192.168.30.2:1812 length 145 (25) Mon Mar 16 15:07:27 2020: Debug: Service-Type = Login-User (25) Mon Mar 16 15:07:27 2020: Debug: User-Name = "evren" (25) Mon Mar 16 15:07:27 2020: Debug: MS-CHAP-Challenge = 0xa0f07329316086f83e9d6cf9be1dbb8b (25) Mon Mar 16 15:07:27 2020: Debug: MS-CHAP2-Response = 0x0000a188e5fb5bcc68173aa94693bed6ed5e0000000000000000a2dc302e211a880cc3c117ca130ec341de241f0888f480ef (25) Mon Mar 16 15:07:27 2020: Debug: Calling-Station-Id = "192.168.30.1" (25) Mon Mar 16 15:07:27 2020: Debug: NAS-Identifier = "MikroTik" (25) Mon Mar 16 15:07:27 2020: Debug: NAS-IP-Address = 192.168.30.6 (25) Mon Mar 16 15:07:27 2020: Debug: # Executing section authorize from file /usr/local/pf/raddb/sites-enabled/packetfence (25) Mon Mar 16 15:07:27 2020: Debug: authorize { (25) Mon Mar 16 15:07:27 2020: Debug: update { (25) Mon Mar 16 15:07:27 2020: Debug: EXPAND %{Packet-Src-IP-Address} (25) Mon Mar 16 15:07:27 2020: Debug: --> 192.168.30.6 (25) Mon Mar 16 15:07:27 2020: Debug: EXPAND %l (25) Mon Mar 16 15:07:27 2020: Debug: --> 1584360447 (25) Mon Mar 16 15:07:27 2020: Debug: } # update = noop (25) Mon Mar 16 15:07:27 2020: Debug: policy packetfence-set-realm-if-machine { (25) Mon Mar 16 15:07:27 2020: Debug: if (User-Name =~ /host\/([a-z0-9_-]*)[\.](.*)/i) { (25) Mon Mar 16 15:07:27 2020: Debug: if (User-Name =~ /host\/([a-z0-9_-]*)[\.](.*)/i) -> FALSE (25) Mon Mar 16 15:07:27 2020: Debug: } # policy packetfence-set-realm-if-machine = noop (25) Mon Mar 16 15:07:27 2020: Debug: policy packetfence-balanced-key-policy { (25) Mon Mar 16 15:07:27 2020: Debug: if (&PacketFence-KeyBalanced && (&PacketFence-KeyBalanced =~ /^(.*)(.)$/i)) { (25) Mon Mar 16 15:07:27 2020: Debug: if (&PacketFence-KeyBalanced && (&PacketFence-KeyBalanced =~ /^(.*)(.)$/i)) -> FALSE (25) Mon Mar 16 15:07:27 2020: Debug: else { (25) Mon Mar 16 15:07:27 2020: Debug: update { (25) Mon Mar 16 15:07:27 2020: Debug: EXPAND %{md5:%{Calling-Station-Id}%{User-Name}} (25) Mon Mar 16 15:07:27 2020: Debug: --> 85bde241d7f98ac7a0bab114b852c753 (25) Mon Mar 16 15:07:27 2020: Debug: EXPAND %{md5:%{Calling-Station-Id}%{User-Name}} (25) Mon Mar 16 15:07:27 2020: Debug: --> 85bde241d7f98ac7a0bab114b852c753 (25) Mon Mar 16 15:07:27 2020: Debug: } # update = noop (25) Mon Mar 16 15:07:27 2020: Debug: } # else = noop (25) Mon Mar 16 15:07:27 2020: Debug: } # policy packetfence-balanced-key-policy = noop (25) Mon Mar 16 15:07:27 2020: Debug: policy packetfence-set-tenant-id { (25) Mon Mar 16 15:07:27 2020: Debug: if (!NAS-IP-Address || NAS-IP-Address == "0.0.0.0"){ (25) Mon Mar 16 15:07:27 2020: Debug: if (!NAS-IP-Address || NAS-IP-Address == "0.0.0.0") -> FALSE (25) Mon Mar 16 15:07:27 2020: Debug: if ( "%{%{control:PacketFence-Tenant-Id}:-0}" == "0") { (25) Mon Mar 16 15:07:27 2020: Debug: EXPAND %{%{control:PacketFence-Tenant-Id}:-0} (25) Mon Mar 16 15:07:27 2020: Debug: --> 0 (25) Mon Mar 16 15:07:27 2020: Debug: if ( "%{%{control:PacketFence-Tenant-Id}:-0}" == "0") -> TRUE (25) Mon Mar 16 15:07:27 2020: Debug: if ( "%{%{control:PacketFence-Tenant-Id}:-0}" == "0") { (25) Mon Mar 16 15:07:27 2020: Debug: update control { (25) Mon Mar 16 15:07:27 2020: Debug: EXPAND %{User-Name} (25) Mon Mar 16 15:07:27 2020: Debug: --> evren (25) Mon Mar 16 15:07:27 2020: Debug: SQL-User-Name set to 'evren' (25) Mon Mar 16 15:07:27 2020: Debug: Executing select query: SELECT IFNULL((SELECT tenant_id FROM radius_nas WHERE nasname = '192.168.30.6'), 0) (25) Mon Mar 16 15:07:27 2020: Debug: EXPAND %{sql: SELECT IFNULL((SELECT tenant_id FROM radius_nas WHERE nasname = '%{NAS-IP-Address}'), 0)} (25) Mon Mar 16 15:07:27 2020: Debug: --> 1 (25) Mon Mar 16 15:07:27 2020: Debug: } # update control = noop (25) Mon Mar 16 15:07:27 2020: Debug: } # if ( "%{%{control:PacketFence-Tenant-Id}:-0}" == "0") = noop (25) Mon Mar 16 15:07:27 2020: Debug: if ( &control:PacketFence-Tenant-Id == 0 ) { (25) Mon Mar 16 15:07:27 2020: Debug: if ( &control:PacketFence-Tenant-Id == 0 ) -> FALSE (25) Mon Mar 16 15:07:27 2020: Debug: } # policy packetfence-set-tenant-id = noop (25) Mon Mar 16 15:07:27 2020: Debug: policy rewrite_calling_station_id { (25) Mon Mar 16 15:07:27 2020: 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)) { (25) Mon Mar 16 15:07:27 2020: 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 (25) Mon Mar 16 15:07:27 2020: Debug: else { (25) Mon Mar 16 15:07:27 2020: Debug: [noop] = noop (25) Mon Mar 16 15:07:27 2020: Debug: } # else = noop (25) Mon Mar 16 15:07:27 2020: Debug: } # policy rewrite_calling_station_id = noop (25) Mon Mar 16 15:07:27 2020: Debug: policy rewrite_called_station_id { (25) Mon Mar 16 15:07:27 2020: 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)) { (25) Mon Mar 16 15:07:27 2020: 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 (25) Mon Mar 16 15:07:27 2020: Debug: else { (25) Mon Mar 16 15:07:27 2020: Debug: [noop] = noop (25) Mon Mar 16 15:07:27 2020: Debug: } # else = noop (25) Mon Mar 16 15:07:27 2020: Debug: } # policy rewrite_called_station_id = noop (25) Mon Mar 16 15:07:27 2020: Debug: policy filter_username { (25) Mon Mar 16 15:07:27 2020: Debug: if (&User-Name) { (25) Mon Mar 16 15:07:27 2020: Debug: if (&User-Name) -> TRUE (25) Mon Mar 16 15:07:27 2020: Debug: if (&User-Name) { (25) Mon Mar 16 15:07:27 2020: Debug: if (&User-Name =~ / /) { (25) Mon Mar 16 15:07:27 2020: Debug: if (&User-Name =~ / /) -> FALSE (25) Mon Mar 16 15:07:27 2020: Debug: if (&User-Name =~ /@[^@]*@/ ) { (25) Mon Mar 16 15:07:27 2020: Debug: if (&User-Name =~ /@[^@]*@/ ) -> FALSE (25) Mon Mar 16 15:07:27 2020: Debug: if (&User-Name =~ /\.\./ ) { (25) Mon Mar 16 15:07:27 2020: Debug: if (&User-Name =~ /\.\./ ) -> FALSE (25) Mon Mar 16 15:07:27 2020: Debug: if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) { (25) Mon Mar 16 15:07:27 2020: Debug: if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) -> FALSE (25) Mon Mar 16 15:07:27 2020: Debug: if (&User-Name =~ /\.$/) { (25) Mon Mar 16 15:07:27 2020: Debug: if (&User-Name =~ /\.$/) -> FALSE (25) Mon Mar 16 15:07:27 2020: Debug: if (&User-Name =~ /@\./) { (25) Mon Mar 16 15:07:27 2020: Debug: if (&User-Name =~ /@\./) -> FALSE (25) Mon Mar 16 15:07:27 2020: Debug: } # if (&User-Name) = noop (25) Mon Mar 16 15:07:27 2020: Debug: } # policy filter_username = noop (25) Mon Mar 16 15:07:27 2020: Debug: policy filter_password { (25) Mon Mar 16 15:07:27 2020: Debug: if (&User-Password && (&User-Password != "%{string:User-Password}")) { (25) Mon Mar 16 15:07:27 2020: Debug: if (&User-Password && (&User-Password != "%{string:User-Password}")) -> FALSE (25) Mon Mar 16 15:07:27 2020: Debug: } # policy filter_password = noop (25) Mon Mar 16 15:07:27 2020: Debug: [preprocess] = ok (25) Mon Mar 16 15:07:27 2020: Debug: suffix: Checking for suffix after "@" (25) Mon Mar 16 15:07:27 2020: Debug: suffix: No '@' in User-Name = "evren", skipping NULL due to config. (25) Mon Mar 16 15:07:27 2020: Debug: [suffix] = noop (25) Mon Mar 16 15:07:27 2020: Debug: if ( !EAP-Message ) { (25) Mon Mar 16 15:07:27 2020: Debug: if ( !EAP-Message ) -> TRUE (25) Mon Mar 16 15:07:27 2020: Debug: if ( !EAP-Message ) { (25) Mon Mar 16 15:07:27 2020: Debug: rest: Expanding URI components (25) Mon Mar 16 15:07:27 2020: Debug: rest: EXPAND http://127.0.0.1:7070 (25) Mon Mar 16 15:07:27 2020: Debug: rest: --> http://127.0.0.1:7070 (25) Mon Mar 16 15:07:27 2020: Debug: rest: EXPAND //radius/rest/filter (25) Mon Mar 16 15:07:27 2020: Debug: rest: --> //radius/rest/filter (25) Mon Mar 16 15:07:27 2020: Debug: rest: Sending HTTP POST to " http://127.0.0.1:7070//radius/rest/filter"; (25) Mon Mar 16 15:07:27 2020: Debug: rest: Encoding attribute "User-Name" (25) Mon Mar 16 15:07:27 2020: Debug: rest: Encoding attribute "NAS-IP-Address" (25) Mon Mar 16 15:07:27 2020: Debug: rest: Encoding attribute "Service-Type" (25) Mon Mar 16 15:07:27 2020: Debug: rest: Encoding attribute "Calling-Station-Id" (25) Mon Mar 16 15:07:27 2020: Debug: rest: Encoding attribute "NAS-Identifier" (25) Mon Mar 16 15:07:27 2020: Debug: rest: Encoding attribute "Event-Timestamp" (25) Mon Mar 16 15:07:27 2020: Debug: rest: Encoding attribute "MS-CHAP-Challenge" (25) Mon Mar 16 15:07:27 2020: Debug: rest: Encoding attribute "MS-CHAP2-Response" (25) Mon Mar 16 15:07:27 2020: Debug: rest: Encoding attribute "SQL-User-Name" (25) Mon Mar 16 15:07:27 2020: Debug: rest: Encoding attribute "FreeRADIUS-Client-IP-Address" (25) Mon Mar 16 15:07:27 2020: Debug: rest: Encoding attribute "PacketFence-KeyBalanced" (25) Mon Mar 16 15:07:27 2020: Debug: rest: Processing response header (25) Mon Mar 16 15:07:27 2020: Debug: rest: Status : 401 (Unauthorized) (25) Mon Mar 16 15:07:27 2020: Debug: rest: Type : json (application/json) (25) Mon Mar 16 15:07:27 2020: Debug: rest: Parsing attribute "Reply-Message" (25) Mon Mar 16 15:07:27 2020: Debug: rest: EXPAND Mac is empty (25) Mon Mar 16 15:07:27 2020: Debug: rest: --> Mac is empty (25) Mon Mar 16 15:07:27 2020: Debug: rest: Reply-Message := "Mac is empty" (25) Mon Mar 16 15:07:27 2020: Debug: rest: Parsing attribute "control:PacketFence-Authorization-Status" (25) Mon Mar 16 15:07:27 2020: Debug: rest: EXPAND allow (25) Mon Mar 16 15:07:27 2020: Debug: rest: --> allow (25) Mon Mar 16 15:07:27 2020: Debug: rest: PacketFence-Authorization-Status := "allow" (25) Mon Mar 16 15:07:27 2020: Debug: [rest] = reject (25) Mon Mar 16 15:07:27 2020: Debug: } # if ( !EAP-Message ) = reject (25) Mon Mar 16 15:07:27 2020: Debug: } # authorize = reject (25) Mon Mar 16 15:07:27 2020: Debug: Using Post-Auth-Type Reject (25) Mon Mar 16 15:07:27 2020: Debug: # Executing group from file /usr/local/pf/raddb/sites-enabled/packetfence (25) Mon Mar 16 15:07:27 2020: Debug: Post-Auth-Type REJECT { (25) Mon Mar 16 15:07:27 2020: Debug: policy packetfence-set-tenant-id { (25) Mon Mar 16 15:07:27 2020: Debug: if (!NAS-IP-Address || NAS-IP-Address == "0.0.0.0"){ (25) Mon Mar 16 15:07:27 2020: Debug: if (!NAS-IP-Address || NAS-IP-Address == "0.0.0.0") -> FALSE (25) Mon Mar 16 15:07:27 2020: Debug: if ( "%{%{control:PacketFence-Tenant-Id}:-0}" == "0") { (25) Mon Mar 16 15:07:27 2020: Debug: EXPAND %{%{control:PacketFence-Tenant-Id}:-0} (25) Mon Mar 16 15:07:27 2020: Debug: --> 1 (25) Mon Mar 16 15:07:27 2020: Debug: if ( "%{%{control:PacketFence-Tenant-Id}:-0}" == "0") -> FALSE (25) Mon Mar 16 15:07:27 2020: Debug: if ( &control:PacketFence-Tenant-Id == 0 ) { (25) Mon Mar 16 15:07:27 2020: Debug: if ( &control:PacketFence-Tenant-Id == 0 ) -> FALSE (25) Mon Mar 16 15:07:27 2020: Debug: } # policy packetfence-set-tenant-id = noop (25) Mon Mar 16 15:07:27 2020: Debug: update { (25) Mon Mar 16 15:07:27 2020: Debug: } # update = noop (25) Mon Mar 16 15:07:27 2020: Debug: if (! EAP-Type || (EAP-Type != TTLS && EAP-Type != PEAP) ) { (25) Mon Mar 16 15:07:27 2020: Debug: if (! EAP-Type || (EAP-Type != TTLS && EAP-Type != PEAP) ) -> TRUE (25) Mon Mar 16 15:07:27 2020: Debug: if (! EAP-Type || (EAP-Type != TTLS && EAP-Type != PEAP) ) { (25) Mon Mar 16 15:07:27 2020: Debug: policy packetfence-audit-log-reject { (25) Mon Mar 16 15:07:27 2020: Debug: if (&User-Name && (&User-Name == "dummy")) { (25) Mon Mar 16 15:07:27 2020: Debug: if (&User-Name && (&User-Name == "dummy")) -> FALSE (25) Mon Mar 16 15:07:27 2020: Debug: else { (25) Mon Mar 16 15:07:27 2020: Debug: policy request-timing { (25) Mon Mar 16 15:07:27 2020: Debug: if ("%{%{control:PacketFence-Request-Time}:-0}" != 0) { (25) Mon Mar 16 15:07:27 2020: Debug: EXPAND %{%{control:PacketFence-Request-Time}:-0} (25) Mon Mar 16 15:07:27 2020: Debug: --> 0 (25) Mon Mar 16 15:07:27 2020: Debug: if ("%{%{control:PacketFence-Request-Time}:-0}" != 0) -> FALSE (25) Mon Mar 16 15:07:27 2020: Debug: } # policy request-timing = noop (25) Mon Mar 16 15:07:27 2020: Debug: sql_reject: EXPAND type.reject.query (25) Mon Mar 16 15:07:27 2020: Debug: sql_reject: --> type.reject.query (25) Mon Mar 16 15:07:27 2020: Debug: sql_reject: Using query template 'query' (25) Mon Mar 16 15:07:27 2020: Debug: sql_reject: EXPAND %{User-Name} (25) Mon Mar 16 15:07:27 2020: Debug: sql_reject: --> evren (25) Mon Mar 16 15:07:27 2020: Debug: sql_reject: SQL-User-Name set to 'evren' (25) Mon Mar 16 15:07:27 2020: Debug: sql_reject: EXPAND INSERT INTO radius_audit_log ( mac, ip, computer_name, user_name, stripped_user_name, realm, event_type, switch_id, switch_mac, switch_ip_address, radius_source_ip_address, called_station_id, calling_station_id, nas_port_type, ssid, nas_port_id, ifindex, nas_port, connection_type, nas_ip_address, nas_identifier, auth_status, reason, auth_type, eap_type, role, node_status, profile, source, auto_reg, is_phone, pf_domain, uuid, radius_request, radius_reply, request_time, tenant_id, radius_ip) VALUES ( '%{request:Calling-Station-Id}', '%{request:Framed-IP-Address}', '%{%{control:PacketFence-Computer-Name}:-N/A}', '%{request:User-Name}', '%{request:Stripped-User-Name}', '%{request:Realm}', 'Radius-Access-Request', '%{%{control:PacketFence-Switch-Id}:-N/A}', '%{%{control:PacketFence-Switch-Mac}:-N/A}', '%{%{control:PacketFence-Switch-Ip-Address}:-N/A}', '%{Packet-Src-IP-Address}', '%{request:Called-Station-Id}', '%{request:Calling-Station-Id}', '%{request:NAS-Port-Type}', '%{request:Called-Station-SSID}', '%{request:NAS-Port-Id}', '%{%{control:PacketFence-IfIndex}:-N/A}', '%{request:NAS-Port}', '%{%{control:PacketFence-Connection-Type}:-N/A}', '%{request:NAS-IP-Address}', '%{request:NAS-Identifier}', 'Reject', '%{request:Module-Failure-Message}', '%{control:Auth-Type}', '%{request:EAP-Type}', '%{%{control:PacketFence-Role}:-N/A}', '%{%{control:PacketFence-Status}:-N/A}', '%{%{control:PacketFence-Profile}:-N/A}', '%{%{control:PacketFence-Source}:-N/A}', '%{%{control:PacketFence-AutoReg}:-0}', '%{%{control:PacketFence-IsPhone}:-0}', '%{request:PacketFence-Domain}', '', '%{pairs:&request:[*]}','%{pairs:&reply:[*]}', '%{%{control:PacketFence-Request-Time}:-N/A}', '%{control:PacketFence-Tenant-Id}', '%{request:PacketFence-Radius-Ip}') (25) Mon Mar 16 15:07:27 2020: Debug: sql_reject: --> INSERT INTO radius_audit_log ( mac, ip, computer_name, user_name, stripped_user_name, realm, event_type, switch_id, switch_mac, switch_ip_address, radius_source_ip_address, called_station_id, calling_station_id, nas_port_type, ssid, nas_port_id, ifindex, nas_port, connection_type, nas_ip_address, nas_identifier, auth_status, reason, auth_type, eap_type, role, node_status, profile, source, auto_reg, is_phone, pf_domain, uuid, radius_request, radius_reply, request_time, tenant_id, radius_ip) VALUES ( '192.168.30.1', '', 'N/A', 'evren', '', '', 'Radius-Access-Request', 'N/A', 'N/A', 'N/A', '192.168.30.6', '', '192.168.30.1', '', '', '', 'N/A', '', 'N/A', '192.168.30.6', 'MikroTik', 'Reject', '', '', '', 'N/A', 'N/A', 'N/A', 'N/A', '0', '0', '', '', 'User-Name =3D =22evren=22=2C NAS-IP-Address =3D 192.168.30.6=2C Service-Type =3D Login-User=2C Calling-Station-Id =3D =22192.168.30.1=22=2C NAS-Identifier =3D =22MikroTik=22=2C Event-Timestamp =3D =22Mar 16 2020 15:07:27 =2B03=22=2C MS-CHAP-Challenge =3D 0xa0f07329316086f83e9d6cf9be1dbb8b=2C MS-CHAP2-Response =3D 0x0000a188e5fb5bcc68173aa94693bed6ed5e0000000000000000a2dc302e211a880cc3c117ca130ec341de241f0888f480ef=2C FreeRADIUS-Client-IP-Address =3D 192.168.30.6=2C PacketFence-KeyBalanced =3D =2285bde241d7f98ac7a0bab114b852c753=22=2C User-Password =3D =22=2A=2A=2A=2A=2A=2A=22=2C SQL-User-Name =3D =22evren=22','Reply-Message =3D =22Mac is empty=22', '0', '1', '') (25) Mon Mar 16 15:07:27 2020: Debug: sql_reject: Executing query: INSERT INTO radius_audit_log ( mac, ip, computer_name, user_name, stripped_user_name, realm, event_type, switch_id, switch_mac, switch_ip_address, radius_source_ip_address, called_station_id, calling_station_id, nas_port_type, ssid, nas_port_id, ifindex, nas_port, connection_type, nas_ip_address, nas_identifier, auth_status, reason, auth_type, eap_type, role, node_status, profile, source, auto_reg, is_phone, pf_domain, uuid, radius_request, radius_reply, request_time, tenant_id, radius_ip) VALUES ( '192.168.30.1', '', 'N/A', 'evren', '', '', 'Radius-Access-Request', 'N/A', 'N/A', 'N/A', '192.168.30.6', '', '192.168.30.1', '', '', '', 'N/A', '', 'N/A', '192.168.30.6', 'MikroTik', 'Reject', '', '', '', 'N/A', 'N/A', 'N/A', 'N/A', '0', '0', '', '', 'User-Name =3D =22evren=22=2C NAS-IP-Address =3D 192.168.30.6=2C Service-Type =3D Login-User=2C Calling-Station-Id =3D =22192.168.30.1=22=2C NAS-Identifier =3D =22MikroTik=22=2C Event-Timestamp =3D =22Mar 16 2020 15:07:27 =2B03=22=2C MS-CHAP-Challenge =3D 0xa0f07329316086f83e9d6cf9be1dbb8b=2C MS-CHAP2-Response =3D 0x0000a188e5fb5bcc68173aa94693bed6ed5e0000000000000000a2dc302e211a880cc3c117ca130ec341de241f0888f480ef=2C FreeRADIUS-Client-IP-Address =3D 192.168.30.6=2C PacketFence-KeyBalanced =3D =2285bde241d7f98ac7a0bab114b852c753=22=2C User-Password =3D =22=2A=2A=2A=2A=2A=2A=22=2C SQL-User-Name =3D =22evren=22','Reply-Message =3D =22Mac is empty=22', '0', '1', '') (25) Mon Mar 16 15:07:27 2020: Debug: sql_reject: SQL query returned: success (25) Mon Mar 16 15:07:27 2020: Debug: sql_reject: 1 record(s) updated (25) Mon Mar 16 15:07:27 2020: Debug: [sql_reject] = ok (25) Mon Mar 16 15:07:27 2020: Debug: } # else = ok (25) Mon Mar 16 15:07:27 2020: Debug: } # policy packetfence-audit-log-reject = ok (25) Mon Mar 16 15:07:27 2020: Debug: } # if (! EAP-Type || (EAP-Type != TTLS && EAP-Type != PEAP) ) = ok (25) Mon Mar 16 15:07:27 2020: Debug: if ("%{%{control:PacketFence-Proxied-From}:-False}" == "True") { (25) Mon Mar 16 15:07:27 2020: Debug: EXPAND %{%{control:PacketFence-Proxied-From}:-False} (25) Mon Mar 16 15:07:27 2020: Debug: --> False (25) Mon Mar 16 15:07:27 2020: Debug: if ("%{%{control:PacketFence-Proxied-From}:-False}" == "True") -> FALSE (25) Mon Mar 16 15:07:27 2020: Debug: attr_filter.access_reject: EXPAND %{User-Name} (25) Mon Mar 16 15:07:27 2020: Debug: attr_filter.access_reject: --> evren (25) Mon Mar 16 15:07:27 2020: Debug: attr_filter.access_reject: Matched entry DEFAULT at line 11 (25) Mon Mar 16 15:07:27 2020: Debug: [attr_filter.access_reject] = updated (25) Mon Mar 16 15:07:27 2020: Debug: attr_filter.packetfence_post_auth: EXPAND %{User-Name} (25) Mon Mar 16 15:07:27 2020: Debug: attr_filter.packetfence_post_auth: --> evren (25) Mon Mar 16 15:07:27 2020: Debug: attr_filter.packetfence_post_auth: Matched entry DEFAULT at line 10 (25) Mon Mar 16 15:07:27 2020: Debug: [attr_filter.packetfence_post_auth] = updated (25) Mon Mar 16 15:07:27 2020: Debug: [eap] = noop (25) Mon Mar 16 15:07:27 2020: Debug: policy remove_reply_message_if_eap { (25) Mon Mar 16 15:07:27 2020: Debug: if (&reply:EAP-Message && &reply:Reply-Message) { (25) Mon Mar 16 15:07:27 2020: Debug: if (&reply:EAP-Message && &reply:Reply-Message) -> FALSE (25) Mon Mar 16 15:07:27 2020: Debug: else { (25) Mon Mar 16 15:07:27 2020: Debug: [noop] = noop (25) Mon Mar 16 15:07:27 2020: Debug: } # else = noop (25) Mon Mar 16 15:07:27 2020: Debug: } # policy remove_reply_message_if_eap = noop (25) Mon Mar 16 15:07:27 2020: Debug: linelog: EXPAND messages.%{%{reply:Packet-Type}:-default} (25) Mon Mar 16 15:07:27 2020: Debug: linelog: --> messages.Access-Reject (25) Mon Mar 16 15:07:27 2020: Debug: linelog: EXPAND [mac:%{Calling-Station-Id}] Rejected user: %{User-Name} (25) Mon Mar 16 15:07:27 2020: Debug: linelog: --> [mac:192.168.30.1] Rejected user: evren (25) Mon Mar 16 15:07:27 2020: Debug: [linelog] = ok (25) Mon Mar 16 15:07:27 2020: Debug: } # Post-Auth-Type REJECT = updated (25) Mon Mar 16 15:07:27 2020: Debug: Delaying response for 1.000000 seconds (25) Mon Mar 16 15:07:27 2020: Debug: (25) Discarding duplicate request from client 192.168.30.6/32 port 35675 - ID: 95 due to delayed response (25) Mon Mar 16 15:07:28 2020: Debug: (25) Discarding duplicate request from client 192.168.30.6/32 port 35675 - ID: 95 due to delayed response (25) Mon Mar 16 15:07:28 2020: Debug: Sending delayed response (25) Mon Mar 16 15:07:28 2020: Debug: Sent Access-Reject Id 95 from 192.168.30.2:1812 to 192.168.30.6:35675 length 34 (25) Mon Mar 16 15:07:28 2020: Debug: Reply-Message = "Mac is empty"
_______________________________________________ PacketFence-users mailing list [email protected] https://lists.sourceforge.net/lists/listinfo/packetfence-users
