[RADIATOR] Logging verify error from EAPTLS_CertificateVerifyFailedHook in AuthLog

[Tuure Vartiainen]

Hi,

> On 27 Feb 2018, at 17.42, Christian Kratzer <ck at cksoft.de> wrote:
> 
> On Tue, 27 Feb 2018, Tuure Vartiainen wrote:
>> 
>> 
>>> On 27 Feb 2018, at 15.22, Christian Kratzer <ck at cksoft.de> wrote:
>>> 
>>> as a business requirement we have implemented following EAPTLS_CertificateVerifyFailedHook to return success on broken expired or missing CRL for TLS authentication with client certificates.
>>> 
>>> This is working as follows:
>>> 
>>>   sub {
>>>       my $verify_error = $_[0];
>>>       my $p = $_[5];
>>> 
>>>       &main::log($main::LOG_DEBUG, "EAPTLS_CertificateVerifyFailedHook: verify_error: $verify_error");
>>> 
>>>       # save verify error to reply for auth logging
>>>       $p->{EAPContext}->{EAPTLS_Session}->{verify_error} = Radius::TLS::verify_error_string($verify_error);
>>> 
>>>       # return success on specific verification error
>>> 	#  3   => 'unable to get certificate CRL',
>>> 	#  12   => 'CRL has expired',
>>>       if( $verify_error==3 || $verify_error==12 ) {
>>>           return 0;
>>>       }
>>> 
>>>       # otherwise pass through original error
>>>       return $verify_error;
>>>   }
>>> 
>>> we also need to log the verify_error in the Handlers authlog.
>>> 
>>> For that we are attempting to store the verify error inside the EAP Session.
>>> 
>>> When trying to access the value from an AuthLogFileHook using %{EAPTLS:verify_error} the value is missing.
>>> 
>>> Any suggestions how we could pass the error from EAPTLS_CertificateVerifyFailedHook back into an AuthLogFileHook ?
>>> 
>> 
>> did you test both access and reject?
>> 
>> Looking at the code, without testing this myself, I would assume that verify_error is available
>> when logging a reject but not when logging an accept?
> 
> we are only interested in logging the verify_error when there actually is a verification failure.
> 
> 
>> $p->{EAPContext}->{EAPTLS_Session} does not actually exist before accepting TLS connection,
>> after which it is assigned in Radius::TLS::get_session_info() and that assignment overwrites verify_error
>> assigned in your EAPTLS_CertificateVerifyFailedHook.
>> 
>> A workaround is to save verify_error in $p->{internal_vars}->{my_tls_verify_error} and log it by using %{RequestVar:my_tls_verify_error}.
> 
> we changed our code to be as follows and also removed the change of return code to simplify:
> 
> 	sub {
> 	    my $verify_error = $_[0];
> 	    my $p = $_[5];
> 
> 	    &main::log($main::LOG_DEBUG, "EAPTLS_CertificateVerifyFailedHook: verify_error: $verify_error");
> 	    $p->{internal_vars}->{my_tls_verify_error} = $verify_error;
> 	    if( $verify_error==3 || $verify_error==12 ) {
> 	       return 0;
> 	    }
> 	    return $verify_error;
> 	}
> 
> 
> this results in following logging that proves the hook actually runs:
> 
> 	Tue Feb 27 16:15:47 2018 564213: DEBUG: Certificate verification failure reason: unable to get certificate CRL
> 	Tue Feb 27 16:15:47 2018 564321: DEBUG: EAPTLS_CertificateVerifyFailedHook: verify_error: 3
> 
> We still cannot acess the error from the logging hook with %{RequestVar:my_tls_verify_error}
> 
> There is a difference if we remove our return 0 to the EAPTLS_CertificateVerifyFailedHook.
> 
> In that case the Reply-Message reflects the error
> 
> 	sub {
> 	    my $verify_error = $_[0];
> 	    my $p = $_[5];
> 
> 	    &main::log($main::LOG_DEBUG, "EAPTLS_CertificateVerifyFailedHook: verify_error: $verify_error");
> 	    $p->{internal_vars}->{my_tls_verify_error} = $verify_error;
> 	    return $verify_error;
> 	}
> 
> 	Tue Feb 27 16:19:40 2018 327336: INFO: Access rejected for host/test1: TLS Alert acknowledged: unable to get certificate CRL, certificate verify failed
> 	Tue Feb 27 16:19:40 2018 329219: DEBUG: Packet dump:
> 	*** Sending to ::1 port 59597 ....
> 	Code:       Access-Reject
> 	Identifier: 8
> 	Authentic:  v&<166>G<185><143>;<241>jl<154><15><237><16><31><25>
> 	Attributes:
> 		EAP-Message = <4><7><0><4>
> 		Message-Authenticator = ~<234>0<19>]<133><171><228><160><23><184>E<173>\i<188>
> 		Reply-Message = "TLS Alert acknowledged: unable to get certificate CRL, certificate verify failed"
> 
> But we still cannot access %{RequestVar:my_tls_verify_error} from the auth logging hook in the handler.
> 

my bad, my_tls_verify_error variable is available during the round when EAPTLS_CertificateVerifyFailedHook is run, but 
as EAP-TLS continues with Radiator sending back TLS alert to the client which will acknowledge it on a next round before 
Radiator will call AuthLog and return Access-Reject, the variable won’t be available anymore to be used by AuthLog. 

A correct way would be to use EAPContext which is available during EAP authentication, 
but currently there’s no special variable for accessing it in e.g. AuthLog’s SuccessFormat or FailureFormat.
However, LogFormatHook can access it through $p so using the hook for forming a log entry can be used as a workaround.

I’ll create a feature request for special variables for accessing EAP context and resume context.


BR
-- 
Tuure Vartiainen <vartiait at open.com.au>

Radiator: the most portable, flexible and configurable RADIUS server
anywhere. SQL, proxy, DBM, files, LDAP, NIS+, password, NT, Emerald,
Platypus, Freeside, TACACS+, PAM, external, Active Directory, EAP, TLS,
TTLS, PEAP, TNC, WiMAX, RSA, Vasco, Yubikey, MOTP, HOTP, TOTP,
DIAMETER etc. Full source on Unix, Windows, MacOSX, Solaris, VMS,
NetWare etc.