Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Enhance logging with Async and high performance appenders #602

Merged
merged 7 commits into from
Apr 23, 2024
Merged

Enhance logging with Async and high performance appenders #602

Show file tree
Hide file tree
Changes from 6 commits
Commits
Show all changes
7 commits
Select commit Hold shift + click to select a range
d98fe23
Move log4j2 appenders to high performance async loggers
AndreKurait Apr 23, 2024
a641dff
Enhance logging with microsecond clock and enhanced performance options
AndreKurait Apr 23, 2024
0a18fbb
Add multilinePattern to log driver
AndreKurait Apr 23, 2024
718aa6a
Add includeLocation and immediateFlush parameters to log4j2.properties
AndreKurait Apr 23, 2024
5d5d8c7
Use synchronous logger in tests
AndreKurait Apr 23, 2024
f5eac21
Update comment in migration-service-core.ts
AndreKurait Apr 23, 2024
643e8e9
Remove include location
AndreKurait Apr 23, 2024
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
2 changes: 2 additions & 0 deletions TrafficCapture/build.gradle
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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 {
Expand Down
10 changes: 6 additions & 4 deletions TrafficCapture/trafficCaptureProxyServer/build.gradle
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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'
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Mostly a side note -- it's very weird that Mend decided it didn't need to run on this push (see here). You're adding and updating dependencies!

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Does it ever run on a PR, or only once it's merged?

A scan is initiated via a valid GitHub 'push' command. A valid 'push' command...

Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yeah, usually I can see the results when I modify build.gradle files before merging. But it's currently doing this same thing to me on the werkzeug PR.

But definitely not a blocker for this!


implementation group: 'com.beust', name: 'jcommander', version: '1.82'
implementation 'com.google.protobuf:protobuf-java:3.22.2'
Expand Down
2 changes: 2 additions & 0 deletions TrafficCapture/trafficCaptureProxyServer/src/main/resources/log4j2.component.properties
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -0,0 +1,2 @@
Log4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector
AsyncLogger.WaitStrategy=Yield
4 changes: 3 additions & 1 deletion TrafficCapture/trafficCaptureProxyServer/src/main/resources/log4j2.properties
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -6,7 +6,9 @@ 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
AndreKurait marked this conversation as resolved.
Show resolved Hide resolved
appender.console.includeLocation = true
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Can you elaborate on including this/why it's important?

https://logging.apache.org/log4j/2.x/manual/async.html#location-location-location

The performance impact of taking a stack trace snapshot is even higher for asynchronous loggers: logging with location is 30-100 times slower than without location.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Removed, had originally included it due to the %c{1} in our layout pattern, though reading now that %c means logger name whereas %C means class which would have necessitated location


rootLogger.level = info
rootLogger.appenderRefs = stderr
Expand Down
11 changes: 7 additions & 4 deletions TrafficCapture/trafficReplayer/build.gradle
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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'
Expand Down
2 changes: 2 additions & 0 deletions TrafficCapture/trafficReplayer/src/main/resources/log4j2.component.properties
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -0,0 +1,2 @@
Log4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector
AsyncLogger.WaitStrategy=Yield
AndreKurait marked this conversation as resolved.
Show resolved Hide resolved
28 changes: 18 additions & 10 deletions TrafficCapture/trafficReplayer/src/main/resources/log4j2.properties
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,4 +1,4 @@
status = error
status = warn

property.tupleDir = ${env:TUPLE_DIR_PATH:-./logs/tuples}

Expand All @@ -8,39 +8,45 @@ 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.includeLocation = true
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.includeLocation = true
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
Expand All @@ -52,11 +58,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
Expand All @@ -65,6 +72,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
Expand Down
2 changes: 1 addition & 1 deletion TrafficCapture/trafficReplayer/src/test/resources/log4j2.properties
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,4 +1,4 @@
status = error
status = error

# Root logger options
rootLogger.level = info
Expand Down
11 changes: 9 additions & 2 deletions deployment/cdk/opensearch-service-migration/lib/service-stacks/migration-service-core.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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";
Expand Down Expand Up @@ -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
});
Expand Down