Update:
Found troubleshooting info here
https://packetfence.org/doc/PacketFence_Installation_Guide.html#_troubleshooting_packetfence
and as suggested checked /usr/local/pf/logs/radius.log where I'm seeing:
Jun 20 18:27:15 PacketFence-ZEN auth[19729]: Need 6 more connections to reach
10 spares
Jun 20 18:27:15 PacketFence-ZEN auth[19729]: rlm_sql (sql): Opening additional
connection (161), 1 of 60 pending slots used
Jun 20 18:27:15 PacketFence-ZEN auth[19729]: (1368) eap: ERROR: Response
appears to match a previous request, but the EAP type is wrong
Jun 20 18:27:15 PacketFence-ZEN auth[19729]: (1368) eap: ERROR: We expected EAP
type PEAP, but received type MD5
Jun 20 18:27:15 PacketFence-ZEN auth[19729]: (1368) eap: ERROR: Your Supplicant
or NAS is probably broken
Jun 20 18:27:15 PacketFence-ZEN auth[19729]: (1368) eap: ERROR: rlm_eap (EAP):
No EAP session matching state 0x084e9838084f818e
Jun 20 18:27:15 PacketFence-ZEN auth[19729]: [mac:50:9a:4c:05:1f:55] Rejected
user: 509a4c051f55
Jun 20 18:27:15 PacketFence-ZEN auth[19729]: (1368) Login incorrect (eap:
Response appears to match a previous request, but the EAP type is wrong):
[509a4c051f55] (from client 10.1.1.75 port 49 cli 50:9a:4c:05:1f:55)
Found a post where someone had the same error as in line 4 above and the
solution was to set default_eap_type = md5 in
/usr/local/pf/conf/radiusd/eap.conf - but I checked and mine is already set
that way.
Followed instructions to turn on debug logging - radius accounting and
authentication debug logs attached.
So I'm still stuck. Any suggestions?
Thanks
Tom Esker
IT Manager
Wyatt Early Harris Wheeler LLP
1912 Eastchester Drive Suite 400
High Point, NC 27265
Direct: 336.819.6020
Disclaimer
The information contained in this communication from the sender is
confidential. It is intended solely for use by the recipient and others
authorized to receive it. If you are not the recipient, you are hereby notified
that any disclosure, copying, distribution or taking action in relation of the
contents of this information is strictly prohibited and may be unlawful.
This email has been scanned for viruses and malware, and may have been
automatically archived by Mimecast Ltd, an innovator in Software as a Service
(SaaS) for business. Providing a safer and more useful place for your human
generated data. Specializing in; Security, archiving and compliance. To find
out more visit the Mimecast website.
(1572) Thu Jun 20 18:54:31 2019: Debug: Received Access-Request Id 0 from
10.1.1.75:49205 to 10.1.1.73:1812 length 118
(1572) Thu Jun 20 18:54:31 2019: Debug: NAS-IP-Address = 10.1.1.75
(1572) Thu Jun 20 18:54:31 2019: Debug: NAS-Port-Type = Ethernet
(1572) Thu Jun 20 18:54:31 2019: Debug: NAS-Port = 49
(1572) Thu Jun 20 18:54:31 2019: Debug: User-Name = "509a4c051f55"
(1572) Thu Jun 20 18:54:31 2019: Debug: Acct-Session-Id = "050000FA"
(1572) Thu Jun 20 18:54:31 2019: Debug: Calling-Station-Id =
"50-9A-4C-05-1F-55"
(1572) Thu Jun 20 18:54:31 2019: Debug: EAP-Message =
0x0200001101353039613463303531663535
(1572) Thu Jun 20 18:54:31 2019: Debug: Message-Authenticator =
0xf74266d1463b5f910fcf5630d6cda640
(1572) Thu Jun 20 18:54:31 2019: Debug: # Executing section authorize from file
/usr/local/pf/raddb/sites-enabled/packetfence
(1572) Thu Jun 20 18:54:31 2019: Debug: authorize {
(1572) Thu Jun 20 18:54:31 2019: Debug: update {
(1572) Thu Jun 20 18:54:31 2019: Debug: EXPAND %{Packet-Src-IP-Address}
(1572) Thu Jun 20 18:54:31 2019: Debug: --> 10.1.1.75
(1572) Thu Jun 20 18:54:31 2019: Debug: EXPAND %l
(1572) Thu Jun 20 18:54:31 2019: Debug: --> 1561056871
(1572) Thu Jun 20 18:54:31 2019: Debug: EXPAND %{Calling-Station-ID}
%{User-Name}
(1572) Thu Jun 20 18:54:31 2019: Debug: --> 50-9A-4C-05-1F-55
509a4c051f55
(1572) Thu Jun 20 18:54:31 2019: Debug: } # update = noop
(1572) Thu Jun 20 18:54:31 2019: Debug: policy
packetfence-set-realm-if-machine {
(1572) Thu Jun 20 18:54:31 2019: Debug: if (User-Name =~
/host\/([a-z0-9_-]*)[\.](.*)/i) {
(1572) Thu Jun 20 18:54:31 2019: Debug: if (User-Name =~
/host\/([a-z0-9_-]*)[\.](.*)/i) -> FALSE
(1572) Thu Jun 20 18:54:31 2019: Debug: } # policy
packetfence-set-realm-if-machine = noop
(1572) Thu Jun 20 18:54:31 2019: Debug: policy packetfence-set-tenant-id {
(1572) Thu Jun 20 18:54:31 2019: Debug: if (!NAS-IP-Address ||
NAS-IP-Address == "0.0.0.0"){
(1572) Thu Jun 20 18:54:31 2019: Debug: if (!NAS-IP-Address ||
NAS-IP-Address == "0.0.0.0") -> FALSE
(1572) Thu Jun 20 18:54:31 2019: Debug: if (
"%{%{control:PacketFence-Tenant-Id}:-0}" == "0") {
(1572) Thu Jun 20 18:54:31 2019: Debug: EXPAND
%{%{control:PacketFence-Tenant-Id}:-0}
(1572) Thu Jun 20 18:54:31 2019: Debug: --> 0
(1572) Thu Jun 20 18:54:31 2019: Debug: if (
"%{%{control:PacketFence-Tenant-Id}:-0}" == "0") -> TRUE
(1572) Thu Jun 20 18:54:31 2019: Debug: if (
"%{%{control:PacketFence-Tenant-Id}:-0}" == "0") {
(1572) Thu Jun 20 18:54:31 2019: Debug: update control {
(1572) Thu Jun 20 18:54:31 2019: Debug: EXPAND %{User-Name}
(1572) Thu Jun 20 18:54:31 2019: Debug: --> 509a4c051f55
(1572) Thu Jun 20 18:54:31 2019: Debug: SQL-User-Name set to
'509a4c051f55'
(1572) Thu Jun 20 18:54:31 2019: Debug: Executing select query:
SELECT IFNULL((SELECT tenant_id FROM radius_nas WHERE nasname = '10.1.1.75'), 0)
(1572) Thu Jun 20 18:54:31 2019: Debug: EXPAND %{sql: SELECT
IFNULL((SELECT tenant_id FROM radius_nas WHERE nasname = '%{NAS-IP-Address}'),
0)}
(1572) Thu Jun 20 18:54:31 2019: Debug: --> 1
(1572) Thu Jun 20 18:54:31 2019: Debug: } # update control = noop
(1572) Thu Jun 20 18:54:31 2019: Debug: } # if (
"%{%{control:PacketFence-Tenant-Id}:-0}" == "0") = noop
(1572) Thu Jun 20 18:54:31 2019: Debug: if (
&control:PacketFence-Tenant-Id == 0 ) {
(1572) Thu Jun 20 18:54:31 2019: Debug: if (
&control:PacketFence-Tenant-Id == 0 ) -> FALSE
(1572) Thu Jun 20 18:54:31 2019: Debug: } # policy
packetfence-set-tenant-id = noop
(1572) Thu Jun 20 18:54:31 2019: Debug: policy rewrite_calling_station_id {
(1572) Thu Jun 20 18:54:31 2019: 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))
{
(1572) Thu Jun 20 18:54:31 2019: 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
(1572) Thu Jun 20 18:54:31 2019: 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))
{
(1572) Thu Jun 20 18:54:31 2019: Debug: update request {
(1572) Thu Jun 20 18:54:31 2019: Debug: EXPAND
%{tolower:%{1}:%{2}:%{3}:%{4}:%{5}:%{6}}
(1572) Thu Jun 20 18:54:31 2019: Debug: --> 50:9a:4c:05:1f:55
(1572) Thu Jun 20 18:54:31 2019: Debug: } # update request = noop
(1572) Thu Jun 20 18:54:31 2019: Debug: [updated] = updated
(1572) Thu Jun 20 18:54:31 2019: 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
(1572) Thu Jun 20 18:54:31 2019: Debug: ... skipping else: Preceding "if"
was taken
(1572) Thu Jun 20 18:54:31 2019: Debug: } # policy
rewrite_calling_station_id = updated
(1572) Thu Jun 20 18:54:31 2019: Debug: policy rewrite_called_station_id {
(1572) Thu Jun 20 18:54:31 2019: 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))
{
(1572) Thu Jun 20 18:54:31 2019: Debug: if ((&Called-Station-Id) &&
(&Called-Station-Id =~
/^([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})(:(.+))?$/i))
-> FALSE
(1572) Thu Jun 20 18:54:31 2019: Debug: else {
(1572) Thu Jun 20 18:54:31 2019: Debug: [noop] = noop
(1572) Thu Jun 20 18:54:31 2019: Debug: } # else = noop
(1572) Thu Jun 20 18:54:31 2019: Debug: } # policy
rewrite_called_station_id = noop
(1572) Thu Jun 20 18:54:31 2019: Debug: policy filter_username {
(1572) Thu Jun 20 18:54:31 2019: Debug: if (&User-Name) {
(1572) Thu Jun 20 18:54:31 2019: Debug: if (&User-Name) -> TRUE
(1572) Thu Jun 20 18:54:31 2019: Debug: if (&User-Name) {
(1572) Thu Jun 20 18:54:31 2019: Debug: if (&User-Name =~ / /) {
(1572) Thu Jun 20 18:54:31 2019: Debug: if (&User-Name =~ / /) -> FALSE
(1572) Thu Jun 20 18:54:31 2019: Debug: if (&User-Name =~ /@[^@]*@/ ) {
(1572) Thu Jun 20 18:54:31 2019: Debug: if (&User-Name =~ /@[^@]*@/ )
-> FALSE
(1572) Thu Jun 20 18:54:31 2019: Debug: if (&User-Name =~ /\.\./ ) {
(1572) Thu Jun 20 18:54:31 2019: Debug: if (&User-Name =~ /\.\./ ) ->
FALSE
(1572) Thu Jun 20 18:54:31 2019: Debug: if ((&User-Name =~ /@/) &&
(&User-Name !~ /@(.+)\.(.+)$/)) {
(1572) Thu Jun 20 18:54:31 2019: Debug: if ((&User-Name =~ /@/) &&
(&User-Name !~ /@(.+)\.(.+)$/)) -> FALSE
(1572) Thu Jun 20 18:54:31 2019: Debug: if (&User-Name =~ /\.$/) {
(1572) Thu Jun 20 18:54:31 2019: Debug: if (&User-Name =~ /\.$/) ->
FALSE
(1572) Thu Jun 20 18:54:31 2019: Debug: if (&User-Name =~ /@\./) {
(1572) Thu Jun 20 18:54:31 2019: Debug: if (&User-Name =~ /@\./) ->
FALSE
(1572) Thu Jun 20 18:54:31 2019: Debug: } # if (&User-Name) = updated
(1572) Thu Jun 20 18:54:31 2019: Debug: } # policy filter_username = updated
(1572) Thu Jun 20 18:54:31 2019: Debug: policy filter_password {
(1572) Thu Jun 20 18:54:31 2019: Debug: if (&User-Password &&
(&User-Password != "%{string:User-Password}")) {
(1572) Thu Jun 20 18:54:31 2019: Debug: if (&User-Password &&
(&User-Password != "%{string:User-Password}")) -> FALSE
(1572) Thu Jun 20 18:54:31 2019: Debug: } # policy filter_password = updated
(1572) Thu Jun 20 18:54:31 2019: Debug: [preprocess] = ok
(1572) Thu Jun 20 18:54:31 2019: Debug: suffix: Checking for suffix after "@"
(1572) Thu Jun 20 18:54:31 2019: Debug: suffix: No '@' in User-Name =
"509a4c051f55", skipping NULL due to config.
(1572) Thu Jun 20 18:54:31 2019: Debug: [suffix] = noop
(1572) Thu Jun 20 18:54:31 2019: Debug: ntdomain: Checking for prefix before "\"
(1572) Thu Jun 20 18:54:31 2019: Debug: ntdomain: No '\' in User-Name =
"509a4c051f55", looking up realm NULL
(1572) Thu Jun 20 18:54:31 2019: Debug: ntdomain: Found realm "null"
(1572) Thu Jun 20 18:54:31 2019: Debug: ntdomain: Adding Stripped-User-Name =
"509a4c051f55"
(1572) Thu Jun 20 18:54:31 2019: Debug: ntdomain: Adding Realm = "null"
(1572) Thu Jun 20 18:54:31 2019: Debug: ntdomain: Authentication realm is LOCAL
(1572) Thu Jun 20 18:54:31 2019: Debug: [ntdomain] = ok
(1572) Thu Jun 20 18:54:31 2019: Debug: eap: Peer sent EAP Response (code 2) ID
0 length 17
(1572) Thu Jun 20 18:54:31 2019: Debug: eap: EAP-Identity reply, returning 'ok'
so we can short-circuit the rest of authorize
(1572) Thu Jun 20 18:54:31 2019: Debug: [eap] = ok
(1572) Thu Jun 20 18:54:31 2019: Debug: } # authorize = ok
(1572) Thu Jun 20 18:54:31 2019: Debug: Found Auth-Type = eap
(1572) Thu Jun 20 18:54:31 2019: Debug: # Executing group from file
/usr/local/pf/raddb/sites-enabled/packetfence
(1572) Thu Jun 20 18:54:31 2019: Debug: authenticate {
(1572) Thu Jun 20 18:54:31 2019: Debug: eap: Peer sent packet with method EAP
Identity (1)
(1572) Thu Jun 20 18:54:31 2019: Debug: eap: Calling submodule eap_peap to
process data
(1572) Thu Jun 20 18:54:31 2019: Debug: eap_peap: Initiating new TLS session
(1572) Thu Jun 20 18:54:31 2019: Debug: eap_peap: [eaptls start] = request
(1572) Thu Jun 20 18:54:31 2019: Debug: eap: Sending EAP Request (code 1) ID 1
length 6
(1572) Thu Jun 20 18:54:31 2019: Debug: eap: EAP session adding &reply:State =
0x1835af0e1834b691
(1572) Thu Jun 20 18:54:31 2019: Debug: [eap] = handled
(1572) Thu Jun 20 18:54:31 2019: Debug: } # authenticate = handled
(1572) Thu Jun 20 18:54:31 2019: Debug: Using Post-Auth-Type Challenge
(1572) Thu Jun 20 18:54:31 2019: Debug: Post-Auth-Type sub-section not found.
Ignoring.
(1572) Thu Jun 20 18:54:31 2019: Debug: # Executing group from file
/usr/local/pf/raddb/sites-enabled/packetfence
(1572) Thu Jun 20 18:54:31 2019: Debug: Sent Access-Challenge Id 0 from
10.1.1.73:1812 to 10.1.1.75:49205 length 0
(1572) Thu Jun 20 18:54:31 2019: Debug: EAP-Message = 0x010100061920
(1572) Thu Jun 20 18:54:31 2019: Debug: Message-Authenticator =
0x00000000000000000000000000000000
(1572) Thu Jun 20 18:54:31 2019: Debug: State =
0x1835af0e1834b691e79b8a73670c6c03
(1572) Thu Jun 20 18:54:31 2019: Debug: Finished request
(1572) Thu Jun 20 18:54:31 2019: Debug: Cleaning up request packet ID 0 with
timestamp +17010(1159) Thu Jun 20 19:00:45 2019: Debug: Received Status-Server Id 209 from
127.0.0.1:58620 to 127.0.0.1:18122 length 50
(1159) Thu Jun 20 19:00:45 2019: Debug: Message-Authenticator =
0x9ef38da37d8f8feabcadbb4fe6303750
(1159) Thu Jun 20 19:00:45 2019: Debug: FreeRADIUS-Statistics-Type = 15
(1159) Thu Jun 20 19:00:45 2019: Debug: # Executing group from file
/usr/local/pf/raddb/sites-enabled/status
(1159) Thu Jun 20 19:00:45 2019: Debug: Autz-Type Status-Server {
(1159) Thu Jun 20 19:00:45 2019: Debug: [ok] = ok
(1159) Thu Jun 20 19:00:45 2019: Debug: } # Autz-Type Status-Server = ok
(1159) Thu Jun 20 19:00:45 2019: Debug: Sent Access-Accept Id 209 from
127.0.0.1:18122 to 127.0.0.1:58620 length 0
(1159) Thu Jun 20 19:00:45 2019: Debug: FreeRADIUS-Total-Access-Requests =
1160
(1159) Thu Jun 20 19:00:45 2019: Debug: FreeRADIUS-Total-Access-Accepts = 0
(1159) Thu Jun 20 19:00:45 2019: Debug: FreeRADIUS-Total-Access-Rejects = 0
(1159) Thu Jun 20 19:00:45 2019: Debug: FreeRADIUS-Total-Access-Challenges = 0
(1159) Thu Jun 20 19:00:45 2019: Debug: FreeRADIUS-Total-Auth-Responses = 0
(1159) Thu Jun 20 19:00:45 2019: Debug:
FreeRADIUS-Total-Auth-Duplicate-Requests = 0
(1159) Thu Jun 20 19:00:45 2019: Debug:
FreeRADIUS-Total-Auth-Malformed-Requests = 0
(1159) Thu Jun 20 19:00:45 2019: Debug:
FreeRADIUS-Total-Auth-Invalid-Requests = 0
(1159) Thu Jun 20 19:00:45 2019: Debug:
FreeRADIUS-Total-Auth-Dropped-Requests = 0
(1159) Thu Jun 20 19:00:45 2019: Debug: FreeRADIUS-Total-Auth-Unknown-Types = 0
(1159) Thu Jun 20 19:00:45 2019: Debug: FreeRADIUS-Total-Accounting-Requests
= 0
(1159) Thu Jun 20 19:00:45 2019: Debug: FreeRADIUS-Total-Accounting-Responses
= 0
(1159) Thu Jun 20 19:00:45 2019: Debug:
FreeRADIUS-Total-Acct-Duplicate-Requests = 0
(1159) Thu Jun 20 19:00:45 2019: Debug:
FreeRADIUS-Total-Acct-Malformed-Requests = 0
(1159) Thu Jun 20 19:00:45 2019: Debug:
FreeRADIUS-Total-Acct-Invalid-Requests = 0
(1159) Thu Jun 20 19:00:45 2019: Debug:
FreeRADIUS-Total-Acct-Dropped-Requests = 0
(1159) Thu Jun 20 19:00:45 2019: Debug: FreeRADIUS-Total-Acct-Unknown-Types = 0
(1159) Thu Jun 20 19:00:45 2019: Debug:
FreeRADIUS-Total-Proxy-Access-Requests = 0
(1159) Thu Jun 20 19:00:45 2019: Debug: FreeRADIUS-Total-Proxy-Access-Accepts
= 0
(1159) Thu Jun 20 19:00:45 2019: Debug: FreeRADIUS-Total-Proxy-Access-Rejects
= 0
(1159) Thu Jun 20 19:00:45 2019: Debug:
FreeRADIUS-Total-Proxy-Access-Challenges = 0
(1159) Thu Jun 20 19:00:45 2019: Debug: FreeRADIUS-Total-Proxy-Auth-Responses
= 0
(1159) Thu Jun 20 19:00:45 2019: Debug:
FreeRADIUS-Total-Proxy-Auth-Duplicate-Requests = 0
(1159) Thu Jun 20 19:00:45 2019: Debug:
FreeRADIUS-Total-Proxy-Auth-Malformed-Requests = 0
(1159) Thu Jun 20 19:00:45 2019: Debug:
FreeRADIUS-Total-Proxy-Auth-Invalid-Requests = 0
(1159) Thu Jun 20 19:00:45 2019: Debug:
FreeRADIUS-Total-Proxy-Auth-Dropped-Requests = 0
(1159) Thu Jun 20 19:00:45 2019: Debug:
FreeRADIUS-Total-Proxy-Auth-Unknown-Types = 0
(1159) Thu Jun 20 19:00:45 2019: Debug:
FreeRADIUS-Total-Proxy-Accounting-Requests = 0
(1159) Thu Jun 20 19:00:45 2019: Debug:
FreeRADIUS-Total-Proxy-Accounting-Responses = 0
(1159) Thu Jun 20 19:00:45 2019: Debug:
FreeRADIUS-Total-Proxy-Acct-Duplicate-Requests = 0
(1159) Thu Jun 20 19:00:45 2019: Debug:
FreeRADIUS-Total-Proxy-Acct-Malformed-Requests = 0
(1159) Thu Jun 20 19:00:45 2019: Debug:
FreeRADIUS-Total-Proxy-Acct-Invalid-Requests = 0
(1159) Thu Jun 20 19:00:45 2019: Debug:
FreeRADIUS-Total-Proxy-Acct-Dropped-Requests = 0
(1159) Thu Jun 20 19:00:45 2019: Debug:
FreeRADIUS-Total-Proxy-Acct-Unknown-Types = 0
(1159) Thu Jun 20 19:00:45 2019: Debug: Finished request
_______________________________________________
PacketFence-users mailing list
[email protected]
https://lists.sourceforge.net/lists/listinfo/packetfence-users
