Decrease log level of message - SIDP-318
authorlajoie <lajoie@ab3bd59b-922f-494d-bb5f-6f0a3c29deca>
Tue, 30 Jun 2009 09:17:26 +0000 (09:17 +0000)
committerlajoie <lajoie@ab3bd59b-922f-494d-bb5f-6f0a3c29deca>
Tue, 30 Jun 2009 09:17:26 +0000 (09:17 +0000)
Clean up some profile handling code and log messages
Make install script executable

git-svn-id: https://subversion.switch.ch/svn/shibboleth/java-idp/branches/REL_2@2850 ab3bd59b-922f-494d-bb5f-6f0a3c29deca

17 files changed:
doc/RELEASE-NOTES.txt
src/main/assembly/bin.xml
src/main/java/edu/internet2/middleware/shibboleth/idp/authn/AuthenticationEngine.java
src/main/java/edu/internet2/middleware/shibboleth/idp/authn/Saml2LoginContext.java
src/main/java/edu/internet2/middleware/shibboleth/idp/authn/provider/IPAddressLoginHandler.java
src/main/java/edu/internet2/middleware/shibboleth/idp/authn/provider/PreviousSessionLoginHandler.java
src/main/java/edu/internet2/middleware/shibboleth/idp/profile/AbstractSAMLProfileHandler.java
src/main/java/edu/internet2/middleware/shibboleth/idp/profile/saml1/AbstractSAML1ProfileHandler.java
src/main/java/edu/internet2/middleware/shibboleth/idp/profile/saml1/ArtifactResolution.java
src/main/java/edu/internet2/middleware/shibboleth/idp/profile/saml1/AttributeQueryProfileHandler.java
src/main/java/edu/internet2/middleware/shibboleth/idp/profile/saml1/ShibbolethSSODecoder.java
src/main/java/edu/internet2/middleware/shibboleth/idp/profile/saml1/ShibbolethSSOEndpointSelector.java
src/main/java/edu/internet2/middleware/shibboleth/idp/profile/saml1/ShibbolethSSOProfileHandler.java
src/main/java/edu/internet2/middleware/shibboleth/idp/profile/saml2/AbstractSAML2ProfileHandler.java
src/main/java/edu/internet2/middleware/shibboleth/idp/profile/saml2/ArtifactResolution.java
src/main/java/edu/internet2/middleware/shibboleth/idp/profile/saml2/AttributeQueryProfileHandler.java
src/main/java/edu/internet2/middleware/shibboleth/idp/profile/saml2/SSOProfileHandler.java

index 2dd2aa5..33bfc7f 100644 (file)
@@ -5,11 +5,11 @@ Changes in Release 2.1.3
 [SIDP-276] - Example RDB Connector, quote principal
 [SIDP-277] - Incorrect null check for request context in UsernamePasswordServlet
 [SIDP-279] - IdP should log NameID for auditing
-[SIDP-280] - when an Idp has no outside (WAN) access Idp fails to collect or release attributes
 [SIDP-285] - Use $IDP_SCOPE$ to populate IdP scope in conf-tmpl\attribute-resolver.xml
 [SIDP-291] - Update libs for 2.1.3 release
 [SIDP-306] - Remove ClientCertAuth rule from SAML 2 SSO SecurityPolicy in relying-party.xml
 [SIDP-310] - Change default relying-party.xml settings for SAML 2 profiles' encryptNameIds parameter from "conditional" to "never"
+[SIDP-318] - IdP erroneously logs many normal events as errors
 
 Changes in Release 2.1.2
 =============================================
index e03c051..9dadba5 100644 (file)
@@ -46,6 +46,8 @@
             <includes>
                 <include>*.sh</include>
             </includes>
+            <fileMode>0755</fileMode>
+            <directoryMode>0755</directoryMode>
         </fileSet>
         <fileSet>
             <directory>src/installer/bat</directory>
index 7ba1c30..33b1b0b 100644 (file)
@@ -207,7 +207,7 @@ public class AuthenticationEngine extends HttpServlet {
         LOG.debug("Returning control to authentication engine");
         LoginContext loginContext = retrieveLoginContext(httpRequest, false);
         if (loginContext == null) {
-            LOG.error("No login context available, unable to return to authentication engine");
+            LOG.warn("No login context available, unable to return to authentication engine");
             forwardRequest("/idp-error.jsp", httpRequest, httpResponse);
         } else {
             forwardRequest(loginContext.getAuthenticationEngineURL(), httpRequest, httpResponse);
@@ -391,7 +391,7 @@ public class AuthenticationEngine extends HttpServlet {
         }
 
         if (supportedLoginHandlers.isEmpty()) {
-            LOG.error("No authentication method, requested by the service provider, is supported");
+            LOG.warn("No authentication method, requested by the service provider, is supported");
             throw new AuthenticationException(
                     "No authentication method, requested by the service provider, is supported");
         }
@@ -472,7 +472,7 @@ public class AuthenticationEngine extends HttpServlet {
                 loginHandlers);
 
         if (loginHandlers.isEmpty()) {
-            LOG.error("Passive authentication required but no login handlers available to support it");
+            LOG.warn("Passive authentication required but no login handlers available to support it");
             throw new PassiveAuthenticationException();
         }
     }
index 7919922..f8d3811 100644 (file)
@@ -134,7 +134,7 @@ public class Saml2LoginContext extends LoginContext implements Serializable {
         AuthnContextComparisonTypeEnumeration comparator = authnContext.getComparison();
         if (comparator != null && comparator != AuthnContextComparisonTypeEnumeration.EXACT) {
             Logger log = LoggerFactory.getLogger(Saml2LoginContext.class);
-            log.error("Unsupported comparision operator ( " + comparator
+            log.warn("Unsupported comparision operator ( " + comparator
                     + ") in RequestedAuthnContext. Only exact comparisions are supported.");
             return requestedMethods;
         }
index 21465ce..5936a6e 100644 (file)
@@ -80,7 +80,7 @@ public class IPAddressLoginHandler extends AbstractLoginHandler {
                 ipList.add(new edu.internet2.middleware.shibboleth.idp.authn.provider.IPAddressLoginHandler.IPEntry(
                         addr));
             } catch (UnknownHostException ex) {
-                log.error("IPAddressHandler: Error parsing IP entry \"" + addr + "\". Ignoring.");
+                log.warn("IPAddressHandler: Error parsing IP entry \"" + addr + "\". Ignoring.");
             }
         }
     }
@@ -229,13 +229,13 @@ public class IPAddressLoginHandler extends AbstractLoginHandler {
 
             int cidrOffset = entry.indexOf("/");
             if (cidrOffset == -1) {
-                log.error("Invalid entry \"" + entry + "\" -- it lacks a netmask component.");
+                log.warn("Invalid entry \"" + entry + "\" -- it lacks a netmask component.");
                 throw new UnknownHostException("entry lacks a netmask component.");
             }
 
             // ensure that only one "/" is present.
             if (entry.indexOf("/", cidrOffset + 1) != -1) {
-                log.error("Invalid entry \"" + entry + "\" -- too many \"/\" present.");
+                log.warn("Invalid entry \"" + entry + "\" -- too many \"/\" present.");
                 throw new UnknownHostException("entry has too many netmask components.");
             }
 
index 6888a61..c2fa8ec 100644 (file)
@@ -105,7 +105,7 @@ public class PreviousSessionLoginHandler extends AbstractLoginHandler {
         
         Session idpSession = (Session) httpRequest.getAttribute(Session.HTTP_SESSION_BINDING_ATTRIBUTE);
         if(idpSession == null){
-            log.error("No existing IdP session available.");
+            log.warn("No existing IdP session available.");
             httpRequest.setAttribute(LoginHandler.AUTHENTICATION_ERROR_KEY, "No existing IdP session available");
         }else{
             log.debug("Using existing IdP session for {}", idpSession.getPrincipalName());
index 7063493..76078d9 100644 (file)
@@ -499,7 +499,7 @@ public abstract class AbstractSAMLProfileHandler extends
 
             Endpoint endpoint = requestContext.getPeerEntityEndpoint();
             if (endpoint == null) {
-                log.error("No peer endpoint available for peer. Unable to send response.");
+                log.warn("No peer endpoint available for peer. Unable to send response.");
                 throw new ProfileException("No peer endpoint available for peer. Unable to send response.");
             }
 
index 73322a7..d3fed40 100644 (file)
@@ -1,5 +1,5 @@
 /*
- * Copyright [2007] [University Corporation for Advanced Internet Development, Inc.]
+ * Copyright 2007 University Corporation for Advanced Internet Development, Inc.
  *
  * Licensed under the Apache License, Version 2.0 (the "License");
  * you may not use this file except in compliance with the License.
@@ -60,6 +60,7 @@ import org.opensaml.xml.signature.SignatureException;
 import org.opensaml.xml.signature.Signer;
 import org.slf4j.Logger;
 import org.slf4j.LoggerFactory;
+import org.slf4j.helpers.MessageFormatter;
 
 import edu.internet2.middleware.shibboleth.common.attribute.AttributeRequestException;
 import edu.internet2.middleware.shibboleth.common.attribute.BaseAttribute;
@@ -360,47 +361,66 @@ public abstract class AbstractSAML1ProfileHandler extends AbstractSAMLProfileHan
      */
     protected NameIdentifier buildNameId(BaseSAML1ProfileRequestContext<?, ?, ?> requestContext)
             throws ProfileException {
-        log.debug("Building assertion NameIdentifier to relying party {} for principal {}", requestContext
-                .getInboundMessageIssuer(), requestContext.getPrincipalName());
+        log.debug("Attemping to build NameIdentifier for principal '{}' in response to request from relying party '{}",
+                requestContext.getPrincipalName(), requestContext.getInboundMessageIssuer());
 
         List<String> supportedNameFormats = getNameFormats(requestContext);
         if (!supportedNameFormats.isEmpty()) {
-            log.debug("SP-supported name formats: {}", supportedNameFormats);
+            log.debug("Relying party '{}' supports the name formats: {}", requestContext.getInboundMessageIssuer(),
+                    supportedNameFormats);
         } else {
-            log.debug("SP indicated no preferred name formats.");
+            log.debug("Relying party '{}' indicated no preferred name formats", requestContext
+                    .getInboundMessageIssuer());
         }
 
         Map<String, BaseAttribute> principalAttributes = requestContext.getAttributes();
         if (principalAttributes == null || principalAttributes.isEmpty()) {
-            log.debug("No attributes for principal {}, no name identifier will be created.", requestContext
-                    .getPrincipalName());
+            log.debug("No attributes for principal '{}', no NameIdentifier will be created for relying party '{}'",
+                    requestContext.getPrincipalName(), requestContext.getInboundMessageIssuer());
             return null;
         }
 
-        SAML1NameIdentifierEncoder nameIdEncoder;
-        try {
-            for (BaseAttribute<?> attribute : principalAttributes.values()) {
-                for (AttributeEncoder encoder : attribute.getEncoders()) {
-                    if (encoder instanceof SAML1NameIdentifierEncoder) {
-                        nameIdEncoder = (SAML1NameIdentifierEncoder) encoder;
-                        if (supportedNameFormats.isEmpty()
-                                || supportedNameFormats.contains(nameIdEncoder.getNameFormat())) {
-                            log.debug("Using attribute {} supporting name format {} to create the NameIdentifier",
-                                    attribute.getId(), nameIdEncoder.getNameFormat());
-                            return nameIdEncoder.encode(attribute);
-                        }
+        BaseAttribute<?> nameIdAttribute = null;
+        SAML1NameIdentifierEncoder nameIdEncoder = null;
+        for (BaseAttribute<?> attribute : principalAttributes.values()) {
+            if (attribute == null) {
+                continue;
+            }
+            for (AttributeEncoder encoder : attribute.getEncoders()) {
+                if (encoder == null) {
+                    continue;
+                }
+                if (encoder instanceof SAML1NameIdentifierEncoder) {
+                    nameIdEncoder = (SAML1NameIdentifierEncoder) encoder;
+                    if (supportedNameFormats.isEmpty() || supportedNameFormats.contains(nameIdEncoder.getNameFormat())) {
+                        nameIdAttribute = attribute;
+                        break;
                     }
                 }
             }
+        }
 
-            log.debug("No attributes for principal {} support an encoding into a supported name ID format.",
-                    requestContext.getPrincipalName());
+        if (nameIdAttribute == null || nameIdEncoder == null) {
+            log
+                    .debug(
+                            "No attributes for principal '{}' supports encoding into a supported NameIdentifier format for relying party '{}'",
+                            requestContext.getPrincipalName(), requestContext.getInboundMessageIssuer());
             return null;
+        }
+
+        try {
+            log
+                    .debug(
+                            "Using attribute '{}' supporting name format '{}' to create the NameIdentifier for relying party '{}'",
+                            new Object[] { nameIdAttribute.getId(), nameIdEncoder.getNameFormat(),
+                                    requestContext.getInboundMessageIssuer() });
+            return nameIdEncoder.encode(nameIdAttribute);
         } catch (AttributeEncodingException e) {
-            log.error("Unable to construct NameIdentifier", e);
-            requestContext.setFailureStatus(buildStatus(StatusCode.RESPONDER, null,
-                    "Unable to construct NameIdentifier"));
-            throw new ProfileException("Unable to encode NameIdentifier attribute", e);
+            requestContext.setFailureStatus(buildStatus(StatusCode.RESPONDER, null, "Unable to encode NameIdentifier"));
+            String msg = MessageFormatter.format("Unable to encode NameIdentifier for relying party '{}'",
+                    requestContext.getInboundMessageIssuer());
+            log.error(msg, e);
+            throw new ProfileException(msg, e);
         }
     }
 
@@ -482,17 +502,18 @@ public abstract class AbstractSAML1ProfileHandler extends AbstractSAMLProfileHan
         SAML1AttributeAuthority attributeAuthority = profileConfiguration.getAttributeAuthority();
 
         try {
-            log.debug("Resolving attributes for principal {} of SAML request from relying party {}", requestContext
-                    .getPrincipalName(), requestContext.getInboundMessageIssuer());
+            log.debug("Resolving attributes for principal '{}' for SAML request from relying party '{}'",
+                    requestContext.getPrincipalName(), requestContext.getInboundMessageIssuer());
             Map<String, BaseAttribute> principalAttributes = attributeAuthority.getAttributes(requestContext);
 
             requestContext.setAttributes(principalAttributes);
         } catch (AttributeRequestException e) {
-            log.error("Error resolving attributes for SAML request from relying party "
-                    + requestContext.getInboundMessageIssuer(), e);
             requestContext.setFailureStatus(buildStatus(StatusCode.RESPONDER, null, "Error resolving attributes"));
-            throw new ProfileException("Error resolving attributes for SAML request from relying party "
-                    + requestContext.getInboundMessageIssuer(), e);
+            String msg = MessageFormatter.format(
+                    "Error resolving attributes for principal '{}' for SAML request from relying party '{}'",
+                    requestContext.getPrincipalName(), requestContext.getInboundMessageIssuer());
+            log.error(msg, e);
+            throw new ProfileException(msg, e);
         }
     }
 
@@ -509,8 +530,9 @@ public abstract class AbstractSAML1ProfileHandler extends AbstractSAMLProfileHan
     protected AttributeStatement buildAttributeStatement(BaseSAML1ProfileRequestContext<?, ?, ?> requestContext,
             String subjectConfMethod) throws ProfileException {
 
-        log.debug("Creating attribute statement in response to SAML request from relying party {}", requestContext
-                .getInboundMessageIssuer());
+        log.debug(
+                "Creating attribute statement about principal '{}'in response to SAML request from relying party '{}'",
+                requestContext.getPrincipalName(), requestContext.getInboundMessageIssuer());
         AbstractSAML1ProfileConfiguration profileConfiguration = requestContext.getProfileConfiguration();
         SAML1AttributeAuthority attributeAuthority = profileConfiguration.getAttributeAuthority();
 
@@ -530,10 +552,11 @@ public abstract class AbstractSAML1ProfileHandler extends AbstractSAMLProfileHan
 
             return statment;
         } catch (AttributeRequestException e) {
-            log.error("Error encoding attributes for principal " + requestContext.getPrincipalName(), e);
             requestContext.setFailureStatus(buildStatus(StatusCode.RESPONDER, null, "Error resolving attributes"));
-            throw new ProfileException("Error encoding attributes for principal " + requestContext.getPrincipalName(),
-                    e);
+            String msg = MessageFormatter.format("Error encoding attributes for principal '{}'", requestContext
+                    .getPrincipalName());
+            log.error(msg, e);
+            throw new ProfileException(msg, e);
         }
     }
 
@@ -548,19 +571,20 @@ public abstract class AbstractSAML1ProfileHandler extends AbstractSAMLProfileHan
         AbstractSAML1ProfileConfiguration profileConfiguration = requestContext.getProfileConfiguration();
         SAML1AttributeAuthority attributeAuthority = profileConfiguration.getAttributeAuthority();
 
-        log.debug("Resolving principal name for subject of SAML request from relying party {}", requestContext
+        log.debug("Resolving principal name for subject of SAML request from relying party '{}'", requestContext
                 .getInboundMessageIssuer());
 
         try {
             String principal = attributeAuthority.getPrincipal(requestContext);
             requestContext.setPrincipalName(principal);
         } catch (AttributeRequestException e) {
-            log.error("Error resolving attributes for SAML request from relying party "
-                    + requestContext.getInboundMessageIssuer(), e);
             requestContext.setFailureStatus(buildStatus(StatusCode.RESPONDER, StatusCode.REQUEST_DENIED,
                     "Error resolving principal"));
-            throw new ProfileException("Error resolving attributes for SAML request from relying party "
-                    + requestContext.getInboundMessageIssuer(), e);
+            String msg = MessageFormatter.format(
+                    "Error resolving principal name for SAML request from relying party '{}'", requestContext
+                            .getInboundMessageIssuer());
+            log.warn(msg, e);
+            throw new ProfileException(msg, e);
         }
     }
 
@@ -576,7 +600,7 @@ public abstract class AbstractSAML1ProfileHandler extends AbstractSAMLProfileHan
      */
     protected void signAssertion(BaseSAML1ProfileRequestContext<?, ?, ?> requestContext, Assertion assertion)
             throws ProfileException {
-        log.debug("Determining if SAML assertion to relying party {} should be signed", requestContext
+        log.debug("Determining if SAML assertion to relying party '{}' should be signed", requestContext
                 .getInboundMessageIssuer());
 
         boolean signAssertion = false;
@@ -590,19 +614,22 @@ public abstract class AbstractSAML1ProfileHandler extends AbstractSAMLProfileHan
                     || (profileConfig.getSignAssertions() == CryptoOperationRequirementLevel.conditional && !encoder
                             .providesMessageIntegrity(requestContext))) {
                 signAssertion = true;
-                log.debug("IdP relying party configuration {} indicates to sign assertions: {}", requestContext
+                log.debug("IdP relying party configuration '{}' indicates to sign assertions: {}", requestContext
                         .getRelyingPartyConfiguration().getRelyingPartyId(), signAssertion);
             }
         } catch (MessageEncodingException e) {
-            log.error("Unable to determine if outbound encoding {} can provide integrity", encoder.getBindingURI());
-            throw new ProfileException("Unable to determine if outbound message should be signed");
+            String msg = MessageFormatter.format(
+                    "Unable to determine if outbound encoding '{}' provides message integrity protection", encoder
+                            .getBindingURI());
+            log.error(msg);
+            throw new ProfileException(msg);
         }
 
         if (!signAssertion && relyingPartyRole instanceof SPSSODescriptor) {
             SPSSODescriptor ssoDescriptor = (SPSSODescriptor) relyingPartyRole;
             if (ssoDescriptor.getWantAssertionsSigned() != null) {
                 signAssertion = ssoDescriptor.getWantAssertionsSigned().booleanValue();
-                log.debug("Entity metadata for relying party {} indicates to sign assertions: {}", requestContext
+                log.debug("Entity metadata for relying party '{}' indicates to sign assertions: {}", requestContext
                         .getInboundMessageIssuer(), signAssertion);
             }
         }
@@ -611,7 +638,7 @@ public abstract class AbstractSAML1ProfileHandler extends AbstractSAMLProfileHan
             return;
         }
 
-        log.debug("Determining signing credntial for assertion to relying party {}", requestContext
+        log.debug("Determining credential to use to sign assertion to relying party '{}'", requestContext
                 .getInboundMessageIssuer());
         Credential signatureCredential = profileConfig.getSigningCredential();
         if (signatureCredential == null) {
@@ -619,12 +646,14 @@ public abstract class AbstractSAML1ProfileHandler extends AbstractSAMLProfileHan
         }
 
         if (signatureCredential == null) {
-            throw new ProfileException("No signing credential is specified for relying party configuration "
-                    + requestContext.getRelyingPartyConfiguration().getProviderId()
-                    + " or it's SAML2 attribute query profile configuration");
+            String msg = MessageFormatter.format(
+                    "No signing credential is specified for relying party configuration '{}'", requestContext
+                            .getRelyingPartyConfiguration().getProviderId());
+            log.warn(msg);
+            throw new ProfileException(msg);
         }
 
-        log.debug("Signing assertion to relying party {}", requestContext.getInboundMessageIssuer());
+        log.debug("Signing assertion to relying party '{}'", requestContext.getInboundMessageIssuer());
         Signature signature = signatureBuilder.buildObject(Signature.DEFAULT_ELEMENT_NAME);
 
         signature.setSigningCredential(signatureCredential);
@@ -633,7 +662,9 @@ public abstract class AbstractSAML1ProfileHandler extends AbstractSAMLProfileHan
             // TODO how to pull what keyInfoGenName to use?
             SecurityHelper.prepareSignatureParams(signature, signatureCredential, null, null);
         } catch (SecurityException e) {
-            throw new ProfileException("Error preparing signature for signing", e);
+            String msg = "Error preparing signature for signing";
+            log.error(msg);
+            throw new ProfileException(msg, e);
         }
 
         assertion.setSignature(signature);
@@ -643,11 +674,13 @@ public abstract class AbstractSAML1ProfileHandler extends AbstractSAMLProfileHan
             assertionMarshaller.marshall(assertion);
             Signer.signObject(signature);
         } catch (MarshallingException e) {
-            log.error("Unable to marshall assertion for signing", e);
-            throw new ProfileException("Unable to marshall assertion for signing", e);
+            String errMsg = "Unable to marshall assertion for signing";
+            log.error(errMsg, e);
+            throw new ProfileException(errMsg, e);
         } catch (SignatureException e) {
-            log.error("Unable to sign assertion", e);
-            throw new ProfileException("Unable to sign assertion", e);
+            String msg = "Unable to sign assertion";
+            log.error(msg, e);
+            throw new ProfileException(msg, e);
         }
     }
 
index 97db7a9..8345cfc 100644 (file)
@@ -47,14 +47,13 @@ import org.opensaml.ws.transport.http.HTTPOutTransport;
 import org.opensaml.xml.security.SecurityException;
 import org.slf4j.Logger;
 import org.slf4j.LoggerFactory;
+import org.slf4j.helpers.MessageFormatter;
 
 import edu.internet2.middleware.shibboleth.common.profile.ProfileException;
 import edu.internet2.middleware.shibboleth.common.profile.provider.BaseSAMLProfileRequestContext;
 import edu.internet2.middleware.shibboleth.common.relyingparty.provider.saml1.ArtifactResolutionConfiguration;
 
-/**
- * SAML 1 Artifact resolution profile handler.
- */
+/** SAML 1 Artifact resolution profile handler. */
 public class ArtifactResolution extends AbstractSAML1ProfileHandler {
 
     /** Class logger. */
@@ -98,13 +97,12 @@ public class ArtifactResolution extends AbstractSAML1ProfileHandler {
 
         try {
             if (requestContext.getProfileConfiguration() == null) {
-                log.error("SAML 1 Artifact resolution profile is not configured for relying party "
-                        + requestContext.getInboundMessageIssuer());
-                requestContext.setFailureStatus(buildStatus(StatusCode.SUCCESS, StatusCode.REQUEST_DENIED,
-                        "SAML 1 Artifact resolution profile is not configured for relying party "
-                                + requestContext.getInboundMessageIssuer()));
-                throw new ProfileException("SAML 1 Artifact resolution profile is not configured for relying party "
-                        + requestContext.getInboundMessageIssuer());
+                String msg = MessageFormatter.format(
+                        "SAML 1 Artifact resolution profile is not configured for relying party '{}'", requestContext
+                                .getInboundMessageIssuer());
+                requestContext.setFailureStatus(buildStatus(StatusCode.SUCCESS, StatusCode.REQUEST_DENIED, msg));
+                log.warn(msg);
+                throw new ProfileException(msg);
             }
 
             checkSamlVersion(requestContext);
@@ -136,7 +134,7 @@ public class ArtifactResolution extends AbstractSAML1ProfileHandler {
      */
     protected void decodeRequest(ArtifactResolutionRequestContext requestContext, HTTPInTransport inTransport,
             HTTPOutTransport outTransport) throws ProfileException {
-        log.debug("Decoding message with decoder binding {}", getInboundBinding());
+        log.debug("Decoding message with decoder binding '{}'", getInboundBinding());
 
         requestContext.setCommunicationProfileId(getProfileId());
 
@@ -155,16 +153,18 @@ public class ArtifactResolution extends AbstractSAML1ProfileHandler {
             SAMLMessageDecoder decoder = getMessageDecoders().get(getInboundBinding());
             requestContext.setMessageDecoder(decoder);
             decoder.decode(requestContext);
-            log.debug("Decoded request");
+            log.debug("Decoded artifact resolution request from relying party '{}'", requestContext
+                    .getInboundMessageIssuer());
         } catch (MessageDecodingException e) {
-            log.error("Error decoding artifact resolve message", e);
-            requestContext.setFailureStatus(buildStatus(StatusCode.RESPONDER, null, "Error decoding message"));
-            throw new ProfileException("Error decoding artifact resolve message", e);
+            String msg = "Error decoding artifact resolve message";
+            requestContext.setFailureStatus(buildStatus(StatusCode.RESPONDER, null, msg));
+            log.warn(msg, e);
+            throw new ProfileException(msg, e);
         } catch (SecurityException e) {
-            log.error("Message did not meet security requirements", e);
-            requestContext.setFailureStatus(buildStatus(StatusCode.RESPONDER, StatusCode.REQUEST_DENIED,
-                    "Message did not meet security requirements"));
-            throw new ProfileException("Message did not meet security requirements", e);
+            String msg = "Message did not meet security requirements";
+            requestContext.setFailureStatus(buildStatus(StatusCode.RESPONDER, StatusCode.REQUEST_DENIED, msg));
+            log.warn(msg, e);
+            throw new ProfileException(msg, e);
         } finally {
             // Set as much information as can be retrieved from the decoded message
             populateRequestContext(requestContext);
@@ -229,7 +229,7 @@ public class ArtifactResolution extends AbstractSAML1ProfileHandler {
     }
 
     /**
-     * Derferences the artifacts within the incoming request and stores them in the request context.
+     * Dereferences the artifacts within the incoming request and stores them in the request context.
      * 
      * @param requestContext current request context
      * 
@@ -240,8 +240,10 @@ public class ArtifactResolution extends AbstractSAML1ProfileHandler {
         List<AssertionArtifact> assertionArtifacts = request.getAssertionArtifacts();
 
         if (assertionArtifacts == null || assertionArtifacts.size() == 0) {
-            log.error("No AssertionArtifacts available in request");
-            throw new ProfileException("No AssertionArtifacts available in request");
+            String msg = MessageFormatter.format("No AssertionArtifacts available in request from relying party '{}'",
+                    requestContext.getInboundMessageIssuer());
+            log.warn(msg);
+            throw new ProfileException(msg);
         }
 
         ArrayList<Assertion> assertions = new ArrayList<Assertion>();
@@ -249,12 +251,15 @@ public class ArtifactResolution extends AbstractSAML1ProfileHandler {
         for (AssertionArtifact assertionArtifact : assertionArtifacts) {
             artifactEntry = artifactMap.get(assertionArtifact.getAssertionArtifact());
             if (artifactEntry == null || artifactEntry.isExpired()) {
-                log.error("Unknown artifact.");
+                log.warn("Unknown AssertionArtifact '{}' from relying party '{}'", assertionArtifact
+                        .getAssertionArtifact(), requestContext.getInboundMessageIssuer());
+                continue;
             }
 
             if (!artifactEntry.getIssuerId().equals(requestContext.getLocalEntityId())) {
-                log.error("Artifact issuer mismatch.  Artifact issued by " + artifactEntry.getIssuerId()
-                        + " but IdP has entity ID of " + requestContext.getLocalEntityId());
+                log.warn("Artifact issuer mismatch.  Artifact issued by '{}' but IdP has entity ID of '{}'",
+                        artifactEntry.getIssuerId(), requestContext.getLocalEntityId());
+                continue;
             }
 
             artifactMap.remove(assertionArtifact.getAssertionArtifact());
index af9f72e..6af8c1d 100644 (file)
@@ -164,11 +164,11 @@ public class AttributeQueryProfileHandler extends AbstractSAML1ProfileHandler {
                 throw new ProfileException("Invalid SAML Attribute Request message.");
             }
         } catch (MessageDecodingException e) {
-            log.error("Error decoding attribute query message", e);
+            log.warn("Error decoding attribute query message", e);
             requestContext.setFailureStatus(buildStatus(StatusCode.RESPONDER, null, "Error decoding message"));
             throw new ProfileException("Error decoding attribute query message", e);
         } catch (SecurityException e) {
-            log.error("Message did not meet security requirements", e);
+            log.warn("Message did not meet security requirements", e);
             requestContext.setFailureStatus(buildStatus(StatusCode.RESPONDER, StatusCode.REQUEST_DENIED,
                     "Message did not meet security requirements"));
             throw new ProfileException("Message did not meet security policy requirements", e);
index 626f912..5f79a4a 100644 (file)
@@ -51,13 +51,13 @@ public class ShibbolethSSODecoder extends BaseSAML1MessageDecoder implements SAM
     /** {@inheritDoc} */
     protected void doDecode(MessageContext messageContext) throws MessageDecodingException {
         if (!(messageContext instanceof ShibbolethSSORequestContext)) {
-            log.error("Invalid message context type, this decoder only support ShibbolethSSORequestContext");
+            log.warn("Invalid message context type, this decoder only support ShibbolethSSORequestContext");
             throw new MessageDecodingException(
                     "Invalid message context type, this decoder only support ShibbolethSSORequestContext");
         }
 
         if (!(messageContext.getInboundMessageTransport() instanceof HTTPInTransport)) {
-            log.error("Invalid inbound message transport type, this decoder only support HTTPInTransport");
+            log.warn("Invalid inbound message transport type, this decoder only support HTTPInTransport");
             throw new MessageDecodingException(
                     "Invalid inbound message transport type, this decoder only support HTTPInTransport");
         }
@@ -67,7 +67,7 @@ public class ShibbolethSSODecoder extends BaseSAML1MessageDecoder implements SAM
 
         String providerId = DatatypeHelper.safeTrimOrNullString(transport.getParameterValue("providerId"));
         if (providerId == null) {
-            log.error("No providerId parameter given in Shibboleth SSO authentication request.");
+            log.warn("No providerId parameter given in Shibboleth SSO authentication request.");
             throw new MessageDecodingException(
                     "No providerId parameter given in Shibboleth SSO authentication request.");
         }
@@ -75,14 +75,14 @@ public class ShibbolethSSODecoder extends BaseSAML1MessageDecoder implements SAM
 
         String shire = DatatypeHelper.safeTrimOrNullString(transport.getParameterValue("shire"));
         if (shire == null) {
-            log.error("No shire parameter given in Shibboleth SSO authentication request.");
+            log.warn("No shire parameter given in Shibboleth SSO authentication request.");
             throw new MessageDecodingException("No shire parameter given in Shibboleth SSO authentication request.");
         }
         requestContext.setSpAssertionConsumerService(shire);
 
         String target = DatatypeHelper.safeTrimOrNullString(transport.getParameterValue("target"));
         if (target == null) {
-            log.error("No target parameter given in Shibboleth SSO authentication request.");
+            log.warn("No target parameter given in Shibboleth SSO authentication request.");
             throw new MessageDecodingException("No target parameter given in Shibboleth SSO authentication request.");
         }
         requestContext.setRelayState(target);
index 9594b16..6636a5f 100644 (file)
@@ -75,11 +75,11 @@ public class ShibbolethSSOEndpointSelector extends BasicEndpointSelector {
      * @return endpoint corresponding to the SP-provdided ACS URL
      */
     protected Endpoint selectEndpointByACS() {
-        log.debug("Selecting endpoint from metadata corresponding to provided ACS URL: {}",
+        log.debug("Selecting endpoint from metadata corresponding to provided ACS URL: '{}'",
                 getSpAssertionConsumerService());
 
         List<Endpoint> endpoints = getEntityRoleMetadata().getEndpoints();
-        log.debug("Relying party role contains {} endpoints", endpoints.size());
+        log.debug("Relying party role contains '{}' endpoints", endpoints.size());
 
         if (endpoints != null && endpoints.size() > 0) {
             for (Endpoint endpoint : endpoints) {
@@ -98,7 +98,7 @@ public class ShibbolethSSOEndpointSelector extends BasicEndpointSelector {
             }
         }
 
-        log.debug("No endpoint meets selection criteria for SAML entity {}", getEntityMetadata().getEntityID());
+        log.debug("No endpoint meets selection criteria for SAML entity '{}'", getEntityMetadata().getEntityID());
         return null;
     }
 }
\ No newline at end of file
index 1996bd6..84d827d 100644 (file)
@@ -49,6 +49,7 @@ import org.opensaml.xml.security.SecurityException;
 import org.opensaml.xml.util.DatatypeHelper;
 import org.slf4j.Logger;
 import org.slf4j.LoggerFactory;
+import org.slf4j.helpers.MessageFormatter;
 
 import edu.internet2.middleware.shibboleth.common.ShibbolethConstants;
 import edu.internet2.middleware.shibboleth.common.profile.ProfileException;
@@ -147,9 +148,9 @@ public class ShibbolethSSOProfileHandler extends AbstractSAML1ProfileHandler {
         RelyingPartyConfiguration rpConfig = getRelyingPartyConfiguration(loginContext.getRelyingPartyId());
         ProfileConfiguration ssoConfig = rpConfig.getProfileConfiguration(ShibbolethSSOConfiguration.PROFILE_ID);
         if (ssoConfig == null) {
-            log.error("Shibboleth SSO profile is not configured for relying party " + loginContext.getRelyingPartyId());
-            throw new ProfileException("Shibboleth SSO profile is not configured for relying party "
-                    + loginContext.getRelyingPartyId());
+            String msg = MessageFormatter.format("Shibboleth SSO profile is not configured for relying party '{}'", loginContext.getRelyingPartyId());
+            log.warn(msg);
+            throw new ProfileException(msg);
         }
         if (loginContext.getRequestedAuthenticationMethods().size() == 0
                 && rpConfig.getDefaultAuthenticationMethod() != null) {
@@ -162,12 +163,14 @@ public class ShibbolethSSOProfileHandler extends AbstractSAML1ProfileHandler {
             RequestDispatcher dispatcher = httpRequest.getRequestDispatcher(authenticationManagerPath);
             dispatcher.forward(httpRequest, httpResponse);
             return;
-        } catch (IOException ex) {
-            log.error("Error forwarding Shibboleth SSO request to AuthenticationManager", ex);
-            throw new ProfileException("Error forwarding Shibboleth SSO request to AuthenticationManager", ex);
-        } catch (ServletException ex) {
-            log.error("Error forwarding Shibboleth SSO request to AuthenticationManager", ex);
-            throw new ProfileException("Error forwarding Shibboleth SSO request to AuthenticationManager", ex);
+        } catch (IOException e) {
+            String msg = "Error forwarding Shibboleth SSO request to AuthenticationManager"; 
+            log.error(msg, e);
+            throw new ProfileException(msg, e);
+        } catch (ServletException e) {
+            String msg = "Error forwarding Shibboleth SSO request to AuthenticationManager";
+            log.error(msg, e);
+            throw new ProfileException(msg, e);
         }
     }
 
@@ -203,12 +206,15 @@ public class ShibbolethSSOProfileHandler extends AbstractSAML1ProfileHandler {
         requestContext.setMessageDecoder(decoder);
         try {
             decoder.decode(requestContext);
+            log.debug("Decoded Shibboleth SSO request from relying party '{}'", requestContext.getInboundMessageIssuer());
         } catch (MessageDecodingException e) {
-            log.error("Error decoding Shibboleth SSO request", e);
-            throw new ProfileException("Error decoding Shibboleth SSO request", e);
+            String msg = "Error decoding Shibboleth SSO request"; 
+            log.warn(msg, e);
+            throw new ProfileException(msg, e);
         } catch (SecurityException e) {
-            log.error("Shibboleth SSO request does not meet security requirements", e);
-            throw new ProfileException("Shibboleth SSO request does not meet security requirements", e);
+            String msg = "Shibboleth SSO request does not meet security requirements";
+            log.warn(msg, e);
+            throw new ProfileException("msg", e);
         }
 
         ShibbolethSSOLoginContext loginContext = new ShibbolethSSOLoginContext();
index 738614c..22a4709 100644 (file)
@@ -74,6 +74,7 @@ import org.opensaml.xml.signature.Signer;
 import org.opensaml.xml.util.DatatypeHelper;
 import org.slf4j.Logger;
 import org.slf4j.LoggerFactory;
+import org.slf4j.helpers.MessageFormatter;
 
 import edu.internet2.middleware.shibboleth.common.attribute.AttributeRequestException;
 import edu.internet2.middleware.shibboleth.common.attribute.BaseAttribute;
@@ -270,7 +271,7 @@ public abstract class AbstractSAML2ProfileHandler extends AbstractSAMLProfileHan
                 if (requestContext.getProfileConfiguration().getEncryptAssertion() == CryptoOperationRequirementLevel.always
                         || (requestContext.getProfileConfiguration().getEncryptAssertion() == CryptoOperationRequirementLevel.conditional && !encoder
                                 .providesMessageConfidentiality(requestContext))) {
-                    log.debug("Attempting to encrypt assertion to relying party {}", requestContext
+                    log.debug("Attempting to encrypt assertion to relying party '{}'", requestContext
                             .getInboundMessageIssuer());
                     try {
                         Encrypter encrypter = getEncrypter(requestContext.getInboundMessageIssuer());
@@ -290,7 +291,7 @@ public abstract class AbstractSAML2ProfileHandler extends AbstractSAMLProfileHan
                     samlResponse.getAssertions().add(assertion);
                 }
             } catch (MessageEncodingException e) {
-                log.error("Unable to determine if outbound encoding {} can provide confidentiality", encoder
+                log.error("Unable to determine if outbound encoding '{}' can provide confidentiality", encoder
                         .getBindingURI());
                 throw new ProfileException("Unable to determine if assertions should be encrypted");
             }
@@ -442,18 +443,18 @@ public abstract class AbstractSAML2ProfileHandler extends AbstractSAMLProfileHan
         AbstractSAML2ProfileConfiguration profileConfiguration = requestContext.getProfileConfiguration();
         SAML2AttributeAuthority attributeAuthority = profileConfiguration.getAttributeAuthority();
         try {
-            log.debug("Resolving attributes for principal {} of SAML request from relying party {}", requestContext
-                    .getPrincipalName(), requestContext.getInboundMessageIssuer());
+            log.debug("Resolving attributes for principal '{}' for SAML request from relying party '{}'",
+                    requestContext.getPrincipalName(), requestContext.getInboundMessageIssuer());
             Map<String, BaseAttribute> principalAttributes = attributeAuthority.getAttributes(requestContext);
 
             requestContext.setAttributes(principalAttributes);
         } catch (AttributeRequestException e) {
-            log.error("Error resolving attributes for SAML request " + requestContext.getInboundSAMLMessageId()
-                    + " from relying party " + requestContext.getInboundMessageIssuer(), e);
             requestContext.setFailureStatus(buildStatus(StatusCode.RESPONDER_URI, null, "Error resolving attributes"));
-            throw new ProfileException("Error resolving attributes for SAML request "
-                    + requestContext.getInboundSAMLMessageId() + " from relying party "
-                    + requestContext.getInboundMessageIssuer(), e);
+            String msg = MessageFormatter.format(
+                    "Error resolving attributes for principal '{}' for SAML request from relying party '{}'",
+                    requestContext.getPrincipalName(), requestContext.getInboundMessageIssuer());
+            log.error(msg, e);
+            throw new ProfileException(msg, e);
         }
     }
 
@@ -468,8 +469,8 @@ public abstract class AbstractSAML2ProfileHandler extends AbstractSAMLProfileHan
      */
     protected AttributeStatement buildAttributeStatement(BaseSAML2ProfileRequestContext<?, ?, ?> requestContext)
             throws ProfileException {
-        log.debug("Creating attribute statement in response to SAML request {} from relying party {}", requestContext
-                .getInboundSAMLMessageId(), requestContext.getInboundMessageIssuer());
+        log.debug("Creating attribute statement in response to SAML request '{}' from relying party '{}'",
+                requestContext.getInboundSAMLMessageId(), requestContext.getInboundMessageIssuer());
 
         AbstractSAML2ProfileConfiguration profileConfiguration = requestContext.getProfileConfiguration();
         SAML2AttributeAuthority attributeAuthority = profileConfiguration.getAttributeAuthority();
@@ -481,10 +482,11 @@ public abstract class AbstractSAML2ProfileHandler extends AbstractSAMLProfileHan
                 return attributeAuthority.buildAttributeStatement(null, requestContext.getAttributes().values());
             }
         } catch (AttributeRequestException e) {
-            log.error("Error encoding attributes for principal " + requestContext.getPrincipalName(), e);
             requestContext.setFailureStatus(buildStatus(StatusCode.RESPONDER_URI, null, "Error resolving attributes"));
-            throw new ProfileException("Error encoding attributes for principal " + requestContext.getPrincipalName(),
-                    e);
+            String msg = MessageFormatter.format("Error encoding attributes for principal '{}'", requestContext
+                    .getPrincipalName());
+            log.error(msg, e);
+            throw new ProfileException(msg, e);
         }
     }
 
@@ -498,29 +500,29 @@ public abstract class AbstractSAML2ProfileHandler extends AbstractSAMLProfileHan
     protected void resolvePrincipal(BaseSAML2ProfileRequestContext<?, ?, ?> requestContext) throws ProfileException {
         AbstractSAML2ProfileConfiguration profileConfiguration = requestContext.getProfileConfiguration();
         if (profileConfiguration == null) {
-            log.error("Unable to resolve principal, no SAML 2 profile configuration for relying party "
-                    + requestContext.getInboundMessageIssuer());
             requestContext.setFailureStatus(buildStatus(StatusCode.RESPONDER_URI, StatusCode.REQUEST_DENIED_URI,
                     "Error resolving principal"));
-            throw new ProfileException(
-                    "Unable to resolve principal, no SAML 2 profile configuration for relying party "
-                            + requestContext.getInboundMessageIssuer());
+            String msg = MessageFormatter.format(
+                    "Unable to resolve principal, no SAML 2 profile configuration for relying party '{}'",
+                    requestContext.getInboundMessageIssuer());
+            log.warn(msg);
+            throw new ProfileException(msg);
         }
         SAML2AttributeAuthority attributeAuthority = profileConfiguration.getAttributeAuthority();
-        log.debug("Resolving principal name for subject of SAML request {} from relying party {}", requestContext
+        log.debug("Resolving principal name for subject of SAML request '{}' from relying party '{}'", requestContext
                 .getInboundSAMLMessageId(), requestContext.getInboundMessageIssuer());
 
         try {
             String principal = attributeAuthority.getPrincipal(requestContext);
             requestContext.setPrincipalName(principal);
         } catch (AttributeRequestException e) {
-            log.error("Error resolving attributes for SAML request " + requestContext.getInboundSAMLMessageId()
-                    + " from relying party " + requestContext.getInboundMessageIssuer(), e);
             requestContext.setFailureStatus(buildStatus(StatusCode.RESPONDER_URI, StatusCode.UNKNOWN_PRINCIPAL_URI,
                     "Error resolving principal"));
-            throw new ProfileException("Error resolving attributes for SAML request "
-                    + requestContext.getInboundSAMLMessageId() + " from relying party "
-                    + requestContext.getInboundMessageIssuer(), e);
+            String msg = MessageFormatter.format(
+                    "Error resolving principal name for SAML request '{}' from relying party '{}'", requestContext
+                            .getInboundSAMLMessageId(), requestContext.getInboundMessageIssuer());
+            log.error(msg, e);
+            throw new ProfileException(msg, e);
         }
     }
 
@@ -536,7 +538,7 @@ public abstract class AbstractSAML2ProfileHandler extends AbstractSAMLProfileHan
      */
     protected void signAssertion(BaseSAML2ProfileRequestContext<?, ?, ?> requestContext, Assertion assertion)
             throws ProfileException {
-        log.debug("Determining if SAML assertion to relying party {} should be signed", requestContext
+        log.debug("Determining if SAML assertion to relying party '{}' should be signed", requestContext
                 .getInboundMessageIssuer());
 
         boolean signAssertion = false;
@@ -548,11 +550,11 @@ public abstract class AbstractSAML2ProfileHandler extends AbstractSAMLProfileHan
                     || (profileConfig.getSignAssertions() == CryptoOperationRequirementLevel.conditional && !encoder
                             .providesMessageIntegrity(requestContext))) {
                 signAssertion = true;
-                log.debug("IdP relying party configuration {} indicates to sign assertions: {}", requestContext
+                log.debug("IdP relying party configuration '{}' indicates to sign assertions: {}", requestContext
                         .getRelyingPartyConfiguration().getRelyingPartyId(), signAssertion);
             }
         } catch (MessageEncodingException e) {
-            log.error("Unable to determine if outbound encoding {} can provide integrity protection", encoder
+            log.error("Unable to determine if outbound encoding '{}' provides message integrity protection", encoder
                     .getBindingURI());
             throw new ProfileException("Unable to determine if outbound message should be signed");
         }
@@ -561,7 +563,7 @@ public abstract class AbstractSAML2ProfileHandler extends AbstractSAMLProfileHan
             SPSSODescriptor ssoDescriptor = (SPSSODescriptor) requestContext.getPeerEntityRoleMetadata();
             if (ssoDescriptor.getWantAssertionsSigned() != null) {
                 signAssertion = ssoDescriptor.getWantAssertionsSigned().booleanValue();
-                log.debug("Entity metadata for relying party {} indicates to sign assertions: {}", requestContext
+                log.debug("Entity metadata for relying party '{} 'indicates to sign assertions: {}", requestContext
                         .getInboundMessageIssuer(), signAssertion);
             }
         }
@@ -570,7 +572,7 @@ public abstract class AbstractSAML2ProfileHandler extends AbstractSAMLProfileHan
             return;
         }
 
-        log.debug("Determining signing credntial for assertion to relying party {}", requestContext
+        log.debug("Determining signing credntial for assertion to relying party '{}'", requestContext
                 .getInboundMessageIssuer());
         Credential signatureCredential = profileConfig.getSigningCredential();
         if (signatureCredential == null) {
@@ -578,9 +580,11 @@ public abstract class AbstractSAML2ProfileHandler extends AbstractSAMLProfileHan
         }
 
         if (signatureCredential == null) {
-            throw new ProfileException("No signing credential is specified for relying party configuration "
-                    + requestContext.getRelyingPartyConfiguration().getProviderId()
-                    + " or it's SAML2 attribute query profile configuration");
+            String msg = MessageFormatter.format(
+                    "No signing credential is specified for relying party configuration '{}'", requestContext
+                            .getRelyingPartyConfiguration().getProviderId());
+            log.warn(msg);
+            throw new ProfileException(msg);
         }
 
         log.debug("Signing assertion to relying party {}", requestContext.getInboundMessageIssuer());
@@ -592,7 +596,9 @@ public abstract class AbstractSAML2ProfileHandler extends AbstractSAMLProfileHan
             // TODO how to pull what keyInfoGenName to use?
             SecurityHelper.prepareSignatureParams(signature, signatureCredential, null, null);
         } catch (SecurityException e) {
-            throw new ProfileException("Error preparing signature for signing", e);
+            String msg = "Error preparing signature for signing";
+            log.error(msg);
+            throw new ProfileException(msg, e);
         }
 
         assertion.setSignature(signature);
@@ -602,11 +608,13 @@ public abstract class AbstractSAML2ProfileHandler extends AbstractSAMLProfileHan
             assertionMarshaller.marshall(assertion);
             Signer.signObject(signature);
         } catch (MarshallingException e) {
-            log.error("Unable to marshall assertion for signing", e);
-            throw new ProfileException("Unable to marshall assertion for signing", e);
+            String errMsg = "Unable to marshall assertion for signing";
+            log.error(errMsg, e);
+            throw new ProfileException(errMsg, e);
         } catch (SignatureException e) {
-            log.error("Unable to sign assertion", e);
-            throw new ProfileException("Unable to sign assertion", e);
+            String msg = "Unable to sign assertion";
+            log.error(msg, e);
+            throw new ProfileException(msg, e);
         }
     }
 
@@ -682,7 +690,8 @@ public abstract class AbstractSAML2ProfileHandler extends AbstractSAMLProfileHan
                     || requestContext.getProfileConfiguration().getEncryptNameID() == CryptoOperationRequirementLevel.always
                     || (requestContext.getProfileConfiguration().getEncryptNameID() == CryptoOperationRequirementLevel.conditional && !encoder
                             .providesMessageConfidentiality(requestContext))) {
-                log.debug("Attempting to encrypt NameID to relying party {}", requestContext.getInboundMessageIssuer());
+                log.debug("Attempting to encrypt NameID to relying party '{}'", requestContext
+                        .getInboundMessageIssuer());
                 try {
                     Encrypter encrypter = getEncrypter(requestContext.getInboundMessageIssuer());
                     subject.setEncryptedID(encrypter.encrypt(nameID));
@@ -701,9 +710,11 @@ public abstract class AbstractSAML2ProfileHandler extends AbstractSAMLProfileHan
                 subject.setNameID(nameID);
             }
         } catch (MessageEncodingException e) {
-            log.error("Unable to determine if outbound encoding {} can provide confidentiality", encoder
-                    .getBindingURI());
-            throw new ProfileException("Unable to determine if assertions should be encrypted");
+            String msg = MessageFormatter.format(
+                    "Unable to determine if outbound encoding '{}' provides message confidentiality protection",
+                    encoder.getBindingURI());
+            log.error(msg);
+            throw new ProfileException(msg);
         }
 
         return subject;
@@ -782,53 +793,72 @@ public abstract class AbstractSAML2ProfileHandler extends AbstractSAMLProfileHan
             supportedNameFormats.clear();
             supportedNameFormats.add(requiredNameFormat);
         }
-
-        Map<String, BaseAttribute> principalAttributes = requestContext.getAttributes();
-        if (principalAttributes == null || principalAttributes.isEmpty()) {
-            if (requiredNameFormat != null) {
-                requestContext.setFailureStatus(buildStatus(StatusCode.RESPONDER_URI,
-                        StatusCode.INVALID_NAMEID_POLICY_URI, "Format not supported: " + requiredNameFormat));
-                throw new ProfileException(
-                        "No attributes for principal, so NameID format required by relying party is not supported");
-            }
-            log.debug("No attributes for principal {}, no name identifier will be created.", requestContext
-                    .getPrincipalName());
-            return null;
-        }
-
         if (!supportedNameFormats.isEmpty()) {
-            log.debug("SP-supported name formats: {}", supportedNameFormats);
+            log.debug("Relying party '{}' supports the name formats: {}", requestContext.getInboundMessageIssuer(),
+                    supportedNameFormats);
         } else {
-            log.debug("SP indicated no preferred name formats.");
+            log.debug("Relying party '{}' indicated no preferred name formats", requestContext
+                    .getInboundMessageIssuer());
         }
 
-        try {
-            SAML2NameIDEncoder nameIdEncoder;
+        BaseAttribute<?> nameIdAttribute = null;
+        SAML2NameIDEncoder nameIdEncoder = null;
+
+        Map<String, BaseAttribute> principalAttributes = requestContext.getAttributes();
+        if (principalAttributes != null) {
             for (BaseAttribute<?> attribute : principalAttributes.values()) {
+                if (attribute == null) {
+                    continue;
+                }
+
                 for (AttributeEncoder encoder : attribute.getEncoders()) {
+                    if (encoder == null) {
+                        continue;
+                    }
+
                     if (encoder instanceof SAML2NameIDEncoder) {
-                        nameIdEncoder = (SAML2NameIDEncoder) encoder;
-                        if (supportedNameFormats.isEmpty()
-                                || supportedNameFormats.contains(nameIdEncoder.getNameFormat())) {
-                            log.debug("Using attribute {} supporting NameID format {} to create the NameID.", attribute
-                                    .getId(), nameIdEncoder.getNameFormat());
-                            NameID nameIdentifier = nameIdEncoder.encode(attribute);
-                            requestContext.setSubjectNameIdentifier(nameIdentifier);
-                            return nameIdentifier;
+                        nameIdEncoder = (SAML2NameIDEncoder)encoder;
+                        
+                        if (requiredNameFormat != null) {
+                            if (nameIdEncoder.getNameFormat().equals(requiredNameFormat)) {
+                                nameIdAttribute = attribute;
+                                nameIdEncoder = (SAML2NameIDEncoder) encoder;
+                                break;
+                            }
+                        } else {
+                            if (supportedNameFormats.isEmpty()
+                                    || supportedNameFormats.contains(nameIdEncoder.getNameFormat())) {
+                                nameIdAttribute = attribute;
+                                nameIdEncoder = (SAML2NameIDEncoder) encoder;
+                                break;
+                            }
                         }
                     }
                 }
             }
+        }
 
+        if (nameIdAttribute == null || nameIdEncoder == null) {
             if (requiredNameFormat != null) {
                 requestContext.setFailureStatus(buildStatus(StatusCode.RESPONDER_URI,
-                        StatusCode.INVALID_NAMEID_POLICY_URI, "Format not supported: " + requiredNameFormat));
-                throw new ProfileException(
-                        "No attributes for principal support NameID format required by relying party");
+                        StatusCode.INVALID_NAMEID_POLICY_URI, "NameID Format not supported: " + requiredNameFormat));
+                String msg = MessageFormatter
+                        .format(
+                                "No attribute of principal '{}' can be encoded in to a NameID of required format '{}' for relying party '{}'",
+                                new Object[] { requestContext.getPrincipalName(), requiredNameFormat,
+                                        requestContext.getInboundMessageIssuer() });
+                log.warn(msg);
+                throw new ProfileException(msg);
+            } else {
+                return null;
             }
-            log.debug("No attributes for principal {} support an encoding into a supported name ID format.",
-                    requestContext.getPrincipalName());
-            return null;
+        }
+
+        log.debug("Using attribute '{}' supporting NameID format '{}' to create the NameID for relying party '{}'",
+                new Object[] { nameIdAttribute.getId(), nameIdEncoder.getNameFormat(),
+                        requestContext.getInboundMessageIssuer() });
+        try {
+            return nameIdEncoder.encode(nameIdAttribute);
         } catch (AttributeEncodingException e) {
             log.error("Unable to encode NameID attribute", e);
             requestContext.setFailureStatus(buildStatus(StatusCode.RESPONDER_URI, null, "Unable to construct NameID"));
@@ -933,7 +963,7 @@ public abstract class AbstractSAML2ProfileHandler extends AbstractSAMLProfileHan
 
         /** The response to the SAML request. */
         private StatusResponseType samlResponse;
-        
+
         /** The unencrypted NameID for the SAML response. */
         private NameID unencryptedNameId;
 
@@ -954,7 +984,7 @@ public abstract class AbstractSAML2ProfileHandler extends AbstractSAMLProfileHan
         public void setSAMLResponse(StatusResponseType response) {
             samlResponse = response;
         }
-        
+
         /**
          * Gets the unencrypted NameID for the SAML response.
          * 
@@ -963,7 +993,7 @@ public abstract class AbstractSAML2ProfileHandler extends AbstractSAMLProfileHan
         public NameID getUnencryptedNameId() {
             return unencryptedNameId;
         }
-        
+
         /**
          * Sets the unencrypted NameID for the SAML response.
          * 
index dddc21f..0c587bf 100644 (file)
@@ -16,6 +16,8 @@
 
 package edu.internet2.middleware.shibboleth.idp.profile.saml2;
 
+import java.text.MessageFormat;
+
 import org.joda.time.DateTime;
 import org.opensaml.common.SAMLObject;
 import org.opensaml.common.SAMLObjectBuilder;
@@ -92,38 +94,47 @@ public class ArtifactResolution extends AbstractSAML2ProfileHandler {
         ArtifactResolutionRequestContext requestContext = new ArtifactResolutionRequestContext();
         try {
             decodeRequest(requestContext, inTransport, outTransport);
-            
+
             if (requestContext.getProfileConfiguration() == null) {
-                log.error("SAML 2 Artifact Resolve profile is not configured for relying party "
-                        + requestContext.getInboundMessageIssuer());
-                requestContext.setFailureStatus(buildStatus(StatusCode.SUCCESS_URI, StatusCode.REQUEST_DENIED_URI,
-                        "SAML 2 Artifact Resolve profile is not configured for relying party "
-                                + requestContext.getInboundMessageIssuer()));
-                throw new ProfileException("SAML 2 Artifact Resolve profile is not configured for relying party "
-                        + requestContext.getInboundMessageIssuer());
+                String msg = MessageFormat.format(
+                        "SAML 2 Artifact Resolve profile is not configured for relying party '{}'", requestContext
+                                .getInboundMessageIssuer());
+                requestContext
+                        .setFailureStatus(buildStatus(StatusCode.SUCCESS_URI, StatusCode.REQUEST_DENIED_URI, msg));
+                log.warn(msg);
+                throw new ProfileException(msg);
             }
 
             checkSamlVersion(requestContext);
 
             SAMLArtifactMapEntry artifactEntry = artifactMap.get(requestContext.getArtifact());
             if (artifactEntry == null || artifactEntry.isExpired()) {
-                log.error("Unknown artifact.");
-                requestContext.setFailureStatus(buildStatus(StatusCode.SUCCESS_URI, StatusCode.REQUEST_DENIED_URI,
-                        "Unknown artifact."));
+                String msg = MessageFormat.format("Unknown artifact '{}' from relying party '{}'", requestContext
+                        .getArtifact(), requestContext.getInboundMessageIssuer());
+                log.error(msg);
+                requestContext
+                        .setFailureStatus(buildStatus(StatusCode.SUCCESS_URI, StatusCode.REQUEST_DENIED_URI, msg));
             }
 
             if (!artifactEntry.getIssuerId().equals(requestContext.getLocalEntityId())) {
-                log.error("Artifact issuer mismatch.  Artifact issued by " + artifactEntry.getIssuerId()
-                        + " but IdP has entity ID of " + requestContext.getLocalEntityId());
-                requestContext.setFailureStatus(buildStatus(StatusCode.SUCCESS_URI, StatusCode.REQUEST_DENIED_URI,
-                        "Artifact issuer mismatch."));
+                String msg = MessageFormat.format(
+                        "Artifact issuer mismatch.  Artifact issued by '{}' but IdP has entity ID of '{}'",
+                        artifactEntry.getIssuerId(), requestContext.getLocalEntityId());
+                log.warn(msg);
+                requestContext
+                        .setFailureStatus(buildStatus(StatusCode.SUCCESS_URI, StatusCode.REQUEST_DENIED_URI, msg));
+                return;
             }
 
             if (!artifactEntry.getRelyingPartyId().equals(requestContext.getInboundMessageIssuer())) {
-                log.error("Artifact requester mismatch.  Artifact was issued to " + artifactEntry.getRelyingPartyId()
-                        + " but was resolve request came from " + requestContext.getInboundMessageIssuer());
-                requestContext.setFailureStatus(buildStatus(StatusCode.SUCCESS_URI, StatusCode.REQUEST_DENIED_URI,
-                        "Artifact requester mismatch."));
+                String msg = MessageFormat
+                        .format(
+                                "Artifact requester mismatch. Artifact was issued to '{}' but the resolve request came from '{}'",
+                                artifactEntry.getRelyingPartyId(), requestContext.getInboundMessageIssuer());
+                log.warn(msg);
+                requestContext
+                        .setFailureStatus(buildStatus(StatusCode.SUCCESS_URI, StatusCode.REQUEST_DENIED_URI, msg));
+                return;
             }
 
             // create the SAML response
@@ -152,7 +163,7 @@ public class ArtifactResolution extends AbstractSAML2ProfileHandler {
      */
     protected void decodeRequest(ArtifactResolutionRequestContext requestContext, HTTPInTransport inTransport,
             HTTPOutTransport outTransport) throws ProfileException {
-        log.debug("Decoding message with decoder binding {}", getInboundBinding());
+        log.debug("Decoding message with decoder binding '{}'", getInboundBinding());
 
         requestContext.setCommunicationProfileId(getProfileId());
 
@@ -171,16 +182,17 @@ public class ArtifactResolution extends AbstractSAML2ProfileHandler {
             SAMLMessageDecoder decoder = getMessageDecoders().get(getInboundBinding());
             requestContext.setMessageDecoder(decoder);
             decoder.decode(requestContext);
-            log.debug("Decoded request");
+            log.debug("Decoded request from relying party '{}'", requestContext.getInboundMessageIssuer());
         } catch (MessageDecodingException e) {
-            log.error("Error decoding artifact resolve message", e);
-            requestContext.setFailureStatus(buildStatus(StatusCode.RESPONDER_URI, null, "Error decoding message"));
-            throw new ProfileException("Error decoding artifact resolve message");
+            String msg = "Error decoding artifact resolve message";
+            requestContext.setFailureStatus(buildStatus(StatusCode.RESPONDER_URI, null, msg));
+            log.warn(msg, e);
+            throw new ProfileException(msg);
         } catch (SecurityException e) {
-            log.error("Message did not meet security requirements", e);
-            requestContext.setFailureStatus(buildStatus(StatusCode.RESPONDER_URI, StatusCode.REQUEST_DENIED_URI,
-                    "Message did not meet security requirements"));
-            throw new ProfileException("Message did not meet security requirements", e);
+            String msg = "Message did not meet security requirements";
+            requestContext.setFailureStatus(buildStatus(StatusCode.RESPONDER_URI, StatusCode.REQUEST_DENIED_URI, msg));
+            log.warn(msg, e);
+            throw new ProfileException(msg, e);
         } finally {
             populateRequestContext(requestContext);
         }
@@ -224,7 +236,7 @@ public class ArtifactResolution extends AbstractSAML2ProfileHandler {
      */
     protected void populateSAMLMessageInformation(BaseSAMLProfileRequestContext requestContext) throws ProfileException {
         ArtifactResolve samlMessage = (ArtifactResolve) requestContext.getInboundSAMLMessage();
-        if(samlMessage != null && samlMessage.getArtifact() != null){
+        if (samlMessage != null && samlMessage.getArtifact() != null) {
             ((ArtifactResolutionRequestContext) requestContext).setArtifact(samlMessage.getArtifact().getArtifact());
         }
     }
@@ -299,7 +311,7 @@ public class ArtifactResolution extends AbstractSAML2ProfileHandler {
         return samlResponse;
     }
 
-    /** Represents the internal state of a SAML 2.0 Artiface resolver request while it's being processed by the IdP. */
+    /** Represents the internal state of a SAML 2.0 Artifact resolver request while it's being processed by the IdP. */
     public class ArtifactResolutionRequestContext extends
             BaseSAML2ProfileRequestContext<ArtifactResolve, ArtifactResponse, ArtifactResolutionConfiguration>
             implements SAML2ArtifactMessageContext<ArtifactResolve, ArtifactResponse, NameID> {
index 8560e95..6c2b300 100644 (file)
@@ -1,5 +1,5 @@
 /*
- * Copyright [2006] [University Corporation for Advanced Internet Development, Inc.]
+ * Copyright 2006 University Corporation for Advanced Internet Development, Inc.
  *
  * Licensed under the Apache License, Version 2.0 (the "License");
  * you may not use this file except in compliance with the License.
@@ -40,6 +40,7 @@ import org.opensaml.ws.transport.http.HTTPOutTransport;
 import org.opensaml.xml.security.SecurityException;
 import org.slf4j.Logger;
 import org.slf4j.LoggerFactory;
+import org.slf4j.helpers.MessageFormatter;
 
 import edu.internet2.middleware.shibboleth.common.profile.ProfileException;
 import edu.internet2.middleware.shibboleth.common.profile.provider.BaseSAMLProfileRequestContext;
@@ -79,11 +80,12 @@ public class AttributeQueryProfileHandler extends AbstractSAML2ProfileHandler {
             decodeRequest(requestContext, inTransport, outTransport);
 
             if (requestContext.getProfileConfiguration() == null) {
-                log.error("SAML 2 Attribute Query profile is not configured for relying party "
-                        + requestContext.getInboundMessageIssuer());
+                String msg = MessageFormatter.format(
+                        "SAML 2 Attribute Query profile is not configured for relying party '{}'", requestContext
+                                .getInboundMessage());
                 requestContext.setFailureStatus(buildStatus(StatusCode.RESPONDER_URI, StatusCode.REQUEST_DENIED_URI,
-                        "SAML 2 Attribute Query profile is not configured for relying party "
-                                + requestContext.getInboundMessageIssuer()));
+                        msg));
+                log.warn(msg);
                 samlResponse = buildErrorResponse(requestContext);
             } else {
                 checkSamlVersion(requestContext);
@@ -137,7 +139,7 @@ public class AttributeQueryProfileHandler extends AbstractSAML2ProfileHandler {
      */
     protected void decodeRequest(AttributeQueryContext requestContext, HTTPInTransport inTransport,
             HTTPOutTransport outTransport) throws ProfileException {
-        log.debug("Decoding message with decoder binding {}", getInboundBinding());
+        log.debug("Decoding message with decoder binding '{}'", getInboundBinding());
 
         requestContext.setCommunicationProfileId(getProfileId());
 
@@ -156,24 +158,25 @@ public class AttributeQueryProfileHandler extends AbstractSAML2ProfileHandler {
             SAMLMessageDecoder decoder = getMessageDecoders().get(getInboundBinding());
             requestContext.setMessageDecoder(decoder);
             decoder.decode(requestContext);
-            log.debug("Decoded request");
+            log.debug("Decoded request from relying party '{}'", requestContext.getInboundMessage());
 
             if (!(requestContext.getInboundSAMLMessage() instanceof AttributeQuery)) {
-                log.error("Incoming message was not a AttributeQuery, it was a {}", requestContext
+                log.warn("Incoming message was not a AttributeQuery, it was a {}", requestContext
                         .getInboundSAMLMessage().getClass().getName());
                 requestContext.setFailureStatus(buildStatus(StatusCode.REQUESTER_URI, null,
                         "Invalid SAML AttributeQuery message."));
                 throw new ProfileException("Invalid SAML AttributeQuery message.");
             }
         } catch (MessageDecodingException e) {
-            log.error("Error decoding attribute query message", e);
-            requestContext.setFailureStatus(buildStatus(StatusCode.RESPONDER_URI, null, "Error decoding message"));
-            throw new ProfileException("Error decoding attribute query message");
+            String msg = "Error decoding attribute query message";
+            log.warn(msg, e);
+            requestContext.setFailureStatus(buildStatus(StatusCode.RESPONDER_URI, null, msg));
+            throw new ProfileException(msg);
         } catch (SecurityException e) {
-            log.error("Message did not meet security requirements", e);
-            requestContext.setFailureStatus(buildStatus(StatusCode.RESPONDER_URI, StatusCode.REQUEST_DENIED_URI,
-                    "Message did not meet security requirements"));
-            throw new ProfileException("Message did not meet security requirements", e);
+            String msg = "Message did not meet security requirements";
+            log.warn(msg, e);
+            requestContext.setFailureStatus(buildStatus(StatusCode.RESPONDER_URI, StatusCode.REQUEST_DENIED_URI, msg));
+            throw new ProfileException(msg, e);
         } finally {
             // Set as much information as can be retrieved from the decoded message
             populateRequestContext(requestContext);
@@ -221,10 +224,11 @@ public class AttributeQueryProfileHandler extends AbstractSAML2ProfileHandler {
         if (query != null) {
             Subject subject = query.getSubject();
             if (subject == null) {
-                log.error("Attribute query did not contain a proper subject");
+                String msg = "Attribute query did not contain a proper subject";
+                log.warn(msg);
                 ((AttributeQueryContext) requestContext).setFailureStatus(buildStatus(StatusCode.REQUESTER_URI, null,
-                        "Attribute query did not contain a proper subject"));
-                throw new ProfileException("Attribute query did not contain a proper subject");
+                        msg));
+                throw new ProfileException(msg);
             }
             requestContext.setSubjectNameIdentifier(subject.getNameID());
         }
index 4e02ac8..6073628 100644 (file)
@@ -23,8 +23,6 @@ import java.util.ArrayList;
 import javax.servlet.RequestDispatcher;
 import javax.servlet.ServletException;
 import javax.servlet.http.HttpServletRequest;
-import javax.xml.parsers.DocumentBuilder;
-import javax.xml.parsers.DocumentBuilderFactory;
 
 import org.joda.time.DateTime;
 import org.joda.time.DateTimeZone;
@@ -62,8 +60,8 @@ import org.opensaml.xml.security.SecurityException;
 import org.opensaml.xml.util.DatatypeHelper;
 import org.slf4j.Logger;
 import org.slf4j.LoggerFactory;
+import org.slf4j.helpers.MessageFormatter;
 import org.w3c.dom.Element;
-import org.xml.sax.InputSource;
 
 import edu.internet2.middleware.shibboleth.common.profile.ProfileException;
 import edu.internet2.middleware.shibboleth.common.profile.provider.BaseSAMLProfileRequestContext;
@@ -75,7 +73,6 @@ import edu.internet2.middleware.shibboleth.common.util.HttpHelper;
 import edu.internet2.middleware.shibboleth.idp.authn.LoginContext;
 import edu.internet2.middleware.shibboleth.idp.authn.PassiveAuthenticationException;
 import edu.internet2.middleware.shibboleth.idp.authn.Saml2LoginContext;
-import edu.internet2.middleware.shibboleth.idp.profile.saml1.ShibbolethSSOProfileHandler.ShibbolethSSORequestContext;
 import edu.internet2.middleware.shibboleth.idp.session.Session;
 
 /** SAML 2.0 SSO request profile handler. */
@@ -171,10 +168,9 @@ public class SSOProfileHandler extends AbstractSAML2ProfileHandler {
             RelyingPartyConfiguration rpConfig = getRelyingPartyConfiguration(relyingPartyId);
             ProfileConfiguration ssoConfig = rpConfig.getProfileConfiguration(SSOConfiguration.PROFILE_ID);
             if (ssoConfig == null) {
-                log.error("SAML 2 SSO profile is not configured for relying party "
-                        + requestContext.getInboundMessageIssuer());
-                throw new ProfileException("SAML 2 SSO profile is not configured for relying party "
-                        + requestContext.getInboundMessageIssuer());
+                String msg = MessageFormatter.format("SAML 2 SSO profile is not configured for relying party '{}'", requestContext.getInboundMessageIssuer());
+                log.warn(msg);
+                throw new ProfileException(msg);
             }
 
             log.debug("Creating login context and transferring control to authentication engine");
@@ -241,7 +237,7 @@ public class SSOProfileHandler extends AbstractSAML2ProfileHandler {
                 String requestedPrincipalName = requestContext.getPrincipalName();
                 if (!DatatypeHelper.safeEquals(loginContext.getPrincipalName(), requestedPrincipalName)) {
                     log
-                            .error(
+                            .warn(
                                     "Authentication request identified principal {} but authentication mechanism identified principal {}",
                                     requestedPrincipalName, loginContext.getPrincipalName());
                     requestContext.setFailureStatus(buildStatus(StatusCode.RESPONDER_URI, StatusCode.AUTHN_FAILED_URI,
@@ -285,7 +281,7 @@ public class SSOProfileHandler extends AbstractSAML2ProfileHandler {
      */
     protected void decodeRequest(SSORequestContext requestContext, HTTPInTransport inTransport,
             HTTPOutTransport outTransport) throws ProfileException {
-        log.debug("Decoding message with decoder binding {}", getInboundBinding());
+        log.debug("Decoding message with decoder binding '{}'", getInboundBinding());
 
         requestContext.setCommunicationProfileId(getProfileId());
 
@@ -304,21 +300,23 @@ public class SSOProfileHandler extends AbstractSAML2ProfileHandler {
             SAMLMessageDecoder decoder = getMessageDecoders().get(getInboundBinding());
             requestContext.setMessageDecoder(decoder);
             decoder.decode(requestContext);
-            log.debug("Decoded request");
+            log.debug("Decoded request from relying party '{}'", requestContext.getInboundMessageIssuer());
 
             if (!(requestContext.getInboundMessage() instanceof AuthnRequest)) {
-                log.error("Incomming message was not a AuthnRequest, it was a {}", requestContext.getInboundMessage()
+                log.warn("Incomming message was not a AuthnRequest, it was a '{}'", requestContext.getInboundMessage()
                         .getClass().getName());
                 requestContext.setFailureStatus(buildStatus(StatusCode.REQUESTER_URI, null,
                         "Invalid SAML AuthnRequest message."));
                 throw new ProfileException("Invalid SAML AuthnRequest message.");
             }
         } catch (MessageDecodingException e) {
-            log.error("Error decoding authentication request message", e);
-            throw new ProfileException("Error decoding authentication request message", e);
+            String msg = "Error decoding authentication request message"; 
+            log.warn(msg, e);
+            throw new ProfileException(msg, e);
         } catch (SecurityException e) {
-            log.error("Message did not meet security requirements", e);
-            throw new ProfileException("Message did not meet security requirements", e);
+            String msg = "Message did not meet security requirements"; 
+            log.warn(msg, e);
+            throw new ProfileException(msg, e);
         }
     }
 
@@ -443,7 +441,7 @@ public class SSOProfileHandler extends AbstractSAML2ProfileHandler {
         long maxSPSessionLifetime = requestContext.getProfileConfiguration().getMaximumSPSessionLifetime();
         if (maxSPSessionLifetime > 0) {
             DateTime lifetime = new DateTime(DateTimeZone.UTC).plus(maxSPSessionLifetime);
-            log.debug("Explicitly setting SP session expiration time to {}", lifetime.toString());
+            log.debug("Explicitly setting SP session expiration time to '{}'", lifetime.toString());
             statement.setSessionNotOnOrAfter(lifetime);
         }
 
@@ -529,7 +527,7 @@ public class SSOProfileHandler extends AbstractSAML2ProfileHandler {
                 } else {
                     endpoint.setBinding(getSupportedOutboundBindings().get(0));
                 }
-                log.warn("Generating endpoint for anonymous relying party. ACS url {} and binding {}", new Object[] {
+                log.warn("Generating endpoint for anonymous relying party. ACS url '{}' and binding '{}'", new Object[] {
                         requestContext.getInboundMessageIssuer(), endpoint.getLocation(), endpoint.getBinding(), });
             } else {
                 log.warn("Unable to generate endpoint for anonymous party.  No ACS url provided.");