2 * Copyright (c) 2016 Red Hat, Inc. and others. All rights reserved.
4 * This program and the accompanying materials are made available under the
5 * terms of the Eclipse Public License v1.0 which accompanies this distribution,
6 * and is available at http://www.eclipse.org/legal/epl-v10.html
8 package org.opendaylight.mdsal.trace.impl;
10 import static java.util.Objects.requireNonNull;
12 import com.google.common.collect.ClassToInstanceMap;
13 import com.google.common.collect.MutableClassToInstanceMap;
14 import edu.umd.cs.findbugs.annotations.SuppressFBWarnings;
15 import java.io.PrintStream;
16 import java.util.ArrayList;
17 import java.util.List;
19 import org.opendaylight.mdsal.binding.dom.codec.api.BindingNormalizedNodeSerializer;
20 import org.opendaylight.mdsal.common.api.LogicalDatastoreType;
21 import org.opendaylight.mdsal.dom.api.ClusteredDOMDataTreeChangeListener;
22 import org.opendaylight.mdsal.dom.api.DOMDataBroker;
23 import org.opendaylight.mdsal.dom.api.DOMDataBrokerExtension;
24 import org.opendaylight.mdsal.dom.api.DOMDataTreeChangeListener;
25 import org.opendaylight.mdsal.dom.api.DOMDataTreeChangeService;
26 import org.opendaylight.mdsal.dom.api.DOMDataTreeIdentifier;
27 import org.opendaylight.mdsal.dom.api.DOMDataTreeReadTransaction;
28 import org.opendaylight.mdsal.dom.api.DOMDataTreeReadWriteTransaction;
29 import org.opendaylight.mdsal.dom.api.DOMDataTreeWriteTransaction;
30 import org.opendaylight.mdsal.dom.api.DOMTransactionChain;
31 import org.opendaylight.mdsal.dom.api.DOMTransactionChainListener;
32 import org.opendaylight.mdsal.trace.api.TracingDOMDataBroker;
33 import org.opendaylight.yang.gen.v1.urn.opendaylight.params.xml.ns.yang.mdsaltrace.rev160908.Config;
34 import org.opendaylight.yangtools.concepts.ListenerRegistration;
35 import org.opendaylight.yangtools.yang.binding.DataObject;
36 import org.opendaylight.yangtools.yang.binding.InstanceIdentifier;
37 import org.opendaylight.yangtools.yang.data.api.YangInstanceIdentifier;
38 import org.slf4j.Logger;
39 import org.slf4j.LoggerFactory;
41 @SuppressWarnings("checkstyle:JavadocStyle")
42 //...because otherwise it whines about the elements in the @code block even though it's completely valid Javadoc
45 * TracingBroker logs "write" operations and listener registrations to the md-sal. It logs the instance identifier path,
46 * the objects themselves, as well as the stack trace of the call invoking the registration or write operation.
47 * It works by operating as a "bump on the stack" between the application and actual DataBroker, intercepting write
48 * and registration calls and writing to the log.
50 * <p>In addition, it (optionally) can also keep track of the stack trace of all new transaction allocations
51 * (including TransactionChains, and transactions created in turn from them), in order to detect and report leaks
52 * from transactions which were not closed.
55 * TracingBroker is designed to be easy to use. In fact, for bundles using Blueprint to inject their DataBroker
56 * TracingBroker can be used without modifying your code at all in two simple steps:
59 * Simply add the dependency "mdsaltrace-features" to
64 * <groupId>org.opendaylight.controller</groupId>
65 * <artifactId>features-mdsal-trace</artifactId>
66 * <version>1.7.0-SNAPSHOT</version>
67 * <classifier>features</classifier>
69 * <scope>runtime</scope>
75 * Then just "feature:install odl-mdsal-trace" before you install your "real" feature(s) and you're done.
76 * Beware that with Karaf 4 due to <a href="https://bugs.opendaylight.org/show_bug.cgi?id=9068">Bug 9068</a>
77 * you'll probably have to use feature:install's --no-auto-refresh flag when installing your "real" feature.
80 * This works because the mdsaltrace-impl bundle registers its service implementing DOMDataBroker with a higher
81 * rank than sal-binding-broker. As such, any OSGi service lookup for DataBroker will receive the TracingBroker.
83 * <h1>Avoiding log bloat:</h1>
84 * TracingBroker can be configured to only print registrations or write ops pertaining to certain subtrees of the
85 * md-sal. This can be done in the code via the methods of this class or via a config file. TracingBroker uses a more
86 * convenient but non-standard representation of the instance identifiers. Each instance identifier segment's
87 * class.getSimpleName() is used separated by a '/'.
89 * <h1>Known issues</h1>
92 * Filtering by paths. For some registrations the codec that converts back from the DOM to binding paths is
93 * busted. As such, an aproximated path is used in the output. For now it is recommended not to use
94 * watchRegistrations and allow all registrations to be logged.
99 public class TracingBroker implements TracingDOMDataBroker {
100 @SuppressFBWarnings("SLF4J_LOGGER_SHOULD_BE_PRIVATE")
101 static final Logger LOG = LoggerFactory.getLogger(TracingBroker.class);
103 private static final int STACK_TRACE_FIRST_RELEVANT_FRAME = 2;
105 // "default" VS "pingpong"
106 private final String type;
107 private final BindingNormalizedNodeSerializer codec;
108 private final DOMDataBroker delegate;
109 private final List<Watch> registrationWatches = new ArrayList<>();
110 private final List<Watch> writeWatches = new ArrayList<>();
112 private final boolean isDebugging;
113 private final CloseTrackedRegistry<TracingTransactionChain> transactionChainsRegistry;
114 private final CloseTrackedRegistry<TracingReadOnlyTransaction> readOnlyTransactionsRegistry;
115 private final CloseTrackedRegistry<TracingWriteTransaction> writeTransactionsRegistry;
116 private final CloseTrackedRegistry<TracingReadWriteTransaction> readWriteTransactionsRegistry;
118 private class Watch {
119 final String iidString;
120 final LogicalDatastoreType store;
122 Watch(String iidString, LogicalDatastoreType storeOrNull) {
123 this.store = storeOrNull;
124 this.iidString = iidString;
127 private String toIidCompString(YangInstanceIdentifier iid) {
128 StringBuilder builder = new StringBuilder();
129 toPathString(iid, builder);
131 return builder.toString();
134 private boolean isParent(String parent, String child) {
135 int parentOffset = 0;
136 if (parent.length() > 0 && parent.charAt(0) == '<') {
137 parentOffset = parent.indexOf('>') + 1;
141 if (child.length() > 0 && child.charAt(0) == '<') {
142 childOffset = child.indexOf('>') + 1;
145 return child.startsWith(parent.substring(parentOffset), childOffset);
148 @SuppressWarnings({ "checkstyle:hiddenField", "hiding" })
149 public boolean subtreesOverlap(YangInstanceIdentifier iid, LogicalDatastoreType store) {
150 if (this.store != null && !this.store.equals(store)) {
154 String otherIidString = toIidCompString(iid);
155 return isParent(iidString, otherIidString) || isParent(otherIidString, iidString);
158 @SuppressWarnings({ "checkstyle:hiddenField", "hiding" })
159 public boolean eventIsOfInterest(YangInstanceIdentifier iid, LogicalDatastoreType store) {
160 if (this.store != null && !this.store.equals(store)) {
164 return isParent(iidString, toPathString(iid));
168 public TracingBroker(String type, DOMDataBroker delegate, Config config, BindingNormalizedNodeSerializer codec) {
169 this.type = requireNonNull(type, "type");
170 this.delegate = requireNonNull(delegate, "delegate");
171 this.codec = requireNonNull(codec, "codec");
174 if (config.isTransactionDebugContextEnabled() != null) {
175 this.isDebugging = config.isTransactionDebugContextEnabled();
177 this.isDebugging = false;
179 final String db = "DataBroker";
180 this.transactionChainsRegistry = new CloseTrackedRegistry<>(db, "createTransactionChain()", isDebugging);
181 this.readOnlyTransactionsRegistry = new CloseTrackedRegistry<>(db, "newReadOnlyTransaction()", isDebugging);
182 this.writeTransactionsRegistry = new CloseTrackedRegistry<>(db, "newWriteOnlyTransaction()", isDebugging);
183 this.readWriteTransactionsRegistry = new CloseTrackedRegistry<>(db, "newReadWriteTransaction()", isDebugging);
186 private void configure(Config config) {
187 registrationWatches.clear();
188 List<String> paths = config.getRegistrationWatches();
190 for (String path : paths) {
191 watchRegistrations(path, null);
195 writeWatches.clear();
196 paths = config.getWriteWatches();
198 for (String path : paths) {
199 watchWrites(path, null);
205 * Log registrations to this subtree of the md-sal.
206 * @param iidString the iid path of the root of the subtree
207 * @param store Which LogicalDataStore? or null for both
209 public void watchRegistrations(String iidString, LogicalDatastoreType store) {
210 LOG.info("Watching registrations to {} in {}", iidString, store);
211 registrationWatches.add(new Watch(iidString, store));
215 * Log writes to this subtree of the md-sal.
216 * @param iidString the iid path of the root of the subtree
217 * @param store Which LogicalDataStore? or null for both
219 public void watchWrites(String iidString, LogicalDatastoreType store) {
220 LOG.info("Watching writes to {} in {}", iidString, store);
221 Watch watch = new Watch(iidString, store);
222 writeWatches.add(watch);
225 @SuppressFBWarnings(value = "UPM_UNCALLED_PRIVATE_METHOD",
226 justification = "https://github.com/spotbugs/spotbugs/issues/811")
227 private boolean isRegistrationWatched(YangInstanceIdentifier iid, LogicalDatastoreType store) {
228 if (registrationWatches.isEmpty()) {
232 for (Watch regInterest : registrationWatches) {
233 if (regInterest.subtreesOverlap(iid, store)) {
241 boolean isWriteWatched(YangInstanceIdentifier iid, LogicalDatastoreType store) {
242 if (writeWatches.isEmpty()) {
246 for (Watch watch : writeWatches) {
247 if (watch.eventIsOfInterest(iid, store)) {
255 static void toPathString(InstanceIdentifier<? extends DataObject> iid, StringBuilder builder) {
256 for (InstanceIdentifier.PathArgument pathArg : iid.getPathArguments()) {
257 builder.append('/').append(pathArg.getType().getSimpleName());
261 String toPathString(YangInstanceIdentifier yiid) {
262 StringBuilder sb = new StringBuilder();
263 toPathString(yiid, sb);
264 return sb.toString();
268 private void toPathString(YangInstanceIdentifier yiid, StringBuilder sb) {
269 InstanceIdentifier<?> iid = codec.fromYangInstanceIdentifier(yiid);
271 reconstructIidPathString(yiid, sb);
273 toPathString(iid, sb);
277 private static void reconstructIidPathString(YangInstanceIdentifier yiid, StringBuilder sb) {
278 sb.append("<RECONSTRUCTED FROM: \"").append(yiid.toString()).append("\">");
279 for (YangInstanceIdentifier.PathArgument pathArg : yiid.getPathArguments()) {
280 if (pathArg instanceof YangInstanceIdentifier.AugmentationIdentifier) {
281 sb.append('/').append("AUGMENTATION");
284 sb.append('/').append(pathArg.getNodeType().getLocalName());
288 String getStackSummary() {
289 StackTraceElement[] stack = Thread.currentThread().getStackTrace();
291 StringBuilder sb = new StringBuilder();
292 for (int i = STACK_TRACE_FIRST_RELEVANT_FRAME; i < stack.length; i++) {
293 StackTraceElement frame = stack[i];
294 sb.append("\n\t(TracingBroker)\t").append(frame.getClassName()).append('.').append(frame.getMethodName());
297 return sb.toString();
301 public DOMDataTreeReadWriteTransaction newReadWriteTransaction() {
302 return new TracingReadWriteTransaction(delegate.newReadWriteTransaction(), this, readWriteTransactionsRegistry);
306 public DOMDataTreeWriteTransaction newWriteOnlyTransaction() {
307 return new TracingWriteTransaction(delegate.newWriteOnlyTransaction(), this, writeTransactionsRegistry);
311 public DOMTransactionChain createTransactionChain(DOMTransactionChainListener transactionChainListener) {
312 return new TracingTransactionChain(delegate.createTransactionChain(transactionChainListener), this,
313 transactionChainsRegistry);
317 public DOMTransactionChain createMergingTransactionChain(DOMTransactionChainListener transactionChainListener) {
318 return new TracingTransactionChain(delegate.createMergingTransactionChain(transactionChainListener), this,
319 transactionChainsRegistry);
323 public DOMDataTreeReadTransaction newReadOnlyTransaction() {
324 return new TracingReadOnlyTransaction(delegate.newReadOnlyTransaction(), readOnlyTransactionsRegistry);
328 public ClassToInstanceMap<DOMDataBrokerExtension> getExtensions() {
329 final ClassToInstanceMap<DOMDataBrokerExtension> delegateExt = delegate.getExtensions();
330 final DOMDataTreeChangeService treeChangeSvc = delegateExt.getInstance(DOMDataTreeChangeService.class);
331 if (treeChangeSvc == null) {
335 final ClassToInstanceMap<DOMDataBrokerExtension> res = MutableClassToInstanceMap.create(delegateExt);
336 res.put(DOMDataTreeChangeService.class, new DOMDataTreeChangeService() {
338 public <L extends DOMDataTreeChangeListener> ListenerRegistration<L> registerDataTreeChangeListener(
339 DOMDataTreeIdentifier domDataTreeIdentifier, L listener) {
340 if (isRegistrationWatched(domDataTreeIdentifier.getRootIdentifier(),
341 domDataTreeIdentifier.getDatastoreType())) {
342 LOG.warn("{} registration (registerDataTreeChangeListener) for {} from {}.",
343 listener instanceof ClusteredDOMDataTreeChangeListener ? "Clustered" : "Non-clustered",
344 toPathString(domDataTreeIdentifier.getRootIdentifier()), getStackSummary());
346 return treeChangeSvc.registerDataTreeChangeListener(domDataTreeIdentifier, listener);
354 public boolean printOpenTransactions(PrintStream ps, int minOpenTXs) {
355 if (transactionChainsRegistry.getAllUnique().isEmpty()
356 && readOnlyTransactionsRegistry.getAllUnique().isEmpty()
357 && writeTransactionsRegistry.getAllUnique().isEmpty()
358 && readWriteTransactionsRegistry.getAllUnique().isEmpty()) {
360 ps.println(type + ": No open transactions, great!");
364 ps.println(type + ": " + getClass().getSimpleName()
365 + " found some not yet (or never..) closed transaction[chain]s!");
366 ps.println("[NB: If no stack traces are shown below, then "
367 + "enable transaction-debug-context-enabled in mdsaltrace_config.xml]");
369 // Flag to track if we really found any real leaks with more (or equal) to minOpenTXs
370 boolean hasFound = print(readOnlyTransactionsRegistry, ps, " ", minOpenTXs);
371 hasFound |= print(writeTransactionsRegistry, ps, " ", minOpenTXs);
372 hasFound |= print(readWriteTransactionsRegistry, ps, " ", minOpenTXs);
374 // Now print details for each non-closed TransactionChain
375 // incl. in turn each ones own read/Write[Only]TransactionsRegistry
376 Set<CloseTrackedRegistryReportEntry<TracingTransactionChain>>
377 entries = transactionChainsRegistry.getAllUnique();
378 if (!entries.isEmpty()) {
379 ps.println(" " + transactionChainsRegistry.getAnchor() + " : "
380 + transactionChainsRegistry.getCreateDescription());
382 for (CloseTrackedRegistryReportEntry<TracingTransactionChain> entry : entries) {
383 ps.println(" " + entry.getNumberAddedNotRemoved() + "x TransactionChains opened but not closed here:");
384 printStackTraceElements(ps, " ", entry.getStackTraceElements());
385 @SuppressWarnings("resource")
386 TracingTransactionChain txChain = (TracingTransactionChain) entry
387 .getExampleCloseTracked().getRealCloseTracked();
388 hasFound |= print(txChain.getReadOnlyTransactionsRegistry(), ps, " ", minOpenTXs);
389 hasFound |= print(txChain.getWriteTransactionsRegistry(), ps, " ", minOpenTXs);
390 hasFound |= print(txChain.getReadWriteTransactionsRegistry(), ps, " ", minOpenTXs);
397 private <T extends CloseTracked<T>> boolean print(
398 CloseTrackedRegistry<T> registry, PrintStream ps, String indent, int minOpenTransactions) {
399 Set<CloseTrackedRegistryReportEntry<T>> unsorted = registry.getAllUnique();
400 if (unsorted.size() < minOpenTransactions) {
404 List<CloseTrackedRegistryReportEntry<T>> entries = new ArrayList<>(unsorted);
405 entries.sort((o1, o2) -> Long.compare(o2.getNumberAddedNotRemoved(), o1.getNumberAddedNotRemoved()));
407 if (!entries.isEmpty()) {
408 ps.println(indent + registry.getAnchor() + " : " + registry.getCreateDescription());
410 entries.forEach(entry -> {
411 ps.println(indent + " " + entry.getNumberAddedNotRemoved()
412 + "x transactions opened here, which are not closed:");
413 printStackTraceElements(ps, indent + " ", entry.getStackTraceElements());
415 if (!entries.isEmpty()) {
421 private void printStackTraceElements(PrintStream ps, String indent, List<StackTraceElement> stackTraceElements) {
422 boolean ellipsis = false;
423 for (final StackTraceElement stackTraceElement : stackTraceElements) {
424 if (isStackTraceElementInteresting(stackTraceElement)) {
425 ps.println(indent + stackTraceElement);
427 } else if (!ellipsis) {
428 ps.println(indent + "(...)");
434 private boolean isStackTraceElementInteresting(StackTraceElement element) {
435 final String className = element.getClassName();
436 return !className.startsWith(getClass().getPackage().getName())
437 && !className.startsWith(CloseTracked.class.getPackage().getName())
438 && !className.startsWith("Proxy")
439 && !className.startsWith("akka")
440 && !className.startsWith("scala")
441 && !className.startsWith("sun.reflect")
442 && !className.startsWith("java.lang.reflect")
443 && !className.startsWith("org.apache.aries.blueprint")
444 && !className.startsWith("org.osgi.util.tracker");