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 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 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 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 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 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 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 from
1.1.1.1:62346 to 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 !~ /@(.+)\.(.+)$/)) {
(47157) Thu Feb 13 13:46:55 2020: Debug: if ((&User-Name =~ /@/) &&
(&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) = 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 !~ /@(.+)\.(.+)$/)) {
(47157) Thu Feb 13 13:46:55 2020: Debug: if ((&User-Name =~ /@/) &&
(&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) = 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 ,
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 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 to 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
[email protected]
https://lists.sourceforge.net/lists/listinfo/packetfence-users
