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.