Re: [PacketFence-users] RADIUS authentication failure

SourceForge Headquarters 1320 Columbia Street Suite 310 San Diego, CA 92101 +1 (858) 422-6466

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...> 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 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: G PL via PacketFence-users <pac...@li...> 
> Sent: Friday, February 14, 2020 1:47 AM
> To: pac...@li...
> Cc: G PL <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', '', '',                'N/A', 'N/A', 'N/A',                'N/A', '0', '0',                '', '', 'Realm =3D =22MYDOMAIN=22=2C NAS-Port =3D 564=2C PacketFence-Radius-Ip =3D =222.2.2.2=22=2C User-Name =3D =22MYDOMAIN=5C=5Cmyuser=22=2C FreeRADIUS-Proxied-To =3D 127.0.0.1=2C NAS-Port-Type =3D Ethernet=2C Acct-Session-Id =3D =228O2.1x810203cc00016034=22=2C Called-Station-Id =3D =2258:00:bb:37:ad:40=22=2C Event-Timestamp =3D =22Feb 13 2020 13:46:55 EST=22=2C EAP-Message =3D 0x020700170144414946554b554e415c316a6c696e64656e=2C PacketFence-KeyBalanced =3D =22eb1f6320f59f6feba568d08011260431=22=2C NAS-IP-Address =3D 1.1.1.1=2C Stripped-User-Name =3D =22myuser=22=2C NAS-Port-Id =3D =22ge-0/0/8.0=22=2C NAS-Identifier =3D =22LAB-4300-VC=22=2C Calling-Station-Id =3D =22f0:1f:af:23:73:6d=22=2C User-Password =3D =22=2A=2A=2A=2A=2A=2A=22=2C Module-Failure-Message =3D =22Failed retrieving values required to evaluate condition=22=2C SQL-User-Name =3D =22MYDOMAIN=5C=5C=5C=5Cmyuser=22','', 'N/A', '1', '2.2.2.2')
> (47157) Thu Feb 13 13:46:55 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               ( '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', '', '',                'N/A', 'N/A', 'N/A',                'N/A', '0', '0',                '', '', 'Realm =3D =22MYDOMAIN=22=2C NAS-Port =3D 564=2C PacketFence-Radius-Ip =3D =222.2.2.2=22=2C User-Name =3D =22MYDOMAIN=5C=5Cmyuser=22=2C FreeRADIUS-Proxied-To =3D 127.0.0.1=2C NAS-Port-Type =3D Ethernet=2C Acct-Session-Id =3D =228O2.1x810203cc00016034=22=2C Called-Station-Id =3D =2258:00:bb:37:ad:40=22=2C Event-Timestamp =3D =22Feb 13 2020 13:46:55 EST=22=2C EAP-Message =3D 0x020700170144414946554b554e415c316a6c696e64656e=2C PacketFence-KeyBalanced =3D =22eb1f6320f59f6feba568d08011260431=22=2C NAS-IP-Address =3D 1.1.1.1=2C Stripped-User-Name =3D =22myuser=22=2C NAS-Port-Id =3D =22ge-0/0/8.0=22=2C NAS-Identifier =3D =22LAB-4300-VC=22=2C Calling-Station-Id =3D =22f0:1f:af:23:73:6d=22=2C User-Password =3D =22=2A=2A=2A=2A=2A=2A=22=2C Module-Failure-Message =3D =22Failed retrieving values required to evaluate condition=22=2C SQL-User-Name =3D =22MYDOMAIN=5C=5C=5C=5Cmyuser=22','', 'N/A', '1', '2.2.2.2')
> (47157) Thu Feb 13 13:46:55 2020: Debug: sql_reject: SQL query returned: success
> (47157) Thu Feb 13 13:46:55 2020: Debug: sql_reject: 1 record(s) updated
> (47157) Thu Feb 13 13:46:55 2020: Debug:           [sql_reject] = ok
> (47157) Thu Feb 13 13:46:55 2020: Debug:         } # else = ok
> (47157) Thu Feb 13 13:46:55 2020: Debug:       } # policy packetfence-audit-log-reject = ok
> (47157) Thu Feb 13 13:46:55 2020: Debug: attr_filter.access_reject: EXPAND %{User-Name}
> (47157) Thu Feb 13 13:46:55 2020: Debug: attr_filter.access_reject:    --> MYDOMAIN\\myuser
> (47157) Thu Feb 13 13:46:55 2020: Debug: attr_filter.access_reject: Matched entry DEFAULT at line 11
> (47157) Thu Feb 13 13:46:55 2020: Debug:       [attr_filter.access_reject] = updated
> (47157) Thu Feb 13 13:46:55 2020: Debug:       update outer.session-state {
> (47157) Thu Feb 13 13:46:55 2020: Debug:       } # update outer.session-state = noop
> (47157) Thu Feb 13 13:46:55 2020: Debug:     } # Post-Auth-Type REJECT = updated
> (47157) Thu Feb 13 13:46:55 2020: Debug: } # server packetfence-tunnel
> (47157) Thu Feb 13 13:46:55 2020: Debug: Virtual server sending reply
> (47157) Thu Feb 13 13:46:55 2020: Debug: eap_peap: Got tunneled reply code 3
> (47157) Thu Feb 13 13:46:55 2020: Debug: eap_peap: Tunneled authentication was rejected
> (47157) Thu Feb 13 13:46:55 2020: Debug: eap_peap: FAILURE
> (47157) Thu Feb 13 13:46:55 2020: Debug: eap: Sending EAP Request (code 1) ID 8 length 46
> (47157) Thu Feb 13 13:46:55 2020: Debug: eap: EAP session adding &reply:State = 0xa7aca802a0a4b173
> (47157) Thu Feb 13 13:46:55 2020: Debug:     [eap] = handled
> (47157) Thu Feb 13 13:46:55 2020: Debug:   } # authenticate = handled
> (47157) Thu Feb 13 13:46:55 2020: Debug: Using Post-Auth-Type Challenge
> (47157) Thu Feb 13 13:46:55 2020: Debug: Post-Auth-Type sub-section not found.  Ignoring.
> (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: session-state: Saving cached attributes
> (47157) Thu Feb 13 13:46:55 2020: Debug:   TLS-Session-Cipher-Suite = "ECDHE-RSA-AES256-GCM-SHA384"
> (47157) Thu Feb 13 13:46:55 2020: Debug:   TLS-Session-Version = "TLS 1.2"
> (47157) Thu Feb 13 13:46:55 2020: Debug:   Module-Failure-Message := "Failed retrieving values required to evaluate condition"
> (47157) Thu Feb 13 13:46:55 2020: Debug: Sent Access-Challenge Id 50 from 2.2.2.2:1812 <http://2.2.2.2:1812/> to 1.1.1.1:62346 <http://1.1.1.1:62346/> length 0
> (47157) Thu Feb 13 13:46:55 2020: Debug:   EAP-Message = 0x0108002e1900170303002326d6be811a8da5a14f28fc850dced4a1020a4298af6952d59d739bc90373465deb811f
> (47157) Thu Feb 13 13:46:55 2020: Debug:   Message-Authenticator = 0x00000000000000000000000000000000
> (47157) Thu Feb 13 13:46:55 2020: Debug:   State = 0xa7aca802a0a4b1731d68285805a095a1
> (47157) Thu Feb 13 13:46:55 2020: Debug: Finished request
>  
> PRIVACY NOTICE: The information contained in this e-mail, including any attachments, is confidential and intended only for the named recipient(s). Unauthorized use, disclosure, forwarding, or copying is strictly prohibited and may be unlawful. If you are not the intended recipient, please delete the e-mail and any attachments and notify us immediately by return e-mail.
> _______________________________________________
> PacketFence-users mailing list
> Pac...@li...
> https://lists.sourceforge.net/lists/listinfo/packetfence-users