Digging through the code, I do see that DRDAConnetionThread can restart the
NetworkServer if it sees a shutdown exception:
private void writeSQLCARD(SQLException e,int severity,
int updateCount, long rowCount ) throws DRDAProtocolException
{
writer.createDssObject();
writer.startDdm(CodePoint.SQLCARD);
writeSQLCAGRP(e, getSqlCode(severity), updateCount, rowCount);
writer.endDdmAndDss();
// If we have a shutdown exception, restart the server.
if (e != null) {
String sqlState = e.getSQLState();
if (sqlState.regionMatches(0,
SQLState.CLOUDSCAPE_SYSTEM_SHUTDOWN, 0, 5)) {
// then we're here because of a shutdown exception;
// "clean up" by restarting the server.
try {
server.startNetworkServer();
} catch (Exception restart)
// any error messages should have already been
printed,
// so we ignore this exception here.
{}
}
}
}
So this would explain how the process was still alive even though the derby.log
said the Derby engine was shutting down. I am still trying to find out how the
derby.log got replaced and recreated with this message being the first one
within when the derby.properties is setup to have derby.log always appended to.
I am having trouble following the code to where this might happen.
I looked at how could a shutdown be triggered and I found that:
SystemContext.cleanupOnError can cause a system shutdown if the exception has
severity >= ExceptionSeverity.SYSTEM_SEVERITY. Right before the shutdown, it
appears a message is logged to derby.log that would indicate the error. But
alas, the derby.log is being recreated for some reason. I am struggling to
find out where or why.
Maybe someone can point me to the right area in the code to look at?
Brett
-----Original Message-----
From: Bergquist, Brett [mailto:[email protected]]
Sent: Tuesday, February 28, 2012 7:41 PM
To: [email protected]
Subject: RE: Had Derby 10.8.2.2 fail today and need some thoughts
Hardware is Oracle M5000 running Solaris 10. Database engine is controlled
through SMF of Solaris. derby.properties is setup to always append to the
log, never truncate. There definitely is not more than one process starting
the Network Server.
Here is another tidbit. Even though the log says the Derby engine was
shutting down, the process was still alive (prstat showed this) and the SMF log
also showed that the Network Server process never terminated.
>From a previous capture of the "derby.log", it also appeared this happened on
>the Feb 24'th as well, but seemed to recover and continue running. Strange?
On an separate thought in case it has to do with an out of memory condition, I
was using jvisualvm the other day and monitoring the heap/garbage collection on
a test system that tries to mimic this setup (Oracle M3000). I did a heap
dump an noticed many objects relating to XA transaction timeout timers. About
600K of these. They seemed to be owned by java.util.TimerTask. I remember
seeing some Derby issue updated yesterday or the day before about
java.util.TimerTask holding on to some things. I bring this up because
recently we added the property to derby.properties to cancel XA transactions if
they take to long. We probably do about 6M XA transactions a day and I am
wondering if maybe there is some sort of leak here. I will try my setup and
look again tomorrow using jvisualvm.
I appreciate your thoughts.
Brett
________________________________________
From: Mike Matrigali [[email protected]]
Sent: Tuesday, February 28, 2012 6:40 PM
To: [email protected]
Subject: Re: Had Derby 10.8.2.2 fail today and need some thoughts
Don't know by more info might help. A catch 22 is that usually the top of the
derby.log usually has all the environment info that could be useful.
Can you list OS, JVM. I/O handling to the log is likely an OS thing. What
properties do you have set, any special for error logging?
I would likely look first for multiple starts and stops of derby and a setting
default for one of them to truncate the derby.log.
Maybe leading to multiple processes trying to write to same derby.log.
/mikem
Bergquist, Brett wrote:
> Our customer called and said the server was not working. Before
> restarting, I retrieved the derby.log and it seems strange because
> this was right at the top of the log:
>
>
>
> ----------------------------------------------------------------
>
> Tue Feb 28 15:33:58 EST 2012: Shutting down Derby engine
>
> ----------------------------------------------------------------
>
> Tue Feb 28 15:37:28 EST 2012 Thread[DRDAConnThread_245,5,main] (XID =
> 1482003981), (SESSIONID = 133257672), (DATABASE = csemdb), (DRDAID =
> ????????.??-4471791624540787385{335696}), Cleanup action starting
>
> Tue Feb 28 15:37:28 EST 2012 Thread[DRDAConnThread_245,5,main] (XID =
> 1482003981), (SESSIONID = 133257672), (DATABASE = csemdb), (DRDAID =
> ????????.??-4471791624540787385{335696}), Failed Statement is: null
>
> java.lang.NullPointerException
>
> Cleanup action completed
>
>
>
> The strange part is "Shutting down Derby engine" is the first thing in
> the log. The server was up and running since 2/16/2012 with no
> problems with about 60M transactions processed, a backup performed each
> night, etc. And then this.
>
>
>
> So any thoughts on how the derby.log could be recreated and have this as
> the first thing in the log? I am thinking maybe an OutOfMemory
> condition but all traces of whatever when wrong are gone, so I am
> trying to work backwards and see how the derby.log could be created
> with this as the first thing in the log.
>
>
>
> Thanks for any help!
>
>
>
> Brett
>
>
>
>
>
