Mon Mar 16 15:07:23 2020: Debug: suffix: No '@' in User-Name = "evren", skipping NULL due to config.
You have your realms setup correctly? Can you post your realms configuration and auth configuration. On Tue, Mar 17, 2020, 7:06 AM evren korkmaz via PacketFence-users < [email protected]> wrote: > 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 >
_______________________________________________ PacketFence-users mailing list [email protected] https://lists.sourceforge.net/lists/listinfo/packetfence-users
