App with logger is starting 1+ minute

[boroda4436]

When starting the SpringBoot application it takes more than 1 minute to initialize the logger. Please see the logs below

` Picked up JAVA_TOOL_OPTIONS: -agentlib:jdwp=transport=dt_socket,server=y,suspend=n,address=*:5005 Listening for transport dt_socket at address: 5005 2021-12-30 14:31:35,853 main ERROR writer initialization timed out 2021-12-30 14:32:35,955 main ERROR writer initialization timed out 2021-12-30 14:32:42.943 INFO [main] my.company.name.MainApplication - - Starting MainApplication v0.0.1-SNAPSHOT on bef49c794617 with PID 1 (/application/BOOT-INF/classes started by root in /application)

...

2021-12-30 14:33:01.371 INFO [main] my.company.name.MainApplication - - Started MainApplication in 24.932 seconds (JVM running for 148.374) `

Please see the application start time (24.932 seconds) and the JVM running time (JVM running for 148.374).

As a result, the application starts well, but it takes too much time. Without a logger application starts in 15-20 seconds.

[kdgregory]

@boroda4436

A timeout typically happens when the logger is unable to contact the AWS service. One reason that can happen is because you're running in a private subnet without access to the Internet. It can be solved with a NAT or using a local endpoint for the logging destination.

Please follow the instructions in the troubleshooting guide to enable debug-level logging from the logging framework, which will provide more information about exactly what is failing.

[kdgregory]

It's been a week, I'm going to assume that you've resolved this yourself.

[boroda4436]

@kdgregory Sorry, for the late reply! I've skipped this issue for a while, but now it looks critical.

One reason that can happen is because you're running in a private subnet without access to the Internet.

Doesn't it mean that in this case the logger will not start at all?

Please follow the instructions in the troubleshooting guide to enable debug-level logging from the logging framework, which will provide more information about exactly what is failing.

I've configured log config to enable debug logs from your lib. Here are logs:

...
my-app-api  | 2022-07-18 16:04:12,079 main DEBUG Building Plugin[name=appender, class=com.kdgregory.log4j2.aws.CloudWatchAppender].
my-app-api  | 2022-07-18 16:04:12,092 main DEBUG CloudWatchAppender$CloudWatchAppenderBuilder(name="CLOUDWATCH_API", logGroup="my-app/local/api", logStream="{date}", retentionPeriod="null", dedicatedWriter="true", PatternLayout(%-5p [%t] %C - %X{requestUUID} - %m%n), Filter=null, Configuration(/application/BOOT-INF/classes/log4j2_local.xml), synchronous="null", batchDelay="null", truncateOversizeMessages="null", discardThreshold="null", discardAction="null", assumedRole="null", clientFactory="null", clientRegion="null", clientEndpoint="null", useShutdownHook="null")
my-app-api  | 2022-07-18 16:04:12,096 main DEBUG Building Plugin[name=appenders, class=org.apache.logging.log4j.core.config.AppendersPlugin].
my-app-api  | 2022-07-18 16:04:12,103 main DEBUG createAppenders(={CONSOLE, com.kdgregory.log4j2.aws.CloudWatchAppender with name CloudWatchAppender})
my-app-api  | 2022-07-18 16:04:12,104 main DEBUG Building Plugin[name=AppenderRef, class=org.apache.logging.log4j.core.config.AppenderRef].
my-app-api  | 2022-07-18 16:04:12,112 main DEBUG createAppenderRef(ref="CONSOLE", level="null", Filter=null)
my-app-api  | 2022-07-18 16:04:12,113 main DEBUG Building Plugin[name=logger, class=org.apache.logging.log4j.core.config.LoggerConfig].
my-app-api  | 2022-07-18 16:04:12,121 main DEBUG createLogger(additivity="false", level="DEBUG", name="com.kdgregory.logging", includeLocation="null", ={CONSOLE}, ={}, Configuration(/application/BOOT-INF/classes/log4j2_local.xml), Filter=null)
my-app-api  | 2022-07-18 16:04:12,126 main DEBUG Building Plugin[name=AppenderRef, class=org.apache.logging.log4j.core.config.AppenderRef].
my-app-api  | 2022-07-18 16:04:12,127 main DEBUG createAppenderRef(ref="CONSOLE", level="null", Filter=null)
my-app-api  | 2022-07-18 16:04:12,128 main DEBUG Building Plugin[name=root, class=org.apache.logging.log4j.core.config.LoggerConfig$RootLogger].
my-app-api  | 2022-07-18 16:04:12,132 main DEBUG createLogger(additivity="null", level="INFO", includeLocation="null", ={CONSOLE}, ={}, Configuration(/application/BOOT-INF/classes/log4j2_local.xml), Filter=null)
my-app-api  | 2022-07-18 16:04:12,134 main DEBUG Building Plugin[name=loggers, class=org.apache.logging.log4j.core.config.LoggersPlugin].
my-app-api  | 2022-07-18 16:04:12,136 main DEBUG createLoggers(={com.kdgregory.logging, root})
my-app-api  | 2022-07-18 16:04:12,138 main DEBUG Configuration XmlConfiguration[location=/application/BOOT-INF/classes/log4j2_local.xml] initialized
my-app-api  | 2022-07-18 16:04:12,139 main DEBUG Starting configuration XmlConfiguration[location=/application/BOOT-INF/classes/log4j2_local.xml]
my-app-api  | 2022-07-18 16:04:12,182 com-kdgregory-aws-logwriter-log4j2-cloudwatch-1 DEBUG log writer starting (thread: com-kdgregory-aws-logwriter-log4j2-cloudwatch-1)

my-app-api  | 2022-07-18 16:05:12,206 main ERROR writer initialization timed out
my-app-api  | 2022-07-18 16:05:12,215 main DEBUG Started configuration XmlConfiguration[location=/application/BOOT-INF/classes/log4j2_local.xml] OK.
my-app-api  | 2022-07-18 16:05:12,220 main DEBUG Shutting down OutputStreamManager SYSTEM_OUT.false.false-1
my-app-api  | 2022-07-18 16:05:12,221 main DEBUG OutputStream closed
my-app-api  | 2022-07-18 16:05:12,221 main DEBUG Shut down OutputStreamManager SYSTEM_OUT.false.false-1, all resources released: true
my-app-api  | 2022-07-18 16:05:12,222 main DEBUG Appender DefaultConsole-1 stopped with status true
my-app-api  | 2022-07-18 16:05:12,223 main DEBUG Stopped org.apache.logging.log4j.core.config.DefaultConfiguration@1d29cf23 OK
my-app-api  | 2022-07-18 16:05:12,415 main DEBUG Registering MBean org.apache.logging.log4j2:type=677327b6
my-app-api  | 2022-07-18 16:05:12,419 main DEBUG Registering MBean org.apache.logging.log4j2:type=677327b6,component=StatusLogger
my-app-api  | 2022-07-18 16:05:12,422 main DEBUG Registering MBean org.apache.logging.log4j2:type=677327b6,component=ContextSelector
my-app-api  | 2022-07-18 16:05:12,425 main DEBUG Registering MBean org.apache.logging.log4j2:type=677327b6,component=Loggers,name=
my-app-api  | 2022-07-18 16:05:12,428 main DEBUG Registering MBean org.apache.logging.log4j2:type=677327b6,component=Loggers,name=com.kdgregory.logging
my-app-api  | 2022-07-18 16:05:12,432 main DEBUG Registering MBean org.apache.logging.log4j2:type=677327b6,component=Appenders,name=CONSOLE
my-app-api  | 2022-07-18 16:05:12,433 main DEBUG Registering MBean org.apache.logging.log4j2:type=677327b6,component=Appenders,name=CLOUDWATCH_API
my-app-api  | 2022-07-18 16:05:12,438 main DEBUG org.apache.logging.log4j.core.util.SystemClock supports precise timestamps.
my-app-api  | 2022-07-18 16:05:12,439 main DEBUG Reconfiguration complete for context[name=677327b6] at URI /application/BOOT-INF/classes/log4j2_local.xml (org.apache.logging.log4j.core.LoggerContext@1a223c6b) with optional ClassLoader: null
my-app-api  | 2022-07-18 16:05:12,440 main DEBUG Shutdown hook enabled. Registering a new one.
...

and then app starts ok

Please, note there is a 1 min delay after 2022-07-18 16:04:12,182. There are no errors that could tell what could be the root cause. Do you have any ideas on how to fix or detect the root cause?

Addition config information is listed below.

I'm running my app in docker. Log42.xml config is below:

<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="debug" packages="com.kdgregory.log4j2.aws">
  <Appenders>
    <Console name="CONSOLE">
      <PatternLayout pattern="%d{yyyy-MM-dd HH:mm:ss.SSS} %-5p [%t] %C - %X{requestUUID} - %m%n"/>
    </Console>
    <CloudWatchAppender name="CLOUDWATCH_API">
      <logGroup>my-app/${env:APP_ENV}/api</logGroup>
      <logStream>{date}</logStream>
      <dedicatedWriter>true</dedicatedWriter>
      <PatternLayout pattern="%-5p [%t] %C - %X{requestUUID} - %m%n" />
    </CloudWatchAppender>
  </Appenders>
  <Loggers>
    <Logger level="debug" name="com.kdgregory.logging" additivity="false">
      <AppenderRef ref="CONSOLE"/>
    </Logger>
    <Root level="info">
      <AppenderRef ref="CONSOLE"/>
    </Root>
  </Loggers>
</Configuration>

P.S. I specifically removed the CLOUDWATCH_API configuration from the Loggers section

pom.xml

    <dependency>
      <groupId>org.springframework.boot</groupId>
      <artifactId>spring-boot-starter-log4j2</artifactId>
    </dependency>
    <dependency>
      <groupId>com.kdgregory.logging</groupId>
      <artifactId>log4j2-aws-appenders</artifactId>
      <version>${kdgregory.cloudwatch.version}</version>
    </dependency>
    <dependency>
      <groupId>com.kdgregory.logging</groupId>
      <artifactId>aws-facade-v2</artifactId>
      <version>${kdgregory.cloudwatch.version}</version>
    </dependency>
    <dependency>
      <groupId>org.apache.logging.log4j</groupId>
      <artifactId>log4j-api</artifactId>
      <version>${log4j2.version}</version>
    </dependency>
    <dependency>
      <groupId>org.apache.logging.log4j</groupId>
      <artifactId>log4j-core</artifactId>
      <version>${log4j2.version}</version>
    </dependency>
    <dependency>
      <groupId>org.apache.logging.log4j</groupId>
      <artifactId>log4j-web</artifactId>
      <version>${log4j2.version}</version>
    </dependency>
    <dependency>
      <groupId>org.apache.logging.log4j</groupId>
      <artifactId>log4j-jcl</artifactId>
      <version>${log4j2.version}</version>
    </dependency>
    <dependency>
      <groupId>org.apache.logging.log4j</groupId>
      <artifactId>log4j-slf4j-impl</artifactId>
      <version>${log4j2.version}</version>
    </dependency>
    <dependency>
      <groupId>software.amazon.awssdk</groupId>
      <artifactId>cloudwatchlogs</artifactId>
      <version>${aws-sdk-v2.version}</version>
    </dependency>

versions:

    <log4j2.version>2.17.1</log4j2.version>
    <kdgregory.cloudwatch.version>3.0.1</kdgregory.cloudwatch.version>
    <aws-sdk-v2.version>2.17.77</aws-sdk-v2.version>

[kdgregory]

@boroda4436

As I said in my original reply, timeouts happen as a result of network configuration, most likely running in a private subnet without a NAT or in a public subnet without a public IP (which includes Lambdas deployed into a public subnet). You can verify this by logging into whatever environment you're deploying into and running the AWS CLI: aws logs describe-log-groups is the first thing that the log-writer does (albeit via the API, not CLI). If your deployment environment doesn't provide the CLI, then you can write a short program that calls the DescribeLogGroups API.

[boroda4436]

Thanks, I'll deep dive into how the NAT works!