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