VIVO-452 First cut at a LoggingRDFService.
This will add instrumentation to the queries against the RDFService. Developers may enable logging, and optionally may restrict output by class, and may enable stack trace info on logging output.
This commit is contained in:
j2blake
parent
754c8004ae
commit
3ba960e6ac
4 changed files with 361 additions and 1 deletions
|
|
@ -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,
|
||||
|
|
|
|||
|
|
@ -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<String> 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();
|
||||
}
|
||||
}
|
||||
|
|
@ -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);
|
||||
}
|
||||
|
||||
}
|
||||
|
|
@ -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<StackTraceElement> 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<StackTraceElement> list = new ArrayList<StackTraceElement>(
|
||||
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<StackTraceElement> list) {
|
||||
ListIterator<StackTraceElement> 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<StackTraceElement> list) {
|
||||
ListIterator<StackTraceElement> 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();
|
||||
}
|
||||
|
||||
}
|
||||
Loading…
Add table
Reference in a new issue