Bug 42933

Summary: IllegalStateException thrown from FileAppender.closeFile() when log file is actively being tailed
Product: Log4j - Now in Jira Reporter: Jake Happs <jake.happs>
Component: AppenderAssignee: log4j-dev <log4j-dev>
Status: NEEDINFO ---    
Severity: major CC: jake.happs, jlindwall, thorbjoern
Priority: P2    
Version: 1.2   
Target Milestone: ---   
Hardware: Sun   
OS: Solaris   

Description Jake Happs 2007-07-18 14:22:39 UTC
I am using a custom subclass of FileAppender to write log messages to a file.  
If the log file being written is being actively tailed (using 'tail -f') and 
the software calls closeFile() or setFile() (which calls closeFile()) on the 
FileAppender superclass, an IllegalStateException is thrown.  The stack trace 
is included below.  This exception is thrown every time closeFile() or setFile
() are called after the exception is first thrown, even if the active tail has 
been closed.

The partial stack trace is:

Exception in thread "AWT-EventQueue-0" java.lang.IllegalStateException: Current 
state = FLUSHED, new state = CODING_END
        at java.nio.charset.CharsetEncoder.throwIllegalStateException
(CharsetEncoder.java:941)
        at java.nio.charset.CharsetEncoder.encode(CharsetEncoder.java:537)
        at sun.nio.cs.StreamEncoder$CharsetSE.flushLeftoverChar
(StreamEncoder.java:358)
        at sun.nio.cs.StreamEncoder$CharsetSE.implClose(StreamEncoder.java:414)
        at sun.nio.cs.StreamEncoder.close(StreamEncoder.java:160)
        at java.io.OutputStreamWriter.close(OutputStreamWriter.java:222)
        at java.io.FilterWriter.close(FilterWriter.java:92)
        at org.apache.log4j.FileAppender.closeFile(FileAppender.java:183)
        at org.apache.log4j.FileAppender.reset(FileAppender.java:338)
        at org.apache.log4j.FileAppender.setFile(FileAppender.java:283)
        ...
        ...
Comment 1 Henri Yandell 2007-08-23 02:16:52 UTC
JVM bug maybe?
Comment 2 John Lindwall 2007-10-04 23:15:08 UTC
We are also seeing this problem but with Log4j's DailyRollingFileAppender and 
FileAppender.  It occurs in jdk 1.5.0_11 and jdk1.5.0_13 but not in 
j2sdk1.3.1_20.

Here is a dorky test program to reproduce it:

import org.apache.log4j.FileAppender;
import org.apache.log4j.Logger;
import org.apache.log4j.Priority;
import org.apache.log4j.PatternLayout;
import org.apache.log4j.spi.LoggingEvent;

public class TailBug
{
    public static void main(String[] args) throws InterruptedException
    {
        final String filename = "tailme";

        FileAppender fa = new FileAppender();
        fa.setName("myappender");
        fa.setFile(filename);
        fa.setLayout(new PatternLayout("%d %m%n"));
        fa.activateOptions();

        writeSomeMessages(fa);

        System.out.println("NOW Start tailing " + filename + "!!!!!\n");
        System.out.println("The logfile will be rotated to in 10 seconds");

        Thread.sleep(10000);

        final String newfilename = "tailme2";

        fa.setFile(newfilename);
        fa.activateOptions();   // Exception will be thrown here

        writeSomeMessages(fa);

        System.out.println("Done!");
    }

    private static void writeSomeMessages(FileAppender fa)
    {
        System.out.println("Logging 5 messages to file " + fa.getFile() 
+ "...\n");
        for( int i = 0; i < 5; i++ )
        {
            fa.append(new LoggingEvent("", Logger.getLogger("log"), 
Priority.WARN, "This is a test message", null));
        }
    }
}
Comment 3 John Lindwall 2007-10-16 14:00:46 UTC
This seems to be Sun JVM bug 5005426 (which was also later reported in a 
duplicate bug 5005419).

It does not affect JVM 1.3.1 or Java 6, in my experimentation.  I'll see if I 
can get this bug re-opened in JDK 1.5.0.



http://bugs.sun.com/bugdatabase/view_bug.do?bug_id=5005426

5005426 

http://bugs.sun.com/bugdatabase/view_bug.do?bug_id=5005419

5005419 
Comment 4 John Lindwall 2007-10-16 14:18:38 UTC
I've opened a bug request with Sun to notify them that this bug (which was 
fixed in 1.3.1 and 1.4.2 AND Java 6) is affecting Java 5.

I'll report any status here; for now their automated system has simply 
accepted my report.
Comment 5 John Lindwall 2007-10-30 09:04:31 UTC
Sun has been very helpful and speedy in addressing this regression bug.  They 
have a fix for it, and it will roll it out ASAP (probably for jdk 1.5.0_15).

-------------

Problem Description
(Expand on problem statement as necessary)

Escalate Bug 5005426 for JDK 5.0.  This bug was fixed in 1.4.2 and in 6.0, but 
still existed in 5.0.

-------------------------------------------------------

Solution Note
(Root Cause, Possible Causes or Actions taken for Closure)

Sustaining will backport the fix into a 5.0 update release (most likely _15).
Comment 6 Thorbjørn Ravn Andersen 2008-06-30 13:28:00 UTC
If this has been identified to be a Sun bug and they have accepted it, would it be reasonable to close this bug?
Comment 7 Thorbjørn Ravn Andersen 2008-08-02 12:36:19 UTC
No response in a month.  Setting to NEEDINFO.