[
https://issues.apache.org/jira/browse/DERBY-5638?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13226391#comment-13226391
]
Mamta A. Satoor commented on DERBY-5638:
----------------------------------------
Mike commented "And to me it looks like the intermittent error happens while
setting up to run test_05_ClobNegative. But your fix seems to be to change
logic at the end of test_05_ClobNegative. "
My understanding of CleanDatabaseTestSetup is that it runs the steup at the
beginning of the suite run and it runs the teardown at the end of the suite
after the last test has run. And these same steps repeat for every suite. I
have put couple printlns in CleanDatabaseTestSetup to see this sequence while
running large data suite. To see these printlns, we need to pass
derby.tests.trace=true as shown below
$ time java -Dderby.tests.debug=true -Dderby.tests.trace=true
junit.textui.TestRunner
org.apache.derbyTesting.functionTests.tests.largedata._Suite > runall.out 2>&1
The use of Dderby.tests.trace=true puts all the println to the console(which I
have redirected to runall.out in my case)
The tests have not finished running(I will attach runall.out with what I have
so far. It is very verbose because all the existing printlns will now get
printed because of trace flag. You can search for "DEBUG: cleanDatabase" in
that file to see when setup and teardown gets called). I can see that debug
println for setup happens before the suite is run. Then after the suite is
finished, teardown is run before the new suite is started. And so on and so
forth.
eg of such a sequence (largedata.Derby5624Test.testDERBY_5624 is the first
suite and it has just one fixture. largedata.LobLimitsTest.test_01_Blob is
start of a new suite.)
DEBUG: cleanDatabase start in setup
DEBUG: cleanDatabase end in setup
.
(emb)largedata.Derby5624Test.testDERBY_5624 used 299858 ms DEBUG: cleanDatabase
start in teardown
DEBUG: cleanDatabase end in teardown
DEBUG: cleanDatabase start in setup
DEBUG: cleanDatabase end in setup
DEBUG: BIGGEST_LOB_SZ=1048576 BIG_LOB_SZ=102400
.
(emb)largedata.LobLimitsTest.test_01_Blob DEBUG:
========================================
An interesting eg of the setup and teardown can be seen when the last test in
embedded suite has run and when the next suite is getting run in network
server(largedata.LobLimitsTest.test_05_ClobNegative is the last test in the
previous suite. largedata.LobLimitsTest.test_01_Blob is the first fixture for
next suite which is a network server suite)
(emb)largedata.LobLimitsTest.test_05_ClobNegative DEBUG: at the beginning of
test_05_ClobNegative
DEBUG: ========================================
DEBUG: START ClobTest #7insert Clob of size = 102400
DEBUG: Got reader for file extinout/charLobLimits.txt
java.io.FileReader@38203820
DEBUG: Closed reader for file extinout/charLobLimits.txt
java.io.FileReader@38203820
DEBUG: ========================================
DEBUG: START ClobTest #7insert Clob of size = 102400
DEBUG: Got reader for file extinout/charLobLimits.txt
java.io.FileReader@46034603
DEBUG: Closed reader for file extinout/charLobLimits.txt
java.io.FileReader@46034603
DEBUG: Got FileWriter for extinout/charLobLimits.txt java.io.FileWriter@34243424
DEBUG: writer java.io.FileWriter@34243424 for file extinout/charLobLimits.txt
closed
DEBUG: ========================================
DEBUG: START ClobTest #9.1 insert Clob of size = 102401
DEBUG: Got reader for file extinout/charLobLimits.txt
java.io.FileReader@5e015e01
DEBUG: Closed reader for file extinout/charLobLimits.txt
java.io.FileReader@5e015e01
DEBUG: ========================================
DEBUG: START ClobTest #9.2 - SELECT CLOB of size = 102400
DEBUG: Matched rows selected with clob of size(102400) =0
DEBUG: Select Clob (102400) rows= 0 = 7
DEBUG: ========================================
DEBUG: ========================================
DEBUG: START ClobTest #10 insert Clob of size = 102401
DEBUG: Got reader for file extinout/charLobLimits.txt
java.io.FileReader@35f135f1
DEBUG: Closed reader for file extinout/charLobLimits.txt
java.io.FileReader@35f135f1
DEBUG: ========================================
DEBUG: START ClobTest #11 insert Clob of size = 102401
DEBUG: Got reader for file extinout/charLobLimits.txt
java.io.FileReader@77f277f2
DEBUG: Closed reader for file extinout/charLobLimits.txt
java.io.FileReader@77f277f2
DEBUG: Rows deleted =2
DEBUG: ========================================
DEBUG: START ClobTest #12.1 -insertClob of size = 102400
DEBUG: ========================================
DEBUG: START ClobTest #12.2 - SELECT CLOB of size = 102400
DEBUG: Select Clob (102400) rows= 0 = 1
DEBUG: Matched rows selected with clob of size(102400) =0
DEBUG: ========================================
DEBUG: Rows deleted =2
DEBUG: ========================================
DEBUG: START ClobTest #13 (setClob with 4Gb clobinsertClob of size = 4294967296
DEBUG: at the end of test_05_ClobNegative
used 506 ms DEBUG: cleanDatabase start in teardown
DEBUG: cleanDatabase end in teardown
DEBUG: Starting network server:
DEBUG: cleanDatabase start in setup
DEBUG: cleanDatabase end in setup
DEBUG: BIGGEST_LOB_SZ=1048576 BIG_LOB_SZ=102400
.
(net)largedata.LobLimitsTest.test_01_Blob DEBUG:
========================================
So based on the above information, I believe that the intermittent error
happens after the last test test_05_ClobNegative in the embedded suite has
finished running and while in the teardown code, it keeps running into lock
time out exceptions(the drop objects is tried 5 times and we see 5 lock
timeouts). Then the network server is started, it goes through the setup
method. The setup method in CleanDatabaseTestSetup looks as follows
protected void setUp() throws Exception {
if (jdbcClient != null )
{ // We have network client (useNetworkClient) on a given host and port.
TestConfiguration current = TestConfiguration.getCurrent();
TestConfiguration modified = new TestConfiguration(current,
jdbcClient,
hostName,
portNo);
TestConfiguration.setCurrent(modified);
}
Connection conn = getConnection();
conn.setAutoCommit(false);
// compress as well to allow the fixtures wrapped in
// this decorator to start with a clean database.
println("cleanDatabase start in setup");
CleanDatabaseTestSetup.cleanDatabase(conn, true);
println("cleanDatabase end in setup");
Statement s = conn.createStatement();
decorateSQL(s);
s.close();
conn.commit();
conn.close();
}
setup() first does the drop of objects again and then goes through the
decorateSQL to create test obects again. This is where in failed intermittent
failures, I believe we start seeing more lock time outs for drop table but with
network server driver(because the new suite is network server suite). And
subsequent try to create the table fails because we were never able to drop the
tables successfully because of lock timeouts.
Sorry for this being such a long comment. Please ask me questions if this is
not clear. I will post svn diff for simple printlns I put for tracking when
setup and teardowns are getting called. I will also put the runall.out for what
has finished so far with these extra printlns.
> intermittent test failure in test_05_ClobNegative when running full
> largedata._Suite; LobLimitsTestjava.sql.SQLException: Table/View 'BLOBTBL'
> already exists in Schema 'APP'.
> ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
>
> Key: DERBY-5638
> URL: https://issues.apache.org/jira/browse/DERBY-5638
> Project: Derby
> Issue Type: Bug
> Components: Test
> Affects Versions: 10.9.0.0
> Environment: ibm 1.6 sr9 fp1, Seen on Windows XP/VMWare, and Linux
> (CentOS)/VMWare
> Reporter: Myrna van Lunteren
> Assignee: Mamta A. Satoor
> Attachments: DERBY5638_patch1_diff.txt, derbyFailed.log,
> derbyPass.log, derbyWithRollbackInTest_05.log
>
>
> I've seen the following failure when running the largedata suite:
> (emb)largedata.Derby5624Test.testDERBY_5624 used 518403 ms .
> (emb)largedata.LobLimitsTest.test_01_Blob used 2422 ms .
> (emb)largedata.LobLimitsTest.test_02_BlobNegative used 31 ms .
> (emb)largedata.LobLimitsTest.test_03_Clob1 used 2375 ms .
> (emb)largedata.LobLimitsTest.test_04_Clob2 used 3234 ms .
> (emb)largedata.LobLimitsTest.test_05_ClobNegative used 516 ms .
> (net)largedata.LobLimitsTest.test_01_Blob used 5360 ms .
> (net)largedata.LobLimitsTest.test_02_BlobNegative used 32 ms .
> (net)largedata.LobLimitsTest.test_03_Clob1 used 2078 ms .
> (net)largedata.LobLimitsTest.test_04_Clob2 used 2390 ms .
> (net)largedata.LobLimitsTest.test_05_ClobNegative used 938 ms .
> (emb)largedata.LobLimitsTest.test_01_Blob used 9188238 ms .
> (emb)largedata.LobLimitsTest.test_02_BlobNegative used 109 ms .
> (emb)largedata.LobLimitsTest.test_03_Clob1 used 8116714 ms .
> (emb)largedata.LobLimitsTest.test_04_Clob2 used 2164002 ms .
> (emb)largedata.LobLimitsTest.test_05_ClobNegative used 685745 ms E
> Time: 22,320.138
> There was 1 error:
> 1) LobLimitsTestjava.sql.SQLException: Table/View 'BLOBTBL' already exists in
> Schema 'APP'.
> at
> org.apache.derby.client.am.SQLExceptionFactory40.getSQLException(Unknown
> Source)
> at org.apache.derby.client.am.SqlException.getSQLException(Unknown
> Source)
> at org.apache.derby.client.am.Statement.execute(Unknown Source)
> at
> org.apache.derbyTesting.functionTests.tests.largedata.LobLimitsTest.setupTables(LobLimitsTest.java:107)
> at
> org.apache.derbyTesting.functionTests.tests.largedata.LobLimitsTest$1.decorateSQL(LobLimitsTest.java:141)
> at
> org.apache.derbyTesting.junit.CleanDatabaseTestSetup.setUp(CleanDatabaseTestSetup.java:112)
> at junit.extensions.TestSetup$1.protect(TestSetup.java:20)
> at junit.extensions.TestSetup.run(TestSetup.java:25)
> at
> org.apache.derbyTesting.junit.BaseTestSetup.run(BaseTestSetup.java:57)
> at junit.extensions.TestDecorator.basicRun(TestDecorator.java:24)
> at junit.extensions.TestSetup$1.protect(TestSetup.java:21)
> at junit.extensions.TestSetup.run(TestSetup.java:25)
> at junit.extensions.TestDecorator.basicRun(TestDecorator.java:24)
> at junit.extensions.TestSetup$1.protect(TestSetup.java:21)
> at junit.extensions.TestSetup.run(TestSetup.java:25)
> at
> org.apache.derbyTesting.junit.BaseTestSetup.run(BaseTestSetup.java:57)
> at junit.extensions.TestDecorator.basicRun(TestDecorator.java:24)
> at junit.extensions.TestSetup$1.protect(TestSetup.java:21)
> at junit.extensions.TestSetup.run(TestSetup.java:25)
> Caused by: org.apache.derby.client.am.SqlException: Table/View 'BLOBTBL'
> already exists in Schema 'APP'.
> at org.apache.derby.client.am.Statement.completeSqlca(Unknown Source)
> at
> org.apache.derby.client.am.Statement.completeExecuteImmediate(Unknown Source)
> at
> org.apache.derby.client.net.NetStatementReply.parseEXCSQLIMMreply(Unknown
> Source)
> at
> org.apache.derby.client.net.NetStatementReply.readExecuteImmediate(Unknown
> Source)
> at
> org.apache.derby.client.net.StatementReply.readExecuteImmediate(Unknown
> Source)
> at
> org.apache.derby.client.net.NetStatement.readExecuteImmediate_(Unknown Source)
> at org.apache.derby.client.am.Statement.readExecuteImmediate(Unknown
> Source)
> at org.apache.derby.client.am.Statement.flowExecute(Unknown Source)
> at org.apache.derby.client.am.Statement.executeX(Unknown Source)
> ... 26 more
> Unfortunately, when this happens, there seems to be no 'fail' directory
> created. The derby.log in the system directory looks very innocent (just some
> start up and shutting down of the database), and the serverConsoleOutput.log
> only has the typical 'failed to find db 'wombat' messages'.
> Note, when this happens, the suite exits, so that instead of the expected 20
> (or 21 on windows, see DERBY-5624 for reason for skipping on Linux default
> installs with 1024 max open files) we only get 15 (or 16) tests run - if the
> test doesn't fail it goes on to run the last 5 fixtures again for network
> server.
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators:
https://issues.apache.org/jira/secure/ContactAdministrators!default.jspa
For more information on JIRA, see: http://www.atlassian.com/software/jira
