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 edu.umd.cs.findbugs.annotations.SuppressFBWarnings;
13 import java.io.PrintStream;
14 import java.util.ArrayList;
15 import java.util.List;
17 import org.opendaylight.mdsal.binding.dom.codec.api.BindingCodecTree;
18 import org.opendaylight.mdsal.common.api.LogicalDatastoreType;
19 import org.opendaylight.mdsal.dom.api.DOMDataBroker;
20 import org.opendaylight.mdsal.dom.api.DOMDataTreeChangeListener;
21 import org.opendaylight.mdsal.dom.api.DOMDataTreeIdentifier;
22 import org.opendaylight.mdsal.dom.api.DOMDataTreeReadTransaction;
23 import org.opendaylight.mdsal.dom.api.DOMDataTreeReadWriteTransaction;
24 import org.opendaylight.mdsal.dom.api.DOMDataTreeWriteTransaction;
25 import org.opendaylight.mdsal.dom.api.DOMTransactionChain;
26 import org.opendaylight.mdsal.trace.api.TracingDOMDataBroker;
27 import org.opendaylight.yang.gen.v1.urn.opendaylight.params.xml.ns.yang.mdsaltrace.rev160908.Config;
28 import org.opendaylight.yangtools.concepts.Registration;
29 import org.opendaylight.yangtools.yang.binding.DataObject;
30 import org.opendaylight.yangtools.yang.binding.InstanceIdentifier;
31 import org.opendaylight.yangtools.yang.data.api.YangInstanceIdentifier;
32 import org.slf4j.Logger;
33 import org.slf4j.LoggerFactory;
35 @SuppressWarnings("checkstyle:JavadocStyle")
36 //...because otherwise it whines about the elements in the @code block even though it's completely valid Javadoc
38 * TracingBroker logs "write" operations and listener registrations to the md-sal. It logs the instance identifier path,
39 * the objects themselves, as well as the stack trace of the call invoking the registration or write operation.
40 * It works by operating as a "bump on the stack" between the application and actual DataBroker, intercepting write
41 * and registration calls and writing to the log.
43 * <p>In addition, it (optionally) can also keep track of the stack trace of all new transaction allocations
44 * (including TransactionChains, and transactions created in turn from them), in order to detect and report leaks
45 * from transactions which were not closed.
48 * TracingBroker is designed to be easy to use. In fact, for bundles using Blueprint to inject their DataBroker
49 * TracingBroker can be used without modifying your code at all in two simple steps:
52 * Simply add the dependency "mdsaltrace-features" to
57 * <groupId>org.opendaylight.controller</groupId>
58 * <artifactId>features-mdsal-trace</artifactId>
59 * <version>1.7.0-SNAPSHOT</version>
60 * <classifier>features</classifier>
62 * <scope>runtime</scope>
68 * Then just "feature:install odl-mdsal-trace" before you install your "real" feature(s) and you're done.
69 * Beware that with Karaf 4 due to <a href="https://bugs.opendaylight.org/show_bug.cgi?id=9068">Bug 9068</a>
70 * you'll probably have to use feature:install's --no-auto-refresh flag when installing your "real" feature.
73 * This works because the mdsaltrace-impl bundle registers its service implementing DOMDataBroker with a higher
74 * rank than sal-binding-broker. As such, any OSGi service lookup for DataBroker will receive the TracingBroker.
76 * <h1>Avoiding log bloat:</h1>
77 * TracingBroker can be configured to only print registrations or write ops pertaining to certain subtrees of the
78 * md-sal. This can be done in the code via the methods of this class or via a config file. TracingBroker uses a more
79 * convenient but non-standard representation of the instance identifiers. Each instance identifier segment's
80 * class.getSimpleName() is used separated by a '/'.
82 * <h1>Known issues</h1>
85 * Filtering by paths. For some registrations the codec that converts back from the DOM to binding paths is
86 * busted. As such, an aproximated path is used in the output. For now it is recommended not to use
87 * watchRegistrations and allow all registrations to be logged.
91 public class TracingBroker implements TracingDOMDataBroker {
92 private static final Logger LOG = LoggerFactory.getLogger(TracingBroker.class);
94 private static final int STACK_TRACE_FIRST_RELEVANT_FRAME = 2;
96 private final BindingCodecTree codec;
97 private final DOMDataBroker delegate;
98 private final List<Watch> registrationWatches = new ArrayList<>();
99 private final List<Watch> writeWatches = new ArrayList<>();
101 private final boolean isDebugging;
102 private final CloseTrackedRegistry<TracingTransactionChain> transactionChainsRegistry;
103 private final CloseTrackedRegistry<TracingReadOnlyTransaction> readOnlyTransactionsRegistry;
104 private final CloseTrackedRegistry<TracingWriteTransaction> writeTransactionsRegistry;
105 private final CloseTrackedRegistry<TracingReadWriteTransaction> readWriteTransactionsRegistry;
107 private class Watch {
108 final String iidString;
109 final LogicalDatastoreType store;
111 Watch(final String iidString, final LogicalDatastoreType storeOrNull) {
113 this.iidString = iidString;
116 private String toIidCompString(final YangInstanceIdentifier iid) {
117 StringBuilder builder = new StringBuilder();
118 toPathString(iid, builder);
119 return builder.append('/').toString();
122 private boolean isParent(final String parent, final String child) {
123 int parentOffset = 0;
124 if (parent.length() > 0 && parent.charAt(0) == '<') {
125 parentOffset = parent.indexOf('>') + 1;
129 if (child.length() > 0 && child.charAt(0) == '<') {
130 childOffset = child.indexOf('>') + 1;
133 return child.startsWith(parent.substring(parentOffset), childOffset);
136 @SuppressWarnings({ "checkstyle:hiddenField", "hiding" })
137 public boolean subtreesOverlap(final YangInstanceIdentifier iid, final LogicalDatastoreType store) {
138 if (this.store != null && !this.store.equals(store)) {
142 String otherIidString = toIidCompString(iid);
143 return isParent(iidString, otherIidString) || isParent(otherIidString, iidString);
146 @SuppressWarnings({ "checkstyle:hiddenField", "hiding" })
147 public boolean eventIsOfInterest(final YangInstanceIdentifier iid, final LogicalDatastoreType store) {
148 if (this.store != null && !this.store.equals(store)) {
152 return isParent(iidString, toPathString(iid));
156 public TracingBroker(final DOMDataBroker delegate, final Config config, final BindingCodecTree codec) {
157 this.delegate = requireNonNull(delegate, "delegate");
158 this.codec = requireNonNull(codec, "codec");
161 isDebugging = Boolean.TRUE.equals(config.getTransactionDebugContextEnabled());
162 final String db = "DataBroker";
163 transactionChainsRegistry = new CloseTrackedRegistry<>(db, "createTransactionChain()", isDebugging);
164 readOnlyTransactionsRegistry = new CloseTrackedRegistry<>(db, "newReadOnlyTransaction()", isDebugging);
165 writeTransactionsRegistry = new CloseTrackedRegistry<>(db, "newWriteOnlyTransaction()", isDebugging);
166 readWriteTransactionsRegistry = new CloseTrackedRegistry<>(db, "newReadWriteTransaction()", isDebugging);
169 private void configure(final Config config) {
170 registrationWatches.clear();
171 Set<String> paths = config.getRegistrationWatches();
173 for (String path : paths) {
174 watchRegistrations(path, null);
178 writeWatches.clear();
179 paths = config.getWriteWatches();
181 for (String path : paths) {
182 watchWrites(path, null);
188 * Log registrations to this subtree of the md-sal.
189 * @param iidString the iid path of the root of the subtree
190 * @param store Which LogicalDataStore? or null for both
192 public void watchRegistrations(final String iidString, final LogicalDatastoreType store) {
193 LOG.info("Watching registrations to {} in {}", iidString, store);
194 registrationWatches.add(new Watch(iidString, store));
198 * Log writes to this subtree of the md-sal.
199 * @param iidString the iid path of the root of the subtree
200 * @param store Which LogicalDataStore? or null for both
202 public void watchWrites(final String iidString, final LogicalDatastoreType store) {
203 LOG.info("Watching writes to {} in {}", iidString, store);
204 Watch watch = new Watch(iidString, store);
205 writeWatches.add(watch);
208 private boolean isRegistrationWatched(final YangInstanceIdentifier iid, final LogicalDatastoreType store) {
209 if (registrationWatches.isEmpty()) {
213 for (Watch regInterest : registrationWatches) {
214 if (regInterest.subtreesOverlap(iid, store)) {
222 boolean isWriteWatched(final YangInstanceIdentifier iid, final LogicalDatastoreType store) {
223 if (writeWatches.isEmpty()) {
227 for (Watch watch : writeWatches) {
228 if (watch.eventIsOfInterest(iid, store)) {
236 static void toPathString(final InstanceIdentifier<? extends DataObject> iid, final StringBuilder builder) {
237 for (var pathArg : iid.getPathArguments()) {
238 builder.append('/').append(pathArg.type().getSimpleName());
242 String toPathString(final YangInstanceIdentifier yiid) {
243 StringBuilder sb = new StringBuilder();
244 toPathString(yiid, sb);
245 return sb.toString();
249 private void toPathString(final YangInstanceIdentifier yiid, final StringBuilder sb) {
250 InstanceIdentifier<?> iid = codec.getInstanceIdentifierCodec().toBinding(yiid);
252 reconstructIidPathString(yiid, sb);
254 toPathString(iid, sb);
258 private static void reconstructIidPathString(final YangInstanceIdentifier yiid, final StringBuilder sb) {
259 sb.append("<RECONSTRUCTED FROM: \"").append(yiid.toString()).append("\">");
260 for (YangInstanceIdentifier.PathArgument pathArg : yiid.getPathArguments()) {
261 sb.append('/').append(pathArg.getNodeType().getLocalName());
265 String getStackSummary() {
266 StackTraceElement[] stack = Thread.currentThread().getStackTrace();
268 StringBuilder sb = new StringBuilder();
269 for (int i = STACK_TRACE_FIRST_RELEVANT_FRAME; i < stack.length; i++) {
270 StackTraceElement frame = stack[i];
271 sb.append("\n\t(TracingBroker)\t").append(frame.getClassName()).append('.').append(frame.getMethodName());
274 return sb.toString();
278 public DOMDataTreeReadWriteTransaction newReadWriteTransaction() {
279 return new TracingReadWriteTransaction(delegate.newReadWriteTransaction(), this, readWriteTransactionsRegistry);
283 public DOMDataTreeWriteTransaction newWriteOnlyTransaction() {
284 return new TracingWriteTransaction(delegate.newWriteOnlyTransaction(), this, writeTransactionsRegistry);
288 public DOMTransactionChain createTransactionChain() {
289 return new TracingTransactionChain(delegate.createTransactionChain(), this, transactionChainsRegistry);
293 public DOMTransactionChain createMergingTransactionChain() {
294 return new TracingTransactionChain(delegate.createMergingTransactionChain(), this, transactionChainsRegistry);
298 public DOMDataTreeReadTransaction newReadOnlyTransaction() {
299 return new TracingReadOnlyTransaction(delegate.newReadOnlyTransaction(), readOnlyTransactionsRegistry);
303 public <T extends Extension> T extension(final Class<T> type) {
304 final var ext = delegate.extension(type);
305 if (DataTreeChangeExtension.class.equals(type) && ext instanceof DataTreeChangeExtension treeChange) {
306 return type.cast(new DataTreeChangeExtension() {
308 public Registration registerTreeChangeListener(final DOMDataTreeIdentifier treeId,
309 final DOMDataTreeChangeListener listener) {
310 notifyIfWatched("Non-clustered", treeId, listener);
311 return treeChange.registerTreeChangeListener(treeId, listener);
315 @Deprecated(since = "13.0.0", forRemoval = true)
316 public Registration registerLegacyTreeChangeListener(final DOMDataTreeIdentifier treeId,
317 final DOMDataTreeChangeListener listener) {
318 notifyIfWatched("Non-clustered", treeId, listener);
319 return treeChange.registerLegacyTreeChangeListener(treeId, listener);
322 private void notifyIfWatched(final String kind, final DOMDataTreeIdentifier treeId,
323 final DOMDataTreeChangeListener listener) {
324 final var rootId = treeId.path();
325 if (isRegistrationWatched(rootId, treeId.datastore()) && LOG.isWarnEnabled()) {
326 LOG.warn("{} registration (registerDataTreeChangeListener) for {} from {}.", kind,
327 toPathString(rootId), getStackSummary());
336 public boolean printOpenTransactions(final PrintStream ps, final int minOpenTXs) {
337 if (transactionChainsRegistry.getAllUnique().isEmpty()
338 && readOnlyTransactionsRegistry.getAllUnique().isEmpty()
339 && writeTransactionsRegistry.getAllUnique().isEmpty()
340 && readWriteTransactionsRegistry.getAllUnique().isEmpty()) {
342 ps.println("No open transactions, great!");
346 ps.println(getClass().getSimpleName() + " found some not yet (or never..) closed transaction[chain]s!");
347 ps.println("[NB: If no stack traces are shown below, then "
348 + "enable transaction-debug-context-enabled in mdsaltrace_config.xml]");
350 // Flag to track if we really found any real leaks with more (or equal) to minOpenTXs
351 boolean hasFound = print(readOnlyTransactionsRegistry, ps, " ", minOpenTXs);
352 hasFound |= print(writeTransactionsRegistry, ps, " ", minOpenTXs);
353 hasFound |= print(readWriteTransactionsRegistry, ps, " ", minOpenTXs);
355 // Now print details for each non-closed TransactionChain
356 // incl. in turn each ones own read/Write[Only]TransactionsRegistry
357 Set<CloseTrackedRegistryReportEntry<TracingTransactionChain>>
358 entries = transactionChainsRegistry.getAllUnique();
359 if (!entries.isEmpty()) {
360 ps.println(" " + transactionChainsRegistry.getAnchor() + " : "
361 + transactionChainsRegistry.getCreateDescription());
363 for (CloseTrackedRegistryReportEntry<TracingTransactionChain> entry : entries) {
364 ps.println(" " + entry.getNumberAddedNotRemoved() + "x TransactionChains opened but not closed here:");
365 printStackTraceElements(ps, " ", entry.getStackTraceElements());
366 @SuppressWarnings("resource")
367 TracingTransactionChain txChain = (TracingTransactionChain) entry
368 .getExampleCloseTracked().getRealCloseTracked();
369 hasFound |= print(txChain.getReadOnlyTransactionsRegistry(), ps, " ", minOpenTXs);
370 hasFound |= print(txChain.getWriteTransactionsRegistry(), ps, " ", minOpenTXs);
371 hasFound |= print(txChain.getReadWriteTransactionsRegistry(), ps, " ", minOpenTXs);
378 final void logEmptySet(final YangInstanceIdentifier yiid) {
379 if (LOG.isDebugEnabled()) {
380 LOG.debug("Empty data set write to {}", toPathString(yiid));
384 @SuppressFBWarnings(value = "SLF4J_SIGN_ONLY_FORMAT", justification = "pre-formatted logs")
385 static final void logOperations(final Object identifier, final List<?> operations) {
386 if (LOG.isWarnEnabled()) {
387 LOG.warn("Transaction {} contains the following operations:", identifier);
388 for (var operation : operations) {
389 LOG.warn("{}", operation);
394 private <T extends CloseTracked<T>> boolean print(final CloseTrackedRegistry<T> registry, final PrintStream ps,
395 final String indent, final int minOpenTransactions) {
396 Set<CloseTrackedRegistryReportEntry<T>> unsorted = registry.getAllUnique();
397 if (unsorted.size() < minOpenTransactions) {
401 List<CloseTrackedRegistryReportEntry<T>> entries = new ArrayList<>(unsorted);
402 entries.sort((o1, o2) -> Long.compare(o2.getNumberAddedNotRemoved(), o1.getNumberAddedNotRemoved()));
404 if (!entries.isEmpty()) {
405 ps.println(indent + registry.getAnchor() + " : " + registry.getCreateDescription());
407 entries.forEach(entry -> {
408 ps.println(indent + " " + entry.getNumberAddedNotRemoved()
409 + "x transactions opened here, which are not closed:");
410 printStackTraceElements(ps, indent + " ", entry.getStackTraceElements());
412 if (!entries.isEmpty()) {
418 private void printStackTraceElements(final PrintStream ps, final String indent,
419 final List<StackTraceElement> stackTraceElements) {
420 boolean ellipsis = false;
421 for (final StackTraceElement stackTraceElement : stackTraceElements) {
422 if (isStackTraceElementInteresting(stackTraceElement)) {
423 ps.println(indent + stackTraceElement);
425 } else if (!ellipsis) {
426 ps.println(indent + "(...)");
432 private boolean isStackTraceElementInteresting(final StackTraceElement element) {
433 final String className = element.getClassName();
434 return !className.startsWith(getClass().getPackage().getName())
435 && !className.startsWith(CloseTracked.class.getPackage().getName())
436 && !className.startsWith("Proxy")
437 && !className.startsWith("akka")
438 && !className.startsWith("scala")
439 && !className.startsWith("sun.reflect")
440 && !className.startsWith("java.lang.reflect")
441 && !className.startsWith("org.apache.aries.blueprint")
442 && !className.startsWith("org.osgi.util.tracker");