perfsonar development work

Author: michael.bischoff
Date: 2008-07-17 06:04:56 -0400 (Thu, 17 Jul 2008)
New Revision: 4226

Modified:
   
trunk/perfsonar_base/src/main/java/org/perfsonar/service/base/web/RequestHandler.java
Log:
multithreaded fix - had to exclude initialisation from timing to avoid 
clogging up the code. 
improved logging

Modified: 
trunk/perfsonar_base/src/main/java/org/perfsonar/service/base/web/RequestHandler.java
===================================================================
--- 
trunk/perfsonar_base/src/main/java/org/perfsonar/service/base/web/RequestHandler.java
       2008-07-17 09:50:50 UTC (rev 4225)
+++ 
trunk/perfsonar_base/src/main/java/org/perfsonar/service/base/web/RequestHandler.java
       2008-07-17 10:04:56 UTC (rev 4226)
@@ -43,10 +43,6 @@
        
        private volatile boolean initialised = false;
        private volatile Object initialisationMutex = new Object();
-
-    private String messageId = null;
-    private long t0 = 0;
-    private String messageType = null;    
     
     /**
      *  Accepts web service based calls and gives back responses
@@ -54,28 +50,14 @@
      *  @param request org.w3c.dom.Document which contains the XML request
      *
      *  @return org.w3c.dom.Document response provided by the service
-     *
-     *  @throws Exception If any fatal error occurred (but almost all errors
-     *          are being catched and converted to PerfSONAR result codes 
      */
     public Document acceptCall(Document request) {
-        
-        setTimeStamp();
-        
-        try {
-            
+       try {           
                if(!initialised) init();
                checkAuxiliaryComponents();
-            Document resp = handleCall(request); 
-            logExecutionTime();
-            return resp;
-            
-        } catch (PerfSONARException pex) {
-            
-            Document err = handleError(pex);  
-            logExecutionTime();
-            return err;
-            
+               return handleCall(request);            
+        } catch (PerfSONARException pex) {            
+               return handleError(pex);  
         }
     }
        /**
@@ -95,26 +77,34 @@
        /**
         * handles the call: convert the request and calls a 
handleRequestMessage and returns the result.
         * @param request
-        * @return
+        * @return a document
         * @throws PerfSONARException
         */
        protected Document handleCall(Document request) throws 
PerfSONARException {
-               logger.info("RequestHandler: Service received a request");
-               logger.debug("RequestHandler: Calling on parser to parse the 
request");
-                               
-               Message requestMessage = convertMessage(request);
-               checkMessage(requestMessage);
-        messageType  = requestMessage.getType();
-        messageId = requestMessage.getId();
+               long startTime = System.currentTimeMillis();
+               String messageType = null;
+        String messageId = null;
                
-               logger.debug("RequestHandler: Message object constructed from 
request. Request is of type: " + requestMessage.getType());
-               /* Check if it isn't just an InitService message */
-               if 
(INIT_SERVICE_MESSAGE_TYPE.equalsIgnoreCase(requestMessage.getType())) {
-                   return handleInitServiceMessage(requestMessage);          
          
-               }
-               
-               assertAuthentication(requestMessage);           
-               return handleRequestMessage(requestMessage);
+               try {
+                       logger.info("RequestHandler: Service received a 
request");
+                       logger.debug("RequestHandler: Calling on parser to 
parse the request");
+                                       
+                       Message requestMessage = convertMessage(request);
+                       checkMessage(requestMessage);
+               messageType = requestMessage.getType();
+               messageId = requestMessage.getId();
+                       
+                       logger.debug("RequestHandler: Message object 
constructed from request. Request is of type: " + requestMessage.getType());
+                       /* Check if it isn't just an InitService message */
+                       if 
(INIT_SERVICE_MESSAGE_TYPE.equalsIgnoreCase(requestMessage.getType())) {
+                           return handleInitServiceMessage(requestMessage);  
                  
+                       }
+                       
+                       assertAuthentication(requestMessage);           
+                       return handleRequestMessage(requestMessage);
+           } finally {
+               logExecutionTime(startTime , messageId, messageType);
+           }
        }       
        /**
         * Called when any error occurred, response with result/error code 
@@ -211,12 +201,13 @@
            try {
                
checkAuthNParam=configuration.getProperty(AuthNComponent.CHECK_AUTHN_PARAM);
            } catch (PerfSONARException e) {
-               checkAuthNParam=null;
+               /* ignore */
            }
                if 
(checkAuthNParam!=null&&checkAuthNParam.equals(AuthNComponent.YES_CHECK_AUTHN))
 {
                        logger.debug("RequestHandler: Authenticating the 
message");
                        if (authnComponent == null) {
                            authnComponent = 
(AuthNComponent)componentManager.getComponent(ComponentNames.AUTHN);
+                           if(authnComponent == null) 
logger.error("RequestHandler.assertAuthentication: authComponent wasn't 
loaded!");
                        }
                        authnComponent.requestAuthN(requestMessage.getType());
                } else {
@@ -271,21 +262,15 @@
     
     /**
      * Print out time of execution (to log)
+     * @param startTime 
+     * @param messageType 
+     * @param messageId 
      * 
      */
-    private void logExecutionTime() {
-
-        long t1 = System.currentTimeMillis();
-        logger.info("Execution Time of message type=["+messageType+
-                "] id=["+ messageId + "] is ["
-                + (t1 - t0) + "] milliseconds");
+    private void logExecutionTime(long startTime, String messageId, String 
messageType) {
+        long time = System.currentTimeMillis() - startTime;        
+        logger.info(String.format("Execution Time of message type=[%s] 
id=[%s] is [%3$tM]min [%3$tS]secs [%3$tL]milisec", messageType, 
messageId,Long.valueOf(time)));
     }    
-
-    /**
-     * Sets current time
-     */
-    private void setTimeStamp() {
-        t0 = System.currentTimeMillis();
-    }        
     
+    
 }