Merge pull request opensearch-project#602 from AndreKurait/EnhancedLo…

…gging Enhance logging with Async and high performance appenders
gregschohn · Apr 23, 2024 · d8b4ba8 · d8b4ba8
2 parents ccb316d + 643e8e9
commit d8b4ba8
Show file tree

Hide file tree

Showing 9 changed files with 47 additions and 22 deletions.
diff --git a/TrafficCapture/build.gradle b/TrafficCapture/build.gradle
@@ -110,6 +110,8 @@ allprojects {
             //  Disable parallel test execution, see MIGRATIONS-1666
             systemProperty 'junit.jupiter.execution.parallel.enabled', 'false'
         }
+        systemProperty 'log4j2.contextSelector', 'org.apache.logging.log4j.core.selector.BasicContextSelector'
+        jvmArgs '-ea'
     }
 
     test {

diff --git a/TrafficCapture/trafficCaptureProxyServer/build.gradle b/TrafficCapture/trafficCaptureProxyServer/build.gradle
@@ -29,10 +29,12 @@ dependencies {
     implementation project(':coreUtilities')
 
     implementation group: 'io.netty', name: 'netty-all', version: '4.1.100.Final'
-    implementation group: 'org.apache.logging.log4j', name: 'log4j-api', version: '2.20.0'
-    implementation group: 'org.apache.logging.log4j', name: 'log4j-core', version: '2.20.0'
-    implementation group: 'org.apache.logging.log4j', name: 'log4j-slf4j2-impl', version: '2.20.0'
-    implementation group: 'org.slf4j', name: 'slf4j-api', version: '2.0.7'
+
+    implementation group: 'org.apache.logging.log4j', name: 'log4j-api', version: '2.23.1'
+    implementation group: 'org.apache.logging.log4j', name: 'log4j-core', version: '2.23.1'
+    implementation group: 'org.apache.logging.log4j', name: 'log4j-slf4j2-impl', version: '2.23.1'
+    implementation group: 'org.slf4j', name: 'slf4j-api', version: '2.0.13'
+    implementation group: 'com.lmax', name: 'disruptor', version: '4.0.0'
 
     implementation group: 'com.beust', name: 'jcommander', version: '1.82'
     implementation 'com.google.protobuf:protobuf-java:3.22.2'

diff --git a/TrafficCapture/trafficCaptureProxyServer/src/main/resources/log4j2.component.properties b/TrafficCapture/trafficCaptureProxyServer/src/main/resources/log4j2.component.properties
@@ -0,0 +1,2 @@
+Log4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector
+AsyncLogger.WaitStrategy=Yield
diff --git a/TrafficCapture/trafficCaptureProxyServer/src/main/resources/log4j2.properties b/TrafficCapture/trafficCaptureProxyServer/src/main/resources/log4j2.properties
@@ -6,7 +6,8 @@ appender.console.type = Console
 appender.console.name = STDERR
 appender.console.target = SYSTEM_ERR
 appender.console.layout.type = PatternLayout
-appender.console.layout.pattern = [%-5level] %d{yyyy-MM-dd HH:mm:ss,SSS}{UTC} [%t] %c{1} - %msg%equals{ ctx=%mdc}{ ctx=\{\}}{}%n
+appender.console.layout.pattern = [%-5level] %d{DEFAULT_MICROS}{UTC} [%t] %c{1} - %msg%equals{ ctx=%mdc}{ ctx=\{\}}{}%n
+appender.console.direct = true
 
 rootLogger.level = info
 rootLogger.appenderRefs = stderr

diff --git a/TrafficCapture/trafficReplayer/build.gradle b/TrafficCapture/trafficReplayer/build.gradle
@@ -50,11 +50,14 @@ dependencies {
     implementation group: 'io.github.resilience4j', name: 'resilience4j-ratelimiter', version:"${resilience4jVersion}"
     implementation group: 'io.github.resilience4j', name: 'resilience4j-retry', version:"${resilience4jVersion}"
     implementation group: 'io.netty', name: 'netty-all', version: '4.1.100.Final'
+
     implementation group: 'org.apache.kafka', name: 'kafka-clients', version: '3.6.0'
-    implementation group: 'org.apache.logging.log4j', name: 'log4j-api', version: '2.20.0'
-    implementation group: 'org.apache.logging.log4j', name: 'log4j-core', version: '2.20.0'
-    implementation group: 'org.apache.logging.log4j', name: 'log4j-slf4j2-impl', version: '2.20.0'
-    implementation group: 'org.slf4j', name: 'slf4j-api', version: '2.0.7'
+    implementation group: 'org.apache.logging.log4j', name: 'log4j-api', version: '2.23.1'
+    implementation group: 'org.apache.logging.log4j', name: 'log4j-core', version: '2.23.1'
+    implementation group: 'org.apache.logging.log4j', name: 'log4j-slf4j2-impl', version: '2.23.1'
+    implementation group: 'org.slf4j', name: 'slf4j-api', version: '2.0.13'
+    implementation group: 'com.lmax', name: 'disruptor', version: '4.0.0'
+
     implementation group: 'software.amazon.awssdk', name: 'arns', version: '2.20.102'
     implementation group: 'software.amazon.awssdk', name: 'auth', version: '2.20.102'
     implementation group: 'software.amazon.awssdk', name: 'sdk-core', version: '2.20.102'

diff --git a/TrafficCapture/trafficReplayer/src/main/resources/log4j2.component.properties b/TrafficCapture/trafficReplayer/src/main/resources/log4j2.component.properties
@@ -0,0 +1,2 @@
+Log4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector
+AsyncLogger.WaitStrategy=Yield
diff --git a/TrafficCapture/trafficReplayer/src/main/resources/log4j2.properties b/TrafficCapture/trafficReplayer/src/main/resources/log4j2.properties
@@ -1,4 +1,4 @@
-status = error
+status = warn
 
 property.tupleDir = ${env:TUPLE_DIR_PATH:-./logs/tuples}
 
@@ -8,39 +8,43 @@ appender.console.type = Console
 appender.console.name = STDERR
 appender.console.target = SYSTEM_ERR
 appender.console.layout.type = PatternLayout
-appender.console.layout.pattern = [%-5level] %d{yyyy-MM-dd HH:mm:ss,SSS}{UTC} [%t] %c{1} - %msg%equals{ ctx=%mdc}{ ctx={}}{}%n
+appender.console.layout.pattern = [%-5level] %d{DEFAULT_MICROS}{UTC} [%t] %c{1} - %msg%equals{ ctx=%mdc}{ ctx={}}{}%n
+appender.console.direct = true
 
-appender.ReplayerLogFile.type = RollingFile
+appender.ReplayerLogFile.type = RollingRandomAccessFile
 appender.ReplayerLogFile.name = ReplayerLogFile
 appender.ReplayerLogFile.fileName = logs/replayer.log
 appender.ReplayerLogFile.filePattern = logs/%d{yyyy-MM}{UTC}/replayer-%d{yyyy-MM-dd-HH-mm}{UTC}-%i.log.gz
 appender.ReplayerLogFile.layout.type = PatternLayout
-appender.ReplayerLogFile.layout.pattern = [%-5level] %d{yyyy-MM-dd HH:mm:ss,SSS}{UTC} [%t] %c{1} - %msg%equals{ ctx=%mdc}{ ctx={}}{}%n
+appender.ReplayerLogFile.layout.pattern = [%-5level] %d{DEFAULT_MICROS}{UTC} [%t] %c{1} - %msg%equals{ ctx=%mdc}{ ctx={}}{}%n
 appender.ReplayerLogFile.policies.type = Policies
 appender.ReplayerLogFile.policies.time.type = TimeBasedTriggeringPolicy
 appender.ReplayerLogFile.policies.time.interval = 60
 appender.ReplayerLogFile.policies.time.modulate = true
 appender.ReplayerLogFile.strategy.type = DefaultRolloverStrategy
 appender.ReplayerLogFile.strategy.max = 288
+appender.ReplayerLogFile.immediateFlush = false
 
-appender.OUTPUT_TUPLES.type = RollingFile
+appender.OUTPUT_TUPLES.type = RollingRandomAccessFile
 appender.OUTPUT_TUPLES.name = OUTPUT_TUPLES
 appender.OUTPUT_TUPLES.fileName = ${tupleDir}/tuples.log
-appender.OUTPUT_TUPLES.filePattern = ${tupleDir}/tuples-%d{yyyy-MM-dd-HH:mm}{UTC}.log
+appender.OUTPUT_TUPLES.filePattern = ${tupleDir}/tuples-%d{yyyy-MM-dd-HH:mm}{UTC}-%i.log.gz
 appender.OUTPUT_TUPLES.layout.type = PatternLayout
 appender.OUTPUT_TUPLES.layout.pattern = %m%n
 appender.OUTPUT_TUPLES.policies.type = Policies
 appender.OUTPUT_TUPLES.policies.size.type = SizeBasedTriggeringPolicy
 appender.OUTPUT_TUPLES.policies.size.size = 10 MB
 appender.OUTPUT_TUPLES.strategy.type = DefaultRolloverStrategy
+appender.OUTPUT_TUPLES.immediateFlush = false
 
 appender.TRANSACTION_SUMMARIES.type = Console
 appender.TRANSACTION_SUMMARIES.name = TransactionSummariesConsole
 appender.TRANSACTION_SUMMARIES.target = SYSTEM_OUT
 appender.TRANSACTION_SUMMARIES.layout.type = PatternLayout
-appender.TRANSACTION_SUMMARIES.layout.pattern = %d{yyyy-MM-dd HH:mm:ss,SSS}{UTC}: %msg%n
+appender.TRANSACTION_SUMMARIES.layout.pattern = %d{DEFAULT_MICROS}{UTC}: %msg%n
+appender.TRANSACTION_SUMMARIES.direct = true
 
-appender.TRANSACTION_SUMMARIES_LOGFILE.type = RollingFile
+appender.TRANSACTION_SUMMARIES_LOGFILE.type = RollingRandomAccessFile
 appender.TRANSACTION_SUMMARIES_LOGFILE.name = TransactionSummariesFile
 appender.TRANSACTION_SUMMARIES_LOGFILE.fileName = logs/progress.log
 appender.TRANSACTION_SUMMARIES_LOGFILE.filePattern = logs/%d{yyyy-MM}{UTC}/progress-%d{yyyy-MM-dd-HH-mm}{UTC}-%i.log.gz
@@ -52,11 +56,12 @@ appender.TRANSACTION_SUMMARIES_LOGFILE.policies.time.interval = 60
 appender.TRANSACTION_SUMMARIES_LOGFILE.policies.time.modulate = true
 appender.TRANSACTION_SUMMARIES_LOGFILE.strategy.type = DefaultRolloverStrategy
 appender.TRANSACTION_SUMMARIES_LOGFILE.strategy.max = 720
+appender.TRANSACTION_SUMMARIES_LOGFILE.immediateFlush = false
 
-appender.ALL_ACTIVE_WORK_MONITOR_LOGFILE.type = RollingFile
+appender.ALL_ACTIVE_WORK_MONITOR_LOGFILE.type = RollingRandomAccessFile
 appender.ALL_ACTIVE_WORK_MONITOR_LOGFILE.name = AllActiveWorkMonitorFile
 appender.ALL_ACTIVE_WORK_MONITOR_LOGFILE.fileName = logs/longRunningActivity.log
-appender.ALL_ACTIVE_WORK_MONITOR_LOGFILE.filePattern = logs/%d{yyyy-MM}{UTC}/longRunningActivity-%d{yyyy-MM-dd-HH-mm}{UTC}-%i.log
+appender.ALL_ACTIVE_WORK_MONITOR_LOGFILE.filePattern = logs/%d{yyyy-MM}{UTC}/longRunningActivity-%d{yyyy-MM-dd-HH-mm}{UTC}-%i.log.gz
 appender.ALL_ACTIVE_WORK_MONITOR_LOGFILE.layout.type = PatternLayout
 appender.ALL_ACTIVE_WORK_MONITOR_LOGFILE.layout.pattern = %msg ([%-5level] %d{yyyy-MM-dd HH:mm:ss,SSS}{UTC})%n
 appender.ALL_ACTIVE_WORK_MONITOR_LOGFILE.policies.type = Policies
@@ -65,6 +70,7 @@ appender.ALL_ACTIVE_WORK_MONITOR_LOGFILE.policies.time.interval = 60
 appender.ALL_ACTIVE_WORK_MONITOR_LOGFILE.policies.time.modulate = true
 appender.ALL_ACTIVE_WORK_MONITOR_LOGFILE.strategy.type = DefaultRolloverStrategy
 appender.ALL_ACTIVE_WORK_MONITOR_LOGFILE.strategy.max = 4
+appender.ALL_ACTIVE_WORK_MONITOR_LOGFILE.immediateFlush = false
 
 rootLogger.level = info
 rootLogger.appenderRef.STDERR.ref = STDERR

diff --git a/TrafficCapture/trafficReplayer/src/test/resources/log4j2.properties b/TrafficCapture/trafficReplayer/src/test/resources/log4j2.properties
@@ -1,4 +1,4 @@
-status = error 
+status = error
 
 # Root logger options
 rootLogger.level = info

diff --git a/deployment/cdk/opensearch-service-migration/lib/service-stacks/migration-service-core.ts b/deployment/cdk/opensearch-service-migration/lib/service-stacks/migration-service-core.ts
@@ -12,7 +12,8 @@ import {
     ServiceConnectService,
     Ulimit,
     OperatingSystemFamily,
-    Volume
+    Volume,
+    AwsLogDriverMode
 } from "aws-cdk-lib/aws-ecs";
 import {DockerImageAsset} from "aws-cdk-lib/aws-ecr-assets";
 import {RemovalPolicy, Stack} from "aws-cdk-lib";
@@ -130,7 +131,13 @@ export class MigrationServiceCore extends Stack {
             portMappings: props.portMappings,
             logging: LogDrivers.awsLogs({
                 streamPrefix: `${props.serviceName}-logs`,
-                logGroup: serviceLogGroup
+                logGroup: serviceLogGroup,
+                // E.g. "[INFO ] 2024-12-31 23:59:59..."
+                // and  "[ERROR] 2024-12-31 23:59:59..."
+                // and  "2024-12-31 23:59:59..."
+                multilinePattern: "^(\\[[A-Z ]{1,5}\\] )?\\d{4}-\\d{2}-\\d{2} \\d{2}:\\d{2}:\\d{2}",
+                // Defer buffering behavior to log4j2 for greater flexibility
+                mode: AwsLogDriverMode.BLOCKING,
             }),
             ulimits: props.ulimits
         });