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