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 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;
  18 import java.util.Set;
  19 import org.opendaylight.mdsal.binding.dom.codec.api.BindingCodecTree;
  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;
  40
  41 @SuppressWarnings("checkstyle:JavadocStyle")
  42 //...because otherwise it whines about the elements in the @code block even though it's completely valid Javadoc
  43
  44 /**
  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.
  49  *
  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.
  53  *
  54  * <h1>Wiring:</h1>
  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:
  57  * <ol>
  58  * <li>
  59  * Simply add the dependency "mdsaltrace-features" to
  60  * your Karaf pom:
  61  * <pre>
  62  * {@code
  63  *  <dependency>
  64  *    <groupId>org.opendaylight.controller</groupId>
  65  *    <artifactId>features-mdsal-trace</artifactId>
  66  *    <version>1.7.0-SNAPSHOT</version>
  67  *    <classifier>features</classifier>
  68  *    <type>xml</type>
  69  *    <scope>runtime</scope>
  70  *  </dependency>
  71  * }
  72  * </pre>
  73  * </li>
  74  * <li>
  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.
  78  * </li>
  79  * </ol>
  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.
  82  * <p> </p>
  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 '/'.
  88  * <p> </p>
  89  * <h1>Known issues</h1>
  90  * <ul>
  91  *     <li>
  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.
  95  *     </li>
  96  * </ul>
  97  *
  98  */
  99 public class TracingBroker implements TracingDOMDataBroker {
 100     @SuppressFBWarnings("SLF4J_LOGGER_SHOULD_BE_PRIVATE")
 101     static final Logger LOG = LoggerFactory.getLogger(TracingBroker.class);
 102
 103     private static final int STACK_TRACE_FIRST_RELEVANT_FRAME = 2;
 104
 105     private final BindingCodecTree codec;
 106     private final DOMDataBroker delegate;
 107     private final List<Watch> registrationWatches = new ArrayList<>();
 108     private final List<Watch> writeWatches = new ArrayList<>();
 109
 110     private final boolean isDebugging;
 111     private final CloseTrackedRegistry<TracingTransactionChain> transactionChainsRegistry;
 112     private final CloseTrackedRegistry<TracingReadOnlyTransaction> readOnlyTransactionsRegistry;
 113     private final CloseTrackedRegistry<TracingWriteTransaction> writeTransactionsRegistry;
 114     private final CloseTrackedRegistry<TracingReadWriteTransaction> readWriteTransactionsRegistry;
 115
 116     private class Watch {
 117         final String iidString;
 118         final LogicalDatastoreType store;
 119
 120         Watch(final String iidString, final LogicalDatastoreType storeOrNull) {
 121             this.store = storeOrNull;
 122             this.iidString = iidString;
 123         }
 124
 125         private String toIidCompString(final YangInstanceIdentifier iid) {
 126             StringBuilder builder = new StringBuilder();
 127             toPathString(iid, builder);
 128             return builder.append('/').toString();
 129         }
 130
 131         private boolean isParent(final String parent, final String child) {
 132             int parentOffset = 0;
 133             if (parent.length() > 0 && parent.charAt(0) == '<') {
 134                 parentOffset = parent.indexOf('>') + 1;
 135             }
 136
 137             int childOffset = 0;
 138             if (child.length() > 0 && child.charAt(0) == '<') {
 139                 childOffset = child.indexOf('>') + 1;
 140             }
 141
 142             return child.startsWith(parent.substring(parentOffset), childOffset);
 143         }
 144
 145         @SuppressWarnings({ "checkstyle:hiddenField", "hiding" })
 146         public boolean subtreesOverlap(final YangInstanceIdentifier iid, final LogicalDatastoreType store) {
 147             if (this.store != null && !this.store.equals(store)) {
 148                 return false;
 149             }
 150
 151             String otherIidString = toIidCompString(iid);
 152             return isParent(iidString, otherIidString) || isParent(otherIidString, iidString);
 153         }
 154
 155         @SuppressWarnings({ "checkstyle:hiddenField", "hiding" })
 156         public boolean eventIsOfInterest(final YangInstanceIdentifier iid, final LogicalDatastoreType store) {
 157             if (this.store != null && !this.store.equals(store)) {
 158                 return false;
 159             }
 160
 161             return isParent(iidString, toPathString(iid));
 162         }
 163     }
 164
 165     public TracingBroker(final DOMDataBroker delegate, final Config config, final BindingCodecTree codec) {
 166         this.delegate = requireNonNull(delegate, "delegate");
 167         this.codec = requireNonNull(codec, "codec");
 168         configure(config);
 169
 170         this.isDebugging = Boolean.TRUE.equals(config.getTransactionDebugContextEnabled());
 171         final String db = "DataBroker";
 172         this.transactionChainsRegistry     = new CloseTrackedRegistry<>(db, "createTransactionChain()", isDebugging);
 173         this.readOnlyTransactionsRegistry  = new CloseTrackedRegistry<>(db, "newReadOnlyTransaction()", isDebugging);
 174         this.writeTransactionsRegistry     = new CloseTrackedRegistry<>(db, "newWriteOnlyTransaction()", isDebugging);
 175         this.readWriteTransactionsRegistry = new CloseTrackedRegistry<>(db, "newReadWriteTransaction()", isDebugging);
 176     }
 177
 178     private void configure(final Config config) {
 179         registrationWatches.clear();
 180         Set<String> paths = config.getRegistrationWatches();
 181         if (paths != null) {
 182             for (String path : paths) {
 183                 watchRegistrations(path, null);
 184             }
 185         }
 186
 187         writeWatches.clear();
 188         paths = config.getWriteWatches();
 189         if (paths != null) {
 190             for (String path : paths) {
 191                 watchWrites(path, null);
 192             }
 193         }
 194     }
 195
 196     /**
 197      * Log registrations 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 watchRegistrations(final String iidString, final LogicalDatastoreType store) {
 202         LOG.info("Watching registrations to {} in {}", iidString, store);
 203         registrationWatches.add(new Watch(iidString, store));
 204     }
 205
 206     /**
 207      * Log writes to this subtree of the md-sal.
 208      * @param iidString the iid path of the root of the subtree
 209      * @param store Which LogicalDataStore? or null for both
 210      */
 211     public void watchWrites(final String iidString, final LogicalDatastoreType store) {
 212         LOG.info("Watching writes to {} in {}", iidString, store);
 213         Watch watch = new Watch(iidString, store);
 214         writeWatches.add(watch);
 215     }
 216
 217     @SuppressFBWarnings(value = "UPM_UNCALLED_PRIVATE_METHOD",
 218             justification = "https://github.com/spotbugs/spotbugs/issues/811")
 219     private boolean isRegistrationWatched(final YangInstanceIdentifier iid, final LogicalDatastoreType store) {
 220         if (registrationWatches.isEmpty()) {
 221             return true;
 222         }
 223
 224         for (Watch regInterest : registrationWatches) {
 225             if (regInterest.subtreesOverlap(iid, store)) {
 226                 return true;
 227             }
 228         }
 229
 230         return false;
 231     }
 232
 233     boolean isWriteWatched(final YangInstanceIdentifier iid, final LogicalDatastoreType store) {
 234         if (writeWatches.isEmpty()) {
 235             return true;
 236         }
 237
 238         for (Watch watch : writeWatches) {
 239             if (watch.eventIsOfInterest(iid, store)) {
 240                 return true;
 241             }
 242         }
 243
 244         return false;
 245     }
 246
 247     static void toPathString(final InstanceIdentifier<? extends DataObject> iid, final StringBuilder builder) {
 248         for (InstanceIdentifier.PathArgument pathArg : iid.getPathArguments()) {
 249             builder.append('/').append(pathArg.getType().getSimpleName());
 250         }
 251     }
 252
 253     String toPathString(final YangInstanceIdentifier  yiid) {
 254         StringBuilder sb = new StringBuilder();
 255         toPathString(yiid, sb);
 256         return sb.toString();
 257     }
 258
 259
 260     private void toPathString(final YangInstanceIdentifier yiid, final StringBuilder sb) {
 261         InstanceIdentifier<?> iid = codec.getInstanceIdentifierCodec().toBinding(yiid);
 262         if (null == iid) {
 263             reconstructIidPathString(yiid, sb);
 264         } else {
 265             toPathString(iid, sb);
 266         }
 267     }
 268
 269     private static void reconstructIidPathString(final YangInstanceIdentifier yiid, final StringBuilder sb) {
 270         sb.append("<RECONSTRUCTED FROM: \"").append(yiid.toString()).append("\">");
 271         for (YangInstanceIdentifier.PathArgument pathArg : yiid.getPathArguments()) {
 272             if (pathArg instanceof YangInstanceIdentifier.AugmentationIdentifier) {
 273                 sb.append('/').append("AUGMENTATION");
 274                 continue;
 275             }
 276             sb.append('/').append(pathArg.getNodeType().getLocalName());
 277         }
 278     }
 279
 280     String getStackSummary() {
 281         StackTraceElement[] stack = Thread.currentThread().getStackTrace();
 282
 283         StringBuilder sb = new StringBuilder();
 284         for (int i = STACK_TRACE_FIRST_RELEVANT_FRAME; i < stack.length; i++) {
 285             StackTraceElement frame = stack[i];
 286             sb.append("\n\t(TracingBroker)\t").append(frame.getClassName()).append('.').append(frame.getMethodName());
 287         }
 288
 289         return sb.toString();
 290     }
 291
 292     @Override
 293     public DOMDataTreeReadWriteTransaction newReadWriteTransaction() {
 294         return new TracingReadWriteTransaction(delegate.newReadWriteTransaction(), this, readWriteTransactionsRegistry);
 295     }
 296
 297     @Override
 298     public DOMDataTreeWriteTransaction newWriteOnlyTransaction() {
 299         return new TracingWriteTransaction(delegate.newWriteOnlyTransaction(), this, writeTransactionsRegistry);
 300     }
 301
 302     @Override
 303     public DOMTransactionChain createTransactionChain(final DOMTransactionChainListener transactionChainListener) {
 304         return new TracingTransactionChain(delegate.createTransactionChain(transactionChainListener), this,
 305             transactionChainsRegistry);
 306     }
 307
 308     @Override
 309     public DOMTransactionChain createMergingTransactionChain(
 310             final DOMTransactionChainListener transactionChainListener) {
 311         return new TracingTransactionChain(delegate.createMergingTransactionChain(transactionChainListener), this,
 312             transactionChainsRegistry);
 313     }
 314
 315     @Override
 316     public DOMDataTreeReadTransaction newReadOnlyTransaction() {
 317         return new TracingReadOnlyTransaction(delegate.newReadOnlyTransaction(), readOnlyTransactionsRegistry);
 318     }
 319
 320     @Override
 321     public ClassToInstanceMap<DOMDataBrokerExtension> getExtensions() {
 322         final ClassToInstanceMap<DOMDataBrokerExtension> delegateExt = delegate.getExtensions();
 323         final DOMDataTreeChangeService treeChangeSvc = delegateExt.getInstance(DOMDataTreeChangeService.class);
 324         if (treeChangeSvc == null) {
 325             return delegateExt;
 326         }
 327
 328         final ClassToInstanceMap<DOMDataBrokerExtension> res = MutableClassToInstanceMap.create(delegateExt);
 329         res.put(DOMDataTreeChangeService.class, new DOMDataTreeChangeService() {
 330             @Override
 331             public <L extends DOMDataTreeChangeListener> ListenerRegistration<L> registerDataTreeChangeListener(
 332                     final DOMDataTreeIdentifier domDataTreeIdentifier, final L listener) {
 333                 if (isRegistrationWatched(domDataTreeIdentifier.getRootIdentifier(),
 334                         domDataTreeIdentifier.getDatastoreType())) {
 335                     LOG.warn("{} registration (registerDataTreeChangeListener) for {} from {}.",
 336                             listener instanceof ClusteredDOMDataTreeChangeListener ? "Clustered" : "Non-clustered",
 337                             toPathString(domDataTreeIdentifier.getRootIdentifier()), getStackSummary());
 338                 }
 339                 return treeChangeSvc.registerDataTreeChangeListener(domDataTreeIdentifier, listener);
 340             }
 341         });
 342
 343         return res;
 344     }
 345
 346     @Override
 347     public boolean printOpenTransactions(final PrintStream ps, final int minOpenTXs) {
 348         if (transactionChainsRegistry.getAllUnique().isEmpty()
 349             && readOnlyTransactionsRegistry.getAllUnique().isEmpty()
 350             && writeTransactionsRegistry.getAllUnique().isEmpty()
 351             && readWriteTransactionsRegistry.getAllUnique().isEmpty()) {
 352
 353             ps.println("No open transactions, great!");
 354             return false;
 355         }
 356
 357         ps.println(getClass().getSimpleName() + " found some not yet (or never..) closed transaction[chain]s!");
 358         ps.println("[NB: If no stack traces are shown below, then "
 359                  + "enable transaction-debug-context-enabled in mdsaltrace_config.xml]");
 360         ps.println();
 361         // Flag to track if we really found any real leaks with more (or equal) to minOpenTXs
 362         boolean hasFound = print(readOnlyTransactionsRegistry, ps, "  ", minOpenTXs);
 363         hasFound |= print(writeTransactionsRegistry, ps, "  ", minOpenTXs);
 364         hasFound |= print(readWriteTransactionsRegistry, ps, "  ", minOpenTXs);
 365
 366         // Now print details for each non-closed TransactionChain
 367         // incl. in turn each ones own read/Write[Only]TransactionsRegistry
 368         Set<CloseTrackedRegistryReportEntry<TracingTransactionChain>>
 369             entries = transactionChainsRegistry.getAllUnique();
 370         if (!entries.isEmpty()) {
 371             ps.println("  " + transactionChainsRegistry.getAnchor() + " : "
 372                     + transactionChainsRegistry.getCreateDescription());
 373         }
 374         for (CloseTrackedRegistryReportEntry<TracingTransactionChain> entry : entries) {
 375             ps.println("    " + entry.getNumberAddedNotRemoved() + "x TransactionChains opened but not closed here:");
 376             printStackTraceElements(ps, "      ", entry.getStackTraceElements());
 377             @SuppressWarnings("resource")
 378             TracingTransactionChain txChain = (TracingTransactionChain) entry
 379                 .getExampleCloseTracked().getRealCloseTracked();
 380             hasFound |= print(txChain.getReadOnlyTransactionsRegistry(), ps, "        ", minOpenTXs);
 381             hasFound |= print(txChain.getWriteTransactionsRegistry(), ps, "        ", minOpenTXs);
 382             hasFound |= print(txChain.getReadWriteTransactionsRegistry(), ps, "        ", minOpenTXs);
 383         }
 384         ps.println();
 385
 386         return hasFound;
 387     }
 388
 389     private <T extends CloseTracked<T>> boolean print(final CloseTrackedRegistry<T> registry, final PrintStream ps,
 390             final String indent, final int minOpenTransactions) {
 391         Set<CloseTrackedRegistryReportEntry<T>> unsorted = registry.getAllUnique();
 392         if (unsorted.size() < minOpenTransactions) {
 393             return false;
 394         }
 395
 396         List<CloseTrackedRegistryReportEntry<T>> entries = new ArrayList<>(unsorted);
 397         entries.sort((o1, o2) -> Long.compare(o2.getNumberAddedNotRemoved(), o1.getNumberAddedNotRemoved()));
 398
 399         if (!entries.isEmpty()) {
 400             ps.println(indent + registry.getAnchor() + " : " + registry.getCreateDescription());
 401         }
 402         entries.forEach(entry -> {
 403             ps.println(indent + "  " + entry.getNumberAddedNotRemoved()
 404                 + "x transactions opened here, which are not closed:");
 405             printStackTraceElements(ps, indent + "    ", entry.getStackTraceElements());
 406         });
 407         if (!entries.isEmpty()) {
 408             ps.println();
 409         }
 410         return true;
 411     }
 412
 413     private void printStackTraceElements(final PrintStream ps, final String indent,
 414             final List<StackTraceElement> stackTraceElements) {
 415         boolean ellipsis = false;
 416         for (final StackTraceElement stackTraceElement : stackTraceElements) {
 417             if (isStackTraceElementInteresting(stackTraceElement)) {
 418                 ps.println(indent + stackTraceElement);
 419                 ellipsis = false;
 420             } else if (!ellipsis) {
 421                 ps.println(indent + "(...)");
 422                 ellipsis = true;
 423             }
 424         }
 425     }
 426
 427     private boolean isStackTraceElementInteresting(final StackTraceElement element) {
 428         final String className = element.getClassName();
 429         return !className.startsWith(getClass().getPackage().getName())
 430             && !className.startsWith(CloseTracked.class.getPackage().getName())
 431             && !className.startsWith("Proxy")
 432             && !className.startsWith("akka")
 433             && !className.startsWith("scala")
 434             && !className.startsWith("sun.reflect")
 435             && !className.startsWith("java.lang.reflect")
 436             && !className.startsWith("org.apache.aries.blueprint")
 437             && !className.startsWith("org.osgi.util.tracker");
 438     }
 439 }