|
I have started to survey ...
My first question was "What is ShutdownException ?" JavaDoc told "A ShutdownException is a runtime exception that is used to notify code that the system has/is being shut down. " http://incubator.apache.org/derby/javadoc/engine/org/apache/derby/iapi/services/context/ShutdownException.html Grepping whole code ,I found ShutdownException was thrown only from next two part. ./engine/org/apache/derby/iapi/services/context/ContextManager.java:374: throw new ShutdownException(); ./engine/org/apache/derby/iapi/services/context/ContextService.java:124: throw new ShutdownException(); Reading each class, I found that these part are executed only when ContextManager or ContextService is in state of shutdown or stopped. These codes completely match explanation in JavaDoc. Each object is in state of shutdown , and ShutdownException happens. Then, next question arise. Why there happens situation of system has/is being shut down during running in DRDAConnThread as reported ? I think reading dataSourcePermissions_net will give me answer. I have read the dataSourcePermissions_net.
dataSourcePermissions_net executes network version of test executed in dataSourcePermissions. Content of tests was implemented in dataSourcePermissions.runTest(). In the test, there exist parts where it is repeated , to create connection to database named wombat and to shut down database via the connection. Reported exception seems to happen in this repeating part. ...see http://issues.apache.org/jira/secure/attachment/20380/derbyall_diff.txt also. I suspect there exists remaining previous thread concerning with that database , when shutting down the database... Then ShutdownException is thrown from previous working thread , I wonder. In my previous comment, I wrote as next.
>In the test, >there exist parts where it is repeated , to create connection to database named wombat and to shut down database via the connection. This is incorrect. Database was shutdown via "another" connection using "jdbc:derby:;shutdown=true", though there exists another connections . Well ... Now I think ShutdownException thrown by rollback process should be treated as Exception. User should not shutdown Database if there remain connections .... Then, Exception in test result itself was truly Exception. And futhermore, connection should be surely closed , though Database was earlier closed and Exception happens in rollback .... I read code org.apache.derby.impl.drda.Database#close();
http://svn.apache.org/repos/asf/incubator/derby/code/trunk/java/drda/org/apache/derby/impl/drda/Database.java Documentation comment for this method said "Close the connection and clean up the statement table.". Reading the code , I found there are next processing 1:if stmtTable exists, call every DRDAStatement.close() in stmtTable. 2:if conn exists 2-1:call conn.rollback() 2-2:call conn.close(). If exception happens in conn.rollback() of 2-1 , conn.close() of 2-2 would be not called as Kathey suggested in previous mail. http://mail-archives.apache.org/mod_mbox/db-derby-dev/200506.mbox/%3c42A65E51.6010800@sbcglobal.net%3e I think conn.close() should be called in finally clause in this method. Consequently, there exists two matter to do.
modify-1: Modify scenario of dataSourcePermissions not to shutdown when connection exists. This will supress errors in test. modify-2: Modify how conn.rollback() is called in org.apache.derby.impl.drda.Database#close() , and make it sure for connection to be closed in exceptional state. Now problem exits in modify-2. How can this to be tested ? The modify-2 can be confirmed under exceptional state that happens indeterministically ... Regarding modify-1, there was a wrong guess in my previous thought.
I thought database was shutdown before closing connection , then connection remains in the dataSourcePermissions test. However, I found connection was closed before shutting down database in the test. To know why connection remains, I read the code around DRDAConnThread. http://svn.apache.org/repos/asf/incubator/derby/code/trunk/java/drda/org/apache/derby/impl/drda/DRDAConnThread.java In last part of DRDAConnThread#run() , I found closing connection at server was caused by DRDAProtocolException that stands for disconnection. This exeption was caused in DDMReader and DDMWriter , calling DRDAConnThread#markCommunicationsFailure when catching IOException. http://svn.apache.org/repos/asf/incubator/derby/code/trunk/java/drda/org/apache/derby/impl/drda/DDMReader.java http://svn.apache.org/repos/asf/incubator/derby/code/trunk/java/drda/org/apache/derby/impl/drda/DDMWriter.java I guess client close the connection one-sidely and DRDAProtocolException representing disconnection happens in server , and rollback and close connection at server follows . Because client is one-side player , client doesn't know wheter server finished work of closing connection . Then ... how to ensure finishing closing connection before shutting down database ...? I have two ideas, neither of which seem ideal but maybe they will give you a better idea.
1) If the exception is intermittent but not harmful you could specify an alternate consoleWriter when you call NetworkServerControl.start(). This way the exception does not print to System.out. This would mean that dataSourcePermissions_net.java would suffer the same deficiencey as the other tests, that the console is not monitored properly by the test. 2) The NetworkServerControl method getRuntimeInfo will show the connection info from the server's perspective. You could alternately sleep for a few seconds and call this method to see the connections from the server perspective. The output is a string that would need to be parsed. It has output that looks like: # Connection Threads : 2 # Active Sessions : 2 # Waiting Sessions : 0 And always includes one session for the runtimeinfo request. The alternate plans ....
alternate-plan-1: Not to output message of exception to STDOUT alternate-plan-2: In the test program , wait to session closed seeing return value of NetworkServerControl#getRuntimeInfo alternate-plan-3: Modify shutdown process to wait session closed. I think alternate-plan-1 have problem that the message of exception should be shown to the user. alternate-plan-3 have problem that If it was failed to close session, shutdown will fail. I think direction of alternation-2 would be best. I will survey one more how to detect all session was closed. To accomplish plan-2,
count of session need to be polled to know wheter all session was closed ... There are next two option. option1: Adding NetworkServerControl#getCountOfSession() method , which retrieve count of sessions from NetworkServerControl. option2: Using getRuntimeInfo() method and parse result of it. In a glance , option1 seems to be straight answer. However , NetworkServerControl#getCountOfSession() have wrong impact to make confusion in future. Because count of session would be vary after the value is retrieved , accessd by other threads. I think count of session is very private information in NetworkServerControl , and should not be retrieved directly from NetworkServerControl. I think it is moderate to take option2 , regarding user checking state of connection seeing getRuntimeInfo ... Summary of what I knew in this issue ever ...
The phenomena found in this issue happens when closing connection falls on shutting down database. To make the phenomena not happen , it is needed to ensure closure of connection before shutting down database. However, it is impossible to close connection in ConnectionPool only using jdbc interface. Then, I think connection managment mechanism outside jdbc is needed to solve this issue .... I have not been able to follow this thread closely, but I don't think I understand how Connection Pooling relates to this problem. Can you post a bit of java code or a standalone java program that demonstrates the issue?
In this test an intentional shutdown causes the close of the connection by network server to encounter an error that prints to the console. It appears it may be the same issue as
It seems this issue is on the high side of "intermittent" I saw it fail twice last night, 1/31 - build 373975
Environment: Generating report for RunSuite derbyall null null null true ------------------ Java Information ------------------ Java Version: 1.5.0_02 Java Vendor: Sun Microsystems Inc. Java home: d:\dev\src\jdk15\jre Java classpath: d:/dev/src/classes/derby.jar;d:/dev/src/classes/derbyLocale_zh_TW.jar;d:/dev/src/classes/derbyLocale_zh_CN.jar;d:/dev/src/classes/derbyLocale_pt_BR.jar;d:/dev/src/classes/derbyLocale_ko_KR.jar;d:/dev/src/classes/derbyLocale_ja_JP.jar;d:/dev/src/classes/derbyLocale_it.jar;d:/dev/src/classes/derbyLocale_fr.jar;d:/dev/src/classes/derbyLocale_es.jar;d:/dev/src/classes/derbyLocale_de_DE.jar;d:/dev/src/classes/derbytools.jar;d:/dev/src/classes/derbynet.jar;d:/dev/src/classes/derbyclient.jar;;d:/dev/src/classes/derbyTesting.jar;d:/dev/src/classes/maps.jar;d:/dev/src/classes/functionTests.jar;d:/dev/src/tools/java/junit.jar;d:/dev/src/tools/java/jndi/fscontext.jar;d:/dev/src/tools/java/RmiJdbc.jar;d:/dev/src/drda/jcc/2.4/db2jcc.jar;d:/dev/src/drda/jcc/2.4/db2jcc_license_c.jar OS name: Windows 2000 OS architecture: x86 OS version: 5.0 Java user name: cloudtst Java user home: C:\Documents and Settings\cloudtst Java user dir: D:\dev\src\JarResults.2006-01-31\jdk15_derbyall java.specification.name: Java Platform API Specification java.specification.version: 1.5 --------- Derby Information -------- JRE - JDBC: J2SE 5.0 - JDBC 3.0 [D:\dev\src\classes\derby.jar] 10.2.0.0 alpha - (373975) [D:\dev\src\classes\derbytools.jar] 10.2.0.0 alpha - (373975) [D:\dev\src\classes\derbynet.jar] 10.2.0.0 alpha - (373975) [D:\dev\src\classes\derbyclient.jar] 10.2.0.0 alpha - (373975) [D:\dev\src\drda\jcc\2.4\db2jcc.jar] 2.4 - (17) [D:\dev\src\drda\jcc\2.4\db2jcc_license_c.jar] 2.4 - (17) ------------------------------------------------------ diff: ********* Diff file derbyall/derbynetclientmats/DerbyNetClient/derbynetmats/derbynetmats/dataSourcePermissions_net.diff *** Start: dataSourcePermissions_net jdk1.5.0_02 DerbyNetClient derbynetmats:derbynetmats 2006-02-01 01:44:45 *** 21a22,23 > org.apache.derby.iapi.services.context.ShutdownException: > agentThread[DRDAConnThread_4,5,derby.daemons] Test Failed. *** End: dataSourcePermissions_net jdk1.5.0_02 DerbyNetClient derbynetmats:derbynetmats 2006-02-01 01:45:28 *** ********* Diff file derbyall/derbynetclientmats/DerbyNetClient/derbynetmats/jdbc20/batchUpdate.diff Second failure: evironment: Generating report for RunSuite derbynetmats null null DerbyNet true ------------------ Java Information ------------------ Java Version: 1.5.0_02 Java Vendor: Sun Microsystems Inc. Java home: d:\dev\src\jdk15\jre Java classpath: d:/dev/src/classes/derby.jar;d:/dev/src/classes/derbytools.jar;d:/dev/src/classes/derbynet.jar;d:/dev/src/classes/derbyclient.jar;d:/dev/src/classes/functionTests.jar;d:/dev/src/classes/derbyTesting.jar;d:/dev/src/tools/java/jndi/fscontext.jar;d:/dev/src/drda/jcc/2.6/db2jcc.jar;d:/dev/src/drda/jcc/2.6/db2jcc_license_c.jar;d:/dev/src/tools/java/junit.jar;d:/dev/src/classes/derbyLocale_zh_TW.jar;d:/dev/src/classes/derbyLocale_zh_CN.jar;d:/dev/src/classes/derbyLocale_pt_BR.jar;d:/dev/src/classes/derbyLocale_ko_KR.jar;d:/dev/src/classes/derbyLocale_ja_JP.jar;d:/dev/src/classes/derbyLocale_it.jar;d:/dev/src/classes/derbyLocale_fr.jar;d:/dev/src/classes/derbyLocale_es.jar;d:/dev/src/classes/derbyLocale_de_DE.jar; OS name: Windows 2000 OS architecture: x86 OS version: 5.0 Java user name: cloudtst Java user home: C:\Documents and Settings\cloudtst Java user dir: D:\dev\src\JarResults.2006-01-31\jdk15_derbynetmats_jcc_2.6 java.specification.name: Java Platform API Specification java.specification.version: 1.5 --------- Derby Information -------- JRE - JDBC: J2SE 5.0 - JDBC 3.0 [D:\dev\src\classes\derby.jar] 10.2.0.0 alpha - (373975) [D:\dev\src\classes\derbytools.jar] 10.2.0.0 alpha - (373975) [D:\dev\src\classes\derbynet.jar] 10.2.0.0 alpha - (373975) [D:\dev\src\classes\derbyclient.jar] 10.2.0.0 alpha - (373975) [D:\dev\src\drda\jcc\2.6\db2jcc.jar] 2.6 - (90) [D:\dev\src\drda\jcc\2.6\db2jcc_license_c.jar] 2.6 - (90) ------------------------------------------------------ Diff: ********* Diff file derbynetmats/DerbyNet/derbynetmats/dataSourcePermissions_net.diff *** Start: dataSourcePermissions_net jdk1.5.0_02 DerbyNet derbynetmats:derbynetmats 2006-02-01 04:32:29 *** 38a39,40 > org.apache.derby.iapi.services.context.ShutdownException: > agentThread[DRDAConnThread_6,5,derby.daemons] Test Failed. *** End: dataSourcePermissions_net jdk1.5.0_02 DerbyNet derbynetmats:derbynetmats 2006-02-01 04:33:05 *** ********* Diff file derbynetmats/DerbyNet/derbynetmats/updatableResultSet.diff Description of patch :
Alter where derbynet/dataSourcePermissions_net.java print ShutdownException from System.out to shutdown.log. Test : Execute derbyall and found no error. The patch committed.
Sending java/drda/org/apache/derby/drda/NetworkServerControl.java Sending java/testing/org/apache/derbyTesting/functionTests/tests/derbynet/dataSourcePermissions_net.java Transmitting file data .. Committed revision 378903. I noticed that the patch for this issue added a new method to the public API.
I think if the public API is being changed we should 1) Add a new Jira issue for that so people know what is being added and can comment 2) Understand why we need a new public method in the API 3) Have javadoc for the api call. I almost missed this all together because it was not mentioned in the patch comments. I thought it was just a test modification. When i updated my client I saw NetworkServerControl had changed so took a look. I was not conscious for modification of public API.
I think it is possible to go on alternative way ,which does not need new method. I will submit patch again for this issue. Writing and testing the new patch, I found manipulating log writer which exists in NetworkServerControlImpl seems to be insufficient...
I could find error was printed to *.out file, though stream for file was passed via constructor. Now, I'm trying to utilize System.setOut and System.setErr instead. This method seems to work well. So are you saying that you start the server with the NetworkServerControl method
public void start(PrintWriter consoleWriter) throws Exception but messages are still going to System.out and System.err? I don't think for this test any of the console output needs to go to System.out. The test is not for testing the console output.
I think that it would be sufficient just start with an alternate console, e.g. DerbyNet.out and all the console output can go there. I don't understand why we need code to alter destination stream before and after shutting down network server Description of the patch :
Alter output before and after shutting down database and escape ShutDownException was printed to console. This modification was done in derbynet/dataSourcePermissions_net.java and derbynet/testSecMec.java which is subclass of former. Test: Execute derbynet/dataSourcePermissions_net.java and Shutting down exception was printed to altered log file. I did same test on derbynet/testSecMec.java. However ShutdownException was not recorded in both of log file and console. It seems that problematic ShutdownException was not happen. Committed
Sending java/testing/org/apache/derbyTesting/functionTests/tests/derbynet/dataSourcePermissions_net.java Sending java/testing/org/apache/derbyTesting/functionTests/tests/derbynet/testSecMec.java Transmitting file data .. Committed revision 380099. This issue has been resolved for over a year with no further movement. Closing.
|
|||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
 |
|
Bug
Closed
Major
The derbynet/dataSourcePermissions_net.java test fails intermittently
However, in this case, the database has been intentionally shut down and the error on rollback is expected. Network Server should treat an error on rollback, when closing a session, as an expected exception if the database has been intentionally shut down.
The intermittent nature of this diff seems to be related to when the session for the disconnected client that shutdown the database gets cleaned up.
When the test fails, this is the trace in the tmp file:
org.apache.derby.iapi.services.context.ShutdownException:
at org.apache.derby.iapi.services.context.ContextManager.checkInterrupt(ContextManager.java:374)
at org.apache.derby.iapi.services.context.ContextManager.popContext(ContextManager.java:152)
at org.apache.derby.iapi.services.context.ContextImpl.popMe(ContextImpl.java:80)
at org.apache.derby.impl.sql.conn.GenericLanguageConnectionContext.resetSavepoints(GenericLanguageConnectionContext.java:1309)
at org.apache.derby.impl.sql.conn.GenericLanguageConnectionContext.doRollback(GenericLanguageConnectionContext.java:1288)
at org.apache.derby.impl.sql.conn.GenericLanguageConnectionContext.userRollback(GenericLanguageConnectionContext.java:1199)
at org.apache.derby.impl.jdbc.TransactionResourceImpl.rollback(TransactionResourceImpl.java:244)
agentThread[DRDAConnThread_3,5,derby.daemons]
at org.apache.derby.impl.jdbc.EmbedConnection.rollback(EmbedConnection.java:894)
at org.apache.derby.impl.drda.Database.close(Database.java:352)
at org.apache.derby.impl.drda.Session.close(Session.java:110)
at org.apache.derby.impl.drda.DRDAConnThread.closeSession(DRDAConnThread.java:6803)
at org.apache.derby.impl.drda.DRDAConnThread.run(DRDAConnThread.java:241)
EXPECTED SHUTDOWN DERBY SQL error: SQLCODEWhen network server closes a session, it tries to perform a rollback on the connection before closing the connection. If it encounters an exception during rollback it treats the exception as an unexpected exception and prints the error to the console.
However, in this case, the database has been intentionally shut down and the error on rollback is expected. Network Server should treat an error on rollback, when closing a session, as an expected exception if the database has been intentionally shut down.
The intermittent nature of this diff seems to be related to when the session for the disconnected client that shutdown the database gets cleaned up.
When the test fails, this is the trace in the tmp file:
org.apache.derby.iapi.services.context.ShutdownException:
at org.apache.derby.iapi.services.context.ContextManager.checkInterrupt(ContextManager.java:374)
at org.apache.derby.iapi.services.context.ContextManager.popContext(ContextManager.java:152)
at org.apache.derby.iapi.services.context.ContextImpl.popMe(ContextImpl.java:80)
at org.apache.derby.impl.sql.conn.GenericLanguageConnectionContext.resetSavepoints(GenericLanguageConnectionContext.java:1309)
at org.apache.derby.impl.sql.conn.GenericLanguageConnectionContext.doRollback(GenericLanguageConnectionContext.java:1288)
at org.apache.derby.impl.sql.conn.GenericLanguageConnectionContext.userRollback(GenericLanguageConnectionContext.java:1199)
at org.apache.derby.impl.jdbc.TransactionResourceImpl.rollback(TransactionResourceImpl.java:244)
agentThread[DRDAConnThread_3,5,derby.daemons]
at org.apache.derby.impl.jdbc.EmbedConnection.rollback(EmbedConnection.java:894)
at org.apache.derby.impl.drda.Database.close(Database.java:352)
at org.apache.derby.impl.drda.Session.close(Session.java:110)
at org.apache.derby.impl.drda.DRDAConnThread.closeSession(DRDAConnThread.java:6803)
at org.apache.derby.impl.drda.DRDAConnThread.run(DRDAConnThread.java:241)
EXPECTED SHUTDOWN DERBY SQL error: SQLCODE: -1, SQLSTATE: 08006 ...