trace/mdsal-trace-impl/src/main/java/org/opendaylight/mdsal/trace/impl/TracingBroker.java

   1 /*
   2  * Copyright (c) 2016 Red Hat, Inc. and others.  All rights reserved.
   3  *
   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
   7  */
   8 package org.opendaylight.mdsal.trace.impl;
   9
  10 import static java.util.Objects.requireNonNull;
  11
  12 import edu.umd.cs.findbugs.annotations.SuppressFBWarnings;
  13 import java.io.PrintStream;
  14 import java.util.ArrayList;
  15 import java.util.List;
  16 import java.util.Set;
  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.ClusteredDOMDataTreeChangeListener;
  20 import org.opendaylight.mdsal.dom.api.DOMDataBroker;
  21 import org.opendaylight.mdsal.dom.api.DOMDataTreeChangeService;
  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.yang.binding.DataObject;
  29 import org.opendaylight.yangtools.yang.binding.InstanceIdentifier;
  30 import org.opendaylight.yangtools.yang.data.api.YangInstanceIdentifier;
  31 import org.slf4j.Logger;
  32 import org.slf4j.LoggerFactory;
  33
  34 @SuppressWarnings("checkstyle:JavadocStyle")
  35 //...because otherwise it whines about the elements in the @code block even though it's completely valid Javadoc
  36 /**
  37  * TracingBroker logs "write" operations and listener registrations to the md-sal. It logs the instance identifier path,
  38  * the objects themselves, as well as the stack trace of the call invoking the registration or write operation.
  39  * It works by operating as a "bump on the stack" between the application and actual DataBroker, intercepting write
  40  * and registration calls and writing to the log.
  41  *
  42  * <p>In addition, it (optionally) can also keep track of the stack trace of all new transaction allocations
  43  * (including TransactionChains, and transactions created in turn from them), in order to detect and report leaks
  44  * from transactions which were not closed.
  45  *
  46  * <h1>Wiring:</h1>
  47  * TracingBroker is designed to be easy to use. In fact, for bundles using Blueprint to inject their DataBroker
  48  * TracingBroker can be used without modifying your code at all in two simple steps:
  49  * <ol>
  50  * <li>
  51  * Simply add the dependency "mdsaltrace-features" to
  52  * your Karaf pom:
  53  * <pre>
  54  * {@code
  55  *  <dependency>
  56  *    <groupId>org.opendaylight.controller</groupId>
  57  *    <artifactId>features-mdsal-trace</artifactId>
  58  *    <version>1.7.0-SNAPSHOT</version>
  59  *    <classifier>features</classifier>
  60  *    <type>xml</type>
  61  *    <scope>runtime</scope>
  62  *  </dependency>
  63  * }
  64  * </pre>
  65  * </li>
  66  * <li>
  67  * Then just "feature:install odl-mdsal-trace" before you install your "real" feature(s) and you're done.
  68  * Beware that with Karaf 4 due to <a href="https://bugs.opendaylight.org/show_bug.cgi?id=9068">Bug 9068</a>
  69  * you'll probably have to use feature:install's --no-auto-refresh flag when installing your "real" feature.
  70  * </li>
  71  * </ol>
  72  * This works because the mdsaltrace-impl bundle registers its service implementing DOMDataBroker with a higher
  73  * rank than sal-binding-broker. As such, any OSGi service lookup for DataBroker will receive the TracingBroker.
  74  * <p> </p>
  75  * <h1>Avoiding log bloat:</h1>
  76  * TracingBroker can be configured to only print registrations or write ops pertaining to certain subtrees of the
  77  * md-sal. This can be done in the code via the methods of this class or via a config file. TracingBroker uses a more
  78  * convenient but non-standard representation of the instance identifiers. Each instance identifier segment's
  79  * class.getSimpleName() is used separated by a '/'.
  80  * <p> </p>
  81  * <h1>Known issues</h1>
  82  * <ul>
  83  *     <li>
  84  *        Filtering by paths. For some registrations the codec that converts back from the DOM to binding paths is
  85  *        busted. As such, an aproximated path is used in the output. For now it is recommended not to use
  86  *        watchRegistrations and allow all registrations to be logged.
  87  *     </li>
  88  * </ul>
  89  */
  90 public class TracingBroker implements TracingDOMDataBroker {
  91     private static final Logger LOG = LoggerFactory.getLogger(TracingBroker.class);
  92
  93     private static final int STACK_TRACE_FIRST_RELEVANT_FRAME = 2;
  94
  95     private final BindingCodecTree codec;
  96     private final DOMDataBroker delegate;
  97     private final List<Watch> registrationWatches = new ArrayList<>();
  98     private final List<Watch> writeWatches = new ArrayList<>();
  99
 100     private final boolean isDebugging;
 101     private final CloseTrackedRegistry<TracingTransactionChain> transactionChainsRegistry;
 102     private final CloseTrackedRegistry<TracingReadOnlyTransaction> readOnlyTransactionsRegistry;
 103     private final CloseTrackedRegistry<TracingWriteTransaction> writeTransactionsRegistry;
 104     private final CloseTrackedRegistry<TracingReadWriteTransaction> readWriteTransactionsRegistry;
 105
 106     private class Watch {
 107         final String iidString;
 108         final LogicalDatastoreType store;
 109
 110         Watch(final String iidString, final LogicalDatastoreType storeOrNull) {
 111             store = storeOrNull;
 112             this.iidString = iidString;
 113         }
 114
 115         private String toIidCompString(final YangInstanceIdentifier iid) {
 116             StringBuilder builder = new StringBuilder();
 117             toPathString(iid, builder);
 118             return builder.append('/').toString();
 119         }
 120
 121         private boolean isParent(final String parent, final String child) {
 122             int parentOffset = 0;
 123             if (parent.length() > 0 && parent.charAt(0) == '<') {
 124                 parentOffset = parent.indexOf('>') + 1;
 125             }
 126
 127             int childOffset = 0;
 128             if (child.length() > 0 && child.charAt(0) == '<') {
 129                 childOffset = child.indexOf('>') + 1;
 130             }
 131
 132             return child.startsWith(parent.substring(parentOffset), childOffset);
 133         }
 134
 135         @SuppressWarnings({ "checkstyle:hiddenField", "hiding" })
 136         public boolean subtreesOverlap(final YangInstanceIdentifier iid, final LogicalDatastoreType store) {
 137             if (this.store != null && !this.store.equals(store)) {
 138                 return false;
 139             }
 140
 141             String otherIidString = toIidCompString(iid);
 142             return isParent(iidString, otherIidString) || isParent(otherIidString, iidString);
 143         }
 144
 145         @SuppressWarnings({ "checkstyle:hiddenField", "hiding" })
 146         public boolean eventIsOfInterest(final YangInstanceIdentifier iid, final LogicalDatastoreType store) {
 147             if (this.store != null && !this.store.equals(store)) {
 148                 return false;
 149             }
 150
 151             return isParent(iidString, toPathString(iid));
 152         }
 153     }
 154
 155     public TracingBroker(final DOMDataBroker delegate, final Config config, final BindingCodecTree codec) {
 156         this.delegate = requireNonNull(delegate, "delegate");
 157         this.codec = requireNonNull(codec, "codec");
 158         configure(config);
 159
 160         isDebugging = Boolean.TRUE.equals(config.getTransactionDebugContextEnabled());
 161         final String db = "DataBroker";
 162         transactionChainsRegistry     = new CloseTrackedRegistry<>(db, "createTransactionChain()", isDebugging);
 163         readOnlyTransactionsRegistry  = new CloseTrackedRegistry<>(db, "newReadOnlyTransaction()", isDebugging);
 164         writeTransactionsRegistry     = new CloseTrackedRegistry<>(db, "newWriteOnlyTransaction()", isDebugging);
 165         readWriteTransactionsRegistry = new CloseTrackedRegistry<>(db, "newReadWriteTransaction()", isDebugging);
 166     }
 167
 168     private void configure(final Config config) {
 169         registrationWatches.clear();
 170         Set<String> paths = config.getRegistrationWatches();
 171         if (paths != null) {
 172             for (String path : paths) {
 173                 watchRegistrations(path, null);
 174             }
 175         }
 176
 177         writeWatches.clear();
 178         paths = config.getWriteWatches();
 179         if (paths != null) {
 180             for (String path : paths) {
 181                 watchWrites(path, null);
 182             }
 183         }
 184     }
 185
 186     /**
 187      * Log registrations to this subtree of the md-sal.
 188      * @param iidString the iid path of the root of the subtree
 189      * @param store Which LogicalDataStore? or null for both
 190      */
 191     public void watchRegistrations(final String iidString, final LogicalDatastoreType store) {
 192         LOG.info("Watching registrations to {} in {}", iidString, store);
 193         registrationWatches.add(new Watch(iidString, store));
 194     }
 195
 196     /**
 197      * Log writes to this subtree of the md-sal.
 198      * @param iidString the iid path of the root of the subtree
 199      * @param store Which LogicalDataStore? or null for both
 200      */
 201     public void watchWrites(final String iidString, final LogicalDatastoreType store) {
 202         LOG.info("Watching writes to {} in {}", iidString, store);
 203         Watch watch = new Watch(iidString, store);
 204         writeWatches.add(watch);
 205     }
 206
 207     private boolean isRegistrationWatched(final YangInstanceIdentifier iid, final LogicalDatastoreType store) {
 208         if (registrationWatches.isEmpty()) {
 209             return true;
 210         }
 211
 212         for (Watch regInterest : registrationWatches) {
 213             if (regInterest.subtreesOverlap(iid, store)) {
 214                 return true;
 215             }
 216         }
 217
 218         return false;
 219     }
 220
 221     boolean isWriteWatched(final YangInstanceIdentifier iid, final LogicalDatastoreType store) {
 222         if (writeWatches.isEmpty()) {
 223             return true;
 224         }
 225
 226         for (Watch watch : writeWatches) {
 227             if (watch.eventIsOfInterest(iid, store)) {
 228                 return true;
 229             }
 230         }
 231
 232         return false;
 233     }
 234
 235     static void toPathString(final InstanceIdentifier<? extends DataObject> iid, final StringBuilder builder) {
 236         for (var pathArg : iid.getPathArguments()) {
 237             builder.append('/').append(pathArg.type().getSimpleName());
 238         }
 239     }
 240
 241     String toPathString(final YangInstanceIdentifier  yiid) {
 242         StringBuilder sb = new StringBuilder();
 243         toPathString(yiid, sb);
 244         return sb.toString();
 245     }
 246
 247
 248     private void toPathString(final YangInstanceIdentifier yiid, final StringBuilder sb) {
 249         InstanceIdentifier<?> iid = codec.getInstanceIdentifierCodec().toBinding(yiid);
 250         if (null == iid) {
 251             reconstructIidPathString(yiid, sb);
 252         } else {
 253             toPathString(iid, sb);
 254         }
 255     }
 256
 257     private static void reconstructIidPathString(final YangInstanceIdentifier yiid, final StringBuilder sb) {
 258         sb.append("<RECONSTRUCTED FROM: \"").append(yiid.toString()).append("\">");
 259         for (YangInstanceIdentifier.PathArgument pathArg : yiid.getPathArguments()) {
 260             sb.append('/').append(pathArg.getNodeType().getLocalName());
 261         }
 262     }
 263
 264     String getStackSummary() {
 265         StackTraceElement[] stack = Thread.currentThread().getStackTrace();
 266
 267         StringBuilder sb = new StringBuilder();
 268         for (int i = STACK_TRACE_FIRST_RELEVANT_FRAME; i < stack.length; i++) {
 269             StackTraceElement frame = stack[i];
 270             sb.append("\n\t(TracingBroker)\t").append(frame.getClassName()).append('.').append(frame.getMethodName());
 271         }
 272
 273         return sb.toString();
 274     }
 275
 276     @Override
 277     public DOMDataTreeReadWriteTransaction newReadWriteTransaction() {
 278         return new TracingReadWriteTransaction(delegate.newReadWriteTransaction(), this, readWriteTransactionsRegistry);
 279     }
 280
 281     @Override
 282     public DOMDataTreeWriteTransaction newWriteOnlyTransaction() {
 283         return new TracingWriteTransaction(delegate.newWriteOnlyTransaction(), this, writeTransactionsRegistry);
 284     }
 285
 286     @Override
 287     public DOMTransactionChain createTransactionChain() {
 288         return new TracingTransactionChain(delegate.createTransactionChain(), this, transactionChainsRegistry);
 289     }
 290
 291     @Override
 292     public DOMTransactionChain createMergingTransactionChain() {
 293         return new TracingTransactionChain(delegate.createMergingTransactionChain(), this, transactionChainsRegistry);
 294     }
 295
 296     @Override
 297     public DOMDataTreeReadTransaction newReadOnlyTransaction() {
 298         return new TracingReadOnlyTransaction(delegate.newReadOnlyTransaction(), readOnlyTransactionsRegistry);
 299     }
 300
 301     @Override
 302     public <T extends Extension> T extension(final Class<T> type) {
 303         final var ext = delegate.extension(type);
 304         if (DOMDataTreeChangeService.class.equals(type) && ext instanceof DOMDataTreeChangeService treeChange) {
 305             return type.cast((DOMDataTreeChangeService) (domDataTreeIdentifier, listener) -> {
 306                 final var rootId = domDataTreeIdentifier.path();
 307                 if (isRegistrationWatched(rootId, domDataTreeIdentifier.datastore())) {
 308                     LOG.warn("{} registration (registerDataTreeChangeListener) for {} from {}.",
 309                         listener instanceof ClusteredDOMDataTreeChangeListener ? "Clustered" : "Non-clustered",
 310                             toPathString(rootId), getStackSummary());
 311                 }
 312                 return treeChange.registerDataTreeChangeListener(domDataTreeIdentifier, listener);
 313             });
 314         }
 315         return ext;
 316     }
 317
 318     @Override
 319     public boolean printOpenTransactions(final PrintStream ps, final int minOpenTXs) {
 320         if (transactionChainsRegistry.getAllUnique().isEmpty()
 321             && readOnlyTransactionsRegistry.getAllUnique().isEmpty()
 322             && writeTransactionsRegistry.getAllUnique().isEmpty()
 323             && readWriteTransactionsRegistry.getAllUnique().isEmpty()) {
 324
 325             ps.println("No open transactions, great!");
 326             return false;
 327         }
 328
 329         ps.println(getClass().getSimpleName() + " found some not yet (or never..) closed transaction[chain]s!");
 330         ps.println("[NB: If no stack traces are shown below, then "
 331                  + "enable transaction-debug-context-enabled in mdsaltrace_config.xml]");
 332         ps.println();
 333         // Flag to track if we really found any real leaks with more (or equal) to minOpenTXs
 334         boolean hasFound = print(readOnlyTransactionsRegistry, ps, "  ", minOpenTXs);
 335         hasFound |= print(writeTransactionsRegistry, ps, "  ", minOpenTXs);
 336         hasFound |= print(readWriteTransactionsRegistry, ps, "  ", minOpenTXs);
 337
 338         // Now print details for each non-closed TransactionChain
 339         // incl. in turn each ones own read/Write[Only]TransactionsRegistry
 340         Set<CloseTrackedRegistryReportEntry<TracingTransactionChain>>
 341             entries = transactionChainsRegistry.getAllUnique();
 342         if (!entries.isEmpty()) {
 343             ps.println("  " + transactionChainsRegistry.getAnchor() + " : "
 344                     + transactionChainsRegistry.getCreateDescription());
 345         }
 346         for (CloseTrackedRegistryReportEntry<TracingTransactionChain> entry : entries) {
 347             ps.println("    " + entry.getNumberAddedNotRemoved() + "x TransactionChains opened but not closed here:");
 348             printStackTraceElements(ps, "      ", entry.getStackTraceElements());
 349             @SuppressWarnings("resource")
 350             TracingTransactionChain txChain = (TracingTransactionChain) entry
 351                 .getExampleCloseTracked().getRealCloseTracked();
 352             hasFound |= print(txChain.getReadOnlyTransactionsRegistry(), ps, "        ", minOpenTXs);
 353             hasFound |= print(txChain.getWriteTransactionsRegistry(), ps, "        ", minOpenTXs);
 354             hasFound |= print(txChain.getReadWriteTransactionsRegistry(), ps, "        ", minOpenTXs);
 355         }
 356         ps.println();
 357
 358         return hasFound;
 359     }
 360
 361     final void logEmptySet(final YangInstanceIdentifier yiid) {
 362         if (LOG.isDebugEnabled()) {
 363             LOG.debug("Empty data set write to {}", toPathString(yiid));
 364         }
 365     }
 366
 367     @SuppressFBWarnings(value = "SLF4J_SIGN_ONLY_FORMAT", justification = "pre-formatted logs")
 368     static final void logOperations(final Object identifier, final List<?> operations) {
 369         if (LOG.isWarnEnabled()) {
 370             LOG.warn("Transaction {} contains the following operations:", identifier);
 371             for (var operation : operations) {
 372                 LOG.warn("{}", operation);
 373             }
 374         }
 375     }
 376
 377     private <T extends CloseTracked<T>> boolean print(final CloseTrackedRegistry<T> registry, final PrintStream ps,
 378             final String indent, final int minOpenTransactions) {
 379         Set<CloseTrackedRegistryReportEntry<T>> unsorted = registry.getAllUnique();
 380         if (unsorted.size() < minOpenTransactions) {
 381             return false;
 382         }
 383
 384         List<CloseTrackedRegistryReportEntry<T>> entries = new ArrayList<>(unsorted);
 385         entries.sort((o1, o2) -> Long.compare(o2.getNumberAddedNotRemoved(), o1.getNumberAddedNotRemoved()));
 386
 387         if (!entries.isEmpty()) {
 388             ps.println(indent + registry.getAnchor() + " : " + registry.getCreateDescription());
 389         }
 390         entries.forEach(entry -> {
 391             ps.println(indent + "  " + entry.getNumberAddedNotRemoved()
 392                 + "x transactions opened here, which are not closed:");
 393             printStackTraceElements(ps, indent + "    ", entry.getStackTraceElements());
 394         });
 395         if (!entries.isEmpty()) {
 396             ps.println();
 397         }
 398         return true;
 399     }
 400
 401     private void printStackTraceElements(final PrintStream ps, final String indent,
 402             final List<StackTraceElement> stackTraceElements) {
 403         boolean ellipsis = false;
 404         for (final StackTraceElement stackTraceElement : stackTraceElements) {
 405             if (isStackTraceElementInteresting(stackTraceElement)) {
 406                 ps.println(indent + stackTraceElement);
 407                 ellipsis = false;
 408             } else if (!ellipsis) {
 409                 ps.println(indent + "(...)");
 410                 ellipsis = true;
 411             }
 412         }
 413     }
 414
 415     private boolean isStackTraceElementInteresting(final StackTraceElement element) {
 416         final String className = element.getClassName();
 417         return !className.startsWith(getClass().getPackage().getName())
 418             && !className.startsWith(CloseTracked.class.getPackage().getName())
 419             && !className.startsWith("Proxy")
 420             && !className.startsWith("akka")
 421             && !className.startsWith("scala")
 422             && !className.startsWith("sun.reflect")
 423             && !className.startsWith("java.lang.reflect")
 424             && !className.startsWith("org.apache.aries.blueprint")
 425             && !className.startsWith("org.osgi.util.tracker");
 426     }
 427 }