From: Scott Cantor Date: Tue, 30 Oct 2007 16:47:09 +0000 (+0000) Subject: Logging improvements, especially around trust operations. X-Git-Tag: 1.3.1~20 X-Git-Url: http://www.project-moonshot.org/gitweb/?a=commitdiff_plain;h=f32bf714cbf655dc98a81ec8479cec272f479828;hp=2489395116030d88905a01d239ab8a1c11e55250;p=shibboleth%2Fcpp-sp.git Logging improvements, especially around trust operations. --- diff --git a/adfs/listener.cpp b/adfs/listener.cpp index 9e10c04..890ac27 100644 --- a/adfs/listener.cpp +++ b/adfs/listener.cpp @@ -210,9 +210,10 @@ void ADFSListener::sessionNew( log->debug("passing signed ADFS assertion to trust layer"); Trust t(app->getTrustProviders()); if (!t.validate(*assertion,role)) { - log->error("unable to verify signed authentication assertion"); + log->error("unable to verify signed ADFS assertion"); throw TrustException("unable to verify signed authentication assertion"); } + log->info("verified digital signature over ADFS assertion"); // Now dummy up the SAML profile response wrapper. param=parser.get_value("wctx"); @@ -351,7 +352,6 @@ void ADFSListener::sessionNew( } // It passes all our tests -- create a new session. - log->info("creating new session"); // Are attributes present? bool attributesPushed=false; diff --git a/apache/mod_apache.cpp b/apache/mod_apache.cpp index 72546ff..1887cf2 100644 --- a/apache/mod_apache.cpp +++ b/apache/mod_apache.cpp @@ -214,7 +214,7 @@ static shib_request_config *init_request_config(request_rec *r) shib_request_config* rc=(shib_request_config*)ap_pcalloc(r->pool,sizeof(shib_request_config)); ap_set_module_config (r->request_config, &mod_shib, rc); memset(rc, 0, sizeof(shib_request_config)); - ap_log_rerror(APLOG_MARK,APLOG_DEBUG|APLOG_NOERRNO,SH_AP_R(r), "shib_init_rc\n"); + //ap_log_rerror(APLOG_MARK,APLOG_DEBUG|APLOG_NOERRNO,SH_AP_R(r), "shib_init_rc\n"); return rc; } @@ -1014,8 +1014,7 @@ bool htAccessControl::authorized( static int shib_post_read(request_rec *r) { shib_request_config* rc = init_request_config(r); - - ap_log_rerror(APLOG_MARK,APLOG_DEBUG|APLOG_NOERRNO,SH_AP_R(r), "shib_post_read"); + //ap_log_rerror(APLOG_MARK,APLOG_DEBUG|APLOG_NOERRNO,SH_AP_R(r), "shib_post_read"); #ifdef SHIB_DEFERRED_HEADERS rc->hdr_out = ap_make_table(r->pool, 5); @@ -1032,7 +1031,7 @@ extern "C" int shib_fixups(request_rec* r) if (dc->bOff==1 || dc->bUseEnvVars!=1) return DECLINED; - ap_log_rerror(APLOG_MARK,APLOG_DEBUG|APLOG_NOERRNO,SH_AP_R(r), "shib_fixup(%d): ENTER", (int)getpid()); + //ap_log_rerror(APLOG_MARK,APLOG_DEBUG|APLOG_NOERRNO,SH_AP_R(r), "shib_fixup(%d): ENTER", (int)getpid()); if (rc==NULL || rc->env==NULL || ap_is_empty_table(rc->env)) return DECLINED; diff --git a/shib-target/MemoryListener.cpp b/shib-target/MemoryListener.cpp index cd2fe2e..79b8129 100644 --- a/shib-target/MemoryListener.cpp +++ b/shib-target/MemoryListener.cpp @@ -219,7 +219,6 @@ void MemoryListener::sessionNew( #endif // It passes all our tests -- create a new session. - log->info("creating new session"); // Are attributes present? bool attributesPushed=false; diff --git a/shib-target/ShibHTTPHook.cpp b/shib-target/ShibHTTPHook.cpp index f9843c4..510b8be 100644 --- a/shib-target/ShibHTTPHook.cpp +++ b/shib-target/ShibHTTPHook.cpp @@ -40,7 +40,9 @@ using namespace std; */ static int verify_callback(X509_STORE_CTX* x509_ctx, void* arg) { - Category::getInstance("OpenSSL").debug("invoking default X509 verify callback"); + Category& log = Category::getInstance("OpenSSL"); + log.debug("invoking default X509 verify callback"); + #if (OPENSSL_VERSION_NUMBER >= 0x00907000L) ShibHTTPHook::ShibHTTPHookCallContext* ctx = reinterpret_cast(arg); #else @@ -66,6 +68,8 @@ static int verify_callback(X509_STORE_CTX* x509_ctx, void* arg) return 0; } + log.info("verified server's TLS key/certificate"); + // Signal success. Hopefully it doesn't matter what's actually in the structure now. return 1; } diff --git a/shib-target/shib-ccache.cpp b/shib-target/shib-ccache.cpp index c328579..af3ea0e 100644 --- a/shib-target/shib-ccache.cpp +++ b/shib-target/shib-ccache.cpp @@ -611,7 +611,7 @@ void InternalCCacheEntry::populate() m_response_post=new_responses.second; m_responseCreated=time(NULL); m_lastRetry=0; - m_cache->log->debug("fetched and stored new response"); + m_cache->log->info("stored new attribute response"); STConfig& stc=static_cast(ShibTargetConfig::getConfig()); stc.getTransactionLog().infoStream() << "Successful attribute query for session (ID: " << m_id << ")"; stc.releaseTransactionLog(); @@ -645,7 +645,7 @@ pair InternalCCacheEntry::getNewResponse() m_cache->log->debug("retry interval exceeded, so trying again"); m_lastRetry=now; - m_cache->log->info("trying to get new attributes for session (ID=%s)", m_id.c_str()); + m_cache->log->debug("trying to get new attributes for session (ID=%s)", m_id.c_str()); // Transaction Logging STConfig& stc=static_cast(ShibTargetConfig::getConfig()); @@ -731,8 +731,6 @@ pair InternalCCacheEntry::getNewResponse() m_cache->log->error("unable to sign SAML 1.0 attribute query, only SAML 1.1 defines signing adequately"); } - m_cache->log->debug("trying to query an AA..."); - // Call context object Trust t(application->getTrustProviders()); ShibHTTPHook::ShibHTTPHookCallContext ctx(credUse,AA); @@ -754,6 +752,7 @@ pair InternalCCacheEntry::getNewResponse() if (r->isSigned()) { if (!t.validate(*r,AA)) throw TrustException("Unable to verify signed response message."); + m_cache->log->info("verified digital signature over attribute response"); } else if (!ctx.isAuthenticated() || XMLString::compareNString(ep->getLocation(),https,6)) throw TrustException("Response message was unauthenticated."); @@ -826,10 +825,15 @@ SAMLResponse* InternalCCacheEntry::filter(SAMLResponse* r, const IApplication* a continue; // Check token signature. - if (assertions[i]->isSigned() && !t.validate(*(assertions[i]),source)) { - m_cache->log->warn("signed assertion failed to validate, removing it"); - r->removeAssertion(i); - continue; + if (assertions[i]->isSigned()) { + if (t.validate(*(assertions[i]),source)) { + m_cache->log->info("verified digital signature over attribute assertion"); + } + else { + m_cache->log->warn("signed assertion failed to validate, removing it"); + r->removeAssertion(i); + continue; + } } i++; } diff --git a/shib/BasicTrust.cpp b/shib/BasicTrust.cpp index c588a42..195d002 100644 --- a/shib/BasicTrust.cpp +++ b/shib/BasicTrust.cpp @@ -202,7 +202,7 @@ bool BasicTrust::validate(const saml::SAMLSignedObject& token, const IRoleDescri log.debug("KeyDescriptor resolved into a key, trying it..."); try { token.verify(key); - log.info("signature verified with KeyDescriptor"); + log.debug("signature verified with KeyDescriptor"); return true; } catch (SAMLException& e) { diff --git a/shib/ShibBrowserProfile.cpp b/shib/ShibBrowserProfile.cpp index 3086310..10f8467 100644 --- a/shib/ShibBrowserProfile.cpp +++ b/shib/ShibBrowserProfile.cpp @@ -130,6 +130,7 @@ SAMLBrowserProfile::BrowserProfileResponse ShibBrowserProfile::receive( TrustException ex("unable to verify signed profile response"); annotateException(&ex,role); // throws it } + log.info("verified digital signature over SSO response"); } // SSO assertion signed? if (bpr.assertion->isSigned()) { @@ -140,6 +141,7 @@ SAMLBrowserProfile::BrowserProfileResponse ShibBrowserProfile::receive( TrustException ex("unable to verify signed authentication assertion"); annotateException(&ex,role); // throws it } + log.info("verified digital signature over SSO assertion"); } // Finally, discard any assertions not issued by the same entity that issued the authn. diff --git a/shib/ShibbolethTrust.cpp b/shib/ShibbolethTrust.cpp index c6bb916..3cd839d 100644 --- a/shib/ShibbolethTrust.cpp +++ b/shib/ShibbolethTrust.cpp @@ -245,7 +245,7 @@ bool ShibbolethTrust::validate(X509* EE, STACK_OF(X509)* untrusted, const IKeyAu sk_X509_free(CAstack); if (ret==1) { - log.info("successfully validated certificate chain"); + log.debug("successfully validated certificate chain"); return true; } @@ -312,7 +312,8 @@ bool ShibbolethTrust::validate(void* certEE, const Iterator& certChain, c buf[len] = '\0'; subjectstr+=buf; } - log.infoStream() << "certificate subject: " << subjectstr << logging::eol; + if (log.isDebugEnabled()) + log.debugStream() << "certificate subject: " << subjectstr << logging::eol; // 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); @@ -328,7 +329,7 @@ bool ShibbolethTrust::validate(void* certEE, const Iterator& certChain, c #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()); checkName=false; break; } @@ -354,7 +355,7 @@ bool ShibbolethTrust::validate(void* certEE, const Iterator& certChain, c 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()); checkName=false; break; } @@ -374,7 +375,7 @@ bool ShibbolethTrust::validate(void* certEE, const Iterator& certChain, c #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()); checkName=false; break; } @@ -515,7 +516,7 @@ bool ShibbolethTrust::validate(const saml::SAMLSignedObject& token, const IRoleD chain.push_back(static_cast(c)->getOpenSSLX509()); if (!certEE) { token.verify(*c); - log.info("signature verified with key inside signature, attempting certificate validation..."); + log.debug("signature verified with key inside signature, attempting certificate validation..."); certEE=static_cast(c)->getOpenSSLX509(); } } diff --git a/shibboleth.spec.in b/shibboleth.spec.in index 7309b39..ff9e7f6 100644 --- a/shibboleth.spec.in +++ b/shibboleth.spec.in @@ -58,7 +58,6 @@ applications that use the shibboleth library. %install [ "$RPM_BUILD_ROOT" != "/" ] && %{__rm} -rf $RPM_BUILD_ROOT - %{__make} install DESTDIR=$RPM_BUILD_ROOT %if "%{_vendor}" == "suse" diff --git a/xmlproviders/XMLTrust.cpp b/xmlproviders/XMLTrust.cpp index 6e6a04e..5642ea3 100644 --- a/xmlproviders/XMLTrust.cpp +++ b/xmlproviders/XMLTrust.cpp @@ -470,7 +470,8 @@ bool XMLTrust::validate(void* certEE, const Iterator& certChain, const IR buf[len] = '\0'; subjectstr+=buf; } - log.infoStream() << "certificate subject: " << subjectstr << xmlproviders::logging::eol; + if (log.isDebugEnabled()) + log.debugStream() << "certificate subject: " << subjectstr << xmlproviders::logging::eol; // 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); @@ -486,7 +487,7 @@ bool XMLTrust::validate(void* certEE, const Iterator& certChain, const IR #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()); checkName=false; break; } @@ -511,7 +512,7 @@ bool XMLTrust::validate(void* certEE, const Iterator& certChain, const IR #else if (!strnicmp(altptr,n->c_str(),altlen)) { #endif - 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()); checkName=false; break; } @@ -531,7 +532,7 @@ bool XMLTrust::validate(void* certEE, const Iterator& certChain, const IR #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()); checkName=false; break; } @@ -597,7 +598,7 @@ bool XMLTrust::validate(void* certEE, const Iterator& certChain, const IR kauth=*keyauths; if (log.isInfoEnabled()) { auto_ptr_char temp(*name); - log.info("KeyAuthority match on %s",temp.get()); + log.debug("KeyAuthority match on %s",temp.get()); } } } @@ -665,7 +666,7 @@ bool XMLTrust::validate(void* certEE, const Iterator& certChain, const IR X509_STORE_free(store); if (ret==1) { - log.info("successfully validated certificate chain"); + log.debug("successfully validated certificate chain"); unlock(); return true; } @@ -741,7 +742,7 @@ bool XMLTrust::validate(const saml::SAMLSignedObject& token, const IRoleDescript KIL=*keybinds; if (log.isInfoEnabled()) { auto_ptr_char temp(*name); - log.info("KeyInfo match on %s",temp.get()); + log.debug("KeyInfo match on %s",temp.get()); } } } @@ -759,7 +760,7 @@ bool XMLTrust::validate(const saml::SAMLSignedObject& token, const IRoleDescript try { token.verify(key); unlock(); - log.info("token verified with KeyInfo, nothing more to verify"); + log.debug("token verified with KeyInfo, nothing more to verify"); return true; } catch (SAMLException& e) {