attempt to achieve consistent debugging output

This commit is contained in:
Andreas Steffen
2008-03-19 12:06:38 +00:00
parent d3a6993777
commit ae8715f956
7 changed files with 79 additions and 69 deletions
+41 -31
View File
@@ -410,11 +410,8 @@ static ocsp_wrapper_t *ocsp_wrapper_create(ocsp_response_t *response)
static certificate_t *fetch_ocsp(private_credential_manager_t *this, char *url, static certificate_t *fetch_ocsp(private_credential_manager_t *this, char *url,
certificate_t *subject, certificate_t *issuer) certificate_t *subject, certificate_t *issuer)
{ {
certificate_t *request, *response, *issuer_cert; certificate_t *request, *response;
chunk_t send, receive; chunk_t send, receive;
identification_t *responder;
auth_info_t *auth;
ocsp_wrapper_t *wrapper;
/* TODO: requestor name, signature */ /* TODO: requestor name, signature */
request = lib->creds->create(lib->creds, request = lib->creds->create(lib->creds,
@@ -429,6 +426,8 @@ static certificate_t *fetch_ocsp(private_credential_manager_t *this, char *url,
send = request->get_encoding(request); send = request->get_encoding(request);
request->destroy(request); request->destroy(request);
DBG1(DBG_CFG, "requesting ocsp response from '%s' ...", url);
if (lib->fetcher->fetch(lib->fetcher, url, &receive, if (lib->fetcher->fetch(lib->fetcher, url, &receive,
FETCH_REQUEST_DATA, send, FETCH_REQUEST_DATA, send,
FETCH_REQUEST_TYPE, "application/ocsp-request", FETCH_REQUEST_TYPE, "application/ocsp-request",
@@ -449,29 +448,40 @@ static certificate_t *fetch_ocsp(private_credential_manager_t *this, char *url,
return NULL; return NULL;
} }
responder = response->get_issuer(response);
auth = auth_info_create(); /* verify the signature of the ocsp response */
wrapper = ocsp_wrapper_create((ocsp_response_t*)response);
this->sets->insert_first(this->sets, wrapper);
issuer_cert = get_trusted_cert(this, KEY_ANY, responder, auth, FALSE, FALSE);
this->sets->remove(this->sets, wrapper, NULL);
free(wrapper);
auth->destroy(auth);
if (!issuer_cert)
{ {
DBG1(DBG_CFG, " ocsp response untrusted: no signer certificate found"); certificate_t *issuer_cert;
response->destroy(response); identification_t *responder;
return NULL; auth_info_t *auth;
} ocsp_wrapper_t *wrapper;
if (!response->issued_by(response, issuer_cert, TRUE)) bool ok;
{
DBG1(DBG_CFG, " ocsp response untrusted: bad signature"); auth = auth_info_create();
response->destroy(response); wrapper = ocsp_wrapper_create((ocsp_response_t*)response);
this->sets->insert_first(this->sets, wrapper);
responder = response->get_issuer(response);
issuer_cert = get_trusted_cert(this, KEY_ANY, responder, auth, FALSE, FALSE);
this->sets->remove(this->sets, wrapper, NULL);
free(wrapper);
auth->destroy(auth);
if (!issuer_cert)
{
DBG1(DBG_CFG, " ocsp response untrusted: no signer certificate found");
response->destroy(response);
return NULL;
}
ok = response->issued_by(response, issuer_cert, TRUE);
issuer_cert->destroy(issuer_cert); issuer_cert->destroy(issuer_cert);
return NULL; DBG1(DBG_CFG, " ocsp response is %strusted: %s signature",
ok ? "":"un", ok ? "good" : "bad");
if (ok)
{
response->destroy(response);
return NULL;
}
} }
issuer_cert->destroy(issuer_cert);
/* TODO: cache response? */ /* TODO: cache response? */
return response; return response;
} }
@@ -863,7 +873,7 @@ static bool check_certificate(private_credential_manager_t *this,
} }
if (issuer && !subject->issued_by(subject, issuer, TRUE)) if (issuer && !subject->issued_by(subject, issuer, TRUE))
{ {
DBG1(DBG_CFG, "certificate %D not issued by %D", DBG1(DBG_CFG, "certificate not issued by \"%D\"",
subject->get_subject(subject), issuer->get_subject(issuer)); subject->get_subject(subject), issuer->get_subject(issuer));
return FALSE; return FALSE;
} }
@@ -1055,8 +1065,8 @@ static certificate_t *get_trusted_cert(private_credential_manager_t *this,
public = subject->get_public_key(subject); public = subject->get_public_key(subject);
if (public) if (public)
{ {
DBG2(DBG_CFG, "using trusted certificate %D", DBG1(DBG_CFG, " using trusted certificate \"%D\"",
subject->get_subject(subject)); subject->get_subject(subject));
this->sets->remove(this->sets, wrapper, NULL); this->sets->remove(this->sets, wrapper, NULL);
free(wrapper); free(wrapper);
this->mutex->unlock(this->mutex); this->mutex->unlock(this->mutex);
@@ -1076,7 +1086,7 @@ static certificate_t *get_trusted_cert(private_credential_manager_t *this,
subject = get_cert(this, CERT_ANY, type, id, FALSE); subject = get_cert(this, CERT_ANY, type, id, FALSE);
if (!subject) if (!subject)
{ {
DBG1(DBG_CFG, "no end entity certificate found for %D", id); DBG1(DBG_CFG, "no end entity certificate found for \"%D\"", id);
} }
else else
{ {
@@ -1093,7 +1103,7 @@ static certificate_t *get_trusted_cert(private_credential_manager_t *this,
issuer == subject ? auth2 : NULL) && issuer == subject ? auth2 : NULL) &&
check_certificate(this, candidate, NULL, crl, ocsp, NULL)) check_certificate(this, candidate, NULL, crl, ocsp, NULL))
{ {
DBG2(DBG_CFG, "using trusted root CA certificate %D", DBG1(DBG_CFG, " using trusted root ca certificate \"%D\"",
candidate->get_subject(candidate)); candidate->get_subject(candidate));
issuer = candidate; issuer = candidate;
trusted = TRUE; trusted = TRUE;
@@ -1120,13 +1130,13 @@ static certificate_t *get_trusted_cert(private_credential_manager_t *this,
{ {
if (issuer != subject) if (issuer != subject)
{ {
DBG2(DBG_CFG, "using intermediate CA certificate %D", DBG1(DBG_CFG, " using intermediate ca certificate \"%D\"",
candidate->get_subject(candidate)); candidate->get_subject(candidate));
auth1->add_item(auth1, AUTHZ_IM_CERT, candidate); auth1->add_item(auth1, AUTHZ_IM_CERT, candidate);
} }
else else
{ {
DBG2(DBG_CFG, "using end entity certificate %D", DBG1(DBG_CFG, " using end entity certificate \"%D\"",
candidate->get_subject(candidate)); candidate->get_subject(candidate));
} }
issuer = candidate; issuer = candidate;
@@ -81,7 +81,7 @@ static status_t verify(private_rsa_authenticator_t *this, chunk_t ike_sa_init,
* TODO: allow other hash algorithms and note it in "auth" */ * TODO: allow other hash algorithms and note it in "auth" */
if (public->verify(public, SIGN_RSA_EMSA_PKCS1_SHA1, octets, auth_data)) if (public->verify(public, SIGN_RSA_EMSA_PKCS1_SHA1, octets, auth_data))
{ {
DBG1(DBG_IKE, "authentication of %D with %N successful", DBG1(DBG_IKE, "authentication of '%D' with %N successful",
other_id, auth_method_names, AUTH_RSA); other_id, auth_method_names, AUTH_RSA);
status = SUCCESS; status = SUCCESS;
} }
@@ -89,7 +89,7 @@ static status_t verify(private_rsa_authenticator_t *this, chunk_t ike_sa_init,
} }
else else
{ {
DBG1(DBG_IKE, "no trusted public key found for %D", other_id); DBG1(DBG_IKE, "no trusted public key found for '%D'", other_id);
} }
chunk_free(&octets); chunk_free(&octets);
return status; return status;
@@ -109,7 +109,7 @@ static status_t build(private_rsa_authenticator_t *this, chunk_t ike_sa_init,
auth_info_t *auth; auth_info_t *auth;
my_id = this->ike_sa->get_my_id(this->ike_sa); my_id = this->ike_sa->get_my_id(this->ike_sa);
DBG1(DBG_IKE, "authentication of %D (myself) with %N", DBG1(DBG_IKE, "authentication of '%D' (myself) with %N",
my_id, auth_method_names, AUTH_RSA); my_id, auth_method_names, AUTH_RSA);
auth = this->ike_sa->get_my_auth(this->ike_sa); auth = this->ike_sa->get_my_auth(this->ike_sa);
@@ -117,7 +117,7 @@ static status_t build(private_rsa_authenticator_t *this, chunk_t ike_sa_init,
my_id, auth); my_id, auth);
if (private == NULL) if (private == NULL)
{ {
DBG1(DBG_IKE, "no RSA private key found for %D", my_id); DBG1(DBG_IKE, "no RSA private key found for '%D'", my_id);
return NOT_FOUND; return NOT_FOUND;
} }
prf = this->ike_sa->get_prf(this->ike_sa); prf = this->ike_sa->get_prf(this->ike_sa);
+21 -21
View File
@@ -187,7 +187,7 @@ static status_t process_auth(private_ike_auth_t *this, message_t *message)
if (auth == NULL) if (auth == NULL)
{ {
SIG(IKE_UP_FAILED, "authentication method %N used by %D not " SIG(IKE_UP_FAILED, "authentication method %N used by '%D' not "
"supported", auth_method_names, auth_method, "supported", auth_method_names, auth_method,
this->ike_sa->get_other_id(this->ike_sa)); this->ike_sa->get_other_id(this->ike_sa));
return NOT_SUPPORTED; return NOT_SUPPORTED;
@@ -228,7 +228,7 @@ static status_t process_id(private_ike_auth_t *this, message_t *message)
req = this->ike_sa->get_other_id(this->ike_sa); req = this->ike_sa->get_other_id(this->ike_sa);
if (!id->matches(id, req)) if (!id->matches(id, req))
{ {
SIG(IKE_UP_FAILED, "peer ID %D unacceptable, %D required", id, req); SIG(IKE_UP_FAILED, "peer ID '%D' unacceptable, '%D' required", id, req);
id->destroy(id); id->destroy(id);
return FAILED; return FAILED;
} }
@@ -316,12 +316,12 @@ static status_t build_auth_eap(private_ike_auth_t *this, message_t *message)
if (!this->initiator) if (!this->initiator)
{ {
this->ike_sa->set_state(this->ike_sa, IKE_ESTABLISHED); this->ike_sa->set_state(this->ike_sa, IKE_ESTABLISHED);
SIG(IKE_UP_SUCCESS, "IKE_SA '%s' established between %D[%H]...[%H]%D", SIG(IKE_UP_SUCCESS, "IKE_SA '%s' established between %H[%D]...[%D]%H",
this->ike_sa->get_name(this->ike_sa), this->ike_sa->get_name(this->ike_sa),
this->ike_sa->get_my_id(this->ike_sa),
this->ike_sa->get_my_host(this->ike_sa), this->ike_sa->get_my_host(this->ike_sa),
this->ike_sa->get_other_host(this->ike_sa), this->ike_sa->get_my_id(this->ike_sa),
this->ike_sa->get_other_id(this->ike_sa)); this->ike_sa->get_other_id(this->ike_sa),
this->ike_sa->get_other_host(this->ike_sa));
return SUCCESS; return SUCCESS;
} }
return NEED_MORE; return NEED_MORE;
@@ -362,12 +362,12 @@ static status_t process_auth_eap(private_ike_auth_t *this, message_t *message)
if (this->initiator) if (this->initiator)
{ {
this->ike_sa->set_state(this->ike_sa, IKE_ESTABLISHED); this->ike_sa->set_state(this->ike_sa, IKE_ESTABLISHED);
SIG(IKE_UP_SUCCESS, "IKE_SA '%s' established between %D[%H]...[%H]%D", SIG(IKE_UP_SUCCESS, "IKE_SA '%s' established between %H[%D]...[%D]%H",
this->ike_sa->get_name(this->ike_sa), this->ike_sa->get_name(this->ike_sa),
this->ike_sa->get_my_id(this->ike_sa),
this->ike_sa->get_my_host(this->ike_sa), this->ike_sa->get_my_host(this->ike_sa),
this->ike_sa->get_other_host(this->ike_sa), this->ike_sa->get_my_id(this->ike_sa),
this->ike_sa->get_other_id(this->ike_sa)); this->ike_sa->get_other_id(this->ike_sa),
this->ike_sa->get_other_host(this->ike_sa));
return SUCCESS; return SUCCESS;
} }
return NEED_MORE; return NEED_MORE;
@@ -399,7 +399,7 @@ static status_t process_eap_i(private_ike_auth_t *this, message_t *message)
return NEED_MORE; return NEED_MORE;
default: default:
this->eap_payload = NULL; this->eap_payload = NULL;
SIG(IKE_UP_FAILED, "failed to authenticate against %D using EAP", SIG(IKE_UP_FAILED, "failed to authenticate against '%D' using EAP",
this->ike_sa->get_other_id(this->ike_sa)); this->ike_sa->get_other_id(this->ike_sa));
return FAILED; return FAILED;
} }
@@ -562,7 +562,7 @@ static status_t build_r(private_ike_auth_t *this, message_t *message)
config = this->ike_sa->get_peer_cfg(this->ike_sa); config = this->ike_sa->get_peer_cfg(this->ike_sa);
if (config == NULL) if (config == NULL)
{ {
SIG(IKE_UP_FAILED, "no matching config found for %D...%D", SIG(IKE_UP_FAILED, "no matching config found for '%D'...'%D'",
this->ike_sa->get_my_id(this->ike_sa), this->ike_sa->get_my_id(this->ike_sa),
this->ike_sa->get_other_id(this->ike_sa)); this->ike_sa->get_other_id(this->ike_sa));
message->add_notify(message, TRUE, AUTHENTICATION_FAILED, chunk_empty); message->add_notify(message, TRUE, AUTHENTICATION_FAILED, chunk_empty);
@@ -580,12 +580,12 @@ static status_t build_r(private_ike_auth_t *this, message_t *message)
if (this->peer_authenticated) if (this->peer_authenticated)
{ {
this->ike_sa->set_state(this->ike_sa, IKE_ESTABLISHED); this->ike_sa->set_state(this->ike_sa, IKE_ESTABLISHED);
SIG(IKE_UP_SUCCESS, "IKE_SA '%s' established between %D[%H]...[%H]%D", SIG(IKE_UP_SUCCESS, "IKE_SA '%s' established between %H[%D]...[%D]%H",
this->ike_sa->get_name(this->ike_sa), this->ike_sa->get_name(this->ike_sa),
this->ike_sa->get_my_id(this->ike_sa),
this->ike_sa->get_my_host(this->ike_sa), this->ike_sa->get_my_host(this->ike_sa),
this->ike_sa->get_other_host(this->ike_sa), this->ike_sa->get_my_id(this->ike_sa),
this->ike_sa->get_other_id(this->ike_sa)); this->ike_sa->get_other_id(this->ike_sa),
this->ike_sa->get_other_host(this->ike_sa));
return SUCCESS; return SUCCESS;
} }
@@ -688,17 +688,17 @@ static status_t process_i(private_ike_auth_t *this, message_t *message)
auth = this->ike_sa->get_other_auth(this->ike_sa); auth = this->ike_sa->get_other_auth(this->ike_sa);
if (!auth->complies(auth, config->get_auth(config))) if (!auth->complies(auth, config->get_auth(config)))
{ {
SIG(IKE_UP_FAILED, "authorization of %D for config %s failed", SIG(IKE_UP_FAILED, "authorization of '%D' for config %s failed",
this->ike_sa->get_other_id(this->ike_sa), config->get_name(config)); this->ike_sa->get_other_id(this->ike_sa), config->get_name(config));
return FAILED; return FAILED;
} }
this->ike_sa->set_state(this->ike_sa, IKE_ESTABLISHED); this->ike_sa->set_state(this->ike_sa, IKE_ESTABLISHED);
SIG(IKE_UP_SUCCESS, "IKE_SA '%s' established between %D[%H]...[%H]%D", SIG(IKE_UP_SUCCESS, "IKE_SA '%s' established between %H[%D]...[%D]%H",
this->ike_sa->get_name(this->ike_sa), this->ike_sa->get_name(this->ike_sa),
this->ike_sa->get_my_id(this->ike_sa),
this->ike_sa->get_my_host(this->ike_sa), this->ike_sa->get_my_host(this->ike_sa),
this->ike_sa->get_other_host(this->ike_sa), this->ike_sa->get_my_id(this->ike_sa),
this->ike_sa->get_other_id(this->ike_sa)); this->ike_sa->get_other_id(this->ike_sa),
this->ike_sa->get_other_host(this->ike_sa));
return SUCCESS; return SUCCESS;
} }
+2 -2
View File
@@ -86,7 +86,7 @@ static void build_certs(private_ike_cert_post_t *this, message_t *message)
{ {
break; break;
} }
DBG1(DBG_IKE, "sending end entity cert %D", DBG1(DBG_IKE, "sending end entity cert \"%D\"",
cert->get_subject(cert)); cert->get_subject(cert));
message->add_payload(message, (payload_t*)payload); message->add_payload(message, (payload_t*)payload);
@@ -98,7 +98,7 @@ static void build_certs(private_ike_cert_post_t *this, message_t *message)
payload = cert_payload_create_from_cert(cert); payload = cert_payload_create_from_cert(cert);
if (payload) if (payload)
{ {
DBG1(DBG_IKE, "sending issuer cert %D", DBG1(DBG_IKE, "sending issuer cert \"%D\"",
cert->get_subject(cert)); cert->get_subject(cert));
message->add_payload(message, (payload_t*)payload); message->add_payload(message, (payload_t*)payload);
} }
+4 -4
View File
@@ -88,7 +88,7 @@ static void process_certreqs(private_ike_cert_pre_t *this, message_t *message)
CERT_X509, KEY_ANY, id, TRUE); CERT_X509, KEY_ANY, id, TRUE);
if (cert) if (cert)
{ {
DBG1(DBG_IKE, "received cert request for %D", DBG1(DBG_IKE, "received cert request for \"%D\"",
cert->get_subject(cert)); cert->get_subject(cert));
auth->add_item(auth, AUTHN_CA_CERT, cert); auth->add_item(auth, AUTHN_CA_CERT, cert);
cert->destroy(cert); cert->destroy(cert);
@@ -133,14 +133,14 @@ static void process_certs(private_ike_cert_pre_t *this, message_t *message)
if (first) if (first)
{ /* the first certificate MUST be an end entity one */ { /* the first certificate MUST be an end entity one */
DBG1(DBG_IKE, "received end entity cert %D", DBG1(DBG_IKE, "received end entity cert \"%D\"",
cert->get_subject(cert)); cert->get_subject(cert));
auth->add_item(auth, AUTHN_SUBJECT_CERT, cert); auth->add_item(auth, AUTHN_SUBJECT_CERT, cert);
first = FALSE; first = FALSE;
} }
else else
{ {
DBG1(DBG_IKE, "received issuer cert %D", DBG1(DBG_IKE, "received issuer cert \"%D\"",
cert->get_subject(cert)); cert->get_subject(cert));
auth->add_item(auth, AUTHN_IM_CERT, cert); auth->add_item(auth, AUTHN_IM_CERT, cert);
} }
@@ -184,7 +184,7 @@ static void add_certreq_payload(message_t *message, certreq_payload_t **reqp,
req = *reqp; req = *reqp;
keyid = public->get_id(public, ID_PUBKEY_INFO_SHA1); keyid = public->get_id(public, ID_PUBKEY_INFO_SHA1);
req->add_keyid(req, keyid->get_encoding(keyid)); req->add_keyid(req, keyid->get_encoding(keyid));
DBG1(DBG_IKE, "sending cert request for %D", DBG1(DBG_IKE, "sending cert request for \"%D\"",
cert->get_subject(cert)); cert->get_subject(cert));
break; break;
} }
@@ -502,19 +502,19 @@ static bool parse_basicOCSPResponse(private_x509_ocsp_response_t *this,
version = (object.len)? (1 + (u_int)*object.ptr) : 1; version = (object.len)? (1 + (u_int)*object.ptr) : 1;
if (version != OCSP_BASIC_RESPONSE_VERSION) if (version != OCSP_BASIC_RESPONSE_VERSION)
{ {
DBG1("OCSP ResponseData version %d not supported", version); DBG1(" ocsp ResponseData version %d not supported", version);
return FALSE; return FALSE;
} }
break; break;
case BASIC_RESPONSE_ID_BY_NAME: case BASIC_RESPONSE_ID_BY_NAME:
this->responderId = identification_create_from_encoding( this->responderId = identification_create_from_encoding(
ID_DER_ASN1_DN, object); ID_DER_ASN1_DN, object);
DBG3(" %D", this->responderId); DBG2(" '%D'", this->responderId);
break; break;
case BASIC_RESPONSE_ID_BY_KEY: case BASIC_RESPONSE_ID_BY_KEY:
this->responderId = identification_create_from_encoding( this->responderId = identification_create_from_encoding(
ID_PUBKEY_INFO_SHA1, object); ID_PUBKEY_INFO_SHA1, object);
DBG3(" %D", this->responderId); DBG2(" '%D'", this->responderId);
break; break;
case BASIC_RESPONSE_PRODUCED_AT: case BASIC_RESPONSE_PRODUCED_AT:
this->producedAt = asn1totime(&object, ASN1_GENERALIZEDTIME); this->producedAt = asn1totime(&object, ASN1_GENERALIZEDTIME);
@@ -527,7 +527,7 @@ static bool parse_basicOCSPResponse(private_x509_ocsp_response_t *this,
break; break;
case BASIC_RESPONSE_CRITICAL: case BASIC_RESPONSE_CRITICAL:
critical = object.len && *object.ptr; critical = object.len && *object.ptr;
DBG3(" %s", critical ? "TRUE" : "FALSE"); DBG2(" %s", critical ? "TRUE" : "FALSE");
break; break;
case BASIC_RESPONSE_EXT_VALUE: case BASIC_RESPONSE_EXT_VALUE:
if (extn_oid == OID_NONCE) if (extn_oid == OID_NONCE)
@@ -591,7 +591,7 @@ static bool parse_OCSPResponse(private_x509_ocsp_response_t *this)
case OCSP_SUCCESSFUL: case OCSP_SUCCESSFUL:
break; break;
default: default:
DBG1("OCSP response status: %N", DBG1(" ocsp response status: %N",
ocsp_status_names, status); ocsp_status_names, status);
return FALSE; return FALSE;
} }
@@ -605,7 +605,7 @@ static bool parse_OCSPResponse(private_x509_ocsp_response_t *this)
case OID_BASIC: case OID_BASIC:
return parse_basicOCSPResponse(this, object, level+1); return parse_basicOCSPResponse(this, object, level+1);
default: default:
DBG1("OCSP response type %#B not supported", &object); DBG1(" ocsp response type %#B not supported", &object);
return FALSE; return FALSE;
} }
break; break;
+1 -1
View File
@@ -934,7 +934,7 @@ static int print(FILE *stream, const struct printf_info *info,
snprintf(buf, sizeof(buf), "%.*s", this->encoded.len, this->encoded.ptr); snprintf(buf, sizeof(buf), "%.*s", this->encoded.len, this->encoded.ptr);
/* TODO: whats returned on failure?*/ /* TODO: whats returned on failure?*/
dntoa(this->encoded, &buf_chunk); dntoa(this->encoded, &buf_chunk);
return fprintf(stream, "\"%s\"", buf); return fprintf(stream, "%s", buf);
} }
case ID_DER_ASN1_GN: case ID_DER_ASN1_GN:
return fprintf(stream, "(ASN.1 general Name"); return fprintf(stream, "(ASN.1 general Name");