util: print SQL Warnings in DEBUG mode

Signed-off-by: Pierre-Alexandre Meyer <pierre@mouraf.org>

pom.xml

@@ -21,7 +21,7 @@
     <parent>
         <artifactId>killbill-oss-parent</artifactId>
         <groupId>org.kill-bill.billing</groupId>
-        <version>0.141.44</version>
+        <version>0.141.45-SNAPSHOT</version>
     </parent>
     <artifactId>killbill</artifactId>
     <version>0.19.7-SNAPSHOT</version>

util/src/main/java/org/killbill/billing/util/entity/dao/EntitySqlDaoTransactionalJdbiWrapper.java

@@ -72,7 +72,7 @@ class JdbiTransaction<ReturnType, M extends EntityModelDao<E>, E extends Entity>
 
         @Override
         public ReturnType inTransaction(final EntitySqlDao<M, E> transactionalSqlDao, final TransactionStatus status) throws Exception {
-            final EntitySqlDaoWrapperFactory factoryEntitySqlDao = new EntitySqlDaoWrapperFactory(h, clock, cacheControllerDispatcher, nonEntityDao, internalCallContextFactory);
+            final EntitySqlDaoWrapperFactory factoryEntitySqlDao = new EntitySqlDaoWrapperFactory(h, clock, cacheControllerDispatcher, internalCallContextFactory);
             return entitySqlDaoTransactionWrapper.inTransaction(factoryEntitySqlDao);
         }
     }

util/src/main/java/org/killbill/billing/util/entity/dao/EntitySqlDaoWrapperFactory.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
@@ -22,7 +22,6 @@
 
 import org.killbill.billing.util.cache.CacheControllerDispatcher;
 import org.killbill.billing.util.callcontext.InternalCallContextFactory;
-import org.killbill.billing.util.dao.NonEntityDao;
 import org.killbill.billing.util.entity.Entity;
 import org.killbill.clock.Clock;
 import org.skife.jdbi.v2.Handle;
@@ -40,14 +39,12 @@ public class EntitySqlDaoWrapperFactory {
     private final Clock clock;
     private final CacheControllerDispatcher cacheControllerDispatcher;
 
-    private final NonEntityDao nonEntityDao;
     private final InternalCallContextFactory internalCallContextFactory;
 
-    public EntitySqlDaoWrapperFactory(final Handle handle, final Clock clock, final CacheControllerDispatcher cacheControllerDispatcher, final NonEntityDao nonEntityDao, final InternalCallContextFactory internalCallContextFactory) {
+    public EntitySqlDaoWrapperFactory(final Handle handle, final Clock clock, final CacheControllerDispatcher cacheControllerDispatcher, final InternalCallContextFactory internalCallContextFactory) {
         this.handle = handle;
         this.clock = clock;
         this.cacheControllerDispatcher = cacheControllerDispatcher;
-        this.nonEntityDao = nonEntityDao;
         this.internalCallContextFactory = internalCallContextFactory;
     }
 
@@ -76,7 +73,7 @@ NewEntity extends Entity> NewSqlDao create(final Class<NewSqlDao> newSqlDaoClass
         final ClassLoader classLoader = newSqlDao.getClass().getClassLoader();
         final Class[] interfacesToImplement = {newSqlDaoClass};
         final EntitySqlDaoWrapperInvocationHandler<NewSqlDao, NewEntityModelDao, NewEntity> wrapperInvocationHandler =
-                new EntitySqlDaoWrapperInvocationHandler<NewSqlDao, NewEntityModelDao, NewEntity>(newSqlDaoClass, newSqlDao, handle, clock, cacheControllerDispatcher, nonEntityDao, internalCallContextFactory);
+                new EntitySqlDaoWrapperInvocationHandler<NewSqlDao, NewEntityModelDao, NewEntity>(newSqlDaoClass, newSqlDao, handle, clock, cacheControllerDispatcher, internalCallContextFactory);
 
         final Object newSqlDaoObject = Proxy.newProxyInstance(classLoader, interfacesToImplement, wrapperInvocationHandler);
         return newSqlDaoClass.cast(newSqlDaoObject);

util/src/main/java/org/killbill/billing/util/entity/dao/EntitySqlDaoWrapperInvocationHandler.java

@@ -1,7 +1,7 @@
 /*
  * Copyright 2010-2012 Ning, Inc.
- * Copyright 2014-2017 Groupon, Inc
- * Copyright 2014-2017 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
@@ -20,11 +20,13 @@
 
 import java.lang.annotation.Annotation;
 import java.lang.reflect.InvocationHandler;
+import java.lang.reflect.InvocationTargetException;
 import java.lang.reflect.Method;
 import java.lang.reflect.ParameterizedType;
 import java.lang.reflect.Type;
 import java.sql.PreparedStatement;
 import java.sql.SQLException;
+import java.sql.SQLWarning;
 import java.util.Collection;
 import java.util.HashMap;
 import java.util.Iterator;
@@ -49,7 +51,6 @@
 import org.killbill.billing.util.callcontext.InternalCallContextFactory;
 import org.killbill.billing.util.dao.EntityAudit;
 import org.killbill.billing.util.dao.EntityHistoryModelDao;
-import org.killbill.billing.util.dao.NonEntityDao;
 import org.killbill.billing.util.dao.TableName;
 import org.killbill.billing.util.entity.Entity;
 import org.killbill.clock.Clock;
@@ -93,7 +94,6 @@ public class EntitySqlDaoWrapperInvocationHandler<S extends EntitySqlDao<M, E>,
 
     private final CacheControllerDispatcher cacheControllerDispatcher;
     private final Clock clock;
-    private final NonEntityDao nonEntityDao;
     private final InternalCallContextFactory internalCallContextFactory;
     private final Profiling<Object, Throwable> prof;
 
@@ -103,14 +103,12 @@ public EntitySqlDaoWrapperInvocationHandler(final Class<S> sqlDaoClass,
                                                 final Clock clock,
                                                 // Special DAO that don't require caching can invoke EntitySqlDaoWrapperInvocationHandler with no caching (e.g NoCachingTenantDao)
                                                 @Nullable final CacheControllerDispatcher cacheControllerDispatcher,
-                                                @Nullable final NonEntityDao nonEntityDao,
                                                 final InternalCallContextFactory internalCallContextFactory) {
         this.sqlDaoClass = sqlDaoClass;
         this.sqlDao = sqlDao;
         this.handle = handle;
         this.clock = clock;
         this.cacheControllerDispatcher = cacheControllerDispatcher;
-        this.nonEntityDao = nonEntityDao;
         this.internalCallContextFactory = internalCallContextFactory;
         this.prof = new Profiling<Object, Throwable>();
     }
@@ -124,7 +122,7 @@ public Object execute() throws Throwable {
                     return invokeSafely(proxy, method, args);
                 }
             });
-        } catch (Throwable t) {
+        } catch (final Throwable t) {
             if (t.getCause() != null && t.getCause().getCause() != null && DBIException.class.isAssignableFrom(t.getCause().getClass())) {
                 // Likely a JDBC error, try to extract the SQL statement and JDBI bindings
                 if (t.getCause() instanceof StatementException) {
@@ -208,7 +206,8 @@ private Object invokeRaw(final Method method, final Object[] args) throws Throwa
         return prof.executeWithProfiling(ProfilingFeatureType.DAO_DETAILS, getProfilingId("raw", method), new WithProfilingCallback<Object, Throwable>() {
             @Override
             public Object execute() throws Throwable {
-                Object result = method.invoke(sqlDao, args);
+                // Real jdbc call
+                final Object result = executeJDBCCall(method, args);
                 // This is *almost* the default invocation except that we want to intercept getById calls to populate the caches; the pattern is to always fetch
                 // the object after it was created, which means this method is (by pattern) first called right after object creation and contains all the goodies we care
                 // about (record_id, account_record_id, object_id, tenant_record_id)
@@ -324,14 +323,15 @@ private Object invokeWithAuditAndHistory(final Audited auditedAnnotation, final
         if (changeType == ChangeType.UPDATE || changeType == ChangeType.DELETE) {
             for (final String entityId : entityIds) {
                 deletedEntities.put(entityId, sqlDao.getById(entityId, context));
+                printSQLWarnings();
             }
         }
 
         // Real jdbc call
         final Object obj = prof.executeWithProfiling(ProfilingFeatureType.DAO_DETAILS, getProfilingId("raw", method), new WithProfilingCallback<Object, Throwable>() {
             @Override
             public Object execute() throws Throwable {
-                return method.invoke(sqlDao, args);
+                return executeJDBCCall(method, args);
             }
         });
 
@@ -350,6 +350,27 @@ public Object execute() throws Throwable {
         }
     }
 
+    private Object executeJDBCCall(final Method method, final Object[] args) throws IllegalAccessException, InvocationTargetException {
+        final Object invoke = method.invoke(sqlDao, args);
+        printSQLWarnings();
+        return invoke;
+    }
+
+    private void printSQLWarnings() {
+        if (logger.isDebugEnabled()) {
+            try {
+                SQLWarning warning = handle.getConnection().getWarnings();
+                while (warning != null) {
+                    logger.debug("[SQL WARNING] {}", warning);
+                    warning = warning.getNextWarning();
+                }
+                handle.getConnection().clearWarnings();
+            } catch (final SQLException e) {
+                logger.debug("Error whilst retrieving SQL warnings", e);
+            }
+        }
+    }
+
     private void populateCacheOnGetByIdInvocation(final M model) {
         populateCaches(cacheControllerDispatcher, model);
     }
@@ -388,6 +409,7 @@ public M execute() throws Throwable {
                 } else {
                     // See note above regarding "markAsInactive" operations
                     reHydratedEntity = MoreObjects.firstNonNull(sqlDao.getById(entityId, context), deletedEntity);
+                    printSQLWarnings();
                 }
                 Preconditions.checkNotNull(reHydratedEntity, "reHydratedEntity cannot be null");
                 final Long entityRecordId = reHydratedEntity.getRecordId();
@@ -483,7 +505,9 @@ private InternalCallContext retrieveContextFromArguments(final Object[] args) {
 
     private Long insertHistory(final Long entityRecordId, final M entityModelDao, final ChangeType changeType, final InternalCallContext context) {
         final EntityHistoryModelDao<M, E> history = new EntityHistoryModelDao<M, E>(entityModelDao, entityRecordId, changeType, clock.getUTCNow());
-        return sqlDao.addHistoryFromTransaction(history, context);
+        final Long recordId = sqlDao.addHistoryFromTransaction(history, context);
+        printSQLWarnings();
+        return recordId;
     }
 
     private void insertAudits(final TableName tableName, final M entityModelDao, final Long entityRecordId, final Long historyRecordId, final ChangeType changeType, final InternalCallContext contextMaybeWithoutAccountRecordId) {
@@ -500,6 +524,7 @@ private void insertAudits(final TableName tableName, final M entityModelDao, fin
             context = contextMaybeWithoutAccountRecordId;
         }
         sqlDao.insertAuditFromTransaction(audit, context);
+        printSQLWarnings();
 
         // We need to invalidate the caches. There is a small window of doom here where caches will be stale.
         // TODO Knowledge on how the key is constructed is also in AuditSqlDao