epam / epam/gflog

LogConfigurator hangs on startup

Open
#18 1 comment 0 reactions 0 assignees View on GitHub
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

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.