Java console logging or STDOUT inside Docker container hangs

[pu2925]

e have Weblogic server running inside the docker container it is
been observed the Weblogic JVM hangs becomes unresponsive. The issue is
reproducible with small java code simulating logging.

Thread dump analysis confirm it hangs with console logging. We tried the same
code on OEL6 environment and it is working fine, Process execute without any
hang.

Environment details below

Issue Environment -

Linux Server release 7.5 (Maipo)
4.14.35-1818.3.3.el7uek.x86_64

Docker Info

[root@prakash ~]# docker info
Containers: 0
Running: 0
Paused: 0
Stopped: 0
Images: 0
Server Version: 18.03.1-ol
Storage Driver: overlay2
Backing Filesystem: xfs
Supports d_type: true
Native Overlay Diff: false
Logging Driver: json-file
Cgroup Driver: cgroupfs
Plugins:
Volume: local
Network: bridge host macvlan null overlay
Log: awslogs fluentd gcplogs gelf journald json-file logentries splunk syslog
Swarm: inactive
Runtimes: runc
Default Runtime: runc
Init Binary: docker-init
containerd version: 773c489c9c1b21a6d78b5c538cd395416ec50f88
runc version: 4fc53a81fb7c994640722ac585fa9ca548971871
init version: 949e6fa
Security Options:
seccomp
 Profile: default
selinux
Kernel Version: 4.14.35-1818.3.3.el7uek.x86_64
Operating System: Oracle Linux Server 7.5
OSType: linux
Architecture: x86_64
CPUs: 4
Total Memory: 29.18GiB
Name: prakash
ID: FORP:QPCV:IK7D:U2RV:A63C:ODDG:LATY:6AQO:EABJ:M4ZG:F3S5:36NG
Docker Root Dir: /var/lib/docker
Debug Mode (client): false
Debug Mode (server): false
Registry: https://index.docker.io/v1/

(Edited for formatting)

[javabrett]

Are you able to share the Dockerfile or otherwise share "The issue is
reproducible with small java code simulating logging."?

Are you able to share the thread dump you took?

[pu2925]

I have used below image -

docker pull container-registry.oracle.com/middleware/weblogic:12.2.1.3

[pu2925]

Full thread dump Java HotSpot(TM) 64-Bit Server VM (25.181-b13 mixed mode):

"Attach Listener" #13 daemon prio=9 os_prio=0 tid=0x00007fba28001000 nid=0x268 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"DestroyJavaVM" #12 prio=5 os_prio=0 tid=0x00007fba70009000 nid=0x227 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Thread-2" #11 prio=5 os_prio=0 tid=0x00007fba70229000 nid=0x237 runnable [0x00007fba3d179000]
   java.lang.Thread.State: RUNNABLE
	at java.io.FileOutputStream.writeBytes(Native Method)
	at java.io.FileOutputStream.write(FileOutputStream.java:326)
	at java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:82)
	at java.io.BufferedOutputStream.flush(BufferedOutputStream.java:140)
	- locked <0x00000005ed00fe18> (a java.io.BufferedOutputStream)
	at java.io.PrintStream.write(PrintStream.java:482)
	- locked <0x00000005ed00fdf8> (a java.io.PrintStream)
	at sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:221)
	at sun.nio.cs.StreamEncoder.implFlushBuffer(StreamEncoder.java:291)
	at sun.nio.cs.StreamEncoder.implFlush(StreamEncoder.java:295)
	at sun.nio.cs.StreamEncoder.flush(StreamEncoder.java:141)
	- locked <0x00000005ed00fde0> (a java.io.OutputStreamWriter)
	at java.io.OutputStreamWriter.flush(OutputStreamWriter.java:229)
	at org.apache.log4j.helpers.QuietWriter.flush(QuietWriter.java:59)
	at org.apache.log4j.WriterAppender.subAppend(WriterAppender.java:324)
	at org.apache.log4j.WriterAppender.append(WriterAppender.java:162)
	at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:251)
	- locked <0x00000005ed00e500> (a org.apache.log4j.ConsoleAppender)
	at org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:66)
	at org.apache.log4j.Category.callAppenders(Category.java:206)
	- locked <0x00000005ed00e278> (a org.apache.log4j.spi.RootLogger)
	at org.apache.log4j.Category.forcedLog(Category.java:391)
	at org.apache.log4j.Category.error(Category.java:305)
	at LoggerImpl.run(LoggerImpl.java:23)

"Thread-1" #10 prio=5 os_prio=0 tid=0x00007fba70226000 nid=0x236 waiting for monitor entry [0x00007fba3d27a000]
   java.lang.Thread.State: BLOCKED (on object monitor)
	at org.apache.log4j.Category.callAppenders(Category.java:204)
	- waiting to lock <0x00000005ed00e278> (a org.apache.log4j.spi.RootLogger)
	at org.apache.log4j.Category.forcedLog(Category.java:391)
	at org.apache.log4j.Category.info(Category.java:666)
	at LoggerImpl.run(LoggerImpl.java:20)

"Thread-0" #9 prio=5 os_prio=0 tid=0x00007fba70225000 nid=0x235 waiting for monitor entry [0x00007fba3d37b000]
   java.lang.Thread.State: BLOCKED (on object monitor)
	at org.apache.log4j.Category.callAppenders(Category.java:204)
	- waiting to lock <0x00000005ed00e278> (a org.apache.log4j.spi.RootLogger)
	at org.apache.log4j.Category.forcedLog(Category.java:391)
	at org.apache.log4j.Category.warn(Category.java:1043)
	at LoggerImpl.run(LoggerImpl.java:21)

"Service Thread" #8 daemon prio=9 os_prio=0 tid=0x00007fba7018e800 nid=0x233 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C1 CompilerThread2" #7 daemon prio=9 os_prio=0 tid=0x00007fba70183000 nid=0x232 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread1" #6 daemon prio=9 os_prio=0 tid=0x00007fba70181800 nid=0x231 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread0" #5 daemon prio=9 os_prio=0 tid=0x00007fba7017e800 nid=0x230 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Signal Dispatcher" #4 daemon prio=9 os_prio=0 tid=0x00007fba7017c800 nid=0x22f runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Finalizer" #3 daemon prio=8 os_prio=0 tid=0x00007fba7014b000 nid=0x22e in Object.wait() [0x00007fba5c483000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	- waiting on <0x00000005ed04a4d0> (a java.lang.ref.ReferenceQueue$Lock)
	at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:144)
	- locked <0x00000005ed04a4d0> (a java.lang.ref.ReferenceQueue$Lock)
	at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:165)
	at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:216)

"Reference Handler" #2 daemon prio=10 os_prio=0 tid=0x00007fba70148000 nid=0x22d in Object.wait() [0x00007fba5c584000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	- waiting on <0x00000005ed04a510> (a java.lang.ref.Reference$Lock)
	at java.lang.Object.wait(Object.java:502)
	at java.lang.ref.Reference.tryHandlePending(Reference.java:191)
	- locked <0x00000005ed04a510> (a java.lang.ref.Reference$Lock)
	at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:153)

"VM Thread" os_prio=0 tid=0x00007fba7013e800 nid=0x22c runnable

"GC task thread#0 (ParallelGC)" os_prio=0 tid=0x00007fba7001e800 nid=0x228 runnable

"GC task thread#1 (ParallelGC)" os_prio=0 tid=0x00007fba70020000 nid=0x229 runnable

"GC task thread#2 (ParallelGC)" os_prio=0 tid=0x00007fba70022000 nid=0x22a runnable

"GC task thread#3 (ParallelGC)" os_prio=0 tid=0x00007fba70024000 nid=0x22b runnable

"VM Periodic Task Thread" os_prio=0 tid=0x00007fba70193800 nid=0x234 waiting on condition

JNI global references: 5

(Edited for formatting)

[pu2925]

Also we can observe the issue on java docker file as below

cat Dockerfile
FROM openjdk:7
CMD ["java", "Main"]

[javabrett]

Also we can observe the issue on java docker file as below

Are you able to share the source project which builds and adds the Main class for this Dockerfile?

[javabrett]

Worth checking if anything else is going-on system-wise which might have halted the JVM. Anything in system logs - still plenty of file-descriptors etc. available to the JVM?

[pu2925]

Its a simple java code to simulate weblogic logging.

import org.apache.log4j.Logger;
public class Test extends Thread{
static Logger logger = Logger.getLogger(Test.class);
static int counter=0;
static String flag="log4j";
public void run(){
long id = Thread.currentThread().getId();

	try {
		++counter;
    	long startTime = System.nanoTime();
    	for (int i=0;i<=5;i++){
        logger.debug("This is debug message -  " + counter );
        logger.info("This is info message -  " + counter );
        logger.warn("This is warn message -  " + counter );
        logger.fatal("This is fatal message -  " + counter );
        logger.error("This is error message -  " + counter );
        
    	}
    	long endTime   = System.nanoTime();
    	long totalTime = endTime - startTime;
    	System.out.println("Total Time " +totalTime/1000000000);
    	System.out.println("Logic executed successfully....");
    }
    catch (Exception e){
    	System.out.println("excetpion is "+ e);
    }
	    	}
  
public static void main(String[] args) { 
	
	LoggerImpl obj=new LoggerImpl();   
     obj.start(); 
     LoggerImpl obj1=new LoggerImpl();   
     obj1.start(); 
     LoggerImpl obj2=new LoggerImpl();   
     obj2.start(); 

}

}

[pu2925]

log4j property file as below

Root logger option

log4j.rootLogger=INFO, file,stdout

configuration to print into file

log4j.appender.file=org.apache.log4j.RollingFileAppender
log4j.appender.file.File=//test//loging.log
log4j.appender.file.MaxFileSize=12MB
log4j.appender.file.MaxBackupIndex=10
log4j.appender.file.layout=org.apache.log4j.PatternLayout
log4j.appender.file.layout.ConversionPattern=%d{yyyy-MM-dd HH:mm:ss} %-5p %c{1}:%L - %m%n

configuration to print on console

log4j.appender.stdout=org.apache.log4j.ConsoleAppender
log4j.appender.stdout.Target=System.out
log4j.appender.stdout.layout=org.apache.log4j.PatternLayout
log4j.appender.stdout.layout.ConversionPattern=%d{yyyy-MM-dd HH:mm:ss} %-5p %c{1}:%L - %m%n

[henrykuijpers]

We are hitting this issue as well. Not specifically with the Oracle docker images, but with Docker in general:

Producing a huge load of logging to stderr (through maven testrun), we see the following hang:

"main" #1 prio=5 os_prio=0 tid=0x00005583ec93a800 nid=0x1ae runnable [0x00007f94a7877000]
   java.lang.Thread.State: RUNNABLE
        at java.io.FileOutputStream.writeBytes(Native Method)
        at java.io.FileOutputStream.write(FileOutputStream.java:326)
        at java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:82)
        at java.io.BufferedOutputStream.flush(BufferedOutputStream.java:140)
        - locked <0x00000006c5902190> (a java.io.BufferedOutputStream)
        at java.io.PrintStream.write(PrintStream.java:482)
        - locked <0x00000006c5902170> (a java.io.PrintStream)
        at sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:221)
        at sun.nio.cs.StreamEncoder.implFlushBuffer(StreamEncoder.java:291)
        at sun.nio.cs.StreamEncoder.flushBuffer(StreamEncoder.java:104)
        - locked <0x00000006c59022b0> (a java.io.OutputStreamWriter)
        at java.io.OutputStreamWriter.flushBuffer(OutputStreamWriter.java:185)
        at java.io.PrintStream.write(PrintStream.java:527)
        - locked <0x00000006c5902170> (a java.io.PrintStream)
        at java.io.PrintStream.print(PrintStream.java:583)
        at org.fusesource.jansi.FilterPrintStream.write(FilterPrintStream.java:99)
        at org.fusesource.jansi.FilterPrintStream.write(FilterPrintStream.java:107)
        at org.fusesource.jansi.FilterPrintStream.print(FilterPrintStream.java:156)
        at java.io.PrintStream.append(PrintStream.java:1065)
        at org.apache.maven.plugin.surefire.report.DirectConsoleOutput.writeTestOutput(DirectConsoleOutput.java:66)
        - locked <0x00000006c5c77788> (a org.fusesource.jansi.AnsiPrintStream)
        at org.apache.maven.plugin.surefire.report.TestSetRunListener.writeTestOutput(TestSetRunListener.java:152)
        - locked <0x00000006c649b138> (a org.apache.maven.plugin.surefire.report.TestSetRunListener)
        at org.apache.maven.surefire.report.ConsoleOutputCapture$ForwardingPrintStream.write(ConsoleOutputCapture.java:60)
        at sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:221)
        at sun.nio.cs.StreamEncoder.implWrite(StreamEncoder.java:282)
        at sun.nio.cs.StreamEncoder.write(StreamEncoder.java:125)
        - locked <0x00000006c6564cf0> (a java.io.OutputStreamWriter)
        at java.io.OutputStreamWriter.write(OutputStreamWriter.java:207)
        at java.io.BufferedWriter.flushBuffer(BufferedWriter.java:129)
        - locked <0x00000006c6564cf0> (a java.io.OutputStreamWriter)
        at java.io.BufferedWriter.write(BufferedWriter.java:230)
        - locked <0x00000006c6564cf0> (a java.io.OutputStreamWriter)
        at java.io.Writer.write(Writer.java:157)
        at java.io.PrintStream.write(PrintStream.java:525)
        - locked <0x00000006c6564c90> (a org.apache.maven.surefire.report.ConsoleOutputCapture$ForwardingPrintStream)
        at java.io.PrintStream.print(PrintStream.java:669)
        at nl.xxx.Xxx.lambda$beforeScenario$0(StepDefinitions.java:156)
        at nl.xxx.Xxx$$Lambda$47/961708482.accept(Unknown Source)
        at java.lang.Iterable.forEach(Iterable.java:75)
        at nl.xxx.beforeScenario(Xxx.java:156)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at cucumber.runtime.Utils$1.call(Utils.java:32)
        at cucumber.runtime.Timeout.timeout(Timeout.java:16)
        at cucumber.runtime.Utils.invoke(Utils.java:26)
        at cucumber.runtime.java.JavaHookDefinition.execute(JavaHookDefinition.java:60)
        at cucumber.runtime.HookDefinitionMatch.runStep(HookDefinitionMatch.java:17)
        at cucumber.runner.UnskipableStep.executeStep(UnskipableStep.java:22)
        at cucumber.api.TestStep.run(TestStep.java:83)
        at cucumber.api.TestCase.run(TestCase.java:58)
        at cucumber.runner.Runner.runPickle(Runner.java:80)
        at cucumber.runtime.junit.PickleRunners$NoStepDescriptions.run(PickleRunners.java:140)
        at cucumber.runtime.junit.FeatureRunner.runChild(FeatureRunner.java:68)
        at cucumber.runtime.junit.FeatureRunner.runChild(FeatureRunner.java:23)
        at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
        at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
        at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
        at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
        at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
        at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
        at cucumber.runtime.junit.FeatureRunner.run(FeatureRunner.java:73)
        at cucumber.api.junit.Cucumber.runChild(Cucumber.java:117)
        at cucumber.api.junit.Cucumber.runChild(Cucumber.java:55)
        at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
        at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
        at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
        at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
        at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
        at cucumber.api.junit.Cucumber$1.evaluate(Cucumber.java:126)
        at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
        at org.apache.maven.surefire.junit4.JUnit4Provider.execute(JUnit4Provider.java:365)
        at org.apache.maven.surefire.junit4.JUnit4Provider.executeWithRerun(JUnit4Provider.java:273)
        at org.apache.maven.surefire.junit4.JUnit4Provider.executeTestSet(JUnit4Provider.java:238)
        at org.apache.maven.surefire.junit4.JUnit4Provider.invoke(JUnit4Provider.java:159)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at org.apache.maven.surefire.util.ReflectionUtils.invokeMethodWithArray2(ReflectionUtils.java:186)
        at org.apache.maven.surefire.booter.ProviderFactory$ProviderProxy.invoke(ProviderFactory.java:161)
        at org.apache.maven.surefire.booter.ProviderFactory.invokeProvider(ProviderFactory.java:84)
        at org.apache.maven.plugin.surefire.InPluginVMSurefireStarter.runSuitesInProcess(InPluginVMSurefireStarter.java:87)
        at org.apache.maven.plugin.surefire.AbstractSurefireMojo.executeProvider(AbstractSurefireMojo.java:1144)
        at org.apache.maven.plugin.surefire.AbstractSurefireMojo.executeAfterPreconditionsChecked(AbstractSurefireMojo.java:1002)
        at org.apache.maven.plugin.surefire.AbstractSurefireMojo.execute(AbstractSurefireMojo.java:848)
        at org.apache.maven.plugin.DefaultBuildPluginManager.executeMojo(DefaultBuildPluginManager.java:137)
        at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:208)
        at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:154)
        at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:146)
        at org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject(LifecycleModuleBuilder.java:117)
        at org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject(LifecycleModuleBuilder.java:81)
        at org.apache.maven.lifecycle.internal.builder.singlethreaded.SingleThreadedBuilder.build(SingleThreadedBuilder.java:56)
        at org.apache.maven.lifecycle.internal.LifecycleStarter.execute(LifecycleStarter.java:128)
        at org.apache.maven.DefaultMaven.doExecute(DefaultMaven.java:305)
        at org.apache.maven.DefaultMaven.doExecute(DefaultMaven.java:192)
        at org.apache.maven.DefaultMaven.execute(DefaultMaven.java:105)
        at org.apache.maven.cli.MavenCli.execute(MavenCli.java:954)
        at org.apache.maven.cli.MavenCli.doMain(MavenCli.java:288)
        at org.apache.maven.cli.MavenCli.main(MavenCli.java:192)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at org.codehaus.plexus.classworlds.launcher.Launcher.launchEnhanced(Launcher.java:289)
        at org.codehaus.plexus.classworlds.launcher.Launcher.launch(Launcher.java:229)
        at org.codehaus.plexus.classworlds.launcher.Launcher.mainWithExitCode(Launcher.java:415)
        at org.codehaus.plexus.classworlds.launcher.Launcher.main(Launcher.java:356)

   Locked ownable synchronizers:
        - None

So this sounds like a generic Docker issue to me.

[chanjarster]

see this issue: moby/moby#35865 (comment)

try upgrade docker-ce to >= 18.06