Bugfix: leverage async appender to avoid blocking thread (#579)

microsoft · Aug 22, 2023 · e3edd72 · e3edd72
1 parent 936a39b
commit e3edd72
Show file tree

Hide file tree

Showing 3 changed files with 85 additions and 40 deletions.
diff --git a/agent/src/main/resources/logback-common.xml b/agent/src/main/resources/logback-common.xml
@@ -43,15 +43,13 @@
     </appender>
 
     <appender name="errorAlarm" class="com.microsoft.hydralab.common.exception.handler.LogbackExceptionHandler">
-        <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
-            <level>ERROR</level>
-        </filter>
     </appender>
 
-    <appender name="warnAlarm" class="com.microsoft.hydralab.common.exception.handler.LogbackExceptionHandler">
-        <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
-            <level>WARN</level>
-        </filter>
+    <appender name ="asyncAlarm" class= "ch.qos.logback.classic.AsyncAppender">
+        <discardingThreshold >20</discardingThreshold>
+        <queueSize>256</queueSize>
+        <neverBlock>true</neverBlock>
+        <appender-ref ref ="errorAlarm"/>
     </appender>
 
     <root level="info">
@@ -64,14 +62,16 @@
     <logger name="com.microsoft" level="debug" additivity="false">
         <appender-ref ref="syslog"/>
         <appender-ref ref="STDOUT"/>
-        <appender-ref ref="errorAlarm"/>
-        <appender-ref ref="warnAlarm"/>
     </logger>
     <logger name="logger.devices" level="debug" additivity="false">
     </logger>
     <logger name="access" level="info" additivity="false">
         <appender-ref ref="accessLog"/>
-        <appender-ref ref="errorAlarm"/>
-        <appender-ref ref="warnAlarm"/>
+    </logger>
+    <logger name="com.microsoft" level="warn" additivity="false">
+        <appender-ref ref="asyncAlarm"/>
+    </logger>
+    <logger name="access" level="warn" additivity="false">
+        <appender-ref ref="asyncAlarm"/>
     </logger>
 </configuration>
diff --git a/agent/src/test/java/com/microsoft/hydralab/agent/exception/ExceptionReporterManagerTest.java b/agent/src/test/java/com/microsoft/hydralab/agent/exception/ExceptionReporterManagerTest.java
@@ -2,53 +2,98 @@
 
 import com.microsoft.hydralab.agent.config.AppOptions;
 import com.microsoft.hydralab.agent.test.BaseTest;
-import com.microsoft.hydralab.common.exception.reporter.AppCenterReporter;
-import com.microsoft.hydralab.common.exception.reporter.ExceptionReporterManager;
-import com.microsoft.hydralab.common.exception.reporter.FileReporter;
+import com.microsoft.hydralab.common.util.DateUtil;
 import com.microsoft.hydralab.common.util.FileUtil;
 import org.junit.jupiter.api.Assertions;
 import org.junit.jupiter.api.MethodOrderer;
-import org.junit.jupiter.api.Order;
 import org.junit.jupiter.api.Test;
 import org.junit.jupiter.api.TestMethodOrder;
 
 import javax.annotation.Resource;
 import java.io.File;
+import java.util.Date;
+import java.util.concurrent.atomic.AtomicInteger;
 
 @TestMethodOrder(MethodOrderer.OrderAnnotation.class)
 class ExceptionReporterManagerTest extends BaseTest {
     @Resource
     AppOptions appOptions;
 
-    @Test
-    @Order(1)
-    void registerExceptionReporter() {
-        AppCenterReporter appCenterReporter = new AppCenterReporter();
-        ExceptionReporterManager.registerExceptionReporter(appCenterReporter);
-        ExceptionReporterManager.registerExceptionReporter(new FileReporter(appOptions.getErrorStorageLocation()));
-    }
+    private static Object lock = new Object();
+    final AtomicInteger count = new AtomicInteger(ROUNDS);
+    static final int ROUNDS = 10;
 
     @Test
-    @Order(2)
     void reportException() {
+        count.set(ROUNDS);
         File folder = new File(appOptions.getErrorStorageLocation());
         if (folder.exists()) {
             FileUtil.deleteFile(folder);
         }
         folder.mkdir();
-        ExceptionReporterManager.reportException(new Exception("test exception1"), true);
-        Assertions.assertEquals(1, folder.listFiles().length, "should have one file");
+        Runnable logError = () -> {
+            baseLogger.error("test exception: {}", Thread.currentThread().getName());
+            try {
+                Thread.sleep(1000);
+            } catch (InterruptedException e) {
+                throw new RuntimeException(e);
+            }
+            synchronized (lock) {
+                if (count.decrementAndGet() == 0) {
+                    lock.notifyAll();
+                }
+            }
+
+        };
+        for (int i = ROUNDS; i > 0; i--) {
+            new Thread(logError).start();
+        }
+        synchronized (lock) {
+            try {
+                lock.wait();
+            } catch (InterruptedException e) {
+                throw new RuntimeException(e);
+            }
+        }
+        File errorFileFolder = new File(folder, DateUtil.ymdFormat.format(new Date()));
+        Assertions.assertEquals(ROUNDS, errorFileFolder.listFiles().length, "should have " + ROUNDS + " file");
+        FileUtil.deleteFile(folder);
     }
 
     @Test
-    @Order(2)
-    void testReportException() {
+    void reportWarning() {
+        count.set(ROUNDS);
         File folder = new File(appOptions.getErrorStorageLocation());
         if (folder.exists()) {
             FileUtil.deleteFile(folder);
         }
         folder.mkdir();
-        ExceptionReporterManager.reportException(new Exception("test exception2"), Thread.currentThread(), true);
-        Assertions.assertEquals(1, folder.listFiles().length, "should have one file");
+        Runnable logWarn = () -> {
+            baseLogger.warn("test warning: {}", Thread.currentThread().getName());
+            try {
+                Thread.sleep(1000);
+            } catch (InterruptedException e) {
+                throw new RuntimeException(e);
+            }
+            synchronized (lock) {
+                if (count.decrementAndGet() == 0) {
+                    lock.notifyAll();
+                }
+            }
+
+        };
+        for (int i = ROUNDS; i > 0; i--) {
+            new Thread(logWarn).start();
+        }
+        synchronized (lock) {
+            try {
+                lock.wait();
+            } catch (InterruptedException e) {
+                throw new RuntimeException(e);
+            }
+        }
+        File warnFileFolder = new File(folder, DateUtil.ymdFormat.format(new Date()));
+        Assertions.assertEquals(ROUNDS, warnFileFolder.listFiles().length, "should have " + ROUNDS + " file");
+        FileUtil.deleteFile(folder);
     }
 }
diff --git a/center/src/main/resources/logback-common.xml b/center/src/main/resources/logback-common.xml
@@ -43,15 +43,13 @@
     </appender>
 
     <appender name="errorAlarm" class="com.microsoft.hydralab.common.exception.handler.LogbackExceptionHandler">
-        <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
-            <level>ERROR</level>
-        </filter>
     </appender>
 
-    <appender name="warnAlarm" class="com.microsoft.hydralab.common.exception.handler.LogbackExceptionHandler">
-        <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
-            <level>WARN</level>
-        </filter>
+    <appender name ="asyncAlarm" class= "ch.qos.logback.classic.AsyncAppender">
+        <discardingThreshold >20</discardingThreshold>
+        <queueSize>256</queueSize>
+        <neverBlock>true</neverBlock>
+        <appender-ref ref ="errorAlarm"/>
     </appender>
 
     <root level="info">
@@ -64,14 +62,16 @@
     <logger name="com.microsoft" level="debug" additivity="false">
         <appender-ref ref="syslog"/>
         <appender-ref ref="STDOUT"/>
-        <appender-ref ref="errorAlarm"/>
-        <appender-ref ref="warnAlarm"/>
     </logger>
     <logger name="logger.devices" level="debug" additivity="false">
     </logger>
     <logger name="access" level="info" additivity="false">
         <appender-ref ref="accessLog"/>
-        <appender-ref ref="errorAlarm"/>
-        <appender-ref ref="warnAlarm"/>
+    </logger>
+    <logger name="com.microsoft" level="warn" additivity="false">
+        <appender-ref ref="asyncAlarm"/>
+    </logger>
+    <logger name="access" level="warn" additivity="false">
+        <appender-ref ref="asyncAlarm"/>
     </logger>
 </configuration>