killbill-memoizeit

diff --git a/util/src/main/java/org/killbill/billing/util/entity/dao/EntitySqlDaoTransactionalJdbiWrapper.java b/util/src/main/java/org/killbill/billing/util/entity/dao/EntitySqlDaoTransactionalJdbiWrapper.java
index 5215534..4cfd83a 100644
--- a/util/src/main/java/org/killbill/billing/util/entity/dao/EntitySqlDaoTransactionalJdbiWrapper.java
+++ b/util/src/main/java/org/killbill/billing/util/entity/dao/EntitySqlDaoTransactionalJdbiWrapper.java
@@ -1,7 +1,7 @@
 /*
  * Copyright 2010-2012 Ning, Inc.
- * Copyright 2014-2016 Groupon, Inc
- * Copyright 2014-2016 The Billing Project, LLC
+ * Copyright 2014-2018 Groupon, Inc
+ * Copyright 2014-2018 The Billing Project, LLC
  *
  * The Billing Project licenses this file to you under the Apache License, version 2.0
  * (the "License"); you may not use this file except in compliance with the
@@ -28,14 +28,17 @@ import org.killbill.clock.Clock;
 import org.skife.jdbi.v2.Handle;
 import org.skife.jdbi.v2.IDBI;
 import org.skife.jdbi.v2.Transaction;
-import org.skife.jdbi.v2.TransactionIsolationLevel;
 import org.skife.jdbi.v2.TransactionStatus;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
 
 /**
  * Transaction manager for EntitySqlDao queries
  */
 public class EntitySqlDaoTransactionalJdbiWrapper {
 
+    private final Logger logger = LoggerFactory.getLogger(EntitySqlDaoTransactionalJdbiWrapper.class);
+
     private final IDBI dbi;
     private final Clock clock;
     private final CacheControllerDispatcher cacheControllerDispatcher;
@@ -81,15 +84,22 @@ public class EntitySqlDaoTransactionalJdbiWrapper {
      * @return result from the transaction fo type ReturnType
      */
     public <ReturnType> ReturnType execute(final EntitySqlDaoTransactionWrapper<ReturnType> entitySqlDaoTransactionWrapper) {
+        final String debugInfo = logger.isDebugEnabled() ? getDebugInfo() : null;
+
         final Handle handle = dbi.open();
+        logger.debug("DBI handle created, transaction: {}", debugInfo);
         try {
             final EntitySqlDao<EntityModelDao<Entity>, Entity> entitySqlDao = handle.attach(InitialEntitySqlDao.class);
             // The transaction isolation level is now set at the pool level: this avoids 3 roundtrips for each transaction
             // Note that if the pool isn't used (tests or PostgreSQL), the transaction level will depend on the DB configuration
             //return entitySqlDao.inTransaction(TransactionIsolationLevel.READ_COMMITTED, new JdbiTransaction<ReturnType, EntityModelDao<Entity>, Entity>(handle, entitySqlDaoTransactionWrapper));
-            return entitySqlDao.inTransaction(new JdbiTransaction<ReturnType, EntityModelDao<Entity>, Entity>(handle, entitySqlDaoTransactionWrapper));
+            logger.debug("Starting transaction {}", debugInfo);
+            final ReturnType returnType = entitySqlDao.inTransaction(new JdbiTransaction<ReturnType, EntityModelDao<Entity>, Entity>(handle, entitySqlDaoTransactionWrapper));
+            logger.debug("Exiting  transaction {}, returning {}", debugInfo, returnType);
+            return returnType;
         } finally {
             handle.close();
+            logger.debug("DBI handle closed,  transaction: {}", debugInfo);
         }
     }
 
@@ -110,7 +120,7 @@ public class EntitySqlDaoTransactionalJdbiWrapper {
     public <ReturnType, E extends Exception> ReturnType execute(@Nullable final Class<E> exception, final EntitySqlDaoTransactionWrapper<ReturnType> entitySqlDaoTransactionWrapper) throws E {
         try {
             return execute(entitySqlDaoTransactionWrapper);
-        } catch (RuntimeException e) {
+        } catch (final RuntimeException e) {
             if (e.getCause() != null && exception != null && e.getCause().getClass().isAssignableFrom(exception)) {
                 throw (E) e.getCause();
             } else if (e.getCause() != null && e.getCause() instanceof RuntimeException) {
@@ -120,4 +130,31 @@ public class EntitySqlDaoTransactionalJdbiWrapper {
             }
         }
     }
+
+    private static String getDebugInfo() {
+        final Throwable t = new Throwable();
+        t.fillInStackTrace();
+
+        final StackTraceElement[] stackTrace = t.getStackTrace();
+        if (stackTrace == null) {
+            return null;
+        }
+
+        final StringBuilder dump = new StringBuilder();
+        int firstEntitySqlDaoCall = 0;
+
+        String className;
+        for (int i = 0; i < stackTrace.length; i++) {
+            className = stackTrace[i].getClassName();
+            if (className.startsWith("org.killbill.billing.util.entity.dao.EntitySqlDaoTransactionalJdbiWrapper")) {
+                firstEntitySqlDaoCall = i;
+            }
+        }
+        final int j = 1 + firstEntitySqlDaoCall;
+
+        dump.append(stackTrace[j].getClassName()).append(".").append(stackTrace[j].getMethodName()).append("(").
+                append(stackTrace[j].getFileName()).append(":").append(stackTrace[j].getLineNumber()).append(")");
+
+        return dump.toString();
+    }
 }

diff --git a/util/src/main/java/org/killbill/billing/util/glue/KillbillApiAopModule.java b/util/src/main/java/org/killbill/billing/util/glue/KillbillApiAopModule.java
index 68c6c04..9176282 100644
--- a/util/src/main/java/org/killbill/billing/util/glue/KillbillApiAopModule.java
+++ b/util/src/main/java/org/killbill/billing/util/glue/KillbillApiAopModule.java
@@ -1,6 +1,6 @@
 /*
- * Copyright 2014 Groupon, Inc
- * Copyright 2014 The Billing Project, LLC
+ * Copyright 2014-2018 Groupon, Inc
+ * Copyright 2014-2018 The Billing Project, LLC
  *
  * The Billing Project licenses this file to you under the Apache License, version 2.0
  * (the "License"); you may not use this file except in compliance with the
@@ -25,6 +25,8 @@ import org.killbill.billing.KillbillApi;
 import org.killbill.commons.profiling.Profiling;
 import org.killbill.commons.profiling.Profiling.WithProfilingCallback;
 import org.killbill.commons.profiling.ProfilingFeature.ProfilingFeatureType;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
 
 import com.google.inject.AbstractModule;
 import com.google.inject.matcher.Matcher;
@@ -32,6 +34,8 @@ import com.google.inject.matcher.Matchers;
 
 public class KillbillApiAopModule extends AbstractModule {
 
+    private static final Logger logger = LoggerFactory.getLogger(KillbillApiAopModule.class);
+
     @Override
     protected void configure() {
 
@@ -49,7 +53,10 @@ public class KillbillApiAopModule extends AbstractModule {
             return prof.executeWithProfiling(ProfilingFeatureType.API, invocation.getMethod().getName(), new WithProfilingCallback() {
                 @Override
                 public Object execute() throws Throwable {
-                    return invocation.proceed();
+                    logger.debug("Entering API call {}, arguments: {}", invocation.getMethod(), invocation.getArguments());
+                    final Object proceed = invocation.proceed();
+                    logger.debug("Exiting  API call {}, returning: {}", invocation.getMethod(), proceed);
+                    return proceed;
                 }
             });
         }