[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