auth_result fired twice?

Hi,

 

Me again. Now we have managed to replicate the issue. Log file shows the following strage behaviour. Our system has recently been upgraded to V10.2

 

 

First, the event CLIENT_ACCEPTED fires off,

 

 

Dec 13 15:29:58 local/tmm debug tmm[21217]: Rule cbz_ocsp_action CLIENT_ACCEPTED: inside event CLIENT_ACCEPTED 3772965817

 

Dec 13 15:29:58 local/tmm debug tmm[21217]: Rule cbz_ocsp_action CLIENT_ACCEPTED: inside event CLIENT_ACCEPTED 2928793149

 

 

Then CLIENTSSL_CLIENTCERT fires,

 

Dec 13 15:29:58 local/tmm debug tmm[21217]: Rule cbz_ocsp_action CLIENTSSL_CLIENTCERT: verify result ok

 

Dec 13 15:29:58 local/tmm debug tmm[21217]: Rule cbz_ocsp_action CLIENTSSL_CLIENTCERT: doing OCSP

 

Dec 13 15:29:58 local/tmm debug tmm[21217]: Rule cbz_ocsp_action CLIENTSSL_CLIENTCERT: verify result ok

 

Dec 13 15:29:58 local/tmm debug tmm[21217]: Rule cbz_ocsp_action CLIENTSSL_CLIENTCERT: doing OCSP

 

 

Event AUTH_RESULT follows, and so far so good.

 

Dec 13 15:30:12 local/tmm debug tmm[21217]: Rule cbz_ocsp_action AUTH_RESULT: authentication status of round 1 0, 3772965817

 

Dec 13 15:30:12 local/tmm debug tmm[21217]: Rule cbz_ocsp_action AUTH_RESULT : OCSP verfication succeeded

 

Dec 13 15:30:12 local/tmm debug tmm[21217]: Rule cbz_ocsp_action AUTH_RESULT: authentication status of round 1 0, 2928793149

 

Dec 13 15:30:12 local/tmm debug tmm[21217]: Rule cbz_ocsp_action AUTH_RESULT: OCSP verfication succeeded

 

 

Then, a couple of minutes later, actually 5 minutes sharp after CLIENTSSL_CLIENTCERT , AUTH_RESULT fires again! This time, it reports an verification error.

 

Dec 13 15:34:58 local/tmm debug tmm[21217]: Rule cbz_ocsp_action AUTH_RESULT: authentication status of round 1 -1, 2928793149

 

Dec 13 15:34:58 local/tmm debug tmm[21217]: Rule cbz_ocsp_action AUTH_RESULT: OCSP verfication error, ocsp:response:status good

 

Dec 13 15:34:58 local/tmm debug tmm[21217]: Rule cbz_ocsp_action AUTH_RESULT: authentication status of round 1 -1, 3772965817

 

Dec 13 15:34:58 local/tmm debug tmm[21217]: Rule cbz_ocsp_action AUTH_RESULT: OCSP verfication error, ocsp:response:status good

 

 

It doesn't always happen in that way. There are some SSL sessions just have one .

 

 

Here is my iRule,

 

 

when CLIENT_ACCEPTED { set tmm_auth_ssl_ocsp_sid [AUTH::start pam default_ssl_ocsp] log local0.debug "inside event CLIENT_ACCEPTED $tmm_auth_ssl_ocsp_sid" } when CLIENTSSL_CLIENTCERT { set ssl_cert [SSL::cert 0] set id [SSL::sessionid] set hash [b64encode [sha1 $ssl_cert]] set ssl_array [list blah1 blah2 $hash] lset ssl_array 0 [X509::verify_cert_error_string [SSL::verify_result]] log local0.debug "verify result [lindex $ssl_array 0]" if {[matchclass 1 equals $::cbz_ocsp_check]} { AUTH::cert_credential $tmm_auth_ssl_ocsp_sid $ssl_cert AUTH::cert_issuer_credential $tmm_auth_ssl_ocsp_sid [SSL::cert issuer 0] AUTH::subscribe $tmm_auth_ssl_ocsp_sid AUTH::authenticate $tmm_auth_ssl_ocsp_sid log local0.debug "doing OCSP" SSL::handshake hold } else { log local0.debug "ocsp bypassed" lset ssl_array 1 "ocsp_bypassed" session add ssl "$id any pool" $ssl_array 21600 } } when AUTH_RESULT { if {[info exists tmm_auth_ssl_ocsp_sid] and $tmm_auth_ssl_ocsp_sid eq [AUTH::last_event_session_id]} { set tmm_auth_status [AUTH::status] log local0.debug "authentication status of round 1 $tmm_auth_status, $tmm_auth_ssl_ocsp_sid" if {$tmm_auth_status eq 0} { Success log local0.debug "OCSP verfication succeeded" SSL::handshake resume lset ssl_array 1 "auth_success" } elseif {$tmm_auth_status eq 1} { Failure log local0.debug "OCSP verfication failed, [AUTH::response_data]" SSL::handshake resume lset ssl_array 1 "auth_failure" } elseif {$tmm_auth_status eq -1} { Error log local0.debug "OCSP verfication error, [AUTH::response_data]" lset ssl_array 1 "auth_failure" } else { Not authorised log local0.debug "OCSP verfication not authorised" reject } session add ssl "$id any pool" $ssl_array 21600 } } when HTTP_REQUEST priority 100 { log local0. "Inside ocsp" if {not([matchclass [string tolower [HTTP::path]] contains $::cbz_data_static])} { if {[matchclass 1 equals $::cbz_ocsp_check]} { set id [SSL::sessionid] set ssl_array1 [session lookup ssl "$id any pool"] set ssl_data0 [lindex $ssl_array1 0] set ssl_data1 [lindex $ssl_array1 1] log local0.debug "session id: $id ssl_data0: $ssl_data0 ssl_data1: $ssl_data1" if { $ssl_data0 contains "expired" } { log local0.debug "Certificate expired" HTTP::path "/common/common.web/html/CertificateExpired.html" } elseif { $ssl_data1 contains "auth_failure" } { log local0.debug "Authentication failure" HTTP::path "/Common/Common.Web/html/OcspFailed.html" } elseif { $ssl_data0 contains "ok" } { HTTP::header insert SSLCLientCertStatus $ssl_data1 } else { log local0.debug "unknow error" HTTP::path "/common/common.web/html/CertificateError.html" } } else { log local0.debug "Generate ocsp bypass header" HTTP::header insert OcspBypassed 1 } } }

 

 

I can think of two places specifying the 5 minutes limit. One is the OCSP profile, idle timeout. Default value is 300 secs, i.e. 5 minutes. Another one is "Validity period" of OCSP responder, which is configured to be 300 secs to be default value as well.