Got it. Simple and concise. On 7/26/19 2:51 PM, Alan DeKok wrote:
On Jul 26, 2019, at 12:38 PM, J Kephart <jkephart@safetynetaccess.com> wrote:
authenticate { (660) Fri Jul 26 09:20:17 2019: WARNING: mschap: No Cleartext-Password configured. Cannot create NT-Password (660) Fri Jul 26 09:20:17 2019: WARNING: mschap: No Cleartext-Password configured. Cannot create LM-Password That's pretty clear.
Yes, it is, but if I'm reading this correctly, it seems to be telling me that there's no such attribute in radcheck. Am I interpreting it correctly, because if so, I can confirm that the Cleartext-Attribute for the user does exist in radcheck.
Read the debug output to see. For ONE user.
Output for one user: (660) Fri Jul 26 09:20:17 2019: Debug: Received Access-Request Id 60 from 67.135.207.161:2414 to 162.220.133.70:1812 length 255 (660) Fri Jul 26 09:20:17 2019: Debug: User-Name = "54-72-4F-69-14-B1" (660) Fri Jul 26 09:20:17 2019: Debug: NAS-IP-Address = 67.135.207.161 (660) Fri Jul 26 09:20:17 2019: Debug: NAS-Port = 1000 (660) Fri Jul 26 09:20:17 2019: Debug: Service-Type = Login-User (660) Fri Jul 26 09:20:17 2019: Debug: Acct-Session-Id = "07001C1F" (660) Fri Jul 26 09:20:17 2019: Debug: Called-Station-Id = "00-50-E8-03-82-6C" (660) Fri Jul 26 09:20:17 2019: Debug: Calling-Station-Id = "54-72-4F-69-14-B1" (660) Fri Jul 26 09:20:17 2019: Debug: Nomadix-Logoff-URL = "http://2.2.2.3" (660) Fri Jul 26 09:20:17 2019: Debug: WISPr-Location-ID = "isocc=,cc=,ac=,network=" (660) Fri Jul 26 09:20:17 2019: Debug: NAS-Identifier = "1000019" (660) Fri Jul 26 09:20:17 2019: Debug: Framed-IP-Address = 172.20.2.32 (660) Fri Jul 26 09:20:17 2019: Debug: MS-CHAP-Challenge = 0x795b0000883100003c760000721e0000 (660) Fri Jul 26 09:20:17 2019: Debug: MS-CHAP2-Response = 0x3700cb4e00005c030000971b0000f33900000000000000000000f3a9415e3205ea7d4a79fdb31489fab0fce1181a95c6584b (660) Fri Jul 26 09:20:17 2019: Debug: # Executing section authorize from file /etc/raddb/sites-enabled/default (660) Fri Jul 26 09:20:17 2019: Debug: authorize { (660) Fri Jul 26 09:20:17 2019: Debug: policy filter_username { (660) Fri Jul 26 09:20:17 2019: Debug: if (&User-Name) { (660) Fri Jul 26 09:20:17 2019: Debug: if (&User-Name) -> TRUE (660) Fri Jul 26 09:20:17 2019: Debug: if (&User-Name) { (660) Fri Jul 26 09:20:17 2019: Debug: if (&User-Name =~ / /) { (660) Fri Jul 26 09:20:17 2019: Debug: if (&User-Name =~ / /) -> FALSE (660) Fri Jul 26 09:20:17 2019: Debug: if (&User-Name =~ /@[^@]*@/ ) { (660) Fri Jul 26 09:20:17 2019: Debug: if (&User-Name =~ /@[^@]*@/ ) -> FALSE (660) Fri Jul 26 09:20:17 2019: Debug: if (&User-Name =~ /\.\./ ) { (660) Fri Jul 26 09:20:17 2019: Debug: if (&User-Name =~ /\.\./ ) -> FALSE (660) Fri Jul 26 09:20:17 2019: Debug: if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) { (660) Fri Jul 26 09:20:17 2019: Debug: if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) -> FALSE (660) Fri Jul 26 09:20:17 2019: Debug: if (&User-Name =~ /\.$/) { (660) Fri Jul 26 09:20:17 2019: Debug: if (&User-Name =~ /\.$/) -> FALSE (660) Fri Jul 26 09:20:17 2019: Debug: if (&User-Name =~ /@\./) { (660) Fri Jul 26 09:20:17 2019: Debug: if (&User-Name =~ /@\./) -> FALSE (660) Fri Jul 26 09:20:17 2019: Debug: } # if (&User-Name) = notfound (660) Fri Jul 26 09:20:17 2019: Debug: } # policy filter_username = notfound (660) Fri Jul 26 09:20:17 2019: Debug: [preprocess] = ok (660) Fri Jul 26 09:20:17 2019: Debug: [chap] = noop (660) Fri Jul 26 09:20:17 2019: Debug: mschap: Found MS-CHAP attributes. Setting 'Auth-Type = mschap' (660) Fri Jul 26 09:20:17 2019: Debug: [mschap] = ok (660) Fri Jul 26 09:20:17 2019: Debug: [digest] = noop (660) Fri Jul 26 09:20:17 2019: Debug: suffix: Checking for suffix after "@" (660) Fri Jul 26 09:20:17 2019: Debug: suffix: No '@' in User-Name = "54-72-4F-69-14-B1", looking up realm NULL (660) Fri Jul 26 09:20:17 2019: Debug: suffix: No such realm "NULL" (660) Fri Jul 26 09:20:17 2019: Debug: [suffix] = noop (660) Fri Jul 26 09:20:17 2019: Debug: eap: No EAP-Message, not doing EAP (660) Fri Jul 26 09:20:17 2019: Debug: [eap] = noop (660) Fri Jul 26 09:20:17 2019: Debug: [files] = noop (660) Fri Jul 26 09:20:17 2019: Debug: sql: EXPAND %{User-Name} (660) Fri Jul 26 09:20:17 2019: Debug: sql: --> 54-72-4F-69-14-B1 (660) Fri Jul 26 09:20:17 2019: Debug: sql: SQL-User-Name set to '54-72-4F-69-14-B1' (660) Fri Jul 26 09:20:17 2019: Debug: sql: EXPAND SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id (660) Fri Jul 26 09:20:17 2019: Debug: sql: --> SELECT id, username, attribute, value, op FROM radcheck WHERE username = '54-72-4F-69-14-B1' ORDER BY id (660) Fri Jul 26 09:20:17 2019: Debug: sql: Executing select query: SELECT id, username, attribute, value, op FROM radcheck WHERE username = '54-72-4F-69-14-B1' ORDER BY id (660) Fri Jul 26 09:20:17 2019: Debug: sql: EXPAND SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority (660) Fri Jul 26 09:20:17 2019: Debug: sql: --> SELECT groupname FROM radusergroup WHERE username = '54-72-4F-69-14-B1' ORDER BY priority (660) Fri Jul 26 09:20:17 2019: Debug: sql: Executing select query: SELECT groupname FROM radusergroup WHERE username = '54-72-4F-69-14-B1' ORDER BY priority (660) Fri Jul 26 09:20:17 2019: Debug: sql: User not found in any groups (660) Fri Jul 26 09:20:17 2019: Debug: [sql] = notfound (660) Fri Jul 26 09:20:17 2019: Debug: [expiration] = noop (660) Fri Jul 26 09:20:17 2019: Debug: [logintime] = noop (660) Fri Jul 26 09:20:17 2019: Debug: [pap] = noop (660) Fri Jul 26 09:20:17 2019: Debug: } # authorize = ok (660) Fri Jul 26 09:20:17 2019: Debug: Found Auth-Type = mschap (660) Fri Jul 26 09:20:17 2019: Debug: # Executing group from file /etc/raddb/sites-enabled/default (660) Fri Jul 26 09:20:17 2019: Debug: authenticate { (660) Fri Jul 26 09:20:17 2019: WARNING: mschap: No Cleartext-Password configured. Cannot create NT-Password (660) Fri Jul 26 09:20:17 2019: WARNING: mschap: No Cleartext-Password configured. Cannot create LM-Password (660) Fri Jul 26 09:20:17 2019: Debug: mschap: Creating challenge hash with username: 54-72-4F-69-14-B1 (660) Fri Jul 26 09:20:17 2019: Debug: mschap: Client is using MS-CHAPv2 (660) Fri Jul 26 09:20:17 2019: ERROR: mschap: FAILED: No NT/LM-Password. Cannot perform authentication (660) Fri Jul 26 09:20:17 2019: ERROR: mschap: MS-CHAP2-Response is incorrect (660) Fri Jul 26 09:20:17 2019: Debug: [mschap] = reject (660) Fri Jul 26 09:20:17 2019: Debug: } # authenticate = reject (660) Fri Jul 26 09:20:17 2019: Debug: Failed to authenticate the user (660) Fri Jul 26 09:20:17 2019: Debug: Using Post-Auth-Type Reject (660) Fri Jul 26 09:20:17 2019: Debug: # Executing group from file /etc/raddb/sites-enabled/default (660) Fri Jul 26 09:20:17 2019: Debug: Post-Auth-Type REJECT { (660) Fri Jul 26 09:20:17 2019: Debug: sql: EXPAND .query (660) Fri Jul 26 09:20:17 2019: Debug: sql: --> .query (660) Fri Jul 26 09:20:17 2019: Debug: sql: Using query template 'query' (660) Fri Jul 26 09:20:17 2019: Debug: sql: EXPAND %{User-Name} (660) Fri Jul 26 09:20:17 2019: Debug: sql: --> 54-72-4F-69-14-B1 (660) Fri Jul 26 09:20:17 2019: Debug: sql: SQL-User-Name set to '54-72-4F-69-14-B1' (660) Fri Jul 26 09:20:17 2019: Debug: sql: EXPAND INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '%{SQL-User-Name}', '%{%{User-Password}:-%{Chap-Password}}', '%{reply:Packet-Type}', '%S') (660) Fri Jul 26 09:20:17 2019: Debug: sql: --> INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '54-72-4F-69-14-B1', '', 'Access-Reject', '2019-07-26 09:20:17') (660) Fri Jul 26 09:20:17 2019: Debug: sql: Executing query: INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '54-72-4F-69-14-B1', '', 'Access-Reject', '2019-07-26 09:20:17') (660) Fri Jul 26 09:20:17 2019: Debug: sql: SQL query returned: success (660) Fri Jul 26 09:20:17 2019: Debug: sql: 1 record(s) updated (660) Fri Jul 26 09:20:17 2019: Debug: [sql] = ok (660) Fri Jul 26 09:20:17 2019: Debug: attr_filter.access_reject: EXPAND %{User-Name} (660) Fri Jul 26 09:20:17 2019: Debug: attr_filter.access_reject: --> 54-72-4F-69-14-B1 (660) Fri Jul 26 09:20:17 2019: Debug: attr_filter.access_reject: Matched entry DEFAULT at line 11 (660) Fri Jul 26 09:20:17 2019: Debug: [attr_filter.access_reject] = updated (660) Fri Jul 26 09:20:17 2019: Debug: [eap] = noop (660) Fri Jul 26 09:20:17 2019: Debug: policy remove_reply_message_if_eap { (660) Fri Jul 26 09:20:17 2019: Debug: if (&reply:EAP-Message && &reply:Reply-Message) { (660) Fri Jul 26 09:20:17 2019: Debug: if (&reply:EAP-Message && &reply:Reply-Message) -> FALSE (660) Fri Jul 26 09:20:17 2019: Debug: else { (660) Fri Jul 26 09:20:17 2019: Debug: [noop] = noop (660) Fri Jul 26 09:20:17 2019: Debug: } # else = noop (660) Fri Jul 26 09:20:17 2019: Debug: } # policy remove_reply_message_if_eap = noop (660) Fri Jul 26 09:20:17 2019: Debug: } # Post-Auth-Type REJECT = updated (660) Fri Jul 26 09:20:17 2019: Debug: EXPAND %{NAS-IP-Address} %{NAS-Identifier} (660) Fri Jul 26 09:20:17 2019: Debug: --> 67.135.207.161 1000019 Let me see if I can be a little more clear. I'm pretty sure that, reading the debug output, the problem is that the user password is not present in the packet that FR receives from the NAS. We know that the instruction we send to the NAS to auth a device is correct, and does include both the username and the correct password. We know that the NAS receives it, but when it tries the auth with FR, it appears to "lose" the password, resulting in a reject response. In short, I believe the problem is in the data sent by the NAS. Thus, I simply want to confirm that my understanding of what I've read is correct, that FR is not the problem (and I really don't think it is), and that the NAS is the actual source of the problem. Having confirmed that, I will then hand it to the NAS vendor and tell them to find/fix what's broken in their devices. Ultimately, I just need a second set of eyes (from someone who is far better at this than I) so I can move in the proper direction. Thank you, Alan. -- Jim