RUNNABLE Thread Stalls in FileOutputStream.writeBytes on Windows When the Console Is Paused
Quartz-triggered jobs and HTTP requests produce a large volume of DEBUG logs. With Logback configured to write to both the console and a rolling file, Tomcat on Windows intermittently appears to stop respodning even though TCP connections remain established.
Observable symptoms
- Tomcat console initially prints logs and then stops updating.
- Browser keeps an ESTABLISHED connection to Tomcat (verified via netstat), but pages stop loading.
- Quartz logs stop appearing even though the scheduler thread is alive.
- A thread dump shows many request threads waiting inside Logback, while one worker thread is RUNNABLE in native write I/O:
"http-bio-8189-exec-2" daemon prio=6 ... java.lang.Thread.State: RUNNABLE
at java.io.FileOutputStream.writeBytes(Native Method)
at java.io.FileOutputStream.write(FileOutputStream.java:345)
at java.io.BufferedOutputStream.write(BufferedOutputStream.java:122)
- locked <0x...> (a java.io.BufferedOutputStream)
at java.io.PrintStream.write(PrintStream.java:480)
- locked <0x...> (a java.io.PrintStream)
at org.apache.tomcat.util.log.SystemLogHandler.write(SystemLogHandler.java:169)
at ch.qos.logback.core.joran.spi.ConsoleTarget$1.write(ConsoleTarget.java:36)
at ch.qos.logback.core.encoder.LayoutWrappingEncoder.doEncode(LayoutWrappingEncoder.java:135)
at ch.qos.logback.core.OutputStreamAppender.writeOut(OutputStreamAppender.java:194)
at ch.qos.logback.core.OutputStreamAppender.subAppend(OutputStreamAppender.java:219)
...
Other worker and scheduler threads are blocked waiting for the same Logback appender locck:
"http-bio-8189-exec-6" daemon prio=6 ... java.lang.Thread.State: WAITING (parking)
- parking to wait for <0x...> (a java.util.concurrent.locks.ReentrantLock$FairSync)
at ch.qos.logback.core.OutputStreamAppender.subAppend(OutputStreamAppender.java:217)
at ch.qos.logback.core.OutputStreamAppender.append(OutputStreamAppender.java:103)
...
"org.springframework.scheduling.quartz.SchedulerFactoryBean#0_QuartzSchedulerThread" ... WAITING (parking)
- parking to wait for <0x...> (a java.util.concurrent.locks.ReentrantLock$FairSync)
at ch.qos.logback.core.OutputStreamAppender.subAppend(OutputStreamAppender.java:217)
...
Root cause
On Windows, selecting text in a console window (QuickEdit mode) suspends the console’s output processing. When ConsoleAppender writes to stdout/stderr continuous, the OS pipe/buffer eventually fills. The thread performing the actual write becomes stuck in the native write call (FileOutputStream.writeBytes), and Logback serializes access via a lock, causing other threads attempting to log to block behind it. The application appears hung while connections remain open.
Why a "blocked" thread still shows RUNNABLE
The Java Thread.State RUNNABLE includes threads executing JVM bytecode or blocked in native calls while waiting for operating system resources (e.g., CPU time or device I/O). A thread stuck in FileOutputStream.writeBytes can therefore show RUNNABLE even though it cannot make forward progress because the OS is not draining the console buffer.
Immediate unstick
- Press Enter in the console window or cancel the selection to resume the console. Output drains and the application continues.
- Permanently disable QuickEdit mode on the console window to prevent accidental pauses.
Hardening and mitigation
- Avoid console logging on Windows for busy servers; write to files only.
- If console output is required, reduce volume (raise level to INFO/WARN) and/or buffer asynchronously.
- Perfer AsyncAppender for I/O isolation to preventt request threads from blocking on slow appenders.
- Separate appenders by level: verbose logs to file, higher-severity logs to console.
Example: configuration that can trigger the issue (console + file at DEBUG)
<configuration>
<appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
<encoder>
<pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</pattern>
</encoder>
</appender>
<appender name="FILE_DAILY" class="ch.qos.logback.core.rolling.RollingFileAppender">
<file>${catalina.base}/logs/foo.log</file>
<rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
<fileNamePattern>${catalina.base}/logs/foo.%d{yyyy-MM-dd}.log</fileNamePattern>
<maxHistory>30</maxHistory>
</rollingPolicy>
<encoder>
<pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{35} - %msg%n</pattern>
</encoder>
</appender>
<root level="DEBUG">
<appender-ref ref="CONSOLE"/>
<appender-ref ref="FILE_DAILY"/>
</root>
</configuration>
Safer alternatives
- Raise console threshold and keep file at DEBUG:
<configuration>
<appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
<filter class="ch.qos.logback.classic.filter.ThresholdFilter">
<level>INFO</level>
</filter>
<encoder>
<pattern>%date{HH:mm:ss} %-5level [%thread] %logger{32} - %msg%n</pattern>
</encoder>
</appender>
<appender name="FILE_DAILY" class="ch.qos.logback.core.rolling.RollingFileAppender">
<file>${catalina.base}/logs/app.log</file>
<rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
<fileNamePattern>${catalina.base}/logs/app.%d{yyyy-MM-dd}.log</fileNamePattern>
<maxHistory>30</maxHistory>
</rollingPolicy>
<encoder>
<pattern>%date %-5level [%thread] %logger{30} - %msg%n</pattern>
</encoder>
</appender>
<appender name="ASYNC_FILE" class="ch.qos.logback.classic.AsyncAppender">
<queueSize>8192</queueSize>
<discardingThreshold>0</discardingThreshold>
<includeCallerData>false</includeCallerData>
<appender-ref ref="FILE_DAILY"/>
</appender>
<root level="DEBUG">
<appender-ref ref="CONSOLE"/>
<appender-ref ref="ASYNC_FILE"/>
</root>
</configuration>
- Remove the console appender entirely for servers and log exclusively to rolling files.
Useful commands
- Inspect connections:
netstat -aon | findstr 8189
- Capture a thread dump:
jstack -l <PID> > thread_dump.txt
Environment snapshot
- OS: Windows Server 2008 R2 Enterprise SP1
- Java: 1.7.0_79 (HotSpot 64-bit, mixed mode)
- Tomcat: 7.0.72
Reference
- https://stackoverflow.com/questions/634102/log4j-is-hanging-my-application-what-am-i-doing-wrong