Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Different failures in TestAutoServer #2249

Open
katzyn opened this issue Nov 11, 2019 · 12 comments
Open

Different failures in TestAutoServer #2249

katzyn opened this issue Nov 11, 2019 · 12 comments

Comments

@katzyn
Copy link
Contributor

katzyn commented Nov 11, 2019

They are possibly caused by #2236.

But the whole class looks suspicious. Perhaps it shouldn't extend the TestDb, but should extend TestBase, be launched only once, and its logic should be reviewed.

21:35:29 00:24.045 org.h2.test.server.TestAutoServer FAIL org.h2.jdbc.JdbcSQLNonTransientConnectionException: Database may be already in use: "Server is running". Possible solutions: close all other connection(s); use the server mode; SQL statement:
localhost:11111/16e5217e8c303bda09d4f276f9561454a41f754c5bf [90020-200]
	at org.h2.message.DbException.getJdbcSQLException(DbException.java:623)
	at org.h2.message.DbException.getJdbcSQLException(DbException.java:429)
	at org.h2.message.DbException.get(DbException.java:205)
	at org.h2.message.DbException.get(DbException.java:181)
	at org.h2.store.FileLock.checkServer(FileLock.java:250)
	at org.h2.store.FileLock.lock(FileLock.java:102)
	at org.h2.engine.Database.open(Database.java:629)
	at org.h2.engine.Database.openDatabase(Database.java:303)
	at org.h2.engine.Database.<init>(Database.java:297)
	at org.h2.engine.Engine.openSession(Engine.java:74)
	at org.h2.engine.Engine.openSession(Engine.java:192)
	at org.h2.engine.Engine.createSessionAndValidate(Engine.java:171)
	at org.h2.engine.Engine.createSession(Engine.java:166)
	at org.h2.server.TcpServerThread.run(TcpServerThread.java:168)
	at java.base/java.lang.Thread.run(Thread.java:834)
ERROR: FAIL (pageStore ) org.h2.jdbc.JdbcSQLNonTransientConnectionException: Database may be already in use: "Server is running". Possible solutions: close all other connection(s); use the server mode; SQL statement:
localhost:11111/16e5217e8c303bda09d4f276f9561454a41f754c5bf [90020-200]
	at org.h2.message.DbException.getJdbcSQLException(DbException.java:623)
	at org.h2.message.DbException.getJdbcSQLException(DbException.java:429)
	at org.h2.message.DbException.get(DbException.java:205)
	at org.h2.message.DbException.get(DbException.java:181)
	at org.h2.store.FileLock.checkServer(FileLock.java:250)
	at org.h2.store.FileLock.lock(FileLock.java:102)
	at org.h2.engine.Database.open(Database.java:629)
	at org.h2.engine.Database.openDatabase(Database.java:303)
	at org.h2.engine.Database.<init>(Database.java:297)
	at org.h2.engine.Engine.openSession(Engine.java:74)
	at org.h2.engine.Engine.openSession(Engine.java:192)
	at org.h2.engine.Engine.createSessionAndValidate(Engine.java:171)
	at org.h2.engine.Engine.createSession(Engine.java:166)
	at org.h2.server.TcpServerThread.run(TcpServerThread.java:168)
	at java.base/java.lang.Thread.run(Thread.java:834)
 org.h2.jdbc.JdbcSQLNonTransientConnectionException: Database may be already in use: "Server is running". Possible solutions: close all other connection(s); use the server mode; SQL statement:
localhost:11111/16e5217e8c303bda09d4f276f9561454a41f754c5bf [90020-200]
	at org.h2.message.DbException.getJdbcSQLException(DbException.java:623)
	at org.h2.message.DbException.getJdbcSQLException(DbException.java:429)
	at org.h2.message.DbException.get(DbException.java:205)
	at org.h2.message.DbException.get(DbException.java:181)
	at org.h2.store.FileLock.checkServer(FileLock.java:250)
	at org.h2.store.FileLock.lock(FileLock.java:102)
	at org.h2.engine.Database.open(Database.java:629)
	at org.h2.engine.Database.openDatabase(Database.java:303)
	at org.h2.engine.Database.<init>(Database.java:297)
	at org.h2.engine.Engine.openSession(Engine.java:74)
	at org.h2.engine.Engine.openSession(Engine.java:192)
	at org.h2.engine.Engine.createSessionAndValidate(Engine.java:171)
	at org.h2.engine.Engine.createSession(Engine.java:166)
	at org.h2.server.TcpServerThread.run(TcpServerThread.java:168)
	at java.base/java.lang.Thread.run(Thread.java:834)
 ------------------------------
org.h2.jdbc.JdbcSQLNonTransientConnectionException: Database may be already in use: "Server is running". Possible solutions: close all other connection(s); use the server mode; SQL statement:
localhost:11111/16e5217e8c303bda09d4f276f9561454a41f754c5bf [90020-200]
	at org.h2.message.DbException.getJdbcSQLException(DbException.java:623)
	at org.h2.message.DbException.getJdbcSQLException(DbException.java:429)
	at org.h2.message.DbException.get(DbException.java:205)
	at org.h2.message.DbException.get(DbException.java:181)
	at org.h2.store.FileLock.checkServer(FileLock.java:250)
	at org.h2.store.FileLock.lock(FileLock.java:102)
	at org.h2.engine.Database.open(Database.java:629)
	at org.h2.engine.Database.openDatabase(Database.java:303)
	at org.h2.engine.Database.<init>(Database.java:297)
	at org.h2.engine.Engine.openSession(Engine.java:74)
	at org.h2.engine.Engine.openSession(Engine.java:192)
	at org.h2.engine.Engine.createSessionAndValidate(Engine.java:171)
	at org.h2.engine.Engine.createSession(Engine.java:166)
	at org.h2.server.TcpServerThread.run(TcpServerThread.java:168)
	at java.base/java.lang.Thread.run(Thread.java:834)
	at org.h2.message.DbException.getJdbcSQLException(DbException.java:623)
	at org.h2.engine.SessionRemote.done(SessionRemote.java:611)
	at org.h2.engine.SessionRemote.initTransfer(SessionRemote.java:147)
	at org.h2.engine.SessionRemote.connectServer(SessionRemote.java:435)
	at org.h2.engine.SessionRemote.connectEmbeddedOrServer(SessionRemote.java:352)
	at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:173)
	at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:152)
	at org.h2.Driver.connect(Driver.java:69)
	at java.sql/java.sql.DriverManager.getConnection(DriverManager.java:677)
	at java.sql/java.sql.DriverManager.getConnection(DriverManager.java:228)
	at org.h2.test.TestDb.getConnectionInternal(TestDb.java:165)
	at org.h2.test.TestDb.getConnection(TestDb.java:38)
	at org.h2.test.server.TestAutoServer.testAutoServer(TestAutoServer.java:100)
	at org.h2.test.server.TestAutoServer.test(TestAutoServer.java:42)
	at org.h2.test.TestBase.runTest(TestBase.java:143)
	at org.h2.test.TestAll.addTest(TestAll.java:1005)
	at org.h2.test.TestAll.test(TestAll.java:815)
	at org.h2.test.TestAll.runTests(TestAll.java:637)
	at org.h2.test.TestAll.testAll(TestAll.java:555)
	at org.h2.test.TestAll.run(TestAll.java:505)
	at org.h2.test.TestAll.main(TestAll.java:447)

10:02:44 00:00.290 org.h2.test.server.TestAutoServer FAIL org.h2.jdbc.JdbcSQLNonTransientConnectionException: Connection is broken: "java.net.SocketTimeoutException: Read timed out: localhost:44703" [90067-200]
ERROR: FAIL (mvStore traceLevelFile defrag ) org.h2.jdbc.JdbcSQLNonTransientConnectionException: Connection is broken: "java.net.SocketTimeoutException: Read timed out: localhost:44703" [90067-200] org.h2.jdbc.JdbcSQLNonTransientConnectionException: Connection is broken: "java.net.SocketTimeoutException: Read timed out: localhost:44703" [90067-200] ------------------------------
org.h2.jdbc.JdbcSQLNonTransientConnectionException: Connection is broken: "java.net.SocketTimeoutException: Read timed out: localhost:44703" [90067-200]
	at org.h2.message.DbException.getJdbcSQLException(DbException.java:623)
	at org.h2.message.DbException.getJdbcSQLException(DbException.java:429)
	at org.h2.message.DbException.get(DbException.java:194)
	at org.h2.engine.SessionRemote.connectServer(SessionRemote.java:439)
	at org.h2.engine.SessionRemote.connectEmbeddedOrServer(SessionRemote.java:321)
	at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:173)
	at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:152)
	at org.h2.Driver.connect(Driver.java:69)
	at java.sql/java.sql.DriverManager.getConnection(DriverManager.java:677)
	at java.sql/java.sql.DriverManager.getConnection(DriverManager.java:228)
	at org.h2.test.server.TestAutoServer.testSocketReadTimeout(TestAutoServer.java:137)
	at org.h2.test.server.TestAutoServer.test(TestAutoServer.java:40)
	at org.h2.test.TestBase.runTest(TestBase.java:143)
	at org.h2.test.TestAll.addTest(TestAll.java:1005)
	at org.h2.test.TestAll.test(TestAll.java:815)
	at org.h2.test.TestAll.runTests(TestAll.java:662)
	at org.h2.test.TestAll.testAll(TestAll.java:555)
	at org.h2.test.TestAll.run(TestAll.java:505)
	at org.h2.test.TestAll.main(TestAll.java:447)
Caused by: java.net.SocketTimeoutException: Read timed out
	at java.base/java.net.SocketInputStream.socketRead0(Native Method)
	at java.base/java.net.SocketInputStream.socketRead(SocketInputStream.java:115)
	at java.base/java.net.SocketInputStream.read(SocketInputStream.java:168)
	at java.base/java.net.SocketInputStream.read(SocketInputStream.java:140)
	at java.base/java.io.BufferedInputStream.fill(BufferedInputStream.java:252)
	at java.base/java.io.BufferedInputStream.read(BufferedInputStream.java:271)
	at java.base/java.io.DataInputStream.readInt(DataInputStream.java:392)
	at org.h2.value.Transfer.readInt(Transfer.java:174)
	at org.h2.engine.SessionRemote.done(SessionRemote.java:604)
	at org.h2.engine.SessionRemote.initTransfer(SessionRemote.java:137)
	at org.h2.engine.SessionRemote.connectServer(SessionRemote.java:435)
	... 15 more
@katzyn
Copy link
Contributor Author

katzyn commented Nov 13, 2019 

07:20:20 00:22.232 org.h2.test.server.TestAutoServer Expected: 11111 actual: 37891
07:20:20 00:22.232 org.h2.test.server.TestAutoServer FAIL java.lang.AssertionError: Expected: 11111 actual: 37891
ERROR: FAIL (pageStore ) java.lang.AssertionError: Expected: 11111 actual: 37891 java.lang.AssertionError: Expected: 11111 actual: 37891 ------------------------------
java.lang.AssertionError: Expected: 11111 actual: 37891
	at org.h2.test.TestBase.fail(TestBase.java:330)
	at org.h2.test.TestBase.assertEquals(TestBase.java:490)
	at org.h2.test.server.TestAutoServer.testAutoServer(TestAutoServer.java:92)
	at org.h2.test.server.TestAutoServer.test(TestAutoServer.java:42)
	at org.h2.test.TestBase.runTest(TestBase.java:143)
	at org.h2.test.TestAll.addTest(TestAll.java:1005)
	at org.h2.test.TestAll.test(TestAll.java:815)
	at org.h2.test.TestAll.runTests(TestAll.java:637)
	at org.h2.test.TestAll.testAll(TestAll.java:555)
	at org.h2.test.TestAll.run(TestAll.java:505)
	at org.h2.test.TestAll.main(TestAll.java:447)

@dyrone
Copy link

dyrone commented Nov 14, 2019

This problem is weird, it looks like the previous connection does not release correctly.

@andreitokar
Copy link
Contributor

I've seen that last exception quite a few times, long before #2236 was introduced.

@katzyn
Copy link
Contributor Author

katzyn commented Nov 16, 2019

I also think that its real cause isn't related with that recent change, the change only increased size of the test and issue became more visible.

@katzyn
Copy link
Contributor Author

katzyn commented Nov 26, 2019 

12:04:57 00:22.179 org.h2.test.server.TestAutoServer FAIL org.h2.jdbc.JdbcSQLNonTransientConnectionException: Error opening database: "Concurrent update" [8000-200]
ERROR: FAIL (pageStore ) org.h2.jdbc.JdbcSQLNonTransientConnectionException: Error opening database: "Concurrent update" [8000-200] org.h2.jdbc.JdbcSQLNonTransientConnectionException: Error opening database: "Concurrent update" [8000-200] ------------------------------
org.h2.jdbc.JdbcSQLNonTransientConnectionException: Error opening database: "Concurrent update" [8000-200]
	at org.h2.message.DbException.getJdbcSQLException(DbException.java:455)
	at org.h2.message.DbException.getJdbcSQLException(DbException.java:429)
	at org.h2.message.DbException.get(DbException.java:194)
	at org.h2.store.FileLock.getExceptionFatal(FileLock.java:429)
	at org.h2.store.FileLock.lockFile(FileLock.java:337)
	at org.h2.store.FileLock.lock(FileLock.java:110)
	at org.h2.engine.Database.open(Database.java:628)
	at org.h2.engine.Database.openDatabase(Database.java:302)
	at org.h2.engine.Database.<init>(Database.java:297)
	at org.h2.engine.Engine.openSession(Engine.java:73)
	at org.h2.engine.Engine.openSession(Engine.java:191)
	at org.h2.engine.Engine.createSessionAndValidate(Engine.java:170)
	at org.h2.engine.Engine.createSession(Engine.java:165)
	at org.h2.engine.Engine.createSession(Engine.java:29)
	at org.h2.engine.SessionRemote.connectEmbeddedOrServer(SessionRemote.java:340)
	at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:173)
	at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:152)
	at org.h2.Driver.connect(Driver.java:69)
	at java.sql.DriverManager.getConnection(DriverManager.java:664)
	at java.sql.DriverManager.getConnection(DriverManager.java:247)
	at org.h2.test.TestDb.getConnectionInternal(TestDb.java:165)
	at org.h2.test.TestDb.getConnection(TestDb.java:52)
	at org.h2.test.server.TestAutoServer.testAutoServer(TestAutoServer.java:75)
	at org.h2.test.server.TestAutoServer.test(TestAutoServer.java:42)
	at org.h2.test.TestBase.runTest(TestBase.java:143)
	at org.h2.test.TestAll.addTest(TestAll.java:1007)
	at org.h2.test.TestAll.test(TestAll.java:816)
	at org.h2.test.TestAll.runTests(TestAll.java:638)
	at org.h2.test.TestAll.testAll(TestAll.java:556)
	at org.h2.test.TestAll.run(TestAll.java:506)
	at org.h2.test.TestAll.main(TestAll.java:448)

@grandinj
Copy link
Contributor

This means that there is some kind of leftover copy of H2 running.

Perhaps we should be doing a global thread dump when this happens to see why the other copy is hangin around.

@katzyn
Copy link
Contributor Author

katzyn commented Nov 26, 2019

With cycled test the failure appears very quickly.

Thread [main] (Suspended (breakpoint at line 39 in TestAutoServer))	
	TestAutoServer.main(String...) line: 39	
Daemon Thread [H2 File Lock Watchdog ...h2database/data/test/TestAutoServer.lock.db] (Running)	
Daemon Thread [H2 TCP Server (tcp://127.0.0.2:39649)] (Running)	
Daemon Thread [MVStore background writer ...h2database/data/test/TestAutoServer.mv.db] (Running)	
Daemon Thread [H2 TCP Server (tcp://127.0.0.2:39649) thread-1] (Running)	
Daemon Thread [H2 TCP Server (tcp://127.0.0.2:39649) thread-2] (Running)	
Daemon Thread [H2 TCP Server (tcp://127.0.0.2:39649) thread-3] (Running)	
Daemon Thread [H2 TCP Server (tcp://127.0.0.2:37761)] (Running)	
Daemon Thread [H2 File Lock Watchdog ...h2database/data/test/TestAutoServer.lock.db] (Running)	
Daemon Thread [MVStore background writer ...h2database/data/test/TestAutoServer.mv.db] (Running)	
Daemon Thread [H2 TCP Server (tcp://127.0.0.2:37761) thread-1] (Running)	
Daemon Thread [H2 File Lock Watchdog ...h2database/data/test/TestAutoServer.lock.db] (Running)	
Daemon Thread [H2 TCP Server (tcp://127.0.0.2:37197)] (Running)	
Daemon Thread [MVStore background writer ...h2database/data/test/TestAutoServer.mv.db] (Running)

@katzyn
Copy link
Contributor Author

katzyn commented Nov 26, 2019

testSocketReadTimeout() is the source of leftover threads, but without this method the failure still appears, but not that quickly.

@katzyn
Copy link
Contributor Author

katzyn commented Nov 26, 2019

Without both testSocketReadTimeout() and testLinkedLocalTablesWithAutoServerReconnect() test case doesn't fail.

@grandinj
Copy link
Contributor

Possibly our test infrastructure should do a quick scan of the current threads after every test to verify that things have shutdown properly, this is not the first time we've had trouble with H2 not shutting down properly.

@katzyn
Copy link
Contributor Author

katzyn commented Nov 26, 2019

In testSocketReadTimeout() one of leftover threads performs a slow query. The connection was broken, but query wasn't stopped. SHUTDOWN can stop it, but the TCP Server Thread isn't stopped anyway.

@katzyn
Copy link
Contributor Author

katzyn commented Nov 26, 2019

It looks like a problem with auto-server mode, SHUTDOWN should stop everything.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
4 participants
@grandinj @dyrone @andreitokar @katzyn