LogConfigurator hangs on startup
- Dominant language
- Java
- Stars
- 49
- Forks
- 3
- PR merge metrics
- No merged PRs in 30d
Description
Somewhat randomly reproducible hang in a service that uses GFLog and Datadog JMX agent.
I am curious if datadog agent is trying to use logging (via JUL) before this service had a chance to fully initialize GFLog (in static initializer).
```
"main" #1 [28] prio=5 os_prio=0 cpu=1188.83ms elapsed=334.73s tid=0x00007faffa68f8e0 nid=28 in Object.wait() [0x00007faffa66d000]
java.lang.Thread.State: RUNNABLE
at com.epam.deltix.gflog.core.LogConfigurator.configure(LogConfigurator.java:62)
- waiting on the Class initialization monitor for com.epam.deltix.gflog.core.LogFactoryImpl
- locked <0x00000007ffd055d0> (a java.lang.Class for com.epam.deltix.gflog.core.LogConfigurator)
at com.hidden.datalayer.commons.log.LogConfigHelper.configure(LogConfigHelper.java:32)
at com.hidden.datalayer.services.averageup.Starter.main(Starter.java:41)
"dd-forwarder-json-sender" #30 [53] daemon prio=5 os_prio=0 cpu=68.47ms elapsed=333.50s tid=0x00007faf93688f80 nid=53 waiting for monitor entry [0x00007faf9320e000]
java.lang.Thread.State: BLOCKED (on object monitor)
at com.epam.deltix.gflog.core.LogConfigurator.configureIfNot(LogConfigurator.java:19)
- waiting to lock <0x00000007ffd055d0> (a java.lang.Class for com.epam.deltix.gflog.core.LogConfigurator)
at com.epam.deltix.gflog.core.LogFactoryImpl.(LogFactoryImpl.java:18)
at com.epam.deltix.gflog.core.LogFactoryBinder.getLogFactory(LogFactoryBinder.java:11)
at java.lang.invoke.DirectMethodHandle$Holder.invokeStatic(java.base@21.0.7/DirectMethodHandle$Holder)
at java.lang.invoke.LambdaForm$MH/0x00007faf9b000400.invoke(java.base@21.0.7/LambdaForm$MH)
at java.lang.invoke.Invokers$Holder.invokeExact_MT(java.base@21.0.7/Invokers$Holder)
at jdk.internal.reflect.DirectMethodHandleAccessor.invokeImpl(java.base@21.0.7/DirectMethodHandleAccessor.java:153)
at jdk.internal.reflect.DirectMethodHandleAccessor.invoke(java.base@21.0.7/DirectMethodHandleAccessor.java:103)
at java.lang.reflect.Method.invoke(java.base@21.0.7/Method.java:580)
at com.epam.deltix.gflog.api.LogFactory$Implementation.(LogFactory.java:56)
at com.epam.deltix.gflog.api.LogFactory.getLog(LogFactory.java:29)
at com.epam.deltix.gflog.jul.JulBridgeLogger.(JulBridgeLogger.java:22)
at com.epam.deltix.gflog.jul.JulBridgeManager.getLogger(JulBridgeManager.java:29)
at java.util.logging.LogManager.demandSystemLogger(java.logging@21.0.7/LogManager.java:574)
at java.util.logging.LogManager$LoggingProviderAccess.demandLoggerFor(java.logging@21.0.7/LogManager.java:2727)
at sun.util.logging.internal.LoggingProviderImpl.demandJULLoggerFor(java.logging@21.0.7/LoggingProviderImpl.java:412)
at sun.util.logging.internal.LoggingProviderImpl.demandLoggerFor(java.logging@21.0.7/LoggingProviderImpl.java:438)
at jdk.internal.logger.DefaultLoggerFinder.getLogger(java.base@21.0.7/DefaultLoggerFinder.java:159)
at jdk.internal.logger.LazyLoggers.getLoggerFromFinder(java.base@21.0.7/LazyLoggers.java:410)
at jdk.internal.logger.LazyLoggers.getLazyLogger(java.base@21.0.7/LazyLoggers.java:465)
at jdk.internal.logger.LazyLoggers.getLogger(java.base@21.0.7/LazyLoggers.java:435)
at java.lang.System.getLogger(java.base@21.0.7/System.java:1826)
at java.lang.ProcessBuilder.start(java.base@21.0.7/ProcessBuilder.java:1141)
at java.lang.ProcessBuilder.start(java.base@21.0.7/ProcessBuilder.java:1089)
at datadog.trace.bootstrap.BootstrapInitializationTelemetry$ForwarderJsonSenderThread.run(BootstrapInitializationTelemetry.java:215)
"dd-jmx-collector" #45 [77] daemon prio=5 os_prio=0 cpu=74.48ms elapsed=317.31s tid=0x00007faf941fd7f0 nid=77 in Object.wait() [0x00007faf92668000]
java.lang.Thread.State: RUNNABLE
at com.epam.deltix.gflog.api.LogFactory.getLog(LogFactory.java:29)
- waiting on the Class initialization monitor for com.epam.deltix.gflog.api.LogFactory$Implementation
at com.epam.deltix.gflog.jul.JulBridgeLogger.(JulBridgeLogger.java:22)
at com.epam.deltix.gflog.jul.JulBridgeManager.getLogger(JulBridgeManager.java:29)
at java.util.logging.LogManager.demandSystemLogger(java.logging@21.0.7/LogManager.java:574)
at java.util.logging.LogManager$LoggingProviderAccess.demandLoggerFor(java.logging@21.0.7/LogManager.java:2727)
at sun.util.logging.internal.LoggingProviderImpl.demandJULLoggerFor(java.logging@21.0.7/LoggingProviderImpl.java:412)
at sun.util.logging.internal.LoggingProviderImpl.demandLoggerFor(java.logging@21.0.7/LoggingProviderImpl.java:438)
at jdk.internal.logger.DefaultLoggerFinder.getLogger(java.base@21.0.7/DefaultLoggerFinder.java:159)
at jdk.internal.logger.LazyLoggers.getLoggerFromFinder(java.base@21.0.7/LazyLoggers.java:410)
at jdk.internal.logger.LazyLoggers.getLazyLogger(java.base@21.0.7/LazyLoggers.java:465)
at jdk.internal.logger.LazyLoggers.getLogger(java.base@21.0.7/LazyLoggers.java:435)
at java.lang.System.getLogger(java.base@21.0.7/System.java:1826)
at com.sun.jmx.remote.util.ClassLogger.(java.management@21.0.7/ClassLogger.java:38)
at javax.management.NotificationBroadcasterSupport.(java.management@21.0.7/NotificationBroadcasterSupport.java:364)
at javax.management.MBeanServerDelegate.(java.management@21.0.7/MBeanServerDelegate.java:73)
at com.sun.jmx.mbeanserver.MBeanServerDelegateImpl.(java.management@21.0.7/MBeanServerDelegateImpl.java:100)
at com.sun.jmx.mbeanserver.JmxMBeanServer.newMBeanServerDelegate(java.management@21.0.7/JmxMBeanServer.java:1374)
at javax.management.MBeanServerBuilder.newMBeanServerDelegate(java.management@21.0.7/MBeanServerBuilder.java:66)
at javax.management.MBeanServerFactory.newMBeanServer(java.management@21.0.7/MBeanServerFactory.java:321)
- locked <0x00000007fcf58ad8> (a javax.management.MBeanServerBuilder)
at javax.management.MBeanServerFactory.createMBeanServer(java.management@21.0.7/MBeanServerFactory.java:231)
at javax.management.MBeanServerFactory.createMBeanServer(java.management@21.0.7/MBeanServerFactory.java:192)
at java.lang.management.ManagementFactory.getPlatformMBeanServer(java.management@21.0.7/ManagementFactory.java:487)
- locked <0x00000007fd487190> (a java.lang.Class for java.lang.management.ManagementFactory)
at org.datadog.jmxfetch.JvmDirectConnection.createConnection(JvmDirectConnection.java:16)
at org.datadog.jmxfetch.JvmDirectConnection.(JvmDirectConnection.java:12)
at org.datadog.jmxfetch.DefaultConnectionFactory.createConnection(DefaultConnectionFactory.java:22)
at datadog.trace.agent.jmxfetch.AgentConnectionFactory.createConnection(AgentConnectionFactory.java:34)
at org.datadog.jmxfetch.Instance.getConnection(Instance.java:436)
at org.datadog.jmxfetch.Instance.init(Instance.java:449)
at org.datadog.jmxfetch.InstanceInitializingTask.call(InstanceInitializingTask.java:15)
at org.datadog.jmxfetch.InstanceInitializingTask.call(InstanceInitializingTask.java:3)
at org.datadog.jmxfetch.tasks.TaskProcessor.processTasks(TaskProcessor.java:72)
at org.datadog.jmxfetch.App.init(App.java:1059)
at org.datadog.jmxfetch.App.run(App.java:268)
at datadog.trace.agent.jmxfetch.JMXFetch$1.run(JMXFetch.java:145)
at java.lang.Thread.runWith(java.base@21.0.7/Thread.java:1596)
at java.lang.Thread.run(java.base@21.0.7/Thread.java:1583)
```
Gradle:
```
gflogVersion=3.0.5
dependencies {
api("com.epam.deltix:gflog-api:$gflogVersion")
implementation("com.epam.deltix:gflog-core:$gflogVersion")
implementation("com.epam.deltix:gflog-jul:$gflogVersion")
runtimeOnly("com.epam.deltix:gflog-slf4j:$gflogVersion")
}
```
```java
public static void main(final String[] args) {
LogConfigHelper.configure("history-query");
// do the work here
}
```
Where LogConfigHelper:
```java
public class LogConfigHelper {
public static final String GFLOG_XML = "gflog.xml";
/**
*
* @param appName - allows using ${app.name} variable in GFLOG.XML file
*/
public static void configure(final String appName) {
//System.setProperty("org.springframework.boot.logging.LoggingSystem", "none"); // disables Spring Logging System, so we solely rely on GF Log
JulBridge.install();
final LogConfig config = getLogConfig(appName);
LogConfigurator.configure(config);
}
private static LogConfig getLogConfig(final String appName) {
LogConfig config = loadLogConfig(appName);
if (config == null) {
config = createConsoleLogConfig();
}
config.conclude();
return config;
}
private static LogConfig loadLogConfig(final String appName) {
LogConfig config = null;
final Properties substitution = System.getProperties();
substitution.put("app.name", appName);
if (LogConfigFactory.CONFIG != null) {
try {
config = LogConfigFactory.load(LogConfigFactory.CONFIG, substitution);
} catch (final Throwable e) {
LogDebug.warn("Can't load GFLog config from gflog.config (" + LogConfigFactory.CONFIG + "): " + e.getMessage());
}
}
if (config == null) {
final File configFile = new File(GFLOG_XML);
try {
if (configFile.exists()) {
config = LogConfigFactory.load(configFile, substitution);
}
} catch (final Throwable e) {
System.err.println("Can't load GFLog config from " + configFile + ": " + e.getMessage());
}
}
return config;
}
private static LogConfig createConsoleLogConfig() {
final LogConfig config = new LogConfig();
final AsyncLogServiceFactory logServiceFactory = new AsyncLogServiceFactory();
logServiceFactory.setOverflowStrategy(OverflowStrategy.DISCARD);
final TemplateLayoutFactory templateFactory = new TemplateLayoutFactory();
templateFactory.setTemplate("%d{yyyy-MM-dd HH:mm:ss.SSS} %p [%t] %m%n"); // .SSSSSSSSS
final ConsoleAppenderFactory appenderFactory = new ConsoleAppenderFactory();
appenderFactory.setLayout(templateFactory.create());
final Appender appender = appenderFactory.create();
final Logger logger = new Logger(LogLevel.INFO, appender);
config.setService(logServiceFactory);
config.addAppender(appender);
config.addLogger(logger);
return config;
}
public static void unconfigure() {
LogConfigurator.unconfigure();
}
}
```
Contributor guide
No contributing guide indexed for this repository
Research direction
Start with LogConfigurator.configure(LogConfigurator.java:62), configureIfNot(LogConfigurator.java:19), and LogFactoryImpl's static initializer at LogFactoryImpl.java:18. Reproduce startup with Java 21, GFLog 3.0.5, and the Datadog JMX agent, then trace the JUL bridge and class-initialization locks. Done means the service starts without the observed initialization deadlock.
Written by the indexing model from the issue text.
Assessment
- Tech stack
- java
- Domain
- backend, observability-sre
- Issue type
- Bug
- Difficulty
- 4/5
- Estimated time
- 3-5 days
- Activity status
- Stale
- Clarity
- Mostly clear
- Newbie friendliness
- 35/100