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.controller.md.sal.trace.dom.impl;
10 import java.io.PrintStream;
11 import java.util.ArrayList;
12 import java.util.HashMap;
13 import java.util.List;
15 import java.util.Objects;
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;
45 @SuppressWarnings("checkstyle:JavadocStyle")
46 //...because otherwise it whines about the elements in the @code block even though it's completely valid Javadoc
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.
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.
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:
63 * Simply add the dependency "mdsaltrace-features" to
68 * <groupId>org.opendaylight.controller</groupId>
69 * <artifactId>features-mdsal-trace</artifactId>
70 * <version>1.7.0-SNAPSHOT</version>
71 * <classifier>features</classifier>
73 * <scope>runtime</scope>
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.
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.
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 '/'.
93 * <h1>Known issues</h1>
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.
103 public class TracingBroker implements TracingDOMDataBroker {
105 static final Logger LOG = LoggerFactory.getLogger(TracingBroker.class);
107 private static final int STACK_TRACE_FIRST_RELEVANT_FRAME = 2;
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<>();
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;
120 private class Watch {
121 final String iidString;
122 final LogicalDatastoreType store;
124 Watch(String iidString, LogicalDatastoreType storeOrNull) {
125 this.store = storeOrNull;
126 this.iidString = iidString;
129 private String toIidCompString(YangInstanceIdentifier iid) {
130 StringBuilder builder = new StringBuilder();
131 toPathString(iid, builder);
133 return builder.toString();
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;
143 if (child.length() > 0 && child.charAt(0) == '<') {
144 childOffset = child.indexOf('>') + 1;
147 return child.startsWith(parent.substring(parentOffset), childOffset);
150 public boolean subtreesOverlap(YangInstanceIdentifier iid, LogicalDatastoreType store,
151 AsyncDataBroker.DataChangeScope scope) {
152 if (this.store != null && !this.store.equals(store)) {
156 String otherIidString = toIidCompString(iid);
159 return isParent(iidString, otherIidString);
160 case ONE: //for now just treat like SUBTREE, even though it's not
162 return isParent(iidString, otherIidString) || isParent(otherIidString, iidString);
168 public boolean eventIsOfInterest(YangInstanceIdentifier iid, LogicalDatastoreType store) {
169 if (this.store != null && !this.store.equals(store)) {
173 return isParent(iidString, toPathString(iid));
177 public TracingBroker(DOMDataBroker delegate, Config config, BindingNormalizedNodeSerializer codec) {
178 this.delegate = Objects.requireNonNull(delegate);
179 this.codec = Objects.requireNonNull(codec);
182 if (config.isTransactionDebugContextEnabled() != null) {
183 this.isDebugging = config.isTransactionDebugContextEnabled();
185 this.isDebugging = false;
187 final String db = "DataBroker";
188 this.transactionChainsRegistry = new CloseTrackedRegistry<>(db, "createTransactionChain()", isDebugging);
189 this.readOnlyTransactionsRegistry = new CloseTrackedRegistry<>(db, "newReadOnlyTransaction()", isDebugging);
190 this.writeTransactionsRegistry = new CloseTrackedRegistry<>(db, "newWriteOnlyTransaction()", isDebugging);
191 this.readWriteTransactionsRegistry = new CloseTrackedRegistry<>(db, "newReadWriteTransaction()", isDebugging);
194 private void configure(Config config) {
195 registrationWatches.clear();
196 List<String> paths = config.getRegistrationWatches();
198 for (String path : paths) {
199 watchRegistrations(path, null);
203 writeWatches.clear();
204 paths = config.getWriteWatches();
206 for (String path : paths) {
207 watchWrites(path, null);
213 * Log registrations to this subtree of the md-sal.
214 * @param iidString the iid path of the root of the subtree
215 * @param store Which LogicalDataStore? or null for both
217 public void watchRegistrations(String iidString, LogicalDatastoreType store) {
218 LOG.info("Watching registrations to {} in {}", iidString, store);
219 registrationWatches.add(new Watch(iidString, store));
223 * Log writes to this subtree of the md-sal.
224 * @param iidString the iid path of the root of the subtree
225 * @param store Which LogicalDataStore? or null for both
227 public void watchWrites(String iidString, LogicalDatastoreType store) {
228 LOG.info("Watching writes to {} in {}", iidString, store);
229 Watch watch = new Watch(iidString, store);
230 writeWatches.add(watch);
233 private boolean isRegistrationWatched(YangInstanceIdentifier iid,
234 LogicalDatastoreType store, DataChangeScope scope) {
235 if (registrationWatches.isEmpty()) {
239 for (Watch regInterest : registrationWatches) {
240 if (regInterest.subtreesOverlap(iid, store, scope)) {
248 boolean isWriteWatched(YangInstanceIdentifier iid, LogicalDatastoreType store) {
249 if (writeWatches.isEmpty()) {
253 for (Watch watch : writeWatches) {
254 if (watch.eventIsOfInterest(iid, store)) {
262 static void toPathString(InstanceIdentifier<? extends DataObject> iid, StringBuilder builder) {
263 for (InstanceIdentifier.PathArgument pathArg : iid.getPathArguments()) {
264 builder.append('/').append(pathArg.getType().getSimpleName());
268 String toPathString(YangInstanceIdentifier yiid) {
269 StringBuilder sb = new StringBuilder();
270 toPathString(yiid, sb);
271 return sb.toString();
275 private void toPathString(YangInstanceIdentifier yiid, StringBuilder sb) {
276 InstanceIdentifier<?> iid = codec.fromYangInstanceIdentifier(yiid);
278 reconstructIidPathString(yiid, sb);
280 toPathString(iid, sb);
284 private void reconstructIidPathString(YangInstanceIdentifier yiid, StringBuilder sb) {
285 sb.append("<RECONSTRUCTED FROM: \"").append(yiid.toString()).append("\">");
286 for (YangInstanceIdentifier.PathArgument pathArg : yiid.getPathArguments()) {
287 if (pathArg instanceof YangInstanceIdentifier.AugmentationIdentifier) {
288 sb.append('/').append("AUGMENTATION");
291 sb.append('/').append(pathArg.getNodeType().getLocalName());
295 String getStackSummary() {
296 StackTraceElement[] stack = Thread.currentThread().getStackTrace();
298 StringBuilder sb = new StringBuilder();
299 for (int i = STACK_TRACE_FIRST_RELEVANT_FRAME; i < stack.length; i++) {
300 StackTraceElement frame = stack[i];
301 sb.append("\n\t(TracingBroker)\t").append(frame.getClassName()).append('.').append(frame.getMethodName());
304 return sb.toString();
308 public DOMDataReadWriteTransaction newReadWriteTransaction() {
309 return new TracingReadWriteTransaction(delegate.newReadWriteTransaction(), this, readWriteTransactionsRegistry);
313 public DOMDataWriteTransaction newWriteOnlyTransaction() {
314 return new TracingWriteTransaction(delegate.newWriteOnlyTransaction(), this, writeTransactionsRegistry);
318 public ListenerRegistration<DOMDataChangeListener> registerDataChangeListener(
319 LogicalDatastoreType store, YangInstanceIdentifier yiid,
320 DOMDataChangeListener listener, DataChangeScope scope) {
321 if (isRegistrationWatched(yiid, store, scope)) {
322 LOG.warn("Registration (registerDataChangeListener) for {} from {}",
323 toPathString(yiid), getStackSummary());
325 return delegate.registerDataChangeListener(store, yiid, listener, scope);
329 public DOMTransactionChain createTransactionChain(TransactionChainListener transactionChainListener) {
330 return new TracingTransactionChain(
331 delegate.createTransactionChain(transactionChainListener), this, transactionChainsRegistry);
335 public DOMDataReadOnlyTransaction newReadOnlyTransaction() {
336 return new TracingReadOnlyTransaction(delegate.newReadOnlyTransaction(), this, readOnlyTransactionsRegistry);
341 public Map<Class<? extends DOMDataBrokerExtension>, DOMDataBrokerExtension> getSupportedExtensions() {
342 Map<Class<? extends DOMDataBrokerExtension>, DOMDataBrokerExtension> res = delegate.getSupportedExtensions();
343 DOMDataTreeChangeService treeChangeSvc = (DOMDataTreeChangeService) res.get(DOMDataTreeChangeService.class);
344 if (treeChangeSvc == null) {
348 res = new HashMap<>(res);
350 res.put(DOMDataTreeChangeService.class, new DOMDataTreeChangeService() {
353 public <L extends DOMDataTreeChangeListener> ListenerRegistration<L> registerDataTreeChangeListener(
354 @Nonnull DOMDataTreeIdentifier domDataTreeIdentifier, @Nonnull L listener) {
355 if (isRegistrationWatched(domDataTreeIdentifier.getRootIdentifier(),
356 domDataTreeIdentifier.getDatastoreType(), DataChangeScope.SUBTREE)) {
357 LOG.warn("{} registration (registerDataTreeChangeListener) for {} from {}.",
358 listener instanceof ClusteredDOMDataTreeChangeListener ? "Clustered" : "Non-clustered",
359 toPathString(domDataTreeIdentifier.getRootIdentifier()), getStackSummary());
361 return treeChangeSvc.registerDataTreeChangeListener(domDataTreeIdentifier, listener);
369 public boolean printOpenTransactions(PrintStream ps) {
370 if (transactionChainsRegistry.getAllUnique().isEmpty()
371 && readOnlyTransactionsRegistry.getAllUnique().isEmpty()
372 && writeTransactionsRegistry.getAllUnique().isEmpty()
373 && readWriteTransactionsRegistry.getAllUnique().isEmpty()) {
378 ps.println(getClass().getSimpleName() + " found some not yet (or never..) closed transaction[chain]s!");
379 ps.println("[NB: If no stack traces are shown below, then "
380 + "enable transaction-debug-context-enabled in mdsaltrace_config.xml]");
382 printRegistryOpenTransactions(readOnlyTransactionsRegistry, ps, " ");
383 printRegistryOpenTransactions(writeTransactionsRegistry, ps, " ");
384 printRegistryOpenTransactions(readWriteTransactionsRegistry, ps, " ");
386 // Now print details for each non-closed TransactionChain
387 // incl. in turn each ones own read/Write[Only]TransactionsRegistry
388 Set<CloseTrackedRegistryReportEntry<TracingTransactionChain>>
389 entries = transactionChainsRegistry.getAllUnique();
390 if (!entries.isEmpty()) {
391 ps.println(" " + transactionChainsRegistry.getAnchor() + " : "
392 + transactionChainsRegistry.getCreateDescription());
394 entries.forEach(entry -> {
395 ps.println(" " + entry.getNumberAddedNotRemoved() + "x TransactionChains opened but not closed here:");
396 printStackTraceElements(ps, " ", entry.getStackTraceElements());
397 @SuppressWarnings("resource")
398 TracingTransactionChain txChain = (TracingTransactionChain) entry
399 .getExampleCloseTracked().getRealCloseTracked();
400 printRegistryOpenTransactions(txChain.getReadOnlyTransactionsRegistry(), ps, " ");
401 printRegistryOpenTransactions(txChain.getWriteTransactionsRegistry(), ps, " ");
402 printRegistryOpenTransactions(txChain.getReadWriteTransactionsRegistry(), ps, " ");
409 private <T extends CloseTracked<T>> void printRegistryOpenTransactions(
410 CloseTrackedRegistry<T> registry, PrintStream ps, String indent) {
411 Set<CloseTrackedRegistryReportEntry<T>> entries = registry.getAllUnique();
412 if (!entries.isEmpty()) {
413 ps.println(indent + registry.getAnchor() + " : " + registry.getCreateDescription());
415 entries.forEach(entry -> {
416 ps.println(indent + " " + entry.getNumberAddedNotRemoved()
417 + "x transactions opened here, which are not closed:");
418 printStackTraceElements(ps, indent + " ", entry.getStackTraceElements());
420 if (!entries.isEmpty()) {
425 private void printStackTraceElements(PrintStream ps, String indent, List<StackTraceElement> stackTraceElements) {
426 boolean ellipsis = false;
427 for (final StackTraceElement stackTraceElement : stackTraceElements) {
428 if (isStackTraceElementInteresting(stackTraceElement)) {
429 ps.println(indent + stackTraceElement);
431 } else if (!ellipsis) {
432 ps.println(indent + "(...)");
438 private boolean isStackTraceElementInteresting(StackTraceElement element) {
439 final String className = element.getClassName();
440 return !className.startsWith(getClass().getPackage().getName())
441 && !className.startsWith(CloseTracked.class.getPackage().getName())
442 && !className.startsWith("Proxy")
443 && !className.startsWith("akka")
444 && !className.startsWith("scala")
445 && !className.startsWith("sun.reflect")
446 && !className.startsWith("java.lang.reflect")
447 && !className.startsWith("org.apache.aries.blueprint")
448 && !className.startsWith("org.osgi.util.tracker");