From af11cc50293f483c26415ddec6691157783be3fd Mon Sep 17 00:00:00 2001
From: Richard Millet <richard.millet@berkeley.edu>
Date: Thu, 12 Aug 2010 05:19:21 +0000
Subject: [PATCH] CSPACE-2587: Add a separate log file for service profiling
 information.  Also adding Laramie's filter class that we're using to profile
 requests to the service layer.

---
 .../src/main/webapp/WEB-INF/web.xml           | 205 +++++++++---------
 .../schemas/collectionobjects_common.xsd      |   1 +
 .../test/CollectionObjectServiceTest.java     |   6 +
 .../resources/collectionobjects_common.xsd    |   1 +
 .../CollectionObjectResource.java             |  21 +-
 .../src/main/config/log/jboss-log4j.xml       |   2 +-
 .../services/common/profile/CSpaceFilter.java |  84 +++++++
 .../services/common/profile/Profiler.java     |  23 +-
 .../common/security/SecurityInterceptor.java  |   4 +
 .../client/java/DocumentModelHandler.java     |   5 +
 .../client/java/RepositoryJavaClientImpl.java |   2 +-
 11 files changed, 239 insertions(+), 115 deletions(-)
 create mode 100644 services/common/src/main/java/org/collectionspace/services/common/profile/CSpaceFilter.java

diff --git a/services/JaxRsServiceProvider/src/main/webapp/WEB-INF/web.xml b/services/JaxRsServiceProvider/src/main/webapp/WEB-INF/web.xml
index 3ed461b9a..c1395cf26 100644
--- a/services/JaxRsServiceProvider/src/main/webapp/WEB-INF/web.xml
+++ b/services/JaxRsServiceProvider/src/main/webapp/WEB-INF/web.xml
@@ -1,98 +1,107 @@
-<?xml version="1.0" encoding="UTF-8"?>
-<!DOCTYPE web-app PUBLIC "-//Sun Microsystems, Inc.//DTD Web Application 2.3//EN" "http://java.sun.com/dtd/web-app_2_3.dtd">
-<!--
-    Document   : web.xml
-    Created on : May 19, 2009, 1:31 PM
-    Author     :
-    Copyright 2009 University of California at Berkeley
-    Description:
-        service layer web application
--->
-<web-app>
-    <display-name>CollectionSpace Services</display-name>
-    <env-entry>
-        <description>Sets the logging context for the Tiger web-app</description>
-        <env-entry-name>cspace-logging-context</env-entry-name>
-        <env-entry-value>CSpaceLoggingContext</env-entry-value>
-        <env-entry-type>java.lang.String</env-entry-type>
-    </env-entry>
-
-    <context-param>
-        <param-name>javax.ws.rs.Application</param-name>
-        <param-value>org.collectionspace.services.jaxrs.CollectionSpaceJaxRsApplication</param-value>
-    </context-param>
-
-    <context-param>
-        <param-name>resteasy.servlet.mapping.prefix</param-name>
-        <param-value>/</param-value>
-    </context-param>
-
-    <!--
-      - Location of the XML file that defines the root application context
-      - Applied by ContextLoaderListener.
-      -->
-    <context-param>
-        <param-name>contextConfigLocation</param-name>
-        <param-value>
-            /WEB-INF/applicationContext-security.xml
-        </param-value>
-    </context-param>
-
-    <filter>
-        <filter-name>springSecurityFilterChain</filter-name>
-        <filter-class>org.springframework.web.filter.DelegatingFilterProxy</filter-class>
-    </filter>
-
-    <filter-mapping>
-        <filter-name>springSecurityFilterChain</filter-name>
-        <url-pattern>/*</url-pattern>
-    </filter-mapping>
-
-    <!-- Listeners -->
-
-    <!--
-      - Loads the root application context of this web app at startup.
-      - The application context is then available via
-      - WebApplicationContextUtils.getWebApplicationContext(servletContext).
-    -->
-    <listener>
-        <listener-class>org.springframework.web.context.ContextLoaderListener</listener-class>
-    </listener>
-
-    <!--
-      - Publishes events for session creation and destruction through the application
-      - context. Optional unless concurrent session control is being used.
-      -->
-    <listener>
-        <listener-class>org.springframework.security.web.session.HttpSessionEventPublisher</listener-class>
-    </listener>
-
-    <!--listener>
-        <listener-class>org.springframework.web.util.Log4jConfigListener</listener-class>
-    </listener-->
-
-    <listener>
-        <listener-class>
-            org.jboss.resteasy.plugins.server.servlet.ResteasyBootstrap
-        </listener-class>
-    </listener>
-
-    <listener>
-        <listener-class>
-            org.collectionspace.services.common.CollectionSpaceServiceContextListener
-        </listener-class>
-    </listener>
-
-    <servlet>
-        <servlet-name>Resteasy</servlet-name>
-        <servlet-class>
-            org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher
-        </servlet-class>
-    </servlet>
-
-    <servlet-mapping>
-        <servlet-name>Resteasy</servlet-name>
-        <url-pattern>/*</url-pattern>
-    </servlet-mapping>
-
-</web-app>
+<?xml version="1.0" encoding="UTF-8"?>
+<!DOCTYPE web-app PUBLIC "-//Sun Microsystems, Inc.//DTD Web Application 2.3//EN" "http://java.sun.com/dtd/web-app_2_3.dtd">
+<!--
+    Document   : web.xml
+    Created on : May 19, 2009, 1:31 PM
+    Author     :
+    Copyright 2009 University of California at Berkeley
+    Description:
+        service layer web application
+-->
+<web-app>
+    <display-name>CollectionSpace Services</display-name>
+    <env-entry>
+        <description>Sets the logging context for the Tiger web-app</description>
+        <env-entry-name>cspace-logging-context</env-entry-name>
+        <env-entry-value>CSpaceLoggingContext</env-entry-value>
+        <env-entry-type>java.lang.String</env-entry-type>
+    </env-entry>
+
+    <context-param>
+        <param-name>javax.ws.rs.Application</param-name>
+        <param-value>org.collectionspace.services.jaxrs.CollectionSpaceJaxRsApplication</param-value>
+    </context-param>
+
+    <context-param>
+        <param-name>resteasy.servlet.mapping.prefix</param-name>
+        <param-value>/</param-value>
+    </context-param>
+
+    <!--
+      - Location of the XML file that defines the root application context
+      - Applied by ContextLoaderListener.
+      -->
+    <context-param>
+        <param-name>contextConfigLocation</param-name>
+        <param-value>
+            /WEB-INF/applicationContext-security.xml
+        </param-value>
+    </context-param>
+
+    <filter>
+        <filter-name>springSecurityFilterChain</filter-name>
+        <filter-class>org.springframework.web.filter.DelegatingFilterProxy</filter-class>
+    </filter>
+
+    <filter>
+		<filter-name>CSpaceFilter</filter-name>
+        <filter-class>org.collectionspace.services.common.profile.CSpaceFilter</filter-class>
+	</filter>
+	<filter-mapping>
+		<filter-name>CSpaceFilter</filter-name>
+		<url-pattern>/*</url-pattern>
+	</filter-mapping>
+    
+    <filter-mapping>
+        <filter-name>springSecurityFilterChain</filter-name>
+        <url-pattern>/*</url-pattern>
+    </filter-mapping>
+
+    <!-- Listeners -->
+
+    <!--
+      - Loads the root application context of this web app at startup.
+      - The application context is then available via
+      - WebApplicationContextUtils.getWebApplicationContext(servletContext).
+    -->
+    <listener>
+        <listener-class>org.springframework.web.context.ContextLoaderListener</listener-class>
+    </listener>
+
+    <!--
+      - Publishes events for session creation and destruction through the application
+      - context. Optional unless concurrent session control is being used.
+      -->
+    <listener>
+        <listener-class>org.springframework.security.web.session.HttpSessionEventPublisher</listener-class>
+    </listener>
+
+    <!--listener>
+        <listener-class>org.springframework.web.util.Log4jConfigListener</listener-class>
+    </listener-->
+
+    <listener>
+        <listener-class>
+            org.jboss.resteasy.plugins.server.servlet.ResteasyBootstrap
+        </listener-class>
+    </listener>
+
+    <listener>
+        <listener-class>
+            org.collectionspace.services.common.CollectionSpaceServiceContextListener
+        </listener-class>
+    </listener>
+
+    <servlet>
+            <servlet-name>Resteasy</servlet-name>
+            <servlet-class>
+                org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher
+            </servlet-class>
+    </servlet>
+    
+    <servlet-mapping>
+        <servlet-name>Resteasy</servlet-name>
+        <url-pattern>/*</url-pattern>
+    </servlet-mapping>
+
+</web-app>
diff --git a/services/collectionobject/3rdparty/nuxeo-platform-cs-collectionobject/src/main/resources/schemas/collectionobjects_common.xsd b/services/collectionobject/3rdparty/nuxeo-platform-cs-collectionobject/src/main/resources/schemas/collectionobjects_common.xsd
index 3c3319578..bd3efb565 100644
--- a/services/collectionobject/3rdparty/nuxeo-platform-cs-collectionobject/src/main/resources/schemas/collectionobjects_common.xsd
+++ b/services/collectionobject/3rdparty/nuxeo-platform-cs-collectionobject/src/main/resources/schemas/collectionobjects_common.xsd
@@ -17,6 +17,7 @@
     xmlns="http://collectionspace.org/collectionobject/"
     targetNamespace="http://collectionspace.org/collectionobject/" version="0.1">
 
+    <xs:element name="remNumber" type="ns:otherNumber"/>
     <!-- Object identification information -->
     <xs:element name="objectNumber" type="xs:string"/>
     <xs:element name="otherNumberList" type="ns:otherNumberList"/>
diff --git a/services/collectionobject/client/src/test/java/org/collectionspace/services/client/test/CollectionObjectServiceTest.java b/services/collectionobject/client/src/test/java/org/collectionspace/services/client/test/CollectionObjectServiceTest.java
index 30beb96ca..392eed3cd 100644
--- a/services/collectionobject/client/src/test/java/org/collectionspace/services/client/test/CollectionObjectServiceTest.java
+++ b/services/collectionobject/client/src/test/java/org/collectionspace/services/client/test/CollectionObjectServiceTest.java
@@ -1122,6 +1122,12 @@ public class CollectionObjectServiceTest extends AbstractServiceTestImpl {
             String objectNumber, String objectName) {
         CollectionobjectsCommon collectionObject = new CollectionobjectsCommon();
 
+        //REM
+        OtherNumber remNumber = new OtherNumber();
+        remNumber.setNumberType("remNumber");
+        remNumber.setNumberValue("2271966-" + System.currentTimeMillis());
+        collectionObject.setRemNumber(remNumber);
+        
         BriefDescriptionList descriptionList = new BriefDescriptionList();
         List<String> descriptions = descriptionList.getBriefDescription();
         descriptions.add("Papier mache bird cow mask with horns, "
diff --git a/services/collectionobject/jaxb/src/main/resources/collectionobjects_common.xsd b/services/collectionobject/jaxb/src/main/resources/collectionobjects_common.xsd
index 306361991..9ebf9ba1d 100644
--- a/services/collectionobject/jaxb/src/main/resources/collectionobjects_common.xsd
+++ b/services/collectionobject/jaxb/src/main/resources/collectionobjects_common.xsd
@@ -32,6 +32,7 @@
             <xs:sequence>
                 <xs:element name="csid" type="xs:string"/>
                 
+                <xs:element name="remNumber" type="ns:otherNumber"/>
                 <!-- Object Identification Information -->
                 <xs:element name="objectNumber" type="xs:string"/>
                 <xs:element name="otherNumberList" type="otherNumberList"/>
diff --git a/services/collectionobject/service/src/main/java/org/collectionspace/services/collectionobject/CollectionObjectResource.java b/services/collectionobject/service/src/main/java/org/collectionspace/services/collectionobject/CollectionObjectResource.java
index 5b9b31bf8..553449cab 100644
--- a/services/collectionobject/service/src/main/java/org/collectionspace/services/collectionobject/CollectionObjectResource.java
+++ b/services/collectionobject/service/src/main/java/org/collectionspace/services/collectionobject/CollectionObjectResource.java
@@ -69,10 +69,14 @@ import org.collectionspace.services.nuxeo.client.java.DocumentModelHandler;
 import org.collectionspace.services.relation.NewRelationResource;
 import org.collectionspace.services.relation.RelationsCommonList;
 import org.collectionspace.services.relation.RelationshipType;
+import org.collectionspace.services.common.profile.Profiler;
+
 import org.jboss.resteasy.plugins.providers.multipart.MultipartInput;
 import org.jboss.resteasy.plugins.providers.multipart.MultipartOutput;
 import org.jboss.resteasy.util.HttpResponseCodes;
+
 import org.nuxeo.ecm.core.api.DocumentModel;
+
 import org.slf4j.Logger;
 import org.slf4j.LoggerFactory;
 
@@ -254,6 +258,9 @@ public class CollectionObjectResource
      */
     private CollectionobjectsCommonList getCollectionObjectList(MultivaluedMap<String, String> queryParams) {
         CollectionobjectsCommonList collectionObjectList;
+        Profiler profiler = new Profiler(this, 1);
+        profiler.start();
+        
         try {
             ServiceContext<MultipartInput, MultipartOutput> ctx = createServiceContext(queryParams);
             DocumentHandler handler = createDocumentHandler(ctx);
@@ -271,6 +278,8 @@ public class CollectionObjectResource
                     Response.Status.INTERNAL_SERVER_ERROR).entity("Index failed").type("text/plain").build();
             throw new WebApplicationException(response);
         }
+        
+        profiler.stop();
         return collectionObjectList;
     }
 
@@ -475,21 +484,17 @@ public class CollectionObjectResource
      * 
      * This is an intentionally empty method used for getting a rough time estimate
      * of the overhead required for a client->server request/response cycle.
+     * @param ms - milliseconds to delay
      * 
      * @return the response
      */
     @GET
-    @Path("/roundtrip")
+    @Path("/{ms}/roundtrip")
     @Produces("application/xml")
-    public Response roundtrip() {
+    public Response roundtrip(
+    		@PathParam("ms") String ms) {
     	Response result = null;
     	
-		if (logger.isDebugEnabled()) {
-			logger.debug("------------------------------------------------------------------------------");
-			logger.debug("Client to server roundtrip called.");
-			logger.debug("------------------------------------------------------------------------------");
-			logger.debug("");
-		}
 		result = Response.status(HttpResponseCodes.SC_OK).build();
 		
 		return result;
diff --git a/services/common/src/main/config/log/jboss-log4j.xml b/services/common/src/main/config/log/jboss-log4j.xml
index 46e979dfe..c765e2831 100644
--- a/services/common/src/main/config/log/jboss-log4j.xml
+++ b/services/common/src/main/config/log/jboss-log4j.xml
@@ -158,7 +158,7 @@
      <param name="DatePattern" value="'.'yyyy-MM-dd"/>
       <param name="File" value="${jboss.server.log.dir}/collectionspace-perf.log"/>
       <layout class="org.apache.log4j.PatternLayout">
-         <param name="ConversionPattern" value="%d %-5p [%t] [%c:%L] %m%n"/>
+         <param name="ConversionPattern" value="%d [%t] %m%n"/>
       </layout>
             <!--filter class="org.jboss.logging.filter.TCLFilter">
          <param name="AcceptOnMatch" value="true"/>
diff --git a/services/common/src/main/java/org/collectionspace/services/common/profile/CSpaceFilter.java b/services/common/src/main/java/org/collectionspace/services/common/profile/CSpaceFilter.java
new file mode 100644
index 000000000..fa7b6004f
--- /dev/null
+++ b/services/common/src/main/java/org/collectionspace/services/common/profile/CSpaceFilter.java
@@ -0,0 +1,84 @@
+/**	
+ * CSpaceFilter.java
+ *
+ * {Purpose of This Class}
+ *
+ * {Other Notes Relating to This Class (Optional)}
+ *
+ * $LastChangedBy: $
+ * $LastChangedRevision: $
+ * $LastChangedDate: $
+ *
+ * This document is a part of the source code and related artifacts
+ * for CollectionSpace, an open source collections management system
+ * for museums and related institutions:
+ *
+ * http://www.collectionspace.org
+ * http://wiki.collectionspace.org
+ *
+ * Copyright © 2009 {Contributing Institution}
+ *
+ * Licensed under the Educational Community License (ECL), Version 2.0.
+ * You may not use this file except in compliance with this License.
+ *
+ * You may obtain a copy of the ECL 2.0 License at
+ * https://source.collectionspace.org/collection-space/LICENSE.txt
+ */
+package org.collectionspace.services.common.profile;
+
+import java.io.IOException;
+import javax.servlet.Filter;
+import javax.servlet.FilterChain;
+import javax.servlet.FilterConfig;
+import javax.servlet.ServletException;
+import javax.servlet.ServletRequest;
+import javax.servlet.ServletResponse;
+import javax.servlet.http.HttpServletRequest;
+//import javax.servlet.ServletContext;
+
+/**
+ * The Class CSpaceFilter.
+ */
+public class CSpaceFilter implements Filter {
+	
+	/** The filter config. */
+	FilterConfig filterConfig = null;
+
+	/* (non-Javadoc)
+	 * @see javax.servlet.Filter#destroy()
+	 */
+	@Override
+	public void destroy() {
+		// Empty method.
+	}
+
+	/* (non-Javadoc)
+	 * @see javax.servlet.Filter#doFilter(javax.servlet.ServletRequest, javax.servlet.ServletResponse, javax.servlet.FilterChain)
+	 */
+	@Override
+	public void doFilter(ServletRequest request, ServletResponse response,
+			FilterChain chain) throws IOException, ServletException {		
+		if (request != null) {
+			HttpServletRequest httpRequest = (HttpServletRequest)request;
+			String uri = httpRequest.getRequestURI();
+			Profiler profiler = new Profiler(uri, 0);
+			profiler.start();
+			chain.doFilter(request, response);
+//			profiler.log(httpRequest.getRequestURI());
+			profiler.stop();
+		}
+	}
+
+	/* (non-Javadoc)
+	 * @see javax.servlet.Filter#init(javax.servlet.FilterConfig)
+	 */
+	@Override
+	public void init(FilterConfig theFilterConfig) throws ServletException {
+		filterConfig = theFilterConfig;
+		if (filterConfig != null) {
+			// We can initialize using the init-params here which we defined in
+			// web.xml)
+		}
+	}
+
+}
diff --git a/services/common/src/main/java/org/collectionspace/services/common/profile/Profiler.java b/services/common/src/main/java/org/collectionspace/services/common/profile/Profiler.java
index a628bf82e..1a85859cd 100644
--- a/services/common/src/main/java/org/collectionspace/services/common/profile/Profiler.java
+++ b/services/common/src/main/java/org/collectionspace/services/common/profile/Profiler.java
@@ -35,6 +35,8 @@ import org.slf4j.LoggerFactory;
  */
 public class Profiler {
 	
+	private int messageIndent = 0;
+	
 	/** The start time. */
 	private long startTime = 0;
 	
@@ -63,8 +65,14 @@ public class Profiler {
      *
      * @param theMessagePrefix the new message prefix
      */
-    protected void setMessagePrefix(String theMessagePrefix) {
-    	messagePrefix = theMessagePrefix + ":";
+    protected void setMessagePrefix(String theMessagePrefix, int indent) {
+    	StringBuffer stringBuffer = new StringBuffer();
+    	for (int i = 0; i < indent; i++) {
+    		stringBuffer.append('\t');
+    	}
+    	stringBuffer.append(theMessagePrefix);
+    	stringBuffer.append(':');
+    	messagePrefix = stringBuffer.toString();
     }
     
     protected StringBuffer getMessagePrefix() {
@@ -74,21 +82,23 @@ public class Profiler {
     /**
      * Instantiates a new profiler.
      * @param theObject 
+     * @param indent 
      *
      * @param theClass the the class
      */
-    public Profiler(Object theObject) {
+    public Profiler(Object theObject, int indent) {
     	if (theObject != null) {
-    		this.setMessagePrefix(theObject.getClass().getSimpleName());
+    		this.setMessagePrefix(theObject.getClass().getSimpleName(), indent);
     	}
     }
 	/**
 	 * Instantiates a new profiler.
 	 *
 	 * @param theMessagePrefix the the message prefix
+	 * @param indent 
 	 */
-	public Profiler(String theMessagePrefix) {
-		this.setMessagePrefix(theMessagePrefix);
+	public Profiler(String theMessagePrefix, int indent) {
+		this.setMessagePrefix(theMessagePrefix, indent);
 	}
 	
 	/*
@@ -149,7 +159,6 @@ public class Profiler {
 			message.append("<<<< Stopped <<<< [");
 			message.append(finalTime);
 			message.append("ms]");
-			message.append('\n');
 			getLogger().debug(message.toString());
 		}		
 	}
diff --git a/services/common/src/main/java/org/collectionspace/services/common/security/SecurityInterceptor.java b/services/common/src/main/java/org/collectionspace/services/common/security/SecurityInterceptor.java
index 5010db2ba..152e4af67 100644
--- a/services/common/src/main/java/org/collectionspace/services/common/security/SecurityInterceptor.java
+++ b/services/common/src/main/java/org/collectionspace/services/common/security/SecurityInterceptor.java
@@ -160,6 +160,10 @@ public class SecurityInterceptor implements PreProcessInterceptor {
 		for (String pathParamName : pathParams.keySet()) {
 			//assumption : path params for csid for any entity has substring csid in name
 			String pathParamValue = pathParams.get(pathParamName).get(0);
+			if ((pathParamName.toLowerCase().indexOf("ms") > -1)) {
+				//replace csids with wildcard
+				uriPath = uriPath.replace(pathParamValue, "*");
+			}
 			if ((pathParamName.toLowerCase().indexOf("csid") > -1)) {
 				//replace csids with wildcard
 				uriPath = uriPath.replace(pathParamValue, "*");
diff --git a/services/common/src/main/java/org/collectionspace/services/nuxeo/client/java/DocumentModelHandler.java b/services/common/src/main/java/org/collectionspace/services/nuxeo/client/java/DocumentModelHandler.java
index a99dec859..e46e751c3 100644
--- a/services/common/src/main/java/org/collectionspace/services/nuxeo/client/java/DocumentModelHandler.java
+++ b/services/common/src/main/java/org/collectionspace/services/nuxeo/client/java/DocumentModelHandler.java
@@ -32,6 +32,8 @@ import org.collectionspace.services.common.document.DocumentFilter;
 import org.collectionspace.services.common.document.DocumentWrapper;
 import org.collectionspace.services.common.document.DocumentHandler.Action;
 import org.collectionspace.services.nuxeo.client.*;
+import org.collectionspace.services.common.profile.Profiler;
+
 import org.nuxeo.ecm.core.api.DocumentModel;
 import org.nuxeo.ecm.core.api.DocumentModelList;
 import org.nuxeo.ecm.core.api.model.PropertyException;
@@ -98,7 +100,10 @@ public abstract class DocumentModelHandler<T, TL>
 
     @Override
     public void handleGetAll(DocumentWrapper<DocumentModelList> wrapDoc) throws Exception {
+    	Profiler profiler = new Profiler(this, 2);
+    	profiler.start();
         setCommonPartList(extractCommonPartList(wrapDoc));
+        profiler.stop();
     }
 
     @Override
diff --git a/services/common/src/main/java/org/collectionspace/services/nuxeo/client/java/RepositoryJavaClientImpl.java b/services/common/src/main/java/org/collectionspace/services/nuxeo/client/java/RepositoryJavaClientImpl.java
index 8e98d20fc..5509569b2 100644
--- a/services/common/src/main/java/org/collectionspace/services/nuxeo/client/java/RepositoryJavaClientImpl.java
+++ b/services/common/src/main/java/org/collectionspace/services/nuxeo/client/java/RepositoryJavaClientImpl.java
@@ -643,7 +643,7 @@ public class RepositoryJavaClientImpl implements RepositoryClient {
 
             // If we have limit and/or offset, then pass true to get totalSize
             // in returned DocumentModelList.
-        	Profiler profiler = new Profiler(this);
+        	Profiler profiler = new Profiler(this, 2);
         	profiler.log("Executing NXQL query: " + query.toString());
         	profiler.start();
             if ((queryContext.docFilter.getOffset() > 0) || (queryContext.docFilter.getPageSize() > 0)) {
-- 
2.47.3