perfsonar development work

Author: rodriguez
Date: 2009-02-09 04:09:37 -0500 (Mon, 09 Feb 2009)
New Revision: 4951

Modified:
   
branches/simple-service-with-base2/src/main/java/org/perfsonar/service/authService/AttrServiceEngine.java
   
branches/simple-service-with-base2/src/main/java/org/perfsonar/service/authService/AuthNServiceEngine.java
   
branches/simple-service-with-base2/src/main/java/org/perfsonar/service/authService/AuthRServiceEngine.java
   
branches/simple-service-with-base2/src/main/java/org/perfsonar/service/authService/GenericServiceEngine.java
Log:
- Improved log information for the AS

Modified: 
branches/simple-service-with-base2/src/main/java/org/perfsonar/service/authService/AttrServiceEngine.java
===================================================================
--- 
branches/simple-service-with-base2/src/main/java/org/perfsonar/service/authService/AttrServiceEngine.java
   2009-02-06 14:37:49 UTC (rev 4950)
+++ 
branches/simple-service-with-base2/src/main/java/org/perfsonar/service/authService/AttrServiceEngine.java
   2009-02-09 09:09:37 UTC (rev 4951)
@@ -1,6 +1,5 @@
 package org.perfsonar.service.authService;
 
-import java.io.ByteArrayInputStream;
 import java.text.Format;
 import java.text.SimpleDateFormat;
 import java.util.Calendar;
@@ -10,8 +9,6 @@
 import java.util.UUID;
 
 import javax.xml.namespace.NamespaceContext;
-import javax.xml.parsers.DocumentBuilder;
-import javax.xml.parsers.DocumentBuilderFactory;
 import javax.xml.xpath.XPath;
 import javax.xml.xpath.XPathConstants;
 import javax.xml.xpath.XPathExpression;
@@ -145,6 +142,7 @@
                        }
                        subject = subject.trim();
                        String urnUser = 
getURNUser(serviceRequest.getMessageElement());
+                       logger.debug("AttrServiceEngine: urn user = 
"+urnUser);
                        if (!subject.equals(urnUser)) {
                                throw new 
PerfSONARException("error.attr.saml_subject","Subject ("+subject+") of the 
SAML assertion is not equals to the user's urn ("+urnUser+") included in the 
security token");
                        }
@@ -213,7 +211,7 @@
                        long end=instantDate.getTime()+max;
                        logger.debug("Period valid of the assertion: 
("+start+","+end+"). Now: "+nowts);
                        if (nowts<start||nowts>end) {
-                               logger.error("AttrAction: SAML assertion not 
valid. The IssueInstant is not accepted by the AS");
+                               logger.info("AttrAction: SAML assertion not 
valid. The IssueInstant is not accepted by the AS");
                                if (nowts<start) {
                                        throw new 
PerfSONARException("error.attr.issueinstant","SAML assertion not valid. The 
IssueInstant is not accepted by the AS as it was created after right now");
                                }

Modified: 
branches/simple-service-with-base2/src/main/java/org/perfsonar/service/authService/AuthNServiceEngine.java
===================================================================
--- 
branches/simple-service-with-base2/src/main/java/org/perfsonar/service/authService/AuthNServiceEngine.java
  2009-02-06 14:37:49 UTC (rev 4950)
+++ 
branches/simple-service-with-base2/src/main/java/org/perfsonar/service/authService/AuthNServiceEngine.java
  2009-02-09 09:09:37 UTC (rev 4951)
@@ -25,6 +25,7 @@
 
     public void takeAction(ServiceMessage serviceRequest, ServiceMessage 
serviceResponse)
                        throws PerfSONARException {
+        logger.debug("AuthNServiceEngine: New message just arrived");
         //extract message
         Message request = serviceRequest.getMessageElement();
 

Modified: 
branches/simple-service-with-base2/src/main/java/org/perfsonar/service/authService/AuthRServiceEngine.java
===================================================================
--- 
branches/simple-service-with-base2/src/main/java/org/perfsonar/service/authService/AuthRServiceEngine.java
  2009-02-06 14:37:49 UTC (rev 4950)
+++ 
branches/simple-service-with-base2/src/main/java/org/perfsonar/service/authService/AuthRServiceEngine.java
  2009-02-09 09:09:37 UTC (rev 4951)
@@ -49,6 +49,8 @@
 
         XPathFactory xfactory = XPathFactory.newInstance();
                xpath = xfactory.newXPath();
+
+        logger.info("AuthR Service Engine started");
        }
 
        private void loadAuthRConfiguration() throws PerfSONARException {
@@ -60,7 +62,7 @@
                }
                else {
                        String m = "AuthRAction: Policy '"+policyFile+"' has 
not found!";
-                       logger.error(m);
+                       logger.fatal(m);
                        throw new 
PerfSONARException("error.authr.not_policy",m);
                }
                logger.debug("AuthRAction: Loading evaluator");
@@ -69,35 +71,34 @@
        }
 
        public void takeAction(ServiceMessage serviceRequest, ServiceMessage 
serviceResponse) throws PerfSONARException {
+        logger.debug("AuthRServiceEngine: New message just arrived");
         //extract message
         Message request = serviceRequest.getMessageElement();
 
         if (checkAuthNInformation(tsCrypto, request)) {
-               logger.info("Authentication data valid");
+               logger.info("AuthRServiceEngine: Authentication data valid");
                SimpleRequest authRRequest = 
getSimpleRequestFromMessage(request);
-               logger.info("AuthRAction: Received request: 
("+authRRequest.getSubject()+","+authRRequest.getResource()+","+authRRequest.getAction()+")");
+               logger.info("AuthRServiceEngine: Received request: 
("+authRRequest.getSubject()+","+authRRequest.getResource()+","+authRRequest.getAction()+")");
                SimpleResponse authRResponse = 
evaluator.evaluateRequest(authRRequest);
 
                if (authRResponse.getDecision()==SimpleResponse.PERMIT) {
-                       logger.debug("AuthRAction: Authorization response: 
PERMIT ("+authRResponse.getDecision()+")");
+                       logger.info("AuthRServiceEngine: Authorization 
response: PERMIT ("+authRResponse.getDecision()+")");
                        Message response = getValidAuthRMessage(request);
                        serviceResponse.setElement(response);
                }
                else if (authRResponse.getDecision()==SimpleResponse.DENY) {
-                       logger.debug("AuthRAction: Authorization response: 
DENY ("+authRResponse.getDecision()+")");
-                       String m = "AuthRAction: The authorization request 
has been denied";
-                       logger.info(m);
+                       logger.info("AuthRServiceEngine: Authorization 
response: DENY ("+authRResponse.getDecision()+")");
+                       String m = "AuthRServiceEngine: The authorization 
request has been denied";
                        throw new PerfSONARException("error.authr.denied",m);
                }
                else if 
(authRResponse.getDecision()==SimpleResponse.INDETERMINATE) {
-                       logger.debug("AuthRAction: Authorization response: 
INDETERMINATE ("+authRResponse.getDecision()+")");
-                       String m = "AuthRAction: The result of the 
authorization request is indeterminate";
-                       logger.info(m);
+                       logger.info("AuthRServiceEngine: Authorization 
response: INDETERMINATE ("+authRResponse.getDecision()+")");
+                       String m = "AuthRServiceEngine: The result of the 
authorization request is indeterminate";
                        throw new 
PerfSONARException("error.authr.indeterminate",m);
                }
                else {
-                       logger.debug("AuthRAction: Authorization response: 
NOT_APPLICABLE ("+authRResponse.getDecision()+")");
-                       String m = "AuthRAction: The authorization request is 
not applicable";
+                       logger.debug("AuthRServiceEngine: Authorization 
response: NOT_APPLICABLE ("+authRResponse.getDecision()+")");
+                       String m = "AuthRServiceEngine: The authorization 
request is not applicable";
                        logger.info(m);
                        throw new 
PerfSONARException("error.authr.not_applicable",m);
                }
@@ -119,7 +120,8 @@
                        nodes = (NodeList) expression.evaluate(doc, 
XPathConstants.NODESET);
                } catch (XPathExpressionException ex) {
                        ex.printStackTrace();
-                       String m = "AuthRAction: There is an error processing 
the request";
+                       String m = "AuthRServiceEngine: There is an error 
processing the request";
+                       logger.error(m);
                        throw new PerfSONARException("error.authr.subject", 
m, ex);
                }
                if (nodes!=null&&nodes.getLength()>0) {
@@ -134,7 +136,8 @@
                        return sr;
                } catch (PEPException ex) {
                        ex.printStackTrace();
-                       String m = "AuthRAction: There is an error processing 
the subject";
+                       String m = "AuthRServiceEngine: There is an error 
processing the subject";
+                       logger.error(m);
                        throw new PerfSONARException("error.authr.subject", 
m, ex);
                }
        }

Modified: 
branches/simple-service-with-base2/src/main/java/org/perfsonar/service/authService/GenericServiceEngine.java
===================================================================
--- 
branches/simple-service-with-base2/src/main/java/org/perfsonar/service/authService/GenericServiceEngine.java
        2009-02-06 14:37:49 UTC (rev 4950)
+++ 
branches/simple-service-with-base2/src/main/java/org/perfsonar/service/authService/GenericServiceEngine.java
        2009-02-09 09:09:37 UTC (rev 4951)
@@ -89,6 +89,7 @@
     }
 
        private void loadKeyStore() throws PerfSONARException {
+               logger.debug("GenericServiceEngine: loading truststore...");
         try {
                String truststoreFile = 
configuration.getExtensionOption("auth-engine", "service.as.truststore_file");
                String truststorePass = 
configuration.getExtensionOption("auth-engine", 
"service.as.truststore_password");
@@ -97,12 +98,14 @@
                tsCrypto=new DynamicCrypto(ks);
         } catch (Exception e) {
                e.printStackTrace();
+               logger.fatal("Error loading truststore...");
                throw new PerfSONARException("error.as.crypto",e);
         }
 
        }
 
        private void loadConfiguration() throws PerfSONARException {
+               logger.debug("GenericServiceEngine: loading 
configuration...");
                props=new Properties();
                String 
maxTtlToken=configuration.getExtensionOption("auth-engine", 
"service.as.maxttl");
                if (maxTtlToken!=null) {
@@ -184,13 +187,11 @@
             for (Element params : requestMetadata.getChildren("parameters")) 
{
                 for (Element p :  params.getChildren("parameter")) {
                        String nameAttr = p.getAttribute("name");
-                       logger.debug("Param: "+nameAttr);
                        if (nameAttr.equals(parameterName)) {
                                String parameterValue = p.getText().trim();
                                if 
(parameterValue==null||parameterValue.equals("")) {
                                        parameterValue = 
p.getAttribute("value");
                                }
-                       logger.debug("ParamValue: "+parameterValue);
                         return parameterValue; //if key has keyId and
                        }
                 }
@@ -208,7 +209,7 @@
                else {
                        Metadata 
metadata=getFirstMetadataFromRequest(request);
                        String 
sentSecToken=getParameterFromKey(metadata,SEC_TOKEN_PARAM);
-                       logger.info("Security Token: "+sentSecToken);
+                       logger.debug("GenericServiceEngine: sent Security 
Token "+sentSecToken);
                        if (sentSecToken!=null&&
                                        sentSecToken!=null&&
                                        
sentSecToken.equals(GenericServiceEngine.X509_ID)) {
@@ -244,7 +245,7 @@
                } finally {
                        if (doc == null) {
                                String m = "GenericServiceEngine: Cannot 
process the Security Token";
-                               logger.error(m);
+                               logger.info(m);
                                throw new 
PerfSONARException("error.authn.not_sectoken",m);
                        }
                }
@@ -285,7 +286,7 @@
                        } finally {
                                if (doc == null) {
                                        String m = "GenericServiceEngine: 
Cannot process the Security Token";
-                                       logger.error(m);
+                                       logger.info(m);
                                        throw new 
PerfSONARException("error.authn.not_sectoken",m);
                                }
                        }
@@ -319,23 +320,24 @@
                                                        end = date.getTime();
                                                }
                                                if 
(now.before(start)||now.after(end)) {
-                                                       
logger.error("GenericServiceEngine: security token not valid. The token was 
created before or after right now");
-                                                       
logger.error("GenericServiceEngine: **** Security token ("+start+","+end+") 
vs now ("+now.getTimeInMillis()+")");
+                                                       
logger.debug("GenericServiceEngine: Security token ("+start+","+end+") vs now 
("+now.getTimeInMillis()+")");
                                                        if 
(now.before(start)) {
+                                                               
logger.info("GenericServiceEngine: Security token not valid. The token was 
created after right now");
                                                                throw new 
PerfSONARException("error.authn.timestamp","Security token not valid. The 
token was created after right now");
                                                        }
                                                        else {
+                                                               
logger.info("GenericServiceEngine: Security token not valid. The token was 
expired before right now");
                                                                throw new 
PerfSONARException("error.authn.timestamp","Security token not valid. The 
token was expired before right now");
                                                        }
                                                }
                                                if ((end-start)>max) {
-                                                       
logger.error("GenericServiceEngine: security token not valid. The valid 
period of time of the token is too long. Max allowed is "+max);
+                                                       
logger.info("GenericServiceEngine: security token not valid. The valid period 
of time of the token is too long. Max allowed is "+max);
                                                        throw new 
PerfSONARException("error.authn.timestamp","The valid period of time of the 
token is too long. Max allowed is "+max);
                                                }
                                        }
                                }
                                if (found==false) {
-                                       logger.error("GenericServiceEngine: 
security token not valid. It's not included the timestamp information");
+                                       logger.info("GenericServiceEngine: 
security token not valid. It's not included the timestamp information");
                                        throw new 
PerfSONARException("error.authn.timestamp","AuthNAction: It's not included 
the timestamp information");
                                }
                        } catch (PerfSONARException e) {
@@ -359,11 +361,13 @@
                SOAPHeaderBlock shb = (SOAPHeaderBlock) list.get(0);
                        String actor=shb.getAttribute(new QName(SOAPENV_NS, 
WSSECHEADER_ACTOR)).getAttributeValue();
                        Vector result = secEngine.processSecurityHeader(doc, 
actor, null, crypto);
-
-                       logger.info("GenericServiceEngine: result= 
'"+(result!=null)+"'");
                        if (result==null) {
+                               logger.info("GenericServiceEngine: Signature 
not valid");
                                throw new 
PerfSONARException("error.authn.wssec","Null response checking the 
signature");
                        }
+                       else {
+                               logger.info("GenericServiceEngine: Signature 
valid");
+                       }
                } catch (PerfSONARException e) {
                        e.printStackTrace();
                        String m = "Null response checking the signature";
@@ -409,12 +413,12 @@
                                        logger.info("GenericServiceEngine: 
the issuer '"+issuer+"' has sent an authN statement about 
'"+subject.getNameIdentifier().getName()+"'");
                                }
                        }
-                       logger.info("GenericServiceEngine: Validating SAML 
assertion");
+                       logger.debug("GenericServiceEngine: Validating SAML 
assertion");
                        val.validate(assertion);
                } catch (Throwable e) {
                        e.printStackTrace();
                        String m = "GenericServiceEngine: the SAML assertion 
is not valid";
-                       logger.info(m);
+                       logger.error(m);
                        throw new 
PerfSONARException("error.authn.assertion_not_valid",m,e);
                }
                logger.info("GenericServiceEngine: the SAML assertion is 
valid");
@@ -460,12 +464,11 @@
                st.setSecTokenFromRequest();
                        Metadata 
metadata=getFirstMetadataFromRequest(request);
                        String 
sentSecToken=getParameterFromKey(metadata,SEC_TOKEN_PARAM);
-                       logger.info("Security Token: "+sentSecToken);
                        if (sentSecToken!=null&&
                                        sentSecToken!=null&&
                                        
sentSecToken.equals(GenericServiceEngine.X509_ID)) {
                                X509Certificate 
cert=(X509Certificate)st.getSecTokenValue();
-                               logger.info("AttrRequest signed by 
"+cert.getSubjectDN().getName()+" issued by "+cert.getIssuerDN().getName());
+//                             logger.info("AttrRequest signed by 
"+cert.getSubjectDN().getName()+" issued by "+cert.getIssuerDN().getName());
                                try {
                            Collection subjectAltNames = 
cert.getSubjectAlternativeNames();
                            if (subjectAltNames != null) {
@@ -477,6 +480,7 @@
                                        String name = (String)values.get(1);
                                        if ((type == 6) && 
(name.startsWith(BaseDefinitions.EDUGAIN_CID_RESOLVER))) {
                                            String componentName = 
URLDecoder.decode(name.substring(name.indexOf('=')+1),"UTF-8");
+                                           
logger.debug("GenericServiceEngine: component ID = "+componentName);
                                            return componentName;
                                        }
                                    }
@@ -511,6 +515,7 @@
                                                                              
  if (statement2 instanceof SAMLAuthenticationStatement) {
                                                                              
          SAMLAuthenticationStatement 
authStatement2=(SAMLAuthenticationStatement)statement;
                                                                              
          String componentID = 
idpIssuer+":user:"+authStatement2.getSubject().getNameIdentifier().getName();
+                                                           
logger.debug("GenericServiceEngine: component ID = "+componentID);
                                                                              
          return componentID;
                                                                              
  }
                                                                        }
@@ -537,7 +542,7 @@
                String componentName = getURNUser(request);
         if (componentName.startsWith(PREFIX_GIDP_BE)) {
                String userdomain = 
componentName.substring(componentName.indexOf("-")+1);
-               logger.info("AttrAction: getDomainUser(\""+componentName+"\") 
= "+userdomain);
+               logger.debug("GenericServiceEngine: 
getDomainUser(\""+componentName+"\") = "+userdomain);
                return userdomain;
         }
         else if (componentName.startsWith(PREFIX_BE)) {
@@ -545,7 +550,7 @@
                if (userfed.indexOf(':')>0) {
                        userfed = userfed.substring(0,userfed.indexOf(':'));
                }
-               logger.info("AttrAction: getDomainUser(\""+componentName+"\") 
= "+userfed);
+               logger.debug("GenericServiceEngine: 
getDomainUser(\""+componentName+"\") = "+userfed);
                return userfed;
         }
         return "";