Help configuring FreeRADIUS on OS X Server - ERROR: (2) mschap: ERROR: (null): status = eServerError
Eric Wittle
eric at wittle.net
Wed Dec 5 04:16:16 CET 2018
And now I’ll resume the path I was originally on.
The problem that is causing my VPN to fail authentication, from comparing the responses outside of debugging, is that 3.0.17 is not returning MS-CHAP2-Success. If we look at opendir.c in rlm_mschap, we see the following code:
if (status == eDSNoErr) {
RDEBUG2("ELW: status == eDSNoErr\n");
if (pStepBuff->fBufferLength > 4) {
RDEBUG2("ELW: pStepBuff->fBufferLength > 4\n");
size_t len;
memcpy(&len, pStepBuff->fBufferData, sizeof(len));
if (len == 40) {
RDEBUG2("ELW: len == 40\n");
char mschap_reply[42] = { '\0' };
pStepBuff->fBufferData[len+4] = '\0';
mschap_reply[0] = 'S';
mschap_reply[1] = '=';
memcpy(&(mschap_reply[2]), &(pStepBuff->fBufferData[4]), len);
mschap_add_reply(request, &request->reply->vps,
*response->vp_strvalue,
"MS-CHAP2-Success",
mschap_reply, len+2);
RDEBUG2("dsDoDirNodeAuth returns stepbuff: %s (len=%zu)\n", mschap_reply, len);
} else {
RDEBUG2("ELW: len == %zu\n", len);
}
}
}
You may notice a few extra lines I added for debugging purposes (text strings with ELW in them). This code seems pretty clearly where MS-CHAP2-Success is supposed to be added to the reply. Below, in the section headed Appendix A, you see the debug output from 3.0.17 with the additional debugging added. It clearly shows that the test “len == 40” is failing during successful authentication, and therefore the MS-CHAP2-Success value is not being added to the reply.
It has been many decades since I did C programming, so this exhausts my ability to debug the problem without digging out my Kernighan & Ritchie, assuming I could find it.
I’ve seen text in various comments that the open directory configuration is owned by Apple, should I assume that opendir.c is owned by them as well? If so, I’ll file a bug with them, and drop back to 2.2.10.
Appendix A
=========
Ready to process requests
(0) Received Access-Request Id 49 from 192.168.1.1:50192 to 192.168.1.2:1812 length 132
(0) Service-Type = Framed-User
(0) Framed-Protocol = PPP
(0) User-Name = "eric"
(0) MS-CHAP-Challenge = 0x2865983ecdee941a08a635417c19deb5
(0) MS-CHAP2-Response = 0x410010c7856c01bf71f1230a236ccd8a535a000000000000000008c485f49f713bcefda1a071a0df4565e3fd316e9c5aa40e
(0) NAS-IP-Address = 127.0.1.1
(0) NAS-Port = 0
(0) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default
(0) authorize {
(0) policy filter_username {
(0) if (&User-Name) {
(0) if (&User-Name) -> TRUE
(0) if (&User-Name) {
(0) if (&User-Name =~ / /) {
(0) if (&User-Name =~ / /) -> FALSE
(0) if (&User-Name =~ /@[^@]*@/ ) {
(0) if (&User-Name =~ /@[^@]*@/ ) -> FALSE
(0) if (&User-Name =~ /\.\./ ) {
(0) if (&User-Name =~ /\.\./ ) -> FALSE
(0) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) {
(0) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) -> FALSE
(0) if (&User-Name =~ /\.$/) {
(0) if (&User-Name =~ /\.$/) -> FALSE
(0) if (&User-Name =~ /@\./) {
(0) if (&User-Name =~ /@\./) -> FALSE
(0) } # if (&User-Name) = notfound
(0) } # policy filter_username = notfound
(0) [preprocess] = ok
(0) auth_log: EXPAND /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d
(0) auth_log: --> /var/log/radius/radacct/192.168.1.1/auth-detail-20181204
(0) auth_log: /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d expands to /var/log/radius/radacct/192.168.1.1/auth-detail-20181204
(0) auth_log: EXPAND %t
(0) auth_log: --> Tue Dec 4 21:59:38 2018
(0) [auth_log] = ok
(0) [chap] = noop
(0) mschap: Found MS-CHAP attributes. Setting 'Auth-Type = mschap'
(0) [mschap] = ok
(0) [digest] = noop
(0) suffix: Checking for suffix after "@"
(0) suffix: No '@' in User-Name = "eric", looking up realm NULL
(0) suffix: No such realm "NULL"
(0) [suffix] = noop
(0) eap: No EAP-Message, not doing EAP
(0) [eap] = noop
(0) files: users: Matched entry DEFAULT at line 181
(0) [files] = ok
(0) opendirectory: The host 192.168.1.1 does not have an access group.
(0) [opendirectory] = ok
(0) sql: EXPAND %{User-Name}
(0) sql: --> eric
(0) sql: SQL-User-Name set to 'eric'
rlm_sql (sql): Closing connection (1): Hit idle_timeout, was idle for 136 seconds
rlm_sql_sqlite: Socket destructor called, closing socket
rlm_sql (sql): Closing connection (2): Hit idle_timeout, was idle for 136 seconds
rlm_sql_sqlite: Socket destructor called, closing socket
rlm_sql (sql): Closing connection (3): Hit idle_timeout, was idle for 136 seconds
rlm_sql_sqlite: Socket destructor called, closing socket
rlm_sql (sql): Closing connection (4): Hit idle_timeout, was idle for 136 seconds
rlm_sql (sql): You probably need to lower "min"
rlm_sql_sqlite: Socket destructor called, closing socket
rlm_sql (sql): Closing connection (0): Hit idle_timeout, was idle for 136 seconds
rlm_sql (sql): You probably need to lower "min"
rlm_sql_sqlite: Socket destructor called, closing socket
rlm_sql (sql): Closing connection (5): Hit idle_timeout, was idle for 136 seconds
rlm_sql (sql): You probably need to lower "min"
rlm_sql_sqlite: Socket destructor called, closing socket
rlm_sql (sql): 0 of 0 connections in use. You may need to increase "spare"
rlm_sql (sql): Opening additional connection (6), 1 of 32 pending slots used
rlm_sql_sqlite: Opening SQLite database "/var/db/radius/freeradius.db"
rlm_sql (sql): Reserved connection (6)
(0) sql: EXPAND SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id
(0) sql: --> SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'eric' ORDER BY id
(0) sql: Executing select query: SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'eric' ORDER BY id
(0) sql: EXPAND SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority
(0) sql: --> SELECT groupname FROM radusergroup WHERE username = 'eric' ORDER BY priority
(0) sql: Executing select query: SELECT groupname FROM radusergroup WHERE username = 'eric' ORDER BY priority
(0) sql: User not found in any groups
rlm_sql (sql): Released connection (6)
Need 2 more connections to reach min connections (3)
rlm_sql (sql): Opening additional connection (7), 1 of 31 pending slots used
rlm_sql_sqlite: Opening SQLite database "/var/db/radius/freeradius.db"
(0) [sql] = notfound
(0) [expiration] = noop
(0) [logintime] = noop
(0) pap: WARNING: No "known good" password found for the user. Not setting Auth-Type
(0) pap: WARNING: Authentication will fail unless a "known good" password is available
(0) [pap] = noop
(0) } # authorize = ok
(0) Found Auth-Type = mschap
(0) # Executing group from file /usr/local/etc/raddb/sites-enabled/default
(0) authenticate {
(0) mschap: WARNING: No Cleartext-Password configured. Cannot create NT-Password
(0) mschap: WARNING: No Cleartext-Password configured. Cannot create LM-Password
(0) mschap: No NT-Password configured. Trying OpenDirectory Authentication
(0) mschap: OD username_string = eric, OD shortUserName=eric (length = 4)
(0) mschap: Stepbuf server challenge :
2865ffffff983effffffcdffffffeeffffff941a08ffffffa635417c19ffffffdeffffffb5
(0) mschap: Stepbuf peer challenge :
10ffffffc7ffffff856c01ffffffbf71fffffff1230a236cffffffcdffffff8a535a
(0) mschap: Stepbuf p24 :
08ffffffc4ffffff85fffffff4ffffff9f713bffffffcefffffffdffffffa1ffffffa071ffffffa0ffffffdf4565ffffffe3fffffffd316effffff9c5affffffa40e
(0) mschap: ELW: status == eDSNoErr
(0) mschap: ELW: pStepBuff->fBufferLength > 4
(0) mschap: ELW: len == 3978992058181353512
(0) [mschap] = ok
(0) } # authenticate = ok
(0) # Executing section post-auth from file /usr/local/etc/raddb/sites-enabled/default
(0) post-auth {
(0) update {
(0) No attributes updated
(0) } # update = noop
(0) reply_log: EXPAND /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/reply-detail-%Y%m%d
(0) reply_log: --> /var/log/radius/radacct/192.168.1.1/reply-detail-20181204
(0) reply_log: /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/reply-detail-%Y%m%d expands to /var/log/radius/radacct/192.168.1.1/reply-detail-20181204
(0) reply_log: EXPAND %t
(0) reply_log: --> Tue Dec 4 21:59:38 2018
(0) [reply_log] = ok
(0) sql: EXPAND .query
(0) sql: --> .query
(0) sql: Using query template 'query'
rlm_sql (sql): Reserved connection (6)
(0) sql: EXPAND %{User-Name}
(0) sql: --> eric
(0) sql: SQL-User-Name set to 'eric'
(0) sql: EXPAND INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '%{SQL-User-Name}', '%{%{User-Password}:-%{Chap-Password}}', '%{reply:Packet-Type}', '%S')
(0) sql: --> INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'eric', '', 'Access-Accept', '2018-12-04 21:59:38')
(0) sql: Executing query: INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'eric', '', 'Access-Accept', '2018-12-04 21:59:38')
(0) sql: SQL query returned: success
(0) sql: 1 record(s) updated
rlm_sql (sql): Released connection (6)
(0) [sql] = ok
(0) [exec] = noop
(0) policy remove_reply_message_if_eap {
(0) if (&reply:EAP-Message && &reply:Reply-Message) {
(0) if (&reply:EAP-Message && &reply:Reply-Message) -> FALSE
(0) else {
(0) [noop] = noop
(0) } # else = noop
(0) } # policy remove_reply_message_if_eap = noop
(0) } # post-auth = ok
(0) Login OK: [eric/<via Auth-Type = mschap>] (from client router.wittle.net port 0)
(0) Sent Access-Accept Id 49 from 192.168.1.2:1812 to 192.168.1.1:50192 length 0
(0) Framed-Protocol = PPP
(0) Framed-Compression = Van-Jacobson-TCP-IP
(0) Finished request
Waking up in 4.9 seconds.
(0) Cleaning up request packet ID 49 with timestamp +136
Ready to process requests
More information about the Freeradius-Users
mailing list