Bug 49481 - Log4j stops writting to file, and then causes server to lockup
Summary: Log4j stops writting to file, and then causes server to lockup
Status: NEW
Alias: None
Product: Log4j - Now in Jira
Classification: Unclassified
Component: Other (show other bugs)
Version: 1.2
Hardware: PC Windows Vista
: P2 major
Target Milestone: ---
Assignee: log4j-dev
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2010-06-21 14:17 UTC by Richard
Modified: 2014-01-16 19:17 UTC (History)
2 users (show)



Attachments
2 console outputs, log manager source, and xml file (29.60 KB, application/x-zip-compressed)
2010-06-21 14:17 UTC, Richard
Details
RAD's OutputStreamWriter (12.94 KB, text/plain)
2010-06-22 14:15 UTC, Richard
Details

Note You need to log in before you can comment on or make changes to this bug.
Description Richard 2010-06-21 14:17:20 UTC
Created attachment 25625 [details]
2 console outputs, log manager source, and xml file

I am using log4j 1.2.16 in a java application called RPlans. It is being run with Rational Application Developer 7.5.5.1 on Windows Vista.

Recently, we have been having problems where log4j stops writing to the file, then later after a MySQL exception, starts spitting out exceptions and causes the application to become unresponsive.

I have attached the console outputs when this happens, my log manager source that I use, and my xml file.

Basically my workstation is acting as a Server for my group, as we can not get a real server at the moment. Every night I reboot my computer before leaving.

Friday (6/21), when the server comes up when I leave, it has access to the log file and is writing logs in it. By the time Monday comes around, and people start using the server again, the logger fails to write to the file (there are messages in the console, but no duplicates in the log file), but it doesn't spit out any exceptions. Then when someone starts using the MySQL connection, MySQL creates an exception on the close (which I believe to be a seperate problem), and after that, log4j spits out exceptions on every use and makes the server unusable until I manually reboot my computer.

Caused by: java.lang.ArrayIndexOutOfBoundsException: Array index out of range: 512
	at java.io.OutputStreamWriter.write(OutputStreamWriter.java:250)
	at java.io.Writer.write(Writer.java:152)
	at org.apache.log4j.helpers.CountingQuietWriter.write(CountingQuietWriter.java:45)

We just recently upgraded to Vista from XP and we never had this problem in XP. This seems to only happen on Monday morning as the server and log4j are fine the rest of the week. We think maybe the admins are deploying updates to the computer, which is causing the file link and mysql link to be disrupted. The log file is being saved to a shared drive, and mysql is running off my computer too.

Last time this happened, I was also using an old version of log4j (1.1.3) (represented in 6/7 console output). So the first thing I tried was upgrading to 1.2.16. The upgrade did produce a different crash (6/7, it just froze on a wait, 6/21 it produced an out of bounds exception), but the end result was still the same.

[6/7/10 8:54:38:404 GMT-05:00] 00000012 ThreadMonitor W   WSVR0605W: Thread "WebContainer : 2" (00000019) has been active for 683784 milliseconds and may be hung.  There is/are 1 thread(s) in total in the server that may be hung.
	at org.apache.log4j.Category.callAppenders(Category.java:253)
	at org.apache.log4j.Category.forcedLog(Category.java:445)
	at org.apache.log4j.Category.info(Category.java:720)
	at gov.ssa.rplansdomain.utils.LogManager.info(LogManager.java:28)

I'm not sure if there is anyway to fix the link with the file, but is there anyway to fix log4j so that it doesn't take down the whole server with it?
Thanks for your help.
Comment 1 Curt Arnold 2010-06-21 22:00:57 UTC
An ArrayOutOfBoundsException at that line has been previously reported on log4j-user and also in contexts that are independent of log4j (search for OutputStreamWriter ArrayOutOfBoundsException).  For the exception that you reported, the issue is either a JDK level bug or a misuse of the JDK (such as concurrent use of a non-thread safe object) resulting in undefined behavior.  log4j passes a String to OutputStreamWriter and can't be responsible for iterating outside of an array.

log4j has a global lock that should have prevented concurrent calls to OutputStreamWriter.

The line number in OutputStreamWriter does not correspond to the current Sun JDK source code available at http://download.java.net/jdk6/source/ since OutputStreamWriter.java has only 218 lines in the version.

I checked the Java bug database and found no reports that seemed to correspond.

As far as I can tell you are running into a JDK bug.  While log4j is involved in the crash, don't have any indication that it is anything other than an innocent victim.

Are you able to upgrade to JDK 6?  If not, do you have access to the JDK code corresponding the JDK that you are running and can you identify what might be going wrong on line 250 of OutputStreamWriter.
Comment 2 Richard 2010-06-22 14:15:41 UTC
Created attachment 25629 [details]
RAD's OutputStreamWriter

line 250: System.arraycopy(cbuf, off, buffer, index+1, len);
Comment 3 Richard 2010-06-22 14:27:33 UTC
I am using RAD, which is an IBM product and they seem to be using their own version of the JDK. Here is the info it tells me:

java.vm.version=2.4
java.vm.vendor=IBM Corporation
java.vm.info=JRE 1.6.0 IBM J9 2.4 Windows Vista x8...
java.vendor.url=http://www.ibm.com/
java.version=1.6.0
java.vendor=IBM Corporation
java.specification.version=1.6
java.class.version=50.0
java.fullversion=JRE 1.6.0 IBM J9 2.4 Windows Vista x8...
java.vm.specification.version=1.0
java.vm.name=IBM J9 VM

I am told by someone else in my area, that they tried to switch it to Sun's JDK and it wouldn't work. IBM must need their own special code in it in places for it work. I am also told that we should have the latest version of the IBM JDK.

As for what is at line 250, I have provided RAD's OutputStreamWriter class. The line contains: System.arraycopy(cbuf, off, buffer, index+1, len);

I noticed the class says 6/6/7 while Sun's says 10/3/23, which seems like it is pretty outdated. I'm not sure if it is possible to update just a few classes to IBM's SDK and see if that will fix the issue.
Comment 4 Gabriel Negri 2014-01-16 18:26:50 UTC
We have the same problem as Richard, with the same IBM JDK. 
Any Log4j correction for this issue? 
Greetings.-