Bug 48141

Summary: Log file rotation issue in Linux VM
Product: Log4j - Now in Jira Reporter: shree <v.shreeraghavan>
Component: OtherAssignee: log4j-dev <log4j-dev>
Status: NEEDINFO ---    
Severity: critical    
Priority: P2    
Version: 1.2   
Target Milestone: ---   
Hardware: PC   
OS: Linux   

Description shree 2009-11-05 13:00:15 UTC
Hi Frds,

I am facing an issue with log4j.

Initially we had java processes running in a physical server(Linux useclpcll068apa.nbcuni.ge.com 2.4.21-27.0.2.ELsmp #1 SMP Wed Jan 12 23:35:44 EST 2005 i686 i686 i386 GNU/Linux , Red Hat Enterprise Linux AS release 3 (Taroon Update 3)) with java version 1.4 for around two years and log file rotation was happening fine. 

Now recently we have moved the process to a VM (2.6.18-53.1.21.el5 #1 SMP Wed May 7 08:42:34 EDT 2008 x86_64 x86_64 x86_64 GNU/Linux , Red Hat Enterprise Linux Server release 5.1 (Tikanga)) with java version 1.5. But now currently when the file reaches the maximum size, then it is not able to rotate the log file. The issue is apvs.log is getting renamed as apvs.log.1 but I am getting the below errors and the new file apvs.log is not getting created. I could not get solution for this in web. When i reduced the size to 1 KB also, i am facing the same issue and it is not consistent and no patter also. Can someone pls help me on this.

Property file entry
==================

#Defining the Application Specific Loggers(APVS) and defining their File Appenders
log4j.logger.com.ge.nbc.program=debug,apvs
log4j.logger.com.ge.nbc.media=debug,apvs
log4j.appender.apvs=org.apache.log4j.RollingFileAppender
log4j.appender.apvs.Threshold=DEBUG
log4j.appender.apvs.File=/nbcpbat01/appl_data/apv/logs/encoderMgr/138/apvs.log
log4j.appender.apvs.MaxFileSize=20MB
log4j.appender.apvs.MaxBackupIndex=5
log4j.appender.apvs.layout=org.apache.log4j.PatternLayout
log4j.appender.apvs.layout.ConversionPattern=%d{yy/MM/dd;HH:mm:ss;SSS;} %-5p %C{3};:(%F:%M():%L) - %m%n

Error that i received in javaerr.log
====================================
log4j:ERROR Could not close org.apache.log4j.helpers.CountingQuietWriter@13c296b
java.io.IOException: Input/output error
	at java.io.FileOutputStream.close0(Native Method)
	at java.io.FileOutputStream.close(FileOutputStream.java:279)
	at sun.nio.cs.StreamEncoder$CharsetSE.implClose(StreamEncoder.java:431)
	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:171)
	at org.apache.log4j.RollingFileAppender.rollOver(RollingFileAppender.java:135)
	at org.apache.log4j.RollingFileAppender.subAppend(RollingFileAppender.java:228)
	at org.apache.log4j.WriterAppender.append(WriterAppender.java:150)
	at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:221)
	at org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:57)
	at org.apache.log4j.Category.callAppenders(Category.java:187)
	at org.apache.log4j.Category.forcedLog(Category.java:372)
	at org.apache.log4j.Category.debug(Category.java:241)
	at com.ge.nbc.media.adapter.encoder.helper.MediaEncoderAdapterHelper.findEncoderStatus(Unknown Source)
	at com.ge.nbc.media.bus.recording.helper.MediaRecordingHelper.processMediaEncoding(MediaRecordingHelper.java:7145)
	at com.ge.nbc.media.bus.recording.helper.MediaRecordingHelper.processMediaRecording(MediaRecordingHelper.java:1892)
	at com.ge.nbc.media.bus.recording.bd.MediaRecordingBD.processMediaRecording(MediaRecordingBD.java:338)
	at com.ge.nbc.program.bus.recording.helper.ProgramRecordingHelper.processProgramRecording(ProgramRecordingHelper.java:624)
	at com.ge.nbc.program.bus.recording.bd.ProgramRecordingBD.processProgramRecording(ProgramRecordingBD.java:370)
	at com.ge.nbc.program.app.recording.handler.ProgramRecordingHandler.onMessage(ProgramRecordingHandler.java:2933)
	at com.tibco.tibjms.TibjmsSession._submit(TibjmsSession.java:2775)
	at com.tibco.tibjms.TibjmsSession._dispatchAsyncMessage(TibjmsSession.java:1413)
	at com.tibco.tibjms.TibjmsSession$Dispatcher.run(TibjmsSession.java:2491)
**Exception in MessageListener**:
java.lang.IllegalStateException: Current state = FLUSHED, new state = CODING
	at java.nio.charset.CharsetEncoder.throwIllegalStateException(CharsetEncoder.java:941)
	at java.nio.charset.CharsetEncoder.encode(CharsetEncoder.java:537)
	at sun.nio.cs.StreamEncoder$CharsetSE.implWrite(StreamEncoder.java:384)
	at sun.nio.cs.StreamEncoder.write(StreamEncoder.java:136)
	at sun.nio.cs.StreamEncoder.write(StreamEncoder.java:146)
	at java.io.OutputStreamWriter.write(OutputStreamWriter.java:204)
	at java.io.Writer.write(Writer.java:126)
	at org.apache.log4j.helpers.CountingQuietWriter.write(CountingQuietWriter.java:36)
	at org.apache.log4j.WriterAppender.subAppend(WriterAppender.java:292)
	at org.apache.log4j.RollingFileAppender.subAppend(RollingFileAppender.java:225)
	at org.apache.log4j.WriterAppender.append(WriterAppender.java:150)
	at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:221)
	at org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:57)
	at org.apache.log4j.Category.callAppenders(Category.java:187)
	at org.apache.log4j.Category.forcedLog(Category.java:372)
	at org.apache.log4j.Category.error(Category.java:303)
	at com.ge.nbc.program.app.recording.handler.ProgramRecordingHandler.onMessage(ProgramRecordingHandler.java:2958)
	at com.tibco.tibjms.TibjmsSession._submit(TibjmsSession.java:2775)
	at com.tibco.tibjms.TibjmsSession._dispatchAsyncMessage(TibjmsSession.java:1413)
	at com.tibco.tibjms.TibjmsSession$Dispatcher.run(TibjmsSession.java:2491)
**Exception in MessageListener**:
java.lang.IllegalStateException: Current state = FLUSHED, new state = CODING

Thanks,
Jayasree
Comment 1 Jacob Kjome 2009-11-05 20:21:41 UTC
*** Bug 48142 has been marked as a duplicate of this bug. ***
Comment 2 Curt Arnold 2009-11-08 13:53:04 UTC
Possibly due to bugs in Sun's Java VM,

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

Looks like they were fixed in JDK 1.6.