diff --git a/webapp/src/edu/cornell/mannlib/vitro/webapp/rdfservice/impl/RDFServiceUtils.java b/webapp/src/edu/cornell/mannlib/vitro/webapp/rdfservice/impl/RDFServiceUtils.java index 1f013e571..c71908418 100644 --- a/webapp/src/edu/cornell/mannlib/vitro/webapp/rdfservice/impl/RDFServiceUtils.java +++ b/webapp/src/edu/cornell/mannlib/vitro/webapp/rdfservice/impl/RDFServiceUtils.java @@ -23,6 +23,7 @@ import edu.cornell.mannlib.vitro.webapp.rdfservice.RDFService.ModelSerialization import edu.cornell.mannlib.vitro.webapp.rdfservice.RDFService.ResultFormat; import edu.cornell.mannlib.vitro.webapp.rdfservice.RDFServiceException; import edu.cornell.mannlib.vitro.webapp.rdfservice.RDFServiceFactory; +import edu.cornell.mannlib.vitro.webapp.rdfservice.impl.logging.LoggingRDFServiceFactory; public class RDFServiceUtils { @@ -34,7 +35,18 @@ public class RDFServiceUtils { public static RDFServiceFactory getRDFServiceFactory(ServletContext context) { Object o = context.getAttribute(RDFSERVICEFACTORY_ATTR); - return (o instanceof RDFServiceFactory) ? (RDFServiceFactory) o : null; + if (o instanceof RDFServiceFactory) { + RDFServiceFactory factory = (RDFServiceFactory) o; + + /* + * Every factory is wrapped in a logger, so we can dynamically + * enable or disable logging. + */ + return new LoggingRDFServiceFactory(context, factory); + } else { + log.error("Expecting an RDFServiceFactory on the context, but found " + o); + return null; + } } public static void setRDFServiceFactory(ServletContext context, diff --git a/webapp/src/edu/cornell/mannlib/vitro/webapp/rdfservice/impl/logging/LoggingRDFService.java b/webapp/src/edu/cornell/mannlib/vitro/webapp/rdfservice/impl/logging/LoggingRDFService.java new file mode 100644 index 000000000..78ccd8a41 --- /dev/null +++ b/webapp/src/edu/cornell/mannlib/vitro/webapp/rdfservice/impl/logging/LoggingRDFService.java @@ -0,0 +1,125 @@ +/* $This file is distributed under the terms of the license in /doc/license.txt$ */ + +package edu.cornell.mannlib.vitro.webapp.rdfservice.impl.logging; + +import java.io.InputStream; +import java.util.List; + +import javax.servlet.ServletContext; + +import edu.cornell.mannlib.vitro.webapp.rdfservice.ChangeListener; +import edu.cornell.mannlib.vitro.webapp.rdfservice.ChangeSet; +import edu.cornell.mannlib.vitro.webapp.rdfservice.RDFService; +import edu.cornell.mannlib.vitro.webapp.rdfservice.RDFServiceException; + +/** + * This RDFService wrapper adds instrumentation to the time-consuming methods of + * the inner RDFService. + * + * For the other methods, it just delegates to the inner RDFService. + */ +public class LoggingRDFService implements RDFService { + private final ServletContext ctx; + private final RDFService innerService; + + LoggingRDFService(ServletContext ctx, RDFService innerService) { + this.ctx = ctx; + this.innerService = innerService; + } + + // ---------------------------------------------------------------------- + // Timed methods + // ---------------------------------------------------------------------- + + @Override + public boolean changeSetUpdate(ChangeSet changeSet) + throws RDFServiceException { + try (RDFServiceLogger l = new RDFServiceLogger(ctx, changeSet)) { + return innerService.changeSetUpdate(changeSet); + } + } + + @Override + public InputStream sparqlConstructQuery(String query, + ModelSerializationFormat resultFormat) throws RDFServiceException { + try (RDFServiceLogger l = new RDFServiceLogger(ctx, resultFormat, query)) { + return innerService.sparqlConstructQuery(query, resultFormat); + } + } + + @Override + public InputStream sparqlDescribeQuery(String query, + ModelSerializationFormat resultFormat) throws RDFServiceException { + try (RDFServiceLogger l = new RDFServiceLogger(ctx, resultFormat, query)) { + return innerService.sparqlDescribeQuery(query, resultFormat); + } + } + + @Override + public InputStream sparqlSelectQuery(String query, ResultFormat resultFormat) + throws RDFServiceException { + try (RDFServiceLogger l = new RDFServiceLogger(ctx, resultFormat, query)) { + return innerService.sparqlSelectQuery(query, resultFormat); + } + } + + @Override + public boolean sparqlAskQuery(String query) throws RDFServiceException { + try (RDFServiceLogger l = new RDFServiceLogger(ctx, query)) { + return innerService.sparqlAskQuery(query); + } + } + + // ---------------------------------------------------------------------- + // Untimed methods + // ---------------------------------------------------------------------- + + @Override + public void newIndividual(String individualURI, String individualTypeURI) + throws RDFServiceException { + innerService.newIndividual(individualURI, individualTypeURI); + } + + @Override + public void newIndividual(String individualURI, String individualTypeURI, + String graphURI) throws RDFServiceException { + innerService.newIndividual(individualURI, individualTypeURI, graphURI); + } + + @Override + public List getGraphURIs() throws RDFServiceException { + return innerService.getGraphURIs(); + } + + @Override + public void getGraphMetadata() throws RDFServiceException { + innerService.getGraphMetadata(); + } + + @Override + public String getDefaultWriteGraphURI() throws RDFServiceException { + return innerService.getDefaultWriteGraphURI(); + } + + @Override + public void registerListener(ChangeListener changeListener) + throws RDFServiceException { + innerService.registerListener(changeListener); + } + + @Override + public void unregisterListener(ChangeListener changeListener) + throws RDFServiceException { + innerService.unregisterListener(changeListener); + } + + @Override + public ChangeSet manufactureChangeSet() { + return innerService.manufactureChangeSet(); + } + + @Override + public void close() { + innerService.close(); + } +} diff --git a/webapp/src/edu/cornell/mannlib/vitro/webapp/rdfservice/impl/logging/LoggingRDFServiceFactory.java b/webapp/src/edu/cornell/mannlib/vitro/webapp/rdfservice/impl/logging/LoggingRDFServiceFactory.java new file mode 100644 index 000000000..8e97346e4 --- /dev/null +++ b/webapp/src/edu/cornell/mannlib/vitro/webapp/rdfservice/impl/logging/LoggingRDFServiceFactory.java @@ -0,0 +1,48 @@ +/* $This file is distributed under the terms of the license in /doc/license.txt$ */ + +package edu.cornell.mannlib.vitro.webapp.rdfservice.impl.logging; + +import javax.servlet.ServletContext; + +import edu.cornell.mannlib.vitro.webapp.rdfservice.ChangeListener; +import edu.cornell.mannlib.vitro.webapp.rdfservice.RDFService; +import edu.cornell.mannlib.vitro.webapp.rdfservice.RDFServiceException; +import edu.cornell.mannlib.vitro.webapp.rdfservice.RDFServiceFactory; + +/** + * If the RDFServiceFactory is wrapped in this, then all RDFServices will be + * wrapped in a LoggingRDFService. + */ +public class LoggingRDFServiceFactory implements RDFServiceFactory { + private final ServletContext ctx; + private final RDFServiceFactory factory; + + public LoggingRDFServiceFactory(ServletContext ctx, + RDFServiceFactory factory) { + this.ctx = ctx; + this.factory = factory; + } + + @Override + public RDFService getRDFService() { + return new LoggingRDFService(ctx, factory.getRDFService()); + } + + @Override + public RDFService getShortTermRDFService() { + return new LoggingRDFService(ctx, factory.getShortTermRDFService()); + } + + @Override + public void registerListener(ChangeListener changeListener) + throws RDFServiceException { + factory.registerListener(changeListener); + } + + @Override + public void unregisterListener(ChangeListener changeListener) + throws RDFServiceException { + factory.unregisterListener(changeListener); + } + +} diff --git a/webapp/src/edu/cornell/mannlib/vitro/webapp/rdfservice/impl/logging/RDFServiceLogger.java b/webapp/src/edu/cornell/mannlib/vitro/webapp/rdfservice/impl/logging/RDFServiceLogger.java new file mode 100644 index 000000000..d529497c7 --- /dev/null +++ b/webapp/src/edu/cornell/mannlib/vitro/webapp/rdfservice/impl/logging/RDFServiceLogger.java @@ -0,0 +1,175 @@ +/* $This file is distributed under the terms of the license in /doc/license.txt$ */ + +package edu.cornell.mannlib.vitro.webapp.rdfservice.impl.logging; + +import java.util.ArrayList; +import java.util.Arrays; +import java.util.Collections; +import java.util.List; +import java.util.ListIterator; +import java.util.regex.Pattern; + +import javax.servlet.ServletContext; + +import org.apache.commons.lang.StringUtils; +import org.apache.commons.logging.Log; +import org.apache.commons.logging.LogFactory; + +import edu.cornell.mannlib.vitro.webapp.config.ConfigurationProperties; + +/** + * Writes the log message for the LoggingRDFService. + * + * If not enabled, or if the logging level is insufficient, this does nothing. + * + * If enabled, it checks for restrictions. If there is a restriction pattern + * (regular expression), the a log message will only be printed if one of the + * fully-qualified class names in the stack trace matches that pattern. + * + * If everything passes muster, the constructor will record the time that the + * instance was created. + * + * When close() is called, if a start time was recorded, then a log record is + * produced. This contains the elapsed time, the name of the method, and any + * arguments passed to the constructor. It may also include a stack trace, if + * requested. + * + * The stack trace is abbreviated. It will reach into this class, and will not + * extend past the first reference to the ApplicationFilterChain. Perhaps it + * should be abbreviated further? + */ +public class RDFServiceLogger implements AutoCloseable { + private static final Log log = LogFactory.getLog(RDFServiceLogger.class); + + private static final String PROPERTY_ENABLED = "developer.loggingRDFService.enable"; + private static final String PROPERTY_STACK_TRACE = "developer.loggingRDFService.stackTrace"; + private static final String PROPERTY_RESTRICTION = "developer.loggingRDFService.restriction"; + + private final ServletContext ctx; + private final Object[] args; + + private boolean isEnabled; + private boolean traceRequested; + private Pattern restriction; + + private String methodName; + private List trace = Collections.emptyList(); + + private long startTime; + + public RDFServiceLogger(ServletContext ctx, Object... args) { + this.ctx = ctx; + this.args = args; + + getProperties(); + + if (isEnabled && log.isInfoEnabled()) { + loadStackTrace(); + if (passesRestrictions()) { + this.startTime = System.currentTimeMillis(); + } + } + } + + private void getProperties() { + ConfigurationProperties props = ConfigurationProperties.getBean(ctx); + isEnabled = Boolean.valueOf(props.getProperty(PROPERTY_ENABLED)); + traceRequested = Boolean.valueOf(props + .getProperty(PROPERTY_STACK_TRACE)); + + String restrictionString = props.getProperty(PROPERTY_RESTRICTION); + if (StringUtils.isNotBlank(restrictionString)) { + try { + restriction = Pattern.compile(restrictionString); + } catch (Exception e) { + log.error("Failed to compile the pattern for " + + PROPERTY_RESTRICTION + " = " + restriction + " " + e); + isEnabled = false; + } + } + } + + private void loadStackTrace() { + StackTraceElement[] stack = Thread.currentThread().getStackTrace(); + List list = new ArrayList( + Arrays.asList(stack)); + + trimStackTraceAtBeginning(list); + trimStackTraceAtEnd(list); + + if (list.isEmpty()) { + this.methodName = "UNKNOWN"; + } else { + this.methodName = list.get(0).getMethodName(); + } + + this.trace = list; + } + + private void trimStackTraceAtBeginning(List list) { + ListIterator iter = list.listIterator(); + while (iter.hasNext()) { + StackTraceElement ste = iter.next(); + if (ste.getClassName().equals(LoggingRDFService.class.getName())) { + break; + } else { + iter.remove(); + } + } + } + + private void trimStackTraceAtEnd(List list) { + ListIterator iter = list.listIterator(); + boolean trimming = false; + while (iter.hasNext()) { + StackTraceElement ste = iter.next(); + if (trimming) { + iter.remove(); + } else if (ste.getClassName().contains("ApplicationFilterChain")) { + trimming = true; + } + } + } + + private boolean passesRestrictions() { + if (restriction == null) { + return true; + } + for (StackTraceElement ste : trace) { + if (restriction.matcher(ste.getClassName()).matches()) { + return true; + } + } + return false; + } + + @Override + public void close() { + if (startTime != 0L) { + long endTime = System.currentTimeMillis(); + + float elapsedSeconds = (endTime - startTime) / 1000.0F; + String cleanArgs = Arrays.deepToString(args).replaceAll( + "[\\n\\r\\t]+", " "); + String formattedTrace = formatStackTrace(); + + log.info(String.format("%8.3f %s %s %s", elapsedSeconds, + methodName, cleanArgs, formattedTrace)); + } + } + + private String formatStackTrace() { + StringBuilder sb = new StringBuilder(); + + if (traceRequested) { + for (StackTraceElement ste : trace) { + sb.append(String.format("\n %d %s", ste.getLineNumber(), + ste.getClassName())); + } + sb.append("\n ..."); + } + + return sb.toString(); + } + +}