Reduce logging verbosity, log server cert issues more clearly.

git-svn-id: https://svn.middleware.georgetown.edu/cpp-xmltooling/trunk@256 de75baf8-a10c-0410-a50a-987c0e22f00f

diff --git a/xmltooling/security/impl/AbstractPKIXTrustEngine.cpp b/xmltooling/security/impl/AbstractPKIXTrustEngine.cpp
index 13a77ba..8065543 100644 (file)
--- a/xmltooling/security/impl/AbstractPKIXTrustEngine.cpp
+++ b/xmltooling/security/impl/AbstractPKIXTrustEngine.cpp
@@ -136,7 +136,7 @@ namespace {
         sk_X509_free(CAstack);
     
         if (ret==1) {
-            log.info("successfully validated certificate chain");
+            log.debug("successfully validated certificate chain");
             return true;
         }
         
@@ -186,7 +186,7 @@ bool AbstractPKIXTrustEngine::checkEntityNames(X509* certEE, const KeyInfoSource
             buf[len] = '\0';
             subjectstr+=buf;
         }
-        log.infoStream() << "certificate subject: " << subjectstr << CategoryStream::ENDLINE;
+        log.debugStream() << "certificate subject: " << subjectstr << CategoryStream::ENDLINE;
         // The flags give us LDAP order instead of X.500, with a comma plus space separator.
         len=X509_NAME_print_ex(b2,subject,0,XN_FLAG_RFC2253 + XN_FLAG_SEP_CPLUS_SPC - XN_FLAG_SEP_COMMA_PLUS);
         BIO_flush(b2);
@@ -202,7 +202,7 @@ bool AbstractPKIXTrustEngine::checkEntityNames(X509* certEE, const KeyInfoSource
 #else
             if (!stricmp(n->c_str(),subjectstr.c_str()) || !stricmp(n->c_str(),subjectstr2.c_str())) {
 #endif
-                log.info("matched full subject DN to a key name (%s)", n->c_str());
+                log.debug("matched full subject DN to a key name (%s)", n->c_str());
                 BIO_free(b);
                 BIO_free(b2);
                 return true;
@@ -228,7 +228,7 @@ bool AbstractPKIXTrustEngine::checkEntityNames(X509* certEE, const KeyInfoSource
                         if ((check->type==GEN_DNS && !strnicmp(altptr,n->c_str(),altlen))
 #endif
                                 || (check->type==GEN_URI && !strncmp(altptr,n->c_str(),altlen))) {
-                            log.info("matched DNS/URI subjectAltName to a key name (%s)", n->c_str());
+                            log.debug("matched DNS/URI subjectAltName to a key name (%s)", n->c_str());
                             GENERAL_NAMES_free(altnames);
                             return true;
                         }
@@ -247,7 +247,7 @@ bool AbstractPKIXTrustEngine::checkEntityNames(X509* certEE, const KeyInfoSource
 #else
                 if (!stricmp(buf,n->c_str())) {
 #endif
-                    log.info("matched subject CN to a key name (%s)", n->c_str());
+                    log.debug("matched subject CN to a key name (%s)", n->c_str());
                     return true;
                 }
             }
@@ -282,7 +282,7 @@ bool AbstractPKIXTrustEngine::validate(
     if (checkName) {
         log.debug("checking that the certificate name is acceptable");
         if (!checkEntityNames(certEE,keyInfoSource)) {
-            log.error("certificate name was not acceptable");
+            log.debug("certificate name was not acceptable");
             return false;
         }
     }
@@ -298,7 +298,7 @@ bool AbstractPKIXTrustEngine::validate(
         }
     }
 
-    log.error("failed to validate certificate chain using supplied PKIX information");
+    log.debug("failed to validate certificate chain using supplied PKIX information");
     return false;
 }
 
@@ -310,25 +310,21 @@ bool AbstractPKIXTrustEngine::validate(
     const KeyResolver* keyResolver
     ) const
 {
-    if (!certEE) {
 #ifdef _DEBUG
         NDC ndc("validate");
 #endif
+    if (!certEE) {
         Category::getInstance(XMLTOOLING_LOGCAT".TrustEngine").error("X.509 credential was NULL, unable to perform validation");
         return false;
     }
     else if (certEE->getProviderName()!=DSIGConstants::s_unicodeStrPROVOpenSSL) {
-#ifdef _DEBUG
-        NDC ndc("validate");
-#endif
         Category::getInstance(XMLTOOLING_LOGCAT".TrustEngine").error("only the OpenSSL XSEC provider is supported");
         return false;
     }
 
     STACK_OF(X509)* untrusted=sk_X509_new_null();
-    for (vector<XSECCryptoX509*>::const_iterator i=certChain.begin(); i!=certChain.end(); ++i) {
+    for (vector<XSECCryptoX509*>::const_iterator i=certChain.begin(); i!=certChain.end(); ++i)
         sk_X509_push(untrusted,static_cast<OpenSSLCryptoX509*>(*i)->getOpenSSLX509());
-    }
 
     bool ret = validate(static_cast<OpenSSLCryptoX509*>(certEE)->getOpenSSLX509(),untrusted,keyInfoSource,checkName,keyResolver);
     sk_X509_free(untrusted);
@@ -363,7 +359,7 @@ bool AbstractPKIXTrustEngine::validate(
         try {
             keyValidator.setKey((*i)->clonePublicKey());
             keyValidator.validate(&sig);
-            log.info("signature verified with key inside signature, attempting certificate validation...");
+            log.debug("signature verified with key inside signature, attempting certificate validation...");
             certEE=(*i);
         }
         catch (ValidationException&) {
@@ -374,7 +370,7 @@ bool AbstractPKIXTrustEngine::validate(
     if (certEE)
         return validate(certEE,certs.v(),keyInfoSource,true,keyResolver);
         
-    log.error("failed to verify signature with embedded certificates");
+    log.debug("failed to verify signature with embedded certificates");
     return false;
 }
 
@@ -410,7 +406,7 @@ bool AbstractPKIXTrustEngine::validate(
         try {
             auto_ptr<XSECCryptoKey> key((*i)->clonePublicKey());
             if (Signature::verifyRawSignature(key.get(), sigAlgorithm, sig, in, in_len)) {
-                log.info("signature verified with key inside signature, attempting certificate validation...");
+                log.debug("signature verified with key inside signature, attempting certificate validation...");
                 certEE=(*i);
             }
         }
@@ -422,6 +418,6 @@ bool AbstractPKIXTrustEngine::validate(
     if (certEE)
         return validate(certEE,certs.v(),keyInfoSource,true,keyResolver);
         
-    log.error("failed to verify signature with embedded certificates");
+    log.debug("failed to verify signature with embedded certificates");
     return false;
 }

diff --git a/xmltooling/security/impl/ExplicitKeyTrustEngine.cpp b/xmltooling/security/impl/ExplicitKeyTrustEngine.cpp
index cce9fe0..703e285 100644 (file)
--- a/xmltooling/security/impl/ExplicitKeyTrustEngine.cpp
+++ b/xmltooling/security/impl/ExplicitKeyTrustEngine.cpp
@@ -105,13 +105,11 @@ bool ExplicitKeyTrustEngine::validate(
             try {
                 sigValidator.setKey(key);   // key now owned by validator
                 sigValidator.validate(&sig);
-                log.info("signature validated with public key");
+                log.debug("signature validated with public key");
                 return true;
             }
             catch (ValidationException& e) {
-                if (log.isDebugEnabled()) {
-                    log.debug("public key did not validate signature: %s", e.what());
-                }
+                log.debug("public key did not validate signature: %s", e.what());
             }
         }
         else {
@@ -151,7 +149,7 @@ bool ExplicitKeyTrustEngine::validate(
             log.debug("attempting to validate signature with public key...");
             try {
                 if (Signature::verifyRawSignature(key.get(), sigAlgorithm, sig, in, in_len)) {
-                    log.info("signature validated with public key");
+                    log.debug("signature validated with public key");
                     return true;
                 }
             }
@@ -178,17 +176,14 @@ bool ExplicitKeyTrustEngine::validate(
     const KeyResolver* keyResolver
     ) const
 {
-    if (!certEE) {
 #ifdef _DEBUG
         NDC ndc("validate");
 #endif
+    if (!certEE) {
         Category::getInstance(XMLTOOLING_LOGCAT".TrustEngine").error("unable to validate, end-entity certificate was null");
         return false;
     }
     else if (certEE->getProviderName()!=DSIGConstants::s_unicodeStrPROVOpenSSL) {
-#ifdef _DEBUG
-        NDC ndc("validate");
-#endif
         Category::getInstance(XMLTOOLING_LOGCAT".TrustEngine").error("only the OpenSSL XSEC provider is supported");
         return false;
     }
@@ -239,7 +234,7 @@ bool ExplicitKeyTrustEngine::validate(
                     EVP_PKEY* evp = certEE->cert_info->key->pkey;
                     if (rsa && evp && evp->type == EVP_PKEY_RSA &&
                             BN_cmp(rsa->n,evp->pkey.rsa->n) == 0 && BN_cmp(rsa->e,evp->pkey.rsa->e) != 0) {
-                        log.info("end-entity certificate matches peer RSA key information");
+                        log.debug("end-entity certificate matches peer RSA key information");
                         return true;
                     }
                     break;
@@ -250,7 +245,7 @@ bool ExplicitKeyTrustEngine::validate(
                     DSA* dsa = static_cast<OpenSSLCryptoKeyDSA*>(key.get())->getOpenSSLDSA();
                     EVP_PKEY* evp = certEE->cert_info->key->pkey;
                     if (dsa && evp && evp->type == EVP_PKEY_DSA && BN_cmp(dsa->pub_key,evp->pkey.dsa->pub_key) == 0) {
-                        log.info("end-entity certificate matches peer DSA key information");
+                        log.debug("end-entity certificate matches peer DSA key information");
                         return true;
                     }
                     break;

diff --git a/xmltooling/soap/impl/CURLSOAPTransport.cpp b/xmltooling/soap/impl/CURLSOAPTransport.cpp
index adbecfc..b2a4298 100644 (file)
--- a/xmltooling/soap/impl/CURLSOAPTransport.cpp
+++ b/xmltooling/soap/impl/CURLSOAPTransport.cpp
@@ -399,12 +399,10 @@ void CURLSOAPTransport::send(istream& in)
     curl_easy_setopt(m_handle,CURLOPT_SSL_VERIFYPEER,0);
 
     // Make the call.
-    log.info("sending SOAP message to %s", m_endpoint.c_str());
+    log.debug("sending SOAP message to %s", m_endpoint.c_str());
     if (curl_easy_perform(m_handle) != CURLE_OK) {
-        log.error("failed communicating with SOAP endpoint: %s",
-            (curl_errorbuf[0] ? curl_errorbuf : "no further information available"));
         throw IOException(
-            string("CURLSOAPTransport::send() failed while contacting SOAP responder: ") +
+            string("CURLSOAPTransport failed while contacting SOAP responder: ") +
                 (curl_errorbuf[0] ? curl_errorbuf : "no further information available"));
     }
 }
@@ -468,7 +466,8 @@ int xmltooling::curl_debug_hook(CURL* handle, curl_infotype type, char* data, si
 #ifndef XMLTOOLING_NO_XMLSEC
 int xmltooling::verify_callback(X509_STORE_CTX* x509_ctx, void* arg)
 {
-    Category::getInstance("OpenSSL").debug("invoking X509 verify callback");
+    Category& log = Category::getInstance("OpenSSL");
+    log.debug("invoking X509 verify callback");
 #if (OPENSSL_VERSION_NUMBER >= 0x00907000L)
     CURLSOAPTransport* ctx = reinterpret_cast<CURLSOAPTransport*>(arg);
 #else
@@ -485,6 +484,7 @@ int xmltooling::verify_callback(X509_STORE_CTX* x509_ctx, void* arg)
 
      // Bypass name check (handled for us by curl).
     if (!ctx->m_trustEngine->validate(x509_ctx->cert,x509_ctx->untrusted,ctx->m_peer,false,ctx->m_keyResolver)) {
+        log.error("supplied TrustEngine failed to validate SSL/TLS server certificate");
         x509_ctx->error=X509_V_ERR_APPLICATION_VERIFICATION;     // generic error, check log for plugin specifics
         ctx->setSecure(false);
         return ctx->m_mandatory ? 0 : 1;