Re: [PacketFence-users] RADIUS authentication failure

[Ludovic Z. <lz...@in...>]

Hello Jeff,

Your configuration looks good.

Your authentication is failing in radius so that’s normal that you don’t see it in the Packetfence.log.

Show me the logs/radius.log related to your device.

Thanks,

Ludovic Zammit
lz...@in... <mailto:lz...@in...> ::  +1.514.447.4918 (x145) ::  www.inverse.ca <http://www.inverse.ca/>
Inverse inc. :: Leaders behind SOGo (http://www.sogo.nu <http://www.sogo.nu/>) and PacketFence (http://packetfence.org <http://packetfence.org/>) 




> On Feb 19, 2020, at 3:43 PM, Jeff Linden <JL...@je...> wrote:
> 
> Ludovic,
>  
> Here are the results.
>  
> # chroot /chroots/<MyDomain> ntlm_auth --username <myusername> --password=<mypassword>
> NT_STATUS_OK: Success (0x0)
>  
> Domain.conf
> -----------------
>  
> [MyDomain]
> workgroup=MYDOMAIN
> ntlm_cache_batch=disabled
> status=enabled
> sticky_dc=*
> registration=0
> ou=Computers
> ntlmv2_only=0
> dns_name=MyDomain.com <http://mydomain.com/>
> ntlm_cache_filter=(&(samAccountName=*)(!(|(lockoutTime=>0)(userAccountControl:1.2.840.113556.1.4.803:=2))))
> server_name=PacketFence
> dns_servers=<DNS IP>
> ad_server=<AD IP>
> ntlm_cache_batch_one_at_a_time=disabled
> ntlm_cache_expiry=3600
> ntlm_cache_on_connection=disabled
>  
> [My2ndDomain]
> status=enabled
> ntlm_cache_batch=disabled
> workgroup=MY2NDDOMAIN
> ntlm_cache_filter=(&(samAccountName=*)(!(|(lockoutTime=>0)(userAccountControl:1.2.840.113556.1.4.803:=2))))
> dns_name=My2ndDomain.com <http://my2nddomain.com/>
> ou=Computers
> ntlmv2_only=0
> sticky_dc=*
> registration=0
> ad_server=<AD IP>
> dns_servers=<DNS IP>
> server_name=PacketFence
> ntlm_cache_on_connection=disabled
> ntlm_cache_expiry=3600
> ntlm_cache_batch_one_at_a_time=disabled
>  
> [My3rdDomain]
> ntlm_cache_filter=(&(samAccountName=*)(!(|(lockoutTime=>0)(userAccountControl:1.2.840.113556.1.4.803:=2))))
> dns_name=My3rdDomain.com <http://my3rddomain.com/>
> ntlmv2_only=0
> ou=Computers
> registration=0
> sticky_dc=*
> status=enabled
> ntlm_cache_batch=disabled
> workgroup=MY3RDDOMAIN
> ntlm_cache_on_connection=disabled
> ntlm_cache_expiry=3600
> ntlm_cache_batch_one_at_a_time=disabled
> ad_server=<AD IP>
> dns_servers=<DNS IP>
> server_name=PacketFence
>  
>  
>  
> realm.conf  (Please note, I added the domain to Default and NULL during testing.  Makes no difference with or without.  I would expect NOT to be having the domain specified there.)
> -----------------
>  
> [1 DEFAULT]
> eduroam_radius_acct_proxy_type=load-balance
> permit_custom_attributes=disabled
> radius_auth_compute_in_pf=enabled
> radius_acct_proxy_type=load-balance
> radius_auth_proxy_type=keyed-balance
> domain=MyDomain
> radius_acct=
> radius_auth=
> eduroam_radius_auth_proxy_type=keyed-balance
> eduroam_radius_auth=
> eduroam_radius_auth_compute_in_pf=enabled
> eduroam_radius_acct=
>  
> [1 NULL]
> eduroam_radius_auth_proxy_type=keyed-balance
> radius_auth=
> radius_acct=
> domain=MyDomain
> eduroam_radius_acct=
> eduroam_radius_auth_compute_in_pf=enabled
> eduroam_radius_auth=
> radius_auth_compute_in_pf=enabled
> radius_acct_proxy_type=load-balance
> permit_custom_attributes=disabled
> eduroam_radius_acct_proxy_type=load-balance
> radius_auth_proxy_type=keyed-balance
>  
> [1 MyDomain]
> radius_acct=
> eduroam_radius_auth_proxy_type=keyed-balance
> radius_auth_compute_in_pf=enabled
> permit_custom_attributes=enabled
> radius_strip_username=disabled
> radius_auth=
> eduroam_radius_acct_proxy_type=load-balance
> admin_strip_username=enabled
> eduroam_radius_auth_compute_in_pf=enabled
> radius_acct_proxy_type=load-balance
> portal_strip_username=enabled
> radius_auth_proxy_type=keyed-balance
> eduroam_radius_acct=
> domain=MyDomain
> eduroam_radius_auth=
> ldap_source=MyDomain
>  
> [1 MY2ndDomain]
> radius_auth_proxy_type=keyed-balance
> eduroam_radius_acct=
> domain=MY2ndDomain
> eduroam_radius_auth=
> radius_auth=
> eduroam_radius_acct_proxy_type=load-balance
> admin_strip_username=enabled
> radius_acct_proxy_type=load-balance
> eduroam_radius_auth_compute_in_pf=enabled
> portal_strip_username=enabled
> radius_acct=
> eduroam_radius_auth_proxy_type=keyed-balance
> radius_auth_compute_in_pf=enabled
> radius_strip_username=enabled
> permit_custom_attributes=enabled
> ldap_source=MY2ndDomain
>  
> [1 My3rdDomain]
> eduroam_radius_acct=
> radius_auth_proxy_type=keyed-balance
> eduroam_radius_auth=
> admin_strip_username=enabled
> eduroam_radius_auth_compute_in_pf=enabled
> portal_strip_username=enabled
> radius_acct_proxy_type=load-balance
> radius_auth=
> eduroam_radius_acct_proxy_type=load-balance
> radius_auth_compute_in_pf=enabled
> permit_custom_attributes=enabled
> radius_strip_username=enabled
> radius_acct=
> eduroam_radius_auth_proxy_type=keyed-balance
> ldap_source=My3rdDomain
> domain=My3rdDomain
>  
>  
>  
> Jeff Linden | Corporate Infrastructure Specialist
> DAIFUKU NORTH AMERICA
> 30100 Cabot Drive, Novi MI 48377
> (248) 419-7530
> 
> DAIFUKU <http://www.daifukuna.com/>
> Always an Edge Ahead
>  
> From: Ludovic Zammit <lz...@in... <mailto:lz...@in...>> 
> Sent: Tuesday, February 18, 2020 8:16 AM
> To: Jeff Linden <JL...@je... <mailto:JL...@je...>>
> Cc: pac...@li... <mailto:pac...@li...>
> Subject: Re: [PacketFence-users] RADIUS authentication failure
>  
> Hello Jeff,
>  
> Your issue there is that you’re 802.1x fails so it fall back to Mac authentication.
>  
> Find why you 802.1x fails and you would ave your answers. It seems that it’s not doing the ntlm authentication properly, could you try that:
>  
> chroot /chroots/YOUR_DOMAIN_NAME/ ntlm_auth —username=bob --password=bob
>  
> Show me the output.
>  
> Also, could you show me your domain.conf and the realm.conf
>  
> Thanks,
> 
> Ludovic Zammit
> lz...@in... <mailto:lz...@in...> ::  +1.514.447.4918 (x145) ::  www.inverse.ca <http://www.inverse.ca/>
> Inverse inc. :: Leaders behind SOGo (http://www.sogo.nu <http://www.sogo.nu/>) and PacketFence (http://packetfence.org <http://packetfence.org/>) 
>  
> 
> 
> 
> 
> On Feb 17, 2020, at 6:21 PM, Jeff Linden <JL...@je... <mailto:JL...@je...>> wrote:
>  
> Ludovic,
>  
> Here is the information from packetfence.log and profiles.conf.  I noticed that the entries created in packetfence.log only relate to the MAC authentication, not the user authentication.  To illustrate, I also included the log data from radius.log for the same connection event.  The entries in radius.log for the user authentication failure occur well before the entries in packetfence.log. 
>  
> As a side note (not significant, but something I’ve wondered about), I notice there are no entries in packetfence.log about user authentication and I believe this changed after upgrading from the previous version.  Before upgrading to 9.0.2, I was unaware of radius.log and in my earlier testing only ever referenced packetfence.log.
>  
>  
> Packetfence.log
> ---------------------
>  
> Feb 17 18:05:59 nadc1-pfence-01 packetfence_httpd.aaa: httpd.aaa(165389) INFO: [mac:ec:f4:bb:33:40:89] handling radius autz request: from switch_ip => (172.20.252.3), connection_type => Ethernet-NoEAP,switch_mac => (58:00:bb:37:ac:80), mac => [ec:f4:bb:33:40:89], port => ge-0/0/11.0, username => "ecf4bb334089" (pf::radius::authorize)
> Feb 17 18:05:59 nadc1-pfence-01 packetfence_httpd.aaa: httpd.aaa(165389) INFO: [mac:ec:f4:bb:33:40:89] Instantiate profile default (pf::Connection::ProfileFactory::_from_profile)
> Feb 17 18:05:59 nadc1-pfence-01 packetfence_httpd.aaa: httpd.aaa(165389) INFO: [mac:ec:f4:bb:33:40:89] is of status unreg; belongs into registration VLAN (pf::role::getRegistrationRole)
> Feb 17 18:05:59 nadc1-pfence-01 packetfence_httpd.aaa: httpd.aaa(165389) INFO: [mac:ec:f4:bb:33:40:89] (172.20.252.3) Added VLAN PFRegistration to the returned RADIUS Access-Accept (pf::Switch::returnRadiusAccessAccept)
> Feb 17 18:05:59 nadc1-pfence-01 packetfence_httpd.aaa: httpd.aaa(165389) INFO: [mac:ec:f4:bb:33:40:89] handling radius autz request: from switch_ip => (172.20.252.3), connection_type => Ethernet-NoEAP,switch_mac => (58:00:bb:37:ac:80), mac => [ec:f4:bb:33:40:89], port => ge-0/0/11.0, username => "ecf4bb334089" (pf::radius::authorize)
> Feb 17 18:05:59 nadc1-pfence-01 packetfence_httpd.aaa: httpd.aaa(165389) INFO: [mac:ec:f4:bb:33:40:89] Instantiate profile default (pf::Connection::ProfileFactory::_from_profile)
> Feb 17 18:05:59 nadc1-pfence-01 packetfence_httpd.aaa: httpd.aaa(165389) INFO: [mac:ec:f4:bb:33:40:89] is of status unreg; belongs into registration VLAN (pf::role::getRegistrationRole)
> Feb 17 18:05:59 nadc1-pfence-01 packetfence_httpd.aaa: httpd.aaa(165389) INFO: [mac:ec:f4:bb:33:40:89] (172.20.252.3) Added VLAN PFRegistration to the returned RADIUS Access-Accept (pf::Switch::returnRadiusAccessAccept)
> Feb 17 18:06:00 nadc1-pfence-01 pfqueue: pfqueue(38087) WARN: [mac:ec:f4:bb:33:40:89] Unable to match MAC address to IP '172.20.252.11' (pf::ip4log::ip2mac)
> Feb 17 18:06:00 nadc1-pfence-01 pfqueue: pfqueue(38087) INFO: [mac:ec:f4:bb:33:40:89] oldip (172.20.252.10) and newip (172.20.252.11) are different for ec:f4:bb:33:40:89 - closing ip4log entry (pf::api::update_ip4log)
> Feb 17 18:06:00 nadc1-pfence-01 pfqueue: pfqueue(38087) WARN: [mac:ec:f4:bb:33:40:89] Unable to match MAC address to IP '172.20.252.11' (pf::ip4log::ip2mac)
> Feb 17 18:06:00 nadc1-pfence-01 pfqueue: pfqueue(38087) INFO: [mac:ec:f4:bb:33:40:89] oldip (172.20.252.10) and newip (172.20.252.11) are different for ec:f4:bb:33:40:89 - closing ip4log entry (pf::api::update_ip4log)
> Feb 17 18:06:00 nadc1-pfence-01 pfqueue: pfqueue(38087) WARN: [mac:ec:f4:bb:33:40:89] Unable to pull accounting history for device ec:f4:bb:33:40:89. The history set doesn't exist yet. (pf::accounting_events_history::latest_mac_history)
> Feb 17 18:06:00 nadc1-pfence-01 pfqueue: pfqueue(38087) WARN: [mac:ec:f4:bb:33:40:89] Unable to pull accounting history for device ec:f4:bb:33:40:89. The history set doesn't exist yet. (pf::accounting_events_history::latest_mac_history)
> Feb 17 18:06:00 nadc1-pfence-01 pfqueue: pfqueue(38087) WARN: [mac:ec:f4:bb:33:40:89] Unable to pull accounting history for device ec:f4:bb:33:40:89. The history set doesn't exist yet. (pf::accounting_events_history::latest_mac_history)
> Feb 17 18:06:00 nadc1-pfence-01 pfqueue: pfqueue(38087) WARN: [mac:ec:f4:bb:33:40:89] Unable to pull accounting history for device ec:f4:bb:33:40:89. The history set doesn't exist yet. (pf::accounting_events_history::latest_mac_history)
> Feb 17 18:06:09 nadc1-pfence-01 pfqueue: pfqueue(38209) WARN: [mac:ec:f4:bb:33:40:89] Unable to pull accounting history for device ec:f4:bb:33:40:89. The history set doesn't exist yet. (pf::accounting_events_history::latest_mac_history)
> Feb 17 18:06:09 nadc1-pfence-01 pfqueue: pfqueue(38209) WARN: [mac:ec:f4:bb:33:40:89] Unable to pull accounting history for device ec:f4:bb:33:40:89. The history set doesn't exist yet. (pf::accounting_events_history::latest_mac_history)
> Feb 17 18:06:09 nadc1-pfence-01 pfqueue: pfqueue(38159) WARN: [mac:ec:f4:bb:33:40:89] Unable to pull accounting history for device ec:f4:bb:33:40:89. The history set doesn't exist yet. (pf::accounting_events_history::latest_mac_history)
> Feb 17 18:06:09 nadc1-pfence-01 pfqueue: pfqueue(38159) WARN: [mac:ec:f4:bb:33:40:89] Unable to pull accounting history for device ec:f4:bb:33:40:89. The history set doesn't exist yet. (pf::accounting_events_history::latest_mac_history)
>  
>  
>  
>  
>  
>  
>  
>  
>  
>  
> Profiles.conf
> ------------------
> #
> # Copyright (C) 2005-2019 Inverse inc.
> #
> # See the enclosed file COPYING for license information (GPL).
> # If you did not receive this file, see
> # http://www.fsf.org/licensing/licenses/gpl.html <http://www.fsf.org/licensing/licenses/gpl.html>
> [default]
> logo=/common/img/daifuku.png
> redirecturl=http://www.daifuku.com/us <http://www.daifuku.com/us>
> always_use_redirecturl=enabled
> access_registration_when_registered=enabled
> network_logoff=enabled
>  
> [Ethernet-EAP]
> autoregister=enabled
> filter=connection_type:Ethernet-EAP
> description=Ethernet-EAP
> locale=
> sources=MyDomain,MyDomain2,Mydomain3
> logo=daifuku.png
> network_logoff=disabled
> access_registration_when_registered=disabled
> #
> # Copyright (C) 2005-2019 Inverse inc.
> #
> # See the enclosed file COPYING for license information (GPL).
> # If you did not receive this file, see
> # http://www.fsf.org/licensing/licenses/gpl.html <http://www.fsf.org/licensing/licenses/gpl.html>
>  
>  
>  
>  
>  
> Radius.log
> --------------
>  
> Feb 17 18:05:21 nadc1-pfence-01 auth[7557]: rlm_sql (sql): Closing connection (347): Hit idle_timeout, was idle for 124 seconds
> Feb 17 18:05:21 nadc1-pfence-01 auth[7557]: rlm_sql (sql): Closing connection (346): Hit idle_timeout, was idle for 124 seconds
> Feb 17 18:05:21 nadc1-pfence-01 auth[7557]: rlm_sql (sql): Closing connection (348): Hit idle_timeout, was idle for 124 seconds
> Feb 17 18:05:21 nadc1-pfence-01 auth[7557]: rlm_sql (sql): Opening additional connection (349), 1 of 64 pending slots used
> Feb 17 18:05:21 nadc1-pfence-01 auth[7557]: Need 2 more connections to reach min connections (3)
> Feb 17 18:05:21 nadc1-pfence-01 auth[7557]: rlm_sql (sql): Opening additional connection (350), 1 of 63 pending slots used
> Feb 17 18:05:22 nadc1-pfence-01 auth[7557]: Need 1 more connections to reach min connections (3)
> Feb 17 18:05:22 nadc1-pfence-01 auth[7557]: rlm_sql (sql): Opening additional connection (351), 1 of 62 pending slots used
> Feb 17 18:05:22 nadc1-pfence-01 auth[7557]: (72988)   Invalid user: [MyDomain\MyUser] (from client 1.1.1.1/32 port 566 cli ec:f4:bb:33:40:89 via TLS tunnel)
> Feb 17 18:05:22 nadc1-pfence-01 auth[7557]: (72988)   Login incorrect (Failed retrieving values required to evaluate condition): [MyDomain\MyUser] (from client 1.1.1.1/32 port 566 cli ec:f4:bb:33:40:89 via TLS tunnel)
> Feb 17 18:05:21 nadc1-pfence-01 auth[7557]: rlm_sql (sql): Closing connection (347): Hit idle_timeout, was idle for 124 seconds
> Feb 17 18:05:21 nadc1-pfence-01 auth[7557]: rlm_sql (sql): Closing connection (346): Hit idle_timeout, was idle for 124 seconds
> Feb 17 18:05:21 nadc1-pfence-01 auth[7557]: rlm_sql (sql): Closing connection (348): Hit idle_timeout, was idle for 124 seconds
> Feb 17 18:05:21 nadc1-pfence-01 auth[7557]: rlm_sql (sql): Opening additional connection (349), 1 of 64 pending slots used
> Feb 17 18:05:21 nadc1-pfence-01 auth[7557]: Need 2 more connections to reach min connections (3)
> Feb 17 18:05:21 nadc1-pfence-01 auth[7557]: rlm_sql (sql): Opening additional connection (350), 1 of 63 pending slots used
> Feb 17 18:05:22 nadc1-pfence-01 auth[7557]: Need 1 more connections to reach min connections (3)
> Feb 17 18:05:22 nadc1-pfence-01 auth[7557]: rlm_sql (sql): Opening additional connection (351), 1 of 62 pending slots used
> Feb 17 18:05:22 nadc1-pfence-01 auth[7557]: (72988)   Invalid user: [MyDomain\MyUser] (from client 1.1.1.1/32 port 566 cli ec:f4:bb:33:40:89 via TLS tunnel)
> Feb 17 18:05:22 nadc1-pfence-01 auth[7557]: (72988)   Login incorrect (Failed retrieving values required to evaluate condition): [MyDomain\MyUser] (from client 1.1.1.1/32 port 566 cli ec:f4:bb:33:40:89 via TLS tunnel)
> Feb 17 18:05:22 nadc1-pfence-01 auth[7557]: [mac:ec:f4:bb:33:40:89] Rejected user: MyDomain\MyUser
> Feb 17 18:05:22 nadc1-pfence-01 auth[7557]: (72989) Login incorrect (eap_peap: The users session was previously rejected: returning reject (again.)): [MyDomain\MyUser] (from client 1.1.1.1/32 port 566 cli ec:f4:bb:33:40:89)
> Feb 17 18:05:22 nadc1-pfence-01 auth[7557]: [mac:ec:f4:bb:33:40:89] Rejected user: MyDomain\MyUser
> Feb 17 18:05:22 nadc1-pfence-01 auth[7557]: (72989) Login incorrect (eap_peap: The users session was previously rejected: returning reject (again.)): [MyDomain\MyUser] (from client 1.1.1.1/32 port 566 cli ec:f4:bb:33:40:89)
> Feb 17 18:05:59 nadc1-pfence-01 auth[7557]: Need 7 more connections to reach 10 spares
> Feb 17 18:05:59 nadc1-pfence-01 auth[7557]: rlm_sql (sql): Opening additional connection (352), 1 of 61 pending slots used
> Feb 17 18:05:59 nadc1-pfence-01 auth[7557]: rlm_rest (rest): Closing connection (133): Hit idle_timeout, was idle for 162 seconds
> Feb 17 18:05:59 nadc1-pfence-01 auth[7557]: rlm_rest (rest): Closing connection (134): Hit idle_timeout, was idle for 162 seconds
> Feb 17 18:05:59 nadc1-pfence-01 auth[7557]: rlm_rest (rest): Opening additional connection (135), 1 of 64 pending slots used
> Feb 17 18:05:59 nadc1-pfence-01 auth[7557]: Need 2 more connections to reach min connections (3)
> Feb 17 18:05:59 nadc1-pfence-01 auth[7557]: rlm_rest (rest): Opening additional connection (136), 1 of 63 pending slots used
> Feb 17 18:05:59 nadc1-pfence-01 auth[7557]: [mac:ec:f4:bb:33:40:89] Accepted user: ecf4bb334089 and returned VLAN PFRegistration
> Feb 17 18:05:59 nadc1-pfence-01 auth[7557]: (72994) Login OK: [ecf4bb334089] (from client 1.1.1.1/32 port 566 cli ec:f4:bb:33:40:89)
> Feb 17 18:05:59 nadc1-pfence-01 auth[7557]: Need 7 more connections to reach 10 spares
> Feb 17 18:05:59 nadc1-pfence-01 auth[7557]: rlm_sql (sql): Opening additional connection (352), 1 of 61 pending slots used
> Feb 17 18:05:59 nadc1-pfence-01 auth[7557]: rlm_rest (rest): Closing connection (133): Hit idle_timeout, was idle for 162 seconds
> Feb 17 18:05:59 nadc1-pfence-01 auth[7557]: rlm_rest (rest): Closing connection (134): Hit idle_timeout, was idle for 162 seconds
> Feb 17 18:05:59 nadc1-pfence-01 auth[7557]: rlm_rest (rest): Opening additional connection (135), 1 of 64 pending slots used
> Feb 17 18:05:59 nadc1-pfence-01 auth[7557]: Need 2 more connections to reach min connections (3)
> Feb 17 18:05:59 nadc1-pfence-01 auth[7557]: rlm_rest (rest): Opening additional connection (136), 1 of 63 pending slots used
> Feb 17 18:05:59 nadc1-pfence-01 auth[7557]: [mac:ec:f4:bb:33:40:89] Accepted user: ecf4bb334089 and returned VLAN PFRegistration
> Feb 17 18:05:59 nadc1-pfence-01 auth[7557]: (72994) Login OK: [ecf4bb334089] (from client 1.1.1.1/32 port 566 cli ec:f4:bb:33:40:89)
>  
>  
> Thank you,
>  
> Jeff
>  
> From: Ludovic Zammit <lz...@in... <mailto:lz...@in...>> 
> Sent: Monday, February 17, 2020 8:30 AM
> To: pac...@li... <mailto:pac...@li...>
> Cc: Jeff Linden <JL...@je... <mailto:JL...@je...>>
> Subject: Re: [PacketFence-users] RADIUS authentication failure
>  
> Hello Jeff,
>  
> Could you show me your profile.conf and grep MAC_ADDRESS in the logs/packetfence.log
>  
> Thanks,
> 
> Ludovic Zammit
> lz...@in... <mailto:lz...@in...> ::  +1.514.447.4918 (x145) ::  www.inverse.ca <http://www.inverse.ca/>
> Inverse inc. :: Leaders behind SOGo (http://www.sogo.nu <http://www.sogo.nu/>) and PacketFence (http://packetfence.org <http://packetfence.org/>) 
>  
> 
> 
> 
> 
> 
> 
> On Feb 14, 2020, at 10:44 AM, Jeff Linden via PacketFence-users <pac...@li... <mailto:pac...@li...>> wrote:
>  
> Thank you for your suggestion.  I do, indeed, have the autoregister box checked in the Connection Profile.  I believe, due to the authentication failure that I’m experiencing currently, the Connection Profile is not yet in play.
>  
> Jeff
>  
> From: G PL via PacketFence-users <pac...@li... <mailto:pac...@li...>> 
> Sent: Friday, February 14, 2020 1:47 AM
> To: pac...@li... <mailto:pac...@li...>
> Cc: G PL <pou...@gm... <mailto:pou...@gm...>>
> Subject: Re: [PacketFence-users] RADIUS authentication failure
>  
> Hello, perhaps in the portal, you don't have check the autoregister box
> 
> Le jeudi 13 février 2020, Jeff Linden via PacketFence-users <pac...@li... <mailto:pac...@li...>> a écrit :
> Hello all,
>  
> Before the end of the year, I had PacketFence version 8.<something> up and running in my lab with 802.1x authenticating successfully for multiple domains and auto-registering devices.  Captive portal was functioning, but very slowly.  It seemed none of the timing options in the Advanced Access Configuration->Captive Portal section were having any effect.
>  
> At this point, I decided to upgrade to version 9.2.0.  It was my first upgrade of PacketFence.  Maybe not the smoothest execution of an upgrade that was ever performed, but I did find the documentation about the extra perl scripts to run and the database schema updates, etc.
>  
> Once I completed the upgrade, I found the Captive Portal timing options appeared to work as expected.  However, 802.1x suffered a setback.  Users could authenticate successfully, but the nodes were not being automatically registered.  In fact, they didn’t show up in the Nodes pane at all.
>  
> After some fruitless investigation, I decided to wipe out the PacketFence configuration (including FreeRadius and MariaDB.)  Completely removed all the relevant software with the apt-get tool.  Then, I re-installed.  It didn’t go smoothly and I did it more than once, but the software is all back up and running.
>  
> I had saved some of my original configuration files and, along the way, tried to use some of them with mixed results.
>  
> In this final iteration, the only configuration file I restored from my original install is switches.conf.  And, I’m having no perceived difficulty with communication between the switches and PacketFence.
>  
> My current difficulty is that 802.1x authentication is failing and I cannot understand why.  Here are some configuration details:
>  
> ·         Three Active Directory domains are configured with successful Joins.
> ·         Matching Realms exist, one for each of the three domains
> ·         For each domain, a matching Authentication Source exists with a CatchAll rule setting the Role as default and Access duration as 5 days
> ·         There is one Connection Profile with all three Authentication Sources defined and the switch activated to Automatically Register Devices
> ·         Two switches, the same as in the original configuration.
> ·         Supplicant is Windows 10 (multiple clients producing the same result)
>                
>  
> Below is some log data.  The most significant things I can find are as follows:
>  
> ·         radius.log reports “Invalid user”.  I’ve sanitized the log data, but the domain, username and password are valid in the domain.  Windows is just passing on my user credentials I use every day.
> ·         raddb reports [packetfence-multi-domain] = fail.  I’ve not found any other clues in the log data to indicate why it is failing.  My hope was the Invalid User message would be more verbose here, but it’s not represented in the raddb data at all.
>  
> I will appreciate any assistance getting me pointed in the right direction.
>  
> Thank you,
>  
> Jeff
>  
> --------------------------
>  
>  
> /usr/local/pf/logs/radius.log
>  
> Feb 13 16:46:55 nadc1-pfence-01 auth[7557]: (49309)   Invalid user: [MYDOMAIN\myuser] (from client 1.1.1.1/32 <http://1.1.1.1/32> port 564 cli f0:1f:af:23:73:6d via TLS tunnel)
> Feb 13 16:46:55 nadc1-pfence-01 auth[7557]: (49309)   Login incorrect (Failed retrieving values required to evaluate condition): [MYDOMAIN\myuser] (from client 1.1.1.1/32 <http://1.1.1.1/32> port 564 cli f0:1f:af:23:73:6d via TLS tunnel)
> Feb 13 16:46:55 nadc1-pfence-01 auth[7557]: [mac:f0:1f:af:23:73:6d] Rejected user: MYDOMAIN\myuser
> Feb 13 16:46:55 nadc1-pfence-01 auth[7557]: (49310) Login incorrect (eap_peap: The users session was previously rejected: returning reject (again.)): [MYDOMAIN\myuser] (from client 1.1.1.1/32 <http://1.1.1.1/32> port 564 cli f0:1f:af:23:73:6d)
> Feb 13 16:46:55 nadc1-pfence-01 auth[7557]: Need 2 more connections to reach 10 spares
> Feb 13 16:46:55 nadc1-pfence-01 auth[7557]: rlm_sql (sql): Opening additional connection (255), 1 of 56 pending slots used
> Feb 13 16:46:55 nadc1-pfence-01 auth[7557]: (49309)   Invalid user: [MYDOMAIN\myuser] (from client 1.1.1.1/32 <http://1.1.1.1/32> port 564 cli f0:1f:af:23:73:6d via TLS tunnel)
> Feb 13 16:46:55 nadc1-pfence-01 auth[7557]: (49309)   Login incorrect (Failed retrieving values required to evaluate condition): [MYDOMAIN\myuser] (from client 1.1.1.1/32 <http://1.1.1.1/32> port 564 cli f0:1f:af:23:73:6d via TLS tunnel)
> Feb 13 16:46:55 nadc1-pfence-01 auth[7557]: [mac:f0:1f:af:23:73:6d] Rejected user: MYDOMAIN\myuser
> Feb 13 16:46:55 nadc1-pfence-01 auth[7557]: (49310) Login incorrect (eap_peap: The users session was previously rejected: returning reject (again.)): [MYDOMAIN\myuser] (from client 1.1.1.1/32 <http://1.1.1.1/32> port 564 cli f0:1f:af:23:73:6d)
>                
>  
>  
>  
>  
> Log data collected with raddb tool
>  
>  
> (47157) Thu Feb 13 13:46:55 2020: Debug: Received Access-Request Id 50 from1.1.1.1:62346 <http://1.1.1.1:62346/> to 2.2.2.2:1812 <http://2.2.2.2:1812/> length 231
> (47157) Thu Feb 13 13:46:55 2020: Debug:   User-Name = "MYDOMAIN\\myuser"
> (47157) Thu Feb 13 13:46:55 2020: Debug:   NAS-Port = 564
> (47157) Thu Feb 13 13:46:55 2020: Debug:   State = 0xa7aca802a1abb1731d68285805a095a1
> (47157) Thu Feb 13 13:46:55 2020: Debug:   EAP-Message = 0x020700361900170303002b0000000000000001c5b68a46bf78d5edf7fc184f64dba1119a9284ca3ae053917e4c0b39e51fcc61d031ae
> (47157) Thu Feb 13 13:46:55 2020: Debug:   Message-Authenticator = 0x16e19f834e7374ca1f5ae680d48502d7
> (47157) Thu Feb 13 13:46:55 2020: Debug:   Acct-Session-Id = "8O2.1x810203cc00016034"
> (47157) Thu Feb 13 13:46:55 2020: Debug:   NAS-Port-Id = "ge-0/0/8.0"
> (47157) Thu Feb 13 13:46:55 2020: Debug:   Calling-Station-Id = "f0-1f-af-23-73-6d"
> (47157) Thu Feb 13 13:46:55 2020: Debug:   Called-Station-Id = "58-00-bb-37-ad-40"
> (47157) Thu Feb 13 13:46:55 2020: Debug:   NAS-Identifier = "LAB-4300-VC"
> (47157) Thu Feb 13 13:46:55 2020: Debug:   NAS-Port-Type = Ethernet
> (47157) Thu Feb 13 13:46:55 2020: Debug: Restoring &session-state
> (47157) Thu Feb 13 13:46:55 2020: Debug:   &session-state:TLS-Session-Cipher-Suite = "ECDHE-RSA-AES256-GCM-SHA384"
> (47157) Thu Feb 13 13:46:55 2020: Debug:   &session-state:TLS-Session-Version = "TLS 1.2"
> (47157) Thu Feb 13 13:46:55 2020: Debug: # Executing section authorize from file /usr/local/pf/raddb/sites-enabled/packetfence
> (47157) Thu Feb 13 13:46:55 2020: Debug:   authorize {
> (47157) Thu Feb 13 13:46:55 2020: Debug:     update {
> (47157) Thu Feb 13 13:46:55 2020: Debug:       EXPAND %{Packet-Src-IP-Address}
> (47157) Thu Feb 13 13:46:55 2020: Debug:          --> 1.1.1.1
> (47157) Thu Feb 13 13:46:55 2020: Debug:       EXPAND %{Packet-Dst-IP-Address}
> (47157) Thu Feb 13 13:46:55 2020: Debug:          --> 2.2.2.2
> (47157) Thu Feb 13 13:46:55 2020: Debug:       EXPAND %l
> (47157) Thu Feb 13 13:46:55 2020: Debug:          --> 1581619615
> (47157) Thu Feb 13 13:46:55 2020: Debug:     } # update = noop
> (47157) Thu Feb 13 13:46:55 2020: Debug:     policy packetfence-set-realm-if-machine {
> (47157) Thu Feb 13 13:46:55 2020: Debug:       if (User-Name =~ /host\/([a-z0-9_-]*)[\.](.*)/i) {
> (47157) Thu Feb 13 13:46:55 2020: Debug:       if (User-Name =~ /host\/([a-z0-9_-]*)[\.](.*)/i)  -> FALSE
> (47157) Thu Feb 13 13:46:55 2020: Debug:     } # policy packetfence-set-realm-if-machine = noop
> (47157) Thu Feb 13 13:46:55 2020: Debug:     policy packetfence-balanced-key-policy {
> (47157) Thu Feb 13 13:46:55 2020: Debug:       if (&PacketFence-KeyBalanced && (&PacketFence-KeyBalanced =~ /^(.*)(.)$/i)) {
> (47157) Thu Feb 13 13:46:55 2020: Debug:       if (&PacketFence-KeyBalanced && (&PacketFence-KeyBalanced =~ /^(.*)(.)$/i))  -> FALSE
> (47157) Thu Feb 13 13:46:55 2020: Debug:       else {
> (47157) Thu Feb 13 13:46:55 2020: Debug:         update {
> (47157) Thu Feb 13 13:46:55 2020: Debug:           EXPAND %{md5:%{Calling-Station-Id}%{User-Name}}
> (47157) Thu Feb 13 13:46:55 2020: Debug:              --> eb1f6320f59f6feba568d08011260431
> (47157) Thu Feb 13 13:46:55 2020: Debug:           EXPAND %{md5:%{Calling-Station-Id}%{User-Name}}
> (47157) Thu Feb 13 13:46:55 2020: Debug:              --> eb1f6320f59f6feba568d08011260431
> (47157) Thu Feb 13 13:46:55 2020: Debug:         } # update = noop
> (47157) Thu Feb 13 13:46:55 2020: Debug:       } # else = noop
> (47157) Thu Feb 13 13:46:55 2020: Debug:     } # policy packetfence-balanced-key-policy = noop
> (47157) Thu Feb 13 13:46:55 2020: Debug:     policy packetfence-set-tenant-id {
> (47157) Thu Feb 13 13:46:55 2020: Debug:       if (!NAS-IP-Address || NAS-IP-Address == "0.0.0.0"){
> (47157) Thu Feb 13 13:46:55 2020: Debug:       if (!NAS-IP-Address || NAS-IP-Address == "0.0.0.0") -> TRUE
> (47157) Thu Feb 13 13:46:55 2020: Debug:       if (!NAS-IP-Address || NAS-IP-Address == "0.0.0.0") {
> (47157) Thu Feb 13 13:46:55 2020: Debug:         update request {
> (47157) Thu Feb 13 13:46:55 2020: Debug:           EXPAND %{Packet-Src-IP-Address}
> (47157) Thu Feb 13 13:46:55 2020: Debug:              --> 1.1.1.1
> (47157) Thu Feb 13 13:46:55 2020: Debug:         } # update request = noop
> (47157) Thu Feb 13 13:46:55 2020: Debug:       } # if (!NAS-IP-Address || NAS-IP-Address == "0.0.0.0") = noop
> (47157) Thu Feb 13 13:46:55 2020: Debug:       if ( "%{%{control:PacketFence-Tenant-Id}:-0}" == "0") {
> (47157) Thu Feb 13 13:46:55 2020: Debug:       EXPAND %{%{control:PacketFence-Tenant-Id}:-0}
> (47157) Thu Feb 13 13:46:55 2020: Debug:          --> 0
> (47157) Thu Feb 13 13:46:55 2020: Debug:       if ( "%{%{control:PacketFence-Tenant-Id}:-0}" == "0")  -> TRUE
> (47157) Thu Feb 13 13:46:55 2020: Debug:       if ( "%{%{control:PacketFence-Tenant-Id}:-0}" == "0")  {
> (47157) Thu Feb 13 13:46:55 2020: Debug:         update control {
> (47157) Thu Feb 13 13:46:55 2020: Debug:           EXPAND %{User-Name}
> (47157) Thu Feb 13 13:46:55 2020: Debug:              --> MYDOMAIN\\myuser
> (47157) Thu Feb 13 13:46:55 2020: Debug:           SQL-User-Name set to 'MYDOMAIN\\myuser'
> (47157) Thu Feb 13 13:46:55 2020: Debug:           Executing select query:  SELECT IFNULL((SELECT tenant_id FROM radius_nas WHERE nasname = '1.1.1.1'), 0)
> (47157) Thu Feb 13 13:46:55 2020: Debug:           EXPAND %{sql: SELECT IFNULL((SELECT tenant_id FROM radius_nas WHERE nasname = '%{NAS-IP-Address}'), 0)}
> (47157) Thu Feb 13 13:46:55 2020: Debug:              --> 1
> (47157) Thu Feb 13 13:46:55 2020: Debug:         } # update control = noop
> (47157) Thu Feb 13 13:46:55 2020: Debug:       } # if ( "%{%{control:PacketFence-Tenant-Id}:-0}" == "0")  = noop
> (47157) Thu Feb 13 13:46:55 2020: Debug:       if ( &control:PacketFence-Tenant-Id == 0 ) {
> (47157) Thu Feb 13 13:46:55 2020: Debug:       if ( &control:PacketFence-Tenant-Id == 0 )  -> FALSE
> (47157) Thu Feb 13 13:46:55 2020: Debug:     } # policy packetfence-set-tenant-id = noop
> (47157) Thu Feb 13 13:46:55 2020: Debug:     policy rewrite_calling_station_id {
> (47157) Thu Feb 13 13:46:55 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)) {
> (47157) Thu Feb 13 13:46:55 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))  -> TRUE
> (47157) Thu Feb 13 13:46:55 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))  {
> (47157) Thu Feb 13 13:46:55 2020: Debug:         update request {
> (47157) Thu Feb 13 13:46:55 2020: Debug:           EXPAND %{tolower:%{1}:%{2}:%{3}:%{4}:%{5}:%{6}}
> (47157) Thu Feb 13 13:46:55 2020: Debug:              --> f0:1f:af:23:73:6d
> (47157) Thu Feb 13 13:46:55 2020: Debug:         } # update request = noop
> (47157) Thu Feb 13 13:46:55 2020: Debug:         [updated] = updated
> (47157) Thu Feb 13 13:46:55 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))  = updated
> (47157) Thu Feb 13 13:46:55 2020: Debug:       ... skipping else: Preceding "if" was taken
> (47157) Thu Feb 13 13:46:55 2020: Debug:     } # policy rewrite_calling_station_id = updated
> (47157) Thu Feb 13 13:46:55 2020: Debug:     policy rewrite_called_station_id {
> (47157) Thu Feb 13 13:46:55 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)) {
> (47157) Thu Feb 13 13:46:55 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))  -> TRUE
> (47157) Thu Feb 13 13:46:55 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))  {
> (47157) Thu Feb 13 13:46:55 2020: Debug:         update request {
> (47157) Thu Feb 13 13:46:55 2020: Debug:           EXPAND %{tolower:%{1}:%{2}:%{3}:%{4}:%{5}:%{6}}
> (47157) Thu Feb 13 13:46:55 2020: Debug:              --> 58:00:bb:37:ad:40
> (47157) Thu Feb 13 13:46:55 2020: Debug:         } # update request = noop
> (47157) Thu Feb 13 13:46:55 2020: Debug:         if ("%{8}") {
> (47157) Thu Feb 13 13:46:55 2020: Debug:         EXPAND %{8}
> (47157) Thu Feb 13 13:46:55 2020: Debug:            -->
> (47157) Thu Feb 13 13:46:55 2020: Debug:         if ("%{8}")  -> FALSE
> (47157) Thu Feb 13 13:46:55 2020: Debug:         elsif ( (Colubris-AVPair) && "%{Colubris-AVPair}" =~ /^ssid=(.*)$/i) {
> (47157) Thu Feb 13 13:46:55 2020: Debug:         elsif ( (Colubris-AVPair) && "%{Colubris-AVPair}" =~ /^ssid=(.*)$/i)  -> FALSE
> (47157) Thu Feb 13 13:46:55 2020: Debug:         elsif (Aruba-Essid-Name) {
> (47157) Thu Feb 13 13:46:55 2020: Debug:         elsif (Aruba-Essid-Name)  -> FALSE
> (47157) Thu Feb 13 13:46:55 2020: Debug:         elsif ( (Cisco-AVPair)  && "%{Cisco-AVPair}" =~ /^ssid=(.*)$/i) {
> (47157) Thu Feb 13 13:46:55 2020: Debug:         elsif ( (Cisco-AVPair)  && "%{Cisco-AVPair}" =~ /^ssid=(.*)$/i)  -> FALSE
> (47157) Thu Feb 13 13:46:55 2020: Debug:         [updated] = updated
> (47157) Thu Feb 13 13:46:55 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))  = updated
> (47157) Thu Feb 13 13:46:55 2020: Debug:       ... skipping else: Preceding "if" was taken
> (47157) Thu Feb 13 13:46:55 2020: Debug:     } # policy rewrite_called_station_id = updated
> (47157) Thu Feb 13 13:46:55 2020: Debug:     policy filter_username {
> (47157) Thu Feb 13 13:46:55 2020: Debug:       if (&User-Name) {
> (47157) Thu Feb 13 13:46:55 2020: Debug:       if (&User-Name)  -> TRUE
> (47157) Thu Feb 13 13:46:55 2020: Debug:       if (&User-Name)  {
> (47157) Thu Feb 13 13:46:55 2020: Debug:         if (&User-Name =~ / /) {
> (47157) Thu Feb 13 13:46:55 2020: Debug:         if (&User-Name =~ / /)  -> FALSE
> (47157) Thu Feb 13 13:46:55 2020: Debug:         if (&User-Name =~ /@[^@]*@/ ) {
> (47157) Thu Feb 13 13:46:55 2020: Debug:         if (&User-Name =~ /@[^@]*@/ )  -> FALSE
> (47157) Thu Feb 13 13:46:55 2020: Debug:         if (&User-Name =~ /\.\./ ) {
> (47157) Thu Feb 13 13:46:55 2020: Debug:         if (&User-Name =~ /\.\./ )  -> FALSE
> (47157) Thu Feb 13 13:46:55 2020: Debug:         if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/) <mailto:/@(.+)\.(.+)$/)>)  {
> (47157) Thu Feb 13 13:46:55 2020: Debug:         if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/) <mailto:/@(.+)\.(.+)$/)>)   -> FALSE
> (47157) Thu Feb 13 13:46:55 2020: Debug:         if (&User-Name =~ /\.$/)  {
> (47157) Thu Feb 13 13:46:55 2020: Debug:         if (&User-Name =~ /\.$/)   -> FALSE
> (47157) Thu Feb 13 13:46:55 2020: Debug:         if (&User-Name =~ /@\./ <mailto:/@\./>)  {
> (47157) Thu Feb 13 13:46:55 2020: Debug:         if (&User-Name =~ /@\./ <mailto:/@\./>)   -> FALSE
> (47157) Thu Feb 13 13:46:55 2020: Debug:       } # if (&User-Name)  = updated
> (47157) Thu Feb 13 13:46:55 2020: Debug:     } # policy filter_username = updated
> (47157) Thu Feb 13 13:46:55 2020: Debug:     policy filter_password {
> (47157) Thu Feb 13 13:46:55 2020: Debug:       if (&User-Password &&       (&User-Password != "%{string:User-Password}")) {
> (47157) Thu Feb 13 13:46:55 2020: Debug:       if (&User-Password &&       (&User-Password != "%{string:User-Password}"))  -> FALSE
> (47157) Thu Feb 13 13:46:55 2020: Debug:     } # policy filter_password = updated
> (47157) Thu Feb 13 13:46:55 2020: Debug:     [preprocess] = ok
> (47157) Thu Feb 13 13:46:55 2020: Debug: suffix: Checking for suffix after "@"
> (47157) Thu Feb 13 13:46:55 2020: Debug: suffix: No '@' in User-Name = "MYDOMAIN\myuser", skipping NULL due to config.
> (47157) Thu Feb 13 13:46:55 2020: Debug:     [suffix] = noop
> (47157) Thu Feb 13 13:46:55 2020: Debug: ntdomain: Checking for prefix before "\"
> (47157) Thu Feb 13 13:46:55 2020: Debug: ntdomain: Looking up realm "MYDOMAIN" for User-Name = "MYDOMAIN\myuser"
> (47157) Thu Feb 13 13:46:55 2020: Debug: ntdomain: Found realm "MYDOMAIN"
> (47157) Thu Feb 13 13:46:55 2020: Debug: ntdomain: Adding Stripped-User-Name = "myuser"
> (47157) Thu Feb 13 13:46:55 2020: Debug: ntdomain: Adding Realm = "MYDOMAIN"
> (47157) Thu Feb 13 13:46:55 2020: Debug: ntdomain: Authentication realm is LOCAL
> (47157) Thu Feb 13 13:46:55 2020: Debug:     [ntdomain] = ok
> (47157) Thu Feb 13 13:46:55 2020: Debug: eap: Peer sent EAP Response (code 2) ID 7 length 54
> (47157) Thu Feb 13 13:46:55 2020: Debug: eap: Continuing tunnel setup
> (47157) Thu Feb 13 13:46:55 2020: Debug:     [eap] = ok
> (47157) Thu Feb 13 13:46:55 2020: Debug:   } # authorize = ok
> (47157) Thu Feb 13 13:46:55 2020: Debug: Found Auth-Type = eap
> (47157) Thu Feb 13 13:46:55 2020: Debug: # Executing group from file /usr/local/pf/raddb/sites-enabled/packetfence
> (47157) Thu Feb 13 13:46:55 2020: Debug:   authenticate {
> (47157) Thu Feb 13 13:46:55 2020: Debug: eap: Expiring EAP session with state 0xa7aca802a1abb173
> (47157) Thu Feb 13 13:46:55 2020: Debug: eap: Finished EAP session with state 0xa7aca802a1abb173
> (47157) Thu Feb 13 13:46:55 2020: Debug: eap: Previous EAP request found for state 0xa7aca802a1abb173, released from the list
> (47157) Thu Feb 13 13:46:55 2020: Debug: eap: Peer sent packet with method EAP PEAP (25)
> (47157) Thu Feb 13 13:46:55 2020: Debug: eap: Calling submodule eap_peap to process data
> (47157) Thu Feb 13 13:46:55 2020: Debug: eap_peap: Continuing EAP-TLS
> (47157) Thu Feb 13 13:46:55 2020: Debug: eap_peap: [eaptls verify] = ok
> (47157) Thu Feb 13 13:46:55 2020: Debug: eap_peap: Done initial handshake
> (47157) Thu Feb 13 13:46:55 2020: Debug: eap_peap: [eaptls process] = ok
> (47157) Thu Feb 13 13:46:55 2020: Debug: eap_peap: Session established.  Decoding tunneled attributes
> (47157) Thu Feb 13 13:46:55 2020: Debug: eap_peap: PEAP state WAITING FOR INNER IDENTITY
> (47157) Thu Feb 13 13:46:55 2020: Debug: eap_peap: Identity - MYDOMAIN\myuser
> (47157) Thu Feb 13 13:46:55 2020: Debug: eap_peap: Got inner identity 'MYDOMAIN\myuser'
> (47157) Thu Feb 13 13:46:55 2020: Debug: eap_peap: Setting default EAP type for tunneled EAP session
> (47157) Thu Feb 13 13:46:55 2020: Debug: eap_peap: Got tunneled request
> (47157) Thu Feb 13 13:46:55 2020: Debug: eap_peap:   EAP-Message = 0x020700170144414946554b554e415c316a6c696e64656e
> (47157) Thu Feb 13 13:46:55 2020: Debug: eap_peap: Setting User-Name to MYDOMAIN\myuser
> (47157) Thu Feb 13 13:46:55 2020: Debug: eap_peap: Sending tunneled request to packetfence-tunnel
> (47157) Thu Feb 13 13:46:55 2020: Debug: eap_peap:   EAP-Message = 0x020700170144414946554b554e415c316a6c696e64656e
> (47157) Thu Feb 13 13:46:55 2020: Debug: eap_peap:   FreeRADIUS-Proxied-To = 127.0.0.1
> (47157) Thu Feb 13 13:46:55 2020: Debug: eap_peap:   User-Name = "MYDOMAIN\\myuser"
> (47157) Thu Feb 13 13:46:55 2020: Debug: eap_peap:   NAS-Port = 564
> (47157) Thu Feb 13 13:46:55 2020: Debug: eap_peap:   Acct-Session-Id = "8O2.1x810203cc00016034"
> (47157) Thu Feb 13 13:46:55 2020: Debug: eap_peap:   NAS-Port-Id = "ge-0/0/8.0"
> (47157) Thu Feb 13 13:46:55 2020: Debug: eap_peap:   Calling-Station-Id := "f0:1f:af:23:73:6d"
> (47157) Thu Feb 13 13:46:55 2020: Debug: eap_peap:   NAS-Identifier = "LAB-4300-VC"
> (47157) Thu Feb 13 13:46:55 2020: Debug: eap_peap:   NAS-Port-Type = Ethernet
> (47157) Thu Feb 13 13:46:55 2020: Debug: eap_peap:   PacketFence-Radius-Ip := "2.2.2.2"
> (47157) Thu Feb 13 13:46:55 2020: Debug: eap_peap:   PacketFence-KeyBalanced := "eb1f6320f59f6feba568d08011260431"
> (47157) Thu Feb 13 13:46:55 2020: Debug: eap_peap:   NAS-IP-Address := 1.1.1.1
> (47157) Thu Feb 13 13:46:55 2020: Debug: eap_peap:   Called-Station-Id := "58:00:bb:37:ad:40"
> (47157) Thu Feb 13 13:46:55 2020: Debug: eap_peap:   Event-Timestamp = "Feb 13 2020 13:46:55 EST"
> (47157) Thu Feb 13 13:46:55 2020: Debug: Virtual server packetfence-tunnel received request
> (47157) Thu Feb 13 13:46:55 2020: Debug:   EAP-Message = 0x020700170144414946554b554e415c316a6c696e64656e
> (47157) Thu Feb 13 13:46:55 2020: Debug:   FreeRADIUS-Proxied-To = 127.0.0.1
> (47157) Thu Feb 13 13:46:55 2020: Debug:   User-Name = "MYDOMAIN\\myuser"
> (47157) Thu Feb 13 13:46:55 2020: Debug:   NAS-Port = 564
> (47157) Thu Feb 13 13:46:55 2020: Debug:   Acct-Session-Id = "8O2.1x810203cc00016034"
> (47157) Thu Feb 13 13:46:55 2020: Debug:   NAS-Port-Id = "ge-0/0/8.0"
> (47157) Thu Feb 13 13:46:55 2020: Debug:   Calling-Station-Id := "f0:1f:af:23:73:6d"
> (47157) Thu Feb 13 13:46:55 2020: Debug:   NAS-Identifier = "LAB-4300-VC"
> (47157) Thu Feb 13 13:46:55 2020: Debug:   NAS-Port-Type = Ethernet
> (47157) Thu Feb 13 13:46:55 2020: Debug:   PacketFence-Radius-Ip := "2.2.2.2"
> (47157) Thu Feb 13 13:46:55 2020: Debug:   PacketFence-KeyBalanced := "eb1f6320f59f6feba568d08011260431"
> (47157) Thu Feb 13 13:46:55 2020: Debug:   NAS-IP-Address := 1.1.1.1
> (47157) Thu Feb 13 13:46:55 2020: Debug:   Called-Station-Id := "58:00:bb:37:ad:40"
> (47157) Thu Feb 13 13:46:55 2020: Debug:   Event-Timestamp = "Feb 13 2020 13:46:55 EST"
> (47157) Thu Feb 13 13:46:55 2020: WARNING: Outer and inner identities are the same.  User privacy is compromised.
> (47157) Thu Feb 13 13:46:55 2020: Debug: server packetfence-tunnel {
> (47157) Thu Feb 13 13:46:55 2020: Debug:   # Executing section authorize from file /usr/local/pf/raddb/sites-enabled/packetfence-tunnel
> (47157) Thu Feb 13 13:46:55 2020: Debug:     authorize {
> (47157) Thu Feb 13 13:46:55 2020: Debug:       if ( outer.EAP-Type == TTLS) {
> (47157) Thu Feb 13 13:46:55 2020: Debug:       if ( outer.EAP-Type == TTLS)  -> FALSE
> (47157) Thu Feb 13 13:46:55 2020: Debug:       policy packetfence-set-realm-if-machine {
> (47157) Thu Feb 13 13:46:55 2020: Debug:         if (User-Name =~ /host\/([a-z0-9_-]*)[\.](.*)/i) {
> (47157) Thu Feb 13 13:46:55 2020: Debug:         if (User-Name =~ /host\/([a-z0-9_-]*)[\.](.*)/i)  -> FALSE
> (47157) Thu Feb 13 13:46:55 2020: Debug:       } # policy packetfence-set-realm-if-machine = notfound
> (47157) Thu Feb 13 13:46:55 2020: Debug:       policy packetfence-set-tenant-id {
> (47157) Thu Feb 13 13:46:55 2020: Debug:         if (!NAS-IP-Address || NAS-IP-Address == "0.0.0.0"){
> (47157) Thu Feb 13 13:46:55 2020: Debug:         if (!NAS-IP-Address || NAS-IP-Address == "0.0.0.0") -> FALSE
> (47157) Thu Feb 13 13:46:55 2020: Debug:         if ( "%{%{control:PacketFence-Tenant-Id}:-0}" == "0") {
> (47157) Thu Feb 13 13:46:55 2020: Debug:         EXPAND %{%{control:PacketFence-Tenant-Id}:-0}
> (47157) Thu Feb 13 13:46:55 2020: Debug:            --> 0
> (47157) Thu Feb 13 13:46:55 2020: Debug:         if ( "%{%{control:PacketFence-Tenant-Id}:-0}" == "0")  -> TRUE
> (47157) Thu Feb 13 13:46:55 2020: Debug:         if ( "%{%{control:PacketFence-Tenant-Id}:-0}" == "0")  {
> (47157) Thu Feb 13 13:46:55 2020: Debug:           update control {
> (47157) Thu Feb 13 13:46:55 2020: Debug:             EXPAND %{User-Name}
> (47157) Thu Feb 13 13:46:55 2020: Debug:                --> MYDOMAIN\\myuser
> (47157) Thu Feb 13 13:46:55 2020: Debug:             SQL-User-Name set to 'MYDOMAIN\\myuser'
> (47157) Thu Feb 13 13:46:55 2020: Debug:             Executing select query:  SELECT IFNULL((SELECT tenant_id FROM radius_nas WHERE nasname = '1.1.1.1'), 0)
> (47157) Thu Feb 13 13:46:55 2020: Debug:             EXPAND %{sql: SELECT IFNULL((SELECT tenant_id FROM radius_nas WHERE nasname = '%{NAS-IP-Address}'), 0)}
> (47157) Thu Feb 13 13:46:55 2020: Debug:                --> 1
> (47157) Thu Feb 13 13:46:55 2020: Debug:           } # update control = noop
> (47157) Thu Feb 13 13:46:55 2020: Debug:         } # if ( "%{%{control:PacketFence-Tenant-Id}:-0}" == "0")  = noop
> (47157) Thu Feb 13 13:46:55 2020: Debug:         if ( &control:PacketFence-Tenant-Id == 0 ) {
> (47157) Thu Feb 13 13:46:55 2020: Debug:         if ( &control:PacketFence-Tenant-Id == 0 )  -> FALSE
> (47157) Thu Feb 13 13:46:55 2020: Debug:       } # policy packetfence-set-tenant-id = noop
> (47157) Thu Feb 13 13:46:55 2020: Debug:       policy filter_username {
> (47157) Thu Feb 13 13:46:55 2020: Debug:         if (&User-Name) {
> (47157) Thu Feb 13 13:46:55 2020: Debug:         if (&User-Name)  -> TRUE
> (47157) Thu Feb 13 13:46:55 2020: Debug:         if (&User-Name)  {
> (47157) Thu Feb 13 13:46:55 2020: Debug:           if (&User-Name =~ / /) {
> (47157) Thu Feb 13 13:46:55 2020: Debug:           if (&User-Name =~ / /)  -> FALSE
> (47157) Thu Feb 13 13:46:55 2020: Debug:           if (&User-Name =~ /@[^@]*@/ ) {
> (47157) Thu Feb 13 13:46:55 2020: Debug:           if (&User-Name =~ /@[^@]*@/ )  -> FALSE
> (47157) Thu Feb 13 13:46:55 2020: Debug:           if (&User-Name =~ /\.\./ ) {
> (47157) Thu Feb 13 13:46:55 2020: Debug:           if (&User-Name =~ /\.\./ )  -> FALSE
> (47157) Thu Feb 13 13:46:55 2020: Debug:           if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/) <mailto:/@(.+)\.(.+)$/)>)  {
> (47157) Thu Feb 13 13:46:55 2020: Debug:           if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/) <mailto:/@(.+)\.(.+)$/)>)   -> FALSE
> (47157) Thu Feb 13 13:46:55 2020: Debug:           if (&User-Name =~ /\.$/)  {
> (47157) Thu Feb 13 13:46:55 2020: Debug:           if (&User-Name =~ /\.$/)   -> FALSE
> (47157) Thu Feb 13 13:46:55 2020: Debug:           if (&User-Name =~ /@\./ <mailto:/@\./>)  {
> (47157) Thu Feb 13 13:46:55 2020: Debug:           if (&User-Name =~ /@\./ <mailto:/@\./>)   -> FALSE
> (47157) Thu Feb 13 13:46:55 2020: Debug:         } # if (&User-Name)  = noop
> (47157) Thu Feb 13 13:46:55 2020: Debug:       } # policy filter_username = noop
> (47157) Thu Feb 13 13:46:55 2020: Debug:       [mschap] = noop
> (47157) Thu Feb 13 13:46:55 2020: Debug: suffix: Checking for suffix after "@"
> (47157) Thu Feb 13 13:46:55 2020: Debug: suffix: No '@' in User-Name = "MYDOMAIN\myuser", skipping NULL due to config.
> (47157) Thu Feb 13 13:46:55 2020: Debug:       [suffix] = noop
> (47157) Thu Feb 13 13:46:55 2020: Debug: ntdomain: Looking up realm "MYDOMAIN" for User-Name = "MYDOMAIN\myuser"
> (47157) Thu Feb 13 13:46:55 2020: Debug: ntdomain: Found realm "MYDOMAIN"
> (47157) Thu Feb 13 13:46:55 2020: Debug: ntdomain: Adding Stripped-User-Name = "myuser"
> (47157) Thu Feb 13 13:46:55 2020: Debug: ntdomain: Adding Realm = "MYDOMAIN"
> (47157) Thu Feb 13 13:46:55 2020: Debug: ntdomain: Authentication realm is LOCAL
> (47157) Thu Feb 13 13:46:55 2020: Debug:       [ntdomain] = ok
> (47157) Thu Feb 13 13:46:55 2020: Debug: packetfence-multi-domain:   $RAD_REQUEST{'User-Name'} = &request:User-Name -> 'MYDOMAIN\myuser'
> (47157) Thu Feb 13 13:46:55 2020: Debug: packetfence-multi-domain:   $RAD_REQUEST{'NAS-IP-Address'} = &request:NAS-IP-Address -> '1.1.1.1'
> (47157) Thu Feb 13 13:46:55 2020: Debug: packetfence-multi-domain:   $RAD_REQUEST{'NAS-Port'} = &request:NAS-Port -> '564'
> (47157) Thu Feb 13 13:46:55 2020: Debug: packetfence-multi-domain:   $RAD_REQUEST{'Called-Station-Id'} = &request:Called-Station-Id -> '58:00:bb:37:ad:40'
> (47157) Thu Feb 13 13:46:55 2020: Debug: packetfence-multi-domain:   $RAD_REQUEST{'Calling-Station-Id'} = &request:Calling-Station-Id -> 'f0:1f:af:23:73:6d'
> (47157) Thu Feb 13 13:46:55 2020: Debug: packetfence-multi-domain:   $RAD_REQUEST{'NAS-Identifier'} = &request:NAS-Identifier -> 'LAB-4300-VC'
> (47157) Thu Feb 13 13:46:55 2020: Debug: packetfence-multi-domain:   $RAD_REQUEST{'NAS-Port-Type'} = &request:NAS-Port-Type -> 'Ethernet'
> (47157) Thu Feb 13 13:46:55 2020: Debug: packetfence-multi-domain:   $RAD_REQUEST{'Acct-Session-Id'} = &request:Acct-Session-Id -> '8O2.1x810203cc00016034'
> (47157) Thu Feb 13 13:46:55 2020: Debug: packetfence-multi-domain:   $RAD_REQUEST{'Event-Timestamp'} = &request:Event-Timestamp -> 'Feb 13 2020 13:46:55 EST'
> (47157) Thu Feb 13 13:46:55 2020: Debug: packetfence-multi-domain:   $RAD_REQUEST{'EAP-Message'} = &request:EAP-Message -> '0x020700170144414946554b554e415c316a6c696e64656e'
> (47157) Thu Feb 13 13:46:55 2020: Debug: packetfence-multi-domain:   $RAD_REQUEST{'NAS-Port-Id'} = &request:NAS-Port-Id -> 'ge-0/0/8.0'
> (47157) Thu Feb 13 13:46:55 2020: Debug: packetfence-multi-domain:   $RAD_REQUEST{'FreeRADIUS-Proxied-To'} = &request:FreeRADIUS-Proxied-To -> '127.0.0.1'
> (47157) Thu Feb 13 13:46:55 2020: Debug: packetfence-multi-domain:   $RAD_REQUEST{'Stripped-User-Name'} = &request:Stripped-User-Name -> 'myuser'
> (47157) Thu Feb 13 13:46:55 2020: Debug: packetfence-multi-domain:   $RAD_REQUEST{'Realm'} = &request:Realm -> 'MYDOMAIN'
> (47157) Thu Feb 13 13:46:55 2020: Debug: packetfence-multi-domain:   $RAD_REQUEST{'SQL-User-Name'} = &request:SQL-User-Name -> 'MYDOMAIN\\myuser'
> (47157) Thu Feb 13 13:46:55 2020: Debug: packetfence-multi-domain:   $RAD_REQUEST{'PacketFence-KeyBalanced'} = &request:PacketFence-KeyBalanced -> 'eb1f6320f59f6feba568d08011260431'
> (47157) Thu Feb 13 13:46:55 2020: Debug: packetfence-multi-domain:   $RAD_REQUEST{'PacketFence-Radius-Ip'} = &request:PacketFence-Radius-Ip -> '2.2.2.2'
> (47157) Thu Feb 13 13:46:55 2020: Debug: packetfence-multi-domain:   $RAD_CHECK{'EAP-Type'} = &control:EAP-Type -> 'MSCHAPv2'
> (47157) Thu Feb 13 13:46:55 2020: Debug: packetfence-multi-domain:   $RAD_CHECK{'PacketFence-Tenant-Id'} = &control:PacketFence-Tenant-Id -> '1'
> (47157) Thu Feb 13 13:46:55 2020: Debug: packetfence-multi-domain:   $RAD_CONFIG{'EAP-Type'} = &control:EAP-Type -> 'MSCHAPv2'
> (47157) Thu Feb 13 13:46:55 2020: Debug: packetfence-multi-domain:   $RAD_CONFIG{'PacketFence-Tenant-Id'} = &control:PacketFence-Tenant-Id -> '1'
> (47157) Thu Feb 13 13:46:55 2020: Debug: packetfence-multi-domain: perl_embed:: module = /usr/local/pf/raddb/mods-config/perl/packetfence-multi-domain.pm <http://packetfence-multi-domain.pm/> , func = authorize exit status= hash- or arrayref expected (not a simple scalar, use allow_nonref to allow this) at /usr/local/pf/lib/pfconfig/cached.pm <http://cached.pm/> line 182.
> (47157) Thu Feb 13 13:46:55 2020: Debug: packetfence-multi-domain: &request:Realm = $RAD_REQUEST{'Realm'} -> 'MYDOMAIN'
> (47157) Thu Feb 13 13:46:55 2020: Debug: packetfence-multi-domain: &request:NAS-Port = $RAD_REQUEST{'NAS-Port'} -> '564'
> (47157) Thu Feb 13 13:46:55 2020: Debug: packetfence-multi-domain: &request:PacketFence-Radius-Ip = $RAD_REQUEST{'PacketFence-Radius-Ip'} -> '2.2.2.2'
> (47157) Thu Feb 13 13:46:55 2020: Debug: packetfence-multi-domain: &request:User-Name = $RAD_REQUEST{'User-Name'} -> 'MYDOMAIN\myuser'
> (47157) Thu Feb 13 13:46:55 2020: Debug: packetfence-multi-domain: &request:FreeRADIUS-Proxied-To = $RAD_REQUEST{'FreeRADIUS-Proxied-To'} -> '127.0.0.1'
> (47157) Thu Feb 13 13:46:55 2020: Debug: packetfence-multi-domain: &request:NAS-Port-Type = $RAD_REQUEST{'NAS-Port-Type'} -> 'Ethernet'
> (47157) Thu Feb 13 13:46:55 2020: Debug: packetfence-multi-domain: &request:Acct-Session-Id = $RAD_REQUEST{'Acct-Session-Id'} -> '8O2.1x810203cc00016034'
> (47157) Thu Feb 13 13:46:55 2020: Debug: packetfence-multi-domain: &request:Called-Station-Id = $RAD_REQUEST{'Called-Station-Id'} -> '58:00:bb:37:ad:40'
> (47157) Thu Feb 13 13:46:55 2020: Debug: packetfence-multi-domain: &request:Event-Timestamp = $RAD_REQUEST{'Event-Timestamp'} -> 'Feb 13 2020 13:46:55 EST'
> (47157) Thu Feb 13 13:46:55 2020: Debug: packetfence-multi-domain: &request:EAP-Message = $RAD_REQUEST{'EAP-Message'} -> '0x020700170144414946554b554e415c316a6c696e64656e'
> (47157) Thu Feb 13 13:46:55 2020: Debug: packetfence-multi-domain: &request:PacketFence-KeyBalanced = $RAD_REQUEST{'PacketFence-KeyBalanced'} -> 'eb1f6320f59f6feba568d08011260431'
> (47157) Thu Feb 13 13:46:55 2020: Debug: packetfence-multi-domain: &request:NAS-IP-Address = $RAD_REQUEST{'NAS-IP-Address'} -> '1.1.1.1'
> (47157) Thu Feb 13 13:46:55 2020: Debug: packetfence-multi-domain: &request:Stripped-User-Name = $RAD_REQUEST{'Stripped-User-Name'} -> 'myuser'
> (47157) Thu Feb 13 13:46:55 2020: Debug: packetfence-multi-domain: &request:SQL-User-Name = $RAD_REQUEST{'SQL-User-Name'} -> 'MYDOMAIN\\myuser'
> (47157) Thu Feb 13 13:46:55 2020: Debug: packetfence-multi-domain: &request:NAS-Port-Id = $RAD_REQUEST{'NAS-Port-Id'} -> 'ge-0/0/8.0'
> (47157) Thu Feb 13 13:46:55 2020: Debug: packetfence-multi-domain: &request:NAS-Identifier = $RAD_REQUEST{'NAS-Identifier'} -> 'LAB-4300-VC'
> (47157) Thu Feb 13 13:46:55 2020: Debug: packetfence-multi-domain: &request:Calling-Station-Id = $RAD_REQUEST{'Calling-Station-Id'} -> 'f0:1f:af:23:73:6d'
> (47157) Thu Feb 13 13:46:55 2020: Debug: packetfence-multi-domain: &control:PacketFence-Tenant-Id = $RAD_CHECK{'PacketFence-Tenant-Id'} -> '1'
> (47157) Thu Feb 13 13:46:55 2020: Debug: packetfence-multi-domain: &control:EAP-Type = $RAD_CHECK{'EAP-Type'} -> 'MSCHAPv2'
> (47157) Thu Feb 13 13:46:55 2020: Debug:       [packetfence-multi-domain] = fail
> (47157) Thu Feb 13 13:46:55 2020: Debug:     } # authorize = fail
> (47157) Thu Feb 13 13:46:55 2020: Debug:   Using Post-Auth-Type Reject
> (47157) Thu Feb 13 13:46:55 2020: Debug:   # Executing group from file /usr/local/pf/raddb/sites-enabled/packetfence-tunnel
> (47157) Thu Feb 13 13:46:55 2020: Debug:     Post-Auth-Type REJECT {
> (47157) Thu Feb 13 13:46:55 2020: Debug:       policy packetfence-set-tenant-id {
> (47157) Thu Feb 13 13:46:55 2020: Debug:         if (!NAS-IP-Address || NAS-IP-Address == "0.0.0.0"){
> (47157) Thu Feb 13 13:46:55 2020: Debug:         if (!NAS-IP-Address || NAS-IP-Address == "0.0.0.0") -> FALSE
> (47157) Thu Feb 13 13:46:55 2020: Debug:         if ( "%{%{control:PacketFence-Tenant-Id}:-0}" == "0") {
> (47157) Thu Feb 13 13:46:55 2020: Debug:         EXPAND %{%{control:PacketFence-Tenant-Id}:-0}
> (47157) Thu Feb 13 13:46:55 2020: Debug:            --> 1
> (47157) Thu Feb 13 13:46:55 2020: Debug:         if ( "%{%{control:PacketFence-Tenant-Id}:-0}" == "0")  -> FALSE
> (47157) Thu Feb 13 13:46:55 2020: Debug:         if ( &control:PacketFence-Tenant-Id == 0 ) {
> (47157) Thu Feb 13 13:46:55 2020: Debug:         if ( &control:PacketFence-Tenant-Id == 0 )  -> FALSE
> (47157) Thu Feb 13 13:46:55 2020: Debug:       } # policy packetfence-set-tenant-id = noop
> (47157) Thu Feb 13 13:46:55 2020: Debug:       update {
> (47157) Thu Feb 13 13:46:55 2020: Debug:       } # update = noop
> (47157) Thu Feb 13 13:46:55 2020: Debug:       policy packetfence-audit-log-reject {
> (47157) Thu Feb 13 13:46:55 2020: Debug:         if (&User-Name && (&User-Name == "dummy")) {
> (47157) Thu Feb 13 13:46:55 2020: Debug:         if (&User-Name && (&User-Name == "dummy"))  -> FALSE
> (47157) Thu Feb 13 13:46:55 2020: Debug:         else {
> (47157) Thu Feb 13 13:46:55 2020: Debug:           policy request-timing {if (control:PacketFence-Request-Time != 0
> (47157) Thu Feb 13 13:46:55 2020: Debug:             ) {
> (47157) Thu Feb 13 13:46:55 2020: ERROR:             Failed retrieving values required to evaluate condition
> (47157) Thu Feb 13 13:46:55 2020: Debug:           } # policy request-timing = noop
> (47157) Thu Feb 13 13:46:55 2020: Debug: sql_reject: EXPAND type.reject.query
> (47157) Thu Feb 13 13:46:55 2020: Debug: sql_reject:    --> type.reject.query
> (47157) Thu Feb 13 13:46:55 2020: Debug: sql_reject: Using query template 'query'
> (47157) Thu Feb 13 13:46:55 2020: Debug: sql_reject: EXPAND %{User-Name}
> (47157) Thu Feb 13 13:46:55 2020: Debug: sql_reject:    --> MYDOMAIN\\myuser
> (47157) Thu Feb 13 13:46:55 2020: Debug: sql_reject: SQL-User-Name set to 'MYDOMAIN\\myuser'
> (47157) Thu Feb 13 13:46:55 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}')
> (47157) Thu Feb 13 13:46:55 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               ( 'f0:1f:af:23:73:6d', '', 'N/A', 'MYDOMAIN=5Cmyuser',                'myuser', 'MYDOMAIN', 'Radius-Access-Request',                'N/A', 'N/A', 'N/A',                '1.1.1.1', '58:00:bb:37:ad:40', 'f0:1f:af:23:73:6d',                'Ethernet', '', 'ge-0/0/8.0',                'N/A', '564', 'N/A',                '1.1.1.1', 'LAB-4300-VC',  'Reject',                 'Failed retrieving values required to evaluate condition', '', '',         ...
 
[truncated message content]