/*
* Copyright (c) 2016 Red Hat, Inc. and others. All rights reserved.
*
* This program and the accompanying materials are made available under the
* terms of the Eclipse Public License v1.0 which accompanies this distribution,
* and is available at http://www.eclipse.org/legal/epl-v10.html
*/
package org.opendaylight.controller.md.sal.trace.dom.impl;
import java.io.PrintStream;
import java.util.ArrayList;
import java.util.HashMap;
import java.util.List;
import java.util.Map;
import java.util.Objects;
import java.util.Set;
import javax.annotation.Nonnull;
import org.opendaylight.controller.md.sal.common.api.data.AsyncDataBroker;
import org.opendaylight.controller.md.sal.common.api.data.LogicalDatastoreType;
import org.opendaylight.controller.md.sal.common.api.data.TransactionChainListener;
import org.opendaylight.controller.md.sal.dom.api.ClusteredDOMDataTreeChangeListener;
import org.opendaylight.controller.md.sal.dom.api.DOMDataBroker;
import org.opendaylight.controller.md.sal.dom.api.DOMDataBrokerExtension;
import org.opendaylight.controller.md.sal.dom.api.DOMDataChangeListener;
import org.opendaylight.controller.md.sal.dom.api.DOMDataReadOnlyTransaction;
import org.opendaylight.controller.md.sal.dom.api.DOMDataReadWriteTransaction;
import org.opendaylight.controller.md.sal.dom.api.DOMDataTreeChangeListener;
import org.opendaylight.controller.md.sal.dom.api.DOMDataTreeChangeService;
import org.opendaylight.controller.md.sal.dom.api.DOMDataTreeIdentifier;
import org.opendaylight.controller.md.sal.dom.api.DOMDataWriteTransaction;
import org.opendaylight.controller.md.sal.dom.api.DOMTransactionChain;
import org.opendaylight.controller.md.sal.trace.api.TracingDOMDataBroker;
import org.opendaylight.controller.md.sal.trace.closetracker.impl.CloseTracked;
import org.opendaylight.controller.md.sal.trace.closetracker.impl.CloseTrackedRegistry;
import org.opendaylight.controller.md.sal.trace.closetracker.impl.CloseTrackedRegistryReportEntry;
import org.opendaylight.mdsal.binding.dom.codec.api.BindingNormalizedNodeSerializer;
import org.opendaylight.yang.gen.v1.urn.opendaylight.params.xml.ns.yang.mdsaltrace.rev160908.Config;
import org.opendaylight.yangtools.concepts.ListenerRegistration;
import org.opendaylight.yangtools.yang.binding.DataObject;
import org.opendaylight.yangtools.yang.binding.InstanceIdentifier;
import org.opendaylight.yangtools.yang.data.api.YangInstanceIdentifier;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
@SuppressWarnings("checkstyle:JavadocStyle")
//...because otherwise it whines about the elements in the @code block even though it's completely valid Javadoc
/**
* TracingBroker logs "write" operations and listener registrations to the md-sal. It logs the instance identifier path,
* the objects themselves, as well as the stack trace of the call invoking the registration or write operation.
* It works by operating as a "bump on the stack" between the application and actual DataBroker, intercepting write
* and registration calls and writing to the log.
*
*
In addition, it (optionally) can also keep track of the stack trace of all new transaction allocations
* (including TransactionChains, and transactions created in turn from them), in order to detect and report leaks
* from transactions which were not closed.
*
*
Wiring:
* TracingBroker is designed to be easy to use. In fact, for bundles using Blueprint to inject their DataBroker
* TracingBroker can be used without modifying your code at all in two simple steps:
*
* -
* Simply add the dependency "mdsaltrace-features" to
* your Karaf pom:
*
* {@code
*
* org.opendaylight.controller
* features-mdsal-trace
* 1.7.0-SNAPSHOT
* features
* xml
* runtime
*
* }
*
*
* -
* Then just "feature:install odl-mdsal-trace" before you install your "real" feature(s) and you're done.
* Beware that with Karaf 4 due to Bug 9068
* you'll probably have to use feature:install's --no-auto-refresh flag when installing your "real" feature.
*
*
* This works because the mdsaltrace-impl bundle registers its service implementing DOMDataBroker with a higher
* rank than sal-binding-broker. As such, any OSGi service lookup for DataBroker will receive the TracingBroker.
*
* Avoiding log bloat:
* TracingBroker can be configured to only print registrations or write ops pertaining to certain subtrees of the
* md-sal. This can be done in the code via the methods of this class or via a config file. TracingBroker uses a more
* convenient but non-standard representation of the instance identifiers. Each instance identifier segment's
* class.getSimpleName() is used separated by a '/'.
*
* Known issues
*
* -
* Filtering by paths. For some registrations the codec that converts back from the DOM to binding paths is
* busted. As such, an aproximated path is used in the output. For now it is recommended not to use
* watchRegistrations and allow all registrations to be logged.
*
*
*
*/
public class TracingBroker implements TracingDOMDataBroker {
static final Logger LOG = LoggerFactory.getLogger(TracingBroker.class);
private static final int STACK_TRACE_FIRST_RELEVANT_FRAME = 2;
private final BindingNormalizedNodeSerializer codec;
private final DOMDataBroker delegate;
private final List registrationWatches = new ArrayList<>();
private final List writeWatches = new ArrayList<>();
private final boolean isDebugging;
private final CloseTrackedRegistry transactionChainsRegistry;
private final CloseTrackedRegistry readOnlyTransactionsRegistry;
private final CloseTrackedRegistry writeTransactionsRegistry;
private final CloseTrackedRegistry readWriteTransactionsRegistry;
private class Watch {
final String iidString;
final LogicalDatastoreType store;
Watch(String iidString, LogicalDatastoreType storeOrNull) {
this.store = storeOrNull;
this.iidString = iidString;
}
private String toIidCompString(YangInstanceIdentifier iid) {
StringBuilder builder = new StringBuilder();
toPathString(iid, builder);
builder.append('/');
return builder.toString();
}
private boolean isParent(String parent, String child) {
int parentOffset = 0;
if (parent.length() > 0 && parent.charAt(0) == '<') {
parentOffset = parent.indexOf('>') + 1;
}
int childOffset = 0;
if (child.length() > 0 && child.charAt(0) == '<') {
childOffset = child.indexOf('>') + 1;
}
return child.startsWith(parent.substring(parentOffset), childOffset);
}
public boolean subtreesOverlap(YangInstanceIdentifier iid, LogicalDatastoreType store,
AsyncDataBroker.DataChangeScope scope) {
if (this.store != null && !this.store.equals(store)) {
return false;
}
String otherIidString = toIidCompString(iid);
switch (scope) {
case BASE:
return isParent(iidString, otherIidString);
case ONE: //for now just treat like SUBTREE, even though it's not
case SUBTREE:
return isParent(iidString, otherIidString) || isParent(otherIidString, iidString);
default:
return false;
}
}
public boolean eventIsOfInterest(YangInstanceIdentifier iid, LogicalDatastoreType store) {
if (this.store != null && !this.store.equals(store)) {
return false;
}
return isParent(iidString, toPathString(iid));
}
}
public TracingBroker(DOMDataBroker delegate, Config config, BindingNormalizedNodeSerializer codec) {
this.delegate = Objects.requireNonNull(delegate);
this.codec = Objects.requireNonNull(codec);
configure(config);
if (config.isTransactionDebugContextEnabled() != null) {
this.isDebugging = config.isTransactionDebugContextEnabled();
} else {
this.isDebugging = false;
}
final String db = "DataBroker";
this.transactionChainsRegistry = new CloseTrackedRegistry<>(db, "createTransactionChain()", isDebugging);
this.readOnlyTransactionsRegistry = new CloseTrackedRegistry<>(db, "newReadOnlyTransaction()", isDebugging);
this.writeTransactionsRegistry = new CloseTrackedRegistry<>(db, "newWriteOnlyTransaction()", isDebugging);
this.readWriteTransactionsRegistry = new CloseTrackedRegistry<>(db, "newReadWriteTransaction()", isDebugging);
}
private void configure(Config config) {
registrationWatches.clear();
List paths = config.getRegistrationWatches();
if (paths != null) {
for (String path : paths) {
watchRegistrations(path, null);
}
}
writeWatches.clear();
paths = config.getWriteWatches();
if (paths != null) {
for (String path : paths) {
watchWrites(path, null);
}
}
}
/**
* Log registrations to this subtree of the md-sal.
* @param iidString the iid path of the root of the subtree
* @param store Which LogicalDataStore? or null for both
*/
public void watchRegistrations(String iidString, LogicalDatastoreType store) {
LOG.info("Watching registrations to {} in {}", iidString, store);
registrationWatches.add(new Watch(iidString, store));
}
/**
* Log writes to this subtree of the md-sal.
* @param iidString the iid path of the root of the subtree
* @param store Which LogicalDataStore? or null for both
*/
public void watchWrites(String iidString, LogicalDatastoreType store) {
LOG.info("Watching writes to {} in {}", iidString, store);
Watch watch = new Watch(iidString, store);
writeWatches.add(watch);
}
private boolean isRegistrationWatched(YangInstanceIdentifier iid,
LogicalDatastoreType store, DataChangeScope scope) {
if (registrationWatches.isEmpty()) {
return true;
}
for (Watch regInterest : registrationWatches) {
if (regInterest.subtreesOverlap(iid, store, scope)) {
return true;
}
}
return false;
}
boolean isWriteWatched(YangInstanceIdentifier iid, LogicalDatastoreType store) {
if (writeWatches.isEmpty()) {
return true;
}
for (Watch watch : writeWatches) {
if (watch.eventIsOfInterest(iid, store)) {
return true;
}
}
return false;
}
static void toPathString(InstanceIdentifier extends DataObject> iid, StringBuilder builder) {
for (InstanceIdentifier.PathArgument pathArg : iid.getPathArguments()) {
builder.append('/').append(pathArg.getType().getSimpleName());
}
}
String toPathString(YangInstanceIdentifier yiid) {
StringBuilder sb = new StringBuilder();
toPathString(yiid, sb);
return sb.toString();
}
private void toPathString(YangInstanceIdentifier yiid, StringBuilder sb) {
InstanceIdentifier> iid = codec.fromYangInstanceIdentifier(yiid);
if (null == iid) {
reconstructIidPathString(yiid, sb);
} else {
toPathString(iid, sb);
}
}
private void reconstructIidPathString(YangInstanceIdentifier yiid, StringBuilder sb) {
sb.append("");
for (YangInstanceIdentifier.PathArgument pathArg : yiid.getPathArguments()) {
if (pathArg instanceof YangInstanceIdentifier.AugmentationIdentifier) {
sb.append('/').append("AUGMENTATION");
continue;
}
sb.append('/').append(pathArg.getNodeType().getLocalName());
}
}
String getStackSummary() {
StackTraceElement[] stack = Thread.currentThread().getStackTrace();
StringBuilder sb = new StringBuilder();
for (int i = STACK_TRACE_FIRST_RELEVANT_FRAME; i < stack.length; i++) {
StackTraceElement frame = stack[i];
sb.append("\n\t(TracingBroker)\t").append(frame.getClassName()).append('.').append(frame.getMethodName());
}
return sb.toString();
}
@Override
public DOMDataReadWriteTransaction newReadWriteTransaction() {
return new TracingReadWriteTransaction(delegate.newReadWriteTransaction(), this, readWriteTransactionsRegistry);
}
@Override
public DOMDataWriteTransaction newWriteOnlyTransaction() {
return new TracingWriteTransaction(delegate.newWriteOnlyTransaction(), this, writeTransactionsRegistry);
}
@Override
public ListenerRegistration registerDataChangeListener(
LogicalDatastoreType store, YangInstanceIdentifier yiid,
DOMDataChangeListener listener, DataChangeScope scope) {
if (isRegistrationWatched(yiid, store, scope)) {
LOG.warn("Registration (registerDataChangeListener) for {} from {}",
toPathString(yiid), getStackSummary());
}
return delegate.registerDataChangeListener(store, yiid, listener, scope);
}
@Override
public DOMTransactionChain createTransactionChain(TransactionChainListener transactionChainListener) {
return new TracingTransactionChain(
delegate.createTransactionChain(transactionChainListener), this, transactionChainsRegistry);
}
@Override
public DOMDataReadOnlyTransaction newReadOnlyTransaction() {
return new TracingReadOnlyTransaction(delegate.newReadOnlyTransaction(), this, readOnlyTransactionsRegistry);
}
@Nonnull
@Override
public Map, DOMDataBrokerExtension> getSupportedExtensions() {
Map, DOMDataBrokerExtension> res = delegate.getSupportedExtensions();
DOMDataTreeChangeService treeChangeSvc = (DOMDataTreeChangeService) res.get(DOMDataTreeChangeService.class);
if (treeChangeSvc == null) {
return res;
}
res = new HashMap<>(res);
res.put(DOMDataTreeChangeService.class, new DOMDataTreeChangeService() {
@Nonnull
@Override
public ListenerRegistration registerDataTreeChangeListener(
@Nonnull DOMDataTreeIdentifier domDataTreeIdentifier, @Nonnull L listener) {
if (isRegistrationWatched(domDataTreeIdentifier.getRootIdentifier(),
domDataTreeIdentifier.getDatastoreType(), DataChangeScope.SUBTREE)) {
LOG.warn("{} registration (registerDataTreeChangeListener) for {} from {}.",
listener instanceof ClusteredDOMDataTreeChangeListener ? "Clustered" : "Non-clustered",
toPathString(domDataTreeIdentifier.getRootIdentifier()), getStackSummary());
}
return treeChangeSvc.registerDataTreeChangeListener(domDataTreeIdentifier, listener);
}
});
return res;
}
@Override
public boolean printOpenTransactions(PrintStream ps) {
if (transactionChainsRegistry.getAllUnique().isEmpty()
&& readOnlyTransactionsRegistry.getAllUnique().isEmpty()
&& writeTransactionsRegistry.getAllUnique().isEmpty()
&& readWriteTransactionsRegistry.getAllUnique().isEmpty()) {
return false;
}
ps.println(getClass().getSimpleName() + " found some not yet (or never..) closed transaction[chain]s!");
ps.println("[NB: If no stack traces are shown below, then "
+ "enable transaction-debug-context-enabled in mdsaltrace_config.xml]");
ps.println();
printRegistryOpenTransactions(readOnlyTransactionsRegistry, ps, " ");
printRegistryOpenTransactions(writeTransactionsRegistry, ps, " ");
printRegistryOpenTransactions(readWriteTransactionsRegistry, ps, " ");
// Now print details for each non-closed TransactionChain
// incl. in turn each ones own read/Write[Only]TransactionsRegistry
Set>
entries = transactionChainsRegistry.getAllUnique();
if (!entries.isEmpty()) {
ps.println(" " + transactionChainsRegistry.getAnchor() + " : "
+ transactionChainsRegistry.getCreateDescription());
}
entries.forEach(entry -> {
ps.println(" " + entry.getNumberAddedNotRemoved() + "x TransactionChains opened but not closed here:");
printStackTraceElements(ps, " ", entry.getStackTraceElements());
@SuppressWarnings("resource")
TracingTransactionChain txChain = (TracingTransactionChain) entry
.getExampleCloseTracked().getRealCloseTracked();
printRegistryOpenTransactions(txChain.getReadOnlyTransactionsRegistry(), ps, " ");
printRegistryOpenTransactions(txChain.getWriteTransactionsRegistry(), ps, " ");
printRegistryOpenTransactions(txChain.getReadWriteTransactionsRegistry(), ps, " ");
});
ps.println();
return true;
}
private > void printRegistryOpenTransactions(
CloseTrackedRegistry registry, PrintStream ps, String indent) {
Set> entries = registry.getAllUnique();
if (!entries.isEmpty()) {
ps.println(indent + registry.getAnchor() + " : " + registry.getCreateDescription());
}
entries.forEach(entry -> {
ps.println(indent + " " + entry.getNumberAddedNotRemoved()
+ "x transactions opened here, which are not closed:");
printStackTraceElements(ps, indent + " ", entry.getStackTraceElements());
});
if (!entries.isEmpty()) {
ps.println();
}
}
private void printStackTraceElements(PrintStream ps, String indent, List stackTraceElements) {
boolean ellipsis = false;
for (final StackTraceElement stackTraceElement : stackTraceElements) {
if (isStackTraceElementInteresting(stackTraceElement)) {
ps.println(indent + stackTraceElement);
ellipsis = false;
} else if (!ellipsis) {
ps.println(indent + "(...)");
ellipsis = true;
}
}
}
private boolean isStackTraceElementInteresting(StackTraceElement element) {
final String className = element.getClassName();
return !className.startsWith(getClass().getPackage().getName())
&& !className.startsWith(CloseTracked.class.getPackage().getName())
&& !className.startsWith("Proxy")
&& !className.startsWith("akka")
&& !className.startsWith("scala")
&& !className.startsWith("sun.reflect")
&& !className.startsWith("java.lang.reflect")
&& !className.startsWith("org.apache.aries.blueprint")
&& !className.startsWith("org.osgi.util.tracker");
}
}