Fading Coder

One Final Commit for the Last Sprint

Home > Tech > Content

RUNNABLE Thread Stalls in FileOutputStream.writeBytes on Windows When the Console Is Paused

Tech 2

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

Related Articles

Understanding Strong and Weak References in Java

Strong References Strong reference are the most prevalent type of object referencing in Java. When an object has a strong reference pointing to it, the garbage collector will not reclaim its memory. F...

Comprehensive Guide to SSTI Explained with Payload Bypass Techniques

Introduction Server-Side Template Injection (SSTI) is a vulnerability in web applications where user input is improper handled within the template engine and executed on the server. This exploit can r...

Implement Image Upload Functionality for Django Integrated TinyMCE Editor

Django’s Admin panel is highly user-friendly, and pairing it with TinyMCE, an effective rich text editor, simplifies content management significantly. Combining the two is particular useful for bloggi...

Leave a Comment

Anonymous

◎Feel free to join the discussion and share your thoughts.