Logging mschap error when send_error=yes

[Brian Julin]

Currently I'm configuring new servers for an eventual 3.0.x migration,
and decided to take a look at password-change.  I have not got that far yet,
just as far as playing around with the server behavior when EAP-MCHAPv2 is set
to send_error = yes, which is a prerequisite for that.  As soon as this is turned on
we seem to lose the ability to log the exact error code returned by ntlm_auth, and
this is actually one of the more critical log messages we need to detect locked
accounts.

With send_error=yes the flow out of the inner tunnel after a bad ntlm auth is as follows:

(8) : ERROR: upn_mschap: Program returned code (1) and output 'Logon failure (0xc000006d)'
(8) : Debug: upn_mschap: External script failed
(8) : ERROR: upn_mschap: External script says: Logon failure (0xc000006d)
(8) : ERROR: upn_mschap: MS-CHAP2-Response is incorrect
(8) : Debug:     modsingle[authenticate]: returned from upn_mschap (rlm_mschap) for request 8
(8) : Debug:     [upn_mschap] = reject
(8) : Debug:   } # Auth-Type MS-CHAP = reject
(8) : Debug: MSCHAP-Error:E=691 R=0 C=792471a3e2e250631e1353c26afb0b8f V=3 M=Authentication failed
(8) : Debug: Found new challenge from MS-CHAP-Error: err=691 retry=0 challenge=792471a3e2e250631e1353c26afb0b8f
(8) : ERROR: MSCHAP Failure
(8) : Debug: eap: Sending EAP Request (code 1) ID 9 length 81
(8) : Debug: eap: EAP session adding &reply:State = 0xb5db88f6b4d292e4
(8) : Debug:       modsingle[authenticate]: returned from eap (rlm_eap) for request 8
(8) : Debug:       [eap] = handled
(8) : Debug:     } # Auth-Type EAP = handled
(8) : Debug: } # server eduroam_idpi_inner

... and there seems to be pretty much no toehold by which to get an unlang statement
into that to store or log MSCHAP-Error or Module-Failure-Message.  I haven't tried
use_tunneled_reply as it is marked as deprecated in favor of the new state handling,
but I've tried just about everything else I can think of.  With send_error=no, default
internal logging would normally log the ntlm_auth result, or we could catch it in the
inner tunnel's post-auth Reject section:

(8) : ERROR: upn_mschap: Program returned code (1) and output 'Logon failure (0xc000006d)'
(8) : Debug: upn_mschap: External script failed
(8) : ERROR: upn_mschap: External script says: Logon failure (0xc000006d)
(8) : ERROR: upn_mschap: MS-CHAP2-Response is incorrect
(8) : Debug:     modsingle[authenticate]: returned from upn_mschap (rlm_mschap) for request 8
(8) : Debug:     [upn_mschap] = reject
(8) : Debug:   } # Auth-Type MS-CHAP = reject
(8) : Debug: eap: Sending EAP Failure (code 4) ID 8 length 4
(8) : Debug: eap: Freeing handler
(8) : Debug:       modsingle[authenticate]: returned from eap (rlm_eap) for request 8
(8) : Debug:       [eap] = reject
(8) : Debug:     } # Auth-Type EAP = reject
(8) : Debug:   Failed to authenticate the user
(8) : Debug:   Using Post-Auth-Type Reject
(8) : Debug:   # Executing group from file /etc/raddb/eduroam_idpi.conf
(8) : Debug:     Post-Auth-Type REJECT {

So my first question is, am I missing a trick that would allow me to log the ntlm_auth result?

The second thing is that, since the failure seems to promulgate down to the EAP layer in
a different fashion (a new challenge seems to always be issued and the failure delayed
until later packets, even when retries are not allowed) the normal logs get filled with
the usual "The users session was previously rejected" stanza, which in this particular
case is not very helpful since there's not much to read above them (and it's a lot of syslog
bulk for a common logon failure.)

No real question there,  just an observation.

The third thing is, while looking further into this I noticed the current code for dealing
with locked accounts appears to be entirely based off SMB-Account-CTRL, which does not
seem to exist when authing against an actual AD server rather than a local Samba setup.
For password changes there is code to use the text returned from ntlm_auth instead, but locked
or disabled accounts just end up sending 691/"Authentication failed" instead
of the actual error.  So I quick-hacked the C code to pass on the code/message for
locks and disables.

Second question: is there any particular reason why the code is the way it is, or is
it just a not-implemented-yet situation?