Fix log initialization timing

* Support the lazy initialization log
* Move the log configuration timing for xml config

Fixes mybatisgh-1272

Author: kazuki43zoo

src/main/java/org/apache/ibatis/builder/xml/XMLConfigBuilder.java

@@ -1,5 +1,5 @@
 /**
- *    Copyright 2009-2017 the original author or authors.
+ *    Copyright 2009-2018 the original author or authors.
  *
  *    Licensed under the Apache License, Version 2.0 (the "License");
  *    you may not use this file except in compliance with the License.
@@ -105,6 +105,7 @@ private void parseConfiguration(XNode root) {
       //issue #117 read properties first
       propertiesElement(root.evalNode("properties"));
       Properties settings = settingsAsProperties(root.evalNode("settings"));
+      setLogImpl(settings);
       loadCustomVfs(settings);
       typeAliasesElement(root.evalNode("typeAliases"));
       pluginElement(root.evalNode("plugins"));
@@ -151,6 +152,11 @@ private void loadCustomVfs(Properties props) throws ClassNotFoundException {
     }
   }
 
+  private void setLogImpl(Properties props) {
+    Class<? extends Log> logImpl = resolveClass(props.getProperty("logImpl"));
+    configuration.setLogImpl(logImpl);
+  }
+
   private void typeAliasesElement(XNode parent) {
     if (parent != null) {
       for (XNode child : parent.getChildren()) {
@@ -262,9 +268,6 @@ private void settingsElement(Properties props) throws Exception {
     configuration.setUseActualParamName(booleanValueOf(props.getProperty("useActualParamName"), true));
     configuration.setReturnInstanceForEmptyRow(booleanValueOf(props.getProperty("returnInstanceForEmptyRow"), false));
     configuration.setLogPrefix(props.getProperty("logPrefix"));
-    @SuppressWarnings("unchecked")
-    Class<? extends Log> logImpl = (Class<? extends Log>)resolveClass(props.getProperty("logImpl"));
-    configuration.setLogImpl(logImpl);
     configuration.setConfigurationFactory(resolveClass(props.getProperty("configurationFactory")));
   }
 

src/main/java/org/apache/ibatis/datasource/pooled/PooledDataSource.java

@@ -1,5 +1,5 @@
 /**
- *    Copyright 2009-2017 the original author or authors.
+ *    Copyright 2009-2018 the original author or authors.
  *
  *    Licensed under the Apache License, Version 2.0 (the "License");
  *    you may not use this file except in compliance with the License.
@@ -39,7 +39,7 @@
  */
 public class PooledDataSource implements DataSource {
 
-  private static final Log log = LogFactory.getLog(PooledDataSource.class);
+  private static final Log log = LogFactory.getLazyInitializationLog(PooledDataSource.class);
 
   private final PoolState state = new PoolState(this);
 

src/main/java/org/apache/ibatis/executor/loader/javassist/JavassistProxyFactory.java

@@ -1,5 +1,5 @@
 /**
- *    Copyright 2009-2017 the original author or authors.
+ *    Copyright 2009-2018 the original author or authors.
  *
  *    Licensed under the Apache License, Version 2.0 (the "License");
  *    you may not use this file except in compliance with the License.
@@ -44,7 +44,7 @@
  */
 public class JavassistProxyFactory implements org.apache.ibatis.executor.loader.ProxyFactory {
 
-  private static final Log log = LogFactory.getLog(JavassistProxyFactory.class);
+  private static final Log log = LogFactory.getLazyInitializationLog(JavassistProxyFactory.class);
   private static final String FINALIZE_METHOD = "finalize";
   private static final String WRITE_REPLACE_METHOD = "writeReplace";
 

src/main/java/org/apache/ibatis/logging/LogFactory.java

@@ -1,5 +1,5 @@
 /**
- *    Copyright 2009-2016 the original author or authors.
+ *    Copyright 2009-2018 the original author or authors.
  *
  *    Licensed under the Apache License, Version 2.0 (the "License");
  *    you may not use this file except in compliance with the License.
@@ -15,11 +15,15 @@
  */
 package org.apache.ibatis.logging;
 
+import org.apache.ibatis.util.Lazy;
+
 import java.lang.reflect.Constructor;
+import java.lang.reflect.Proxy;
 
 /**
  * @author Clinton Begin
  * @author Eduardo Macarron
+ * @author Kazuki Shimizu
  */
 public final class LogFactory {
 
@@ -85,6 +89,30 @@ public static Log getLog(String logger) {
     }
   }
 
+  /**
+   * Returns a log that lazy initialization.
+   *
+   * @param aClass a logger class
+   * @return a log that lazy initialization(proxied log object)
+   * @since 3.5.0
+   */
+  public static Log getLazyInitializationLog(Class<?> aClass) {
+    return getLazyInitializationLog(aClass.getName());
+  }
+
+  /**
+   * Returns a log that lazy initialization.
+   *
+   * @param logger a logger name
+   * @return a log that lazy initialization(proxied log object)
+   * @since 3.5.0
+   */
+  public static Log getLazyInitializationLog(String logger) {
+    Lazy<Log> lazyLog = Lazy.of(() -> getLog(logger));
+    return (Log) Proxy.newProxyInstance(Log.class.getClassLoader(), new Class<?>[]{Log.class},
+        (proxy, method, args) -> method.invoke(lazyLog.get(), args));
+  }
+
   public static synchronized void useCustomLogging(Class<? extends Log> clazz) {
     setImplementation(clazz);
   }

src/main/java/org/apache/ibatis/session/AutoMappingUnknownColumnBehavior.java

@@ -1,5 +1,5 @@
 /**
- *    Copyright 2009-2016 the original author or authors.
+ *    Copyright 2009-2018 the original author or authors.
  *
  *    Licensed under the Apache License, Version 2.0 (the "License");
  *    you may not use this file except in compliance with the License.
@@ -62,7 +62,7 @@ public void doAction(MappedStatement mappedStatement, String columnName, String
   /**
    * Logger
    */
-  private static final Log log = LogFactory.getLog(AutoMappingUnknownColumnBehavior.class);
+  private static final Log log = LogFactory.getLazyInitializationLog(AutoMappingUnknownColumnBehavior.class);
 
   /**
    * Perform the action when detects an unknown column (or unknown property type) of automatic mapping target.

src/main/java/org/apache/ibatis/util/Lazy.java

@@ -0,0 +1,86 @@
+/**
+ *    Copyright 2009-2018 the original author or authors.
+ *
+ *    Licensed under the Apache License, Version 2.0 (the "License");
+ *    you may not use this file except in compliance with the License.
+ *    You may obtain a copy of the License at
+ *
+ *       http://www.apache.org/licenses/LICENSE-2.0
+ *
+ *    Unless required by applicable law or agreed to in writing, software
+ *    distributed under the License is distributed on an "AS IS" BASIS,
+ *    WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ *    See the License for the specific language governing permissions and
+ *    limitations under the License.
+ */
+package org.apache.ibatis.util;
+
+import java.util.function.Supplier;
+
+/**
+ * The container to delay the creation of an object using a {@link Supplier}.
+ * <p>
+ * Note, that no concurrency control is applied during the lookup of {@link #get()} or {@link #getNullable()},
+ * which means in concurrent access scenarios, the provided {@link Supplier} can be called multiple times.
+ *
+ * @param <T> object type
+ * @author Kazuki Shimizu
+ * @since 3.5.0
+ */
+public class Lazy<T> {
+
+  private final Supplier<? extends T> supplier;
+  private T object = null;
+  private boolean resolved = false;
+
+  private Lazy(Supplier<? extends T> supplier) {
+    this.supplier = supplier;
+  }
+
+  /**
+   * Creates a new {@link Lazy} to produce an object lazily.
+   *
+   * @param <T> the type of which to produce an object of eventually.
+   * @param supplier the {@link Supplier} to create the object lazily.
+   * @return a new {@link Lazy}
+   * @throws IllegalArgumentException If specified supplier is {@literal null}
+   */
+  public static <T> Lazy<T> of(Supplier<? extends T> supplier) {
+    if (supplier == null) {
+      throw new IllegalArgumentException("'supplier' must be specified.");
+    }
+    return new Lazy<>(supplier);
+  }
+
+  /**
+   * Returns the object created by the specified {@link Supplier}.
+   * lookups.
+   *
+   * @return the object created by the specified {@link Supplier}
+   * @throws IllegalStateException If the object created by the configured {@link Supplier} is {@literal null}
+   */
+  public T get() {
+    T object = getNullable();
+    if (object == null) {
+      throw new IllegalStateException("Expected lazy evaluation to yield a non-null object but got null.");
+    }
+    return object;
+  }
+
+  /**
+   * Returns the object created by the specified {@link Supplier}.
+   *
+   * @return the object created by the specified {@link Supplier}
+   */
+  public T getNullable() {
+    T resolvedObject = this.object;
+    if (this.resolved) {
+      return resolvedObject;
+    }
+    T creationObject = supplier.get();
+    this.object = creationObject;
+    this.resolved = true;
+    return creationObject;
+  }
+
+}

src/main/java/org/apache/ibatis/util/package-info.java

@@ -0,0 +1,19 @@
+/**
+ *    Copyright 2009-2018 the original author or authors.
+ *
+ *    Licensed under the Apache License, Version 2.0 (the "License");
+ *    you may not use this file except in compliance with the License.
+ *    You may obtain a copy of the License at
+ *
+ *       http://www.apache.org/licenses/LICENSE-2.0
+ *
+ *    Unless required by applicable law or agreed to in writing, software
+ *    distributed under the License is distributed on an "AS IS" BASIS,
+ *    WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ *    See the License for the specific language governing permissions and
+ *    limitations under the License.
+ */
+/**
+ * Utilities.
+ */
+package org.apache.ibatis.util;

src/test/java/log4j.properties

@@ -1,5 +1,5 @@
 #
-#    Copyright 2009-2016 the original author or authors.
+#    Copyright 2009-2018 the original author or authors.
 #
 #    Licensed under the Apache License, Version 2.0 (the "License");
 #    you may not use this file except in compliance with the License.
@@ -20,11 +20,7 @@ log4j.rootLogger=ERROR, stdout
 ### Uncomment for MyBatis logging
 log4j.logger.org.apache.ibatis=ERROR
 
-log4j.logger.org.apache.ibatis.session.AutoMappingUnknownColumnBehavior=WARN, lastEventSavedAppender
-
 ### Console output...
 log4j.appender.stdout=org.apache.log4j.ConsoleAppender
 log4j.appender.stdout.layout=org.apache.log4j.PatternLayout
 log4j.appender.stdout.layout.ConversionPattern=%5p [%t] - %m%n
-
-log4j.appender.lastEventSavedAppender=org.apache.ibatis.session.AutoMappingUnknownColumnBehaviorTest$LastEventSavedAppender

src/test/java/org/apache/ibatis/logging/LogFactoryTest.java

@@ -28,7 +28,9 @@
 import org.apache.ibatis.logging.slf4j.Slf4jImpl;
 import org.apache.ibatis.logging.stdout.StdOutImpl;
 import org.apache.ibatis.session.SqlSessionFactoryBuilder;
+import org.apache.ibatis.test.logging.MockitoLogImpl;
 import org.junit.Test;
+import org.mockito.Mockito;
 
 public class LogFactoryTest {
 
@@ -106,4 +108,48 @@ private void logSomething(Log log) {
     log.error("Error with Exception.", new Exception("Test exception."));
   }
 
+  @Test
+  public void shouldLazyInitializationLogByClass() {
+    Class<? extends Log> currentLogImplClass = LogFactory.getLog(LogFactoryTest.class).getClass();
+    try {
+      Log log = LogFactory.getLazyInitializationLog(LogFactoryTest.class);
+
+      LogFactory.useCustomLogging(MockitoLogImpl.class);
+      MockitoLogImpl.reset();
+
+      log.warn("log message");
+
+      Mockito.verify(MockitoLogImpl.logs.get(LogFactoryTest.class.getName())).warn("log message");
+
+    } finally {
+      try {
+        LogFactory.useCustomLogging(currentLogImplClass);
+      } finally {
+        MockitoLogImpl.reset();
+      }
+    }
+  }
+
+  @Test
+  public void shouldLazyInitializationLogByName() {
+    String loggerName = LogFactoryTest.class.getName() + ".byName";
+    Class<? extends Log> currentLogImplClass = LogFactory.getLog(loggerName).getClass();
+    try {
+      Log log = LogFactory.getLazyInitializationLog(loggerName);
+
+      LogFactory.useCustomLogging(MockitoLogImpl.class);
+      MockitoLogImpl.reset();
+
+      log.warn("log message");
+
+      Mockito.verify(MockitoLogImpl.logs.get(loggerName)).warn("log message");
+
+    } finally {
+      try {
+        LogFactory.useCustomLogging(currentLogImplClass);
+      } finally {
+        MockitoLogImpl.reset();
+      }
+    }
+  }
 }

src/test/java/org/apache/ibatis/session/AutoMappingUnknownColumnBehaviorTest.java

@@ -19,18 +19,21 @@
 import org.apache.ibatis.annotations.Select;
 import org.apache.ibatis.domain.blog.Author;
 import org.apache.ibatis.exceptions.PersistenceException;
+import org.apache.ibatis.logging.Log;
+import org.apache.ibatis.logging.LogFactory;
 import org.apache.ibatis.mapping.Environment;
+import org.apache.ibatis.test.logging.MockitoLogImpl;
 import org.apache.ibatis.transaction.TransactionFactory;
 import org.apache.ibatis.transaction.jdbc.JdbcTransactionFactory;
-import org.apache.log4j.spi.LoggingEvent;
-import org.apache.log4j.varia.NullAppender;
+import org.junit.AfterClass;
 import org.junit.BeforeClass;
 import org.junit.Test;
 
 import javax.sql.DataSource;
 import java.util.concurrent.atomic.AtomicInteger;
 
 import static org.assertj.core.api.Assertions.assertThat;
+import static org.mockito.Mockito.*;
 
 /**
  * Tests for specify the behavior when detects an unknown column (or unknown property type) of automatic mapping target.
@@ -80,24 +83,27 @@ public void setUsername(String username) {
         }
     }
 
-    public static class LastEventSavedAppender extends NullAppender {
-        private static LoggingEvent event;
-
-        public void doAppend(LoggingEvent event) {
-            LastEventSavedAppender.event = event;
-        }
-    }
-
     private static SqlSessionFactory sqlSessionFactory;
+    private static Class<? extends Log> originalLogImplClass;
 
     @BeforeClass
     public static void setup() throws Exception {
+        originalLogImplClass = LogFactory.getLog(AutoMappingUnknownColumnBehaviorTest.class).getClass();
+
         DataSource dataSource = BaseDataTest.createBlogDataSource();
         TransactionFactory transactionFactory = new JdbcTransactionFactory();
         Environment environment = new Environment("Production", transactionFactory, dataSource);
         Configuration configuration = new Configuration(environment);
         configuration.addMapper(Mapper.class);
         sqlSessionFactory = new SqlSessionFactoryBuilder().build(configuration);
+        sqlSessionFactory.getConfiguration().setLogImpl(MockitoLogImpl.class);
+
+        MockitoLogImpl.reset();
+    }
+
+    @AfterClass
+    public static void restore() {
+        LogFactory.useCustomLogging(originalLogImplClass);
     }
 
     @Test
@@ -119,7 +125,8 @@ public void warningCauseByUnknownPropertyType() {
             SimpleAuthor author = mapper.selectSimpleAuthor(101);
             assertThat(author.getId()).isNull();
             assertThat(author.getUsername()).isEqualTo("jim");
-            assertThat(LastEventSavedAppender.event.getMessage().toString()).isEqualTo("Unknown column is detected on 'org.apache.ibatis.session.AutoMappingUnknownColumnBehaviorTest$Mapper.selectSimpleAuthor' auto-mapping. Mapping parameters are [columnName=ID,propertyName=id,propertyType=java.util.concurrent.atomic.AtomicInteger]");
+            verify(MockitoLogImpl.logs.get(AutoMappingUnknownColumnBehavior.class.getName()), times(1))
+                .warn("Unknown column is detected on 'org.apache.ibatis.session.AutoMappingUnknownColumnBehaviorTest$Mapper.selectSimpleAuthor' auto-mapping. Mapping parameters are [columnName=ID,propertyName=id,propertyType=java.util.concurrent.atomic.AtomicInteger]");
         }
     }