[shibboleth-sp2] 99/119: Logging improvements, especially around trust operations.

Ferenc Wágner wferi-guest at moszumanska.debian.org
Tue Jan 26 21:29:54 UTC 2016


This is an automated email from the git hooks/post-receive script.

wferi-guest pushed a commit to annotated tag 1.3.1
in repository shibboleth-sp2.

commit f32bf714cbf655dc98a81ec8479cec272f479828
Author: Scott Cantor <cantor.2 at osu.edu>
Date:   Tue Oct 30 16:47:09 2007 +0000

    Logging improvements, especially around trust operations.
---
 adfs/listener.cpp              |  4 ++--
 apache/mod_apache.cpp          |  7 +++----
 shib-target/MemoryListener.cpp |  1 -
 shib-target/ShibHTTPHook.cpp   |  6 +++++-
 shib-target/shib-ccache.cpp    | 20 ++++++++++++--------
 shib/BasicTrust.cpp            |  2 +-
 shib/ShibBrowserProfile.cpp    |  2 ++
 shib/ShibbolethTrust.cpp       | 13 +++++++------
 shibboleth.spec.in             |  1 -
 xmlproviders/XMLTrust.cpp      | 17 +++++++++--------
 10 files changed, 41 insertions(+), 32 deletions(-)

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<ShibHTTPHook::ShibHTTPHookCallContext*>(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<STConfig&>(ShibTargetConfig::getConfig());
         stc.getTransactionLog().infoStream() <<  "Successful attribute query for session (ID: " << m_id << ")";
         stc.releaseTransactionLog();
@@ -645,7 +645,7 @@ pair<SAMLResponse*,SAMLResponse*> 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<STConfig&>(ShibTargetConfig::getConfig());
@@ -731,8 +731,6 @@ pair<SAMLResponse*,SAMLResponse*> 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<SAMLResponse*,SAMLResponse*> 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<void*>& 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<void*>& 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<void*>& 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<void*>& 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<OpenSSLCryptoX509*>(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<OpenSSLCryptoX509*>(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<void*>& 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<void*>& 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<void*>& 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<void*>& 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<void*>& 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<void*>& 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) {

-- 
Alioth's /usr/local/bin/git-commit-notice on /srv/git.debian.org/git/pkg-shibboleth/shibboleth-sp2.git



More information about the Pkg-shibboleth-devel mailing list