JDK-6712096 : IllegalStateException thrown with text- Current state = FLUSHED,new state=CODING
  • Type: Bug
  • Component: core-libs
  • Sub-Component: java.nio
  • Affected Version: 5.0
  • Priority: P4
  • Status: Closed
  • Resolution: Duplicate
  • OS: windows_xp
  • CPU: x86
  • Submitted: 2008-06-09
  • Updated: 2011-02-16
  • Resolved: 2008-06-14
Related Reports
Duplicate :  
Description
FULL PRODUCT VERSION :
java version "1.5.0_11"
Java(TM) 2 Runtime Environment, Standard Edition (build 1.5.0_11-b03)
Java HotSpot(TM) 64-Bit Server VM (build 1.5.0_11-b03, mixed mode)

ADDITIONAL OS VERSION INFORMATION :
Linux xldn2364dap 2.6.18-8.1.1.el5 #1 SMP Mon Feb 26 20:37:57 EST 2007 x86_64


A DESCRIPTION OF THE PROBLEM :
I believe the cause of the problem is;
- the disk runs out of space in the middle of writing to a file.
- the underlying stream throws an exception.
- this leaves the CharsetEncoder in an inconsistent state. 
- the exception thrown is swallowed by the Writer so you don't see it.
- however the writer/encoder is now in an unrecoverable state, even if
space is now made available.

This is difficult to reproduce as the disk system must run out space at
a certain stage in the encoding. E.g. in the middle of writing a
mult-byte character.

* I feel this is a design flaw in the encoders as it should have finally
{ } blocks to ensure the system is always in a consistent state.
* The Writer shouldn't absorb the exception unless it is going to handle
it correctly.
* Java should have a means of detecting when space is about to run out.
(In Java 5!)
* Log4j should use this to prevent the file from hitting the space
limit.
* Ideally the writer should have a mode where it blocks if no free space
is available. (As it would for other streaming devices like Sockets)

The work around I put in place is as follows;

This is clunky as it 
- waits for the IllegalStateException rather than trapping the actual
IOException raised.
- there is no clean/efficient way to detect the free disk space in Java
5.
- it writes out a file to test the disk space.  If there are multiple
appenders this could cause other log file to run out of space. :(

ERROR MESSAGES/STACK TRACES THAT OCCUR :

java.lang.IllegalStateException: Current state = FLUSHED, new state = CODING

        at java.nio.charset.CharsetEncoder.throwIllegalStateException(Unknown Source)
        at java.nio.charset.CharsetEncoder.encode(Unknown Source)
        at sun.nio.cs.StreamEncoder$CharsetSE.implWrite(Unknown Source)
        at sun.nio.cs.StreamEncoder.write(Unknown Source)
        at sun.nio.cs.StreamEncoder.write(Unknown Source)
        at java.io.OutputStreamWriter.write(Unknown Source)
        at java.io.Writer.write(Unknown Source)
        at org.apache.log4j.helpers.CountingQuietWriter.write(CountingQuietWriter.java:45)
        at org.apache.log4j.WriterAppender.subAppend(WriterAppender.java:302)
        at org.apache.log4j.RollingFileAppender.subAppend(RollingFileAppender.java:263)
        at org.apache.log4j.WriterAppender.append(WriterAppender.java:160)
        at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:251)
        at org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:66)
        at org.apache.log4j.Category.callAppenders(Category.java:206)
        at org.apache.log4j.Category.forcedLog(Category.java:391)
        at org.apache.log4j.Category.info(Category.java:666)


---------- BEGIN SOURCE ----------

import org.apache.log4j.Layout;
import org.apache.log4j.spi.LoggingEvent;

import java.io.File;
import java.io.FileNotFoundException;
import java.io.FileOutputStream;
import java.io.IOException;

public class RollingFileAppender extends
org.apache.log4j.RollingFileAppender {

    public RollingFileAppender() {
        super();
    }

    public RollingFileAppender(Layout layout, String filename, boolean
append) throws IOException {
        super(layout, filename, append);
    }

    public RollingFileAppender(Layout layout, String filename) throws
IOException {
        super(layout, filename);
    }

    public void append(LoggingEvent event) {
        boolean diskOkay = true;
        while (true) {
            if (diskOkay)
                try {
                    super.append(event);
                    return;
                } catch (IllegalStateException e) {
                    if (Thread.currentThread().isInterrupted())
                        throw e;
                    e.printStackTrace();
                }
            diskOkay = waitForFreeSpace();
        }
    }

    private boolean waitForFreeSpace() {
        System.err.println("WARN: Checking free disk space after failing
to write to log file " + fileName);

        File testFile = new File(fileName + ".test");
        FileOutputStream fos = null;
        boolean diskOkay = false;
        try {
            fos = new FileOutputStream(testFile);
            int tenMB = 10 * 1000 * 1000;
            int size = maxFileSize > tenMB ? tenMB : (int) maxFileSize;
            fos.write(new byte[size]);
            fos.close();
            super.rollOver();
            return true;
        } catch (FileNotFoundException e) {
            throw new AssertionError(e);
        } catch (IOException e) {
            System.err.println("ERROR: Log directory out of disk space "
+ fileName + " retrying in 30 seconds.");
            e.printStackTrace();
        } finally {
            LifecycleUtils.close(fos);
            testFile.delete();
        }
        Threads.sleep(30 * 1000);
        return false;
    }
}

---------- END SOURCE ----------


REPRODUCIBILITY :
This bug can be reproduced rarely.

Comments
EVALUATION A CharsetEncoder can only be in "flushed" state after its flush() methold gets invoked StreamEncoder only invokes encoder.flush() in its implClose() (from close()). StreamEncoder.close() is only invoked by its up-level OutputStreamWriter (in this case) So it appears that the uplevel invoker in log4j tries to close the writer, but gets a IOException, then somehow (since the writer is not closed) a second try of "write" operation from uplevel writer/logger triggers this IllegalStateException. I tend to believe this is what happened, and this a dup of 5005426. The fix of 5005426 (in jdk6) should have solved this problem. The solution is to catch the IOException in StreamEncoder when closing, reset the encoder and then re-throw the IOException to up-level invoker. Closed this bug as dup of 5005426, please escalate if a backport to 5u releases is really necessary.
14-06-2008

EVALUATION looks similar to 5005426, need take a detailed look to decide if it's a dup.
13-06-2008