Fix logger factory lazy initialization problem (rabbitmq#133)

Author: alaneuler

pom.xml

@@ -4,7 +4,7 @@
 
     <groupId>com.alipay.sofa.common</groupId>
     <artifactId>sofa-common-tools</artifactId>
-    <version>1.3.2</version>
+    <version>1.3.3</version>
     <packaging>jar</packaging>
 
     <name>${project.groupId}:${project.artifactId}</name>

src/main/java/com/alipay/sofa/common/log/LoggerSpaceManager.java

@@ -22,6 +22,8 @@
 import org.slf4j.ILoggerFactory;
 import org.slf4j.Logger;
 
+import java.util.Collection;
+import java.util.Collections;
 import java.util.Map;
 
 /**
@@ -41,7 +43,7 @@ public class LoggerSpaceManager {
      * @return logger of org.slf4j.Logger type
      */
     public static Logger getLoggerBySpace(String name, String spaceName) {
-        return MultiAppLoggerSpaceManager.getLoggerBySpace(name, spaceName);
+        return getLoggerBySpace(name, new SpaceId(spaceName), Collections.emptyMap());
     }
 
     /**

src/main/java/com/alipay/sofa/common/log/MultiAppLoggerSpaceManager.java

@@ -24,6 +24,7 @@
 import com.alipay.sofa.common.log.factory.LoggerSpaceFactory4Log4jBuilder;
 import com.alipay.sofa.common.log.factory.LoggerSpaceFactory4LogbackBuilder;
 import com.alipay.sofa.common.log.factory.LoggerSpaceFactoryBuilder;
+import com.alipay.sofa.common.log.proxy.TemporaryILoggerFactoryPool;
 import com.alipay.sofa.common.space.SpaceId;
 import com.alipay.sofa.common.utils.ClassLoaderUtil;
 import com.alipay.sofa.common.utils.ReportUtil;
@@ -111,12 +112,7 @@ static void doInit(String spaceName, Map<String, String> props, ClassLoader spac
      */
     static void doInit(SpaceId spaceId, Map<String, String> props, ClassLoader spaceClassloader) {
         LogSpace logSpace = new LogSpace(props, spaceClassloader);
-
-        AbstractLoggerSpaceFactory loggerSpaceFactory = createILoggerFactory(spaceId, logSpace,
-            spaceClassloader);
-        logSpace.setAbstractLoggerSpaceFactory(loggerSpaceFactory);
-
-        LOG_FACTORY_MAP.put(spaceId, logSpace);
+        LOG_FACTORY_MAP.putIfAbsent(spaceId, logSpace);
     }
 
     /**
@@ -187,11 +183,24 @@ public static Logger getLoggerBySpace(String name, com.alipay.sofa.common.log.Sp
     private static AbstractLoggerSpaceFactory getILoggerFactoryBySpaceName(SpaceId spaceId,
                                                                            ClassLoader spaceClassloader) {
         if (!isSpaceInitialized(spaceId)) {
-            // If get logger without initializing, log space will be initialized with empty config map
-            init(spaceId, null, spaceClassloader);
+            return TemporaryILoggerFactoryPool.get(spaceId, spaceClassloader);
         }
 
-        return LOG_FACTORY_MAP.get(spaceId).getAbstractLoggerSpaceFactory();
+        AbstractLoggerSpaceFactory factory = NOP_LOGGER_FACTORY;
+        LogSpace space = LOG_FACTORY_MAP.get(spaceId);
+        if (!isSpaceILoggerFactoryExisted(spaceId)) {
+            synchronized (space) {
+                if (!isSpaceILoggerFactoryExisted(spaceId)) {
+                    factory = createILoggerFactory(spaceId, space, spaceClassloader);
+                    space.setAbstractLoggerSpaceFactory(factory);
+                }
+            }
+        } else {
+            factory = LOG_FACTORY_MAP.get(spaceId).getAbstractLoggerSpaceFactory();
+        }
+
+
+        return factory;
     }
 
     public static Logger setLoggerLevel(String loggerName, String spaceName,
@@ -258,6 +267,11 @@ public static boolean isSpaceInitialized(com.alipay.sofa.common.log.SpaceId spac
         return LOG_FACTORY_MAP.containsKey(spaceId);
     }
 
+    private static boolean isSpaceILoggerFactoryExisted(SpaceId spaceId) {
+        return isSpaceInitialized(spaceId)
+                && LOG_FACTORY_MAP.get(spaceId).getAbstractLoggerSpaceFactory() != null;
+    }
+
     @Deprecated
     public static Map getSpacesMap() {
         return Collections.emptyMap();

src/main/java/com/alipay/sofa/common/log/proxy/LoggerProxy.java

@@ -23,7 +23,6 @@
 /**
  * Created by [email protected] on 2016/12/1.
  */
-@Deprecated
 public class LoggerProxy implements Logger {
 
     private TemporaryILoggerFactory.LoggerSelector loggerSelector;

src/main/java/com/alipay/sofa/common/log/proxy/TemporaryILoggerFactory.java

@@ -26,7 +26,6 @@
  * space
  * Created by [email protected] on 2016/12/1.
  */
-@Deprecated
 public class TemporaryILoggerFactory extends AbstractLoggerSpaceFactory {
 
     private final String      space;

src/main/java/com/alipay/sofa/common/log/proxy/TemporaryILoggerFactoryPool.java

@@ -26,7 +26,6 @@
 /**
  * Created by [email protected] on 2016/12/5.
  */
-@Deprecated
 public class TemporaryILoggerFactoryPool {
 
     private static final ConcurrentHashMap<SpaceIdWithClassloader, TemporaryILoggerFactory> temporaryILoggerFactoryMap = new ConcurrentHashMap<SpaceIdWithClassloader, TemporaryILoggerFactory>();

src/test/java/com/alipay/sofa/common/log/LazyLogFactoryInitializingTest.java

@@ -0,0 +1,89 @@
+/*
+ * Licensed to the Apache Software Foundation (ASF) under one or more
+ * contributor license agreements.  See the NOTICE file distributed with
+ * this work for additional information regarding copyright ownership.
+ * The ASF 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 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 com.alipay.sofa.common.log;
+
+import org.junit.Assert;
+import org.junit.Test;
+import org.slf4j.Logger;
+
+import java.io.File;
+import java.nio.charset.StandardCharsets;
+import java.nio.file.Files;
+import java.nio.file.Paths;
+import java.util.HashMap;
+import java.util.List;
+import java.util.Map;
+
+/**
+ * @author <a href="mailto:[email protected]">Alaneuler</a>
+ * Created on 2021/3/3
+ */
+public class LazyLogFactoryInitializingTest {
+    public static final String SPACE_NAME = "lazy.init";
+
+    static {
+        System.setProperty(Constants.LOGBACK_MIDDLEWARE_LOG_DISABLE_PROP_KEY, "true");
+    }
+
+    public static Logger       logger     = MultiAppLoggerSpaceManager.getLoggerBySpace(
+                                              "LAZY-INIT", SPACE_NAME);
+
+    @Test
+    public void test() throws Exception {
+        logger.info("test1");
+        logger.info("test2");
+        logger.info("test3");
+        logger.info("test4");
+
+        File directory = new File(Constants.LOGGING_PATH_DEFAULT + "/lazy");
+        if (directory.isDirectory()) {
+            File[] files = directory.listFiles();
+            if (files != null) {
+                for (File f : files) {
+                    if (f.getName().startsWith("monitor.log")) {
+                        Assert.fail();
+                    }
+                }
+            }
+        }
+
+        Map<String, String> props = new HashMap<>();
+        props.put("logging.path." + SPACE_NAME, "./logs/");
+        props.put("logging.level." + SPACE_NAME, "INFO");
+        props.put("date.pattern." + SPACE_NAME, "yyyy-MM-dd");
+        MultiAppLoggerSpaceManager.init(SPACE_NAME, props);
+
+        try {
+            Files.write(Paths.get("./logs/lazy/monitor.log"), "".getBytes(StandardCharsets.UTF_8));
+        } catch (Throwable e) {
+            // just ignore
+        }
+        logger.info("test1");
+        logger.info("test2");
+        logger.info("test3");
+        logger.info("test4");
+
+        List<String> lines = Files.readAllLines(Paths.get("./logs/lazy/monitor.log"), StandardCharsets.UTF_8);
+        int count = 0;
+        for (String line : lines) {
+            if (line.contains("LAZY-INIT - test")) {
+                ++count;
+            }
+        }
+        Assert.assertTrue(count >= 4);
+    }
+}

src/test/resources/lazy/init/log/log4j2/log-conf.xml

@@ -0,0 +1,23 @@
+<?xml version="1.0" encoding="UTF-8"?>
+<Configuration status="OFF">
+    <Appenders>
+        <RollingFile name="LAZY-INIT-APPENDER"
+                     fileName="${logging.path.lazy.init}/lazy/monitor.log" append="true"
+                     filePattern="${logging.path.lazy.init}/lazy/monitor.log.%d{${date.pattern.lazy.init}}">
+            <ThresholdFilter level="${logging.level.lazy.init}" onMatch="ACCEPT" onMismatch="DENY"/>
+            <PatternLayout charset="UTF-8">
+                <pattern>%d [%t] %-5p %c{2} - %m%n %throwable</pattern>
+            </PatternLayout>
+            <Policies>
+                <!-- 按天分日志文件:重要的是 filePattern 配置到按照天 -->
+                <TimeBasedTriggeringPolicy interval="1" modulate="true"/>
+            </Policies>
+        </RollingFile>
+    </Appenders>
+
+    <Loggers>
+        <Logger name="LAZY-INIT" level="${logging.level.lazy.init}" additivity="false">
+            <AppenderRef ref="LAZY-INIT-APPENDER"/>
+        </Logger>
+    </Loggers>
+</Configuration>